[Date Prev][Date Next] [Thread Prev][Thread Next] [Date Index] [Thread Index]

Bug#753732: NFS sec=krb5 does not work with cross-realm

Package: nfs-common
Version: 1.2.6-4
NFS with sec=krb5i or sec=krb5p using MIT Kerberos does not work when cross-realm authentication is used -- only when clients have an Kerberos ticket for the same realm. This happens consistently and in cases when cross-realm authentication does work with other services on the same machine, such as SSH.
To illustrate, I've included two sets of NFS debug output from both a client (daboia.dapadam.nl) and a server (cerastes.dapadam.nl): one set with a successful authentication and the other with a failure. The first set involves a user, jwinius, with an MIT Kerberos ticket from the same realm, DAPADAM.NL, that results in a successful authentication: 

=== Begin === Success, client log output =================
Jul 1 16:08:37 daboia rpc.gssd[1422]: handling gssd upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt0) Jul 1 16:08:37 daboia rpc.gssd[1422]: handle_gssd_upcall: 'mech=krb5 uid=10000 enctypes=18,17,16,23,3,1,2 ' Jul 1 16:08:37 daboia rpc.gssd[1422]: handling krb5 upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt0) Jul 1 16:08:37 daboia rpc.gssd[1422]: process_krb5_upcall: service is '<null>' Jul 1 16:08:37 daboia rpc.gssd[1422]: getting credentials for client with uid 10000 for server cerastes.dapadam.nl Jul 1 16:08:37 daboia rpc.gssd[1422]: CC file '/tmp/krb5cc_0_8TcUINGCct' being considered, with preferred realm 'DAPADAM.NL' Jul 1 16:08:37 daboia rpc.gssd[1422]: CC file '/tmp/krb5cc_0_8TcUINGCct' owned by 0, not 10000 Jul 1 16:08:37 daboia rpc.gssd[1422]: CC file '/tmp/krb5cc_machine_DAPADAM.NL' being considered, with preferred realm 'DAPADAM.NL' Jul 1 16:08:37 daboia rpc.gssd[1422]: CC file '/tmp/krb5cc_machine_DAPADAM.NL' owned by 0, not 10000 Jul 1 16:08:37 daboia rpc.gssd[1422]: CC file '/tmp/krb5cc_10000_HFd9c1oOJy' being considered, with preferred realm 'DAPADAM.NL' Jul 1 16:08:37 daboia rpc.gssd[1422]: CC file '/tmp/krb5cc_10000_HFd9c1oOJy'(jwinius@DAPADAM.NL) passed all checks and has mtime of 1404223701 Jul 1 16:08:37 daboia rpc.gssd[1422]: CC file '/tmp/krb5cc_0' being considered, with preferred realm 'DAPADAM.NL' Jul 1 16:08:37 daboia rpc.gssd[1422]: CC file '/tmp/krb5cc_0' owned by 0, not 10000 Jul 1 16:08:37 daboia rpc.gssd[1422]: using FILE:/tmp/krb5cc_10000_HFd9c1oOJy as credentials cache for client with uid 10000 for server cerastes.dapadam.nl Jul 1 16:08:37 daboia rpc.gssd[1422]: using environment variable to select krb5 ccache FILE:/tmp/krb5cc_10000_HFd9c1oOJy Jul 1 16:08:37 daboia rpc.gssd[1422]: creating context using fsuid 10000 (save_uid 0) Jul 1 16:08:37 daboia rpc.gssd[1422]: creating tcp client for server cerastes.dapadam.nl 
Jul  1 16:08:37 daboia rpc.gssd[1422]: DEBUG: port already set to 2049
Jul 1 16:08:37 daboia rpc.gssd[1422]: creating context with server nfs@cerastes.dapadam.nl Jul 1 16:08:37 daboia rpc.gssd[1422]: DEBUG: serialize_krb5_ctx: lucid version! 
Jul  1 16:08:37 daboia rpc.gssd[1422]: prepare_krb5_rfc4121_buffer: protocol 1
Jul 1 16:08:37 daboia rpc.gssd[1422]: prepare_krb5_rfc4121_buffer: serializing key with enctype 18 and size 32 
Jul  1 16:08:37 daboia rpc.gssd[1422]: doing downcall
Jul 1 16:08:37 daboia rpc.idmapd[1417]: nfs4_name_to_uid: calling nsswitch->name_to_uid Jul 1 16:08:37 daboia rpc.idmapd[1417]: nss_getpwnam: name 'jwinius@dapadam.nl' domain 'dapadam.nl': resulting localname 'jwinius' Jul 1 16:08:37 daboia rpc.idmapd[1417]: nfs4_name_to_uid: nsswitch->name_to_uid returned 0 Jul 1 16:08:37 daboia rpc.idmapd[1417]: nfs4_name_to_uid: final return value is 0 Jul 1 16:08:37 daboia rpc.idmapd[1417]: Client 0: (user) name "jwinius@dapadam.nl" -> id "10000" Jul 1 16:08:37 daboia rpc.idmapd[1417]: nfs4_name_to_gid: calling nsswitch->name_to_gid Jul 1 16:08:37 daboia rpc.idmapd[1417]: nfs4_name_to_gid: nsswitch->name_to_gid returned 0 Jul 1 16:08:37 daboia rpc.idmapd[1417]: nfs4_name_to_gid: final return value is 0 Jul 1 16:08:37 daboia rpc.idmapd[1417]: Client 0: (group) name "jwinius@dapadam.nl" -> id "10000" Jul 1 16:08:37 daboia rpc.gssd[1422]: dir_notify_handler: sig 37 si 0x7fff3cdee670 data 0x7fff3cdee540 
Jul  1 16:08:37 daboia rpc.idmapd[1417]: New client: 2
Jul 1 16:17:01 daboia /USR/SBIN/CRON[2399]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly) 
=== End ===== Success, client log output =================

