freeipa

#7289 System error (4) after update from Fedora 26 to Fedora 27
Closed: invalid Opened by trisooma.

Closed: invalid
Reopen Issue

Request for enhancement

As a user I want to be able to upgrade to a newer version of Fedora and still be able to log in using freeipa.

Issue

After my recent upgrade to Fedora 27 (from Fedora 26) I cannot log in using freeipa anymore; I can see in the logs (/var/log/secure):

Nov 29 16:45:10 carbon gdm-password][9199]: pam_sss(gdm-password:auth): authentication success; logname= uid=0 euid=0 tty=/dev/tty1 ruser= rhost= user=remko
Nov 29 16:45:10 carbon gdm-password][9199]: pam_sss(gdm-password:account): Access denied for user remko: 4 (System error)

Steps to Reproduce

  1. start with a working installation of Fedora 26, that is enrolled in freeipa and can log in using sssd
  2. upgrade to Fedora 27 (using DNF system upgrade)

Actual behavior

Users can no longer log in using their freeipa accounts, the error posted above appears

Expected behavior

Users can login like before the upgrade.

Version/Release/Distribution

freeipa-server-4.4.4-4.fc26.x86_64
freeipa-client-4.4.4-4.fc26.x86_64
package ipa-server is not installed
package ipa-client is not installed
389-ds-base-1.3.6.11-1.fc26.x86_64
pki-ca-10.3.5-12.fc26.noarch
krb5-server-1.15.2-4.fc26.x86_64

I am running freeipa/freeipa-server:fedora-26 in a docker container.

Additional info:

I created a virtual machine installed Fedora 27, installed freeipa-client, ran ipa-client-install and from this machine I can login with freeipa users.
I have verified that /etc/sssd/sssd.conf is the same on both machines, however I cannot login from my upgraded machine.
I also have captured the network traffic for the failed login attempt if you are interested.

krb5_child.log

selinux_child.log

sssd_pam.log

sssd_phasma.nl.log

Something is up with the selinux child process:

(Wed Nov 29 17:15:16 2017) [sssd[be[phasma.nl]]] [read_pipe_handler] (0x0400): EOF received, client finished
(Wed Nov 29 17:15:16 2017) [sssd[be[phasma.nl]]] [selinux_child_done] (0x0020): selinux_child_parse_response failed: [22][Invalid argument]
(Wed Nov 29 17:15:16 2017) [sssd[be[phasma.nl]]] [dp_req_done] (0x0400): DP Request [PAM SELinux #6]: Request handler finished [0]: Success
(Wed Nov 29 17:15:16 2017) [sssd[be[phasma.nl]]] [_dp_req_recv] (0x0400): DP Request [PAM SELinux #6]: Receiving request data.
(Wed Nov 29 17:15:16 2017) [sssd[be[phasma.nl]]] [dp_req_destructor] (0x0400): DP Request [PAM SELinux #6]: Request removed.
(Wed Nov 29 17:15:16 2017) [sssd[be[phasma.nl]]] [dp_req_destructor] (0x0400): Number of active DP request: 0

This is the selinux_child.log:

(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [main] (0x0400): selinux_child started.
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [main] (0x2000): Running with effective IDs: [0][0].
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [main] (0x2000): Running with real IDs [0][0].
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [main] (0x0400): context initialized
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [unpack_buffer] (0x2000): seuser length: 12
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [unpack_buffer] (0x2000): seuser: unconfined_u
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [unpack_buffer] (0x2000): mls_range length: 14
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [unpack_buffer] (0x2000): mls_range: s0-s0:c0.c1023
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [unpack_buffer] (0x2000): username length: 5
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [unpack_buffer] (0x2000): username: remko
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [main] (0x0400): performing selinux operations
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [seuser_needs_update] (0x2000): getseuserbyname: ret: 0 seuser: unconfined_u mls: unknown
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [libsemanage] (0x0020): could not cache policy database
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [libsemanage] (0x0020): could not cache join database
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [libsemanage] (0x0020): could not enter read-only section
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [libsemanage] (0x0020): could not cache policy database
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [libsemanage] (0x0020): could not cache join database
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [libsemanage] (0x0020): could not enter read-only section
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [libsemanage] (0x0020): Error while reading kernel policy from /var/lib/selinux/targeted/active/policy.linked.
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [set_seuser] (0x0020): Cannot commit SELinux transaction
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [main] (0x0020): Cannot set SELinux login context.
(Wed Nov 29 17:15:16 2017) [[sssd[selinux_child[11307]]]] [main] (0x0020): selinux_child failed!

What is your SELinux status? Do you see any AVC denials?

btw for a quick workaround, you can set:

selinux_provider=none

I've noticed this as well in a fedora 27 container. I can confirm the workaround is working.
Edited by g5pw

@jhrozek thanks for you quick reply. As far as I can tell SELinux is disabled ; getenforce returns 'Disabled' and sestatus also returns 'disabled'. Should sssd (or some child process) be doing anything with selinux when it is disabled?

The workaround works! I can log in again.

We still run the SELinux provider even if SELinux is disabled, mostly to have the right labels set up if the admin then enables SELinux. Also because nobody should ever disable SELInux, it's pointless to optimize the flow for that scenario :-P

Does the system even have the selinux-policy-targeted RPM installed?

@g5pw does your container have the selinux-policy-targeted RPM?

@jhrozek I have selinux-policy-targeted-3.13.1-283.16.fc27.noarch installed.

I guess you are right about not having SELinux enabled, I remember though when it was still shiny and new it gave me more headache than peace of mind. Might try enabling it again :-)

Metadata Update from @trisooma:
- Issue close_status updated to: worksforme

Sorry, I was at least partially joking a bit about SELInux being disabled. While it's not a recommended configuration, it's something that should work in general.

I wouldn't close this ticket until we get to the root of it. Let me try to reproduce the same bug locally.

Metadata Update from @trisooma:
- Issue status updated to: Open (was: Closed)

Maybe you can see if something has changed between versions, since it was working on my 'old' install with SELinux disabled. And a fresh install of Fedora 27 works (this also has SELinux disabled).

Let me know if you need some logs/files.

Metadata Update from @trisooma:
- Issue close_status updated to: worksforme

@g5pw does your container have the selinux-policy-targeted RPM?

Are you referring to a package? If so, my logs show:

# dnf list --installed | grep selinux
libselinux.x86_64                           2.7-2.fc27                  @fedora
libselinux-utils.x86_64                     2.7-2.fc27                  @fedora
rpm-plugin-selinux.x86_64                   4.14.0-2.fc27               @fedora
Edited by g5pw

Metadata Update from @trisooma:
- Issue status updated to: Open (was: Closed)

I'm sorry this issue stalled.

I'm quite sure that the problem that @trisooma is seeing is different from what @g5pw is seeing. And I can only reproduce the bug that @g5pw reports, in a Docker container. I filed sssd bug https://pagure.io/SSSD/sssd/issue/3618 to track that.

@trisooma I'm really sorry I can't reproduce your error. Could you please open a new bug against sssd at https://pagure.io/SSSD/sssd so that we track the problem at the right place? Could you please also add strace logs? You would add something like this to your [domain] section of sssd.conf:

command = strace -tt -ff -o /tmp/sssd-strace /usr/libexec/sssd/sssd_be --domain YOURDOMAIN --debug-to-files

@rcritten I'm done with this ticket, please triage as you see fit.

I'm inclined to close this as the problem seems to be on the SSSD side and is better-tracked there.

Metadata Update from @rcritten:
- Issue close_status updated to: invalid
- Issue status updated to: Closed (was: Open)
Metadata
None
None
None
None
None
None
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.