[Dovecot] Dovecot 2.0.1 Quota dict timeout
Since an upgrade to 2.0.1 from 1.2.x we're seeing this on (mostly) large mailboxes (Maildir)
Sep 4 11:27:25 dovecot: dict: mysql: Connected to 192.168.dd.dd (accounts) ... Sep 4 11:27:46 kelly-a dovecot: lda(u1@example.com):): msgid=<123@xxx>: saved mail to INBOX Sep 4 11:27:47 dovecot: dict: Error: sql dict: commit failed: Not connected to database Sep 4 11:27:47 dovecot: imap(u1@example.com): Error: dict quota: Quota update failed, it's now desynced
The dict is MySQL on another server, same switch. It does appear that the quota gets out of sync. From the entries I checked an email is often being delivered shortly before the error (as above). But I also see it happen with the lda:
Sep 4 08:27:11 dovecot: pop3(u2@example.com): Disconnected: Logged out... Sep 4 08:42:48 dovecot: lda(u2@example.com): msgid=<123@aaa>: saved mail to INBOX Sep 4 08:43:26 dovecot: lda(u2@example.com): msgid=<123@bbb>: saved mail to INBOX Sep 4 08:43:26 dovecot: dict: Error: sql dict: commit failed: Not connected to database Sep 4 08:43:26 dovecot: lda(u2@example.com): Error: dict quota: Quota update failed, it's now desynced Sep 4 08:46:14 dovecot: pop3-login: Login: user=<u2@example.com>,...
This is happening on two different dovecot servers. The only thing they share is the MySQL server, but it has a load of 0.5 at peak.
Is there something that can be tuned to keep this from happening?
Possibly relevant entries from doveconf -n. Any tuning regarding dict
can be assumed as default:
maildir_very_dirty_syncs = yes mail_plugins = quota plugin { quota = dict:user:%LTd-%LTn:proxy::quota }
Thanks!
David
On Sat, 2010-09-04 at 12:17 -0700, David Jonas wrote:
Sep 4 11:27:47 dovecot: dict: Error: sql dict: commit failed: Not connected to database
Hmm. dict process thinks that all of its SQL connections are in use. Although why that happens is slightly strange, because unless you changed the defaults one process can handle only a single client connection at a time, and normally one client wouldn't be sending multiple requests simultaneously.
There is anyway a potential problem with an asynchronous SQL query not being finished when a synchronous SQL query is started. Although that's a problem only with PostgreSQL, not MySQL. Anyway, should be fixed some day..
Well, see if this helps: http://hg.dovecot.org/dovecot-2.0/rev/902f008f17cf
On 9/7/10 , Sep 7, 11:56 AM, Timo Sirainen wrote:
On Sat, 2010-09-04 at 12:17 -0700, David Jonas wrote:
Sep 4 11:27:47 dovecot: dict: Error: sql dict: commit failed: Not connected to database Hmm. dict process thinks that all of its SQL connections are in use. Although why that happens is slightly strange, because unless you changed the defaults one process can handle only a single client connection at a time, and normally one client wouldn't be sending multiple requests simultaneously. I didn't change any defaults regarding dict.
service dict { unix_listener dict { group = vmail mode = 0600 user = vmail } }
imap-login and pop3-login have "service_count = 0" , but the protocol directives only have "mail_plugins" set, e.g.:
protocol imap { mail_plugins = $mail_plugins imap_quota }
There is anyway a potential problem with an asynchronous SQL query not being finished when a synchronous SQL query is started. Although that's a problem only with PostgreSQL, not MySQL. Anyway, should be fixed some day..
Well, see if this helps: http://hg.dovecot.org/dovecot-2.0/rev/902f008f17cf The patch didn't seem to make a difference. I'm still seeing the error.
If you have any ideas on debugging I'm open to trying them. Dovecot 2.0.1 running on CentOS release 4.8 (Final) i386. MySQL AB's devel/client/shared rpms, 4.1.22. I can insert some logging probes (or whatever you like) if you give me pointers on how and where.
On Tue, 2010-09-07 at 18:07 -0700, David Jonas wrote:
Well, see if this helps: http://hg.dovecot.org/dovecot-2.0/rev/902f008f17cf The patch didn't seem to make a difference. I'm still seeing the error.
If you have any ideas on debugging I'm open to trying them. Dovecot 2.0.1 running on CentOS release 4.8 (Final) i386. MySQL AB's devel/client/shared rpms, 4.1.22. I can insert some logging probes (or whatever you like) if you give me pointers on how and where.
Try the attached patch what it logs with it?
On 9/8/10 , Sep 8, 8:05 AM, Timo Sirainen wrote:
On Tue, 2010-09-07 at 18:07 -0700, David Jonas wrote:
Well, see if this helps: http://hg.dovecot.org/dovecot-2.0/rev/902f008f17cf The patch didn't seem to make a difference. I'm still seeing the error.
If you have any ideas on debugging I'm open to trying them. Dovecot 2.0.1 running on CentOS release 4.8 (Final) i386. MySQL AB's devel/client/shared rpms, 4.1.22. I can insert some logging probes (or whatever you like) if you give me pointers on how and where.
Try the attached patch what it logs with it?
Hm, nothing extra gets logged. I'm not sure this will help, but I inserted a few more probes wherever sql_not_connected_result comes up. One fired, src/lib-sql/driver-mysql.c around line 294:
Sep 9 12:17:23 dovecot: dict: Warning: In driver_mysql_query_s, driver_mysql_do_query returned 0, query=BEGIN Sep 9 12:17:23 dovecot: dict: Error: sql dict: commit failed: Not connected to database Sep 9 12:17:23 dovecot: lda(u@example.com): Error: dict quota: Quota update failed, it's now desynced
On 9/9/10 , Sep 9, 12:23 PM, David Jonas wrote:
On 9/8/10 , Sep 8, 8:05 AM, Timo Sirainen wrote:
On Tue, 2010-09-07 at 18:07 -0700, David Jonas wrote:
Well, see if this helps: http://hg.dovecot.org/dovecot-2.0/rev/902f008f17cf The patch didn't seem to make a difference. I'm still seeing the error.
If you have any ideas on debugging I'm open to trying them. Dovecot 2.0.1 running on CentOS release 4.8 (Final) i386. MySQL AB's devel/client/shared rpms, 4.1.22. I can insert some logging probes (or whatever you like) if you give me pointers on how and where.
Try the attached patch what it logs with it?
Hm, nothing extra gets logged. I'm not sure this will help, but I inserted a few more probes wherever sql_not_connected_result comes up. One fired, src/lib-sql/driver-mysql.c around line 294:
Sep 9 12:17:23 dovecot: dict: Warning: In driver_mysql_query_s, driver_mysql_do_query returned 0, query=BEGIN Sep 9 12:17:23 dovecot: dict: Error: sql dict: commit failed: Not connected to database Sep 9 12:17:23 dovecot: lda(u@example.com): Error: dict quota: Quota update failed, it's now desynced
A little more info:
Sep 9 19:31:30 dovecot: dict: Warning: mysql_query failed, error=Lost connection to MySQL server during query, query=BEGIN
Generated from this probe in src/lib-sql/driver-mysql.c near line 219, in driver_mysql_do_query():
if (mysql_query(db->mysql, query) == 0) return 1;
/* failed */ i_warning("mysql_query failed, error=%s, query=%s", mysql_error(db->mysql), query);
On 10.9.2010, at 3.41, David Jonas wrote:
Sep 9 19:31:30 dovecot: dict: Warning: mysql_query failed, error=Lost connection to MySQL server during query, query=BEGIN
Oh, so it actually is losing connection. I thought it was because of the SQL pooling. I guess I'll need to figure out why it's not logging that error. But anyway, it doesn't then seem that the problem is Dovecot's. Something is closing your MySQL connection.
participants (2)
-
David Jonas
-
Timo Sirainen