2022-12-15 01:35:22

by Connor O'Brien

[permalink] [raw]
Subject: [PATCH bpf-next v2] bpf: btf: limit logging of ignored BTF mismatches

Enabling CONFIG_MODULE_ALLOW_BTF_MISMATCH is an indication that BTF
mismatches are expected and module loading should proceed
anyway. Logging with pr_warn() on every one of these "benign"
mismatches creates unnecessary noise when many such modules are
loaded. Instead, handle this case with a single log warning that BTF
info may be unavailable.

Mismatches also result in calls to __btf_verifier_log() via
__btf_verifier_log_type() or btf_verifier_log_member(), adding several
additional lines of logging per mismatched module. Add checks to these
paths to skip logging for module BTF mismatches in the "allow
mismatch" case.

All existing logging behavior is preserved in the default
CONFIG_MODULE_ALLOW_BTF_MISMATCH=n case.

Signed-off-by: Connor O'Brien <[email protected]>
---
v2:
- Use pr_warn_once instead of skipping logging entirely
- Also skip btf verifier logs for ignored mismatches

v1: https://lore.kernel.org/bpf/[email protected]/
---
kernel/bpf/btf.c | 24 +++++++++++++++++++++---
1 file changed, 21 insertions(+), 3 deletions(-)

diff --git a/kernel/bpf/btf.c b/kernel/bpf/btf.c
index f7dd8af06413..16b959b49595 100644
--- a/kernel/bpf/btf.c
+++ b/kernel/bpf/btf.c
@@ -1404,6 +1404,13 @@ __printf(4, 5) static void __btf_verifier_log_type(struct btf_verifier_env *env,
if (log->level == BPF_LOG_KERNEL && !fmt)
return;

+ /*
+ * Skip logging when loading module BTF with mismatches permitted
+ */
+ if (env->btf->base_btf && env->btf->kernel_btf &&
+ IS_ENABLED(CONFIG_MODULE_ALLOW_BTF_MISMATCH))
+ return;
+
__btf_verifier_log(log, "[%u] %s %s%s",
env->log_type_id,
btf_type_str(t),
@@ -1443,6 +1450,14 @@ static void btf_verifier_log_member(struct btf_verifier_env *env,

if (log->level == BPF_LOG_KERNEL && !fmt)
return;
+
+ /*
+ * Skip logging when loading module BTF with mismatches permitted
+ */
+ if (env->btf->base_btf && env->btf->kernel_btf &&
+ IS_ENABLED(CONFIG_MODULE_ALLOW_BTF_MISMATCH))
+ return;
+
/* The CHECK_META phase already did a btf dump.
*
* If member is logged again, it must hit an error in
@@ -7260,11 +7275,14 @@ static int btf_module_notify(struct notifier_block *nb, unsigned long op,
}
btf = btf_parse_module(mod->name, mod->btf_data, mod->btf_data_size);
if (IS_ERR(btf)) {
- pr_warn("failed to validate module [%s] BTF: %ld\n",
- mod->name, PTR_ERR(btf));
kfree(btf_mod);
- if (!IS_ENABLED(CONFIG_MODULE_ALLOW_BTF_MISMATCH))
+ if (!IS_ENABLED(CONFIG_MODULE_ALLOW_BTF_MISMATCH)) {
+ pr_warn("failed to validate module [%s] BTF: %ld\n",
+ mod->name, PTR_ERR(btf));
err = PTR_ERR(btf);
+ } else {
+ pr_warn_once("Kernel module BTF mismatch detected, BTF debug info may be unavailable for some modules\n");
+ }
goto out;
}
err = btf_alloc_id(btf);
--
2.39.0.rc1.256.g54fd8350bd-goog


2022-12-16 05:54:12

by Yonghong Song

[permalink] [raw]
Subject: Re: [PATCH bpf-next v2] bpf: btf: limit logging of ignored BTF mismatches



On 12/14/22 4:53 PM, Connor O'Brien wrote:
> Enabling CONFIG_MODULE_ALLOW_BTF_MISMATCH is an indication that BTF
> mismatches are expected and module loading should proceed
> anyway. Logging with pr_warn() on every one of these "benign"
> mismatches creates unnecessary noise when many such modules are
> loaded. Instead, handle this case with a single log warning that BTF
> info may be unavailable.
>
> Mismatches also result in calls to __btf_verifier_log() via
> __btf_verifier_log_type() or btf_verifier_log_member(), adding several
> additional lines of logging per mismatched module. Add checks to these
> paths to skip logging for module BTF mismatches in the "allow
> mismatch" case.
>
> All existing logging behavior is preserved in the default
> CONFIG_MODULE_ALLOW_BTF_MISMATCH=n case.
>
> Signed-off-by: Connor O'Brien <[email protected]>

Ack with a few nits below.

Acked-by: Yonghong Song <[email protected]>

> ---
> v2:
> - Use pr_warn_once instead of skipping logging entirely
> - Also skip btf verifier logs for ignored mismatches
>
> v1: https://lore.kernel.org/bpf/[email protected]/
> ---
> kernel/bpf/btf.c | 24 +++++++++++++++++++++---
> 1 file changed, 21 insertions(+), 3 deletions(-)
>
> diff --git a/kernel/bpf/btf.c b/kernel/bpf/btf.c
> index f7dd8af06413..16b959b49595 100644
> --- a/kernel/bpf/btf.c
> +++ b/kernel/bpf/btf.c
> @@ -1404,6 +1404,13 @@ __printf(4, 5) static void __btf_verifier_log_type(struct btf_verifier_env *env,
> if (log->level == BPF_LOG_KERNEL && !fmt)
> return;
>
> + /*
> + * Skip logging when loading module BTF with mismatches permitted
> + */

Just use one line for the above comment.

> + if (env->btf->base_btf && env->btf->kernel_btf &&
> + IS_ENABLED(CONFIG_MODULE_ALLOW_BTF_MISMATCH))
> + return;

I believe env->btf->base_btf alone is enough to test it should be a
module btf. If env->btf->base_btf is true, env->btf->kernel_btf should
also be true. The other way is not true, env->btf->kernel_btf is true,
the btf could be vmlinux (env->btf->base_btf == NULL) or be a module.

> +
> __btf_verifier_log(log, "[%u] %s %s%s",
> env->log_type_id,
> btf_type_str(t),
> @@ -1443,6 +1450,14 @@ static void btf_verifier_log_member(struct btf_verifier_env *env,
>
> if (log->level == BPF_LOG_KERNEL && !fmt)
> return;
> +
> + /*
> + * Skip logging when loading module BTF with mismatches permitted
> + */

Same, just use one line for the above comments.

> + if (env->btf->base_btf && env->btf->kernel_btf &&
> + IS_ENABLED(CONFIG_MODULE_ALLOW_BTF_MISMATCH))
> + return;
> +
> /* The CHECK_META phase already did a btf dump.
> *
> * If member is logged again, it must hit an error in
> @@ -7260,11 +7275,14 @@ static int btf_module_notify(struct notifier_block *nb, unsigned long op,
> }
> btf = btf_parse_module(mod->name, mod->btf_data, mod->btf_data_size);
> if (IS_ERR(btf)) {
> - pr_warn("failed to validate module [%s] BTF: %ld\n",
> - mod->name, PTR_ERR(btf));
> kfree(btf_mod);
> - if (!IS_ENABLED(CONFIG_MODULE_ALLOW_BTF_MISMATCH))
> + if (!IS_ENABLED(CONFIG_MODULE_ALLOW_BTF_MISMATCH)) {
> + pr_warn("failed to validate module [%s] BTF: %ld\n",
> + mod->name, PTR_ERR(btf));
> err = PTR_ERR(btf);
> + } else {
> + pr_warn_once("Kernel module BTF mismatch detected, BTF debug info may be unavailable for some modules\n");
> + }
> goto out;
> }
> err = btf_alloc_id(btf);

2022-12-20 22:27:09

by Andrii Nakryiko

[permalink] [raw]
Subject: Re: [PATCH bpf-next v2] bpf: btf: limit logging of ignored BTF mismatches

On Thu, Dec 15, 2022 at 9:06 PM Yonghong Song <[email protected]> wrote:
>
>
>
> On 12/14/22 4:53 PM, Connor O'Brien wrote:
> > Enabling CONFIG_MODULE_ALLOW_BTF_MISMATCH is an indication that BTF
> > mismatches are expected and module loading should proceed
> > anyway. Logging with pr_warn() on every one of these "benign"
> > mismatches creates unnecessary noise when many such modules are
> > loaded. Instead, handle this case with a single log warning that BTF
> > info may be unavailable.
> >
> > Mismatches also result in calls to __btf_verifier_log() via
> > __btf_verifier_log_type() or btf_verifier_log_member(), adding several
> > additional lines of logging per mismatched module. Add checks to these
> > paths to skip logging for module BTF mismatches in the "allow
> > mismatch" case.
> >
> > All existing logging behavior is preserved in the default
> > CONFIG_MODULE_ALLOW_BTF_MISMATCH=n case.
> >
> > Signed-off-by: Connor O'Brien <[email protected]>
>
> Ack with a few nits below.
>
> Acked-by: Yonghong Song <[email protected]>
>
> > ---
> > v2:
> > - Use pr_warn_once instead of skipping logging entirely
> > - Also skip btf verifier logs for ignored mismatches
> >
> > v1: https://lore.kernel.org/bpf/[email protected]/
> > ---
> > kernel/bpf/btf.c | 24 +++++++++++++++++++++---
> > 1 file changed, 21 insertions(+), 3 deletions(-)
> >
> > diff --git a/kernel/bpf/btf.c b/kernel/bpf/btf.c
> > index f7dd8af06413..16b959b49595 100644
> > --- a/kernel/bpf/btf.c
> > +++ b/kernel/bpf/btf.c
> > @@ -1404,6 +1404,13 @@ __printf(4, 5) static void __btf_verifier_log_type(struct btf_verifier_env *env,
> > if (log->level == BPF_LOG_KERNEL && !fmt)
> > return;
> >
> > + /*
> > + * Skip logging when loading module BTF with mismatches permitted
> > + */
>
> Just use one line for the above comment.
>
> > + if (env->btf->base_btf && env->btf->kernel_btf &&
> > + IS_ENABLED(CONFIG_MODULE_ALLOW_BTF_MISMATCH))
> > + return;
>
> I believe env->btf->base_btf alone is enough to test it should be a
> module btf. If env->btf->base_btf is true, env->btf->kernel_btf should
> also be true. The other way is not true, env->btf->kernel_btf is true,
> the btf could be vmlinux (env->btf->base_btf == NULL) or be a module.
>

Seems like we are also using log->level == BPF_LOG_KERNEL check for
when working with kernel BTFs, so let's stick to the same pattern?


> > +
> > __btf_verifier_log(log, "[%u] %s %s%s",
> > env->log_type_id,
> > btf_type_str(t),
> > @@ -1443,6 +1450,14 @@ static void btf_verifier_log_member(struct btf_verifier_env *env,
> >
> > if (log->level == BPF_LOG_KERNEL && !fmt)
> > return;
> > +
> > + /*
> > + * Skip logging when loading module BTF with mismatches permitted
> > + */
>
> Same, just use one line for the above comments.
>
> > + if (env->btf->base_btf && env->btf->kernel_btf &&
> > + IS_ENABLED(CONFIG_MODULE_ALLOW_BTF_MISMATCH))
> > + return;
> > +
> > /* The CHECK_META phase already did a btf dump.
> > *
> > * If member is logged again, it must hit an error in
> > @@ -7260,11 +7275,14 @@ static int btf_module_notify(struct notifier_block *nb, unsigned long op,
> > }
> > btf = btf_parse_module(mod->name, mod->btf_data, mod->btf_data_size);
> > if (IS_ERR(btf)) {
> > - pr_warn("failed to validate module [%s] BTF: %ld\n",
> > - mod->name, PTR_ERR(btf));
> > kfree(btf_mod);
> > - if (!IS_ENABLED(CONFIG_MODULE_ALLOW_BTF_MISMATCH))
> > + if (!IS_ENABLED(CONFIG_MODULE_ALLOW_BTF_MISMATCH)) {
> > + pr_warn("failed to validate module [%s] BTF: %ld\n",
> > + mod->name, PTR_ERR(btf));
> > err = PTR_ERR(btf);
> > + } else {
> > + pr_warn_once("Kernel module BTF mismatch detected, BTF debug info may be unavailable for some modules\n");
> > + }
> > goto out;
> > }
> > err = btf_alloc_id(btf);