Logging messages with dictionary args in Python 2.4b1 leads to exception

[Stefan Behnel]

Hi!

I'm trying to do this in Py2.4b1:

-------------------------------
import logging
values = {'test':'bla'}
logging.log(logging.FATAL, 'Test is %(test)s', values)
-------------------------------

This leads to en exception:

-----------------------------
Traceback (most recent call last):
File "/usr/lib/python2.4/logging/__init__.py", line 692, in emit
msg = self.format(record)
File "/usr/lib/python2.4/logging/__init__.py", line 578, in format
return fmt.format(record)
File "/usr/lib/python2.4/logging/__init__.py", line 368, in format
record.message = record.getMessage()
File "/usr/lib/python2.4/logging/__init__.py", line 239, in getMessage
msg = msg % self.args
TypeError: format requires a mapping
-----------------------------

Now, values /is/ a mapping. I looked into logging/__init__.py, but I can
only see that the '*args' parameter (as which 'values' is fed in) should
have been unpacked like this in logging.log():

apply(root.log, (level, msg)+args, kwargs)

Which should lead to the second argument being '(level, msg, args)' in my
understanding and which should allow using dicts when doing this later on
in LogRecord:

msg = msg % self.args

Now, I'm somewhat confused that this doesn't work and I'm also worried
that this is only done in the module methods and not inside the class that
actually handles the logging (the root object in this case). This should
encourage a diverting behaviour of the module methods and the Logger
object methods with the same name. This looks like a bug to me. Adding the
tuple should /only/ be done inside the class, not in the module functions.

Wouldn't it be better to handle dictionaries directly inside LogRecord?
Something like this would do the trick:

 

[Vinay Sajip]

Now, I'm somewhat confused that this doesn't work and I'm also worried
that this is only done in the module methods and not inside the class that
actually handles the logging (the root object in this case). This should
encourage a diverting behaviour of the module methods and the Logger
object methods with the same name. This looks like a bug to me. Adding the
tuple should /only/ be done inside the class, not in the module functions.

It's not a bug; however, the use case is not unreasonable, so I'll try
and get the functionality (sent by Stefan to me as a patch) into 2.4
final.

Regards,


Vinay Sajip

 

[Paul Clinch]

Hi!

I'm trying to do this in Py2.4b1:

-------------------------------
import logging
values = {'test':'bla'}
logging.log(logging.FATAL, 'Test is %(test)s', values)
-------------------------------

This leads to en exception:

-----------------------------
Traceback (most recent call last):
File "/usr/lib/python2.4/logging/__init__.py", line 692, in emit
msg = self.format(record)
File "/usr/lib/python2.4/logging/__init__.py", line 578, in format
return fmt.format(record)
File "/usr/lib/python2.4/logging/__init__.py", line 368, in format
record.message = record.getMessage()
File "/usr/lib/python2.4/logging/__init__.py", line 239, in getMessage
msg = msg % self.args
TypeError: format requires a mapping

Not sure about 2.4 but but in 2.3:-
logging.fatal( 'Test is %(test)s', values)

with the same error, however :-
logging.fatal( 'Test is %(test)s' % values)

is fine. An why shouldn't you use it in this fashion?

Now, values /is/ a mapping. I looked into logging/__init__.py, but I can
only see that the '*args' parameter (as which 'values' is fed in) should
have been unpacked like this in logging.log():

apply(root.log, (level, msg)+args, kwargs)

Which should lead to the second argument being '(level, msg, args)' in my
understanding and which should allow using dicts when doing this later on
in LogRecord:

msg = msg % self.args

*args is not a mapping, its a tuple. Positional arguments in the
format string will be found.

Now, I'm somewhat confused that this doesn't work and I'm also worried
that this is only done in the module methods and not inside the class that
actually handles the logging (the root object in this case). This should
encourage a diverting behaviour of the module methods and the Logger
object methods with the same name. This looks like a bug to me. Adding the
tuple should /only/ be done inside the class, not in the module functions.

Wouldn't it be better to handle dictionaries directly inside LogRecord?
Something like this would do the trick:

-----------------------
if len(self.args) == 1:
msg = msg % self.args[0] # may be a single value or a dictionary
else:
msg = msg % self.args # looks like a value tuple
-----------------------

Could anyone please comment on this?

Stefan

I haven't read the source so I punt on commenting.

Regards, Paul Clinch

 

[Stefan Behnel]

logging.fatal( 'Test is %(test)s' % values)
is fine. An why shouldn't you use it in this fashion?

