possible module refcount leak with auth_gss

possible module refcount leak with auth_gss

[Jeff Layton]

We had someone report a bug against Fedora that they were seeing very
high module reference counts for some krb5 related modules on his nfs
server. For instance:

# lsmod
Module                  Size  Used by
des_generic            25216  52736 
cbc                    12160  52736 
rpcsec_gss_krb5        15632  26370 

...the cbc and des_generic each have roughly 2 module references per
rpcsec_gss_krb5 refcount so I'm assuming that the "lynchpin" here is
the rpcsec_gss_krb5 refcount which seems to be increasing w/o bound.

I've been able to reproduce this fairly easily by setting up a nfs
server with a krb5 authenticated export. If I then mount that and
immediately unmount it from a client, the refcount on rpcsec_gss_krb5 on
the server increases by 1. For instance:

First mount and unmount:
Module                  Size  Used by
cbc                    12288  2 
rpcsec_gss_krb5        19208  1 
des_generic            25344  2 

Second mount and unmount:
Module                  Size  Used by
cbc                    12288  4 
rpcsec_gss_krb5        19208  2 
des_generic            25344  4 

Third mount and unmount:
Module                  Size  Used by
cbc                    12288  6 
rpcsec_gss_krb5        19208  3 
des_generic            25344  6 

...while that's an easy way to reproduce it, there may be other ways to
make it grow.

Some printk debugging shows that the references are increased as a
result of rsc_parse(). From my (rather naive) look at this code, it
looks like each entry in the rsc_cache holds a module reference.

I'm guessing that when these cache entries are released that the module
references also get released, but I haven't been successful in making
that occur. It seems like the module references are never put, so either
the entries are never getting flushed out of the cache or the module
references aren't being properly released by this code. There's no
"content" file for this cache though, so it's hard to tell whether the
cache is populated at any given time.

Either way, this seems likely to be a bug. There doesn't seem to be a
way to make the refcounts go down again once they've been increased. Can
anyone confirm whether this is working as intended? If not, do you have
any idea where the problem may be, or how to approach tracking this
down? Unfortunately, I'm finding this code to be very hard to follow.

Any help or suggestions appreciated...

Thanks,
-- 
Jeff Layton <jlayton@redhat.com>

Re: possible module refcount leak with auth_gss

[J. Bruce Fields]

On Mon, Dec 08, 2008 at 10:28:55AM -0500, Jeff Layton wrote:
> We had someone report a bug against Fedora that they were seeing very
> high module reference counts for some krb5 related modules on his nfs
> server. For instance:
> 
> # lsmod
> Module                  Size  Used by
> des_generic            25216  52736 
> cbc                    12160  52736 
> rpcsec_gss_krb5        15632  26370 
> 
> ...the cbc and des_generic each have roughly 2 module references per
> rpcsec_gss_krb5 refcount so I'm assuming that the "lynchpin" here is
> the rpcsec_gss_krb5 refcount which seems to be increasing w/o bound.

You may want to see this discussion:

	http://marc.info/?t=122819524700001&r=1&w=2

And these patches:

	http://marc.info/?l=linux-nfs&m=122843371318602&w=2

In addition to increasing the timeouts on those cache entries, perhaps
we could flush the contexts on rmmod?  Or change the reference counting
somehow--e.g., take a reference only in the presence of export cache
entries that mention krb5, and destroy contexts when the last such goes
away?

Also to check: a recent client should be sending destroy_ctx calls on
unmount, and a recent server should be acting on them.  Perhaps there's
a bug there.  I'd do an unmount, watch the wire to make sure the
destroy_ctx calls are really going across (they'll look like NFSv4 NULL
calls, with the interesting fields in the cred in the rpc header).  Then
take a close look at the destroy_ctx code (see the second occurence of
RPC_GSS_PROC_DESTROY in svcauth_gss_accept(), around line 1126).

--b.

