Bug 1014868
| Summary: | SyslogHandler fails to log messages which contain NUL bytes | ||
|---|---|---|---|
| Product: | [Retired] Beaker | Reporter: | Dan Callaghan <dcallagh> |
| Component: | scheduler | Assignee: | Dan Callaghan <dcallagh> |
| Status: | CLOSED CURRENTRELEASE | QA Contact: | Raymond Mancy <rmancy> |
| Severity: | unspecified | Docs Contact: | |
| Priority: | unspecified | ||
| Version: | 0.15 | CC: | aigao, asaha, dcallagh, ebaak, jingwang, llim, qwan, rmancy |
| Target Milestone: | 0.15.1 | ||
| Target Release: | --- | ||
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | Bug Fix | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2013-10-23 06:59:19 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
On second thought, the problem might actually be caused by < > characters in the stack trace. See bug 1014870 for a traceback that triggers it. 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 ''). (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. On Gerrit: http://gerrit.beaker-project.org/2329 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? (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. 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.
beaker 0.15.1 has been released. |
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.