diff mbox series

[SMB3,client] minor updates to "stop flooding dmesg" patch

Message ID CAH2r5ms2jpBVtpYaE2hOgnfnjx73MnmPW2pQZnY-42ARYMf9ZQ@mail.gmail.com (mailing list archive)
State New, archived
Headers show
Series [SMB3,client] minor updates to "stop flooding dmesg" patch | expand

Commit Message

Steve French Oct. 8, 2024, 5:17 a.m. UTC
I was not as comfortable with taking out where the error is logged on
session setup, but the other parts of the two patches below were fine.
So have added them back into for-next after the one small change to "
smb: client: stop flooding dmesg on failed session setups"

commit e25f5175ef11a56bba4fbfc66832817d59e887c6 (HEAD -> for-next,
origin/for-next)
Author: Paulo Alcantara <pc@manguebit.com>
Date:   Wed Sep 18 02:04:18 2024 -0300

    smb: client: stop flooding dmesg with automounts

    Avoid logging info and expected errors when automounting DFS links and
    reparse mount points as a share might contain hundreds of them and the
    client would end up flooding dmesg.

    Signed-off-by: Paulo Alcantara (Red Hat) <pc@manguebit.com>
    Signed-off-by: Steve French <stfrench@microsoft.com>

commit 2f34f5e966f7d99418b42b8c67cffbbbde94704b
Author: Paulo Alcantara <pc@manguebit.com>
Date:   Wed Sep 18 02:04:12 2024 -0300

    smb: client: stop flooding dmesg on failed session setups

    Stop flooding dmesg over failed session setups as kerberos tickets
    getting expired or passwords being rotated is a very common scenario.

    Signed-off-by: Paulo Alcantara (Red Hat) <pc@manguebit.com>
    Signed-off-by: Steve French <stfrench@microsoft.com>

Comments

Paulo Alcantara Oct. 8, 2024, 6:35 p.m. UTC | #1
Steve French <smfrench@gmail.com> writes:

> I was not as comfortable with taking out where the error is logged on
> session setup, but the other parts of the two patches below were fine.
> So have added them back into for-next after the one small change to "
> smb: client: stop flooding dmesg on failed session setups"

NAK.  These changes just invalidated the patch entirely.  Either remove
it or make the "Send error in SessSetup" error messages being printed
out only once.

The client can still flood dmesg with "\\<hostname> Send error in
SessSetup = ..." messages over failed session setups with this patch.

Just try it yourself:

  kinit ...
  for i in `seq 300`; do mount.cifs //srv/share /mnt -o sec=krb5,echo_interval=5,nosharesock,nohandlecache; done
  # disconnect srv
  sleep 30
  kdestroy -A
  # reconnect srv
  journalctl -k -f
  ...
  CIFS: VFS: \\srv has not responded in 15 seconds. Reconnecting...
  CIFS: VFS: \\srv has not responded in 15 seconds. Reconnecting...
  CIFS: VFS: \\srv has not responded in 15 seconds. Reconnecting...
  CIFS: VFS: \\srv has not responded in 15 seconds. Reconnecting...
  CIFS: VFS: \\srv has not responded in 15 seconds. Reconnecting...
  CIFS: VFS: \\srv has not responded in 15 seconds. Reconnecting...
  CIFS: VFS: \\srv has not responded in 15 seconds. Reconnecting...
  CIFS: VFS: \\srv has not responded in 15 seconds. Reconnecting...
  CIFS: VFS: \\srv has not responded in 15 seconds. Reconnecting...
  CIFS: VFS: \\srv has not responded in 15 seconds. Reconnecting...
  cifs_setup_session: 23 callbacks suppressed
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  cifs_setup_session: 1618 callbacks suppressed
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  cifs_setup_session: 1786 callbacks suppressed
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  cifs_setup_session: 1728 callbacks suppressed
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  CIFS: VFS: \\srv Send error in SessSetup = -126
  ...
Paulo Alcantara Oct. 8, 2024, 8:15 p.m. UTC | #2
Steve French <smfrench@gmail.com> writes:

> We still will need to have a way to log these messages at least every few
> minutes if error in session setup. That is Clifton critical information for
> user to know

Agreed.  I just think that "\\<srv> Send error in SessSetup = ..."
doesn't really mean anything to the user.  Further I/Os from the user
will fail with -ENOKEY, which also doesn't tell much.

Without this message we at least have

        VFS: \\srv has not responded in N seconds. Reconnecting...

