answered
2017-11-29 15:19:39 +0300
After investigation, I'm putting here my thoughts even if I was not able to find the root issue. It may help discussing. It will take time for me to write everything down, so I'll update this answer in the coming days.
Proper initialisation
Following logs
One can see the connexion establishing.
[23263] nov. 30 13:47:37 [Debug] Messaging : IMAP : Secure connection established
[23263] nov. 30 13:47:37 [Debug] IMAP : "3" RECV: * OK IMAP4 ready
From imapclient.cpp#862, the transition after initialisation will ask the server for capabilities.
[23263] nov. 30 13:47:37 [Debug] IMAP : "3" SEND a001 CAPABILITY
[23263] nov. 30 13:47:38 [Debug] IMAP : "3" RECV: * CAPABILITY IMAP4REV1 X-NETSCAPE LOGIN-REFERRALS AUTH=PLAIN
[23263] nov. 30 13:47:38 [Debug] IMAP : "3" RECV: a001 OK completed
Then will authenticate with the given authentification, here AUTH=PLAIN.
[23263] nov. 30 13:47:38 [Debug] IMAP : "3" SEND a004 AUTHENTICATE PLAIN
[23263] nov. 30 13:47:38 [Debug] IMAP : "3" RECV: +
[23263] nov. 30 13:47:38 [Debug] IMAP : "3" SEND SEND: <login hidden="">
[23263] nov. 30 13:47:38 [Debug] IMAP : "3" RECV: a004 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE NOTIFY SPECIAL-USE QUOTA] Logged in
</login>
From the login response, one can see that IDLE is possible, so from imapclient.cpp#906, the monitor() function is called and starting an idle session for every folder (here only inbox). This is visible with the IMAP : "I:1" tag, meaning idle session 1.
[23263] nov. 30 13:47:38 [Debug] IMAP : "I:1" About to open connection "hidden login" "server address"
[23263] nov. 30 13:47:38 [Debug] IMAP : "I:1" Setting read buffer size to 10240
[23263] nov. 30 13:47:38 [Debug] Messaging : IMAP : connection established
[23263] nov. 30 13:47:39 [Debug] Messaging : Push email established for account 44 "hidden login"
[23263] nov. 30 13:47:39 [Debug] Messaging : Action completed 99913824206849 result success
Then the main connexion is finishing its process.
[23263] nov. 30 13:47:38 [Debug] IMAP : "3" SEND a005 ENABLE QRESYNC CONDSTORE
[23263] nov. 30 13:47:38 [Debug] IMAP : "3" RECV: * ENABLED QRESYNC CONDSTORE
[23263] nov. 30 13:47:38 [Debug] IMAP : "3" RECV: a005 OK Enabled (0.000 + 0.000 secs).
[23263] nov. 30 13:47:38 [Debug] IMAP : "3" SEND a006 SELECT INBOX (QRESYNC (1457523307 10201 6427:6465))
[23263] nov. 30 13:47:38 [Debug] IMAP : "3" RECV: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft $Forwarded $MDNSent)
[23263] nov. 30 13:47:38 [Debug] IMAP : "3" RECV: * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft $Forwarded $MDNSent \*)] Flags permitted.
[23263] nov. 30 13:47:38 [Debug] IMAP : "3" RECV: * 39 EXISTS
[23263] nov. 30 13:47:38 [Debug] IMAP : "3" RECV: * 0 RECENT
[23263] nov. 30 13:47:38 [Debug] IMAP : "3" RECV: * OK [UIDVALIDITY 1457523307] UIDs valid
[23263] nov. 30 13:47:38 [Debug] IMAP : "3" RECV: * OK [UIDNEXT 6466] Predicted next UID
[23263] nov. 30 13:47:38 [Debug] IMAP : "3" RECV: * OK [HIGHESTMODSEQ 10201] Highest
[23263] nov. 30 13:47:38 [Debug] IMAP : "3" RECV: a006 OK [READ-WRITE] Select completed (0.000 + 0.000 secs).
[23263] nov. 30 13:47:39 [Debug] IMAP : "3" SEND a007 LOGOUT
[23263] nov. 30 13:47:39 [Debug] IMAP : "3" RECV: * BYE Logging out
[23263] nov. 30 13:47:39 [Debug] IMAP : "3" RECV: a007 OK Logout completed (0.000 + 0.000 secs).
One can follow the establishing of the "I:1" session with more or less the same procedure. The important command is the a0004 one at the end.
[23263] nov. 30 13:47:39 [Debug] Messaging : IMAP : Secure connection established
[23263] nov. 30 13:47:39 [Debug] IMAP : "I:1" RECV: * OK IMAP4 ready
[23263] nov. 30 13:47:39 [Debug] IMAP : "I:1" SEND a001 CAPABILITY
[23263] nov. 30 13:47:39 [Debug] IMAP : "I:1" RECV: * CAPABILITY IMAP4REV1 X-NETSCAPE LOGIN-REFERRALS AUTH=PLAIN
[23263] nov. 30 13:47:39 [Debug] IMAP : "I:1" RECV: a001 OK completed
[23263] nov. 30 13:47:39 [Debug] IMAP : "I:1" SEND a002 AUTHENTICATE PLAIN
[23263] nov. 30 13:47:39 [Debug] IMAP : "I:1" RECV: +
[23263] nov. 30 13:47:39 [Debug] IMAP : "I:1" SEND SEND: <login hidden="">
[23263] nov. 30 13:47:39 [Debug] IMAP : "I:1" RECV: a002 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS BINARY MOVE NOTIFY SPECIAL-USE QUOTA] Logged in
[23263] nov. 30 13:47:39 [Debug] IMAP : "I:1" SEND a003 SELECT INBOX (CONDSTORE)
[23263] nov. 30 13:47:39 [Debug] IMAP : "I:1" RECV: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft $Forwarded $MDNSent)
[23263] nov. 30 13:47:39 [Debug] IMAP : "I:1" RECV: * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft $Forwarded $MDNSent \*)] Flags permitted.
[23263] nov. 30 13:47:39 [Debug] IMAP : "I:1" RECV: * 39 EXISTS
[23263] nov. 30 13:47:39 [Debug] IMAP : "I:1" RECV: * 0 RECENT
[23263] nov. 30 13:47:39 [Debug] IMAP : "I:1" RECV: * OK [UIDVALIDITY 1457523307] UIDs valid
[23263] nov. 30 13:47:39 [Debug] IMAP : "I:1" RECV: * OK [UIDNEXT 6466] Predicted next UID
[23263] nov. 30 13:47:39 [Debug] IMAP : "I:1" RECV: * OK [HIGHESTMODSEQ 10201] Highest
[23263] nov. 30 13:47:39 [Debug] IMAP : "I:1" RECV: a003 OK [READ-WRITE] Select completed (0.000 + 0.000 secs).
[23263] nov. 30 13:47:39 [Debug] IMAP : "I:1" SEND a004 IDLE
[23263] nov. 30 13:47:39 [Debug] IMAP : "I:1" RECV: + idling
[23263] nov. 30 13:47:39 [Debug] IMAP : "I:1" IDLE: Idle connection established.
</login>
After this the idle connexion is established and working. Mail is synced on the fly. Every two minutes the server is sending a still alive message.
[23263] nov. 30 13:47:40 [Debug] IMAP : "I:1" RECV: * OK Still here
[23263] nov. 30 13:49:41 [Debug] IMAP : "I:1" RECV: * OK Still here
[23263] nov. 30 13:51:41 [Debug] IMAP : "I:1" RECV: * OK Still here
Code path when establishing an idle connexion
The entry point is in ImapClient::monitor() from imapclient.cpp#1956. There an IdleProtocol object is created for every folder to be used in idle mode. This new IdleProtocol object (inheriting from ImapProtocol) is labelled with "I:x" where x is increased during the life time of the messageserver.
Then this protocol object is used as a normal protocol object, calling open(), which will trigger a set of actions (see idleCommandTransition()), like for the normal (non idle) protocol. After all checks, the idle command is sent and on success, the code will run IdleProtocol::idleContinuation() from imapclient.cpp#402.
This will start a timer (_idleTimer) to send DONE after 29 minutes, to ensure server modifications. When this timer triggers, the DONE command is send back. On completion, the continuation is called from line #510 whih will trigger a new idle command and so on.
To protect against unresponsive server while sending the DONE command, a timer is launched that last for idleRetryDelay as defined in the client object.
Loosing network and reestablishing the idle connexion
Loosing the connection
If there is a network disconnection (like 3G bad signal), something like this appears in the logs:
[23263] nov. 30 13:53:43 [Debug] Messaging : IDLE session error: QNetworkSession::Connecting
It corresponds to a callback on network issue in imapservice.cpp#1975. This imap service object is somehow on top of the imap client that has been discussed before. Than, the idle status is set to false in this service object and setPersistentConnectionStatus is called, resulting on the account status been modified. This modification is then caught by the imap client in a callback on account settings, see the logs:
[23263] nov. 30 13:53:43 [Debug] IMAP : void ImapClient::onAccountsUpdated(const QMailAccountIdList&) "login"
[23263] nov. 30 13:53:43 [Debug] Messaging : HasPersistentConnection for 44 changed to false
Another callback of the imap service object is also called: onOnlineStateChanged resulting in calling the onSessionError callback with a invalid configuration error, as seen in the logs:
[23263] nov. 30 13:53:43 [Debug] Messaging : IDLE session error: QNetworkSession::InvalidConfigurationError
Which finally ends up by calling closeIdleSession() which will terminate the QNetworkSession. At this point the idle protocol is still not affected.
For the lower layer (the protocol one), a callback is triggered, idleTransportError() from imapclient.cpp#540, as seen in the logs:
[23263] nov. 30 13:53:43 [Debug] IMAP : "I:1" IDLE: An IMAP IDLE related error occurred.
An attempt to automatically recover is scheduled in 30 seconds.
This first close the connection and starts a timer that will try to recover in 30 seconds.
Recoonection after a network issue
Indeed 30 seconds later in the logs, one can see:
[23263] nov. 30 13:54:14 [Debug] IMAP : "3" IDLE: IMAP IDLE error recovery trying to establish IDLE state now.
This corresponds to the response to the openRequest() signal emitted in the callback. Before this signal, the recover timer is started again with a double waiting time (capped by one hour for it not to become too long). In the signal handler, all idle protocols are closed and the signal restartPushEmail is emitted.
This signal is caught by the imap service, as seen in the logs:
[23263] nov. 30 13:54:14 [Debug] Messaging : Attempting to restart push email for account 44 "login"
which corresponds to restartPushEmail() in imapservice.cpp#1748. Then, since the network session was previously closed, a new session is opened, as in imapservice.cpp#1763. This session is testing the network capability and will pass only when network is up again, as seen in the logs:
[23263] nov. 30 13:54:14 [Debug] Messaging : IDLE Session: Opening...
[23263] nov. 30 13:54:14 [Debug] Messaging : IDLE session error: QNetworkSession::InvalidConfigurationError
[23263] nov. 30 13:54:14 [Debug] Messaging : IDLE Session: Closing...
[23263] nov. 30 14:04:16 [Debug] Messaging : IDLE Session: Network state changed: false
[23263] nov. 30 14:04:16 [Debug] Messaging : IDLE session error: QNetworkSession::InvalidConfigurationError
[23263] nov. 30 14:04:45 [Debug] Messaging : IDLE Session: Network state changed: true
[23263] nov. 30 14:04:45 [Debug] Messaging : IDLE Session: Opening...
[23263] nov. 30 14:04:45 [Debug] Messaging : IDLE session opened, state 3
At this point the imapclient is still not reconnected.
From the logs, one can see that the email client is reconnecting:
[23263] nov. 30 14:04:45 [Debug] IMAP : "3" About to open connection "login" "server"
This corresponds to the open() of the imap protocol. But I cannot see from where this function is called.
Then, the logical connection process is followed with the creation of a new idle protocol when the capabilities are known, see:
[23263] nov. 30 14:04:46 [Debug] IMAP : "I:2" About to open connection "login" "server"
Notice the "I:2" protocol label.
Failing cases
To be written.
Original (outdated) post
Some thoughts to investigate this further:
in imapservice.cpp, any change in the connection state breaks the idle state. So when both connections are active, I guess the fact that the device may switch between the two from time to time according to signal strength will trigger the reported behaviour. In the meantime, I don't see any attempt to reestablish the idle state after reconnection. Maybe it's done upper in the stack, but IMHO it's missing.
I use general mail with a regular dovecot server and see also this behaviour
hoschi ( 2015-06-24 20:19:35 +0300 )editFor me imap idle does not usually work after a change from mobile to wifi. Sometimes it works.
But if I disable both data connections and turn wifi on first imap idle keeps working. So it's just the switch from mobile to wifi that breaks it.
Idle isn't recovered even after 30 minutes which should be some kind of connection renew interval.
hetas ( 2015-07-02 19:24:34 +0300 )editSame for me using Dovecot. 4G works fine but wifi won't use idle. Sometimes restarting the radios fixes it, but not always.
wheelybird ( 2015-09-08 20:09:08 +0300 )editStill present in 1.1.9.28. I've stopped using wifi at all because of this problem. Very annoying.
hetas ( 2015-09-24 21:11:44 +0300 )editI've created a bug internally to track this issue, and we will investigate which piece of our stack is detecting the connection status wrongly (buteo vs qmf) and hopefully figure out how to fix it.
chris.adams ( 2015-09-28 12:45:51 +0300 )edit