zed syslog entries drop important info

ZED will log zevents summaries to the syslog, however the log entries 
tend to drop event details that can be useful for diagnosis. This is 
especially true for ereport events, like io, checksum, and delay.

Update the all-syslog.sh script to log additional event information.

Add an optional config option, ZED_SYSLOG_DISPLAY_GUIDS, to zed.rc
for choosing GUIDs over names for pool and vdev.

Change the default ZED_SYSLOG_SUBCLASS_EXCLUDE to exclude history_event 
events. These events tend to be frequent, convey no meaningful info, 
and are already logged in the zpool history.

Reviewed-by: John Kennedy <[email protected]>
Reviewed-by: Pavel Zakharov <[email protected]>
Reviewed-by: Brian Behlendorf <[email protected]>
Signed-off-by: Don Brady <[email protected]>
Closes #10967 

3 files changed, 60 insertions, 29 deletions

diff --git a/tests/zfs-tests/tests/functional/events/events_001_pos.ksh b/tests/zfs-tests/tests/functional/events/events_001_pos.ksh
index 5121f66b7..189cf435e 100755
--- a/tests/zfs-tests/tests/functional/events/events_001_pos.ksh
+++ b/tests/zfs-tests/tests/functional/events/events_001_pos.ksh
@@ -94,22 +94,22 @@ run_and_verify -p "$MPOOL"\
     -e "resource.fs.zfs.statechange" \
     -e "sysevent.fs.zfs.config_sync" \
     "zpool offline $MPOOL $VDEV1"
-run_and_verify -p "$MPOOL" -d 10 \
+run_and_verify -p "$MPOOL" \
     -e "resource.fs.zfs.statechange" \
     -e "sysevent.fs.zfs.vdev_online" \
+    -e "sysevent.fs.zfs.config_sync" \
     -e "sysevent.fs.zfs.resilver_start" \
-    -e "sysevent.fs.zfs.resilver_finish" \
     -e "sysevent.fs.zfs.history_event" \
-    -e "sysevent.fs.zfs.config_sync" \
+    -e "sysevent.fs.zfs.resilver_finish" \
     "zpool online $MPOOL $VDEV1"
 
 # Attach then detach a device from the mirror.
-run_and_verify -p "$MPOOL" -d 10 \
+run_and_verify -p "$MPOOL" \
     -e "sysevent.fs.zfs.vdev_attach" \
     -e "sysevent.fs.zfs.resilver_start" \
-    -e "sysevent.fs.zfs.resilver_finish" \
-    -e "sysevent.fs.zfs.history_event" \
     -e "sysevent.fs.zfs.config_sync" \
+    -e "sysevent.fs.zfs.history_event" \
+    -e "sysevent.fs.zfs.resilver_finish" \
     "zpool attach $MPOOL $VDEV1 $VDEV4"
 run_and_verify -p "$MPOOL" \
     -e "sysevent.fs.zfs.vdev_remove" \
@@ -117,20 +117,20 @@ run_and_verify -p "$MPOOL" \
     "zpool detach $MPOOL $VDEV4"
 
 # Replace a device
-run_and_verify -p "$MPOOL" -d 10 \
+run_and_verify -p "$MPOOL" \
     -e "sysevent.fs.zfs.vdev_attach" \
     -e "sysevent.fs.zfs.resilver_start" \
+    -e "sysevent.fs.zfs.config_sync" \
+    -e "sysevent.fs.zfs.history_event" \
     -e "sysevent.fs.zfs.resilver_finish" \
     -e "sysevent.fs.zfs.vdev_remove" \
-    -e "sysevent.fs.zfs.history_event" \
-    -e "sysevent.fs.zfs.config_sync" \
     "zpool replace -f $MPOOL $VDEV1 $VDEV4"
 
 # Scrub a pool.
-run_and_verify -p "$MPOOL" -d 10 \
+run_and_verify -p "$MPOOL" \
     -e "sysevent.fs.zfs.scrub_start" \
-    -e "sysevent.fs.zfs.scrub_finish" \
     -e "sysevent.fs.zfs.history_event" \
+    -e "sysevent.fs.zfs.scrub_finish" \
     "zpool scrub $MPOOL"
 
 # Export then import a pool
@@ -139,9 +139,9 @@ run_and_verify -p "$MPOOL" \
     -e "sysevent.fs.zfs.config_sync" \
     "zpool export $MPOOL"
 run_and_verify -p "$MPOOL" \
-    -e "sysevent.fs.zfs.pool_import" \
-    -e "sysevent.fs.zfs.history_event" \
     -e "sysevent.fs.zfs.config_sync" \
+    -e "sysevent.fs.zfs.history_event" \
+    -e "sysevent.fs.zfs.pool_import" \
     "zpool import -d $TEST_BASE_DIR $MPOOL"
 
 # Destroy the pool
diff --git a/tests/zfs-tests/tests/functional/events/events_002_pos.ksh b/tests/zfs-tests/tests/functional/events/events_002_pos.ksh
index 76ad6237f..7a78d93a8 100755
--- a/tests/zfs-tests/tests/functional/events/events_002_pos.ksh
+++ b/tests/zfs-tests/tests/functional/events/events_002_pos.ksh
@@ -92,7 +92,7 @@ done
 
 # 5. Start the ZED and verify it only handled the new missed events.
 log_must zed_start
