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 }