=== Begin === Success, server log output =================
Jul  1 16:08:37 cerastes rpc.svcgssd[3295]: leaving poll
Jul  1 16:08:37 cerastes rpc.svcgssd[3295]: handling null request
Jul 1 16:08:37 cerastes rpc.svcgssd[3295]: svcgssd_limit_krb5_enctypes: Calling gss_set_allowable_enctypes with 7 enctypes from the kernel 
Jul  1 16:08:37 cerastes rpc.svcgssd[3295]: sname = jwinius@DAPADAM.NL
Jul 1 16:08:37 cerastes rpc.svcgssd[3295]: DEBUG: serialize_krb5_ctx: lucid version! Jul 1 16:08:37 cerastes rpc.svcgssd[3295]: prepare_krb5_rfc4121_buffer: protocol 1 Jul 1 16:08:37 cerastes rpc.svcgssd[3295]: prepare_krb5_rfc4121_buffer: serializing key with enctype 18 and size 32 
Jul  1 16:08:37 cerastes rpc.svcgssd[3295]: doing downcall
Jul 1 16:08:37 cerastes rpc.svcgssd[3295]: mech: krb5, hndl len: 4, ctx len 52, timeout: 1404310094 (86377 from now), clnt: <null>, uid: 10000, gid: 10000, num 
Jul  1 16:08:37 cerastes rpc.svcgssd[3295]:   (   1) 10000
Jul  1 16:08:37 cerastes rpc.svcgssd[3295]: sending null reply
Jul 1 16:08:37 cerastes rpc.svcgssd[3295]: writing message: \x \x6082025806092a864886f71201020201006e82024730820243a003020105a10302010ea20703050020000000a38201 
Jul  1 16:08:37 cerastes rpc.svcgssd[3295]: finished handling null request
Jul  1 16:08:37 cerastes rpc.svcgssd[3295]: entering poll
Jul 1 16:08:37 cerastes rpc.idmapd[1579]: nfsdcb: authbuf=gss/krb5i authtype=user Jul 1 16:08:37 cerastes rpc.idmapd[1579]: nfs4_uid_to_name: calling nsswitch->uid_to_name Jul 1 16:08:37 cerastes rpc.idmapd[1579]: nfs4_uid_to_name: nsswitch->uid_to_name returned 0 Jul 1 16:08:37 cerastes rpc.idmapd[1579]: nfs4_uid_to_name: final return value is 0 Jul 1 16:08:37 cerastes rpc.idmapd[1579]: Server : (user) id "0" -> name "root@dapadam.nl" Jul 1 16:08:37 cerastes rpc.idmapd[1579]: nfsdcb: authbuf=gss/krb5i authtype=group Jul 1 16:08:37 cerastes rpc.idmapd[1579]: nfs4_gid_to_name: calling nsswitch->gid_to_name Jul 1 16:08:37 cerastes rpc.idmapd[1579]: nfs4_gid_to_name: nsswitch->gid_to_name returned 0 Jul 1 16:08:37 cerastes rpc.idmapd[1579]: nfs4_gid_to_name: final return value is 0 Jul 1 16:08:37 cerastes rpc.idmapd[1579]: Server : (group) id "0" -> name "root@dapadam.nl" Jul 1 16:08:37 cerastes rpc.idmapd[1579]: nfsdcb: authbuf=gss/krb5i authtype=user Jul 1 16:08:37 cerastes rpc.idmapd[1579]: nfs4_uid_to_name: calling nsswitch->uid_to_name Jul 1 16:08:37 cerastes rpc.idmapd[1579]: nfs4_uid_to_name: nsswitch->uid_to_name returned 0 Jul 1 16:08:37 cerastes rpc.idmapd[1579]: nfs4_uid_to_name: final return value is 0 Jul 1 16:08:37 cerastes rpc.idmapd[1579]: Server : (user) id "10000" -> name "jwinius@dapadam.nl" Jul 1 16:08:37 cerastes rpc.idmapd[1579]: nfsdcb: authbuf=gss/krb5i authtype=group Jul 1 16:08:37 cerastes rpc.idmapd[1579]: nfs4_gid_to_name: calling nsswitch->gid_to_name Jul 1 16:08:37 cerastes rpc.idmapd[1579]: nfs4_gid_to_name: nsswitch->gid_to_name returned 0 Jul 1 16:08:37 cerastes rpc.idmapd[1579]: nfs4_gid_to_name: final return value is 0 Jul 1 16:08:37 cerastes rpc.idmapd[1579]: Server : (group) id "10000" -> name "jwinius@dapadam.nl" Jul 1 16:17:01 cerastes /USR/SBIN/CRON[3331]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly) 
=== End ===== Success, server log output =================
The second set involves a user account with the same name, jwinius, but with a Kerberos ticket from a different, albeit trusted realm: UMRK.NL. This always results in an authentication failure: 

