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(1M) 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(1M) 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(5) repository (due to svc.configd(1M)
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(1M)
73 * has occurred. Failure should be recoverable by restart
74 * of svc.startd(1M).
75 *
76 * LOG_ERR An smf(5) event requiring administrative intervention
77 * has occurred. Includes instance being moved to the
78 * maintenance state.
79 *
80 * LOG_WARNING A potentially destabilizing smf(5) event not requiring
81 * administrative intervention has occurred.
82 *
83 * LOG_NOTICE A noteworthy smf(5) event has occurred. Includes
84 * individual instance failures.
85 *
86 * LOG_INFO A noteworthy operation internal to svc.startd(1M) 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(1M) 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_OTHER:
504 action = gettext("failed: transitioned to "
505 "maintenance (see 'svcs -xv' for details)");
506 break;
507 case START_REQUESTED:
508 assert(outcome != START_REQUESTED);
509 /*FALLTHROUGH*/
510 default:
511 action = gettext("outcome unknown?");
512 }
513
514 message = uu_msprintf("[ %s %s ]\n",
515 inst->ri_i.i_fmri + strlen("svc:/"), action);
516
517 severity = LOG_ERR;
518 }
519
520
521 if (message == NULL) {
522 log_error(LOG_NOTICE,
523 "Could not log boot message for %s: %s.\n",
524 inst->ri_i.i_fmri, uu_strerror(uu_error()));
525 } else {
526 /*
527 * All significant errors should to go to syslog to
528 * communicate appropriate information even for systems
529 * without a console connected during boot. Send the
530 * message to stderr only if the severity is lower than
531 * (indicated by >) LOG_ERR.
532 */
533 if (!st->st_log_login_reached && severity > LOG_ERR) {
534 /*LINTED*/
535 if (fprintf(stderr, message) < 0)
536 log_error(LOG_NOTICE, "Could not log for %s: "
537 "fprintf() failed with %s.\n",
538 inst->ri_i.i_fmri, strerror(errno));
539 } else {
540 log_framework(severity, "%s %s\n",
541 inst->ri_i.i_fmri + strlen("svc:/"), action);
542 }
543
544 uu_free(message);
545 }
546 }
547
548 /*
549 * log_console - log a message to the consoles and to syslog
550 *
551 * This logs a message as-is to the console (and auxiliary consoles),
552 * as well as to the master restarter log.
553 */
554 /*PRINTFLIKE2*/
555 void
556 log_console(int severity, const char *format, ...)
557 {
558 va_list args;
559
560 va_start(args, format);
561 vlog_prefix(severity, "", format, args);
562 va_end(args);
563
564 va_start(args, format);
565 (void) vfprintf(stderr, format, args);
566 va_end(args);
567 }
568
569 /*
570 * void log_init()
571 *
572 * Set up the log files, if necessary, for the current invocation. This
573 * function should be called before any other functions in this file. Set the
574 * syslog(3C) logging mask such that severities of the importance of
575 * LOG_NOTICE and above are passed through, but lower severity messages are
576 * masked out.
577 *
578 * It may be called multiple times to change the logging configuration due to
579 * administrative request.
580 */
581 void
582 log_init()
583 {
584 int dirfd, logfd;
585 char *dir;
586 struct stat sb;
587
588 if (st->st_start_time.tv_sec == 0) {
589 if (getzoneid() != GLOBAL_ZONEID) {
590 st->st_start_time.tv_sec = time(NULL);
591 } else {
592 /*
593 * We need to special-case the BOOT_TIME utmp entry, and
594 * drag that value out of the kernel if it's there.
595 */
596 kstat_ctl_t *kc;
597 kstat_t *ks;
598 kstat_named_t *boot;
599
600 if (((kc = kstat_open()) != 0) &&
601 ((ks = kstat_lookup(kc, "unix", 0, "system_misc"))
602 != NULL) &&
603 (kstat_read(kc, ks, NULL) != -1) &&
604 ((boot = kstat_data_lookup(ks, "boot_time")) !=
605 NULL)) {
606 /*
607 * If we're here, then we've successfully found
608 * the boot_time kstat... use its value.
609 */
610 st->st_start_time.tv_sec = boot->value.ul;
611 } else {
612 st->st_start_time.tv_sec = time(NULL);
613 }
614
615 if (kc)
616 (void) kstat_close(kc);
617 }
618 }
619
620 /*
621 * Establish our timezone if the appropriate directory is available.
622 */
623 if (!st->st_log_timezone_known && stat(FS_TIMEZONE_DIR, &sb) == 0) {
624 tzset();
625 st->st_log_timezone_known = 1;
626 }
627
628 /*
629 * Establish our locale if the appropriate directory is available. Set
630 * the locale string from the environment so we can extract template
631 * information correctly, if the locale directories aren't yet
632 * available.
633 */
634 if (st->st_locale != NULL)
635 free(st->st_locale);
636
637 if ((st->st_locale = getenv("LC_ALL")) == NULL)
638 if ((st->st_locale = getenv("LC_MESSAGES")) == NULL)
639 st->st_locale = getenv("LANG");
640
641 if (!st->st_log_locale_known && stat(FS_LOCALE_DIR, &sb) == 0) {
642 (void) setlocale(LC_ALL, "");
643 st->st_locale = setlocale(LC_MESSAGES, NULL);
644 if (st->st_locale)
645 st->st_log_locale_known = 1;
646
647 (void) textdomain(TEXT_DOMAIN);
648 }
649
650 if (st->st_locale) {
651 st->st_locale = safe_strdup(st->st_locale);
652 xstr_sanitize(st->st_locale);
653 }
654
655 if (logfile) {
656 (void) fclose(logfile);
657 logfile = NULL;
658 }
659
660 /*
661 * Set syslog(3C) behaviour in all cases.
662 */
663 closelog();
664 openlog("svc.startd", LOG_PID | LOG_CONS, LOG_DAEMON);
665 (void) setlogmask(LOG_UPTO(LOG_NOTICE));
666
667 if ((dirfd = log_dir_writeable(LOG_PREFIX_NORMAL)) == -1) {
668 if ((dirfd = log_dir_writeable(LOG_PREFIX_EARLY)) == -1)
669 return;
670 else
671 dir = LOG_PREFIX_EARLY;
672 } else {
673 dir = LOG_PREFIX_NORMAL;
674 }
675
676 st->st_log_prefix = dir;
677
678 (void) umask(fmask);
679 if ((logfd = openat(dirfd, STARTD_DEFAULT_LOG,
680 O_CREAT | O_RDWR | O_APPEND, 0644)) == -1) {
681 (void) close(dirfd);
682 (void) umask(dmask);
683 return;
684 }
685
686 (void) close(dirfd);
687 (void) umask(dmask);
688
689 if ((logfile = fdopen(logfd, "a")) == NULL)
690 if (errno != EROFS)
691 log_error(LOG_WARNING, "can't open logfile %s/%s",
692 dir, STARTD_DEFAULT_LOG);
693
694 if (logfile &&
695 fcntl(fileno(logfile), F_SETFD, FD_CLOEXEC) == -1)
696 log_error(LOG_WARNING,
697 "couldn't mark logfile close-on-exec: %s\n",
698 strerror(errno));
699 }