Race condition when caching GSS context

Thursday, 30 January 2020

Hi,

While setting up some Kerberos shares with ganesha I came across an issue where the client
receives RPCSEC_GSS_CREDPROBLEM. The source of this error is is form following code in
function _svcauth_gss which is used when authenticating RPCSEC_GSS request,

    442         /* Context lookup. */
    443         if ((gc->gc_proc == RPCSEC_GSS_DATA)
    444             || (gc->gc_proc == RPCSEC_GSS_DESTROY)) {
    445 
    446                 /* Per RFC 2203 5.3.3.3, if a valid security context
    447                  * cannot be found to authorize a request, the
    448                  * implementation returns RPCSEC_GSS_CREDPROBLEM.
    449                  * N.B., we are explicitly allowed to discard contexts
    450                  * for any reason (e.g., to save space). */
    451                 gd = authgss_ctx_hash_get(gc);
    452                 if (!gd) {
    453                         rc = RPCSEC_GSS_CREDPROBLEM;
    454                         goto cred_free;
    455                 }
    456                 if (gc->gc_svc != gd->sec.svc)
    457                         gd->sec.svc = gc->gc_svc;
    458         }

When the GSS proc is GSS_DATA or GSS_DESTROY, ntirpc expects the context to be in the
cache. If not it returns RPCSEC_GSS_CREDPROBLEM.

For the above condition to be true, this context should have been inserted in the cache as
part of GSS_INIT request. In the same function, the svc_rpc_gss_data object is inserted in
the cache but there is a difference in the dispatch code. When the request is
RPCSEC_GSS_INIT, ntirpc sends the reply back to the client before caching the context.

    533                 *no_dispatch = true;
    534 
    535                 req->rq_msg.RPCM_ack.ar_results.where = &gr;
    536                 req->rq_msg.RPCM_ack.ar_results.proc =
    537                                         (xdrproc_t) xdr_rpc_gss_init_res;
    538                 call_stat = svc_sendreply(req);                                 
<-- Sending reply to client here
    539 
    540                 /* XXX */
    541                 gss_release_buffer(&min_stat, &gr.gr_token);
    542                 gss_release_buffer(&min_stat, &gd->checksum);
    543                 mem_free(gr.gr_ctx.value, 0);
    544 
    545                 if (call_stat >= XPRT_DIED) {
    546                         rc = AUTH_FAILED;
    547                         goto gd_free;
    548                 }
    549 
    550                 if (gr.gr_major == GSS_S_COMPLETE) {
    ……
    ……
    583                         (void)authgss_ctx_hash_set(gd);                     
<-- Inserting the svc_rpc_gss_data object into the cache
    584                 }

In my setup, I observed that, the client can send another request, let's say
EXCHANGE_ID with RPCSEC_GSS_DATA and end up returning the CREDPROBLEM error if that work
thread gets scheduled first and tries to authenticate the request before the context is
inserted in the cache. I believe we should be sending the reply after inserting the
context in the cache.

Please find some logs below which confirm the race. Svc_10 is the RPCSEC_GSS_INIT request
and svc_4 is RPCSEC_GSS_DATA request. We can observe that rbtree_x_cached_lookup happens
before rbtree_x_cached_insert for hash key f8003f00,

2020-01-30T16:52:42Z : ganesha.nfsd-2248[none] [svc_10] 0 :rpc :TIRPC
:xdr_reply_encode:109 SUCCESS
2020-01-30T16:52:42Z : ganesha.nfsd-2248[none] [svc_10] 0 :rpc :TIRPC
:xdr_rpc_gss_encode() success (0x7f89fc002360:16)
2020-01-30T16:52:42Z : ganesha.nfsd-2248[none] [svc_10] 0 :rpc :TIRPC
:xdr_rpc_gss_encode() success (0x7f89fc008bb0:155)
2020-01-30T16:52:42Z : ganesha.nfsd-2248[none] [svc_10] 0 :rpc :TIRPC
:xdr_rpc_gss_init_res() encode success (ctx 0x7f89fc002360:16, maj 0, min 0, win 32, token
0x7f89fc008bb0:155)
2020-01-30T16:52:42Z : ganesha.nfsd-2248[none] [svc_10] 0 :rpc :TIRPC :svc_ref_it()
0x7f8a04000a90 fd 32 xp_refcnt 5 af 10 port 35536 @svc_ioq_write_now:265
2020-01-30T16:52:42Z : ganesha.nfsd-2248[none] [svc_10] 0 :rpc :TIRPC :svc_release_it()
0x7f8a04000a90 fd 32 xp_refcnt 4 af 10 port 35536 @svc_ioq_write:233
2020-01-30T16:52:42Z : ganesha.nfsd-2248[none] [svc_10] 0 :rpc :TIRPC :xdr_ioq_destroy()
xioq 0x7f89fc002800
....
....
2020-01-30T16:52:42Z : ganesha.nfsd-2248[none] [svc_4] 0 :rpc :TIRPC :xdr_rpc_gss_cred()
decode success (v 1, proc 0, seq 1, svc 2, ctx 0x7f8a0c001780:16)
2020-01-30T16:52:42Z : ganesha.nfsd-2248[none] [svc_4] 0 :rpc :TIRPC
:rbtree_x_cached_lookup: t 0x7f8a0c0021c0 nk 0x7f8a20153e80 nv (nil)( hk f8003f00
slot/offset 56)
2020-01-30T16:52:42Z : ganesha.nfsd-2248[none] [svc_4] 0 :rpc :TIRPC :xdr_rpc_gss_cred()
decode success (v 1, proc 0, seq 1, svc 2, ctx 0x7f8a0c001780:16)
2020-01-30T16:52:42Z : ganesha.nfsd-2248[none] [svc_4] 728 :nfs_rpc_process_request :DISP
:Could not authenticate request... rejecting with AUTH_STAT=RPCSEC_GSS_CREDPROBLEM
....
....
2020-01-30T16:52:42Z : ganesha.nfsd-2248[none] [svc_10] 0 :rpc :TIRPC
:rbtree_x_cached_insert: cix 9 ct 0x7f8a0c0021c0 t 0x7f8a0c0021c0 inserting 0x7f89fc001890
(cache hk f8003f00 slot/offset 56) flags 3
2020-01-30T16:52:42Z : ganesha.nfsd-2248[none] [svc_10] 0 :rpc :TIRPC :xdr_rpc_gss_cred()
decode success (v 1, proc 1, seq 0, svc 1, ctx (nil):0)
2020-01-30T16:52:42Z : ganesha.nfsd-2248[none] [svc_10] 740 :nfs_rpc_process_request :DISP
:RPCSEC_GSS no_dispatch=1 gc->gc_proc=(1) RPCSEC_GSS_INIT

Is this a known issue or being worked on already?

Thanks,
Sriram

2024

2023

2022

2021

2020

2019

2018