Various logging fixlets (#39837)

We have agreed the bump.

NEWS

@@ -27,8 +27,6 @@ CHANGES WITH 259 in spe:
           * libseccomp >= 2.4.0,
           * python >= 3.9.0.
 
-          Please provide feedback on systemd-devel if this would cause problems.
-
         * The parsing of RootImageOptions= and the mount image parameters of
           ExtensionImages= and MountImages= will be changed in the next version
           so that the last duplicated definition for a given partition wins and

src/core/apparmor-setup.c

@@ -20,7 +20,7 @@ int mac_apparmor_setup(void) {
         int r;
 
         if (!mac_apparmor_use()) {
-                log_debug("Skipping AppArmor initialization: not supported by the kernel, is disabled or libapparmor is not installed.");
+                log_debug("Skipping AppArmor initialization: not supported by the kernel, disabled, or libapparmor not installed.");
                 return 0;
         }
 

src/home/pam_systemd_home.c

@@ -62,7 +62,7 @@ static int parse_argv(
                                 *debug = k;
 
                 } else
-                        pam_syslog(handle, LOG_WARNING, "Unknown parameter '%s', ignoring", argv[i]);
+                        pam_syslog(handle, LOG_WARNING, "Unknown parameter '%s', ignoring.", argv[i]);
         }
 
         return 0;
@@ -186,9 +186,8 @@ static int acquire_user_record(
                                 goto user_unknown;
                         }
 
-                        pam_syslog(handle, LOG_ERR,
-                                   "Failed to query user record: %s", bus_error_message(&error, r));
-                        return PAM_SERVICE_ERR;
+                        return pam_syslog_pam_error(handle, LOG_ERR, PAM_SERVICE_ERR,
+                                                    "Failed to query user record: %s", bus_error_message(&error, r));
                 }
 
                 r = sd_bus_message_read(reply, "sbo", &json, NULL, NULL);
@@ -684,8 +683,10 @@ static int acquire_home(
                                                 if (home_locked)
                                                         (void) pam_prompt_graceful(handle, PAM_ERROR_MSG, NULL, _("Home of user %s is currently locked, please unlock locally first."), ur->user_name);
 
-                                                if (FLAGS_SET(flags, ACQUIRE_MUST_AUTHENTICATE) || debug)
-                                                        pam_syslog(handle, FLAGS_SET(flags, ACQUIRE_MUST_AUTHENTICATE) ? LOG_ERR : LOG_DEBUG, "Failed to prompt for password/prompt.");
+                                                if (FLAGS_SET(flags, ACQUIRE_MUST_AUTHENTICATE))
+                                                        pam_syslog(handle, LOG_ERR, "Failed to prompt for password/prompt.");
+                                                else if (debug)
+                                                        pam_debug_syslog(handle, debug, "Failed to prompt for password/prompt.");
 
                                                 return home_not_active || home_locked ? PAM_PERM_DENIED : PAM_CONV_ERR;
                                         }
@@ -806,7 +807,7 @@ _public_ PAM_EXTERN int pam_sm_authenticate(
                        &debug) < 0)
                 return PAM_AUTH_ERR;
 
-        pam_debug_syslog(handle, debug, "pam-systemd-homed authenticating");
+        pam_debug_syslog(handle, debug, "pam-systemd-homed: authenticating...");
 
         return acquire_home(handle, ACQUIRE_MUST_AUTHENTICATE|flags, debug, /* bus_data= */ NULL);
 }
@@ -873,7 +874,7 @@ _public_ PAM_EXTERN int pam_sm_open_session(
                        &debug) < 0)
                 return PAM_SESSION_ERR;
 
-        pam_debug_syslog(handle, debug, "pam-systemd-homed session start");
+        pam_debug_syslog(handle, debug, "pam-systemd-homed: starting session...");
 
         r = fallback_shell_can_work(handle, &flags);
         if (r != PAM_SUCCESS)
@@ -923,7 +924,7 @@ _public_ PAM_EXTERN int pam_sm_close_session(
                        &debug) < 0)
                 return PAM_SESSION_ERR;
 
