journalctl --after-cursor combined with -u misses a log entry

[pulkomandy]

systemd version the issue has been seen with

250

Used distribution

Yocto Kirkstone

Linux kernel version used

5.15.85-6.2.1-rt55

CPU architectures issue was seen on

aarch64

Component

journalctl

Expected behaviour you didn't see

I am trying to use cursors to detect logs after a specific point in time (in relation with an automated test system).

The basic idea is we do this:

CURSOR=`journalctl --show-cursor`
systemd-cat -t test echo "____ CURSOR MARKER ____"

then perform some tests, then later on check for specific logs this way:

journalctl -u some_other_unit --after-cursor $CURSOR

When combining --after-cursor with -u in this way, the first message in the log is missing.

With journalctl -c it is working fine (but there is one message from "before" the cursor marker):

Full log:

root@s32g274aconbox2liebherr:~# journalctl -c 's=99886ee10fdf49a3a8fc135a5db3cdb9;i=56dc;b=b88b342dc1ec4fd78fe4f47996ed3276;m=11366d64a;t=60b733a4831c7;x=a1af33b6a0681f19'
Dec 01 14:03:07 s32g274aconbox2liebherr clouduploader[9303]: [info]: [cloud] No changes to properties, not sending device twin
Dec 01 14:03:07 s32g274aconbox2liebherr test[9417]: ____ CURSOR MARKER ____
Dec 01 14:03:07 s32g274aconbox2liebherr modem[9273]: [info]: [modem] Modem Cellular online on 4G network
Dec 01 14:03:07 s32g274aconbox2liebherr modem[9273]: [info]: [modem] State of Cellular connection change to Connected
Dec 01 14:03:07 s32g274aconbox2liebherr modem[9273]: [info]: [modem] State of Cellular connection change to Available

With filter on a specific unit:

root@s32g274aconbox2liebherr:~# journalctl -u modem -c 's=99886ee10fdf49a3a8fc135a5db3cdb9;i=56dc;b=b88b342dc1ec4fd78fe4f47996ed3276;m=11366d64a;t=60b733a4831c7;x=a1af33b6a0681f19'
Dec 01 14:03:07 s32g274aconbox2liebherr modem[9273]: [info]: [modem] Modem Cellular online on 4G network
Dec 01 14:03:07 s32g274aconbox2liebherr modem[9273]: [info]: [modem] State of Cellular connection change to Connected
Dec 01 14:03:07 s32g274aconbox2liebherr modem[9273]: [info]: [modem] State of Cellular connection change to Available

We get exactly the expected messages here.

I expect that when using --after-cursor, we would get this:

root@s32g274aconbox2liebherr:~# journalctl --after-cursor 's=99886ee10fdf49a3a8fc135a5db3cdb9;i=56dc;b=b88b342dc1ec4fd78fe4f47996ed3276;m=11366d64a;t=60b733a4831c7;x=a1af33b6a0681f19'
Dec 01 14:03:07 s32g274aconbox2liebherr test[9417]: ____ CURSOR MARKER ____
Dec 01 14:03:07 s32g274aconbox2liebherr modem[9273]: [info]: [modem] Modem Cellular online on 4G network
Dec 01 14:03:07 s32g274aconbox2liebherr modem[9273]: [info]: [modem] State of Cellular connection change to Connected
Dec 01 14:03:07 s32g274aconbox2liebherr modem[9273]: [info]: [modem] State of Cellular connection change to Available

root@s32g274aconbox2liebherr:~# journalctl -u modem --after-cursor 's=99886ee10fdf49a3a8fc135a5db3cdb9;i=56dc;b=b88b342dc1ec4fd78fe4f47996ed3276;m=11366d64a;t=60b733a4831c7;x=a1af33b6a0681f19'
Dec 01 14:03:07 s32g274aconbox2liebherr modem[9273]: [info]: [modem] Modem Cellular online on 4G network
Dec 01 14:03:07 s32g274aconbox2liebherr modem[9273]: [info]: [modem] State of Cellular connection change to Connected
Dec 01 14:03:07 s32g274aconbox2liebherr modem[9273]: [info]: [modem] State of Cellular connection change to Available

Unexpected behaviour you saw

Here is an example without any unit filter, note how the log start with the "____ CURSOR MARKER ____" log as expected, and after it there are 3 messages from our "modem" service:

root@machine:~# journalctl --after-cursor 's=99886ee10fdf49a3a8fc135a5db3cdb9;i=56dc;b=b88b342dc1ec4fd78fe4f47996ed3276;m=11366d64a;t=60b733a4831c7;x=a1af33b6a0681f19'
Dec 01 14:03:07 s32g274aconbox2liebherr test[9417]: ____ CURSOR MARKER ____
Dec 01 14:03:07 s32g274aconbox2liebherr modem[9273]: [info]: [modem] Modem Cellular online on 4G network
Dec 01 14:03:07 s32g274aconbox2liebherr modem[9273]: [info]: [modem] State of Cellular connection change to Connected
Dec 01 14:03:07 s32g274aconbox2liebherr modem[9273]: [info]: [modem] State of Cellular connection change to Available

Now I try to filter this to get only the messages from the modem service:

root@s32g274aconbox2liebherr:~# journalctl -u modem --after-cursor 's=99886ee10fdf49a3a8fc135a5db3cdb9;i=56dc;b=b88b342dc1ec4fd78fe4f47996ed3276;m=11366d64a;t=60b733a4831c7;x=a1af33b6a0681f19'
Dec 01 14:03:07 s32g274aconbox2liebherr modem[9273]: [info]: [modem] State of Cellular connection change to Connected
Dec 01 14:03:07 s32g274aconbox2liebherr modem[9273]: [info]: [modem] State of Cellular connection change to Available

The cursor marker is not visible (since it is in another unit), but also the fist message from the modem service is now missing. It looks like --after-cursor attempts to get the output from -c and simply skip over the first message, without checking if that message is actually the one pointed by the cursor, or some later message because there were other journalctl options causing the initial message pointed by the cursor to not appear.

Steps to reproduce the problem

CURSOR=`journalctl --show-cursor`
systemd-cat -t test echo "____ CURSOR MARKER ____"
journalctl --after-cursor $CURSOR # look for messages from some_other_unit and note the first message after the "____ CURSOR MARKER ____" log
journalctl -u some_other_unit --after-cursor $CURSOR

Notice that the first message from "some_oter_unit" after the "____ CURSOR MARKER ____" is missing in the second call to journalctl

Additional program output to the terminal or log subsystem illustrating the issue

No response