dovecot - Jun 2017 - 2nd try: Thunderbird "Empty Trash" causes inconsistent IMAP session state?

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 at xxx.org): Info: IMAP session state is
> inconsistent, please relogin. in=1369 out=222662
> May 29 00:12:05 imap(xxx at xxx.org): Info: IMAP session state is
> inconsistent, please relogin. in=204 out=1504
> May 29 00:40:29 imap(xxx at xxx.org): Info: IMAP session state is
> inconsistent, please relogin. in=1213 out=6414
> May 29 00:40:30 imap(xxx at 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 at xxx.org): Info: IMAP session state is
>> inconsistent, please relogin. in=1369 out=222662
>> May 29 00:12:05 imap(xxx at xxx.org): Info: IMAP session state is
>> inconsistent, please relogin. in=204 out=1504
>> May 29 00:40:29 imap(xxx at xxx.org): Info: IMAP session state is
>> inconsistent, please relogin. in=1213 out=6414
>> May 29 00:40:30 imap(xxx at 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
>>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: dovecot-info.log.tar.xz
Type: application/x-xz
Size: 2440 bytes
Desc: not available
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20170607/a12681d9/attachment-0001.xz>

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 at xxx.org): Info: IMAP session state is
>>> inconsistent, please relogin. in=1369 out=222662
>>> May 29 00:12:05 imap(xxx at xxx.org): Info: IMAP session state is
>>> inconsistent, please relogin. in=204 out=1504
>>> May 29 00:40:29 imap(xxx at xxx.org): Info: IMAP session state is
>>> inconsistent, please relogin. in=1213 out=6414
>>> May 29 00:40:30 imap(xxx at 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
>>>
>