Here is the updated patch - seems to work. See attached.
# |||| / delay
# TASK-PID CPU# ||||| TIMESTAMP FUNCTION
# | | | ||||| | |
mount.cifs-14551 [005] ..... 7636.547906: smb3_connect_done:
conn_id=0x1 server=localhost addr=127.0.0.1:445
mount.cifs-14558 [004] ..... 7642.405413: smb3_connect_done:
conn_id=0x2 server=smfrench.file.core.windows.net
addr=52.239.158.232:445
mount.cifs-14741 [005] ..... 7818.490716: smb3_connect_done:
conn_id=0x3 server=::1 addr=[::1]:445/0%0
mount.cifs-14810 [000] ..... 7966.380337: smb3_connect_err:
rc=-101 conn_id=0x4 server=::2 addr=[::2]:445/0%0
mount.cifs-14810 [000] ..... 7966.380356: smb3_connect_err:
rc=-101 conn_id=0x4 server=::2 addr=[::2]:139/0%0
mount.cifs-14818 [003] ..... 7986.771992: smb3_connect_done:
conn_id=0x5 server=127.0.0.9 addr=127.0.0.9:445
mount.cifs-14825 [008] ..... 8008.178109: smb3_connect_err:
rc=-115 conn_id=0x6 server=124.23.0.9 addr=124.23.0.9:445
mount.cifs-14825 [008] ..... 8013.298085: smb3_connect_err:
rc=-115 conn_id=0x6 server=124.23.0.9 addr=124.23.0.9:139
cifsd-14553 [006] ..... 8036.735615: smb3_reconnect:
conn_id=0x1 server=localhost current_mid=32
cifsd-14743 [010] ..... 8036.735644: smb3_reconnect:
conn_id=0x3 server=::1 current_mid=29
cifsd-14743 [010] ..... 8036.735686: smb3_connect_err:
rc=-111 conn_id=0x3 server=::1 addr=[::1]:445/0%0
cifsd-14553 [008] ..... 8036.737867: smb3_connect_err:
rc=-111 conn_id=0x1 server=localhost addr=127.0.0.1:445
cifsd-14743 [010] ..... 8039.921740: smb3_connect_err:
rc=-111 conn_id=0x3 server=::1 addr=[::1]:445/0%0
cifsd-14553 [008] ..... 8039.921743: smb3_connect_err:
rc=-111 conn_id=0x1 server=localhost addr=127.0.0.1:445
cifsd-14553 [008] ..... 8042.993894: smb3_connect_err:
rc=-111 conn_id=0x1 server=localhost addr=127.0.0.1:445
cifsd-14743 [010] ..... 8042.993894: smb3_connect_err:
rc=-111 conn_id=0x3 server=::1 addr=[::1]:445/0%0
cifsd-14553 [008] ..... 8046.065824: smb3_connect_err:
rc=-111 conn_id=0x1 server=localhost addr=127.0.0.1:445
cifsd-14743 [010] ..... 8046.065824: smb3_connect_err:
rc=-111 conn_id=0x3 server=::1 addr=[::1]:445/0%0
cifsd-14553 [008] ..... 8049.137796: smb3_connect_done:
conn_id=0x1 server=localhost addr=127.0.0.1:445
cifsd-14743 [010] ..... 8049.137796: smb3_connect_done:
conn_id=0x3 server=::1 addr=[::1]:445/0%0
On Thu, Nov 4, 2021 at 12:07 PM Stefan Metzmacher <metze@xxxxxxxxx> wrote:
>
> Am 04.11.21 um 18:02 schrieb Stefan Metzmacher:
> > I looked at my smbdirect dirver code and there I use:
> >
> > TP_STRUCT__entry(
> > ...
> > __array(__u8, addr, sizeof(struct sockaddr_storage))
> > ),
> > TP_fast_assign(
>
> Here I missed the 'struct sockaddr_storage *pss = NULL;' helper variable...
> > pss = (struct sockaddr_storage *)__entry->addr;
> > *pss = *addr;
> > ),
> > TP_printk("... %pISp",
> > __entry->addr)
>
> My full example is here:
>
> https://git.samba.org/?p=metze/linux/smbdirect.git;a=blob;f=smbdirect_trace.h;hb=refs/heads/smbdirect-work-in-progress#l100
>
> metze
>
> > Am 04.11.21 um 16:26 schrieb Steve French:
> >> changing it to __kernel_sockaddr_storage the build error is:
> >>
> >> from /home/smfrench/cifs-2.6/fs/cifs/trace.c:8:
> >> /home/smfrench/cifs-2.6/fs/cifs/./trace.h:867:32: error: conversion to
> >> non-scalar type requested
> >> 867 | __field(struct __kernel_sockaddr_storage, dst_addr)
> >> | ^~~~~~~~~~~~~~~~~~~~~~~~~
> >> ./include/trace/trace_events.h:477:9: note: in definition of macro
> >> ‘DECLARE_EVENT_CLASS’
> >> 477 | tstruct
> >> \
> >> | ^~~~~~~
> >> /home/smfrench/cifs-2.6/fs/cifs/./trace.h:864:9: note: in expansion of
> >> macro ‘TP_STRUCT__entry’
> >> 864 | TP_STRUCT__entry(
> >>
> >> On Thu, Nov 4, 2021 at 10:09 AM Steve French <smfrench@xxxxxxxxx> wrote:
> >>>
> >>> That looked like a good suggestion and will make the code cleaner but
> >>> with that change ran into this unexpected build error. Ideas?
> >>>
> >>> CC [M] /home/smfrench/cifs-2.6/fs/cifs/file.o
> >>> In file included from ./include/trace/define_trace.h:102,
> >>> from /home/smfrench/cifs-2.6/fs/cifs/trace.h:977,
> >>> from /home/smfrench/cifs-2.6/fs/cifs/trace.c:8:
> >>> ./include/linux/socket.h:42:26: error: conversion to non-scalar type requested
> >>> 42 | #define sockaddr_storage __kernel_sockaddr_storage
> >>> | ^~~~~~~~~~~~~~~~~~~~~~~~~
> >>> ./include/trace/trace_events.h:477:9: note: in definition of macro
> >>> ‘DECLARE_EVENT_CLASS’
> >>> 477 | tstruct
> >>> \
> >>> | ^~~~~~~
> >>> /home/smfrench/cifs-2.6/fs/cifs/./trace.h:864:9: note: in expansion of
> >>> macro ‘TP_STRUCT__entry’
> >>> 864 | TP_STRUCT__entry(
> >>> | ^~~~~~~~~~~~~~~~
> >>> ./include/trace/trace_events.h:439:22: note: in expansion of macro
> >>> ‘is_signed_type’
> >>> 439 | .is_signed = is_signed_type(_type), .filter_type =
> >>> _filter_type },
> >>> | ^~~~~~~~~~~~~~
> >>> ./include/trace/trace_events.h:448:33: note: in expansion of macro ‘__field_ext’
> >>> 448 | #define __field(type, item) __field_ext(type, item, FILTER_OTHER)
> >>> | ^~~~~~~~~~~
> >>> /home/smfrench/cifs-2.6/fs/cifs/./trace.h:867:17: note: in expansion
> >>> of macro ‘__field’
> >>> 867 | __field(struct sockaddr_storage, dst_addr)
> >>> | ^~~~~~~
> >>> /home/smfrench/cifs-2.6/fs/cifs/./trace.h:867:32: note: in expansion
> >>> of macro ‘sockaddr_storage’
> >>> 867 | __field(struct sockaddr_storage, dst_addr)
> >>>
> >>> On Thu, Nov 4, 2021 at 2:14 AM Stefan Metzmacher <metze@xxxxxxxxx> wrote:
> >>>>
> >>>> Hi Steve,
> >>>>
> >>>> you should made this generic (not ipv4/ipv6 specific) and use something like this:
> >>>>
> >>>> TP_PROTO(const char *hostname, __u64 conn_id, const struct sockaddr_storage *dst_addr)
> >>>>
> >>>> TP_STRUCT__entry(
> >>>> __string(hostname, hostname)
> >>>> __field(__u64, conn_id)
> >>>> __field(struct sockaddr_storage, dst_addr)
> >>>>
> >>>> TP_fast_assign(
> >>>> __entry->conn_id = conn_id;
> >>>> __entry->dst_addr = *dst_addr;
> >>>> __assign_str(hostname, hostname);
> >>>> ),
> >>>>
> >>>> With that you should be able to use this:
> >>>>
> >>>> TP_printk("conn_id=0x%llx server=%s addr=%pISpsfc",
> >>>> __entry->conn_id,
> >>>> __get_str(hostname),
> >>>> &__entry->dst_addr)
> >>>>
> >>>> I hope that helps.
> >>>>
> >>>> metze
> >>>>
> >>>> Am 04.11.21 um 07:09 schrieb Steve French:
> >>>>> It wasn't obvious to me the best way to pass in a pointer to the ipv4
> >>>>> (and ipv6 address) to a dynamic trace point (unless I create a temp
> >>>>> string first in generic_ip_connect and do the conversion (via "%pI4"
> >>>>> and "%pI6" with sprintf) e.g.
> >>>>>
> >>>>> sprintf(ses->ip_addr, "%pI4", &addr->sin_addr);
> >>>>>
> >>>>> The approach I tried passing in the pointer to sin_addr (the
> >>>>> ipv4_address) caused an oops on loading it the first time and the
> >>>>> warning:
> >>>>>
> >>>>> [14928.818532] event smb3_ipv4_connect has unsafe dereference of argument 3
> >>>>> [14928.818534] print_fmt: "conn_id=0x%llx server=%s addr=%pI4:%d",
> >>>>> REC->conn_id, __get_str(hostname), REC->ipaddr, REC->port
> >>>>>
> >>>>>
> >>>>> What I tried was the following (also see attached diff) to print the
> >>>>> ipv4 address that we were trying to connect to
> >>>>>
> >>>>> DECLARE_EVENT_CLASS(smb3_connect_class,
> >>>>> TP_PROTO(char *hostname,
> >>>>> __u64 conn_id,
> >>>>> __u16 port,
> >>>>> struct in_addr *ipaddr),
> >>>>> TP_ARGS(hostname, conn_id, port, ipaddr),
> >>>>> TP_STRUCT__entry(
> >>>>> __string(hostname, hostname)
> >>>>> __field(__u64, conn_id)
> >>>>> __field(__u16, port)
> >>>>> __field(const void *, ipaddr)
> >>>>> ),
> >>>>> TP_fast_assign(
> >>>>> __entry->port = port;
> >>>>> __entry->conn_id = conn_id;
> >>>>> __entry->ipaddr = ipaddr;
> >>>>> __assign_str(hostname, hostname);
> >>>>> ),
> >>>>> TP_printk("conn_id=0x%llx server=%s addr=%pI4:%d",
> >>>>> __entry->conn_id,
> >>>>> __get_str(hostname),
> >>>>> __entry->ipaddr,
> >>>>> __entry->port)
> >>>>> )
> >>>>>
> >>>>> #define DEFINE_SMB3_CONNECT_EVENT(name) \
> >>>>> DEFINE_EVENT(smb3_connect_class, smb3_##name, \
> >>>>> TP_PROTO(char *hostname, \
> >>>>> __u64 conn_id, \
> >>>>> __u16 port, \
> >>>>> struct in_addr *ipaddr), \
> >>>>> TP_ARGS(hostname, conn_id, port, ipaddr))
> >>>>>
> >>>>> DEFINE_SMB3_CONNECT_EVENT(ipv4_connect);
> >>>>>
> >>>>> Any ideas how to pass in the ipv4 address - or is it better to convert
> >>>>> it to a string before we call the trace point (which seems wasteful to
> >>>>> me but there must be examples of how to pass in structs to printks in
> >>>>> trace in Linux)
> >>>>>
> >>>>
> >>>
> >>>
> >>> --
> >>> Thanks,
> >>>
> >>> Steve
> >>
> >>
> >>
> >
> >
>
>
--
Thanks,
Steve
From 95fc095e1f47aee46550d26231bb2d79c26f4470 Mon Sep 17 00:00:00 2001
From: Steve French <stfrench@xxxxxxxxxxxxx>
Date: Thu, 4 Nov 2021 15:56:37 -0500
Subject: [PATCH] smb3: add dynamic trace points for socket connection
In debugging user problems with ip address/DNS issues with
smb3 mounts, we sometimes needed additional info on the hostname
and ip address.
Add two tracepoints, one to show socket connection success
and one for failures to connect to the socket.
Sample output:
mount.cifs-14551 [005] ..... 7636.547906: smb3_connect_done: conn_id=0x1 server=localhost addr=127.0.0.1:445
mount.cifs-14558 [004] ..... 7642.405413: smb3_connect_done: conn_id=0x2 server=smfrench.file.core.windows.net addr=52.239.158.232:445
mount.cifs-14741 [005] ..... 7818.490716: smb3_connect_done: conn_id=0x3 server=::1 addr=[::1]:445/0%0
mount.cifs-14810 [000] ..... 7966.380337: smb3_connect_err: rc=-101 conn_id=0x4 server=::2 addr=[::2]:445/0%0
mount.cifs-14810 [000] ..... 7966.380356: smb3_connect_err: rc=-101 conn_id=0x4 server=::2 addr=[::2]:139/0%0
mount.cifs-14818 [003] ..... 7986.771992: smb3_connect_done: conn_id=0x5 server=127.0.0.9 addr=127.0.0.9:445
mount.cifs-14825 [008] ..... 8008.178109: smb3_connect_err: rc=-115 conn_id=0x6 server=124.23.0.9 addr=124.23.0.9:445
mount.cifs-14825 [008] ..... 8013.298085: smb3_connect_err: rc=-115 conn_id=0x6 server=124.23.0.9 addr=124.23.0.9:139
cifsd-14553 [006] ..... 8036.735615: smb3_reconnect: conn_id=0x1 server=localhost current_mid=32
cifsd-14743 [010] ..... 8036.735644: smb3_reconnect: conn_id=0x3 server=::1 current_mid=29
cifsd-14743 [010] ..... 8039.921740: smb3_connect_err: rc=-111 conn_id=0x3 server=::1 addr=[::1]:445/0%0
cifsd-14553 [008] ..... 8042.993894: smb3_connect_err: rc=-111 conn_id=0x1 server=localhost addr=127.0.0.1:445
cifsd-14743 [010] ..... 8042.993894: smb3_connect_err: rc=-111 conn_id=0x3 server=::1 addr=[::1]:445/0%0
cifsd-14553 [008] ..... 8046.065824: smb3_connect_err: rc=-111 conn_id=0x1 server=localhost addr=127.0.0.1:445
cifsd-14743 [010] ..... 8046.065824: smb3_connect_err: rc=-111 conn_id=0x3 server=::1 addr=[::1]:445/0%0
cifsd-14553 [008] ..... 8049.137796: smb3_connect_done: conn_id=0x1 server=localhost addr=127.0.0.1:445
cifsd-14743 [010] ..... 8049.137796: smb3_connect_done: conn_id=0x3 server=::1 addr=[::1]:445/0%0
Signed-off-by: Steve French <stfrench@xxxxxxxxxxxxx>
---
fs/cifs/connect.c | 3 +-
fs/cifs/trace.h | 71 +++++++++++++++++++++++++++++++++++++++++++++++
2 files changed, 73 insertions(+), 1 deletion(-)
diff --git a/fs/cifs/connect.c b/fs/cifs/connect.c
index e6e261dfd107..144f0bb5098f 100644
--- a/fs/cifs/connect.c
+++ b/fs/cifs/connect.c
@@ -2649,11 +2649,12 @@ generic_ip_connect(struct TCP_Server_Info *server)
rc = 0;
if (rc < 0) {
cifs_dbg(FYI, "Error %d connecting to server\n", rc);
+ trace_smb3_connect_err(server->hostname, server->conn_id, &server->dstaddr, rc);
sock_release(socket);
server->ssocket = NULL;
return rc;
}
-
+ trace_smb3_connect_done(server->hostname, server->conn_id, &server->dstaddr);
if (sport == htons(RFC1001_PORT))
rc = ip_rfc1001_connect(server);
diff --git a/fs/cifs/trace.h b/fs/cifs/trace.h
index dafcb6ab050d..6cecf302dcfd 100644
--- a/fs/cifs/trace.h
+++ b/fs/cifs/trace.h
@@ -11,6 +11,8 @@
#define _CIFS_TRACE_H
#include <linux/tracepoint.h>
+#include <linux/net.h>
+#include <linux/inet.h>
/*
* Please use this 3-part article as a reference for writing new tracepoints:
@@ -854,6 +856,75 @@ DEFINE_EVENT(smb3_lease_err_class, smb3_##name, \
DEFINE_SMB3_LEASE_ERR_EVENT(lease_err);
+DECLARE_EVENT_CLASS(smb3_connect_class,
+ TP_PROTO(char *hostname,
+ __u64 conn_id,
+ const struct __kernel_sockaddr_storage *dst_addr),
+ TP_ARGS(hostname, conn_id, dst_addr),
+ TP_STRUCT__entry(
+ __string(hostname, hostname)
+ __field(__u64, conn_id)
+ __array(__u8, dst_addr, sizeof(struct sockaddr_storage))
+ ),
+ TP_fast_assign(
+ struct sockaddr_storage *pss = NULL;
+
+ __entry->conn_id = conn_id;
+ pss = (struct sockaddr_storage *)__entry->dst_addr;
+ *pss = *dst_addr;
+ __assign_str(hostname, hostname);
+ ),
+ TP_printk("conn_id=0x%llx server=%s addr=%pISpsfc",
+ __entry->conn_id,
+ __get_str(hostname),
+ __entry->dst_addr)
+)
+
+#define DEFINE_SMB3_CONNECT_EVENT(name) \
+DEFINE_EVENT(smb3_connect_class, smb3_##name, \
+ TP_PROTO(char *hostname, \
+ __u64 conn_id, \
+ const struct __kernel_sockaddr_storage *addr), \
+ TP_ARGS(hostname, conn_id, addr))
+
+DEFINE_SMB3_CONNECT_EVENT(connect_done);
+
+DECLARE_EVENT_CLASS(smb3_connect_err_class,
+ TP_PROTO(char *hostname, __u64 conn_id,
+ const struct __kernel_sockaddr_storage *dst_addr, int rc),
+ TP_ARGS(hostname, conn_id, dst_addr, rc),
+ TP_STRUCT__entry(
+ __string(hostname, hostname)
+ __field(__u64, conn_id)
+ __array(__u8, dst_addr, sizeof(struct sockaddr_storage))
+ __field(int, rc)
+ ),
+ TP_fast_assign(
+ struct sockaddr_storage *pss = NULL;
+
+ __entry->conn_id = conn_id;
+ __entry->rc = rc;
+ pss = (struct sockaddr_storage *)__entry->dst_addr;
+ *pss = *dst_addr;
+ __assign_str(hostname, hostname);
+ ),
+ TP_printk("rc=%d conn_id=0x%llx server=%s addr=%pISpsfc",
+ __entry->rc,
+ __entry->conn_id,
+ __get_str(hostname),
+ __entry->dst_addr)
+)
+
+#define DEFINE_SMB3_CONNECT_ERR_EVENT(name) \
+DEFINE_EVENT(smb3_connect_err_class, smb3_##name, \
+ TP_PROTO(char *hostname, \
+ __u64 conn_id, \
+ const struct __kernel_sockaddr_storage *addr, \
+ int rc), \
+ TP_ARGS(hostname, conn_id, addr, rc))
+
+DEFINE_SMB3_CONNECT_ERR_EVENT(connect_err);
+
DECLARE_EVENT_CLASS(smb3_reconnect_class,
TP_PROTO(__u64 currmid,
__u64 conn_id,
--
2.32.0
