"unknown mail transport error" after upgrading to v3.5.1

[firefrei]

Hello,

I am running two independent instances of docker-postfix. Both failed to relay mails after upgrading to the latest image version (v3.5.1).

mailq says: "unknown mail transport error" logs say:

...
postfix_1  | 2022-06-20T20:48:13.644584+00:00 INFO    postfix/qmgr[204]: B45FD26006F: from=<a@example.com>, size=1070, nrcpt=1 (queue active)
postfix_1  | 2022-06-20T20:48:13.644996+00:00 INFO    postfix/qmgr[204]: B46A82600ED: from=<a@example.com>, size=1081, nrcpt=1 (queue active)
postfix_1  | 2022-06-20T20:48:14.644048+00:00 WARNING postfix/qmgr[204]: warning: private/smtp socket: malformed response
postfix_1  | 2022-06-20T20:48:14.644061+00:00 WARNING postfix/qmgr[204]: warning: transport smtp failure -- see a previous warning/fatal/panic logfile record for the problem description
postfix_1  | 2022-06-20T20:48:14.644081+00:00 WARNING postfix/master[202]: warning: process /usr/libexec/postfix/smtp pid 276 killed by signal 11
postfix_1  | 2022-06-20T20:48:14.644088+00:00 WARNING postfix/master[202]: warning: /usr/libexec/postfix/smtp: bad command startup -- throttling
postfix_1  | 2022-06-20T20:48:14.699067+00:00 INFO    postfix/error[284]: 0F6AF2600E5: to=<b@example.com>, relay=none, delay=51985, delays=51984/1/0/0.05, dsn=4.3.0, status=deferred (unknown mail transport error)
postfix_1  | 2022-06-20T20:48:14.738454+00:00 INFO    postfix/error[287]: A8F972600F7: to=<c@example.com>, relay=none, delay=38594, delays=38593/1/0/0.08, dsn=4.3.0, status=deferred (unknown mail transport error)
postfix_1  | 2022-06-20T20:48:14.738538+00:00 INFO    postfix/error[289]: A46CC2600E3: to=<d@example.com>, relay=none, delay=49635, delays=49634/1/0/0.08, dsn=4.3.0, status=deferred (unknown mail transport error)
postfix_1  | 2022-06-20T20:48:14.739029+00:00 INFO    postfix/error[285]: A77472600E1: to=<c@example.com>, relay=none, delay=60374, delays=60373/1/0/0.09, dsn=4.3.0, status=deferred (unknown mail transport error)
postfix_1  | 2022-06-20T20:48:14.739134+00:00 INFO    postfix/error[291]: 1BF8526006E: to=<c@example.com>, relay=none, delay=67982, delays=67981/1/0/0.08, dsn=4.3.0, status=deferred (unknown mail transport error)
postfix_1  | 2022-06-20T20:48:14.740031+00:00 WARNING postfix/qmgr[204]: warning: private/smtp socket: malformed response
postfix_1  | 2022-06-20T20:48:14.740040+00:00 WARNING postfix/qmgr[204]: warning: transport smtp failure -- see a previous warning/fatal/panic logfile record for the problem description
postfix_1  | 2022-06-20T20:48:14.740480+00:00 WARNING postfix/master[202]: warning: process /usr/libexec/postfix/smtp pid 278 killed by signal 11
postfix_1  | 2022-06-20T20:48:14.748416+00:00 WARNING postfix/qmgr[204]: warning: private/smtp socket: malformed response
postfix_1  | 2022-06-20T20:48:14.748426+00:00 WARNING postfix/qmgr[204]: warning: transport smtp failure -- see a previous warning/fatal/panic logfile record for the problem description
postfix_1  | 2022-06-20T20:48:14.748519+00:00 WARNING postfix/master[202]: warning: process /usr/libexec/postfix/smtp pid 277 killed by signal 11
postfix_1  | 2022-06-20T20:48:14.759636+00:00 WARNING postfix/master[202]: warning: process /usr/libexec/postfix/smtp pid 275 killed by signal 11
postfix_1  | 2022-06-20T20:48:14.759660+00:00 WARNING postfix/qmgr[204]: warning: private/smtp socket: malformed response
postfix_1  | 2022-06-20T20:48:14.759667+00:00 WARNING postfix/qmgr[204]: warning: transport smtp failure -- see a previous warning/fatal/panic logfile record for the problem description
...

As the container only has an IPv4 address, I set POSTFIX_inet_protocols="ipv4" in order to deactivate the lookup of ipv6 addresses by postfix - no changes. postfix flush also does not help.

Reverting to v3.5.0 solves the issue.

[firefrei]

Probably also important: I am using SASL-XOAUTH with Office365.

[bokysan]

Well, for starters, you will need to share your postfix configuration / startup parameters so that I know how to replicate the issue.

[firefrei]

Sure! Environment variables:

RELAYHOST="[smtp.office365.com]:587"
RELAYHOST_USERNAME="webservice@example.com"
ALLOWED_SENDER_DOMAINS="webservice@example.com"
POSTFIX_smtp_tls_security_level="encrypt"
POSTFIX_myhostname="example.com"
POSTFIX_inet_protocols="ipv4"
XOAUTH2_CLIENT_ID="-"
XOAUTH2_SECRET="-"
XOAUTH2_SYSLOG_ON_FAILURE="yes"
XOAUTH2_FULL_TRACE="yes"
INBOUND_DEBUGGING="no"

/etc/sasl-xoauth2.conf (manually created)

{
  "token_endpoint": "https://login.microsoftonline.com/1234567890/oauth2/v2.0/token",
  "client_id": "0987654321",
  "client_secret": "",
  "log_to_syslog_on_failure": "yes",
  "log_full_trace_on_failure": "yes"
}

/var/spool/postfix/xoauth2-tokens/webservice\@example.com

{
    "access_token" : "blabla",
    "expiry" : "1655877563",
    "refresh_token" : "blubblub"
}

[kljensen]

@firefrei did you figure this out?

[firefrei]

Yes and No. One of my installation suddenly started working, however, the second one still does not work. Both have the latest image. I could not figure out yet what the differences are. Both are authenticating against Office365. v3.5.0 works fine on the second installation, but needs manual interaction every 90 days ;-).

So, yes. Problem still exists.