ZED crashes frequently after recent changes to ZED

[don-brady]

Type	Version/Name
Distribution Name	Ubuntu
Distribution Version	18.04.5 LTS
Linux Kernel	5.4.0-1043
Architecture	x86_64
ZFS Version	2021.04.19.20-562e20d
SPL Version	2021.04.19.20-562e20d

Describe the problem you're observing

ZED is crashing. Looks like a regression from commit ca2ce9c50b6b579

Describe how to reproduce the problem

Happens during our internal test runs. I will try and isolate.

Include any warning/errors/backtraces from the system logs

#1  0x00007f456ba74921 in __GI_abort () at abort.c:79
#2  0x00007f456ca9c805 in libspl_assertf (file=0x7f456caab199 "../../module/avl/avl.c",
    func=0x7f456caab1b0 <__FUNCTION__.5089> "avl_add", line=640, format=<optimized out>) at assert.c:45
#3  0x00007f456caa4cfc in libspl_assert (line=640, func=<synthetic pointer>, file=0x7f456caab199 "../../module/avl/avl.c",
    buf=0x7f456caab170 "avl_find(tree, new_node, &where) == NULL") at ../../lib/libspl/include/assert.h:46
#4  0x00007f456caa501b in avl_add (tree=tree@entry=0x5567dedee320 <_launched_processes>, new_node=new_node@entry=0x5567dee98080)
    at ../../module/avl/avl.c:640
#5  0x00005567debe14f9 in _zed_exec_fork_child (eid=eid@entry=2487, dir=<optimized out>, prog=prog@entry=0x5567dee8d580 "all-syslog.sh",
    env=env@entry=0x5567dee97bc0, zfd=7, in_foreground=B_TRUE) at zed_exec.c:180
#6  0x00005567debe1b3f in zed_exec_process (eid=2487, class=<optimized out>, subclass=subclass@entry=0x5567dee95d90 "history_event",
    zcp=zcp@entry=0x7ffc31d582f0, envs=envs@entry=0x5567dee96a30) at zed_exec.c:360
#7  0x00005567debe1253 in zed_event_service (zcp=0x7ffc31d582f0) at zed_event.c:979
#8  0x00005567debdc7e0 in main (argc=<optimized out>, argv=<optimized out>) at zed.c:291```

[behlendorf]

@nabijaczleweli would you mind taking a look at this. It appears we're somehow getting in to a situation where we're inserting duplicate pids in to the AVL tree which causes the ASSERT. How that's possible I'm not sure, but it appears to be the case.

[nabijaczleweli]

Hm. I mean, there is technically a race between the time wait4() returns and the time we pop the now-dead child from _launched_processes I guess? i.e. wait4() returns with pid 2323, then fork() returns with immediately-recycled pid 2323 and log, allocation, &c. up to the lock and avl_add(&_launched_processes, node {.pid = 2323}) happen before the movement of like fifty bytes and lock in the reaper?

I didn't actually think this was possible! And with such quick PID reuse!

@don-brady can you try the following patch? It'll ensure we remove the waited-for PID from the tree before we try to add a new one.

diff --git a/cmd/zed/zed_exec.c b/cmd/zed/zed_exec.c
index 8c8452ca7..59f087cec 100644
--- a/cmd/zed/zed_exec.c
+++ b/cmd/zed/zed_exec.c
@@ -205,10 +205,13 @@ _reap_children(void *arg)
 	(void) sigaction(SIGCHLD, &sa, NULL);
 
 	for (_reap_children_stop = B_FALSE; !_reap_children_stop; ) {
-		pid = wait4(0, &status, 0, &usage);
+		(void) pthread_mutex_lock(&_launched_processes_lock);
+		errno = 0;
+		pid = wait4(0, &status, WNOHANG, &usage);
 
-		if (pid == (pid_t)-1) {
-			if (errno == ECHILD)
+		if (pid == 0 || pid == (pid_t)-1) {
+			(void) pthread_mutex_unlock(&_launched_processes_lock);
+			if (errno == 0 || errno == ECHILD)
 				pause();
 			else if (errno != EINTR)
 				zed_log_msg(LOG_WARNING,
@@ -217,7 +220,6 @@ _reap_children(void *arg)
 		} else {
 			memset(&node, 0, sizeof (node));
 			node.pid = pid;
-			(void) pthread_mutex_lock(&_launched_processes_lock);
 			pnode = avl_find(&_launched_processes, &node, NULL);
 			if (pnode) {
 				memcpy(&node, pnode, sizeof (node));

[don-brady]

@nabijaczleweli thanks for quick response! I'm running with the above change now. It doesn't always assert so I'lll need to run it for a while to see if solves the crashes.

[don-brady]

So far it's looking good. But since the failure was intermittent this is not conclusive. The fix seems correct but I'm not 100% certain it completely closes the window for recycled pid numbers (I don't have enough context).

I'll continue testing.

[don-brady]

@nabijaczleweli I still haven't seen the assert with the above change applied. Could you open a PR?

[nabijaczleweli]

#11928