-log_must file_wait $ZED_DEBUG_LOG 15
+log_must file_wait $ZED_DEBUG_LOG 35
 log_must cp $ZED_DEBUG_LOG $TMP_EVENTS_ZED
 
 log_mustnot grep -q "sysevent.fs.zfs.pool_create" $TMP_EVENTS_ZED
diff --git a/tests/zfs-tests/tests/functional/events/events_common.kshlib b/tests/zfs-tests/tests/functional/events/events_common.kshlib
index 26afc1091..5f4c629dc 100644
--- a/tests/zfs-tests/tests/functional/events/events_common.kshlib
+++ b/tests/zfs-tests/tests/functional/events/events_common.kshlib
@@ -23,11 +23,35 @@
 # Copyright (c) 2017 by Lawrence Livermore National Security, LLC.
 # Use is subject to license terms.
 #
+# Copyright (c) 2020 by Delphix. All rights reserved.
+#
 
 . $STF_SUITE/include/libtest.shlib
 . $STF_SUITE/tests/functional/events/events.cfg
 
 #
+# wait for 'event' to show up in the log 'file'
+function file_wait_event # file event timeout
+{
+	file=$1
+	event=$2
+	timeout=${3:-120}
+
+	SECONDS=0
+
+	until grep -q "^ZEVENT_CLASS=$event" $ZED_DEBUG_LOG ; do
+		if [[ $SECONDS -gt $timeout ]]; then
+			echo file_wait_event exceeded $SECONDS seconds
+			return 1
+		fi
+
+		sleep 1
+	done
+
+	return 0;
+}
+
+#
 # Wait for up to 'timeout' seconds for the 'file' to settle, i.e.
 # not be updated for a period of 'delay' seconds.
 #
@@ -41,6 +65,7 @@ function file_wait # file delay timeout
 
 	while [ $(( $(date +%s) - $(stat -c %Y $file) )) -lt $delay ]; do
 		if [[ $SECONDS -gt $timeout ]]; then
+			echo file_wait exceeded $SECONDS seconds
 			return 1
 		fi
 
@@ -52,30 +77,22 @@ function file_wait # file delay timeout
 
 function run_and_verify
 {
-	typeset delay event pool zedlog
+	typeset event pool
 	set -A events
 
-	while getopts "d:e:p:z:" opt; do
+	while getopts "e:p:" opt; do
 		case $opt in
-		d)
-			delay=$OPTARG
-			;;
 		e)
-			events[${#events[*]}+1]=$OPTARG
+			events+=("$OPTARG")
 			;;
 		p)
 			pool=$OPTARG
 			;;
-		z)
-			zedlog=$OPTARG
-			;;
 		esac
 	done
 	shift $(($OPTIND - 1))
 
 	pool=${pool:-$TESTPOOL}
-	delay=${delay:-3}
-	zedlog=${zedlog:-$ZED_DEBUG_LOG}
 	fullcmd="$1"
 	cmd=$(echo $fullcmd | awk '{print $1}')
 
@@ -87,21 +104,30 @@ function run_and_verify
 
 	# Remove any previous events from the logs.
 	log_must zpool events -c
-	log_must truncate -s 0 $zedlog
+	log_must truncate -s 0 $ZED_DEBUG_LOG
 
 	# Run the command as provided.
 	log_must eval "$fullcmd"
 
 	# Collect the new events and verify there are some.
 	log_must zpool sync -f
-	log_must file_wait $zedlog $delay
-	log_must cp $zedlog $TMP_EVENTS_ZED
 	log_must eval "zpool events >$TMP_EVENTS 2>/dev/null"
 	log_must eval "zpool events -v > $TMP_EVENTS_FULL 2>/dev/null"
 
 	log_must test -s $TMP_EVENTS
 	log_must test -s $TMP_EVENTS_FULL
-	log_must test -s $TMP_EVENTS_ZED
+
+	# If the only event is history then we don't observe zed debug log
+	if [[ "${events[0]}" != "sysevent.fs.zfs.history_event" ]]; then
+		# wait for the last event to show up in the debug log
+		log_must file_wait_event $ZED_DEBUG_LOG ${events[-1]}
+
+		log_must cp $ZED_DEBUG_LOG $TMP_EVENTS_ZED
+		log_must test -s $TMP_EVENTS_ZED
+
+		log_note "Events logged:"
+		grep "^ZEVENT_CLASS" $TMP_EVENTS_ZED
+	fi
 
 	log_note "Events generated:"
 	cat $TMP_EVENTS
@@ -118,6 +144,11 @@ function run_and_verify
 		    $TMP_EVENTS_FULL >$TMP_EVENT_FULL
 		log_must grep -q "pool = \"$pool\"" $TMP_EVENT_FULL
 
+		# all-debug.sh filters history events (seen in ZED_DEBUG_LOG)
+		if [[ "$event" == "sysevent.fs.zfs.history_event" ]]; then
+			continue
+		fi
+
 		# Verify the event was received by the ZED and logged.
 		awk -v event="$event" \
 		    'BEGIN{FS="\n"; RS=""} $0 ~ event { print $0 }' \