which tells the user that connection was lost.  And, in case server
dropped the session (e.g. STATUS_USER_SESSION_DELETED), we'll also have
the above message printed out as we currently mark tcp ses for
reconnect.

We still need to handle these excessive upcalls as in my example we have
several kworkers attempting to reconnect a SMB session (on every 2s) and
then repeatedly failing due to expired key.  This could be done in a
different patch, though.
Paulo Alcantara Oct. 8, 2024, 8:25 p.m. UTC | #3
Paulo Alcantara <pc@manguebit.com> writes:

> Without this message we at least have
>
>         VFS: \\srv has not responded in N seconds. Reconnecting...
>
> which tells the user that connection was lost.  And, in case server
> dropped the session (e.g. STATUS_USER_SESSION_DELETED), we'll also have
> the above message printed out as we currently mark tcp ses for
> reconnect.

Err, no.  I forgot that we only print this in server_unresponsive().  We
call cifs_reconnect() when the session is dropped and don't print
anything.
Steve French Oct. 9, 2024, 5:15 a.m. UTC | #4
my goal was to at least get the non-controversial debug message
spamming improvements in, even if figuring out the rest of them (to
make sure we are logging important session setup failures enough for
users to see the error at least once) will take more work to improve.

On Tue, Oct 8, 2024 at 3:25 PM Paulo Alcantara <pc@manguebit.com> wrote:
>
> Paulo Alcantara <pc@manguebit.com> writes:
>
> > Without this message we at least have
> >
> >         VFS: \\srv has not responded in N seconds. Reconnecting...
> >
> > which tells the user that connection was lost.  And, in case server
> > dropped the session (e.g. STATUS_USER_SESSION_DELETED), we'll also have
> > the above message printed out as we currently mark tcp ses for
> > reconnect.
>
> Err, no.  I forgot that we only print this in server_unresponsive().  We
> call cifs_reconnect() when the session is dropped and don't print
> anything.
diff mbox series

Patch

From 2f34f5e966f7d99418b42b8c67cffbbbde94704b Mon Sep 17 00:00:00 2001
From: Paulo Alcantara <pc@manguebit.com>
Date: Wed, 18 Sep 2024 02:04:12 -0300
Subject: [PATCH 1/2] smb: client: stop flooding dmesg on failed session setups

Stop flooding dmesg over failed session setups as kerberos tickets
getting expired or passwords being rotated is a very common scenario.

Signed-off-by: Paulo Alcantara (Red Hat) <pc@manguebit.com>
Signed-off-by: Steve French <stfrench@microsoft.com>
---
 fs/smb/client/connect.c | 2 ++
 fs/smb/client/smb2pdu.c | 4 ++--
 2 files changed, 4 insertions(+), 2 deletions(-)

diff --git a/fs/smb/client/connect.c b/fs/smb/client/connect.c
index 15d94ac4095e..48e87f3a7b24 100644
--- a/fs/smb/client/connect.c
+++ b/fs/smb/client/connect.c
@@ -3374,6 +3374,8 @@  int cifs_mount_get_session(struct cifs_mount_ctx *mnt_ctx)
 	ses = cifs_get_smb_ses(server, ctx);
 	if (IS_ERR(ses)) {
 		rc = PTR_ERR(ses);
+		if (rc == -ENOKEY && ctx->sectype == Kerberos)
+			cifs_dbg(VFS, "Verify user has a krb5 ticket and keyutils is installed\n");
 		ses = NULL;
 		goto out;
 	}
diff --git a/fs/smb/client/smb2pdu.c b/fs/smb/client/smb2pdu.c
index b2f16a7b696d..6f7f9a1f0a1f 100644
--- a/fs/smb/client/smb2pdu.c
+++ b/fs/smb/client/smb2pdu.c
@@ -1636,8 +1636,8 @@  SMB2_auth_kerberos(struct SMB2_sess_data *sess_data)
 	spnego_key = cifs_get_spnego_key(ses, server);
 	if (IS_ERR(spnego_key)) {
 		rc = PTR_ERR(spnego_key);
-		if (rc == -ENOKEY)
-			cifs_dbg(VFS, "Verify user has a krb5 ticket and keyutils is installed\n");
+		cifs_dbg(FYI, "%s: couldn't auth with kerberos: %d\n",
+			 __func__, rc);
 		spnego_key = NULL;
 		goto out;
 	}
-- 
2.43.0