[v2] CIFS: Print message when attempting a mount

Commit Message

Rodrigo Freire Oct. 2, 2018, 11:57 a.m. UTC

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.

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 VFS: 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 VFS: Attempting to mount //172.25.250.19/c$

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.

Signed-off-by: Rodrigo Freire <[e-mail]>
---
 fs/cifs/cifsfs.c | 6 +++++-
 1 file changed, 5 insertions(+), 1 deletion(-)

Comments

Steve French Oct. 2, 2018, 7:17 p.m. UTC | #1

Are you sure that these aren't logged by the automounter (for ext4,
xfs etc.).  When I looked in my dmesg logs I didn't find matching log
entries in the file systems themselves.  Do you have an example?

On the idea of adding cifsFYI logging here - I slightly prefer using
ftrace (trace-cmd, ie dynamic tracing) so there is less overhead and
easier to turn on/off following the example of xfs, f2fs, nfs, nfsd
etc.
On Tue, Oct 2, 2018 at 6:57 AM Rodrigo Freire <[e-mail]> wrote:
>
> 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.
>
> 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 VFS: 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 VFS: Attempting to mount //172.25.250.19/c$
>
> 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.
>
> Signed-off-by: Rodrigo Freire <[e-mail]>
> ---
>  fs/cifs/cifsfs.c | 6 +++++-
>  1 file changed, 5 insertions(+), 1 deletion(-)
>
> diff --git a/fs/cifs/cifsfs.c b/fs/cifs/cifsfs.c
> index 7065426..7fde6bc 100644
> --- a/fs/cifs/cifsfs.c
> +++ b/fs/cifs/cifsfs.c
> @@ -707,7 +707,11 @@ 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 (cifsFYI)
> +               cifs_dbg(FYI, "Devname: %s flags: %d\n", dev_name, flags);
> +       else
> +               cifs_dbg(VFS, "Attempting to mount %s\n", dev_name);
>
>         volume_info = cifs_get_volume_info((char *)data, dev_name, is_smb3);
>         if (IS_ERR(volume_info))
> --
> 1.8.3.1
>

Rodrigo Freire Oct. 2, 2018, 7:28 p.m. UTC | #2

Hi Steve,

----- Original Message ----- 
> From: "Steve French" <[e-mail]>
> To: [e-mail]
> Cc: "LKML" <[e-mail]>, "Steve French"
> <[e-mail]>, "CIFS" <[e-mail]>, "Pavel Shilovsky"
> <[e-mail]>
> Sent: Tuesday, October 2, 2018 4:17:02 PM
> Subject: Re: [PATCH v2] CIFS: Print message when attempting a mount
>
> Are you sure that these aren't logged by the automounter (for ext4,
> xfs etc.). When I looked in my dmesg logs I didn't find matching log
> entries in the file systems themselves. Do you have an example?

I'm positive about it. Check it out:

[rfreire@rf ~]$ cd git/upstream/fs/ext4/
[rfreire@rf ext4]$ 
[rfreire@rf ext4]$ 
[rfreire@rf ext4]$ grep -r "mounted filesystem with"
super.c:		ext4_msg(sb, KERN_INFO, "mounted filesystem with%s. "


[rfreire@rf ext4]$ dmesg | grep mount
[   21.550897] EXT4-fs (dm-1): mounted filesystem with ordered data mode. Opts: (null)
[   22.216213] EXT4-fs (dm-1): re-mounted. Opts: discard
[   22.598267] EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null)
[   22.605225] EXT4-fs (sdc): mounted filesystem without journal. Opts: discard
[   24.029161] EXT4-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null)
[   24.047777] EXT4-fs (dm-4): mounted filesystem without journal. Opts: (null)

