1 /* error logging functions
2 * Copyright (C) 1997 Angelos D. Keromytis.
3 * Copyright (C) 1998-2001 D. Hugh Redelmeier.
5 * This program is free software; you can redistribute it and/or modify it
6 * under the terms of the GNU General Public License as published by the
7 * Free Software Foundation; either version 2 of the License, or (at your
8 * option) any later version. See <http://www.fsf.org/copyleft/gpl.txt>.
10 * This program is distributed in the hope that it will be useful, but
11 * WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY
12 * or FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
26 #include <signal.h> /* used only if MSG_NOSIGNAL not defined */
27 #include <sys/queue.h>
30 #include <sys/types.h>
34 #include "constants.h"
39 #include "connections.h"
41 #include "whack.h" /* needs connections.h */
44 /* close one per-peer log */
45 static void perpeer_logclose(struct connection
*c
); /* forward */
49 log_to_stderr
= TRUE
, /* should log go to stderr? */
50 log_to_syslog
= TRUE
, /* should log go to syslog? */
51 log_to_perpeer
= FALSE
; /* should log go to per-IP file? */
54 logged_txt_warning
= FALSE
; /* should we complain about finding KEY? */
56 /* should we complain when we find no local id */
58 logged_myid_fqdn_txt_warning
= FALSE
,
59 logged_myid_ip_txt_warning
= FALSE
,
60 logged_myid_fqdn_key_warning
= FALSE
,
61 logged_myid_ip_key_warning
= FALSE
;
63 /* may include trailing / */
64 const char *base_perpeer_logdir
= PERPEERLOGDIR
;
65 static int perpeer_count
= 0;
67 /* from sys/queue.h */
68 static TAILQ_HEAD(perpeer
, connection
) perpeer_list
;
71 /* Context for logging.
73 * Global variables: must be carefully adjusted at transaction boundaries!
74 * If the context provides a whack file descriptor, messages
75 * should be copied to it -- see whack_log()
77 int whack_log_fd
= NULL_FD
; /* only set during whack_handle() */
78 struct state
*cur_state
= NULL
; /* current state, for diagnostics */
79 struct connection
*cur_connection
= NULL
; /* current connection, for diagnostics */
80 const ip_address
*cur_from
= NULL
; /* source of current current message */
81 u_int16_t cur_from_port
; /* host order */
84 init_log(const char *program
)
89 openlog(program
, LOG_CONS
| LOG_NDELAY
| LOG_PID
, LOG_AUTHPRIV
);
91 TAILQ_INIT(&perpeer_list
);
97 /* exit if the queue has not been initialized */
98 if (perpeer_list
.tqh_last
== NULL
)
101 /* end of queue is given by pointer to "HEAD" */
102 while (TAILQ_LAST(&perpeer_list
, perpeer
) != (void *)&perpeer_list
)
103 perpeer_logclose(TAILQ_LAST(&perpeer_list
, perpeer
));
115 /* Sanitize character string in situ: turns dangerous characters into \OOO.
116 * With a bit of work, we could use simpler reps for \\, \r, etc.,
117 * but this is only to protect against something that shouldn't be used.
118 * Truncate resulting string to what fits in buffer.
121 sanitize(char *buf
, size_t size
)
123 # define UGLY_WIDTH 4 /* width for ugly character: \OOO */
128 passert(size
>= UGLY_WIDTH
); /* need room to swing cat */
130 /* find right side of string to be sanitized and count
131 * number of columns to be added. Stop on end of string
132 * or lack of room for more result.
134 for (p
= buf
; *p
!= '\0' && &p
[added
] < &buf
[size
- UGLY_WIDTH
]; )
136 unsigned char c
= *p
++;
138 if (c
== '\\' || !isprint(c
))
139 added
+= UGLY_WIDTH
- 1;
142 /* at this point, p points after last original character to be
143 * included. added is how many characters are added to sanitize.
144 * so p[added] will point after last sanitized character.
148 len
= &p
[added
] - buf
;
150 /* scan backwards, copying characters to their new home
151 * and inserting the expansions for ugly characters.
152 * It is finished when no more shifting is required.
153 * This is a predecrement loop.
157 char fmtd
[UGLY_WIDTH
+ 1];
160 while ((c
= *--p
) != '\\' && isprint(c
))
162 added
-= UGLY_WIDTH
- 1;
163 snprintf(fmtd
, sizeof(fmtd
), "\\%03o", c
);
164 memcpy(p
+ added
, fmtd
, UGLY_WIDTH
);
170 /* format a string for the log, with suitable prefixes.
171 * A format starting with ~ indicates that this is a reprocessing
172 * of the message, so prefixing and quoting is suppressed.
175 fmt_log(char *buf
, size_t buf_len
, const char *fmt
, va_list ap
)
177 bool reproc
= *fmt
== '~';
179 struct connection
*c
= cur_state
!= NULL ? cur_state
->st_connection
184 fmt
++; /* ~ at start of format suppresses this prefix */
187 /* start with name of connection */
188 char *const be
= buf
+ buf_len
;
191 snprintf(bp
, be
- bp
, "\"%s\"", c
->name
);
194 /* if it fits, put in any connection instance information */
195 if (be
- bp
> CONN_INST_BUF
)
197 fmt_conn_instance(c
, bp
);
201 if (cur_state
!= NULL
)
204 snprintf(bp
, be
- bp
, " #%lu", cur_state
->st_serialno
);
207 snprintf(bp
, be
- bp
, ": ");
209 else if (cur_from
!= NULL
)
211 /* peer's IP address */
212 /* Note: must not use ip_str() because our caller might! */
213 char ab
[ADDRTOT_BUF
];
215 (void) addrtot(cur_from
, 0, ab
, sizeof(ab
));
216 snprintf(buf
, buf_len
, "packet from %s:%u: "
217 , ab
, (unsigned)cur_from_port
);
221 vsnprintf(buf
+ ps
, buf_len
- ps
, fmt
, ap
);
223 (void)sanitize(buf
, buf_len
);
227 perpeer_logclose(struct connection
*c
)
229 /* only free/close things if we had used them! */
230 if (c
->log_file
!= NULL
)
232 passert(perpeer_count
> 0);
234 TAILQ_REMOVE(&perpeer_list
, c
, log_link
);
242 perpeer_logfree(struct connection
*c
)
245 if (c
->log_file_name
!= NULL
)
247 pfree(c
->log_file_name
);
248 c
->log_file_name
= NULL
;
249 c
->log_file_err
= FALSE
;
253 /* open the per-peer log */
255 open_peerlog(struct connection
*c
)
257 syslog(LOG_INFO
, "opening log file for conn %s", c
->name
);
259 if (c
->log_file_name
== NULL
)
261 char peername
[ADDRTOT_BUF
], dname
[ADDRTOT_BUF
];
262 int peernamelen
, lf_len
;
264 addrtot(&c
->spd
.that
.host_addr
, 'Q', peername
, sizeof(peername
));
265 peernamelen
= strlen(peername
);
267 /* copy IP address, turning : and . into / */
275 if (c
== '.' || c
== ':')
281 lf_len
= peernamelen
* 2
282 + strlen(base_perpeer_logdir
)
285 c
->log_file_name
= alloc_bytes(lf_len
, "per-peer log file name");
287 fprintf(stderr
, "base dir |%s| dname |%s| peername |%s|"
288 , base_perpeer_logdir
, dname
, peername
);
289 snprintf(c
->log_file_name
, lf_len
, "%s/%s/%s.log"
290 , base_perpeer_logdir
, dname
, peername
);
292 syslog(LOG_DEBUG
, "conn %s logfile is %s", c
->name
, c
->log_file_name
);
295 /* now open the file, creating directories if necessary */
297 { /* create the directory */
299 int bpl_len
= strlen(base_perpeer_logdir
);
302 dname
= clone_str(c
->log_file_name
, "temp copy of file name");
303 dname
= dirname(dname
);
305 if (access(dname
, W_OK
) != 0)
311 syslog(LOG_CRIT
, "can not write to %s: %s"
312 , dname
, strerror(errno
));
313 c
->log_file_err
= TRUE
;
319 /* directory does not exist, walk path creating dirs */
320 /* start at base_perpeer_logdir */
321 slashloc
= dname
+ bpl_len
;
322 slashloc
++; /* since, by construction there is a slash
325 while (*slashloc
!= '\0')
329 /* look for next slash */
330 while (*slashloc
!= '\0' && *slashloc
!= '/') slashloc
++;
332 saveslash
= *slashloc
;
336 if (mkdir(dname
, 0750) != 0 && errno
!= EEXIST
)
338 syslog(LOG_CRIT
, "can not create dir %s: %s"
339 , dname
, strerror(errno
));
340 c
->log_file_err
= TRUE
;
344 syslog(LOG_DEBUG
, "created new directory %s", dname
);
345 *slashloc
= saveslash
;
353 c
->log_file
= fopen(c
->log_file_name
, "a");
354 if (c
->log_file
== NULL
)
358 syslog(LOG_CRIT
, "logging system can not open %s: %s"
359 , c
->log_file_name
, strerror(errno
));
360 c
->log_file_err
= TRUE
;
365 /* look for a connection to close! */
366 while (perpeer_count
>= MAX_PEERLOG_COUNT
)
368 /* can not be NULL because perpeer_count > 0 */
369 passert(TAILQ_LAST(&perpeer_list
, perpeer
) != (void *)&perpeer_list
);
371 perpeer_logclose(TAILQ_LAST(&perpeer_list
, perpeer
));
374 /* insert this into the list */
375 TAILQ_INSERT_HEAD(&perpeer_list
, c
, log_link
);
376 passert(c
->log_file
!= NULL
);
380 /* log a line to cur_connection's log */
382 peerlog(const char *prefix
, const char *m
)
384 if (cur_connection
== NULL
)
386 /* we can not log it in this case. Oh well. */
390 if (cur_connection
->log_file
== NULL
)
392 open_peerlog(cur_connection
);
395 /* despite our attempts above, we may not be able to open the file. */
396 if (cur_connection
->log_file
!= NULL
)
405 strftime(datebuf
, sizeof(datebuf
), "%Y-%m-%d %T", t
);
406 fprintf(cur_connection
->log_file
, "%s %s%s\n", datebuf
, prefix
, m
);
408 /* now move it to the front of the list */
409 TAILQ_REMOVE(&perpeer_list
, cur_connection
, log_link
);
410 TAILQ_INSERT_HEAD(&perpeer_list
, cur_connection
, log_link
);
415 plog(const char *message
, ...)
418 char m
[LOG_WIDTH
]; /* longer messages will be truncated */
420 va_start(args
, message
);
421 fmt_log(m
, sizeof(m
), message
, args
);
425 fprintf(stderr
, "%s\n", m
);
427 syslog(LOG_WARNING
, "%s", m
);
431 whack_log(RC_LOG
, "~%s", m
);
435 loglog(int mess_no
, const char *message
, ...)
438 char m
[LOG_WIDTH
]; /* longer messages will be truncated */
440 va_start(args
, message
);
441 fmt_log(m
, sizeof(m
), message
, args
);
445 fprintf(stderr
, "%s\n", m
);
447 syslog(LOG_WARNING
, "%s", m
);
451 whack_log(mess_no
, "~%s", m
);
455 log_errno_routine(int e
, const char *message
, ...)
458 char m
[LOG_WIDTH
]; /* longer messages will be truncated */
460 va_start(args
, message
);
461 fmt_log(m
, sizeof(m
), message
, args
);
465 fprintf(stderr
, "ERROR: %s. Errno %d: %s\n", m
, e
, strerror(e
));
467 syslog(LOG_ERR
, "ERROR: %s. Errno %d: %s", m
, e
, strerror(e
));
470 peerlog(strerror(e
), m
);
473 whack_log(RC_LOG_SERIOUS
474 , "~ERROR: %s. Errno %d: %s", m
, e
, strerror(e
));
478 exit_log(const char *message
, ...)
481 char m
[LOG_WIDTH
]; /* longer messages will be truncated */
483 va_start(args
, message
);
484 fmt_log(m
, sizeof(m
), message
, args
);
488 fprintf(stderr
, "FATAL ERROR: %s\n", m
);
490 syslog(LOG_ERR
, "FATAL ERROR: %s", m
);
492 peerlog("FATAL ERROR: ", m
);
494 whack_log(RC_LOG_SERIOUS
, "~FATAL ERROR: %s", m
);
500 exit_log_errno_routine(int e
, const char *message
, ...)
503 char m
[LOG_WIDTH
]; /* longer messages will be truncated */
505 va_start(args
, message
);
506 fmt_log(m
, sizeof(m
), message
, args
);
510 fprintf(stderr
, "FATAL ERROR: %s. Errno %d: %s\n", m
, e
, strerror(e
));
512 syslog(LOG_ERR
, "FATAL ERROR: %s. Errno %d: %s", m
, e
, strerror(e
));
514 peerlog(strerror(e
), m
);
516 whack_log(RC_LOG_SERIOUS
517 , "~FATAL ERROR: %s. Errno %d: %s", m
, e
, strerror(e
));
522 /* emit message to whack.
523 * form is "ddd statename text" where
524 * - ddd is a decimal status code (RC_*) as described in whack.h
525 * - text is a human-readable annotation
528 static volatile sig_atomic_t dying_breath
= FALSE
;
532 whack_log(int mess_no
, const char *message
, ...)
534 int wfd
= whack_log_fd
!= NULL_FD ? whack_log_fd
535 : cur_state
!= NULL ? cur_state
->st_whack_sock
545 char m
[LOG_WIDTH
]; /* longer messages will be truncated */
546 int prelen
= snprintf(m
, sizeof(m
), "%03d ", mess_no
);
548 passert(prelen
>= 0);
550 va_start(args
, message
);
551 fmt_log(m
+prelen
, sizeof(m
)-prelen
, message
, args
);
557 /* status output copied to log */
559 fprintf(stderr
, "%s\n", m
+ prelen
);
561 syslog(LOG_WARNING
, "%s", m
+ prelen
);
569 /* write to whack socket, but suppress possible SIGPIPE */
570 size_t len
= strlen(m
);
571 #ifdef MSG_NOSIGNAL /* depends on version of glibc??? */
572 m
[len
] = '\n'; /* don't need NUL, do need NL */
573 (void) send(wfd
, m
, len
+ 1, MSG_NOSIGNAL
);
574 #else /* !MSG_NOSIGNAL */
579 m
[len
] = '\n'; /* don't need NUL, do need NL */
580 act
.sa_handler
= SIG_IGN
;
581 sigemptyset(&act
.sa_mask
);
582 act
.sa_flags
= 0; /* no nothing */
583 r
= sigaction(SIGPIPE
, &act
, &oldact
);
586 (void) write(wfd
, m
, len
+ 1);
588 r
= sigaction(SIGPIPE
, &oldact
, NULL
);
590 #endif /* !MSG_NOSIGNAL */
595 /* Build up a diagnostic in a static buffer.
596 * Although this would be a generally useful function, it is very
597 * hard to come up with a discipline that prevents different uses
598 * from interfering. It is intended that by limiting it to building
599 * diagnostics, we will avoid this problem.
600 * Juggling is performed to allow an argument to be a previous
601 * result: the new string may safely depend on the old one. This
602 * restriction is not checked in any way: violators will produce
603 * confusing results (without crashing!).
605 char diag_space
[sizeof(diag_space
)];
608 builddiag(const char *fmt
, ...)
610 static char diag_space
[LOG_WIDTH
]; /* longer messages will be truncated */
611 char t
[sizeof(diag_space
)]; /* build result here first */
615 t
[0] = '\0'; /* in case nothing terminates string */
616 vsnprintf(t
, sizeof(t
), fmt
, args
);
618 strcpy(diag_space
, t
);
622 /* Debugging message support */
627 switch_fail(int n
, const char *file_str
, unsigned long line_no
)
631 snprintf(buf
, sizeof(buf
), "case %d unexpected", n
);
632 passert_fail(buf
, file_str
, line_no
);
636 passert_fail(const char *pred_str
, const char *file_str
, unsigned long line_no
)
638 /* we will get a possibly unplanned prefix. Hope it works */
639 loglog(RC_LOG_SERIOUS
, "ASSERTION FAILED at %s:%lu: %s", file_str
, line_no
, pred_str
);
643 show_status(TRUE
, NULL
);
645 abort(); /* exiting correctly doesn't always work */
649 pexpect_log(const char *pred_str
, const char *file_str
, unsigned long line_no
)
651 /* we will get a possibly unplanned prefix. Hope it works */
652 loglog(RC_LOG_SERIOUS
, "EXPECTATION FAILED at %s:%lu: %s", file_str
, line_no
, pred_str
);
656 base_debugging
= DBG_NONE
, /* default to reporting nothing */
657 cur_debugging
= DBG_NONE
;
660 extra_debugging(const struct connection
*c
)
668 if (c
!= NULL
&& c
->extra_debugging
!= 0)
670 plog("enabling for connection: %s"
671 , bitnamesof(debug_bit_names
, c
->extra_debugging
& ~cur_debugging
));
672 cur_debugging
|= c
->extra_debugging
;
676 /* log a debugging message (prefixed by "| ") */
679 DBG_log(const char *message
, ...)
682 char m
[LOG_WIDTH
]; /* longer messages will be truncated */
684 va_start(args
, message
);
685 vsnprintf(m
, sizeof(m
), message
, args
);
688 (void)sanitize(m
, sizeof(m
));
691 fprintf(stderr
, "| %s\n", m
);
693 syslog(LOG_DEBUG
, "| %s", m
);
698 /* dump raw bytes in hex to stderr (for lack of any better destination) */
701 DBG_dump(const char *label
, const void *p
, size_t len
)
703 # define DUMP_LABEL_WIDTH 20 /* arbitrary modest boundary */
704 # define DUMP_WIDTH (4 * (1 + 4 * 3) + 1)
705 char buf
[DUMP_LABEL_WIDTH
+ DUMP_WIDTH
];
707 const unsigned char *cp
= p
;
711 if (label
!= NULL
&& label
[0] != '\0')
713 /* Handle the label. Care must be taken to avoid buffer overrun. */
714 size_t llen
= strlen(label
);
716 if (llen
+ 1 > sizeof(buf
))
718 DBG_log("%s", label
);
723 if (buf
[llen
-1] == '\n')
725 buf
[llen
-1] = '\0'; /* get rid of newline */
728 else if (llen
< DUMP_LABEL_WIDTH
)
742 for (i
= 0; len
!=0 && i
!=4; i
++)
745 for (j
= 0; len
!=0 && j
!=4; len
--, j
++)
747 static const char hexdig
[] = "0123456789abcdef";
750 *bp
++ = hexdig
[(*cp
>> 4) & 0xF];
751 *bp
++ = hexdig
[*cp
& 0xF];
759 # undef DUMP_LABEL_WIDTH
766 show_status(bool all
, const char *name
)
770 show_ifaces_status();
773 whack_log(RC_COMMENT
, BLANK_FORMAT
); /* spacer */
775 show_connections_status(all
, name
);
776 show_states_status(all
, name
);
782 /* ip_str: a simple to use variant of addrtot.
783 * It stores its result in a static buffer.
784 * This means that newer calls overwrite the storage of older calls.
785 * Note: this is not used in any of the logging functions, so their
786 * callers may use it.
789 ip_str(const ip_address
*src
)
791 static char buf
[ADDRTOT_BUF
];
793 addrtot(src
, 0, buf
, sizeof(buf
));
798 * a routine that attempts to schedule itself daily.
803 daily_log_reset(void)
805 /* now perform actions */
806 logged_txt_warning
= FALSE
;
808 logged_myid_fqdn_txt_warning
= FALSE
;
809 logged_myid_ip_txt_warning
= FALSE
;
810 logged_myid_fqdn_key_warning
= FALSE
;
811 logged_myid_ip_key_warning
= FALSE
;
815 daily_log_event(void)
820 /* attempt to schedule oneself to midnight, local time
821 * do this by getting seconds in the day, and delaying
822 * by 86400 - hour*3600+minutes*60+seconds.
825 ltime
= localtime(&n
);
826 interval
= (24 * 60 * 60)
829 + ltime
->tm_hour
* 3600);
831 event_schedule(EVENT_LOG_DAILY
, interval
, NULL
);