centos-sig-hyperscale / systemd

Clone
Source Code
GIT

#8 logind: add debug messages to session creation logic
Merged a year ago by daandemeyer. Opened a year ago by naccyde.
centos-sig-hyperscale/ naccyde/systemd systemd-logind-verbose  into  hs+fb-v255.4

file modified
+101 -51 
@@ -710,119 +710,147 @@ 
 

  

          assert(message);
 

  

-         if (!uid_is_valid(uid))
 

+         if (!uid_is_valid(uid)) {
 

+                 log_debug("create_session: UID is not valid");
 

                  return sd_bus_error_set(error, SD_BUS_ERROR_INVALID_ARGS, "Invalid UID");
 

+         }
 

  

-         if (flags != 0)
 

+         if (flags != 0) {
 

+                 log_debug("create_session: flag shouldn't be set");
 

                  return sd_bus_error_set(error, SD_BUS_ERROR_INVALID_ARGS, "Flags must be zero.");
 

+         }
 

  

          if (pidfd >= 0) {
 

                  r = pidref_set_pidfd(&leader, pidfd);
 

                  if (r < 0)
 

-                         return r;
 

+                         return log_debug_errno(r, "create_session: failed to set pidfd: %m");
 

          } else if (pid == 0) {
 

                  _cleanup_(sd_bus_creds_unrefp) sd_bus_creds *creds = NULL;
 

                  pid_t p;
 

  

                  r = sd_bus_query_sender_creds(message, SD_BUS_CREDS_PID, &creds);
 

                  if (r < 0)
 

-                         return r;
 

+                         return log_debug_errno(r, "create_session: failed to query sender creds: %m");
 

  

                  r = sd_bus_creds_get_pid(creds, &p);
 

                  if (r < 0)
 

-                         return r;
 

+                         return log_debug_errno(r, "create_session: failed to get pid from creds: %m");
 

  

                  r = pidref_set_pid(&leader, p);
 

                  if (r < 0)
 

-                         return r;
 

+                         return log_debug_errno(r, "create_session: failed to set pid: %m");
 

          } else {
 

                  assert(pid > 0);
 

  

                  r = pidref_set_pid(&leader, pid);
 

                  if (r < 0)
 

-                         return r;
 

+                         return log_debug_errno(r, "create_session: failed to set pid: %m");
 

          }
 

  

-         if (leader.pid == 1 || leader.pid == getpid_cached())
 

