| Message ID | 20221018064825.never.323-kees@kernel.org (mailing list archive) |
|---|---|
| State | Changes Requested |
| Delegated to: | Paul Moore |
| Headers | show |
| Series | LSM: Better reporting of actual LSMs at boot | expand |
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) ;) 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.)
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
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"); } @@ -222,7 +222,7 @@ static void __init prepare_lsm(struct lsm_info *lsm) if (enabled) { if ((lsm->flags & LSM_FLAG_EXCLUSIVE) && !exclusive) { exclusive = lsm; - init_debug("exclusive chosen: %s\n", lsm->name); + init_debug("exclusive chosen: %s\n", lsm->name); } lsm_set_blob_sizes(lsm->blobs); @@ -250,7 +250,7 @@ static void __init ordered_lsm_parse(const char *order, const char *origin) /* LSM_ORDER_FIRST is always first. */ for (lsm = __start_lsm_info; lsm < __end_lsm_info; lsm++) { if (lsm->order == LSM_ORDER_FIRST) - append_ordered_lsm(lsm, "first"); + append_ordered_lsm(lsm, " first"); } /* Process "security=", if given. */ @@ -289,7 +289,8 @@ static void __init ordered_lsm_parse(const char *order, const char *origin) } if (!found) - init_debug("%s ignored: %s\n", origin, name); + init_debug("%s ignored: %s (not built into kernel)\n", + origin, name); } /* Process "security=", if given. */ @@ -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); } kfree(sep); @@ -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); + kfree(effective); +} + static void __init ordered_lsm_init(void) { struct lsm_info **lsm; @@ -327,7 +367,8 @@ static void __init ordered_lsm_init(void) if (chosen_lsm_order) { if (chosen_major_lsm) { - pr_info("security= is ignored because it is superseded by lsm=\n"); + pr_warn("security=%s is ignored because it is superseded by lsm=%s\n", + chosen_major_lsm, chosen_lsm_order); chosen_major_lsm = NULL; } ordered_lsm_parse(chosen_lsm_order, "cmdline"); @@ -337,6 +378,8 @@ static void __init ordered_lsm_init(void) for (lsm = ordered_lsms; *lsm; lsm++) prepare_lsm(*lsm); + report_lsm_order(); + init_debug("cred blob size = %d\n", blob_sizes.lbs_cred); init_debug("file blob size = %d\n", blob_sizes.lbs_file); init_debug("inode blob size = %d\n", blob_sizes.lbs_inode); @@ -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"); if (lsm->enabled) lsm_append(lsm->name, &lsm_names); }
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(-)