From 66447e8fafa53396510b9a2c789fef6e5df0d6ac Mon Sep 17 00:00:00 2001
From: Zachary Snow <zach@zachjs.com>
Date: Mon, 3 Jan 2022 20:12:22 -0700
Subject: [PATCH] logger: fix unmatched expected warnings and errors

- Prevent unmatched expected error patterns from self-matching
- Prevent infinite recursion on unmatched expected warnings
- Always print the error message for unmatched error patterns
- Add test coverage for all unmatched message types
- Add test coverage for excess matched logs and warnings
---
 kernel/log.cc                | 22 +++++++++----------
 tests/various/logger_fail.sh | 42 ++++++++++++++++++++++++++++++++++++
 2 files changed, 53 insertions(+), 11 deletions(-)
 create mode 100755 tests/various/logger_fail.sh

diff --git a/kernel/log.cc b/kernel/log.cc
index e7ce4cc46..4bcce3b28 100644
--- a/kernel/log.cc
+++ b/kernel/log.cc
@@ -71,7 +71,6 @@ int string_buf_index = -1;
 static struct timeval initial_tv = { 0, 0 };
 static bool next_print_log = false;
 static int log_newline_count = 0;
-static bool display_error_log_msg = true;
 
 static void log_id_cache_clear()
 {
@@ -338,8 +337,7 @@ static void logv_error_with_prefix(const char *prefix,
 				f = stderr;
 
 	log_last_error = vstringf(format, ap);
-	if (display_error_log_msg)
-		log("%s%s", prefix, log_last_error.c_str());
+	log("%s%s", prefix, log_last_error.c_str());
 	log_flush();
 
 	log_make_debug = bak_log_make_debug;
@@ -665,7 +663,14 @@ void log_wire(RTLIL::Wire *wire, std::string indent)
 
 void log_check_expected()
 {
-	for (auto &item : log_expect_warning) {
+	// copy out all of the expected logs so that they cannot be re-checked
+	// or match against themselves
+	dict<std::string, LogExpectedItem> expect_log, expect_warning, expect_error;
+	std::swap(expect_warning, log_expect_warning);
+	std::swap(expect_log, log_expect_log);
+	std::swap(expect_error, log_expect_error);
+
+	for (auto &item : expect_warning) {
 		if (item.second.current_count == 0) {
 			log_warn_regexes.clear();
 			log_error("Expected warning pattern '%s' not found !\n", item.first.c_str());
@@ -677,7 +682,7 @@ void log_check_expected()
 		}
 	}
 
-	for (auto &item : log_expect_log) {
+	for (auto &item : expect_log) {
 		if (item.second.current_count == 0) {
 			log_warn_regexes.clear();
 			log_error("Expected log pattern '%s' not found !\n", item.first.c_str());
@@ -689,7 +694,7 @@ void log_check_expected()
 		}
 	}
 
-	for (auto &item : log_expect_error)
+	for (auto &item : expect_error)
 		if (item.second.current_count == item.second.expected_count) {
 			log_warn_regexes.clear();
 			log("Expected error pattern '%s' found !!!\n", item.first.c_str());
@@ -701,14 +706,9 @@ void log_check_expected()
 				_Exit(0);
 			#endif
 		} else {
-			display_error_log_msg = false;
 			log_warn_regexes.clear();
 			log_error("Expected error pattern '%s' not found !\n", item.first.c_str());
 		}
-
-	log_expect_warning.clear();
-	log_expect_log.clear();
-	log_expect_error.clear();
 }
 
 // ---------------------------------------------------
diff --git a/tests/various/logger_fail.sh b/tests/various/logger_fail.sh
new file mode 100755
index 000000000..19b650007
--- /dev/null
+++ b/tests/various/logger_fail.sh
@@ -0,0 +1,42 @@
+#!/bin/bash
+
+fail() {
+	echo "$1" >&2
+	exit 1
+}
+
+runTest() {
+	desc="$1"
+	want="$2"
+	shift 2
+	echo "running '$desc' with args $@"
+	output=`../../yosys -q "$@" 2>&1`
+	if [ $? -ne 1 ]; then
+		fail "exit code for '$desc' was not 1"
+	fi
+	if [ "$output" != "$want" ]; then
+		fail "output for '$desc' did not match"
+	fi
+}
+
+unmet() {
+	kind=$1
+	runTest "unmet $kind" \
+		"ERROR: Expected $kind pattern 'foobar' not found !" \
+		-p "logger -expect $kind \"foobar\" 1"
+}
+
+unmet log
+unmet warning
+unmet error
+
+runTest "too many logs" \
+	"ERROR: Expected log pattern 'statistics' found 2 time(s), instead of 1 time(s) !" \
+	-p "logger -expect log \"statistics\" 1" -p stat -p stat
+
+runTest "too many warnings" \
+	"Warning: Found log message matching -W regex:
+Printing statistics.
+ERROR: Expected warning pattern 'statistics' found 2 time(s), instead of 1 time(s) !" \
+	-p "logger -warn \"Printing statistics\"" \
+	-p "logger -expect warning \"statistics\" 1" -p stat -p stat
-- 
2.30.2