Bug 26180 - Xorg server doesn't log message timestamp
Summary: Xorg server doesn't log message timestamp
Status: RESOLVED FIXED
Alias: None
Product: xorg
Classification: Unclassified
Component: Server/General (show other bugs)
Version: 7.4 (2008.09)
Hardware: Other All
: medium normal
Assignee: Xorg Project Team
QA Contact: Xorg Project Team
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-01-22 18:50 UTC by Victor Stinner
Modified: 2010-09-19 21:23 UTC (History)
0 users

See Also:
i915 platform:
i915 features:


Attachments
Add timestamp to the Xorg logs (1.79 KB, patch)
2010-01-22 18:50 UTC, Victor Stinner
no flags Details | Splinter Review
Version 2 of the patch: write also the timestamp for the needBuffer case (2.46 KB, patch)
2010-01-22 19:07 UTC, Victor Stinner
no flags Details | Splinter Review
Version 3: repeat the timestamp prefix for each line for a multiline log (3.84 KB, patch)
2010-01-22 20:16 UTC, Victor Stinner
no flags Details | Splinter Review
Version 4: fix Xorg -help and fix the buffer allocation test (4.69 KB, patch)
2010-01-25 17:31 UTC, Victor Stinner
no flags Details | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Victor Stinner 2010-01-22 18:50:23 UTC
Created attachment 32777 [details] [review]
Add timestamp to the Xorg logs

Hi,

Since some weks (after a Debian Sid upgrade), Xorg "lost" my keyboard after 2 to 10 days. But my problem is not the keyboard, but that Xorg doesn't log timestamp in Xorg.0.log.

Ubuntu has its own patch, 160_log_timestamping.patch, but it's disabled because "the patch also has a serious stack corruption bug"...
https://bugs.launchpad.net/ubuntu/+source/xorg-server/+bug/285787

160_log_timestamping.patch only changes LogVMessageVerb(), so messages written by ErrorF() and VErrorF() don't have the timestamp. And the timestamp is repeated multiple times per line of the log message doesn't contain any newline character.

I wrote my own patch:
 - patch LogVWrite() to write the timestamp before any kind of message
 - detect the new line character to avoid multiple timestamps per line
 - use time()+localtime()+strftime("%F %T ") to get timestamp like "2010-01-23 03:15:10", whereas Ubuntu's patch writes the number of seconds (and microseconds) since Xorg started (eg. "[ 0.019917] ")
 - add a static buffer of 21 bytes in LogVWrite() (allocated in the stack at runtime)

The timestamp is only read and formatted once per log line (and not once call to LogVWrite()). I don't know the overhead, but it should be quite small.

There is a reentrant function localtime_r() but it is not available everywhere, and I don't feel confortable with the autotools :-)
Comment 1 Victor Stinner 2010-01-22 19:04:35 UTC
A better patch would be to write the timestamp prefix before each line of text, if the message contains something after a newline character. But it becomes a little more complex, but my patch is enough for me yet :-)

Example of logs showing the limitations of my patch:
-------------------------
2010-01-23 03:15:10
X.Org X Server 1.7.42010-01-23 03:15:10
Release Date: 2010-01-08
2010-01-23 03:15:10 X Protocol Version 11, Revision 0
2010-01-23 03:15:10 Build Operating System: Linux 2.6.32-trunk-686 i686 Debian
(...)
2010-01-23 03:15:10 Current version of pixman: 0.16.4
2010-01-23 03:15:10 	Before reporting problems, check http://wiki.x.org
	to make sure that you have the latest version.
2010-01-23 03:15:10 Markers: (--) probed, (**) from config file, (==) default setting,
	2010-01-23 03:15:10 (++) from command line, (!!) notice, (II) informational,
	2010-01-23 03:15:10 (WW) warning, (EE) error, (NI) not implemented, (??) unknown.
2010-01-23 03:15:10 (==) Log file: "/var/log/Xorg.0.log", Time: Sat Jan 23 03:15:10 2010
(...)
2010-01-23 03:15:10 (II) Module ABI versions:
2010-01-23 03:15:10 	X.Org ANSI C Emulation: 0.4
2010-01-23 03:15:10 	X.Org Video Driver: 6.0
2010-01-23 03:15:10 	X.Org XInput driver : 7.0
2010-01-23 03:15:10 	X.Org Server Extension : 2.0
2010-01-23 03:15:10 (++) using VT number 8

