regression in logger output to syslog

regression in logger output to syslog

[Olaf Hering]

I used a script with openSUSE 11.4 which called logger like this:
# logger -t "$l[$PPID] $i" "`sed -n ${c}p < $t`"

The tag was something like "me[123] foo: blah", and the number remained
stable for a single run.

Now with systemd and util-linux-2.26.2 the number does always change. If
I understand the man page correctly this is supposed to achieve the
same, but the $PPID never made it into journalctl -f outout:

logger -t "me"  --id=$PPID "foo: blah"

Instead the pid of the logger processs is used.
How can I restore the old behaviour?

Olaf

Re: regression in logger output to syslog

[Karel Zak]

On Fri, Oct 09, 2015 at 10:25:41AM +0200, Olaf Hering wrote:
> I used a script with openSUSE 11.4 which called logger like this:
> # logger -t "$l[$PPID] $i" "`sed -n ${c}p < $t`"
> 
> The tag was something like "me[123] foo: blah", and the number remained
> stable for a single run.
> 
> Now with systemd and util-linux-2.26.2 the number does always change. 

Not sure if I understand the problem. How can logger update have any
impact to the $PPID if this variable is generated by shell?
 
> IfI understand the man page correctly this is supposed to achieve the
> same, but the $PPID never made it into journalctl -f outout:
> 
> logger -t "me"  --id=$PPID "foo: blah"

 $ logger --no-act --stderr --id=$PPID "this is message"
 <13>Oct 12 12:40:07 kzak[1562]: this is message
 $ logger --no-act --stderr --id=$PPID "this is message"
 <13>Oct 12 12:40:07 kzak[1562]: this is message

.. still the same number. It seems that the problem is your script
where is probably any fork/exec before logger call.

Maybe you need to save the PID at the begin of the script:

#!/bin/bash

REPORTED_PID=$$

... your script ...

logger --id=$REPORTED_PID "foo: blah"

    Karel


-- 
 Karel Zak  <kzak@redhat.com>
 http://karelzak.blogspot.com

Re: regression in logger output to syslog

[Olaf Hering]

On Mon, Oct 12, Karel Zak wrote:

> On Fri, Oct 09, 2015 at 10:25:41AM +0200, Olaf Hering wrote:
> > I used a script with openSUSE 11.4 which called logger like this:
> > # logger -t "$l[$PPID] $i" "`sed -n ${c}p < $t`"
> > 
> > The tag was something like "me[123] foo: blah", and the number remained
> > stable for a single run.
> > 
> > Now with systemd and util-linux-2.26.2 the number does always change. 
> 
> Not sure if I understand the problem. How can logger update have any
> impact to the $PPID if this variable is generated by shell?

I'm sure the PPID variable itself is correct. But its value does not
appear anymore in journalctl -f.

>  $ logger --no-act --stderr --id=$PPID "this is message"
>  <13>Oct 12 12:40:07 kzak[1562]: this is message
>  $ logger --no-act --stderr --id=$PPID "this is message"
>  <13>Oct 12 12:40:07 kzak[1562]: this is message
> 
> .. still the same number. It seems that the problem is your script
> where is probably any fork/exec before logger call.

While having a 'journalctl -f &' running:

root@probook:~ # echo $PPID
2824
root@probook:~ # logger -t "me"  --id=$PPID "foo: blah"
root@probook:~ # Oct 12 15:29:55 probook.fritz.box me[6911]: foo: blah

root@probook:~ # logger -t "me"  --id=$PPID "foo: blah"
root@probook:~ # Oct 12 15:30:01 probook.fritz.box me[6912]: foo: blah
logger -t "me"  --id=$PPID "foo: blah"
root@probook:~ # Oct 12 15:30:05 probook.fritz.box me[6939]: foo: blah
root@probook:~ # logger -t "me" --no-act --stderr  --id=$PPID "foo: blah"
<13>Oct 12 15:32:26 me[2824]: foo: blah
root@probook:~ # logger -t "me" --no-act --stderr  --id=$PPID "foo: blah"
<13>Oct 12 15:32:28 me[2824]: foo: blah


So, its "systemd" who eats the required info.


Olaf

Re: regression in logger output to syslog

[Olaf Hering]

On Mon, Oct 12, Olaf Hering wrote:

> So, its "systemd" who eats the required info.

In case you miss it:

...
We do not allow faking syslog PID fields, for security reasons, it
will always be set to what the kernel passed to journald.

If this is something to support, then "logger" needs to to be patched so
that it can fake the SCM_CREDENTIALS metadata of the messages sent.
This requires privileges, but is not hard to do. Please file a bug
against util-linux and ask for for this to be added.

Lennart
...

Olaf

Re: regression in logger output to syslog

[Karel Zak]

On Wed, Oct 21, 2015 at 11:37:43AM +0200, Olaf Hering wrote:
> On Mon, Oct 12, Olaf Hering wrote:
> 
> > So, its "systemd" who eats the required info.
> 
> In case you miss it:
> 
> ...
> We do not allow faking syslog PID fields, for security reasons, it
> will always be set to what the kernel passed to journald.
> 
> If this is something to support, then "logger" needs to to be patched so
> that it can fake the SCM_CREDENTIALS metadata of the messages sent.
> This requires privileges, but is not hard to do. Please file a bug
> against util-linux and ask for for this to be added.

 Implemented, try logger(1) from util-linux git tree, please. 
 
 Thanks!

    Karel


