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