Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Haraka crashing after provision #511

Closed
Infern1 opened this issue Nov 1, 2022 · 11 comments
Closed

Haraka crashing after provision #511

Infern1 opened this issue Nov 1, 2022 · 11 comments
Labels
bug

Comments

@Infern1
Copy link
Collaborator

Infern1 commented Nov 1, 2022

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):

  • OS: FreeBSD
  • Version 13.1
Nov  1 16:55:55 haraka haraka[4518]: [INFO] [A7A354A6-F28D-4A1A-B388-732D7B134C6B.1] [rspamd] action: add header, is_skipped: false, required_score: 15, score: 8.758744, urls: www.maximiles.nl, emails: contact@maximiles.nl, time: 0.463
Nov  1 16:55:55 haraka haraka[4518]: [INFO] [A7A354A6-F28D-4A1A-B388-732D7B134C6B.1] [geoip] received=78.40.91.14 country=FR
Nov  1 16:55:55 haraka haraka[4518]: [NOTICE] [A7A354A6-F28D-4A1A-B388-732D7B134C6B.1] [core] message mid=<20221101_154629_039100.no-reply@return.maximiles.nl> size=32052 rcpts=1/0/0 delay=0.489 code=CONT msg=""
Nov  1 16:55:55 haraka haraka[4518]: [INFO] [A7A354A6-F28D-4A1A-B388-732D7B134C6B.1] [queue/smtp_forward] Configuring authentication for SMTP server 172.16.15.8:25
Nov  1 16:55:55 haraka haraka[4518]: [INFO] [A7A354A6-F28D-4A1A-B388-732D7B134C6B.1] [queue/smtp_forward] forwarding to 172.16.15.8:25
Nov  1 16:55:55 haraka haraka[4518]: [INFO] [A7A354A6-F28D-4A1A-B388-732D7B134C6B.1] [queue/smtp_forward] capabilities received
Nov  1 16:56:20 haraka haraka[4519]: [CRIT] [-] [core] Error [ERR_UNHANDLED_ERROR]: Unhandled error. ('FCEAA55A-0236-4479-8940-1D394B488DF5: [172.16.15.8:25] SMTP connection timed out ')
Nov  1 16:56:20 haraka haraka[4519]: [CRIT] [-] [core]     at SMTPClient.emit (node:events:502:17)
Nov  1 16:56:20 haraka haraka[4519]: [CRIT] [-] [core]     at pluggableStream.<anonymous> (/root/Haraka/smtp_client.js:174:32)
Nov  1 16:56:20 haraka haraka[4519]: [CRIT] [-] [core]     at pluggableStream.emit (node:events:513:28)
Nov  1 16:56:20 haraka haraka[4519]: [CRIT] [-] [core]     at Socket.<anonymous> (/root/Haraka/tls_socket.js:94:18)
Nov  1 16:56:20 haraka haraka[4519]: [CRIT] [-] [core]     at Socket.emit (node:events:513:28)
Nov  1 16:56:20 haraka haraka[4519]: [CRIT] [-] [core]     at Socket._onTimeout (node:net:526:8)
Nov  1 16:56:20 haraka haraka[4519]: [CRIT] [-] [core]     at listOnTimeout (node:internal/timers:559:17)
Nov  1 16:56:20 haraka haraka[4519]: [CRIT] [-] [core]     at new NodeError (node:internal/errors:387:5)
Nov  1 16:56:20 haraka haraka[4519]: [CRIT] [-] [core]     at processTimers (node:internal/timers:502:7)
Nov  1 16:56:20 haraka haraka[4519]: [NOTICE] [-] [core] Shutting down
Nov  1 16:56:21 haraka haraka[4499]: [NOTICE] [-] [core] worker 2 exited with error code: 1
Nov  1 16:56:21 haraka haraka[4499]: [NOTICE] [-] [core] worker started worker=3 pid=5002
Nov  1 16:56:21 haraka haraka[5002]: loglevel: INFO
Nov  1 16:56:21 haraka haraka[5002]: [INFO] [-] [core] Loading plugins
Nov  1 16:56:21 haraka haraka[5002]: [INFO] [-] [core] Loading plugin: process_title
Nov  1 16:56:21 haraka haraka[5002]: [INFO] [-] [core] Loading plugin: syslog
Nov  1 16:56:21 haraka haraka[5002]: [INFO] [-] [core] Loading plugin: relay
Nov  1 16:56:21 haraka haraka[5002]: [INFO] [-] [core] Loading plugin: access
Nov  1 16:56:21 haraka haraka[5002]: [INFO] [-] [core] Loading plugin: p0f
Nov  1 16:56:21 haraka haraka[5002]: [INFO] [-] [core] Loading plugin: geoip
Nov  1 16:56:21 haraka haraka[5002]: [INFO] [-] [core] Loading plugin: fcrdns
Nov  1 16:56:21 haraka haraka[5002]: [INFO] [-] [core] Loading plugin: dnsbl
Nov  1 16:56:21 haraka haraka[5002]: [INFO] [-] [core] Loading plugin: helo.checks
Nov  1 16:56:21 haraka haraka[5002]: [INFO] [-] [core] Loading plugin: tls
Nov  1 16:56:21 haraka haraka[5002]: [INFO] [-] [core] loading tls.ini
@Infern1 Infern1 added the bug label Nov 1, 2022
@Infern1
Copy link
Collaborator Author

