search

tarickb / sasl-xoauth2

SASL plugin for XOAUTH2
Other
72 stars 20 forks source link

RHEL 8 and sasl-xoauth2 #63

Closed augustus-p closed 1 year ago

augustus-p commented 1 year ago

Hi

Excuse the lengthy post, best to have all the details & context...

First let me say, an excellent package to address the demands of Gmail & Office365 without basic authentication.

I have installed and configured on RHEL 8 the Red Hat version of sasl-xoauth2. RH made the package available from the epel repo listed at https://copr.fedorainfracloud.org/coprs/jjelen/sasl-xoauth2/ for various RHEL/Fedora releases. That's the version I used on RHEL 8.

I had already set up an Office365 account and configured various elements such as client id, tenant, scope and all the fun stuff required for managing OAuth2. Objective was to permit postfix on RHEL 8 to issue SMTP mail via the Office365 account using the OAuth2 client id & token. Hence no need for basic authentication.

Postfix has been configured to use the sasl-xoauth2 plugin. Most of this is covered in the README.

However, there is one fundamental problem which confirmed my previous observations and tests when building sasl-xoauth2 from source on RHEL 8. The sasl-xoauth2 plugin fails to authenticate. Here are the last few postfix log entries:

Apr 26 10:01:48 jaspah postfix/smtp[8401]: Trusted TLS connection established to smtp.office365.com[52.97.211.242]:587: TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits) key-exchange ECDHE (P-384) server-signature RSA-PSS (2048 bits) server-digest SHA256
Apr 26 10:01:48 jaspah postfix/smtp[8401]: SSL_connect:SSL negotiation finished successfully
Apr 26 10:01:48 jaspah postfix/smtp[8401]: SSL_connect:SSL negotiation finished successfully
Apr 26 10:01:48 jaspah postfix/smtp[8401]: SSL_connect:SSLv3/TLS read server session ticket
Apr 26 10:01:49 jaspah postfix/smtp[8401]: 0B54620C6416: SASL authentication failed; cannot authenticate to server smtp.office365.com[52.97.211.242]: generic failure
Apr 26 10:01:49 jaspah sasl-xoauth2[8401]: auth failed: 2023-04-26 10:01:49: TokenStore::Write: failed to open file /etc/postfix/tokens/ruralfunkexp@outlook.json.8401.1682499709308 for writing: Permission denied

Not sure if the final line is as a result of the failure to authenticate previoulsy, the file/directory permissions are correct. And no chroot

Using the sasl-xoauth2 plugin supports using an access_token json file in the smtp_sasl_password_maps file but it fails to authenticate with Office365. It assumes that a token file is used, not embedded token details.

