Skip to content

nsexec.c: don't write logs that are to be discarded #3201

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.

Sign up for GitHub

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

Merged
kolyshkin merged 5 commits into from
Sep 13, 2021
Merged

nsexec.c: don't write logs that are to be discarded #3201

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
0a3577c
utils_linux: simplify newProcess
kolyshkin Jun 30, 2021
6c4a3b1
runc init: pass _LIBCONTAINER_LOGLEVEL as int
kolyshkin Jul 26, 2021
d2f49d4
libct/nsenter/nsexec.c: improve bail
kolyshkin Jul 28, 2021
d5ffe83
libct/nsenter/nsexec.c: factor out getenv_int
kolyshkin Jul 28, 2021
f1b703f
libct/nsenter/nsexec.c: honor _LIBCONTAINER_LOGLEVEL
kolyshkin Jul 28, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 0 additions & 6 deletions exec.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -132,11 +132,6 @@ func execProcess(context *cli.Context) (int, error) {
return -1, err
}

logLevel := "info"
if context.GlobalBool("debug") {
logLevel = "debug"
}

r := &runner{
enableSubreaper: false,
shouldDestroy: false,
Expand All @@ -147,7 +142,6 @@ func execProcess(context *cli.Context) (int, error) {
action: CT_ACT_RUN,
init: false,
preserveFDs: context.Int("preserve-fds"),
logLevel: logLevel,
}
return r.run(p)
}
Expand Down
4 changes: 2 additions & 2 deletions init.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,7 @@ func init() {
runtime.GOMAXPROCS(1)
runtime.LockOSThread()

logLevel, err := logrus.ParseLevel(os.Getenv("_LIBCONTAINER_LOGLEVEL"))
level, err := strconv.Atoi(os.Getenv("_LIBCONTAINER_LOGLEVEL"))
if err != nil {
panic(err)
}
Expand All @@ -27,7 +27,7 @@ func init() {
panic(err)
}

logrus.SetLevel(logLevel)
logrus.SetLevel(logrus.Level(level))
logrus.SetOutput(os.NewFile(uintptr(logPipeFd), "logpipe"))
logrus.SetFormatter(new(logrus.JSONFormatter))
logrus.Debug("child process in init()")
Expand Down
107 changes: 68 additions & 39 deletions libcontainer/nsenter/nsexec.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -89,14 +89,21 @@ struct nlconfig_t {
size_t gidmappath_len;
};

#define PANIC "panic"
#define FATAL "fatal"
#define ERROR "error"
#define WARNING "warning"
#define INFO "info"
#define DEBUG "debug"
/*
* Log levels are the same as in logrus.
*/
#define PANIC 0
#define FATAL 1
#define ERROR 2
#define WARNING 3
#define INFO 4
#define DEBUG 5
#define TRACE 6

static const char *level_str[] = { "panic", "fatal", "error", "warning", "info", "debug", "trace" };

static int logfd = -1;
static int loglevel = DEBUG;

/*
* List of netlink message types sent to us as part of bootstrapping the init.
Expand Down Expand Up @@ -134,13 +141,13 @@ int setns(int fd, int nstype)
}
#endif

static void write_log(const char *level, const char *format, ...)
static void write_log(int level, const char *format, ...)
{
char *message = NULL, *stage = NULL, *json = NULL;
va_list args;
int ret;

if (logfd < 0 || level == NULL)
if (logfd < 0 || level > loglevel)
goto out;

va_start(args, format);
Expand All @@ -162,7 +169,8 @@ static void write_log(const char *level, const char *format, ...)
goto out;
}

ret = asprintf(&json, "{\"level\":\"%s\", \"msg\": \"%s[%d]: %s\"}\n", level, stage, getpid(), message);
ret = asprintf(&json, "{\"level\":\"%s\", \"msg\": \"%s[%d]: %s\"}\n",
level_str[level], stage, getpid(), message);
if (ret < 0) {
json = NULL;
goto out;
Expand All @@ -182,10 +190,14 @@ static void write_log(const char *level, const char *format, ...)
/* XXX: This is ugly. */
static int syncfd = -1;

#define bail(fmt, ...) \
do { \
write_log(FATAL, fmt ": %m", ##__VA_ARGS__); \
exit(1); \
#define bail(fmt, ...) \
do { \
if (logfd < 0) \
fprintf(stderr, "FATAL: " fmt ": %m\n", \
##__VA_ARGS__); \
else \
write_log(FATAL, fmt ": %m", ##__VA_ARGS__); \
exit(1); \
} while(0)

static int write_file(char *data, size_t data_len, char *pathfmt, ...)
Expand Down Expand Up @@ -376,41 +388,55 @@ static int clone_parent(jmp_buf *env, int jmpval)
}

/*
* 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.
* Returns an environment variable value as a non-negative integer, or -ENOENT
* if the variable was not found or has an empty value.
*
* If the value can not be converted to an integer, or the result is out of
* range, the function bails out.
*/
static int initpipe(void)
static int getenv_int(const char *name)
{
int pipenum;
char *initpipe, *endptr;
char *val, *endptr;
int ret;

initpipe = getenv("_LIBCONTAINER_INITPIPE");
if (initpipe == NULL || *initpipe == '\0')
return -1;
val = getenv(name);
/* Treat empty value as unset variable. */
if (val == NULL || *val == '\0')
return -ENOENT;

pipenum = strtol(initpipe, &endptr, 10);
if (*endptr != '\0')
bail("unable to parse _LIBCONTAINER_INITPIPE");
ret = strtol(val, &endptr, 10);
if (val == endptr || *endptr != '\0')
bail("unable to parse %s=%s", name, val);
/*
* Sanity check: this must be a small non-negative number.
* Practically, we pass two fds (3 and 4) and a log level,
* for which the maximum is 6 (TRACE).
* */
if (ret < 0 || ret > TRACE)
bail("bad value for %s=%s (%d)", name, val, ret);

return pipenum;
return ret;
}

/*
* Sets up logging by getting log fd and log level from the environment,
* if available.
*/
static void setup_logpipe(void)
{
char *logpipe, *endptr;
int i;

logpipe = getenv("_LIBCONTAINER_LOGPIPE");
if (logpipe == NULL || *logpipe == '\0') {
i = getenv_int("_LIBCONTAINER_LOGPIPE");
if (i < 0) {
/* We are not runc init, or log pipe was not provided. */
return;
}
logfd = i;

logfd = strtol(logpipe, &endptr, 10);
if (logpipe == endptr || *endptr != '\0') {
fprintf(stderr, "unable to parse _LIBCONTAINER_LOGPIPE, value: %s\n", logpipe);
/* It is too early to use bail */
exit(1);
}
i = getenv_int("_LIBCONTAINER_LOGLEVEL");
if (i < 0)
return;
Comment on lines +437 to +438
Copy link
Member

@thaJeztah thaJeztah Sep 10, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we have a convention on wether or not to use curly braces for these? I realise it's common in C to omit them, but (e.g.) a couple of lines up we do use curly braces (given, in that case because of the comment).

Wondering if we need to have a convention (also as a safeguard), at least for "new" code.

Copy link
Contributor Author

@kolyshkin kolyshkin Sep 10, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good point.

In Go, obligatory curly braces (and, ultimately, gofmt) were introduced in order to minimize such discussions.

In C, curly braces are optional if the body has a single statement, which sometimes leads to bugs like this

zero();

if (val > max) /* Fixup val because something something */
	val = max;
	one();

two();

It's kinda hard to spot that one() is called unconditionally here (especially if the code is lengthier than in this example).

Fortunately, here we use indent (which is a poor man's gofmt for C), which will show a warning about wrong indentation in CI. It won't prevent a bug, but at least it will be obvious.

This is why I think both styles (with and without braces) are OK in here.

Copy link
Member

@thaJeztah thaJeztah Sep 10, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, I'm ok with this (especially because it's already for quite some code), just have to think about Apple's infamous "goto fail" security issue every time I see code without the curly braces 😂 https://www.imperialviolet.org/2014/02/22/applebug.html

Copy link
Contributor Author

@kolyshkin kolyshkin Sep 13, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wish we have some linter to take care of it (I mean real linter, not the indentation checker, although it seems to alleviate the issue so it is visible to the naked eye).

loglevel = i;
}

/* Returns the clone(2) flag for a namespace, given the name of a namespace. */
Expand Down Expand Up @@ -621,12 +647,15 @@ void nsexec(void)
setup_logpipe();

/*
* 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.
* Get the init pipe fd from the environment. The init pipe is used to
* read the bootstrap data and tell the parent what the new pids are
* after the setup is done.
*/
pipenum = initpipe();
if (pipenum == -1)
pipenum = getenv_int("_LIBCONTAINER_INITPIPE");
if (pipenum < 0) {
/* We are not a runc init. Just return to go runtime. */
return;
}

/*
* We need to re-exec if we are not in a cloned binary. This is necessary
Expand Down
16 changes: 5 additions & 11 deletions utils_linux.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -97,7 +97,7 @@ func getDefaultImagePath(context *cli.Context) string {

// newProcess returns a new libcontainer Process with the arguments from the
// spec and stdio from the current process.
func newProcess(p specs.Process, init bool, logLevel string) (*libcontainer.Process, error) {
func newProcess(p specs.Process) (*libcontainer.Process, error) {
lp := &libcontainer.Process{
Args: p.Args,
Env: p.Env,
Expand All @@ -107,8 +107,6 @@ func newProcess(p specs.Process, init bool, logLevel string) (*libcontainer.Proc
Label: p.SelinuxLabel,
NoNewPrivileges: &p.NoNewPrivileges,
AppArmorProfile: p.ApparmorProfile,
Init: init,
LogLevel: logLevel,
}

if p.ConsoleSize != nil {
Expand Down Expand Up @@ -257,7 +255,6 @@ type runner struct {
action CtAct
notifySocket *notifySocket
criuOpts *libcontainer.CriuOpts
logLevel string
}

func (r *runner) run(config *specs.Process) (int, error) {
Expand All @@ -270,10 +267,13 @@ func (r *runner) run(config *specs.Process) (int, error) {
if err = r.checkTerminal(config); err != nil {
return -1, err
}
process, err := newProcess(*config, r.init, r.logLevel)
process, err := newProcess(*config)
if err != nil {
return -1, err
}
process.LogLevel = strconv.Itoa(int(logrus.GetLevel()))
// Populate the fields that come from runner.
process.Init = r.init
if len(r.listenFDs) > 0 {
process.Env = append(process.Env, "LISTEN_FDS="+strconv.Itoa(len(r.listenFDs)), "LISTEN_PID=1")
process.ExtraFiles = append(process.ExtraFiles, r.listenFDs...)
Expand Down Expand Up @@ -430,11 +430,6 @@ func startContainer(context *cli.Context, spec *specs.Spec, action CtAct, criuOp
listenFDs = activation.Files(false)
}

logLevel := "info"
if context.GlobalBool("debug") {
logLevel = "debug"
}

r := &runner{
enableSubreaper: !context.Bool("no-subreaper"),
shouldDestroy: !context.Bool("keep"),
Expand All @@ -448,7 +443,6 @@ func startContainer(context *cli.Context, spec *specs.Spec, action CtAct, criuOp
action: action,
criuOpts: criuOpts,
init: true,
logLevel: logLevel,
}
return r.run(spec.Process)
}