1414302 – gssproxy does not managing its credential cache properly

RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 1414302 - gssproxy does not managing its credential cache properly

Summary: gssproxy does not managing its credential cache properly

Keywords:
Status:	CLOSED DUPLICATE of bug 1292487
Alias:	None
Product:	Red Hat Enterprise Linux 7
Classification:	Red Hat
Component:	gssproxy
Sub Component:
Version:	7.3
Hardware:	x86_64
OS:	Linux
Priority:	unspecified
Severity:	medium
Target Milestone:	rc
Target Release:	---
Assignee:	Robbie Harwood
QA Contact:	Kaleem
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2017-01-18 09:31 UTC by Andrey Bondarenko
Modified:	2020-02-14 18:29 UTC (History)
CC List:	4 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2017-01-27 21:13:48 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Comment 1 Andrey Bondarenko 2017-01-18 09:55:35 UTC

Description of problem:
As root, we try to read a file on a secure nfs mount, and it works as expected:

# klist -c krb5ccmachine_example.com
Ticket cache: FILE:krb5ccmachine_example.com
Default principal: host/a301-7026-8431.ldn.example.com

Valid starting       Expires              Service principal
01/13/2017 08:43:58  01/14/2017 08:43:58  krbtgt/example.com
        renew until 01/20/2017 08:43:58
# cat /home/soleng/secret
You Win! You are reading this file securely!
# klist -c krb5ccmachine_example.com
Ticket cache: FILE:krb5ccmachine_example.com
Default principal: host/a301-7026-8431.ldn.example.com

Valid starting       Expires              Service principal
01/13/2017 08:43:58  01/14/2017 08:43:58  krbtgt/example.com
        renew until 01/20/2017 08:43:58
01/13/2017 10:15:00  01/13/2017 20:15:00  nfs/dldn6008nfs.ldn.example.com
        renew until 01/20/2017 08:43:58
# mount | grep /home/soleng
elured:/vol/home/soleng on /home/soleng type nfs 
(rw,nosuid,relatime,vers=3,rsize=65536,wsize=65536,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=krb5,mountaddr=10.10.130.119,mountvers=3,mountport=4046,mountproto=udp,local_lock=none,addr=10.10.130.119)
# getent hosts elured
10.10.130.119   dldn6008nfs.ldn.example.com elured.ldn.example.com

So, no problems there.

Becoming the unieng user and testing the keytab:

# su - unieng
$ klist -k /var/spool/keytabs/unieng/keytab
Keytab name: FILE:/var/spool/keytabs/unieng/keytab
KVNO Principal
---- --------------------------------------------------------------------------
   2 unieng/a301-7026-8431.ldn.example.com
   2 unieng/a301-7026-8431.ldn.example.com
   2 unieng/a301-7026-8431.ldn.example.com
   2 unieng/a301-7026-8431.ldn.example.com

$ kinit -k -t  /var/spool/keytabs/unieng/keytab -c /tmp/kccunieng unieng/a301-7026-8431.ldn.example.com
$ klist -c /tmp/kccunieng
Ticket cache: FILE:/tmp/kccunieng
Default principal: unieng/a301-7026-8431.ldn.example.com

Valid starting       Expires              Service principal
01/13/2017 10:26:48  01/14/2017 10:26:48  krbtgt/example.com
        renew until 01/20/2017 10:26:48

NB: this ccache is NOT used by gssproxy! gssproxy is supposed to obtain the credentials for unieng as soon as a secure nfs operation 
is attempted.

unieng tries to read a file on a secure nfs mount with the valid keytab and it fails:

$ cat /home/soleng/secret
cat: /home/soleng/secret: Permission denied

Looking at the gssproxy configuration:

# cat /etc/gssproxy/gssproxy.conf
[gssproxy]

[service/HTTP]
  mechs = krb5
  cred_store = keytab:/etc/gssproxy/http.keytab
  cred_store = ccache:/var/lib/gssproxy/clients/krb5cc_%U
  euid = 48

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