+         if (leader.pid == 1 || leader.pid == getpid_cached()) {
 

+                 log_debug("create_session: leader PID is 1 or our own PID");
 

                  return sd_bus_error_set(error, SD_BUS_ERROR_INVALID_ARGS, "Invalid leader PID");
 

+         }
 

  

          if (isempty(type))
 

                  t = _SESSION_TYPE_INVALID;
 

          else {
 

                  t = session_type_from_string(type);
 

-                 if (t < 0)
 

+                 if (t < 0) {
 

+                         log_debug("create_session: invalid session type");
 

                          return sd_bus_error_setf(error, SD_BUS_ERROR_INVALID_ARGS,
 

                                                   "Invalid session type %s", type);
 

+                 }
 

          }
 

  

          if (isempty(class))
 

                  c = _SESSION_CLASS_INVALID;
 

          else {
 

                  c = session_class_from_string(class);
 

-                 if (c < 0)
 

+                 if (c < 0) {
 

+                         log_debug("create_session: invalid session class");
 

                          return sd_bus_error_setf(error, SD_BUS_ERROR_INVALID_ARGS,
 

                                                   "Invalid session class %s", class);
 

+                 }
 

          }
 

  

          if (isempty(desktop))
 

                  desktop = NULL;
 

          else {
 

-                 if (!string_is_safe(desktop))
 

+                 if (!string_is_safe(desktop)) {
 

+                         log_debug("create_session: invalid desktop string");
 

                          return sd_bus_error_setf(error, SD_BUS_ERROR_INVALID_ARGS,
 

                                                   "Invalid desktop string %s", desktop);
 

+                 }
 

          }
 

  

          if (isempty(cseat))
 

                  seat = NULL;
 

          else {
 

                  seat = hashmap_get(m->seats, cseat);
 

-                 if (!seat)
 

+                 if (!seat) {
 

+                         log_debug("create_session: no such seat");
 

                          return sd_bus_error_setf(error, BUS_ERROR_NO_SUCH_SEAT,
 

                                                   "No seat '%s' known", cseat);
 

+                 }
 

          }
 

  

          if (tty_is_vc(tty)) {
 

                  int v;
 

  

-                 if (!seat)
 

+                 if (!seat) {
 

                          seat = m->seat0;
 

-                 else if (seat != m->seat0)
 

+                 } else if (seat != m->seat0) {
 

+                         log_debug("create_session: virtual console TTY specified but seat is not seat0");
 

                          return sd_bus_error_setf(error, SD_BUS_ERROR_INVALID_ARGS,
 

                                                   "TTY %s is virtual console but seat %s is not seat0", tty, seat->id);
 

+                 }
 

  

                  v = vtnr_from_tty(tty);
 

-                 if (v <= 0)
 

+                 if (v <= 0) {
 

+                         log_debug("create_session: invalid virtual console TTY");
 

                          return sd_bus_error_setf(error, SD_BUS_ERROR_INVALID_ARGS,
 

                                                   "Cannot determine VT number from virtual console TTY %s", tty);
 

+                 }
 

  

-                 if (vtnr == 0)
 

+                 if (vtnr == 0) {
 

                          vtnr = (uint32_t) v;
 

-                 else if (vtnr != (uint32_t) v)
 

+                 } else if (vtnr != (uint32_t) v) {
 

+                         log_debug("create_session: specified TTY and VT number do not match");
 

                          return sd_bus_error_setf(error, SD_BUS_ERROR_INVALID_ARGS,
 

                                                   "Specified TTY and VT number do not match");
 

+                 }
 

  

          } else if (tty_is_console(tty)) {
 

  

-                 if (!seat)
 

+                 if (!seat) {
 

                          seat = m->seat0;
 

-                 else if (seat != m->seat0)
 

+                 } else if (seat != m->seat0) {
 

+                         log_debug("create_session: console TTY specified but seat is not seat0");
 

                          return sd_bus_error_setf(error, SD_BUS_ERROR_INVALID_ARGS,
 

                                                   "Console TTY specified but seat is not seat0");
 

+                 }
 

  

-                 if (vtnr != 0)
 

+                 if (vtnr != 0) {
 

+                         log_debug("create_session: console TTY specified but VT number is not 0");
 

                          return sd_bus_error_setf(error, SD_BUS_ERROR_INVALID_ARGS,
 

                                                   "Console TTY specified but VT number is not 0");
 

+                 }
 

          }
 

  

          if (seat) {
 

                  if (seat_has_vts(seat)) {
 

-                         if (vtnr <= 0 || vtnr > 63)
 

+                         if (vtnr <= 0 || vtnr > 63) {
 

+                                 log_debug("create_session: VT number out of range");
 

                                  return sd_bus_error_setf(error, SD_BUS_ERROR_INVALID_ARGS,
 

                                                           "VT number out of range");
 

+                         }
 

                  } else {
 

-                         if (vtnr != 0)
 

+                         if (vtnr != 0) {
 

+                                 log_debug("create_session: seat has no VTs but VT number not 0");
 

                                  return sd_bus_error_setf(error, SD_BUS_ERROR_INVALID_ARGS,
 

                                                           "Seat has no VTs but VT number not 0");
 

+                         }
 

                  }
 

          }
 

  
@@ -846,10 +874,12 @@ 
 

           * which is a special PAM session that avoids creating a logind session. */
 

          r = manager_get_user_by_pid(m, leader.pid, NULL);
 

          if (r < 0)
 

-                 return r;
 

-         if (r > 0)
 

+                 return log_debug_errno(r, "create_session: failed to get user by PID: %m");
 

