Bug 960943 - krb5 nfsv4 Invalid token was supplied
krb5 nfsv4 Invalid token was supplied
Status: CLOSED NEXTRELEASE
Product: Red Hat Enterprise Linux 6
Classification: Red Hat
Component: krb5 (Show other bugs)
6.4
Unspecified Unspecified
unspecified Severity high
: rc
: ---
Assigned To: Roland Mainz
BaseOS QE Security Team
:
Depends On:
Blocks: 1061410
  Show dependency treegraph
 
Reported: 2013-05-08 06:57 EDT by Hansjoerg Maurer
Modified: 2015-09-08 13:27 EDT (History)
10 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2014-11-21 14:51:29 EST
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
logs of rpc.gssd in debug mode (47.38 KB, text/plain)
2013-05-08 06:57 EDT, Hansjoerg Maurer
no flags Details
wireshark capture nfsv4_maurerh.cap (36.12 KB, application/octet-stream)
2014-09-01 08:19 EDT, Hansjoerg Maurer
no flags Details
wireshark capture nfsv4_hotel.cap (21.93 KB, application/octet-stream)
2014-09-01 08:19 EDT, Hansjoerg Maurer
no flags Details
wireshark capture nfsv4_maurerh_tcp.cap (28.25 KB, application/octet-stream)
2014-09-01 08:38 EDT, Hansjoerg Maurer
no flags Details

  None (edit)
Description Hansjoerg Maurer 2013-05-08 06:57:18 EDT
Created attachment 745205 [details]
logs of rpc.gssd in debug mode

Description of problem:

our unix workstations ar connected to Active Directory with QUEST Vintela Authentication Services
krb5 login etc works fine

Mounting a directory with nfs4 with kerberos works fine
Accessing the mounted directory works for some users and fails for other users

