Bug 1581502

+++ This bug was initially created as a clone of Bug #1552216 +++

Description of problem:
I've only noticed this problem because puppet keeps trying to restart autofs.service since it consults systemd which reports it's no longer running, which is in fact incorrect.  It is running, but the PID file either disappears or is never created.

Version-Release number of selected component (if applicable):
autofs-5.1.4-5.fc27.x86_64
systemd-234-10.git5f8984e.fc27.x86_64

How reproducible:
I have several F27 workstations managed nearly identically by puppet; some have never exhibited the behavior while two have.  One of those seems to have gotten better for unknown reasons while the other continues to be a problem where this is very reproducible.

Steps to Reproduce:
Boot and wait until login via ssh is possible.

Actual results:
Looking at the misbehaving host, I can see:

$ ps -fC automount
UID        PID  PPID  C STIME TTY          TIME CMD
root      1002     1  0 12:03 ?        00:00:00 /usr/sbin/automount -d --pid-file /run/autofs.pid

That looks good, however:

$ ls -l /run/autofs.pid
/bin/ls: cannot access '/run/autofs.pid': No such file or directory

The journal output and the debugging messages from boot to failure are attached.

--- Additional comment from John Florian on 2018-03-06 12:23:54 EST ---

I should also mention that I've put SELinux into Permissive mode, rebooted and seen the same results.

--- Additional comment from Ian Kent on 2018-03-06 19:11:17 EST ---

I'm not sure this is automount but it's as good a place to
start the investigation as any.

--- Additional comment from John Florian on 2018-03-07 09:12:23 EST ---

