LMTP-Process stays in RCPT TO state

Pascal Christen

5 Oct 2019 5 Oct '19

2:01 p.m.

We tried to update our Dovecot Director-Ring to 2.3 (latest version) and had one problem/bug. When we try to deliver an email from Exim to a receiving Dovecot (2.3 latest) via the LMTP-Proxy the LMTP process stays open forever and never closes. So after a few hours, we hit the LMPT-Process limit.

The problem only exists if the receiving Dovecot reports "Quota exceeded (mailbox for user is full)" back to the Exim. If this is the case the state on the LMPT process stays at "lmtp: [_IP_ RCPT TO] (lmtp) and never closes. The TCP-Connection to the Exim is then in CLOSE_WAIT state on the Proxy. On the receiving Dovecot we set the "lmtp_rcpt_check_quota=yes" option. For me, it sounds similar to this bug: https://dovecot.org/list/dovecot/2018-January/110697.html but without the SEGFAULT which makes it harder to debug it.

May you guys know why it doesn't change the state to IDLE or READY after reporting the quota issue or see something fishy in the commit above. If not I try to get a trace of the hanging process.

Greetings Pascal

Attachments:

attachment.html (text/html — 3.6 KB)

Show replies by date

Stephan Bosch

6 Oct 6 Oct

6:55 p.m.

On 05/10/2019 13:01, Pascal Christen via dovecot wrote:

...

Hi

We tried to update our Dovecot Director-Ring to 2.3 (latest version) and had one problem/bug. When we try to deliver an email from Exim to a receiving Dovecot (2.3 latest) via the LMTP-Proxy the LMTP process stays open forever and never closes. So after a few hours, we hit the LMPT-Process limit.

The problem only exists if the receiving Dovecot reports "Quota exceeded (mailbox for user is full)" back to the Exim. If this is the case the state on the LMPT process stays at "lmtp: [_IP_ RCPT TO] (lmtp) and never closes. The TCP-Connection to the Exim is then in CLOSE_WAIT state on the Proxy. On the receiving Dovecot we set the "lmtp_rcpt_check_quota=yes" option. For me, it sounds similar to this bug: https://dovecot.org/list/dovecot/2018-January/110697.html but without the SEGFAULT which makes it harder to debug it.

May you guys know why it doesn't change the state to IDLE or READY after reporting the quota issue or see something fishy in the commit above. If not I try to get a trace of the hanging process.

Greetings Pascal

So far, I haven't been able to reproduce anything weird at this end. Can you provide:

Output from `dovecot -n'
Protocol logs from the connections between Exim and Dovecot director/proxy and between Dovecot director/proxy and Dovecot backend (e.g. using ngrep when connections are plaintext or using the rawlog facility).
Dovecot debug logs produced with `log_debug=category:lmtp' for both director/proxy and backend

Regards,

Stephan.

Pascal Christen

6 Dec 6 Dec

12:08 p.m.

I tried to get some logs: https://pastebin.com/Z8xVzpzW

As you can see the process isn't shutdown and still in transaction as long dovecot is running. It destroyed the transaction when I stopped Dovecot. And this behavior only happens when the mailbox of user is full...

Any Ideas how to debug this correctly?

...

So far, I haven't been able to reproduce anything weird at this end. Can you provide:

Output from `dovecot -n'

Protocol logs from the connections between Exim and Dovecot director/proxy and between Dovecot director/proxy and Dovecot backend (e.g. using ngrep when connections are plaintext or using the rawlog facility).

Dovecot debug logs produced with `log_debug=category:lmtp' for both director/proxy and backend

Regards,

Stephan.

Stephan Bosch

10:26 p.m.

On 06/12/2019 11:08, Pascal Christen via dovecot wrote:

...

Hi

I tried to get some logs: https://pastebin.com/Z8xVzpzW

As you can see the process isn't shutdown and still in transaction as long dovecot is running. It destroyed the transaction when I stopped Dovecot. And this behavior only happens when the mailbox of user is full...

Any Ideas how to debug this correctly?

The provided logs look incomplete. The reception of the RCPT command by the server-side is not in the log, only the generation of the response. Also much of the client-side activity is not in the logs.

Also, a raw log of the TCP protocol exchange between Dovecot and Exim and also between proxy and backend can be useful. If the connections are plaintext you can use wireshark or - if not - you can use the Dovecot rawlog facilities.

Regards,

Stephan.

...

...
So far, I haven't been able to reproduce anything weird at this end. Can you provide:

Output from `dovecot -n'

Protocol logs from the connections between Exim and Dovecot director/proxy and between Dovecot director/proxy and Dovecot backend (e.g. using ngrep when connections are plaintext or using the rawlog facility).

Dovecot debug logs produced with `log_debug=category:lmtp' for both director/proxy and backend

Regards,

Stephan.

Pascal Christen

23 Jun 23 Jun

5:01 p.m.

Hi Stephan

