fine grain logging cotrol

[Eric S. Johansson]

I need to to be able to conditionally log based on the method the log
statement is in and one other factor like a log level. in order to do
so, I need to be able to automatically find out the name of the method
and its class but I haven't found out how to do that yet.

for example,

class catus(Felis):
def Siamese_cat( yowl, purr, demand_food):

...
log("state of litter box %s"% litter_box.smell, level = 1)
If the table of methods logged contains "catus.Siamese_cat", then I
would expect to see the output of the log statements in a log file. If
not then I wouldn't see anything in the log.

Has somebody done this already? Is it even possible to do without
manually adding the class and method information for every log statement?

a related question is using signals for reloading configurations etc. I
have to find any good examples of how to use signals to cause a
long-running process to reload external data. Any good pointers?
--- eric

[Peter Otten]

Eric S. Johansson wrote:

I need to to be able to conditionally log based on the method the log
statement is in and one other factor like a log level. in order to do
so, I need to be able to automatically find out the name of the method
and its class but I haven't found out how to do that yet.

for example,

class catus(Felis):
def Siamese_cat( yowl, purr, demand_food):

...
log("state of litter box %s"% litter_box.smell, level = 1)
If the table of methods logged contains "catus.Siamese_cat", then I
would expect to see the output of the log statements in a log file. If
not then I wouldn't see anything in the log.

Has somebody done this already? Is it even possible to do without
manually adding the class and method information for every log statement?

a related question is using signals for reloading configurations etc. I
have to find any good examples of how to use signals to cause a
long-running process to reload external data. Any good pointers?

Instead of rolling your own, use the logging package which can handle
everything but the class info out of the box (levels are spelt as method
names info(), warn() etc.).

import logging

class LoggedType(type):
def __new__(mcl, name, bases, classdict):
classdict["logger"] = logging.getLogger(name)
return type.__new__(mcl, name, bases, classdict)

class Felis:
__metaclass__ = LoggedType
def alpha(self):
self.logger.info("felis-alpha")

class Catus(Felis):
def alpha(self):
self.logger.info("catus-alpha")
def beta(self):
self.logger.info("catus-beta")

if __name__ == "__main__":
logging.basicConfig(format="%(name)s.%(funcName)s: %(message)s",
level=logging.INFO)
f = Felis()
f.alpha()
c = Catus()
c.alpha()
c.beta()

If the metaclass bothers you, here's a simpler alternative:

class Felis(object):
logger = logging.getLogger("Felis")
def alpha(self):
self.logger.info("felis-alpha")

class Catus(Felis):
logger = logging.getLogger("Catus")
def alpha(self):
self.logger.info("catus-alpha")
def beta(self):
self.logger.info("catus-beta")

Peter

[Eric S. Johansson]

Peter Otten wrote:

Eric S. Johansson wrote:

>I need to to be able to conditionally log based on the method the log
statement is in and one other factor like a log level. in order to do
so, I need to be able to automatically find out the name of the method
and its class but I haven't found out how to do that yet.

for example,

class catus(Felis):
def Siamese_cat( yowl, purr, demand_food):

...
log("state of litter box %s"% litter_box.smell, level = 1)
If the table of methods logged contains "catus.Siamese_cat", then I
would expect to see the output of the log statements in a log file. If
not then I wouldn't see anything in the log.

Has somebody done this already? Is it even possible to do without
manually adding the class and method information for every log statement?

a related question is using signals for reloading configurations etc. I
have to find any good examples of how to use signals to cause a
long-running process to reload external data. Any good pointers?

Instead of rolling your own, use the logging package which can handle
everything but the class info out of the box (levels are spelt as method
names info(), warn() etc.).

I was planning on using logging. I've been using syslog for too long

>
import logging

class LoggedType(type):
def __new__(mcl, name, bases, classdict):
classdict["logger"] = logging.getLogger(name)
return type.__new__(mcl, name, bases, classdict)

