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