> On 05/01/2023 18:38 EET Gerben Wierda <[email protected]> wrote: > > > I am setting up a new server combination (postfix + dovecot). dovecot's auth > service works for postfix. Just lmtp does not and I need to find out why. I > don't see anything in the dovecot logging, but I see this on the postfix side > (debug) > > Jan 05 16:11:59 snape postfix/lmtp[127]: connection established > Jan 05 16:11:59 snape postfix/lmtp[127]: master_notify: status 0 > Jan 05 16:11:59 snape postfix/lmtp[127]: deliver_request_initial: send > initial response > Jan 05 16:11:59 snape postfix/lmtp[127]: send attr protocol = > delivery_request_protocol > Jan 05 16:16:59 snape postfix/lmtp[126]: smtp_get: timeout > Jan 05 16:16:59 snape postfix/lmtp[126]: connect to subsystem private/defer > Jan 05 16:16:59 snape postfix/lmtp[126]: private/defer socket: wanted > attribute: protocol > Jan 05 16:16:59 snape postfix/lmtp[126]: input attribute name: protocol > Jan 05 16:16:59 snape postfix/lmtp[126]: input attribute value: > delivery_status_protocol > Jan 05 16:16:59 snape postfix/lmtp[126]: private/defer socket: wanted > attribute: (list terminator) > Jan 05 16:16:59 snape postfix/lmtp[126]: input attribute name: (end) > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr nrequest = 0 > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr flags = 0 > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr queue_id = C71B3D1262 > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr original_recipient = > [email protected] > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr recipient = [email protected] > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr offset = > 18446744073709551615 > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr dsn_orig_rcpt = > rfc822;[email protected] > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr notify_flags = 0 > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr status = 4.4.2 > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr diag_type = > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr diag_text = > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr mta_type = > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr mta_mname = > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr action = delayed > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr reason = conversation with > snape.rna.nl (http://snape.rna.nl)[private/lmtp] timed out while receiving > the initial server greeting > Jan 05 16:16:59 snape postfix/lmtp[126]: private/defer socket: wanted > attribute: status > Jan 05 16:16:59 snape postfix/lmtp[126]: input attribute name: status > Jan 05 16:16:59 snape postfix/lmtp[126]: input attribute value: 0 > Jan 05 16:16:59 snape postfix/lmtp[126]: private/defer socket: wanted > attribute: (list terminator) > Jan 05 16:16:59 snape postfix/lmtp[126]: input attribute name: (end) > Jan 05 16:16:59 snape postfix/lmtp[126]: C71B3D1262: to=<[email protected]>, > relay=snape.rna.nl (http://snape.rna.nl)[private/lmtp], delay=300, > delays=0.02/0/300/0, dsn=4.4.2, status=deferred (conversation with > snape.rna.nl (http://snape.rna.nl)[private/lmtp] timed out while receiving > the initial server greeting) > Jan 05 16:16:59 snape postfix/lmtp[126]: flush_add: site rna.nl > (http://rna.nl) id C71B3D1262 > Jan 05 16:16:59 snape postfix/lmtp[126]: match_list_match: rna.nl > (http://rna.nl): no match > Jan 05 16:16:59 snape postfix/lmtp[126]: flush_add: site rna.nl > (http://rna.nl) id C71B3D1262 status 4 > Jan 05 16:16:59 snape postfix/lmtp[126]: deliver_request_final: send: > "conversation with snape.rna.nl (http://snape.rna.nl)[private/lmtp] timed out > while receiving the initial server greeting" -1 > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr status = 4.4.2 > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr diag_type = > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr diag_text = > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr mta_type = > Jan 05 16:16:59 snape postfix/lmtp[127]: master_notify: status 1 > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr mta_mname = > Jan 05 16:16:59 snape postfix/lmtp[127]: connection closed > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr action = > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr reason = conversation with > snape.rna.nl (http://snape.rna.nl)[private/lmtp] timed out while receiving > the initial server greeting > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr status = 4294967295 > Jan 05 16:16:59 snape postfix/lmtp[126]: master_notify: status 1 > Jan 05 16:16:59 snape postfix/lmtp[126]: connection closed > > It seems dovecot doesn't react to whatever postfix is doing on the socket. > Another possibility is that the socket doesn't really work and dovecot never > gets a connection request. How can I debug this? > > Might I test if the socket is the problem by running lmtp on the dovecot side > on TCP on 127.0.0.1 and have postfix use that? Just to see if it works? If > so, how do I tell postfix to do that? In dovecot I have added the tcp: > > service lmtp { > inet_listener lmtp { > address = 127.0.0.1 > port = 24 > } > unix_listener /var/spool/postfix/private/lmtp { > mode = 0660 > user = postfix > group = postfix > } > } > service lmtp { > executable = lmtp -L > } > protocol lmtp { > info_log_path = /var/log/mail/dovecot-lmtp.log > } > > > Any other tips? > > > Gerben Wierda (LinkedIn (https://www.linkedin.com/in/gerbenwierda))
Maybe selinux or apparmor? Also, using TCP instead of unix socket is not a bad idea to try out. Aki
