Add debug logs for container creation

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"))
     {

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, &notify_socket, err);
       if (UNLIKELY (ret < 0))
@@ -2589,13 +2614,15 @@ 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))
         goto fail;
     }
   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);

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,13 +4456,17 @@ 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)
         {
           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;

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");

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");