1 /* $OpenBSD: log.c,v 1.64 2024/12/07 10:05:36 djm Exp $ */
2 /*
3 * Author: Tatu Ylonen <ylo@cs.hut.fi>
4 * Copyright (c) 1995 Tatu Ylonen <ylo@cs.hut.fi>, Espoo, Finland
5 * All rights reserved
6 *
7 * As far as I am concerned, the code I have written for this software
8 * can be used freely for any purpose. Any derived versions of this
9 * software must be clearly marked as such, and if the derived work is
10 * incompatible with the protocol description in the RFC file, it must be
11 * called by a name other than "ssh" or "Secure Shell".
12 */
13 /*
14 * Copyright (c) 2000 Markus Friedl. All rights reserved.
15 *
16 * Redistribution and use in source and binary forms, with or without
17 * modification, are permitted provided that the following conditions
18 * are met:
19 * 1. Redistributions of source code must retain the above copyright
20 * notice, this list of conditions and the following disclaimer.
21 * 2. Redistributions in binary form must reproduce the above copyright
22 * notice, this list of conditions and the following disclaimer in the
23 * documentation and/or other materials provided with the distribution.
24 *
25 * THIS SOFTWARE IS PROVIDED BY THE AUTHOR ``AS IS'' AND ANY EXPRESS OR
26 * IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES
27 * OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE DISCLAIMED.
28 * IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR ANY DIRECT, INDIRECT,
29 * INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT
30 * NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
31 * DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
32 * THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
33 * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE OF
34 * THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
35 */
36
37 #include <sys/types.h>
38
39 #include <errno.h>
40 #include <fcntl.h>
41 #include <limits.h>
42 #include <stdarg.h>
43 #include <stdio.h>
44 #include <stdlib.h>
45 #include <string.h>
46 #include <syslog.h>
47 #include <time.h>
48 #include <unistd.h>
49 #include <vis.h>
50
51 #include "log.h"
52 #include "match.h"
53
54 static LogLevel log_level = SYSLOG_LEVEL_INFO;
55 static int log_on_stderr = 1;
56 static int log_stderr_fd = STDERR_FILENO;
57 static int log_facility = LOG_AUTH;
58 static const char *argv0;
59 static log_handler_fn *log_handler;
60 static void *log_handler_ctx;
61 static char **log_verbose;
62 static size_t nlog_verbose;
63 extern char *__progname;
64
65 /* textual representation of log-facilities/levels */
66
67 static struct {
68 const char *name;
69 SyslogFacility val;
70 } log_facilities[] = {
71 { "DAEMON", SYSLOG_FACILITY_DAEMON },
72 { "USER", SYSLOG_FACILITY_USER },
73 { "AUTH", SYSLOG_FACILITY_AUTH },
74 { "LOCAL0", SYSLOG_FACILITY_LOCAL0 },
75 { "LOCAL1", SYSLOG_FACILITY_LOCAL1 },
76 { "LOCAL2", SYSLOG_FACILITY_LOCAL2 },
77 { "LOCAL3", SYSLOG_FACILITY_LOCAL3 },
78 { "LOCAL4", SYSLOG_FACILITY_LOCAL4 },
79 { "LOCAL5", SYSLOG_FACILITY_LOCAL5 },
80 { "LOCAL6", SYSLOG_FACILITY_LOCAL6 },
81 { "LOCAL7", SYSLOG_FACILITY_LOCAL7 },
82 { NULL, SYSLOG_FACILITY_NOT_SET }
83 };
84
85 static struct {
86 const char *name;
87 LogLevel val;
88 } log_levels[] =
89 {
90 { "QUIET", SYSLOG_LEVEL_QUIET },
91 { "FATAL", SYSLOG_LEVEL_FATAL },
92 { "ERROR", SYSLOG_LEVEL_ERROR },
93 { "INFO", SYSLOG_LEVEL_INFO },
94 { "VERBOSE", SYSLOG_LEVEL_VERBOSE },
95 { "DEBUG", SYSLOG_LEVEL_DEBUG1 },
96 { "DEBUG1", SYSLOG_LEVEL_DEBUG1 },
97 { "DEBUG2", SYSLOG_LEVEL_DEBUG2 },
98 { "DEBUG3", SYSLOG_LEVEL_DEBUG3 },
99 { NULL, SYSLOG_LEVEL_NOT_SET }
100 };
101
102 LogLevel
log_level_get(void)103 log_level_get(void)
104 {
105 return log_level;
106 }
107
108 SyslogFacility
log_facility_number(char * name)109 log_facility_number(char *name)
110 {
111 int i;
112
113 if (name != NULL)
114 for (i = 0; log_facilities[i].name; i++)
115 if (strcasecmp(log_facilities[i].name, name) == 0)
116 return log_facilities[i].val;
117 return SYSLOG_FACILITY_NOT_SET;
118 }
119
120 const char *
log_facility_name(SyslogFacility facility)121 log_facility_name(SyslogFacility facility)
122 {
123 u_int i;
124
125 for (i = 0; log_facilities[i].name; i++)
126 if (log_facilities[i].val == facility)
127 return log_facilities[i].name;
128 return NULL;
129 }
130
131 LogLevel
log_level_number(char * name)132 log_level_number(char *name)
133 {
134 int i;
135
136 if (name != NULL)
137 for (i = 0; log_levels[i].name; i++)
138 if (strcasecmp(log_levels[i].name, name) == 0)
139 return log_levels[i].val;
140 return SYSLOG_LEVEL_NOT_SET;
141 }
142
143 const char *
log_level_name(LogLevel level)144 log_level_name(LogLevel level)
145 {
146 u_int i;
147
148 for (i = 0; log_levels[i].name != NULL; i++)
149 if (log_levels[i].val == level)
150 return log_levels[i].name;
151 return NULL;
152 }
153
154 void
log_verbose_add(const char * s)155 log_verbose_add(const char *s)
156 {
157 char **tmp;
158
159 /* Ignore failures here */
160 if ((tmp = recallocarray(log_verbose, nlog_verbose, nlog_verbose + 1,
161 sizeof(*log_verbose))) != NULL) {
162 log_verbose = tmp;
163 if ((log_verbose[nlog_verbose] = strdup(s)) != NULL)
164 nlog_verbose++;
165 }
166 }
167
168 void
log_verbose_reset(void)169 log_verbose_reset(void)
170 {
171 size_t i;
172
173 for (i = 0; i < nlog_verbose; i++)
174 free(log_verbose[i]);
175 free(log_verbose);
176 log_verbose = NULL;
177 nlog_verbose = 0;
178 }
179
180 /*
181 * Initialize the log.
182 */
183
184 void
log_init(const char * av0,LogLevel level,SyslogFacility facility,int on_stderr)185 log_init(const char *av0, LogLevel level, SyslogFacility facility,
186 int on_stderr)
187 {
188 argv0 = av0;
189
190 if (log_change_level(level) != 0) {
191 fprintf(stderr, "Unrecognized internal syslog level code %d\n",
192 (int) level);
193 exit(1);
194 }
195
196 log_handler = NULL;
197 log_handler_ctx = NULL;
198
199 log_on_stderr = on_stderr;
200 if (on_stderr)
201 return;
202
203 switch (facility) {
204 case SYSLOG_FACILITY_DAEMON:
205 log_facility = LOG_DAEMON;
206 break;
207 case SYSLOG_FACILITY_USER:
208 log_facility = LOG_USER;
209 break;
210 case SYSLOG_FACILITY_AUTH:
211 log_facility = LOG_AUTH;
212 break;
213 case SYSLOG_FACILITY_LOCAL0:
214 log_facility = LOG_LOCAL0;
215 break;
216 case SYSLOG_FACILITY_LOCAL1:
217 log_facility = LOG_LOCAL1;
218 break;
219 case SYSLOG_FACILITY_LOCAL2:
220 log_facility = LOG_LOCAL2;
221 break;
222 case SYSLOG_FACILITY_LOCAL3:
223 log_facility = LOG_LOCAL3;
224 break;
225 case SYSLOG_FACILITY_LOCAL4:
226 log_facility = LOG_LOCAL4;
227 break;
228 case SYSLOG_FACILITY_LOCAL5:
229 log_facility = LOG_LOCAL5;
230 break;
231 case SYSLOG_FACILITY_LOCAL6:
232 log_facility = LOG_LOCAL6;
233 break;
234 case SYSLOG_FACILITY_LOCAL7:
235 log_facility = LOG_LOCAL7;
236 break;
237 default:
238 fprintf(stderr,
239 "Unrecognized internal syslog facility code %d\n",
240 (int) facility);
241 exit(1);
242 }
243 }
244
245 int
log_change_level(LogLevel new_log_level)246 log_change_level(LogLevel new_log_level)
247 {
248 /* no-op if log_init has not been called */
249 if (argv0 == NULL)
250 return 0;
251
252 switch (new_log_level) {
253 case SYSLOG_LEVEL_QUIET:
254 case SYSLOG_LEVEL_FATAL:
255 case SYSLOG_LEVEL_ERROR:
256 case SYSLOG_LEVEL_INFO:
257 case SYSLOG_LEVEL_VERBOSE:
258 case SYSLOG_LEVEL_DEBUG1:
259 case SYSLOG_LEVEL_DEBUG2:
260 case SYSLOG_LEVEL_DEBUG3:
261 log_level = new_log_level;
262 return 0;
263 default:
264 return -1;
265 }
266 }
267
268 int
log_is_on_stderr(void)269 log_is_on_stderr(void)
270 {
271 return log_on_stderr && log_stderr_fd == STDERR_FILENO;
272 }
273
274 /* redirect what would usually get written to stderr to specified file */
275 void
log_redirect_stderr_to(const char * logfile)276 log_redirect_stderr_to(const char *logfile)
277 {
278 int fd;
279
280 if (logfile == NULL) {
281 if (log_stderr_fd != STDERR_FILENO) {
282 close(log_stderr_fd);
283 log_stderr_fd = STDERR_FILENO;
284 }
285 return;
286 }
287
288 if ((fd = open(logfile, O_WRONLY|O_CREAT|O_APPEND, 0600)) == -1) {
289 fprintf(stderr, "Couldn't open logfile %s: %s\n", logfile,
290 strerror(errno));
291 exit(1);
292 }
293 log_stderr_fd = fd;
294 }
295
296 #define MSGBUFSIZ 1024
297
298 void
set_log_handler(log_handler_fn * handler,void * ctx)299 set_log_handler(log_handler_fn *handler, void *ctx)
300 {
301 log_handler = handler;
302 log_handler_ctx = ctx;
303 }
304
305 static void
do_log(LogLevel level,int force,const char * suffix,const char * fmt,va_list args)306 do_log(LogLevel level, int force, const char *suffix, const char *fmt,
307 va_list args)
308 {
309 struct syslog_data sdata = SYSLOG_DATA_INIT;
310 char msgbuf[MSGBUFSIZ];
311 char fmtbuf[MSGBUFSIZ];
312 char *txt = NULL;
313 int pri = LOG_INFO;
314 int saved_errno = errno;
315 log_handler_fn *tmp_handler;
316 const char *progname = argv0 != NULL ? argv0 : __progname;
317
318 if (!force && level > log_level)
319 return;
320
321 switch (level) {
322 case SYSLOG_LEVEL_FATAL:
323 if (!log_on_stderr)
324 txt = "fatal";
325 pri = LOG_CRIT;
326 break;
327 case SYSLOG_LEVEL_ERROR:
328 if (!log_on_stderr)
329 txt = "error";
330 pri = LOG_ERR;
331 break;
332 case SYSLOG_LEVEL_INFO:
333 pri = LOG_INFO;
334 break;
335 case SYSLOG_LEVEL_VERBOSE:
336 pri = LOG_INFO;
337 break;
338 case SYSLOG_LEVEL_DEBUG1:
339 txt = "debug1";
340 pri = LOG_DEBUG;
341 break;
342 case SYSLOG_LEVEL_DEBUG2:
343 txt = "debug2";
344 pri = LOG_DEBUG;
345 break;
346 case SYSLOG_LEVEL_DEBUG3:
347 txt = "debug3";
348 pri = LOG_DEBUG;
349 break;
350 default:
351 txt = "internal error";
352 pri = LOG_ERR;
353 break;
354 }
355 if (txt != NULL && log_handler == NULL) {
356 snprintf(fmtbuf, sizeof(fmtbuf), "%s: %s", txt, fmt);
357 vsnprintf(msgbuf, sizeof(msgbuf), fmtbuf, args);
358 } else {
359 vsnprintf(msgbuf, sizeof(msgbuf), fmt, args);
360 }
361 if (suffix != NULL) {
362 snprintf(fmtbuf, sizeof(fmtbuf), "%s: %s", msgbuf, suffix);
363 strlcpy(msgbuf, fmtbuf, sizeof(msgbuf));
364 }
365 strnvis(fmtbuf, msgbuf, sizeof(fmtbuf), VIS_SAFE|VIS_OCTAL);
366 if (log_handler != NULL) {
367 /* Avoid recursion */
368 tmp_handler = log_handler;
369 log_handler = NULL;
370 tmp_handler(level, force, fmtbuf, log_handler_ctx);
371 log_handler = tmp_handler;
372 } else if (log_on_stderr) {
373 snprintf(msgbuf, sizeof msgbuf, "%s%s%.*s\r\n",
374 (log_on_stderr > 1) ? progname : "",
375 (log_on_stderr > 1) ? ": " : "",
376 (int)sizeof msgbuf - 3, fmtbuf);
377 (void)write(log_stderr_fd, msgbuf, strlen(msgbuf));
378 } else {
379 openlog_r(progname, LOG_PID, log_facility, &sdata);
380 syslog_r(pri, &sdata, "%.500s", fmtbuf);
381 closelog_r(&sdata);
382 }
383 errno = saved_errno;
384 }
385
386 void
sshlog(const char * file,const char * func,int line,int showfunc,LogLevel level,const char * suffix,const char * fmt,...)387 sshlog(const char *file, const char *func, int line, int showfunc,
388 LogLevel level, const char *suffix, const char *fmt, ...)
389 {
390 va_list args;
391
392 va_start(args, fmt);
393 sshlogv(file, func, line, showfunc, level, suffix, fmt, args);
394 va_end(args);
395 }
396
397 void
sshlogdie(const char * file,const char * func,int line,int showfunc,LogLevel level,const char * suffix,const char * fmt,...)398 sshlogdie(const char *file, const char *func, int line, int showfunc,
399 LogLevel level, const char *suffix, const char *fmt, ...)
400 {
401 va_list args;
402
403 va_start(args, fmt);
404 sshlogv(file, func, line, showfunc, SYSLOG_LEVEL_INFO,
405 suffix, fmt, args);
406 va_end(args);
407 cleanup_exit(255);
408 }
409
410 void
sshlogv(const char * file,const char * func,int line,int showfunc,LogLevel level,const char * suffix,const char * fmt,va_list args)411 sshlogv(const char *file, const char *func, int line, int showfunc,
412 LogLevel level, const char *suffix, const char *fmt, va_list args)
413 {
414 char tag[128], fmt2[MSGBUFSIZ + 128];
415 int forced = 0;
416 const char *cp;
417 size_t i;
418
419 /* short circuit processing early if we're not going to log anything */
420 if (nlog_verbose == 0 && level > log_level)
421 return;
422
423 snprintf(tag, sizeof(tag), "%.48s:%.48s():%d (bin=%s, pid=%ld)",
424 (cp = strrchr(file, '/')) == NULL ? file : cp + 1, func, line,
425 argv0 == NULL ? "UNKNOWN" : argv0, (long)getpid());
426 for (i = 0; i < nlog_verbose; i++) {
427 if (match_pattern_list(tag, log_verbose[i], 0) == 1) {
428 forced = 1;
429 break;
430 }
431 }
432
433 if (forced)
434 snprintf(fmt2, sizeof(fmt2), "%s: %s", tag, fmt);
435 else if (showfunc)
436 snprintf(fmt2, sizeof(fmt2), "%s: %s", func, fmt);
437 else
438 strlcpy(fmt2, fmt, sizeof(fmt2));
439
440 do_log(level, forced, suffix, fmt2, args);
441 }
442
443 void
sshlogdirect(LogLevel level,int forced,const char * fmt,...)444 sshlogdirect(LogLevel level, int forced, const char *fmt, ...)
445 {
446 va_list args;
447
448 va_start(args, fmt);
449 do_log(level, forced, NULL, fmt, args);
450 va_end(args);
451 }
452
453
454 /*
455 * A simple system for ratelimiting aperiodic events such as logs, without
456 * needing to be hooked into a mainloop/timer. A running total of events is
457 * maintained and when it exceeds a threshold further events are dropped
458 * until the rate falls back below that threshold.
459 *
460 * To prevent flipping in and out of rate-limiting, there is a hysteresis
461 * timer that delays leaving the rate-limited state.
462 *
463 * While in the rate-limited state, events can be periodically allowed though
464 * and the number of dropped events since the last log obtained.
465 *
466 * XXX a moving average rate of events might be a better approach here rather
467 * than linear decay, which can suppress events for a while after large
468 * bursts.
469 */
470
471 /* #define RATELIMIT_DEBUG 1 */
472
473 #ifdef RATELIMIT_DEBUG
474 # define RLDBG(x) do { \
475 printf("%s:%d %s: ", __FILE__, __LINE__, __func__); \
476 printf x; \
477 printf("\n"); \
478 fflush(stdout); \
479 } while (0)
480 #else
481 # define RLDBG(x)
482 #endif
483
484 /* set up a ratelimit */
485 void
log_ratelimit_init(struct log_ratelimit_ctx * rl,u_int threshold,u_int max_accum,u_int hysteresis,u_int log_every)486 log_ratelimit_init(struct log_ratelimit_ctx *rl, u_int threshold,
487 u_int max_accum, u_int hysteresis, u_int log_every)
488 {
489 memset(rl, 0, sizeof(*rl));
490 rl->threshold = threshold;
491 rl->max_accum = max_accum;
492 rl->hysteresis = hysteresis;
493 rl->log_every = log_every;
494 RLDBG(("called: rl=%p thresh=%u max=%u hys=%u log_every=%u",
495 rl, rl->threshold, rl->max_accum, rl->hysteresis, rl->log_every));
496 }
497
498 /*
499 * check whether a log event should be dropped because of rate-limiting.
500 * returns non-zero if the event should be dropped. If events_since_last
501 * is supplied then, for periodic logs, it will be set to the number of
502 * dropped events since the last message.
503 */
504 int
log_ratelimit(struct log_ratelimit_ctx * rl,time_t now,int * active,u_int * events_dropped)505 log_ratelimit(struct log_ratelimit_ctx *rl, time_t now, int *active,
506 u_int *events_dropped)
507 {
508 time_t olast_event;
509
510 RLDBG(("called: rl=%p thresh=%u max=%u hys=%u log_every=%u "
511 "accum=%u since=%ld since_last=%u", rl, rl->threshold,
512 rl->max_accum, rl->hysteresis,
513 rl->log_every, rl->accumulated_events,
514 rl->last_event == 0 ? -1 : (long)(now - rl->last_event),
515 rl->ratelimited_events));
516
517 if (now < 0)
518 return 0;
519 if (events_dropped != NULL)
520 *events_dropped = 0;
521 if (active != NULL)
522 *active = rl->ratelimit_active;
523
524 /* First, decay accumulated events */
525 if (rl->last_event <= 0)
526 rl->last_event = now;
527 if (now > rl->last_event) {
528 uint64_t n = now - rl->last_event;
529
530 if (n > UINT_MAX)
531 n = UINT_MAX;
532 if (rl->accumulated_events < (u_int)n)
533 rl->accumulated_events = 0;
534 else
535 rl->accumulated_events -= (u_int)n;
536 RLDBG(("decay: accum=%u", rl->accumulated_events));
537 }
538 rl->accumulated_events++; /* add this event */
539 if (rl->accumulated_events > rl->max_accum)
540 rl->accumulated_events = rl->max_accum;
541 olast_event = rl->last_event;
542 rl->last_event = now;
543 RLDBG(("check threshold: accum=%u vs thresh=%u",
544 rl->accumulated_events, rl->threshold));
545
546 /* Are we under threshold? */
547 if (rl->accumulated_events < rl->threshold) {
548 if (!rl->ratelimit_active)
549 return 0;
550 RLDBG(("under threshold: hys=%u since_hys=%ld since_last=%ld",
551 rl->hysteresis, rl->hysteresis_start == 0 ? -1 :
552 (long)(now - rl->hysteresis_start),
553 olast_event == 0 ? -1 : (long)(now - olast_event)));
554 if (rl->hysteresis_start == 0) {
555 /* active, but under threshold; hysteresis */
556 if (olast_event + rl->hysteresis < now) {
557 /* hysteresis expired before this event */
558 RLDBG(("hysteresis preexpired"));
559 goto inactive;
560 }
561 RLDBG(("start hysteresis"));
562 rl->hysteresis_start = now;
563 } else if (rl->hysteresis_start + rl->hysteresis < now) {
564 /* Hysteresis period expired, transition to inactive */
565 RLDBG(("complete hysteresis"));
566 inactive:
567 if (events_dropped != NULL)
568 *events_dropped = rl->ratelimited_events;
569 if (active != NULL)
570 *active = 0;
571 rl->ratelimit_active = 0;
572 rl->ratelimit_start = 0;
573 rl->last_log = 0;
574 rl->hysteresis_start = 0;
575 rl->ratelimited_events = 0;
576 return 0;
577 }
578 /* ratelimiting active, but in hysteresis period */
579 } else if (!rl->ratelimit_active) {
580 /* Transition to rate-limiting */
581 RLDBG(("start ratelimit"));
582 rl->ratelimit_active = 1;
583 rl->ratelimit_start = now;
584 rl->last_log = now;
585 rl->hysteresis_start = 0;
586 rl->ratelimited_events = 1;
587 if (active != NULL)
588 *active = 1;
589 return 1;
590 } else if (rl->hysteresis_start != 0) {
591 /* active and over threshold; reset hysteresis timer */
592 RLDBG(("clear hysteresis"));
593 rl->hysteresis_start = 0;
594 }
595
596 /* over threshold or in hysteresis period; log periodically */
597 if (active != NULL)
598 *active = 1;
599 RLDBG(("log_every=%u since_log=%ld", rl->log_every,
600 (long)(now - rl->last_log)));
601 if (rl->log_every > 0 && now >= rl->last_log + rl->log_every) {
602 RLDBG(("periodic: since_last=%u", rl->ratelimited_events));
603 rl->last_log = now;
604 if (events_dropped != NULL) {
605 *events_dropped = rl->ratelimited_events;
606 rl->ratelimited_events = 0;
607 }
608 return 0;
609 }
610
611 /* drop event */
612 rl->ratelimited_events++;
613 RLDBG(("drop: ratelimited_events=%u", rl->ratelimited_events));
614 return 1;
615 }
616