Warning message
in [Postfix]
|
From: Jerry on 10 Mar 2010 05:30 On Tue, 9 Mar 2010 19:19:28 -0500 Victor Duchovni <Victor.Duchovni(a)morganstanley.com> replied: >Is this the MUA? Does the MUA bother to send QUIT, or does it just >disconnect? You can use "debug_peer_list" to see what this client >is up to after it sends mail. OK Victor, this is the complete output of "debug_peer_list" with appropriate entries disguised. I changed the password prior to sending so it would not be a security problem. I realize that this is probably way more than you wanted; however, I did not want to leave any important information out. Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: connect from xxxxxx.my_domain.com[192.168.1.101] Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: match_hostname: xxxxxx.my_domain.com ~? 127.0.0.0/8 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: match_hostaddr: 192.168.1.101 ~? 127.0.0.0/8 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: match_hostname: xxxxxx.my_domain.com ~? 192.168.1.0/24 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: match_hostaddr: 192.168.1.101 ~? 192.168.1.0/24 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: report connect to all milters Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "j" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: result "xxxxxx.my_domain.com" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "{daemon_name}" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: result "ORIGINATING" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "v" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: result "Postfix 2.7-20100117" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter8_connect: non-protocol events for protocol version 6: Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter8_connect: transport=unix endpoint=/var/run/clamav/clmilter.sock Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter8_connect: my_version=0x6 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter8_connect: my_actions=0x1ff SMFIF_ADDHDRS SMFIF_CHGBODY SMFIF_ADDRCPT SMFIF_DELRCPT SMFIF_CHGHDRS SMFIF_QUARANTINE SMFIF_CHGFROM SMFIF_ADDRCPT_PAR SMFIF_SETSYMLIST Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: 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 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter8_connect: milter unix:/var/run/clamav/clmilter.sock version 6 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter8_connect: events SMFIP_NOHELO SMFIP_NOEOH SMFIP_NOUNKNOWN SMFIP_NODATA Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter8_connect: requests SMFIF_ADDHDRS SMFIF_QUARANTINE Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter8_conn_event: milter unix:/var/run/clamav/clmilter.sock: connect xxxxxx.my_domain.com/192.168.1.101 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: event: SMFIC_CONNECT; macros: j=xxxxxx.my_domain.com {daemon_name}=ORIGINATING v=Postfix 2.7-20100117 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: reply: SMFIR_ACCEPT data 0 bytes Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 220 xxxxxx.my_domain.com ESMTP Postfix (2.7-20100117) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: watchdog_pat: 0x28607d88 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: < xxxxxx.my_domain.com[192.168.1.101]: EHLO xxxxxx.my_domain.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: report helo to all milters Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "{tls_version}" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "{cipher}" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "{cipher_bits}" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "{cert_subject}" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "{cert_issuer}" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter8_helo_event: skip milter unix:/var/run/clamav/clmilter.sock Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250-xxxxxx.my_domain.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250-PIPELINING Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250-SIZE 10240000 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250-ETRN Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: match_hostname: xxxxxx.my_domain.com ~? 127.0.0.0/8 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: match_hostaddr: 192.168.1.101 ~? 127.0.0.0/8 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: match_hostname: xxxxxx.my_domain.com ~? 192.168.1.0/24 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: match_hostaddr: 192.168.1.101 ~? 192.168.1.0/24 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250-STARTTLS Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250-XVERP Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250-ENHANCEDSTATUSCODES Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250-8BITMIME Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250 DSN Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: watchdog_pat: 0x28607d88 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: < xxxxxx.my_domain.com[192.168.1.101]: STARTTLS Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: query milter states for other event Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter8_other_event: milter unix:/var/run/clamav/clmilter.sock Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 220 2.0.0 Ready to start TLS Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: abort all milters Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter8_abort: skip milter unix:/var/run/clamav/clmilter.sock Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr request = seed Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr size = 32 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/tlsmgr: wanted attribute: status Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: status Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: 0 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/tlsmgr: wanted attribute: seed Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: seed Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: Ss+VdY4crk1YNolMhFiFLlcQqwuHNfkRLcaiFyLEuDE= Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/tlsmgr: wanted attribute: (list terminator) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: (end) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr request = update Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr cache_type = smtpd Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr cache_id = 1F230F5B582F44EBA99161DE4EA6DBDC728276215D95AE70681442B4A33E1D6C&s=submission Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr session = [data 127 bytes] Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/tlsmgr: wanted attribute: status Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: status Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: 0 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/tlsmgr: wanted attribute: (list terminator) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: (end) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: xsasl_cyrus_server_create: SASL service=smtp, realm=xxxxxx.my_domain.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: name_mask: noanonymous Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: watchdog_pat: 0x28607d88 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: < xxxxxx.my_domain.com[192.168.1.101]: EHLO xxxxxx.my_domain.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: report helo to all milters Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "{tls_version}" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: result "TLSv1" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "{cipher}" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: result "DHE-RSA-AES128-SHA" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "{cipher_bits}" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: result "128" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "{cert_subject}" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "{cert_issuer}" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter8_helo_event: skip milter unix:/var/run/clamav/clmilter.sock Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250-xxxxxx.my_domain.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250-PIPELINING Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250-SIZE 10240000 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250-ETRN Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250-AUTH LOGIN PLAIN DIGEST-MD5 CRAM-MD5 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: match_hostname: xxxxxx.my_domain.com ~? 127.0.0.0/8 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: match_hostaddr: 192.168.1.101 ~? 127.0.0.0/8 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: match_hostname: xxxxxx.my_domain.com ~? 192.168.1.0/24 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: match_hostaddr: 192.168.1.101 ~? 192.168.1.0/24 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250-AUTH=LOGIN PLAIN DIGEST-MD5 CRAM-MD5 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250-XVERP Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250-ENHANCEDSTATUSCODES Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250-8BITMIME Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250 DSN Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: watchdog_pat: 0x28607d88 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: < xxxxxx.my_domain.com[192.168.1.101]: AUTH CRAM-MD5 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: query milter states for other event Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter8_other_event: milter unix:/var/run/clamav/clmilter.sock Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: xsasl_cyrus_server_first: sasl_method CRAM-MD5 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: xsasl_cyrus_server_auth_response: uncoded server challenge: <2423173764.9924061(a)xxxxxx.my_domain.com> Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 334 PDI0MjMxNzM3NjQuOTkyNDA2MUBzY29ycGlvLnNlaWJlcmNvbS5uZXQ+ Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: < xxxxxx.my_domain.com[192.168.1.101]: Z2VyYXJkIDM4ODg0YmZkMjI4OTQ2NTZkYjM2OGNhODBkYThlZmIx Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: xsasl_cyrus_server_next: decoded response: user 38884bfd22894656db368ca80da8efb1 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 235 2.7.0 Authentication successful Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: watchdog_pat: 0x28607d88 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: < xxxxxx.my_domain.com[192.168.1.101]: MAIL FROM:<user(a)my_domain.comuser@my_domain.com> SIZE=1495 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: extract_addr: input: <user(a)my_domain.com> Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: smtpd_check_addr: addr=user(a)my_domain.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: connect to subsystem private/rewrite Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr request = rewrite Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr rule = local Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr address = user(a)my_domain.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: flags Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: flags Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: 0 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: address Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: address Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: user(a)my_domain.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: (list terminator) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: (end) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: rewrite_clnt: local: user(a)my_domain.com -> user(a)my_domain.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr request = resolve Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr sender = Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr address = user(a)my_domain.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: flags Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: flags Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: 0 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: transport Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: transport Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: dovecot Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: nexthop Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: nexthop Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: my_domain.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: recipient Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: recipient Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: user(a)my_domain.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: flags Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: flags Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: 1024 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: (list terminator) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: (end) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: resolve_clnt: `' -> `user(a)my_domain.com' -> transp=`dovecot' host=`my_domain.com' rcpt=`user(a)my_domain.com' flags= class=virtual Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: ctable_locate: install entry key user(a)my_domain.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: extract_addr: in: <user(a)my_domain.com>, result: user(a)my_domain.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: report sender to all milters Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "i" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "{auth_type}" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: result "CRAM-MD5" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "{auth_authen}" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: result "user(a)xxxxxx.my_domain.com" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "{auth_author}" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "{mail_addr}" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: ctable_locate: leave existing entry key user(a)my_domain.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: result "user(a)my_domain.com" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "{mail_host}" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: ctable_locate: leave existing entry key user(a)my_domain.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: result "my_domain.com" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "{mail_mailer}" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: ctable_locate: leave existing entry key user(a)my_domain.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: result "dovecot" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter8_mail_event: skip milter unix:/var/run/clamav/clmilter.sock Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: fsspace: .: block size 2048, blocks free 512223 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: smtpd_check_queue: blocks 2048 avail 512223 min_free 0 msg_size_limit 10240000 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250 2.1.0 Ok Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: watchdog_pat: 0x28607d88 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: < xxxxxx.my_domain.com[192.168.1.101]: RCPT TO:<recipient(a)ISP.com> Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: extract_addr: input: <recipient(a)ISP.com> Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: smtpd_check_addr: addr=recipient(a)ISP.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr request = rewrite Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr rule = local Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr address = recipient(a)ISP.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: flags Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: flags Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: 0 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: address Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: address Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: recipient(a)ISP.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: (list terminator) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: (end) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: rewrite_clnt: local: recipient(a)ISP.com -> recipient(a)ISP.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr request = resolve Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr sender = Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr address = recipient(a)ISP.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: flags Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: flags Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: 0 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: transport Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: transport Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: smtp Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: nexthop Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: nexthop Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: ISP.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: recipient Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: recipient Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: recipient(a)ISP.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: flags Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: flags Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: 4096 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: (list terminator) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: (end) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: resolve_clnt: `' -> `recipient(a)ISP.com' -> transp=`smtp' host=`ISP.com' rcpt=`recipient(a)ISP.com' flags= class=default Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: ctable_locate: install entry key recipient(a)ISP.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: extract_addr: in: <recipient(a)ISP.com>, result: recipient(a)ISP.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr request = rewrite Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr rule = local Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr address = double-bounce Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: flags Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: flags Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: 0 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: address Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: address Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: double-bounce(a)my_domain.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: private/rewrite socket: wanted attribute: (list terminator) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: (end) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: rewrite_clnt: local: double-bounce -> double-bounce(a)my_domain.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: >>> START Client host RESTRICTIONS <<< Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: generic_checks: name=permit_sasl_authenticated Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: generic_checks: name=permit_sasl_authenticated status=1 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: >>> START Recipient address RESTRICTIONS <<< Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: generic_checks: name=permit_sasl_authenticated Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: generic_checks: name=permit_sasl_authenticated status=1 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: >>> CHECKING RECIPIENT MAPS <<< Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: ctable_locate: leave existing entry key recipient(a)ISP.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: maps_find: recipient_canonical_maps: recipient(a)ISP.com: not found Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: match_list_match: ISP.com: no match Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: maps_find: recipient_canonical_maps: @ISP.com: not found Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: mail_addr_find: recipient(a)ISP.com -> (not found) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: maps_find: canonical_maps: recipient(a)ISP.com: not found Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: match_list_match: ISP.com: no match Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: maps_find: canonical_maps: @ISP.com: not found Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: mail_addr_find: recipient(a)ISP.com -> (not found) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: maps_find: virtual_alias_maps: recipient(a)ISP.com: not found Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: match_list_match: ISP.com: no match Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: maps_find: virtual_alias_maps: @ISP.com: not found Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: mail_addr_find: recipient(a)ISP.com -> (not found) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: report recipient to all milters (flags=0x0) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "i" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "{rcpt_addr}" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: ctable_locate: leave existing entry key recipient(a)ISP.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: result "recipient(a)ISP.com" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "{rcpt_host}" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: ctable_locate: leave existing entry key recipient(a)ISP.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: result "ISP.com" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "{rcpt_mailer}" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: ctable_locate: leave existing entry key recipient(a)ISP.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: result "smtp" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter8_rcpt_event: skip milter unix:/var/run/clamav/clmilter.sock Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: smtpd_check_rewrite: trying: permit_inet_interfaces Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: permit_inet_interfaces: xxxxxx.my_domain.com 192.168.1.101 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: before input_transp_cleanup: cleanup flags = enable_header_body_filter enable_automatic_bcc enable_address_mapping enable_milters Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: after input_transp_cleanup: cleanup flags = enable_header_body_filter enable_automatic_bcc enable_address_mapping enable_milters Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: connect to subsystem public/cleanup Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: public/cleanup socket: wanted attribute: queue_id Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: queue_id Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: 9350E22831 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: public/cleanup socket: wanted attribute: (list terminator) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: (end) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: send attr flags = 242 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: 9350E22831: client=xxxxxx.my_domain.com[192.168.1.101], sasl_method=CRAM-MD5, sasl_username=user(a)xxxxxx.my_domain.com Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250 2.1.5 Ok Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: watchdog_pat: 0x28607d88 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: < xxxxxx.my_domain.com[192.168.1.101]: DATA Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: report data to all milters Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: "i" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter_macro_lookup: result "9350E22831" Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter8_data_event: skip milter unix:/var/run/clamav/clmilter.sock Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 354 End data with <CR><LF>.<CR><LF> Mar 10 04:59:46 xxxxxxx postfix/cleanup[93355]: 9350E22831: message-id=<20100310045946.575e6a8b(a)xxxxxx.my_domain.com> Mar 10 04:59:46 xxxxxxx postfix/qmgr[1317]: 9350E22831: from=<user(a)my_domain.com>, size=1889, nrcpt=1 (queue active) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: public/cleanup socket: wanted attribute: status Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: status Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: 0 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: public/cleanup socket: wanted attribute: reason Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: reason Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute value: (end) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: public/cleanup socket: wanted attribute: (list terminator) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: input attribute name: (end) Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 250 2.0.0 Ok: queued as 9350E22831 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: abort all milters Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter8_abort: skip milter unix:/var/run/clamav/clmilter.sock Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: watchdog_pat: 0x28607d88 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: < xxxxxx.my_domain.com[192.168.1.101]: QUIT Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 221 2.0.0 Bye Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: match_hostname: xxxxxx.my_domain.com ~? 127.0.0.0/8 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: match_hostaddr: 192.168.1.101 ~? 127.0.0.0/8 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: match_hostname: xxxxxx.my_domain.com ~? 192.168.1.0/24 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: match_hostaddr: 192.168.1.101 ~? 192.168.1.0/24 Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: warning: network_biopair_interop: error reading 5 bytes from the network: Connection reset by peer Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: abort all milters Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter8_abort: skip milter unix:/var/run/clamav/clmilter.sock Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: disconnect event to all milters Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: milter8_disc_event: skip quit milter unix:/var/run/clamav/clmilter.sock Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: disconnect from xxxxxx.my_domain.com[192.168.1.101] Mar 10 04:59:49 xxxxxxx postfix/smtp[93359]: 9350E22831: to=<recipient(a)ISP.com>, relay=smtp.gmail.com[74.125.93.109]:25, delay=3, delays=0.12/0.02/0.97/1.9, dsn=2.0.0, status=sent (250 2.0.0 OK 1268215189 5sm18267533qwg.53) Mar 10 04:59:49 xxxxxxx postfix/qmgr[1317]: 9350E22831: removed -- Jerry postfix.user(a)yahoo.com TO REPORT A PROBLEM see http://www.postfix.org/DEBUG_README.html#mail TO (UN)SUBSCRIBE see http://www.postfix.org/lists.html Veni, Vidi, VISA: I came, I saw, I did a little shopping.
From: Wietse Venema on 10 Mar 2010 08:23 Jerry: > Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: < xxxxxx.my_domain.com[192.168.1.101]: QUIT > Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 221 2.0.0 Bye > Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: warning: network_biopair_interop: error reading 5 bytes from the network: Connection reset by peer The client sends QUIT and disconnects. It's not going to wait for the server's "220 Bye" response. If the server were to report an error, there is nothing the client could do anyway. In the case of Postfix SMTP read/write requests, I think this warning message is redundant. The function that reports this warning also returns a standard read(2) or write(2) error result to the caller, and leaves it up to the caller to take action. Such warnings are useful in debug mode, but otherwise it's just noise. I see that there also is redundancy in error reporting for accept() and connect() operations that could be streamlined (report the system errno value in the caller instead of the low-level helper). Wietse
From: Victor Duchovni on 10 Mar 2010 14:03 On Wed, Mar 10, 2010 at 08:23:00AM -0500, Wietse Venema wrote: > > Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: < xxxxxx.my_domain.com[192.168.1.101]: QUIT > > Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 221 2.0.0 Bye > > Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: warning: network_biopair_interop: error reading 5 bytes from the network: Connection reset by peer > > The client sends QUIT and disconnects. It's not going to wait for > the server's "220 Bye" response. If the server were to report an > error, there is nothing the client could do anyway. With TLS sessions, after "QUIT" processing, the server tries to perform a clean SSL_shutdown() of the SSL/TLS session. If the client closes the connection without performing the SSL_shutdown(), you'll see the above warning. From the SSL_shutdown(3) manpage: NOTES SSL_shutdown() tries to send the "close notify" shutdown alert to the peer. Whether the operation succeeds or not, the SSL_SENT_SHUTDOWN flag is set and a currently open session is considered closed and good and will be kept in the session cache for further reuse. The shutdown procedure consists of 2 steps: the sending of the "close notify" shutdown alert and the reception of the peer's "close notify" shutdown alert. According to the TLS standard, it is acceptable for an application to only send its shutdown alert and then close the underlying connection without waiting for the peer's response (this way resources can be saved, as the process can already terminate or serve another connection). When the underlying connection shall be used for more communications, the complete shutdown procedure (bidirectional "close notify" alerts) must be performed, so that the peers stay synchronized. Another option (given that Postfix does not have a "STOPTLS" feature that would allow re-use of the physical connection for further I/O after SSL shutdown) is for Postfix to not do a full (bi-directional) SSL_shutdown(), and just send the "close notify" without waiting for a peer response. -- Viktor. P.S. Morgan Stanley is looking for a New York City based, Senior Unix system/email administrator to architect and sustain our perimeter email environment. If you are interested, please drop me a note.
From: Wietse Venema on 10 Mar 2010 15:08 Victor Duchovni: > On Wed, Mar 10, 2010 at 08:23:00AM -0500, Wietse Venema wrote: > > > > Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: < xxxxxx.my_domain.com[192.168.1.101]: QUIT > > > Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: > xxxxxx.my_domain.com[192.168.1.101]: 221 2.0.0 Bye > > > Mar 10 04:59:46 xxxxxxx postfix/smtpd[93352]: warning: network_biopair_interop: error reading 5 bytes from the network: Connection reset by peer > > > > The client sends QUIT and disconnects. It's not going to wait for > > the server's "220 Bye" response. If the server were to report an > > error, there is nothing the client could do anyway. > > With TLS sessions, after "QUIT" processing, the server tries to perform > a clean SSL_shutdown() of the SSL/TLS session. If the client closes > the connection without performing the SSL_shutdown(), you'll see the > above warning. From the SSL_shutdown(3) manpage: > > NOTES > SSL_shutdown() tries to send the "close notify" shutdown > alert to the peer. Whether the operation succeeds or not, the > SSL_SENT_SHUTDOWN flag is set and a currently open session is > considered closed and good and will be kept in the session cache > for further reuse. > > The shutdown procedure consists of 2 steps: the sending of the > "close notify" shutdown alert and the reception of the peer's > "close notify" shutdown alert. According to the TLS standard, it > is acceptable for an application to only send its shutdown alert > and then close the underlying connection without waiting for the > peer's response (this way resources can be saved, as the process > can already terminate or serve another connection). When the > underlying connection shall be used for more communications, > the complete shutdown procedure (bidirectional "close notify" > alerts) must be performed, so that the peers stay synchronized. > > Another option (given that Postfix does not have a "STOPTLS" feature that > would allow re-use of the physical connection for further I/O after SSL > shutdown) The Postfix SMTP client does properly shutdown the connnection. smtp_session_free() calls tls_client_stop(). tls_client_stop() is an alias for tls_session_stop(). tls_session_stop() calls tls_bio_shutdown(). tls_bio_shutdown() is an alias that calls SSL_shutdown(). Sending application-level data after turning off TLS is definitely a no-no. That leaves us with redundant error handling in Postfix: logging a warning with errno, and then passing the error up-stream where we know that the error is harmless. The fix is not to log that condition by default. > is for Postfix to not do a full (bi-directional) SSL_shutdown(), > and just send the "close notify" without waiting for a peer response. Wietse
From: Victor Duchovni on 10 Mar 2010 15:23 On Wed, Mar 10, 2010 at 03:08:18PM -0500, Wietse Venema wrote: > > With TLS sessions, after "QUIT" processing, the server tries to perform > > a clean SSL_shutdown() of the SSL/TLS session. If the client closes > > the connection without performing the SSL_shutdown(), you'll see the > > above warning. [...] > > > > Another option (given that Postfix does not have a "STOPTLS" feature that > > would allow re-use of the physical connection for further I/O after SSL > > shutdown) > > The Postfix SMTP client does properly shutdown the connnection. Yes, my point was that it would legal to do just a one-sided SSL_shutdown(), instead of a full bi-directional SSL_shutdown(). > smtp_session_free() calls tls_client_stop(). > tls_client_stop() is an alias for tls_session_stop(). > tls_session_stop() calls tls_bio_shutdown(). > tls_bio_shutdown() is an alias that calls SSL_shutdown(). Yes, it calls SSL_shutdown() twice, once to notify the peer, and another time to read the peer's shutdown alert. We could omit the second step if we wanted to, and thereby avoid the condition that generates this (harmless) warning. > Sending application-level data after turning off TLS is definitely > a no-no. At this time there is no standard for reverting an SMTP connection to plain-text and resuming TLS on the same connection (or even continuing in plain-text). Technically, this is possible, and potentially even an interesting SMTP extension that would allow caching of TLS connections, by suspending TLS, caching the socket, and then resuming TLS when the plain-text socket is re-used. We still have soft (remember good IPs) connection re-use on the drawing board. Most likely the above will never be needed. -- Viktor. P.S. Morgan Stanley is looking for a New York City based, Senior Unix system/email administrator to architect and sustain our perimeter email environment. If you are interested, please drop me a note.
First
|
Prev
|
Next
|
Last
Pages: 1 2 3 Prev: problem with relay, please help me... Next: conten filter and always_bcc parameter |