dovecot oauth

Sat Jul 4 21:12:24 EEST 2020

Hello,

I'm trying to configure roundcube / dovecot to work with keycloak.
I activated xoauth2 oauthbearer in dovecot.
But a problem occurs when dovecot tries to contact the keycloak server
(logs are below).

My problem looks like this one:
https://dovecot.org/pipermail/dovecot/2019-December/117768.html
The response to this problem was about a bug in oauth driver
(https://dovecot.org/pipermail/dovecot/2019-December/117787.html).

Mizuki was using Dovecot v2.2.36 (1f10bfa63)
I have Dovecot Dovecot v2.3.4.1 (f79e8e7e4)

I'm wondering if this bug is still present in my version or if I have
another problem.

Both my servers (dovecot and keycloak) are using let's encrypt certificates.
I tried to configure Keycloak with nginx proxy and without it (access
via port 8443) (in case the problem came from the ssl config on the
keycloak server), but still the same error.

If the bug is fixed, then could someone tell me what do I have to put in
the option tls_ca_cert_file?

I tried with /etc/letsencrypt/live/my.host/chain.pem and also certs I
got from let's encrypt website (https://letsencrypt.org/certificates/ /
tried ISRG Root X1 (self-signed) & Let’s Encrypt Authority X3 (IdenTrust
cross-signed) & Let’s Encrypt Authority X3 (Signed by ISRG Root X1))
But I always have the same error.

Thanks,
Kenny

My configs:
- I'm on a Debian Buster with Dovecot / postfix / roundcube
- dovecot -n :
---
# 2.3.4.1 (f79e8e7e4): /etc/dovecot/dovecot.conf
# Pigeonhole version 0.5.4 ()
# OS: Linux 4.19.0-5-cloud-amd64 x86_64 Debian 10.4
auth_debug = yes
auth_mechanisms = xoauth2 oauthbearer login
auth_verbose = yes
debug_log_path = /var/log/dovecot-debug.log
first_valid_gid = 10000
first_valid_uid = 10000
info_log_path = /var/log/dovecot.log
last_valid_gid = 20000
last_valid_uid = 20000
lda_mailbox_autocreate = yes
log_path = /var/log/dovecot.log
mail_debug = yes
mail_gid = mail
mail_location = maildir:~/Maildir
mail_privileged_group = mail
namespace inbox {
  inbox = yes
  location =
  mailbox Drafts {
    special_use = \Drafts
  }
  mailbox Junk {
    special_use = \Junk
  }
  mailbox Sent {
    special_use = \Sent
  }
  mailbox "Sent Messages" {
    special_use = \Sent
  }
  mailbox Trash {
    special_use = \Trash
  }
  prefix =
}
passdb {
  args = /etc/dovecot/dovecot-ldap.conf.ext
  driver = ldap
}
passdb {
  args = /etc/dovecot/dovecot-oauth2.conf.ext
  driver = oauth2
  mechanisms = xoauth2 oauthbearer
}
plugin {
  sieve = file:~/sieve;active=~/.dovecot.sieve
}
protocols = " imap" 
service auth {
  unix_listener /var/spool/postfix/private/auth {
    mode = 0600
    user = postfix  
  }
  unix_listener auth-master {
    mode = 0600
    user = mail
  }
  unix_listener auth-userdb {
    mode = 0600
    user = mail
  }
}
service stats {
  unix_listener stats-reader {
    mode = 0600
    user = mail
  }
  unix_listener stats-writer {
    mode = 0600
    user = mail
  }
}
ssl_cert = </etc/letsencrypt/live/my.host/fullchain.pem
ssl_client_ca_dir = /etc/ssl/certs
ssl_dh = # hidden, use -P to show it
ssl_key = # hidden, use -P to show it
ssl_prefer_server_ciphers = yes
ssl_require_crl = no
userdb {
  args = /etc/dovecot/dovecot-ldap.conf.ext
  driver = ldap
}
userdb {
  args = gid=mail home=/var/mail/%u
  driver = static
}
verbose_ssl = yes
protocol lda {
  info_log_path = /var/log/dovecot-deliver.log
  log_path = /var/log/dovecot-deliver-errors.log
}
------

- dovecot-oauth2.conf.ext
-----
tokeninfo_url =
https://my.keycloak.host/auth/realms/test_saml/protocol/openid-connect/token
introspection_mode = post
introspection_url =
https://my.keycloak.host/auth/realms/test_saml/protocol/openid-connect/token/introspect
username_attribute = email
tls_ca_cert_file = /etc/letsencrypt/live/my.host/chain.pem
#tls_ca_cert_file = /etc/ssl/certs/letsencrypt.pem
#active_attribute = enableMail
#active_value = TRUE
debug =  yes
rawlog_dir = /tmp/oauth2
-----

