xnu-6153.141.1.tar.gz
[apple/xnu.git] / libkern / os / log.c
1 /* * Copyright (c) 2019 Apple Inc. All rights reserved. */
2
3 #include <stddef.h>
4 #undef offset
5
6 #include <kern/cpu_data.h>
7 #include <os/base.h>
8 #include <os/object.h>
9 #include <os/log.h>
10 #include <stdbool.h>
11 #include <stdint.h>
12
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>
21
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>
29
30 #include <firehose/tracepoint_private.h>
31 #include <firehose/chunk_private.h>
32 #include <os/firehose_buffer_private.h>
33 #include <os/firehose.h>
34
35 #include <os/log_private.h>
36 #include "trace_internal.h"
37
38 #include "log_encode.h"
39
40 /* on embedded, with no kext loading or unloads,
41 * make the kernel use the libtrace shared cache path for logging
42 */
43 #define FIREHOSE_USES_SHARED_CACHE NO_KEXTD
44
45 #if FIREHOSE_USES_SHARED_CACHE
46 extern vm_offset_t segLOWESTTEXT;
47 #endif
48
49 struct os_log_s {
50 int a;
51 };
52
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;
57
58 extern void bsd_log_lock(void);
59 extern void bsd_log_unlock(void);
60 extern void logwakeup(struct msgbuf *);
61
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)
65
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);
70
71 extern int oslog_stream_open;
72
73 extern void *OSKextKextForAddress(const void *);
74
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;
83
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;
88
89 static bool oslog_boot_done = false;
90 extern boolean_t early_boot_complete;
91
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 */
96
97 // XXX
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);
101
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);
105
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);
109
110 static void
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);
113
114 static void
115 _os_log_to_msgbuf_internal(const char *format, va_list args, bool safe, bool logging, bool addcr);
116
117 static void
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);
120
121
122 static void
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);
125
126 bool
127 os_log_info_enabled(os_log_t log __unused)
128 {
129 return true;
130 }
131
132 bool
133 os_log_debug_enabled(os_log_t log __unused)
134 {
135 return true;
136 }
137
138 os_log_t
139 os_log_create(const char *subsystem __unused, const char *category __unused)
140 {
141 return &_os_log_default;
142 }
143
144 bool
145 _os_log_string_is_public(const char *str __unused)
146 {
147 return true;
148 }
149
150 __attribute__((noinline, not_tail_called)) void
151 _os_log_internal(void *dso, os_log_t log, uint8_t type, const char *message, ...)
152 {
153 va_list args;
154 void *addr = __builtin_return_address(0);
155
156 va_start(args, message);
157
158 _os_log_with_args_internal(log, type, message, args, addr, dso, FALSE, FALSE);
159
160 va_end(args);
161
162 return;
163 }
164
165 __attribute__((noinline, not_tail_called)) int
166 _os_log_internal_driverKit(void *dso, os_log_t log, uint8_t type, const char *message, ...)
167 {
168 va_list args;
169 void *addr = __builtin_return_address(0);
170 bool driverKitLog = FALSE;
171
172 /*
173 * We want to be able to identify dexts from the logs.
174 *
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.
179 *
180 * Dext however are not loaded in kernel space so they do not
181 * have a kernel range of addresses.
182 *
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.
187 *
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.
191 */
192 task_t self_task = current_task();
193
194 /*
195 * Only dextis are supposed to use this log path.
196 */
197 if (!task_is_driver(self_task)) {
198 return EPERM;
199 }
200
201 uint64_t loadTag = get_task_loadTag(self_task);
202 if (loadTag != 0) {
203 driverKitLog = TRUE;
204 addr = (void*) loadTag;
205 }
206 va_start(args, message);
207
208 _os_log_with_args_internal(log, type, message, args, addr, dso, driverKitLog, true);
209
210 va_end(args);
211
212 return 0;
213 }
214
215 #pragma mark - shim functions
216
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)
219 {
220 // if no address passed, look it up
221 if (addr == NULL) {
222 addr = __builtin_return_address(0);
223 }
224
225 _os_log_with_args_internal(oslog, type, format, args, addr, NULL, FALSE, FALSE);
226 }
227
228 static void
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)
231 {
232 uint32_t logging_config = atm_get_diagnostic_config();
233 boolean_t safe;
234 boolean_t logging;
235
236 if (format[0] == '\0') {
237 return;
238 }
239
240 /* early boot can log to dmesg for later replay (27307943) */
241 safe = (!early_boot_complete || oslog_is_safe());
242
243 if (logging_config & ATM_TRACE_DISABLE || logging_config & ATM_TRACE_OFF) {
244 logging = false;
245 } else {
246 logging = true;
247 }
248
249 if (oslog != &_os_log_replay) {
250 _os_log_to_msgbuf_internal(format, args, safe, logging, addcr);
251 }
252
253 if (safe && logging) {
254 _os_log_to_log_internal(oslog, type, format, args, addr, dso, driverKit);
255 }
256 }
257
258 static void
259 _os_log_to_msgbuf_internal(const char *format, va_list args, bool safe, bool logging, bool addcr)
260 {
261 static int msgbufreplay = -1;
262 va_list args_copy;
263
264 #if DEVELOPMENT || DEBUG
265 if (safe) {
266 bsd_log_lock();
267 }
268 #else
269 bsd_log_lock();
270 #endif
271
272 if (!safe) {
273 if (-1 == msgbufreplay) {
274 msgbufreplay = msgbufp->msg_bufx;
275 }
276 } else if (logging && (-1 != msgbufreplay)) {
277 uint32_t i;
278 uint32_t localbuff_size;
279 int newl, position;
280 char *localbuff, *p, *s, *next, ch;
281
282 position = msgbufreplay;
283 msgbufreplay = -1;
284 localbuff_size = (msgbufp->msg_size + 2); /* + '\n' + '\0' */
285 /* Size for non-blocking */
286 if (localbuff_size > 4096) {
287 localbuff_size = 4096;
288 }
289 bsd_log_unlock();
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 */
293 bsd_log_lock();
294 /*
295 * The message buffer is circular; start at the replay pointer, and
296 * make one loop up to write pointer - 1.
297 */
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;
302 }
303 ch = *p;
304 if (ch == '\0') {
305 continue;
306 }
307 newl = (ch == '\n');
308 localbuff[i++] = ch;
309 if (i >= (localbuff_size - 2)) {
310 break;
311 }
312 }
313 bsd_log_unlock();
314
315 if (!newl) {
316 localbuff[i++] = '\n';
317 }
318 localbuff[i++] = 0;
319
320 s = localbuff;
321 while ((next = strchr(s, '\n'))) {
322 next++;
323 ch = next[0];
324 next[0] = 0;
325 os_log(&_os_log_replay, "%s", s);
326 next[0] = ch;
327 s = next;
328 }
329 kfree(localbuff, localbuff_size);
330 }
331 bsd_log_lock();
332 }
333
334 va_copy(args_copy, args);
335 vprintf_log_locked(format, args_copy, addcr);
336 va_end(args_copy);
337
338 #if DEVELOPMENT || DEBUG
339 if (safe) {
340 bsd_log_unlock();
341 logwakeup(msgbufp);
342 }
343 #else
344 bsd_log_unlock();
345 if (safe) {
346 logwakeup(msgbufp);
347 }
348 #endif
349 }
350
351 static void
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)
354 {
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];
359 va_list args_copy;
360
361 if (addr == NULL) {
362 return;
363 }
364
365 #if FIREHOSE_USES_SHARED_CACHE
366 dso = (void *) segLOWESTTEXT;
367 #else /* FIREHOSE_USES_SHARED_CACHE */
368 if (dso == NULL) {
369 dso = (void *) OSKextKextForAddress(format);
370 if (dso == NULL) {
371 return;
372 }
373 }
374
375 if (!_os_trace_addr_in_text_segment(dso, format)) {
376 return;
377 }
378 if (!driverKit) {
379 void *dso_addr = (void *) OSKextKextForAddress(addr);
380 if (dso != dso_addr) {
381 return;
382 }
383 }
384 #endif /* FIREHOSE_USES_SHARED_CACHE */
385
386 memset(&context, 0, sizeof(context));
387 memset(buffer, 0, OS_LOG_BUFFER_MAX_SIZE);
388
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);
394
395 va_copy(args_copy, args);
396
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);
400 } else {
401 os_atomic_inc(&oslog_p_error_count, relaxed);
402 }
403
404 va_end(args_copy);
405 }
406
407 static inline size_t
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)
410 {
411 uintptr_t shift_addr = (uintptr_t)address - (uintptr_t)dso;
412 #if FIREHOSE_USES_SHARED_CACHE
413
414 *flags = _firehose_tracepoint_flags_pc_style_shared_cache;
415 memcpy(buf, (uint32_t[]){ shift_addr },
416 sizeof(uint32_t));
417 return sizeof(uint32_t);
418
419 #else /* FIREHOSE_USES_SHARED_CACHE */
420 kernel_mach_header_t *mh = dso;
421
422 /*
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
426 * absolute pc.
427 */
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);
432 } else {
433 *flags = _firehose_tracepoint_flags_pc_style_absolute;
434 if (!driverKit) {
435 shift_addr = VM_KERNEL_UNSLIDE(address);
436 } else {
437 shift_addr = (uintptr_t) address;
438 }
439 memcpy(buf, (uintptr_t[]){ shift_addr }, sizeof(uintptr_t));
440 #if __LP64__
441 return 6; // 48 bits are enough
442 #else
443 return sizeof(uintptr_t);
444 #endif
445 }
446 #endif /* !FIREHOSE_USES_SHARED_CACHE */
447 }
448
449
450 OS_ALWAYS_INLINE
451 static inline size_t
452 _os_log_buffer_pack(uint8_t *buffdata, size_t buffdata_sz,
453 os_log_buffer_context_t ctx)
454 {
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;
458
459 if (total_sz > buffdata_sz) {
460 return 0;
461 }
462
463 memcpy(buffdata, buffer, buffer_sz);
464 memcpy(&buffdata[buffer_sz], ctx->pubdata, ctx->pubdata_sz);
465 return total_sz;
466 }
467
468 static void
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)
471 {
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;
477 uint64_t timestamp;
478 uint64_t thread_id;
479
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) {
485 return;
486 }
487 buffdata_sz += addr_len;
488
489 timestamp = firehose_tracepoint_time(firehose_activity_flags_default);
490 thread_id = thread_tid(current_thread());
491
492 if (driverKit) {
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);
497 } else {
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));
501 }
502
503 if (FALSE) {
504 firehose_debug_trace(stream, trace_id.ftid_value, timestamp,
505 format, buffdata, buffdata_sz);
506 }
507 if (type == OS_LOG_TYPE_INFO || type == OS_LOG_TYPE_DEBUG) {
508 stream = firehose_stream_memory;
509 } else {
510 stream = firehose_stream_persist;
511 }
512 _firehose_trace(stream, trace_id, timestamp, buffdata, buffdata_sz);
513 }
514
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)
518 {
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);
522
523 firehose_tracepoint_t ft;
524
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);
528 return 0;
529 }
530
531 if (oslog_stream_open && (stream != firehose_stream_metadata)) {
532 stream_lock();
533 if (!oslog_stream_open) {
534 stream_unlock();
535 goto out;
536 }
537
538 oslog_s_total_msgcount++;
539 oslog_streamwrite_locked(ftid, stamp, pubdata, publen);
540 stream_unlock();
541 oslog_streamwakeup();
542 }
543
544 out:
545 ft = __firehose_buffer_tracepoint_reserve(stamp, stream, (uint16_t)publen, 0, NULL);
546 if (!fastpath(ft)) {
547 if (oslog_boot_done) {
548 if (stream == firehose_stream_metadata) {
549 os_atomic_inc(&oslog_p_metadata_dropped_msgcount, relaxed);
550 } else {
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);
554 }
555 return 0;
556 }
557 firehose_chunk_t fbc = firehose_boot_chunk;
558 long offset;
559
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);
563 if (offset <= 0) {
564 os_atomic_inc(&oslog_p_boot_dropped_msgcount, relaxed);
565 return 0;
566 }
567
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;
574 }
575 if (!oslog_boot_done) {
576 oslog_boot_done = true;
577 }
578 memcpy(ft->ft_data, pubdata, publen);
579
580 __firehose_buffer_tracepoint_flush(ft, ftid);
581 if (stream == firehose_stream_metadata) {
582 os_atomic_inc(&oslog_p_metadata_saved_msgcount, relaxed);
583 } else {
584 os_atomic_inc(&oslog_p_saved_msgcount, relaxed);
585 }
586 return ftid.ftid_value;
587 }
588
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)
592 {
593 oslog_stream_buf_entry_t m_entry = NULL;
594 firehose_tracepoint_t ft = NULL;
595 size_t m_entry_len = 0;
596
597 if (!pubdata) {
598 return NULL;
599 }
600
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);
604 if (!m_entry) {
605 return NULL;
606 }
607
608 m_entry->type = type;
609 m_entry->timestamp = stamp;
610 m_entry->size = sizeof(struct firehose_tracepoint_s) + publen;
611
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);
617
618 return m_entry;
619 }
620
621 #ifdef KERNEL
622 void
623 firehose_trace_metadata(firehose_stream_t stream, firehose_tracepoint_id_u ftid,
624 uint64_t stamp, const void *pubdata, size_t publen)
625 {
626 oslog_stream_buf_entry_t m_entry = NULL;
627
628 // If streaming mode is not on, only log the metadata
629 // in the persistence buffer
630
631 stream_lock();
632 if (!oslog_stream_open) {
633 stream_unlock();
634 goto finish;
635 }
636 stream_unlock();
637
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);
641 if (!m_entry) {
642 os_atomic_inc(&oslog_s_error_count, relaxed);
643 goto finish;
644 }
645
646 stream_lock();
647 if (!oslog_stream_open) {
648 stream_unlock();
649 kfree(m_entry, sizeof(struct oslog_stream_buf_entry_s) +
650 sizeof(struct firehose_tracepoint_s) + publen);
651 goto finish;
652 }
653 oslog_s_metadata_msgcount++;
654 oslog_streamwrite_metadata_locked(m_entry);
655 stream_unlock();
656
657 finish:
658 _firehose_trace(stream, ftid, stamp, pubdata, publen);
659 }
660 #endif
661
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)
665 {
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);
669 size_t i;
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",
673 (unsigned int)i,
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
682 );
683 }
684 return trace_id;
685 }
686
687 void
688 __firehose_buffer_push_to_logd(firehose_buffer_t fb __unused, bool for_io __unused)
689 {
690 oslogwakeup();
691 return;
692 }
693
694 void
695 __firehose_allocate(vm_offset_t *addr, vm_size_t size __unused)
696 {
697 firehose_chunk_t kernel_buffer = (firehose_chunk_t)kernel_firehose_addr;
698
699 if (kernel_firehose_addr) {
700 *addr = kernel_firehose_addr;
701 } else {
702 *addr = 0;
703 return;
704 }
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);
709 return;
710 }
711 // There isnt a lock held in this case.
712 void
713 __firehose_critical_region_enter(void)
714 {
715 disable_preemption();
716 return;
717 }
718
719 void
720 __firehose_critical_region_leave(void)
721 {
722 enable_preemption();
723 return;
724 }
725
726 #ifdef CONFIG_XNUPOST
727
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 "#")
732
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);
743
744 kern_return_t test_os_log(void);
745 kern_return_t test_os_log_parallel(void);
746
747 #define GENOSLOGHELPER(fname, ident, callout_f) \
748 void fname(uint32_t uniqid, uint64_t count) \
749 { \
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++) \
755 { \
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);*/ \
760 } \
761 }
762
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);
768
769 kern_return_t
770 test_os_log()
771 {
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;
779 int datalen = 0;
780 uint64_t a = mach_absolute_time();
781 uint64_t seqno = 1;
782 uint64_t total_seqno = 2;
783
784 os_log_t log_handle = os_log_create("com.apple.xnu.test.t1", "kpost");
785
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");
790
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);
795
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");
799
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);
803
804 seqno += 1;
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);
808
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");
812
813 uint32_t logging_config = atm_get_diagnostic_config();
814 T_LOG("checking atm_diagnostic_config 0x%X", logging_config);
815
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.");
818 return KERN_SUCCESS;
819 }
820
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");
823
824 a = mach_absolute_time();
825 total_seqno = 1;
826 seqno = 1;
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");
834
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");
838
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");
842
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");
846
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");
850
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");
854
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");
858
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);
861
862 return KERN_SUCCESS;
863 }
864
865 static uint32_t _test_log_loop_count = 0;
866 void
867 _test_log_loop(void * arg __unused, wait_result_t wres __unused)
868 {
869 uint32_t uniqid = RandomULong();
870 test_oslog_debug_helper(uniqid, 100);
871 os_atomic_add(&_test_log_loop_count, 100, relaxed);
872 }
873
874 kern_return_t
875 test_os_log_parallel(void)
876 {
877 thread_t thread[2];
878 kern_return_t kr;
879 uint32_t uniqid = RandomULong();
880
881 printf("oslog internal counters total %u , saved %u, dropped %u", oslog_p_total_msgcount, oslog_p_saved_msgcount,
882 oslog_p_dropped_msgcount);
883
884 kr = kernel_thread_start(_test_log_loop, NULL, &thread[0]);
885 T_ASSERT_EQ_INT(kr, KERN_SUCCESS, "kernel_thread_start returned successfully");
886
887 kr = kernel_thread_start(_test_log_loop, NULL, &thread[1]);
888 T_ASSERT_EQ_INT(kr, KERN_SUCCESS, "kernel_thread_start returned successfully");
889
890 test_oslog_info_helper(uniqid, 100);
891
892 /* wait until other thread has also finished */
893 while (_test_log_loop_count < 200) {
894 delay(1000);
895 }
896
897 thread_deallocate(thread[0]);
898 thread_deallocate(thread[1]);
899
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");
903
904 return KERN_SUCCESS;
905 }
906
907 void
908 test_oslog_handleOSLogCtl(int32_t * in, int32_t * out, int32_t len)
909 {
910 if (!in || !out || len != 4) {
911 return;
912 }
913 switch (in[0]) {
914 case 1:
915 {
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;
921 break;
922 }
923 case 2:
924 {
925 /* mini stress run */
926 out[0] = test_os_log_parallel();
927 break;
928 }
929 case 3:
930 {
931 /* drop msg tests */
932 out[1] = RandomULong();
933 out[0] = test_stresslog_dropmsg(out[1]);
934 break;
935 }
936 case 4:
937 {
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;
943 return;
944 }
945
946 switch (in[1]) {
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;
953 }
954 out[0] = KERN_SUCCESS;
955 break;
956 /* end of case 4 */
957 }
958 default:
959 {
960 out[0] = KERN_INVALID_VALUE;
961 break;
962 }
963 }
964 return;
965 }
966
967 kern_return_t
968 test_stresslog_dropmsg(uint32_t uniqid)
969 {
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);
978 }
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);
981 return KERN_SUCCESS;
982 }
983
984 #endif