Hi guys,
first of all, many thanks to SOGo team for this brilliant project.
I used SOGo for several years and I install it for my customers who are
very happy with this exchange alternative ;-)
Unfortunately, I have recently installed SOGo for one of my customers
and we have a very strange behaviour.
We start SOGo service and after a "random" time (few minutes or few
hours), we observe via top linux command one, then several sogod
processus running at 100% cpu. We see in SOGo log "pid xxxx has been
hanging in the same request for x minutes"
and then watchdog messages :
"safety belt -- sending KILL signal to pid xxxx"
child xxxx exited
(terminated due to signal 9)
child spawned with pid xxxx'
I know the meaning of previous messages which are finally quite normal,
but in the meantime, 5 or 7 process SOGOd running at the same time at
100 % seem to be strange. I never encounter this kind of issue so I
started to make some analysis.
I first check with strace command to see system calls made by SOGOd
process : nothing was displayed except the kill system call made by the
watchdog. So it's 100% "pure" cpu usage.
I have installed the debug tools in order to provide you some backtrace.
You will find below 2 different backtraces done at 2 different moments.
They are a little bit different, but the others traces I've made look
similar.
Please can you help me as I try to push this solution for this
customer ?
There are right now 5 test users and 5 activesync enabled.
Thanks for your help, especially to indicate me if I need to open a bug.
Regards,
Emmanuel
________________________________________________________________________
Here are 2 backtraces of the 100% sogod process :
=========================== 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 ()
