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