-- 
 Karel Zak  <kzak@redhat.com>
 http://karelzak.blogspot.com

Re: regression in logger output to syslog

[Olaf Hering]

On Thu, Oct 29, Karel Zak wrote:

> On Wed, Oct 21, 2015 at 11:37:43AM +0200, Olaf Hering wrote:
> > On Mon, Oct 12, Olaf Hering wrote:
> > 
> > > So, its "systemd" who eats the required info.
> > 
> > In case you miss it:
> > 
> > ...
> > We do not allow faking syslog PID fields, for security reasons, it
> > will always be set to what the kernel passed to journald.
> > 
> > If this is something to support, then "logger" needs to to be patched so
> > that it can fake the SCM_CREDENTIALS metadata of the messages sent.
> > This requires privileges, but is not hard to do. Please file a bug
> > against util-linux and ask for for this to be added.
> 
>  Implemented, try logger(1) from util-linux git tree, please. 

Not sure what the "We" above refers to, but this change from 27a9eb5
may still not work for me:

+                   && geteuid() == 0 && kill(ctl->pid, 0) == 0) {

For me its required to run logger as non-root and still get the
specified number, like it used to do it years ago.

Olaf

Re: regression in logger output to syslog

[Lennart Poettering]

On Thu, 29.10.15 15:20, Olaf Hering (olaf@aepfle.de) wrote:

> On Thu, Oct 29, Karel Zak wrote:
> 
> > On Wed, Oct 21, 2015 at 11:37:43AM +0200, Olaf Hering wrote:
> > > On Mon, Oct 12, Olaf Hering wrote:
> > > 
> > > > So, its "systemd" who eats the required info.
> > > 
> > > In case you miss it:
> > > 
> > > ...
> > > We do not allow faking syslog PID fields, for security reasons, it
> > > will always be set to what the kernel passed to journald.
> > > 
> > > If this is something to support, then "logger" needs to to be patched so
> > > that it can fake the SCM_CREDENTIALS metadata of the messages sent.
> > > This requires privileges, but is not hard to do. Please file a bug
> > > against util-linux and ask for for this to be added.
> > 
> >  Implemented, try logger(1) from util-linux git tree, please. 
> 
> Not sure what the "We" above refers to, but this change from 27a9eb5
> may still not work for me:
> 
> +                   && geteuid() == 0 && kill(ctl->pid, 0) == 0) {
> 
> For me its required to run logger as non-root and still get the
> specified number, like it used to do it years ago.

Sorry, but this is something we are unlikely to support in
systemd. Allowing unprivileged processes to fake arbitrary UIDs is
a security problem, and it's really nothing we should provide support
for.

Sorry,

Lennart

-- 
Lennart Poettering, Red Hat

Re: regression in logger output to syslog

[Karel Zak]

On Thu, Oct 29, 2015 at 03:36:16PM +0100, Lennart Poettering wrote:
> On Thu, 29.10.15 15:20, Olaf Hering (olaf@aepfle.de) wrote:
> > +                   && geteuid() == 0 && kill(ctl->pid, 0) == 0) {
> > 
> > For me its required to run logger as non-root and still get the
> > specified number, like it used to do it years ago.
> 
> Sorry, but this is something we are unlikely to support in
> systemd. Allowing unprivileged processes to fake arbitrary UIDs is
> a security problem, and it's really nothing we should provide support
> for.

I think the problem is how Olaf see the log (e.g. by journal -f),
because journal contains *both* (fake and real) PIDs:

as non-root:

 $ echo $PPID
 1550

 $ logger -p info --id=$PPID "This is message baby!"


in the log:

 # journalctl -n 1
 Oct 29 16:23:26 ws kzak[30917]: This is message baby!


 # journalctl --output json-pretty -n 1
 {
        "__CURSOR" : "s=bbb763e3c9a144809dfe81e768d5a062;i=272c4;b=4f6802931e38450fa2bfd5f549f5103d;m=2c1ada2db1;t=5233fe472ce01;x=aaadb4455972d31",
        "__REALTIME_TIMESTAMP" : "1446132206194177",
        "__MONOTONIC_TIMESTAMP" : "189429067185",
        "_BOOT_ID" : "4f6802931e38450fa2bfd5f549f5103d",
        "PRIORITY" : "6",
        "_UID" : "1000",
        "_GID" : "1000",
        "_MACHINE_ID" : "160952cecfb7413db963a880ce10c399",
        "_HOSTNAME" : "ws",
        "_TRANSPORT" : "syslog",
        "SYSLOG_FACILITY" : "1",
        "SYSLOG_IDENTIFIER" : "kzak",
        "_COMM" : "logger",
        "SYSLOG_PID" : "1550",
        "MESSAGE" : "This is message baby!",
        "_PID" : "30917",
        "_SOURCE_REALTIME_TIMESTAMP" : "1446132206193526"
 }


_PID is the real PID, SYSLOG_PID is what has been specified by --id on
logger command line.

    Karel

-- 
 Karel Zak  <kzak@redhat.com>
 http://karelzak.blogspot.com