* Logs:
-------
Jul 04 17:00:12 auth: Debug:
oauth2(my.mail at whatever,::1,<fG8uk6CpBJ0AAAAAAAAAAAAAAAAAAAAB>): oauth2:
Making token validation lookup to
https://my.keycloak.host/auth/realms/test_saml/protocol/openid-connect/token
Jul 04 17:00:12 auth: Debug: http-client: host my.keycloak.host: Host
created
Jul 04 17:00:12 auth: Debug: http-client: host my.keycloak.host: Host
session created
Jul 04 17:00:12 auth: Debug: http-client: host my.keycloak.host: IPs
have expired; need to refresh DNS lookup
Jul 04 17:00:12 auth: Debug: http-client: host my.keycloak.host:
Performing asynchronous DNS lookup
Jul 04 17:00:12 auth: Debug: http-client[1]: request [Req1: GET
https://my.keycloak.host/auth/realms/test_saml/protocol/openid-connect/tokeneyJhbGciOiJFUzI1NiIsInR5cCIgOiAiSldU...
(long token)]: Submitted (requests left=1)
Jul 04 17:00:12 auth: Debug: http-client: host my.keycloak.host: DNS
lookup successful; got 1 IPs
Jul 04 17:00:12 auth: Debug: http-client: peer 151.62.56.14 (shared):
Peer created
Jul 04 17:00:12 auth: Debug: http-client: peer 151.62.56.14: Peer pool
created
Jul 04 17:00:12 auth: Debug: http-client[1]: peer 151.62.56.14: Peer created
Jul 04 17:00:12 auth: Debug: http-client[1]: queue
https://my.keycloak.host: Setting up connection to 151.62.56.14
(SSL=my.keycloak.host) (1 requests pending)
Jul 04 17:00:12 auth: Debug: http-client[1]: peer 151.62.56.14: Linked
queue https://my.keycloak.host (1 queues linked)
Jul 04 17:00:12 auth: Debug: http-client[1]: queue
https://my.keycloak.host: Started new connection to 151.62.56.14
(SSL=my.keycloak.host)
Jul 04 17:00:12 auth: Debug: http-client[1]: peer 151.62.56.14: Creating
1 new connections to handle requests (already 0 usable, connecting to 0,
closing 0)
Jul 04 17:00:12 auth: Debug: http-client[1]: peer 151.62.56.14: Making
new connection 1 of 1 (0 connections exist, 0 pending)
Jul 04 17:00:12 auth: Debug: http-client[1]: conn 151.62.56.14 [0]:
(151.62.56.14): Connecting
Jul 04 17:00:12 auth: Debug: http-client[1]: conn 151.62.56.14 [0]:
(151.62.56.14): Waiting for connect (fd=22) to finish for max 0 msecs
Jul 04 17:00:12 auth: Debug: http-client[1]: conn 151.62.56.14 [0]:
HTTPS connection created (1 parallel connections exist)
Jul 04 17:00:12 auth: Debug: http-client[1]: conn 151.62.56.14 [0]:
(151.62.56.14): Client connected (fd=22)
Jul 04 17:00:12 auth: Debug: http-client[1]: conn 151.62.56.14 [0]:
Connected
Jul 04 17:00:12 auth: Debug: http-client[1]: conn 151.62.56.14 [0]:
Starting SSL handshake
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x10, ret=1:
before SSL initialization
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x1001, ret=1:
before SSL initialization
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x1001, ret=1:
SSLv3/TLS write client hello
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x1002,
ret=-1: SSLv3/TLS write client hello
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x1002,
ret=-1: SSLv3/TLS write client hello
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x1001, ret=1:
SSLv3/TLS write client hello
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x1001, ret=1:
SSLv3/TLS read server hello
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL error: Received
invalid SSL certificate: unable to get issuer certificate: /C=US/O=Let's
Encrypt/CN=Let's Encrypt Authority X3
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x1001, ret=1:
SSLv3/TLS read server certificate
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x1001, ret=1:
SSLv3/TLS read server key exchange
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x1001, ret=1:
SSLv3/TLS read server done
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x1001, ret=1:
SSLv3/TLS write client key exchange
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x1001, ret=1:
SSLv3/TLS write change cipher spec
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x1001, ret=1:
SSLv3/TLS write finished
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x1002,
ret=-1: SSLv3/TLS write finished
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x1002,
ret=-1: SSLv3/TLS write finished

==> dovecot.log <==
Jul 04 17:00:12 auth: Info: Received invalid SSL certificate: unable to
get issuer certificate: /C=US/O=Let's Encrypt/CN=Let's Encrypt Authority X3