with an error in libkrb5 (compiled with debug CFLAG

rpcsec_gss: gss_init_sec_context: Invalid token was supplied - krb5_gss_get_error_message(0, p=0x7f602d385a10) FOUND! -> 0x7f602d363030/Success



Version-Release number of selected component (if applicable):
RHEL6.4
krb5-libs-1.10.3-10.el6.2.x86_64

How reproducible:
100%

Server has a nfs/ SPN in AD

Steps to Reproduce:
rmc-vb56 Client and rmc-intra02 server
1.
mount -t nfs4 -o sec=krb5p rmc-intra02.robotic.dlr.de:/ /mnt/a
works
[root@rmc-vb56 ~]# klist -ec /tmp/krb5cc_machine_INTRA.DLR.DE
Ticket cache: FILE:/tmp/krb5cc_machine_INTRA.DLR.DE
Default principal: host/rmc-vb56.cluster.robotic.dlr.de@INTRA.DLR.DE

Valid starting     Expires            Service principal
05/08/13 11:25:41  05/08/13 21:25:41  krbtgt/INTRA.DLR.DE@INTRA.DLR.DE
        renew until 05/15/13 11:25:41, Etype (skey, tkt): arcfour-hmac, aes256-cts-hmac-sha1-96
05/08/13 11:25:43  05/08/13 21:25:41  nfs/rmc-intra02.robotic.dlr.de@
        renew until 05/15/13 11:25:41, Etype (skey, tkt): arcfour-hmac, arcfour-hmac
05/08/13 11:25:43  05/08/13 21:25:41  nfs/rmc-intra02.robotic.dlr.de@INTRA.DLR.DE
        renew until 05/15/13 11:25:41, Etype (skey, tkt): arcfour-hmac, arcfour-hmac

2. access to /mnt/a as User hotel works

3. access to /mnt/a as user maurerh fails with error in libkrb5
  

Actual results:


Expected results:


Additional info:

attached the logs of rpc.gssd in debug mode with
libtirpc.so.1
libgssglue.so.1
libkrb5.so.3 
compiled with debug options for both cases
The tocken size of maurerh (big PAC due to many groups) is 8516 bytes
the one of hotel (Testuser where it works) is 1455 bytes
The Bug with the libtirpc tocken size
https://bugzilla.redhat.com/show_bug.cgi?format=multiple&id=562807
should be fixed in this version
Comment 3 Hansjoerg Maurer 2014-03-28 05:26:15 EDT
Hi

if you want me to collect further debugging information, let me know .

Regards


Hansjörg
Comment 7 Roland Mainz 2014-08-26 10:45:32 EDT
Some random fishing to find the root cause:
1. Make sure all involved hosts have host/ and nfs/ entries. This is NFSv4 which needs them to make sure delegations work (depending on NFSv4 server and client implementation)

2. Please make sure Kerberos5 server and client use the same enctypes, e.g. "default_tgs_enctypes" and "default_tkt_enctypes" should list the name types. As last resort add "allow_weak_crypto = 1".
I think I've seen this before caused by a gross mismatch in Kerberos5 versions between server and client and forcing them to use the same enctypes fixed it.

Do [1] and [2] help with the problem ?
Comment 8 Nalin Dahyabhai 2014-08-26 11:01:21 EDT
More information about what the server implementation is (it sounds like it might also be an AD server, but it's not clear) might help in reproducing this (hopefully it's not specific to VAS, as I don't think I have access to that), and a full packet capture from a failed attempt would help us rule out SPNEGO-related mechanism OID confusion which was recently fixed upstream.
Comment 9 Hansjoerg Maurer 2014-09-01 06:54:12 EDT
Hi

thank you your your reply (have been on vacation last wekk, therefore the delay).

The server side is an active directory  (2008R2)
The hosts have host/ and nfs/ entries.
The problem is, that we have some User accounts, where it works, and some accounts
where it does not work and libkrb5
compiled with debug CFLAG
logs this error


rpcsec_gss: gss_init_sec_context: Invalid token was supplied - krb5_gss_get_error_message(0, p=0x7f602d385a10) FOUND! -> 0x7f602d363030/Success

Therefore I do not think it is an encyrption error

Both accounts (working and not working)  differ in there group memberships and in the resulting PAC Token Size

The tocken size of maurerh (acoount where it fails) (big PAC due to many groups) is 8516 bytes the one of hotel (Testuser where it works) is 1455 bytes

I will try to reproduce it and capture a wireshark trace on Port 88

Regards

Hansjörg
Comment 10 Roland Mainz 2014-09-01 07:44:20 EDT
Hansjörg, could you please run "kadmin" and send the output of these two commands back:

getprinc <working_account>
getprinc <nonworking_account>
Comment 11 Roland Mainz 2014-09-01 08:03:47 EDT
(In reply to Hansjoerg Maurer from comment #9)
[snip]
> The tocken size of maurerh (acoount where it fails) (big PAC due to many
> groups) is 8516 bytes the one of hotel (Testuser where it works) is 1455
> bytes

Gut feeling about UDP (just to rule this out, in theory UDP/IPv4 has a package size limit of AFAIK 65507 bytes but we should not hit it in our case... in theory):
Do you use TCP or UDP for Krb5 communication ? Do you have any way to force TCP-only operation and then test this issue again ?
Comment 12 Hansjoerg Maurer 2014-09-01 08:16:37 EDT
Hi

attached you get
- two wireshark trace of the working (nfsv4_hotel.cap) and failing (nfsv4_maurerh.cap)

- the trace was captured with the Option  host rmc-intra02 or port 88
in order to get the kerberos and NFS Packets

The sequenz of the commands and the debug messages are here   
mount -t nfs4 -o sec=krb5p rmc-intra02.robotic.dlr.de:/ /mnt/a

Start of capture nfsv4_maurerh.cap
                                  
maurerh at rmc-vb56.cluster.robotic.dlr.de:~> kinit
Password for maurerh@INTRA.DLR.DE:                 
maurerh at rmc-vb56.cluster.robotic.dlr.de:~> ll /mnt/a/
/bin/ls: Zugriff auf /mnt/a/ nicht möglich: Keine Berechtigung
maurerh at rmc-vb56.cluster.robotic.dlr.de:~> klist           
Ticket cache: FILE:/tmp/krb5cc_7740                           
Default principal: maurerh@INTRA.DLR.DE                       

Valid starting     Expires            Service principal
09/01/14 13:43:35  09/01/14 23:43:35  krbtgt/INTRA.DLR.DE@INTRA.DLR.DE
        renew until 09/08/14 13:43:35                                 
09/01/14 13:44:01  09/01/14 23:43:35  nfs/rmc-intra02.robotic.dlr.de@ 
        renew until 09/08/14 13:43:35                                 
09/01/14 13:44:01  09/01/14 23:43:35  nfs/rmc-intra02.robotic.dlr.de@INTRA.DLR.DE
        renew until 09/08/14 13:43:35                                            

End of capture nfsv4_maurerh.cap
Syslog in Client                
[root@rmc-vb56 ~]# Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: handling gssd upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt186)
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: handle_gssd_upcall: 'mech=krb5 uid=7740 enctypes=18,17,16,23,3,1,2 '         
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: handling krb5 upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt186)                   
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: process_krb5_upcall: service is '<null>'                                     
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: getting credentials for client with uid 7740 for server rmc-intra02.robotic.dlr.de
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: handling gssd upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt186)                        
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: handle_gssd_upcall: 'mech=krb5 uid=7740 enctypes=18,17,16,23,3,1,2 '              
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: handling krb5 upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt186)                        
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: process_krb5_upcall: service is '<null>'                                          
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: getting credentials for client with uid 7740 for server rmc-intra02.robotic.dlr.de
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: CC file '/tmp/krb5cc_7740' being considered, with preferred realm 'INTRA.DLR.DE'  
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: CC file '/tmp/krb5cc_7740' being considered, with preferred realm 'INTRA.DLR.DE'  
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: CC file '/tmp/krb5cc_7740'(maurerh@INTRA.DLR.DE) passed all checks and has mtime of 1409572407
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: CC file '/tmp/krb5cc_machine_INTRA.DLR.DE' being considered, with preferred realm 'INTRA.DLR.DE'
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: CC file '/tmp/krb5cc_machine_INTRA.DLR.DE' owned by 0, not 7740                                 
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: using FILE:/tmp/krb5cc_7740 as credentials cache for client with uid 7740 for server rmc-intra02.robotic.dlr.de
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: using environment variable to select krb5 ccache FILE:/tmp/krb5cc_7740                                         
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: creating context using fsuid 7740 (save_uid 0)                                                                 
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: CC file '/tmp/krb5cc_7740'(maurerh@INTRA.DLR.DE) passed all checks and has mtime of 1409572407                 
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: CC file '/tmp/krb5cc_machine_INTRA.DLR.DE' being considered, with preferred realm 'INTRA.DLR.DE'               
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: CC file '/tmp/krb5cc_machine_INTRA.DLR.DE' owned by 0, not 7740                                                
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: using FILE:/tmp/krb5cc_7740 as credentials cache for client with uid 7740 for server rmc-intra02.robotic.dlr.de
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: using environment variable to select krb5 ccache FILE:/tmp/krb5cc_7740                                         
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: creating context using fsuid 7740 (save_uid 0)                                                                 
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: creating tcp client for server rmc-intra02.robotic.dlr.de                                                      
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: DEBUG: port already set to 2049                                                                                
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: creating tcp client for server rmc-intra02.robotic.dlr.de                                                      
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: DEBUG: port already set to 2049                                                                                
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: creating context with server nfs@rmc-intra02.robotic.dlr.de                                                    
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: creating context with server nfs@rmc-intra02.robotic.dlr.de                                                    
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: WARNING: Failed to create krb5 context for user with uid 7740 for server rmc-intra02.robotic.dlr.de            
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: WARNING: Failed to create krb5 context for user with uid 7740 for server rmc-intra02.robotic.dlr.de            
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: WARNING: Failed to create krb5 context for user with uid 7740 for server rmc-intra02.robotic.dlr.de            
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: WARNING: Failed to create krb5 context for user with uid 7740 for server rmc-intra02.robotic.dlr.de            
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: doing error downcall                                                                                           
Sep  1 13:53:51 rmc-vb56 rpc.gssd[1911]: doing error downcall                                                                                           


Start of capture nfsv4_hotel.cap

