xref: /openbsd-src/usr.bin/ssh/log.c (revision cc7fda5dc13177fbb968f11eafde9629247b7deb) 
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
103 log_level_get(void)
104 {
105 	return log_level;
106 }
107 
108 SyslogFacility
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 *
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
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 *
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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