Hello
I've seen repeated issues with my SOGo 1.3.11 server over last few
weeks, when previously had no issues at all over a period of several months.
ie logs in debug mode below.
localhost - - [27/Jan/2012:10:25:03 GMT] "REPORT
/SOGo/dav/xxxxx/Calendar/xxxx_personal/ HTTP/1.1" 207 125/245 0.032 - - 0
Jan 27 10:25:03 sogod [1207]: |SOGo| request took 1.812697 seconds to
execute
localhost - - [27/Jan/2012:10:25:03 GMT] "REPORT
/SOGo/dav/xxxxx/Calendar/xxx_personal/ HTTP/1.1" 207 4179/223 1.853
29074 85% 10M
Jan 27 10:25:05 sogod [1204]: |SOGo| request took 3.646416 seconds to
execute
localhost - - [27/Jan/2012:10:25:05 GMT] "REPORT
/SOGo/dav/xxxxx/Calendar/xxxx_personal/ HTTP/1.1" 207 6268/223 3.649
45748 86% 0
Jan 27 10:25:09 sogod [1203]: |SOGo| request took 8.294960 seconds to
execute
localhost - - [27/Jan/2012:10:25:09 GMT] "REPORT
/SOGo/dav/xxxxx/Calendar/xxxx_personal/ HTTP/1.1" 207 18394/223 8.308
159667 88% 3M
Jan 27 10:25:30 sogod [1206]: |SOGo| request took 29.164965 seconds to
execute
$9 92% 357M
Jan 27 10:25:30 sogod [1206]: |SOGo| terminating app, vMem size limit
(512 MB) has been reached (currently 559 MB)
Jan 27 10:25:30 sogod [1128]: <0x0x19b6dc0[WOWatchDogChild]> child 1206
exited
Jan 27 10:25:30 sogod [1128]: <0x0x1a709c0[WOWatchDog]> child spawned
with pid 2441
Then later on:
Jan 27 10:41:56 sogod [2441]: |SOGo| request took 0.152470 seconds to
execute
localhost - - [27/Jan/2012:10:41:56 GMT] "REPORT
/SOGo/dav/xxxxx/Calendar/personal/ HTTP/1.1" 207 125/245 0.154 - - 0
Jan 27 10:41:58 sogod [1128]: [ERROR] <0x0x19eb160[WOWatchDogChild]>
FAILURE receiving status for child 1207
Jan 27 10:41:58 sogod [1128]: [ERROR] <0x0x19eb160[WOWatchDogChild]>
socket: <NGActiveSocket[0x0x19b7150]: mode=rw address=(nil)
connectedTo=<0x0x1965b00[NGLocalSocketAddress]:
/tmp/_ngsocket_0x468_0x17c1cd0_000> receive-timeout=1.000s>
Jan 27 10:41:58 sogod [1128]: [ERROR] <0x0x19eb160[WOWatchDogChild]>
exception: <NGSocketTimedOutException: 0x19d4d80>
NAME:NGSocketTimedOutException REASON:the socket was shutdown
INFO:{errno = 11; error = "Resource temporarily unavailable"; stream =
"{object = <NGActiveSocket[0x0x19b7150]: mode=rw address=(nil)
connectedTo=<0x0x1965b00[NGLocalSocketAddress]:
/tmp/_ngsocket_0x468_0x17c1cd0_000> receive-timeout=1.000s>;}"; }
Jan 27 10:41:58 sogod [1128]: <0x0x19eb160[WOWatchDogChild]> sending
terminate signal to pid 1207
Jan 27 10:41:58 sogod [1128]: [ERROR] <0x0x19eb160[WOWatchDogChild]>
FAILURE notifying child 1207
Jan 27 10:41:58 sogod [1128]: <0x0x19eb160[WOWatchDogChild]> sending
terminate signal to pid 1207
Jan 27 10:41:59 sogod [1207]: [ERROR] <0x0x1900770[WOHttpAdaptor]> http
server caught: <NGCouldNotAcceptException: 0x20e56f0>
NAME:NGCouldNotAcceptException REASON:Could not accept: not a valid
socket descriptor INFO:(nil)
Jan 27 10:42:02 sogod [1128]: [ERROR] <0x0x19eb160[WOWatchDogChild]>
FAILURE receiving status for child 1207
Jan 27 10:42:02 sogod [1128]: [ERROR] <0x0x19eb160[WOWatchDogChild]>
socket: <NGActiveSocket[0x0x19b7150]: mode=rw address=(nil)
connectedTo=<0x0x1965b00[NGLocalSocketAddress]:
/tmp/_ngsocket_0x468_0x17c1cd0_000> receive-timeout=1.000s>
Jan 27 10:42:02 sogod [1128]: [ERROR] <0x0x19eb160[WOWatchDogChild]>
exception: <NGSocketConnectionResetException: 0x1961cc0>
NAME:NGSocketConnectionResetException REASON:reached end of stream
<NGActiveSocket[0x0x19b7150]: mode=rw address=(nil)
connectedTo=<0x0x1965b00[NGLocalSocketAddress]:
/tmp/_ngsocket_0x468_0x17c1cd0_000> receive-timeout=1.000s> INFO:{errno
= 104; error = "Connection reset by peer"; stream = "{object =
<NGActiveSocket[0x0x19b7150]: mode=rw address=(nil)
connectedTo=<0x0x1965b00[NGLocalSocketAddress]:
/tmp/_ngsocket_0x468_0x17c1cd0_000> receive-timeout=1.000s>;}"; }
Jan 27 10:42:02 sogod [1128]: <0x0x19eb160[WOWatchDogChild]> sending
terminate signal to pid 1207
Jan 27 10:42:02 sogod [1128]: [ERROR] <0x0x19eb160[WOWatchDogChild]>
FAILURE notifying child 1207
Jan 27 10:42:02 sogod [1128]: <0x0x19eb160[WOWatchDogChild]> sending
terminate signal to pid 1207
Jan 27 10:42:02 sogod [2441]: |SOGo| starting method 'REPORT' on uri
'/SOGo/dav/xxxx/Calendar/xxx_personal/'
Jan 27 10:42:02 sogod [2441]: <<0x0x1d97680[GCSFolder]>>D releasing
channel: <MySQL4Channel[0x0x1cbe8e0] connection=0x0x1815da0>
Jan 27 10:42:02 sogod [2441]: <<0x0x1d97680[GCSFolder]>>D releasing
channel: <MySQL4Channel[0x0x1e11b30] connection=0x0x1d642a0>
Jan 27 10:42:02 sogod [2441]: <<0x0x1d97680[GCSFolder]>>D releasing
channel: <MySQL4Channel[0x0x1cbe8e0] connection=0x0x1815da0>
Jan 27 10:42:02 sogod [2441]: |SOGo| request took 0.012297 seconds to
execute
localhost - - [27/Jan/2012:10:42:02 GMT] "REPORT
/SOGo/dav/xxxx/Calendar/xxx_personal/ HTTP/1.1" 207 125/245 0.014 - - 0
Jan 27 10:42:02 sogod [1128]: <0x0x19eb160[WOWatchDogChild]> child 1207
exited
Jan 27 10:42:02 sogod [1128]: <0x0x1a709c0[WOWatchDog]> child spawned
with pid 2669
Then this particular failure repeats approx every 10 mins, until I did a
sudo service sogo restart which stopped the issue.
We have approx 30 users using Thunderbird 3.1.x/Lightning for
calendars/tasks and have 5 WOWorkers with SxVMemLimit set to 512MB;
previously set to 384MB with no problems like this for months.
Using Ubuntu 10.04 LTS server, with 2GB ram and a MYSQl db for SQL auth.
I've also seen lots of times recently the following :-
Jan 25 09:57:20 sogod [27399]: |SOGo| terminating app, vMem size limit
(512 MB) has been reached (currently 564 MB)
Jan 25 09:57:20 sogod [27376]: <0x0x26aa6f0[WOWatchDogChild]> child
27399 exited
Jan 25 09:57:20 sogod [27376]: <0x0x272ff40[WOWatchDog]> child spawned
with pid 27721
Then, at around 8am each morning normally SOGo will check for existing
worker processes and restart them if necessary. But if I had issues with
SOGo processes having to restart the previous day, then I see errors as
below:
Jan 26 08:28:13 sogod [525]: version 1.3.11 (build @vizzini.inverse.ca
201112122226) -- starting
Jan 26 08:28:13 sogod [525]: vmem size check enabled: shutting down app
when vmem > 512 MB
Jan 26 08:28:13 sogod [525]: <0x0x1e4a1d0[SOGoProductLoader]> SOGo
products loaded from '/usr/lib/GNUstep/SOGo':
Jan 26 08:28:13 sogod [525]: <0x0x1e4a1d0[SOGoProductLoader]>
ContactsUI.SOGo, AdministrationUI.SOGo, SchedulerUI.SOGo,
MailPartViewers.SO$
Jan 26 08:28:14 sogod [525]: [WARN] <0x0x1fadf40[WOWatchDog]> listening
socket: attempt 1 failed
Jan 26 08:28:15 sogod [525]: [WARN] <0x0x1fadf40[WOWatchDog]> listening
socket: attempt 2 failed
Jan 26 08:28:16 sogod [525]: [WARN] <0x0x1fadf40[WOWatchDog]> listening
socket: attempt 3 failed
Jan 26 08:28:17 sogod [525]: [WARN] <0x0x1fadf40[WOWatchDog]> listening
socket: attempt 4 failed
Jan 26 08:28:18 sogod [525]: [WARN] <0x0x1fadf40[WOWatchDog]> listening
socket: attempt 5 failed
Jan 26 08:28:19 sogod [525]: [ERROR] <0x0x1fadf40[WOWatchDog]> unable to
listen on specified port, check that no other process is already us$
Jan 26 09:15:31 sogod [1124]: version 1.3.11 (build @vizzini.inverse.ca
201112122226) -- starting
Jan 26 09:15:31 sogod [1124]: vmem size check enabled: shutting down app
when vmem > 512 MB
Jan 26 09:15:31 sogod [1124]: <0x0x11a57b0[SOGoProductLoader]> SOGo
products loaded from '/usr/lib/GNUstep/SOGo':
Jan 26 09:15:31 sogod [1124]: <0x0x11a57b0[SOGoProductLoader]>
ContactsUI.SOGo, AdministrationUI.SOGo, SchedulerUI.SOGo, MailPartViewers.S$
Jan 26 09:15:31 sogod [1124]: <0x0x1309530[WOWatchDog]> listening on *:20000
Jan 26 09:15:31 sogod [1124]: <0x0x1309530[WOWatchDog]> watchdog process
pid: 1124
Jan 26 09:15:31 sogod [1124]: <0x0x7fa5bac23ca0[WOWatchDogChild]>
watchdog request timeout set to 10 minutes
Jan 26 09:15:31 sogod [1124]: <0x0x1309530[WOWatchDog]> preparing 5 children
Jan 26 09:15:31 sogod [1124]: <0x0x1309530[WOWatchDog]> child spawned
with pid 1201
Jan 26 09:15:31 sogod [1124]: <0x0x1309530[WOWatchDog]> child spawned
with pid 1202
Jan 26 09:15:31 sogod [1124]: <0x0x1309530[WOWatchDog]> child spawned
with pid 1203
Jan 26 09:15:31 sogod [1124]: <0x0x1309530[WOWatchDog]> child spawned
with pid 1204
Jan 26 09:15:31 sogod [1124]: <0x0x1309530[WOWatchDog]> child spawned
with pid 1205
Jan 26 09:15:32 sogod [1202]: <0x0x129d5c0[SOGoCache]> Cache cleanup
interval set every 300.000000 seconds
Jan 26 09:15:32 sogod [1202]: <0x0x129d5c0[SOGoCache]> Using host(s)
'127.0.0.1' as server(s)
Jan 26 09:15:32 sogod [1205]: <0x0x10f7580[SOGoCache]> Cache cleanup
interval set every 300.000000 seconds
Jan 26 09:15:32 sogod [1205]: <0x0x10f7580[SOGoCache]> Using host(s)
'127.0.0.1' as server(s)
Jan 26 09:15:32 sogod [1204]: <0x0x129d680[SOGoCache]> Cache cleanup
interval set every 300.000000 seconds
Jan 26 09:15:32 sogod [1204]: <0x0x129d680[SOGoCache]> Using host(s)
'127.0.0.1' as server(s)
Jan 26 09:15:32 sogod [1201]: <0x0x12e2ba0[SOGoCache]> Cache cleanup
interval set every 300.000000 seconds
Jan 26 09:15:32 sogod [1201]: <0x0x12e2ba0[SOGoCache]> Using host(s)
'127.0.0.1' as server(s)
Jan 26 09:15:32 sogod [1203]: <0x0x129d5c0[SOGoCache]> Cache cleanup
interval set every 300.000000 seconds
Jan 26 09:15:32 sogod [1203]: <0x0x129d5c0[SOGoCache]> Using host(s)
'127.0.0.1' as server(s)
I really need some help with this.
Julian Robbins
UK
My .GNUStepsDefault Config
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE plist PUBLIC "-//GNUstep//DTD plist 0.9//EN"
"http://www.gnustep.org/plist-0_9.xml";>
<plist version="0.9">
<dict>
<key>NSGlobalDomain</key>
<dict>
</dict>
<key>sogod</key>
<dict>
<key>GCSFolderDebugEnabled</key>
<string>YES</string>
<key>NGImap4DisableIMAP4Pooling</key>
<string>NO</string>
<key>OCSFolderInfoURL</key>
<string>mysql://root:[email protected]:3306/sogo/sogo_folder_info</string>
<key>OCSFolderManagerSQLDebugEnabled</key>
<string>YES</string>
<key>OCSSessionsFolderURL</key>
<string>mysql://root:[email protected]:3306/sogo/sogo_sessions_folder</string>
<key>SOGoACLsSendEMailNotifications</key>
<string>=</string>
<key>SOGoAppointmentSendEMailNotifications</key>
<string>YES</string>
<key>SOGoAppointmentSendEMailReceipts</key>
<string>=</string>
<key>SOGoCalendarDefaultRoles</key>
<array>
<string>PublicViewer</string>
<string>ConfidentialDAndTViewer</string>
</array>
<key>SOGoContactsDefaultRoles</key>
<array>
<string>ObjectViewer</string>
<string>ObjectCreator</string>
</array>
<key>SOGoDebugRequests</key>
<string>YES</string>
<key>SOGoDraftsFolderName</key>
<string>INBOX/Drafts</string>
<key>SOGoEnablePublicAccess</key>
<string>YES</string>
<key>SOGoFoldersSendEMailNotifications</key>
<string>=</string>
<key>SOGoIMAPAclConformsToIMAPExt</key>
<string>YES</string>
<key>SOGoIMAPServer</key>
<string>comms.q-par.com</string>
<key>SOGoImapDebugEnabled</key>
<string>YES</string>
<key>SOGoLanguage</key>
<string>English</string>
<key>SOGoLoginModule</key>
<string>Calendar</string>
<key>SOGoMailDomain</key>
<string>q-par.com</string>
<key>SOGoMailingMechanism</key>
<string>smtp</string>
<key>SOGoMemcachedHost</key>
<string>127.0.0.1</string>
<key>SOGoProfileURL</key>
<string>mysql://root:[email protected]:3306/sogo/sogo_user_profile</string>
<key>SOGoSMTPServer</key>
<string>xxxx</string>
<key>SOGoSentFolderName</key>
<string>INBOX/Sent</string>
<key>SOGoSuperUsernames</key>
<array>
<string>xxxxx</string>
<string>xxxxx</string>
</array>
<key>SOGoTimeZone</key>
<string>Europe/London</string>
<key>SOGoTrashFolderName</key>
<string>INBOX/Trash</string>
<key>SOGoUIxDebugEnabled</key>
<string>YES</string>
<key>SOGoUserSources</key>
<array>
<dict>
<key>KindFieldName</key>
<string>description</string>
<key>MultipleBookingsFieldName</key>
<string>multiplebook</string>
<key>canAuthenticate</key>
<string>YES</string>
<key>displayName</key>
<string>SOGo Users</string>
<key>id</key>
<string>users</string>
<key>isAddressBook</key>
<string>YES</string>
<key>type</key>
<string>sql</string>
<key>userPasswordAlgorithm</key>
<string>md5</string>
<key>viewURL</key>
<string>mysql://root:[email protected]:3306/sogo/sogo_users</string>
</dict>
</array>
<key>SoDebugBaseURL</key>
<string>YES</string>
<key>SoDebugKeyLookup</key>
<string>YES</string>
<key>SxVMemLimit</key>
<string>512</string>
<key>WOWorkersCount</key>
<string>5</string>
</dict>
</dict>
</plist>
--
[email protected]
https://inverse.ca/sogo/lists
