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