> Am 28.01.2025 um 13:47 schrieb Christian Rößner via dovecot
> <[email protected]>:
>
>
>
>> Am 28.01.2025 um 12:43 schrieb Timo Sirainen via dovecot
>> <[email protected]>:
>>
>> 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 -- [email protected]
> To unsubscribe send an email to [email protected]
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": "[email protected]",
"mail_from_raw": "[email protected]",
"rcpt_to": "[email protected]",
"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
_______________________________________________
dovecot mailing list -- [email protected]
To unsubscribe send an email to [email protected]
