SASL authentication failed; cannot authenticate to server smtp.gmail.com[X.X.X.X]: bad protocol / cancel

[nightfly83]

Hi, on my system (Ubuntu 16.4.07 LTS with ESM), when try to connect to gmail via Postfix and sasl-xoauth2 I receive this error:

Oct 8 08:19:01 fw-scar postfix/smtp[19884]: 2467B284D8C: to=destinationaddress@gmail.com, relay=smtp.gmail.com[142.251.9.109]:587, delay=0.72, delays=0.1/0.03/0.58/0, dsn=4.7.0, status=deferred (SASL authentication failed; cannot authenticate to server smtp.gmail.com[142.251.9.109]: bad protocol / cancel)

Everything seems to be configured correctly:

/etc/sasl-xoauth2.conf**
**{
  "client_id": "MY CLIENT ID",
  "client_secret": "MY CLIENT SECRET",
  "log_to_syslog_on_failure": "yes",
  "log_full_trace_on_failure": "yes"
}**

**sasl-xoauth2-test-config -c /etc/sasl-xoauth2.conf
Config check passed.**

**sasl-xoauth2-test-config -r /etc/tokens/rcstudioscar.json
Config check passed.
Token refresh succeeded.

Just in case, I copied the certificate file (with the *crt extension) in /var/spool/postfix/etc/ssl/certs/ and a copy of /etc/tokens/mytokensfile is in /var/spool/postfix/etc/tokens (just to avoid any chroot issue).

This is my saslfinger output:

saslfinger - postfix Cyrus sasl configuration sab  8 ott 2022, 09.09.53, CEST
version: 1.0.4
mode: client-side SMTP AUTH

-- basics --
Postfix: 3.1.0
System: Ubuntu 16.04.7 LTS \n \l

-- smtp is linked to --
        libsasl2.so.2 => /usr/lib/i386-linux-gnu/libsasl2.so.2 (0xb74c9000)

-- active SMTP AUTH and TLS parameters for smtp --
relayhost = [smtp.gmail.com]:587
smtp_sasl_auth_enable = yes
smtp_sasl_mechanism_filter = xoauth2
smtp_sasl_password_maps = hash:/etc/postfix/sasl_passwd
smtp_sasl_security_options =
smtp_tls_CAfile = /etc/ssl/certs/ca-certificates.crt
smtp_tls_security_level = encrypt
smtp_tls_session_cache_database = btree:${data_directory}/smtp_scache

-- listing of /usr/lib/sasl2 --
totale 656
drwxr-xr-x   2 root root   4096 ott  7 21:08 .
drwxr-xr-x 158 root root  69632 ott  8 08:00 ..
-rw-r--r--   1 root root      4 ott  7 15:43 berkeley_db.active
-rw-r--r--   1 root root      4 feb 22  2022 berkeley_db.txt
-rw-r--r--   1 root root 580924 ott  7 20:47 libsasl-xoauth2.so
-rw-r--r--   1 root root    190 ott  7 21:08 sasl-xoauth2.conf

-- listing of /usr/local/lib/sasl2 --
totale 576
drwxr-xr-x  2 root root   4096 ott  7 12:34 .
drwxr-xr-x 13 root root   4096 ott  7 12:34 ..
-rw-r--r--  1 root root 580924 ott  7 12:34 libsasl-xoauth2.so

-- listing of /etc/postfix/sasl --
totale 8
drwxr-xr-x 2 root root 4096 lug 28  2020 .
drwxr-xr-x 3 root root 4096 ott  7 21:40 ..

-- permissions for /etc/postfix/sasl_passwd --
-rw-r--r-- 1 root root 79 ott  7 20:51 /etc/postfix/sasl_passwd

-- permissions for /etc/postfix/sasl_passwd.db --
-rw-r--r-- 1 root root 12288 ott  7 20:51 /etc/postfix/sasl_passwd.db

/etc/postfix/sasl_passwd.db is up to date.

-- active services in /etc/postfix/master.cf --
# service type  private unpriv  chroot  wakeup  maxproc command + args
#               (yes)   (yes)   (no)    (never) (100)
smtp      inet  n       -       y       -       -       smtpd
smtps     inet  n       -       n       -       -       smtpd
pickup    unix  n       -       y       60      1       pickup
cleanup   unix  n       -       y       -       0       cleanup
qmgr      unix  n       -       n       300     1       qmgr
tlsmgr    unix  -       -       y       1000?   1       tlsmgr
rewrite   unix  -       -       y       -       -       trivial-rewrite
bounce    unix  -       -       y       -       0       bounce
defer     unix  -       -       y       -       0       bounce
trace     unix  -       -       y       -       0       bounce
verify    unix  -       -       y       -       1       verify
flush     unix  n       -       y       1000?   0       flush
proxymap  unix  -       -       n       -       -       proxymap
proxywrite unix -       -       n       -       1       proxymap
smtp      unix  -       -       n       -       -       smtp
relay     unix  -       -       n       -       -       smtp
showq     unix  n       -       y       -       -       showq
error     unix  -       -       y       -       -       error
retry     unix  -       -       y       -       -       error
discard   unix  -       -       y       -       -       discard
local     unix  -       n       n       -       -       local
virtual   unix  -       n       n       -       -       virtual
lmtp      unix  -       -       y       -       -       lmtp
anvil     unix  -       -       y       -       1       anvil
scache    unix  -       -       y       -       1       scache
maildrop  unix  -       n       n       -       -       pipe
  flags=DRhu user=vmail argv=/usr/bin/maildrop -d ${recipient}