> 
> I've been able to reproduce this fairly easily by setting up a nfs
> server with a krb5 authenticated export. If I then mount that and
> immediately unmount it from a client, the refcount on rpcsec_gss_krb5 on
> the server increases by 1. For instance:
> 
> First mount and unmount:
> Module                  Size  Used by
> cbc                    12288  2 
> rpcsec_gss_krb5        19208  1 
> des_generic            25344  2 
> 
> Second mount and unmount:
> Module                  Size  Used by
> cbc                    12288  4 
> rpcsec_gss_krb5        19208  2 
> des_generic            25344  4 
> 
> Third mount and unmount:
> Module                  Size  Used by
> cbc                    12288  6 
> rpcsec_gss_krb5        19208  3 
> des_generic            25344  6 
> 
> ...while that's an easy way to reproduce it, there may be other ways to
> make it grow.
> 
> Some printk debugging shows that the references are increased as a
> result of rsc_parse(). From my (rather naive) look at this code, it
> looks like each entry in the rsc_cache holds a module reference.
> 
> I'm guessing that when these cache entries are released that the module
> references also get released, but I haven't been successful in making
> that occur. It seems like the module references are never put, so either
> the entries are never getting flushed out of the cache or the module
> references aren't being properly released by this code. There's no
> "content" file for this cache though, so it's hard to tell whether the
> cache is populated at any given time.
> 
> Either way, this seems likely to be a bug. There doesn't seem to be a
> way to make the refcounts go down again once they've been increased. Can
> anyone confirm whether this is working as intended? If not, do you have
> any idea where the problem may be, or how to approach tracking this
> down? Unfortunately, I'm finding this code to be very hard to follow.
> 
> Any help or suggestions appreciated...
> 
> Thanks,
> -- 
> Jeff Layton <jlayton@redhat.com>
> _______________________________________________
> NFSv4 mailing list
> NFSv4@linux-nfs.org
> http://linux-nfs.org/cgi-bin/mailman/listinfo/nfsv4

Re: possible module refcount leak with auth_gss

[Jeff Layton]

On Mon, 8 Dec 2008 12:37:06 -0500
"J. Bruce Fields" <bfields@fieldses.org> wrote:

> On Mon, Dec 08, 2008 at 10:28:55AM -0500, Jeff Layton wrote:
> > We had someone report a bug against Fedora that they were seeing very
> > high module reference counts for some krb5 related modules on his nfs
> > server. For instance:
> > 
> > # lsmod
> > Module                  Size  Used by
> > des_generic            25216  52736 
> > cbc                    12160  52736 
> > rpcsec_gss_krb5        15632  26370 
> > 
> > ...the cbc and des_generic each have roughly 2 module references per
> > rpcsec_gss_krb5 refcount so I'm assuming that the "lynchpin" here is
> > the rpcsec_gss_krb5 refcount which seems to be increasing w/o bound.
> 
> You may want to see this discussion:
> 
> 	http://marc.info/?t=122819524700001&r=1&w=2
> 
> And these patches:
> 
> 	http://marc.info/?l=linux-nfs&m=122843371318602&w=2
> 

Doh! I saw that discussion and didn't make the connection. Thanks for
pointing that out.

> In addition to increasing the timeouts on those cache entries, perhaps
> we could flush the contexts on rmmod?  Or change the reference counting
> somehow--e.g., take a reference only in the presence of export cache
> entries that mention krb5, and destroy contexts when the last such goes
> away?
> 

That sounds like a better scheme than what we have currently. As it stands
now, you can't just unplug the module -- you have to wait for the entries
in the cache to time out.

