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
43extern vm_offset_t segLOWESTTEXT;
44#endif
45
46struct os_log_s {
47 int a;
48};
49
50struct os_log_s _os_log_default;
51struct os_log_s _os_log_replay;
52extern vm_offset_t kernel_firehose_addr;
53extern firehose_chunk_t firehose_boot_chunk;
54
55extern void bsd_log_lock(void);
56extern void bsd_log_unlock(void);
57extern void logwakeup(struct msgbuf *);
58
59decl_lck_spin_data(extern, oslog_stream_lock)
60extern void oslog_streamwakeup(void);
61void oslog_streamwrite_locked(firehose_tracepoint_id_u ftid,
62 uint64_t stamp, const void *pubdata, size_t publen);
63extern void oslog_streamwrite_metadata_locked(oslog_stream_buf_entry_t m_entry);
64
65extern int oslog_stream_open;
66
67extern void *OSKextKextForAddress(const void *);
68
69/* Counters for persistence mode */
70uint32_t oslog_p_total_msgcount = 0;
71uint32_t oslog_p_metadata_saved_msgcount = 0;
72uint32_t oslog_p_metadata_dropped_msgcount = 0;
73uint32_t oslog_p_error_count = 0;
74uint32_t oslog_p_saved_msgcount = 0;
75uint32_t oslog_p_dropped_msgcount = 0;
76uint32_t oslog_p_boot_dropped_msgcount = 0;
77
78/* Counters for streaming mode */
79uint32_t oslog_s_total_msgcount = 0;
80uint32_t oslog_s_error_count = 0;
81uint32_t oslog_s_metadata_msgcount = 0;
82
83static bool oslog_boot_done = false;
84extern boolean_t early_boot_complete;
85
86#ifdef XNU_KERNEL_PRIVATE
87bool startup_serial_logging_active = true;
88uint64_t startup_serial_num_procs = 300;
89#endif /* XNU_KERNEL_PRIVATE */
90
91// XXX
92firehose_tracepoint_id_t
93firehose_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
96static 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
100static oslog_stream_buf_entry_t
101oslog_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
104static 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
108static void
109_os_log_to_msgbuf_internal(const char *format, va_list args, bool safe, bool logging);
110
111static 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
116static 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
120bool
121os_log_info_enabled(os_log_t log __unused)
122{
123 return true;
124}
125
126bool
127os_log_debug_enabled(os_log_t log __unused)
128{
129 return true;
130}
131
132os_log_t
133os_log_create(const char *subsystem __unused, const char *category __unused)
134{
135 return &_os_log_default;
136}
137
138bool
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
162os_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
172static 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
202static 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
282static 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
338static 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
370OS_ALWAYS_INLINE
371static 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
388static 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
429static 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
459out:
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
506static oslog_stream_buf_entry_t
507oslog_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
539void
540firehose_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
574finish:
575 _firehose_trace(stream, ftid, stamp, pubdata, publen);
576}
577#endif
578
579firehose_tracepoint_id_t
580firehose_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
604void
605__firehose_buffer_push_to_logd(firehose_buffer_t fb __unused, bool for_io __unused) {
606 oslogwakeup();
607 return;
608}
609
610void
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.
629void
630__firehose_critical_region_enter(void) {
631 disable_preemption();
632 return;
633}
634
635void
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
648extern u_int32_t RandomULong(void);
649extern uint32_t find_pattern_in_buffer(char * pattern, uint32_t len, int expected_count);
650void test_oslog_default_helper(uint32_t uniqid, uint64_t count);
651void test_oslog_info_helper(uint32_t uniqid, uint64_t count);
652void test_oslog_debug_helper(uint32_t uniqid, uint64_t count);
653void test_oslog_error_helper(uint32_t uniqid, uint64_t count);
654void test_oslog_fault_helper(uint32_t uniqid, uint64_t count);
655void _test_log_loop(void * arg __unused, wait_result_t wres __unused);
656void test_oslog_handleOSLogCtl(int32_t * in, int32_t * out, int32_t len);
657kern_return_t test_stresslog_dropmsg(uint32_t uniqid);
658
659kern_return_t test_os_log(void);
660kern_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
678GENOSLOGHELPER(test_oslog_info_helper, "oslog_info_helper", os_log_info);
679GENOSLOGHELPER(test_oslog_fault_helper, "oslog_fault_helper", os_log_fault);
680GENOSLOGHELPER(test_oslog_debug_helper, "oslog_debug_helper", os_log_debug);
681GENOSLOGHELPER(test_oslog_error_helper, "oslog_error_helper", os_log_error);
682GENOSLOGHELPER(test_oslog_default_helper, "oslog_default_helper", os_log);
683
684kern_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
780static uint32_t _test_log_loop_count = 0;
781void _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
788kern_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
821void 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
880kern_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
898