Poste.IO send username twice when authenticating to SMTP with AUTH PLAIN

Note: Seem to be linked to Issue ~~#961~~

‌

Trying to configure my own mail service, I selected Poste.IO for that. To ensure my mail will be delivered from a trust worthy IP, I selected dynu.com as a smarthost and wish to have my mail send through them. Unfortunately, Poste.IO is unable to authenticate to the service. After a lot of troubleshooting, I found the root cause in the delivery log (/data/log/delivery/del/x/y/___id___.1). When trying to authenticate, Poste.IO sends this :

AUTH PLAIN Username64Username64Password64

That is, the username is encoded base64 and sent twice before the password. That always results in 535 Authentication Failed. When connecting manually to the service with Telnet, I can authenticate to it using AUTH LOGIN and sending the encoded username and password separately.

I searched a lot about this and there is this very old thing that I found and that mentions the same kind of problem :

https://www.perlmonks.org/?node_id=781634

‌

Poste.IO is installed from the latest container image in Docker Hub.

Smarthost is “relay.dynu.com”

Port is 465

Username (provided by Dynu) is : relay@relay.yourdomain.com

Password is as required by Dynu, 4 to 20 chars with upper, lower, number and other (I use - + or _ as special to reduce risks)

‌

Options would be to force Poste.IO to use AUTH LOGIN instead of AUTH PLAIN (it may avoid the bug) or fix the code to ensure that the username is sent only once. I tried to remove the username in the WebUI and add it in the password field instead, hoping that both would be encoded in a single step and sent as one. Unfortunately, the WebUI injects something in the Username field itself if I do that.

Should you need more test or data about this, feel free to ask me.

Here is the log (with some censured data striked through…)

