search

nymea / nymea-plugins

A collection of plugins for the nymea IoT server.
GNU Lesser General Public License v3.0
22 stars 25 forks source link

"Pipelining not supported" error when sending email notification to OpenSMTPD server #724

Open lifepillar opened 8 months ago

lifepillar commented 8 months ago

Using OpenSMTPD 7.3.0 built with OpenSSL 3.0.12. The SMTP server drops the connection with “Pipelining not supported” after the mail notification plugin has sent the mail body.

nymea's debug log:

 I | MailNotification: Start sending message "Hello" "world"
 I | MailNotification: SmtpClient::StateInitialize
 I | MailNotification: Connected
 I | MailNotification: <-- "220 mail.my.domain ESMTP OpenSMTPD\r\n"
 I | MailNotification: Server response: 220 "220 mail.my.domain ESMTP OpenSMTPD\r\n"
 I | MailNotification: --> "EHLO localhost"
 I | MailNotification: SmtpClient::StateStartTls
 I | MailNotification: <-- "250-mail.my.domain Hello localhost [10.xx.xx.101], pleased to meet you\r\n"
 I | MailNotification: Server response: 250 "250-mail.my.domain Hello localhost [10.xx.xx.101], pleased to meet you\r\n"
 I | MailNotification: <-- "250-8BITMIME\r\n"
 I | MailNotification: Server response: 250 "250-8BITMIME\r\n"
 I | MailNotification: <-- "250-ENHANCEDSTATUSCODES\r\n"
 I | MailNotification: Server response: 250 "250-ENHANCEDSTATUSCODES\r\n"
 I | MailNotification: <-- "250-SIZE 36700160\r\n"
 I | MailNotification: Server response: 250 "250-SIZE 36700160\r\n"
 I | MailNotification: <-- "250-DSN\r\n"
 I | MailNotification: Server response: 250 "250-DSN\r\n"
 I | MailNotification: <-- "250-STARTTLS\r\n"
 I | MailNotification: Server response: 250 "250-STARTTLS\r\n"
 I | MailNotification: <-- "250 HELP\r\n"
 I | MailNotification: Server response: 250 "250 HELP\r\n"
 I | MailNotification: --> "STARTTLS"
 I | MailNotification: SmtpClient::StateHandShake
 I | MailNotification: <-- "220 2.0.0 Ready to start TLS\r\n"
 I | MailNotification: Server response: 220 "220 2.0.0 Ready to start TLS\r\n"
 I | MailNotification: Start client encryption...
 I | MailNotification: Socket encrypted
 I | MailNotification: --> "EHLO localhost"
 I | MailNotification: SmtpClient::StateAuthentification
 I | MailNotification: <-- "250-mail.my.domain Hello localhost [10.xx.xx.101], pleased to meet you\r\n"
 I | MailNotification: Server response: 250 "250-mail.my.domain Hello localhost [10.xx.xx.101], pleased to meet you\r\n"
 I | MailNotification: <-- "250-8BITMIME\r\n"
 I | MailNotification: Server response: 250 "250-8BITMIME\r\n"
 I | MailNotification: <-- "250-ENHANCEDSTATUSCODES\r\n"
 I | MailNotification: Server response: 250 "250-ENHANCEDSTATUSCODES\r\n"
 I | MailNotification: <-- "250-SIZE 36700160\r\n"
 I | MailNotification: Server response: 250 "250-SIZE 36700160\r\n"
 I | MailNotification: <-- "250-DSN\r\n"
 I | MailNotification: Server response: 250 "250-DSN\r\n"
 I | MailNotification: <-- "250-AUTH PLAIN LOGIN\r\n"
 I | MailNotification: Server response: 250 "250-AUTH PLAIN LOGIN\r\n"
 I | MailNotification: <-- "250 HELP\r\n"
 I | MailNotification: Server response: 250 "250 HELP\r\n"
 I | MailNotification: --> "AUTH PLAIN xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx"
 I | MailNotification: SmtpClient::StateMail
 I | MailNotification: <-- "235 2.0.0 Authentication succeeded\r\n"
 I | MailNotification: Server response: 235 "235 2.0.0 Authentication succeeded\r\n"
 I | MailNotification: --> "MAIL FROM:<nymea@mail.my.domain>"
 I | MailNotification: Prepare recipients list ("myself@mail.my.domain")
 I | MailNotification: SmtpClient::StateRcpt
 I | MailNotification: <-- "250 2.0.0 Ok\r\n"
 I | MailNotification: Server response: 250 "250 2.0.0 Ok\r\n"
 I | MailNotification: --> "RCPT TO:<myself@mail.my.domain>"
 I | MailNotification: SmtpClient::StateData
 I | MailNotification: <-- "250 2.1.5 Destination address valid: Recipient ok\r\n"
 I | MailNotification: Server response: 250 "250 2.1.5 Destination address valid: Recipient ok\r\n"
 I | MailNotification: --> "DATA"
 I | MailNotification: SmtpClient::StateBody
 I | MailNotification: <-- "354 Enter mail, end with \".\" on a line by itself\r\n"
 I | MailNotification: Server response: 354 "354 Enter mail, end with \".\" on a line by itself\r\n"
 I | MailNotification: --> "To: myself@mail.my.domain\r\nFrom: nymea@mail.my.domain\r\nSubject: Hello\r\nDate: 17 Dec 2023 15:35:19 +0100\r\nContent-Type: text/plain; charset=\"UTF-8\"\r\nContent-Transfer-Encoding: quoted-printable\r\nMIME-Version: 1.0\r\nX-Mailer: nymea;\r\n\r\nworld\r\n.\r\n\r\n.\r\n"
 I | MailNotification: SmtpClient::StateQuit
 I | MailNotification: <-- "500 5.5.1 Invalid command: Pipelining not supported\r\n"
 I | MailNotification: Server response: 500 "500 5.5.1 Invalid command: Pipelining not supported\r\n"
 W | MailNotification: Received unexpected error code from smtp server 500 "500 5.5.1 Invalid command: Pipelining not supported\r\n"
 I | MailNotification: Disconnected
 I | MailNotification: SmtpClient::StateIdle
 I | LogEngine: Sending log write event to influx "http://127.0.0.1:8086/write?db=nymea&precision=ms&rp=discrete" "action-{xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxxxx}-notify params=\"%7B%22body%22%3A%22world%22%2C%22title%22%3A%22Hello%22%7D\",status=\"ThingErrorHardwareFailure\",triggeredBy=\"TriggeredByUser\" 1702823719310"
 I | LogEngine: Started: true false