[hotel@rmc-vb56 ~]$ kinit
Password for hotel@INTRA.DLR.DE:
[hotel@rmc-vb56 ~]$ ll /mnt/a/  
insgesamt 4                     
drwxr-xr-x 6 root root 4096 17. Mai 2013  home_local
[hotel@rmc-vb56 ~]$ ll /mnt/a/home_local/           
insgesamt 36                                        
drwx------ 2 hotel   root  4096 15. Jul 2013  hotel 
drwx------ 2 root    root 16384 19. Nov 2012  lost+found
drwx------ 2 maurerh root  4096 25. Apr 2013  maurerh   
[hotel@rmc-vb56 ~]$ ll /mnt/a/home_local/hotel/         
insgesamt 0                                             
-rw-r--r-- 1 hotel dlr_hotel_p 0 30. Apr 2013  test     
-rw------- 1 hotel dlr_hotel_p 0 15. Jul 2013  test1    
-rw-r--r-- 1 hotel dlr_hotel_p 0 30. Apr 2013  test2    
[hotel@rmc-vb56 ~]$ klist                               
Ticket cache: FILE:/tmp/krb5cc_6252                     
Default principal: hotel@INTRA.DLR.DE                   

Valid starting     Expires            Service principal
09/01/14 13:47:26  09/01/14 23:47:26  krbtgt/INTRA.DLR.DE@INTRA.DLR.DE
        renew until 09/08/14 13:47:26                                 

End of capture nfsv4_hotel.cap
Syslog in Client
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: handle_gssd_upcall: 'mech=krb5 uid=6252 enctypes=18,17,16,23,3,1,2 '
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: handling gssd upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt186)
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: handle_gssd_upcall: 'mech=krb5 uid=6252 enctypes=18,17,16,23,3,1,2 '
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: handling krb5 upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt186)
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: process_krb5_upcall: service is '<null>'
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: getting credentials for client with uid 6252 for server rmc-intra02.robotic.dlr.de
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: CC file '/tmp/krb5cc_6252' being considered, with preferred realm 'INTRA.DLR.DE'
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: handling krb5 upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt186)
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: process_krb5_upcall: service is '<null>'
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: getting credentials for client with uid 6252 for server rmc-intra02.robotic.dlr.de
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: CC file '/tmp/krb5cc_6252' being considered, with preferred realm 'INTRA.DLR.DE'
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: CC file '/tmp/krb5cc_6252'(hotel@INTRA.DLR.DE) passed all checks and has mtime of 1409572519
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: CC file '/tmp/krb5cc_machine_INTRA.DLR.DE' being considered, with preferred realm 'INTRA.DLR.DE'
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: CC file '/tmp/krb5cc_machine_INTRA.DLR.DE' owned by 0, not 6252
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: using FILE:/tmp/krb5cc_6252 as credentials cache for client with uid 6252 for server rmc-intra02.robotic.dlr.de
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: using environment variable to select krb5 ccache FILE:/tmp/krb5cc_6252
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: creating context using fsuid 6252 (save_uid 0)
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: CC file '/tmp/krb5cc_6252'(hotel@INTRA.DLR.DE) passed all checks and has mtime of 1409572519
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: CC file '/tmp/krb5cc_machine_INTRA.DLR.DE' being considered, with preferred realm 'INTRA.DLR.DE'
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: CC file '/tmp/krb5cc_machine_INTRA.DLR.DE' owned by 0, not 6252
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: using FILE:/tmp/krb5cc_6252 as credentials cache for client with uid 6252 for server rmc-intra02.robotic.dlr.de
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: using environment variable to select krb5 ccache FILE:/tmp/krb5cc_6252
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: creating context using fsuid 6252 (save_uid 0)
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: creating tcp client for server rmc-intra02.robotic.dlr.de
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: DEBUG: port already set to 2049
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: creating tcp client for server rmc-intra02.robotic.dlr.de
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: DEBUG: port already set to 2049
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: creating context with server nfs@rmc-intra02.robotic.dlr.de
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: creating context with server nfs@rmc-intra02.robotic.dlr.de
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: DEBUG: serialize_krb5_ctx: lucid version!
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: prepare_krb5_rfc4121_buffer: protocol 1
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: DEBUG: serialize_krb5_ctx: lucid version!
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: prepare_krb5_rfc4121_buffer: protocol 1
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: prepare_krb5_rfc4121_buffer: serializing key with enctype 18 and size 32
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: doing downcall
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: prepare_krb5_rfc4121_buffer: serializing key with enctype 18 and size 32
Sep  1 13:55:32 rmc-vb56 rpc.gssd[1911]: doing downcall

Regrads