castor:/var/lib/docker/volumes/Poste.IO/_data/log/delivery/del/0/B# cat 0B1B6DB7-6CDC-40E7-B001-B7A6406B0612.1
2023-01-12T01:13:11.525Z [1] [DEBUG] [outbound] running send_email hooks
2023-01-12T01:13:11.526Z [1] [DEBUG] [outbound] Sending mail: 1673485991493_1673485991493_0_1943_TZjyui_1_mailer.~~yourdomain.com~~
2023-01-12T01:13:11.526Z [1] [DEBUG] [outbound] running get_mx hooks
2023-01-12T01:13:11.527Z [1] [DEBUG] [outbound] running get_mx hook in relay plugin
2023-01-12T01:13:11.527Z [1] [DEBUG] [outbound] hook=get_mx plugin=relay function=force_routing params=gmail.com retval=CONT msg=""
2023-01-12T01:13:11.527Z [1] [DEBUG] [outbound] running get_mx hook in rcpt_database plugin
2023-01-12T01:13:11.528Z [1] [DEBUG] [outbound] registered relays: {"":[{"priority":0,"exchange":"relay.dynu.com","port":"465","auth_user":"relay@relay.~~yourdomain.com~~","auth_pass":"~~PasswordInClearText~~","forced":true}]}
2023-01-12T01:13:11.537Z [1] [DEBUG] [outbound] {"skip_plugins":[],"remote_source":false,"original_rcpt_to":["~~myself~~@gmail.com"],"new_rcpt_to":[{"original":"~~myself~~@gmail.com","original_host":"gmail.com","host":"gmail.com","user":"~~myself~~"}],"remote_destination":true,"attachment_count":0,"attachments":[],"attachment_ctypes":["text/plain"],"attachment_files":[],"attachment_archive_files":[],"authentication_results":[]}
2023-01-12T01:13:11.537Z [1] [INFO] [outbound] hook=get_mx plugin=rcpt_database function=hook_get_mx params=gmail.com retval=OK msg="[object Object]"
2023-01-12T01:13:11.538Z [1] [DEBUG] [outbound] Got a MX from Plugin: gmail.com => 0 {"priority":0,"exchange":"relay.dynu.com","port":"465","auth_user":"relay@relay.~~yourdomain.com~~","auth_pass":"~~PasswordInClearText~~","forced":true}
2023-01-12T01:13:11.540Z [1] [INFO] [outbound] Looking up A records for: relay.dynu.com
2023-01-12T01:13:11.545Z [1] [INFO] [outbound] Attempting to deliver to mailer.~~yourdomain.com~~: 168.235.105.136:465 (0) (0)
2023-01-12T01:13:11.732Z [1] [PROTOCOL] [outbound] S: 220 relay.wiredblade.com ESMTP\r\n
2023-01-12T01:13:11.733Z [1] [PROTOCOL] [outbound] C: EHLO mailer.~~yourdomain.com~~
2023-01-12T01:13:11.821Z [1] [PROTOCOL] [outbound] S: 250-relay.wiredblade.com\r\n
2023-01-12T01:13:11.821Z [1] [PROTOCOL] [outbound] S: 250-SIZE\r\n
2023-01-12T01:13:11.822Z [1] [PROTOCOL] [outbound] S: 250-STARTTLS\r\n
2023-01-12T01:13:11.822Z [1] [PROTOCOL] [outbound] S: 250-AUTH LOGIN PLAIN\r\n
2023-01-12T01:13:11.822Z [1] [PROTOCOL] [outbound] S: 250 HELP\r\n
2023-01-12T01:13:11.824Z [1] [DEBUG] [outbound] Trying TLS for domain: gmail.com, host: 168.235.105.136
2023-01-12T01:13:11.824Z [1] [PROTOCOL] [outbound] C: STARTTLS
2023-01-12T01:13:11.913Z [1] [PROTOCOL] [outbound] S: 220 Ready to start TLS\r\n
2023-01-12T01:13:12.132Z [1] [INFO] [outbound] secured verified=true cipher=ECDHE-RSA-AES256-GCM-SHA384 version=TLSv1.2 cn=.dynu.com organization="" issuer="Sectigo Limited" expires="Mar 7 23:59:59 2023 GMT" fingerprint=59:3E:7A:B3:71:B7:78:50:0C:88:2C:FA:B7:60:C4:FF:E8:0D:0A:C0
2023-01-12T01:13:12.133Z [1] [PROTOCOL] [outbound] C: EHLO mailer.~~yourdomain.com~~
2023-01-12T01:13:12.217Z [1] [PROTOCOL] [outbound] S: 250-relay.wiredblade.com\r\n
2023-01-12T01:13:12.218Z [1] [PROTOCOL] [outbound] S: 250-SIZE\r\n
2023-01-12T01:13:12.218Z [1] [PROTOCOL] [outbound] S: 250-AUTH LOGIN PLAIN\r\n
2023-01-12T01:13:12.218Z [1] [PROTOCOL] [outbound] S: 250 HELP\r\n
2023-01-12T01:13:12.219Z [1] [PROTOCOL] [outbound] C: AUTH PLAIN ~~cmVsYXlAcmVsYXkueW91cmRvbWFpbi5jb21yZWxheUByZWxheS55b3VyZG9tYWluLmNvbVBhc3N3b3JkSW5DbGVhclRleHQ=~~
2023-01-12T01:13:12.321Z [1] [PROTOCOL] [outbound] S: 535 Authentication failed. Restarting authentication process.\r\n
2023-01-12T01:13:12.322Z [1] [PROTOCOL] [outbound] C: QUIT
2023-01-12T01:13:12.322Z [1] [INFO] [outbound] bouncing mail: 535 Authentication failed. Restarting authentication process.
2023-01-12T01:13:12.323Z [1] [DEBUG] [outbound] running bounce hooks
2023-01-12T01:13:12.323Z [1] [DEBUG] [outbound] running bounce hook in stats plugin
2023-01-12T01:13:12.326Z [1] [DEBUG] [outbound] hook=bounce plugin=stats function=hook_bounce params="" retval=CONT msg=""
2023-01-12T01:13:12.326Z [1] [DEBUG] [outbound] running bounce hook in log plugin
2023-01-12T01:13:12.327Z [1] [DEBUG] [outbound] hook=bounce plugin=log function=hook_bounce params="" retval=CONT msg=""
2023-01-12T01:13:12.328Z [1] [DEBUG] [outbound] running bounce hook in srs plugin
2023-01-12T01:13:12.328Z [1] [DEBUG] [outbound] hook=bounce plugin=srs function=hook_bounce params="" retval=CONT msg=""

Comments (3)