Peculiarity of '@' in logging.Formatter

[Charlie Martin]

This is what seems like an odd bug, but in code I'd thing often-enough used it must be the expected behavior and I just don't understand. Please, sirs/mesdames, is this a bug?

Example code:
---------------- begin code -------------------
#!/usr/bin/env python

"""
@-character WTF?
"""
import sys
import os
import logging, logging.handlers
import socket

log = logging.getLogger(__name__)
log.setLevel(logging.DEBUG)

fmtColon = logging.Formatter('[%(module)s:%(lineno)03d]:%(message)s')
strC = logging.handlers.SysLogHandler(address='/dev/log')
strC.setFormatter(fmtColon)
strC.setLevel(logging.DEBUG)
log.addHandler(strC)

fmtAt = logging.Formatter('[%(module)s@%(lineno)03d]:%(message)s')
strA = logging.handlers.SysLogHandler(address='/dev/log')
strA.setFormatter(fmtAt)
strA.setLevel(logging.DEBUG)
log.addHandler(strA)

log.info("My log message:isn't it special?")
---------------- end code ----------------

produces these entries in the syslog messages:

---------------- begin results ----------------------
Nov 21 16:09:56 crmartin [atSign: 026]:My log message:isn't it special?
Nov 21 16:09:56 crmartin [atSign@026]: My log message:isn't it special?
---------------- end results ------------------------

Observe:

* in the first entry, "[atSign: 026]:My" with space after the first ":"; that space isn't in the format string.

* in the second entry "[atSign@026]: My" again has an additional space after the first ":"

the colons following are unchanged.

This **seems** like it must be some obscure bug, but perhaps it's some undocumented feature?

 

[Charlie Martin]

Oops, forgot the python version etc:

bash $ /usr/bin/env python -V
Python 2.7

On SuSE 11.4

bash $ uname -a
Linux crmartin 2.6.37.6-0.9-desktop #1 SMP PREEMPT 2011-10-19 22:33:27 +0200 x86_64 x86_64 x86_64 GNU/Linux

 

[Tiaburn Stedd]

Upvote this. Looks like a bug for me.

---------------- begin results ----------------------
Nov 22 16:47:45 lvaltp0521 [minitest: 021]:My log message:isn't it
special?
Nov 22 16:47:45 lvaltp0521 [minitest@021]: My log message:isn't it
special?
---------------- end results ------------------------

~$ python --version
Python 2.6.6

 

[Vinay Sajip]

This is what seems like an odd bug, but in code I'd
thing often-enough used it must be the expected behavior
and I just don't understand.  Please, sirs/mesdames, is
this a bug?

It may be a bug, but if so, it's in the syslog daemon rather than
logging. Please try again with FileHandlers in place of
SysLogHandlers, and confirm whether the anomaly still occurs.

I could reproduce the problem on a Suse 11.3 machine running Python
2.6, but it doesn't occur on Ubuntu for example:

Nov 23 12:33:09 eta-jaunty [slhtest3:026]:My log message:isn't it
special?
Nov 23 12:33:09 eta-jaunty [slhtest3@026]:My log message:isn't it
special?

I get the same (expected) result on Ubuntu for both Python 2.6 and
2.7.

I noticed that on Suse the syslog daemon is rsyslogd, whereas on
Ubuntu it's plain syslogd. Daemons do differ on how they parse
messages :-(

I ran the script with strace, and logging is writing correctly to the
socket:

socket(PF_FILE, SOCK_DGRAM, 0) = 3
connect(3, {sa_family=AF_FILE, path="/dev/log"}, 10) = 0
socket(PF_FILE, SOCK_DGRAM, 0) = 4
connect(4, {sa_family=AF_FILE, path="/dev/log"}, 10) = 0
gettimeofday({1322052499, 78501}, NULL) = 0
send(3, "<14>[slhtest:026]:My log message"..., 51, 0) = 51
send(4, "<14>[slhtest@026]:My log message"..., 51, 0) = 51
close(4) = 0
close(3) = 0

This is on Suse 11.3, where the formatting anomaly does occur - so it
appears to be down to how rsyslogd does things.

Regards,

Vinay Sajip