__new__ is new to me. took a look at
http://www.python.org/download/relea...intro/#__new__ which
give me some clue but not enough. what I get is that in call
initialization, you add an entry to the class dict (adds new method??).
I see that name, bases, or classdict are part of the normal class
construction process and refer to the class under construction. I'm
guessing mcl comes from __metaclass__ and defaults to type?

the getLogger creates a logging channel so there is one channel per
class? but what selects the class for output or is that a derived
logger class I need to create?

also, how could one automatically determine the method doing the logging?

>
class Felis:
__metaclass__ = LoggedType

needed in every top level class?

def alpha(self):
self.logger.info("felis-alpha")

class Catus(Felis):
def alpha(self):
self.logger.info("catus-alpha")
def beta(self):
self.logger.info("catus-beta")

if __name__ == "__main__":
logging.basicConfig(format="%(name)s.%(funcName)s: %(message)s",
level=logging.INFO)
f = Felis()
f.alpha()
c = Catus()
c.alpha()
c.beta()

>
If the metaclass bothers you, here's a simpler alternative:

simpler to implement but more error prone. I like the metaclass model.
now if one could fill in the class and method name automatically, life
would be good.

[Peter Otten]

Eric S. Johansson wrote:

Peter Otten wrote:

>Eric S. Johansson wrote:

>>I need to to be able to conditionally log based on the method the log
statement is in and one other factor like a log level. in order to do
so, I need to be able to automatically find out the name of the method
and its class but I haven't found out how to do that yet.

for example,

class catus(Felis):
def Siamese_cat( yowl, purr, demand_food):

...
log("state of litter box %s"% litter_box.smell, level = 1)
If the table of methods logged contains "catus.Siamese_cat", then I
would expect to see the output of the log statements in a log file. If
not then I wouldn't see anything in the log.

Has somebody done this already? Is it even possible to do without
manually adding the class and method information for every log
statement?

a related question is using signals for reloading configurations etc. I
have to find any good examples of how to use signals to cause a
long-running process to reload external data. Any good pointers?

Instead of rolling your own, use the logging package which can handle
everything but the class info out of the box (levels are spelt as method
names info(), warn() etc.).

I was planning on using logging. I've been using syslog for too long

>>
import logging

class LoggedType(type):
def __new__(mcl, name, bases, classdict):
classdict["logger"] = logging.getLogger(name)
return type.__new__(mcl, name, bases, classdict)

__new__ is new to me. took a look at
http://www.python.org/download/relea...intro/#__new__ which
give me some clue but not enough. what I get is that in call
initialization, you add an entry to the class dict (adds new method??).
I see that name, bases, or classdict are part of the normal class
construction process and refer to the class under construction. I'm
guessing mcl comes from __metaclass__ and defaults to type?

The first parameter to __new__() is always the actual class (here
LoggedType). Because LoggedType's purpose is to serve as a metaclass I used
the shortcut mcl.

the getLogger creates a logging channel so there is one channel per
class? but what selects the class for output or is that a derived
logger class I need to create?

As a general direction try to understand the logging package, the __new__()
method (a constructor in C++), and metaclasses (a class is an instance of
another class which is called metaclass to avoid confusion when talking
about both) independently before jumping into the mix.

also, how could one automatically determine the method doing the logging?

>>
class Felis:
__metaclass__ = LoggedType

needed in every top level class?

Yes. The good news is that you only need one toplevel class

class Logged:
__metaclass__ = LoggedType

that you can inherit from.

> def alpha(self):
self.logger.info("felis-alpha")

class Catus(Felis):
def alpha(self):
self.logger.info("catus-alpha")
def beta(self):
self.logger.info("catus-beta")

if __name__ == "__main__":
logging.basicConfig(format="%(name)s.%(funcName)s: %(message)s",
level=logging.INFO)
f = Felis()
f.alpha()
c = Catus()
c.alpha()
c.beta()

>>
If the metaclass bothers you, here's a simpler alternative:

simpler to implement but more error prone. I like the metaclass model.
now if one could fill in the class and method name automatically, life
would be good.

