source: squid-ssl/trunk/fuentes/src/icmp/debug.cc @ 5495

Last change on this file since 5495 was 5495, checked in by Juanma, 22 months ago

Initial release

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