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/startup.h>
29 #include <kern/task.h>
30
31 #include <firehose/tracepoint_private.h>
32 #include <firehose/chunk_private.h>
33 #include <os/firehose_buffer_private.h>
34 #include <os/firehose.h>
35
36 #include <os/log_private.h>
37 #include "trace_internal.h"
38
39 #include "log_encode.h"
40 #include "log_internal.h"
41 #include "log_mem.h"
42 #include "log_queue.h"
43
44 #define OS_LOGMEM_BUF_ORDER 14
45 #define OS_LOGMEM_MIN_LOG_ORDER 9
46 #define OS_LOGMEM_MAX_LOG_ORDER (OS_LOG_MAX_SIZE_ORDER)
47
48 struct os_log_s {
49 int a;
50 };
51
52 struct os_log_s _os_log_default;
53 struct os_log_s _os_log_replay;
54 struct logmem_s os_log_mem;
55
56 extern vm_offset_t kernel_firehose_addr;
57 extern firehose_chunk_t firehose_boot_chunk;
58
59 extern bool bsd_log_lock(bool);
60 extern void bsd_log_unlock(void);
61 extern void logwakeup(struct msgbuf *);
62
63 extern void oslog_stream(bool, firehose_tracepoint_id_u, uint64_t, const void *, size_t);
64 extern void *OSKextKextForAddress(const void *);
65
66 /* Counters for persistence mode */
67 SCALABLE_COUNTER_DEFINE(oslog_p_total_msgcount);
68 SCALABLE_COUNTER_DEFINE(oslog_p_metadata_saved_msgcount);
69 SCALABLE_COUNTER_DEFINE(oslog_p_metadata_dropped_msgcount);
70 SCALABLE_COUNTER_DEFINE(oslog_p_error_count);
71 SCALABLE_COUNTER_DEFINE(oslog_p_saved_msgcount);
72 SCALABLE_COUNTER_DEFINE(oslog_p_dropped_msgcount);
73 SCALABLE_COUNTER_DEFINE(oslog_p_boot_dropped_msgcount);
74 SCALABLE_COUNTER_DEFINE(oslog_p_coprocessor_total_msgcount);
75 SCALABLE_COUNTER_DEFINE(oslog_p_coprocessor_dropped_msgcount);
76 SCALABLE_COUNTER_DEFINE(oslog_p_unresolved_kc_msgcount);
77
78 /* Counters for msgbuf logging */
79 SCALABLE_COUNTER_DEFINE(oslog_msgbuf_msgcount)
80 SCALABLE_COUNTER_DEFINE(oslog_msgbuf_dropped_msgcount)
81
82 static bool oslog_boot_done = false;
83 static bool oslog_disabled = false;
84
85 #ifdef XNU_KERNEL_PRIVATE
86 bool startup_serial_logging_active = true;
87 uint64_t startup_serial_num_procs = 300;
88 #endif /* XNU_KERNEL_PRIVATE */
89
90 bool os_log_disabled(void);
91
92 __osloglike(3, 0)
93 static void
94 _os_log_with_args_internal(os_log_t, os_log_type_t, const char *, va_list,
95 uint64_t, void *, void *, bool, bool);
96
97 __osloglike(1, 0)
98 static void
99 _os_log_to_msgbuf_internal(const char *, va_list, uint64_t, bool, bool, bool);
100
101 __startup_func
102 static void
oslog_init(void)103 oslog_init(void)
104 {
105 /*
106 * Disable kernel logging if ATM_TRACE_DISABLE set. ATM_TRACE_DISABLE
107 * bit is not supposed to change during a system run but nothing really
108 * prevents userspace from unintentionally doing so => we stash initial
109 * value in a dedicated variable for a later reference, just in case.
110 */
111 oslog_disabled = atm_get_diagnostic_config() & ATM_TRACE_DISABLE;
112 }
113 STARTUP(OSLOG, STARTUP_RANK_FIRST, oslog_init);
114
115 __startup_func
116 static void
oslog_init_logmem(void)117 oslog_init_logmem(void)
118 {
119 if (os_log_disabled()) {
120 printf("Long logs support disabled: Logging disabled by ATM\n");
121 return;
122 }
123
124 const size_t logmem_size = logmem_required_size(OS_LOGMEM_BUF_ORDER, OS_LOGMEM_MIN_LOG_ORDER);
125 vm_offset_t addr;
126
127 if (kmem_alloc(kernel_map, &addr, logmem_size + ptoa(2),
128 KMA_KOBJECT | KMA_PERMANENT | KMA_ZERO | KMA_GUARD_FIRST | KMA_GUARD_LAST,
129 VM_KERN_MEMORY_LOG) == KERN_SUCCESS) {
130 logmem_init(&os_log_mem, (void *)(addr + PAGE_SIZE), logmem_size,
131 OS_LOGMEM_BUF_ORDER, OS_LOGMEM_MIN_LOG_ORDER, OS_LOGMEM_MAX_LOG_ORDER);
132 printf("Long logs support configured: size: %u\n", os_log_mem.lm_cnt_free);
133 } else {
134 printf("Long logs support disabled: Not enough memory\n");
135 }
136 }
137 STARTUP(OSLOG, STARTUP_RANK_SECOND, oslog_init_logmem);
138
139 static bool
os_log_safe(void)140 os_log_safe(void)
141 {
142 return oslog_is_safe() || startup_phase < STARTUP_SUB_EARLY_BOOT;
143 }
144
145 static bool
os_log_turned_off(void)146 os_log_turned_off(void)
147 {
148 return oslog_disabled || (atm_get_diagnostic_config() & ATM_TRACE_OFF);
149 }
150
151 bool
os_log_info_enabled(os_log_t log __unused)152 os_log_info_enabled(os_log_t log __unused)
153 {
154 return !os_log_turned_off();
155 }
156
157 bool
os_log_debug_enabled(os_log_t log __unused)158 os_log_debug_enabled(os_log_t log __unused)
159 {
160 return !os_log_turned_off();
161 }
162
163 bool
os_log_disabled(void)164 os_log_disabled(void)
165 {
166 return oslog_disabled;
167 }
168
169 os_log_t
os_log_create(const char * subsystem __unused,const char * category __unused)170 os_log_create(const char *subsystem __unused, const char *category __unused)
171 {
172 return &_os_log_default;
173 }
174
175 __attribute__((noinline, not_tail_called)) void
_os_log_internal(void * dso,os_log_t log,uint8_t type,const char * fmt,...)176 _os_log_internal(void *dso, os_log_t log, uint8_t type, const char *fmt, ...)
177 {
178 uint64_t ts = firehose_tracepoint_time(firehose_activity_flags_default);
179 void *addr = __builtin_return_address(0);
180 va_list args;
181
182 va_start(args, fmt);
183 _os_log_with_args_internal(log, type, fmt, args, ts, addr, dso, FALSE, FALSE);
184 va_end(args);
185 }
186
187 __attribute__((noinline, not_tail_called)) void
_os_log_at_time(void * dso,os_log_t log,uint8_t type,uint64_t ts,const char * fmt,...)188 _os_log_at_time(void *dso, os_log_t log, uint8_t type, uint64_t ts, const char *fmt, ...)
189 {
190 void *addr = __builtin_return_address(0);
191 va_list args;
192
193 va_start(args, fmt);
194 _os_log_with_args_internal(log, type, fmt, args, ts, addr, dso, FALSE, FALSE);
195 va_end(args);
196 }
197
198 __attribute__((noinline, not_tail_called)) int
_os_log_internal_driverKit(void * dso,os_log_t log,uint8_t type,const char * fmt,...)199 _os_log_internal_driverKit(void *dso, os_log_t log, uint8_t type, const char *fmt, ...)
200 {
201 uint64_t ts = firehose_tracepoint_time(firehose_activity_flags_default);
202 void *addr = __builtin_return_address(0);
203 bool driverKitLog = FALSE;
204 va_list args;
205
206 /*
207 * We want to be able to identify dexts from the logs.
208 *
209 * Usually the addr is used to understand if the log line
210 * was generated by a kext or the kernel main executable.
211 * Logd uses copyKextUUIDForAddress with the addr specified
212 * in the log line to retrieve the kext UUID of the sender.
213 *
214 * Dext however are not loaded in kernel space so they do not
215 * have a kernel range of addresses.
216 *
217 * To make the same mechanism work, OSKext fakes a kernel
218 * address range for dexts using the loadTag,
219 * so we just need to use the loadTag as addr here
220 * to allow logd to retrieve the correct UUID.
221 *
222 * NOTE: loadTag is populated in the task when the dext is matching,
223 * so if log lines are generated before the matching they will be
224 * identified as kernel main executable.
225 */
226 task_t self_task = current_task();
227
228 /*
229 * Only dextis are supposed to use this log path. Verified in log_data()
230 * but worth of another check here in case this function gets called
231 * directly.
232 */
233 if (!task_is_driver(self_task)) {
234 return EPERM;
235 }
236
237 uint64_t loadTag = get_task_loadTag(self_task);
238 if (loadTag != 0) {
239 driverKitLog = TRUE;
240 addr = (void*) loadTag;
241 }
242
243 va_start(args, fmt);
244 _os_log_with_args_internal(log, type, fmt, args, ts, addr, dso, driverKitLog, true);
245 va_end(args);
246
247 return 0;
248 }
249
250 #pragma mark - shim functions
251
252 __attribute__((noinline, not_tail_called)) void
os_log_with_args(os_log_t oslog,os_log_type_t type,const char * fmt,va_list args,void * addr)253 os_log_with_args(os_log_t oslog, os_log_type_t type, const char *fmt,
254 va_list args, void *addr)
255 {
256 uint64_t ts = firehose_tracepoint_time(firehose_activity_flags_default);
257
258 // if no address passed, look it up
259 if (addr == NULL) {
260 addr = __builtin_return_address(0);
261 }
262
263 _os_log_with_args_internal(oslog, type, fmt, args, ts, addr, NULL, FALSE, FALSE);
264 }
265
266 static firehose_stream_t
firehose_stream(os_log_type_t type)267 firehose_stream(os_log_type_t type)
268 {
269 return (type == OS_LOG_TYPE_INFO || type == OS_LOG_TYPE_DEBUG) ?
270 firehose_stream_memory : firehose_stream_persist;
271 }
272
273 static firehose_tracepoint_id_t
firehose_ftid(os_log_type_t type,const char * fmt,firehose_tracepoint_flags_t flags,void * dso,void * addr,bool driverKit)274 firehose_ftid(os_log_type_t type, const char *fmt, firehose_tracepoint_flags_t flags,
275 void *dso, void *addr, bool driverKit)
276 {
277 uint32_t off;
278
279 if (driverKit) {
280 /*
281 * Set FIREHOSE_TRACEPOINT_PC_DYNAMIC_BIT so logd will not try
282 * to find the format string in the executable text.
283 */
284 off = (uint32_t)((uintptr_t)addr | FIREHOSE_TRACEPOINT_PC_DYNAMIC_BIT);
285 } else {
286 off = _os_trace_offset(dso, fmt, (_firehose_tracepoint_flags_activity_t)flags);
287 }
288
289 return FIREHOSE_TRACE_ID_MAKE(firehose_tracepoint_namespace_log, type, flags, off);
290 }
291
292 static firehose_tracepoint_flags_t
firehose_ftid_flags(const void * dso,bool driverKit)293 firehose_ftid_flags(const void *dso, bool driverKit)
294 {
295 kc_format_t kcformat = KCFormatUnknown;
296 __assert_only bool result = PE_get_primary_kc_format(&kcformat);
297 assert(result);
298
299 if (kcformat == KCFormatStatic || kcformat == KCFormatKCGEN) {
300 return _firehose_tracepoint_flags_pc_style_shared_cache;
301 }
302
303 /*
304 * driverKit will have the dso set as MH_EXECUTE (it is logging from a
305 * syscall in the kernel) but needs logd to parse the address as an
306 * absolute pc.
307 */
308 const kernel_mach_header_t *mh = dso;
309 if (mh->filetype == MH_EXECUTE && !driverKit) {
310 return _firehose_tracepoint_flags_pc_style_main_exe;
311 }
312
313 return _firehose_tracepoint_flags_pc_style_absolute;
314 }
315
316 static void *
resolve_dso(const char * fmt,void * dso,void * addr,bool driverKit)317 resolve_dso(const char *fmt, void *dso, void *addr, bool driverKit)
318 {
319 kc_format_t kcformat = KCFormatUnknown;
320
321 if (!addr || !PE_get_primary_kc_format(&kcformat)) {
322 return NULL;
323 }
324
325 switch (kcformat) {
326 case KCFormatStatic:
327 case KCFormatKCGEN:
328 dso = PE_get_kc_baseaddress(KCKindPrimary);
329 break;
330 case KCFormatDynamic:
331 case KCFormatFileset:
332 if (!dso && (dso = (void *)OSKextKextForAddress(fmt)) == NULL) {
333 return NULL;
334 }
335 if (!_os_trace_addr_in_text_segment(dso, fmt)) {
336 return NULL;
337 }
338 if (!driverKit && (dso != (void *)OSKextKextForAddress(addr))) {
339 return NULL;
340 }
341 break;
342 default:
343 panic("unknown KC format type");
344 }
345
346 return dso;
347 }
348
349 static inline uintptr_t
resolve_location(firehose_tracepoint_flags_t flags,uintptr_t dso,uintptr_t addr,bool driverKit,size_t * loc_size)350 resolve_location(firehose_tracepoint_flags_t flags, uintptr_t dso, uintptr_t addr,
351 bool driverKit, size_t *loc_size)
352 {
353 switch (flags) {
354 case _firehose_tracepoint_flags_pc_style_shared_cache:
355 case _firehose_tracepoint_flags_pc_style_main_exe:
356 *loc_size = sizeof(uint32_t);
357 return addr - dso;
358 case _firehose_tracepoint_flags_pc_style_absolute:
359 *loc_size = sizeof(uintptr_t);
360 return driverKit ? addr : VM_KERNEL_UNSLIDE(addr);
361 default:
362 panic("Unknown firehose tracepoint flags %x", flags);
363 }
364 }
365
366 static void
log_payload_init(log_payload_t lp,firehose_stream_t stream,firehose_tracepoint_id_u ftid,uint64_t timestamp,size_t data_size)367 log_payload_init(log_payload_t lp, firehose_stream_t stream, firehose_tracepoint_id_u ftid,
368 uint64_t timestamp, size_t data_size)
369 {
370 lp->lp_stream = stream;
371 lp->lp_ftid = ftid;
372 lp->lp_timestamp = timestamp;
373 lp->lp_data_size = (uint16_t)data_size;
374 }
375
376 static void
_os_log_to_log_internal(os_log_type_t type,const char * fmt,va_list args,uint64_t ts,void * addr,void * dso,bool driverKit)377 _os_log_to_log_internal(os_log_type_t type, const char *fmt, va_list args,
378 uint64_t ts, void *addr, void *dso, bool driverKit)
379 {
380 counter_inc(&oslog_p_total_msgcount);
381
382 dso = resolve_dso(fmt, dso, addr, driverKit);
383 if (__improbable(!dso)) {
384 counter_inc(&oslog_p_unresolved_kc_msgcount);
385 return;
386 }
387
388 firehose_tracepoint_flags_t flags = firehose_ftid_flags(dso, driverKit);
389
390 size_t loc_sz = 0;
391 uintptr_t loc = resolve_location(flags, (uintptr_t)dso, (uintptr_t)addr,
392 driverKit, &loc_sz);
393
394 firehose_tracepoint_id_u ftid;
395 ftid.ftid_value = firehose_ftid(type, fmt, flags, dso, addr, driverKit);
396
397 __attribute__((uninitialized, aligned(8)))
398 uint8_t buffer[OS_LOG_BUFFER_MAX_SIZE];
399 struct os_log_context_s ctx;
400
401 os_log_context_init(&ctx, &os_log_mem, buffer, sizeof(buffer));
402
403 if (!os_log_context_encode(&ctx, fmt, args, loc, loc_sz)) {
404 counter_inc(&oslog_p_error_count);
405 os_log_context_free(&ctx);
406 return;
407 }
408
409 log_payload_s log;
410 log_payload_init(&log, firehose_stream(type), ftid, ts, ctx.ctx_content_sz);
411
412 if (!log_queue_log(&log, ctx.ctx_buffer, true)) {
413 counter_inc(&oslog_p_dropped_msgcount);
414 }
415
416 os_log_context_free(&ctx);
417 }
418
419 static void
_os_log_with_args_internal(os_log_t oslog,os_log_type_t type,const char * fmt,va_list args,uint64_t ts,void * addr,void * dso,bool driverKit,bool addcr)420 _os_log_with_args_internal(os_log_t oslog, os_log_type_t type, const char *fmt,
421 va_list args, uint64_t ts, void *addr, void *dso, bool driverKit, bool addcr)
422 {
423 if (fmt[0] == '\0') {
424 return;
425 }
426
427 /* early boot can log to dmesg for later replay (27307943) */
428 bool safe = os_log_safe();
429 bool logging = !os_log_turned_off();
430
431 if (oslog != &_os_log_replay) {
432 _os_log_to_msgbuf_internal(fmt, args, ts, safe, logging, addcr);
433 }
434
435 if (safe && logging) {
436 _os_log_to_log_internal(type, fmt, args, ts, addr, dso, driverKit);
437 }
438 }
439
440 static void
_os_log_to_msgbuf_internal(const char * format,va_list args,uint64_t timestamp,bool safe,bool logging,bool addcr)441 _os_log_to_msgbuf_internal(const char *format, va_list args, uint64_t timestamp,
442 bool safe, bool logging, bool addcr)
443 {
444 /*
445 * The following threshold was determined empirically as the point where
446 * it would be more advantageous to be able to fit in more log lines than
447 * to know exactly when a log line was printed out. We don't want to use up
448 * a large percentage of the log buffer on timestamps in a memory-constricted
449 * environment.
450 */
451 const int MSGBUF_TIMESTAMP_THRESHOLD = 4096;
452 static int msgbufreplay = -1;
453 static bool newlogline = true;
454 va_list args_copy;
455
456 if (!bsd_log_lock(safe)) {
457 counter_inc(&oslog_msgbuf_dropped_msgcount);
458 return;
459 }
460
461 if (!safe) {
462 if (-1 == msgbufreplay) {
463 msgbufreplay = msgbufp->msg_bufx;
464 }
465 } else if (logging && (-1 != msgbufreplay)) {
466 uint32_t i;
467 uint32_t localbuff_size;
468 int newl, position;
469 char *localbuff, *p, *s, *next, ch;
470
471 position = msgbufreplay;
472 msgbufreplay = -1;
473 localbuff_size = (msgbufp->msg_size + 2); /* + '\n' + '\0' */
474 /* Size for non-blocking */
475 if (localbuff_size > 4096) {
476 localbuff_size = 4096;
477 }
478 bsd_log_unlock();
479 /* Allocate a temporary non-circular buffer */
480 localbuff = kalloc_data(localbuff_size, Z_NOWAIT);
481 if (localbuff != NULL) {
482 /* in between here, the log could become bigger, but that's fine */
483 bsd_log_lock(true);
484 /*
485 * The message buffer is circular; start at the replay pointer, and
486 * make one loop up to write pointer - 1.
487 */
488 p = msgbufp->msg_bufc + position;
489 for (i = newl = 0; p != msgbufp->msg_bufc + msgbufp->msg_bufx - 1; ++p) {
490 if (p >= msgbufp->msg_bufc + msgbufp->msg_size) {
491 p = msgbufp->msg_bufc;
492 }
493 ch = *p;
494 if (ch == '\0') {
495 continue;
496 }
497 newl = (ch == '\n');
498 localbuff[i++] = ch;
499 if (i >= (localbuff_size - 2)) {
500 break;
501 }
502 }
503 bsd_log_unlock();
504
505 if (!newl) {
506 localbuff[i++] = '\n';
507 }
508 localbuff[i++] = 0;
509
510 s = localbuff;
511 while ((next = strchr(s, '\n'))) {
512 next++;
513 ch = next[0];
514 next[0] = 0;
515 os_log(&_os_log_replay, "%s", s);
516 next[0] = ch;
517 s = next;
518 }
519 kfree_data(localbuff, localbuff_size);
520 }
521 bsd_log_lock(true);
522 }
523
524 /* Do not prepend timestamps when we are memory-constricted */
525 if (newlogline && (msgbufp->msg_size > MSGBUF_TIMESTAMP_THRESHOLD)) {
526 clock_sec_t secs;
527 clock_usec_t microsecs;
528 absolutetime_to_microtime(timestamp, &secs, µsecs);
529 printf_log_locked(FALSE, "[%5lu.%06u]: ", (unsigned long)secs, microsecs);
530 }
531
532 #pragma clang diagnostic push
533 #pragma clang diagnostic ignored "-Wformat-nonliteral"
534 va_copy(args_copy, args);
535 newlogline = vprintf_log_locked(format, args_copy, addcr);
536 va_end(args_copy);
537 #pragma clang diagnostic pop
538
539 bsd_log_unlock();
540 logwakeup(msgbufp);
541 counter_inc(&oslog_msgbuf_msgcount);
542 }
543
544 bool
os_log_coprocessor(void * buff,uint64_t buff_len,os_log_type_t type,const char * uuid,uint64_t timestamp,uint32_t offset,bool stream_log)545 os_log_coprocessor(void *buff, uint64_t buff_len, os_log_type_t type,
546 const char *uuid, uint64_t timestamp, uint32_t offset, bool stream_log)
547 {
548 if (os_log_turned_off()) {
549 return false;
550 }
551
552 if (!os_log_safe()) {
553 counter_inc(&oslog_p_coprocessor_dropped_msgcount);
554 return false;
555 }
556
557 if (buff_len + 16 + sizeof(uint32_t) > OS_LOG_BUFFER_MAX_SIZE) {
558 counter_inc(&oslog_p_coprocessor_dropped_msgcount);
559 return false;
560 }
561
562 firehose_stream_t stream = firehose_stream(type);
563 // unlike kext, where pc is used to find uuid, in coprocessor logs the uuid is passed as part of the tracepoint
564 firehose_tracepoint_flags_t flags = _firehose_tracepoint_flags_pc_style_uuid_relative;
565
566 __attribute__((uninitialized))
567 uint8_t pubdata[OS_LOG_BUFFER_MAX_SIZE];
568 size_t wr_pos = 0;
569
570 memcpy(pubdata, &offset, sizeof(uint32_t));
571 wr_pos += sizeof(uint32_t);
572 memcpy(pubdata + wr_pos, uuid, 16);
573 wr_pos += 16;
574
575 memcpy(pubdata + wr_pos, buff, buff_len);
576
577 // create firehose trace id
578 firehose_tracepoint_id_u trace_id;
579 trace_id.ftid_value = FIREHOSE_TRACE_ID_MAKE(firehose_tracepoint_namespace_log,
580 type, flags, offset);
581
582 counter_inc(&oslog_p_coprocessor_total_msgcount);
583
584 log_payload_s log;
585 log_payload_init(&log, stream, trace_id, timestamp, buff_len + wr_pos);
586
587 if (!log_queue_log(&log, pubdata, stream_log)) {
588 counter_inc(&oslog_p_coprocessor_dropped_msgcount);
589 return false;
590 }
591
592 return true;
593 }
594
595 static firehose_tracepoint_id_t
_firehose_trace_early_boot(firehose_tracepoint_id_u ftid,uint64_t stamp,const void * pubdata,size_t publen)596 _firehose_trace_early_boot(firehose_tracepoint_id_u ftid, uint64_t stamp, const void *pubdata, size_t publen)
597 {
598 firehose_chunk_t fbc = firehose_boot_chunk;
599
600 //only stream available during boot is persist
601 long offset = firehose_chunk_tracepoint_try_reserve(fbc, stamp,
602 firehose_stream_persist, 0, (uint16_t)publen, 0, NULL);
603 if (offset <= 0) {
604 counter_inc(&oslog_p_boot_dropped_msgcount);
605 return 0;
606 }
607
608 firehose_tracepoint_t ft = firehose_chunk_tracepoint_begin(fbc, stamp, (uint16_t)publen,
609 thread_tid(current_thread()), offset);
610 memcpy(ft->ft_data, pubdata, publen);
611 firehose_chunk_tracepoint_end(fbc, ft, ftid);
612
613 counter_inc(&oslog_p_saved_msgcount);
614
615 return ftid.ftid_value;
616 }
617
618 static inline firehose_tracepoint_id_t
_firehose_trace(firehose_stream_t stream,firehose_tracepoint_id_u ftid,uint64_t stamp,const void * data,size_t datalen)619 _firehose_trace(firehose_stream_t stream, firehose_tracepoint_id_u ftid,
620 uint64_t stamp, const void *data, size_t datalen)
621 {
622 const uint16_t __assert_only ft_size = offsetof(struct firehose_tracepoint_s, ft_data);
623 const size_t __assert_only _firehose_chunk_payload_size = sizeof(((struct firehose_chunk_s *)0)->fc_data);
624 assert((ft_size + datalen) <= _firehose_chunk_payload_size);
625
626 firehose_tracepoint_t ft = __firehose_buffer_tracepoint_reserve(stamp, stream, (uint16_t)datalen, 0, NULL);
627
628 if (fastpath(ft)) {
629 oslog_boot_done = true;
630
631 memcpy(ft->ft_data, data, datalen);
632 __firehose_buffer_tracepoint_flush(ft, ftid);
633
634 if (stream == firehose_stream_metadata) {
635 counter_inc(&oslog_p_metadata_saved_msgcount);
636 } else {
637 counter_inc(&oslog_p_saved_msgcount);
638 }
639
640 return ftid.ftid_value;
641 }
642
643 if (!oslog_boot_done) {
644 return _firehose_trace_early_boot(ftid, stamp, data, datalen);
645 }
646
647 return 0;
648 }
649
650 static firehose_tracepoint_code_t
coproc_reg_type_to_firehost_code(os_log_coproc_reg_t reg_type)651 coproc_reg_type_to_firehost_code(os_log_coproc_reg_t reg_type)
652 {
653 switch (reg_type) {
654 case os_log_coproc_register_memory:
655 return firehose_tracepoint_code_load_memory;
656 case os_log_coproc_register_harvest_fs_ftab:
657 return firehose_tracepoint_code_load_filesystem_ftab;
658 default:
659 return firehose_tracepoint_code_invalid;
660 }
661 }
662
663 void
os_log_coprocessor_register_with_type(const char * uuid,const char * file_path,os_log_coproc_reg_t reg_type)664 os_log_coprocessor_register_with_type(const char *uuid, const char *file_path, os_log_coproc_reg_t reg_type)
665 {
666 size_t path_size = strlen(file_path) + 1;
667 size_t uuid_info_len = sizeof(struct firehose_trace_uuid_info_s) + path_size;
668
669 if (os_log_disabled() || path_size > PATH_MAX) {
670 return;
671 }
672
673 __attribute__((uninitialized))
674 union {
675 struct firehose_trace_uuid_info_s uuid_info;
676 char path[PATH_MAX + sizeof(struct firehose_trace_uuid_info_s)];
677 } buf;
678
679 // write metadata to uuid_info
680 memcpy(buf.uuid_info.ftui_uuid, uuid, sizeof(uuid_t));
681 buf.uuid_info.ftui_size = 1;
682 buf.uuid_info.ftui_address = 1;
683
684 uint64_t stamp = firehose_tracepoint_time(firehose_activity_flags_default);
685
686 // create tracepoint id
687 firehose_tracepoint_id_u trace_id;
688 trace_id.ftid_value = FIREHOSE_TRACE_ID_MAKE(firehose_tracepoint_namespace_metadata, _firehose_tracepoint_type_metadata_coprocessor,
689 (firehose_tracepoint_flags_t)0, coproc_reg_type_to_firehost_code(reg_type));
690
691 // write path to buffer
692 memcpy(buf.uuid_info.ftui_path, file_path, path_size);
693
694 // send metadata tracepoint to firehose for coprocessor registration in logd
695 firehose_trace_metadata(firehose_stream_metadata, trace_id, stamp, (void *)&buf, uuid_info_len);
696 return;
697 }
698
699 #ifdef KERNEL
700 void
firehose_trace_metadata(firehose_stream_t stream,firehose_tracepoint_id_u ftid,uint64_t stamp,const void * pubdata,size_t publen)701 firehose_trace_metadata(firehose_stream_t stream, firehose_tracepoint_id_u ftid,
702 uint64_t stamp, const void *pubdata, size_t publen)
703 {
704 if (os_log_disabled()) {
705 return;
706 }
707
708 if (!os_log_safe()) {
709 counter_inc(&oslog_p_metadata_dropped_msgcount);
710 return;
711 }
712
713 log_payload_s log;
714 log_payload_init(&log, stream, ftid, stamp, publen);
715
716 if (!log_queue_log(&log, pubdata, true)) {
717 counter_inc(&oslog_p_metadata_dropped_msgcount);
718 }
719 }
720 #endif
721
722 bool
log_payload_send(log_payload_t lp,const void * lp_data,bool use_stream)723 log_payload_send(log_payload_t lp, const void *lp_data, bool use_stream)
724 {
725 if (use_stream) {
726 bool is_metadata = (lp->lp_stream == firehose_stream_metadata);
727 oslog_stream(is_metadata, lp->lp_ftid, lp->lp_timestamp, lp_data, lp->lp_data_size);
728 }
729
730 return _firehose_trace(lp->lp_stream, lp->lp_ftid, lp->lp_timestamp,
731 lp_data, lp->lp_data_size);
732 }
733
734 void
__firehose_buffer_push_to_logd(firehose_buffer_t fb __unused,bool for_io __unused)735 __firehose_buffer_push_to_logd(firehose_buffer_t fb __unused, bool for_io __unused)
736 {
737 oslogwakeup();
738 return;
739 }
740
741 void
__firehose_allocate(vm_offset_t * addr,vm_size_t size __unused)742 __firehose_allocate(vm_offset_t *addr, vm_size_t size __unused)
743 {
744 firehose_chunk_t kernel_buffer = (firehose_chunk_t)kernel_firehose_addr;
745
746 if (kernel_firehose_addr) {
747 *addr = kernel_firehose_addr;
748 } else {
749 *addr = 0;
750 return;
751 }
752 // Now that we are done adding logs to this chunk, set the number of writers to 0
753 // Without this, logd won't flush when the page is full
754 firehose_boot_chunk->fc_pos.fcp_refcnt = 0;
755 memcpy(&kernel_buffer[FIREHOSE_BUFFER_KERNEL_CHUNK_COUNT - 1], (const void *)firehose_boot_chunk, FIREHOSE_CHUNK_SIZE);
756 return;
757 }
758 // There isnt a lock held in this case.
759 void
__firehose_critical_region_enter(void)760 __firehose_critical_region_enter(void)
761 {
762 disable_preemption();
763 return;
764 }
765
766 void
__firehose_critical_region_leave(void)767 __firehose_critical_region_leave(void)
768 {
769 enable_preemption();
770 return;
771 }
772
773 #ifdef CONFIG_XNUPOST
774
775 #include <tests/xnupost.h>
776 #define TESTOSLOGFMT(fn_name) "%u^%llu/%llu^kernel^0^test^" fn_name
777 #define TESTOSLOGPFX "TESTLOG:%u#"
778 #define TESTOSLOG(fn_name) TESTOSLOGPFX TESTOSLOGFMT(fn_name "#")
779
780 extern u_int32_t RandomULong(void);
781 extern size_t find_pattern_in_buffer(const char *pattern, size_t len, size_t expected_count);
782 void test_oslog_default_helper(uint32_t uniqid, uint64_t count);
783 void test_oslog_info_helper(uint32_t uniqid, uint64_t count);
784 void test_oslog_debug_helper(uint32_t uniqid, uint64_t count);
785 void test_oslog_error_helper(uint32_t uniqid, uint64_t count);
786 void test_oslog_fault_helper(uint32_t uniqid, uint64_t count);
787 void _test_log_loop(void * arg __unused, wait_result_t wres __unused);
788 void test_oslog_handleOSLogCtl(int32_t * in, int32_t * out, int32_t len);
789 kern_return_t test_stresslog_dropmsg(uint32_t uniqid);
790
791 kern_return_t test_os_log(void);
792 kern_return_t test_os_log_parallel(void);
793
794 #define GENOSLOGHELPER(fname, ident, callout_f) \
795 void fname(uint32_t uniqid, uint64_t count) \
796 { \
797 int32_t datalen = 0; \
798 uint32_t checksum = 0; \
799 char databuffer[256]; \
800 T_LOG("Doing os_log of %llu TESTLOG msgs for fn " ident, count); \
801 for (uint64_t i = 0; i < count; i++) \
802 { \
803 datalen = scnprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT(ident), uniqid, i + 1, count); \
804 checksum = crc32(0, databuffer, datalen); \
805 callout_f(OS_LOG_DEFAULT, TESTOSLOG(ident), checksum, uniqid, i + 1, count); \
806 /*T_LOG(TESTOSLOG(ident), checksum, uniqid, i + 1, count);*/ \
807 } \
808 }
809
810 GENOSLOGHELPER(test_oslog_info_helper, "oslog_info_helper", os_log_info);
811 GENOSLOGHELPER(test_oslog_fault_helper, "oslog_fault_helper", os_log_fault);
812 GENOSLOGHELPER(test_oslog_debug_helper, "oslog_debug_helper", os_log_debug);
813 GENOSLOGHELPER(test_oslog_error_helper, "oslog_error_helper", os_log_error);
814 GENOSLOGHELPER(test_oslog_default_helper, "oslog_default_helper", os_log);
815
816 kern_return_t
test_os_log()817 test_os_log()
818 {
819 __attribute__((uninitialized))
820 char databuffer[256];
821 uint32_t uniqid = RandomULong();
822 size_t match_count = 0;
823 uint32_t checksum = 0;
824 uint32_t total_msg = 0;
825 uint32_t saved_msg = 0;
826 uint32_t dropped_msg = 0;
827 size_t datalen = 0;
828 uint64_t a = mach_absolute_time();
829 uint64_t seqno = 1;
830 uint64_t total_seqno = 2;
831
832 os_log_t log_handle = os_log_create("com.apple.xnu.test.t1", "kpost");
833
834 T_ASSERT_EQ_PTR(&_os_log_default, log_handle, "os_log_create returns valid value.");
835 T_ASSERT_EQ_INT(TRUE, os_log_info_enabled(log_handle), "os_log_info is enabled");
836 T_ASSERT_EQ_INT(TRUE, os_log_debug_enabled(log_handle), "os_log_debug is enabled");
837 T_ASSERT_EQ_PTR(&_os_log_default, OS_LOG_DEFAULT, "ensure OS_LOG_DEFAULT is _os_log_default");
838
839 total_msg = counter_load(&oslog_p_total_msgcount);
840 saved_msg = counter_load(&oslog_p_saved_msgcount);
841 dropped_msg = counter_load(&oslog_p_dropped_msgcount);
842 T_LOG("oslog internal counters total %u , saved %u, dropped %u", total_msg, saved_msg, dropped_msg);
843
844 T_LOG("Validating with uniqid %u u64 %llu", uniqid, a);
845 T_ASSERT_NE_UINT(0, uniqid, "random number should not be zero");
846 T_ASSERT_NE_ULLONG(0, a, "absolute time should not be zero");
847
848 datalen = scnprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT("printf_only"), uniqid, seqno, total_seqno);
849 checksum = crc32(0, databuffer, datalen);
850 printf(TESTOSLOG("printf_only") "mat%llu\n", checksum, uniqid, seqno, total_seqno, a);
851
852 seqno += 1;
853 datalen = scnprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT("printf_only"), uniqid, seqno, total_seqno);
854 checksum = crc32(0, databuffer, datalen);
855 printf(TESTOSLOG("printf_only") "mat%llu\n", checksum, uniqid, seqno, total_seqno, a);
856
857 datalen = scnprintf(databuffer, sizeof(databuffer), "kernel^0^test^printf_only#mat%llu", a);
858 match_count = find_pattern_in_buffer(databuffer, datalen, total_seqno);
859 T_EXPECT_EQ_ULONG(match_count, total_seqno, "verify printf_only goes to systemlog buffer");
860
861 uint32_t logging_config = atm_get_diagnostic_config();
862 T_LOG("checking atm_diagnostic_config 0x%X", logging_config);
863
864 if ((logging_config & ATM_TRACE_OFF) || (logging_config & ATM_TRACE_DISABLE)) {
865 T_LOG("ATM_TRACE_OFF / ATM_TRACE_DISABLE is set. Would not see oslog messages. skipping the rest of test.");
866 return KERN_SUCCESS;
867 }
868
869 /* for enabled logging printfs should be saved in oslog as well */
870 T_EXPECT_GE_UINT((counter_load(&oslog_p_total_msgcount) - total_msg), 2, "atleast 2 msgs should be seen by oslog system");
871
872 a = mach_absolute_time();
873 total_seqno = 1;
874 seqno = 1;
875 total_msg = counter_load(&oslog_p_total_msgcount);
876 saved_msg = counter_load(&oslog_p_saved_msgcount);
877 dropped_msg = counter_load(&oslog_p_dropped_msgcount);
878 datalen = scnprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT("oslog_info"), uniqid, seqno, total_seqno);
879 checksum = crc32(0, databuffer, datalen);
880 os_log_info(log_handle, TESTOSLOG("oslog_info") "mat%llu", checksum, uniqid, seqno, total_seqno, a);
881 T_EXPECT_GE_UINT((counter_load(&oslog_p_total_msgcount) - total_msg), 1, "total message count in buffer");
882
883 datalen = scnprintf(databuffer, sizeof(databuffer), "kernel^0^test^oslog_info#mat%llu", a);
884 match_count = find_pattern_in_buffer(databuffer, datalen, total_seqno);
885 T_EXPECT_EQ_ULONG(match_count, total_seqno, "verify oslog_info does not go to systemlog buffer");
886
887 total_msg = counter_load(&oslog_p_total_msgcount);
888 test_oslog_info_helper(uniqid, 10);
889 T_EXPECT_GE_UINT(counter_load(&oslog_p_total_msgcount) - total_msg, 10, "test_oslog_info_helper: Should have seen 10 msgs");
890
891 total_msg = counter_load(&oslog_p_total_msgcount);
892 test_oslog_debug_helper(uniqid, 10);
893 T_EXPECT_GE_UINT(counter_load(&oslog_p_total_msgcount) - total_msg, 10, "test_oslog_debug_helper:Should have seen 10 msgs");
894
895 total_msg = counter_load(&oslog_p_total_msgcount);
896 test_oslog_error_helper(uniqid, 10);
897 T_EXPECT_GE_UINT(counter_load(&oslog_p_total_msgcount) - total_msg, 10, "test_oslog_error_helper:Should have seen 10 msgs");
898
899 total_msg = counter_load(&oslog_p_total_msgcount);
900 test_oslog_default_helper(uniqid, 10);
901 T_EXPECT_GE_UINT(counter_load(&oslog_p_total_msgcount) - total_msg, 10, "test_oslog_default_helper:Should have seen 10 msgs");
902
903 total_msg = counter_load(&oslog_p_total_msgcount);
904 test_oslog_fault_helper(uniqid, 10);
905 T_EXPECT_GE_UINT(counter_load(&oslog_p_total_msgcount) - total_msg, 10, "test_oslog_fault_helper:Should have seen 10 msgs");
906
907 T_LOG("oslog internal counters total %u , saved %u, dropped %u", counter_load(&oslog_p_total_msgcount), counter_load(&oslog_p_saved_msgcount),
908 counter_load(&oslog_p_dropped_msgcount));
909
910 return KERN_SUCCESS;
911 }
912
913 static uint32_t _test_log_loop_count = 0;
914 void
_test_log_loop(void * arg __unused,wait_result_t wres __unused)915 _test_log_loop(void * arg __unused, wait_result_t wres __unused)
916 {
917 uint32_t uniqid = RandomULong();
918 test_oslog_debug_helper(uniqid, 100);
919 os_atomic_add(&_test_log_loop_count, 100, relaxed);
920 }
921
922 kern_return_t
test_os_log_parallel(void)923 test_os_log_parallel(void)
924 {
925 thread_t thread[2];
926 kern_return_t kr;
927 uint32_t uniqid = RandomULong();
928
929 printf("oslog internal counters total %lld , saved %lld, dropped %lld", counter_load(&oslog_p_total_msgcount), counter_load(&oslog_p_saved_msgcount),
930 counter_load(&oslog_p_dropped_msgcount));
931
932 kr = kernel_thread_start(_test_log_loop, NULL, &thread[0]);
933 T_ASSERT_EQ_INT(kr, KERN_SUCCESS, "kernel_thread_start returned successfully");
934
935 kr = kernel_thread_start(_test_log_loop, NULL, &thread[1]);
936 T_ASSERT_EQ_INT(kr, KERN_SUCCESS, "kernel_thread_start returned successfully");
937
938 test_oslog_info_helper(uniqid, 100);
939
940 /* wait until other thread has also finished */
941 while (_test_log_loop_count < 200) {
942 delay(1000);
943 }
944
945 thread_deallocate(thread[0]);
946 thread_deallocate(thread[1]);
947
948 T_LOG("oslog internal counters total %lld , saved %lld, dropped %lld", counter_load(&oslog_p_total_msgcount), counter_load(&oslog_p_saved_msgcount),
949 counter_load(&oslog_p_dropped_msgcount));
950 T_PASS("parallel_logging tests is now complete");
951
952 return KERN_SUCCESS;
953 }
954
955 void
test_oslog_handleOSLogCtl(int32_t * in,int32_t * out,int32_t len)956 test_oslog_handleOSLogCtl(int32_t * in, int32_t * out, int32_t len)
957 {
958 if (!in || !out || len != 4) {
959 return;
960 }
961 switch (in[0]) {
962 case 1:
963 {
964 /* send out counters */
965 out[1] = counter_load(&oslog_p_total_msgcount);
966 out[2] = counter_load(&oslog_p_saved_msgcount);
967 out[3] = counter_load(&oslog_p_dropped_msgcount);
968 out[0] = KERN_SUCCESS;
969 break;
970 }
971 case 2:
972 {
973 /* mini stress run */
974 out[0] = test_os_log_parallel();
975 break;
976 }
977 case 3:
978 {
979 /* drop msg tests */
980 out[1] = RandomULong();
981 out[0] = test_stresslog_dropmsg(out[1]);
982 break;
983 }
984 case 4:
985 {
986 /* invoke log helpers */
987 uint32_t uniqid = in[3];
988 int32_t msgcount = in[2];
989 if (uniqid == 0 || msgcount == 0) {
990 out[0] = KERN_INVALID_VALUE;
991 return;
992 }
993
994 switch (in[1]) {
995 case OS_LOG_TYPE_INFO: test_oslog_info_helper(uniqid, msgcount); break;
996 case OS_LOG_TYPE_DEBUG: test_oslog_debug_helper(uniqid, msgcount); break;
997 case OS_LOG_TYPE_ERROR: test_oslog_error_helper(uniqid, msgcount); break;
998 case OS_LOG_TYPE_FAULT: test_oslog_fault_helper(uniqid, msgcount); break;
999 case OS_LOG_TYPE_DEFAULT:
1000 default: test_oslog_default_helper(uniqid, msgcount); break;
1001 }
1002 out[0] = KERN_SUCCESS;
1003 break;
1004 /* end of case 4 */
1005 }
1006 default:
1007 {
1008 out[0] = KERN_INVALID_VALUE;
1009 break;
1010 }
1011 }
1012 return;
1013 }
1014
1015 kern_return_t
test_stresslog_dropmsg(uint32_t uniqid)1016 test_stresslog_dropmsg(uint32_t uniqid)
1017 {
1018 uint32_t total, saved, dropped;
1019 total = counter_load(&oslog_p_total_msgcount);
1020 saved = counter_load(&oslog_p_saved_msgcount);
1021 dropped = counter_load(&oslog_p_dropped_msgcount);
1022 uniqid = RandomULong();
1023 test_oslog_debug_helper(uniqid, 100);
1024 while ((counter_load(&oslog_p_dropped_msgcount) - dropped) == 0) {
1025 test_oslog_debug_helper(uniqid, 100);
1026 }
1027 printf("test_stresslog_dropmsg: logged %lld msgs, saved %lld and caused a drop of %lld msgs. \n", counter_load(&oslog_p_total_msgcount) - total,
1028 counter_load(&oslog_p_saved_msgcount) - saved, counter_load(&oslog_p_dropped_msgcount) - dropped);
1029 return KERN_SUCCESS;
1030 }
1031
1032 #endif
1033