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