2010-01-23 03:15:10 (--) PCI:*(0:0:2:0) 8086:2582:1028:01c7 Intel Corporation 82915G/GV/910GL Integrated Graphics Controller rev 4, Mem @ 0xdff80000/524288, 0xc0000000/268435456, 0xdff40000/262144, I/O @ 0x0000ecd8/8
2010-01-23 03:15:10 (II) Open ACPI successful (/var/run/acpid.socket)
2010-01-23 03:15:10 (II) "extmod" will be loaded. This was enabled by default and also specified in the config file.
(...)
2010-01-23 03:15:10 (II) intel: Driver for Intel Integrated Graphics Chipsets: i810,
	2010-01-23 03:15:10 i810-dc100, i810e, i815, i830M, 845G, 852GM/855GM, 865G, 915G,
	2010-01-23 03:15:10 E7221 (i915), 915GM, 945G, 945GM, 945GME, Pineview GM, Pineview G,
	2010-01-23 03:15:10 965G, G35, 965Q, 946GZ, 965GM, 965GME/GLE, G33, Q35, Q33, GM45,
	2010-01-23 03:15:10 4 Series, G45/G43, Q45/Q43, G41, B43, Clarkdale, Arrandale
2010-01-23 03:15:10 (II) Primary Device is: PCI 00@00:02:0
2010-01-23 03:15:10 drmOpenDevice: node name is /dev/dri/card0
(...)
2010-01-23 03:15:11 (II) config/udev: Adding input device "Power Button" (/dev/input/event1)
(...)
-------------------------
Comment 2 Victor Stinner 2010-01-22 19:07:37 UTC
Created attachment 32778 [details] [review]
Version 2 of the patch: write also the timestamp for the needBuffer case
Comment 3 Victor Stinner 2010-01-22 20:16:24 UTC
Created attachment 32779 [details] [review]
Version 3: repeat the timestamp prefix for each line for a multiline log

Well, it wasn't so hard to repeat the timestamp prefix for each line if LogVWrite() is called with a message contains multiple lines. My patch version 3 works as expected:
---------------------------------------
2010-01-23 05:09:51 
2010-01-23 05:09:51 X.Org X Server 1.7.4
2010-01-23 05:09:51 Release Date: 2010-01-08
2010-01-23 05:09:51 X Protocol Version 11, Revision 0
2010-01-23 05:09:51 Build Operating System: Linux 2.6.32-trunk-686 i686 Debian
2010-01-23 05:09:51 Current Operating System: Linux marge 2.6.32-trunk-686 #1 SMP Sun Jan 10 06:32:16 UTC 2010 i686
2010-01-23 05:09:51 Kernel command line: BOOT_IMAGE=/boot/vmlinuz-2.6.32-trunk-686 root=UUID=91266004-cbbf-432b-b3ed-5552358e63ec ro quiet
2010-01-23 05:09:51 Build Date: 23 January 2010  02:47:11AM
2010-01-23 05:09:51 xorg-server 2:1.7.4-1 (haypo@marge) 
2010-01-23 05:09:51 Current version of pixman: 0.16.4
2010-01-23 05:09:51 	Before reporting problems, check http://wiki.x.org
2010-01-23 05:09:51 	to make sure that you have the latest version.
2010-01-23 05:09:51 Markers: (--) probed, (**) from config file, (==) default setting,
2010-01-23 05:09:51 	(++) from command line, (!!) notice, (II) informational,
2010-01-23 05:09:51 	(WW) warning, (EE) error, (NI) not implemented, (??) unknown.
2010-01-23 05:09:51 (==) Log file: "/var/log/Xorg.0.log", Time: Sat Jan 23 05:09:51 2010
2010-01-23 05:09:51 (==) Using config file: "/etc/X11/xorg.conf"
(...)
2010-01-23 05:09:51 (**) FontPath set to:
2010-01-23 05:09:51 	/usr/share/fonts/X11/misc,
2010-01-23 05:09:51 	/usr/share/fonts/X11/Type1,
2010-01-23 05:09:51 	/var/lib/defoma/x-ttcidfont-conf.d/dirs/TrueType,
2010-01-23 05:09:51 	/usr/share/fonts/X11/misc,
2010-01-23 05:09:51 	/usr/share/fonts/X11/Type1,
2010-01-23 05:09:51 	/var/lib/defoma/x-ttcidfont-conf.d/dirs/TrueType,
2010-01-23 05:09:51 	built-ins
2010-01-23 05:09:51 (**) ModulePath set to "/usr/lib/xorg/modules"
2010-01-23 05:09:51 (WW) AllowEmptyInput is on, devices using drivers 'kbd', 'mouse' or 'vmmouse' will be disabled.
2010-01-23 05:09:51 (WW) Disabling Mouse0
2010-01-23 05:09:51 (WW) Disabling Keyboard0
2010-01-23 05:09:51 (II) Loader magic: 0x81e7c20
2010-01-23 05:09:51 (II) Module ABI versions:
2010-01-23 05:09:51 	X.Org ANSI C Emulation: 0.4
2010-01-23 05:09:51 	X.Org Video Driver: 6.0
2010-01-23 05:09:51 	X.Org XInput driver : 7.0
2010-01-23 05:09:51 	X.Org Server Extension : 2.0
2010-01-23 05:09:51 (++) using VT number 8
2010-01-23 05:09:51 
2010-01-23 05:09:51 (--) PCI:*(0:0:2:0) 8086:2582:1028:01c7 Intel Corporation 82915G/GV/910GL Integrated Graphics Controller rev 4, Mem @ 0xdff80000/524288, 0xc0000000/268435456, 0xdff40000/262144, I/O @ 0x0000ecd8/8
(...)
---------------------------------------
Comment 4 Victor Stinner 2010-01-25 16:54:02 UTC
There is also a patch for Xorg in Cygwin: http://www.cygwin.com/ml/cygwin-xfree/2009-01/msg00073.html

