0003208: Process sogod running at 100% CPU with android 5.1 synchronization - SOGo | BTS

ID	Project	Category	View Status	Date Submitted	Last Update

0003208	SOGo	ActiveSync	public	2015-05-06 17:33	2015-05-22 12:29

Reporter	Emmanuel dHumieres	Assigned To	ludovic
Priority	normal	Severity	major	Reproducibility	always
Status	resolved	Resolution	no change required
Product Version	2.2.17

Summary	0003208: Process sogod running at 100% CPU with android 5.1 synchronization
Description	When a synchronization is made from a Nexus 5 (Android 5.1), one then several sogod process start running at 100% CPU. Sometimes we can notice a light decrease of the number of these crazy process, but most of the time, we can reach 9 or 10 sogod process at 100% at the same time (PREFORK has been set to 10 in /etc/init.d/sogo). When "faulty user" removes his account on his Nexus 5, process finally run at a normal level of CPU (crazy process being killed by "safety belt") If user creates again his exchange account on his Nexus 5, sogod process start again running at 100%. SOGo server 2.2.17a-1 is running on a Ubuntu 14.04 fully updated.
Steps To Reproduce	Create an exchange account on a Nexus 5.1 and wait few minutes to observe high CPU load with sogod process. Please notice that I have not been able to test nexus 5.1 synchronization on another SOGo server. So I cannot guarantee that Reproducibility is always on other SOGo servers.
Additional Information	After his account creation, user can see his mails, but not his calendars and events (related to https://code.google.com/p/android/issues/detail?id=79389 ???) I tried to apply the linux command strace to check system calls from a sogod process running at 100% CPU. Nothing was displayed except the kill system call made by the watchdog "safety belt" : so 100% pure cpu time You will find in attachment, two stacks of two different sogod process running at 100% CPU (trace were made at two different moments)
Tags	No tags attached.

Emmanuel dHumieres 2015-05-06 17:33 reporter	sogod_traces.txt (10,801 bytes) =========================== trace 1 ============================= #0 0x00007fc8c8e87df1 in _wordcopy_fwd_dest_aligned (dstp=<optimized out>, srcp=<optimized out>, len=1964944) at wordcopy.c:207 #1 0x00007fc8c8e82417 in __memmove_sse2 (dest=0x7fc8ac4bec00, src=<optimized out>, len=33734901) at ../string/memmove.c:79 #2 0x00007fc8c9c93dd7 in memmove (__len=<optimized out>, __src=<optimized out>, __dest=<optimized out>) at /usr/include/x86_64-linux-gnu/bits/string3.h:57 #3 fillHole (size=1, index=977904, self=0x7fc8cefc34b8) at GSString.m:2161 #4 -[GSMutableString replaceCharactersInRange:withString:] (self=0x7fc8cefc34b8, _cmd=<optimized out>, aRange=..., aString=0x7fc8bd7c2620 <_OBJC_INSTANCE_3>) at GSString.m:4998 #5 0x00007fc8c9e4b019 in -[NSMutableString(GNUstepBase) replaceString:withString:] (self=0x7fc8cefc34b8, _cmd=<optimized out>, replace=0x7fc8bd7c2600 <_OBJC_INSTANCE_2>, by=0x7fc8bd7c2620 <_OBJC_INSTANCE_3>) at NSMutableString+GNUstepBase.m:300 #6 0x00007fc8c9e4c036 in -[NSString(GNUstepBase) stringByReplacingString:withString:] (self=0x7fc8cece46c8, _cmd=<optimized out>, replace=0x7fc8bd7c2600 <_OBJC_INSTANCE_2>, by=0x7fc8bd7c2620 <_OBJC_INSTANCE_3>) at NSString+GNUstepBase.m:216 #7 0x00007fc8bd5987af in -[NSData(ActiveSync) activeSyncRepresentationInContext:] (self=0x7fc8ceff7218, _cmd=0x7fc8bd7ca970 <_OBJC_SELECTOR_TABLE+1648>, context=0x7fc8ceb1a608) at NSData+ActiveSync.m:60 #8 0x00007fc8bd5a4eea in -[SOGoActiveSyncDispatcher processItemOperations:inResponse:] (self=0x7fc8cecf5208, _cmd=0x7fc8ceac7c00, theDocumentElement=0x7fc8cecc5738, theResponse=0x7fc8cf04b2b8) at SOGoActiveSyncDispatcher.m:1303 #9 0x00007fc8bd5ab91a in -[SOGoActiveSyncDispatcher dispatchRequest:inResponse:context:] (self=0x7fc8cecf5208, _cmd=0x7fc8be25c8a0 <_OBJC_SELECTOR_TABLE+96>, theRequest=0x7fc8cea9dfb8, theResponse=0x7fc8cf04b2b8, theContext=0x7fc8ceb1a608) at SOGoActiveSyncDispatcher.m:2638 #10 0x00007fc8be055675 in -[SOGoMicrosoftActiveSyncActions microsoftServerActiveSyncAction] (self=0x7fc8ceccd738, _cmd=0x7fc8ceac7c40) at SOGoMicrosoftActiveSyncActions.m:57 #11 0x00007fc8cb5c74d4 in -[SoActionInvocation callOnObject:withPositionalParametersWhenNotNil:inContext:] () from /usr/lib/libNGObjWeb.so.4.9 #12 0x00007fc8cb5c2bf8 in -[SoObjectMethodDispatcher dispatchInContext:] () from /usr/lib/libNGObjWeb.so.4.9 #13 0x00007fc8cb5c4bc9 in -[SoObjectRequestHandler handleRequest:inContext:session:application:] () ---Type <return> to continue, or q <return> to quit--- from /usr/lib/libNGObjWeb.so.4.9 #14 0x00007fc8cb55acde in -[WORequestHandler handleRequest:] (self=0x7fc8ceaf1308, _cmd=<optimized out>, _request=0x7fc8cea9dfb8) at WORequestHandler.m:237 #15 0x00007fc8cb52268c in -[WOCoreApplication dispatchRequest:usingHandler:] (self=0x7fc8ce9e5048, _cmd=<optimized out>, _request=0x7fc8cea9dfb8, handler=0x7fc8ceaf1308) at WOCoreApplication.m:712 #16 0x00007fc8cc8d0822 in -[SOGo dispatchRequest:] (self=0x7fc8ce9e5048, _cmd=0x7fc8cb8cf8b0 <_OBJC_SELECTOR_TABLE+1840>, _request=0x7fc8cea9dfb8) at SOGo.m:453 #17 0x00007fc8cb5b596d in -[WOHttpTransaction _run] (self=0x7fc8ced5b228, _cmd=<optimized out>) at WOHttpTransaction.m:596 #18 0x00007fc8cb5b6e38 in -[WOHttpTransaction run] (self=0x7fc8ced5b228, _cmd=<optimized out>) at WOHttpTransaction.m:649 #19 0x00007fc8cb5b1eda in -[WOHttpAdaptor runConnection:] (self=0x7fc8cea589d8, _cmd=<optimized out>, _socket=<optimized out>) at WOHttpAdaptor.m:367 #20 0x00007fc8cb5b2d16 in -[WOHttpAdaptor _handleAcceptedConnection:] (self=0x7fc8cea589d8, _cmd=<optimized out>, _connection=0x7fc8cefbe0e8) at WOHttpAdaptor.m:401 #21 0x00007fc8cb5b30aa in -[WOHttpAdaptor _handleConnection:] (self=0x7fc8cea589d8, _cmd=<optimized out>, connection=0x7fc8cefbe0e8) at WOHttpAdaptor.m:460 #22 0x00007fc8cb5b2258 in -[WOHttpAdaptor acceptControlMessage:] (self=0x7fc8cea589d8, _cmd=<optimized out>, aNotification=<optimized out>) at WOHttpAdaptor.m:499 #23 0x00007fc8c9d5843d in -[NSNotificationCenter _postAndRelease:] (self=0x7fc8ce794778, _cmd=<optimized out>, notification=0x7fc8cea61228) at NSNotificationCenter.m:1223 #24 0x00007fc8c9e52487 in -[GSRunLoopCtxt pollUntil:within:] (self=0x7fc8ce904b48, _cmd=<optimized out>, milliseconds=<optimized out>, contexts=<optimized out>) at GSRunLoopCtxt.m:632 #25 0x00007fc8c9d9dd70 in -[NSRunLoop acceptInputForMode:beforeDate:] (self=0x7fc8ce9c2ba8, _cmd=<optimized out>, mode=0x7fc8ca21f520 <_OBJC_INSTANCE_2>, limit_date=<optimized out>) at NSRunLoop.m:1195 #26 0x00007fc8c9d9cb8c in -[NSRunLoop runMode:beforeDate:] (self=0x7fc8ce9c2ba8, _cmd=0x7fc8cb838e30 <_OBJC_SELECTOR_TABLE+1360>, mode=0x7fc8ca21f520 <_OBJC_INSTANCE_2>, date=0x7fc8ce9bb278) at NSRunLoop.m:1263 #27 0x00007fc8cb523a6e in -[WOCoreApplication run] (self=0x7fc8ce9e5048, _cmd=<optimized out>) at WOCoreApplication.m:584 ---Type <return> to continue, or q <return> to quit--- #28 0x00007fc8cc8cff2d in -[SOGo run] (self=0x7fc8ce9e5048, _cmd=0x7fc8cb876240 <_OBJC_SELECTOR_TABLE+608>) at SOGo.m:277 #29 0x00007fc8cb5635e4 in -[WOWatchDog _spawnChild:] (self=0x7fc8ce9ab408, _cmd=<optimized out>, child=0x7fc8ce9b7798) at WOWatchDogApplicationMain.m:595 #30 0x00007fc8cb562426 in -[WOWatchDog _ensureChildren] (self=0x7fc8ce9ab408, _cmd=<optimized out>) at WOWatchDogApplicationMain.m:685 #31 0x00007fc8cb563d12 in -[WOWatchDog run:argc:argv:] (self=0x7fc8ce9ab408, _cmd=<optimized out>, newAppName=<optimized out>, newArgC=<optimized out>, newArgV=<optimized out>) at WOWatchDogApplicationMain.m:936 #32 0x00007fc8cb56428b in WOWatchDogApplicationMain (appName=0x7fc8ccad6140 <_OBJC_INSTANCE_0>, argc=7, argv=0x7fff9d6d02f8) at WOWatchDogApplicationMain.m:1050 #33 0x00007fc8cc8cf25e in main (argc=7, argv=0x7fff9d6d02f8, env=0x7fff9d6d0338) at sogod.m:53 =========================== trace 2 ============================= #0 _wordcopy_fwd_dest_aligned (dstp=140663607000616, srcp=140663607000632, len=4152100) at wordcopy.c:201 #1 0x00007feee78bb417 in __memmove_sse2 (dest=0x7feecc400100, src=<optimized out>, len=34526805) at ../string/memmove.c:79 #2 0x00007feee86ccdd7 in memmove (__len=<optimized out>, __src=<optimized out>, __dest=<optimized out>) at /usr/include/x86_64-linux-gnu/bits/string3.h:57 #3 fillHole (size=1, index=196848, self=0x7feeec4f9cf8) at GSString.m:2161 #4 -[GSMutableString replaceCharactersInRange:withString:] (self=0x7feeec4f9cf8, _cmd=<optimized out>, aRange=..., aString=0x7feedc1fb620) at GSString.m:4998 #5 0x00007feee8884019 in -[NSMutableString(GNUstepBase) replaceString:withString:] (self=0x7feeec4f9cf8, _cmd=<optimized out>, replace=0x7feedc1fb600, by=0x7feedc1fb620) at NSMutableString+GNUstepBase.m:300 #6 0x00007feee8885036 in -[NSString(GNUstepBase) stringByReplacingString:withString:] (self=0x7feeec4fae48, _cmd=<optimized out>, replace=0x7feedc1fb600, by=0x7feedc1fb620) at NSString+GNUstepBase.m:216 #7 0x00007feedbfd17af in ?? () from /usr/lib/GNUstep/SOGo/ActiveSync.SOGo/./ActiveSync #8 0x00007feedbfddeea in ?? () from /usr/lib/GNUstep/SOGo/ActiveSync.SOGo/./ActiveSync #9 0x00007feedbfe491a in ?? () from /usr/lib/GNUstep/SOGo/ActiveSync.SOGo/./ActiveSync #10 0x00007feedca8e675 in ?? () from /usr/lib/GNUstep/SOGo/MainUI.SOGo/./MainUI #11 0x00007feeea0004d4 in -[SoActionInvocation callOnObject:withPositionalParametersWhenNotNil:inContext:] () from /usr/lib/libNGObjWeb.so.4.9 #12 0x00007feee9ffbbf8 in -[SoObjectMethodDispatcher dispatchInContext:] () from /usr/lib/libNGObjWeb.so.4.9 #13 0x00007feee9ffdbc9 in -[SoObjectRequestHandler handleRequest:inContext:session:application:] () from /usr/lib/libNGObjWeb.so.4.9 #14 0x00007feee9f93cde in -[WORequestHandler handleRequest:] (self=0x7feeec1dd838, _cmd=<optimized out>, _request=0x7feeebf53c48) at WORequestHandler.m:237 #15 0x00007feee9f5b68c in -[WOCoreApplication dispatchRequest:usingHandler:] (self=0x7feeec17b6b8, _cmd=<optimized out>, _request=0x7feeebf53c48, handler=0x7feeec1dd838) at WOCoreApplication.m:712 #16 0x00007feeeb309822 in ?? () ---Type <return> to continue, or q <return> to quit--- #17 0x00007feee9fee96d in -[WOHttpTransaction _run] (self=0x7feeec21bee8, _cmd=<optimized out>) at WOHttpTransaction.m:596 #18 0x00007feee9fefe38 in -[WOHttpTransaction run] (self=0x7feeec21bee8, _cmd=<optimized out>) at WOHttpTransaction.m:649 #19 0x00007feee9feaeda in -[WOHttpAdaptor runConnection:] (self=0x7feeec21cb88, _cmd=<optimized out>, _socket=<optimized out>) at WOHttpAdaptor.m:367 #20 0x00007feee9febd16 in -[WOHttpAdaptor _handleAcceptedConnection:] (self=0x7feeec21cb88, _cmd=<optimized out>, _connection=0x7feeec21c918) at WOHttpAdaptor.m:401 #21 0x00007feee9fec0aa in -[WOHttpAdaptor _handleConnection:] (self=0x7feeec21cb88, _cmd=<optimized out>, connection=0x7feeec21c918) at WOHttpAdaptor.m:460 #22 0x00007feee9feb258 in -[WOHttpAdaptor acceptControlMessage:] (self=0x7feeec21cb88, _cmd=<optimized out>, aNotification=<optimized out>) at WOHttpAdaptor.m:499 #23 0x00007feee879143d in -[NSNotificationCenter _postAndRelease:] (self=0x7feeebf58778, _cmd=<optimized out>, notification=0x7feeec21c8e8) at NSNotificationCenter.m:1223 #24 0x00007feee888b487 in -[GSRunLoopCtxt pollUntil:within:] (self=0x7feeec0c87f8, _cmd=<optimized out>, milliseconds=<optimized out>, contexts=<optimized out>) at GSRunLoopCtxt.m:632 #25 0x00007feee87d6d70 in -[NSRunLoop acceptInputForMode:beforeDate:] (self=0x7feeec186848, _cmd=<optimized out>, mode=0x7feee8c58520 <_OBJC_INSTANCE_2>, limit_date=<optimized out>) at NSRunLoop.m:1195 #26 0x00007feee87d5b8c in -[NSRunLoop runMode:beforeDate:] (self=0x7feeec186848, _cmd=0x7feeea271e30 <_OBJC_SELECTOR_TABLE+1360>, mode=0x7feee8c58520 <_OBJC_INSTANCE_2>, date=0x7feeec0c6708) at NSRunLoop.m:1263 #27 0x00007feee9f5ca6e in -[WOCoreApplication run] (self=0x7feeec17b6b8, _cmd=<optimized out>) at WOCoreApplication.m:584 #28 0x00007feeeb308f2d in ?? () #29 0x00007feee9f9c5e4 in -[WOWatchDog _spawnChild:] (self=0x7feeec16f0a8, _cmd=<optimized out>, child=0x7feeec15bc48) at WOWatchDogApplicationMain.m:595 #30 0x00007feee9f9b426 in -[WOWatchDog _ensureChildren] (self=0x7feeec16f0a8, _cmd=<optimized out>) at WOWatchDogApplicationMain.m:685 ---Type <return> to continue, or q <return> to quit--- #31 0x00007feee9f9cd12 in -[WOWatchDog run:argc:argv:] (self=0x7feeec16f0a8, _cmd=<optimized out>, newAppName=<optimized out>, newArgC=<optimized out>, newArgV=<optimized out>) at WOWatchDogApplicationMain.m:936 #32 0x00007feee9f9d28b in WOWatchDogApplicationMain (appName=0x7feeeb50f140, argc=7, argv=0x7ffefd005588) at WOWatchDogApplicationMain.m:1050 #33 0x00007feeeb30825e in main () sogod_traces.txt (10,801 bytes)

tfu 2015-05-09 19:34 reporter ~0008460	Do you see anything in sogo.log which looks like a loop? i.e. does the "faulty device" send requests over and over again? Try to set SOGoMaximumSyncResponseSize or SOGoMaximumSyncWindowSize to a low value and see whether at least some calendar entries can be synced before the problem starts.

Emmanuel dHumieres 2015-05-10 10:18 reporter ~0008462	You're right. I send you in attachment sogo_log.txt an extract from SOGo logs. There are 2 users : username1 and firstname.lastname displayed in the log. The involved faulty user is firstname.lastname. And we can see that many consecutive requests are sent for the user firstname.lastname, compare to the good one username1. I will try to set the 2 variables SOGoMaximumSyncResponseSize or SOGoMaximumSyncWindowSize as you mentioned to a lower value and give you result in return. Please note that real ip addresses and usernames have been masked in the attachment.

Emmanuel dHumieres 2015-05-10 10:19 reporter	sogo_log.txt (33,300 bytes) May 04 11:02:36 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 0/102 0.601 - - 0 May 04 11:02:37 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 0/71 0.014 - - 0 May 04 11:02:37 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=Sync&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 0/73 0.006 - - 0 May 04 11:02:37 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 93993/46 0.412 - - 8K May 04 11:02:38 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 93993/46 0.383 - - 0 May 04 11:02:39 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 93993/46 0.380 - - 0 May 04 11:02:40 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 7271/44 0.268 - - 0 May 04 11:02:40 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 5083/44 0.349 - - 0 May 04 11:02:41 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 3327/44 0.366 - - 0 May 04 11:02:42 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 1755/44 0.373 - - 0 May 04 11:02:42 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 38712/44 0.359 - - 0 May 04 11:02:43 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 9039/44 0.389 - - 0 May 04 11:02:44 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 9043/44 0.349 - - 0 May 04 11:02:45 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 1571/44 0.348 - - 0 May 04 11:02:45 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 76739/44 0.367 - - 0 May 04 11:02:46 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 9530/44 0.347 - - 0 May 04 11:02:46 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 33938/44 0.370 - - 4K May 04 11:02:47 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 97441/46 0.383 - - 0 May 04 11:02:48 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 97441/46 0.493 - - 0 May 04 11:02:49 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 97441/46 0.375 - - 0 May 04 11:02:50 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 519290/44 0.982 - - 1M May 04 11:02:51 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 94713/46 0.375 - - 0 May 04 11:02:52 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 94713/46 0.382 - - 0 May 04 11:02:53 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 94713/46 0.375 - - 0 May 04 11:02:54 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 44951/44 0.382 - - 0 May 04 11:02:55 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 83068/44 0.369 - - 0 May 04 11:02:55 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 11680/44 0.349 - - 0 May 04 11:02:56 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 44979/44 0.363 - - 0 May 04 11:02:57 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 12179/44 0.350 - - 0 May 04 11:03:00 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 1057887/44 2.670 - - 7M May 04 11:03:02 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 72401/46 0.366 - - 0 May 04 11:03:02 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 72401/46 0.372 - - 0 May 04 11:03:03 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 26985/44 0.346 - - 0 May 04 11:03:04 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 17789/46 0.349 - - 0 May 04 11:03:05 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 24292/44 0.495 - - 0 May 04 11:03:06 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 9071/44 0.385 - - 0 May 04 11:03:06 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 106934/44 0.473 - - 0 May 04 11:03:09 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 1044315/44 2.861 - - 10M May 04 11:03:11 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 97887/48 0.372 - - 0 May 04 11:03:12 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 97887/48 0.495 - - 0 May 04 11:03:13 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 97887/48 0.382 - - 0 May 04 11:03:14 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 242909/44 0.529 - - 0 May 04 11:03:17 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 1031802/44 2.603 - - 10M May 04 11:03:20 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 848425/44 1.875 - - 9M May 04 11:03:21 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 90921/46 0.372 - - 0 May 04 11:03:22 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 90921/46 0.379 - - 0 May 04 11:03:22 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 545/44 0.447 - - 0 May 04 11:03:24 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 122378/46 0.404 - - 0 May 04 11:03:24 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 122378/46 0.393 - - 0 May 04 11:03:25 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 87505/44 0.392 - - 0 May 04 11:03:26 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 41301/44 0.275 - - 0 May 04 11:03:27 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 13975/44 0.338 - - 0 May 04 11:03:28 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 78073/46 0.364 - - 0 May 04 11:03:29 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 78073/46 0.364 - - 0 May 04 11:03:29 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 9043/44 0.375 - - 0 May 04 11:03:30 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 9530/44 0.346 - - 0 May 04 11:03:31 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 997/44 0.474 - - 0 May 04 11:03:31 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 44979/44 0.362 - - 0 May 04 11:03:32 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 12179/44 0.348 - - 0 May 04 11:03:32 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 28945/46 0.362 - - 16K May 04 11:03:33 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 28945/46 0.350 - - 0 May 04 11:03:34 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 44951/44 0.498 - - -16K May 04 11:03:35 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 83068/44 0.370 - - 0 May 04 11:03:35 sogod [2585]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 11680/44 0.400 - - 0 May 04 11:03:36 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 44979/44 0.361 - - 8K May 04 11:03:36 sogod [2585]: <0x0x7feeecfcfed8[SOGoActiveSyncDispatcher]> Sleeping 10 seconds while detecting changes... May 04 11:03:37 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 12179/44 0.353 - - 0 May 04 11:03:41 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 1267899/44 4.029 - - 9M May 04 11:03:43 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 68413/46 0.373 - - 0 May 04 11:03:43 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 68413/46 0.374 - - 0 May 04 11:03:44 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 2811/44 0.341 - - 0 May 04 11:03:45 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 38712/44 0.357 - - 0 May 04 11:03:45 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 9043/44 0.364 - - 0 May 04 11:03:46 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 9530/44 0.348 - - 0 May 04 11:03:46 sogod [2585]: yy.yy.yy.yy "POST /SOGo/Microsoft-Server-ActiveSync?User=username1&DeviceId=OH9LDN0MI50UTCUJSQFINN0K5G&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200 13/244 10.894 - - 0 May 04 11:03:47 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 997/44 0.345 - - 0 May 04 11:03:47 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 44979/44 0.377 - - 0 May 04 11:03:48 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 12179/44 0.355 - - 0 May 04 11:03:49 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 1267/44 0.349 - - 0 May 04 11:03:49 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 2127/44 0.350 - - 0 May 04 11:03:49 sogod [2592]: yy.yy.yy.yy "POST /SOGo/Microsoft-Server-ActiveSync?User=username1&DeviceId=OH9LDN0MI50UTCUJSQFINN0K5G&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200 13/0 0.003 - - 0 May 04 11:03:50 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 2083/44 0.347 - - 0 May 04 11:03:51 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 3371/44 0.350 - - 0 May 04 11:03:51 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 3874/44 0.360 - - 0 May 04 11:03:53 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 4728/45 0.342 - - 0 May 04 11:03:53 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 11589/45 0.282 - - 0 May 04 11:03:54 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 26416/45 0.351 - - 0 May 04 11:03:54 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 68265/45 0.363 - - 0 May 04 11:03:55 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 1444/45 0.345 - - 0 May 04 11:03:56 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 4876/45 0.344 - - 0 May 04 11:03:57 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 88040/45 0.420 - - 0 May 04 11:03:57 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 43032/45 0.357 - - 0 May 04 11:03:58 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 3700/45 0.512 - - 0 May 04 11:03:59 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 1352/45 0.348 - - 0 May 04 11:04:00 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 3700/45 0.349 - - 0 May 04 11:04:00 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 61976/45 0.359 - - 0 May 04 11:04:01 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 30259/44 0.356 - - 0 May 04 11:04:02 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 1283/44 0.349 - - 0 May 04 11:04:02 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 62019/44 0.361 - - 0 May 04 11:04:03 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 21023/44 0.354 - - 0 May 04 11:04:04 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 1283/44 0.341 - - 0 May 04 11:04:05 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 3087/44 0.346 - - 0 May 04 11:04:05 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 44955/44 0.404 - - 0 May 04 11:04:06 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 21007/44 0.351 - - 0 May 04 11:04:07 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 9039/44 0.346 - - 0 May 04 11:04:07 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 9530/44 0.355 - - 0 May 04 11:04:08 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 545/44 0.346 - - 0 May 04 11:04:09 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 9043/44 0.348 - - 0 May 04 11:04:09 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 9530/44 0.367 - - 0 May 04 11:04:10 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 10956/44 0.360 - - 0 May 04 11:04:11 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 5906/44 0.346 - - 0 May 04 11:04:12 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 8259/44 0.339 - - 0 May 04 11:04:12 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 8259/44 0.373 - - 0 May 04 11:04:13 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 44979/44 0.360 - - 0 May 04 11:04:14 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 12179/44 0.272 - - 0 May 04 11:04:15 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 8259/44 0.367 - - 0 May 04 11:04:15 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 86681/46 0.401 - - 0 May 04 11:04:16 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 86681/46 0.368 - - 0 May 04 11:04:17 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 86681/46 0.375 - - 0 May 04 11:04:17 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 8259/44 0.366 - - 0 May 04 11:04:18 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 44979/44 0.281 - - 0 May 04 11:04:19 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 8259/44 0.349 - - 0 May 04 11:04:19 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 44971/44 0.364 - - 0 May 04 11:04:20 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 12179/44 0.351 - - 0 May 04 11:04:49 sogod [2592]: xx.xx.xx.xx "POST /SOGo/Microsoft-Server-ActiveSync?Cmd=ItemOperations&User=firstname.lastname%40scriptandgo.com&DeviceId=android1415355582575&DeviceType=Android HTTP/1.1" 200 3560830/44 28.532 - - 26M May 04 11:04:51 sogod [2592]: <0x0x7feeed045208[SOGoActiveSyncDispatcher]> Sleeping 10 seconds while detecting changes... ..../.... May 04 11:12:16 sogod [2588]: <0x0x7feeec660308[SOGoActiveSyncDispatcher]> Sleeping 10 seconds while detecting changes... May 04 11:12:18 sogod [2530]: [WARN] <0x0x7feeec17bd58[WOWatchDogChild]> pid 2591 has been hanging in the same request for 2 minutes May 04 11:12:26 sogod [2530]: [WARN] <0x0x7feeec17ee08[WOWatchDogChild]> pid 2592 has been hanging in the same request for 3 minutes May 04 11:12:26 sogod [2588]: yy.yy.yy.yy "POST /SOGo/Microsoft-Server-ActiveSync?User=username1&DeviceId=OH9LDN0MI50UTCUJSQFINN0K5G&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200 13/244 11.300 - - 4M May 04 11:12:28 sogod [2530]: [WARN] <0x0x7feeec1570a8[WOWatchDogChild]> pid 2585 has been hanging in the same request for 7 minutes May 04 11:12:29 sogod [2588]: yy.yy.yy.yy "POST /SOGo/Microsoft-Server-ActiveSync?User=username1&DeviceId=OH9LDN0MI50UTCUJSQFINN0K5G&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200 13/0 0.003 - - 0 May 04 11:12:33 sogod [2530]: [WARN] <0x0x7feeec1868c8[WOWatchDogChild]> pid 2594 has been hanging in the same request for 1 minutes May 04 11:13:18 sogod [2530]: [WARN] <0x0x7feeec17bd58[WOWatchDogChild]> pid 2591 has been hanging in the same request for 3 minutes May 04 11:13:26 sogod [2530]: [WARN] <0x0x7feeec17ee08[WOWatchDogChild]> pid 2592 has been hanging in the same request for 4 minutes May 04 11:13:28 sogod [2530]: [WARN] <0x0x7feeec1570a8[WOWatchDogChild]> pid 2585 has been hanging in the same request for 8 minutes May 04 11:13:31 sogod [2588]: <0x0x7feeec661bb8[SOGoActiveSyncDispatcher]> Sleeping 10 seconds while detecting changes... May 04 11:13:33 sogod [2530]: [WARN] <0x0x7feeec1868c8[WOWatchDogChild]> pid 2594 has been hanging in the same request for 2 minutes May 04 11:13:41 sogod [2588]: yy.yy.yy.yy "POST /SOGo/Microsoft-Server-ActiveSync?User=username1&DeviceId=OH9LDN0MI50UTCUJSQFINN0K5G&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200 13/244 11.257 - - -204K May 04 11:13:43 sogod [2588]: yy.yy.yy.yy "POST /SOGo/Microsoft-Server-ActiveSync?User=username1&DeviceId=OH9LDN0MI50UTCUJSQFINN0K5G&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200 13/0 0.006 - - 0 May 04 11:14:18 sogod [2530]: [WARN] <0x0x7feeec17bd58[WOWatchDogChild]> pid 2591 has been hanging in the same request for 4 minutes May 04 11:14:26 sogod [2530]: [WARN] <0x0x7feeec17ee08[WOWatchDogChild]> pid 2592 has been hanging in the same request for 5 minutes May 04 11:14:28 sogod [2530]: [WARN] <0x0x7feeec1570a8[WOWatchDogChild]> pid 2585 has been hanging in the same request for 9 minutes May 04 11:14:33 sogod [2530]: [WARN] <0x0x7feeec1868c8[WOWatchDogChild]> pid 2594 has been hanging in the same request for 3 minutes May 04 11:14:45 sogod [2588]: <0x0x7feeec68a6c8[SOGoActiveSyncDispatcher]> Sleeping 10 seconds while detecting changes... May 04 11:14:55 sogod [2588]: yy.yy.yy.yy "POST /SOGo/Microsoft-Server-ActiveSync?User=username1&DeviceId=OH9LDN0MI50UTCUJSQFINN0K5G&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200 13/244 11.499 - - 28K May 04 11:14:59 sogod [2588]: yy.yy.yy.yy "POST /SOGo/Microsoft-Server-ActiveSync?User=username1&DeviceId=OH9LDN0MI50UTCUJSQFINN0K5G&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200 13/0 0.007 - - 0 May 04 11:15:18 sogod [2530]: [WARN] <0x0x7feeec17bd58[WOWatchDogChild]> pid 2591 has been hanging in the same request for 5 minutes May 04 11:15:26 sogod [2530]: [WARN] <0x0x7feeec17ee08[WOWatchDogChild]> pid 2592 has been hanging in the same request for 6 minutes May 04 11:15:28 sogod [2530]: [WARN] <0x0x7feeec1570a8[WOWatchDogChild]> safety belt -- sending KILL signal to pid 2585 May 04 11:15:28 sogod [2530]: <0x0x7feeec1570a8[WOWatchDogChild]> child 2585 exited May 04 11:15:28 sogod [2530]: <0x0x7feeec1570a8[WOWatchDogChild]> (terminated due to signal 9) May 04 11:15:28 sogod [2530]: <0x0x7feeec16f0a8[WOWatchDog]> child spawned with pid 21536 May 04 11:15:33 sogod [2530]: [WARN] <0x0x7feeec1868c8[WOWatchDogChild]> pid 2594 has been hanging in the same request for 4 minutes May 04 11:15:59 sogod [21536]: <0x0x7feeebfa6ef8[SOGoCache]> Cache cleanup interval set every 300.000000 seconds May 04 11:15:59 sogod [21536]: <0x0x7feeebfa6ef8[SOGoCache]> Using host(s) 'localhost' as server(s) May 04 11:15:59 sogod [21536]: [WARN] <0x0x7feeec4bca48[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists in DAV permissions table May 04 11:15:59 sogod [21536]: [WARN] <0x0x7feeec4bca48[SOGoWebDAVAclManager]> entry '{DAV:}write-properties' already exists in DAV permissions table May 04 11:15:59 sogod [21536]: [WARN] <0x0x7feeec4bca48[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already exists in DAV permissions table May 04 11:16:01 sogod [21536]: <0x0x7feeec0739e8[SOGoActiveSyncDispatcher]> Sleeping 10 seconds while detecting changes... May 04 11:16:11 sogod [21536]: yy.yy.yy.yy "POST /SOGo/Microsoft-Server-ActiveSync?User=username1&DeviceId=OH9LDN0MI50UTCUJSQFINN0K5G&DeviceType=iPhone&Cmd=Ping HTTP/1.1" 200 13/244 11.340 - - 8M May 04 11:16:11 sogod [21536]: [WARN] <0x0x7feeea2d02c0[WOxElemBuilder]> could not locate builders: WOxExtElemBuilder,WOxExtElemBuilder sogo_log.txt (33,300 bytes)

tfu 2015-05-10 14:29 reporter ~0008464	From what I see in the log changing above parameters won't help. There seems to be a problem while processing a itemOperation. A tcpdump will help to understand what's going on: tcpdump -i lo -s 0 -w /tmp/dump.pcap tcp and port 20000 You can send me the tcpdump and I'll have a look (tfu@aon.at).

Emmanuel dHumieres 2015-05-22 12:02 reporter ~0008522	I sent Thomas a tcpdump output. His analysis is the following : "From what I see in the tcpdump the client is busy with fetching mail attachment from the server. This is done via a ItemOperation per attachment. It seems that the device is set to auto-download all attachments. The response of ItemOperation has to be base64 encoding before it is sent to the client and this might take some CPU depending on the attachment size. Try to disable the attachment auto-download on the device and retry. " I asked the user to disable the auto-download option on his mobile, and no more hanging process. After that, contacts, calendars and mails were working fine, without server exhaustion. So ... not a bug !!! ;-)

Date Modified	Username	Field	Change
2015-05-06 17:33	Emmanuel dHumieres	New Issue
2015-05-06 17:33	Emmanuel dHumieres	File Added: sogod_traces.txt
2015-05-09 19:34	tfu	Note Added: 0008460
2015-05-10 10:18	Emmanuel dHumieres	Note Added: 0008462
2015-05-10 10:19	Emmanuel dHumieres	File Added: sogo_log.txt
2015-05-10 14:29	tfu	Note Added: 0008464
2015-05-22 12:02	Emmanuel dHumieres	Note Added: 0008522
2015-05-22 12:29	ludovic	Status	new => resolved
2015-05-22 12:29	ludovic	Resolution	open => no change required
2015-05-22 12:29	ludovic	Assigned To	=> ludovic