koldfront

Timestamps in .xsession-errors #c #unix #x

Once in a while it annoys me that the logfile that the programs I start under X outputs to, ~/.xsession-errors, has no timestamps.

A quick online search reveals that I'm not the only one - but I didn't find any satisfactory solution.

Then I thought "I know Unix!" and proceeded to make my ~/.xsession-errors a named pipe:

mv -i .xsession-errors .xsession-errors.log
mkfifo --mode 0600 .xsession-errors

My cunning plan was then to have timestamp read from the pipe and write to a file, which would then have the timestamps, yay! (I don't want two copies of the log file, without and with timestamps, because I'm tidy that way.)

The first problem is that the login manager I use, lightdm, renames and recreates ~/.xsession-errors:

    priv->log_filename = g_strdup (".xsession-errors");
    priv->log_mode = LOG_MODE_BACKUP_AND_TRUNCATE;
    priv->to_child_input = -1;
    priv->from_child_output = -1;

so my pipe just disappears, and I'm back to a log file with no timestamps.

As lightdm is free and open source software I could just download the source package, change the LOG_MODE-line, build it, and install the resulting package.

But I am lazy, so instead I thought "Hmm, I wonder if I could just patch the binary? LOG_MODE_APPEND has the value 1".

I have no experience in disassembling binaries, so I looked around and found the radare2-cutter package, started Cutter /usr/sbin/lightdm, searched for .xsession-errors, clicked to see the cross references, and found some x86 assembly code that looked just about right:

0x0001e839      lea     rdi, str..xsession_errors ; 0x3566f
0x0001e840      mov     qword [rbx + 0x18], rax
0x0001e844      mov     rbp, rax
0x0001e847      call    g_strdup   ; sym.imp.g_strdup
0x0001e84c      mov     qword [rbp + 0x80], rax
0x0001e853      mov     rax, qword [rbx + 0x18]
0x0001e857      mov     dword [rax + 0x88], 0
0x0001e861      mov     qword [rax + 0x14], 0xffffffffffffffff

Now, I haven't ever done anything in x86 assembly either, but how hard can it be? It looks like it calls g_strdup, and then something is set to 0 and something else to -1. That's very similar to the C-code above.

So I changed the , 0 to , 1 and saved the result.

Now, to find the right place to start consuming from the named pipe was a little tricky, the places I tried first started reading too late, which meant that the pipe filled up and logging in stalled. Not so great.

I ended up adding a script run with @reboot in my personal crontab, where the script looks like this:

#!/bin/sh

if [ -p ".xsession-errors" ]; then
  exec timestamp < ~/.xsession-errors ~/.xsession-errors.log
else
  tail -f ~/.xsession-errors | timestamp ~/.xsession-errors.log
fi

(so it works regardless of whether ~/.xsession-errors is a named pipe or a real file).

A quick reboot later, and I now have the coveted timestamps in my ~/.xsession-errors.log (and no duplication) - woohoo!

Thanks to @kas for goading me on and suggesting solutions and things to try.