From a5320ae3e71ce20261f4656715c5da95ffe4d719 Mon Sep 17 00:00:00 2001 From: Sascha Grunert Date: Thu, 5 Sep 2024 10:38:17 +0200 Subject: [PATCH] Add debug logs for container creation Signed-off-by: Sascha Grunert --- src/create.c | 1 + src/libcrun/container.c | 43 ++++++++++++++++++++++++++++++++++++++--- src/libcrun/linux.c | 22 ++++++++++++++++++++- src/libcrun/status.c | 2 ++ src/libcrun/utils.c | 2 ++ 5 files changed, 66 insertions(+), 4 deletions(-) diff --git a/src/create.c b/src/create.c index e9c2ce46e..a5699894d 100644 --- a/src/create.c +++ b/src/create.c @@ -162,6 +162,7 @@ crun_command_create (struct crun_global_arguments *global_args, int argc, char * if (container == NULL) libcrun_fail_with_error (0, "error loading config.json"); + libcrun_debug ("Using bundle: %s", bundle); crun_context.bundle = bundle; if (getenv ("LISTEN_FDS")) { diff --git a/src/libcrun/container.c b/src/libcrun/container.c index be3c28214..5068e8e81 100644 --- a/src/libcrun/container.c +++ b/src/libcrun/container.c @@ -598,6 +598,7 @@ libcrun_container_load_from_file (const char *path, libcrun_error_t *err) { runtime_spec_schema_config_schema *container_def; cleanup_free char *oci_error = NULL; + libcrun_debug ("Loading container from config file: %s", path); container_def = runtime_spec_schema_config_schema_parse_file (path, NULL, &oci_error); if (container_def == NULL) { @@ -1382,9 +1383,11 @@ open_hooks_output (libcrun_container_t *container, int *out_fd, int *err_fd, lib *err_fd = *out_fd = -1; + libcrun_debug ("Opening hooks output"); annotation = find_annotation (container, "run.oci.hooks.stdout"); if (annotation) { + libcrun_debug ("Found run.oci.hooks.stdout annotation"); *out_fd = TEMP_FAILURE_RETRY (open (annotation, O_CREAT | O_WRONLY | O_APPEND | O_CLOEXEC, 0700)); if (UNLIKELY (*out_fd < 0)) return crun_make_error (err, errno, "open `%s`", annotation); @@ -1393,6 +1396,7 @@ open_hooks_output (libcrun_container_t *container, int *out_fd, int *err_fd, lib annotation = find_annotation (container, "run.oci.hooks.stderr"); if (annotation) { + libcrun_debug ("Found run.oci.hooks.stderr annotation"); *err_fd = TEMP_FAILURE_RETRY (open (annotation, O_CREAT | O_WRONLY | O_APPEND | O_CLOEXEC, 0700)); if (UNLIKELY (*err_fd < 0)) return crun_make_error (err, errno, "open `%s`", annotation); @@ -2402,6 +2406,7 @@ libcrun_container_run_internal (libcrun_container_t *container, libcrun_context_ if (! detach || context->notify_socket) { + libcrun_debug ("Setting child subreaper"); ret = prctl (PR_SET_CHILD_SUBREAPER, 1, 0, 0, 0); if (UNLIKELY (ret < 0)) return crun_make_error (err, errno, "set child subreaper"); @@ -2411,8 +2416,14 @@ libcrun_container_run_internal (libcrun_container_t *container, libcrun_context_ { const char *label = NULL; + libcrun_debug ("Creating new keyring"); + if (def->process) - label = def->process->selinux_label; + { + label = def->process->selinux_label; + if (label) + libcrun_debug ("Using SELinux process label: %s", label); + } ret = libcrun_create_keyring (container->context->id, label, err); if (UNLIKELY (ret < 0)) @@ -2421,6 +2432,7 @@ libcrun_container_run_internal (libcrun_container_t *container, libcrun_context_ if (def->process && def->process->terminal && ! detach && context->console_socket == NULL) { + libcrun_debug ("Creating terminal socket pair"); container_args.has_terminal_socket_pair = 1; ret = create_socket_pair (container_args.terminal_socketpair, err); if (UNLIKELY (ret < 0)) @@ -2441,6 +2453,7 @@ libcrun_container_run_internal (libcrun_container_t *container, libcrun_context_ unsigned int seccomp_gen_options = 0; const char *annotation; + libcrun_debug ("Initializing seccomp"); annotation = find_annotation (container, "run.oci.seccomp_fail_unknown_syscall"); if (annotation && strcmp (annotation, "0") != 0) seccomp_gen_options = LIBCRUN_SECCOMP_FAIL_UNKNOWN_SYSCALL; @@ -2474,13 +2487,22 @@ libcrun_container_run_internal (libcrun_container_t *container, libcrun_context_ cgroup_manager = CGROUP_MANAGER_CGROUPFS; if (context->systemd_cgroup) - cgroup_manager = CGROUP_MANAGER_SYSTEMD; + { + libcrun_debug ("Using systemd cgroup manager"); + cgroup_manager = CGROUP_MANAGER_SYSTEMD; + } else if (context->force_no_cgroup) - cgroup_manager = CGROUP_MANAGER_DISABLED; + { + libcrun_debug ("Disabling cgroup manager"); + cgroup_manager = CGROUP_MANAGER_DISABLED; + } + else + libcrun_debug ("Using cgroupfs cgroup manager"); /* If we are root (either on the host or in a namespace), then chown the cgroup to root in the container user namespace. */ get_root_in_the_userns (def, container->host_uid, container->host_gid, &root_uid, &root_gid); + libcrun_debug ("Using container host UID %d and GID %d", container->host_uid, container->host_gid); memset (&cg, 0, sizeof (cg)); @@ -2509,6 +2531,7 @@ libcrun_container_run_internal (libcrun_container_t *container, libcrun_context_ if (container_args.custom_handler && container_args.custom_handler->vtable->modify_oci_configuration) { + libcrun_debug ("Using custom handler to modify OCI configuration"); ret = container_args.custom_handler->vtable->modify_oci_configuration (container_args.custom_handler->cookie, container_args.context, container->container_def, @@ -2523,9 +2546,11 @@ libcrun_container_run_internal (libcrun_container_t *container, libcrun_context_ cg.pid = pid; cg.joined = cgroup_dirfd_s.joined; + libcrun_debug ("Running container on PID: %d", pid); if (context->fifo_exec_wait_fd < 0 && context->notify_socket) { + libcrun_debug ("Using notify socket: %s", context->notify_socket); /* Do not open the notify socket here on "create". "start" will take care of it. */ ret = get_notify_fd (context, container, ¬ify_socket, err); if (UNLIKELY (ret < 0)) @@ -2589,6 +2614,7 @@ libcrun_container_run_internal (libcrun_container_t *container, libcrun_context_ prestart hooks. */ if (def->hooks && def->hooks->prestart_len) { + libcrun_debug ("Running 'prestart' hooks"); ret = do_hooks (def, pid, context->id, false, NULL, "created", (hook **) def->hooks->prestart, def->hooks->prestart_len, hooks_out_fd, hooks_err_fd, err); if (UNLIKELY (ret != 0)) @@ -2596,6 +2622,7 @@ libcrun_container_run_internal (libcrun_container_t *container, libcrun_context_ } if (def->hooks && def->hooks->create_runtime_len) { + libcrun_debug ("Running 'create' hooks"); ret = do_hooks (def, pid, context->id, false, NULL, "created", (hook **) def->hooks->create_runtime, def->hooks->create_runtime_len, hooks_out_fd, hooks_err_fd, err); if (UNLIKELY (ret != 0)) @@ -2626,6 +2653,7 @@ libcrun_container_run_internal (libcrun_container_t *container, libcrun_context_ if (def->process && def->process->terminal && ! detach && context->console_socket == NULL) { + libcrun_debug ("Receiving console socket fd"); terminal_fd = receive_fd_from_socket (socket_pair_0, err); if (UNLIKELY (terminal_fd < 0)) goto fail; @@ -2646,6 +2674,7 @@ libcrun_container_run_internal (libcrun_container_t *container, libcrun_context_ if (UNLIKELY (ret < 0)) goto fail; + libcrun_debug ("Writing container status"); ret = write_container_status (container, context, pid, cgroup_status, err); if (UNLIKELY (ret < 0)) goto fail; @@ -2654,6 +2683,7 @@ libcrun_container_run_internal (libcrun_container_t *container, libcrun_context_ hooks will be executed as part of the start command. */ if (context->fifo_exec_wait_fd < 0 && def->hooks && def->hooks->poststart_len) { + libcrun_debug ("Running 'poststart' hooks"); ret = do_hooks (def, pid, context->id, true, NULL, "running", (hook **) def->hooks->poststart, def->hooks->poststart_len, hooks_out_fd, hooks_err_fd, err); if (UNLIKELY (ret < 0)) @@ -2663,6 +2693,7 @@ libcrun_container_run_internal (libcrun_container_t *container, libcrun_context_ /* Let's receive the seccomp notify fd and handle it as part of wait_for_process(). */ if (own_seccomp_receiver_fd >= 0) { + libcrun_debug ("Receiving seccomp fd"); seccomp_notify_fd = receive_fd_from_socket (own_seccomp_receiver_fd, err); if (UNLIKELY (seccomp_notify_fd < 0)) goto fail; @@ -2742,16 +2773,19 @@ libcrun_copy_config_file (const char *id, const char *state_root, libcrun_contai if (container->config_file == NULL) { + libcrun_debug ("Writing config file to: %s", dest_path); ret = write_file (dest_path, container->config_file_content, strlen (container->config_file_content), err); if (UNLIKELY (ret < 0)) return ret; } else { + libcrun_debug ("Reading config file: %s", container->config_file); ret = read_all_file (container->config_file, &buffer, &len, err); if (UNLIKELY (ret < 0)) return ret; + libcrun_debug ("Writing config file to: %s", dest_path); ret = write_file (dest_path, buffer, len, err); if (UNLIKELY (ret < 0)) return ret; @@ -2891,6 +2925,7 @@ libcrun_container_create (libcrun_context_t *context, libcrun_container_t *conta cleanup_close int exec_fifo_fd = -1; context->detach = 1; + libcrun_debug ("Creating container: %s", context->id); container->context = context; ret = validate_options (options, LIBCRUN_CREATE_OPTIONS_PREFORK, err); @@ -2917,6 +2952,7 @@ libcrun_container_create (libcrun_context_t *context, libcrun_container_t *conta if ((options & LIBCRUN_RUN_OPTIONS_PREFORK) == 0) { + libcrun_debug ("Running with prefork enabled"); ret = libcrun_copy_config_file (context->id, context->state_root, container, err); if (UNLIKELY (ret < 0)) return ret; @@ -2949,6 +2985,7 @@ libcrun_container_create (libcrun_context_t *context, libcrun_container_t *conta { if (exit_code != 0) { + libcrun_debug ("Exit code is %d, deleting container", exit_code); libcrun_error_t tmp_err = NULL; libcrun_container_delete (context, def, context->id, true, &tmp_err); crun_error_release (&tmp_err); diff --git a/src/libcrun/linux.c b/src/libcrun/linux.c index e4e81f2e0..e2db6ebd5 100644 --- a/src/libcrun/linux.c +++ b/src/libcrun/linux.c @@ -3327,6 +3327,9 @@ libcrun_set_rlimits (runtime_spec_schema_config_schema_process_rlimits_element * return crun_make_error (err, 0, "invalid rlimit `%s`", type); limit.rlim_cur = new_rlimits[i]->soft; limit.rlim_max = new_rlimits[i]->hard; + libcrun_debug ("Set rlimit: soft = %llu, hard = %llu", + (unsigned long long) limit.rlim_cur, + (unsigned long long) limit.rlim_max); if (UNLIKELY (setrlimit (resource, &limit) < 0)) return crun_make_error (err, errno, "setrlimit `%s`", type); } @@ -3374,6 +3377,7 @@ libcrun_set_oom (libcrun_container_t *container, libcrun_error_t *err) char oom_buffer[16]; if (def->process == NULL || ! def->process->oom_score_adj_present) return 0; + libcrun_debug ("Write OOM score adj: %d", def->process->oom_score_adj); sprintf (oom_buffer, "%i", def->process->oom_score_adj); fd = open ("/proc/self/oom_score_adj", O_RDWR | O_CLOEXEC); if (fd < 0) @@ -3805,6 +3809,7 @@ join_namespaces (runtime_spec_schema_config_schema *def, int *namespaces_to_join return crun_make_error (err, errno, "cannot get current working directory"); } + libcrun_debug ("Joining %s namespace: %s", def->linux->namespaces[orig_index]->type, def->linux->namespaces[orig_index]->path); ret = setns (namespaces_to_join[i], value); if (UNLIKELY (ret < 0)) { @@ -3907,11 +3912,16 @@ configure_init_status (struct init_status_s *ns, libcrun_container_t *container, ns->all_namespaces |= value; if (def->linux->namespaces[i]->path == NULL) - ns->namespaces_to_unshare |= value; + { + libcrun_debug ("Unsharing namespace: %s", def->linux->namespaces[i]->type); + ns->namespaces_to_unshare |= value; + } else { int fd; + libcrun_debug ("Joining %s namespace: %s", def->linux->namespaces[i]->type, def->linux->namespaces[i]->path); + if (ns->fd_len >= MAX_NAMESPACES) return crun_make_error (err, 0, "too many namespaces to join"); @@ -4446,6 +4456,8 @@ set_id_init (libcrun_container_t *container, libcrun_error_t *err) root_mapped = root_mapped_in_container_p (def->linux->uid_mappings, def->linux->uid_mappings_len); if (! root_mapped) uid = def->process->user->uid; + + libcrun_debug ("Using mapped UID in container: %d", uid); } if (def->linux->gid_mappings_len != 0) @@ -4453,6 +4465,8 @@ set_id_init (libcrun_container_t *container, libcrun_error_t *err) root_mapped = root_mapped_in_container_p (def->linux->gid_mappings, def->linux->gid_mappings_len); if (! root_mapped) gid = def->process->user->gid; + + libcrun_debug ("Using mapped GID in container: %d", gid); } } @@ -4567,6 +4581,7 @@ init_container (libcrun_container_t *container, int sync_socket_container, struc { if (init_status->delayed_userns_create) { + libcrun_debug ("Unsharing user namespace"); ret = unshare (CLONE_NEWUSER); if (UNLIKELY (ret < 0)) return crun_make_error (err, errno, "unshare (CLONE_NEWUSER)"); @@ -4587,6 +4602,7 @@ init_container (libcrun_container_t *container, int sync_socket_container, struc else { /* If we need to join another user namespace, do it immediately before creating any other namespace. */ + libcrun_debug ("Joining existing user namespace"); ret = setns (init_status->fd[init_status->userns_index], CLONE_NEWUSER); if (UNLIKELY (ret < 0)) return crun_make_error (err, errno, "cannot setns `%s`", @@ -4622,12 +4638,14 @@ init_container (libcrun_container_t *container, int sync_socket_container, struc if (def->linux->time_offsets->boottime) { sprintf (fmt_buffer, "boottime %" PRIi64 " %" PRIu32, def->linux->time_offsets->boottime->secs, def->linux->time_offsets->boottime->nanosecs); + libcrun_debug ("Using boot time offset: secs = %lld, nanosecs = %d", (long long int) def->linux->time_offsets->boottime->secs, def->linux->time_offsets->boottime->nanosecs); ret = write (fd, fmt_buffer, strlen (fmt_buffer)); if (UNLIKELY (ret < 0)) return crun_make_error (err, errno, "write `%s`", timens_offsets_file); } if (def->linux->time_offsets->monotonic) { + libcrun_debug ("Using monotonic time offset: secs = %lld, nanosecs = %d", (long long int) def->linux->time_offsets->monotonic->secs, def->linux->time_offsets->monotonic->nanosecs); sprintf (fmt_buffer, "monotonic %" PRIi64 " %" PRIu32, def->linux->time_offsets->monotonic->secs, def->linux->time_offsets->monotonic->nanosecs); ret = write (fd, fmt_buffer, strlen (fmt_buffer)); if (UNLIKELY (ret < 0)) @@ -4649,6 +4667,7 @@ init_container (libcrun_container_t *container, int sync_socket_container, struc /* Report back the new PID. */ if (pid_container) { + libcrun_debug ("Running container PID after fork: %d", pid_container); ret = send_success_to_sync_socket (sync_socket_container, err); if (UNLIKELY (ret < 0)) return ret; @@ -4723,6 +4742,7 @@ libcrun_run_linux_container (libcrun_container_t *container, container_entrypoin size_t i; int ret; + libcrun_debug ("Running linux container"); ret = configure_init_status (&init_status, container, err); if (UNLIKELY (ret < 0)) return ret; diff --git a/src/libcrun/status.c b/src/libcrun/status.c index 5020066c2..47d913b06 100644 --- a/src/libcrun/status.c +++ b/src/libcrun/status.c @@ -441,6 +441,7 @@ libcrun_status_check_directories (const char *state_root, const char *id, libcru cleanup_free char *run_directory = get_run_directory (state_root); int ret; + libcrun_debug ("Checking run directory: %s", run_directory); ret = crun_ensure_directory (run_directory, 0700, false, err); if (UNLIKELY (ret < 0)) return ret; @@ -684,6 +685,7 @@ libcrun_status_create_exec_fifo (const char *state_root, const char *id, libcrun if (UNLIKELY (ret < 0)) return ret; + libcrun_debug ("Creating exec fifo: %s", fifo_path); ret = mkfifo (fifo_path, 0600); if (UNLIKELY (ret < 0)) return crun_make_error (err, errno, "mkfifo"); diff --git a/src/libcrun/utils.c b/src/libcrun/utils.c index 4dbc7f68e..0669f47bd 100644 --- a/src/libcrun/utils.c +++ b/src/libcrun/utils.c @@ -1055,6 +1055,8 @@ open_unix_domain_client_socket (const char *path, int dgram, libcrun_error_t *er cleanup_close int destfd = -1; cleanup_close int fd = -1; + libcrun_debug ("Opening UNIX domain socket: %s", path); + fd = socket (AF_UNIX, dgram ? SOCK_DGRAM : SOCK_STREAM, 0); if (UNLIKELY (fd < 0)) return crun_make_error (err, errno, "error creating UNIX socket");