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