0004422: Outlook 2016 does a full mailbox re-sync couple of times a day - SOGo | BTS

ID	Project	Category	View Status	Date Submitted	Last Update

0004422	SOGo	ActiveSync	public	2018-03-13 20:37	2018-03-15 20:02

Reporter	gregk@kgbconsulting.ca	Assigned To	ludovic
Priority	normal	Severity	major	Reproducibility	random
Status	resolved	Resolution	fixed
Platform	[Client] Outlook 2016	OS	Windows
Product Version	nightly master
Fixed in Version	4.0.1

Summary	0004422: 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
Tags	No tags attached.

gregk@kgbconsulting.ca 2018-03-13 20: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 2018-03-15 08: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 2018-03-15 15:36 administrator ~0012709	I think I know what can cause this. I'll work on a fix so you can test a nightly build.

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