+         if (r > 0) {
 

+                 log_debug("create_session: already in a logind session");
 

                  return sd_bus_error_setf(error, BUS_ERROR_SESSION_BUSY,
 

                                           "Already running in a session or user slice");
 

+         }
 

  

          /*
 

           * Old gdm and lightdm start the user-session on the same VT as
 
@@ -865,13 +895,17 @@ 
 

              vtnr > 0 &&
 

              vtnr < MALLOC_ELEMENTSOF(m->seat0->positions) &&
 

              m->seat0->positions[vtnr] &&
 

-             m->seat0->positions[vtnr]->class != SESSION_GREETER)
 

+             m->seat0->positions[vtnr]->class != SESSION_GREETER) {
 

+                 log_debug("create_session: VT is already taken");
 

                  return sd_bus_error_set(error, BUS_ERROR_SESSION_BUSY, "Already occupied by a session");
 

+         }
 

  

-         if (hashmap_size(m->sessions) >= m->sessions_max)
 

+         if (hashmap_size(m->sessions) >= m->sessions_max) {
 

+                 log_debug("create_session: maximum number of sessions reached");
 

                  return sd_bus_error_setf(error, SD_BUS_ERROR_LIMITS_EXCEEDED,
 

                                           "Maximum number of sessions (%" PRIu64 ") reached, refusing further sessions.",
 

                                           m->sessions_max);
 

+         }
 

  

          (void) audit_session_from_pid(leader.pid, &audit_id);
 

          if (audit_session_is_valid(audit_id)) {
 
@@ -907,17 +941,23 @@ 
 

          manager_reconnect_utmp(m);
 

  

          r = manager_add_user_by_uid(m, uid, &user);
 

-         if (r < 0)
 

+         if (r < 0) {
 

+                 log_debug_errno(r, "create_session: failed to add user: %m");
 

                  goto fail;
 

+         }
 

  

          r = manager_add_session(m, id, &session);
 

-         if (r < 0)
 

+         if (r < 0) {
 

+                 log_debug_errno(r, "create_session: failed to add session: %m");
 

                  goto fail;
 

+         }
 

  

          session_set_user(session, user);
 

          r = session_set_leader_consume(session, TAKE_PIDREF(leader));
 

-         if (r < 0)
 

+         if (r < 0) {
 

+                 log_debug_errno(r, "create_session: failed to set leader: %m");
 

                  goto fail;
 

+         }
 

  

          session->original_type = session->type = t;
 

          session->class = c;
 
@@ -976,21 +1016,29 @@ 
 

  

          if (seat) {
 

                  r = seat_attach_session(seat, session);
 

-                 if (r < 0)
 

+                 if (r < 0) {
 

+                         log_debug_errno(r, "create_session: failed to attach session to seat: %m");
 

                          goto fail;
 

+                 }
 

          }
 

  

          r = sd_bus_message_enter_container(message, 'a', "(sv)");
 

-         if (r < 0)
 

+         if (r < 0) {
 

+                 log_debug_errno(r, "create_session: failed to enter container: %m");
 

                  goto fail;
 

+         }
 

  

          r = session_start(session, message, error);
 

-         if (r < 0)
 

+         if (r < 0) {
 

+                 log_debug_errno(r, "create_session: failed to start session: %m");
 

                  goto fail;
 

+         }
 

  

          r = sd_bus_message_exit_container(message);
 

-         if (r < 0)
 

+         if (r < 0) {
 

+                 log_debug_errno(r, "create_session: failed to exit container: %m");
 

                  goto fail;
 

+         }
 

  

          session->create_message = sd_bus_message_ref(message);
 

  
@@ -1038,7 +1086,7 @@ 
 

                                  &remote_user,
 

                                  &remote_host);
 

          if (r < 0)
 

-                 return r;
 

+                 return log_debug_errno(r, "method_create_session: failed to parse message: %m");
 

  

          return create_session(
 

                          message,
 
@@ -1087,7 +1135,7 @@ 
 

                                  &remote_host,
 

                                  &flags);
 

          if (r < 0)
 

-                 return r;
 

+                 return log_debug_errno(r, "method_create_session_pidfd: failed to parse message: %m");
 

  

          return create_session(
 

                          message,
 
@@ -4142,85 +4190,87 @@ 
 

  

          r = bus_message_new_method_call(manager->bus, &m, bus_systemd_mgr, "StartTransientUnit");
 

          if (r < 0)
 

-                 return r;
 

+                 return log_debug_errno(r, "manager_start_scope: failed to call method 'StartTransientUnit': %m");
 

  

          r = sd_bus_message_append(m, "ss", strempty(scope), "fail");
 

          if (r < 0)
 

-                 return r;
 

+                 return log_debug_errno(r, "manager_start_scope: failed to append 'fail' to message: %m");
 

  

          r = sd_bus_message_open_container(m, 'a', "(sv)");
 

          if (r < 0)
 

-                 return r;
 

+                 return log_debug_errno(r, "manager_start_scope: failed to open container: %m");
 

  

          if (!isempty(slice)) {
 

                  r = sd_bus_message_append(m, "(sv)", "Slice", "s", slice);
 

                  if (r < 0)
 

-                         return r;
 

+                         return log_debug_errno(r, "manager_start_scope: failed to append 'Slice' to message: %m");
 

          }
 

  

          if (!isempty(description)) {
 

                  r = sd_bus_message_append(m, "(sv)", "Description", "s", description);
 

                  if (r < 0)
 

-                         return r;
 

+                         return log_debug_errno(r, "manager_start_scope: failed to append 'Description' to message: %m");
 

          }
 

  

          STRV_FOREACH(i, wants) {
 

                  r = sd_bus_message_append(m, "(sv)", "Wants", "as", 1, *i);
 

                  if (r < 0)
 

-                         return r;
 

+                         return log_debug_errno(r, "manager_start_scope: failed to append 'Wants' to message: %m");
 

          }
 

  

          STRV_FOREACH(i, after) {
 

                  r = sd_bus_message_append(m, "(sv)", "After", "as", 1, *i);
 

                  if (r < 0)
 

-                         return r;
 

+                         return log_debug_errno(r, "manager_start_scope: failed to append 'After' to message: %m");
 

          }
 

  

          if (!empty_or_root(requires_mounts_for)) {
 

                  r = sd_bus_message_append(m, "(sv)", "RequiresMountsFor", "as", 1, requires_mounts_for);
 

                  if (r < 0)
 

-                         return r;
 

+                         return log_debug_errno(r, "manager_start_scope: failed to append 'RequiresMountsFor' to message: %m");
 

          }
 

  

          /* Make sure that the session shells are terminated with SIGHUP since bash and friends tend to ignore
 

           * SIGTERM */
 

          r = sd_bus_message_append(m, "(sv)", "SendSIGHUP", "b", true);
 

          if (r < 0)
 

