weird disconnect from Chase bank
2017-01-12 by Bill Levering
Recently, I changed the following flag in sendmail.mc from: INPUT_MAIL_FILTER(`greylist',`S=local:/var/run/milter-greylist/milter-greylist.sock, F=, T=S:240s;R:240s’)dnl to: INPUT_MAIL_FILTER(`greylist',`S=local:/var/run/milter-greylist/milter-greylist.sock, F=T, T=S:240s;R:240s')dnl and added some RBL entries. And now mail from Chase bank disconnects… A) I’m wondering if chase is dropping the connection because of the long delay of going thru the RBLs B) something else? Any ideas? Bill Below shows more logging from sendmail. From what I’m seeing, it looks like the HELO process proceeds normally, and then no DATA is sent (for the body of the message). Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: milter=greylist, action=helo, continue Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250-mail.planx.com Hello shvj13.jpmchase.com [159.53.110.191], pleased to meet you Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250-ENHANCEDSTATUSCODES Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250-PIPELINING Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250-8BITMIME Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250-SIZE Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250-DSN Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250-ETRN Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250-AUTH LOGIN PLAIN Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250-DELIVERBY Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250 HELP Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: milter=greylist, action=helo, continue Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250-mail.planx.com Hello shvj13.jpmchase.com [159.53.110.191], pleased to meet you Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250-ENHANCEDSTATUSCODES Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250-PIPELINING Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250-8BITMIME Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250-SIZE Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250-DSN Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250-ETRN Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250-AUTH LOGIN PLAIN Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250-DELIVERBY Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250 HELP Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: <-- MAIL From:<chaseonline@...se.com> SIZE=2338 Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: <-- MAIL From:<chaseonline@...> SIZE=2338 Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: Milter: sender: <chaseonline@emailonline.chase.com> Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: Milter: sender: <chaseonline@...> Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: milter=greylist, action=mail, continue Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: milter=greylist, action=mail, continue Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: milter=opendkim, action=mail, continue Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250 2.1.0 <chaseonline@...>... Sender ok Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: milter=opendkim, action=mail, continue Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: --- 250 2.1.0 <chaseonline@...>... Sender ok Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: <-- RCPT To:<idbill@...> Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: <-- RCPT To:<idbill@planx.com> Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: Milter: rcpts: <idbill@...> Jan 12 17:09:16 mail sendmail[7976]: v0CH9GFL007976: Milter: rcpts: <idbill@...> Jan 12 17:10:47 mail milter-greylist: v0CH9GFL007976: addr 159.53.110.191 from <chaseonline@...> rcpt <idbill@...>: autowhitelisted for another 120:00:00 Jan 12 17:10:47 mail milter-greylist: v0CH9GFL007976: addr 159.53.110.191 from <chaseonline@emailonline.chase.com> rcpt <idbill@...>: autowhitelisted for another 120:00:00 Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: milter=greylist, action=rcpt, continue Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: milter=greylist, action=rcpt, continue Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: milter=opendkim, action=rcpt, continue Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: --- 250 2.1.5 <idbill@planx.com>... Recipient ok Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: <-- DATA Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: milter=opendkim, action=rcpt, continue Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: --- 250 2.1.5 <idbill@...>... Recipient ok Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: <-- DATA Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: milter=greylist, action=data, continue Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: --- 354 Enter mail, end with "." on a line by itself Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: collect: premature EOM: unexpected close Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: milter=greylist, action=data, continue Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: --- 354 Enter mail, end with "." on a line by itself Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: collect: premature EOM: unexpected close Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: collect: unexpected close on connection from shvj13.jpmchase.com, sender=<chaseonline@...> Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: --- 421 4.4.1 collect: unexpected close on connection from shvj13.jpmchase.com, from=<chaseonline@...m> (hold) Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: --- 421 4.4.1 collect: unexpected close on connection from shvj13.jpmchase.com, from=<chaseonline@...> (held) Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: from=<chaseonline@...>, size=0, class=0, nrcpts=1, proto=ESMTP, daemon=MTA-v6, relay=shvj13.jpmchase.com [159.53.110.191] Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: --- 421 4.4.1 collect: unexpected close on connection from shvj13.jpmchase.com, from=<chaseonline@...> (hold) Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: --- 421 4.4.1 collect: unexpected close on connection from shvj13.jpmchase.com, from=<chaseonline@...ase.com> (held) Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: from=<chaseonline@...>, size=0, class=0, nrcpts=1, proto=ESMTP, daemon=MTA-v6, relay=shvj13.jpmchase.com [159.53.110.191] Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: collect: unexpected close on connection from shvj13.jpmchase.com, sender=<chaseonline@emailonline.chase.com> Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: --- 421 4.4.1 collect: unexpected close on connection from shvj13.jpmchase.com, from=<chaseonline@...> (hold) Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: --- 421 4.4.1 collect: unexpected close on connection from shvj13.jpmchase.com, from=<chaseonline@...> (held) Jan 12 17:10:47 mail sendmail[7976]: v0CH9GFL007976: from=<chaseonline@...>, size=0, class=0, nrcpts=1, proto=ESMTP, daemon=MTA-v6, relay=shvj13.jpmchase.com [159.53.110.191] Jan 12 17:10:47 mail sendmail[7976]: STARTTLS: write error=syscall error (-1), errno=32, get_error=error:00000000:lib(0):func(0):reason(0), retry=99, ssl_err=5 Jan 12 17:10:47 mail sendmail[7976]: STARTTLS: write error=syscall error (-1), errno=32, get_error=error:00000000:lib(0):func(0):reason(0), retry=99, ssl_err=5 This is with filter-greylist disabled: Jan 12 19:46:27 mail sendmail[15392]: STARTTLS=server, relay=shvf11.jpmchase.com [159.53.46.148], version=TLSv1/SSLv3, verify=NOT, cipher=DHE-RSA-AES256-GCM-SHA384, bits=256/256 Jan 12 19:46:27 mail sendmail[15392]: STARTTLS=server, relay=shvf11.jpmchase.com [159.53.46.148], version=TLSv1/SSLv3, verify=NOT, cipher=DHE-RSA-AES256-GCM-SHA384, bits=256/256 Jan 12 19:46:27 mail spamd[26858]: spamd: got connection over /run/spamd.sock Jan 12 19:46:27 mail spamd[26858]: spamd: got connection over /run/spamd.sock Jan 12 19:46:27 mail spamd[26858]: spamd: processing message <1738981032.31282985.1484185802834.JavaMail.wasadm@cdc2vpc5lpr16> for idbill:1018 Jan 12 19:46:27 mail spamd[26858]: spamd: processing message <1738981032.31282985.1484185802834.JavaMail.wasadm@cdc2vpc5lpr16> for idbill:1018 Jan 12 19:46:27 mail sendmail[15392]: v0CJkL66015392: from=<chaseonline@emailonline.chase.com>, size=2336, class=0, nrcpts=1, msgid=<-1336726568.30646495.1484183798591.JavaMail.wasadm@cdc2vpc5lpr20>, proto=ESMTP, daemon=MTA-v6, relay=shvf11.jpmchase.com [159.53.46.148] Jan 12 19:46:27 mail sendmail[15392]: v0CJkL66015392: from=<chaseonline@...>, size=2336, class=0, nrcpts=1, msgid=<-1336726568.30646495.1484183798591.JavaMail.wasadm@cdc2vpc5lpr20>, proto=ESMTP, daemon=MTA-v6, relay=shvf11.jpmchase.com [159.53.46.148] Jan 12 19:46:27 mail opendkim[15320]: v0CJkL66015392: shvf11.jpmchase.com [159.53.46.148] not internal Jan 12 19:46:27 mail opendkim[15320]: v0CJkL66015392: not authenticated Jan 12 19:46:27 mail opendkim[15320]: v0CJkL66015392: shvf11.jpmchase.com [159.53.46.148] not internal Jan 12 19:46:27 mail opendkim[15320]: v0CJkL66015392: not authenticated Jan 12 19:46:27 mail opendkim[15320]: v0CJkL66015392: DKIM verification successful Jan 12 19:46:27 mail sendmail[15392]: v0CJkL66015392: Milter insert (1): header: Authentication-Results: mail.planx.com;\n\tdkim=pass (2048-bit key) header.d=emailonline.chase.com header.i=@emailonline.chase.com header.b="v5p4IZct" Jan 12 19:46:27 mail opendkim[15320]: v0CJkL66015392: DKIM verification successful Jan 12 19:46:27 mail sendmail[15392]: v0CJkL66015392: Milter insert (1): header: Authentication-Results: mail.planx.com;\n\tdkim=pass (2048-bit key) header.d=emailonline.chase.com header.i=@... header.b="v5p4IZct" Jan 12 19:46:27 mail spamd[26858]: spamd: clean message (1.6/4.0) for idbill:1018 in 0.4 seconds, 2867 bytes. Jan 12 19:46:27 mail spamd[26858]: spamd: result: . 1 - DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,HTML_MESSAGE,HTML_MIME_NO_HTML_TAG,MIME_HTML_ONLY,SPF_PASS scantime=0.4,size=2867,user=idbill,uid=1018,required_score=4.0,rhost=localhost,raddr=127.0.0.1,rport=/run/spamd.sock,mid=<1738981032.31282985.1484185802834.JavaMail.wasadm@cdc2vpc5lpr16>,autolearn=no Jan 12 19:46:27 mail spamd[26858]: spamd: clean message (1.6/4.0) for idbill:1018 in 0.4 seconds, 2867 bytes. Jan 12 19:46:27 mail spamd[26858]: spamd: result: . 1 - DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,HTML_MESSAGE,HTML_MIME_NO_HTML_TAG,MIME_HTML_ONLY,SPF_PASS scantime=0.4,size=2867,user=idbill,uid=1018,required_score=4.0,rhost=localhost,raddr=127.0.0.1,rport=/run/spamd.sock,mid=<1738981032.31282985.1484185802834.JavaMail.wasadm@cdc2vpc5lpr16>,autolearn=no Jan 12 19:46:27 mail spamd[32249]: spamd: got connection over /run/spamd.sock Jan 12 19:46:27 mail spamd[32249]: spamd: got connection over /run/spamd.sock Jan 12 19:46:27 mail spamd[5274]: prefork: child states: IB Jan 12 19:46:27 mail spamd[5274]: prefork: child states: IB Jan 12 19:46:27 mail spamd[32249]: spamd: processing message <-1336726568.30646495.1484183798591.JavaMail.wasadm@cdc2vpc5lpr20> for idbill:1018 Jan 12 19:46:27 mail spamd[32249]: spamd: processing message <-1336726568.30646495.1484183798591.JavaMail.wasadm@cdc2vpc5lpr20> for idbill:1018 Jan 12 19:46:30 mail spamd[32249]: spamd: clean message (-3.4/4.0) for idbill:1018 in 2.6 seconds, 2868 bytes. Jan 12 19:46:30 mail spamd[32249]: spamd: result: . -3 - DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,HTML_MESSAGE,HTML_MIME_NO_HTML_TAG,MIME_HTML_ONLY,RCVD_IN_DNSWL_HI,SPF_PASS scantime=2.6,size=2868,user=idbill,uid=1018,required_score=4.0,rhost=localhost,raddr=127.0.0.1,rport=/run/spamd.sock,mid=<-1336726568.30646495.1484183798591.JavaMail.wasadm@cdc2vpc5lpr20>,autolearn=ham Jan 12 19:46:30 mail spamd[32249]: spamd: clean message (-3.4/4.0) for idbill:1018 in 2.6 seconds, 2868 bytes. Jan 12 19:46:30 mail spamd[32249]: spamd: result: . -3 - DKIM_SIGNED,DKIM_VALID,DKIM_VALID_AU,HTML_MESSAGE,HTML_MIME_NO_HTML_TAG,MIME_HTML_ONLY,RCVD_IN_DNSWL_HI,SPF_PASS scantime=2.6,size=2868,user=idbill,uid=1018,required_score=4.0,rhost=localhost,raddr=127.0.0.1,rport=/run/spamd.sock,mid=<-1336726568.30646495.1484183798591.JavaMail.wasadm@cdc2vpc5lpr20>,autolearn=ham Jan 12 19:46:30 mail spamd[5274]: prefork: child states: II Jan 12 19:46:30 mail spamd[5274]: prefork: child states: II Jan 12 19:46:48 mail sendmail[15406]: v0CJkL66015392: to=<idbill@...>, delay=00:00:21, xdelay=00:00:21, mailer=local, pri=32755, dsn=2.0.0, stat=Sent Jan 12 19:46:48 mail sendmail[15406]: v0CJkL66015392: to=<idbill@...>, delay=00:00:21, xdelay=00:00:21, mailer=local, pri=32755, dsn=2.0.0, stat=Sent