Hello,
I'm experiencing an issue where smtpd shuts itself down. Last line it
logs is "smtpd: process pony socket closed". I'm not sure where to
begin to diagnose this.
Here are a few facts I think are relevant :
- this happened both on OpenBSD 6.7 and 6.8 (same machine).
- it happened after receiving an inbound connection from one of
those "scanners" that crawl the net looking for vulnerabilities.
- I'm running a filter developed in-house, its code quality is not
the best, so a bug there is likely. But can a misbehaving filter
cause smtpd to terminate ?
- The filter itself never crashes, it just terminates when it notices
smtpd has gone away.
- Each time it happened, said filter was sending a reject to
smtpd ("450 4.3.0 RBL processing error, try again later") because
of a DNS timeout. It is likely that smtpd would have been
experiencing timeout for some its own DNS checks at the same time.
- Each occurence of this issue combines both the connection of an
external scanner and DNS timeouts.
I managed to capture smtpd traces of the latest event :
Oct 21 12:48:18 hostname smtpd[50488]: smtp: 0x2d6669ad000: connected to listener 0x2d6f5d14000 [hostname=hostname.domain.tld, port=25, tag=]
Oct 21 12:48:18 hostname smtpd[50488]: mproc: pony -> lka : 28 IMSG_GETNAMEINFO
Oct 21 12:48:18 hostname smtpd[50488]: mproc: pony -> control : 46 IMSG_STAT_INCREMENT
Oct 21 12:48:18 hostname smtpd[50488]: mproc: pony -> control : 52 IMSG_STAT_INCREMENT
Oct 21 12:48:18 hostname smtpd[2927]: imsg: lka <- pony: IMSG_GETNAMEINFO (len=28)
Oct 21 12:48:18 hostname smtpd[12402]: imsg: control <- pony: IMSG_STAT_INCREMENT (len=46)
Oct 21 12:48:18 hostname smtpd[12402]: ramstat: increment: smtp.session
Oct 21 12:48:18 hostname smtpd[12402]: ramstat: smtp.session (0xd692c9c5401): 0 -> 1
Oct 21 12:48:18 hostname smtpd[12402]: imsg: control <- pony: IMSG_STAT_INCREMENT (len=52)
Oct 21 12:48:18 hostname smtpd[12402]: ramstat: increment: smtp.session.inet4
Oct 21 12:48:18 hostname smtpd[12402]: ramstat: smtp.session.inet4 (0xd69486802c1): 12 -> 13
Oct 21 12:48:22 hostname smtpd[2927]: mproc: lka -> pony : 50 IMSG_GETNAMEINFO
Oct 21 12:48:22 hostname smtpd[50488]: imsg: pony <- lka: IMSG_GETNAMEINFO (len=50)
Oct 21 12:48:22 hostname smtpd[50488]: mproc: pony -> lka : 52 IMSG_GETADDRINFO
Oct 21 12:48:22 hostname smtpd[2927]: imsg: lka <- pony: IMSG_GETADDRINFO (len=52)
Oct 21 12:48:22 hostname smtpd[2927]: mproc: lka -> pony : 41 IMSG_GETADDRINFO
Oct 21 12:48:22 hostname last message repeated 15 times
Oct 21 12:48:22 hostname smtpd[2927]: mproc: lka -> pony : 8 IMSG_GETADDRINFO_END
Oct 21 12:48:22 hostname smtpd[50488]: imsg: pony <- lka: IMSG_GETADDRINFO (len=41)
Oct 21 12:48:22 hostname last message repeated 15 times
Oct 21 12:48:22 hostname smtpd[50488]: imsg: pony <- lka: IMSG_GETADDRINFO_END (len=8)
Oct 21 12:48:22 hostname smtpd[50488]: smtp: 0x2d6669ad000: STATE_NEW -> STATE_CONNECTED
Oct 21 12:48:22 hostname smtpd[50488]: 5cf54239c7aa819e smtp connected address=162.142.125.33 host=scanner-04.ch1.censys-scanner.com
Oct 21 12:48:22 hostname smtpd[50488]: mproc: pony -> lka : 20 IMSG_FILTER_SMTP_BEGIN
Oct 21 12:48:22 hostname smtpd[50488]: mproc: pony -> lka : 120 IMSG_REPORT_SMTP_LINK_CONNECT
Oct 21 12:48:22 hostname smtpd[50488]: mproc: pony -> lka : 28 IMSG_FILTER_SMTP_PROTOCOL
Oct 21 12:48:22 hostname smtpd[2927]: imsg: lka <- pony: IMSG_FILTER_SMTP_BEGIN (len=20)
Oct 21 12:48:22 hostname smtpd[2927]: 5cf54239c7aa819e filters session-begin
Oct 21 12:48:22 hostname smtpd[2927]: imsg: lka <- pony: IMSG_REPORT_SMTP_LINK_CONNECT (len=120)
Oct 21 12:48:22 hostname smtpd[2927]: imsg: lka <- pony: IMSG_FILTER_SMTP_PROTOCOL (len=28)
Oct 21 12:48:22 hostname smtpd[2927]: 5cf54239c7aa819e filters protocol phase=connect, resume=n, action="" filter=rbl
Oct 21 12:48:22 hostname opensmtpd-filter-rbl: Querying RBL zen.spamhaus.org for IP 162.142.125.33 failed with TRY_AGAIN
Oct 21 12:48:22 hostname smtpd[2927]: mproc: lka -> pony : 61 IMSG_FILTER_SMTP_PROTOCOL
Oct 21 12:48:22 hostname smtpd[50488]: imsg: pony <- lka: IMSG_FILTER_SMTP_PROTOCOL (len=61)
Oct 21 12:48:22 hostname smtpd[2927]: 5cf54239c7aa819e filters protocol phase=connect, resume=y, action=""
Oct 21 12:48:22 hostname smtpd[50488]: mproc: pony -> lka : 90 IMSG_??? (142)
Oct 21 12:48:22 hostname smtpd[2927]: mproc: lka -> pony : 12 IMSG_FILTER_SMTP_PROTOCOL
Oct 21 12:48:22 hostname smtpd[50488]: smtp: 0x2d6669ad000: >>> 450 4.3.0 RBL processing error, try again later
Oct 21 12:48:22 hostname smtpd[50488]: mproc: pony -> lka : 82 IMSG_REPORT_SMTP_PROTOCOL_SERVER
Oct 21 12:48:22 hostname smtpd[50488]: 5cf54239c7aa819e smtp failed-command command="" result="450 4.3.0 RBL processing error, try again later"
Oct 21 12:48:22 hostname smtpd[50488]: smtp: 0x2d6669ad000: IO_LOWAT <io:0x2d70feccc00 fd=15 to=300000 fl=W ib=0 ob=0>
Oct 21 12:48:22 hostname smtpd[2927]: imsg: lka <- pony: IMSG_??? (142) (len=90)
Oct 21 12:48:22 hostname smtpd[2927]: imsg: lka <- pony: IMSG_REPORT_SMTP_PROTOCOL_SERVER (len=82)
Oct 21 12:48:22 hostname smtpd[50488]: imsg: pony <- lka: IMSG_FILTER_SMTP_PROTOCOL (len=12)
Oct 21 12:48:22 hostname smtpd[89937]: smtpd: process pony socket closed
Oct 21 12:48:22 hostname opensmtpd-filter-rbl: Lost connection with smtpd. Exiting.
Filter lines from smtpd.conf looks like this :
filter "nofcrdns" phase rcpt-to match !fcrdns reject "550 Client RDNS is not forward-confirmed"
filter "dyn_rdns" phase rcpt-to match rdns regex <dyn_rdns> \
reject "550 5.7.1 Sender RDNS rejected (dynamic IP)"
filter "malware_cidr" phase rcpt-to match src <malware_cidr> \
reject "550 5.7.1 Client IP rejected (MALWARE)"
filter "malware_rdns" phase rcpt-to match rdns regex <malware_rdns> \
reject "550 5.7.1 Client RDNS rejected (MALWARE)"
filter "malware_helo" phase rcpt-to match helo <malware_helo> \
reject "550 5.7.1 HELO command rejected (MALWARE)"
filter "malware_ehlo" phase rcpt-to match helo <malware_helo> \
reject "550 5.7.1 EHLO command rejected (MALWARE)"
filter "malware_senders" phase rcpt-to match mail-from <malware_senders> \
reject "550 5.7.1 Sender address rejected (MALWARE)"
filter "spam_cidr" phase rcpt-to match src <spam_cidr> \
reject "550 5.7.1 Client IP rejected (SPAM)"
filter "spam_rdns" phase rcpt-to match rdns regex <spam_rdns> \
reject "550 5.7.1 Client RDNS rejected (SPAM)"
filter "spam_helo" phase rcpt-to match helo <spam_helo> \
reject "550 5.7.1 HELO command rejected (SPAM)"
filter "spam_ehlo" phase rcpt-to match helo <spam_helo> \
reject "550 5.7.1 EHLO command rejected (SPAM)"
filter "spam_senders" phase rcpt-to match mail-from <spam_senders> \
reject "550 5.7.1 Sender address rejected (SPAM)"
filter "rbl" proc-exec "opensmtpd-filter-rbl -r zen.spamhaus.org -j bl.spamcop.net"
filter "fullfilter" chain { \
nofcrdns, dyn_rdns, \
malware_cidr, malware_rdns, malware_helo, malware_ehlo, malware_senders, \
spam_cidr, spam_rdns, spam_helo, spam_ehlo, spam_senders, rbl \
}
listen on all tls pki "hostname.domain.tld" no-dsn filter "fullfilter"
Any pointers to start troubleshooting this ?
Thanks,
Best regards,
Antonin
