Version 3 of the patch attached. Sample output below:
(trace-cmd record -e *query_info_co* -e smb3_hardlink* -e
smb3_rename* -e smb3_set_eof* -e smb3_set_info_co* -e smb3_mkdir* -e
smb3_delete* -e smb3_rmdir*)
mkdir-17927 [003] .... 447434.636544:
smb3_query_info_compound_enter: xid=7 sid=0x7dc5fd6f tid=0xc7968732
path=\newdir
mkdir-17927 [003] .... 447434.637240:
smb3_query_info_compound_err: xid=7 sid=0x7dc5fd6f tid=0xc7968732
rc=-2
mkdir-17942 [000] .... 447446.807606:
smb3_query_info_compound_enter: xid=8 sid=0x7dc5fd6f tid=0xc7968732
path=\newdir
mkdir-17942 [000] .... 447446.808233:
smb3_query_info_compound_err: xid=8 sid=0x7dc5fd6f tid=0xc7968732
rc=-2
mkdir-17942 [000] .... 447446.808251: smb3_mkdir_enter:
xid=9 sid=0x7dc5fd6f tid=0xc7968732 path=\newdir
mkdir-17942 [000] .... 447446.809161: smb3_mkdir_done:
xid=9 sid=0x7dc5fd6f tid=0xc7968732
mkdir-17942 [000] .... 447446.809178:
smb3_query_info_compound_enter: xid=9 sid=0x7dc5fd6f tid=0xc7968732
path=\newdir
mkdir-17942 [000] .... 447446.809979:
smb3_query_info_compound_done: xid=9 sid=0x7dc5fd6f tid=0xc7968732
rmdir-17943 [001] .... 447451.374029:
smb3_query_info_compound_enter: xid=10 sid=0x7dc5fd6f tid=0xc7968732
path=\baddir
rmdir-17943 [001] .... 447451.379621:
smb3_query_info_compound_err: xid=10 sid=0x7dc5fd6f tid=0xc7968732
rc=-2
rmdir-17944 [001] .... 447456.088795:
smb3_query_info_compound_enter: xid=11 sid=0x7dc5fd6f tid=0xc7968732
path=\newdir
rmdir-17944 [001] .... 447456.089615:
smb3_query_info_compound_done: xid=11 sid=0x7dc5fd6f tid=0xc7968732
rmdir-17944 [001] .... 447456.089640: smb3_rmdir_enter:
xid=12 sid=0x7dc5fd6f tid=0xc7968732 path=\newdir
rmdir-17944 [001] .... 447456.090651: smb3_rmdir_done:
xid=12 sid=0x7dc5fd6f tid=0xc7968732
touch-17945 [006] .... 447460.575789:
smb3_set_info_compound_enter: xid=14 sid=0x7dc5fd6f tid=0xc7968732
path=\file
touch-17945 [006] .... 447460.576571:
smb3_set_info_compound_done: xid=14 sid=0x7dc5fd6f tid=0xc7968732
ln-17946 [001] .... 447468.254480:
smb3_query_info_compound_enter: xid=16 sid=0x7dc5fd6f tid=0xc7968732
path=\linkedfile
ln-17946 [001] .... 447468.255082:
smb3_query_info_compound_err: xid=16 sid=0x7dc5fd6f tid=0xc7968732
rc=-2
ln-17946 [001] .... 447468.255118:
smb3_query_info_compound_enter: xid=17 sid=0x7dc5fd6f tid=0xc7968732
path=\file
ln-17946 [001] .... 447468.255715:
smb3_query_info_compound_done: xid=17 sid=0x7dc5fd6f tid=0xc7968732
ln-17946 [001] .... 447468.255760:
smb3_query_info_compound_enter: xid=18 sid=0x7dc5fd6f tid=0xc7968732
path=\linkedfile
ln-17946 [001] .... 447468.256254:
smb3_query_info_compound_err: xid=18 sid=0x7dc5fd6f tid=0xc7968732
rc=-2
ln-17946 [001] .... 447468.256277: smb3_hardlink_enter:
xid=19 sid=0x7dc5fd6f tid=0xc7968732 path=\file
ln-17946 [001] .... 447468.256954: smb3_hardlink_done:
xid=19 sid=0x7dc5fd6f tid=0xc7968732
gmain-2225 [004] .... 447468.257130:
smb3_query_info_compound_enter: xid=20 sid=0x7dc5fd6f tid=0xc7968732
path=\linkedfile
gmain-2225 [005] .... 447468.257788:
smb3_query_info_compound_done: xid=20 sid=0x7dc5fd6f tid=0xc7968732
On Tue, Mar 12, 2019 at 4:51 PM Pavel Shilovsky <piastryyy@xxxxxxxxx> wrote:
>
> I actually like the idea proposed in the patch: this way we will be
> able to track logical operations better. In a case we need a deeper
> logging we already have mid traces which contains MID, TID, SID and
> CMD - everything you need to trace individual SMB packet regardless of
> whether it is a part of compounding chain or not.
>
> Now in order to match both logical operation and SMB packets traces we
> need something common - like XID. Currently we do not propagate XID
> down to the transport layer, let's do that - this way we can trace
> individual system call from the very beginning to the completeness on
> every layer inside cifs.ko.
>
> вт, 12 мар. 2019 г. в 00:19, Steve French <smfrench@xxxxxxxxx>:
> >
> > The general feeling I am getting from tracing the compounding is that
> > we have to have the more granular tracing available
> > (similar to this patch), and also (with followon patch) add noisier
> > optional trace points lower down (that are generic) that we turn on
> > less frequently (in particular when the filename is not good enough
> > and we must have the xid - even if it makes the trace very noisy)
> >
> >
> > On Tue, Mar 12, 2019 at 1:06 AM ronnie sahlberg
> > <ronniesahlberg@xxxxxxxxx> wrote:
> > >
> > > Hmm.
> > >
> > > I don't think this is the wrong layer to add the tracing.
> > > Instead of adding the tracing in say smb2_compound_op(), where we
> > > create the compound,
> > > I think it will be better to add the tracing down in the leaf
> > > functions, i.e. down in SMB2_open_init(), SMB2_query_info_init(), ...
> > >
> > > That way we know that we will always have tracing for all opens/closes/...
> > >
> > > But then what to do about the trace_smb3_..._err()/trace_smb3_..._done() calls ?
> > > These I think should be moved down and handled inside compound_send_recv().
> > > That way we can have one single place where we call the appropriate
> > > _err()/_done() functions
> > > and we know that we will catch every single completed function.
> > >
> > > I.e. just put it in a single place instead of in every single call-site.
> > > In compound_send_recv we can just loop over all the responses, cast it
> > > to a smb2_hdr structure, looka at both the command code as well as the
> > > status code and call the appropriate xys_err() or xyz_done() functions
> > > as needed.
> > >
> > > Let me show an example of what I mean for a open/query/close compound :
> > >
> > > trace_smb3_open_enter(xid=5, filename="foo", ...) from SMB2_open_init()
> > > trace_smb3_query_info_enter(xid=5,... ) from SMB2_query_info_init()
> > > trace_smb3_close_enter(xid=5, ...) from SMB2_close_init()
> > > (maybe have additional tracing in compound_send_recv() that we are
> > > about to send xid=5 to the wire)
> > > trace_smb3_open_done(xid=5, ...) from compound_send_recv()
> > > trace_smb3_query_info_done(xid=5, ...) from compound_send_recv()
> > > trace_smb3_close_done(xid=5, ...) from compound_send_recv()
> > >
>
> As pointed above we already have a similar tracing inside
> compound_send_recv and other transport layer functions - command level
> tracing. The only problem is that we do not log failure cases when we
> didn't send the packet - we only log server responses in
> map_smb2_to_linux_error. This is another area of the tracing where a
> fix is needed.
>
> --
> Best regards,
> Pavel Shilovsky
--
Thanks,
Steve
From fe3cfc252be9857c160973e499c3bdd7428e3c96 Mon Sep 17 00:00:00 2001
From: Steve French <stfrench@xxxxxxxxxxxxx>
Date: Wed, 13 Mar 2019 00:02:47 -0500
Subject: [PATCH] smb3: Add dynamic trace points for various compounded smb3
ops
Adds trace points for enter and exit (done vs. error) for:
compounded query and setinfo, hardlink, rename,
mkdir, rmdir, set_eof, delete (unlink)
Signed-off-by: Steve French <stfrench@xxxxxxxxxxxxx>
---
fs/cifs/smb2inode.c | 72 +++++++++++++++++++++++++--
fs/cifs/trace.h | 117 ++++++++++++++++++++++++++++++++++++++++++++
2 files changed, 185 insertions(+), 4 deletions(-)
diff --git a/fs/cifs/smb2inode.c b/fs/cifs/smb2inode.c
index b6e07e2eed10..278405d26c47 100644
--- a/fs/cifs/smb2inode.c
+++ b/fs/cifs/smb2inode.c
@@ -37,6 +37,16 @@
#include "smb2pdu.h"
#include "smb2proto.h"
+static void
+free_set_inf_compound(struct smb_rqst *rqst)
+{
+ if (rqst[1].rq_iov)
+ SMB2_set_info_free(&rqst[1]);
+ if (rqst[2].rq_iov)
+ SMB2_close_free(&rqst[2]);
+}
+
+
static int
smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon,
struct cifs_sb_info *cifs_sb, const char *full_path,
@@ -112,14 +122,18 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon,
PATH_MAX * 2, 0, NULL);
smb2_set_next_command(tcon, &rqst[num_rqst]);
smb2_set_related(&rqst[num_rqst++]);
+ trace_smb3_query_info_compound_enter(xid, ses->Suid, tcon->tid,
+ full_path);
break;
case SMB2_OP_DELETE:
+ trace_smb3_delete_enter(xid, ses->Suid, tcon->tid, full_path);
break;
case SMB2_OP_MKDIR:
/*
* Directories are created through parameters in the
* SMB2_open() call.
*/
+ trace_smb3_mkdir_enter(xid, ses->Suid, tcon->tid, full_path);
break;
case SMB2_OP_RMDIR:
memset(&si_iov, 0, sizeof(si_iov));
@@ -135,6 +149,7 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon,
SMB2_O_INFO_FILE, 0, data, size);
smb2_set_next_command(tcon, &rqst[num_rqst]);
smb2_set_related(&rqst[num_rqst++]);
+ trace_smb3_rmdir_enter(xid, ses->Suid, tcon->tid, full_path);
break;
case SMB2_OP_SET_EOF:
memset(&si_iov, 0, sizeof(si_iov));
@@ -150,6 +165,7 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon,
SMB2_O_INFO_FILE, 0, data, size);
smb2_set_next_command(tcon, &rqst[num_rqst]);
smb2_set_related(&rqst[num_rqst++]);
+ trace_smb3_set_eof_enter(xid, ses->Suid, tcon->tid, full_path);
break;
case SMB2_OP_SET_INFO:
memset(&si_iov, 0, sizeof(si_iov));
@@ -166,6 +182,8 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon,
SMB2_O_INFO_FILE, 0, data, size);
smb2_set_next_command(tcon, &rqst[num_rqst]);
smb2_set_related(&rqst[num_rqst++]);
+ trace_smb3_set_info_compound_enter(xid, ses->Suid, tcon->tid,
+ full_path);
break;
case SMB2_OP_RENAME:
memset(&si_iov, 0, sizeof(si_iov));
@@ -190,6 +208,7 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon,
SMB2_O_INFO_FILE, 0, data, size);
smb2_set_next_command(tcon, &rqst[num_rqst]);
smb2_set_related(&rqst[num_rqst++]);
+ trace_smb3_rename_enter(xid, ses->Suid, tcon->tid, full_path);
break;
case SMB2_OP_HARDLINK:
memset(&si_iov, 0, sizeof(si_iov));
@@ -214,6 +233,7 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon,
SMB2_O_INFO_FILE, 0, data, size);
smb2_set_next_command(tcon, &rqst[num_rqst]);
smb2_set_related(&rqst[num_rqst++]);
+ trace_smb3_hardlink_enter(xid, ses->Suid, tcon->tid, full_path);
break;
default:
cifs_dbg(VFS, "Invalid command\n");
@@ -252,21 +272,65 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon,
SMB2_query_info_free(&rqst[1]);
if (rqst[2].rq_iov)
SMB2_close_free(&rqst[2]);
+ if (rc)
+ trace_smb3_query_info_compound_err(xid, ses->Suid,
+ tcon->tid, rc);
+ else
+ trace_smb3_query_info_compound_done(xid, ses->Suid,
+ tcon->tid);
break;
case SMB2_OP_DELETE:
+ if (rc)
+ trace_smb3_delete_err(xid, ses->Suid, tcon->tid, rc);
+ else
+ trace_smb3_delete_done(xid, ses->Suid, tcon->tid);
+ if (rqst[1].rq_iov)
+ SMB2_close_free(&rqst[1]);
+ break;
case SMB2_OP_MKDIR:
+ if (rc)
+ trace_smb3_mkdir_err(xid, ses->Suid, tcon->tid, rc);
+ else
+ trace_smb3_mkdir_done(xid, ses->Suid, tcon->tid);
if (rqst[1].rq_iov)
SMB2_close_free(&rqst[1]);
break;
case SMB2_OP_HARDLINK:
+ if (rc)
+ trace_smb3_hardlink_err(xid, ses->Suid, tcon->tid, rc);
+ else
+ trace_smb3_hardlink_done(xid, ses->Suid, tcon->tid);
+ free_set_inf_compound(rqst);
+ break;
case SMB2_OP_RENAME:
+ if (rc)
+ trace_smb3_rename_err(xid, ses->Suid, tcon->tid, rc);
+ else
+ trace_smb3_rename_done(xid, ses->Suid, tcon->tid);
+ free_set_inf_compound(rqst);
+ break;
case SMB2_OP_RMDIR:
+ if (rc)
+ trace_smb3_rmdir_err(xid, ses->Suid, tcon->tid, rc);
+ else
+ trace_smb3_rmdir_done(xid, ses->Suid, tcon->tid);
+ free_set_inf_compound(rqst);
+ break;
case SMB2_OP_SET_EOF:
+ if (rc)
+ trace_smb3_set_eof_err(xid, ses->Suid, tcon->tid, rc);
+ else
+ trace_smb3_set_eof_done(xid, ses->Suid, tcon->tid);
+ free_set_inf_compound(rqst);
+ break;
case SMB2_OP_SET_INFO:
- if (rqst[1].rq_iov)
- SMB2_set_info_free(&rqst[1]);
- if (rqst[2].rq_iov)
- SMB2_close_free(&rqst[2]);
+ if (rc)
+ trace_smb3_set_info_compound_err(xid, ses->Suid,
+ tcon->tid, rc);
+ else
+ trace_smb3_set_info_compound_done(xid, ses->Suid,
+ tcon->tid);
+ free_set_inf_compound(rqst);
break;
}
free_rsp_buf(resp_buftype[0], rsp_iov[0].iov_base);
diff --git a/fs/cifs/trace.h b/fs/cifs/trace.h
index c78e96c4cc53..30bf51c7e8fe 100644
--- a/fs/cifs/trace.h
+++ b/fs/cifs/trace.h
@@ -242,6 +242,123 @@ DEFINE_SMB3_INF_ERR_EVENT(query_info_err);
DEFINE_SMB3_INF_ERR_EVENT(set_info_err);
DEFINE_SMB3_INF_ERR_EVENT(fsctl_err);
+DECLARE_EVENT_CLASS(smb3_inf_compound_enter_class,
+ TP_PROTO(unsigned int xid,
+ __u32 tid,
+ __u64 sesid,
+ const char *full_path),
+ TP_ARGS(xid, tid, sesid, full_path),
+ TP_STRUCT__entry(
+ __field(unsigned int, xid)
+ __field(__u32, tid)
+ __field(__u64, sesid)
+ __string(path, full_path)
+ ),
+ TP_fast_assign(
+ __entry->xid = xid;
+ __entry->tid = tid;
+ __entry->sesid = sesid;
+ __assign_str(path, full_path);
+ ),
+ TP_printk("xid=%u sid=0x%llx tid=0x%x path=%s",
+ __entry->xid, __entry->sesid, __entry->tid,
+ __get_str(path))
+)
+
+#define DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(name) \
+DEFINE_EVENT(smb3_inf_compound_enter_class, smb3_##name, \
+ TP_PROTO(unsigned int xid, \
+ __u32 tid, \
+ __u64 sesid, \
+ const char *full_path), \
+ TP_ARGS(xid, tid, sesid, full_path))
+
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(query_info_compound_enter);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(hardlink_enter);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(rename_enter);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(rmdir_enter);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(set_eof_enter);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(set_info_compound_enter);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(delete_enter);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(mkdir_enter);
+
+
+DECLARE_EVENT_CLASS(smb3_inf_compound_done_class,
+ TP_PROTO(unsigned int xid,
+ __u32 tid,
+ __u64 sesid),
+ TP_ARGS(xid, tid, sesid),
+ TP_STRUCT__entry(
+ __field(unsigned int, xid)
+ __field(__u32, tid)
+ __field(__u64, sesid)
+ ),
+ TP_fast_assign(
+ __entry->xid = xid;
+ __entry->tid = tid;
+ __entry->sesid = sesid;
+ ),
+ TP_printk("xid=%u sid=0x%llx tid=0x%x",
+ __entry->xid, __entry->sesid, __entry->tid)
+)
+
+#define DEFINE_SMB3_INF_COMPOUND_DONE_EVENT(name) \
+DEFINE_EVENT(smb3_inf_compound_done_class, smb3_##name, \
+ TP_PROTO(unsigned int xid, \
+ __u32 tid, \
+ __u64 sesid), \
+ TP_ARGS(xid, tid, sesid))
+
+DEFINE_SMB3_INF_COMPOUND_DONE_EVENT(query_info_compound_done);
+DEFINE_SMB3_INF_COMPOUND_DONE_EVENT(hardlink_done);
+DEFINE_SMB3_INF_COMPOUND_DONE_EVENT(rename_done);
+DEFINE_SMB3_INF_COMPOUND_DONE_EVENT(rmdir_done);
+DEFINE_SMB3_INF_COMPOUND_DONE_EVENT(set_eof_done);
+DEFINE_SMB3_INF_COMPOUND_DONE_EVENT(set_info_compound_done);
+DEFINE_SMB3_INF_COMPOUND_DONE_EVENT(delete_done);
+DEFINE_SMB3_INF_COMPOUND_DONE_EVENT(mkdir_done);
+
+
+DECLARE_EVENT_CLASS(smb3_inf_compound_err_class,
+ TP_PROTO(unsigned int xid,
+ __u32 tid,
+ __u64 sesid,
+ int rc),
+ TP_ARGS(xid, tid, sesid, rc),
+ TP_STRUCT__entry(
+ __field(unsigned int, xid)
+ __field(__u32, tid)
+ __field(__u64, sesid)
+ __field(int, rc)
+ ),
+ TP_fast_assign(
+ __entry->xid = xid;
+ __entry->tid = tid;
+ __entry->sesid = sesid;
+ __entry->rc = rc;
+ ),
+ TP_printk("xid=%u sid=0x%llx tid=0x%x rc=%d",
+ __entry->xid, __entry->sesid, __entry->tid,
+ __entry->rc)
+)
+
+#define DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(name) \
+DEFINE_EVENT(smb3_inf_compound_err_class, smb3_##name, \
+ TP_PROTO(unsigned int xid, \
+ __u32 tid, \
+ __u64 sesid, \
+ int rc), \
+ TP_ARGS(xid, tid, sesid, rc))
+
+DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(query_info_compound_err);
+DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(hardlink_err);
+DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(rename_err);
+DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(rmdir_err);
+DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(set_eof_err);
+DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(set_info_compound_err);
+DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(mkdir_err);
+DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(delete_err);
+
/*
* For logging SMB3 Status code and Command for responses which return errors
*/
--
2.17.1
