stdout overwriting logger output for service units

stdout overwriting logger output for service units

[jcmalek]

[-- Attachment #1: Type: text/plain, Size: 2554 bytes --]

Hi there Poky team,

I have recently noticed that some of the stdout output has been overwriting the logger output when I do a "journalctl -u service_name" on any of the services. The systemd team has referred me to this project (my downstream distro) to look into the issue before they are willing to have a look. They would ideally like this tested on a newer version of systemd. The steps to reproduce the problem are fairly simple. I have hopefully included all the relevant details below. Please let me know if there is anything else you need.

systemd version the issue has been seen with
--------------------------------------------

246

Used distribution
-----------------

Poky (Yocto Project Reference Distro) 3.2.4 \n \l

Linux kernel version used
-------------------------

5.12.10

CPU architectures issue was seen on
-----------------------------------

arm

Component
---------

journalctl

Expected behaviour you didn't see
---------------------------------

Expected both logger and standard output to appear in service unit logs:

journalctl -f -u test
Nov 16 15:05:08 c-00012 sh[1617]: Standard output: 1
Nov 16 15:05:08 c-00012 root[1650]: Logger: 1
Nov 16 15:05:08 c-00012 sh[1617]: Standard output: 2
Nov 16 15:05:08 c-00012 root[1652]: Logger: 2
Nov 16 15:05:09 c-00012 sh[1617]: Standard output: 3
Nov 16 15:05:09 c-00012 root[1654]: Logger: 3
Nov 16 15:05:10 c-00012 sh[1617]: Standard output: 4
Nov 16 15:05:10 c-00012 root[1656]: Logger: 4
Nov 16 15:05:11 c-00012 sh[1617]: Standard output: 5
Nov 16 15:05:11 c-00012 root[1658]: Logger: 5

Unexpected behaviour you saw
----------------------------

I only get the standard output messages and every once and a while one of the logger messages sneaks through:

journalctl -f -u test
Nov 16 15:05:08 c-00012 sh[1617]: Standard output: 1
Nov 16 15:05:08 c-00012 sh[1617]: Standard output: 2
Nov 16 15:05:09 c-00012 sh[1617]: Standard output: 3
Nov 16 15:06:09 c-00012 root[1654]: Logger: 3
Nov 16 15:05:10 c-00012 sh[1617]: Standard output: 4
Nov 16 15:05:11 c-00012 sh[1617]: Standard output: 5

Steps to reproduce the problem
------------------------------

test.service contents:

[Unit]
Description=Test
DefaultDependencies=no

[Service]
Type=oneshot
ExecStart=/bin/sh /mytest.sh
RemainAfterExit=yes

/mytest.sh contents:

#!/bin/sh
i=0
while [ $i -le 100 ]; do
 echo "Standard output: ${i}"
 logger "Logger: ${i}"
 sleep 1
 i=$((i+1))
done

* journalctl -f -u test
* systemctl start test

[-- Attachment #2: Type: text/html, Size: 10413 bytes --]

Re: [poky] stdout overwriting logger output for service units

[Khem Raj]

maybe try

[Service]
StandardError=journal
StandardOutput=journal

as well in your service unit file, might help.

On Wed, Nov 23, 2022 at 9:08 AM <jcmalek@lakeheadu.ca> wrote:
>
> Hi there Poky team,
>
> I have recently noticed that some of the stdout output has been overwriting the logger output when I do a "journalctl -u service_name" on any of the services. The systemd team has referred me to this project (my downstream distro) to look into the issue before they are willing to have a look. They would ideally like this tested on a newer version of systemd. The steps to reproduce the problem are fairly simple. I have hopefully included all the relevant details below. Please let me know if there is anything else you need.
>
>
>
> systemd version the issue has been seen with
>
> 246
>
> Used distribution
>
> Poky (Yocto Project Reference Distro) 3.2.4 \n \l
>
> Linux kernel version used
>
> 5.12.10
>
> CPU architectures issue was seen on
>
> arm
>
> Component
>
> journalctl
>
> Expected behaviour you didn't see
>
> Expected both logger and standard output to appear in service unit logs:
>
> journalctl -f -u test
> Nov 16 15:05:08 c-00012 sh[1617]: Standard output: 1
> Nov 16 15:05:08 c-00012 root[1650]: Logger: 1
> Nov 16 15:05:08 c-00012 sh[1617]: Standard output: 2
> Nov 16 15:05:08 c-00012 root[1652]: Logger: 2
> Nov 16 15:05:09 c-00012 sh[1617]: Standard output: 3
> Nov 16 15:05:09 c-00012 root[1654]: Logger: 3
> Nov 16 15:05:10 c-00012 sh[1617]: Standard output: 4
> Nov 16 15:05:10 c-00012 root[1656]: Logger: 4
> Nov 16 15:05:11 c-00012 sh[1617]: Standard output: 5
> Nov 16 15:05:11 c-00012 root[1658]: Logger: 5
>
> Unexpected behaviour you saw
>
> I only get the standard output messages and every once and a while one of the logger messages sneaks through:
>
> journalctl -f -u test
> Nov 16 15:05:08 c-00012 sh[1617]: Standard output: 1
> Nov 16 15:05:08 c-00012 sh[1617]: Standard output: 2
> Nov 16 15:05:09 c-00012 sh[1617]: Standard output: 3
> Nov 16 15:06:09 c-00012 root[1654]: Logger: 3
> Nov 16 15:05:10 c-00012 sh[1617]: Standard output: 4
> Nov 16 15:05:11 c-00012 sh[1617]: Standard output: 5
>
> Steps to reproduce the problem
>
> test.service contents:
>
> [Unit]
> Description=Test
> DefaultDependencies=no
>
>
> [Service]
> Type=oneshot
> ExecStart=/bin/sh /mytest.sh
> RemainAfterExit=yes
>
> /mytest.sh contents:
>
> #!/bin/sh
> i=0
> while [ $i -le 100 ]; do
>   echo "Standard output: ${i}"
>   logger "Logger: ${i}"
>   sleep 1
>   i=$((i+1))
> done
>
> journalctl -f -u test
> systemctl start test
>
>
> 
>

Re: stdout overwriting logger output for service units

[jcmalek]

[-- Attachment #1: Type: text/plain, Size: 212 bytes --]

Thanks but no luck when I tried:

[Service]
StandardError=journal
StandardOutput=journal

Or:

[Service]
StandardError=kmsg
StandardOutput=kmsg

I still have the same problem in both of these cases.

[-- Attachment #2: Type: text/html, Size: 761 bytes --]