[horde] Problem syncing with AS on Horde webmail 5.2.16

Mon Apr 10 15:22:00 UTC 2017

Hello Michael

I have opened a bug report on Android bug tracker but with my past
experience I am not expecting to see any feedback from Google on this....

In the meantime I have narrowed down the issue to occur when I switch from
cell data (which doesn't have access to my horde server) to my wifi which
does have access to horde..

Somehow Android must be interpreting the sudden and rapid change of network
as a glitch and initiates a full resync event to eliminate data errors??
Just a theory.

Sent from mobile

On Mar 13, 2017 8:17 PM, "Michael J Rubinsky" <mrubinsk at horde.org> wrote:

Quoting Louis-Philippe Allard <lp.allard.1 at gmail.com>:

Quoting Michael J Rubinsky <mrubinsk at horde.org>:
>
> Quoting Louis-Philippe Allard <lp.allard.1 at gmail.com>:
>>
>> Quoting Michael J Rubinsky <mrubinsk at horde.org>:
>>>
>>> Quoting Louis-Philippe Allard <lp.allard.1 at gmail.com>:
>>>>
>>>> Hello,
>>>>>
>>>>> so I managed to create the Exchange account on the phone, and sync
>>>>> goes well.  There was numerous Android updates betwen now and when I
>>>>> initially posted to the maillist so.... Perhaps some stuff was fixed on the
>>>>> android side?
>>>>>
>>>>> Anyways, now that sync works well, I am facing a new problem.....
>>>>> Once the exchange account is successfully synced, all is OK then all of a
>>>>> sudden, a Gmail icon shows up in the notification bar and says "Couldnt
>>>>> sign in".  Immediately, all data from the exchange (AS) server is removed
>>>>> fromt he phone!  The account is actually removed from the phone.  This is
>>>>> applicable for the calendar and contacts.
>>>>>
>>>>> I have narrowed this down to the fact that while at work,  my phone
>>>>> doesnt have access to my horde server and therefore cannot sync.  Fair
>>>>> enough, but in former times (last time I successfully used AS & Android)
>>>>> the data would remain on the phone until syncing was possible again.
>>>>>
>>>>> Now because of this, once the exchange server is once again available,
>>>>> I have to manually sync the account on the phone by going in Settings >
>>>>> Accounts > Echange > Sync all...
>>>>>
>>>>> Major annoyance.  Is it a problem on the Horde side or is it on the
>>>>> crappy android side?
>>>>>
>>>>
>>>> Hard to say without seeing any logs. However, I have never seen this
>>>> behavior with any of my test devices when they are unable to reach the
>>>> server, and this happens fairly often for my various test boxes, since they
>>>> are not always even powered on.
>>>>
>>>> In former times, when the exchange server
>>>>> Louis-Philippe Allard
>>>>> lp.allard.1 at gmail.com
>>>>> Sent using Horde Groupware on GNU/Linux
>>>>> --
>>>>> Horde mailing list
>>>>> Frequently Asked Questions: http://horde.org/faq/
>>>>> To unsubscribe, mail: horde-unsubscribe at lists.horde.org
>>>>>
>>>>
>>>> --
>>>> mike
>>>> The Horde Project
>>>> http://www.horde.org
>>>> https://www.facebook.com/hordeprojecthttps://www.twitter.
>>>> com/hordeproject
>>>>
>>>
>>> Michael, how do I generate an obfuscated log?  I am not going to post a
>>> 30Mb log file with million of personal calendar and contacts information..
>>>
>>> Perhaps opening a temporary gmail account to recreate my current setup?
>>>
>>
>> Yes, that would be my suggestion.
>>
>> Louis-Philippe Allard
>>> lp.allard.1 at gmail.com
>>> Sent using Horde Groupware on GNU/Linux
>>> --
>>> Horde mailing list
>>> Frequently Asked Questions: http://horde.org/faq/
>>> To unsubscribe, mail: horde-unsubscribe at lists.horde.org
>>>
>>
>> --
>> mike
>> The Horde Project
>> http://www.horde.org
>> https://www.facebook.com/hordeprojecthttps://www.twitter.com/hordeproject
>>
>
> Hello Mike,
>
> attached is finally a short log of an anon email account I setup exactly
> like my normal account.
>
> I setup the exchange account on the phone, let it sync until complete,
> then disconnected the phone from my LAN where my Horde server resides,
> waited a few minutes, then reconnected to the LAN, the phone synced
> quickly, and sure enough the account disappeared frm the phone.
>
> The attached log file captured all of that.
>
> If you dont see a problem in the log file, I can do more runs...
>

There is nothing in the log to indicate that the client should reset
itself. After the initial sync, and the disconnect/reconnect event, there
is this (truncated to only the pertinent log lines)

2017-03-13T19:26:47-04:00 androidc274924331 DEBUG: [10579] I
<FolderHierarchy:FolderSync>
2017-03-13T19:26:47-04:00 androidc274924331 DEBUG: [10579] I
 <FolderHierarchy:SyncKey>
2017-03-13T19:26:47-04:00 androidc274924331 DEBUG: [10579] I
 {58c72a43-1908-4885-872d-2951c0a8006e}1
2017-03-13T19:26:47-04:00 androidc274924331 DEBUG: [10579] I
 </FolderHierarchy:SyncKey>
2017-03-13T19:26:47-04:00 androidc274924331 INFO: [10579] No folder changes
found.
2017-03-13T19:26:47-04:00 androidc274924331 DEBUG: [10579] O
<FolderHierarchy:FolderSync>
2017-03-13T19:26:47-04:00 androidc274924331 DEBUG: [10579] O
 <FolderHierarchy:Status>
2017-03-13T19:26:47-04:00 androidc274924331 DEBUG: [10579] O    1
2017-03-13T19:26:47-04:00 androidc274924331 DEBUG: [10579] O
 </FolderHierarchy:Status>
2017-03-13T19:26:47-04:00 androidc274924331 DEBUG: [10579] O
 <FolderHierarchy:SyncKey>
2017-03-13T19:26:47-04:00 androidc274924331 DEBUG: [10579] O
{58c72a43-1908-4885-872d-2951c0a8006e}1
2017-03-13T19:26:47-04:00 androidc274924331 DEBUG: [10579] O
 </FolderHierarchy:SyncKey>
2017-03-13T19:26:47-04:00 androidc274924331 DEBUG: [10579] O
 <FolderHierarchy:Changes>
2017-03-13T19:26:47-04:00 androidc274924331 DEBUG: [10579] O
<FolderHierarchy:Count>
2017-03-13T19:26:47-04:00 androidc274924331 DEBUG: [10579] O     0
2017-03-13T19:26:47-04:00 androidc274924331 DEBUG: [10579] O
</FolderHierarchy:Count>
2017-03-13T19:26:47-04:00 androidc274924331 DEBUG: [10579] O
 </FolderHierarchy:Changes>
2017-03-13T19:26:47-04:00 androidc274924331 DEBUG: [10579] O
</FolderHierarchy:FolderSync>2017-03-13T19:26:47-04:00 androidc274924331
INFO: [10579] Loading FOLDERSYNC state containing 8 folders.
2017-03-13T19:26:47-04:00 androidc274924331 DEBUG: [10579] I
</FolderHierarchy:FolderSync>

This is a normal FOLDERSYNC request to sync the folder tree. A lot of
clients issue this when first (re)connecting. The result is that there were
no folder tree changes, and we tell the client that. FolderHierarchy:Status
of 1 means success and the FolderHierarchy:Count shows no changes.  For
some reason, the client issues a few of these requests that run
concurrently. This is "odd", but it's not the only client that I've seen do
this, and our code handles this fine.

Now, here is the problem. For some unknown reason, the client then issues
the following:

2017-03-13T19:27:45-04:00 androidc274924331 INFO: [13393] Handling
FOLDERSYNC command.
2017-03-13T19:27:45-04:00 androidc274924331 INFO: [13393] Checking
policykey for device: ANDROIDC274924331 user: testemail at gmail.com
2017-03-13T19:27:45-04:00 androidc274924331 INFO: [13393] Policykey: 0
verified.
2017-03-13T19:27:45-04:00 androidc274924331 DEBUG: [13393] I
<FolderHierarchy:FolderSync>
2017-03-13T19:27:45-04:00 androidc274924331 DEBUG: [13393] I
 <FolderHierarchy:SyncKey>
2017-03-13T19:27:45-04:00 androidc274924331 DEBUG: [13393] I     0
2017-03-13T19:27:45-04:00 androidc274924331 DEBUG: [13393] I
 </FolderHierarchy:SyncKey>

This is another FOLDERSYNC request, but notice that the
FolderHierarchy:SyncKey field is '0'. This indicates that the client is
requesting a completely new pairing - it has lost it's state and must start
over. As to WHY this happens, I have no idea, but there is nothing that the
server is sending to the client that indicates it should do this. The only
things that are being sent to the client up to this point are successful
responses.  I would guess it's a bug in the Android client.

> Thanks!
>  Louis-Philippe Allard
> lp.allard.1 at gmail.com
> Sent using Horde Groupware on GNU/Linux
>

-- 
mike
The Horde Project
http://www.horde.org
https://www.facebook.com/hordeproject
https://www.twitter.com/hordeproject