udev-rules: logs result of format substitution

This also drops redundant token string in log message on truncation.

No functional change, but should improve debuggability.

1 files changed, 105 insertions, 138 deletions

diff --git a/src/udev/udev-rules.c b/src/udev/udev-rules.c
index cac7d0abfc..c42124c28d 100644
--- a/src/udev/udev-rules.c
+++ b/src/udev/udev-rules.c
@@ -298,6 +298,23 @@ static bool token_is_for_parents(UdevRuleToken *token) {
 #define log_event_trace(event, ...)                                     \
         _log_event_trace(event, UNIQ_T(e, UNIQ), __VA_ARGS__)
 
+#define _log_event_truncated(event, token, token_u, what, format)       \
+        ({                                                              \
+                UdevRuleToken *token_u = ASSERT_PTR(token);             \
+                                                                        \
+                token_u->type < _TK_M_MAX ?                             \
+                        log_event_debug(event, token_u,                 \
+                                        "The %s is truncated while substituting into \"%s\", assuming the token fails.", \
+                                        what, (const char*) format) :   \
+                        log_event_warning(                              \
+                                        event, token_u,                 \
+                                        "The %s is truncated while substituting into \"%s\", refusing to apply the token.", \
+                                        what, (const char*) format);    \
+        })
+
+#define log_event_truncated(event, token, what, format)                 \
+        _log_event_truncated(event, token, UNIQ_T(t, UNIQ), what, format)
+
 /* Mainly used when parsing .rules files. */
 #define log_file_full_errno_zerook(...)                                 \
         log_udev_rule_file_full(NULL, __VA_ARGS__)
@@ -352,26 +369,6 @@ static void log_unknown_owner(sd_device *dev, UdevRuleLine *line, int error, con
                 log_udev_rule_line_full(dev, line, LOG_ERR, error, "Failed to resolve %s '%s', ignoring: %m", entity, name);
 }
 
-static void log_event_truncated(
-                UdevEvent *event,
-                UdevRuleToken *token,
-                const char *what,
-                const char *format,
-                const char *key,
-                bool is_match) {
-
-        if (is_match)
-                log_event_debug(event, token,
-                                "The %s is truncated while substituting into '%s', "
-                                "assuming the %s key does not match.",
-                                what, format, key);
-        else
-                log_event_warning(event, token,
-                                  "The %s is truncated while substituting into '%s', "
-                                  "refusing to apply the %s key.",
-                                  what, format, key);
-}
-
 /*** Other functions ***/
 
 static UdevRuleToken* udev_rule_token_free(UdevRuleToken *token) {
@@ -1777,6 +1774,54 @@ bool udev_rules_should_reload(UdevRules *rules) {
         return false;
 }
 
+static bool apply_format_full(
+                UdevEvent *event,
+                UdevRuleToken *token,
+                const char *format,
+                char *result,
+                size_t result_size,
+                bool replace_whitespace,
+                const char *what) {
+
+        assert(event);
+        assert(token);
+        assert(format);
+        assert(result);
+        assert(what);
+
+        bool truncated = false;
+        (void) udev_event_apply_format(event, format, result, result_size, replace_whitespace, &truncated);
+        if (truncated) {
+                log_event_truncated(event, token, what, format);
+                return false;
+        }
+
+        if (event->trace && !streq(format, result))
+                log_event_trace(event, token, "Format substitution: \"%s\" -> \"%s\"", format, result);
+
+        return true;
+}
+
+static bool apply_format_value(
+                UdevEvent *event,
+                UdevRuleToken *token,
+                char *result,
+                size_t result_size,
+                const char *what) {
+
+        return apply_format_full(event, token, token->value, result, result_size, /* replace_whitespace = */ false, what);
+}
+
+static bool apply_format_attr(
+                UdevEvent *event,
+                UdevRuleToken *token,
+                char *result,
+                size_t result_size,
+                const char *what) {
+
+        return apply_format_full(event, token, token->data, result, result_size, /* replace_whitespace = */ false, what);
+}
+
 static bool token_match_string(UdevRuleToken *token, const char *str) {
         const char *value;
         bool match = false, case_insensitive;
@@ -1835,7 +1880,6 @@ static bool token_match_string(UdevRuleToken *token, const char *str) {
 static bool token_match_attr(UdevRuleToken *token, sd_device *dev, UdevEvent *event) {
         char nbuf[UDEV_NAME_SIZE], vbuf[UDEV_NAME_SIZE];
         const char *name, *value;
-        bool truncated;
 
         assert(token);
         assert(IN_SET(token->type, TK_M_ATTR, TK_M_PARENTS_ATTR));
@@ -1846,12 +1890,8 @@ static bool token_match_attr(UdevRuleToken *token, sd_device *dev, UdevEvent *ev
 
         switch (token->attr_subst_type) {
         case SUBST_TYPE_FORMAT:
-                (void) udev_event_apply_format(event, name, nbuf, sizeof(nbuf), false, &truncated);
-                if (truncated) {
-                        log_event_truncated(event, token, "sysfs attribute name", name,
-                                            token->type == TK_M_ATTR ? "ATTR" : "ATTRS", /* is_match = */ true);
+                if (!apply_format_attr(event, token, nbuf, sizeof(nbuf), "sysfs attribute name"))
                         return false;
-                }
 
                 name = nbuf;
                 _fallthrough_;
@@ -2119,13 +2159,9 @@ static int udev_rule_apply_token_to_event(
         case TK_M_SYSCTL: {
                 _cleanup_free_ char *value = NULL;
                 char buf[UDEV_PATH_SIZE];
-                bool truncated;
 
-                (void) udev_event_apply_format(event, token->data, buf, sizeof(buf), false, &truncated);
-                if (truncated) {
-                        log_event_truncated(event, token, "sysctl entry name", token->data, "SYSCTL", /* is_match = */ true);
+                if (!apply_format_attr(event, token, buf, sizeof(buf), "sysctl entry name"))
                         return false;
-                }
 
                 r = sysctl_read(sysctl_normalize(buf), &value);
                 if (r < 0 && r != -ENOENT)
@@ -2137,13 +2173,10 @@ static int udev_rule_apply_token_to_event(
                 mode_t mode = PTR_TO_MODE(token->data);
                 char buf[UDEV_PATH_SIZE];
                 struct stat statbuf;
-                bool match, truncated;
+                bool match;
 
-                (void) udev_event_apply_format(event, token->value, buf, sizeof(buf), false, &truncated);
-                if (truncated) {
-                        log_event_truncated(event, token, "file name", token->value, "TEST", /* is_match = */ true);
+                if (!apply_format_value(event, token, buf, sizeof(buf), "file name"))
                         return false;
-                }
 
                 if (!path_is_absolute(buf) &&
                     udev_resolve_subsys_kernel(buf, buf, sizeof(buf), false) < 0) {
@@ -2154,6 +2187,7 @@ static int udev_rule_apply_token_to_event(
                         if (r < 0)
                                 return log_event_error_errno(event, token, r, "Failed to get syspath: %m");
 
+                        bool truncated;
                         strscpy_full(tmp, sizeof(tmp), buf, &truncated);
                         assert(!truncated);
                         strscpyl_full(buf, sizeof(buf), &truncated, val, "/", tmp, NULL);
@@ -2178,15 +2212,12 @@ static int udev_rule_apply_token_to_event(
         }
         case TK_M_PROGRAM: {
                 char buf[UDEV_LINE_SIZE], result[UDEV_LINE_SIZE];
-                bool truncated;
                 size_t count;
 
                 event->program_result = mfree(event->program_result);
-                (void) udev_event_apply_format(event, token->value, buf, sizeof(buf), false, &truncated);
-                if (truncated) {
-                        log_event_truncated(event, token, "command", token->value, "PROGRAM", /* is_match = */ true);
+
+                if (!apply_format_value(event, token, buf, sizeof(buf), "command"))
                         return false;
-                }
 
                 log_event_debug(event, token, "Running PROGRAM=\"%s\"", buf);
 
@@ -2212,13 +2243,9 @@ static int udev_rule_apply_token_to_event(
         case TK_M_IMPORT_FILE: {
                 _cleanup_fclose_ FILE *f = NULL;
                 char buf[UDEV_PATH_SIZE];
-                bool truncated;
 
-                (void) udev_event_apply_format(event, token->value, buf, sizeof(buf), false, &truncated);
-                if (truncated) {
-                        log_event_truncated(event, token, "file name to be imported", token->value, "IMPORT", /* is_match = */ true);
+                if (!apply_format_value(event, token, buf, sizeof(buf), "file name to be imported"))
                         return false;
-                }
 
                 log_event_debug(event, token, "Importing properties from '%s'", buf);
 
@@ -2265,11 +2292,8 @@ static int udev_rule_apply_token_to_event(
                 char buf[UDEV_LINE_SIZE], result[UDEV_LINE_SIZE];
                 bool truncated;
 
-                (void) udev_event_apply_format(event, token->value, buf, sizeof(buf), false, &truncated);
-                if (truncated) {
-                        log_event_truncated(event, token, "command", token->value, "IMPORT", /* is_match = */ true);
+                if (!apply_format_value(event, token, buf, sizeof(buf), "command"))
                         return false;
-                }
 
                 log_event_debug(event, token, "Importing properties from results of '%s'", buf);
 
@@ -2330,7 +2354,6 @@ static int udev_rule_apply_token_to_event(
                 assert(cmd >= 0 && cmd < _UDEV_BUILTIN_MAX);
                 unsigned mask = 1U << (int) cmd;
                 char buf[UDEV_LINE_SIZE];
-                bool truncated;
 
                 if (udev_builtin_run_once(cmd)) {
                         /* check if we ran already */
@@ -2344,11 +2367,8 @@ static int udev_rule_apply_token_to_event(
                         event->builtin_run |= mask;
                 }
 
-                (void) udev_event_apply_format(event, token->value, buf, sizeof(buf), false, &truncated);
-                if (truncated) {
-                        log_event_truncated(event, token, "builtin command", token->value, "IMPORT", /* is_match = */ true);
+                if (!apply_format_value(event, token, buf, sizeof(buf), "builtin command"))
                         return false;
-                }
 
                 log_event_debug(event, token, "Importing properties from results of builtin command '%s'", buf);
 
@@ -2398,13 +2418,9 @@ static int udev_rule_apply_token_to_event(
         }
         case TK_M_IMPORT_PARENT: {
                 char buf[UDEV_PATH_SIZE];
-                bool truncated;
 
-                (void) udev_event_apply_format(event, token->value, buf, sizeof(buf), false, &truncated);
-                if (truncated) {
-                        log_event_truncated(event, token, "property name", token->value, "IMPORT", /* is_match = */ true);
+                if (!apply_format_value(event, token, buf, sizeof(buf), "property name"))
                         return false;
-                }
 
                 r = import_parent_into_properties(dev, buf);
                 if (r < 0)
@@ -2461,18 +2477,14 @@ static int udev_rule_apply_token_to_event(
         case TK_A_OWNER: {
                 char owner[UDEV_NAME_SIZE];
                 const char *ow = owner;
-                bool truncated;
 
                 if (event->owner_final)
                         break;
                 if (token->op == OP_ASSIGN_FINAL)
                         event->owner_final = true;
 
-                (void) udev_event_apply_format(event, token->value, owner, sizeof(owner), false, &truncated);
-                if (truncated) {
-                        log_event_truncated(event, token, "user name", token->value, "OWNER", /* is_match = */ false);
-                        break;
-                }
+                if (!apply_format_value(event, token, owner, sizeof(owner), "user name"))
+                        return true;
 
                 r = get_user_creds(&ow, &event->uid, NULL, NULL, NULL, USER_CREDS_ALLOW_MISSING);
                 if (r < 0)
@@ -2484,18 +2496,14 @@ static int udev_rule_apply_token_to_event(
         case TK_A_GROUP: {
                 char group[UDEV_NAME_SIZE];
                 const char *gr = group;
-                bool truncated;
 
                 if (event->group_final)
                         break;
                 if (token->op == OP_ASSIGN_FINAL)
                         event->group_final = true;
 
-                (void) udev_event_apply_format(event, token->value, group, sizeof(group), false, &truncated);
-                if (truncated) {
-                        log_event_truncated(event, token, "group name", token->value, "GROUP", /* is_match = */ false);
-                        break;
-                }
+                if (!apply_format_value(event, token, group, sizeof(group), "group name"))
+                        return true;
 
                 r = get_group_creds(&gr, &event->gid, USER_CREDS_ALLOW_MISSING);
                 if (r < 0)
@@ -2506,18 +2514,14 @@ static int udev_rule_apply_token_to_event(
         }
         case TK_A_MODE: {
                 char mode_str[UDEV_NAME_SIZE];
-                bool truncated;
 
                 if (event->mode_final)
                         break;
                 if (token->op == OP_ASSIGN_FINAL)
                         event->mode_final = true;
 
-                (void) udev_event_apply_format(event, token->value, mode_str, sizeof(mode_str), false, &truncated);
-                if (truncated) {
-                        log_event_truncated(event, token, "mode", token->value, "MODE", /* is_match = */ false);
-                        break;
-                }
+                if (!apply_format_value(event, token, mode_str, sizeof(mode_str), "mode"))
+                        return true;
 
                 r = parse_mode(mode_str, &event->mode);
                 if (r < 0)
@@ -2559,17 +2563,13 @@ static int udev_rule_apply_token_to_event(
         case TK_A_SECLABEL: {
                 _cleanup_free_ char *name = NULL, *label = NULL;
                 char label_str[UDEV_LINE_SIZE] = {};
-                bool truncated;
 
                 name = strdup(token->data);
                 if (!name)
                         return log_oom();
 
-                (void) udev_event_apply_format(event, token->value, label_str, sizeof(label_str), false, &truncated);
-                if (truncated) {
-                        log_event_truncated(event, token, "security label", token->value, "SECLABEL", /* is_match = */ false);
-                        break;
-                }
+                if (!apply_format_value(event, token, label_str, sizeof(label_str), "security label"))
+                        return true;
 
                 if (!isempty(label_str))
                         label = strdup(label_str);
@@ -2597,7 +2597,6 @@ static int udev_rule_apply_token_to_event(
                 const char *val, *name = token->data;
                 char value_new[UDEV_NAME_SIZE], *p = value_new;
                 size_t count, l = sizeof(value_new);
-                bool truncated;
 
                 if (isempty(token->value)) {
                         if (token->op == OP_ADD)
@@ -2610,6 +2609,7 @@ static int udev_rule_apply_token_to_event(
 
                 if (token->op == OP_ADD &&
                     device_get_property_value_with_fallback(dev, name, event->worker ? event->worker->properties : NULL, &val) >= 0) {
+                        bool truncated;
                         l = strpcpyl_full(&p, l, &truncated, val, " ", NULL);
                         if (truncated) {
                                 log_event_warning(event, token,
@@ -2619,13 +2619,8 @@ static int udev_rule_apply_token_to_event(
                         }
                 }
 
-                (void) udev_event_apply_format(event, token->value, p, l, false, &truncated);
-                if (truncated) {
-                        _cleanup_free_ char *key_with_name = strjoin("ENV{", name, "}");
-                        log_event_truncated(event, token, "property value", token->value,
-                                            key_with_name ?: "ENV", /* is_match = */ false);
-                        break;
-                }
+                if (!apply_format_value(event, token, p, l, "property value"))
+                        return true;
 
                 if (event->esc == ESCAPE_REPLACE) {
                         count = udev_replace_chars(p, NULL);
@@ -2642,13 +2637,9 @@ static int udev_rule_apply_token_to_event(
         }
         case TK_A_TAG: {
                 char buf[UDEV_PATH_SIZE];
-                bool truncated;
 
-                (void) udev_event_apply_format(event, token->value, buf, sizeof(buf), false, &truncated);
-                if (truncated) {
-                        log_event_truncated(event, token, "tag name", token->value, "TAG", /* is_match = */ false);
-                        break;
-                }
+                if (!apply_format_value(event, token, buf, sizeof(buf), "tag name"))
+                        return true;
 
                 if (token->op == OP_ASSIGN)
                         device_cleanup_tags(dev);
@@ -2666,7 +2657,6 @@ static int udev_rule_apply_token_to_event(
         }
         case TK_A_NAME: {
                 char buf[UDEV_PATH_SIZE];
-                bool truncated;
                 size_t count;
 
                 if (event->name_final)
@@ -2681,11 +2671,8 @@ static int udev_rule_apply_token_to_event(
                         break;
                 }
 
-                (void) udev_event_apply_format(event, token->value, buf, sizeof(buf), false, &truncated);
-                if (truncated) {
-                        log_event_truncated(event, token, "network interface name", token->value, "NAME", /* is_match = */ false);
-                        break;
-                }
+                if (!apply_format_value(event, token, buf, sizeof(buf), "network interface name"))
+                        return true;
 
                 if (IN_SET(event->esc, ESCAPE_UNSET, ESCAPE_REPLACE)) {
                         if (naming_scheme_has(NAMING_REPLACE_STRICTLY))
@@ -2706,7 +2693,6 @@ static int udev_rule_apply_token_to_event(
         }
         case TK_A_DEVLINK: {
                 char buf[UDEV_PATH_SIZE];
-                bool truncated;
                 size_t count;
 
                 if (event->devlink_final)
@@ -2718,12 +2704,10 @@ static int udev_rule_apply_token_to_event(
                 if (IN_SET(token->op, OP_ASSIGN, OP_ASSIGN_FINAL))
                         device_cleanup_devlinks(dev);
 
-                (void) udev_event_apply_format(event, token->value, buf, sizeof(buf),
-                                               /* replace_whitespace = */ event->esc != ESCAPE_NONE, &truncated);
-                if (truncated) {
-                        log_event_truncated(event, token, "symbolic link path", token->value, "SYMLINK", /* is_match = */ false);
-                        break;
-                }
+                if (!apply_format_full(event, token, token->value, buf, sizeof(buf),
+                                       /* replace_whitespace = */ event->esc != ESCAPE_NONE,
+                                       "symbolic link path"))
+                        return true;
 
                 /* By default or string_escape=none, allow multiple symlinks separated by spaces. */
                 if (event->esc == ESCAPE_UNSET)
@@ -2773,10 +2757,10 @@ static int udev_rule_apply_token_to_event(
         case TK_A_ATTR: {
                 char buf[UDEV_PATH_SIZE], value[UDEV_NAME_SIZE];
                 const char *val, *key_name = token->data;
-                bool truncated;
 
                 if (udev_resolve_subsys_kernel(key_name, buf, sizeof(buf), false) < 0 &&
                     sd_device_get_syspath(dev, &val) >= 0) {
+                        bool truncated;
                         strscpyl_full(buf, sizeof(buf), &truncated, val, "/", key_name, NULL);
                         if (truncated) {
                                 log_event_warning(event, token,
@@ -2791,11 +2775,9 @@ static int udev_rule_apply_token_to_event(
                         log_event_error_errno(event, token, r, "Could not find file matches '%s', ignoring: %m", buf);
                         break;
                 }
-                (void) udev_event_apply_format(event, token->value, value, sizeof(value), false, &truncated);
-                if (truncated) {
-                        log_event_truncated(event, token, "attribute value", token->value, "ATTR", /* is_match = */ false);
-                        break;
-                }
+
+                if (!apply_format_value(event, token, value, sizeof(value), "attribute value"))
+                        return true;
 
                 if (EVENT_MODE_DESTRUCTIVE(event)) {
                         log_event_debug(event, token, "Writing ATTR{'%s'}=\"%s\".", buf, value);
@@ -2813,21 +2795,12 @@ static int udev_rule_apply_token_to_event(
         }
         case TK_A_SYSCTL: {
                 char buf[UDEV_PATH_SIZE], value[UDEV_NAME_SIZE];
-                bool truncated;
 
-                (void) udev_event_apply_format(event, token->data, buf, sizeof(buf), false, &truncated);
-                if (truncated) {
-                        log_event_truncated(event, token, "sysctl entry name", token->data, "SYSCTL", /* is_match = */ false);
-                        break;
-                }
+                if (!apply_format_attr(event, token, buf, sizeof(buf), "sysctl entry name"))
+                        return true;
 
-                (void) udev_event_apply_format(event, token->value, value, sizeof(value), false, &truncated);
-                if (truncated) {
-                        _cleanup_free_ char *key_with_name = strjoin("SYSCTL{", buf, "}");
-                        log_event_truncated(event, token, "sysctl value", token->value,
-                                            key_with_name ?: "SYSCTL", /* is_match = */ false);
-                        break;
-                }
+                if (!apply_format_value(event, token, value, sizeof(value), "sysctl value"))
+                        return true;
 
                 sysctl_normalize(buf);
 
@@ -2845,7 +2818,6 @@ static int udev_rule_apply_token_to_event(
         case TK_A_RUN_PROGRAM: {
                 _cleanup_free_ char *cmd = NULL;
                 char buf[UDEV_LINE_SIZE];
-                bool truncated;
 
                 if (event->run_final)
                         break;
@@ -2855,13 +2827,8 @@ static int udev_rule_apply_token_to_event(
                 if (IN_SET(token->op, OP_ASSIGN, OP_ASSIGN_FINAL))
                         ordered_hashmap_clear_free_key(event->run_list);
 
-                (void) udev_event_apply_format(event, token->value, buf, sizeof(buf), false, &truncated);
-                if (truncated) {
-                        log_event_truncated(event, token, "command", token->value,
-                                            token->type == TK_A_RUN_BUILTIN ? "RUN{builtin}" : "RUN{program}",
-                                            /* is_match = */ false);
-                        break;
-                }
+                if (!apply_format_value(event, token, buf, sizeof(buf), "command"))
+                        return true;
 
                 cmd = strdup(buf);
                 if (!cmd)