-                 return r;
 

+                 return log_debug_errno(r, "manager_start_scope: failed to append 'SendSIGHUP' to message: %m");
 

  

          r = bus_append_scope_pidref(m, pidref);
 

          if (r < 0)
 

-                 return r;
 

+                 return log_debug_errno(r, "manager_start_scope: failed to append PID ref to scope: %m");
 

  

          /* For login session scopes, if a process is OOM killed by the kernel, *don't* terminate the rest of
 

             the scope */
 

          r = sd_bus_message_append(m, "(sv)", "OOMPolicy", "s", "continue");
 

          if (r < 0)
 

-                 return r;
 

+                 return log_debug_errno(r, "manager_start_scope: failed to append 'OMMPolicy' to message: %m");
 

  

          /* disable TasksMax= for the session scope, rely on the slice setting for it */
 

          r = sd_bus_message_append(m, "(sv)", "TasksMax", "t", UINT64_MAX);
 

-         if (r < 0)
 

+         if (r < 0) {
 

+                 log_debug_errno(r, "manager_start_scope: failed to append 'TasksMax' to message: %m");
 

                  return bus_log_create_error(r);
 

+         }
 

  

          if (more_properties) {
 

                  /* If TasksMax also appears here, it will overwrite the default value set above */
 

                  r = sd_bus_message_copy(m, more_properties, true);
 

                  if (r < 0)
 

-                         return r;
 

+                         return log_debug_errno(r, "manager_start_scope: failed to copy more properties to message: %m");
 

          }
 

  

          r = sd_bus_message_close_container(m);
 

          if (r < 0)
 

-                 return r;
 

+                 return log_debug_errno(r, "manager_start_scope: close container: %m");
 

  

          r = sd_bus_message_append(m, "a(sa(sv))", 0);
 

          if (r < 0)
 

-                 return r;
 

+                 return log_debug_errno(r, "manager_start_scope: failed to append to message: %m");
 

  

          r = sd_bus_call(manager->bus, m, 0, error, &reply);
 

          if (r < 0)
 

-                 return r;
 

+                 return log_debug_errno(r, "manager_start_scope: failed to call method: %m");
 

  

          return strdup_job(reply, job);
 

  }

file modified
+12 -6 
@@ -817,30 +817,36 @@ 
 

          /* This is called after the session scope and the user service were successfully created, and finishes where
 

           * bus_manager_create_session() left off. */
 

  

-         if (!s->create_message)
 

