Gerben Wierda
2023-Jan-05 16:38 UTC
postfix connects to dovecot lmtp socket, but nothing is delivered
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 = sysbh at
rna.nl
Jan 05 16:16:59 snape postfix/lmtp[126]: send attr recipient = sysbh at rna.nl
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;sysbh
at rna.nl
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[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=<sysbh at rna.nl>,
relay=snape.rna.nl[private/lmtp], delay=300, delays=0.02/0/300/0, dsn=4.4.2,
status=deferred (conversation with 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 id C71B3D1262
Jan 05 16:16:59 snape postfix/lmtp[126]: match_list_match: rna.nl: no match
Jan 05 16:16:59 snape postfix/lmtp[126]: flush_add: site rna.nl id C71B3D1262
status 4
Jan 05 16:16:59 snape postfix/lmtp[126]: deliver_request_final: send:
"conversation with 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[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>)
R&A IT Strategy <https://ea.rna.nl/> (main site)
Book: Chess and the Art of Enterprise?Architecture
<https://ea.rna.nl/the-book/>
Book: Mastering ArchiMate <https://ea.rna.nl/the-book-edition-iii/>
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<https://dovecot.org/pipermail/dovecot/attachments/20230105/613dd980/attachment-0001.htm>
Aki Tuomi
2023-Jan-05 17:16 UTC
postfix connects to dovecot lmtp socket, but nothing is delivered
> On 05/01/2023 18:38 EET Gerben Wierda <gerben.wierda at rna.nl> 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 = sysbh at rna.nl > Jan 05 16:16:59 snape postfix/lmtp[126]: send attr recipient = sysbh at rna.nl > 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;sysbh at rna.nl > 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=<sysbh at rna.nl>, 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
dovecot at ptld.com
2023-Jan-05 17:17 UTC
postfix connects to dovecot lmtp socket, but nothing is delivered
> 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 > }Looks like you are activating both a socket and a port. Im not sure what dovecot does, does it bind to both or does it pick one and ignore the other. You only need to use one or the other. And what does your postfix side look like? Where is postfix trying to connect? To the socket or the port? For using a socket postfix would look something like: virtual_transport = lmtp:unix:private/lmtp