(In reply to Ian Kent from comment #2)
> I'm not sure this is automount but it's as good a place to
> start the investigation as any.

I feel/felt much the same.  I repeated my testing dozens of times before posting this.  At times I thought everything was ok because `systemctl status autofs` reported good, but I later learned it would do this for a short while even if the PID file wasn't present.  I think it uses a timeout waiting for the subprocess to be "ready".

I then was suspicious that something else (e.g., tmpwatch) was rm'ing the file but didn't find anything obvious.  I can say that /run/ has lots of other files (*.pid included) and even the autofs.fifo-* pipes.

I've stopped/disabled puppet to keep things simple.  I tried playing with auditctl/ausearch to capture more evidence but either it caught nothing or I'm doing it wrong.

Most confusing to me is how many other systems I have access to that work just fine.  That alone (combined with the consistency from puppet) tends to smell like a race condition.  But TBH, I'm out of ideas ATM.  :-/

--- Additional comment from Ian Kent on 2018-03-07 19:24:55 EST ---

(In reply to John Florian from comment #3)
> 
> Most confusing to me is how many other systems I have access to that work
> just fine.  That alone (combined with the consistency from puppet) tends to
> smell like a race condition.  But TBH, I'm out of ideas ATM.  :-/

Are they all using a 5.1.4 based rpm, what revisions?

I'm checking changes to the pid file handling code.

I know there is one recent one but there were couple of
other very small changes some time ago.

I think I'll focus on the most recent change for now.

It was meant to cover a case were a pid file contained a
valid pid but the executable itself was not automount.

That lead to a false positive when checking if the daemon
was already running.

This change went into 5.1.4 so it matches the appearance
of the problem.

There are two things I'd like to do, first try with this
change reverted, and second try with some extra logging
to work out what's broken.

Given the nature of the problem, not being consistently
reproducible, this might be difficult verify but I don't
see any other alternative.

Also I'd rather not make scratch builds, would you be ok
with me providing source rpms and having you build them
on one of your own machines?

Ian

--- Additional comment from Ian Kent on 2018-03-07 20:59:31 EST ---

(In reply to Ian Kent from comment #4)
> 
> Also I'd rather not make scratch builds, would you be ok
> with me providing source rpms and having you build them
> on one of your own machines?

If this is ok with you then please use the source rpms at
http://people.redhat.com/~ikent/autofs-test/

The one with reverted in the name has the recent change I
mentioned reverted.

The one with logging has instrumentation in the pid file
check and create code.

If you could give both of these a try that would be great.

Perhaps it will be best to try the instrumented package
first in case the one with the change reverted clears
whatever it is causing the problem.

There was another recent change to file create permissions
that isn't present in the f27 rpm but I'm pretty sure that
was needed because of changes to selinux policy and you have
tried in permissive mode. Probably not relevant. 

Ian

--- Additional comment from John Florian on 2018-03-08 09:23 EST ---



--- Additional comment from John Florian on 2018-03-08 09:24:29 EST ---

(In reply to Ian Kent from comment #4)
> (In reply to John Florian from comment #3)
> > 
> > Most confusing to me is how many other systems I have access to that work
> > just fine.  That alone (combined with the consistency from puppet) tends to
> > smell like a race condition.  But TBH, I'm out of ideas ATM.  :-/
> 
> Are they all using a 5.1.4 based rpm, what revisions?

Yes, with autofs-5.1.4-5.fc27.x86_64.

> There are two things I'd like to do, first try with this
> change reverted, and second try with some extra logging
> to work out what's broken.
> 
> Given the nature of the problem, not being consistently
> reproducible, this might be difficult verify but I don't
> see any other alternative.

No worries here.  If you're here to help and I'm here to do your bidding.  :-)
 
> Also I'd rather not make scratch builds, would you be ok
> with me providing source rpms and having you build them
> on one of your own machines?

WFM.  Just fed the logging variant into my koji and deployed on my "snoopy" host that has been very consistent in failing and thankfully continues to cooperate for us now.  Thus, same result: automount running as PID 1000, but no /run/autofs.pid file.  New log (from sudo journalctl -b -u autofs > /tmp/autofs.log) attached.

--- Additional comment from Ian Kent on 2018-03-08 20:15:39 EST ---

> systemd[1]: Starting Automounts filesystems on demand...
> automount[1000]: Starting automounter version 5.1.4-6.logging.fc27, master map auto.master
> automount[994]: aquire_flag_file: we_created_flagfile set to 1
> automount[994]: aquire_flag_file: flag file created, pid written to flag file, return 1

Pid file for automount process 1000 created ok.

> automount[1000]: using kernel protocol version 5.02
> automount[1000]: lookup_nss_read_master: reading master files auto.master

Snip uninteresting ...

> automount[1000]: do_init: parse(sun): init gathered global options: (null)
> automount[1000]: mounted indirect on /mnt with timeout 600, freq 150 seconds
> automount[1000]: st_ready: st_ready(): state = 0 path /mnt
> automount[1000]: ghosting enabled
> systemd[1]: Stopped Automounts filesystems on demand.

Umm .. that's not right!
systemd has stopped a service it is currently starting not
stopping. But we did see that before.

> systemd[1]: Starting Automounts filesystems on demand...

And now ....

> automount[1037]: flag_is_owned: pid 1000 tries 2
> automount[1037]: flag_is_owned: got pid from pid file
> automount[1037]: check_pid_exe_name: checking paths self /usr/sbin/automount and pid /usr/sbin/automount
> automount[1037]: check_pid_exe_name: pid exe name and self exe name match automount, return 1
> automount[1037]: aquire_flag_file: someone else made the link, return 0
> automount[1037]: /usr/sbin/automount: program is already running.

The pid file for automount process 1000 has been found by the
new automount process 1037 and it sees that automount process
1000 is already running, that's correct!

> systemd[1]: autofs.service: PID file /run/autofs.pid not readable (yet?) after start: No such file or directory

But now the pid file is gone!
I'll check if the automount code path, based on these log entries
results in removing the pid file.
Hopefully I will find something wrong there.

But that won't help the obvious systemd brokenness.

Ian

--- Additional comment from Ian Kent on 2018-03-08 20:45:25 EST ---

(In reply to Ian Kent from comment #8)
> > automount[1037]: aquire_flag_file: someone else made the link, return 0
> > automount[1037]: /usr/sbin/automount: program is already running.
> 
> The pid file for automount process 1000 has been found by the
> new automount process 1037 and it sees that automount process
> 1000 is already running, that's correct!
> 
> > systemd[1]: autofs.service: PID file /run/autofs.pid not readable (yet?) after start: No such file or directory
> 
> But now the pid file is gone!
> I'll check if the automount code path, based on these log entries
> results in removing the pid file.
> Hopefully I will find something wrong there.

It doesn't look like automount is removing the pid file.

But, based on the log output above, I've added a check and log
entry that will tell us if I'm correct or not.

Can you please give the newly uploaded source rpm a try.
It has the same file name but a newer date.

Ian

--- Additional comment from John Florian on 2018-03-09 15:16 EST ---



--- Additional comment from John Florian on 2018-03-09 15:20:03 EST ---

Ian, thanks for the play-by-play; that explains a lot of my early confusion, especially with the systemd oddity.  Newest log is ready for your perusal.

--- Additional comment from John Florian on 2018-03-09 15:50:01 EST ---

Here's something else I forgot to relay.  If one of these workstations does get rebooted and things are fouled as above, I can do the following and everything *will* be happy:

$ sudo stop systemctl
$ sudo kill PID_OF_RUNNING_AUTOMOUNT
$ sudo systemctl start autofs

After this, the PID file will exist and remain.  How this is so different from the situation right after boot I don't know.  It's the primary reason I suspected SEL at one point, since I figured starting as an "unconfined user" (may not be correct SEL terminology) might be at play, but I've ruled that out.  I'm still guessing a race condition and bootup just happens to get the timing right.  Anyway, just wanted to share this in case it's a good clue.

--- Additional comment from Ian Kent on 2018-03-10 00:55:29 EST ---

(In reply to John Florian from comment #12)
> Here's something else I forgot to relay.  If one of these workstations does
> get rebooted and things are fouled as above, I can do the following and
> everything *will* be happy:
> 
> $ sudo stop systemctl
> $ sudo kill PID_OF_RUNNING_AUTOMOUNT
> $ sudo systemctl start autofs
> 
> After this, the PID file will exist and remain.  How this is so different
> from the situation right after boot I don't know.  It's the primary reason I
> suspected SEL at one point, since I figured starting as an "unconfined user"
> (may not be correct SEL terminology) might be at play, but I've ruled that
> out.  I'm still guessing a race condition and bootup just happens to get the
> timing right.  Anyway, just wanted to share this in case it's a good clue.

I can't help but think this is something in systemd.
I can't ignore the fact it's trying to start autofs a second time,
which is plain wrong.

There was one more change that was made specifically for f28 that
appeared to be needed for selinux to fix some odd behaviour but I
didn't think it was relevant here because you tried with selinux
in permissive mode.

So there's only two more things that I think we can do.

First, add a stat(2) call immediately before automount exits to
make certain the pid file still exits when the second automount
process exits.

Add that f28 change (file create permissions change) in case the
odd permissions are confusing systemd causing it to do something
stupid.

I'll make another source rpm with these cahnges a bit later this
weekend.

Ian

--- Additional comment from Ian Kent on 2018-03-10 01:05:41 EST ---

(In reply to John Florian from comment #12)
> 
> After this, the PID file will exist and remain.  How this is so different
> from the situation right after boot I don't know.  It's the primary reason I
> suspected SEL at one point, since I figured starting as an "unconfined user"
> (may not be correct SEL terminology) might be at play, but I've ruled that
> out.  I'm still guessing a race condition and bootup just happens to get the
> timing right.  Anyway, just wanted to share this in case it's a good clue.

Except that systemd thinks it has stopped autofs while it's starting
it. What it does in that case I don't know and I'm not keen to look
because when I have looked at the systemd code in the past I've not
had much success in locating what I need.

The code in autofs that creates the pid file is more complicated
than I would like but when you realize the link(2) call is atomic
(at least it should be and if called simultaneously by two or
more processes only one will succeed) it makes more sense.

Point being I don't think there is a race in the autofs pid file
create and check code, at least I can't see it.

Ian

--- Additional comment from Ian Kent on 2018-03-11 21:35:37 EDT ---

Umm ... this is embarrassing.

The code that I have been looking at isn't managing the pid file.
It's managing the /run/autofs-running file, oops!

What's even more silly is that the race avoidance in
aquire_flag_file() obviously can't be used because automount
doesn't know what method systemd uses for locking during pid
file access and evaluation.

The only thing that automount does with the pid file is create
it if the daemon successfully forks and remove it at daemon
exit.

What it doesn't do is remove the pid file if startup fails
to complete after becoming a daemon. So a stale pid file can
exist.

But from systemd.service(5):
PIDFile=
  Takes an absolute file name pointing to the PID file of this daemon.
  Use of this option is recommended for services where Type= is set
  to forking. systemd will read the PID of the main process of the
  daemon after start-up of the service. systemd will not write to
  the file configured here, although it will remove the file after
  the service has shut down if it still exists.

So the service shutdown message seen in the log indicates that
systemd will (incorrectly) remove the pid file.

Anyway I've removed the previous logging and added checks for
pid file existence and contents at error exits when switching
to be a daemon (the site of the "already running" message).

Please try:
autofs-5.1.4-6.logging.2.fc27.src.rpm
at
http://people.redhat.com/~ikent/autofs-test/

Ian

--- Additional comment from John Florian on 2018-03-12 13:47 EDT ---



--- Additional comment from John Florian on 2018-03-12 13:48:06 EDT ---

(In reply to Ian Kent from comment #15)
> Umm ... this is embarrassing.

Jerry Seinfeld says that, "pain is knowledge rushing in to fill a gap."  (Like when you stub your toe in the dark, you now know where the corner of the bed is located.)  I say, if that's true then embarrassment must have its own corollary.  :-)  So, I'm certainly not passing any judgment here!
 
> The code that I have been looking at isn't managing the pid file.
> It's managing the /run/autofs-running file, oops!

Heh!  If I had a dollar for every time I put a sanity check message in my own code, only to find out I never get any such message.
 
> Please try:
> autofs-5.1.4-6.logging.2.fc27.src.rpm
> at
> http://people.redhat.com/~ikent/autofs-test/

Done.  Still no PID file though.  Latest log now attached.

--- Additional comment from Ian Kent on 2018-03-12 20:02:02 EDT ---

(In reply to John Florian from comment #16)
> Created attachment 1407307 [details]
> logging for autofs-5.1.4-6.logging.2.fc27.x86_64

From the log we can see:

> automount[992]: automount_path_to_fifo: fifo name /run/autofs.fifo-home
> automount[992]: lookup_nss_read_map: reading map file /etc/auto.master.d/_home.map
> automount[992]: do_init: parse(sun): init gathered global options: (null)
> automount[992]: mounted indirect on /home with timeout 600, freq 150 seconds
> automount[987]: /usr/sbin/automount: in parent, opened pid file /run/autofs.pid.
> automount[987]: pid line: 992

These two lines are from the parent process the daemon is
forked from. This is a check to see if the pid file exists
and check what it contains.

It clearly exists at this point and contains the pid of the
daemon process.

Just below that in the log there's:
> automount[992]: ghosting enabled
> systemd[1]: Stopped Automounts filesystems on demand.

according to the man page this deletes the pid file.

> systemd[1]: Starting Automounts filesystems on demand...
> automount[1008]: /usr/sbin/automount: program is already running.

This is established from /run/autofs-running, which we have seen
from previous logging work ok.

> automount[1008]: /usr/sbin/automount: in parent, failed to open pid file: No such file or directory
> automount[1008]: /usr/sbin/automount: in child, failed to open pid file: No such file or directory

And now the pid file is gone.

> systemd[1]: autofs.service: PID file /run/autofs.pid not readable (yet?) after start: No such file or directory
> automount[992]: handle_packet: type = 3

One thing all this logging we have collected shows is that when
the pid file is removed automount has not been anywhere near the
only place it removes the pid file.

This must be the systemd incorrect belief of systemd that the
service has been stopped while it is being started.

Perhaps Zbigniew Jędrzejewski-Szmek can help with this?

Ian

--- Additional comment from Zbigniew Jędrzejewski-Szmek on 2018-03-13 03:36:23 EDT ---

When systemd stops a service, it'll remove the pidfile. So most likely it's systemd that is removing the pidfile in the logs above.

autofs.service has KillMode=process, which means that the service itself is responsible for killing all of its children when it exists. It does not do that, and one of the remaining processes interferes with systemd trying to start automount again. I don't know what automount is doing exactly, but based on the logs above, it seems that:
1. systemd forks automount as pid 994
2. 994 forks 1000 to do the real work, writes a pidfile
3. 994 exits, so systemd thinks the daemon has exited
4. systemd tries to start automount again, forks 1037
5. 1037 sees the pidfile and exits
6. systemd removes the pidfile because start of the process failed

systemd should treat 1000 as the main process of the service, but it does not. Is 994 returning 0 (success) after it writes the pid file? If it returns anything else systemd will consider that the start process failed. You might want to enable systemd debug logging (systemctl set-log-level debug, or systemd.log-level=debug on the kernel command line), and then systemd will log those details.

--- Additional comment from John Florian on 2018-03-13 09:36 EDT ---

This latest attachment is much the same as the prior, but also includes systemd debugging.  This was produced with:

sudo journalctl -b SYSLOG_IDENTIFIER=systemd + _SYSTEMD_UNIT=autofs.service > /tmp/systemd+autofs.log

Of course, there's a lot more here that systemd is doing beyond autofs, but it's otherwise all inclusive and only limited by the fact that the host was freshly rebooted to reproduce the problem as that still seems to be the most reliable manner.  I tried a shorter capture of: 1) stopping autofs.service, 2) ensuring the automount process was gone, 3) ensuring the PID file was gone, and 4) starting autofs.service, but as before, this resulted in a clean startup of the service without the quirkiness we're chasing.  So a full reboot it is, er, was.

--- Additional comment from Ian Kent on 2018-03-13 21:18:52 EDT ---

(In reply to Zbigniew Jędrzejewski-Szmek from comment #19)
> When systemd stops a service, it'll remove the pidfile. So most likely it's
> systemd that is removing the pidfile in the logs above.

Yes, that's how it appears.

> 
> autofs.service has KillMode=process, which means that the service itself is
> responsible for killing all of its children when it exists. It does not do
> that, and one of the remaining processes interferes with systemd trying to
> start automount again. I don't know what automount is doing exactly, but
> based on the logs above, it seems that:

Ok, the KillMode=process is a recent change.

I think your saying that I've not done what's required for
that to function correctly and that could well be the case.

The reason the change was mode is that there are cases where
a restart needs to not kill certain sub-processes and it was
suggested that using KillMode=process was sufficient to fix
that problem.

> 1. systemd forks automount as pid 994
> 2. 994 forks 1000 to do the real work, writes a pidfile
> 3. 994 exits, so systemd thinks the daemon has exited
> 4. systemd tries to start automount again, forks 1037
> 5. 1037 sees the pidfile and exits
> 6. systemd removes the pidfile because start of the process failed

automount startup should be the same as it has been for quite
a while now and the above is what would be expected for any
daemon except for systemd trying to start the service again.

> 
> systemd should treat 1000 as the main process of the service, but it does
> not. Is 994 returning 0 (success) after it writes the pid file? If it
> returns anything else systemd will consider that the start process failed.
> You might want to enable systemd debug logging (systemctl set-log-level
> debug, or systemd.log-level=debug on the kernel command line), and then
> systemd will log those details.

It looks like it should be returning 0 but I can check that
by adding some more instrumentation. If it's not returning
0 when it should be I can fix that.

TBH I've assumed it is returning 0 because the log indicates
it should be, as has been the case for ages now. Making
assumptions is usually not good when trying to track down
a problem so my bad!

I'll also have a look at the new log that's been posted.

Thanks for answering my question so quickly, it's much
appreciated.

Ian

--- Additional comment from Ian Kent on 2018-03-13 22:25:16 EDT ---

I have posted:
autofs-5.1.4-6.logging.3.fc27.src.rpm
at
http://people.redhat.com/~ikent/autofs-test/

That should tell us what automount is returning.

One thing that I can see is that systemd is declaring the
autofs service stopped quite a while before its start up
is completed.

During start up there will be two processes running, possibly
for some time, in order for the parent to return a meaningful
status so I don't think that can be changed.

The amount of time automount spends starting up can be a bit
long now due to fairly recent changes.

Could this be causing a problem?

--- Additional comment from Ian Kent on 2018-03-13 22:30:37 EDT ---

(In reply to Ian Kent from comment #22)
> 
> During start up there will be two processes running, possibly
> for some time, in order for the parent to return a meaningful
> status so I don't think that can be changed.
> 
> The amount of time automount spends starting up can be a bit
> long now due to fairly recent changes.

Although, in this case it appears the autofs configuration
is good so the start up time appears to much the same as it
has been for a long time.

Ian

--- Additional comment from John Florian on 2018-03-14 13:34 EDT ---

Ian,

It looks like there's a type error that's preventing a successful build.  Please see the attached build.log.

--- Additional comment from Ian Kent on 2018-03-14 19:37:15 EDT ---

(In reply to John Florian from comment #24)
> Created attachment 1408101 [details]
> autofs-5.1.4-6.logging.3.fc27 build failed
> 
> Ian,
> 
> It looks like there's a type error that's preventing a successful build. 
> Please see the attached build.log.

Oh .. that's an obvious dumb mistake.

I must have added that after the original test build ....

--- Additional comment from Ian Kent on 2018-03-14 20:13:09 EDT ---

(In reply to Ian Kent from comment #25)
> (In reply to John Florian from comment #24)
> > Created attachment 1408101 [details]
> > autofs-5.1.4-6.logging.3.fc27 build failed
> > 
> > Ian,
> > 
> > It looks like there's a type error that's preventing a successful build. 
> > Please see the attached build.log.
> 
> Oh .. that's an obvious dumb mistake.
> 
> I must have added that after the original test build ....

Fixed, please try again.

--- Additional comment from John Florian on 2018-03-16 10:13 EDT ---



--- Additional comment from Ian Kent on 2018-03-16 22:46:04 EDT ---

The log implies that sm-notify is triggering an autofs restart,
at least that's what it looks like ....

So could you try adding "rpc-statd.service rpcbind.service"
(mostly for rpc-statd) to the "After" line in
/usr/lib/systemd/system/autofs.service and see if that
makes a difference.

I'd also be interested in what's in the statd state
directories, /var/lib/nfs/statd/sm and /var/lib/nfs/statd/sm.bak
before rebooting with the above unit change.

I'm tempted to say remove the statd monitor and notify lists
with "rm -rf /var/lib/nfs/statd/sm /var/lib/nfs/statd/sm.bak"
but I'm not sure what services should be stopped before doing
that and it might interfere with lock preservation over NFS
server restart.

Historically the client lists in the statd state directory
had very poor resemblance to the actual client list so I was
never very concerned about it myself at least when about to
reboot a machine.

--- Additional comment from John Florian on 2018-03-19 12:08:05 EDT ---

Before rebooting with the service file changes, I have:

$ sudo -i find /var/lib/nfs/statd/sm /var/lib/nfs/statd/sm.bak -ls
Agent pid 30994
   393419      4 drwx------   2  rpcuser  rpcuser      4096 Jan 19 12:55 /var/lib/nfs/statd/sm
   393420      4 drwx------   2  rpcuser  rpcuser      4096 Jan 19 12:55 /var/lib/nfs/statd/sm.bak

After rebooting with that change, the `find` returns the exact same results BUT I now have /run/autofs.pid and it appears that the service starts normally.  I can get another log, if desired but I suspect this info serves the purpose.

--- Additional comment from Ian Kent on 2018-03-19 21:14:42 EDT ---

(In reply to John Florian from comment #29)
> Before rebooting with the service file changes, I have:
> 
> $ sudo -i find /var/lib/nfs/statd/sm /var/lib/nfs/statd/sm.bak -ls
> Agent pid 30994
>    393419      4 drwx------   2  rpcuser  rpcuser      4096 Jan 19 12:55
> /var/lib/nfs/statd/sm
>    393420      4 drwx------   2  rpcuser  rpcuser      4096 Jan 19 12:55
> /var/lib/nfs/statd/sm.bak
> 
> After rebooting with that change, the `find` returns the exact same results
> BUT I now have /run/autofs.pid and it appears that the service starts
> normally.  I can get another log, if desired but I suspect this info serves
> the purpose.

Mmm ... I thought we would see something in those directories.
I thought you were running an NFS server on this machine ....

Anyway, my thinking on that was if autofs wasn't running when
statd was started a restart wouldn't be requested and that
sounds like it's the case. I'll make that change and hopefully
we'll be done with this one.

The reason the statd dependency was added to the autofs unit
was due to nfs mount running a script to start statd if it
wasn't already running at first mount. That script would
invoke systemctl to start statd which is ok in most cases
except ....

When a site has automount maps that use /usr/local bin and
possibly sbin directories to mount architecture dependent
directories the systemctl start would hang because it had
those same /usr/local directories in its PATH.

This would cause the boot to hang.

Ian

--- Additional comment from Zbigniew Jędrzejewski-Szmek on 2018-03-20 08:44:59 EDT ---

(In reply to Ian Kent from comment #22)
> I have posted:
> autofs-5.1.4-6.logging.3.fc27.src.rpm
> at
> http://people.redhat.com/~ikent/autofs-test/
> 
> That should tell us what automount is returning.
> 
> One thing that I can see is that systemd is declaring the
> autofs service stopped quite a while before its start up
> is completed.
> 
> During start up there will be two processes running, possibly
> for some time, in order for the parent to return a meaningful
> status so I don't think that can be changed.
> 
> The amount of time automount spends starting up can be a bit
> long now due to fairly recent changes.
> 
> Could this be causing a problem?
Not by itself. Various daemons start slowly and systemd has code to deal with that. Nevertheless, I expect that this slow start exposes a race somewhere the daemon startup notification. It is possible that the fact that the restart signal comes at an inconvenient time triggers that bug.

Looking at the code, I see that the only place where a signal handling happens is in statemachine() in the child. This means that if the parent receives a signal, it will just terminate, i.e. it will not kill the child properly. So a trivial sequence of events would be:
1. systemd forks parent
2. parent forks child
3. a restart request comes in
4. parent receives a notification from child, spends some time writing a pid file
5. the restart request results in systemd sending SIGTERM to parent
6. parent terminates
7. child carries on

Normally, if KillMode= was at the default setting, systemd would also terminate the child, but here it does not.

What about simply doing away with daemonization and replacing that with --foreground, Type=notify, and a call to sd_notify("READY=1") in the line in the child that sends the notification to parent that it is ready? This should be vastly simpler and more reliable.

--- Additional comment from Zbigniew Jędrzejewski-Szmek on 2018-03-20 09:04 EDT ---

See attached patch (not even compile tested, just a quick proof of concept).

--- Additional comment from John Florian on 2018-03-20 09:05:45 EDT ---

(In reply to Ian Kent from comment #30)
 
> Mmm ... I thought we would see something in those directories.
> I thought you were running an NFS server on this machine ....

This one is just a NFS client.  I'm guessing your determination for this was based on what services are running.  My puppet manifests manage most all of the NFS client (and server) services, but I won't swear my puppet code is correct for what's needed where.  That's never been overly clear to me and I'm not sure it was even clear to the the packaging folks over the years watching how some of these got juggled around.  Then again, that might be NFS v2/3/4 evolution.

> Anyway, my thinking on that was if autofs wasn't running when
> statd was started a restart wouldn't be requested and that
> sounds like it's the case. I'll make that change and hopefully
> we'll be done with this one.
> 
> The reason the statd dependency was added to the autofs unit
> was due to nfs mount running a script to start statd if it
> wasn't already running at first mount. That script would
> invoke systemctl to start statd which is ok in most cases
> except ....
> 
> When a site has automount maps that use /usr/local bin and
> possibly sbin directories to mount architecture dependent
> directories the systemctl start would hang because it had
> those same /usr/local directories in its PATH.
> 
> This would cause the boot to hang.

The tangled webs we weave.  :-)  Thank goodness systemd lets these relationships be expressed so succinctly and precisely.  I don't envy anyone trying to figure out what goes where and when at the generic level of Fedora as a whole.

--- Additional comment from John Florian on 2018-03-20 09:10:38 EDT ---

(In reply to Zbigniew Jędrzejewski-Szmek from comment #32)
> Created attachment 1410456 [details]
> POC patch to use sd_notify
> 
> See attached patch (not even compile tested, just a quick proof of concept).

If someone can get this into srpm format I'll be happy to test it.  My koji doesn't have a distgit setup so patches aren't as trivial for me as I'd like.

--- Additional comment from Ian Kent on 2018-03-20 22:31:33 EDT ---

(In reply to Zbigniew Jędrzejewski-Szmek from comment #31)
> > The amount of time automount spends starting up can be a bit
> > long now due to fairly recent changes.
> > 
> > Could this be causing a problem?
> Not by itself. Various daemons start slowly and systemd has code to deal
> with that. Nevertheless, I expect that this slow start exposes a race
> somewhere the daemon startup notification. It is possible that the fact that
> the restart signal comes at an inconvenient time triggers that bug.
> 
> Looking at the code, I see that the only place where a signal handling
> happens is in statemachine() in the child. This means that if the parent
> receives a signal, it will just terminate, i.e. it will not kill the child
> properly. So a trivial sequence of events would be:

Yes, the list of blocked signals set at the beginning of main()
doesn't include SIGTERM (and a couple of others) but I don't
think that's sufficient since systemd could send a SIGKILL if
a SIGTERM doesn't get the job done.

> 1. systemd forks parent
> 2. parent forks child
> 3. a restart request comes in
> 4. parent receives a notification from child, spends some time writing a pid
> file
> 5. the restart request results in systemd sending SIGTERM to parent
> 6. parent terminates
> 7. child carries on

Yes, that could be happening based on the most recent log.

> 
> Normally, if KillMode= was at the default setting, systemd would also
> terminate the child, but here it does not.
> 
> What about simply doing away with daemonization and replacing that with
> --foreground, Type=notify, and a call to sd_notify("READY=1") in the line in
> the child that sends the notification to parent that it is ready? This
> should be vastly simpler and more reliable.

I'll need to think about the implications of that for a bit.

--- Additional comment from Ian Kent on 2018-03-20 22:33:10 EDT ---

(In reply to Zbigniew Jędrzejewski-Szmek from comment #32)
> Created attachment 1410456 [details]
> POC patch to use sd_notify
> 
> See attached patch (not even compile tested, just a quick proof of concept).

I'll need to make a patch based on this, there's not quite
enough there I think.

--- Additional comment from Ian Kent on 2018-03-21 01:35:19 EDT ---

(In reply to John Florian from comment #34)
> (In reply to Zbigniew Jędrzejewski-Szmek from comment #32)
> > Created attachment 1410456 [details]
> > POC patch to use sd_notify
> > 
> > See attached patch (not even compile tested, just a quick proof of concept).
> 
> If someone can get this into srpm format I'll be happy to test it.  My koji
> doesn't have a distgit setup so patches aren't as trivial for me as I'd like.

I have posted:
autofs-5.1.4-6.systemd.1.fc27.src.rpm
at
http://people.redhat.com/~ikent/autofs-test/

Please give this a try.

Also please ensure that the unit file change of comment #28
is not present so we can try and reproduce the original
problem.

Can you also post a log with systemd debugging enabled so
we can see what happens with the change.

--- Additional comment from John Florian on 2018-03-21 11:05 EDT ---

I got a build failure with this due to a missing BR on systemd-devel.  I got around that with:

--- SPECS/autofs.spec.orig      2018-03-21 10:27:00.318328355 -0400
+++ SPECS/autofs.spec   2018-03-21 10:27:04.520544018 -0400
@@ -27,6 +27,7 @@

 %if %{with_systemd}
 BuildRequires: systemd-units
+BuildRequires: systemd-devel
 %endif
 BuildRequires: gcc
 BuildRequires: autoconf, hesiod-devel, openldap-devel, bison, flex, libxml2-devel

So onto the test.

$ rpm -q autofs
autofs-5.1.4-6.systemd.1.fc27.x86_64
$ rpm -Vf /usr/lib/systemd/system/autofs.service
S.5....T.  c /etc/auto.master
..?......  c /etc/autofs_ldap_auth.conf
S.5....T.  c /etc/sysconfig/autofs

Good to go!  Rebooted and it looks to me like a good startup.  There's no PID file, but it looks like that's expected now.  Logs are attached from:

sudo journalctl -b SYSLOG_IDENTIFIER=systemd + _SYSTEMD_UNIT=autofs.service | xz > /tmp/systemd+autofs.log.xz

--- Additional comment from Ian Kent on 2018-03-21 20:06:10 EDT ---

(In reply to John Florian from comment #38)
> Created attachment 1411248 [details]
> autofs-5.1.4-6.systemd.1.fc27.x86_64  logging
> 
> I got a build failure with this due to a missing BR on systemd-devel.  I got
> around that with:
> 
> --- SPECS/autofs.spec.orig      2018-03-21 10:27:00.318328355 -0400
> +++ SPECS/autofs.spec   2018-03-21 10:27:04.520544018 -0400
> @@ -27,6 +27,7 @@
> 
>  %if %{with_systemd}
>  BuildRequires: systemd-units
> +BuildRequires: systemd-devel

Of course, my bad.
I just use my local system for the build test so I missed that.

>  %endif
>  BuildRequires: gcc
>  BuildRequires: autoconf, hesiod-devel, openldap-devel, bison, flex,
> libxml2-devel
> 
> So onto the test.
> 
> $ rpm -q autofs
> autofs-5.1.4-6.systemd.1.fc27.x86_64
> $ rpm -Vf /usr/lib/systemd/system/autofs.service
> S.5....T.  c /etc/auto.master
> ..?......  c /etc/autofs_ldap_auth.conf
> S.5....T.  c /etc/sysconfig/autofs
> 
> Good to go!  Rebooted and it looks to me like a good startup.  There's no
> PID file, but it looks like that's expected now.  Logs are attached from:

Thanks, I'll check.

--- Additional comment from Ian Kent on 2018-03-21 20:36:21 EDT ---

I'm not sure we have captured an instance of the original problem.

systemd[1]: Starting NFS status monitor for NFSv2/3 locking....
systemd[982]: rpc-statd.service: Executing: /usr/sbin/rpc.statd
systemd[1]: Starting Notify NFS peers of a restart...
systemd[983]: rpc-statd-notify.service: Executing: /usr/sbin/sm-notify
systemd[1]: Starting Automounts filesystems on demand...
systemd[985]: autofs.service: Executing: /usr/sbin/automount -d --foreground --dont-check-daemon
systemd[1]: Started Notify NFS peers of a restart.
Starting Preprocess NFS configuration...
systemd[987]: nfs-config.service: Executing: /usr/libexec/nfs-utils/nfs-utils_env.sh
systemd[1]: Stopped Automounts filesystems on demand.
systemd[990]: autofs.service: Executing: /usr/sbin/automount -d --foreground --dont-check-daemon
systemd[1]: Starting Automounts filesystems on demand...
systemd[1]: Started Preprocess NFS configuration.
systemd[1]: Started Dynamic System Tuning Daemon.
automount[990]: Starting automounter version 5.1.4-6.systemd.1.fc27, master map auto.master

I think this demonstrates that the NFS sm-notify requests a
restart of autofs but autofs hasn't begun when it does this
so it isn't interrupted as it was in previous logs.

It looks more like what I would expect from the "After=" change.

Perhaps the "After=" change has changed something and systemd
doesn't see a need to change it back or perhaps there's another
mistake in the rpm install.

While I don't particularly like this change I'm willing to
accept it upstream so perhaps the best thing to do is use
this along with the "After=" change to be absolutely sure
the problem is covered.

Thoughts?

--- Additional comment from Ian Kent on 2018-03-21 21:21 EDT ---

Note: this is against the upstream code tree. It need minor changes
to apply to f27.

--- Additional comment from Ian Kent on 2018-03-21 21:23 EDT ---

Note: This patch is against the upstream code tree. It will need
minor changes for f27.

--- Additional comment from John Florian on 2018-03-22 17:55 EDT ---

(In reply to Ian Kent from comment #40)
> I'm not sure we have captured an instance of the original problem.

Drats!  It had been so consistent.

> I think this demonstrates that the NFS sm-notify requests a
> restart of autofs but autofs hasn't begun when it does this
> so it isn't interrupted as it was in previous logs.

I missed that.  I've reboot several times and even tried reinstalling this autofs build (to wiggle the systemd wires, so to speak), but I'm getting results consistent with the last you've seen.

> It looks more like what I would expect from the "After=" change.

While my `rpm -V` verified OK, a quick sanity test...

$ systemctl cat autofs.service | grep After=
After=network.target ypbind.service sssd.service network-online.target remote-fs.target

 
> Perhaps the "After=" change has changed something and systemd
> doesn't see a need to change it back or perhaps there's another
> mistake in the rpm install.

Not sure what to think here.  Wait, crap!  I just had an idea.  I went back and installed the problematic version, well autofs-1:5.1.4-6.fc27 actually (-6 vs -5 originally), got my original failures and then went back to autofs-1:5.1.4-6.systemd.1.fc27 and now I think I've caught it being restarted.  Then I realized I had puppet enabled/started (to config autofs for me).  This made me skittish that it might've been involved, so I stopped/disabled puppet and rebooted one more time.  Good news!  I think I've got the logging you want showing automount being restarted.  Phew!  Please see the attached.

--- Additional comment from Ian Kent on 2018-03-22 20:57:16 EDT ---

(In reply to John Florian from comment #43)
> 
> Not sure what to think here.  Wait, crap!  I just had an idea.  I went back
> and installed the problematic version, well autofs-1:5.1.4-6.fc27 actually
> (-6 vs -5 originally), got my original failures and then went back to
> autofs-1:5.1.4-6.systemd.1.fc27 and now I think I've caught it being
> restarted.  Then I realized I had puppet enabled/started (to config autofs
> for me).  This made me skittish that it might've been involved, so I
> stopped/disabled puppet and rebooted one more time.  Good news!  I think
> I've got the logging you want showing automount being restarted.  Phew! 
> Please see the attached.

Ha, did you change the autofs configuration?
Looks like there's no autofs debugging output in the log.

It does appear as though the problem was reproduced but we can't
be sure until we can see where autofs is in it's startup when it
receives the SIGTERM and restart request.

It's also worth mentioning that it shouldn't matter if some of
the mounts are mounted and not cleaned up because the signal
arrives at the wrong time for automount. automount should just
re-connect to them on the next startup.

--- Additional comment from John Florian on 2018-03-23 09:33 EDT ---

(In reply to Ian Kent from comment #44)
> Ha, did you change the autofs configuration?
> Looks like there's no autofs debugging output in the log.

Doh!  Yes, I did.  In an earlier attempt to get it "broken" again, I had tried a simple package remove/install.  That "lost" the configs and I just used puppet to put things back exactly like they once were.  It just happened to be the wrong "once".  Sorry about that.  I get crosstalk in my brain debugging too many things at once.
 
> It does appear as though the problem was reproduced but we can't
> be sure until we can see where autofs is in it's startup when it
> receives the SIGTERM and restart request.

Looks like we're in luck.  autofs is logging debug again and the restart of automount was once again captured.

--- Additional comment from Ian Kent on 2018-03-25 01:21:54 EDT ---

(In reply to John Florian from comment #45)
> Created attachment 1412106 [details]
> new and improved, now with two scoops of debug
> 
> (In reply to Ian Kent from comment #44)
> > Ha, did you change the autofs configuration?
> > Looks like there's no autofs debugging output in the log.
> 
> Doh!  Yes, I did.  In an earlier attempt to get it "broken" again, I had
> tried a simple package remove/install.  That "lost" the configs and I just
> used puppet to put things back exactly like they once were.  It just
> happened to be the wrong "once".  Sorry about that.  I get crosstalk in my
> brain debugging too many things at once.
>  
> > It does appear as though the problem was reproduced but we can't
> > be sure until we can see where autofs is in it's startup when it
> > receives the SIGTERM and restart request.
> 
> Looks like we're in luck.  autofs is logging debug again and the restart of
> automount was once again captured.

Indeed, that log looks like it is doing what was intended.

It looks like statd was started but systemd didn't do anything
until autofs notified it that startup was complete. It them
shutdown autofs and started it again.

I'll add both of the changes anyway (above), just to be sure.

Thanks for your efforts and persistence in working this, ;)

Ian

--- Additional comment from Fedora Update System on 2018-03-25 23:01:34 EDT ---

autofs-5.1.4-7.fc27 has been submitted as an update to Fedora 27. https://bodhi.fedoraproject.org/updates/FEDORA-2018-fa53dc3267

--- Additional comment from John Florian on 2018-03-26 11:28:38 EDT ---

(In reply to Ian Kent from comment #46)

> Thanks for your efforts and persistence in working this, ;)

Right back at ya!

--- Additional comment from Fedora Update System on 2018-03-26 12:41:38 EDT ---

autofs-5.1.4-7.fc27 has been pushed to the Fedora 27 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-2018-fa53dc3267

--- Additional comment from Fedora Update System on 2018-03-30 09:55:50 EDT ---

autofs-5.1.4-7.fc27 has been pushed to the Fedora 27 stable repository. If problems still persist, please make note of it in this bug report.

--- Additional comment from John Florian on 2018-05-22 19:03:13 EDT ---

I am now seeing this problem with autofs-5.0.7-83.el7.x86_64 (on CentOS 7.5).  Do you want to continue that here or in a new ticket?  If a new ticket, where is best, here for EL7 or at https://bugs.centos.org?

--- Additional comment from Ian Kent on 2018-05-22 19:58:03 EDT ---

(In reply to John Florian from comment #51)
> I am now seeing this problem with autofs-5.0.7-83.el7.x86_64 (on CentOS
> 7.5).  Do you want to continue that here or in a new ticket?  If a new
> ticket, where is best, here for EL7 or at https://bugs.centos.org?

I'll clone this bug for RHEL-7 and see how we go.