Thunderbird "Empty Trash" causes inconsistent IMAP session state?
All,
having successfully compiled and set up Dovecot 2.2.29.1 on my Thecus NAS as a newbie without any further hassle, and already imported an external mail archive of ~15 GB into a lz4-compressed mdbox (with impressive performance on the old Intel Atom CPU!), I stumbled into a minor, but reproducible issue that might well be already known, but I haven't managed to find any pointers through Google search:
When I *manually empty the Trash folder from Thunderbird* (52.1.1, regardless of Windows or Linux client) by right-clicking on a non-empty Trash folder and then selecting "Empty trash", Dovecot produces the following log message, and I need to restart Thunderbird client in order to properly refresh its folder status:
May 30 23:42:04 imap(xxx@xxx.org): Info: *IMAP session state is inconsistent, please relogin.* in=405 out=3114
Is this behaviour and message intended, or did I indeed run into a bug here?
Many thanks & best regards Andreas
Resending - any ideas why I might get "IMAP session state is inconsistent" whenever emtyping the trash in Thunderbird?
Thanks, Andreas
Am 31.05.2017 um 00:02 schrieb awl1:
All,
having successfully compiled and set up Dovecot 2.2.29.1 on my Thecus NAS as a newbie without any further hassle, and already imported an external mail archive of ~15 GB into a lz4-compressed mdbox (with impressive performance on the old Intel Atom CPU!), I stumbled into a minor, but reproducible issue that might well be already known, but I haven't managed to find any pointers through Google search:
When I *manually empty the Trash folder from Thunderbird* (52.1.1, regardless of Windows or Linux client) by right-clicking on a non-empty Trash folder and then selecting "Empty trash", Dovecot produces the following log message, and I need to restart Thunderbird client in order to properly refresh its folder status:
May 30 23:42:04 imap(xxx@xxx.org): Info: *IMAP session state is inconsistent, please relogin.* in=405 out=3114
Is this behaviour and message intended, or did I indeed run into a bug here?
Many thanks & best regards Andreas
On 05.06.2017 11:02, awl1 wrote:
Resending - any ideas why I might get "IMAP session state is inconsistent" whenever emtyping the trash in Thunderbird?
Thanks, Andreas
Am 31.05.2017 um 00:02 schrieb awl1:
All,
having successfully compiled and set up Dovecot 2.2.29.1 on my Thecus NAS as a newbie without any further hassle, and already imported an external mail archive of ~15 GB into a lz4-compressed mdbox (with impressive performance on the old Intel Atom CPU!), I stumbled into a minor, but reproducible issue that might well be already known, but I haven't managed to find any pointers through Google search:
When I *manually empty the Trash folder from Thunderbird* (52.1.1, regardless of Windows or Linux client) by right-clicking on a non-empty Trash folder and then selecting "Empty trash", Dovecot produces the following log message, and I need to restart Thunderbird client in order to properly refresh its folder status:
May 30 23:42:04 imap(xxx@xxx.org): Info: *IMAP session state is inconsistent, please relogin.* in=405 out=3114
Is this behaviour and message intended, or did I indeed run into a bug here?
Many thanks & best regards Andreas Hello
Can you please provide the output of doveconf -n? The version of your lz4 library could be useful also, if it is not the distributions default. ref. https://dovecot.org/bugreport.html
br, Teemu
Hello Teemu,
the version of my lz4 library is the most recent lz4-1.7.5, and "dovecot -n" output is as follows:
# 2.2.30.1 (eebd877): /raid/data/module/Dovecot/sys/etc/dovecot/dovecot.conf # OS: Linux 2.6.33N7700 i686 auth_debug = yes auth_debug_passwords = yes auth_verbose = yes auth_verbose_passwords = sha1 info_log_path = /raid/data/module/Dovecot/sys/var/log/dovecot-info.log log_path = /raid/data/module/Dovecot/sys/var/log/dovecot.log mail_debug = yes mail_fsync = never mail_full_filesystem_access = yes mail_location = mdbox:~/mdbox mail_plugins = " fts fts_lucene zlib" mdbox_rotate_size = 32 M passdb { args = /raid/data/module/Dovecot/sys/etc/dovecot/imap.passwd driver = passwd-file } plugin { fts = lucene fts_lucene = whitespace_chars=@. zlib_save = lz4 zlib_save_level = 6 } protocols = imap ssl = required ssl_cert =
Many thanks for looking into this & best regards Andreas
Am 05.06.2017 um 12:34 schrieb Teemu Huovila:
Hello
Can you please provide the output of doveconf -n? The version of your lz4 library could be useful also, if it is not the distributions default. ref. https://dovecot.org/bugreport.html
br, Teemu
On 05.06.2017 14:06, awl1 wrote:
Hello Teemu,
the version of my lz4 library is the most recent lz4-1.7.5, and "dovecot -n" output is as follows:
Can you provide full logs for the imap session? Basically you can do grep session-id logfile.
Aki
Hello Aki,
sorry, but I am still a newbie to Dovecot:
Hmm - I don't seem to have IMAP session IDs in every line of my dovecot-info.log. that could be used to extract IMAP session-related info.
I assume that I have to set up logging in a specific way to add and then find the IMAP session ID in my logs. Could you please point me to the docs about how to configure this for the future?
What I can offer now from my old logs is to provide log file excerpts from some minutes/seconds before the "Empty Trash" action caused the "inconsistent IMPA state" message until shortly after - would that help as well!?
Best regards & apologies Andreas
Am 05.06.2017 um 13:13 schrieb Aki Tuomi:
Can you provide full logs for the imap session? Basically you can do grep session-id logfile.
Aki
Yes, that would help too.
Aki
On 05.06.2017 14:35, awl1 wrote:
Hello Aki,
sorry, but I am still a newbie to Dovecot:
Hmm - I don't seem to have IMAP session IDs in every line of my dovecot-info.log. that could be used to extract IMAP session-related info.
I assume that I have to set up logging in a specific way to add and then find the IMAP session ID in my logs. Could you please point me to the docs about how to configure this for the future?
What I can offer now from my old logs is to provide log file excerpts from some minutes/seconds before the "Empty Trash" action caused the "inconsistent IMPA state" message until shortly after - would that help as well!?
Best regards & apologies Andreas
Am 05.06.2017 um 13:13 schrieb Aki Tuomi:
Can you provide full logs for the imap session? Basically you can do grep session-id logfile.
Aki
Hello again,
here you are (log excerpt from May 29 00:06:02 until May 29 01:17:49):
May 29 00:12:05 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=1369 out=222662 May 29 00:12:05 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=204 out=1504 May 29 00:40:29 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=1213 out=6414 May 29 00:40:30 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=227 out=1430
I'd still be interested anyway in what I'd have t do in order to add the session ID to my future log files. Is this documented anywhere?
https://wiki.dovecot.org/Variables does not help enough with regards to how to apply it to logfile settings in dovecot.conf... :-(
Thanks again & best regards Andreas
Am 05.06.2017 um 13:50 schrieb Aki Tuomi:
Yes, that would help too.
Aki
On 05.06.2017 14:35, awl1 wrote:
Hello Aki,
sorry, but I am still a newbie to Dovecot:
Hmm - I don't seem to have IMAP session IDs in every line of my dovecot-info.log. that could be used to extract IMAP session-related info.
I assume that I have to set up logging in a specific way to add and then find the IMAP session ID in my logs. Could you please point me to the docs about how to configure this for the future?
What I can offer now from my old logs is to provide log file excerpts from some minutes/seconds before the "Empty Trash" action caused the "inconsistent IMPA state" message until shortly after - would that help as well!?
Best regards & apologies Andreas
Am 05.06.2017 um 13:13 schrieb Aki Tuomi:
Can you provide full logs for the imap session? Basically you can do grep session-id logfile.
Aki
Am 05.06.2017 um 14:13 schrieb awl1:
Hello again,
here you are (log excerpt from May 29 00:06:02 until May 29 01:17:49):
May 29 00:12:05 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=1369 out=222662 May 29 00:12:05 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=204 out=1504 May 29 00:40:29 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=1213 out=6414 May 29 00:40:30 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=227 out=1430
I'd still be interested anyway in what I'd have t do in order to add the session ID to my future log files. Is this documented anywhere?
https://wiki.dovecot.org/Variables does not help enough with regards to how to apply it to logfile settings in dovecot.conf... :-(
Something like this should log the session.
/etc/dovecot/conf.d/10-logging.conf: mail_log_prefix = "%s(%u,%{session}): "
-- Alex JOST
Thank you, Alex - works like a charm! :-)
The wiki does not seem to currently document the "mail_log_prefix" setting anywhere (the only Google search hits are from the alias and tutorials from other sources), so maybe the Devecot team would want to add this to a wiki page...
Thanks & BR Andreas
Am 05.06.2017 um 16:02 schrieb Alex JOST:
Something like this should log the session.
/etc/dovecot/conf.d/10-logging.conf: mail_log_prefix = "%s(%u,%{session}): "
That log didn't do much help, can you try enabling mail_debug=yes for a moment and see if it gives any more insight?
Aki
On 05.06.2017 15:13, awl1 wrote:
Hello again,
here you are (log excerpt from May 29 00:06:02 until May 29 01:17:49):
May 29 00:12:05 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=1369 out=222662 May 29 00:12:05 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=204 out=1504 May 29 00:40:29 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=1213 out=6414 May 29 00:40:30 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=227 out=1430
I'd still be interested anyway in what I'd have t do in order to add the session ID to my future log files. Is this documented anywhere?
https://wiki.dovecot.org/Variables does not help enough with regards to how to apply it to logfile settings in dovecot.conf... :-(
Thanks again & best regards Andreas
Am 05.06.2017 um 13:50 schrieb Aki Tuomi:
Yes, that would help too.
Aki
On 05.06.2017 14:35, awl1 wrote:
Hello Aki,
sorry, but I am still a newbie to Dovecot:
Hmm - I don't seem to have IMAP session IDs in every line of my dovecot-info.log. that could be used to extract IMAP session-related info.
I assume that I have to set up logging in a specific way to add and then find the IMAP session ID in my logs. Could you please point me to the docs about how to configure this for the future?
What I can offer now from my old logs is to provide log file excerpts from some minutes/seconds before the "Empty Trash" action caused the "inconsistent IMPA state" message until shortly after - would that help as well!?
Best regards & apologies Andreas
Am 05.06.2017 um 13:13 schrieb Aki Tuomi:
Can you provide full logs for the imap session? Basically you can do grep session-id logfile.
Aki
Hello Aki,
please find attached the debug log from another incident, this time with IMAP session ID (<yH0lKWRRpNHAqOh5>) in the logs and with "mail_debug=yes" in dovecot.conf.
I can consistently reproduce the "inconsistent state" error message by the following steps from the most recent Thunderbird version (52.1.1, on 64-bit Linux Ubuntu 16.04.02 LTS):
- copy a folder (in the sample log: named "Dilbert") with several mail messages from my mail provider remote IMAP account into my local Dovecot archive account
- delete this folder from the Dovecot archive account into the Trash folder
- empty the Trash folder from Thunderbird
- immediately, the message about "inconsistent IMAP session state" appears in the dovecot-info.log
In case the log even with mail_debug=yes again is no real help (which I fear to be the case, as to me, the log looks very similar to the previous log), would you be able to insert some additional debug log statements into Dovecot code at some appropriate places, and let me try again with such an additional debug version?
Many thanks & best regards Andreas
Am 07.06.2017 um 07:57 schrieb Aki Tuomi:
That log didn't do much help, can you try enabling mail_debug=yes for a moment and see if it gives any more insight? Aki On 05.06.2017 15:13, awl1 wrote:
Hello again,
here you are (log excerpt from May 29 00:06:02 until May 29 01:17:49):
May 29 00:12:05 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=1369 out=222662 May 29 00:12:05 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=204 out=1504 May 29 00:40:29 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=1213 out=6414 May 29 00:40:30 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=227 out=1430
I'd still be interested anyway in what I'd have t do in order to add the session ID to my future log files. Is this documented anywhere?
https://wiki.dovecot.org/Variables does not help enough with regards to how to apply it to logfile settings in dovecot.conf... :-(
Thanks again & best regards Andreas
Am 05.06.2017 um 13:50 schrieb Aki Tuomi:
Yes, that would help too.
Aki
On 05.06.2017 14:35, awl1 wrote:
Hello Aki,
sorry, but I am still a newbie to Dovecot:
Hmm - I don't seem to have IMAP session IDs in every line of my dovecot-info.log. that could be used to extract IMAP session-related info.
I assume that I have to set up logging in a specific way to add and then find the IMAP session ID in my logs. Could you please point me to the docs about how to configure this for the future?
What I can offer now from my old logs is to provide log file excerpts from some minutes/seconds before the "Empty Trash" action caused the "inconsistent IMPA state" message until shortly after - would that help as well!?
Best regards & apologies Andreas
Am 05.06.2017 um 13:13 schrieb Aki Tuomi:
Can you provide full logs for the imap session? Basically you can do grep session-id logfile.
Aki
Sorry, just one more thing I've just noticed now from looking at the IMAP session IDs:
Dovecot seems to map the steps as outlined below to four different IMAP session IDs all related to the exact same Thunderbird client instance:
- <yH0lKWRRpNHAqOh5> session for the folder copy of folder "Dilbert" with 317 messages
- <VcMlLWRRqNHAqOh5> session for the deletion of folder "Dilbert" into Trash
- </qSFLWRRqtHAqOh5> session from which the empty Trash seems to be run and which ends up in "inconsistent state"
- <HHmhLWRRrNHAqOh5> another session seemingly accessing the Trash folder for which I am unable to determine its exact purpose
Maybe the issue is that the fourth session should not even exist or at least has a race condition with the third one?
Thanks again & best regards Andreas
Am 07.06.2017 um 22:19 schrieb awl1:
Hello Aki,
please find attached the debug log from another incident, this time with IMAP session ID (<yH0lKWRRpNHAqOh5>) in the logs and with "mail_debug=yes" in dovecot.conf.
I can consistently reproduce the "inconsistent state" error message by the following steps from the most recent Thunderbird version (52.1.1, on 64-bit Linux Ubuntu 16.04.02 LTS):
- copy a folder (in the sample log: named "Dilbert") with several mail messages from my mail provider remote IMAP account into my local Dovecot archive account
- delete this folder from the Dovecot archive account into the Trash folder
- empty the Trash folder from Thunderbird
- immediately, the message about "inconsistent IMAP session state" appears in the dovecot-info.log
In case the log even with mail_debug=yes again is no real help (which I fear to be the case, as to me, the log looks very similar to the previous log), would you be able to insert some additional debug log statements into Dovecot code at some appropriate places, and let me try again with such an additional debug version?
Many thanks & best regards Andreas
Am 07.06.2017 um 07:57 schrieb Aki Tuomi:
That log didn't do much help, can you try enabling mail_debug=yes for a moment and see if it gives any more insight? Aki On 05.06.2017 15:13, awl1 wrote:
Hello again,
here you are (log excerpt from May 29 00:06:02 until May 29 01:17:49):
May 29 00:12:05 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=1369 out=222662 May 29 00:12:05 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=204 out=1504 May 29 00:40:29 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=1213 out=6414 May 29 00:40:30 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=227 out=1430
I'd still be interested anyway in what I'd have t do in order to add the session ID to my future log files. Is this documented anywhere?
https://wiki.dovecot.org/Variables does not help enough with regards to how to apply it to logfile settings in dovecot.conf... :-(
Thanks again & best regards Andreas
Am 05.06.2017 um 13:50 schrieb Aki Tuomi:
Yes, that would help too.
Aki
On 05.06.2017 14:35, awl1 wrote:
Hello Aki,
sorry, but I am still a newbie to Dovecot:
Hmm - I don't seem to have IMAP session IDs in every line of my dovecot-info.log. that could be used to extract IMAP session-related info.
I assume that I have to set up logging in a specific way to add and then find the IMAP session ID in my logs. Could you please point me to the docs about how to configure this for the future?
What I can offer now from my old logs is to provide log file excerpts from some minutes/seconds before the "Empty Trash" action caused the "inconsistent IMPA state" message until shortly after - would that help as well!?
Best regards & apologies Andreas
Am 05.06.2017 um 13:13 schrieb Aki Tuomi:
Can you provide full logs for the imap session? Basically you can do grep session-id logfile.
Aki
Hello Aki,
do you have any news on this issue in the meantime?
Thanks & best regards Andreas
Am 07.06.2017 um 22:30 schrieb awl1:
Sorry, just one more thing I've just noticed now from looking at the IMAP session IDs:
Dovecot seems to map the steps as outlined below to four different IMAP session IDs all related to the exact same Thunderbird client instance:
- <yH0lKWRRpNHAqOh5> session for the folder copy of folder "Dilbert" with 317 messages
- <VcMlLWRRqNHAqOh5> session for the deletion of folder "Dilbert" into Trash
- </qSFLWRRqtHAqOh5> session from which the empty Trash seems to be run and which ends up in "inconsistent state"
- <HHmhLWRRrNHAqOh5> another session seemingly accessing the Trash folder for which I am unable to determine its exact purpose
Maybe the issue is that the fourth session should not even exist or at least has a race condition with the third one?
Thanks again & best regards Andreas
Am 07.06.2017 um 22:19 schrieb awl1:
Hello Aki,
please find attached the debug log from another incident, this time with IMAP session ID (<yH0lKWRRpNHAqOh5>) in the logs and with "mail_debug=yes" in dovecot.conf.
I can consistently reproduce the "inconsistent state" error message by the following steps from the most recent Thunderbird version (52.1.1, on 64-bit Linux Ubuntu 16.04.02 LTS):
- copy a folder (in the sample log: named "Dilbert") with several mail messages from my mail provider remote IMAP account into my local Dovecot archive account
- delete this folder from the Dovecot archive account into the Trash folder
- empty the Trash folder from Thunderbird
- immediately, the message about "inconsistent IMAP session state" appears in the dovecot-info.log
In case the log even with mail_debug=yes again is no real help (which I fear to be the case, as to me, the log looks very similar to the previous log), would you be able to insert some additional debug log statements into Dovecot code at some appropriate places, and let me try again with such an additional debug version?
Many thanks & best regards Andreas
Am 07.06.2017 um 07:57 schrieb Aki Tuomi:
That log didn't do much help, can you try enabling mail_debug=yes for a moment and see if it gives any more insight? Aki On 05.06.2017 15:13, awl1 wrote:
Hello again,
here you are (log excerpt from May 29 00:06:02 until May 29 01:17:49):
May 29 00:12:05 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=1369 out=222662 May 29 00:12:05 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=204 out=1504 May 29 00:40:29 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=1213 out=6414 May 29 00:40:30 imap(xxx@xxx.org): Info: IMAP session state is inconsistent, please relogin. in=227 out=1430
I'd still be interested anyway in what I'd have t do in order to add the session ID to my future log files. Is this documented anywhere?
https://wiki.dovecot.org/Variables does not help enough with regards to how to apply it to logfile settings in dovecot.conf... :-(
Thanks again & best regards Andreas
Am 05.06.2017 um 13:50 schrieb Aki Tuomi:
Yes, that would help too.
Aki
On 05.06.2017 14:35, awl1 wrote:
Hello Aki,
sorry, but I am still a newbie to Dovecot:
Hmm - I don't seem to have IMAP session IDs in every line of my dovecot-info.log. that could be used to extract IMAP session-related info.
I assume that I have to set up logging in a specific way to add and then find the IMAP session ID in my logs. Could you please point me to the docs about how to configure this for the future?
What I can offer now from my old logs is to provide log file excerpts from some minutes/seconds before the "Empty Trash" action caused the "inconsistent IMPA state" message until shortly after - would that help as well!?
Best regards & apologies Andreas
Am 05.06.2017 um 13:13 schrieb Aki Tuomi: > Can you provide full logs for the imap session? Basically you > can do > grep session-id logfile. > > Aki
participants (4)
-
Aki Tuomi
-
Alex JOST
-
awl1
-
Teemu Huovila