1 /* $NetBSD: log.c,v 1.5 2020/05/24 19:46:26 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 http://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 */ 64 typedef struct isc_logchannel isc_logchannel_t; 65 66 struct isc_logchannel { 67 char *name; 68 unsigned int type; 69 int level; 70 unsigned int flags; 71 isc_logdestination_t destination; 72 ISC_LINK(isc_logchannel_t) link; 73 }; 74 75 /*! 76 * The logchannellist structure associates categories and modules with 77 * channels. First the appropriate channellist is found based on the 78 * category, and then each structure in the linked list is checked for 79 * a matching module. It is expected that the number of channels 80 * associated with any given category will be very short, no more than 81 * three or four in the more unusual cases. 82 */ 83 typedef struct isc_logchannellist isc_logchannellist_t; 84 85 struct isc_logchannellist { 86 const isc_logmodule_t *module; 87 isc_logchannel_t *channel; 88 ISC_LINK(isc_logchannellist_t) link; 89 }; 90 91 /*! 92 * This structure is used to remember messages for pruning via 93 * isc_log_[v]write1(). 94 */ 95 typedef struct isc_logmessage isc_logmessage_t; 96 97 struct isc_logmessage { 98 char *text; 99 isc_time_t time; 100 ISC_LINK(isc_logmessage_t) link; 101 }; 102 103 /*! 104 * The isc_logconfig structure is used to store the configurable information 105 * about where messages are actually supposed to be sent -- the information 106 * that could changed based on some configuration file, as opposed to the 107 * the category/module specification of isc_log_[v]write[1] that is compiled 108 * into a program, or the debug_level which is dynamic state information. 109 */ 110 struct isc_logconfig { 111 unsigned int magic; 112 isc_log_t *lctx; 113 ISC_LIST(isc_logchannel_t) channels; 114 ISC_LIST(isc_logchannellist_t) * channellists; 115 unsigned int channellist_count; 116 unsigned int duplicate_interval; 117 int_fast32_t highest_level; 118 char *tag; 119 bool dynamic; 120 }; 121 122 /*! 123 * This isc_log structure provides the context for the isc_log functions. 124 * The log context locks itself in isc_log_doit, the internal backend to 125 * isc_log_write. The locking is necessary both to provide exclusive access 126 * to the buffer into which the message is formatted and to guard against 127 * competing threads trying to write to the same syslog resource. (On 128 * some systems, such as BSD/OS, stdio is thread safe but syslog is not.) 129 * Unfortunately, the lock cannot guard against a _different_ logging 130 * context in the same program competing for syslog's attention. Thus 131 * There Can Be Only One, but this is not enforced. 132 * XXXDCL enforce it? 133 * 134 * Note that the category and module information is not locked. 135 * This is because in the usual case, only one isc_log_t is ever created 136 * in a program, and the category/module registration happens only once. 137 * XXXDCL it might be wise to add more locking overall. 138 */ 139 struct isc_log { 140 /* Not locked. */ 141 unsigned int magic; 142 isc_mem_t *mctx; 143 isc_logcategory_t *categories; 144 unsigned int category_count; 145 isc_logmodule_t *modules; 146 unsigned int module_count; 147 atomic_int_fast32_t debug_level; 148 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 */ 162 static 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 */ 169 static 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 */ 180 LIBISC_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 */ 191 LIBISC_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 */ 201 static isc_logchannellist_t default_channel; 202 203 /*! 204 * libisc logs to this context. 205 */ 206 LIBISC_EXTERNAL_DATA isc_log_t *isc_lctx = NULL; 207 208 /*! 209 * Forward declarations. 210 */ 211 static void 212 assignchannel(isc_logconfig_t *lcfg, unsigned int category_id, 213 const isc_logmodule_t *module, isc_logchannel_t *channel); 214 215 static void 216 sync_channellist(isc_logconfig_t *lcfg); 217 218 static void 219 sync_highest_level(isc_log_t *lctx, isc_logconfig_t *lcfg); 220 221 static isc_result_t 222 greatest_version(isc_logfile_t *file, int versions, int *greatest); 223 224 static void 225 isc_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 */ 250 void 251 isc_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 299 void 300 isc_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 357 void 358 isc_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 381 void 382 isc_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 429 void 430 isc_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 502 void 503 isc_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 548 isc_logcategory_t * 549 isc_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 573 void 574 isc_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 619 isc_logmodule_t * 620 isc_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 644 void 645 isc_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 724 isc_result_t 725 isc_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 773 void 774 isc_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 787 void 788 isc_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 797 void 798 isc_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 811 void 812 isc_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 821 void 822 isc_log_setcontext(isc_log_t *lctx) { 823 isc_lctx = lctx; 824 } 825 826 void 827 isc_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 858 unsigned int 859 isc_log_getdebuglevel(isc_log_t *lctx) { 860 REQUIRE(VALID_CONTEXT(lctx)); 861 862 return (atomic_load_acquire(&lctx->debug_level)); 863 } 864 865 void 866 isc_log_setduplicateinterval(isc_logconfig_t *lcfg, unsigned int interval) { 867 REQUIRE(VALID_CONFIG(lcfg)); 868 869 lcfg->duplicate_interval = interval; 870 } 871 872 unsigned int 873 isc_log_getduplicateinterval(isc_logconfig_t *lcfg) { 874 REQUIRE(VALID_CONTEXT(lcfg)); 875 876 return (lcfg->duplicate_interval); 877 } 878 879 void 880 isc_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 896 char * 897 isc_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. */ 904 void 905 isc_log_opensyslog(const char *tag, int options, int facility) { 906 (void)openlog(tag, options, facility); 907 } 908 909 void 910 isc_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 935 static void 936 assignchannel(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 */ 980 static void 981 sync_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 1013 static void 1014 sync_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 1019 static isc_result_t 1020 greatest_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 1104 static isc_result_t 1105 remove_old_tsversions(isc_logfile_t *file, int versions) { 1106 isc_result_t result; 1107 char *bname, *digit_end; 1108 const char *dirname; 1109 int64_t version, last = INT64_MAX; 1110 int64_t to_keep[ISC_LOG_MAX_VERSIONS]; 1111 size_t bnamelen; 1112 isc_dir_t dir; 1113 char sep = '/'; 1114 #ifdef _WIN32 1115 char *bname2; 1116 #endif /* ifdef _WIN32 */ 1117 /* 1118 * It is safe to DE_CONST the file.name because it was copied 1119 * with isc_mem_strdup(). 1120 */ 1121 bname = strrchr(file->name, sep); 1122 #ifdef _WIN32 1123 bname2 = strrchr(file->name, '\\'); 1124 if ((bname != NULL && bname2 != NULL && bname2 > bname) || 1125 (bname == NULL && bname2 != NULL)) 1126 { 1127 bname = bname2; 1128 sep = '\\'; 1129 } 1130 #endif /* ifdef _WIN32 */ 1131 if (bname != NULL) { 1132 *bname++ = '\0'; 1133 dirname = file->name; 1134 } else { 1135 DE_CONST(file->name, bname); 1136 dirname = "."; 1137 } 1138 bnamelen = strlen(bname); 1139 1140 isc_dir_init(&dir); 1141 result = isc_dir_open(&dir, dirname); 1142 1143 /* 1144 * Replace the file separator if it was taken out. 1145 */ 1146 if (bname != file->name) { 1147 *(bname - 1) = sep; 1148 } 1149 1150 /* 1151 * Return if the directory open failed. 1152 */ 1153 if (result != ISC_R_SUCCESS) { 1154 return (result); 1155 } 1156 1157 if (versions > 0) { 1158 /* 1159 * First we fill 'to_keep' structure using insertion sort 1160 */ 1161 memset(to_keep, 0, versions * sizeof(long long)); 1162 while (isc_dir_read(&dir) == ISC_R_SUCCESS) { 1163 if (dir.entry.length > bnamelen && 1164 strncmp(dir.entry.name, bname, bnamelen) == 0 && 1165 dir.entry.name[bnamelen] == '.') 1166 { 1167 char *ename = &dir.entry.name[bnamelen + 1]; 1168 version = strtoull(ename, &digit_end, 10); 1169 if (*digit_end == '\0') { 1170 int i = 0; 1171 while (i < versions && 1172 version < to_keep[i]) { 1173 i++; 1174 } 1175 if (i < versions) { 1176 memmove(&to_keep[i + 1], 1177 &to_keep[i], 1178 sizeof(long long) * 1179 versions - 1180 i - 1); 1181 to_keep[i] = version; 1182 } 1183 } 1184 } 1185 } 1186 1187 /* 1188 * to_keep[versions - 1] is the last one we want to keep 1189 */ 1190 last = to_keep[versions - 1]; 1191 isc_dir_reset(&dir); 1192 } 1193 1194 /* 1195 * Then we remove all files that we don't want to_keep 1196 */ 1197 while (isc_dir_read(&dir) == ISC_R_SUCCESS) { 1198 if (dir.entry.length > bnamelen && 1199 strncmp(dir.entry.name, bname, bnamelen) == 0 && 1200 dir.entry.name[bnamelen] == '.') 1201 { 1202 char *ename = &dir.entry.name[bnamelen + 1]; 1203 version = strtoull(ename, &digit_end, 10); 1204 /* 1205 * Remove any backup files that exceed versions. 1206 */ 1207 if (*digit_end == '\0' && version < last) { 1208 result = isc_file_remove(dir.entry.name); 1209 if (result != ISC_R_SUCCESS && 1210 result != ISC_R_FILENOTFOUND) { 1211 syslog(LOG_ERR, 1212 "unable to remove " 1213 "log file '%s': %s", 1214 dir.entry.name, 1215 isc_result_totext(result)); 1216 } 1217 } 1218 } 1219 } 1220 1221 isc_dir_close(&dir); 1222 1223 return (ISC_R_SUCCESS); 1224 } 1225 1226 static isc_result_t 1227 roll_increment(isc_logfile_t *file) { 1228 int i, n, greatest; 1229 char current[PATH_MAX + 1]; 1230 char newpath[PATH_MAX + 1]; 1231 const char *path; 1232 isc_result_t result = ISC_R_SUCCESS; 1233 1234 REQUIRE(file != NULL); 1235 REQUIRE(file->versions != 0); 1236 1237 path = file->name; 1238 1239 if (file->versions == ISC_LOG_ROLLINFINITE) { 1240 /* 1241 * Find the first missing entry in the log file sequence. 1242 */ 1243 for (greatest = 0; greatest < INT_MAX; greatest++) { 1244 n = snprintf(current, sizeof(current), "%s.%u", path, 1245 (unsigned)greatest); 1246 if (n >= (int)sizeof(current) || n < 0 || 1247 !isc_file_exists(current)) { 1248 break; 1249 } 1250 } 1251 } else { 1252 /* 1253 * Get the largest existing version and remove any 1254 * version greater than the permitted version. 1255 */ 1256 result = greatest_version(file, file->versions, &greatest); 1257 if (result != ISC_R_SUCCESS) { 1258 return (result); 1259 } 1260 1261 /* 1262 * Increment if greatest is not the actual maximum value. 1263 */ 1264 if (greatest < file->versions - 1) { 1265 greatest++; 1266 } 1267 } 1268 1269 for (i = greatest; i > 0; i--) { 1270 result = ISC_R_SUCCESS; 1271 n = snprintf(current, sizeof(current), "%s.%u", path, 1272 (unsigned)(i - 1)); 1273 if (n >= (int)sizeof(current) || n < 0) { 1274 result = ISC_R_NOSPACE; 1275 } 1276 if (result == ISC_R_SUCCESS) { 1277 n = snprintf(newpath, sizeof(newpath), "%s.%u", path, 1278 (unsigned)i); 1279 if (n >= (int)sizeof(newpath) || n < 0) { 1280 result = ISC_R_NOSPACE; 1281 } 1282 } 1283 if (result == ISC_R_SUCCESS) { 1284 result = isc_file_rename(current, newpath); 1285 } 1286 if (result != ISC_R_SUCCESS && result != ISC_R_FILENOTFOUND) { 1287 syslog(LOG_ERR, 1288 "unable to rename log file '%s.%u' to " 1289 "'%s.%u': %s", 1290 path, i - 1, path, i, isc_result_totext(result)); 1291 } 1292 } 1293 1294 n = snprintf(newpath, sizeof(newpath), "%s.0", path); 1295 if (n >= (int)sizeof(newpath) || n < 0) { 1296 result = ISC_R_NOSPACE; 1297 } else { 1298 result = isc_file_rename(path, newpath); 1299 } 1300 if (result != ISC_R_SUCCESS && result != ISC_R_FILENOTFOUND) { 1301 syslog(LOG_ERR, "unable to rename log file '%s' to '%s.0': %s", 1302 path, path, isc_result_totext(result)); 1303 } 1304 1305 return (ISC_R_SUCCESS); 1306 } 1307 1308 static isc_result_t 1309 roll_timestamp(isc_logfile_t *file) { 1310 int n; 1311 char newts[PATH_MAX + 1]; 1312 char newpath[PATH_MAX + 1]; 1313 const char *path; 1314 isc_time_t now; 1315 isc_result_t result = ISC_R_SUCCESS; 1316 1317 REQUIRE(file != NULL); 1318 REQUIRE(file->versions != 0); 1319 1320 path = file->name; 1321 1322 /* 1323 * First find all the logfiles and remove the oldest ones 1324 * Save one fewer than file->versions because we'll be renaming 1325 * the existing file to a timestamped version after this. 1326 */ 1327 if (file->versions != ISC_LOG_ROLLINFINITE) { 1328 remove_old_tsversions(file, file->versions - 1); 1329 } 1330 1331 /* Then just rename the current logfile */ 1332 isc_time_now(&now); 1333 isc_time_formatshorttimestamp(&now, newts, PATH_MAX + 1); 1334 n = snprintf(newpath, sizeof(newpath), "%s.%s", path, newts); 1335 if (n >= (int)sizeof(newpath) || n < 0) { 1336 result = ISC_R_NOSPACE; 1337 } else { 1338 result = isc_file_rename(path, newpath); 1339 } 1340 if (result != ISC_R_SUCCESS && result != ISC_R_FILENOTFOUND) { 1341 syslog(LOG_ERR, "unable to rename log file '%s' to '%s.0': %s", 1342 path, path, isc_result_totext(result)); 1343 } 1344 1345 return (ISC_R_SUCCESS); 1346 } 1347 1348 isc_result_t 1349 isc_logfile_roll(isc_logfile_t *file) { 1350 isc_result_t result; 1351 1352 REQUIRE(file != NULL); 1353 1354 /* 1355 * Do nothing (not even excess version trimming) if ISC_LOG_ROLLNEVER 1356 * is specified. Apparently complete external control over the log 1357 * files is desired. 1358 */ 1359 if (file->versions == ISC_LOG_ROLLNEVER) { 1360 return (ISC_R_SUCCESS); 1361 } else if (file->versions == 0) { 1362 result = isc_file_remove(file->name); 1363 if (result != ISC_R_SUCCESS && result != ISC_R_FILENOTFOUND) { 1364 syslog(LOG_ERR, "unable to remove log file '%s': %s", 1365 file->name, isc_result_totext(result)); 1366 } 1367 return (ISC_R_SUCCESS); 1368 } 1369 1370 switch (file->suffix) { 1371 case isc_log_rollsuffix_increment: 1372 return (roll_increment(file)); 1373 case isc_log_rollsuffix_timestamp: 1374 return (roll_timestamp(file)); 1375 default: 1376 return (ISC_R_UNEXPECTED); 1377 } 1378 } 1379 1380 static isc_result_t 1381 isc_log_open(isc_logchannel_t *channel) { 1382 struct stat statbuf; 1383 bool regular_file; 1384 bool roll = false; 1385 isc_result_t result = ISC_R_SUCCESS; 1386 const char *path; 1387 1388 REQUIRE(channel->type == ISC_LOG_TOFILE); 1389 REQUIRE(FILE_STREAM(channel) == NULL); 1390 1391 path = FILE_NAME(channel); 1392 1393 REQUIRE(path != NULL && *path != '\0'); 1394 1395 /* 1396 * Determine type of file; only regular files will be 1397 * version renamed, and only if the base file exists 1398 * and either has no size limit or has reached its size limit. 1399 */ 1400 if (stat(path, &statbuf) == 0) { 1401 regular_file = S_ISREG(statbuf.st_mode) ? true : false; 1402 /* XXXDCL if not regular_file complain? */ 1403 if ((FILE_MAXSIZE(channel) == 0 && 1404 FILE_VERSIONS(channel) != ISC_LOG_ROLLNEVER) || 1405 (FILE_MAXSIZE(channel) > 0 && 1406 statbuf.st_size >= FILE_MAXSIZE(channel))) 1407 { 1408 roll = regular_file; 1409 } 1410 } else if (errno == ENOENT) { 1411 regular_file = true; 1412 POST(regular_file); 1413 } else { 1414 result = ISC_R_INVALIDFILE; 1415 } 1416 1417 /* 1418 * Version control. 1419 */ 1420 if (result == ISC_R_SUCCESS && roll) { 1421 if (FILE_VERSIONS(channel) == ISC_LOG_ROLLNEVER) { 1422 return (ISC_R_MAXSIZE); 1423 } 1424 result = isc_logfile_roll(&channel->destination.file); 1425 if (result != ISC_R_SUCCESS) { 1426 if ((channel->flags & ISC_LOG_OPENERR) == 0) { 1427 syslog(LOG_ERR, 1428 "isc_log_open: isc_logfile_roll '%s' " 1429 "failed: %s", 1430 FILE_NAME(channel), 1431 isc_result_totext(result)); 1432 channel->flags |= ISC_LOG_OPENERR; 1433 } 1434 return (result); 1435 } 1436 } 1437 1438 result = isc_stdio_open(path, "a", &FILE_STREAM(channel)); 1439 1440 return (result); 1441 } 1442 1443 bool 1444 isc_log_wouldlog(isc_log_t *lctx, int level) { 1445 /* 1446 * Try to avoid locking the mutex for messages which can't 1447 * possibly be logged to any channels -- primarily debugging 1448 * messages that the debug level is not high enough to print. 1449 * 1450 * If the level is (mathematically) less than or equal to the 1451 * highest_level, or if there is a dynamic channel and the level is 1452 * less than or equal to the debug level, the main loop must be 1453 * entered to see if the message should really be output. 1454 */ 1455 if (lctx == NULL) { 1456 return (false); 1457 } 1458 1459 int highest_level = atomic_load_acquire(&lctx->highest_level); 1460 if (level <= highest_level) { 1461 return (true); 1462 } 1463 if (atomic_load_acquire(&lctx->dynamic)) { 1464 int debug_level = atomic_load_acquire(&lctx->debug_level); 1465 if (level <= debug_level) { 1466 return (true); 1467 } 1468 } 1469 1470 return (false); 1471 } 1472 1473 static void 1474 isc_log_doit(isc_log_t *lctx, isc_logcategory_t *category, 1475 isc_logmodule_t *module, int level, bool write_once, 1476 const char *format, va_list args) { 1477 int syslog_level; 1478 const char *time_string; 1479 char local_time[64]; 1480 char iso8601z_string[64]; 1481 char iso8601l_string[64]; 1482 char level_string[24] = { 0 }; 1483 struct stat statbuf; 1484 bool matched = false; 1485 bool printtime, iso8601, utc, printtag, printcolon; 1486 bool printcategory, printmodule, printlevel, buffered; 1487 isc_logchannel_t *channel; 1488 isc_logchannellist_t *category_channels; 1489 isc_result_t result; 1490 1491 REQUIRE(lctx == NULL || VALID_CONTEXT(lctx)); 1492 REQUIRE(category != NULL); 1493 REQUIRE(module != NULL); 1494 REQUIRE(level != ISC_LOG_DYNAMIC); 1495 REQUIRE(format != NULL); 1496 1497 /* 1498 * Programs can use libraries that use this logging code without 1499 * wanting to do any logging, thus the log context is allowed to 1500 * be non-existent. 1501 */ 1502 if (lctx == NULL) { 1503 return; 1504 } 1505 1506 REQUIRE(category->id < lctx->category_count); 1507 REQUIRE(module->id < lctx->module_count); 1508 1509 if (!isc_log_wouldlog(lctx, level)) { 1510 return; 1511 } 1512 1513 local_time[0] = '\0'; 1514 iso8601l_string[0] = '\0'; 1515 iso8601z_string[0] = '\0'; 1516 1517 RDLOCK(&lctx->lcfg_rwl); 1518 LOCK(&lctx->lock); 1519 1520 lctx->buffer[0] = '\0'; 1521 1522 isc_logconfig_t *lcfg = lctx->logconfig; 1523 1524 category_channels = ISC_LIST_HEAD(lcfg->channellists[category->id]); 1525 1526 /* 1527 * XXXDCL add duplicate filtering? (To not write multiple times 1528 * to the same source via various channels). 1529 */ 1530 do { 1531 /* 1532 * If the channel list end was reached and a match was 1533 * made, everything is finished. 1534 */ 1535 if (category_channels == NULL && matched) { 1536 break; 1537 } 1538 1539 if (category_channels == NULL && !matched && 1540 category_channels != ISC_LIST_HEAD(lcfg->channellists[0])) 1541 { 1542 /* 1543 * No category/module pair was explicitly 1544 * configured. Try the category named "default". 1545 */ 1546 category_channels = 1547 ISC_LIST_HEAD(lcfg->channellists[0]); 1548 } 1549 1550 if (category_channels == NULL && !matched) { 1551 /* 1552 * No matching module was explicitly configured 1553 * for the category named "default". Use the 1554 * internal default channel. 1555 */ 1556 category_channels = &default_channel; 1557 } 1558 1559 if (category_channels->module != NULL && 1560 category_channels->module != module) { 1561 category_channels = ISC_LIST_NEXT(category_channels, 1562 link); 1563 continue; 1564 } 1565 1566 matched = true; 1567 1568 channel = category_channels->channel; 1569 category_channels = ISC_LIST_NEXT(category_channels, link); 1570 1571 int_fast32_t dlevel = atomic_load_acquire(&lctx->debug_level); 1572 if (((channel->flags & ISC_LOG_DEBUGONLY) != 0) && dlevel == 0) 1573 { 1574 continue; 1575 } 1576 1577 if (channel->level == ISC_LOG_DYNAMIC) { 1578 if (dlevel < level) { 1579 continue; 1580 } 1581 } else if (channel->level < level) { 1582 continue; 1583 } 1584 1585 if ((channel->flags & ISC_LOG_PRINTTIME) != 0 && 1586 local_time[0] == '\0') { 1587 isc_time_t isctime; 1588 1589 TIME_NOW(&isctime); 1590 1591 isc_time_formattimestamp(&isctime, local_time, 1592 sizeof(local_time)); 1593 isc_time_formatISO8601ms(&isctime, iso8601z_string, 1594 sizeof(iso8601z_string)); 1595 isc_time_formatISO8601Lms(&isctime, iso8601l_string, 1596 sizeof(iso8601l_string)); 1597 } 1598 1599 if ((channel->flags & ISC_LOG_PRINTLEVEL) != 0 && 1600 level_string[0] == '\0') { 1601 if (level < ISC_LOG_CRITICAL) { 1602 snprintf(level_string, sizeof(level_string), 1603 "level %d: ", level); 1604 } else if (level > ISC_LOG_DYNAMIC) { 1605 snprintf(level_string, sizeof(level_string), 1606 "%s %d: ", log_level_strings[0], 1607 level); 1608 } else { 1609 snprintf(level_string, sizeof(level_string), 1610 "%s: ", log_level_strings[-level]); 1611 } 1612 } 1613 1614 /* 1615 * Only format the message once. 1616 */ 1617 if (lctx->buffer[0] == '\0') { 1618 (void)vsnprintf(lctx->buffer, sizeof(lctx->buffer), 1619 format, args); 1620 1621 /* 1622 * Check for duplicates. 1623 */ 1624 if (write_once) { 1625 isc_logmessage_t *message, *next; 1626 isc_time_t oldest; 1627 isc_interval_t interval; 1628 size_t size; 1629 1630 isc_interval_set(&interval, 1631 lcfg->duplicate_interval, 0); 1632 1633 /* 1634 * 'oldest' is the age of the oldest 1635 * messages which fall within the 1636 * duplicate_interval range. 1637 */ 1638 TIME_NOW(&oldest); 1639 if (isc_time_subtract(&oldest, &interval, 1640 &oldest) != ISC_R_SUCCESS) 1641 { 1642 /* 1643 * Can't effectively do the 1644 * checking without having a 1645 * valid time. 1646 */ 1647 message = NULL; 1648 } else { 1649 message = ISC_LIST_HEAD(lctx->messages); 1650 } 1651 1652 while (message != NULL) { 1653 if (isc_time_compare(&message->time, 1654 &oldest) < 0) { 1655 /* 1656 * This message is older 1657 * than the 1658 * duplicate_interval, 1659 * so it should be 1660 * dropped from the 1661 * history. 1662 * 1663 * Setting the interval 1664 * to be to be longer 1665 * will obviously not 1666 * cause the expired 1667 * message to spring 1668 * back into existence. 1669 */ 1670 next = ISC_LIST_NEXT(message, 1671 link); 1672 1673 ISC_LIST_UNLINK(lctx->messages, 1674 message, link); 1675 1676 isc_mem_put( 1677 lctx->mctx, message, 1678 sizeof(*message) + 1 + 1679 strlen(message->text)); 1680 1681 message = next; 1682 continue; 1683 } 1684 1685 /* 1686 * This message is in the 1687 * duplicate filtering interval 1688 * ... 1689 */ 1690 if (strcmp(lctx->buffer, 1691 message->text) == 0) { 1692 /* 1693 * ... and it is a 1694 * duplicate. Unlock the 1695 * mutex and get the 1696 * hell out of Dodge. 1697 */ 1698 goto unlock; 1699 } 1700 1701 message = ISC_LIST_NEXT(message, link); 1702 } 1703 1704 /* 1705 * It wasn't in the duplicate interval, 1706 * so add it to the message list. 1707 */ 1708 size = sizeof(isc_logmessage_t) + 1709 strlen(lctx->buffer) + 1; 1710 message = isc_mem_get(lctx->mctx, size); 1711 message->text = (char *)(message + 1); 1712 size -= sizeof(isc_logmessage_t); 1713 strlcpy(message->text, lctx->buffer, size); 1714 TIME_NOW(&message->time); 1715 ISC_LINK_INIT(message, link); 1716 ISC_LIST_APPEND(lctx->messages, message, link); 1717 } 1718 } 1719 1720 utc = ((channel->flags & ISC_LOG_UTC) != 0); 1721 iso8601 = ((channel->flags & ISC_LOG_ISO8601) != 0); 1722 printtime = ((channel->flags & ISC_LOG_PRINTTIME) != 0); 1723 printtag = ((channel->flags & 1724 (ISC_LOG_PRINTTAG | ISC_LOG_PRINTPREFIX)) != 0 && 1725 lcfg->tag != NULL); 1726 printcolon = ((channel->flags & ISC_LOG_PRINTTAG) != 0 && 1727 lcfg->tag != NULL); 1728 printcategory = ((channel->flags & ISC_LOG_PRINTCATEGORY) != 0); 1729 printmodule = ((channel->flags & ISC_LOG_PRINTMODULE) != 0); 1730 printlevel = ((channel->flags & ISC_LOG_PRINTLEVEL) != 0); 1731 buffered = ((channel->flags & ISC_LOG_BUFFERED) != 0); 1732 1733 if (printtime) { 1734 if (iso8601) { 1735 if (utc) { 1736 time_string = iso8601z_string; 1737 } else { 1738 time_string = iso8601l_string; 1739 } 1740 } else { 1741 time_string = local_time; 1742 } 1743 } else { 1744 time_string = ""; 1745 } 1746 1747 switch (channel->type) { 1748 case ISC_LOG_TOFILE: 1749 if (FILE_MAXREACHED(channel)) { 1750 /* 1751 * If the file can be rolled, OR 1752 * If the file no longer exists, OR 1753 * If the file is less than the maximum 1754 * size, (such as if it had been renamed 1755 * and a new one touched, or it was 1756 * truncated in place) 1757 * ... then close it to trigger 1758 * reopening. 1759 */ 1760 if (FILE_VERSIONS(channel) != 1761 ISC_LOG_ROLLNEVER || 1762 (stat(FILE_NAME(channel), &statbuf) != 0 && 1763 errno == ENOENT) || 1764 statbuf.st_size < FILE_MAXSIZE(channel)) 1765 { 1766 (void)fclose(FILE_STREAM(channel)); 1767 FILE_STREAM(channel) = NULL; 1768 FILE_MAXREACHED(channel) = false; 1769 } else { 1770 /* 1771 * Eh, skip it. 1772 */ 1773 break; 1774 } 1775 } 1776 1777 if (FILE_STREAM(channel) == NULL) { 1778 result = isc_log_open(channel); 1779 if (result != ISC_R_SUCCESS && 1780 result != ISC_R_MAXSIZE && 1781 (channel->flags & ISC_LOG_OPENERR) == 0) 1782 { 1783 syslog(LOG_ERR, 1784 "isc_log_open '%s' " 1785 "failed: %s", 1786 FILE_NAME(channel), 1787 isc_result_totext(result)); 1788 channel->flags |= ISC_LOG_OPENERR; 1789 } 1790 if (result != ISC_R_SUCCESS) { 1791 break; 1792 } 1793 channel->flags &= ~ISC_LOG_OPENERR; 1794 } 1795 /* FALLTHROUGH */ 1796 1797 case ISC_LOG_TOFILEDESC: 1798 fprintf(FILE_STREAM(channel), "%s%s%s%s%s%s%s%s%s%s\n", 1799 printtime ? time_string : "", 1800 printtime ? " " : "", printtag ? lcfg->tag : "", 1801 printcolon ? ": " : "", 1802 printcategory ? category->name : "", 1803 printcategory ? ": " : "", 1804 printmodule ? (module != NULL ? module->name 1805 : "no_module") 1806 : "", 1807 printmodule ? ": " : "", 1808 printlevel ? level_string : "", lctx->buffer); 1809 1810 if (!buffered) { 1811 fflush(FILE_STREAM(channel)); 1812 } 1813 1814 /* 1815 * If the file now exceeds its maximum size 1816 * threshold, note it so that it will not be 1817 * logged to any more. 1818 */ 1819 if (FILE_MAXSIZE(channel) > 0) { 1820 INSIST(channel->type == ISC_LOG_TOFILE); 1821 1822 /* XXXDCL NT fstat/fileno */ 1823 /* XXXDCL complain if fstat fails? */ 1824 if (fstat(fileno(FILE_STREAM(channel)), 1825 &statbuf) >= 0 && 1826 statbuf.st_size > FILE_MAXSIZE(channel)) 1827 { 1828 FILE_MAXREACHED(channel) = true; 1829 } 1830 } 1831 1832 break; 1833 1834 case ISC_LOG_TOSYSLOG: 1835 if (level > 0) { 1836 syslog_level = LOG_DEBUG; 1837 } else if (level < ISC_LOG_CRITICAL) { 1838 syslog_level = LOG_CRIT; 1839 } else { 1840 syslog_level = syslog_map[-level]; 1841 } 1842 1843 (void)syslog( 1844 FACILITY(channel) | syslog_level, 1845 "%s%s%s%s%s%s%s%s%s%s", 1846 printtime ? time_string : "", 1847 printtime ? " " : "", printtag ? lcfg->tag : "", 1848 printcolon ? ": " : "", 1849 printcategory ? category->name : "", 1850 printcategory ? ": " : "", 1851 printmodule ? (module != NULL ? module->name 1852 : "no_module") 1853 : "", 1854 printmodule ? ": " : "", 1855 printlevel ? level_string : "", lctx->buffer); 1856 break; 1857 1858 case ISC_LOG_TONULL: 1859 break; 1860 } 1861 } while (1); 1862 1863 unlock: 1864 UNLOCK(&lctx->lock); 1865 RDUNLOCK(&lctx->lcfg_rwl); 1866 } 1867