OpenSMTPD log:

smtp: 0x274320c42000: connected to listener 0x274320c7b000 [hostname=mail.my.domain, port=587, tag=]
smtp: 0x274320c42000: STATE_NEW -> STATE_CONNECTED
66eb9485da071242 smtp connected address=10.xx.xx.101 host=nymea.my.domain
smtp: 0x274320c42000: >>> 220 mail.my.domain ESMTP OpenSMTPD
smtp: 0x274320c42000: <<< EHLO localhost
smtp: 0x274320c42000: STATE_CONNECTED -> STATE_HELO
smtp: 0x274320c42000: >>> 250-mail.my.domain Hello localhost [10.xx.xx.101], pleased to meet you
smtp: 0x274320c42000: >>> 250-8BITMIME
smtp: 0x274320c42000: >>> 250-ENHANCEDSTATUSCODES
smtp: 0x274320c42000: >>> 250-SIZE 36700160
smtp: 0x274320c42000: >>> 250-DSN
smtp: 0x274320c42000: >>> 250-STARTTLS
smtp: 0x274320c42000: >>> 250 HELP
smtp: 0x274320c42000: <<< STARTTLS
smtp: 0x274320c42000: >>> 220 2.0.0 Ready to start TLS
smtp: 0x274320c42000: STATE_HELO -> STATE_TLS
debug: dispatcher: rsae_priv_enc
66eb9485da071242 smtp tls ciphers=TLSv1.3:TLS_AES_256_GCM_SHA384:256
smtp: 0x274320c42000: STATE_TLS -> STATE_HELO
smtp: 0x274320c42000: <<< EHLO localhost
smtp: 0x274320c42000: STATE_HELO -> STATE_HELO
smtp: 0x274320c42000: >>> 250-mail.my.domain Hello localhost [10.xx.xx.101], pleased to meet you
smtp: 0x274320c42000: >>> 250-8BITMIME
smtp: 0x274320c42000: >>> 250-ENHANCEDSTATUSCODES
smtp: 0x274320c42000: >>> 250-SIZE 36700160
smtp: 0x274320c42000: >>> 250-DSN
smtp: 0x274320c42000: >>> 250-AUTH PLAIN LOGIN
smtp: 0x274320c42000: >>> 250 HELP
smtp: 0x274320c42000: <<< AUTH PLAIN xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
smtp: 0x274320c42000: STATE_HELO -> STATE_AUTH_INIT
debug: lka: authenticating for passwds:myself@mail.my.domain
66eb9485da071242 smtp authentication user=myself@mail.my.domain result=ok
smtp: 0x274320c42000: >>> 235 2.0.0 Authentication succeeded
smtp: 0x274320c42000: STATE_AUTH_INIT -> STATE_HELO
smtp: 0x274320c42000: <<< MAIL FROM:<nymea@mail.my.domain>
smtp: 0x274320c42000: >>> 250 2.0.0 Ok
smtp: 0x274320c42000: <<< RCPT TO:<myself@mail.my.domain>
debug: aliases_virtual_get: '@mail.my.domain' resolved to 1 nodes
smtp: 0x274320c42000: >>> 250 2.1.5 Destination address valid: Recipient ok
smtp: 0x274320c42000: <<< DATA
smtp: 0x274320c42000: fd 15 from queue
smtp: 0x274320c42000: message fd 15
smtp: 0x274320c42000: message begin
smtp: 0x274320c42000: >>> 354 Enter mail, end with "." on a line by itself
smtp: 0x274320c42000: STATE_HELO -> STATE_BODY
<<< [MSG] To: myself@mail.my.domain
<<< [MSG] From: nymea@mail.my.domain
<<< [MSG] Subject: Hello
<<< [MSG] Date: 17 Dec 2023 15:49:30 +0100
<<< [MSG] Content-Type: text/plain; charset="UTF-8"
<<< [MSG] Content-Transfer-Encoding: quoted-printable
<<< [MSG] MIME-Version: 1.0
<<< [MSG] X-Mailer: nymea;
<<< [MSG] 
<<< [MSG] world
<<< [MSG] .
<<< [EOM]
smtp: 0x274320c42000: >>> 500 5.5.1 Invalid command: Pipelining not supported
66eb9485da071242 smtp bad-input result="500 5.5.1 Invalid command: Pipelining not supported"
smtp: 0x274320c42000: STATE_BODY -> STATE_QUIT
66eb9485da071242 smtp disconnected reason=quit

I have no issues with any other client (and I have several). I've even tried a manual session with openssl s_client: no problem at all.

Is it possible that nymea sends multiple commands without waiting for a response?

lifepillar commented 8 months ago

The double dot at the end of the mail body looks suspicious to me:

I | MailNotification: --> "To: myself@mail.my.domain\r\nFrom: nymea@mail.my.domain\r\nSubject: Hello\r\nDate: 17 Dec 2023 15:35:19 +0100\r\nContent-Type: text/plain; charset=\"UTF-8\"\r\nContent-Transfer-Encoding: quoted-printable\r\nMIME-Version: 1.0\r\nX-Mailer: nymea;\r\n\r\nworld\r\n.\r\n\r\n.\r\n"

mzanetti commented 8 months ago

This pull request removes the double \r\n.\r\n: https://github.com/nymea/nymea-plugins/pull/725

It will be included in the next experimental build. Would appreciate if you could test and confirm back if it works.

lifepillar commented 8 months ago

Thanks for the quick feedback! Looking at the PR, the fix looks good to me. I'll see if I can build it myself, otherwise I'll wait for the experimental build.

t-mon commented 8 months ago

The patch is already in the landing build and will be released soon :-)