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