smb3: minor debugging clarifications in rfc1001 len processing

I ran into some cases where the server was returning the wrong length
on frames but I couldn't easily match them to the command in the
network trace (or server logs) since I need the command and/or
multiplex id to find the offending SMB2/SMB3 command.  Add these
two fields to the log message.

Signed-off-by: Steve French <stfrench@microsoft.com>
---
 fs/cifs/smb2misc.c | 7 +++++--
 fs/cifs/smb2ops.c  | 4 ++++
 3 files changed, 10 insertions(+), 2 deletions(-)

     }

Reviewed-by: Ronnie Sahlberg <lsahlber@redhat.com>

On Wed, Aug 29, 2018 at 7:53 AM, Steve French <smfrench@gmail.com> wrote:
> I ran into some cases where the server was returning the wrong length
> on frames but I couldn't easily match them to the command in the
> network trace (or server logs) since I need the command and/or
> multiplex id to find the offending SMB2/SMB3 command.  Add these
> two fields to the log message.
>
> Signed-off-by: Steve French <stfrench@microsoft.com>
> ---
>  fs/cifs/smb2misc.c | 7 +++++--
>  fs/cifs/smb2ops.c  | 4 ++++
>  3 files changed, 10 insertions(+), 2 deletions(-)
>
> diff --git a/fs/cifs/smb2misc.c b/fs/cifs/smb2misc.c
> index db0453660ff6..9171720dc658 100644
> --- a/fs/cifs/smb2misc.c
> +++ b/fs/cifs/smb2misc.c
> @@ -254,10 +254,13 @@ smb2_check_message(char *buf, unsigned int len,
> struct TCP_Server_Info *srvr)
>           */
>          if (clc_len < len) {
>              printk_once(KERN_WARNING
> -                "SMB2 server sent bad RFC1001 len %d not %d\n",
> -                len, clc_len);
> +                 "srv rsp too long %d not %d for cmd:%d mid:%llu\n",
> +                 len, clc_len, command, mid);
>              return 0;
>          }
> +        printk_once(KERN_WARNING
> +            "srv rsp too short, len %d not %d. cmd:%d mid:%llu\n",
> +            len, clc_len, command, mid);
>
>          return 1;
>      }
>
>
> --
> Thanks,
>
> Steve

> -----Original Message-----
> From: linux-cifs-owner@vger.kernel.org <linux-cifs-owner@vger.kernel.org> On
> Behalf Of ronnie sahlberg
> Sent: Tuesday, August 28, 2018 5:56 PM
> To: Steve French <smfrench@gmail.com>
> Cc: CIFS <linux-cifs@vger.kernel.org>
> Subject: Re: [PATCH] smb3: minor debugging clarifications in rfc1001 len
> processing
> 
> Reviewed-by: Ronnie Sahlberg <lsahlber@redhat.com>
> 
> On Wed, Aug 29, 2018 at 7:53 AM, Steve French <smfrench@gmail.com>
> wrote:
> > I ran into some cases where the server was returning the wrong length
> > on frames but I couldn't easily match them to the command in the
> > network trace (or server logs) since I need the command and/or
> > multiplex id to find the offending SMB2/SMB3 command.  Add these
> > two fields to the log message.
> >
> > Signed-off-by: Steve French <stfrench@microsoft.com>
> > ---
> >  fs/cifs/smb2misc.c | 7 +++++--
> >  fs/cifs/smb2ops.c  | 4 ++++
> >  3 files changed, 10 insertions(+), 2 deletions(-)
> >
> > diff --git a/fs/cifs/smb2misc.c b/fs/cifs/smb2misc.c
> > index db0453660ff6..9171720dc658 100644
> > --- a/fs/cifs/smb2misc.c
> > +++ b/fs/cifs/smb2misc.c
> > @@ -254,10 +254,13 @@ smb2_check_message(char *buf, unsigned int len,
> > struct TCP_Server_Info *srvr)
> >           */
> >          if (clc_len < len) {
> >              printk_once(KERN_WARNING
> > -                "SMB2 server sent bad RFC1001 len %d not %d\n",
> > -                len, clc_len);
> > +                 "srv rsp too long %d not %d for cmd:%d mid:%llu\n",
> > +                 len, clc_len, command, mid);