I thought a logging API was usually trying to do costly things only when
it knows it has to. You /could/ do that, but since it doesn't come for
free - why not first do the check if you will actually log this message?

Ok, I know there's an overhead anyway: function calls, object creation,
etc. But copying strings and creating string representations of objects
can be /very/ expensive and should only be done if the log message is
definitely written.

I'd simply say that constructing a log message from arguments is such a
common thing that it is worth providing efficient API support for it. And
I think it's truely counter-pythonic to prevent the usage of dictionaries
at this point.

Stefan

 

[Steve Holden]

I thought a logging API was usually trying to do costly things only when
it knows it has to. You /could/ do that, but since it doesn't come for
free - why not first do the check if you will actually log this message?

Ok, I know there's an overhead anyway: function calls, object creation,
etc. But copying strings and creating string representations of objects
can be /very/ expensive and should only be done if the log message is
definitely written.

Well that's as may be, but is the logging function going to be taking up
much of your program's run time? I'd suspect not. Premature
optimisation, etc., etc.

I'd simply say that constructing a log message from arguments is such a
common thing that it is worth providing efficient API support for it.
And I think it's truely counter-pythonic to prevent the usage of
dictionaries at this point.

Your original message observed that LogRecord performs

msg = msg % self.args

and you said "this should work"; that was where your mistake lay. The
call was constructed using

apply(root.log, (level, msg)+args, kwargs)

and I presume that args was actually obtained from a formal parameter
*args (allowing the functiopn call to aggregate all non-keyword
arguments). Thus for your call to work the usage in LogRecord would have
had to be

msg = msg % self.args[0]

The point of the interface currently used is that it allows you to pass
a variable number of arguments for substitution into the message when
it's actually built. The *args construct neatly aggregates them into a
tuple. So when the substituion was performed inside LogRecord you were
actually providing a tuple whose single element was a dictionary, an
attempt doomed to failure.

A possible enhancement which might meet your arguments would allow the
user to provide EITHER a tuple of arguments OR a set of keyword
arguments. LogRecord could then say:

if args:
msg = msg % args
else:
msg = msg % kwargs

and you would then be able to make a call like

logging.log(logging.FATAL, 'Test is %(test)s', **values)

But with the code you presented, it's no use bleating that "values *is*
a mapping". While this is certainly true, values was unfortunately just
the only element in the args tuple, and it's the args tuple that's
currently used for substituion. I presume the patch you sent Vijay will
do something similar?

regards
Steve

 

[Stefan Behnel]

A possible enhancement which might meet your arguments would allow the
user to provide EITHER a tuple of arguments OR a set of keyword
arguments. LogRecord could then say:

if args:
msg = msg % args
else:
msg = msg % kwargs

and you would then be able to make a call like

logging.log(logging.FATAL, 'Test is %(test)s', **values)

But with the code you presented, it's no use bleating that "values *is*
a mapping". While this is certainly true, values was unfortunately just
the only element in the args tuple, and it's the args tuple that's
currently used for substituion. I presume the patch you sent Vijay will
do something similar?

What it does is: check if there is only one element in args and then
unpack it.

This leads to three different cases how
msg = msg % args
is evaluated:

1) the tuple is longer than one, i.e. args actually is a tuple
=> current beahaviour

2) the tuple contained one element, but not a dict, i.e. args is a value
=> replace the single template in msg with that value
=> current behaviour

3) the tuple contained one element, which was a dict, i.e. args is a dict
=> replace the dictionary templates in msg with the values in args

I find this very much the expected behaviour, which when used by actual
code looks like this:

log("message %s %d", 1, 2)
or
log("message %(a) %(b)", {'a':1, 'b':2})


I find it absolutely wrong if the second raises an exception. That would
differ from any other common use case of dictionaries in Python.

Even this works:
log("message %s", {'a':1, 'b':2})

So the only (!) change is the additional support for dictionary arguments.
No drawbacks.

I think, this is totally the right thing to do.

Stefan

 

[Vinay Sajip]

I thought a logging API was usually trying to do costly things only when

it knows it has to. You /could/ do that, but since it doesn't come for
free - why not first do the check if you will actually log this message?

Right.

I'd simply say that constructing a log message from arguments is such a
common thing that it is worth providing efficient API support for it. And
I think it's truely counter-pythonic to prevent the usage of dictionaries
at this point.

Patch checked into CVS. Now:
'Snow White', 'number':7})

gives

WARNING:root:Snow White and the 7 dwarves

Regards,