I then loaded the cyrus-sasl-xoauth2 plugin (I didn't need to install the entire package avalable at https://github.com/moriyoshi/cyrus-sasl-xoauth2). I had to delete the original sasl-xoauth2 plugin and create symlinks. The cyrus plugin does not support the use of an access_token json file and is dependent on an embedded token in the smtp_sasl_password_maps file -- not ideal. However, the cyrus plugin authenticates with Office365.

Therefore in /usr/lib64/sasl2/...

load cyrus-sasl-xoauth2 plugin - libsasl-xoauth2.so.3.0.0 delete sasl-xoauth2 plugin after keeping backup - libsasl-xoauth2.so

Create symlinks: symlink - libsasl-xoauth2.so -> libsasl-xoauth2.so.3.0.0 symlink - libsasl-xoauth2.so.3 -> libsasl-xoauth2.so.3.0.0

What was also a concern was the sudden 'disappearance' for no obvious reason of the sasl-xoauth2 plugin when reported by 'pluginviewer -c'. Could be when I added the full tracing log option to sasl-xoauth2.conf. Here it is before it disappeared:

$ pluginviewer -c [extract]
Installed and properly configured SASL (client side) mechanisms are:
  GSS-SPNEGO GSSAPI EXTERNAL XOAUTH2 LOGIN PLAIN ANONYMOUS
Available SASL (client side) mechanisms matching your criteria are:
  GSS-SPNEGO GSSAPI EXTERNAL XOAUTH2 LOGIN PLAIN ANONYMOUS
List of client plugins follows
Plugin "sasl-xoauth2" [loaded],     API version: 4     <================== sasl-xoauth2 plugin - SPF: 60
    SASL mechanism: XOAUTH2, best SSF: 60
    security flags: NO_ANONYMOUS|PASS_CREDENTIALS
    features: WANT_CLIENT_FIRST|PROXY_AUTHENTICATION

After loading cyrus-sasl-xoauth2:

$ pluginviewer -c [extrcat]
Installed and properly configured SASL (client side) mechanisms are:
  GSS-SPNEGO GSSAPI EXTERNAL LOGIN PLAIN XOAUTH2 ANONYMOUS
Available SASL (client side) mechanisms matching your criteria are:
  GSS-SPNEGO GSSAPI EXTERNAL LOGIN PLAIN XOAUTH2 ANONYMOUS
List of client plugins follows
Plugin "sasl-xoauth2" [loaded],     API version: 4     <========== cyrus-sasl-xoauth2 plugin - SPF: 0
    SASL mechanism: XOAUTH2, best SSF: 0
    security flags: NO_ANONYMOUS|PASS_CREDENTIALS
    features: WANT_CLIENT_FIRST|PROXY_AUTHENTICATION

Therefore using all the components of your sasl-xoauth2 but substituting the xoauth2 plugin for moriyoshi's cyrus-sasl-xoauth2 plugin postfix authenticates and can issue emails via Office365.

If the sasl-xoauth2 plugin authorisation issue can be resolved that would be ideal because it supports using an access_token json file in the postfix smtp_sasl_password_maps file. Also it meets all other requirements to permit postfix to send emails via Office365.

I should add that it could be some trivial config that I've not set up, in which case can you please advise.

Many thanks again for a great package.

The same issue is apparent whether using the Red Hat package or building from source. I haven't tested on RHEL 7 but will do so in due course.

Regards

augustus-p

augustus-p commented 1 year ago

For information, it's the same situation on RHEL 7; the sasl-xoauth2 plugin generates a failure when trying to authorise. Replacing the plugin with the cyrus-sasl-xoauth2 version (no symlinks required) and embedding the access_token in the postfix smtp_sasl_password_maps file authorisation is successfull and email is sent via SMTP uising Office265 tenant.

augustus-p

tarickb commented 1 year ago

Thanks for the detailed notes. My guess is that the user under which Postfix is running (probably postfix) doesn't have write access on the directory containing the token file (rather than the token file itself).

If that's not the case, a few additional details might be helpful:

  1. Can you enable verbose logging and attach the resulting syslog entries?
  2. Can you attach the output of stat /etc/postfix/tokens/ruralfunkexp@outlook.json.8401.1682499709308 and stat /etc/postfix/tokens/?
  3. Can you include a copy of your smtp_sasl_password_maps (with sensitive parts redacted)?
augustus-p commented 1 year ago

Thanks for the quick response.

In answer to your questions...

> My guess is that the user under which Postfix is running (probably postfix) doesn't have write access on the directory containing the token file (rather than the token file itself). - Permissions look fine

$ ls -la /etc/postfix [Extract]
drwxr-xr-x.   5 root    root     4096 Apr 28 09:05 .
drwxr-xr-x. 168 root    root    12288 Apr 28 08:52 ..
drwxr-xr-x. 2 postfix postfix   114 Apr 26 10:08 tokens

$ ls -la /etc/postfix/tokens  [Extract]
total 16
drwxr-xr-x. 2 postfix postfix  114 Apr 26 10:08 .
drwxr-xr-x. 5 root    root    4096 Apr 28 08:41 ..
-rw-rw-r--. 1 postfix postfix 2792 Apr 28 08:42 ruralfunkexp@outlook.json

> Can you enable verbose logging and attach the resulting syslog entries? - Logged to postfix maillog

# /var/log/maillog [Extract + redactions]

Apr 28 09:15:24 jaspah postfix/smtpd[11344]: connect from localhost[127.0.0.1]
Apr 28 09:15:24 jaspah postfix/smtpd[11344]: discarding EHLO keywords: CHUNKING
Apr 28 09:15:24 jaspah postfix/smtpd[11344]: D1C9020B9288: client=localhost[127.0.0.1]
Apr 28 09:15:24 jaspah postfix/cleanup[11347]: D1C9020B9288: info: header Subject: Test mail from jaspah - Fri, 28 Apr 2023 09:15:24 +0100 from localhost[127.0.0.1]; from=<############@outlook.com> to=<##############> proto=ESMTP helo=<jaspah>
.
.
Apr 28 09:15:25 jaspah postfix/smtp[11348]: SSL_connect:SSL negotiation finished successfully
Apr 28 09:15:25 jaspah postfix/smtp[11348]: SSL_connect:SSLv3/TLS read server session ticket
Apr 28 09:15:26 jaspah postfix/smtp[11348]: D1C9020B9288: SASL authentication failed; cannot authenticate to server smtp.office365.com[40.99.214.130]: generic failure
Apr 28 09:15:26 jaspah sasl-xoauth2[11348]: auth failed:
Apr 28 09:15:26 jaspah sasl-xoauth2[11348]:  2023-04-28 09:15:25: Client: created
Apr 28 09:15:26 jaspah sasl-xoauth2[11348]:  2023-04-28 09:15:25: Client::DoStep: called with state 0
Apr 28 09:15:26 jaspah sasl-xoauth2[11348]:  2023-04-28 09:15:25: Client::InitialStep: TriggerAuthNameCallback err=0
Apr 28 09:15:26 jaspah sasl-xoauth2[11348]:  2023-04-28 09:15:25: Client::InitialStep: TriggerPasswordCallback err=0
Apr 28 09:15:26 jaspah sasl-xoauth2[11348]:  2023-04-28 09:15:25: TokenStore::Read: file=/etc/postfix/tokens/ruralfunkexp@outlook.json
Apr 28 09:15:26 jaspah sasl-xoauth2[11348]:  2023-04-28 09:15:25: TokenStore::Read: refresh=###############
Apr 28 09:15:26 jaspah sasl-xoauth2[11348]:  2023-04-28 09:15:25: TokenStore::GetAccessToken: token expired. refreshing.
Apr 28 09:15:26 jaspah sasl-xoauth2[11348]:  2023-04-28 09:15:25: TokenStore::Refresh: attempt 1
Apr 28 09:15:26 jaspah sasl-xoauth2[11348]:  2023-04-28 09:15:25: TokenStore::Refresh: token_endpoint: https://login.microsoftonline.com/consumers/oauth2/v2.0/token
Apr 28 09:15:26 jaspah sasl-xoauth2[11348]:  2023-04-28 09:15:25: TokenStore::Refresh: request: client_id=#############&client_secret=###########&grant_type=refresh_token&refresh_token=###############
Apr 28 09:15:26 jaspah sasl-xoauth2[11348]:  2023-04-28 09:15:26: TokenStore::Refresh: code=200, response={"token_type":"Bearer","scope":"https://outlook.office.com/SMTP.Send","expires_in":3599,"ext_expires_in":3599,"access_token":"################
Apr 28 09:15:26 jaspah sasl-xoauth2[11348]:  2023-04-28 09:15:26: TokenStore::Refresh: response includes updated refresh token
Apr 28 09:15:26 jaspah sasl-xoauth2[11348]:  2023-04-28 09:15:26: TokenStore::Write: failed to open file /etc/postfix/tokens/ruralfunkexp@outlook.json.11348.1682669726218 for writing: Permission denied
Apr 28 09:15:26 jaspah sasl-xoauth2[11348]:  2023-04-28 09:15:26: Client::DoStep: new state 0 and err -1
Apr 28 09:15:26 jaspah sasl-xoauth2[11348]:  2023-04-28 09:15:26: Client: destroyed

> Can you attach the output of stat /etc/postfix/tokens/ruralfunkexp@outlook.json.8401.1682499709308 and stat /etc/postfix/tokens/?

I think this may be the issue. There appears to be a temporary file extension generated (.8401.1682499709308) each time postfix tries to authenticate. I doubt it's a postfix activity since it does not occur with the cyrus plugin. See extract above from maillog -- the extension in this instance is '.11348.1682669726218'. The file does not exist therefore cannot be opened. Should it not be using the filename /etc/postfix/tokens/ruralfunkexp@outlook.json?

$ stat /etc/postfix/tokens/ruralfunkexp@outlook.json 
  File: /etc/postfix/tokens/ruralfunkexp@outlook.json
  Size: 2792        Blocks: 8          IO Block: 4096   regular file
Device: fd00h/64768d    Inode: 103084898   Links: 1
Access: (0664/-rw-rw-r--)  Uid: (   89/ postfix)   Gid: (   89/ postfix)
Context: unconfined_u:object_r:postfix_etc_t:s0
Access: 2023-04-28 08:46:15.266673719 +0100
Modify: 2023-04-28 08:42:58.803505045 +0100
Change: 2023-04-28 08:45:15.944031393 +0100
 Birth: 2023-04-25 14:52:09.003175064 +0100

$ stat /etc/postfix/tokens
  File: /etc/postfix/tokens
  Size: 114         Blocks: 0          IO Block: 4096   directory
Device: fd00h/64768d    Inode: 103084884   Links: 2
Access: (0755/drwxr-xr-x)  Uid: (   89/ postfix)   Gid: (   89/ postfix)
Context: unconfined_u:object_r:postfix_etc_t:s0
Access: 2023-04-28 08:49:17.004484426 +0100
Modify: 2023-04-26 10:08:08.566004023 +0100
Change: 2023-04-28 08:49:08.200085046 +0100
 Birth: 2023-04-25 14:48:28.814190567 +0100

Can you include a copy of your smtp_sasl_password_maps (with sensitive parts redacted)?

$ smtp_sasl_password_maps

[smtp.office365.com]:587 #############@outlook.com:/etc/postfix/tokens/ruralfunkexp@outlook.json

Hope that helps.

Let me know if you need more details.

Thanks.

augustus-p

tarickb commented 1 year ago

Okay, a few more tests/details might be helpful here:

  1. Can you try chmod 0600 /etc/postfix/tokens/ruralfunkexp@outlook.json, then repeat your test and include verbose logs?
  2. Can you verify that the smtp process is indeed running as postfix? Might be helpful to see /etc/postfix/main.cf (particularly the value of mail_owner) and /etc/postfix/master.cf.
augustus-p commented 1 year ago

I've grabbed what might be useful regarding postfix. You'll see that postfix runs as command master for connections on port 25. Though not relevant to SMTP connections to outlook.com.

$ ls -l tokens/ruralfunkexp@outlook.json 
-rw-------. 1 postfix postfix 2792 Apr 28 16:26 tokens/ruralfunkexp@outlook.json

$ postconf -n|grep mail_owner
mail_owner = postfix

$ grep smtp master.cf|grep -v smtpd
smtp      unix  -       -       n       -       -       smtp
relay     unix  -       -       n       -       -       smtp

# lsof -nP -i:25
COMMAND  PID USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
master  8735 root   14u  IPv4  68064      0t0  TCP 127.0.0.1:25 (LISTEN)

# lsof -i:25
COMMAND  PID USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
master  8735 root   14u  IPv4  68064      0t0  TCP localhost:smtp (LISTEN)

$ ps -ef|grep postfix|grep -v grep
root        8735       1  0 08:41 ?        00:00:00 /usr/libexec/postfix/master -w
postfix    30228    8735  0 16:27 ?        00:00:00 qmgr -l -t unix -u
postfix    30229    8735  0 16:27 ?        00:00:00 pickup -l -t unix -u
postfix    30243    8735  0 16:27 ?        00:00:00 tlsmgr -l -t unix -u

# /var/log/maillog [Extract + redactions]

Apr 28 16:27:19 jaspah postfix/smtpd[30241]: connect from localhost[127.0.0.1]
Apr 28 16:27:19 jaspah postfix/cleanup[30245]: 0C34F20A10D9: info: header Subject: Test mail from jaspah - Fri, 28 Apr 2023 16:27:18 +0100 from localhost[127.0.0.1]; from=<#########@outlook.com> to=<outlook@roadwater.org> proto=ESMTP helo=<jaspah>
Apr 28 16:27:19 jaspah postfix/cleanup[30245]: 0C34F20A10D9: message-id=<20230428162718.030240@jaspah>
Apr 28 16:27:19 jaspah postfix/qmgr[30228]: 0C34F20A10D9: from=<#########@outlook.com>, size=507, nrcpt=1 (queue active)

Apr 28 16:27:19 jaspah postfix/smtp[30246]: SSL_connect:SSL negotiation finished successfully
Apr 28 16:27:19 jaspah postfix/smtp[30246]: SSL_connect:SSL negotiation finished successfully
Apr 28 16:27:19 jaspah postfix/smtp[30246]: SSL_connect:SSLv3/TLS read server session ticket
Apr 28 16:27:20 jaspah postfix/smtp[30246]: 0C34F20A10D9: SASL authentication failed; cannot authenticate to server smtp.office365.com[40.99.213.82]: generic failure
Apr 28 16:27:20 jaspah sasl-xoauth2[30246]: auth failed:
Apr 28 16:27:20 jaspah sasl-xoauth2[30246]:  2023-04-28 16:27:19: Client: created
Apr 28 16:27:20 jaspah sasl-xoauth2[30246]:  2023-04-28 16:27:19: Client::DoStep: called with state 0
Apr 28 16:27:20 jaspah sasl-xoauth2[30246]:  2023-04-28 16:27:19: Client::InitialStep: TriggerAuthNameCallback err=0
Apr 28 16:27:20 jaspah sasl-xoauth2[30246]:  2023-04-28 16:27:19: Client::InitialStep: TriggerPasswordCallback err=0
Apr 28 16:27:20 jaspah sasl-xoauth2[30246]:  2023-04-28 16:27:19: TokenStore::Read: file=/etc/postfix/tokens/ruralfunkexp@outlook.json
Apr 28 16:27:20 jaspah sasl-xoauth2[30246]:  2023-04-28 16:27:19: TokenStore::Read: refresh=#########, access=#########
Apr 28 16:27:20 jaspah sasl-xoauth2[30246]:  2023-04-28 16:27:19: TokenStore::GetAccessToken: token expired. refreshing.
Apr 28 16:27:20 jaspah sasl-xoauth2[30246]:  2023-04-28 16:27:19: TokenStore::Refresh: attempt 1
Apr 28 16:27:20 jaspah sasl-xoauth2[30246]:  2023-04-28 16:27:19: TokenStore::Refresh: token_endpoint: https://login.microsoftonline.com/consumers/oauth2/v2.0/token
Apr 28 16:27:20 jaspah sasl-xoauth2[30246]:  2023-04-28 16:27:19: TokenStore::Refresh: request: client_id=#########&client_secret=#########&grant_type=refresh_token&refresh_token=#########
Apr 28 16:27:20 jaspah sasl-xoauth2[30246]:  2023-04-28 16:27:20: TokenStore::Refresh: code=200, response={"token_type":"Bearer","scope":"https://outlook.office.com/SMTP.Send","expires_in":3600,"ext_expires_in":3600,"access_token":"#########
Apr 28 16:27:20 jaspah sasl-xoauth2[30246]:  2023-04-28 16:27:20: TokenStore::Refresh: response includes updated refresh token
Apr 28 16:27:20 jaspah sasl-xoauth2[30246]:  2023-04-28 16:27:20: TokenStore::Write: failed to open file /etc/postfix/tokens/ruralfunkexp@outlook.json.30246.1682695640127 for writing: Permission denied
Apr 28 16:27:20 jaspah sasl-xoauth2[30246]:  2023-04-28 16:27:20: Client::DoStep: new state 0 and err -1
Apr 28 16:27:20 jaspah sasl-xoauth2[30246]:  2023-04-28 16:27:20: Client: destroyed

Incidentally why does the plugin look to read/write to the json file + extension 30246.1682695640127 (is that a PID.xxxx?)

Thanks again for the quick response.

augustus-p

tarickb commented 1 year ago

Is it possible you have SELinux enabled? Can you check the audit logs?

Incidentally why does the plugin look to read/write to the json file + extension 30246.1682695640127 (is that a PID.xxxx?)

Yeah it's PID and a timestamp. It writes the updated token to a new file (the token file path plus ".$pid.$timestamp") then atomically renames that to the to token file path. It does this to avoid the potential for a concurrent process to read garbage out of the token file.

augustus-p commented 1 year ago

Good call, selinux set to from enforcing to permissive did the trick. I'll need to sort policy to sort enforcing mode, it's a requirement.

I'll carry on testing and report back any issues.

Many thanks. You can now announce that it also works on RHEL with the selinux caveat ;)

augustus-p

augustus-p commented 1 year ago

Quick update...

Asserted SELinux policies in enforcing mode on both RHEL 7 & 8 and both systems now successfully issuing mail via Office365 scope SMTP.send.

Refesh token & access token can also be updated as part of separate script to be run manaully or via cron if required.

Thanks

augustus-p

tarickb commented 1 year ago

Thanks @augustus-p! I've added a note in the README about using pre-built packages for RHEL/Fedora, and a warning about SELinux.