LMTP-Process stays in RCPT TO state
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
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.
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?
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.
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.
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.
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 <dovecot@dovecot.org <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.
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.
participants (2)
-
Pascal Christen
-
Stephan Bosch