1 /* * Copyright (c) 2019 Apple Inc. All rights reserved. */
6 #include <kern/cpu_data.h>
13 #include <vm/vm_kern.h>
14 #include <mach/vm_statistics.h>
15 #include <kern/debug.h>
16 #include <libkern/libkern.h>
17 #include <libkern/kernel_mach_header.h>
18 #include <pexpert/pexpert.h>
19 #include <uuid/uuid.h>
20 #include <sys/msgbuf.h>
22 #include <mach/mach_time.h>
23 #include <kern/thread.h>
24 #include <kern/simple_lock.h>
25 #include <kern/kalloc.h>
26 #include <kern/clock.h>
27 #include <kern/assert.h>
28 #include <kern/task.h>
30 #include <firehose/tracepoint_private.h>
31 #include <firehose/chunk_private.h>
32 #include <os/firehose_buffer_private.h>
33 #include <os/firehose.h>
35 #include <os/log_private.h>
36 #include "trace_internal.h"
38 #include "log_encode.h"
40 /* on embedded, with no kext loading or unloads,
41 * make the kernel use the libtrace shared cache path for logging
43 #define FIREHOSE_USES_SHARED_CACHE NO_KEXTD
45 #if FIREHOSE_USES_SHARED_CACHE
46 extern vm_offset_t segLOWESTTEXT
;
53 struct os_log_s _os_log_default
;
54 struct os_log_s _os_log_replay
;
55 extern vm_offset_t kernel_firehose_addr
;
56 extern firehose_chunk_t firehose_boot_chunk
;
58 extern void bsd_log_lock(void);
59 extern void bsd_log_unlock(void);
60 extern void logwakeup(struct msgbuf
*);
62 decl_lck_spin_data(extern, oslog_stream_lock
);
63 #define stream_lock() lck_spin_lock(&oslog_stream_lock)
64 #define stream_unlock() lck_spin_unlock(&oslog_stream_lock)
66 extern void oslog_streamwakeup(void);
67 void oslog_streamwrite_locked(firehose_tracepoint_id_u ftid
,
68 uint64_t stamp
, const void *pubdata
, size_t publen
);
69 extern void oslog_streamwrite_metadata_locked(oslog_stream_buf_entry_t m_entry
);
71 extern int oslog_stream_open
;
73 extern void *OSKextKextForAddress(const void *);
75 /* Counters for persistence mode */
76 uint32_t oslog_p_total_msgcount
= 0;
77 uint32_t oslog_p_metadata_saved_msgcount
= 0;
78 uint32_t oslog_p_metadata_dropped_msgcount
= 0;
79 uint32_t oslog_p_error_count
= 0;
80 uint32_t oslog_p_saved_msgcount
= 0;
81 uint32_t oslog_p_dropped_msgcount
= 0;
82 uint32_t oslog_p_boot_dropped_msgcount
= 0;
84 /* Counters for streaming mode */
85 uint32_t oslog_s_total_msgcount
= 0;
86 uint32_t oslog_s_error_count
= 0;
87 uint32_t oslog_s_metadata_msgcount
= 0;
89 static bool oslog_boot_done
= false;
90 extern boolean_t early_boot_complete
;
92 #ifdef XNU_KERNEL_PRIVATE
93 bool startup_serial_logging_active
= true;
94 uint64_t startup_serial_num_procs
= 300;
95 #endif /* XNU_KERNEL_PRIVATE */
98 firehose_tracepoint_id_t
99 firehose_debug_trace(firehose_stream_t stream
, firehose_tracepoint_id_t trace_id
,
100 uint64_t timestamp
, const char *format
, const void *pubdata
, size_t publen
);
102 static inline firehose_tracepoint_id_t
103 _firehose_trace(firehose_stream_t stream
, firehose_tracepoint_id_u ftid
,
104 uint64_t stamp
, const void *pubdata
, size_t publen
);
106 static oslog_stream_buf_entry_t
107 oslog_stream_create_buf_entry(oslog_stream_link_type_t type
, firehose_tracepoint_id_u ftid
,
108 uint64_t stamp
, const void* pubdata
, size_t publen
);
111 _os_log_with_args_internal(os_log_t oslog __unused
, os_log_type_t type __unused
,
112 const char *format
, va_list args
, void *addr
, void *dso
, bool driverKit
, bool addcr
);
115 _os_log_to_msgbuf_internal(const char *format
, va_list args
, bool safe
, bool logging
, bool addcr
);
118 _os_log_to_log_internal(os_log_t oslog
, os_log_type_t type
,
119 const char *format
, va_list args
, void *addr
, void *dso
, bool driverKit
);
123 _os_log_actual(os_log_t oslog
, os_log_type_t type
, const char *format
, void
124 *dso
, void *addr
, os_log_buffer_context_t context
, bool driverKit
);
127 os_log_info_enabled(os_log_t log __unused
)
133 os_log_debug_enabled(os_log_t log __unused
)
139 os_log_create(const char *subsystem __unused
, const char *category __unused
)
141 return &_os_log_default
;
145 _os_log_string_is_public(const char *str __unused
)
150 __attribute__((noinline
, not_tail_called
)) void
151 _os_log_internal(void *dso
, os_log_t log
, uint8_t type
, const char *message
, ...)
154 void *addr
= __builtin_return_address(0);
156 va_start(args
, message
);
158 _os_log_with_args_internal(log
, type
, message
, args
, addr
, dso
, FALSE
, FALSE
);
165 __attribute__((noinline
, not_tail_called
)) int
166 _os_log_internal_driverKit(void *dso
, os_log_t log
, uint8_t type
, const char *message
, ...)
169 void *addr
= __builtin_return_address(0);
170 bool driverKitLog
= FALSE
;
173 * We want to be able to identify dexts from the logs.
175 * Usually the addr is used to understand if the log line
176 * was generated by a kext or the kernel main executable.
177 * Logd uses copyKextUUIDForAddress with the addr specified
178 * in the log line to retrieve the kext UUID of the sender.
180 * Dext however are not loaded in kernel space so they do not
181 * have a kernel range of addresses.
183 * To make the same mechanism work, OSKext fakes a kernel
184 * address range for dexts using the loadTag,
185 * so we just need to use the loadTag as addr here
186 * to allow logd to retrieve the correct UUID.
188 * NOTE: loadTag is populated in the task when the dext is matching,
189 * so if log lines are generated before the matching they will be
190 * identified as kernel main executable.
192 task_t self_task
= current_task();
195 * Only dextis are supposed to use this log path.
197 if (!task_is_driver(self_task
)) {
201 uint64_t loadTag
= get_task_loadTag(self_task
);
204 addr
= (void*) loadTag
;
206 va_start(args
, message
);
208 _os_log_with_args_internal(log
, type
, message
, args
, addr
, dso
, driverKitLog
, true);
215 #pragma mark - shim functions
217 __attribute__((noinline
, not_tail_called
)) void
218 os_log_with_args(os_log_t oslog
, os_log_type_t type
, const char *format
, va_list args
, void *addr
)
220 // if no address passed, look it up
222 addr
= __builtin_return_address(0);
225 _os_log_with_args_internal(oslog
, type
, format
, args
, addr
, NULL
, FALSE
, FALSE
);
229 _os_log_with_args_internal(os_log_t oslog
, os_log_type_t type
,
230 const char *format
, va_list args
, void *addr
, void *dso
, bool driverKit
, bool addcr
)
232 uint32_t logging_config
= atm_get_diagnostic_config();
236 if (format
[0] == '\0') {
240 /* early boot can log to dmesg for later replay (27307943) */
241 safe
= (!early_boot_complete
|| oslog_is_safe());
243 if (logging_config
& ATM_TRACE_DISABLE
|| logging_config
& ATM_TRACE_OFF
) {
249 if (oslog
!= &_os_log_replay
) {
250 _os_log_to_msgbuf_internal(format
, args
, safe
, logging
, addcr
);
253 if (safe
&& logging
) {
254 _os_log_to_log_internal(oslog
, type
, format
, args
, addr
, dso
, driverKit
);
259 _os_log_to_msgbuf_internal(const char *format
, va_list args
, bool safe
, bool logging
, bool addcr
)
261 static int msgbufreplay
= -1;
264 #if DEVELOPMENT || DEBUG
273 if (-1 == msgbufreplay
) {
274 msgbufreplay
= msgbufp
->msg_bufx
;
276 } else if (logging
&& (-1 != msgbufreplay
)) {
278 uint32_t localbuff_size
;
280 char *localbuff
, *p
, *s
, *next
, ch
;
282 position
= msgbufreplay
;
284 localbuff_size
= (msgbufp
->msg_size
+ 2); /* + '\n' + '\0' */
285 /* Size for non-blocking */
286 if (localbuff_size
> 4096) {
287 localbuff_size
= 4096;
290 /* Allocate a temporary non-circular buffer */
291 if ((localbuff
= (char *)kalloc_noblock(localbuff_size
))) {
292 /* in between here, the log could become bigger, but that's fine */
295 * The message buffer is circular; start at the replay pointer, and
296 * make one loop up to write pointer - 1.
298 p
= msgbufp
->msg_bufc
+ position
;
299 for (i
= newl
= 0; p
!= msgbufp
->msg_bufc
+ msgbufp
->msg_bufx
- 1; ++p
) {
300 if (p
>= msgbufp
->msg_bufc
+ msgbufp
->msg_size
) {
301 p
= msgbufp
->msg_bufc
;
309 if (i
>= (localbuff_size
- 2)) {
316 localbuff
[i
++] = '\n';
321 while ((next
= strchr(s
, '\n'))) {
325 os_log(&_os_log_replay
, "%s", s
);
329 kfree(localbuff
, localbuff_size
);
334 va_copy(args_copy
, args
);
335 vprintf_log_locked(format
, args_copy
, addcr
);
338 #if DEVELOPMENT || DEBUG
352 _os_log_to_log_internal(os_log_t oslog
, os_log_type_t type
,
353 const char *format
, va_list args
, void *addr
, void *dso
, bool driverKit
)
355 struct os_log_buffer_context_s context
;
356 unsigned char buffer_data
[OS_LOG_BUFFER_MAX_SIZE
] __attribute__((aligned(8)));
357 os_log_buffer_t buffer
= (os_log_buffer_t
)buffer_data
;
358 uint8_t pubdata
[OS_LOG_BUFFER_MAX_SIZE
];
365 #if FIREHOSE_USES_SHARED_CACHE
366 dso
= (void *) segLOWESTTEXT
;
367 #else /* FIREHOSE_USES_SHARED_CACHE */
369 dso
= (void *) OSKextKextForAddress(format
);
375 if (!_os_trace_addr_in_text_segment(dso
, format
)) {
379 void *dso_addr
= (void *) OSKextKextForAddress(addr
);
380 if (dso
!= dso_addr
) {
384 #endif /* FIREHOSE_USES_SHARED_CACHE */
386 memset(&context
, 0, sizeof(context
));
387 memset(buffer
, 0, OS_LOG_BUFFER_MAX_SIZE
);
389 context
.shimmed
= true;
390 context
.buffer
= buffer
;
391 context
.content_sz
= OS_LOG_BUFFER_MAX_SIZE
- sizeof(*buffer
);
392 context
.pubdata
= pubdata
;
393 context
.pubdata_sz
= sizeof(pubdata
);
395 va_copy(args_copy
, args
);
397 os_atomic_inc(&oslog_p_total_msgcount
, relaxed
);
398 if (_os_log_encode(format
, args_copy
, 0, &context
)) {
399 _os_log_actual(oslog
, type
, format
, dso
, addr
, &context
, driverKit
);
401 os_atomic_inc(&oslog_p_error_count
, relaxed
);
408 _os_trace_write_location_for_address(uint8_t buf
[static sizeof(uint64_t)],
409 void *dso
, const void *address
, firehose_tracepoint_flags_t
*flags
, __unused
bool driverKit
)
411 uintptr_t shift_addr
= (uintptr_t)address
- (uintptr_t)dso
;
412 #if FIREHOSE_USES_SHARED_CACHE
414 *flags
= _firehose_tracepoint_flags_pc_style_shared_cache
;
415 memcpy(buf
, (uint32_t[]){ shift_addr
},
417 return sizeof(uint32_t);
419 #else /* FIREHOSE_USES_SHARED_CACHE */
420 kernel_mach_header_t
*mh
= dso
;
423 * driverKit will have the dso set as MH_EXECUTE
424 * (it is logging from a syscall in the kernel)
425 * but needs logd to parse the address as an
428 if (mh
->filetype
== MH_EXECUTE
&& !driverKit
) {
429 *flags
= _firehose_tracepoint_flags_pc_style_main_exe
;
430 memcpy(buf
, (uint32_t[]){ shift_addr
}, sizeof(uint32_t));
431 return sizeof(uint32_t);
433 *flags
= _firehose_tracepoint_flags_pc_style_absolute
;
435 shift_addr
= VM_KERNEL_UNSLIDE(address
);
437 shift_addr
= (uintptr_t) address
;
439 memcpy(buf
, (uintptr_t[]){ shift_addr
}, sizeof(uintptr_t));
441 return 6; // 48 bits are enough
443 return sizeof(uintptr_t);
446 #endif /* !FIREHOSE_USES_SHARED_CACHE */
452 _os_log_buffer_pack(uint8_t *buffdata
, size_t buffdata_sz
,
453 os_log_buffer_context_t ctx
)
455 os_log_buffer_t buffer
= ctx
->buffer
;
456 size_t buffer_sz
= sizeof(*ctx
->buffer
) + ctx
->content_sz
;
457 size_t total_sz
= buffer_sz
+ ctx
->pubdata_sz
;
459 if (total_sz
> buffdata_sz
) {
463 memcpy(buffdata
, buffer
, buffer_sz
);
464 memcpy(&buffdata
[buffer_sz
], ctx
->pubdata
, ctx
->pubdata_sz
);
469 _os_log_actual(os_log_t oslog __unused
, os_log_type_t type
, const char *format
,
470 void *dso
, void *addr
, os_log_buffer_context_t context
, bool driverKit
)
472 firehose_stream_t stream
;
473 firehose_tracepoint_flags_t flags
= 0;
474 firehose_tracepoint_id_u trace_id
;
475 uint8_t buffdata
[OS_LOG_BUFFER_MAX_SIZE
];
476 size_t addr_len
= 0, buffdata_sz
;
480 // dso == the start of the binary that was loaded
481 addr_len
= _os_trace_write_location_for_address(buffdata
, dso
, addr
, &flags
, driverKit
);
482 buffdata_sz
= _os_log_buffer_pack(buffdata
+ addr_len
,
483 sizeof(buffdata
) - addr_len
, context
);
484 if (buffdata_sz
== 0) {
487 buffdata_sz
+= addr_len
;
489 timestamp
= firehose_tracepoint_time(firehose_activity_flags_default
);
490 thread_id
= thread_tid(current_thread());
493 // set FIREHOSE_TRACEPOINT_PC_DYNAMIC_BIT so logd will not try to find the format string in
494 // the executable text
495 trace_id
.ftid_value
= FIREHOSE_TRACE_ID_MAKE(firehose_tracepoint_namespace_log
,
496 type
, flags
, (uintptr_t) addr
| FIREHOSE_TRACEPOINT_PC_DYNAMIC_BIT
);
498 // create trace_id after we've set additional flags
499 trace_id
.ftid_value
= FIREHOSE_TRACE_ID_MAKE(firehose_tracepoint_namespace_log
,
500 type
, flags
, _os_trace_offset(dso
, format
, (_firehose_tracepoint_flags_activity_t
)flags
));
504 firehose_debug_trace(stream
, trace_id
.ftid_value
, timestamp
,
505 format
, buffdata
, buffdata_sz
);
507 if (type
== OS_LOG_TYPE_INFO
|| type
== OS_LOG_TYPE_DEBUG
) {
508 stream
= firehose_stream_memory
;
510 stream
= firehose_stream_persist
;
512 _firehose_trace(stream
, trace_id
, timestamp
, buffdata
, buffdata_sz
);
515 static inline firehose_tracepoint_id_t
516 _firehose_trace(firehose_stream_t stream
, firehose_tracepoint_id_u ftid
,
517 uint64_t stamp
, const void *pubdata
, size_t publen
)
519 const uint16_t ft_size
= offsetof(struct firehose_tracepoint_s
, ft_data
);
520 const size_t _firehose_chunk_payload_size
=
521 sizeof(((struct firehose_chunk_s
*)0)->fc_data
);
523 firehose_tracepoint_t ft
;
525 if (slowpath(ft_size
+ publen
> _firehose_chunk_payload_size
)) {
526 // We'll need to have some handling here. For now - return 0
527 os_atomic_inc(&oslog_p_error_count
, relaxed
);
531 if (oslog_stream_open
&& (stream
!= firehose_stream_metadata
)) {
533 if (!oslog_stream_open
) {
538 oslog_s_total_msgcount
++;
539 oslog_streamwrite_locked(ftid
, stamp
, pubdata
, publen
);
541 oslog_streamwakeup();
545 ft
= __firehose_buffer_tracepoint_reserve(stamp
, stream
, (uint16_t)publen
, 0, NULL
);
547 if (oslog_boot_done
) {
548 if (stream
== firehose_stream_metadata
) {
549 os_atomic_inc(&oslog_p_metadata_dropped_msgcount
, relaxed
);
551 // If we run out of space in the persistence buffer we're
552 // dropping the message.
553 os_atomic_inc(&oslog_p_dropped_msgcount
, relaxed
);
557 firehose_chunk_t fbc
= firehose_boot_chunk
;
560 //only stream available during boot is persist
561 offset
= firehose_chunk_tracepoint_try_reserve(fbc
, stamp
,
562 firehose_stream_persist
, 0, publen
, 0, NULL
);
564 os_atomic_inc(&oslog_p_boot_dropped_msgcount
, relaxed
);
568 ft
= firehose_chunk_tracepoint_begin(fbc
, stamp
, publen
,
569 thread_tid(current_thread()), offset
);
570 memcpy(ft
->ft_data
, pubdata
, publen
);
571 firehose_chunk_tracepoint_end(fbc
, ft
, ftid
);
572 os_atomic_inc(&oslog_p_saved_msgcount
, relaxed
);
573 return ftid
.ftid_value
;
575 if (!oslog_boot_done
) {
576 oslog_boot_done
= true;
578 memcpy(ft
->ft_data
, pubdata
, publen
);
580 __firehose_buffer_tracepoint_flush(ft
, ftid
);
581 if (stream
== firehose_stream_metadata
) {
582 os_atomic_inc(&oslog_p_metadata_saved_msgcount
, relaxed
);
584 os_atomic_inc(&oslog_p_saved_msgcount
, relaxed
);
586 return ftid
.ftid_value
;
589 static oslog_stream_buf_entry_t
590 oslog_stream_create_buf_entry(oslog_stream_link_type_t type
, firehose_tracepoint_id_u ftid
,
591 uint64_t stamp
, const void* pubdata
, size_t publen
)
593 oslog_stream_buf_entry_t m_entry
= NULL
;
594 firehose_tracepoint_t ft
= NULL
;
595 size_t m_entry_len
= 0;
601 m_entry_len
= sizeof(struct oslog_stream_buf_entry_s
) +
602 sizeof(struct firehose_tracepoint_s
) + publen
;
603 m_entry
= (oslog_stream_buf_entry_t
) kalloc(m_entry_len
);
608 m_entry
->type
= type
;
609 m_entry
->timestamp
= stamp
;
610 m_entry
->size
= sizeof(struct firehose_tracepoint_s
) + publen
;
612 ft
= m_entry
->metadata
;
613 ft
->ft_thread
= thread_tid(current_thread());
614 ft
->ft_id
.ftid_value
= ftid
.ftid_value
;
615 ft
->ft_length
= publen
;
616 memcpy(ft
->ft_data
, pubdata
, publen
);
623 firehose_trace_metadata(firehose_stream_t stream
, firehose_tracepoint_id_u ftid
,
624 uint64_t stamp
, const void *pubdata
, size_t publen
)
626 oslog_stream_buf_entry_t m_entry
= NULL
;
628 // If streaming mode is not on, only log the metadata
629 // in the persistence buffer
632 if (!oslog_stream_open
) {
638 // Setup and write the stream metadata entry
639 m_entry
= oslog_stream_create_buf_entry(oslog_stream_link_type_metadata
, ftid
,
640 stamp
, pubdata
, publen
);
642 os_atomic_inc(&oslog_s_error_count
, relaxed
);
647 if (!oslog_stream_open
) {
649 kfree(m_entry
, sizeof(struct oslog_stream_buf_entry_s
) +
650 sizeof(struct firehose_tracepoint_s
) + publen
);
653 oslog_s_metadata_msgcount
++;
654 oslog_streamwrite_metadata_locked(m_entry
);
658 _firehose_trace(stream
, ftid
, stamp
, pubdata
, publen
);
662 firehose_tracepoint_id_t
663 firehose_debug_trace(firehose_stream_t stream
, firehose_tracepoint_id_t trace_id
,
664 uint64_t timestamp
, const char *format
, const void *pubdata
, size_t publen
)
666 kprintf("[os_log stream 0x%x trace_id 0x%llx timestamp %llu format '%s' data %p len %lu]\n",
667 (unsigned int)stream
, (unsigned long long)trace_id
, timestamp
,
668 format
, pubdata
, publen
);
670 const unsigned char *cdata
= (const unsigned char *)pubdata
;
671 for (i
= 0; i
< publen
; i
+= 8) {
672 kprintf(">oslog 0x%08x: 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x\n",
674 (i
+ 0) < publen
? cdata
[i
+ 0] : 0,
675 (i
+ 1) < publen
? cdata
[i
+ 1] : 0,
676 (i
+ 2) < publen
? cdata
[i
+ 2] : 0,
677 (i
+ 3) < publen
? cdata
[i
+ 3] : 0,
678 (i
+ 4) < publen
? cdata
[i
+ 4] : 0,
679 (i
+ 5) < publen
? cdata
[i
+ 5] : 0,
680 (i
+ 6) < publen
? cdata
[i
+ 6] : 0,
681 (i
+ 7) < publen
? cdata
[i
+ 7] : 0
688 __firehose_buffer_push_to_logd(firehose_buffer_t fb __unused
, bool for_io __unused
)
695 __firehose_allocate(vm_offset_t
*addr
, vm_size_t size __unused
)
697 firehose_chunk_t kernel_buffer
= (firehose_chunk_t
)kernel_firehose_addr
;
699 if (kernel_firehose_addr
) {
700 *addr
= kernel_firehose_addr
;
705 // Now that we are done adding logs to this chunk, set the number of writers to 0
706 // Without this, logd won't flush when the page is full
707 firehose_boot_chunk
->fc_pos
.fcp_refcnt
= 0;
708 memcpy(&kernel_buffer
[FIREHOSE_BUFFER_KERNEL_CHUNK_COUNT
- 1], (const void *)firehose_boot_chunk
, FIREHOSE_CHUNK_SIZE
);
711 // There isnt a lock held in this case.
713 __firehose_critical_region_enter(void)
715 disable_preemption();
720 __firehose_critical_region_leave(void)
726 #ifdef CONFIG_XNUPOST
728 #include <tests/xnupost.h>
729 #define TESTOSLOGFMT(fn_name) "%u^%llu/%llu^kernel^0^test^" fn_name
730 #define TESTOSLOGPFX "TESTLOG:%u#"
731 #define TESTOSLOG(fn_name) TESTOSLOGPFX TESTOSLOGFMT(fn_name "#")
733 extern u_int32_t
RandomULong(void);
734 extern uint32_t find_pattern_in_buffer(char * pattern
, uint32_t len
, int expected_count
);
735 void test_oslog_default_helper(uint32_t uniqid
, uint64_t count
);
736 void test_oslog_info_helper(uint32_t uniqid
, uint64_t count
);
737 void test_oslog_debug_helper(uint32_t uniqid
, uint64_t count
);
738 void test_oslog_error_helper(uint32_t uniqid
, uint64_t count
);
739 void test_oslog_fault_helper(uint32_t uniqid
, uint64_t count
);
740 void _test_log_loop(void * arg __unused
, wait_result_t wres __unused
);
741 void test_oslog_handleOSLogCtl(int32_t * in
, int32_t * out
, int32_t len
);
742 kern_return_t
test_stresslog_dropmsg(uint32_t uniqid
);
744 kern_return_t
test_os_log(void);
745 kern_return_t
test_os_log_parallel(void);
747 #define GENOSLOGHELPER(fname, ident, callout_f) \
748 void fname(uint32_t uniqid, uint64_t count) \
750 int32_t datalen = 0; \
751 uint32_t checksum = 0; \
752 char databuffer[256]; \
753 T_LOG("Doing os_log of %llu TESTLOG msgs for fn " ident, count); \
754 for (uint64_t i = 0; i < count; i++) \
756 datalen = scnprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT(ident), uniqid, i + 1, count); \
757 checksum = crc32(0, databuffer, datalen); \
758 callout_f(OS_LOG_DEFAULT, TESTOSLOG(ident), checksum, uniqid, i + 1, count); \
759 /*T_LOG(TESTOSLOG(ident), checksum, uniqid, i + 1, count);*/ \
763 GENOSLOGHELPER(test_oslog_info_helper
, "oslog_info_helper", os_log_info
);
764 GENOSLOGHELPER(test_oslog_fault_helper
, "oslog_fault_helper", os_log_fault
);
765 GENOSLOGHELPER(test_oslog_debug_helper
, "oslog_debug_helper", os_log_debug
);
766 GENOSLOGHELPER(test_oslog_error_helper
, "oslog_error_helper", os_log_error
);
767 GENOSLOGHELPER(test_oslog_default_helper
, "oslog_default_helper", os_log
);
772 char databuffer
[256];
773 uint32_t uniqid
= RandomULong();
774 uint32_t match_count
= 0;
775 uint32_t checksum
= 0;
776 uint32_t total_msg
= 0;
777 uint32_t saved_msg
= 0;
778 uint32_t dropped_msg
= 0;
780 uint64_t a
= mach_absolute_time();
782 uint64_t total_seqno
= 2;
784 os_log_t log_handle
= os_log_create("com.apple.xnu.test.t1", "kpost");
786 T_ASSERT_EQ_PTR(&_os_log_default
, log_handle
, "os_log_create returns valid value.");
787 T_ASSERT_EQ_INT(TRUE
, os_log_info_enabled(log_handle
), "os_log_info is enabled");
788 T_ASSERT_EQ_INT(TRUE
, os_log_debug_enabled(log_handle
), "os_log_debug is enabled");
789 T_ASSERT_EQ_PTR(&_os_log_default
, OS_LOG_DEFAULT
, "ensure OS_LOG_DEFAULT is _os_log_default");
791 total_msg
= oslog_p_total_msgcount
;
792 saved_msg
= oslog_p_saved_msgcount
;
793 dropped_msg
= oslog_p_dropped_msgcount
;
794 T_LOG("oslog internal counters total %u , saved %u, dropped %u", total_msg
, saved_msg
, dropped_msg
);
796 T_LOG("Validating with uniqid %u u64 %llu", uniqid
, a
);
797 T_ASSERT_NE_UINT(0, uniqid
, "random number should not be zero");
798 T_ASSERT_NE_ULLONG(0, a
, "absolute time should not be zero");
800 datalen
= scnprintf(databuffer
, sizeof(databuffer
), TESTOSLOGFMT("printf_only"), uniqid
, seqno
, total_seqno
);
801 checksum
= crc32(0, databuffer
, datalen
);
802 printf(TESTOSLOG("printf_only") "mat%llu\n", checksum
, uniqid
, seqno
, total_seqno
, a
);
805 datalen
= scnprintf(databuffer
, sizeof(databuffer
), TESTOSLOGFMT("printf_only"), uniqid
, seqno
, total_seqno
);
806 checksum
= crc32(0, databuffer
, datalen
);
807 printf(TESTOSLOG("printf_only") "mat%llu\n", checksum
, uniqid
, seqno
, total_seqno
, a
);
809 datalen
= scnprintf(databuffer
, sizeof(databuffer
), "kernel^0^test^printf_only#mat%llu", a
);
810 match_count
= find_pattern_in_buffer(databuffer
, datalen
, total_seqno
);
811 T_EXPECT_EQ_UINT(match_count
, 2, "verify printf_only goes to systemlog buffer");
813 uint32_t logging_config
= atm_get_diagnostic_config();
814 T_LOG("checking atm_diagnostic_config 0x%X", logging_config
);
816 if ((logging_config
& ATM_TRACE_OFF
) || (logging_config
& ATM_TRACE_DISABLE
)) {
817 T_LOG("ATM_TRACE_OFF / ATM_TRACE_DISABLE is set. Would not see oslog messages. skipping the rest of test.");
821 /* for enabled logging printfs should be saved in oslog as well */
822 T_EXPECT_GE_UINT((oslog_p_total_msgcount
- total_msg
), 2, "atleast 2 msgs should be seen by oslog system");
824 a
= mach_absolute_time();
827 total_msg
= oslog_p_total_msgcount
;
828 saved_msg
= oslog_p_saved_msgcount
;
829 dropped_msg
= oslog_p_dropped_msgcount
;
830 datalen
= scnprintf(databuffer
, sizeof(databuffer
), TESTOSLOGFMT("oslog_info"), uniqid
, seqno
, total_seqno
);
831 checksum
= crc32(0, databuffer
, datalen
);
832 os_log_info(log_handle
, TESTOSLOG("oslog_info") "mat%llu", checksum
, uniqid
, seqno
, total_seqno
, a
);
833 T_EXPECT_GE_UINT((oslog_p_total_msgcount
- total_msg
), 1, "total message count in buffer");
835 datalen
= scnprintf(databuffer
, sizeof(databuffer
), "kernel^0^test^oslog_info#mat%llu", a
);
836 match_count
= find_pattern_in_buffer(databuffer
, datalen
, total_seqno
);
837 T_EXPECT_EQ_UINT(match_count
, 1, "verify oslog_info does not go to systemlog buffer");
839 total_msg
= oslog_p_total_msgcount
;
840 test_oslog_info_helper(uniqid
, 10);
841 T_EXPECT_GE_UINT(oslog_p_total_msgcount
- total_msg
, 10, "test_oslog_info_helper: Should have seen 10 msgs");
843 total_msg
= oslog_p_total_msgcount
;
844 test_oslog_debug_helper(uniqid
, 10);
845 T_EXPECT_GE_UINT(oslog_p_total_msgcount
- total_msg
, 10, "test_oslog_debug_helper:Should have seen 10 msgs");
847 total_msg
= oslog_p_total_msgcount
;
848 test_oslog_error_helper(uniqid
, 10);
849 T_EXPECT_GE_UINT(oslog_p_total_msgcount
- total_msg
, 10, "test_oslog_error_helper:Should have seen 10 msgs");
851 total_msg
= oslog_p_total_msgcount
;
852 test_oslog_default_helper(uniqid
, 10);
853 T_EXPECT_GE_UINT(oslog_p_total_msgcount
- total_msg
, 10, "test_oslog_default_helper:Should have seen 10 msgs");
855 total_msg
= oslog_p_total_msgcount
;
856 test_oslog_fault_helper(uniqid
, 10);
857 T_EXPECT_GE_UINT(oslog_p_total_msgcount
- total_msg
, 10, "test_oslog_fault_helper:Should have seen 10 msgs");
859 T_LOG("oslog internal counters total %u , saved %u, dropped %u", oslog_p_total_msgcount
, oslog_p_saved_msgcount
,
860 oslog_p_dropped_msgcount
);
865 static uint32_t _test_log_loop_count
= 0;
867 _test_log_loop(void * arg __unused
, wait_result_t wres __unused
)
869 uint32_t uniqid
= RandomULong();
870 test_oslog_debug_helper(uniqid
, 100);
871 os_atomic_add(&_test_log_loop_count
, 100, relaxed
);
875 test_os_log_parallel(void)
879 uint32_t uniqid
= RandomULong();
881 printf("oslog internal counters total %u , saved %u, dropped %u", oslog_p_total_msgcount
, oslog_p_saved_msgcount
,
882 oslog_p_dropped_msgcount
);
884 kr
= kernel_thread_start(_test_log_loop
, NULL
, &thread
[0]);
885 T_ASSERT_EQ_INT(kr
, KERN_SUCCESS
, "kernel_thread_start returned successfully");
887 kr
= kernel_thread_start(_test_log_loop
, NULL
, &thread
[1]);
888 T_ASSERT_EQ_INT(kr
, KERN_SUCCESS
, "kernel_thread_start returned successfully");
890 test_oslog_info_helper(uniqid
, 100);
892 /* wait until other thread has also finished */
893 while (_test_log_loop_count
< 200) {
897 thread_deallocate(thread
[0]);
898 thread_deallocate(thread
[1]);
900 T_LOG("oslog internal counters total %u , saved %u, dropped %u", oslog_p_total_msgcount
, oslog_p_saved_msgcount
,
901 oslog_p_dropped_msgcount
);
902 T_PASS("parallel_logging tests is now complete");
908 test_oslog_handleOSLogCtl(int32_t * in
, int32_t * out
, int32_t len
)
910 if (!in
|| !out
|| len
!= 4) {
916 /* send out counters */
917 out
[1] = oslog_p_total_msgcount
;
918 out
[2] = oslog_p_saved_msgcount
;
919 out
[3] = oslog_p_dropped_msgcount
;
920 out
[0] = KERN_SUCCESS
;
925 /* mini stress run */
926 out
[0] = test_os_log_parallel();
932 out
[1] = RandomULong();
933 out
[0] = test_stresslog_dropmsg(out
[1]);
938 /* invoke log helpers */
939 uint32_t uniqid
= in
[3];
940 int32_t msgcount
= in
[2];
941 if (uniqid
== 0 || msgcount
== 0) {
942 out
[0] = KERN_INVALID_VALUE
;
947 case OS_LOG_TYPE_INFO
: test_oslog_info_helper(uniqid
, msgcount
); break;
948 case OS_LOG_TYPE_DEBUG
: test_oslog_debug_helper(uniqid
, msgcount
); break;
949 case OS_LOG_TYPE_ERROR
: test_oslog_error_helper(uniqid
, msgcount
); break;
950 case OS_LOG_TYPE_FAULT
: test_oslog_fault_helper(uniqid
, msgcount
); break;
951 case OS_LOG_TYPE_DEFAULT
:
952 default: test_oslog_default_helper(uniqid
, msgcount
); break;
954 out
[0] = KERN_SUCCESS
;
960 out
[0] = KERN_INVALID_VALUE
;
968 test_stresslog_dropmsg(uint32_t uniqid
)
970 uint32_t total
, saved
, dropped
;
971 total
= oslog_p_total_msgcount
;
972 saved
= oslog_p_saved_msgcount
;
973 dropped
= oslog_p_dropped_msgcount
;
974 uniqid
= RandomULong();
975 test_oslog_debug_helper(uniqid
, 100);
976 while ((oslog_p_dropped_msgcount
- dropped
) == 0) {
977 test_oslog_debug_helper(uniqid
, 100);
979 printf("test_stresslog_dropmsg: logged %u msgs, saved %u and caused a drop of %u msgs. \n", oslog_p_total_msgcount
- total
,
980 oslog_p_saved_msgcount
- saved
, oslog_p_dropped_msgcount
- dropped
);