journalctl missing log between the system@suffix.journal

[syyhao1994]

systemd version the issue has been seen with

v246

CPU architecture issue was seen on

aarch64

Expected behaviour you didn't see

journalctl get all the log of system@suffix.journal

Unexpected behaviour you saw

journalctl missing some log between the files of system@suffix.journal.

Steps to reproduce the problem

for reproduce the problem easily, i modify the RuntimeMaxUse=8M RuntimeMaxFileSize=1M The problem is exist as well if we store the log under /var/log/journal.

1.the test.sh is used as below

[root@localhost ~]# cat test.sh
#!/bin/bash
while true
do
    for i in {0..10}
    do
        echo "MCE $i"
        echo "CPU 0 BANK 4"
        echo "MISC 0 ADDR 118abb000"
        echo "MCG status:"
        echo "MCi status:"
        echo "Corrected error"
        echo "Error enabled"
        echo "MCi_MISC register valid"
        echo "MCi_ADDR register valid"
        echo "MCA: MEMORY CONTROLLER RD_CHANNEL2_ERR"
        echo "Transaction: Memory read error"
        echo "PCU: PCU internal error No Error"
        echo "STATUS 9c00000000210092 MCGSTATUS 0"
        echo "MCGCAP 100010a APICID 0 SOCKETID 0"
        echo "MICROCODE 1"
        echo "CPUID Vendor Intel Family 6 Model 79 Step 1"
        echo "Hardware event. This is not a software error."
    done
done

[root@localhost ~]# cat /etc/rc.local
#!/bin/bash
# THIS FILE IS ADDED FOR COMPATIBILITY PURPOSES
#
# It is highly advisable to create own systemd services or udev rules
# to run scripts during boot instead of using this file.
#
# In contrast to previous versions due to parallel execution during boot
# this script will NOT be run after all other services.
#
# Please note that you must run 'chmod +x /etc/rc.d/rc.local' to ensure
# that this script will be executed during boot.

touch /var/lock/subsys/local
/usr/bin/bash /root/test.sh &

3 systemctl restart rc-local.service or reboot

4.

kill -9 pid(test.sh) 

Killing the test.sh.

5. We get the journactl_all.log by executing the command below, you will find the log in journactl_all.log is not continuous as we want. This log could be seen at the link: https://github.com/syyhao1994/files/blob/master/journactl_all.log.

   journalctl > journalctl_all.log

Then i got the systemxxx_all.log by executing the command list below. And i compared these two log, i found that the missing log was exactly between the two system@suffix.journal files. This log could be seen as the link: https://github.com/syyhao1994/files/blob/master/systemxxx_all.log

journalctl --file system@d62db8d1cdfd4c54a01f9dafba710337-00000000000277a9-0005b29e02ae604d.journal > /home/systemxxx_all.log
journalctl --file system@d62db8d1cdfd4c54a01f9dafba710337-0000000000027c10-0005b29e02aeb88c.journal >> /home/systemxxx_all.log
journalctl --file system@d62db8d1cdfd4c54a01f9dafba710337-000000000002807b-0005b29e02af0bf1.journal >> /home/systemxxx_all.log
journalctl --file system@d62db8d1cdfd4c54a01f9dafba710337-00000000000284e6-0005b29e02af582b.journal >> /home/systemxxx_all.log
journalctl --file system@d62db8d1cdfd4c54a01f9dafba710337-000000000002894d-0005b29e02afabcc.journal >> /home/systemxxx_all.log
journalctl --file system@d62db8d1cdfd4c54a01f9dafba710337-0000000000028db8-0005b29e02affdba.journal >> /home/systemxxx_all.log
journalctl --file system@d62db8d1cdfd4c54a01f9dafba710337-0000000000029223-0005b29e02b050de.journal >> /home/systemxxx_all.log
journalctl --file system@d62db8d1cdfd4c54a01f9dafba710337-000000000002968e-0005b29e02b09d43.journal >> /home/systemxxx_all.log
journalctl --file system.journal >> /home/systemxxx_all.log

The details could be seen at https://github.com/systemd/systemd/issues/17452.

Does anyone could give any suggestions about this problem? I am tring to figure out the solution to this problem but have't success util now. I am very curious about the solution of this problem. Thanks a lot. @poettering @georgmu @keszybz @yuwata

[syyhao1994]

Does anyone has any idea about this problem? cc @poettering @georgmu @keszybz @yuwata

[syyhao1994]

cc @mrc0mmand @poettering @georgmu @keszybz @yuwata

[vcaputo]

I'd love to take a look at this but I'm short on more time to volunteer towards systemd stuff, hopefully one of the RH folks can. It does appear to be a potentially important issue at a glance.

[syyhao1994]

I'd love to take a look at this but I'm short on more time to volunteer towards systemd stuff, hopefully one of the RH folks can. It does appear to be a potentially important issue at a glance.

I appreciate your work for it very much. I have studied for a long time, but i can't figure out how to resolve this util now. I think this problem is quite important and serious because it may cause missing log of journald. cc @vcaputo

[poettering]

You set extremely low limits on the overall directory size, which suggests vacuuming ran, i.e. old files got deleted to make space for new ones. This takes a couple of params into account, and most importantly age: oldest files are removed first.

I see that you are on an arm machine. Is the system clock correct during early boot? embedded devices aren't good at that. If the system clock is off, we might just vaccuuming a file that appears oldest because the timestamps are all off and start at the same time on each boot.

[syyhao1994]

You set extremely low limits on the overall directory size, which suggests vacuuming ran, i.e. old files got deleted to make space for new ones. This takes a couple of params into account, and most importantly age: oldest files are removed first.

