Bug 1415090

Summary: gssproxy 0.6 failed to start
Product: [Fedora] Fedora Reporter: Lukas Slebodnik <lslebodn>
Component: gssproxyAssignee: Robbie Harwood <rharwood>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: urgent Docs Contact:
Priority: unspecified    
Version: 25CC: gdeschner, rharwood, ssorce
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: gssproxy-0.6.1-2.fc25 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-01-29 00:20:47 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Lukas Slebodnik 2017-01-20 08:48:44 UTC
Description of problem:
The latest upgrade of gssproxy broke start op gssproxy.service

Version-Release number of selected component (if applicable):
sh$ rpm -q  gssproxy krb5-libs
gssproxy-0.6.0-1.fc26.x86_64
krb5-libs-1.15-4.fc26.x86_64

How reproducible:
Deterministic

Steps to Reproduce:
1. systemctl start gssproxy.service
2. systemclt status gssproxy.service

Actual results:
[root@graviton ~]# systemctl start gssproxy
Job for gssproxy.service failed because the control process exited with error code.
See "systemctl status gssproxy.service" and "journalctl -xe" for details.
[root@graviton ~]# systemctl status gssproxy
● gssproxy.service - GSSAPI Proxy Daemon
   Loaded: loaded (/usr/lib/systemd/system/gssproxy.service; disabled; vendor preset: disabled)
   Active: failed (Result: exit-code) since Fri 2017-01-20 09:47:04 CET; 5s ago
  Process: 3588 ExecStart=/usr/sbin/gssproxy -D (code=exited, status=1/FAILURE)

Jan 20 09:47:04 graviton.brq.redhat.com systemd[1]: Starting GSSAPI Proxy Daemon...
Jan 20 09:47:04 graviton.brq.redhat.com gssproxy[3588]: Failed to read krb5 config for service/nfs-server.
Jan 20 09:47:04 graviton.brq.redhat.com gssproxy[3588]: Error reading configuration -1765328203: Unknown error -1765328203
Jan 20 09:47:04 graviton.brq.redhat.com systemd[1]: gssproxy.service: Control process exited, code=exited status=1
Jan 20 09:47:04 graviton.brq.redhat.com systemd[1]: Failed to start GSSAPI Proxy Daemon.
Jan 20 09:47:04 graviton.brq.redhat.com systemd[1]: gssproxy.service: Unit entered failed state.
Jan 20 09:47:04 graviton.brq.redhat.com systemd[1]: gssproxy.service: Failed with result 'exit-code'.


Expected results:
Service start without problems

Additional info:

Comment 1 Lukas Slebodnik 2017-01-20 08:52:46 UTC
Debug output does not help a lot (at least for me). And there are not any AVCs 

sh# systemctl status gssproxy
● gssproxy.service - GSSAPI Proxy Daemon
   Loaded: loaded (/usr/lib/systemd/system/gssproxy.service; disabled; vendor preset: disabled)
  Drop-In: /run/systemd/system/gssproxy.service.d
           └─debug.conf
   Active: failed (Result: exit-code) since Fri 2017-01-20 09:50:17 CET; 3s ago
  Process: 3640 ExecStart=/usr/sbin/gssproxy -D -d (code=exited, status=1/FAILURE)

Jan 20 09:50:17 host.example.com systemd[1]: Starting GSSAPI Proxy Daemon...
Jan 20 09:50:17 host.example.com gssproxy[3640]: Failed to read krb5 config for service/nfs-server.
Jan 20 09:50:17 host.example.com gssproxy[3640]: [2017/01/20 08:50:17]: Debug Enabled (level: 0)
Jan 20 09:50:17 host.example.com gssproxy[3640]: [2017/01/20 08:50:17]: Config file(s) not found! 
Jan 20 09:50:17 host.example.com gssproxy[3640]: Error reading configuration -1765328203: Unknown error -1765328203
Jan 20 09:50:17 host.example.com systemd[1]: gssproxy.service: Control process exited, code=exited status=1
Jan 20 09:50:17 host.example.com systemd[1]: Failed to start GSSAPI Proxy Daemon.
Jan 20 09:50:17 host.example.com systemd[1]: gssproxy.service: Unit entered failed state. 
Jan 20 09:50:17 host.example.com systemd[1]: gssproxy.service: Failed with result 'exit-code'.

Comment 2 Lukas Slebodnik 2017-01-20 08:55:24 UTC
strace is a little bit more helpful

