David Jonas
2007-Jul-24 21:09 UTC
[Dovecot] Quota plugin, Maildir, dict backend loop problem
Hello, I've been working with the quota plugin(s) the past few days and have been having some real trouble. Only a few entries are appearing in the database, a couple more when I restarted dovecot. None of the current entries were being updated either. I think I've tracked it down to somewhere in the dict backend. I put in a few i_info() statements and recompiled. A few queries get through, then it seems to try the same query about three times and then no new more queries at all (the i_info is right after the allocation of the query string). I couldn't find any errors in the log. An strace of the dict pid shows the following loop. Dovecot -n to follow as well. A quick tcpdump showed a loop something like this: < SELECT current FROM quota WHERE ...> 513965019< BEGIN < INSERT INTO quota (current, ... < COMMIT> ?? (error_r appears to be (null)).. repeat .. In all my tests it appears that the quota value being set during the loop is 0, but that would be the most common case anyway. An insert query would look like this: INSERT INTO quota (current, path, username) VALUES (0, 'quota/storage', 'user at example.com') ON DUPLICATE KEY UPDATE current = current + 0; Help on what to do/try next would greatly be appreciated. Thanks, David $ strace -p 19816 epoll_wait(5, {{EPOLLIN, {u32=153555248, u64=153555248}}, {EPOLLIN, {u32=153601240, u64=153601240}}, {EPOLLIN|EPOLLHUP, {u32=153567344, u64=153567344}}}, 29, 2147483647) = 3 gettimeofday({1185308526, 494477}, {420, 0}) = 0 read(20, "Lpriv/quota/storage\n", 4044) = 20 fcntl64(9, F_SETFL, O_RDWR|O_NONBLOCK) = 0 read(9, 0x9271eb8, 8192) = -1 EAGAIN (Resource temporarily unavailable) fcntl64(9, F_SETFL, O_RDWR) = 0 setsockopt(9, SOL_SOCKET, SO_SNDTIMEO, "\2003\341\1\0\0\0\0", 8) = 0 write(9, "l\0\0\0\3SELECT current FROM quota W"..., 112) = 112 setsockopt(9, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0\0\0\0", 8) = 0 read(9, "\1\0\0\1", 4) = 4 read(9, "\1", 1) = 1 setsockopt(9, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0\0\0\0", 8) = 0 read(9, "6\0\0\2", 4) = 4 read(9, "\3def\10vpopmail\5quota\5quota\7curren"..., 54) = 54 setsockopt(9, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0\0\0\0", 8) = 0 read(9, "\1\0\0\3", 4) = 4 read(9, "\376", 1) = 1 setsockopt(9, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0\0\0\0", 8) = 0 read(9, "\n\0\0\4", 4) = 4 read(9, "\t582670292", 10) = 10 setsockopt(9, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0\0\0\0", 8) = 0 read(9, "\5\0\0\5", 4) = 4 read(9, "\376\0\0\2\0", 5) = 5 write(20, "O582670292\n", 11) = 11 read(10, "B1\nA1\tpriv/quota/storage\t-24324\n"..., 4043) = 35 fcntl64(9, F_SETFL, O_RDWR|O_NONBLOCK) = 0 read(9, 0x9271eb8, 8192) = -1 EAGAIN (Resource temporarily unavailable) fcntl64(9, F_SETFL, O_RDWR) = 0 setsockopt(9, SOL_SOCKET, SO_SNDTIMEO, "\2003\341\1\0\0\0\0", 8) = 0 write(9, "\6\0\0\0\3BEGIN", 10) = 10 setsockopt(9, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0\0\0\0", 8) = 0 read(9, "\7\0\0\1", 4) = 4 read(9, "\0\0\0\3\0\0\0", 7) = 7 fcntl64(9, F_SETFL, O_RDWR|O_NONBLOCK) = 0 read(9, 0x9271eb8, 8192) = -1 EAGAIN (Resource temporarily unavailable) fcntl64(9, F_SETFL, O_RDWR) = 0 setsockopt(9, SOL_SOCKET, SO_SNDTIMEO, "\2003\341\1\0\0\0\0", 8) = 0 write(9, "\247\0\0\0\3INSERT INTO quota (current,"..., 171) = 171 setsockopt(9, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0\0\0\0", 8) = 0 read(9, "\7\0\0\1", 4) = 4 read(9, "\0\2\0\3\0\0\0", 7) = 7 fcntl64(9, F_SETFL, O_RDWR|O_NONBLOCK) = 0 read(9, 0x9271eb8, 8192) = -1 EAGAIN (Resource temporarily unavailable) fcntl64(9, F_SETFL, O_RDWR) = 0 setsockopt(9, SOL_SOCKET, SO_SNDTIMEO, "\2003\341\1\0\0\0\0", 8) = 0 write(9, "\7\0\0\0\3COMMIT", 11) = 11 setsockopt(9, SOL_SOCKET, SO_RCVTIMEO, "\2003\341\1\0\0\0\0", 8) = 0 read(9, "\7\0\0\1", 4) = 4 read(9, "\0\0\0\2\0\0\0", 7) = 7 write(10, "O\n", 2) = 2 read(14, "", 3998) = 0 epoll_ctl(5, EPOLL_CTL_DEL, 14, {0, {u32=153567344, u64=153567344}}) = 0 close(14) = 0 epoll_wait(5, {{EPOLLIN|EPOLLHUP, {u32=153601240, u64=153601240}}}, 29, 2147483647) = 1 gettimeofday({1185308526, 500644}, {420, 0}) = 0 read(10, "", 4008) = 0 epoll_ctl(5, EPOLL_CTL_DEL, 10, {0, {u32=153601240, u64=153601240}}) = 0 close(10) = 0 epoll_wait(5, <unfinished ...> Process 19816 detached $ /usr/local/dovecot/sbin/dovecot -n # 1.0.2: /etc/dovecot.conf protocols: imap pop3 ssl_disable: yes disable_plaintext_auth: no login_dir: /usr/local/dovecot/var/run/dovecot/login login_executable(default): /usr/local/dovecot/libexec/dovecot/imap-login login_executable(imap): /usr/local/dovecot/libexec/dovecot/imap-login login_executable(pop3): /usr/local/dovecot/libexec/dovecot/pop3-login login_greeting: postoffice.no-ip.com login_log_format_elements: user=<%u@%d> method=%m rip=%r lip=%l %c login_process_per_connection: no verbose_proctitle: yes first_valid_uid: 89 maildir_stat_dirs: yes maildir_copy_with_hardlinks: yes mail_executable(default): /usr/local/dovecot/libexec/dovecot/imap mail_executable(imap): /usr/local/dovecot/libexec/dovecot/imap mail_executable(pop3): /usr/local/dovecot/libexec/dovecot/pop3 mail_plugins(default): quota imap_quota mail_plugins(imap): quota imap_quota mail_plugins(pop3): quota mail_plugin_dir(default): /usr/local/dovecot/lib/dovecot/imap mail_plugin_dir(imap): /usr/local/dovecot/lib/dovecot/imap mail_plugin_dir(pop3): /usr/local/dovecot/lib/dovecot/pop3 mail_log_prefix: %Us(%u)[%p]: pop3_uidl_format(default): pop3_uidl_format(imap): pop3_uidl_format(pop3): %f pop3_client_workarounds(default): pop3_client_workarounds(imap): pop3_client_workarounds(pop3): outlook-no-nuls oe-ns-eoh auth default: cache_size: 100 cache_ttl: 600 user: nobody username_translation: %@ username_format: %Lu verbose: yes passdb: driver: sql args: /etc/dovecot-sql.conf userdb: driver: prefetch plugin: quota: dict:storage=102400000 proxy::quotadict dict: quotadict: mysql:/etc/dovecot-dict-quota.conf $ cat /etc/dovecot-dict-quota.conf connect = host=192.168.15.25 dbname=vpopmail user=xxx password=xxx table = quota select_field = current where_field = path username_field = username $ cat /etc/redhat-release Red Hat Enterprise Linux ES release 4 (Nahant Update 5) $ rpm -qa | grep -i mysql MySQL-devel-standard-4.1.22-0.rhel4 MySQL-shared-standard-4.1.22-0.rhel4 MySQL-client-standard-4.1.22-0.rhel4 $ lsof -c dict -n COMMAND PID USER FD TYPE DEVICE SIZE NODE NAME dict 19816 root cwd DIR 8,5 4096 464289 /usr/local/dovecot/var/run/dovecot dict 19816 root rtd DIR 8,7 4096 2 / dict 19816 root txt REG 8,5 1868454 464309 /usr/local/dovecot/libexec/dovecot/dict dict 19816 root mem REG 8,7 47404 160369 /lib/libnss_files-2.3.4.so dict 19816 root mem REG 8,7 112168 160456 /lib/ld-2.3.4.so dict 19816 root mem REG 8,7 1529008 163193 /lib/tls/libc-2.3.4.so dict 19816 root mem REG 8,7 16732 165083 /lib/libdl-2.3.4.so dict 19816 root mem REG 8,7 213772 165079 /lib/tls/libm-2.3.4.so dict 19816 root mem REG 8,7 107800 165077 /lib/tls/libpthread-2.3.4.so dict 19816 root mem REG 8,7 28476 165086 /lib/libcrypt-2.3.4.so dict 19816 root mem REG 8,7 97120 165087 /lib/libnsl-2.3.4.so dict 19816 root 0r CHR 1,3 1797 /dev/null dict 19816 root 1r CHR 1,3 1797 /dev/null dict 19816 root 2w FIFO 0,7 52832717 pipe dict 19816 root 3u unix 0xf4e58180 52832640 /usr/local/dovecot/var/run/dovecot/dict-server dict 19816 root 4r CHR 1,9 466 /dev/urandom dict 19816 root 5r 0000 0,8 0 52832719 eventpoll dict 19816 root 6r FIFO 0,7 52832720 pipe dict 19816 root 7w FIFO 0,7 52832720 pipe dict 19816 root 8u unix 0xf6fac480 52884208 /usr/local/dovecot/var/run/dovecot/dict-server dict 19816 root 9u IPv4 52832745 TCP 192.168.15.55:46058->192.168.15.25:mysql (ESTABLISHED) dict 19816 root 10u unix 0xdae69240 52881759 /usr/local/dovecot/var/run/dovecot/dict-server dict 19816 root 11u unix 0xf36af680 52884148 /usr/local/dovecot/var/run/dovecot/dict-server dict 19816 root 12u unix 0xf505f6c0 52881064 /usr/local/dovecot/var/run/dovecot/dict-server dict 19816 root 13u unix 0xd5d84280 52884278 /usr/local/dovecot/var/run/dovecot/dict-server dict 19816 root 15u unix 0xd1ab9b00 52883941 /usr/local/dovecot/var/run/dovecot/dict-server dict 19816 root 16u unix 0xf6faca80 52884264 /usr/local/dovecot/var/run/dovecot/dict-server dict 19816 root 17u unix 0xf63cb1c0 52884235 /usr/local/dovecot/var/run/dovecot/dict-server
Jasper Bryant-Greene
2007-Jul-24 21:23 UTC
[Dovecot] Quota transaction bug? (was: Re: Quota plugin, Maildir, dict backend loop problem)
On Tue, Jul 24, 2007 at 02:09:23PM -0700, David Jonas wrote:> < SELECT current FROM quota WHERE ... > > 513965019 > < BEGIN > < INSERT INTO quota (current, ... > < COMMIT > > ?? (error_r appears to be (null))Unrelated to the original post, but the above would appear to be a bug to me. Because the SELECT is done before the transaction starts, the value in the INSERT which is based on the SELECT may no longer be consistent with the actual value in that table. I had a look through the code as I wanted to include a patch to move the SELECT into the transaction with this email, but I'm not familiar enough with the Dovecot codebase to find the code that performs the above SQL. If anyone can point me in the right direction I'd be happy to submit a patch. Jasper
Timo Sirainen
2007-Jul-25 03:11 UTC
[Dovecot] Quota plugin, Maildir, dict backend loop problem
On 25.7.2007, at 0.09, David Jonas wrote:> I've been working with the quota plugin(s) the past few days and have > been having some real trouble. Only a few entries are appearing in the > database, a couple more when I restarted dovecot. None of the current > entries were being updated either...> INSERT INTO quota (current, path, username) VALUES (0, 'quota/ > storage', > 'user at example.com') ON DUPLICATE KEY UPDATE current = current + 0;You do have a unique index key on path+username and nothing else, right? It worked with me last I tried.. -------------- next part -------------- A non-text attachment was scrubbed... Name: PGP.sig Type: application/pgp-signature Size: 186 bytes Desc: This is a digitally signed message part URL: <http://dovecot.org/pipermail/dovecot/attachments/20070725/fe0f3ee0/attachment-0002.bin>
David Jonas
2007-Jul-25 16:43 UTC
[Dovecot] Quota plugin, Maildir, dict backend loop problem
Timo Sirainen wrote:> On 25.7.2007, at 0.09, David Jonas wrote: > >> I've been working with the quota plugin(s) the past few days and have >> been having some real trouble. Only a few entries are appearing in the >> database, a couple more when I restarted dovecot. None of the current >> entries were being updated either. > .. >> INSERT INTO quota (current, path, username) VALUES (0, 'quota/storage', >> 'user at example.com') ON DUPLICATE KEY UPDATE current = current + 0; > > You do have a unique index key on path+username and nothing else, right?Sure do. Just like the docs.> It worked with me last I tried..I think I found the problem. I had an aggressive exported CFLAGS line from a recent memcache compile: CFLAGS="-O3 -march=pentium4 -mmmx -msse2" Recompiled after clearing CFLAGS and it seems to work fine now. Guess something important got optimized away. I'm having some other issues, like the entries being wildly inaccurate (1.6G for an account with no mail) and some updating issues. But quotas aren't overly pressing, so should I just wait for v1.1? Is v1.1alpha1 stable enough for some production time? I haven't seen much noise about it on the list. Perhaps I should toss it in the water... Thanks for your help, David