[Freeipa-users] Errors when trying IPA,Dovecot GSSAPI.

Wed Mar 6 14:33:54 UTC 2013

Hi,
I hope someone here can shed some light on what is wrong in my test environment.
The error seem to be that Dovecot on mail server wants to access mail folder in my home directory  on the NFS Server but can't get credentials for it. rpc.gssd on Mail Server try either to open a cachefile in /tmp that is corrupt or expired or if no cache file exists it just do error downcall.
No try to update the key or create a new one.
Should not forwardable tickets update the cache or generate a new one?
The permission denied error in maillog i believe is because of no valid kerberos credentials.

IPAserver
NFS Server for Home Directory through autofs, IPA Client with nfs/share.test.net
Mail server IPA Client with imap/mail.test.net,smtp/mail.test.net

Clients pc's that are also IPA clients

Everything is Red Hat 6.4 server and Client with default settings for IPA server and client.

When trying to get mail i get ticket not accepted but i do get a imap ticket that i can see with klist.

Ticket cache: FILE:/tmp/krb5cc_1644800003_UsqtSh
Default principal: johan at TEST.NET

Valid starting     Expires            Service principal
03/06/13 14:34:28  03/07/13 14:34:28  krbtgt/TEST.NET at TEST.NET
03/06/13 14:40:41  03/07/13 14:34:28  imap/mail.test.net at TEST.NET
03/06/13 14:44:43  03/07/13 14:34:28  host/share.test.net at TEST.NET

Hopefully relevant logs:

Mail Server /var/log/messages with rpc.gssapi -vvv:

Mar  6 14:43:21 mail rpc.gssd[1143]: handling gssd upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt12)
Mar  6 14:43:21 mail rpc.gssd[1143]: handle_gssd_upcall: 'mech=krb5 uid=1644800003 enctypes=18,17,16,23,3,1,2 '
Mar  6 14:43:21 mail rpc.gssd[1143]: handling krb5 upcall (/var/lib/nfs/rpc_pipefs/nfs/clnt12)
Mar  6 14:43:21 mail rpc.gssd[1143]: process_krb5_upcall: service is '<null>'
Mar  6 14:43:21 mail rpc.gssd[1143]: getting credentials for client with uid 1644800003 for server share.test.net
Mar  6 14:43:21 mail rpc.gssd[1143]: CC file '/tmp/krb5cc_machine_TEST.NET' being considered, with preferred realm 'TEST.NET'
Mar  6 14:43:21 mail rpc.gssd[1143]: CC file '/tmp/krb5cc_machine_TEST.NET' owned by 0, not 1644800003
Mar  6 14:43:21 mail rpc.gssd[1143]: CC file '/tmp/krb5cc_1644800001_MOFHds' being considered, with preferred realm 'TEST.NET'
Mar  6 14:43:21 mail rpc.gssd[1143]: CC file '/tmp/krb5cc_1644800001_MOFHds' owned by 0, not 1644800003
Mar  6 14:43:21 mail rpc.gssd[1143]: CC file '/tmp/krb5cc_0' being considered, with preferred realm 'TEST.NET'
Mar  6 14:43:21 mail rpc.gssd[1143]: CC file '/tmp/krb5cc_0' owned by 0, not 1644800003
Mar  6 14:43:21 mail rpc.gssd[1143]: WARNING: Failed to create krb5 context for user with uid 1644800003 for server share.test.net
Mar  6 14:43:21 mail rpc.gssd[1143]: doing error downcall

Mail Server /var/log/maillog:

