Re: Why does metrics exporter not work anymore?

28 Jan 2025 · */*


      ...
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