[service/nfs-client]
  mechs = krb5
  cred_store = keytab:/etc/krb5.keytab
  cred_store = ccache:FILE:/var/lib/gssproxy/clients/krb5cc_%U
  cred_store = client_keytab:/var/spool/keytabs/%u/keytab
  cred_usage = initiate
  allow_any_uid = yes
  trusted = yes
  euid = 0

Checking for a unieng ccache, there's nothing there:

# ls /var/lib/gssproxy/clients/krb5cc_*
ls: cannot access /var/lib/gssproxy/clients/krb5cc_*: No such file or directory

The messages file says:
Jan 13 10:18:28 a301-7026-8431 gssproxy: gssproxy[979]: (OID: { 1 2 840 113554 1 2 2 }) Unspecified GSS failure.  Minor code may 
provide more information, No credentials cache found

and in case it matters:

# getenforce
Permissive
$ rpm -q krb5-libs
krb5-libs-1.14.1-26.el7.x86_64


here's a gssproxy strace of a failed secure nfs access attempt by unieng. Note that is seems to completely ignore the unieng 
keytab and ccache. It *should* be opening /var/lib/gssproxy/clients/krb5cc_4767, but instead looks for 
/var/lib/gssproxy/clients/krb5cc_0

# cat /tmp/gssproxy.strace
Process 979 attached with 6 threads
[pid   984] futex(0xb8c3e4, FUTEX_WAIT_PRIVATE, 393, NULL <unfinished ...>
[pid   983] futex(0xb8c0e4, FUTEX_WAIT_PRIVATE, 1, NULL <unfinished ...>
[pid   982] futex(0xb8bde4, FUTEX_WAIT_PRIVATE, 1, NULL <unfinished ...>
[pid   981] futex(0xb8bae4, FUTEX_WAIT_PRIVATE, 1, NULL <unfinished ...>
[pid   980] futex(0xb8b7e4, FUTEX_WAIT_PRIVATE, 1, NULL <unfinished ...>
[pid   979] epoll_wait(5, {}, 1, 30000) = 0
[pid   979] epoll_wait(5, {}, 1, 30000) = 0
[pid   979] epoll_wait(5, {{EPOLLIN, {u32=12111552, u64=12111552}}}, 1, 30000) = 1
[pid   979] read(12, "\200\0\0t", 4)    = 4
[pid   979] read(12, "8\235\267\211\0\0\0\0\0\0\0\2\0\6\32\360\0\0\0\1\0\0\0\6\0\0\0\0\0\0\0\0"..., 116) = 116
[pid   979] futex(0xb8c3e4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0xb8c3e0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...>
[pid   984] <... futex resumed> )       = 0
[pid   979] <... futex resumed> )       = 1
[pid   984] futex(0xb8c3b8, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid   979] futex(0xb8c3b8, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid   984] <... futex resumed> )       = -1 EAGAIN (Resource temporarily unavailable)
[pid   979] <... futex resumed> )       = 0
[pid   984] futex(0xb8c3b8, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid   979] epoll_ctl(5, EPOLL_CTL_DEL, 12, {0, {u32=0, u64=0}} <unfinished ...>
[pid   984] <... futex resumed> )       = 0
[pid   979] <... epoll_ctl resumed> )   = 0
[pid   984] open("/etc/passwd", O_RDONLY|O_CLOEXEC <unfinished ...>
[pid   979] epoll_wait(5,  <unfinished ...>
[pid   984] <... open resumed> )        = 13
[pid   984] fstat(13, {st_mode=S_IFREG|0644, st_size=1523, ...}) = 0
[pid   984] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd0aa186000
[pid   984] read(13, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1523
[pid   984] close(13)                   = 0
[pid   984] munmap(0x7fd0aa186000, 4096) = 0
[pid   984] access("/etc/krb5.conf", R_OK) = 0
[pid   984] stat("/etc/krb5.conf", {st_mode=S_IFREG|0644, st_size=941, ...}) = 0
[pid   984] open("/dev/urandom", O_RDONLY) = 13
[pid   984] fcntl(13, F_SETFD, FD_CLOEXEC) = 0
[pid   984] fstat(13, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 9), ...}) = 0
[pid   984] read(13, "\10\3443\33\216|\226,\355>=\231\17\232\266\202\250\336;\233\16\0004\344\31C\203\201T\207\336\265"..., 64) = 64
[pid   984] close(13)                   = 0
[pid   984] open("/var/lib/gssproxy/clients/krb5cc_0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
[pid   984] open("/var/spool/keytabs/root/keytab", O_RDONLY) = -1 ENOENT (No such file or directory)
[pid   984] writev(2, [{"gssproxy[979]: (OID: { 1 2 840 1"..., 141}], 1) = 141
[pid   984] sendto(3, "<83>Jan 13 10:43:49 gssproxy[979"..., 161, MSG_NOSIGNAL, NULL, 0) = 161
[pid   984] write(10, "\0", 1)          = 1
[pid   979] <... epoll_wait resumed> {{EPOLLIN, {u32=12109648, u64=12109648}}}, 1, 30000) = 1
[pid   984] futex(0xb8c3e4, FUTEX_WAIT_PRIVATE, 395, NULL <unfinished ...>
[pid   979] read(4, "\0", 1)            = 1
[pid   979] epoll_ctl(5, EPOLL_CTL_ADD, 12, {EPOLLOUT|EPOLLERR|EPOLLHUP, {u32=12110992, u64=12110992}}) = 0
[pid   979] epoll_wait(5, {{EPOLLOUT, {u32=12110992, u64=12110992}}}, 1, 30000) = 1
[pid   979] writev(12, [{"\200\0\0\260", 4}, {"8\235\267\211\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\r\0\0"..., 176}], 2) = 
180
[pid   979] epoll_ctl(5, EPOLL_CTL_ADD, 12, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=12111552, u64=12111552}}) = -1 EEXIST (File exists)
[pid   979] epoll_ctl(5, EPOLL_CTL_MOD, 12, {EPOLLIN|EPOLLOUT|EPOLLERR|EPOLLHUP, {u32=12110992, u64=12110992}}) = 0
[pid   979] epoll_ctl(5, EPOLL_CTL_MOD, 12, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=12111552, u64=12111552}}) = 0
[pid   979] epoll_wait(5, {{EPOLLIN, {u32=12111552, u64=12111552}}}, 1, 30000) = 1
[pid   979] read(12, "\200\0\0t", 4)    = 4
[pid   979] read(12, "8\235\267\212\0\0\0\0\0\0\0\2\0\6\32\360\0\0\0\1\0\0\0\6\0\0\0\0\0\0\0\0"..., 116) = 116
[pid   979] futex(0xb8c3e4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0xb8c3e0, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
[pid   979] epoll_ctl(5, EPOLL_CTL_DEL, 12, {0, {u32=0, u64=0}}) = 0
[pid   979] epoll_wait(5,  <unfinished ...>
[pid   984] <... futex resumed> )       = 0
[pid   984] futex(0xb8c3b8, FUTEX_WAKE_PRIVATE, 1) = 0
[pid   984] open("/etc/passwd", O_RDONLY|O_CLOEXEC) = 13
[pid   984] fstat(13, {st_mode=S_IFREG|0644, st_size=1523, ...}) = 0
[pid   984] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fd0aa186000
[pid   984] read(13, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1523
[pid   984] close(13)                   = 0
[pid   984] munmap(0x7fd0aa186000, 4096) = 0
[pid   984] access("/etc/krb5.conf", R_OK) = 0
[pid   984] stat("/etc/krb5.conf", {st_mode=S_IFREG|0644, st_size=941, ...}) = 0
[pid   984] open("/dev/urandom", O_RDONLY) = 13
[pid   984] fcntl(13, F_SETFD, FD_CLOEXEC) = 0
[pid   984] fstat(13, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 9), ...}) = 0
[pid   984] read(13, "c\0230\355_\241&}\257\200f\353\301\225\203F\376/\317\2555tO\205\351\266X\263~\211b\345"..., 64) = 64
[pid   984] close(13)                   = 0
[pid   984] open("/var/lib/gssproxy/clients/krb5cc_0", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
[pid   984] open("/var/spool/keytabs/root/keytab", O_RDONLY) = -1 ENOENT (No such file or directory)
[pid   984] writev(2, [{"gssproxy[979]: (OID: { 1 2 840 1"..., 141}], 1) = 141
[pid   984] sendto(3, "<83>Jan 13 10:43:49 gssproxy[979"..., 161, MSG_NOSIGNAL, NULL, 0) = 161
[pid   984] write(10, "\0", 1)          = 1
[pid   979] <... epoll_wait resumed> {{EPOLLIN, {u32=12109648, u64=12109648}}}, 1, 30000) = 1
[pid   984] futex(0xb8c3e4, FUTEX_WAIT_PRIVATE, 397, NULL <unfinished ...>
[pid   979] read(4, "\0", 1)            = 1
[pid   979] epoll_ctl(5, EPOLL_CTL_ADD, 12, {EPOLLOUT|EPOLLERR|EPOLLHUP, {u32=12110992, u64=12110992}}) = 0
[pid   979] epoll_wait(5, {{EPOLLOUT, {u32=12110992, u64=12110992}}}, 1, 30000) = 1
[pid   979] writev(12, [{"\200\0\0\260", 4}, {"8\235\267\212\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\r\0\0"..., 176}], 2) = 
180
[pid   979] epoll_ctl(5, EPOLL_CTL_ADD, 12, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=12111552, u64=12111552}}) = -1 EEXIST (File exists)
[pid   979] epoll_ctl(5, EPOLL_CTL_MOD, 12, {EPOLLIN|EPOLLOUT|EPOLLERR|EPOLLHUP, {u32=12110992, u64=12110992}}) = 0
[pid   979] epoll_ctl(5, EPOLL_CTL_MOD, 12, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=12111552, u64=12111552}}) = 0
[pid   979] epoll_wait(5,

If we downgrade the krb5-workstation to 1.13.2 & restart gssproxy things seem to work:

# klist -V
Kerberos 5 version 1.13.2
# su - unieng
Last login: Fri Jan 13 10:43:44 EST 2017 on pts/2
$ cat /home/soleng/secret
cat: /home/soleng/secret: Permission denied
$ exit
# ls /var/lib/gssproxy/clients/krb5cc_*
ls: cannot access /var/lib/gssproxy/clients/krb5cc_*: No such file or directory
# systemctl restart gssproxy
# su - unieng
Last login: Fri Jan 13 17:52:31 EST 2017 on pts/0
$ cat /home/soleng/secret
You Win! You are reading this file securely!
$ exit
# klist -c /var/lib/gssproxy/clients/krb5cc_4767
Ticket cache: FILE:/var/lib/gssproxy/clients/krb5cc_4767
Default principal: unieng/a301-7026-8431.ldn.example.com

Valid starting       Expires              Service principal
01/13/2017 17:53:18  01/14/2017 17:53:18  krbtgt/example.com
        renew until 01/20/2017 17:53:18
01/13/2017 17:53:18  01/14/2017 03:53:18  nfs/dldn6008nfs.ldn.example.com
        renew until 01/20/2017 17:53:18

HOWEVER

Previous testing indicates that this functional state is temporary. In this version:

Credential cache file (expired), from last good run:
# klist -c /var/lib/gssproxy/clients/krb5cc_4767
Ticket cache: FILE:/var/lib/gssproxy/clients/krb5cc_4767
Default principal: unieng/a301-7026-8431.ldn.example.com

Valid starting       Expires              Service principal
01/13/2017 17:53:18  01/14/2017 17:53:18  krbtgt/example.com
        renew until 01/20/2017 17:53:18
01/13/2017 17:53:18  01/14/2017 03:53:18  nfs/dldn6008nfs.ldn.example.com
        renew until 01/20/2017 17:53:18


Now, gssproxy must renew the expired credentials, but it doesn't. Failure log:

Jan 17 08:16:28 a301-7026-8431 gssproxy: gssproxy[6324]: (OID: { 1 2 840 113554 1 2 2 }) Unspecified GSS failure.  Minor code may 
provide more information, No credentials cache found


Once again, it only looks for uid 0's ccache and keytab (root's files, not unieng's), which is wrong. Failure trace:

# cat /tmp/gssproxy.strace
Process 6324 attached with 6 threads
[pid  6328] futex(0x1545024, FUTEX_WAIT_PRIVATE, 1, NULL <unfinished ...>
[pid  6327] futex(0x1544d24, FUTEX_WAIT_PRIVATE, 1, NULL <unfinished ...>
[pid  6326] futex(0x1544a24, FUTEX_WAIT_PRIVATE, 1, NULL <unfinished ...>
[pid  6325] futex(0x1544724, FUTEX_WAIT_PRIVATE, 1, NULL <unfinished ...>
[pid  6329] futex(0x1545324, FUTEX_WAIT_PRIVATE, 41, NULL <unfinished ...>
[pid  6324] epoll_wait(5, {{EPOLLIN, {u32=22306288, u64=22306288}}}, 1, 30000) = 1
[pid  6324] read(12, "\200\0\0t", 4)    = 4
[pid  6324] read(12, "8\235\267\220\0\0\0\0\0\0\0\2\0\6\32\360\0\0\0\1\0\0\0\6\0\0\0\0\0\0\0\0"..., 116) = 116
[pid  6324] futex(0x1545324, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x1545320, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1} <unfinished ...>
[pid  6329] <... futex resumed> )       = 0
[pid  6324] <... futex resumed> )       = 1
[pid  6329] futex(0x15452f8, FUTEX_WAIT_PRIVATE, 2, NULL <unfinished ...>
[pid  6324] futex(0x15452f8, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  6329] <... futex resumed> )       = -1 EAGAIN (Resource temporarily unavailable)
[pid  6324] <... futex resumed> )       = 0
[pid  6329] futex(0x15452f8, FUTEX_WAKE_PRIVATE, 1 <unfinished ...>
[pid  6324] epoll_ctl(5, EPOLL_CTL_DEL, 12, {0, {u32=0, u64=0}} <unfinished ...>
[pid  6329] <... futex resumed> )       = 0
[pid  6324] <... epoll_ctl resumed> )   = 0
[pid  6329] open("/etc/passwd", O_RDONLY|O_CLOEXEC <unfinished ...>
[pid  6324] epoll_wait(5,  <unfinished ...>
[pid  6329] <... open resumed> )        = 14
[pid  6329] fstat(14, {st_mode=S_IFREG|0644, st_size=1523, ...}) = 0
[pid  6329] mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f056954e000
[pid  6329] read(14, "root:x:0:0:root:/root:/bin/bash\n"..., 4096) = 1523
[pid  6329] close(14)                   = 0
[pid  6329] munmap(0x7f056954e000, 4096) = 0
[pid  6329] access("/etc/krb5.conf", R_OK) = 0
[pid  6329] stat("/etc/krb5.conf", {st_mode=S_IFREG|0644, st_size=941, ...}) = 0
[pid  6329] open("/dev/urandom", O_RDONLY) = 14
[pid  6329] fcntl(14, F_SETFD, FD_CLOEXEC) = 0
[pid  6329] fstat(14, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 9), ...}) = 0
[pid  6329] read(14, "\215\304\252\246w=B\3736\227\351\212\213\201\364\16=z\222\30~~.\334\322\3332\316\343P\23r"..., 64) = 64
[pid  6329] close(14)                   = 0
[pid  6329] open("/var/lib/gssproxy/clients/krb5cc_0", O_RDONLY) = -1 ENOENT (No such file or directory)
[pid  6329] open("/var/spool/keytabs/root/keytab", O_RDONLY) = -1 ENOENT (No such file or directory)
[pid  6329] writev(2, [{"gssproxy[6324]: (OID: { 1 2 840 "..., 142}], 1) = 142
[pid  6329] sendto(3, "<83>Jan 17 08:16:28 gssproxy[632"..., 162, MSG_NOSIGNAL, NULL, 0) = 162
[pid  6329] write(10, "\0", 1)          = 1
[pid  6324] <... epoll_wait resumed> {{EPOLLIN, {u32=22304400, u64=22304400}}}, 1, 30000) = 1
[pid  6329] futex(0x1545324, FUTEX_WAIT_PRIVATE, 43, NULL <unfinished ...>
[pid  6324] read(4, "\0", 1)            = 1
[pid  6324] epoll_ctl(5, EPOLL_CTL_ADD, 12, {EPOLLOUT|EPOLLERR|EPOLLHUP, {u32=22305360, u64=22305360}}) = 0
[pid  6324] epoll_wait(5, {{EPOLLOUT, {u32=22305360, u64=22305360}}}, 1, 30000) = 1
[pid  6324] writev(12, [{"\200\0\0\260", 4}, {"8\235\267\220\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\r\0\0"..., 176}], 2) = 
180
[pid  6324] epoll_ctl(5, EPOLL_CTL_ADD, 12, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=22306288, u64=22306288}}) = -1 EEXIST (File exists)
[pid  6324] epoll_ctl(5, EPOLL_CTL_MOD, 12, {EPOLLIN|EPOLLOUT|EPOLLERR|EPOLLHUP, {u32=22305360, u64=22305360}}) = 0
[pid  6324] epoll_ctl(5, EPOLL_CTL_MOD, 12, {EPOLLIN|EPOLLERR|EPOLLHUP, {u32=22306288, u64=22306288}}) = 0
[pid  6324] epoll_wait(5,

Comment 4 Simo Sorce 2017-01-20 17:43:25 UTC

What version of gssproxy is this ?
Can you provide gssproxy debug logs ?

Comment 5 John Devitofranceschi 2017-01-20 21:33:17 UTC

Version of gssproxy - 

# rpm -q gssproxy
gssproxy-0.4.1-7.el7.x86_64

# gssproxy --version
0.4.1
# gssproxy -i -d
Debug Enabled
Client connected (fd = 11) (pid = 15559) (uid = 0) (gid = 0) (context = system_u:system_r:kernel_t:s0)
Client connected (fd = 12) (pid = 2687) (uid = 0) (gid = 0) (context = system_u:system_r:gssd_t:s0)
gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) for service "nfs-client", euid: 0, socket: (null)
gssproxy[15559]: (OID: { 1 2 840 113554 1 2 2 }) Unspecified GSS failure.  Minor code may provide more information, No credentials cache found
gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) for service "nfs-client", euid: 0, socket: (null)
gssproxy[15559]: (OID: { 1 2 840 113554 1 2 2 }) Unspecified GSS failure.  Minor code may provide more information, No credentials cache found