Differences with my patch:
 - use a new static buffer of 1024 bytes (my patch adds a static buffer of 21 bytes)
 - use strncat(), whereas my patch calls fwrite() twice
 - use localtime_r(), my patch uses localtime()
 - fix also some newlines in messages (dix/registry.c and hw/xwin/winprocarg.c)
Comment 5 Victor Stinner 2010-01-25 16:54:31 UTC
See also Debian feature request: http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=202923
(xserver-xfree86: want timestamps in server log messages)
Comment 6 Victor Stinner 2010-01-25 16:58:35 UTC
Oops, my patch has the same issue than the Cygwin's patch: Xorg -help write help with the timestamp!
http://www.cygwin.com/ml/cygwin-xfree/2009-01/msg00116.html

logTimestamp and logFileTimestamp should be set to FALSE for -help.

"Xorg -help" causes also a segfault on realloc() :-/
Comment 7 Alan Coopersmith 2010-01-25 17:05:53 UTC
See also the xorg-devel discussion about the last patch proposed for this,
and how these functions need to be signal-safe (not just re-entrant) so
most of the time functions can't be used:
http://lists.x.org/archives/xorg-devel/2009-September/001836.html
http://lists.x.org/archives/xorg-devel/2009-September/001837.html

The standard list of signal-safe functions, according to POSIX/Unix08, is:
http://www.opengroup.org/onlinepubs/9699919799/functions/V2_chap02.html#tag_15_04
(scroll down a couple pages to get to the list) 
Comment 8 Victor Stinner 2010-01-25 17:13:38 UTC
> "Xorg -help" causes also a segfault on realloc()

The problem comes from LogVWrite(). The "if (len > bufferUnused)" test
is wrong: more value should be used instead of len in this test. I will write a
new fixed patch.
Comment 9 Victor Stinner 2010-01-25 17:31:37 UTC
Created attachment 32818 [details] [review]
Version 4: fix Xorg -help and fix the buffer allocation test

New patch fixing Xorg -help and the realloc crash. There are other options printing Xorg usage, which may also disable the timestamp. I don't know Xorg enough to check all options.
Comment 10 Victor Stinner 2010-01-26 15:33:20 UTC
> (...) how these functions need to be signal-safe (not just re-entrant)

LogVWrite() uses vsnprintf(), fwrite(), fflush(), fsync(), malloc(), realloc(), memcpy(), ... None of these functions are part of the signal-safe list. Are you sure that the current implementation of LogVWrite() can be called from a signal handler?

I'm not sure that a call to localtime_r() or strftime() is worse than calling malloc() or fwrite() in a signal handler.

I think that localtime_r() and strftime() are reentrant. Is that right?