Hansjörg
Comment 13 Hansjoerg Maurer 2014-09-01 08:19:11 EDT
Created attachment 933340 [details]
wireshark capture nfsv4_maurerh.cap
Comment 14 Hansjoerg Maurer 2014-09-01 08:19:48 EDT
Created attachment 933341 [details]
wireshark capture nfsv4_hotel.cap
Comment 15 Roland Mainz 2014-09-01 08:22:48 EDT
(In reply to Roland Mainz from comment #11)
> (In reply to Hansjoerg Maurer from comment #9)
> [snip]
> > The tocken size of maurerh (acoount where it fails) (big PAC due to many
> > groups) is 8516 bytes the one of hotel (Testuser where it works) is 1455
> > bytes
> 
> Gut feeling about UDP (just to rule this out, in theory UDP/IPv4 has a
> package size limit of AFAIK 65507 bytes but we should not hit it in our
> case... in theory):
> Do you use TCP or UDP for Krb5 communication ? Do you have any way to force
> TCP-only operation and then test this issue again ?

Grumpf... I hit "Send" to early: There is http://blogs.technet.com/b/shanecothran/archive/2010/07/16/maxtokensize-and-kerberos-token-bloat.aspx which talks about "MaxTokenSize" for Kerberos5 ... so please check whether upgrading this limit and/or TCP connections help... and after that my next guesses revolve around legacy DES keys (see comment #10) ...
Comment 16 Hansjoerg Maurer 2014-09-01 08:36:38 EDT
Hi

> getprinc <working_account>
> getprinc <nonworking_account>


I expect these commands have to be Run on the KDC?
I have no access to the Active Directory Domain Controller.

If you sent me the list of attributes you are interested in, I can provide them

Regards

Hansjörg
Comment 17 Hansjoerg Maurer 2014-09-01 08:37:02 EDT
Hi

I have set
[libdefaults]
 udp_preference_limit = 1

which force communication to tcp (attached nfsv4_maurerh_tcp.cap)
I did it both on server and client, but same error



maurerh at rmc-vb56.cluster.robotic.dlr.de:~> kinit
Password for maurerh@INTRA.DLR.DE:
maurerh at rmc-vb56.cluster.robotic.dlr.de:~> klist
Ticket cache: FILE:/tmp/krb5cc_7740
Default principal: maurerh@INTRA.DLR.DE

Valid starting     Expires            Service principal
09/01/14 14:30:03  09/02/14 00:30:03  krbtgt/INTRA.DLR.DE@INTRA.DLR.DE
        renew until 09/08/14 14:30:03
maurerh at rmc-vb56.cluster.robotic.dlr.de:~> ll /mnt/a/
/bin/ls: Zugriff auf /mnt/a/ nicht möglich: Keine Berechtigung
maurerh at rmc-vb56.cluster.robotic.dlr.de:~> klist
Ticket cache: FILE:/tmp/krb5cc_7740
Default principal: maurerh@INTRA.DLR.DE

Valid starting     Expires            Service principal
09/01/14 14:30:03  09/02/14 00:30:03  krbtgt/INTRA.DLR.DE@INTRA.DLR.DE
        renew until 09/08/14 14:30:03
09/01/14 14:30:42  09/02/14 00:30:03  nfs/rmc-intra02.robotic.dlr.de@
        renew until 09/08/14 14:30:03
09/01/14 14:30:42  09/02/14 00:30:03  nfs/rmc-intra02.robotic.dlr.de@INTRA.DLR.DE
        renew until 09/08/14 14:30:03
Comment 18 Hansjoerg Maurer 2014-09-01 08:38:03 EDT
Created attachment 933346 [details]
wireshark capture nfsv4_maurerh_tcp.cap
Comment 19 Roland Mainz 2014-09-01 08:56:46 EDT
(In reply to Hansjoerg Maurer from comment #16)
> > getprinc <working_account>
> > getprinc <nonworking_account>
> 
> 
> I expect these commands have to be Run on the KDC?
> I have no access to the Active Directory Domain Controller.
> 
> If you sent me the list of attributes you are interested in, I can provide
> them

Typically "getprinc" command output for kadmin/kadmin.local looks like this:
-- snip --
<kadminsh> getprinc fleyta
Principal: fleyta@USERS.NRUBSIG.ORG
Expiration date: [never]
Last password change: Thu Mar 20 22:46:34 CET 2014
Password expiration date: [none]
Maximum ticket life: 0 days 10:00:00
Maximum renewable life: 7 days 00:00:00
Last modified: Thu Mar 20 22:46:34 CET 2014 (root/admin@USERS.NRUBSIG.ORG)
Last successful authentication: [never]
Last failed authentication: [never]
Failed password attempts: 0
Number of keys: 4
Key: vno 5, AES-256 CTS mode with 96-bit SHA-1 HMAC, no salt
Key: vno 5, AES-128 CTS mode with 96-bit SHA-1 HMAC, no salt
Key: vno 5, Triple DES cbc mode with HMAC/sha1, no salt
Key: vno 5, ArcFour with HMAC/md5, no salt
MKey: vno 1
Attributes:
Policy: [none]
-- snip --

The lines with "Key:" are the interesting ones (I once saw a gss problem with an identical error messsage as yours caused by usage of legacy DES keys which one side (either server or client) didn't understand because Kerberos5 versions were nearly a decade out of sync) ...
Comment 20 Hansjoerg Maurer 2014-09-02 09:44:31 EDT
Hi

I am unable to run the kadmin commands against the active directory
I have attached the klist on the creditial cache, where you can see the encryption types


[hotel@rmc-vb56 ~]$ klist -eA
Ticket cache: FILE:/tmp/krb5cc_6252
Default principal: hotel@INTRA.DLR.DE

Valid starting     Expires            Service principal
09/02/14 15:37:10  09/03/14 01:37:10  krbtgt/INTRA.DLR.DE@INTRA.DLR.DE
        renew until 09/09/14 15:37:10, Etype (skey, tkt): arcfour-hmac, aes256-cts-hmac-sha1-96

maurerh at rmc-vb56.cluster.robotic.dlr.de:~> klist -eA
Ticket cache: FILE:/tmp/krb5cc_7740
Default principal: maurerh@INTRA.DLR.DE

Valid starting     Expires            Service principal
09/02/14 15:37:45  09/03/14 01:37:45  krbtgt/INTRA.DLR.DE@INTRA.DLR.DE
        renew until 09/09/14 15:37:45, Etype (skey, tkt): arcfour-hmac, aes256-cts-hmac-sha1-96


User maurerh is in about 60 groups and according to the logs, the tocken size was 8516 bytes. 
Using TCP does not improve the problem
regards

Hansjörg Maurer
Comment 21 Hansjoerg Maurer 2014-09-11 04:47:06 EDT
Hi  

did the same test with two RHEL7 machines with the same result

regards

Hansjörg Maurer
Comment 23 Roland Mainz 2014-11-21 11:19:34 EST
(In reply to Hansjoerg Maurer from comment #0)
[snip]
> The tocken size of maurerh (big PAC due to many groups) is 8516 bytes
> the one of hotel (Testuser where it works) is 1455 bytes
> The Bug with the libtirpc tocken size
> https://bugzilla.redhat.com/show_bug.cgi?format=multiple&id=562807
> should be fixed in this version

Mhhh... there is a design issue of the communication method used between the kernel NFS parts and userland rpc.gssd which limits the possible ticket size to 2k (AFAIK pagesize/2) ... that is fixed in RHEL7.1 if you use gssproxy with NFS. It might be simply that issue (workaround is to reduce the size of the tickets... a real backport of gssproxy support is AFAIK unlikely for RHEL6.x because it would mean to backport a *lot* of fixes (and therefore includes a lot of risk)).
Comment 24 Dmitri Pal 2014-11-21 14:51:29 EST
The issue of large PAC is not fixable in RHEL6. In RHEL7 we introduced GSS proxy that addresses this but it can't be ported back.
Comment 25 Hansjoerg Maurer 2015-03-05 10:56:39 EST
Hi

I did not find gssproxy in the RHEL 7.1 Release Notes
Is gssproxy included in 7.1 and do you have any docmentation
Regrads

Hansjörg
Comment 26 Simo Sorce 2015-03-05 19:45:37 EST
(In reply to Hansjoerg Maurer from comment #25)
> Hi
> 
> I did not find gssproxy in the RHEL 7.1 Release Notes
> Is gssproxy included in 7.1 and do you have any docmentation
> Regrads
> 
> Hansjörg

GSS-Proxy is included in RHEL 7.
RHEL 7.1 has version 0.3.0-10.el7

Documentation is still a little scarce, here you can find some info from the upstream project: https://fedorahosted.org/gss-proxy/

HTH,
Simo
Comment 27 Hansjoerg Maurer 2015-04-21 09:58:29 EDT
Hi

I tried to test it with rhel7.1, but with no success
The mount itself works fine, but accessing the mount point as Active Directory User fails with permission denied.

Client logs:
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: WARNING: Failed to create krb5 context for user with uid 7740 for server rmc-testvm03.robotic.dlr.de

Accessing the share as root works:

I found an ticket on the gssproxy project page, regarding SPN aliases

https://fedorahosted.org/gss-proxy/ticket/134

In AD we  have added an additional nfs/ SPN to the host/ Object of the NFS Server and aliased nfs/ to host/
Could that be the problem?

attached some information and logs

  
NFS-Server: rmc-testvm03
NFS-Client: rmc-testvm04


Keytab on server:
slot KVNO Principal
---- ---- ---------------------------------------------------------------------
   1    2 host/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE
   2    2               RMC-TESTVM03$@INTRA.DLR.DE
   3    2           host/RMC-TESTVM03@INTRA.DLR.DE
   4    2 cifs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE
   5    2           cifs/RMC-TESTVM03@INTRA.DLR.DE
   6    2 host/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE
   7    2               RMC-TESTVM03$@INTRA.DLR.DE
   8    2           host/RMC-TESTVM03@INTRA.DLR.DE
   9    2 cifs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE
  10    2           cifs/RMC-TESTVM03@INTRA.DLR.DE
  11    2 host/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE
  12    2               RMC-TESTVM03$@INTRA.DLR.DE
  13    2           host/RMC-TESTVM03@INTRA.DLR.DE
  14    2 cifs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE
  15    2           cifs/RMC-TESTVM03@INTRA.DLR.DE
  16    2 nfs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE
  17    2 nfs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE
  18    2 nfs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE
  19    3               RMC-TESTVM03$@INTRA.DLR.DE
  20    3 host/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE
  21    3           host/RMC-TESTVM03@INTRA.DLR.DE
  22    3 cifs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE
  23    3           cifs/RMC-TESTVM03@INTRA.DLR.DE
  24    3 nfs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE
  25    3               RMC-TESTVM03$@INTRA.DLR.DE
  26    3 host/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE
  27    3           host/RMC-TESTVM03@INTRA.DLR.DE
  28    3 cifs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE
  29    3           cifs/RMC-TESTVM03@INTRA.DLR.DE
  30    3 nfs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE
  31    3               RMC-TESTVM03$@INTRA.DLR.DE
  32    3 host/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE
  33    3           host/RMC-TESTVM03@INTRA.DLR.DE
  34    3 cifs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE
  35    3           cifs/RMC-TESTVM03@INTRA.DLR.DE
  36    3 nfs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE


Vno  Type                     Principal                                      Date
  2  aes128-cts-hmac-sha1-96  host/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE  2015-04-15
  2  aes128-cts-hmac-sha1-96  RMC-TESTVM03$@INTRA.DLR.DE                     2015-04-15
  2  aes128-cts-hmac-sha1-96  host/RMC-TESTVM03@INTRA.DLR.DE                 2015-04-15
  2  aes128-cts-hmac-sha1-96  cifs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE  2015-04-15
  2  aes128-cts-hmac-sha1-96  cifs/RMC-TESTVM03@INTRA.DLR.DE                 2015-04-15
  2  aes256-cts-hmac-sha1-96  host/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE  2015-04-15
  2  aes256-cts-hmac-sha1-96  RMC-TESTVM03$@INTRA.DLR.DE                     2015-04-15
  2  aes256-cts-hmac-sha1-96  host/RMC-TESTVM03@INTRA.DLR.DE                 2015-04-15
  2  aes256-cts-hmac-sha1-96  cifs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE  2015-04-15
  2  aes256-cts-hmac-sha1-96  cifs/RMC-TESTVM03@INTRA.DLR.DE                 2015-04-15
  2  arcfour-hmac-md5         host/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE  2015-04-15
  2  arcfour-hmac-md5         RMC-TESTVM03$@INTRA.DLR.DE                     2015-04-15
  2  arcfour-hmac-md5         host/RMC-TESTVM03@INTRA.DLR.DE                 2015-04-15
  2  arcfour-hmac-md5         cifs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE  2015-04-15
  2  arcfour-hmac-md5         cifs/RMC-TESTVM03@INTRA.DLR.DE                 2015-04-15
  2  aes128-cts-hmac-sha1-96  nfs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE   2015-04-15
  2  aes256-cts-hmac-sha1-96  nfs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE   2015-04-15
  2  arcfour-hmac-md5         nfs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE   2015-04-15
  3  aes128-cts-hmac-sha1-96  RMC-TESTVM03$@INTRA.DLR.DE                     2015-04-15
  3  aes128-cts-hmac-sha1-96  host/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE  2015-04-15
  3  aes128-cts-hmac-sha1-96  host/RMC-TESTVM03@INTRA.DLR.DE                 2015-04-15
  3  aes128-cts-hmac-sha1-96  cifs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE  2015-04-15
  3  aes128-cts-hmac-sha1-96  cifs/RMC-TESTVM03@INTRA.DLR.DE                 2015-04-15
  3  aes128-cts-hmac-sha1-96  nfs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE   2015-04-15
  3  aes256-cts-hmac-sha1-96  RMC-TESTVM03$@INTRA.DLR.DE                     2015-04-15
  3  aes256-cts-hmac-sha1-96  host/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE  2015-04-15
  3  aes256-cts-hmac-sha1-96  host/RMC-TESTVM03@INTRA.DLR.DE                 2015-04-15
  3  aes256-cts-hmac-sha1-96  cifs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE  2015-04-15
  3  aes256-cts-hmac-sha1-96  cifs/RMC-TESTVM03@INTRA.DLR.DE                 2015-04-15
  3  aes256-cts-hmac-sha1-96  nfs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE   2015-04-15
  3  arcfour-hmac-md5         RMC-TESTVM03$@INTRA.DLR.DE                     2015-04-15
  3  arcfour-hmac-md5         host/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE  2015-04-15
  3  arcfour-hmac-md5         host/RMC-TESTVM03@INTRA.DLR.DE                 2015-04-15
  3  arcfour-hmac-md5         cifs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE  2015-04-15
  3  arcfour-hmac-md5         cifs/RMC-TESTVM03@INTRA.DLR.DE                 2015-04-15
  3  arcfour-hmac-md5         nfs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE   2015-04-15



Crediential cache on Client

maurerh at rmc-testvm04.robotic.dlr.de:~> klist
Ticket cache: FILE:/tmp/krb5cc_7740
Default principal: maurerh@INTRA.DLR.DE

Valid starting       Expires              Service principal
21.04.2015 15:42:42  22.04.2015 01:42:33  krbtgt/INTRA.DLR.DE@INTRA.DLR.DE
        renew until 28.04.2015 15:42:42
21.04.2015 15:42:45  22.04.2015 01:42:33  nfs/rmc-testvm03.robotic.dlr.de@
        renew until 28.04.2015 15:42:42
21.04.2015 15:42:45  22.04.2015 01:42:33  nfs/rmc-testvm03.robotic.dlr.de@INTRA.DLR.DE
        renew until 28.04.2015 15:42:42


Logs accessing as user maurerh:
Client:
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[670]: handling gssd upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt6)
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[670]: handle_gssd_upcall: 'mech=krb5 uid=7740 enctypes=18,17,16,23,3,1,2 '
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: handling krb5 upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt6)
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: process_krb5_upcall: service is '<null>'
Apr 21 15:36:56 rmc-testvm04 gssproxy: Failed to get peer's SELinux context (92:Das Protokoll ist nicht verfügbar)
Apr 21 15:36:56 rmc-testvm04 gssproxy: Client connected (fd = 12) (pid = 4251) (uid = 7740) (gid = 43466)
Apr 21 15:36:56 rmc-testvm04 gssproxy: gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) for service "nfs-client", euid: 7740, socket: (null)
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: creating tcp client for server rmc-testvm03.robotic.dlr.de
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: DEBUG: port already set to 2049
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: creating context with server nfs@rmc-testvm03.robotic.dlr.de
Apr 21 15:36:56 rmc-testvm04 gssproxy: gp_rpc_execute: executing 8 (GSSX_INIT_SEC_CONTEXT) for service "nfs-client", euid: 7740, socket: (null)
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: WARNING: Failed to create krb5 context for user with uid 7740 for server nfs@rmc-testvm03.robotic.dlr.de
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: getting credentials for client with uid 7740 for server rmc-testvm03.robotic.dlr.de
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: CC '/tmp/krb5cc_7740' being considered, with preferred realm 'INTRA.DLR.DE'
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: CC 'FILE:/tmp/krb5cc_7740'(maurerh@INTRA.DLR.DE) passed all checks and has mtime of 1429623416
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: CC '/tmp/krb5cc_6252' being considered, with preferred realm 'INTRA.DLR.DE'
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: CC '/tmp/krb5cc_6252' owned by 6252, not 7740
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: CC '/tmp/krb5ccmachine_INTRA.DLR.DE' being considered, with preferred realm 'INTRA.DLR.DE'
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: CC '/tmp/krb5ccmachine_INTRA.DLR.DE' owned by 0, not 7740
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: using FILE:/tmp/krb5cc_7740 as credentials cache for client with uid 7740 for server rmc-testvm03.robotic.dlr.de
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: using environment variable to select krb5 ccache FILE:/tmp/krb5cc_7740
Apr 21 15:36:56 rmc-testvm04 gssproxy: gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) for service "nfs-client", euid: 7740, socket: (null)
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: creating tcp client for server rmc-testvm03.robotic.dlr.de
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: DEBUG: port already set to 2049
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: creating context with server nfs@rmc-testvm03.robotic.dlr.de
Apr 21 15:36:56 rmc-testvm04 gssproxy: gp_rpc_execute: executing 8 (GSSX_INIT_SEC_CONTEXT) for service "nfs-client", euid: 7740, socket: (null)
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: WARNING: Failed to create krb5 context for user with uid 7740 for server nfs@rmc-testvm03.robotic.dlr.de
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: getting credentials for client with uid 7740 for server rmc-testvm03.robotic.dlr.de
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: Error doing scandir on directory '/run/user/7740': No such file or directory
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: WARNING: Failed to create krb5 context for user with uid 7740 for server rmc-testvm03.robotic.dlr.de
Apr 21 15:36:56 rmc-testvm04 rpc.gssd[4251]: doing error downcall


Server:
Apr 21 15:36:56 rmc-testvm03 gssproxy: gp_rpc_execute: executing 9 (GSSX_ACCEPT_SEC_CONTEXT) for service "nfs-server", euid: 0, socket: /run/gssproxy.sock
Apr 21 15:36:56 rmc-testvm03 gssproxy: gp_rpc_execute: executing 9 (GSSX_ACCEPT_SEC_CONTEXT) for service "nfs-server", euid: 0, socket: /run/gssproxy.sock

Logs when accessing as root:
Client:
Apr 21 15:34:09 rmc-testvm04 rpc.gssd[670]: handling gssd upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt6)
Apr 21 15:34:09 rmc-testvm04 rpc.gssd[670]: handle_gssd_upcall: 'mech=krb5 uid=0 enctypes=18,17,16,23,3,1,2 '
Apr 21 15:34:09 rmc-testvm04 rpc.gssd[4175]: handling krb5 upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt6)
Apr 21 15:34:09 rmc-testvm04 rpc.gssd[4175]: process_krb5_upcall: service is '<null>'
Apr 21 15:34:09 rmc-testvm04 rpc.gssd[4175]: Full hostname for 'rmc-testvm03.robotic.dlr.de' is 'rmc-testvm03.robotic.dlr.de'
Apr 21 15:34:09 rmc-testvm04 rpc.gssd[4175]: Full hostname for 'rmc-testvm04.robotic.dlr.de' is 'rmc-testvm04.robotic.dlr.de'
Apr 21 15:34:09 rmc-testvm04 rpc.gssd[4175]: Success getting keytab entry for 'RMC-TESTVM04$@INTRA.DLR.DE'
Apr 21 15:34:10 rmc-testvm04 rpc.gssd[4175]: Successfully obtained machine credentials for principal 'RMC-TESTVM04$@INTRA.DLR.DE' stored in ccache 'FILE:/tmp/krb5ccmachine_INTRA.DLR.DE'
Apr 21 15:34:10 rmc-testvm04 rpc.gssd[4175]: INFO: Credentials in CC 'FILE:/tmp/krb5ccmachine_INTRA.DLR.DE' are good until 1429659249
Apr 21 15:34:10 rmc-testvm04 rpc.gssd[4175]: using FILE:/tmp/krb5ccmachine_INTRA.DLR.DE as credentials cache for machine creds
Apr 21 15:34:10 rmc-testvm04 rpc.gssd[4175]: using environment variable to select krb5 ccache FILE:/tmp/krb5ccmachine_INTRA.DLR.DE
Apr 21 15:34:10 rmc-testvm04 rpc.gssd[4175]: creating tcp client for server rmc-testvm03.robotic.dlr.de
Apr 21 15:34:10 rmc-testvm04 rpc.gssd[4175]: DEBUG: port already set to 2049
Apr 21 15:34:10 rmc-testvm04 rpc.gssd[4175]: creating context with server nfs@rmc-testvm03.robotic.dlr.de
Apr 21 15:34:10 rmc-testvm04 gssproxy: Failed to get peer's SELinux context (92:Das Protokoll ist nicht verfügbar)
Apr 21 15:34:10 rmc-testvm04 gssproxy: Client connected (fd = 12) (pid = 4175) (uid = 0) (gid = 0)
Apr 21 15:34:10 rmc-testvm04 gssproxy: gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) for service "nfs-client", euid: 0, socket: (null)
Apr 21 15:34:10 rmc-testvm04 gssproxy: gp_rpc_execute: executing 8 (GSSX_INIT_SEC_CONTEXT) for service "nfs-client", euid: 0, socket: (null)
Apr 21 15:34:14 rmc-testvm04 gssproxy: gp_rpc_execute: executing 8 (GSSX_INIT_SEC_CONTEXT) for service "nfs-client", euid: 0, socket: (null)
Apr 21 15:34:14 rmc-testvm04 rpc.gssd[4175]: DEBUG: serialize_krb5_ctx: lucid version!
Apr 21 15:34:14 rmc-testvm04 rpc.gssd[4175]: prepare_krb5_rfc4121_buffer: protocol 1
Apr 21 15:34:14 rmc-testvm04 rpc.gssd[4175]: prepare_krb5_rfc4121_buffer: serializing key with enctype 18 and size 32
Apr 21 15:34:14 rmc-testvm04 rpc.gssd[4175]: doing downcall: lifetime_rec=35994 acceptor=nfs@rmc-testvm03.robotic.dlr.de

