Infern1
commented
1 year ago Somehow qmail-smtpd server is not working
Closed Infern1 closed 1 year ago
Infern1
commented
1 year ago Somehow qmail-smtpd server is not working
Infern1
commented
1 year ago It seems qmail-smtpd fail a sleep or something
Connection coming at 21:37:27
Nov 1 21:35:17 haraka haraka[47395]: [NOTICE] [14F141D4-E9F8-4441-AAEE-31D12EDF46B0] [core] connect ip=87.253.155.103 port=42272 local_ip=172.16.15.9 local_port=25
Nov 1 21:35:17 haraka haraka[47395]: [INFO] [14F141D4-E9F8-4441-AAEE-31D12EDF46B0] [core] client half closed connection ip=87.253.155.103
Nov 1 21:35:17 haraka haraka[47395]: [INFO] [14F141D4-E9F8-4441-AAEE-31D12EDF46B0] [karma] score: 0
Nov 1 21:35:17 haraka haraka[47395]: [NOTICE] [14F141D4-E9F8-4441-AAEE-31D12EDF46B0] [core] disconnect ip=87.253.155.103 rdns="" helo="" relay=N early=N esmtp=N tls=N pipe=N errors=0 txns=0 rcpts=0/0/0 msgs=0/0/0 bytes=0 lr="" time=0.007
Nov 1 21:37:27 haraka haraka[47395]: [CRIT] [-] [core] Error [ERR_UNHANDLED_ERROR]: Unhandled error. ('8DC73B30-FD3B-44A3-A711-EF011482AC52: [172.16.15.8:25] SMTP connection timed out ')
Nov 1 21:37:27 haraka haraka[47395]: [CRIT] [-] [core] at SMTPClient.emit (node:events:502:17)
Nov 1 21:37:27 haraka haraka[47395]: [CRIT] [-] [core] at pluggableStream.<anonymous> (/root/Haraka/smtp_client.js:174:32)
Nov 1 21:37:27 haraka haraka[47395]: [CRIT] [-] [core] at new NodeError (node:internal/errors:387:5)
Nov 1 21:37:27 haraka haraka[47395]: [CRIT] [-] [core] at Socket.<anonymous> (/root/Haraka/tls_socket.js:94:18)
Nov 1 21:37:27 haraka haraka[47395]: [CRIT] [-] [core] at Socket.emit (node:events:513:28)
Nov 1 21:37:27 haraka haraka[47395]: [CRIT] [-] [core] at Socket._onTimeout (node:net:526:8)
Nov 1 21:37:27 haraka haraka[47395]: [CRIT] [-] [core] at listOnTimeout (node:internal/timers:559:17)
Nov 1 21:37:27 haraka haraka[47395]: [CRIT] [-] [core] at processTimers (node:internal/timers:502:7)
Nov 1 21:37:27 haraka haraka[47395]: [CRIT] [-] [core] at pluggableStream.emit (node:events:513:28)
Nov 1 21:37:27 haraka haraka[47395]: [NOTICE] [-] [core] Shutting down
Nov 1 21:37:27 haraka haraka[13597]: [NOTICE] [-] [core] worker 46 exited with error code: 1
Nov 1 21:37:27 haraka haraka[13597]: [NOTICE] [-] [core] worker started worker=47 pid=47907
Nov 1 21:37:28 haraka haraka[47907]: loglevel: INFO
Nov 1 21:37:28 haraka haraka[47907]: [INFO] [-] [core] Loading plugins
Nov 1 21:37:28 haraka haraka[47907]: [INFO] [-] [core] Loading plugin: process_title
Nov 1 21:37:28 haraka haraka[47907]: [INFO] [-] [core] Loading plugin: syslog
Nov 1 21:37:28 haraka haraka[47907]: [INFO] [-] [core] Loading plugin: relay
Nov 1 21:37:28 haraka haraka[47907]: [INFO] [-] [core] Loading plugin: access
Nov 1 21:37:28 haraka haraka[47907]: [INFO] [-] [core] Loading plugin: geoip
Nov 1 21:37:28 haraka haraka[47907]: log format: DEFAULT
Nov 1 21:37:28 haraka haraka[47907]: loglevel: LOGINFO
Nov 1 21:37:28 haraka haraka[47907]: Starting up Haraka version 2.8.28
Nov 1 21:37:28 haraka haraka[47907]: [INFO] [-] [core] Loading plugin: dnsbl
Nov 1 21:37:28 haraka haraka[47907]: [INFO] [-] [core] Loading plugin: fcrdns
Nov 1 21:37:28 haraka haraka[47907]: [INFO] [-] [core] Loading plugin: helo.checks
Nov 1 21:37:28 haraka haraka[47907]: [INFO] [-] [core] Loading plugin: tls
Nov 1 21:37:28 haraka haraka[47907]: [INFO] [-] [core] loading tls.ini
Nov 1 21:37:28 haraka haraka[47907]: [INFO] [-] [core] Loading plugin: auth/auth_vpopmaild
Nov 1 21:37:28 haraka haraka[47907]: [INFO] [-] [core] Loading plugin: bounceNothing special in the log of qmail-smtpd
2022-11-01 21:32:40.325230500 47647 < RSET^M
2022-11-01 21:32:40.325231500 47647 > 250 flushed^M
2022-11-01 21:37:27.776837500 47606 < [EOF]
2022-11-01 21:37:27.776839500 47606 > [EOF]
2022-11-01 21:37:27.777342500 47605 < [EOF]
2022-11-01 21:37:27.777343500 47605 > [EOF]
2022-11-01 21:37:27.777387500 tcpserver: end 47606 status 256
2022-11-01 21:37:27.777388500 tcpserver: status: 4/10
2022-11-01 21:37:27.777389500 tcpserver: end 47605 status 256
2022-11-01 21:37:27.777390500 tcpserver: status: 3/10
2022-11-01 21:37:40.359482500 47646 < [EOF]
2022-11-01 21:37:40.359484500 47646 > [EOF]
2022-11-01 21:37:40.360069500 47444 < [EOF]
2022-11-01 21:37:40.360070500 47444 > [EOF]
2022-11-01 21:37:40.360506500 47647 < [EOF]
2022-11-01 21:37:40.360507500 47647 > [EOF]
2022-11-01 21:37:40.360716500 tcpserver: end 47647 status 256
2022-11-01 21:37:40.360717500 tcpserver: status: 2/10
2022-11-01 21:37:40.360718500 tcpserver: end 47646 status 256
2022-11-01 21:37:40.360719500 tcpserver: status: 1/10
2022-11-01 21:37:40.360720500 tcpserver: end 47444 status 256
2022-11-01 21:37:40.360721500 tcpserver: status: 0/10Problem seems to be there with latest checkout of Haraka
When I go back to 2.8.29 problem is not there, just then TLS is not working...
2022-11-02T11:55:17.355Z [DEBUG] [75C91A2F-FE8B-4137-82A0-30B653F69008] [core] hook=ehlo plugin=data.uribl function=hook_ehlo params=EUR01-HE1-obe.outbound.protection.outlook.com retval=CONT msg=""
2022-11-02T11:55:17.356Z [DEBUG] [75C91A2F-FE8B-4137-82A0-30B653F69008] [core] running capabilities hooks
2022-11-02T11:55:17.356Z [DEBUG] [75C91A2F-FE8B-4137-82A0-30B653F69008] [core] running capabilities hook in tls plugin
2022-11-02T11:55:47.367Z [CRIT] [75C91A2F-FE8B-4137-82A0-30B653F69008] [core] Plugin tls timed out on hook capabilities - make sure it calls the callback
2022-11-02T11:55:47.367Z [INFO] [75C91A2F-FE8B-4137-82A0-30B653F69008] [core] hook=capabilities plugin=tls function=advertise_starttls params="" retval=DENYSOFT msg="plugin timeout"
2022-11-02T11:55:47.367Z [DEBUG] [75C91A2F-FE8B-4137-82A0-30B653F69008] [core] running deny hooks
2022-11-02T11:55:47.368Z [DEBUG] [75C91A2F-FE8B-4137-82A0-30B653F69008] [core] running deny hook in karma plugin
2022-11-02T11:55:47.368Z [DEBUG] [75C91A2F-FE8B-4137-82A0-30B653F69008] [core] hook=deny plugin=karma function=hook_deny params=903 retval=CONT msg=""
2022-11-02T11:55:47.368Z [DEBUG] [75C91A2F-FE8B-4137-82A0-30B653F69008] [core] running deny hook in watch plugin
2022-11-02T11:55:47.368Z [DEBUG] [75C91A2F-FE8B-4137-82A0-30B653F69008] [watch] watch deny saw: tls deny from capabilities
2022-11-02T11:55:47.368Z [DEBUG] [75C91A2F-FE8B-4137-82A0-30B653F69008] [watch] watch sending dark red to tls
2022-11-02T11:55:47.369Z [DEBUG] [75C91A2F-FE8B-4137-82A0-30B653F69008] [core] hook=deny plugin=watch function=w_deny params=903 retval=CONT msg=""
2022-11-02T11:55:47.369Z [PROTOCOL] [75C91A2F-FE8B-4137-82A0-30B653F69008] [core] S: 250-haraka Hello mail-eopbgr130129.outbound.protection.outlook.com [40.107.13.129], Haraka is at your service.
2022-11-02T11:55:47.369Z [PROTOCOL] [75C91A2F-FE8B-4137-82A0-30B653F69008] [core] S: 250-PIPELINING
2022-11-02T11:55:47.369Z [PROTOCOL] [75C91A2F-FE8B-4137-82A0-30B653F69008] [core] S: 250-8BITMIME
2022-11-02T11:55:47.369Z [PROTOCOL] [75C91A2F-FE8B-4137-82A0-30B653F69008] [core] S: 250-SMTPUTF8
2022-11-02T11:55:47.370Z [PROTOCOL] [75C91A2F-FE8B-4137-82A0-30B653F69008] [core] S: 250 SIZE 0
2022-11-02T11:55:47.418Z [PROTOCOL] [75C91A2F-FE8B-4137-82A0-30B653F69008] [core] C: MAIL FROM:<info@edverhelst.nl> SIZE=101982 state=1
2022-11-02T11:55:47.425Z [DEBUG] [75C91A2F-FE8B-4137-82A0-30B653F69008.1] [core] running mail hooks
2022-11-02T11:55:47.425Z [DEBUG] [75C91A2F-FE8B-4137-82A0-30B653F69008.1] [core] running mail hook in karma plugin
2022-11-02T11:55:47.426Z [DEBUG] [75C91A2F-FE8B-4137-82A0-30B653F69008.1] [core] hook=mail plugin=karma function=hook_mail params=<info@edverhelst.nl> retval=CONT msg=""
2022-11-02T11:55:47.426Z [DEBUG] [75C91A2F-FE8B-4137-82A0-30B653F69008.1] [core] running mail hook in mail_from.is_resolvable plugin
2022-11-02T11:55:47.427Z [DEBUG] [75C91A2F-FE8B-4137-82A0-30B653F69008.1] [core] pipeline: RCPT TO:<info@schoonmaakbedrijfvdeem.nl>\r
2022-11-02T11:55:47.724Z [DEBUG] [75C91A2F-FE8B-4137-82A0-30B653F69008.1] [mail_from.is_resolvable] edverhelst.nl: MX 0 edverhelst-nl.mail.protection.outlook.com => 104.47.17.74,104.47.18.74
2022-11-02T11:55:47.724Z [DEBUG] [75C91A2F-FE8B-4137-82A0-30B653F69008.1] [mail_from.is_resolvable] edverhelst.nl: 104.47.17.74,104.47.18.74
2022-11-02T11:55:47.725Z [DEBUG] [75C91A2F-FE8B-4137-82A0-30B653F69008.1] [core] hook=mail plugin=mail_from.is_resolvable function=hook_mail params=<info@edverhelst.nl> retval=CONT msg=""
2022-11-02T11:55:47.725Z [DEBUG] [75C91A2F-FE8B-4137-82A0-30B653F69008.1] [core] running mail hook in spf plugin
2022-11-02T11:55:47.727Z [DE
rricker1
commented
1 year ago I'm experiencing the same problem on FreeBSD 12.3-RELEASE-p6 GENERIC amd64.
Nov 16 16:14:37 haraka haraka[62900]: [CRIT] [-] [core] Error [ERR_UNHANDLED_ERROR]: Unhandled error. ('C9416CC7-8FE7-4B7A-9B0C-D6FB7E3F867F: [172.16.15.8:25] SMTP connection timed out ')
Nov 16 16:14:37 haraka haraka[62900]: [CRIT] [-] [core] at new NodeError (node:internal/errors:387:5)
Nov 16 16:14:37 haraka haraka[62900]: [CRIT] [-] [core] at pluggableStream.
msimerson
commented
1 year ago I'm seeing it happen after a message is successfully delivered. I haven't gotten to the bottom of it yet.
Nov 22 20:14:55 haraka haraka[79678]: [NOTICE] [6D755B64-82C6-46FF-B0E0-C1BCFECB034C.1] [core] disconnect ip=172.16.15.11 rdns=monitor helo=monitor relay=N early=N esmtp=Y tls=N pipe=N errors=0 txns=1 rcpts=1/0/0 msgs=1/0/0 bytes=278 lr="" time=0.184
Nov 22 20:34:55 haraka haraka[79678]: [CRIT] [-] [core] Error [ERR_UNHANDLED_ERROR]: Unhandled error. ('A5014285-811D-4CF1-BDA9-E386F2223E65: [172.16.15.8:25] SMTP connection ended ')
Nov 22 20:34:55 haraka haraka[79678]: [CRIT] [-] [core] at SMTPClient.emit (node:events:502:17)
Nov 22 20:34:55 haraka haraka[79678]: [CRIT] [-] [core] at pluggableStream.<anonymous> (/root/Haraka/smtp_client.js:174:32)
Nov 22 20:34:55 haraka haraka[79678]: [CRIT] [-] [core] at pluggableStream.emit (node:events:525:35)
Nov 22 20:34:55 haraka haraka[79678]: [CRIT] [-] [core] at Socket.<anonymous> (/root/Haraka/tls_socket.js:79:18)
Nov 22 20:34:55 haraka haraka[79678]: [CRIT] [-] [core] at Socket.emit (node:events:525:35)
Nov 22 20:34:55 haraka haraka[79678]: [CRIT] [-] [core] at endReadableNT (node:internal/streams/readable:1358:12)
Nov 22 20:34:55 haraka haraka[79678]: [CRIT] [-] [core] at processTicksAndRejections (node:internal/process/task_queues:83:21)
Nov 22 20:34:55 haraka haraka[79678]: [CRIT] [-] [core] at new NodeError (node:internal/errors:387:5)
Nov 22 20:34:55 haraka haraka[79678]: [NOTICE] [-] [core] Shutting down
johannes73
commented
1 year ago I am experiencing a similar problem with timeouts for the absolute majority - but not all - of incoming email.
You will find the timeout at 13:52:48.
uname -a
FreeBSD mail.smartnet.se 12.3-RELEASE-p6 FreeBSD 12.3-RELEASE-p6 GENERIC amd6413:52:12 [NOTICE] [core] connect ip=108.174.3.203 port=53615 local_ip=172.16.15.9 local_port=25
13:52:12 [INFO] [karma] score: 0, connections: 1, history: 0
13:52:12 [INFO] [p0f] os="Linux 2.2.x-3.x" link_type="Ethernet or modem" distance=21 total_conn=2
13:52:12 [INFO] [fcrdns] ip=108.174.3.203 rdns="maile-bc.linkedin.com" rdns_len=1 fcrdns="maile-bc.linkedin.com" fcrdns_len=1 other_ips_len=0 invalid_tlds=0 generic_rdns=true
13:52:12 [INFO] [dnsbl]
13:52:12 [ERROR] [geoip] can't calculate distance, set public_ip in smtp.ini
13:52:12 [INFO] [geoip] NA, US
13:52:12 [INFO] [helo.checks] helo_host: maile-bc.linkedin.com
13:52:12 [INFO] [spf] identity=helo ip=108.174.3.203 domain="maile-bc.linkedin.com" mfrom= result=Pass
13:52:12 [INFO] [spf] scope: helo, result: Pass, domain: maile-bc.linkedin.com
13:52:13 [INFO] [tls] secured: cipher=ECDHE-RSA-AES128-GCM-SHA256 version=TLSv1.2 verified=false cn="mail.linkedin.com" organization="LinkedIn Corporation" issuer="DigiCert Inc" expires="Jun 14 23:59:59 2023 GMT" fingerprint=56:00:67:0F:DB:3F:5F:33:5E:EA:03:C3:25:EE:CB:D2:B6:A7:FC:79
13:52:13 [INFO] [core] hook=unrecognized_command plugin=tls function=upgrade_connection params=STARTTLS retval=OK msg=""
13:52:13 [INFO] [helo.checks] helo_host: maile-bc.linkedin.com
13:52:13 [INFO] [1] [spf] identity=mfrom ip=108.174.3.203 domain="bounce.linkedin.com" mfrom= result=Pass
13:52:13 [INFO] [1] [spf] scope: mfrom, result: Pass, domain: bounce.linkedin.com
13:52:13 [INFO] [1] [qmail-deliverable] not local
13:52:13 [NOTICE] [1] [core] sender code=CONT msg=""
13:52:13 [INFO] [1] [qmail-deliverable] vpopmail dir
13:52:13 [INFO] [1] [qmail-deliverable] pass:rcpt.vpopmail dir, msg:mail_from.not local
13:52:13 [INFO] [1] [core] hook=rcpt plugin=qmail-deliverable function=hook_rcpt params= retval=OK msg=""
13:52:13 [NOTICE] [1] [core] recipient code=OK msg="" sender=m-3q2rk669zkvgey3k9fb15uv298gcm58vc8uo8jdglxrlyj7sa71x0@bounce.linkedin.com
13:52:14 [INFO] [1] [clamd] pass:clean
13:52:18 [INFO] [1] [rspamd] action: no action, is_skipped: false, required_score: 15, score: -4.01, urls: static-exp1.licdn.com,www.linkedin.com,se.linkedin.com,itunes.apple.com,play.google.com, time: 4.164
13:52:18 [INFO] [1] [geoip] received=108.174.3.203 country=US
13:52:18 [NOTICE] [1] [core] message mid=<970977791.8923510.1668775746341@ltx1-app87886.prod.linkedin.com> size=52088 rcpts=1/0/0 delay=4.214 code=CONT msg=""
13:52:18 [INFO] [1] [queue/smtp_forward] Configuring authentication for SMTP server 172.16.15.8:25
13:52:18 [INFO] [1] [queue/smtp_forward] forwarding to 172.16.15.8:25
13:52:48 [CRIT] [1] [core] Plugin queue/smtp_forward timed out on hook queue - make sure it calls the callback
13:52:48 [INFO] [1] [core] hook=queue plugin=queue/smtp_forward function=queue_forward params="" retval=DENYSOFT msg="plugin timeout"
13:52:48 [NOTICE] [1] [core] queue code=DENYSOFT msg="plugin timeout (38C5C748-92C6-48F7-BB7C-55A40AF89C33.1)"
13:52:48 [INFO] [1] [karma] score: 0, connections: 1, history: 0, fail:rcpt_toWhen I test the SMTP most times it times out, but not always.
jexec monitor swaks -to me@domain.com -server $(get_jail_ip haraka)
(...)
-> This is a test mailing
->
-> .
<- 250 ok 1450154720 qp 21123 (ID)
-> QUIT
<- 221 haraka closing connection. Have a jolly good day.
=== Connection closed with remote host.
(...)
-> This is a test mailing
->
->
-> .
<** Timeout (30 secs) waiting for server response
-> QUIT
<** 450 [A9857554-6B7@haraka] plugin timeout (A9857554-6B72-4271-BA40-D62B6E50313F.1)
=== Connection closed with remote host.
Not all messages are successfully delivered before the timeout. I am receiving these from some of my remote servers. They eventually come through.
** THIS IS A WARNING MESSAGE ONLY **
** YOU DO NOT NEED TO RESEND YOUR MESSAGE **
**********************************************The original message was received at Fri, 18 Nov 2022 03:25:45 -0800 (PST) from localhost [127.0.0.1]
----- Transcript of session follows ----- ... while talking to mail.XXXXXX.com.:
DATA <<< 450 [B22149AA-C48@haraka] plugin timeout (B22149AA-C481-4974-BB4F-1DACB99B8C46.1) servers@XXXXXX... Deferred: 450 [B22149AA-C48@haraka] plugin timeout (B22149AA-C481-4974-BB4F-1DACB99B8C46.1) Warning: message still undelivered after 4 hours Will keep trying until message is 5 days old
johannes73
commented
1 year ago When I repeatedly try:
jexec monitor swaks -to me@domain.com -server $(get_jail_ip haraka)
usually the two first times, messages are delivered:
(...)
<- 250 ok 1668790758 qp 19105 (24EE431F-A2D1-4F63-82FA-4309C8ABB818.1)
-> QUIT
<- 221 haraka closing connection. Have a jolly good day.
=== Connection closed with remote host.
Typically the third time it times out. Not sure if this is a clue...
(...)
<** Timeout (30 secs) waiting for server response
-> QUIT
<** 450 [2B52B40A-FF3@haraka] plugin timeout (2B52B40A-FF37-490F-BE91-6EF40FEC0357.1)
=== Connection closed with remote host.
On our server (Freebsd 12.3) these timeouts, and retries from senders, caused big delays in the majority of deliveries. I today made a small test and sent 10 test emails from Gmail to our server. Normally it would take only seconds for delivery. Now after 3 hours only 50% of the emails were delivered (it took individual emails between 25 minutes and 2 h 2 minutes), and the remaining 50% were still not delivered.
A big thank you to you all and especially @Infern1 for mentioning that it works with an earlier version of haraka. When I tested to go back to haraka 2.8.27 it seems to work normally again.
I am not the best at PRs and git, but here is a diff of the hack I used. It is probably not done the optimal way. But it works.
# diff provision/haraka.sh provision/haraka.sh.orig
25,29c25
< # JohA 22-11-21:
< # stage_exec git clone --depth=1 https://github.com/haraka/Haraka.git /root/Haraka
< stage_exec git clone https://github.com/haraka/Haraka.git /root/Haraka
< stage_exec bash -c "cd /root/Haraka/ && git checkout 8582195"
< # /JohA
---
> stage_exec git clone --depth=1 https://github.com/haraka/Haraka.git /root/Haraka
I ran it like this:
sh provision/haraka.sh
instead of the normal
provision haraka
msimerson
commented
1 year ago I have found and fixed the basis for the original crasher in this issue. The updated generic-pool is emitting a "timed out" error when a pooled smtp client times out. That was causing the crash. I also fixed another issue while diagnosing that one. And yet, there remains the issue @johannes73 raised, which was that subsequent calls to a pooled client were failing. I don't have the time to get to the bottom of that issue, so I've just disabled smtp_client pooling.
Describe the bug Haraka crashing on timeout, no clue yet where to look
To Reproduce Some mail coming in
Expected behavior No crash
Server (please complete the following information):