-        pam_debug_syslog(handle, debug, "pam-systemd-homed session end");
+        pam_debug_syslog(handle, debug, "pam-systemd-homed: closing session...");
 
         r = pam_get_user(handle, &username, NULL);
         if (r != PAM_SUCCESS)
@@ -991,7 +992,7 @@ _public_ PAM_EXTERN int pam_sm_acct_mgmt(
                        &debug) < 0)
                 return PAM_AUTH_ERR;
 
-        pam_debug_syslog(handle, debug, "pam-systemd-homed account management");
+        pam_debug_syslog(handle, debug, "pam-systemd-homed: starting account management...");
 
         r = fallback_shell_can_work(handle, &flags);
         if (r != PAM_SUCCESS)
@@ -1107,7 +1108,7 @@ _public_ PAM_EXTERN int pam_sm_chauthtok(
                        &debug) < 0)
                 return PAM_AUTH_ERR;
 
-        pam_debug_syslog(handle, debug, "pam-systemd-homed account management");
+        pam_debug_syslog(handle, debug, "pam-systemd-homed: starting authentication token management...");
 
         r = acquire_user_record(handle, /* username= */ NULL, debug, &ur, /* bus_data= */ NULL);
         if (r != PAM_SUCCESS)

src/login/pam_systemd.c

