Revision: 23087 http://trac.macosforge.org/projects/launchd/changeset/23087 Author: zarzycki@apple.com Date: 2007-02-19 15:21:02 -0800 (Mon, 19 Feb 2007) Log Message: ----------- More debugging goo. Modified Paths: -------------- trunk/launchd/src/launchd.c trunk/launchd/src/launchd_core_logic.c trunk/launchd/src/launchd_runtime.c trunk/launchd/src/launchd_runtime.h trunk/launchd/src/launchd_unix_ipc.c trunk/launchd/src/liblaunch_private.h Modified: trunk/launchd/src/launchd.c =================================================================== --- trunk/launchd/src/launchd.c 2007-02-19 18:04:45 UTC (rev 23086) +++ trunk/launchd/src/launchd.c 2007-02-19 23:21:02 UTC (rev 23087) @@ -50,7 +50,6 @@ #include <unistd.h> #include <signal.h> #include <errno.h> -#include <syslog.h> #include <libgen.h> #include <stdio.h> #include <stdlib.h> @@ -137,9 +136,6 @@ launchd_runtime_init(); - openlog(getprogname(), LOG_PID|LOG_CONS, LOG_LAUNCHD); - setlogmask(LOG_UPTO(/* LOG_DEBUG */ LOG_NOTICE)); - for (i = 0; i < (sizeof(sigigns) / sizeof(int)); i++) { launchd_assumes(signal(sigigns[i], SIG_IGN) != SIG_ERR); } @@ -217,7 +213,7 @@ doom_why = "trying to read/write"; case SIGILL: case SIGFPE: - syslog(LOG_EMERG, "We crashed %s: %p (sent by PID %u)", doom_why, crash_addr, crash_pid); + runtime_syslog(LOG_EMERG, "We crashed %s: %p (sent by PID %u)", doom_why, crash_addr, crash_pid); sync(); sleep(3); /* the kernel will panic() when PID 1 exits */ @@ -280,7 +276,7 @@ void launchd_single_user(void) { - syslog(LOG_NOTICE, "Going to single-user mode"); + runtime_syslog(LOG_NOTICE, "Going to single-user mode"); re_exec_in_single_user_mode = true; @@ -314,7 +310,7 @@ launchd_assumes(close(tmpfd) == 0); } else { if (-1 == (tmpfd = open(path, flags | O_NOCTTY, DEFFILEMODE))) { - syslog(LOG_ERR, "open(\"%s\", ...): %m", path); + runtime_syslog(LOG_ERR, "open(\"%s\", ...): %m", path); } else if (tmpfd != fd) { launchd_assumes(dup2(tmpfd, fd) != -1); launchd_assumes(close(tmpfd) == 0); @@ -433,5 +429,5 @@ } } - syslog(LOG_NOTICE, "Bug: %s:%u (%s):%u: %s", file, line, buf, saved_errno, test); + runtime_syslog(LOG_NOTICE, "Bug: %s:%u (%s):%u: %s", file, line, buf, saved_errno, test); } Modified: trunk/launchd/src/launchd_core_logic.c =================================================================== --- trunk/launchd/src/launchd_core_logic.c 2007-02-19 18:04:45 UTC (rev 23086) +++ trunk/launchd/src/launchd_core_logic.c 2007-02-19 23:21:02 UTC (rev 23087) @@ -57,7 +57,6 @@ #include <unistd.h> #include <signal.h> #include <errno.h> -#include <syslog.h> #include <libgen.h> #include <stdio.h> #include <stdlib.h> @@ -225,7 +224,7 @@ static pid_t jobmgr_fork(jobmgr_t jm); static void jobmgr_setup_env_from_other_jobs(jobmgr_t jm); static struct machservice *jobmgr_lookup_service(jobmgr_t jm, const char *name, bool check_parent); -static void jobmgr_logv(jobmgr_t jm, int pri, int err, const char *msg, va_list ap); +static void jobmgr_logv(jobmgr_t jm, int pri, int err, const char *msg, va_list ap) __attribute__((format(printf, 4, 0))); static void jobmgr_log(jobmgr_t jm, int pri, const char *msg, ...) __attribute__((format(printf, 3, 4))); /* static void jobmgr_log_error(jobmgr_t jm, int pri, const char *msg, ...) __attribute__((format(printf, 3, 4))); */ static void jobmgr_log_bug(jobmgr_t jm, const char *rcs_rev, const char *path, unsigned int line, const char *test); @@ -274,7 +273,7 @@ mode_t mask; unsigned int globargv:1, wait4debugger:1, unload_at_exit:1, stall_before_exec:1, only_once:1, currently_ignored:1, forced_peers_to_demand_mode:1, setnice:1, hopefully_exits_last:1, removal_pending:1, - wait4pipe_eof:1, sent_sigkill:1; + wait4pipe_eof:1, sent_sigkill:1, debug_before_kill:1; char label[0]; }; @@ -317,7 +316,7 @@ static void job_kill(job_t j); static void job_uncork_fork(job_t j); static void job_log_stdouterr(job_t j); -static void job_logv(job_t j, int pri, int err, const char *msg, va_list ap); +static void job_logv(job_t j, int pri, int err, const char *msg, va_list ap) __attribute__((format(printf, 4, 0))); static void job_log_error(job_t j, int pri, const char *msg, ...) __attribute__((format(printf, 3, 4))); static void job_log_bug(job_t j, const char *rcs_rev, const char *path, unsigned int line, const char *test); static kern_return_t job_handle_mpm_wait(job_t j, mach_port_t srp, int *waitstatus); @@ -536,6 +535,10 @@ } } + if (debug_shutdown_hangs && jm->parentmgr == NULL && getpid() == 1) { + jobmgr_assumes(jm, kevent_mod((uintptr_t)jm, EVFILT_TIMER, EV_ADD, NOTE_SECONDS, 3, jm) != -1); + } + return jobmgr_do_garbage_collection(jm); } @@ -577,8 +580,10 @@ if (jm->parentmgr) { SLIST_REMOVE(&jm->parentmgr->submgrs, jm, jobmgr_s, sle); } else if (getpid() == 1) { + jobmgr_log(jm, LOG_DEBUG, "About to call reboot(0x%x).", jm->reboot_flags); jobmgr_assumes(jm, reboot(jm->reboot_flags) != -1); } else { + jobmgr_log(jm, LOG_DEBUG, "About to exit."); exit(EXIT_SUCCESS); } @@ -1081,6 +1086,8 @@ case 'E': if (strcasecmp(key, LAUNCH_JOBKEY_ENABLEGLOBBING) == 0) { j->globargv = value; + } else if (strcasecmp(key, LAUNCH_JOBKEY_ENTERKERNELDEBUGGERBEFOREKILL) == 0) { + j->debug_before_kill = value; } break; case 'w': @@ -1459,7 +1466,7 @@ return NULL; } else if (label[0] == '\0' || (strncasecmp(label, "", strlen("com.apple.launchd")) == 0) || (strtol(label, NULL, 10) != 0)) { - syslog(LOG_ERR, "Somebody attempted to use a reserved prefix for a label: %s", label); + jobmgr_log(root_jobmgr, LOG_ERR, "Somebody attempted to use a reserved prefix for a label: %s", label); /* the empty string, com.apple.launchd and number prefixes for labels are reserved */ errno = EINVAL; return NULL; @@ -1810,18 +1817,16 @@ } else if (&j->exit_timeout == ident) { if (j->sent_sigkill) { struct timeval tvd, tve; - double delta; job_assumes(j, gettimeofday(&tve, NULL) != -1); timersub(&tve, &j->sent_sigterm_time, &tvd); - delta = (double)tvd.tv_sec + (double)tvd.tv_usec / (double)1000000; - delta -= (double)j->exit_timeout; - job_log(j, LOG_ERR, "Did not die after sending SIGKILL %f seconds ago...", delta); - if (debug_shutdown_hangs && delta > 60) { + job_log(j, LOG_ERR, "Did not die after sending SIGKILL %lu seconds ago...", tvd.tv_sec); + } else { + job_force_sampletool(j); + if (j->debug_before_kill) { + job_log(j, LOG_NOTICE, "Exit timeout elapsed. Entering the kernel debugger."); job_assumes(j, host_reboot(mach_host_self(), HOST_REBOOT_DEBUGGER) == KERN_SUCCESS); } - } else { - job_force_sampletool(j); job_log(j, LOG_WARNING, "Exit timeout elapsed (%u seconds). Killing.", j->exit_timeout); job_kill(j); } @@ -1854,6 +1859,9 @@ return (void)jobmgr_assumes(jm, false); } break; + case EVFILT_TIMER: + jobmgr_log(jm, LOG_NOTICE, "Still alive with %u children.", total_children); + break; default: return (void)jobmgr_assumes(jm, false); } @@ -2512,7 +2520,7 @@ if (jm->parentmgr) { jobmgr_logv(jm->parentmgr, pri, 0, newmsg, ap); } else { - vsyslog(pri, newmsg, ap); + runtime_vsyslog(pri, newmsg, ap); } } @@ -3749,11 +3757,16 @@ goto out; } + job_log(j, LOG_DEBUG, "Waiting for 'sample' to finish."); + if (!job_assumes(j, waitpid(sp, &wstatus, 0) != -1)) { goto out; } - sync(); + /* + * This won't work if the VFS or filesystems are sick: + * sync(); + */ if (!job_assumes(j, WIFEXITED(wstatus) && WEXITSTATUS(wstatus) == 0)) { goto out; @@ -3789,12 +3802,15 @@ } if (logfile_fd != -1) { + job_assumes(j, fcntl(logfile_fd, F_FULLFSYNC, 0) != -1); job_assumes(j, close(logfile_fd) != -1); } if (console_fd != -1) { job_assumes(j, close(console_fd) != -1); } + + job_log(j, LOG_DEBUG, "Finished sampling."); } bool Modified: trunk/launchd/src/launchd_runtime.c =================================================================== --- trunk/launchd/src/launchd_runtime.c 2007-02-19 18:04:45 UTC (rev 23086) +++ trunk/launchd/src/launchd_runtime.c 2007-02-19 23:21:02 UTC (rev 23087) @@ -124,6 +124,9 @@ pthread_attr_setstacksize(&attr, PTHREAD_STACK_MIN); launchd_assert(pthread_create(&demand_thread, &attr, mport_demand_loop, NULL) == 0); pthread_attr_destroy(&attr); + + openlog(getprogname(), LOG_PID|LOG_CONS, LOG_LAUNCHD); + setlogmask(LOG_UPTO(/* LOG_DEBUG */ LOG_NOTICE)); } void * @@ -352,7 +355,7 @@ break; } - syslog(level, "KEVENT: ident = %s filter = %s flags = %s fflags = %s data = 0x%x udata = %p", + runtime_syslog(level, "KEVENT: ident = %s filter = %s flags = %s fflags = %s data = 0x%lx udata = %p", ident_buf, filter_str, flags_buf, fflags_buf, kev->data, kev->udata); } @@ -849,70 +852,78 @@ } } -#if 0 - -/* For ugly debug scenarios where syslogd is long gone (for example, during system shutdown). */ - void -closelog(void) +runtime_openlog(const char *ident, int logopt, int facility) { + openlog(ident, logopt, facility); } -void -openlog(const char *ident, int logopt, int facility) -{ - ident = 0; - logopt = 0; - facility = 0; -} - int -setlogmask(int maskpri) +runtime_setlogmask(int maskpri) { - return maskpri; + return setlogmask(maskpri); } void -syslog(int priority, const char *message, ...) +runtime_syslog(int priority, const char *message, ...) { va_list ap; va_start(ap, message); - vsyslog(priority, message, ap); + runtime_vsyslog(priority, message, ap); va_end(ap); } void -vsyslog(int priority, const char *message, va_list args) +runtime_vsyslog(int priority, const char *message, va_list args) { static pthread_mutex_t ourlock = PTHREAD_MUTEX_INITIALIZER; static FILE *ourlogfile = NULL; + static struct timeval shutdown_start = { 0, 0 }; + struct timeval tvnow, tvd; int saved_errno = errno; char newmsg[10000]; + double float_time; size_t i, j; + if (!(debug_shutdown_hangs && getpid() == 1)) { + return vsyslog(priority, message, args); + } + + 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_raw.log", "/var/log/launchd_raw-old.log"); - ourlogfile = fopen("/var/log/launchd_raw.log", "a"); - chmod("/var/log/launchd_raw.log", DEFFILEMODE); + 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; + syslog(LOG_ERR, "Couldn't open alternate log file!"); + return vsyslog(priority, message, args); } if (message == NULL) { return; } - snprintf(newmsg, sizeof(newmsg), "p%u pp%u\t", getpid(), getppid()); + timersub(&tvnow, &shutdown_start, &tvd); + float_time = (double)tvd.tv_sec + (double)tvd.tv_usec / (double)1000000; + snprintf(newmsg, sizeof(newmsg), "%f\t", float_time); + for (i = 0, j = strlen(newmsg); message[i];) { if (message[i] == '%' && message[i + 1] == 'm') { char *errs = strerror(saved_errno); @@ -932,5 +943,3 @@ fflush(ourlogfile); } - -#endif Modified: trunk/launchd/src/launchd_runtime.h =================================================================== --- trunk/launchd/src/launchd_runtime.h 2007-02-19 18:04:45 UTC (rev 23086) +++ trunk/launchd/src/launchd_runtime.h 2007-02-19 23:21:02 UTC (rev 23087) @@ -24,6 +24,7 @@ #include <sys/types.h> #include <bsm/libbsm.h> #include <stdbool.h> +#include <syslog.h> struct ldcred { uid_t euid; @@ -68,6 +69,12 @@ int kevent_mod(uintptr_t ident, short filter, u_short flags, u_int fflags, intptr_t data, void *udata); +void runtime_openlog(const char *ident, int logopt, int facility); +int runtime_setlogmask(int maskpri); +void runtime_syslog(int priority, const char *message, ...) __attribute__((format(printf, 2, 3))); +void runtime_vsyslog(int priority, const char *message, va_list args) __attribute__((format(printf, 2, 0))); + + kern_return_t launchd_set_bport(mach_port_t name); kern_return_t launchd_get_bport(mach_port_t *name); kern_return_t launchd_mport_notify_req(mach_port_t name, mach_msg_id_t which); Modified: trunk/launchd/src/launchd_unix_ipc.c =================================================================== --- trunk/launchd/src/launchd_unix_ipc.c 2007-02-19 18:04:45 UTC (rev 23086) +++ trunk/launchd/src/launchd_unix_ipc.c 2007-02-19 23:21:02 UTC (rev 23087) @@ -39,7 +39,6 @@ #include <unistd.h> #include <signal.h> #include <errno.h> -#include <syslog.h> #include <libgen.h> #include <stdio.h> #include <stdlib.h> @@ -81,9 +80,9 @@ } if (-1 == unlink(sockpath)) { - syslog(LOG_WARNING, "unlink(\"%s\"): %m", sockpath); + runtime_syslog(LOG_WARNING, "unlink(\"%s\"): %m", sockpath); } else if (-1 == rmdir(sockdir)) { - syslog(LOG_WARNING, "rmdir(\"%s\"): %m", sockdir); + runtime_syslog(LOG_WARNING, "rmdir(\"%s\"): %m", sockdir); } } @@ -115,11 +114,11 @@ stat(ourdir, &sb); if (!S_ISDIR(sb.st_mode)) { errno = EEXIST; - syslog(LOG_ERR, "mkdir(\"%s\"): %m", LAUNCHD_SOCK_PREFIX); + runtime_syslog(LOG_ERR, "mkdir(\"%s\"): %m", LAUNCHD_SOCK_PREFIX); goto out_bad; } } else { - syslog(LOG_ERR, "mkdir(\"%s\"): %m", ourdir); + runtime_syslog(LOG_ERR, "mkdir(\"%s\"): %m", ourdir); goto out_bad; } } @@ -133,7 +132,7 @@ if (unlink(sun.sun_path) == -1 && errno != ENOENT) { if (errno != EROFS) { - syslog(LOG_ERR, "unlink(\"thesocket\"): %m"); + runtime_syslog(LOG_ERR, "unlink(\"thesocket\"): %m"); } goto out_bad; } @@ -148,18 +147,18 @@ if (r == -1) { if (errno != EROFS) { - syslog(LOG_ERR, "bind(\"thesocket\"): %m"); + runtime_syslog(LOG_ERR, "bind(\"thesocket\"): %m"); } goto out_bad; } if (listen(fd, SOMAXCONN) == -1) { - syslog(LOG_ERR, "listen(\"thesocket\"): %m"); + runtime_syslog(LOG_ERR, "listen(\"thesocket\"): %m"); goto out_bad; } if (kevent_mod(fd, EVFILT_READ, EV_ADD, 0, 0, &kqipc_listen_callback) == -1) { - syslog(LOG_ERR, "kevent_mod(\"thesocket\", EVFILT_READ): %m"); + runtime_syslog(LOG_ERR, "kevent_mod(\"thesocket\", EVFILT_READ): %m"); goto out_bad; } @@ -213,7 +212,7 @@ if (kev->filter == EVFILT_READ) { if (launchd_msg_recv(c->conn, ipc_readmsg, c) == -1 && errno != EAGAIN) { if (errno != ECONNRESET) { - syslog(LOG_DEBUG, "%s(): recv: %m", __func__); + runtime_syslog(LOG_DEBUG, "%s(): recv: %m", __func__); } ipc_close(c); } @@ -221,14 +220,14 @@ r = launchd_msg_send(c->conn, NULL); if (r == -1) { if (errno != EAGAIN) { - syslog(LOG_DEBUG, "%s(): send: %m", __func__); + runtime_syslog(LOG_DEBUG, "%s(): send: %m", __func__); ipc_close(c); } } else if (r == 0) { kevent_mod(launchd_getfd(c->conn), EVFILT_WRITE, EV_DELETE, 0, 0, NULL); } } else { - syslog(LOG_DEBUG, "%s(): unknown filter type!", __func__); + runtime_syslog(LOG_DEBUG, "%s(): unknown filter type!", __func__); ipc_close(c); } } @@ -310,7 +309,7 @@ if (errno == EAGAIN) { kevent_mod(launchd_getfd(rmc.c->conn), EVFILT_WRITE, EV_ADD, 0, 0, &rmc.c->kqconn_callback); } else { - syslog(LOG_DEBUG, "launchd_msg_send() == -1: %m"); + runtime_syslog(LOG_DEBUG, "launchd_msg_send() == -1: %m"); ipc_close(rmc.c); } } @@ -332,7 +331,7 @@ if (rmc->c->j) { job_log(rmc->c->j, LOG_DEBUG, "Unix IPC request: %s", cmd); } else { - syslog(LOG_DEBUG, "Unix IPC request: %s", cmd); + runtime_syslog(LOG_DEBUG, "Unix IPC request: %s", cmd); } if (data == NULL) { @@ -471,7 +470,7 @@ ltmpsz = launch_data_get_opaque_size(in); if (ltmpsz > sizeof(l)) { - syslog(LOG_WARNING, "Too much rlimit data sent!"); + runtime_syslog(LOG_WARNING, "Too much rlimit data sent!"); ltmpsz = sizeof(l); } @@ -507,12 +506,12 @@ if (gval > 0) { launchd_assumes(sysctl(gmib, 2, NULL, NULL, &gval, sizeof(gval)) != -1); } else { - syslog(LOG_WARNING, "sysctl(\"%s\"): can't be zero", gstr); + runtime_syslog(LOG_WARNING, "sysctl(\"%s\"): can't be zero", gstr); } if (pval > 0) { launchd_assumes(sysctl(pmib, 2, NULL, NULL, &pval, sizeof(pval)) != -1); } else { - syslog(LOG_WARNING, "sysctl(\"%s\"): can't be zero", pstr); + runtime_syslog(LOG_WARNING, "sysctl(\"%s\"): can't be zero", pstr); } } launchd_assumes(setrlimit(i, ltmp + i) != -1); Modified: trunk/launchd/src/liblaunch_private.h =================================================================== --- trunk/launchd/src/liblaunch_private.h 2007-02-19 18:04:45 UTC (rev 23086) +++ trunk/launchd/src/liblaunch_private.h 2007-02-19 23:21:02 UTC (rev 23087) @@ -49,6 +49,8 @@ #define LAUNCH_KEY_BATCHCONTROL "BatchControl" #define LAUNCH_KEY_BATCHQUERY "BatchQuery" +#define LAUNCH_JOBKEY_ENTERKERNELDEBUGGERBEFOREKILL "EnterKernelDebuggerBeforeKill" + #define LAUNCH_JOBKEY_MACH_KUNCSERVER "kUNCServer" #define LAUNCH_JOBKEY_MACH_EXCEPTIONSERVER "ExceptionServer" #define LAUNCH_JOBKEY_MACH_TASKSPECIALPORT "TaskSpecialPort"