From mboxrd@z Thu Jan 1 00:00:00 1970 Received: from mail-pf1-f170.google.com (mail-pf1-f170.google.com [209.85.210.170]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (No client certificate requested) by smtp.subspace.kernel.org (Postfix) with ESMTPS id 444AD3C07 for ; Tue, 4 Apr 2023 16:15:24 +0000 (UTC) Received: by mail-pf1-f170.google.com with SMTP id u20so21793869pfk.12 for ; Tue, 04 Apr 2023 09:15:24 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=umich.edu; s=google-2016-06-03; t=1680624923; h=content-transfer-encoding:cc:to:subject:message-id:date:from :in-reply-to:references:mime-version:from:to:cc:subject:date :message-id:reply-to; bh=wu3q5lWQSYmMEw6APY+n4HkdWyAwfkX9OfWilZBoP4g=; b=W9DZNog3VwsqwYx4+j2Ervz/pOS+Apq08192NmP1L0ESxItT1M/WI7LvcuG5XAigSO JKnFPfTstp7VFXBa95+gGZP9wsZ7mi4p+XiRgdHtM1BC/9BGDKMnV+XHbt352B1y1Lqr Qz1XyDeX8zXI/i+XeggtN3ViTAt6A8igtTmd8+I/B6pLPtcKP5FqRE8v/orA42s+zfQX ISA65LKGuOJkqCgEwqQhgWYhz1iBKtPVavUybWtQutpCh7if6psGPaRYIiHnwEVoknBH t9YozgL+MrSsDhflY/U0zR8dqtDXabbozGNFUK97KuOZpZKYwVHlpVnBRGC/x7gMAJHl 6L5g== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20210112; t=1680624923; h=content-transfer-encoding:cc:to:subject:message-id:date:from :in-reply-to:references:mime-version:x-gm-message-state:from:to:cc :subject:date:message-id:reply-to; bh=wu3q5lWQSYmMEw6APY+n4HkdWyAwfkX9OfWilZBoP4g=; b=eCA18CVM2DhG+eZZNYrGW5+YVtmSEoz5EHpV3qW+MN/pxd/8pqNGoZkDgUeNkDjXNJ OawFuvSWn7Gs2kkxXx992dOGhQlbhwhz9ZROSkds4yR25XUAxUWeynALH9iUc04qeKZc 6XMqGZ6oK3k+Stc2+XHv3WpnkuN/FLCqskdSZkl4CJxHWiEapq2ivUD2huwWcu4Wh+ee rYXwb1UUDXC98ro69cXYwNMPDq3BFl5Fi8sY9yx/aH2gncwqDg6OLU9Tgcv+M/zeVNck NKQGxFLVTmCVAwI8aW+8n6QRuP97QM4gsuoSL5Rk9yYE6s0siZMWDUroSDhkdoXGFOeE 7lJw== X-Gm-Message-State: AAQBX9c6eRT0kXilvlMxIVFGIrK8M2SPq4GZ5s/WKbudvpurifvvOY33 Xf+Mmb+eu2qXe7cn3/nqFHxpkAM+B+TPFLtQrto= X-Google-Smtp-Source: AKy350ZjUjgd6GEJ4jFzpBVeZFRvKPGi1YEmB1BtoSNFxyuSoq0TgWBRJ17gOpAuyP+VnIQW0mMXizmpT6TLJWCPDWU= X-Received: by 2002:a05:6a00:14c9:b0:627:fb45:9279 with SMTP id w9-20020a056a0014c900b00627fb459279mr13127pfu.0.1680624923347; Tue, 04 Apr 2023 09:15:23 -0700 (PDT) Precedence: bulk X-Mailing-List: kernel-tls-handshake@lists.linux.dev List-Id: List-Subscribe: List-Unsubscribe: MIME-Version: 1.0 References: <6B4F534A-3D98-4AAC-8537-2D78D4EFFEA6@oracle.com> <2F8C7CC4-157D-479B-9DBB-51A4D39EEA96@oracle.com> In-Reply-To: <2F8C7CC4-157D-479B-9DBB-51A4D39EEA96@oracle.com> From: Olga Kornievskaia Date: Tue, 4 Apr 2023 12:15:12 -0400 Message-ID: Subject: Re: kernel oops To: Chuck Lever III Cc: "kernel-tls-handshake@lists.linux.dev" Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable On Tue, Apr 4, 2023 at 10:54=E2=80=AFAM Chuck Lever III wrote: > > > > > On Apr 4, 2023, at 10:44 AM, Olga Kornievskaia wrote: > > > > On Tue, Apr 4, 2023 at 10:32=E2=80=AFAM Chuck Lever III wrote: > >> > >>> On Apr 4, 2023, at 10:24 AM, Olga Kornievskaia wrote= : > >>> > >>> On Fri, Mar 31, 2023 at 10:25=E2=80=AFAM Chuck Lever III wrote: > >>>> > >>>> > >>>> > >>>>> On Mar 31, 2023, at 10:23 AM, Olga Kornievskaia wr= ote: > >>>>> > >>>>> Hi Chuck, > >>>>> > >>>>> Have you seen this oops? This is not my testing so all I know was t= hat > >>>>> it was an attempt to mount with xprtsec=3Dtls (against ONTAP). > >>>>> > >>>>> [ 316.939747] BUG: kernel NULL pointer dereference, address: 00000= 00000000018 > >>>>> [ 316.939848] #PF: supervisor read access in kernel mode > >>>>> [ 316.939914] #PF: error_code(0x0000) - not-present page > >>>>> [ 316.939984] PGD 0 P4D 0 > >>>>> [ 316.940041] Oops: 0000 [#1] PREEMPT SMP PTI > >>>>> [ 316.940109] CPU: 0 PID: 511 Comm: kworker/u2:30 Kdump: loaded No= t > >>>>> tainted 6.2.1+ #2 > >>>>> [ 316.940181] Hardware name: VMware, Inc. VMware7,1/440BX Desktop > >>>>> Reference Platform, BIOS VMW71.00V.16707776.B64.2008070230 08/07/20= 20 > >>>>> [ 316.940259] Workqueue: xprtiod xs_tls_connect [sunrpc] > >>>>> [ 316.940463] RIP: 0010:xs_tls_connect+0x3e1/0x590 [sunrpc] > >>>>> [ 316.940556] Code: ff ff ff 48 2b 83 f8 fe ff ff 48 89 83 00 ff f= f > >>>>> ff e8 03 d3 ff ff e9 a8 fd ff ff 49 8b 97 f8 05 00 00 66 83 bb e0 f= 9 > >>>>> ff ff 0a <48> 8b 6a 18 0f 84 fd 00 00 00 48 8d 72 18 4c 89 e7 48 89= 14 > >>>>> 24 e8 > >>>>> [ 316.940719] RSP: 0018:ffffa69d40f5fdc8 EFLAGS: 00010293 > >>>>> [ 316.940786] RAX: 0000000000000000 RBX: ffff9b0c46333e40 RCX: 000= 0000000000000 > >>>>> [ 316.940872] RDX: 0000000000000000 RSI: ffffa69d40f5fd20 RDI: 000= 0000000000000 > >>>>> [ 316.940940] RBP: ffff9b0c46350200 R08: ffff9b0cf7e31968 R09: 000= 0000000000159 > >>>>> [ 316.941008] R10: 0000000000000001 R11: 00000049c8887a40 R12: fff= f9b0c46333800 > >>>>> [ 316.941075] R13: 0000000004208160 R14: ffff9b0c44e18a00 R15: fff= f9b0c42dab800 > >>>>> [ 316.941159] FS: 0000000000000000(0000) GS:ffff9b0cf7e00000(0000= ) > >>>>> knlGS:0000000000000000 > >>>>> [ 316.941243] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > >>>>> [ 316.941309] CR2: 0000000000000018 CR3: 0000000102e48004 CR4: 000= 00000007706f0 > >>>>> [ 316.941391] PKRU: 55555554 > >>>>> [ 316.941443] Call Trace: > >>>>> [ 316.941513] > >>>>> [ 316.941578] process_one_work+0x1b0/0x3c0 > >>>>> [ 316.941689] worker_thread+0x30/0x360 > >>>>> [ 316.941755] ? __pfx_worker_thread+0x10/0x10 > >>>>> [ 316.941822] kthread+0xd7/0x100 > >>>>> [ 316.941900] ? __pfx_kthread+0x10/0x10 > >>>>> [ 316.941968] ret_from_fork+0x29/0x50 > >>>>> [ 316.942049] > >>>>> [ 316.942099] Modules linked in: rpcsec_gss_krb5 auth_rpcgss nfsv4 > >>>>> dns_resolver ib_core nfsv3 nfs_acl nfs lockd grace fscache netfs ex= t4 > >>>>> rfkill mbcache jbd2 loop vsock_loopback > >>>>> vmw_vsock_virtio_transport_common vmw_vsock_vmci_transport vsock > >>>>> sunrpc tls vfat fat dm_multipath intel_rapl_msr intel_rapl_common > >>>>> isst_if_mbox_msr isst_if_common nfit libnvdimm crct10dif_pclmul > >>>>> crc32_pclmul ghash_clmulni_intel rapl vmw_balloon joydev pcspkr > >>>>> i2c_piix4 vmw_vmci xfs libcrc32c vmwgfx drm_ttm_helper ttm sr_mod > >>>>> cdrom drm_kms_helper syscopyarea sd_mod sysfillrect ata_generic > >>>>> sysimgblt sg ahci libahci ata_piix crc32c_intel serio_raw drm vmxne= t3 > >>>>> vmw_pvscsi libata dm_mirror dm_region_hash dm_log dm_mod nvme_tcp > >>>>> nvme_fabrics nvme_core t10_pi crc64_rocksoft crc64 ipmi_devintf > >>>>> ipmi_msghandler fuse > >>>>> [ 316.942550] CR2: 0000000000000018 > >>>>> > >>>>> Please note this was still on "commit > >>>>> caa52379f0046e974fd16585dd7ede624699d8e2 (HEAD -> 03152023-v7, > >>>>> origin/upcall-v7)". If you think somethings done to address it I'll > >>>>> have them update to the latest. > >>>> > >>>> Update and retry. It has a familiar ring, but I can't say I've > >>>> seen this recently. > >>> > >>> Hi Chuck, > >>> > >>> I've updated the kernel code to the latest commit > >>> 46588cade103b446f74a7ee160a83cd2a80399e7 (HEAD -> > >>> chuck-rpc-with-tls-04032023, chuck/topic-rpc-with-tls-upcall) but the > >>> client is still crashing but looks like in a different place. This > >>> happens when the server terminates the connection (immediately) as th= e > >>> tls handshake happens. > >> > >> Why is the server doing that? > > > > I'm not sure what kind of a reason you are looking for. I think the > > server can send an RST at any point in a TCP connection and the client > > shouldn't crash. > > No doubt. > > > > But the real reason is probably because the server's > > code is getting developed and they ran into some error and resetting > > the connection. > > That's what I was looking for. I wanted to know if it was > Linux NFSD doing this. > > > >>> Here's the stack trace: > >>> [ 677.274299] BUG: kernel NULL pointer dereference, address: 0000000= 000000030 > >>> [ 677.274424] #PF: supervisor read access in kernel mode > >>> [ 677.274517] #PF: error_code(0x0000) - not-present page > >>> [ 677.274609] PGD 0 P4D 0 > >>> [ 677.274689] Oops: 0000 [#1] PREEMPT SMP PTI > >>> [ 677.274785] CPU: 0 PID: 518 Comm: kworker/u2:29 Kdump: loaded Not > >>> tainted 6.3.0-rc4+ #13 > >>> [ 677.274881] Hardware name: VMware, Inc. VMware7,1/440BX Desktop > >>> Reference Platform, BIOS VMW71.00V.16707776.B64.2008070230 08/07/2020 > >>> [ 677.274981] Workqueue: xprtiod xs_tls_connect [sunrpc] > >>> [ 677.275137] RIP: 0010:handshake_req_cancel+0x2b/0x3b0 > >> > >> scripts/faddr2line on this RIP > >> > >> Which pointer is NULL? > > > > I apologize I don't have that info and I'm working on trying to figure > > out how to get this information to you. Lab kernels are built with > > CONFIG_DEBUG_INFO disabled and thus I can't do faddr2line. I will > > attempt to build on with debugging enabled (has been problematic > > before for the lab machines so not sure if that'll be successful I > > might have to hack the linux kernel to simulate the reset). > > Jakub asked that NULL checking be removed from handshake_req_cancel, > or at least that's what I read into his comment. That choice is > definitely flushing bugs. > > So this crasher is familiar. req_cancel is getting called in some > scenario where the socket or request is partially filled in. We > have to figure out how that's happening. > > If debug info is a problem, then just add a sarcastic quantity of > NULL checks in handshake_req_cancel, rebuild, and it should tell > you exactly which pointer is bad. I added a check for sock-sk null and if so return true. I thought that would "prevent" the crash but it then proceeded to crash elsewhere. Sorry I'm still on non-debug-symbol kernel (as I thought I'd add the checks that that'd be enough :)). [ 284.368211] AGLO: handshake_req_cancel sock->sk is NULL [ 284.368249] BUG: kernel NULL pointer dereference, address: 0000000000000= 018 [ 284.368320] #PF: supervisor read access in kernel mode [ 284.368363] #PF: error_code(0x0000) - not-present page [ 284.368411] PGD 0 P4D 0 [ 284.368438] Oops: 0000 [#1] PREEMPT SMP PTI [ 284.368473] CPU: 0 PID: 521 Comm: kworker/u2:30 Kdump: loaded Not tainted 6.3.0-rc4+ #14 [ 284.368523] Hardware name: VMware, Inc. VMware7,1/440BX Desktop Reference Platform, BIOS VMW71.00V.16707776.B64.2008070230 08/07/2020 [ 284.368580] Workqueue: xprtiod xs_tls_connect [sunrpc] [ 284.368720] RIP: 0010:xs_tls_connect+0x3e5/0x590 [sunrpc] [ 284.368844] Code: ff ff ff 48 2b 83 f8 fe ff ff 48 89 83 00 ff ff ff e8 bf d2 ff ff e9 a8 fd ff ff 49 8b 97 f8 05 00 00 66 83 bb e0 f9 ff ff 0a <48> 8b 6a 18 0f 84 fd 00 00 00 48 8d 72 18 4c 89 e7 48 89 14 24 e8 [ 284.368973] RSP: 0018:ffffba17c0f67dc8 EFLAGS: 00010293 [ 284.369010] RAX: 0000000000000000 RBX: ffff963143c1fe40 RCX: 00000000000= 00000 [ 284.369051] RDX: 0000000000000000 RSI: ffff9631f7e20840 RDI: ffff9631f7e= 20840 [ 284.369091] RBP: ffff9631463d8a00 R08: 0000000000000000 R09: c0000000fff= f7fff [ 284.369130] R10: 0000000000000001 R11: ffffba17c0f67bb8 R12: ffff963143c= 1f800 [ 284.369175] R13: 0000000004208160 R14: ffff963143f6f600 R15: ffff963143c= 1e000 [ 284.369259] FS: 0000000000000000(0000) GS:ffff9631f7e00000(0000) knlGS:0000000000000000 [ 284.369319] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 284.369367] CR2: 0000000000000018 CR3: 0000000102d12004 CR4: 00000000007= 706f0 [ 284.369458] PKRU: 55555554 [ 284.369483] Call Trace: [ 284.369523] [ 284.369583] process_one_work+0x1b0/0x3c0 [ 284.369633] worker_thread+0x34/0x360 [ 284.369668] ? __pfx_worker_thread+0x10/0x10 [ 284.369704] kthread+0xdb/0x110 [ 284.369736] ? __pfx_kthread+0x10/0x10 [ 284.369767] ret_from_fork+0x29/0x50 [ 284.369808] [ 284.369843] Modules linked in: rpcsec_gss_krb5 auth_rpcgss nfsv4 dns_resolver nfsv3 nfs_acl nfs lockd grace fscache netfs ext4 mbcache jbd2 loop rfkill vsock_loopback vmw_vsock_virtio_transport_common vmw_vsock_vmci_transport vsock sunrpc vfat fat dm_multipath intel_rapl_msr intel_rapl_common isst_if_mbox_msr isst_if_common nfit libnvdimm crct10dif_pclmul crc32_pclmul ghash_clmulni_intel rapl vmw_balloon joydev pcspkr vmw_vmci i2c_piix4 xfs libcrc32c vmwgfx drm_ttm_helper ttm sr_mod cdrom drm_kms_helper sd_mod syscopyarea sysfillrect ata_generic sysimgblt sg ata_piix ahci libahci crc32c_intel serio_raw vmxnet3 libata drm vmw_pvscsi dm_mirror dm_region_hash dm_log dm_mod nvme_tcp nvme_fabrics nvme_core t10_pi crc64_rocksoft crc64 ipmi_devintf ipmi_msghandler fuse [ 284.370300] CR2: 0000000000000018 > > BPF might also be a solution, but I'm not sure if it relies on > debug info. Might be only BTF is needed. > > > >>> [ 677.275269] Code: 0f 1e fa 0f 1f 44 00 00 41 57 41 56 41 55 41 54 > >>> 55 53 48 83 ec 28 48 8b 6f 18 65 48 8b 04 25 28 00 00 00 48 89 44 24 > >>> 20 31 c0 <48> 8b 5d 30 48 89 6c 24 18 e8 97 15 5f ff 4c 8b 25 50 2e 7= 0 > >>> 01 41 > >>> [ 677.275474] RSP: 0018:ffffaed400f6fcf8 EFLAGS: 00010246 > >>> [ 677.275570] RAX: 0000000000000000 RBX: ffff93f085b33800 RCX: 00000= 00000000000 > >>> [ 677.275663] RDX: ffff93f085b33f08 RSI: ffffaed400f6fd18 RDI: ffff9= 3f083aa6700 > >>> [ 677.275756] RBP: 0000000000000000 R08: ffff93f137e32968 R09: 00000= 09d9663fa40 > >>> [ 677.275850] R10: 0000000000000000 R11: 0000009d9663fa40 R12: ffff9= 3f083aa6700 > >>> [ 677.275943] R13: 0000000000000000 R14: ffff93f082999e00 R15: ffff9= 3f085b33800 > >>> [ 677.276049] FS: 0000000000000000(0000) GS:ffff93f137e00000(0000) > >>> knlGS:0000000000000000 > >>> [ 677.276154] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > >>> [ 677.276247] CR2: 0000000000000030 CR3: 000000010797c002 CR4: 00000= 000007706f0 > >>> [ 677.276355] PKRU: 55555554 > >>> [ 677.276427] Call Trace: > >>> [ 677.276521] > >>> [ 677.276605] ? wait_for_completion_interruptible_timeout+0xfa/0x17= 0 > >>> [ 677.276725] xs_tls_handshake_sync+0x14f/0x170 [sunrpc] > >>> [ 677.276850] ? __pfx_xs_tls_handshake_done+0x10/0x10 [sunrpc] > >>> [ 677.276967] xs_tls_connect+0x14c/0x590 [sunrpc] > >>> [ 677.277086] process_one_work+0x1b0/0x3c0 > >>> [ 677.277209] worker_thread+0x34/0x360 > >>> [ 677.277303] ? __pfx_worker_thread+0x10/0x10 > >>> [ 677.277396] kthread+0xdb/0x110 > >>> [ 677.277527] ? __pfx_kthread+0x10/0x10 > >>> [ 677.277619] ret_from_fork+0x29/0x50 > >>> [ 677.277731] > >>> [ 677.277803] Modules linked in: rpcsec_gss_krb5 auth_rpcgss nfsv4 > >>> dns_resolver nfsv3 nfs_acl nfs lockd grace fscache netfs ext4 mbcache > >>> jbd2 loop rfkill vsock_loopback vmw_vsock_virtio_transport_common > >>> vmw_vsock_vmci_transport vsock sunrpc vfat fat dm_multipath > >>> intel_rapl_msr intel_rapl_common isst_if_mbox_msr isst_if_common nfit > >>> libnvdimm crct10dif_pclmul crc32_pclmul ghash_clmulni_intel rapl > >>> vmw_balloon joydev pcspkr vmw_vmci i2c_piix4 xfs libcrc32c vmwgfx > >>> drm_ttm_helper ttm sr_mod cdrom drm_kms_helper syscopyarea sysfillrec= t > >>> sd_mod ata_generic sysimgblt sg ata_piix ahci libahci crc32c_intel > >>> serio_raw drm vmxnet3 vmw_pvscsi libata dm_mirror dm_region_hash > >>> dm_log dm_mod nvme_tcp nvme_fabrics nvme_core t10_pi crc64_rocksoft > >>> crc64 ipmi_devintf ipmi_msghandler fuse > >>> [ 677.278383] CR2: 0000000000000030 > >>> > >>> Network trace from the server: > >>> > >>> [kolga@scs000085536 ~/pcaps]$ tshark -t ad -r e0d_20230404_084311.trc= 0 > >>> 1 2023-04-04 08:43:28.027546 10.235.232.77 =E2=86=92 10.63.20.131 T= CP 74 > >>> 727 =E2=86=92 2049 [SYN] Seq=3D0 Win=3D64240 Len=3D0 MSS=3D1460 SACK_= PERM=3D1 > >>> TSval=3D4059503415 TSecr=3D0 WS=3D128 > >>> 2 2023-04-04 08:43:28.027645 10.63.20.131 =E2=86=92 10.235.232.77 T= CP 74 > >>> 2049 =E2=86=92 727 [SYN, ACK] Seq=3D0 Ack=3D1 Win=3D65535 Len=3D0 MSS= =3D1460 WS=3D256 > >>> SACK_PERM=3D1 TSval=3D2256845073 TSecr=3D4059503415 > >>> 3 2023-04-04 08:43:28.027813 10.235.232.77 =E2=86=92 10.63.20.131 T= CP 66 > >>> 727 =E2=86=92 2049 [ACK] Seq=3D1 Ack=3D1 Win=3D64256 Len=3D0 TSval=3D= 4059503415 > >>> TSecr=3D2256845073 > >>> 4 2023-04-04 08:43:28.027952 10.235.232.77 =E2=86=92 10.63.20.131 N= FS 110 > >>> V4 NULL Call > >>> 5 2023-04-04 08:43:28.028301 10.63.20.131 =E2=86=92 10.235.232.77 N= FS 102 > >>> V4 NULL Reply (Call In 4) > >>> 6 2023-04-04 08:43:28.028563 10.235.232.77 =E2=86=92 10.63.20.131 T= CP 66 > >>> 727 =E2=86=92 2049 [ACK] Seq=3D45 Ack=3D37 Win=3D64256 Len=3D0 TSval= =3D4059503416 > >>> TSecr=3D2256845073 > >>> 7 2023-04-04 08:43:28.331181 10.63.20.131 =E2=86=92 10.235.232.77 T= CP 66 > >>> 2049 =E2=86=92 727 [RST, ACK] Seq=3D37 Ack=3D45 Win=3D0 Len=3D0 TSval= =3D2256845383 > >>> TSecr=3D4059503416 > >>> > >>> > >>>> > >>>> > >>>> -- > >>>> Chuck Lever > >> > >> > >> -- > >> Chuck Lever > > > -- > Chuck Lever > >