[ZCM] [ZC] 1142/ 8 Reject "Can't reopen Z2.log on SIGUSR2"

Sun Nov 13 14:49:04 EST 2005

Issue #1142 Update (Reject) "Can't reopen Z2.log on SIGUSR2"
 Status Rejected, Zope/bug medium
To followup, visit:
  http://www.zope.org/Collectors/Zope/1142

==============================================================
= Reject - Entry #8 by efge on Nov 13, 2005 2:49 pm

 Status: Pending => Rejected

It says "permission denied", this is a configuration problem.

________________________________________
= Edit - Entry #7 by efge on Nov 13, 2005 2:48 pm

 Changes: submitter email, edited transcript, importance (critical => medium)
________________________________________
= Comment - Entry #6 by djay on Jan 14, 2004 7:57 am

This problem is still occuring for me and worse, sometimes it doesn't just restart but hangs causing a loss of service for days until I discover it and restart. Surely even if something unexpected is happening with the Z2.log the server should fall into a screaming heap? Is there any fix for this? Is no one experiencing the same problem?
________________________________________
= Comment - Entry #5 by tseaver on Dec 6, 2003 10:48 pm

> = Comment - Entry #4 by djay on Dec 6, 2003 8:57 pm
> 
> as can be seen by this log except this bug is definatly causing resets.
>   That makes it most likely culprit for turning my server into a vegitable
>   occasionaly.
> 
> Anyone know how I can fix this?
> 
> ------
> 2003-12-07T07:37:04 INFO(0) Z2 Caught signal SIGUSR2
> ------
> 2003-12-07T07:37:05 INFO(0) Z2 Reopening log files
> ------
> 2003-12-07T07:37:05 PROBLEM(100) Z2 A handler for SIGUSR2 failed!
> Traceback (innermost last):
>   File /usr/lib/zope/lib/python/zdaemon/SignalHandler.py, line 58, in
>     signalHand
> ler
>   File /usr/lib/zope/lib/python/Signals/Signals.py, line 45, in
>     logfileReopenHan
> dler
>     (Object: reopen)
>   File /usr/lib/zope/ZServer/medusa/logger.py, line 55, in reopen
> IOError: [Errno 13] Permission denied: '/var/log/zope/default/Z2.log'

Please check the file ownership / group and writeability
of that log file;  I'm guessing that somehow, the file
was created as belonging to a different user than the
one Zope is running as (check the directory's ownership
and writeability, too).

You want to have the directory and the log files in it
owned and writeable by the user as whom Zope runs.
________________________________________
= Comment - Entry #4 by djay on Dec 6, 2003 8:57 pm

as can be seen by this log except this bug is definatly causing resets. That makes it most likely culprit for turning my server into a vegitable occasionaly.

Anyone know how I can fix this?

------
2003-12-07T07:37:04 INFO(0) Z2 Caught signal SIGUSR2
------
2003-12-07T07:37:05 INFO(0) Z2 Reopening log files
------
2003-12-07T07:37:05 PROBLEM(100) Z2 A handler for SIGUSR2 failed!
Traceback (innermost last):
  File /usr/lib/zope/lib/python/zdaemon/SignalHandler.py, line 58, in signalHand
ler
  File /usr/lib/zope/lib/python/Signals/Signals.py, line 45, in logfileReopenHan
dler
    (Object: reopen)
  File /usr/lib/zope/ZServer/medusa/logger.py, line 55, in reopen
