[PATCH bpf-next v2] bpf: Add bpf_check_attach_target_with_klog method to output failure logs to kernel

[PATCH bpf-next v2] bpf: Add bpf_check_attach_target_with_klog method to output failure logs to kernel

[Zheao Li]

This is a v2 patch, previous Link: https://lore.kernel.org/bpf/20240724152521.20546-1-me@manjusaka.me/T/#u

Compare with v1:

1. Format the code style and signed-off field
2. Use a shorter name bpf_check_attach_target_with_klog instead of
original name bpf_check_attach_target_with_kernel_log

When attaching a freplace hook, failures can occur,
but currently, no output is provided to help developers diagnose the root cause.

This commit adds a new method, bpf_check_attach_target_with_klog,
which outputs the verifier log to the kernel.
Developers can then use dmesg to obtain more detailed information about the failure.

For an example of eBPF code,
Link: https://github.com/Asphaltt/learn-by-example/blob/main/ebpf/freplace/main.go

Co-developed-by: Leon Hwang <hffilwlqm@gmail.com>
Signed-off-by: Leon Hwang <hffilwlqm@gmail.com>
Signed-off-by: Zheao Li <me@manjusaka.me>
---
 include/linux/bpf_verifier.h |  5 +++++
 kernel/bpf/syscall.c         |  5 +++--
 kernel/bpf/trampoline.c      |  6 +++---
 kernel/bpf/verifier.c        | 19 +++++++++++++++++++
 4 files changed, 30 insertions(+), 5 deletions(-)

diff --git a/include/linux/bpf_verifier.h b/include/linux/bpf_verifier.h
index 5cea15c81b8a..8eddba62c194 100644
--- a/include/linux/bpf_verifier.h
+++ b/include/linux/bpf_verifier.h
@@ -848,6 +848,11 @@ static inline void bpf_trampoline_unpack_key(u64 key, u32 *obj_id, u32 *btf_id)
 		*btf_id = key & 0x7FFFFFFF;
 }
 
