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 "includes.h" 38 39 #include <sys/types.h> 40 41 #include <errno.h> 42 #include <fcntl.h> 43 #include <limits.h> 44 #include <stdarg.h> 45 #include <stdio.h> 46 #include <stdlib.h> 47 #include <string.h> 48 #include <syslog.h> 49 #include <time.h> 50 #include <unistd.h> 51 #if defined(HAVE_STRNVIS) && defined(HAVE_VIS_H) && !defined(BROKEN_STRNVIS) 52 # include <vis.h> 53 #endif 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 68 extern char *__progname; 69 70 #define LOG_SYSLOG_VIS (VIS_CSTYLE|VIS_NL|VIS_TAB|VIS_OCTAL) 71 #define LOG_STDERR_VIS (VIS_SAFE|VIS_OCTAL) 72 73 /* textual representation of log-facilities/levels */ 74 75 static struct { 76 const char *name; 77 SyslogFacility val; 78 } log_facilities[] = { 79 { "DAEMON", SYSLOG_FACILITY_DAEMON }, 80 { "USER", SYSLOG_FACILITY_USER }, 81 { "AUTH", SYSLOG_FACILITY_AUTH }, 82 #ifdef LOG_AUTHPRIV 83 { "AUTHPRIV", SYSLOG_FACILITY_AUTHPRIV }, 84 #endif 85 { "LOCAL0", SYSLOG_FACILITY_LOCAL0 }, 86 { "LOCAL1", SYSLOG_FACILITY_LOCAL1 }, 87 { "LOCAL2", SYSLOG_FACILITY_LOCAL2 }, 88 { "LOCAL3", SYSLOG_FACILITY_LOCAL3 }, 89 { "LOCAL4", SYSLOG_FACILITY_LOCAL4 }, 90 { "LOCAL5", SYSLOG_FACILITY_LOCAL5 }, 91 { "LOCAL6", SYSLOG_FACILITY_LOCAL6 }, 92 { "LOCAL7", SYSLOG_FACILITY_LOCAL7 }, 93 { NULL, SYSLOG_FACILITY_NOT_SET } 94 }; 95 96 static struct { 97 const char *name; 98 LogLevel val; 99 } log_levels[] = 100 { 101 { "QUIET", SYSLOG_LEVEL_QUIET }, 102 { "FATAL", SYSLOG_LEVEL_FATAL }, 103 { "ERROR", SYSLOG_LEVEL_ERROR }, 104 { "INFO", SYSLOG_LEVEL_INFO }, 105 { "VERBOSE", SYSLOG_LEVEL_VERBOSE }, 106 { "DEBUG", SYSLOG_LEVEL_DEBUG1 }, 107 { "DEBUG1", SYSLOG_LEVEL_DEBUG1 }, 108 { "DEBUG2", SYSLOG_LEVEL_DEBUG2 }, 109 { "DEBUG3", SYSLOG_LEVEL_DEBUG3 }, 110 { NULL, SYSLOG_LEVEL_NOT_SET } 111 }; 112 113 LogLevel 114 log_level_get(void) 115 { 116 return log_level; 117 } 118 119 SyslogFacility 120 log_facility_number(char *name) 121 { 122 int i; 123 124 if (name != NULL) 125 for (i = 0; log_facilities[i].name; i++) 126 if (strcasecmp(log_facilities[i].name, name) == 0) 127 return log_facilities[i].val; 128 return SYSLOG_FACILITY_NOT_SET; 129 } 130 131 const char * 132 log_facility_name(SyslogFacility facility) 133 { 134 u_int i; 135 136 for (i = 0; log_facilities[i].name; i++) 137 if (log_facilities[i].val == facility) 138 return log_facilities[i].name; 139 return NULL; 140 } 141 142 LogLevel 143 log_level_number(char *name) 144 { 145 int i; 146 147 if (name != NULL) 148 for (i = 0; log_levels[i].name; i++) 149 if (strcasecmp(log_levels[i].name, name) == 0) 150 return log_levels[i].val; 151 return SYSLOG_LEVEL_NOT_SET; 152 } 153 154 const char * 155 log_level_name(LogLevel level) 156 { 157 u_int i; 158 159 for (i = 0; log_levels[i].name != NULL; i++) 160 if (log_levels[i].val == level) 161 return log_levels[i].name; 162 return NULL; 163 } 164 165 void 166 log_verbose_add(const char *s) 167 { 168 char **tmp; 169 170 /* Ignore failures here */ 171 if ((tmp = recallocarray(log_verbose, nlog_verbose, nlog_verbose + 1, 172 sizeof(*log_verbose))) != NULL) { 173 log_verbose = tmp; 174 if ((log_verbose[nlog_verbose] = strdup(s)) != NULL) 175 nlog_verbose++; 176 } 177 } 178 179 void 180 log_verbose_reset(void) 181 { 182 size_t i; 183 184 for (i = 0; i < nlog_verbose; i++) 185 free(log_verbose[i]); 186 free(log_verbose); 187 log_verbose = NULL; 188 nlog_verbose = 0; 189 } 190 191 /* 192 * Initialize the log. 193 */ 194 195 void 196 log_init(const char *av0, LogLevel level, SyslogFacility facility, 197 int on_stderr) 198 { 199 #if defined(HAVE_OPENLOG_R) && defined(SYSLOG_DATA_INIT) 200 struct syslog_data sdata = SYSLOG_DATA_INIT; 201 #endif 202 203 argv0 = av0; 204 205 if (log_change_level(level) != 0) { 206 fprintf(stderr, "Unrecognized internal syslog level code %d\n", 207 (int) level); 208 exit(1); 209 } 210 211 log_handler = NULL; 212 log_handler_ctx = NULL; 213 214 log_on_stderr = on_stderr; 215 if (on_stderr) 216 return; 217 218 switch (facility) { 219 case SYSLOG_FACILITY_DAEMON: 220 log_facility = LOG_DAEMON; 221 break; 222 case SYSLOG_FACILITY_USER: 223 log_facility = LOG_USER; 224 break; 225 case SYSLOG_FACILITY_AUTH: 226 log_facility = LOG_AUTH; 227 break; 228 #ifdef LOG_AUTHPRIV 229 case SYSLOG_FACILITY_AUTHPRIV: 230 log_facility = LOG_AUTHPRIV; 231 break; 232 #endif 233 case SYSLOG_FACILITY_LOCAL0: 234 log_facility = LOG_LOCAL0; 235 break; 236 case SYSLOG_FACILITY_LOCAL1: 237 log_facility = LOG_LOCAL1; 238 break; 239 case SYSLOG_FACILITY_LOCAL2: 240 log_facility = LOG_LOCAL2; 241 break; 242 case SYSLOG_FACILITY_LOCAL3: 243 log_facility = LOG_LOCAL3; 244 break; 245 case SYSLOG_FACILITY_LOCAL4: 246 log_facility = LOG_LOCAL4; 247 break; 248 case SYSLOG_FACILITY_LOCAL5: 249 log_facility = LOG_LOCAL5; 250 break; 251 case SYSLOG_FACILITY_LOCAL6: 252 log_facility = LOG_LOCAL6; 253 break; 254 case SYSLOG_FACILITY_LOCAL7: 255 log_facility = LOG_LOCAL7; 256 break; 257 default: 258 fprintf(stderr, 259 "Unrecognized internal syslog facility code %d\n", 260 (int) facility); 261 exit(1); 262 } 263 264 /* 265 * If an external library (eg libwrap) attempts to use syslog 266 * immediately after reexec, syslog may be pointing to the wrong 267 * facility, so we force an open/close of syslog here. 268 */ 269 #if defined(HAVE_OPENLOG_R) && defined(SYSLOG_DATA_INIT) 270 openlog_r(argv0 ? argv0 : __progname, LOG_PID, log_facility, &sdata); 271 closelog_r(&sdata); 272 #else 273 openlog(argv0 ? argv0 : __progname, LOG_PID, log_facility); 274 closelog(); 275 #endif 276 } 277 278 int 279 log_change_level(LogLevel new_log_level) 280 { 281 /* no-op if log_init has not been called */ 282 if (argv0 == NULL) 283 return 0; 284 285 switch (new_log_level) { 286 case SYSLOG_LEVEL_QUIET: 287 case SYSLOG_LEVEL_FATAL: 288 case SYSLOG_LEVEL_ERROR: 289 case SYSLOG_LEVEL_INFO: 290 case SYSLOG_LEVEL_VERBOSE: 291 case SYSLOG_LEVEL_DEBUG1: 292 case SYSLOG_LEVEL_DEBUG2: 293 case SYSLOG_LEVEL_DEBUG3: 294 log_level = new_log_level; 295 return 0; 296 default: 297 return -1; 298 } 299 } 300 301 int 302 log_is_on_stderr(void) 303 { 304 return log_on_stderr && log_stderr_fd == STDERR_FILENO; 305 } 306 307 /* redirect what would usually get written to stderr to specified file */ 308 void 309 log_redirect_stderr_to(const char *logfile) 310 { 311 int fd; 312 313 if (logfile == NULL) { 314 if (log_stderr_fd != STDERR_FILENO) { 315 close(log_stderr_fd); 316 log_stderr_fd = STDERR_FILENO; 317 } 318 return; 319 } 320 321 if ((fd = open(logfile, O_WRONLY|O_CREAT|O_APPEND, 0600)) == -1) { 322 fprintf(stderr, "Couldn't open logfile %s: %s\n", logfile, 323 strerror(errno)); 324 exit(1); 325 } 326 log_stderr_fd = fd; 327 } 328 329 #define MSGBUFSIZ 1024 330 331 void 332 set_log_handler(log_handler_fn *handler, void *ctx) 333 { 334 log_handler = handler; 335 log_handler_ctx = ctx; 336 } 337 338 static void 339 do_log(LogLevel level, int force, const char *suffix, const char *fmt, 340 va_list args) 341 { 342 #if defined(HAVE_OPENLOG_R) && defined(SYSLOG_DATA_INIT) 343 struct syslog_data sdata = SYSLOG_DATA_INIT; 344 #endif 345 char msgbuf[MSGBUFSIZ]; 346 char fmtbuf[MSGBUFSIZ]; 347 char *txt = NULL; 348 int pri = LOG_INFO; 349 int saved_errno = errno; 350 log_handler_fn *tmp_handler; 351 const char *progname = argv0 != NULL ? argv0 : __progname; 352 353 if (!force && level > log_level) 354 return; 355 356 switch (level) { 357 case SYSLOG_LEVEL_FATAL: 358 if (!log_on_stderr) 359 txt = "fatal"; 360 pri = LOG_CRIT; 361 break; 362 case SYSLOG_LEVEL_ERROR: 363 if (!log_on_stderr) 364 txt = "error"; 365 pri = LOG_ERR; 366 break; 367 case SYSLOG_LEVEL_INFO: 368 pri = LOG_INFO; 369 break; 370 case SYSLOG_LEVEL_VERBOSE: 371 pri = LOG_INFO; 372 break; 373 case SYSLOG_LEVEL_DEBUG1: 374 txt = "debug1"; 375 pri = LOG_DEBUG; 376 break; 377 case SYSLOG_LEVEL_DEBUG2: 378 txt = "debug2"; 379 pri = LOG_DEBUG; 380 break; 381 case SYSLOG_LEVEL_DEBUG3: 382 txt = "debug3"; 383 pri = LOG_DEBUG; 384 break; 385 default: 386 txt = "internal error"; 387 pri = LOG_ERR; 388 break; 389 } 390 if (txt != NULL && log_handler == NULL) { 391 snprintf(fmtbuf, sizeof(fmtbuf), "%s: %s", txt, fmt); 392 vsnprintf(msgbuf, sizeof(msgbuf), fmtbuf, args); 393 } else { 394 vsnprintf(msgbuf, sizeof(msgbuf), fmt, args); 395 } 396 if (suffix != NULL) { 397 snprintf(fmtbuf, sizeof(fmtbuf), "%s: %s", msgbuf, suffix); 398 strlcpy(msgbuf, fmtbuf, sizeof(msgbuf)); 399 } 400 strnvis(fmtbuf, msgbuf, sizeof(fmtbuf), 401 log_on_stderr ? LOG_STDERR_VIS : LOG_SYSLOG_VIS); 402 if (log_handler != NULL) { 403 /* Avoid recursion */ 404 tmp_handler = log_handler; 405 log_handler = NULL; 406 tmp_handler(level, force, fmtbuf, log_handler_ctx); 407 log_handler = tmp_handler; 408 } else if (log_on_stderr) { 409 snprintf(msgbuf, sizeof msgbuf, "%s%s%.*s\r\n", 410 (log_on_stderr > 1) ? progname : "", 411 (log_on_stderr > 1) ? ": " : "", 412 (int)sizeof msgbuf - 3, fmtbuf); 413 (void)write(log_stderr_fd, msgbuf, strlen(msgbuf)); 414 } else { 415 #if defined(HAVE_OPENLOG_R) && defined(SYSLOG_DATA_INIT) 416 openlog_r(progname, LOG_PID, log_facility, &sdata); 417 syslog_r(pri, &sdata, "%.500s", fmtbuf); 418 closelog_r(&sdata); 419 #else 420 openlog(progname, LOG_PID, log_facility); 421 syslog(pri, "%.500s", fmtbuf); 422 closelog(); 423 #endif 424 } 425 errno = saved_errno; 426 } 427 428 void 429 sshlog(const char *file, const char *func, int line, int showfunc, 430 LogLevel level, const char *suffix, const char *fmt, ...) 431 { 432 va_list args; 433 434 va_start(args, fmt); 435 sshlogv(file, func, line, showfunc, level, suffix, fmt, args); 436 va_end(args); 437 } 438 439 void 440 sshlogdie(const char *file, const char *func, int line, int showfunc, 441 LogLevel level, const char *suffix, const char *fmt, ...) 442 { 443 va_list args; 444 445 va_start(args, fmt); 446 sshlogv(file, func, line, showfunc, SYSLOG_LEVEL_INFO, 447 suffix, fmt, args); 448 va_end(args); 449 cleanup_exit(255); 450 } 451 452 void 453 sshlogv(const char *file, const char *func, int line, int showfunc, 454 LogLevel level, const char *suffix, const char *fmt, va_list args) 455 { 456 char tag[128], fmt2[MSGBUFSIZ + 128]; 457 int forced = 0; 458 const char *cp; 459 size_t i; 460 461 /* short circuit processing early if we're not going to log anything */ 462 if (nlog_verbose == 0 && level > log_level) 463 return; 464 465 snprintf(tag, sizeof(tag), "%.48s:%.48s():%d (bin=%s, pid=%ld)", 466 (cp = strrchr(file, '/')) == NULL ? file : cp + 1, func, line, 467 argv0 == NULL ? "UNKNOWN" : argv0, (long)getpid()); 468 for (i = 0; i < nlog_verbose; i++) { 469 if (match_pattern_list(tag, log_verbose[i], 0) == 1) { 470 forced = 1; 471 break; 472 } 473 } 474 475 if (forced) 476 snprintf(fmt2, sizeof(fmt2), "%s: %s", tag, fmt); 477 else if (showfunc) 478 snprintf(fmt2, sizeof(fmt2), "%s: %s", func, fmt); 479 else 480 strlcpy(fmt2, fmt, sizeof(fmt2)); 481 482 do_log(level, forced, suffix, fmt2, args); 483 } 484 485 void 486 sshlogdirect(LogLevel level, int forced, const char *fmt, ...) 487 { 488 va_list args; 489 490 va_start(args, fmt); 491 do_log(level, forced, NULL, fmt, args); 492 va_end(args); 493 } 494 495 496 /* 497 * A simple system for ratelimiting aperiodic events such as logs, without 498 * needing to be hooked into a mainloop/timer. A running total of events is 499 * maintained and when it exceeds a threshold further events are dropped 500 * until the rate falls back below that threshold. 501 * 502 * To prevent flipping in and out of rate-limiting, there is a hysteresis 503 * timer that delays leaving the rate-limited state. 504 * 505 * While in the rate-limited state, events can be periodically allowed though 506 * and the number of dropped events since the last log obtained. 507 * 508 * XXX a moving average rate of events might be a better approach here rather 509 * than linear decay, which can suppress events for a while after large 510 * bursts. 511 */ 512 513 /* #define RATELIMIT_DEBUG 1 */ 514 515 #ifdef RATELIMIT_DEBUG 516 # define RLDBG(x) do { \ 517 printf("%s:%d %s: ", __FILE__, __LINE__, __func__); \ 518 printf x; \ 519 printf("\n"); \ 520 fflush(stdout); \ 521 } while (0) 522 #else 523 # define RLDBG(x) 524 #endif 525 526 /* set up a ratelimit */ 527 void 528 log_ratelimit_init(struct log_ratelimit_ctx *rl, u_int threshold, 529 u_int max_accum, u_int hysteresis, u_int log_every) 530 { 531 memset(rl, 0, sizeof(*rl)); 532 rl->threshold = threshold; 533 rl->max_accum = max_accum; 534 rl->hysteresis = hysteresis; 535 rl->log_every = log_every; 536 RLDBG(("called: rl=%p thresh=%u max=%u hys=%u log_every=%u", 537 rl, rl->threshold, rl->max_accum, rl->hysteresis, rl->log_every)); 538 } 539 540 /* 541 * check whether a log event should be dropped because of rate-limiting. 542 * returns non-zero if the event should be dropped. If events_since_last 543 * is supplied then, for periodic logs, it will be set to the number of 544 * dropped events since the last message. 545 */ 546 int 547 log_ratelimit(struct log_ratelimit_ctx *rl, time_t now, int *active, 548 u_int *events_dropped) 549 { 550 time_t olast_event; 551 552 RLDBG(("called: rl=%p thresh=%u max=%u hys=%u log_every=%u " 553 "accum=%u since=%ld since_last=%u", rl, rl->threshold, 554 rl->max_accum, rl->hysteresis, 555 rl->log_every, rl->accumulated_events, 556 rl->last_event == 0 ? -1 : (long)(now - rl->last_event), 557 rl->ratelimited_events)); 558 559 if (now < 0) 560 return 0; 561 if (events_dropped != NULL) 562 *events_dropped = 0; 563 if (active != NULL) 564 *active = rl->ratelimit_active; 565 566 /* First, decay accumulated events */ 567 if (rl->last_event <= 0) 568 rl->last_event = now; 569 if (now > rl->last_event) { 570 uint64_t n = now - rl->last_event; 571 572 if (n > UINT_MAX) 573 n = UINT_MAX; 574 if (rl->accumulated_events < (u_int)n) 575 rl->accumulated_events = 0; 576 else 577 rl->accumulated_events -= (u_int)n; 578 RLDBG(("decay: accum=%u", rl->accumulated_events)); 579 } 580 rl->accumulated_events++; /* add this event */ 581 if (rl->accumulated_events > rl->max_accum) 582 rl->accumulated_events = rl->max_accum; 583 olast_event = rl->last_event; 584 rl->last_event = now; 585 RLDBG(("check threshold: accum=%u vs thresh=%u", 586 rl->accumulated_events, rl->threshold)); 587 588 /* Are we under threshold? */ 589 if (rl->accumulated_events < rl->threshold) { 590 if (!rl->ratelimit_active) 591 return 0; 592 RLDBG(("under threshold: hys=%u since_hys=%ld since_last=%ld", 593 rl->hysteresis, rl->hysteresis_start == 0 ? -1 : 594 (long)(now - rl->hysteresis_start), 595 olast_event == 0 ? -1 : (long)(now - olast_event))); 596 if (rl->hysteresis_start == 0) { 597 /* active, but under threshold; hysteresis */ 598 if (olast_event + rl->hysteresis < now) { 599 /* hysteresis expired before this event */ 600 RLDBG(("hysteresis preexpired")); 601 goto inactive; 602 } 603 RLDBG(("start hysteresis")); 604 rl->hysteresis_start = now; 605 } else if (rl->hysteresis_start + rl->hysteresis < now) { 606 /* Hysteresis period expired, transition to inactive */ 607 RLDBG(("complete hysteresis")); 608 inactive: 609 if (events_dropped != NULL) 610 *events_dropped = rl->ratelimited_events; 611 if (active != NULL) 612 *active = 0; 613 rl->ratelimit_active = 0; 614 rl->ratelimit_start = 0; 615 rl->last_log = 0; 616 rl->hysteresis_start = 0; 617 rl->ratelimited_events = 0; 618 return 0; 619 } 620 /* ratelimiting active, but in hysteresis period */ 621 } else if (!rl->ratelimit_active) { 622 /* Transition to rate-limiting */ 623 RLDBG(("start ratelimit")); 624 rl->ratelimit_active = 1; 625 rl->ratelimit_start = now; 626 rl->last_log = now; 627 rl->hysteresis_start = 0; 628 rl->ratelimited_events = 1; 629 if (active != NULL) 630 *active = 1; 631 return 1; 632 } else if (rl->hysteresis_start != 0) { 633 /* active and over threshold; reset hysteresis timer */ 634 RLDBG(("clear hysteresis")); 635 rl->hysteresis_start = 0; 636 } 637 638 /* over threshold or in hysteresis period; log periodically */ 639 if (active != NULL) 640 *active = 1; 641 RLDBG(("log_every=%u since_log=%ld", rl->log_every, 642 (long)(now - rl->last_log))); 643 if (rl->log_every > 0 && now >= rl->last_log + rl->log_every) { 644 RLDBG(("periodic: since_last=%u", rl->ratelimited_events)); 645 rl->last_log = now; 646 if (events_dropped != NULL) { 647 *events_dropped = rl->ratelimited_events; 648 rl->ratelimited_events = 0; 649 } 650 return 0; 651 } 652 653 /* drop event */ 654 rl->ratelimited_events++; 655 RLDBG(("drop: ratelimited_events=%u", rl->ratelimited_events)); 656 return 1; 657 } 658