1 /* 2 * CDDL HEADER START 3 * 4 * The contents of this file are subject to the terms of the 5 * Common Development and Distribution License (the "License"). 6 * You may not use this file except in compliance with the License. 7 * 8 * You can obtain a copy of the license at usr/src/OPENSOLARIS.LICENSE 9 * or http://www.opensolaris.org/os/licensing. 10 * See the License for the specific language governing permissions 11 * and limitations under the License. 12 * 13 * When distributing Covered Code, include this CDDL HEADER in each 14 * file and include the License file at usr/src/OPENSOLARIS.LICENSE. 15 * If applicable, add the following below this CDDL HEADER, with the 16 * fields enclosed by brackets "[]" replaced with your own identifying 17 * information: Portions Copyright [yyyy] [name of copyright owner] 18 * 19 * CDDL HEADER END 20 */ 21 /* 22 * Copyright 2010 Sun Microsystems, Inc. All rights reserved. 23 * Use is subject to license terms. 24 * Copyright 2011 Nexenta Systems. All rights reserved. 25 * Copyright 2017 RackTop Systems. 26 */ 27 28 /* 29 * log.c - debugging and logging functions 30 * 31 * Logging destinations 32 * svc.startd(8) supports three logging destinations: the system log, a 33 * daemon-specific log (in the /var/svc/log hierarchy by default), and to the 34 * standard output (redirected to the /var/svc/log/svc.startd.log file by 35 * default). Any or all of these destinations may be used to 36 * communicate a specific message; the audiences for each destination differ. 37 * 38 * Generic messages associated with svc.startd(8) are made by the 39 * log_framework() and log_error() functions. For these messages, svc.startd 40 * logs under its own name and under the LOG_DAEMON facility when issuing 41 * events to the system log. By design, severities below LOG_NOTICE are never 42 * issued to the system log. 43 * 44 * Messages associated with a specific service instance are logged using the 45 * log_instance() or log_instance_fmri() functions. These messages are always 46 * sent to the appropriate per-instance log file. 47 * 48 * In the case of verbose or debug boot, the log_transition() function 49 * displays messages regarding instance transitions to the system console, 50 * until the expected login services are available. 51 * 52 * Finally, log_console() displays messages to the system consoles and 53 * the master restarter log file. This is used when booting to a milestone 54 * other than 'all'. 55 * 56 * Logging detail 57 * The constants for severity from <syslog.h> are reused, with a specific 58 * convention here. (It is worth noting that the #define values for the LOG_ 59 * levels are such that more important severities have lower values.) The 60 * severity determines the importance of the event, and its addressibility by 61 * the administrator. Each severity level's use is defined below, along with 62 * an illustrative example. 63 * 64 * LOG_EMERG Not used presently. 65 * 66 * LOG_ALERT An unrecoverable operation requiring external 67 * intervention has occurred. Includes an inability to 68 * write to the smf(7) repository (due to svc.configd(8) 69 * absence, due to permissions failures, etc.). Message 70 * should identify component at fault. 71 * 72 * LOG_CRIT An unrecoverable operation internal to svc.startd(8) 73 * has occurred. Failure should be recoverable by restart 74 * of svc.startd(8). 75 * 76 * LOG_ERR An smf(7) event requiring administrative intervention 77 * has occurred. Includes instance being moved to the 78 * maintenance state. 79 * 80 * LOG_WARNING A potentially destabilizing smf(7) event not requiring 81 * administrative intervention has occurred. 82 * 83 * LOG_NOTICE A noteworthy smf(7) event has occurred. Includes 84 * individual instance failures. 85 * 86 * LOG_INFO A noteworthy operation internal to svc.startd(8) has 87 * occurred. Includes recoverable failures or otherwise 88 * unexpected outcomes. 89 * 90 * LOG_DEBUG An internal operation only of interest to a 91 * svc.startd(8) developer has occurred. 92 * 93 * Logging configuration 94 * The preferred approach is to set the logging property values 95 * in the options property group of the svc.startd default instance. The 96 * valid values are "quiet", "verbose", and "debug". "quiet" is the default; 97 * "verbose" and "debug" allow LOG_INFO and LOG_DEBUG logging requests to 98 * reach the svc.startd.log file, respectively. 99 */ 100 101 #include <sys/stat.h> 102 #include <sys/statvfs.h> 103 #include <sys/time.h> 104 #include <sys/types.h> 105 #include <assert.h> 106 #include <errno.h> 107 #include <fcntl.h> 108 #include <kstat.h> 109 #include <libgen.h> 110 #include <libintl.h> 111 #include <libuutil.h> 112 #include <locale.h> 113 #include <malloc.h> 114 #include <pthread.h> 115 #include <stdarg.h> 116 #include <stdio.h> 117 #include <strings.h> 118 #include <syslog.h> 119 #include <unistd.h> 120 #include <zone.h> 121 122 #include "startd.h" 123 124 125 #define LOGBUF_SZ (60 * 80) /* 60 lines */ 126 127 static FILE *logfile = NULL; 128 129 /* 130 * This parameter can be modified using mdb to turn on & off extended 131 * internal debug logging. Although a performance loss can be expected. 132 */ 133 static int internal_debug_flags = 0x0; 134 135 #ifndef NDEBUG 136 /* 137 * This is a circular buffer for all (even those not emitted externally) 138 * logging messages. To read it properly you should start after the first 139 * null, go until the second, and then go back to the beginning until the 140 * first null. Or use ::startd_log in mdb. 141 */ 142 static char logbuf[LOGBUF_SZ] = ""; 143 static pthread_mutex_t logbuf_mutex = PTHREAD_MUTEX_INITIALIZER; 144 #endif 145 146 static void 147 xstrftime_poststart(char *buf, size_t bufsize, struct timeval *time) 148 { 149 long sec, usec; 150 151 sec = time->tv_sec - st->st_start_time.tv_sec; 152 usec = time->tv_usec - st->st_start_time.tv_usec; 153 154 if (usec < 0) { 155 sec -= 1; 156 usec += 1000000; 157 } 158 159 (void) snprintf(buf, bufsize, "start + %d.%02ds", sec, usec / 10000); 160 } 161 162 static void 163 vlog_prefix(int severity, const char *prefix, const char *format, va_list args) 164 { 165 char buf[512], *cp; 166 char timebuf[LOG_DATE_SIZE]; 167 struct timeval now; 168 struct tm ltime; 169 170 #ifdef NDEBUG 171 if (severity > st->st_log_level_min) 172 return; 173 #endif 174 175 if (gettimeofday(&now, NULL) != 0) 176 (void) fprintf(stderr, "gettimeofday(3C) failed: %s\n", 177 strerror(errno)); 178 179 if (st->st_log_timezone_known) 180 (void) strftime(timebuf, sizeof (timebuf), "%b %e %T", 181 localtime_r(&now.tv_sec, <ime)); 182 else 183 xstrftime_poststart(timebuf, sizeof (timebuf), &now); 184 185 (void) snprintf(buf, sizeof (buf), "%s/%d%s: ", timebuf, pthread_self(), 186 prefix); 187 cp = strchr(buf, '\0'); 188 (void) vsnprintf(cp, sizeof (buf) - (cp - buf), format, args); 189 190 #ifndef NDEBUG 191 /* Copy into logbuf. */ 192 (void) pthread_mutex_lock(&logbuf_mutex); 193 if (strlen(logbuf) + strlen(buf) + 1 <= sizeof (logbuf)) 194 (void) strcat(logbuf, buf); 195 else 196 (void) strlcpy(logbuf, buf, sizeof (logbuf)); 197 (void) pthread_mutex_unlock(&logbuf_mutex); 198 199 if (severity > st->st_log_level_min) 200 return; 201 #endif 202 203 if (st->st_log_flags & STARTD_LOG_FILE && logfile) { 204 (void) fputs(buf, logfile); 205 (void) fflush(logfile); 206 } 207 if (st->st_log_flags & STARTD_LOG_TERMINAL) 208 (void) fputs(buf, stdout); 209 if (st->st_log_flags & STARTD_LOG_SYSLOG && st->st_log_timezone_known) 210 vsyslog(severity, format, args); 211 } 212 213 /*PRINTFLIKE2*/ 214 void 215 log_error(int severity, const char *format, ...) 216 { 217 va_list args; 218 219 va_start(args, format); 220 vlog_prefix(severity, " ERROR", format, args); 221 va_end(args); 222 } 223 224 /*PRINTFLIKE2*/ 225 void 226 log_framework(int severity, const char *format, ...) 227 { 228 va_list args; 229 230 va_start(args, format); 231 vlog_prefix(severity, "", format, args); 232 va_end(args); 233 } 234 235 /* 236 * log_framework2() differs from log_framework() by the fact that 237 * some checking are done before logging the messages in the internal 238 * buffer for performance reasons. 239 * The messages aren't logged if: 240 * - severity >= LOG_DEBUG and 241 * - st_log_level_min < LOG_DEBUG and 242 * - internal_debug_flags is not set for 'flags' 243 */ 244 void 245 log_framework2(int severity, int flags, const char *format, ...) 246 { 247 va_list args; 248 249 if ((severity < LOG_DEBUG) || 250 (internal_debug_flags & flags) || 251 st->st_log_level_min >= LOG_DEBUG) { 252 va_start(args, format); 253 vlog_prefix(severity, "", format, args); 254 va_end(args); 255 } 256 } 257 258 /* 259 * void log_preexec() 260 * 261 * log_preexec() should be invoked prior to any exec(2) calls, to prevent the 262 * logfile and syslogd file descriptors from being leaked to child processes. 263 * Why openlog(3C) lacks a close-on-exec option is a minor mystery. 264 */ 265 void 266 log_preexec() 267 { 268 closelog(); 269 } 270 271 /* 272 * void setlog() 273 * Close file descriptors and redirect output. 274 */ 275 void 276 setlog(const char *logstem) 277 { 278 int fd; 279 char logfile[PATH_MAX]; 280 281 closefrom(0); 282 283 (void) open("/dev/null", O_RDONLY); 284 285 (void) snprintf(logfile, PATH_MAX, "%s/%s", st->st_log_prefix, logstem); 286 287 (void) umask(fmask); 288 fd = open(logfile, O_WRONLY|O_CREAT|O_APPEND, 289 S_IRUSR|S_IWUSR|S_IRGRP|S_IROTH); 290 (void) umask(dmask); 291 292 if (fd == -1) 293 return; 294 295 (void) dup2(fd, STDOUT_FILENO); 296 (void) dup2(fd, STDERR_FILENO); 297 298 if (fd != STDOUT_FILENO && fd != STDERR_FILENO) 299 startd_close(fd); 300 } 301 302 static int 303 log_dir_writeable(const char *path) 304 { 305 int fd; 306 struct statvfs svb; 307 308 if ((fd = open(path, O_RDONLY, 0644)) == -1) 309 return (-1); 310 311 if (fstatvfs(fd, &svb) == -1) 312 return (-1); 313 314 if (svb.f_flag & ST_RDONLY) { 315 (void) close(fd); 316 317 fd = -1; 318 } 319 320 return (fd); 321 } 322 323 static void 324 vlog_instance(const char *fmri, const char *logstem, boolean_t canlog, 325 const char *format, va_list args) 326 { 327 char logfile[PATH_MAX]; 328 char *message; 329 char omessage[1024]; 330 int fd, err; 331 char timebuf[LOG_DATE_SIZE]; 332 struct tm ltime; 333 struct timeval now; 334 335 (void) snprintf(logfile, PATH_MAX, "%s/%s", st->st_log_prefix, 336 logstem); 337 338 (void) umask(fmask); 339 fd = open(logfile, O_WRONLY|O_CREAT|O_APPEND, 340 S_IRUSR|S_IWUSR|S_IRGRP|S_IROTH); 341 err = errno; 342 (void) umask(dmask); 343 344 if (fd == -1) { 345 if (canlog) 346 log_error(LOG_NOTICE, "Could not log for %s: open(%s) " 347 "failed with %s.\n", fmri, logfile, strerror(err)); 348 349 return; 350 } 351 352 (void) vsnprintf(omessage, sizeof (omessage), format, args); 353 354 if (gettimeofday(&now, NULL) != 0) 355 (void) fprintf(stderr, "gettimeofday(3C) failed: %s\n", 356 strerror(errno)); 357 358 if (st->st_log_timezone_known) 359 (void) strftime(timebuf, sizeof (timebuf), "%b %e %T", 360 localtime_r(&now.tv_sec, <ime)); 361 else 362 xstrftime_poststart(timebuf, sizeof (timebuf), &now); 363 364 message = uu_msprintf("[ %s %s ]\n", timebuf, omessage); 365 366 if (message == NULL) { 367 if (canlog) 368 log_error(LOG_NOTICE, "Could not log for %s: %s.\n", 369 fmri, uu_strerror(uu_error())); 370 } else { 371 if (write(fd, message, strlen(message)) < 0 && canlog) 372 log_error(LOG_NOTICE, "Could not log for %s: write(%d) " 373 "failed with %s.\n", fmri, fd, 374 strerror(errno)); 375 376 uu_free(message); 377 } 378 379 if (close(fd) != 0 && canlog) 380 log_framework(LOG_NOTICE, "close(%d) failed: %s.\n", fd, 381 strerror(errno)); 382 } 383 384 /* 385 * void log_instance(const restarter_inst_t *, boolean_t, const char *, ...) 386 * 387 * The log_instance() format is "[ month day time message ]". (The 388 * brackets distinguish svc.startd messages from method output.) We avoid 389 * calling log_*() functions on error when canlog is not set, since we may 390 * be called from a child process. 391 * 392 * When adding new calls to this function, consider: If this is called before 393 * any instances have started, then it should be called with canlog clear, 394 * lest we spew errors to the console when booted on the miniroot. 395 */ 396 /*PRINTFLIKE3*/ 397 void 398 log_instance(const restarter_inst_t *inst, boolean_t canlog, 399 const char *format, ...) 400 { 401 va_list args; 402 403 va_start(args, format); 404 vlog_instance(inst->ri_i.i_fmri, inst->ri_logstem, canlog, format, 405 args); 406 va_end(args); 407 } 408 409 /* 410 * void log_instance_fmri(const char *, const char *,boolean_t, const char *, 411 * ...) 412 * 413 * The log_instance_fmri() format is "[ month day time message ]". (The 414 * brackets distinguish svc.startd messages from method output.) We avoid 415 * calling log_*() functions on error when canlog is not set, since we may 416 * be called from a child process. 417 * 418 * For new calls to this function, see the warning in log_instance()'s 419 * comment. 420 */ 421 /*PRINTFLIKE4*/ 422 void 423 log_instance_fmri(const char *fmri, const char *logstem, boolean_t canlog, 424 const char *format, ...) 425 { 426 va_list args; 427 428 va_start(args, format); 429 vlog_instance(fmri, logstem, canlog, format, args); 430 va_end(args); 431 } 432 433 /* 434 * void log_transition(const restarter_inst_t *, start_outcome_t) 435 * 436 * The log_transition() format is 437 * 438 * [ _service_fmri_ _participle_ (_common_name_) ] 439 * 440 * Again, brackets separate messages from specific service instance output to 441 * the console. 442 */ 443 void 444 log_transition(const restarter_inst_t *inst, start_outcome_t outcome) 445 { 446 char *message; 447 char omessage[1024]; 448 char *action; 449 int severity; 450 451 if (outcome == START_REQUESTED) { 452 char *cname = NULL; 453 454 cname = inst->ri_common_name; 455 if (cname == NULL) 456 cname = inst->ri_C_common_name; 457 458 if (!(st->st_boot_flags & STARTD_BOOT_VERBOSE)) 459 return; 460 461 if (inst->ri_start_index > 1) 462 return; 463 464 if (cname) 465 (void) snprintf(omessage, sizeof (omessage), " (%s)", 466 cname); 467 else 468 *omessage = '\0'; 469 470 action = gettext("starting"); 471 472 message = uu_msprintf("[ %s %s%s ]\n", 473 inst->ri_i.i_fmri + strlen("svc:/"), action, 474 omessage); 475 476 severity = LOG_INFO; 477 } else { 478 switch (outcome) { 479 case DEGRADE_REQUESTED: 480 action = gettext("transitioned to degraded by " 481 "request (see 'svcs -xv' for details)"); 482 break; 483 case MAINT_REQUESTED: 484 action = gettext("transitioned to maintenance by " 485 "request (see 'svcs -xv' for details)"); 486 break; 487 case START_FAILED_REPEATEDLY: 488 action = gettext("failed repeatedly: transitioned to " 489 "maintenance (see 'svcs -xv' for details)"); 490 break; 491 case START_FAILED_CONFIGURATION: 492 action = gettext("misconfigured: transitioned to " 493 "maintenance (see 'svcs -xv' for details)"); 494 break; 495 case START_FAILED_FATAL: 496 action = gettext("failed fatally: transitioned to " 497 "maintenance (see 'svcs -xv' for details)"); 498 break; 499 case START_FAILED_TIMEOUT_FATAL: 500 action = gettext("timed out: transitioned to " 501 "maintenance (see 'svcs -xv' for details)"); 502 break; 503 case START_FAILED_DEGRADED: 504 action = gettext("transitioned to degraded " 505 "(see 'svcs -xv' for details)"); 506 break; 507 case START_FAILED_OTHER: 508 action = gettext("failed: transitioned to " 509 "maintenance (see 'svcs -xv' for details)"); 510 break; 511 case START_REQUESTED: 512 assert(outcome != START_REQUESTED); 513 /*FALLTHROUGH*/ 514 default: 515 action = gettext("outcome unknown?"); 516 } 517 518 message = uu_msprintf("[ %s %s ]\n", 519 inst->ri_i.i_fmri + strlen("svc:/"), action); 520 521 severity = LOG_ERR; 522 } 523 524 525 if (message == NULL) { 526 log_error(LOG_NOTICE, 527 "Could not log boot message for %s: %s.\n", 528 inst->ri_i.i_fmri, uu_strerror(uu_error())); 529 } else { 530 /* 531 * All significant errors should to go to syslog to 532 * communicate appropriate information even for systems 533 * without a console connected during boot. Send the 534 * message to stderr only if the severity is lower than 535 * (indicated by >) LOG_ERR. 536 */ 537 if (!st->st_log_login_reached && severity > LOG_ERR) { 538 /*LINTED*/ 539 if (fprintf(stderr, message) < 0) 540 log_error(LOG_NOTICE, "Could not log for %s: " 541 "fprintf() failed with %s.\n", 542 inst->ri_i.i_fmri, strerror(errno)); 543 } else { 544 log_framework(severity, "%s %s\n", 545 inst->ri_i.i_fmri + strlen("svc:/"), action); 546 } 547 548 uu_free(message); 549 } 550 } 551 552 /* 553 * log_console - log a message to the consoles and to syslog 554 * 555 * This logs a message as-is to the console (and auxiliary consoles), 556 * as well as to the master restarter log. 557 */ 558 /*PRINTFLIKE2*/ 559 void 560 log_console(int severity, const char *format, ...) 561 { 562 va_list args; 563 564 va_start(args, format); 565 vlog_prefix(severity, "", format, args); 566 va_end(args); 567 568 va_start(args, format); 569 (void) vfprintf(stderr, format, args); 570 va_end(args); 571 } 572 573 /* 574 * void log_init() 575 * 576 * Set up the log files, if necessary, for the current invocation. This 577 * function should be called before any other functions in this file. Set the 578 * syslog(3C) logging mask such that severities of the importance of 579 * LOG_NOTICE and above are passed through, but lower severity messages are 580 * masked out. 581 * 582 * It may be called multiple times to change the logging configuration due to 583 * administrative request. 584 */ 585 void 586 log_init() 587 { 588 int dirfd, logfd; 589 char *dir; 590 struct stat sb; 591 592 if (st->st_start_time.tv_sec == 0) { 593 if (getzoneid() != GLOBAL_ZONEID) { 594 st->st_start_time.tv_sec = time(NULL); 595 } else { 596 /* 597 * We need to special-case the BOOT_TIME utmp entry, and 598 * drag that value out of the kernel if it's there. 599 */ 600 kstat_ctl_t *kc; 601 kstat_t *ks; 602 kstat_named_t *boot; 603 604 if (((kc = kstat_open()) != 0) && 605 ((ks = kstat_lookup(kc, "unix", 0, "system_misc")) 606 != NULL) && 607 (kstat_read(kc, ks, NULL) != -1) && 608 ((boot = kstat_data_lookup(ks, "boot_time")) != 609 NULL)) { 610 /* 611 * If we're here, then we've successfully found 612 * the boot_time kstat... use its value. 613 */ 614 st->st_start_time.tv_sec = boot->value.ul; 615 } else { 616 st->st_start_time.tv_sec = time(NULL); 617 } 618 619 if (kc) 620 (void) kstat_close(kc); 621 } 622 } 623 624 /* 625 * Establish our timezone if the appropriate directory is available. 626 */ 627 if (!st->st_log_timezone_known && stat(FS_TIMEZONE_DIR, &sb) == 0) { 628 tzset(); 629 st->st_log_timezone_known = 1; 630 } 631 632 /* 633 * Establish our locale if the appropriate directory is available. Set 634 * the locale string from the environment so we can extract template 635 * information correctly, if the locale directories aren't yet 636 * available. 637 */ 638 if (st->st_locale != NULL) 639 free(st->st_locale); 640 641 if ((st->st_locale = getenv("LC_ALL")) == NULL) 642 if ((st->st_locale = getenv("LC_MESSAGES")) == NULL) 643 st->st_locale = getenv("LANG"); 644 645 if (!st->st_log_locale_known && stat(FS_LOCALE_DIR, &sb) == 0) { 646 (void) setlocale(LC_ALL, ""); 647 st->st_locale = setlocale(LC_MESSAGES, NULL); 648 if (st->st_locale) 649 st->st_log_locale_known = 1; 650 651 (void) textdomain(TEXT_DOMAIN); 652 } 653 654 if (st->st_locale) { 655 st->st_locale = safe_strdup(st->st_locale); 656 xstr_sanitize(st->st_locale); 657 } 658 659 if (logfile) { 660 (void) fclose(logfile); 661 logfile = NULL; 662 } 663 664 /* 665 * Set syslog(3C) behaviour in all cases. 666 */ 667 closelog(); 668 openlog("svc.startd", LOG_PID | LOG_CONS, LOG_DAEMON); 669 (void) setlogmask(LOG_UPTO(LOG_NOTICE)); 670 671 if ((dirfd = log_dir_writeable(LOG_PREFIX_NORMAL)) == -1) { 672 if ((dirfd = log_dir_writeable(LOG_PREFIX_EARLY)) == -1) 673 return; 674 else 675 dir = LOG_PREFIX_EARLY; 676 } else { 677 dir = LOG_PREFIX_NORMAL; 678 } 679 680 st->st_log_prefix = dir; 681 682 (void) umask(fmask); 683 if ((logfd = openat(dirfd, STARTD_DEFAULT_LOG, 684 O_CREAT | O_RDWR | O_APPEND, 0644)) == -1) { 685 (void) close(dirfd); 686 (void) umask(dmask); 687 return; 688 } 689 690 (void) close(dirfd); 691 (void) umask(dmask); 692 693 if ((logfile = fdopen(logfd, "a")) == NULL) 694 if (errno != EROFS) 695 log_error(LOG_WARNING, "can't open logfile %s/%s", 696 dir, STARTD_DEFAULT_LOG); 697 698 if (logfile && 699 fcntl(fileno(logfile), F_SETFD, FD_CLOEXEC) == -1) 700 log_error(LOG_WARNING, 701 "couldn't mark logfile close-on-exec: %s\n", 702 strerror(errno)); 703 } 704