[horde] Horde Activesync with Outlook 2013/2016: duplicate folders on folder creation

Mon Nov 14 22:17:40 UTC 2016

Quoting hn at axxedia-it.de:

> Zitat von Michael J Rubinsky <mrubinsk at horde.org>:
>
>> Quoting Hendrik Noack <hn at axxedia-it.de>:
>>
>>>> -----Ursprüngliche Nachricht-----
>>>> Von: horde [mailto:horde-bounces at lists.horde.org] Im Auftrag von Michael
>>>> J Rubinsky
>>>> Gesendet: Montag, 14. November 2016 21:33
>>>> An: horde at lists.horde.org
>>>> Betreff: Re: [horde] Horde Activesync with Outlook 2013/2016: duplicate
>>>> folders on folder creation
>>>>
>>>>
>>>> Quoting Hendrik Noack <hn at axxedia-it.de>:
>>>>
>>>>>> -----Ursprüngliche Nachricht-----
>>>>>> Von: horde [mailto:horde-bounces at lists.horde.org] Im Auftrag von
>>>>>> Michael J Rubinsky
>>>>>> Gesendet: Montag, 14. November 2016 19:39
>>>>>> An: horde at lists.horde.org
>>>>>> Betreff: Re: [horde] Horde Activesync with Outlook 2013/2016:
>>>>>> duplicate folders on folder creation
>>>>>>
>>>>>>
>>>>>> Quoting Michael J Rubinsky <mrubinsk at horde.org>:
>>>>>>
>>>>>>> Quoting Hendrik Noack <hn at axxedia-it.de>:
>>>>>>>
>>>>>>>>> -----Ursprüngliche Nachricht-----
>>>>>>>>> Von: horde [mailto:horde-bounces at lists.horde.org] Im Auftrag von
>>>>>>>>> Michael J Rubinsky
>>>>>>>>> Gesendet: Montag, 14. November 2016 14:56
>>>>>>>>> An: horde at lists.horde.org
>>>>>>>>> Betreff: Re: [horde] Horde Activesync with Outlook 2013/2016:
>>>>>>>>> duplicate folders on folder creation
>>>>>>>>>
>>>>>>>>>
>>>>>>>>> Quoting Hendrik Noack <hn at axxedia-it.de>:
>>>>>>>>>
>>>>>>>>>> -----Ursprüngliche Nachricht----- Quoting Hendrik Noack <hn at
>>>>>>>>>> axxedia-it.de>:
>>>>>>>>>>
>>>>>>>>>>> Hello everbody,
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> I did not find anything on the internet on that topic, so I
>>>>>>>>>>> hope maybe someone has seen this behaviour before.
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> We are using Debian 8 with Dovecot, Exim and Horde on top. The
>>>>>>>>>>> Horde installation is up to date. Our clients are using Outlook
>>>>>>>>>>> 2013/2016 to connect via Horde activesync.
>>>>>>>>>>>
>>>>>>>>>>> We also have a bunch of iOS and Android devices.
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> It’s not always happening, but too often to be just a rare bug.
>>>>>>>>>>> When an Outlook client creates a new mail folder, the folder is
>>>>>>>>>>> created, then a
>>>>>>>>>> sync
>>>>>>>>>>> against horde is started and the very same folder is
>>>>>>>>>>> immediately sync‘ed back as another new folder. The client now
>>>>>>>>>>> has: folder and folder [1] in
>>>>>>>>>> the
>>>>>>>>>>> database. Right after the appearances of the duplicate folder a
>>>>>>>>>>> new sync
>>>>>>>>>> is
>>>>>>>>>>> started that clears out all mails, contacts and appointments
>>>>>>>>>>> from that client, so that Outlook appears to be empty. A reset
>>>>>>>>>>> in activesync for
>>>>>>>>>> that
>>>>>>>>>>> client on the server side does not clear this problem, I have
>>>>>>>>>>> to delete
>>>>>>>>>> the
>>>>>>>>>>> local .ost cache for that client. The next sync will then bring
>>>>>>>>>>> back all mails, contacts and appointment. The duplicate folder
>>>>>>>>>>> is also gone, as it was never duplicated on the server side.
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> Creating a folder in IMP always works as it should, I have
>>>>>>>>>>> never seen duplicates in Outlook when I created the folder in IMP.
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> My guess is, that there must be something going terribly wrong
>>>>>>>>>>> sometimes when Outlook tries to create a new folder via
>>>> activesync.
>>>>>>>>>>> Or maybe this a problem with my Dovecot configuraiton, but like
>>>>>>>>>>> I said, the duplicates
>>>>>>>>>> never
>>>>>>>>>>> reach the server.
>>>>>>>>>>
>>>>>>>>>> Please provide a sync log for further assistance.
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>> Any ideas would be much appreciated.
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> Mit freundlichen Grüßen / Best regards
>>>>>>>>>>>
>>>>>>>>>>> Hendrik Noack
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> --
>>>>>>>>>>> Axxedia IT GmbH
>>>>>>>>>>>
>>>>>>>>>>> Schwabstr. 30
>>>>>>>>>>> 71106 Magstadt
>>>>>>>>>>>
>>>>>>>>>>> Tel +49 7159 4979763
>>>>>>>>>>> Fax +49 7159 4979775
>>>>>>>>>>>
>>>>>>>>>>> Mail hn at axxedia-it.de <mailto:hn at axxedia-it.de>
>>>>>>>>>>>
>>>>>>>>>>> Sitz der Gesellschaft: Schwabstr. 30, 71106 Magstadt
>>>>>>>>>>> Geschäftsführer: Hendrik Noack . Amtsgericht: Stuttgart HRB
>>>>>>>>>>> 727296
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> --
>>>>>>>>>> mike
>>>>>>>>>> The Horde Project
>>>>>>>>>> http://www.horde.org
>>>>>>>>>> https://www.facebook.com/hordeproject
>>>>>>>>>> https://www.twitter.com/hordeproject
>>>>>>>>>> -------------- next part -------------- A non-text attachment
>>>>>>>>>> was scrubbed...
>>>>>>>>>> Name: smime.p7s
>>>>>>>>>> Type: application/pkcs7-signature
>>>>>>>>>> Size: 2007 bytes
>>>>>>>>>> Desc: S/MIME Signature
>>>>>>>>>> URL:
>>>>>>>>>> <https://lists.horde.org/archives/horde/attachments/20161111/95c
>>>>>>>>>> 292
>>>>>>>>>> 17/
>>>>>>>>>> attach
>>>>>>>>>> ment.bin>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> Hi Mike,
>>>>>>>>>>
>>>>>>>>>> your help is always appreciated. Murphy's law is a bi***, I had
>>>>>>>>>> to bother a few people until it was my private Outlook  that did
>>>>>>>>>> me a favor and created a duplicate folder (got a small horde
>>>>>>>>>> install with dovecot and exim in my basement too, just for fun).
>>>>>>>>>>
>>>>>>>>>> The log file is pretty big, so I decided to put it into my owncloud.
>>>>>>>>>> https://www.schwabstrasse.me/owncloud/s/Uk5Dn7x0YWuftT4
>>>>>>>>>
>>>>>>>>> File Not Found.
>>>>>>>>
>>>>>>>> Ouch, you are right. Here we go:
>>>>>>>> https://www.schwabstrasse.me/owncloud/s/MUjejC0cNY8aaDS
>>>>>>>>
>>>>>>>> I set the expiration date too soon.
>>>>>>>>
>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>> I created a subfolder Test in Belege. Search for "Belege.Test"
>>>>>>>>>>
>>>>>>>>>> Btw my private Outlook client is not using Active Directory
>>>>>>>>>> authentication via pam, but pam is used for local
>>>>>>>>>> authentication, and I still don't think it's related to
>>>>>>>>>> authentication, but
>>>>>> who knows...
>>>>>>>
>>>>>>> There seems to be something wrong on your system with creating the
>>>>>>> new ActiveSync UID for the new mail folder. Normally, this is what
>>>>>>> the log would show when creating a new folder:
>>>>>>>
>>>>>>> 2016-11-14T17:07:42+00:00 INFO: [10032]
>>>>>>> Horde_ActiveSync_Connector_Importer::importFolderChange(,
>>>> NewTest,
>>>>>>> F956400b5, 12)
>>>>>>> 2016-11-14T17:07:42+00:00 INFO: [10032]
>>>>>>> Horde_Core_ActiveSync_Driver::changeFolder(, NewTest, test, , 12)
>>>>>>> 2016-11-14T17:07:43+00:00 INFO: [10032] Polling
>>>>>>> Horde_Core_ActiveSync_Driver::_getMailFolders()
>>>>>>> 2016-11-14T17:07:43+00:00 INFO: [10032] Creating new folder uuid
>>>>>>> for
>>>>>>> test/NewTest: Fb9f3cfda
>>>>>>> 2016-11-14T17:07:43+00:00 INFO: [10032] Updating state during
>>>>>>> change
>>>>>>> 2016-11-14T17:07:43+00:00 INFO: [10032] Collection without id found:
>>>>>>> a:1:{s:8:"serverid";s:12:"test/NewTest";}
>>>>>>> 2016-11-14T17:07:43+00:00 INFO: [10032] Updating serverid in folder
>>>>>>> state. Setting test/NewTest for Fb9f3cfda.
>>>>>>>
>>>>>>> Notice the line about "Creating new folder uuid...". In your log,
>>>>>>> this doesn't happen so we can't send the new UUID to the client,
>>>>>>> and it's not "attached" to the new server-side folder:
>>>>>>>
>>>>>>> 2016-11-11T15:14:47+01:00 INFO: [10222]
>>>>>>> Horde_ActiveSync_Connector_Importer::importFolderChange(, Test,
>>>>>>> F9fe7ff65, 12)
>>>>>>> 2016-11-11T15:14:47+01:00 INFO: [10222]
>>>>>>> Horde_Core_ActiveSync_Driver::changeFolder(, Test, Belege, , 12)
>>>>>>> 2016-11-11T15:14:47+01:00 INFO: [10222] Polling
>>>>>>> Horde_Core_ActiveSync_Driver::_getMailFolders()
>>>>>>> 2016-11-11T15:14:47+01:00 INFO: [10222] Updating state during
>>>>>>> change
>>>>>>> 2016-11-11T15:14:47+01:00 INFO: [10222] Collection without id found:
>>>>>>> a:1:{s:8:"serverid";s:0:"";}
>>>>>>> 2016-11-11T15:14:47+01:00 INFO: [10222] Updating serverid in folder
>>>>>>> state. Setting  for .
>>>>>>>
>>>>>>> However, when the next FOLDERSYNC is done, it notices the new
>>>>>>> folder, and since the uuid create failed earlier, it is sent to the
>>>>>>> client as a NEW folder. As to WHY your installation is behaving
>>>>>>> this way, I don't know. I can't reproduce this locally on any of my
>>>>>>> test systems and test clients - including Outlook. I will try to
>>>>>>> find some places to add some more useful logging to see if we can
>>>>>>> track down the reason. What version of Horde_Core is on your system?
>>>>>>
>>>>>> Try updating to the just released Horde_Core package. See if it
>>>>>> helps, or at least gives us a better idea of what is happening.
>>>>>
>>>>> Sync is done and I created a new folder NewTest. It instantly
>>>>> duplicated the folder again.
>>>>> I see two new lines in the log with ERR: but they are empty afterwards...
>>>>
>>>>
>>>> The blank message was from a typo, but that's fine, because I know
>>>> where it's failing for you now at least - though I don't know why.
>>>> Also, your log has a weird entry in it:
>>>>
>>>>
>>>> 2016-11-14T20:33:46+01:00 INFO: [4591] Creating new
>>>> Horde_ActiveSync_SyncCache.
>>>> 2016-11-14T20:33:46+01:00 INFO: [4591] Loading state for synckey
>>>> {582a0f63-9520-494c-b490-1320c0a80202}3
>>>> 2016-11-14T20:33:46+01:00 INFO: [4591] Loading FOLDERSYNC state
>>>> containing 54 folders.
>>>> 2016-11-14T20:33:46+01:00 INFO: [4591]
>>>> Horde_ActiveSync_Connector_Importer::importFolderChange(, NewTest,
>>>> Fa261a33a, 12)
>>>> 2016-11-14T20:33:46+01:00 INFO: [4591]
>>>> Horde_Core_ActiveSync_Driver::changeFolder(, NewTest, Belege, , 12)
>>>> 2016-11-14T20:33:46+01:00 INFO: [4591] New IMAP folder created:
>>>> Belege.NewTest
>>>> 2016-11-14T20:33:46+01:00 INFO: [4591] Device entry exists for
>>>> BB90462ADAB445BE964429B4F6244FFD, updating userAgent, version, and
>>>> supported.
>>>>
>>>> ^^^ This entry is from code that saves device properties and happens
>>>> much earlier in the request. In fact, your log shows it happening in
>>>> the correct place also. There is absolutely no code path that would
>>>> trigger this portion of the code to run immediately after the IMAP
>>>> folder was created.
>>>>
>>>> The issue in your setup for some reason is the folder list doesn't
>>>> return the new folder when it should. Probably returning a cached
>>>> version of it, but what's curious is that the folder list should not
>>>> have been loaded at that point in the request yet, so it shouldn't
>>>> have been cached.
>>>>
>>>> You're not running apache mpm-worker with mod_php by any chance are
>>>> you?
>>>
>>> No I'm not running mpm-worker, but I'm using memcache for my owncloud.
>>
>> I have no idea what's causing this then. At the very least, we now  
>> send back an appropriate error code to the client to indicate there  
>> was a problem. However, Outlook seems to be ignoring it and keeping  
>> the newly created folder in the UI. I'll keep looking, but I'm  
>> running out of ideas.
>>
>
> I'm fighting this problem for a while now. For some clients it's ok to just
> clear the .ost file and do a complete sync to get rid of the  
> duplicates for a while, for others
> it doesn't work at all (like my private Outlook client).
>
> If you need anything else, config files for apache, php, dovecot or  
> whatever helps to find the issue here,
> I will gladly offer them to you.

You are using sql for $conf[activesync][storage], right?

-- 
mike
The Horde Project
http://www.horde.org
https://www.facebook.com/hordeproject
https://www.twitter.com/hordeproject
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 2007 bytes
Desc: S/MIME Signature
URL: <https://lists.horde.org/archives/horde/attachments/20161114/21213e28/attachment.bin>