> On Jun 17, 2024, at 7:12 AM, Wietse Venema via Postfix-users > <postfix-users@postfix.org> wrote: > > Paul Schmehl via Postfix-users: >>> On Jun 16, 2024, at 5:02?PM, Wietse Venema via Postfix-users >>> <postfix-users@postfix.org> wrote: >>> >>> Paul Schmehl via Postfix-users: >>>> I?m trying to sort out a problem with Roundcube failing to send email with >>>> an error message that says SMTP Error(): authentication failed. In the >>>> roundcube error log I find this: >>>> >>>> [16-Jun-2024 13:58:24 -0500]: <5s9tomcd> PHP Error: SMTP server does not >>>> support authentication (POST >>>> /webmail/?_task=mail&_unlock=loading1718564304121&_framed=1&_action=send) >>>> [16-Jun-2024 13:58:24 -0500]: <5s9tomcd> SMTP Error: Authentication >>>> failure: mail.stovebolt.com <http://mail.stovebolt.com/> >>> >>> Look in Your logs. >>> >>> - Did the client connect to port 25 or 578? >>> >> >> 578 >> >>> - Did the client send starttls? That is logged in the "disconnect >>> from" line. >>> >> >> I don't see anything in the postfix logs (/var/log/maillog) from roundcube. >> I guess I need to enable debug. > > No debug logging needed. This information is ALWAYS logged: > > Example of client that sends starttls: > disconnect from host[addr] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 > commands=7
When I grep for “disconnect from” I get 118,816 entries in the log. 20,297 of those are from one IP. When I look in the logs for the timestamp that is in the roundcube smtp log, I find nothing. [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 220 mail.stovebolt.com ESMTP Postfix [17-Jun-2024 15:24:58 -0500]: <so35oiot> Send: EHLO www.stovebolt.com [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 250-mail.stovebolt.com [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 250-PIPELINING [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 250-SIZE 900000000 [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 250-VRFY [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 250-ETRN [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 250-STARTTLS [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 250-AUTH PLAIN LOGIN [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 250-AUTH=PLAIN LOGIN [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 250-ENHANCEDSTATUSCODES [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 250-8BITMIME [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 250-DSN [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 250-SMTPUTF8 [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 250 CHUNKING [17-Jun-2024 15:24:58 -0500]: <so35oiot> Send: AUTH LOGIN [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 334 VXNlcm5hbWU6 [17-Jun-2024 15:24:58 -0500]: <so35oiot> Send: Z2Vlaw== [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 334 UGFzc3dvcmQ6 [17-Jun-2024 15:24:58 -0500]: <so35oiot> Send: ****** [24] [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 235 2.7.0 Authentication successful [17-Jun-2024 15:24:58 -0500]: <so35oiot> Send: MAIL FROM:<g...@stovebolt.com> [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 250 2.1.0 Ok [17-Jun-2024 15:24:58 -0500]: <so35oiot> Send: RCPT TO:<edi...@stovebolt.com> [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 250 2.1.5 Ok [17-Jun-2024 15:24:58 -0500]: <so35oiot> Send: RCPT TO:<john.peggy.milli...@gmail.com> [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 250 2.1.5 Ok [17-Jun-2024 15:24:58 -0500]: <so35oiot> Send: DATA [17-Jun-2024 15:24:58 -0500]: <so35oiot> Recv: 354 End data with <CR><LF>.<CR><LF> [17-Jun-2024 15:24:58 -0500]: <so35oiot> Send: MIME-Version: 1.0 So, that’s one session in Roundcube. There should be a corresponding entry in the maillog, right? grep "15:24:5" /var/log/maillog Jun 16 15:24:56 ded602 postfix/smtpd[11494]: connect from unknown[80.244.11.69] Jun 16 15:24:56 ded602 postfix/smtpd[11670]: connect from unknown[80.244.11.66] Jun 16 15:24:57 ded602 postfix/smtpd[11491]: connect from unknown[80.244.11.120] Jun 16 15:24:57 ded602 postfix/smtpd[10413]: connect from unknown[80.244.11.149] Jun 16 15:24:57 ded602 postfix/smtpd[10411]: connect from unknown[80.244.11.118] Jun 16 15:24:57 ded602 postfix/smtpd[11420]: disconnect from unknown[80.244.11.148] ehlo=1 auth=0/1 rset=1 quit=1 commands=3/4 Jun 16 15:24:58 ded602 postfix/smtpd[11669]: connect from unknown[80.244.11.67] Jun 16 15:24:58 ded602 postfix/smtpd[11317]: disconnect from unknown[80.244.11.121] ehlo=1 auth=0/1 rset=1 quit=1 commands=3/4 Jun 16 15:24:58 ded602 postfix/smtpd[11318]: disconnect from unknown[80.244.11.148] ehlo=1 auth=0/1 rset=1 quit=1 commands=3/4 Jun 16 15:24:58 ded602 postfix/smtpd[11668]: disconnect from unknown[80.244.11.119] ehlo=1 auth=0/1 rset=1 quit=1 commands=3/4 Jun 16 15:24:58 ded602 postfix/smtpd[11420]: connect from unknown[80.244.11.146] Jun 16 15:24:58 ded602 postfix/smtpd[10679]: disconnect from unknown[80.244.11.140] ehlo=1 auth=0/1 rset=1 quit=1 commands=3/4 Jun 16 15:24:59 ded602 postfix/smtpd[10737]: disconnect from unknown[80.244.11.119] ehlo=1 auth=0/1 rset=1 quit=1 commands=3/4 Jun 16 15:24:59 ded602 postfix/smtpd[11670]: disconnect from unknown[80.244.11.66] ehlo=1 auth=0/1 rset=1 quit=1 commands=3/4 Jun 16 15:24:59 ded602 postfix/smtpd[10414]: disconnect from unknown[80.244.11.69] ehlo=1 auth=0/1 rset=1 quit=1 commands=3/4 Jun 16 15:24:59 ded602 postfix/smtpd[11490]: connect from unknown[80.244.11.119] Jun 17 15:24:57 ded602 postfix/smtpd[9578]: connect from unknown[80.94.95.242] Now, this makes no sense to me at all. So, I grepped for one of the recipient addresses. I found nothing even close to that timestamp. > > Example of client that does not send starttls: > disconnect from host[addr] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5 > > In your case there may be only ehlo but no mail, rcpt, and so on. Again, when I grep for this I find 118000+ entries. Paul Schmehl paul.schm...@gmail.com
_______________________________________________ Postfix-users mailing list -- postfix-users@postfix.org To unsubscribe send an email to postfix-users-le...@postfix.org
