messages to rsyslog without timestamp lose 16 chars

[Scott Moser]

on boot of a precise image, I did not see messages in /var/log/cloud-init.log as expected.

I noticed that some of them are in /var/log/syslog:
Dec 16 16:41:30 server-3393 d-init-cfg[INFO]: cloud-init-cfg ['all', 'config']
Dec 16 16:41:30 server-3393 it__.py[DEBUG]: handling mounts with freq=None and args=[]
Dec 16 16:41:30 server-3393 SourceEc2.py[DEBUG]: unable to convert swap to a device
Dec 16 16:41:30 server-3393 kernel: [ 83.058563] kjournald starting. Commit interval 5 seconds
Dec 16 16:41:30 server-3393 it__.py[DEBUG]: handling ssh-import-id with freq=None and args=[]
Dec 16 16:41:30 server-3393 sh_import_id.py[DEBUG]: importing ssh ids. cmd = ['sudo', '-Hu', 'ubuntu', 'ssh-import-id', 'smoser']

I'm not sure where the beginning of those log statements are going.

cloud-init uses python logging, and places the following content in /etc/rsyslog.d/21-cloudinit.conf:
# Log cloudinit generated log messages to file
:syslogtag, isequal, "[CLOUDINIT]" /var/log/cloud-init.log

# comment out the following line to allow CLOUDINIT messages through.
# Doing so means you'll also get CLOUDINIT messages in /var/log/syslog
& ~

ProblemType: Bug
DistroRelease: Ubuntu 12.04
Package: cloud-init 0.6.2-0ubuntu1
ProcVersionSignature: User Name 3.2.0-4.10-virtual 3.2.0-rc5
Uname: Linux 3.2.0-4-virtual x86_64
ApportVersion: 1.90-0ubuntu1
Architecture: amd64
Date: Fri Dec 16 17:29:28 2011
Ec2AMI: ami-00000102
Ec2AMIManifest: FIXME
Ec2AvailabilityZone: nova
Ec2InstanceType: m1.small
Ec2Kernel: unavailable
Ec2Ramdisk: unavailable
PackageArchitecture: all
ProcEnviron:
 PATH=(custom, user)
 LANG=en_US.UTF-8
 SHELL=/bin/bash
SourcePackage: cloud-init
UpgradeStatus: No upgrade log present (probably fresh install)

[Mike-forbes+bugzilla (mike-forbes+bugzilla)]

Rsyslog seems to be stripping log messages for python logging[1]

I've tested this in rsyslog 5.8.6. It was working fine in 5.8.5

Example:
in my python log file ini:

[formatter_detailed]
format=appname [%(process)d]: %(name)s %(module)s(%(lineno)d): %(message)s

which gives:

Dec 6 09:22:06 hostname name module(230): message

If I add some spacing to my formatting:

[formatter_detailed]
format=xxxxxxxxxxxxxxx appname[%(process)d]: %(name)s %(module)s(%(lineno)d): %(message)s

I get what I'd expect to see (and what was working previously)

Dec 6 09:24:02 hostname appname[14019]: name module(230): message

Ubuntu Lucid;
rsyslogd 5.8.6, compiled with:
 FEATURE_REGEXP: Yes
 FEATURE_LARGEFILE: No
 GSSAPI Kerberos 5 support: Yes
 FEATURE_DEBUG (debug build, slow code): No
 32bit Atomic operations supported: Yes
 64bit Atomic operations supported: Yes
 Runtime Instrumentation (slow code): No

[1]
http://docs.python.org/library/logging.html#logrecord-attributes

[Scott Moser (smoser)]

It seems this is possibly rsyslog or python logging related, because cloud-init did not change between oneiric and precise,. In oneiric, it works:
Dec 16 17:36:04 server-3395 [CLOUDINIT] __init__.py[DEBUG]: handling final-message with freq=None and args=[]
Dec 16 21:11:30 server-3395 [CLOUDINIT] cloud-init-cfg[INFO]: cloud-init-cfg ['apt-update-upgrade', 'always']
Dec 16 21:11:30 server-3395 [CLOUDINIT] __init__.py[DEBUG]: handling apt-update-upgrade with freq=always and args=[]

That final message in /var/log/cloud-init.log was generated when I just now (4 hours after booting) ran:
sudo cloud-init-cfg apt-update-upgrade always

[Scott Moser (smoser)]

You can compare the output above, with what i found in /var/log/syslog after running he same on precise:
Dec 16 21:14:02 server-3393 d-init-cfg[INFO]: cloud-init-cfg ['apt-update-upgrade', 'always']
Dec 16 21:14:02 server-3393 it__.py[DEBUG]: handling apt-update-upgrade with freq=always and args=[]
Dec 16 21:14:02 server-3393 pt_update_upgrade.py[DEBUG]: selected mirror at: http://ubuntu-mirror.novalocal/ubuntu

It seems like data is being lost for a message.

[Scott Moser (smoser)]

