Bug 26180

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)
(...)
-------------------------

Created attachment 32778 [details] [review]
Version 2 of the patch: write also the timestamp for the needBuffer case

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
(...)
---------------------------------------

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)

See also Debian feature request: http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=202923
(xserver-xfree86: want timestamps in server log messages)

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() :-/

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) 

> "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.

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.

> (...) 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)

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 #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().

> 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.

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. ?

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.

(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.