View Issue Details

IDProjectCategoryView StatusLast Update
0004422SOGoActiveSyncpublic2018-03-15 16:02
Reportergregk@kgbconsulting.ca Assigned Toludovic  
PrioritynormalSeveritymajorReproducibilityrandom
Status resolvedResolutionfixed 
Platform[Client] Outlook 2016OSWindows 
Product Versionnightly master 
Fixed in Version4.0.1 
Summary0004422: Outlook 2016 does a full mailbox re-sync couple of times a day
Description

I have three user, all using Outlook 2016 that complain that it is happening 1 to 2 times a day. Does not seem to happen with Android or iPhone.

I verified that max_allowed_packet is set properly.

Most re-sync instances are preceeded by SOGo returning a 503 or 501. I've attached the SOGo log showing the 503 error. I have tcpdumps as well and I noticed that the same device ID had issued another request concurrent with the one that ended in 503 error.

Additional Information

Ubuntu 16.04
SOGo 3.2.10.20180225-1

TagsNo tags attached.

Activities

gregk@kgbconsulting.ca

gregk@kgbconsulting.ca

2018-03-13 16:37

reporter  

response_503_eas.log (3,905 bytes)   
Mar 09 10:36:46 sogod [31089]: |SOGo| starting method 'POST' on uri '/SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user@domain.com&DeviceId=B0F13CDE5391495C880206B4B9928870&DeviceType=WindowsOutlook15'
Mar 09 10:36:46 sogod [31089]: <0x0x55dbe6d1d140[SOGoActiveSyncDispatcher]> EAS - request for device B0F13CDE5391495C880206B4B9928870: <?xml version="1.0"?>
2018-03-09 10:36:46.067 sogod[31089] <MySQL4Channel[0x0x55dbe6860eb0] connection=0x0x55dbe6375790> SQL: SELECT * FROM sogo_cache_folder WHERE c_path = '/B0F13CDE5391495C880206B4B9928870' AND c_uid = 'user@domain.com';
2018-03-09 10:36:46.102 sogod[31089] <MySQL4Channel[0x0x55dbe6860eb0] connection=0x0x55dbe6375790>   query has results, entering fetch-mode.
2018-03-09 10:36:46.103 sogod[31089] <MySQL4Channel[0x0x55dbe6860eb0] connection=0x0x55dbe6375790> SQL: UPDATE sogo_cache_folder  SET c_lastmodified = 1520609806, c_deleted = 0,      c_version = 52785, c_content = 'NQQAABBTeW5jUmVxdWVzdCttYWlsLzQyNzc0NTI1YzJmYjJlNWE3NDc5MDAwMDI3MTgyMDhk
2018-03-09 10:36:46.130 sogod[31089] <MySQL4Channel[0x0x55dbe6860eb0] connection=0x0x55dbe6375790>   query has no results.
Mar 09 10:36:46 sogod [31089]: <0x0x55dbe8c10360[NGImap4Client]> TLS started successfully.
2018-03-09 10:36:46.622 sogod[31089] <MySQL4Channel[0x0x55dbe6860eb0] connection=0x0x55dbe6375790> SQL: SELECT * FROM sogo_cache_folder WHERE c_path = '/B0F13CDE5391495C880206B4B9928870+folder70ccc319e9bed459106d00002718208d' AND c_uid = 'user@domain.com';
2018-03-09 10:36:46.661 sogod[31089] <MySQL4Channel[0x0x55dbe6860eb0] connection=0x0x55dbe6375790>   query has results, entering fetch-mode.
Mar 09 10:36:46 sogod [31089]: <0x0x55dbe6d1d140[SOGoActiveSyncDispatcher]> EAS - processSyncCollection: no folderMetadata found: folderINBOX
2018-03-09 10:36:46.661 sogod[31089] <MySQL4Channel[0x0x55dbe6860eb0] connection=0x0x55dbe6375790> SQL: SELECT * FROM sogo_cache_folder WHERE c_path = '/B0F13CDE5391495C880206B4B9928870' AND c_uid = 'user@domain.com';
2018-03-09 10:36:46.678 sogod[31089] <MySQL4Channel[0x0x55dbe6860eb0] connection=0x0x55dbe6375790>   query has results, entering fetch-mode.
2018-03-09 10:36:46.679 sogod[31089] <MySQL4Channel[0x0x55dbe6860eb0] connection=0x0x55dbe6375790> SQL: SELECT * FROM sogo_cache_folder WHERE c_path = '/B0F13CDE5391495C880206B4B9928870' AND c_uid = 'user@domain.com';
2018-03-09 10:36:46.719 sogod[31089] <MySQL4Channel[0x0x55dbe6860eb0] connection=0x0x55dbe6375790>   query has results, entering fetch-mode.
Mar 09 10:36:46 sogod [31089]: <0x0x55dbe6d1d140[SOGoActiveSyncDispatcher]> EAS - Discard response {FolderSyncKey = "activesync01_dlcgroup_ca_77c8_20519158_3"; PingCachedFolders = ("mail%2F70ccc319e9bed459106d00002718208d", "vevent%2Fpersonal", "vcard%2Fpersonal", "mail%2F69d06038ac36d659365100002718208d", "vtodo%2Fpersonal", "mail%2F2d38473a72da2e5abf4800002718208d", "mail%2F6fdc441bab07875ab91a00002718208d"); PingHeartbeatInterval = 250; PingRequest = 30662; SyncRequest = 1520609665; "SyncRequest+mail/2d38473a72da2e5abf4800002718208d" = 30664; "SyncRequest+mail/42774525c2fb2e5a747900002718208d" = 4473; "SyncRequest+mail/68d06038ac36d659365100002718208d" = 23939; "SyncRequest+mail/69d06038ac36d659365100002718208d" = 30664; "SyncRequest+mail/6ad06038ac36d659365100002718208d" = 23939; "SyncRequest+mail/6fdc441bab07875ab91a00002718208d" = 30664; "SyncRequest+mail/70ccc319e9bed459106d00002718208d" = 30664; "SyncRequest+mail/861f511d8f25285a117e00002718208d" = 19437; "SyncRequest+mail/Shared" = 13887; "SyncRequest+vcard/personal" = 30664; "SyncRequest+vevent/personal" = 30664; "SyncRequest+vtodo/personal" = 30664; }
Mar 09 10:36:46 sogod [31089]: |SOGo| request took 0.666614 seconds to execute
Mar 09 10:36:46 sogod [31089]: 70.50.139.19 "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user@domain.com&DeviceId=B0F13CDE5391495C880206B4B9928870&DeviceType=WindowsOutlook15 HTTP/1.0" 503 0/630 0.670 - - 0
response_503_eas.log (3,905 bytes)   
gregk@kgbconsulting.ca

