src/debug.cc

   1 /*
   2  * Copyright (C) 1996-2016 The Squid Software Foundation and contributors
   3  *
   4  * Squid software is distributed under GPLv2+ license and includes
   5  * contributions from numerous individuals and organizations.
   6  * Please see the COPYING and CONTRIBUTORS files for details.
   7  */
   8
   9 /* DEBUG: section 00    Debug Routines */
  10
  11 #include "squid.h"
  12 #include "Debug.h"
  13 #include "ipc/Kids.h"
  14 #include "SquidTime.h"
  15 #include "util.h"
  16
  17 #include <algorithm>
  18
  19 /* for shutting_down flag in xassert() */
  20 #include "globals.h"
  21
  22 char *Debug::debugOptions = NULL;
  23 int Debug::override_X = 0;
  24 int Debug::log_stderr = -1;
  25 bool Debug::log_syslog = false;
  26 int Debug::Levels[MAX_DEBUG_SECTIONS];
  27 char *Debug::cache_log = NULL;
  28 int Debug::rotateNumber = -1;
  29 FILE *debug_log = NULL;
  30 static char *debug_log_file = NULL;
  31 static int Ctx_Lock = 0;
  32 static const char *debugLogTime(void);
  33 static const char *debugLogKid(void);
  34 static void ctx_print(void);
  35 #if HAVE_SYSLOG
  36 #ifdef LOG_LOCAL4
  37 static int syslog_facility = 0;
  38 #endif
  39 static void _db_print_syslog(const char *format, va_list args);
  40 #endif
  41 static void _db_print_stderr(const char *format, va_list args);
  42 static void _db_print_file(const char *format, va_list args);
  43
  44 #if _SQUID_WINDOWS_
  45 extern LPCRITICAL_SECTION dbg_mutex;
  46 typedef BOOL (WINAPI * PFInitializeCriticalSectionAndSpinCount) (LPCRITICAL_SECTION, DWORD);
  47 #endif
  48
  49 void
  50 _db_print(const char *format,...)
  51 {
  52     char f[BUFSIZ];
  53     f[0]='\0';
  54     va_list args1;
  55     va_list args2;
  56     va_list args3;
  57
  58 #if _SQUID_WINDOWS_
  59     /* Multiple WIN32 threads may call this simultaneously */
  60
  61     if (!dbg_mutex) {
  62         HMODULE krnl_lib = GetModuleHandle("Kernel32");
  63         PFInitializeCriticalSectionAndSpinCount InitializeCriticalSectionAndSpinCount = NULL;
  64
  65         if (krnl_lib)
  66             InitializeCriticalSectionAndSpinCount =
  67                 (PFInitializeCriticalSectionAndSpinCount) GetProcAddress(krnl_lib,
  68                         "InitializeCriticalSectionAndSpinCount");
  69
  70         dbg_mutex = static_cast<CRITICAL_SECTION*>(xcalloc(1, sizeof(CRITICAL_SECTION)));
  71
  72         if (InitializeCriticalSectionAndSpinCount) {
  73             /* let multiprocessor systems EnterCriticalSection() fast */
  74
  75             if (!InitializeCriticalSectionAndSpinCount(dbg_mutex, 4000)) {
  76                 if (debug_log) {
  77                     fprintf(debug_log, "FATAL: _db_print: can't initialize critical section\n");
  78                     fflush(debug_log);
  79                 }
  80
  81                 fprintf(stderr, "FATAL: _db_print: can't initialize critical section\n");
  82                 abort();
  83             } else
  84                 InitializeCriticalSection(dbg_mutex);
  85         }
  86     }
  87
  88     EnterCriticalSection(dbg_mutex);
  89 #endif
  90
  91     /* give a chance to context-based debugging to print current context */
  92     if (!Ctx_Lock)
  93         ctx_print();
  94
  95     va_start(args1, format);
  96     va_start(args2, format);
  97     va_start(args3, format);
  98
  99     snprintf(f, BUFSIZ, "%s%s| %s",
 100              debugLogTime(),
 101              debugLogKid(),
 102              format);
 103
 104     _db_print_file(f, args1);
 105     _db_print_stderr(f, args2);
 106
 107 #if HAVE_SYSLOG
 108     _db_print_syslog(format, args3);
 109 #endif
 110
 111 #if _SQUID_WINDOWS_
 112     LeaveCriticalSection(dbg_mutex);
 113 #endif
 114
 115     va_end(args1);
 116     va_end(args2);
 117     va_end(args3);
 118 }
 119
 120 static void
 121 _db_print_file(const char *format, va_list args)
 122 {
 123     if (debug_log == NULL)
 124         return;
 125
 126     /* give a chance to context-based debugging to print current context */
 127     if (!Ctx_Lock)
 128         ctx_print();
 129
 130     vfprintf(debug_log, format, args);
 131     fflush(debug_log);
 132 }
 133
 134 static void
 135 _db_print_stderr(const char *format, va_list args)
 136 {
 137     if (Debug::log_stderr < Debug::Level())
 138         return;
 139
 140     if (debug_log == stderr)
 141         return;
 142
 143     vfprintf(stderr, format, args);
 144 }
 145
 146 #if HAVE_SYSLOG
 147 static void
 148 _db_print_syslog(const char *format, va_list args)
 149 {
 150     /* level 0,1 go to syslog */
 151
 152     if (Debug::Level() > 1)
 153         return;
 154
 155     if (!Debug::log_syslog)
 156         return;
 157
 158     char tmpbuf[BUFSIZ];
 159     tmpbuf[0] = '\0';
 160
 161     vsnprintf(tmpbuf, BUFSIZ, format, args);
 162
 163     tmpbuf[BUFSIZ - 1] = '\0';
 164
 165     syslog(Debug::Level() == 0 ? LOG_WARNING : LOG_NOTICE, "%s", tmpbuf);
 166 }
 167 #endif /* HAVE_SYSLOG */
 168
 169 static void
 170 debugArg(const char *arg)
 171 {
 172     int s = 0;
 173     int l = 0;
 174     int i;
 175
 176     if (!strncasecmp(arg, "rotate=", 7)) {
 177         arg += 7;
 178         Debug::rotateNumber = atoi(arg);
 179         return;
 180     } else if (!strncasecmp(arg, "ALL", 3)) {
 181         s = -1;
 182         arg += 4;
 183     } else {
 184         s = atoi(arg);
 185         while (*arg && *arg++ != ',');
 186     }
 187
 188     l = atoi(arg);
 189     assert(s >= -1);
 190
 191     if (s >= MAX_DEBUG_SECTIONS)
 192         s = MAX_DEBUG_SECTIONS-1;
 193
 194     if (l < 0)
 195         l = 0;
 196
 197     if (l > 10)
 198         l = 10;
 199
 200     if (s >= 0) {
 201         Debug::Levels[s] = l;
 202         return;
 203     }
 204
 205     for (i = 0; i < MAX_DEBUG_SECTIONS; ++i)
 206         Debug::Levels[i] = l;
 207 }
 208
 209 static void
 210 debugOpenLog(const char *logfile)
 211 {
 212     if (logfile == NULL) {
 213         debug_log = stderr;
 214         return;
 215     }
 216
 217     if (debug_log_file)
 218         xfree(debug_log_file);
 219
 220     debug_log_file = xstrdup(logfile);  /* keep a static copy */
 221
 222     if (debug_log && debug_log != stderr)
 223         fclose(debug_log);
 224
 225     // Bug 4423: ignore the stdio: logging module name if present
 226     const char *logfilename;
 227     if (strncmp(logfile, "stdio:",6) == 0)
 228         logfilename = logfile + 6;
 229     else
 230         logfilename = logfile;
 231
 232     debug_log = fopen(logfilename, "a+");
 233
 234     if (!debug_log) {
 235         fprintf(stderr, "WARNING: Cannot write log file: %s\n", logfile);
 236         perror(logfile);
 237         fprintf(stderr, "         messages will be sent to 'stderr'.\n");
 238         fflush(stderr);
 239         debug_log = stderr;
 240     }
 241
 242 #if _SQUID_WINDOWS_
 243     setmode(fileno(debug_log), O_TEXT);
 244 #endif
 245 }
 246
 247 #if HAVE_SYSLOG
 248 #ifdef LOG_LOCAL4
 249
 250 static struct syslog_facility_name {
 251     const char *name;
 252     int facility;
 253 }
 254
 255 syslog_facility_names[] = {
 256
 257 #ifdef LOG_AUTH
 258     {
 259         "auth", LOG_AUTH
 260     },
 261 #endif
 262 #ifdef LOG_AUTHPRIV
 263     {
 264         "authpriv", LOG_AUTHPRIV
 265     },
 266 #endif
 267 #ifdef LOG_CRON
 268     {
 269         "cron", LOG_CRON
 270     },
 271 #endif
 272 #ifdef LOG_DAEMON
 273     {
 274         "daemon", LOG_DAEMON
 275     },
 276 #endif
 277 #ifdef LOG_FTP
 278     {
 279         "ftp", LOG_FTP
 280     },
 281 #endif
 282 #ifdef LOG_KERN
 283     {
 284         "kern", LOG_KERN
 285     },
 286 #endif
 287 #ifdef LOG_LPR
 288     {
 289         "lpr", LOG_LPR
 290     },
 291 #endif
 292 #ifdef LOG_MAIL
 293     {
 294         "mail", LOG_MAIL
 295     },
 296 #endif
 297 #ifdef LOG_NEWS
 298     {
 299         "news", LOG_NEWS
 300     },
 301 #endif
 302 #ifdef LOG_SYSLOG
 303     {
 304         "syslog", LOG_SYSLOG
 305     },
 306 #endif
 307 #ifdef LOG_USER
 308     {
 309         "user", LOG_USER
 310     },
 311 #endif
 312 #ifdef LOG_UUCP
 313     {
 314         "uucp", LOG_UUCP
 315     },
 316 #endif
 317 #ifdef LOG_LOCAL0
 318     {
 319         "local0", LOG_LOCAL0
 320     },
 321 #endif
 322 #ifdef LOG_LOCAL1
 323     {
 324         "local1", LOG_LOCAL1
 325     },
 326 #endif
 327 #ifdef LOG_LOCAL2
 328     {
 329         "local2", LOG_LOCAL2
 330     },
 331 #endif
 332 #ifdef LOG_LOCAL3
 333     {
 334         "local3", LOG_LOCAL3
 335     },
 336 #endif
 337 #ifdef LOG_LOCAL4
 338     {
 339         "local4", LOG_LOCAL4
 340     },
 341 #endif
 342 #ifdef LOG_LOCAL5
 343     {
 344         "local5", LOG_LOCAL5
 345     },
 346 #endif
 347 #ifdef LOG_LOCAL6
 348     {
 349         "local6", LOG_LOCAL6
 350     },
 351 #endif
 352 #ifdef LOG_LOCAL7
 353     {
 354         "local7", LOG_LOCAL7
 355     },
 356 #endif
 357     {
 358         NULL, 0
 359     }
 360 };
 361
 362 #endif
 363
 364 void
 365 _db_set_syslog(const char *facility)
 366 {
 367     Debug::log_syslog = true;
 368
 369 #ifdef LOG_LOCAL4
 370 #ifdef LOG_DAEMON
 371
 372     syslog_facility = LOG_DAEMON;
 373 #else
 374
 375     syslog_facility = LOG_LOCAL4;
 376 #endif /* LOG_DAEMON */
 377
 378     if (facility) {
 379
 380         struct syslog_facility_name *n;
 381
 382         for (n = syslog_facility_names; n->name; ++n) {
 383             if (strcmp(n->name, facility) == 0) {
 384                 syslog_facility = n->facility;
 385                 return;
 386             }
 387         }
 388
 389         fprintf(stderr, "unknown syslog facility '%s'\n", facility);
 390         exit(1);
 391     }
 392
 393 #else
 394     if (facility)
 395         fprintf(stderr, "syslog facility type not supported on your system\n");
 396
 397 #endif /* LOG_LOCAL4 */
 398 }
 399
 400 #endif
 401
 402 void
 403 Debug::parseOptions(char const *options)
 404 {
 405     int i;
 406     char *p = NULL;
 407     char *s = NULL;
 408
 409     if (override_X) {
 410         debugs(0, 9, "command-line -X overrides: " << options);
 411         return;
 412     }
 413
 414     for (i = 0; i < MAX_DEBUG_SECTIONS; ++i)
 415         Debug::Levels[i] = 0;
 416
 417     if (options) {
 418         p = xstrdup(options);
 419
 420         for (s = strtok(p, w_space); s; s = strtok(NULL, w_space))
 421             debugArg(s);
 422
 423         xfree(p);
 424     }
 425 }
 426
 427 void
 428 _db_init(const char *logfile, const char *options)
 429 {
 430     Debug::parseOptions(options);
 431
 432     debugOpenLog(logfile);
 433
 434 #if HAVE_SYSLOG && defined(LOG_LOCAL4)
 435
 436     if (Debug::log_syslog)
 437         openlog(APP_SHORTNAME, LOG_PID | LOG_NDELAY | LOG_CONS, syslog_facility);
 438
 439 #endif /* HAVE_SYSLOG */
 440
 441     /* Pre-Init TZ env, see bug #2656 */
 442     tzset();
 443 }
 444
 445 void
 446 _db_rotate_log(void)
 447 {
 448     if (debug_log_file == NULL)
 449         return;
 450
 451 #ifdef S_ISREG
 452     struct stat sb;
 453     if (stat(debug_log_file, &sb) == 0)
 454         if (S_ISREG(sb.st_mode) == 0)
 455             return;
 456 #endif
 457
 458     char from[MAXPATHLEN];
 459     from[0] = '\0';
 460
 461     char to[MAXPATHLEN];
 462     to[0] = '\0';
 463
 464     /*
 465      * NOTE: we cannot use xrename here without having it in a
 466      * separate file -- tools.c has too many dependencies to be
 467      * used everywhere debug.c is used.
 468      */
 469     /* Rotate numbers 0 through N up one */
 470     for (int i = Debug::rotateNumber; i > 1;) {
 471         --i;
 472         snprintf(from, MAXPATHLEN, "%s.%d", debug_log_file, i - 1);
 473         snprintf(to, MAXPATHLEN, "%s.%d", debug_log_file, i);
 474 #if _SQUID_WINDOWS_
 475         remove
 476         (to);
 477 #endif
 478         errno = 0;
 479         if (rename(from, to) == -1) {
 480             const auto saved_errno = errno;
 481             debugs(0, DBG_IMPORTANT, "log rotation failed: " << xstrerr(saved_errno));
 482         }
 483     }
 484
 485     /*
 486      * You can't rename open files on Microsoft "operating systems"
 487      * so we close before renaming.
 488      */
 489 #if _SQUID_WINDOWS_
 490     if (debug_log != stderr)
 491         fclose(debug_log);
 492 #endif
 493     /* Rotate the current log to .0 */
 494     if (Debug::rotateNumber > 0) {
 495         snprintf(to, MAXPATHLEN, "%s.%d", debug_log_file, 0);
 496 #if _SQUID_WINDOWS_
 497         errno = 0;
 498         if (remove(to) == -1) {
 499             const auto saved_errno = errno;
 500             debugs(0, DBG_IMPORTANT, "removal of log file " << to << " failed: " << xstrerr(saved_errno));
 501         }
 502 #endif
 503         errno = 0;
 504         if (rename(debug_log_file, to) == -1) {
 505             const auto saved_errno = errno;
 506             debugs(0, DBG_IMPORTANT, "renaming file " << debug_log_file << " to "
 507                    << to << "failed: " << xstrerr(saved_errno));
 508         }
 509     }
 510
 511     /* Close and reopen the log.  It may have been renamed "manually"
 512      * before HUP'ing us. */
 513     if (debug_log != stderr)
 514         debugOpenLog(Debug::cache_log);
 515 }
 516
 517 static const char *
 518 debugLogTime(void)
 519 {
 520
 521     time_t t = getCurrentTime();
 522
 523     struct tm *tm;
 524     static char buf[128];
 525     static time_t last_t = 0;
 526
 527     if (Debug::Level() > 1) {
 528         char buf2[128];
 529         tm = localtime(&t);
 530         strftime(buf2, 127, "%Y/%m/%d %H:%M:%S", tm);
 531         buf2[127] = '\0';
 532         snprintf(buf, 127, "%s.%03d", buf2, (int) current_time.tv_usec / 1000);
 533         last_t = t;
 534     } else if (t != last_t) {
 535         tm = localtime(&t);
 536         strftime(buf, 127, "%Y/%m/%d %H:%M:%S", tm);
 537         last_t = t;
 538     }
 539
 540     buf[127] = '\0';
 541     return buf;
 542 }
 543
 544 static const char *
 545 debugLogKid(void)
 546 {
 547     if (KidIdentifier != 0) {
 548         static char buf[16];
 549         if (!*buf) // optimization: fill only once after KidIdentifier is set
 550             snprintf(buf, sizeof(buf), " kid%d", KidIdentifier);
 551         return buf;
 552     }
 553
 554     return "";
 555 }
 556
 557 void
 558 xassert(const char *msg, const char *file, int line)
 559 {
 560     debugs(0, DBG_CRITICAL, "assertion failed: " << file << ":" << line << ": \"" << msg << "\"");
 561
 562     if (!shutting_down)
 563         abort();
 564 }
 565
 566 /*
 567  * Context-based Debugging
 568  *
 569  * Rationale
 570  * ---------
 571  *
 572  * When you have a long nested processing sequence, it is often impossible
 573  * for low level routines to know in what larger context they operate. If a
 574  * routine coredumps, one can restore the context using debugger trace.
 575  * However, in many case you do not want to coredump, but just want to report
 576  * a potential problem. A report maybe useless out of problem context.
 577  *
 578  * To solve this potential problem, use the following approach:
 579  *
 580  * int
 581  * top_level_foo(const char *url)
 582  * {
 583  *      // define current context
 584  *      // note: we stack but do not dup ctx descriptions!
 585  *      Ctx ctx = ctx_enter(url);
 586  *      ...
 587  *      // go down; middle_level_bar will eventually call bottom_level_boo
 588  *      middle_level_bar(method, protocol);
 589  *      ...
 590  *      // exit, clean after yourself
 591  *      ctx_exit(ctx);
 592  * }
 593  *
 594  * void
 595  * bottom_level_boo(int status, void *data)
 596  * {
 597  *      // detect exceptional condition, and simply report it, the context
 598  *      // information will be available somewhere close in the log file
 599  *      if (status == STRANGE_STATUS)
 600  *      debugs(13, 6, "DOS attack detected, data: " << data);
 601  *      ...
 602  * }
 603  *
 604  * Current implementation is extremely simple but still very handy. It has a
 605  * negligible overhead (descriptions are not duplicated).
 606  *
 607  * When the _first_ debug message for a given context is printed, it is
 608  * prepended with the current context description. Context is printed with
 609  * the same debugging level as the original message.
 610  *
 611  * Note that we do not print context every type you do ctx_enter(). This
 612  * approach would produce too many useless messages.  For the same reason, a
 613  * context description is printed at most _once_ even if you have 10
 614  * debugging messages within one context.
 615  *
 616  * Contexts can be nested, of course. You must use ctx_enter() to enter a
 617  * context (push it onto stack).  It is probably safe to exit several nested
 618  * contexts at _once_ by calling ctx_exit() at the top level (this will pop
 619  * all context till current one). However, as in any stack, you cannot start
 620  * in the middle.
 621  *
 622  * Analysis:
 623  * i)   locate debugging message,
 624  * ii)  locate current context by going _upstream_ in your log file,
 625  * iii) hack away.
 626  *
 627  *
 628  * To-Do:
 629  * -----
 630  *
 631  *       decide if we want to dup() descriptions (adds overhead) but allows to
 632  *       add printf()-style interface
 633  *
 634  * implementation:
 635  * ---------------
 636  *
 637  * descriptions for contexts over CTX_MAX_LEVEL limit are ignored, you probably
 638  * have a bug if your nesting goes that deep.
 639  */
 640
 641 #define CTX_MAX_LEVEL 255
 642
 643 /*
 644  * produce a warning when nesting reaches this level and then double
 645  * the level
 646  */
 647 static int Ctx_Warn_Level = 32;
 648 /* all descriptions has been printed up to this level */
 649 static int Ctx_Reported_Level = -1;
 650 /* descriptions are still valid or active up to this level */
 651 static int Ctx_Valid_Level = -1;
 652 /* current level, the number of nested ctx_enter() calls */
 653 static int Ctx_Current_Level = -1;
 654 /* saved descriptions (stack) */
 655 static const char *Ctx_Descrs[CTX_MAX_LEVEL + 1];
 656 /* "safe" get secription */
 657 static const char *ctx_get_descr(Ctx ctx);
 658
 659 Ctx
 660 ctx_enter(const char *descr)
 661 {
 662     ++Ctx_Current_Level;
 663
 664     if (Ctx_Current_Level <= CTX_MAX_LEVEL)
 665         Ctx_Descrs[Ctx_Current_Level] = descr;
 666
 667     if (Ctx_Current_Level == Ctx_Warn_Level) {
 668         debugs(0, DBG_CRITICAL, "# ctx: suspiciously deep (" << Ctx_Warn_Level << ") nesting:");
 669         Ctx_Warn_Level *= 2;
 670     }
 671
 672     return Ctx_Current_Level;
 673 }
 674
 675 void
 676 ctx_exit(Ctx ctx)
 677 {
 678     assert(ctx >= 0);
 679     Ctx_Current_Level = (ctx >= 0) ? ctx - 1 : -1;
 680
 681     if (Ctx_Valid_Level > Ctx_Current_Level)
 682         Ctx_Valid_Level = Ctx_Current_Level;
 683 }
 684
 685 /*
 686  * the idea id to print each context description at most once but provide enough
 687  * info for deducing the current execution stack
 688  */
 689 static void
 690 ctx_print(void)
 691 {
 692     /* lock so _db_print will not call us recursively */
 693     ++Ctx_Lock;
 694     /* ok, user saw [0,Ctx_Reported_Level] descriptions */
 695     /* first inform about entries popped since user saw them */
 696
 697     if (Ctx_Valid_Level < Ctx_Reported_Level) {
 698         if (Ctx_Reported_Level != Ctx_Valid_Level + 1)
 699             _db_print("ctx: exit levels from %2d down to %2d\n",
 700                       Ctx_Reported_Level, Ctx_Valid_Level + 1);
 701         else
 702             _db_print("ctx: exit level %2d\n", Ctx_Reported_Level);
 703
 704         Ctx_Reported_Level = Ctx_Valid_Level;
 705     }
 706
 707     /* report new contexts that were pushed since last report */
 708     while (Ctx_Reported_Level < Ctx_Current_Level) {
 709         ++Ctx_Reported_Level;
 710         ++Ctx_Valid_Level;
 711         _db_print("ctx: enter level %2d: '%s'\n", Ctx_Reported_Level,
 712                   ctx_get_descr(Ctx_Reported_Level));
 713     }
 714
 715     /* unlock */
 716     --Ctx_Lock;
 717 }
 718
 719 /* checks for nulls and overflows */
 720 static const char *
 721 ctx_get_descr(Ctx ctx)
 722 {
 723     if (ctx < 0 || ctx > CTX_MAX_LEVEL)
 724         return "<lost>";
 725
 726     return Ctx_Descrs[ctx] ? Ctx_Descrs[ctx] : "<null>";
 727 }
 728
 729 Debug::Context *Debug::Current = nullptr;
 730
 731 Debug::Context::Context(const int aSection, const int aLevel):
 732     level(aLevel),
 733     sectionLevel(Levels[aSection]),
 734     upper(Current)
 735 {
 736     formatStream();
 737 }
 738
 739 /// Optimization: avoids new Context creation for every debugs().
 740 void
 741 Debug::Context::rewind(const int aSection, const int aLevel)
 742 {
 743     level = aLevel;
 744     sectionLevel = Levels[aSection];
 745     assert(upper == Current);
 746
 747     buf.str(std::string());
 748     buf.clear();
 749     // debugs() users are supposed to preserve format, but
 750     // some do not, so we have to waste cycles resetting it for all.
 751     formatStream();
 752 }
 753
 754 /// configures default formatting for the debugging stream
 755 void
 756 Debug::Context::formatStream()
 757 {
 758     const static std::ostringstream cleanStream;
 759     buf.flags(cleanStream.flags() | std::ios::fixed);
 760     buf.width(cleanStream.width());
 761     buf.precision(2);
 762     buf.fill(' ');
 763     // If this is not enough, use copyfmt(cleanStream) which is ~10% slower.
 764 }
 765
 766 std::ostringstream &
 767 Debug::Start(const int section, const int level)
 768 {
 769     Context *future = nullptr;
 770
 771     // prepare future context
 772     if (Current) {
 773         // all reentrant debugs() calls get here; create a dedicated context
 774         future = new Context(section, level);
 775     } else {
 776         // Optimization: Nearly all debugs() calls get here; avoid allocations
 777         static Context *topContext = new Context(1, 1);
 778         topContext->rewind(section, level);
 779         future = topContext;
 780     }
 781
 782     Current = future;
 783
 784     return future->buf;
 785 }
 786
 787 void
 788 Debug::Finish()
 789 {
 790     // TODO: Optimize to remove at least one extra copy.
 791     _db_print("%s\n", Current->buf.str().c_str());
 792
 793     Context *past = Current;
 794     Current = past->upper;
 795     if (Current)
 796         delete past;
 797     // else it was a static topContext from Debug::Start()
 798 }
 799
 800 size_t
 801 BuildPrefixInit()
 802 {
 803     // XXX: This must be kept in sync with the actual debug.cc location
 804     const char *ThisFileNameTail = "src/debug.cc";
 805
 806     const char *file=__FILE__;
 807
 808     // Disable heuristic if it does not work.
 809     if (!strstr(file, ThisFileNameTail))
 810         return 0;
 811
 812     return strlen(file)-strlen(ThisFileNameTail);
 813 }
 814
 815 const char*
 816 SkipBuildPrefix(const char* path)
 817 {
 818     static const size_t BuildPrefixLength = BuildPrefixInit();
 819
 820     return path+BuildPrefixLength;
 821 }
 822
 823 /// print data bytes using hex notation
 824 void
 825 Raw::printHex(std::ostream &os) const
 826 {
 827     const auto savedFill = os.fill('0');
 828     const auto savedFlags = os.flags(); // std::ios_base::fmtflags
 829     os << std::hex;
 830     std::for_each(data_, data_ + size_,
 831     [&os](const char &c) { os << std::setw(2) << static_cast<uint8_t>(c); });
 832     os.flags(savedFlags);
 833     os.fill(savedFill);
 834 }
 835
 836 std::ostream &
 837 Raw::print(std::ostream &os) const
 838 {
 839     if (label_)
 840         os << ' ' << label_ << '[' << size_ << ']';
 841
 842     if (!size_)
 843         return os;
 844
 845     // finalize debugging level if no level was set explicitly via minLevel()
 846     const int finalLevel = (level >= 0) ? level :
 847                            (size_ > 40 ? DBG_DATA : Debug::SectionLevel());
 848     if (finalLevel <= Debug::SectionLevel()) {
 849         os << (label_ ? '=' : ' ');
 850         if (data_) {
 851             if (useHex_)
 852                 printHex(os);
 853             else
 854                 os.write(data_, size_);
 855         } else {
 856             os << "[null]";
 857         }
 858     }
 859
 860     return os;
 861 }
 862