Re: Kernel Oops in test_verifier "#828/p reference tracking: bpf_sk_release(btf_tcp_sock)"

From: Yonghong Song <yhs@fb.com>
To: Tony Ambardar <tony.ambardar@gmail.com>
Cc: bpf <bpf@vger.kernel.org>, <linux-mips@vger.kernel.org>,
	Alexei Starovoitov <ast@kernel.org>,
	Daniel Borkmann <daniel@iogearbox.net>,
	Andrii Nakryiko <andrii@kernel.org>
Subject: Re: Kernel Oops in test_verifier "#828/p reference tracking: bpf_sk_release(btf_tcp_sock)"
Date: Tue, 15 Jun 2021 22:55:04 -0700	[thread overview]
Message-ID: <f888e1ef-acef-2b3d-3ac8-06a051f979d7@fb.com> (raw)
In-Reply-To: <CAPGftE8d03K4_S1pTyRVWZL7w67FukES_PV8SR=0_6DXhXzjQw@mail.gmail.com>

On 6/15/21 7:21 PM, Tony Ambardar wrote:
> On Sun, 13 Jun 2021 at 23:14, Yonghong Song <yhs@fb.com> wrote:
>>
>> On 6/12/21 5:07 PM, Tony Ambardar wrote:
>>> On Fri, 11 Jun 2021 at 08:57, Yonghong Song <yhs@fb.com> wrote:
>>>>
>>>> On 6/10/21 6:02 PM, Tony Ambardar wrote:
>>>>> Hello,
>>>>>
>>>>> I encountered an NPE and kernel Oops [1] while running the
>>>>> 'test_verifier' selftest on MIPS32 with LTS kernel 5.10.41. This was
>>>>> observed during development of a MIPS32 JIT but is verifier-related.
>>>>>
>>>>> Initial troubleshooting [2] points to an unchecked NULL dereference in
>>>>> btf_type_by_id(), with an unexpected BTF type ID. The root cause is
>>>>> unclear, whether source of the ID or a potential underlying BTF
>>>>> problem.
>>>>
>>>> Do you know what is the faulty btf ID number? What is the maximum id
>>>> for vmlinux BTF?
>>>
>>> Thanks for the suggestions, Yonghong.
>>>
>>> I had built/packaged bpftool for the target, which shows the maximum as:
>>>
>>>     root@OpenWrt:~# bpftool btf dump file /sys/kernel/btf/vmlinux format
>>> raw|tail -5
>>>     [43179] FUNC 'pci_load_of_ranges' type_id=43178 linkage=static
>>>     [43180] ARRAY '(anon)' type_id=23 index_type_id=23 nr_elems=16
>>>     [43181] FUNC 'pcibios_plat_dev_init' type_id=29264 linkage=static
>>>     [43182] FUNC 'pcibios_map_irq' type_id=29815 linkage=static
>>>     [43183] FUNC 'mips_pcibios_init' type_id=115 linkage=static
>>>
>>> After adding NULL handling and debug pr_err() to kernel_type_name(), I next see:
>>>
>>>     root@OpenWrt:~# ./test_verifier_eb 828
>>>     [   87.196692] btf_type_by_id(btf_vmlinux, 3062497280) returns NULL
>>>     [   87.196958] btf_type_by_id(btf_vmlinux, 2936995840) returns NULL
>>>     #828/p reference tracking: bpf_sk_release(btf_tcp_sock) FAIL
>>>
>>> Those large type ids make me suspect an endianness issue, even though bpftool
>>> can still properly access the vmlinux BTF. Changing byte order and
>>> looking up the
>>> resulting type ids seems to confirm this:
>>>
>>>     Check endianness:
>>>       3062497280 -> 0xB68A0000 --swap endian--> 0x00008AB6 -> 35510
>>>     bpftool btf dump file /sys/kernel/btf/vmlinux format raw|fgrep "[35510]":
>>>       [35510] STRUCT 'tcp_sock' size=1752 vlen=136
>>>
>>>     Check endianness:
>>>       2936995840 -> 0xAF0F0000 --swap endian--> 0x00000FAF -> 4015
>>>     bpftool btf dump file /sys/kernel/btf/vmlinux format raw|fgrep "[4015]":
>>>       [4015] STRUCT 'sock_common' size=112 vlen=25
>>>
>>> As a further test, I repeated "test_verifier 828" across mips{32,64}{be,le}
>>> systems and confirm seeing the problem only with the big-endian ones.
>>
>>   From the above information, looks like vmlinux BTF is correct.
>> Below resolve_btfids command output seems indicating the btf_id list
>> is also correct.
>>
>> The kernel_type_name is used in a few places for verifier verbose output.
>>
>> $ grep kernel_type_name kernel/bpf/verifier.c
>> static const char *kernel_type_name(const struct btf* btf, u32 id)
>>                                   verbose(env, "%s",
>> kernel_type_name(reg->btf, reg->btf_id));
>>                                   regno, kernel_type_name(reg->btf,
>> reg->btf_id),
>>                                   kernel_type_name(btf_vmlinux,
>> *arg_btf_id));
>>
>> The most suspicous target is reg->btf_id, which is propagated from
>> the result of bpf_sk_lookup_tcp() helper.
>>
>>>
>>>> The involved helper is bpf_sk_release.
>>>>
>>>> static const struct bpf_func_proto bpf_sk_release_proto = {
>>>>            .func           = bpf_sk_release,
>>>>            .gpl_only       = false,
>>>>            .ret_type       = RET_INTEGER,
>>>>            .arg1_type      = ARG_PTR_TO_BTF_ID_SOCK_COMMON,
>>>> };
>>>>
>>>> Eventually, the btf_id is taken from btf_sock_ids[6] where
>>>> btf_sock_ids is a kernel global variable.
>>>>
>>>> Could you check btf_sock_ids[6] to see whether the number
>>>> makes sense?
>>>
>>> What I see matches the second btf_type_by_id() NULL call above:
>>>     [   56.556121] btf_sock_ids[6]: 2936995840
>>>
>>>> The id is computed by resolve_btfids in
>>>> tools/bpf/resolve_btfids, you might add verbose mode to your linux build
>>>> to get more information.
>>>
>>> The verbose build didn't print any details of the btf ids. Was there anything
>>> special to do in invocation? I manually ran "resolve_btfids -v vmlinux" from
>>> the build dir and this, strangely, gave slightly different results than bpftool
>>> but not the huge endian-swapped type ids. Is this expected?
>>>
>>>     # ./tools/bpf/resolve_btfids/resolve_btfids -v vmlinux
>>>     ...
>>>     patching addr   116: ID   35522 [tcp_sock]
>>>     ...
>>>     patching addr   112: ID    4021 [sock_common]
>>>
>>> Do any of the details above help narrow down things? What do you suggest
>>> for next steps?
>>
>> We need to identify issues by dumping detailed verifier logs.
>> Could you apply the following change?
>>
>> --- a/tools/testing/selftests/bpf/test_verifier.c
>> +++ b/tools/testing/selftests/bpf/test_verifier.c
>> @@ -1088,7 +1088,7 @@ static void do_test_single(struct bpf_test *test,
>> bool unpriv,
>>           attr.insns_cnt = prog_len;
>>           attr.license = "GPL";
>>           if (verbose)
>> -               attr.log_level = 1;
>> +               attr.log_level = 3;
>>           else if (expected_ret == VERBOSE_ACCEPT)
>>                   attr.log_level = 2;
>>           else
>>
>> Run command like `./test_verifier -v 828 828`?
>>
>> I attached the verifier output for x86_64.
>> Maybe by comparing x86 output vs. mips32 output, you can
>> find which insn starts to have *wrong* verifier state
>> and then we can go from there.
> 
> I realized too late your test output must be for a different kernel version as
> well as arch, as the test numbering is different and doesn't match my test:
> "reference tracking: bpf_sk_release(btf_tcp_sock)".
> 
> Given the problem is seen on big-endian and not little-systems, I applied
> your patch for both mips32 variant systems and recaptured log output,
> which should make for a stricter A/B comparison. I also kept my earlier
> patches to catch the NULLs and print debug info.
> 
> The logs are identical until insn #18, where the failing MIPS32BE shows:
> 
> 18: R0_w=ptr_or_null_(null)(id=3,off=0,imm=0)
> R6_w=sock(id=0,ref_obj_id=2,off=0,imm=0) R10=fp0 fp-8=????0000
> fp-16=0000mmmm fp-24=mmmmmmmm fp-32=mmmmmmmm fp-40=mmmmmmmm
> fp-48=mmmmmmmm refs=2
> 
> while the succeed MIPS32LE test shows:
> 
> 18: R0_w=ptr_or_null_tcp_sock(id=3,off=0,imm=0)
> R6_w=sock(id=0,ref_obj_id=2,off=0,imm=0) R10=fp0 fp-8=????0000
> fp-16=0000mmmm fp-24=mmmmmmmm fp-32=mmmmmmmm fp-40=mmmmmmmm
> fp-48=mmmmmmmm refs=2
> 
> There are then further differences you can see in the attached logs. It's
> not clear to me what these differences mean however. Any ideas?

The above R0_w is to capture the return value for bpf_skc_to_tcp_sock()

const struct bpf_func_proto bpf_skc_to_tcp_sock_proto = {
         .func                   = bpf_skc_to_tcp_sock,
         .gpl_only               = false,
         .ret_type               = RET_PTR_TO_BTF_ID_OR_NULL,
         .arg1_type              = ARG_PTR_TO_BTF_ID_SOCK_COMMON,
         .ret_btf_id             = &btf_sock_ids[BTF_SOCK_TYPE_TCP],
};

 From the above func_proto, it should return the btf_id for
btf_sock_ids[BTF_SOCK_TYPE_TCP].

It does like the root cause is still endianness of btf_sock_ids
written by resolve_btfids.

> 
> Following your earlier comments on the large, endian-swapped values
> in btf_sock_ids[6], I noticed this is true of all btf_sock_ids[]
> elements, based on debug output:
> 
>      btf_sock_ids[0] = 2139684864
>      btf_sock_ids[1] = 2794061824
>      btf_sock_ids[2] = 2844459008
>      btf_sock_ids[3] = 1234305024
>      btf_sock_ids[4] = 3809411072
>      btf_sock_ids[5] = 1946812416
>      btf_sock_ids[6] = 2936995840
>      btf_sock_ids[7] = 3062497280
>      btf_sock_ids[8] = 2861236224
>      btf_sock_ids[9] = 1251082240
>      btf_sock_ids[10] = 1334968320
>      btf_sock_ids[11] = 1267859456
>      btf_sock_ids[12] = 1318191104
> 
> If these are populated by resolve_btfids, how could we re-verify that
> it's being done properly?
> 
>>>
>>> Thanks,
>>> Tony
>>>
[...]