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