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

Mon Nov 14 22:11:47 UTC 2016

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.

>> Infact I checked all the servers on which I have seen this problem,  
>> they all use
>> Mpm-prefork and also memcache.
>>
>>
>> root at haus-server:~# a2query -M
>> prefork
>> root at haus-server:~# a2query -m
>> authn_file (enabled by unknown)
>> alias (enabled by unknown)
>> env (enabled by unknown)
>> filter (enabled by maintainer script)
>> status (enabled by unknown)
>> rewrite (enabled by unknown)
>> authz_user (enabled by unknown)
>> setenvif (enabled by unknown)
>> auth_basic (enabled by unknown)
>> authn_core (enabled by maintainer script)
>> cgi (enabled by unknown)
>> authz_core (enabled by maintainer script)
>> authz_groupfile (enabled by unknown)
>> php5 (enabled by unknown)
>> reqtimeout (enabled by unknown)
>> ssl (enabled by unknown)
>> socache_shmcb (enabled by maintainer script)
>> deflate (enabled by unknown)
>> mpm_prefork (enabled by site administrator)
>> mime (enabled by unknown)
>> dir (enabled by unknown)
>> negotiation (enabled by unknown)
>> access_compat (enabled by maintainer script)
>> autoindex (enabled by unknown)
>> socache_memcache (enabled by site administrator)
>> headers (enabled by site administrator)
>> authz_host (enabled by unknown)
>
>
>
> -- 
> mike
> The Horde Project
> http://www.horde.org
> https://www.facebook.com/hordeproject
> https://www.twitter.com/hordeproject