From fad9451f4e8d056dee0780cd38a7fc98a221d4e4 Mon Sep 17 00:00:00 2001 From: Quentin Deslandes Date: Mar 04 2024 14:31:08 +0000 Subject: logind: add debug messages to session creation logic 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 --- diff --git a/src/login/logind-dbus.c b/src/login/logind-dbus.c index ec1f2f3..7c967b0 100644 --- a/src/login/logind-dbus.c +++ b/src/login/logind-dbus.c @@ -710,119 +710,147 @@ static int create_session( 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 @@ static int create_session( * 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 @@ static int create_session( 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 @@ static int create_session( 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 @@ static int create_session( 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 @@ static int method_create_session(sd_bus_message *message, void *userdata, sd_bus &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 @@ static int method_create_session_pidfd(sd_bus_message *message, void *userdata, &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 @@ int manager_start_scope( 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); } diff --git a/src/login/logind-session-dbus.c b/src/login/logind-session-dbus.c index a136ae4..ae09421 100644 --- a/src/login/logind-session-dbus.c +++ b/src/login/logind-session-dbus.c @@ -817,30 +817,36 @@ int session_send_create_reply(Session *s, sd_bus_error *error) { /* 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 " diff --git a/src/login/logind-session.c b/src/login/logind-session.c index 3988e55..fedb76d 100644 --- a/src/login/logind-session.c +++ b/src/login/logind-session.c @@ -83,6 +83,8 @@ int session_new(Session **ret, Manager *m, const char *id) { if (r < 0) return r; + log_debug("Created new session %s", id); + *ret = TAKE_PTR(s); return 0; } @@ -153,6 +155,7 @@ Session* session_free(Session *s) { 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 @@ static int session_start_scope(Session *s, sd_bus_message *properties, sd_bus_er _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 @@ static int session_start_scope(Session *s, sd_bus_message *properties, sd_bus_er 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);