+int bpf_check_attach_target_with_klog(const struct bpf_prog *prog,
+					    const struct bpf_prog *tgt_prog,
+					    u32 btf_id,
+					    struct bpf_attach_target_info *tgt_info);
+
 int bpf_check_attach_target(struct bpf_verifier_log *log,
 			    const struct bpf_prog *prog,
 			    const struct bpf_prog *tgt_prog,
diff --git a/kernel/bpf/syscall.c b/kernel/bpf/syscall.c
index 869265852d51..bf826fcc8cf4 100644
--- a/kernel/bpf/syscall.c
+++ b/kernel/bpf/syscall.c
@@ -3464,8 +3464,9 @@ static int bpf_tracing_prog_attach(struct bpf_prog *prog,
 		 */
 		struct bpf_attach_target_info tgt_info = {};
 
-		err = bpf_check_attach_target(NULL, prog, tgt_prog, btf_id,
-					      &tgt_info);
+		err = bpf_check_attach_target_with_klog(prog, NULL,
+							      prog->aux->attach_btf_id,
+							      &tgt_info);
 		if (err)
 			goto out_unlock;
 
diff --git a/kernel/bpf/trampoline.c b/kernel/bpf/trampoline.c
index f8302a5ca400..8862adaa7302 100644
--- a/kernel/bpf/trampoline.c
+++ b/kernel/bpf/trampoline.c
@@ -699,9 +699,9 @@ int bpf_trampoline_link_cgroup_shim(struct bpf_prog *prog,
 	u64 key;
 	int err;
 
-	err = bpf_check_attach_target(NULL, prog, NULL,
-				      prog->aux->attach_btf_id,
-				      &tgt_info);
+	err = bpf_check_attach_target_with_klog(prog, NULL,
+						      prog->aux->attach_btf_id,
+						      &tgt_info);
 	if (err)
 		return err;
 
diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
index 1f5302fb0957..4873b72f5a9a 100644
--- a/kernel/bpf/verifier.c
+++ b/kernel/bpf/verifier.c
@@ -21643,6 +21643,25 @@ static int check_non_sleepable_error_inject(u32 btf_id)
 	return btf_id_set_contains(&btf_non_sleepable_error_inject, btf_id);
 }
 
+int bpf_check_attach_target_with_klog(const struct bpf_prog *prog,
+					    const struct bpf_prog *tgt_prog,
+					    u32 btf_id,
+					    struct bpf_attach_target_info *tgt_info);
+{
+	struct bpf_verifier_log *log;
+	int err;
+
+	log = kzalloc(sizeof(*log), GFP_KERNEL | __GFP_NOWARN);
+	if (!log) {
+		err = -ENOMEM;
+		return err;
+	}
+	log->level = BPF_LOG_KERNEL;
+	err = bpf_check_attach_target(log, prog, tgt_prog, btf_id, tgt_info);
+	kfree(log);
+	return err;
+}
+
 int bpf_check_attach_target(struct bpf_verifier_log *log,
 			    const struct bpf_prog *prog,
 			    const struct bpf_prog *tgt_prog,
-- 
2.34.1

Re: [PATCH bpf-next v2] bpf: Add bpf_check_attach_target_with_klog method to output failure logs to kernel

[Yonghong Song]

On 7/24/24 10:15 PM, Zheao Li wrote:
> This is a v2 patch, previous Link: https://lore.kernel.org/bpf/20240724152521.20546-1-me@manjusaka.me/T/#u
>
> Compare with v1:
>
> 1. Format the code style and signed-off field
> 2. Use a shorter name bpf_check_attach_target_with_klog instead of
> original name bpf_check_attach_target_with_kernel_log
>
> When attaching a freplace hook, failures can occur,
> but currently, no output is provided to help developers diagnose the root cause.
>
> This commit adds a new method, bpf_check_attach_target_with_klog,
> which outputs the verifier log to the kernel.
> Developers can then use dmesg to obtain more detailed information about the failure.
>
> For an example of eBPF code,
> Link: https://github.com/Asphaltt/learn-by-example/blob/main/ebpf/freplace/main.go
>
> Co-developed-by: Leon Hwang <hffilwlqm@gmail.com>
> Signed-off-by: Leon Hwang <hffilwlqm@gmail.com>
> Signed-off-by: Zheao Li <me@manjusaka.me>
> ---
>   include/linux/bpf_verifier.h |  5 +++++
>   kernel/bpf/syscall.c         |  5 +++--
>   kernel/bpf/trampoline.c      |  6 +++---
>   kernel/bpf/verifier.c        | 19 +++++++++++++++++++
>   4 files changed, 30 insertions(+), 5 deletions(-)
>
> diff --git a/include/linux/bpf_verifier.h b/include/linux/bpf_verifier.h
> index 5cea15c81b8a..8eddba62c194 100644
> --- a/include/linux/bpf_verifier.h
> +++ b/include/linux/bpf_verifier.h
> @@ -848,6 +848,11 @@ static inline void bpf_trampoline_unpack_key(u64 key, u32 *obj_id, u32 *btf_id)
>   		*btf_id = key & 0x7FFFFFFF;
>   }
>   
> +int bpf_check_attach_target_with_klog(const struct bpf_prog *prog,
> +					    const struct bpf_prog *tgt_prog,
> +					    u32 btf_id,
> +					    struct bpf_attach_target_info *tgt_info);

format issue in the above. Same code alignment is needed for arguments in different lines.

> +
>   int bpf_check_attach_target(struct bpf_verifier_log *log,
>   			    const struct bpf_prog *prog,
>   			    const struct bpf_prog *tgt_prog,
> diff --git a/kernel/bpf/syscall.c b/kernel/bpf/syscall.c
> index 869265852d51..bf826fcc8cf4 100644
> --- a/kernel/bpf/syscall.c
> +++ b/kernel/bpf/syscall.c
> @@ -3464,8 +3464,9 @@ static int bpf_tracing_prog_attach(struct bpf_prog *prog,
>   		 */
>   		struct bpf_attach_target_info tgt_info = {};
>   
> -		err = bpf_check_attach_target(NULL, prog, tgt_prog, btf_id,
> -					      &tgt_info);
> +		err = bpf_check_attach_target_with_klog(prog, NULL,
> +							      prog->aux->attach_btf_id,
> +							      &tgt_info);

code alignment issue here as well.
Also, the argument should be 'prog, tgt_prog, btf_id, &tgt_info', right?

>   		if (err)
>   			goto out_unlock;
>   
> diff --git a/kernel/bpf/trampoline.c b/kernel/bpf/trampoline.c
> index f8302a5ca400..8862adaa7302 100644
> --- a/kernel/bpf/trampoline.c
> +++ b/kernel/bpf/trampoline.c
> @@ -699,9 +699,9 @@ int bpf_trampoline_link_cgroup_shim(struct bpf_prog *prog,
>   	u64 key;
>   	int err;
>   
> -	err = bpf_check_attach_target(NULL, prog, NULL,
> -				      prog->aux->attach_btf_id,
> -				      &tgt_info);
> +	err = bpf_check_attach_target_with_klog(prog, NULL,
> +						      prog->aux->attach_btf_id,
> +						      &tgt_info);

code alignment issue here

>   	if (err)
>   		return err;
>   
> diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
> index 1f5302fb0957..4873b72f5a9a 100644
> --- a/kernel/bpf/verifier.c
> +++ b/kernel/bpf/verifier.c
> @@ -21643,6 +21643,25 @@ static int check_non_sleepable_error_inject(u32 btf_id)
>   	return btf_id_set_contains(&btf_non_sleepable_error_inject, btf_id);
>   }
>   
> +int bpf_check_attach_target_with_klog(const struct bpf_prog *prog,
> +					    const struct bpf_prog *tgt_prog,
> +					    u32 btf_id,
> +					    struct bpf_attach_target_info *tgt_info);

code alignment issue here.

> +{
> +	struct bpf_verifier_log *log;
> +	int err;
> +
> +	log = kzalloc(sizeof(*log), GFP_KERNEL | __GFP_NOWARN);

__GFP_NOWARN is unnecessary here.

> +	if (!log) {
> +		err = -ENOMEM;
> +		return err;
> +	}
> +	log->level = BPF_LOG_KERNEL;
> +	err = bpf_check_attach_target(log, prog, tgt_prog, btf_id, tgt_info);
> +	kfree(log);
> +	return err;
> +}
> +
>   int bpf_check_attach_target(struct bpf_verifier_log *log,
>   			    const struct bpf_prog *prog,
>   			    const struct bpf_prog *tgt_prog,

More importantly, Andrii has implemented retsnoop, which intends to locate
precise location in the kernel where err happens. The link is
   https://github.com/anakryiko/retsnoop

Maybe you want to take a look and see whether it can resolve your issue.
We should really avoid putting more stuff in dmesg whenever possible.

Re: [PATCH bpf-next v2] bpf: Add bpf_check_attach_target_with_klog method to output failure logs to kernel

[Leon Hwang]

On 25/7/24 13:54, Yonghong Song wrote:
> 
> On 7/24/24 10:15 PM, Zheao Li wrote:
>> This is a v2 patch, previous Link:
>> https://lore.kernel.org/bpf/20240724152521.20546-1-me@manjusaka.me/T/#u
>>
>> Compare with v1:
>>
>> 1. Format the code style and signed-off field
>> 2. Use a shorter name bpf_check_attach_target_with_klog instead of
>> original name bpf_check_attach_target_with_kernel_log
>>
>> When attaching a freplace hook, failures can occur,
>> but currently, no output is provided to help developers diagnose the
>> root cause.
>>
>> This commit adds a new method, bpf_check_attach_target_with_klog,
>> which outputs the verifier log to the kernel.
>> Developers can then use dmesg to obtain more detailed information
>> about the failure.
>>
>> For an example of eBPF code,
>> Link:
>> https://github.com/Asphaltt/learn-by-example/blob/main/ebpf/freplace/main.go
>>
>> Co-developed-by: Leon Hwang <hffilwlqm@gmail.com>
>> Signed-off-by: Leon Hwang <hffilwlqm@gmail.com>
>> Signed-off-by: Zheao Li <me@manjusaka.me>
>> ---
>>   include/linux/bpf_verifier.h |  5 +++++
>>   kernel/bpf/syscall.c         |  5 +++--
>>   kernel/bpf/trampoline.c      |  6 +++---
>>   kernel/bpf/verifier.c        | 19 +++++++++++++++++++
>>   4 files changed, 30 insertions(+), 5 deletions(-)
>>
>> diff --git a/include/linux/bpf_verifier.h b/include/linux/bpf_verifier.h
>> index 5cea15c81b8a..8eddba62c194 100644
>> --- a/include/linux/bpf_verifier.h
>> +++ b/include/linux/bpf_verifier.h
>> @@ -848,6 +848,11 @@ static inline void bpf_trampoline_unpack_key(u64
>> key, u32 *obj_id, u32 *btf_id)
>>           *btf_id = key & 0x7FFFFFFF;
>>   }
>>   +int bpf_check_attach_target_with_klog(const struct bpf_prog *prog,
>> +                        const struct bpf_prog *tgt_prog,
>> +                        u32 btf_id,
>> +                        struct bpf_attach_target_info *tgt_info);
> 
> format issue in the above. Same code alignment is needed for arguments
> in different lines.
> 
>> +
>>   int bpf_check_attach_target(struct bpf_verifier_log *log,
>>                   const struct bpf_prog *prog,
>>                   const struct bpf_prog *tgt_prog,
>> diff --git a/kernel/bpf/syscall.c b/kernel/bpf/syscall.c
>> index 869265852d51..bf826fcc8cf4 100644
>> --- a/kernel/bpf/syscall.c
>> +++ b/kernel/bpf/syscall.c
>> @@ -3464,8 +3464,9 @@ static int bpf_tracing_prog_attach(struct
>> bpf_prog *prog,
>>            */
>>           struct bpf_attach_target_info tgt_info = {};
>>   -        err = bpf_check_attach_target(NULL, prog, tgt_prog, btf_id,
>> -                          &tgt_info);
>> +        err = bpf_check_attach_target_with_klog(prog, NULL,
>> +                                  prog->aux->attach_btf_id,
>> +                                  &tgt_info);
> 
> code alignment issue here as well.
> Also, the argument should be 'prog, tgt_prog, btf_id, &tgt_info', right?
> 
>>           if (err)
>>               goto out_unlock;
>>   diff --git a/kernel/bpf/trampoline.c b/kernel/bpf/trampoline.c
>> index f8302a5ca400..8862adaa7302 100644
>> --- a/kernel/bpf/trampoline.c
>> +++ b/kernel/bpf/trampoline.c
>> @@ -699,9 +699,9 @@ int bpf_trampoline_link_cgroup_shim(struct
>> bpf_prog *prog,
>>       u64 key;
>>       int err;
>>   -    err = bpf_check_attach_target(NULL, prog, NULL,
>> -                      prog->aux->attach_btf_id,
>> -                      &tgt_info);
>> +    err = bpf_check_attach_target_with_klog(prog, NULL,
>> +                              prog->aux->attach_btf_id,
>> +                              &tgt_info);
> 
> code alignment issue here
> 
>>       if (err)
>>           return err;
>>   diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
>> index 1f5302fb0957..4873b72f5a9a 100644
>> --- a/kernel/bpf/verifier.c
>> +++ b/kernel/bpf/verifier.c
>> @@ -21643,6 +21643,25 @@ static int
>> check_non_sleepable_error_inject(u32 btf_id)
>>       return btf_id_set_contains(&btf_non_sleepable_error_inject,
>> btf_id);
>>   }
>>   +int bpf_check_attach_target_with_klog(const struct bpf_prog *prog,
>> +                        const struct bpf_prog *tgt_prog,
>> +                        u32 btf_id,
>> +                        struct bpf_attach_target_info *tgt_info);
> 
> code alignment issue here.
> 
>> +{
>> +    struct bpf_verifier_log *log;
>> +    int err;
>> +
>> +    log = kzalloc(sizeof(*log), GFP_KERNEL | __GFP_NOWARN);
> 
> __GFP_NOWARN is unnecessary here.
> 
>> +    if (!log) {
>> +        err = -ENOMEM;
>> +        return err;
>> +    }
>> +    log->level = BPF_LOG_KERNEL;
>> +    err = bpf_check_attach_target(log, prog, tgt_prog, btf_id,
>> tgt_info);
>> +    kfree(log);
>> +    return err;
>> +}
>> +
>>   int bpf_check_attach_target(struct bpf_verifier_log *log,
>>                   const struct bpf_prog *prog,
>>                   const struct bpf_prog *tgt_prog,
> 
> More importantly, Andrii has implemented retsnoop, which intends to locate
> precise location in the kernel where err happens. The link is
>   https://github.com/anakryiko/retsnoop
> 
> Maybe you want to take a look and see whether it can resolve your issue.
> We should really avoid putting more stuff in dmesg whenever possible.
> 

retsnoop is really cool.

However, when something wrong in bpf_check_attach_target(), retsnoop
only gets its return value -EINVAL, without any bpf_log() in it. It's
hard to figure out the reason why bpf_check_attach_target() returns -EINVAL.

How about adding a tracepoint in bpf_check_attach_target_with_klog()?
It's to avoid putting stuff in dmesg.

Thanks,
Leon

Re: [PATCH bpf-next v2] bpf: Add bpf_check_attach_target_with_klog method to output failure logs to kernel

[Yonghong Song]

On 7/24/24 11:05 PM, Leon Hwang wrote:
>
> On 25/7/24 13:54, Yonghong Song wrote:
>> On 7/24/24 10:15 PM, Zheao Li wrote:
>>> This is a v2 patch, previous Link:
>>> https://lore.kernel.org/bpf/20240724152521.20546-1-me@manjusaka.me/T/#u
>>>
>>> Compare with v1:
>>>
>>> 1. Format the code style and signed-off field
>>> 2. Use a shorter name bpf_check_attach_target_with_klog instead of
>>> original name bpf_check_attach_target_with_kernel_log
>>>
>>> When attaching a freplace hook, failures can occur,
>>> but currently, no output is provided to help developers diagnose the
>>> root cause.
>>>
>>> This commit adds a new method, bpf_check_attach_target_with_klog,
>>> which outputs the verifier log to the kernel.
>>> Developers can then use dmesg to obtain more detailed information
>>> about the failure.
>>>
>>> For an example of eBPF code,
>>> Link:
>>> https://github.com/Asphaltt/learn-by-example/blob/main/ebpf/freplace/main.go
>>>
>>> Co-developed-by: Leon Hwang <hffilwlqm@gmail.com>
>>> Signed-off-by: Leon Hwang <hffilwlqm@gmail.com>
>>> Signed-off-by: Zheao Li <me@manjusaka.me>
>>> ---
>>>    include/linux/bpf_verifier.h |  5 +++++
>>>    kernel/bpf/syscall.c         |  5 +++--
>>>    kernel/bpf/trampoline.c      |  6 +++---
>>>    kernel/bpf/verifier.c        | 19 +++++++++++++++++++
>>>    4 files changed, 30 insertions(+), 5 deletions(-)
>>>
>>> diff --git a/include/linux/bpf_verifier.h b/include/linux/bpf_verifier.h
>>> index 5cea15c81b8a..8eddba62c194 100644
>>> --- a/include/linux/bpf_verifier.h
>>> +++ b/include/linux/bpf_verifier.h
>>> @@ -848,6 +848,11 @@ static inline void bpf_trampoline_unpack_key(u64
>>> key, u32 *obj_id, u32 *btf_id)
>>>            *btf_id = key & 0x7FFFFFFF;
>>>    }
>>>    +int bpf_check_attach_target_with_klog(const struct bpf_prog *prog,
>>> +                        const struct bpf_prog *tgt_prog,
>>> +                        u32 btf_id,
>>> +                        struct bpf_attach_target_info *tgt_info);
>> format issue in the above. Same code alignment is needed for arguments
>> in different lines.
>>
>>> +
>>>    int bpf_check_attach_target(struct bpf_verifier_log *log,
>>>                    const struct bpf_prog *prog,
>>>                    const struct bpf_prog *tgt_prog,
>>> diff --git a/kernel/bpf/syscall.c b/kernel/bpf/syscall.c
>>> index 869265852d51..bf826fcc8cf4 100644
>>> --- a/kernel/bpf/syscall.c
>>> +++ b/kernel/bpf/syscall.c
>>> @@ -3464,8 +3464,9 @@ static int bpf_tracing_prog_attach(struct
>>> bpf_prog *prog,
>>>             */
>>>            struct bpf_attach_target_info tgt_info = {};
>>>    -        err = bpf_check_attach_target(NULL, prog, tgt_prog, btf_id,
>>> -                          &tgt_info);
>>> +        err = bpf_check_attach_target_with_klog(prog, NULL,
>>> +                                  prog->aux->attach_btf_id,
>>> +                                  &tgt_info);
>> code alignment issue here as well.
>> Also, the argument should be 'prog, tgt_prog, btf_id, &tgt_info', right?
>>
>>>            if (err)
>>>                goto out_unlock;
>>>    diff --git a/kernel/bpf/trampoline.c b/kernel/bpf/trampoline.c
>>> index f8302a5ca400..8862adaa7302 100644
>>> --- a/kernel/bpf/trampoline.c
>>> +++ b/kernel/bpf/trampoline.c
>>> @@ -699,9 +699,9 @@ int bpf_trampoline_link_cgroup_shim(struct
>>> bpf_prog *prog,
>>>        u64 key;
>>>        int err;
>>>    -    err = bpf_check_attach_target(NULL, prog, NULL,
>>> -                      prog->aux->attach_btf_id,
>>> -                      &tgt_info);
>>> +    err = bpf_check_attach_target_with_klog(prog, NULL,
>>> +                              prog->aux->attach_btf_id,
>>> +                              &tgt_info);
>> code alignment issue here
>>
>>>        if (err)
>>>            return err;
>>>    diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
>>> index 1f5302fb0957..4873b72f5a9a 100644
>>> --- a/kernel/bpf/verifier.c
>>> +++ b/kernel/bpf/verifier.c
>>> @@ -21643,6 +21643,25 @@ static int
>>> check_non_sleepable_error_inject(u32 btf_id)
>>>        return btf_id_set_contains(&btf_non_sleepable_error_inject,
>>> btf_id);
>>>    }
>>>    +int bpf_check_attach_target_with_klog(const struct bpf_prog *prog,
>>> +                        const struct bpf_prog *tgt_prog,
>>> +                        u32 btf_id,
>>> +                        struct bpf_attach_target_info *tgt_info);
>> code alignment issue here.
>>
>>> +{
>>> +    struct bpf_verifier_log *log;
>>> +    int err;
>>> +
>>> +    log = kzalloc(sizeof(*log), GFP_KERNEL | __GFP_NOWARN);
>> __GFP_NOWARN is unnecessary here.
>>
>>> +    if (!log) {
>>> +        err = -ENOMEM;
>>> +        return err;
>>> +    }
>>> +    log->level = BPF_LOG_KERNEL;
>>> +    err = bpf_check_attach_target(log, prog, tgt_prog, btf_id,
>>> tgt_info);
>>> +    kfree(log);
>>> +    return err;
>>> +}
>>> +
>>>    int bpf_check_attach_target(struct bpf_verifier_log *log,
>>>                    const struct bpf_prog *prog,
>>>                    const struct bpf_prog *tgt_prog,
>> More importantly, Andrii has implemented retsnoop, which intends to locate
>> precise location in the kernel where err happens. The link is
>>    https://github.com/anakryiko/retsnoop
>>
>> Maybe you want to take a look and see whether it can resolve your issue.
>> We should really avoid putting more stuff in dmesg whenever possible.
>>
> retsnoop is really cool.
>
> However, when something wrong in bpf_check_attach_target(), retsnoop
> only gets its return value -EINVAL, without any bpf_log() in it. It's
> hard to figure out the reason why bpf_check_attach_target() returns -EINVAL.

It should have line number like below in https://github.com/anakryiko/retsnoop

|$ sudo ./retsnoop -e '*sys_bpf' -a ':kernel/bpf/*.c' Receiving data... 
20:19:36.372607 -> 20:19:36.372682 TID/PID 8346/8346 (simfail/simfail): 
entry_SYSCALL_64_after_hwframe+0x63 (arch/x86/entry/entry_64.S:120:0) 
do_syscall_64+0x35 (arch/x86/entry/common.c:80:7) . do_syscall_x64 
(arch/x86/entry/common.c:50:12) 73us [-ENOMEM] __x64_sys_bpf+0x1a 
(kernel/bpf/syscall.c:5067:1) 70us [-ENOMEM] __sys_bpf+0x38b 
(kernel/bpf/syscall.c:4947:9) . map_create (kernel/bpf/syscall.c:1106:8) 
. find_and_alloc_map (kernel/bpf/syscall.c:132:5) ! 50us [-ENOMEM] 
array_map_alloc !* 2us [NULL] bpf_map_alloc_percpu Could you double 
check? It does need corresponding kernel source though. |

>
> How about adding a tracepoint in bpf_check_attach_target_with_klog()?
> It's to avoid putting stuff in dmesg.
>
> Thanks,
> Leon
>
>

Re: [PATCH bpf-next v2] bpf: Add bpf_check_attach_target_with_klog method to output failure logs to kernel

[Manjusaka]

On 2024/7/25 14:09, Yonghong Song wrote:
> 
> On 7/24/24 11:05 PM, Leon Hwang wrote:
>>
>> On 25/7/24 13:54, Yonghong Song wrote:
>>> On 7/24/24 10:15 PM, Zheao Li wrote:
>>>> This is a v2 patch, previous Link:
>>>> https://lore.kernel.org/bpf/20240724152521.20546-1-me@manjusaka.me/T/#u
>>>>
>>>> Compare with v1:
>>>>
>>>> 1. Format the code style and signed-off field
>>>> 2. Use a shorter name bpf_check_attach_target_with_klog instead of
>>>> original name bpf_check_attach_target_with_kernel_log
>>>>
>>>> When attaching a freplace hook, failures can occur,
>>>> but currently, no output is provided to help developers diagnose the
>>>> root cause.
>>>>
>>>> This commit adds a new method, bpf_check_attach_target_with_klog,
>>>> which outputs the verifier log to the kernel.
>>>> Developers can then use dmesg to obtain more detailed information
>>>> about the failure.
>>>>
>>>> For an example of eBPF code,
>>>> Link:
>>>> https://github.com/Asphaltt/learn-by-example/blob/main/ebpf/freplace/main.go
>>>>
>>>> Co-developed-by: Leon Hwang <hffilwlqm@gmail.com>
>>>> Signed-off-by: Leon Hwang <hffilwlqm@gmail.com>
>>>> Signed-off-by: Zheao Li <me@manjusaka.me>
>>>> ---
>>>>    include/linux/bpf_verifier.h |  5 +++++
>>>>    kernel/bpf/syscall.c         |  5 +++--
>>>>    kernel/bpf/trampoline.c      |  6 +++---
>>>>    kernel/bpf/verifier.c        | 19 +++++++++++++++++++
>>>>    4 files changed, 30 insertions(+), 5 deletions(-)
>>>>
>>>> diff --git a/include/linux/bpf_verifier.h b/include/linux/bpf_verifier.h
>>>> index 5cea15c81b8a..8eddba62c194 100644
>>>> --- a/include/linux/bpf_verifier.h
>>>> +++ b/include/linux/bpf_verifier.h
>>>> @@ -848,6 +848,11 @@ static inline void bpf_trampoline_unpack_key(u64
>>>> key, u32 *obj_id, u32 *btf_id)
>>>>            *btf_id = key & 0x7FFFFFFF;
>>>>    }
>>>>    +int bpf_check_attach_target_with_klog(const struct bpf_prog *prog,
>>>> +                        const struct bpf_prog *tgt_prog,
>>>> +                        u32 btf_id,
>>>> +                        struct bpf_attach_target_info *tgt_info);
>>> format issue in the above. Same code alignment is needed for arguments
>>> in different lines.
>>>
>>>> +
>>>>    int bpf_check_attach_target(struct bpf_verifier_log *log,
>>>>                    const struct bpf_prog *prog,
>>>>                    const struct bpf_prog *tgt_prog,
>>>> diff --git a/kernel/bpf/syscall.c b/kernel/bpf/syscall.c
>>>> index 869265852d51..bf826fcc8cf4 100644
>>>> --- a/kernel/bpf/syscall.c
>>>> +++ b/kernel/bpf/syscall.c
>>>> @@ -3464,8 +3464,9 @@ static int bpf_tracing_prog_attach(struct
>>>> bpf_prog *prog,
>>>>             */
>>>>            struct bpf_attach_target_info tgt_info = {};
>>>>    -        err = bpf_check_attach_target(NULL, prog, tgt_prog, btf_id,
>>>> -                          &tgt_info);
>>>> +        err = bpf_check_attach_target_with_klog(prog, NULL,
>>>> +                                  prog->aux->attach_btf_id,
>>>> +                                  &tgt_info);
>>> code alignment issue here as well.
>>> Also, the argument should be 'prog, tgt_prog, btf_id, &tgt_info', right?
>>>
>>>>            if (err)
>>>>                goto out_unlock;
>>>>    diff --git a/kernel/bpf/trampoline.c b/kernel/bpf/trampoline.c
>>>> index f8302a5ca400..8862adaa7302 100644
>>>> --- a/kernel/bpf/trampoline.c
>>>> +++ b/kernel/bpf/trampoline.c
>>>> @@ -699,9 +699,9 @@ int bpf_trampoline_link_cgroup_shim(struct
>>>> bpf_prog *prog,
>>>>        u64 key;
>>>>        int err;
>>>>    -    err = bpf_check_attach_target(NULL, prog, NULL,
>>>> -                      prog->aux->attach_btf_id,
>>>> -                      &tgt_info);
>>>> +    err = bpf_check_attach_target_with_klog(prog, NULL,
>>>> +                              prog->aux->attach_btf_id,
>>>> +                              &tgt_info);
>>> code alignment issue here
>>>
>>>>        if (err)
>>>>            return err;
>>>>    diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
>>>> index 1f5302fb0957..4873b72f5a9a 100644
>>>> --- a/kernel/bpf/verifier.c
>>>> +++ b/kernel/bpf/verifier.c
>>>> @@ -21643,6 +21643,25 @@ static int
>>>> check_non_sleepable_error_inject(u32 btf_id)
>>>>        return btf_id_set_contains(&btf_non_sleepable_error_inject,
>>>> btf_id);
>>>>    }
>>>>    +int bpf_check_attach_target_with_klog(const struct bpf_prog *prog,
>>>> +                        const struct bpf_prog *tgt_prog,
>>>> +                        u32 btf_id,
>>>> +                        struct bpf_attach_target_info *tgt_info);
>>> code alignment issue here.
>>>
>>>> +{
>>>> +    struct bpf_verifier_log *log;
>>>> +    int err;
>>>> +
>>>> +    log = kzalloc(sizeof(*log), GFP_KERNEL | __GFP_NOWARN);
>>> __GFP_NOWARN is unnecessary here.
>>>
>>>> +    if (!log) {
>>>> +        err = -ENOMEM;
>>>> +        return err;
>>>> +    }
>>>> +    log->level = BPF_LOG_KERNEL;
>>>> +    err = bpf_check_attach_target(log, prog, tgt_prog, btf_id,
>>>> tgt_info);
>>>> +    kfree(log);
>>>> +    return err;
>>>> +}
>>>> +
>>>>    int bpf_check_attach_target(struct bpf_verifier_log *log,
>>>>                    const struct bpf_prog *prog,
>>>>                    const struct bpf_prog *tgt_prog,
>>> More importantly, Andrii has implemented retsnoop, which intends to locate
>>> precise location in the kernel where err happens. The link is
>>>    https://github.com/anakryiko/retsnoop
>>>
>>> Maybe you want to take a look and see whether it can resolve your issue.
>>> We should really avoid putting more stuff in dmesg whenever possible.
>>>
>> retsnoop is really cool.
>>
>> However, when something wrong in bpf_check_attach_target(), retsnoop
>> only gets its return value -EINVAL, without any bpf_log() in it. It's
>> hard to figure out the reason why bpf_check_attach_target() returns -EINVAL.
> 
> It should have line number like below in https://github.com/anakryiko/retsnoop
> 
> |$ sudo ./retsnoop -e '*sys_bpf' -a ':kernel/bpf/*.c' Receiving data... 20:19:36.372607 -> 20:19:36.372682 TID/PID 8346/8346 (simfail/simfail): entry_SYSCALL_64_after_hwframe+0x63 (arch/x86/entry/entry_64.S:120:0) do_syscall_64+0x35 (arch/x86/entry/common.c:80:7) . do_syscall_x64 (arch/x86/entry/common.c:50:12) 73us [-ENOMEM] __x64_sys_bpf+0x1a (kernel/bpf/syscall.c:5067:1) 70us [-ENOMEM] __sys_bpf+0x38b (kernel/bpf/syscall.c:4947:9) . map_create (kernel/bpf/syscall.c:1106:8) . find_and_alloc_map (kernel/bpf/syscall.c:132:5) ! 50us [-ENOMEM] array_map_alloc !* 2us [NULL] bpf_map_alloc_percpu Could you double check? It does need corresponding kernel source though. |
> 
>>
>> How about adding a tracepoint in bpf_check_attach_target_with_klog()?
>> It's to avoid putting stuff in dmesg.
>>
>> Thanks,
>> Leon
>>
>>


Thanks for the review and reply. I will update the patch later when we reach the same point

Actually, for personally, I think it would be better to get the error message from dmesg. 

I can get enough information without installing extra dependency

Thanks

Zheao Li/Nadeshiko Manju

Re: [PATCH bpf-next v2] bpf: Add bpf_check_attach_target_with_klog method to output failure logs to kernel

[Alexei Starovoitov]

On Wed, Jul 24, 2024 at 11:33 PM Manjusaka <me@manjusaka.me> wrote:
>
> Actually, for personally, I think it would be better to get the error message from dmesg.

This is a non-starter. We're not going to pollute dmesg with
verifier messages.

Re: [PATCH bpf-next v2] bpf: Add bpf_check_attach_target_with_klog method to output failure logs to kernel

[Leon Hwang]

On 25/7/24 14:09, Yonghong Song wrote:
> 
> On 7/24/24 11:05 PM, Leon Hwang wrote:
>>
>> On 25/7/24 13:54, Yonghong Song wrote:
>>> On 7/24/24 10:15 PM, Zheao Li wrote:
>>>> This is a v2 patch, previous Link:
>>>> https://lore.kernel.org/bpf/20240724152521.20546-1-me@manjusaka.me/T/#u
>>>>
>>>> Compare with v1:
>>>>
>>>> 1. Format the code style and signed-off field
>>>> 2. Use a shorter name bpf_check_attach_target_with_klog instead of
>>>> original name bpf_check_attach_target_with_kernel_log
>>>>
>>>> When attaching a freplace hook, failures can occur,
>>>> but currently, no output is provided to help developers diagnose the
>>>> root cause.
>>>>
>>>> This commit adds a new method, bpf_check_attach_target_with_klog,
>>>> which outputs the verifier log to the kernel.
>>>> Developers can then use dmesg to obtain more detailed information
>>>> about the failure.
>>>>
>>>> For an example of eBPF code,
>>>> Link:
>>>> https://github.com/Asphaltt/learn-by-example/blob/main/ebpf/freplace/main.go
>>>>
>>>> Co-developed-by: Leon Hwang <hffilwlqm@gmail.com>
>>>> Signed-off-by: Leon Hwang <hffilwlqm@gmail.com>
>>>> Signed-off-by: Zheao Li <me@manjusaka.me>
>>>> ---
>>>>    include/linux/bpf_verifier.h |  5 +++++
>>>>    kernel/bpf/syscall.c         |  5 +++--
>>>>    kernel/bpf/trampoline.c      |  6 +++---
>>>>    kernel/bpf/verifier.c        | 19 +++++++++++++++++++
>>>>    4 files changed, 30 insertions(+), 5 deletions(-)
>>>>
>>>> diff --git a/include/linux/bpf_verifier.h
>>>> b/include/linux/bpf_verifier.h
>>>> index 5cea15c81b8a..8eddba62c194 100644
>>>> --- a/include/linux/bpf_verifier.h
>>>> +++ b/include/linux/bpf_verifier.h
>>>> @@ -848,6 +848,11 @@ static inline void bpf_trampoline_unpack_key(u64
>>>> key, u32 *obj_id, u32 *btf_id)
>>>>            *btf_id = key & 0x7FFFFFFF;
>>>>    }
>>>>    +int bpf_check_attach_target_with_klog(const struct bpf_prog *prog,
>>>> +                        const struct bpf_prog *tgt_prog,
>>>> +                        u32 btf_id,
>>>> +                        struct bpf_attach_target_info *tgt_info);
>>> format issue in the above. Same code alignment is needed for arguments
>>> in different lines.
>>>
>>>> +
>>>>    int bpf_check_attach_target(struct bpf_verifier_log *log,
>>>>                    const struct bpf_prog *prog,
>>>>                    const struct bpf_prog *tgt_prog,
>>>> diff --git a/kernel/bpf/syscall.c b/kernel/bpf/syscall.c
>>>> index 869265852d51..bf826fcc8cf4 100644
>>>> --- a/kernel/bpf/syscall.c
>>>> +++ b/kernel/bpf/syscall.c
>>>> @@ -3464,8 +3464,9 @@ static int bpf_tracing_prog_attach(struct
>>>> bpf_prog *prog,
>>>>             */
>>>>            struct bpf_attach_target_info tgt_info = {};
>>>>    -        err = bpf_check_attach_target(NULL, prog, tgt_prog, btf_id,
>>>> -                          &tgt_info);
>>>> +        err = bpf_check_attach_target_with_klog(prog, NULL,
>>>> +                                  prog->aux->attach_btf_id,
>>>> +                                  &tgt_info);
>>> code alignment issue here as well.
>>> Also, the argument should be 'prog, tgt_prog, btf_id, &tgt_info', right?
>>>
>>>>            if (err)
>>>>                goto out_unlock;
>>>>    diff --git a/kernel/bpf/trampoline.c b/kernel/bpf/trampoline.c
>>>> index f8302a5ca400..8862adaa7302 100644
>>>> --- a/kernel/bpf/trampoline.c
>>>> +++ b/kernel/bpf/trampoline.c
>>>> @@ -699,9 +699,9 @@ int bpf_trampoline_link_cgroup_shim(struct
>>>> bpf_prog *prog,
>>>>        u64 key;
>>>>        int err;
>>>>    -    err = bpf_check_attach_target(NULL, prog, NULL,
>>>> -                      prog->aux->attach_btf_id,
>>>> -                      &tgt_info);
>>>> +    err = bpf_check_attach_target_with_klog(prog, NULL,
>>>> +                              prog->aux->attach_btf_id,
>>>> +                              &tgt_info);
>>> code alignment issue here
>>>
>>>>        if (err)
>>>>            return err;
>>>>    diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
>>>> index 1f5302fb0957..4873b72f5a9a 100644
>>>> --- a/kernel/bpf/verifier.c
>>>> +++ b/kernel/bpf/verifier.c
>>>> @@ -21643,6 +21643,25 @@ static int
>>>> check_non_sleepable_error_inject(u32 btf_id)
>>>>        return btf_id_set_contains(&btf_non_sleepable_error_inject,
>>>> btf_id);
>>>>    }
>>>>    +int bpf_check_attach_target_with_klog(const struct bpf_prog *prog,
>>>> +                        const struct bpf_prog *tgt_prog,
>>>> +                        u32 btf_id,
>>>> +                        struct bpf_attach_target_info *tgt_info);
>>> code alignment issue here.
>>>
>>>> +{
>>>> +    struct bpf_verifier_log *log;
>>>> +    int err;
>>>> +
>>>> +    log = kzalloc(sizeof(*log), GFP_KERNEL | __GFP_NOWARN);
>>> __GFP_NOWARN is unnecessary here.
>>>
>>>> +    if (!log) {
>>>> +        err = -ENOMEM;
>>>> +        return err;
>>>> +    }
>>>> +    log->level = BPF_LOG_KERNEL;
>>>> +    err = bpf_check_attach_target(log, prog, tgt_prog, btf_id,
>>>> tgt_info);
>>>> +    kfree(log);
>>>> +    return err;
>>>> +}
>>>> +
>>>>    int bpf_check_attach_target(struct bpf_verifier_log *log,
>>>>                    const struct bpf_prog *prog,
>>>>                    const struct bpf_prog *tgt_prog,
>>> More importantly, Andrii has implemented retsnoop, which intends to
>>> locate
>>> precise location in the kernel where err happens. The link is
>>>    https://github.com/anakryiko/retsnoop
>>>
>>> Maybe you want to take a look and see whether it can resolve your issue.
>>> We should really avoid putting more stuff in dmesg whenever possible.
>>>
>> retsnoop is really cool.
>>
>> However, when something wrong in bpf_check_attach_target(), retsnoop
>> only gets its return value -EINVAL, without any bpf_log() in it. It's
>> hard to figure out the reason why bpf_check_attach_target() returns
>> -EINVAL.
> 
> It should have line number like below in
> https://github.com/anakryiko/retsnoop
> 
> |$ sudo ./retsnoop -e '*sys_bpf' -a ':kernel/bpf/*.c' Receiving data...
> 20:19:36.372607 -> 20:19:36.372682 TID/PID 8346/8346 (simfail/simfail):
> entry_SYSCALL_64_after_hwframe+0x63 (arch/x86/entry/entry_64.S:120:0)
> do_syscall_64+0x35 (arch/x86/entry/common.c:80:7) . do_syscall_x64
> (arch/x86/entry/common.c:50:12) 73us [-ENOMEM] __x64_sys_bpf+0x1a
> (kernel/bpf/syscall.c:5067:1) 70us [-ENOMEM] __sys_bpf+0x38b
> (kernel/bpf/syscall.c:4947:9) . map_create (kernel/bpf/syscall.c:1106:8)
> . find_and_alloc_map (kernel/bpf/syscall.c:132:5) ! 50us [-ENOMEM]
> array_map_alloc !* 2us [NULL] bpf_map_alloc_percpu Could you double
> check? It does need corresponding kernel source though. |
> 

I have a try on an Ubuntu 24.04 VM, whose kernel is 6.8.0-39-generic.

$ sudo retsnoop -e '*sys_bpf' -a ':kernel/bpf/*.c' -T
Receiving data...
07:18:38.643643 -> 07:18:38.643728 TID/PID 6042/6039 (freplace/freplace):

FUNCTION CALL TRACE                                   RESULT
   DURATION
---------------------------------------------------
--------------------  --------
→ __x64_sys_bpf

    → __sys_bpf

        ↔ bpf_check_uarg_tail_zero                    [0]
    2.376us
        → link_create

            ↔ __bpf_prog_get
[0xffffb55f40db3000]   2.796us
            ↔ bpf_prog_attach_check_attach_type       [0]
    2.260us
            → bpf_tracing_prog_attach

                ↔ __bpf_prog_get
[0xffffb55f40d71000]   9.455us
                → bpf_check_attach_target

                    → btf_check_type_match

                        → btf_check_func_type_match

                            ↔ bpf_log                 [void]
    2.578us
                        ← btf_check_func_type_match   [-EINVAL]
    7.659us
                    ← btf_check_type_match            [-EINVAL]
   15.950us
                ← bpf_check_attach_target             [-EINVAL]
   22.397us
                ↔ __bpf_prog_put                      [void]
    2.323us
            ← bpf_tracing_prog_attach                 [-EINVAL]
   45.509us
            ↔ __bpf_prog_put                          [void]
    2.182us
        ← link_create                                 [-EINVAL]
   66.445us
    ← __sys_bpf                                       [-EINVAL]
   77.347us
← __x64_sys_bpf                                       [-EINVAL]
   81.979us

                    entry_SYSCALL_64_after_hwframe+0x78
(arch/x86/entry/entry_64.S:130:0)
                    do_syscall_64+0x7f
(arch/x86/entry/common.c:83:7)
                    . do_syscall_x64
(arch/x86/entry/common.c:52:12)
                    x64_sys_call+0x1936
(arch/x86/entry/syscall_64.c:33:1)
    81us [-EINVAL]  __x64_sys_bpf+0x1a
(kernel/bpf/syscall.c:5588:1)
    77us [-EINVAL]  __sys_bpf+0x4ae
(kernel/bpf/syscall.c:5556:9)
!   66us [-EINVAL]  link_create

!*  45us [-EINVAL]  bpf_tracing_prog_attach

!*  22us [-EINVAL]  bpf_check_attach_target

!*  15us [-EINVAL]  btf_check_type_match

!*   7us [-EINVAL]  btf_check_func_type_match

P.S. Check
https://gist.github.com/Asphaltt/883fd7362968f7747e820d63a9519971 to
have a better view of this output.

When attach freplace prog to a static-noline subprog, there is a
bpf_log() in btf_check_func_type_match(). However, I don't know what
bpf_log() logs.

With this patch, we are able to figure out what bpf_log() logs.
Therefore, we are able to figure out the reason why it fails to attach
freplace prog.

Thanks,
Leon

Re: [PATCH bpf-next v2] bpf: Add bpf_check_attach_target_with_klog method to output failure logs to kernel

[Andrii Nakryiko]

On Thu, Jul 25, 2024 at 12:33 AM Leon Hwang <hffilwlqm@gmail.com> wrote:
>
>
>
> On 25/7/24 14:09, Yonghong Song wrote:
> >
> > On 7/24/24 11:05 PM, Leon Hwang wrote:
> >>
> >> On 25/7/24 13:54, Yonghong Song wrote:
> >>> On 7/24/24 10:15 PM, Zheao Li wrote:
> >>>> This is a v2 patch, previous Link:
> >>>> https://lore.kernel.org/bpf/20240724152521.20546-1-me@manjusaka.me/T/#u
> >>>>
> >>>> Compare with v1:
> >>>>
> >>>> 1. Format the code style and signed-off field
> >>>> 2. Use a shorter name bpf_check_attach_target_with_klog instead of
> >>>> original name bpf_check_attach_target_with_kernel_log
> >>>>
> >>>> When attaching a freplace hook, failures can occur,
> >>>> but currently, no output is provided to help developers diagnose the
> >>>> root cause.
> >>>>
> >>>> This commit adds a new method, bpf_check_attach_target_with_klog,
> >>>> which outputs the verifier log to the kernel.
> >>>> Developers can then use dmesg to obtain more detailed information
> >>>> about the failure.
> >>>>
> >>>> For an example of eBPF code,
> >>>> Link:
> >>>> https://github.com/Asphaltt/learn-by-example/blob/main/ebpf/freplace/main.go
> >>>>
> >>>> Co-developed-by: Leon Hwang <hffilwlqm@gmail.com>
> >>>> Signed-off-by: Leon Hwang <hffilwlqm@gmail.com>
> >>>> Signed-off-by: Zheao Li <me@manjusaka.me>
> >>>> ---
> >>>>    include/linux/bpf_verifier.h |  5 +++++
> >>>>    kernel/bpf/syscall.c         |  5 +++--
> >>>>    kernel/bpf/trampoline.c      |  6 +++---
> >>>>    kernel/bpf/verifier.c        | 19 +++++++++++++++++++
> >>>>    4 files changed, 30 insertions(+), 5 deletions(-)
> >>>>
> >>>> diff --git a/include/linux/bpf_verifier.h
> >>>> b/include/linux/bpf_verifier.h
> >>>> index 5cea15c81b8a..8eddba62c194 100644
> >>>> --- a/include/linux/bpf_verifier.h
> >>>> +++ b/include/linux/bpf_verifier.h
> >>>> @@ -848,6 +848,11 @@ static inline void bpf_trampoline_unpack_key(u64
> >>>> key, u32 *obj_id, u32 *btf_id)
> >>>>            *btf_id = key & 0x7FFFFFFF;
> >>>>    }
> >>>>    +int bpf_check_attach_target_with_klog(const struct bpf_prog *prog,
> >>>> +                        const struct bpf_prog *tgt_prog,
> >>>> +                        u32 btf_id,
> >>>> +                        struct bpf_attach_target_info *tgt_info);
> >>> format issue in the above. Same code alignment is needed for arguments
> >>> in different lines.
> >>>
> >>>> +
> >>>>    int bpf_check_attach_target(struct bpf_verifier_log *log,
> >>>>                    const struct bpf_prog *prog,
> >>>>                    const struct bpf_prog *tgt_prog,
> >>>> diff --git a/kernel/bpf/syscall.c b/kernel/bpf/syscall.c
> >>>> index 869265852d51..bf826fcc8cf4 100644
> >>>> --- a/kernel/bpf/syscall.c
> >>>> +++ b/kernel/bpf/syscall.c
> >>>> @@ -3464,8 +3464,9 @@ static int bpf_tracing_prog_attach(struct
> >>>> bpf_prog *prog,
> >>>>             */
> >>>>            struct bpf_attach_target_info tgt_info = {};
> >>>>    -        err = bpf_check_attach_target(NULL, prog, tgt_prog, btf_id,
> >>>> -                          &tgt_info);
> >>>> +        err = bpf_check_attach_target_with_klog(prog, NULL,
> >>>> +                                  prog->aux->attach_btf_id,
> >>>> +                                  &tgt_info);
> >>> code alignment issue here as well.
> >>> Also, the argument should be 'prog, tgt_prog, btf_id, &tgt_info', right?
> >>>
> >>>>            if (err)
> >>>>                goto out_unlock;
> >>>>    diff --git a/kernel/bpf/trampoline.c b/kernel/bpf/trampoline.c
> >>>> index f8302a5ca400..8862adaa7302 100644
> >>>> --- a/kernel/bpf/trampoline.c
> >>>> +++ b/kernel/bpf/trampoline.c
> >>>> @@ -699,9 +699,9 @@ int bpf_trampoline_link_cgroup_shim(struct
> >>>> bpf_prog *prog,
> >>>>        u64 key;
> >>>>        int err;
> >>>>    -    err = bpf_check_attach_target(NULL, prog, NULL,
> >>>> -                      prog->aux->attach_btf_id,
> >>>> -                      &tgt_info);
> >>>> +    err = bpf_check_attach_target_with_klog(prog, NULL,
> >>>> +                              prog->aux->attach_btf_id,
> >>>> +                              &tgt_info);
> >>> code alignment issue here
> >>>
> >>>>        if (err)
> >>>>            return err;
> >>>>    diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
> >>>> index 1f5302fb0957..4873b72f5a9a 100644
> >>>> --- a/kernel/bpf/verifier.c
> >>>> +++ b/kernel/bpf/verifier.c
> >>>> @@ -21643,6 +21643,25 @@ static int
> >>>> check_non_sleepable_error_inject(u32 btf_id)
> >>>>        return btf_id_set_contains(&btf_non_sleepable_error_inject,
> >>>> btf_id);
> >>>>    }
> >>>>    +int bpf_check_attach_target_with_klog(const struct bpf_prog *prog,
> >>>> +                        const struct bpf_prog *tgt_prog,
> >>>> +                        u32 btf_id,
> >>>> +                        struct bpf_attach_target_info *tgt_info);
> >>> code alignment issue here.
> >>>
> >>>> +{
> >>>> +    struct bpf_verifier_log *log;
> >>>> +    int err;
> >>>> +
> >>>> +    log = kzalloc(sizeof(*log), GFP_KERNEL | __GFP_NOWARN);
> >>> __GFP_NOWARN is unnecessary here.
> >>>
> >>>> +    if (!log) {
> >>>> +        err = -ENOMEM;
> >>>> +        return err;
> >>>> +    }
> >>>> +    log->level = BPF_LOG_KERNEL;
> >>>> +    err = bpf_check_attach_target(log, prog, tgt_prog, btf_id,
> >>>> tgt_info);
> >>>> +    kfree(log);
> >>>> +    return err;
> >>>> +}
> >>>> +
> >>>>    int bpf_check_attach_target(struct bpf_verifier_log *log,
> >>>>                    const struct bpf_prog *prog,
> >>>>                    const struct bpf_prog *tgt_prog,
> >>> More importantly, Andrii has implemented retsnoop, which intends to
> >>> locate
> >>> precise location in the kernel where err happens. The link is
> >>>    https://github.com/anakryiko/retsnoop
> >>>
> >>> Maybe you want to take a look and see whether it can resolve your issue.
> >>> We should really avoid putting more stuff in dmesg whenever possible.
> >>>
> >> retsnoop is really cool.
> >>
> >> However, when something wrong in bpf_check_attach_target(), retsnoop
> >> only gets its return value -EINVAL, without any bpf_log() in it. It's
> >> hard to figure out the reason why bpf_check_attach_target() returns
> >> -EINVAL.
> >
> > It should have line number like below in
> > https://github.com/anakryiko/retsnoop
> >
> > |$ sudo ./retsnoop -e '*sys_bpf' -a ':kernel/bpf/*.c' Receiving data...
> > 20:19:36.372607 -> 20:19:36.372682 TID/PID 8346/8346 (simfail/simfail):
> > entry_SYSCALL_64_after_hwframe+0x63 (arch/x86/entry/entry_64.S:120:0)
> > do_syscall_64+0x35 (arch/x86/entry/common.c:80:7) . do_syscall_x64
> > (arch/x86/entry/common.c:50:12) 73us [-ENOMEM] __x64_sys_bpf+0x1a
> > (kernel/bpf/syscall.c:5067:1) 70us [-ENOMEM] __sys_bpf+0x38b
> > (kernel/bpf/syscall.c:4947:9) . map_create (kernel/bpf/syscall.c:1106:8)
> > . find_and_alloc_map (kernel/bpf/syscall.c:132:5) ! 50us [-ENOMEM]
> > array_map_alloc !* 2us [NULL] bpf_map_alloc_percpu Could you double
> > check? It does need corresponding kernel source though. |
> >
>
> I have a try on an Ubuntu 24.04 VM, whose kernel is 6.8.0-39-generic.
>
> $ sudo retsnoop -e '*sys_bpf' -a ':kernel/bpf/*.c' -T
> Receiving data...
> 07:18:38.643643 -> 07:18:38.643728 TID/PID 6042/6039 (freplace/freplace):
>
> FUNCTION CALL TRACE                                   RESULT
>    DURATION
> ---------------------------------------------------
> --------------------  --------
> → __x64_sys_bpf
>
>     → __sys_bpf
>
>         ↔ bpf_check_uarg_tail_zero                    [0]
>     2.376us
>         → link_create
>
>             ↔ __bpf_prog_get
> [0xffffb55f40db3000]   2.796us
>             ↔ bpf_prog_attach_check_attach_type       [0]
>     2.260us
>             → bpf_tracing_prog_attach
>
>                 ↔ __bpf_prog_get
> [0xffffb55f40d71000]   9.455us
>                 → bpf_check_attach_target
>
>                     → btf_check_type_match
>
>                         → btf_check_func_type_match
>
>                             ↔ bpf_log                 [void]
>     2.578us
>                         ← btf_check_func_type_match   [-EINVAL]
>     7.659us
>                     ← btf_check_type_match            [-EINVAL]
>    15.950us
>                 ← bpf_check_attach_target             [-EINVAL]
>    22.397us
>                 ↔ __bpf_prog_put                      [void]
>     2.323us
>             ← bpf_tracing_prog_attach                 [-EINVAL]
>    45.509us
>             ↔ __bpf_prog_put                          [void]
>     2.182us
>         ← link_create                                 [-EINVAL]
>    66.445us
>     ← __sys_bpf                                       [-EINVAL]
>    77.347us
> ← __x64_sys_bpf                                       [-EINVAL]
>    81.979us
>
>                     entry_SYSCALL_64_after_hwframe+0x78
> (arch/x86/entry/entry_64.S:130:0)
>                     do_syscall_64+0x7f
> (arch/x86/entry/common.c:83:7)
>                     . do_syscall_x64
> (arch/x86/entry/common.c:52:12)
>                     x64_sys_call+0x1936
> (arch/x86/entry/syscall_64.c:33:1)
>     81us [-EINVAL]  __x64_sys_bpf+0x1a
> (kernel/bpf/syscall.c:5588:1)
>     77us [-EINVAL]  __sys_bpf+0x4ae
> (kernel/bpf/syscall.c:5556:9)
> !   66us [-EINVAL]  link_create
>
> !*  45us [-EINVAL]  bpf_tracing_prog_attach
>
> !*  22us [-EINVAL]  bpf_check_attach_target
>
> !*  15us [-EINVAL]  btf_check_type_match
>
> !*   7us [-EINVAL]  btf_check_func_type_match
>
> P.S. Check
> https://gist.github.com/Asphaltt/883fd7362968f7747e820d63a9519971 to
> have a better view of this output.
>
> When attach freplace prog to a static-noline subprog, there is a
> bpf_log() in btf_check_func_type_match(). However, I don't know what
> bpf_log() logs.

If you build the very latest retsnoop from Github (this functionality
hasn't been released just yet, I added it literally two days ago), you
will be able to capture bpf_log's format string. vararg arguments
themselves are not (yet) captured, but I'm going to play with that.

Try something like this:

sudo ./retsnoop -e verbose -e bpf_log -e bpf_verifier_vlog -e
bpf_verifier_log_write -STA -v

And you might see something like:

FUNCTION CALLS   RESULT  DURATION  ARGS
--------------   ------  --------  ----
↔ bpf_log        [void]   2.555us  log=&{} fmt='func '%s' arg%d has
btf_id %d type %s '%s' ' =(vararg)

or

FUNCTION CALLS   RESULT  DURATION  ARGS
--------------   ------  --------  ----
↔ bpf_log        [void]   5.729us  log=&{} fmt='arg#%d reference
type('%s %s') size cannot be determined: %ld ' =(vararg)


So you'll get a general understanding from format string (but yeah,
actual arguments would be good to have).


This is not really a solution, but definitely useful for debugging.

Is there some simple way for me to reproduce your specific issue, I'd
like to use that as one motivating example to see how far retsnoop can
be pushed.

P.S. I do think that putting any logging like this into dmesg is
definitely wrong, btw.

>
> With this patch, we are able to figure out what bpf_log() logs.
> Therefore, we are able to figure out the reason why it fails to attach
> freplace prog.
>
> Thanks,
> Leon
>

Re: [PATCH bpf-next v2] bpf: Add bpf_check_attach_target_with_klog method to output failure logs to kernel

[Leon Hwang]

On 26/7/24 05:27, Andrii Nakryiko wrote:
> On Thu, Jul 25, 2024 at 12:33 AM Leon Hwang <hffilwlqm@gmail.com> wrote:
>>
>>
>>
>> On 25/7/24 14:09, Yonghong Song wrote:
>>>
>>> On 7/24/24 11:05 PM, Leon Hwang wrote:
>>>>
>>>> On 25/7/24 13:54, Yonghong Song wrote:
>>>>> On 7/24/24 10:15 PM, Zheao Li wrote:
>>>>>> This is a v2 patch, previous Link:
>>>>>> https://lore.kernel.org/bpf/20240724152521.20546-1-me@manjusaka.me/T/#u
>>>>>>

[SNI]

>>>>> More importantly, Andrii has implemented retsnoop, which intends to
>>>>> locate
>>>>> precise location in the kernel where err happens. The link is
>>>>>    https://github.com/anakryiko/retsnoop
>>>>>
>>>>> Maybe you want to take a look and see whether it can resolve your issue.
>>>>> We should really avoid putting more stuff in dmesg whenever possible.
>>>>>
>>>> retsnoop is really cool.
>>>>
>>>> However, when something wrong in bpf_check_attach_target(), retsnoop
>>>> only gets its return value -EINVAL, without any bpf_log() in it. It's
>>>> hard to figure out the reason why bpf_check_attach_target() returns
>>>> -EINVAL.
>>>
>>> It should have line number like below in
>>> https://github.com/anakryiko/retsnoop
>>>
>>> |$ sudo ./retsnoop -e '*sys_bpf' -a ':kernel/bpf/*.c' Receiving data...
>>> 20:19:36.372607 -> 20:19:36.372682 TID/PID 8346/8346 (simfail/simfail):
>>> entry_SYSCALL_64_after_hwframe+0x63 (arch/x86/entry/entry_64.S:120:0)
>>> do_syscall_64+0x35 (arch/x86/entry/common.c:80:7) . do_syscall_x64
>>> (arch/x86/entry/common.c:50:12) 73us [-ENOMEM] __x64_sys_bpf+0x1a
>>> (kernel/bpf/syscall.c:5067:1) 70us [-ENOMEM] __sys_bpf+0x38b
>>> (kernel/bpf/syscall.c:4947:9) . map_create (kernel/bpf/syscall.c:1106:8)
>>> . find_and_alloc_map (kernel/bpf/syscall.c:132:5) ! 50us [-ENOMEM]
>>> array_map_alloc !* 2us [NULL] bpf_map_alloc_percpu Could you double
>>> check? It does need corresponding kernel source though. |
>>>
>>
>> I have a try on an Ubuntu 24.04 VM, whose kernel is 6.8.0-39-generic.
>>
>> $ sudo retsnoop -e '*sys_bpf' -a ':kernel/bpf/*.c' -T
>> Receiving data...
>> 07:18:38.643643 -> 07:18:38.643728 TID/PID 6042/6039 (freplace/freplace):
>>
>> FUNCTION CALL TRACE                                   RESULT
>>    DURATION
>> ---------------------------------------------------
>> --------------------  --------
>> → __x64_sys_bpf
>>
>>     → __sys_bpf
>>
>>         ↔ bpf_check_uarg_tail_zero                    [0]
>>     2.376us
>>         → link_create
>>
>>             ↔ __bpf_prog_get
>> [0xffffb55f40db3000]   2.796us
>>             ↔ bpf_prog_attach_check_attach_type       [0]
>>     2.260us
>>             → bpf_tracing_prog_attach
>>
>>                 ↔ __bpf_prog_get
>> [0xffffb55f40d71000]   9.455us
>>                 → bpf_check_attach_target
>>
>>                     → btf_check_type_match
>>
>>                         → btf_check_func_type_match
>>
>>                             ↔ bpf_log                 [void]
>>     2.578us
>>                         ← btf_check_func_type_match   [-EINVAL]
>>     7.659us
>>                     ← btf_check_type_match            [-EINVAL]
>>    15.950us
>>                 ← bpf_check_attach_target             [-EINVAL]
>>    22.397us
>>                 ↔ __bpf_prog_put                      [void]
>>     2.323us
>>             ← bpf_tracing_prog_attach                 [-EINVAL]
>>    45.509us
>>             ↔ __bpf_prog_put                          [void]
>>     2.182us
>>         ← link_create                                 [-EINVAL]
>>    66.445us
>>     ← __sys_bpf                                       [-EINVAL]
>>    77.347us
>> ← __x64_sys_bpf                                       [-EINVAL]
>>    81.979us
>>
>>                     entry_SYSCALL_64_after_hwframe+0x78
>> (arch/x86/entry/entry_64.S:130:0)
>>                     do_syscall_64+0x7f
>> (arch/x86/entry/common.c:83:7)
>>                     . do_syscall_x64
>> (arch/x86/entry/common.c:52:12)
>>                     x64_sys_call+0x1936
>> (arch/x86/entry/syscall_64.c:33:1)
>>     81us [-EINVAL]  __x64_sys_bpf+0x1a
>> (kernel/bpf/syscall.c:5588:1)
>>     77us [-EINVAL]  __sys_bpf+0x4ae
>> (kernel/bpf/syscall.c:5556:9)
>> !   66us [-EINVAL]  link_create
>>
>> !*  45us [-EINVAL]  bpf_tracing_prog_attach
>>
>> !*  22us [-EINVAL]  bpf_check_attach_target
>>
>> !*  15us [-EINVAL]  btf_check_type_match
>>
>> !*   7us [-EINVAL]  btf_check_func_type_match
>>
>> P.S. Check
>> https://gist.github.com/Asphaltt/883fd7362968f7747e820d63a9519971 to
>> have a better view of this output.
>>
>> When attach freplace prog to a static-noline subprog, there is a
>> bpf_log() in btf_check_func_type_match(). However, I don't know what
>> bpf_log() logs.
> 
> If you build the very latest retsnoop from Github (this functionality
> hasn't been released just yet, I added it literally two days ago), you
> will be able to capture bpf_log's format string. vararg arguments
> themselves are not (yet) captured, but I'm going to play with that.
> 
> Try something like this:
> 
> sudo ./retsnoop -e verbose -e bpf_log -e bpf_verifier_vlog -e
> bpf_verifier_log_write -STA -v
> 
> And you might see something like:
> 
> FUNCTION CALLS   RESULT  DURATION  ARGS
> --------------   ------  --------  ----
> ↔ bpf_log        [void]   2.555us  log=&{} fmt='func '%s' arg%d has
> btf_id %d type %s '%s' ' =(vararg)
> 
> or
> 
> FUNCTION CALLS   RESULT  DURATION  ARGS
> --------------   ------  --------  ----
> ↔ bpf_log        [void]   5.729us  log=&{} fmt='arg#%d reference
> type('%s %s') size cannot be determined: %ld ' =(vararg)
> 
> 
> So you'll get a general understanding from format string (but yeah,
> actual arguments would be good to have).
> 

Build and run, sudo ./retsnoop -e verbose -e bpf_log -e
bpf_verifier_vlog -e bpf_verifier_log_write -STA -v, here's the output:


FUNCTION CALLS   RESULT  DURATION  ARGS
--------------   ------  --------  ----
↔ bpf_log        [void]   1.350us  log=NULL fmt='%s() is not a global
function ' =(vararg)

It's great to show arguments.

> 
> This is not really a solution, but definitely useful for debugging.

I try another way with following bpf code:

#include "vmlinux.h"
#include <bpf/bpf_helpers.h>
#include <bpf/bpf_tracing.h>

SEC("kprobe/bpf_log")
int k_bpf_log(struct pt_regs *ctx)
{
    const char *arg2 = (const char *) PT_REGS_PARM2(ctx);
    void *arg3 = (void *) PT_REGS_PARM3(ctx);
    void *arg4 = (void *) PT_REGS_PARM4(ctx);
    void *arg5 = (void *) PT_REGS_PARM5(ctx);
    char buf[30];

    bpf_probe_read_kernel_str(buf, 30, arg2);
    bpf_trace_printk(buf, 30, arg3, arg4, arg5);

    return BPF_OK;
}

It is able to print the log message:
<...>-6212    [003] ...21  3585.117121: bpf_trace_printk:
stub_handler_static() is not a global function

But it's not generic enough to inspect the log.

> 
> Is there some simple way for me to reproduce your specific issue, I'd
> like to use that as one motivating example to see how far retsnoop can
> be pushed.

Sure, here's my example to reproduce the issue:
https://github.com/Asphaltt/learn-by-example/tree/main/ebpf/freplace,
which relies on Go, clang and llvm-strip.

Reproduce the issue by:

git clone https://github.com/Asphaltt/learn-by-example.git
cd learn-by-example/ebpf/freplace
go generate
go build
./freplace --freplace-failed

Then, it will output something like:
2024/07/26 01:45:43 Failed to freplace(stub_handler_static): create
link: invalid argument

> 
> P.S. I do think that putting any logging like this into dmesg is
> definitely wrong, btw.
> 

Understand.

Is it OK to add a tracepoint here? I think tracepoint is more generic
than retsnoop-like way.

Thanks,
Leon

Re: [PATCH bpf-next v2] bpf: Add bpf_check_attach_target_with_klog method to output failure logs to kernel

[Andrii Nakryiko]

On Thu, Jul 25, 2024 at 7:57 PM Leon Hwang <hffilwlqm@gmail.com> wrote:
>
>
>
> On 26/7/24 05:27, Andrii Nakryiko wrote:
> > On Thu, Jul 25, 2024 at 12:33 AM Leon Hwang <hffilwlqm@gmail.com> wrote:
> >>
> >>
> >>
> >> On 25/7/24 14:09, Yonghong Song wrote:
> >>>
> >>> On 7/24/24 11:05 PM, Leon Hwang wrote:
> >>>>
> >>>> On 25/7/24 13:54, Yonghong Song wrote:
> >>>>> On 7/24/24 10:15 PM, Zheao Li wrote:
> >>>>>> This is a v2 patch, previous Link:
> >>>>>> https://lore.kernel.org/bpf/20240724152521.20546-1-me@manjusaka.me/T/#u
> >>>>>>
>
> [SNI]
>

[...]

> >
>
> Build and run, sudo ./retsnoop -e verbose -e bpf_log -e
> bpf_verifier_vlog -e bpf_verifier_log_write -STA -v, here's the output:
>
>
> FUNCTION CALLS   RESULT  DURATION  ARGS
> --------------   ------  --------  ----
> ↔ bpf_log        [void]   1.350us  log=NULL fmt='%s() is not a global
> function ' =(vararg)
>
> It's great to show arguments.
>

Thanks for repro steps, they worked. Also, I just pushed latest
retsnoop version to Github that does support capturing vararg
arguments for printf-like functions. See full debugging log at [0],
but I basically did just two things:

$ sudo retsnoop -e '*sys_bpf' --lbr -n freplace

-n freplace filters by process name, to avoid the noise. I traced
bpf() syscall (*sys_bf), and I requested function call LBR (Last
Branch Record) stack. LBR showed that we have
bpf_prog_attach_check_attach_type() call, and then eventually we get
to bpf_log().

So I then traced bpf_log (no --lbr this time, but I requested function
trace + arguments capture:

$ sudo retsnoop -n freplace -e '*sys_bpf' -a bpf_log -TA

17:02:39.968302 -> 17:02:39.968307 TID/PID 2730863/2730855 (freplace/freplace):

FUNCTION CALLS      RESULT     DURATION  ARGS
-----------------   ---------  --------  ----
→ __x64_sys_bpf
regs=&{.r15=2,.r14=0xc0000061c0,.bp=0xc00169f8a8,.bx=28,.r11=514,.ax=0xffffffffffffffda,.cx=0x404f4e,.dx=64,.si=0xc00169fa10…
    → __sys_bpf                          cmd=28
uattr={{.kernel=0xc00169fa10,.user=0xc00169fa10}} size=64
        ↔ bpf_log   [void]      1.550us  log=NULL fmt='%s() is not a
global function ' vararg0='stub_handler_static'
    ← __sys_bpf     [-EINVAL]   4.115us
← __x64_sys_bpf     [-EINVAL]   5.467us


For __x64_sys_bpf that's struct pt_regs, which isn't that interesting,
but then we have:

↔ bpf_log   [void]      1.550us  log=NULL fmt='%s() is not a global
function ' vararg0='stub_handler_static'

Which showed format string and the argument passed to it:
'stub_hanler_static' subprogram seems to be the problem here.


Anyways, tbh, for a problem like this, it's probably best to just
request a verbose log when doing the BPF_PROG_LOAD command. You can
*normally* use veristat tool to get that easily, if you have a .bpf.o
object file on the disk. But in this case it's freplace and veristat
doesn't know what's the target BPF program, so it's not that useful in
this case:

$ sudo veristat -v freplace_bpfel.o
Processing 'freplace_bpfel.o'...
libbpf: prog 'freplace_handler': attach program FD is not set
libbpf: prog 'freplace_handler': failed to prepare load attributes: -22
libbpf: prog 'freplace_handler': failed to load: -22
libbpf: failed to load object 'freplace_bpfel.o'
PROCESSING freplace_bpfel.o/freplace_handler, DURATION US: 0, VERDICT:
failure, VERIFIER LOG:

File              Program           Verdict  Duration (us)  Insns
States  Peak states
----------------  ----------------  -------  -------------  -----
------  -----------
freplace_bpfel.o  freplace_handler  failure              0      0
 0            0
----------------  ----------------  -------  -------------  -----
------  -----------
Done. Processed 1 files, 0 programs. Skipped 1 files, 0 programs.

But for lots of other programs this would be a no-brainer.


  [0] https://gist.github.com/anakryiko/88a1597a68e43dc945e40fde88a96e7e

[...]

>
> Is it OK to add a tracepoint here? I think tracepoint is more generic
> than retsnoop-like way.

I personally don't see a problem with adding tracepoint, but how would
it look like, given we are talking about vararg printf-style function
calls? I'm not sure how that should be represented in such a way as to
make it compatible with tracepoints and not cause any runtime
overhead.

>
> Thanks,
> Leon
>
>

Re: [PATCH bpf-next v2] bpf: Add bpf_check_attach_target_with_klog method to output failure logs to kernel

[Leon Hwang]

On 2024/7/27 08:12, Andrii Nakryiko wrote:
> On Thu, Jul 25, 2024 at 7:57 PM Leon Hwang <hffilwlqm@gmail.com> wrote:
>>
>>
>>
>> On 26/7/24 05:27, Andrii Nakryiko wrote:
>>> On Thu, Jul 25, 2024 at 12:33 AM Leon Hwang <hffilwlqm@gmail.com> wrote:
>>>>
>>>>
>>>>
>>>> On 25/7/24 14:09, Yonghong Song wrote:
>>>>>
>>>>> On 7/24/24 11:05 PM, Leon Hwang wrote:
>>>>>>
>>>>>> On 25/7/24 13:54, Yonghong Song wrote:
>>>>>>> On 7/24/24 10:15 PM, Zheao Li wrote:
>>>>>>>> This is a v2 patch, previous Link:
>>>>>>>> https://lore.kernel.org/bpf/20240724152521.20546-1-me@manjusaka.me/T/#u
>>>>>>>>
>>
>> [SNI]
>>
> 
> [...]
> 
>>>
>>
>> Build and run, sudo ./retsnoop -e verbose -e bpf_log -e
>> bpf_verifier_vlog -e bpf_verifier_log_write -STA -v, here's the output:
>>
>>
>> FUNCTION CALLS   RESULT  DURATION  ARGS
>> --------------   ------  --------  ----
>> ↔ bpf_log        [void]   1.350us  log=NULL fmt='%s() is not a global
>> function ' =(vararg)
>>
>> It's great to show arguments.
>>
> 
> Thanks for repro steps, they worked. Also, I just pushed latest
> retsnoop version to Github that does support capturing vararg
> arguments for printf-like functions. See full debugging log at [0],
> but I basically did just two things:
> 
> $ sudo retsnoop -e '*sys_bpf' --lbr -n freplace
> 
> -n freplace filters by process name, to avoid the noise. I traced
> bpf() syscall (*sys_bf), and I requested function call LBR (Last
> Branch Record) stack. LBR showed that we have
> bpf_prog_attach_check_attach_type() call, and then eventually we get
> to bpf_log().
> 
> So I then traced bpf_log (no --lbr this time, but I requested function
> trace + arguments capture:
> 
> $ sudo retsnoop -n freplace -e '*sys_bpf' -a bpf_log -TA
> 
> 17:02:39.968302 -> 17:02:39.968307 TID/PID 2730863/2730855 (freplace/freplace):
> 
> FUNCTION CALLS      RESULT     DURATION  ARGS
> -----------------   ---------  --------  ----
> → __x64_sys_bpf
> regs=&{.r15=2,.r14=0xc0000061c0,.bp=0xc00169f8a8,.bx=28,.r11=514,.ax=0xffffffffffffffda,.cx=0x404f4e,.dx=64,.si=0xc00169fa10…
>     → __sys_bpf                          cmd=28
> uattr={{.kernel=0xc00169fa10,.user=0xc00169fa10}} size=64
>         ↔ bpf_log   [void]      1.550us  log=NULL fmt='%s() is not a
> global function ' vararg0='stub_handler_static'
>     ← __sys_bpf     [-EINVAL]   4.115us
> ← __x64_sys_bpf     [-EINVAL]   5.467us
> 
> 
> For __x64_sys_bpf that's struct pt_regs, which isn't that interesting,
> but then we have:
> 
> ↔ bpf_log   [void]      1.550us  log=NULL fmt='%s() is not a global
> function ' vararg0='stub_handler_static'

It's awesome to show vararg.

> 
> Which showed format string and the argument passed to it:
> 'stub_hanler_static' subprogram seems to be the problem here.
> 
> 
> Anyways, tbh, for a problem like this, it's probably best to just
> request a verbose log when doing the BPF_PROG_LOAD command. You can
> *normally* use veristat tool to get that easily, if you have a .bpf.o
> object file on the disk. But in this case it's freplace and veristat
> doesn't know what's the target BPF program, so it's not that useful in
> this case:
> 
> $ sudo veristat -v freplace_bpfel.o
> Processing 'freplace_bpfel.o'...
> libbpf: prog 'freplace_handler': attach program FD is not set
> libbpf: prog 'freplace_handler': failed to prepare load attributes: -22
> libbpf: prog 'freplace_handler': failed to load: -22
> libbpf: failed to load object 'freplace_bpfel.o'
> PROCESSING freplace_bpfel.o/freplace_handler, DURATION US: 0, VERDICT:
> failure, VERIFIER LOG:
> 
> File              Program           Verdict  Duration (us)  Insns
> States  Peak states
> ----------------  ----------------  -------  -------------  -----
> ------  -----------
> freplace_bpfel.o  freplace_handler  failure              0      0
>  0            0
> ----------------  ----------------  -------  -------------  -----
> ------  -----------
> Done. Processed 1 files, 0 programs. Skipped 1 files, 0 programs.
> 
> But for lots of other programs this would be a no-brainer.
> 
> 
>   [0] https://gist.github.com/anakryiko/88a1597a68e43dc945e40fde88a96e7e
> 
> [...]
> 
>>
>> Is it OK to add a tracepoint here? I think tracepoint is more generic
>> than retsnoop-like way.
> 
> I personally don't see a problem with adding tracepoint, but how would
> it look like, given we are talking about vararg printf-style function
> calls? I'm not sure how that should be represented in such a way as to
> make it compatible with tracepoints and not cause any runtime
> overhead.

The tracepoint is not about vararg printf-style function calls.

It is to trace the reason why it fails to bpf_check_attach_target() at
attach time.

So, let me introduce bpf_check_attach_target_with_tracepoint() and
BPF_LOG_KERNEL_WITHOUT_PRINT. bpf_check_attach_target_with_tracepoint()
is to call bpf_check_attach_target() and then to call
trace_bpf_check_attach_target() if err. BPF_LOG_KERNEL_WITHOUT_PRINT is
to avoid pr_err() in bpf_verifier_vlog().

Here's the diff without trace_bpf_check_attach_target() definition:

diff --git a/include/linux/bpf_verifier.h b/include/linux/bpf_verifier.h
index bfd093ac333f2..717e4deda2998 100644
--- a/include/linux/bpf_verifier.h
+++ b/include/linux/bpf_verifier.h
@@ -629,6 +629,7 @@ struct bpf_verifier_log {
 #define BPF_LOG_LEVEL	(BPF_LOG_LEVEL1 | BPF_LOG_LEVEL2)
 #define BPF_LOG_MASK	(BPF_LOG_LEVEL | BPF_LOG_STATS | BPF_LOG_FIXED)
 #define BPF_LOG_KERNEL	(BPF_LOG_MASK + 1) /* kernel internal flag */
+#define BPF_LOG_KERNEL_WITHOUT_PRINT (BPF_LOG_KERNEL << 1)
 #define BPF_LOG_MIN_ALIGNMENT 8U
 #define BPF_LOG_ALIGNMENT 40U

@@ -853,6 +854,11 @@ int bpf_check_attach_target(struct bpf_verifier_log
*log,
 			    const struct bpf_prog *tgt_prog,
 			    u32 btf_id,
 			    struct bpf_attach_target_info *tgt_info);
+int bpf_check_attach_target_with_tracepoint(const struct bpf_prog *prog,
+					    const struct bpf_prog *tgt_prog,
+					    u32 btf_id,
+					    struct bpf_attach_target_info *tgt_info);
+
 void bpf_free_kfunc_btf_tab(struct bpf_kfunc_btf_tab *tab);

 int mark_chain_precision(struct bpf_verifier_env *env, int regno);
diff --git a/kernel/bpf/log.c b/kernel/bpf/log.c
index 5aebfc3051e3a..2bdcdd2fc320f 100644
--- a/kernel/bpf/log.c
+++ b/kernel/bpf/log.c
@@ -65,8 +65,10 @@ void bpf_verifier_vlog(struct bpf_verifier_log *log,
const char *fmt,

 	n = vscnprintf(log->kbuf, BPF_VERIFIER_TMP_LOG_SIZE, fmt, args);

-	if (log->level == BPF_LOG_KERNEL) {
+	if (log->level & BPF_LOG_KERNEL) {
 		bool newline = n > 0 && log->kbuf[n - 1] == '\n';
+		if (log->level & BPF_LOG_KERNEL_WITHOUT_PRINT)
+			return;

 		pr_err("BPF: %s%s", log->kbuf, newline ? "" : "\n");
 		return;
diff --git a/kernel/bpf/syscall.c b/kernel/bpf/syscall.c
index 869265852d515..4d293a8da5a9b 100644
--- a/kernel/bpf/syscall.c
+++ b/kernel/bpf/syscall.c
@@ -3464,8 +3464,8 @@ static int bpf_tracing_prog_attach(struct bpf_prog
*prog,
 		 */
 		struct bpf_attach_target_info tgt_info = {};

-		err = bpf_check_attach_target(NULL, prog, tgt_prog, btf_id,
-					      &tgt_info);
+		err = bpf_check_attach_target_with_tracepoint(prog, tgt_prog,
+							      btf_id, &tgt_info);
 		if (err)
 			goto out_unlock;

diff --git a/kernel/bpf/trampoline.c b/kernel/bpf/trampoline.c
index f8302a5ca400d..44b9f95a07e9c 100644
--- a/kernel/bpf/trampoline.c
+++ b/kernel/bpf/trampoline.c
@@ -699,9 +699,9 @@ int bpf_trampoline_link_cgroup_shim(struct bpf_prog
*prog,
 	u64 key;
 	int err;

-	err = bpf_check_attach_target(NULL, prog, NULL,
-				      prog->aux->attach_btf_id,
-				      &tgt_info);
+	err = bpf_check_attach_target_with_tracepoint(prog, NULL,
+						      prog->aux->attach_btf_id,
+						      &tgt_info);
 	if (err)
 		return err;

diff --git a/kernel/bpf/verifier.c b/kernel/bpf/verifier.c
index 1f5302fb09570..acd9b1b96c76c 100644
--- a/kernel/bpf/verifier.c
+++ b/kernel/bpf/verifier.c
@@ -21929,6 +21929,28 @@ int bpf_check_attach_target(struct
bpf_verifier_log *log,
 	return 0;
 }

+int bpf_check_attach_target_with_tracepoint(const struct bpf_prog *prog,
+					    const struct bpf_prog *tgt_prog,
+					    u32 btf_id,
+					    struct bpf_attach_target_info *tgt_info);
+{
+	struct bpf_verifier_log *log;
+	int err;
+
+	log = kzalloc(sizeof(*log), GFP_KERNEL);
+	if (!log) {
+		err = -ENOMEM;
+		return err;
+	}
+
+	log->level = BPF_LOG_KERNEL | BPF_LOG_KERNEL_WITHOUT_PRINT;
+	err = bpf_check_attach_target(log, prog, tgt_prog, btf_id, tgt_info);
+	if (err)
+		trace_bpf_check_attach_target(log->kbuf);
+	kfree(log);
+	return err;
+}
+
 BTF_SET_START(btf_id_deny)
 BTF_ID_UNUSED
 #ifdef CONFIG_SMP

Re: [PATCH bpf-next v2] bpf: Add bpf_check_attach_target_with_klog method to output failure logs to kernel

[Andrii Nakryiko]

On Fri, Jul 26, 2024 at 9:04 PM Leon Hwang <hffilwlqm@gmail.com> wrote:
>
>
>
> On 2024/7/27 08:12, Andrii Nakryiko wrote:
> > On Thu, Jul 25, 2024 at 7:57 PM Leon Hwang <hffilwlqm@gmail.com> wrote:
> >>
> >>
> >>
> >> On 26/7/24 05:27, Andrii Nakryiko wrote:
> >>> On Thu, Jul 25, 2024 at 12:33 AM Leon Hwang <hffilwlqm@gmail.com> wrote:
> >>>>
> >>>>
> >>>>
> >>>> On 25/7/24 14:09, Yonghong Song wrote:
> >>>>>
> >>>>> On 7/24/24 11:05 PM, Leon Hwang wrote:
> >>>>>>
> >>>>>> On 25/7/24 13:54, Yonghong Song wrote:
> >>>>>>> On 7/24/24 10:15 PM, Zheao Li wrote:
> >>>>>>>> This is a v2 patch, previous Link:
> >>>>>>>> https://lore.kernel.org/bpf/20240724152521.20546-1-me@manjusaka.me/T/#u
> >>>>>>>>
> >>
> >> [SNI]
> >>
> >
> > [...]
> >
> >>>
> >>
> >> Build and run, sudo ./retsnoop -e verbose -e bpf_log -e
> >> bpf_verifier_vlog -e bpf_verifier_log_write -STA -v, here's the output:
> >>
> >>
> >> FUNCTION CALLS   RESULT  DURATION  ARGS
> >> --------------   ------  --------  ----
> >> ↔ bpf_log        [void]   1.350us  log=NULL fmt='%s() is not a global
> >> function ' =(vararg)
> >>
> >> It's great to show arguments.
> >>
> >
> > Thanks for repro steps, they worked. Also, I just pushed latest
> > retsnoop version to Github that does support capturing vararg
> > arguments for printf-like functions. See full debugging log at [0],
> > but I basically did just two things:
> >
> > $ sudo retsnoop -e '*sys_bpf' --lbr -n freplace
> >
> > -n freplace filters by process name, to avoid the noise. I traced
> > bpf() syscall (*sys_bf), and I requested function call LBR (Last
> > Branch Record) stack. LBR showed that we have
> > bpf_prog_attach_check_attach_type() call, and then eventually we get
> > to bpf_log().
> >
> > So I then traced bpf_log (no --lbr this time, but I requested function
> > trace + arguments capture:
> >
> > $ sudo retsnoop -n freplace -e '*sys_bpf' -a bpf_log -TA
> >
> > 17:02:39.968302 -> 17:02:39.968307 TID/PID 2730863/2730855 (freplace/freplace):
> >
> > FUNCTION CALLS      RESULT     DURATION  ARGS
> > -----------------   ---------  --------  ----
> > → __x64_sys_bpf
> > regs=&{.r15=2,.r14=0xc0000061c0,.bp=0xc00169f8a8,.bx=28,.r11=514,.ax=0xffffffffffffffda,.cx=0x404f4e,.dx=64,.si=0xc00169fa10…
> >     → __sys_bpf                          cmd=28
> > uattr={{.kernel=0xc00169fa10,.user=0xc00169fa10}} size=64
> >         ↔ bpf_log   [void]      1.550us  log=NULL fmt='%s() is not a
> > global function ' vararg0='stub_handler_static'
> >     ← __sys_bpf     [-EINVAL]   4.115us
> > ← __x64_sys_bpf     [-EINVAL]   5.467us
> >
> >
> > For __x64_sys_bpf that's struct pt_regs, which isn't that interesting,
> > but then we have:
> >
> > ↔ bpf_log   [void]      1.550us  log=NULL fmt='%s() is not a global
> > function ' vararg0='stub_handler_static'
>
> It's awesome to show vararg.
>
> >
> > Which showed format string and the argument passed to it:
> > 'stub_hanler_static' subprogram seems to be the problem here.
> >
> >
> > Anyways, tbh, for a problem like this, it's probably best to just
> > request a verbose log when doing the BPF_PROG_LOAD command. You can
> > *normally* use veristat tool to get that easily, if you have a .bpf.o
> > object file on the disk. But in this case it's freplace and veristat
> > doesn't know what's the target BPF program, so it's not that useful in
> > this case:
> >
> > $ sudo veristat -v freplace_bpfel.o
> > Processing 'freplace_bpfel.o'...
> > libbpf: prog 'freplace_handler': attach program FD is not set
> > libbpf: prog 'freplace_handler': failed to prepare load attributes: -22
> > libbpf: prog 'freplace_handler': failed to load: -22
> > libbpf: failed to load object 'freplace_bpfel.o'
> > PROCESSING freplace_bpfel.o/freplace_handler, DURATION US: 0, VERDICT:
> > failure, VERIFIER LOG:
> >
> > File              Program           Verdict  Duration (us)  Insns
> > States  Peak states
> > ----------------  ----------------  -------  -------------  -----
> > ------  -----------
> > freplace_bpfel.o  freplace_handler  failure              0      0
> >  0            0
> > ----------------  ----------------  -------  -------------  -----
> > ------  -----------
> > Done. Processed 1 files, 0 programs. Skipped 1 files, 0 programs.
> >
> > But for lots of other programs this would be a no-brainer.
> >
> >
> >   [0] https://gist.github.com/anakryiko/88a1597a68e43dc945e40fde88a96e7e
> >
> > [...]
> >
> >>
> >> Is it OK to add a tracepoint here? I think tracepoint is more generic
> >> than retsnoop-like way.
> >
> > I personally don't see a problem with adding tracepoint, but how would
> > it look like, given we are talking about vararg printf-style function
> > calls? I'm not sure how that should be represented in such a way as to
> > make it compatible with tracepoints and not cause any runtime
> > overhead.
>
> The tracepoint is not about vararg printf-style function calls.
>
> It is to trace the reason why it fails to bpf_check_attach_target() at
> attach time.
>

Oh, that changes things. I don't think we can keep adding extra
tracepoints for various potential reasons that BPF prog might be
failing to verify.

But there is usually no need either. This particular code already
supports emitting extra information into verifier log, you just have
to provide that. This is done by libbpf automatically, can't your
library of choice do the same (if BPF program failed).

Why go to all this trouble if we already have a facility to debug
issues like this. Note every issue is logged into verifier log, but in
this case it is.

> So, let me introduce bpf_check_attach_target_with_tracepoint() and
> BPF_LOG_KERNEL_WITHOUT_PRINT. bpf_check_attach_target_with_tracepoint()
> is to call bpf_check_attach_target() and then to call
> trace_bpf_check_attach_target() if err. BPF_LOG_KERNEL_WITHOUT_PRINT is
> to avoid pr_err() in bpf_verifier_vlog().
>
> Here's the diff without trace_bpf_check_attach_target() definition:

[...]

Re: [PATCH bpf-next v2] bpf: Add bpf_check_attach_target_with_klog method to output failure logs to kernel

[Leon Hwang]

On 30/7/24 05:01, Andrii Nakryiko wrote:
> On Fri, Jul 26, 2024 at 9:04 PM Leon Hwang <hffilwlqm@gmail.com> wrote:
>>
>>
>>
>> On 2024/7/27 08:12, Andrii Nakryiko wrote:
>>> On Thu, Jul 25, 2024 at 7:57 PM Leon Hwang <hffilwlqm@gmail.com> wrote:
>>>>
>>>>
>>>>

[...]

>>>>
>>>> Is it OK to add a tracepoint here? I think tracepoint is more generic
>>>> than retsnoop-like way.
>>>
>>> I personally don't see a problem with adding tracepoint, but how would
>>> it look like, given we are talking about vararg printf-style function
>>> calls? I'm not sure how that should be represented in such a way as to
>>> make it compatible with tracepoints and not cause any runtime
>>> overhead.
>>
>> The tracepoint is not about vararg printf-style function calls.
>>
>> It is to trace the reason why it fails to bpf_check_attach_target() at
>> attach time.
>>
> 
> Oh, that changes things. I don't think we can keep adding extra
> tracepoints for various potential reasons that BPF prog might be
> failing to verify.
> 
> But there is usually no need either. This particular code already
> supports emitting extra information into verifier log, you just have
> to provide that. This is done by libbpf automatically, can't your
> library of choice do the same (if BPF program failed).
> 
> Why go to all this trouble if we already have a facility to debug
> issues like this. Note every issue is logged into verifier log, but in
> this case it is.
> 

Yeah, it is unnecessary to add tracepoint here, as we are able to trace
the log message in bpf_log() arguments with retsnoop.

Thanks,
Leon

Re: [PATCH bpf-next v2] bpf: Add bpf_check_attach_target_with_klog method to output failure logs to kernel

[Andrii Nakryiko]

On Mon, Jul 29, 2024 at 8:32 PM Leon Hwang <hffilwlqm@gmail.com> wrote:
>
>
>
> On 30/7/24 05:01, Andrii Nakryiko wrote:
> > On Fri, Jul 26, 2024 at 9:04 PM Leon Hwang <hffilwlqm@gmail.com> wrote:
> >>
> >>
> >>
> >> On 2024/7/27 08:12, Andrii Nakryiko wrote:
> >>> On Thu, Jul 25, 2024 at 7:57 PM Leon Hwang <hffilwlqm@gmail.com> wrote:
> >>>>
> >>>>
> >>>>
>
> [...]
>
> >>>>
> >>>> Is it OK to add a tracepoint here? I think tracepoint is more generic
> >>>> than retsnoop-like way.
> >>>
> >>> I personally don't see a problem with adding tracepoint, but how would
> >>> it look like, given we are talking about vararg printf-style function
> >>> calls? I'm not sure how that should be represented in such a way as to
> >>> make it compatible with tracepoints and not cause any runtime
> >>> overhead.
> >>
> >> The tracepoint is not about vararg printf-style function calls.
> >>
> >> It is to trace the reason why it fails to bpf_check_attach_target() at
> >> attach time.
> >>
> >
> > Oh, that changes things. I don't think we can keep adding extra
> > tracepoints for various potential reasons that BPF prog might be
> > failing to verify.
> >
> > But there is usually no need either. This particular code already
> > supports emitting extra information into verifier log, you just have
> > to provide that. This is done by libbpf automatically, can't your
> > library of choice do the same (if BPF program failed).
> >
> > Why go to all this trouble if we already have a facility to debug
> > issues like this. Note every issue is logged into verifier log, but in
> > this case it is.
> >
>
> Yeah, it is unnecessary to add tracepoint here, as we are able to trace
> the log message in bpf_log() arguments with retsnoop.

My point was that you don't even need retsnoop, you can just ask for
verifier log directly, that's the main way to understand and debug BPF
program verification/load failures.

>
> Thanks,
> Leon

Re: [PATCH bpf-next v2] bpf: Add bpf_check_attach_target_with_klog method to output failure logs to kernel

[Leon Hwang]

On 31/7/24 01:28, Andrii Nakryiko wrote:
> On Mon, Jul 29, 2024 at 8:32 PM Leon Hwang <hffilwlqm@gmail.com> wrote:
>>
>>
>>
>> On 30/7/24 05:01, Andrii Nakryiko wrote:
>>> On Fri, Jul 26, 2024 at 9:04 PM Leon Hwang <hffilwlqm@gmail.com> wrote:
>>>>
>>>>
>>>>
>>>> On 2024/7/27 08:12, Andrii Nakryiko wrote:
>>>>> On Thu, Jul 25, 2024 at 7:57 PM Leon Hwang <hffilwlqm@gmail.com> wrote:
>>>>>>
>>>>>>
>>>>>>
>>
>> [...]
>>
>>>>>>
>>>>>> Is it OK to add a tracepoint here? I think tracepoint is more generic
>>>>>> than retsnoop-like way.
>>>>>
>>>>> I personally don't see a problem with adding tracepoint, but how would
>>>>> it look like, given we are talking about vararg printf-style function
>>>>> calls? I'm not sure how that should be represented in such a way as to
>>>>> make it compatible with tracepoints and not cause any runtime
>>>>> overhead.
>>>>
>>>> The tracepoint is not about vararg printf-style function calls.
>>>>
>>>> It is to trace the reason why it fails to bpf_check_attach_target() at
>>>> attach time.
>>>>
>>>
>>> Oh, that changes things. I don't think we can keep adding extra
>>> tracepoints for various potential reasons that BPF prog might be
>>> failing to verify.
>>>
>>> But there is usually no need either. This particular code already
>>> supports emitting extra information into verifier log, you just have
>>> to provide that. This is done by libbpf automatically, can't your
>>> library of choice do the same (if BPF program failed).
>>>
>>> Why go to all this trouble if we already have a facility to debug
>>> issues like this. Note every issue is logged into verifier log, but in
>>> this case it is.
>>>
>>
>> Yeah, it is unnecessary to add tracepoint here, as we are able to trace
>> the log message in bpf_log() arguments with retsnoop.
> 
> My point was that you don't even need retsnoop, you can just ask for
> verifier log directly, that's the main way to understand and debug BPF
> program verification/load failures.
> 

Nope. It is not about BPF program verification/load failures. It is
about freplace program attach failures instead.

As for freplace program, it can attach to a different target from the
target at load time, since commit 4a1e7c0c63e0 ("bpf: Support attaching
freplace programs to multiple attach points").

This patch tries to provide a better way to figure out the reason why a
freplace program fails to attach.

For example:

tcp_connect.c:

#include "vmlinux.h"
#include <bpf/bpf_helpers.h>

static __noinline int
stub_handler_static(void)
{
    bpf_printk("freplace, stub handler static\n");

    return 0;
}

__noinline int
stub_handler(void)
{
    bpf_printk("freplace, stub handler\n");

    return 0;
}

SEC("kprobe/tcp_connect")
int k_tcp_connect(struct pt_regs *ctx)
{
    stub_handler_static();

    return stub_handler();
}

char __license[] SEC("license") = "GPL";

freplace.c:

#include "vmlinux.h"
#include <bpf/bpf_helpers.h>

SEC("freplace/stub_handler")
int freplace_handler(void)
{
    bpf_printk("freplace, replaced handler\n");

    return 0;
}

char __license[] SEC("license") = "GPL";

And, here's pseudo C code snippet with libbpf to show attach failure:

tcp_skel = tcp_connect__open_and_load();
prog_fd = tcp_skel->progs.k_tcp_connect;
freplace_skel = freplace__open();
freplace_prog = freplace_skel->progs.freplace_handler;
err = bpf_program__set_attach_target(freplace_prog, prog_fd,
"stub_handler");
err = freplace__load(freplace_skel);
freplace_link = bpf_program__attach_freplace(freplace_prog, prog_fd,
"stub_handler_static");

freplace_link will be -EINVAL because stub_handler_static() is not a
global function, as we have figured out.

With this patch, "stub_handler_static() is not a global function" will
be printed in dmesg. But we should not pollute dmesg with such message.

If there's the tracepoint that I mentioned previously,
"stub_handler_static() is not a global function" can be retrieved by the
tracepoint.

Thanks,
Leon

Re: [PATCH bpf-next v2] bpf: Add bpf_check_attach_target_with_klog method to output failure logs to kernel

[Andrii Nakryiko]

On Tue, Jul 30, 2024 at 8:31 PM Leon Hwang <hffilwlqm@gmail.com> wrote:
>
>
>
> On 31/7/24 01:28, Andrii Nakryiko wrote:
> > On Mon, Jul 29, 2024 at 8:32 PM Leon Hwang <hffilwlqm@gmail.com> wrote:
> >>
> >>
> >>
> >> On 30/7/24 05:01, Andrii Nakryiko wrote:
> >>> On Fri, Jul 26, 2024 at 9:04 PM Leon Hwang <hffilwlqm@gmail.com> wrote:
> >>>>
> >>>>
> >>>>
> >>>> On 2024/7/27 08:12, Andrii Nakryiko wrote:
> >>>>> On Thu, Jul 25, 2024 at 7:57 PM Leon Hwang <hffilwlqm@gmail.com> wrote:
> >>>>>>
> >>>>>>
> >>>>>>
> >>
> >> [...]
> >>
> >>>>>>
> >>>>>> Is it OK to add a tracepoint here? I think tracepoint is more generic
> >>>>>> than retsnoop-like way.
> >>>>>
> >>>>> I personally don't see a problem with adding tracepoint, but how would
> >>>>> it look like, given we are talking about vararg printf-style function
> >>>>> calls? I'm not sure how that should be represented in such a way as to
> >>>>> make it compatible with tracepoints and not cause any runtime
> >>>>> overhead.
> >>>>
> >>>> The tracepoint is not about vararg printf-style function calls.
> >>>>
> >>>> It is to trace the reason why it fails to bpf_check_attach_target() at
> >>>> attach time.
> >>>>
> >>>
> >>> Oh, that changes things. I don't think we can keep adding extra
> >>> tracepoints for various potential reasons that BPF prog might be
> >>> failing to verify.
> >>>
> >>> But there is usually no need either. This particular code already
> >>> supports emitting extra information into verifier log, you just have
> >>> to provide that. This is done by libbpf automatically, can't your
> >>> library of choice do the same (if BPF program failed).
> >>>
> >>> Why go to all this trouble if we already have a facility to debug
> >>> issues like this. Note every issue is logged into verifier log, but in
> >>> this case it is.
> >>>
> >>
> >> Yeah, it is unnecessary to add tracepoint here, as we are able to trace
> >> the log message in bpf_log() arguments with retsnoop.
> >
> > My point was that you don't even need retsnoop, you can just ask for
> > verifier log directly, that's the main way to understand and debug BPF
> > program verification/load failures.
> >
>
> Nope. It is not about BPF program verification/load failures. It is
> about freplace program attach failures instead.

Ah, my bad, it's at an attach time. Still, I don't think a tracepoint
for every possible failure will ever work. Perhaps the right approach
is to wire up bpf_log into attach commands (LINK_CREATE, at least), so
that the kernel can report back what's the reason for declining
attachment?

>
> As for freplace program, it can attach to a different target from the
> target at load time, since commit 4a1e7c0c63e0 ("bpf: Support attaching
> freplace programs to multiple attach points").
>

[...]

Re: [PATCH bpf-next v2] bpf: Add bpf_check_attach_target_with_klog method to output failure logs to kernel

[Leon Hwang]

On 2/8/24 00:59, Andrii Nakryiko wrote:
> On Tue, Jul 30, 2024 at 8:31 PM Leon Hwang <hffilwlqm@gmail.com> wrote:
>>
>>
>>
>> On 31/7/24 01:28, Andrii Nakryiko wrote:
>>> On Mon, Jul 29, 2024 at 8:32 PM Leon Hwang <hffilwlqm@gmail.com> wrote:
>>>>
>>>>
>>>>
>>>> On 30/7/24 05:01, Andrii Nakryiko wrote:
>>>>> On Fri, Jul 26, 2024 at 9:04 PM Leon Hwang <hffilwlqm@gmail.com> wrote:
>>>>>>
>>>>>>
>>>>>>
>>>>>> On 2024/7/27 08:12, Andrii Nakryiko wrote:
>>>>>>> On Thu, Jul 25, 2024 at 7:57 PM Leon Hwang <hffilwlqm@gmail.com> wrote:
>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>
>>>> [...]
>>>>
>>>>>>>>
>>>>>>>> Is it OK to add a tracepoint here? I think tracepoint is more generic
>>>>>>>> than retsnoop-like way.
>>>>>>>
>>>>>>> I personally don't see a problem with adding tracepoint, but how would
>>>>>>> it look like, given we are talking about vararg printf-style function
>>>>>>> calls? I'm not sure how that should be represented in such a way as to
>>>>>>> make it compatible with tracepoints and not cause any runtime
>>>>>>> overhead.
>>>>>>
>>>>>> The tracepoint is not about vararg printf-style function calls.
>>>>>>
>>>>>> It is to trace the reason why it fails to bpf_check_attach_target() at
>>>>>> attach time.
>>>>>>
>>>>>
>>>>> Oh, that changes things. I don't think we can keep adding extra
>>>>> tracepoints for various potential reasons that BPF prog might be
>>>>> failing to verify.
>>>>>
>>>>> But there is usually no need either. This particular code already
>>>>> supports emitting extra information into verifier log, you just have
>>>>> to provide that. This is done by libbpf automatically, can't your
>>>>> library of choice do the same (if BPF program failed).
>>>>>
>>>>> Why go to all this trouble if we already have a facility to debug
>>>>> issues like this. Note every issue is logged into verifier log, but in
>>>>> this case it is.
>>>>>
>>>>
>>>> Yeah, it is unnecessary to add tracepoint here, as we are able to trace
>>>> the log message in bpf_log() arguments with retsnoop.
>>>
>>> My point was that you don't even need retsnoop, you can just ask for
>>> verifier log directly, that's the main way to understand and debug BPF
>>> program verification/load failures.
>>>
>>
>> Nope. It is not about BPF program verification/load failures. It is
>> about freplace program attach failures instead.
> 
> Ah, my bad, it's at an attach time. Still, I don't think a tracepoint
> for every possible failure will ever work. Perhaps the right approach
> is to wire up bpf_log into attach commands (LINK_CREATE, at least), so
> that the kernel can report back what's the reason for declining
> attachment?
> 

OK. Let me take a try.

Thanks,
Leon