=== Begin === Failure, client log output =================
Jul 1 16:22:19 daboia rpc.gssd[1423]: handling gssd upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt0) Jul 1 16:22:19 daboia rpc.gssd[1423]: handle_gssd_upcall: 'mech=krb5 uid=10000 enctypes=18,17,16,23,3,1,2 ' Jul 1 16:22:19 daboia rpc.gssd[1423]: handling krb5 upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt0) Jul 1 16:22:19 daboia rpc.gssd[1423]: process_krb5_upcall: service is '<null>' Jul 1 16:22:19 daboia rpc.gssd[1423]: getting credentials for client with uid 10000 for server cerastes.dapadam.nl Jul 1 16:22:19 daboia rpc.gssd[1423]: CC file '/tmp/krb5cc_machine_DAPADAM.NL' being considered, with preferred realm 'DAPADAM.NL' Jul 1 16:22:19 daboia rpc.gssd[1423]: CC file '/tmp/krb5cc_machine_DAPADAM.NL' owned by 0, not 10000 Jul 1 16:22:19 daboia rpc.gssd[1423]: CC file '/tmp/krb5cc_10000_goDYeANk0D' being considered, with preferred realm 'DAPADAM.NL' Jul 1 16:22:19 daboia rpc.gssd[1423]: CC file '/tmp/krb5cc_10000_goDYeANk0D'(jwinius@UMRK.NL) passed all checks and has mtime of 1404224533 Jul 1 16:22:19 daboia rpc.gssd[1423]: CC file '/tmp/krb5cc_0_emiVRCT1ma' being considered, with preferred realm 'DAPADAM.NL' Jul 1 16:22:19 daboia rpc.gssd[1423]: CC file '/tmp/krb5cc_0_emiVRCT1ma' owned by 0, not 10000 Jul 1 16:22:19 daboia rpc.gssd[1423]: CC file '/tmp/krb5cc_0' being considered, with preferred realm 'DAPADAM.NL' Jul 1 16:22:19 daboia rpc.gssd[1423]: CC file '/tmp/krb5cc_0' owned by 0, not 10000 Jul 1 16:22:19 daboia rpc.gssd[1423]: using FILE:/tmp/krb5cc_10000_goDYeANk0D as credentials cache for client with uid 10000 for server cerastes.dapadam.nl Jul 1 16:22:19 daboia rpc.gssd[1423]: using environment variable to select krb5 ccache FILE:/tmp/krb5cc_10000_goDYeANk0D Jul 1 16:22:19 daboia rpc.gssd[1423]: creating context using fsuid 10000 (save_uid 0) Jul 1 16:22:19 daboia rpc.gssd[1423]: creating tcp client for server cerastes.dapadam.nl 
Jul  1 16:22:19 daboia rpc.gssd[1423]: DEBUG: port already set to 2049
Jul 1 16:22:19 daboia rpc.gssd[1423]: creating context with server nfs@cerastes.dapadam.nl Jul 1 16:22:19 daboia rpc.gssd[1423]: DEBUG: serialize_krb5_ctx: lucid version! 
Jul  1 16:22:19 daboia rpc.gssd[1423]: prepare_krb5_rfc4121_buffer: protocol 1
Jul 1 16:22:19 daboia rpc.gssd[1423]: prepare_krb5_rfc4121_buffer: serializing key with enctype 18 and size 32 
Jul  1 16:22:19 daboia rpc.gssd[1423]: doing downcall
Jul 1 16:22:19 daboia rpc.idmapd[1418]: nfs4_name_to_uid: calling nsswitch->name_to_uid Jul 1 16:22:19 daboia rpc.idmapd[1418]: nss_getpwnam: name 'jwinius@dapadam.nl' domain 'dapadam.nl': resulting localname 'jwinius' Jul 1 16:22:19 daboia rpc.idmapd[1418]: nfs4_name_to_uid: nsswitch->name_to_uid returned 0 Jul 1 16:22:19 daboia rpc.idmapd[1418]: nfs4_name_to_uid: final return value is 0 Jul 1 16:22:19 daboia rpc.idmapd[1418]: Client 0: (user) name "jwinius@dapadam.nl" -> id "10000" Jul 1 16:22:19 daboia rpc.idmapd[1418]: nfs4_name_to_gid: calling nsswitch->name_to_gid Jul 1 16:22:19 daboia rpc.idmapd[1418]: nfs4_name_to_gid: nsswitch->name_to_gid returned 0 Jul 1 16:22:19 daboia rpc.idmapd[1418]: nfs4_name_to_gid: final return value is 0 Jul 1 16:22:19 daboia rpc.idmapd[1418]: Client 0: (group) name "jwinius@dapadam.nl" -> id "10000" Jul 1 16:22:19 daboia rpc.gssd[1423]: dir_notify_handler: sig 37 si 0x7fffcbbd9ef0 data 0x7fffcbbd9dc0 
Jul  1 16:22:19 daboia rpc.idmapd[1418]: New client: 2
=== End ===== Failure, client log output =================

