2 * DEBUG: section 00 Debug Routines
3 * AUTHOR: Harvest Derived
5 * SQUID Web Proxy Cache http://www.squid-cache.org/
6 * ----------------------------------------------------------
8 * Squid is the result of efforts by numerous individuals from
9 * the Internet community; see the CONTRIBUTORS file for full
10 * details. Many organizations have provided support for Squid's
11 * development; see the SPONSORS file for full details. Squid is
12 * Copyrighted (C) 2001 by the Regents of the University of
13 * California; see the COPYRIGHT file for full details. Squid
14 * incorporates software developed and/or copyrighted by other
15 * sources; see the CREDITS file for full details.
17 * This program is free software; you can redistribute it and/or modify
18 * it under the terms of the GNU General Public License as published by
19 * the Free Software Foundation; either version 2 of the License, or
20 * (at your option) any later version.
22 * This program is distributed in the hope that it will be useful,
23 * but WITHOUT ANY WARRANTY; without even the implied warranty of
24 * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
25 * GNU General Public License for more details.
27 * You should have received a copy of the GNU General Public License
28 * along with this program; if not, write to the Free Software
29 * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111, USA.
35 #include "SquidTime.h"
39 /* for shutting_down flag in xassert() */
42 char *Debug::debugOptions
= NULL
;
43 int Debug::override_X
= 0;
44 int Debug::log_stderr
= -1;
45 bool Debug::log_syslog
= false;
46 int Debug::Levels
[MAX_DEBUG_SECTIONS
];
48 int Debug::sectionLevel
;
49 char *Debug::cache_log
= NULL
;
50 int Debug::rotateNumber
= -1;
51 FILE *debug_log
= NULL
;
52 static char *debug_log_file
= NULL
;
53 static int Ctx_Lock
= 0;
54 static const char *debugLogTime(void);
55 static const char *debugLogKid(void);
56 static void ctx_print(void);
59 static int syslog_facility
= 0;
61 static void _db_print_syslog(const char *format
, va_list args
);
63 static void _db_print_stderr(const char *format
, va_list args
);
64 static void _db_print_file(const char *format
, va_list args
);
67 extern LPCRITICAL_SECTION dbg_mutex
;
68 typedef BOOL (WINAPI
* PFInitializeCriticalSectionAndSpinCount
) (LPCRITICAL_SECTION
, DWORD
);
72 _db_print(const char *format
,...)
81 /* Multiple WIN32 threads may call this simultaneously */
84 HMODULE krnl_lib
= GetModuleHandle("Kernel32");
85 PFInitializeCriticalSectionAndSpinCount InitializeCriticalSectionAndSpinCount
= NULL
;
88 InitializeCriticalSectionAndSpinCount
=
89 (PFInitializeCriticalSectionAndSpinCount
) GetProcAddress(krnl_lib
,
90 "InitializeCriticalSectionAndSpinCount");
92 dbg_mutex
= static_cast<CRITICAL_SECTION
*>(xcalloc(1, sizeof(CRITICAL_SECTION
)));
94 if (InitializeCriticalSectionAndSpinCount
) {
95 /* let multiprocessor systems EnterCriticalSection() fast */
97 if (!InitializeCriticalSectionAndSpinCount(dbg_mutex
, 4000)) {
99 fprintf(debug_log
, "FATAL: _db_print: can't initialize critical section\n");
103 fprintf(stderr
, "FATAL: _db_print: can't initialize critical section\n");
106 InitializeCriticalSection(dbg_mutex
);
110 EnterCriticalSection(dbg_mutex
);
113 /* give a chance to context-based debugging to print current context */
117 va_start(args1
, format
);
118 va_start(args2
, format
);
119 va_start(args3
, format
);
121 snprintf(f
, BUFSIZ
, "%s%s| %s",
126 _db_print_file(f
, args1
);
127 _db_print_stderr(f
, args2
);
130 _db_print_syslog(format
, args3
);
134 LeaveCriticalSection(dbg_mutex
);
143 _db_print_file(const char *format
, va_list args
)
145 if (debug_log
== NULL
)
148 /* give a chance to context-based debugging to print current context */
152 vfprintf(debug_log
, format
, args
);
157 _db_print_stderr(const char *format
, va_list args
)
159 if (Debug::log_stderr
< Debug::level
)
162 if (debug_log
== stderr
)
165 vfprintf(stderr
, format
, args
);
170 _db_print_syslog(const char *format
, va_list args
)
172 /* level 0,1 go to syslog */
174 if (Debug::level
> 1)
177 if (!Debug::log_syslog
)
183 vsnprintf(tmpbuf
, BUFSIZ
, format
, args
);
185 tmpbuf
[BUFSIZ
- 1] = '\0';
187 syslog(Debug::level
== 0 ? LOG_WARNING
: LOG_NOTICE
, "%s", tmpbuf
);
189 #endif /* HAVE_SYSLOG */
192 debugArg(const char *arg
)
198 if (!strncasecmp(arg
, "rotate=", 7)) {
200 Debug::rotateNumber
= atoi(arg
);
202 } else if (!strncasecmp(arg
, "ALL", 3)) {
207 while (*arg
&& *arg
++ != ',');
213 if (s
>= MAX_DEBUG_SECTIONS
)
214 s
= MAX_DEBUG_SECTIONS
-1;
223 Debug::Levels
[s
] = l
;
227 for (i
= 0; i
< MAX_DEBUG_SECTIONS
; ++i
)
228 Debug::Levels
[i
] = l
;
232 debugOpenLog(const char *logfile
)
234 if (logfile
== NULL
) {
240 xfree(debug_log_file
);
242 debug_log_file
= xstrdup(logfile
); /* keep a static copy */
244 if (debug_log
&& debug_log
!= stderr
)
247 debug_log
= fopen(logfile
, "a+");
250 fprintf(stderr
, "WARNING: Cannot write log file: %s\n", logfile
);
252 fprintf(stderr
, " messages will be sent to 'stderr'.\n");
258 setmode(fileno(debug_log
), O_TEXT
);
265 static struct syslog_facility_name
{
270 syslog_facility_names
[] = {
279 "authpriv", LOG_AUTHPRIV
380 _db_set_syslog(const char *facility
)
382 Debug::log_syslog
= true;
387 syslog_facility
= LOG_DAEMON
;
390 syslog_facility
= LOG_LOCAL4
;
391 #endif /* LOG_DAEMON */
395 struct syslog_facility_name
*n
;
397 for (n
= syslog_facility_names
; n
->name
; ++n
) {
398 if (strcmp(n
->name
, facility
) == 0) {
399 syslog_facility
= n
->facility
;
404 fprintf(stderr
, "unknown syslog facility '%s'\n", facility
);
410 fprintf(stderr
, "syslog facility type not supported on your system\n");
412 #endif /* LOG_LOCAL4 */
418 Debug::parseOptions(char const *options
)
425 debugs(0, 9, "command-line -X overrides: " << options
);
429 for (i
= 0; i
< MAX_DEBUG_SECTIONS
; ++i
)
430 Debug::Levels
[i
] = 0;
433 p
= xstrdup(options
);
435 for (s
= strtok(p
, w_space
); s
; s
= strtok(NULL
, w_space
))
443 _db_init(const char *logfile
, const char *options
)
445 Debug::parseOptions(options
);
447 debugOpenLog(logfile
);
449 #if HAVE_SYSLOG && defined(LOG_LOCAL4)
451 if (Debug::log_syslog
)
452 openlog(APP_SHORTNAME
, LOG_PID
| LOG_NDELAY
| LOG_CONS
, syslog_facility
);
454 #endif /* HAVE_SYSLOG */
456 /* Pre-Init TZ env, see bug #2656 */
463 if (debug_log_file
== NULL
)
468 if (stat(debug_log_file
, &sb
) == 0)
469 if (S_ISREG(sb
.st_mode
) == 0)
473 char from
[MAXPATHLEN
];
480 * NOTE: we cannot use xrename here without having it in a
481 * separate file -- tools.c has too many dependencies to be
482 * used everywhere debug.c is used.
484 /* Rotate numbers 0 through N up one */
485 for (int i
= Debug::rotateNumber
; i
> 1;) {
487 snprintf(from
, MAXPATHLEN
, "%s.%d", debug_log_file
, i
- 1);
488 snprintf(to
, MAXPATHLEN
, "%s.%d", debug_log_file
, i
);
497 * You can't rename open files on Microsoft "operating systems"
498 * so we close before renaming.
501 if (debug_log
!= stderr
)
504 /* Rotate the current log to .0 */
505 if (Debug::rotateNumber
> 0) {
506 snprintf(to
, MAXPATHLEN
, "%s.%d", debug_log_file
, 0);
511 rename(debug_log_file
, to
);
514 /* Close and reopen the log. It may have been renamed "manually"
515 * before HUP'ing us. */
516 if (debug_log
!= stderr
)
517 debugOpenLog(Debug::cache_log
);
524 time_t t
= getCurrentTime();
527 static char buf
[128];
528 static time_t last_t
= 0;
530 if (Debug::level
> 1) {
533 strftime(buf2
, 127, "%Y/%m/%d %H:%M:%S", tm
);
535 snprintf(buf
, 127, "%s.%03d", buf2
, (int) current_time
.tv_usec
/ 1000);
537 } else if (t
!= last_t
) {
539 strftime(buf
, 127, "%Y/%m/%d %H:%M:%S", tm
);
550 if (KidIdentifier
!= 0) {
552 if (!*buf
) // optimization: fill only once after KidIdentifier is set
553 snprintf(buf
, sizeof(buf
), " kid%d", KidIdentifier
);
561 xassert(const char *msg
, const char *file
, int line
)
563 debugs(0, DBG_CRITICAL
, "assertion failed: " << file
<< ":" << line
<< ": \"" << msg
<< "\"");
570 * Context-based Debugging
575 * When you have a long nested processing sequence, it is often impossible
576 * for low level routines to know in what larger context they operate. If a
577 * routine coredumps, one can restore the context using debugger trace.
578 * However, in many case you do not want to coredump, but just want to report
579 * a potential problem. A report maybe useless out of problem context.
581 * To solve this potential problem, use the following approach:
584 * top_level_foo(const char *url)
586 * // define current context
587 * // note: we stack but do not dup ctx descriptions!
588 * Ctx ctx = ctx_enter(url);
590 * // go down; middle_level_bar will eventually call bottom_level_boo
591 * middle_level_bar(method, protocol);
593 * // exit, clean after yourself
598 * bottom_level_boo(int status, void *data)
600 * // detect exceptional condition, and simply report it, the context
601 * // information will be available somewhere close in the log file
602 * if (status == STRANGE_STATUS)
603 * debugs(13, 6, "DOS attack detected, data: " << data);
607 * Current implementation is extremely simple but still very handy. It has a
608 * negligible overhead (descriptions are not duplicated).
610 * When the _first_ debug message for a given context is printed, it is
611 * prepended with the current context description. Context is printed with
612 * the same debugging level as the original message.
614 * Note that we do not print context every type you do ctx_enter(). This
615 * approach would produce too many useless messages. For the same reason, a
616 * context description is printed at most _once_ even if you have 10
617 * debugging messages within one context.
619 * Contexts can be nested, of course. You must use ctx_enter() to enter a
620 * context (push it onto stack). It is probably safe to exit several nested
621 * contexts at _once_ by calling ctx_exit() at the top level (this will pop
622 * all context till current one). However, as in any stack, you cannot start
626 * i) locate debugging message,
627 * ii) locate current context by going _upstream_ in your log file,
634 * decide if we want to dup() descriptions (adds overhead) but allows to
635 * add printf()-style interface
640 * descriptions for contexts over CTX_MAX_LEVEL limit are ignored, you probably
641 * have a bug if your nesting goes that deep.
644 #define CTX_MAX_LEVEL 255
647 * produce a warning when nesting reaches this level and then double
650 static int Ctx_Warn_Level
= 32;
651 /* all descriptions has been printed up to this level */
652 static int Ctx_Reported_Level
= -1;
653 /* descriptions are still valid or active up to this level */
654 static int Ctx_Valid_Level
= -1;
655 /* current level, the number of nested ctx_enter() calls */
656 static int Ctx_Current_Level
= -1;
657 /* saved descriptions (stack) */
658 static const char *Ctx_Descrs
[CTX_MAX_LEVEL
+ 1];
659 /* "safe" get secription */
660 static const char *ctx_get_descr(Ctx ctx
);
663 ctx_enter(const char *descr
)
667 if (Ctx_Current_Level
<= CTX_MAX_LEVEL
)
668 Ctx_Descrs
[Ctx_Current_Level
] = descr
;
670 if (Ctx_Current_Level
== Ctx_Warn_Level
) {
671 debugs(0, DBG_CRITICAL
, "# ctx: suspiciously deep (" << Ctx_Warn_Level
<< ") nesting:");
675 return Ctx_Current_Level
;
682 Ctx_Current_Level
= (ctx
>= 0) ? ctx
- 1 : -1;
684 if (Ctx_Valid_Level
> Ctx_Current_Level
)
685 Ctx_Valid_Level
= Ctx_Current_Level
;
689 * the idea id to print each context description at most once but provide enough
690 * info for deducing the current execution stack
695 /* lock so _db_print will not call us recursively */
697 /* ok, user saw [0,Ctx_Reported_Level] descriptions */
698 /* first inform about entries popped since user saw them */
700 if (Ctx_Valid_Level
< Ctx_Reported_Level
) {
701 if (Ctx_Reported_Level
!= Ctx_Valid_Level
+ 1)
702 _db_print("ctx: exit levels from %2d down to %2d\n",
703 Ctx_Reported_Level
, Ctx_Valid_Level
+ 1);
705 _db_print("ctx: exit level %2d\n", Ctx_Reported_Level
);
707 Ctx_Reported_Level
= Ctx_Valid_Level
;
710 /* report new contexts that were pushed since last report */
711 while (Ctx_Reported_Level
< Ctx_Current_Level
) {
712 ++Ctx_Reported_Level
;
714 _db_print("ctx: enter level %2d: '%s'\n", Ctx_Reported_Level
,
715 ctx_get_descr(Ctx_Reported_Level
));
722 /* checks for nulls and overflows */
724 ctx_get_descr(Ctx ctx
)
726 if (ctx
< 0 || ctx
> CTX_MAX_LEVEL
)
729 return Ctx_Descrs
[ctx
] ? Ctx_Descrs
[ctx
] : "<null>";
732 int Debug::TheDepth
= 0;
737 assert(TheDepth
>= 0);
740 assert(CurrentDebug
);
741 *CurrentDebug
<< std::endl
<< "reentrant debuging " << TheDepth
<< "-{";
743 assert(!CurrentDebug
);
744 CurrentDebug
= new std::ostringstream();
745 // set default formatting flags
746 CurrentDebug
->setf(std::ios::fixed
);
747 CurrentDebug
->precision(2);
749 return *CurrentDebug
;
755 assert(TheDepth
>= 0);
756 assert(CurrentDebug
);
758 *CurrentDebug
<< "}-" << TheDepth
<< std::endl
;
760 assert(TheDepth
== 1);
761 _db_print("%s\n", CurrentDebug
->str().c_str());
768 // Hack: replaces global ::xassert() to debug debugging assertions
769 // Relies on assert macro calling xassert() without a specific scope.
771 Debug::xassert(const char *msg
, const char *file
, int line
)
775 *CurrentDebug
<< "assertion failed: " << file
<< ":" << line
<<
776 ": \"" << msg
<< "\"";
781 std::ostringstream (*Debug::CurrentDebug
)(NULL
);
786 // XXX: This must be kept in sync with the actual debug.cc location
787 const char *ThisFileNameTail
= "src/debug.cc";
789 const char *file
=__FILE__
;
791 // Disable heuristic if it does not work.
792 if (!strstr(file
, ThisFileNameTail
))
795 return strlen(file
)-strlen(ThisFileNameTail
);
799 SkipBuildPrefix(const char* path
)
801 static const size_t BuildPrefixLength
= BuildPrefixInit();
803 return path
+BuildPrefixLength
;
807 Raw::print(std::ostream
&os
) const
810 os
<< ' ' << label_
<< '[' << size_
<< ']';
815 // finalize debugging level if no level was set explicitly via minLevel()
816 const int finalLevel
= (level
>= 0) ? level
:
817 (size_
> 40 ? DBG_DATA
: Debug::sectionLevel
);
818 if (finalLevel
<= Debug::sectionLevel
) {
819 os
<< (label_
? '=' : ' ');
821 os
.write(data_
, size_
);