On 12/05/20 21:07 -0400, Viktor Dukhovni wrote:
At this point, clone your submission service onto port 588, and configure that copy with "smtpd -vvv" + all the other options. Then use your client to connect to port 588, and there should now be voluminous logging from the Postfix I/O layer (events and vstreams). The question is now whether Postfix is seeing EOF from OpenSSL and then reciprocating by closing the stream, or somehow deciding to close the stream (for no obvious reason).
Thanks. I've attached the log, pruned to the important section. I wish I could offer an interpretation, but I'm ignorant to the arcana that's on full display in this log. Alexander
May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: reply: SMFIR_CONTINUE data 0 bytes May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: before input_transp_cleanup: cleanup flags = enable_header_body_filter enable_automatic_bcc enable_address_mapping enable_milters May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: after input_transp_cleanup: cleanup flags = enable_header_body_filter enable_automatic_bcc enable_address_mapping enable_milters May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: name_mask: sendmail May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: name_mask: verify May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: connect to subsystem public/cleanup May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: vstream_buf_get_ready: fd 24 got 23 May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: public/cleanup socket: wanted attribute: queue_id May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: input attribute name: queue_id May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: input attribute value: 2F82C102C059 May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: public/cleanup socket: wanted attribute: (list terminator) May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: input attribute name: (end) May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: send attr flags = 242 May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type m len 1 data 0 May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: send 0 milters May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type T len 16 data 1589335446 May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type A len 22 data log_ident= May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type A len 22 data rewrite_co May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type A len 17 data sasl_metho May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type A len 42 data sasl_usern May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type S len 28 data <data scrubbed>@ May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type A len 51 data log_client May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type A len 32 data log_client May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type A len 21 data log_client May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type A len 69 data log_messag May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type A len 32 data log_helo_n May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type A len 23 data log_protoc May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type A len 47 data client_nam May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type A len 55 data reverse_cl May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type A len 28 data client_add May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type A len 17 data client_por May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type A len 29 data server_add May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type A len 15 data server_por May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type A len 28 data helo_name= May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type A len 19 data protocol_n May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type A len 21 data client_add May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: 2F82C102C059: client=<data scrubbed>[<data scrubbed>], sasl_method=LOGIN, sasl_username=<data scrubbed> May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type A len 45 data dsn_orig_r May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: rec_put: type R len 24 data <data scrubbed> May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: vstream_fflush_some: fd 24 flush 763 May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: > <data scrubbed>[<data scrubbed>]: 250 2.1.5 Ok May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: watchdog_pat: 0x5571a55eaa60 May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: vstream_fflush_some: fd 17 flush 14 May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: warning: TLS library problem: error:140E0197:SSL routines:SSL_shutdown:shutdown while in init:../ssl/ssl_lib.c:2086: May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: smtp_get: EOF ...match_hostname/addr stuff... May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: send attr request = disconnect May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: send attr ident = 588:<data scrubbed> May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: vstream_fflush_some: fd 18 flush 44 May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: vstream_buf_get_ready: fd 18 got 10 May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: private/anvil: wanted attribute: status May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: input attribute name: status May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: input attribute value: 0 May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: private/anvil: wanted attribute: (list terminator) May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: input attribute name: (end) May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: lost connection after RCPT from <data scrubbed>[<data scrubbed>] May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: abort all milters May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: milter8_abort: abort milter inet:localhost:8891 May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: vstream_fflush_some: fd 24 flush 0 May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: abort all milters May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: milter8_abort: abort milter inet:localhost:8891 May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: disconnect event to all milters May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: milter8_disc_event: quit milter inet:localhost:8891 May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: vstream_fflush_some: fd 19 flush 15 May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: disconnect from <data scrubbed>[<data scrubbed>] ehlo=2 starttls=1 auth=1 mail=1 rcpt=1 commands=6 May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: free all milters May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: free milter inet:localhost:8891 May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: master_notify: status 1 May 12 19:04:06 vasaconsulting postfix/smtpd[3301]: connection closed