=== Begin === Failure, server log output =================
Jul  1 16:22:18 cerastes rpc.svcgssd[3295]: leaving poll
Jul  1 16:22:18 cerastes rpc.svcgssd[3295]: handling null request
Jul 1 16:22:18 cerastes rpc.svcgssd[3295]: svcgssd_limit_krb5_enctypes: Calling gss_set_allowable_enctypes with 7 enctypes from the kernel 
Jul  1 16:22:18 cerastes rpc.svcgssd[3295]: sname = jwinius@UMRK.NL
Jul 1 16:22:18 cerastes rpc.svcgssd[3295]: nss_gss_princ_to_ids: Local-Realm 'UMRK.NL': NOT FOUND Jul 1 16:22:18 cerastes rpc.svcgssd[3295]: DEBUG: serialize_krb5_ctx: lucid version! Jul 1 16:22:18 cerastes rpc.svcgssd[3295]: prepare_krb5_rfc4121_buffer: protocol 1 Jul 1 16:22:18 cerastes rpc.svcgssd[3295]: prepare_krb5_rfc4121_buffer: serializing key with enctype 18 and size 32 
Jul  1 16:22:18 cerastes rpc.svcgssd[3295]: doing downcall
Jul 1 16:22:18 cerastes rpc.svcgssd[3295]: mech: krb5, hndl len: 4, ctx len 52, timeout: 1404299912 (75374 from now), clnt: <null>, uid: -1, gid: -1, num aux g 
Jul  1 16:22:18 cerastes rpc.svcgssd[3295]: sending null reply
Jul 1 16:22:18 cerastes rpc.svcgssd[3295]: writing message: \x \x6082025106092a864886f71201020201006e8202403082023ca003020105a10302010ea20703050020000000a38201 
Jul  1 16:22:18 cerastes rpc.svcgssd[3295]: finished handling null request
Jul  1 16:22:18 cerastes rpc.svcgssd[3295]: entering poll
Jul 1 16:22:18 cerastes rpc.idmapd[1579]: nfsdcb: authbuf=gss/krb5i authtype=user Jul 1 16:22:18 cerastes rpc.idmapd[1579]: nfs4_uid_to_name: calling nsswitch->uid_to_name Jul 1 16:22:18 cerastes rpc.idmapd[1579]: nfs4_uid_to_name: nsswitch->uid_to_name returned 0 Jul 1 16:22:18 cerastes rpc.idmapd[1579]: nfs4_uid_to_name: final return value is 0 Jul 1 16:22:18 cerastes rpc.idmapd[1579]: Server : (user) id "10000" -> name "jwinius@dapadam.nl" Jul 1 16:22:18 cerastes rpc.idmapd[1579]: nfsdcb: authbuf=gss/krb5i authtype=group Jul 1 16:22:18 cerastes rpc.idmapd[1579]: nfs4_gid_to_name: calling nsswitch->gid_to_name Jul 1 16:22:18 cerastes rpc.idmapd[1579]: nfs4_gid_to_name: nsswitch->gid_to_name returned 0 Jul 1 16:22:18 cerastes rpc.idmapd[1579]: nfs4_gid_to_name: final return value is 0 Jul 1 16:22:18 cerastes rpc.idmapd[1579]: Server : (group) id "10000" -> name "jwinius@dapadam.nl" 
=== End ===== Failure, server log output =================
The user experience ends with a "Permission denied" message, although the client does receive a Kerberos service ticket despite the failure. The rpc.idmapd daemon seems to translate the jwinius@UMRK.NL account to "jwinius@dapadam.nl" with user ID 10000. In some situations this might be incorrect, but here it's okay because both accounts belong to the same person.
When authentication fails, the only evidence that I can see for this in the server's log output is in the fifth line shown: "nss_gss_princ_to_ids: Local-Realm 'UMRK.NL': NOT FOUND". Apparently, the local Kerberos KDC is not interrogated and the trust entry for the UMRK.NL realm is never discovered.
For both machines, the verbosity for rpc.idmapd was set to 5, rpc.gssd was used with the options "-D -vvvvvvvvvv" (see Debian bug report #728255 for why I use -D) and rpc.svcgssd was run with the option "-vvvvvvvvvv". The rpc.mountd daemon was also running (with option "--port 32767"), but rpc.statd was disabled. Moreover, I generally get better results when running rpc.svcgssd on the client as well as the server; this daemon is actually part of the nfs-common package, although the startup script does not yet reflect this and needs to be modified for it to start on the client.
Reply to: