SMTP timeouts (postfix, clamav-milter, cyrus-sasl)

(0 comments)

So I had the problem that for some reason I couldn'T send emails anymore ..

looking at the logs i was unsure what the problem was ..

somehow there was nothing in the mail.log file after this:


Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: connect from unknown[<public IP of email client>]
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: smtp_stream_setup: maxtime=300 enable_deadline=0
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: match_hostname: smtpd_client_event_limit_exceptions: unknown ~? <exception ip>/24
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: match_hostaddr: smtpd_client_event_limit_exceptions: <public IP of email client> ~? <exception ip>/24
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: match_hostname: smtpd_client_event_limit_exceptions: unknown ~? 127.0.0.0/8
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: match_hostaddr: smtpd_client_event_limit_exceptions: <public IP of email client> ~? 127.0.0.0/8
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: match_hostname: smtpd_client_event_limit_exceptions: unknown ~? <public IP of email client>/32
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: match_hostaddr: smtpd_client_event_limit_exceptions: <public IP of email client> ~? <public IP of email client>/32
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: report connect to all milters
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: "j"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: result "<mailserver FQDN>"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: "{daemon_name}"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: result "<mailserver FQDN>"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: "{daemon_addr}"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: result "<mailserver IP>"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: "v"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: result "Postfix <version>"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter8_connect: non-protocol events for protocol version 6:
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter8_connect: transport=unix endpoint=/var/run/clamav/clamav-milter.sock
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter8_connect: my_version=0x6
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter8_connect: my_actions=0x1ff SMFIF_ADDHDRS SMFIF_CHGBODY SMFIF_ADDRCPT SMFIF_DELRCPT SMFIF_CHGHDRS SMFIF_QUARANTINE SMFIF_CHGFROM SMFIF_ADDRCPT_PAR SMFIF_SETSYMLIST
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter8_connect: my_events=0x1fffff SMFIP_NOCONNECT SMFIP_NOHELO SMFIP_NOMAIL SMFIP_NORCPT SMFIP_NOBODY SMFIP_NOHDRS SMFIP_NOEOH SMFIP_NR_HDR SMFIP_NOUNKNOWN SMFIP_NODATA SMFIP_SKIP SMFIP_RCPT_REJ SMFIP_NR_CONN SMFIP_NR_HELO SMFIP_NR_MAIL SMFIP_NR_RCPT SMFIP_NR_DATA SMFIP_NR_UNKN SMFIP_NR_EOH SMFIP_NR_BODY SMFIP_HDR_LEADSPC
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter8_connect: milter unix:/var/run/clamav/clamav-milter.sock version 6
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter8_connect: events SMFIP_NOHELO SMFIP_NOEOH SMFIP_NOUNKNOWN SMFIP_NODATA
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter8_connect: requests SMFIF_QUARANTINE
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter8_conn_event: milter unix:/var/run/clamav/clamav-milter.sock: connect unknown/<public IP of email client>
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: event: SMFIC_CONNECT; macros: j=<mailserver FQDN> {daemon_name}=<mailserver FQDN> {daemon_addr}=<mailserver IP> v=Postfix <version>
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: reply: SMFIR_CONTINUE data 0 bytes
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: > unknown[<public IP of email client>]: 220 <mailserver FQDN> ESMTP Postfix
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: watchdog_pat: 0x7ff2a3d7dea0
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: < unknown[<public IP of email client>]: EHLO [<internal IP of email client>]
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: report helo to all milters
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: "{tls_version}"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: "{cipher}"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: "{cipher_bits}"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: "{cert_subject}"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: "{cert_issuer}"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter8_helo_event: milter unix:/var/run/clamav/clamav-milter.sock: helo [<internal IP of email client>]
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: event: SMFIC_HELO; macros: (none)
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: skipping event SMFIC_HELO for milter unix:/var/run/clamav/clamav-milter.sock
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: match_list_match: unknown: no match
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: match_list_match: <public IP of email client>: no match
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: > unknown[<public IP of email client>]: 250-<mailserver FQDN>
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: > unknown[<public IP of email client>]: 250-PIPELINING
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: > unknown[<public IP of email client>]: 250-SIZE 20480000
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: > unknown[<public IP of email client>]: 250-ETRN
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: > unknown[<public IP of email client>]: 250-STARTTLS
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: > unknown[<public IP of email client>]: 250-ENHANCEDSTATUSCODES
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: > unknown[<public IP of email client>]: 250-8BITMIME
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: > unknown[<public IP of email client>]: 250 DSN
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: watchdog_pat: 0x7ff2a3d7dea0
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: < unknown[<public IP of email client>]: STARTTLS
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: query milter states for other event
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter8_other_event: milter unix:/var/run/clamav/clamav-milter.sock
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: > unknown[<public IP of email client>]: 220 2.0.0 Ready to start TLS
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: abort all milters
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter8_abort: abort milter unix:/var/run/clamav/clamav-milter.sock
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: send attr request = seed
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: send attr size = 32
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: private/tlsmgr: wanted attribute: status
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: input attribute name: status
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: input attribute value: 0
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: private/tlsmgr: wanted attribute: seed
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: input attribute name: seed
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: input attribute value: <seed>
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: private/tlsmgr: wanted attribute: (list terminator)
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: input attribute name: (end)
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: send attr request = tktkey
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: send attr keyname = [data 16 bytes]
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: private/tlsmgr: wanted attribute: status
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: input attribute name: status
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: input attribute value: 4294967295
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: private/tlsmgr: wanted attribute: keybuf
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: input attribute name: keybuf
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: input attribute value: <keybuf>
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: private/tlsmgr: wanted attribute: (list terminator)
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: input attribute name: (end)
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: send attr request = tktkey
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: send attr keyname = [data 0 bytes]
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: private/tlsmgr: wanted attribute: status
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: input attribute name: status
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: input attribute value: 0
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: private/tlsmgr: wanted attribute: keybuf
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: input attribute name: keybuf
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: input attribute value: <keybuf 2>
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: private/tlsmgr: wanted attribute: (list terminator)
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: input attribute name: (end)
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: Anonymous TLS connection established from unknown[<public IP of email client>]: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: xsasl_cyrus_server_create: SASL service=smtp, realm=(null)
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: name_mask: noanonymous
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: watchdog_pat: 0x7ff2a3d7dea0
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: < unknown[<public IP of email client>]: EHLO [<internal IP of email client>]
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: report helo to all milters
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: "{tls_version}"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: result "TLSv1.2"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: "{cipher}"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: result "ECDHE-RSA-AES128-GCM-SHA256"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: "{cipher_bits}"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: result "128"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: "{cert_subject}"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter_macro_lookup: "{cert_issuer}"
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter8_helo_event: milter unix:/var/run/clamav/clamav-milter.sock: helo [<internal IP of email client>]
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: event: SMFIC_HELO; macros: {tls_version}=TLSv1.2 {cipher}=ECDHE-RSA-AES128-GCM-SHA256 {cipher_bits}=128
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: skipping event SMFIC_HELO for milter unix:/var/run/clamav/clamav-milter.sock
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: match_list_match: unknown: no match
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: match_list_match: <public IP of email client>: no match
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: > unknown[<public IP of email client>]: 250-<mailserver FQDN>
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: > unknown[<public IP of email client>]: 250-PIPELINING
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: > unknown[<public IP of email client>]: 250-SIZE 20480000
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: > unknown[<public IP of email client>]: 250-ETRN
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: > unknown[<public IP of email client>]: 250-AUTH PLAIN
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: > unknown[<public IP of email client>]: 250-AUTH=PLAIN
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: > unknown[<public IP of email client>]: 250-ENHANCEDSTATUSCODES
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: > unknown[<public IP of email client>]: 250-8BITMIME
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: > unknown[<public IP of email client>]: 250 DSN
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: watchdog_pat: 0x7ff2a3d7dea0
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: < unknown[<public IP of email client>]: AUTH PLAIN <auth>=
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: query milter states for other event
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: milter8_other_event: milter unix:/var/run/clamav/clamav-milter.sock
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: xsasl_cyrus_server_first: sasl_method PLAIN, init_response <auth>=
Jul  2 10:37:06 lordvan postfix/submission/smtpd[13411]: xsasl_cyrus_server_first: decoded initial response

At first I suspected clamav-milter, but after thinking it over again that would mean It would not accept any emails from other servers either .. so it wasn'T that ..

Took me a while to figure out the difference .. what did not work was authenticated SMTP, since all emails from other servers,.. arrive just fine .. turns out Cyrus-SASL was the culprit.. a quick restart of the service solved the problem for me .. probably just some weird error after it's been running for ages. Just putting it in my cronjob to occasionally restart that too should prevent that from happening again ;)

Currently unrated

Comments

There are currently no comments

New Comment

required

required (not published)

optional

required

Recent Posts

Archive

2020
2019
2018
2014
2012
2011
2010
2009
2008
2007

Categories

Authors

Feeds

RSS / Atom