Francis Augusto Medeiros-Logeay Oslo, Norway
On 2023-11-20 09:04, Aki Tuomi wrote:
On 20/11/2023 10:03 EET Francis Augusto Medeiros-Logeay <r_f@med-lo.eu> wrote:
Try adding /?token= to tokeninfo_url. Dovecot 2.3.7.2 will simply concatenate tokeninfo_url and token, so you need to provide the URL in that fashion.
Aki
Thanks Aki.
Still no go:
Nov 20 08:59:19 auth: Debug: http-client: host auth.mydomain.com: Host created
<snip/>
oauth2(francis@mydomain.com,10.10.40.30,<4Gv83JAKyOcKCige>): oauth2 failed: Token validation failed: connect(10.10.200.10:443) failed: Connection refused
It still doesn't work after I fixed that "connection refused" problem. I had a NAT reflector problem. But with that out of the way, I still don't get it to work:
Nov 20 13:43:03 auth: Error: ldap(francis@mydomain.com,10.10.40.30,<joax05QKsSAKCige>): ldap_bind() failed: Constraint violation Nov 20 13:43:03 auth: Debug: http-client: host auth.mydomain.com: Host created Nov 20 13:43:03 auth: Debug: http-client: host auth.mydomain.com: Host session created Nov 20 13:43:03 auth: Debug: http-client: host auth.mydomain.com: Need to perform DNS lookup Nov 20 13:43:03 auth: Debug: http-client: host auth.mydomain.com: Performing asynchronous DNS lookup Nov 20 13:43:03 auth: Debug: http-client: host auth.mydomain.com: conn unix:dns-client: dns(auth.mydomain.com): Lookup started Nov 20 13:43:03 auth: Debug: http-client: host auth.mydomain.com: conn unix:dns-client: Connecting Nov 20 13:43:03 auth: Debug: http-client: host auth.mydomain.com: conn unix:dns-client (pid=2800,uid=0): Client connected (fd=23) Nov 20 13:43:03 auth: Debug: http-client: host auth.mydomain.com: conn unix:dns-client (pid=2800,uid=0): Sending version handshake Nov 20 13:43:03 auth: Debug: http-client[1]: request [Req1: GET https://auth.mydomain.com/realms/myrealm/protocol/openid-connect/userinfo?to......: Submitted (requests left=1) Nov 20 13:43:03 auth: Debug: http-client: host auth.mydomain.com: conn unix:dns-client (pid=2800,uid=0): dns(auth.mydomain.com): Lookup successful after 5 msecs Nov 20 13:43:03 auth: Debug: http-client: host auth.mydomain.com: DNS lookup successful; got 1 IPs Nov 20 13:43:03 auth: Debug: http-client: peer 10.10.20.100:443 (shared): Peer created Nov 20 13:43:03 auth: Debug: http-client: peer 10.10.20.100:443: Peer pool created Nov 20 13:43:03 auth: Debug: http-client[1]: peer 10.10.20.100:443: Peer created Nov 20 13:43:03 auth: Debug: http-client[1]: queue https://auth.mydomain.com:443: Setting up connection to 10.10.20.100:443 (SSL=auth.mydomain.com) (1 requests pending) Nov 20 13:43:03 auth: Debug: http-client[1]: peer 10.10.20.100:443: Linked queue https://auth.mydomain.com:443 (1 queues linked) Nov 20 13:43:03 auth: Debug: http-client[1]: queue https://auth.mydomain.com:443: Started new connection to 10.10.20.100:443 (SSL=auth.mydomain.com) Nov 20 13:43:03 auth: Debug: http-client: host auth.mydomain.com: conn unix:dns-client (pid=2800,uid=0): Disconnected: Connection closed (fd=23) Nov 20 13:43:03 auth: Debug: http-client: host auth.mydomain.com: conn unix:dns-client (pid=2800,uid=0): Disconnect: deinit Nov 20 13:43:03 auth: Debug: http-client[1]: peer 10.10.20.100:443: Creating 1 new connections to handle requests (already 0 usable, connecting to 0, closing 0) Nov 20 13:43:03 auth: Debug: http-client[1]: peer 10.10.20.100:443: Making new connection 1 of 1 (0 connections exist, 0 pending) Nov 20 13:43:03 auth: Debug: http-client: conn 10.10.20.100:443 [1]: Connecting Nov 20 13:43:03 auth: Debug: http-client: conn 10.10.20.100:443 [1]: Waiting for connect (fd=23) to finish for max 0 msecs Nov 20 13:43:03 auth: Debug: http-client: conn 10.10.20.100:443 [1]: HTTPS connection created (1 parallel connections exist) Nov 20 13:43:03 auth: Debug: http-client: conn 10.10.20.100:443 [1]: Client connected (fd=23) Nov 20 13:43:03 auth: Debug: http-client: conn 10.10.20.100:443 [1]: Connected Nov 20 13:43:03 auth: Debug: http-client: conn 10.10.20.100:443 [1]: Starting SSL handshake Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x10, ret=1: before SSL initialization Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1001, ret=1: before SSL initialization Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1001, ret=1: SSLv3/TLS write client hello Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1002, ret=-1: SSLv3/TLS write client hello Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1002, ret=-1: SSLv3/TLS write client hello Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1002, ret=-1: SSLv3/TLS write client hello Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1001, ret=1: SSLv3/TLS write client hello Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1001, ret=1: SSLv3/TLS read server hello Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1002, ret=-1: TLSv1.3 read encrypted extensions Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1002, ret=-1: TLSv1.3 read encrypted extensions Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1002, ret=-1: TLSv1.3 read encrypted extensions Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1001, ret=1: TLSv1.3 read encrypted extensions Nov 20 13:43:03 auth: Info: Received valid SSL certificate: /C=US/O=Internet Security Research Group/CN=ISRG Root X1 Nov 20 13:43:03 auth: Info: Received valid SSL certificate: /C=US/O=Let's Encrypt/CN=R3 Nov 20 13:43:03 auth: Info: Received valid SSL certificate: /CN=auth.mydomain.com Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1001, ret=1: SSLv3/TLS read server certificate Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1001, ret=1: TLSv1.3 read server certificate verify Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1001, ret=1: SSLv3/TLS read finished Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1001, ret=1: SSLv3/TLS write change cipher spec Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1001, ret=1: SSLv3/TLS write finished Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x20, ret=1: SSL negotiation finished successfully Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1002, ret=1: SSL negotiation finished successfully Nov 20 13:43:03 auth: Debug: http-client: conn 10.10.20.100:443 [1]: SSL handshake successful Nov 20 13:43:03 auth: Debug: http-client: conn 10.10.20.100:443 [1]: Ready for requests Nov 20 13:43:03 auth: Debug: http-client[1]: peer 10.10.20.100:443: Successfully connected (1 connections exist, 0 pending) Nov 20 13:43:03 auth: Debug: http-client: peer 10.10.20.100:443: Successfully connected (1 connections exist, 0 pending) Nov 20 13:43:03 auth: Debug: http-client[1]: peer 10.10.20.100:443: Using 1 idle connections to handle 1 requests (1 total connections ready) Nov 20 13:43:03 auth: Debug: http-client[1]: queue https://auth.mydomain.com:443: Connection to peer 10.10.20.100:443 claimed request [Req1: GET https://auth.mydomain.com/realms/myrealm/protocol/openid-connect/userinfo?to...] Nov 20 13:43:03 auth: Debug: http-client: conn 10.10.20.100:443 [1]: Claimed request [Req1: GET https://auth.mydomain.com/realms/myrealm/protocol/openid-connect/userinfo?to...] Nov 20 13:43:03 auth: Debug: http-client[1]: request [Req1: GET https://auth.mydomain.com/realms/myrealm/protocol/openid-connect/userinfo?to......: Sent header Nov 20 13:43:03 auth: Debug: http-client[1]: peer 10.10.20.100:443: No more requests to service for this peer (1 connections exist, 0 pending) Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1001, ret=1: SSL negotiation finished successfully Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1001, ret=1: SSL negotiation finished successfully Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1001, ret=1: SSLv3/TLS read server session ticket Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1002, ret=1: SSL negotiation finished successfully Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1001, ret=1: SSL negotiation finished successfully Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1001, ret=1: SSL negotiation finished successfully Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1001, ret=1: SSLv3/TLS read server session ticket Nov 20 13:43:03 auth: Debug: auth.mydomain.com: SSL: where=0x1002, ret=1: SSL negotiation finished successfully Nov 20 13:43:03 auth: Debug: http-client: conn 10.10.20.100:443 [1]: Got 401 response for request [Req1: GET https://auth.mydomain.com/realms/myrealm/protocol/openid-connecc2lvbl9z...re...]: Unauthorized (took 7 ms + 20 ms in queue) Nov 20 13:43:03 auth: Debug: http-client[1]: request [Req1: GET https://auth.mydomain.com/realms/myrealm/protocol/openid-connect/userinfo?to......: Finished Nov 20 13:43:03 auth: Debug: http-client[1]: queue https://auth.mydomain.com:443: Dropping request [Req1: GET https://auth.mydomain.com/realms/myrealm/protocol/openid-connect/userinfo?to...] Nov 20 13:43:03 auth: Debug: http-client: host auth.mydomain.com: Host is idle (timeout = 1799981 msecs) Nov 20 13:43:03 auth: Debug: http-client[1]: request [Req1: GET https://auth.mydomain.com/realms/myrealm/protocol/openid-connect/userinfo?to......: Free (requests left=1) Nov 20 13:43:03 auth: Debug: http-client[1]: peer 10.10.20.100:443: No requests to service for this peer (1 connections exist, 0 pending) Nov 20 13:43:03 auth: Debug: http-client: conn 10.10.20.100:443 [1]: No more requests queued; going idle (timeout = 60000 msecs) Nov 20 13:43:05 imap-login: Info: Disconnected: Connection closed (auth service reported temporary failure): user=<francis@mydomain.com>, method=XOAUTH2, rip=10.10.40.30, lip=172.18.0.10, TLS, session=<joax05QKsSAKCige> Nov 20 13:43:05 imap-login: Info: Login: user=<francis@mydomain.com>, method=PLAIN, rip=80.202.241.120, lip=172.18.0.10, mpid=2815, TLS, session=<CYPX05QKj/tQyvF4> Nov 20 13:43:12 imap(francis@mydomain.com)<2822><+yVA1JQKj7wKCigB>: Info: Disconnected: Logged out in=218 out=2443 deleted=0 expunged=0 trashed=0 hdr_count=0 hdr_bytes=0 body_count=0 body_bytes=0 Nov 20 13:43:22 auth: Debug: http-client[1]: peer 10.10.20.100:443: Peer close Nov 20 13:43:22 auth: Debug: http-client[1]: peer 10.10.20.100:443: Peer disconnect Nov 20 13:43:22 auth: Debug: http-client: conn 10.10.20.100:443 [1]: Lost peer; already idle Nov 20 13:43:22 auth: Debug: http-client: conn 10.10.20.100:443 [1]: Detached peer Nov 20 13:43:22 auth: Debug: http-client[1]: peer 10.10.20.100:443: Peer destroy Nov 20 13:43:22 auth: Debug: http-client: host auth.mydomain.com: Host session destroy Nov 20 13:43:22 auth: Debug: http-client[1]: queue https://auth.mydomain.com:443: Destroy Nov 20 13:43:22 auth: Debug: http-client: host auth.mydomain.com: Host destroy Nov 20 13:43:22 auth: Debug: http-client: conn 10.10.20.100:443 [1]: Connection destroy Nov 20 13:43:22 auth: Debug: http-client: conn 10.10.20.100:443 [1]: Connection disconnect Nov 20 13:43:22 auth: Debug: http-client: conn 10.10.20.100:443 [1]: Disconnected: Connection closed (fd=24) Nov 20 13:43:22 auth: Debug: auth.mydomain.com: SSL alert: close notify Nov 20 13:43:22 auth: Debug: http-client: peer 10.10.20.100:443: Peer pool destroy Nov 20 13:43:22 auth: Debug: http-client: peer 10.10.20.100:443 (shared): Peer destroy
Any clue?
Best, Francis