FWIW, I tested out Kevin's patches and it still didn't seem to help. The
refcounts never seemed to go down (even after several hours). How long
should the context live in the cache with those patches? Until the krb5
ticket expires? I'll leave the box in this state until around this time
tomorrow to be sure (that's when the ticket expires).

> Also to check: a recent client should be sending destroy_ctx calls on
> unmount, and a recent server should be acting on them.  Perhaps there's
> a bug there.  I'd do an unmount, watch the wire to make sure the
> destroy_ctx calls are really going across (they'll look like NFSv4 NULL
> calls, with the interesting fields in the cred in the rpc header).  Then
> take a close look at the destroy_ctx code (see the second occurence of
> RPC_GSS_PROC_DESTROY in svcauth_gss_accept(), around line 1126).
> 

I didn't have 2 hosts with recent kernels, so I tested this on a
machine with a recent kernel mounting itself. The kernel was:

2.6.28-0.121.rc7.git5.fc11.x86_64

(relatively recent pull from Linus tree AFAIK)

On host foo.bar.baz:

# mount -t nfs4 -o sec=krb5 foo.bar.baz:/ /mnt/test
# umount /mnt/test

The refcount on the module went up by 1 after this. I also did a
capture on port 2049. During the unmount, I didn't see any RPC activity
between client and server. The only thing I see is the socket being
closed:

 36   1.584397 10.11.231.229 -> 10.11.231.229 TCP 1016 > nfs [FIN, ACK] Seq=1377 Ack=1389 Win=40320 Len=0 TSV=1648278 TSER=1646778
 37   1.584551 10.11.231.229 -> 10.11.231.229 TCP nfs > 1016 [FIN, ACK] Seq=1389 Ack=1378 Win=41344 Len=0 TSV=1648278 TSER=1648278
 38   1.584614 10.11.231.229 -> 10.11.231.229 TCP 1016 > nfs [ACK] Seq=1378 Ack=1390 Win=40320 Len=0 TSV=1648278 TSER=1648278

It looks like the destroy_ctx isn't working AFAICT. I haven't started
digging into the code yet to figure out why however.

Thanks for the info so far.

Cheers,
-- 
Jeff Layton <jlayton@redhat.com>

Re: possible module refcount leak with auth_gss

[Kevin Coffman]

On Tue, Dec 9, 2008 at 3:38 PM, Jeff Layton <jlayton@redhat.com> wrote:
> On Mon, 8 Dec 2008 12:37:06 -0500
> "J. Bruce Fields" <bfields@fieldses.org> wrote:
>
>> On Mon, Dec 08, 2008 at 10:28:55AM -0500, Jeff Layton wrote:
>> > We had someone report a bug against Fedora that they were seeing very
>> > high module reference counts for some krb5 related modules on his nfs
>> > server. For instance:
>> >
>> > # lsmod
>> > Module                  Size  Used by
>> > des_generic            25216  52736
>> > cbc                    12160  52736
>> > rpcsec_gss_krb5        15632  26370
>> >
>> > ...the cbc and des_generic each have roughly 2 module references per
>> > rpcsec_gss_krb5 refcount so I'm assuming that the "lynchpin" here is
>> > the rpcsec_gss_krb5 refcount which seems to be increasing w/o bound.
>>
>> You may want to see this discussion:
>>
>>       http://marc.info/?t=122819524700001&r=1&w=2
>>
>> And these patches:
>>
>>       http://marc.info/?l=linux-nfs&m=122843371318602&w=2
>>
>
> Doh! I saw that discussion and didn't make the connection. Thanks for
> pointing that out.
>
>> In addition to increasing the timeouts on those cache entries, perhaps
>> we could flush the contexts on rmmod?  Or change the reference counting
>> somehow--e.g., take a reference only in the presence of export cache
>> entries that mention krb5, and destroy contexts when the last such goes
>> away?
>>
>
> That sounds like a better scheme than what we have currently. As it stands
> now, you can't just unplug the module -- you have to wait for the entries
> in the cache to time out.
>
> FWIW, I tested out Kevin's patches and it still didn't seem to help. The
> refcounts never seemed to go down (even after several hours). How long
> should the context live in the cache with those patches? Until the krb5
> ticket expires? I'll leave the box in this state until around this time
> tomorrow to be sure (that's when the ticket expires).

Yes, that should be the normal expiration with my patches.  The
default ticket lifetime is 10 hours I believe, but that is
configurable by realm (and service).  You can shorten the lifetime for
testing by setting an /etc/krb5.conf option.  This example should
limit lifetimes to 5 minutes (300 seconds) for testing purposes.

[libdefaults]
ticket_lifetime = 300s

K.C.

Re: possible module refcount leak with auth_gss

[Jeff Layton]

On Tue, 9 Dec 2008 18:21:08 -0500
"Kevin Coffman" <kwc@umich.edu> wrote:

> On Tue, Dec 9, 2008 at 3:38 PM, Jeff Layton <jlayton@redhat.com> wrote:
> > On Mon, 8 Dec 2008 12:37:06 -0500
> > "J. Bruce Fields" <bfields@fieldses.org> wrote:
> >
> >> On Mon, Dec 08, 2008 at 10:28:55AM -0500, Jeff Layton wrote:
> >> > We had someone report a bug against Fedora that they were seeing very
> >> > high module reference counts for some krb5 related modules on his nfs
> >> > server. For instance:
> >> >
> >> > # lsmod
> >> > Module                  Size  Used by
> >> > des_generic            25216  52736
> >> > cbc                    12160  52736
> >> > rpcsec_gss_krb5        15632  26370
> >> >
> >> > ...the cbc and des_generic each have roughly 2 module references per
> >> > rpcsec_gss_krb5 refcount so I'm assuming that the "lynchpin" here is
> >> > the rpcsec_gss_krb5 refcount which seems to be increasing w/o bound.
> >>
> >> You may want to see this discussion:
> >>
> >>       http://marc.info/?t=122819524700001&r=1&w=2
> >>
> >> And these patches:
> >>
> >>       http://marc.info/?l=linux-nfs&m=122843371318602&w=2
> >>
> >
> > Doh! I saw that discussion and didn't make the connection. Thanks for
> > pointing that out.
> >
> >> In addition to increasing the timeouts on those cache entries, perhaps
> >> we could flush the contexts on rmmod?  Or change the reference counting
> >> somehow--e.g., take a reference only in the presence of export cache
> >> entries that mention krb5, and destroy contexts when the last such goes
> >> away?
> >>
> >
> > That sounds like a better scheme than what we have currently. As it stands
> > now, you can't just unplug the module -- you have to wait for the entries
> > in the cache to time out.
> >
> > FWIW, I tested out Kevin's patches and it still didn't seem to help. The
> > refcounts never seemed to go down (even after several hours). How long
> > should the context live in the cache with those patches? Until the krb5
> > ticket expires? I'll leave the box in this state until around this time
> > tomorrow to be sure (that's when the ticket expires).
> 
> Yes, that should be the normal expiration with my patches.  The
> default ticket lifetime is 10 hours I believe, but that is
> configurable by realm (and service).  You can shorten the lifetime for
> testing by setting an /etc/krb5.conf option.  This example should
> limit lifetimes to 5 minutes (300 seconds) for testing purposes.
> 
> [libdefaults]
> ticket_lifetime = 300s
> 

Thanks Kevin,

It works. With a nfs-utils that has your patches to properly set the
cache timeouts it looks like this problem is generally fixed. The module
refcounts go back to normal once the tickets expire.

That said, I think we should have a look at Bruce's suggestion for changing
the way that the module refcounts are actually handled. It would seem to
make more sense to hold the reference based on the exports using that auth
scheme, and to purge the caches on module unload.

Not a huge deal, but probably something we should consider.

-- 
Jeff Layton <jlayton@redhat.com>

Re: possible module refcount leak with auth_gss

[J. Bruce Fields]

On Wed, Dec 10, 2008 at 11:25:06AM -0500, Jeff Layton wrote:
> It works. With a nfs-utils that has your patches to properly set the
> cache timeouts it looks like this problem is generally fixed. The module
> refcounts go back to normal once the tickets expire.
> 
> That said, I think we should have a look at Bruce's suggestion for changing
> the way that the module refcounts are actually handled. It would seem to
> make more sense to hold the reference based on the exports using that auth
> scheme, and to purge the caches on module unload.
> 
> Not a huge deal, but probably something we should consider.

Yeah.  Since I don't care enough about module unloading, I'm not going
to work on this now.  But it's unfortunate.

I'm a little more worried about why the RPC_GSS_PROC_DESTROY requests
aren't working.

--b.

Re: possible module refcount leak with auth_gss

[Jeff Layton]

On Wed, 10 Dec 2008 11:31:36 -0500
"J. Bruce Fields" <bfields@fieldses.org> wrote:

> On Wed, Dec 10, 2008 at 11:25:06AM -0500, Jeff Layton wrote:
> > It works. With a nfs-utils that has your patches to properly set the
> > cache timeouts it looks like this problem is generally fixed. The module
> > refcounts go back to normal once the tickets expire.
> > 
> > That said, I think we should have a look at Bruce's suggestion for changing
> > the way that the module refcounts are actually handled. It would seem to
> > make more sense to hold the reference based on the exports using that auth
> > scheme, and to purge the caches on module unload.
> > 
> > Not a huge deal, but probably something we should consider.
> 
> Yeah.  Since I don't care enough about module unloading, I'm not going
> to work on this now.  But it's unfortunate.
> 
> I'm a little more worried about why the RPC_GSS_PROC_DESTROY requests
> aren't working.
> 

I took some time today to dig into this. Here's some debug output from
the RPC_GSS_PROC_DESTROY request on the client:

RPC:     0 holding RPCSEC_GSS cred ffff880011579bb8
RPC:       new task initialized, procpid 2846
RPC:       allocated task ffff88001e110000
RPC:    11 __rpc_execute flags=0x281
RPC:    11 call_start nfs4 proc NULL (async)
RPC:    11 call_reserve (status 0)
RPC:    11 call_refresh (status 0)
RPC:    11 refreshing RPCSEC_GSS cred ffff880011579bb8
RPC:    11 call_refreshresult (status -13)
RPC:    11 return 0, status -13
RPC:    11 release task
RPC:    11 releasing RPCSEC_GSS cred ffff880011579bb8

...looks like we're trying to refresh the credentials before sending the
call but that's failing. That's as far as I've gotten with it so far
though.

-- 
Jeff Layton <jlayton@redhat.com>

Re: possible module refcount leak with auth_gss

[Jeff Layton]

On Tue, 16 Dec 2008 16:45:32 -0500
Jeff Layton <jlayton@redhat.com> wrote:

> On Wed, 10 Dec 2008 11:31:36 -0500
> "J. Bruce Fields" <bfields@fieldses.org> wrote:
> 
> > On Wed, Dec 10, 2008 at 11:25:06AM -0500, Jeff Layton wrote:
> > > It works. With a nfs-utils that has your patches to properly set the
> > > cache timeouts it looks like this problem is generally fixed. The module
> > > refcounts go back to normal once the tickets expire.
> > > 
> > > That said, I think we should have a look at Bruce's suggestion for changing
> > > the way that the module refcounts are actually handled. It would seem to
> > > make more sense to hold the reference based on the exports using that auth
> > > scheme, and to purge the caches on module unload.
> > > 
> > > Not a huge deal, but probably something we should consider.
> > 
> > Yeah.  Since I don't care enough about module unloading, I'm not going
> > to work on this now.  But it's unfortunate.
> > 
> > I'm a little more worried about why the RPC_GSS_PROC_DESTROY requests
> > aren't working.
> > 
> 
> I took some time today to dig into this. Here's some debug output from
> the RPC_GSS_PROC_DESTROY request on the client:
> 
> RPC:     0 holding RPCSEC_GSS cred ffff880011579bb8
> RPC:       new task initialized, procpid 2846
> RPC:       allocated task ffff88001e110000
> RPC:    11 __rpc_execute flags=0x281
> RPC:    11 call_start nfs4 proc NULL (async)
> RPC:    11 call_reserve (status 0)
> RPC:    11 call_refresh (status 0)
> RPC:    11 refreshing RPCSEC_GSS cred ffff880011579bb8
> RPC:    11 call_refreshresult (status -13)
> RPC:    11 return 0, status -13
> RPC:    11 release task
> RPC:    11 releasing RPCSEC_GSS cred ffff880011579bb8
> 
> ...looks like we're trying to refresh the credentials before sending the
> call but that's failing. That's as far as I've gotten with it so far
> though.
> 

I see why this is occuring, but I'm afraid I don't understand the code
well enough to understand why it's written this way...

gss_destroying_context() does this:

        if (gss_cred->gc_ctx == NULL ||
            test_and_clear_bit(RPCAUTH_CRED_UPTODATE, &cred->cr_flags) == 0)
                return 0;

        gss_cred->gc_ctx->gc_proc = RPC_GSS_PROC_DESTROY;
        cred->cr_ops = &gss_nullops;

...and then it does the rpc NULL call. The problem is that we're clearing
RPCAUTH_CRED_UPTODATE and then setting cr_ops to gss_nullops. The rpc
call is done, call_reserve checks the RPCAUTH_CRED_UPTODATE bit, and calls
call_refresh because it's not set.

call_refresh calls rpcauth_refreshcred which calls the crrefresh op. That's
now gss_refresh_null, and that just returns -EACCES. The RPC call then
fails w/o ever being sent.

It seems like we either need to not clear the UPTODATE bit for the cred, or
not set the cr_ops to the nullops before doing the call. Any thoughts?

-- 
Jeff Layton <jlayton@redhat.com>

Re: possible module refcount leak with auth_gss

[J. Bruce Fields]

On Tue, Dec 16, 2008 at 09:40:51PM -0500, Jeff Layton wrote:
> On Tue, 16 Dec 2008 16:45:32 -0500
> Jeff Layton <jlayton@redhat.com> wrote:
> > I took some time today to dig into this. Here's some debug output from
> > the RPC_GSS_PROC_DESTROY request on the client:
> > 
> > RPC:     0 holding RPCSEC_GSS cred ffff880011579bb8
> > RPC:       new task initialized, procpid 2846
> > RPC:       allocated task ffff88001e110000
> > RPC:    11 __rpc_execute flags=0x281
> > RPC:    11 call_start nfs4 proc NULL (async)
> > RPC:    11 call_reserve (status 0)
> > RPC:    11 call_refresh (status 0)
> > RPC:    11 refreshing RPCSEC_GSS cred ffff880011579bb8
> > RPC:    11 call_refreshresult (status -13)
> > RPC:    11 return 0, status -13
> > RPC:    11 release task
> > RPC:    11 releasing RPCSEC_GSS cred ffff880011579bb8
> > 
> > ...looks like we're trying to refresh the credentials before sending the
> > call but that's failing. That's as far as I've gotten with it so far
> > though.
> > 
> 
> I see why this is occuring, but I'm afraid I don't understand the code
> well enough to understand why it's written this way...
> 
> gss_destroying_context() does this:
> 
>         if (gss_cred->gc_ctx == NULL ||
>             test_and_clear_bit(RPCAUTH_CRED_UPTODATE, &cred->cr_flags) == 0)
>                 return 0;
> 
>         gss_cred->gc_ctx->gc_proc = RPC_GSS_PROC_DESTROY;
>         cred->cr_ops = &gss_nullops;
> 
> ...and then it does the rpc NULL call. The problem is that we're clearing
> RPCAUTH_CRED_UPTODATE and then setting cr_ops to gss_nullops. The rpc
> call is done, call_reserve checks the RPCAUTH_CRED_UPTODATE bit, and calls
> call_refresh because it's not set.
> 
> call_refresh calls rpcauth_refreshcred which calls the crrefresh op. That's
> now gss_refresh_null, and that just returns -EACCES. The RPC call then
> fails w/o ever being sent.
> 
> It seems like we either need to not clear the UPTODATE bit for the cred, or
> not set the cr_ops to the nullops before doing the call. Any thoughts?

We certainly shouldn't be really refreshing the cred--that'd end up
creating a new gss context when what we're trying to do is destroy one.
So leaving cr_ops set to gss_credops() doesn't sound right.

Maybe that gss_refresh_null() should just return 0 and pretend the
cred's fine, instead of returning -EACCES?

--b.

Re: possible module refcount leak with auth_gss

[Jeff Layton]

On Wed, 17 Dec 2008 14:20:47 -0500
"J. Bruce Fields" <bfields@fieldses.org> wrote:

> On Tue, Dec 16, 2008 at 09:40:51PM -0500, Jeff Layton wrote:
> > On Tue, 16 Dec 2008 16:45:32 -0500
> > Jeff Layton <jlayton@redhat.com> wrote:
> > > I took some time today to dig into this. Here's some debug output from
> > > the RPC_GSS_PROC_DESTROY request on the client:
> > > 
> > > RPC:     0 holding RPCSEC_GSS cred ffff880011579bb8
> > > RPC:       new task initialized, procpid 2846
> > > RPC:       allocated task ffff88001e110000
> > > RPC:    11 __rpc_execute flags=0x281
> > > RPC:    11 call_start nfs4 proc NULL (async)
> > > RPC:    11 call_reserve (status 0)
> > > RPC:    11 call_refresh (status 0)
> > > RPC:    11 refreshing RPCSEC_GSS cred ffff880011579bb8
> > > RPC:    11 call_refreshresult (status -13)
> > > RPC:    11 return 0, status -13
> > > RPC:    11 release task
> > > RPC:    11 releasing RPCSEC_GSS cred ffff880011579bb8
> > > 
> > > ...looks like we're trying to refresh the credentials before sending the
> > > call but that's failing. That's as far as I've gotten with it so far
> > > though.
> > > 
> > 
> > I see why this is occuring, but I'm afraid I don't understand the code
> > well enough to understand why it's written this way...
> > 
> > gss_destroying_context() does this:
> > 
> >         if (gss_cred->gc_ctx == NULL ||
> >             test_and_clear_bit(RPCAUTH_CRED_UPTODATE, &cred->cr_flags) == 0)
> >                 return 0;
> > 
> >         gss_cred->gc_ctx->gc_proc = RPC_GSS_PROC_DESTROY;
> >         cred->cr_ops = &gss_nullops;
> > 
> > ...and then it does the rpc NULL call. The problem is that we're clearing
> > RPCAUTH_CRED_UPTODATE and then setting cr_ops to gss_nullops. The rpc
> > call is done, call_reserve checks the RPCAUTH_CRED_UPTODATE bit, and calls
> > call_refresh because it's not set.
> > 
> > call_refresh calls rpcauth_refreshcred which calls the crrefresh op. That's
> > now gss_refresh_null, and that just returns -EACCES. The RPC call then
> > fails w/o ever being sent.
> > 
> > It seems like we either need to not clear the UPTODATE bit for the cred, or
> > not set the cr_ops to the nullops before doing the call. Any thoughts?
> 
> We certainly shouldn't be really refreshing the cred--that'd end up
> creating a new gss context when what we're trying to do is destroy one.
> So leaving cr_ops set to gss_credops() doesn't sound right.
> 
> Maybe that gss_refresh_null() should just return 0 and pretend the
> cred's fine, instead of returning -EACCES?
> 

Possibly -- it does look like this is the only place that those credops
are used.

What's the reasoning behind clearing the RPCAUTH_CRED_UPTODATE bit
here? If we don't want to refresh the cred, would it be better to just
leave it set?

-- 
Jeff Layton <jlayton@redhat.com>

Re: possible module refcount leak with auth_gss

[J. Bruce Fields]

On Wed, Dec 17, 2008 at 02:34:58PM -0500, Jeff Layton wrote:
> On Wed, 17 Dec 2008 14:20:47 -0500
> "J. Bruce Fields" <bfields@fieldses.org> wrote:
> > We certainly shouldn't be really refreshing the cred--that'd end up
> > creating a new gss context when what we're trying to do is destroy one.
> > So leaving cr_ops set to gss_credops() doesn't sound right.
> > 
> > Maybe that gss_refresh_null() should just return 0 and pretend the
> > cred's fine, instead of returning -EACCES?
> > 
> 
> Possibly -- it does look like this is the only place that those credops
> are used.
> 
> What's the reasoning behind clearing the RPCAUTH_CRED_UPTODATE bit
> here? If we don't want to refresh the cred, would it be better to just
> leave it set?

It looks like the CRED_UPTODATE is just being used as a signal to decide
whether the PROC_DESTROY has already been sent; the test_and_clear_bit
ensures that the null call is made just once.  Maybe a separate flag
would be simpler.

This is Trond's code, so he should probably comment.

--b.

Re: possible module refcount leak with auth_gss

[Trond Myklebust]

On Wed, 2008-12-17 at 14:41 -0500, J. Bruce Fields wrote:
> It looks like the CRED_UPTODATE is just being used as a signal to decide
> whether the PROC_DESTROY has already been sent; the test_and_clear_bit
> ensures that the null call is made just once.  Maybe a separate flag
> would be simpler.

Just make a separate gss_destroy_cred() which doesn't call
gss_destroying_context() and stick it into gss_nullops.

Trond

Re: possible module refcount leak with auth_gss

[J. Bruce Fields]

On Wed, Dec 17, 2008 at 02:54:11PM -0500, Trond Myklebust wrote:
> On Wed, 2008-12-17 at 14:41 -0500, J. Bruce Fields wrote:
> > It looks like the CRED_UPTODATE is just being used as a signal to decide
> > whether the PROC_DESTROY has already been sent; the test_and_clear_bit
> > ensures that the null call is made just once.  Maybe a separate flag
> > would be simpler.
> 
> Just make a separate gss_destroy_cred() which doesn't call
> gss_destroying_context() and stick it into gss_nullops.

Lost you there.  So you're thinking the current end of
gss_destroy_cred():

	rcu_assign_pointer(gss_cred->gc_ctx, NULL);
	call_rcu(&cred->cr_rcu, gss_free_cred_callback);
	if (ctx)
		gss_put_ctx(ctx);
	kref_put(&gss_auth->kref,
	gss_free_callback);

should go into a separate gss_nullops.crdestroy, and the real work of
gss_destroying_context() (rpc_call_null, etc.) should be done
unconditionally?

(And presumably the rpc code already ensures that ->crdestroy is called
exactly once?)

OK, makes sense.

--b.

Re: possible module refcount leak with auth_gss

[J. Bruce Fields]

On Wed, Dec 17, 2008 at 03:07:01PM -0500, bfields wrote:
> On Wed, Dec 17, 2008 at 02:54:11PM -0500, Trond Myklebust wrote:
> > On Wed, 2008-12-17 at 14:41 -0500, J. Bruce Fields wrote:
> > > It looks like the CRED_UPTODATE is just being used as a signal to decide
> > > whether the PROC_DESTROY has already been sent; the test_and_clear_bit
> > > ensures that the null call is made just once.  Maybe a separate flag
> > > would be simpler.
> > 
> > Just make a separate gss_destroy_cred() which doesn't call
> > gss_destroying_context() and stick it into gss_nullops.
> 
> Lost you there.  So you're thinking the current end of
> gss_destroy_cred():
> 
> 	rcu_assign_pointer(gss_cred->gc_ctx, NULL);
> 	call_rcu(&cred->cr_rcu, gss_free_cred_callback);
> 	if (ctx)
> 		gss_put_ctx(ctx);
> 	kref_put(&gss_auth->kref,
> 	gss_free_callback);
> 
> should go into a separate gss_nullops.crdestroy, and the real work of
> gss_destroying_context() (rpc_call_null, etc.) should be done
> unconditionally?
  ^^^^^^^^^^^^^^^

(OK, we still do want to skip it in the !UPTODATE case, but no need to
clear UPTODATE as any sort of extra guard against a second call any
more.)

--b.

> 
> (And presumably the rpc code already ensures that ->crdestroy is called
> exactly once?)
> 
> OK, makes sense.
> 
> --b.

Re: possible module refcount leak with auth_gss

[Trond Myklebust]

On Wed, 2008-12-17 at 15:07 -0500, J. Bruce Fields wrote:
> On Wed, Dec 17, 2008 at 02:54:11PM -0500, Trond Myklebust wrote:
> > On Wed, 2008-12-17 at 14:41 -0500, J. Bruce Fields wrote:
> > > It looks like the CRED_UPTODATE is just being used as a signal to decide
> > > whether the PROC_DESTROY has already been sent; the test_and_clear_bit
> > > ensures that the null call is made just once.  Maybe a separate flag
> > > would be simpler.
> > 
> > Just make a separate gss_destroy_cred() which doesn't call
> > gss_destroying_context() and stick it into gss_nullops.
> 
> Lost you there.  So you're thinking the current end of
> gss_destroy_cred():
> 
> 	rcu_assign_pointer(gss_cred->gc_ctx, NULL);
> 	call_rcu(&cred->cr_rcu, gss_free_cred_callback);
> 	if (ctx)
> 		gss_put_ctx(ctx);
> 	kref_put(&gss_auth->kref,
> 	gss_free_callback);
> 
> should go into a separate gss_nullops.crdestroy, and the real work of
> gss_destroying_context() (rpc_call_null, etc.) should be done
> unconditionally?

Not unconditionally. If the session has already expired, there is no
point in sending a GSS_DESTROY. In that case, and that case only, you
jump straight to the gss_nullops.crdestroy() code.

> (And presumably the rpc code already ensures that ->crdestroy is called
> exactly once?)

Yes.

Trond

Re: possible module refcount leak with auth_gss

[Trond Myklebust]

On Wed, 2008-12-17 at 14:20 -0500, J. Bruce Fields wrote:
> On Tue, Dec 16, 2008 at 09:40:51PM -0500, Jeff Layton wrote:
> > On Tue, 16 Dec 2008 16:45:32 -0500
> > Jeff Layton <jlayton@redhat.com> wrote:
> > > I took some time today to dig into this. Here's some debug output from
> > > the RPC_GSS_PROC_DESTROY request on the client:
> > > 
> > > RPC:     0 holding RPCSEC_GSS cred ffff880011579bb8
> > > RPC:       new task initialized, procpid 2846
> > > RPC:       allocated task ffff88001e110000
> > > RPC:    11 __rpc_execute flags=0x281
> > > RPC:    11 call_start nfs4 proc NULL (async)
> > > RPC:    11 call_reserve (status 0)
> > > RPC:    11 call_refresh (status 0)
> > > RPC:    11 refreshing RPCSEC_GSS cred ffff880011579bb8
> > > RPC:    11 call_refreshresult (status -13)
> > > RPC:    11 return 0, status -13
> > > RPC:    11 release task
> > > RPC:    11 releasing RPCSEC_GSS cred ffff880011579bb8
> > > 
> > > ...looks like we're trying to refresh the credentials before sending the
> > > call but that's failing. That's as far as I've gotten with it so far
> > > though.
> > > 
> > 
> > I see why this is occuring, but I'm afraid I don't understand the code
> > well enough to understand why it's written this way...
> > 
> > gss_destroying_context() does this:
> > 
> >         if (gss_cred->gc_ctx == NULL ||
> >             test_and_clear_bit(RPCAUTH_CRED_UPTODATE, &cred->cr_flags) == 0)
> >                 return 0;

Should probably just be a test_bit()

> >         gss_cred->gc_ctx->gc_proc = RPC_GSS_PROC_DESTROY;
> >         cred->cr_ops = &gss_nullops;
> > 
> > ...and then it does the rpc NULL call. The problem is that we're clearing
> > RPCAUTH_CRED_UPTODATE and then setting cr_ops to gss_nullops. The rpc
> > call is done, call_reserve checks the RPCAUTH_CRED_UPTODATE bit, and calls
> > call_refresh because it's not set.
> > 
> > call_refresh calls rpcauth_refreshcred which calls the crrefresh op. That's
> > now gss_refresh_null, and that just returns -EACCES. The RPC call then
> > fails w/o ever being sent.
> > 
> > It seems like we either need to not clear the UPTODATE bit for the cred, or
> > not set the cr_ops to the nullops before doing the call. Any thoughts?
> 
> We certainly shouldn't be really refreshing the cred--that'd end up
> creating a new gss context when what we're trying to do is destroy one.
> So leaving cr_ops set to gss_credops() doesn't sound right.
> 
> Maybe that gss_refresh_null() should just return 0 and pretend the
> cred's fine, instead of returning -EACCES?

That would be wrong, since we would end up sending GSS_DESTROY requests
for sessions that are already dead.

Trond