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

[Kees Cook <keescook@chromium.org>]

On Tue, Oct 18, 2022 at 05:50:09PM -0400, Paul Moore wrote:
> On Tue, Oct 18, 2022 at 2:48 AM Kees Cook <keescook@chromium.org> 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@paul-moore.com>
> > Cc: James Morris <jmorris@namei.org>
> > Cc: "Serge E. Hallyn" <serge@hallyn.com>
> > Cc: linux-security-module@vger.kernel.org
> > Signed-off-by: Kees Cook <keescook@chromium.org>
> > ---
> >  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) ;)

Fair point. Commit log will be looong. :)

> 
> 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"));

Sure, will do.

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

I prefer "skipped", so I'll update the security= report...

> 
> > @@ -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?

I just kinda dislike pr_cont(), but yeah, it's a lot shorter. :P

 security/security.c |   32 ++++++--------------------------
 1 file changed, 6 insertions(+), 26 deletions(-)

> 
> > @@ -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?

I think of it as "debug" being a "show your work" mode, and the final
list should always be visible.

I will send a v2.

-Kees

-- 
Kees Cook