src/log.c

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