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