Improve nsexec logging #2487

It does not make sense to have a string for a numeric type. Signed-off-by: Kir Kolyshkin <[email protected]>

1. Remove redundant "echo $output" from the first test case, as "runc" helper function already logs the output. 2. Show the contents of log.out to stderr, so it case of error we can see what is going on. 3. Remove the check that `log.out` file exists. This check is redundant, since right after it we do `cat log.out` and check its exit code. 4. Factor out common checks into check_debug. Signed-off-by: Kir Kolyshkin <[email protected]>

Error handling is slightly cleaner this way. While at it, do minor refactoring and fix error logging in processEntry. Signed-off-by: Kir Kolyshkin <[email protected]>

This fixes a big red warning in my vim. Signed-off-by: Kir Kolyshkin <[email protected]>

I have noticed that ConfigureLogs do not return an error in case logging was already configured -- instead it just warns about it. So I went ahead and changed the warning to the actual error... ... only to discover I broke things badly, because in case of runc init logging is configured twice. The fix is to not configure logging in case we are init. Signed-off-by: Kir Kolyshkin <[email protected]>

Sometimes debug.bats test cases are failing like this: > not ok 27 global --debug to --log --log-format 'json' > # (in test file tests/integration/debug.bats, line 77) > # `[[ "${output}" == *"child process in init()"* ]]' failed It happens more when writing to disk. This issue is caused by the fact that runc spawns log forwarding goroutine (ForwardLogs) but does not wait for it to finish, resulting in missing debug lines from nsexec. ForwardLogs itself, though, never finishes, because it reads from a reading side of a pipe which writing side is not closed. This is especially true in case of runc create, which spawns runc init and exits; meanwhile runc init waits on exec fifo for some undetermined long time before doing execve. So, to fix the failure described above, we need to: 1. Make runc create/run/exec wait for ForwardLogs to finish; 2. Make runc init close its log pipe file descriptor (i.e. the one which value is passed in _LIBCONTAINER_LOGPIPE environment variable). This is exactly what this commit does. In addition, it - adds logrus debug to late stages of runc init, and amends the integration tests to check for those messages; - adds runc --debug exec test cases, similar to those in debug.bats but for runc exec eather than runc run; - refactors libcotainer/logs unit tests to simplify and update for the new ForwardLogs. PS I have to admit I still do not understand why closing log pipe fd is required in e.g. (*linuxSetnsInit).Init, right before the execve which (thanks to CLOEXEC) closes the fd anyway. Signed-off-by: Kir Kolyshkin <[email protected]>

@kolyshkin

In order to make 'runc --debug' actually useful for debugging nsexec bugs, provide information about all the internal operations when in debug mode. [@kolyshkin: auto-fix formatting using indent for make validate to pass] Signed-off-by: Aleksa Sarai <[email protected]> Signed-off-by: Kir Kolyshkin <[email protected]>

Some strings logged by write_log() contain \n, which leads to errors like this one: > # time="2020-06-07T15:41:37Z" level=error msg="failed to decode \"{\\\"level\\\":\\\"debug\\\", \\\"msg\\\": \\\"nsexec-0[2265]: update /proc/2266/uid_map to '0 1000 1\\n\" to json: invalid character '\\n' in string literal" The fix is to escape such characters. Signed-off-by: Kir Kolyshkin <[email protected]>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve nsexec logging #2487

Improve nsexec logging #2487

Commits on Mar 6, 2021