Ludovic Pouzenc
2018-Dec-20 17:09 UTC
Authentication/Penalty disabled (socket mode=0) introduces constant 5 sec delays (2.27 on debian 9)
Hi, I hit a bizare problem with dovecot 2.2.7 on debian 9 with LMTP enabled and auth/penalty disabled as documented here : https://wiki.dovecot.org/Authentication/Penalty Use case : I run a swaks command to send an email to an exim4 that tries to make a callout to dovecot-lmtp. At RCPT TO: swaks hangs 5.0<something-small> seconds then process normally (exim is waiting for callout completion). with strace, I see 5 second delay with many tries to socket connection. (PID 9652 was an auth process freshly forked) [pid 9652] socket(AF_UNIX, SOCK_STREAM, 0) = 14 [pid 9652] fcntl(14, F_GETFL) = 0x2 (flags O_RDWR) [pid 9652] fcntl(14, F_SETFL, O_RDWR|O_NONBLOCK) = 0 [pid 9652] connect(14, {sa_family=AF_UNIX, sun_path="anvil-auth-penalty"}, 110) = -1 ECONNREFUSED (Connection refused) [pid 9652] close(14) = 0 [pid 9652] nanosleep({tv_sec=0, tv_nsec=20000000}, NULL) = 0 [pid 9652] socket(AF_UNIX, SOCK_STREAM, 0) = 14 [pid 9652] fcntl(14, F_GETFL) = 0x2 (flags O_RDWR) [pid 9652] fcntl(14, F_SETFL, O_RDWR|O_NONBLOCK) = 0 [pid 9652] connect(14, {sa_family=AF_UNIX, sun_path="anvil-auth-penalty"}, 110) = -1 ECONNREFUSED (Connection refused) [pid 9652] close(14) = 0 [pid 9652] nanosleep({tv_sec=0, tv_nsec=50000000}, NULL) = 0 [pid 9652] socket(AF_UNIX, SOCK_STREAM, 0) = 14 [pid 9652] fcntl(14, F_GETFL) = 0x2 (flags O_RDWR) [pid 9652] fcntl(14, F_SETFL, O_RDWR|O_NONBLOCK) = 0 [pid 9652] connect(14, {sa_family=AF_UNIX, sun_path="anvil-auth-penalty"}, 110) = -1 ECONNREFUSED (Connection refused) [pid 9652] close(14) = 0 [pid 9652] nanosleep({tv_sec=0, tv_nsec=90000000}, NULL) = 0 with ddd I get to: src/lib-master/anvil-client.c: int anvil_client_connect(struct anvil_client *client, bool retry) { //[...] fd = retry ? net_connect_unix_with_retries(client->path, 5000) : net_connect_unix(client->path); //[...] and retry is forced to TRUE by the caller and net_connect_unix_with_retries retries in case of ECONNREFUSED. How I get into it : ssh -X root at telegraphe-test apt install dovecot-dbg cd /dev/shm apt source dovecot cd dovecot-2.2.27 pidof dovecot ddd /usr/sbin/dovecot set follow-fork-mode child attach 11833 cont # Send an e-mail from swaks to exim that use transport=smtp in LMTP mode to dovecot-lmtp, press interrupt while exim is blocking after RCPT TO: (gdb) bt #0 0x00007f81528af270 in __nanosleep_nocancel () at ../sysdeps/unix/syscall-template.S:84 #1 0x00007f81528d8b84 in usleep (useconds=<optimized out>) at ../sysdeps/posix/usleep.c:32 #2 0x00007f815329368e in net_connect_unix_with_retries (path=0x562dc200ce10 <error: Cannot access memory at address 0x562dc200ce10>, msecs=msecs at entry=5000) at net.c:347 #3 0x00007f815320ce0d in anvil_client_connect (client=0x562dc200cda0, retry=retry at entry=true) at anvil-client.c:136 #4 0x0000562dc1429f5d in auth_penalty_init (path=0x562dc1451846 <error: Cannot access memory at address 0x562dc1451846>) at auth-penalty.c:37 #5 0x0000562dc1424166 in main_preinit () at main.c:202 #6 main (argc=<optimized out>, argv=<optimized out>) at main.c:396 (gdb) bt full #1 0x00007f81528d8b84 in usleep (useconds=<optimized out>) at ../sysdeps/posix/usleep.c:32 ts = {tv_sec = 0, tv_nsec = 80000000} #2 0x00007f815329368e in net_connect_unix_with_retries (path=0x562dc200ce10 <error: Cannot access memory at address 0x562dc200ce10>, msecs=msecs at entry=5000) at net.c:347 start = {tv_sec = 1545319486, tv_usec = 241864} now = {tv_sec = 1545319490, tv_usec = 198061} fd = -1 #3 0x00007f815320ce0d in anvil_client_connect (client=0x562dc200cda0, retry=retry at entry=true) at anvil-client.c:136 fd = <optimized out> __FUNCTION__ = <error reading variable __FUNCTION__ (Cannot access memory at address 0x7f81532a8260)> #4 0x0000562dc1429f5d in auth_penalty_init (path=0x562dc1451846 <error: Cannot access memory at address 0x562dc1451846>) at auth-penalty.c:37 No locals. #5 0x0000562dc1424166 in main_preinit () at main.c:202 mod_set = <error reading variable mod_set (Cannot access memory at address 0x7ffda885db80)> #6 main (argc=<optimized out>, argv=<optimized out>) at main.c:396 c = <optimized out> Backtrace stopped: Cannot access memory at address 0x7ffda885dbf8 (gdb) Code I've read : src/auth/main.c: static void main_preinit(void) if (!worker) auth_penalty = auth_penalty_init(AUTH_PENALTY_ANVIL_PATH); auth_request_stats_init(); src/auth/auth-penalty.c: struct auth_penalty *auth_penalty_init(const char *path) if (anvil_client_connect(penalty->client, TRUE) < 0) penalty->disabled = TRUE; else { src/lib-master/anvil-client.c: int anvil_client_connect(struct anvil_client *client, bool retry) fd = retry ? net_connect_unix_with_retries(client->path, 5000) : net_connect_unix(client->path); src/lib/net.c : int net_connect_unix_with_retries(const char *path, unsigned int msecs) { struct timeval start, now; int fd; if (gettimeofday(&start, NULL) < 0) i_panic("gettimeofday() failed: %m"); do { fd = net_connect_unix(path); if (fd != -1 || (errno != EAGAIN && errno != ECONNREFUSED)) // <------------------ HERE, I go into ECONNREFUSED case during 5 seconds break; /* busy. wait for a while. */ usleep(((rand() % 10) + 1) * 10000); if (gettimeofday(&now, NULL) < 0) i_panic("gettimeofday() failed: %m"); } while (timeval_diff_msecs(&now, &start) < (int)msecs); return fd; } Additionnal environment infos (mailboxes are NFS-backed) : lsb_release -a No LSB modules are available. Distributor ID: Debian Description: Debian GNU/Linux 9.2 (stretch) Release: 9.2 Codename: stretch mount | grep ^/ /dev/sda1 on / type ext4 (rw,relatime,errors=remount-ro,data=ordered) mount | grep nfs nfs1:/mail/maildir on /var/maildir type nfs (rw,relatime,vers=3,rsize=65536,wsize=65536,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=172.16.2.28,mountvers=3,mountport=635,mountproto=udp,local_lock=none,addr=172.16.2.28) nfs1:/mail on /var/mail type nfs (rw,relatime,vers=3,rsize=65536,wsize=65536,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=172.16.2.28,mountvers=3,mountport=635,mountproto=udp,local_lock=none,addr=172.16.2.28) cifs1:/homepermanents/info/lpouzenc on /home/lpouzenc type nfs (rw,nosuid,nodev,relatime,vers=3,rsize=65536,wsize=65536,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=172.16.2.29,mountvers=3,mountport=635,mountproto=udp,local_lock=none,addr=172.16.2.29) telegraphe-test:~# apt-cache policy dovecot-core dovecot-core: Install??: 1:2.2.27-3+deb9u2 Candidat?: 1:2.2.27-3+deb9u2 Table de version?: *** 1:2.2.27-3+deb9u2 500 500 http://miroir/debian stretch/main amd64 Packages 500 http://security.debian.org/debian-security stretch/updates/main amd64 Packages 100 /var/lib/dpkg/status telegraphe-test:~# dovecot -n # 2.2.27 (c0f36b0): /etc/dovecot/dovecot.conf # Pigeonhole version 0.4.16 (fed8554) doveconf: Warning: service auth { client_limit=10000 } is lower than required under max. load (10240) # OS: Linux 4.9.0-4-amd64 x86_64 Debian 9.2 nfs auth_verbose = yes default_client_limit = 10000 default_process_limit = 2048 lda_mailbox_autocreate = yes lda_mailbox_autosubscribe = yes mail_debug = yes mail_fsync = always mail_location = maildir:/var/mail/maildir/%u managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date index ihave duplicate mime foreverypart extracttext mmap_disable = yes namespace inbox { inbox = yes location mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix separator = / } passdb { driver = pam } plugin { sieve = file:/var/mail/mailconf/%1u/%u/sieve;active=/var/mail/mailconf/%1u/%u/.dovecot.sieve sieve_before = /var/mail/mailconf/global/sieve/before.d sieve_global = /var/mail/mailconf/global/sieve sieve_vacation_dont_check_recipient = yes } protocols = " imap lmtp sieve sieve" service anvil { unix_listener anvil-auth-penalty { mode = 00 } } service lmtp { inet_listener lmtp { port = 24 } } service managesieve { process_limit = 16 } ssl_cert = </etc/ssl/certs/telegraphe7_cert.pem ssl_key = # hidden, use -P to show it syslog_facility = local0 userdb { driver = passwd } verbose_proctitle = yes protocol lmtp { auth_username_format = %n mail_plugins = " sieve" } protocol imap { mail_max_userip_connections = 20 } Could you see a config tuning that keeps auth-penalty out of the way (it seems to behaves badly here, because we have perdition IMAP proxy in front, and it keeps track only of his IP and adds 2/4/8/15s delays to "random" legit clients. Could it be saved with a dedicated config entry to disable auth-penalty ? Is there solution to have auth-penalty working while having perdition IMAP proxy ? Regards, Ludovic Pouzenc -- Ludovic POUZENC - Ing?nieur Syst?me IMT Mines Albi (http://www.imt-mines-albi.fr) 81013 ALBI CT Cedex 09 - Tel : 05 63 49 33 56 -------------- next part -------------- An HTML attachment was scrubbed... URL: <https://dovecot.org/pipermail/dovecot/attachments/20181220/b2942a3b/attachment.html>
Stephan Bosch
2019-Jan-06 19:04 UTC
Authentication/Penalty disabled (socket mode=0) introduces constant 5 sec delays (2.27 on debian 9)
Op 20/12/2018 om 18:09 schreef Ludovic Pouzenc:> Hi, > > I hit a bizare problem with dovecot 2.2.7 on debian 9 with LMTP enabled and auth/penalty disabled as documented here : > https://wiki.dovecot.org/Authentication/Penalty > > Use case : I run a swaks command to send an email to an exim4 that tries to make a callout to dovecot-lmtp. > At RCPT TO: swaks hangs 5.0<something-small> seconds then process normally (exim is waiting for callout completion). > > with strace, I see 5 second delay with many tries to socket connection.The sources confirm this behavior, but only for the first connection attempt (i.e. the first 5 seconds of reconnections), which happens at auth startup (which then takes 5 seconds longer). After that, it will mark auth-penalty as disabled and it will not try connecting to it again. Is that what you're referring to? Regards, Stephan.> > (PID 9652 was an auth process freshly forked) > > [pid 9652] socket(AF_UNIX, SOCK_STREAM, 0) = 14 > [pid 9652] fcntl(14, F_GETFL) = 0x2 (flags O_RDWR) > [pid 9652] fcntl(14, F_SETFL, O_RDWR|O_NONBLOCK) = 0 > [pid 9652] connect(14, {sa_family=AF_UNIX, sun_path="anvil-auth-penalty"}, 110) = -1 ECONNREFUSED (Connection refused) > [pid 9652] close(14) = 0 > [pid 9652] nanosleep({tv_sec=0, tv_nsec=20000000}, NULL) = 0 > [pid 9652] socket(AF_UNIX, SOCK_STREAM, 0) = 14 > [pid 9652] fcntl(14, F_GETFL) = 0x2 (flags O_RDWR) > [pid 9652] fcntl(14, F_SETFL, O_RDWR|O_NONBLOCK) = 0 > [pid 9652] connect(14, {sa_family=AF_UNIX, sun_path="anvil-auth-penalty"}, 110) = -1 ECONNREFUSED (Connection refused) > [pid 9652] close(14) = 0 > [pid 9652] nanosleep({tv_sec=0, tv_nsec=50000000}, NULL) = 0 > [pid 9652] socket(AF_UNIX, SOCK_STREAM, 0) = 14 > [pid 9652] fcntl(14, F_GETFL) = 0x2 (flags O_RDWR) > [pid 9652] fcntl(14, F_SETFL, O_RDWR|O_NONBLOCK) = 0 > [pid 9652] connect(14, {sa_family=AF_UNIX, sun_path="anvil-auth-penalty"}, 110) = -1 ECONNREFUSED (Connection refused) > [pid 9652] close(14) = 0 > [pid 9652] nanosleep({tv_sec=0, tv_nsec=90000000}, NULL) = 0 > > > with ddd I get to: > src/lib-master/anvil-client.c: int anvil_client_connect(struct anvil_client *client, bool retry) { > //[...] > fd = retry ? net_connect_unix_with_retries(client->path, 5000) : net_connect_unix(client->path); > //[...] > > and retry is forced to TRUE by the caller and net_connect_unix_with_retries retries in case of ECONNREFUSED. > > > How I get into it : > > ssh -X root at telegraphe-test > > apt install dovecot-dbg > cd /dev/shm > apt source dovecot > cd dovecot-2.2.27 > pidof dovecot > ddd /usr/sbin/dovecot > set follow-fork-mode child > attach 11833 > cont > > # Send an e-mail from swaks to exim that use transport=smtp in LMTP mode to dovecot-lmtp, press interrupt while exim is blocking after RCPT TO: > > > (gdb) bt > #0 0x00007f81528af270 in __nanosleep_nocancel () at ../sysdeps/unix/syscall-template.S:84 > #1 0x00007f81528d8b84 in usleep (useconds=<optimized out>) at ../sysdeps/posix/usleep.c:32 > #2 0x00007f815329368e in net_connect_unix_with_retries (path=0x562dc200ce10 <error: Cannot access memory at address 0x562dc200ce10>, msecs=msecs at entry=5000) at net.c:347 > #3 0x00007f815320ce0d in anvil_client_connect (client=0x562dc200cda0, retry=retry at entry=true) at anvil-client.c:136 > #4 0x0000562dc1429f5d in auth_penalty_init (path=0x562dc1451846 <error: Cannot access memory at address 0x562dc1451846>) at auth-penalty.c:37 > #5 0x0000562dc1424166 in main_preinit () at main.c:202 > #6 main (argc=<optimized out>, argv=<optimized out>) at main.c:396 > > (gdb) bt full > #1 0x00007f81528d8b84 in usleep (useconds=<optimized out>) at ../sysdeps/posix/usleep.c:32 > ts = {tv_sec = 0, tv_nsec = 80000000} > #2 0x00007f815329368e in net_connect_unix_with_retries (path=0x562dc200ce10 <error: Cannot access memory at address 0x562dc200ce10>, msecs=msecs at entry=5000) at net.c:347 > start = {tv_sec = 1545319486, tv_usec = 241864} > now = {tv_sec = 1545319490, tv_usec = 198061} > fd = -1 > #3 0x00007f815320ce0d in anvil_client_connect (client=0x562dc200cda0, retry=retry at entry=true) at anvil-client.c:136 > fd = <optimized out> > __FUNCTION__ = <error reading variable __FUNCTION__ (Cannot access memory at address 0x7f81532a8260)> > #4 0x0000562dc1429f5d in auth_penalty_init (path=0x562dc1451846 <error: Cannot access memory at address 0x562dc1451846>) at auth-penalty.c:37 > No locals. > #5 0x0000562dc1424166 in main_preinit () at main.c:202 > mod_set = <error reading variable mod_set (Cannot access memory at address 0x7ffda885db80)> > #6 main (argc=<optimized out>, argv=<optimized out>) at main.c:396 > c = <optimized out> > Backtrace stopped: Cannot access memory at address 0x7ffda885dbf8 > (gdb) > > Code I've read : > > src/auth/main.c: static void main_preinit(void) > > if (!worker) > auth_penalty = auth_penalty_init(AUTH_PENALTY_ANVIL_PATH); > auth_request_stats_init(); > > src/auth/auth-penalty.c: struct auth_penalty *auth_penalty_init(const char *path) > > if (anvil_client_connect(penalty->client, TRUE) < 0) > penalty->disabled = TRUE; > else { > > src/lib-master/anvil-client.c: int anvil_client_connect(struct anvil_client *client, bool retry) > > fd = retry ? net_connect_unix_with_retries(client->path, 5000) : > net_connect_unix(client->path); > > src/lib/net.c : int net_connect_unix_with_retries(const char *path, unsigned int msecs) { > struct timeval start, now; > int fd; > > if (gettimeofday(&start, NULL) < 0) > i_panic("gettimeofday() failed: %m"); > > do { > fd = net_connect_unix(path); > if (fd != -1 || (errno != EAGAIN && errno != ECONNREFUSED)) // <------------------ HERE, I go into ECONNREFUSED case during 5 seconds > break; > > /* busy. wait for a while. */ > usleep(((rand() % 10) + 1) * 10000); > if (gettimeofday(&now, NULL) < 0) > i_panic("gettimeofday() failed: %m"); > } while (timeval_diff_msecs(&now, &start) < (int)msecs); > return fd; > } > > Additionnal environment infos (mailboxes are NFS-backed) : > > lsb_release -a > No LSB modules are available. > Distributor ID: Debian > Description: Debian GNU/Linux 9.2 (stretch) > Release: 9.2 > Codename: stretch > > > mount | grep ^/ > /dev/sda1 on / type ext4 (rw,relatime,errors=remount-ro,data=ordered) > > mount | grep nfs > nfs1:/mail/maildir on /var/maildir type nfs (rw,relatime,vers=3,rsize=65536,wsize=65536,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=172.16.2.28,mountvers=3,mountport=635,mountproto=udp,local_lock=none,addr=172.16.2.28) > nfs1:/mail on /var/mail type nfs (rw,relatime,vers=3,rsize=65536,wsize=65536,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=172.16.2.28,mountvers=3,mountport=635,mountproto=udp,local_lock=none,addr=172.16.2.28) > cifs1:/homepermanents/info/lpouzenc on /home/lpouzenc type nfs (rw,nosuid,nodev,relatime,vers=3,rsize=65536,wsize=65536,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=172.16.2.29,mountvers=3,mountport=635,mountproto=udp,local_lock=none,addr=172.16.2.29) > > > > telegraphe-test:~# apt-cache policy dovecot-core > dovecot-core: > Install??: 1:2.2.27-3+deb9u2 > Candidat?: 1:2.2.27-3+deb9u2 > Table de version?: > *** 1:2.2.27-3+deb9u2 500 > 500http://miroir/debian stretch/main amd64 Packages > 500http://security.debian.org/debian-security stretch/updates/main amd64 Packages > 100 /var/lib/dpkg/status > > telegraphe-test:~# dovecot -n > # 2.2.27 (c0f36b0): /etc/dovecot/dovecot.conf > # Pigeonhole version 0.4.16 (fed8554) > doveconf: Warning: service auth { client_limit=10000 } is lower than required under max. load (10240) > # OS: Linux 4.9.0-4-amd64 x86_64 Debian 9.2 nfs > auth_verbose = yes > default_client_limit = 10000 > default_process_limit = 2048 > lda_mailbox_autocreate = yes > lda_mailbox_autosubscribe = yes > mail_debug = yes > mail_fsync = always > mail_location = maildir:/var/mail/maildir/%u > managesieve_notify_capability = mailto > managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date index ihave duplicate mime foreverypart extracttext > mmap_disable = yes > namespace inbox { > inbox = yes > location > mailbox Drafts { > special_use = \Drafts > } > mailbox Junk { > special_use = \Junk > } > mailbox Sent { > special_use = \Sent > } > mailbox "Sent Messages" { > special_use = \Sent > } > mailbox Trash { > special_use = \Trash > } > prefix > separator = / > } > passdb { > driver = pam > } > plugin { > sieve =file:/var/mail/mailconf/%1u/%u/sieve;active=/var/mail/mailconf/%1u/%u/.dovecot.sieve > sieve_before = /var/mail/mailconf/global/sieve/before.d > sieve_global = /var/mail/mailconf/global/sieve > sieve_vacation_dont_check_recipient = yes > } > protocols = " imap lmtp sieve sieve" > service anvil { > unix_listener anvil-auth-penalty { > mode = 00 > } > } > service lmtp { > inet_listener lmtp { > port = 24 > } > } > service managesieve { > process_limit = 16 > } > ssl_cert = </etc/ssl/certs/telegraphe7_cert.pem > ssl_key = # hidden, use -P to show it > syslog_facility = local0 > userdb { > driver = passwd > } > verbose_proctitle = yes > protocol lmtp { > auth_username_format = %n > mail_plugins = " sieve" > } > protocol imap { > mail_max_userip_connections = 20 > } > > > > Could you see a config tuning that keeps auth-penalty out of the way (it seems to behaves badly here, because we have perdition IMAP proxy in front, and it keeps track only of his IP and adds 2/4/8/15s delays to "random" legit clients. > > Could it be saved with a dedicated config entry to disable auth-penalty ? > > Is there solution to have auth-penalty working while having perdition IMAP proxy ? > > Regards, > Ludovic Pouzenc > -- > Ludovic POUZENC - Ing?nieur Syst?me > IMT Mines Albi (http://www.imt-mines-albi.fr) > 81013 ALBI CT Cedex 09 - Tel : 05 63 49 33 56
Ludovic Pouzenc
2019-Jan-08 10:05 UTC
Authentication/Penalty disabled (socket mode=0) introduces constant 5 sec delays (2.27 on debian 9)
Hi, I can confirm that in the bad behavior, the 5 second delay occurs at each AUTH in our case. I think the configuration we have kill auth process at each end of AUTH (and fork a new one for next next AUTH). I think the "disable" flag is local to the process that is killed / respawned. A collegue of mine, Laurent Guerby, has found a workaround for us and it's findings seems very valuable for this ticket. We now know how to not having the troubles in our setup : by manual removing the auth-penalty socket with "rm" (or by rebooting the whole VM because the socket is in a tmpfs). The rm is needed only one time. I think now a clean reproducer of the problem is : (I go through a fairly similar one but not this exact one) * take a vanilla Debian 9 (probably not limited this particular version/distro) * make sure use have non-root local unix user account (adduser testimap for instance) * apt install dovecot-imapd * keep default config (it may need TLS certificate addition, default config make uses of auth-penalty and system auth, don't touch that now) * let it start at least one time (should be already started after install) * try at least 1 auth via IMAP (against a local unix user account * verify that auth-penalty socket exists * check with lsof if some process have opened it o Should see 1 dovecot process * change dovecot config to not use penalty o service anvil { ?? unix_listener anvil-auth-penalty { ???? mode = 00 ?? } } * restart dovecot * check if the auth-penalty socket exists o For me it persists and it seems now to be the root problem * (here you can do anything like dovecot stop / start, dovecot will never remove the auth-penalty socket by itself) * check with lsof if some process have opened it o No process * try at least 2 auth (against a a local unix user account) via IMAP o You should have 5 second penalty twice The socket open retries loop happens if the socket exists but noone "listen" on it. The socket open retries loop don't happen if the socket does not exists at all. (I think there is 1 try, the system returns non existing error, this bails out) Regards, Ludovic On 06/01/2019 20:04, Stephan Bosch wrote:> > Op 20/12/2018 om 18:09 schreef Ludovic Pouzenc: >> Hi, >> >> I hit a bizare problem with dovecot 2.2.7 on debian 9 with LMTP >> enabled and auth/penalty disabled as documented here : >> ? https://wiki.dovecot.org/Authentication/Penalty >> >> Use case : I run a swaks command to send an email to an exim4 that >> tries to make a callout to dovecot-lmtp. >> At RCPT TO: swaks hangs 5.0<something-small> seconds then process >> normally (exim is waiting for callout completion). >> >> with strace, I see 5 second delay with many tries to socket connection. > > The sources confirm this behavior, but only for the first connection > attempt (i.e. the first 5 seconds of reconnections), which happens at > auth startup (which then takes 5 seconds longer). After that, it will > mark auth-penalty as disabled and it will not try connecting to it > again. Is that what you're referring to? > > > Regards, > > Stephan. > > > > >> >> (PID 9652 was an auth process freshly forked) >> >> [pid? 9652] socket(AF_UNIX, SOCK_STREAM, 0) = 14 >> [pid? 9652] fcntl(14, F_GETFL)????????? = 0x2 (flags O_RDWR) >> [pid? 9652] fcntl(14, F_SETFL, O_RDWR|O_NONBLOCK) = 0 >> [pid? 9652] connect(14, {sa_family=AF_UNIX, >> sun_path="anvil-auth-penalty"}, 110) = -1 ECONNREFUSED (Connection >> refused) >> [pid? 9652] close(14)?????????????????? = 0 >> [pid? 9652] nanosleep({tv_sec=0, tv_nsec=20000000}, NULL) = 0 >> [pid? 9652] socket(AF_UNIX, SOCK_STREAM, 0) = 14 >> [pid? 9652] fcntl(14, F_GETFL)????????? = 0x2 (flags O_RDWR) >> [pid? 9652] fcntl(14, F_SETFL, O_RDWR|O_NONBLOCK) = 0 >> [pid? 9652] connect(14, {sa_family=AF_UNIX, >> sun_path="anvil-auth-penalty"}, 110) = -1 ECONNREFUSED (Connection >> refused) >> [pid? 9652] close(14)?????????????????? = 0 >> [pid? 9652] nanosleep({tv_sec=0, tv_nsec=50000000}, NULL) = 0 >> [pid? 9652] socket(AF_UNIX, SOCK_STREAM, 0) = 14 >> [pid? 9652] fcntl(14, F_GETFL)????????? = 0x2 (flags O_RDWR) >> [pid? 9652] fcntl(14, F_SETFL, O_RDWR|O_NONBLOCK) = 0 >> [pid? 9652] connect(14, {sa_family=AF_UNIX, >> sun_path="anvil-auth-penalty"}, 110) = -1 ECONNREFUSED (Connection >> refused) >> [pid? 9652] close(14)?????????????????? = 0 >> [pid? 9652] nanosleep({tv_sec=0, tv_nsec=90000000}, NULL) = 0 >> >> >> with ddd I get to: >> src/lib-master/anvil-client.c: int anvil_client_connect(struct >> anvil_client *client, bool retry) { >> //[...] >> fd = retry ? net_connect_unix_with_retries(client->path, 5000) : >> net_connect_unix(client->path); >> //[...] >> >> and retry is forced to TRUE by the caller and >> net_connect_unix_with_retries retries in case of ECONNREFUSED. >> >> >> How I get into it : >> >> ssh -X root at telegraphe-test >> >> apt install dovecot-dbg >> cd /dev/shm >> apt source dovecot >> cd dovecot-2.2.27 >> pidof dovecot >> ddd /usr/sbin/dovecot >> set follow-fork-mode child >> attach 11833 >> cont >> >> # Send an e-mail from swaks to exim that use transport=smtp in LMTP >> mode to dovecot-lmtp, press interrupt while exim is blocking after >> RCPT TO: >> >> >> (gdb) bt >> #0? 0x00007f81528af270 in __nanosleep_nocancel () at >> ../sysdeps/unix/syscall-template.S:84 >> #1? 0x00007f81528d8b84 in usleep (useconds=<optimized out>) at >> ../sysdeps/posix/usleep.c:32 >> #2? 0x00007f815329368e in net_connect_unix_with_retries >> (path=0x562dc200ce10 <error: Cannot access memory at address >> 0x562dc200ce10>, msecs=msecs at entry=5000) at net.c:347 >> #3? 0x00007f815320ce0d in anvil_client_connect >> (client=0x562dc200cda0, retry=retry at entry=true) at anvil-client.c:136 >> #4? 0x0000562dc1429f5d in auth_penalty_init (path=0x562dc1451846 >> <error: Cannot access memory at address 0x562dc1451846>) at >> auth-penalty.c:37 >> #5? 0x0000562dc1424166 in main_preinit () at main.c:202 >> #6? main (argc=<optimized out>, argv=<optimized out>) at main.c:396 >> >> (gdb) bt full >> #1? 0x00007f81528d8b84 in usleep (useconds=<optimized out>) at >> ../sysdeps/posix/usleep.c:32 >> ???????? ts = {tv_sec = 0, tv_nsec = 80000000} >> #2? 0x00007f815329368e in net_connect_unix_with_retries >> (path=0x562dc200ce10 <error: Cannot access memory at address >> 0x562dc200ce10>, msecs=msecs at entry=5000) at net.c:347 >> ???????? start = {tv_sec = 1545319486, tv_usec = 241864} >> ???????? now = {tv_sec = 1545319490, tv_usec = 198061} >> ???????? fd = -1 >> #3? 0x00007f815320ce0d in anvil_client_connect >> (client=0x562dc200cda0, retry=retry at entry=true) at anvil-client.c:136 >> ???????? fd = <optimized out> >> ???????? __FUNCTION__ = <error reading variable __FUNCTION__ (Cannot >> access memory at address 0x7f81532a8260)> >> #4? 0x0000562dc1429f5d in auth_penalty_init (path=0x562dc1451846 >> <error: Cannot access memory at address 0x562dc1451846>) at >> auth-penalty.c:37 >> No locals. >> #5? 0x0000562dc1424166 in main_preinit () at main.c:202 >> ???????? mod_set = <error reading variable mod_set (Cannot access >> memory at address 0x7ffda885db80)> >> #6? main (argc=<optimized out>, argv=<optimized out>) at main.c:396 >> ???????? c = <optimized out> >> Backtrace stopped: Cannot access memory at address 0x7ffda885dbf8 >> (gdb) >> >> Code I've read : >> >> src/auth/main.c: static void main_preinit(void) >> >> ???????? if (!worker) >> ???????????????? auth_penalty = >> auth_penalty_init(AUTH_PENALTY_ANVIL_PATH); >> ???????? auth_request_stats_init(); >> >> src/auth/auth-penalty.c: struct auth_penalty *auth_penalty_init(const >> char *path) >> >> ???????? if (anvil_client_connect(penalty->client, TRUE) < 0) >> ???????????????? penalty->disabled = TRUE; >> ???????? else { >> >> src/lib-master/anvil-client.c: int anvil_client_connect(struct >> anvil_client *client, bool retry) >> >> ???????? fd = retry ? net_connect_unix_with_retries(client->path, >> 5000) : >> ???????????????? net_connect_unix(client->path); >> >> src/lib/net.c : int net_connect_unix_with_retries(const char *path, >> unsigned int msecs) { >> ???????? struct timeval start, now; >> ???????? int fd; >> ???? ???????? if (gettimeofday(&start, NULL) < 0) >> ???????????????? i_panic("gettimeofday() failed: %m"); >> ???? ???????? do { >> ???????????????? fd = net_connect_unix(path); >> ???????????????? if (fd != -1 || (errno != EAGAIN && errno != >> ECONNREFUSED))? // <------------------ HERE, I go into ECONNREFUSED >> case during 5 seconds >> ???????????????????????? break; >> ???? ???????????????? /* busy. wait for a while. */ >> ???????????????? usleep(((rand() % 10) + 1) * 10000); >> ???????????????? if (gettimeofday(&now, NULL) < 0) >> ???????????????????????? i_panic("gettimeofday() failed: %m"); >> ???????? } while (timeval_diff_msecs(&now, &start) < (int)msecs); >> ???????? return fd; >> } >> >> Additionnal environment infos (mailboxes are NFS-backed) : >> >> lsb_release -a >> No LSB modules are available. >> Distributor ID:??? Debian >> Description:??? Debian GNU/Linux 9.2 (stretch) >> Release:??? 9.2 >> Codename:??? stretch >> >> >> mount | grep ^/ >> /dev/sda1 on / type ext4 (rw,relatime,errors=remount-ro,data=ordered) >> >> mount | grep nfs >> nfs1:/mail/maildir on /var/maildir type nfs >> (rw,relatime,vers=3,rsize=65536,wsize=65536,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=172.16.2.28,mountvers=3,mountport=635,mountproto=udp,local_lock=none,addr=172.16.2.28) >> nfs1:/mail on /var/mail type nfs >> (rw,relatime,vers=3,rsize=65536,wsize=65536,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=172.16.2.28,mountvers=3,mountport=635,mountproto=udp,local_lock=none,addr=172.16.2.28) >> cifs1:/homepermanents/info/lpouzenc on /home/lpouzenc type nfs >> (rw,nosuid,nodev,relatime,vers=3,rsize=65536,wsize=65536,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=172.16.2.29,mountvers=3,mountport=635,mountproto=udp,local_lock=none,addr=172.16.2.29) >> >> >> >> telegraphe-test:~# apt-cache policy dovecot-core >> dovecot-core: >> ?? Install??: 1:2.2.27-3+deb9u2 >> ?? Candidat?: 1:2.2.27-3+deb9u2 >> ? Table de version?: >> ? *** 1:2.2.27-3+deb9u2 500 >> ???????? 500http://miroir/debian? stretch/main amd64 Packages >> ???????? 500http://security.debian.org/debian-security >> stretch/updates/main amd64 Packages >> ???????? 100 /var/lib/dpkg/status >> >> telegraphe-test:~# dovecot -n >> # 2.2.27 (c0f36b0): /etc/dovecot/dovecot.conf >> # Pigeonhole version 0.4.16 (fed8554) >> doveconf: Warning: service auth { client_limit=10000 } is lower than >> required under max. load (10240) >> # OS: Linux 4.9.0-4-amd64 x86_64 Debian 9.2 nfs >> auth_verbose = yes >> default_client_limit = 10000 >> default_process_limit = 2048 >> lda_mailbox_autocreate = yes >> lda_mailbox_autosubscribe = yes >> mail_debug = yes >> mail_fsync = always >> mail_location = maildir:/var/mail/maildir/%u >> managesieve_notify_capability = mailto >> managesieve_sieve_capability = fileinto reject envelope >> encoded-character vacation subaddress comparator-i;ascii-numeric >> relational regex imap4flags copy include variables body enotify >> environment mailbox date index ihave duplicate mime foreverypart >> extracttext >> mmap_disable = yes >> namespace inbox { >> ?? inbox = yes >> ?? location >> ?? mailbox Drafts { >> ???? special_use = \Drafts >> ?? } >> ?? mailbox Junk { >> ???? special_use = \Junk >> ?? } >> ?? mailbox Sent { >> ???? special_use = \Sent >> ?? } >> ?? mailbox "Sent Messages" { >> ???? special_use = \Sent >> ?? } >> ?? mailbox Trash { >> ???? special_use = \Trash >> ?? } >> ?? prefix >> ?? separator = / >> } >> passdb { >> ?? driver = pam >> } >> plugin { >> ?? sieve >> =file:/var/mail/mailconf/%1u/%u/sieve;active=/var/mail/mailconf/%1u/%u/.dovecot.sieve >> ?? sieve_before = /var/mail/mailconf/global/sieve/before.d >> ?? sieve_global = /var/mail/mailconf/global/sieve >> ?? sieve_vacation_dont_check_recipient = yes >> } >> protocols = " imap lmtp sieve sieve" >> service anvil { >> ?? unix_listener anvil-auth-penalty { >> ???? mode = 00 >> ?? } >> } >> service lmtp { >> ?? inet_listener lmtp { >> ???? port = 24 >> ?? } >> } >> service managesieve { >> ?? process_limit = 16 >> } >> ssl_cert = </etc/ssl/certs/telegraphe7_cert.pem >> ssl_key =? # hidden, use -P to show it >> syslog_facility = local0 >> userdb { >> ?? driver = passwd >> } >> verbose_proctitle = yes >> protocol lmtp { >> ?? auth_username_format = %n >> ?? mail_plugins = " sieve" >> } >> protocol imap { >> ?? mail_max_userip_connections = 20 >> } >> >> >> >> Could you see a config tuning that keeps auth-penalty out of the way >> (it seems to behaves badly here, because we have perdition IMAP proxy >> in front, and it keeps track only of his IP and adds 2/4/8/15s delays >> to "random" legit clients. >> >> Could it be saved with a dedicated config entry to disable >> auth-penalty ? >> >> Is there solution to have auth-penalty working while having perdition >> IMAP proxy ? >> >> Regards, >> Ludovic Pouzenc >> -- >> Ludovic POUZENC - Ing?nieur Syst?me >> IMT Mines Albi? (http://www.imt-mines-albi.fr) >> 81013 ALBI CT Cedex 09 - Tel : 05 63 49 33 56-- Ludovic POUZENC - Ing?nieur Syst?me IMT Mines Albi (http://www.imt-mines-albi.fr) 81013 ALBI CT Cedex 09 - Tel : 05 63 49 33 56 -------------- next part -------------- An HTML attachment was scrubbed... URL: <https://dovecot.org/pipermail/dovecot/attachments/20190108/8500768b/attachment-0001.html>
Maybe Matching Threads
- Authentication/Penalty disabled (socket mode=0) introduces constant 5 sec delays (2.27 on debian 9)
- Authentication/Penalty disabled (socket mode=0) introduces constant 5 sec delays (2.27 on debian 9)
- dovecot 2.0 vs. SELinux
- "sieve: failed to store into mailbox 'Junk': Read-only mbox" over root_squashed NFS, lmtp : euid/egid set and access() don't mix together for me
- Handling of failed connect()s when ssh-agent is busy