Bug 1018042

Summary:	All log entries have "journal" prepended
Product:	[Fedora] Fedora	Reporter:	Pete Zaitcev <zaitcev>
Component:	openstack-swift	Assignee:	Silas Sewell <silas>
Status:	CLOSED UPSTREAM	QA Contact:	Fedora Extras Quality Assurance <extras-qa>
Severity:	unspecified	Docs Contact:
Priority:	unspecified
Version:	rawhide	CC:	apevec, breu, david, derekh, itamar, jonathansteffan, markmc, mmagr, rbryant, silas, zaitcev
Target Milestone:	---
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2013-11-05 14:51:22 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:

Description Pete Zaitcev 2013-10-11 04:31:54 UTC

Description of problem:

Log entries look like this:

Oct 10 23:57:49 kvm-rei journal: proxy-server 192.168.128.11 192.168.128.11 11/Oct/2013/03/57/49 GET /v1/AUTH_t1%3Fformat%3Djson HTTP/1.0 200 - - MIIF.........i8w%3D%3D - 786 - tx22d63c0146ca40c7bff2e-005257773d - 0.0455 - -

They used to be like this on RHEL 6:

Oct 10 23:54:20 rhev-a24c-01 proxy-server 10.10.55.128 127.0.0.1 11/Oct/2013/03/54/20 GET /v1/AUTH_test%3Fformat%3Djson HTTP/1.0 200 - - AUTH_tka.........6a7 - 907 - tx6018d95b1cec45c8aa5ed-005257766c - 0.0392 - -

Version-Release number of selected component (if applicable):

openstack-swift-1.9.1-2.fc21.noarch
rsyslog-7.4.2-2.fc20.x86_64

How reproducible:

Seems stable

Steps to Reproduce:
1. Install openstack-swift-proxy

Actual results:

Different log format

Expected results:

Traditional log format

Additional info:

We thought it was systemd journal thing, but then realized
that /var/log/messages still has normal looking entries
from every other service.

[zaitcev@kvm-rei ~]$ cat /etc/rsyslog.d/swift.conf 
local0.*	/var/log/swift/swift.log

But actually same thing happens if we let logs go into
/var/log/messages too.

Comment 1 Pete Zaitcev 2013-10-21 21:47:17 UTC

Oh, brother, it's just as I suspected.

The /dev/log is served by the systemd-journal, which parses the messages,
optionally stores them, then reassembles them back and forwards to rsyslog.
At the parsing time, something called "identifier" is searched by
looking for a word surrounded by whitespace and ending with a colon.
It's in src/journal/journal-syslog.c,
 server_process_syslog_message => syslog_parse_identifier
If the indentifier is not set, something in the depths of systemd adds it.

There's an option of forwarding to syslog raw, and in fact it is enabled
by default in systemd. Rsyslog is configured to listen on
/run/systemd/journal/syslog as well (with $SystemLogSocketName
in /etc/rsyslog.d/listen.conf), but it does not actually listen there.

The way journal forwards logging to rsyslogd is fairly strange
and difficult to pick up with strace - apparently it goes through
shared mmap-ed file, watched with inotify in
/var/log/journal/xxxxxxxxx/user-531.journal

Comment 2 Pete Zaitcev 2013-11-05 14:51:22 UTC

merged upstream (tentatively at least), will track in Icehouse