Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

SysLogHandler incorrectly appends \000 to messages #56377

Closed
CarlCrowder mannequin opened this issue May 24, 2011 · 14 comments
Closed

SysLogHandler incorrectly appends \000 to messages #56377

CarlCrowder mannequin opened this issue May 24, 2011 · 14 comments
Assignees
Labels
stdlib Python modules in the Lib dir type-bug An unexpected behavior, bug, or error

Comments

@CarlCrowder
Copy link
Mannequin

CarlCrowder mannequin commented May 24, 2011

BPO 12168

Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.

Show more details

GitHub fields:

assignee = 'https://github.com/vsajip'
closed_at = <Date 2011-06-09.17:38:19.098>
created_at = <Date 2011-05-24.11:44:12.842>
labels = ['type-bug', 'library']
title = 'SysLogHandler incorrectly appends \\000 to messages'
updated_at = <Date 2021-11-04.14:34:50.711>
user = 'https://bugs.python.org/CarlCrowder'

bugs.python.org fields:

activity = <Date 2021-11-04.14:34:50.711>
actor = 'eryksun'
assignee = 'vinay.sajip'
closed = True
closed_date = <Date 2011-06-09.17:38:19.098>
closer = 'vinay.sajip'
components = ['Library (Lib)']
creation = <Date 2011-05-24.11:44:12.842>
creator = 'Carl.Crowder'
dependencies = []
files = []
hgrepos = []
issue_num = 12168
keywords = []
message_count = 14.0
messages = ['136743', '136767', '136768', '136771', '136847', '136856', '136857', '136858', '136859', '136860', '136875', '137996', '138112', '138127']
nosy_count = 0.0
nosy_names = []
pr_nums = []
priority = 'normal'
resolution = 'fixed'
stage = None
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue12168'
versions = []

@CarlCrowder
Copy link
Mannequin Author

CarlCrowder mannequin commented May 24, 2011

logging.handlers.SysLogHandler contains this class variable and comment:

# curious: when talking to the unix-domain '/dev/log' socket, a
# zero-terminator seems to be required.  this string is placed
# into a class variable so that it can be overridden if
# necessary.
log_format_string = '<%d>%s\000'

And separately, in emit:

    msg = self.format(record) + '\000'

The assumption here is that a null character must be appended to delimit the syslog message. In RFC5424, there is no mention of a message delimiter, and in fact the previous syslog RFC, RFC3164, specifically states:

The MSG part will fill the remainder of the syslog packet. This will usually contain some additional information of the process that generated the message, and then the text of the message. There is no ending delimiter to this part.

I believe this comment and behaviour is due to an older version of syslogd. Checking the manpage for an older version of rsyslog for example includes this piece of information [1]:

There is probably one important consideration when installing rsyslogd. It is dependent on proper formatting of messages by the syslog function. The functioning of the syslog function in the shared libraries changed somewhere in the region of libc.so.4.[2-4].n. The specific change was to null-terminate the message before transmitting it to the /dev/log socket. Proper functioning of this version of rsyslogd is dependent on null-termination of the message.

I'm running Ubuntu 11.04 with rsyslogd 4.6.4 (that is, the standard version). In the manpage for this version of rsyslogd, there is no reference to null-terminators. Removing "+ '\000'" from the SysLogHandler results in messages still being received correctly.

Problem behaviour:

  1. When running any RFC compliant syslog receiver that handles syslog messages, such as flume[2], this null character is not stripped as it is not expected to be present. Current versions of syslog cope because previously they assumed it existed.
  2. The log_format_string class variable is not actually used anywhere, so it cannot be overridden usefully.

Removing the null terminator will cause older typical versions of syslogd to fail to receive messages, however including it causes any normal receiver that does not implement the non-standard behaviour to receive an additional unwanted null.

Suggestion for a fix is either to properly use the log_format_string class variable, or to allow an optional "append_null" argument to the SysLogHandler constructor. By default, this should be True, as it will continue to work with the main use case, which is unix syslog demons. Having the option will allow other use cases to also use the SysLogHandler.

[1] http://manpages.ubuntu.com/manpages/hardy/man8/rsyslogd.8.html#contenttoc8
[2] http://www.cloudera.com/blog/category/flume/

@CarlCrowder CarlCrowder mannequin added stdlib Python modules in the Lib dir type-bug An unexpected behavior, bug, or error labels May 24, 2011
@bitdancer
Copy link
Member

While I agree that it should ideally be possible to actually control this behavior as indicated by the comment, any syslog handler that does not sanitize the messages it receives is broken.

@bitdancer
Copy link
Member

s/handler/receiver/

@vsajip
Copy link
Member

vsajip commented May 24, 2011

Even though expecting the NUL-terminator is legacy behaviour, newer versions of the syslog daemons presumably follow Postel's rule of "be conservative in what you do, be liberal in what you accept from others". Can flume not be changed to follow this principle, given that ordinarily you wouldn't expect a NUL terminator byte on syslog messages?

When the implementation of SysLogHandler was changed to comply (more closely) with RFC5424, the log_format_string value was inadvertently left behind in Python 2.x, and it makes sense to remove it since changing it doesn't do anything useful.