Why is this a KERN_WARNING? It's not fatal, and not illegal.
Seems to me it's a KERN_INFO.

I'd suggest rather than "too long", a more informational wording
such as "longer than expected" or similar.

Tom.

> >              return 0;
> >          }
> > +        printk_once(KERN_WARNING
> > +            "srv rsp too short, len %d not %d. cmd:%d mid:%llu\n",
> > +            len, clc_len, command, mid);
> >
> >          return 1;
> >      }
> >
> >
> > --
> > Thanks,
> >
> > Steve

OK - updated the wording in the warning message (and the comments around it).

If we make it lower than KERN_WARNING it won't be logged by default, and I am
suspicious that we have seen this happen before a network disconnect by the
server so want to at least see it logged once by default in case it turns out to
be related.

I have seen few cases where normal use logs it - so with your suggested
wording change I doubt it will cause confusion.
On Wed, Aug 29, 2018 at 8:15 AM Tom Talpey <ttalpey@microsoft.com> wrote:
>
> > -----Original Message-----
> > From: linux-cifs-owner@vger.kernel.org <linux-cifs-owner@vger.kernel.org> On
> > Behalf Of ronnie sahlberg
> > Sent: Tuesday, August 28, 2018 5:56 PM
> > To: Steve French <smfrench@gmail.com>
> > Cc: CIFS <linux-cifs@vger.kernel.org>
> > Subject: Re: [PATCH] smb3: minor debugging clarifications in rfc1001 len
> > processing
> >
> > Reviewed-by: Ronnie Sahlberg <lsahlber@redhat.com>
> >
> > On Wed, Aug 29, 2018 at 7:53 AM, Steve French <smfrench@gmail.com>
> > wrote:
> > > I ran into some cases where the server was returning the wrong length
> > > on frames but I couldn't easily match them to the command in the
> > > network trace (or server logs) since I need the command and/or
> > > multiplex id to find the offending SMB2/SMB3 command.  Add these
> > > two fields to the log message.
> > >
> > > Signed-off-by: Steve French <stfrench@microsoft.com>
> > > ---
> > >  fs/cifs/smb2misc.c | 7 +++++--
> > >  fs/cifs/smb2ops.c  | 4 ++++
> > >  3 files changed, 10 insertions(+), 2 deletions(-)
> > >
> > > diff --git a/fs/cifs/smb2misc.c b/fs/cifs/smb2misc.c
> > > index db0453660ff6..9171720dc658 100644
> > > --- a/fs/cifs/smb2misc.c
> > > +++ b/fs/cifs/smb2misc.c
> > > @@ -254,10 +254,13 @@ smb2_check_message(char *buf, unsigned int len,
> > > struct TCP_Server_Info *srvr)
> > >           */
> > >          if (clc_len < len) {
> > >              printk_once(KERN_WARNING
> > > -                "SMB2 server sent bad RFC1001 len %d not %d\n",
> > > -                len, clc_len);
> > > +                 "srv rsp too long %d not %d for cmd:%d mid:%llu\n",
> > > +                 len, clc_len, command, mid);
>
> Why is this a KERN_WARNING? It's not fatal, and not illegal.
> Seems to me it's a KERN_INFO.
>
> I'd suggest rather than "too long", a more informational wording
> such as "longer than expected" or similar.
>
> Tom.
>
> > >              return 0;
> > >          }
> > > +        printk_once(KERN_WARNING
> > > +            "srv rsp too short, len %d not %d. cmd:%d mid:%llu\n",
> > > +            len, clc_len, command, mid);
> > >
> > >          return 1;
> > >      }
> > >
> > >
> > > --
> > > Thanks,
> > >
> > > Steve

