[horde] Horde Activesync with Outlook 2013/2016: duplicate folders on folder creation
Hendrik Noack
hn at axxedia-it.de
Mon Nov 14 19:42:36 UTC 2016
> -----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/95c292
> >>>> 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...
2016-11-14T19:33:46+00:00 INFO: [4591] Horde_Core_ActiveSync_Driver::authenticate() attempt for hendrik
2016-11-14T20:33:46+01:00 INFO: [4591] FOLDERCREATE request received for user hendrik
2016-11-14T20:33:46+01:00 INFO: [4591] Device entry exists for BB90462ADAB445BE964429B4F6244FFD, updating userAgent, version, and supported.
2016-11-14T20:33:46+01:00 INFO: [4591] Request being handled for device: BB90462ADAB445BE964429B4F6244FFD, Supporting protocol version: 14.0, Using Horde_ActiveSync v2.37.3
2016-11-14T20:33:46+01:00 INFO: [4591] GET VARIABLES: Array
(
[Cmd] => FolderCreate
[User] => hendrik
[DeviceId] => BB90462ADAB445BE964429B4F6244FFD
[DeviceType] => WindowsOutlook15
)
2016-11-14T20:33:46+01:00 INFO: [BB90462ADAB445BE964429B4F6244FFD] Handling FOLDER[CREATE|DELETE|CHANGE] command.
2016-11-14T20:33:46+01:00 DEBUG: [4591] I <FolderHierarchy:FolderCreate>
2016-11-14T20:33:46+01:00 DEBUG: [4591] I <FolderHierarchy:SyncKey>
2016-11-14T20:33:46+01:00 DEBUG: [4591] I {582a0f63-9520-494c-b490-1320c0a80202}3
2016-11-14T20:33:46+01:00 DEBUG: [4591] I </FolderHierarchy:SyncKey>
2016-11-14T20:33:46+01:00 DEBUG: [4591] I <FolderHierarchy:ParentId>
2016-11-14T20:33:46+01:00 DEBUG: [4591] I Fa261a33a
2016-11-14T20:33:46+01:00 DEBUG: [4591] I </FolderHierarchy:ParentId>
2016-11-14T20:33:46+01:00 DEBUG: [4591] I <FolderHierarchy:DisplayName>
2016-11-14T20:33:46+01:00 DEBUG: [4591] I NewTest
2016-11-14T20:33:46+01:00 DEBUG: [4591] I </FolderHierarchy:DisplayName>
2016-11-14T20:33:46+01:00 DEBUG: [4591] I <FolderHierarchy:Type>
2016-11-14T20:33:46+01:00 DEBUG: [4591] I 12
2016-11-14T20:33:46+01:00 DEBUG: [4591] I </FolderHierarchy:Type>
2016-11-14T20:33:46+01:00 DEBUG: [4591] I </FolderHierarchy:FolderCreate>
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.
2016-11-14T20:33:46+01:00 INFO: [4591] Polling Horde_Core_ActiveSync_Driver::_getMailFolders()
2016-11-14T20:33:46+01:00 ERR:
2016-11-14T20:33:46+01:00 ERR:
2016-11-14T20:33:46+01:00 DEBUG: [4591] O <FolderHierarchy:FolderCreate>
2016-11-14T20:33:46+01:00 DEBUG: [4591] O <FolderHierarchy:Status>
2016-11-14T20:33:46+01:00 DEBUG: [4591] O 6
2016-11-14T20:33:46+01:00 DEBUG: [4591] O </FolderHierarchy:Status>
2016-11-14T20:33:46+01:00 DEBUG: [4591] O </FolderHierarchy:FolderCreate>
2016-11-14T20:33:46+01:00 INFO: [4591] Maximum memory usage for ActiveSync request: 8650752 bytes.
2016-11-14T19:33:46+00:00 INFO: [4591] Horde_Core_ActiveSync_Driver::authenticate() attempt for hendrik
2016-11-14T20:33:47+01:00 INFO: [4591] FOLDERSYNC request received for user hendrik
2016-11-14T20:33:47+01:00 INFO: [4591] Device entry exists for BB90462ADAB445BE964429B4F6244FFD, updating userAgent, version, and supported.
2016-11-14T20:33:47+01:00 INFO: [4591] Request being handled for device: BB90462ADAB445BE964429B4F6244FFD, Supporting protocol version: 14.0, Using Horde_ActiveSync v2.37.3
2016-11-14T20:33:47+01:00 INFO: [4591] GET VARIABLES: Array
(
[Cmd] => FolderSync
[User] => hendrik
[DeviceId] => BB90462ADAB445BE964429B4F6244FFD
[DeviceType] => WindowsOutlook15
)
2016-11-14T20:33:47+01:00 INFO: [4591] Handling FOLDERSYNC command.
2016-11-14T20:33:47+01:00 INFO: [4591] Checking policykey for device: BB90462ADAB445BE964429B4F6244FFD user: hendrik
2016-11-14T20:33:47+01:00 INFO: [4591] Allowing BB90462ADAB445BE964429B4F6244FFD to connect since PROVISIONING_LOOSE is true and is either non-provisionable or has broken provisioning.
2016-11-14T20:33:47+01:00 INFO: [4591] Stored key: 0
2016-11-14T20:33:47+01:00 INFO: [4591] Policykey: verified.
2016-11-14T20:33:47+01:00 DEBUG: [4591] I <FolderHierarchy:FolderSync>
2016-11-14T20:33:47+01:00 DEBUG: [4591] I <FolderHierarchy:SyncKey>
2016-11-14T20:33:47+01:00 DEBUG: [4591] I {582a0f63-9520-494c-b490-1320c0a80202}3
2016-11-14T20:33:47+01:00 DEBUG: [4591] I </FolderHierarchy:SyncKey>
2016-11-14T20:33:47+01:00 INFO: [4591] Creating new Horde_ActiveSync_SyncCache.
2016-11-14T20:33:47+01:00 INFO: [4591] Loading state for synckey {582a0f63-9520-494c-b490-1320c0a80202}3
2016-11-14T20:33:47+01:00 INFO: [4591] Loading FOLDERSYNC state containing 54 folders.
2016-11-14T20:33:47+01:00 DEBUG: [4591] I </FolderHierarchy:FolderSync>
2016-11-14T20:33:47+01:00 INFO: [4591] Initializing folder diff engine
2016-11-14T20:33:47+01:00 INFO: [4591] Horde_Core_ActiveSync_Driver::getFolderList()
2016-11-14T20:33:47+01:00 INFO: [4591] Polling Horde_Core_ActiveSync_Driver::_getMailFolders()
2016-11-14T20:33:47+01:00 INFO: [4591] Creating new folder uuid for Belege.NewTest: Fe64b6a19
2016-11-14T20:33:47+01:00 INFO: [4591] Found 3 folder changes.
2016-11-14T20:33:47+01:00 INFO: [4591] Updating state during delete
2016-11-14T20:33:47+01:00 INFO: [4591] Returning folder Belege.NewTest (Fe64b6a19 type 12) from Horde_Core_ActiveSync_Driver::getFolder()
2016-11-14T20:33:47+01:00 INFO: [4591] Updating state during foldersync
2016-11-14T20:33:47+01:00 INFO: [4591] Returning folder Belege.NewTest (Fe64b6a19 type 12) from Horde_Core_ActiveSync_Driver::getFolder()
2016-11-14T20:33:47+01:00 INFO: [4591] Updating state during delete
2016-11-14T20:33:47+01:00 DEBUG: [4591] O <FolderHierarchy:FolderSync>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O <FolderHierarchy:Status>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O 1
2016-11-14T20:33:47+01:00 DEBUG: [4591] O </FolderHierarchy:Status>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O <FolderHierarchy:SyncKey>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O {582a0f63-9520-494c-b490-1320c0a80202}4
2016-11-14T20:33:47+01:00 DEBUG: [4591] O </FolderHierarchy:SyncKey>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O <FolderHierarchy:Changes>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O <FolderHierarchy:Count>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O 3
2016-11-14T20:33:47+01:00 DEBUG: [4591] O </FolderHierarchy:Count>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O <FolderHierarchy:Add>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O <FolderHierarchy:ServerEntryId>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O Fe64b6a19
2016-11-14T20:33:47+01:00 DEBUG: [4591] O </FolderHierarchy:ServerEntryId>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O <FolderHierarchy:ParentId>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O Fa261a33a
2016-11-14T20:33:47+01:00 DEBUG: [4591] O </FolderHierarchy:ParentId>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O <FolderHierarchy:DisplayName>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O NewTest
2016-11-14T20:33:47+01:00 DEBUG: [4591] O </FolderHierarchy:DisplayName>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O <FolderHierarchy:Type>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O 12
2016-11-14T20:33:47+01:00 DEBUG: [4591] O </FolderHierarchy:Type>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O </FolderHierarchy:Add>
2016-11-14T20:33:47+01:00 INFO: [4591] Collection without id found: a:1:{s:8:"serverid";s:14:"Belege.NewTest";}
2016-11-14T20:33:47+01:00 DEBUG: [4591] O <FolderHierarchy:Remove>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O <FolderHierarchy:ServerEntryId>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O Ff47c2d9f
2016-11-14T20:33:47+01:00 DEBUG: [4591] O </FolderHierarchy:ServerEntryId>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O </FolderHierarchy:Remove>
2016-11-14T20:33:47+01:00 INFO: [4591] Removing device BB90462ADAB445BE964429B4F6244FFD state for user hendrik and collection Ff47c2d9f.
2016-11-14T20:33:47+01:00 DEBUG: [4591] O <FolderHierarchy:Remove>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O <FolderHierarchy:ServerEntryId>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O Fa864367d
2016-11-14T20:33:47+01:00 DEBUG: [4591] O </FolderHierarchy:ServerEntryId>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O </FolderHierarchy:Remove>
2016-11-14T20:33:47+01:00 INFO: [4591] Removing device BB90462ADAB445BE964429B4F6244FFD state for user hendrik and collection Fa864367d.
2016-11-14T20:33:47+01:00 DEBUG: [4591] O </FolderHierarchy:Changes>
2016-11-14T20:33:47+01:00 DEBUG: [4591] O </FolderHierarchy:FolderSync>
2016-11-14T20:33:47+01:00 INFO: [4591] Saving state: a:8:{i:0;s:39:"{582a0f63-9520-494c-b490-1320c0a80202}4";i:1;O:21:"Horde_Db_Value_Binary":1:{s:5:"value";s:7139:"a:53:{i:0;a:5:{s:2:"id";s:9:"T112cf525";s:3:"mod";s:31:"Aufgabenliste von Hendrik Noack";s:6:"parent";s:1:"0";s:8:"serverid";s:29:"Tasks:Ptgp4qb0fZnX228Tf-_4455";s:4:"type";i:7;}i:1;a:5:{s:2:"id";s:2:"RI";s:3:"mod";s:2:"RI";s:6:"parent";s:1:"0";s:8:"serverid";s:2:"RI";s:4:"type";i:19;}i:2;a:5:{s:2:"id";s:6:"OUTBOX";s:3:"mod";s:11:"Postausgang";s:
>
> --
> 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: 5735 bytes
Desc: not available
URL: <https://lists.horde.org/archives/horde/attachments/20161114/0852a6ac/attachment.bin>
More information about the horde
mailing list