nsexec logging race

[kolyshkin]

As reported in https://kubernetes.slack.com/archives/CAZH62UR1/p1627584431224800

[20:46] nb3:apps% kubectl logs nextcloud-nextcloud-846d6bbcf-9mmp8 nextcloud
time="2021-07-29T20:45:35+02:00" level=error msg="failed to decode \"{\\\"level\\\":\\\"debug\\\", \\\"msg\\\": \\\"nsexec-0[7972]: forward stage-1 (7973) and stage-2 (7974) pids to runc{\\\"level\\\":\\\"debug\\\", \\\"msg\\\": \\\"nsexec-1[7973]: signal completion to stage-0\\\"}\" to json: invalid character 'l' after object key:value pair"
time="2021-07-29T20:45:35+02:00" level=error msg="failed to decode \"\\\"}\" to json: unexpected end of JSON input"
Initializing nextcloud 20.0.11.1 ...
Initializing finished
New nextcloud instance
[29-Jul-2021 18:45:40] NOTICE: fpm is running, pid 1
[29-Jul-2021 18:45:40] NOTICE: ready to handle connections

What we see here is runc failed to decode JSON log message from runc init's nsexec.c. The messages are:

{"level":"debug", "msg": "nsexec-0[7972]: forward stage-1 (7973) and stage-2 (7974) pids to runc{"level":"debug", "msg": "nsexec-1[7973]: signal completion to stage-0"}
}

Looks like the code hit a jackpot of a debug log race between the parent at

runc/libcontainer/nsenter/nsexec.c

Lines 820 to 821 in d962bb0

	write_log(DEBUG, "forward stage-1 (%d) and stage-2 (%d) pids to runc",
	stage1_pid, stage2_pid);

and the first child at

runc/libcontainer/nsenter/nsexec.c

Line 1021 in d962bb0

write_log(DEBUG, "signal completion to stage-0");

Cc @cyphar

[kolyshkin]

As the production rarely uses debug, in practice this is fixed by b1bc762

[kolyshkin]

Another possible solution is something like this

diff --git a/libcontainer/nsenter/nsexec.c b/libcontainer/nsenter/nsexec.c
index 8199faf3..0c9eca00 100644
--- a/libcontainer/nsenter/nsexec.c
+++ b/libcontainer/nsenter/nsexec.c
@@ -142,7 +142,7 @@ int setns(int fd, int nstype)
 
 static void write_log(const char *level, const char *format, ...)
 {
-       char *message = NULL, *stage = NULL;
+       char *message = NULL, *stage = NULL, *json = NULL;
        va_list args;
        int ret;
 
@@ -164,11 +164,16 @@ static void write_log(const char *level, const char *format, ...)
        if (ret < 0)
                goto out;
 
-       dprintf(logfd, "{\"level\":\"%s\", \"msg\": \"%s[%d]: %s\"}\n", level, stage, getpid(), message);
+       ret = asprintf(&json, "{\"level\":\"%s\", \"msg\": \"%s[%d]: %s\"}\n", level, stage, getpid(), message);
+       if (ret < 0)
+               goto out;
+
+       write(logfd, json, ret);
 
 out:
        free(message);
        free(stage);
+       free(json);
 }
 
 /* XXX: This is ugly. */

[kolyshkin]

Fixed in https://github.com/opencontainers/runc/releases/tag/v1.0.2