0003606: SOGoActiveSyncDispatcher does not re-initiate Ping loop - SOGo

ID	Project	Category	View Status	Date Submitted	Last Update

0003606	SOGo	ActiveSync	public	2016-03-29 13:11	2016-04-01 18:57

Reporter	m_emelchenkov	Assigned To	ludovic
Priority	normal	Severity	minor	Reproducibility	always
Status	resolved	Resolution	fixed
Platform	iPhone	OS	iOS	OS Version	8.4.1
Product Version	nightly v2
Fixed in Version	3.1.0

Summary	0003606: SOGoActiveSyncDispatcher does not re-initiate Ping loop
Description	5 seconds interval and 0000015:0000006 minutes timeout — its OK, as configured. At 16:00:44 timeout ended, ping terminated, OK. At 16:00:46 client disconnected because sogod timeout, OK. At 16:00:46 sogod receive Ping from iOS. And then nothing, no new logs. It seems sogod does not re-initiate connection. It starts checking changes again only at 16:04:08. I am not quite sure how ActiveSync protocol should work but this situation does not look right to me. Correct me if I am wrong. Mar 29 15:59:39 sogod [23518]: <0x0x7fe27367fc18[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 15:59:44 sogod [23516]: [WARN] <0x0x7fe27335d768[WOWatchDogChild]> pid 23518 has been hanging in the same request for 5 minutes Mar 29 15:59:44 sogod [23518]: <0x0x7fe27367fc18[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 15:59:49 sogod [23518]: <0x0x7fe27367fc18[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 15:59:55 sogod [23518]: <0x0x7fe27367fc18[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 16:00:00 sogod [23518]: <0x0x7fe27367fc18[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 16:00:05 sogod [23518]: <0x0x7fe27367fc18[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 16:00:10 sogod [23518]: <0x0x7fe27367fc18[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 16:00:15 sogod [23519]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/Calendar/ HTTP/1.1" 401 0/2217 0.010 - - 8K Mar 29 16:00:15 sogod [23519]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/Calendar/ HTTP/1.1" 207 1442/2217 0.015 10044 85% 104K Mar 29 16:00:15 sogod [23518]: <0x0x7fe27367fc18[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 16:00:15 sogod [23519]: 127.0.0.1 "PROPPATCH /SOGo/dav/user@domain/Calendar/ HTTP/1.1" 403 250/422 0.001 - - 0 Mar 29 16:00:15 sogod [23519]: 127.0.0.1 "PROPPATCH /SOGo/dav/user@domain/Calendar/ HTTP/1.1" 403 254/430 0.001 - - 0 Mar 29 16:00:16 sogod [23519]: 127.0.0.1 "REPORT /SOGo/dav/user@domain/ HTTP/1.1" 401 0/768 0.001 - - 0 Mar 29 16:00:16 sogod [23519]: 127.0.0.1 "REPORT /SOGo/dav/user@domain/ HTTP/1.1" 207 397/768 0.002 - - 4K Mar 29 16:00:20 sogod [23518]: <0x0x7fe27367fc18[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 16:00:26 sogod [23518]: <0x0x7fe27367fc18[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 16:00:31 sogod [23518]: <0x0x7fe27367fc18[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 16:00:36 sogod [23518]: <0x0x7fe27367fc18[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 16:00:41 sogod [23518]: <0x0x7fe27367fc18[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 16:00:44 sogod [23516]: [WARN] <0x0x7fe27335d768[WOWatchDogChild]> pid 23518 has been hanging in the same request for 6 minutes Mar 29 16:00:46 sogod [23518]: [ERROR] <0x0x7fe27365a488[WOHttpTransaction]> client disconnected during delivery of response for <WORequest[0x0x7fe2734ad508]: method=POST uri=/SOGo/Microsoft-Server-ActiveSync?User=user@domain&DeviceId=12345&DeviceType=iPhone&Cmd=Ping app=SOGo rqKey=Microsoft-Server-ActiveSync rqPath=(null)> (len=20): the socket was shutdown Mar 29 16:00:46 sogod [23518]: localhost.localdomain "POST /SOGo/Microsoft-Server-ActiveSync?User=user@domain&DeviceId=12345&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200 20/194 362.087 - - 2M Mar 29 16:04:08 sogod [23518]: <0x0x7fe2735f1618[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 16:04:13 sogod [23518]: <0x0x7fe2735f1618[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 16:04:18 sogod [23518]: <0x0x7fe2735f1618[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 16:04:24 sogod [23518]: <0x0x7fe2735f1618[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping...
Tags	No tags attached.

tfu 2016-03-29 15:52 reporter ~0009884	You can better analyze the traffic with SOGoEASDebugEnabled = YES.

m_emelchenkov 2016-03-29 20:30 reporter	Log.txt (34,453 bytes) Mar 29 23:05:32 sogod [28354]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/Contacts/ HTTP/1.1" 207 645/717 0.008 2734 76% 0 Mar 29 23:05:32 sogod [28354]: 127.0.0.1 "PROPPATCH /SOGo/dav/user@domain/Contacts/ HTTP/1.1" 403 232/298 0.002 - - 0 Mar 29 23:05:33 sogod [28354]: 127.0.0.1 "REPORT /SOGo/dav/user@domain/Contacts/personal/ HTTP/1.1" 207 125/210 0.006 - - 0 Mar 29 23:05:34 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> EAS - request for device 12345: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <Ping xmlns="Ping:"> <HeartbeatInterval>600</HeartbeatInterval> <Folders> <Folder> <Id>mail%2F9d224603ff6be456110800004fca1e17</Id> <Class>Email</Class> </Folder> <Folder> <Id>mail%2F9c224603ff6be456110800004fca1e17</Id> <Class>Email</Class> </Folder> <Folder> <Id>vcard%2Fpersonal</Id> <Class>Contacts</Class> </Folder> <Folder> <Id>vevent%2Fpersonal</Id> <Class>Calendar</Class> </Folder> </Folders> </Ping> Mar 29 23:05:35 sogod [28354]: [WARN] <0x0x7fad5a60f7a8[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table Mar 29 23:05:35 sogod [28354]: [WARN] <0x0x7fad5a60f7a8[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table Mar 29 23:05:35 sogod [28354]: [WARN] <0x0x7fad5a60f7a8[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table Mar 29 23:05:35 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:05:40 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:05:45 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:05:50 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:05:55 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:06:01 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:06:06 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:06:11 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:06:16 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:06:21 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:06:26 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:06:32 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:06:34 sogod [28352]: [WARN] <0x0x7fad5a0f78d8[WOWatchDogChild]> pid 28354 has been hanging in the same request for 1 minutes Mar 29 23:06:37 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:06:42 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:06:47 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:06:52 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:06:57 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:07:03 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:07:08 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:07:13 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:07:18 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:07:23 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:07:28 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:07:34 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:07:34 sogod [28352]: [WARN] <0x0x7fad5a0f78d8[WOWatchDogChild]> pid 28354 has been hanging in the same request for 2 minutes Mar 29 23:07:39 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:07:44 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:07:49 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:07:54 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:07:59 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:08:05 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:08:10 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:08:15 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:08:20 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:08:25 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:08:30 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:08:34 sogod [28352]: [WARN] <0x0x7fad5a0f78d8[WOWatchDogChild]> pid 28354 has been hanging in the same request for 3 minutes Mar 29 23:08:36 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:08:41 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:08:46 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:08:51 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:08:56 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:09:01 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:09:07 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:09:12 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:09:17 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:09:22 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:09:27 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:09:32 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:09:34 sogod [28352]: [WARN] <0x0x7fad5a0f78d8[WOWatchDogChild]> pid 28354 has been hanging in the same request for 4 minutes Mar 29 23:09:38 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:09:43 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:09:48 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:09:50 sogod [28355]: <0x0x7fad5a363228[SOGoCache]> Cache cleanup interval set every 300.000000 seconds Mar 29 23:09:50 sogod [28355]: <0x0x7fad5a363228[SOGoCache]> Using host(s) 'localhost' as server(s) Mar 29 23:09:50 sogod [28355]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/Calendar/ HTTP/1.1" 401 0/2217 0.002 - - 912K Mar 29 23:09:50 sogod [28355]: [WARN] <0x0x7fad5a3c2988[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table Mar 29 23:09:50 sogod [28355]: [WARN] <0x0x7fad5a3c2988[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table Mar 29 23:09:50 sogod [28355]: [WARN] <0x0x7fad5a3c2988[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table Mar 29 23:09:50 sogod [28355]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/Calendar/ HTTP/1.1" 207 1442/2217 0.040 10044 85% 2M Mar 29 23:09:51 sogod [28355]: 127.0.0.1 "PROPPATCH /SOGo/dav/user@domain/Calendar/ HTTP/1.1" 403 250/422 0.002 - - 20K Mar 29 23:09:51 sogod [28355]: 127.0.0.1 "PROPPATCH /SOGo/dav/user@domain/Calendar/ HTTP/1.1" 403 254/430 0.001 - - 0 Mar 29 23:09:53 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:09:58 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:10:03 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:10:09 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:10:14 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:10:19 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:10:24 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:10:29 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:10:34 sogod [28352]: [WARN] <0x0x7fad5a0f78d8[WOWatchDogChild]> pid 28354 has been hanging in the same request for 5 minutes Mar 29 23:10:34 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:10:40 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:10:45 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:10:50 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:10:55 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:11:00 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:11:05 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:11:11 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:11:16 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:11:21 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:11:26 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:11:31 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:11:34 sogod [28352]: [WARN] <0x0x7fad5a0f78d8[WOWatchDogChild]> pid 28354 has been hanging in the same request for 6 minutes Mar 29 23:11:36 sogod [28354]: <0x0x7fad5a3a8858[SOGoActiveSyncDispatcher]> EAS - response for device 12345: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <Ping xmlns="Ping:"> <Status>5</Status> <HeartbeatInterval>354</HeartbeatInterval> </Ping> Mar 29 23:11:36 sogod [28354]: [ERROR] <0x0x7fad5a45ba08[WOHttpTransaction]> client disconnected during delivery of response for <WORequest[0x0x7fad5a493ca8]: method=POST uri=/SOGo/Microsoft-Server-ActiveSync?User=user@domain&DeviceId=12345&DeviceType=iPhone&Cmd=Ping app=SOGo rqKey=Microsoft-Server-ActiveSync rqPath=(null)> (len=20): the socket was shutdown Mar 29 23:11:36 sogod [28354]: localhost.localdomain "POST /SOGo/Microsoft-Server-ActiveSync?User=user@domain&DeviceId=12345&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200 20/194 362.033 - - 1M Mar 29 23:12:25 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> EAS - request for device 12345: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <Ping xmlns="Ping:"> <HeartbeatInterval>600</HeartbeatInterval> <Folders> <Folder> <Id>mail%2F9d224603ff6be456110800004fca1e17</Id> <Class>Email</Class> </Folder> <Folder> <Id>mail%2F9c224603ff6be456110800004fca1e17</Id> <Class>Email</Class> </Folder> <Folder> <Id>vcard%2Fpersonal</Id> <Class>Contacts</Class> </Folder> <Folder> <Id>vevent%2Fpersonal</Id> <Class>Calendar</Class> </Folder> </Folders> </Ping> Mar 29 23:12:25 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:12:30 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:12:36 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:12:41 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:12:46 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:12:51 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:12:56 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:13:01 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:13:07 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:13:12 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:13:17 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:13:22 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:13:25 sogod [28352]: [WARN] <0x0x7fad5a0f78d8[WOWatchDogChild]> pid 28354 has been hanging in the same request for 1 minutes Mar 29 23:13:27 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:13:32 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:13:38 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:13:43 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:13:48 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:13:53 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:13:58 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:14:03 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:14:09 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:14:14 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:14:19 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:14:24 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:14:25 sogod [28352]: [WARN] <0x0x7fad5a0f78d8[WOWatchDogChild]> pid 28354 has been hanging in the same request for 2 minutes Mar 29 23:14:29 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:14:34 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:14:40 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:14:45 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:14:50 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:14:55 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:15:00 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:15:05 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:15:11 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:15:16 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:15:21 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:15:25 sogod [28352]: [WARN] <0x0x7fad5a0f78d8[WOWatchDogChild]> pid 28354 has been hanging in the same request for 3 minutes Mar 29 23:15:26 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:15:31 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:15:36 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:15:42 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:15:47 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:15:50 sogod [28355]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/Calendar/ HTTP/1.1" 401 0/2217 0.001 - - 0 Mar 29 23:15:51 sogod [28355]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/Calendar/ HTTP/1.1" 207 1442/2217 0.025 10044 85% 44K Mar 29 23:15:51 sogod [28355]: 127.0.0.1 "PROPPATCH /SOGo/dav/user@domain/Calendar/ HTTP/1.1" 403 250/422 0.001 - - 0 Mar 29 23:15:51 sogod [28355]: 127.0.0.1 "PROPPATCH /SOGo/dav/user@domain/Calendar/ HTTP/1.1" 403 254/430 0.001 - - 0 Mar 29 23:15:52 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:15:57 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:16:02 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:16:07 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:16:13 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:16:18 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:16:23 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:16:25 sogod [28352]: [WARN] <0x0x7fad5a0f78d8[WOWatchDogChild]> pid 28354 has been hanging in the same request for 4 minutes Mar 29 23:16:28 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:16:33 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:16:38 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:16:44 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:16:49 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:16:54 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:16:59 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:17:04 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:17:09 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:17:15 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:17:20 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:17:25 sogod [28352]: [WARN] <0x0x7fad5a0f78d8[WOWatchDogChild]> pid 28354 has been hanging in the same request for 5 minutes Mar 29 23:17:25 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:17:30 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:17:35 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:17:40 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:17:46 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:17:51 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:17:56 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:18:01 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:18:06 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:18:11 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:18:17 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:18:22 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:18:25 sogod [28352]: [WARN] <0x0x7fad5a0f78d8[WOWatchDogChild]> pid 28354 has been hanging in the same request for 6 minutes Mar 29 23:18:27 sogod [28354]: <0x0x7fad5a3ba218[SOGoActiveSyncDispatcher]> EAS - response for device 12345: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <Ping xmlns="Ping:"> <Status>5</Status> <HeartbeatInterval>354</HeartbeatInterval> </Ping> Mar 29 23:18:27 sogod [28354]: [ERROR] <0x0x7fad5a45ba08[WOHttpTransaction]> client disconnected during delivery of response for <WORequest[0x0x7fad5a3ab3e8]: method=POST uri=/SOGo/Microsoft-Server-ActiveSync?User=user@domain&DeviceId=12345&DeviceType=iPhone&Cmd=Ping app=SOGo rqKey=Microsoft-Server-ActiveSync rqPath=(null)> (len=20): the socket was shutdown Mar 29 23:18:27 sogod [28354]: localhost.localdomain "POST /SOGo/Microsoft-Server-ActiveSync?User=user@domain&DeviceId=12345&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200 20/194 362.062 - - 56K Mar 29 23:21:50 sogod [28354]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/Calendar/ HTTP/1.1" 401 0/2217 0.003 - - 56K Mar 29 23:21:50 sogod [28354]: 127.0.0.1 "PROPFIND /SOGo/dav/user@domain/Calendar/ HTTP/1.1" 207 1442/2217 0.024 10044 85% 192K Mar 29 23:21:50 sogod [28354]: 127.0.0.1 "PROPPATCH /SOGo/dav/user@domain/Calendar/ HTTP/1.1" 403 250/422 0.001 - - 4K Mar 29 23:21:50 sogod [28354]: 127.0.0.1 "PROPPATCH /SOGo/dav/user@domain/Calendar/ HTTP/1.1" 403 254/430 0.001 - - 0 Mar 29 23:21:56 sogod [28354]: <0x0x7fad5a247b98[SOGoActiveSyncDispatcher]> EAS - request for device 12345: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <Ping xmlns="Ping:"> <HeartbeatInterval>600</HeartbeatInterval> <Folders> <Folder> <Id>mail%2F9d224603ff6be456110800004fca1e17</Id> <Class>Email</Class> </Folder> <Folder> <Id>mail%2F9c224603ff6be456110800004fca1e17</Id> <Class>Email</Class> </Folder> <Folder> <Id>vcard%2Fpersonal</Id> <Class>Contacts</Class> </Folder> <Folder> <Id>vevent%2Fpersonal</Id> <Class>Calendar</Class> </Folder> </Folders> </Ping> Mar 29 23:21:56 sogod [28354]: <0x0x7fad5a247b98[SOGoActiveSyncDispatcher]> Change detected using Ping, we let the EAS client know to send a Sync. Mar 29 23:21:56 sogod [28354]: <0x0x7fad5a247b98[SOGoActiveSyncDispatcher]> EAS - response for device 12345: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <Ping xmlns="Ping:"> <Status>2</Status> <Folders> <Folder>mail%2F9c224603ff6be456110800004fca1e17</Folder> </Folders> </Ping> Mar 29 23:21:56 sogod [28354]: localhost.localdomain "POST /SOGo/Microsoft-Server-ActiveSync?User=user@domain&DeviceId=12345&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200 58/194 0.436 - - 4K Mar 29 23:22:41 sogod [28354]: <0x0x7fad5a4cc738[SOGoActiveSyncDispatcher]> EAS - request for device 12345: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <Sync xmlns="AirSync:"> <Collections> <Collection> <SyncKey>473-1289</SyncKey> <CollectionId>mail%2F9c224603ff6be456110800004fca1e17</CollectionId> <GetChanges/> <WindowSize>25</WindowSize> <Options> <FilterType>5</FilterType> <MIMETruncation>1</MIMETruncation> <MIMESupport>0</MIMESupport> <BodyPreference xmlns="AirSyncBase:"> <Type>1</Type> <TruncationSize>500</TruncationSize> </BodyPreference> </Options> </Collection> </Collections> </Sync> Mar 29 23:22:41 sogod [28354]: <0x0x7fad5a40a748[NGImap4Client]> Note: no key found for sorting, using 'DATE': (null) Mar 29 23:22:41 sogod [28354]: <0x0x7fad5a4cc738[SOGoActiveSyncDispatcher]> EAS - sortedBySequence (321) - lastObject: 471-1286 Mar 29 23:22:41 sogod [28354]: <0x0x7fad5a4cc738[SOGoActiveSyncDispatcher]> EAS - allCacheObjects (2) - lastObject: 473-<null> Mar 29 23:22:41 sogod [28354]: <0x0x7fad5a4cc738[SOGoActiveSyncDispatcher]> EAS - found in cache: 0 k = 0 Mar 29 23:22:41 sogod [28354]: <0x0x7fad5a4cc738[SOGoActiveSyncDispatcher]> EAS - Dealing with cacheObject: 472-<null> Mar 29 23:22:41 sogod [28354]: <0x0x7fad5a4cc738[SOGoActiveSyncDispatcher]> EAS - ADD! Mar 29 23:22:41 sogod [28354]: <0x0x7fad5a4cc738[SOGoActiveSyncDispatcher]> EAS - skipping old deleted UID: 472 Mar 29 23:22:41 sogod [28354]: <0x0x7fad5a4cc738[SOGoActiveSyncDispatcher]> EAS - Dealing with cacheObject: 473-<null> Mar 29 23:22:41 sogod [28354]: <0x0x7fad5a4cc738[SOGoActiveSyncDispatcher]> EAS - ADD! Mar 29 23:22:41 sogod [28354]: <0x0x7fad5a4cc738[SOGoActiveSyncDispatcher]> EAS - skipping old deleted UID: 473 Mar 29 23:22:41 sogod [28354]: <0x0x7fad5a4cc738[SOGoActiveSyncDispatcher]> Change detected during Sync, we push the content. Mar 29 23:22:41 sogod [28354]: <0x0x7fad5a4cc738[SOGoActiveSyncDispatcher]> EAS - response for device 12345: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <Sync xmlns="AirSync:"> <Collections> <Collection> <Class>Email</Class> <SyncKey>474-1292</SyncKey> <CollectionId>mail%2F9c224603ff6be456110800004fca1e17</CollectionId> <Status>1</Status> </Collection> </Collections> </Sync> Mar 29 23:22:41 sogod [28354]: localhost.localdomain "POST /SOGo/Microsoft-Server-ActiveSync?User=user@domain&DeviceId=12345&DeviceType=iPhone&Cmd=Sync HTTP/1.1" 200 79/105 0.593 - - 108K Mar 29 23:22:42 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> EAS - request for device 12345: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <Ping xmlns="Ping:"> <Folders> <Folder> <Id>mail%2F9d224603ff6be456110800004fca1e17</Id> <Class>Email</Class> </Folder> <Folder> <Id>mail%2F9c224603ff6be456110800004fca1e17</Id> <Class>Email</Class> </Folder> <Folder> <Id>vcard%2Fpersonal</Id> <Class>Contacts</Class> </Folder> <Folder> <Id>vevent%2Fpersonal</Id> <Class>Calendar</Class> </Folder> </Folders> </Ping> Mar 29 23:22:43 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:22:48 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:22:53 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:22:58 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:23:04 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:23:09 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:23:14 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:23:19 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:23:24 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:23:29 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:23:35 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:23:40 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:23:42 sogod [28352]: [WARN] <0x0x7fad5a0f78d8[WOWatchDogChild]> pid 28354 has been hanging in the same request for 1 minutes Mar 29 23:23:45 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:23:50 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:23:55 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:24:00 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:24:06 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:24:11 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:24:16 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:24:21 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:24:26 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:24:31 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:24:37 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:24:42 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:24:42 sogod [28352]: [WARN] <0x0x7fad5a0f78d8[WOWatchDogChild]> pid 28354 has been hanging in the same request for 2 minutes Mar 29 23:24:47 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:24:52 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:24:57 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:25:02 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 29 23:25:08 sogod [28354]: <0x0x7fad5a5139f8[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Log.txt (34,453 bytes)

m_emelchenkov 2016-03-29 20:30 reporter ~0009888	Please look at log with debug enabled. I started SOGo and waited until it receives Ping request from iPhone (time 23:05:34). Then it reconnected with 1 minute delay (time 23:11:36, 23:11:36 and 23:12:25). But the second reconnect was worser: 23:18:27, 23:18:27 and 23:21:56 -- 3.5 minute delay. In these delays I do not receive messages because SOGoActiveSyncDispatcher do not do anything.

tfu 2016-03-30 10:52 reporter ~0009893	Try to increase proxy_read_timeout and check whether error "...client disconnected during delivery of response... " is still there after the change.

m_emelchenkov 2016-03-30 11:02 reporter ~0009894	It was already configured more than SOGO maximum ping time. Yesterday chnaged all values to 59 min and 3700 for proxy timeout, the issue still exists.

tfu 2016-03-30 12:14 reporter ~0009898	When you say "the issue still exists" do you mean the error message is still there? The message Mar 29 16:00:46 sogod [23518]: [ERROR] <0x0x7fe27365a488[WOHttpTransaction]> client disconnected during delivery of response for <WORequest[0x0x7fe2734ad508] normally means that the other side (client/proxy) stopped reading before sogo was able to deliver the response. In case of the logfile you uploaded it happened after 362 secs.

m_emelchenkov 2016-03-30 12:18 reporter ~0009899	362 was max pin time, 370 or even 380 was prozy time. Iphone max ping time is 600. It is not client broke the channel, its sogo.

m_emelchenkov 2016-03-30 12:21 reporter ~0009900	I understabd what you mean. Ill try to increase proxy timeout and will look there, this evening or tomorrow.

m_emelchenkov 2016-03-30 12:22 reporter ~0009901	Better, write me proxy and timeouts configs to test with, which values you need to good diag?

tfu 2016-03-30 12:52 reporter ~0009903	It is not client broke the channel, its sogo. How have you found/confirmed that?

m_emelchenkov 2016-03-30 14:08 reporter ~0009904	Because it have no sense, client have timeout 600 and it worked in a such way with z-push before. However, it could be really proxy timeout settings issues (of course I reconfigured it multiple times to achieve best results but anyway it's strange), so nevermind and let's check. Let me know best timeout settings for testing, to make a test which will help us understand the root of this problem.

m_emelchenkov 2016-03-30 20:56 reporter ~0009906	For testing, I lowered SOGoMaximumPingInterval to 180 and set proxy_send_timeout/proxy_read_timeout to 3600. The ERROR disappeared, instead we can see ping status 3. However, there is a delay between Ping POST (23:50:51) and re-initiating sync loop (23:51:52). I checked it multiple times. Every time it has 1 second delay. Can we eliminate this delay? Mar 30 23:50:50 sogod [1806]: localhost.localdomain "POST /SOGo/Microsoft-Server-ActiveSync?User=user@domain&DeviceId=12345&DeviceType=iPhone&Cmd=Sync HTTP/1.1" 200 16683/105 0.922 - - 512K Mar 30 23:50:51 sogod [1806]: <0x0x7f826e0b4ea8[SOGoActiveSyncDispatcher]> EAS - response for device 12345: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <Ping xmlns="Ping:"> <Status>3</Status> </Ping> Mar 30 23:50:51 sogod [1806]: localhost.localdomain "POST /SOGo/Microsoft-Server-ActiveSync?User=user@domain&DeviceId=12345&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200 13/0 0.003 - - 0 Mar 30 23:51:51 sogod [1806]: <0x0x7f826e117948[SOGoActiveSyncDispatcher]> EAS - request for device 12345: <?xml version="1.0"?> <!DOCTYPE ActiveSync PUBLIC "-//MICROSOFT//DTD ActiveSync//EN" "http://www.microsoft.com/"> <Ping xmlns="Ping:"> <HeartbeatInterval>180</HeartbeatInterval> <Folders> <Folder> <Id>mail%2F9d224603ff6be456110800004fca1e17</Id> <Class>Email</Class> </Folder> <Folder> <Id>mail%2F9c224603ff6be456110800004fca1e17</Id> <Class>Email</Class> </Folder> <Folder> <Id>vcard%2Fpersonal</Id> <Class>Contacts</Class> </Folder> <Folder> <Id>vevent%2Fpersonal</Id> <Class>Calendar</Class> </Folder> </Folders> </Ping> Mar 30 23:51:52 sogod [1806]: <0x0x7f826e117948[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 30 23:51:57 sogod [1806]: <0x0x7f826e117948[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 30 23:52:02 sogod [1806]: <0x0x7f826e117948[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 30 23:52:07 sogod [1806]: <0x0x7f826e117948[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 30 23:52:12 sogod [1806]: <0x0x7f826e117948[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 30 23:52:17 sogod [1806]: <0x0x7f826e117948[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 30 23:52:23 sogod [1806]: <0x0x7f826e117948[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping... Mar 30 23:52:28 sogod [1806]: <0x0x7f826e117948[SOGoActiveSyncDispatcher]> Sleeping 5 seconds while detecting changes in Ping...

tfu 2016-03-31 08:03 reporter ~0009907	Ping status 3 is returned by sogo when it received an empty ping request. The device should then return with a non-empty request, but obviously iphone doesn't do that immediately.

m_emelchenkov 2016-03-31 08:05 reporter ~0009908	Then workaround maybe? I did not tested it with fresh iOS version (will do it later as soon as buy new phone). 8.4.1 is a bit old, so if you will not close this ticket for several days/weeks, then I'll be able to post new info from latest iOS.

tfu 2016-03-31 09:07 reporter ~0009909	I'll try to avoid the status = 3. i.e. caching the initial ping payload.

ludovic 2016-04-01 18:57 administrator ~0009916	Also fixed for 2.3.10.

sogo: master 80d29f28 2016-04-01 14:52 ludovic Details Diff	(fix) now cache heartbeat and folders during EAS ping ops (fixes 0003606)	Affected Issues 0003606
	mod - ActiveSync/SOGoActiveSyncDispatcher.m	Diff File
sogo: v2 38ddc0b6 2016-04-01 14:52 ludovic Details Diff	(fix) now cache heartbeat and folders during EAS ping ops (fixes 0003606)	Affected Issues 0003606
	mod - ActiveSync/SOGoActiveSyncDispatcher.m	Diff File

Date Modified	Username	Field	Change
2016-03-29 13:11	m_emelchenkov	New Issue
2016-03-29 15:52	tfu	Note Added: 0009884
2016-03-29 20:30	m_emelchenkov	File Added: Log.txt
2016-03-29 20:30	m_emelchenkov	Note Added: 0009888
2016-03-30 10:52	tfu	Note Added: 0009893
2016-03-30 11:02	m_emelchenkov	Note Added: 0009894
2016-03-30 12:14	tfu	Note Added: 0009898
2016-03-30 12:18	m_emelchenkov	Note Added: 0009899
2016-03-30 12:21	m_emelchenkov	Note Added: 0009900
2016-03-30 12:22	m_emelchenkov	Note Added: 0009901
2016-03-30 12:52	tfu	Note Added: 0009903
2016-03-30 14:08	m_emelchenkov	Note Added: 0009904
2016-03-30 20:56	m_emelchenkov	Note Added: 0009906
2016-03-31 08:03	tfu	Note Added: 0009907
2016-03-31 08:05	m_emelchenkov	Note Added: 0009908
2016-03-31 09:07	tfu	Note Added: 0009909
2016-04-01 18:53	ludovic	Changeset attached	=> sogo master 80d29f28
2016-04-01 18:53	ludovic	Assigned To	=> ludovic
2016-04-01 18:53	ludovic	Resolution	open => fixed
2016-04-01 18:54	ludovic	Changeset attached	=> sogo v2 38ddc0b6
2016-04-01 18:57	ludovic	Note Added: 0009916
2016-04-01 18:57	ludovic	Status	new => resolved
2016-04-01 18:57	ludovic	Fixed in Version	=> 3.1.0

View Issue Details

Activities

Related Changesets

Issue History