Line data Source code
1 : /*
2 : Unix SMB/CIFS implementation.
3 : Samba utility functions
4 : Copyright (C) Andrew Tridgell 1992-1998
5 : Copyright (C) Elrond 2002
6 : Copyright (C) Simo Sorce 2002
7 :
8 : This program is free software; you can redistribute it and/or modify
9 : it under the terms of the GNU General Public License as published by
10 : the Free Software Foundation; either version 3 of the License, or
11 : (at your option) any later version.
12 :
13 : This program is distributed in the hope that it will be useful,
14 : but WITHOUT ANY WARRANTY; without even the implied warranty of
15 : MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
16 : GNU General Public License for more details.
17 :
18 : You should have received a copy of the GNU General Public License
19 : along with this program. If not, see <http://www.gnu.org/licenses/>.
20 : */
21 :
22 : #include "replace.h"
23 : #include <talloc.h>
24 : #include "system/filesys.h"
25 : #include "system/syslog.h"
26 : #include "system/locale.h"
27 : #include "system/network.h"
28 : #include "system/time.h"
29 : #include "time_basic.h"
30 : #include "close_low_fd.h"
31 : #include "memory.h"
32 : #include "util_strlist.h" /* LIST_SEP */
33 : #include "blocking.h"
34 : #include "debug.h"
35 : #include <assert.h>
36 :
37 : /* define what facility to use for syslog */
38 : #ifndef SYSLOG_FACILITY
39 : #define SYSLOG_FACILITY LOG_DAEMON
40 : #endif
41 :
42 : /* -------------------------------------------------------------------------- **
43 : * Defines...
44 : */
45 :
46 : /*
47 : * format_bufr[FORMAT_BUFR_SIZE - 1] should always be reserved
48 : * for a terminating null byte.
49 : */
50 : #define FORMAT_BUFR_SIZE 4096
51 :
52 : /* -------------------------------------------------------------------------- **
53 : * This module implements Samba's debugging utility.
54 : *
55 : * The syntax of a debugging log file is represented as:
56 : *
57 : * <debugfile> :== { <debugmsg> }
58 : *
59 : * <debugmsg> :== <debughdr> '\n' <debugtext>
60 : *
61 : * <debughdr> :== '[' TIME ',' LEVEL ']' [ [FILENAME ':'] [FUNCTION '()'] ]
62 : *
63 : * <debugtext> :== { <debugline> }
64 : *
65 : * <debugline> :== TEXT '\n'
66 : *
67 : * TEXT is a string of characters excluding the newline character.
68 : * LEVEL is the DEBUG level of the message (an integer in the range 0..10).
69 : * TIME is a timestamp.
70 : * FILENAME is the name of the file from which the debug message was generated.
71 : * FUNCTION is the function from which the debug message was generated.
72 : *
73 : * Basically, what that all means is:
74 : *
75 : * - A debugging log file is made up of debug messages.
76 : *
77 : * - Each debug message is made up of a header and text. The header is
78 : * separated from the text by a newline.
79 : *
80 : * - The header begins with the timestamp and debug level of the message
81 : * enclosed in brackets. The filename and function from which the
82 : * message was generated may follow. The filename is terminated by a
83 : * colon, and the function name is terminated by parenthesis.
84 : *
85 : * - The message text is made up of zero or more lines, each terminated by
86 : * a newline.
87 : */
88 :
89 : /* state variables for the debug system */
90 : static struct {
91 : bool initialized;
92 : enum debug_logtype logtype; /* The type of logging we are doing: eg stdout, file, stderr */
93 : char prog_name[255];
94 : char hostname[HOST_NAME_MAX+1];
95 : bool reopening_logs;
96 : bool schedule_reopen_logs;
97 : int forced_log_priority;
98 :
99 : struct debug_settings settings;
100 : debug_callback_fn callback;
101 : void *callback_private;
102 : char header_str[300];
103 : size_t hs_len;
104 : } state = {
105 : .settings = {
106 : .timestamp_logs = true
107 : },
108 : };
109 :
110 : struct debug_class {
111 : /*
112 : * The debug loglevel of the class.
113 : */
114 : int loglevel;
115 :
116 : /*
117 : * An optional class specific logfile, may be NULL in which case the
118 : * "global" logfile is used and fd is -1.
119 : */
120 : char *logfile;
121 : int fd;
122 : /* inode number of the logfile to detect logfile rotation */
123 : ino_t ino;
124 : };
125 :
126 : /*
127 : * default_classname_table[] is read in from debug-classname-table.c
128 : * so that test_logging.c can use it too.
129 : */
130 : #include "lib/util/debug-classes/debug-classname-table.c"
131 :
132 : /*
133 : * This is to allow reading of dbgc_config before the debug
134 : * system has been initialized.
135 : */
136 : static struct debug_class debug_class_list_initial[ARRAY_SIZE(default_classname_table)] = {
137 : [DBGC_ALL] = { .fd = 2 },
138 : };
139 :
140 : static size_t debug_num_classes = 0;
141 : static struct debug_class *dbgc_config = debug_class_list_initial;
142 :
143 : static int current_msg_level = 0;
144 : static int current_msg_class = 0;
145 :
146 : /*
147 : * DBG_DEV(): when and how to user it.
148 : *
149 : * As a developer, you sometimes want verbose logging between point A and
150 : * point B, where the relationship between these points is not easily defined
151 : * in terms of the call stack.
152 : *
153 : * For example, you might be interested in what is going on in functions in
154 : * lib/util/util_str.c in an ldap worker process after a particular query. If
155 : * you use gdb, something will time out and you won't get the full
156 : * conversation. If you add fprintf() or DBG_ERR()s to util_str.c, you'll get
157 : * a massive flood, and there's a chance one will accidentally slip into a
158 : * release and the whole world will flood. DBG_DEV is a solution.
159 : *
160 : * On start-up, DBG_DEV() is switched OFF. Nothing is printed.
161 : *
162 : * 1. Add `DBG_DEV("formatted msg %d, etc\n", i);` where needed.
163 : *
164 : * 2. At each point you want to start debugging, add `debug_developer_enable()`.
165 : *
166 : * 3. At each point you want debugging to stop, add `debug_developer_disable()`.
167 : *
168 : * In DEVELOPER builds, the message will be printed at level 0, as with
169 : * DBG_ERR(). In production builds, the macro resolves to nothing.
170 : *
171 : * The messages are printed with a "<function_name>:DEV:<pid>:" prefix.
172 : */
173 :
174 : static bool debug_developer_is_enabled = false;
175 :
176 0 : bool debug_developer_enabled(void)
177 : {
178 0 : return debug_developer_is_enabled;
179 : }
180 :
181 : /*
182 : * debug_developer_disable() will turn DBG_DEV() on in the current
183 : * process and children.
184 : */
185 0 : void debug_developer_enable(void)
186 : {
187 0 : debug_developer_is_enabled = true;
188 0 : }
189 :
190 : /*
191 : * debug_developer_disable() will make DBG_DEV() do nothing in the current
192 : * process (and children).
193 : */
194 0 : void debug_developer_disable(void)
195 : {
196 0 : debug_developer_is_enabled = false;
197 0 : }
198 :
199 : /*
200 : * Within debug.c, DBG_DEV() always writes to stderr, because some functions
201 : * here will attempt infinite recursion with normal DEBUG macros.
202 : */
203 : #ifdef DEVELOPER
204 : #undef DBG_DEV
205 : #define DBG_DEV(fmt, ...) \
206 : (void)((debug_developer_enabled()) \
207 : && (fprintf(stderr, "%s:DEV:%d: " fmt "%s", \
208 : __func__, getpid(), ##__VA_ARGS__, "")) )
209 : #endif
210 :
211 :
212 : #if defined(WITH_SYSLOG) || defined(HAVE_LIBSYSTEMD_JOURNAL) || defined(HAVE_LIBSYSTEMD)
213 84 : static int debug_level_to_priority(int level)
214 : {
215 : /*
216 : * map debug levels to syslog() priorities
217 : */
218 76 : static const int priority_map[] = {
219 : LOG_ERR, /* 0 */
220 : LOG_WARNING, /* 1 */
221 : LOG_NOTICE, /* 2 */
222 : LOG_NOTICE, /* 3 */
223 : LOG_NOTICE, /* 4 */
224 : LOG_NOTICE, /* 5 */
225 : LOG_INFO, /* 6 */
226 : LOG_INFO, /* 7 */
227 : LOG_INFO, /* 8 */
228 : LOG_INFO, /* 9 */
229 : };
230 76 : int priority;
231 :
232 84 : if (state.forced_log_priority != -1) {
233 84 : level = state.forced_log_priority;
234 : }
235 :
236 84 : if (level < 0 || (size_t)level >= ARRAY_SIZE(priority_map))
237 0 : priority = LOG_DEBUG;
238 : else
239 84 : priority = priority_map[level];
240 :
241 84 : return priority;
242 : }
243 : #endif
244 :
245 : /* -------------------------------------------------------------------------- **
246 : * Debug backends. When logging to DEBUG_FILE, send the log entries to
247 : * all active backends.
248 : */
249 :
250 25748 : static void debug_file_log(int msg_level, const char *msg, size_t msg_len)
251 : {
252 25748 : struct iovec iov[] = {
253 : {
254 : .iov_base = discard_const(state.header_str),
255 25748 : .iov_len = state.hs_len,
256 : },
257 : {
258 : .iov_base = discard_const(msg),
259 : .iov_len = msg_len,
260 : },
261 : };
262 1292 : ssize_t ret;
263 1292 : int fd;
264 :
265 25748 : check_log_size();
266 :
267 25748 : if (dbgc_config[current_msg_class].fd != -1) {
268 14146 : fd = dbgc_config[current_msg_class].fd;
269 : } else {
270 11838 : fd = dbgc_config[DBGC_ALL].fd;
271 : }
272 :
273 1292 : do {
274 25748 : ret = writev(fd, iov, ARRAY_SIZE(iov));
275 25748 : } while (ret == -1 && errno == EINTR);
276 25748 : }
277 :
278 : #ifdef WITH_SYSLOG
279 186809 : static void debug_syslog_reload(bool enabled, bool previously_enabled,
280 : const char *prog_name, char *option)
281 : {
282 186809 : if (enabled && !previously_enabled) {
283 9273 : const char *ident = NULL;
284 9273 : if ((prog_name != NULL) && (prog_name[0] != '\0')) {
285 4397 : ident = prog_name;
286 : }
287 : #ifdef LOG_DAEMON
288 9273 : openlog(ident, LOG_PID, SYSLOG_FACILITY);
289 : #else
290 : /* for old systems that have no facility codes. */
291 : openlog(ident, LOG_PID);
292 : #endif
293 9273 : return;
294 : }
295 :
296 177536 : if (!enabled && previously_enabled) {
297 0 : closelog();
298 : }
299 : }
300 :
301 84 : static void debug_syslog_log(int msg_level, const char *msg, size_t msg_len)
302 : {
303 76 : int priority;
304 :
305 84 : priority = debug_level_to_priority(msg_level);
306 :
307 : /*
308 : * Specify the facility to interoperate with other syslog
309 : * callers (vfs_full_audit for example).
310 : */
311 84 : priority |= SYSLOG_FACILITY;
312 :
313 84 : if (state.hs_len > 0) {
314 80 : syslog(priority, "%s", state.header_str);
315 : }
316 84 : syslog(priority, "%s", msg);
317 84 : }
318 : #endif /* WITH_SYSLOG */
319 :
320 : #if defined(HAVE_LIBSYSTEMD_JOURNAL) || defined(HAVE_LIBSYSTEMD)
321 : #include <systemd/sd-journal.h>
322 0 : static void debug_systemd_log(int msg_level, const char *msg, size_t msg_len)
323 : {
324 0 : if (state.hs_len > 0) {
325 0 : size_t len = state.hs_len;
326 :
327 0 : if (state.header_str[len - 1] == '\n') {
328 0 : len -= 1;
329 : }
330 :
331 0 : sd_journal_send("MESSAGE=%.*s",
332 : (int)len,
333 : state.header_str,
334 : "PRIORITY=%d",
335 : debug_level_to_priority(msg_level),
336 : "LEVEL=%d",
337 : msg_level,
338 : NULL);
339 : }
340 :
341 0 : if ((msg_len > 0) && (msg[msg_len - 1] == '\n')) {
342 0 : msg_len -= 1;
343 : }
344 :
345 0 : sd_journal_send("MESSAGE=%.*s",
346 : (int)msg_len,
347 : msg,
348 : "PRIORITY=%d",
349 : debug_level_to_priority(msg_level),
350 : "LEVEL=%d",
351 : msg_level,
352 : NULL);
353 0 : }
354 : #endif
355 :
356 : #ifdef HAVE_LTTNG_TRACEF
357 : #include <lttng/tracef.h>
358 : static void debug_lttng_log(int msg_level, const char *msg, size_t msg_len)
359 : {
360 : if (state.hs_len > 0) {
361 : size_t len = state.hs_len;
362 :
363 : if (state.header_str[len - 1] == '\n') {
364 : len -= 1;
365 : }
366 :
367 : tracef("%.*s", (int)len, state.header_str);
368 : }
369 :
370 : if ((msg_len > 0) && (msg[msg_len - 1] == '\n')) {
371 : msg_len -= 1;
372 : }
373 : tracef("%.*s", (int)msg_len, msg);
374 : }
375 : #endif /* WITH_LTTNG_TRACEF */
376 :
377 : #ifdef HAVE_GPFS
378 : #include "gpfswrap.h"
379 186809 : static void debug_gpfs_reload(bool enabled, bool previously_enabled,
380 : const char *prog_name, char *option)
381 : {
382 186809 : if (enabled) {
383 0 : gpfswrap_init();
384 : }
385 :
386 186809 : if (enabled && !previously_enabled) {
387 0 : gpfswrap_init_trace();
388 0 : return;
389 : }
390 :
391 186809 : if (!enabled && previously_enabled) {
392 0 : gpfswrap_fini_trace();
393 0 : return;
394 : }
395 :
396 186809 : if (enabled) {
397 : /*
398 : * Trigger GPFS library to adjust state if necessary.
399 : */
400 0 : gpfswrap_query_trace();
401 : }
402 : }
403 :
404 0 : static void copy_no_nl(char *out,
405 : size_t out_size,
406 : const char *in,
407 : size_t in_len)
408 : {
409 0 : size_t len;
410 : /*
411 : * Some backends already add an extra newline, so also provide
412 : * a buffer without the newline character.
413 : */
414 0 : len = MIN(in_len, out_size - 1);
415 0 : if ((len > 0) && (in[len - 1] == '\n')) {
416 0 : len--;
417 : }
418 :
419 0 : memcpy(out, in, len);
420 0 : out[len] = '\0';
421 0 : }
422 :
423 0 : static void debug_gpfs_log(int msg_level, const char *msg, size_t msg_len)
424 : {
425 0 : char no_nl[FORMAT_BUFR_SIZE];
426 :
427 0 : if (state.hs_len > 0) {
428 0 : copy_no_nl(no_nl,
429 : sizeof(no_nl),
430 : state.header_str,
431 : state.hs_len);
432 0 : gpfswrap_add_trace(msg_level, no_nl);
433 : }
434 :
435 0 : copy_no_nl(no_nl, sizeof(no_nl), msg, msg_len);
436 0 : gpfswrap_add_trace(msg_level, no_nl);
437 0 : }
438 : #endif /* HAVE_GPFS */
439 :
440 : #define DEBUG_RINGBUF_SIZE (1024 * 1024)
441 : #define DEBUG_RINGBUF_SIZE_OPT "size="
442 :
443 : static char *debug_ringbuf;
444 : static size_t debug_ringbuf_size;
445 : static size_t debug_ringbuf_ofs;
446 :
447 : /* We ensure in debug_ringbuf_log() that this is always \0 terminated */
448 0 : char *debug_get_ringbuf(void)
449 : {
450 0 : return debug_ringbuf;
451 : }
452 :
453 : /* Return the size of the ringbuf (including a \0 terminator) */
454 0 : size_t debug_get_ringbuf_size(void)
455 : {
456 0 : return debug_ringbuf_size;
457 : }
458 :
459 186809 : static void debug_ringbuf_reload(bool enabled, bool previously_enabled,
460 : const char *prog_name, char *option)
461 : {
462 4572 : bool cmp;
463 186809 : size_t optlen = strlen(DEBUG_RINGBUF_SIZE_OPT);
464 :
465 186809 : debug_ringbuf_size = DEBUG_RINGBUF_SIZE;
466 186809 : debug_ringbuf_ofs = 0;
467 :
468 186809 : SAFE_FREE(debug_ringbuf);
469 :
470 186809 : if (!enabled) {
471 182237 : return;
472 : }
473 :
474 0 : if (option != NULL) {
475 0 : cmp = strncmp(option, DEBUG_RINGBUF_SIZE_OPT, optlen);
476 0 : if (cmp == 0) {
477 0 : debug_ringbuf_size = (size_t)strtoull(
478 0 : option + optlen, NULL, 10);
479 : }
480 : }
481 :
482 0 : debug_ringbuf = calloc(debug_ringbuf_size, sizeof(char));
483 0 : if (debug_ringbuf == NULL) {
484 0 : return;
485 : }
486 : }
487 :
488 0 : static void _debug_ringbuf_log(int msg_level, const char *msg, size_t msg_len)
489 : {
490 0 : size_t allowed_size;
491 :
492 0 : if (debug_ringbuf == NULL) {
493 0 : return;
494 : }
495 :
496 : /* Ensure the buffer is always \0 terminated */
497 0 : allowed_size = debug_ringbuf_size - 1;
498 :
499 0 : if (msg_len > allowed_size) {
500 0 : return;
501 : }
502 :
503 0 : if ((debug_ringbuf_ofs + msg_len) < debug_ringbuf_ofs) {
504 0 : return;
505 : }
506 :
507 0 : if ((debug_ringbuf_ofs + msg_len) > allowed_size) {
508 0 : debug_ringbuf_ofs = 0;
509 : }
510 :
511 0 : memcpy(debug_ringbuf + debug_ringbuf_ofs, msg, msg_len);
512 0 : debug_ringbuf_ofs += msg_len;
513 : }
514 :
515 0 : static void debug_ringbuf_log(int msg_level, const char *msg, size_t msg_len)
516 : {
517 0 : if (state.hs_len > 0) {
518 0 : _debug_ringbuf_log(msg_level, state.header_str, state.hs_len);
519 : }
520 0 : _debug_ringbuf_log(msg_level, msg, msg_len);
521 0 : }
522 :
523 : static struct debug_backend {
524 : const char *name;
525 : int log_level;
526 : int new_log_level;
527 : void (*reload)(bool enabled, bool prev_enabled,
528 : const char *prog_name, char *option);
529 : void (*log)(int msg_level,
530 : const char *msg,
531 : size_t len);
532 : char *option;
533 : } debug_backends[] = {
534 : {
535 : .name = "file",
536 : .log = debug_file_log,
537 : },
538 : #ifdef WITH_SYSLOG
539 : {
540 : .name = "syslog",
541 : .reload = debug_syslog_reload,
542 : .log = debug_syslog_log,
543 : },
544 : #endif
545 :
546 : #if defined(HAVE_LIBSYSTEMD_JOURNAL) || defined(HAVE_LIBSYSTEMD)
547 : {
548 : .name = "systemd",
549 : .log = debug_systemd_log,
550 : },
551 : #endif
552 :
553 : #ifdef HAVE_LTTNG_TRACEF
554 : {
555 : .name = "lttng",
556 : .log = debug_lttng_log,
557 : },
558 : #endif
559 :
560 : #ifdef HAVE_GPFS
561 : {
562 : .name = "gpfs",
563 : .reload = debug_gpfs_reload,
564 : .log = debug_gpfs_log,
565 : },
566 : #endif
567 : {
568 : .name = "ringbuf",
569 : .log = debug_ringbuf_log,
570 : .reload = debug_ringbuf_reload,
571 : },
572 : };
573 :
574 307471 : static struct debug_backend *debug_find_backend(const char *name)
575 : {
576 12976 : unsigned i;
577 :
578 337901 : for (i = 0; i < ARRAY_SIZE(debug_backends); i++) {
579 337899 : if (strcmp(name, debug_backends[i].name) == 0) {
580 307469 : return &debug_backends[i];
581 : }
582 : }
583 :
584 2 : return NULL;
585 : }
586 :
587 : /*
588 : * parse "backend[:option][@loglevel]
589 : */
590 217227 : static void debug_backend_parse_token(char *tok)
591 : {
592 5140 : char *backend_name_option, *backend_name,*backend_level, *saveptr;
593 5140 : char *backend_option;
594 5140 : struct debug_backend *b;
595 :
596 : /*
597 : * First parse into backend[:option] and loglevel
598 : */
599 217227 : backend_name_option = strtok_r(tok, "@\0", &saveptr);
600 217227 : if (backend_name_option == NULL) {
601 2 : return;
602 : }
603 :
604 217227 : backend_level = strtok_r(NULL, "\0", &saveptr);
605 :
606 : /*
607 : * Now parse backend[:option]
608 : */
609 217227 : backend_name = strtok_r(backend_name_option, ":\0", &saveptr);
610 217227 : if (backend_name == NULL) {
611 0 : return;
612 : }
613 :
614 217227 : backend_option = strtok_r(NULL, "\0", &saveptr);
615 :
616 : /*
617 : * Find and update backend
618 : */
619 217227 : b = debug_find_backend(backend_name);
620 217227 : if (b == NULL) {
621 2 : return;
622 : }
623 :
624 217225 : if (backend_level == NULL) {
625 156387 : b->new_log_level = MAX_DEBUG_LEVEL;
626 : } else {
627 60838 : b->new_log_level = atoi(backend_level);
628 : }
629 :
630 217225 : if (backend_option != NULL) {
631 0 : b->option = strdup(backend_option);
632 0 : if (b->option == NULL) {
633 0 : return;
634 : }
635 : }
636 : }
637 :
638 : /*
639 : * parse "backend1[:option1][@loglevel1] backend2[option2][@loglevel2] ... "
640 : * and enable/disable backends accordingly
641 : */
642 186809 : static void debug_set_backends(const char *param)
643 186809 : {
644 186809 : size_t str_len = strlen(param);
645 186809 : char str[str_len+1];
646 4572 : char *tok, *saveptr;
647 4572 : unsigned i;
648 :
649 : /*
650 : * initialize new_log_level to detect backends that have been
651 : * disabled
652 : */
653 1120854 : for (i = 0; i < ARRAY_SIZE(debug_backends); i++) {
654 934045 : SAFE_FREE(debug_backends[i].option);
655 934045 : debug_backends[i].new_log_level = -1;
656 : }
657 :
658 186809 : memcpy(str, param, str_len + 1);
659 :
660 186809 : tok = strtok_r(str, LIST_SEP, &saveptr);
661 186809 : if (tok == NULL) {
662 0 : return;
663 : }
664 :
665 404036 : while (tok != NULL) {
666 217227 : debug_backend_parse_token(tok);
667 217227 : tok = strtok_r(NULL, LIST_SEP, &saveptr);
668 : }
669 :
670 : /*
671 : * Let backends react to config changes
672 : */
673 1120854 : for (i = 0; i < ARRAY_SIZE(debug_backends); i++) {
674 934045 : struct debug_backend *b = &debug_backends[i];
675 :
676 934045 : if (b->reload) {
677 560427 : bool enabled = b->new_log_level > -1;
678 560427 : bool previously_enabled = b->log_level > -1;
679 :
680 560427 : b->reload(enabled, previously_enabled, state.prog_name,
681 : b->option);
682 : }
683 934045 : b->log_level = b->new_log_level;
684 : }
685 : }
686 :
687 4831 : static void debug_backends_log(const char *msg, size_t msg_len, int msg_level)
688 : {
689 1235 : size_t i;
690 :
691 28986 : for (i = 0; i < ARRAY_SIZE(debug_backends); i++) {
692 24155 : if (msg_level <= debug_backends[i].log_level) {
693 4915 : debug_backends[i].log(msg_level, msg, msg_len);
694 : }
695 : }
696 :
697 : /* Only log the header once */
698 4831 : state.hs_len = 0;
699 4831 : }
700 :
701 1039135724 : int debuglevel_get_class(size_t idx)
702 : {
703 1039135724 : return dbgc_config[idx].loglevel;
704 : }
705 :
706 2046 : void debuglevel_set_class(size_t idx, int level)
707 : {
708 2046 : dbgc_config[idx].loglevel = level;
709 2046 : }
710 :
711 :
712 : /* -------------------------------------------------------------------------- **
713 : * Internal variables.
714 : *
715 : * debug_count - Number of debug messages that have been output.
716 : * Used to check log size.
717 : *
718 : * current_msg_level - Internal copy of the message debug level. Written by
719 : * dbghdr() and read by Debug1().
720 : *
721 : * format_bufr - Used to format debug messages. The dbgtext() function
722 : * prints debug messages to a string, and then passes the
723 : * string to format_debug_text(), which uses format_bufr
724 : * to build the formatted output.
725 : *
726 : * format_pos - Marks the first free byte of the format_bufr.
727 : *
728 : *
729 : * log_overflow - When this variable is true, never attempt to check the
730 : * size of the log. This is a hack, so that we can write
731 : * a message using DEBUG, from open_logs() when we
732 : * are unable to open a new log file for some reason.
733 : */
734 :
735 : static int debug_count = 0;
736 : static char format_bufr[FORMAT_BUFR_SIZE];
737 : static size_t format_pos = 0;
738 : static bool log_overflow = false;
739 :
740 : /*
741 : * Define all the debug class selection names here. Names *MUST NOT* contain
742 : * white space. There must be one name for each DBGC_<class name>, and they
743 : * must be in the table in the order of DBGC_<class name>..
744 : */
745 :
746 : static char **classname_table = NULL;
747 :
748 :
749 : /* -------------------------------------------------------------------------- **
750 : * Functions...
751 : */
752 :
753 : static void debug_init(void);
754 :
755 : /***************************************************************************
756 : Free memory pointed to by global pointers.
757 : ****************************************************************************/
758 :
759 15809 : void gfree_debugsyms(void)
760 : {
761 5 : unsigned i;
762 :
763 15809 : TALLOC_FREE(classname_table);
764 :
765 15809 : if ( dbgc_config != debug_class_list_initial ) {
766 14784 : TALLOC_FREE( dbgc_config );
767 14784 : dbgc_config = discard_const_p(struct debug_class,
768 : debug_class_list_initial);
769 : }
770 :
771 15809 : debug_num_classes = 0;
772 :
773 15809 : state.initialized = false;
774 :
775 94854 : for (i = 0; i < ARRAY_SIZE(debug_backends); i++) {
776 79045 : SAFE_FREE(debug_backends[i].option);
777 : }
778 15809 : }
779 :
780 : /****************************************************************************
781 : utility lists registered debug class names's
782 : ****************************************************************************/
783 :
784 0 : char *debug_list_class_names_and_levels(void)
785 : {
786 0 : char *buf = talloc_strdup(NULL, "");
787 0 : size_t i;
788 : /* prepare strings */
789 0 : for (i = 0; i < debug_num_classes; i++) {
790 0 : talloc_asprintf_addbuf(&buf,
791 : "%s:%d%s",
792 0 : classname_table[i],
793 0 : dbgc_config[i].loglevel,
794 0 : i == (debug_num_classes - 1) ? "\n" : " ");
795 : }
796 0 : return buf;
797 : }
798 :
799 : /****************************************************************************
800 : Utility to translate names to debug class index's (internal version).
801 : ****************************************************************************/
802 :
803 1388311 : static int debug_lookup_classname_int(const char* classname)
804 : {
805 25866 : size_t i;
806 :
807 1388311 : if (classname == NULL) {
808 0 : return -1;
809 : }
810 :
811 27673177 : for (i=0; i < debug_num_classes; i++) {
812 26285951 : char *entry = classname_table[i];
813 26285951 : if (entry != NULL && strcmp(classname, entry)==0) {
814 1085 : return i;
815 : }
816 : }
817 1362445 : return -1;
818 : }
819 :
820 : /****************************************************************************
821 : Add a new debug class to the system.
822 : ****************************************************************************/
823 :
824 1387226 : int debug_add_class(const char *classname)
825 : {
826 24781 : int ndx;
827 1387226 : struct debug_class *new_class_list = NULL;
828 24781 : char **new_name_list;
829 24781 : int default_level;
830 :
831 1387226 : if (classname == NULL) {
832 0 : return -1;
833 : }
834 :
835 : /* check the init has yet been called */
836 1387226 : debug_init();
837 :
838 1387226 : ndx = debug_lookup_classname_int(classname);
839 1387226 : if (ndx >= 0) {
840 0 : return ndx;
841 : }
842 1387226 : ndx = debug_num_classes;
843 :
844 1387226 : if (dbgc_config == debug_class_list_initial) {
845 : /* Initial loading... */
846 35068 : new_class_list = NULL;
847 : } else {
848 1351526 : new_class_list = dbgc_config;
849 : }
850 :
851 1387226 : default_level = dbgc_config[DBGC_ALL].loglevel;
852 :
853 1387226 : new_class_list = talloc_realloc(NULL,
854 : new_class_list,
855 : struct debug_class,
856 : ndx + 1);
857 1387226 : if (new_class_list == NULL) {
858 0 : return -1;
859 : }
860 :
861 1387226 : dbgc_config = new_class_list;
862 :
863 1387226 : dbgc_config[ndx] = (struct debug_class) {
864 : .loglevel = default_level,
865 : .fd = -1,
866 : };
867 :
868 1387226 : new_name_list = talloc_realloc(NULL, classname_table, char *, ndx + 1);
869 1387226 : if (new_name_list == NULL) {
870 0 : return -1;
871 : }
872 1387226 : classname_table = new_name_list;
873 :
874 1387226 : classname_table[ndx] = talloc_strdup(classname_table, classname);
875 1387226 : if (classname_table[ndx] == NULL) {
876 0 : return -1;
877 : }
878 :
879 1387226 : debug_num_classes = ndx + 1;
880 :
881 1387226 : return ndx;
882 : }
883 :
884 : /****************************************************************************
885 : Utility to translate names to debug class index's (public version).
886 : ****************************************************************************/
887 :
888 1085 : static int debug_lookup_classname(const char *classname)
889 : {
890 1085 : int ndx;
891 :
892 1085 : if (classname == NULL || !*classname)
893 0 : return -1;
894 :
895 1085 : ndx = debug_lookup_classname_int(classname);
896 :
897 1085 : if (ndx != -1)
898 0 : return ndx;
899 :
900 0 : DBG_WARNING("Unknown classname[%s] -> adding it...\n", classname);
901 0 : return debug_add_class(classname);
902 : }
903 :
904 : /****************************************************************************
905 : Dump the current registered debug levels.
906 : ****************************************************************************/
907 :
908 268987 : static void debug_dump_status(int level)
909 : {
910 5307 : size_t q;
911 :
912 268987 : DEBUG(level, ("INFO: Current debug levels:\n"));
913 10496115 : for (q = 0; q < debug_num_classes; q++) {
914 10227128 : const char *classname = classname_table[q];
915 10227128 : DEBUGADD(level, (" %s: %d\n",
916 : classname,
917 : dbgc_config[q].loglevel));
918 : }
919 268987 : }
920 :
921 1085 : static bool debug_parse_param(char *param)
922 : {
923 1085 : char *class_name;
924 1085 : char *class_file = NULL;
925 1085 : char *class_level;
926 1085 : char *saveptr = NULL;
927 1085 : int ndx;
928 :
929 1085 : class_name = strtok_r(param, ":", &saveptr);
930 1085 : if (class_name == NULL) {
931 0 : return false;
932 : }
933 :
934 1085 : class_level = strtok_r(NULL, "@\0", &saveptr);
935 1085 : if (class_level == NULL) {
936 0 : return false;
937 : }
938 :
939 1085 : class_file = strtok_r(NULL, "\0", &saveptr);
940 :
941 1085 : ndx = debug_lookup_classname(class_name);
942 1085 : if (ndx == -1) {
943 0 : return false;
944 : }
945 :
946 1085 : dbgc_config[ndx].loglevel = atoi(class_level);
947 :
948 1085 : if (class_file == NULL) {
949 0 : return true;
950 : }
951 :
952 894 : TALLOC_FREE(dbgc_config[ndx].logfile);
953 :
954 894 : dbgc_config[ndx].logfile = talloc_strdup(NULL, class_file);
955 894 : if (dbgc_config[ndx].logfile == NULL) {
956 0 : return false;
957 : }
958 0 : return true;
959 : }
960 :
961 : /****************************************************************************
962 : Parse the debug levels from smb.conf. Example debug level string:
963 : 3 tdb:5 printdrivers:7
964 : Note: the 1st param has no "name:" preceding it.
965 : ****************************************************************************/
966 :
967 268987 : bool debug_parse_levels(const char *params_str)
968 268987 : {
969 268987 : size_t str_len = strlen(params_str);
970 268987 : char str[str_len+1];
971 5307 : char *tok, *saveptr;
972 5307 : size_t i;
973 :
974 : /* Just in case */
975 268987 : debug_init();
976 :
977 268987 : memcpy(str, params_str, str_len+1);
978 :
979 268987 : tok = strtok_r(str, LIST_SEP, &saveptr);
980 268987 : if (tok == NULL) {
981 0 : return true;
982 : }
983 :
984 : /* Allow DBGC_ALL to be specified w/o requiring its class name e.g."10"
985 : * v.s. "all:10", this is the traditional way to set DEBUGLEVEL
986 : */
987 268987 : if (isdigit(tok[0])) {
988 268987 : dbgc_config[DBGC_ALL].loglevel = atoi(tok);
989 268987 : tok = strtok_r(NULL, LIST_SEP, &saveptr);
990 : } else {
991 0 : dbgc_config[DBGC_ALL].loglevel = 0;
992 : }
993 :
994 : /* Array is debug_num_classes long */
995 10227128 : for (i = DBGC_ALL+1; i < debug_num_classes; i++) {
996 9958141 : dbgc_config[i].loglevel = dbgc_config[DBGC_ALL].loglevel;
997 9958141 : TALLOC_FREE(dbgc_config[i].logfile);
998 : }
999 :
1000 270072 : while (tok != NULL) {
1001 1085 : bool ok;
1002 :
1003 1085 : ok = debug_parse_param(tok);
1004 1085 : if (!ok) {
1005 0 : DEBUG(0,("debug_parse_params: unrecognized debug "
1006 : "class name or format [%s]\n", tok));
1007 0 : return false;
1008 : }
1009 :
1010 1085 : tok = strtok_r(NULL, LIST_SEP, &saveptr);
1011 : }
1012 :
1013 268987 : debug_dump_status(5);
1014 :
1015 268987 : return true;
1016 : }
1017 :
1018 : /* setup for logging of talloc warnings */
1019 0 : static void talloc_log_fn(const char *msg)
1020 : {
1021 0 : DEBUG(0,("%s", msg));
1022 0 : }
1023 :
1024 49096 : void debug_setup_talloc_log(void)
1025 : {
1026 49096 : talloc_set_log_fn(talloc_log_fn);
1027 49096 : }
1028 :
1029 :
1030 : /****************************************************************************
1031 : Init debugging (one time stuff)
1032 : ****************************************************************************/
1033 :
1034 3116446 : static void debug_init(void)
1035 : {
1036 139849 : size_t i;
1037 :
1038 3116446 : if (state.initialized)
1039 2941529 : return;
1040 :
1041 35700 : state.initialized = true;
1042 :
1043 35700 : debug_setup_talloc_log();
1044 :
1045 1392932 : for (i = 0; i < ARRAY_SIZE(default_classname_table); i++) {
1046 1356600 : debug_add_class(default_classname_table[i]);
1047 : }
1048 35700 : dbgc_config[DBGC_ALL].fd = 2;
1049 :
1050 214200 : for (i = 0; i < ARRAY_SIZE(debug_backends); i++) {
1051 178500 : debug_backends[i].log_level = -1;
1052 178500 : debug_backends[i].new_log_level = -1;
1053 : }
1054 : }
1055 :
1056 186809 : void debug_set_settings(struct debug_settings *settings,
1057 : const char *logging_param,
1058 : int syslog_level, bool syslog_only)
1059 : {
1060 4572 : char fake_param[256];
1061 186809 : size_t len = 0;
1062 :
1063 : /*
1064 : * This forces in some smb.conf derived values into the debug
1065 : * system. There are no pointers in this structure, so we can
1066 : * just structure-assign it in
1067 : */
1068 186809 : state.settings = *settings;
1069 :
1070 : /*
1071 : * If 'logging' is not set, create backend settings from
1072 : * deprecated 'syslog' and 'syslog only' parameters
1073 : */
1074 186809 : if (logging_param != NULL) {
1075 186809 : len = strlen(logging_param);
1076 : }
1077 186809 : if (len == 0) {
1078 30420 : if (syslog_only) {
1079 2 : snprintf(fake_param, sizeof(fake_param),
1080 : "syslog@%d", syslog_level - 1);
1081 : } else {
1082 30418 : snprintf(fake_param, sizeof(fake_param),
1083 : "syslog@%d file@%d", syslog_level -1,
1084 : MAX_DEBUG_LEVEL);
1085 : }
1086 :
1087 29852 : logging_param = fake_param;
1088 : }
1089 :
1090 186809 : debug_set_backends(logging_param);
1091 186809 : }
1092 :
1093 21651 : static void ensure_hostname(void)
1094 : {
1095 212 : int ret;
1096 :
1097 21651 : if (state.hostname[0] != '\0') {
1098 20356 : return;
1099 : }
1100 :
1101 1085 : ret = gethostname(state.hostname, sizeof(state.hostname));
1102 1085 : if (ret != 0) {
1103 0 : strlcpy(state.hostname, "unknown", sizeof(state.hostname));
1104 0 : return;
1105 : }
1106 :
1107 : /*
1108 : * Ensure NUL termination, since POSIX isn't clear about that.
1109 : *
1110 : * Don't worry about truncating at the first '.' or similar,
1111 : * since this is usually not fully qualified. Trying to
1112 : * truncate opens up the multibyte character gates of hell.
1113 : */
1114 1085 : state.hostname[sizeof(state.hostname) - 1] = '\0';
1115 : }
1116 :
1117 0 : void debug_set_hostname(const char *name)
1118 : {
1119 0 : strlcpy(state.hostname, name, sizeof(state.hostname));
1120 0 : }
1121 :
1122 1766 : void debug_set_forced_log_priority(int forced_log_priority)
1123 : {
1124 1766 : state.forced_log_priority = forced_log_priority;
1125 1766 : }
1126 :
1127 : /**
1128 : * Ensure debug logs are initialised.
1129 : *
1130 : * setup_logging() is called to direct logging to the correct outputs, whether
1131 : * those be stderr, stdout, files, or syslog, and set the program name used in
1132 : * the logs. It can be called multiple times.
1133 : *
1134 : * There is an order of precedence to the log type. Once set to DEBUG_FILE, it
1135 : * cannot be reset DEFAULT_DEBUG_STDERR, but can be set to DEBUG_STDERR, after
1136 : * which DEBUG_FILE is unavailable). This makes it possible to override for
1137 : * debug to stderr on the command line, as the smb.conf cannot reset it back
1138 : * to file-based logging. See enum debug_logtype.
1139 : *
1140 : * @param prog_name the program name. Directory path component will be
1141 : * ignored.
1142 : *
1143 : * @param new_logtype the requested destination for the debug log,
1144 : * as an enum debug_logtype.
1145 : */
1146 31448 : void setup_logging(const char *prog_name, enum debug_logtype new_logtype)
1147 : {
1148 31448 : debug_init();
1149 31448 : if (state.logtype < new_logtype) {
1150 2909 : state.logtype = new_logtype;
1151 : }
1152 31448 : if (prog_name) {
1153 31448 : const char *p = strrchr(prog_name, '/');
1154 :
1155 31448 : if (p) {
1156 1159 : prog_name = p + 1;
1157 : }
1158 :
1159 31448 : strlcpy(state.prog_name, prog_name, sizeof(state.prog_name));
1160 : }
1161 31448 : reopen_logs_internal();
1162 31448 : }
1163 :
1164 : /***************************************************************************
1165 : Set the logfile name.
1166 : **************************************************************************/
1167 :
1168 222518 : void debug_set_logfile(const char *name)
1169 : {
1170 222518 : if (name == NULL || *name == 0) {
1171 : /* this copes with calls when smb.conf is not loaded yet */
1172 106 : return;
1173 : }
1174 222412 : TALLOC_FREE(dbgc_config[DBGC_ALL].logfile);
1175 222412 : dbgc_config[DBGC_ALL].logfile = talloc_strdup(NULL, name);
1176 :
1177 222412 : reopen_logs_internal();
1178 : }
1179 :
1180 3710760 : static void debug_close_fd(int fd)
1181 : {
1182 3710760 : if (fd > 2) {
1183 88696 : close(fd);
1184 : }
1185 3411490 : }
1186 :
1187 660 : enum debug_logtype debug_get_log_type(void)
1188 : {
1189 660 : return state.logtype;
1190 : }
1191 :
1192 4 : bool debug_get_output_is_stderr(void)
1193 : {
1194 4 : return (state.logtype == DEBUG_DEFAULT_STDERR) || (state.logtype == DEBUG_STDERR);
1195 : }
1196 :
1197 115 : bool debug_get_output_is_stdout(void)
1198 : {
1199 115 : return (state.logtype == DEBUG_DEFAULT_STDOUT) || (state.logtype == DEBUG_STDOUT);
1200 : }
1201 :
1202 55 : void debug_set_callback(void *private_ptr, debug_callback_fn fn)
1203 : {
1204 55 : debug_init();
1205 55 : if (fn) {
1206 36 : state.logtype = DEBUG_CALLBACK;
1207 36 : state.callback_private = private_ptr;
1208 36 : state.callback = fn;
1209 : } else {
1210 19 : state.logtype = DEBUG_DEFAULT_STDERR;
1211 19 : state.callback_private = NULL;
1212 19 : state.callback = NULL;
1213 : }
1214 55 : }
1215 :
1216 137 : static void debug_callback_log(const char *msg, size_t msg_len, int msg_level)
1217 137 : {
1218 137 : char msg_copy[msg_len];
1219 :
1220 137 : if ((msg_len > 0) && (msg[msg_len-1] == '\n')) {
1221 137 : memcpy(msg_copy, msg, msg_len-1);
1222 137 : msg_copy[msg_len-1] = '\0';
1223 137 : msg = msg_copy;
1224 : }
1225 :
1226 137 : state.callback(state.callback_private, msg_level, msg);
1227 137 : }
1228 :
1229 : /**************************************************************************
1230 : reopen the log files
1231 : note that we now do this unconditionally
1232 : We attempt to open the new debug fp before closing the old. This means
1233 : if we run out of fd's we just keep using the old fd rather than aborting.
1234 : Fix from dgibson@linuxcare.com.
1235 : **************************************************************************/
1236 :
1237 3391150 : static bool reopen_one_log(struct debug_class *config)
1238 : {
1239 3391150 : int old_fd = config->fd;
1240 3391150 : const char *logfile = config->logfile;
1241 297220 : struct stat st;
1242 297220 : int new_fd;
1243 297220 : int ret;
1244 :
1245 3391150 : if (logfile == NULL) {
1246 3300147 : debug_close_fd(old_fd);
1247 3300147 : config->fd = -1;
1248 3300147 : return true;
1249 : }
1250 :
1251 91003 : new_fd = open(logfile, O_WRONLY|O_APPEND|O_CREAT, 0644);
1252 91003 : if (new_fd == -1) {
1253 1106 : log_overflow = true;
1254 1106 : DBG_ERR("Unable to open new log file '%s': %s\n",
1255 : logfile, strerror(errno));
1256 1106 : log_overflow = false;
1257 1106 : return false;
1258 : }
1259 :
1260 89897 : debug_close_fd(old_fd);
1261 89897 : smb_set_close_on_exec(new_fd);
1262 89897 : config->fd = new_fd;
1263 :
1264 89897 : ret = fstat(new_fd, &st);
1265 89897 : if (ret != 0) {
1266 0 : log_overflow = true;
1267 0 : DBG_ERR("Unable to fstat() new log file '%s': %s\n",
1268 : logfile, strerror(errno));
1269 0 : log_overflow = false;
1270 0 : return false;
1271 : }
1272 :
1273 89897 : config->ino = st.st_ino;
1274 89897 : return true;
1275 : }
1276 :
1277 : /**
1278 : reopen the log file (usually called because the log file name might have changed)
1279 : */
1280 410977 : bool reopen_logs_internal(void)
1281 : {
1282 410977 : struct debug_backend *b = NULL;
1283 9906 : mode_t oldumask;
1284 9906 : size_t i;
1285 410977 : bool ok = true;
1286 :
1287 410977 : if (state.reopening_logs) {
1288 0 : return true;
1289 : }
1290 :
1291 : /* Now clear the SIGHUP induced flag */
1292 410977 : state.schedule_reopen_logs = false;
1293 :
1294 410977 : switch (state.logtype) {
1295 17 : case DEBUG_CALLBACK:
1296 17 : return true;
1297 227919 : case DEBUG_STDOUT:
1298 : case DEBUG_DEFAULT_STDOUT:
1299 227919 : debug_close_fd(dbgc_config[DBGC_ALL].fd);
1300 227919 : dbgc_config[DBGC_ALL].fd = 1;
1301 227919 : return true;
1302 :
1303 92797 : case DEBUG_DEFAULT_STDERR:
1304 : case DEBUG_STDERR:
1305 92797 : debug_close_fd(dbgc_config[DBGC_ALL].fd);
1306 92797 : dbgc_config[DBGC_ALL].fd = 2;
1307 92797 : return true;
1308 :
1309 90244 : case DEBUG_FILE:
1310 90244 : b = debug_find_backend("file");
1311 90244 : assert(b != NULL);
1312 :
1313 90244 : b->log_level = MAX_DEBUG_LEVEL;
1314 90244 : break;
1315 : }
1316 :
1317 90244 : oldumask = umask( 022 );
1318 :
1319 98080 : for (i = DBGC_ALL; i < debug_num_classes; i++) {
1320 90244 : if (dbgc_config[i].logfile != NULL) {
1321 82408 : break;
1322 : }
1323 : }
1324 90244 : if (i == debug_num_classes) {
1325 0 : return false;
1326 : }
1327 :
1328 90244 : state.reopening_logs = true;
1329 :
1330 3480288 : for (i = DBGC_ALL; i < debug_num_classes; i++) {
1331 3391150 : ok = reopen_one_log(&dbgc_config[i]);
1332 3391150 : if (!ok) {
1333 1086 : break;
1334 : }
1335 : }
1336 :
1337 : /* Fix from klausr@ITAP.Physik.Uni-Stuttgart.De
1338 : * to fix problem where smbd's that generate less
1339 : * than 100 messages keep growing the log.
1340 : */
1341 90244 : force_check_log_size();
1342 90244 : (void)umask(oldumask);
1343 :
1344 : /*
1345 : * If log file was opened or created successfully, take over stderr to
1346 : * catch output into logs.
1347 : */
1348 90244 : if (!state.settings.debug_no_stderr_redirect &&
1349 90244 : dbgc_config[DBGC_ALL].fd > 0) {
1350 90244 : if (dup2(dbgc_config[DBGC_ALL].fd, 2) == -1) {
1351 : /* Close stderr too, if dup2 can't point it -
1352 : at the logfile. There really isn't much
1353 : that can be done on such a fundamental
1354 : failure... */
1355 0 : close_low_fd(2);
1356 : }
1357 : }
1358 :
1359 90244 : state.reopening_logs = false;
1360 :
1361 90244 : return ok;
1362 : }
1363 :
1364 : /**************************************************************************
1365 : Force a check of the log size.
1366 : ***************************************************************************/
1367 :
1368 9795289 : void force_check_log_size( void )
1369 : {
1370 9795289 : debug_count = 100;
1371 9795289 : }
1372 :
1373 0 : _PUBLIC_ void debug_schedule_reopen_logs(void)
1374 : {
1375 0 : state.schedule_reopen_logs = true;
1376 0 : }
1377 :
1378 :
1379 : /***************************************************************************
1380 : Check to see if there is any need to check if the logfile has grown too big.
1381 : **************************************************************************/
1382 :
1383 9737875 : bool need_to_check_log_size(void)
1384 : {
1385 32015 : int maxlog;
1386 32015 : size_t i;
1387 :
1388 9737875 : if (debug_count < 100) {
1389 44409 : return false;
1390 : }
1391 :
1392 9693204 : maxlog = state.settings.max_log_size * 1024;
1393 9693204 : if (maxlog <= 0) {
1394 2925 : debug_count = 0;
1395 2925 : return false;
1396 : }
1397 :
1398 9690279 : if (dbgc_config[DBGC_ALL].fd > 2) {
1399 2555 : return true;
1400 : }
1401 :
1402 368129712 : for (i = DBGC_ALL + 1; i < debug_num_classes; i++) {
1403 358442088 : if (dbgc_config[i].fd != -1) {
1404 0 : return true;
1405 : }
1406 : }
1407 :
1408 9687624 : debug_count = 0;
1409 9687624 : return false;
1410 : }
1411 :
1412 : /**************************************************************************
1413 : Check to see if the log has grown to be too big.
1414 : **************************************************************************/
1415 :
1416 1769 : static void do_one_check_log_size(off_t maxlog, struct debug_class *config)
1417 1769 : {
1418 1769 : char name[strlen(config->logfile) + 5];
1419 70 : struct stat st;
1420 70 : int ret;
1421 1769 : bool reopen = false;
1422 70 : bool ok;
1423 :
1424 1769 : if (maxlog == 0) {
1425 1769 : return;
1426 : }
1427 :
1428 1769 : ret = stat(config->logfile, &st);
1429 1769 : if (ret != 0) {
1430 0 : return;
1431 : }
1432 1769 : if (st.st_size >= maxlog ) {
1433 0 : reopen = true;
1434 : }
1435 :
1436 1769 : if (st.st_ino != config->ino) {
1437 0 : reopen = true;
1438 : }
1439 :
1440 1769 : if (!reopen) {
1441 1699 : return;
1442 : }
1443 :
1444 : /* reopen_logs_internal() modifies *_fd */
1445 0 : (void)reopen_logs_internal();
1446 :
1447 0 : if (config->fd <= 2) {
1448 0 : return;
1449 : }
1450 0 : ret = fstat(config->fd, &st);
1451 0 : if (ret != 0) {
1452 0 : config->ino = (ino_t)0;
1453 0 : return;
1454 : }
1455 :
1456 0 : config->ino = st.st_ino;
1457 :
1458 0 : if (st.st_size < maxlog) {
1459 0 : return;
1460 : }
1461 :
1462 0 : snprintf(name, sizeof(name), "%s.old", config->logfile);
1463 :
1464 0 : (void)rename(config->logfile, name);
1465 :
1466 0 : ok = reopen_logs_internal();
1467 0 : if (ok) {
1468 0 : return;
1469 : }
1470 : /* We failed to reopen a log - continue using the old name. */
1471 0 : (void)rename(name, config->logfile);
1472 : }
1473 :
1474 1769 : static void do_check_log_size(off_t maxlog)
1475 : {
1476 70 : size_t i;
1477 :
1478 70523 : for (i = DBGC_ALL; i < debug_num_classes; i++) {
1479 68754 : if (dbgc_config[i].fd == -1) {
1480 66985 : continue;
1481 : }
1482 1769 : if (dbgc_config[i].logfile == NULL) {
1483 0 : continue;
1484 : }
1485 1769 : do_one_check_log_size(maxlog, &dbgc_config[i]);
1486 : }
1487 1769 : }
1488 :
1489 27258 : void check_log_size( void )
1490 : {
1491 1322 : off_t maxlog;
1492 :
1493 27258 : if (geteuid() != 0) {
1494 : /*
1495 : * We need to be root to change the log file (tests use a fake
1496 : * geteuid() from third_party/uid_wrapper). Otherwise we skip
1497 : * this and let the main smbd loop or some other process do
1498 : * the work.
1499 : */
1500 8270 : return;
1501 : }
1502 :
1503 17867 : if(log_overflow || (!state.schedule_reopen_logs && !need_to_check_log_size())) {
1504 16098 : return;
1505 : }
1506 :
1507 1769 : maxlog = state.settings.max_log_size * 1024;
1508 :
1509 1769 : if (state.schedule_reopen_logs) {
1510 0 : (void)reopen_logs_internal();
1511 : }
1512 :
1513 1769 : do_check_log_size(maxlog);
1514 :
1515 : /*
1516 : * Here's where we need to panic if dbgc_config[DBGC_ALL].fd == 0 or -1
1517 : * (invalid values)
1518 : */
1519 :
1520 1769 : if (dbgc_config[DBGC_ALL].fd <= 0) {
1521 : /* This code should only be reached in very strange
1522 : * circumstances. If we merely fail to open the new log we
1523 : * should stick with the old one. ergo this should only be
1524 : * reached when opening the logs for the first time: at
1525 : * startup or when the log level is increased from zero.
1526 : * -dwg 6 June 2000
1527 : */
1528 0 : int fd = open( "/dev/console", O_WRONLY, 0);
1529 0 : if (fd != -1) {
1530 0 : smb_set_close_on_exec(fd);
1531 0 : dbgc_config[DBGC_ALL].fd = fd;
1532 0 : DBG_ERR("check_log_size: open of debug file %s failed "
1533 : "- using console.\n",
1534 : dbgc_config[DBGC_ALL].logfile);
1535 : } else {
1536 : /*
1537 : * We cannot continue without a debug file handle.
1538 : */
1539 0 : abort();
1540 : }
1541 : }
1542 1769 : debug_count = 0;
1543 : }
1544 :
1545 : /*************************************************************************
1546 : Write an debug message on the debugfile.
1547 : This is called by format_debug_text().
1548 : ************************************************************************/
1549 :
1550 251875 : static void Debug1(const char *msg, size_t msg_len)
1551 : {
1552 251875 : int old_errno = errno;
1553 :
1554 251875 : debug_count++;
1555 :
1556 251875 : switch(state.logtype) {
1557 137 : case DEBUG_CALLBACK:
1558 137 : debug_callback_log(msg, msg_len, current_msg_level);
1559 137 : break;
1560 246907 : case DEBUG_STDOUT:
1561 : case DEBUG_STDERR:
1562 : case DEBUG_DEFAULT_STDOUT:
1563 : case DEBUG_DEFAULT_STDERR:
1564 246907 : if (state.settings.debug_syslog_format ==
1565 : DEBUG_SYSLOG_FORMAT_ALWAYS) {
1566 20917 : debug_file_log(current_msg_level, msg, msg_len);
1567 : } else {
1568 225990 : if (dbgc_config[DBGC_ALL].fd > 0) {
1569 6180 : ssize_t ret;
1570 6180 : do {
1571 225990 : ret = write(dbgc_config[DBGC_ALL].fd,
1572 : msg,
1573 : msg_len);
1574 225990 : } while (ret == -1 && errno == EINTR);
1575 : }
1576 : }
1577 240670 : break;
1578 4831 : case DEBUG_FILE:
1579 4831 : debug_backends_log(msg, msg_len, current_msg_level);
1580 3596 : break;
1581 7472 : };
1582 :
1583 251875 : errno = old_errno;
1584 251875 : }
1585 :
1586 : /**************************************************************************
1587 : Print the buffer content via Debug1(), then reset the buffer.
1588 : Input: none
1589 : Output: none
1590 : ****************************************************************************/
1591 :
1592 251840 : static void bufr_print( void )
1593 : {
1594 251840 : format_bufr[format_pos] = '\0';
1595 251840 : (void)Debug1(format_bufr, format_pos);
1596 251840 : format_pos = 0;
1597 251840 : }
1598 :
1599 : /*
1600 : * If set (by tevent_thread_call_depth_set()) to value > 0, debug code will use
1601 : * it for the trace indentation.
1602 : */
1603 : static size_t debug_call_depth = 0;
1604 :
1605 45 : size_t *debug_call_depth_addr(void)
1606 : {
1607 45 : return &debug_call_depth;
1608 : }
1609 :
1610 : /***************************************************************************
1611 : Format the debug message text.
1612 :
1613 : Input: msg - Text to be added to the "current" debug message text.
1614 :
1615 : Output: none.
1616 :
1617 : Notes: The purpose of this is two-fold. First, each call to syslog()
1618 : (used by Debug1(), see above) generates a new line of syslog
1619 : output. This is fixed by storing the partial lines until the
1620 : newline character is encountered. Second, printing the debug
1621 : message lines when a newline is encountered allows us to add
1622 : spaces, thus indenting the body of the message and making it
1623 : more readable.
1624 : **************************************************************************/
1625 :
1626 1428730 : static void format_debug_text( const char *msg )
1627 : {
1628 109225 : size_t i;
1629 1428730 : bool timestamp = (state.logtype == DEBUG_FILE && (state.settings.timestamp_logs));
1630 :
1631 1428730 : debug_init();
1632 :
1633 16888443 : for( i = 0; msg[i]; i++ ) {
1634 : /* Indent two spaces at each new line. */
1635 15350488 : if(timestamp && 0 == format_pos) {
1636 : /* Limit the maximum indentation to 20 levels */
1637 4831 : size_t depth = MIN(20, debug_call_depth);
1638 4831 : format_bufr[0] = format_bufr[1] = ' ';
1639 4831 : format_pos = 2;
1640 : /*
1641 : * Indent by four spaces for each depth level,
1642 : * but only if the current debug level is >= 8.
1643 : */
1644 4831 : if (depth > 0 && debuglevel_get() >= 8 &&
1645 0 : format_pos + 4 * depth < FORMAT_BUFR_SIZE) {
1646 0 : memset(&format_bufr[format_pos],
1647 : ' ',
1648 : 4 * depth);
1649 0 : format_pos += 4 * depth;
1650 : }
1651 : }
1652 :
1653 : /* If there's room, copy the character to the format buffer. */
1654 15350488 : if (format_pos < FORMAT_BUFR_SIZE - 1)
1655 15350488 : format_bufr[format_pos++] = msg[i];
1656 :
1657 : /* If a newline is encountered, print & restart. */
1658 15350488 : if( '\n' == msg[i] )
1659 251805 : bufr_print();
1660 :
1661 : /* If the buffer is full dump it out, reset it, and put out a line
1662 : * continuation indicator.
1663 : */
1664 15350488 : if (format_pos >= FORMAT_BUFR_SIZE - 1) {
1665 35 : const char cont[] = " +>\n";
1666 35 : bufr_print();
1667 35 : (void)Debug1(cont , sizeof(cont) - 1);
1668 : }
1669 : }
1670 :
1671 : /* Just to be safe... */
1672 1428730 : format_bufr[format_pos] = '\0';
1673 1428730 : }
1674 :
1675 : /***************************************************************************
1676 : Flush debug output, including the format buffer content.
1677 :
1678 : Input: none
1679 : Output: none
1680 : ***************************************************************************/
1681 :
1682 0 : void dbgflush( void )
1683 : {
1684 0 : bufr_print();
1685 0 : }
1686 :
1687 1426545 : bool dbgsetclass(int level, int cls)
1688 : {
1689 : /* Set current_msg_level. */
1690 1426545 : current_msg_level = level;
1691 :
1692 : /* Set current message class */
1693 1426545 : current_msg_class = cls;
1694 :
1695 1426545 : return true;
1696 : }
1697 :
1698 : /***************************************************************************
1699 : Put a Debug Header into header_str.
1700 :
1701 : Input: level - Debug level of the message (not the system-wide debug
1702 : level. )
1703 : cls - Debuglevel class of the calling module.
1704 : location - Pointer to a string containing the name of the file
1705 : from which this function was called, or an empty string
1706 : if the __FILE__ macro is not implemented.
1707 : func - Pointer to a string containing the name of the function
1708 : from which this function was called, or an empty string
1709 : if the __FUNCTION__ macro is not implemented.
1710 :
1711 : Output: Always true. This makes it easy to fudge a call to dbghdr()
1712 : in a macro, since the function can be called as part of a test.
1713 : Eg: ( (level <= DEBUGLEVEL) && (dbghdr(level,"",line)) )
1714 :
1715 : Notes: This function takes care of setting current_msg_level.
1716 :
1717 : ****************************************************************************/
1718 :
1719 59307 : bool dbghdrclass(int level, int cls, const char *location, const char *func)
1720 : {
1721 : /* Ensure we don't lose any real errno value. */
1722 59307 : int old_errno = errno;
1723 59307 : bool verbose = false;
1724 4338 : struct timeval tv;
1725 4338 : struct timeval_buf tvbuf;
1726 :
1727 : /*
1728 : * This might be overkill, but if another early return is
1729 : * added later then initialising these avoids potential
1730 : * problems
1731 : */
1732 59307 : state.hs_len = 0;
1733 59307 : state.header_str[0] = '\0';
1734 :
1735 59307 : if( format_pos ) {
1736 : /* This is a fudge. If there is stuff sitting in the format_bufr, then
1737 : * the *right* thing to do is to call
1738 : * format_debug_text( "\n" );
1739 : * to write the remainder, and then proceed with the new header.
1740 : * Unfortunately, there are several places in the code at which
1741 : * the DEBUG() macro is used to build partial lines. That in mind,
1742 : * we'll work under the assumption that an incomplete line indicates
1743 : * that a new header is *not* desired.
1744 : */
1745 1958 : return( true );
1746 : }
1747 :
1748 57293 : dbgsetclass(level, cls);
1749 :
1750 : /*
1751 : * Don't print a header if we're logging to stdout,
1752 : * unless 'debug syslog format = always'
1753 : */
1754 57293 : if (state.logtype != DEBUG_FILE &&
1755 53557 : state.settings.debug_syslog_format != DEBUG_SYSLOG_FORMAT_ALWAYS)
1756 : {
1757 30374 : return true;
1758 : }
1759 :
1760 : /*
1761 : * Print the header if timestamps (or debug syslog format) is
1762 : * turned on. If parameters are not yet loaded, then default
1763 : * to timestamps on.
1764 : */
1765 23507 : if (!(state.settings.timestamp_logs ||
1766 0 : state.settings.debug_prefix_timestamp ||
1767 0 : state.settings.debug_syslog_format != DEBUG_SYSLOG_FORMAT_NO))
1768 : {
1769 0 : return true;
1770 : }
1771 :
1772 23507 : GetTimeOfDay(&tv);
1773 :
1774 23507 : if (state.settings.debug_syslog_format != DEBUG_SYSLOG_FORMAT_NO) {
1775 21651 : if (state.settings.debug_hires_timestamp) {
1776 21651 : timeval_str_buf(&tv, true, true, &tvbuf);
1777 : } else {
1778 0 : time_t t;
1779 0 : struct tm *tm;
1780 :
1781 0 : t = (time_t)tv.tv_sec;
1782 0 : tm = localtime(&t);
1783 0 : if (tm != NULL) {
1784 0 : size_t len;
1785 0 : len = strftime(tvbuf.buf,
1786 : sizeof(tvbuf.buf),
1787 : "%b %e %T",
1788 : tm);
1789 0 : if (len == 0) {
1790 : /* Trigger default time format below */
1791 0 : tm = NULL;
1792 : }
1793 : }
1794 0 : if (tm == NULL) {
1795 0 : snprintf(tvbuf.buf,
1796 : sizeof(tvbuf.buf),
1797 : "%ld seconds since the Epoch", (long)t);
1798 : }
1799 : }
1800 :
1801 21651 : ensure_hostname();
1802 21651 : state.hs_len = snprintf(state.header_str,
1803 : sizeof(state.header_str),
1804 : "%s %.*s %s[%u]: ",
1805 : tvbuf.buf,
1806 : (int)(sizeof(state.hostname) - 1),
1807 : state.hostname,
1808 : state.prog_name,
1809 21651 : (unsigned int) getpid());
1810 :
1811 21651 : goto full;
1812 : }
1813 :
1814 1856 : timeval_str_buf(&tv, false, state.settings.debug_hires_timestamp,
1815 : &tvbuf);
1816 :
1817 1856 : state.hs_len = snprintf(state.header_str,
1818 : sizeof(state.header_str),
1819 : "[%s, %2d",
1820 : tvbuf.buf,
1821 : level);
1822 1856 : if (state.hs_len >= sizeof(state.header_str) - 1) {
1823 0 : goto full;
1824 : }
1825 :
1826 1856 : if (unlikely(dbgc_config[cls].loglevel >= 10)) {
1827 0 : verbose = true;
1828 : }
1829 :
1830 1766 : if (verbose || state.settings.debug_pid) {
1831 180 : state.hs_len += snprintf(state.header_str + state.hs_len,
1832 90 : sizeof(state.header_str) - state.hs_len,
1833 : ", pid=%u",
1834 90 : (unsigned int)getpid());
1835 90 : if (state.hs_len >= sizeof(state.header_str) - 1) {
1836 0 : goto full;
1837 : }
1838 : }
1839 :
1840 1856 : if (verbose || state.settings.debug_uid) {
1841 180 : state.hs_len += snprintf(state.header_str + state.hs_len,
1842 90 : sizeof(state.header_str) - state.hs_len,
1843 : ", effective(%u, %u), real(%u, %u)",
1844 90 : (unsigned int)geteuid(),
1845 90 : (unsigned int)getegid(),
1846 90 : (unsigned int)getuid(),
1847 90 : (unsigned int)getgid());
1848 90 : if (state.hs_len >= sizeof(state.header_str) - 1) {
1849 0 : goto full;
1850 : }
1851 : }
1852 :
1853 1856 : if ((verbose || state.settings.debug_class)
1854 90 : && (cls != DBGC_ALL)) {
1855 74 : state.hs_len += snprintf(state.header_str + state.hs_len,
1856 74 : sizeof(state.header_str) - state.hs_len,
1857 : ", class=%s",
1858 74 : classname_table[cls]);
1859 74 : if (state.hs_len >= sizeof(state.header_str) - 1) {
1860 0 : goto full;
1861 : }
1862 : }
1863 :
1864 1856 : if (debug_traceid_get() != 0) {
1865 0 : state.hs_len += snprintf(state.header_str + state.hs_len,
1866 0 : sizeof(state.header_str) - state.hs_len,
1867 : ", traceid=%" PRIu64,
1868 : debug_traceid_get());
1869 0 : if (state.hs_len >= sizeof(state.header_str) - 1) {
1870 0 : goto full;
1871 : }
1872 : }
1873 :
1874 1856 : if (debug_call_depth > 0) {
1875 0 : state.hs_len += snprintf(state.header_str + state.hs_len,
1876 0 : sizeof(state.header_str) - state.hs_len,
1877 : ", depth=%zu",
1878 : debug_call_depth);
1879 0 : if (state.hs_len >= sizeof(state.header_str) - 1) {
1880 0 : goto full;
1881 : }
1882 : }
1883 :
1884 1856 : state.header_str[state.hs_len] = ']';
1885 1856 : state.hs_len++;
1886 1856 : if (state.hs_len < sizeof(state.header_str) - 1) {
1887 1856 : state.header_str[state.hs_len] = ' ';
1888 1856 : state.hs_len++;
1889 : }
1890 1856 : state.header_str[state.hs_len] = '\0';
1891 :
1892 1856 : if (!state.settings.debug_prefix_timestamp) {
1893 1856 : state.hs_len += snprintf(state.header_str + state.hs_len,
1894 1198 : sizeof(state.header_str) - state.hs_len,
1895 : "%s(%s)\n",
1896 : location,
1897 : func);
1898 1856 : if (state.hs_len >= sizeof(state.header_str)) {
1899 0 : goto full;
1900 : }
1901 : }
1902 :
1903 1856 : full:
1904 : /*
1905 : * Above code never overflows state.header_str and always
1906 : * NUL-terminates correctly. However, state.hs_len can point
1907 : * past the end of the buffer to indicate that truncation
1908 : * occurred, so fix it if necessary, since state.hs_len is
1909 : * expected to be used after return.
1910 : */
1911 23507 : if (state.hs_len >= sizeof(state.header_str)) {
1912 0 : state.hs_len = sizeof(state.header_str) - 1;
1913 : }
1914 :
1915 23507 : errno = old_errno;
1916 23507 : return( true );
1917 : }
1918 :
1919 : /***************************************************************************
1920 : Add text to the body of the "current" debug message via the format buffer.
1921 :
1922 : Input: format_str - Format string, as used in printf(), et. al.
1923 : ... - Variable argument list.
1924 :
1925 : ..or.. va_alist - Old style variable parameter list starting point.
1926 :
1927 : Output: Always true. See dbghdr() for more info, though this is not
1928 : likely to be used in the same way.
1929 :
1930 : ***************************************************************************/
1931 :
1932 : static inline bool __dbgtext_va(const char *format_str, va_list ap) PRINTF_ATTRIBUTE(1,0);
1933 1428730 : static inline bool __dbgtext_va(const char *format_str, va_list ap)
1934 : {
1935 1428730 : char *msgbuf = NULL;
1936 1428730 : bool ret = true;
1937 109225 : int res;
1938 :
1939 1428730 : res = vasprintf(&msgbuf, format_str, ap);
1940 1428730 : if (res != -1) {
1941 1428730 : format_debug_text(msgbuf);
1942 : } else {
1943 0 : ret = false;
1944 : }
1945 1428730 : SAFE_FREE(msgbuf);
1946 1428730 : return ret;
1947 : }
1948 :
1949 0 : bool dbgtext_va(const char *format_str, va_list ap)
1950 : {
1951 0 : return __dbgtext_va(format_str, ap);
1952 : }
1953 :
1954 1428730 : bool dbgtext(const char *format_str, ... )
1955 : {
1956 109225 : va_list ap;
1957 109225 : bool ret;
1958 :
1959 1428730 : va_start(ap, format_str);
1960 1428730 : ret = __dbgtext_va(format_str, ap);
1961 1428730 : va_end(ap);
1962 :
1963 1428730 : return ret;
1964 : }
1965 :
1966 : static uint64_t debug_traceid = 0;
1967 :
1968 3715408 : uint64_t debug_traceid_set(uint64_t id)
1969 : {
1970 3715408 : uint64_t old_id = debug_traceid;
1971 3715408 : debug_traceid = id;
1972 3715408 : return old_id;
1973 : }
1974 :
1975 2451585 : uint64_t debug_traceid_get(void)
1976 : {
1977 2451585 : return debug_traceid;
1978 : }
|