We tried it again last week with the latest dovecot version and still having the same issue. The whole setup works perfectly fine with the latest version of dovecot 2.2

The problem only exists if the quota of the user is full, every other message gets delivered without a problem, and the lmtp process change back to READY state. But in this case, it stays in the "RCPT TO” forever. I’ve talked to ‘cmouse’ today on the IRC and he recommended continue here.

kdump and lmtp debug logs: https://pastebin.com/raw/MSVcj6qN https://pastebin.com/raw/MSVcj6qN & And from the backend I only have a tcpdump from another process but it's always the same behaviour: https://pastebin.com/tVj842Dq https://pastebin.com/tVj842Dq

If it doesn’t help, please let me know which logfiles exactly would help and would make the difference ;)

Greetings Pascal

...

On 6 Dec 2019, at 21:26, Stephan Bosch via dovecot dovecot@dovecot.org wrote:

On 06/12/2019 11:08, Pascal Christen via dovecot wrote:

...
Hi

I tried to get some logs: https://pastebin.com/Z8xVzpzW

As you can see the process isn't shutdown and still in transaction as long dovecot is running. It destroyed the transaction when I stopped Dovecot. And this behavior only happens when the mailbox of user is full...

Any Ideas how to debug this correctly?

The provided logs look incomplete. The reception of the RCPT command by the server-side is not in the log, only the generation of the response. Also much of the client-side activity is not in the logs.

Also, a raw log of the TCP protocol exchange between Dovecot and Exim and also between proxy and backend can be useful. If the connections are plaintext you can use wireshark or - if not - you can use the Dovecot rawlog facilities.

Regards,

Stephan.

...
...
So far, I haven't been able to reproduce anything weird at this end. Can you provide:

Output from `dovecot -n'

Protocol logs from the connections between Exim and Dovecot director/proxy and between Dovecot director/proxy and Dovecot backend (e.g. using ngrep when connections are plaintext or using the rawlog facility).

Dovecot debug logs produced with `log_debug=category:lmtp' for both director/proxy and backend

Regards,

Stephan.

Stephan Bosch

26 Jun 26 Jun

3:54 a.m.

On 23/06/2020 16:01, Pascal Christen wrote:

...

Hi Stephan

We tried it again last week with the latest dovecot version and still having the same issue. The whole setup works perfectly fine with the latest version of dovecot 2.2

The problem only exists if the quota of the user is full, every other message gets delivered without a problem, and the lmtp process change back to READY state. But in this case, it stays in the "RCPT TO” forever. I’ve talked to ‘cmouse’ today on the IRC and he recommended continue here.

kdump and lmtp debug logs: https://pastebin.com/raw/MSVcj6qN & And from the backend I only have a tcpdump from another process but it's always the same behaviour: https://pastebin.com/tVj842Dq

If it doesn’t help, please let me know which logfiles exactly would help and would make the difference ;)

Managed to reproduce it myself. We have a fix pending. Tracking this issue internally as DOP-1956.

Regards,

Stephan.

...

Greetings Pascal

...
On 6 Dec 2019, at 21:26, Stephan Bosch via dovecot mailto:dovecot@dovecot.org> wrote:

On 06/12/2019 11:08, Pascal Christen via dovecot wrote:

...
Hi

I tried to get some logs: https://pastebin.com/Z8xVzpzW

As you can see the process isn't shutdown and still in transaction as long dovecot is running. It destroyed the transaction when I stopped Dovecot. And this behavior only happens when the mailbox of user is full...

Any Ideas how to debug this correctly?

The provided logs look incomplete. The reception of the RCPT command by the server-side is not in the log, only the generation of the response. Also much of the client-side activity is not in the logs.

Also, a raw log of the TCP protocol exchange between Dovecot and Exim and also between proxy and backend can be useful. If the connections are plaintext you can use wireshark or - if not - you can use the Dovecot rawlog facilities.

Regards,

Stephan.

...
...
So far, I haven't been able to reproduce anything weird at this end. Can you provide:

Output from `dovecot -n'

Protocol logs from the connections between Exim and Dovecot director/proxy and between Dovecot director/proxy and Dovecot backend (e.g. using ngrep when connections are plaintext or using the rawlog facility).

Dovecot debug logs produced with `log_debug=category:lmtp' for both director/proxy and backend

Regards,

Stephan.

Pascal Christen

7 Sep 7 Sep

10:13 a.m.

Hi Stephan

Do you have some news about this issue? If you need any further logs or help please let me know. If you need someone who tests the patch - I'm in.

Greetings Pascal

...

On 26 Jun 2020, at 02:54, Stephan Bosch stephan@rename-it.nl wrote:

Managed to reproduce it myself. We have a fix pending. Tracking this issue internally as DOP-1956.

Regards,

Stephan.

1480

Age (days ago)

1818

Last active (days ago)

List overview

6 comments

2 participants

participants (2)

Pascal Christen
Stephan Bosch