Merge pull request #1705 from YosysHQ/logger_pass

Logger pass

CHANGELOG

@@ -62,6 +62,7 @@ Yosys 0.9 .. Yosys 0.9-dev
     - Added "synth_xilinx -dff"
     - Improved support of $readmem[hb] Memory Content File inclusion
     - Added "opt_lut_ins" pass
+    - Added "logger" pass
 
 Yosys 0.8 .. Yosys 0.9
 ----------------------

kernel/driver.cc

@@ -558,6 +558,10 @@ int main(int argc, char **argv)
 		fprintf(f, "\n");
 	}
 
+	if (log_expect_no_warnings && log_warnings_count_noexpect)
+		log_error("Unexpected warnings found: %d unique messages, %d total, %d expected\n", GetSize(log_warnings),
+					log_warnings_count, log_warnings_count - log_warnings_count_noexpect);
+
 	if (print_stats)
 	{
 		std::string hash = log_hasher->final().substr(0, 10);
@@ -664,6 +668,8 @@ int main(int argc, char **argv)
 	}
 #endif
 
+	log_check_expected();
+
 	yosys_atexit();
 
 	memhasher_off();

kernel/log.cc

@@ -42,8 +42,11 @@ std::vector<FILE*> log_files;
 std::vector<std::ostream*> log_streams;
 std::map<std::string, std::set<std::string>> log_hdump;
 std::vector<std::regex> log_warn_regexes, log_nowarn_regexes, log_werror_regexes;
+std::vector<std::pair<std::regex,LogExpectedItem>> log_expect_log, log_expect_warning, log_expect_error;
 std::set<std::string> log_warnings, log_experimentals, log_experimentals_ignored;
 int log_warnings_count = 0;
+int log_warnings_count_noexpect = 0;
+bool log_expect_no_warnings = false;
 bool log_hdump_all = false;
 FILE *log_errfile = NULL;
 SHA1 *log_hasher = NULL;
@@ -68,6 +71,8 @@ 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 check_expected_logs = true;
+static bool display_error_log_msg = true;
 
 static void log_id_cache_clear()
 {
@@ -162,7 +167,7 @@ void logv(const char *format, va_list ap)
 	{
 		log_warn_regex_recusion_guard = true;
 
-		if (log_warn_regexes.empty())
+		if (log_warn_regexes.empty() && log_expect_log.empty())
 		{
 			linebuffer.clear();
 		}
@@ -174,6 +179,11 @@ void logv(const char *format, va_list ap)
 				for (auto &re : log_warn_regexes)
 					if (std::regex_search(linebuffer, re))
 						log_warning("Found log message matching -W regex:\n%s", str.c_str());
+
+				for (auto &item : log_expect_log)
+					if (std::regex_search(linebuffer, item.first))
+						item.second.current_count++;
+
 				linebuffer.clear();
 			}
 		}