I see that you are on an arm machine. Is the system clock correct during early boot? embedded devices aren't good at that. If the system clock is off, we might just vaccuuming a file that appears oldest because the timestamps are all off and start at the same time on each boot.

Thanks for your attention a lot.

The reason that i set low limits is just for reproduce the problem easily, i have tried that the problem is still exist even if i keep the default configuration of journald.conf.

The system clock is correct(maybe a little inaccurate). And i also tested this on X86_64 virtual machine, the problem is still exist.

And i don't actually cares about the oldest files very much. Because i store the journal under the directory of /run/log/journal, and i definitely will lose the old files when i reboot the vritual machine. The problem is that the log in the system@suffix.journal files are continuously but when i use journalctl the log between the system@suffix.journal files missing some log(Because we write the log continuesly, so the timestamps may be the same at the tail of system@suffix1.journal and the beginning of system@suffix2.journal).

The problem is not in writing, but in reading the journal, i think the problem maybe cause by the missing searching entry between system@suffix.journal that may have the same timestamps? I have tried to make some revise in next_beyond_location like the code listed below, hard-coding found to true:

/* OK, we found the spot, now let's advance until an entry
         * that is actually different from what we were previously
         * looking at. This is necessary to handle entries which exist
         * in two (or more) journal files, and which shall all be
         * suppressed but one. */

        for (;;) {
                bool found;
                // I commented the if condition here
                /*if (j->current_location.type == LOCATION_DISCRETE) {
                        int k;

                        k = compare_with_location(f, &j->current_location, j->current_file);

                        found = direction == DIRECTION_DOWN ? k > 0 : k < 0;
                } else
                        found = true;*/
                //hard-coding found to true
                found = true;

                if (found)
                        return 1;

                r = next_with_matches(j, f, direction, &c, &cp);
                if (r <= 0)
                        return r;

                journal_file_save_location(f, c, cp);
        }

And i used journalctl then, the log would not missing, but there is another problem is that some log at the beginning of system@suffix2.journal may go up to the end of system@suffix1.journal. Just like the two logs listed below. You can use the compare tool to see the difference between these two files and you will get it:

https://github.com/syyhao1994/files/blob/master/system%40xxx_sd24.log https://github.com/syyhao1994/files/blob/master/journalctl_sd24_all.log

This problem is similiar to the issue listed below, but they are different.#14898

[syyhao1994]

Do i need to feed back more details to make this problem more clearly? cc @poettering @yuwata @keszybz

[syyhao1994]

       /* If contents and timestamps match, these entries are
         * identical, even if the seqnum does not match */
        if (sd_id128_equal(af->current_boot_id, bf->current_boot_id) &&
            af->current_monotonic == bf->current_monotonic &&
            af->current_realtime == bf->current_realtime &&
            af->current_xor_hash == bf->current_xor_hash)
                return 0;

I figure out that this code could skip the logs in the tail of the system@suffix.log, the log shouldn't skip even the content and the timestamp are the same. And the reason why the logs of the head of the system@suffix.log are missing is under studing. Hope someone could get involve together to figure this problem out totally. cc @poettering @yuwata @keszybz @vcaputo @georgmu

[syyhao1994]

       /* If contents and timestamps match, these entries are
         * identical, even if the seqnum does not match */
        if (sd_id128_equal(af->current_boot_id, bf->current_boot_id) &&
            af->current_monotonic == bf->current_monotonic &&
            af->current_realtime == bf->current_realtime &&
            af->current_xor_hash == bf->current_xor_hash)
                return 0;

I figure out that this code could skip the logs in the tail of the system@suffix.log, the log shouldn't skip even the content and the timestamp are the same. And the reason why the logs of the head of the system@suffix.log are missing is under studing. Hope someone could get involve together to figure this problem out totally. cc @poettering @yuwata @keszybz @vcaputo @georgmu

if (l->monotonic_set &&
            sd_id128_equal(f->current_boot_id, l->boot_id) &&
            l->realtime_set &&
            f->current_realtime == l->realtime &&
            l->xor_hash_set &&
            f->current_xor_hash == l->xor_hash &&
            f != current_file)
                return 0;

The skipping of the logs in the head of the system@suffix.log maybe caused by the code listed above. So i don't think it is full enough to make the judgement to just skip the log that have the same realtime, monotonic and the xor_hash. If there are two same entries in the different .journal files. The log betweent these two entries are missing directly regardless the log between them.

https://github.com/systemd/systemd/issues/14898 The issue mentioned above just avoid the problem by showing duplicate entries if they are from the same file, but the code listed above could skip many logs that between two same entries that in different .journal files. So i think we shouldn't skip these logs as we want to showing duplicate entries if they are from the same file.

Maybe we shouldn't drop the log before figure out the how to reduce the repeating logs exactly. I think repeating logs is better than missing logs.

@vcaputo @poettering @yuwata @mrc0mmand @keszybz

[syyhao1994]

if (l->monotonic_set &&
            sd_id128_equal(f->current_boot_id, l->boot_id) &&
            l->realtime_set &&
            f->current_realtime == l->realtime &&
            l->xor_hash_set &&
            f->current_xor_hash == l->xor_hash &&
            f != current_file)
                return 0;

And the reason of missing logs at the begining of the system@suffix.log is caused by the code listed above. If there are two same entries in different .journal files, we just skip the one in the later .journal files. I think we should not skipping the logs even they have the same contests and timestamps. In this issue this mechanism caused the missing log by executing journalctl. I think showing repeating logs is better than missing logs that really matters. I made a PR as listed, please review. https://github.com/systemd/systemd/pull/17926 @vcaputo @poettering @yuwata @mrc0mmand @keszybz