]>
Commit | Line | Data |
---|---|---|
38d04788 | 1 | |
30a4f2a8 | 2 | /* |
e24070c5 | 3 | * $Id: debug.cc,v 1.85 2002/09/01 15:16:35 hno Exp $ |
30a4f2a8 | 4 | * |
5 | * DEBUG: section 0 Debug Routines | |
6 | * AUTHOR: Harvest Derived | |
7 | * | |
2b6662ba | 8 | * SQUID Web Proxy Cache http://www.squid-cache.org/ |
e25c139f | 9 | * ---------------------------------------------------------- |
30a4f2a8 | 10 | * |
2b6662ba | 11 | * Squid is the result of efforts by numerous individuals from |
12 | * the Internet community; see the CONTRIBUTORS file for full | |
13 | * details. Many organizations have provided support for Squid's | |
14 | * development; see the SPONSORS file for full details. Squid is | |
15 | * Copyrighted (C) 2001 by the Regents of the University of | |
16 | * California; see the COPYRIGHT file for full details. Squid | |
17 | * incorporates software developed and/or copyrighted by other | |
18 | * sources; see the CREDITS file for full details. | |
30a4f2a8 | 19 | * |
20 | * This program is free software; you can redistribute it and/or modify | |
21 | * it under the terms of the GNU General Public License as published by | |
22 | * the Free Software Foundation; either version 2 of the License, or | |
23 | * (at your option) any later version. | |
24 | * | |
25 | * This program is distributed in the hope that it will be useful, | |
26 | * but WITHOUT ANY WARRANTY; without even the implied warranty of | |
27 | * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the | |
28 | * GNU General Public License for more details. | |
29 | * | |
30 | * You should have received a copy of the GNU General Public License | |
31 | * along with this program; if not, write to the Free Software | |
cbdec147 | 32 | * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111, USA. |
e25c139f | 33 | * |
30a4f2a8 | 34 | */ |
ed43818f | 35 | |
44a47c6e | 36 | #include "squid.h" |
090089c4 | 37 | |
090089c4 | 38 | static char *debug_log_file = NULL; |
123abbe1 | 39 | static int Ctx_Lock = 0; |
4873d3a4 | 40 | static const char *debugLogTime(time_t); |
2d72d4fd | 41 | static void ctx_print(void); |
811ef305 | 42 | #if HAVE_SYSLOG |
43 | static void _db_print_syslog(const char *format, va_list args); | |
44 | #endif | |
45 | static void _db_print_stderr(const char *format, va_list args); | |
46 | static void _db_print_file(const char *format, va_list args); | |
24382924 | 47 | |
b8d8561b | 48 | void |
811ef305 | 49 | #if STDC_HEADERS |
a3d5953d | 50 | _db_print(const char *format,...) |
090089c4 | 51 | { |
090089c4 | 52 | #else |
b8d8561b | 53 | _db_print(va_alist) |
090089c4 | 54 | va_dcl |
55 | { | |
0ee4272b | 56 | const char *format = NULL; |
97f61b08 | 57 | #endif |
95d659f0 | 58 | LOCAL_ARRAY(char, f, BUFSIZ); |
cd11dce6 | 59 | va_list args1; |
6de2df60 | 60 | #if STDC_HEADERS |
cd11dce6 | 61 | va_list args2; |
62 | va_list args3; | |
380de6f3 | 63 | #else |
64 | #define args2 args1 | |
65 | #define args3 args1 | |
66 | #endif | |
67 | /* give a chance to context-based debugging to print current context */ | |
68 | if (!Ctx_Lock) | |
69 | ctx_print(); | |
70 | #if STDC_HEADERS | |
cd11dce6 | 71 | va_start(args1, format); |
72 | va_start(args2, format); | |
73 | va_start(args3, format); | |
090089c4 | 74 | #else |
cd11dce6 | 75 | format = va_arg(args1, const char *); |
74946a0f | 76 | #endif |
811ef305 | 77 | snprintf(f, BUFSIZ, "%s| %s", |
78 | debugLogTime(squid_curtime), | |
79 | format); | |
cd11dce6 | 80 | _db_print_file(f, args1); |
81 | _db_print_stderr(f, args2); | |
811ef305 | 82 | #if HAVE_SYSLOG |
cd11dce6 | 83 | _db_print_syslog(format, args3); |
84 | #endif | |
85 | va_end(args1); | |
86 | #if STDC_HEADERS | |
87 | va_end(args2); | |
88 | va_end(args3); | |
811ef305 | 89 | #endif |
811ef305 | 90 | } |
74946a0f | 91 | |
811ef305 | 92 | static void |
93 | _db_print_file(const char *format, va_list args) | |
94 | { | |
74946a0f | 95 | if (debug_log == NULL) |
96 | return; | |
123abbe1 | 97 | /* give a chance to context-based debugging to print current context */ |
98 | if (!Ctx_Lock) | |
99 | ctx_print(); | |
811ef305 | 100 | vfprintf(debug_log, format, args); |
17a0a4ee | 101 | if (!Config.onoff.buffered_logs) |
12b9e9b1 | 102 | fflush(debug_log); |
090089c4 | 103 | } |
104 | ||
811ef305 | 105 | static void |
106 | _db_print_stderr(const char *format, va_list args) | |
107 | { | |
108 | if (opt_debug_stderr < _db_level) | |
109 | return; | |
110 | if (debug_log == stderr) | |
111 | return; | |
112 | vfprintf(stderr, format, args); | |
113 | } | |
114 | ||
115 | #if HAVE_SYSLOG | |
116 | static void | |
117 | _db_print_syslog(const char *format, va_list args) | |
118 | { | |
119 | LOCAL_ARRAY(char, tmpbuf, BUFSIZ); | |
120 | /* level 0,1 go to syslog */ | |
121 | if (_db_level > 1) | |
122 | return; | |
123 | if (0 == opt_syslog_enable) | |
124 | return; | |
125 | tmpbuf[0] = '\0'; | |
126 | vsnprintf(tmpbuf, BUFSIZ, format, args); | |
127 | tmpbuf[BUFSIZ - 1] = '\0'; | |
128 | syslog(_db_level == 0 ? LOG_WARNING : LOG_NOTICE, "%s", tmpbuf); | |
129 | } | |
130 | #endif /* HAVE_SYSLOG */ | |
131 | ||
b8d8561b | 132 | static void |
0ee4272b | 133 | debugArg(const char *arg) |
12b9e9b1 | 134 | { |
c9f06944 | 135 | int s = 0; |
136 | int l = 0; | |
137 | int i; | |
c9f06944 | 138 | if (!strncasecmp(arg, "ALL", 3)) { |
139 | s = -1; | |
140 | arg += 4; | |
141 | } else { | |
142 | s = atoi(arg); | |
143 | while (*arg && *arg++ != ','); | |
144 | } | |
145 | l = atoi(arg); | |
b6a2f15e | 146 | assert(s >= -1); |
147 | assert(s < MAX_DEBUG_SECTIONS); | |
148 | if (l < 0) | |
149 | l = 0; | |
150 | if (l > 10) | |
151 | l = 10; | |
c9f06944 | 152 | if (s >= 0) { |
153 | debugLevels[s] = l; | |
154 | return; | |
155 | } | |
156 | for (i = 0; i < MAX_DEBUG_SECTIONS; i++) | |
157 | debugLevels[i] = l; | |
12b9e9b1 | 158 | } |
159 | ||
b8d8561b | 160 | static void |
0ee4272b | 161 | debugOpenLog(const char *logfile) |
ccff9601 | 162 | { |
163 | if (logfile == NULL) { | |
164 | debug_log = stderr; | |
165 | return; | |
166 | } | |
167 | if (debug_log_file) | |
5c46528b | 168 | xfree(debug_log_file); |
ccff9601 | 169 | debug_log_file = xstrdup(logfile); /* keep a static copy */ |
f2cc1af5 | 170 | if (debug_log && debug_log != stderr) |
a0bbd6c8 | 171 | fclose(debug_log); |
ccff9601 | 172 | debug_log = fopen(logfile, "a+"); |
173 | if (!debug_log) { | |
174 | fprintf(stderr, "WARNING: Cannot write log file: %s\n", logfile); | |
175 | perror(logfile); | |
176 | fprintf(stderr, " messages will be sent to 'stderr'.\n"); | |
177 | fflush(stderr); | |
178 | debug_log = stderr; | |
179 | } | |
e24070c5 | 180 | #if defined(_SQUID_CYGWIN_)||defined(_SQUID_MSWIN_) |
c4aefe96 | 181 | setmode(fileno(debug_log), O_TEXT); |
182 | #endif | |
ccff9601 | 183 | } |
184 | ||
b8d8561b | 185 | void |
0ee4272b | 186 | _db_init(const char *logfile, const char *options) |
090089c4 | 187 | { |
12b9e9b1 | 188 | int i; |
189 | char *p = NULL; | |
190 | char *s = NULL; | |
090089c4 | 191 | |
12b9e9b1 | 192 | for (i = 0; i < MAX_DEBUG_SECTIONS; i++) |
193 | debugLevels[i] = -1; | |
090089c4 | 194 | |
30a4f2a8 | 195 | if (options) { |
196 | p = xstrdup(options); | |
197 | for (s = strtok(p, w_space); s; s = strtok(NULL, w_space)) | |
12b9e9b1 | 198 | debugArg(s); |
12b9e9b1 | 199 | xfree(p); |
200 | } | |
ccff9601 | 201 | debugOpenLog(logfile); |
090089c4 | 202 | |
30a4f2a8 | 203 | #if HAVE_SYSLOG && defined(LOG_LOCAL4) |
6e40f263 | 204 | if (opt_syslog_enable) |
b8de7ebe | 205 | openlog(appname, LOG_PID | LOG_NDELAY | LOG_CONS, LOG_LOCAL4); |
db40ae20 | 206 | #endif /* HAVE_SYSLOG */ |
207 | ||
090089c4 | 208 | } |
209 | ||
b8d8561b | 210 | void |
0673c0ba | 211 | _db_rotate_log(void) |
090089c4 | 212 | { |
213 | int i; | |
95d659f0 | 214 | LOCAL_ARRAY(char, from, MAXPATHLEN); |
215 | LOCAL_ARRAY(char, to, MAXPATHLEN); | |
88738790 | 216 | #ifdef S_ISREG |
2edc2504 | 217 | struct stat sb; |
88738790 | 218 | #endif |
090089c4 | 219 | |
220 | if (debug_log_file == NULL) | |
221 | return; | |
71d95578 | 222 | #ifdef S_ISREG |
2edc2504 | 223 | if (stat(debug_log_file, &sb) == 0) |
224 | if (S_ISREG(sb.st_mode) == 0) | |
225 | return; | |
71d95578 | 226 | #endif |
090089c4 | 227 | |
1f38f50a | 228 | /* |
229 | * NOTE: we cannot use xrename here without having it in a | |
230 | * separate file -- tools.c has too many dependencies to be | |
231 | * used everywhere debug.c is used. | |
232 | */ | |
090089c4 | 233 | /* Rotate numbers 0 through N up one */ |
b6f794d6 | 234 | for (i = Config.Log.rotateNumber; i > 1;) { |
090089c4 | 235 | i--; |
042461c3 | 236 | snprintf(from, MAXPATHLEN, "%s.%d", debug_log_file, i - 1); |
237 | snprintf(to, MAXPATHLEN, "%s.%d", debug_log_file, i); | |
090089c4 | 238 | rename(from, to); |
239 | } | |
e24070c5 | 240 | /* |
241 | * You can't rename open files on Microsoft "operating systems" | |
242 | * so we close before renaming. | |
243 | */ | |
244 | #ifdef _SQUID_MSWIN_ | |
245 | if (debug_log != stderr) | |
246 | fclose(debug_log); | |
247 | #endif | |
090089c4 | 248 | /* Rotate the current log to .0 */ |
b6f794d6 | 249 | if (Config.Log.rotateNumber > 0) { |
042461c3 | 250 | snprintf(to, MAXPATHLEN, "%s.%d", debug_log_file, 0); |
090089c4 | 251 | rename(debug_log_file, to); |
252 | } | |
253 | /* Close and reopen the log. It may have been renamed "manually" | |
254 | * before HUP'ing us. */ | |
0a8020d1 | 255 | if (debug_log != stderr) |
b6f794d6 | 256 | debugOpenLog(Config.Log.log); |
090089c4 | 257 | } |
4873d3a4 | 258 | |
259 | static const char * | |
260 | debugLogTime(time_t t) | |
261 | { | |
262 | struct tm *tm; | |
263 | static char buf[128]; | |
264 | static time_t last_t = 0; | |
265 | if (t != last_t) { | |
2ac76861 | 266 | tm = localtime(&t); |
267 | strftime(buf, 127, "%Y/%m/%d %H:%M:%S", tm); | |
268 | last_t = t; | |
4873d3a4 | 269 | } |
270 | return buf; | |
271 | } | |
272 | ||
bb71ea1f | 273 | void |
274 | xassert(const char *msg, const char *file, int line) | |
8a6218c6 | 275 | { |
bb71ea1f | 276 | debug(0, 0) ("assertion failed: %s:%d: \"%s\"\n", file, line, msg); |
277 | if (!shutting_down) | |
8a6218c6 | 278 | abort(); |
bb71ea1f | 279 | } |
280 | ||
123abbe1 | 281 | /* |
282 | * Context-based Debugging | |
26970499 | 283 | * |
284 | * Rationale | |
285 | * --------- | |
286 | * | |
287 | * When you have a long nested processing sequence, it is often impossible | |
288 | * for low level routines to know in what larger context they operate. If a | |
289 | * routine coredumps, one can restore the context using debugger trace. | |
290 | * However, in many case you do not want to coredump, but just want to report | |
291 | * a potential problem. A report maybe useless out of problem context. | |
292 | * | |
293 | * To solve this potential problem, use the following approach: | |
294 | * | |
295 | * int | |
296 | * top_level_foo(const char *url) | |
297 | * { | |
298 | * // define current context | |
299 | * // note: we stack but do not dup ctx descriptions! | |
300 | * Ctx ctx = ctx_enter(url); | |
301 | * ... | |
302 | * // go down; middle_level_bar will eventually call bottom_level_boo | |
303 | * middle_level_bar(method, protocol); | |
304 | * ... | |
305 | * // exit, clean after yourself | |
306 | * ctx_exit(ctx); | |
307 | * } | |
308 | * | |
309 | * void | |
310 | * bottom_level_boo(int status, void *data) | |
311 | * { | |
312 | * // detect exceptional condition, and simply report it, the context | |
313 | * // information will be available somewhere close in the log file | |
314 | * if (status == STRANGE_STATUS) | |
315 | * debug(13, 6) ("DOS attack detected, data: %p\n", data); | |
316 | * ... | |
317 | * } | |
318 | * | |
319 | * Current implementation is extremely simple but still very handy. It has a | |
320 | * negligible overhead (descriptions are not duplicated). | |
321 | * | |
322 | * When the _first_ debug message for a given context is printed, it is | |
323 | * prepended with the current context description. Context is printed with | |
324 | * the same debugging level as the original message. | |
325 | * | |
326 | * Note that we do not print context every type you do ctx_enter(). This | |
327 | * approach would produce too many useless messages. For the same reason, a | |
328 | * context description is printed at most _once_ even if you have 10 | |
329 | * debugging messages within one context. | |
330 | * | |
331 | * Contexts can be nested, of course. You must use ctx_enter() to enter a | |
332 | * context (push it onto stack). It is probably safe to exit several nested | |
333 | * contexts at _once_ by calling ctx_exit() at the top level (this will pop | |
334 | * all context till current one). However, as in any stack, you cannot start | |
335 | * in the middle. | |
336 | * | |
337 | * Analysis: | |
338 | * i) locate debugging message, | |
339 | * ii) locate current context by going _upstream_ in your log file, | |
340 | * iii) hack away. | |
341 | * | |
342 | * | |
123abbe1 | 343 | * To-Do: |
26970499 | 344 | * ----- |
345 | * | |
123abbe1 | 346 | * decide if we want to dup() descriptions (adds overhead) but allows to |
347 | * add printf()-style interface | |
26970499 | 348 | * |
2ac76861 | 349 | * implementation: |
26970499 | 350 | * --------------- |
2ac76861 | 351 | * |
123abbe1 | 352 | * descriptions for contexts over CTX_MAX_LEVEL limit are ignored, you probably |
353 | * have a bug if your nesting goes that deep. | |
354 | */ | |
2ac76861 | 355 | |
123abbe1 | 356 | #define CTX_MAX_LEVEL 255 |
2ac76861 | 357 | |
358 | /* | |
359 | * produce a warning when nesting reaches this level and then double | |
360 | * the level | |
361 | */ | |
362 | static int Ctx_Warn_Level = 32; | |
123abbe1 | 363 | /* all descriptions has been printed up to this level */ |
a3f9588e | 364 | static int Ctx_Reported_Level = -1; |
123abbe1 | 365 | /* descriptions are still valid or active up to this level */ |
a3f9588e | 366 | static int Ctx_Valid_Level = -1; |
123abbe1 | 367 | /* current level, the number of nested ctx_enter() calls */ |
a3f9588e | 368 | static int Ctx_Current_Level = -1; |
123abbe1 | 369 | /* saved descriptions (stack) */ |
2ac76861 | 370 | static const char *Ctx_Descrs[CTX_MAX_LEVEL + 1]; |
b70d1c58 | 371 | /* "safe" get secription */ |
372 | static const char *ctx_get_descr(Ctx ctx); | |
123abbe1 | 373 | |
374 | ||
375 | Ctx | |
376 | ctx_enter(const char *descr) | |
377 | { | |
378 | Ctx_Current_Level++; | |
379 | ||
380 | if (Ctx_Current_Level <= CTX_MAX_LEVEL) | |
381 | Ctx_Descrs[Ctx_Current_Level] = descr; | |
382 | ||
383 | if (Ctx_Current_Level == Ctx_Warn_Level) { | |
2ac76861 | 384 | debug(0, 0) ("# ctx: suspiciously deep (%d) nesting:\n", Ctx_Warn_Level); |
123abbe1 | 385 | Ctx_Warn_Level *= 2; |
386 | } | |
123abbe1 | 387 | return Ctx_Current_Level; |
388 | } | |
389 | ||
390 | void | |
391 | ctx_exit(Ctx ctx) | |
392 | { | |
393 | assert(ctx >= 0); | |
2ac76861 | 394 | Ctx_Current_Level = (ctx >= 0) ? ctx - 1 : -1; |
123abbe1 | 395 | if (Ctx_Valid_Level > Ctx_Current_Level) |
396 | Ctx_Valid_Level = Ctx_Current_Level; | |
397 | } | |
398 | ||
399 | /* | |
400 | * the idea id to print each context description at most once but provide enough | |
401 | * info for deducing the current execution stack | |
402 | */ | |
403 | static void | |
9bc73deb | 404 | ctx_print(void) |
123abbe1 | 405 | { |
406 | /* lock so _db_print will not call us recursively */ | |
407 | Ctx_Lock++; | |
408 | /* ok, user saw [0,Ctx_Reported_Level] descriptions */ | |
409 | /* first inform about entries popped since user saw them */ | |
410 | if (Ctx_Valid_Level < Ctx_Reported_Level) { | |
2ac76861 | 411 | if (Ctx_Reported_Level != Ctx_Valid_Level + 1) |
412 | _db_print("ctx: exit levels from %2d down to %2d\n", | |
413 | Ctx_Reported_Level, Ctx_Valid_Level + 1); | |
4a0d3a91 | 414 | else |
415 | _db_print("ctx: exit level %2d\n", Ctx_Reported_Level); | |
123abbe1 | 416 | Ctx_Reported_Level = Ctx_Valid_Level; |
417 | } | |
418 | /* report new contexts that were pushed since last report */ | |
419 | while (Ctx_Reported_Level < Ctx_Current_Level) { | |
420 | Ctx_Reported_Level++; | |
421 | Ctx_Valid_Level++; | |
2ac76861 | 422 | _db_print("ctx: enter level %2d: '%s'\n", Ctx_Reported_Level, |
b70d1c58 | 423 | ctx_get_descr(Ctx_Reported_Level)); |
123abbe1 | 424 | } |
425 | /* unlock */ | |
426 | Ctx_Lock--; | |
427 | } | |
b70d1c58 | 428 | |
429 | /* checks for nulls and overflows */ | |
430 | static const char * | |
431 | ctx_get_descr(Ctx ctx) | |
432 | { | |
2ac76861 | 433 | if (ctx < 0 || ctx > CTX_MAX_LEVEL) |
434 | return "<lost>"; | |
b70d1c58 | 435 | return Ctx_Descrs[ctx] ? Ctx_Descrs[ctx] : "<null>"; |
436 | } |