Server:
Apr 21 15:34:14 rmc-testvm03 gssproxy: gp_rpc_execute: executing 9 (GSSX_ACCEPT_SEC_CONTEXT) for service "nfs-server", euid: 0, socket: /run/gssproxy.sock
Apr 21 15:34:14 rmc-testvm03 rpc.idmapd[674]: nfsdcb: authbuf=gss/krb5p authtype=user
Apr 21 15:34:14 rmc-testvm03 rpc.idmapd[674]: nfs4_uid_to_name: calling nsswitch->uid_to_name
Apr 21 15:34:14 rmc-testvm03 rpc.idmapd[674]: nfs4_uid_to_name: nsswitch->uid_to_name returned 0
Apr 21 15:34:14 rmc-testvm03 rpc.idmapd[674]: nfs4_uid_to_name: final return value is 0
Apr 21 15:34:14 rmc-testvm03 rpc.idmapd[674]: Server : (user) id "0" -> name "root@INTRA.DLR.DE"
Apr 21 15:34:14 rmc-testvm03 rpc.idmapd[674]: nfsdcb: authbuf=gss/krb5p authtype=group
Apr 21 15:34:14 rmc-testvm03 rpc.idmapd[674]: nfs4_gid_to_name: calling nsswitch->gid_to_name
Apr 21 15:34:14 rmc-testvm03 rpc.idmapd[674]: nfs4_gid_to_name: nsswitch->gid_to_name returned 0
Apr 21 15:34:14 rmc-testvm03 rpc.idmapd[674]: nfs4_gid_to_name: final return value is 0
Apr 21 15:34:14 rmc-testvm03 rpc.idmapd[674]: Server : (group) id "0" -> name "root@INTRA.DLR.DE"

