Re: [systemd-devel] journal handling of process title changes
On Sun, 23.03.14 21:46, Patrick Donnelly (batr...@batbytes.com) wrote:
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.
Yupp, the client side also sends an identifier to the server which is
used if it exists. It's container in the SYSLOG_IDENTIFIER field.
I figure what happens for you is that when you change argv[0] the GNU
program_invocation_short_name variable is not updated, and sd-journal
picks up that variable for setting SYSLOG_IDENTIFIER.
#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;
}
I figure you can fix this by changing program_invocation_short_name too:
program_invocation_short_name = basename(argv[0]);
See:
http://linux.die.net/man/3/program_invocation_short_name
If you don't update it too it will still point to the old value...
p_i_s_n is used internally by glibc too btw, so it should be updated in
any case if you change argv[0].
Lennart
--
Lennart Poettering, Red Hat
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] journal handling of process title changes
On Mon, Mar 24, 2014 at 12:30 PM, Lennart Poettering lenn...@poettering.net wrote: On Sun, 23.03.14 21:46, Patrick Donnelly (batr...@batbytes.com) wrote: 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. Yupp, the client side also sends an identifier to the server which is used if it exists. It's container in the SYSLOG_IDENTIFIER field. I figure what happens for you is that when you change argv[0] the GNU program_invocation_short_name variable is not updated, and sd-journal picks up that variable for setting SYSLOG_IDENTIFIER. Yes, this is it. Yay obscure glibc side-effects. I assume I could just override SYSLOG_IDENTIFIER manually? Also, if someone could update the documentation for systemd.journal-fields(7) saying where SYSLOG_IDENTIFIER is derived (by default?), that'd probably help too. Thanks Lennart! -- Patrick Donnelly ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] journal handling of process title changes
On Mon, 24.03.14 19:01, Patrick Donnelly (batr...@batbytes.com) wrote: On Mon, Mar 24, 2014 at 12:30 PM, Lennart Poettering lenn...@poettering.net wrote: On Sun, 23.03.14 21:46, Patrick Donnelly (batr...@batbytes.com) wrote: 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. Yupp, the client side also sends an identifier to the server which is used if it exists. It's container in the SYSLOG_IDENTIFIER field. I figure what happens for you is that when you change argv[0] the GNU program_invocation_short_name variable is not updated, and sd-journal picks up that variable for setting SYSLOG_IDENTIFIER. Yes, this is it. Yay obscure glibc side-effects. I assume I could just override SYSLOG_IDENTIFIER manually? Yes. Also, if someone could update the documentation for systemd.journal-fields(7) saying where SYSLOG_IDENTIFIER is derived (by default?), that'd probably help too. I added a vague reference there now. I left it a bit vague on purpose, since I don't want to document too much of glibc's own internals (i.e. that it derives the syslog identifiers from p_i_s_n, since it's not for us to document and thus cement this behaviour). Lennart -- Lennart Poettering, Red Hat ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] journal handling of process title changes
On Sun, 23.03.14 00:32, Patrick Donnelly (batr...@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...
#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...
Lennart
--
Lennart Poettering, Red Hat
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] journal handling of process title changes
[adding message to list, sorry Lennart...]
On Sun, Mar 23, 2014 at 9:25 PM, Lennart Poettering
lenn...@poettering.net wrote:
On Sun, 23.03.14 00:32, Patrick Donnelly (batr...@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
___
systemd-devel mailing list
systemd-devel@lists.freedesktop.org
http://lists.freedesktop.org/mailman/listinfo/systemd-devel
