[Dovecot] 2.0beta4 doesn't respond to DONE after untagged FETCH during IDLE
Using K-9 Mail to IDLE on a test folder "MyIncTmp". When there is a flag change on a message in the folder, which generates an untagged FETCH, K-9 Mail responds with a DONE, but dovecot does not exit IDLE state (LOG 1). However, if a new message is delivered, generating an untagged EXISTS, K-9 Mail responds the same way, with a DONE, and dovecot does exit IDLE state. (LOG 2) You can also see in LOG 1 that the "OK Still here" continues to be sent, corroborating that dovecot is still in IDLE state.
I hope this information is helpful.
Sincerely, Dan.
LOG 1: failure to exit IDLE after untagged FETCH 04-16 08:25:48.911: VERBOSE/k9(10160): Sending IMAP command IDLE on connection conn1127686952 04-16 08:25:48.921: VERBOSE/k9(10160): conn1127686952>>> 13 IDLE 04-16 08:25:48.921: VERBOSE/k9(10160): Sent IMAP command IDLE with tag 13 for conn1127686952 04-16 08:25:49.191: VERBOSE/k9(10160): <<< #+# [idling] 04-16 08:25:49.201: VERBOSE/k9(10160): conn1127686952<<<#+# [idling] 04-16 08:25:49.201: VERBOSE/k9(10160): Got async response: #+# [idling] 04-16 08:25:49.201: DEBUG/k9(10160): Idling dantest:MyIncTmp/Thread-24/conn1127686952 04-16 08:25:49.201: DEBUG/k9(10160): Considering releasing WakeLock for Pushing 04-16 08:25:49.201: DEBUG/k9(10160): Releasing WakeLock for Pushing for thread Thread-24 04-16 08:25:54.491: VERBOSE/k9(10160): <<< #null# [16, FETCH, [FLAGS, [\Seen, \Recent]]] 04-16 08:25:54.491: VERBOSE/k9(10160): conn1127686952<<<#null# [16, FETCH, [FLAGS, [\Seen, \Recent]]] 04-16 08:25:54.491: VERBOSE/k9(10160): Got async response: #null# [16, FETCH, [FLAGS, [\Seen, \Recent]]] 04-16 08:25:54.501: DEBUG/k9(10160): Acquired WakeLock for Pushing for thread Thread-24 04-16 08:25:54.501: DEBUG/k9(10160): Got useful async untagged response: #null# [16, FETCH, [FLAGS, [\Seen, \Recent]]] for dantest:MyIncTmp/Thread-24/conn1127686952 04-16 08:25:54.501: VERBOSE/k9(10160): conn1127686952>>> DONE 04-16 08:26:54.571: DEBUG/k9(10160): Acquired WakeLock for Pushing for thread Thread-24 04-16 08:26:54.581: ERROR/k9(10160): Error 'Read timed out' 04-16 08:26:54.581: ERROR/k9(10160): java.net.SocketTimeoutException: Read timed out 04-16 08:27:00.141: VERBOSE/k9(10160): Sending IMAP command NOOP on connection conn1127686952 04-16 08:27:00.141: VERBOSE/k9(10160): conn1127686952>>> 14 NOOP 04-16 08:27:00.141: VERBOSE/k9(10160): Sent IMAP command NOOP with tag 14 for conn1127686952 04-16 08:27:26.651: VERBOSE/k9(10160): conn1127686952<<<#null# [OK, Still, here]
LOG 2: successful exit from IDLE after untagged EXISTS 04-16 08:28:35.271: INFO/k9(10160): About to IDLE for dantest:MyIncTmp/Thread-24/conn1126759992 04-16 08:28:35.271: VERBOSE/k9(10160): Sending IMAP command IDLE on connection conn1126759992 04-16 08:28:35.281: VERBOSE/k9(10160): conn1126759992>>> 10 IDLE 04-16 08:28:35.281: VERBOSE/k9(10160): Sent IMAP command IDLE with tag 10 for conn1126759992 04-16 08:28:35.531: VERBOSE/k9(10160): <<< #+# [idling] 04-16 08:28:35.531: VERBOSE/k9(10160): conn1126759992<<<#+# [idling] 04-16 08:28:35.531: VERBOSE/k9(10160): Got async response: #+# [idling] 04-16 08:28:35.531: DEBUG/k9(10160): Idling dantest:MyIncTmp/Thread-24/conn1126759992 04-16 08:28:35.531: DEBUG/k9(10160): Considering releasing WakeLock for Pushing 04-16 08:28:35.531: DEBUG/k9(10160): Releasing WakeLock for Pushing for thread Thread-24 04-16 08:28:51.621: VERBOSE/k9(10160): <<< #null# [18, EXISTS] 04-16 08:28:51.621: VERBOSE/k9(10160): conn1126759992<<<#null# [18, EXISTS] 04-16 08:28:51.621: VERBOSE/k9(10160): Got async response: #null# [18, EXISTS] 04-16 08:28:51.621: DEBUG/k9(10160): Acquired WakeLock for Pushing for thread Thread-24 04-16 08:28:51.631: DEBUG/k9(10160): Got useful async untagged response: #null# [18, EXISTS] for dantest:MyIncTmp/Thread-24/conn1126759992 04-16 08:28:51.631: VERBOSE/k9(10160): conn1126759992>>> DONE 04-16 08:28:51.631: VERBOSE/k9(10160): <<< #null# [1, RECENT] 04-16 08:28:51.631: VERBOSE/k9(10160): conn1126759992<<<#null# [1, RECENT] 04-16 08:28:51.631: VERBOSE/k9(10160): Got async response: #null# [1, RECENT] 04-16 08:28:51.901: VERBOSE/k9(10160): <<< #10# [OK, Idle, completed.] 04-16 08:28:51.901: VERBOSE/k9(10160): conn1126759992<<<#10# [OK, Idle, completed.] 04-16 08:28:51.901: VERBOSE/k9(10160): Got async response: #10# [OK, Idle, completed.]
Having applied Timo's patch to my "OK Still here" problem and removing mine, I am no longer having the problem with exiting IDLE after receiving an untagged FETCH. I'm not sure how the two are related, but for whatever reason, this problem isn't happening anymore. If it happens again, I'll raise the issue again. In the meantime, I have no reason to believe it a problem with 2.0beta4.
Sorry for the confusion.
Dan.
Daniel I. Applebaum wrote:
Using K-9 Mail to IDLE on a test folder "MyIncTmp". When there is a flag change on a message in the folder, which generates an untagged FETCH, K-9 Mail responds with a DONE, but dovecot does not exit IDLE state (LOG 1). However, if a new message is delivered, generating an untagged EXISTS, K-9 Mail responds the same way, with a DONE, and dovecot does exit IDLE state. (LOG 2) You can also see in LOG 1 that the "OK Still here" continues to be sent, corroborating that dovecot is still in IDLE state.
I hope this information is helpful.
Sincerely, Dan.
LOG 1: failure to exit IDLE after untagged FETCH 04-16 08:25:48.911: VERBOSE/k9(10160): Sending IMAP command IDLE on connection conn1127686952 04-16 08:25:48.921: VERBOSE/k9(10160): conn1127686952>>> 13 IDLE 04-16 08:25:48.921: VERBOSE/k9(10160): Sent IMAP command IDLE with tag 13 for conn1127686952 04-16 08:25:49.191: VERBOSE/k9(10160): <<< #+# [idling] 04-16 08:25:49.201: VERBOSE/k9(10160): conn1127686952<<<#+# [idling] 04-16 08:25:49.201: VERBOSE/k9(10160): Got async response: #+# [idling] 04-16 08:25:49.201: DEBUG/k9(10160): Idling dantest:MyIncTmp/Thread-24/conn1127686952 04-16 08:25:49.201: DEBUG/k9(10160): Considering releasing WakeLock for Pushing 04-16 08:25:49.201: DEBUG/k9(10160): Releasing WakeLock for Pushing for thread Thread-24 04-16 08:25:54.491: VERBOSE/k9(10160): <<< #null# [16, FETCH, [FLAGS, [\Seen, \Recent]]] 04-16 08:25:54.491: VERBOSE/k9(10160): conn1127686952<<<#null# [16, FETCH, [FLAGS, [\Seen, \Recent]]] 04-16 08:25:54.491: VERBOSE/k9(10160): Got async response: #null# [16, FETCH, [FLAGS, [\Seen, \Recent]]] 04-16 08:25:54.501: DEBUG/k9(10160): Acquired WakeLock for Pushing for thread Thread-24 04-16 08:25:54.501: DEBUG/k9(10160): Got useful async untagged response: #null# [16, FETCH, [FLAGS, [\Seen, \Recent]]] for dantest:MyIncTmp/Thread-24/conn1127686952 04-16 08:25:54.501: VERBOSE/k9(10160): conn1127686952>>> DONE 04-16 08:26:54.571: DEBUG/k9(10160): Acquired WakeLock for Pushing for thread Thread-24 04-16 08:26:54.581: ERROR/k9(10160): Error 'Read timed out' 04-16 08:26:54.581: ERROR/k9(10160): java.net.SocketTimeoutException: Read timed out 04-16 08:27:00.141: VERBOSE/k9(10160): Sending IMAP command NOOP on connection conn1127686952 04-16 08:27:00.141: VERBOSE/k9(10160): conn1127686952>>> 14 NOOP 04-16 08:27:00.141: VERBOSE/k9(10160): Sent IMAP command NOOP with tag 14 for conn1127686952 04-16 08:27:26.651: VERBOSE/k9(10160): conn1127686952<<<#null# [OK, Still, here]
LOG 2: successful exit from IDLE after untagged EXISTS 04-16 08:28:35.271: INFO/k9(10160): About to IDLE for dantest:MyIncTmp/Thread-24/conn1126759992 04-16 08:28:35.271: VERBOSE/k9(10160): Sending IMAP command IDLE on connection conn1126759992 04-16 08:28:35.281: VERBOSE/k9(10160): conn1126759992>>> 10 IDLE 04-16 08:28:35.281: VERBOSE/k9(10160): Sent IMAP command IDLE with tag 10 for conn1126759992 04-16 08:28:35.531: VERBOSE/k9(10160): <<< #+# [idling] 04-16 08:28:35.531: VERBOSE/k9(10160): conn1126759992<<<#+# [idling] 04-16 08:28:35.531: VERBOSE/k9(10160): Got async response: #+# [idling] 04-16 08:28:35.531: DEBUG/k9(10160): Idling dantest:MyIncTmp/Thread-24/conn1126759992 04-16 08:28:35.531: DEBUG/k9(10160): Considering releasing WakeLock for Pushing 04-16 08:28:35.531: DEBUG/k9(10160): Releasing WakeLock for Pushing for thread Thread-24 04-16 08:28:51.621: VERBOSE/k9(10160): <<< #null# [18, EXISTS] 04-16 08:28:51.621: VERBOSE/k9(10160): conn1126759992<<<#null# [18, EXISTS] 04-16 08:28:51.621: VERBOSE/k9(10160): Got async response: #null# [18, EXISTS] 04-16 08:28:51.621: DEBUG/k9(10160): Acquired WakeLock for Pushing for thread Thread-24 04-16 08:28:51.631: DEBUG/k9(10160): Got useful async untagged response: #null# [18, EXISTS] for dantest:MyIncTmp/Thread-24/conn1126759992 04-16 08:28:51.631: VERBOSE/k9(10160): conn1126759992>>> DONE 04-16 08:28:51.631: VERBOSE/k9(10160): <<< #null# [1, RECENT] 04-16 08:28:51.631: VERBOSE/k9(10160): conn1126759992<<<#null# [1, RECENT] 04-16 08:28:51.631: VERBOSE/k9(10160): Got async response: #null# [1, RECENT] 04-16 08:28:51.901: VERBOSE/k9(10160): <<< #10# [OK, Idle, completed.] 04-16 08:28:51.901: VERBOSE/k9(10160): conn1126759992<<<#10# [OK, Idle, completed.] 04-16 08:28:51.901: VERBOSE/k9(10160): Got async response: #10# [OK, Idle, completed.]
Having applied Timo's patch to my "OK Still here" problem and removing mine, I am no longer having the problem with exiting IDLE after receiving an untagged FETCH. I'm not sure how the two are related, but for whatever reason, this problem isn't happening anymore. If it happens again, I'll raise the issue again. In the meantime, I have no reason to believe it a problem with 2.0beta4.
Sorry for the confusion.
Dan.
Daniel I. Applebaum wrote:
Using K-9 Mail to IDLE on a test folder "MyIncTmp". When there is a flag change on a message in the folder, which generates an untagged FETCH, K-9 Mail responds with a DONE, but dovecot does not exit IDLE state (LOG 1). However, if a new message is delivered, generating an untagged EXISTS, K-9 Mail responds the same way, with a DONE, and dovecot does exit IDLE state. (LOG 2) You can also see in LOG 1 that the "OK Still here" continues to be sent, corroborating that dovecot is still in IDLE state.
I hope this information is helpful.
Sincerely, Dan.
LOG 1: failure to exit IDLE after untagged FETCH 04-16 08:25:48.911: VERBOSE/k9(10160): Sending IMAP command IDLE on connection conn1127686952 04-16 08:25:48.921: VERBOSE/k9(10160): conn1127686952>>> 13 IDLE 04-16 08:25:48.921: VERBOSE/k9(10160): Sent IMAP command IDLE with tag 13 for conn1127686952 04-16 08:25:49.191: VERBOSE/k9(10160): <<< #+# [idling] 04-16 08:25:49.201: VERBOSE/k9(10160): conn1127686952<<<#+# [idling] 04-16 08:25:49.201: VERBOSE/k9(10160): Got async response: #+# [idling] 04-16 08:25:49.201: DEBUG/k9(10160): Idling dantest:MyIncTmp/Thread-24/conn1127686952 04-16 08:25:49.201: DEBUG/k9(10160): Considering releasing WakeLock for Pushing 04-16 08:25:49.201: DEBUG/k9(10160): Releasing WakeLock for Pushing for thread Thread-24 04-16 08:25:54.491: VERBOSE/k9(10160): <<< #null# [16, FETCH, [FLAGS, [\Seen, \Recent]]] 04-16 08:25:54.491: VERBOSE/k9(10160): conn1127686952<<<#null# [16, FETCH, [FLAGS, [\Seen, \Recent]]] 04-16 08:25:54.491: VERBOSE/k9(10160): Got async response: #null# [16, FETCH, [FLAGS, [\Seen, \Recent]]] 04-16 08:25:54.501: DEBUG/k9(10160): Acquired WakeLock for Pushing for thread Thread-24 04-16 08:25:54.501: DEBUG/k9(10160): Got useful async untagged response: #null# [16, FETCH, [FLAGS, [\Seen, \Recent]]] for dantest:MyIncTmp/Thread-24/conn1127686952 04-16 08:25:54.501: VERBOSE/k9(10160): conn1127686952>>> DONE 04-16 08:26:54.571: DEBUG/k9(10160): Acquired WakeLock for Pushing for thread Thread-24 04-16 08:26:54.581: ERROR/k9(10160): Error 'Read timed out' 04-16 08:26:54.581: ERROR/k9(10160): java.net.SocketTimeoutException: Read timed out 04-16 08:27:00.141: VERBOSE/k9(10160): Sending IMAP command NOOP on connection conn1127686952 04-16 08:27:00.141: VERBOSE/k9(10160): conn1127686952>>> 14 NOOP 04-16 08:27:00.141: VERBOSE/k9(10160): Sent IMAP command NOOP with tag 14 for conn1127686952 04-16 08:27:26.651: VERBOSE/k9(10160): conn1127686952<<<#null# [OK, Still, here]
LOG 2: successful exit from IDLE after untagged EXISTS 04-16 08:28:35.271: INFO/k9(10160): About to IDLE for dantest:MyIncTmp/Thread-24/conn1126759992 04-16 08:28:35.271: VERBOSE/k9(10160): Sending IMAP command IDLE on connection conn1126759992 04-16 08:28:35.281: VERBOSE/k9(10160): conn1126759992>>> 10 IDLE 04-16 08:28:35.281: VERBOSE/k9(10160): Sent IMAP command IDLE with tag 10 for conn1126759992 04-16 08:28:35.531: VERBOSE/k9(10160): <<< #+# [idling] 04-16 08:28:35.531: VERBOSE/k9(10160): conn1126759992<<<#+# [idling] 04-16 08:28:35.531: VERBOSE/k9(10160): Got async response: #+# [idling] 04-16 08:28:35.531: DEBUG/k9(10160): Idling dantest:MyIncTmp/Thread-24/conn1126759992 04-16 08:28:35.531: DEBUG/k9(10160): Considering releasing WakeLock for Pushing 04-16 08:28:35.531: DEBUG/k9(10160): Releasing WakeLock for Pushing for thread Thread-24 04-16 08:28:51.621: VERBOSE/k9(10160): <<< #null# [18, EXISTS] 04-16 08:28:51.621: VERBOSE/k9(10160): conn1126759992<<<#null# [18, EXISTS] 04-16 08:28:51.621: VERBOSE/k9(10160): Got async response: #null# [18, EXISTS] 04-16 08:28:51.621: DEBUG/k9(10160): Acquired WakeLock for Pushing for thread Thread-24 04-16 08:28:51.631: DEBUG/k9(10160): Got useful async untagged response: #null# [18, EXISTS] for dantest:MyIncTmp/Thread-24/conn1126759992 04-16 08:28:51.631: VERBOSE/k9(10160): conn1126759992>>> DONE 04-16 08:28:51.631: VERBOSE/k9(10160): <<< #null# [1, RECENT] 04-16 08:28:51.631: VERBOSE/k9(10160): conn1126759992<<<#null# [1, RECENT] 04-16 08:28:51.631: VERBOSE/k9(10160): Got async response: #null# [1, RECENT] 04-16 08:28:51.901: VERBOSE/k9(10160): <<< #10# [OK, Idle, completed.] 04-16 08:28:51.901: VERBOSE/k9(10160): conn1126759992<<<#10# [OK, Idle, completed.] 04-16 08:28:51.901: VERBOSE/k9(10160): Got async response: #10# [OK, Idle, completed.]
participants (2)
-
Daniel I. Applebaum
-
Daniel I. Applebaum