src/debug.cc

   1 /*
   2  * $Id: debug.cc,v 1.106 2007/12/04 15:20:22 rousskov Exp $
   3  *
   4  * DEBUG: section 0     Debug Routines
   5  * AUTHOR: Harvest Derived
   6  *
   7  * SQUID Web Proxy Cache          http://www.squid-cache.org/
   8  * ----------------------------------------------------------
   9  *
  10  *  Squid is the result of efforts by numerous individuals from
  11  *  the Internet community; see the CONTRIBUTORS file for full
  12  *  details.   Many organizations have provided support for Squid's
  13  *  development; see the SPONSORS file for full details.  Squid is
  14  *  Copyrighted (C) 2001 by the Regents of the University of
  15  *  California; see the COPYRIGHT file for full details.  Squid
  16  *  incorporates software developed and/or copyrighted by other
  17  *  sources; see the CREDITS file for full details.
  18  *
  19  *  This program is free software; you can redistribute it and/or modify
  20  *  it under the terms of the GNU General Public License as published by
  21  *  the Free Software Foundation; either version 2 of the License, or
  22  *  (at your option) any later version.
  23  *
  24  *  This program is distributed in the hope that it will be useful,
  25  *  but WITHOUT ANY WARRANTY; without even the implied warranty of
  26  *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  27  *  GNU General Public License for more details.
  28  *
  29  *  You should have received a copy of the GNU General Public License
  30  *  along with this program; if not, write to the Free Software
  31  *  Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111, USA.
  32  *
  33  */
  34
  35 #include "squid.h"
  36 #include "Debug.h"
  37 #include "SquidTime.h"
  38 #include <sstream>
  39
  40 int Debug::Levels[MAX_DEBUG_SECTIONS];
  41 int Debug::level;
  42
  43 static char *debug_log_file = NULL;
  44 static int Ctx_Lock = 0;
  45 static const char *debugLogTime(void);
  46 static void ctx_print(void);
  47 #if HAVE_SYSLOG
  48 #ifdef LOG_LOCAL4
  49 static int syslog_facility = 0;
  50 #endif
  51 static void _db_print_syslog(const char *format, va_list args);
  52 #endif
  53 static void _db_print_stderr(const char *format, va_list args);
  54 static void _db_print_file(const char *format, va_list args);
  55
  56 #ifdef _SQUID_MSWIN_
  57 SQUIDCEXTERN LPCRITICAL_SECTION dbg_mutex;
  58 typedef BOOL (WINAPI * PFInitializeCriticalSectionAndSpinCount) (LPCRITICAL_SECTION, DWORD);
  59
  60 #endif
  61
  62 void
  63 #if STDC_HEADERS
  64 _db_print(const char *format,...)
  65 {
  66 #else
  67 _db_print(va_alist)
  68 va_dcl
  69 {
  70     const char *format = NULL;
  71 #endif
  72
  73     LOCAL_ARRAY(char, f, BUFSIZ);
  74     va_list args1;
  75 #if STDC_HEADERS
  76
  77     va_list args2;
  78     va_list args3;
  79 #else
  80 #define args2 args1
  81 #define args3 args1
  82 #endif
  83 #ifdef _SQUID_MSWIN_
  84     /* Multiple WIN32 threads may call this simultaneously */
  85
  86     if (!dbg_mutex)
  87     {
  88         HMODULE krnl_lib = GetModuleHandle("Kernel32");
  89         PFInitializeCriticalSectionAndSpinCount InitializeCriticalSectionAndSpinCount = NULL;
  90
  91         if (krnl_lib)
  92             InitializeCriticalSectionAndSpinCount =
  93                 (PFInitializeCriticalSectionAndSpinCount) GetProcAddress(krnl_lib,
  94                         "InitializeCriticalSectionAndSpinCount");
  95
  96         dbg_mutex = static_cast<CRITICAL_SECTION*>(xcalloc(1, sizeof(CRITICAL_SECTION)));
  97
  98         if (InitializeCriticalSectionAndSpinCount) {
  99             /* let multiprocessor systems EnterCriticalSection() fast */
 100
 101             if (!InitializeCriticalSectionAndSpinCount(dbg_mutex, 4000)) {
 102                 if (debug_log) {
 103                     fprintf(debug_log, "FATAL: _db_print: can't initialize critical section\n");
 104                     fflush(debug_log);
 105                 }
 106
 107                 fprintf(stderr, "FATAL: _db_print: can't initialize critical section\n");
 108                 abort();
 109             } else
 110                 InitializeCriticalSection(dbg_mutex);
 111         }
 112     }
 113
 114     EnterCriticalSection(dbg_mutex);
 115 #endif
 116     /* give a chance to context-based debugging to print current context */
 117
 118     if (!Ctx_Lock)
 119         ctx_print();
 120
 121 #if STDC_HEADERS
 122
 123     va_start(args1, format);
 124
 125     va_start(args2, format);
 126
 127     va_start(args3, format);
 128
 129 #else
 130
 131     format = va_arg(args1, const char *);
 132
 133 #endif
 134
 135     snprintf(f, BUFSIZ, "%s| %s",
 136              debugLogTime(),
 137              format);
 138
 139     _db_print_file(f, args1);
 140
 141     _db_print_stderr(f, args2);
 142
 143 #if HAVE_SYSLOG
 144
 145     _db_print_syslog(format, args3);
 146
 147 #endif
 148 #ifdef _SQUID_MSWIN_
 149
 150     LeaveCriticalSection(dbg_mutex);
 151
 152 #endif
 153
 154     va_end(args1);
 155
 156 #if STDC_HEADERS
 157
 158     va_end(args2);
 159
 160     va_end(args3);
 161
 162 #endif
 163 }
 164
 165 static void
 166 _db_print_file(const char *format, va_list args) {
 167     if (debug_log == NULL)
 168         return;
 169
 170     /* give a chance to context-based debugging to print current context */
 171     if (!Ctx_Lock)
 172         ctx_print();
 173
 174     vfprintf(debug_log, format, args);
 175
 176     if (!Config.onoff.buffered_logs)
 177         fflush(debug_log);
 178 }
 179
 180 static void
 181 _db_print_stderr(const char *format, va_list args) {
 182     if (opt_debug_stderr < Debug::level)
 183         return;
 184
 185     if (debug_log == stderr)
 186         return;
 187
 188     vfprintf(stderr, format, args);
 189 }
 190
 191 #if HAVE_SYSLOG
 192 static void
 193 _db_print_syslog(const char *format, va_list args) {
 194     LOCAL_ARRAY(char, tmpbuf, BUFSIZ);
 195     /* level 0,1 go to syslog */
 196
 197     if (Debug::level > 1)
 198         return;
 199
 200     if (0 == opt_syslog_enable)
 201         return;
 202
 203     tmpbuf[0] = '\0';
 204
 205     vsnprintf(tmpbuf, BUFSIZ, format, args);
 206
 207     tmpbuf[BUFSIZ - 1] = '\0';
 208
 209     syslog(Debug::level == 0 ? LOG_WARNING : LOG_NOTICE, "%s", tmpbuf);
 210 }
 211
 212 #endif /* HAVE_SYSLOG */
 213
 214 static void
 215 debugArg(const char *arg) {
 216     int s = 0;
 217     int l = 0;
 218     int i;
 219
 220     if (!strncasecmp(arg, "ALL", 3)) {
 221         s = -1;
 222         arg += 4;
 223     } else {
 224         s = atoi(arg);
 225
 226         while (*arg && *arg++ != ',')
 227
 228             ;
 229     }
 230
 231     l = atoi(arg);
 232     assert(s >= -1);
 233
 234     if(s >= MAX_DEBUG_SECTIONS)
 235         s = MAX_DEBUG_SECTIONS-1;
 236
 237     if (l < 0)
 238         l = 0;
 239
 240     if (l > 10)
 241         l = 10;
 242
 243     if (s >= 0) {
 244         Debug::Levels[s] = l;
 245         return;
 246     }
 247
 248     for (i = 0; i < MAX_DEBUG_SECTIONS; i++)
 249         Debug::Levels[i] = l;
 250 }
 251
 252 static void
 253 debugOpenLog(const char *logfile) {
 254     if (logfile == NULL) {
 255         debug_log = stderr;
 256         return;
 257     }
 258
 259     if (debug_log_file)
 260         xfree(debug_log_file);
 261
 262     debug_log_file = xstrdup(logfile);  /* keep a static copy */
 263
 264     if (debug_log && debug_log != stderr)
 265         fclose(debug_log);
 266
 267     debug_log = fopen(logfile, "a+");
 268
 269     if (!debug_log) {
 270         fprintf(stderr, "WARNING: Cannot write log file: %s\n", logfile);
 271         perror(logfile);
 272         fprintf(stderr, "         messages will be sent to 'stderr'.\n");
 273         fflush(stderr);
 274         debug_log = stderr;
 275     }
 276
 277 #ifdef _SQUID_WIN32_
 278     setmode(fileno(debug_log), O_TEXT);
 279
 280 #endif
 281 }
 282
 283 #if HAVE_SYSLOG
 284 #ifdef LOG_LOCAL4
 285
 286 static struct syslog_facility_name {
 287     const char *name;
 288     int facility;
 289 }
 290
 291 syslog_facility_names[] = {
 292
 293 #ifdef LOG_AUTH
 294                               {
 295                                   "auth", LOG_AUTH
 296                               },
 297 #endif
 298 #ifdef LOG_AUTHPRIV
 299                               {
 300                                   "authpriv", LOG_AUTHPRIV
 301                               },
 302 #endif
 303 #ifdef LOG_CRON
 304                               {
 305                                   "cron", LOG_CRON
 306                               },
 307 #endif
 308 #ifdef LOG_DAEMON
 309                               {
 310                                   "daemon", LOG_DAEMON
 311                               },
 312 #endif
 313 #ifdef LOG_FTP
 314                               {
 315                                   "ftp", LOG_FTP
 316                               },
 317 #endif
 318 #ifdef LOG_KERN
 319                               {
 320                                   "kern", LOG_KERN
 321                               },
 322 #endif
 323 #ifdef LOG_LPR
 324                               {
 325                                   "lpr", LOG_LPR
 326                               },
 327 #endif
 328 #ifdef LOG_MAIL
 329                               {
 330                                   "mail", LOG_MAIL
 331                               },
 332 #endif
 333 #ifdef LOG_NEWS
 334                               {
 335                                   "news", LOG_NEWS
 336                               },
 337 #endif
 338 #ifdef LOG_SYSLOG
 339                               {
 340                                   "syslog", LOG_SYSLOG
 341                               },
 342 #endif
 343 #ifdef LOG_USER
 344                               {
 345                                   "user", LOG_USER
 346                               },
 347 #endif
 348 #ifdef LOG_UUCP
 349                               {
 350                                   "uucp", LOG_UUCP
 351                               },
 352 #endif
 353 #ifdef LOG_LOCAL0
 354                               {
 355                                   "local0", LOG_LOCAL0
 356                               },
 357 #endif
 358 #ifdef LOG_LOCAL1
 359                               {
 360                                   "local1", LOG_LOCAL1
 361                               },
 362 #endif
 363 #ifdef LOG_LOCAL2
 364                               {
 365                                   "local2", LOG_LOCAL2
 366                               },
 367 #endif
 368 #ifdef LOG_LOCAL3
 369                               {
 370                                   "local3", LOG_LOCAL3
 371                               },
 372 #endif
 373 #ifdef LOG_LOCAL4
 374                               {
 375                                   "local4", LOG_LOCAL4
 376                               },
 377 #endif
 378 #ifdef LOG_LOCAL5
 379                               {
 380                                   "local5", LOG_LOCAL5
 381                               },
 382 #endif
 383 #ifdef LOG_LOCAL6
 384                               {
 385                                   "local6", LOG_LOCAL6
 386                               },
 387 #endif
 388 #ifdef LOG_LOCAL7
 389                               {
 390                                   "local7", LOG_LOCAL7
 391                               },
 392 #endif
 393                               {
 394                                   NULL, 0
 395                               }
 396                           };
 397
 398 #endif
 399
 400 void
 401 _db_set_syslog(const char *facility) {
 402     opt_syslog_enable = 1;
 403 #ifdef LOG_LOCAL4
 404 #ifdef LOG_DAEMON
 405
 406     syslog_facility = LOG_DAEMON;
 407 #else
 408
 409     syslog_facility = LOG_LOCAL4;
 410 #endif
 411
 412     if (facility) {
 413
 414         struct syslog_facility_name *n;
 415
 416         for (n = syslog_facility_names; n->name; n++) {
 417             if (strcmp(n->name, facility) == 0) {
 418                 syslog_facility = n->facility;
 419                 return;
 420             }
 421         }
 422
 423         fprintf(stderr, "unknown syslog facility '%s'\n", facility);
 424         exit(1);
 425     }
 426
 427 #else
 428     if (facility)
 429         fprintf(stderr, "syslog facility type not supported on your system\n");
 430
 431 #endif
 432 }
 433
 434 #endif
 435
 436 void
 437 Debug::parseOptions(char const *options) {
 438     int i;
 439     char *p = NULL;
 440     char *s = NULL;
 441
 442     if(Config.onoff.debug_override_X) {
 443         debugs(0, 9, "command-line -X overrides: " << options);
 444         return;
 445     }
 446
 447     for (i = 0; i < MAX_DEBUG_SECTIONS; i++)
 448         Debug::Levels[i] = -1;
 449
 450     if (options) {
 451         p = xstrdup(options);
 452
 453         for (s = strtok(p, w_space); s; s = strtok(NULL, w_space))
 454             debugArg(s);
 455
 456         xfree(p);
 457     }
 458 }
 459
 460 void
 461 _db_init(const char *logfile, const char *options) {
 462     Debug::parseOptions(options);
 463
 464     debugOpenLog(logfile);
 465
 466 #if HAVE_SYSLOG && defined(LOG_LOCAL4)
 467
 468     if (opt_syslog_enable)
 469         openlog(appname, LOG_PID | LOG_NDELAY | LOG_CONS, syslog_facility);
 470
 471 #endif /* HAVE_SYSLOG */
 472
 473 }
 474
 475 void
 476 _db_rotate_log(void) {
 477     int i;
 478     LOCAL_ARRAY(char, from, MAXPATHLEN);
 479     LOCAL_ARRAY(char, to, MAXPATHLEN);
 480 #ifdef S_ISREG
 481
 482     struct stat sb;
 483 #endif
 484
 485     if (debug_log_file == NULL)
 486         return;
 487
 488 #ifdef S_ISREG
 489
 490     if (stat(debug_log_file, &sb) == 0)
 491         if (S_ISREG(sb.st_mode) == 0)
 492             return;
 493
 494 #endif
 495
 496     /*
 497      * NOTE: we cannot use xrename here without having it in a
 498      * separate file -- tools.c has too many dependencies to be
 499      * used everywhere debug.c is used.
 500      */
 501     /* Rotate numbers 0 through N up one */
 502     for (i = Config.Log.rotateNumber; i > 1;) {
 503         i--;
 504         snprintf(from, MAXPATHLEN, "%s.%d", debug_log_file, i - 1);
 505         snprintf(to, MAXPATHLEN, "%s.%d", debug_log_file, i);
 506 #ifdef _SQUID_MSWIN_
 507
 508         remove
 509             (to);
 510
 511 #endif
 512
 513         rename(from, to);
 514     }
 515
 516     /*
 517      * You can't rename open files on Microsoft "operating systems"
 518      * so we close before renaming.
 519      */
 520 #ifdef _SQUID_MSWIN_
 521     if (debug_log != stderr)
 522         fclose(debug_log);
 523
 524 #endif
 525     /* Rotate the current log to .0 */
 526     if (Config.Log.rotateNumber > 0) {
 527         snprintf(to, MAXPATHLEN, "%s.%d", debug_log_file, 0);
 528 #ifdef _SQUID_MSWIN_
 529
 530         remove
 531             (to);
 532
 533 #endif
 534
 535         rename(debug_log_file, to);
 536     }
 537
 538     /* Close and reopen the log.  It may have been renamed "manually"
 539      * before HUP'ing us. */
 540     if (debug_log != stderr)
 541         debugOpenLog(Config.Log.log);
 542 }
 543
 544 static const char *
 545 debugLogTime(void) {
 546
 547     time_t t = getCurrentTime();
 548
 549     struct tm *tm;
 550     static char buf[128];
 551     static time_t last_t = 0;
 552
 553     if (Debug::level > 1) {
 554         char buf2[128];
 555         tm = localtime(&t);
 556         strftime(buf2, 127, "%Y/%m/%d %H:%M:%S", tm);
 557         buf2[127] = '\0';
 558         snprintf(buf, 127, "%s.%03d", buf2, (int) current_time.tv_usec / 1000);
 559         last_t = t;
 560     } else if (t != last_t) {
 561         tm = localtime(&t);
 562         strftime(buf, 127, "%Y/%m/%d %H:%M:%S", tm);
 563         last_t = t;
 564     }
 565
 566     buf[127] = '\0';
 567     return buf;
 568 }
 569
 570 void
 571 xassert(const char *msg, const char *file, int line) {
 572     debugs(0, 0, "assertion failed: " << file << ":" << line << ": \"" << msg << "\"");
 573
 574     if (!shutting_down)
 575         abort();
 576 }
 577
 578 /*
 579  * Context-based Debugging
 580  *
 581  * Rationale
 582  * ---------
 583  *
 584  * When you have a long nested processing sequence, it is often impossible
 585  * for low level routines to know in what larger context they operate. If a
 586  * routine coredumps, one can restore the context using debugger trace.
 587  * However, in many case you do not want to coredump, but just want to report
 588  * a potential problem. A report maybe useless out of problem context.
 589  *
 590  * To solve this potential problem, use the following approach:
 591  *
 592  * int
 593  * top_level_foo(const char *url)
 594  * {
 595  *      // define current context
 596  *      // note: we stack but do not dup ctx descriptions!
 597  *      Ctx ctx = ctx_enter(url);
 598  *      ...
 599  *      // go down; middle_level_bar will eventually call bottom_level_boo
 600  *      middle_level_bar(method, protocol);
 601  *      ...
 602  *      // exit, clean after yourself
 603  *      ctx_exit(ctx);
 604  * }
 605  *
 606  * void
 607  * bottom_level_boo(int status, void *data)
 608  * {
 609  *      // detect exceptional condition, and simply report it, the context
 610  *      // information will be available somewhere close in the log file
 611  *      if (status == STRANGE_STATUS)
 612  *      debugs(13, 6, "DOS attack detected, data: " << data);
 613  *      ...
 614  * }
 615  *
 616  * Current implementation is extremely simple but still very handy. It has a
 617  * negligible overhead (descriptions are not duplicated).
 618  *
 619  * When the _first_ debug message for a given context is printed, it is
 620  * prepended with the current context description. Context is printed with
 621  * the same debugging level as the original message.
 622  *
 623  * Note that we do not print context every type you do ctx_enter(). This
 624  * approach would produce too many useless messages.  For the same reason, a
 625  * context description is printed at most _once_ even if you have 10
 626  * debugging messages within one context.
 627  *
 628  * Contexts can be nested, of course. You must use ctx_enter() to enter a
 629  * context (push it onto stack).  It is probably safe to exit several nested
 630  * contexts at _once_ by calling ctx_exit() at the top level (this will pop
 631  * all context till current one). However, as in any stack, you cannot start
 632  * in the middle.
 633  *
 634  * Analysis:
 635  * i)   locate debugging message,
 636  * ii)  locate current context by going _upstream_ in your log file,
 637  * iii) hack away.
 638  *
 639  *
 640  * To-Do:
 641  * -----
 642  *
 643  *       decide if we want to dup() descriptions (adds overhead) but allows to
 644  *       add printf()-style interface
 645  *
 646  * implementation:
 647  * ---------------
 648  *
 649  * descriptions for contexts over CTX_MAX_LEVEL limit are ignored, you probably
 650  * have a bug if your nesting goes that deep.
 651  */
 652
 653 #define CTX_MAX_LEVEL 255
 654
 655 /*
 656  * produce a warning when nesting reaches this level and then double
 657  * the level
 658  */
 659 static int Ctx_Warn_Level = 32;
 660 /* all descriptions has been printed up to this level */
 661 static int Ctx_Reported_Level = -1;
 662 /* descriptions are still valid or active up to this level */
 663 static int Ctx_Valid_Level = -1;
 664 /* current level, the number of nested ctx_enter() calls */
 665 static int Ctx_Current_Level = -1;
 666 /* saved descriptions (stack) */
 667 static const char *Ctx_Descrs[CTX_MAX_LEVEL + 1];
 668 /* "safe" get secription */
 669 static const char *ctx_get_descr(Ctx ctx);
 670
 671
 672 Ctx
 673 ctx_enter(const char *descr) {
 674     Ctx_Current_Level++;
 675
 676     if (Ctx_Current_Level <= CTX_MAX_LEVEL)
 677         Ctx_Descrs[Ctx_Current_Level] = descr;
 678
 679     if (Ctx_Current_Level == Ctx_Warn_Level) {
 680         debugs(0, 0, "# ctx: suspiciously deep (" << Ctx_Warn_Level << ") nesting:");
 681         Ctx_Warn_Level *= 2;
 682     }
 683
 684     return Ctx_Current_Level;
 685 }
 686
 687 void
 688 ctx_exit(Ctx ctx) {
 689     assert(ctx >= 0);
 690     Ctx_Current_Level = (ctx >= 0) ? ctx - 1 : -1;
 691
 692     if (Ctx_Valid_Level > Ctx_Current_Level)
 693         Ctx_Valid_Level = Ctx_Current_Level;
 694 }
 695
 696 /*
 697  * the idea id to print each context description at most once but provide enough
 698  * info for deducing the current execution stack
 699  */
 700 static void
 701 ctx_print(void) {
 702     /* lock so _db_print will not call us recursively */
 703     Ctx_Lock++;
 704     /* ok, user saw [0,Ctx_Reported_Level] descriptions */
 705     /* first inform about entries popped since user saw them */
 706
 707     if (Ctx_Valid_Level < Ctx_Reported_Level) {
 708         if (Ctx_Reported_Level != Ctx_Valid_Level + 1)
 709             _db_print("ctx: exit levels from %2d down to %2d\n",
 710                       Ctx_Reported_Level, Ctx_Valid_Level + 1);
 711         else
 712             _db_print("ctx: exit level %2d\n", Ctx_Reported_Level);
 713
 714         Ctx_Reported_Level = Ctx_Valid_Level;
 715     }
 716
 717     /* report new contexts that were pushed since last report */
 718     while (Ctx_Reported_Level < Ctx_Current_Level) {
 719         Ctx_Reported_Level++;
 720         Ctx_Valid_Level++;
 721         _db_print("ctx: enter level %2d: '%s'\n", Ctx_Reported_Level,
 722                   ctx_get_descr(Ctx_Reported_Level));
 723     }
 724
 725     /* unlock */
 726     Ctx_Lock--;
 727 }
 728
 729 /* checks for nulls and overflows */
 730 static const char *
 731 ctx_get_descr(Ctx ctx) {
 732     if (ctx < 0 || ctx > CTX_MAX_LEVEL)
 733         return "<lost>";
 734
 735     return Ctx_Descrs[ctx] ? Ctx_Descrs[ctx] : "<null>";
 736 }
 737
 738 std::ostream &
 739 Debug::getDebugOut() {
 740     assert (CurrentDebug == NULL);
 741     CurrentDebug = new std::ostringstream();
 742     // set default formatting flags
 743     CurrentDebug->setf(std::ios::fixed);
 744     CurrentDebug->precision(2);
 745     return *CurrentDebug;
 746 }
 747
 748 void
 749 Debug::finishDebug() {
 750     _db_print("%s\n", CurrentDebug->str().c_str());
 751     delete CurrentDebug;
 752     CurrentDebug = NULL;
 753 }
 754
 755 std::ostringstream (*Debug::CurrentDebug)(NULL);