We have moved to a new Sailfish OS Forum. Please start new discussions there.
34

Email IMAP idle doesn't work with both connections active. [released]

Tracked by Jolla (In release)

asked 2015-06-23 21:11:52 +0200

ApB gravatar image

updated 2019-03-25 21:25:39 +0200

I have a gmail account set up as normal email. With both connections active imap push doesn't work. The minimized app doesn't show the usual up to date on the cover it shows the time since the last update.

If i deactivate both or the connection changes (move away from my wifi) it seems to work fine but i'll need to test more. It seems related to this > https://together.jolla.com/question/91937/bug-imap-idle-aka-push-email-does-not-work-with-generic-imap-account/ but in that bug the cover always shows up to date even thought it doesn't sync.

So not sure if it is that bug or something different all together.

Screen shots:

image description

image description

Update: big number

COME ON JOLLA

BTW. This continues to be an unacceptable bug. Surprised not many people hitting it.

Any updates on this?? Jolla?? Sailors?? @Joona Petrell ?? @veskuh?? @chris.adams

edit retag flag offensive reopen delete

The question has been closed for the following reason "released in a software update" by ApB
close date 2019-05-15 00:13:04.347822

Comments

1

I use general mail with a regular dovecot server and see also this behaviour

hoschi ( 2015-06-24 20:19:35 +0200 )edit
1

For 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 +0200 )edit

Same 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 +0200 )edit

Still 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 +0200 )edit
1

I'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 +0200 )edit

4 Answers

Sort by » oldest newest most voted
5

answered 2016-10-05 22:05:46 +0200

poddl gravatar image

still present in 2.0.4.13

edit flag offensive delete publish link more

Comments

4

This is quite an important one jolla. Come on.

ApB ( 2016-10-05 22:15:10 +0200 )edit
5

answered 2017-11-29 15:19:39 +0200

updated 2018-01-11 10:38:43 +0200

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.

edit flag offensive delete publish link more

Comments

@damien-caliste any update on this?

ApB ( 2017-12-21 18:58:32 +0200 )edit

As said in the last meeting, I've reproduced the bug and have log about it. I've investigated it without success though, the code is quite complex for me.

After the holidays, I'll discuss here the code path I've understood and how it relates to the log.

Damien Caliste ( 2017-12-23 17:00:27 +0200 )edit

@damien-caliste thanks i came late in the meeting and didn't read the logs. Thanks.

ApB ( 2017-12-25 14:31:53 +0200 )edit
1

I think the problem is messageserver5 missing some network changes. I can easily reproduce this by disabling wlan at home, restarting messageserver5 and re-enabling wlan again.

The Jolla1 reconnects to wlan but messageserver5 keeps the old connections open.

Here is some output of the device at my desk. I'm logged in as root over wlan (netmask 192.168.178.0/24):

[root@Sailfish ~]# ip route get 9.9.9.9
9.9.9.9 via 192.168.178.2 dev wlan0  src 192.168.178.28 
cache 

[root@Sailfish ~]# netstat -anpt | grep messageserver
tcp        0      0 10.170.101.86:38447         66.102.1.109:993            ESTABLISHED  628/messageserver 
tcp        0      0 10.170.101.86:38445         66.102.1.109:993            ESTABLISHED  628/messageserver

Obviously the source address of these connections should be 192.168.178.28, but messageserver5 didn't reconnect.

Eierkopp ( 2018-01-10 19:33:39 +0200 )edit
1

@Damien Caliste

Any updates.

ApB ( 2018-03-07 10:49:38 +0200 )edit
4

answered 2016-10-07 12:35:57 +0200

poddl gravatar image

It is even getting more worse:

The minimized app show the usual up to date on the cover, but does not update the imap idle account. This is a new behavior. Now we can not even see anymore, if the idle is active or not.

edit flag offensive delete publish link more

Comments

Yes, but their got the problem only on some mail provider. The problem here occurs only sometimes, but only after network change.

The behavior before had an indicator on the cover, it shows up to date or time since the last update

Now, jolla screwed something more up, the indicator is now missing, showing idle, but does not run in idle. This appears since the update to 2.0.4.13. My mail account did not change. Before I switched to airplane and back, then the idle was fine again, without indicator, no way to check...

poddl ( 2016-10-07 13:29:53 +0200 )edit

I'll check when i get the update. I am not on Early Access but the email problems are present for quite a while. And its bad cause email is the most basic of basic functions on a smartphone. :/

ApB ( 2016-10-07 13:40:27 +0200 )edit

what I'm not understand:

On all devices I used connman before, there where no problems at all, it is running pretty well, even imap idle. So why need so much effort on this case? Is there some layer between? I thought this should already running out of the box on linux systems.

And not only the IMAP issues, so much network change issues, to find in this forum.

poddl ( 2016-10-07 14:31:56 +0200 )edit
2

answered 2017-02-17 13:06:10 +0200

poddl gravatar image

still present in 2.1.0.9

edit flag offensive delete publish link more

Question tools

Follow
13 followers

Stats

Asked: 2015-06-23 21:11:52 +0200

Seen: 2,521 times

Last updated: Mar 25 '19