Changeset 23446

Timestamp:

10/23/07 13:37:23 (14 months ago)

Author:

zarzycki@…

Message:

Aggressive logging.

Location:

trunk/launchd/src

Files:

• launchctl.c (modified) (14 diffs)
• launchd_core_logic.c (modified) (20 diffs)
• launchd_runtime.c (modified) (1 diff)

trunk/launchd/src/launchctl.c

@@ -75 +75 @@
 #include <sysexits.h>
 #include <util.h>
+#include <spawn.h>
+
+extern char **environ;
 
 
@@ -133 +136 @@
 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);
@@ -1405 +1408 @@
         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);
         }
 
@@ -1412 +1415 @@
         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);
@@ -1433 +1436 @@
         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);
         }
 
@@ -1447 +1450 @@
         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);
         }
 
@@ -1455 +1458 @@
         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);
         }
 
@@ -1554 +1557 @@
         }
 
-        fwexec(bcc_tool, true);
+        fwexec(bcc_tool, NULL);
 }
 
@@ -2557 +2560 @@
         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;
@@ -2704 +2707 @@
 
 pid_t
-fwexec(const char *const *argv, bool _wait)
-{
-        int wstatus;
+fwexec(const char *const *argv, 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;
         }
 
@@ -2756 +2755 @@
 #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;
         }
@@ -2779 +2778 @@
          */
 
-        assumes(fwexec(remount_tool, true) != -1);
+        assumes(fwexec(remount_tool, NULL) != -1);
 }
 
@@ -2931 +2930 @@
                 }
                 sysctl_tool[2] = val;
-                assumes(fwexec(sysctl_tool, true) != -1);
+                assumes(fwexec(sysctl_tool, NULL) != -1);
 skip_sysctl_tool:
                 free(tmpstr);
@@ -3098 +3097 @@
         CFRelease(bootrootProp);
 
-        if (!assumes((p = fwexec(kextcache_tool, false)) != -1)) {
-                return;
-        }
-
-        if (!assumes(waitpid(p, &wstatus, 0) != -1)) {
+        if (!assumes((p = fwexec(kextcache_tool, &wstatus)) != -1)) {
                 return;
         }

trunk/launchd/src/launchd_core_logic.c

@@ -133 +133 @@
         LIST_ENTRY(machservice) port_hash_sle;
         job_t                   job;
-        uint64_t                bad_perf_cnt;
         unsigned int            gen_num;
         mach_port_name_t        port;
@@ -359 +358 @@
                      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];
 };
@@ -397 +396 @@
 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);
@@ -406 +405 @@
 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);
@@ -1035 +1035 @@
         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)) {
@@ -1062 +1063 @@
 
         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);
         }
 
@@ -1082 +1098 @@
         }
 
+        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)) {
@@ -1087 +1108 @@
         }
 
-        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++;
@@ -1108 +1129 @@
 
                 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.");
                 }
 
@@ -2045 +2066 @@
         }
 
-        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;
@@ -2293 +2314 @@
 
 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);
-
-                if (job_assumes(j, sysctl(mib, 4, &kp, &len, NULL, 0) != -1)) {
-                        char newlabel[1000];
-
-                        snprintf(newlabel, sizeof(newlabel), "%p.%s", j, kp.kp_proc.p_comm);
-
-                        job_log(j, LOG_DEBUG, "Program changed. Updating the label to: %s", newlabel);
-
-                        LIST_REMOVE(j, label_hash_sle);
-                        strcpy((char *)j->label, newlabel);
-                        LIST_INSERT_HEAD(&label_hash[hash_label(j->label)], j, label_hash_sle);
+        bool program_changed = false;
+
+        if (fflags & NOTE_EXEC) {
+                program_changed = true;
+
+                if (j->anonymous) {
+                        int mib[] = { CTL_KERN, KERN_PROC, KERN_PROC_PID, j->p };
+                        struct kinfo_proc kp;
+                        size_t len = sizeof(kp);
+
+                        if (job_assumes(j, sysctl(mib, 4, &kp, &len, NULL, 0) != -1) && job_assumes(j, len == sizeof(kp))) {
+                                char newlabel[1000];
+
+                                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);
         }
 
@@ -2468 +2534 @@
         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)) {
@@ -2763 +2829 @@
 
 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 };
@@ -2835 +2901 @@
                 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);
                 }
@@ -3751 +3817 @@
 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;
                 }
@@ -3917 +3981 @@
 
         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 {
@@ -3975 +4039 @@
         strcpy((char *)ms->name, name);
         ms->job = j;
+        ms->gen_num = 1;
         ms->per_pid = pid_local;
 
@@ -5726 +5791 @@
         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);
@@ -5807 +5872 @@
                 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)) {
@@ -6470 +6534 @@
         }
 
-        jr->unload_at_exit = true;
-        jr->wait4pipe_eof = true;
+        jr->legacy_LS_job = true;
         jr->abandon_pg = true;
         jr->stall_before_exec = jr->wait4debugger;

trunk/launchd/src/launchd_runtime.c

@@ -1174 +1174 @@
         size_t i, j;
 
+        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 (apple_internal_logging == 1) {
-                apple_internal_logging = stat("/AppleInternal", &sb);
-        }
-
-
         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);