View Issue Details

IDProjectCategoryView StatusLast Update
0003603SOGoActiveSyncpublic2016-03-28 17:40
Reporterm_emelchenkov Assigned Toludovic  
PrioritynormalSeveritymajorReproducibilityalways
Status resolvedResolutionfixed 
PlatformiPhoneOSiOSOS Version8.4.1
Product Versionnightly v2 
Fixed in Version3.1.0 
Summary0003603: SOGoActiveSyncDispatcher multiplied
Description

Every time I refreshing Inbox in Mail.app on iPhone I see in logs
SOGoActiveSyncDispatcher: Sleeping X seconds while detecting changes in Ping, and after each refresh there on more SOGoActiveSyncDispatcher until end of free preforked processes, then everything stop worked because can't handle new connections. I suppose there should be only one channel between the phone and the server, instead there are many of them, each time created new.

TagsNo tags attached.

Activities

m_emelchenkov

m_emelchenkov

2016-03-27 07:18

reporter   ~0009850

After sometime (timeout): "client disconnected during delivery of response for <WORequest[0x0x7f73209d30d8]: method=POST......the socket was shutdown". "frozen" connections each time I refreshing mail Inbox.

/nginx/
proxy_connect_timeout 60;
proxy_send_timeout 360;
proxy_read_timeout 360;

/ SOGo /
SOGoMaximumPingInterval = 354;
SOGoMaximumSyncInterval = 354;
SOGoInternalSyncInterval = 3;

m_emelchenkov

m_emelchenkov

2016-03-27 07:39

reporter   ~0009851

Also (maybe not related and maybe even not a bug) after receiving mail there are two "Change detected during Sync, we push the content." records in logs and two POSTs. Should it fire two times on single incoming message or not?

m_emelchenkov

m_emelchenkov

2016-03-27 07:43

reporter   ~0009852

By the way, after receiving mail it stops SOGoActiveSyncDispatcher, so no new mail delivered to iPhone. After some time it starts dispatch it again. Too many points, let's diagnose step-by-step starting from my first problem described in "Description". If other problems will exists after fixing it then I will open new issues there. Thanks.

tfu

tfu

2016-03-28 12:08

reporter  

3603.diff (2,784 bytes)   
diff --git a/ActiveSync/SOGoActiveSyncDispatcher.m b/ActiveSync/SOGoActiveSyncDispatcher.m
index 17599ae..091efc6 100644
--- a/ActiveSync/SOGoActiveSyncDispatcher.m
+++ b/ActiveSync/SOGoActiveSyncDispatcher.m
@@ -2164,7 +2164,7 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 - (void) processPing: (id <DOMElement>) theDocumentElement
           inResponse: (WOResponse *) theResponse
 {
-  NSString *collectionId, *realCollectionId, *syncKey;
+  NSString *collectionId, *realCollectionId, *syncKey, *key, *processIdentifier;
   NSMutableArray *foldersWithChanges, *allFoldersID;
   SOGoMicrosoftActiveSyncFolderType folderType;
   NSMutableDictionary *folderMetadata;
@@ -2177,8 +2177,13 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
   NSData *d;
   NSAutoreleasePool *pool;
 
-  int i, j, heartbeatInterval, defaultInterval, internalInterval, status;
+  int i, j, heartbeatInterval, defaultInterval, internalInterval, status, total_sleep;
   
+  // Let other ping requests know that a new request has arrived.
+  processIdentifier = [NSString stringWithFormat: @"%d", [[NSProcessInfo processInfo] processIdentifier]];
+  key = [NSString stringWithFormat: @"%@+%@", [[context activeUser] login], [context objectForKey: @"DeviceType"]];
+  [[SOGoCache sharedCache] setValue: processIdentifier forKey: key];
+
   defaults = [SOGoSystemDefaults sharedSystemDefaults];
   defaultInterval = [defaults maximumPingInterval];
   internalInterval = [defaults internalSyncInterval];
@@ -2272,8 +2277,29 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
         }
       else
         {
-          [self logWithFormat: @"Sleeping %d seconds while detecting changes in Ping...", internalInterval];
-          sleep(internalInterval);
+          total_sleep = 0;
+
+          while (total_sleep < internalInterval)
+            {
+              // We check if we must break the current ping request since an other ping request
+              // has just arrived.
+              if ([[SOGoCache sharedCache] valueForKey: key] && ![[[SOGoCache sharedCache] valueForKey: key] isEqualToString: processIdentifier])
+                {
+                  if (debugOn)
+                    [self logWithFormat: @"EAS - Ping request canceled (%@)", [[SOGoCache sharedCache] valueForKey: key]];
+
+                  // Make sure we end the heardbeat-loop.
+                  heartbeatInterval = internalInterval = 1;
+
+                  break;
+                }
+              else
+                {
+                  [self logWithFormat: @"Sleeping %d seconds while detecting changes in Ping...", internalInterval-total_sleep];
+                  sleep(5);
+                  total_sleep += 5;
+                }
+            }
         }
     }
   
