Why does metrics exporter not work anymore?
Hi,
I am trying to get the metrics exporter to work in 2.4.0, but for some reason, I do not see any connection attempts to the named http server nor do I get any errors:
$ doveconf -n
2.4.0 (daeb6bc59c): /etc/dovecot/dovecot.conf
Pigeonhole version 2.4.0 (1b2d5bb9)
OS: Linux 6.10.14-linuxkit x86_64 Debian 12.9
Hostname: b7638a15bee0
dovecot_config_version = 2.4.0 auth_allow_cleartext = yes auth_cache_verify_password_with_worker = yes auth_failure_delay = 0 secs auth_mechanisms = auth_mechanisms { plain = yes login = yes } auth_username_format = %{user | username | lower} debug_log_path = /dev/stdout default_internal_group = vmail default_internal_user = vmail default_login_user = vmail dovecot_storage_version = 2.4.0 first_valid_uid = 1000 imap_id_retain = yes info_log_path = /dev/stdout last_valid_uid = 1000 listen = listen {
- = yes } lmtp_proxy = yes log_path = /dev/stdout mail_debug = yes mail_driver = sdbox mail_gid = vmail mail_home = /srv/mail/%Ln mail_path = ~/Mail mail_uid = vmail protocols { imap = yes pop3 = yes lmtp = yes } ssl = no verbose_proctitle = yes namespace inbox { inbox = yes separator = / } service lmtp { inet_listener lmtp { port = 24 ssl = no } } service imap-login { client_limit = 100 process_min_avail = 1 restart_request_count = unlimited inet_listener imap { port = 143 } } service pop3-login { client_limit = 100 process_min_avail = 1 restart_request_count = unlimited inet_listener pop3 { port = 110 } } event_exporter log { driver = log format = json time_format = rfc3339 } event_exporter conn_state { driver = http-post format = json http_post_url = http://nauthilus:8080/api/v1/custom/dovecot-session-cleaner time_format = rfc3339 http_client_request_absolute_timeout = 5sec } metric client_disconnect_http { exporter = conn_state exporter_include = exporter_include { name = yes hostname = yes timestamps = yes categories = yes fields = yes } filter = event=mail_user_session_finished AND (category=imap OR category=pop3 OR category=lmtp OR category=sieve) } metric imap_noop { exporter = conn_state exporter_include = exporter_include { name = yes hostname = yes timestamps = yes categories = yes fields = yes } filter = event=imap_command_finished AND cmd_name=NOOP } passdb lua { lua_file = /etc/dovecot/auth.lua } userdb prefetch { } userdb lua { auth_verbose = no lua_file = /etc/dovecot/auth.lua result_failure = return-fail result_internalfail = return-fail result_success = continue-ok skip = never }
It is an example Docker setup found here:
https://github.com/croessner/nauthilus-demo
There are no error logs in dovecot.
Thanks in advance
Christian Rößner
Rößner-Network-Solutions Zertifizierter ITSiBe / CISO Marburger Str. 70a, 36304 Alsfeld Fax: +49 6631 78823409, Mobil: +49 171 9905345 USt-IdNr.: DE225643613, https://roessner.website PGP fingerprint: 658D 1342 B762 F484 2DDF 1E88 38A5 4346 D727 94E5
Hi,
Am 27.01.2025 um 15:42 schrieb Armin Tüting via dovecot <dovecot@dovecot.org>:
On Mon, 2025-01-27 at 14:50 +0100, Christian Rößner via dovecot wrote:
mail_home = /srv/mail/%Ln This can't be right.
Yes, that was wrong (thank you), but not causing any issues. I fixed it, but still no events...
Christian Rößner
Rößner-Network-Solutions Zertifizierter ITSiBe / CISO Marburger Str. 70a, 36304 Alsfeld Fax: +49 6631 78823409, Mobil: +49 171 9905345 USt-IdNr.: DE225643613, https://roessner.website PGP fingerprint: 658D 1342 B762 F484 2DDF 1E88 38A5 4346 D727 94E5
I double checked with settings from 2.3.21. The old version is working. The new one does not.
So I update this question to be a bug.
Thanks
Christian
Am 27.01.2025 um 14:50 schrieb Christian Rößner via dovecot <dovecot@dovecot.org>:
Hi,
I am trying to get the metrics exporter to work in 2.4.0, but for some reason, I do not see any connection attempts to the named http server nor do I get any errors:
$ doveconf -n
2.4.0 (daeb6bc59c): /etc/dovecot/dovecot.conf
Pigeonhole version 2.4.0 (1b2d5bb9)
OS: Linux 6.10.14-linuxkit x86_64 Debian 12.9
Hostname: b7638a15bee0
dovecot_config_version = 2.4.0 auth_allow_cleartext = yes auth_cache_verify_password_with_worker = yes auth_failure_delay = 0 secs auth_mechanisms = auth_mechanisms { plain = yes login = yes } auth_username_format = %{user | username | lower} debug_log_path = /dev/stdout default_internal_group = vmail default_internal_user = vmail default_login_user = vmail dovecot_storage_version = 2.4.0 first_valid_uid = 1000 imap_id_retain = yes info_log_path = /dev/stdout last_valid_uid = 1000 listen = listen {
- = yes } lmtp_proxy = yes log_path = /dev/stdout mail_debug = yes mail_driver = sdbox mail_gid = vmail mail_home = /srv/mail/%Ln mail_path = ~/Mail mail_uid = vmail protocols { imap = yes pop3 = yes lmtp = yes } ssl = no verbose_proctitle = yes namespace inbox { inbox = yes separator = / } service lmtp { inet_listener lmtp { port = 24 ssl = no } } service imap-login { client_limit = 100 process_min_avail = 1 restart_request_count = unlimited inet_listener imap { port = 143 } } service pop3-login { client_limit = 100 process_min_avail = 1 restart_request_count = unlimited inet_listener pop3 { port = 110 } } event_exporter log { driver = log format = json time_format = rfc3339 } event_exporter conn_state { driver = http-post format = json http_post_url = http://nauthilus:8080/api/v1/custom/dovecot-session-cleaner time_format = rfc3339 http_client_request_absolute_timeout = 5sec } metric client_disconnect_http { exporter = conn_state exporter_include = exporter_include { name = yes hostname = yes timestamps = yes categories = yes fields = yes } filter = event=mail_user_session_finished AND (category=imap OR category=pop3 OR category=lmtp OR category=sieve) } metric imap_noop { exporter = conn_state exporter_include = exporter_include { name = yes hostname = yes timestamps = yes categories = yes fields = yes } filter = event=imap_command_finished AND cmd_name=NOOP } passdb lua { lua_file = /etc/dovecot/auth.lua } userdb prefetch { } userdb lua { auth_verbose = no lua_file = /etc/dovecot/auth.lua result_failure = return-fail result_internalfail = return-fail result_success = continue-ok skip = never }
It is an example Docker setup found here:
https://github.com/croessner/nauthilus-demo
There are no error logs in dovecot.
Thanks in advance
Christian Rößner
Rößner-Network-Solutions Zertifizierter ITSiBe / CISO Marburger Str. 70a, 36304 Alsfeld Fax: +49 6631 78823409, Mobil: +49 171 9905345 USt-IdNr.: DE225643613, https://roessner.website PGP fingerprint: 658D 1342 B762 F484 2DDF 1E88 38A5 4346 D727 94E5
dovecot mailing list -- dovecot@dovecot.org To unsubscribe send an email to dovecot-leave@dovecot.org
Christian Rößner
Rößner-Network-Solutions Zertifizierter ITSiBe / CISO Marburger Str. 70a, 36304 Alsfeld Fax: +49 6631 78823409, Mobil: +49 171 9905345 USt-IdNr.: DE225643613, https://roessner.website PGP fingerprint: 658D 1342 B762 F484 2DDF 1E88 38A5 4346 D727 94E5
On 27. Jan 2025, at 15.50, Christian Rößner via dovecot <dovecot@dovecot.org> wrote:
event_exporter conn_state { driver = http-post format = json http_post_url = http://nauthilus:8080/api/v1/custom/dovecot-session-cleaner time_format = rfc3339 http_client_request_absolute_timeout = 5sec } metric client_disconnect_http { exporter = conn_state exporter_include = exporter_include { name = yes hostname = yes timestamps = yes categories = yes fields = yes } filter = event=mail_user_session_finished AND (category=imap OR category=pop3 OR category=lmtp OR category=sieve) } metric imap_noop { exporter = conn_state exporter_include = exporter_include { name = yes hostname = yes timestamps = yes categories = yes fields = yes } filter = event=imap_command_finished AND cmd_name=NOOP }
These seem to work fine with me. I copy&pasted them to my config except changed it to connect to localhost. Then did a test session:
% nc localhost 143
- OK [CAPABILITY IMAP4rev1 LOGIN-REFERRALS ID ENABLE IDLE SASL-IR LITERAL+ STARTTLS AUTH=PLAIN] Dovecot ready. x login tss pass x OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE SNIPPET=FUZZY PREVIEW=FUZZY PREVIEW STATUS=SIZE SAVEDATE COMPRESS=DEFLATE INPROGRESS NOTIFY SPECIAL-USE LITERAL+] Logged in x select inbox
- FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
- OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \*)] Flags permitted.
- 0 EXISTS
- 0 RECENT
- OK [UIDVALIDITY 1738009228] UIDs valid
- OK [UIDNEXT 1] Predicted next UID x OK [READ-WRITE] Select completed (0.008 + 0.000 + 0.008 secs). x noop x OK NOOP completed (0.001 + 0.000 secs). x logout
- BYE Logging out x OK Logout completed (0.001 + 0.000 secs).
It tried to connect on NOOP and LOGOUT commands as expected:
2025-01-27T22:20:25.683680+02:00 ubuntu dovecot: imap-login: Logged in: user=<tss>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=1297445, secured, session=<Z3VrzrUszs5/AAAB> 2025-01-27T22:20:29.252767+02:00 ubuntu dovecot: stats: Error: Failed to export event via HTTP POST: 9003 connect(127.0.0.1:8080) failed: Connection refused 2025-01-27T22:20:48.469938+02:00 ubuntu dovecot: imap(tss)<1297445><Z3VrzrUszs5/AAAB>: Disconnected: Logged out in=30 out=858 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 2025-01-27T22:20:48.470406+02:00 ubuntu dovecot: stats: Error: Failed to export event via HTTP POST: 9003 connect(127.0.0.1:8080) failed: Connection refused
Am 27.01.2025 um 21:22 schrieb Timo Sirainen via dovecot <dovecot@dovecot.org>:
On 27. Jan 2025, at 15.50, Christian Rößner via dovecot <dovecot@dovecot.org> wrote:
event_exporter conn_state { driver = http-post format = json http_post_url = http://nauthilus:8080/api/v1/custom/dovecot-session-cleaner time_format = rfc3339 http_client_request_absolute_timeout = 5sec } metric client_disconnect_http { exporter = conn_state exporter_include = exporter_include { name = yes hostname = yes timestamps = yes categories = yes fields = yes } filter = event=mail_user_session_finished AND (category=imap OR category=pop3 OR category=lmtp OR category=sieve) } metric imap_noop { exporter = conn_state exporter_include = exporter_include { name = yes hostname = yes timestamps = yes categories = yes fields = yes } filter = event=imap_command_finished AND cmd_name=NOOP }
These seem to work fine with me. I copy&pasted them to my config except changed it to connect to localhost. Then did a test session:
% nc localhost 143
- OK [CAPABILITY IMAP4rev1 LOGIN-REFERRALS ID ENABLE IDLE SASL-IR LITERAL+ STARTTLS AUTH=PLAIN] Dovecot ready. x login tss pass x OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE SNIPPET=FUZZY PREVIEW=FUZZY PREVIEW STATUS=SIZE SAVEDATE COMPRESS=DEFLATE INPROGRESS NOTIFY SPECIAL-USE LITERAL+] Logged in x select inbox
- FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
- OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \*)] Flags permitted.
- 0 EXISTS
- 0 RECENT
- OK [UIDVALIDITY 1738009228] UIDs valid
- OK [UIDNEXT 1] Predicted next UID x OK [READ-WRITE] Select completed (0.008 + 0.000 + 0.008 secs). x noop x OK NOOP completed (0.001 + 0.000 secs). x logout
- BYE Logging out x OK Logout completed (0.001 + 0.000 secs).
It tried to connect on NOOP and LOGOUT commands as expected:
2025-01-27T22:20:25.683680+02:00 ubuntu dovecot: imap-login: Logged in: user=<tss>, method=PLAIN, rip=127.0.0.1, lip=127.0.0.1, mpid=1297445, secured, session=<Z3VrzrUszs5/AAAB> 2025-01-27T22:20:29.252767+02:00 ubuntu dovecot: stats: Error: Failed to export event via HTTP POST: 9003 connect(127.0.0.1:8080) failed: Connection refused 2025-01-27T22:20:48.469938+02:00 ubuntu dovecot: imap(tss)<1297445><Z3VrzrUszs5/AAAB>: Disconnected: Logged out in=30 out=858 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 2025-01-27T22:20:48.470406+02:00 ubuntu dovecot: stats: Error: Failed to export event via HTTP POST: 9003 connect(127.0.0.1:8080) failed: Connection refused
dovecot mailing list -- dovecot@dovecot.org To unsubscribe send an email to dovecot-leave@dovecot.org
And here is the same from my system:
The "director"-part (I know there does not exist a director anymore. Nauthilus replaces it in some way concerning the server-part of Dovecot):
director | Jan 28 09:23:48 auth-worker(94): Info: request=passdb protocol=imap proxy_host=backend-1 auth_status_code=200 auth_status_message=<OK> nauthilus_session=2sFfQiOh7OJYFYbFu11OnEVrCAx director | Jan 28 09:23:48 imap-login: Info: proxy(testaccount,backend-1[172.22.0.5]:143): Started proxying to remote host (0.015 secs): user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.3, session=<JYRzv8As/PasFgAB> director | Jan 28 09:24:02 imap-login: Info: proxy(testaccount,backend-1[172.22.0.5]:143): Disconnected by server (0s idle, in=298, out=1019): user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.3, session=<JYRzv8As/PasFgAB>
The tshark-Output from the same container:
69 405.512799379 172.22.0.3 → 172.22.0.4 HTTP 525 POST /api/v1/auth/header HTTP/1.1 71 405.517035967 172.22.0.4 → 172.22.0.3 HTTP 335 HTTP/1.1 200 OK
Do connection to /api/v1/custom/dovecot-session-cleaner As configured in the event exporter.
From my computer testing it:
telnet localhost 1430 Trying 127.0.0.1... Connected to localhost.localdomain. Escape character is '^]'.
- OK [CAPABILITY IMAP4rev1 LOGIN-REFERRALS ID ENABLE IDLE SASL-IR LITERAL+ AUTH=PLAIN AUTH=LOGIN] Dovecot ready. . login testuser testpassword . OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE SNIPPET=FUZZY PREVIEW=FUZZY PREVIEW STATUS=SIZE SAVEDATE COMPRESS=DEFLATE INPROGRESS NOTIFY LITERAL+ UTF8=ACCEPT FILTER=SIEVE] Logged in . select inbox
- FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
- OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft \*)] Flags permitted.
- 39 EXISTS
- 0 RECENT
- OK [UNSEEN 13] First unseen.
- OK [UIDVALIDITY 1737973265] UIDs valid
- OK [UIDNEXT 40] Predicted next UID . OK [READ-WRITE] Select completed (0.001 + 0.000 + 0.001 secs). . noop . OK NOOP completed (0.001 + 0.000 secs). . logout
- BYE Logging out . OK Logout completed (0.001 + 0.000 secs). Connection closed by foreign host.
For testing the connection with tshark, I copied your Dockerfile from Github and added tshark.
Could it be something with the official docker image?
Christian Rößner
Rößner-Network-Solutions Zertifizierter ITSiBe / CISO Marburger Str. 70a, 36304 Alsfeld Fax: +49 6631 78823409, Mobil: +49 171 9905345 USt-IdNr.: DE225643613, https://roessner.website PGP fingerprint: 658D 1342 B762 F484 2DDF 1E88 38A5 4346 D727 94E5
Am 28.01.2025 um 10:30 schrieb Christian Rößner <lists@mlserv.org>:
Do connection to /api/v1/custom/dovecot-session-cleaner
Not Do! I mean No!
Christian Rößner
Rößner-Network-Solutions Zertifizierter ITSiBe / CISO Marburger Str. 70a, 36304 Alsfeld Fax: +49 6631 78823409, Mobil: +49 171 9905345 USt-IdNr.: DE225643613, https://roessner.website PGP fingerprint: 658D 1342 B762 F484 2DDF 1E88 38A5 4346 D727 94E5
On 28. Jan 2025, at 11.30, Christian Rößner via dovecot <dovecot@dovecot.org> wrote:
director | Jan 28 09:23:48 auth-worker(94): Info: request=passdb protocol=imap proxy_host=backend-1 auth_status_code=200 auth_status_message=<OK> nauthilus_session=2sFfQiOh7OJYFYbFu11OnEVrCAx director | Jan 28 09:23:48 imap-login: Info: proxy(testaccount,backend-1[172.22.0.5]:143): Started proxying to remote host (0.015 secs): user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.3, session=<JYRzv8As/PasFgAB> director | Jan 28 09:24:02 imap-login: Info: proxy(testaccount,backend-1[172.22.0.5]:143): Disconnected by server (0s idle, in=298, out=1019): user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.3, session=<JYRzv8As/PasFgAB>
Try adding to dovecot.conf:
log_debug = category=debug
and see what it logs.
On 28. Jan 2025, at 13.43, Timo Sirainen <timo@sirainen.com> wrote:
On 28. Jan 2025, at 11.30, Christian Rößner via dovecot <dovecot@dovecot.org> wrote:
director | Jan 28 09:23:48 auth-worker(94): Info: request=passdb protocol=imap proxy_host=backend-1 auth_status_code=200 auth_status_message=<OK> nauthilus_session=2sFfQiOh7OJYFYbFu11OnEVrCAx director | Jan 28 09:23:48 imap-login: Info: proxy(testaccount,backend-1[172.22.0.5]:143): Started proxying to remote host (0.015 secs): user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.3, session=<JYRzv8As/PasFgAB> director | Jan 28 09:24:02 imap-login: Info: proxy(testaccount,backend-1[172.22.0.5]:143): Disconnected by server (0s idle, in=298, out=1019): user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.3, session=<JYRzv8As/PasFgAB>
Try adding to dovecot.conf:
log_debug = category=debug
and see what it logs.
Hmm. Actually looking at this again, those log messages are from proxy. The events you configured are only sent by backend.
Am 28.01.2025 um 12:43 schrieb Timo Sirainen via dovecot <dovecot@dovecot.org>:
log_debug = category=debug
Here is the debug output:
director | Jan 28 12:38:18 master: Info: Dovecot v2.4.0 (daeb6bc59c) starting up for imap, pop3, lmtp (core dumps disabled) director | Jan 28 12:38:18 imap-login: Debug: conn unix:stats-writer: Connecting director | Jan 28 12:38:18 imap-login: Debug: conn unix:stats-writer (pid=7,uid=1000): Client connected (fd=10) director | Jan 28 12:38:18 imap-login: Debug: conn unix:stats-writer (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:18 pop3-login: Debug: conn unix:stats-writer: Connecting director | Jan 28 12:38:18 pop3-login: Debug: conn unix:stats-writer (pid=7,uid=1000): Client connected (fd=10) director | Jan 28 12:38:18 pop3-login: Debug: conn unix:stats-writer (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:18 anvil: Debug: conn anvil: Server accepted connection (fd=8) director | Jan 28 12:38:18 anvil: Debug: conn anvil: Server accepted connection (fd=9) director | Jan 28 12:38:18 stats: Debug: conn unix:stats (pid=9,uid=1000): Server accepted connection (fd=13) director | Jan 28 12:38:18 stats: Debug: conn unix:stats (pid=9,uid=1000): Sending version handshake director | Jan 28 12:38:18 stats: Debug: conn unix:stats (pid=10,uid=1000): Server accepted connection (fd=14) director | Jan 28 12:38:18 stats: Debug: conn unix:stats (pid=10,uid=1000): Sending version handshake director | Jan 28 12:38:18 imap-login: Debug: conn unix:anvil: Connecting director | Jan 28 12:38:18 imap-login: Debug: conn unix:anvil (pid=7,uid=1000): Client connected (fd=12) director | Jan 28 12:38:18 imap-login: Debug: conn unix:anvil (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:18 pop3-login: Debug: conn unix:anvil: Connecting director | Jan 28 12:38:18 pop3-login: Debug: conn unix:anvil (pid=7,uid=1000): Client connected (fd=12) director | Jan 28 12:38:18 pop3-login: Debug: conn unix:anvil (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:18 anvil: Debug: conn unix:anvil (pid=9,uid=1000): Server accepted connection (fd=15) director | Jan 28 12:38:18 anvil: Debug: conn unix:anvil (pid=10,uid=1000): Server accepted connection (fd=16) director | Jan 28 12:38:18 pop3-login: Debug: auth-client: conn unix:login: Connecting director | Jan 28 12:38:18 pop3-login: Debug: auth-client: conn unix:login (pid=7,uid=1000): Client connected (fd=13) director | Jan 28 12:38:18 imap-login: Debug: auth-client: conn unix:login: Connecting director | Jan 28 12:38:18 imap-login: Debug: auth-client: conn unix:login (pid=7,uid=1000): Client connected (fd=13) director | Jan 28 12:38:18 auth: Debug: conn unix:/run/dovecot/stats-writer: Connecting director | Jan 28 12:38:18 auth: Debug: conn unix:/run/dovecot/stats-writer (pid=7,uid=1000): Client connected (fd=7) director | Jan 28 12:38:18 auth: Debug: conn unix:/run/dovecot/stats-writer (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:18 stats: Debug: conn unix:stats (pid=15,uid=1000): Server accepted connection (fd=15) director | Jan 28 12:38:18 stats: Debug: conn unix:stats (pid=15,uid=1000): Sending version handshake director | Jan 28 12:38:18 auth: Debug: conn unix:anvil-auth-penalty: Connecting director | Jan 28 12:38:18 auth: Debug: conn unix:anvil-auth-penalty (pid=7,uid=1000): Client connected (fd=15) director | Jan 28 12:38:18 auth: Debug: conn unix:anvil-auth-penalty (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:18 anvil: Debug: conn unix:anvil (pid=15,uid=1000): Server accepted connection (fd=17) director | Jan 28 12:38:18 auth: Debug: Wrote new auth token secret to /run/dovecot/auth-token-secret.dat director | Jan 28 12:38:18 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: Server accepted connection (fd=18) director | Jan 28 12:38:18 auth: Debug: conn unix:login (pid=10,uid=1000) [2]: Server accepted connection (fd=19) director | Jan 28 12:38:18 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: auth client connected (pid=9) director | Jan 28 12:38:18 auth: Debug: conn unix:login (pid=10,uid=1000) [2]: auth client connected (pid=10) director | Jan 28 12:38:50 imap-login: Debug: auth-client: request [1]: Started request director | Jan 28 12:38:50 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: client in: AUTH 1 PLAIN protocol=imap final-resp-ok session=KEaTecMsQvasFgAB lip=172.22.0.5rip=172.22.0.1 lport=143 rport=63042 director | Jan 28 12:38:50 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: client passdb out: CONT 1 director | Jan 28 12:38:50 imap-login: Debug: auth-client: conn unix:login (pid=7,uid=1000): auth input: CONT 1 director | Jan 28 12:38:50 imap-login: Debug: auth-client: request [1]: Got challenge director | Jan 28 12:38:50 imap-login: Debug: auth-client: request [1]: Continue request director | Jan 28 12:38:50 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: client in: CONT<hidden> director | Jan 28 12:38:50 auth(testuser,172.22.0.1,sasl:plain)<KEaTecMsQvasFgAB>: Debug: lua: Performing passdb lookup director | Jan 28 12:38:50 auth: Debug: conn unix:auth-worker: Connecting director | Jan 28 12:38:50 auth: Debug: conn unix:auth-worker (pid=7,uid=1000): Client connected (fd=20) director | Jan 28 12:38:50 auth: Debug: conn unix:auth-worker (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:50 auth-worker: Debug: conn unix:/run/dovecot/stats-writer: Connecting director | Jan 28 12:38:50 auth-worker: Debug: conn unix:/run/dovecot/stats-writer (pid=7,uid=1000): Client connected (fd=7) director | Jan 28 12:38:50 auth-worker: Debug: conn unix:/run/dovecot/stats-writer (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:50 stats: Debug: conn unix:stats (pid=16,uid=1000): Server accepted connection (fd=16) director | Jan 28 12:38:50 stats: Debug: conn unix:stats (pid=16,uid=1000): Sending version handshake director | Jan 28 12:38:50 auth-worker(16): Debug: conn unix:auth-worker (pid=15,uid=1000): Server accepted connection (fd=12) director | Jan 28 12:38:50 auth-worker(16): Debug: conn unix:auth-worker (pid=15,uid=1000): Sending version handshake director | Jan 28 12:38:50 auth-worker(16): Debug: conn unix:auth-worker (pid=15,uid=1000): auth-worker<1>: Handling PASSV request director | Jan 28 12:38:50 auth-worker(testuser,172.22.0.1)<16><KEaTecMsQvasFgAB>: request [1]: Debug: lua: Performing passdb lookup director | Jan 28 12:38:50 auth-worker(testuser,172.22.0.1)<16><KEaTecMsQvasFgAB>: request [1]: Debug: lua: Calling auth_password_verify director | Jan 28 12:38:50 auth: Debug: auth-worker: Worker sent process limit '30' director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: Host created director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: Host session created director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: Need to perform DNS lookup director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: Performing asynchronous DNS lookup director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: conn unix:/run/dovecot/dns-client: dns(nauthilus): Lookup started director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: conn unix:/run/dovecot/dns-client: Connecting director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: conn unix:/run/dovecot/dns-client (pid=7,uid=1000): Client connected (fd=8) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: conn unix:/run/dovecot/dns-client (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: request [Req1: POST http://nauthilus:8080/api/v1/auth/header]: Submitted (requests left=1) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: Waiting for 1 requests to finish director | Jan 28 12:38:50 dns-client: Debug: conn unix:/run/dovecot/stats-writer: Connecting director | Jan 28 12:38:50 dns-client: Debug: conn unix:/run/dovecot/stats-writer (pid=7,uid=1000): Client connected (fd=7) director | Jan 28 12:38:50 dns-client: Debug: conn unix:/run/dovecot/stats-writer (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:50 stats: Debug: conn unix:stats (pid=17,uid=1000): Server accepted connection (fd=17) director | Jan 28 12:38:50 stats: Debug: conn unix:stats (pid=17,uid=1000): Sending version handshake director | Jan 28 12:38:50 dns-client: Debug: conn unix:dns-client (pid=16,uid=1000): Server accepted connection (fd=13) director | Jan 28 12:38:50 dns-client: Debug: conn unix:dns-client (pid=16,uid=1000): Sending version handshake director | Jan 28 12:38:50 dns-client: Debug: conn unix:dns-client (pid=16,uid=1000): nauthilus: Resolving director | Jan 28 12:38:50 dns-client: Debug: conn unix:dns-client (pid=16,uid=1000): nauthilus: Resolve success: 172.22.0.4 director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: conn unix:/run/dovecot/dns-client (pid=7,uid=1000): dns(nauthilus): Lookup successful after 4 msecs director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: DNS lookup successful; got 1 IPs director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: peer 172.22.0.4:8080 (shared): Peer created director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: peer 172.22.0.4:8080: Peer pool created director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Peer created director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: queue http://nauthilus:8080: Setting up connection to 172.22.0.4:8080 (1 requests pending) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Linked queue http://nauthilus:8080 (1 queues linked) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: queue http://nauthilus:8080: Started new connection to 172.22.0.4:8080 director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: conn unix:/run/dovecot/dns-client (pid=7,uid=1000): Disconnected: Connection closed (fd=8) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: conn unix:/run/dovecot/dns-client (pid=7,uid=1000): Disconnect: deinit director | Jan 28 12:38:50 dns-client: Debug: conn unix:dns-client (pid=16,uid=1000): Disconnected: Connection closed (fd=13) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Creating 1 new connections to handle requests (already 0 usable, connecting to 0, closing 0) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Making new connection 1 of 1 (0 connections exist, 0 pending) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Connecting director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Waiting for connect (fd=8) to finish for max 0 msecs director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: HTTP connection created (1 parallel connections exist) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Client connected (fd=8) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Connected director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Ready for requests director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Successfully connected (1 connections exist, 0 pending) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: peer 172.22.0.4:8080: Successfully connected (1 connections exist, 0 pending) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Using 1 idle connections to handle 1 requests (1 total connections ready) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: queue http://nauthilus:8080: Connection to peer 172.22.0.4:8080 claimed request [Req1: POST http://nauthilus:8080/api/v1/auth/header] director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Claimed request [Req1: POST http://nauthilus:8080/api/v1/auth/header] director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: request [Req1: POST http://nauthilus:8080/api/v1/auth/header]: Sent header director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: No more requests to service for this peer (1 connections exist, 0 pending) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Got 200 response for request [Req1: POST http://nauthilus:8080/api/v1/auth/header]: OK (took 5 ms + 6 ms in queue) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: request [Req1: POST http://nauthilus:8080/api/v1/auth/header]: Finished director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: queue http://nauthilus:8080: Dropping request [Req1: POST http://nauthilus:8080/api/v1/auth/header] director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: Host is idle (timeout = 1799993 msecs) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: request [Req1: POST http://nauthilus:8080/api/v1/auth/header]: Free (requests left=1) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: All requests finished director | Jan 28 12:38:50 auth-worker(16): Info: request=passdb protocol=imap proxy_host=backend-1 auth_status_code=200 auth_status_message=<OK> nauthilus_session=2sG39Fb74g18mD1jl7DegMz9TDL director | Jan 28 12:38:50 auth-worker(testuser,172.22.0.1)<16><KEaTecMsQvasFgAB>: request [1]: Debug: lua: username changed testuser -> testaccount director | Jan 28 12:38:50 auth-worker(testaccount,172.22.0.1)<16><KEaTecMsQvasFgAB>: request [1]: Debug: lua: Finished passdb lookup director | Jan 28 12:38:50 auth-worker(16): Debug: conn unix:auth-worker (pid=15,uid=1000): auth-worker<1>: Finished director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: No requests to service for this peer (1 connections exist, 0 pending) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: No more requests queued; going idle director | Jan 28 12:38:50 auth(testuser,172.22.0.1,sasl:plain)<KEaTecMsQvasFgAB>: Debug: lua: username changed testuser -> testaccount director | Jan 28 12:38:50 auth(testaccount,172.22.0.1,sasl:plain)<KEaTecMsQvasFgAB>: Debug: lua: Finished passdb lookup director | Jan 28 12:38:50 auth(testaccount,172.22.0.1,sasl:plain)<KEaTecMsQvasFgAB>: Debug: Auth request finished director | Jan 28 12:38:50 auth(testaccount,172.22.0.1,sasl:plain)<KEaTecMsQvasFgAB>: Debug: proxy: dns(backend-1): Lookup started director | Jan 28 12:38:50 auth: Debug: conn unix:dns-client: Connecting director | Jan 28 12:38:50 auth: Debug: conn unix:dns-client (pid=7,uid=1000): Client connected (fd=21) director | Jan 28 12:38:50 auth: Debug: conn unix:dns-client (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:50 dns-client: Debug: conn unix:dns-client (pid=15,uid=1000): Server accepted connection (fd=13) director | Jan 28 12:38:50 dns-client: Debug: conn unix:dns-client (pid=15,uid=1000): Sending version handshake director | Jan 28 12:38:50 dns-client: Debug: conn unix:dns-client (pid=15,uid=1000): backend-1: Resolving director | Jan 28 12:38:50 dns-client: Debug: conn unix:dns-client (pid=15,uid=1000): backend-1: Resolve success: 172.22.0.3 director | Jan 28 12:38:50 auth(testaccount,172.22.0.1,sasl:plain)<KEaTecMsQvasFgAB>: Debug: proxy: dns(backend-1): Lookup successful after 0 msecs director | Jan 28 12:38:50 imap-login: Debug: auth-client: conn unix:login (pid=7,uid=1000): auth input: OK 1 user=testaccount proxy=y host=backend-1 proxy_timeout=120 hostip=172.22.0.3 original_user=testuser pass=testpassword director | Jan 28 12:38:50 imap-login: Debug: auth-client: request [1]: Finished director | Jan 28 12:38:50 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: client passdb out: OK 1 user=testaccount proxy=y host=backend-1 proxy_timeout=120 hostip=172.22.0.3 original_user=testuser pass=<hidden> director | Jan 28 12:38:50 imap-login: Debug: Ignoring unknown passdb extra field: original_user: user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.5, session=<KEaTecMsQvasFgAB> director | Jan 28 12:38:50 imap-login: Debug: proxy(testaccount,backend-1[172.22.0.3]:143): Created proxy session to remote host: user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.5, session=<KEaTecMsQvasFgAB> director | Jan 28 12:38:50 imap-login: Debug: proxy(testaccount,backend-1[172.22.0.3]:143): Connecting to remote host: user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.5, session=<KEaTecMsQvasFgAB> director | Jan 28 12:38:50 imap-login: Info: proxy(testaccount,backend-1[172.22.0.3]:143): Started proxying to remote host (0.020 secs): user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.5, session=<KEaTecMsQvasFgAB> director | Jan 28 12:38:50 imap-login: Debug: auth-client: request [2]: Started request director | Jan 28 12:38:50 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: client in: AUTH 2 PLAIN protocol=imap final-resp-ok session=IUeTecMsRvasFgAB lip=172.22.0.5rip=172.22.0.1 lport=143 rport=63046 director | Jan 28 12:38:50 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: client passdb out: CONT 2 director | Jan 28 12:38:50 imap-login: Debug: auth-client: conn unix:login (pid=7,uid=1000): auth input: CONT 2 director | Jan 28 12:38:50 imap-login: Debug: auth-client: request [2]: Got challenge director | Jan 28 12:38:50 imap-login: Debug: auth-client: request [2]: Continue request director | Jan 28 12:38:50 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: client in: CONT<hidden> director | Jan 28 12:38:50 auth(testuser,172.22.0.1,sasl:plain)<IUeTecMsRvasFgAB>: Debug: lua: Performing passdb lookup director | Jan 28 12:38:50 auth-worker(16): Debug: conn unix:auth-worker (pid=15,uid=1000): auth-worker<2>: Handling PASSV request director | Jan 28 12:38:50 auth-worker(testuser,172.22.0.1)<16><IUeTecMsRvasFgAB>: request [2]: Debug: lua: Performing passdb lookup director | Jan 28 12:38:50 auth-worker(testuser,172.22.0.1)<16><IUeTecMsRvasFgAB>: request [2]: Debug: lua: Calling auth_password_verify director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: queue http://nauthilus:8080: Using existing connection to 172.22.0.4:8080 (1 requests pending) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: request [Req2: POST http://nauthilus:8080/api/v1/auth/header]: Submitted (requests left=1) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: Waiting for 1 requests to finish director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Using 1 idle connections to handle 1 requests (1 total connections ready) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: queue http://nauthilus:8080: Connection to peer 172.22.0.4:8080 claimed request [Req2: POST http://nauthilus:8080/api/v1/auth/header] director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Claimed request [Req2: POST http://nauthilus:8080/api/v1/auth/header] director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: request [Req2: POST http://nauthilus:8080/api/v1/auth/header]: Sent header director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: No more requests to service for this peer (1 connections exist, 0 pending) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Got 200 response for request [Req2: POST http://nauthilus:8080/api/v1/auth/header]: OK (took 6 ms + 0 ms in queue) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: request [Req2: POST http://nauthilus:8080/api/v1/auth/header]: Finished director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: queue http://nauthilus:8080: Dropping request [Req2: POST http://nauthilus:8080/api/v1/auth/header] director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: Host is idle (timeout = 1799880 msecs) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: request [Req2: POST http://nauthilus:8080/api/v1/auth/header]: Free (requests left=1) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: All requests finished director | Jan 28 12:38:50 auth-worker(16): Info: request=passdb protocol=imap proxy_host=backend-1 auth_status_code=200 auth_status_message=<OK> nauthilus_session=2sG39Fakmqx5lQZSuXwqJRfDDyO director | Jan 28 12:38:50 auth-worker(testuser,172.22.0.1)<16><IUeTecMsRvasFgAB>: request [2]: Debug: lua: username changed testuser -> testaccount director | Jan 28 12:38:50 auth-worker(testaccount,172.22.0.1)<16><IUeTecMsRvasFgAB>: request [2]: Debug: lua: Finished passdb lookup director | Jan 28 12:38:50 auth-worker(16): Debug: conn unix:auth-worker (pid=15,uid=1000): auth-worker<2>: Finished director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: No requests to service for this peer (1 connections exist, 0 pending) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: No more requests queued; going idle director | Jan 28 12:38:50 auth(testuser,172.22.0.1,sasl:plain)<IUeTecMsRvasFgAB>: Debug: lua: username changed testuser -> testaccount director | Jan 28 12:38:50 auth(testaccount,172.22.0.1,sasl:plain)<IUeTecMsRvasFgAB>: Debug: lua: Finished passdb lookup director | Jan 28 12:38:50 auth(testaccount,172.22.0.1,sasl:plain)<IUeTecMsRvasFgAB>: Debug: Auth request finished director | Jan 28 12:38:50 auth(testaccount,172.22.0.1,sasl:plain)<IUeTecMsRvasFgAB>: Debug: proxy: dns(backend-1): Lookup started director | Jan 28 12:38:50 auth(testaccount,172.22.0.1,sasl:plain)<IUeTecMsRvasFgAB>: Debug: proxy: dns(backend-1): Lookup successful after 0 msecs director | Jan 28 12:38:50 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: client passdb out: OK 2 user=testaccount proxy=y host=backend-1 proxy_timeout=120 hostip=172.22.0.3 original_user=testuser pass=<hidden> director | Jan 28 12:38:50 imap-login: Debug: auth-client: conn unix:login (pid=7,uid=1000): auth input: OK 2 user=testaccount proxy=y host=backend-1 proxy_timeout=120 hostip=172.22.0.3 original_user=testuser pass=testpassword director | Jan 28 12:38:50 imap-login: Debug: auth-client: request [2]: Finished director | Jan 28 12:38:50 imap-login: Debug: Ignoring unknown passdb extra field: original_user: user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.5, session=<IUeTecMsRvasFgAB> director | Jan 28 12:38:50 imap-login: Debug: proxy(testaccount,backend-1[172.22.0.3]:143): Created proxy session to remote host: user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.5, session=<IUeTecMsRvasFgAB> director | Jan 28 12:38:50 imap-login: Debug: proxy(testaccount,backend-1[172.22.0.3]:143): Connecting to remote host: user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.5, session=<IUeTecMsRvasFgAB> director | Jan 28 12:38:50 imap-login: Info: proxy(testaccount,backend-1[172.22.0.3]:143): Started proxying to remote host (0.021 secs): user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.5, session=<IUeTecMsRvasFgAB> director | Jan 28 12:39:38 imap-login: Info: proxy(testaccount,backend-1[172.22.0.3]:143): Disconnected by server (0s idle, in=443, out=929): user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.5, session=<KEaTecMsQvasFgAB> director | Jan 28 12:39:38 imap-login: Info: proxy(testaccount,backend-1[172.22.0.3]:143): Disconnected by server (0s idle, in=706, out=4582): user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.5, session=<IUeTecMsRvasFgAB> director | Jan 28 12:39:50 auth: Debug: conn unix:dns-client (pid=7,uid=1000): Disconnected: Connection closed (fd=21) director | Jan 28 12:39:50 auth: Debug: conn unix:dns-client (pid=7,uid=1000): Disconnect: Idle timeout director | Jan 28 12:39:50 dns-client: Debug: conn unix:dns-client (pid=15,uid=1000): Disconnected: Deinitializing (fd=13) director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Aborting connection with temporary error: Connection lost: read((conn:172.22.0.4:8080,id=1)) failed: EOF (No requests, last input 0 secs ago, connected 60.121 secs ago) director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Connection disconnect director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Disconnected: Connection closed (fd=8) director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Detached peer director | Jan 28 12:39:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Lost a connection (1 queues linked, 0 connections left, 0 connections pending, 0 requests pending, 0 requests urgent) director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Retrying pending requests director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Connection close director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Connection destroy director | Jan 28 12:39:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: No requests to service for this peer (0 connections exist, 0 pending) director | Jan 28 12:39:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Dropping peer now director | Jan 28 12:39:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Peer close director | Jan 28 12:39:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Peer disconnect director | Jan 28 12:39:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Peer destroy director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: peer 172.22.0.4:8080: Peer pool destroy director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: peer 172.22.0.4:8080 (shared): Peer destroy director | Jan 28 12:39:50 imap-login: Debug: auth-client: conn unix:login (pid=7,uid=1000): Disconnected: Connection closed (fd=13) director | Jan 28 12:39:50 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: Disconnected: Connection closed (fd=18)
Further information:
docker exec -it nauthilus bash 044510af705c:/usr/app$ ifconfig eth0 Link encap:Ethernet HWaddr 02:42:AC:16:00:04 inet addr:172.22.0.4 Bcast:172.22.255.255 Mask:255.255.0.0 UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1 RX packets:883 errors:0 dropped:0 overruns:0 frame:0 TX packets:1111 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:0 RX bytes:88062 (85.9 KiB) TX bytes:76751 (74.9 KiB)
eth1 Link encap:Ethernet HWaddr 02:42:AC:17:00:03 inet addr:172.23.0.3 Bcast:172.23.255.255 Mask:255.255.0.0 UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1 RX packets:69 errors:0 dropped:0 overruns:0 frame:0 TX packets:75 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:0 RX bytes:5399 (5.2 KiB) TX bytes:7397 (7.2 KiB)
lo Link encap:Local Loopback inet addr:127.0.0.1 Mask:255.0.0.0 inet6 addr: ::1/128 Scope:Host UP LOOPBACK RUNNING MTU:65536 Metric:1 RX packets:494 errors:0 dropped:0 overruns:0 frame:0 TX packets:494 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:1000 RX bytes:34887 (34.0 KiB) TX bytes:34887 (34.0 KiB)
044510af705c:/usr/app$ netstat -tulpn Active Internet connections (only servers) Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name tcp 0 0 127.0.0.11:38653 0.0.0.0:* LISTEN - tcp 0 0 :::8080 :::* LISTEN 1/nauthilus udp 0 0 127.0.0.11:50436 0.0.0.0:* - 044510af705c:/usr/app$ ping -c1 nauthilus PING nauthilus (172.22.0.4): 56 data bytes 64 bytes from 172.22.0.4: seq=0 ttl=42 time=0.024 ms
--- nauthilus ping statistics --- 1 packets transmitted, 1 packets received, 0% packet loss round-trip min/avg/max = 0.024/0.024/0.024 ms
044510af705c:/usr/app$ curl http://localhost:8080/ping pong
Why is this temporary error?
Christian Rößner
Rößner-Network-Solutions Zertifizierter ITSiBe / CISO Marburger Str. 70a, 36304 Alsfeld Fax: +49 6631 78823409, Mobil: +49 171 9905345 USt-IdNr.: DE225643613, https://roessner.website PGP fingerprint: 658D 1342 B762 F484 2DDF 1E88 38A5 4346 D727 94E5
On 28/01/2025 14:47 EET Christian Rößner via dovecot <dovecot@dovecot.org> wrote:
Am 28.01.2025 um 12:43 schrieb Timo Sirainen via dovecot <dovecot@dovecot.org>:
log_debug = category=debug
Here is the debug output:
director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Aborting connection with temporary error: Connection lost: read((conn:172.22.0.4:8080,id=1)) failed: EOF (No requests, last input 0 secs ago, connected 60.121 secs ago)
You sure the remote end didn't just crash?
Aki
Am 28.01.2025 um 14:00 schrieb Aki Tuomi via dovecot <dovecot@dovecot.org>:
On 28/01/2025 14:47 EET Christian Rößner via dovecot <dovecot@dovecot.org> wrote:
Am 28.01.2025 um 12:43 schrieb Timo Sirainen via dovecot <dovecot@dovecot.org>:
log_debug = category=debug
Here is the debug output:
director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Aborting connection with temporary error: Connection lost: read((conn:172.22.0.4:8080,id=1)) failed: EOF (No requests, last input 0 secs ago, connected 60.121 secs ago)
You sure the remote end didn't just crash?
Yes
Steps to reproduce:
git clone https://github.com/croessner/nauthilus-demo docker compose up -d ./nauthilus-test.sh
docker compose logs director docker compose logs nauthilus
You will see 2 errors in Nauthilus, but they do not matter (and have been fixed in main).
I have the same setup running on Rocky Linux 8 with Dovecot 2.3.21.1 (repo.dovecot.org). And as I have Loki in place, I see that the /api/v1/custom/dovecot-session/cleaner URL is called frequently over time. So the general setup is working since months. I only discovered this issue right now with Docker.
Even with older Docker image 2.3-latest, the problem exists. So my guessing is the docker image. Or a very hard to find config error. But I do not know which mistake I could have done.
Christian Rößner
Rößner-Network-Solutions Zertifizierter ITSiBe / CISO Marburger Str. 70a, 36304 Alsfeld Fax: +49 6631 78823409, Mobil: +49 171 9905345 USt-IdNr.: DE225643613, https://roessner.website PGP fingerprint: 658D 1342 B762 F484 2DDF 1E88 38A5 4346 D727 94E5
On 28. Jan 2025, at 15.00, Aki Tuomi via dovecot <dovecot@dovecot.org> wrote:
On 28/01/2025 14:47 EET Christian Rößner via dovecot <dovecot@dovecot.org> wrote:
Am 28.01.2025 um 12:43 schrieb Timo Sirainen via dovecot <dovecot@dovecot.org>:
log_debug = category=debug
Here is the debug output:
director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Aborting connection with temporary error: Connection lost: read((conn:172.22.0.4:8080,id=1)) failed: EOF (No requests, last input 0 secs ago, connected 60.121 secs ago)
You sure the remote end didn't just crash?
This is just a bit confusing lib-http debug message. There were no more requests, so it closed the connection after idling 60 seconds.
Anyway, like I mentioned in my other email, I think the problem here is simply that the events should be configured to Dovecot backend, not to Dovecot proxy.
Am 28.01.2025 um 14:51 schrieb Timo Sirainen via dovecot <dovecot@dovecot.org>:
Anyway, like I mentioned in my other email, I think the problem here is simply that the events should be configured to Dovecot backend, not to Dovecot proxy.
But this would track sessions on the backends and not the ones on the proxy. How else can I see "disconnects" and "established-connections" on the proxy side?
Christian Rößner
Rößner-Network-Solutions Zertifizierter ITSiBe / CISO Marburger Str. 70a, 36304 Alsfeld Fax: +49 6631 78823409, Mobil: +49 171 9905345 USt-IdNr.: DE225643613, https://roessner.website PGP fingerprint: 658D 1342 B762 F484 2DDF 1E88 38A5 4346 D727 94E5
On 28. Jan 2025, at 17.19, Christian Rößner <lists@mlserv.org> wrote:
Am 28.01.2025 um 14:51 schrieb Timo Sirainen via dovecot <dovecot@dovecot.org>:
Anyway, like I mentioned in my other email, I think the problem here is simply that the events should be configured to Dovecot backend, not to Dovecot proxy.
But this would track sessions on the backends and not the ones on the proxy. How else can I see "disconnects" and "established-connections" on the proxy side?
This is now getting into a different topic though. You said the previous events & event exporting worked in v2.3, but they definitely didn't work in v2.3 proxies either.
Anyway, for proxies you have proxy_session_established and proxy_session_finished events.
Am 28.01.2025 um 22:20 schrieb Timo Sirainen via dovecot <dovecot@dovecot.org>:
proxy_session_finished events.
With remote_ip and remote_port as tracking criteria.
Thank you very much.
I was on the wrong path, because my Rocky 8 still used proxy_maybe being always the same host as the proxy itself. So I thought it was working.
The Docker stack in fact used different machines. And obviously I did not test it well enough.
I will fix it soon. Then this will become an alternative for Director setups with dynamic backend routing.
Am 28.01.2025 um 13:47 schrieb Christian Rößner via dovecot <dovecot@dovecot.org>:
Am 28.01.2025 um 12:43 schrieb Timo Sirainen via dovecot <dovecot@dovecot.org>:
log_debug = category=debug
Here is the debug output:
director | Jan 28 12:38:18 master: Info: Dovecot v2.4.0 (daeb6bc59c) starting up for imap, pop3, lmtp (core dumps disabled) director | Jan 28 12:38:18 imap-login: Debug: conn unix:stats-writer: Connecting director | Jan 28 12:38:18 imap-login: Debug: conn unix:stats-writer (pid=7,uid=1000): Client connected (fd=10) director | Jan 28 12:38:18 imap-login: Debug: conn unix:stats-writer (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:18 pop3-login: Debug: conn unix:stats-writer: Connecting director | Jan 28 12:38:18 pop3-login: Debug: conn unix:stats-writer (pid=7,uid=1000): Client connected (fd=10) director | Jan 28 12:38:18 pop3-login: Debug: conn unix:stats-writer (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:18 anvil: Debug: conn anvil: Server accepted connection (fd=8) director | Jan 28 12:38:18 anvil: Debug: conn anvil: Server accepted connection (fd=9) director | Jan 28 12:38:18 stats: Debug: conn unix:stats (pid=9,uid=1000): Server accepted connection (fd=13) director | Jan 28 12:38:18 stats: Debug: conn unix:stats (pid=9,uid=1000): Sending version handshake director | Jan 28 12:38:18 stats: Debug: conn unix:stats (pid=10,uid=1000): Server accepted connection (fd=14) director | Jan 28 12:38:18 stats: Debug: conn unix:stats (pid=10,uid=1000): Sending version handshake director | Jan 28 12:38:18 imap-login: Debug: conn unix:anvil: Connecting director | Jan 28 12:38:18 imap-login: Debug: conn unix:anvil (pid=7,uid=1000): Client connected (fd=12) director | Jan 28 12:38:18 imap-login: Debug: conn unix:anvil (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:18 pop3-login: Debug: conn unix:anvil: Connecting director | Jan 28 12:38:18 pop3-login: Debug: conn unix:anvil (pid=7,uid=1000): Client connected (fd=12) director | Jan 28 12:38:18 pop3-login: Debug: conn unix:anvil (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:18 anvil: Debug: conn unix:anvil (pid=9,uid=1000): Server accepted connection (fd=15) director | Jan 28 12:38:18 anvil: Debug: conn unix:anvil (pid=10,uid=1000): Server accepted connection (fd=16) director | Jan 28 12:38:18 pop3-login: Debug: auth-client: conn unix:login: Connecting director | Jan 28 12:38:18 pop3-login: Debug: auth-client: conn unix:login (pid=7,uid=1000): Client connected (fd=13) director | Jan 28 12:38:18 imap-login: Debug: auth-client: conn unix:login: Connecting director | Jan 28 12:38:18 imap-login: Debug: auth-client: conn unix:login (pid=7,uid=1000): Client connected (fd=13) director | Jan 28 12:38:18 auth: Debug: conn unix:/run/dovecot/stats-writer: Connecting director | Jan 28 12:38:18 auth: Debug: conn unix:/run/dovecot/stats-writer (pid=7,uid=1000): Client connected (fd=7) director | Jan 28 12:38:18 auth: Debug: conn unix:/run/dovecot/stats-writer (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:18 stats: Debug: conn unix:stats (pid=15,uid=1000): Server accepted connection (fd=15) director | Jan 28 12:38:18 stats: Debug: conn unix:stats (pid=15,uid=1000): Sending version handshake director | Jan 28 12:38:18 auth: Debug: conn unix:anvil-auth-penalty: Connecting director | Jan 28 12:38:18 auth: Debug: conn unix:anvil-auth-penalty (pid=7,uid=1000): Client connected (fd=15) director | Jan 28 12:38:18 auth: Debug: conn unix:anvil-auth-penalty (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:18 anvil: Debug: conn unix:anvil (pid=15,uid=1000): Server accepted connection (fd=17) director | Jan 28 12:38:18 auth: Debug: Wrote new auth token secret to /run/dovecot/auth-token-secret.dat director | Jan 28 12:38:18 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: Server accepted connection (fd=18) director | Jan 28 12:38:18 auth: Debug: conn unix:login (pid=10,uid=1000) [2]: Server accepted connection (fd=19) director | Jan 28 12:38:18 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: auth client connected (pid=9) director | Jan 28 12:38:18 auth: Debug: conn unix:login (pid=10,uid=1000) [2]: auth client connected (pid=10) director | Jan 28 12:38:50 imap-login: Debug: auth-client: request [1]: Started request director | Jan 28 12:38:50 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: client in: AUTH 1 PLAIN protocol=imap final-resp-ok session=KEaTecMsQvasFgAB lip=172.22.0.5rip=172.22.0.1 lport=143 rport=63042 director | Jan 28 12:38:50 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: client passdb out: CONT 1 director | Jan 28 12:38:50 imap-login: Debug: auth-client: conn unix:login (pid=7,uid=1000): auth input: CONT 1 director | Jan 28 12:38:50 imap-login: Debug: auth-client: request [1]: Got challenge director | Jan 28 12:38:50 imap-login: Debug: auth-client: request [1]: Continue request director | Jan 28 12:38:50 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: client in: CONT<hidden> director | Jan 28 12:38:50 auth(testuser,172.22.0.1,sasl:plain)<KEaTecMsQvasFgAB>: Debug: lua: Performing passdb lookup director | Jan 28 12:38:50 auth: Debug: conn unix:auth-worker: Connecting director | Jan 28 12:38:50 auth: Debug: conn unix:auth-worker (pid=7,uid=1000): Client connected (fd=20) director | Jan 28 12:38:50 auth: Debug: conn unix:auth-worker (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:50 auth-worker: Debug: conn unix:/run/dovecot/stats-writer: Connecting director | Jan 28 12:38:50 auth-worker: Debug: conn unix:/run/dovecot/stats-writer (pid=7,uid=1000): Client connected (fd=7) director | Jan 28 12:38:50 auth-worker: Debug: conn unix:/run/dovecot/stats-writer (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:50 stats: Debug: conn unix:stats (pid=16,uid=1000): Server accepted connection (fd=16) director | Jan 28 12:38:50 stats: Debug: conn unix:stats (pid=16,uid=1000): Sending version handshake director | Jan 28 12:38:50 auth-worker(16): Debug: conn unix:auth-worker (pid=15,uid=1000): Server accepted connection (fd=12) director | Jan 28 12:38:50 auth-worker(16): Debug: conn unix:auth-worker (pid=15,uid=1000): Sending version handshake director | Jan 28 12:38:50 auth-worker(16): Debug: conn unix:auth-worker (pid=15,uid=1000): auth-worker<1>: Handling PASSV request director | Jan 28 12:38:50 auth-worker(testuser,172.22.0.1)<16><KEaTecMsQvasFgAB>: request [1]: Debug: lua: Performing passdb lookup director | Jan 28 12:38:50 auth-worker(testuser,172.22.0.1)<16><KEaTecMsQvasFgAB>: request [1]: Debug: lua: Calling auth_password_verify director | Jan 28 12:38:50 auth: Debug: auth-worker: Worker sent process limit '30' director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: Host created director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: Host session created director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: Need to perform DNS lookup director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: Performing asynchronous DNS lookup director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: conn unix:/run/dovecot/dns-client: dns(nauthilus): Lookup started director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: conn unix:/run/dovecot/dns-client: Connecting director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: conn unix:/run/dovecot/dns-client (pid=7,uid=1000): Client connected (fd=8) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: conn unix:/run/dovecot/dns-client (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: request [Req1: POST http://nauthilus:8080/api/v1/auth/header]: Submitted (requests left=1) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: Waiting for 1 requests to finish director | Jan 28 12:38:50 dns-client: Debug: conn unix:/run/dovecot/stats-writer: Connecting director | Jan 28 12:38:50 dns-client: Debug: conn unix:/run/dovecot/stats-writer (pid=7,uid=1000): Client connected (fd=7) director | Jan 28 12:38:50 dns-client: Debug: conn unix:/run/dovecot/stats-writer (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:50 stats: Debug: conn unix:stats (pid=17,uid=1000): Server accepted connection (fd=17) director | Jan 28 12:38:50 stats: Debug: conn unix:stats (pid=17,uid=1000): Sending version handshake director | Jan 28 12:38:50 dns-client: Debug: conn unix:dns-client (pid=16,uid=1000): Server accepted connection (fd=13) director | Jan 28 12:38:50 dns-client: Debug: conn unix:dns-client (pid=16,uid=1000): Sending version handshake director | Jan 28 12:38:50 dns-client: Debug: conn unix:dns-client (pid=16,uid=1000): nauthilus: Resolving director | Jan 28 12:38:50 dns-client: Debug: conn unix:dns-client (pid=16,uid=1000): nauthilus: Resolve success: 172.22.0.4 director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: conn unix:/run/dovecot/dns-client (pid=7,uid=1000): dns(nauthilus): Lookup successful after 4 msecs director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: DNS lookup successful; got 1 IPs director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: peer 172.22.0.4:8080 (shared): Peer created director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: peer 172.22.0.4:8080: Peer pool created director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Peer created director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: queue http://nauthilus:8080: Setting up connection to 172.22.0.4:8080 (1 requests pending) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Linked queue http://nauthilus:8080 (1 queues linked) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: queue http://nauthilus:8080: Started new connection to 172.22.0.4:8080 director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: conn unix:/run/dovecot/dns-client (pid=7,uid=1000): Disconnected: Connection closed (fd=8) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: conn unix:/run/dovecot/dns-client (pid=7,uid=1000): Disconnect: deinit director | Jan 28 12:38:50 dns-client: Debug: conn unix:dns-client (pid=16,uid=1000): Disconnected: Connection closed (fd=13) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Creating 1 new connections to handle requests (already 0 usable, connecting to 0, closing 0) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Making new connection 1 of 1 (0 connections exist, 0 pending) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Connecting director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Waiting for connect (fd=8) to finish for max 0 msecs director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: HTTP connection created (1 parallel connections exist) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Client connected (fd=8) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Connected director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Ready for requests director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Successfully connected (1 connections exist, 0 pending) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: peer 172.22.0.4:8080: Successfully connected (1 connections exist, 0 pending) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Using 1 idle connections to handle 1 requests (1 total connections ready) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: queue http://nauthilus:8080: Connection to peer 172.22.0.4:8080 claimed request [Req1: POST http://nauthilus:8080/api/v1/auth/header] director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Claimed request [Req1: POST http://nauthilus:8080/api/v1/auth/header] director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: request [Req1: POST http://nauthilus:8080/api/v1/auth/header]: Sent header director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: No more requests to service for this peer (1 connections exist, 0 pending) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Got 200 response for request [Req1: POST http://nauthilus:8080/api/v1/auth/header]: OK (took 5 ms + 6 ms in queue) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: request [Req1: POST http://nauthilus:8080/api/v1/auth/header]: Finished director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: queue http://nauthilus:8080: Dropping request [Req1: POST http://nauthilus:8080/api/v1/auth/header] director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: Host is idle (timeout = 1799993 msecs) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: request [Req1: POST http://nauthilus:8080/api/v1/auth/header]: Free (requests left=1) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: All requests finished director | Jan 28 12:38:50 auth-worker(16): Info: request=passdb protocol=imap proxy_host=backend-1 auth_status_code=200 auth_status_message=<OK> nauthilus_session=2sG39Fb74g18mD1jl7DegMz9TDL director | Jan 28 12:38:50 auth-worker(testuser,172.22.0.1)<16><KEaTecMsQvasFgAB>: request [1]: Debug: lua: username changed testuser -> testaccount director | Jan 28 12:38:50 auth-worker(testaccount,172.22.0.1)<16><KEaTecMsQvasFgAB>: request [1]: Debug: lua: Finished passdb lookup director | Jan 28 12:38:50 auth-worker(16): Debug: conn unix:auth-worker (pid=15,uid=1000): auth-worker<1>: Finished director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: No requests to service for this peer (1 connections exist, 0 pending) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: No more requests queued; going idle director | Jan 28 12:38:50 auth(testuser,172.22.0.1,sasl:plain)<KEaTecMsQvasFgAB>: Debug: lua: username changed testuser -> testaccount director | Jan 28 12:38:50 auth(testaccount,172.22.0.1,sasl:plain)<KEaTecMsQvasFgAB>: Debug: lua: Finished passdb lookup director | Jan 28 12:38:50 auth(testaccount,172.22.0.1,sasl:plain)<KEaTecMsQvasFgAB>: Debug: Auth request finished director | Jan 28 12:38:50 auth(testaccount,172.22.0.1,sasl:plain)<KEaTecMsQvasFgAB>: Debug: proxy: dns(backend-1): Lookup started director | Jan 28 12:38:50 auth: Debug: conn unix:dns-client: Connecting director | Jan 28 12:38:50 auth: Debug: conn unix:dns-client (pid=7,uid=1000): Client connected (fd=21) director | Jan 28 12:38:50 auth: Debug: conn unix:dns-client (pid=7,uid=1000): Sending version handshake director | Jan 28 12:38:50 dns-client: Debug: conn unix:dns-client (pid=15,uid=1000): Server accepted connection (fd=13) director | Jan 28 12:38:50 dns-client: Debug: conn unix:dns-client (pid=15,uid=1000): Sending version handshake director | Jan 28 12:38:50 dns-client: Debug: conn unix:dns-client (pid=15,uid=1000): backend-1: Resolving director | Jan 28 12:38:50 dns-client: Debug: conn unix:dns-client (pid=15,uid=1000): backend-1: Resolve success: 172.22.0.3 director | Jan 28 12:38:50 auth(testaccount,172.22.0.1,sasl:plain)<KEaTecMsQvasFgAB>: Debug: proxy: dns(backend-1): Lookup successful after 0 msecs director | Jan 28 12:38:50 imap-login: Debug: auth-client: conn unix:login (pid=7,uid=1000): auth input: OK 1 user=testaccount proxy=y host=backend-1 proxy_timeout=120 hostip=172.22.0.3 original_user=testuser pass=testpassword director | Jan 28 12:38:50 imap-login: Debug: auth-client: request [1]: Finished director | Jan 28 12:38:50 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: client passdb out: OK 1 user=testaccount proxy=y host=backend-1 proxy_timeout=120 hostip=172.22.0.3 original_user=testuser pass=<hidden> director | Jan 28 12:38:50 imap-login: Debug: Ignoring unknown passdb extra field: original_user: user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.5, session=<KEaTecMsQvasFgAB> director | Jan 28 12:38:50 imap-login: Debug: proxy(testaccount,backend-1[172.22.0.3]:143): Created proxy session to remote host: user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.5, session=<KEaTecMsQvasFgAB> director | Jan 28 12:38:50 imap-login: Debug: proxy(testaccount,backend-1[172.22.0.3]:143): Connecting to remote host: user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.5, session=<KEaTecMsQvasFgAB> director | Jan 28 12:38:50 imap-login: Info: proxy(testaccount,backend-1[172.22.0.3]:143): Started proxying to remote host (0.020 secs): user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.5, session=<KEaTecMsQvasFgAB> director | Jan 28 12:38:50 imap-login: Debug: auth-client: request [2]: Started request director | Jan 28 12:38:50 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: client in: AUTH 2 PLAIN protocol=imap final-resp-ok session=IUeTecMsRvasFgAB lip=172.22.0.5rip=172.22.0.1 lport=143 rport=63046 director | Jan 28 12:38:50 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: client passdb out: CONT 2 director | Jan 28 12:38:50 imap-login: Debug: auth-client: conn unix:login (pid=7,uid=1000): auth input: CONT 2 director | Jan 28 12:38:50 imap-login: Debug: auth-client: request [2]: Got challenge director | Jan 28 12:38:50 imap-login: Debug: auth-client: request [2]: Continue request director | Jan 28 12:38:50 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: client in: CONT<hidden> director | Jan 28 12:38:50 auth(testuser,172.22.0.1,sasl:plain)<IUeTecMsRvasFgAB>: Debug: lua: Performing passdb lookup director | Jan 28 12:38:50 auth-worker(16): Debug: conn unix:auth-worker (pid=15,uid=1000): auth-worker<2>: Handling PASSV request director | Jan 28 12:38:50 auth-worker(testuser,172.22.0.1)<16><IUeTecMsRvasFgAB>: request [2]: Debug: lua: Performing passdb lookup director | Jan 28 12:38:50 auth-worker(testuser,172.22.0.1)<16><IUeTecMsRvasFgAB>: request [2]: Debug: lua: Calling auth_password_verify director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: queue http://nauthilus:8080: Using existing connection to 172.22.0.4:8080 (1 requests pending) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: request [Req2: POST http://nauthilus:8080/api/v1/auth/header]: Submitted (requests left=1) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: Waiting for 1 requests to finish director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Using 1 idle connections to handle 1 requests (1 total connections ready) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: queue http://nauthilus:8080: Connection to peer 172.22.0.4:8080 claimed request [Req2: POST http://nauthilus:8080/api/v1/auth/header] director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Claimed request [Req2: POST http://nauthilus:8080/api/v1/auth/header] director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: request [Req2: POST http://nauthilus:8080/api/v1/auth/header]: Sent header director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: No more requests to service for this peer (1 connections exist, 0 pending) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Got 200 response for request [Req2: POST http://nauthilus:8080/api/v1/auth/header]: OK (took 6 ms + 0 ms in queue) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: request [Req2: POST http://nauthilus:8080/api/v1/auth/header]: Finished director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: queue http://nauthilus:8080: Dropping request [Req2: POST http://nauthilus:8080/api/v1/auth/header] director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: host nauthilus: Host is idle (timeout = 1799880 msecs) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: request [Req2: POST http://nauthilus:8080/api/v1/auth/header]: Free (requests left=1) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: All requests finished director | Jan 28 12:38:50 auth-worker(16): Info: request=passdb protocol=imap proxy_host=backend-1 auth_status_code=200 auth_status_message=<OK> nauthilus_session=2sG39Fakmqx5lQZSuXwqJRfDDyO director | Jan 28 12:38:50 auth-worker(testuser,172.22.0.1)<16><IUeTecMsRvasFgAB>: request [2]: Debug: lua: username changed testuser -> testaccount director | Jan 28 12:38:50 auth-worker(testaccount,172.22.0.1)<16><IUeTecMsRvasFgAB>: request [2]: Debug: lua: Finished passdb lookup director | Jan 28 12:38:50 auth-worker(16): Debug: conn unix:auth-worker (pid=15,uid=1000): auth-worker<2>: Finished director | Jan 28 12:38:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: No requests to service for this peer (1 connections exist, 0 pending) director | Jan 28 12:38:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: No more requests queued; going idle director | Jan 28 12:38:50 auth(testuser,172.22.0.1,sasl:plain)<IUeTecMsRvasFgAB>: Debug: lua: username changed testuser -> testaccount director | Jan 28 12:38:50 auth(testaccount,172.22.0.1,sasl:plain)<IUeTecMsRvasFgAB>: Debug: lua: Finished passdb lookup director | Jan 28 12:38:50 auth(testaccount,172.22.0.1,sasl:plain)<IUeTecMsRvasFgAB>: Debug: Auth request finished director | Jan 28 12:38:50 auth(testaccount,172.22.0.1,sasl:plain)<IUeTecMsRvasFgAB>: Debug: proxy: dns(backend-1): Lookup started director | Jan 28 12:38:50 auth(testaccount,172.22.0.1,sasl:plain)<IUeTecMsRvasFgAB>: Debug: proxy: dns(backend-1): Lookup successful after 0 msecs director | Jan 28 12:38:50 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: client passdb out: OK 2 user=testaccount proxy=y host=backend-1 proxy_timeout=120 hostip=172.22.0.3 original_user=testuser pass=<hidden> director | Jan 28 12:38:50 imap-login: Debug: auth-client: conn unix:login (pid=7,uid=1000): auth input: OK 2 user=testaccount proxy=y host=backend-1 proxy_timeout=120 hostip=172.22.0.3 original_user=testuser pass=testpassword director | Jan 28 12:38:50 imap-login: Debug: auth-client: request [2]: Finished director | Jan 28 12:38:50 imap-login: Debug: Ignoring unknown passdb extra field: original_user: user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.5, session=<IUeTecMsRvasFgAB> director | Jan 28 12:38:50 imap-login: Debug: proxy(testaccount,backend-1[172.22.0.3]:143): Created proxy session to remote host: user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.5, session=<IUeTecMsRvasFgAB> director | Jan 28 12:38:50 imap-login: Debug: proxy(testaccount,backend-1[172.22.0.3]:143): Connecting to remote host: user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.5, session=<IUeTecMsRvasFgAB> director | Jan 28 12:38:50 imap-login: Info: proxy(testaccount,backend-1[172.22.0.3]:143): Started proxying to remote host (0.021 secs): user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.5, session=<IUeTecMsRvasFgAB> director | Jan 28 12:39:38 imap-login: Info: proxy(testaccount,backend-1[172.22.0.3]:143): Disconnected by server (0s idle, in=443, out=929): user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.5, session=<KEaTecMsQvasFgAB> director | Jan 28 12:39:38 imap-login: Info: proxy(testaccount,backend-1[172.22.0.3]:143): Disconnected by server (0s idle, in=706, out=4582): user=<testaccount>, method=PLAIN, rip=172.22.0.1, lip=172.22.0.5, session=<IUeTecMsRvasFgAB> director | Jan 28 12:39:50 auth: Debug: conn unix:dns-client (pid=7,uid=1000): Disconnected: Connection closed (fd=21) director | Jan 28 12:39:50 auth: Debug: conn unix:dns-client (pid=7,uid=1000): Disconnect: Idle timeout director | Jan 28 12:39:50 dns-client: Debug: conn unix:dns-client (pid=15,uid=1000): Disconnected: Deinitializing (fd=13) director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Aborting connection with temporary error: Connection lost: read((conn:172.22.0.4:8080,id=1)) failed: EOF (No requests, last input 0 secs ago, connected 60.121 secs ago) director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Connection disconnect director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Disconnected: Connection closed (fd=8) director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Detached peer director | Jan 28 12:39:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Lost a connection (1 queues linked, 0 connections left, 0 connections pending, 0 requests pending, 0 requests urgent) director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Retrying pending requests director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Connection close director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: conn 172.22.0.4:8080 [1]: Connection destroy director | Jan 28 12:39:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: No requests to service for this peer (0 connections exist, 0 pending) director | Jan 28 12:39:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Dropping peer now director | Jan 28 12:39:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Peer close director | Jan 28 12:39:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Peer disconnect director | Jan 28 12:39:50 auth-worker(16): Debug: http-client[1]: peer 172.22.0.4:8080: Peer destroy director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: peer 172.22.0.4:8080: Peer pool destroy director | Jan 28 12:39:50 auth-worker(16): Debug: http-client: peer 172.22.0.4:8080 (shared): Peer destroy director | Jan 28 12:39:50 imap-login: Debug: auth-client: conn unix:login (pid=7,uid=1000): Disconnected: Connection closed (fd=13) director | Jan 28 12:39:50 auth: Debug: conn unix:login (pid=9,uid=1000) [1]: Disconnected: Connection closed (fd=18)
Further information:
docker exec -it nauthilus bash 044510af705c:/usr/app$ ifconfig eth0 Link encap:Ethernet HWaddr 02:42:AC:16:00:04 inet addr:172.22.0.4 Bcast:172.22.255.255 Mask:255.255.0.0 UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1 RX packets:883 errors:0 dropped:0 overruns:0 frame:0 TX packets:1111 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:0 RX bytes:88062 (85.9 KiB) TX bytes:76751 (74.9 KiB)
eth1 Link encap:Ethernet HWaddr 02:42:AC:17:00:03 inet addr:172.23.0.3 Bcast:172.23.255.255 Mask:255.255.0.0 UP BROADCAST RUNNING MULTICAST MTU:1500 Metric:1 RX packets:69 errors:0 dropped:0 overruns:0 frame:0 TX packets:75 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:0 RX bytes:5399 (5.2 KiB) TX bytes:7397 (7.2 KiB)
lo Link encap:Local Loopback inet addr:127.0.0.1 Mask:255.0.0.0 inet6 addr: ::1/128 Scope:Host UP LOOPBACK RUNNING MTU:65536 Metric:1 RX packets:494 errors:0 dropped:0 overruns:0 frame:0 TX packets:494 errors:0 dropped:0 overruns:0 carrier:0 collisions:0 txqueuelen:1000 RX bytes:34887 (34.0 KiB) TX bytes:34887 (34.0 KiB)
044510af705c:/usr/app$ netstat -tulpn Active Internet connections (only servers) Proto Recv-Q Send-Q Local Address Foreign Address State PID/Program name tcp 0 0 127.0.0.11:38653 0.0.0.0:* LISTEN - tcp 0 0 :::8080 :::* LISTEN 1/nauthilus udp 0 0 127.0.0.11:50436 0.0.0.0:* - 044510af705c:/usr/app$ ping -c1 nauthilus PING nauthilus (172.22.0.4): 56 data bytes 64 bytes from 172.22.0.4: seq=0 ttl=42 time=0.024 ms
--- nauthilus ping statistics --- 1 packets transmitted, 1 packets received, 0% packet loss round-trip min/avg/max = 0.024/0.024/0.024 ms
044510af705c:/usr/app$ curl http://localhost:8080/ping pong
Why is this temporary error?
Christian Rößner
Rößner-Network-Solutions Zertifizierter ITSiBe / CISO Marburger Str. 70a, 36304 Alsfeld Fax: +49 6631 78823409, Mobil: +49 171 9905345 USt-IdNr.: DE225643613, https://roessner.website PGP fingerprint: 658D 1342 B762 F484 2DDF 1E88 38A5 4346 D727 94E5
dovecot mailing list -- dovecot@dovecot.org To unsubscribe send an email to dovecot-leave@dovecot.org
curl -v -X POST -H "Content-Type: application-json" -d '{ "event": "mail_user_session_finished", "hostname": "node2.roessner-net.de", "start_time": "2024-07-02T14:01:57.693768Z", "end_time": "2024-07-02T14:01:57.718345Z", "categories": [ "smtp-server", "service:lmtp", "lmtp", "storage" ], "fields": { "reason_code":[ "lmtp:cmd_data" ], "duration": 24204, "protocol": "lmtp", "remote_ip": "192.168.0.2", "remote_port": 52470, "connection_id": "AzaWIlUIhGZ0Ji0AWFyohA", "session": "AzaWIlUIhGZ0Ji0AWFyohA", "transaction_id": "AzaWIlUIhGZ0Ji0AWFyohA", "mail_from": "foo@example.com", "mail_from_raw": "foo@example.com", "rcpt_to": "christian@roessner.email", "user": "OzGaYPkrkskL0WIWfNENDl8v5QfGpvfZ!mail.de", "utime": 1, "stime": 1, "minor_faults": 98, "vol_cs": 9, "invol_cs": 1, "rss": 12554240, "vsz": 105050112, "rchar": 17624, "wchar": 3342, "syscr": 45, "syscw": 22 } }' http://127.0.0.1:8080/api/v1/custom/dovecot-session-cleaner Note: Unnecessary use of -X or --request, POST is already inferred.
- Trying 127.0.0.1:8080...
- Connected to 127.0.0.1 (127.0.0.1) port 8080
POST /api/v1/custom/dovecot-session-cleaner HTTP/1.1 Host: 127.0.0.1:8080 User-Agent: curl/8.7.1 Accept: */* Content-Type: application-json Content-Length: 953
- upload completely sent off: 953 bytes < HTTP/1.1 200 OK < Content-Type: application/json; charset=utf-8 < Date: Tue, 28 Jan 2025 12:57:46 GMT < Content-Length: 2 <
- Connection #0 to host 127.0.0.1 left intact
{}%
Nauthilus is working as expected.
Christian Rößner
Rößner-Network-Solutions Zertifizierter ITSiBe / CISO Marburger Str. 70a, 36304 Alsfeld Fax: +49 6631 78823409, Mobil: +49 171 9905345 USt-IdNr.: DE225643613, https://roessner.website PGP fingerprint: 658D 1342 B762 F484 2DDF 1E88 38A5 4346 D727 94E5
participants (4)
-
Aki Tuomi
-
Armin Tüting
-
Christian Rößner
-
Timo Sirainen