Reviewed-by me. Only issue is that it is very verbose like this : + if (rc) + trace_smb3_rmdir_err(xid, ses->Suid, tcon->tid, rc); + else + trace_smb3_rmdir_done(xid, ses->Suid, tcon->tid); We can do this late but this pattern can be simplified to a single line with a macro. It is always rc that decides which tracepoint we use, and the error path tracepoint has a small subset of the arguments,except for rc, than the _done tracepoint have. So the macro could take both rc as well as all the arguments for _done as this : TRACE_SMB3_RMDIR_END(rc, xid, suid, tid) which then expands to the four lines of code. We can do that later, just to reduce the amount of emacs real-estate these lines take up. On Wed, Mar 13, 2019 at 3:03 PM Steve French <smfrench@xxxxxxxxx> wrote: > > 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
