Pdns: MySQL backend restart issue

[maniaque]

Hi there!

Having problems with restarting MySQL backend while PowerDNS is running (Ubuntu 16.04, PowerDNS 4.0.0~alpha2-3build1)

After restart both MySQL and PowerDNS are started, I see following statements in journalctl

May 06 00:09:37 vova pdns[31743]: gmysql Connection successful. Connected to database 'pdns' on
May 06 00:09:37 vova pdns[31743]: gmysql Connection successful. Connected to database 'pdns' on
May 06 00:09:37 vova pdns[31743]: gmysql Connection successful. Connected to database 'pdns' on

Afterwards I restart MySQL. It breaks everything down in pieces:

May 06 00:09:11 vova pdns[30268]: Backend reported condition which prevented lookup

There is only one cure - restart PowerDNS. Doesn't look like good solution.

[pieterlexis]

hi manique, this is fixed in the current master (in #3666). We will release Alpha3 soon that should land in Ubuntu Xenial. If you want to use PowerDNS 4, I would recommend for now using the master packages at https://repo.powerdns.com/

[willtorres]

I was experiencing the issue in #3535, so I installed the alpha3 version. It seems like PDNS loses connection to MySQL for some reason, I do query, it returns REFUSED, I do another query, it returns the correct data. Is it supposed to be losing the db connection so frequently?

[Habbie]

No, it's not supposed to lose it frequently. It is also not supposed to use REFUSED for that. Reopening this ticket - if you have any logs or other information, please provide them.

[Habbie]

If you are also experiencing #3535 in alpha3, please let us know.

[willtorres]

Here's my logfile.
log.txt

The resulting queries:

$ nslookup admin-02.internal 192.168.99.100
Server:     192.168.99.100
Address:    192.168.99.100#53

Name:   admin-02.internal
Address: 10.10.5.30

$ nslookup admin-02.internal 192.168.99.100
Server:     192.168.99.100
Address:    192.168.99.100#53

** server can't find admin-02.internal.iad.buffalo-ggn.net: REFUSED

$ nslookup admin-02.internal 192.168.99.100
Server:     192.168.99.100
Address:    192.168.99.100#53

Name:   admin-02.internal
Address: 10.10.5.30

[Habbie]

@willtorres we need output from reliable tools like dig, drill or delv. nslookup output is not useful for debugging (same goes for host). Thank you.

[willtorres]

These were done in succession, about 2 seconds apart

$ dig @192.168.99.100 admin-02.internal

; <<>> DiG 9.8.3-P1 <<>> @192.168.99.100 admin-02.internal
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 62152
;; flags: qr aa rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0
;; WARNING: recursion requested but not available

;; QUESTION SECTION:
;admin-02.internal.     IN  A

;; Query time: 9 msec
;; SERVER: 192.168.99.100#53(192.168.99.100)
;; WHEN: Fri May 13 11:01:05 2016
;; MSG SIZE  rcvd: 35

$ dig @192.168.99.100 admin-02.internal

; <<>> DiG 9.8.3-P1 <<>> @192.168.99.100 admin-02.internal
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: SERVFAIL, id: 22069
;; flags: qr aa rd; QUERY: 1, ANSWER: 0, AUTHORITY: 0, ADDITIONAL: 0
;; WARNING: recursion requested but not available

;; QUESTION SECTION:
;admin-02.internal.     IN  A

;; Query time: 5 msec
;; SERVER: 192.168.99.100#53(192.168.99.100)
;; WHEN: Fri May 13 11:01:08 2016
;; MSG SIZE  rcvd: 35


$ dig @192.168.99.100 admin-02.internal

; <<>> DiG 9.8.3-P1 <<>> @192.168.99.100 admin-02.internal
; (1 server found)
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 26634
;; flags: qr aa rd; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 0
;; WARNING: recursion requested but not available

;; QUESTION SECTION:
;admin-02.internal.     IN  A

;; ANSWER SECTION:
admin-02.internal.  86400   IN  A   10.10.5.30

;; Query time: 4 msec
;; SERVER: 192.168.99.100#53(192.168.99.100)
;; WHEN: Fri May 13 11:01:12 2016
;; MSG SIZE  rcvd: 51

[Habbie]

Ok - now we see SERVFAIL which is of course sad but not in itself a bug. If you manage to spot REFUSED with dig in such a situation, please post again. Also, please put ``` around your pastes. Thanks!

[maniaque]

Well, in my case this was also SERVFAIL, I think, we need more system logs here.

[maniaque]

BTW, can anyone please say, which exact Debian package version have this fix? I still would like to move 4.x to production ;)

[Habbie]

As said, alpha3 has fixed #3535. #3666 which is also in Alpha3 should have fixed gsql reconnection behaviour. However, if a database goes down as often as yours appears to do, I'm not sure we can do more..

[maniaque]

In my case, it goes down not very often. Will look for Alpha3 in Debian. Thanks.

[Habbie]

alpha3 is now in Debian sid, and of course also at https://repo.powerdns.com/

[wk]

Recently performed an in-place upgrade of PowerDNS 3.3 (Ubuntu 14.04/Trusty build) to PowerDNS 4.0.0-alpha3 (PowerDNS Repository build) on an Ubuntu 14.04/Trusty host; also seeing intermittent MySQL backend drops:

May 17 10:15:50 DNS001-A pdns[31618]: Backend reported permanent error which prevented lookup (GSQLBackend lookup query:Could not execute mysql statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: Lost connection to MySQL server during query), aborting
May 17 10:15:50 DNS001-A pdns[31618]: TCP nameserver had error, cycling backend: GSQLBackend lookup query:Could not execute mysql statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: Lost connection to MySQL server during query

Have not previously experienced this with PowerDNS 3.3, and no other moving parts of the setup have changed.

MySQL Libraries on client:

ii  libmysqlclient18:amd64               5.5.49-0ubuntu0.14.04.1          amd64        MySQL database client library
ii  mysql-client                         5.5.49-0ubuntu0.14.04.1          all          MySQL database client (metapackage depending on the latest version)
ii  mysql-client-5.5                     5.5.49-0ubuntu0.14.04.1          amd64        MySQL database client binaries
ii  mysql-client-core-5.5                5.5.49-0ubuntu0.14.04.1          amd64        MySQL database core client binaries
ii  mysql-common                         5.5.49-0ubuntu0.14.04.1          all          MySQL database common files, e.g. /etc/mysql/my.cnf

MySQL Server:

ii  libmysqlclient18:amd64              5.5.49-0ubuntu0.14.04.1          amd64        MySQL database client library
ii  mysql-client-5.5                    5.5.49-0ubuntu0.14.04.1          amd64        MySQL database client binaries
ii  mysql-client-core-5.5               5.5.49-0ubuntu0.14.04.1          amd64        MySQL database core client binaries
ii  mysql-common                        5.5.49-0ubuntu0.14.04.1          all          MySQL database common files, e.g. /etc/mysq /my.cnf
ii  mysql-server                        5.5.49-0ubuntu0.14.04.1          all          MySQL database server (metapackage depending on the latest version)
ii  mysql-server-5.5                    5.5.49-0ubuntu0.14.04.1          amd64        MySQL database server binaries and system database setup
ii  mysql-server-core-5.5               5.5.49-0ubuntu0.14.04.1          amd64        MySQL database server binaries

The servers this has been occurring on are very lightly loaded (average of under 5 queries/sec), and the backend drops have been occurring at a frequency of no more than once a day so far. The connectivity appears to be recovered automatically on a subsequent query.

[mind04]

5 qps and lost connections for tcp looks like a mysql server is closing idle tcp backend connections after mysql wait_timeout.

[willtorres]

@mind04 Thank you so much! I've increased the wait_timeout to the maximum, and my connections are staying alive.

[wk]

Upon further investigation, it appears that the second log line is significant:

May 17 10:15:50 DNS001-A pdns[31618]: TCP nameserver had error, cycling backend: GSQLBackend lookup query:Could not execute mysql statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: Lost connection to MySQL server during query

While the server in question handles an average of 5 queries/sec, the bulk of those queries are _UDP_.

The 5 queries/second load keeps the MySQL connections of the 3 default distributor threads sufficiently utilized to prevent time-outs even with a fairly aggressive wait_timeout setting (although this may not be the case on even quieter servers).

The _TCP_ receiver, however, maintains its own backend thread. In the above scenario, it sees just a fraction of the load, the time-out is hit fairly regularly, and the connection is lost. It is receiving the first _TCP_ query in a long while that triggered the issue.

This leaves open the question of why a lost connection would result in an error in the first place. After all, the gmysqlbackend makes use of the libmysqlclient MYSQL_OPT_RECONNECT option, which should result in a transparent reconnect after a time-out, rather than in an error. The answer to that may lie in the documentation of this feature itself. Amongst the caveats, the following is listed:

[...]
The connection-related state is affected as follows: 
[...]
* Prepared statements are released. 
[...]

A cursory look through the code suggests that gsql's setDB function prepares the statements ahead of time when a database backend is initialized.

Perhaps when a previously prepared statement is executed after a silent re-connect by libmysqlclient, the prepared statement, as per the documentation, is no longer available, and an error occurs - resulting in the behaviour outlined in this issue?

[Habbie]

Yes, it certainly is looking like we may need to work on re-preparing the statements, or perhaps even just handling the reconnection ourselves.

[wk]

There is no obvious way to trigger on the reconnection attempt and perform a re-preparation of the queries _in-query_ since the raison d'être of MYSQL_OPT_RECONNECT is to hide what has transpired from the application.

There are, however, a number of ways to work around this.

Switch from query preparation at backend thread init to a just-in-time model.
The minimal re-factoring here would probably be something along the lines of turning gmysqlbackend's implementation of the prepare function into a dummy that returns a pointer, and doing the real work as part of the execute function just prior to actual execution.

Ping the database with mysql_ping() before executing each query.
According to the mysql_ping() documentation, this will, with a bit of extra work, allow identifying when a reconnect has occurred.

If mysql_ping()) does cause a reconnect, there is no explicit indication of it. To determine whether a reconnect occurs, call mysql_thread_id() to get the original connection identifier before calling mysql_ping(), then call mysql_thread_id() again to see whether the identifier has changed. 

Thus, by keeping track and comparing the mysql_thread_id before and after mysql_ping() a reconnect can be detected, and the queries can be re-prepared prior to execution.

Drop MYSQL_OPT_RECONNECT and mask the problem with regular mysql_ping().
The current default server-side wait_timeout value is 28800 seconds, but there may be valid reasons (or at least a wide-spread practice in shared web hosting environments with legacy PHP applications) to set this variable globally to values as short as 30 seconds.

By simply firing off a mysql_ping() on a timer with intervals shorter than wait_timeout, it should be possible to prevent session time-outs in the first place. In such a scenario, MYSQL_OPT_RECONNECT can be disabled, with the ultimate fallback becoming full backend restart.

Since the client can get and set the wait_timeout variable for its own session, gmysqlbackend could also potentially first determine the current value in order to configure its mysql_ping() timer, or override it during init to a sensible value in order to reduce noise.

[cmouse]

Partially fixed by #3937

[pieterlexis]

Should be fixed in #3937

[CaptainQwark]

I'm still having this problem on 4.0.1 with TCP connections on my master server (only serving slaves). The first slave that connects for an AXFR after more than 'wait_timeout' seconds (mysql setting, default 8 hours) gets a disconnected TCP session and misses the update.

I will work around this by increasing the wait_timeout setting, but I think pdns-gmysql should prevent the connection/transfer from failing. E.g. by a keepalive-ping to mysql or a reconnect before failing the TCP session, just as @wk suggested.

logs from master:

Aug 22 11:59:47 ns-master pdns[5065]: AXFR of domain 'zeelandnet-lab1.nl' initiated by 192.168.222.193
Aug 22 11:59:47 ns-master pdns[5065]: AXFR of domain 'zeelandnet-lab1.nl' allowed: client IP 192.168.222.193 is in allow-axfr-ips
Aug 22 11:59:47 ns-master pdns[5065]: TCP nameserver had error, cycling backend: GSQLBackend lookup query:Could not prepare statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: MySQL server has gone away
Aug 22 11:59:47 ns-master pdns[5065]: AXFR of domain 'zeelandnet-lab1.nl' initiated by 192.168.222.195
Aug 22 11:59:47 ns-master pdns[5065]: TCP server is without backend connections in doAXFR, launching
Aug 22 11:59:47 ns-master pdns[5065]: AXFR of domain 'zeelandnet-lab1.nl' allowed: client IP 192.168.222.195 is in allow-axfr-ips
Aug 22 11:59:47 ns-master pdns[5065]: AXFR of domain 'zeelandnet-lab1.nl' to 192.168.222.195 finished

logs from failing slave:

Aug 22 11:59:47 ns1-1 pdns[5054]: Received serial number updates for 1 zone, had 0 timeouts
Aug 22 11:59:47 ns1-1 pdns[5054]: Domain 'zeelandnet-lab1.nl' is stale, master serial 2016082201, our serial 2016081801
Aug 22 11:59:47 ns1-1 pdns[5054]: Initiating transfer of 'zeelandnet-lab1.nl' from remote '192.168.222.194'
Aug 22 11:59:47 ns1-1 pdns[5054]: Backend launched with banner: OK#011pdns-dynamic-backend.py ready
Aug 22 11:59:47 ns1-1 pdns[5054]: Starting AXFR of 'zeelandnet-lab1.nl' from remote 192.168.222.194:53
Aug 22 11:59:47 ns1-1 pdns[5054]: Unable to AXFR zone 'zeelandnet-lab1.nl' from remote '192.168.222.194' (resolver): Remote nameserver closed TCP connection

[wk]

This indeed appears to not function ideally in 4.0.1, and may be unintentional. I can replicate this behaviour.

What appears to have happened is this:

• In this issue, PowerDNS/pdns#3824, the root cause of MYSQL_OPT_RECONNECT failing was traced to prepared queries being discarded after a reconnect; since the gsql backend prepared all queries in advance, this caused the first query after MYSQL_OPT_RECONNECT to fail.
• In order to resolve this issue, @cmouse has introduced lazy query preparation in PowerDNS/pdns#3937, which was merged.
• At the same time, however, @mind04 has been working on PowerDNS/pdns#4071 where in this commit he has completely disabled the MYSQL_OPT_RECONNECT functionality.

As a result of both these commits being merged, a situation emerged in which the precondition for MYSQL_OPT_RECONNECT being functional has in fact been resolved, but the feature itself has been forcefully disabled, leading to the outcome @CaptainQwark is seeing.

[marekruzicka]

Hi, thanx for making this crystal clear...
Anyway what is the current recommendation here?
I'm on 4.0.1 at the moment, and this instabillity is pretty much killing me.

[Marlinc]

@marekruzicka I'm currently waiting for Maxscale to implement https://jira.mariadb.org/browse/MXS-852?jql=text%20~%20%22prepared%22. This would at least soften the issue as Maxscale could handle the fail-over to another node on the background.

[marekruzicka]

@Marlinc Well as I understand it, issue is already solved, just disabled.

So when can we expect it to be released?

[rgacogne]

I might be mistaken but I don't think we can enable MYSQL_OPT_RECONNECT right now. Otherwise what happens if we prepare a statement, use it, then a reconnect occurs under our feet? We have no way of knowing that existing prepared statements are not valid anymore and will fail as soon as we try to use them. We need to be able to invalidate our statements if a reconnect occurs, either by being notified by libmysql when it happens or by somehow being able to tell that the use of a statement failed because the connection has changed. Or am I missing something obvious?

[cmouse]

Well, current code actually releases the statement, forcing repreparation on next round. Of course the best option would be to detect what caused the error, and with this information, decide whether to invalidate all the statements.

[rgacogne]

And if we know that the error was caused by a reconnect we should probably try again right after invalidating the statements, right?

[cmouse]

Well, yes, I suppose so. I guess the good idea would be to perform the reconnection in pdns code and not in mysql driver.

[mik997]

PowerDNS 4.0.1 on Ubuntu 16.04 with MariaDB 10.0.28 backend:

Nov 21 12:13:57 Backend reported permanent error which prevented lookup (GSQLBackend lookup query:Could not execute mysql statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: Lost connection to MySQL server during query), aborting

and

Nov 21 12:13:57 Backend error (retry once): GSQLBackend lookup query:Could not execute mysql statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: Lost connection to MySQL server during query

being logged every 3 - 10 minutes in syslog

queries being handled Ok as far as I can tell

any progress towards a solution? Is it recommended to increase the mysql timeout value?

[madpsy]

I too am seeing this with 4.0.1-1pdns.xenial talking to a (high performance) MariaDB Galera cluster. I thought it was a timeout with the load balancing but after a few tests I don't believe it is.

This completely breaks AXFR and the only way to restore functionality is to restart pdns.

It's possible the cause is wait_timeout in MariaDB (600 seconds) but increasing that is a bodge not a fix and no telling what affect it would have on other applications using the cluster.

My opinion is PowerDNS should either regularly use mysql_ping(), as per a configurable value or handle the reconnection gracefully.

Nov 29 14:22:19 Backend reported permanent error which prevented lookup (GSQLBackend lookup query:Could not execute mysql statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: Lost connection to MySQL server during query), aborting

[mik997]

@madpsy thanks for reporting your experience :) I see @peterthomassen has a workaround above which increases the wait_timeout to 28800 (8 hours?)

I'm wondering if this is Ok to use on production nameservers?

[madpsy]

@mik997 The wait_timeout workaround would likely 'fix' it but only because there's a greater chance of pdns sending a query within ~8 hours than, in my case, 10 minutes. wait_timeout in my environment is set to a sensible value for a reason - to prevent long-lived stale connections.

As for if it's suitable for production.. sure, as long as other applications, which may misbehave, aren't using the same SQL server (otherwise you may end up exhausting max_connections). Again, if no query is sent within wait_timeine then the same will happen. AFAIK there is a separate connection for AXFR's and for normal DNS queries, therefore it may occur with both if there's neither a AXFR request or all the queries are hitting one of the caches.

I've only been using pdns for 24 hours (in testing) so what I stated might be grossly inaccurate but the debug I've done so far point towards this.

[thechile]

I'm seeing these errors as well on below setup.

cat /etc/redhat-release
CentOS Linux release 7.3.1611 (Core)

$rpm -qa | grep Maria
MariaDB-client-10.1.20-1.el7.centos.x86_64
MariaDB-shared-10.1.20-1.el7.centos.x86_64
MariaDB-server-10.1.20-1.el7.centos.x86_64
MariaDB-common-10.1.20-1.el7.centos.x86_64

$rpm -qa | grep pdns
pdns-backend-geoip-4.0.1-1pdns.el7.x86_64
pdns-recursor-4.0.3-1pdns.el7.x86_64
pdns-4.0.1-1pdns.el7.x86_64
pdns-backend-mysql-4.0.1-1pdns.el7.x86_64

Error Messages

Jan 05 22:36:26 pdns_server[43756]: Jan 05 22:36:25 Backend reported permanent error which prevented lookup (GSQLBackend lookup query:Could not execute mysql statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: Lost connection to MySQL server during query), aborting
Jan 05 22:36:26 pdns_server[43756]: Jan 05 22:36:25 Backend error (retry once): GSQLBackend lookup query:Could not execute mysql statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: Lost connection to MySQL server during query
Jan 05 22:36:26 pdns_server[43756]: Jan 05 22:36:26 gmysql Connection successful. Connected to database 'powerdns' on 'localhost'.

So yea, complains and reconnects within 1 second so probably doesn't disrupt much but is fugly error in logs.

Looking back at logs is seems to happen every two hours'ish but no exact pattern.

Jan 05 18:46:12 pdns_server[43756]: Jan 05 18:46:12 Backend reported permanent error which prevented lookup (GSQLBackend lookup query:Could not execute mysql statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: Lost connection to MySQL server during query), aborting
Jan 05 20:02:04 pdns_server[43756]: Jan 05 20:02:04 Backend reported permanent error which prevented lookup (GSQLBackend lookup query:Could not execute mysql statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: Lost connection to MySQL server during query), aborting
Jan 05 22:36:26 pdns_server[43756]: Jan 05 22:36:25 Backend reported permanent error which prevented lookup (GSQLBackend lookup query:Could not execute mysql statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: Lost connection to MySQL server during query), aborting

Also, the error is always logged for me when query is for .. WHERE disabled=0 and type=? and name=?:. Can someone explain what the ? means and is it significant to the problem ?

Thank you.

[psi-4ward]

@thechile ? is the placeholder char for the prepared statement.

Is this a MariaDB problem and does not occur with Oracle MySQL?

[madpsy]

@psi-4ward I suspect both. Oracle MySQL may have a higher default value or users of MariaDB generally set sensible values or something in between.

[marekruzicka]

We are running PXC (Percona XtraDB Cluster) and are experiencing the same bug, so it is most likely general mysql-esque issue.

[TomasMerta]

A have set wait_timeout=30 in MySQL (Percona) server due to bad written PHP scripts etc.
As a workaround I use:
1) set gmysql-group=powerdns in pdns.conf
2) add new group section for powerdns in my.cnf. It is important to add powerdns group after [client] group section

[powerdns]
init-command='SET wait_timeout=28800'

3) restart pdns server and pdns use new wait_timeout value

[psi-4ward]

Thanks @TomasMerta, works for me

[psi-4ward]

Seems that is fixed in 4.0.2

[marekruzicka]

@psi-4ward It's not. Maybe partially, I don't really know how it was behaving before...

It really comes down to how are you trying to create new records once you no longer have "write session" opened (eg. after hitting wait_timeout) - API vs nsupdate.

Once we hit wait_timeout (after 8hours) and we try to create new record via API, we can see that new session (write session) is opened to the DB and record is created as expected. I'm not sure if this was the case before 4.0.2 was out.
But in the same situation, when there is no "write session" opened, and you try to create new record using nsupdate, you are back to above mentioned errors.

Jan 05 22:36:26 pdns_server[43756]: Jan 05 22:36:25 Backend reported permanent error which prevented lookup (GSQLBackend lookup query:Could not execute mysql statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: Lost connection to MySQL server during query), aborting Jan 05 22:36:26 pdns_server[43756]: Jan 05 22:36:25 Backend error (retry once): GSQLBackend lookup query:Could not execute mysql statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: Lost connection to MySQL server during query Jan 05 22:36:26 pdns_server[43756]: Jan 05 22:36:26 gmysql Connection successful. Connected to database 'powerdns' on 'localhost'.

[binBASH]

Also seeing this with powerdns 4.0.3

Jan 21 14:32:02 Backend reported permanent error which prevented lookup (GSQLBackend lookup query:Could not execute mysql statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: Lost connection to MySQL server during query), aborting
Jan 21 14:32:02 TCP nameserver had error, cycling backend: GSQLBackend lookup query:Could not execute mysql statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: Lost connection to MySQL server during query
Jan 21 14:33:25 TCP server is without backend connections, launching

[zeha]

Once we hit wait_timeout (after 8hours) and we try to create new record via API, we can see that new session (write session) is opened to the DB and record is created as expected. I'm not sure if this was the case before 4.0.2 was out.

API should never have been affected by this.

[aiso-net]

Im having the same issue as well with 4.0.3 that binBASH is having:

Feb 11 11:47:06 pdns[25695]: Backend error (retry once): GSQLBackend lookup query:Could not prepare statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: MySQL server has gone away
Feb 11 11:50:05 pdns[25695]: Backend reported permanent error which prevented lookup (GSQLBackend lookup query:Could not prepare statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: MySQL server has gone away), aborting
Feb 11 11:50:05  pdns[25695]: TCP nameserver had error, cycling backend: GSQLBackend lookup query:Could not prepare statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: MySQL server has gone away
Feb 11 11:50:10 pdns[25695]: TCP server is without backend connections, launching
Feb 11 11:52:49 pdns[25695]: Backend reported permanent error which prevented lookup (GSQLBackend lookup query:Could not execute mysql statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: Lost connection to MySQL server during query), aborting

wait timeout on mysql is set to 3600 and I can access mysql via command line fine.

[Habbie]

Assorted notes, feel free to ignore:

• e258fd1 (just before we went prepared) is super stable unless you disable MYSQL_OPT_RECONNECT in which case it becomes unusable with wait_timeout=1
• master (276ec0983774f3e08733d8cd30d8d58bf93ff9c9): wait_timeout=1 causes working retry on UDP, drops TCP queries; enabling MYSQL_OPT_RECONNECT does not appear to change anything

[Habbie]

~Ok, I'm going to claim that #5005 fixes this once and for all. The three commits apply cleanly to rel/auth-4.0.x. Anybody willing to try?~ nope

[stecklars]

Just curious whether this issue would have any significant effect when using PowerDNS as a nameserver for a domain. I'm also seeing this behaviour and was wondering if this may prevent users from getting the relevant DNS records and therefore accessing the domains and its services that do have a PowerDNS nameserver?

I mainly see this on "ANY" queries as other queries are usually done via UDP, where this isn't happening for me. However when issuing an ANY query via dig, it automatically seems to reconnect after the communications error and actually return the correct results:

$ dig @ns1.mydomain.com myseconddomain.com ANY
;; Truncated, retrying in TCP mode.
;; communications error to [IP]#53: end of file

; «» DiG 9.9.5-3ubuntu0.8-Ubuntu «» @ns1.mydomain.com myseconddomain.com ANY
; (2 servers found)
;; global options: +cmd
;; Got answer:
;; -»HEADER«- opcode: QUERY, status: NOERROR, id: 15163
;; flags: qr aa rd; QUERY: 1, ANSWER: 8, AUTHORITY: 0, ADDITIONAL: 8
;; WARNING: recursion requested but not available

[Correct answer follows]

Would this bug prevent users from visiting websites / sending mails to domains using PowerDNS, under normal circumstances?

[jph]

@stecklars I believe it would; I'm doing testing now and just ran into this same bug. I got an EOF error:

;; communications error to 172.0.0.10#53: end of file

and had to re-run the query, which was simply an A record dig. So I believe this could be potentially breaking on real client requests if the nameserver isn't particularly busy (enough to keep the timeout from being reached).

For the thread/maintainers: I'm running Centos 7.3.1611 + PowerDNS Authoritative 4.0.3 + Recursor 4.0.4 (from the PowerDNS repositories) and I most definitely see these issues.

[stecklars]

Uh, then this would be a serious problem for me. I guess as a easy workaround I could just create a cron job on a random server that runs a query every few minutes...

[Spacefish]

Having the same problem with 4.0.2:
TCP nameserver had error, cycling backend: GSQLBackend lookup query:Could not execute mysql statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: Lost connection to MySQL server during query

I don´t want / need prepared statements / a persistent MySQL connection. Could we just have a mode, which opens the connection per request and closes it afterwards? I know this is bad performance wise for high volume servers, but i don´t care for the 100 queries run against my DNS a day.
Better have i working slow than not have it working at all / sporadic failures.

[martinsmatthews]

Am seeing this on on pdns 4.0.3, mysql (or percona, have tried both) 5.7.17.

This causes the AXFR from the slave to fail - Slave log

Mar 30 18:37:30 Starting AXFR of 'example.com' from remote 192.168.0.1:53
Mar 30 18:37:30 Unable to AXFR zone 'example.com' from remote '192.168.0.1' (resolver): Remote nameserver closed TCP connection

Master log

Mar 30 18:37:30 AXFR of domain 'example.com' initiated by 192.168.0.2
Mar 30 18:37:30 AXFR of domain 'example.com' allowed: client IP 192.168.0.2 is in allow-axfr-ips
Mar 30 18:37:30 TCP nameserver had error, cycling backend: GSQLBackend lookup query:Could not execute mysql statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: Lost connection to MySQL server during query
Mar 30 18:37:30 Removed from notification list: 'example.com' to 192.168.0.2:53 (was acknowledged)
Mar 30 18:37:30 Received unsuccessful notification report for 'example.com' from 192.168.0.1:53, error: Not Implemented
Mar 30 18:37:30 Removed from notification list: 'example.com' to 192.168.0.1:53 Not Implemented
Mar 30 18:37:32 No master domains need notifications

The next AXFR query is successful as it opens a new connection.

We already have a wait_timeout of 8 hours (the default), increasing this to 1 week seems like a bad option, but possibly our only choice if we want to stay with the mysql backend.

Any chance this will be fixed in 4.0.4? Are there any other work arounds other than increasing the wait_timeout?

Can the slave be configured to run the AXFR on a schedule that is more frequent than the connect timeout? I guess that doesn't guarantee that the connections in the retrieval pool will be fresh though. Would setting retrieval-threads to 1 help? We have just a single slave and no other clients allowed to run AXFR queries.

[Habbie]

As we have been unable to figure out a reliable way to fix this, and it appears this only affects machines with very low traffic, I am sad to say I am removing the 4.1 milestone from this.

[martinsmatthews]

That's a shame, any chance we could get the slave to retry the AXFR query - it would only need to retry once from what I can see.

[madpsy]

In my case, although not particularly high traffic, dnsdist is performing aggressive caching so that exacerbates the issue.

[stecklars]

Just curious, are there any downsides of running for example
dig @localhost +tcp somedomainonmynameserver.tld ANY >/dev/null 2>&1
every few minutes in a cronjob on each nameserver?

That should fix the issue, shouldn't it?
Looking at my logs there are no more error messages.

[jph]

@stecklars that's what I've ended up doing, and it's working fine in my case. No more errors for over a week.

[martinsmatthews]

We do this as part of our monitoring to check a couple of records we are authoritative for and also some we are not to test that recursion is also working, but not specifically as a keepalive on the mysql connection.

The AXFR is trickier as there is a separate backend/thread pool for this. We were already checking that the SOA serial matches when querying the master and slave using dig. Now, when they don't, we run a pdns_control notify * on the master - this causes master to re-notify the slave and the slave to rerun the AXFR query which works this time as the failed backend has been cycled after the first failure. Nasty but we can't see any other options.

[Habbie]

5245 should be of extreme interest to you and testing would be appreciated.

[Habbie]

Ping! We cannot fix bugs if you don't test our fixes!

[sparc]

Not sure my problem has nothing to do with wait_timeout (i ahve it set at 10 sec) as i get this error at a frequency that is usually as high as one every one or three seconds:

Backend reported permanent error which prevented lookup (GSQLBackend lookup query:Could not execute mysql statement: SELECT content,ttl,prio,type,domain_id,disabled,name,auth FROM records WHERE disabled=0 and type=? and name=?: Lost connection to MySQL server during query), aborting

this started as soon as we upgraded to version 4 and it's happening since then and the dig trick makes no difference. The database is also used by php + webserver without any problem

[Habbie]

A 10 second wait_timeout would definitely be a great way to cause this problem. Can you test the patch in #5245?

[sparc]

how can i get the path once i have the repo setup ?

[jph]

I'm getting my lab set up now, and will test this fix as soon as I'm done. I will update this comment accordingly. Thanks, and sorry for the delay.

[Habbie]

Testing packages (based on the master branch + the fixes in #5245) are now available at https://downloads.powerdns.com/autobuilt/. Browse to your flavour, then find the files with 'authsqlconnectionreset' in their name.

[iammattmartin]

I've been testing this the last few days.

Connection before was in minutes... we're now up to over a day without the same error. Looks good.

[Poil]

Hi,

Sorry, but ... I'm unable to find if 4.0.4 have this fix ?

Best regards,

[Habbie]

@Poil this fix is not in 4.0.4. It is on the master branch, and will be in 4.1.0. A release candidate for 4.1.0 should come within one or two weeks.

[TCB13]

I'm running PowerDNS Authoritative Server 4.0.3 from Debian repos so I still have this issue. Is there any workaround?

[Poil]

When I was using powerDNS, I'd configured session timeout to 1 year. (I'm no more working for the same company, I didn't keep how I did that)

[TCB13]

@Poil thanks for the tip. What is strange about this is that it only happens in zone transfers. The server is running without any issues and answering dig queries just fine, however in AXFR this error happens.

[Poil]

Yes it because the slave doesn't do a retry (and get an error when the session timed out) it comes back only after the value of the SOA if there is no a new notify (a change on the zone)

[rgacogne]

I'm running PowerDNS Authoritative Server 4.0.3 from Debian repos so I still have this issue. Is there any workaround?

Did you consider using the 4.1 packages we provide at https://repo.powerdns.com?

[hb9xar]

Running PDNS 4.0.4 as autoritative DNS server for quite a number of domains. The issue only did happens on TCP queries (UDP queries are so frequent, they don't cause the session timeout to hit).

I use the following workaround to increase the session timeout for mysql connections used by PDNS:

in /etc/my.cnf, add a section

[powerdns]
init-command='SET wait_timeout=86400'

in pdns.conf, set "gmysql-group":

#################################
# launch        Which backends to launch and order to query them in
#
# launch=
launch=gmysql
gmysql-host=<mysql host>
gmysql-user=<database user>
gmysql-password=<database password>
gmysql-dbname=<database name>
gmysql-group=powerdns

This causes pdns to read the [powerdns] section in my.cnf to set a long session timeout. In my case, 1 day was enough to also cover the less often TCP queries.

UDP and TCP queries use individual database connections (running in separate threads?), so keeping UDP alive with sufficient queries still will not fix the issue with TCP time-outs. Since the above mentioned change, I did not observe any further database connection timeouts / reconnects.

/Thomas

[TCB13]

@rgacogne so can I just pin the repos and run apt update? Anything else I should be aware of? Thank you.

[Habbie]

@rgacogne so can I just pin the repos and run apt update? Anything else I should be aware of? Thank you.

Please visit https://www.powerdns.com/opensource.html to see how you can reach us for support.

[TCB13]

@rgacogne @Habbie already upgraded. I was running as an authoritative server only, I decided to remove powerdns completely and then install version 4.1 from the repo. Placed my settings back into /etc/powerdns and everything is running fine.