Well, the method name is already there in my example; a class name is there,
too (disguised as the logger name), but it is the name of the actual
instance's class, not the class where the method is defined.
Here is a revised example that logs the defining class:

import logging

class LoggedType(type):
def __new__(mcl, name, bases, classdict):
classdict["_%s__logger" % name] = logging.getLogger(name)
return type.__new__(mcl, name, bases, classdict)

class Logged:
__metaclass__ = LoggedType

class Felis(Logged):
def alpha(self):
self.__logger.info("Felis.alpha")
def gamma(self):
self.__logger.info("Felis.gamma")

class Catus(Felis):
def alpha(self):
self.__logger.info("Catus.alpha")
def beta(self):
self.__logger.info("Catus.beta")

if __name__ == "__main__":
logging.basicConfig(
format="EXPECTED %(message)s GOT %(name)s.%(funcName)s",
level=logging.INFO)
f = Felis()
f.alpha()
f.gamma()
c = Catus()
c.alpha()
c.beta()
c.gamma()

Peter

[Peter Otten]

Eric S. Johansson wrote:

[in private mail -- please don't, Eric]

Peter Otten wrote:

As a general direction try to understand the logging package, the
__new__() method (a constructor in C++), and metaclasses (a class is
an instance of another class which is called metaclass to avoid
confusion when talking about both) independently before jumping into
the mix.

I've spent a big chunk of the afternoon/evening and am ok with
metaclasses. *but what has my knickers in a twist is the format
statement. *how do I get the logger to let me fill in funcName. *I've
tried what the docs say should work (but it doesn't)

self.__logger.info("Felis.alpha", funcName="hisss")

I don't understand. The logging package detects the function name without
user intervention.

Perhaps it's time to step back and explain what you want to achieve rather
than how you proceed.

Peter

[Eric S. Johansson]

Peter Otten wrote:

Eric S. Johansson wrote:

[in private mail -- please don't, Eric]

sorry. my preference is for private mail. it's my way of trying to be
kind to others by reducing list clutter.

I don't understand. The logging package detects the function name without
user intervention.

not in 2.4 afaik. according to the docs for debug/info it the only
kwargs which is inspected is exc_info.

Perhaps it's time to step back and explain what you want to achieve rather
than how you proceed.

print a log message if a predicate yields true.

should be able to have different predicates.

the desired predicate is a match on class, method, and level number.
class and method should be found automatically by the logging predicate
code.

apologies again for violating your email protocol and thanks for the help.

[Peter Otten]

Eric S. Johansson wrote:

Peter Otten wrote:

>Eric S. Johansson wrote:

[in private mail -- please don't, Eric]

sorry. my preference is for private mail. it's my way of trying to be
kind to others by reducing list clutter.

It is not list clutter in my book; it gives others the chance to correct,
add to, or even profit from our conversation.

>I don't understand. The logging package detects the function name without
user intervention.

not in 2.4 afaik.

Hmm, I must have overread that constraint in your previous posts...

Here is yet another revision of my example then:

import logging
import sys

class LoggedType(type):
def __new__(mcl, name, bases, classdict):
def get_logger(self):
return logging.getLogger("%s.%s" % (name,
sys._getframe(1).f_code.co_name))
classdict["_%s__logger" % name] = property(get_logger)
return type.__new__(mcl, name, bases, classdict)

class Logged:
__metaclass__ = LoggedType

class Felis(Logged):
def alpha(self):
self.__logger.info("Felis.alpha")
def gamma(self):
self.__logger.info("Felis.gamma")

class Catus(Felis):
def alpha(self):
self.__logger.info("Catus.alpha")
def beta(self):
self.__logger.info("Catus.beta")

if __name__ == "__main__":
logging.basicConfig(
format="EXPECTED %(message)s GOT %(name)s", level=logging.INFO)
f = Felis()
f.alpha()
f.gamma()
c = Catus()
c.alpha()
c.beta()
c.gamma()

Peter

[Eric S. Johansson]

Peter Otten wrote:

Eric S. Johansson wrote:

Here is yet another revision of my example then:

it's making more and more sense although I don't quite follow 'property'
quite yet. But I see that get_logger is invoked prior to the
__logger.info call.

I was looking at how to implement one of my other requirements
(conditional based on a predicate) and I see that I could use a filter.
I've experimented a little but come up empty. This is what I changed:

class filter_test (logging.Filter):
test_names = { "Felis.alpha" : True,
"Catus.alpha" : False,
}

def ___init__ (self, name):
"""simple filter test """
self.name = name

def filter(self, record):
"""test and forget """
return test_names.has_key(self.name) and test_names[self.name]

class LoggedType(type):
def __new__(mcl, name, bases, classdict):
def get_logger(self):
tag = "%s.%s" % (name,sys._getframe(1).f_code.co_name)
lgr = logging.getLogger(tag)
lgr.addFilter(filter_test)
return lgr

classdict["_%s__logger" % name] = property(get_logger)
return type.__new__(mcl, name, bases, classdict)

It's probably real obvious but I keep getting a:

File "C:\Python24\lib\logging\__init__.py", line 539, in filter
if not f.filter(record):
TypeError: unbound method filter() must be called with filter_test
instance as first argument (got LogRecord instance instead)
I'm puzzled that I thought I was adding the filter object at the right
point in time with addFilter. I wouldn't be surprised if I was totally
off base but I'd be interested in figuring out how I went off the rails
so I can fill in the knowledge.

---eric

[Gabriel Genellina]

En Fri, 23 Mar 2007 19:34:31 -0300, Eric S. Johansson <es*@harvee.org>
escribió:

class LoggedType(type):
def __new__(mcl, name, bases, classdict):
def get_logger(self):
tag = "%s.%s" % (name,sys._getframe(1).f_code.co_name)
lgr = logging.getLogger(tag)
lgr.addFilter(filter_test)
return lgr

classdict["_%s__logger" % name] = property(get_logger)
return type.__new__(mcl, name, bases, classdict)

It's probably real obvious but I keep getting a:

File "C:\Python24\lib\logging\__init__.py", line 539, in filter
if not f.filter(record):
TypeError: unbound method filter() must be called with filter_test
instance as first argument (got LogRecord instance instead)

I don't get all the details of what's all that stuff for, but from the
error and traceback, I think you forgot to create the filter_test
instance. That is, change lgr.addFilter(filter_test) to
lgr.addFilter(filter_test())

--
Gabriel Genellina

[Eric S. Johansson]

Gabriel Genellina wrote:

I don't get all the details of what's all that stuff for, but from the
error and traceback, I think you forgot to create the filter_test
instance. That is, change lgr.addFilter(filter_test) to
lgr.addFilter(filter_test())

do'h . for some reason, I thought addFilter took a class instead of an
instance. but on testing, I'm still missing something and getting the
same error

[Eric S. Johansson]

Dennis Lee Bieber wrote:

On Fri, 23 Mar 2007 21:15:56 -0400, "Eric S. Johansson" <es*@harvee.org>
declaimed the following in comp.lang.python:

>Gabriel Genellina wrote:

>>I don't get all the details of what's all that stuff for, but from the
error and traceback, I think you forgot to create the filter_test
instance. That is, change lgr.addFilter(filter_test) to
lgr.addFilter(filter_test())

do'h . for some reason, I thought addFilter took a class instead of an
instance. but on testing, I'm still missing something and getting the
same error

Doesn't your filter_test class require a parameter itself -- the
"name"?

yes. here is the code that fails. I don't understand why the unbound
method. what is really weird is that when I singlestep through the
code, it never seems to call filter_test. it is like the method never
existed.

File "C:\Python24\lib\logging\__init__.py", line 539, in filter
if not f.filter(record):
TypeError: unbound method filter() must be called with filter_test
instance as first argument (got LogRecord instance instead)

------------------
import logging
import sys

class filter_test (logging.Filter):
test_names = { "Felis.alpha" : True,
"Catus.alpha" : False,
}

def ___init__ (self, name):
"""simple filter test """
logging.Filter.__init__(self, name)
self.test_name = name

def filter(self, record):
"""test and forget """
return test_names.has_key( self.test_name) and test_names[
self.test_name ]

class LoggedType(type):
def __new__(mcl, name, bases, classdict):
def get_logger(self):
tag = "%s.%s" % (name,sys._getframe(1).f_code.co_name)
lgr = logging.getLogger(tag)
fl = filter_test(tag)
lgr.addFilter(fl)
return lgr

classdict["_%s__logger" % name] = property(get_logger)
return type.__new__(mcl, name, bases, classdict)

class Logged:
__metaclass__ = LoggedType

class Felis(Logged):
def alpha(self):
self.__logger.info("Felis.alpha")
def gamma(self):
self.__logger.info("Felis.gamma")

class Catus(Felis):
def alpha(self):
self.__logger.info("Catus.alpha")
def beta(self):
self.__logger.info("Catus.beta")

if __name__ == "__main__":
logging.basicConfig(
format="EXPECTED %(message)s GOT %(name)s", level=logging.INFO)
f = Felis()
f.alpha()
f.gamma()
c = Catus()
c.alpha()
c.beta()
c.gamma()

[Eric S. Johansson]

Dennis Lee Bieber wrote:

On Sat, 24 Mar 2007 11:29:34 -0400, "Eric S. Johansson" <es*@harvee.org>
declaimed the following in comp.lang.python:

>yes. here is the code that fails. I don't understand why the unbound
method. what is really weird is that when I singlestep through the
code, it never seems to call filter_test. it is like the method never
existed.

Among other things -- the init is never called... You have too many
_ on it. Second, I suspect you needed to overload getLogger -- there is
no code, that I could see that would /invoke/ a get_logger method.

get_logger does get called as part of the metaclass magic. I don't
understand it well enough to explain but a debugger reveals some. for
example, stepping through get_logger, I hit the first two statements but
after executing getLogger, I end up at logger.info. this leads me to
believe that __new__ runs at the start of every method invocation (not
just at object creation). I obviously need to read more on the topic.
I am really puzzled that get_logger never makes past getLogger but
hopefully insight will arrive.

[Eric S. Johansson]

Dennis Lee Bieber wrote:

I've never resorted to the debugger -- it's always been faster for
me to just wolf-fence* code with print statements...

depends on the situation for me. normally I use log statements that
turn on or off based on predicates (now I need to figure out how to
handle a SIGUSR1 to reload the who-logs info) hence this quest. when
done it's going into my rcsoc (random cross section of code) collection
which I'll publish one of these days. Also, I need to see if I can make
this lower overhead by pre computing as much of the predicate term as
possible and perform the test before calling a log statement. I put in
*lots* of log statements but leave most of them off until needed.
different form of wolf fence.

Could you possibly be confusing the execution of the "def"
statement... Remember, in Python "class" and "def" are executable
statements themselves. That is, what you are seeing during __new__ is
the execution of the statement that defines the get_logger method, NOT a
call of get_logger itself.

I know def executes. forth plays similar games and I spent a *lot* of
time in the guts of forth. With python, I'm just not familiar enough
with what goes on beneath the sheets.

>
Ah.. Okay... the wolf howled... Looking deeper at the code, it is
not a direct call to get_logger, but an indirect one via the dictionary
entry.

right. still not comfortable the property call. if I'm reading the
right docs, the first arg is a get method and I'm not sure how a logger
fills that need.

>
classdict["_Felis.alpha__logger"]

None the less, your posted code did have too many _ on the init,
meaning the initialization never took place, AND the references to
"test_names" needs to be prefixed with "self."

my most common brain fades. I also miss tt/ttt, ss/sss, 1l and
probably a few others. I sometimes think IDE's should have a "did you
mean" function to alert you to stuff that's "almost" right. kind of
like the lisp programmer's assistant.

--- eric