KERN_WARNING is defined as: "A warning, meaning nothing serious by
itself but might indicate problems" so probably fine
On Wed, Aug 29, 2018 at 9:30 AM Steve French <smfrench@gmail.com> wrote:
>
> OK - updated the wording in the warning message (and the comments around it).
>
> If we make it lower than KERN_WARNING it won't be logged by default, and I am
> suspicious that we have seen this happen before a network disconnect by the
> server so want to at least see it logged once by default in case it turns out to
> be related.
>
> I have seen few cases where normal use logs it - so with your suggested
> wording change I doubt it will cause confusion.
> On Wed, Aug 29, 2018 at 8:15 AM Tom Talpey <ttalpey@microsoft.com> wrote:
> >
> > > -----Original Message-----
> > > From: linux-cifs-owner@vger.kernel.org <linux-cifs-owner@vger.kernel.org> On
> > > Behalf Of ronnie sahlberg
> > > Sent: Tuesday, August 28, 2018 5:56 PM
> > > To: Steve French <smfrench@gmail.com>
> > > Cc: CIFS <linux-cifs@vger.kernel.org>
> > > Subject: Re: [PATCH] smb3: minor debugging clarifications in rfc1001 len
> > > processing
> > >
> > > Reviewed-by: Ronnie Sahlberg <lsahlber@redhat.com>
> > >
> > > On Wed, Aug 29, 2018 at 7:53 AM, Steve French <smfrench@gmail.com>
> > > wrote:
> > > > I ran into some cases where the server was returning the wrong length
> > > > on frames but I couldn't easily match them to the command in the
> > > > network trace (or server logs) since I need the command and/or
> > > > multiplex id to find the offending SMB2/SMB3 command.  Add these
> > > > two fields to the log message.
> > > >
> > > > Signed-off-by: Steve French <stfrench@microsoft.com>
> > > > ---
> > > >  fs/cifs/smb2misc.c | 7 +++++--
> > > >  fs/cifs/smb2ops.c  | 4 ++++
> > > >  3 files changed, 10 insertions(+), 2 deletions(-)
> > > >
> > > > diff --git a/fs/cifs/smb2misc.c b/fs/cifs/smb2misc.c
> > > > index db0453660ff6..9171720dc658 100644
> > > > --- a/fs/cifs/smb2misc.c
> > > > +++ b/fs/cifs/smb2misc.c
> > > > @@ -254,10 +254,13 @@ smb2_check_message(char *buf, unsigned int len,
> > > > struct TCP_Server_Info *srvr)
> > > >           */
> > > >          if (clc_len < len) {
> > > >              printk_once(KERN_WARNING
> > > > -                "SMB2 server sent bad RFC1001 len %d not %d\n",
> > > > -                len, clc_len);
> > > > +                 "srv rsp too long %d not %d for cmd:%d mid:%llu\n",
> > > > +                 len, clc_len, command, mid);
> >
> > Why is this a KERN_WARNING? It's not fatal, and not illegal.
> > Seems to me it's a KERN_INFO.
> >
> > I'd suggest rather than "too long", a more informational wording
> > such as "longer than expected" or similar.
> >
> > Tom.
> >
> > > >              return 0;
> > > >          }
> > > > +        printk_once(KERN_WARNING
> > > > +            "srv rsp too short, len %d not %d. cmd:%d mid:%llu\n",
> > > > +            len, clc_len, command, mid);
> > > >
> > > >          return 1;
> > > >      }
> > > >
> > > >
> > > > --
> > > > Thanks,
> > > >
> > > > Steve
>
>
>
> --
> Thanks,
>
> Steve

> -----Original Message-----
> From: Steve French <smfrench@gmail.com>
> Sent: Wednesday, August 29, 2018 10:32 AM
> To: Tom Talpey <ttalpey@microsoft.com>
> Cc: ronnie sahlberg <ronniesahlberg@gmail.com>; CIFS <linux-
> cifs@vger.kernel.org>
> Subject: Re: [PATCH] smb3: minor debugging clarifications in rfc1001 len
> processing
> 
> KERN_WARNING is defined as: "A warning, meaning nothing serious by
> itself but might indicate problems" so probably fine

