x.org logging doesn't put timestamp on the log lines

[Joolz]

Binary package hint: xorg

After an x crash I was looking at the logfile. It's a bit bothering that there are no timestamps. Can this be added to the logging? TIA!

[Martijn vdS (martijn)]

Confirmed, X logs without timestamps, and that can be annoying when you're trying to find intermittent bugs.

[Launchpad Janitor (janitor)]

This bug was fixed in the package xorg-server - 2:1.5.99.902-0ubuntu3

---------------
xorg-server (2:1.5.99.902-0ubuntu3) jaunty; urgency=low

  * Add 160_log_timestamping.patch: Show timestamps in Xorg.*.log
    files.
    (LP: #285787)

 -- Bryce Harrington <email address hidden> Fri, 06 Feb 2009 06:28:48 -0800

[Tormod Volden (tormodvolden)]

I tested it, and unfortunately it is quite ugly since the LogVWrite sometimes is called several times in a line (without line feed), so you get timestamps all over.

I modified the patch to only include timestamps on the messages which start with the (xx) prefix, since these always are on a new line. Basically I moved Bryce's stuff to LogVMessageVerb instead.

Attached an untested debdiff, it's baking in my PPA, so I will test later.

[Tormod Volden (tormodvolden)]

Packages are now in my PPA. It looks a lot better I would say. Still not perfect, but to get it much better we would need upstream rework I think.

[Tormod Volden (tormodvolden)]

These lines still look bad: $ egrep "..*\[[0-9 .]{12}\]" /var/log/Xorg.0.log
Markers: [ 0.019856] (--) probed, [ 0.019882] (**) from config file, [ 0.019900] (==) default setting,
 [ 0.019917] (++) from command line, [ 0.019934] (!!) notice, [ 0.019951] (II) informational,
 [ 0.019968] (WW) warning, [ 0.019986] (EE) error, [ 0.020003] (NI) not implemented, [ 0.020020] (??) unknown.
[ 0.353524] (==) RADEON(0): Depth 24, [ 0.353532] (--) framebuffer bpp 32

The first block could be worked around by hard-coding, or making a new Log function for this only, none of which are particularly elegant. The last line can be broken up in two lines.

Anyhow, I think the timestamping should be configurable and set to off by default, to keep compatibility with upstream.

[Launchpad Janitor (janitor)]

This bug was fixed in the package xorg-server - 2:1.5.99.902-0ubuntu4

---------------
xorg-server (2:1.5.99.902-0ubuntu4) jaunty; urgency=low

  * 160_log_timestamping.patch: Only add timestamp on tagged messages
    (LP: #285787)

 -- Tormod Volden <email address hidden> Fri, 06 Feb 2009 23:33:11 +0100

[Victor Stinner (vstinner)]

Last week I wrote a patch to log messages with timestamps in Xorg logs:

   https://bugs.freedesktop.org/show_bug.cgi?id=26180

Differences with the Ubuntu patch:
 - patch LogVWrite() to write the timestamp before any kind of message
 - detect the new line character to avoid multiple timestamps per line: avoid " ... [ 0.019968] (WW) warning, [ 0.019986] (EE) error, [ 0.020003] (NI) not implemented, [ 0.020020] (??) unknown ..."
 - use time()+localtime()+strftime("%F %T ") to get timestamp like "2010-01-23 03:15:10", instead of the number of seconds (and microseconds) since Xorg started (eg. "[ 0.019917] ")

[Victor Stinner (vstinner)]

There is also a patch for Xorg in Cygwin: http://www.cygwin.com/ml/cygwin-xfree/2009-01/msg00073.html

Differences between my patch and Cygwin patch:
 - use a new static buffer of 1024 bytes (my patch adds a buffer of 21 bytes)
 - use strncat(), whereas my patch calls fwrite() twice
 - use localtime_r()
 - fix also some newlines in messages (dix/registry.c and hw/xwin/winprocarg.c)