Bug 1875801 - autofs doesn't work after reboot
Summary: autofs doesn't work after reboot
Keywords:
Status: CLOSED DUPLICATE of bug 1874338
Alias: None
Product: Fedora
Classification: Fedora
Component: autofs
Version: 32
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Ian Kent
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2020-09-04 12:12 UTC by Pierre Ossman
Modified: 2020-09-23 02:36 UTC (History)
3 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2020-09-23 02:36:12 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Pierre Ossman 2020-09-04 12:12:17 UTC
Description of problem:
autofs has gotten extremely unreliable the last few years and we're now seeing it completely non-functional after boot. It start up, but does not mount anything. I suspect it is racing with other services (like the network and sssd) which makes it very unreliable when used from systemd.

Version-Release number of selected component (if applicable):
autofs-5.1.6-7.fc32.x86_64
sssd-2.3.1-2.fc32.x86_64

How reproducible:
Comes and goes, but 100% on some machines.

Steps to Reproduce:
1. Join machine to FreeIPA domain
2. Configure autofs
3. Reboot

Actual results:
Nothing is provided via autofs.

Expected results:
autofs directories are available.

Additional info:
We've tried various hacks with limited success. Right now we've made sssd.service wait for NetworkManager-wait-online.service, and made autofs.service wait for sssd.service. Apparently that is not sufficient.

Comment 1 Pierre Ossman 2020-09-04 12:23:58 UTC
I can see bug 1189767 which claims to have fixed this (several times). But it seems like this bug still isn't fully gone.

Comment 2 Pierre Ossman 2020-09-04 12:25:41 UTC
Also note that I have absolute no errors from autofs in the log when this happens:

> -- Reboot --
> Sep 04 13:58:48 localhost.localdomain systemd[1]: Starting Automounts filesystems on demand...
> Sep 04 13:58:50 linma.lkpg.cendio.se systemd[1]: Started Automounts filesystems on demand.
> Sep 04 14:01:04 linma.lkpg.cendio.se systemd[1]: Stopping Automounts filesystems on demand...
> Sep 04 14:01:04 linma.lkpg.cendio.se systemd[1]: autofs.service: Succeeded.
> Sep 04 14:01:04 linma.lkpg.cendio.se systemd[1]: Stopped Automounts filesystems on demand.
> Sep 04 14:01:12 linma.lkpg.cendio.se systemd[1]: Starting Automounts filesystems on demand...
> Sep 04 14:01:12 linma.lkpg.cendio.se systemd[1]: Started Automounts filesystems on demand.

