Re: [PATCH] LSM: Better reporting of actual LSMs at boot

[Paul Moore]

On Tue, Oct 18, 2022 at 2:48 AM Kees Cook <keescook@xxxxxxxxxxxx> wrote:
>
> 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 <paul@xxxxxxxxxxxxxx>
> Cc: James Morris <jmorris@xxxxxxxxx>
> Cc: "Serge E. Hallyn" <serge@xxxxxxxxxx>
> Cc: linux-security-module@xxxxxxxxxxxxxxx
> Signed-off-by: Kees Cook <keescook@xxxxxxxxxxxx>
> ---
>  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 ...

> diff --git a/security/security.c b/security/security.c
> index 9696dd64095e..6f6079dec270 100644
> --- a/security/security.c
> +++ b/security/security.c
> @@ -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"));

> @@ -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.)

> @@ -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 ? "" : ",",
> +                                         (*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?

> @@ -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*");
> +       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?

(This is one of the reasons why it can be nice to see an example of
the output in the commit description.)

-- 
paul-moore.com