[PATCH v3 0/2] CIFS: Info-level log support, print message when attempting mount.

[PATCH v3 0/2] CIFS: Info-level log support, print message when attempting mount.

[Rodrigo Freire]

Hi Steve,
From our conversation over v2, I came out with this v3 patch, which I broke
in two commits:

* The first commit in cifs_debug.h, creating the cifs_info() function.
  - The aim of this commit is to allow to the developer to be able to print
    informational-level data without having to use pr_info, pr_notice etc,
    in line with other filesystems.
    . One interesting and noteworthy feature of cifs_info() is that it is
      transparent to the CIFS_DEBUG config state, either in "y" or "n".
    . Also, by using KERN_INFO level, it can be safely filtered by a
      maintainer / administrator, without cluttering their log monitors,
      since this is a low level alert.
  - I took the liberty to not add it inside the existing pr_debug, because
    of the eventual need of some developer to print stuff that should be
    printed not only in CIFS_DEBUG mode (as there are plenty of pr_notice
    scattered over the code).
  - Also, this is not a debug but a info message, so i liked cifs_info() 
    more ;-)
  - I saw plenty of pr_notice() in CIFS code, but I resisted the urge to
    convert them to cifs_info().

* The second commit contains the code printing a cifs_info() when attempting
  a CIFS mount operation.

Appreciate your review.

V3: Created a new cifs_info() function, moved the mount attempt message to
    cifs_info

V2: Created a loop to select the right cifs_dbg message to be printed,
    considering the current system's scenario, in order to avoid a
    duplicate message or stripping out important information in
    debug.

Rodrigo Freire (2):
  CIFS: Adds information-level logging function
  CIFS: Print message when attempting a mount

 fs/cifs/cifs_debug.h | 16 ++++++++++++++++
 fs/cifs/cifsfs.c     |  7 ++++++-
 fs/cifs/transport.c  |  2 +-
 3 files changed, 23 insertions(+), 2 deletions(-)

-- 
1.8.3.1

[PATCH v3 1/2] CIFS: Adds information-level logging function

[Rodrigo Freire]

Currently, CIFS lacks a internal logging function that prints out data
when CIFS_DEBUG=n. When CIFS_DEBUG=y, the only message level for CIFS
events are KERN_ERR or KERN_DEBUG.

This patch creates cifs_info(), which is useful for printing
non-critical event messges, at either CIFS_DEBUG state.

Signed-off-by: Rodrigo Freire <rfreire@redhat.com>
---
 fs/cifs/cifs_debug.h | 16 ++++++++++++++++
 1 file changed, 16 insertions(+)

diff --git a/fs/cifs/cifs_debug.h b/fs/cifs/cifs_debug.h
index f4f3f08..72db298 100644
--- a/fs/cifs/cifs_debug.h
+++ b/fs/cifs/cifs_debug.h
@@ -47,6 +47,17 @@
  */
 #ifdef CONFIG_CIFS_DEBUG
 
