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=
Any clue?
Best, Francis