Changeset 23470

Timestamp:

12/19/07 10:13:19 (12 months ago)

Author:

zarzycki@…

Message:

Better shutdown logging.

Location:

trunk/launchd/src

Files:

• launchd.c (modified) (2 diffs)
• launchd.h (modified) (1 diff)
• launchd_core_logic.c (modified) (5 diffs)
• launchd_runtime.c (modified) (10 diffs)
• launchd_runtime.h (modified) (1 diff)

trunk/launchd/src/launchd.c

@@ -96 +96 @@
 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
@@ -262 +263 @@
         }
 
+        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);

trunk/launchd/src/launchd.h

@@ -33 +33 @@
 
 extern bool shutdown_in_progress;
+extern bool fake_shutdown_in_progress;
 extern bool network_up;
 

trunk/launchd/src/launchd_core_logic.c

@@ -2482 +2482 @@
 jobmgr_callback(void *obj, struct kevent *kev)
 {
+        struct timeval tvnow;
         jobmgr_t jm = obj;
+        job_t ji;
 
         switch (kev->filter) {
@@ -2497 +2499 @@
                 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);
@@ -4454 +4474 @@
                 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);
         }
@@ -5750 +5771 @@
 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;
@@ -5769 +5789 @@
 
         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)) {

trunk/launchd/src/launchd_runtime.c

@@ -106 +106 @@
 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);
@@ -117 +116 @@
 };
 static sigset_t sigign_set;
+static FILE *ourlogfile;
+
 
 mach_port_t
@@ -1118 +1119 @@
 }
 
-static FILE *ourlogfile;
-
 void
 runtime_closelog(void)
 {
+        runtime_log_push();
+
         if (ourlogfile) {
                 launchd_assumes(fflush(ourlogfile) == 0);
@@ -1132 +1133 @@
 runtime_fsync(int fd)
 {
+#if 0
         if (do_apple_internal_logging()) {
                 return fcntl(fd, F_FULLFSYNC, NULL);
@@ -1137 +1139 @@
                 return fsync(fd);
         }
+#else
+        return fsync(fd);
+#endif
 }
 
@@ -1167 +1172 @@
 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) {
@@ -1187 +1187 @@
         }
 
-        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
@@ -1366 +1307 @@
 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;
 
@@ -1372 +1317 @@
                 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);
-
-        mig_deallocate(outval, outvalCnt);
+        while ((lm = STAILQ_FIRST(&logmsg_queue))) {
+                timersub(&lm->when, &shutdown_start, &tvd);
+
+                /* 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);
+        }
 }
 
@@ -1425 +1404 @@
 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);

trunk/launchd/src/launchd_runtime.h

@@ -150 +150 @@
 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);