6.0.0-alpha12
6/12/25

[#12339] PING-SYNC storm in ActiveSync is back
Summary PING-SYNC storm in ActiveSync is back
Queue Synchronization
Queue Version Git master
Type Bug
State Resolved
Priority 2. Medium
Owners mrubinsk (at) horde (dot) org
Requester arjen+horde (at) de-korte (dot) org
Created 06/11/2013 (4384 days ago)
Due
Updated 07/21/2013 (4344 days ago)
Assigned 06/23/2013 (4372 days ago)
Resolved 07/21/2013 (4344 days ago)
Github Issue Link
Github Pull Request
Milestone
Patch No

History
07/21/2013 10:13:32 PM Michael Rubinsky Comment #22
State ⇒ Resolved
Reply to this comment
Going to resolve until somebody can provide reliable steps to reproduce.
06/27/2013 07:42:43 PM Michael Rubinsky Comment #21 Reply to this comment
Unfortunately, I don't see the cause for the failed sync in this 
portion of the log.

I've added some additional logging to the code, and also changed it so 
we no longer clear the sync state when this happens. This will at 
least prevent the client from continuously trying over and over again 
after it reaches this point.
06/24/2013 04:51:49 AM jhaar-horde (at) whanau (dot) org Comment #20 Reply to this comment
06/24/2013 04:43:24 AM jhaar-horde (at) whanau (dot) org Comment #19 Reply to this comment
This should be better, I see some "INSERT INTO" errors in there - 
they're probably important ;-)
Hmm, didn't like me using the same attachment name. Renamed to "4...-1.zip"


06/24/2013 04:40:45 AM jhaar-horde (at) whanau (dot) org Comment #18 Reply to this comment
This should be better, I see some "INSERT INTO" errors in there - 
they're probably important ;-)


06/24/2013 01:06:35 AM Michael Rubinsky Comment #17 Reply to this comment
OK how do I get that? Is that the same file - just with more data in it?
Yes.
What should I look for so I know when it contains what you need?
Multiple cycles of <SYNC> request and responses with the same <SYNCKEY> value.
(ie the file is now twice as large as the one I sent through - will 
that contain what you need?)
Maybe?
06/23/2013 11:50:53 PM jhaar-horde (at) whanau (dot) org Comment #16 Reply to this comment
the response. I would need a synclog that shows the full cycle of 
request/response that keeps repeating (this contains only a portion 
of the last response).
OK how do I get that? Is that the same file - just with more data in 
it? What should I look for so I know when it contains what you need? 
(ie the file is now twice as large as the one I sent through - will 
that contain what you need?)
06/23/2013 10:50:53 PM Michael Rubinsky Comment #15
State ⇒ Feedback
Reply to this comment
No, it's not the cause of the problem, but rather a result of it. It 
means the client is continuously requesting the same synckey over and 
over again - probably because it didn't like some data it received in 
the response. I would need a synclog that shows the full cycle of 
request/response that keeps repeating (this contains only a portion of 
the last response).
06/23/2013 09:15:19 PM jhaar-horde (at) whanau (dot) org Comment #14
New Attachment: 49F0F79FA24A4D73889C1F0A61C274CC.zip Download
Reply to this comment
Hi there

Sorry, but the issue returned. Very strange - before it was Outlook 
2013 that worked and Android that couldn't update, whereas now Android 
is working fine, but Outlook 2013 cannot update!

Attached is the ActiveSync logfile for Outlook. The "ERR: Reached 
MAXIMUM_SYNCKEY_COUNT possible sync loop" looks like where the problem 
begins?
06/16/2013 08:41:54 PM jhaar-horde (at) whanau (dot) org Comment #13 Reply to this comment
Thanks to your reference to the other bug, by reading about that I 
decided to reinitialize the entire horde database.  That fixed the 
problem

i.e. it appears the upgrade from 5.0 to 5.1 involves a bunch of SQL 
schema changes, and something went wrong in there - leading to this 
problem?

I did backup the original database, so if you need "chunks" that could 
show the problem, let me know

Jason
06/14/2013 01:48:12 PM Michael Rubinsky Comment #12
State ⇒ Resolved
Reply to this comment
Going to resolve this one to avoid confusing it with Bug: 12316. This 
bug was a regression of an earlier fixed bug, not related to the 
"Unknown Message" bug in the other ticket.
06/14/2013 01:45:31 PM Michael Rubinsky Comment #11 Reply to this comment
I'm using courier-imap and it has a courierimapuids file that 
contains the uid mappings to Maildir files. I just deleted the one 
for my inbox, and made my (imap) Thunderbird "repair folder" - which 
forced courier-imap to generate it. Both Outlook and Android 
certainly noticed the change, spontaneously did a "re-jig" and 
suddenly my Android was up-to-date again.
Thanks for this clarification. At least I know the UIDVALIDITY code is 
working as intended.
Attached is the Outlook sync log. I captured this after the above changes
This is Bug: 12316

06/14/2013 02:19:10 AM jhaar-horde (at) whanau (dot) org Comment #10
New Attachment: outlook2013.txt.gz Download
Reply to this comment

I'm using courier-imap and it has a courierimapuids file that contains 
the uid mappings to Maildir files. I just deleted the one for my 
inbox, and made my (imap) Thunderbird "repair folder" - which forced 
courier-imap to generate it. Both Outlook and Android certainly 
noticed the change, spontaneously did a "re-jig" and suddenly my 
Android was up-to-date again. However, I just sent a new message in 
and it didn't show up on the Android or Outlook - but did on TB - so 
it's out of whack again

Attached is the Outlook sync log. I captured this after the above changes




06/14/2013 12:24:04 AM Michael Rubinsky Comment #9 Reply to this comment
Attached.maybe the following is the report of the problem?

ERR: Unknown message.
Bug: 12316
Now that I've enabled per-device sync logging, I can see something 
else. My Android is blocking on this error (I guess),
This is happening because, for some reason you are getting UIDs back 
from your IMAP server that are lower than the minimum UID received in 
the initial sync. No idea why this is happening at this point. My 
guess is that the UIDs are no longer valid (UIDVALIDITY changed), but 
I'm waiting for someone to test those changes.
but the traffic storm I'm seeing is actually from my Outlook 2013 - 
it's log file is huge and growing by megabytes per minute (60,100 
lines per minute). However, email seems to be in sync - it's simply 
continually checking?
Yes, that's how ActiveSync works. The difference with Outlook is that 
it syncs EVERY email folder COMPLETELY and pushes every folder, 
whereas android, by default, only pushes INBOX. Now, if it's actually 
issuing continuous SYNC requests (and not looping within the single 
SYNC request) then *that* is a problem.
I have set "forcedheartbeat" in an attempt to slow down Outlook - 
but even after a restart doesn't seem to have any effect
This setting is simply the time that each PING or SYNC request lasts 
before initiating another one, so you will still see the checks. If 
you want to reduce the number of actual checks performed during each 
heartbeat you should increase the 'waitinterval' setting. This will 
cause the server to wait longer between backend checks. Of course, 
this also means it will be longer before the change is detected and 
therefore longer to be pushed to the device.
I'm guessing there's a corrupt email that causes Android to fault and stop,
Not a corrupt email, but unexpected (or unexplained) email UIDs being 
received from the imap client.
whereas Outlook gets past it but then goes back to re-check and ends 
up looping?
No idea how Outllook is getting past this. A log from Outlook would 
possibly be helpful as well.
06/14/2013 12:07:44 AM jhaar-horde (at) whanau (dot) org Comment #8
New Attachment: androidc96870711.txt.gz Download
Reply to this comment
I can get you logs if you want to know what we're seeing - just let
me know what you need
The sync log, attach to ticket please.
Attached.maybe the following is the report of the problem?

ERR: Unknown message.

Now that I've enabled per-device sync logging, I can see something 
else. My Android is blocking on this error (I guess), but the traffic 
storm I'm seeing is actually from my Outlook 2013 - it's log file is 
huge and growing by megabytes per minute (60,100 lines per minute). 
However, email seems to be in sync - it's simply continually checking? 
I have set "forcedheartbeat" in an attempt to slow down Outlook - but 
even after a restart doesn't seem to have any effect

I'm guessing there's a corrupt email that causes Android to fault and 
stop, whereas Outlook gets past it but then goes back to re-check and 
ends up looping?

Just guesses :-)

Thanks

Jason


06/12/2013 06:53:01 PM Michael Rubinsky Comment #7 Reply to this comment
I can get you logs if you want to know what we're seeing - just let 
me know what you need
The sync log, attach to ticket please.
06/12/2013 06:47:28 PM jhaar-horde (at) whanau (dot) org Comment #6 Reply to this comment
I think I'm seeing this too. I was happily running 5.0.X until this 
week when I updated to 5.1.X. Since then, ActiveSync has become 
basically broken. Android phones are continually resynching - never 
finishing.

From a fresh reset they successfully download mail, but then can 
never get updates. The logs show continuous " 200 " download activity, 
but nothing new shows up in the device

I have manually applied the two patches mentioned in this ticket but 
they haven't helped.

I can get you logs if you want to know what we're seeing - just let me 
know what you need
06/11/2013 09:01:21 PM arjen+horde (at) de-korte (dot) org Comment #5 Reply to this comment
Does this fix?
I'm not sure, since the problem did not always occur. I have been 
experimenting with a NoSQL cache (MongoDB) lately and noticed a few 
times when I restarted Apache and/or MongoDB. It happened three times 
so far and I only noticed it because of the *huge* battery drain on 
the respective phones. I'll keep an eye on it. If it doesn't happen 
again in the next few days, it is most likely resolved by these changes.
06/11/2013 08:48:38 PM Michael Rubinsky Comment #4
State ⇒ Feedback
Assigned to Michael Rubinsky
Reply to this comment
Does this fix?

06/11/2013 08:45:01 PM Git Commit Comment #3 Reply to this comment
Changes have been made in Git (master):

commit e8b8ebb65de1d70ff92ef1b010a58a00e12c3577
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date:   Tue Jun 11 16:43:30 2013 -0400

     Bug: 12339 Fix regression of Bug: 12075 in preventing PING-SYNC loop.

  .../lib/Horde/ActiveSync/Collections.php           |    3 +++
  .../lib/Horde/ActiveSync/Request/Ping.php          |    1 +
  2 files changed, 4 insertions(+), 0 deletions(-)

http://git.horde.org/horde-git/-/commit/e8b8ebb65de1d70ff92ef1b010a58a00e12c3577
06/11/2013 08:27:18 PM arjen+horde (at) de-korte (dot) org Comment #2 Reply to this comment
For the record, this is with Horde_ActiveSync-2.4.0.
06/11/2013 06:53:41 PM arjen+horde (at) de-korte (dot) org Comment #1
Priority ⇒ 2. Medium
State ⇒ Unconfirmed
New Attachment: PING-SYNC-loop.log.gz Download
Patch ⇒ No
Milestone ⇒
Queue ⇒ Synchronization
Summary ⇒ PING-SYNC storm in ActiveSync is back
Type ⇒ Bug
Reply to this comment
Bug http://bugs.horde.org/ticket/12075 is back in Horde-5.1.0.

The behavior is identical, the loop is broken by forcing a flag change 
or new messages in the folder where this happens.

Log of two iterations attached.

Saved Queries