<html xmlns:v="urn:schemas-microsoft-com:vml" xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40"> <head> <meta http-equiv="Content-Type" content="text/html; charset=utf-8"> <meta name="Generator" content="Microsoft Word 15 (filtered medium)"> <style></style> </head> <body lang="DE" link="#0563C1" vlink="#954F72"> <div class="WordSection1"> Hi Folks,<o:p></o:p> <o:p> </o:p> First of all, thank you, Lennart, for your explanation. If I understand it correctly, it is a timing issue that occurs because the initiating process has already terminated and is unable to provide the information needed by the logger. If this is the reason for the error, then delaying its termination should eliminate it. To test it, I have added a usleep (10'000'000)command as the last instruction in test 4, but without success - the test still loses a message.<o:p></o:p> <o:p> </o:p> So I have followed the advice of Ulrich to deliver my test sources, so you can experiment for yourself. My current test is stripped down to the relevant source code and attached as file CompactJournalIntegrationTest.tar. The test contains file CMakeLists.txt, which can be used to build up the entire test via cmake. It is based on Google’s testing framework, which is fetched automatically from the Git repository. <o:p></o:p> <o:p> </o:p> Essentially there are 4 tests with increasing complexity:<o:p></o:p> <ol style="margin-top:0cm" start="1" type="1"> <li class="MsoListParagraph" style="margin-left:0cm;mso-list:l1 level1 lfo1">The first one just sends 5 small messages (~20 bytes) with priority Debug, Info, Warning, Error and Critical (the customer only needs these priorities). After that, the logger’s storage is synchronized and analyzed if all messages have been arrived correctly (via APIs sd_journal_...).<o:p></o:p></li><li class="MsoListParagraph" style="margin-left:0cm;mso-list:l1 level1 lfo1">The second test sends 10,000 small messages (~20 bytes) to the logger with priority Debug. After that, the logger’s storage is synchronized and analyzed if all messages have been arrived correctly (via APIs sd_journal_...).<o:p></o:p></li><li class="MsoListParagraph" style="margin-left:0cm;mso-list:l1 level1 lfo1">The third one sends 10,000 big messages (~10,000 bytes) to the logger with priority Debug, which are good to compress. After that, the logger’s storage is synchronized and analyzed if all messages have been arrived correctly (via APIs sd_journal_...).<o:p></o:p></li><li class="MsoListParagraph" style="margin-left:0cm;mso-list:l1 level1 lfo1">The last one sends 10,000 big messages (~10,000 bytes) to the logger with priority Debug, which are hard to compress. After that, the logger’s storage is synchronized and analyzed if all messages have been arrived correctly (via APIs sd_journal_...).<o:p></o:p></li></ol> The tests are named JournalIntegrationTest.T1 … JournalIntegrationTest.T4 and must be started with command sudo ./JournalIntegrationTest. Add –help to get further information.<o:p></o:p> <o:p> </o:p> The following observations can be made now:<o:p></o:p> <ul style="margin-top:0cm" type="disc"> <li class="MsoListParagraph" style="margin-left:0cm;mso-list:l0 level1 lfo2">If all tests are started separately, all is fine.<o:p></o:p></li><li class="MsoListParagraph" style="margin-left:0cm;mso-list:l0 level1 lfo2">If test 3 + 4 are started together, all is fine.<o:p></o:p></li><li class="MsoListParagraph" style="margin-left:0cm;mso-list:l0 level1 lfo2">If test 2 + 3 + 4 are started together, all is fine.<o:p></o:p></li><li class="MsoListParagraph" style="margin-left:0cm;mso-list:l0 level1 lfo2">If test 1 + 2 + 3 + 4 are started together, test 4 has lost one message, which is always the last one.<o:p></o:p></li></ul> <o:p> </o:p> An incorrect test run looks like the following.<o:p></o:p> <o:p> </o:p> developer@debianVM ..b/CompactJournaldIntegrationTest/build % sudo ./JournalIntegrationTest --gtest_filter="*.T4:*.T3:*.T2:*.T1"<o:p></o:p> Running main() from /home/developer/scb/CompactJournaldIntegrationTest/build/_deps/googletest-src/googletest/src/gtest_main.cc<o:p></o:p> Note: Google Test filter = *.T4:*.T3:*.T2:*.T1<o:p></o:p> [==========] Running 4 tests from 1 test suite.<o:p></o:p> [----------] Global test environment set-up.<o:p></o:p> [----------] 4 tests from JournalIntegrationTest<o:p></o:p> [ RUN ] JournalIntegrationTest.T1<o:p></o:p> [ OK ] JournalIntegrationTest.T1 (87 ms)<o:p></o:p> [ RUN ] JournalIntegrationTest.T2<o:p></o:p> [ OK ] JournalIntegrationTest.T2 (1850 ms)<o:p></o:p> [ RUN ] JournalIntegrationTest.T3<o:p></o:p> [ OK ] JournalIntegrationTest.T3 (8090 ms)<o:p></o:p> [ RUN ] JournalIntegrationTest.T4<o:p></o:p> /home/developer/scb/CompactJournaldIntegrationTest/Test.cpp:104: Failure<o:p></o:p> Expected equality of these values:<o:p></o:p> numberOfMessages<o:p></o:p> Which is: 10000<o:p></o:p> foundCounter<o:p></o:p> Which is: 9999<o:p></o:p> [ FAILED ] JournalIntegrationTest.T4 (16758 ms)<o:p></o:p> [----------] 4 tests from JournalIntegrationTest (26785 ms total)<o:p></o:p> <o:p> </o:p> [----------] Global test environment tear-down<o:p></o:p> [==========] 4 tests from 1 test suite ran. (26785 ms total)<o:p></o:p> [ PASSED ] 3 tests.<o:p></o:p> [ FAILED ] 1 test, listed below:<o:p></o:p> [ FAILED ] JournalIntegrationTest.T4<o:p></o:p> <o:p> </o:p> 1 FAILED TEST<o:p></o:p> <o:p> </o:p> Via parameter –gtest_filter it is possible to select the tests that should run. Running the suite without test 1 will succeed.<o:p></o:p> <o:p> </o:p> developer@debianVM ..b/CompactJournaldIntegrationTest/build % sudo ./JournalIntegrationTest --gtest_filter="*.T4:*.T3:*.T2"<o:p></o:p> Running main() from /home/developer/scb/CompactJournaldIntegrationTest/build/_deps/googletest-src/googletest/src/gtest_main.cc<o:p></o:p> Note: Google Test filter = *.T4:*.T3:*.T2<o:p></o:p> [==========] Running 3 tests from 1 test suite.<o:p></o:p> [----------] Global test environment set-up.<o:p></o:p> [----------] 3 tests from JournalIntegrationTest<o:p></o:p> [ RUN ] JournalIntegrationTest.T2<o:p></o:p> [ OK ] JournalIntegrationTest.T2 (1371 ms)<o:p></o:p> [ RUN ] JournalIntegrationTest.T3<o:p></o:p> [ OK ] JournalIntegrationTest.T3 (8171 ms)<o:p></o:p> [ RUN ] JournalIntegrationTest.T4<o:p></o:p> [ OK ] JournalIntegrationTest.T4 (17595 ms)<o:p></o:p> [----------] 3 tests from JournalIntegrationTest (27137 ms total)<o:p></o:p> <o:p> </o:p> [----------] Global test environment tear-down<o:p></o:p> [==========] 3 tests from 1 test suite ran. (27137 ms total)<o:p></o:p> [ PASSED ] 3 tests.<o:p></o:p> <o:p> </o:p> Also a single run of T4 works.<o:p></o:p> <o:p> </o:p> developer@debianVM ..b/CompactJournaldIntegrationTest/build % sudo ./JournalIntegrationTest --gtest_filter="*.T4" <o:p></o:p> Running main() from /home/developer/scb/CompactJournaldIntegrationTest/build/_deps/googletest-src/googletest/src/gtest_main.cc<o:p></o:p> Note: Google Test filter = *.T4<o:p></o:p> [==========] Running 1 test from 1 test suite.<o:p></o:p> [----------] Global test environment set-up.<o:p></o:p> [----------] 1 test from JournalIntegrationTest<o:p></o:p> [ RUN ] JournalIntegrationTest.T4<o:p></o:p> [ OK ] JournalIntegrationTest.T4 (17343 ms)<o:p></o:p> [----------] 1 test from JournalIntegrationTest (17344 ms total)<o:p></o:p> <o:p> </o:p> [----------] Global test environment tear-down<o:p></o:p> [==========] 1 test from 1 test suite ran. (17344 ms total)<o:p></o:p> [ PASSED ] 1 test.<o:p></o:p> <o:p> </o:p> So, do you have an idea what’s going on here?<o:p></o:p> <o:p> </o:p> You will find the corresponding configuration attached below.<o:p></o:p> <o:p> </o:p> Greetings from Berlin,<o:p></o:p> Andreas<o:p></o:p> <o:p> </o:p> <o:p> </o:p> <o:p> </o:p> <o:p> </o:p> [Journal]<o:p></o:p> Storage=persistent<o:p></o:p> Compress=yes<o:p></o:p> Seal=yes<o:p></o:p> SplitMode=none<o:p></o:p> #SyncIntervalSec=5m<o:p></o:p> #RateLimitIntervalSec=30s<o:p></o:p> #RateLimitBurst=10000<o:p></o:p> SystemMaxUse=500M<o:p></o:p> #SystemKeepFree=<o:p></o:p> SystemMaxFileSize=50M<o:p></o:p> SystemMaxFiles=13<o:p></o:p> #RuntimeMaxUse=<o:p></o:p> #RuntimeKeepFree=<o:p></o:p> #RuntimeMaxFileSize=<o:p></o:p> #RuntimeMaxFiles=100<o:p></o:p> MaxRetentionSec=12month<o:p></o:p> #MaxFileSec=1month<o:p></o:p> #ForwardToSyslog=yes<o:p></o:p> #ForwardToKMsg=no<o:p></o:p> #ForwardToConsole=no<o:p></o:p> #ForwardToWall=yes<o:p></o:p> #TTYPath=/dev/console<o:p></o:p> #MaxLevelStore=debug<o:p></o:p> #MaxLevelSyslog=debug<o:p></o:p> #MaxLevelKMsg=notice<o:p></o:p> #MaxLevelConsole=info<o:p></o:p> #MaxLevelWall=emerg<o:p></o:p> #LineMax=48K<o:p></o:p> #ReadKMsg=yes<o:p></o:p> <o:p> </o:p> <o:p> </o:p> <o:p> </o:p> -----Ursprüngliche Nachricht----- Von: Ulrich Windl <Ulrich.Windl@rz.uni-regensburg.de> Gesendet: Dienstag, 6. Juli 2021 14:16 An: Andreas Krueger <Andreas.Krueger@fmc-ag.com>; Lennart Poettering <lennart@poettering.net> Cc: Georg Brand <Georg.Brand@fmc-ag.com>; Thomas Zimmermann <thomas.zimmermann@fmc-ag.com>; systemd-devel@lists.freedesktop.org Betreff: Antw: [EXT] Re: [systemd-devel] Failing UnitTest for Journald <o:p> </o:p> *** This message is from an EXTERNAL SENDER - be CAUTIOUS with links and when opening attachments ***<o:p></o:p> <o:p> </o:p> <o:p> </o:p> >>> Lennart Poettering <<a href="mailto:lennart@poettering.net">lennart@poettering.net</a>> schrieb am 06.07.2021 um <o:p></o:p> >>> 11:15<o:p></o:p> in<o:p></o:p> Nachricht <YOQfRHFU4pNzn3qJ@gardel-login>:<o:p></o:p> > On Mo, 05.07.21 18:46, Andreas Krueger (Andreas.Krueger@fmc‑ag.com) wrote:<o:p></o:p> ><o:p> </o:p> >> Hi Folks,<o:p></o:p> >><o:p> </o:p> >> for a customer I have to verify the behavior of the logger in its <o:p></o:p> >> system (Linux debianVM 4.19.0‑6‑amd64 #1 SMP Debian<o:p></o:p> >> 4.19.67‑2+deb10u1 (2019‑09‑20) x86_64 GNU/Linux), which is journald <o:p></o:p> >> (systemd 241 (241)). For this, I have written some unit tests that <o:p></o:p> >> work all well, when executed separately. But running together they <o:p></o:p> >> lead to some erroneous behavior that I cannot explain ‑ maybe you <o:p></o:p> >> have an idea what's going wrong...<o:p></o:p> ><o:p> </o:p> > I am not sure I follow entirely what you are doing. But please be <o:p></o:p> > aware of the following race we cannot fix without kernel changes:<o:p></o:p> ><o:p> </o:p> > Whenever journald receieves a log message from a client it uses the <o:p></o:p> > SCM_CREDENTIALS metadata of the incoming packet to retrieve further <o:p></o:p> > medadata from /proc/$PID/ about the client. If the sender's process <o:p></o:p> > exited by the time the message is processed this data is not available <o:p></o:p> > anymore, and thus will not be stored along with the message, and can <o:p></o:p> > thus not be used to search/filter for the message.<o:p></o:p> <o:p> </o:p> I don't know how such a client would be named then, but have you considered naming it "stale-PID-<PID>"?<o:p></o:p> At least then the users could notice that something might not work as expected.<o:p></o:p> <o:p> </o:p> While trying to lear I found that in my manual page for SYSTEMD-JOURNALD.SERVICE a page sd_journal_print(4) is referred to, but it dpoes not exist in my system (systemd-228-157.27.1.x86_64 of SLES12)...<o:p></o:p> <o:p> </o:p> ><o:p> </o:p> > Thus: whenever you have a process that logs and immediately exits <o:p></o:p> > there's a chance that once journald processes that log message, it is <o:p></o:p> > seen and written to disk but without much of the metadata. If you then <o:p></o:p> > use "journalctl ‑u" or a similar command (e.g. the log output of <o:p></o:p> > systemctl status) to look for the logs of the unit it will likely not <o:p></o:p> > be found since the unit name is one of the metadata fields not <o:p></o:p> > available in this case (since it is extracted from the <o:p> </o:p> > /proc/$PID/cgroup file by journald).<o:p></o:p> ><o:p> </o:p> > You should see the log message if you do not use filtering though, <o:p></o:p> > i.e. "journalctl ‑e" or so should show it.<o:p></o:p> ><o:p> </o:p> > We'd really like to fix this one day, but unfortunately kernel <o:p></o:p> > developers so far shot down any attempt to optionally attach more <o:p></o:p> > metadata to AF_UNIX datagrams (if we had just the cgroup this would <o:p></o:p> > already make things *so* much better for us).<o:p></o:p> <o:p> </o:p> Regards,<o:p></o:p> Ulrich<o:p></o:p> <o:p> </o:p> ><o:p> </o:p> > Lennart<o:p></o:p> ><o:p> </o:p> > ‑‑<o:p></o:p> > Lennart Poettering, Berlin<o:p></o:p> > _______________________________________________<o:p></o:p> > systemd‑devel mailing list<o:p></o:p> > systemd‑devel@lists.freedesktop.org<o:p></o:p> > https://lists.freedesktop.org/mailman/listinfo/systemd‑devel<o:p></o:p> <o:p> </o:p> <o:p> </o:p> <o:p> </o:p> </div> </body> </html>