[Zope3-Users] Logging level for transcript.log

Vinny vinny-mail-01+zope3users at palaceofretention.ca
Sun Feb 4 20:16:14 EST 2007


Hi Jim,

Thanks for answering.  I appreciate you're a busy man.  
Further discussion follows below inline.

Vinny

On Sat, 03 Feb 2007 11:15:58 -0500
Jim Fulton <jim at zope.com> wrote:
> Vinny wrote:
> > Hi,
> > 
> > Where can I find the configuration setting for the 
> > logging level used in the transcript.log file?
> > 
> > I have tried looking in etc/zope.conf, etc/zdaemon.conf
> > and came up empty handed.  I can see ERROR levels easily
> > enough. 
> 
> The transcript log is created by zdaemon and captures
> all output from the application being run, in this case,
> Zope.  It has nothing to do with the Python logging system
> and has no concept of log level.

So, the zdaemon is catching _all_ output?  Including output
destined to a specified file?  Preventing it from getting to
file?  Is this expected behaviour?  Can anyone reproduce this?

It is entirely possible that I am doing something completely
stupid.  My background is in cold fusion (yes, I know, eeww),
so I am out of my depth with both python's object orientation 
_and_ zope 3 being new to me.  Hence, I hope to determine
some sort of process flow by placing logging statements all
over the place.

> 
>  > This works and shows up in transcript.log:
>  >
>  > import logging
>  >
>  > logging.basicConfig(level=logging.DEBUG,
>  >                     format='%(asctime)s %(levelname)-8s
>  > %(message)s', datefmt='%a, %d %b %Y %H:%M:%S',
>  >                     filename='/usr/local/www/Zope3/mv/lib/python/hello/utility/log',
>  >                     filemode='a')
>  >
>  > logging.error('Pack my box with %d dozen %s', 5, 'liquor jugs')
>  >
>  > But this does not show up in transcript.log:
>  >
>  > logging.debug('Pack my box with %d dozen %s', 5, 'liquor jugs')
>  >
>  > Both messages end up in my local log file.  

Hmm, my statement above is not correct.  I was confused (and still
am, I guess).  The messages are not being written to my log
file when zope starts/runs (see above and below).  They are written when
I run the __init__.py files manually, though.  I made sure that
the access permissions on the file/directory were ok for user www.
Doesn't seem to make a difference.  The messages are not written
to my specified file (even to one in the /tmp directory). 

[snip]

>  > with zope.  Where do I find out about the zope logger?
> 
> That's a good question.  Logging is controlled through ZConfig and
> I'm not aware that our ZConfig setup is documented, except through
> comments in sample zope.conf files.  I'm not a big fan of how we
> currently do configuration.
> 
> I think you want to change the logging level by adding a level
> option to the event log:
> 
> <eventlog>
>    level debug
> 
>    <logfile>
>      path $LOGDIR/z3.log
>      formatter zope.exceptions.log.Formatter
>    </logfile>
> 
>    <logfile>
>      path STDOUT
>      formatter zope.exceptions.log.Formatter
>    </logfile>
> </eventlog>
> 
> In this example, I have set the logging level for the
> event logger to debug, so you will see debug messages.
> The default logging level is info.

Using the 'level debug' config. option certainly has added
a great deal of interesting information to the transcript.log.
I thank you for that, in as much as it will provide future
enlightenment on just what is going on at zope startup. 
It has also allowed me to use the logging.debug setting
even though, now that I know the default level is INFO,
I should probably just be using logging.info().

> 
> Note that in the example above we are sending output to
> 2 places, z3.log and standard output.  Because the zdaemon
> transcript log captures standard output, it is the standard
> output logger that affects the transcript log.  IMO, it is
> silly to log to two places. I would just log to standard
> output.  (The only problem with this is that older versions
> os zdaemon don't support log rotation. I have fixed this
> in the latest version of zdaemon.)

The logging in two places confused me at first.  I didn't know
which log was more accurate, or in use.  I only surmised 
after a while that transcript held some of the errors that I 
usually came across and that z3 didn't.  Although there doesn't
seem to be detectable, by me, consistency in what gets logged
where.  

