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

Mon Nov 14 21:12:19 UTC 2016

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.

> 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
-------------- 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/c9822519/attachment.bin>