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 :-)
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.
Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.