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

Wed Mar 6 15:16:21 UTC 2013

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On 03/06/2013 08:30 PM, Dale Macartney wrote:
> 
> 
> On 03/06/2013 02:46 PM, M.R Niranjan wrote:
>> On 03/06/2013 08:03 PM, Johan Petersson wrote:
>> > 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.
> 
> 
>> > _______________________________________________
>> > Freeipa-users mailing list
>> > Freeipa-users at redhat.com
>> > https://www.redhat.com/mailman/listinfo/freeipa-users
> 
>> Can you check if the below article helps:
> 
> 
> http://www.freeipa.org/page/Dovecot_IMAPS_Integration_with_FreeIPA_using_Single_Sign_On
> 
> There is a caveat to that article. Not sure if you remember where we got
> up to with that Niranjan, but basically authentication kept failing for
> ipa users if the user's mail spool was not already present.
> 
It's been a while i touched upon that, please do keep mail spool on the
checklist. Thanks Dale for reminding.

> Just keep that in mind if you manage to get that far.
> 
> Dale
> 
> 
>> _______________________________________________
>> Freeipa-users mailing list
>> Freeipa-users at redhat.com
>> https://www.redhat.com/mailman/listinfo/freeipa-users
> 
> 
> 
> 
> _______________________________________________
> Freeipa-users mailing list
> Freeipa-users at redhat.com
> https://www.redhat.com/mailman/listinfo/freeipa-users
> 

- -- 
Regards
M.R.Niranjan
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.13 (GNU/Linux)
Comment: Using GnuPG with undefined - http://www.enigmail.net/

iEYEARECAAYFAlE3XcUACgkQLu3FX2BHx8d8wQCgg7dSrT5PwDeOOMTjtanWmM95
AmUAnjf8dCvrBGTGY8tBye4xQBf1z7OO
=m7hq
-----END PGP SIGNATURE-----