race condition in logs -f with journald driver

[vrothberg]

Reproducer from #10222 (comment):

$ while :;do ./bin/podman run --log-driver=journald -d --name foo quay.io/libpod/testimage:20210427 sh -c 'echo hi;sleep 2;echo bye';./bin/podman logs -f foo;./bin/podman rm foo;done
caf4dce7ce3ac5d08da339a8c0ecd4ec97df498cd472fbff61182352e71cf831
hi     <---- there is no subsequent bye!
caf4dce7ce3ac5d08da339a8c0ecd4ec97df498cd472fbff61182352e71cf831
08f58203f738027300d651fed861f1673eb8a1a953b869c788d905664b709938
hi
bye

I know where the error is and will drop a // FIXME in libpod/container_logs_linux.go (and a link to the code once #10222 is merged).

[vrothberg]

@rhatdan FYI

[vrothberg]

As pointed out in https://github.com/containers/podman/pull/10222/files#diff-20cc30e1cdf302ef7404e5923eada3912c68c8b8943c0a7a0a834b29236eba69R92, using the Follow API is racy. In order to get it done correctly, we have to implement our custom follow function that forward everything from stdout and stderr UNTIL we read on the journal that the container died (i.e., get the died event).

I looked at the journal and the died event is always printed after the logs are written. The problem at the moment is that we have to many things running concurrently. Having one goroutine reading the log and filtering out what's necessary until we read the died event seems one way to avoid that race.

[mheon]

We should refactor the Wait code to use the logic where we wait for the Died event - it’s already implemented for the Compat API, and should not be that bad to pry into Libpod. We should then be able to use that in the Follow function, as well as turning off polling for every consumer of the existing Wait code.

…

On Wed, May 12, 2021 at 12:07 Valentin Rothberg ***@***.***> wrote: As pointed out in https://github.com/containers/podman/pull/10222/files#diff-20cc30e1cdf302ef7404e5923eada3912c68c8b8943c0a7a0a834b29236eba69R92, using the Follow API is racy. In order to get it done correctly, *we* have to implement our custom follow function that forward everything from stdout and stderr UNTIL we read on the journal that the container died (i.e., get the died event). I looked at the journal and the died event is always printed *after* the logs are written. The problem at the moment is that we have to many things running concurrently. Having one goroutine reading the log and filtering out what's necessary until we read the died event seems one way to avoid that race. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#10323 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AB3AOCCUX7XY6TJVWPQ3WT3TNKRVJANCNFSM44Y4JX6Q> .

[vrothberg]

That is not enough to resolve the race unfortunately (tried that). The race is in reading the journal. Follow() may sleep when streaming which can cause the died event to be read before the last logs.

…

On Wed 12 May 2021 at 20:29, Matthew Heon ***@***.***> wrote: We should refactor the Wait code to use the logic where we wait for the Died event - it’s already implemented for the Compat API, and should not be that bad to pry into Libpod. We should then be able to use that in the Follow function, as well as turning off polling for every consumer of the existing Wait code. On Wed, May 12, 2021 at 12:07 Valentin Rothberg ***@***.***> wrote: > As pointed out in > https://github.com/containers/podman/pull/10222/files#diff-20cc30e1cdf302ef7404e5923eada3912c68c8b8943c0a7a0a834b29236eba69R92 , > using the Follow API is racy. In order to get it done correctly, *we* > have to implement our custom follow function that forward everything from > stdout and stderr UNTIL we read on the journal that the container died > (i.e., get the died event). > > I looked at the journal and the died event is always printed *after* the > logs are written. The problem at the moment is that we have to many things > running concurrently. Having one goroutine reading the log and filtering > out what's necessary until we read the died event seems one way to avoid > that race. > > — > You are receiving this because you are subscribed to this thread. > Reply to this email directly, view it on GitHub > < #10323 (comment)>, > or unsubscribe > < https://github.com/notifications/unsubscribe-auth/AB3AOCCUX7XY6TJVWPQ3WT3TNKRVJANCNFSM44Y4JX6Q > > . > — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#10323 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/ACZDRA5OUWH54IUZZHBF3O3TNLCHJANCNFSM44Y4JX6Q> .