4 #include <kern/cpu_data.h>
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>
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>
27 #include <firehose/tracepoint_private.h>
28 #include <firehose/chunk_private.h>
29 #include <os/firehose_buffer_private.h>
30 #include <os/firehose.h>
32 #include <os/log_private.h>
33 #include "trace_internal.h"
35 #include "log_encode.h"
37 /* on embedded, with no kext loading or unloads,
38 * make the kernel use the libtrace shared cache path for logging
40 #define FIREHOSE_USES_SHARED_CACHE NO_KEXTD
42 #if FIREHOSE_USES_SHARED_CACHE
43 extern vm_offset_t segLOWESTTEXT
;
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
;
55 extern void bsd_log_lock(void);
56 extern void bsd_log_unlock(void);
57 extern void logwakeup(struct msgbuf
*);
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
);
65 extern int oslog_stream_open
;
67 extern void *OSKextKextForAddress(const void *);
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;
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;
83 static bool oslog_boot_done
= false;
84 extern boolean_t early_boot_complete
;
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 */
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
);
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
);
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
);
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
);
109 _os_log_to_msgbuf_internal(const char *format
, va_list args
, bool safe
, bool logging
);
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
);
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
);
121 os_log_info_enabled(os_log_t log __unused
)
127 os_log_debug_enabled(os_log_t log __unused
)
133 os_log_create(const char *subsystem __unused
, const char *category __unused
)
135 return &_os_log_default
;
139 _os_log_string_is_public(const char *str __unused
)
144 __attribute__((noinline
,not_tail_called
)) void
145 _os_log_internal(void *dso
, os_log_t log
, uint8_t type
, const char *message
, ...)
148 void *addr
= __builtin_return_address(0);
150 va_start(args
, message
);
152 _os_log_with_args_internal(log
, type
, message
, args
, addr
, dso
);
159 #pragma mark - shim functions
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
)
164 // if no address passed, look it up
166 addr
= __builtin_return_address(0);
169 _os_log_with_args_internal(oslog
, type
, format
, args
, addr
, NULL
);
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
)
176 uint32_t logging_config
= atm_get_diagnostic_config();
180 if (format
[0] == '\0') {
184 /* early boot can log to dmesg for later replay (27307943) */
185 safe
= (!early_boot_complete
|| oslog_is_safe());
187 if (logging_config
& ATM_TRACE_DISABLE
|| logging_config
& ATM_TRACE_OFF
) {
193 if (oslog
!= &_os_log_replay
) {
194 _os_log_to_msgbuf_internal(format
, args
, safe
, logging
);
197 if (safe
&& logging
) {
198 _os_log_to_log_internal(oslog
, type
, format
, args
, addr
, dso
);
203 _os_log_to_msgbuf_internal(const char *format
, va_list args
, bool safe
, bool logging
)
205 static int msgbufreplay
= -1;
208 #if DEVELOPMENT || DEBUG
217 if (-1 == msgbufreplay
) msgbufreplay
= msgbufp
->msg_bufx
;
218 } else if (logging
&& (-1 != msgbufreplay
)) {
220 uint32_t localbuff_size
;
222 char *localbuff
, *p
, *s
, *next
, ch
;
224 position
= msgbufreplay
;
226 localbuff_size
= (msgbufp
->msg_size
+ 2); /* + '\n' + '\0' */
227 /* Size for non-blocking */
228 if (localbuff_size
> 4096) localbuff_size
= 4096;
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 */
235 * The message buffer is circular; start at the replay pointer, and
236 * make one loop up to write pointer - 1.
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
;
243 if (ch
== '\0') continue;
246 if (i
>= (localbuff_size
- 2)) break;
250 if (!newl
) localbuff
[i
++] = '\n';
254 while ((next
= strchr(s
, '\n'))) {
258 os_log(&_os_log_replay
, "%s", s
);
262 kfree(localbuff
, localbuff_size
);
267 va_copy(args_copy
, args
);
268 vprintf_log_locked(format
, args_copy
);
271 #if DEVELOPMENT || DEBUG
278 if (safe
) logwakeup(msgbufp
);
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
)
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
];
296 #if FIREHOSE_USES_SHARED_CACHE
297 dso
= (void *) segLOWESTTEXT
;
298 #else /* FIREHOSE_USES_SHARED_CACHE */
300 dso
= (void *) OSKextKextForAddress(format
);
306 if (!_os_trace_addr_in_text_segment(dso
, format
)) {
310 void *dso_addr
= (void *) OSKextKextForAddress(addr
);
311 if (dso
!= dso_addr
) {
314 #endif /* FIREHOSE_USES_SHARED_CACHE */
316 memset(&context
, 0, sizeof(context
));
317 memset(buffer
, 0, OS_LOG_BUFFER_MAX_SIZE
);
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
);
325 va_copy(args_copy
, args
);
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
);
332 (void)hw_atomic_add(&oslog_p_error_count
, 1);
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
)
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
},
346 return sizeof(uint32_t);
348 #else /* FIREHOSE_USES_SHARED_CACHE */
349 kernel_mach_header_t
*mh
= dso
;
351 if (mh
->filetype
== MH_EXECUTE
) {
352 *flags
= _firehose_tracepoint_flags_pc_style_main_exe
;
354 memcpy(buf
, (uint32_t[]){ (uintptr_t)address
- (uintptr_t)dso
},
356 return sizeof(uint32_t);
358 *flags
= _firehose_tracepoint_flags_pc_style_absolute
;
359 memcpy(buf
, (uintptr_t[]){ VM_KERNEL_UNSLIDE(address
) }, sizeof(uintptr_t));
361 return 6; // 48 bits are enough
363 return sizeof(uintptr_t);
366 #endif /* !FIREHOSE_USES_SHARED_CACHE */
372 _os_log_buffer_pack(uint8_t *buffdata
, size_t buffdata_sz
,
373 os_log_buffer_context_t ctx
)
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
;
379 if (total_sz
> buffdata_sz
) {
383 memcpy(buffdata
, buffer
, buffer_sz
);
384 memcpy(&buffdata
[buffer_sz
], ctx
->pubdata
, ctx
->pubdata_sz
);
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
)
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
;
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) {
407 buffdata_sz
+= addr_len
;
409 timestamp
= firehose_tracepoint_time(firehose_activity_flags_default
);
410 thread_id
= thread_tid(current_thread());
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
));
417 firehose_debug_trace(stream
, trace_id
.ftid_value
, timestamp
,
418 format
, buffdata
, buffdata_sz
);
420 if (type
== OS_LOG_TYPE_INFO
|| type
== OS_LOG_TYPE_DEBUG
) {
421 stream
= firehose_stream_memory
;
424 stream
= firehose_stream_persist
;
426 _firehose_trace(stream
, trace_id
, timestamp
, buffdata
, buffdata_sz
);
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
)
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
);
437 firehose_tracepoint_t ft
;
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);
445 if (oslog_stream_open
&& (stream
!= firehose_stream_metadata
)) {
447 lck_spin_lock(&oslog_stream_lock
);
448 if (!oslog_stream_open
) {
449 lck_spin_unlock(&oslog_stream_lock
);
453 oslog_s_total_msgcount
++;
454 oslog_streamwrite_locked(ftid
, stamp
, pubdata
, publen
);
455 lck_spin_unlock(&oslog_stream_lock
);
456 oslog_streamwakeup();
460 ft
= __firehose_buffer_tracepoint_reserve(stamp
, stream
, (uint16_t)publen
, 0, NULL
);
462 if (oslog_boot_done
) {
463 if (stream
== firehose_stream_metadata
) {
464 (void)hw_atomic_add(&oslog_p_metadata_dropped_msgcount
, 1);
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);
473 firehose_chunk_t fbc
= firehose_boot_chunk
;
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
);
480 (void)hw_atomic_add(&oslog_p_boot_dropped_msgcount
, 1);
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
;
491 if (!oslog_boot_done
) {
492 oslog_boot_done
= true;
494 memcpy(ft
->ft_data
, pubdata
, publen
);
496 __firehose_buffer_tracepoint_flush(ft
, ftid
);
497 if (stream
== firehose_stream_metadata
) {
498 (void)hw_atomic_add(&oslog_p_metadata_saved_msgcount
, 1);
501 (void)hw_atomic_add(&oslog_p_saved_msgcount
, 1);
503 return ftid
.ftid_value
;
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
)
510 oslog_stream_buf_entry_t m_entry
= NULL
;
511 firehose_tracepoint_t ft
= NULL
;
512 size_t m_entry_len
= 0;
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
);
525 m_entry
->type
= type
;
526 m_entry
->timestamp
= stamp
;
527 m_entry
->size
= sizeof(struct firehose_tracepoint_s
) + publen
;
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
);
540 firehose_trace_metadata(firehose_stream_t stream
, firehose_tracepoint_id_u ftid
,
541 uint64_t stamp
, const void *pubdata
, size_t publen
)
543 oslog_stream_buf_entry_t m_entry
= NULL
;
545 // If streaming mode is not on, only log the metadata
546 // in the persistence buffer
548 lck_spin_lock(&oslog_stream_lock
);
549 if (!oslog_stream_open
) {
550 lck_spin_unlock(&oslog_stream_lock
);
553 lck_spin_unlock(&oslog_stream_lock
);
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
);
559 (void)hw_atomic_add(&oslog_s_error_count
, 1);
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
);
570 oslog_s_metadata_msgcount
++;
571 oslog_streamwrite_metadata_locked(m_entry
);
572 lck_spin_unlock(&oslog_stream_lock
);
575 _firehose_trace(stream
, ftid
, stamp
, pubdata
, publen
);
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
)
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
);
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",
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
605 __firehose_buffer_push_to_logd(firehose_buffer_t fb __unused
, bool for_io __unused
) {
611 __firehose_allocate(vm_offset_t
*addr
, vm_size_t size __unused
)
613 firehose_chunk_t kernel_buffer
= (firehose_chunk_t
)kernel_firehose_addr
;
615 if (kernel_firehose_addr
) {
616 *addr
= kernel_firehose_addr
;
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
);
628 // There isnt a lock held in this case.
630 __firehose_critical_region_enter(void) {
631 disable_preemption();
636 __firehose_critical_region_leave(void) {
641 #ifdef CONFIG_XNUPOST
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 "#")
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
);
659 kern_return_t
test_os_log(void);
660 kern_return_t
test_os_log_parallel(void);
662 #define GENOSLOGHELPER(fname, ident, callout_f) \
663 void fname(uint32_t uniqid, uint64_t count) \
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++) \
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);*/ \
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
);
684 kern_return_t
test_os_log()
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;
694 uint64_t a
= mach_absolute_time();
696 uint64_t total_seqno
= 2;
698 os_log_t log_handle
= os_log_create("com.apple.xnu.test.t1", "kpost");
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");
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
);
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");
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
);
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
);
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");
727 uint32_t logging_config
= atm_get_diagnostic_config();
728 T_LOG("checking atm_diagnostic_config 0x%X", logging_config
);
730 if ((logging_config
& ATM_TRACE_OFF
) || (logging_config
& ATM_TRACE_DISABLE
))
732 T_LOG("ATM_TRACE_OFF / ATM_TRACE_DISABLE is set. Would not see oslog messages. skipping the rest of test.");
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");
739 a
= mach_absolute_time();
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");
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");
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");
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");
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");
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");
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");
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
);
780 static uint32_t _test_log_loop_count
= 0;
781 void _test_log_loop(void * arg __unused
, wait_result_t wres __unused
)
783 uint32_t uniqid
= RandomULong();
784 test_oslog_debug_helper(uniqid
, 100);
785 (void)hw_atomic_add(&_test_log_loop_count
, 100);
788 kern_return_t
test_os_log_parallel(void)
792 uint32_t uniqid
= RandomULong();
794 printf("oslog internal counters total %u , saved %u, dropped %u", oslog_p_total_msgcount
, oslog_p_saved_msgcount
,
795 oslog_p_dropped_msgcount
);
797 kr
= kernel_thread_start(_test_log_loop
, NULL
, &thread
[0]);
798 T_ASSERT_EQ_INT(kr
, KERN_SUCCESS
, "kernel_thread_start returned successfully");
800 kr
= kernel_thread_start(_test_log_loop
, NULL
, &thread
[1]);
801 T_ASSERT_EQ_INT(kr
, KERN_SUCCESS
, "kernel_thread_start returned successfully");
803 test_oslog_info_helper(uniqid
, 100);
805 /* wait until other thread has also finished */
806 while (_test_log_loop_count
< 200)
811 thread_deallocate(thread
[0]);
812 thread_deallocate(thread
[1]);
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");
821 void test_oslog_handleOSLogCtl(int32_t * in
, int32_t * out
, int32_t len
)
823 if (!in
|| !out
|| len
!= 4)
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
;
837 /* mini stress run */
838 out
[0] = test_os_log_parallel();
844 out
[1] = RandomULong();
845 out
[0] = test_stresslog_dropmsg(out
[1]);
850 /* invoke log helpers */
851 uint32_t uniqid
= in
[3];
852 int32_t msgcount
= in
[2];
853 if (uniqid
== 0 || msgcount
== 0)
855 out
[0] = KERN_INVALID_VALUE
;
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;
867 out
[0] = KERN_SUCCESS
;
873 out
[0] = KERN_INVALID_VALUE
;
880 kern_return_t
test_stresslog_dropmsg(uint32_t uniqid
)
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)
890 test_oslog_debug_helper(uniqid
, 100);
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
);