LSM: Better reporting of actual LSMs at boot

Enhance the details reported by "lsm.debug" in several ways:

- report contents of "security="
- report contents of "CONFIG_LSM"
- report contents of "lsm="
- report any early LSM details
- whitespace-align the output of similar phases for easier visual parsing
- change "disabled" to more accurate "skipped"
- explain what "skipped" and "ignored" mean in a parenthetical

Upgrade the "security= is ignored" warning from pr_info to pr_warn, and include full arguments list to make the cause even more clear.

Replace static "Security Framework initializing" pr_info with specific list of the resulting order of enabled LSMs.

Cc Paul Moore <[email protected]>

Cc James Morris <[email protected]>

Cc "Serge E. Hallyn" <[email protected]>

Cc [email protected]

Signed-off-by Kees Cook <[email protected]>

---
 security/security.c | 61 +++++++++++++++++++++++++++++++++++++++------
 1 file changed, 54 insertions(+), 7 deletions(-)

security/security.c +25 -0

@@ -318,6 +320,44 @@ static void __init lsm_early_task(struct task_struct *task);
 
 static int lsm_append(const char *new, char **result);
 
+static void __init report_lsm_order(void)
+{
+       struct lsm_info **lsm, *early;
+       size_t size = 0;
+       char *effective, *step, *end;
+
+       /* Count the length of each enabled LSM name. */
+       for (early = __start_early_lsm_info; early < __end_early_lsm_info; early++)
+               if (is_enabled(early))
+                       size += strlen(early->name) + 1;
+       for (lsm = ordered_lsms; *lsm; lsm++)
+               if (is_enabled(*lsm))
+                       size += strlen((*lsm)->name) + 1;
+
+       /* Allocate space with trailing %NUL or give up. */
+       size += 1;
+       effective = kzalloc(size, GFP_KERNEL);
+       if (!effective)
+               return;
+       end = effective + size;
+       step = effective;
+
+       /* Append each enabled LSM name. */
+       for (early = __start_early_lsm_info; early < __end_early_lsm_info; early++)
+               if (is_enabled(early))

security/security.c +1 -1

@@ -393,13 +436,17 @@ int __init security_init(void)
 {
        struct lsm_info *lsm;
 
-       pr_info("Security Framework initializing\n");
+       init_debug("legacy security=%s\n", chosen_major_lsm ?: " *unspecified*");

Quoted 17 lines · Kees Cook

Enhance the details reported by "lsm.debug" in several ways:

- report contents of "security="
- report contents of "CONFIG_LSM"
- report contents of "lsm="
- report any early LSM details
- whitespace-align the output of similar phases for easier visual parsing
- change "disabled" to more accurate "skipped"
- explain what "skipped" and "ignored" mean in a parenthetical

Upgrade the "security= is ignored" warning from pr_info to pr_warn, and include full arguments list to make the cause even more clear.

Replace static "Security Framework initializing" pr_info with specific list of the resulting order of enabled LSMs.

Quoted 8 lines

Cc Paul Moore <[email protected]>

Cc James Morris <[email protected]>

Cc "Serge E. Hallyn" <[email protected]>

Cc [email protected]

Signed-off-by Kees Cook <[email protected]>

---
 security/security.c | 61 +++++++++++++++++++++++++++++++++++++++------
 1 file changed, 54 insertions(+), 7 deletions(-)

I don't know about you, but when I'm reading commit descriptions about how a patch changes the user visible output of something, e.g. console messages, I always enjoy seeing an example of the new output, both in normal and debug mode (hint, hint) ;)

More comments below ...

security/security.c static void __init append_ordered_lsm(struct lsm_info *lsm, const char *from) · line 163

Quoted 11 lines

security/security.c +1 -1

index 9696dd64095e..6f6079dec270 100644
@@ -159,7 +159,7 @@ static void __init append_ordered_lsm(struct lsm_info *lsm, const char *from)
                lsm->enabled = &lsm_enabled_true;
        ordered_lsms[last_lsm++] = lsm;
 
-       init_debug("%s ordering: %s (%sabled)\n", from, lsm->name,
+       init_debug("%s ordered: %s (%sabled)\n", from, lsm->name,
                   is_enabled(lsm) ? "en" : "dis");

This isn't your fault, but since you're changing this line let's get rid of the "en"/"dis" and do a proper "enabled"/"disabled" string to make it slightly easier to find string while grep'ing through the sources. Example:

  init_debug("... %s\n", (is_enabled(lsm) ? "enabled" : "disabled"));

security/security.c static void __init ordered_lsm_parse(const char *order, const char *origin) · line 312

Quoted 8 lines

security/security.c +2 -1

@@ -307,7 +308,8 @@ static void __init ordered_lsm_parse(const char *order, const char *origin)
                if (exists_ordered_lsm(lsm))
                        continue;
                set_enabled(lsm, false);
-               init_debug("%s disabled: %s\n", origin, lsm->name);
+               init_debug("%s skipped: %s (not in requested order)\n",
+                          origin, lsm->name);

I'm not sure the distinction between "disabled" and "skipped" above is that significant, and in fact I tend to think "disabled" is more appropriate. There is also some (minor) advantage to keeping the user visible log messages consistent.

However, I do think the parenthetical explanations are a nice addition.

(If we did go the "skipped" route, I think we should also change the "security=%s disabled: %s\n" further up the function for the sake of consistent language.)

Quoted 37 lines

security/security.c +32 -0

@@ -318,6 +320,44 @@ static void __init lsm_early_task(struct task_struct *task);
 
 static int lsm_append(const char *new, char **result);
 
+static void __init report_lsm_order(void)
+{
+       struct lsm_info **lsm, *early;
+       size_t size = 0;
+       char *effective, *step, *end;
+
+       /* Count the length of each enabled LSM name. */
+       for (early = __start_early_lsm_info; early < __end_early_lsm_info; early++)
+               if (is_enabled(early))
+                       size += strlen(early->name) + 1;
+       for (lsm = ordered_lsms; *lsm; lsm++)
+               if (is_enabled(*lsm))
+                       size += strlen((*lsm)->name) + 1;
+
+       /* Allocate space with trailing %NUL or give up. */
+       size += 1;
+       effective = kzalloc(size, GFP_KERNEL);
+       if (!effective)
+               return;
+       end = effective + size;
+       step = effective;
+
+       /* Append each enabled LSM name. */
+       for (early = __start_early_lsm_info; early < __end_early_lsm_info; early++)
+               if (is_enabled(early))
+                       step += scnprintf(step, end - step, "%s%s",
+                                         step == effective ? "" : ",",
+                                         early->name);
+       for (lsm = ordered_lsms; *lsm; lsm++)
+               if (is_enabled(*lsm))
+                       step += scnprintf(step, end - step, "%s%s",
+                                         step == effective ? "" : ",",

security/security.c static void __init lsm_early_task(struct task_struct *task); · line 357

Quoted 3 lines

security/security.c +3 -0

+                                         (*lsm)->name);
+
+       pr_info("initializing lsm=%s\n", effective);

Instead of going through all the trouble of determining the string size and formatting the string via a series of scnprintf() calls, why not cut out the intermediate string buffer and use pr_info()/pr_cont()? What am I missing?

Quoted 7 lines

security/security.c +1 -1

@@ -393,13 +436,17 @@ int __init security_init(void)
 {
        struct lsm_info *lsm;
 
-       pr_info("Security Framework initializing\n");
+       init_debug("legacy security=%s\n", chosen_major_lsm ?: " *unspecified*");

security/security.c int __init security_init(void) · line 449

Quoted 10 lines

security/security.c +4 -0

+       init_debug("  CONFIG_LSM=%s\n", builtin_lsm_order);
+       init_debug("boot arg lsm=%s\n", chosen_lsm_order ?: " *unspecified*");
 
        /*
         * Append the names of the early LSM modules now that kmalloc() is
         * available
         */
        for (lsm = __start_early_lsm_info; lsm < __end_early_lsm_info; lsm++) {
+               init_debug("  early started: %s (%sabled)\n", lsm->name,
+                          is_enabled(lsm) ? "en" : "dis");

See the earlier comment about "en"/"dis" versus "enabled"/"disabled".

However, I wonder how useful the above debug message is when you consider report_lsm_order(). Since report_lsm_order() dumps both the early and normal LSMs, perhaps it makes more sense to annotate the output there to indicate early vs normal LSM loading?