stat("/etc/krb5.conf", {st_mode=S_IFREG|0644, st_size=1037, ...}) = 0
open("/etc/krb5.conf", O_RDONLY)        = 3
fcntl(3, F_SETFD, FD_CLOEXEC)           = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=1037, ...}) = 0
read(3, "# To opt out of the system crypt"..., 4096) = 1037
open("/etc/krb5.conf.d/", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 4
fstat(4, {st_mode=S_IFDIR|0755, st_size=106, ...}) = 0
getdents(4, /* 5 entries */, 32768)     = 176
open("/etc/krb5.conf.d//crypto-policies", O_RDONLY) = 5
fstat(5, {st_mode=S_IFREG|0644, st_size=125, ...}) = 0
read(5, "permitted_enctypes = aes256-cts-"..., 4096) = 125
read(5, "", 4096)                       = 0
close(5)                                = 0
open("/etc/krb5.conf.d//fedoraproject_org", O_RDONLY) = 5
fstat(5, {st_mode=S_IFREG|0644, st_size=181, ...}) = 0
read(5, "[realms]\n FEDORAPROJECT.ORG = {\n"..., 4096) = 181
read(5, "", 4096)                       = 0
close(5)                                = 0
open("/etc/krb5.conf.d//stg_fedoraproject_org", O_RDONLY) = 5
fstat(5, {st_mode=S_IFREG|0644, st_size=205, ...}) = 0
read(5, "[realms]\n STG.FEDORAPROJECT.ORG "..., 4096) = 205
read(5, "", 4096)                       = 0
close(5)                                = 0
getdents(4, /* 0 entries */, 32768)     = 0
close(4)                                = 0
read(3, "", 4096)                       = 0
close(3)                                = 0
getpid()                                = 3687
open("/etc/krb5.keytab", O_RDONLY)      = -1 ENOENT (No such file or directory)
open("/etc/localtime", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=2272, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=2272, ...}) = 0
read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\7\0\0\0\7\0\0\0\0"..., 4096) = 2272
lseek(3, -1449, SEEK_CUR)               = 823
read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\10\0\0\0\10\0\0\0\0"..., 4096) = 1449
close(3)                                = 0
socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 3
connect(3, {sa_family=AF_UNIX, sun_path="/dev/log"}, 110) = 0
sendto(3, "<11>Jan 20 09:53:36 gssproxy: Fa"..., 81, MSG_NOSIGNAL, NULL, 0) = 81
sendto(3, "<11>Jan 20 09:53:36 gssproxy: Er"..., 96, MSG_NOSIGNAL, NULL, 0) = 96
write(2, "[2017/01/20 08:53:36]: ", 23) = 23
write(2, "Debug Enabled (level: 0)\n", 25) = 25
write(2, "[2017/01/20 08:53:36]: ", 23) = 23
write(2, "Config file(s) not found!\n", 26) = 26

Comment 3 Lukas Slebodnik 2017-01-20 11:46:25 UTC
The same bug is even without fedora specific configure files.

stat("/etc/krb5.conf", {st_mode=S_IFREG|0644, st_size=677, ...}) = 0
open("/etc/krb5.conf", O_RDONLY)        = 3
fcntl(3, F_SETFD, FD_CLOEXEC)           = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=677, ...}) = 0
read(3, "# To opt out of the system crypt"..., 4096) = 677
open("/etc/krb5.conf.d/", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 4
fstat(4, {st_mode=S_IFDIR|0755, st_size=29, ...}) = 0
getdents(4, /* 3 entries */, 32768)     = 88
open("/etc/krb5.conf.d//crypto-policies", O_RDONLY) = 5
fstat(5, {st_mode=S_IFREG|0644, st_size=125, ...}) = 0
read(5, "permitted_enctypes = aes256-cts-"..., 4096) = 125
read(5, "", 4096)                       = 0
close(5)                                = 0
getdents(4, /* 0 entries */, 32768)     = 0
close(4)                                = 0
read(3, "", 4096)                       = 0
close(3)                                = 0
gettimeofday({tv_sec=1484912736, tv_usec=354387}, NULL) = 0
open("/etc/krb5.keytab", O_RDONLY)      = -1 ENOENT (No such file or directory)
open("/etc/localtime", O_RDONLY|O_CLOEXEC) = 3
fstat(3, {st_mode=S_IFREG|0644, st_size=2272, ...}) = 0
fstat(3, {st_mode=S_IFREG|0644, st_size=2272, ...}) = 0
read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\7\0\0\0\7\0\0\0\0"..., 4096) = 2272
lseek(3, -1449, SEEK_CUR)               = 823
read(3, "TZif2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\10\0\0\0\10\0\0\0\0"..., 4096) = 1449
close(3)                                = 0
socket(AF_UNIX, SOCK_DGRAM|SOCK_CLOEXEC, 0) = 3
connect(3, {sa_family=AF_UNIX, sun_path="/dev/log"}, 110) = 0
sendto(3, "<11>Jan 20 12:45:36 gssproxy: Fa"..., 81, MSG_NOSIGNAL, NULL, 0) = 81
sendto(3, "<11>Jan 20 12:45:36 gssproxy: Er"..., 96, MSG_NOSIGNAL, NULL, 0) = 96
write(2, "[2017/01/20 11:45:36]: ", 23) = 23
write(2, "Debug Enabled (level: 0)\n", 25) = 25
write(2, "[2017/01/20 11:45:36]: ", 23) = 23
write(2, "Config file(s) not found!\n", 26) = 26

Comment 4 Fedora Update System 2017-01-20 22:54:29 UTC
gssproxy-0.6.1-1.fc25 has been submitted as an update to Fedora 25. https://bodhi.fedoraproject.org/updates/FEDORA-2017-bdfba1e58c

Comment 5 Fedora Update System 2017-01-21 22:25:59 UTC
gssproxy-0.6.1-1.fc25 has been pushed to the Fedora 25 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2017-bdfba1e58c

Comment 6 Fedora Update System 2017-01-23 22:22:17 UTC
gssproxy-0.6.1-2.fc25 has been submitted as an update to Fedora 25. https://bodhi.fedoraproject.org/updates/FEDORA-2017-4c47de4898

Comment 7 Fedora Update System 2017-01-28 19:19:12 UTC
gssproxy-0.6.1-2.fc25 has been pushed to the Fedora 25 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2017-4c47de4898

Comment 8 Fedora Update System 2017-01-29 00:20:47 UTC
gssproxy-0.6.1-2.fc25 has been pushed to the Fedora 25 stable repository. If problems still persist, please make note of it in this bug report.