2 * $Id: debug.cc,v 1.109 2008/02/26 18:43:30 rousskov Exp $
4 * DEBUG: section 0 Debug Routines
5 * AUTHOR: Harvest Derived
7 * SQUID Web Proxy Cache http://www.squid-cache.org/
8 * ----------------------------------------------------------
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.
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.
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.
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.
36 #include "SquidTime.h"
41 int Debug::Levels
[MAX_DEBUG_SECTIONS
];
44 static char *debug_log_file
= NULL
;
45 static int Ctx_Lock
= 0;
46 static const char *debugLogTime(void);
47 static void ctx_print(void);
50 static int syslog_facility
= 0;
52 static void _db_print_syslog(const char *format
, va_list args
);
54 static void _db_print_stderr(const char *format
, va_list args
);
55 static void _db_print_file(const char *format
, va_list args
);
58 SQUIDCEXTERN LPCRITICAL_SECTION dbg_mutex
;
59 typedef BOOL (WINAPI
* PFInitializeCriticalSectionAndSpinCount
) (LPCRITICAL_SECTION
, DWORD
);
65 _db_print(const char *format
,...)
71 const char *format
= NULL
;
74 LOCAL_ARRAY(char, f
, BUFSIZ
);
85 /* Multiple WIN32 threads may call this simultaneously */
89 HMODULE krnl_lib
= GetModuleHandle("Kernel32");
90 PFInitializeCriticalSectionAndSpinCount InitializeCriticalSectionAndSpinCount
= NULL
;
93 InitializeCriticalSectionAndSpinCount
=
94 (PFInitializeCriticalSectionAndSpinCount
) GetProcAddress(krnl_lib
,
95 "InitializeCriticalSectionAndSpinCount");
97 dbg_mutex
= static_cast<CRITICAL_SECTION
*>(xcalloc(1, sizeof(CRITICAL_SECTION
)));
99 if (InitializeCriticalSectionAndSpinCount
) {
100 /* let multiprocessor systems EnterCriticalSection() fast */
102 if (!InitializeCriticalSectionAndSpinCount(dbg_mutex
, 4000)) {
104 fprintf(debug_log
, "FATAL: _db_print: can't initialize critical section\n");
108 fprintf(stderr
, "FATAL: _db_print: can't initialize critical section\n");
111 InitializeCriticalSection(dbg_mutex
);
115 EnterCriticalSection(dbg_mutex
);
117 /* give a chance to context-based debugging to print current context */
124 va_start(args1
, format
);
126 va_start(args2
, format
);
128 va_start(args3
, format
);
132 format
= va_arg(args1
, const char *);
136 snprintf(f
, BUFSIZ
, "%s| %s",
140 _db_print_file(f
, args1
);
142 _db_print_stderr(f
, args2
);
146 _db_print_syslog(format
, args3
);
151 LeaveCriticalSection(dbg_mutex
);
167 _db_print_file(const char *format
, va_list args
) {
168 if (debug_log
== NULL
)
171 /* give a chance to context-based debugging to print current context */
175 vfprintf(debug_log
, format
, args
);
177 //*AYJ:*/ if (!Config.onoff.buffered_logs)
182 _db_print_stderr(const char *format
, va_list args
) {
183 if (opt_debug_stderr
< Debug::level
)
186 if (debug_log
== stderr
)
189 vfprintf(stderr
, format
, args
);
194 _db_print_syslog(const char *format
, va_list args
) {
195 LOCAL_ARRAY(char, tmpbuf
, BUFSIZ
);
196 /* level 0,1 go to syslog */
198 if (Debug::level
> 1)
201 if (0 == opt_syslog_enable
)
206 vsnprintf(tmpbuf
, BUFSIZ
, format
, args
);
208 tmpbuf
[BUFSIZ
- 1] = '\0';
210 syslog(Debug::level
== 0 ? LOG_WARNING
: LOG_NOTICE
, "%s", tmpbuf
);
213 #endif /* HAVE_SYSLOG */
216 debugArg(const char *arg
) {
221 if (!strncasecmp(arg
, "ALL", 3)) {
227 while (*arg
&& *arg
++ != ',');
233 if(s
>= MAX_DEBUG_SECTIONS
)
234 s
= MAX_DEBUG_SECTIONS
-1;
243 Debug::Levels
[s
] = l
;
247 for (i
= 0; i
< MAX_DEBUG_SECTIONS
; i
++)
248 Debug::Levels
[i
] = l
;
252 debugOpenLog(const char *logfile
) {
253 if (logfile
== NULL
) {
259 xfree(debug_log_file
);
261 debug_log_file
= xstrdup(logfile
); /* keep a static copy */
263 if (debug_log
&& debug_log
!= stderr
)
266 debug_log
= fopen(logfile
, "a+");
269 fprintf(stderr
, "WARNING: Cannot write log file: %s\n", logfile
);
271 fprintf(stderr
, " messages will be sent to 'stderr'.\n");
277 setmode(fileno(debug_log
), O_TEXT
);
285 static struct syslog_facility_name
{
290 syslog_facility_names
[] = {
299 "authpriv", LOG_AUTHPRIV
400 _db_set_syslog(const char *facility
) {
401 opt_syslog_enable
= 1;
405 syslog_facility
= LOG_DAEMON
;
408 syslog_facility
= LOG_LOCAL4
;
413 struct syslog_facility_name
*n
;
415 for (n
= syslog_facility_names
; n
->name
; n
++) {
416 if (strcmp(n
->name
, facility
) == 0) {
417 syslog_facility
= n
->facility
;
422 fprintf(stderr
, "unknown syslog facility '%s'\n", facility
);
428 fprintf(stderr
, "syslog facility type not supported on your system\n");
436 Debug::parseOptions(char const *options
) {
441 if(Config
.onoff
.debug_override_X
) {
442 debugs(0, 9, "command-line -X overrides: " << options
);
446 for (i
= 0; i
< MAX_DEBUG_SECTIONS
; i
++)
447 Debug::Levels
[i
] = 0;
450 p
= xstrdup(options
);
452 for (s
= strtok(p
, w_space
); s
; s
= strtok(NULL
, w_space
))
460 _db_init(const char *logfile
, const char *options
) {
461 Debug::parseOptions(options
);
463 debugOpenLog(logfile
);
465 #if HAVE_SYSLOG && defined(LOG_LOCAL4)
467 if (opt_syslog_enable
)
468 openlog(APP_SHORTNAME
, LOG_PID
| LOG_NDELAY
| LOG_CONS
, syslog_facility
);
470 #endif /* HAVE_SYSLOG */
475 _db_rotate_log(void) {
477 LOCAL_ARRAY(char, from
, MAXPATHLEN
);
478 LOCAL_ARRAY(char, to
, MAXPATHLEN
);
484 if (debug_log_file
== NULL
)
489 if (stat(debug_log_file
, &sb
) == 0)
490 if (S_ISREG(sb
.st_mode
) == 0)
496 * NOTE: we cannot use xrename here without having it in a
497 * separate file -- tools.c has too many dependencies to be
498 * used everywhere debug.c is used.
500 /* Rotate numbers 0 through N up one */
501 for (i
= Config
.Log
.rotateNumber
; i
> 1;) {
503 snprintf(from
, MAXPATHLEN
, "%s.%d", debug_log_file
, i
- 1);
504 snprintf(to
, MAXPATHLEN
, "%s.%d", debug_log_file
, i
);
516 * You can't rename open files on Microsoft "operating systems"
517 * so we close before renaming.
520 if (debug_log
!= stderr
)
524 /* Rotate the current log to .0 */
525 if (Config
.Log
.rotateNumber
> 0) {
526 snprintf(to
, MAXPATHLEN
, "%s.%d", debug_log_file
, 0);
534 rename(debug_log_file
, to
);
537 /* Close and reopen the log. It may have been renamed "manually"
538 * before HUP'ing us. */
539 if (debug_log
!= stderr
)
540 debugOpenLog(Config
.Log
.log
);
546 time_t t
= getCurrentTime();
549 static char buf
[128];
550 static time_t last_t
= 0;
552 if (Debug::level
> 1) {
555 strftime(buf2
, 127, "%Y/%m/%d %H:%M:%S", tm
);
557 snprintf(buf
, 127, "%s.%03d", buf2
, (int) current_time
.tv_usec
/ 1000);
559 } else if (t
!= last_t
) {
561 strftime(buf
, 127, "%Y/%m/%d %H:%M:%S", tm
);
570 xassert(const char *msg
, const char *file
, int line
) {
571 debugs(0, 0, "assertion failed: " << file
<< ":" << line
<< ": \"" << msg
<< "\"");
578 * Context-based Debugging
583 * When you have a long nested processing sequence, it is often impossible
584 * for low level routines to know in what larger context they operate. If a
585 * routine coredumps, one can restore the context using debugger trace.
586 * However, in many case you do not want to coredump, but just want to report
587 * a potential problem. A report maybe useless out of problem context.
589 * To solve this potential problem, use the following approach:
592 * top_level_foo(const char *url)
594 * // define current context
595 * // note: we stack but do not dup ctx descriptions!
596 * Ctx ctx = ctx_enter(url);
598 * // go down; middle_level_bar will eventually call bottom_level_boo
599 * middle_level_bar(method, protocol);
601 * // exit, clean after yourself
606 * bottom_level_boo(int status, void *data)
608 * // detect exceptional condition, and simply report it, the context
609 * // information will be available somewhere close in the log file
610 * if (status == STRANGE_STATUS)
611 * debugs(13, 6, "DOS attack detected, data: " << data);
615 * Current implementation is extremely simple but still very handy. It has a
616 * negligible overhead (descriptions are not duplicated).
618 * When the _first_ debug message for a given context is printed, it is
619 * prepended with the current context description. Context is printed with
620 * the same debugging level as the original message.
622 * Note that we do not print context every type you do ctx_enter(). This
623 * approach would produce too many useless messages. For the same reason, a
624 * context description is printed at most _once_ even if you have 10
625 * debugging messages within one context.
627 * Contexts can be nested, of course. You must use ctx_enter() to enter a
628 * context (push it onto stack). It is probably safe to exit several nested
629 * contexts at _once_ by calling ctx_exit() at the top level (this will pop
630 * all context till current one). However, as in any stack, you cannot start
634 * i) locate debugging message,
635 * ii) locate current context by going _upstream_ in your log file,
642 * decide if we want to dup() descriptions (adds overhead) but allows to
643 * add printf()-style interface
648 * descriptions for contexts over CTX_MAX_LEVEL limit are ignored, you probably
649 * have a bug if your nesting goes that deep.
652 #define CTX_MAX_LEVEL 255
655 * produce a warning when nesting reaches this level and then double
658 static int Ctx_Warn_Level
= 32;
659 /* all descriptions has been printed up to this level */
660 static int Ctx_Reported_Level
= -1;
661 /* descriptions are still valid or active up to this level */
662 static int Ctx_Valid_Level
= -1;
663 /* current level, the number of nested ctx_enter() calls */
664 static int Ctx_Current_Level
= -1;
665 /* saved descriptions (stack) */
666 static const char *Ctx_Descrs
[CTX_MAX_LEVEL
+ 1];
667 /* "safe" get secription */
668 static const char *ctx_get_descr(Ctx ctx
);
672 ctx_enter(const char *descr
) {
675 if (Ctx_Current_Level
<= CTX_MAX_LEVEL
)
676 Ctx_Descrs
[Ctx_Current_Level
] = descr
;
678 if (Ctx_Current_Level
== Ctx_Warn_Level
) {
679 debugs(0, 0, "# ctx: suspiciously deep (" << Ctx_Warn_Level
<< ") nesting:");
683 return Ctx_Current_Level
;
689 Ctx_Current_Level
= (ctx
>= 0) ? ctx
- 1 : -1;
691 if (Ctx_Valid_Level
> Ctx_Current_Level
)
692 Ctx_Valid_Level
= Ctx_Current_Level
;
696 * the idea id to print each context description at most once but provide enough
697 * info for deducing the current execution stack
701 /* lock so _db_print will not call us recursively */
703 /* ok, user saw [0,Ctx_Reported_Level] descriptions */
704 /* first inform about entries popped since user saw them */
706 if (Ctx_Valid_Level
< Ctx_Reported_Level
) {
707 if (Ctx_Reported_Level
!= Ctx_Valid_Level
+ 1)
708 _db_print("ctx: exit levels from %2d down to %2d\n",
709 Ctx_Reported_Level
, Ctx_Valid_Level
+ 1);
711 _db_print("ctx: exit level %2d\n", Ctx_Reported_Level
);
713 Ctx_Reported_Level
= Ctx_Valid_Level
;
716 /* report new contexts that were pushed since last report */
717 while (Ctx_Reported_Level
< Ctx_Current_Level
) {
718 Ctx_Reported_Level
++;
720 _db_print("ctx: enter level %2d: '%s'\n", Ctx_Reported_Level
,
721 ctx_get_descr(Ctx_Reported_Level
));
728 /* checks for nulls and overflows */
730 ctx_get_descr(Ctx ctx
) {
731 if (ctx
< 0 || ctx
> CTX_MAX_LEVEL
)
734 return Ctx_Descrs
[ctx
] ? Ctx_Descrs
[ctx
] : "<null>";
737 int Debug::TheDepth
= 0;
740 Debug::getDebugOut() {
741 assert(TheDepth
>= 0);
744 assert(CurrentDebug
);
745 *CurrentDebug
<< std::endl
<< "reentrant debuging " << TheDepth
<< "-{";
747 assert(!CurrentDebug
);
748 CurrentDebug
= new std::ostringstream();
749 // set default formatting flags
750 CurrentDebug
->setf(std::ios::fixed
);
751 CurrentDebug
->precision(2);
753 return *CurrentDebug
;
757 Debug::finishDebug() {
758 assert(TheDepth
>= 0);
759 assert(CurrentDebug
);
761 *CurrentDebug
<< "}-" << TheDepth
<< std::endl
;
763 assert(TheDepth
== 1);
764 _db_print("%s\n", CurrentDebug
->str().c_str());
771 // Hack: replaces global ::xassert() to debug debugging assertions
772 // Relies on assert macro calling xassert() without a specific scope.
774 Debug::xassert(const char *msg
, const char *file
, int line
) {
777 *CurrentDebug
<< "assertion failed: " << file
<< ":" << line
<<
778 ": \"" << msg
<< "\"";
783 std::ostringstream (*Debug::CurrentDebug
)(NULL
);