==> dovecot-debug.log <==
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x1002,
ret=-1: SSLv3/TLS write finished
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x1001, ret=1:
SSLv3/TLS write finished
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x1001, ret=1:
SSLv3/TLS read change cipher spec
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x1001, ret=1:
SSLv3/TLS read finished
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x20, ret=1:
SSL negotiation finished successfully
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL: where=0x1002, ret=1:
SSL negotiation finished successfully
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL error: Received
invalid SSL certificate: unable to get issuer certificate: /C=US/O=Let's
Encrypt/CN=Let's Encrypt Authority X3
Jul 04 17:00:12 auth: Debug: http-client[1]: peer 151.62.56.14:
Connection failed (1 connections exist, 0 pending)
Jul 04 17:00:12 auth: Debug: http-client: peer 151.62.56.14: Failed to
make connection (1 connections exist, 0 pending)
Jul 04 17:00:12 auth: Debug: http-client[1]: peer 151.62.56.14: Failed
to establish any connection within our peer pool: SSL handshaking with
151.62.56.14 failed: read(SSL 151.62.56.14) failed: Received invalid SSL
certificate: unable to get issuer certificate: /C=US/O=Let's
Encrypt/CN=Let's Encrypt Authority X3 (1 connections exist, 0 pending)
Jul 04 17:00:12 auth: Debug: http-client[1]: queue
https://my.keycloak.host: Failed to set up connection to 151.62.56.14
(SSL=my.keycloak.host): SSL handshaking with 151.62.56.14 failed:
read(SSL 151.62.56.14) failed: Received invalid SSL certificate: unable
to get issuer certificate: /C=US/O=Let's Encrypt/CN=Let's Encrypt
Authority X3 (1 peers pending, 1 requests pending)
Jul 04 17:00:12 auth: Debug: http-client[1]: queue
https://my.keycloak.host: Failed to set up any connection; failing all
queued requests
Jul 04 17:00:12 auth: Debug: http-client[1]: peer 151.62.56.14: Unlinked
queue https://my.keycloak.host (0 queues linked)
Jul 04 17:00:12 auth: Debug: http-client[1]: request [Req1: GET
https://my.keycloak.host/auth/realms/test_saml/protocol/openid-connect/tokeneyJhbGciOiJFUzI1NiIsInR5cCIgOiAiSldUIiwia2...
(long token)]: Error: 9003 SSL handshaking with 151.62.56.14 failed:
read(SSL 151.62.56.14) failed: Received invalid SSL certificate: unable
to get issuer certificate: /C=US/O=Let's Encrypt/CN=Let's Encrypt
Authority X3
Jul 04 17:00:12 auth: Debug: http-client[1]: queue
https://my.keycloak.host: Dropping request [Req1: GET
https://my.keycloak.host/auth/realms/test_saml/protocol/openid-connect/tokeneyJhbGciOiJFUzI1NiIsInR5cCIgOiAiSldUIiwia2...
(long token)]
Jul 04 17:00:12 auth: Debug:
oauth2(my.mail at whatever,::1,<fG8uk6CpBJ0AAAAAAAAAAAAAAAAAAAAB>): oauth2:
callback(-1, SSL handshaking with 151.62.56.14 failed: read(SSL
151.62.56.14) failed: Received invalid SSL certificate: unable to get
issuer certificate: /C=US/O=Let's Encrypt/CN=Let's Encrypt Authority X3)

==> dovecot.log <==
Jul 04 17:00:12 auth: Error:
oauth2(my.mail at whatever,::1,<fG8uk6CpBJ0AAAAAAAAAAAAAAAAAAAAB>): oauth2
failed: SSL handshaking with 151.62.56.14 failed: read(SSL 151.62.56.14)
failed: Received invalid SSL certificate: unable to get issuer
certificate: /C=US/O=Let's Encrypt/CN=Let's Encrypt Authority X3

==> dovecot-debug.log <==
Jul 04 17:00:12 auth: Debug: http-client[1]: request [Req1: GET
https://my.keycloak.host/auth/realms/test_saml/protocol/openid-connect/tokeneyJhbGciOiJFUzI1NiIsInR5cCIgOiAiSldUIiwia2...
(long token)]: Destroy (requests left=1)
Jul 04 17:00:12 auth: Debug: http-client[1]: request [Req1: GET
https://my.keycloak.host/auth/realms/test_saml/protocol/openid-connect/tokeneyJhbGciOiJFUzI1NiIsInR5cCIgOiAiSldUIiwia2...
(long token)]: Free (requests left=0)
Jul 04 17:00:12 auth: Debug: http-client[1]: conn 151.62.56.14 [0]: SSL
handshaking with 151.62.56.14 failed: read(SSL 151.62.56.14) failed:
Received invalid SSL certificate: unable to get issuer certificate:
/C=US/O=Let's Encrypt/CN=Let's Encrypt Authority X3
Jul 04 17:00:12 auth: Debug: http-client[1]: conn 151.62.56.14 [0]:
Connection close
Jul 04 17:00:12 auth: Debug: http-client[1]: conn 151.62.56.14 [0]:
Connection disconnect
Jul 04 17:00:12 auth: Debug: http-client[1]: conn 151.62.56.14 [0]:
(151.62.56.14): Disconnected: Connection closed: Received invalid SSL
certificate: unable to get issuer certificate: /C=US/O=Let's
Encrypt/CN=Let's Encrypt Authority X3 (fd=22)
Jul 04 17:00:12 auth: Debug: my.keycloak.host: SSL error: Received
invalid SSL certificate: unable to get issuer certificate: /C=US/O=Let's
Encrypt/CN=Let's Encrypt Authority X3
Jul 04 17:00:12 auth: Debug: http-client[1]: conn 151.62.56.14 [0]:
Detached peer
Jul 04 17:00:12 auth: Debug: http-client[1]: conn 151.62.56.14 [0]:
Connection destroy
-------