Comment 3 Ian Kent 2020-09-04 13:37:04 UTC
(In reply to Pierre Ossman from comment #2)
> Also note that I have absolute no errors from autofs in the log when this
> happens:
> 
> > -- Reboot --
> > Sep 04 13:58:48 localhost.localdomain systemd[1]: Starting Automounts filesystems on demand...
> > Sep 04 13:58:50 linma.lkpg.cendio.se systemd[1]: Started Automounts filesystems on demand.
> > Sep 04 14:01:04 linma.lkpg.cendio.se systemd[1]: Stopping Automounts filesystems on demand...
> > Sep 04 14:01:04 linma.lkpg.cendio.se systemd[1]: autofs.service: Succeeded.
> > Sep 04 14:01:04 linma.lkpg.cendio.se systemd[1]: Stopped Automounts filesystems on demand.
> > Sep 04 14:01:12 linma.lkpg.cendio.se systemd[1]: Starting Automounts filesystems on demand...
> > Sep 04 14:01:12 linma.lkpg.cendio.se systemd[1]: Started Automounts filesystems on demand.

Yes, but that only means that autofs doesn't see what it thinks is an error.
I'll not go on about that because it's been talked about a lot in bugs like the
one above.

We do however, need to understand what's happening before we go much further.

Probably the best way to do that is to get an autofs debug log.

You can do that using systemd journalctl after setting "logging = debug" in
/etc/autofs.conf.

Clearly we will need to reboot the machine after setting this to capture the
logging we want to see.

Once done you can use journalctl to get log output, possibly with a time range,
although just piping the journalctl output to "grep automount" should be
sufficient.

A couple of questions though, if you reboot a machine and autofs is not
functioning does "service autofs reload" then make it functional?

IOW is the problem that the master map is not available via sssd when autofs
is started?

What do you have in the automount entry in /etc/nsswitch.conf?

Ian

Comment 4 Pierre Ossman 2020-09-04 13:52:41 UTC
(In reply to Ian Kent from comment #3)
> 
> Probably the best way to do that is to get an autofs debug log.
> 
> You can do that using systemd journalctl after setting "logging = debug" in
> /etc/autofs.conf.
> 
> Clearly we will need to reboot the machine after setting this to capture the
> logging we want to see.
> 

Sure, no problem. It's getting late here though so I'll have to get back to you on Monday with this.

> 
> A couple of questions though, if you reboot a machine and autofs is not
> functioning does "service autofs reload" then make it functional?
> 

I've done "systemctl restart autofs" which got it running most of the time (not all though, for unknown reasons). I have not tried "reload".

> IOW is the problem that the master map is not available via sssd when autofs
> is started?
> 

Probably. However "automount --dumpmaps" give us the correct information. But at this point the machine is fully booted, so it is beyond any race during startup.

> What do you have in the automount entry in /etc/nsswitch.conf?
> 

I have:

> automount: sss

And as mentioned earlier, sssd is configured to talk to a FreeIPA server. So I was hoping that sssd would be providing a cached map even if there is some issue talking to the server.

Comment 5 Ian Kent 2020-09-04 14:17:49 UTC
(In reply to Pierre Ossman from comment #4)
> (In reply to Ian Kent from comment #3)
> > 
> > Probably the best way to do that is to get an autofs debug log.
> > 
> > You can do that using systemd journalctl after setting "logging = debug" in
> > /etc/autofs.conf.
> > 
> > Clearly we will need to reboot the machine after setting this to capture the
> > logging we want to see.
> > 
> 
> Sure, no problem. It's getting late here though so I'll have to get back to
> you on Monday with this.

Thanks, it's late for me here too.

> 
> > 
> > A couple of questions though, if you reboot a machine and autofs is not
> > functioning does "service autofs reload" then make it functional?
> > 
> 
> I've done "systemctl restart autofs" which got it running most of the time
> (not all though, for unknown reasons). I have not tried "reload".

That shouldn't make a difference, a restart will have much the same effect.

> 
> > IOW is the problem that the master map is not available via sssd when autofs
> > is started?
> > 
> 
> Probably. However "automount --dumpmaps" give us the correct information.
> But at this point the machine is fully booted, so it is beyond any race
> during startup.

Right, the dumpmaps will consult whatever it would consult based on current
configuration. It does this independent of the running automount.

Showing what is expected essentially means that the configuration of all the
bits along the way are setup correctly.

> 
> > What do you have in the automount entry in /etc/nsswitch.conf?
> > 
> 
> I have:
> 
> > automount: sss
> 
> And as mentioned earlier, sssd is configured to talk to a FreeIPA server. So
> I was hoping that sssd would be providing a cached map even if there is some
> issue talking to the server.

I don't know myself but I thought that at boot sssd would start from scratch
and load the maps that are subsequently used for caching. It's not quite that
simple but the master map must be available at startup so it should be cached
once sssd is completely up and running. The problem used to be that sssd would
return ENOENT saying there are no entries when it hadn't yet completed it's
initial read as well as ENOENT when there are really no entries.

Before going into adding extra targeted logging to get more accurate detail
on what's happening we can further check if the master map isn't available
via sssd at boot by trying to use a configuration option I added to try and
work around this problem. I don't know if sssd still returns what I need for
this to help but lets try.

Set the configuration option "sss_master_map_wait" in /etc/autofs.conf to a
non-zero value (in seconds) and see if that helps. Since I don't know what
a sensible value would be in your environment it would make sense to set it
quite high to start with, say 10 or even 20 seconds, and work backward if it
does help to see what best suits your environment.

Ian

Comment 6 Pierre Ossman 2020-09-07 11:21:38 UTC
So with debug logging enabled I'm getting:

> [root@linma ~]# journalctl -u autofs -b
> -- Logs begin at Tue 2020-09-01 07:06:37 CEST, end at Mon 2020-09-07 13:15:01 CEST. --
> Sep 07 13:13:54 localhost.localdomain systemd[1]: Starting Automounts filesystems on demand...
> Sep 07 13:13:54 localhost.localdomain automount[1197]: Starting automounter version 5.1.6-7.fc32, master map auto.master
> Sep 07 13:13:54 localhost.localdomain automount[1197]: using kernel protocol version 5.05
> Sep 07 13:13:54 localhost.localdomain automount[1197]: lookup_nss_read_master: reading master sss auto.master
> Sep 07 13:13:54 localhost.localdomain automount[1197]: do_init: parse(sun): init gathered global options: (null)
> Sep 07 13:13:54 localhost.localdomain automount[1197]: master_do_mount: mounting /home
> Sep 07 13:13:54 localhost.localdomain automount[1197]: automount_path_to_fifo: fifo name /run/autofs.fifo-home
> Sep 07 13:13:54 localhost.localdomain automount[1197]: lookup_nss_read_map: reading map sss auto.home
> Sep 07 13:13:54 localhost.localdomain automount[1197]: do_init: parse(sun): init gathered global options: nfsvers=3,nosuid
> Sep 07 13:13:54 localhost.localdomain automount[1197]: lookup_read_map: map read not needed, so not done
> Sep 07 13:13:54 localhost.localdomain automount[1197]: mounted indirect on /home with timeout 300, freq 75 seconds
> Sep 07 13:13:54 localhost.localdomain automount[1197]: st_ready: st_ready(): state = 0 path /home
> Sep 07 13:13:54 localhost.localdomain systemd[1]: Started Automounts filesystems on demand.

Oddly enough it is picking up on some things, like that there is a "auto.home", and that the default options are "nfsvers=3,nosuid".

So is it loading the master map but not the sub-map?

Anyway, I also tried setting "sss_master_map_wait" to "10" which did not help. I'm also not seeing any change in the log output. I.e. it didn't have a 10 second delay starting up.

Comment 7 Pierre Ossman 2020-09-07 11:27:38 UTC
If I restart it (with debugging still on), the startup looks identical. However when I access it I start getting these:

> Sep 07 13:22:00 linma.lkpg.cendio.se automount[1924]: handle_packet: type = 3
> Sep 07 13:22:00 linma.lkpg.cendio.se automount[1924]: handle_packet_missing_indirect: token 2, name ossman, request pid 1935
> Sep 07 13:22:00 linma.lkpg.cendio.se automount[1924]: attempting to mount entry /home/ossman
...

So it looks like there is some communication with the kernel that is messed up.

Digging further, I can see that the mount options are screwed up when it isn't working:

> auto.home /home autofs rw,relatime,fd=-1,pgrp=1195,timeout=300,minproto=5,maxproto=5,indirect,pipe_ino=-1 0 0

Compared with after a restart:

> auto.home /home autofs rw,relatime,fd=6,pgrp=1946,timeout=300,minproto=5,maxproto=5,indirect,pipe_ino=46726 0 0

Comment 8 Pierre Ossman 2020-09-07 11:29:42 UTC
Also for reference, I can see the pipe being open by the automount process, even if it hasn't been properly passed on to the kernel.

Comment 9 Pierre Ossman 2020-09-07 14:43:23 UTC
So we keep getting the issue of autofs also breaking after it's been restarted and "fixed":

> [root@linma ~]# cat /proc/mounts | grep home
> auto.home /home autofs rw,relatime,fd=-1,pgrp=1196,timeout=300,minproto=5,maxproto=5,indirect,pipe_ino=-1 0 0
> [root@linma ~]# systemctl restart autofs
> [root@linma ~]# cat /proc/mounts | grep home
> auto.home /home autofs rw,relatime,fd=6,pgrp=1901,timeout=300,minproto=5,maxproto=5,indirect,pipe_ino=47817 0 0
> [root@linma ~]# ls /home/ossman
> ...
> [root@linma ~]# cat /proc/mounts | grep home
> auto.home /home autofs rw,relatime,fd=6,pgrp=1901,timeout=300,minproto=5,maxproto=5,indirect,pipe_ino=47817 0 0
> fileserver.lkpg.cendio.se:/export/home/ossman /home/ossman nfs rw,nosuid,relatime,vers=3,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=10.47.128.1,mountvers=3,mountport=35750,mountproto=udp,local_lock=none,addr=10.47.128.1 0 0
> [root@linma ~]# cat /proc/mounts | grep home
> auto.home /home autofs rw,relatime,fd=-1,pgrp=1901,timeout=300,minproto=5,maxproto=5,indirect,pipe_ino=-1 0 0
> fileserver.lkpg.cendio.se:/export/home/ossman /home/ossman nfs rw,nosuid,relatime,vers=3,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=10.47.128.1,mountvers=3,mountport=35750,mountproto=udp,local_lock=none,addr=10.47.128.1 0 0

As you can see, after mounting "ossman" it decided to screw up the auto.home mount again.

Looking at the debug log I can see these when this happens:

> ...
> Sep 07 16:30:39 linma.lkpg.cendio.se automount[1901]: mounted /home/ossman
> Sep 07 16:30:39 linma.lkpg.cendio.se automount[1901]: st_readmap: state 1 path /home
> Sep 07 16:30:39 linma.lkpg.cendio.se automount[1901]: re-reading map for /home
> Sep 07 16:30:39 linma.lkpg.cendio.se automount[1901]: lookup_nss_read_map: reading map sss auto.home
> Sep 07 16:30:39 linma.lkpg.cendio.se automount[1901]: do_init: parse(sun): init gathered global options: nfsvers=3,nosuid
> Sep 07 16:30:39 linma.lkpg.cendio.se automount[1901]: lookup_read_map: map read not needed, so not done
> Sep 07 16:30:39 linma.lkpg.cendio.se automount[1901]: st_ready: st_ready(): state = 4 path /home

When things work it stops at the "mounted" line.

Comment 10 Pierre Ossman 2020-09-07 14:51:09 UTC
Scratch that. Those log lines can appear even if things continue working.

However what does break things is logging in locally on GDM. Everything works up until then. Unfortunately there is nothing in the log from automount when this happens. Lots of stuff from the rest of the login though, so I'm not sure what might be interesting.

Except for this:

> Sep 07 16:45:16 linma.lkpg.cendio.se audit[1422]: AVC avc:  denied  { write } for  pid=1422 comm="gnome-shell" path="pipe:[49541]" dev="pipefs" ino=49541 scontext=system_u:system_r:xdm_t:s0-s0:c0.c1023 tcontext=system_u:system_r:automount_t:s0 tclass=fifo_file permissive=0
> Sep 07 16:45:21 linma.lkpg.cendio.se systemd[1]: Starting SSSD Kerberos Cache Manager...
> Sep 07 16:45:21 linma.lkpg.cendio.se systemd[1]: Started SSSD Kerberos Cache Manager.
> Sep 07 16:45:21 linma.lkpg.cendio.se audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=sssd-kcm comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
> Sep 07 16:45:21 linma.lkpg.cendio.se kcm[1950]: Starting up

The pipe inode number there in the AVC is the one that gets screwed up. But I don't understand how gdm can screw things up for automount.

Comment 11 Pierre Ossman 2020-09-07 15:01:38 UTC
And setting SELinux to permissive makes the problem go away.

That's all the debugging we have time for today, unfortunately. Hopefully this gives you something to work with. Perhaps the GDM and/or SELinux people also need to be involved.

Comment 12 Ian Kent 2020-09-08 04:12:22 UTC
(In reply to Pierre Ossman from comment #11)
> And setting SELinux to permissive makes the problem go away.

Right.

I tried to duplicate this without using sssd, which shouldn't make any
difference by the look of it, and I didn't see the selinux fail no matter
what I did.

I'm wondering whether what you see when you look at the mount table entry
is real or the result of an selinux denial.  I'm not sure how that could
happen since the kernel is simply attempting to read a structure field
for the fd and trying to access the pipe file inode for the pipe_ino. so
there's no write at all. It could be that, for some reason, the login
process is using a different mount namespace but again I don't understand
why that would result in what your seeing.

What's even stranger is that it appears the home directory does get mounted
as you see it when you look at the mount table but also the autofs mount
looks broken. That's odd because the mount gets triggered by the kernel
when the user space process attempts to access the directory and that does
cause a write to the kernel pipe which must have succeeded since the mount
is present. Unless the mount was triggered at some earlier time and the
login process is just using the existing mounted mount but doesn't actually
have access to the pipe due to selinux.

Do you see any selinux read denials in the log?

I'd like to work out if that mount table entry is actually accurate or
is due to an access problem. To do that log into the machine as root from
somewhere else and look at the autofs mount table entry. Or, if you can't
login from elsewhere, log out and then login as root and check the autofs
mount table entry. But if there really is some problem with GDM this might
not show what I'm trying to verify, ideally login from somewhere else.

Do you use any systemd settings that cause the use of mount namespaces?
For example PrivateTemp creates a mount namespace for the private temp
directory.
Have you made any changes to any systemd units that might affect this?

It would be interesting to see if using audit2allow to create a local
type enforcement module for the AVC we think is causing the problem.

Do this by creating a file (I called it tt.deny below) with the AVC
denial in it taken from the log output of what we think is causing
the problem.

Based on the log entry above it should look like this (not sure about
the newline here, just cut and paste from the log entry):
AVC avc:  denied  { write } for  pid=1422 comm="gnome-shell" path="pipe:[49541]" dev="pipefs" ino=49541 scontext=system_u:system_r:xdm_t:s0-s0:c0.c1023 tcontext=system_u:system_r:automount_t:s0 tclass=fifo_file permissive=0

Run sudo "audit2allow -i tt.deny -m local_autofs > local_autofs.te" to
create a text type enforcement module named local_autofs.te if you want
to have a look at what will be used for the module (I think there will
already be a module named autofs so I'm avoiding using that as the name).

Run "sudo audit2allow -i tt.deny -M local_autofs" to generate a binary
type enforcement module named local_autofs.pp that can be loaded into
the selinux security context.

Running "semodule -i local_autofs.pp" should then load the binary module
into the selinux context and should be persistent so it survives a reboot.

Then test to see if the problem is resolved or we need to look for some
more AVC records related to this problem.

The advantage to doing this is, 1) we can verify if it really is an selinux
restriction and, 2) you will have a workaround while we work out what to do
about resolving it and finally, 3) it may be useful for the selinux folks
if we need to ask them for help.

Ian

Comment 13 Pierre Ossman 2020-09-08 07:38:47 UTC
(In reply to Ian Kent from comment #12)
> 
> What's even stranger is that it appears the home directory does get mounted
> as you see it when you look at the mount table but also the autofs mount
> looks broken. That's odd because the mount gets triggered by the kernel
> when the user space process attempts to access the directory and that does
> cause a write to the kernel pipe which must have succeeded since the mount
> is present. Unless the mount was triggered at some earlier time and the
> login process is just using the existing mounted mount but doesn't actually
> have access to the pipe due to selinux.
> 

When things break there is no successful mount. There is not a single log line from automount either, so it doesn't seem to get a request from the kernel.

The successful mounts are when I manually do a "ls /home/foo" as root (via SSH). Nothing breaks by doing that.

> Do you see any selinux read denials in the log?
> 

No, just the one I quoted earlier.

Also note that this appears right as GDM starts. It seems it probes the home directory of the last logged in user on startup, and that is somehow triggering this issue. That also explains why things are broken on boot, so it doesn't seem to be a race with sssd.

Now that things are in permissive mode the sequence is:

> Sep 07 16:58:49 linma.lkpg.cendio.se systemd[1]: Reached target Multi-User System.
> Sep 07 16:58:49 linma.lkpg.cendio.se systemd[1]: Reached target Graphical Interface.
> Sep 07 16:58:49 linma.lkpg.cendio.se audit[1424]: AVC avc:  denied  { write } for  pid=1424 comm="gnome-shell" path="pipe:[17963]" dev="pipefs" ino=17963 scontext=system_u:system_r:xdm_t:s0-s0:c0.c1023 tcontext>
> Sep 07 16:58:49 linma.lkpg.cendio.se automount[1203]: handle_packet: type = 3
> Sep 07 16:58:49 linma.lkpg.cendio.se automount[1203]: handle_packet_missing_indirect: token 1, name linma, request pid 1424
> Sep 07 16:58:49 linma.lkpg.cendio.se automount[1203]: attempting to mount entry /home/linma


> I'd like to work out if that mount table entry is actually accurate or
> is due to an access problem. To do that log into the machine as root from
> somewhere else and look at the autofs mount table entry. Or, if you can't
> login from elsewhere, log out and then login as root and check the autofs
> mount table entry. But if there really is some problem with GDM this might
> not show what I'm trying to verify, ideally login from somewhere else.
> 

I'm not sure what you want me to do. What I've done is access the machine remotely as root (as to not trigger any home directory access), and run:

> cat /proc/mounts | grep home

All mount output in my previous comments come from running that.

> Do you use any systemd settings that cause the use of mount namespaces?
> For example PrivateTemp creates a mount namespace for the private temp
> directory.

Not that we've configured at least. I can't say anything about what's configured by default. This is also a very recently installed machine, so there should be very little accumulated cruft.

> Have you made any changes to any systemd units that might affect this?
> 

We've added the following to try to resolve earlier startup races with autofs:

> /etc/systemd/system/autofs.service.d/requires-sssd.conf:# Ansible managed
> /etc/systemd/system/autofs.service.d/requires-sssd.conf:[Unit]
> /etc/systemd/system/autofs.service.d/requires-sssd.conf:After=sssd.service
> /etc/systemd/system/autofs.service.d/requires-sssd.conf:Requires=sssd.service
> /etc/systemd/system/sssd.service.d/wait-for-network.conf:# Ansible managed
> /etc/systemd/system/sssd.service.d/wait-for-network.conf:[Unit]
> /etc/systemd/system/sssd.service.d/wait-for-network.conf:After=NetworkManager-wait-online.service
> /etc/systemd/system/sssd.service.d/wait-for-network.conf:Requires=NetworkManager-wait-online.service

> It would be interesting to see if using audit2allow to create a local
> type enforcement module for the AVC we think is causing the problem.
> 

I've created the module and there is no more AVC in the log and autofs doesn't break on boot. So this rule does indeed seem to be key to the issue.

Comment 14 Ian Kent 2020-09-09 01:09:16 UTC
(In reply to Pierre Ossman from comment #13)
> (In reply to Ian Kent from comment #12)
> > 
> > What's even stranger is that it appears the home directory does get mounted
> > as you see it when you look at the mount table but also the autofs mount
> > looks broken. That's odd because the mount gets triggered by the kernel
> > when the user space process attempts to access the directory and that does
> > cause a write to the kernel pipe which must have succeeded since the mount
> > is present. Unless the mount was triggered at some earlier time and the
> > login process is just using the existing mounted mount but doesn't actually
> > have access to the pipe due to selinux.
> > 
> 
> When things break there is no successful mount. There is not a single log
> line from automount either, so it doesn't seem to get a request from the
> kernel.

Right, I couldn't understand how the AVC could break autofs but now I know
what you were doing I see where the problem is.

When the kernel writes to the automount communication pipe and an error
is returned that's other than -ENOMEM or -ERESTARTSYS (an interrupted
system call) it sets the mount (in this case /home) catatonic which
basically disables it.

The reason that's done is if the daemon has gone away and processes are
trying to access a mount (say at shutdown or other similar case) we need
to avoid those processes hanging and once set catatonic those attempts
will just always fail.

On one hand I'm not sure that should change since selinux may have caught
something bad happening so disabling the automount mount seems sensible
but on the other hand, well, it disables the mount system wide ...

So I'm not sure what to do about this, if anything ...

> 
> The successful mounts are when I manually do a "ls /home/foo" as root (via
> SSH). Nothing breaks by doing that.
> 
> > Do you see any selinux read denials in the log?
> > 
> 
> No, just the one I quoted earlier.
> 
> Also note that this appears right as GDM starts. It seems it probes the home
> directory of the last logged in user on startup, and that is somehow
> triggering this issue. That also explains why things are broken on boot, so
> it doesn't seem to be a race with sssd.

Right, we now know what's happening.
I think GDM does access the home directory and in the context of the requesting
process so an selinux denial must be causing an error return other than the
expected ones.

> 
> Now that things are in permissive mode the sequence is:
> 
> > Sep 07 16:58:49 linma.lkpg.cendio.se systemd[1]: Reached target Multi-User System.
> > Sep 07 16:58:49 linma.lkpg.cendio.se systemd[1]: Reached target Graphical Interface.
> > Sep 07 16:58:49 linma.lkpg.cendio.se audit[1424]: AVC avc:  denied  { write } for  pid=1424 comm="gnome-shell" path="pipe:[17963]" dev="pipefs" ino=17963 scontext=system_u:system_r:xdm_t:s0-s0:c0.c1023 tcontext>
> > Sep 07 16:58:49 linma.lkpg.cendio.se automount[1203]: handle_packet: type = 3
> > Sep 07 16:58:49 linma.lkpg.cendio.se automount[1203]: handle_packet_missing_indirect: token 1, name linma, request pid 1424
> > Sep 07 16:58:49 linma.lkpg.cendio.se automount[1203]: attempting to mount entry /home/linma

Yep, and that's a successful write to the daemon pipe with the selinux denial
ignored.

> 
> 
> > I'd like to work out if that mount table entry is actually accurate or
> > is due to an access problem. To do that log into the machine as root from
> > somewhere else and look at the autofs mount table entry. Or, if you can't
> > login from elsewhere, log out and then login as root and check the autofs
> > mount table entry. But if there really is some problem with GDM this might
> > not show what I'm trying to verify, ideally login from somewhere else.
> > 
> 
> I'm not sure what you want me to do. What I've done is access the machine
> remotely as root (as to not trigger any home directory access), and run:
> 
> > cat /proc/mounts | grep home
> 
> All mount output in my previous comments come from running that.

Yes, it makes sense to me know, I just wanted to know if the mount appeared
broken to the root user after the fail which we know it does now.

> 
> > Do you use any systemd settings that cause the use of mount namespaces?
> > For example PrivateTemp creates a mount namespace for the private temp
> > directory.
> 
> Not that we've configured at least. I can't say anything about what's
> configured by default. This is also a very recently installed machine, so
> there should be very little accumulated cruft.
> 
> > Have you made any changes to any systemd units that might affect this?
> > 
> 
> We've added the following to try to resolve earlier startup races with
> autofs:
> 
> > /etc/systemd/system/autofs.service.d/requires-sssd.conf:# Ansible managed
> > /etc/systemd/system/autofs.service.d/requires-sssd.conf:[Unit]
> > /etc/systemd/system/autofs.service.d/requires-sssd.conf:After=sssd.service
> > /etc/systemd/system/autofs.service.d/requires-sssd.conf:Requires=sssd.service
> > /etc/systemd/system/sssd.service.d/wait-for-network.conf:# Ansible managed
> > /etc/systemd/system/sssd.service.d/wait-for-network.conf:[Unit]
> > /etc/systemd/system/sssd.service.d/wait-for-network.conf:After=NetworkManager-wait-online.service
> > /etc/systemd/system/sssd.service.d/wait-for-network.conf:Requires=NetworkManager-wait-online.service

Yep, not relavant now.

> 
> > It would be interesting to see if using audit2allow to create a local
> > type enforcement module for the AVC we think is causing the problem.
> > 
> 
> I've created the module and there is no more AVC in the log and autofs
> doesn't break on boot. So this rule does indeed seem to be key to the issue.

Regardless of working out if there's a sensible way to make this handling
in the kernel better I think this needs to be fixed in the selinux policy.

With that type enforcement policy you at least have a workaround so I'll
reassign this bug to selinux and we'll see how it goes.

Ian

Comment 15 Jason Tibbitts 2020-09-09 06:24:10 UTC
I just wanted to make a note that I've been plagued by what appears to be the same issue for the past several days and I've been pulling my hair out trying to understand the problem.

Interestingly, I can ssh in as root and reference automounted filesystems without any issue.  But as soon as I try to ssh into the machine as a user, autofs stops mounting home directories.  And indeed I get a single selinux denial:

type=AVC msg=audit(1599630754.962:413): avc:  denied  { write } for  pid=16138 comm="sshd" path="pipe:[30431]" dev="pipefs" ino=30431 scontext=system_u:system_r:sshd_t:s0-s0:c0.c1023 tcontext=system_u:system_r:automount_t:s0 tclass=fifo_file permissive=0

But I edited /etc/selinux/conf to set permissive mode and rebooted.  Sadly it seems that's not enough to put the machine in permissive mode:

Loaded policy name:             targeted
Current mode:                   enforcing
Mode from config file:          permissive

That seems to be new because I really thought this used to work.  Anyway, I logged in as root after a reboot, ran setenforce 0, and then logged in as a user and now it works.  I still get just the one AVC, only now with permissive=1 at the end.

I am running selinux-policy-targeted-3.14.5-43.fc32.noarch but I tried downgrading to selinux-policy-targeted-3.14.5-42.fc32.noarch and that doesn't seem to help.  But I know I didn't have trouble until recently and for me the upgrade to the -43 package happened on September 2nd.  So now I'm going to try to see if things are perhaps better with an older kernel.

Comment 16 Jason Tibbitts 2020-09-09 06:41:33 UTC
I can confirm that the problem does not occur if I simply boot back to kernel-5.7.17-200.fc32.x86_64, with selinux enabled and the current policy installed.  If I boot kernel-5.8.4-200.fc32.x86_64 or kernel-5.8.6-201.fc32.x86_64 then the problem happens immediately when the first non-root user connects via ssh.  The problematic AVC is not present at all.

So something within the kernel has changed here and I guess our selinux policy needs to adapt.  For now I'll push out a local selinux module via ansible.

Comment 17 Ian Kent 2020-09-09 08:30:59 UTC
(In reply to Jason Tibbitts from comment #16)
> I can confirm that the problem does not occur if I simply boot back to
> kernel-5.7.17-200.fc32.x86_64, with selinux enabled and the current policy
> installed.  If I boot kernel-5.8.4-200.fc32.x86_64 or
> kernel-5.8.6-201.fc32.x86_64 then the problem happens immediately when the
> first non-root user connects via ssh.  The problematic AVC is not present at
> all.
> 
> So something within the kernel has changed here and I guess our selinux
> policy needs to adapt.  For now I'll push out a local selinux module via
> ansible.

Yes, Christoph Hellwig did make a small change in there, I'm pretty sure
that went into 5.8.

It looked ok to me but there are some extra checks in the write function
that's now used.

I'm using 5.8.4-200 on the f32 vm I'm using, but maybe the kernel was
updated after I ran the tests, I'll need to re-check and see if I can
reproduce it.

Comment 18 Ian Kent 2020-09-09 08:33:39 UTC
(In reply to Jason Tibbitts from comment #15)
> I just wanted to make a note that I've been plagued by what appears to be
> the same issue for the past several days and I've been pulling my hair out
> trying to understand the problem.
> 
> Interestingly, I can ssh in as root and reference automounted filesystems
> without any issue.  But as soon as I try to ssh into the machine as a user,
> autofs stops mounting home directories.  And indeed I get a single selinux
> denial:
> 
> type=AVC msg=audit(1599630754.962:413): avc:  denied  { write } for 
> pid=16138 comm="sshd" path="pipe:[30431]" dev="pipefs" ino=30431
> scontext=system_u:system_r:sshd_t:s0-s0:c0.c1023
> tcontext=system_u:system_r:automount_t:s0 tclass=fifo_file permissive=0
> 
> But I edited /etc/selinux/conf to set permissive mode and rebooted.  Sadly
> it seems that's not enough to put the machine in permissive mode:
> 
> Loaded policy name:             targeted
> Current mode:                   enforcing
> Mode from config file:          permissive
> 
> That seems to be new because I really thought this used to work.  Anyway, I
> logged in as root after a reboot, ran setenforce 0, and then logged in as a
> user and now it works.  I still get just the one AVC, only now with
> permissive=1 at the end.

That's my understanding too.
Something must have changed.

Ian

Comment 19 Ian Kent 2020-09-10 02:18:41 UTC
(In reply to Ian Kent from comment #17)
> (In reply to Jason Tibbitts from comment #16)
> > I can confirm that the problem does not occur if I simply boot back to
> > kernel-5.7.17-200.fc32.x86_64, with selinux enabled and the current policy
> > installed.  If I boot kernel-5.8.4-200.fc32.x86_64 or
> > kernel-5.8.6-201.fc32.x86_64 then the problem happens immediately when the
> > first non-root user connects via ssh.  The problematic AVC is not present at
> > all.
> > 
> > So something within the kernel has changed here and I guess our selinux
> > policy needs to adapt.  For now I'll push out a local selinux module via
> > ansible.
> 
> Yes, Christoph Hellwig did make a small change in there, I'm pretty sure
> that went into 5.8.
> 
> It looked ok to me but there are some extra checks in the write function
> that's now used.
> 
> I'm using 5.8.4-200 on the f32 vm I'm using, but maybe the kernel was
> updated after I ran the tests, I'll need to re-check and see if I can
> reproduce it.

Aaaha, I have been able to reproduce it on the 5.8 kernel.

It's odd though, I was able to login ok, it wasn't until I tried to ssh
into a user after the home directory was umounted.

Restarting autofs and trying to log in again via ssh resulted in the
breakage your seeing.

However, although it's hard to find due to the log noise, I did see an
AVC like the one you reported above.

AVC avc:  denied  { write } for  pid=18511 comm="sshd" path="pipe:[125246]" dev="pipefs" ino=125246 scontext=system_u:system_r:sshd_t:s0-s0:c0.c1023 tcontext=system_u:system_r:automount_t:s0 tclass=fifo_file permissive=0

Continuing ...

Comment 20 Ian Kent 2020-09-10 02:31:11 UTC
Ok, so I created a local autofs type enforcement policy module for both
AVCs, the xdm one you had (which for some unknown reason I don't see)
and the sshd one I have seen.

The text of the module is:
[root@localhost ~]# cat local_autofs.te 

module local_autofs 1.0;

require {
	type sshd_t;
	type xdm_t;
	type automount_t;
	class fifo_file write;
}

#============= sshd_t ==============
allow sshd_t automount_t:fifo_file write;

#============= xdm_t ==============
allow xdm_t automount_t:fifo_file write;

and followed the procedure to create the binary module, loaded it
and then login via ssh worked ok.

So it still looks like this is an selinux restriction.

Can you check this also please.

Ian

Comment 21 Jason Tibbitts 2020-09-10 02:56:10 UTC
That policy module is identical the the one I deployed last night and it does appear to function (though I have not yet been able to go to the office to actually test a graphical login).

I do agree that the most reasonable path to a fix lies in the selinux policy, though at a higher level I think the real problem is one of coordination.  I'm just not sure how anyone would have known that the kernel shouldn't have been pushed without the selinux policy being updated.  I did do some testing, but by logging in as root and making sure I could still see automounted directories.  Sadly that doesn't trigger the issue.

Another question is whether autofs could have, well, done something useful instead of silently breaking.  Even in verbose mode it logs nothing.  Maybe it's not sitting at the right place to be able to even detect the problem and output something; I don't know enough to say.

In any case, I guess this should get reassigned to selinux-policy.

Comment 22 Ian Kent 2020-09-10 04:55:25 UTC
(In reply to Jason Tibbitts from comment #21)
> That policy module is identical the the one I deployed last night and it
> does appear to function (though I have not yet been able to go to the office
> to actually test a graphical login).

Lets's hope that works ok.

> 
> I do agree that the most reasonable path to a fix lies in the selinux
> policy, though at a higher level I think the real problem is one of
> coordination.  I'm just not sure how anyone would have known that the kernel
> shouldn't have been pushed without the selinux policy being updated.  I did
> do some testing, but by logging in as root and making sure I could still see
> automounted directories.  Sadly that doesn't trigger the issue.

Not sure I understand exactly what your saying but I think it refers to
things not breaking after you've checked if automounting is working.

If the mount corresponding to the home directory your testing with is
already mounted then the access problem won't occur because the mount
is already present and the VFS path walk will just follow the mount
when its accessed at login, so there won't be a write to the pipe.

> 
> Another question is whether autofs could have, well, done something useful
> instead of silently breaking.  Even in verbose mode it logs nothing.  Maybe
> it's not sitting at the right place to be able to even detect the problem
> and output something; I don't know enough to say.

Nothing gets logged from automount because it never sees anything, it
errors before that.

As I said I'm still thinking about this, but I'm leaning toward adding
handling of an additional error or two for the pipe return and perhaps
a error print to the kernel log. I really don't want to break the access
for the automount not running case though (like at system shutdown for
example) as that really needs to have the automount set to catatonic
mode.

That's going to take a while, I'll need to inspect the kernel write
functions and instrument a kernel to verify what errors are returned
for the case I have been able to reproduce.

Even if I do that the automount will still fail but the autofs mount
won't become crippled so an selinux change will still be needed.

> 
> In any case, I guess this should get reassigned to selinux-policy.

Right, let's just make sure the selinux change is working and I'll
do that, any kernel change will need to go upstream anyway so it's
a bit out of scope here.

Ian

Comment 23 Pierre Ossman 2020-09-21 14:45:50 UTC
We're also getting the sshd problems now, so things are screwed up again:

> Sep 21 16:34:26 samuel.lkpg.cendio.se audit[305057]: AVC avc:  denied  { write } for  pid=305057 comm="sshd" path="pipe:[42249]" dev="pipefs" ino=42249 scontext=system_u:system_r:sshd_t:s0-s0:c0.c1023 tcontext=system_u:system_r:automount_t:s0 tclass=fifo_file permissive=0

It got rid of the gdm issue though, so I think it is appropriate to involve the SELinux folks.

We also _only_ get the sshd stuff on one machine. It doesn't seem to suffer from the gdm/xdm trigger. It is running:

kernel-5.8.9-200.fc32.x86_64
selinux-policy-3.14.5-43.fc32.noarch
autofs-5.1.6-7.fc32.x86_64

Comment 24 Ian Kent 2020-09-23 02:36:12 UTC
(In reply to Pierre Ossman from comment #23)
> We're also getting the sshd problems now, so things are screwed up again:
> 
> > Sep 21 16:34:26 samuel.lkpg.cendio.se audit[305057]: AVC avc:  denied  { write } for  pid=305057 comm="sshd" path="pipe:[42249]" dev="pipefs" ino=42249 scontext=system_u:system_r:sshd_t:s0-s0:c0.c1023 tcontext=system_u:system_r:automount_t:s0 tclass=fifo_file permissive=0
> 
> It got rid of the gdm issue though, so I think it is appropriate to involve
> the SELinux folks.
> 
> We also _only_ get the sshd stuff on one machine. It doesn't seem to suffer
> from the gdm/xdm trigger. It is running:
> 
> kernel-5.8.9-200.fc32.x86_64
> selinux-policy-3.14.5-43.fc32.noarch
> autofs-5.1.6-7.fc32.x86_64

Ok, so there's another bug been reported on this and that's resulted in
upstream discussion about what should be done to resolve the problem
introduced by Christoph Hellwig's patch that changed the kernel write
function used by the autofs kernel module.

For the time being we'll need to continue to use selinux modules to
alter the pipe write permission.

Since the other bug relates to the upstream discussion I'm going to
set this as a duplicate of that bug so that others that see this
bug know where to look (and so you can track what's going on yourself).

Ian

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


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