3603.diff (2,784 bytes)   
tfu

tfu

2016-03-28 12:09

reporter   ~0009853

Attached patch should avoid duplicate ping requests.
-> I don't have an iPhone to test.

ludovic

ludovic

2016-03-28 13:33

administrator   ~0009854

Why not do the same thing we do for Sync requests? Using only the SOGoCache isn't cluster safe.

Using SOGoCacheGCSObject is.

tfu

tfu

2016-03-28 15:31

reporter  

3603-1.diff (3,074 bytes)   
diff --git a/ActiveSync/SOGoActiveSyncDispatcher.m b/ActiveSync/SOGoActiveSyncDispatcher.m
index 17599ae..3c8a66e 100644
--- a/ActiveSync/SOGoActiveSyncDispatcher.m
+++ b/ActiveSync/SOGoActiveSyncDispatcher.m
@@ -2164,11 +2164,12 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 - (void) processPing: (id <DOMElement>) theDocumentElement
           inResponse: (WOResponse *) theResponse
 {
-  NSString *collectionId, *realCollectionId, *syncKey;
+  NSString *collectionId, *realCollectionId, *syncKey, *processIdentifier, *pingRequestInCache;
   NSMutableArray *foldersWithChanges, *allFoldersID;
   SOGoMicrosoftActiveSyncFolderType folderType;
   NSMutableDictionary *folderMetadata;
   SOGoSystemDefaults *defaults;
+  SOGoCacheGCSObject *o;
   id <DOMElement> aCollection;
   NSArray *allCollections;
 
@@ -2177,8 +2178,17 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
   NSData *d;
   NSAutoreleasePool *pool;
 
-  int i, j, heartbeatInterval, defaultInterval, internalInterval, status;
+  int i, j, heartbeatInterval, defaultInterval, internalInterval, status, total_sleep;
   
+  // Let other ping requests know that a new request has arrived.
+  processIdentifier = [NSString stringWithFormat: @"%d", [[NSProcessInfo processInfo] processIdentifier]];
+  o = [SOGoCacheGCSObject objectWithName: [context objectForKey: @"DeviceId"]  inContainer: nil  useCache: NO];
+  [o setObjectType: ActiveSyncGlobalCacheObject];
+  [o setTableUrl: [self folderTableURL]];
+  [o reloadIfNeeded];
+  [[o properties] setObject: processIdentifier forKey: @"PingRequest"];
+  [o save];
+
   defaults = [SOGoSystemDefaults sharedSystemDefaults];
   defaultInterval = [defaults maximumPingInterval];
   internalInterval = [defaults internalSyncInterval];
@@ -2272,8 +2282,30 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
         }
       else
         {
-          [self logWithFormat: @"Sleeping %d seconds while detecting changes in Ping...", internalInterval];
-          sleep(internalInterval);
+          total_sleep = 0;
+
+          while (total_sleep < internalInterval)
+            {
+              // We check if we must break the current ping request since an other ping request
+              // has just arrived.
+              pingRequestInCache = [[self globalMetadataForDevice] objectForKey: @"PingRequest"];
+              if (pingRequestInCache && ![pingRequestInCache isEqualToString: processIdentifier])
+                {
+                  if (debugOn)
+                    [self logWithFormat: @"EAS - Ping request canceled (%@)", pingRequestInCache];
+
+                  // Make sure we end the heardbeat-loop.
+                  internalInterval = heartbeatInterval;
+
+                  break;
+                }
+              else
+                {
+                  [self logWithFormat: @"Sleeping %d seconds while detecting changes in Ping...", internalInterval-total_sleep];
+                  sleep(5);
+                  total_sleep += 5;
+                }
+            }
         }
     }
   
