Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

race: systemctl --wait start UNIT followed by journalctl -u UNIT: output sometimes missing #28650

Closed
edsantiago opened this issue Aug 2, 2023 · 3 comments

Comments

@edsantiago
Copy link

systemd version the issue has been seen with

systemd-253.7-1.fc38.x86_64

Used distribution

Fedora 38

Linux kernel version used

6.4.6-200.fc38.x86_64

CPU architectures issue was seen on

x86_64

Component

journalctl

Expected behaviour you didn't see

[ context: SERVICE emits one line of output and exits immediately ]

# systemctl --wait start SERVICE
# journalctl -u SERVICE
...date..host... one line of output!

Unexpected behaviour you saw

Sometimes fail to see output.

It is possible that this is the same as #2913 or #3767 or perhaps another issue I couldn't find. Or perhaps there's a --flush-output option to systemd start. If so I apologize.

Steps to reproduce the problem

journald-race.sh

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

...........................................................................
**FAILED foo-ZHFwFXrHH5PcmrEuilyD.service in 170 seconds

-- No entries --
retrying after 2 seconds:
Aug 02 14:28:15 host bash[144555]: GOT HERE
Aug 02 14:28:15 host systemd[1]: Started foo-ZHFwFXrHH5PcmrEuilyD.service - foo.
Aug 02 14:28:15 host systemd[1]: foo-ZHFwFXrHH5PcmrEuilyD.service: Deactivated successfully.
@edsantiago edsantiago added the bug 🐛 Programming errors, that need preferential fixing label Aug 2, 2023
@yuwata
Copy link
Member

yuwata commented Aug 2, 2023

That's expected. Please specify Type=oneshot for such testcase. Please see systemd.service(5) for more details.

@yuwata yuwata closed this as completed Aug 2, 2023
@yuwata yuwata added not-a-bug and removed bug 🐛 Programming errors, that need preferential fixing labels Aug 2, 2023
@edsantiago
Copy link
Author

@yuwata thank you for your quick response. I've modified the reproducer script as follows and I still see the same symptom:

@@ -15,6 +15,7 @@
 
 [Service]
 ExecStart=/bin/bash -c "echo GOT HERE"
+Type=oneshot
 EOF
 
     systemctl daemon-reload

@yuwata
Copy link
Member

yuwata commented Aug 2, 2023

Then, such 'race' is still expected. Simply, journald has not processed the output.

edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 2, 2023
Some people might expect this to work:

    systemctl --wait start foo
    journalctl -u foo  ---> displays output from foo

Well, it does not. Not reliably, anyway:

   systemd/systemd#28650

Shrug, okay, deal with it: write value of %T to a tmpfile
instead of relying on journal. I tested with TMPDIR=<many values>
on an SELinux system and, by golly, it works fine.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 3, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: Sleep(1) before every 'podman logs' or 'journalctl'.
Better ideas welcome.

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 3, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: Sleep(1) before every 'podman logs' or 'journalctl'.
Better ideas welcome.

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 3, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: Sleep(1) before every 'podman logs' or 'journalctl'.
Better ideas welcome.

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 3, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: Sleep(1) before every 'podman logs' or 'journalctl'.
Better ideas welcome.

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 3, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: Sleep(1) before every 'podman logs' or 'journalctl'.
Better ideas welcome.

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 3, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: Sleep(1) before every 'podman logs' or 'journalctl'.
Better ideas welcome.

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 3, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: Sleep(1) before every 'podman logs' or 'journalctl'.
Better ideas welcome.

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 3, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: Sleep(1) before every 'podman logs' or 'journalctl'.
Better ideas welcome.

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 4, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: Sleep(1) before every 'podman logs' or 'journalctl'.
Better ideas welcome.

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 4, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: Sleep(1) before every 'podman logs' or 'journalctl'.
Better ideas welcome.

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 4, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: Sleep(1) before every 'podman logs' or 'journalctl'.
Better ideas welcome.

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 7, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: wrap some podman-logs tests inside Eventually()
so they will be retried when log == journald

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 7, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: wrap some podman-logs tests inside Eventually()
so they will be retried when log == journald

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 8, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: wrap some podman-logs tests inside Eventually()
so they will be retried when log == journald

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 8, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: wrap some podman-logs tests inside Eventually()
so they will be retried when log == journald

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 8, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: wrap some podman-logs tests inside Eventually()
so they will be retried when log == journald

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 9, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: wrap some podman-logs tests inside Eventually()
so they will be retried when log == journald

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 9, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: wrap some podman-logs tests inside Eventually()
so they will be retried when log == journald

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 9, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: wrap some podman-logs tests inside Eventually()
so they will be retried when log == journald

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 9, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: wrap some podman-logs tests inside Eventually()
so they will be retried when log == journald

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
edsantiago added a commit to edsantiago/libpod that referenced this issue Aug 9, 2023
...to reduce flakes.

Reason: journald makes no guarantees. Just because a systemd job
has finished, or podman has written+flushed log entries, doesn't
mean that journald will actually know about them:

   systemd/systemd#28650

Workaround: wrap some podman-logs tests inside Eventually()
so they will be retried when log == journald

This addresses, but does not close, containers#18501. That's a firehose,
with many more failures than I can possibly cross-reference.
I will leave it open, then keep monitoring missing-logs flakes
over time, and pick those off as they occur.

Signed-off-by: Ed Santiago <santiago@redhat.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Development

No branches or pull requests

2 participants