Ok, sounds good. Ideally, it never kicks out.

Tom.


> On Wed, Aug 29, 2018 at 9:30 AM Steve French <smfrench@gmail.com>
> wrote:
> >
> > OK - updated the wording in the warning message (and the comments around
> it).
> >
> > If we make it lower than KERN_WARNING it won't be logged by default, and I
> am
> > suspicious that we have seen this happen before a network disconnect by the
> > server so want to at least see it logged once by default in case it turns out to
> > be related.
> >
> > I have seen few cases where normal use logs it - so with your suggested
> > wording change I doubt it will cause confusion.
> > On Wed, Aug 29, 2018 at 8:15 AM Tom Talpey <ttalpey@microsoft.com>
> wrote:
> > >
> > > > -----Original Message-----
> > > > From: linux-cifs-owner@vger.kernel.org <linux-cifs-
> owner@vger.kernel.org> On
> > > > Behalf Of ronnie sahlberg
> > > > Sent: Tuesday, August 28, 2018 5:56 PM
> > > > To: Steve French <smfrench@gmail.com>
> > > > Cc: CIFS <linux-cifs@vger.kernel.org>
> > > > Subject: Re: [PATCH] smb3: minor debugging clarifications in rfc1001 len
> > > > processing
> > > >
> > > > Reviewed-by: Ronnie Sahlberg <lsahlber@redhat.com>
> > > >
> > > > On Wed, Aug 29, 2018 at 7:53 AM, Steve French <smfrench@gmail.com>
> > > > wrote:
> > > > > I ran into some cases where the server was returning the wrong length
> > > > > on frames but I couldn't easily match them to the command in the
> > > > > network trace (or server logs) since I need the command and/or
> > > > > multiplex id to find the offending SMB2/SMB3 command.  Add these
> > > > > two fields to the log message.
> > > > >
> > > > > Signed-off-by: Steve French <stfrench@microsoft.com>
> > > > > ---
> > > > >  fs/cifs/smb2misc.c | 7 +++++--
> > > > >  fs/cifs/smb2ops.c  | 4 ++++
> > > > >  3 files changed, 10 insertions(+), 2 deletions(-)
> > > > >
> > > > > diff --git a/fs/cifs/smb2misc.c b/fs/cifs/smb2misc.c
> > > > > index db0453660ff6..9171720dc658 100644
> > > > > --- a/fs/cifs/smb2misc.c
> > > > > +++ b/fs/cifs/smb2misc.c
> > > > > @@ -254,10 +254,13 @@ smb2_check_message(char *buf, unsigned
> int len,
> > > > > struct TCP_Server_Info *srvr)
> > > > >           */
> > > > >          if (clc_len < len) {
> > > > >              printk_once(KERN_WARNING
> > > > > -                "SMB2 server sent bad RFC1001 len %d not %d\n",
> > > > > -                len, clc_len);
> > > > > +                 "srv rsp too long %d not %d for cmd:%d mid:%llu\n",
> > > > > +                 len, clc_len, command, mid);
> > >
> > > Why is this a KERN_WARNING? It's not fatal, and not illegal.
> > > Seems to me it's a KERN_INFO.
> > >
> > > I'd suggest rather than "too long", a more informational wording
> > > such as "longer than expected" or similar.
> > >
> > > Tom.
> > >
> > > > >              return 0;
> > > > >          }
> > > > > +        printk_once(KERN_WARNING
> > > > > +            "srv rsp too short, len %d not %d. cmd:%d mid:%llu\n",
> > > > > +            len, clc_len, command, mid);
> > > > >
> > > > >          return 1;
> > > > >      }
> > > > >
> > > > >
> > > > > --
> > > > > Thanks,
> > > > >
> > > > > Steve
> >
> >
> >
> > --
> > Thanks,
> >
> > Steve
> 
> 
> 
> --
> Thanks,
> 
> Steve