gssproxy.conf on server
[gssproxy]
  debug = true

[service/nfs-server]
  mechs = krb5
  socket = /run/gssproxy.sock
  cred_store = keytab:/etc/krb5.keytab
  cred_store = ccache:FILE:/tmp/krb5cc_%U
#  cred_usage = both
  trusted = yes
  kernel_nfsd = yes
  euid = 0
  debug = true

#[service/nfs-client]
#  mechs = krb5
#  cred_store = keytab:/etc/krb5.keytab
#  #cred_store = ccache:FILE:/tmp/krb5cc_%U
#  cred_store = ccache:FILE:/var/lib/gssproxy/clients/krb5cc_%U
#  cred_store = client_keytab:/var/lib/gssproxy/clients/%U.keytab
#  cred_usage = initiate
#  allow_any_uid = yes
#  impersonate = true
#  euid = 0
#  debug = true


gssproxy.conf on client
[gssproxy]
  debug = true

[service/nfs-server]
  mechs = krb5
  socket = /run/gssproxy.sock
  cred_store = keytab:/etc/krb5.keytab
  trusted = yes
  cred_usage = both
  kernel_nfsd = yes
  euid = 0
  debug = true
  allow_any_uid = yes

[service/nfs-client]
  mechs = krb5
  cred_store = keytab:/etc/krb5.keytab
  cred_store = ccache:FILE:/tmp/krb5cc_%U
  #cred_store = ccache:FILE:/var/lib/gssproxy/clients/krb5cc_%U
  cred_store = client_keytab:/var/lib/gssproxy/clients/%U.keytab
  cred_usage = initiate
  allow_any_uid = yes
  impersonate = true
  euid = 0
  debug = true
