[horde] Horde Activesync with Outlook 2013/2016: duplicate folders on folder creation
Michael J Rubinsky
mrubinsk at horde.org
Tue Nov 15 01:00:03 UTC 2016
Quoting Michael J Rubinsky <mrubinsk at horde.org>:
> 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.
Ok. Try this. In Horde_Core_ActiveSync_Driver::_getMailFolders(), line
3234 add a parameter true so the line looks like so:
$imap_folders = $this->_imap->getMailboxes(true);
And see if that helps. I have no idea how or why your folder tree is
loaded before this point, but it's the only logical explanation for
what I'm seeing in your logs.
> 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
--
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/20161115/ff85b9b8/attachment-0001.bin>
More information about the horde
mailing list