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@rna.nl Jan 05 16:16:59 snape postfix/lmtp[126]: send attr recipient = sysbh@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@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@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/>
On 05/01/2023 18:38 EET Gerben Wierda <gerben.wierda@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@rna.nl Jan 05 16:16:59 snape postfix/lmtp[126]: send attr recipient = sysbh@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@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@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
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/lmtpOn 05/01/2023 19:17 EET dovecot@ptld.com wrote:
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
This is a rare case where one should look at
doveconf service/lmtp
to see what the default listeners are.
Aki
On 5 Jan 2023, at 18:17, dovecot@ptld.com wrote:
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
Ha, my mistake. As dovecot had not created the socket I assumed th elmtp socket was the one the new config had created, so I changed the config to use that one.
Now I only have to find out why dovecot doesn't create the /var/spool/postfix/private/dovecot-lmtp socket
The inet_listener was added to see if I could work around this.
G
On 5 Jan 2023, at 18:17, dovecot@ptld.com wrote:
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
I removed the tcp port for now.
/ # doveconf service/lmtp service lmtp { chroot = client_limit = 1 drop_priv_before_exec = no executable = lmtp extra_groups = $default_internal_group group = idle_kill = 0 privileged_group = process_limit = 0 process_min_avail = 0 protocol = lmtp service_count = 0 type = unix_listener /var/spool/postfix/private/dovecot-lmtp { group = mail mode = 0660 user = postfix } unix_listener lmtp { group = mode = 0666 user = } user = vsz_limit = 18446744073709551615 B }
postfix config:
mailbox_transport = lmtp:unix:private/dovecot-lmtp virtual_transport = lmtp:unix:private/dovecot-lmtp
I had confused postfix's own lmtp socket with dovecot's, which was originally named dovecot-lmtp but when it wasn't created I though my config was wrong.
What seems to happen is that /var/spool/postfix/private/dovecot-lmtp isn't created by dovecot at launch, but /var/spool/postfix/private/auth is
G
Boy do I feel stupid.
protocols was not set in the new version's dovecot.conf. And default it only contains imap. My old server had an override in dovecot.conf and I copied conf.d over but started with afresh dovecot.conf, so lmtp was missing.
G
On 5 Jan 2023, at 18:39, Gerben Wierda <gerben.wierda@rna.nl> wrote:
On 5 Jan 2023, at 18:17, dovecot@ptld.com <mailto:dovecot@ptld.com> wrote:
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
I removed the tcp port for now.
/ # doveconf service/lmtp service lmtp { chroot = client_limit = 1 drop_priv_before_exec = no executable = lmtp extra_groups = $default_internal_group group = idle_kill = 0 privileged_group = process_limit = 0 process_min_avail = 0 protocol = lmtp service_count = 0 type = unix_listener /var/spool/postfix/private/dovecot-lmtp { group = mail mode = 0660 user = postfix } unix_listener lmtp { group = mode = 0666 user = } user = vsz_limit = 18446744073709551615 B }
postfix config:
mailbox_transport = lmtp:unix:private/dovecot-lmtp virtual_transport = lmtp:unix:private/dovecot-lmtp
I had confused postfix's own lmtp socket with dovecot's, which was originally named dovecot-lmtp but when it wasn't created I though my config was wrong.
What seems to happen is that /var/spool/postfix/private/dovecot-lmtp isn't created by dovecot at launch, but /var/spool/postfix/private/auth is
G
Hmm: according to the documentation, the default is "imap pop3 lmtp"
But my installation (2.3.20, Alpine apk) for some reason only ran "imap" by default
G
On 5 Jan 2023, at 21:27, Gerben Wierda <gerben.wierda@rna.nl> wrote:
Boy do I feel stupid.
protocols was not set in the new version's dovecot.conf. And default it only contains imap. My old server had an override in dovecot.conf and I copied conf.d over but started with afresh dovecot.conf, so lmtp was missing.
G
On 5 Jan 2023, at 18:39, Gerben Wierda <gerben.wierda@rna.nl <mailto:gerben.wierda@rna.nl>> wrote:
On 5 Jan 2023, at 18:17, dovecot@ptld.com <mailto:dovecot@ptld.com> wrote:
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
I removed the tcp port for now.
/ # doveconf service/lmtp service lmtp { chroot = client_limit = 1 drop_priv_before_exec = no executable = lmtp extra_groups = $default_internal_group group = idle_kill = 0 privileged_group = process_limit = 0 process_min_avail = 0 protocol = lmtp service_count = 0 type = unix_listener /var/spool/postfix/private/dovecot-lmtp { group = mail mode = 0660 user = postfix } unix_listener lmtp { group = mode = 0666 user = } user = vsz_limit = 18446744073709551615 B }
postfix config:
mailbox_transport = lmtp:unix:private/dovecot-lmtp virtual_transport = lmtp:unix:private/dovecot-lmtp
I had confused postfix's own lmtp socket with dovecot's, which was originally named dovecot-lmtp but when it wasn't created I though my config was wrong.
What seems to happen is that /var/spool/postfix/private/dovecot-lmtp isn't created by dovecot at launch, but /var/spool/postfix/private/auth is
G
Gerben Wierda skrev den 2023-01-05 21:34:
Hmm: according to the documentation, the default is "imap pop3 lmtp"
But my installation (2.3.20, Alpine apk) for some reason only ran "imap" by default
and now you know there is no defaults ?
in case of not working a doveconf -n would be helpfull on maillists
if you use precompiled software blame them for there maybe changed defaults
participants (4)
-
Aki Tuomi
-
Benny Pedersen
-
dovecot＠ptld.com
-
Gerben Wierda