I'm moving this to package rsyslog, I've verified that this is a regression caused by using rsyslog from precise (5.8.6-1ubuntu3).
The issue is fixed and demonstrable by:
 $ url="https://launchpad.net/ubuntu/+archive/primary/+files/rsyslog_5.8.1-1ubuntu2_amd64.deb"
 $ wget "$url" -O "${url##*/}"
 $ sudo dpkg -i "${url##*/}"
 $ sudo cloud-init start

After the above, a message from 'cloud-init start' will be in /var/log/cloud-init.log. Running that otherwise would put the mangled message in /var/log/syslog.

[Scott Moser (smoser)]

This is a simple test case that shows the problem using python logging.config.

Just run it with:
 ./python-logging-syslog.py my message

It will output to console the same string it should be writing to syslog.
However, the one to syslog is messed up. (tail -f /var/log/syslog).

[Scott Moser (smoser)]

I strace with that of:
  logger "[FOO] bar"

And found that logger writes 16 bytes before the message, an example with apostrophe added to show trailing white space:
  'Dec 19 13:18:44 '

If I modify the above test case to as:
 format=0123456789012345[CLOUDINIT] %(filename)s[%(levelname)s]: %(message)s

Then I get my message correctly filtered to /var/log/cloud-init.log.

Ie, running:
$ ./python-logging-syslog.py "hello world"
displays:
    0123456789012345[CLOUDINIT] python-logging-syslog.py[DEBUG]: hello world
produces in /var/log/cloud-init.log:
    Dec 19 18:25:45 server-3418 [CLOUDINIT] python-logging-syslog.py[DEBUG]: hello world

, and a new line there like:
Dec 19 18:22:06 server-3418 [CLOUDINIT] mytest.py[DEBUG]: foo

[Mike-forbes+bugzilla (mike-forbes+bugzilla)]

See also; Scott Moser on the rsyslog mailing list wrote:

I'm using python logging [1] to write to syslog in cloud-init [2].
I've noticed a problem in the development version of ubuntu that has
rsyslog 5.8.6, that does not exist in the Ubuntu 11.10 release that has
rsyslog 5.8.1 [3].

The issue can be seen by running the attached test case.
If you run it like:
 $ ./python-logging-syslog.py foobar
You'll see output to the console of:
 [MYTAG] python-logging-syslog.py[DEBUG]: foobar
and in /var/log/syslog, you see a message like:
 Dec 19 19:01:21 server-3418 ogging-syslog.py[DEBUG]: foobar

strace led me to see that the python-logging messages do not have a
TIMESTAMP field directly after the PRIVAL. As a result, 16 characters are
getting chopped from the incoming message.

It seems that rsyslog was previously more forgiving there and allow
messages without a TIMESTAMP.

The Ubuntu and Debian default rsyslog.conf has
 $ModLoad imuxsock
And I'm writing to syslog in python through /dev/log.

I've not tested, but it looks to me like this behavior might have changed
it would seem that commit 54cee2ce69c5bbd96aa51ac8636f4b029e2ceb7 [4]
might be the source of the change.

Is it intended that messages require the TIMESTAMP field now?

--
[1] http://docs.python.org/library/logging.html
[2] https://launchpad.net/cloud-init
[3] http://pad.lv/905419
[4] http://git.adiscon.com/?p=rsyslog.git;a=commit;h=54cee2ce69c5bbd96aa51ac8636f4b029e2ceb75

[Scott Moser (smoser)]

sent mail to upstream at http://lists.adiscon.net/pipermail/rsyslog/2011-December/014155.html
it was previously reported at http://bugzilla.adiscon.com/show_bug.cgi?id=295

[Rgerhards-j (rgerhards-j)]

problem is indeed that the date is missing where it was expected. The usual syslog() call places it there. I added logic to support missing dates. I have a bit boldly claimed in ChangeLog that it fixes this bug, but I had actually not time to check it against your code. I'd appreciate if you could give the fix a try and report back.

It will be released as part of 5.8.7.

Patch available in git:

http://git.adiscon.com/?p=rsyslog.git;a=commitdiff;h=f112b51b8d6c358b87ac608112d393adb047ea0f

[Launchpad Janitor (janitor)]

This bug was fixed in the package rsyslog - 5.8.6-1ubuntu4

---------------
rsyslog (5.8.6-1ubuntu4) precise; urgency=low

  * debian/patches/100-imuxsock-allow-missing-date.patch
    fix bug in imuxsock that truncated messages if they did not
    contain a date field (LP: #905419).
 -- Scott Moser <email address hidden> Tue, 20 Dec 2011 11:55:11 -0500

[Mike-forbes+bugzilla (mike-forbes+bugzilla)]

I can confirm this patch fixes the issue for me.

Thanks :)

(In reply to comment #2)
> problem is indeed that the date is missing where it was expected. The usual
> syslog() call places it there. I added logic to support missing dates. I have a
> bit boldly claimed in ChangeLog that it fixes this bug, but I had actually not
> time to check it against your code. I'd appreciate if you could give the fix a
> try and report back.
>
> It will be released as part of 5.8.7.
>
> Patch available in git:
>
> http://git.adiscon.com/?p=rsyslog.git;a=commitdiff;h=f112b51b8d6c358b87ac608112d393adb047ea0f