[horde] new tests for Re: problem ActiveSync Android Event with end date

[Steffen]

On Wed, 5 Feb 2014, Steffen wrote:
> On Fri, 31 Jan 2014, Michael J Rubinsky wrote:
>> Quoting Steffen <skhorde at smail.inf.fh-bonn-rhein-sieg.de>:
>>> On Fri, 10 Jan 2014, Steffen wrote:
>
>>> 12:03 one event repeated each 4th week end on 28th March
>> 
>> ^^^ This event is NEVER sent to the server, at least not in the log you 
>> posted.
>
> OK, thanks for checking the logs.
>
>>> Most interessting is that the time stamp gets 1 hour back ??? From 12:04
>>> to 11:04. It's another PID. During that phase, no Calendar entries in
>>> the log. I also had log entries another time with a line:
>>> Skipping @Calendar@ because it is not PINGable.
>>> 
>>> Then there is a jump in the hour again with the same PID at the time
>>> I remove the repeated event:
>>> 2014-01-30T11:08:01+00:00 DEBUG: [1671] I       </Data>
>>> 2014-01-30T11:08:01+00:00 INFO: [1671]
>>> Horde_Core_ActiveSync_Driver::changeMessage(@Calendar@,  ...)
>>> 2014-01-30T12:08:01+01:00 INFO: [1671] Updating state during change
>>> 2014-01-30T12:08:01+01:00 DEBUG: [1671] I      </Add>
>>> 
>>> And with the "12" hour logs, the "Calendar" stuff appears again.
>>> 
>>> The log is attached
>> 
>> I have no idea what is going on. Your synclog also seems to indicate your 
>> client is issuing multiple, identical requests. Given the fact that the 
>> event in question is not even sent to the server from the client, this 
>> seems like a client bug.
>
> Hmm, I will try this with other setups.
>
> Do you have an idea, why the log time stamp warps one hour back into the past 
> and back into current again? Is Horde switching to UTC maybe? The 1 hour is 
> the difference of the local server time to UTC.
>
> Is it possible that the time difference break the acceptance of some request 
> / response? I mean, several SYNC implementations add sanity checking that a 
> SYNC message is in a defined time frame. Maybe Horde tags responses with a 
> timestamp, which is one hour too old?

I have re-tested with a Nexus5 with Android v4.4.2 and an upgraded Horde, 
now Horde_ActiveSync v2.12.3.

On both versions of Horde_ActiveSync v2.12.1 and v2.12.3 the Nexus5 
Exchange Server Force Closes as soon one triggers a sync with the repeated 
event with repeat end date. It happily works with other events. Attached 
you'll find the log of the 2nd attempt Nexus5 with v2.12.3. Before the 
test I removed the ActiveSync device from Horde via Admin GUI.

Events with repeat end date won't work on v2.12.3 with my personal Android 
v4.2 device still.

The Nexus5 log starts with the log time "2014-02-05T07:52:44+00:00" 
although the local server time is one hour ahead. So the change of the
logtime does not have no (direct) connection to the event problem.
The logtime than warps to the current time:

2014-02-05T07:53:50+00:00 INFO: [4627] Initializing state for collection: @Calendar@, synckey: {52f1edde-3948-4876-9b7b-11b2c25f42d0}2
2014-02-05T07:53:50+00:00 INFO: [4627] Loading state for synckey {52f1edde-3948-4876-9b7b-11b2c25f42d0}2
2014-02-05T07:53:50+00:00 INFO: [4627] Initializing message diff engine for @Calendar@ (@Calendar@)
2014-02-05T08:53:50+01:00 INFO: [4627] Using SYNCSTAMP 27109 for @Calendar at .
2014-02-05T08:53:50+01:00 INFO: [4627] Horde_Core_ActiveSync_Driver::getServerChanges(@Calendar@, 27109, 27109, 1390377230, 1)
2014-02-05T08:53:50+01:00 INFO: [4627] Fetching changes for calendar using MODSEQ.
2014-02-05T08:53:50+01:00 INFO: [4627] Found 0 message changes in @Calendar at .

-- 
Steffen
-------------- next part --------------
A non-text attachment was scrubbed...
Name: Nexus5.v4.4.2.async.log.bz2
Type: application/octet-stream
Size: 8444 bytes
Desc: 
URL: <http://lists.horde.org/archives/horde/attachments/20140205/bf974d79/attachment-0001.obj>