> 
> Jim
> 

I suppose my last question is: Can I use the python logging
facility to write my own logfiles?  What have I missed?
I ought to be able to write my own logs, eh?

My little 'hello' application has a simple __init__.py that 
looks like this:

/usr/local/www/Zope3/mv/lib/python/hello/__init__.py
=============
import logging

logging.basicConfig(level=logging.DEBUG,
                    format='%(asctime)s %(levelname)-8s %(message)s',
                    datefmt='%a, %d %b %Y %H:%M:%S',
                    filename='/usr/local/www/Zope3/mv/lib/python/hello/utility/log',
                    filemode='a')
logging.error('Anything %d times %s in %s', 5, 'a day', 'hello/__init__.py')
=============

..and further experimental logging:

/usr/local/www/Zope3/mv/lib/python/hello/utility/__init__.py
==============
# testing utility detection and creation
# 
import logging

logging.basicConfig(level=logging.DEBUG,
                    format='%(asctime)s %(levelname)-8s %(message)s',
                    datefmt='%a, %d %b %Y %H:%M:%S',
                    filename='/tmp/hellolog',
                    filemode='a')
logging.debug('Pack my box with %d dozen %s', 5, 'liquor jugs')

from persistent import Persistent
from zope.interface import implements
from zope.app.folder.folder import Folder
from zope.app.folder.interfaces import IFolder

class IMyFolder(IFolder):
    pass

class MyFolder(Folder):
    implements(IMyFolder)
    logging.info('Within %s', 'MyFolder')
    
    def __init__(self, name):
        logging.debug('Within %s at %s creating %s', 'MyFolder', '__init__', name)
        self.name = name

from zope.publisher.browser import BrowserPage, TestRequest

context = object()
request = TestRequest()

class MakeMyFolder(BrowserPage):

    def __call__(self):
        logging.info('Within %s', 'MakeMyFolder')
        my_folder = MyFolder(name='one')
        #site = removeSecurityProxy(self.context)
        #alsoProvides(site, IWCSite)
        #self.request.response.redirect('.')

# I eventually want to create folders and so forth programatically
# for a ZMI-free install.  Not sure how yet.
  
huh = MakeMyFolder(context, request)()

=================


I get the following relevant info. in the transcript.log
when starting up zope (on FreeBSD 6.2) using:

# /usr/local/etc/rc.d/zope3 restart /usr/local/www/Zope3/mv  

============

[snip]
2007-02-04T16:43:02 DEBUG config include /usr/local/www/Zope3/mv/etc/package-includes/hello-configure.zcml
------
2007-02-04T16:43:02 ERROR root Anything 5 times a day in hello/__init__.py
------
2007-02-04T16:43:02 DEBUG config include /usr/local/www/Zope3/mv/lib/python/hello/configure.zcml
------
2007-02-04T16:43:02 DEBUG config include /usr/local/www/Zope3/mv/lib/python/hello/browser/configure.zcml
------
2007-02-04T16:43:02 DEBUG root Pack my box with 5 dozen liquor jugs
------
2007-02-04T16:43:02 INFO root Within MyFolder
------
2007-02-04T16:43:02 INFO root Within MakeMyFolder
------
2007-02-04T16:43:02 DEBUG root Within MyFolder at __init__ creating one
------
2007-02-04T16:43:02 DEBUG config include /usr/local/www/Zope3/mv/lib/python/hello/utility/configure.zcml
------
[snip]
==============

/usr/local/www/Zope3/mv/lib/python/hello/utility: ls -la
total 12
drwxrwxr-x  2 mv   www   512 Feb  4 16:43 .
drwxr-xr-x  5 mv   www   512 Feb  4 15:23 ..
-rwxr-xr-x  1 mv   www  1238 Feb  4 16:42 __init__.py
-rw-r--r--  1 www  www  1913 Feb  4 16:43 __init__.pyc
-rwxr-xr-x  1 mv   www   282 Feb  4 15:34 configure.zcml
-rwxrwxr-x  1 www  www   955 Feb  4 15:52 log

============

Thanks to anyone for their consideration!

Vinny


More information about the Zope3-users mailing list