View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0001865SOGoPackaging (Debian)public2012-07-09 13:302012-07-25 15:40
Reportermaxb Assigned Tojraby 
PrioritynormalSeveritymajorReproducibilitysometimes
Status resolvedResolutionfixed 
Product Version1.3.16 
Target Version1.3.17Fixed in Version1.3.17 
Summary0001865: daily log rotation stops sogo due to old process taking too long to exit
Description

I have recently switched from a manual installation of SOGo to using the provided Debian packages on Debian squeeze.

Since switching, most days, SOGo stops and fails to restart when cron runs logrotate. The logrotate executes "/etc/init.d/sogo restart", but usually the old process still has the listening tcp socket open when the new one tries to start, so it exits after 5 tries to open the socket.

Additional Information

Old (rotated) file:

Jul 09 06:22:21 sogod [4722]: |SOGo| starting method 'REPORT' on uri '/SOGo/dav/mdyson/Calendar/personal/'
Jul 09 06:22:21 sogod [4722]: |SOGo| request took 0.014786 seconds to execute
10.9.64.100 - - [09/Jul/2012:06:22:21 GMT] "REPORT /SOGo/dav/mdyson/Calendar/personal/ HTTP/1.1" 207 125/182 0.016 - - 0
Jul 09 06:25:03 sogod [3152]: <0x0x2a52980[WOWatchDog]> Terminating with SIGINT or SIGTERM
Jul 09 06:25:03 sogod [3152]: <0x0x29a2870[WOWatchDogChild]> sending terminate signal to pid 4722
Jul 09 06:25:03 sogod [3152]: <0x0x2a52980[WOWatchDog]> Terminating with SIGINT or SIGTERM
Jul 09 06:25:03 sogod [3152]: <0x0x2a52980[WOWatchDog]> Terminating with SIGINT or SIGTERM
Jul 09 06:25:03 sogod [3152]: <0x0x2a52980[WOWatchDog]> Terminating with SIGINT or SIGTERM
... repeated many many times ...
Jul 09 06:25:22 sogod [3152]: <0x0x2a52980[WOWatchDog]> Terminating with SIGINT or SIGTERM
Jul 09 06:25:23 sogod [3152]: <0x0x2a52980[WOWatchDog]> Terminating with SIGINT or SIGTERM
Jul 09 06:25:23 sogod [3152]: <0x0x2a52980[WOWatchDog]> Terminating with SIGINT or SIGTERM
Jul 09 06:25:46 sogod [4722]: [ERROR] <0x0x2a5c580[WOHttpAdaptor]> failure notifying watchdog we are busy: <NGSocketShutdownDuringWriteException: 0x2cf1e00> NAME:NGSocketShutdownDuringWriteException REASON:the socket was shutdown INFO:{er
Jul 09 06:25:46 sogod [4722]: |SOGo| starting method 'REPORT' on uri '/SOGo/dav/sogo-calendars/Calendar/1574-4FA1F100-B-610C858/'
Jul 09 06:25:46 sogod [4722]: |SOGo| request took 0.038364 seconds to execute
10.9.64.100 - - [09/Jul/2012:06:25:46 GMT] "REPORT /SOGo/dav/sogo-calendars/Calendar/1574-4FA1F100-B-610C858/ HTTP/1.1" 207 125/182 0.039 - - 8K
Jul 09 06:25:46 sogod [4722]: [ERROR] <0x0x2a5c580[WOHttpAdaptor]> failure notifying watchdog we are ready: <NGSocketException: 0x2da7170> NAME:NGSocketException REASON:NGActiveSocket is not open

New log file:

Jul 09 06:25:23 sogod [5967]: version 1.3.16 (build @vizzini.inverse.ca 201206071319) -- starting
Jul 09 06:25:23 sogod [5967]: vmem size check enabled: shutting down app when vmem > 1024 MB
Jul 09 06:25:23 sogod [5967]: <0x0x193cd10[SOGoProductLoader]> SOGo products loaded from '/usr/lib/GNUstep/SOGo':
Jul 09 06:25:23 sogod [5967]: <0x0x193cd10[SOGoProductLoader]> CommonUI.SOGo, ContactsUI.SOGo, SchedulerUI.SOGo, Mailer.SOGo, MailerUI.SOGo, Appointments.SOGo, MainUI.SOGo, MailPartViewers.SOGo, AdministrationUI.SOGo, Contacts.SOGo, Pre
Jul 09 06:25:23 sogod [5967]: [WARN] <0x0x1ae3980[WOWatchDog]> listening socket: attempt 1 failed
Jul 09 06:25:24 sogod [5967]: [WARN] <0x0x1ae3980[WOWatchDog]> listening socket: attempt 2 failed
Jul 09 06:25:25 sogod [5967]: [WARN] <0x0x1ae3980[WOWatchDog]> listening socket: attempt 3 failed
Jul 09 06:25:26 sogod [5967]: [WARN] <0x0x1ae3980[WOWatchDog]> listening socket: attempt 4 failed
Jul 09 06:25:27 sogod [5967]: [WARN] <0x0x1ae3980[WOWatchDog]> listening socket: attempt 5 failed
Jul 09 06:25:28 sogod [5967]: [ERROR] <0x0x1ae3980[WOWatchDog]> unable to listen on specified port, check that no other process is already using it

TagsNo tags attached.

Activities

axelr

axelr

2012-07-20 08:00

reporter   ~0004182

Just to confirm we are experiencing the same problem with Debian(squeeze).
I just increased the restart timeout to 10s in the init script, let's see if this helps.
jraby

jraby

2012-07-23 17:49

viewer   ~0004208

Thanks for reporting this, this behavior was fixed long ago in the rpm packages by using copytruncate to avoid restarting sogo, but we were not using the same logrotate script for debian packages.

This is now fixed and will be available in the next release.

Meanwhile, you might want to fix the logrotate file:
<pre>

--- Scripts/logrotate 5ac300f25f43168b49020fd21b2dbaf8c8c240d5
+++ Scripts/logrotate ac5a8f3bc947e43bae7dfc28fe15282d266079a7
@@ -5,9 +5,5 @@
compress
delaycompress
notifempty

  • create 640 sogo sogo
  • sharedscripts
  • postrotate
  • /etc/init.d/sogod restart > /dev/null
  • endscript
  • copytruncate
    }

</pre>

Issue History

Date Modified Username Field Change
2012-07-09 13:30 maxb New Issue
2012-07-20 08:00 axelr Note Added: 0004182
2012-07-23 12:40 ludovic Status new => assigned
2012-07-23 12:40 ludovic Assigned To => jraby
2012-07-23 17:49 jraby Note Added: 0004208
2012-07-23 17:49 jraby Status assigned => resolved
2012-07-23 17:49 jraby Resolution open => fixed
2012-07-23 18:01 ludovic Fixed in Version => 1.3.17
2012-07-25 15:40 francis Target Version => 1.3.17