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
xstrftime_poststart(char * buf,size_t bufsize,struct timeval * time)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
vlog_prefix(int severity,const char * prefix,const char * format,va_list args)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
log_error(int severity,const char * format,...)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
log_framework(int severity,const char * format,...)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
log_framework2(int severity,int flags,const char * format,...)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
log_preexec()264 log_preexec()
265 {
266 closelog();
267 }
268
269 /*
270 * void setlog()
271 * Close file descriptors and redirect output.
272 */
273 void
setlog(const char * logstem)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
log_dir_writeable(const char * path)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
vlog_instance(const char * fmri,const char * logstem,boolean_t canlog,const char * format,va_list args)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
log_instance(const restarter_inst_t * inst,boolean_t canlog,const char * format,...)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
log_instance_fmri(const char * fmri,const char * logstem,boolean_t canlog,const char * format,...)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
log_transition(const restarter_inst_t * inst,start_outcome_t outcome)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
log_console(int severity,const char * format,...)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
log_init()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