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 /* on embedded, with no kext loading or unloads,
  38  * make the kernel use the libtrace shared cache path for logging
  39  */
  40 #define FIREHOSE_USES_SHARED_CACHE NO_KEXTD
  41
  42 #if FIREHOSE_USES_SHARED_CACHE
  43 extern vm_offset_t   segLOWESTTEXT;
  44 #endif
  45
  46 struct os_log_s {
  47         int a;
  48 };
  49
  50 struct os_log_s _os_log_default;
  51 struct os_log_s _os_log_replay;
  52 extern vm_offset_t kernel_firehose_addr;
  53 extern firehose_chunk_t firehose_boot_chunk;
  54
  55 extern void bsd_log_lock(void);
  56 extern void bsd_log_unlock(void);
  57 extern void logwakeup(struct msgbuf *);
  58
  59 decl_lck_spin_data(extern, oslog_stream_lock)
  60 extern void oslog_streamwakeup(void);
  61 void oslog_streamwrite_locked(firehose_tracepoint_id_u ftid,
  62                 uint64_t stamp, const void *pubdata, size_t publen);
  63 extern void oslog_streamwrite_metadata_locked(oslog_stream_buf_entry_t m_entry);
  64
  65 extern int oslog_stream_open;
  66
  67 extern void *OSKextKextForAddress(const void *);
  68
  69 /* Counters for persistence mode */
  70 uint32_t oslog_p_total_msgcount = 0;
  71 uint32_t oslog_p_metadata_saved_msgcount = 0;
  72 uint32_t oslog_p_metadata_dropped_msgcount = 0;
  73 uint32_t oslog_p_error_count = 0;
  74 uint32_t oslog_p_saved_msgcount = 0;
  75 uint32_t oslog_p_dropped_msgcount = 0;
  76 uint32_t oslog_p_boot_dropped_msgcount = 0;
  77
  78 /* Counters for streaming mode */
  79 uint32_t oslog_s_total_msgcount = 0;
  80 uint32_t oslog_s_error_count = 0;
  81 uint32_t oslog_s_metadata_msgcount = 0;
  82
  83 static bool oslog_boot_done = false;
  84 extern boolean_t early_boot_complete;
  85
  86 #ifdef XNU_KERNEL_PRIVATE
  87 bool startup_serial_logging_active = true;
  88 uint64_t startup_serial_num_procs = 300;
  89 #endif /* XNU_KERNEL_PRIVATE */
  90
  91 // XXX
  92 firehose_tracepoint_id_t
  93 firehose_debug_trace(firehose_stream_t stream, firehose_tracepoint_id_t trace_id,
  94                 uint64_t timestamp, const char *format, const void *pubdata, size_t publen);
  95
  96 static inline firehose_tracepoint_id_t
  97 _firehose_trace(firehose_stream_t stream, firehose_tracepoint_id_u ftid,
  98                 uint64_t stamp, const void *pubdata, size_t publen);
  99
 100 static oslog_stream_buf_entry_t
 101 oslog_stream_create_buf_entry(oslog_stream_link_type_t type, firehose_tracepoint_id_u ftid,
 102                                 uint64_t stamp, const void* pubdata, size_t publen);
 103
 104 static void
 105 _os_log_with_args_internal(os_log_t oslog __unused, os_log_type_t type __unused,
 106                 const char *format, va_list args, void *addr, void *dso);
 107
 108 static void
 109 _os_log_to_msgbuf_internal(const char *format, va_list args, bool safe, bool logging);
 110
 111 static void
 112 _os_log_to_log_internal(os_log_t oslog, os_log_type_t type,
 113                 const char *format, va_list args, void *addr, void *dso);
 114
 115
 116 static void
 117 _os_log_actual(os_log_t oslog, os_log_type_t type, const char *format, void
 118                 *dso, void *addr, os_log_buffer_context_t context);
 119
 120 bool
 121 os_log_info_enabled(os_log_t log __unused)
 122 {
 123         return true;
 124 }
 125
 126 bool
 127 os_log_debug_enabled(os_log_t log __unused)
 128 {
 129         return true;
 130 }
 131
 132 os_log_t
 133 os_log_create(const char *subsystem __unused, const char *category __unused)
 134 {
 135         return &_os_log_default;
 136 }
 137
 138 bool
 139 _os_log_string_is_public(const char *str __unused)
 140 {
 141         return true;
 142 }
 143
 144 __attribute__((noinline,not_tail_called)) void
 145 _os_log_internal(void *dso, os_log_t log, uint8_t type, const char *message, ...)
 146 {
 147     va_list args;
 148     void *addr = __builtin_return_address(0);
 149
 150     va_start(args, message);
 151
 152     _os_log_with_args_internal(log, type, message, args, addr, dso);
 153
 154     va_end(args);
 155
 156     return;
 157 }
 158
 159 #pragma mark - shim functions
 160
 161 __attribute__((noinline,not_tail_called)) void
 162 os_log_with_args(os_log_t oslog, os_log_type_t type, const char *format, va_list args, void *addr)
 163 {
 164     // if no address passed, look it up
 165     if (addr == NULL) {
 166         addr = __builtin_return_address(0);
 167     }
 168
 169     _os_log_with_args_internal(oslog, type, format, args, addr, NULL);
 170 }
 171
 172 static void
 173 _os_log_with_args_internal(os_log_t oslog, os_log_type_t type,
 174                 const char *format, va_list args, void *addr, void *dso)
 175 {
 176     uint32_t  logging_config = atm_get_diagnostic_config();
 177     boolean_t safe;
 178     boolean_t logging;
 179
 180     if (format[0] == '\0') {
 181         return;
 182     }
 183
 184     /* early boot can log to dmesg for later replay (27307943) */
 185     safe = (!early_boot_complete || oslog_is_safe());
 186
 187         if (logging_config & ATM_TRACE_DISABLE || logging_config & ATM_TRACE_OFF) {
 188                 logging = false;
 189         } else {
 190                 logging = true;
 191         }
 192
 193     if (oslog != &_os_log_replay) {
 194         _os_log_to_msgbuf_internal(format, args, safe, logging);
 195     }
 196
 197     if (safe && logging) {
 198         _os_log_to_log_internal(oslog, type, format, args, addr, dso);
 199     }
 200 }
 201
 202 static void
 203 _os_log_to_msgbuf_internal(const char *format, va_list args, bool safe, bool logging)
 204 {
 205     static int msgbufreplay = -1;
 206     va_list args_copy;
 207
 208 #if DEVELOPMENT || DEBUG
 209     if (safe) {
 210         bsd_log_lock();
 211     }
 212 #else
 213     bsd_log_lock();
 214 #endif
 215
 216     if (!safe) {
 217         if (-1 == msgbufreplay) msgbufreplay = msgbufp->msg_bufx;
 218     } else if (logging && (-1 != msgbufreplay)) {
 219         uint32_t i;
 220         uint32_t localbuff_size;
 221         int newl, position;
 222         char *localbuff, *p, *s, *next, ch;
 223
 224         position = msgbufreplay;
 225         msgbufreplay = -1;
 226         localbuff_size = (msgbufp->msg_size + 2); /* + '\n' + '\0' */
 227         /* Size for non-blocking */
 228         if (localbuff_size > 4096) localbuff_size = 4096;
 229         bsd_log_unlock();
 230         /* Allocate a temporary non-circular buffer */
 231         if ((localbuff = (char *)kalloc_noblock(localbuff_size))) {
 232             /* in between here, the log could become bigger, but that's fine */
 233             bsd_log_lock();
 234             /*
 235              * The message buffer is circular; start at the replay pointer, and
 236              * make one loop up to write pointer - 1.
 237              */
 238             p = msgbufp->msg_bufc + position;
 239             for (i = newl = 0; p != msgbufp->msg_bufc + msgbufp->msg_bufx - 1; ++p) {
 240                 if (p >= msgbufp->msg_bufc + msgbufp->msg_size)
 241                     p = msgbufp->msg_bufc;
 242                 ch = *p;
 243                 if (ch == '\0') continue;
 244                 newl = (ch == '\n');
 245                 localbuff[i++] = ch;
 246                 if (i >= (localbuff_size - 2)) break;
 247             }
 248             bsd_log_unlock();
 249
 250             if (!newl) localbuff[i++] = '\n';
 251             localbuff[i++] = 0;
 252
 253             s = localbuff;
 254             while ((next = strchr(s, '\n'))) {
 255                 next++;
 256                 ch = next[0];
 257                 next[0] = 0;
 258                 os_log(&_os_log_replay, "%s", s);
 259                 next[0] = ch;
 260                 s = next;
 261             }
 262             kfree(localbuff, localbuff_size);
 263         }
 264         bsd_log_lock();
 265     }
 266
 267     va_copy(args_copy, args);
 268     vprintf_log_locked(format, args_copy);
 269     va_end(args_copy);
 270
 271 #if DEVELOPMENT || DEBUG
 272     if (safe) {
 273         bsd_log_unlock();
 274         logwakeup(msgbufp);
 275     }
 276 #else
 277     bsd_log_unlock();
 278     if (safe) logwakeup(msgbufp);
 279 #endif
 280 }
 281
 282 static void
 283 _os_log_to_log_internal(os_log_t oslog, os_log_type_t type,
 284                 const char *format, va_list args, void *addr, void *dso)
 285 {
 286     struct os_log_buffer_context_s context;
 287     unsigned char buffer_data[OS_LOG_BUFFER_MAX_SIZE] __attribute__((aligned(8)));
 288     os_log_buffer_t buffer = (os_log_buffer_t)buffer_data;
 289     uint8_t pubdata[OS_LOG_BUFFER_MAX_SIZE];
 290     va_list args_copy;
 291
 292     if (addr == NULL) {
 293         return;
 294     }
 295
 296 #if FIREHOSE_USES_SHARED_CACHE
 297     dso = (void *) segLOWESTTEXT;
 298 #else /* FIREHOSE_USES_SHARED_CACHE */
 299     if (dso == NULL) {
 300         dso = (void *) OSKextKextForAddress(format);
 301         if (dso == NULL) {
 302             return;
 303         }
 304     }
 305
 306     if (!_os_trace_addr_in_text_segment(dso, format)) {
 307         return;
 308     }
 309
 310     void *dso_addr = (void *) OSKextKextForAddress(addr);
 311     if (dso != dso_addr) {
 312         return;
 313     }
 314 #endif /* FIREHOSE_USES_SHARED_CACHE */
 315
 316     memset(&context, 0, sizeof(context));
 317     memset(buffer, 0, OS_LOG_BUFFER_MAX_SIZE);
 318
 319     context.shimmed = true;
 320     context.buffer = buffer;
 321     context.content_sz = OS_LOG_BUFFER_MAX_SIZE - sizeof(*buffer);
 322     context.pubdata = pubdata;
 323     context.pubdata_sz = sizeof(pubdata);
 324
 325     va_copy(args_copy, args);
 326
 327     (void)hw_atomic_add(&oslog_p_total_msgcount, 1);
 328     if (_os_log_encode(format, args_copy, 0, &context)) {
 329         _os_log_actual(oslog, type, format, dso, addr, &context);
 330     }
 331     else {
 332         (void)hw_atomic_add(&oslog_p_error_count, 1);
 333     }
 334
 335     va_end(args_copy);
 336 }
 337
 338 static inline size_t
 339 _os_trace_write_location_for_address(uint8_t buf[static sizeof(uint64_t)],
 340                 void *dso, const void *address, firehose_tracepoint_flags_t *flags)
 341 {
 342 #if FIREHOSE_USES_SHARED_CACHE
 343     *flags = _firehose_tracepoint_flags_pc_style_shared_cache;
 344     memcpy(buf, (uint32_t[]){ (uintptr_t)address - (uintptr_t)dso },
 345                         sizeof(uint32_t));
 346         return sizeof(uint32_t);
 347
 348 #else /* FIREHOSE_USES_SHARED_CACHE */
 349     kernel_mach_header_t *mh = dso;
 350
 351         if (mh->filetype == MH_EXECUTE) {
 352                 *flags = _firehose_tracepoint_flags_pc_style_main_exe;
 353
 354                 memcpy(buf, (uint32_t[]){ (uintptr_t)address - (uintptr_t)dso },
 355                                 sizeof(uint32_t));
 356                 return sizeof(uint32_t);
 357         } else {
 358                 *flags = _firehose_tracepoint_flags_pc_style_absolute;
 359                 memcpy(buf, (uintptr_t[]){ VM_KERNEL_UNSLIDE(address) }, sizeof(uintptr_t));
 360 #if __LP64__
 361                 return 6; // 48 bits are enough
 362 #else
 363                 return sizeof(uintptr_t);
 364 #endif
 365         }
 366 #endif /* !FIREHOSE_USES_SHARED_CACHE */
 367 }
 368
 369
 370 OS_ALWAYS_INLINE
 371 static inline size_t
 372 _os_log_buffer_pack(uint8_t *buffdata, size_t buffdata_sz,
 373                 os_log_buffer_context_t ctx)
 374 {
 375         os_log_buffer_t buffer = ctx->buffer;
 376         size_t buffer_sz = sizeof(*ctx->buffer) + ctx->content_sz;
 377         size_t total_sz  = buffer_sz + ctx->pubdata_sz;
 378
 379         if (total_sz > buffdata_sz) {
 380                 return 0;
 381         }
 382
 383         memcpy(buffdata, buffer, buffer_sz);
 384         memcpy(&buffdata[buffer_sz], ctx->pubdata, ctx->pubdata_sz);
 385         return total_sz;
 386 }
 387
 388 static void
 389 _os_log_actual(os_log_t oslog __unused, os_log_type_t type, const char *format,
 390                 void *dso, void *addr, os_log_buffer_context_t context)
 391 {
 392         firehose_stream_t stream;
 393         firehose_tracepoint_flags_t flags = 0;
 394         firehose_tracepoint_id_u trace_id;
 395         uint8_t buffdata[OS_LOG_BUFFER_MAX_SIZE];
 396         size_t addr_len = 0, buffdata_sz;
 397         uint64_t timestamp;
 398         uint64_t thread_id;
 399
 400         // dso == the start of the binary that was loaded
 401         addr_len = _os_trace_write_location_for_address(buffdata, dso, addr, &flags);
 402         buffdata_sz = _os_log_buffer_pack(buffdata + addr_len,
 403                         sizeof(buffdata) - addr_len, context);
 404         if (buffdata_sz == 0) {
 405                 return;
 406         }
 407         buffdata_sz += addr_len;
 408
 409         timestamp = firehose_tracepoint_time(firehose_activity_flags_default);
 410         thread_id = thread_tid(current_thread());
 411
 412         // create trace_id after we've set additional flags
 413         trace_id.ftid_value = FIREHOSE_TRACE_ID_MAKE(firehose_tracepoint_namespace_log,
 414                         type, flags, _os_trace_offset(dso, format, flags));
 415
 416         if (FALSE) {
 417                 firehose_debug_trace(stream, trace_id.ftid_value, timestamp,
 418                                         format, buffdata, buffdata_sz);
 419         }
 420         if (type == OS_LOG_TYPE_INFO || type == OS_LOG_TYPE_DEBUG) {
 421                 stream = firehose_stream_memory;
 422         }
 423         else {
 424                 stream = firehose_stream_persist;
 425         }
 426         _firehose_trace(stream, trace_id, timestamp, buffdata, buffdata_sz);
 427 }
 428
 429 static inline firehose_tracepoint_id_t
 430 _firehose_trace(firehose_stream_t stream, firehose_tracepoint_id_u ftid,
 431                 uint64_t stamp, const void *pubdata, size_t publen)
 432 {
 433         const uint16_t ft_size = offsetof(struct firehose_tracepoint_s, ft_data);
 434         const size_t _firehose_chunk_payload_size =
 435                         sizeof(((struct firehose_chunk_s *)0)->fc_data);
 436
 437         firehose_tracepoint_t ft;
 438
 439         if (slowpath(ft_size + publen > _firehose_chunk_payload_size)) {
 440                 // We'll need to have some handling here. For now - return 0
 441                 (void)hw_atomic_add(&oslog_p_error_count, 1);
 442                 return 0;
 443         }
 444
 445         if (oslog_stream_open && (stream != firehose_stream_metadata)) {
 446
 447                 lck_spin_lock(&oslog_stream_lock);
 448                 if (!oslog_stream_open) {
 449                         lck_spin_unlock(&oslog_stream_lock);
 450                         goto out;
 451                 }
 452
 453                 oslog_s_total_msgcount++;
 454                 oslog_streamwrite_locked(ftid, stamp, pubdata, publen);
 455                 lck_spin_unlock(&oslog_stream_lock);
 456                 oslog_streamwakeup();
 457         }
 458
 459 out:
 460         ft = __firehose_buffer_tracepoint_reserve(stamp, stream, (uint16_t)publen, 0, NULL);
 461         if (!fastpath(ft)) {
 462                 if (oslog_boot_done) {
 463                         if (stream == firehose_stream_metadata) {
 464                                 (void)hw_atomic_add(&oslog_p_metadata_dropped_msgcount, 1);
 465                         }
 466                         else {
 467                                 // If we run out of space in the persistence buffer we're
 468                                 // dropping the message.
 469                                 (void)hw_atomic_add(&oslog_p_dropped_msgcount, 1);
 470                         }
 471                         return 0;
 472                 }
 473                 firehose_chunk_t fbc = firehose_boot_chunk;
 474                 long offset;
 475
 476                 //only stream available during boot is persist
 477                 offset = firehose_chunk_tracepoint_try_reserve(fbc, stamp,
 478                                 firehose_stream_persist, 0, publen, 0, NULL);
 479                 if (offset <= 0) {
 480                         (void)hw_atomic_add(&oslog_p_boot_dropped_msgcount, 1);
 481                         return 0;
 482                 }
 483
 484                 ft = firehose_chunk_tracepoint_begin(fbc, stamp, publen,
 485                                 thread_tid(current_thread()), offset);
 486                 memcpy(ft->ft_data, pubdata, publen);
 487                 firehose_chunk_tracepoint_end(fbc, ft, ftid);
 488                 (void)hw_atomic_add(&oslog_p_saved_msgcount, 1);
 489                 return ftid.ftid_value;
 490         }
 491         if (!oslog_boot_done) {
 492                 oslog_boot_done = true;
 493         }
 494         memcpy(ft->ft_data, pubdata, publen);
 495
 496         __firehose_buffer_tracepoint_flush(ft, ftid);
 497         if (stream == firehose_stream_metadata) {
 498                 (void)hw_atomic_add(&oslog_p_metadata_saved_msgcount, 1);
 499         }
 500         else {
 501                 (void)hw_atomic_add(&oslog_p_saved_msgcount, 1);
 502         }
 503         return ftid.ftid_value;
 504 }
 505
 506 static oslog_stream_buf_entry_t
 507 oslog_stream_create_buf_entry(oslog_stream_link_type_t type, firehose_tracepoint_id_u ftid,
 508                                 uint64_t stamp, const void* pubdata, size_t publen)
 509 {
 510         oslog_stream_buf_entry_t m_entry = NULL;
 511         firehose_tracepoint_t ft = NULL;
 512         size_t m_entry_len = 0;
 513
 514         if (!pubdata) {
 515                 return NULL;
 516         }
 517
 518         m_entry_len = sizeof(struct oslog_stream_buf_entry_s) +
 519                         sizeof(struct firehose_tracepoint_s) + publen;
 520         m_entry = (oslog_stream_buf_entry_t) kalloc(m_entry_len);
 521         if (!m_entry) {
 522                 return NULL;
 523         }
 524
 525         m_entry->type = type;
 526         m_entry->timestamp = stamp;
 527         m_entry->size = sizeof(struct firehose_tracepoint_s) + publen;
 528
 529         ft = m_entry->metadata;
 530         ft->ft_thread = thread_tid(current_thread());
 531         ft->ft_id.ftid_value = ftid.ftid_value;
 532         ft->ft_length = publen;
 533         memcpy(ft->ft_data, pubdata, publen);
 534
 535         return m_entry;
 536 }
 537
 538 #ifdef KERNEL
 539 void
 540 firehose_trace_metadata(firehose_stream_t stream, firehose_tracepoint_id_u ftid,
 541                 uint64_t stamp, const void *pubdata, size_t publen)
 542 {
 543         oslog_stream_buf_entry_t m_entry = NULL;
 544
 545         // If streaming mode is not on, only log  the metadata
 546         // in the persistence buffer
 547
 548         lck_spin_lock(&oslog_stream_lock);
 549         if (!oslog_stream_open) {
 550                 lck_spin_unlock(&oslog_stream_lock);
 551                 goto finish;
 552         }
 553         lck_spin_unlock(&oslog_stream_lock);
 554
 555         // Setup and write the stream metadata entry
 556         m_entry = oslog_stream_create_buf_entry(oslog_stream_link_type_metadata, ftid,
 557                                                         stamp, pubdata, publen);
 558         if (!m_entry) {
 559                 (void)hw_atomic_add(&oslog_s_error_count, 1);
 560                 goto finish;
 561         }
 562
 563         lck_spin_lock(&oslog_stream_lock);
 564         if (!oslog_stream_open) {
 565                 lck_spin_unlock(&oslog_stream_lock);
 566                 kfree(m_entry, sizeof(struct oslog_stream_buf_entry_s) +
 567                         sizeof(struct firehose_tracepoint_s) + publen);
 568                 goto finish;
 569         }
 570         oslog_s_metadata_msgcount++;
 571         oslog_streamwrite_metadata_locked(m_entry);
 572         lck_spin_unlock(&oslog_stream_lock);
 573
 574 finish:
 575         _firehose_trace(stream, ftid, stamp, pubdata, publen);
 576 }
 577 #endif
 578
 579 firehose_tracepoint_id_t
 580 firehose_debug_trace(firehose_stream_t stream, firehose_tracepoint_id_t trace_id,
 581                 uint64_t timestamp, const char *format, const void *pubdata, size_t publen)
 582 {
 583         kprintf("[os_log stream 0x%x trace_id 0x%llx timestamp %llu format '%s' data %p len %lu]\n",
 584                         (unsigned int)stream, (unsigned long long)trace_id, timestamp,
 585                         format, pubdata, publen);
 586         size_t i;
 587         const unsigned char *cdata = (const unsigned char *)pubdata;
 588         for (i=0; i < publen; i += 8) {
 589                 kprintf(">oslog 0x%08x: 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x\n",
 590                                 (unsigned int)i,
 591                                 (i+0) < publen ? cdata[i+0] : 0,
 592                                 (i+1) < publen ? cdata[i+1] : 0,
 593                                 (i+2) < publen ? cdata[i+2] : 0,
 594                                 (i+3) < publen ? cdata[i+3] : 0,
 595                                 (i+4) < publen ? cdata[i+4] : 0,
 596                                 (i+5) < publen ? cdata[i+5] : 0,
 597                                 (i+6) < publen ? cdata[i+6] : 0,
 598                                 (i+7) < publen ? cdata[i+7] : 0
 599                         );
 600         }
 601         return trace_id;
 602 }
 603
 604 void
 605 __firehose_buffer_push_to_logd(firehose_buffer_t fb __unused, bool for_io __unused) {
 606         oslogwakeup();
 607         return;
 608 }
 609
 610 void
 611 __firehose_allocate(vm_offset_t *addr, vm_size_t size __unused)
 612 {
 613         firehose_chunk_t kernel_buffer = (firehose_chunk_t)kernel_firehose_addr;
 614
 615         if (kernel_firehose_addr) {
 616                 *addr = kernel_firehose_addr;
 617         }
 618         else {
 619                 *addr = 0;
 620                 return;
 621         }
 622         // Now that we are done adding logs to this chunk, set the number of writers to 0
 623         // Without this, logd won't flush when the page is full
 624         firehose_boot_chunk->fc_pos.fcp_refcnt = 0;
 625         memcpy(&kernel_buffer[FIREHOSE_BUFFER_KERNEL_CHUNK_COUNT - 1], (const void *)firehose_boot_chunk, FIREHOSE_CHUNK_SIZE);
 626         return;
 627 }
 628 // There isnt a lock held in this case.
 629 void
 630 __firehose_critical_region_enter(void) {
 631         disable_preemption();
 632         return;
 633 }
 634
 635 void
 636 __firehose_critical_region_leave(void) {
 637         enable_preemption();
 638         return;
 639 }
 640
 641 #ifdef CONFIG_XNUPOST
 642
 643 #include <tests/xnupost.h>
 644 #define TESTOSLOGFMT(fn_name) "%u^%llu/%llu^kernel^0^test^" fn_name
 645 #define TESTOSLOGPFX "TESTLOG:%u#"
 646 #define TESTOSLOG(fn_name) TESTOSLOGPFX TESTOSLOGFMT(fn_name "#")
 647
 648 extern u_int32_t RandomULong(void);
 649 extern uint32_t find_pattern_in_buffer(char * pattern, uint32_t len, int expected_count);
 650 void test_oslog_default_helper(uint32_t uniqid, uint64_t count);
 651 void test_oslog_info_helper(uint32_t uniqid, uint64_t count);
 652 void test_oslog_debug_helper(uint32_t uniqid, uint64_t count);
 653 void test_oslog_error_helper(uint32_t uniqid, uint64_t count);
 654 void test_oslog_fault_helper(uint32_t uniqid, uint64_t count);
 655 void _test_log_loop(void * arg __unused, wait_result_t wres __unused);
 656 void test_oslog_handleOSLogCtl(int32_t * in, int32_t * out, int32_t len);
 657 kern_return_t test_stresslog_dropmsg(uint32_t uniqid);
 658
 659 kern_return_t test_os_log(void);
 660 kern_return_t test_os_log_parallel(void);
 661
 662 #define GENOSLOGHELPER(fname, ident, callout_f)                                                            \
 663     void fname(uint32_t uniqid, uint64_t count)                                                            \
 664     {                                                                                                      \
 665         int32_t datalen = 0;                                                                               \
 666         uint32_t checksum = 0;                                                                             \
 667         char databuffer[256];                                                                              \
 668         T_LOG("Doing os_log of %llu TESTLOG msgs for fn " ident, count);                                   \
 669         for (uint64_t i = 0; i < count; i++)                                                               \
 670         {                                                                                                  \
 671             datalen = snprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT(ident), uniqid, i + 1, count); \
 672             checksum = crc32(0, databuffer, datalen);                                                      \
 673             callout_f(OS_LOG_DEFAULT, TESTOSLOG(ident), checksum, uniqid, i + 1, count);                   \
 674             /*T_LOG(TESTOSLOG(ident), checksum, uniqid, i + 1, count);*/                                   \
 675         }                                                                                                  \
 676     }
 677
 678 GENOSLOGHELPER(test_oslog_info_helper, "oslog_info_helper", os_log_info);
 679 GENOSLOGHELPER(test_oslog_fault_helper, "oslog_fault_helper", os_log_fault);
 680 GENOSLOGHELPER(test_oslog_debug_helper, "oslog_debug_helper", os_log_debug);
 681 GENOSLOGHELPER(test_oslog_error_helper, "oslog_error_helper", os_log_error);
 682 GENOSLOGHELPER(test_oslog_default_helper, "oslog_default_helper", os_log);
 683
 684 kern_return_t test_os_log()
 685 {
 686     char databuffer[256];
 687     uint32_t uniqid = RandomULong();
 688     uint32_t match_count = 0;
 689     uint32_t checksum = 0;
 690     uint32_t total_msg = 0;
 691     uint32_t saved_msg = 0;
 692     uint32_t dropped_msg = 0;
 693     int datalen = 0;
 694     uint64_t a = mach_absolute_time();
 695     uint64_t seqno = 1;
 696     uint64_t total_seqno = 2;
 697
 698     os_log_t log_handle = os_log_create("com.apple.xnu.test.t1", "kpost");
 699
 700     T_ASSERT_EQ_PTR(&_os_log_default, log_handle, "os_log_create returns valid value.");
 701     T_ASSERT_EQ_INT(TRUE, os_log_info_enabled(log_handle), "os_log_info is enabled");
 702     T_ASSERT_EQ_INT(TRUE, os_log_debug_enabled(log_handle), "os_log_debug is enabled");
 703     T_ASSERT_EQ_PTR(&_os_log_default, OS_LOG_DEFAULT, "ensure OS_LOG_DEFAULT is _os_log_default");
 704
 705     total_msg = oslog_p_total_msgcount;
 706     saved_msg = oslog_p_saved_msgcount;
 707     dropped_msg = oslog_p_dropped_msgcount;
 708     T_LOG("oslog internal counters total %u , saved %u, dropped %u", total_msg, saved_msg, dropped_msg);
 709
 710     T_LOG("Validating with uniqid %u u64 %llu", uniqid, a);
 711     T_ASSERT_NE_UINT(0, uniqid, "random number should not be zero");
 712     T_ASSERT_NE_ULLONG(0, a, "absolute time should not be zero");
 713
 714     datalen = snprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT("printf_only"), uniqid, seqno, total_seqno);
 715     checksum = crc32(0, databuffer, datalen);
 716     printf(TESTOSLOG("printf_only") "mat%llu\n", checksum, uniqid, seqno, total_seqno, a);
 717
 718     seqno += 1;
 719     datalen = snprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT("printf_only"), uniqid, seqno, total_seqno);
 720     checksum = crc32(0, databuffer, datalen);
 721     printf(TESTOSLOG("printf_only") "mat%llu\n", checksum, uniqid, seqno, total_seqno, a);
 722
 723     datalen = snprintf(databuffer, sizeof(databuffer), "kernel^0^test^printf_only#mat%llu", a);
 724     match_count = find_pattern_in_buffer(databuffer, datalen, total_seqno);
 725     T_EXPECT_EQ_UINT(match_count, 2, "verify printf_only goes to systemlog buffer");
 726
 727     uint32_t logging_config = atm_get_diagnostic_config();
 728     T_LOG("checking atm_diagnostic_config 0x%X", logging_config);
 729
 730     if ((logging_config & ATM_TRACE_OFF) || (logging_config & ATM_TRACE_DISABLE))
 731     {
 732         T_LOG("ATM_TRACE_OFF / ATM_TRACE_DISABLE is set. Would not see oslog messages. skipping the rest of test.");
 733         return KERN_SUCCESS;
 734     }
 735
 736     /* for enabled logging printfs should be saved in oslog as well */
 737     T_EXPECT_GE_UINT((oslog_p_total_msgcount - total_msg), 2, "atleast 2 msgs should be seen by oslog system");
 738
 739     a = mach_absolute_time();
 740     total_seqno = 1;
 741     seqno = 1;
 742     total_msg = oslog_p_total_msgcount;
 743     saved_msg = oslog_p_saved_msgcount;
 744     dropped_msg = oslog_p_dropped_msgcount;
 745     datalen = snprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT("oslog_info"), uniqid, seqno, total_seqno);
 746     checksum = crc32(0, databuffer, datalen);
 747     os_log_info(log_handle, TESTOSLOG("oslog_info") "mat%llu", checksum, uniqid, seqno, total_seqno, a);
 748     T_EXPECT_GE_UINT((oslog_p_total_msgcount - total_msg), 1, "total message count in buffer");
 749
 750     datalen = snprintf(databuffer, sizeof(databuffer), "kernel^0^test^oslog_info#mat%llu", a);
 751     match_count = find_pattern_in_buffer(databuffer, datalen, total_seqno);
 752     T_EXPECT_EQ_UINT(match_count, 1, "verify oslog_info does not go to systemlog buffer");
 753
 754     total_msg = oslog_p_total_msgcount;
 755     test_oslog_info_helper(uniqid, 10);
 756     T_EXPECT_GE_UINT(oslog_p_total_msgcount - total_msg, 10, "test_oslog_info_helper: Should have seen 10 msgs");
 757
 758     total_msg = oslog_p_total_msgcount;
 759     test_oslog_debug_helper(uniqid, 10);
 760     T_EXPECT_GE_UINT(oslog_p_total_msgcount - total_msg, 10, "test_oslog_debug_helper:Should have seen 10 msgs");
 761
 762     total_msg = oslog_p_total_msgcount;
 763     test_oslog_error_helper(uniqid, 10);
 764     T_EXPECT_GE_UINT(oslog_p_total_msgcount - total_msg, 10, "test_oslog_error_helper:Should have seen 10 msgs");
 765
 766     total_msg = oslog_p_total_msgcount;
 767     test_oslog_default_helper(uniqid, 10);
 768     T_EXPECT_GE_UINT(oslog_p_total_msgcount - total_msg, 10, "test_oslog_default_helper:Should have seen 10 msgs");
 769
 770     total_msg = oslog_p_total_msgcount;
 771     test_oslog_fault_helper(uniqid, 10);
 772     T_EXPECT_GE_UINT(oslog_p_total_msgcount - total_msg, 10, "test_oslog_fault_helper:Should have seen 10 msgs");
 773
 774     T_LOG("oslog internal counters total %u , saved %u, dropped %u", oslog_p_total_msgcount, oslog_p_saved_msgcount,
 775           oslog_p_dropped_msgcount);
 776
 777     return KERN_SUCCESS;
 778 }
 779
 780 static uint32_t _test_log_loop_count = 0;
 781 void _test_log_loop(void * arg __unused, wait_result_t wres __unused)
 782 {
 783     uint32_t uniqid = RandomULong();
 784     test_oslog_debug_helper(uniqid, 100);
 785     (void)hw_atomic_add(&_test_log_loop_count, 100);
 786 }
 787
 788 kern_return_t test_os_log_parallel(void)
 789 {
 790     thread_t thread[2];
 791     kern_return_t kr;
 792     uint32_t uniqid = RandomULong();
 793
 794     printf("oslog internal counters total %u , saved %u, dropped %u", oslog_p_total_msgcount, oslog_p_saved_msgcount,
 795            oslog_p_dropped_msgcount);
 796
 797     kr = kernel_thread_start(_test_log_loop, NULL, &thread[0]);
 798     T_ASSERT_EQ_INT(kr, KERN_SUCCESS, "kernel_thread_start returned successfully");
 799
 800     kr = kernel_thread_start(_test_log_loop, NULL, &thread[1]);
 801     T_ASSERT_EQ_INT(kr, KERN_SUCCESS, "kernel_thread_start returned successfully");
 802
 803     test_oslog_info_helper(uniqid, 100);
 804
 805     /* wait until other thread has also finished */
 806     while (_test_log_loop_count < 200)
 807     {
 808         delay(1000);
 809     }
 810
 811     thread_deallocate(thread[0]);
 812     thread_deallocate(thread[1]);
 813
 814     T_LOG("oslog internal counters total %u , saved %u, dropped %u", oslog_p_total_msgcount, oslog_p_saved_msgcount,
 815           oslog_p_dropped_msgcount);
 816     T_PASS("parallel_logging tests is now complete");
 817
 818     return KERN_SUCCESS;
 819 }
 820
 821 void test_oslog_handleOSLogCtl(int32_t * in, int32_t * out, int32_t len)
 822 {
 823     if (!in || !out || len != 4)
 824         return;
 825     switch (in[0]) {
 826             case 1:
 827             {
 828                 /* send out counters */
 829                 out[1] = oslog_p_total_msgcount;
 830                 out[2] = oslog_p_saved_msgcount;
 831                 out[3] = oslog_p_dropped_msgcount;
 832                 out[0] = KERN_SUCCESS;
 833                 break;
 834             }
 835             case 2:
 836             {
 837                 /* mini stress run */
 838                 out[0] = test_os_log_parallel();
 839                 break;
 840             }
 841             case 3:
 842             {
 843                 /* drop msg tests */
 844                         out[1] = RandomULong();
 845                 out[0] = test_stresslog_dropmsg(out[1]);
 846                 break;
 847             }
 848             case 4:
 849             {
 850                 /* invoke log helpers */
 851                 uint32_t uniqid = in[3];
 852                 int32_t msgcount = in[2];
 853                 if (uniqid == 0 || msgcount == 0)
 854                 {
 855                     out[0] = KERN_INVALID_VALUE;
 856                     return;
 857                 }
 858
 859                 switch (in[1]) {
 860                         case OS_LOG_TYPE_INFO: test_oslog_info_helper(uniqid, msgcount); break;
 861                         case OS_LOG_TYPE_DEBUG: test_oslog_debug_helper(uniqid, msgcount); break;
 862                         case OS_LOG_TYPE_ERROR: test_oslog_error_helper(uniqid, msgcount); break;
 863                         case OS_LOG_TYPE_FAULT: test_oslog_fault_helper(uniqid, msgcount); break;
 864                         case OS_LOG_TYPE_DEFAULT:
 865                         default: test_oslog_default_helper(uniqid, msgcount); break;
 866                 }
 867                 out[0] = KERN_SUCCESS;
 868                 break;
 869                 /* end of case 4 */
 870             }
 871             default:
 872             {
 873                 out[0] = KERN_INVALID_VALUE;
 874                 break;
 875             }
 876     }
 877     return;
 878 }
 879
 880 kern_return_t test_stresslog_dropmsg(uint32_t uniqid)
 881 {
 882     uint32_t total, saved, dropped;
 883     total = oslog_p_total_msgcount;
 884     saved = oslog_p_saved_msgcount;
 885     dropped = oslog_p_dropped_msgcount;
 886     uniqid = RandomULong();
 887     test_oslog_debug_helper(uniqid, 100);
 888     while ((oslog_p_dropped_msgcount - dropped) == 0)
 889     {
 890         test_oslog_debug_helper(uniqid, 100);
 891     }
 892     printf("test_stresslog_dropmsg: logged %u msgs, saved %u and caused a drop of %u msgs. \n", oslog_p_total_msgcount - total,
 893            oslog_p_saved_msgcount - saved, oslog_p_dropped_msgcount - dropped);
 894     return KERN_SUCCESS;
 895 }
 896
 897 #endif