1 /* $NetBSD: log.c,v 1.34 2026/04/08 18:58:40 christos Exp $ */ 2 /* $OpenBSD: log.c,v 1.67 2026/02/14 00:18:34 jsg Exp $ */ 3 4 /* 5 * Author: Tatu Ylonen <ylo (at) cs.hut.fi> 6 * Copyright (c) 1995 Tatu Ylonen <ylo (at) 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.34 2026/04/08 18:58:40 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 <unistd.h> 53 #include <vis.h> 54 55 #include "log.h" 56 #include "match.h" 57 58 static LogLevel log_level = SYSLOG_LEVEL_INFO; 59 static int log_on_stderr = 1; 60 static int log_stderr_fd = STDERR_FILENO; 61 static int log_facility = LOG_AUTH; 62 static const char *argv0; 63 static log_handler_fn *log_handler; 64 static void *log_handler_ctx; 65 static char **log_verbose; 66 static size_t nlog_verbose; 67 extern char *__progname; 68 69 /* textual representation of log-facilities/levels */ 70 71 static struct { 72 const char *name; 73 SyslogFacility val; 74 } log_facilities[] = { 75 { "DAEMON", SYSLOG_FACILITY_DAEMON }, 76 { "USER", SYSLOG_FACILITY_USER }, 77 { "AUTH", SYSLOG_FACILITY_AUTH }, 78 { "LOCAL0", SYSLOG_FACILITY_LOCAL0 }, 79 { "LOCAL1", SYSLOG_FACILITY_LOCAL1 }, 80 { "LOCAL2", SYSLOG_FACILITY_LOCAL2 }, 81 { "LOCAL3", SYSLOG_FACILITY_LOCAL3 }, 82 { "LOCAL4", SYSLOG_FACILITY_LOCAL4 }, 83 { "LOCAL5", SYSLOG_FACILITY_LOCAL5 }, 84 { "LOCAL6", SYSLOG_FACILITY_LOCAL6 }, 85 { "LOCAL7", SYSLOG_FACILITY_LOCAL7 }, 86 { NULL, SYSLOG_FACILITY_NOT_SET } 87 }; 88 89 static struct { 90 const char *name; 91 LogLevel val; 92 } log_levels[] = 93 { 94 { "QUIET", SYSLOG_LEVEL_QUIET }, 95 { "FATAL", SYSLOG_LEVEL_FATAL }, 96 { "ERROR", SYSLOG_LEVEL_ERROR }, 97 { "INFO", SYSLOG_LEVEL_INFO }, 98 { "VERBOSE", SYSLOG_LEVEL_VERBOSE }, 99 { "DEBUG", SYSLOG_LEVEL_DEBUG1 }, 100 { "DEBUG1", SYSLOG_LEVEL_DEBUG1 }, 101 { "DEBUG2", SYSLOG_LEVEL_DEBUG2 }, 102 { "DEBUG3", SYSLOG_LEVEL_DEBUG3 }, 103 { NULL, SYSLOG_LEVEL_NOT_SET } 104 }; 105 106 LogLevel 107 log_level_get(void) 108 { 109 return log_level; 110 } 111 112 SyslogFacility 113 log_facility_number(char *name) 114 { 115 int i; 116 117 if (name != NULL) 118 for (i = 0; log_facilities[i].name; i++) 119 if (strcasecmp(log_facilities[i].name, name) == 0) 120 return log_facilities[i].val; 121 return SYSLOG_FACILITY_NOT_SET; 122 } 123 124 const char * 125 log_facility_name(SyslogFacility facility) 126 { 127 u_int i; 128 129 for (i = 0; log_facilities[i].name; i++) 130 if (log_facilities[i].val == facility) 131 return log_facilities[i].name; 132 return NULL; 133 } 134 135 LogLevel 136 log_level_number(char *name) 137 { 138 int i; 139 140 if (name != NULL) 141 for (i = 0; log_levels[i].name; i++) 142 if (strcasecmp(log_levels[i].name, name) == 0) 143 return log_levels[i].val; 144 return SYSLOG_LEVEL_NOT_SET; 145 } 146 147 const char * 148 log_level_name(LogLevel level) 149 { 150 u_int i; 151 152 for (i = 0; log_levels[i].name != NULL; i++) 153 if (log_levels[i].val == level) 154 return log_levels[i].name; 155 return NULL; 156 } 157 158 void 159 log_verbose_add(const char *s) 160 { 161 char **tmp; 162 163 /* Ignore failures here */ 164 if ((tmp = recallocarray(log_verbose, nlog_verbose, nlog_verbose + 1, 165 sizeof(*log_verbose))) != NULL) { 166 log_verbose = tmp; 167 if ((log_verbose[nlog_verbose] = strdup(s)) != NULL) 168 nlog_verbose++; 169 } 170 } 171 172 void 173 log_verbose_reset(void) 174 { 175 size_t i; 176 177 for (i = 0; i < nlog_verbose; i++) 178 free(log_verbose[i]); 179 free(log_verbose); 180 log_verbose = NULL; 181 nlog_verbose = 0; 182 } 183 184 /* 185 * Initialize the log. 186 */ 187 188 void 189 log_init(const char *av0, LogLevel level, SyslogFacility facility, 190 int on_stderr) 191 { 192 argv0 = av0; 193 194 if (log_change_level(level) != 0) { 195 fprintf(stderr, "Unrecognized internal syslog level code %d\n", 196 (int) level); 197 exit(1); 198 } 199 200 log_handler = NULL; 201 log_handler_ctx = NULL; 202 203 log_on_stderr = on_stderr; 204 if (on_stderr) 205 return; 206 207 switch (facility) { 208 case SYSLOG_FACILITY_DAEMON: 209 log_facility = LOG_DAEMON; 210 break; 211 case SYSLOG_FACILITY_USER: 212 log_facility = LOG_USER; 213 break; 214 case SYSLOG_FACILITY_AUTH: 215 log_facility = LOG_AUTH; 216 break; 217 case SYSLOG_FACILITY_LOCAL0: 218 log_facility = LOG_LOCAL0; 219 break; 220 case SYSLOG_FACILITY_LOCAL1: 221 log_facility = LOG_LOCAL1; 222 break; 223 case SYSLOG_FACILITY_LOCAL2: 224 log_facility = LOG_LOCAL2; 225 break; 226 case SYSLOG_FACILITY_LOCAL3: 227 log_facility = LOG_LOCAL3; 228 break; 229 case SYSLOG_FACILITY_LOCAL4: 230 log_facility = LOG_LOCAL4; 231 break; 232 case SYSLOG_FACILITY_LOCAL5: 233 log_facility = LOG_LOCAL5; 234 break; 235 case SYSLOG_FACILITY_LOCAL6: 236 log_facility = LOG_LOCAL6; 237 break; 238 case SYSLOG_FACILITY_LOCAL7: 239 log_facility = LOG_LOCAL7; 240 break; 241 default: 242 fprintf(stderr, 243 "Unrecognized internal syslog facility code %d\n", 244 (int) facility); 245 exit(1); 246 } 247 } 248 249 int 250 log_change_level(LogLevel new_log_level) 251 { 252 /* no-op if log_init has not been called */ 253 if (argv0 == NULL) 254 return 0; 255 256 switch (new_log_level) { 257 case SYSLOG_LEVEL_QUIET: 258 case SYSLOG_LEVEL_FATAL: 259 case SYSLOG_LEVEL_ERROR: 260 case SYSLOG_LEVEL_INFO: 261 case SYSLOG_LEVEL_VERBOSE: 262 case SYSLOG_LEVEL_DEBUG1: 263 case SYSLOG_LEVEL_DEBUG2: 264 case SYSLOG_LEVEL_DEBUG3: 265 log_level = new_log_level; 266 return 0; 267 default: 268 return -1; 269 } 270 } 271 272 int 273 log_is_on_stderr(void) 274 { 275 return log_on_stderr && log_stderr_fd == STDERR_FILENO; 276 } 277 278 /* redirect what would usually get written to stderr to specified file */ 279 void 280 log_redirect_stderr_to(const char *logfile) 281 { 282 int fd; 283 284 if (logfile == NULL) { 285 if (log_stderr_fd != STDERR_FILENO) { 286 close(log_stderr_fd); 287 log_stderr_fd = STDERR_FILENO; 288 } 289 return; 290 } 291 292 if ((fd = open(logfile, O_WRONLY|O_CREAT|O_APPEND, 0600)) == -1) { 293 fprintf(stderr, "Couldn't open logfile %s: %s\n", logfile, 294 strerror(errno)); 295 exit(1); 296 } 297 log_stderr_fd = fd; 298 } 299 300 #define MSGBUFSIZ 1024 301 302 void 303 set_log_handler(log_handler_fn *handler, void *ctx) 304 { 305 log_handler = handler; 306 log_handler_ctx = ctx; 307 } 308 309 static void 310 do_log(LogLevel level, int force, const char *suffix, const char *fmt, 311 va_list args) 312 { 313 struct syslog_data sdata = SYSLOG_DATA_INIT; 314 char msgbuf[MSGBUFSIZ], *msgbufp; 315 char visbuf[MSGBUFSIZ * 4 + 1]; 316 size_t len, len2; 317 const char *txt = NULL; 318 int pri = LOG_INFO; 319 int saved_errno = errno; 320 log_handler_fn *tmp_handler; 321 const char *progname = argv0 != NULL ? argv0 : __progname; 322 323 if (!force && level > log_level) 324 return; 325 326 switch (level) { 327 case SYSLOG_LEVEL_FATAL: 328 if (!log_on_stderr) 329 txt = "fatal"; 330 pri = LOG_CRIT; 331 break; 332 case SYSLOG_LEVEL_ERROR: 333 if (!log_on_stderr) 334 txt = "error"; 335 pri = LOG_ERR; 336 break; 337 case SYSLOG_LEVEL_INFO: 338 pri = LOG_INFO; 339 break; 340 case SYSLOG_LEVEL_VERBOSE: 341 pri = LOG_INFO; 342 break; 343 case SYSLOG_LEVEL_DEBUG1: 344 txt = "debug1"; 345 pri = LOG_DEBUG; 346 break; 347 case SYSLOG_LEVEL_DEBUG2: 348 txt = "debug2"; 349 pri = LOG_DEBUG; 350 break; 351 case SYSLOG_LEVEL_DEBUG3: 352 txt = "debug3"; 353 pri = LOG_DEBUG; 354 break; 355 default: 356 txt = "internal error"; 357 pri = LOG_ERR; 358 break; 359 } 360 len = sizeof(msgbuf); 361 msgbufp = msgbuf; 362 if (txt != NULL && log_handler == NULL) { 363 len2 = strlen(txt); 364 if (len2 > len - 2) 365 len2 = len - 2; 366 memcpy(msgbufp, txt, len2); 367 msgbufp += len2; 368 *msgbufp++ = ':'; 369 *msgbufp++ = ' '; 370 len -= len2 + 2; 371 } 372 vsnprintf(msgbufp, len, fmt, args); 373 if (suffix != NULL) { 374 snprintf(visbuf, sizeof(visbuf), "%s: %s", msgbuf, suffix); 375 strlcpy(msgbuf, visbuf, sizeof(msgbuf)); 376 } 377 strnvis(visbuf, sizeof(visbuf), msgbuf, VIS_SAFE|VIS_OCTAL); 378 if (log_handler != NULL) { 379 /* Avoid recursion */ 380 tmp_handler = log_handler; 381 log_handler = NULL; 382 /* Note: this sends the raw (i.e. no strnvis) log message */ 383 tmp_handler(level, force, msgbuf, 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 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 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 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 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 through 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 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 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
Indexes created Thu Jun 11 00:25:07 UTC 2026