View Issue Details

IDProjectCategoryView StatusLast Update
0003606SOGoActiveSyncpublic2016-04-01 14:57
Reporterm_emelchenkov Assigned Toludovic  
PrioritynormalSeverityminorReproducibilityalways
Status resolvedResolutionfixed 
PlatformiPhoneOSiOSOS Version8.4.1
Product Versionnightly v2 
Fixed in Version3.1.0 
Summary0003606: SOGoActiveSyncDispatcher does not re-initiate Ping loop
Description
  1. 5 seconds interval and 0000015:0000006 minutes timeout — its OK, as configured.
  2. At 16:00:44 timeout ended, ping terminated, OK.
  3. At 16:00:46 client disconnected because sogod timeout, OK.
  4. At 16:00:46 sogod receive Ping from iOS. And then nothing, no new logs. It seems sogod does not re-initiate connection.
  5. 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...

TagsNo tags attached.

Activities

tfu

tfu

2016-03-29 11:52

reporter   ~0009884

You can better analyze the traffic with SOGoEASDebugEnabled = YES.

m_emelchenkov

m_emelchenkov

2016-03-29 16: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

m_emelchenkov

2016-03-29 16: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

tfu

2016-03-30 06: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

m_emelchenkov

2016-03-30 07: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

tfu

2016-03-30 08: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

m_emelchenkov

2016-03-30 08: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

m_emelchenkov

2016-03-30 08:21

reporter   ~0009900

I understabd what you mean. Ill try to increase proxy timeout and will look there, this evening or tomorrow.

m_emelchenkov

m_emelchenkov

2016-03-30 08:22

reporter   ~0009901

Better, write me proxy and timeouts configs to test with, which values you need to good diag?

tfu

tfu

2016-03-30 08:52

reporter   ~0009903

It is not client broke the channel, its sogo.
How have you found/confirmed that?

m_emelchenkov

m_emelchenkov

2016-03-30 10: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

m_emelchenkov

2016-03-30 16: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/&quot;>
<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/&quot;>
<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

tfu

2016-03-31 04: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

m_emelchenkov

2016-03-31 04: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

tfu

2016-03-31 05:07

reporter   ~0009909

I'll try to avoid the status = 3. i.e. caching the initial ping payload.

ludovic

ludovic

2016-04-01 14:57

administrator   ~0009916

Also fixed for 2.3.10.

Related Changesets

sogo: master 80d29f28

2016-04-01 14:52:31

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:31

ludovic

Details Diff
(fix) now cache heartbeat and folders during EAS ping ops (fixes 0003606) Affected Issues
0003606
mod - ActiveSync/SOGoActiveSyncDispatcher.m Diff File

Issue History

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