| Message ID | 162066202717.94415.8666073108309704792.stgit@klimt.1015granger.net (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | NFSD callback and lease management observability | expand |
On Mon, May 10, 2021 at 11:53 AM Chuck Lever <chuck.lever@oracle.com> wrote: > > We are especially interested in capturing clientID conflicts. > > Signed-off-by: Chuck Lever <chuck.lever@oracle.com> > --- > fs/nfsd/nfs4state.c | 9 +++++++-- > fs/nfsd/trace.h | 37 +++++++++++++++++++++++++++++++++++++ > 2 files changed, 44 insertions(+), 2 deletions(-) > > diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c > index a61601fe422a..528cabffa1e9 100644 > --- a/fs/nfsd/nfs4state.c > +++ b/fs/nfsd/nfs4state.c > @@ -3180,6 +3180,7 @@ nfsd4_exchange_id(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, > } > /* case 6 */ > exid->flags |= EXCHGID4_FLAG_CONFIRMED_R; > + trace_nfsd_clid_existing(conf); > goto out_copy; > } > if (!creds_match) { /* case 3 */ > @@ -3188,15 +3189,18 @@ nfsd4_exchange_id(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, > trace_nfsd_clid_cred_mismatch(conf, rqstp); > goto out; > } > + trace_nfsd_clid_new(new); > goto out_new; > } > if (verfs_match) { /* case 2 */ > conf->cl_exchange_flags |= EXCHGID4_FLAG_CONFIRMED_R; > + trace_nfsd_clid_existing(conf); > goto out_copy; > } > /* case 5, client reboot */ > trace_nfsd_clid_verf_mismatch(conf, rqstp, &verf); > conf = NULL; > + trace_nfsd_clid_new(new); > goto out_new; > } > > @@ -3996,10 +4000,12 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, > if (same_verf(&conf->cl_verifier, &clverifier)) { > copy_clid(new, conf); > gen_confirm(new, nn); > + trace_nfsd_clid_existing(new); > } else > trace_nfsd_clid_verf_mismatch(conf, rqstp, > &clverifier); > - } > + } else > + trace_nfsd_clid_new(new); > new->cl_minorversion = 0; > gen_callback(new, setclid, rqstp); > add_to_unconfirmed(new); > @@ -4017,7 +4023,6 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, > return status; > } > > - > __be32 > nfsd4_setclientid_confirm(struct svc_rqst *rqstp, > struct nfsd4_compound_state *cstate, > diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h > index 523045c37749..6ddff13e3181 100644 > --- a/fs/nfsd/trace.h > +++ b/fs/nfsd/trace.h > @@ -626,6 +626,43 @@ TRACE_EVENT(nfsd_clid_verf_mismatch, > ) > ); > > +DECLARE_EVENT_CLASS(nfsd_clid_class, > + TP_PROTO(const struct nfs4_client *clp), > + TP_ARGS(clp), > + TP_STRUCT__entry( > + __field(u32, cl_boot) > + __field(u32, cl_id) > + __array(unsigned char, addr, sizeof(struct sockaddr_in6)) > + __field(unsigned long, flavor) > + __array(unsigned char, verifier, NFS4_VERIFIER_SIZE) > + __field(unsigned int, namelen) > + __dynamic_array(unsigned char, name, clp->cl_name.len) > + ), > + TP_fast_assign( > + memcpy(__entry->addr, &clp->cl_addr, > + sizeof(struct sockaddr_in6)); > + __entry->flavor = clp->cl_cred.cr_flavor; > + memcpy(__entry->verifier, (void *)&clp->cl_verifier, > + NFS4_VERIFIER_SIZE); > + __entry->namelen = clp->cl_name.len; > + memcpy(__get_dynamic_array(name), clp->cl_name.data, > + clp->cl_name.len); > + ), > + TP_printk("addr=%pISpc name='%.*s' verifier=0x%s flavor=%s client=%08x:%08x\n", > + __entry->addr, __entry->namelen, __get_str(name), > + __print_hex_str(__entry->verifier, NFS4_VERIFIER_SIZE), > + show_nfsd_authflavor(__entry->flavor), > + __entry->cl_boot, __entry->cl_id) > +); > + > +#define DEFINE_CLID_EVENT(name) \ > +DEFINE_EVENT(nfsd_clid_class, nfsd_clid_##name, \ > + TP_PROTO(const struct nfs4_client *clp), \ > + TP_ARGS(clp)) > + > +DEFINE_CLID_EVENT(new); > +DEFINE_CLID_EVENT(existing); > + > /* > * from fs/nfsd/filecache.h > */ > > I just got this oops when testing duplicate hostnames and having enabled these tracepoints with: trace-cmd start -e nfsd:nfsd_clid* [ 408.119259] ------------[ cut here ]------------ [ 408.136659] fmt: 'addr=%pISpc name='%.*s' verifier=0x%s flavor=%s client=%08x:%08x [ 408.136659] [ 408.136659] ' current_buffer: ' nfsd-1117 [001] .... 408.844043: nfsd_clid_new: addr=192.168.122.8:676 name='' [ 408.136831] WARNING: CPU: 4 PID: 15097 at kernel/trace/trace.c:3759 trace_check_vprintf+0x9f9/0x1040 [ 408.149530] Modules linked in: nft_fib_inet nft_fib_ipv4 nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 nft_reject nft_ct nft_chain_nat nf_tables ebtable_nat ebtable_broute ip6table_nat ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 iptable_mangle iptable_raw iptable_security ip_set rfkill nfnetlink ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter cachefiles intel_rapl_msr intel_rapl_common joydev virtio_balloon nfsd i2c_piix4 auth_rpcgss nfs_acl lockd grace sunrpc drm ip_tables xfs libcrc32c crct10dif_pclmul crc32_pclmul crc32c_intel virtio_net ata_generic ghash_clmulni_intel net_failover virtio_console serio_raw pata_acpi virtio_blk failover qemu_fw_cfg [ 408.176536] CPU: 4 PID: 15097 Comm: trace-cmd Kdump: loaded Not tainted 5.13.0-rc1-chuck-nfsd+ #12 [ 408.180288] Hardware name: Red Hat KVM, BIOS 0.5.1 01/01/2011 [ 408.182731] RIP: 0010:trace_check_vprintf+0x9f9/0x1040 [ 408.184912] Code: 00 00 49 8b 94 24 b0 20 00 00 48 8b 74 24 30 4c 89 4c 24 18 48 c7 c7 00 65 6c ba 44 89 44 24 10 4c 89 54 24 08 e8 e5 a2 bd 01 <0f> 0b 4c 8b 54 24 08 44 8b 44 24 10 4c 8b 4c 24 18 e9 c8 fc ff ff [ 408.192521] RSP: 0018:ffff888115617a30 EFLAGS: 00010282 [ 408.194732] RAX: 0000000000000000 RBX: 0000000000000013 RCX: 0000000000000000 [ 408.197706] RDX: 0000000000000027 RSI: 0000000000000004 RDI: ffffed1022ac2f3c [ 408.200667] RBP: dffffc0000000000 R08: 0000000000000001 R09: ffff8881e3d20a0b [ 408.203621] R10: ffffed103c7a4141 R11: 0000000000000001 R12: ffff888110984000 [ 408.206571] R13: ffffffffc0ef9b80 R14: ffff8881109850b0 R15: ffff8881109860b0 [ 408.209537] FS: 00007fc70350b740(0000) GS:ffff8881e3d00000(0000) knlGS:0000000000000000 [ 408.212887] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 408.215297] CR2: 00005638a21aa9c8 CR3: 000000010c53a000 CR4: 00000000000406e0 [ 408.218245] Call Trace: [ 408.219335] trace_event_printf+0x9d/0xc0 [ 408.221041] ? trace_print_hex_dump_seq+0x120/0x120 [ 408.223137] trace_raw_output_nfsd_clid_class+0x175/0x1f0 [nfsd] [ 408.225936] print_trace_line+0x75c/0x1430 [ 408.227709] ? tracing_buffers_read+0x820/0x820 [ 408.229637] ? _raw_spin_unlock_irqrestore+0xa/0x20 [ 408.231710] ? trace_find_next_entry_inc+0x10f/0x1b0 [ 408.233815] s_show+0xc1/0x3d0 [ 408.235431] seq_read_iter+0x93c/0xfe0 [ 408.237042] ? lru_cache_add+0x176/0x290 [ 408.238722] seq_read+0x311/0x4c0 [ 408.246280] ? seq_read_iter+0xfe0/0xfe0 [ 408.247937] ? vm_iomap_memory+0x1d0/0x1d0 [ 408.249705] ? inode_security+0x43/0xe0 [ 408.251393] vfs_read+0x111/0x400 [ 408.252841] ksys_read+0xdd/0x1a0 [ 408.254279] ? __ia32_sys_pwrite64+0x1b0/0x1b0 [ 408.256138] do_syscall_64+0x40/0x80 [ 408.257670] entry_SYSCALL_64_after_hwframe+0x44/0xae [ 408.259767] RIP: 0033:0x7fc703600442
> [ 408.223137] trace_raw_output_nfsd_clid_class+0x175/0x1f0 [nfsd] That's from the newest patch, so not surprising. I'll have a look. > On May 10, 2021, at 3:56 PM, David Wysochanski <dwysocha@redhat.com> wrote: > > On Mon, May 10, 2021 at 11:53 AM Chuck Lever <chuck.lever@oracle.com> wrote: >> >> We are especially interested in capturing clientID conflicts. >> >> Signed-off-by: Chuck Lever <chuck.lever@oracle.com> >> --- >> fs/nfsd/nfs4state.c | 9 +++++++-- >> fs/nfsd/trace.h | 37 +++++++++++++++++++++++++++++++++++++ >> 2 files changed, 44 insertions(+), 2 deletions(-) >> >> diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c >> index a61601fe422a..528cabffa1e9 100644 >> --- a/fs/nfsd/nfs4state.c >> +++ b/fs/nfsd/nfs4state.c >> @@ -3180,6 +3180,7 @@ nfsd4_exchange_id(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, >> } >> /* case 6 */ >> exid->flags |= EXCHGID4_FLAG_CONFIRMED_R; >> + trace_nfsd_clid_existing(conf); >> goto out_copy; >> } >> if (!creds_match) { /* case 3 */ >> @@ -3188,15 +3189,18 @@ nfsd4_exchange_id(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, >> trace_nfsd_clid_cred_mismatch(conf, rqstp); >> goto out; >> } >> + trace_nfsd_clid_new(new); >> goto out_new; >> } >> if (verfs_match) { /* case 2 */ >> conf->cl_exchange_flags |= EXCHGID4_FLAG_CONFIRMED_R; >> + trace_nfsd_clid_existing(conf); >> goto out_copy; >> } >> /* case 5, client reboot */ >> trace_nfsd_clid_verf_mismatch(conf, rqstp, &verf); >> conf = NULL; >> + trace_nfsd_clid_new(new); >> goto out_new; >> } >> >> @@ -3996,10 +4000,12 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, >> if (same_verf(&conf->cl_verifier, &clverifier)) { >> copy_clid(new, conf); >> gen_confirm(new, nn); >> + trace_nfsd_clid_existing(new); >> } else >> trace_nfsd_clid_verf_mismatch(conf, rqstp, >> &clverifier); >> - } >> + } else >> + trace_nfsd_clid_new(new); >> new->cl_minorversion = 0; >> gen_callback(new, setclid, rqstp); >> add_to_unconfirmed(new); >> @@ -4017,7 +4023,6 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, >> return status; >> } >> >> - >> __be32 >> nfsd4_setclientid_confirm(struct svc_rqst *rqstp, >> struct nfsd4_compound_state *cstate, >> diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h >> index 523045c37749..6ddff13e3181 100644 >> --- a/fs/nfsd/trace.h >> +++ b/fs/nfsd/trace.h >> @@ -626,6 +626,43 @@ TRACE_EVENT(nfsd_clid_verf_mismatch, >> ) >> ); >> >> +DECLARE_EVENT_CLASS(nfsd_clid_class, >> + TP_PROTO(const struct nfs4_client *clp), >> + TP_ARGS(clp), >> + TP_STRUCT__entry( >> + __field(u32, cl_boot) >> + __field(u32, cl_id) >> + __array(unsigned char, addr, sizeof(struct sockaddr_in6)) >> + __field(unsigned long, flavor) >> + __array(unsigned char, verifier, NFS4_VERIFIER_SIZE) >> + __field(unsigned int, namelen) >> + __dynamic_array(unsigned char, name, clp->cl_name.len) >> + ), >> + TP_fast_assign( >> + memcpy(__entry->addr, &clp->cl_addr, >> + sizeof(struct sockaddr_in6)); >> + __entry->flavor = clp->cl_cred.cr_flavor; >> + memcpy(__entry->verifier, (void *)&clp->cl_verifier, >> + NFS4_VERIFIER_SIZE); >> + __entry->namelen = clp->cl_name.len; >> + memcpy(__get_dynamic_array(name), clp->cl_name.data, >> + clp->cl_name.len); >> + ), >> + TP_printk("addr=%pISpc name='%.*s' verifier=0x%s flavor=%s client=%08x:%08x\n", >> + __entry->addr, __entry->namelen, __get_str(name), >> + __print_hex_str(__entry->verifier, NFS4_VERIFIER_SIZE), >> + show_nfsd_authflavor(__entry->flavor), >> + __entry->cl_boot, __entry->cl_id) >> +); >> + >> +#define DEFINE_CLID_EVENT(name) \ >> +DEFINE_EVENT(nfsd_clid_class, nfsd_clid_##name, \ >> + TP_PROTO(const struct nfs4_client *clp), \ >> + TP_ARGS(clp)) >> + >> +DEFINE_CLID_EVENT(new); >> +DEFINE_CLID_EVENT(existing); >> + >> /* >> * from fs/nfsd/filecache.h >> */ >> >> > > I just got this oops when testing duplicate hostnames and having > enabled these tracepoints with: > trace-cmd start -e nfsd:nfsd_clid* > > [ 408.119259] ------------[ cut here ]------------ > [ 408.136659] fmt: 'addr=%pISpc name='%.*s' verifier=0x%s flavor=%s > client=%08x:%08x > [ 408.136659] > [ 408.136659] ' current_buffer: ' nfsd-1117 [001] .... > 408.844043: nfsd_clid_new: addr=192.168.122.8:676 name='' > [ 408.136831] WARNING: CPU: 4 PID: 15097 at kernel/trace/trace.c:3759 > trace_check_vprintf+0x9f9/0x1040 > [ 408.149530] Modules linked in: nft_fib_inet nft_fib_ipv4 > nft_fib_ipv6 nft_fib nft_reject_inet nf_reject_ipv4 nf_reject_ipv6 > nft_reject nft_ct nft_chain_nat nf_tables ebtable_nat ebtable_broute > ip6table_nat ip6table_mangle ip6table_raw ip6table_security > iptable_nat nf_nat nf_conntrack nf_defrag_ipv6 nf_defrag_ipv4 > iptable_mangle iptable_raw iptable_security ip_set rfkill nfnetlink > ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter > cachefiles intel_rapl_msr intel_rapl_common joydev virtio_balloon nfsd > i2c_piix4 auth_rpcgss nfs_acl lockd grace sunrpc drm ip_tables xfs > libcrc32c crct10dif_pclmul crc32_pclmul crc32c_intel virtio_net > ata_generic ghash_clmulni_intel net_failover virtio_console serio_raw > pata_acpi virtio_blk failover qemu_fw_cfg > [ 408.176536] CPU: 4 PID: 15097 Comm: trace-cmd Kdump: loaded Not > tainted 5.13.0-rc1-chuck-nfsd+ #12 > [ 408.180288] Hardware name: Red Hat KVM, BIOS 0.5.1 01/01/2011 > [ 408.182731] RIP: 0010:trace_check_vprintf+0x9f9/0x1040 > [ 408.184912] Code: 00 00 49 8b 94 24 b0 20 00 00 48 8b 74 24 30 4c > 89 4c 24 18 48 c7 c7 00 65 6c ba 44 89 44 24 10 4c 89 54 24 08 e8 e5 > a2 bd 01 <0f> 0b 4c 8b 54 24 08 44 8b 44 24 10 4c 8b 4c 24 18 e9 c8 fc > ff ff > [ 408.192521] RSP: 0018:ffff888115617a30 EFLAGS: 00010282 > [ 408.194732] RAX: 0000000000000000 RBX: 0000000000000013 RCX: 0000000000000000 > [ 408.197706] RDX: 0000000000000027 RSI: 0000000000000004 RDI: ffffed1022ac2f3c > [ 408.200667] RBP: dffffc0000000000 R08: 0000000000000001 R09: ffff8881e3d20a0b > [ 408.203621] R10: ffffed103c7a4141 R11: 0000000000000001 R12: ffff888110984000 > [ 408.206571] R13: ffffffffc0ef9b80 R14: ffff8881109850b0 R15: ffff8881109860b0 > [ 408.209537] FS: 00007fc70350b740(0000) GS:ffff8881e3d00000(0000) > knlGS:0000000000000000 > [ 408.212887] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 408.215297] CR2: 00005638a21aa9c8 CR3: 000000010c53a000 CR4: 00000000000406e0 > [ 408.218245] Call Trace: > [ 408.219335] trace_event_printf+0x9d/0xc0 > [ 408.221041] ? trace_print_hex_dump_seq+0x120/0x120 > [ 408.223137] trace_raw_output_nfsd_clid_class+0x175/0x1f0 [nfsd] > [ 408.225936] print_trace_line+0x75c/0x1430 > [ 408.227709] ? tracing_buffers_read+0x820/0x820 > [ 408.229637] ? _raw_spin_unlock_irqrestore+0xa/0x20 > [ 408.231710] ? trace_find_next_entry_inc+0x10f/0x1b0 > [ 408.233815] s_show+0xc1/0x3d0 > [ 408.235431] seq_read_iter+0x93c/0xfe0 > [ 408.237042] ? lru_cache_add+0x176/0x290 > [ 408.238722] seq_read+0x311/0x4c0 > [ 408.246280] ? seq_read_iter+0xfe0/0xfe0 > [ 408.247937] ? vm_iomap_memory+0x1d0/0x1d0 > [ 408.249705] ? inode_security+0x43/0xe0 > [ 408.251393] vfs_read+0x111/0x400 > [ 408.252841] ksys_read+0xdd/0x1a0 > [ 408.254279] ? __ia32_sys_pwrite64+0x1b0/0x1b0 > [ 408.256138] do_syscall_64+0x40/0x80 > [ 408.257670] entry_SYSCALL_64_after_hwframe+0x44/0xae > [ 408.259767] RIP: 0033:0x7fc703600442 > -- Chuck Lever
As Dave reported yesterday, this patch is unfinished and is probably junk. But any thoughts on how the tracepoints should be organized in this code would help. So I was thinking we probably want a tracepoint to fire for each case that is handled in this code (and in nfsd4_exchangeid). However, this comment in nfsd4_setclientid: /* Cases below refer to rfc 3530 section 14.2.33: */ Is confusing. - RFC 3530 is superceded by RFC 7530, and the section numbers have changed. - The cases in this section in both RFCs aren't numbered, they are bullet points. > On May 10, 2021, at 11:53 AM, Chuck Lever <chuck.lever@oracle.com> wrote: > > We are especially interested in capturing clientID conflicts. > > Signed-off-by: Chuck Lever <chuck.lever@oracle.com> > --- > fs/nfsd/nfs4state.c | 9 +++++++-- > fs/nfsd/trace.h | 37 +++++++++++++++++++++++++++++++++++++ > 2 files changed, 44 insertions(+), 2 deletions(-) > > diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c > index a61601fe422a..528cabffa1e9 100644 > --- a/fs/nfsd/nfs4state.c > +++ b/fs/nfsd/nfs4state.c > @@ -3180,6 +3180,7 @@ nfsd4_exchange_id(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, > } > /* case 6 */ > exid->flags |= EXCHGID4_FLAG_CONFIRMED_R; > + trace_nfsd_clid_existing(conf); > goto out_copy; > } > if (!creds_match) { /* case 3 */ > @@ -3188,15 +3189,18 @@ nfsd4_exchange_id(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, > trace_nfsd_clid_cred_mismatch(conf, rqstp); > goto out; > } > + trace_nfsd_clid_new(new); > goto out_new; > } > if (verfs_match) { /* case 2 */ > conf->cl_exchange_flags |= EXCHGID4_FLAG_CONFIRMED_R; > + trace_nfsd_clid_existing(conf); > goto out_copy; > } > /* case 5, client reboot */ > trace_nfsd_clid_verf_mismatch(conf, rqstp, &verf); > conf = NULL; > + trace_nfsd_clid_new(new); > goto out_new; > } > > @@ -3996,10 +4000,12 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, > if (same_verf(&conf->cl_verifier, &clverifier)) { > copy_clid(new, conf); > gen_confirm(new, nn); > + trace_nfsd_clid_existing(new); > } else > trace_nfsd_clid_verf_mismatch(conf, rqstp, > &clverifier); > - } > + } else > + trace_nfsd_clid_new(new); > new->cl_minorversion = 0; > gen_callback(new, setclid, rqstp); > add_to_unconfirmed(new); > @@ -4017,7 +4023,6 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, > return status; > } > > - > __be32 > nfsd4_setclientid_confirm(struct svc_rqst *rqstp, > struct nfsd4_compound_state *cstate, > diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h > index 523045c37749..6ddff13e3181 100644 > --- a/fs/nfsd/trace.h > +++ b/fs/nfsd/trace.h > @@ -626,6 +626,43 @@ TRACE_EVENT(nfsd_clid_verf_mismatch, > ) > ); > > +DECLARE_EVENT_CLASS(nfsd_clid_class, > + TP_PROTO(const struct nfs4_client *clp), > + TP_ARGS(clp), > + TP_STRUCT__entry( > + __field(u32, cl_boot) > + __field(u32, cl_id) > + __array(unsigned char, addr, sizeof(struct sockaddr_in6)) > + __field(unsigned long, flavor) > + __array(unsigned char, verifier, NFS4_VERIFIER_SIZE) > + __field(unsigned int, namelen) > + __dynamic_array(unsigned char, name, clp->cl_name.len) > + ), > + TP_fast_assign( > + memcpy(__entry->addr, &clp->cl_addr, > + sizeof(struct sockaddr_in6)); > + __entry->flavor = clp->cl_cred.cr_flavor; > + memcpy(__entry->verifier, (void *)&clp->cl_verifier, > + NFS4_VERIFIER_SIZE); > + __entry->namelen = clp->cl_name.len; > + memcpy(__get_dynamic_array(name), clp->cl_name.data, > + clp->cl_name.len); > + ), > + TP_printk("addr=%pISpc name='%.*s' verifier=0x%s flavor=%s client=%08x:%08x\n", > + __entry->addr, __entry->namelen, __get_str(name), > + __print_hex_str(__entry->verifier, NFS4_VERIFIER_SIZE), > + show_nfsd_authflavor(__entry->flavor), > + __entry->cl_boot, __entry->cl_id) > +); > + > +#define DEFINE_CLID_EVENT(name) \ > +DEFINE_EVENT(nfsd_clid_class, nfsd_clid_##name, \ > + TP_PROTO(const struct nfs4_client *clp), \ > + TP_ARGS(clp)) > + > +DEFINE_CLID_EVENT(new); > +DEFINE_CLID_EVENT(existing); > + > /* > * from fs/nfsd/filecache.h > */ > > -- Chuck Lever
On Tue, May 11, 2021 at 03:59:00PM +0000, Chuck Lever III wrote: > As Dave reported yesterday, this patch is unfinished and is probably > junk. But any thoughts on how the tracepoints should be organized > in this code would help. > > So I was thinking we probably want a tracepoint to fire for each > case that is handled in this code (and in nfsd4_exchangeid). > However, this comment in nfsd4_setclientid: > > /* Cases below refer to rfc 3530 section 14.2.33: */ > > Is confusing. > > - RFC 3530 is superceded by RFC 7530, and the section numbers have changed. > > - The cases in this section in both RFCs aren't numbered, they are > bullet points. Honestly I think those particular comments should just go. The code doesn't even follow those bullet points very closely any more. --b. diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c index f47f72bc871f..2aa5d15b08ed 100644 --- a/fs/nfsd/nfs4state.c +++ b/fs/nfsd/nfs4state.c @@ -3954,11 +3954,9 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, new = create_client(clname, rqstp, &clverifier); if (new == NULL) return nfserr_jukebox; - /* Cases below refer to rfc 3530 section 14.2.33: */ spin_lock(&nn->client_lock); conf = find_confirmed_client_by_name(&clname, nn); if (conf && client_has_state(conf)) { - /* case 0: */ status = nfserr_clid_inuse; if (clp_used_exchangeid(conf)) goto out; @@ -3970,7 +3968,6 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, unconf = find_unconfirmed_client_by_name(&clname, nn); if (unconf) unhash_client_locked(unconf); - /* We need to handle only case 1: probable callback update */ if (conf && same_verf(&conf->cl_verifier, &clverifier)) { copy_clid(new, conf); gen_confirm(new, nn);
> On May 11, 2021, at 1:38 PM, Bruce Fields <bfields@fieldses.org> wrote: > > On Tue, May 11, 2021 at 03:59:00PM +0000, Chuck Lever III wrote: >> As Dave reported yesterday, this patch is unfinished and is probably >> junk. But any thoughts on how the tracepoints should be organized >> in this code would help. >> >> So I was thinking we probably want a tracepoint to fire for each >> case that is handled in this code (and in nfsd4_exchangeid). >> However, this comment in nfsd4_setclientid: >> >> /* Cases below refer to rfc 3530 section 14.2.33: */ >> >> Is confusing. >> >> - RFC 3530 is superceded by RFC 7530, and the section numbers have changed. >> >> - The cases in this section in both RFCs aren't numbered, they are >> bullet points. > > Honestly I think those particular comments should just go. The code > doesn't even follow those bullet points very closely any more. OK, I'll squash this in, and include similar changes to nfsd4_setclientid_confirm(). > --b. > > diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c > index f47f72bc871f..2aa5d15b08ed 100644 > --- a/fs/nfsd/nfs4state.c > +++ b/fs/nfsd/nfs4state.c > @@ -3954,11 +3954,9 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, > new = create_client(clname, rqstp, &clverifier); > if (new == NULL) > return nfserr_jukebox; > - /* Cases below refer to rfc 3530 section 14.2.33: */ > spin_lock(&nn->client_lock); > conf = find_confirmed_client_by_name(&clname, nn); > if (conf && client_has_state(conf)) { > - /* case 0: */ > status = nfserr_clid_inuse; > if (clp_used_exchangeid(conf)) > goto out; > @@ -3970,7 +3968,6 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, > unconf = find_unconfirmed_client_by_name(&clname, nn); > if (unconf) > unhash_client_locked(unconf); > - /* We need to handle only case 1: probable callback update */ > if (conf && same_verf(&conf->cl_verifier, &clverifier)) { > copy_clid(new, conf); > gen_confirm(new, nn); -- Chuck Lever
On Tue, May 11, 2021 at 05:40:20PM +0000, Chuck Lever III wrote: > > > > On May 11, 2021, at 1:38 PM, Bruce Fields <bfields@fieldses.org> wrote: > > > > On Tue, May 11, 2021 at 03:59:00PM +0000, Chuck Lever III wrote: > >> As Dave reported yesterday, this patch is unfinished and is probably > >> junk. But any thoughts on how the tracepoints should be organized > >> in this code would help. > >> > >> So I was thinking we probably want a tracepoint to fire for each > >> case that is handled in this code (and in nfsd4_exchangeid). > >> However, this comment in nfsd4_setclientid: > >> > >> /* Cases below refer to rfc 3530 section 14.2.33: */ > >> > >> Is confusing. > >> > >> - RFC 3530 is superceded by RFC 7530, and the section numbers have changed. > >> > >> - The cases in this section in both RFCs aren't numbered, they are > >> bullet points. > > > > Honestly I think those particular comments should just go. The code > > doesn't even follow those bullet points very closely any more. > > OK, I'll squash this in, and include similar changes to > nfsd4_setclientid_confirm(). The setclientid_confirm cases are a little more complicated and I think the code there may map more closely to the RFC bullet points. But I'm not particularly attached to them, feel free to use your judgement for those.... --b. > > > > --b. > > > > diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c > > index f47f72bc871f..2aa5d15b08ed 100644 > > --- a/fs/nfsd/nfs4state.c > > +++ b/fs/nfsd/nfs4state.c > > @@ -3954,11 +3954,9 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, > > new = create_client(clname, rqstp, &clverifier); > > if (new == NULL) > > return nfserr_jukebox; > > - /* Cases below refer to rfc 3530 section 14.2.33: */ > > spin_lock(&nn->client_lock); > > conf = find_confirmed_client_by_name(&clname, nn); > > if (conf && client_has_state(conf)) { > > - /* case 0: */ > > status = nfserr_clid_inuse; > > if (clp_used_exchangeid(conf)) > > goto out; > > @@ -3970,7 +3968,6 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, > > unconf = find_unconfirmed_client_by_name(&clname, nn); > > if (unconf) > > unhash_client_locked(unconf); > > - /* We need to handle only case 1: probable callback update */ > > if (conf && same_verf(&conf->cl_verifier, &clverifier)) { > > copy_clid(new, conf); > > gen_confirm(new, nn); > > -- > Chuck Lever > >
diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c index a61601fe422a..528cabffa1e9 100644 --- a/fs/nfsd/nfs4state.c +++ b/fs/nfsd/nfs4state.c @@ -3180,6 +3180,7 @@ nfsd4_exchange_id(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, } /* case 6 */ exid->flags |= EXCHGID4_FLAG_CONFIRMED_R; + trace_nfsd_clid_existing(conf); goto out_copy; } if (!creds_match) { /* case 3 */ @@ -3188,15 +3189,18 @@ nfsd4_exchange_id(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, trace_nfsd_clid_cred_mismatch(conf, rqstp); goto out; } + trace_nfsd_clid_new(new); goto out_new; } if (verfs_match) { /* case 2 */ conf->cl_exchange_flags |= EXCHGID4_FLAG_CONFIRMED_R; + trace_nfsd_clid_existing(conf); goto out_copy; } /* case 5, client reboot */ trace_nfsd_clid_verf_mismatch(conf, rqstp, &verf); conf = NULL; + trace_nfsd_clid_new(new); goto out_new; } @@ -3996,10 +4000,12 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, if (same_verf(&conf->cl_verifier, &clverifier)) { copy_clid(new, conf); gen_confirm(new, nn); + trace_nfsd_clid_existing(new); } else trace_nfsd_clid_verf_mismatch(conf, rqstp, &clverifier); - } + } else + trace_nfsd_clid_new(new); new->cl_minorversion = 0; gen_callback(new, setclid, rqstp); add_to_unconfirmed(new); @@ -4017,7 +4023,6 @@ nfsd4_setclientid(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, return status; } - __be32 nfsd4_setclientid_confirm(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate, diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h index 523045c37749..6ddff13e3181 100644 --- a/fs/nfsd/trace.h +++ b/fs/nfsd/trace.h @@ -626,6 +626,43 @@ TRACE_EVENT(nfsd_clid_verf_mismatch, ) ); +DECLARE_EVENT_CLASS(nfsd_clid_class, + TP_PROTO(const struct nfs4_client *clp), + TP_ARGS(clp), + TP_STRUCT__entry( + __field(u32, cl_boot) + __field(u32, cl_id) + __array(unsigned char, addr, sizeof(struct sockaddr_in6)) + __field(unsigned long, flavor) + __array(unsigned char, verifier, NFS4_VERIFIER_SIZE) + __field(unsigned int, namelen) + __dynamic_array(unsigned char, name, clp->cl_name.len) + ), + TP_fast_assign( + memcpy(__entry->addr, &clp->cl_addr, + sizeof(struct sockaddr_in6)); + __entry->flavor = clp->cl_cred.cr_flavor; + memcpy(__entry->verifier, (void *)&clp->cl_verifier, + NFS4_VERIFIER_SIZE); + __entry->namelen = clp->cl_name.len; + memcpy(__get_dynamic_array(name), clp->cl_name.data, + clp->cl_name.len); + ), + TP_printk("addr=%pISpc name='%.*s' verifier=0x%s flavor=%s client=%08x:%08x\n", + __entry->addr, __entry->namelen, __get_str(name), + __print_hex_str(__entry->verifier, NFS4_VERIFIER_SIZE), + show_nfsd_authflavor(__entry->flavor), + __entry->cl_boot, __entry->cl_id) +); + +#define DEFINE_CLID_EVENT(name) \ +DEFINE_EVENT(nfsd_clid_class, nfsd_clid_##name, \ + TP_PROTO(const struct nfs4_client *clp), \ + TP_ARGS(clp)) + +DEFINE_CLID_EVENT(new); +DEFINE_CLID_EVENT(existing); + /* * from fs/nfsd/filecache.h */
We are especially interested in capturing clientID conflicts. Signed-off-by: Chuck Lever <chuck.lever@oracle.com> --- fs/nfsd/nfs4state.c | 9 +++++++-- fs/nfsd/trace.h | 37 +++++++++++++++++++++++++++++++++++++ 2 files changed, 44 insertions(+), 2 deletions(-)