Hi,
In the last weeks we are facing a problem with our SOGo server.
From time to time (sometimes twice a day) the parent process consumes
full cpu.
We tried several things and are out of ideas right now. It looks like
the child processes are somehow occupied in a request but do not need
any cpu and the parent process does something like busy waiting for the
child processes.
We are a company with about 30 users. All of them are accessing sogo
through thunderbird 3.1.10 with lightning 1.0b2+105i, sogo-integrator
3.105 and sogo-connector 3.105.
The server was running with SOGo 1.3.7 till today and now with 1.3.8,
but the problem is still there.
Many users have a lot of calendar subscriptions and the biggest
calendars have up to 3500 events.
We have a ldap directory containing our company addresses with about
1900 entries. We gave it the id public so that is the default search
base for email addresses. We thought this might be a problem since we
found out that a listing through DAV took several seconds. Setting
SOGoLDAPQueryLimit 15 helped with searching speed but the problem still
occurs.
I attached our configuration (sogoconfig.txt), gdb backtraces from
parent (parent-gdb.txt) and one child (child-gdb.txt), and a typical
extract from a strace from the parent process (parent-strace.txt)
Does anyone else have this problem or maybe even have a solution?
In the logs we have several strange entries.
1.
Jul 18 12:15:56 sogod [22720]: [WARN] <0x0x15297a0[WOWatchDogChild]> pid
23581 has been hanging in the same request for 1 minutes
This brought me to the idea i mentioned before.
2.
Jul 18 12:16:09 sogod [23733]: |SOGo| terminating app, vMem size limit
(512 MB) has been reached (currently 624 MB)
Jul 18 12:16:09 sogod [22720]: [ERROR] <0x0x153e620[WOWatchDogChild]>
FAILURE receiving status for child 23733
Jul 18 12:16:09 sogod [22720]: [ERROR] <0x0x153e620[WOWatchDogChild]>
socket: <NGActiveSocket[0x0x14f9000]: mode=rw address=(nil)
connectedTo=<0x0x14a1650[NGLocalSocketAddress]:
/tmp/_ngsocket_0x58c0_0x1288540_000> receive-timeout=1.000s>
Jul 18 12:16:09 sogod [22720]: [ERROR] <0x0x153e620[WOWatchDogChild]>
exception: <NGSocketConnectionResetException: 0x14f3340>
NAME:NGSocketConnectionResetException REASON:reached end of stream
<NGActiveSocket[0x0x14f9000]: mode=rw address=(nil)
connectedTo=<0x0x14a1650[NGLocalSocketAddress]:
/tmp/_ngsocket_0x58c0_0x1288540_000> receive-timeout=1.000s> INFO:{errno
= 104; error = "Connection reset by peer"; stream = "{object =
<NGActiveSocket[0x0x14f9000]: mode=rw address=(nil)
connectedTo=<0x0x14a1650[NGLocalSocketAddress]:
/tmp/_ngsocket_0x58c0_0x1288540_000> receive-timeout=1.000s>;}"; }
Jul 18 12:16:09 sogod [22720]: <0x0x153e620[WOWatchDogChild]> sending
terminate signal to pid 23733
Jul 18 12:16:09 sogod [22720]: [ERROR] <0x0x153e620[WOWatchDogChild]>
FAILURE notifying child 23733
Jul 18 12:16:09 sogod [22720]: <0x0x153e620[WOWatchDogChild]> sending
terminate signal to pid 23733
Jul 18 12:16:09 sogod [22720]: <0x0x153e620[WOWatchDogChild]> child
23733 exited
Jul 18 12:16:09 sogod [22720]: <0x0x12ef4a0[WOWatchDog]> child spawned
with pid 23798
I tried to change SxVMemLimit but it then the error just comes with
higher numbers.
When hanging this error comes pretty often. About once or twice per minute.
3.
Jul 18 06:28:15 sogod [22500]: [WARN]
<0x0x24aead0[SOGoWebDAVAclManager]> entry '{DAV:}write' already exists
in DAV permissions table
Jul 18 06:28:15 sogod [22500]: [WARN]
<0x0x24aead0[SOGoWebDAVAclManager]> entry '{DAV:}write-properties'
already exists in DAV permissions table
Jul 18 06:28:15 sogod [22500]: [WARN]
<0x0x24aead0[SOGoWebDAVAclManager]> entry '{DAV:}write-content' already
exists in DAV permissions table
No idea what this warning tries to tell me.
4.
2011-07-18 06:28:19.659 sogod[22501] WARNING(-[SaxXMLReaderFactory
_loadBundlePath:infoDictionary:nameMap:typeMap:]): multiple parsers
available for MIME type 'text/x-vcard', using 'VSvCardSaxDriver' as
default for type text/x-vcard.
2011-07-18 06:28:19.659 sogod[22501] WARNING(-[SaxXMLReaderFactory
_loadBundlePath:infoDictionary:nameMap:typeMap:]): multiple parsers
available for MIME type 'text/calendar', using 'VSiCalSaxDriver' as
default for type text/calendar.
I don't think this is a real problem
5.
Jul 18 12:42:03 sogod [24839]: <0x0x7fca2d5d08c0[NSString]> Got invalid
multibyte sequence. ToEncode: UCS-2LE FromEncode: UTF-8.
Jul 18 12:42:03 sogod [24839]: <0x0x7fca2d5d08c0[NSString]> Got invalid
multibyte sequence. ToEncode: UCS-2LE FromEncode: UTF-8.
Jul 18 12:42:03 sogod [24839]: <0x0x7fca2d5d08c0[NSString]> Got invalid
multibyte sequence. ToEncode: UCS-2LE FromEncode: UTF-8.
Jul 18 12:42:03 sogod [24839]: <0x0x7fca2d5d08c0[NSString]> Got invalid
multibyte sequence. ToEncode: UCS-2LE FromEncode: UTF-8.
Jul 18 12:42:03 sogod [24839]: <0x0x7fca2d5d08c0[NSString]> Got invalid
multibyte sequence. ToEncode: UCS-2LE FromEncode: UTF-8.
Jul 18 12:42:03 sogod [24839]: <0x0x7fca2d5d08c0[NSString]> Got invalid
multibyte sequence. ToEncode: UCS-2LE FromEncode: UTF-8.
Jul 18 12:42:03 sogod [24839]: <0x0x7fca2d5d08c0[NSString]> Got invalid
multibyte sequence. ToEncode: UCS-2LE FromEncode: UTF-8.
Jul 18 12:42:03 sogod [24839]: <0x0x7fca2d5d08c0[NSString]> Got invalid
multibyte sequence. ToEncode: UCS-2LE FromEncode: UTF-8.
Again no idea what it tries to tell me.
Thanks
Raffael
--
users@sogo.nu
https://inverse.ca/sogo/lists
sogod SOGoDraftsFolderName INBOX.Drafts
sogod SOGoUserSources '(
{
CNFieldName = cn;
UIDFieldName = mail;
baseDN = "ou=employees,dc=a4d,dc=ch";
bindDN = "cn=sogo,dc=a4d,dc=ch";
bindFields = (
mail
);
bindPassword = secret;
canAuthenticate = YES;
encryption = STARTTLS;
hostname = a4d.ch;
id = logins;
isAddressBook = NO;
port = 389;
},
{
CNFieldName = cn;
IDFieldName = uid;
UIDFieldName = uid;
baseDN = "ou=employees,dc=a4d,dc=ch";
bindDN = "cn=sogo,dc=a4d,dc=ch";
bindPassword = secret;
canAuthenticate = NO;
displayName = "Team Adressen";
encryption = STARTTLS;
hostname = a4d.ch;
id = team;
isAddressBook = YES;
port = 389;
},
{
CNFieldName = cn;
IDFieldName = uid;
baseDN = "ou=contacts,dc=a4d,dc=ch";
bindDN = "cn=sogo,dc=a4d,dc=ch";
bindPassword = secret;
canAuthenticate = NO;
displayName = "Alle Adressen";
encryption = STARTTLS;
hostname = a4d.ch;
id = public;
isAddressBook = YES;
port = 389;
},
{
CNFieldName = cn;
MultipleBookingsFieldName = MultipleBookings;
UIDFieldName = mail;
baseDN = "ou=resources,dc=a4d,dc=ch";
bindDN = "cn=sogo,dc=a4d,dc=ch";
bindPassword = secret;
canAuthenticate = YES;
displayName = Resourcen;
encryption = STARTTLS;
hostname = a4d.ch;
id = resources;
isAddressBook = NO;
port = 389;
}
)'
sogod SOGoSMTPServer 127.0.0.1
sogod WOPort 20000
sogod SOGoLanguage German
sogod SOGoLDAPQueryLimit 15
sogod SOGoFirstDayOfWeek 1
sogod SOGoProfileURL mysql://sogo:secret@localhost:3306/sogo/sogo_user_profile
sogod SOGoTimeZone Europe/Zurich
sogod SOGoFoldersSendEMailNotifications YES
sogod SxVMemLimit 512
sogod SOGoMailingMechanism smtp
sogod OCSSessionsFolderURL
mysql://sogo:secret@localhost:3306/sogo/sogo_sessions_folder
sogod SOGoTrashFolderName INBOX.Trash
sogod SOGoSuperUsernames '(
"someonea4d.ch",
"someonee...@a4d.ch"
)'
sogod SOGoMailDomain a4d.ch
sogod OCSFolderInfoURL mysql://sogo:secret@localhost:3306/sogo/sogo_folder_info
sogod SOGoSentFolderName INBOX.Sent
sogod SOGoACLsSendEMailNotifications YES
sogod SOGoAppointmentSendEMailNotifications YES
#0 0x00007fff053836fd in gettimeofday ()
#1 0x00007fca2c38890a in gettimeofday () from /lib/libc.so.6
#2 0x00007fca2d0a1095 in GSTimeNow () at NSCalendarDate.m:295
#3 0x00007fca2d0d625a in -[NSGDate timeIntervalSinceNow] (self=0x14a0730,
_cmd=0x7fca2d5c28c0) at NSDate.m:1381
#4 0x00007fca2d172f9e in -[NSRunLoop acceptInputForMode:beforeDate:]
(self=0x160fd70, _cmd=0x7fca2d5c2930, mode=0x7fca2d5c1860, limit_date=0x14a0730)
at NSRunLoop.m:1137
#5 0x00007fca2d17352d in -[NSRunLoop runMode:beforeDate:] (self=0x160fd70,
_cmd=0x7fca2ee521e0, mode=0x7fca2d5c1860, date=0x14a0730) at NSRunLoop.m:1239
#6 0x00007fca2eb36dd2 in -[WOWatchDog run:argc:argv:] (self=0x12ef4a0,
_cmd=<value optimized out>, newAppName=<value optimized out>,
newArgC=<value optimized out>, newArgV=<value optimized out>) at
WOWatchDogApplicationMain.m:930
#7 0x00007fca2eb37cb4 in WOWatchDogApplicationMain (appName=0x6084a0, argc=7,
argv=0x7fff05262fe8) at WOWatchDogApplicationMain.m:1036
#8 0x0000000000401ab3 in main (argc=7, argv=0x7fff05262fe8,
env=0x7fff05263028) at sogod.m:53
#0 0x00007fca2c3c0b9f in poll () from /lib/libc.so.6
#1 0x00007fca2d224d43 in -[GSRunLoopCtxt pollUntil:within:] (self=0x12d6800,
_cmd=0x7fca2d5c28e0, milliseconds=411, contexts=0x151a820) at
GSRunLoopCtxt.m:390
#2 0x00007fca2d173138 in -[NSRunLoop acceptInputForMode:beforeDate:]
(self=0x160fd70, _cmd=0x7fca2d5c2930, mode=0x7fca2d5c1860, limit_date=0x15b3c70)
at NSRunLoop.m:1164
#3 0x00007fca2d17352d in -[NSRunLoop runMode:beforeDate:] (self=0x160fd70,
_cmd=0x7fca2ee521e0, mode=0x7fca2d5c1860, date=0x15b3c70) at NSRunLoop.m:1239
#4 0x00007fca2eb36dd2 in -[WOWatchDog run:argc:argv:] (self=0x12ef4a0,
_cmd=<value optimized out>, newAppName=<value optimized out>,
newArgC=<value optimized out>, newArgV=<value optimized out>) at
WOWatchDogApplicationMain.m:930
#5 0x00007fca2eb37cb4 in WOWatchDogApplicationMain (appName=0x6084a0, argc=7,
argv=0x7fff05262fe8) at WOWatchDogApplicationMain.m:1036
#6 0x0000000000401ab3 in main (argc=7, argv=0x7fff05262fe8,
env=0x7fff05263028) at sogod.m:53
gettimeofday({1310984491, 619316}, NULL) = 0
gettimeofday({1310984491, 619396}, NULL) = 0
gettimeofday({1310984491, 619447}, NULL) = 0
poll([{fd=4, events=POLLIN}, {fd=10, events=POLLIN}, {fd=8, events=POLLIN},
{fd=9, events=POLLIN}, {fd=7, events=POLLIN}, {fd=3, events=POLLIN}], 6, 453) =
1 ([{fd=9, revents=POLLIN}])
select(10, [9], NULL, NULL, {0, 0}) = 1 (in [9], left {0, 0})
ioctl(9, FIONREAD, [4]) = 0
recvfrom(9, "\1\0\0\0"..., 4, 0, NULL, NULL) = 4
wait4(-1, 0x7fff05262df4, WNOHANG, NULL) = 0
gettimeofday({1310984491, 670345}, NULL) = 0
gettimeofday({1310984491, 670400}, NULL) = 0
gettimeofday({1310984491, 670450}, NULL) = 0
poll([{fd=4, events=POLLIN}, {fd=10, events=POLLIN}, {fd=8, events=POLLIN},
{fd=9, events=POLLIN}, {fd=7, events=POLLIN}, {fd=3, events=POLLIN}], 6, 402) =
1 ([{fd=3, revents=POLLIN}])
sendto(9, "\0\0\0\0"..., 4, 0, NULL, 0) = 4
recvfrom(9, "\0\0\0\0"..., 4, 0, NULL, NULL) = 4
gettimeofday({1310984491, 916834}, NULL) = 0
wait4(-1, 0x7fff05262df4, WNOHANG, NULL) = 0
gettimeofday({1310984491, 916954}, NULL) = 0
gettimeofday({1310984491, 917006}, NULL) = 0
gettimeofday({1310984491, 917055}, NULL) = 0
#0 0x00007fc0292c7b9f in poll () from /lib/libc.so.6
#1 0x00007fc02b115a86 in NGDescriptorRecv (_fd=7, _buf=0xcb7b300 "", _len=512,
_flags=0, _timeout=120000) at NGDescriptorFunctions.m:215
#2 0x00007fc02b11a047 in -[NGActiveSocket readBytes:count:] (self=0x6915ee0,
_cmd=<value optimized out>, _buf=0xcb7b300, _len=512) at NGActiveSocket.m:731
#3 0x00007fc02b10c43f in -[NGBufferedStream readBytes:count:] (self=0x5b90960,
_cmd=0x7fc02b338eb0, _buf=0x7ffff61e6a57, _len=1) at NGBufferedStream.m:289
#4 0x00007fc02b112f6f in NGReadByteFromStream (_stream=0x5b90960) at
NGStream.m:160
#5 0x00007fc02b10bb5b in -[NGBufferedStream readByte] () at
NGBufferedStream.m:336
#6 0x00007fc02b117063 in -[NGByteBuffer la:] (self=0xcfc90a0, _cmd=<value
optimized out>, _la=0) at NGByteBuffer.m:215
#7 0x00007fc02b1166e7 in -[NGByteBuffer readByte] (self=0xcfc90a0, _cmd=<value
optimized out>) at NGByteBuffer.m:130
#8 0x00007fc02ba46e5f in -[NGHttpMessageParser parseRequestLine]
(self=0xa99e620, _cmd=0x7fc02bd63be0) at NGHttpMessageParser.m:78
#9 0x00007fc02ba46018 in -[NGHttpMessageParser parsePrefix] (self=0xa99e620,
_cmd=<value optimized out>) at NGHttpMessageParser.m:506
#10 0x00007fc02b607d4f in -[NGMimePartParser parsePart] (self=0xa99e620,
_cmd=<value optimized out>) at NGMimePartParser.m:1236
#11 0x00007fc02b6071d9 in -[NGMimePartParser parsePartFromStream:]
(self=0xa99e620, _cmd=<value optimized out>, _stream=<value optimized out>)
at NGMimePartParser.m:1269
#12 0x00007fc02ba467d8 in -[NGHttpMessageParser parseRequestFromStream:]
(self=0xa99e620, _cmd=0x7fc02bdb3440, _stream=0x5b90960) at
NGHttpMessageParser.m:697
#13 0x00007fc02ba948c3 in -[WOHttpTransaction parseRequestFromStream:]
(self=0x5c61730, _cmd=<value optimized out>, _in=0x5b90960) at
WOHttpTransaction.m:623
#14 0x00007fc02ba93627 in -[WOHttpTransaction _readRequest] (self=0x5c61730,
_cmd=0x7fc02bdb33d0) at WOHttpTransaction.m:365
#15 0x00007fc02ba94553 in -[WOHttpTransaction _run] (self=0x5c61730,
_cmd=<value optimized out>) at WOHttpTransaction.m:540
#16 0x00007fc02ba94778 in -[WOHttpTransaction run] (self=0x5c61730, _cmd=<value
optimized out>) at WOHttpTransaction.m:599
#17 0x00007fc02ba90929 in -[WOHttpAdaptor runConnection:] (self=0xd63d30,
_cmd=<value optimized out>, _socket=<value optimized out>) at
WOHttpAdaptor.m:384
#18 0x00007fc02ba90b3e in -[WOHttpAdaptor _handleAcceptedConnection:]
(self=0xd63d30, _cmd=<value optimized out>, _connection=0x6915ee0) at
WOHttpAdaptor.m:418
#19 0x00007fc02ba90fb9 in -[WOHttpAdaptor _handleConnection:] (self=0xd63d30,
_cmd=<value optimized out>, connection=0x6915ee0) at WOHttpAdaptor.m:477
#20 0x00007fc02ba91201 in -[WOHttpAdaptor acceptControlMessage:]
(self=0xd63d30, _cmd=<value optimized out>, aNotification=<value optimized out>)
at WOHttpAdaptor.m:516
#21 0x00007fc02a0383c5 in -[NSNotificationCenter _postAndRelease:]
(self=0xd1bc10, _cmd=0x7fc02a4ae630, notification=0x7d2a5d0) at
NSNotificationCenter.m:1070
#22 0x00007fc02a038c9c in -[NSNotificationCenter
postNotificationName:object:userInfo:] (self=0xd1bc10, _cmd=0x7fc02a4ae640,
name=0x7fc02b0c77e0,
object=0xfc2840, info=0x0) at NSNotificationCenter.m:1129
#23 0x00007fc02a038b51 in -[NSNotificationCenter postNotificationName:object:]
(self=0xd1bc10, _cmd=0x7fc02b0c76d0, name=0x7fc02b0c77e0, object=0xfc2840)
at NSNotificationCenter.m:1109
#24 0x00007fc02a12c4aa in -[GSRunLoopCtxt pollUntil:within:] (self=0xd66d60,
_cmd=0x7fc02a4c98e0, milliseconds=7992, contexts=0xfaaf40) at
GSRunLoopCtxt.m:598
#25 0x00007fc02a07a138 in -[NSRunLoop acceptInputForMode:beforeDate:]
(self=0x10a0490, _cmd=0x7fc02a4c9930, mode=0x7fc02a4c8860, limit_date=0xb9cd090)
at NSRunLoop.m:1164
#26 0x00007fc02a07a52d in -[NSRunLoop runMode:beforeDate:] (self=0x10a0490,
_cmd=0x7fc02bd19540, mode=0x7fc02a4c8860, date=0xb9cd090) at NSRunLoop.m:1239
#27 0x00007fc02b9f93e9 in -[WOCoreApplication run] (self=0x1135f40, _cmd=<value
optimized out>) at WOCoreApplication.m:576
#28 0x00000000004027a0 in -[SOGo run] (self=0x1135f40, _cmd=0x7fc02bd58df0) at
SOGo.m:275
#29 0x00007fc02ba3e43b in -[WOWatchDog _spawnChild:] (self=0xd7fa00,
_cmd=<value optimized out>, child=0x102fbc0) at WOWatchDogApplicationMain.m:563
#30 0x00007fc02ba3d5b6 in -[WOWatchDog _ensureChildren] (self=0xd7fa00,
_cmd=<value optimized out>) at WOWatchDogApplicationMain.m:653
#31 0x00007fc02ba3dc8e in -[WOWatchDog run:argc:argv:] (self=0xd7fa00,
_cmd=<value optimized out>, newAppName=<value optimized out>,
newArgC=<value optimized out>, newArgV=<value optimized out>) at
WOWatchDogApplicationMain.m:927
#32 0x00007fc02ba3ecb4 in WOWatchDogApplicationMain (appName=0x6084a0, argc=7,
argv=0x7ffff61e7778) at WOWatchDogApplicationMain.m:1036
#33 0x0000000000401ab3 in main (argc=7, argv=0x7ffff61e7778,
env=0x7ffff61e77b8) at sogod.m:53
