fine grain logging cotrol

E

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
 
P

Peter Otten

Eric said:
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
 
E

Eric S. Johansson

Peter said:
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/releases/2.2.3/descrintro/#__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.
 
P

Peter Otten

Eric said:
Peter said:
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/releases/2.2.3/descrintro/#__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?


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.
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
 
P

Peter Otten

Eric S. Johansson wrote:

[in private mail -- please don't, Eric]
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
 
E

Eric S. Johansson

Peter said:
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.
 
P

Peter Otten

Eric said:
Peter said:
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.
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
 
E

Eric S. Johansson

Peter said:
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
 
G

Gabriel Genellina

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())
 
E

Eric S. Johansson

Gabriel said:
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
 
E

Eric S. Johansson

Dennis said:
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()
 
D

Dennis Lee Bieber

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.

I've flagged the changed lines with #######
-=-=-=-=-import logging
import sys

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

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

def filter(self, record):
"""test and forget """
return self.test_names.get(self.test_name, False) #######

class LoggedType(type):
def __new__(mcl, name, bases, classdict):
def getLogger(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(getLogger) #######
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()


--
Wulfraed Dennis Lee Bieber KD6MOG
(e-mail address removed) (e-mail address removed)
HTTP://wlfraed.home.netcom.com/
(Bestiaria Support Staff: (e-mail address removed))
HTTP://www.bestiaria.com/
 
E

Eric S. Johansson

Dennis said:
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.
 
D

Dennis Lee Bieber

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.
I've never resorted to the debugger -- it's always been faster for
me to just wolf-fence* code with print statements...

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.

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.

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."

(With fenceposts installed...)

E:\UserData\Dennis Lee Bieber\My Documents>python old_filter.py
__new__ invoked
__new__ invoked
__new__ invoked
get_logger invoked
EXPECTED Felis.alpha GOT Felis.alpha
get_logger invoked
get_logger invoked
get_logger invoked
get_logger invoked




* wolf fence
There is one wolf in Alaska, Find it!

Build a fence from north to south, splitting the state into two
regions. Sit on the middle of the fence and wait for the wolf to howl.
Determine that the wolf is, say, on the east side of the fence.

Build a fence from the middle of the first fence to the east. Sit on
the middle of that fence and wait for the wolf to howl...

Repeat procedure until the wolf is penned in.

-=-=-=-
The is a bug in the code...

Put a print statement in the middle of the code; run. If the print
statement is reached before the failure, the bug is on the side after
the print statement...

Put another print statement in the middle of that section, repeat...

-=-=-=-

Of course, nothing bars one from putting in a few extra fences at
the start (divide alaska N/S and E/W, sit at the intersection and
determine which quadrant the wolf howl comes from <G>)
--
Wulfraed Dennis Lee Bieber KD6MOG
(e-mail address removed) (e-mail address removed)
HTTP://wlfraed.home.netcom.com/
(Bestiaria Support Staff: (e-mail address removed))
HTTP://www.bestiaria.com/
 
E

Eric S. Johansson

Dennis said:
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
 

Ask a Question

Want to reply to this thread or ask your own question?

You'll need to choose a username for the site, which only take a couple of moments. After that, you can post your question and our members will help you out.

Ask a Question

Members online

Forum statistics

Threads
473,744
Messages
2,569,479
Members
44,899
Latest member
RodneyMcAu

Latest Threads

Top