Created attachment 1404967 [details] output of `journalctl -b -u autofs` 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.
I should also mention that I've put SELinux into Permissive mode, rebooted and seen the same results.
I'm not sure this is automount but it's as good a place to start the investigation as any.
(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. :-/
(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
(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
Created attachment 1405876 [details] same but from autofs-5.1.4-6.logging.fc27.x86_64
(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.
> 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
(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
Created attachment 1406386 [details] from comment 10
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.
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.
(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
(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
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
Created attachment 1407307 [details] logging for autofs-5.1.4-6.logging.2.fc27.x86_64
(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.
(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
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.
Created attachment 1407575 [details] logging from autofs-5.1.4-6.logging.2.fc27.x86_64 with systemd debugging 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.
(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
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?
(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
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.
(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 ....
(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.
Created attachment 1408813 [details] logging from autofs-5.1.4-6.logging.3.fc27 with systemd debugging
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.
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.
(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
(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.
Created attachment 1410456 [details] POC patch to use sd_notify See attached patch (not even compile tested, just a quick proof of concept).
(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.
(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.
(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.
(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.
(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.
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 %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
(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.
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?
Created attachment 1411558 [details] Patch - add units After line to include statd service Note: this is against the upstream code tree. It need minor changes to apply to f27.
Created attachment 1411559 [details] Patch - use systemd sd_notify() at startup Note: This patch is against the upstream code tree. It will need minor changes for f27.
Created attachment 1411868 [details] another stab at autofs-5.1.4-6.systemd.1.fc27.x86_64 logging (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.
(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.
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.
(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
autofs-5.1.4-7.fc27 has been submitted as an update to Fedora 27. https://bodhi.fedoraproject.org/updates/FEDORA-2018-fa53dc3267
(In reply to Ian Kent from comment #46) > Thanks for your efforts and persistence in working this, ;) Right back at ya!
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
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.
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?
(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.
Thanks Ian! I wasn't even aware of BZs clone feature. That's perfect.