* [PATCH] gssd: cut down log chatter in gssd_search_krb5_keytab
@ 2013-11-07 15:47 Jeff Layton
2013-11-07 15:58 ` Christoph Hellwig
2013-11-07 16:47 ` Steve Dickson
0 siblings, 2 replies; 10+ messages in thread
From: Jeff Layton @ 2013-11-07 15:47 UTC (permalink / raw)
To: steved; +Cc: linux-nfs
Because the kernel now looks for krb5 creds by default when mounting, we
need to always have clients run rpc.gssd to avoid the 15s hang on the
first mount attempt.
In situations however where people don't have krb5 set up, this leads to
a lot of log spamming on mount attempts. Try to cut down on some of the
log chatter by lowering the priority of the log messages in
gssd_search_krb5_keytab().
Signed-off-by: Jeff Layton <jlayton@redhat.com>
---
utils/gssd/krb5_util.c | 8 ++++----
1 file changed, 4 insertions(+), 4 deletions(-)
diff --git a/utils/gssd/krb5_util.c b/utils/gssd/krb5_util.c
index 697d1d2..2ca3adc 100644
--- a/utils/gssd/krb5_util.c
+++ b/utils/gssd/krb5_util.c
@@ -711,13 +711,13 @@ gssd_search_krb5_keytab(krb5_context context, krb5_keytab kt,
*/
if ((code = krb5_kt_get_name(context, kt, kt_name, BUFSIZ))) {
k5err = gssd_k5_err_msg(context, code);
- printerr(0, "ERROR: %s attempting to get keytab name\n", k5err);
+ printerr(1, "ERROR: %s attempting to get keytab name\n", k5err);
retval = code;
goto out;
}
if ((code = krb5_kt_start_seq_get(context, kt, &cursor))) {
k5err = gssd_k5_err_msg(context, code);
- printerr(0, "ERROR: %s while beginning keytab scan "
+ printerr(1, "ERROR: %s while beginning keytab scan "
"for keytab '%s'\n", k5err, kt_name);
retval = code;
goto out;
@@ -727,7 +727,7 @@ gssd_search_krb5_keytab(krb5_context context, krb5_keytab kt,
if ((code = krb5_unparse_name(context, kte->principal,
&pname))) {
k5err = gssd_k5_err_msg(context, code);
- printerr(0, "WARNING: Skipping keytab entry because "
+ printerr(1, "WARNING: Skipping keytab entry because "
"we failed to unparse principal name: %s\n",
k5err);
k5_free_kt_entry(context, kte);
@@ -768,7 +768,7 @@ gssd_search_krb5_keytab(krb5_context context, krb5_keytab kt,
if ((code = krb5_kt_end_seq_get(context, kt, &cursor))) {
k5err = gssd_k5_err_msg(context, code);
- printerr(0, "WARNING: %s while ending keytab scan for "
+ printerr(1, "WARNING: %s while ending keytab scan for "
"keytab '%s'\n", k5err, kt_name);
}
--
1.8.3.1
^ permalink raw reply related [flat|nested] 10+ messages in thread
* Re: [PATCH] gssd: cut down log chatter in gssd_search_krb5_keytab
2013-11-07 15:47 [PATCH] gssd: cut down log chatter in gssd_search_krb5_keytab Jeff Layton
@ 2013-11-07 15:58 ` Christoph Hellwig
2013-11-07 16:09 ` Jeff Layton
2013-11-07 16:47 ` Steve Dickson
1 sibling, 1 reply; 10+ messages in thread
From: Christoph Hellwig @ 2013-11-07 15:58 UTC (permalink / raw)
To: Jeff Layton; +Cc: steved, linux-nfs
On Thu, Nov 07, 2013 at 10:47:33AM -0500, Jeff Layton wrote:
> Because the kernel now looks for krb5 creds by default when mounting, we
> need to always have clients run rpc.gssd to avoid the 15s hang on the
> first mount attempt.
Not sure if it's the same hangs, but I see about the same length of a
hang on my Debian wheezy systems when accessing the first file for a
data operation, with rpc.gssd running or not. Funnily enough this also
happens when trying to read a non-existand file, but not for things like
a simple readdir.
Still looking into it, but being a non-interruptible sleep it's fairly
annoying.
That being said Debian wheezy also only starts rpc.gssd from the init
scripts if it sees a krb option in /etc/fstab, which I don't have.
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH] gssd: cut down log chatter in gssd_search_krb5_keytab
2013-11-07 15:58 ` Christoph Hellwig
@ 2013-11-07 16:09 ` Jeff Layton
2013-11-07 16:21 ` Christoph Hellwig
0 siblings, 1 reply; 10+ messages in thread
From: Jeff Layton @ 2013-11-07 16:09 UTC (permalink / raw)
To: Christoph Hellwig; +Cc: steved, linux-nfs
On Thu, 7 Nov 2013 07:58:37 -0800
Christoph Hellwig <hch@infradead.org> wrote:
> On Thu, Nov 07, 2013 at 10:47:33AM -0500, Jeff Layton wrote:
> > Because the kernel now looks for krb5 creds by default when mounting, we
> > need to always have clients run rpc.gssd to avoid the 15s hang on the
> > first mount attempt.
>
> Not sure if it's the same hangs, but I see about the same length of a
> hang on my Debian wheezy systems when accessing the first file for a
> data operation, with rpc.gssd running or not. Funnily enough this also
> happens when trying to read a non-existand file, but not for things like
> a simple readdir.
>
> Still looking into it, but being a non-interruptible sleep it's fairly
> annoying.
>
> That being said Debian wheezy also only starts rpc.gssd from the init
> scripts if it sees a krb option in /etc/fstab, which I don't have.
>
It may be the same issue. IIRC, the attempt to use krb5i by default
is done in the SETCLIENTID call (see kernel commit 4edaa30888 for some
background, but there were some later tweaks to this approach).
--
Jeff Layton <jlayton@redhat.com>
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH] gssd: cut down log chatter in gssd_search_krb5_keytab
2013-11-07 16:09 ` Jeff Layton
@ 2013-11-07 16:21 ` Christoph Hellwig
2013-11-07 16:33 ` Jeff Layton
0 siblings, 1 reply; 10+ messages in thread
From: Christoph Hellwig @ 2013-11-07 16:21 UTC (permalink / raw)
To: Jeff Layton; +Cc: Christoph Hellwig, steved, linux-nfs
On Thu, Nov 07, 2013 at 11:09:28AM -0500, Jeff Layton wrote:
> It may be the same issue. IIRC, the attempt to use krb5i by default
> is done in the SETCLIENTID call (see kernel commit 4edaa30888 for some
> background, but there were some later tweaks to this approach).
I'm still seing my issue after reverting that commit by hand.
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH] gssd: cut down log chatter in gssd_search_krb5_keytab
2013-11-07 16:21 ` Christoph Hellwig
@ 2013-11-07 16:33 ` Jeff Layton
2013-11-07 16:35 ` Christoph Hellwig
0 siblings, 1 reply; 10+ messages in thread
From: Jeff Layton @ 2013-11-07 16:33 UTC (permalink / raw)
To: Christoph Hellwig; +Cc: steved, linux-nfs
On Thu, 7 Nov 2013 08:21:23 -0800
Christoph Hellwig <hch@infradead.org> wrote:
> On Thu, Nov 07, 2013 at 11:09:28AM -0500, Jeff Layton wrote:
> > It may be the same issue. IIRC, the attempt to use krb5i by default
> > is done in the SETCLIENTID call (see kernel commit 4edaa30888 for some
> > background, but there were some later tweaks to this approach).
>
> I'm still seing my issue after reverting that commit by hand.
Hrm...
You'd also see these messages in the log if it were the same problem:
RPC: AUTH_GSS upcall timed out.
...it could also be a delay when trying to set up the callback channel
if you're running v4.0. Do you have the callback port firewalled off?
--
Jeff Layton <jlayton@redhat.com>
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH] gssd: cut down log chatter in gssd_search_krb5_keytab
2013-11-07 16:33 ` Jeff Layton
@ 2013-11-07 16:35 ` Christoph Hellwig
2013-11-07 16:36 ` Jeff Layton
0 siblings, 1 reply; 10+ messages in thread
From: Christoph Hellwig @ 2013-11-07 16:35 UTC (permalink / raw)
To: Jeff Layton; +Cc: steved, linux-nfs
On Thu, Nov 07, 2013 at 11:33:10AM -0500, Jeff Layton wrote:
> > I'm still seing my issue after reverting that commit by hand.
>
> Hrm...
>
> You'd also see these messages in the log if it were the same problem:
>
> RPC: AUTH_GSS upcall timed out.
>
> ...it could also be a delay when trying to set up the callback channel
> if you're running v4.0. Do you have the callback port firewalled off?
Not seeing any of those, and running with 4.1 at the moment, although I
could try 4.0. Talking to a server on the same host, so firewalling is
unlikely.
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH] gssd: cut down log chatter in gssd_search_krb5_keytab
2013-11-07 16:35 ` Christoph Hellwig
@ 2013-11-07 16:36 ` Jeff Layton
2013-11-07 16:38 ` Christoph Hellwig
0 siblings, 1 reply; 10+ messages in thread
From: Jeff Layton @ 2013-11-07 16:36 UTC (permalink / raw)
To: Christoph Hellwig; +Cc: steved, linux-nfs
On Thu, 7 Nov 2013 08:35:20 -0800
Christoph Hellwig <hch@infradead.org> wrote:
> On Thu, Nov 07, 2013 at 11:33:10AM -0500, Jeff Layton wrote:
> > > I'm still seing my issue after reverting that commit by hand.
> >
> > Hrm...
> >
> > You'd also see these messages in the log if it were the same problem:
> >
> > RPC: AUTH_GSS upcall timed out.
> >
> > ...it could also be a delay when trying to set up the callback channel
> > if you're running v4.0. Do you have the callback port firewalled off?
>
> Not seeing any of those, and running with 4.1 at the moment, although I
> could try 4.0. Talking to a server on the same host, so firewalling is
> unlikely.
>
No idea then, sorry...
--
Jeff Layton <jlayton@redhat.com>
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH] gssd: cut down log chatter in gssd_search_krb5_keytab
2013-11-07 16:36 ` Jeff Layton
@ 2013-11-07 16:38 ` Christoph Hellwig
0 siblings, 0 replies; 10+ messages in thread
From: Christoph Hellwig @ 2013-11-07 16:38 UTC (permalink / raw)
To: Jeff Layton; +Cc: steved, linux-nfs
On Thu, Nov 07, 2013 at 11:36:56AM -0500, Jeff Layton wrote:
> No idea then, sorry...
4.0 is also affected, interestingly it's only reproducible on the first
mount of a volume after the server started, so I'll assume a server
issue. I'm trying to drill it down time permitting, but so far I have
no clue what's going on. Doesn't help that recent versions of
latencytop are unusable..
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH] gssd: cut down log chatter in gssd_search_krb5_keytab
2013-11-07 15:47 [PATCH] gssd: cut down log chatter in gssd_search_krb5_keytab Jeff Layton
2013-11-07 15:58 ` Christoph Hellwig
@ 2013-11-07 16:47 ` Steve Dickson
2013-11-07 16:56 ` Jeff Layton
1 sibling, 1 reply; 10+ messages in thread
From: Steve Dickson @ 2013-11-07 16:47 UTC (permalink / raw)
To: Jeff Layton; +Cc: linux-nfs
Hello,
My thoughts...
On 07/11/13 10:47, Jeff Layton wrote:
> Because the kernel now looks for krb5 creds by default when mounting, we
> need to always have clients run rpc.gssd to avoid the 15s hang on the
> first mount attempt.
>
> In situations however where people don't have krb5 set up, this leads to
> a lot of log spamming on mount attempts. Try to cut down on some of the
> log chatter by lowering the priority of the log messages in
> gssd_search_krb5_keytab().
>
> Signed-off-by: Jeff Layton <jlayton@redhat.com>
> ---
> utils/gssd/krb5_util.c | 8 ++++----
> 1 file changed, 4 insertions(+), 4 deletions(-)
>
> diff --git a/utils/gssd/krb5_util.c b/utils/gssd/krb5_util.c
> index 697d1d2..2ca3adc 100644
> --- a/utils/gssd/krb5_util.c
> +++ b/utils/gssd/krb5_util.c
> @@ -711,13 +711,13 @@ gssd_search_krb5_keytab(krb5_context context, krb5_keytab kt,
> */
> if ((code = krb5_kt_get_name(context, kt, kt_name, BUFSIZ))) {
> k5err = gssd_k5_err_msg(context, code);
> - printerr(0, "ERROR: %s attempting to get keytab name\n", k5err);
> + printerr(1, "ERROR: %s attempting to get keytab name\n", k5err);
> retval = code;
> goto out;
> }
> if ((code = krb5_kt_start_seq_get(context, kt, &cursor))) {
> k5err = gssd_k5_err_msg(context, code);
> - printerr(0, "ERROR: %s while beginning keytab scan "
> + printerr(1, "ERROR: %s while beginning keytab scan "
> "for keytab '%s'\n", k5err, kt_name);
> retval = code;
> goto out;
I'm thinking these need to stay... I don't think is a good idea
to mask out messages describing failures...
> @@ -727,7 +727,7 @@ gssd_search_krb5_keytab(krb5_context context, krb5_keytab kt,
> if ((code = krb5_unparse_name(context, kte->principal,
> &pname))) {
> k5err = gssd_k5_err_msg(context, code);
> - printerr(0, "WARNING: Skipping keytab entry because "
> + printerr(1, "WARNING: Skipping keytab entry because "
> "we failed to unparse principal name: %s\n",
> k5err);
> k5_free_kt_entry(context, kte);
> @@ -768,7 +768,7 @@ gssd_search_krb5_keytab(krb5_context context, krb5_keytab kt,
>
> if ((code = krb5_kt_end_seq_get(context, kt, &cursor))) {
> k5err = gssd_k5_err_msg(context, code);
> - printerr(0, "WARNING: %s while ending keytab scan for "
> + printerr(1, "WARNING: %s while ending keytab scan for "
> "keytab '%s'\n", k5err, kt_name);
> }
I think warnings would be ok to mask out...
steved.
>
>
^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: [PATCH] gssd: cut down log chatter in gssd_search_krb5_keytab
2013-11-07 16:47 ` Steve Dickson
@ 2013-11-07 16:56 ` Jeff Layton
0 siblings, 0 replies; 10+ messages in thread
From: Jeff Layton @ 2013-11-07 16:56 UTC (permalink / raw)
To: Steve Dickson; +Cc: linux-nfs
On Thu, 07 Nov 2013 11:47:55 -0500
Steve Dickson <SteveD@redhat.com> wrote:
> Hello,
>
> My thoughts...
>
> On 07/11/13 10:47, Jeff Layton wrote:
> > Because the kernel now looks for krb5 creds by default when mounting, we
> > need to always have clients run rpc.gssd to avoid the 15s hang on the
> > first mount attempt.
> >
> > In situations however where people don't have krb5 set up, this leads to
> > a lot of log spamming on mount attempts. Try to cut down on some of the
> > log chatter by lowering the priority of the log messages in
> > gssd_search_krb5_keytab().
> >
> > Signed-off-by: Jeff Layton <jlayton@redhat.com>
> > ---
> > utils/gssd/krb5_util.c | 8 ++++----
> > 1 file changed, 4 insertions(+), 4 deletions(-)
> >
> > diff --git a/utils/gssd/krb5_util.c b/utils/gssd/krb5_util.c
> > index 697d1d2..2ca3adc 100644
> > --- a/utils/gssd/krb5_util.c
> > +++ b/utils/gssd/krb5_util.c
> > @@ -711,13 +711,13 @@ gssd_search_krb5_keytab(krb5_context context, krb5_keytab kt,
> > */
> > if ((code = krb5_kt_get_name(context, kt, kt_name, BUFSIZ))) {
> > k5err = gssd_k5_err_msg(context, code);
> > - printerr(0, "ERROR: %s attempting to get keytab name\n", k5err);
> > + printerr(1, "ERROR: %s attempting to get keytab name\n", k5err);
> > retval = code;
> > goto out;
> > }
> > if ((code = krb5_kt_start_seq_get(context, kt, &cursor))) {
> > k5err = gssd_k5_err_msg(context, code);
> > - printerr(0, "ERROR: %s while beginning keytab scan "
> > + printerr(1, "ERROR: %s while beginning keytab scan "
> > "for keytab '%s'\n", k5err, kt_name);
> > retval = code;
> > goto out;
> I'm thinking these need to stay... I don't think is a good idea
> to mask out messages describing failures...
>
The above message is the one that's the problem when there is no
keytab. I just went ahead and lowered the priority on the others for
good measure. If you don't want to take the above hunk, then there's
probably no need to bother with this patch at all.
> > @@ -727,7 +727,7 @@ gssd_search_krb5_keytab(krb5_context context, krb5_keytab kt,
> > if ((code = krb5_unparse_name(context, kte->principal,
> > &pname))) {
> > k5err = gssd_k5_err_msg(context, code);
> > - printerr(0, "WARNING: Skipping keytab entry because "
> > + printerr(1, "WARNING: Skipping keytab entry because "
> > "we failed to unparse principal name: %s\n",
> > k5err);
> > k5_free_kt_entry(context, kte);
> > @@ -768,7 +768,7 @@ gssd_search_krb5_keytab(krb5_context context, krb5_keytab kt,
> >
> > if ((code = krb5_kt_end_seq_get(context, kt, &cursor))) {
> > k5err = gssd_k5_err_msg(context, code);
> > - printerr(0, "WARNING: %s while ending keytab scan for "
> > + printerr(1, "WARNING: %s while ending keytab scan for "
> > "keytab '%s'\n", k5err, kt_name);
> > }
> I think warnings would be ok to mask out...
>
> steved.
>
> >
> >
--
Jeff Layton <jlayton@redhat.com>
^ permalink raw reply [flat|nested] 10+ messages in thread
end of thread, other threads:[~2013-11-07 16:56 UTC | newest]
Thread overview: 10+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2013-11-07 15:47 [PATCH] gssd: cut down log chatter in gssd_search_krb5_keytab Jeff Layton
2013-11-07 15:58 ` Christoph Hellwig
2013-11-07 16:09 ` Jeff Layton
2013-11-07 16:21 ` Christoph Hellwig
2013-11-07 16:33 ` Jeff Layton
2013-11-07 16:35 ` Christoph Hellwig
2013-11-07 16:36 ` Jeff Layton
2013-11-07 16:38 ` Christoph Hellwig
2013-11-07 16:47 ` Steve Dickson
2013-11-07 16:56 ` Jeff Layton
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.