+/* Information level messages, minor events */
+#define cifs_info_func(ratefunc, fmt, ...)			\
+do {								\
+	pr_info_ ## ratefunc("CIFS: " fmt, ##__VA_ARGS__); 	\
+} while (0)
+
+#define cifs_info(fmt, ...)					\
+do { 								\
+	cifs_info_func(ratelimited, fmt, ##__VA_ARGS__); 	\
+} while (0)
+
 /* information message: e.g., configuration, major event */
 #define cifs_dbg_func(ratefunc, type, fmt, ...)			\
 do {								\
@@ -81,6 +92,11 @@
 	if (0)								\
 		pr_debug(fmt, ##__VA_ARGS__);				\
 } while (0)
+
+#define cifs_info(fmt, ...)						\
+do {									\
+	pr_info("CIFS: "fmt, ##__VA_ARGS__);				\
+} while (0)
 #endif
 
 #endif				/* _H_CIFS_DEBUG */
-- 
1.8.3.1

[PATCH v3 2/2] CIFS: Print message when attempting a mount

[Rodrigo Freire]

Currently, no messages are printed when mounting a CIFS filesystem and
no debug configuration is enabled.

However, a CIFS mount information is valuable when troubleshooting
and/or forensic analyzing a system and finding out if was a CIFS
endpoint mount attempted.

Other filesystems such as XFS, EXT* does issue a printk() when mounting
their filesystems.

A terse log message is printed only if cifsFYI is not enabled. Otherwise,
the default full debug message is printed.

In order to not clutter and classify correctly the event messages, these
are logged as KERN_INFO level.

Sample mount operations:

[root@corinthians ~]# mount -o user=administrator //172.25.250.18/c$ /mnt
(non-existent system)

[root@corinthians ~]# mount -o user=administrator //172.25.250.19/c$ /mnt
(Valid system)

Kernel message log for the mount operations:

[  450.464543] CIFS: Attempting to mount //172.25.250.18/c$
[  456.478186] CIFS VFS: Error connecting to socket. Aborting operation.
[  456.478381] CIFS VFS: cifs_mount failed w/return code = -113
[  467.688866] CIFS: Attempting to mount //172.25.250.19/c$

Signed-off-by: Rodrigo Freire <rfreire@redhat.com>
---
 fs/cifs/cifsfs.c    | 7 ++++++-
 fs/cifs/transport.c | 2 +-
 2 files changed, 7 insertions(+), 2 deletions(-)

diff --git a/fs/cifs/cifsfs.c b/fs/cifs/cifsfs.c
index 7065426..ebdf25e 100644
--- a/fs/cifs/cifsfs.c
+++ b/fs/cifs/cifsfs.c
@@ -707,7 +707,12 @@ static int cifs_set_super(struct super_block *sb, void *data)
 	struct cifs_mnt_data mnt_data;
 	struct dentry *root;
 
-	cifs_dbg(FYI, "Devname: %s flags: %d\n", dev_name, flags);
+	/* Prints in Kernel / CIFS log the attempted mount operation *
+ 	 *	IF CIFS_DEBUG && cifs_FYI */
+	if (cifsFYI)
+		cifs_dbg(FYI, "Devname: %s flags: %d\n", dev_name, flags);
+	else
+		cifs_info("Attempting to mount %s\n", dev_name);
 
 	volume_info = cifs_get_volume_info((char *)data, dev_name, is_smb3);
 	if (IS_ERR(volume_info))
diff --git a/fs/cifs/transport.c b/fs/cifs/transport.c
index 78f96fa..c2afd6a 100644
--- a/fs/cifs/transport.c
+++ b/fs/cifs/transport.c
@@ -128,7 +128,7 @@ void cifs_mid_q_entry_release(struct mid_q_entry *midEntry)
 		if (cifsFYI & CIFS_TIMER) {
 			pr_debug(" CIFS slow rsp: cmd %d mid %llu",
 			       midEntry->command, midEntry->mid);
-			pr_info(" A: 0x%lx S: 0x%lx R: 0x%lx\n",
+			cifs_info(" A: 0x%lx S: 0x%lx R: 0x%lx\n",
 			       now - midEntry->when_alloc,
 			       now - midEntry->when_sent,
 			       now - midEntry->when_received);
-- 
1.8.3.1

Re: [PATCH v3 0/2] CIFS: Info-level log support, print message when attempting mount.

[Steve French]

[-- Attachment #1: Type: text/plain, Size: 2384 bytes --]

Merged into cifs-2.6.git for-next

Made a trivial tab/space correction in the patch (pointed out by
checkpatch) and then added a trivial followon patch to address a
comment/style (trivial)
issue pointed out by checkpatch and to add a little more detailed
comments about generally when to use each debug function.  If any
objections let me know.


On Sun, Oct 7, 2018 at 10:21 AM Rodrigo Freire <rfreire@redhat.com> wrote:
>
> Hi Steve,
> From our conversation over v2, I came out with this v3 patch, which I broke
> in two commits:
>
> * The first commit in cifs_debug.h, creating the cifs_info() function.
>   - The aim of this commit is to allow to the developer to be able to print
>     informational-level data without having to use pr_info, pr_notice etc,
>     in line with other filesystems.
>     . One interesting and noteworthy feature of cifs_info() is that it is
>       transparent to the CIFS_DEBUG config state, either in "y" or "n".
>     . Also, by using KERN_INFO level, it can be safely filtered by a
>       maintainer / administrator, without cluttering their log monitors,
>       since this is a low level alert.
>   - I took the liberty to not add it inside the existing pr_debug, because
>     of the eventual need of some developer to print stuff that should be
>     printed not only in CIFS_DEBUG mode (as there are plenty of pr_notice
>     scattered over the code).
>   - Also, this is not a debug but a info message, so i liked cifs_info()
>     more ;-)
>   - I saw plenty of pr_notice() in CIFS code, but I resisted the urge to
>     convert them to cifs_info().
>
> * The second commit contains the code printing a cifs_info() when attempting
>   a CIFS mount operation.
>
> Appreciate your review.
>
> V3: Created a new cifs_info() function, moved the mount attempt message to
>     cifs_info
>
> V2: Created a loop to select the right cifs_dbg message to be printed,
>     considering the current system's scenario, in order to avoid a
>     duplicate message or stripping out important information in
>     debug.
>
> Rodrigo Freire (2):
>   CIFS: Adds information-level logging function
>   CIFS: Print message when attempting a mount
>
>  fs/cifs/cifs_debug.h | 16 ++++++++++++++++
>  fs/cifs/cifsfs.c     |  7 ++++++-
>  fs/cifs/transport.c  |  2 +-
>  3 files changed, 23 insertions(+), 2 deletions(-)
>
> --
> 1.8.3.1
>


-- 
Thanks,

Steve

[-- Attachment #2: 0001-cifs-minor-clarification-in-comments.patch --]
[-- Type: text/x-patch, Size: 1951 bytes --]

From 4c939344f94a273a1eab89cf58f74c9ad68a8a8d Mon Sep 17 00:00:00 2001
From: Steve French <stfrench@microsoft.com>
Date: Sun, 7 Oct 2018 13:52:18 -0500
Subject: [PATCH] cifs: minor clarification in comments

Clarify meaning (in comments) meaning of various
options for debug messages in cifs.ko. Also fixed
trivial formatting/style issue with previous patch.

Signed-off-by: Steve French <stfrench@microsoft.com>
---
 fs/cifs/cifs_debug.h | 12 ++++++++++++
 fs/cifs/cifsfs.c     |  6 ++++--
 2 files changed, 16 insertions(+), 2 deletions(-)

diff --git a/fs/cifs/cifs_debug.h b/fs/cifs/cifs_debug.h
index 72db2987e066..631dc1bb21c1 100644
--- a/fs/cifs/cifs_debug.h
+++ b/fs/cifs/cifs_debug.h
@@ -47,6 +47,18 @@ extern int cifsFYI;
  */
 #ifdef CONFIG_CIFS_DEBUG
 
+
+/*
+ * When adding tracepoints and debug messages we have various choices.
+ * Some considerations:
+ *
+ * Use cifs_dbg(VFS, ...) for things we always want logged, and the user to see
+ *     cifs_info(...) slightly less important, admin can filter via loglevel > 6
+ *     cifs_dbg(FYI, ...) minor debugging messages, off by default
+ *     trace_smb3_*  ftrace functions are preferred for complex debug messages
+ *                 intended for developers or experienced admins, off by default
+ */
+
 /* Information level messages, minor events */
 #define cifs_info_func(ratefunc, fmt, ...)			\
 do {								\
diff --git a/fs/cifs/cifsfs.c b/fs/cifs/cifsfs.c
index d78a31560995..7de9603c54f1 100644
--- a/fs/cifs/cifsfs.c
+++ b/fs/cifs/cifsfs.c
@@ -717,8 +717,10 @@ cifs_smb3_do_mount(struct file_system_type *fs_type,
 	struct cifs_mnt_data mnt_data;
 	struct dentry *root;
 
-	/* Prints in Kernel / CIFS log the attempted mount operation *
-	 *	IF CIFS_DEBUG && cifs_FYI */
+	/*
+	 * Prints in Kernel / CIFS log the attempted mount operation
+	 *	If CIFS_DEBUG && cifs_FYI
+	 */
 	if (cifsFYI)
 		cifs_dbg(FYI, "Devname: %s flags: %d\n", dev_name, flags);
 	else
-- 
2.17.1

Re: [PATCH v3 0/2] CIFS: Info-level log support, print message when attempting mount.

[Rodrigo Freire]

Thanks Steve! Sorry for overlooking it, whoops.

One more question; what’s your/community opinion on rewriting the existing pr_notice to the new cifs_info?

I could happily retrofit it.

Have a great week!

- RF
Sent from a mobile device

> On 7 Oct 2018, at 15:59, Steve French <smfrench@gmail.com> wrote:
> 
> Merged into cifs-2.6.git for-next
> 
> Made a trivial tab/space correction in the patch (pointed out by
> checkpatch) and then added a trivial followon patch to address a
> comment/style (trivial)
> issue pointed out by checkpatch and to add a little more detailed
> comments about generally when to use each debug function.  If any
> objections let me know.
> 
> 
>> On Sun, Oct 7, 2018 at 10:21 AM Rodrigo Freire <rfreire@redhat.com> wrote:
>> 
>> Hi Steve,
>> From our conversation over v2, I came out with this v3 patch, which I broke
>> in two commits:
>> 
>> * The first commit in cifs_debug.h, creating the cifs_info() function.
>>  - The aim of this commit is to allow to the developer to be able to print
>>    informational-level data without having to use pr_info, pr_notice etc,
>>    in line with other filesystems.
>>    . One interesting and noteworthy feature of cifs_info() is that it is
>>      transparent to the CIFS_DEBUG config state, either in "y" or "n".
>>    . Also, by using KERN_INFO level, it can be safely filtered by a
>>      maintainer / administrator, without cluttering their log monitors,
>>      since this is a low level alert.
>>  - I took the liberty to not add it inside the existing pr_debug, because
>>    of the eventual need of some developer to print stuff that should be
>>    printed not only in CIFS_DEBUG mode (as there are plenty of pr_notice
>>    scattered over the code).
>>  - Also, this is not a debug but a info message, so i liked cifs_info()
>>    more ;-)
>>  - I saw plenty of pr_notice() in CIFS code, but I resisted the urge to
>>    convert them to cifs_info().
>> 
>> * The second commit contains the code printing a cifs_info() when attempting
>>  a CIFS mount operation.
>> 
>> Appreciate your review.
>> 
>> V3: Created a new cifs_info() function, moved the mount attempt message to
>>    cifs_info
>> 
>> V2: Created a loop to select the right cifs_dbg message to be printed,
>>    considering the current system's scenario, in order to avoid a
>>    duplicate message or stripping out important information in
>>    debug.
>> 
>> Rodrigo Freire (2):
>>  CIFS: Adds information-level logging function
>>  CIFS: Print message when attempting a mount
>> 
>> fs/cifs/cifs_debug.h | 16 ++++++++++++++++
>> fs/cifs/cifsfs.c     |  7 ++++++-
>> fs/cifs/transport.c  |  2 +-
>> 3 files changed, 23 insertions(+), 2 deletions(-)
>> 
>> --
>> 1.8.3.1
>> 
> 
> 
> -- 
> Thanks,
> 
> Steve
> <0001-cifs-minor-clarification-in-comments.patch>

Re: [PATCH v3 0/2] CIFS: Info-level log support, print message when attempting mount.

[Steve French]

On Sun, Oct 7, 2018 at 3:27 PM Rodrigo Freire <rfreire@redhat.com> wrote:
>
> Thanks Steve! Sorry for overlooking it, whoops.
>
> One more question; what’s your/community opinion on rewriting the existing pr_notice to the new cifs_info?
>
> I could happily retrofit it.

I don't have a strong opinion. The four callers could be changed, but
my gut reaction
is that it is a much higher priority to add useful dynamic tracepoints
(ftrace ie trace-cmd)
to cifs to make it easier to debug real customer problems that are
currently awkward to
debug.   By comparison, even ext4 has over 100 dynamic tracepoints, but larger
file systems like XFS has 500 (!), and nfs (including SunRPC) has about 100.

My guess is that going from our current 28 dynamic trace points (in
cifs.ko) to double
that (at least) will happen as developers add tracepoints to help them
debug real
problems (and of course it will help developers working on future problems even
more ...)


> > On 7 Oct 2018, at 15:59, Steve French <smfrench@gmail.com> wrote:
> >
> > Merged into cifs-2.6.git for-next
> >
> > Made a trivial tab/space correction in the patch (pointed out by
> > checkpatch) and then added a trivial followon patch to address a
> > comment/style (trivial)
> > issue pointed out by checkpatch and to add a little more detailed
> > comments about generally when to use each debug function.  If any
> > objections let me know.
> >
> >
> >> On Sun, Oct 7, 2018 at 10:21 AM Rodrigo Freire <rfreire@redhat.com> wrote:
> >>
> >> Hi Steve,
> >> From our conversation over v2, I came out with this v3 patch, which I broke
> >> in two commits:
> >>
> >> * The first commit in cifs_debug.h, creating the cifs_info() function.
> >>  - The aim of this commit is to allow to the developer to be able to print
> >>    informational-level data without having to use pr_info, pr_notice etc,
> >>    in line with other filesystems.
> >>    . One interesting and noteworthy feature of cifs_info() is that it is
> >>      transparent to the CIFS_DEBUG config state, either in "y" or "n".
<snip>


-- 
Thanks,

Steve