I agree that we could use macros to shrink this - but as long as it is readable, seems fine to me. On Wed, Mar 13, 2019 at 12:38 AM ronnie sahlberg <ronniesahlberg@xxxxxxxxx> wrote: > > 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 -- Thanks, Steve