3603-1.diff (3,074 bytes)   
tfu

tfu

2016-03-28 15:31

reporter   ~0009858

Attached a new version of the patch.

ludovic

ludovic

2016-03-28 15:52

administrator   ~0009859

How about cleaning up this data in case we got stale data with sogo-tool?

You could also replace in your patch:

processIdentifier = [NSString stringWithFormat: @"%d", [[NSProcessInfo processInfo] processIdentifier]];
o = [SOGoCacheGCSObject objectWithName: [context objectForKey: @"DeviceId"] inContainer: nil useCache: NO];
[o setObjectType: ActiveSyncGlobalCacheObject];
[o setTableUrl: [self folderTableURL]];
[o reloadIfNeeded];

with:

o = [self globalMetadataForDevice];

m_emelchenkov

m_emelchenkov

2016-03-28 16:29

reporter   ~0009860

I'd love to test! Can I wait for nightly build or need to compile it myself?

tfu

tfu

2016-03-28 16:37

reporter   ~0009861

I don't think that there is an additional cleanup needed. "globalMetadata" will be cleaned with resetdevice.

With the change you suggested o would be a dictionary, how do you suggest to do the save ([o save])?

ludovic

ludovic

2016-03-28 17:14

administrator   ~0009862

[o save] :-)

tfu

tfu

2016-03-28 17:32

reporter   ~0009863

don't think so.
[self globalMetadataForDevice] doesn't return a SOGoCacheGCSObject.

ludovic

ludovic

2016-03-28 17:34

administrator   ~0009864

Ah, true - forget it then.

ludovic

ludovic

2016-03-28 17:40

administrator   ~0009865

Also fixed for 2.3.10.

Related Changesets

sogo: master 5a342f2f

2016-03-28 17:37:07

ludovic

Details Diff
(fix) prevent double Sync ops from same device (fixes 0003603) Affected Issues
0003603
mod - ActiveSync/SOGoActiveSyncDispatcher.m Diff File

sogo: v2 821b9d1f

2016-03-28 17:37:07

ludovic

Details Diff
(fix) prevent double Sync ops from same device (fixes 0003603) Affected Issues
0003603
mod - ActiveSync/SOGoActiveSyncDispatcher.m Diff File

Issue History

Date Modified Username Field Change
2016-03-27 07:13 m_emelchenkov New Issue
2016-03-27 07:18 m_emelchenkov Note Added: 0009850
2016-03-27 07:39 m_emelchenkov Note Added: 0009851
2016-03-27 07:43 m_emelchenkov Note Added: 0009852
2016-03-28 12:08 tfu File Added: 3603.diff
2016-03-28 12:09 tfu Note Added: 0009853
2016-03-28 13:33 ludovic Note Added: 0009854
2016-03-28 15:31 tfu File Added: 3603-1.diff
2016-03-28 15:31 tfu Note Added: 0009858
2016-03-28 15:52 ludovic Note Added: 0009859
2016-03-28 16:29 m_emelchenkov Note Added: 0009860
2016-03-28 16:37 tfu Note Added: 0009861
2016-03-28 17:14 ludovic Note Added: 0009862
2016-03-28 17:32 tfu Note Added: 0009863
2016-03-28 17:34 ludovic Note Added: 0009864
2016-03-28 17:38 ludovic Changeset attached => sogo master 5a342f2f
2016-03-28 17:38 ludovic Assigned To => ludovic
2016-03-28 17:38 ludovic Resolution open => fixed
2016-03-28 17:39 ludovic Changeset attached => sogo v2 821b9d1f
2016-03-28 17:40 ludovic Note Added: 0009865
2016-03-28 17:40 ludovic Status new => resolved
2016-03-28 17:40 ludovic Fixed in Version => 3.1.0