Having an append_nul parameter to control NUL-termination is certainly doable, and this approach will keep the 2.x and 3.x implementations more or less the same (as 3.x doesn't have a log_format_string attribute). I suggest "nul" rather than "null" since we're talking about appending a NUL byte to the message.

However, having it as an additional keyword parameter to the constructor could cause dictConfig failures if configurations specifying it are used with an old version of Python (e.g. 3.2.0) which doesn't have the parameter. For this reason, it might be better to have an append_nul class attribute (defaulting to True) which can be overridden with an instance attribute set to False. (This approach can still be used with dictConfig, as you can use a factory function other than the SysLogHandler class to construct a SysLogHandler instance.)

@CarlCrowder
Copy link
Mannequin Author

CarlCrowder mannequin commented May 25, 2011

Flume certainly could avoid parsing certain values. However, while a syslog application "should avoid octet values below 32", they are still "legal" [1]. I don't think that adjusting flume to reject legal values due to legacy behaviour in some unix syslog daemons is the Right Thing™ here.

[1] http://tools.ietf.org/html/rfc5424#section-6.4

@CarlCrowder CarlCrowder mannequin changed the title SysLogHandler incorrectly appents \000 to messages SysLogHandler incorrectly appends \000 to messages May 25, 2011
@bitdancer
Copy link
Member

And it goes on to say:

"[...] but a syslog application MAY modify these characters upon reception. For example, it might change them into an escape sequence (e.g., value 0 may be changed to "\0")"

Flume should not break if it receives NULs. But there should be a way to prevent generating them, and Vinay has agreed with that. Now we just need a patch :) (he's probably working on one...)

@CarlCrowder
Copy link
Mannequin Author

CarlCrowder mannequin commented May 25, 2011

Oh, I understand. Flume doesn't break, it handles the \0 just fine, the problem is that I ended up with a message with that additional byte on the end. Sorry for the confusion!

@akheron
Copy link
Member

akheron commented May 25, 2011

FWIW, I once stumbled on this problem, and solved it by making my own log handler that uses functions from the syslog module.

@vsajip
Copy link
Member

vsajip commented May 25, 2011

Petri Lehtinen <petri@digip.org> added the comment:

FWIW, I once stumbled on this problem, and solved it by making my own log
handler that uses functions from the syslog module.

@petri: It's great that it worked for you, but IIRC the syslog module has had
thread-safety issues at least on some platforms, which is why it's not used in
the SysLogHandler implementation (disclaimer: this was a while ago, I don't know
if the syslog module is thread-safe now - I believe the thread-safety issues
were in the underlying C APIs).

I am working on a patch, watch this space :-)

@akheron
Copy link
Member

akheron commented May 25, 2011

Vinay Sajip wrote:

@petri: It's great that it worked for you, but IIRC the syslog module has had
thread-safety issues at least on some platforms, which is why it's not used in
the SysLogHandler implementation (disclaimer: this was a while ago, I don't know
if the syslog module is thread-safe now - I believe the thread-safety issues
were in the underlying C APIs).

Ah, I was not aware of thread safety issues. A quick search revealed
that there has been a non-standard syslog_r() function that's thread
safe, but nowadays POSIX requires syslog() to be thread safe, too.

@vsajip
Copy link
Member

vsajip commented May 25, 2011

Please note: this change is too late for inclusion in Python 3.2.1 :-( as it has already rc status. So I will probably push this change once 3.2.1 is out.

@python-dev
Copy link
Mannequin

python-dev mannequin commented Jun 9, 2011

New changeset 260b84851d1f by Vinay Sajip in branch '3.2':
Issue bpo-12168: SysLogHandler now allows NUL termination to be controlled using a new 'append_nul' attribute on the handler.
http://hg.python.org/cpython/rev/260b84851d1f

New changeset ac1217099b3f by Vinay Sajip in branch 'default':
Merged fix for issue bpo-12168 from 3.2.
http://hg.python.org/cpython/rev/ac1217099b3f

@vsajip vsajip closed this as completed Jun 9, 2011
@merwok
Copy link
Member

merwok commented Jun 10, 2011

Should this new attribute be documented?

@python-dev
Copy link
Mannequin

python-dev mannequin commented Jun 10, 2011

New changeset 3cf5d61fd6d7 by Vinay Sajip in branch '3.2':
Documented change for Issue bpo-12168.
http://hg.python.org/cpython/rev/3cf5d61fd6d7

New changeset 6658b9b9f5f3 by Vinay Sajip in branch 'default':
Merged documentation change for Issue bpo-12168.
http://hg.python.org/cpython/rev/6658b9b9f5f3

@ahmedsayeed1982 ahmedsayeed1982 mannequin added topic-regex 3.10 only security fixes and removed stdlib Python modules in the Lib dir labels Nov 4, 2021
@eryksun eryksun added stdlib Python modules in the Lib dir and removed topic-regex 3.10 only security fixes labels Nov 4, 2021
@ezio-melotti ezio-melotti transferred this issue from another repository Apr 10, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
stdlib Python modules in the Lib dir type-bug An unexpected behavior, bug, or error
Projects
None yet
Development

No branches or pull requests

5 participants