Comment 28 Simo Sorce 2015-04-26 18:56:31 EDT
Unless you explicitly configured the client to allow s4u2proxy (you most probably haven't) remove the 'impersonate' option from service/nfs-client.
Also remove the client_keytab option unless you actually grabbed and stored any keytab in /var/lib/gssproxy/clients/ on the client.

You may also want to consider disabling the use of GSS-Proxy on the client side, and use it on the server side only for now.
Comment 29 Hansjoerg Maurer 2015-04-28 08:42:54 EDT
Hi 

thank you for your reply

I modified the gssproxy client section but no sucess

[service/nfs-client]
  mechs = krb5
  cred_store = keytab:/etc/krb5.keytab
  cred_store = ccache:FILE:/tmp/krb5cc_%U
  cred_usage = initiate
  allow_any_uid = yes
  euid = 0
  debug = true


Then I disabled gssproxy on the client
(not straight forward on RHEL7 with systemd dependencies to get 
rpc.gssd and rpc.idmapd running without gssproxy :-)) 

But no success (mount succeeds, access as root succeeds, but access as user maurerh not)
Logs in Client with gssproxy disables on client

Apr 28 14:39:57 rmc-testvm04 rpc.gssd[1440]: handling gssd upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt2)
Apr 28 14:39:57 rmc-testvm04 rpc.gssd[1440]: handle_gssd_upcall: 'mech=krb5 uid=7740 enctypes=18,17,16,23,3,1,2 '
Apr 28 14:39:57 rmc-testvm04 rpc.gssd[1601]: handling krb5 upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt2)
Apr 28 14:39:57 rmc-testvm04 rpc.gssd[1601]: process_krb5_upcall: service is '<null>'
Apr 28 14:39:57 rmc-testvm04 rpc.gssd[1601]: creating tcp client for server rmc-testvm03.robotic.dlr.de
Apr 28 14:39:57 rmc-testvm04 rpc.gssd[1601]: DEBUG: port already set to 2049
Apr 28 14:39:57 rmc-testvm04 rpc.gssd[1601]: creating context with server nfs@rmc-testvm03.robotic.dlr.de
Apr 28 14:40:00 rmc-testvm04 rpc.gssd[1601]: WARNING: Failed to create krb5 context for user with uid 7740 for server nfs@rmc-testvm03.robotic.dlr.de
Apr 28 14:40:00 rmc-testvm04 rpc.gssd[1601]: getting credentials for client with uid 7740 for server rmc-testvm03.robotic.dlr.de
Apr 28 14:40:00 rmc-testvm04 rpc.gssd[1601]: CC '/tmp/krb5cc_7740' being considered, with preferred realm 'INTRA.DLR.DE'
Apr 28 14:40:00 rmc-testvm04 rpc.gssd[1601]: CC 'FILE:/tmp/krb5cc_7740'(maurerh@INTRA.DLR.DE) passed all checks and has mtime of 1430224800
Apr 28 14:40:00 rmc-testvm04 rpc.gssd[1601]: CC '/tmp/krb5ccmachine_INTRA.DLR.DE' being considered, with preferred realm 'INTRA.DLR.DE'
Apr 28 14:40:00 rmc-testvm04 rpc.gssd[1601]: CC '/tmp/krb5ccmachine_INTRA.DLR.DE' owned by 0, not 7740
Apr 28 14:40:00 rmc-testvm04 rpc.gssd[1601]: using FILE:/tmp/krb5cc_7740 as credentials cache for client with uid 7740 for server rmc-testvm03.robotic.dlr.de
Apr 28 14:40:00 rmc-testvm04 rpc.gssd[1601]: using environment variable to select krb5 ccache FILE:/tmp/krb5cc_7740
Apr 28 14:40:00 rmc-testvm04 rpc.gssd[1601]: creating tcp client for server rmc-testvm03.robotic.dlr.de
Apr 28 14:40:00 rmc-testvm04 rpc.gssd[1601]: DEBUG: port already set to 2049
Apr 28 14:40:00 rmc-testvm04 rpc.gssd[1601]: creating context with server nfs@rmc-testvm03.robotic.dlr.de
Apr 28 14:40:00 rmc-testvm04 rpc.gssd[1601]: WARNING: Failed to create krb5 context for user with uid 7740 for server nfs@rmc-testvm03.robotic.dlr.de
Apr 28 14:40:00 rmc-testvm04 rpc.gssd[1601]: getting credentials for client with uid 7740 for server rmc-testvm03.robotic.dlr.de
Apr 28 14:40:00 rmc-testvm04 rpc.gssd[1601]: Error doing scandir on directory '/run/user/7740': No such file or directory
Apr 28 14:40:00 rmc-testvm04 rpc.gssd[1601]: WARNING: Failed to create krb5 context for user with uid 7740 for server rmc-testvm03.robotic.dlr.de
Apr 28 14:40:00 rmc-testvm04 rpc.gssd[1601]: doing error downcall
Apr 28 14:40:01 rmc-testvm04 systemd: Starting Session 3 of user root.
Apr 28 14:40:01 rmc-testvm04 systemd: Started Session 3 of user root.


Log on server 


Apr 28 14:40:00 rmc-testvm03 gssproxy: gp_rpc_execute: executing 9 (GSSX_ACCEPT_SEC_CONTEXT) for service "nfs-server", euid: 0, socket: /run/gssproxy.sock
Apr 28 14:40:00 rmc-testvm03 gssproxy: gp_rpc_execute: executing 9 (GSSX_ACCEPT_SEC_CONTEXT) for service "nfs-server", euid: 0, socket: /run/gssproxy.sock


Regards

Hansjörg

Note You need to log in before you can comment on or make changes to this bug.