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