Since I updated to Debian Bullseye, nfs clients stopped working:
# mount -vvt nfs4 -o sec=krb5 nfs11:/srv /mnt
mount.nfs4: timeout set for Wed Sep 15 20:25:49 2021
mount.nfs4: trying text-based options 'sec=krb5,vers=4.2,addr=x.y.11.63,clientaddr=x.y.11.42'
mount.nfs4: mount(2): Permission denied
mount.nfs4: access denied by server while mounting nfs11:/srv
When I install 5.9 kernel (linux-image-5.9.0-0.bpo.5-cloud-amd64) on the same system - it works.
I also tried:
- Debian Testing Kernel (kernel 5.14) - does not work
- Ubuntu 21.10 Impish (kernel 5.13) - does not work
- Ubuntu 20.04 Focal (kernel 5.4) - works
Provided, that all the systems has an identical NFS/Kerberos setup, my conclusion: Something has changed in the kernel that does not allow to mount NFS/Kerberos shares.
- My KDC - Samba4 AD
- My Kerberos and NFS setup is pretty mach standard, as in any how-to
- HOSTNAME$@REALM nfs/fqdn@REALM host/... principles are there in the client and server key-tab
I put RPCGSSDOPTS="-vvv" in /etc/default/nfs-common for debugging. In the following logs:
- nfs11 - my test nfs server (Debian 11, kernel 5.10)
- tst2 - my test nfs client (Debian 11)
Here is the syslog when the client is attempting to mount nfs share:
nfs client booted with 5.9 kernel (mounts successfully)
rpc.gssd[446]: #012handle_gssd_upcall: 'mech=krb5 uid=0 service=* enctypes=18,17,16,23,3,1,2' (nfs/clnt0)
rpc.gssd[446]: krb5_use_machine_creds: uid 0 tgtname (null)
rpc.gssd[446]: Full hostname for 'nfs11.my.domain' is 'nfs11.my.domain'
rpc.gssd[446]: Full hostname for 'tst2.my.domain' is 'tst2.my.domain'
rpc.gssd[446]: Success getting keytab entry for '[email protected]'
rpc.gssd[446]: gssd_get_single_krb5_cred: principal '[email protected]' ccache:'FILE:/tmp/krb5ccmachine_MY.DOMAIN'
rpc.gssd[446]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_MY.DOMAIN' are good until 1631755378
rpc.gssd[446]: creating tcp client for server nfs11.my.domain
rpc.gssd[446]: DEBUG: port already set to 2049
rpc.gssd[446]: creating context with server [email protected]
rpc.gssd[446]: doing downcall: lifetime_rec=36000 [email protected]
rpc.gssd[446]: #012handle_gssd_upcall: 'mech=krb5 uid=0 enctypes=18,17,16,23,3,1,2' (nfs/clnt0)
rpc.gssd[446]: krb5_use_machine_creds: uid 0 tgtname (null)
rpc.gssd[446]: Full hostname for 'nfs11.my.domain' is 'nfs11.my.domain'
rpc.gssd[446]: Full hostname for 'tst2.my.domain' is 'tst2.my.domain'
rpc.gssd[446]: Success getting keytab entry for '[email protected]'
rpc.gssd[446]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_MY.DOMAIN' are good until 1631755378
rpc.gssd[446]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_MY.DOMAIN' are good until 1631755378
rpc.gssd[446]: creating tcp client for server nfs11.my.domain
rpc.gssd[446]: DEBUG: port already set to 2049
rpc.gssd[446]: creating context with server [email protected]
rpc.gssd[446]: doing downcall: lifetime_rec=36000 [email protected]
nfsidmap[524]: key: 0x3b88d120 type: uid value: [email protected] timeout 600
nfsidmap[524]: nfs4_name_to_uid: calling nsswitch->name_to_uid
nfsidmap[524]: nss_getpwnam: name '[email protected]' domain 'my.domain': resulting localname 'root'
nfsidmap[524]: nfs4_name_to_uid: nsswitch->name_to_uid returned 0
nfsidmap[524]: nfs4_name_to_uid: final return value is 0
nfsidmap[525]: key: 0x317cb571 type: gid value: [email protected] timeout 600
nfsidmap[525]: nfs4_name_to_gid: calling nsswitch->name_to_gid
nfsidmap[525]: nfs4_name_to_gid: nsswitch->name_to_gid returned 0
nfsidmap[525]: nfs4_name_to_gid: final return value is 0
nfs client booted with 5.10 kernel (does not mount)
rpc.gssd[450]: #012handle_gssd_upcall: 'mech=krb5 uid=0 service=* enctypes=18,17,16,3,1,2' (nfs/clnt3)
rpc.gssd[450]: krb5_use_machine_creds: uid 0 tgtname (null)
rpc.gssd[450]: Full hostname for 'nfs11.my.domain' is 'nfs11.my.domain'
rpc.gssd[450]: Full hostname for 'tst2.my.domain' is 'tst2.my.domain'
rpc.gssd[450]: Success getting keytab entry for '[email protected]'
rpc.gssd[450]: gssd_get_single_krb5_cred: principal '[email protected]' ccache:'FILE:/tmp/krb5ccmachine_MY.DOMAIN'
rpc.gssd[450]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_MY.DOMAIN' are good until 1631656676
rpc.gssd[450]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_MY.DOMAIN' are good until 1631629984
rpc.gssd[450]: creating tcp client for server nfs11.my.domain
rpc.gssd[450]: DEBUG: port already set to 2049
rpc.gssd[450]: creating context with server [email protected]
rpc.gssd[450]: WARNING: Failed to create krb5 context for user with uid 0 for server [email protected]
rpc.gssd[450]: WARNING: Failed to create machine krb5 context with cred cache FILE:/tmp/krb5ccmachine_MY.DOMAIN for server nfs11.my.domain
rpc.gssd[450]: creating tcp client for server nfs11.my.domain
rpc.gssd[450]: DEBUG: port already set to 2049
rpc.gssd[450]: creating context with server [email protected]
rpc.gssd[450]: WARNING: Failed to create krb5 context for user with uid 0 for server [email protected]
rpc.gssd[450]: WARNING: Failed to create machine krb5 context with cred cache FILE:/tmp/krb5ccmachine_MY.DOMAIN for server nfs11.my.domain
rpc.gssd[450]: WARNING: Machine cache prematurely expired or corrupted trying to recreate cache for server nfs11.my.domain
rpc.gssd[450]: Full hostname for 'nfs11.my.domain' is 'nfs11.my.domain'
rpc.gssd[450]: Full hostname for 'tst2.my.domain' is 'tst2.my.domain'
rpc.gssd[450]: Success getting keytab entry for '[email protected]'
rpc.gssd[450]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_MY.DOMAIN' are good until 1631656676
rpc.gssd[450]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_MY.DOMAIN' are good until 1631656676
rpc.gssd[450]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_MY.DOMAIN' are good until 1631629984
rpc.gssd[450]: creating tcp client for server nfs11.my.domain
rpc.gssd[450]: DEBUG: port already set to 2049
rpc.gssd[450]: creating context with server [email protected]
rpc.gssd[450]: WARNING: Failed to create krb5 context for user with uid 0 for server [email protected]
rpc.gssd[450]: WARNING: Failed to create machine krb5 context with cred cache FILE:/tmp/krb5ccmachine_MY.DOMAIN for server nfs11.my.domain
rpc.gssd[450]: creating tcp client for server nfs11.my.domain
rpc.gssd[450]: DEBUG: port already set to 2049
rpc.gssd[450]: creating context with server [email protected]
rpc.gssd[450]: WARNING: Failed to create krb5 context for user with uid 0 for server [email protected]
rpc.gssd[450]: WARNING: Failed to create machine krb5 context with cred cache FILE:/tmp/krb5ccmachine_MY.DOMAIN for server nfs11.my.domain
rpc.gssd[450]: ERROR: Failed to create machine krb5 context with any credentials cache for server nfs11.my.domain
rpc.gssd[450]: doing error downcall
I googled a lot and didn't find anything related... Currently as a workaround I run backported kernel from previous release in all nfs client systems. But I think it is dangerous, and something tells me it may break at any time.
Has anyone experienced such a problem? Maybe I should adjust something to match changes in kernel? Maybe I should fill the kernel bug?
UPDATE. Added KDC logs.
KDC while mounting from client with 5.9 kernel - successfully
[2021/09/21 21:55:12.061264, 3] ../../source4/smbd/service_stream.c:67(stream_terminate_connection)
stream_terminate_connection: Terminating connection - 'dcesrv: NT_STATUS_CONNECTION_DISCONNECTED'
[2021/09/21 21:55:44.743415, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: AS-REQ [email protected] from ipv4:x.y.11.42:38701 for krbtgt/[email protected]
[2021/09/21 21:55:44.747105, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: Client sent patypes: 150, 149
[2021/09/21 21:55:44.747154, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: Looking for PKINIT pa-data -- [email protected]
[2021/09/21 21:55:44.747178, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: Looking for ENC-TS pa-data -- [email protected]
[2021/09/21 21:55:44.747209, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: No preauth found, returning PREAUTH-REQUIRED -- [email protected]
[2021/09/21 21:55:44.751030, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: AS-REQ [email protected] from ipv4:x.y.11.42:50506 for krbtgt/[email protected]
[2021/09/21 21:55:44.753959, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: Client sent patypes: encrypted-timestamp, 150, 149
[2021/09/21 21:55:44.754060, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: Looking for PKINIT pa-data -- [email protected]
[2021/09/21 21:55:44.754114, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: Looking for ENC-TS pa-data -- [email protected]
[2021/09/21 21:55:44.754187, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: ENC-TS Pre-authentication succeeded -- [email protected] using arcfour-hmac-md5
[2021/09/21 21:55:44.754275, 3] ../../auth/auth_log.c:635(log_authentication_event_human_readable)
Auth: [Kerberos KDC,ENC-TS Pre-authentication] user [(null)]\[[email protected]] at [Tue, 21 Sep 2021 21:55:44.754261 +06] with [arcfour-hmac-md5] status [NT_STATUS_OK] workstation [(null)] remote host [ipv4:x.y.11.42:50506] became [MYDOM]\[tst2$] [S-1-5-21-3408476796-3867293677-901807371-6619]. local host [NULL]
{"timestamp": "2021-09-21T21:55:44.754359+0600", "type": "Authentication", "Authentication": {"version": {"major": 1, "minor": 2}, "eventId": 4624, "logonId": "dd24014b273cc7a8", "logonType": 3, "status": "NT_STATUS_OK", "localAddress": null, "remoteAddress": "ipv4:x.y.11.42:50506", "serviceDescription": "Kerberos KDC", "authDescription": "ENC-TS Pre-authentication", "clientDomain": null, "clientAccount": "[email protected]", "workstation": null, "becameAccount": "tst2$", "becameDomain": "MYDOM", "becameSid": "S-1-5-21-3408476796-3867293677-901807371-6619", "mappedAccount": "tst2$", "mappedDomain": "MYDOM", "netlogonComputer": null, "netlogonTrustAccount": null, "netlogonNegotiateFlags": "0x00000000", "netlogonSecureChannelType": 0, "netlogonTrustAccountSid": null, "passwordType": "arcfour-hmac-md5", "duration": 3366}}
[2021/09/21 21:55:44.761108, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: AS-REQ authtime: 2021-09-21T21:55:44 starttime: unset endtime: 2021-09-22T07:55:44 renew till: 2021-09-22T21:55:44
[2021/09/21 21:55:44.761282, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: Client supported enctypes: arcfour-hmac-md5, aes128-cts-hmac-sha1-96, aes256-cts-hmac-sha1-96, using arcfour-hmac-md5/arcfour-hmac-md5
[2021/09/21 21:55:44.761368, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: Requested flags: renewable-ok, forwardable
[2021/09/21 21:55:44.767382, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: TGS-REQ [email protected] from ipv4:x.y.11.42:39570 for nfs/[email protected] [canonicalize, renewable, forwardable]
[2021/09/21 21:55:44.773999, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: TGS-REQ authtime: 2021-09-21T21:55:44 starttime: 2021-09-21T21:55:44 endtime: 2021-09-22T07:55:44 renew till: 2021-09-22T21:55:44
[2021/09/21 21:55:44.774695, 3] ../../source4/smbd/service_stream.c:67(stream_terminate_connection)
stream_terminate_connection: Terminating connection - 'kdc_tcp_call_loop: tstream_read_pdu_blob_recv() - NT_STATUS_CONNECTION_DISCONNECTED'
KDC while mounting from client with 5.10 kernel - failed to mount
[2021/09/22 00:31:39.893723, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: AS-REQ [email protected] from ipv4:x.y.11.42:46094 for krbtgt/[email protected]
[2021/09/22 00:31:39.899112, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: Client sent patypes: 150, 149
[2021/09/22 00:31:39.899162, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: Looking for PKINIT pa-data -- [email protected]
[2021/09/22 00:31:39.899186, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: Looking for ENC-TS pa-data -- [email protected]
[2021/09/22 00:31:39.899221, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: No preauth found, returning PREAUTH-REQUIRED -- [email protected]
[2021/09/22 00:31:39.901942, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: AS-REQ [email protected] from ipv4:x.y.11.42:39303 for krbtgt/[email protected]
[2021/09/22 00:31:39.905030, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: Client sent patypes: encrypted-timestamp, 150, 149
[2021/09/22 00:31:39.905080, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: Looking for PKINIT pa-data -- [email protected]
[2021/09/22 00:31:39.905105, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: Looking for ENC-TS pa-data -- [email protected]
[2021/09/22 00:31:39.905171, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: ENC-TS Pre-authentication succeeded -- [email protected] using arcfour-hmac-md5
[2021/09/22 00:31:39.905270, 3] ../../auth/auth_log.c:635(log_authentication_event_human_readable)
Auth: [Kerberos KDC,ENC-TS Pre-authentication] user [(null)]\[[email protected]] at [Wed, 22 Sep 2021 00:31:39.905248 +06] with [arcfour-hmac-md5] status [NT_STATUS_OK] workstation [(null)] remote host [ipv4:x.y.11.42:39303] became [MYDOM]\[tst2$] [S-1-5-21-3408476796-3867293677-901807371-6621]. local host [NULL]
{"timestamp": "2021-09-22T00:31:39.905331+0600", "type": "Authentication", "Authentication": {"version": {"major": 1, "minor": 2}, "eventId": 4624, "logonId": "8511280d720bd92c", "logonType": 3, "status": "NT_STATUS_OK", "localAddress": null, "remoteAddress": "ipv4:x.y.11.42:39303", "serviceDescription": "Kerberos KDC", "authDescription": "ENC-TS Pre-authentication", "clientDomain": null, "clientAccount": "[email protected]", "workstation": null, "becameAccount": "tst2$", "becameDomain": "MYDOM", "becameSid": "S-1-5-21-3408476796-3867293677-901807371-6621", "mappedAccount": "tst2$", "mappedDomain": "MYDOM", "netlogonComputer": null, "netlogonTrustAccount": null, "netlogonNegotiateFlags": "0x00000000", "netlogonSecureChannelType": 0, "netlogonTrustAccountSid": null, "passwordType": "arcfour-hmac-md5", "duration": 3429}}
[2021/09/22 00:31:39.912509, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: AS-REQ authtime: 2021-09-22T00:31:39 starttime: unset endtime: 2021-09-22T10:31:39 renew till: 2021-09-23T00:31:39
[2021/09/22 00:31:39.912597, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: Client supported enctypes: arcfour-hmac-md5, aes128-cts-hmac-sha1-96, aes256-cts-hmac-sha1-96, using arcfour-hmac-md5/arcfour-hmac-md5
[2021/09/22 00:31:39.912663, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: Requested flags: renewable-ok, forwardable
[2021/09/22 00:31:39.918313, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: TGS-REQ [email protected] from ipv4:x.y.11.42:59850 for nfs/[email protected] [canonicalize, renewable, forwardable]
[2021/09/22 00:31:39.924869, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: TGS-REQ authtime: 2021-09-22T00:31:39 starttime: 2021-09-22T00:31:39 endtime: 2021-09-22T10:31:39 renew till: 2021-09-23T00:31:39
[2021/09/22 00:31:39.925340, 3] ../../source4/smbd/service_stream.c:67(stream_terminate_connection)
stream_terminate_connection: Terminating connection - 'kdc_tcp_call_loop: tstream_read_pdu_blob_recv() - NT_STATUS_CONNECTION_DISCONNECTED'
[2021/09/22 00:31:39.928319, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: TGS-REQ [email protected] from ipv4:x.y.11.42:59852 for nfs/[email protected] [renewable, forwardable]
[2021/09/22 00:31:39.930936, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: Server (nfs/[email protected]) has no support for etypes
[2021/09/22 00:31:39.930998, 3] ../../source4/auth/kerberos/krb5_init_context.c:80(smb_krb5_debug_wrapper)
Kerberos: Failed building TGS-REP to ipv4:x.y.11.42:59852
[2021/09/22 00:31:39.931336, 3] ../../source4/smbd/service_stream.c:67(stream_terminate_connection)
stream_terminate_connection: Terminating connection - 'kdc_tcp_call_loop: tstream_read_pdu_blob_recv() - NT_STATUS_CONNECTION_DISCONNECTED'
I see Server (nfs/[email protected]) has no support for etypes error. Google finds an old issues related to old enctypes, nothing useful. All the packages are up to date.
I have made some progress, thanks to the comments. I installed fresh Samba DC, joined both client (5.10 kernel) and server to new KDC - and it worked! New KDC allows NFS clients with any kernel to mount shares. It seems that the problem is in my production Samba DC. I looked into ldap DBs and it seems they are similar, except very few additions on fresh dc like 3 new objects and some fields. Currently I don't know what I should tweak in the production DC to make it behave like fresh one. Reinstall would be the last resort, because it involves A LOT of time.
Production DC was created long ago, and was migrated several times using standard samba replication or backups. Production and fresh DC info:
- oEMInformation: Provisioned by SAMBA 4.1.6-Ubuntu
- oEMInformation: Provisioned by SAMBA 4.13.5-Debian
Currently DCs are running under identical Debian operating systems.
UPDATE 2. Solved!
See the solution is below.