> 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-le...@dovecot.org