Mar 06 14:43:11 master: Info: Dovecot v2.0.9 starting up (core dumps disabled)
Mar 06 14:43:21 auth: Debug: Loading modules from directory: /usr/lib64/dovecot/auth
Mar 06 14:43:21 auth: Debug: Module loaded: /usr/lib64/dovecot/auth/libauthdb_ldap.so
Mar 06 14:43:21 auth: Debug: Module loaded: /usr/lib64/dovecot/auth/libdriver_sqlite.so
Mar 06 14:43:21 auth: Debug: Module loaded: /usr/lib64/dovecot/auth/libmech_gssapi.so
Mar 06 14:43:21 auth: Debug: auth client connected (pid=2183)
Mar 06 14:43:21 auth: Debug: client in: AUTH    1       GSSAPI  service=imap    secured lip=192.168.0.33        rip=192.168.0.202       lport=143       rport=36424
Mar 06 14:43:21 auth: Debug: gssapi(?,192.168.0.202): Using all keytab entries
Mar 06 14:43:21 auth: Debug: client out: CONT   1
Mar 06 14:43:21 auth: Debug: client in: CONT<hidden>
Mar 06 14:43:21 auth: Debug: gssapi(johan at TEST.NET,192.168.0.202): security context state completed.
Mar 06 14:43:21 auth: Debug: client out: CONT   1       YIGZBgkqhkiG9xIBAgICAG+BiTCBhqADAgEFoQMCAQ+iejB4oAMCARKicQRv1MwL+M8NJprfWznLmhNSKz2ONwOwvw+2nJkIlLZiRLgIfQECmsAnkj6v54ukCkFNkcl0eCKTuHX9/8CTSpBQZL0RpeHHqfqMDDVRtKuiVaK7DzFOf/RC2ZTKmRD4l54p4PF5KA39L3VTNbkKhsIN
Mar 06 14:43:21 auth: Debug: client in: CONT<hidden>
Mar 06 14:43:21 auth: Debug: gssapi(johan at TEST.NET,192.168.0.202): Negotiated security layer
Mar 06 14:43:21 auth: Debug: client out: CONT   1       BQQF/wAMAAAAAAAAN4/a0gH///+o8Mw0PdRlusfHcCo=
Mar 06 14:43:21 auth: Debug: client in: CONT<hidden>
Mar 06 14:43:21 auth: Debug: client out: OK     1       user=johan
Mar 06 14:43:21 auth: Debug: master in: REQUEST 1818361857      2183    1       2f9e416bebaaac9a0a3f266165753c1b
Mar 06 14:43:21 auth: Debug: passwd(johan,192.168.0.202): lookup
Mar 06 14:43:21 auth: Debug: master out: USER   1818361857      johan   system_groups_user=johan        uid=1644800003  gid=1644800003  home=/nethome/johan
Mar 06 14:43:21 imap-login: Info: Login: user=<johan>, method=GSSAPI, rip=192.168.0.202, lip=192.168.0.33, mpid=2186, TLS
Mar 06 14:43:21 imap(johan): Error: chdir(/nethome/johan/) failed: Permission denied (euid=1644800003(johan) egid=1644800003(johan) missing +x perm: /nethome/johan, euid is not dir owner)
Mar 06 14:43:21 imap(johan): Error: chdir(/nethome/johan) failed: Permission denied
Mar 06 14:43:21 imap(johan): Error: user johan: Initialization failed: Initializing mail storage from mail_location setting failed: stat(/nethome/johan/mail) failed: Permission denied (euid=1644800003(johan) egid=1644800003(johan) missing +x perm: /nethome/johan, euid is not dir owner)
Mar 06 14:43:21 imap(johan): Error: Invalid user settings. Refer to server log for more information.

NFS Server /var/log/messages with rpc.svcgssd -vvv:

Mar  6 14:43:21 share rpc.svcgssd[17422]: handling null request
Mar  6 14:43:21 share rpc.svcgssd[17422]: svcgssd_limit_krb5_enctypes: Calling gss_set_allowable_enctypes with 7 enctypes from the kernel
Mar  6 14:43:21 share rpc.svcgssd[17422]: sname = nfs/mail.test.net at TEST.NET
Mar  6 14:43:21 share rpc.svcgssd[17422]: DEBUG: serialize_krb5_ctx: lucid version!
Mar  6 14:43:21 share rpc.svcgssd[17422]: prepare_krb5_rfc4121_buffer: protocol 1
Mar  6 14:43:21 share rpc.svcgssd[17422]: prepare_krb5_rfc4121_buffer: serializing key with enctype 18 and size 32
Mar  6 14:43:21 share rpc.svcgssd[17422]: doing downcall
Mar  6 14:43:21 share rpc.svcgssd[17422]: mech: krb5, hndl len: 4, ctx len 52, timeout: 1362657132 (79731 from now), clnt: nfs at mail.test.net, uid: -1, gid: -1, num aux grps: 0:
Mar  6 14:43:21 share rpc.svcgssd[17422]: sending null reply
Mar  6 14:43:21 share rpc.svcgssd[17422]: writing message: \x \x6082026406092a864886f71201020201006e8202533082024fa003020105a10302010ea20703050020000000a382015d6182015930820155a003020105a10a1b08544553542e4e4554a220301ea003020103a11730151b036e66731b0e73686172652e746573742e6e6574a382011e3082011aa003020112a103020101a282010c048201080bd88fab1779cae6f283c843e375c2771728abafc384c52f50cc7b2af86583170f495fd96ad3665acb035e08fdac19c820c8ed16fa1120409d165b7eec74e418c11f3d24601c6ad2ee752185f20b4c9667a52dd8e11485e2aef2d5f7fd3ae6991d097e303287e5627f83dc514bca1932262dfa0df4836d55541a6dbce88cc88678cb037acdeada894dc4f3c0dbeaf7f157c9d57e6193ed3ca917f467b17291b4661742f6755a73c8c2b6b9d2b23334ee1cc3b108ee3d825db5edd042c7f9441afe76422f69c400620160fe415e28cdbe9637ca20062cad2999a453c4c4e4e694577bb7f861db6071759a4a0692ce0988fe9c6bdae423f04d22c8f5090d0f76ce235db4ceb9fe13fca481d83081d5a003020112a281cd0481ca1eb49a3eb4c68ce63349590168de47cd5af0bdcaa8a21434f3cbba3ec41a4469bae62d4dd65d037d6c02fcb0a24ff9679a22ab7ffd48857ea7b72f12ab3776c8d28b
27a985a0fa53bfc162da8fda7e8ca49a2e57093f2af0bc4d2a4148420aa1bacb8f7bc4313650060ccae01426ff752405aab2f52ed332f0ac5e670e0013acf9acef23e0e1e5beb85b497d506526aed62a0718377d7e360ce9d5ddf812d02839daa6ee62887e0370a63a49f0345f2eb0d4f9f069c983ed0c63cec039e97378d5abe4eeb214c2e735af 1362577461 0 0 \xbc000000 \x60819906092a864886f71201020202006f8189308186a003020105a10302010fa27a3078a003020112a271046f598391477156abf0dce0a5d58927fc329174a95f47e0dbfb6ab9e77937ba24047c50beafed6bff70e4d133c6304bfb8b47e48b3c17b87ff5a3f44095ab138804a821c155e80410d0f8ec1e663416e935b50c1a90b030d828d7d6c9d2199a46193a04fb32dbd88f18984d5913a3bc60
Mar  6 14:43:21 share rpc.svcgssd[17422]: finished handling null request
Mar  6 14:43:21 share rpc.svcgssd[17422]: entering poll

