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