[systemd-devel] Antw: [EXT] Re: Failing UnitTest for Journald
>>> Lennart Poettering schrieb am 06.07.2021 um 11:15 in Nachricht : > On Mo, 05.07.21 18:46, Andreas Krueger (Andreas.Krueger@fmc‑ag.com) wrote: > >> Hi Folks, >> >> for a customer I have to verify the behavior of the logger in its >> system (Linux debianVM 4.19.0‑6‑amd64 #1 SMP Debian >> 4.19.67‑2+deb10u1 (2019‑09‑20) x86_64 GNU/Linux), which is journald >> (systemd 241 (241)). For this, I have written some unit tests that >> work all well, when executed separately. But running together they >> lead to some erroneous behavior that I cannot explain ‑ maybe you >> have an idea what's going wrong... > > I am not sure I follow entirely what you are doing. But please be > aware of the following race we cannot fix without kernel changes: > > Whenever journald receieves a log message from a client it uses the > SCM_CREDENTIALS metadata of the incoming packet to retrieve further > medadata from /proc/$PID/ about the client. If the sender's process > exited by the time the message is processed this data is not available > anymore, and thus will not be stored along with the message, and can > thus not be used to search/filter for the message. I don't know how such a client would be named then, but have you considered naming it "stale-PID-"? At least then the users could notice that something might not work as expected. 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)... > > Thus: whenever you have a process that logs and immediately exits > there's a chance that once journald processes that log message, it is > seen and written to disk but without much of the metadata. If you then > use "journalctl ‑u" or a similar command (e.g. the log output of > systemctl status) to look for the logs of the unit it will likely not > be found since the unit name is one of the metadata fields not > available in this case (since it is extracted from the > /proc/$PID/cgroup file by journald). > > You should see the log message if you do not use filtering though, > i.e. "journalctl ‑e" or so should show it. > > We'd really like to fix this one day, but unfortunately kernel > developers so far shot down any attempt to optionally attach more > metadata to AF_UNIX datagrams (if we had just the cgroup this would > already make things *so* much better for us). Regards, Ulrich > > Lennart > > ‑‑ > Lennart Poettering, Berlin > ___ > systemd‑devel mailing list > systemd‑de...@lists.freedesktop.org > https://lists.freedesktop.org/mailman/listinfo/systemd‑devel ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/systemd-devel
[systemd-devel] Please unsubscribe me at the enclosed mail!
hish...@cs.technion.ac.il Thanks, Hisham Abdu MSC. ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/systemd-devel
Re: [systemd-devel] Failing UnitTest for Journald
On Mo, 05.07.21 18:46, Andreas Krueger (andreas.krue...@fmc-ag.com) wrote: > Hi Folks, > > for a customer I have to verify the behavior of the logger in its > system (Linux debianVM 4.19.0-6-amd64 #1 SMP Debian > 4.19.67-2+deb10u1 (2019-09-20) x86_64 GNU/Linux), which is journald > (systemd 241 (241)). For this, I have written some unit tests that > work all well, when executed separately. But running together they > lead to some erroneous behavior that I cannot explain - maybe you > have an idea what's going wrong... I am not sure I follow entirely what you are doing. But please be aware of the following race we cannot fix without kernel changes: Whenever journald receieves a log message from a client it uses the SCM_CREDENTIALS metadata of the incoming packet to retrieve further medadata from /proc/$PID/ about the client. If the sender's process exited by the time the message is processed this data is not available anymore, and thus will not be stored along with the message, and can thus not be used to search/filter for the message. Thus: whenever you have a process that logs and immediately exits there's a chance that once journald processes that log message, it is seen and written to disk but without much of the metadata. If you then use "journalctl -u" or a similar command (e.g. the log output of systemctl status) to look for the logs of the unit it will likely not be found since the unit name is one of the metadata fields not available in this case (since it is extracted from the /proc/$PID/cgroup file by journald). You should see the log message if you do not use filtering though, i.e. "journalctl -e" or so should show it. We'd really like to fix this one day, but unfortunately kernel developers so far shot down any attempt to optionally attach more metadata to AF_UNIX datagrams (if we had just the cgroup this would already make things *so* much better for us). Lennart -- Lennart Poettering, Berlin ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/systemd-devel
[systemd-devel] Antw: [EXT] Failing UnitTest for Journald
Hi! My guess is you'll get a faster useful response if you publish your test cases. Regards, Ulrich >>> Andreas Krueger schrieb am 05.07.2021 um 20:46 in Nachricht > Hi Folks, > > for a customer I have to verify the behavior of the logger in its system > (Linux debianVM 4.19.0‑6‑amd64 #1 SMP Debian 4.19.67‑2+deb10u1 (2019‑09‑20) x86_64 > GNU/Linux), which is journald (systemd 241 (241)). > For this, I have written some unit tests that work all well, when executed > separately. But running together they lead to some erroneous behavior that I > cannot explain ‑ maybe you have an idea what's going wrong... > > Essentially there are 4 tests with increasing complexity: > > 1. 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_...). > 2. 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_...). > 3. 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_...). > 4. 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_...). > > The following observations can be made now: > > * If all tests are started separately, all is fine. > * If test 3 + 4 are started together, all is fine. > * If test 2 + 3 + 4 are started together, all is fine. > * If test 1 + 2 + 3 + 4 are started together, test 4 has lost one > message, which is always the last one. > > In my test collection there is another quite simple test, which is a bit > more complex than test 1 ‑ let's call it 1a. When test 1 + 1a + 2 + 3 + 4 are > started together, test 4 loses about 10 messages, which are always the last > messages sent to the logger. This can be verified just by using the command > journalctl ‑no‑pager ‑n 20. > > Suspecting that this may be a timing issue, I have delayed the execution of > test 4 by 10 seconds, but without success. Does anyone have an idea for this > behavior? > > Attached next you will find the corresponding configuration. > > With regards, > Andreas > > > > > [Journal] > Storage=persistent > Compress=yes > Seal=yes > SplitMode=none > #SyncIntervalSec=5m > #RateLimitIntervalSec=30s > #RateLimitBurst=1 > SystemMaxUse=500M > #SystemKeepFree= > SystemMaxFileSize=50M > SystemMaxFiles=13 > #RuntimeMaxUse= > #RuntimeKeepFree= > #RuntimeMaxFileSize= > #RuntimeMaxFiles=100 > MaxRetentionSec=12month > #MaxFileSec=1month > #ForwardToSyslog=yes > #ForwardToKMsg=no > #ForwardToConsole=no > #ForwardToWall=yes > #TTYPath=/dev/console > #MaxLevelStore=debug > #MaxLevelSyslog=debug > #MaxLevelKMsg=notice > #MaxLevelConsole=info > #MaxLevelWall=emerg > #LineMax=48K > #ReadKMsg=yes ___ systemd-devel mailing list systemd-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/systemd-devel