uucp      unix  -       n       n       -       -       pipe
  flags=Fqhu user=uucp argv=uux -r -n -z -a$sender - $nexthop!rmail ($recipient)
ifmail    unix  -       n       n       -       -       pipe
  flags=F user=ftn argv=/usr/lib/ifmail/ifmail -r $nexthop ($recipient)
bsmtp     unix  -       n       n       -       -       pipe
  flags=Fq. user=bsmtp argv=/usr/lib/bsmtp/bsmtp -t$nexthop -f$sender $recipient
scalemail-backend unix  -       n       n       -       2       pipe
  flags=R user=scalemail argv=/usr/lib/scalemail/bin/scalemail-store ${nexthop} ${user} ${extension}
mailman   unix  -       n       n       -       -       pipe
  flags=FR user=list argv=/usr/lib/mailman/bin/postfix-to-mailman.py
  ${nexthop} ${user}

-- mechanisms on [smtp.gmail.com]:587 --

Some additional informations:

1) I was unable to pickup any email via the sasl_xoauth2 lib before to copy it in /var/lib (i was getting the error "No worthy mechs found"); 2) With these 2 entries in my /etc/sasl-xoauth2.conf file:

"log_to_syslog_on_failure": "yes",
"log_full_trace_on_failure": "yes"

I'm unable to get any trace inside /var/log/syslog:

Oct  8 08:57:09 fw-scar sasl-xoauth2: set log_full_trace_on_failure to see full 14 line(s) of tracing.
Oct  8 08:57:09 fw-scar sasl-xoauth2: set log_full_trace_on_failure to see full 14 line(s) of tracing.
Oct  8 08:57:09 fw-scar sasl-xoauth2: auth failed: 2022-10-08 08:57:09: TokenStore::Refresh: request failed
Oct  8 08:57:09 fw-scar sasl-xoauth2: auth failed: 2022-10-08 08:57:09: TokenStore::Refresh: request failed
Oct  8 08:57:09 fw-scar sasl-xoauth2: set log_full_trace_on_failure to see full 14 line(s) of tracing.
Oct  8 08:57:09 fw-scar sasl-xoauth2: set log_full_trace_on_failure to see full 14 line(s) of tracing.

And no trace log inside /var/log/mail.log:

Oct  8 08:57:09 fw-scar sasl-xoauth2: auth failed: 2022-10-08 08:57:09: TokenStore::Refresh: request failed
Oct  8 08:57:09 fw-scar sasl-xoauth2: set log_full_trace_on_failure to see full 14 line(s) of tracing.
Oct  8 08:57:09 fw-scar sasl-xoauth2: auth failed: 2022-10-08 08:57:09: TokenStore::Refresh: request failed
Oct  8 08:57:09 fw-scar sasl-xoauth2: set log_full_trace_on_failure to see full 14 line(s) of tracing.
Oct  8 08:57:09 fw-scar sasl-xoauth2: auth failed: 2022-10-08 08:57:09: TokenStore::Refresh: request failed
Oct  8 08:57:09 fw-scar sasl-xoauth2: set log_full_trace_on_failure to see full 14 line(s) of tracing.
Oct  8 08:57:09 fw-scar sasl-xoauth2: auth failed: 2022-10-08 08:57:09: TokenStore::Refresh: request failed
Oct  8 08:57:09 fw-scar sasl-xoauth2: set log_full_trace_on_failure to see full 14 line(s) of tracing.

Any help will be appreciated.

Thanks.

[tarickb]

The fact that you're seeing "set log_full_trace_on_failure to see full ..." in your logs despite having log_full_trace_on_failure set in your config file leads me to believe that the library is probably looking for its config file in an unexpected spot. I'm assuming you've built the library yourself since we don't have a pre-built library for Xenial, so can you double-check the baked-in config-file path?

$ strings PATH_TO_LIB_DIR/libsasl-xoauth2.so | grep sasl-xoauth2.conf
/etc/sasl-xoauth2.conf

My guess is that your library is looking in /usr/local/etc rather than /etc, in which case you'll have to move sasl-xoauth2.conf.

[nightfly83]

Yes, you're guess was right:

root@fw-scar:~# strings /usr/lib/sasl2/libsasl-xoauth2.so | grep sasl-xoauth2.conf /usr/local/etc/sasl-xoauth2.conf And sure, the package was compiled from source.

Problem solved, Thanks for your help.