src/log.c

   1 #include <dispatch/dispatch.h>
   2 #include <os/assumes.h>
   3 #include "job_reply.h"
   4
   5 #include "launchd.h"
   6 #include "launch_internal.h"
   7 #include "vproc_internal.h"
   8 #include "log.h"
   9
  10 #define ROUND_TO_64BIT_WORD_SIZE(x)     ((x + 7) & ~7)
  11 #define LAUNCHD_DEBUG_LOG "launchd-debug.%s.log"
  12 #define LAUNCHD_PERF_LOG "launchd-perf.%s.log"
  13 #define LAUNCHD_SHUTDOWN_LOG "launchd-shutdown.%s.log"
  14 #define LAUNCHD_LOWLEVEL_LOG "launchd-lowlevel.%s.log"
  15
  16 os_redirect_assumes(_launchd_os_redirect);
  17
  18 char *launchd_username = "unknown";
  19 char *launchd_label = "com.apple.launchd.unknown";
  20 mach_port_t launchd_drain_reply_port;
  21 bool launchd_var_available = false;
  22 int64_t launchd_system_start;
  23
  24 static FILE *_launchd_shutdown_log;
  25 static FILE *_launchd_debug_log;
  26 static FILE *_launchd_perf_log;
  27 static STAILQ_HEAD(, logmsg_s) _launchd_logq = STAILQ_HEAD_INITIALIZER(_launchd_logq);
  28 static size_t _launchd_logq_sz;
  29 static size_t _launchd_logq_cnt;
  30 static int _launchd_log_up2 = LOG_UPTO(LOG_NOTICE);
  31
  32 static int64_t _launchd_shutdown_start;
  33
  34 struct _launchd_open_log_ctx_s {
  35         const char *path;
  36         FILE **filep;
  37 };
  38
  39 static void
  40 _launchd_open_log_once(void *ctx)
  41 {
  42         struct _launchd_open_log_ctx_s *ctx2 = ctx;
  43         const char *path = ctx2->path;
  44         FILE **filep = ctx2->filep;
  45
  46         char saved[PATH_MAX];
  47         snprintf(saved, sizeof(saved), "%s.1", path);
  48         (void)rename(path, saved);
  49
  50         FILE *file = fopen(path, "w");
  51         if (file) {
  52                 (void)_fd(fileno(file));
  53                 *filep = file;
  54         } else if (launchd_console) {
  55                 fprintf(launchd_console, "Could not open %s: %d: %s\n", path, errno, strerror(errno));
  56         }
  57 }
  58
  59 static void
  60 _launchd_shutdown_start_once(void *ctx __attribute__((unused)))
  61 {
  62         _launchd_shutdown_start = runtime_get_wall_time();
  63 }
  64
  65 int
  66 runtime_setlogmask(int maskpri)
  67 {
  68         _launchd_log_up2 = maskpri;
  69         return _launchd_log_up2;
  70 }
  71
  72 static bool
  73 _logmsg_add(struct launchd_syslog_attr *attr, int err_num, const char *msg)
  74 {
  75         size_t lm_sz = sizeof(struct logmsg_s) + strlen(msg) + strlen(attr->from_name) + strlen(attr->about_name) + strlen(attr->session_name) + 4;
  76         char *data_off;
  77         struct logmsg_s *lm;
  78
  79         /* Force the unpacking for the log_drain cause unalignment faults. */
  80         lm_sz = ROUND_TO_64BIT_WORD_SIZE(lm_sz);
  81
  82         if (unlikely((lm = calloc(1, lm_sz)) == NULL)) {
  83                 return false;
  84         }
  85
  86         data_off = lm->data;
  87
  88         lm->when = runtime_get_wall_time();
  89         lm->from_pid = attr->from_pid;
  90         lm->about_pid = attr->about_pid;
  91         lm->err_num = err_num;
  92         lm->pri = attr->priority;
  93         lm->obj_sz = lm_sz;
  94         lm->msg = data_off;
  95         data_off += sprintf(data_off, "%s", msg) + 1;
  96         lm->from_name = data_off;
  97         data_off += sprintf(data_off, "%s", attr->from_name) + 1;
  98         lm->about_name = data_off;
  99         data_off += sprintf(data_off, "%s", attr->about_name) + 1;
 100         lm->session_name = data_off;
 101         data_off += sprintf(data_off, "%s", attr->session_name) + 1;
 102
 103         STAILQ_INSERT_TAIL(&_launchd_logq, lm, sqe);
 104         _launchd_logq_sz += lm_sz;
 105         _launchd_logq_cnt++;
 106
 107         return true;
 108 }
 109
 110 static void
 111 _logmsg_remove(struct logmsg_s *lm)
 112 {
 113         STAILQ_REMOVE(&_launchd_logq, lm, logmsg_s, sqe);
 114         _launchd_logq_sz -= lm->obj_sz;
 115         _launchd_logq_cnt--;
 116
 117         free(lm);
 118 }
 119
 120 bool
 121 _launchd_os_redirect(const char *message)
 122 {
 123         launchd_syslog(LOG_ERR, "%s", message);
 124         return true;
 125 }
 126
 127 void
 128 launchd_syslog(int pri, const char *message, ...)
 129 {
 130         struct launchd_syslog_attr attr = {
 131                 .from_name = launchd_label,
 132                 .about_name = launchd_label,
 133                 .session_name = pid1_magic ? "System" : "Background",
 134                 .priority = pri,
 135                 .from_uid = launchd_uid,
 136                 .from_pid = getpid(),
 137                 .about_pid = getpid(),
 138         };
 139
 140         va_list ap;
 141
 142         va_start(ap, message);
 143         launchd_vsyslog(&attr, message, ap);
 144         va_end(ap);
 145 }
 146
 147 void
 148 launchd_vsyslog(struct launchd_syslog_attr *attr, const char *fmt, va_list args)
 149 {
 150         int saved_errno = errno;
 151         char message[2048];
 152
 153         static dispatch_once_t perf_once = 0;
 154         static dispatch_once_t shutdown_once = 0;
 155         static dispatch_once_t shutdown_start_once = 0;
 156         static dispatch_once_t debug_once = 0;
 157
 158         bool echo2console = (attr->priority & LOG_CONSOLE);
 159         attr->priority &= ~LOG_CONSOLE;
 160         if (attr->priority == LOG_APPLEONLY && launchd_apple_internal) {
 161                 attr->priority = LOG_NOTICE;
 162         }
 163
 164         FILE *log2here = NULL;
 165
 166         /* launchctl is responsible for mounting /var as read-write. So we need to
 167          * wait until /var/log is available before trying to log anything to our log
 168          * anything to our auxilliary log files. This is kind of a hack because
 169          * we'll lose the first few relevant messages at boot for debug and
 170          * performance logging, but the loss isn't too bad.
 171          */
 172         if (launchd_var_available) {
 173                 /* This file is for logging low-level errors where we can't necessarily be
 174                  * assured that we can write to the console or use syslog.
 175                  */
 176                 char *store = launchd_copy_persistent_store(LAUNCHD_PERSISTENT_STORE_LOGS, NULL);
 177                 char path[PATH_MAX];
 178
 179                 if (attr->priority == LOG_PERF) {
 180                         if (launchd_log_perf) {
 181                                 (void)snprintf(path, sizeof(path), "%s" LAUNCHD_PERF_LOG, store, launchd_username);
 182
 183                                 struct _launchd_open_log_ctx_s ctx2 = {
 184                                         .path = path,
 185                                         .filep = &_launchd_perf_log,
 186                                 };
 187                                 dispatch_once_f(&perf_once, &ctx2, _launchd_open_log_once);
 188                                 log2here = _launchd_perf_log;
 189                         }
 190
 191                         // Don't log performance messages to the normal syslog store.
 192                         attr->priority = LOG_DEBUG + 1;
 193                 } else {
 194                         if (launchd_shutting_down && launchd_log_shutdown) {
 195                                 dispatch_once_f(&shutdown_start_once, NULL, _launchd_shutdown_start_once);
 196
 197                                 (void)snprintf(path, sizeof(path), "%s" LAUNCHD_SHUTDOWN_LOG, store, launchd_username);
 198
 199                                 struct _launchd_open_log_ctx_s ctx2 = {
 200                                         .path = path,
 201                                         .filep = &_launchd_shutdown_log,
 202                                 };
 203                                 dispatch_once_f(&shutdown_once, &ctx2, _launchd_open_log_once);
 204                                 log2here = _launchd_shutdown_log;
 205                         } else if (launchd_log_debug) {
 206                                 (void)snprintf(path, sizeof(path), "%s" LAUNCHD_DEBUG_LOG, store, launchd_username);
 207
 208                                 struct _launchd_open_log_ctx_s ctx2 = {
 209                                         .path = path,
 210                                         .filep = &_launchd_debug_log,
 211                                 };
 212                                 dispatch_once_f(&debug_once, &ctx2, _launchd_open_log_once);
 213                                 log2here = _launchd_debug_log;
 214                         }
 215                 }
 216
 217                 free(store);
 218
 219         }
 220
 221         vsnprintf(message, sizeof(message), fmt, args);
 222         if (echo2console && launchd_console) {
 223                 fprintf(launchd_console, "%-32s %-8u %-64s %-8u  %s\n", attr->from_name, attr->from_pid, attr->about_name, attr->about_pid, message);
 224         }
 225
 226         if (log2here) {
 227                 int64_t delta = 0;
 228                 if (log2here == _launchd_shutdown_log) {
 229                         delta = runtime_get_wall_time() - _launchd_shutdown_start;
 230                 } else {
 231                         delta = runtime_get_wall_time() - launchd_system_start;
 232                 }
 233
 234                 fprintf(log2here, "%-8lld %-32s %-8u %-24s %-8u  %s\n", delta, attr->from_name, attr->from_pid, attr->about_name, attr->about_pid, message);
 235         }
 236
 237         if ((LOG_MASK(attr->priority) & _launchd_log_up2)) {
 238                 _logmsg_add(attr, saved_errno, message);
 239         }
 240 }
 241
 242 static kern_return_t
 243 _launchd_log_pack(vm_offset_t *outval, mach_msg_type_number_t *outvalCnt)
 244 {
 245         struct logmsg_s *lm;
 246         void *offset;
 247
 248         *outvalCnt = _launchd_logq_sz;
 249
 250         mig_allocate(outval, *outvalCnt);
 251
 252         if (unlikely(*outval == 0)) {
 253                 return 1;
 254         }
 255
 256         offset = (void *)*outval;
 257         while ((lm = STAILQ_FIRST(&_launchd_logq))) {
 258                 lm->from_name_offset = lm->from_name - (char *)lm;
 259                 lm->about_name_offset = lm->about_name - (char *)lm;
 260                 lm->msg_offset = lm->msg - (char *)lm;
 261                 lm->session_name_offset = lm->session_name - (char *)lm;
 262
 263                 memcpy(offset, lm, lm->obj_sz);
 264
 265                 offset += lm->obj_sz;
 266
 267                 _logmsg_remove(lm);
 268         }
 269
 270         return 0;
 271 }
 272
 273 static void
 274 _launchd_log_uncork_pending_drain(void)
 275 {
 276         mach_msg_type_number_t outvalCnt;
 277         mach_port_t tmp_port;
 278         vm_offset_t outval;
 279
 280         if (!launchd_drain_reply_port) {
 281                 return;
 282         }
 283
 284         if (_launchd_logq_cnt == 0) {
 285                 return;
 286         }
 287
 288         if (_launchd_log_pack(&outval, &outvalCnt) != 0) {
 289                 return;
 290         }
 291
 292         tmp_port = launchd_drain_reply_port;
 293         launchd_drain_reply_port = MACH_PORT_NULL;
 294
 295         if (unlikely(errno = job_mig_log_drain_reply(tmp_port, 0, outval, outvalCnt))) {
 296                 if (errno != MACH_SEND_INVALID_DEST) {
 297                         (void)os_assumes_zero(errno);
 298                 }
 299                 (void)os_assumes_zero(launchd_mport_deallocate(tmp_port));
 300         }
 301
 302         mig_deallocate(outval, outvalCnt);
 303 }
 304
 305 void
 306 launchd_log_push(void)
 307 {
 308         vm_offset_t outval = 0;
 309         mach_msg_type_number_t outvalCnt = 0;
 310
 311         if (!pid1_magic) {
 312                 if (_launchd_perf_log) {
 313                         (void)fflush(_launchd_perf_log);
 314                 }
 315                 if (_launchd_shutdown_log) {
 316                         (void)fflush(_launchd_shutdown_log);
 317                 }
 318                 if (_launchd_debug_log) {
 319                         (void)fflush(_launchd_debug_log);
 320                 }
 321
 322                 if (_launchd_logq_cnt && _launchd_log_pack(&outval, &outvalCnt) == 0) {
 323                         (void)_vprocmgr_log_forward(inherited_bootstrap_port, (void *)outval, outvalCnt);
 324                         mig_deallocate(outval, outvalCnt);
 325                 }
 326         } else {
 327                 _launchd_log_uncork_pending_drain();
 328         }
 329 }
 330
 331 kern_return_t
 332 launchd_log_forward(uid_t forward_uid, gid_t forward_gid, vm_offset_t inval, mach_msg_type_number_t invalCnt)
 333 {
 334         struct logmsg_s *lm, *lm_walk;
 335         mach_msg_type_number_t data_left = invalCnt;
 336
 337         if (inval == 0) {
 338                 return 0;
 339         }
 340
 341         for (lm_walk = (struct logmsg_s *)inval; (data_left > 0) && (lm_walk->obj_sz <= data_left); lm_walk = ((void *)lm_walk + lm_walk->obj_sz)) {
 342                 /* malloc(3) returns non-NULL when you ask for zero bytes. If our object
 343                  * is zero bytes, something is wrong.
 344                  */
 345                 if (lm_walk->obj_sz == 0) {
 346                         launchd_syslog(LOG_WARNING, "Encountered a log message of size 0 with %u bytes left in forwarded data. Ignoring remaining messages.", data_left);
 347                         break;
 348                 }
 349
 350                 if (lm_walk->obj_sz < sizeof(struct logmsg_s)) {
 351                         launchd_syslog(LOG_WARNING, "Received bytes %llu are less than expected bytes %lu.", lm_walk->obj_sz, sizeof(struct logmsg_s));
 352                         break;
 353                 }
 354
 355                 if (!(lm = malloc(lm_walk->obj_sz))) {
 356                         launchd_syslog(LOG_WARNING, "Failed to allocate %llu bytes for log message with %u bytes left in forwarded data. Ignoring remaining messages.", lm_walk->obj_sz, data_left);
 357                         break;
 358                 }
 359
 360                 memcpy(lm, lm_walk, lm_walk->obj_sz);
 361                 lm->sender_uid = forward_uid;
 362                 lm->sender_gid = forward_gid;
 363
 364                 lm->from_name += (size_t)lm;
 365                 lm->about_name += (size_t)lm;
 366                 lm->msg += (size_t)lm;
 367                 lm->session_name += (size_t)lm;
 368
 369                 STAILQ_INSERT_TAIL(&_launchd_logq, lm, sqe);
 370                 _launchd_logq_sz += lm->obj_sz;
 371                 _launchd_logq_cnt++;
 372
 373                 data_left -= lm->obj_sz;
 374         }
 375
 376         mig_deallocate(inval, invalCnt);
 377
 378         return 0;
 379 }
 380
 381 kern_return_t
 382 launchd_log_drain(mach_port_t srp, vm_offset_t *outval, mach_msg_type_number_t *outvalCnt)
 383 {
 384         (void)os_assumes_zero(launchd_drain_reply_port);
 385
 386         if ((_launchd_logq_cnt == 0) || launchd_shutting_down) {
 387                 launchd_drain_reply_port = srp;
 388                 (void)os_assumes_zero(launchd_mport_notify_req(launchd_drain_reply_port, MACH_NOTIFY_DEAD_NAME));
 389
 390                 return MIG_NO_REPLY;
 391         }
 392
 393         return _launchd_log_pack(outval, outvalCnt);
 394 }
 395
 396 void
 397 launchd_closelog(void)
 398 {
 399         launchd_log_push();
 400
 401         if (_launchd_shutdown_log) {
 402                 (void)fflush(_launchd_shutdown_log);
 403                 (void)runtime_fsync(fileno(_launchd_shutdown_log));
 404         }
 405 }