Add dlogf facility for nsexec logging

exec.go

@@ -93,6 +93,10 @@ following will output a list of processes running in the container:
 			Name:  "preserve-fds",
 			Usage: "Pass N additional file descriptors to the container (stdio + $LISTEN_FDS + N in total)",
 		},
+		cli.StringFlag{
+			Name:  "exec-log",
+			Usage: "exec log file",
+		},
 	},
 	Action: func(context *cli.Context) error {
 		if err := checkArgs(context, 1, minArgs); err != nil {
@@ -143,6 +147,7 @@ func execProcess(context *cli.Context) (int, error) {
 		consoleSocket:   context.String("console-socket"),
 		detach:          detach,
 		pidFile:         context.String("pid-file"),
+		execLog:         context.String("exec-log"),
 		action:          CT_ACT_RUN,
 		init:            false,
 		preserveFDs:     context.Int("preserve-fds"),

libcontainer/container_linux.go

@@ -479,11 +479,17 @@ func (c *linuxContainer) commandTemplate(p *Process, childPipe *os.File) (*exec.
 			fmt.Sprintf("_LIBCONTAINER_CONSOLE=%d", stdioFdCount+len(cmd.ExtraFiles)-1),
 		)
 	}
+
 	cmd.ExtraFiles = append(cmd.ExtraFiles, childPipe)
 	cmd.Env = append(cmd.Env,
 		fmt.Sprintf("_LIBCONTAINER_INITPIPE=%d", stdioFdCount+len(cmd.ExtraFiles)-1),
 		fmt.Sprintf("_LIBCONTAINER_STATEDIR=%s", c.root),
 	)
+
+	if execLogEnv := getExecLogEnv(p.Env); execLogEnv != "" {
+		cmd.Env = append(cmd.Env, execLogEnv)
+	}
+
 	// NOTE: when running a container with no PID namespace and the parent process spawning the container is
 	// PID1 the pdeathsig is being delivered to the container's init process by the kernel for some reason
 	// even with the parent still running.
@@ -522,6 +528,15 @@ func (c *linuxContainer) newInitProcess(p *Process, cmd *exec.Cmd, parentPipe, c
 	return init, nil
 }
 
+func getExecLogEnv(env []string) string {
+	for _, entry := range env {
+		if strings.HasPrefix(entry, "_LIBCONTAINER_EXECLOG=") {
+			return entry
+		}
+	}
+	return ""
+}
+
 func (c *linuxContainer) newSetnsProcess(p *Process, cmd *exec.Cmd, parentPipe, childPipe *os.File) (*setnsProcess, error) {
 	cmd.Env = append(cmd.Env, "_LIBCONTAINER_INITTYPE="+string(initSetns))
 	state, err := c.currentState()

libcontainer/nsenter/nsexec.c

@@ -14,11 +14,13 @@
 #include <stdlib.h>
 #include <stdbool.h>
 #include <string.h>
+#include <time.h>
 #include <unistd.h>
 
 #include <sys/ioctl.h>
 #include <sys/prctl.h>
 #include <sys/socket.h>
+#include <sys/timeb.h>
 #include <sys/types.h>
 #include <sys/wait.h>
 
@@ -110,6 +112,9 @@ struct nlconfig_t {
 #define UIDMAPPATH_ATTR	    27288
 #define GIDMAPPATH_ATTR	    27289
 
+#define MAX_TIMESTAMP_LEN 32
+#define MAX_LOG_MESSAGE_LEN 256
+
 /*
  * Use the raw syscall for versions of glibc which don't include a function for
  * it, namely (glibc 2.12).
@@ -331,25 +336,21 @@ static int clone_parent(jmp_buf *env, int jmpval)
 	return clone(child_func, ca.stack_ptr, CLONE_PARENT | SIGCHLD, &ca);
 }
 
-/*
- * Gets the init pipe fd from the environment, which is used to read the
- * bootstrap data and tell the parent what the new pid is after we finish
- * setting up the environment.
- */
-static int initpipe(void)
+/* Get the fd from given envrionment variable. */
+static int getfd(char *envfd)
 {
-	int pipenum;
-	char *initpipe, *endptr;
+	int fdnum;
+	char *fd, *endptr;
 
-	initpipe = getenv("_LIBCONTAINER_INITPIPE");
-	if (initpipe == NULL || *initpipe == '\0')
+	fd = getenv(envfd);
+	if (fd == NULL || *fd == '\0')
 		return -1;
 
-	pipenum = strtol(initpipe, &endptr, 10);
+	fdnum = strtol(fd, &endptr, 10);
 	if (*endptr != '\0')
-		bail("unable to parse _LIBCONTAINER_INITPIPE");
+		bail("unable to parse %s", envfd);
 
-	return pipenum;
+	return fdnum;
 }
 
 /* Returns the clone(2) flag for a namespace, given the name of a namespace. */
@@ -537,21 +538,74 @@ void join_namespaces(char *nslist)
 /* Defined in cloned_binary.c. */
 extern int ensure_cloned_binary(void);
 
+static int nowformatted(char *buf)
+{
+        struct timeb now;
+
+        if (ftime(&now) < 0) return 1;
+
+        if (strftime(buf, MAX_TIMESTAMP_LEN, "%Y-%m-%d-%H:%M:%S", localtime(&now.time)) == 0) return 1;
+        if (sprintf(&buf[strlen(buf)], ":%03u", now.millitm) == 0) return 1;
+
+        return 0;
+}
+
+/* Write a timestamp prefixed message into fd */
+static void dlog(int fd, const char *message)
+{
+	/* Logging is best effort, a failure to log shouldn't impact other
+	 * operations so we just abort the logging attempt if we fail for any
+	 * reason. */
+
+        char timestamp[MAX_TIMESTAMP_LEN], logline[MAX_LOG_MESSAGE_LEN];
+
+	/* There are two reasons for this to fail: either the attempt to open
+	 * the log fd failed or the log fd wasn't set. Either way the outcome
+	 * is the same - we won't or can't log. */
+        if (fd < 0) return;
+
+        if (nowformatted(timestamp) != 0) return;
+        if (snprintf(logline, MAX_LOG_MESSAGE_LEN, "[%s] %s\n", timestamp, message) == 0) return;
+	(void) write(fd, logline, strlen(logline));
+}
+
+static void dlogf(int fd, const char *fmt, ...)
+{
+        va_list argp;
+        char message[MAX_LOG_MESSAGE_LEN];
+
+        if (fd < 0) return;
+
+        va_start(argp, fmt);
+        vsnprintf(message, MAX_LOG_MESSAGE_LEN, fmt, argp);
+        va_end(argp);
+
+        dlog(fd, message);
+}
+
 void nsexec(void)
 {
-	int pipenum;
+	int pipenum, logfd;
 	jmp_buf env;
 	int sync_child_pipe[2], sync_grandchild_pipe[2];
 	struct nlconfig_t config = { 0 };
 
 	/*
-	 * If we don't have an init pipe, just return to the go routine.
-	 * We'll only get an init pipe for start or exec.
+	 * Gets the init pipe fd from the environment, which is used to read the
+	 * bootstrap data and tell the parent what the new pid is after we finish
+	 * setting up the environment. If we don't have an init pipe, just
+	 * return to the go routine. We'll only get an init pipe for start or
+	 * exec.
 	 */
-	pipenum = initpipe();
+	pipenum = getfd("_LIBCONTAINER_INITPIPE");
 	if (pipenum == -1)
 		return;
 
+	logfd = getfd("_LIBCONTAINER_EXECLOG");
+
+	/* TODO: this is a showcase, remove it */
+	dlogf(logfd, "Hi from nsexec! Pid is: %ld", getpid());
+
 	/*
 	 * We need to re-exec if we are not in a cloned binary. This is necessary
 	 * to ensure that containers won't be able to access the host binary

run.go

@@ -61,6 +61,10 @@ command(s) that get executed on start, edit the args parameter of the spec. See
 			Name:  "preserve-fds",
 			Usage: "Pass N additional file descriptors to the container (stdio + $LISTEN_FDS + N in total)",
 		},
+		cli.StringFlag{
+			Name:  "exec-log",
+			Usage: "exec log file",
+		},
 	},
 	Action: func(context *cli.Context) error {
 		if err := checkArgs(context, 1, exactArgs); err != nil {

utils_linux.go

@@ -258,6 +258,7 @@ type runner struct {
 	listenFDs       []*os.File
 	preserveFDs     int
 	pidFile         string
+	execLog         string
 	consoleSocket   string
 	container       libcontainer.Container
 	action          CtAct
@@ -279,6 +280,16 @@ func (r *runner) run(config *specs.Process) (int, error) {
 		process.Env = append(process.Env, fmt.Sprintf("LISTEN_FDS=%d", len(r.listenFDs)), "LISTEN_PID=1")
 		process.ExtraFiles = append(process.ExtraFiles, r.listenFDs...)
 	}
+	if r.execLog != "" {
+		execLogFile, err := os.OpenFile(r.execLog, os.O_CREATE|os.O_WRONLY, 0755)
+		if err != nil {
+			return -1, err
+		}
+		defer execLogFile.Close()
+
+		process.Env = append(process.Env, fmt.Sprintf("_LIBCONTAINER_EXECLOG=%d", 3+len(r.listenFDs)))
+		process.ExtraFiles = append(process.ExtraFiles, execLogFile)
+	}
 	baseFd := 3 + len(process.ExtraFiles)
 	for i := baseFd; i < baseFd+r.preserveFDs; i++ {
 		_, err := os.Stat(fmt.Sprintf("/proc/self/fd/%d", i))
@@ -439,6 +450,7 @@ func startContainer(context *cli.Context, spec *specs.Spec, action CtAct, criuOp
 		action:          action,
 		criuOpts:        criuOpts,
 		init:            true,
+		execLog:         context.String("exec-log"),
 	}
 	return r.run(spec.Process)
 }