Vinay

 

[Alex Martelli]

Even this works:
log("message %s", {'a':1, 'b':2})

So the only (!) change is the additional support for dictionary arguments.
No drawbacks.

Actually, I think that:

log('msg %s', (1, 2, 3))

works w/o your patch but your patch breaks it, so it's not strictly true
that there are no drawbacks, I believe. Possibly the drawback's minor,
though.


Alex

 

[Stefan Behnel]

log('msg %s', (1, 2, 3))

works w/o your patch but your patch breaks it, so it's not strictly true
that there are no drawbacks, I believe. Possibly the drawback's minor,
though.

I just checked that, you're right.

"msg %s" % (1,2,3)

throws an exception, while

"msg %s" % ((1,2,3),)

does not.

It's maybe not that a common use case, I guess, but it's definitely a
deviation from the original interface as in Python 2.3, so it breaks
compatibility.

Maybe we still need a check for the actual type of args?

The only problematic case is a tuple as only argument, everything else
should work. So there are three possible solutions for backward compatibility:

1) document the change )
2) check for a dictionary as first argument
3) check for a tuple as first argument

Since the tuple is the only problematic thing you could hand in, I
personally feel a preference for making that the "exception" (i.e. I vote
for 3).

Any comments?

Stefan

 

[Vinay Sajip]

The only problematic case is a tuple as only argument, everything else

should work. So there are three possible solutions for backward compatibility:

1) document the change )
2) check for a dictionary as first argument
3) check for a tuple as first argument

Since the tuple is the only problematic thing you could hand in, I
personally feel a preference for making that the "exception" (i.e. I vote
for 3).

I would prefer (2), as the change is catering for the specific use
case of a single dictionary argument. This is what is currently in
CVS.

Regards,


Vinay Sajip

 

[Steve Holden]

I would prefer (2), as the change is catering for the specific use
case of a single dictionary argument. This is what is currently in
CVS.

Regards,


Vinay Sajip

Couldn't we just use keyword arguments to indicate dictionary-style
substitution? That seems to make a simpler, more elegant solution to me:

if args:
msg = msg % args
else:
msg = msg % kwargs

Or am I (as I so often do) missing something?

regards
Steve

 

[Steve Holden]

Patch checked into CVS. Now:



'Snow White', 'number':7})

gives

WARNING:root:Snow White and the 7 dwarves

Regards,


Vinay

But how much simpler

logging.want("%(string)s and the %(number)d dwarves",
string="Snow White", number=7)

seems (to me). Use kwargs!

regards
Steve

 

[Vinay Sajip]

But how much simpler

logging.want("%(string)s and the %(number)d dwarves",
string="Snow White", number=7)

logging.want? ;-)

Well, it was a trivial example. In real use cases, the dict would be a
variable rather than a literal. The problem with using kwargs is that
it could interfere with keyword arguments passed to the logging method
(currently only exc_info, but there may be others in future).

Regards,


Vinay Sajip

 

[Steve Holden]

logging.want? ;-)

Wishful thinking

Well, it was a trivial example. In real use cases, the dict would be a
variable rather than a literal. The problem with using kwargs is that
it could interfere with keyword arguments passed to the logging method
(currently only exc_info, but there may be others in future).

Indeed, my ignorance of the current API misled me. But *otherwise* it
would have been a good idea, no?

regards
Steve

 

[Bengt Richter]

Wishful thinking


Indeed, my ignorance of the current API misled me. But *otherwise* it
would have been a good idea, no?

Jumping into unknown wider context here, but (as you know, I'm sure)
as of recent versions you can easily pass a dict arg using keywords:
('here:', {'number': 7, 'string': 'Snow White'}, '<-is a dict') {'this': 'is a kwarg'}
^__args tuple_________________________________________________^ ^___kw arg___________^

Less confusing perhaps, the dict arg isolated:
{'number': 7, 'string': 'Snow White'}

Regards,
Bengt Richter

 

[Steve Holden]

Vinay Sajip wrote:

[...]


Jumping into unknown wider context here, but (as you know, I'm sure)
as of recent versions you can easily pass a dict arg using keywords:
('here:', {'number': 7, 'string': 'Snow White'}, '<-is a dict') {'this': 'is a kwarg'}
^__args tuple_________________________________________________^ ^___kw arg___________^

Less confusing perhaps, the dict arg isolated:
{'number': 7, 'string': 'Snow White'}

Regards,
Bengt Richter

That strikes me as an acceptable compromise.

regards
Steve