+         if (!s->create_message) {
 

+                 log_debug("session_send_create_reply: no create_message set");
 

                  return 0;
 

+         }
 

  

-         if (!sd_bus_error_is_set(error) && !session_ready(s))
 

+         if (!sd_bus_error_is_set(error) && !session_ready(s)) {
 

+                 log_debug("session_send_create_reply: no sd_bus_error nor session ready");
 

                  return 0;
 

+         }
 

  

          c = TAKE_PTR(s->create_message);
 

-         if (error)
 

+         if (error) {
 

+                 log_debug("session_send_create_reply: reply with error");
 

                  return sd_bus_reply_method_error(c, error);
 

+         }
 

  

          fifo_fd = session_create_fifo(s);
 

          if (fifo_fd < 0)
 

-                 return fifo_fd;
 

+                 return log_debug_errno(fifo_fd, "session_send_create_reply: failed to create session fifo: %m");
 

  

          r = session_watch_pidfd(s);
 

          if (r < 0)
 

-                 return r;
 

+                 return log_debug_errno(r, "session_send_create_reply: failed to watch session pidfd: %m");
 

  

          /* Update the session state file before we notify the client about the result. */
 

          session_save(s);
 

  

          p = session_bus_path(s);
 

          if (!p)
 

-                 return -ENOMEM;
 

+                 return log_debug_errno(-ENOMEM, "session_send_create_reply: failed to allocate bus path: %m");
 

  

          log_debug("Sending reply about created session: "
 

                    "id=%s object_path=%s uid=%u runtime_path=%s "

file modified
+7 
@@ -83,6 +83,8 @@ 
 

          if (r < 0)
 

                  return r;
 

  

+         log_debug("Created new session %s", id);
 

+ 

          *ret = TAKE_PTR(s);
 

          return 0;
 

  }
 
@@ -153,6 +155,7 @@ 
 

          free(s->service);
 

          free(s->desktop);
 

  

+         log_debug("Freed session %s", s->id);
 

          hashmap_remove(s->manager->sessions, s->id);
 

  

          sd_event_source_unref(s->fifo_event_source);
 
@@ -661,6 +664,8 @@ 
 

                  _cleanup_free_ char *scope = NULL;
 

                  const char *description;
 

  

+                 log_debug("Created new scope for session %s", s->id);
 

+ 

                  s->scope_job = mfree(s->scope_job);
 

  

                  scope = strjoin("session-", s->id, ".scope");
 
@@ -701,6 +706,8 @@ 
 

                                                 scope, bus_error_message(error, r));
 

  

                  s->scope = TAKE_PTR(scope);
 

+         } else {
 

+                 log_debug("Skipping scope creation for session %s, scope already exists", s->id);
 

          }
 

  

          (void) hashmap_put(s->manager->session_units, s->scope, s);

In order to debug an issue where logind keeps a lot of session in
"opening" state, we need to add debug messages to the session creation
logic.

Signed-off-by: Quentin Deslandes qde@naccy.de

Why isn't this an upstream change?

This change is specific to an issue we've been dealing with in production. We don't know yet what is going on, so the idea it to makesystemd-logind more verbose in order to gather information. That's the reason this change is targeting hs+fb specifically.

I should have mentioned that in the PR!

Honestly, I'm not sure why more verbosity tagged with debug isn't valuable generally anyway, but sure...

Since this is an fb branch, poking @dcavalca and @daandemeyer.

rebased onto 9c746dc
a year ago

rebased onto ca38171eceb348ba845303cac13e8a34508e48d4
a year ago

Rebased on hs+fb-v255.4

rebased onto 32b6194
a year ago

rebased onto 5706f7b
a year ago

rebased onto 9f12a00
a year ago

log_debug_errno?

This will also crash, you should only use log_debug_errno() if there's an error. Please just use log_debug() here.

Ditto

Ditto

Ditto

Ditto

rebased onto 90bd416
a year ago

rebased onto fad9451
a year ago

Pull-Request has been merged by daandemeyer
a year ago
Metadata
None
No Tags
Changes Summary 3
+101 -51
file changed
src/login/logind-dbus.c
+12 -6
file changed
src/login/logind-session-dbus.c
+7 -0
file changed
src/login/logind-session.c
Powered by Pagure 5.14.1
Documentation • File an Issue • About • SSH Hostkey/Fingerprint
© Red Hat, Inc. and others.