[systemd-devel] journal handling of process title changes

[Patrick Donnelly]

[adding message to list, sorry Lennart...]

On Sun, Mar 23, 2014 at 9:25 PM, Lennart Poettering
<lennart at poettering.net> wrote:
> On Sun, 23.03.14 00:32, Patrick Donnelly (batrick at batbytes.com) wrote:
>
>> It seems the journal is reading from /proc/pid/cmdline (argv[0]) for
>> each entry. So when reading using journalctl, we don't see process
>> title changes properly. See the below example:
>
> We are reading both /proc/$PID/comm and /proc/$PID/cmdline, and augment
> journal entries with that. Unfortunately the kernel is currently too
> limited to do this in a race-free way. This means that a service that
> logs and terminates quickly afterwrads will trigger a race: journald
> won't be able to read comm and cmdline in time. Also, if you keep
> changing the comm/argv lines then we might use a later comm/argv for
> messages already written long before since we only read this data much
> later...

My problem is not related to race conditions. The issue is that
/proc/pid/cmdline is shown instead of /proc/pid/comm for each journal
entry. That is:

$ journalctl --boot
[...]
Mar 23 21:39:01 host a.out[10697]: hi
Mar 23 21:39:01 host c[10697]: bye2
[...]

These identifiers are being pulled from cmdline or argv[0] somehow.

>> #include <sys/prctl.h>
>> #include <systemd/sd-journal.h>
>>
>> int main (int argc, char *argv[])
>> {
>>     printf("%d\n", prctl(PR_SET_NAME, "foo", 0, 0, 0));
>>     sd_journal_print(LOG_INFO, "hi");
>>     strcpy(argv[0], "abc");
>>     sd_journal_print(LOG_INFO, "bye2");
>>     return 0;
>> }
>>
>> gcc test.c -o a.out -lsystemd
>> ./a.out
>>
>> we see:
>>
>> ... a.out[10321]: hi
>> ... a.out[10321]: bye
>> ... c[10321]: bye2
>>
>> I don't see how after a cursory glance at the code, but systemd is
>> also magically remembering the "old" beginning of argv[0]. So, even if
>> I change argv[0], I must start my changes from the beginning of the
>> basename of the old title. So in the above example, "ab" replaced "./"
>> in argv[0], only "c" is printed in the log.
>>
>> It seems to me systemd should be using /proc/pid/comm for this.
>
> And we do. Can you please dump the respective lines with "-o verbose"
> from the journal? They should explain in detail what we are seeing
> there...

Sun 2014-03-23 21:39:01.932343 EDT
[s=485c69d197f74e3d855818a78b6d83b7;i=5d896;b=82f837d8221c4200bb8617f809638558;m=1459584e5;t=4f5504cd311bc;x=f318a8725568092f]
    _MACHINE_ID=aae1a91de027484998daf076d8422b7e
    _HOSTNAME=host
    PRIORITY=6
    _GID=100
    _TRANSPORT=journal
    _UID=1000
    CODE_FUNC=main
    MESSAGE=hi
    CODE_FILE=test.c
    CODE_LINE=7
    SYSLOG_IDENTIFIER=a.out
    _PID=10697
    _BOOT_ID=82f837d8221c4200bb8617f809638558
    _SOURCE_REALTIME_TIMESTAMP=1395625141932343
Sun 2014-03-23 21:39:01.932352 EDT
[s=485c69d197f74e3d855818a78b6d83b7;i=5d897;b=82f837d8221c4200bb8617f809638558;m=145958577;t=4f5504cd3124e;x=cfde456defb6c064]
    _MACHINE_ID=aae1a91de027484998daf076d8422b7e
    _HOSTNAME=host
    PRIORITY=6
    _GID=100
    _TRANSPORT=journal
    _UID=1000
    CODE_FUNC=main
    CODE_FILE=test.c
    CODE_LINE=9
    MESSAGE=bye2
    SYSLOG_IDENTIFIER=c
    _PID=10697
    _BOOT_ID=82f837d8221c4200bb8617f809638558
    _SOURCE_REALTIME_TIMESTAMP=1395625141932352

--
Patrick Donnelly