[ZODB-Dev] restart log weirdness

[Guido van Rossum]

> Oh this is pretty hysterical...
> 
> If you start up Zope with STUPID_LOG_FILE="duh" (not an absolute path, a
> relative path), *two* "duh" logfiles will be written.  One in the
> current working directory.  The other in the "var" directory of your
> instance.
> 
> The current working directory "duh" is messages from zdaemon.  The var
> directory "duh" is messages from Zope.

I was aware of this and passed an absolute filename.  Besides, I was
working with the ZEO storage server, which doesn't chdir.  (Why does
Zope chdir to var?)

> Do messages from the child process still make it to the logfile after
> the signal is sent?

Yes.

> It doesn't appear that the zLOG messages that are emitted by zdaemon
> *ever* make it to a zLOG-backed disk-file logfile, independent of
> signals, at least that I could tell by setting the STUPID_LOG_FILE
> envvar before starting Zope.

See above -- I did see all these.

> OTOH, if you start up in 'debug mode' (Z_DEBUG_MODE=1) with the
> STUPID_LOG_FILE envar set to '' (telling zLOG to log to stderr),
> zdaemon's messages are printed to the console along with the server's
> messages.

I've now tried this.  Same problem: after sending SIGUSR2, no more
messages from zdaemon, but the SIGTERM is still passed on (I see the
"Shutting down (shutdown)" message from the storage server).
Hm... but the SIGHUP no longer seems to be passed on in after this
point -- I don't see a "Shutting down (restart)" when I send a SIGHUP
in that case.

> > I can't find anything to explain this.
> 
> > Could it be that the subprocess and the parent process share a file
> > descriptor and that when the child closes it (as part of the reopening
> > procedure) the parent's file descriptor is somehow also closed?
> 
> I'm not sure if we're describing the same phenomenon, but I think *my*
> phenomenon is caused by the fact that the zdaemon process inherits a
> zLOG set up in such a way (by virtue of forking before some other later
> zLOG setup) that it's backed by MinimalLogger.  Because MinimalLogger is
> not initialized, it returns instead of actually logging.

Why would MinimalLogger not be initialized?  It initializes itself
on import.

> Meanwhile,
> under Zope at least, the child server's zLOG is backed by
> ZLogger.stupidFileLogger, which gets initialized on every write, so the
> child's messages do go to a logfile.  I still dont understand why I do
> see log messages from zdaemon under debug mode when the log goes to the
> console, but the machinations of this code are making my head spin so
> I'm giving up. ;-)
> 
> The logging system in Zope is such a mess that I'm not sure it's worth
> disentangling.  We should try hard to replace zLOG/ZLogger and the
> medusa logger with Vinay Sajip's PEP 282 logger (or something) soon.

I'm looking forward to that too.  But I'm not sure that what I'm
seeing has much to do with zLOG.  It smells more and more of a zdaemon
bug.

> I'm not sure that what you're seeing is at all related to any of this,
> but if the only problem really is that messages sent by zdaemon dont
> make it to a logfile while the child's messages do, I think the answer
> is to call it a feature until we can replace the logging system. ;-)

Um, SIGHUP no longer gets forwarded either it appears.  I'll
investigate more (using print statements rather than log messages :-).

--Guido van Rossum (home page: http://www.python.org/~guido/)