kernel/log.cc

   1 /*
   2  *  yosys -- Yosys Open SYnthesis Suite
   3  *
   4  *  Copyright (C) 2012  Clifford Wolf <clifford@clifford.at>
   5  *
   6  *  Permission to use, copy, modify, and/or distribute this software for any
   7  *  purpose with or without fee is hereby granted, provided that the above
   8  *  copyright notice and this permission notice appear in all copies.
   9  *
  10  *  THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES
  11  *  WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF
  12  *  MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR
  13  *  ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES
  14  *  WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN
  15  *  ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF
  16  *  OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
  17  *
  18  */
  19
  20 #include "kernel/yosys.h"
  21 #include "libs/sha1/sha1.h"
  22 #include "backends/ilang/ilang_backend.h"
  23
  24 #if !defined(_WIN32) || defined(__MINGW32__)
  25 #  include <sys/time.h>
  26 #endif
  27
  28 #if defined(__linux__) || defined(__FreeBSD__)
  29 #  include <dlfcn.h>
  30 #endif
  31
  32 #include <stdlib.h>
  33 #include <stdio.h>
  34 #include <string.h>
  35 #include <stdarg.h>
  36 #include <vector>
  37 #include <list>
  38
  39 YOSYS_NAMESPACE_BEGIN
  40
  41 std::vector<FILE*> log_files;
  42 std::vector<std::ostream*> log_streams;
  43 std::map<std::string, std::set<std::string>> log_hdump;
  44 std::vector<std::regex> log_warn_regexes, log_nowarn_regexes, log_werror_regexes;
  45 std::set<std::string> log_warnings, log_experimentals;
  46 int log_warnings_count = 0;
  47 bool log_hdump_all = false;
  48 FILE *log_errfile = NULL;
  49 SHA1 *log_hasher = NULL;
  50
  51 bool log_time = false;
  52 bool log_error_stderr = false;
  53 bool log_cmd_error_throw = false;
  54 bool log_quiet_warnings = false;
  55 int log_verbose_level;
  56 string log_last_error;
  57 void (*log_error_atexit)() = NULL;
  58
  59 int log_make_debug = 0;
  60 int log_force_debug = 0;
  61 int log_debug_suppressed = 0;
  62
  63 vector<int> header_count;
  64 vector<char*> log_id_cache;
  65 vector<shared_str> string_buf;
  66 int string_buf_index = -1;
  67
  68 static struct timeval initial_tv = { 0, 0 };
  69 static bool next_print_log = false;
  70 static int log_newline_count = 0;
  71
  72 static void log_id_cache_clear()
  73 {
  74         for (auto p : log_id_cache)
  75                 free(p);
  76         log_id_cache.clear();
  77 }
  78
  79 #if defined(_WIN32) && !defined(__MINGW32__)
  80 // this will get time information and return it in timeval, simulating gettimeofday()
  81 int gettimeofday(struct timeval *tv, struct timezone *tz)
  82 {
  83         LARGE_INTEGER counter;
  84         LARGE_INTEGER freq;
  85
  86         QueryPerformanceFrequency(&freq);
  87         QueryPerformanceCounter(&counter);
  88
  89         counter.QuadPart *= 1000000;
  90         counter.QuadPart /= freq.QuadPart;
  91
  92         tv->tv_sec = long(counter.QuadPart / 1000000);
  93         tv->tv_usec = counter.QuadPart % 1000000;
  94
  95         return 0;
  96 }
  97 #endif
  98
  99 void logv(const char *format, va_list ap)
 100 {
 101         while (format[0] == '\n' && format[1] != 0) {
 102                 log("\n");
 103                 format++;
 104         }
 105
 106         if (log_make_debug && !ys_debug(1))
 107                 return;
 108
 109         std::string str = vstringf(format, ap);
 110
 111         if (str.empty())
 112                 return;
 113
 114         size_t nnl_pos = str.find_last_not_of('\n');
 115         if (nnl_pos == std::string::npos)
 116                 log_newline_count += GetSize(str);
 117         else
 118                 log_newline_count = GetSize(str) - nnl_pos - 1;
 119
 120         if (log_hasher)
 121                 log_hasher->update(str);
 122
 123         if (log_time)
 124         {
 125                 std::string time_str;
 126
 127                 if (next_print_log || initial_tv.tv_sec == 0) {
 128                         next_print_log = false;
 129                         struct timeval tv;
 130                         gettimeofday(&tv, NULL);
 131                         if (initial_tv.tv_sec == 0)
 132                                 initial_tv = tv;
 133                         if (tv.tv_usec < initial_tv.tv_usec) {
 134                                 tv.tv_sec--;
 135                                 tv.tv_usec += 1000000;
 136                         }
 137                         tv.tv_sec -= initial_tv.tv_sec;
 138                         tv.tv_usec -= initial_tv.tv_usec;
 139                         time_str += stringf("[%05d.%06d] ", int(tv.tv_sec), int(tv.tv_usec));
 140                 }
 141
 142                 if (format[0] && format[strlen(format)-1] == '\n')
 143                         next_print_log = true;
 144
 145                 for (auto f : log_files)
 146                         fputs(time_str.c_str(), f);
 147
 148                 for (auto f : log_streams)
 149                         *f << time_str;
 150         }
 151
 152         for (auto f : log_files)
 153                 fputs(str.c_str(), f);
 154
 155         for (auto f : log_streams)
 156                 *f << str;
 157
 158         static std::string linebuffer;
 159         static bool log_warn_regex_recusion_guard = false;
 160
 161         if (!log_warn_regex_recusion_guard)
 162         {
 163                 log_warn_regex_recusion_guard = true;
 164
 165                 if (log_warn_regexes.empty())
 166                 {
 167                         linebuffer.clear();
 168                 }
 169                 else
 170                 {
 171                         linebuffer += str;
 172
 173                         if (!linebuffer.empty() && linebuffer.back() == '\n') {
 174                                 for (auto &re : log_warn_regexes)
 175                                         if (std::regex_search(linebuffer, re))
 176                                                 log_warning("Found log message matching -W regex:\n%s", str.c_str());
 177                                 linebuffer.clear();
 178                         }
 179                 }
 180
 181                 log_warn_regex_recusion_guard = false;
 182         }
 183 }
 184
 185 void logv_header(RTLIL::Design *design, const char *format, va_list ap)
 186 {
 187         bool pop_errfile = false;
 188
 189         log_spacer();
 190         if (header_count.size() > 0)
 191                 header_count.back()++;
 192
 193         if (int(header_count.size()) <= log_verbose_level && log_errfile != NULL) {
 194                 log_files.push_back(log_errfile);
 195                 pop_errfile = true;
 196         }
 197
 198         std::string header_id;
 199
 200         for (int c : header_count)
 201                 header_id += stringf("%s%d", header_id.empty() ? "" : ".", c);
 202
 203         log("%s. ", header_id.c_str());
 204         logv(format, ap);
 205         log_flush();
 206
 207         if (log_hdump_all)
 208                 log_hdump[header_id].insert("yosys_dump_" + header_id + ".il");
 209
 210         if (log_hdump.count(header_id) && design != nullptr)
 211                 for (auto &filename : log_hdump.at(header_id)) {
 212                         log("Dumping current design to '%s'.\n", filename.c_str());
 213                         if (yosys_xtrace)
 214                                 IdString::xtrace_db_dump();
 215                         Pass::call(design, {"dump", "-o", filename});
 216                         if (yosys_xtrace)
 217                                 log("#X# -- end of dump --\n");
 218                 }
 219
 220         if (pop_errfile)
 221                 log_files.pop_back();
 222 }
 223
 224 static void logv_warning_with_prefix(const char *prefix,
 225                                      const char *format, va_list ap)
 226 {
 227         std::string message = vstringf(format, ap);
 228         bool suppressed = false;
 229
 230         for (auto &re : log_nowarn_regexes)
 231                 if (std::regex_search(message, re))
 232                         suppressed = true;
 233
 234         if (suppressed)
 235         {
 236                 log("Suppressed %s%s", prefix, message.c_str());
 237         }
 238         else
 239         {
 240                 int bak_log_make_debug = log_make_debug;
 241                 log_make_debug = 0;
 242
 243                 for (auto &re : log_werror_regexes)
 244                         if (std::regex_search(message, re))
 245                                 log_error("%s",  message.c_str());
 246
 247                 if (log_warnings.count(message))
 248                 {
 249                         log("%s%s", prefix, message.c_str());
 250                         log_flush();
 251                 }
 252                 else
 253                 {
 254                         if (log_errfile != NULL && !log_quiet_warnings)
 255                                 log_files.push_back(log_errfile);
 256
 257                         log("%s%s", prefix, message.c_str());
 258                         log_flush();
 259
 260                         if (log_errfile != NULL && !log_quiet_warnings)
 261                                 log_files.pop_back();
 262
 263                         log_warnings.insert(message);
 264                 }
 265
 266                 log_warnings_count++;
 267                 log_make_debug = bak_log_make_debug;
 268         }
 269 }
 270
 271 void logv_warning(const char *format, va_list ap)
 272 {
 273         logv_warning_with_prefix("Warning: ", format, ap);
 274 }
 275
 276 void logv_warning_noprefix(const char *format, va_list ap)
 277 {
 278         logv_warning_with_prefix("", format, ap);
 279 }
 280
 281 void log_file_warning(const std::string &filename, int lineno,
 282                       const char *format, ...)
 283 {
 284         va_list ap;
 285         va_start(ap, format);
 286         std::string prefix = stringf("%s:%d: Warning: ",
 287                         filename.c_str(), lineno);
 288         logv_warning_with_prefix(prefix.c_str(), format, ap);
 289         va_end(ap);
 290 }
 291
 292 void log_file_info(const std::string &filename, int lineno,
 293                       const char *format, ...)
 294 {
 295         va_list ap;
 296         va_start(ap, format);
 297         std::string fmt = stringf("%s:%d: Info: %s",
 298                         filename.c_str(), lineno, format);
 299         logv(fmt.c_str(), ap);
 300         va_end(ap);
 301 }
 302
 303 YS_ATTRIBUTE(noreturn)
 304 static void logv_error_with_prefix(const char *prefix,
 305                                    const char *format, va_list ap)
 306 {
 307 #ifdef EMSCRIPTEN
 308         auto backup_log_files = log_files;
 309 #endif
 310         int bak_log_make_debug = log_make_debug;
 311         log_make_debug = 0;
 312         log_suppressed();
 313
 314         if (log_errfile != NULL)
 315                 log_files.push_back(log_errfile);
 316
 317         if (log_error_stderr)
 318                 for (auto &f : log_files)
 319                         if (f == stdout)
 320                                 f = stderr;
 321
 322         log_last_error = vstringf(format, ap);
 323         log("%s%s", prefix, log_last_error.c_str());
 324         log_flush();
 325
 326         log_make_debug = bak_log_make_debug;
 327
 328         if (log_error_atexit)
 329                 log_error_atexit();
 330
 331 #ifdef EMSCRIPTEN
 332         log_files = backup_log_files;
 333         throw 0;
 334 #elif defined(_MSC_VER)
 335         _exit(1);
 336 #else
 337         _Exit(1);
 338 #endif
 339 }
 340
 341 void logv_error(const char *format, va_list ap)
 342 {
 343         logv_error_with_prefix("ERROR: ", format, ap);
 344 }
 345
 346 void log_file_error(const string &filename, int lineno,
 347                     const char *format, ...)
 348 {
 349         va_list ap;
 350         va_start(ap, format);
 351         std::string prefix = stringf("%s:%d: ERROR: ",
 352                                      filename.c_str(), lineno);
 353         logv_error_with_prefix(prefix.c_str(), format, ap);
 354 }
 355
 356 void log(const char *format, ...)
 357 {
 358         va_list ap;
 359         va_start(ap, format);
 360         logv(format, ap);
 361         va_end(ap);
 362 }
 363
 364 void log_header(RTLIL::Design *design, const char *format, ...)
 365 {
 366         va_list ap;
 367         va_start(ap, format);
 368         logv_header(design, format, ap);
 369         va_end(ap);
 370 }
 371
 372 void log_warning(const char *format, ...)
 373 {
 374         va_list ap;
 375         va_start(ap, format);
 376         logv_warning(format, ap);
 377         va_end(ap);
 378 }
 379
 380 void log_experimental(const char *format, ...)
 381 {
 382         va_list ap;
 383         va_start(ap, format);
 384         string s = vstringf(format, ap);
 385         va_end(ap);
 386
 387         if (log_experimentals.count(s) == 0) {
 388                 log_warning("Feature '%s' is experimental.\n", s.c_str());
 389                 log_experimentals.insert(s);
 390         }
 391 }
 392
 393 void log_warning_noprefix(const char *format, ...)
 394 {
 395         va_list ap;
 396         va_start(ap, format);
 397         logv_warning_noprefix(format, ap);
 398         va_end(ap);
 399 }
 400
 401 void log_error(const char *format, ...)
 402 {
 403         va_list ap;
 404         va_start(ap, format);
 405         logv_error(format, ap);
 406 }
 407
 408 void log_cmd_error(const char *format, ...)
 409 {
 410         va_list ap;
 411         va_start(ap, format);
 412
 413         if (log_cmd_error_throw) {
 414                 log_last_error = vstringf(format, ap);
 415                 log("ERROR: %s", log_last_error.c_str());
 416                 log_flush();
 417                 throw log_cmd_error_exception();
 418         }
 419
 420         logv_error(format, ap);
 421 }
 422
 423 void log_spacer()
 424 {
 425         if (log_newline_count < 2) log("\n");
 426         if (log_newline_count < 2) log("\n");
 427 }
 428
 429 void log_push()
 430 {
 431         header_count.push_back(0);
 432 }
 433
 434 void log_pop()
 435 {
 436         header_count.pop_back();
 437         log_id_cache_clear();
 438         string_buf.clear();
 439         string_buf_index = -1;
 440         log_flush();
 441 }
 442
 443 #if (defined(__linux__) || defined(__FreeBSD__)) && defined(YOSYS_ENABLE_PLUGINS)
 444 void log_backtrace(const char *prefix, int levels)
 445 {
 446         if (levels <= 0) return;
 447
 448         Dl_info dli;
 449         void *p;
 450
 451         if ((p = __builtin_extract_return_addr(__builtin_return_address(0))) && dladdr(p, &dli)) {
 452                 log("%sframe #1: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 453         } else {
 454                 log("%sframe #1: ---\n", prefix);
 455                 return;
 456         }
 457
 458         if (levels <= 1) return;
 459
 460 #ifndef DEBUG
 461         log("%sframe #2: [build Yosys with ENABLE_DEBUG for deeper backtraces]\n", prefix);
 462 #else
 463         if ((p = __builtin_extract_return_addr(__builtin_return_address(1))) && dladdr(p, &dli)) {
 464                 log("%sframe #2: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 465         } else {
 466                 log("%sframe #2: ---\n", prefix);
 467                 return;
 468         }
 469
 470         if (levels <= 2) return;
 471
 472         if ((p = __builtin_extract_return_addr(__builtin_return_address(2))) && dladdr(p, &dli)) {
 473                 log("%sframe #3: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 474         } else {
 475                 log("%sframe #3: ---\n", prefix);
 476                 return;
 477         }
 478
 479         if (levels <= 3) return;
 480
 481         if ((p = __builtin_extract_return_addr(__builtin_return_address(3))) && dladdr(p, &dli)) {
 482                 log("%sframe #4: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 483         } else {
 484                 log("%sframe #4: ---\n", prefix);
 485                 return;
 486         }
 487
 488         if (levels <= 4) return;
 489
 490         if ((p = __builtin_extract_return_addr(__builtin_return_address(4))) && dladdr(p, &dli)) {
 491                 log("%sframe #5: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 492         } else {
 493                 log("%sframe #5: ---\n", prefix);
 494                 return;
 495         }
 496
 497         if (levels <= 5) return;
 498
 499         if ((p = __builtin_extract_return_addr(__builtin_return_address(5))) && dladdr(p, &dli)) {
 500                 log("%sframe #6: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 501         } else {
 502                 log("%sframe #6: ---\n", prefix);
 503                 return;
 504         }
 505
 506         if (levels <= 6) return;
 507
 508         if ((p = __builtin_extract_return_addr(__builtin_return_address(6))) && dladdr(p, &dli)) {
 509                 log("%sframe #7: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 510         } else {
 511                 log("%sframe #7: ---\n", prefix);
 512                 return;
 513         }
 514
 515         if (levels <= 7) return;
 516
 517         if ((p = __builtin_extract_return_addr(__builtin_return_address(7))) && dladdr(p, &dli)) {
 518                 log("%sframe #8: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 519         } else {
 520                 log("%sframe #8: ---\n", prefix);
 521                 return;
 522         }
 523
 524         if (levels <= 8) return;
 525
 526         if ((p = __builtin_extract_return_addr(__builtin_return_address(8))) && dladdr(p, &dli)) {
 527                 log("%sframe #9: %p %s(%p) %s(%p)\n", prefix, p, dli.dli_fname, dli.dli_fbase, dli.dli_sname, dli.dli_saddr);
 528         } else {
 529                 log("%sframe #9: ---\n", prefix);
 530                 return;
 531         }
 532
 533         if (levels <= 9) return;
 534 #endif
 535 }
 536 #else
 537 void log_backtrace(const char*, int) { }
 538 #endif
 539
 540 void log_reset_stack()
 541 {
 542         while (header_count.size() > 1)
 543                 header_count.pop_back();
 544         log_id_cache_clear();
 545         string_buf.clear();
 546         string_buf_index = -1;
 547         log_flush();
 548 }
 549
 550 void log_flush()
 551 {
 552         for (auto f : log_files)
 553                 fflush(f);
 554
 555         for (auto f : log_streams)
 556                 f->flush();
 557 }
 558
 559 void log_dump_val_worker(RTLIL::IdString v) {
 560         log("%s", log_id(v));
 561 }
 562
 563 void log_dump_val_worker(RTLIL::SigSpec v) {
 564         log("%s", log_signal(v));
 565 }
 566
 567 void log_dump_val_worker(RTLIL::State v) {
 568         log("%s", log_signal(v));
 569 }
 570
 571 const char *log_signal(const RTLIL::SigSpec &sig, bool autoint)
 572 {
 573         std::stringstream buf;
 574         ILANG_BACKEND::dump_sigspec(buf, sig, autoint);
 575
 576         if (string_buf.size() < 100) {
 577                 string_buf.push_back(buf.str());
 578                 return string_buf.back().c_str();
 579         } else {
 580                 if (++string_buf_index == 100)
 581                         string_buf_index = 0;
 582                 string_buf[string_buf_index] = buf.str();
 583                 return string_buf[string_buf_index].c_str();
 584         }
 585 }
 586
 587 const char *log_const(const RTLIL::Const &value, bool autoint)
 588 {
 589         if ((value.flags & RTLIL::CONST_FLAG_STRING) == 0)
 590                 return log_signal(value, autoint);
 591
 592         std::string str = "\"" + value.decode_string() + "\"";
 593
 594         if (string_buf.size() < 100) {
 595                 string_buf.push_back(str);
 596                 return string_buf.back().c_str();
 597         } else {
 598                 if (++string_buf_index == 100)
 599                         string_buf_index = 0;
 600                 string_buf[string_buf_index] = str;
 601                 return string_buf[string_buf_index].c_str();
 602         }
 603 }
 604
 605 const char *log_id(RTLIL::IdString str)
 606 {
 607         log_id_cache.push_back(strdup(str.c_str()));
 608         const char *p = log_id_cache.back();
 609         if (p[0] != '\\')
 610                 return p;
 611         if (p[1] == '$' || p[1] == '\\' || p[1] == 0)
 612                 return p;
 613         if (p[1] >= '0' && p[1] <= '9')
 614                 return p;
 615         return p+1;
 616 }
 617
 618 void log_module(RTLIL::Module *module, std::string indent)
 619 {
 620         std::stringstream buf;
 621         ILANG_BACKEND::dump_module(buf, indent, module, module->design, false);
 622         log("%s", buf.str().c_str());
 623 }
 624
 625 void log_cell(RTLIL::Cell *cell, std::string indent)
 626 {
 627         std::stringstream buf;
 628         ILANG_BACKEND::dump_cell(buf, indent, cell);
 629         log("%s", buf.str().c_str());
 630 }
 631
 632 void log_wire(RTLIL::Wire *wire, std::string indent)
 633 {
 634         std::stringstream buf;
 635         ILANG_BACKEND::dump_wire(buf, indent, wire);
 636         log("%s", buf.str().c_str());
 637 }
 638
 639 // ---------------------------------------------------
 640 // This is the magic behind the code coverage counters
 641 // ---------------------------------------------------
 642 #if defined(YOSYS_ENABLE_COVER) && (defined(__linux__) || defined(__FreeBSD__))
 643
 644 dict<std::string, std::pair<std::string, int>> extra_coverage_data;
 645
 646 void cover_extra(std::string parent, std::string id, bool increment) {
 647         if (extra_coverage_data.count(id) == 0) {
 648                 for (CoverData *p = __start_yosys_cover_list; p != __stop_yosys_cover_list; p++)
 649                         if (p->id == parent)
 650                                 extra_coverage_data[id].first = stringf("%s:%d:%s", p->file, p->line, p->func);
 651                 log_assert(extra_coverage_data.count(id));
 652         }
 653         if (increment)
 654                 extra_coverage_data[id].second++;
 655 }
 656
 657 dict<std::string, std::pair<std::string, int>> get_coverage_data()
 658 {
 659         dict<std::string, std::pair<std::string, int>> coverage_data;
 660
 661         for (auto &it : pass_register) {
 662                 std::string key = stringf("passes.%s", it.first.c_str());
 663                 coverage_data[key].first = stringf("%s:%d:%s", __FILE__, __LINE__, __FUNCTION__);
 664                 coverage_data[key].second += it.second->call_counter;
 665         }
 666
 667         for (auto &it : extra_coverage_data) {
 668                 if (coverage_data.count(it.first))
 669                         log_warning("found duplicate coverage id \"%s\".\n", it.first.c_str());
 670                 coverage_data[it.first].first = it.second.first;
 671                 coverage_data[it.first].second += it.second.second;
 672         }
 673
 674         for (CoverData *p = __start_yosys_cover_list; p != __stop_yosys_cover_list; p++) {
 675                 if (coverage_data.count(p->id))
 676                         log_warning("found duplicate coverage id \"%s\".\n", p->id);
 677                 coverage_data[p->id].first = stringf("%s:%d:%s", p->file, p->line, p->func);
 678                 coverage_data[p->id].second += p->counter;
 679         }
 680
 681         for (auto &it : coverage_data)
 682                 if (!it.second.first.compare(0, strlen(YOSYS_SRC "/"), YOSYS_SRC "/"))
 683                         it.second.first = it.second.first.substr(strlen(YOSYS_SRC "/"));
 684
 685         return coverage_data;
 686 }
 687
 688 #endif
 689
 690 YOSYS_NAMESPACE_END