(my version uses localtime(), not localtime_rt(), but it's easy to change that)
Comment 11 Victor Stinner 2010-01-26 15:55:14 UTC
I found the following signal handlers in Xorg server:
 * os/utils.c, SIGALRM: SmartScheduleTimer() increments a 'long'
 * os/utils.c, SIGHUP: AutoResetServer() modify a 'volatile char' and another 'volatile char' (and save and then restore errno, but it looks useless to me)
 * os/utils.c, SIGTERM and SIGINT: GiveUp() is very close to AutoResetServer(), it just write another value (it does also save/restore errno)
 * hw/xfree86/os-support/bsd/bsd_VTsw.c: read some xf86Info attributes (int), and maybe modify a xf86Info attribute (Bool)
 * hw/dmx/dmxinit.c, SIGQUIT: GiveUp() from os/utils.c
 * hw/kdrive/ephyr/hostx.c, SIGUSR1: hostx_handle_signal() changes a 'static int' and call fprintf() if EPHYR_WANT_DEBUG define is 1 (default is hardcoded to 0)

Except hostx_handle_signal(), no signal handle call any function. hostx_handle_signal() calls hostx_toggle_damage_debug() (just modify a variable), and fprintf() in debug mode (which require to modify the source code).

As I understand, signal handler of the Xorg server are only asynchronous, because it's too hard to write "safe code" in a signal handler.

Does the problem with LogVWrite() and signal unsafe functions come from code outside Xorg server, like some drivers?

Note: The variables modified by signal handlers might be declared using the volatile keyword.
Comment 12 Julien Cristau 2010-01-26 16:14:34 UTC
> --- Comment #11 from Victor Stinner <victor.stinner@haypocalc.com>  2010-01-26 15:55:14 PST ---
> I found the following signal handlers in Xorg server:

you missed probably the most important one, xf86SIGIO().
Comment 13 Victor Stinner 2010-01-26 16:43:12 UTC
> you missed probably the most important one, xf86SIGIO()

Oops. I was looking for call to OsSignal(), but there are direct calls to sigaction().

xf86SIGIO() uses xf86Msg() to log errors (which calls indirectly LogVWrite()). Ok, I now have an example of usage of LogVWrite() in a signal handler.

Other signal handler (using sigaction()) in Xorg xserver:
 * os/osinit.c, SIGSEGV, SIGQUIT, SIGILL, SIGFPE, SIGBUS, SIGSYS, SIGXCPU, SIGXFSZ and SIGEMT: OsSigHandler() calls:
   - LogMessage() if dlerror() is not NULL (and if RTLD_DI_SETSIGNAL is defined)
   - OsSigWrapper(signo) if OsSigWrapper is not NULL
   - xorg_backtrace(): writes the backtrace using ErrorF(),
   - ErrorF()
   - FatalError()
 * hw/kdrive/src/kinput.c, SIGIO: KdSigio(), call read() method of each kdInputFds
 * hw/kdrive/linux/linux.c, SIGUSR1: LinuxVTRequest() sets a 'Bool' to 1
 * hw/xfree86/os-support/shared/sigio.c, SIGIO: xf86SIGIO() presented before
 * hw/xfree86/os-support/sco/sco_init.c, SIGSUR1: xf86VTRequest() read/write some xf86info attributes
 * hw/dmx/input/dmxsigio.c, SIGIO: dmxSigioHandler() calls collect_events() method of each dmxInputs

So there are at least two signal handlers calling (indirectly) LogVWrite(): xf86SIGIO() and OsSigHandler(). Since these handlers are widely used, I guess that my above comments are wrong: LogVWrite() looks to be signal-safe.
Comment 14 Victor Stinner 2010-01-26 16:59:28 UTC
I see that localtime_r() and strftime() from the GNU libc use a lock. I suppose that this is enough to say that both functions are signal-unsafe (deadlock).

Should these 2 functions be replaced by other signal-safe functions? Or should LogVWrite() delay the call localtime_r(), strftime(), fwrite(), etc. ?
Comment 15 Matej Cepl 2010-06-07 12:23:26 UTC
Well, there is now http://cgit.freedesktop.org/xorg/xserver/commit/?id=d2322b6309bf15a45002b42e7e6ba3d6b5bfa932 ... it is probably not perfect, but I guess this bug is ready for closing.
Comment 16 Jesse Adkins 2010-09-19 21:23:11 UTC
(In reply to comment #15)
> Well, there is now
> http://cgit.freedesktop.org/xorg/xserver/commit/?id=d2322b6309bf15a45002b42e7e6ba3d6b5bfa932
> ... it is probably not perfect, but I guess this bug is ready for closing.

Agreed. Closing this.


Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct.