6.0.0-beta1
03.07.25

[#12930] AS: Endless loop with Windows Phone 7.8
Summary AS: Endless loop with Windows Phone 7.8
Queue Synchronization
Queue Version Git master
Type Bug
State Resolved
Priority 1. Low
Owners mrubinsk (at) horde (dot) org
Requester thomas.jarosch (at) intra2net (dot) com
Created 01/21/2014 (4181 days ago)
Due
Updated 01/23/2014 (4179 days ago)
Assigned 01/21/2014 (4181 days ago)
Resolved 01/23/2014 (4179 days ago)
Github Issue Link
Github Pull Request
Milestone
Patch No

History
01/23/2014 06:20:23 PM Michael Rubinsky State ⇒ Resolved
 
01/22/2014 04:38:35 PM Michael Rubinsky Comment #15 Reply to this comment
Some new info:
The phone is a LG E900 with the recent Windows Phone 7.8 update.

So it's a bit ironic that a Windows phone does not conform to the 
ActiveSync spec ;)
Agreed. I have a Lumia 822 running WP8 and an HTC something or other 
running 6.5 that both work correctly (do not request the RI collection 
unless it is sent the RI folder in a FOLDERSYNC response).


01/22/2014 02:14:11 PM Thomas Jarosch Comment #14
Summary ⇒ AS: Endless loop with Windows Phone 7.8
Reply to this comment
Some new info:
The phone is a LG E900 with the recent Windows Phone 7.8 update.

So it's a bit ironic that a Windows phone does not conform to the 
ActiveSync spec ;)

It seems to sync with the latest fixes (backported to FRAMEWORK_5).
I'll try to gather some logs once it's done with the initial sync.

01/22/2014 10:11:30 AM Thomas Jarosch Comment #13 Reply to this comment

[Show Quoted Text - 10 lines]
Ah, the code in Collections.php was copied from 
Driver/Base.php:_getFolderUidForBackendId()
which contains a $type parameter.

I'm extending the Driver/Base.php:_getFolderUidForBackendId() function
to check $type for the correct type OR $id for 'RI'.
Then we support both "modes" if $type is not given.

01/22/2014 10:02:13 AM Thomas Jarosch Comment #12 Reply to this comment

[Show Quoted Text - 18 lines]
Nice! I'll test it ASAP.

I think the new code in "public function getFolderUidForBackendId($folderid)"
contains a typo: It accesses "$type" instead of "$id".
-> Buuuuuuuug

I think it should be:
         // Always use RI for recipient cache.
         if ($folderid == 'RI') {
             return $folderid;
         }

01/22/2014 07:06:27 AM Git Commit Comment #11 Reply to this comment
Changes have been made in Git (master):

commit ae02bbf0279959f2a3d25f7c011e503970fda975
Author: Michael J Rubinsky <mrubinsk@horde.org>
Date:   Wed Jan 22 02:02:52 2014 -0500

     Add support in Horde_ActiveSync for Recipient Cache.

     Needs backend support, but this prevents broken clients from
     killing the sync completely (see Bug #12930).

  .../lib/Horde/ActiveSync/Collections.php           |   11 +++++++++++
  .../lib/Horde/ActiveSync/Driver/Base.php           |    4 ++++
  .../lib/Horde/ActiveSync/Request/Sync.php          |    9 ++++++++-
  .../Core/lib/Horde/Core/ActiveSync/Driver.php      |   13 +++++++++++++
  4 files changed, 36 insertions(+), 1 deletions(-)

http://git.horde.org/horde-git/-/commit/ae02bbf0279959f2a3d25f7c011e503970fda975
01/21/2014 04:06:59 PM Thomas Jarosch Comment #10 Reply to this comment
May be we should add a sanity limit of 5.000+ "sync options" the next
time an AS client sends us an unexpected tag ;) Just log it, bail out
of the loop and continue.
Either that or bail out if nothing was successfully parsed by the 
bottom of the loop. Something should be parsed through each iteration.
if we choose the latter route, an unknown tag in the middle of the sync option
wbxml stream might kill further option parsing. Though that should 
never happen ;)

[Show Quoted Text - 9 lines]
I've excluded the specific user from ActiveSync for now.
(the server really struggles when ten or more 100% CPU time tasks are 
running :o)).
I'll check tomorrow morning if some other phone causes trouble, too. 
Hopefully not :)

01/21/2014 03:52:52 PM Michael Rubinsky Comment #9 Reply to this comment

[Show Quoted Text - 13 lines]
Either that or bail out if nothing was successfully parsed by the 
bottom of the loop. Something should be parsed through each iteration.
The user mentioned something about a recent OTA Android update for 
her phone. I have to ask for the specific model again. May be that 
update "enabled" the RI collection.
If that's the case, I might as well go ahead and implement the RI 
functionality now since I'll have to implement at least part of it 
anyway. If the device is erroneously asking for the RI collection, it 
is probably also expecting a return value for it as well. Just 
ignoring the MAXITEMS is likely to cause problems on the client side.
01/21/2014 03:29:14 PM Thomas Jarosch Comment #8 Reply to this comment
Not sure about the infinite loop, but if helps you, it's dying
because the MAXITEMS node is not expected. You can see this in
Horde_ActiveSYnc_Request_Sync::  line 1142 where there is a TODO to
remind me to implement it when we implement the RI cache.
...and that is EXACTLY why it loops. There is no escape from the 
while() loop in that case.
Thanks for the analysis!

May be we should add a sanity limit of 5.000+ "sync options" the next 
time an AS client sends us an unexpected tag ;) Just log it, bail out 
of the loop and continue.

The user mentioned something about a recent OTA Android update for her 
phone. I have to ask for the specific model again. May be that update 
"enabled" the RI collection.

@Arjen: I still run 2.8.5 because of QA. When I update to a new 
version, I have to test all the devices I have floating around again. 
Therefore I prefer to apply known fixes to 2.8.5 and will update every 
few months or so to the current pear version. I also update the horde 
apps and framework at the same time ;)

01/21/2014 03:18:23 PM Michael Rubinsky Comment #7 Reply to this comment
Not sure about the infinite loop, but if helps you, it's dying 
because the MAXITEMS node is not expected. You can see this in 
Horde_ActiveSYnc_Request_Sync::  line 1142 where there is a TODO to 
remind me to implement it when we implement the RI cache.
...and that is EXACTLY why it loops. There is no escape from the 
while() loop in that case.
01/21/2014 03:16:18 PM Michael Rubinsky Comment #6 Reply to this comment

[Show Quoted Text - 9 lines]
Not sure about the infinite loop, but if helps you, it's dying because 
the MAXITEMS node is not expected. You can see this in 
Horde_ActiveSYnc_Request_Sync::  line 1142 where there is a TODO to 
remind me to implement it when we implement the RI cache.
01/21/2014 03:14:39 PM Michael Rubinsky Comment #5 Reply to this comment
Horde_ActiveSync version is 2.8.5. Any known, related issue?
Any particular reason why you're still running 2.8.5 instead of the 
latest version? Pear has 2.11.0 available as of now, so I'd try 
upgrading to the latest version first.
This particular issue is still present in current PEAR. It's because 
the client is issuing a SYNC request for a collection that it 
shouldn't be.
01/21/2014 03:07:05 PM arjen+horde (at) de-korte (dot) org Comment #4 Reply to this comment
Horde_ActiveSync version is 2.8.5. Any known, related issue?
Any particular reason why you're still running 2.8.5 instead of the 
latest version? Pear has 2.11.0 available as of now, so I'd try 
upgrading to the latest version first.
01/21/2014 02:53:03 PM Thomas Jarosch Comment #3 Reply to this comment
I should be able to take a look at this tonight, if I don't get 
stranded here at work by the pending snow storm :)
I shouldn't have asked you earlier about the snow storms :o)

I still try to figure out how to trace this with gdb. There was an 
infinite loop
in the Kolab code once and it would be nice to debug this easily if it 
should ever pop up again.

01/21/2014 02:23:15 PM Michael Rubinsky Comment #2
Assigned to Michael Rubinsky
State ⇒ Assigned
Reply to this comment
You are close. "RI" in the <FolderId> node stands for the Recipient 
Information Cache - it's something like a "popular recipient" cache to 
speed lookups. It's on the TODO to integrate this with IMP's favorite 
recipients functionality. The thing is, I'm pretty sure the device is 
NOT supposed to request this unless the server indicates that it is in 
use. Sounds like a bug in the client, though I have 2 Samsung test 
devices that don't exhibit this behavior.

I should be able to take a look at this tonight, if I don't get 
stranded here at work by the pending snow storm :)
01/21/2014 02:13:13 PM Thomas Jarosch Comment #1
State ⇒ Unconfirmed
New Attachment: endless_loop_log.txt Download
Patch ⇒ No
Milestone ⇒
Priority ⇒ 1. Low
Type ⇒ Bug
Summary ⇒ AS: Endless loop with Samsung phone
Queue ⇒ Synchronization
Reply to this comment
Hi,

I've one box that somehow triggers an endless loop via ActiveSync 
until the PHP timeout is reached.

The Samsung phone sends a request and the httpd process gets stuck in 
a loop, eating up 100% CPU time. I've tried to attach "strace" to it 
but it does not communicate anything with the linux kernel, so I guess 
it's stuck in a loop.

The last bits I see in the ActiveSync log look like this:

2014-01-21T11:59:45+01:00 ef6bd35e390f8ed625df47ceaee3ae1f DEBUG: 
[18254] I    <Folder>
2014-01-21T11:59:45+01:00 ef6bd35e390f8ed625df47ceaee3ae1f DEBUG: 
[18254] I     <SyncKey>
2014-01-21T11:59:45+01:00 ef6bd35e390f8ed625df47ceaee3ae1f DEBUG: 
[18254] I       {52cbc9bb-e888-4cd3-92ed-17f95c4fb70f}1
2014-01-21T11:59:45+01:00 ef6bd35e390f8ed625df47ceaee3ae1f DEBUG: 
[18254] I     </SyncKey>
2014-01-21T11:59:45+01:00 ef6bd35e390f8ed625df47ceaee3ae1f DEBUG: 
[18254] I     <FolderId>
2014-01-21T11:59:45+01:00 ef6bd35e390f8ed625df47ceaee3ae1f DEBUG: 
[18254] I       RI
2014-01-21T11:59:45+01:00 ef6bd35e390f8ed625df47ceaee3ae1f DEBUG: 
[18254] I     </FolderId>
2014-01-21T11:59:45+01:00 ef6bd35e390f8ed625df47ceaee3ae1f DEBUG: 
[18254] I     <Options>
2014-01-21T11:59:45+01:00 ef6bd35e390f8ed625df47ceaee3ae1f DEBUG: 
[18254] I      <MaxItems>

The full sync log of the device is attached to this report.

Horde_ActiveSync version is 2.8.5. Any known, related issue?

I'm currently thinking about ways to debug this since I don't have any 
hint what might be wrong.
My first uneducated guess is that something is wrong in the binary 
WBXML data and we run into an endless loop while decoding it. Just a 
*wild* theory though.

Installing xdebug will probably slow down the productive box to a crawl :(

May be "gdb" might do the trick to debug this:
http://derickrethans.nl/what-is-php-doing.html

Cheers,
Thomas

Saved Queries