XFS sample dmesg (from https://www.reddit.com/r/archlinux/comments/40b9r9/xfs_partition_is_mounted_during_boot_and_then/):

[ 2.764491] XFS (sdb1): Mounting V5 Filesystem
[ 3.200886] XFS (sdb1): Ending clean mount
[ 5.384218] XFS (sdb1): Unmounting Filesystem

Relevant code:

[rfreire@rf ~]$ cd ../xfs

[rfreire@rf xfs]$ grep "Mounting V" *.c
xfs_log.c:		xfs_notice(mp, "Mounting V%d Filesystem",


> On the idea of adding cifsFYI logging here - I slightly prefer using
> ftrace (trace-cmd, ie dynamic tracing) so there is less overhead and
> easier to turn on/off following the example of xfs, f2fs, nfs, nfsd
> etc.

Remember that cifsFYI already exists; I just moved it inside a if clause
to print it only when running under debug. (they way it is originally).

> On Tue, Oct 2, 2018 at 6:57 AM Rodrigo Freire <[e-mail]> wrote:
> >
> > 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.


> --
> Thanks,

Thank You! o/

Steve French Oct. 2, 2018, 8:35 p.m. UTC | #3

I noticed that on at least the first system I looked at (Ubuntu 18.04)
it defaults to KERN_WARNING (ie 4) so wouldn't have shown a KERN_INFO
which is level 6 (as the mount example from ext4) by default
or the xfs_notice (which is level 5)

https://elinux.org/Debugging_by_printing

On Tue, Oct 2, 2018 at 2:28 PM Rodrigo Freire <[e-mail]> wrote:
>
> Hi Steve,
>
> ----- Original Message -----
> > From: "Steve French" <[e-mail]>
> > To: [e-mail]
> > Cc: "LKML" <[e-mail]>, "Steve French"
> > <[e-mail]>, "CIFS" <[e-mail]>, "Pavel Shilovsky"
> > <[e-mail]>
> > Sent: Tuesday, October 2, 2018 4:17:02 PM
> > Subject: Re: [PATCH v2] CIFS: Print message when attempting a mount
> >
> > Are you sure that these aren't logged by the automounter (for ext4,
> > xfs etc.). When I looked in my dmesg logs I didn't find matching log
> > entries in the file systems themselves. Do you have an example?
>
> I'm positive about it. Check it out:
>
> [rfreire@rf ~]$ cd git/upstream/fs/ext4/
> [rfreire@rf ext4]$
> [rfreire@rf ext4]$
> [rfreire@rf ext4]$ grep -r "mounted filesystem with"
> super.c:                ext4_msg(sb, KERN_INFO, "mounted filesystem with%s. "
>
>
> [rfreire@rf ext4]$ dmesg | grep mount
> [   21.550897] EXT4-fs (dm-1): mounted filesystem with ordered data mode. Opts: (null)
> [   22.216213] EXT4-fs (dm-1): re-mounted. Opts: discard
> [   22.598267] EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null)
> [   22.605225] EXT4-fs (sdc): mounted filesystem without journal. Opts: discard
> [   24.029161] EXT4-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null)
> [   24.047777] EXT4-fs (dm-4): mounted filesystem without journal. Opts: (null)
>
> XFS sample dmesg (from https://www.reddit.com/r/archlinux/comments/40b9r9/xfs_partition_is_mounted_during_boot_and_then/):
>
> [ 2.764491] XFS (sdb1): Mounting V5 Filesystem
> [ 3.200886] XFS (sdb1): Ending clean mount
> [ 5.384218] XFS (sdb1): Unmounting Filesystem
>
> Relevant code:
>
> [rfreire@rf ~]$ cd ../xfs
>
> [rfreire@rf xfs]$ grep "Mounting V" *.c
> xfs_log.c:              xfs_notice(mp, "Mounting V%d Filesystem",
>
>
> > On the idea of adding cifsFYI logging here - I slightly prefer using
> > ftrace (trace-cmd, ie dynamic tracing) so there is less overhead and
> > easier to turn on/off following the example of xfs, f2fs, nfs, nfsd
> > etc.
>
> Remember that cifsFYI already exists; I just moved it inside a if clause
> to print it only when running under debug. (they way it is originally).
>
> > On Tue, Oct 2, 2018 at 6:57 AM Rodrigo Freire <[e-mail]> wrote:
> > >
> > > 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.
>
>
> > --
> > Thanks,
>
> Thank You! o/

Rodrigo Freire Oct. 2, 2018, 9:20 p.m. UTC | #4

Hi Steve o/

I personally like more a pr_info() instead of a cifs_dbg (which wraps to a
pr_warn). But in order to keep in line with the general CIFS coding style
I stuck to cifs_dbg

But I would happily rewrite the cifs_dbg to pr_info a v3: That would be
good enough too.

Ah for what is worth my test/target systems are CentOS/Red Hat Enterprise
Linux.

Thoughts?

Thanks!

- RF.

----- Original Message ----- 
> From: "Steve French" <[e-mail]>
> To: [e-mail]
> Cc: "LKML" <[e-mail]>, "Steve French"
> <[e-mail]>, "CIFS" <[e-mail]>, "Pavel Shilovsky"
> <[e-mail]>
> Sent: Tuesday, October 2, 2018 5:35:49 PM
> Subject: Re: [PATCH v2] CIFS: Print message when attempting a mount

> I noticed that on at least the first system I looked at (Ubuntu 18.04)
> it defaults to KERN_WARNING (ie 4) so wouldn't have shown a KERN_INFO
> which is level 6 (as the mount example from ext4) by default
> or the xfs_notice (which is level 5)

> https://elinux.org/Debugging_by_printing

> On Tue, Oct 2, 2018 at 2:28 PM Rodrigo Freire <[e-mail]> wrote:
> >
> > Hi Steve,
> >
> > ----- Original Message -----
> > > From: "Steve French" <[e-mail]>
> > > To: [e-mail]
> > > Cc: "LKML" <[e-mail]>, "Steve French"
> > > <[e-mail]>, "CIFS" <[e-mail]>, "Pavel
> > > Shilovsky"
> > > <[e-mail]>
> > > Sent: Tuesday, October 2, 2018 4:17:02 PM
> > > Subject: Re: [PATCH v2] CIFS: Print message when attempting a mount
> > >
> > > Are you sure that these aren't logged by the automounter (for ext4,
> > > xfs etc.). When I looked in my dmesg logs I didn't find matching log
> > > entries in the file systems themselves. Do you have an example?
> >
> > I'm positive about it. Check it out:
> >
> > [rfreire@rf ~]$ cd git/upstream/fs/ext4/
> > [rfreire@rf ext4]$
> > [rfreire@rf ext4]$
> > [rfreire@rf ext4]$ grep -r "mounted filesystem with"
> > super.c: ext4_msg(sb, KERN_INFO, "mounted filesystem with%s. "
> >
> >
> > [rfreire@rf ext4]$ dmesg | grep mount
> > [ 21.550897] EXT4-fs (dm-1): mounted filesystem with ordered data mode.
> > Opts: (null)
> > [ 22.216213] EXT4-fs (dm-1): re-mounted. Opts: discard
> > [ 22.598267] EXT4-fs (sda1): mounted filesystem with ordered data mode.
> > Opts: (null)
> > [ 22.605225] EXT4-fs (sdc): mounted filesystem without journal. Opts:
> > discard
> > [ 24.029161] EXT4-fs (dm-2): mounted filesystem with ordered data mode.
> > Opts: (null)
> > [ 24.047777] EXT4-fs (dm-4): mounted filesystem without journal. Opts:
> > (null)
> >
> > XFS sample dmesg (from
> > https://www.reddit.com/r/archlinux/comments/40b9r9/xfs_partition_is_mounted_during_boot_and_then/):
> >
> > [ 2.764491] XFS (sdb1): Mounting V5 Filesystem
> > [ 3.200886] XFS (sdb1): Ending clean mount
> > [ 5.384218] XFS (sdb1): Unmounting Filesystem
> >
> > Relevant code:
> >
> > [rfreire@rf ~]$ cd ../xfs
> >
> > [rfreire@rf xfs]$ grep "Mounting V" *.c
> > xfs_log.c: xfs_notice(mp, "Mounting V%d Filesystem",
> >
> >
> > > On the idea of adding cifsFYI logging here - I slightly prefer using
> > > ftrace (trace-cmd, ie dynamic tracing) so there is less overhead and
> > > easier to turn on/off following the example of xfs, f2fs, nfs, nfsd
> > > etc.
> >
> > Remember that cifsFYI already exists; I just moved it inside a if clause
> > to print it only when running under debug. (they way it is originally).
> >
> > > On Tue, Oct 2, 2018 at 6:57 AM Rodrigo Freire <[e-mail]> wrote:
> > > >
> > > > 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.
> >
> >
> > > --
> > > Thanks,
> >
> > Thank You! o/

> --
> Thanks,

> Steve

Steve French Oct. 2, 2018, 9:25 p.m. UTC | #5

It is an interesting question - my gut reaction is that messages that
need more immediate attention should be logged as KERN_ERR (similar to
cifs_dbg(VFS ...) but given how easy it is now to use dynamic tracing
and better to read, if a developer would need it ... probably best to
use ftrace (trace-cmd).  Note that xfs has more than 570 (!) dynamic
trace point callouts now vs. fewer than 30 for xfs_notice
On Tue, Oct 2, 2018 at 4:20 PM Rodrigo Freire <[e-mail]> wrote:
>
> Hi Steve o/
>
> I personally like more a pr_info() instead of a cifs_dbg (which wraps to a
> pr_warn). But in order to keep in line with the general CIFS coding style
> I stuck to cifs_dbg
>
> But I would happily rewrite the cifs_dbg to pr_info a v3: That would be
> good enough too.
>
> Ah for what is worth my test/target systems are CentOS/Red Hat Enterprise
> Linux.
>
> Thoughts?
>
> Thanks!
>
> - RF.
>
> ----- Original Message -----
> > From: "Steve French" <[e-mail]>
> > To: [e-mail]
> > Cc: "LKML" <[e-mail]>, "Steve French"
> > <[e-mail]>, "CIFS" <[e-mail]>, "Pavel Shilovsky"
> > <[e-mail]>
> > Sent: Tuesday, October 2, 2018 5:35:49 PM
> > Subject: Re: [PATCH v2] CIFS: Print message when attempting a mount
>
> > I noticed that on at least the first system I looked at (Ubuntu 18.04)
> > it defaults to KERN_WARNING (ie 4) so wouldn't have shown a KERN_INFO
> > which is level 6 (as the mount example from ext4) by default
> > or the xfs_notice (which is level 5)
>
> > https://elinux.org/Debugging_by_printing
>
> > On Tue, Oct 2, 2018 at 2:28 PM Rodrigo Freire <[e-mail]> wrote:
> > >
> > > Hi Steve,
> > >
> > > ----- Original Message -----
> > > > From: "Steve French" <[e-mail]>
> > > > To: [e-mail]
> > > > Cc: "LKML" <[e-mail]>, "Steve French"
> > > > <[e-mail]>, "CIFS" <[e-mail]>, "Pavel
> > > > Shilovsky"
> > > > <[e-mail]>
> > > > Sent: Tuesday, October 2, 2018 4:17:02 PM
> > > > Subject: Re: [PATCH v2] CIFS: Print message when attempting a mount
> > > >
> > > > Are you sure that these aren't logged by the automounter (for ext4,
> > > > xfs etc.). When I looked in my dmesg logs I didn't find matching log
> > > > entries in the file systems themselves. Do you have an example?
> > >
> > > I'm positive about it. Check it out:
> > >
> > > [rfreire@rf ~]$ cd git/upstream/fs/ext4/
> > > [rfreire@rf ext4]$
> > > [rfreire@rf ext4]$
> > > [rfreire@rf ext4]$ grep -r "mounted filesystem with"
> > > super.c: ext4_msg(sb, KERN_INFO, "mounted filesystem with%s. "
> > >
> > >
> > > [rfreire@rf ext4]$ dmesg | grep mount
> > > [ 21.550897] EXT4-fs (dm-1): mounted filesystem with ordered data mode.
> > > Opts: (null)
> > > [ 22.216213] EXT4-fs (dm-1): re-mounted. Opts: discard
> > > [ 22.598267] EXT4-fs (sda1): mounted filesystem with ordered data mode.
> > > Opts: (null)
> > > [ 22.605225] EXT4-fs (sdc): mounted filesystem without journal. Opts:
> > > discard
> > > [ 24.029161] EXT4-fs (dm-2): mounted filesystem with ordered data mode.
> > > Opts: (null)
> > > [ 24.047777] EXT4-fs (dm-4): mounted filesystem without journal. Opts:
> > > (null)
> > >
> > > XFS sample dmesg (from
> > > https://www.reddit.com/r/archlinux/comments/40b9r9/xfs_partition_is_mounted_during_boot_and_then/):
> > >
> > > [ 2.764491] XFS (sdb1): Mounting V5 Filesystem
> > > [ 3.200886] XFS (sdb1): Ending clean mount
> > > [ 5.384218] XFS (sdb1): Unmounting Filesystem
> > >
> > > Relevant code:
> > >
> > > [rfreire@rf ~]$ cd ../xfs
> > >
> > > [rfreire@rf xfs]$ grep "Mounting V" *.c
> > > xfs_log.c: xfs_notice(mp, "Mounting V%d Filesystem",
> > >
> > >
> > > > On the idea of adding cifsFYI logging here - I slightly prefer using
> > > > ftrace (trace-cmd, ie dynamic tracing) so there is less overhead and
> > > > easier to turn on/off following the example of xfs, f2fs, nfs, nfsd
> > > > etc.
> > >
> > > Remember that cifsFYI already exists; I just moved it inside a if clause
> > > to print it only when running under debug. (they way it is originally).
> > >
> > > > On Tue, Oct 2, 2018 at 6:57 AM Rodrigo Freire <[e-mail]> wrote:
> > > > >
> > > > > 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.
> > >
> > >
> > > > --
> > > > Thanks,
> > >
> > > Thank You! o/
>
> > --
> > Thanks,
>
> > Steve

Rodrigo Freire Oct. 2, 2018, 9:53 p.m. UTC | #6

Hi hi again Steve \o

I do see potential for a ftrace rewrite for the cifs_dbg messages.

But for the original post, I am aiming for a message to be printed
and found in dmesg, helping to correlate and troubleshoot events in
production systems.

So given the debugging nature of ftrace, this is not of help for my
patch request.

So, ACK for v2, using cifs_dbg(VFS) which actually translates to a
pr_warn(), or request a V3 using pr_info() (which I am absolutely fine
with) or...?

Let me know.

I appreciate your time and review!

- RF.

----- Original Message ----- 

> From: "Steve French" <[e-mail]>
> To: [e-mail]
> Cc: "LKML" <[e-mail]>, "Steve French"
> <[e-mail]>, "CIFS" <[e-mail]>, "Pavel Shilovsky"
> <[e-mail]>
> Sent: Tuesday, October 2, 2018 6:25:46 PM
> Subject: Re: [PATCH v2] CIFS: Print message when attempting a mount

> It is an interesting question - my gut reaction is that messages that
> need more immediate attention should be logged as KERN_ERR (similar to
> cifs_dbg(VFS ...) but given how easy it is now to use dynamic tracing
> and better to read, if a developer would need it ... probably best to
> use ftrace (trace-cmd). Note that xfs has more than 570 (!) dynamic
> trace point callouts now vs. fewer than 30 for xfs_notice
> On Tue, Oct 2, 2018 at 4:20 PM Rodrigo Freire <[e-mail]> wrote:
> >
> > Hi Steve o/
> >
> > I personally like more a pr_info() instead of a cifs_dbg (which wraps to a
> > pr_warn). But in order to keep in line with the general CIFS coding style
> > I stuck to cifs_dbg
> >
> > But I would happily rewrite the cifs_dbg to pr_info a v3: That would be
> > good enough too.
> >
> > Ah for what is worth my test/target systems are CentOS/Red Hat Enterprise
> > Linux.
> >
> > Thoughts?
> >
> > Thanks!
> >
> > - RF.
> >
> > ----- Original Message -----
> > > From: "Steve French" <[e-mail]>
> > > To: [e-mail]
> > > Cc: "LKML" <[e-mail]>, "Steve French"
> > > <[e-mail]>, "CIFS" <[e-mail]>, "Pavel
> > > Shilovsky"
> > > <[e-mail]>
> > > Sent: Tuesday, October 2, 2018 5:35:49 PM
> > > Subject: Re: [PATCH v2] CIFS: Print message when attempting a mount
> >
> > > I noticed that on at least the first system I looked at (Ubuntu 18.04)
> > > it defaults to KERN_WARNING (ie 4) so wouldn't have shown a KERN_INFO
> > > which is level 6 (as the mount example from ext4) by default
> > > or the xfs_notice (which is level 5)
> >
> > > https://elinux.org/Debugging_by_printing
> >
> > > On Tue, Oct 2, 2018 at 2:28 PM Rodrigo Freire <[e-mail]> wrote:
> > > >
> > > > Hi Steve,
> > > >
> > > > ----- Original Message -----
> > > > > From: "Steve French" <[e-mail]>
> > > > > To: [e-mail]
> > > > > Cc: "LKML" <[e-mail]>, "Steve French"
> > > > > <[e-mail]>, "CIFS" <[e-mail]>, "Pavel
> > > > > Shilovsky"
> > > > > <[e-mail]>
> > > > > Sent: Tuesday, October 2, 2018 4:17:02 PM
> > > > > Subject: Re: [PATCH v2] CIFS: Print message when attempting a mount
> > > > >
> > > > > Are you sure that these aren't logged by the automounter (for ext4,
> > > > > xfs etc.). When I looked in my dmesg logs I didn't find matching log
> > > > > entries in the file systems themselves. Do you have an example?
> > > >
> > > > I'm positive about it. Check it out:
> > > >
> > > > [rfreire@rf ~]$ cd git/upstream/fs/ext4/
> > > > [rfreire@rf ext4]$
> > > > [rfreire@rf ext4]$
> > > > [rfreire@rf ext4]$ grep -r "mounted filesystem with"
> > > > super.c: ext4_msg(sb, KERN_INFO, "mounted filesystem with%s. "
> > > >
> > > >
> > > > [rfreire@rf ext4]$ dmesg | grep mount
> > > > [ 21.550897] EXT4-fs (dm-1): mounted filesystem with ordered data mode.
> > > > Opts: (null)
> > > > [ 22.216213] EXT4-fs (dm-1): re-mounted. Opts: discard
> > > > [ 22.598267] EXT4-fs (sda1): mounted filesystem with ordered data mode.
> > > > Opts: (null)
> > > > [ 22.605225] EXT4-fs (sdc): mounted filesystem without journal. Opts:
> > > > discard
> > > > [ 24.029161] EXT4-fs (dm-2): mounted filesystem with ordered data mode.
> > > > Opts: (null)
> > > > [ 24.047777] EXT4-fs (dm-4): mounted filesystem without journal. Opts:
> > > > (null)
> > > >
> > > > XFS sample dmesg (from
> > > > https://www.reddit.com/r/archlinux/comments/40b9r9/xfs_partition_is_mounted_during_boot_and_then/):
> > > >
> > > > [ 2.764491] XFS (sdb1): Mounting V5 Filesystem
> > > > [ 3.200886] XFS (sdb1): Ending clean mount
> > > > [ 5.384218] XFS (sdb1): Unmounting Filesystem
> > > >
> > > > Relevant code:
> > > >
> > > > [rfreire@rf ~]$ cd ../xfs
> > > >
> > > > [rfreire@rf xfs]$ grep "Mounting V" *.c
> > > > xfs_log.c: xfs_notice(mp, "Mounting V%d Filesystem",
> > > >
> > > >
> > > > > On the idea of adding cifsFYI logging here - I slightly prefer using
> > > > > ftrace (trace-cmd, ie dynamic tracing) so there is less overhead and
> > > > > easier to turn on/off following the example of xfs, f2fs, nfs, nfsd
> > > > > etc.
> > > >
> > > > Remember that cifsFYI already exists; I just moved it inside a if
> > > > clause
> > > > to print it only when running under debug. (they way it is originally).
> > > >
> > > > > On Tue, Oct 2, 2018 at 6:57 AM Rodrigo Freire <[e-mail]>
> > > > > wrote:
> > > > > >
> > > > > > 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.
> > > >
> > > >
> > > > > --
> > > > > Thanks,
> > > >
> > > > Thank You! o/
> >
> > > --
> > > Thanks,
> >
> > > Steve

> --
> Thanks,

> Steve

Steven French Oct. 6, 2018, 5:13 p.m. UTC | #7

Comparing what other file systems print to dmesg at mount time is 
interesting - just tried it for  four file systems, two log nothing by 
default, two log something. See below.


BTRFS:

root@smf-Thinkpad-P51:~/# mount /btrfs
root@smf-Thinkpad-P51:~/c# dmesg
[96283.701117] BTRFS info (device mmcblk0p1): disk space caching is enabled
[96283.701121] BTRFS info (device mmcblk0p1): has skinny extents
[96283.708477] BTRFS info (device mmcblk0p1): enabling ssd optimizations


EXT4:

root@smf-Thinkpad-P51:~# mount /dev/nvme0n1p6 /ext4
root@smf-Thinkpad-P51:~# dmesg
[96654.422038] EXT4-fs (nvme0n1p6): mounted filesystem with ordered data 
mode. Opts: (null)


VFAT:

root@smf-Thinkpad-P51:~# mount /dev/nvme0n1p1 /fat
root@smf-Thinkpad-P51:~# dmesg
root@smf-Thinkpad-P51:~#


NFS (it logs messages first time the module is loaded, for the 
id_resolver, but not for the mount):

root@smf-Thinkpad-P51:~# mount -t nfs localhost:/nfsexport /nfs
root@smf-Thinkpad-P51:~# dmesg
root@smf-Thinkpad-P51:~#


On 10/02/2018 04:53 PM, Rodrigo Freire wrote:
> Hi hi again Steve \o
>
> I do see potential for a ftrace rewrite for the cifs_dbg messages.
>
> But for the original post, I am aiming for a message to be printed
> and found in dmesg, helping to correlate and troubleshoot events in
> production systems.
>
> So given the debugging nature of ftrace, this is not of help for my
> patch request.
>
> So, ACK for v2, using cifs_dbg(VFS) which actually translates to a
> pr_warn(), or request a V3 using pr_info() (which I am absolutely fine
> with) or...?
>
> Let me know.
>
> I appreciate your time and review!
>
> - RF.
>
> ----- Original Message -----
>
>> From: "Steve French" <[e-mail]>
>> To: [e-mail]
>> Cc: "LKML" <[e-mail]>, "Steve French"
>> <[e-mail]>, "CIFS" <[e-mail]>, "Pavel Shilovsky"
>> <[e-mail]>
>> Sent: Tuesday, October 2, 2018 6:25:46 PM
>> Subject: Re: [PATCH v2] CIFS: Print message when attempting a mount
>> It is an interesting question - my gut reaction is that messages that
>> need more immediate attention should be logged as KERN_ERR (similar to
>> cifs_dbg(VFS ...) but given how easy it is now to use dynamic tracing
>> and better to read, if a developer would need it ... probably best to
>> use ftrace (trace-cmd). Note that xfs has more than 570 (!) dynamic
>> trace point callouts now vs. fewer than 30 for xfs_notice
>> On Tue, Oct 2, 2018 at 4:20 PM Rodrigo Freire <[e-mail]> wrote:
>>> Hi Steve o/
>>>
>>> I personally like more a pr_info() instead of a cifs_dbg (which wraps to a
>>> pr_warn). But in order to keep in line with the general CIFS coding style
>>> I stuck to cifs_dbg
>>>
>>> But I would happily rewrite the cifs_dbg to pr_info a v3: That would be
>>> good enough too.
>>>
>>> Ah for what is worth my test/target systems are CentOS/Red Hat Enterprise
>>> Linux.
>>>
>>> Thoughts?
>>>
>>> Thanks!
>>>
>>> - RF.
>>>
>>> ----- Original Message -----
>>>> From: "Steve French" <[e-mail]>
>>>> To: [e-mail]
>>>> Cc: "LKML" <[e-mail]>, "Steve French"
>>>> <[e-mail]>, "CIFS" <[e-mail]>, "Pavel
>>>> Shilovsky"
>>>> <[e-mail]>
>>>> Sent: Tuesday, October 2, 2018 5:35:49 PM
>>>> Subject: Re: [PATCH v2] CIFS: Print message when attempting a mount
>>>> I noticed that on at least the first system I looked at (Ubuntu 18.04)
>>>> it defaults to KERN_WARNING (ie 4) so wouldn't have shown a KERN_INFO
>>>> which is level 6 (as the mount example from ext4) by default
>>>> or the xfs_notice (which is level 5)
>>>> https://elinux.org/Debugging_by_printing
>>>> On Tue, Oct 2, 2018 at 2:28 PM Rodrigo Freire <[e-mail]> wrote:
>>>>> Hi Steve,
>>>>>
>>>>> ----- Original Message -----
>>>>>> From: "Steve French" <[e-mail]>
>>>>>> To: [e-mail]
>>>>>> Cc: "LKML" <[e-mail]>, "Steve French"
>>>>>> <[e-mail]>, "CIFS" <[e-mail]>, "Pavel
>>>>>> Shilovsky"
>>>>>> <[e-mail]>
>>>>>> Sent: Tuesday, October 2, 2018 4:17:02 PM
>>>>>> Subject: Re: [PATCH v2] CIFS: Print message when attempting a mount
>>>>>>
>>>>>> Are you sure that these aren't logged by the automounter (for ext4,
>>>>>> xfs etc.). When I looked in my dmesg logs I didn't find matching log
>>>>>> entries in the file systems themselves. Do you have an example?
>>>>> I'm positive about it. Check it out:
>>>>>
>>>>> [rfreire@rf ~]$ cd git/upstream/fs/ext4/
>>>>> [rfreire@rf ext4]$
>>>>> [rfreire@rf ext4]$
>>>>> [rfreire@rf ext4]$ grep -r "mounted filesystem with"
>>>>> super.c: ext4_msg(sb, KERN_INFO, "mounted filesystem with%s. "
>>>>>
>>>>>
>>>>> [rfreire@rf ext4]$ dmesg | grep mount
>>>>> [ 21.550897] EXT4-fs (dm-1): mounted filesystem with ordered data mode.
>>>>> Opts: (null)
>>>>> [ 22.216213] EXT4-fs (dm-1): re-mounted. Opts: discard
>>>>> [ 22.598267] EXT4-fs (sda1): mounted filesystem with ordered data mode.
>>>>> Opts: (null)
>>>>> [ 22.605225] EXT4-fs (sdc): mounted filesystem without journal. Opts:
>>>>> discard
>>>>> [ 24.029161] EXT4-fs (dm-2): mounted filesystem with ordered data mode.
>>>>> Opts: (null)
>>>>> [ 24.047777] EXT4-fs (dm-4): mounted filesystem without journal. Opts:
>>>>> (null)
>>>>>
>>>>> XFS sample dmesg (from
>>>>> https://www.reddit.com/r/archlinux/comments/40b9r9/xfs_partition_is_mounted_during_boot_and_then/):
>>>>>
>>>>> [ 2.764491] XFS (sdb1): Mounting V5 Filesystem
>>>>> [ 3.200886] XFS (sdb1): Ending clean mount
>>>>> [ 5.384218] XFS (sdb1): Unmounting Filesystem
>>>>>
>>>>> Relevant code:
>>>>>
>>>>> [rfreire@rf ~]$ cd ../xfs
>>>>>
>>>>> [rfreire@rf xfs]$ grep "Mounting V" *.c
>>>>> xfs_log.c: xfs_notice(mp, "Mounting V%d Filesystem",
>>>>>
>>>>>
>>>>>> On the idea of adding cifsFYI logging here - I slightly prefer using
>>>>>> ftrace (trace-cmd, ie dynamic tracing) so there is less overhead and
>>>>>> easier to turn on/off following the example of xfs, f2fs, nfs, nfsd
>>>>>> etc.
>>>>> Remember that cifsFYI already exists; I just moved it inside a if
>>>>> clause
>>>>> to print it only when running under debug. (they way it is originally).
>>>>>
>>>>>> On Tue, Oct 2, 2018 at 6:57 AM Rodrigo Freire <[e-mail]>
>>>>>> wrote:
>>>>>>> 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.
>>>>>
>>>>>> --
>>>>>> Thanks,
>>>>> Thank You! o/
>>>> --
>>>> Thanks,
>>>> Steve
>> --
>> Thanks,
>> Steve

Steve French Oct. 6, 2018, 7:09 p.m. UTC | #8

On Tue, Oct 2, 2018 at 4:53 PM Rodrigo Freire <[e-mail]> wrote:
>
> Hi hi again Steve \o
>
> I do see potential for a ftrace rewrite for the cifs_dbg messages.

Was looking at this on current kernels and debugging mount is probably
fine for developers (or users) - plenty of debug messages get printed
via the dynamic ftrace points.  In practice some would prefer less
noisy trace logs so the minimum set for some would be something like
this (which already works with current cifs).  If we want to add some
default log messages on mount to dmesg instead of the trace-cmd log,
maybe we should log them at a slightly less noisy level (as we see
with xfs and btrfs) so they will be more log friendly


root@smf-Thinkpad~/# trace-cmd record -e smb3_enter* -e smb3_exit*
Hit Ctrl^C to stop recording


root@smf-Thinkpad:~/# trace-cmd show
# tracer: nop
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
      mount.cifs-14199 [002] .... 97642.728411: smb3_enter:
cifs_mount: xid=20
      mount.cifs-14199 [002] .... 97642.728669: smb3_enter:
cifs_get_smb_ses: xid=21
      mount.cifs-14199 [003] .... 97642.742336: smb3_exit_done:
cifs_get_smb_ses: xid=21
      mount.cifs-14199 [003] .... 97642.742343: smb3_enter:
cifs_setup_ipc: xid=22
      mount.cifs-14199 [003] .... 97642.742530: smb3_exit_done:
cifs_setup_ipc: xid=22
      mount.cifs-14199 [003] .... 97642.742532: smb3_enter:
cifs_get_tcon: xid=23
      mount.cifs-14199 [003] .... 97642.742674: smb3_exit_done:
cifs_get_tcon: xid=23
      mount.cifs-14199 [003] .... 97642.743267: smb3_exit_done:
cifs_mount: xid=20
      mount.cifs-14199 [003] .... 97642.743311: smb3_enter:
cifs_root_iget: xid=24
      mount.cifs-14199 [003] .... 97642.743471: smb3_exit_done:
cifs_root_iget: xid=24

Rodrigo Freire Oct. 6, 2018, 7:32 p.m. UTC | #9

Hi Steve! o/ 

Appreciate your time and review. 

For a v3, what would you like more: a pr_info() straight away in the code
for the message, or, writing a new cifs_info() function wrapping
over pr_info, like we have in cifs_dbg (which translates to pr_debug or pr_err)?

Waiting for your comments. Thanks!

---
Rodrigo Freire - Principal Technical Account Manager
GLOBAL CUSTOMER SUCCESS - Partnering with you to help achieve your business goals
redhat.com | TRIED. TESTED. TRUSTED. | redhat.com/trusted 

----- Original Message ----- 

> From: "Steve French" <[e-mail]>
> To: [e-mail]
> Cc: "LKML" <[e-mail]>, "Steve French"
> <[e-mail]>, "CIFS" <[e-mail]>, "Pavel Shilovsky"
> <[e-mail]>
> Sent: Saturday, October 6, 2018 4:09:30 PM
> Subject: Re: [PATCH v2] CIFS: Print message when attempting a mount

> On Tue, Oct 2, 2018 at 4:53 PM Rodrigo Freire <[e-mail]> wrote:
> >
> > Hi hi again Steve \o
> >
> > I do see potential for a ftrace rewrite for the cifs_dbg messages.

> Was looking at this on current kernels and debugging mount is probably
> fine for developers (or users) - plenty of debug messages get printed
> via the dynamic ftrace points. In practice some would prefer less
> noisy trace logs so the minimum set for some would be something like
> this (which already works with current cifs). If we want to add some
> default log messages on mount to dmesg instead of the trace-cmd log,
> maybe we should log them at a slightly less noisy level (as we see
> with xfs and btrfs) so they will be more log friendly

> root@smf-Thinkpad~/# trace-cmd record -e smb3_enter* -e smb3_exit*
> Hit Ctrl^C to stop recording

> root@smf-Thinkpad:~/# trace-cmd show
> # tracer: nop
> #
> # _-----=> irqs-off
> # / _----=> need-resched
> # | / _---=> hardirq/softirq
> # || / _--=> preempt-depth
> # ||| / delay
> # TASK-PID CPU# |||| TIMESTAMP FUNCTION
> # | | | |||| | |
> mount.cifs-14199 [002] .... 97642.728411: smb3_enter:
> cifs_mount: xid=20
> mount.cifs-14199 [002] .... 97642.728669: smb3_enter:
> cifs_get_smb_ses: xid=21
> mount.cifs-14199 [003] .... 97642.742336: smb3_exit_done:
> cifs_get_smb_ses: xid=21
> mount.cifs-14199 [003] .... 97642.742343: smb3_enter:
> cifs_setup_ipc: xid=22
> mount.cifs-14199 [003] .... 97642.742530: smb3_exit_done:
> cifs_setup_ipc: xid=22
> mount.cifs-14199 [003] .... 97642.742532: smb3_enter:
> cifs_get_tcon: xid=23
> mount.cifs-14199 [003] .... 97642.742674: smb3_exit_done:
> cifs_get_tcon: xid=23
> mount.cifs-14199 [003] .... 97642.743267: smb3_exit_done:
> cifs_mount: xid=20
> mount.cifs-14199 [003] .... 97642.743311: smb3_enter:
> cifs_root_iget: xid=24
> mount.cifs-14199 [003] .... 97642.743471: smb3_exit_done:
> cifs_root_iget: xid=24

> --
> Thanks,

> Steve

Steve French Oct. 6, 2018, 11:27 p.m. UTC | #10

Maybe simplest approach to address your request is to add a less noisy
(pr_notice, or pr_info if you prefer) as xfs does in the example you
mentioned:

> xfs_log.c:              xfs_notice(mp, "Mounting V%d Filesystem",

Would be small addition to the following in cifs_debug.h

/* information message: e.g., configuration, major event */
#define cifs_dbg_func(ratefunc, type, fmt, ...)                 \
do {                                                            \
        if ((type) & FYI && cifsFYI & CIFS_INFO) {              \
                pr_debug_ ## ratefunc("%s: "                    \
                                fmt, __FILE__, ##__VA_ARGS__);  \
        } else if ((type) & VFS) {                              \
                pr_err_ ## ratefunc("CIFS VFS: "                \
                                 fmt, ##__VA_ARGS__);           \



On Sat, Oct 6, 2018 at 2:32 PM Rodrigo Freire <[e-mail]> wrote:
>
> Hi Steve! o/
>
> Appreciate your time and review.
>
> For a v3, what would you like more: a pr_info() straight away in the code
> for the message, or, writing a new cifs_info() function wrapping
> over pr_info, like we have in cifs_dbg (which translates to pr_debug or pr_err)?
>
> Waiting for your comments. Thanks!
>
> ---
> Rodrigo Freire - Principal Technical Account Manager
> GLOBAL CUSTOMER SUCCESS - Partnering with you to help achieve your business goals
> redhat.com | TRIED. TESTED. TRUSTED. | redhat.com/trusted
>
> ----- Original Message -----
>
> > From: "Steve French" <[e-mail]>
> > To: [e-mail]
> > Cc: "LKML" <[e-mail]>, "Steve French"
> > <[e-mail]>, "CIFS" <[e-mail]>, "Pavel Shilovsky"
> > <[e-mail]>
> > Sent: Saturday, October 6, 2018 4:09:30 PM
> > Subject: Re: [PATCH v2] CIFS: Print message when attempting a mount
>
> > On Tue, Oct 2, 2018 at 4:53 PM Rodrigo Freire <[e-mail]> wrote:
> > >
> > > Hi hi again Steve \o
> > >
> > > I do see potential for a ftrace rewrite for the cifs_dbg messages.
>
> > Was looking at this on current kernels and debugging mount is probably
> > fine for developers (or users) - plenty of debug messages get printed
> > via the dynamic ftrace points. In practice some would prefer less
> > noisy trace logs so the minimum set for some would be something like
> > this (which already works with current cifs). If we want to add some
> > default log messages on mount to dmesg instead of the trace-cmd log,
> > maybe we should log them at a slightly less noisy level (as we see
> > with xfs and btrfs) so they will be more log friendly

Patch

diff --git a/fs/cifs/cifsfs.c b/fs/cifs/cifsfs.c
index 7065426..7fde6bc 100644
--- a/fs/cifs/cifsfs.c
+++ b/fs/cifs/cifsfs.c
@@ -707,7 +707,11 @@  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 (cifsFYI)
+		cifs_dbg(FYI, "Devname: %s flags: %d\n", dev_name, flags);
+	else
+		cifs_dbg(VFS, "Attempting to mount %s\n", dev_name);
 
 	volume_info = cifs_get_volume_info((char *)data, dev_name, is_smb3);
 	if (IS_ERR(volume_info))