General discussion on installation and configuration of SOGo

Text archives Help


[SOGo] SOGo keeps falling over when previously fine


Chronological Thread 
  • From: Julian Robbins < >
  • To: users < >
  • Subject: [SOGo] SOGo keeps falling over when previously fine
  • Date: Fri, 27 Jan 2012 12:36:31 +0000
  • Organization: Q-par Angus Ltd

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:xxxxx@127.0.0.1:3306/sogo/sogo_folder_info</string>
<key>OCSFolderManagerSQLDebugEnabled</key>
<string>YES</string>
<key>OCSSessionsFolderURL</key>
<string>mysql://root:xxxxxx@127.0.0.1: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:xxxxx@127.0.0.1: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:xxxxxx@127.0.0.1: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>




Archive powered by MHonArc 2.6.18.

Top of page