IPA Server /var/log/dirsrv/slapd-TEST-NET/access:

[06/Mar/2013:14:43:21 +0100] conn=1273 fd=70 slot=70 connection from 192.168.0.33 to 192.168.0.30
[06/Mar/2013:14:43:21 +0100] conn=1273 op=0 BIND dn="" method=sasl version=3 mech=GSSAPI
[06/Mar/2013:14:43:21 +0100] conn=1273 op=0 RESULT err=14 tag=97 nentries=0 etime=0, SASL bind in progress
[06/Mar/2013:14:43:21 +0100] conn=1273 op=1 BIND dn="" method=sasl version=3 mech=GSSAPI
[06/Mar/2013:14:43:21 +0100] conn=1273 op=1 RESULT err=14 tag=97 nentries=0 etime=0, SASL bind in progress
[06/Mar/2013:14:43:21 +0100] conn=1273 op=2 BIND dn="" method=sasl version=3 mech=GSSAPI
[06/Mar/2013:14:43:21 +0100] conn=1273 op=2 RESULT err=0 tag=97 nentries=0 etime=0 dn="fqdn=mail.test.net,cn=computers,cn=accounts,dc=test,dc=net"
[06/Mar/2013:14:43:21 +0100] conn=1273 op=3 SRCH base="automountmapname=auto_nethome,cn=default,cn=automount,dc=test,dc=net" scope=2 filter="(&(objectClass=automount)(|(automountKey=johan)(automountKey=/)(automountKey=\2a)))" attrs="automountKey automountInformation"
[06/Mar/2013:14:43:21 +0100] conn=1273 op=3 RESULT err=0 tag=101 nentries=1 etime=0
[06/Mar/2013:14:43:21 +0100] conn=1273 op=4 UNBIND
[06/Mar/2013:14:43:21 +0100] conn=1273 op=4 fd=70 closed - U1
[06/Mar/2013:14:43:21 +0100] conn=1270 op=16 SRCH base="cn=accounts,dc=test,dc=net" scope=2 filter="(&(uid=nfs/mail.test.net)(objectClass=posixAccount))" attrs="objectClass uid userPassword uidNumber gidNumber gecos homeDirectory loginShell krbPrincipalName cn memberOf nsUniqueId modifyTimestamp entryusn shadowLastChange shadowMin shadowMax shadowWarning shadowInactive shadowExpire shadowFlag krbLastPwdChange krbPasswordExpiration pwdattribute authorizedService accountexpires useraccountcontrol nsAccountLock host logindisabled loginexpirationtime loginallowedtimemap ipaSshPubKey"
[06/Mar/2013:14:43:21 +0100] conn=1270 op=16 RESULT err=0 tag=101 nentries=0 etime=0

Regards,
Johan.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://listman.redhat.com/archives/freeipa-users/attachments/20130306/77ab221e/attachment.htm>