gregk@kgbconsulting.ca

2018-03-15 04:17

reporter   ~0012703

Another re-sync preceeded by a "EAS - Discard response" and a 503 returned to Outlook. However, the same user got 5 more "503" responses today without a re-sync.

Mar 14 17:05:36 sogod [30661]: <0x0x55dbe6c1f290[SOGoActiveSyncDispatcher]> EAS - Discard response {FolderSyncKey = "activesync_domain_ca_6dc4_20597161_1"; PingCa
chedFolders = ("mail%2Fa5e29d19dc534459b772000010c902f0", "vevent%2Fpersonal", "vcard%2Fpersonal", "mail%2Ff132a012befb78590b34000010c902f0", "mail%2Fd78ddd07060f6559
4a1200002718208d", "vtodo%2Fpersonal", "mail%2Fa13fb733122f8e59ab6a000010c902f0"); PingHeartbeatInterval = 250; PingRequest = 32497; SyncRequest = 1521061418; "SyncRe
quest+mail/Shared" = 12111; "SyncRequest+mail/a13fb733122f8e59ab6a000010c902f0" = 25901; "SyncRequest+mail/a5e29d19dc534459b772000010c902f0" = 25901; "SyncRequest+mai
l/d78ddd07060f65594a1200002718208d" = 25901; "SyncRequest+mail/f132a012befb78590b34000010c902f0" = 25901; "SyncRequest+vcard/personal" = 25901; "SyncRequest+vevent/pe
rsonal" = 25901; "SyncRequest+vtodo/personal" = 25901; }
Mar 14 17:05:36 sogod [30661]: |SOGo| request took 0.851257 seconds to execute
Mar 14 17:05:36 sogod [30661]: 68.150.85.49 "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=user@domain.com&DeviceId=30E987C782D04B7CAF0C0C6969E3EBE
7&DeviceType=WindowsOutlook15 HTTP/1.0" 503 0/618 0.852 - - 0

ludovic

ludovic

2018-03-15 11:36

administrator   ~0012709

I think I know what can cause this. I'll work on a fix so you can test a nightly build.

Related Changesets

sogo: master 982cbed7

2018-03-15 16:01:50

ludovic

Details Diff
(fix) avoid potential cache update when breaking sync queries (fixes 0004422) Affected Issues
0004422
mod - ActiveSync/SOGoActiveSyncDispatcher+Sync.m Diff File
mod - NEWS Diff File

Issue History

Date Modified Username Field Change
2018-03-13 16:37 gregk@kgbconsulting.ca New Issue
2018-03-13 16:37 gregk@kgbconsulting.ca File Added: response_503_eas.log
2018-03-15 04:17 gregk@kgbconsulting.ca Note Added: 0012703
2018-03-15 11:36 ludovic Note Added: 0012709
2018-03-15 16:02 ludovic Changeset attached => sogo master 982cbed7
2018-03-15 16:02 ludovic Assigned To => ludovic
2018-03-15 16:02 ludovic Resolution open => fixed
2018-03-15 16:02 ludovic Status new => resolved
2018-03-15 16:02 ludovic Fixed in Version => 4.0.1