[Bug 905419] Re: messages to rsyslog without timestamp lose 16 chars

Mon Dec 19 21:21:24 UTC 2011

Launchpad has imported 2 comments from the remote bug at
http://bugzilla.adiscon.com/show_bug.cgi?id=295.

If you reply to an imported comment from within Launchpad, your comment
will be sent to the remote bug automatically. Read more about
Launchpad's inter-bugtracker facilities at
https://help.launchpad.net/InterBugTracking.

------------------------------------------------------------------------
On 2011-12-05T20:27:22+00:00 Mike-forbes+bugzilla wrote:

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

Reply at: https://bugs.launchpad.net/rsyslog/+bug/905419/comments/0

------------------------------------------------------------------------
On 2011-12-19T20:34:38+00:00 Mike-forbes+bugzilla wrote:

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

Reply at: https://bugs.launchpad.net/rsyslog/+bug/905419/comments/8

** Changed in: rsyslog
       Status: Unknown => Confirmed

** Changed in: rsyslog
   Importance: Unknown => High

-- 
You received this bug notification because you are a member of Ubuntu
Foundations Bugs, which is subscribed to rsyslog in Ubuntu.
https://bugs.launchpad.net/bugs/905419

Title:
  messages to rsyslog without timestamp lose 16 chars

Status in Rsyslog:
  Confirmed
Status in “rsyslog” package in Ubuntu:
  Confirmed

Bug description:
  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)

To manage notifications about this bug go to:
https://bugs.launchpad.net/rsyslog/+bug/905419/+subscriptions