@@ -244,6 +254,13 @@ static void logv_warning_with_prefix(const char *prefix,
 			if (std::regex_search(message, re))
 				log_error("%s",  message.c_str());
 
+		bool warning_match = false;
+		for (auto &item : log_expect_warning)
+			if (std::regex_search(message, item.first)) {
+				item.second.current_count++;
+				warning_match = true;
+			}
+
 		if (log_warnings.count(message))
 		{
 			log("%s%s", prefix, message.c_str());
@@ -263,6 +280,8 @@ static void logv_warning_with_prefix(const char *prefix,
 			log_warnings.insert(message);
 		}
 
+		if (!warning_match)
+			log_warnings_count_noexpect++;
 		log_warnings_count++;
 		log_make_debug = bak_log_make_debug;
 	}
@@ -320,7 +339,8 @@ static void logv_error_with_prefix(const char *prefix,
 				f = stderr;
 
 	log_last_error = vstringf(format, ap);
-	log("%s%s", prefix, log_last_error.c_str());
+	if (display_error_log_msg)
+		log("%s%s", prefix, log_last_error.c_str());
 	log_flush();
 
 	log_make_debug = bak_log_make_debug;
@@ -328,6 +348,12 @@ static void logv_error_with_prefix(const char *prefix,
 	if (log_error_atexit)
 		log_error_atexit();
 
+	for (auto &item : log_expect_error)
+		if (std::regex_search(log_last_error, item.first))
+			item.second.current_count++;
+
+	if (check_expected_logs)
+		log_check_expected();
 #ifdef EMSCRIPTEN
 	log_files = backup_log_files;
 	throw 0;
@@ -636,6 +662,53 @@ void log_wire(RTLIL::Wire *wire, std::string indent)
 	log("%s", buf.str().c_str());
 }
 
+void log_check_expected()
+{
+	check_expected_logs = false;
+
+	for (auto &item : log_expect_warning) {
+		if (item.second.current_count == 0) {
+			log_warn_regexes.clear();
+			log_error("Expected warning pattern '%s' not found !\n", item.second.pattern.c_str());
+		}
+		if (item.second.current_count != item.second.expected_count) {
+			log_warn_regexes.clear();
+			log_error("Expected warning pattern '%s' found %d time(s), instead of %d time(s) !\n", 
+				item.second.pattern.c_str(), item.second.current_count, item.second.expected_count);
+		}
+	}
+
+	for (auto &item : log_expect_log) {
+		if (item.second.current_count == 0) {
+			log_warn_regexes.clear();
+			log_error("Expected log pattern '%s' not found !\n", item.second.pattern.c_str());
+		}
+		if (item.second.current_count != item.second.expected_count) {
+			log_warn_regexes.clear();
+			log_error("Expected log pattern '%s' found %d time(s), instead of %d time(s) !\n",
+				item.second.pattern.c_str(), item.second.current_count, item.second.expected_count);
+		}
+	}
+
+	for (auto &item : log_expect_error)
+		if (item.second.current_count == item.second.expected_count) {
+			log_warn_regexes.clear();
+			log("Expected error pattern '%s' found !!!\n", item.second.pattern.c_str());
+			#ifdef EMSCRIPTEN
+				log_files = backup_log_files;
+				throw 0;
+			#elif defined(_MSC_VER)
+				_exit(0);
+			#else
+				_Exit(0);
+			#endif			
+		} else {
+			display_error_log_msg = false;
+			log_warn_regexes.clear();
+			log_error("Expected error pattern '%s' not found !\n", item.second.pattern.c_str());
+		}
+}
+
 // ---------------------------------------------------
 // This is the magic behind the code coverage counters
 // ---------------------------------------------------

kernel/log.h

@@ -52,6 +52,8 @@ extern std::map<std::string, std::set<std::string>> log_hdump;
 extern std::vector<std::regex> log_warn_regexes, log_nowarn_regexes, log_werror_regexes;
 extern std::set<std::string> log_warnings, log_experimentals, log_experimentals_ignored;
 extern int log_warnings_count;
+extern int log_warnings_count_noexpect;
+extern bool log_expect_no_warnings;
 extern bool log_hdump_all;
 extern FILE *log_errfile;
 extern SHA1 *log_hasher;
@@ -135,6 +137,23 @@ void log_backtrace(const char *prefix, int levels);
 void log_reset_stack();
 void log_flush();
 
+struct LogExpectedItem
+{
+	LogExpectedItem(std::string pattern, int expected) :
+		expected_count(expected),
+		current_count(0),
+		pattern(pattern)
+	{
+	}
+
+	int expected_count;
+	int current_count;
+	std::string pattern;
+};
+
+extern std::vector<std::pair<std::regex,LogExpectedItem>> log_expect_log, log_expect_warning, log_expect_error;
+void log_check_expected();
+
 const char *log_signal(const RTLIL::SigSpec &sig, bool autoint = true);
 const char *log_const(const RTLIL::Const &value, bool autoint = true);
 const char *log_id(RTLIL::IdString id);

passes/cmds/Makefile.inc

@@ -33,3 +33,4 @@ OBJS += passes/cmds/blackbox.o
 OBJS += passes/cmds/ltp.o
 OBJS += passes/cmds/bugpoint.o
 OBJS += passes/cmds/scratchpad.o
+OBJS += passes/cmds/logger.o

passes/cmds/logger.cc

@@ -0,0 +1,201 @@
+/*
+ *  yosys -- Yosys Open SYnthesis Suite
+ *
+ *  Copyright (C) 2020  Miodrag Milanovic <clifford@clifford.at>
+ *
+ *  Permission to use, copy, modify, and/or distribute this software for any
+ *  purpose with or without fee is hereby granted, provided that the above
+ *  copyright notice and this permission notice appear in all copies.
+ *
+ *  THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES
+ *  WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF
+ *  MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR
+ *  ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES
+ *  WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN
+ *  ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF
+ *  OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
+ *
+ */
+
+#include "kernel/register.h"
+#include "kernel/log.h"
+
+USING_YOSYS_NAMESPACE
+PRIVATE_NAMESPACE_BEGIN
+
+struct LoggerPass : public Pass {
+	LoggerPass() : Pass("logger", "set logger properties") { }
+	void help() YS_OVERRIDE
+	{
+		//   |---v---|---v---|---v---|---v---|---v---|---v---|---v---|---v---|---v---|---v---|
+		log("\n");
+		log("    logger [options]\n");
+		log("\n");
+		log("This command sets global logger properties, also available using command line\n");
+		log("options.\n");
+		log("\n");
+		log("    -[no]time\n");
+		log("        enable/disable display of timestamp in log output.\n");
+		log("\n");
+		log("    -[no]stderr\n");
+		log("        enable/disable logging errors to stderr.\n");
+		log("\n");
+		log("    -warn regex\n");
+		log("        print a warning for all log messages matching the regex.\n");
+		log("\n");
+		log("    -nowarn regex\n");
+		log("        if a warning message matches the regex, it is printed as regular\n");
+		log("        message instead.\n");
+		log("\n");
+		log("    -werror regex\n");
+		log("        if a warning message matches the regex, it is printed as error\n");
+		log("        message instead and the tool terminates with a nonzero return code.\n");
+		log("\n");
+		log("    -[no]debug\n");
+		log("        globally enable/disable debug log messages.\n");
+		log("\n");
+		log("    -experimental <feature>\n");
+		log("        do not print warnings for the specified experimental feature\n");
+		log("\n");
+		log("    -expect <type> <regex> <expected_count>\n");
+		log("        expect log,warning or error to appear. In case of error return code is 0.\n");
+		log("\n");
+		log("    -expect-no-warnings\n");
+		log("        gives error in case there is at least one warning that is not expected.\n");
+		log("\n");
+	}
+
+	void execute(std::vector<std::string> args, RTLIL::Design * design) YS_OVERRIDE
+	{
+		size_t argidx;
+		for (argidx = 1; argidx < args.size(); argidx++)
+		{
+
+			if (args[argidx] == "-time") {
+				log_time = true;
+				log("Enabled timestamp in logs.\n");
+				continue;
+			}
+			if (args[argidx] == "-notime") {
+				log_time = false;
+				log("Disabled timestamp in logs.\n");
+				continue;
+			}
+			if (args[argidx] == "-stderr") {
+				log_error_stderr = true;
+				log("Enabled loggint errors to stderr.\n");
+				continue;
+			}
+			if (args[argidx] == "-nostderr") {
+				log_error_stderr = false;
+				log("Disabled loggint errors to stderr.\n");
+				continue;
+			}
+			if (args[argidx] == "-warn" && argidx+1 < args.size()) {
+				std::string pattern = args[++argidx];
+				if (pattern.front() == '\"' && pattern.back() == '\"') pattern = pattern.substr(1, pattern.size() - 2);		
+				try {
+					log("Added regex '%s' for warnings to warn list.\n", pattern.c_str());
+					log_warn_regexes.push_back(std::regex(pattern,
+						std::regex_constants::nosubs |
+						std::regex_constants::optimize |
+						std::regex_constants::egrep));
+				}
+				catch (const std::regex_error& e) {
+					log_cmd_error("Error in regex expression '%s' !\n", pattern.c_str());
+				}
+				continue;
+			}
+			if (args[argidx] == "-nowarn" && argidx+1 < args.size()) {
+				std::string pattern = args[++argidx];
+				if (pattern.front() == '\"' && pattern.back() == '\"') pattern = pattern.substr(1, pattern.size() - 2);	
+				try {
+					log("Added regex '%s' for warnings to nowarn list.\n", pattern.c_str());
+					log_nowarn_regexes.push_back(std::regex(pattern,
+						std::regex_constants::nosubs |
+						std::regex_constants::optimize |
+						std::regex_constants::egrep));
+				}
+				catch (const std::regex_error& e) {
+					log_cmd_error("Error in regex expression '%s' !\n", pattern.c_str());
+				}
+				continue;
+			}
+			if (args[argidx] == "-werror" && argidx+1 < args.size()) {
+				std::string pattern = args[++argidx];
+				if (pattern.front() == '\"' && pattern.back() == '\"') pattern = pattern.substr(1, pattern.size() - 2);	
+				try {
+					log("Added regex '%s' for warnings to werror list.\n", pattern.c_str());
+					log_werror_regexes.push_back(std::regex(pattern,
+						std::regex_constants::nosubs |
+						std::regex_constants::optimize |
+						std::regex_constants::egrep));
+				}
+				catch (const std::regex_error& e) {
+					log_cmd_error("Error in regex expression '%s' !\n", pattern.c_str());
+				}
+				continue;
+			}
+			if (args[argidx] == "-debug") {
+				log_force_debug = 1;
+				log("Enabled debug log messages.\n");
+				continue;
+			}
+			if (args[argidx] == "-nodebug") {
+				log_force_debug = 0;
+				log("Disabled debug log messages.\n");
+				continue;
+			}
+			if (args[argidx] == "-experimental" && argidx+1 < args.size()) {
+				std::string value = args[++argidx];
+				log("Added '%s' experimental ignore list.\n", value.c_str());
+				log_experimentals_ignored.insert(value);
+				continue;
+			}
+			if (args[argidx] == "-expect" && argidx+3 < args.size()) {
+				std::string type = args[++argidx];
+				if (type!="error" && type!="warning" && type!="log")
+					log_cmd_error("Expect command require type to be 'log', 'warning' or 'error' !\n");
+				if (type=="error" && log_expect_error.size()>0)
+					log_cmd_error("Only single error message can be expected !\n");
+				std::string pattern = args[++argidx];
+				if (pattern.front() == '\"' && pattern.back() == '\"') pattern = pattern.substr(1, pattern.size() - 2);					
+				int count = atoi(args[++argidx].c_str());
+				if (count<=0)
+					log_cmd_error("Number of expected messages must be higher then 0 !\n");
+				if (type=="error" && count!=1)
+					log_cmd_error("Expected error message occurrences must be 1 !\n");
+				log("Added regex '%s' for warnings to expected %s list.\n", pattern.c_str(), type.c_str());
+				try {
+					if (type=="error")
+						log_expect_error.push_back(std::make_pair(std::regex(pattern,
+							std::regex_constants::nosubs |
+							std::regex_constants::optimize |
+							std::regex_constants::egrep), LogExpectedItem(pattern, count)));
+					else if (type=="warning")
+						log_expect_warning.push_back(std::make_pair(std::regex(pattern,
+							std::regex_constants::nosubs |
+							std::regex_constants::optimize |
+							std::regex_constants::egrep), LogExpectedItem(pattern, count)));
+					else
+						log_expect_log.push_back(std::make_pair(std::regex(pattern,
+							std::regex_constants::nosubs |
+							std::regex_constants::optimize |
+							std::regex_constants::egrep), LogExpectedItem(pattern, count)));
+				}
+				catch (const std::regex_error& e) {
+					log_cmd_error("Error in regex expression '%s' !\n", pattern.c_str());
+				}
+				continue;
+			}
+			if (args[argidx] == "-expect-no-warnings") {
+				log_expect_no_warnings = true;
+				continue;
+			}
+			break;
+		}
+		extra_args(args, argidx, design, false);
+	}
+} LoggerPass;
+
+PRIVATE_NAMESPACE_END