Revision: 23446 http://trac.macosforge.org/projects/launchd/changeset/23446 Author: zarzycki@apple.com Date: 2007-10-23 13:37:23 -0700 (Tue, 23 Oct 2007) Log Message: ----------- Aggressive logging. Modified Paths: -------------- trunk/launchd/src/launchctl.c trunk/launchd/src/launchd_core_logic.c trunk/launchd/src/launchd_runtime.c Modified: trunk/launchd/src/launchctl.c =================================================================== --- trunk/launchd/src/launchctl.c 2007-10-23 15:47:01 UTC (rev 23445) +++ trunk/launchd/src/launchctl.c 2007-10-23 20:37:23 UTC (rev 23446) @@ -74,8 +74,11 @@ #include <bootfiles.h> #include <sysexits.h> #include <util.h> +#include <spawn.h> +extern char **environ; + #define LAUNCH_SECDIR "/tmp/launch-XXXXXX" #define MACHINIT_JOBKEY_ONDEMAND "OnDemand" @@ -132,7 +135,7 @@ static void _log_launchctl_bug(const char *rcs_rev, const char *path, unsigned int line, const char *test); static void loopback_setup_ipv4(void); static void loopback_setup_ipv6(void); -static pid_t fwexec(const char *const *argv, bool _wait); +static pid_t fwexec(const char *const *argv, int *wstatus); static void do_potential_fsck(void); static bool path_check(const char *path); static bool is_safeboot(void); @@ -1404,19 +1407,19 @@ if (path_check("/etc/rc.server")) { const char *rcserver_tool[] = { _PATH_BSHELL, "/etc/rc.server", NULL }; - assumes(fwexec(rcserver_tool, true) != -1); + assumes(fwexec(rcserver_tool, NULL) != -1); } apply_sysctls_from_file("/etc/sysctl.conf"); if (path_check("/etc/rc.cdrom")) { const char *rccdrom_tool[] = { _PATH_BSHELL, "/etc/rc.cdrom", "multiuser", NULL }; - assumes(fwexec(rccdrom_tool, true) != -1); + assumes(fwexec(rccdrom_tool, NULL) != -1); assumes(reboot(RB_HALT) != -1); _exit(EXIT_FAILURE); } else if (is_netboot()) { const char *rcnetboot_tool[] = { _PATH_BSHELL, "/etc/rc.netboot", "init", NULL }; - if (!assumes(fwexec(rcnetboot_tool, true) != -1)) { + if (!assumes(fwexec(rcnetboot_tool, NULL) != -1)) { assumes(reboot(RB_HALT) != -1); _exit(EXIT_FAILURE); } @@ -1432,12 +1435,12 @@ if (path_check("/etc/fstab")) { const char *mount_tool[] = { "mount", "-vat", "nonfs", NULL }; - assumes(fwexec(mount_tool, true) != -1); + assumes(fwexec(mount_tool, NULL) != -1); } if (path_check("/etc/rc.installer_cleanup")) { const char *rccleanup_tool[] = { _PATH_BSHELL, "/etc/rc.installer_cleanup", "multiuser", NULL }; - assumes(fwexec(rccleanup_tool, true) != -1); + assumes(fwexec(rccleanup_tool, NULL) != -1); } empty_dir(_PATH_VARRUN, NULL); @@ -1446,7 +1449,7 @@ if (path_check("/usr/libexec/dirhelper")) { const char *dirhelper_tool[] = { "/usr/libexec/dirhelper", "-machineBoot", NULL }; - assumes(fwexec(dirhelper_tool, true) != -1); + assumes(fwexec(dirhelper_tool, NULL) != -1); } assumes(touch_file(_PATH_UTMPX, DEFFILEMODE) != -1); @@ -1454,7 +1457,7 @@ if (path_check("/etc/security/rc.audit")) { const char *audit_tool[] = { _PATH_BSHELL, "/etc/security/rc.audit", NULL }; - assumes(fwexec(audit_tool, true) != -1); + assumes(fwexec(audit_tool, NULL) != -1); } do_BootCache_magic(BOOTCACHE_START); @@ -1553,7 +1556,7 @@ return; } - fwexec(bcc_tool, true); + fwexec(bcc_tool, NULL); } int @@ -2556,7 +2559,7 @@ setgid(getgid()); setuid(getuid()); - if (fwexec((const char *const *)argv + 2, true) == -1) { + if (fwexec((const char *const *)argv + 2, NULL) == -1) { fprintf(stderr, "%s bsexec failed: %s\n", getprogname(), strerror(errno)); return 1; } @@ -2703,31 +2706,27 @@ } pid_t -fwexec(const char *const *argv, bool _wait) +fwexec(const char *const *argv, int *wstatus) { - int wstatus; + int wstatus2; pid_t p; - switch ((p = fork())) { - case -1: - break; - case 0: - if (!_wait) { - setsid(); - } - execvp(argv[0], (char *const *)argv); - _exit(EXIT_FAILURE); - break; - default: - if (!_wait) - return p; - if (p == waitpid(p, &wstatus, 0)) { - if (WIFEXITED(wstatus) && WEXITSTATUS(wstatus) == EXIT_SUCCESS) - return p; - } - break; + errno = posix_spawnp(&p, argv[0], NULL, NULL, (char **)argv, environ); + + if (errno) { + return -1; } + if (waitpid(p, wstatus ? wstatus : &wstatus2, 0) == -1) { + return -1; + } + + if (wstatus) { + return p; + } else if (WIFEXITED(wstatus2) && WEXITSTATUS(wstatus2) == EXIT_SUCCESS) { + return p; + } + return -1; } @@ -2755,12 +2754,12 @@ } #endif - if (fwexec(fsck_tool, true) != -1) { + if (fwexec(fsck_tool, NULL) != -1) { goto out; } } - if (fwexec(safe_fsck_tool, true) != -1) { + if (fwexec(safe_fsck_tool, NULL) != -1) { goto out; } @@ -2778,7 +2777,7 @@ * assumes(mount(sfs.f_fstypename, "/", MNT_UPDATE, NULL) != -1); */ - assumes(fwexec(remount_tool, true) != -1); + assumes(fwexec(remount_tool, NULL) != -1); } bool @@ -2930,7 +2929,7 @@ goto skip_sysctl_tool; } sysctl_tool[2] = val; - assumes(fwexec(sysctl_tool, true) != -1); + assumes(fwexec(sysctl_tool, NULL) != -1); skip_sysctl_tool: free(tmpstr); } @@ -3097,14 +3096,10 @@ CFRelease(bootrootProp); - if (!assumes((p = fwexec(kextcache_tool, false)) != -1)) { + if (!assumes((p = fwexec(kextcache_tool, &wstatus)) != -1)) { return; } - if (!assumes(waitpid(p, &wstatus, 0) != -1)) { - return; - } - if (WIFEXITED(wstatus) && WEXITSTATUS(wstatus) == EX_OSFILE) { assumes(reboot(RB_AUTOBOOT) != -1); } Modified: trunk/launchd/src/launchd_core_logic.c =================================================================== --- trunk/launchd/src/launchd_core_logic.c 2007-10-23 15:47:01 UTC (rev 23445) +++ trunk/launchd/src/launchd_core_logic.c 2007-10-23 20:37:23 UTC (rev 23446) @@ -132,7 +132,6 @@ LIST_ENTRY(machservice) name_hash_sle; LIST_ENTRY(machservice) port_hash_sle; job_t job; - uint64_t bad_perf_cnt; unsigned int gen_num; mach_port_name_t port; unsigned int isActive:1, reset:1, recv:1, hide:1, kUNCServer:1, per_user_hack:1, debug_on_close:1, per_pid:1, special_port_num:10; @@ -358,11 +357,11 @@ ondemand:1, session_create:1, low_pri_io:1, no_init_groups:1, priv_port_has_senders:1, importing_global_env:1, importing_hard_limits:1, setmask:1, legacy_mach_job:1, start_pending:1; mode_t mask; - unsigned int globargv:1, wait4debugger:1, unload_at_exit:1, stall_before_exec:1, only_once:1, + unsigned int globargv:1, wait4debugger:1, internal_exc_handler: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, debug_before_kill:1, weird_bootstrap:1, start_on_mount:1, + legacy_LS_job:1, sent_sigkill:1, debug_before_kill:1, weird_bootstrap:1, start_on_mount:1, per_user:1, hopefully_exits_first:1, deny_unknown_mslookups:1, unload_at_mig_return:1, abandon_pg:1, - poll_for_vfs_changes:1, internal_exc_handler:1; + poll_for_vfs_changes:1; const char label[0]; }; @@ -396,7 +395,7 @@ static bool job_setup_machport(job_t j); static void job_setup_fd(job_t j, int target_fd, const char *path, int flags); static void job_postfork_become_user(job_t j); -static void job_find_and_blame_pids_with_weird_uids(job_t j); +static void job_log_pids_with_weird_uids(job_t j); static void job_force_sampletool(job_t j); static void job_setup_exception_port(job_t j, task_t target_task); static void job_reparent_hack(job_t j, const char *where); @@ -405,6 +404,7 @@ static void job_callback_timer(job_t j, void *ident); static void job_callback_read(job_t j, int ident); static void job_log_stray_pg(job_t j); +static void job_log_chidren_without_exec(job_t j); static job_t job_new_anonymous(jobmgr_t jm, pid_t anonpid); static job_t job_new(jobmgr_t jm, const char *label, const char *prog, const char *const *argv); static job_t job_new_via_mach_init(job_t j, const char *cmd, uid_t uid, bool ond); @@ -1034,9 +1034,10 @@ int mib[] = { CTL_KERN, KERN_PROC, KERN_PROC_PID, anonpid }; struct kinfo_proc kp; size_t len = sizeof(kp); - const char *zombie = NULL; bool shutdown_state; job_t jp = NULL, jr = NULL; + uid_t kp_euid, kp_uid, kp_svuid; + gid_t kp_egid, kp_gid, kp_svgid; if (!jobmgr_assumes(jm, anonpid != 0)) { return NULL; @@ -1061,10 +1062,25 @@ } if (kp.kp_proc.p_stat == SZOMB) { - jobmgr_log(jm, LOG_DEBUG, "Tried to create an anonymous job for zombie PID: %u", anonpid); - zombie = "zombie"; + jobmgr_log(jm, LOG_DEBUG, "Tried to create an anonymous job for zombie PID %u: %s", anonpid, kp.kp_proc.p_comm); } + if (kp.kp_proc.p_flag & P_SUGID) { + jobmgr_log(jm, LOG_APPLEONLY, "Inconsistency: P_SUGID is set on PID %u: %s", anonpid, kp.kp_proc.p_comm); + } + + kp_euid = kp.kp_eproc.e_ucred.cr_uid; + kp_uid = kp.kp_eproc.e_pcred.p_ruid; + kp_svuid = kp.kp_eproc.e_pcred.p_svuid; + kp_egid = kp.kp_eproc.e_ucred.cr_gid; + kp_gid = kp.kp_eproc.e_pcred.p_rgid; + kp_svgid = kp.kp_eproc.e_pcred.p_svgid; + + if (kp_euid != kp_uid || kp_euid != kp_svuid || kp_uid != kp_svuid || kp_egid != kp_gid || kp_egid != kp_svgid || kp_gid != kp_svgid) { + jobmgr_log(jm, LOG_APPLEONLY, "Inconsistency: Mixed credentials (e/r/s UID %u/%u/%u GID %u/%u/%u) detected on PID %u: %s", + kp_euid, kp_uid, kp_svuid, kp_egid, kp_gid, kp_svgid, anonpid, kp.kp_proc.p_comm); + } + switch (kp.kp_eproc.e_ppid) { case 0: /* the kernel */ @@ -1081,13 +1097,18 @@ break; } + if (jp && !jp->anonymous && !(kp.kp_proc.p_flag & P_EXEC)) { + job_log(jp, LOG_APPLEONLY, "Performance and sanity: fork() without exec*(). Please switch to posix_spawn()"); + } + + /* A total hack: Normally, job_new() returns an error during shutdown, but anonymous jobs are special. */ if ((shutdown_state = jm->shutting_down)) { jm->shutting_down = false; } - if (jobmgr_assumes(jm, (jr = job_new(jm, AUTO_PICK_LEGACY_LABEL, zombie ? zombie : kp.kp_proc.p_comm, NULL)) != NULL)) { - u_int proc_fflags = NOTE_EXEC|NOTE_EXIT /* |NOTE_REAP */; + if (jobmgr_assumes(jm, (jr = job_new(jm, AUTO_PICK_LEGACY_LABEL, kp.kp_proc.p_comm, NULL)) != NULL)) { + u_int proc_fflags = NOTE_EXEC|NOTE_FORK|NOTE_EXIT /* |NOTE_REAP */; total_anon_children++; jr->anonymous = true; @@ -1107,7 +1128,7 @@ } if (shutdown_state && jm->hopefully_first_cnt == 0) { - job_log(jr, LOG_APPLEONLY, "This process showed up to the party while all the guests were leaving. Odds are that it will have a miserable time"); + job_log(jr, LOG_APPLEONLY, "This process showed up to the party while all the guests were leaving. Odds are that it will have a miserable time."); } job_log(jr, LOG_DEBUG, "Created PID %u anonymously by PPID %u%s%s", anonpid, kp.kp_eproc.e_ppid, jp ? ": " : "", jp ? jp->label : ""); @@ -2044,7 +2065,7 @@ j->weird_bootstrap = false; } - if (j->log_redirect_fd && !j->wait4pipe_eof) { + if (j->log_redirect_fd && !j->legacy_LS_job) { job_assumes(j, runtime_close(j->log_redirect_fd) != -1); j->log_redirect_fd = 0; } @@ -2292,28 +2313,73 @@ } void +job_log_chidren_without_exec(job_t j) +{ + int mib[] = { CTL_KERN, KERN_PROC, KERN_PROC_ALL }; + size_t i, kp_cnt, len = 10*1024*1024; + struct kinfo_proc *kp; + + if (j->anonymous || j->per_user) { + return; + } + + if (!job_assumes(j, (kp = malloc(len)) != NULL)) { + return; + } + if (!job_assumes(j, sysctl(mib, 3, kp, &len, NULL, 0) != -1)) { + goto out; + } + + kp_cnt = len / sizeof(struct kinfo_proc); + + for (i = 0; i < kp_cnt; i++) { + if (kp[i].kp_eproc.e_ppid != j->p) { + continue; + } else if (kp[i].kp_proc.p_flag & P_EXEC) { + continue; + } + + job_log(j, LOG_APPLEONLY, "Performance and sanity: fork() without exec*(). Please switch to posix_spawn()"); + } + +out: + free(kp); +} + +void job_callback_proc(job_t j, int flags, int fflags) { - if ((fflags & NOTE_EXEC) && j->anonymous) { - int mib[] = { CTL_KERN, KERN_PROC, KERN_PROC_PID, j->p }; - struct kinfo_proc kp; - size_t len = sizeof(kp); + bool program_changed = false; - if (job_assumes(j, sysctl(mib, 4, &kp, &len, NULL, 0) != -1)) { - char newlabel[1000]; + if (fflags & NOTE_EXEC) { + program_changed = true; - snprintf(newlabel, sizeof(newlabel), "%p.%s", j, kp.kp_proc.p_comm); + if (j->anonymous) { + int mib[] = { CTL_KERN, KERN_PROC, KERN_PROC_PID, j->p }; + struct kinfo_proc kp; + size_t len = sizeof(kp); - job_log(j, LOG_DEBUG, "Program changed. Updating the label to: %s", newlabel); + if (job_assumes(j, sysctl(mib, 4, &kp, &len, NULL, 0) != -1) && job_assumes(j, len == sizeof(kp))) { + char newlabel[1000]; - LIST_REMOVE(j, label_hash_sle); - strcpy((char *)j->label, newlabel); - LIST_INSERT_HEAD(&label_hash[hash_label(j->label)], j, label_hash_sle); + snprintf(newlabel, sizeof(newlabel), "%p.%s", j, kp.kp_proc.p_comm); + + job_log(j, LOG_INFO, "Program changed. Updating the label to: %s", newlabel); + j->lastlookup = NULL; + j->lastlookup_gennum = 0; + + LIST_REMOVE(j, label_hash_sle); + strcpy((char *)j->label, newlabel); + LIST_INSERT_HEAD(&label_hash[hash_label(j->label)], j, label_hash_sle); + } + } else { + job_log(j, LOG_DEBUG, "Program changed"); } } if (fflags & NOTE_FORK) { - job_log(j, LOG_DEBUG, "Called fork()"); + job_log(j, LOG_DEBUG, "fork()ed%s", program_changed ? ". For this message only: We don't know whether this event happened before or after execve()." : ""); + job_log_chidren_without_exec(j); } if (fflags & NOTE_EXIT) { @@ -2467,7 +2533,7 @@ char nbuf[64]; pid_t c; bool sipc = false; - u_int proc_fflags = /* NOTE_EXEC|NOTE_FORK| */ NOTE_EXIT /* |NOTE_REAP */; + u_int proc_fflags = NOTE_EXIT|NOTE_FORK|NOTE_EXEC /* NOTE_REAP */; if (!job_assumes(j, j->mgr != NULL)) { return; @@ -2762,7 +2828,7 @@ } void -job_find_and_blame_pids_with_weird_uids(job_t j) +job_log_pids_with_weird_uids(job_t j) { int mib[] = { CTL_KERN, KERN_PROC, KERN_PROC_ALL }; size_t i, kp_cnt, len = 10*1024*1024; @@ -2834,7 +2900,7 @@ } else if (j->mach_uid) { if ((pwe = getpwuid(j->mach_uid)) == NULL) { job_log(j, LOG_ERR, "getpwuid(\"%u\") failed", j->mach_uid); - job_find_and_blame_pids_with_weird_uids(j); + job_log_pids_with_weird_uids(j); _exit(EXIT_FAILURE); } } else { @@ -3750,10 +3816,8 @@ bool job_useless(job_t j) { - /* Yes, j->unload_at_exit and j->only_once seem the same, but they'll differ someday... */ - - if ((j->unload_at_exit || j->only_once) && j->start_time != 0) { - if (j->unload_at_exit && j->j_port) { + if ((j->legacy_LS_job || j->only_once) && j->start_time != 0) { + if (j->legacy_LS_job && j->j_port) { return false; } job_log(j, LOG_INFO, "Exited. Was only configured to run once."); @@ -3916,7 +3980,7 @@ } if (j->log_redirect_fd) { - if (job_assumes(j, j->wait4pipe_eof)) { + if (job_assumes(j, j->legacy_LS_job)) { return "Standard out/error is still valid"; } else { job_assumes(j, runtime_close(j->log_redirect_fd) != -1); @@ -3974,6 +4038,7 @@ strcpy((char *)ms->name, name); ms->job = j; + ms->gen_num = 1; ms->per_pid = pid_local; if (*serviceport == MACH_PORT_NULL) { @@ -5725,9 +5790,9 @@ runtime_get_caller_creds(&ldc); -#if 0 - job_log(j, LOG_APPLEONLY, "bootstrap_register() is deprecated. Service: %s", servicename); -#endif + if (!(flags & BOOTSTRAP_PER_PID_SERVICE) && !j->legacy_LS_job) { + job_log(j, LOG_APPLEONLY, "Performance: bootstrap_register() is deprecated. Service: %s", servicename); + } job_log(j, LOG_DEBUG, "%sMach service registration attempt: %s", flags & BOOTSTRAP_PER_PID_SERVICE ? "Per PID " : "", servicename); @@ -5806,17 +5871,16 @@ if (ms) { launchd_assumes(machservice_port(ms) != MACH_PORT_NULL); job_log(j, LOG_DEBUG, "%sMach service lookup: %s", flags & BOOTSTRAP_PER_PID_SERVICE ? "Per PID " : "", servicename); -#if 0 - /* After Leopard ships, we should enable this */ + if (j->lastlookup == ms && j->lastlookup_gennum == ms->gen_num && !j->per_user) { - ms->bad_perf_cnt++; - job_log(j, LOG_APPLEONLY, "Performance opportunity: Number of bootstrap_lookup(... \"%s\" ...) calls that should have been cached: %llu", - servicename, ms->bad_perf_cnt); + job_log(ms->job, LOG_APPLEONLY, "Performance: Please fix the framework to cache the Mach port for service: %s", servicename); } + j->lastlookup = ms; j->lastlookup_gennum = ms->gen_num; -#endif + *serviceportp = machservice_port(ms); + kr = BOOTSTRAP_SUCCESS; } else if (!(flags & BOOTSTRAP_PER_PID_SERVICE) && (inherited_bootstrap_port != MACH_PORT_NULL)) { job_log(j, LOG_DEBUG, "Mach service lookup forwarded: %s", servicename); @@ -6469,8 +6533,7 @@ jr->mach_uid = ldc.uid; } - jr->unload_at_exit = true; - jr->wait4pipe_eof = true; + jr->legacy_LS_job = true; jr->abandon_pg = true; jr->stall_before_exec = jr->wait4debugger; jr->wait4debugger = false; Modified: trunk/launchd/src/launchd_runtime.c =================================================================== --- trunk/launchd/src/launchd_runtime.c 2007-10-23 15:47:01 UTC (rev 23445) +++ trunk/launchd/src/launchd_runtime.c 2007-10-23 20:37:23 UTC (rev 23446) @@ -1173,22 +1173,23 @@ char newmsg[10000]; size_t i, j; - if (!(LOG_MASK(attr->priority) & internal_mask_pri)) { - goto out; - } - if (apple_internal_logging == 1) { apple_internal_logging = stat("/AppleInternal", &sb); } + if (attr->priority == LOG_APPLEONLY) { + if (apple_internal_logging == 0) { + attr->priority = LOG_NOTICE; + } else { + return; + } + } + if (!(LOG_MASK(attr->priority) & internal_mask_pri)) { + goto out; + } + if (!(debug_shutdown_hangs && getpid() == 1)) { - if (attr->priority == LOG_APPLEONLY) { - if (apple_internal_logging == -1) { - goto out; - } - attr->priority = LOG_NOTICE; - } vsnprintf(newmsg, sizeof(newmsg), message, args); logmsg_add(attr, saved_errno, newmsg); goto out;