Merge pull request #138 from YosysHQ/refactor_log

Tidy up logging code, add log file support, make timing failures non-fatal errors

common/command.cc

@@ -40,7 +40,7 @@
 
 NEXTPNR_NAMESPACE_BEGIN
 
-CommandHandler::CommandHandler(int argc, char **argv) : argc(argc), argv(argv) { log_files.push_back(stdout); }
+CommandHandler::CommandHandler(int argc, char **argv) : argc(argc), argv(argv) { log_streams.clear(); }
 
 bool CommandHandler::parseOptions()
 {
@@ -64,14 +64,14 @@ bool CommandHandler::parseOptions()
 bool CommandHandler::executeBeforeContext()
 {
     if (vm.count("help") || argc == 1) {
-        std::cout << boost::filesystem::basename(argv[0])
+        std::cerr << boost::filesystem::basename(argv[0])
                   << " -- Next Generation Place and Route (git sha1 " GIT_COMMIT_HASH_STR ")\n";
-        std::cout << options << "\n";
+        std::cerr << options << "\n";
         return argc != 1;
     }
 
     if (vm.count("version")) {
-        std::cout << boost::filesystem::basename(argv[0])
+        std::cerr << boost::filesystem::basename(argv[0])
                   << " -- Next Generation Place and Route (git sha1 " GIT_COMMIT_HASH_STR ")\n";
         return true;
     }
@@ -84,7 +84,9 @@ po::options_description CommandHandler::getGeneralOptions()
     po::options_description general("General options");
     general.add_options()("help,h", "show help");
     general.add_options()("verbose,v", "verbose output");
-    general.add_options()("quiet,q", "quiet mode, only errors displayed");
+    general.add_options()("quiet,q", "quiet mode, only errors and warnings displayed");
+    general.add_options()("log,l", po::value<std::string>(),
+                          "log file, all log messages are written to this file regardless of -q");
     general.add_options()("debug", "debug output");
     general.add_options()("force,f", "keep running after errors");
 #ifndef NO_GUI
@@ -128,7 +130,17 @@ void CommandHandler::setupContext(Context *ctx)
     }
 
     if (vm.count("quiet")) {
-        log_quiet_warnings = true;
+        log_streams.push_back(std::make_pair(&std::cerr, LogLevel::WARNING));
+    } else {
+        log_streams.push_back(std::make_pair(&std::cerr, LogLevel::LOG));
+    }
+
+    if (vm.count("log")) {
+        std::string logfilename = vm["log"].as<std::string>();
+        logfile = std::ofstream(logfilename);
+        if (!logfile)
+            log_error("Failed to open log file '%s' for writing.\n", logfilename.c_str());
+        log_streams.push_back(std::make_pair(&logfile, LogLevel::LOG));
     }
 
     if (vm.count("force")) {
@@ -258,7 +270,7 @@ int CommandHandler::executeMain(std::unique_ptr<Context> ctx)
     deinit_python();
 #endif
 
-    return 0;
+    return had_nonfatal_error ? 1 : 0;
 }
 
 void CommandHandler::conflicting_options(const boost::program_options::variables_map &vm, const char *opt1,

common/command.h

@@ -66,6 +66,7 @@ class CommandHandler
     int argc;
     char **argv;
     ProjectHandler project;
+    std::ofstream logfile;
 };
 
 NEXTPNR_NAMESPACE_END

common/log.cc

@@ -32,19 +32,14 @@ NEXTPNR_NAMESPACE_BEGIN
 
 NPNR_NORETURN void logv_error(const char *format, va_list ap) NPNR_ATTRIBUTE(noreturn);
 
-std::vector<FILE *> log_files;
+std::vector<std::pair<std::ostream *, LogLevel>> log_streams;
-std::vector<std::ostream *> log_streams;
-FILE *log_errfile = NULL;
 log_write_type log_write_function = nullptr;
 
-bool log_error_stderr = false;
-bool log_cmd_error_throw = false;
-bool log_quiet_warnings = false;
 std::string log_last_error;
 void (*log_error_atexit)() = NULL;
 
-// static bool next_print_log = false;
 static int log_newline_count = 0;
+bool had_nonfatal_error = false;
 
 std::string stringf(const char *fmt, ...)
 {
@@ -88,7 +83,7 @@ std::string vstringf(const char *fmt, va_list ap)
     return string;
 }
 
-void logv(const char *format, va_list ap)
+void logv(const char *format, va_list ap, LogLevel level = LogLevel::LOG)
 {
     //
     // Trim newlines from the beginning
@@ -108,90 +103,50 @@ void logv(const char *format, va_list ap)
     else
         log_newline_count = str.size() - nnl_pos - 1;
 
-    for (auto f : log_files)
-        fputs(str.c_str(), f);
-
     for (auto f : log_streams)
-        *f << str;
+        if (f.second <= level)
+            *f.first << str;
     if (log_write_function)
         log_write_function(str);
 }
 
-void logv_info(const char *format, va_list ap)
+void log_with_level(LogLevel level, const char *format, ...)
+{
+    va_list ap;
+    va_start(ap, format);
+    logv(format, ap, level);
+    va_end(ap);
+}
+
+void logv_prefixed(const char *prefix, const char *format, va_list ap, LogLevel level)
 {
     std::string message = vstringf(format, ap);
 
-    log_always("Info: %s", message.c_str());
+    log_with_level(level, "%s%s", prefix, message.c_str());
     log_flush();
 }
 
-void logv_warning(const char *format, va_list ap)
-{
-    std::string message = vstringf(format, ap);
-
-    log_always("Warning: %s", message.c_str());
-    log_flush();
-}
-
-void logv_warning_noprefix(const char *format, va_list ap)
-{
-    std::string message = vstringf(format, ap);
-
-    log_always("%s", message.c_str());
-}
-
-void logv_error(const char *format, va_list ap)
-{
-#ifdef EMSCRIPTEN
-    auto backup_log_files = log_files;
-#endif
-
-    if (log_errfile != NULL)
-        log_files.push_back(log_errfile);
-
-    if (log_error_stderr)
-        for (auto &f : log_files)
-            if (f == stdout)
-                f = stderr;
-
-    log_last_error = vstringf(format, ap);
-    log_always("ERROR: %s", log_last_error.c_str());
-    log_flush();
-
-    if (log_error_atexit)
-        log_error_atexit();
-
-#ifdef EMSCRIPTEN
-    log_files = backup_log_files;
-#endif
-    throw log_execution_error_exception();
-}
-
 void log_always(const char *format, ...)
 {
     va_list ap;
     va_start(ap, format);
-    logv(format, ap);
+    logv(format, ap, LogLevel::ALWAYS);
     va_end(ap);
 }
 
 void log(const char *format, ...)
 {
-    if (log_quiet_warnings)
-        return;
     va_list ap;
     va_start(ap, format);
-    logv(format, ap);
+    logv(format, ap, LogLevel::LOG);
     va_end(ap);
 }
 
 void log_info(const char *format, ...)
 {
-    if (log_quiet_warnings)
-        return;
     va_list ap;
     va_start(ap, format);
-    logv_info(format, ap);
+    logv_prefixed("Info: ", format, ap, LogLevel::INFO);
     va_end(ap);
 }
 
@@ -199,15 +154,7 @@ void log_warning(const char *format, ...)
 {
     va_list ap;
     va_start(ap, format);
-    logv_warning(format, ap);
+    logv_prefixed("Warning: ", format, ap, LogLevel::WARNING);
-    va_end(ap);
-}
-
-void log_warning_noprefix(const char *format, ...)
-{
-    va_list ap;
-    va_start(ap, format);
-    logv_warning_noprefix(format, ap);
     va_end(ap);
 }
 
@@ -215,41 +162,35 @@ void log_error(const char *format, ...)
 {
     va_list ap;
     va_start(ap, format);
-    logv_error(format, ap);
+    logv_prefixed("ERROR: ", format, ap, LogLevel::ERROR);
-}
 
-void log_cmd_error(const char *format, ...)
+    if (log_error_atexit)
-{
+        log_error_atexit();
-    va_list ap;
-    va_start(ap, format);
 
-    if (log_cmd_error_throw) {
+    throw log_execution_error_exception();
-        log_last_error = vstringf(format, ap);
-        log_always("ERROR: %s", log_last_error.c_str());
-        log_flush();
-        throw log_cmd_error_exception();
-    }
-
-    logv_error(format, ap);
 }
 
 void log_break()
 {
-    if (log_quiet_warnings)
-        return;
     if (log_newline_count < 2)
-        log_always("\n");
+        log("\n");
     if (log_newline_count < 2)
-        log_always("\n");
+        log("\n");
+}
+
+void log_nonfatal_error(const char *format, ...)
+{
+    va_list ap;
+    va_start(ap, format);
+    logv_prefixed("ERROR: ", format, ap, LogLevel::ERROR);
+    va_end(ap);
+    had_nonfatal_error = true;
 }
 
 void log_flush()
 {
-    for (auto f : log_files)
-        fflush(f);
-
     for (auto f : log_streams)
-        f->flush();
+        f.first->flush();
 }
 
 NEXTPNR_NAMESPACE_END

common/log.h

@@ -42,14 +42,21 @@ struct log_execution_error_exception
 {
 };
 
-extern std::vector<FILE *> log_files;
+enum class LogLevel
-extern std::vector<std::ostream *> log_streams;
+{
-extern FILE *log_errfile;
+    LOG,
+    INFO,
+    WARNING,
+    ERROR,
+    ALWAYS
+};
+
+extern std::vector<std::pair<std::ostream *, LogLevel>> log_streams;
 extern log_write_type log_write_function;
 
-extern bool log_quiet_warnings;
 extern std::string log_last_error;
 extern void (*log_error_atexit)();
+extern bool had_nonfatal_error;
 
 std::string stringf(const char *fmt, ...);
 std::string vstringf(const char *fmt, va_list ap);
@@ -59,10 +66,8 @@ void log(const char *format, ...) NPNR_ATTRIBUTE(format(printf, 1, 2));
 void log_always(const char *format, ...) NPNR_ATTRIBUTE(format(printf, 1, 2));
 void log_info(const char *format, ...) NPNR_ATTRIBUTE(format(printf, 1, 2));
 void log_warning(const char *format, ...) NPNR_ATTRIBUTE(format(printf, 1, 2));
-void log_warning_noprefix(const char *format, ...) NPNR_ATTRIBUTE(format(printf, 1, 2));
 NPNR_NORETURN void log_error(const char *format, ...) NPNR_ATTRIBUTE(format(printf, 1, 2), noreturn);
-NPNR_NORETURN void log_cmd_error(const char *format, ...) NPNR_ATTRIBUTE(format(printf, 1, 2), noreturn);
+void log_nonfatal_error(const char *format, ...) NPNR_ATTRIBUTE(format(printf, 1, 2));
-
 void log_break();
 void log_flush();
 
@@ -75,7 +80,6 @@ static inline void log_assert_worker(bool cond, const char *expr, const char *fi
     NEXTPNR_NAMESPACE_PREFIX log_assert_worker(_assert_expr_, #_assert_expr_, __FILE__, __LINE__)
 
 #define log_abort() log_error("Abort in %s:%d.\n", __FILE__, __LINE__)
-#define log_ping() log("-- %s:%d %s --\n", __FILE__, __LINE__, __PRETTY_FUNCTION__)
 
 NEXTPNR_NAMESPACE_END
 

common/router1.cc

@@ -812,7 +812,8 @@ bool router1(Context *ctx, const Router1Cfg &cfg)
 #endif
 
         log_info("Checksum: 0x%08x\n", ctx->checksum());
-        timing_analysis(ctx, true /* slack_histogram */, true /* print_fmax */, true /* print_path */);
+        timing_analysis(ctx, true /* slack_histogram */, true /* print_fmax */, true /* print_path */,
+                        true /* warn_on_failure */);
 
         ctx->unlock();
         return true;

common/timing.cc

@@ -485,11 +485,11 @@ void assign_budget(Context *ctx, bool quiet)
             for (auto &user : net.second->users) {
                 // Post-update check
                 if (!ctx->auto_freq && user.budget < 0)
-                    log_warning("port %s.%s, connected to net '%s', has negative "
+                    log_info("port %s.%s, connected to net '%s', has negative "
-                                "timing budget of %fns\n",
+                             "timing budget of %fns\n",
-                                user.cell->name.c_str(ctx), user.port.c_str(ctx), net.first.c_str(ctx),
+                             user.cell->name.c_str(ctx), user.port.c_str(ctx), net.first.c_str(ctx),
-                                ctx->getDelayNS(user.budget));
+                             ctx->getDelayNS(user.budget));
-                else if (ctx->verbose)
+                else if (ctx->debug)
                     log_info("port %s.%s, connected to net '%s', has "
                              "timing budget of %fns\n",
                              user.cell->name.c_str(ctx), user.port.c_str(ctx), net.first.c_str(ctx),
@@ -513,7 +513,7 @@ void assign_budget(Context *ctx, bool quiet)
         log_info("Checksum: 0x%08x\n", ctx->checksum());
 }
 
-void timing_analysis(Context *ctx, bool print_histogram, bool print_fmax, bool print_path)
+void timing_analysis(Context *ctx, bool print_histogram, bool print_fmax, bool print_path, bool warn_on_failure)
 {
     auto format_event = [ctx](const ClockEvent &e, int field_width = 0) {
         std::string value;
@@ -705,15 +705,17 @@ void timing_analysis(Context *ctx, bool print_histogram, bool print_fmax, bool p
         for (auto &clock : clock_reports) {
             const auto &clock_name = clock.first.str(ctx);
             const int width = max_width - clock_name.size();
-            if (ctx->nets.at(clock.first)->clkconstr) {
+            float target = ctx->target_freq / 1e6;
-                float target = 1000 / ctx->getDelayNS(ctx->nets.at(clock.first)->clkconstr->period.minDelay());
+            if (ctx->nets.at(clock.first)->clkconstr)
+                target = 1000 / ctx->getDelayNS(ctx->nets.at(clock.first)->clkconstr->period.minDelay());
+
+            bool passed = target < clock_fmax[clock.first];
+            if (!warn_on_failure || passed)
                 log_info("Max frequency for clock %*s'%s': %.02f MHz (%s at %.02f MHz)\n", width, "",
-                         clock_name.c_str(), clock_fmax[clock.first],
+                         clock_name.c_str(), clock_fmax[clock.first], passed ? "PASS" : "FAIL", target);
-                         (target < clock_fmax[clock.first]) ? "PASS" : "FAIL", target);
+            else
-            } else {
+                log_nonfatal_error("Max frequency for clock %*s'%s': %.02f MHz (%s at %.02f MHz)\n", width, "",
-                log_info("Max frequency for clock %*s'%s': %.02f MHz\n", width, "", clock_name.c_str(),
+                            clock_name.c_str(), clock_fmax[clock.first], passed ? "PASS" : "FAIL", target);
-                         clock_fmax[clock.first]);
-            }
         }
         for (auto &eclock : empty_clocks) {
             if (eclock != ctx->id("$async$"))

common/timing.h

@@ -29,7 +29,8 @@ void assign_budget(Context *ctx, bool quiet = false);
 
 // Perform timing analysis and print out the fmax, and optionally the
 //    critical path
-void timing_analysis(Context *ctx, bool slack_histogram = true, bool print_fmax = true, bool print_path = false);
+void timing_analysis(Context *ctx, bool slack_histogram = true, bool print_fmax = true, bool print_path = false,
+                     bool warn_on_failure = false);
 
 NEXTPNR_NAMESPACE_END
 

gui/basewindow.cc

@@ -44,7 +44,6 @@ BaseMainWindow::BaseMainWindow(std::unique_ptr<Context> context, ArchArgs args,
     initBasenameResource();
     qRegisterMetaType<std::string>();
 
-    log_files.clear();
     log_streams.clear();
 
     setObjectName("BaseMainWindow");