IOError: [Errno 13] Permission denied: '/var/log/zope/default/Z2.log'
------
2003-12-07T07:37:06 ERROR(200) ZServer uncaptured python exception, closing chan
nel <ZServer.HTTPServer.zhttp_channel connected 127.0.0.1:32806 at 0x935762c cha
nnel#: 1417 requests:> (exceptions.ValueError:I/O operation on closed file [/usr
/lib/zope/lib/python/ThreadedAsync/LoopCallback.py|poll|124] [/usr/lib/zope/ZSer
ver/medusa/asyncore.py|handle_write_event|402] [/usr/lib/zope/ZServer/medusa/asy
nchat.py|handle_write|146] [/usr/lib/zope/ZServer/medusa/asynchat.py|initiate_se
nd|208] [/usr/lib/zope/ZServer/medusa/asynchat.py|refill_buffer|195] [/usr/lib/z
ope/ZServer/Producers.py|more|36] [/usr/lib/zope/ZServer/medusa/http_server.py|l
og|292] [/usr/lib/zope/ZServer/medusa/logger.py|log|256] [/usr/lib/zope/ZServer/
medusa/logger.py|log|86] [/usr/lib/zope/ZServer/medusa/logger.py|write|61])
------
2003-12-07T07:37:11 ERROR(200) zdaemon Process 3189 terminated normally, exit st
atus: 1
------
2003-12-07T07:37:11 INFO(0) zdaemon Started subprocess: pid 14594
------
________________________________________
= Comment - Entry #3 by djay on Dec 5, 2003 8:24 pm

I don't know if its misconfiguration or a but but something is critical for me in that my server is hanging and I'm left with a production system that is server nothing. 

A little more background may be in order. 
Its not a loaded site. It's quite new, not much traffic yet (although could always do with more http://www.eatmanifesto.com). I am also doing nothing to my knowledge to deliberatly rotate the logs. It's a debian install which my friend did which may put in some cron job to do this. I'm not sure.

Here is the latest error to occur. This one restarted successfully but certainly the searer has gone dead on other occasions

2003-12-06T07:37:28 INFO(0) Z2 Caught signal SIGUSR2
------
2003-12-06T07:37:28 INFO(0) Z2 Reopening log files
------
2003-12-06T07:37:28 PROBLEM(100) Z2 A handler for SIGUSR2 failed!
Traceback (innermost last):
  File /usr/lib/zope/lib/python/zdaemon/SignalHandler.py, line 58, in signalHand
ler
  File /usr/lib/zope/lib/python/Signals/Signals.py, line 45, in logfileReopenHan
dler
    (Object: reopen)
  File /usr/lib/zope/ZServer/medusa/logger.py, line 55, in reopen
IOError: [Errno 13] Permission denied: '/var/log/zope/default/Z2.log'
------
2003-12-06T08:15:58 ERROR(200) ZServer uncaptured python exception, closing chan
nel <ZServer.HTTPServer.zhttp_channel connected 127.0.0.1:54017 at 0x983e9ac cha
nnel#: 959 requests:> (exceptions.ValueError:I/O operation on closed file [/usr/
lib/zope/lib/python/ThreadedAsync/LoopCallback.py|poll|124] [/usr/lib/zope/ZServ
er/medusa/asyncore.py|handle_write_event|402] [/usr/lib/zope/ZServer/medusa/asyn
chat.py|handle_write|146] [/usr/lib/zope/ZServer/medusa/asynchat.py|initiate_sen
d|208] [/usr/lib/zope/ZServer/medusa/asynchat.py|refill_buffer|195] [/usr/lib/zo
pe/ZServer/Producers.py|more|36] [/usr/lib/zope/ZServer/medusa/http_server.py|lo
g|292] [/usr/lib/zope/ZServer/medusa/logger.py|log|256] [/usr/lib/zope/ZServer/m
edusa/logger.py|log|86] [/usr/lib/zope/ZServer/medusa/logger.py|write|61])
________________________________________
= Comment - Entry #2 by camil7 on Dec 4, 2003 12:25 pm

The problem sounds very much like a misconfiguration.

Personally I thing rotating the log files via USR2
seems to be broken under high load; if the server tries
to write something to the log while concurrently closing
and reopen the log, anything odd may happen.

Better dont use it, try 'cp Z2.log Z2.log.old && cat /dev/null > Z2.log' instead ... 

Anyway, even if it is a Zope bug, I do not think it is 
"critical".

________________________________________
= Request - Entry #1 by djay on Dec 4, 2003 4:08 am

My server is crashing every couple of days, Crashing as in not responding and not auto restarted. The only thing I can find in the logger is an exception due to a SIGUSR2 failure. A permission denied failure is occuring when trying to reopen Z2.log. Would this cause my symtoms? Is this a bug? or some misconfiguration?
==============================================================