It is looking for a ccache for root:

^Z[1] + Stopped                  gssproxy -i -d
# touch /var/lib/gssproxy/clients/krb5cc_0
# fg
gssproxy -i -d
gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) for service "nfs-client", euid: 0, socket: (null)
gssproxy[15559]: (OID: { 1 2 840 113554 1 2 2 }) Unspecified GSS failure.  Minor code may provide more information, Bad format in credentials cache

Removing the root ccache:
^Z[1] + Stopped                  gssproxy -i -d
# rm /var/lib/gssproxy/clients/krb5cc_0
# fg
gssproxy -i -d
gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) for service "nfs-client", euid: 0, socket: (null)
gssproxy[15559]: (OID: { 1 2 840 113554 1 2 2 }) Unspecified GSS failure.  Minor code may provide more information, No credentials cache found
gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) for service "nfs-client", euid: 0, socket: (null)
gssproxy[15559]: (OID: { 1 2 840 113554 1 2 2 }) Unspecified GSS failure.  Minor code may provide more information, No credentials cache found

Most of the time, if I restart gssproxy, it will work:
# gssproxy -i -d
Debug Enabled
Client connected (fd = 11) (pid = 15649) (uid = 0) (gid = 0) (context = system_u:system_r:kernel_t:s0)
Client connected (fd = 12) (pid = 15693) (uid = 4767) (gid = 5072) (context = system_u:system_r:gssd_t:s0)
gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) for service "nfs-client", euid: 4767, socket: (null)
gp_rpc_execute: executing 8 (GSSX_INIT_SEC_CONTEXT) for service "nfs-client", euid: 4767, socket: (null)
gp_rpc_execute: executing 8 (GSSX_INIT_SEC_CONTEXT) for service "nfs-client", euid: 4767, socket: (null)


