search

haraka / Haraka

A fast, highly extensible, and event driven SMTP server
https://haraka.github.io
MIT License
5.02k stars 662 forks source link

hook_disconnect not firing on certain connections #381

Closed smfreegard closed 8 years ago

smfreegard commented 10 years ago

I've got a weird issue here that I can't work out. Here's a complete log of a session that never timed out and didn't run hook_disconnect:

Nov  8 12:03:46 mailsf5 haraka[4219]: [NOTICE] [95005D32-A451-4553-9132-C4384DC723E9] [core] connect ip=96.31.86.244 port=40064 local_ip=0.0.0.0 local_port=25
Nov  8 12:03:46 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9] [rdns] ip=96.31.86.244 rdns="96-31-86-244.static.hvvc.us" rdns_len=1 fcrdns="96-31-86-244.static.hvvc.us" fcrdns_len=1 other_ips_len=0 invalid_tlds=0 generic_rdns=true hostid="96.31.86.244"
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9] [access_map_common] using match k=concurrent-connect: v=5 action="5" msg="undefined" results=0
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9] [access_map_common] using match k=rate-connect: v=5 action="5" msg="undefined" results=0
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9] [ip_country] country: US
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9] [spf] identity=helo ip=96.31.86.244 domain="ag4sc.com" mfrom=<postmaster@ag4sc.com> result=Pass
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9] [tls] secured: cipher=AES256-SHA version=TLSv1/SSLv3 verified=false error="Error: UNABLE_TO_GET_ISSUER_CERT"
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9] [core] hook=unrecognized_command plugin=tls function=hook_unrecognized_command params="STARTTLS" retval=OK msg=""
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9] [spf] identity=helo ip=96.31.86.244 domain="ag4sc.com" mfrom=<postmaster@ag4sc.com> result=Pass
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [check_syntax] <list@ag4sc.com> mail_case=upper mail_spaces=false
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [spf] identity=mfrom ip=96.31.86.244 domain="ag4sc.com" mfrom=<list@ag4sc.com> result=Pass
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [sender_auth] result="Pass" method="spf"
Nov  8 12:03:47 mailsf5 haraka[4219]: [NOTICE] [95005D32-A451-4553-9132-C4384DC723E9.1] [core] sender <list@ag4sc.com> code=CONT msg=""
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [check_syntax] <xxxxx.xxxx@xxxx.org> rcpt_case=upper rcpt_spaces=false
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [route_map_common] match k=route:xxxx.org v=FORWARD:127.0.0.1:26; RCPT:192.168.200.191; RELAY
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [route_map_common] using match k=route:xxxx.org v=FORWARD:127.0.0.1:26; RCPT:192.168.200.191; RELAY
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [core] hook=rcpt plugin=route_map function=hook_rcpt params="<xxxx.xxxx@xxxx.org>" retval=OK msg=""
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [access_map_common] using match k=length-to:xxxx.org v=20M action="20M" msg="undefined" results=1
Nov  8 12:03:47 mailsf5 haraka[4219]: [NOTICE] [95005D32-A451-4553-9132-C4384DC723E9.1] [core] recipient <xxxx.xxxx@xxxx.org> code=CONT msg="" sender="list@ag4sc.com"
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [delay_checks] using preferences: xxxx.xxxx@xxxx.org
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [check_syntax] mail_case=upper mail_spaces=false rcpt_case=upper rcpt_spaces=false
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [ip_country] received=96.31.86.244 country=US
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [ip_country] received=96.31.86.244 country=US
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [route_map] recipients: valid=1 invalid=0 unverified=0 relay=0 norelay=0
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [access_map_common] using match k=length-to:xxxx.org v=20M action="20M" msg="undefined" results=1
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [domain_info] domain="ag4sc.com" last_update=44 primary_ns="dns1.ctechsites.com" serial=2013092500 refresh=86400 retry=7200 expiration=3600000 minimum=86400 flags="NS_SINGLE_IP"
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [utf8blocks] subject total: 100%
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [utf8blocks] subject nonlatin: 0%
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [utf8blocks] subject Basic Latin: 100%
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [utf8blocks] body total: 100%
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [utf8blocks] body nonlatin: 0%
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [utf8blocks] body Basic Latin: 100%
Nov  8 12:03:47 mailsf5 haraka[4219]: [NOTICE] [95005D32-A451-4553-9132-C4384DC723E9.1] [core] message mid="<ec3316a0faa3c869fe09136c3b3ce196@ag4sc.info>" size=5101 rcpts=1/0/0 delay=0.103 code=CONT msg=""
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [add_watermark] mid="<ec3316a0faa3c869fe09136c3b3ce196@ag4sc.info> " watermark="<WM!904f85d6c77a058ef2dfbe40571467b80e1af5f769c0c0fdac197b2d3a3326f0b6d2851af0b5b668ee1c66bf7da2cba0!@mailsf5.ag.org>"
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [queue/smtp_forward] forwarding to localhost:26
Nov  8 12:03:47 mailsf5 haraka[4219]: [INFO] [95005D32-A451-4553-9132-C4384DC723E9.1] [core] hook=queue plugin=queue/smtp_forward function=hook_queue params="" retval=OK msg="2.0.0 rA8D8RNp030476 Message accepted for delivery (95005D32-A451-4553-9132-C4384DC723E9.1)"
Nov  8 12:03:47 mailsf5 haraka[4219]: [NOTICE] [95005D32-A451-4553-9132-C4384DC723E9.1] [core] queue code=CONT msg="2.0.0 rA8D8RNp030476 Message accepted for delivery (95005D32-A451-4553-9132-C4384DC723E9.1)"

The problem here is that this happened 5 times on this IP address and it therefore started to hit the concurrency rate limits.

i've checked the timeout functions when the session is encrypted under TLS; these work as expected - I just can't see why it never fired here.

baudehlo commented 10 years ago

Did we ever solve this?

celesteking commented 9 years ago

Guys, make a script that would run across log file and check if every UUID includes "[core] connect" and "[core] disconnect". I've never encountered this, btw.

baudehlo commented 8 years ago

I'm gonna close this just to clean up the issue count. @smfreegard please re-open if you see it again.