@@ -145,7 +145,7 @@ static int parse_argv(
                 } else if ((p = startswith(argv[i], "area="))) {
 
                         if (!isempty(p) && !filename_is_valid(p))
-                                pam_syslog(handle, LOG_WARNING, "Area name specified among PAM module parameters is not valid, ignoring: %m");
+                                pam_syslog(handle, LOG_WARNING, "Area name specified among PAM module parameters is not valid, ignoring: %s", p);
                         else if (area)
                                 *area = p;
 
@@ -233,10 +233,9 @@ static int acquire_user_record(
                         return PAM_USER_UNKNOWN;
                 }
 
-                if (!uid_is_valid(ur->uid)) {
-                        pam_syslog_errno(handle, LOG_ERR, r, "User record of user '%s' has no UID, refusing: %m", username);
-                        return PAM_USER_UNKNOWN;
-                }
+                if (!uid_is_valid(ur->uid))
+                        return pam_syslog_pam_error(handle, LOG_ERR, PAM_USER_UNKNOWN,
+                                                    "User record of user '%s' has no UID, refusing.", username);
 
                 r = sd_json_variant_format(ur->json, 0, &formatted);
                 if (r < 0)
@@ -386,7 +385,7 @@ static int append_session_memory_max(pam_handle_t *handle, sd_bus_message *m, co
         r = parse_size(limit, 1024, &val);
         if (r < 0) {
                 pam_syslog(handle, LOG_WARNING, "Failed to parse systemd.memory_max, ignoring: %s", limit);
-                return PAM_SUCCESS;
+                return 0;
         }
 
         return sd_bus_message_append(m, "(sv)", "MemoryMax", "t", val);
@@ -510,7 +509,9 @@ static bool getenv_harder_bool(pam_handle_t *handle, const char *key, bool fallb
 
         r = parse_boolean(v);
         if (r < 0) {
-                pam_syslog(handle, LOG_WARNING, "Failed to parse environment variable value '%s' of '%s', falling back to using '%s'.", v, key, true_false(fallback));
+                pam_syslog(handle, LOG_WARNING,
+                           "Failed to parse environment variable value '%s' of '%s', falling back to using '%s'.",
+                           v, key, true_false(fallback));
                 return fallback;
         }
 
@@ -530,7 +531,9 @@ static uint32_t getenv_harder_uint32(pam_handle_t *handle, const char *key, uint
         uint32_t u;
         r = safe_atou32(v, &u);
         if (r < 0) {
-                pam_syslog(handle, LOG_WARNING, "Failed to parse environment variable value '%s' of '%s' as unsigned integer, falling back to using %" PRIu32 ".", v, key, fallback);
+                pam_syslog(handle, LOG_WARNING,
+                           "Failed to parse environment variable value '%s' of '%s' as unsigned integer, falling back to using %" PRIu32 ".",
+                           v, key, fallback);
                 return fallback;
         }
 
@@ -570,7 +573,7 @@ static int update_environment(pam_handle_t *handle, const char *key, const char
         return PAM_SUCCESS;
 }
 
-static int propagate_credential_to_environment(pam_handle_t *handle, const char *credential, const char *varname) {
+static int propagate_credential_to_environment(pam_handle_t *handle, bool debug, const char *credential, const char *varname) {
         int r;
 
         assert(handle);
@@ -583,7 +586,7 @@ static int propagate_credential_to_environment(pam_handle_t *handle, const char
 
         r = read_credential(credential, (void**) &value, /* ret_size= */ NULL);
         if (r < 0) {
-                log_debug_errno(r, "Failed to read credential '%s', ignoring: %m", credential);
+                pam_debug_syslog_errno(handle, debug, r, "Failed to read credential '%s', ignoring: %m", credential);
                 return PAM_SUCCESS;
         }
 
@@ -647,7 +650,6 @@ static int pam_putenv_and_log(pam_handle_t *handle, const char *e, bool debug) {
                                             "Failed to set PAM environment variable %s: @PAMERR@", e);
 
         pam_debug_syslog(handle, debug, "PAM environment variable %s set based on user record.", e);
-
         return PAM_SUCCESS;
 }
 
@@ -973,7 +975,7 @@ static void session_context_mangle(
         }
 
         if (c->seat && !streq(c->seat, "seat0") && c->vtnr != 0) {
-                pam_debug_syslog(handle, debug, "Ignoring vtnr %"PRIu32" for %s which is not seat0", c->vtnr, c->seat);
+                pam_debug_syslog(handle, debug, "Ignoring vtnr %"PRIu32" for %s which is not seat0.", c->vtnr, c->seat);
                 c->vtnr = 0;
         }
 
@@ -1115,7 +1117,7 @@ static int register_session(
 
                 r = sd_varlink_connect_address(&vl, "/run/systemd/io.systemd.Login");
                 if (r < 0)
-                        log_debug_errno(r, "Failed to connect to logind via Varlink, falling back to D-Bus: %m");
+                        pam_debug_syslog_errno(handle, debug, r, "Failed to connect to logind via Varlink, falling back to D-Bus: %m");
                 else {
                         r = sd_varlink_set_allow_fd_passing_output(vl, true);
                         if (r < 0)
@@ -1341,7 +1343,7 @@ static int register_session(
         return PAM_SUCCESS;
 }
 
-static int import_shell_credentials(pam_handle_t *handle) {
+static int import_shell_credentials(pam_handle_t *handle, bool debug) {
 
         static const char *const propagate[] = {
                 "shell.prompt.prefix", "SHELL_PROMPT_PREFIX",
@@ -1354,7 +1356,7 @@ static int import_shell_credentials(pam_handle_t *handle) {
         assert(handle);
 
         STRV_FOREACH_PAIR(k, v, propagate) {
-                r = propagate_credential_to_environment(handle, *k, *v);
+                r = propagate_credential_to_environment(handle, debug, *k, *v);
                 if (r != PAM_SUCCESS)
                         return r;
         }
@@ -1749,7 +1751,7 @@ _public_ PAM_EXTERN int pam_sm_open_session(
                        &default_capability_ambient_set) < 0)
                 return PAM_SESSION_ERR;
 
-        pam_debug_syslog(handle, debug, "pam-systemd initializing");
+        pam_debug_syslog(handle, debug, "pam-systemd: initializing...");
 
         _cleanup_(user_record_unrefp) UserRecord *ur = NULL;
         r = acquire_user_record(handle, &ur);
@@ -1792,7 +1794,7 @@ _public_ PAM_EXTERN int pam_sm_open_session(
         if (r != PAM_SUCCESS)
                 return r;
 
-        r = import_shell_credentials(handle);
+        r = import_shell_credentials(handle, debug);
         if (r != PAM_SUCCESS)
                 return r;
 
@@ -1835,7 +1837,7 @@ _public_ PAM_EXTERN int pam_sm_close_session(
                        /* default_capability_ambient_set= */ NULL) < 0)
                 return PAM_SESSION_ERR;
 
-        pam_debug_syslog(handle, debug, "pam-systemd shutting down");
+        pam_debug_syslog(handle, debug, "pam-systemd: shutting down...");
 
         /* Only release session if it wasn't pre-existing when we
          * tried to create it */
@@ -1853,7 +1855,7 @@ _public_ PAM_EXTERN int pam_sm_close_session(
 
                 r = sd_varlink_connect_address(&vl, "/run/systemd/io.systemd.Login");
                 if (r < 0)
-                        log_debug_errno(r, "Failed to connect to logind via Varlink, falling back to D-Bus: %m");
+                        pam_debug_syslog_errno(handle, debug, r, "Failed to connect to logind via Varlink, falling back to D-Bus: %m");
                 else {
                         _cleanup_(sd_json_variant_unrefp) sd_json_variant *vreply = NULL;
                         const char *error_id = NULL;

src/login/pam_systemd_loadkey.c

@@ -44,7 +44,7 @@ _public_ PAM_EXTERN int pam_sm_authenticate(
                         pam_syslog(handle, LOG_WARNING, "Unknown parameter '%s', ignoring.", argv[i]);
         }
 
-        pam_debug_syslog(handle, debug, "pam-systemd-loadkey initializing");
+        pam_debug_syslog(handle, debug, "pam-systemd-loadkey: initializing...");
 
         /* Retrieve the key. */
 
@@ -76,10 +76,10 @@ _public_ PAM_EXTERN int pam_sm_authenticate(
 
         size_t passwords_len = strv_length(passwords);
         if (passwords_len == 0) {
-                pam_debug_syslog(handle, debug, "Key is empty");
+                pam_debug_syslog(handle, debug, "Key is empty.");
                 return PAM_AUTHINFO_UNAVAIL;
         } else if (passwords_len > 1)
-                pam_debug_syslog(handle, debug, "Multiple passwords found in the key. Using the last one");
+                pam_debug_syslog(handle, debug, "Multiple passwords found in the key. Using the last one.");
 
         r = pam_set_item(handle, PAM_AUTHTOK, passwords[passwords_len - 1]);
         if (r != PAM_SUCCESS)

src/shared/pam-util.c

@@ -69,16 +69,21 @@ void pam_log_setup(void) {
         log_set_target(LOG_TARGET_SYSLOG);
 }
 
+int errno_to_pam_error(int error) {
+        return ERRNO_VALUE(error) == ENOMEM ? PAM_BUF_ERR : PAM_SERVICE_ERR;
+}
+
 int pam_syslog_errno(pam_handle_t *handle, int level, int error, const char *format, ...) {
         va_list ap;
 
+        error = ERRNO_VALUE(error);
         LOCAL_ERRNO(error);
 
         va_start(ap, format);
         sym_pam_vsyslog(handle, level, format, ap);
         va_end(ap);
 
-        return error == -ENOMEM ? PAM_BUF_ERR : PAM_SERVICE_ERR;
+        return errno_to_pam_error(error);
 }
 
 int pam_syslog_pam_error(pam_handle_t *handle, int level, int error, const char *format, ...) {

src/shared/pam-util.h

@@ -31,6 +31,8 @@ int dlopen_libpam(void);
 
 void pam_log_setup(void);
 
+int errno_to_pam_error(int error) _const_;
+
 int pam_syslog_errno(pam_handle_t *handle, int level, int error, const char *format, ...) _printf_(4,5);
 
 int pam_syslog_pam_error(pam_handle_t *handle, int level, int error, const char *format, ...) _printf_(4,5);
@@ -45,8 +47,10 @@ int pam_syslog_pam_error(pam_handle_t *handle, int level, int error, const char
 /* Call pam_syslog_errno if debug is enabled */
 #define pam_debug_syslog_errno(handle, debug, error, fmt, ...)          \
         ({                                                              \
-                if (debug)                                              \
-                        pam_syslog_errno(handle, LOG_DEBUG, error, fmt, ## __VA_ARGS__); \
+                int _error = (error);                                   \
+                debug ?                                                 \
+                        pam_syslog_errno(handle, LOG_DEBUG, _error, fmt, ## __VA_ARGS__) : \
+                        errno_to_pam_error(_error);                     \
         })
 
 static inline int pam_log_oom(pam_handle_t *handle) {