Re: cfengine watchdog is not biting
Xander Cage <[email protected]> Mon, 11 Mar 2024 05:47:02 -0700 (PDT)
| Newsgroups | gmane.comp.sysutils.cfengine.general |
|---|---|
| Message-ID | <[email protected]> |
btw...i think we found out what was to reason for all this...it seems to have to do with lpar reboots...if the watchdog is running at reboot time, it gets killed mid run and the pidfile is not removed and the registered pid "MIGHT" be picked up by another process (even in aix, which has some countermeasures against this) which leads to the discribed problems. On Monday, March 11, 2024 at 1:39:58 PM UTC+1 Xander Cage wrote: > here you go...not changed much tho... > > root@aixtest01: /root # bash -c 'ps -p $$; echo $$ > > /var/cfengine/watchdog_changed.pid; /opt/freeware/bin/sleep infinity' & > [1] 17432958 > root@aixtest01: /root # PID TTY TIME CMD > 17432958 pts/11 0:00 bash_64 > > root@aixtest01: /root # /var/cfengine/bin/watchdog_changed > We have a pidfile > No current process matching pid in file > > > On Thursday, March 7, 2024 at 4:55:05 AM UTC+1 [email protected] wrote: > >> Thanks, Xander. >> >> On closer inspection and some testing on a Linux system, there is a >> possible race condition where a process can actually have a /proc entry >> that is a fraction of a second *newer* than a file created by that very >> process. That's why the commands I gave you for testing didn't function as >> expected. >> >> Example output: >> >> # bash -c 'echo $$ > pidfile; ls -ldt --full-time pidfile /proc/$$' >> dr-xr-xr-x 9 root root 0 2024-03-07 03:31:15.961650417 +0000 /proc/742781 >> -rw-r--r-- 1 root root 7 2024-03-07 03:31:15.953650428 +0000 pidfile >> >> On the surface of it this would look like a bug, wherein my modified >> watchdog could potentially see a factually valid pidfile that matched the >> actual running instance of the watchdog that generated the pidfile—but the >> new watchdog would disregard the pidfile because it's *older* than the >> running process, according to /proc. This would be a problem. >> >> However, when I added a run of 'ps -p $$' in my test command ahead of the >> pidfile creation, I was unable to trigger the race condition and the >> timestamps are much further apart than the discrepancy shown above. (I >> tried many times; the sequence of events seems completely reliable and the >> time interval much more consistent.) >> >> # bash -c 'ps -p $$; echo $$ > pidfile; ls -ldt --full-time pidfile >> /proc/$$' >> PID TTY TIME CMD >> 750818 pts/1 00:00:00 bash >> -rw-r--r-- 1 root root 7 2024-03-07 03:36:57.569061554 +0000 pidfile >> dr-xr-xr-x 9 root root 0 2024-03-07 03:36:57.537061615 +0000 /proc/750818 >> >> I speculate that the /proc entry *has* to be created before the ps >> command can run successfully, so the kernel will do that before continuing, >> whereas in the earlier command the pidfile can go ahead and get created >> when the kernel hasn't yet bothered with the /proc update. In the >> watchdog code, there is a run of ps -p on the pidfile contents before >> pidfile creation, so I think it is *likely* impossible for this race >> condition to be hit with the script as written. (I can't prove it >> definitively.) >> >> In any case—could you please try the following modified test command? >> Just the one test case, since this is the only "interesting" code path >> left untested. >> >> bash -c 'ps -p $$; echo $$ > /var/cfengine/watchdog_changed.pid; >> /opt/freeware/bin/sleep infinity' & >> /var/cfengine/bin/watchdog_changed >> >> Expected output from the second part: >> >> We have a pidfile >> There is a process with the PID in the file, but is it stale? >> We can know for sure if it's stale >> Pidfile is definitely correct >> >> Best, >> --Mike Weilgart >> >> On Feb 27, 2024, at 7:15 AM, Xander Cage <[email protected]> wrote: >> >> new run with echoes... >> >> root@aixtest01: /root # bash -c 'echo $$ > >> /var/cfengine/watchdog_changed.pid && exec /opt/freeware/bin/sleep >> infinity' & >> [1] 4456792 >> root@aixtest01: /root # /var/cfengine/bin/watchdog_changed >> We have a pidfile >> There is a process with the PID in the file, but is it stale? >> We can know for sure if its stale >> Pidfile is stale, ignore it >> >> root@aixtest01: /root # bash -c 'echo $$ > >> /var/cfengine/watchdog_changed.pid' >> root@aixtest01: /root # /var/cfengine/bin/watchdog_changed >> We have a pidfile >> No current process matching pid in file >> >> root@aixtest01: /root # bash -c 'echo $$ > >> /var/cfengine/watchdog_changed.pid && touch -t 02210927 >> /var/cfengine/watchdog_changed.pid && exec /opt/freeware/bin/sleep >> infinity' & >> [2] 12321240 >> root@aixtest01: /root # /var/cfengine/bin/watchdog_changed >> We have a pidfile >> There is a process with the PID in the file, but is it stale? >> We can know for sure if its stale >> Pidfile is stale, ignore it >> >> [2]+ Stopped bash -c 'echo $$ > >> /var/cfengine/watchdog_changed.pid && touch -t 02210927 >> /var/cfengine/watchdog_changed.pid && exec /opt/freeware/bin/sleep infinity' >> >> On Monday, February 26, 2024 at 7:54:42 PM UTC+1 [email protected] >> wrote: >> >>> Hi Xander, >>> >>> From that output it doesn't appear that the edited watchdog is looking >>> at the same modified location for the pidfile as you're using, since the >>> first test should have produced an "abort" message. >>> >>> Could you please run those same tests again but convert the inline >>> comments to echo commands as shown below, so we can see which branch is >>> being taken? >>> >>> Expected results: Your first test should give "Pidfile is definitely >>> correct" and an abort message; second test should say "Pidfile is stale, >>> ignore it"; third test should say "No current process matching pid in file". >>> >>> Best, >>> --Mike Weilgart >>> >>> ###### >>> if [ -s $PIDFILE ]; then >>> echo We have a pidfile >>> if ps -p $(cat $PIDFILE) > /dev/null 2>&1 ; then >>> echo 'There is a process with the PID in the file, but is it >>> stale?' >>> if [ -d /proc ]; then >>> echo "We can know for sure if it's stale" >>> actual_process="/proc/$(cat "$PIDFILE")" >>> newer="$(ls -1dt "$PIDFILE" "$actual_process" | head -n 1)" >>> if [ "$actual_process" = "$newer" ]; then >>> echo Pidfile is stale, ignore it >>> echo $$ > $PIDFILE >>> else >>> >>> echo Pidfile is definitely correct >>> echo "$(date) Aborting execution of watchdog $$, >>> existing watchdog process $(cat $PIDFILE) running" >> ${LOGFILE} >>> exit 1 >>> fi >>> else >>> echo "No /proc, pidfile shows a running process, we'll >>> assume it's valid" >>> echo "$(date) Aborting execution of watchdog $$, existing >>> watchdog process $(cat $PIDFILE) running" >> ${LOGFILE} >>> exit 1 >>> fi >>> else >>> echo No current process matching pid in file >>> echo $$ > $PIDFILE >>> fi >>> else >>> echo No pidfile at all >>> echo $$ > $PIDFILE >>> fi >>> ###### >>> >>> On Feb 26, 2024, at 1:44 AM, Xander Cage <[email protected]> wrote: >>> >>> did the requested tests... >>> >>> >>> root@aixtest01: /root # bash -c 'echo $$ > >>> /var/cfengine/watchdog_changed.pid && exec /opt/freeware/bin/sleep >>> infinity' & >>> [2] 22020394 >>> root@aixtest01: /root # /var/cfengine/bin/watchdog_changed >>> >>> log output: >>> >>> Mon Feb 26 10:36:45 CET 2024 Initiating watchdog 4456948 >>> Mon Feb 26 10:36:47 CET 2024 Found 0 symptoms, threshold (0) not >>> breached, no remediation or collection performed >>> Mon Feb 26 10:36:47 CET 2024 DONE watchdog 4456948 >>> >>> >>> root@aixtest01: /root # bash -c 'echo $$ > >>> /var/cfengine/watchdog_changed.pid' >>> root@aixtest01: /root # /var/cfengine/bin/watchdog_changed >>> >>> log output: >>> >>> Mon Feb 26 10:37:52 CET 2024 Initiating watchdog 17432960 >>> Mon Feb 26 10:37:53 CET 2024 Found 0 symptoms, threshold (0) not >>> breached, no remediation or collection performed >>> Mon Feb 26 10:37:53 CET 2024 DONE watchdog 17432960 >>> >>> >>> root@aixtest01: /root # bash -c 'echo $$ > >>> /var/cfengine/watchdog_changed.pid && touch -t 02210927 >>> /var/cfengine/watchdog_changed.pid && exec /opt/freeware/bin/sleep >>> infinity' & >>> [3] 32964974 >>> root@aixtest01: /root # /var/cfengine/bin/watchdog_changed >>> >>> [3]+ Stopped bash -c 'echo $$ > >>> /var/cfengine/watchdog_changed.pid && touch -t 02210927 >>> /var/cfengine/watchdog_changed.pid && exec /opt/freeware/bin/sleep infinity' >>> >>> log output: >>> >>> Mon Feb 26 10:39:28 CET 2024 Initiating watchdog 12321050 >>> Mon Feb 26 10:39:31 CET 2024 Found 0 symptoms, threshold (0) not >>> breached, no remediation or collection performed >>> Mon Feb 26 10:39:31 CET 2024 DONE watchdog 12321050 >>> >>> expected something more exiting...but it is what is i guess.... >>> >>> >>> On Friday, February 23, 2024 at 9:20:49 AM UTC+1 Xander Cage wrote: >>> >>>> no problem...will do the tests next week... >>>> >>>> On Thursday, February 22, 2024 at 6:32:06 PM UTC+1 [email protected] >>>> wrote: >>>> >>>>> Thanks Xander, >>>>> >>>>> You could test it by running something like: >>>>> >>>>> bash -c 'echo $$ > /var/cfengine/watchdog.pid && exec sleep infinity' & >>>>> >>>>> Running bash separately ensures the pid will be different, and the >>>>> exec makes the sleep run with the same PID as the shell was running with >>>>> (i.e. that PID is taken oven by the sleep) and the & makes it all happen in >>>>> the background. >>>>> >>>>> Then you've got a pidfile showing a valid, running process that is >>>>> definitely using that pid. >>>>> >>>>> To simulate stale pidfile with no process using that pid is easy, just >>>>> put a number in there and then exit: >>>>> >>>>> bash -c 'echo $$ > /var/cfengine/watchdog.pid' >>>>> >>>>> To simulate stale pidfile where there is a process running on that pid >>>>> but it's newer than the pidfile is also possible; it requires use of touch >>>>> to set an old mtime. Checking AIX docs ( >>>>> https://www.ibm.com/docs/en/aix/7.3?topic=t-touch-command) it looks >>>>> like it should be something like: >>>>> >>>>> bash -c 'echo $$ > /var/cfengine/watchdog.pid && touch -t >>>>> 02210927 /var/cfengine/watchdog.pid && exec sleep infinity' & >>>>> >>>>> (That would set the mtime to 24 hours ago at this writing - Feb 21 at >>>>> 9:27 in the morning.) >>>>> >>>>> Then in each case run the watchdog and see what happens, maybe convert >>>>> my inline comments to echo commands so you can see which branch is taken. >>>>> (E.g. echo "Pidfile is definitely correct") >>>>> >>>>> I much prefer submitting fully tested code but unfortunately I don't >>>>> have access to any AIX systems, so if you could try the above it would be >>>>> very much appreciated. :) And this way any issues can be found before the >>>>> updated code is included in any release. >>>>> >>>>> Best, >>>>> --Mike Weilgart >>>>> >>>>> On Feb 22, 2024, at 5:26 AM, Xander Cage <[email protected]> wrote: >>>>> >>>>> forgot to post the error: >>>>> >>>>> root@aixtest01: /root # /var/cfengine/bin/watchdog_changed >>>>> /var/cfengine/bin/watchdog_changed[52]: syntax error at line 64 : >>>>> `else' unexpected >>>>> >>>>> On Thursday, February 22, 2024 at 2:25:03 PM UTC+1 Xander Cage wrote: >>>>> >>>>>> i dont think the problematic situation can be simulated, but running >>>>>> the changed script shows a missing "then" ;-) >>>>>> >>>>>> >>>>>> https://github.com/cfengine/masterfiles/blob/70eb84ad845af716fdc53b1299544e7b521a563d/cfe_internal/core/watchdog/templates/watchdog.mustache#L60 >>>>>> >>>>>> after adding it, the scripts runs without errors.... >>>>>> >>>>>> On Thursday, February 22, 2024 at 2:47:24 AM UTC+1 >>>>>> [email protected] wrote: >>>>>> >>>>>>> I opened a pull request: >>>>>>> https://github.com/cfengine/masterfiles/pull/2841 >>>>>>> >>>>>>> Would like some help with testing. Would be especially great to >>>>>>> test on some of these systems where the existing pidfile logic isn't >>>>>>> working, besides testing the usual cases. >>>>>>> >>>>>>> Best, >>>>>>> --Mike Weilgart >>>>>>> On Wednesday, February 21, 2024 at 6:59:41 AM UTC-8 nick.a...@ >>>>>>> northern.tech wrote: >>>>>>> >>>>>>>> Thanks for filing the ticket. :D >>>>>>>> >>>>>>>> On Tuesday, February 20, 2024 at 6:34:15 AM UTC-6 Xander Cage wrote: >>>>>>>> >>>>>>>>> ticket created -> >>>>>>>>> https://northerntech.atlassian.net/browse/CFE-4335 >>>>>>>>> >>>>>>>>> >>>>>>>>> On Tuesday, February 20, 2024 at 11:11:20 AM UTC+1 Xander Cage >>>>>>>>> wrote: >>>>>>>>> >>>>>>>>>> Hi, >>>>>>>>>> >>>>>>>>>> At times the cfengine watchdog script is unable to resolve >>>>>>>>>> hanging cf-agents. the reason is that if the system is under high load the >>>>>>>>>> watchdog "hangs" because it reads his own stale pid file and is doing >>>>>>>>>> simply nothing. >>>>>>>>>> >>>>>>>>>> example: >>>>>>>>>> >>>>>>>>>> i had 332 hanging cf-agent processe but the watchdog log just >>>>>>>>>> shows this. >>>>>>>>>> >>>>>>>>>> Tue Feb 20 10:57:00 CET 2024 Initiating watchdog 6816488 >>>>>>>>>> Tue Feb 20 10:57:00 CET 2024 Aborting execution of watchdog >>>>>>>>>> 6816488, existing watchdog process 16450014 running >>>>>>>>>> Tue Feb 20 10:58:00 CET 2024 Initiating watchdog 44499432 >>>>>>>>>> Tue Feb 20 10:58:00 CET 2024 Aborting execution of watchdog >>>>>>>>>> 44499432, existing watchdog process 16450014 running >>>>>>>>>> >>>>>>>>>> after deleting the pid file... >>>>>>>>>> >>>>>>>>>> Tue Feb 20 10:59:00 CET 2024 Initiating watchdog 25756150 >>>>>>>>>> Tue Feb 20 10:59:01 CET 2024 Found cf-execd not running >>>>>>>>>> Tue Feb 20 10:59:03 CET 2024 Found 332 occurrences of cf-execd >>>>>>>>>> terminating unresponsive cf-agent >>>>>>>>>> Tue Feb 20 10:59:04 CET 2024 Found 2 symptoms, threshold (0) >>>>>>>>>> breached. >>>>>>>>>> Tue Feb 20 10:59:06 CET 2024 Initiating apoptosis >>>>>>>>>> Tue Feb 20 10:59:10 CET 2024 Initiating anastasis >>>>>>>>>> >>>>>>>>>> i guess there is room for impovement, as this can bring a system >>>>>>>>>> down quite easyily. >>>>>>>>>> >>>>>>>>>> wbr >>>>>>>>>> >>>>>>>>>> chris >>>>>>>>>> >>>>>>>>>> >>>>> -- >>>>> You received this message because you are subscribed to a topic in the >>>>> Google Groups "help-cfengine" group. >>>>> To unsubscribe from this topic, visit >>>>> https://groups.google.com/d/topic/help-cfengine/ddLSAt7qsos/unsubscribe >>>>> . >>>>> To unsubscribe from this group and all its topics, send an email to >>>>> [email protected]. >>>>> To view this discussion on the web visit >>>>> https://groups.google.com/d/msgid/help-cfengine/24484aa8-cf0f-4882-a8b5-47894c81af5cn%40googlegroups.com >>>>> <https://groups.google.com/d/msgid/help-cfengine/24484aa8-cf0f-4882-a8b5-47894c81af5cn%40googlegroups.com?utm_medium=email&utm_source=footer> >>>>> . >>>>> >>>>> >>> -- >>> You received this message because you are subscribed to a topic in the >>> Google Groups "help-cfengine" group. >>> To unsubscribe from this topic, visit >>> https://groups.google.com/d/topic/help-cfengine/ddLSAt7qsos/unsubscribe. >>> To unsubscribe from this group and all its topics, send an email to >>> [email protected]. >>> To view this discussion on the web visit >>> https://groups.google.com/d/msgid/help-cfengine/0292d488-b8f5-44ac-b442-2f721dd82163n%40googlegroups.com >>> <https://groups.google.com/d/msgid/help-cfengine/0292d488-b8f5-44ac-b442-2f721dd82163n%40googlegroups.com?utm_medium=email&utm_source=footer> >>> . >>> >>> >> -- >> You received this message because you are subscribed to a topic in the >> Google Groups "help-cfengine" group. >> To unsubscribe from this topic, visit >> https://groups.google.com/d/topic/help-cfengine/ddLSAt7qsos/unsubscribe. >> To unsubscribe from this group and all its topics, send an email to >> [email protected]. >> To view this discussion on the web visit >> https://groups.google.com/d/msgid/help-cfengine/f42d2969-81b7-4882-8cd6-e11d69f8dad6n%40googlegroups.com >> <https://groups.google.com/d/msgid/help-cfengine/f42d2969-81b7-4882-8cd6-e11d69f8dad6n%40googlegroups.com?utm_medium=email&utm_source=footer> >> . >> >> -- You received this message because you are subscribed to the Google Groups "help-cfengine" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. To view this discussion on the web visit https://groups.google.com/d/msgid/help-cfengine/b92d5d94-e6de-4d1f-b6f6-6646fda65cfen%40googlegroups.com.