For about 5 minutes or so:
(5 minutes later...)
Client connected (fd = 12) (pid = 2687) (uid = 0) (gid = 0) (context = system_u:system_r:gssd_t:s0)
gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) for service "nfs-client", euid: 0, socket: (null)
gssproxy[15649]: (OID: { 1 2 840 113554 1 2 2 }) Unspecified GSS failure.  Minor code may provide more information, No credentials cache found
gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) for service "nfs-client", euid: 0, socket: (null)
gssproxy[15649]: (OID: { 1 2 840 113554 1 2 2 }) Unspecified GSS failure.  Minor code may provide more information, No credentials cache found
gp_rpc_execute: executing 6 (GSSX_ACQUIRE_CRED) for service "nfs-client", euid: 0, socket: (null)
gssproxy[15649]: (OID: { 1 2 840 113554 1 2 2 }) Unspecified GSS failure.  Minor code may provide more information, No credentials cache found

jd

Comment 6 John Devitofranceschi 2017-01-24 20:40:23 UTC

By the way, in the last example pid 2687 is rpc.gssd.  Subsequent testing has indicated that things work just fine as long as rpc.gssd does not connect to gssproxy as a client. Once that happens it seems to be "game over".

Comment 7 John Devitofranceschi 2017-01-24 20:54:34 UTC

I just noticed that our RHN server had newer versions of the gssproxy and nfs-utils packages so I updated them.  Nearly immediate failures seem to have stopped. I'll test some more.

Currently installed versions:

# rpm -q gssproxy nfs-utils
gssproxy-0.4.1-13.el7.x86_64
nfs-utils-1.3.0-0.33.el7.x86_64

Comment 8 Robbie Harwood 2017-01-24 21:55:11 UTC

Thanks John.  I'll leave this bugzilla open with NEEDINFO and if the problem doesn't recur we'll close it.

Comment 9 John Devitofranceschi 2017-01-27 19:42:50 UTC

The new rpms seem to have done the trick.  For my own peace of mind, which of the changes that are logged in the changelog fixed the problem?

jd

Comment 10 Robbie Harwood 2017-01-27 21:13:48 UTC

(In reply to John Devitofranceschi from comment #9)
> The new rpms seem to have done the trick.  For my own peace of mind, which
> of the changes that are logged in the changelog fixed the problem?

Almost certainly it was the fixes for making gssproxy work with 1.14 - two fixes to gssproxy interposer behavior, and one to krb5.  (This was bz#1292487 according to the changelog.)

Please reopen if the problem recurs.

*** This bug has been marked as a duplicate of bug 1292487 ***

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