Bug 1014868 - SyslogHandler fails to log messages which contain NUL bytes
SyslogHandler fails to log messages which contain NUL bytes
Status: CLOSED CURRENTRELEASE
Product: Beaker
Classification: Community
Component: scheduler (Show other bugs)
0.15
Unspecified Unspecified
unspecified Severity unspecified (vote)
: 0.15.1
: ---
Assigned To: Dan Callaghan
Raymond Mancy
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2013-10-02 20:32 EDT by Dan Callaghan
Modified: 2014-12-07 20:16 EST (History)
9 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2013-10-23 02:59:19 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Dan Callaghan 2013-10-02 20:32:31 EDT
Kid does some hackery to inject template filenames into stack traces (or doesn't do hackery to inject them properly, whatever) when an exception happens during template processing. Normally the stack trace looks like this:

[...]
  File "/usr/lib/python2.6/site-packages/kid/filter.py", line 26, in apply_matches
    for ev, item in stream:
  File "/usr/lib/python2.6/site-packages/kid/parser.py", line 179, in _track
    for p in stream:
  File "/usr/lib/python2.6/site-packages/kid/parser.py", line 221, in _coalesce
    for ev, item in stream:
  File "/home/dcallagh/work/beaker/Server/bkr/server/templates/system_notes.py", line 141, in _pull
  File "/usr/lib/python2.6/site-packages/kid/parser.py", line 179, in _track
    for p in stream:
  File "/usr/lib/python2.6/site-packages/kid/parser.py", line 130, in strip
    for ev, item in self._iter:
  File "/usr/lib/python2.6/site-packages/kid/parser.py", line 179, in _track
    for p in stream:
[...]

Note the source line is missing for the template file (system_notes.kid), so presumably some attribute somewhere in the traceback is None instead of a real value.

When an exception like this happens in Beaker running in Apache, logging to syslog, the following appears in the Apache error log:

[Thu Oct 03 00:19:44 2013] [error] /usr/lib/python2.6/site-packages/kid/codewriter.py:91: DeprecationWarning: BaseException.message has been deprecated as of Python 2.6
[Thu Oct 03 00:19:44 2013] [error]   setattr(self, arg, getattr(error, arg))
[Thu Oct 03 00:19:44 2013] [error] Traceback (most recent call last):
[Thu Oct 03 00:19:44 2013] [error]   File "/usr/lib/python2.6/site-packages/bkr/log.py", line 50, in emit
[Thu Oct 03 00:19:44 2013] [error]     syslog.syslog(priority, line)
[Thu Oct 03 00:19:44 2013] [error] TypeError: [priority,] message string

I'm guessing "line" in this case is None which is a TypeError. Not sure where the BaseException.message warning is coming from.
Comment 1 Dan Callaghan 2013-10-02 20:44:13 EDT
On second thought, the problem might actually be caused by < > characters in the stack trace. See bug 1014870 for a traceback that triggers it.
Comment 3 Dan Callaghan 2013-10-03 03:07:09 EDT
It turns out the exception is actually caused by the line having NUL bytes, which is not allowed by the syslog(3) library call (nor by the syslog protocol I imagine).

Here is the repr of the line which it's trying to log, from the stack trace caused by bug 1014870:

' \xff\xfe<\x00x\x00m\x00l\x00>\x00<\x00p\x00>\x00a\x00s\x00d\x00f\x00 \x00<\x00l\x00o\x00l\x00>\x00<\x00/\x00p\x00>\x00<\x00/\x00x\x00m\x00l\x00>\x00'

which looks like UTF-16 as bytes with a prepended space character. How Kid ever produced that is completely beyond me. But nevertheless, SyslogHandler should deal with NUL bytes gracefully (replace them with '?' or '\x00' or '').
Comment 4 Dan Callaghan 2013-10-03 03:11:50 EDT
(In reply to Dan Callaghan from comment #3)
> which looks like UTF-16 as bytes with a prepended space character. How Kid
> ever produced that is completely beyond me.

Oh, of course, the prepended space is actually from SyslogHandler due to the multi-line message. So Kid is really just spitting out UTF-16 as bytes, which is not such a surprising bug I suppose.
Comment 5 Dan Callaghan 2013-10-03 03:12:59 EDT
On Gerrit: http://gerrit.beaker-project.org/2329
Comment 7 wangjing 2013-10-08 04:56:59 EDT
hi, Dan,

1. I'v seen the error logs in comment0, but what's ur expected results?

2. due to bug 1014870 might be the cause of this bug, and it has been verified now, so the problem of this bug may not be reproduced again, right?
Comment 8 Dan Callaghan 2013-10-08 18:13:39 EDT
(In reply to wangjing from comment #7)
> 1. I'v seen the error logs in comment0, but what's ur expected results?

Expected result is no TypeError on stderr (/var/log/httpd/error_log) and a complete stack trace in /var/log/beaker/server-debug.log (previously the line full of \x00 junk was missing):

[...]
Oct  8 09:55:27 beaker beaker-server[328]:    File "/usr/lib/python2.6/site-packages/kid/parser.py", line 221, in _coalesce
Oct  8 09:55:27 beaker beaker-server[328]:      for ev, item in stream:
Oct  8 09:55:27 beaker beaker-server[328]:    File "/usr/lib/python2.6/site-packages/kid/parser.py", line 393, in __iter__
Oct  8 09:55:27 beaker beaker-server[328]:      for ev, stuff in self._expat_stream():
Oct  8 09:55:27 beaker beaker-server[328]:    File "/usr/lib/python2.6/site-packages/kid/parser.py", line 372, in _expat_stream
Oct  8 09:55:27 beaker beaker-server[328]:      feed(data)
Oct  8 09:55:27 beaker beaker-server[328]:    File "/usr/lib/python2.6/site-packages/kid/parser.py", line 434, in feed
Oct  8 09:55:27 beaker beaker-server[328]:      raise expat.ExpatError(e)
Oct  8 09:55:27 beaker beaker-server[328]:  ExpatError: Error parsing XML:
Oct  8 09:55:27 beaker beaker-server[328]:  <FF><FE><\x00x\x00m\x00l\x00>\x00<\x00p\x00>\x00a\x00s\x00d\x00f\x00 \x00<\x00l\x00o\x00l\x00>\x00<\x00/\x00p\x00>\x00<\x00/\x00x\x00m\x00l\x00>\x00
Oct  8 09:55:27 beaker beaker-server[328]:                       ^
Oct  8 09:55:27 beaker beaker-server[328]:  mismatched tag: line 1, column 21
Oct  8 09:55:27 beaker beaker-server[328]:  Error in code generated from template file 'build/lib/bkr/server/templates/system.kid'

> 2. due to bug 1014870 might be the cause of this bug, and it has been
> verified now, so the problem of this bug may not be reproduced again, right?

Right, there is no way to reproduce this naturally now that bug 1014870 is fixed. I think the only way to verify it would be to manually inject some code like raise Exception('\xff\xfe<\x00') somewhere.

I will ask one of the other Beaker developers to verify this bug in their environment.
Comment 9 Raymond Mancy 2013-10-08 19:27:41 EDT
I have verified this on my local install of Beaker.

Steps to verify were:
Inserting the following into my_paginate_grid.kid pre patch:
  <?python
  raise Exception('\xff\xfe<\x00')
  ?>

This gave the TypeError mentioned previously when accessing Beaker's main page.

I then upgraded to the patched version of Beaker, re-added the exception in the template, restarted apache and the TypeError was no longer present. Also, it now prints the literal zero byte string in server-debug.log:


  Exception: ��<\x00

Unfortunately there is no good way to recover the unicode char, but as expected we are printing the zero byte in this case.
Comment 11 Raymond Mancy 2013-10-23 02:59:19 EDT
beaker 0.15.1 has been released.

Note You need to log in before you can comment on or make changes to this bug.