libkern/os/log.c

   1 #include <stddef.h>
   2 #undef offset
   3
   4 #include <kern/cpu_data.h>
   5 #include <os/base.h>
   6 #include <os/object.h>
   7 #include <os/log.h>
   8 #include <stdbool.h>
   9 #include <stdint.h>
  10
  11 #include <vm/vm_kern.h>
  12 #include <mach/vm_statistics.h>
  13 #include <kern/debug.h>
  14 #include <libkern/libkern.h>
  15 #include <libkern/kernel_mach_header.h>
  16 #include <pexpert/pexpert.h>
  17 #include <uuid/uuid.h>
  18 #include <sys/msgbuf.h>
  19
  20 #include <mach/mach_time.h>
  21 #include <kern/thread.h>
  22 #include <kern/simple_lock.h>
  23 #include <kern/kalloc.h>
  24 #include <kern/clock.h>
  25 #include <kern/assert.h>
  26
  27 #include <firehose/tracepoint_private.h>
  28 #include <firehose/chunk_private.h>
  29 #include <os/firehose_buffer_private.h>
  30 #include <os/firehose.h>
  31
  32 #include <os/log_private.h>
  33 #include "trace_internal.h"
  34
  35 #include "log_encode.h"
  36
  37 struct os_log_s {
  38         int a;
  39 };
  40
  41 struct os_log_s _os_log_default;
  42 struct os_log_s _os_log_replay;
  43 extern vm_offset_t kernel_firehose_addr;
  44 extern firehose_chunk_t firehose_boot_chunk;
  45
  46 extern void bsd_log_lock(void);
  47 extern void bsd_log_unlock(void);
  48 extern void logwakeup(struct msgbuf *);
  49
  50 decl_lck_spin_data(extern, oslog_stream_lock)
  51 extern void oslog_streamwakeup(void);
  52 void oslog_streamwrite_locked(firehose_tracepoint_id_u ftid,
  53                 uint64_t stamp, const void *pubdata, size_t publen);
  54 extern void oslog_streamwrite_metadata_locked(oslog_stream_buf_entry_t m_entry);
  55
  56 extern int oslog_stream_open;
  57
  58 extern void *OSKextKextForAddress(const void *);
  59
  60 /* Counters for persistence mode */
  61 uint32_t oslog_p_total_msgcount = 0;
  62 uint32_t oslog_p_metadata_saved_msgcount = 0;
  63 uint32_t oslog_p_metadata_dropped_msgcount = 0;
  64 uint32_t oslog_p_error_count = 0;
  65 uint32_t oslog_p_saved_msgcount = 0;
  66 uint32_t oslog_p_dropped_msgcount = 0;
  67 uint32_t oslog_p_boot_dropped_msgcount = 0;
  68
  69 /* Counters for streaming mode */
  70 uint32_t oslog_s_total_msgcount = 0;
  71 uint32_t oslog_s_error_count = 0;
  72 uint32_t oslog_s_metadata_msgcount = 0;
  73
  74 static bool oslog_boot_done = false;
  75 extern boolean_t early_boot_complete;
  76
  77 #ifdef XNU_KERNEL_PRIVATE
  78 bool startup_serial_logging_active = true;
  79 uint64_t startup_serial_num_procs = 300;
  80 #endif /* XNU_KERNEL_PRIVATE */
  81
  82 // XXX
  83 firehose_tracepoint_id_t
  84 firehose_debug_trace(firehose_stream_t stream, firehose_tracepoint_id_t trace_id,
  85                 uint64_t timestamp, const char *format, const void *pubdata, size_t publen);
  86
  87 static inline firehose_tracepoint_id_t
  88 _firehose_trace(firehose_stream_t stream, firehose_tracepoint_id_u ftid,
  89                 uint64_t stamp, const void *pubdata, size_t publen);
  90
  91 static oslog_stream_buf_entry_t
  92 oslog_stream_create_buf_entry(oslog_stream_link_type_t type, firehose_tracepoint_id_u ftid,
  93                                 uint64_t stamp, const void* pubdata, size_t publen);
  94
  95 static void
  96 _os_log_with_args_internal(os_log_t oslog __unused, os_log_type_t type __unused,
  97                 const char *format, va_list args, void *addr, void *dso);
  98
  99 static void
 100 _os_log_to_msgbuf_internal(const char *format, va_list args, bool safe, bool logging);
 101
 102 static void
 103 _os_log_to_log_internal(os_log_t oslog, os_log_type_t type,
 104                 const char *format, va_list args, void *addr, void *dso);
 105
 106
 107 static void
 108 _os_log_actual(os_log_t oslog, os_log_type_t type, const char *format, void
 109                 *dso, void *addr, os_log_buffer_context_t context);
 110
 111 bool
 112 os_log_info_enabled(os_log_t log __unused)
 113 {
 114         return true;
 115 }
 116
 117 bool
 118 os_log_debug_enabled(os_log_t log __unused)
 119 {
 120         return true;
 121 }
 122
 123 os_log_t
 124 os_log_create(const char *subsystem __unused, const char *category __unused)
 125 {
 126         return &_os_log_default;
 127 }
 128
 129 bool
 130 _os_log_string_is_public(const char *str __unused)
 131 {
 132         return true;
 133 }
 134
 135 __attribute__((noinline,not_tail_called)) void
 136 _os_log_internal(void *dso, os_log_t log, uint8_t type, const char *message, ...)
 137 {
 138     va_list args;
 139     void *addr = __builtin_return_address(0);
 140
 141     va_start(args, message);
 142
 143     _os_log_with_args_internal(log, type, message, args, addr, dso);
 144
 145     va_end(args);
 146
 147     return;
 148 }
 149
 150 #pragma mark - shim functions
 151
 152 __attribute__((noinline,not_tail_called)) void
 153 os_log_with_args(os_log_t oslog, os_log_type_t type, const char *format, va_list args, void *addr)
 154 {
 155     // if no address passed, look it up
 156     if (addr == NULL) {
 157         addr = __builtin_return_address(0);
 158     }
 159
 160     _os_log_with_args_internal(oslog, type, format, args, addr, NULL);
 161 }
 162
 163 static void
 164 _os_log_with_args_internal(os_log_t oslog, os_log_type_t type,
 165                 const char *format, va_list args, void *addr, void *dso)
 166 {
 167     uint32_t  logging_config = atm_get_diagnostic_config();
 168     boolean_t safe;
 169     boolean_t logging;
 170
 171     if (format[0] == '\0') {
 172         return;
 173     }
 174
 175     /* early boot can log to dmesg for later replay (27307943) */
 176     safe = (!early_boot_complete || oslog_is_safe());
 177
 178         if (logging_config & ATM_TRACE_DISABLE || logging_config & ATM_TRACE_OFF) {
 179                 logging = false;
 180         } else {
 181                 logging = true;
 182         }
 183
 184     if (oslog != &_os_log_replay) {
 185         _os_log_to_msgbuf_internal(format, args, safe, logging);
 186     }
 187
 188     if (safe && logging) {
 189         _os_log_to_log_internal(oslog, type, format, args, addr, dso);
 190     }
 191 }
 192
 193 static void
 194 _os_log_to_msgbuf_internal(const char *format, va_list args, bool safe, bool logging)
 195 {
 196     static int msgbufreplay = -1;
 197     va_list args_copy;
 198
 199 #if DEVELOPMENT || DEBUG
 200     if (safe) {
 201         bsd_log_lock();
 202     }
 203 #else
 204     bsd_log_lock();
 205 #endif
 206
 207     if (!safe) {
 208         if (-1 == msgbufreplay) msgbufreplay = msgbufp->msg_bufx;
 209     } else if (logging && (-1 != msgbufreplay)) {
 210         uint32_t i;
 211         uint32_t localbuff_size;
 212         int newl, position;
 213         char *localbuff, *p, *s, *next, ch;
 214
 215         position = msgbufreplay;
 216         msgbufreplay = -1;
 217         localbuff_size = (msgbufp->msg_size + 2); /* + '\n' + '\0' */
 218         /* Size for non-blocking */
 219         if (localbuff_size > 4096) localbuff_size = 4096;
 220         bsd_log_unlock();
 221         /* Allocate a temporary non-circular buffer */
 222         if ((localbuff = (char *)kalloc_noblock(localbuff_size))) {
 223             /* in between here, the log could become bigger, but that's fine */
 224             bsd_log_lock();
 225             /*
 226              * The message buffer is circular; start at the replay pointer, and
 227              * make one loop up to write pointer - 1.
 228              */
 229             p = msgbufp->msg_bufc + position;
 230             for (i = newl = 0; p != msgbufp->msg_bufc + msgbufp->msg_bufx - 1; ++p) {
 231                 if (p >= msgbufp->msg_bufc + msgbufp->msg_size)
 232                     p = msgbufp->msg_bufc;
 233                 ch = *p;
 234                 if (ch == '\0') continue;
 235                 newl = (ch == '\n');
 236                 localbuff[i++] = ch;
 237                 if (i >= (localbuff_size - 2)) break;
 238             }
 239             bsd_log_unlock();
 240
 241             if (!newl) localbuff[i++] = '\n';
 242             localbuff[i++] = 0;
 243
 244             s = localbuff;
 245             while ((next = strchr(s, '\n'))) {
 246                 next++;
 247                 ch = next[0];
 248                 next[0] = 0;
 249                 os_log(&_os_log_replay, "%s", s);
 250                 next[0] = ch;
 251                 s = next;
 252             }
 253             kfree(localbuff, localbuff_size);
 254         }
 255         bsd_log_lock();
 256     }
 257
 258     va_copy(args_copy, args);
 259     vprintf_log_locked(format, args_copy);
 260     va_end(args_copy);
 261
 262 #if DEVELOPMENT || DEBUG
 263     if (safe) {
 264         bsd_log_unlock();
 265         logwakeup(msgbufp);
 266     }
 267 #else
 268     bsd_log_unlock();
 269     if (safe) logwakeup(msgbufp);
 270 #endif
 271 }
 272
 273 static void
 274 _os_log_to_log_internal(os_log_t oslog, os_log_type_t type,
 275                 const char *format, va_list args, void *addr, void *dso)
 276 {
 277     struct os_log_buffer_context_s context;
 278     unsigned char buffer_data[OS_LOG_BUFFER_MAX_SIZE] __attribute__((aligned(8)));
 279     os_log_buffer_t buffer = (os_log_buffer_t)buffer_data;
 280     uint8_t pubdata[OS_LOG_BUFFER_MAX_SIZE];
 281     va_list args_copy;
 282
 283     if (dso == NULL) {
 284         dso = (void *) OSKextKextForAddress(format);
 285         if (dso == NULL) {
 286             return;
 287         }
 288     }
 289
 290     if (!_os_trace_addr_in_text_segment(dso, format)) {
 291         return;
 292     }
 293
 294     if (addr == NULL) {
 295         return;
 296     }
 297
 298     void *dso_addr = (void *) OSKextKextForAddress(addr);
 299     if (dso != dso_addr) {
 300         return;
 301     }
 302
 303     memset(&context, 0, sizeof(context));
 304     memset(buffer, 0, OS_LOG_BUFFER_MAX_SIZE);
 305
 306     context.shimmed = true;
 307     context.buffer = buffer;
 308     context.content_sz = OS_LOG_BUFFER_MAX_SIZE - sizeof(*buffer);
 309     context.pubdata = pubdata;
 310     context.pubdata_sz = sizeof(pubdata);
 311
 312     va_copy(args_copy, args);
 313
 314     (void)hw_atomic_add(&oslog_p_total_msgcount, 1);
 315     if (_os_log_encode(format, args_copy, 0, &context)) {
 316         _os_log_actual(oslog, type, format, dso, addr, &context);
 317     }
 318     else {
 319         (void)hw_atomic_add(&oslog_p_error_count, 1);
 320     }
 321
 322     va_end(args_copy);
 323 }
 324
 325 static inline size_t
 326 _os_trace_write_location_for_address(uint8_t buf[static sizeof(uint64_t)],
 327                 void *dso, const void *address, firehose_tracepoint_flags_t *flags)
 328 {
 329         kernel_mach_header_t *mh = dso;
 330
 331         if (mh->filetype == MH_EXECUTE) {
 332                 *flags = _firehose_tracepoint_flags_pc_style_main_exe;
 333                 memcpy(buf, (uint32_t[]){ (uintptr_t)address - (uintptr_t)dso },
 334                                 sizeof(uint32_t));
 335                 return sizeof(uint32_t);
 336         } else {
 337                 *flags = _firehose_tracepoint_flags_pc_style_absolute;
 338                 memcpy(buf, (uintptr_t[]){ VM_KERNEL_UNSLIDE(address) }, sizeof(uintptr_t));
 339 #if __LP64__
 340                 return 6; // 48 bits are enough
 341 #else
 342                 return sizeof(uintptr_t);
 343 #endif
 344         }
 345 }
 346
 347
 348 OS_ALWAYS_INLINE
 349 static inline size_t
 350 _os_log_buffer_pack(uint8_t *buffdata, size_t buffdata_sz,
 351                 os_log_buffer_context_t ctx)
 352 {
 353         os_log_buffer_t buffer = ctx->buffer;
 354         size_t buffer_sz = sizeof(*ctx->buffer) + ctx->content_sz;
 355         size_t total_sz  = buffer_sz + ctx->pubdata_sz;
 356
 357         if (total_sz > buffdata_sz) {
 358                 return 0;
 359         }
 360
 361         memcpy(buffdata, buffer, buffer_sz);
 362         memcpy(&buffdata[buffer_sz], ctx->pubdata, ctx->pubdata_sz);
 363         return total_sz;
 364 }
 365
 366 static void
 367 _os_log_actual(os_log_t oslog __unused, os_log_type_t type, const char *format,
 368                 void *dso, void *addr, os_log_buffer_context_t context)
 369 {
 370         firehose_stream_t stream;
 371         firehose_tracepoint_flags_t flags = 0;
 372         firehose_tracepoint_id_u trace_id;
 373         uint8_t buffdata[OS_LOG_BUFFER_MAX_SIZE];
 374         size_t addr_len = 0, buffdata_sz;
 375         uint64_t timestamp;
 376         uint64_t thread_id;
 377
 378         // dso == the start of the binary that was loaded
 379         addr_len = _os_trace_write_location_for_address(buffdata, dso, addr, &flags);
 380         buffdata_sz = _os_log_buffer_pack(buffdata + addr_len,
 381                         sizeof(buffdata) - addr_len, context);
 382         if (buffdata_sz == 0) {
 383                 return;
 384         }
 385         buffdata_sz += addr_len;
 386
 387         timestamp = firehose_tracepoint_time(firehose_activity_flags_default);
 388         thread_id = thread_tid(current_thread());
 389
 390         // create trace_id after we've set additional flags
 391         trace_id.ftid_value = FIREHOSE_TRACE_ID_MAKE(firehose_tracepoint_namespace_log,
 392                         type, flags, _os_trace_offset(dso, format, flags));
 393
 394         if (FALSE) {
 395                 firehose_debug_trace(stream, trace_id.ftid_value, timestamp,
 396                                         format, buffdata, buffdata_sz);
 397         }
 398         if (type == OS_LOG_TYPE_INFO || type == OS_LOG_TYPE_DEBUG) {
 399                 stream = firehose_stream_memory;
 400         }
 401         else {
 402                 stream = firehose_stream_persist;
 403         }
 404         _firehose_trace(stream, trace_id, timestamp, buffdata, buffdata_sz);
 405 }
 406
 407 static inline firehose_tracepoint_id_t
 408 _firehose_trace(firehose_stream_t stream, firehose_tracepoint_id_u ftid,
 409                 uint64_t stamp, const void *pubdata, size_t publen)
 410 {
 411         const uint16_t ft_size = offsetof(struct firehose_tracepoint_s, ft_data);
 412         const size_t _firehose_chunk_payload_size =
 413                         sizeof(((struct firehose_chunk_s *)0)->fc_data);
 414
 415         firehose_tracepoint_t ft;
 416
 417         if (slowpath(ft_size + publen > _firehose_chunk_payload_size)) {
 418                 // We'll need to have some handling here. For now - return 0
 419                 (void)hw_atomic_add(&oslog_p_error_count, 1);
 420                 return 0;
 421         }
 422
 423         if (oslog_stream_open && (stream != firehose_stream_metadata)) {
 424
 425                 lck_spin_lock(&oslog_stream_lock);
 426                 if (!oslog_stream_open) {
 427                         lck_spin_unlock(&oslog_stream_lock);
 428                         goto out;
 429                 }
 430
 431                 oslog_s_total_msgcount++;
 432                 oslog_streamwrite_locked(ftid, stamp, pubdata, publen);
 433                 lck_spin_unlock(&oslog_stream_lock);
 434                 oslog_streamwakeup();
 435         }
 436
 437 out:
 438         ft = __firehose_buffer_tracepoint_reserve(stamp, stream, (uint16_t)publen, 0, NULL);
 439         if (!fastpath(ft)) {
 440                 if (oslog_boot_done) {
 441                         if (stream == firehose_stream_metadata) {
 442                                 (void)hw_atomic_add(&oslog_p_metadata_dropped_msgcount, 1);
 443                         }
 444                         else {
 445                                 // If we run out of space in the persistence buffer we're
 446                                 // dropping the message.
 447                                 (void)hw_atomic_add(&oslog_p_dropped_msgcount, 1);
 448                         }
 449                         return 0;
 450                 }
 451                 firehose_chunk_t fbc = firehose_boot_chunk;
 452                 long offset;
 453
 454                 //only stream available during boot is persist
 455                 offset = firehose_chunk_tracepoint_try_reserve(fbc, stamp,
 456                                 firehose_stream_persist, 0, publen, 0, NULL);
 457                 if (offset <= 0) {
 458                         (void)hw_atomic_add(&oslog_p_boot_dropped_msgcount, 1);
 459                         return 0;
 460                 }
 461
 462                 ft = firehose_chunk_tracepoint_begin(fbc, stamp, publen,
 463                                 thread_tid(current_thread()), offset);
 464                 memcpy(ft->ft_data, pubdata, publen);
 465                 firehose_chunk_tracepoint_end(fbc, ft, ftid);
 466                 (void)hw_atomic_add(&oslog_p_saved_msgcount, 1);
 467                 return ftid.ftid_value;
 468         }
 469         if (!oslog_boot_done) {
 470                 oslog_boot_done = true;
 471         }
 472         memcpy(ft->ft_data, pubdata, publen);
 473
 474         __firehose_buffer_tracepoint_flush(ft, ftid);
 475         if (stream == firehose_stream_metadata) {
 476                 (void)hw_atomic_add(&oslog_p_metadata_saved_msgcount, 1);
 477         }
 478         else {
 479                 (void)hw_atomic_add(&oslog_p_saved_msgcount, 1);
 480         }
 481         return ftid.ftid_value;
 482 }
 483
 484 static oslog_stream_buf_entry_t
 485 oslog_stream_create_buf_entry(oslog_stream_link_type_t type, firehose_tracepoint_id_u ftid,
 486                                 uint64_t stamp, const void* pubdata, size_t publen)
 487 {
 488         oslog_stream_buf_entry_t m_entry = NULL;
 489         firehose_tracepoint_t ft = NULL;
 490         size_t m_entry_len = 0;
 491
 492         if (!pubdata) {
 493                 return NULL;
 494         }
 495
 496         m_entry_len = sizeof(struct oslog_stream_buf_entry_s) +
 497                         sizeof(struct firehose_tracepoint_s) + publen;
 498         m_entry = (oslog_stream_buf_entry_t) kalloc(m_entry_len);
 499         if (!m_entry) {
 500                 return NULL;
 501         }
 502
 503         m_entry->type = type;
 504         m_entry->timestamp = stamp;
 505         m_entry->size = sizeof(struct firehose_tracepoint_s) + publen;
 506
 507         ft = m_entry->metadata;
 508         ft->ft_thread = thread_tid(current_thread());
 509         ft->ft_id.ftid_value = ftid.ftid_value;
 510         ft->ft_length = publen;
 511         memcpy(ft->ft_data, pubdata, publen);
 512
 513         return m_entry;
 514 }
 515
 516 #ifdef KERNEL
 517 void
 518 firehose_trace_metadata(firehose_stream_t stream, firehose_tracepoint_id_u ftid,
 519                 uint64_t stamp, const void *pubdata, size_t publen)
 520 {
 521         oslog_stream_buf_entry_t m_entry = NULL;
 522
 523         // If streaming mode is not on, only log  the metadata
 524         // in the persistence buffer
 525
 526         lck_spin_lock(&oslog_stream_lock);
 527         if (!oslog_stream_open) {
 528                 lck_spin_unlock(&oslog_stream_lock);
 529                 goto finish;
 530         }
 531         lck_spin_unlock(&oslog_stream_lock);
 532
 533         // Setup and write the stream metadata entry
 534         m_entry = oslog_stream_create_buf_entry(oslog_stream_link_type_metadata, ftid,
 535                                                         stamp, pubdata, publen);
 536         if (!m_entry) {
 537                 (void)hw_atomic_add(&oslog_s_error_count, 1);
 538                 goto finish;
 539         }
 540
 541         lck_spin_lock(&oslog_stream_lock);
 542         if (!oslog_stream_open) {
 543                 lck_spin_unlock(&oslog_stream_lock);
 544                 kfree(m_entry, sizeof(struct oslog_stream_buf_entry_s) +
 545                         sizeof(struct firehose_tracepoint_s) + publen);
 546                 goto finish;
 547         }
 548         oslog_s_metadata_msgcount++;
 549         oslog_streamwrite_metadata_locked(m_entry);
 550         lck_spin_unlock(&oslog_stream_lock);
 551
 552 finish:
 553         _firehose_trace(stream, ftid, stamp, pubdata, publen);
 554 }
 555 #endif
 556
 557 firehose_tracepoint_id_t
 558 firehose_debug_trace(firehose_stream_t stream, firehose_tracepoint_id_t trace_id,
 559                 uint64_t timestamp, const char *format, const void *pubdata, size_t publen)
 560 {
 561         kprintf("[os_log stream 0x%x trace_id 0x%llx timestamp %llu format '%s' data %p len %lu]\n",
 562                         (unsigned int)stream, (unsigned long long)trace_id, timestamp,
 563                         format, pubdata, publen);
 564         size_t i;
 565         const unsigned char *cdata = (const unsigned char *)pubdata;
 566         for (i=0; i < publen; i += 8) {
 567                 kprintf(">oslog 0x%08x: 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x\n",
 568                                 (unsigned int)i,
 569                                 (i+0) < publen ? cdata[i+0] : 0,
 570                                 (i+1) < publen ? cdata[i+1] : 0,
 571                                 (i+2) < publen ? cdata[i+2] : 0,
 572                                 (i+3) < publen ? cdata[i+3] : 0,
 573                                 (i+4) < publen ? cdata[i+4] : 0,
 574                                 (i+5) < publen ? cdata[i+5] : 0,
 575                                 (i+6) < publen ? cdata[i+6] : 0,
 576                                 (i+7) < publen ? cdata[i+7] : 0
 577                         );
 578         }
 579         return trace_id;
 580 }
 581
 582 void
 583 __firehose_buffer_push_to_logd(firehose_buffer_t fb __unused, bool for_io __unused) {
 584         oslogwakeup();
 585         return;
 586 }
 587
 588 void
 589 __firehose_allocate(vm_offset_t *addr, vm_size_t size __unused)
 590 {
 591         firehose_chunk_t kernel_buffer = (firehose_chunk_t)kernel_firehose_addr;
 592
 593         if (kernel_firehose_addr) {
 594                 *addr = kernel_firehose_addr;
 595         }
 596         else {
 597                 *addr = 0;
 598                 return;
 599         }
 600         // Now that we are done adding logs to this chunk, set the number of writers to 0
 601         // Without this, logd won't flush when the page is full
 602         firehose_boot_chunk->fc_pos.fcp_refcnt = 0;
 603         memcpy(&kernel_buffer[FIREHOSE_BUFFER_KERNEL_CHUNK_COUNT - 1], (const void *)firehose_boot_chunk, FIREHOSE_CHUNK_SIZE);
 604         return;
 605 }
 606 // There isnt a lock held in this case.
 607 void
 608 __firehose_critical_region_enter(void) {
 609         disable_preemption();
 610         return;
 611 }
 612
 613 void
 614 __firehose_critical_region_leave(void) {
 615         enable_preemption();
 616         return;
 617 }
 618