1 /* $NetBSD: log.c,v 1.11 2024/09/22 00:14:08 christos Exp $ */ 2 3 /* 4 * Copyright (C) Internet Systems Consortium, Inc. ("ISC") 5 * 6 * SPDX-License-Identifier: MPL-2.0 7 * 8 * This Source Code Form is subject to the terms of the Mozilla Public 9 * License, v. 2.0. If a copy of the MPL was not distributed with this 10 * file, you can obtain one at https://mozilla.org/MPL/2.0/. 11 * 12 * See the COPYRIGHT file distributed with this work for additional 13 * information regarding copyright ownership. 14 */ 15 16 /*! \file */ 17 18 #include <errno.h> 19 #include <inttypes.h> 20 #include <limits.h> 21 #include <stdbool.h> 22 #include <stdlib.h> 23 #include <sys/types.h> /* dev_t FreeBSD 2.1 */ 24 #include <time.h> 25 #include <unistd.h> 26 27 #include <isc/atomic.h> 28 #include <isc/dir.h> 29 #include <isc/errno.h> 30 #include <isc/file.h> 31 #include <isc/log.h> 32 #include <isc/magic.h> 33 #include <isc/mem.h> 34 #include <isc/print.h> 35 #include <isc/rwlock.h> 36 #include <isc/stat.h> 37 #include <isc/stdio.h> 38 #include <isc/string.h> 39 #include <isc/thread.h> 40 #include <isc/time.h> 41 #include <isc/util.h> 42 43 #define LCTX_MAGIC ISC_MAGIC('L', 'c', 't', 'x') 44 #define VALID_CONTEXT(lctx) ISC_MAGIC_VALID(lctx, LCTX_MAGIC) 45 46 #define LCFG_MAGIC ISC_MAGIC('L', 'c', 'f', 'g') 47 #define VALID_CONFIG(lcfg) ISC_MAGIC_VALID(lcfg, LCFG_MAGIC) 48 49 #define RDLOCK(lp) RWLOCK(lp, isc_rwlocktype_read); 50 #define WRLOCK(lp) RWLOCK(lp, isc_rwlocktype_write); 51 #define RDUNLOCK(lp) RWUNLOCK(lp, isc_rwlocktype_read); 52 #define WRUNLOCK(lp) RWUNLOCK(lp, isc_rwlocktype_write); 53 54 static thread_local bool forcelog = false; 55 56 /* 57 * XXXDCL make dynamic? 58 */ 59 #define LOG_BUFFER_SIZE (8 * 1024) 60 61 /*! 62 * This is the structure that holds each named channel. A simple linked 63 * list chains all of the channels together, so an individual channel is 64 * found by doing strcmp()s with the names down the list. Their should 65 * be no performance penalty from this as it is expected that the number 66 * of named channels will be no more than a dozen or so, and name lookups 67 * from the head of the list are only done when isc_log_usechannel() is 68 * called, which should also be very infrequent. 69 */ 70 typedef struct isc_logchannel isc_logchannel_t; 71 72 struct isc_logchannel { 73 char *name; 74 unsigned int type; 75 int level; 76 unsigned int flags; 77 isc_logdestination_t destination; 78 ISC_LINK(isc_logchannel_t) link; 79 }; 80 81 /*! 82 * The logchannellist structure associates categories and modules with 83 * channels. First the appropriate channellist is found based on the 84 * category, and then each structure in the linked list is checked for 85 * a matching module. It is expected that the number of channels 86 * associated with any given category will be very short, no more than 87 * three or four in the more unusual cases. 88 */ 89 typedef struct isc_logchannellist isc_logchannellist_t; 90 91 struct isc_logchannellist { 92 const isc_logmodule_t *module; 93 isc_logchannel_t *channel; 94 ISC_LINK(isc_logchannellist_t) link; 95 }; 96 97 /*! 98 * This structure is used to remember messages for pruning via 99 * isc_log_[v]write1(). 100 */ 101 typedef struct isc_logmessage isc_logmessage_t; 102 103 struct isc_logmessage { 104 char *text; 105 isc_time_t time; 106 ISC_LINK(isc_logmessage_t) link; 107 }; 108 109 /*! 110 * The isc_logconfig structure is used to store the configurable information 111 * about where messages are actually supposed to be sent -- the information 112 * that could changed based on some configuration file, as opposed to the 113 * the category/module specification of isc_log_[v]write[1] that is compiled 114 * into a program, or the debug_level which is dynamic state information. 115 */ 116 struct isc_logconfig { 117 unsigned int magic; 118 isc_log_t *lctx; 119 ISC_LIST(isc_logchannel_t) channels; 120 ISC_LIST(isc_logchannellist_t) * channellists; 121 unsigned int channellist_count; 122 unsigned int duplicate_interval; 123 int_fast32_t highest_level; 124 char *tag; 125 bool dynamic; 126 }; 127 128 /*! 129 * This isc_log structure provides the context for the isc_log functions. 130 * The log context locks itself in isc_log_doit, the internal backend to 131 * isc_log_write. The locking is necessary both to provide exclusive access 132 * to the buffer into which the message is formatted and to guard against 133 * competing threads trying to write to the same syslog resource. (On 134 * some systems, such as BSD/OS, stdio is thread safe but syslog is not.) 135 * Unfortunately, the lock cannot guard against a _different_ logging 136 * context in the same program competing for syslog's attention. Thus 137 * There Can Be Only One, but this is not enforced. 138 * XXXDCL enforce it? 139 * 140 * Note that the category and module information is not locked. 141 * This is because in the usual case, only one isc_log_t is ever created 142 * in a program, and the category/module registration happens only once. 143 * XXXDCL it might be wise to add more locking overall. 144 */ 145 struct isc_log { 146 /* Not locked. */ 147 unsigned int magic; 148 isc_mem_t *mctx; 149 isc_logcategory_t *categories; 150 unsigned int category_count; 151 isc_logmodule_t *modules; 152 unsigned int module_count; 153 atomic_int_fast32_t debug_level; 154 isc_rwlock_t lcfg_rwl; 155 /* Locked by isc_log lcfg_rwl */ 156 isc_logconfig_t *logconfig; 157 isc_mutex_t lock; 158 /* Locked by isc_log lock. */ 159 char buffer[LOG_BUFFER_SIZE]; 160 ISC_LIST(isc_logmessage_t) messages; 161 atomic_bool dynamic; 162 atomic_int_fast32_t highest_level; 163 }; 164 165 /*! 166 * Used when ISC_LOG_PRINTLEVEL is enabled for a channel. 167 */ 168 static const char *log_level_strings[] = { "debug", "info", "notice", 169 "warning", "error", "critical" }; 170 171 /*! 172 * Used to convert ISC_LOG_* priorities into syslog priorities. 173 * XXXDCL This will need modification for NT. 174 */ 175 static const int syslog_map[] = { LOG_DEBUG, LOG_INFO, LOG_NOTICE, 176 LOG_WARNING, LOG_ERR, LOG_CRIT }; 177 178 /*! 179 * When adding new categories, a corresponding ISC_LOGCATEGORY_foo 180 * definition needs to be added to <isc/log.h>. 181 * 182 * The default category is provided so that the internal default can 183 * be overridden. Since the default is always looked up as the first 184 * channellist in the log context, it must come first in isc_categories[]. 185 */ 186 isc_logcategory_t isc_categories[] = { { "default", 0 }, /* "default 187 must come 188 first. */ 189 { "general", 0 }, 190 { "sslkeylog", 0 }, 191 { NULL, 0 } }; 192 193 /*! 194 * See above comment for categories, and apply it to modules. 195 */ 196 isc_logmodule_t isc_modules[] = { { "socket", 0 }, { "time", 0 }, 197 { "interface", 0 }, { "timer", 0 }, 198 { "file", 0 }, { "netmgr", 0 }, 199 { "other", 0 }, { NULL, 0 } }; 200 201 /*! 202 * This essentially constant structure must be filled in at run time, 203 * because its channel member is pointed to a channel that is created 204 * dynamically with isc_log_createchannel. 205 */ 206 static isc_logchannellist_t default_channel; 207 208 /*! 209 * libisc logs to this context. 210 */ 211 isc_log_t *isc_lctx = NULL; 212 213 /*! 214 * Forward declarations. 215 */ 216 static void 217 assignchannel(isc_logconfig_t *lcfg, unsigned int category_id, 218 const isc_logmodule_t *module, isc_logchannel_t *channel); 219 220 static void 221 sync_channellist(isc_logconfig_t *lcfg); 222 223 static void 224 sync_highest_level(isc_log_t *lctx, isc_logconfig_t *lcfg); 225 226 static isc_result_t 227 greatest_version(isc_logfile_t *file, int versions, int *greatest); 228 229 static void 230 isc_log_doit(isc_log_t *lctx, isc_logcategory_t *category, 231 isc_logmodule_t *module, int level, bool write_once, 232 const char *format, va_list args) ISC_FORMAT_PRINTF(6, 0); 233 234 /*@{*/ 235 /*! 236 * Convenience macros. 237 */ 238 239 #define FACILITY(channel) (channel->destination.facility) 240 #define FILE_NAME(channel) (channel->destination.file.name) 241 #define FILE_STREAM(channel) (channel->destination.file.stream) 242 #define FILE_VERSIONS(channel) (channel->destination.file.versions) 243 #define FILE_SUFFIX(channel) (channel->destination.file.suffix) 244 #define FILE_MAXSIZE(channel) (channel->destination.file.maximum_size) 245 #define FILE_MAXREACHED(channel) (channel->destination.file.maximum_reached) 246 247 /*@}*/ 248 /**** 249 **** Public interfaces. 250 ****/ 251 252 /* 253 * Establish a new logging context, with default channels. 254 */ 255 void 256 isc_log_create(isc_mem_t *mctx, isc_log_t **lctxp, isc_logconfig_t **lcfgp) { 257 isc_log_t *lctx; 258 isc_logconfig_t *lcfg = NULL; 259 260 REQUIRE(mctx != NULL); 261 REQUIRE(lctxp != NULL && *lctxp == NULL); 262 REQUIRE(lcfgp == NULL || *lcfgp == NULL); 263 264 lctx = isc_mem_get(mctx, sizeof(*lctx)); 265 lctx->mctx = NULL; 266 isc_mem_attach(mctx, &lctx->mctx); 267 lctx->categories = NULL; 268 lctx->category_count = 0; 269 lctx->modules = NULL; 270 lctx->module_count = 0; 271 atomic_init(&lctx->debug_level, 0); 272 273 ISC_LIST_INIT(lctx->messages); 274 275 isc_mutex_init(&lctx->lock); 276 isc_rwlock_init(&lctx->lcfg_rwl, 0, 0); 277 278 /* 279 * Normally setting the magic number is the last step done 280 * in a creation function, but a valid log context is needed 281 * by isc_log_registercategories and isc_logconfig_create. 282 * If either fails, the lctx is destroyed and not returned 283 * to the caller. 284 */ 285 lctx->magic = LCTX_MAGIC; 286 287 isc_log_registercategories(lctx, isc_categories); 288 isc_log_registermodules(lctx, isc_modules); 289 isc_logconfig_create(lctx, &lcfg); 290 291 sync_channellist(lcfg); 292 293 lctx->logconfig = lcfg; 294 295 atomic_init(&lctx->highest_level, lcfg->highest_level); 296 atomic_init(&lctx->dynamic, lcfg->dynamic); 297 298 *lctxp = lctx; 299 if (lcfgp != NULL) { 300 *lcfgp = lcfg; 301 } 302 } 303 304 void 305 isc_logconfig_create(isc_log_t *lctx, isc_logconfig_t **lcfgp) { 306 isc_logconfig_t *lcfg; 307 isc_logdestination_t destination; 308 int level = ISC_LOG_INFO; 309 310 REQUIRE(lcfgp != NULL && *lcfgp == NULL); 311 REQUIRE(VALID_CONTEXT(lctx)); 312 313 lcfg = isc_mem_get(lctx->mctx, sizeof(*lcfg)); 314 315 lcfg->lctx = lctx; 316 lcfg->channellists = NULL; 317 lcfg->channellist_count = 0; 318 lcfg->duplicate_interval = 0; 319 lcfg->highest_level = level; 320 lcfg->tag = NULL; 321 lcfg->dynamic = false; 322 ISC_LIST_INIT(lcfg->channels); 323 lcfg->magic = LCFG_MAGIC; 324 325 /* 326 * Create the default channels: 327 * default_syslog, default_stderr, default_debug and null. 328 */ 329 destination.facility = LOG_DAEMON; 330 isc_log_createchannel(lcfg, "default_syslog", ISC_LOG_TOSYSLOG, level, 331 &destination, 0); 332 333 destination.file.stream = stderr; 334 destination.file.name = NULL; 335 destination.file.versions = ISC_LOG_ROLLNEVER; 336 destination.file.suffix = isc_log_rollsuffix_increment; 337 destination.file.maximum_size = 0; 338 isc_log_createchannel(lcfg, "default_stderr", ISC_LOG_TOFILEDESC, level, 339 &destination, ISC_LOG_PRINTTIME); 340 341 /* 342 * Set the default category's channel to default_stderr, 343 * which is at the head of the channels list because it was 344 * just created. 345 */ 346 default_channel.channel = ISC_LIST_HEAD(lcfg->channels); 347 348 destination.file.stream = stderr; 349 destination.file.name = NULL; 350 destination.file.versions = ISC_LOG_ROLLNEVER; 351 destination.file.suffix = isc_log_rollsuffix_increment; 352 destination.file.maximum_size = 0; 353 isc_log_createchannel(lcfg, "default_debug", ISC_LOG_TOFILEDESC, 354 ISC_LOG_DYNAMIC, &destination, ISC_LOG_PRINTTIME); 355 356 isc_log_createchannel(lcfg, "null", ISC_LOG_TONULL, ISC_LOG_DYNAMIC, 357 NULL, 0); 358 359 *lcfgp = lcfg; 360 } 361 362 void 363 isc_logconfig_use(isc_log_t *lctx, isc_logconfig_t *lcfg) { 364 isc_logconfig_t *old_cfg; 365 366 REQUIRE(VALID_CONTEXT(lctx)); 367 REQUIRE(VALID_CONFIG(lcfg)); 368 REQUIRE(lcfg->lctx == lctx); 369 370 /* 371 * Ensure that lcfg->channellist_count == lctx->category_count. 372 * They won't be equal if isc_log_usechannel has not been called 373 * since any call to isc_log_registercategories. 374 */ 375 sync_channellist(lcfg); 376 377 WRLOCK(&lctx->lcfg_rwl); 378 old_cfg = lctx->logconfig; 379 lctx->logconfig = lcfg; 380 sync_highest_level(lctx, lcfg); 381 WRUNLOCK(&lctx->lcfg_rwl); 382 383 isc_logconfig_destroy(&old_cfg); 384 } 385 386 void 387 isc_log_destroy(isc_log_t **lctxp) { 388 isc_log_t *lctx; 389 isc_logconfig_t *lcfg; 390 isc_mem_t *mctx; 391 isc_logmessage_t *message; 392 393 REQUIRE(lctxp != NULL && VALID_CONTEXT(*lctxp)); 394 395 lctx = *lctxp; 396 *lctxp = NULL; 397 mctx = lctx->mctx; 398 399 /* Stop the logging as a first thing */ 400 atomic_store_release(&lctx->debug_level, 0); 401 atomic_store_release(&lctx->highest_level, 0); 402 atomic_store_release(&lctx->dynamic, false); 403 404 WRLOCK(&lctx->lcfg_rwl); 405 lcfg = lctx->logconfig; 406 lctx->logconfig = NULL; 407 WRUNLOCK(&lctx->lcfg_rwl); 408 409 if (lcfg != NULL) { 410 isc_logconfig_destroy(&lcfg); 411 } 412 413 isc_rwlock_destroy(&lctx->lcfg_rwl); 414 isc_mutex_destroy(&lctx->lock); 415 416 while ((message = ISC_LIST_HEAD(lctx->messages)) != NULL) { 417 ISC_LIST_UNLINK(lctx->messages, message, link); 418 419 isc_mem_put(mctx, message, 420 sizeof(*message) + strlen(message->text) + 1); 421 } 422 423 lctx->buffer[0] = '\0'; 424 lctx->categories = NULL; 425 lctx->category_count = 0; 426 lctx->modules = NULL; 427 lctx->module_count = 0; 428 lctx->mctx = NULL; 429 lctx->magic = 0; 430 431 isc_mem_putanddetach(&mctx, lctx, sizeof(*lctx)); 432 } 433 434 void 435 isc_logconfig_destroy(isc_logconfig_t **lcfgp) { 436 isc_logconfig_t *lcfg; 437 isc_mem_t *mctx; 438 isc_logchannel_t *channel; 439 char *filename; 440 unsigned int i; 441 442 REQUIRE(lcfgp != NULL && VALID_CONFIG(*lcfgp)); 443 444 lcfg = *lcfgp; 445 *lcfgp = NULL; 446 447 /* 448 * This function cannot be called with a logconfig that is in 449 * use by a log context. 450 */ 451 REQUIRE(lcfg->lctx != NULL); 452 453 RDLOCK(&lcfg->lctx->lcfg_rwl); 454 REQUIRE(lcfg->lctx->logconfig != lcfg); 455 RDUNLOCK(&lcfg->lctx->lcfg_rwl); 456 457 mctx = lcfg->lctx->mctx; 458 459 while ((channel = ISC_LIST_HEAD(lcfg->channels)) != NULL) { 460 ISC_LIST_UNLINK(lcfg->channels, channel, link); 461 462 if (channel->type == ISC_LOG_TOFILE) { 463 /* 464 * The filename for the channel may have ultimately 465 * started its life in user-land as a const string, 466 * but in isc_log_createchannel it gets copied 467 * into writable memory and is not longer truly const. 468 */ 469 DE_CONST(FILE_NAME(channel), filename); 470 isc_mem_free(mctx, filename); 471 472 if (FILE_STREAM(channel) != NULL) { 473 (void)fclose(FILE_STREAM(channel)); 474 } 475 } 476 477 isc_mem_free(mctx, channel->name); 478 isc_mem_put(mctx, channel, sizeof(*channel)); 479 } 480 481 for (i = 0; i < lcfg->channellist_count; i++) { 482 isc_logchannellist_t *item; 483 while ((item = ISC_LIST_HEAD(lcfg->channellists[i])) != NULL) { 484 ISC_LIST_UNLINK(lcfg->channellists[i], item, link); 485 isc_mem_put(mctx, item, sizeof(*item)); 486 } 487 } 488 489 if (lcfg->channellist_count > 0) { 490 isc_mem_put(mctx, lcfg->channellists, 491 lcfg->channellist_count * 492 sizeof(ISC_LIST(isc_logchannellist_t))); 493 } 494 495 lcfg->dynamic = false; 496 if (lcfg->tag != NULL) { 497 isc_mem_free(lcfg->lctx->mctx, lcfg->tag); 498 } 499 lcfg->tag = NULL; 500 lcfg->highest_level = 0; 501 lcfg->duplicate_interval = 0; 502 lcfg->magic = 0; 503 504 isc_mem_put(mctx, lcfg, sizeof(*lcfg)); 505 } 506 507 void 508 isc_log_registercategories(isc_log_t *lctx, isc_logcategory_t categories[]) { 509 isc_logcategory_t *catp; 510 511 REQUIRE(VALID_CONTEXT(lctx)); 512 REQUIRE(categories != NULL && categories[0].name != NULL); 513 514 /* 515 * XXXDCL This somewhat sleazy situation of using the last pointer 516 * in one category array to point to the next array exists because 517 * this registration function returns void and I didn't want to have 518 * change everything that used it by making it return an isc_result_t. 519 * It would need to do that if it had to allocate memory to store 520 * pointers to each array passed in. 521 */ 522 if (lctx->categories == NULL) { 523 lctx->categories = categories; 524 } else { 525 /* 526 * Adjust the last (NULL) pointer of the already registered 527 * categories to point to the incoming array. 528 */ 529 for (catp = lctx->categories; catp->name != NULL;) { 530 if (catp->id == UINT_MAX) { 531 /* 532 * The name pointer points to the next array. 533 * Ick. 534 */ 535 DE_CONST(catp->name, catp); 536 } else { 537 catp++; 538 } 539 } 540 541 catp->name = (void *)categories; 542 catp->id = UINT_MAX; 543 } 544 545 /* 546 * Update the id number of the category with its new global id. 547 */ 548 for (catp = categories; catp->name != NULL; catp++) { 549 catp->id = lctx->category_count++; 550 } 551 } 552 553 isc_logcategory_t * 554 isc_log_categorybyname(isc_log_t *lctx, const char *name) { 555 isc_logcategory_t *catp; 556 557 REQUIRE(VALID_CONTEXT(lctx)); 558 REQUIRE(name != NULL); 559 560 for (catp = lctx->categories; catp->name != NULL;) { 561 if (catp->id == UINT_MAX) { 562 /* 563 * catp is neither modified nor returned to the 564 * caller, so removing its const qualifier is ok. 565 */ 566 DE_CONST(catp->name, catp); 567 } else { 568 if (strcmp(catp->name, name) == 0) { 569 return (catp); 570 } 571 catp++; 572 } 573 } 574 575 return (NULL); 576 } 577 578 void 579 isc_log_registermodules(isc_log_t *lctx, isc_logmodule_t modules[]) { 580 isc_logmodule_t *modp; 581 582 REQUIRE(VALID_CONTEXT(lctx)); 583 REQUIRE(modules != NULL && modules[0].name != NULL); 584 585 /* 586 * XXXDCL This somewhat sleazy situation of using the last pointer 587 * in one category array to point to the next array exists because 588 * this registration function returns void and I didn't want to have 589 * change everything that used it by making it return an isc_result_t. 590 * It would need to do that if it had to allocate memory to store 591 * pointers to each array passed in. 592 */ 593 if (lctx->modules == NULL) { 594 lctx->modules = modules; 595 } else { 596 /* 597 * Adjust the last (NULL) pointer of the already registered 598 * modules to point to the incoming array. 599 */ 600 for (modp = lctx->modules; modp->name != NULL;) { 601 if (modp->id == UINT_MAX) { 602 /* 603 * The name pointer points to the next array. 604 * Ick. 605 */ 606 DE_CONST(modp->name, modp); 607 } else { 608 modp++; 609 } 610 } 611 612 modp->name = (void *)modules; 613 modp->id = UINT_MAX; 614 } 615 616 /* 617 * Update the id number of the module with its new global id. 618 */ 619 for (modp = modules; modp->name != NULL; modp++) { 620 modp->id = lctx->module_count++; 621 } 622 } 623 624 isc_logmodule_t * 625 isc_log_modulebyname(isc_log_t *lctx, const char *name) { 626 isc_logmodule_t *modp; 627 628 REQUIRE(VALID_CONTEXT(lctx)); 629 REQUIRE(name != NULL); 630 631 for (modp = lctx->modules; modp->name != NULL;) { 632 if (modp->id == UINT_MAX) { 633 /* 634 * modp is neither modified nor returned to the 635 * caller, so removing its const qualifier is ok. 636 */ 637 DE_CONST(modp->name, modp); 638 } else { 639 if (strcmp(modp->name, name) == 0) { 640 return (modp); 641 } 642 modp++; 643 } 644 } 645 646 return (NULL); 647 } 648 649 void 650 isc_log_createchannel(isc_logconfig_t *lcfg, const char *name, 651 unsigned int type, int level, 652 const isc_logdestination_t *destination, 653 unsigned int flags) { 654 isc_logchannel_t *channel; 655 isc_mem_t *mctx; 656 unsigned int permitted = ISC_LOG_PRINTALL | ISC_LOG_DEBUGONLY | 657 ISC_LOG_BUFFERED | ISC_LOG_ISO8601 | 658 ISC_LOG_UTC; 659 660 REQUIRE(VALID_CONFIG(lcfg)); 661 REQUIRE(name != NULL); 662 REQUIRE(type == ISC_LOG_TOSYSLOG || type == ISC_LOG_TOFILE || 663 type == ISC_LOG_TOFILEDESC || type == ISC_LOG_TONULL); 664 REQUIRE(destination != NULL || type == ISC_LOG_TONULL); 665 REQUIRE(level >= ISC_LOG_CRITICAL); 666 REQUIRE((flags & ~permitted) == 0); 667 668 /* XXXDCL find duplicate names? */ 669 670 mctx = lcfg->lctx->mctx; 671 672 channel = isc_mem_get(mctx, sizeof(*channel)); 673 674 channel->name = isc_mem_strdup(mctx, name); 675 676 channel->type = type; 677 channel->level = level; 678 channel->flags = flags; 679 ISC_LINK_INIT(channel, link); 680 681 switch (type) { 682 case ISC_LOG_TOSYSLOG: 683 FACILITY(channel) = destination->facility; 684 break; 685 686 case ISC_LOG_TOFILE: 687 /* 688 * The file name is copied because greatest_version wants 689 * to scribble on it, so it needs to be definitely in 690 * writable memory. 691 */ 692 FILE_NAME(channel) = isc_mem_strdup(mctx, 693 destination->file.name); 694 FILE_STREAM(channel) = NULL; 695 FILE_VERSIONS(channel) = destination->file.versions; 696 FILE_SUFFIX(channel) = destination->file.suffix; 697 FILE_MAXSIZE(channel) = destination->file.maximum_size; 698 FILE_MAXREACHED(channel) = false; 699 break; 700 701 case ISC_LOG_TOFILEDESC: 702 FILE_NAME(channel) = NULL; 703 FILE_STREAM(channel) = destination->file.stream; 704 FILE_MAXSIZE(channel) = 0; 705 FILE_VERSIONS(channel) = ISC_LOG_ROLLNEVER; 706 FILE_SUFFIX(channel) = isc_log_rollsuffix_increment; 707 break; 708 709 case ISC_LOG_TONULL: 710 /* Nothing. */ 711 break; 712 713 default: 714 UNREACHABLE(); 715 } 716 717 ISC_LIST_PREPEND(lcfg->channels, channel, link); 718 719 /* 720 * If default_stderr was redefined, make the default category 721 * point to the new default_stderr. 722 */ 723 if (strcmp(name, "default_stderr") == 0) { 724 default_channel.channel = channel; 725 } 726 } 727 728 isc_result_t 729 isc_log_usechannel(isc_logconfig_t *lcfg, const char *name, 730 const isc_logcategory_t *category, 731 const isc_logmodule_t *module) { 732 isc_log_t *lctx; 733 isc_logchannel_t *channel; 734 735 REQUIRE(VALID_CONFIG(lcfg)); 736 REQUIRE(name != NULL); 737 738 lctx = lcfg->lctx; 739 740 REQUIRE(category == NULL || category->id < lctx->category_count); 741 REQUIRE(module == NULL || module->id < lctx->module_count); 742 743 for (channel = ISC_LIST_HEAD(lcfg->channels); channel != NULL; 744 channel = ISC_LIST_NEXT(channel, link)) 745 { 746 if (strcmp(name, channel->name) == 0) { 747 break; 748 } 749 } 750 751 if (channel == NULL) { 752 return (ISC_R_NOTFOUND); 753 } 754 755 if (category != NULL) { 756 assignchannel(lcfg, category->id, module, channel); 757 } else { 758 /* 759 * Assign to all categories. Note that this includes 760 * the default channel. 761 */ 762 for (size_t i = 0; i < lctx->category_count; i++) { 763 assignchannel(lcfg, i, module, channel); 764 } 765 } 766 767 /* 768 * Update the highest logging level, if the current lcfg is in use. 769 */ 770 if (lcfg->lctx->logconfig == lcfg) { 771 sync_highest_level(lctx, lcfg); 772 } 773 774 return (ISC_R_SUCCESS); 775 } 776 777 void 778 isc_log_write(isc_log_t *lctx, isc_logcategory_t *category, 779 isc_logmodule_t *module, int level, const char *format, ...) { 780 va_list args; 781 782 /* 783 * Contract checking is done in isc_log_doit(). 784 */ 785 786 va_start(args, format); 787 isc_log_doit(lctx, category, module, level, false, format, args); 788 va_end(args); 789 } 790 791 void 792 isc_log_vwrite(isc_log_t *lctx, isc_logcategory_t *category, 793 isc_logmodule_t *module, int level, const char *format, 794 va_list args) { 795 /* 796 * Contract checking is done in isc_log_doit(). 797 */ 798 isc_log_doit(lctx, category, module, level, false, format, args); 799 } 800 801 void 802 isc_log_write1(isc_log_t *lctx, isc_logcategory_t *category, 803 isc_logmodule_t *module, int level, const char *format, ...) { 804 va_list args; 805 806 /* 807 * Contract checking is done in isc_log_doit(). 808 */ 809 810 va_start(args, format); 811 isc_log_doit(lctx, category, module, level, true, format, args); 812 va_end(args); 813 } 814 815 void 816 isc_log_vwrite1(isc_log_t *lctx, isc_logcategory_t *category, 817 isc_logmodule_t *module, int level, const char *format, 818 va_list args) { 819 /* 820 * Contract checking is done in isc_log_doit(). 821 */ 822 isc_log_doit(lctx, category, module, level, true, format, args); 823 } 824 825 void 826 isc_log_setcontext(isc_log_t *lctx) { 827 isc_lctx = lctx; 828 } 829 830 void 831 isc_log_setdebuglevel(isc_log_t *lctx, unsigned int level) { 832 REQUIRE(VALID_CONTEXT(lctx)); 833 834 atomic_store_release(&lctx->debug_level, level); 835 /* 836 * Close ISC_LOG_DEBUGONLY channels if level is zero. 837 */ 838 if (level == 0) { 839 RDLOCK(&lctx->lcfg_rwl); 840 isc_logconfig_t *lcfg = lctx->logconfig; 841 if (lcfg != NULL) { 842 LOCK(&lctx->lock); 843 for (isc_logchannel_t *channel = 844 ISC_LIST_HEAD(lcfg->channels); 845 channel != NULL; 846 channel = ISC_LIST_NEXT(channel, link)) 847 { 848 if (channel->type == ISC_LOG_TOFILE && 849 (channel->flags & ISC_LOG_DEBUGONLY) != 0 && 850 FILE_STREAM(channel) != NULL) 851 { 852 (void)fclose(FILE_STREAM(channel)); 853 FILE_STREAM(channel) = NULL; 854 } 855 } 856 UNLOCK(&lctx->lock); 857 } 858 RDUNLOCK(&lctx->lcfg_rwl); 859 } 860 } 861 862 unsigned int 863 isc_log_getdebuglevel(isc_log_t *lctx) { 864 REQUIRE(VALID_CONTEXT(lctx)); 865 866 return (atomic_load_acquire(&lctx->debug_level)); 867 } 868 869 void 870 isc_log_setduplicateinterval(isc_logconfig_t *lcfg, unsigned int interval) { 871 REQUIRE(VALID_CONFIG(lcfg)); 872 873 lcfg->duplicate_interval = interval; 874 } 875 876 unsigned int 877 isc_log_getduplicateinterval(isc_logconfig_t *lcfg) { 878 REQUIRE(VALID_CONTEXT(lcfg)); 879 880 return (lcfg->duplicate_interval); 881 } 882 883 void 884 isc_log_settag(isc_logconfig_t *lcfg, const char *tag) { 885 REQUIRE(VALID_CONFIG(lcfg)); 886 887 if (tag != NULL && *tag != '\0') { 888 if (lcfg->tag != NULL) { 889 isc_mem_free(lcfg->lctx->mctx, lcfg->tag); 890 } 891 lcfg->tag = isc_mem_strdup(lcfg->lctx->mctx, tag); 892 } else { 893 if (lcfg->tag != NULL) { 894 isc_mem_free(lcfg->lctx->mctx, lcfg->tag); 895 } 896 lcfg->tag = NULL; 897 } 898 } 899 900 char * 901 isc_log_gettag(isc_logconfig_t *lcfg) { 902 REQUIRE(VALID_CONFIG(lcfg)); 903 904 return (lcfg->tag); 905 } 906 907 /* XXXDCL NT -- This interface will assuredly be changing. */ 908 void 909 isc_log_opensyslog(const char *tag, int options, int facility) { 910 (void)openlog(tag, options, facility); 911 } 912 913 void 914 isc_log_closefilelogs(isc_log_t *lctx) { 915 REQUIRE(VALID_CONTEXT(lctx)); 916 917 RDLOCK(&lctx->lcfg_rwl); 918 isc_logconfig_t *lcfg = lctx->logconfig; 919 if (lcfg != NULL) { 920 LOCK(&lctx->lock); 921 for (isc_logchannel_t *channel = ISC_LIST_HEAD(lcfg->channels); 922 channel != NULL; channel = ISC_LIST_NEXT(channel, link)) 923 { 924 if (channel->type == ISC_LOG_TOFILE && 925 FILE_STREAM(channel) != NULL) 926 { 927 (void)fclose(FILE_STREAM(channel)); 928 FILE_STREAM(channel) = NULL; 929 } 930 } 931 UNLOCK(&lctx->lock); 932 } 933 RDUNLOCK(&lctx->lcfg_rwl); 934 } 935 936 /**** 937 **** Internal functions 938 ****/ 939 940 static void 941 assignchannel(isc_logconfig_t *lcfg, unsigned int category_id, 942 const isc_logmodule_t *module, isc_logchannel_t *channel) { 943 isc_logchannellist_t *new_item; 944 isc_log_t *lctx; 945 946 REQUIRE(VALID_CONFIG(lcfg)); 947 948 lctx = lcfg->lctx; 949 950 REQUIRE(category_id < lctx->category_count); 951 REQUIRE(module == NULL || module->id < lctx->module_count); 952 REQUIRE(channel != NULL); 953 954 /* 955 * Ensure lcfg->channellist_count == lctx->category_count. 956 */ 957 sync_channellist(lcfg); 958 959 new_item = isc_mem_get(lctx->mctx, sizeof(*new_item)); 960 961 new_item->channel = channel; 962 new_item->module = module; 963 ISC_LIST_INITANDPREPEND(lcfg->channellists[category_id], new_item, 964 link); 965 966 /* 967 * Remember the highest logging level set by any channel in the 968 * logging config, so isc_log_doit() can quickly return if the 969 * message is too high to be logged by any channel. 970 */ 971 if (channel->type != ISC_LOG_TONULL) { 972 if (lcfg->highest_level < channel->level) { 973 lcfg->highest_level = channel->level; 974 } 975 if (channel->level == ISC_LOG_DYNAMIC) { 976 lcfg->dynamic = true; 977 } 978 } 979 } 980 981 /* 982 * This would ideally be part of isc_log_registercategories(), except then 983 * that function would have to return isc_result_t instead of void. 984 */ 985 static void 986 sync_channellist(isc_logconfig_t *lcfg) { 987 unsigned int bytes; 988 isc_log_t *lctx; 989 void *lists; 990 991 REQUIRE(VALID_CONFIG(lcfg)); 992 993 lctx = lcfg->lctx; 994 995 REQUIRE(lctx->category_count != 0); 996 997 if (lctx->category_count == lcfg->channellist_count) { 998 return; 999 } 1000 1001 bytes = lctx->category_count * sizeof(ISC_LIST(isc_logchannellist_t)); 1002 1003 lists = isc_mem_get(lctx->mctx, bytes); 1004 1005 memset(lists, 0, bytes); 1006 1007 if (lcfg->channellist_count != 0) { 1008 bytes = lcfg->channellist_count * 1009 sizeof(ISC_LIST(isc_logchannellist_t)); 1010 memmove(lists, lcfg->channellists, bytes); 1011 isc_mem_put(lctx->mctx, lcfg->channellists, bytes); 1012 } 1013 1014 lcfg->channellists = lists; 1015 lcfg->channellist_count = lctx->category_count; 1016 } 1017 1018 static void 1019 sync_highest_level(isc_log_t *lctx, isc_logconfig_t *lcfg) { 1020 atomic_store(&lctx->highest_level, lcfg->highest_level); 1021 atomic_store(&lctx->dynamic, lcfg->dynamic); 1022 } 1023 1024 static isc_result_t 1025 greatest_version(isc_logfile_t *file, int versions, int *greatestp) { 1026 char *digit_end; 1027 char dirbuf[PATH_MAX + 1]; 1028 const char *bname; 1029 const char *dirname = "."; 1030 int version, greatest = -1; 1031 isc_dir_t dir; 1032 isc_result_t result; 1033 size_t bnamelen; 1034 1035 bname = strrchr(file->name, '/'); 1036 if (bname != NULL) { 1037 /* 1038 * Copy the complete file name to dirbuf. 1039 */ 1040 size_t len = strlcpy(dirbuf, file->name, sizeof(dirbuf)); 1041 if (len >= sizeof(dirbuf)) { 1042 result = ISC_R_NOSPACE; 1043 syslog(LOG_ERR, "unable to remove log files: %s", 1044 isc_result_totext(result)); 1045 return (result); 1046 } 1047 1048 /* 1049 * Truncate after trailing '/' so the code works for 1050 * files in the root directory. 1051 */ 1052 bname++; 1053 dirbuf[bname - file->name] = '\0'; 1054 dirname = dirbuf; 1055 } else { 1056 bname = file->name; 1057 } 1058 bnamelen = strlen(bname); 1059 1060 isc_dir_init(&dir); 1061 result = isc_dir_open(&dir, dirname); 1062 1063 /* 1064 * Return if the directory open failed. 1065 */ 1066 if (result != ISC_R_SUCCESS) { 1067 return (result); 1068 } 1069 1070 while (isc_dir_read(&dir) == ISC_R_SUCCESS) { 1071 if (dir.entry.length > bnamelen && 1072 strncmp(dir.entry.name, bname, bnamelen) == 0 && 1073 dir.entry.name[bnamelen] == '.') 1074 { 1075 version = strtol(&dir.entry.name[bnamelen + 1], 1076 &digit_end, 10); 1077 /* 1078 * Remove any backup files that exceed versions. 1079 */ 1080 if (*digit_end == '\0' && version >= versions) { 1081 int n = dirfd(dir.handle); 1082 if (n >= 0) { 1083 n = unlinkat(n, dir.entry.name, 0); 1084 } 1085 if (n < 0) { 1086 result = isc_errno_toresult(errno); 1087 if (result != ISC_R_SUCCESS && 1088 result != ISC_R_FILENOTFOUND) 1089 { 1090 syslog(LOG_ERR, 1091 "unable to remove log " 1092 "file '%s%s': %s", 1093 bname == file->name 1094 ? "" 1095 : dirname, 1096 dir.entry.name, 1097 isc_result_totext( 1098 result)); 1099 } 1100 } 1101 } else if (*digit_end == '\0' && version > greatest) { 1102 greatest = version; 1103 } 1104 } 1105 } 1106 isc_dir_close(&dir); 1107 1108 *greatestp = greatest; 1109 return (ISC_R_SUCCESS); 1110 } 1111 1112 static void 1113 insert_sort(int64_t to_keep[], int64_t versions, int64_t version) { 1114 int i = 0; 1115 while (i < versions && version < to_keep[i]) { 1116 i++; 1117 } 1118 if (i == versions) { 1119 return; 1120 } 1121 if (i < versions - 1) { 1122 memmove(&to_keep[i + 1], &to_keep[i], 1123 sizeof(to_keep[0]) * (versions - i - 1)); 1124 } 1125 to_keep[i] = version; 1126 } 1127 1128 static int64_t 1129 last_to_keep(int64_t versions, isc_dir_t *dirp, const char *bname, 1130 size_t bnamelen) { 1131 int64_t to_keep[ISC_LOG_MAX_VERSIONS] = { 0 }; 1132 int64_t version = 0; 1133 1134 if (versions <= 0) { 1135 return (INT64_MAX); 1136 } 1137 1138 if (versions > ISC_LOG_MAX_VERSIONS) { 1139 versions = ISC_LOG_MAX_VERSIONS; 1140 } 1141 /* 1142 * First we fill 'to_keep' structure using insertion sort 1143 */ 1144 memset(to_keep, 0, sizeof(to_keep)); 1145 while (isc_dir_read(dirp) == ISC_R_SUCCESS) { 1146 char *digit_end = NULL; 1147 char *ename = NULL; 1148 1149 if (dirp->entry.length <= bnamelen || 1150 strncmp(dirp->entry.name, bname, bnamelen) != 0 || 1151 dirp->entry.name[bnamelen] != '.') 1152 { 1153 continue; 1154 } 1155 1156 ename = &dirp->entry.name[bnamelen + 1]; 1157 version = strtoull(ename, &digit_end, 10); 1158 if (*digit_end == '\0') { 1159 insert_sort(to_keep, versions, version); 1160 } 1161 } 1162 1163 isc_dir_reset(dirp); 1164 1165 /* 1166 * to_keep[versions - 1] is the last one we want to keep 1167 */ 1168 return (to_keep[versions - 1]); 1169 } 1170 1171 static isc_result_t 1172 remove_old_tsversions(isc_logfile_t *file, int versions) { 1173 char *digit_end; 1174 char dirbuf[PATH_MAX + 1]; 1175 const char *bname; 1176 const char *dirname = "."; 1177 int64_t version, last = INT64_MAX; 1178 isc_dir_t dir; 1179 isc_result_t result; 1180 size_t bnamelen; 1181 1182 bname = strrchr(file->name, '/'); 1183 if (bname != NULL) { 1184 /* 1185 * Copy the complete file name to dirbuf. 1186 */ 1187 size_t len = strlcpy(dirbuf, file->name, sizeof(dirbuf)); 1188 if (len >= sizeof(dirbuf)) { 1189 result = ISC_R_NOSPACE; 1190 syslog(LOG_ERR, "unable to remove log files: %s", 1191 isc_result_totext(result)); 1192 return (result); 1193 } 1194 1195 /* 1196 * Truncate after trailing '/' so the code works for 1197 * files in the root directory. 1198 */ 1199 bname++; 1200 dirbuf[bname - file->name] = '\0'; 1201 dirname = dirbuf; 1202 } else { 1203 bname = file->name; 1204 } 1205 bnamelen = strlen(bname); 1206 1207 isc_dir_init(&dir); 1208 result = isc_dir_open(&dir, dirname); 1209 1210 /* 1211 * Return if the directory open failed. 1212 */ 1213 if (result != ISC_R_SUCCESS) { 1214 return (result); 1215 } 1216 1217 last = last_to_keep(versions, &dir, bname, bnamelen); 1218 1219 while (isc_dir_read(&dir) == ISC_R_SUCCESS) { 1220 if (dir.entry.length > bnamelen && 1221 strncmp(dir.entry.name, bname, bnamelen) == 0 && 1222 dir.entry.name[bnamelen] == '.') 1223 { 1224 version = strtoull(&dir.entry.name[bnamelen + 1], 1225 &digit_end, 10); 1226 /* 1227 * Remove any backup files that exceed versions. 1228 */ 1229 if (*digit_end == '\0' && version < last) { 1230 int n = dirfd(dir.handle); 1231 if (n >= 0) { 1232 n = unlinkat(n, dir.entry.name, 0); 1233 } 1234 if (n < 0) { 1235 result = isc_errno_toresult(errno); 1236 if (result != ISC_R_SUCCESS && 1237 result != ISC_R_FILENOTFOUND) 1238 { 1239 syslog(LOG_ERR, 1240 "unable to remove log " 1241 "file '%s%s': %s", 1242 bname == file->name 1243 ? "" 1244 : dirname, 1245 dir.entry.name, 1246 isc_result_totext( 1247 result)); 1248 } 1249 } 1250 } 1251 } 1252 } 1253 isc_dir_close(&dir); 1254 return (ISC_R_SUCCESS); 1255 } 1256 1257 static isc_result_t 1258 roll_increment(isc_logfile_t *file) { 1259 int i, n, greatest; 1260 char current[PATH_MAX + 1]; 1261 char newpath[PATH_MAX + 1]; 1262 const char *path; 1263 isc_result_t result = ISC_R_SUCCESS; 1264 1265 REQUIRE(file != NULL); 1266 REQUIRE(file->versions != 0); 1267 1268 path = file->name; 1269 1270 if (file->versions == ISC_LOG_ROLLINFINITE) { 1271 /* 1272 * Find the first missing entry in the log file sequence. 1273 */ 1274 for (greatest = 0; greatest < INT_MAX; greatest++) { 1275 n = snprintf(current, sizeof(current), "%s.%u", path, 1276 (unsigned)greatest); 1277 if (n >= (int)sizeof(current) || n < 0 || 1278 !isc_file_exists(current)) 1279 { 1280 break; 1281 } 1282 } 1283 } else { 1284 /* 1285 * Get the largest existing version and remove any 1286 * version greater than the permitted version. 1287 */ 1288 result = greatest_version(file, file->versions, &greatest); 1289 if (result != ISC_R_SUCCESS) { 1290 return (result); 1291 } 1292 1293 /* 1294 * Increment if greatest is not the actual maximum value. 1295 */ 1296 if (greatest < file->versions - 1) { 1297 greatest++; 1298 } 1299 } 1300 1301 for (i = greatest; i > 0; i--) { 1302 result = ISC_R_SUCCESS; 1303 n = snprintf(current, sizeof(current), "%s.%u", path, 1304 (unsigned)(i - 1)); 1305 if (n >= (int)sizeof(current) || n < 0) { 1306 result = ISC_R_NOSPACE; 1307 } 1308 if (result == ISC_R_SUCCESS) { 1309 n = snprintf(newpath, sizeof(newpath), "%s.%u", path, 1310 (unsigned)i); 1311 if (n >= (int)sizeof(newpath) || n < 0) { 1312 result = ISC_R_NOSPACE; 1313 } 1314 } 1315 if (result == ISC_R_SUCCESS) { 1316 result = isc_file_rename(current, newpath); 1317 } 1318 if (result != ISC_R_SUCCESS && result != ISC_R_FILENOTFOUND) { 1319 syslog(LOG_ERR, 1320 "unable to rename log file '%s.%u' to " 1321 "'%s.%u': %s", 1322 path, i - 1, path, i, isc_result_totext(result)); 1323 } 1324 } 1325 1326 n = snprintf(newpath, sizeof(newpath), "%s.0", path); 1327 if (n >= (int)sizeof(newpath) || n < 0) { 1328 result = ISC_R_NOSPACE; 1329 } else { 1330 result = isc_file_rename(path, newpath); 1331 } 1332 if (result != ISC_R_SUCCESS && result != ISC_R_FILENOTFOUND) { 1333 syslog(LOG_ERR, "unable to rename log file '%s' to '%s.0': %s", 1334 path, path, isc_result_totext(result)); 1335 } 1336 1337 return (ISC_R_SUCCESS); 1338 } 1339 1340 static isc_result_t 1341 roll_timestamp(isc_logfile_t *file) { 1342 int n; 1343 char newts[PATH_MAX + 1]; 1344 char newpath[PATH_MAX + 1]; 1345 const char *path; 1346 isc_time_t now; 1347 isc_result_t result = ISC_R_SUCCESS; 1348 1349 REQUIRE(file != NULL); 1350 REQUIRE(file->versions != 0); 1351 1352 path = file->name; 1353 1354 /* 1355 * First find all the logfiles and remove the oldest ones 1356 * Save one fewer than file->versions because we'll be renaming 1357 * the existing file to a timestamped version after this. 1358 */ 1359 if (file->versions != ISC_LOG_ROLLINFINITE) { 1360 remove_old_tsversions(file, file->versions - 1); 1361 } 1362 1363 /* Then just rename the current logfile */ 1364 isc_time_now(&now); 1365 isc_time_formatshorttimestamp(&now, newts, PATH_MAX + 1); 1366 n = snprintf(newpath, sizeof(newpath), "%s.%s", path, newts); 1367 if (n >= (int)sizeof(newpath) || n < 0) { 1368 result = ISC_R_NOSPACE; 1369 } else { 1370 result = isc_file_rename(path, newpath); 1371 } 1372 if (result != ISC_R_SUCCESS && result != ISC_R_FILENOTFOUND) { 1373 syslog(LOG_ERR, "unable to rename log file '%s' to '%s.0': %s", 1374 path, path, isc_result_totext(result)); 1375 } 1376 1377 return (ISC_R_SUCCESS); 1378 } 1379 1380 isc_result_t 1381 isc_logfile_roll(isc_logfile_t *file) { 1382 isc_result_t result; 1383 1384 REQUIRE(file != NULL); 1385 1386 /* 1387 * Do nothing (not even excess version trimming) if ISC_LOG_ROLLNEVER 1388 * is specified. Apparently complete external control over the log 1389 * files is desired. 1390 */ 1391 if (file->versions == ISC_LOG_ROLLNEVER) { 1392 return (ISC_R_SUCCESS); 1393 } else if (file->versions == 0) { 1394 result = isc_file_remove(file->name); 1395 if (result != ISC_R_SUCCESS && result != ISC_R_FILENOTFOUND) { 1396 syslog(LOG_ERR, "unable to remove log file '%s': %s", 1397 file->name, isc_result_totext(result)); 1398 } 1399 return (ISC_R_SUCCESS); 1400 } 1401 1402 switch (file->suffix) { 1403 case isc_log_rollsuffix_increment: 1404 return (roll_increment(file)); 1405 case isc_log_rollsuffix_timestamp: 1406 return (roll_timestamp(file)); 1407 default: 1408 return (ISC_R_UNEXPECTED); 1409 } 1410 } 1411 1412 static isc_result_t 1413 isc_log_open(isc_logchannel_t *channel) { 1414 struct stat statbuf; 1415 bool regular_file; 1416 bool roll = false; 1417 isc_result_t result = ISC_R_SUCCESS; 1418 const char *path; 1419 1420 REQUIRE(channel->type == ISC_LOG_TOFILE); 1421 REQUIRE(FILE_STREAM(channel) == NULL); 1422 1423 path = FILE_NAME(channel); 1424 1425 REQUIRE(path != NULL && *path != '\0'); 1426 1427 /* 1428 * Determine type of file; only regular files will be 1429 * version renamed, and only if the base file exists 1430 * and either has no size limit or has reached its size limit. 1431 */ 1432 if (stat(path, &statbuf) == 0) { 1433 regular_file = S_ISREG(statbuf.st_mode) ? true : false; 1434 /* XXXDCL if not regular_file complain? */ 1435 if ((FILE_MAXSIZE(channel) == 0 && 1436 FILE_VERSIONS(channel) != ISC_LOG_ROLLNEVER) || 1437 (FILE_MAXSIZE(channel) > 0 && 1438 statbuf.st_size >= FILE_MAXSIZE(channel))) 1439 { 1440 roll = regular_file; 1441 } 1442 } else if (errno == ENOENT) { 1443 regular_file = true; 1444 POST(regular_file); 1445 } else { 1446 result = ISC_R_INVALIDFILE; 1447 } 1448 1449 /* 1450 * Version control. 1451 */ 1452 if (result == ISC_R_SUCCESS && roll) { 1453 if (FILE_VERSIONS(channel) == ISC_LOG_ROLLNEVER) { 1454 return (ISC_R_MAXSIZE); 1455 } 1456 result = isc_logfile_roll(&channel->destination.file); 1457 if (result != ISC_R_SUCCESS) { 1458 if ((channel->flags & ISC_LOG_OPENERR) == 0) { 1459 syslog(LOG_ERR, 1460 "isc_log_open: isc_logfile_roll '%s' " 1461 "failed: %s", 1462 FILE_NAME(channel), 1463 isc_result_totext(result)); 1464 channel->flags |= ISC_LOG_OPENERR; 1465 } 1466 return (result); 1467 } 1468 } 1469 1470 result = isc_stdio_open(path, "a", &FILE_STREAM(channel)); 1471 1472 return (result); 1473 } 1474 1475 ISC_NO_SANITIZE_THREAD bool 1476 isc_log_wouldlog(isc_log_t *lctx, int level) { 1477 /* 1478 * Try to avoid locking the mutex for messages which can't 1479 * possibly be logged to any channels -- primarily debugging 1480 * messages that the debug level is not high enough to print. 1481 * 1482 * If the level is (mathematically) less than or equal to the 1483 * highest_level, or if there is a dynamic channel and the level is 1484 * less than or equal to the debug level, the main loop must be 1485 * entered to see if the message should really be output. 1486 */ 1487 if (lctx == NULL) { 1488 return (false); 1489 } 1490 if (forcelog) { 1491 return (true); 1492 } 1493 1494 int highest_level = atomic_load_acquire(&lctx->highest_level); 1495 if (level <= highest_level) { 1496 return (true); 1497 } 1498 if (atomic_load_acquire(&lctx->dynamic)) { 1499 int debug_level = atomic_load_acquire(&lctx->debug_level); 1500 if (level <= debug_level) { 1501 return (true); 1502 } 1503 } 1504 1505 return (false); 1506 } 1507 1508 static void 1509 isc_log_doit(isc_log_t *lctx, isc_logcategory_t *category, 1510 isc_logmodule_t *module, int level, bool write_once, 1511 const char *format, va_list args) { 1512 int syslog_level; 1513 const char *time_string; 1514 char local_time[64]; 1515 char iso8601z_string[64]; 1516 char iso8601l_string[64]; 1517 char level_string[24] = { 0 }; 1518 struct stat statbuf; 1519 bool matched = false; 1520 bool printtime, iso8601, utc, printtag, printcolon; 1521 bool printcategory, printmodule, printlevel, buffered; 1522 isc_logchannel_t *channel; 1523 isc_logchannellist_t *category_channels; 1524 int_fast32_t dlevel; 1525 isc_result_t result; 1526 1527 REQUIRE(lctx == NULL || VALID_CONTEXT(lctx)); 1528 REQUIRE(category != NULL); 1529 REQUIRE(module != NULL); 1530 REQUIRE(level != ISC_LOG_DYNAMIC); 1531 REQUIRE(format != NULL); 1532 1533 /* 1534 * Programs can use libraries that use this logging code without 1535 * wanting to do any logging, thus the log context is allowed to 1536 * be non-existent. 1537 */ 1538 if (lctx == NULL) { 1539 return; 1540 } 1541 1542 REQUIRE(category->id < lctx->category_count); 1543 REQUIRE(module->id < lctx->module_count); 1544 1545 if (!isc_log_wouldlog(lctx, level)) { 1546 return; 1547 } 1548 1549 local_time[0] = '\0'; 1550 iso8601l_string[0] = '\0'; 1551 iso8601z_string[0] = '\0'; 1552 1553 RDLOCK(&lctx->lcfg_rwl); 1554 LOCK(&lctx->lock); 1555 1556 lctx->buffer[0] = '\0'; 1557 1558 isc_logconfig_t *lcfg = lctx->logconfig; 1559 1560 category_channels = ISC_LIST_HEAD(lcfg->channellists[category->id]); 1561 1562 /* 1563 * XXXDCL add duplicate filtering? (To not write multiple times 1564 * to the same source via various channels). 1565 */ 1566 do { 1567 /* 1568 * If the channel list end was reached and a match was 1569 * made, everything is finished. 1570 */ 1571 if (category_channels == NULL && matched) { 1572 break; 1573 } 1574 1575 if (category_channels == NULL && !matched && 1576 category_channels != ISC_LIST_HEAD(lcfg->channellists[0])) 1577 { 1578 /* 1579 * No category/module pair was explicitly 1580 * configured. Try the category named "default". 1581 */ 1582 category_channels = 1583 ISC_LIST_HEAD(lcfg->channellists[0]); 1584 } 1585 1586 if (category_channels == NULL && !matched) { 1587 /* 1588 * No matching module was explicitly configured 1589 * for the category named "default". Use the 1590 * internal default channel. 1591 */ 1592 category_channels = &default_channel; 1593 } 1594 1595 if (category_channels->module != NULL && 1596 category_channels->module != module) 1597 { 1598 category_channels = ISC_LIST_NEXT(category_channels, 1599 link); 1600 continue; 1601 } 1602 1603 matched = true; 1604 1605 channel = category_channels->channel; 1606 category_channels = ISC_LIST_NEXT(category_channels, link); 1607 1608 if (!forcelog) { 1609 dlevel = atomic_load_acquire(&lctx->debug_level); 1610 if (((channel->flags & ISC_LOG_DEBUGONLY) != 0) && 1611 dlevel == 0) 1612 { 1613 continue; 1614 } 1615 1616 if (channel->level == ISC_LOG_DYNAMIC) { 1617 if (dlevel < level) { 1618 continue; 1619 } 1620 } else if (channel->level < level) { 1621 continue; 1622 } 1623 } 1624 1625 if ((channel->flags & ISC_LOG_PRINTTIME) != 0 && 1626 local_time[0] == '\0') 1627 { 1628 isc_time_t isctime; 1629 1630 TIME_NOW(&isctime); 1631 1632 isc_time_formattimestamp(&isctime, local_time, 1633 sizeof(local_time)); 1634 isc_time_formatISO8601ms(&isctime, iso8601z_string, 1635 sizeof(iso8601z_string)); 1636 isc_time_formatISO8601Lms(&isctime, iso8601l_string, 1637 sizeof(iso8601l_string)); 1638 } 1639 1640 if ((channel->flags & ISC_LOG_PRINTLEVEL) != 0 && 1641 level_string[0] == '\0') 1642 { 1643 if (level < ISC_LOG_CRITICAL) { 1644 snprintf(level_string, sizeof(level_string), 1645 "level %d: ", level); 1646 } else if (level > ISC_LOG_DYNAMIC) { 1647 snprintf(level_string, sizeof(level_string), 1648 "%s %d: ", log_level_strings[0], 1649 level); 1650 } else { 1651 snprintf(level_string, sizeof(level_string), 1652 "%s: ", log_level_strings[-level]); 1653 } 1654 } 1655 1656 /* 1657 * Only format the message once. 1658 */ 1659 if (lctx->buffer[0] == '\0') { 1660 (void)vsnprintf(lctx->buffer, sizeof(lctx->buffer), 1661 format, args); 1662 1663 /* 1664 * Check for duplicates. 1665 */ 1666 if (write_once) { 1667 isc_logmessage_t *message, *next; 1668 isc_time_t oldest; 1669 isc_interval_t interval; 1670 size_t size; 1671 1672 isc_interval_set(&interval, 1673 lcfg->duplicate_interval, 0); 1674 1675 /* 1676 * 'oldest' is the age of the oldest 1677 * messages which fall within the 1678 * duplicate_interval range. 1679 */ 1680 TIME_NOW(&oldest); 1681 if (isc_time_subtract(&oldest, &interval, 1682 &oldest) != ISC_R_SUCCESS) 1683 { 1684 /* 1685 * Can't effectively do the 1686 * checking without having a 1687 * valid time. 1688 */ 1689 message = NULL; 1690 } else { 1691 message = ISC_LIST_HEAD(lctx->messages); 1692 } 1693 1694 while (message != NULL) { 1695 if (isc_time_compare(&message->time, 1696 &oldest) < 0) 1697 { 1698 /* 1699 * This message is older 1700 * than the 1701 * duplicate_interval, 1702 * so it should be 1703 * dropped from the 1704 * history. 1705 * 1706 * Setting the interval 1707 * to be to be longer 1708 * will obviously not 1709 * cause the expired 1710 * message to spring 1711 * back into existence. 1712 */ 1713 next = ISC_LIST_NEXT(message, 1714 link); 1715 1716 ISC_LIST_UNLINK(lctx->messages, 1717 message, link); 1718 1719 isc_mem_put( 1720 lctx->mctx, message, 1721 sizeof(*message) + 1 + 1722 strlen(message->text)); 1723 1724 message = next; 1725 continue; 1726 } 1727 1728 /* 1729 * This message is in the 1730 * duplicate filtering interval 1731 * ... 1732 */ 1733 if (strcmp(lctx->buffer, 1734 message->text) == 0) 1735 { 1736 /* 1737 * ... and it is a 1738 * duplicate. Unlock the 1739 * mutex and get the 1740 * hell out of Dodge. 1741 */ 1742 goto unlock; 1743 } 1744 1745 message = ISC_LIST_NEXT(message, link); 1746 } 1747 1748 /* 1749 * It wasn't in the duplicate interval, 1750 * so add it to the message list. 1751 */ 1752 size = sizeof(isc_logmessage_t) + 1753 strlen(lctx->buffer) + 1; 1754 message = isc_mem_get(lctx->mctx, size); 1755 message->text = (char *)(message + 1); 1756 size -= sizeof(isc_logmessage_t); 1757 strlcpy(message->text, lctx->buffer, size); 1758 TIME_NOW(&message->time); 1759 ISC_LINK_INIT(message, link); 1760 ISC_LIST_APPEND(lctx->messages, message, link); 1761 } 1762 } 1763 1764 utc = ((channel->flags & ISC_LOG_UTC) != 0); 1765 iso8601 = ((channel->flags & ISC_LOG_ISO8601) != 0); 1766 printtime = ((channel->flags & ISC_LOG_PRINTTIME) != 0); 1767 printtag = ((channel->flags & 1768 (ISC_LOG_PRINTTAG | ISC_LOG_PRINTPREFIX)) != 0 && 1769 lcfg->tag != NULL); 1770 printcolon = ((channel->flags & ISC_LOG_PRINTTAG) != 0 && 1771 lcfg->tag != NULL); 1772 printcategory = ((channel->flags & ISC_LOG_PRINTCATEGORY) != 0); 1773 printmodule = ((channel->flags & ISC_LOG_PRINTMODULE) != 0); 1774 printlevel = ((channel->flags & ISC_LOG_PRINTLEVEL) != 0); 1775 buffered = ((channel->flags & ISC_LOG_BUFFERED) != 0); 1776 1777 if (printtime) { 1778 if (iso8601) { 1779 if (utc) { 1780 time_string = iso8601z_string; 1781 } else { 1782 time_string = iso8601l_string; 1783 } 1784 } else { 1785 time_string = local_time; 1786 } 1787 } else { 1788 time_string = ""; 1789 } 1790 1791 switch (channel->type) { 1792 case ISC_LOG_TOFILE: 1793 if (FILE_MAXREACHED(channel)) { 1794 /* 1795 * If the file can be rolled, OR 1796 * If the file no longer exists, OR 1797 * If the file is less than the maximum 1798 * size, (such as if it had been renamed 1799 * and a new one touched, or it was 1800 * truncated in place) 1801 * ... then close it to trigger 1802 * reopening. 1803 */ 1804 if (FILE_VERSIONS(channel) != 1805 ISC_LOG_ROLLNEVER || 1806 (stat(FILE_NAME(channel), &statbuf) != 0 && 1807 errno == ENOENT) || 1808 statbuf.st_size < FILE_MAXSIZE(channel)) 1809 { 1810 (void)fclose(FILE_STREAM(channel)); 1811 FILE_STREAM(channel) = NULL; 1812 FILE_MAXREACHED(channel) = false; 1813 } else { 1814 /* 1815 * Eh, skip it. 1816 */ 1817 break; 1818 } 1819 } 1820 1821 if (FILE_STREAM(channel) == NULL) { 1822 result = isc_log_open(channel); 1823 if (result != ISC_R_SUCCESS && 1824 result != ISC_R_MAXSIZE && 1825 (channel->flags & ISC_LOG_OPENERR) == 0) 1826 { 1827 syslog(LOG_ERR, 1828 "isc_log_open '%s' " 1829 "failed: %s", 1830 FILE_NAME(channel), 1831 isc_result_totext(result)); 1832 channel->flags |= ISC_LOG_OPENERR; 1833 } 1834 if (result != ISC_R_SUCCESS) { 1835 break; 1836 } 1837 channel->flags &= ~ISC_LOG_OPENERR; 1838 } 1839 FALLTHROUGH; 1840 1841 case ISC_LOG_TOFILEDESC: 1842 fprintf(FILE_STREAM(channel), "%s%s%s%s%s%s%s%s%s%s\n", 1843 printtime ? time_string : "", 1844 printtime ? " " : "", printtag ? lcfg->tag : "", 1845 printcolon ? ": " : "", 1846 printcategory ? category->name : "", 1847 printcategory ? ": " : "", 1848 printmodule ? (module != NULL ? module->name 1849 : "no_module") 1850 : "", 1851 printmodule ? ": " : "", 1852 printlevel ? level_string : "", lctx->buffer); 1853 1854 if (!buffered) { 1855 fflush(FILE_STREAM(channel)); 1856 } 1857 1858 /* 1859 * If the file now exceeds its maximum size 1860 * threshold, note it so that it will not be 1861 * logged to any more. 1862 */ 1863 if (FILE_MAXSIZE(channel) > 0) { 1864 INSIST(channel->type == ISC_LOG_TOFILE); 1865 1866 /* XXXDCL NT fstat/fileno */ 1867 /* XXXDCL complain if fstat fails? */ 1868 if (fstat(fileno(FILE_STREAM(channel)), 1869 &statbuf) >= 0 && 1870 statbuf.st_size > FILE_MAXSIZE(channel)) 1871 { 1872 FILE_MAXREACHED(channel) = true; 1873 } 1874 } 1875 1876 break; 1877 1878 case ISC_LOG_TOSYSLOG: 1879 if (level > 0) { 1880 syslog_level = LOG_DEBUG; 1881 } else if (level < ISC_LOG_CRITICAL) { 1882 syslog_level = LOG_CRIT; 1883 } else { 1884 syslog_level = syslog_map[-level]; 1885 } 1886 1887 (void)syslog( 1888 FACILITY(channel) | syslog_level, 1889 "%s%s%s%s%s%s%s%s%s%s", 1890 printtime ? time_string : "", 1891 printtime ? " " : "", printtag ? lcfg->tag : "", 1892 printcolon ? ": " : "", 1893 printcategory ? category->name : "", 1894 printcategory ? ": " : "", 1895 printmodule ? (module != NULL ? module->name 1896 : "no_module") 1897 : "", 1898 printmodule ? ": " : "", 1899 printlevel ? level_string : "", lctx->buffer); 1900 break; 1901 1902 case ISC_LOG_TONULL: 1903 break; 1904 } 1905 } while (1); 1906 1907 unlock: 1908 UNLOCK(&lctx->lock); 1909 RDUNLOCK(&lctx->lcfg_rwl); 1910 } 1911 1912 void 1913 isc_log_setforcelog(bool v) { 1914 forcelog = v; 1915 } 1916