Revision: 23470 http://trac.macosforge.org/projects/launchd/changeset/23470 Author: zarzycki@apple.com Date: 2007-12-19 10:13:19 -0800 (Wed, 19 Dec 2007) Log Message: ----------- Better shutdown logging. Modified Paths: -------------- trunk/launchd/src/launchd.c trunk/launchd/src/launchd.h trunk/launchd/src/launchd_core_logic.c trunk/launchd/src/launchd_runtime.c trunk/launchd/src/launchd_runtime.h Modified: trunk/launchd/src/launchd.c =================================================================== --- trunk/launchd/src/launchd.c 2007-12-19 17:40:56 UTC (rev 23469) +++ trunk/launchd/src/launchd.c 2007-12-19 18:13:19 UTC (rev 23470) @@ -95,12 +95,13 @@ static void handle_pid1_crashes_separately(void); static void prep_shutdown_log_dir(void); -static bool re_exec_in_single_user_mode = false; +static bool re_exec_in_single_user_mode; static void *crash_addr; static pid_t crash_pid; -bool shutdown_in_progress = false; -bool network_up = false; +bool shutdown_in_progress; +bool fake_shutdown_in_progress; +bool network_up; int main(int argc, char *const *argv) @@ -261,12 +262,12 @@ prep_shutdown_log_dir(); } + runtime_log_push(); + if (launchd_assumes(gettimeofday(&tvnow, NULL) != -1)) { runtime_syslog(LOG_NOTICE, "Shutdown began at: %lu.%06u", tvnow.tv_sec, tvnow.tv_usec); } - launchd_log_vm_stats(); - launchd_assert(jobmgr_shutdown(root_jobmgr) != NULL); } Modified: trunk/launchd/src/launchd.h =================================================================== --- trunk/launchd/src/launchd.h 2007-12-19 17:40:56 UTC (rev 23469) +++ trunk/launchd/src/launchd.h 2007-12-19 18:13:19 UTC (rev 23470) @@ -32,6 +32,7 @@ struct conncb; extern bool shutdown_in_progress; +extern bool fake_shutdown_in_progress; extern bool network_up; bool init_check_pid(pid_t); Modified: trunk/launchd/src/launchd_core_logic.c =================================================================== --- trunk/launchd/src/launchd_core_logic.c 2007-12-19 17:40:56 UTC (rev 23469) +++ trunk/launchd/src/launchd_core_logic.c 2007-12-19 18:13:19 UTC (rev 23470) @@ -2481,7 +2481,9 @@ void jobmgr_callback(void *obj, struct kevent *kev) { + struct timeval tvnow; jobmgr_t jm = obj; + job_t ji; switch (kev->filter) { case EVFILT_PROC: @@ -2496,6 +2498,24 @@ return launchd_shutdown(); case SIGUSR1: return calendarinterval_callback(); + case SIGUSR2: + fake_shutdown_in_progress = true; + runtime_setlogmask(LOG_UPTO(LOG_DEBUG)); + + runtime_closelog(); /* HACK -- force 'start' time to be set */ + + if (getpid() == 1 && jobmgr_assumes(jm, gettimeofday(&tvnow, NULL) != -1)) { + jobmgr_log(jm, LOG_NOTICE, "Anticipatory shutdown began at: %lu.%06u", tvnow.tv_sec, tvnow.tv_usec); + LIST_FOREACH(ji, &root_jobmgr->jobs, sle) { + if (ji->per_user && ji->p) { + job_assumes(ji, runtime_kill(ji->p, SIGUSR2) != -1); + } + } + } else { + jobmgr_log(jm, LOG_NOTICE, "Anticipatory per-user launchd shutdown"); + } + + return; default: return (void)jobmgr_assumes(jm, false); } @@ -4453,6 +4473,7 @@ if (!jm) { jobmgr_assumes(jmr, kevent_mod(SIGTERM, EVFILT_SIGNAL, EV_ADD, 0, 0, jmr) != -1); jobmgr_assumes(jmr, kevent_mod(SIGUSR1, EVFILT_SIGNAL, EV_ADD, 0, 0, jmr) != -1); + jobmgr_assumes(jmr, kevent_mod(SIGUSR2, EVFILT_SIGNAL, EV_ADD, 0, 0, jmr) != -1); jobmgr_assumes(jmr, kevent_mod(0, EVFILT_FS, EV_ADD, VQ_MOUNT|VQ_UNMOUNT|VQ_UPDATE, 0, jmr) != -1); } @@ -5749,7 +5770,6 @@ kern_return_t job_mig_check_in(job_t j, name_t servicename, mach_port_t *serviceportp) { - static pid_t last_warned_pid = 0; struct machservice *ms; struct ldcred ldc; job_t jo; @@ -5768,11 +5788,14 @@ } if ((jo = machservice_job(ms)) != j) { + static pid_t last_warned_pid; + if (last_warned_pid != ldc.pid) { job_log(j, LOG_NOTICE, "Check-in of Mach service failed. The service \"%s\" is owned by: %s", servicename, jo->label); last_warned_pid = ldc.pid; } - return BOOTSTRAP_NOT_PRIVILEGED; + + return BOOTSTRAP_NOT_PRIVILEGED; } if (machservice_active(ms)) { job_log(j, LOG_WARNING, "Check-in of Mach service failed. Already active: %s", servicename); Modified: trunk/launchd/src/launchd_runtime.c =================================================================== --- trunk/launchd/src/launchd_runtime.c 2007-12-19 17:40:56 UTC (rev 23469) +++ trunk/launchd/src/launchd_runtime.c 2007-12-19 18:13:19 UTC (rev 23470) @@ -105,7 +105,6 @@ static mach_port_t drain_reply_port; static void runtime_log_uncork_pending_drain(void); static kern_return_t runtime_log_pack(vm_offset_t *outval, mach_msg_type_number_t *outvalCnt); -static void runtime_log_push(void); static bool logmsg_add(struct runtime_syslog_attr *attr, int err_num, const char *msg); static void logmsg_remove(struct logmsg_s *lm); @@ -116,7 +115,9 @@ SIGXFSZ, SIGVTALRM, SIGPROF, SIGWINCH, SIGINFO, SIGUSR1, SIGUSR2 }; static sigset_t sigign_set; +static FILE *ourlogfile; + mach_port_t runtime_get_kernel_port(void) { @@ -1117,11 +1118,11 @@ return close(fd); } -static FILE *ourlogfile; - void runtime_closelog(void) { + runtime_log_push(); + if (ourlogfile) { launchd_assumes(fflush(ourlogfile) == 0); launchd_assumes(runtime_fsync(fileno(ourlogfile)) != -1); @@ -1131,11 +1132,15 @@ int runtime_fsync(int fd) { +#if 0 if (do_apple_internal_logging()) { return fcntl(fd, F_FULLFSYNC, NULL); } else { return fsync(fd); } +#else + return fsync(fd); +#endif } int @@ -1166,13 +1171,8 @@ void runtime_vsyslog(struct runtime_syslog_attr *attr, const char *message, va_list args) { - static pthread_mutex_t ourlock = PTHREAD_MUTEX_INITIALIZER; - static struct timeval shutdown_start; - static struct timeval prev_msg; - struct timeval tvnow, tvd_total, tvd_msg_delta = { 0, 0 }; int saved_errno = errno; char newmsg[10000]; - size_t i, j; if (attr->priority == LOG_APPLEONLY) { if (do_apple_internal_logging()) { @@ -1186,70 +1186,11 @@ return; } - if (getpid() != 1 || !shutdown_in_progress) { - vsnprintf(newmsg, sizeof(newmsg), message, args); - logmsg_add(attr, saved_errno, newmsg); - return; - } - - if (shutdown_start.tv_sec == 0) { - gettimeofday(&shutdown_start, NULL); - } - - if (gettimeofday(&tvnow, NULL) == -1) { - tvnow.tv_sec = 0; - tvnow.tv_usec = 0; - } - - pthread_mutex_lock(&ourlock); - - if (ourlogfile == NULL) { - rename("/var/log/launchd-shutdown.log", "/var/log/launchd-shutdown.log.1"); - ourlogfile = fopen("/var/log/launchd-shutdown.log", "a"); - } - - pthread_mutex_unlock(&ourlock); - - if (ourlogfile == NULL) { - return; - } - - if (message == NULL) { - return; - } - - timersub(&tvnow, &shutdown_start, &tvd_total); - - if (prev_msg.tv_sec != 0) { - timersub(&tvnow, &prev_msg, &tvd_msg_delta); - } - - prev_msg = tvnow; - - snprintf(newmsg, sizeof(newmsg), "%3ld.%06d%4ld.%06d%6u %-40s%6u %-40s ", - tvd_total.tv_sec, tvd_total.tv_usec, - tvd_msg_delta.tv_sec, tvd_msg_delta.tv_usec, - attr->from_pid, attr->from_name, - attr->about_pid, attr->about_name); - - for (i = 0, j = strlen(newmsg); message[i];) { - if (message[i] == '%' && message[i + 1] == 'm') { - char *errs = strerror(saved_errno); - strcpy(newmsg + j, errs ? errs : "unknown error"); - j += strlen(newmsg + j); - i += 2; - } else { - newmsg[j] = message[i]; - j++; - i++; - } - } - - strcpy(newmsg + j, "\n"); - - vfprintf(ourlogfile, newmsg, args); + vsnprintf(newmsg, sizeof(newmsg), message, args); + logmsg_add(attr, saved_errno, newmsg); } + bool logmsg_add(struct runtime_syslog_attr *attr, int err_num, const char *msg) { @@ -1365,24 +1306,62 @@ void runtime_log_push(void) { + static pthread_mutex_t ourlock = PTHREAD_MUTEX_INITIALIZER; + static struct timeval shutdown_start; + struct timeval tvd; mach_msg_type_number_t outvalCnt; + struct logmsg_s *lm; vm_offset_t outval; if (logmsg_queue_cnt == 0) { launchd_assumes(STAILQ_EMPTY(&logmsg_queue)); return; - } else if (getpid() == 1) { + } else if (getpid() != 1) { + if (runtime_log_pack(&outval, &outvalCnt) == 0) { + launchd_assumes(_vprocmgr_log_forward(inherited_bootstrap_port, (void *)outval, outvalCnt) == NULL); + mig_deallocate(outval, outvalCnt); + } + return; + } + + if (!shutdown_in_progress && !fake_shutdown_in_progress) { runtime_log_uncork_pending_drain(); return; } - if (runtime_log_pack(&outval, &outvalCnt) != 0) { + if (shutdown_start.tv_sec == 0) { + gettimeofday(&shutdown_start, NULL); + launchd_log_vm_stats(); + } + + + pthread_mutex_lock(&ourlock); + + if (ourlogfile == NULL) { + rename("/var/log/launchd-shutdown.log", "/var/log/launchd-shutdown.log.1"); + ourlogfile = fopen("/var/log/launchd-shutdown.log", "a"); + } + + pthread_mutex_unlock(&ourlock); + + if (!ourlogfile) { return; } - launchd_assumes(_vprocmgr_log_forward(inherited_bootstrap_port, (void *)outval, outvalCnt) == NULL); + while ((lm = STAILQ_FIRST(&logmsg_queue))) { + timersub(&lm->when, &shutdown_start, &tvd); - mig_deallocate(outval, outvalCnt); + /* don't ask */ + if (tvd.tv_sec < 0) { + tvd.tv_sec = 0; + tvd.tv_usec = 0; + } + + fprintf(ourlogfile, "%3ld.%06d%6u %-40s%6u %-40s %s\n", tvd.tv_sec, tvd.tv_usec, + lm->from_pid, lm->from_name, lm->about_pid, lm->about_name, lm->msg); + + logmsg_remove(lm); + } } kern_return_t @@ -1424,10 +1403,9 @@ kern_return_t runtime_log_drain(mach_port_t srp, vm_offset_t *outval, mach_msg_type_number_t *outvalCnt) { - if (logmsg_queue_cnt == 0) { - launchd_assumes(STAILQ_EMPTY(&logmsg_queue)); - launchd_assumes(drain_reply_port == 0); + launchd_assumes(drain_reply_port == 0); + if ((logmsg_queue_cnt == 0) || shutdown_in_progress || fake_shutdown_in_progress) { drain_reply_port = srp; launchd_assumes(launchd_mport_notify_req(drain_reply_port, MACH_NOTIFY_DEAD_NAME) == KERN_SUCCESS); Modified: trunk/launchd/src/launchd_runtime.h =================================================================== --- trunk/launchd/src/launchd_runtime.h 2007-12-19 17:40:56 UTC (rev 23469) +++ trunk/launchd/src/launchd_runtime.h 2007-12-19 18:13:19 UTC (rev 23470) @@ -149,6 +149,7 @@ void runtime_closelog(void); void runtime_syslog(int pri, const char *message, ...) __attribute__((format(printf, 2, 3))); void runtime_vsyslog(struct runtime_syslog_attr *attr, const char *message, va_list args) __attribute__((format(printf, 2, 0))); +void runtime_log_push(void); kern_return_t launchd_set_bport(mach_port_t name);