Infern1 commented Nov 1, 2022

Somehow qmail-smtpd server is not working

image

@Infern1
Copy link
Collaborator Author

Infern1 commented Nov 1, 2022

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: bounce

Nothing 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/10

@Infern1
Copy link
Collaborator Author

Infern1 commented Nov 2, 2022

Problem 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
Copy link

rricker1 commented Nov 17, 2022 •
edited
Loading

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. (/root/Haraka/smtp_client.js:174:32)
Nov 16 16:14:37 haraka haraka[62900]: [CRIT] [-] [core] at pluggableStream.emit (node:events:513:28)
Nov 16 16:14:37 haraka haraka[62900]: [CRIT] [-] [core] at SMTPClient.emit (node:events:502:17)
Nov 16 16:14:37 haraka haraka[62900]: [CRIT] [-] [core] at Socket.emit (node:events:513:28)
Nov 16 16:14:37 haraka haraka[62900]: [CRIT] [-] [core] at Socket._onTimeout (node:net:526:8)
Nov 16 16:14:37 haraka haraka[62900]: [CRIT] [-] [core] at Socket. (/root/Haraka/tls_socket.js:94:18)
Nov 16 16:14:37 haraka haraka[62900]: [CRIT] [-] [core] at listOnTimeout (node:internal/timers:559:17)
Nov 16 16:14:37 haraka haraka[62900]: [CRIT] [-] [core] at processTimers (node:internal/timers:502:7)
Nov 16 16:14:37 haraka haraka[62900]: [NOTICE] [-] [core] Shutting down
Nov 16 16:14:37 haraka haraka[39530]: [NOTICE] [-] [core] worker 1 exited with error code: 1
Nov 16 16:14:37 haraka haraka[39530]: [NOTICE] [-] [core] worker started worker=4 pid=94960
Nov 16 16:14:38 haraka haraka[94960]: loglevel: INFO

@msimerson
Copy link
Owner

msimerson commented Nov 18, 2022 •
edited
Loading

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
Copy link

johannes73 commented Nov 18, 2022 •
edited
Loading

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  amd64

13: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_to

@johannes73
Copy link

When I test the SMTP most times it times out, but not always.

Test SMTP

jexec monitor swaks -to me@domain.com -server $(get_jail_ip haraka)

Expected behavior

(...)
 -> 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.

Result

(...)
 -> 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.

@rricker1
Copy link

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
Copy link

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.

@johannes73
Copy link

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
Copy link
Owner

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.

@greenshrike greenshrike mentioned this issue Dec 14, 2022
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@msimerson @Infern1 @johannes73 @rricker1