1/*
2 * Copyright (c) 2019-2023 Apple Inc. All rights reserved.
3 */
4
5#undef offset
6
7#include <kern/cpu_data.h>
8#include <os/base.h>
9#include <os/hash.h>
10#include <os/object.h>
11#include <os/log.h>
12#include <stdbool.h>
13#include <stddef.h>
14#include <stdint.h>
15
16#include <vm/vm_kern.h>
17#include <mach/vm_statistics.h>
18#include <kern/debug.h>
19#include <libkern/libkern.h>
20#include <libkern/kernel_mach_header.h>
21#include <pexpert/pexpert.h>
22#include <uuid/uuid.h>
23#include <sys/msgbuf.h>
24
25#include <mach/mach_time.h>
26#include <kern/thread.h>
27#include <kern/simple_lock.h>
28#include <kern/kalloc.h>
29#include <kern/clock.h>
30#include <kern/assert.h>
31#include <kern/smr_hash.h>
32#include <kern/startup.h>
33#include <kern/task.h>
34
35#include <firehose/firehose_types_private.h>
36#include <firehose/tracepoint_private.h>
37#include <firehose/chunk_private.h>
38#include <os/firehose_buffer_private.h>
39#include <os/firehose.h>
40#include <os/log_private.h>
41
42#include "log_encode.h"
43#include "log_internal.h"
44#include "log_mem.h"
45#include "log_queue.h"
46#include "trace_internal.h"
47
48#define OS_LOGMEM_BUF_ORDER 14
49#define OS_LOGMEM_MIN_LOG_ORDER 9
50#define OS_LOGMEM_MAX_LOG_ORDER (OS_LOG_MAX_SIZE_ORDER)
51
52#define OS_LOG_SUBSYSTEM_MAX_CNT 1024
53#define OS_LOG_SUBSYSTEM_NONE 0xffff
54#define OS_LOG_SUBSYSTEM_BASE 0x0001 // OS_LOG_DEFAULT takes 0 by definition
55#define OS_LOG_SUBSYSTEM_LAST (OS_LOG_SUBSYSTEM_BASE + OS_LOG_SUBSYSTEM_MAX_CNT)
56#define OS_LOG_SUBSYSTEM_NAME_MAX_LEN 128
57
58/*
59 * OSLog subsystem type. The struct layout matches its libtrace counterpart
60 * and also matches what libtrace (logd) expects from subsystem registration
61 * metadata payload.
62 */
63struct os_log_subsystem_s {
64 uint16_t ols_id;
65 union {
66 struct {
67 uint8_t ols_sub_size;
68 uint8_t ols_cat_size;
69 };
70 uint16_t ols_sizes;
71 };
72 char ols_name[2 * OS_LOG_SUBSYSTEM_NAME_MAX_LEN];
73};
74
75struct os_log_s {
76 struct os_log_subsystem_s ol_subsystem;
77 struct smrq_slink ol_hash_link;
78};
79
80struct os_log_s _os_log_default;
81struct os_log_s _os_log_replay;
82
83/* Counters for persistence mode */
84SCALABLE_COUNTER_DEFINE(oslog_p_total_msgcount);
85SCALABLE_COUNTER_DEFINE(oslog_p_metadata_saved_msgcount);
86SCALABLE_COUNTER_DEFINE(oslog_p_metadata_dropped_msgcount);
87SCALABLE_COUNTER_DEFINE(oslog_p_signpost_saved_msgcount);
88SCALABLE_COUNTER_DEFINE(oslog_p_signpost_dropped_msgcount);
89SCALABLE_COUNTER_DEFINE(oslog_p_error_count);
90SCALABLE_COUNTER_DEFINE(oslog_p_saved_msgcount);
91SCALABLE_COUNTER_DEFINE(oslog_p_dropped_msgcount);
92SCALABLE_COUNTER_DEFINE(oslog_p_boot_dropped_msgcount);
93SCALABLE_COUNTER_DEFINE(oslog_p_coprocessor_total_msgcount);
94SCALABLE_COUNTER_DEFINE(oslog_p_coprocessor_dropped_msgcount);
95SCALABLE_COUNTER_DEFINE(oslog_p_unresolved_kc_msgcount);
96
97/* Counters for msgbuf logging */
98SCALABLE_COUNTER_DEFINE(oslog_msgbuf_msgcount)
99SCALABLE_COUNTER_DEFINE(oslog_msgbuf_dropped_msgcount)
100
101/* Log subsystem counters */
102SCALABLE_COUNTER_DEFINE(oslog_subsystem_count);
103SCALABLE_COUNTER_DEFINE(oslog_subsystem_found);
104SCALABLE_COUNTER_DEFINE(oslog_subsystem_dropped);
105
106LCK_GRP_DECLARE(oslog_cache_lock_grp, "oslog_cache_lock_grp");
107LCK_TICKET_DECLARE(oslog_cache_lock, &oslog_cache_lock_grp);
108
109static bool oslog_boot_done = false;
110static SECURITY_READ_ONLY_LATE(bool) oslog_disabled = false;
111
112static uint16_t os_log_subsystem_id = OS_LOG_SUBSYSTEM_BASE;
113
114static struct logmem_s os_log_mem;
115static struct smr_hash os_log_cache;
116
117static struct firehose_chunk_s firehose_boot_chunk = {
118 .fc_pos = {
119 .fcp_next_entry_offs = offsetof(struct firehose_chunk_s, fc_data),
120 .fcp_private_offs = FIREHOSE_CHUNK_SIZE,
121 .fcp_refcnt = 1, // Indicate that there is a writer to this chunk
122 .fcp_stream = firehose_stream_persist,
123 .fcp_flag_io = 1, // Lets assume this is coming from the io bank
124 },
125};
126
127bool os_log_disabled(void);
128
129extern vm_offset_t kernel_firehose_addr;
130extern bool bsd_log_lock(bool);
131extern void bsd_log_unlock(void);
132extern void logwakeup(void);
133extern void oslog_stream(bool, firehose_tracepoint_id_u, uint64_t, const void *, size_t);
134extern void *OSKextKextForAddress(const void *);
135
136static bool
137os_log_safe(void)
138{
139 return oslog_is_safe() || startup_phase < STARTUP_SUB_EARLY_BOOT;
140}
141
142static bool
143os_log_turned_off(void)
144{
145 return oslog_disabled || (atm_get_diagnostic_config() & ATM_TRACE_OFF);
146}
147
148bool
149os_log_info_enabled(os_log_t log __unused)
150{
151 return !os_log_turned_off();
152}
153
154bool
155os_log_debug_enabled(os_log_t log __unused)
156{
157 return !os_log_turned_off();
158}
159
160bool
161os_log_disabled(void)
162{
163 return oslog_disabled;
164}
165
166static inline size_t
167log_payload_priv_data_size(const log_payload_s *lp)
168{
169 assert3u(lp->lp_pub_data_size, <=, lp->lp_data_size);
170 return lp->lp_data_size - lp->lp_pub_data_size;
171}
172
173static inline const uint8_t *
174log_payload_priv_data(const log_payload_s *lp, const uint8_t *lp_data)
175{
176 if (log_payload_priv_data_size(lp) == 0) {
177 return NULL;
178 }
179 return &lp_data[lp->lp_pub_data_size];
180}
181
182static void
183log_payload_init(log_payload_t lp, firehose_stream_t stream, firehose_tracepoint_id_u ftid,
184 uint64_t timestamp, size_t data_size, size_t pub_data_size)
185{
186 assert3u(pub_data_size, <=, data_size);
187 assert3u(data_size, <, UINT16_MAX);
188
189 lp->lp_stream = stream;
190 lp->lp_ftid = ftid;
191 lp->lp_timestamp = timestamp;
192 lp->lp_pub_data_size = (uint16_t)pub_data_size;
193 lp->lp_data_size = (uint16_t)data_size;
194}
195
196static firehose_stream_t
197firehose_stream(os_log_type_t type)
198{
199 return (type == OS_LOG_TYPE_INFO || type == OS_LOG_TYPE_DEBUG) ?
200 firehose_stream_memory : firehose_stream_persist;
201}
202
203static firehose_tracepoint_id_t
204firehose_ftid(os_log_type_t type, const char *fmt, firehose_tracepoint_flags_t flags,
205 void *dso, void *addr, bool driverKit)
206{
207 uint32_t off;
208
209 if (driverKit) {
210 /*
211 * Set FIREHOSE_TRACEPOINT_PC_DYNAMIC_BIT so logd will not try
212 * to find the format string in the executable text.
213 */
214 off = (uint32_t)((uintptr_t)addr | FIREHOSE_TRACEPOINT_PC_DYNAMIC_BIT);
215 } else {
216 off = _os_trace_offset(dso, addr: fmt, flags: (_firehose_tracepoint_flags_activity_t)flags);
217 }
218
219 return FIREHOSE_TRACE_ID_MAKE(firehose_tracepoint_namespace_log, type, flags, off);
220}
221
222static firehose_tracepoint_flags_t
223firehose_ftid_flags(const void *dso, bool driverKit)
224{
225 kc_format_t kcformat = KCFormatUnknown;
226 __assert_only bool result = PE_get_primary_kc_format(type: &kcformat);
227 assert(result);
228
229 if (kcformat == KCFormatStatic || kcformat == KCFormatKCGEN) {
230 return _firehose_tracepoint_flags_pc_style_shared_cache;
231 }
232
233 /*
234 * driverKit will have the dso set as MH_EXECUTE (it is logging from a
235 * syscall in the kernel) but needs logd to parse the address as an
236 * absolute pc.
237 */
238 const kernel_mach_header_t *mh = dso;
239 if (mh->filetype == MH_EXECUTE && !driverKit) {
240 return _firehose_tracepoint_flags_pc_style_main_exe;
241 }
242
243 return _firehose_tracepoint_flags_pc_style_absolute;
244}
245
246static void *
247resolve_dso(const char *fmt, void *dso, void *addr, bool driverKit)
248{
249 kc_format_t kcformat = KCFormatUnknown;
250
251 if (!addr || !PE_get_primary_kc_format(type: &kcformat)) {
252 return NULL;
253 }
254
255 switch (kcformat) {
256 case KCFormatStatic:
257 case KCFormatKCGEN:
258 dso = PE_get_kc_baseaddress(type: KCKindPrimary);
259 break;
260 case KCFormatDynamic:
261 case KCFormatFileset:
262 if (!dso && (dso = (void *)OSKextKextForAddress(fmt)) == NULL) {
263 return NULL;
264 }
265 if (!_os_trace_addr_in_text_segment(dso, addr: fmt)) {
266 return NULL;
267 }
268 if (!driverKit && (dso != (void *)OSKextKextForAddress(addr))) {
269 return NULL;
270 }
271 break;
272 default:
273 panic("unknown KC format type");
274 }
275
276 return dso;
277}
278
279static inline uintptr_t
280resolve_location(firehose_tracepoint_flags_t flags, uintptr_t dso, uintptr_t addr,
281 bool driverKit, size_t *loc_size)
282{
283 switch (flags & _firehose_tracepoint_flags_pc_style_mask) {
284 case _firehose_tracepoint_flags_pc_style_shared_cache:
285 case _firehose_tracepoint_flags_pc_style_main_exe:
286 *loc_size = sizeof(uint32_t);
287 return addr - dso;
288 case _firehose_tracepoint_flags_pc_style_absolute:
289 *loc_size = sizeof(uintptr_t);
290 return driverKit ? addr : VM_KERNEL_UNSLIDE(addr);
291 default:
292 panic("Unknown firehose tracepoint flags %x", flags);
293 }
294}
295
296__startup_func
297static void
298oslog_init(void)
299{
300 /*
301 * Disable kernel logging if ATM_TRACE_DISABLE set. ATM_TRACE_DISABLE
302 * bit is not supposed to change during a system run but nothing really
303 * prevents userspace from unintentionally doing so => we stash initial
304 * value in a dedicated variable for a later reference, just in case.
305 */
306 oslog_disabled = atm_get_diagnostic_config() & ATM_TRACE_DISABLE;
307
308 if (!oslog_disabled) {
309 smr_hash_init(smrh: &os_log_cache, OS_LOG_SUBSYSTEM_MAX_CNT / 4);
310 }
311}
312STARTUP(OSLOG, STARTUP_RANK_FIRST, oslog_init);
313
314__startup_func
315static void
316oslog_init_logmem(void)
317{
318 if (os_log_disabled()) {
319 printf("Long logs support disabled: Logging disabled by ATM\n");
320 return;
321 }
322
323 const size_t logmem_size = logmem_required_size(OS_LOGMEM_BUF_ORDER, OS_LOGMEM_MIN_LOG_ORDER);
324 vm_offset_t addr;
325
326 if (kmem_alloc(map: kernel_map, addrp: &addr, size: logmem_size + ptoa(2),
327 flags: KMA_KOBJECT | KMA_PERMANENT | KMA_ZERO | KMA_GUARD_FIRST | KMA_GUARD_LAST,
328 VM_KERN_MEMORY_LOG) == KERN_SUCCESS) {
329 logmem_init(&os_log_mem, (void *)(addr + PAGE_SIZE), logmem_size,
330 OS_LOGMEM_BUF_ORDER, OS_LOGMEM_MIN_LOG_ORDER, OS_LOGMEM_MAX_LOG_ORDER);
331 printf("Long logs support configured: size: %u\n", os_log_mem.lm_cnt_free);
332 } else {
333 printf("Long logs support disabled: Not enough memory\n");
334 }
335}
336STARTUP(OSLOG, STARTUP_RANK_SECOND, oslog_init_logmem);
337
338bool
339os_log_encoded_metadata(firehose_tracepoint_id_u ftid, uint64_t ts, const void *msg,
340 size_t msg_size)
341{
342 assert(ftid.ftid._namespace == firehose_tracepoint_namespace_metadata);
343 counter_inc(&oslog_p_total_msgcount);
344
345 if (!os_log_safe() || os_log_disabled()) {
346 counter_inc(&oslog_p_metadata_dropped_msgcount);
347 return false;
348 }
349
350 log_payload_s log;
351 log_payload_init(lp: &log, stream: firehose_stream_metadata, ftid, timestamp: ts, data_size: msg_size, pub_data_size: msg_size);
352
353 if (log_queue_log(&log, msg, true)) {
354 return true;
355 }
356
357 counter_inc(&oslog_p_metadata_dropped_msgcount);
358 return false;
359}
360
361bool
362os_log_encoded_log(firehose_tracepoint_id_u ftid, uint64_t ts, const void *msg,
363 size_t msg_size, size_t pub_data_size)
364{
365 assert(ftid.ftid._namespace == firehose_tracepoint_namespace_log);
366 counter_inc(&oslog_p_total_msgcount);
367
368 if (!os_log_safe() || os_log_disabled()) {
369 counter_inc(&oslog_p_dropped_msgcount);
370 return false;
371 }
372
373 firehose_stream_t stream = firehose_stream(type: ftid.ftid._type);
374
375 log_payload_s log;
376 log_payload_init(lp: &log, stream, ftid, timestamp: ts, data_size: msg_size, pub_data_size);
377
378 if (log_queue_log(&log, msg, true)) {
379 return true;
380 }
381
382 counter_inc(&oslog_p_dropped_msgcount);
383 return false;
384}
385
386bool
387os_log_encoded_signpost(firehose_tracepoint_id_u ftid, uint64_t ts, const void *msg,
388 size_t msg_size, size_t pub_data_size)
389{
390 assert(ftid.ftid._namespace == firehose_tracepoint_namespace_signpost);
391 counter_inc(&oslog_p_total_msgcount);
392
393 if (!os_log_safe() || os_log_disabled()) {
394 counter_inc(&oslog_p_signpost_dropped_msgcount);
395 return false;
396 }
397
398 log_payload_s log;
399 log_payload_init(lp: &log, stream: firehose_stream_signpost, ftid, timestamp: ts, data_size: msg_size, pub_data_size);
400
401 if (log_queue_log(&log, msg, true)) {
402 return true;
403 }
404
405 counter_inc(&oslog_p_signpost_dropped_msgcount);
406 return false;
407}
408
409static inline size_t
410os_log_subsystem_name_size(const char *name)
411{
412 return MIN(strlen(name) + 1, OS_LOG_SUBSYSTEM_NAME_MAX_LEN);
413}
414
415bool
416os_log_subsystem_id_valid(uint16_t sid)
417{
418 return sid >= OS_LOG_SUBSYSTEM_BASE && sid <= os_log_subsystem_id;
419}
420
421static inline size_t
422os_log_subsystem_id_length(const struct os_log_subsystem_s *sub)
423{
424 return sub->ols_sub_size + sub->ols_cat_size;
425}
426
427static inline size_t
428os_log_subsystem_size(const struct os_log_subsystem_s *tbs)
429{
430 assert(tbs->ols_sub_size <= OS_LOG_SUBSYSTEM_NAME_MAX_LEN);
431 assert(tbs->ols_cat_size <= OS_LOG_SUBSYSTEM_NAME_MAX_LEN);
432 return sizeof(*tbs) - sizeof(tbs->ols_name) + os_log_subsystem_id_length(sub: tbs);
433}
434
435static void
436os_log_subsystem_init(struct os_log_subsystem_s *ols, uint16_t sid, const char *sub, const char *cat)
437{
438 ols->ols_sub_size = os_log_subsystem_name_size(name: sub);
439 ols->ols_cat_size = os_log_subsystem_name_size(name: cat);
440 strlcpy(dst: &ols->ols_name[0], src: sub, OS_LOG_SUBSYSTEM_NAME_MAX_LEN);
441 strlcpy(dst: &ols->ols_name[ols->ols_sub_size], src: cat, OS_LOG_SUBSYSTEM_NAME_MAX_LEN);
442 ols->ols_id = sid;
443}
444
445static void
446os_log_subsystem_register(const struct os_log_subsystem_s *ols, uint64_t stamp)
447{
448 assert(os_log_subsystem_id_valid(ols->ols_id));
449
450 firehose_tracepoint_id_u trace_id;
451 trace_id.ftid_value = FIREHOSE_TRACE_ID_MAKE(firehose_tracepoint_namespace_metadata,
452 _firehose_tracepoint_type_metadata_subsystem, 0, ols->ols_id);
453
454 os_log_encoded_metadata(ftid: trace_id, ts: stamp, msg: ols, msg_size: os_log_subsystem_size(tbs: ols));
455}
456
457#if DEVELOPMENT || DEBUG
458static bool
459os_log_valid(const struct os_log_s *log)
460{
461 return os_log_subsystem_id_valid(log->ol_subsystem.ols_id);
462}
463#endif // DEVELOPMENT || DEBUG
464
465static smrh_key_t
466os_log_key(const struct os_log_subsystem_s *sub)
467{
468 return (smrh_key_t) {
469 .smrk_opaque = sub->ols_name,
470 .smrk_len = os_log_subsystem_id_length(sub)
471 };
472}
473
474static uint32_t
475os_log_key_hash(smrh_key_t key, uint32_t seed)
476{
477 return smrh_key_hash_mem(key, seed);
478}
479
480static bool
481os_log_key_equ(smrh_key_t k1, smrh_key_t k2)
482{
483 return k1.smrk_len == k2.smrk_len ? smrh_key_equ_mem(k1, k2) : false;
484}
485
486static uint32_t
487os_log_hash(const struct smrq_slink *link, uint32_t seed)
488{
489 const os_log_t log = __container_of(link, struct os_log_s, ol_hash_link);
490 return os_log_key_hash(key: os_log_key(sub: &log->ol_subsystem), seed);
491}
492
493static bool
494os_log_equ(const struct smrq_slink *link, smrh_key_t key)
495{
496 const os_log_t h = __container_of(link, struct os_log_s, ol_hash_link);
497 return os_log_key_equ(k1: os_log_key(sub: &h->ol_subsystem), k2: key);
498}
499
500static bool
501oslog_try_get(void *oslog __unused)
502{
503 return true;
504}
505
506SMRH_TRAITS_DEFINE(os_log_cache_traits, struct os_log_s, ol_hash_link,
507 .domain = &smr_oslog,
508 .key_hash = os_log_key_hash,
509 .key_equ = os_log_key_equ,
510 .obj_hash = os_log_hash,
511 .obj_equ = os_log_equ,
512 .obj_try_get = oslog_try_get
513 );
514
515static os_log_t
516os_log_cache_find_by_sub(const struct os_log_subsystem_s *sub)
517{
518 os_log_t log = smr_hash_get(&os_log_cache, os_log_key(sub), &os_log_cache_traits);
519 assert(!log || os_log_valid(log));
520 return log;
521}
522
523static os_log_t
524os_log_cache_insert(os_log_t log)
525{
526 assert(os_log_subsystem_id_valid(log->ol_subsystem.ols_id));
527
528 os_log_t found = smr_hash_serialized_get_or_insert(&os_log_cache,
529 os_log_key(&log->ol_subsystem), &log->ol_hash_link,
530 &os_log_cache_traits);
531 assert(!found || os_log_valid(found));
532 return found;
533}
534
535static os_log_t
536os_log_allocate(const struct os_log_subsystem_s *subsystem)
537{
538 os_log_t new = kalloc_type(struct os_log_s, Z_WAITOK_ZERO);
539 if (new) {
540 new->ol_subsystem = *subsystem;
541 }
542 return new;
543}
544
545static uint16_t
546os_log_subsystem_id_next(void)
547{
548 assert(os_log_subsystem_id_valid(os_log_subsystem_id));
549
550 if (__improbable(os_log_subsystem_id == OS_LOG_SUBSYSTEM_LAST)) {
551 return OS_LOG_SUBSYSTEM_NONE;
552 }
553 return os_log_subsystem_id++;
554}
555
556static void
557os_log_subsystem_id_revert(uint16_t __assert_only sid)
558{
559 assert(os_log_subsystem_id_valid(os_log_subsystem_id));
560 assert3u(os_log_subsystem_id, ==, sid + 1);
561 os_log_subsystem_id--;
562}
563
564static os_log_t
565os_log_create_impl(const char *subsystem, const char *category, uint64_t stamp)
566{
567 if (os_log_disabled()) {
568 return OS_LOG_DISABLED;
569 }
570
571 struct os_log_subsystem_s new_sub;
572 os_log_subsystem_init(ols: &new_sub, OS_LOG_SUBSYSTEM_NONE, sub: subsystem, cat: category);
573
574 os_log_t log = os_log_cache_find_by_sub(sub: &new_sub);
575 if (log) {
576 counter_inc(&oslog_subsystem_found);
577 return log;
578 }
579
580 if (!(log = os_log_allocate(subsystem: &new_sub))) {
581 counter_inc(&oslog_subsystem_dropped);
582 return OS_LOG_DEFAULT;
583 }
584
585 lck_ticket_lock(tlock: &oslog_cache_lock, grp: &oslog_cache_lock_grp);
586
587 log->ol_subsystem.ols_id = os_log_subsystem_id_next();
588 if (__improbable(log->ol_subsystem.ols_id == OS_LOG_SUBSYSTEM_NONE)) {
589 lck_ticket_unlock(tlock: &oslog_cache_lock);
590 kfree_type(struct os_log_s, log);
591 counter_inc(&oslog_subsystem_dropped);
592 return OS_LOG_DEFAULT;
593 }
594
595 os_log_t found = os_log_cache_insert(log);
596 if (__improbable(found)) {
597 os_log_subsystem_id_revert(sid: log->ol_subsystem.ols_id);
598 lck_ticket_unlock(tlock: &oslog_cache_lock);
599 kfree_type(struct os_log_s, log);
600 counter_inc(&oslog_subsystem_found);
601 return found;
602 }
603
604 lck_ticket_unlock(tlock: &oslog_cache_lock);
605
606 os_log_subsystem_register(ols: &log->ol_subsystem, stamp);
607 counter_inc(&oslog_subsystem_count);
608
609 return log;
610}
611
612os_log_t
613os_log_create(const char *subsystem, const char *category)
614{
615 uint64_t stamp = firehose_tracepoint_time(flags: firehose_activity_flags_default);
616 return os_log_create_impl(subsystem, category, stamp);
617}
618
619static void
620_os_log_to_msgbuf_internal(const char *format, va_list args, uint64_t timestamp,
621 bool safe, bool logging, bool addcr)
622{
623 /*
624 * The following threshold was determined empirically as the point where
625 * it would be more advantageous to be able to fit in more log lines than
626 * to know exactly when a log line was printed out. We don't want to use up
627 * a large percentage of the log buffer on timestamps in a memory-constricted
628 * environment.
629 */
630 const int MSGBUF_TIMESTAMP_THRESHOLD = 4096;
631 static int msgbufreplay = -1;
632 static bool newlogline = true;
633 va_list args_copy;
634
635 if (!bsd_log_lock(safe)) {
636 counter_inc(&oslog_msgbuf_dropped_msgcount);
637 return;
638 }
639
640 if (!safe) {
641 if (-1 == msgbufreplay) {
642 msgbufreplay = msgbufp->msg_bufx;
643 }
644 } else if (logging && (-1 != msgbufreplay)) {
645 uint32_t i;
646 uint32_t localbuff_size;
647 int newl, position;
648 char *localbuff, *p, *s, *next, ch;
649
650 position = msgbufreplay;
651 msgbufreplay = -1;
652 localbuff_size = (msgbufp->msg_size + 2); /* + '\n' + '\0' */
653 /* Size for non-blocking */
654 if (localbuff_size > 4096) {
655 localbuff_size = 4096;
656 }
657 bsd_log_unlock();
658 /* Allocate a temporary non-circular buffer */
659 localbuff = kalloc_data(localbuff_size, Z_NOWAIT);
660 if (localbuff != NULL) {
661 /* in between here, the log could become bigger, but that's fine */
662 bsd_log_lock(true);
663 /*
664 * The message buffer is circular; start at the replay pointer, and
665 * make one loop up to write pointer - 1.
666 */
667 p = msgbufp->msg_bufc + position;
668 for (i = newl = 0; p != msgbufp->msg_bufc + msgbufp->msg_bufx - 1; ++p) {
669 if (p >= msgbufp->msg_bufc + msgbufp->msg_size) {
670 p = msgbufp->msg_bufc;
671 }
672 ch = *p;
673 if (ch == '\0') {
674 continue;
675 }
676 newl = (ch == '\n');
677 localbuff[i++] = ch;
678 if (i >= (localbuff_size - 2)) {
679 break;
680 }
681 }
682 bsd_log_unlock();
683
684 if (!newl) {
685 localbuff[i++] = '\n';
686 }
687 localbuff[i++] = 0;
688
689 s = localbuff;
690 while ((next = strchr(s, c: '\n'))) {
691 next++;
692 ch = next[0];
693 next[0] = 0;
694 os_log(&_os_log_replay, "%s", s);
695 next[0] = ch;
696 s = next;
697 }
698 kfree_data(localbuff, localbuff_size);
699 }
700 bsd_log_lock(true);
701 }
702
703 /* Do not prepend timestamps when we are memory-constricted */
704 if (newlogline && (msgbufp->msg_size > MSGBUF_TIMESTAMP_THRESHOLD)) {
705 clock_sec_t secs;
706 clock_usec_t microsecs;
707 absolutetime_to_microtime(abstime: timestamp, secs: &secs, microsecs: &microsecs);
708 printf_log_locked(FALSE, "[%5lu.%06u]: ", (unsigned long)secs, microsecs);
709 }
710
711#pragma clang diagnostic push
712#pragma clang diagnostic ignored "-Wformat-nonliteral"
713 va_copy(args_copy, args);
714 newlogline = vprintf_log_locked(format, args_copy, driverkit: addcr);
715 va_end(args_copy);
716#pragma clang diagnostic pop
717
718 bsd_log_unlock();
719 logwakeup();
720 counter_inc(&oslog_msgbuf_msgcount);
721}
722
723static void
724_os_log_to_log_internal(uint16_t sid, os_log_type_t type, const char *fmt, va_list args,
725 uint64_t ts, void *addr, void *dso, bool driverKit)
726{
727 dso = resolve_dso(fmt, dso, addr, driverKit);
728 if (__improbable(!dso)) {
729 counter_inc(&oslog_p_unresolved_kc_msgcount);
730 return;
731 }
732
733 firehose_tracepoint_flags_t flags = firehose_ftid_flags(dso, driverKit);
734 if (sid != 0) {
735 flags |= _firehose_tracepoint_flags_log_has_subsystem;
736 }
737
738 size_t loc_sz = 0;
739 uintptr_t loc = resolve_location(flags, dso: (uintptr_t)dso, addr: (uintptr_t)addr,
740 driverKit, loc_size: &loc_sz);
741
742 firehose_tracepoint_id_u ftid = {
743 .ftid_value = firehose_ftid(type, fmt, flags, dso, addr, driverKit)
744 };
745
746 __attribute__((uninitialized, aligned(8)))
747 uint8_t buffer[OS_LOG_BUFFER_MAX_SIZE];
748 struct os_log_context_s ctx;
749
750 os_log_context_init(&ctx, &os_log_mem, buffer, sizeof(buffer));
751
752 if (!os_log_context_encode(&ctx, fmt, args, loc, loc_sz, sid)) {
753 counter_inc(&oslog_p_error_count);
754 os_log_context_free(&ctx);
755 return;
756 }
757
758 log_payload_s log;
759 log_payload_init(lp: &log, stream: firehose_stream(type), ftid, timestamp: ts, data_size: ctx.ctx_content_sz, pub_data_size: ctx.ctx_content_sz);
760
761 if (!log_queue_log(&log, ctx.ctx_buffer, true)) {
762 counter_inc(&oslog_p_dropped_msgcount);
763 }
764
765 os_log_context_free(&ctx);
766}
767
768static void
769_os_log_with_args_internal(os_log_t oslog, os_log_type_t type, const char *fmt,
770 va_list args, uint64_t ts, void *addr, void *dso, bool driverKit, bool addcr)
771{
772 counter_inc(&oslog_p_total_msgcount);
773
774 if (oslog == OS_LOG_DISABLED) {
775 counter_inc(&oslog_p_dropped_msgcount);
776 return;
777 }
778
779 if (__improbable(fmt[0] == '\0')) {
780 counter_inc(&oslog_p_error_count);
781 return;
782 }
783
784 /* early boot can log to dmesg for later replay (27307943) */
785 bool safe = os_log_safe();
786 bool logging = !os_log_turned_off();
787
788 if (oslog != &_os_log_replay) {
789 _os_log_to_msgbuf_internal(format: fmt, args, timestamp: ts, safe, logging, addcr);
790 }
791
792 if (safe && logging) {
793 const uint16_t sid = oslog->ol_subsystem.ols_id;
794 _os_log_to_log_internal(sid, type, fmt, args, ts, addr, dso, driverKit);
795 }
796}
797
798__attribute__((noinline, not_tail_called)) void
799_os_log_internal(void *dso, os_log_t log, uint8_t type, const char *fmt, ...)
800{
801 uint64_t ts = firehose_tracepoint_time(flags: firehose_activity_flags_default);
802 void *addr = __builtin_return_address(0);
803 va_list args;
804
805 va_start(args, fmt);
806 _os_log_with_args_internal(oslog: log, type, fmt, args, ts, addr, dso, FALSE, FALSE);
807 va_end(args);
808}
809
810__attribute__((noinline, not_tail_called)) void
811_os_log_at_time(void *dso, os_log_t log, uint8_t type, uint64_t ts, const char *fmt, ...)
812{
813 void *addr = __builtin_return_address(0);
814 va_list args;
815
816 va_start(args, fmt);
817 _os_log_with_args_internal(oslog: log, type, fmt, args, ts, addr, dso, FALSE, FALSE);
818 va_end(args);
819}
820
821__attribute__((noinline, not_tail_called)) int
822_os_log_internal_driverKit(void *dso, os_log_t log, uint8_t type, const char *fmt, ...)
823{
824 uint64_t ts = firehose_tracepoint_time(flags: firehose_activity_flags_default);
825 void *addr = __builtin_return_address(0);
826 bool driverKitLog = FALSE;
827 va_list args;
828
829 /*
830 * We want to be able to identify dexts from the logs.
831 *
832 * Usually the addr is used to understand if the log line
833 * was generated by a kext or the kernel main executable.
834 * Logd uses copyKextUUIDForAddress with the addr specified
835 * in the log line to retrieve the kext UUID of the sender.
836 *
837 * Dext however are not loaded in kernel space so they do not
838 * have a kernel range of addresses.
839 *
840 * To make the same mechanism work, OSKext fakes a kernel
841 * address range for dexts using the loadTag,
842 * so we just need to use the loadTag as addr here
843 * to allow logd to retrieve the correct UUID.
844 *
845 * NOTE: loadTag is populated in the task when the dext is matching,
846 * so if log lines are generated before the matching they will be
847 * identified as kernel main executable.
848 */
849 task_t self_task = current_task();
850
851 /*
852 * Only dexts are supposed to use this log path. Verified in log_data()
853 * but worth of another check here in case this function gets called
854 * directly.
855 */
856 if (!task_is_driver(task: self_task)) {
857 return EPERM;
858 }
859
860 uint64_t loadTag = get_task_loadTag(task: self_task);
861 if (loadTag != 0) {
862 driverKitLog = TRUE;
863 addr = (void *)loadTag;
864 }
865
866 va_start(args, fmt);
867 _os_log_with_args_internal(oslog: log, type, fmt, args, ts, addr, dso, driverKit: driverKitLog, true);
868 va_end(args);
869
870 return 0;
871}
872
873__attribute__((noinline, not_tail_called)) void
874os_log_with_args(os_log_t oslog, os_log_type_t type, const char *fmt,
875 va_list args, void *addr)
876{
877 uint64_t ts = firehose_tracepoint_time(flags: firehose_activity_flags_default);
878
879 // if no address passed, look it up
880 if (addr == NULL) {
881 addr = __builtin_return_address(0);
882 }
883
884 _os_log_with_args_internal(oslog, type, fmt, args, ts, addr, NULL, FALSE, FALSE);
885}
886
887bool
888os_log_coprocessor(void *buff, uint64_t buff_len, os_log_type_t type,
889 const char *uuid, uint64_t timestamp, uint32_t offset, bool stream_log)
890{
891 counter_inc(&oslog_p_coprocessor_total_msgcount);
892
893 if (os_log_turned_off() || !os_log_safe()) {
894 counter_inc(&oslog_p_coprocessor_dropped_msgcount);
895 return false;
896 }
897
898 if (buff_len + 16 + sizeof(uint32_t) > OS_LOG_BUFFER_MAX_SIZE) {
899 counter_inc(&oslog_p_coprocessor_dropped_msgcount);
900 return false;
901 }
902
903 __attribute__((uninitialized))
904 uint8_t pubdata[OS_LOG_BUFFER_MAX_SIZE];
905 size_t wr_pos = 0;
906
907 memcpy(dst: pubdata, src: &offset, n: sizeof(uint32_t));
908 wr_pos += sizeof(uint32_t);
909 memcpy(dst: pubdata + wr_pos, src: uuid, n: 16);
910 wr_pos += 16;
911
912 memcpy(dst: pubdata + wr_pos, src: buff, n: buff_len);
913 wr_pos += buff_len;
914
915 /*
916 * Unlike KEXTs, where PC is used to find UUID, in coprocessor logs the UUID
917 * is passed as part of the tracepoint.
918 */
919 firehose_tracepoint_namespace_t ns = firehose_tracepoint_namespace_log;
920 firehose_tracepoint_flags_t flags = _firehose_tracepoint_flags_pc_style_uuid_relative;
921 firehose_tracepoint_id_u trace_id = {
922 .ftid_value = FIREHOSE_TRACE_ID_MAKE(ns, type, flags, offset)
923 };
924
925 log_payload_s log;
926 log_payload_init(lp: &log, stream: firehose_stream(type), ftid: trace_id, timestamp, data_size: wr_pos, pub_data_size: wr_pos);
927
928 if (!log_queue_log(&log, pubdata, stream_log)) {
929 counter_inc(&oslog_p_coprocessor_dropped_msgcount);
930 return false;
931 }
932
933 return true;
934}
935
936static inline firehose_tracepoint_t
937firehose_trace_start(const log_payload_s *lp, uint8_t **ft_priv_data)
938{
939 uint16_t priv_data_size = (uint16_t)log_payload_priv_data_size(lp);
940 uint16_t pub_data_size = (uint16_t)lp->lp_pub_data_size;
941
942 if (priv_data_size > 0) {
943 pub_data_size += sizeof(struct firehose_buffer_range_s);
944 }
945
946 assert3u(offsetof(struct firehose_tracepoint_s, ft_data) +
947 pub_data_size + priv_data_size, <=, sizeof(((firehose_chunk_t)0)->fc_data));
948
949 firehose_tracepoint_t ft = __firehose_buffer_tracepoint_reserve(stamp: lp->lp_timestamp,
950 stream: lp->lp_stream, pubsize: pub_data_size, privsize: priv_data_size, privptr: ft_priv_data);
951
952 if (fastpath(ft)) {
953 oslog_boot_done = true;
954 return ft;
955 }
956
957 if (fastpath(oslog_boot_done)) {
958 return 0;
959 }
960
961 /*
962 * Early boot logging when kernel logging is up and running but logd is
963 * not yet ready. Only the persist firehose stream is available.
964 */
965
966 long offset = firehose_chunk_tracepoint_try_reserve(fc: &firehose_boot_chunk,
967 stamp: lp->lp_timestamp, stream: firehose_stream_persist, qos: 0, pubsize: pub_data_size,
968 privsize: priv_data_size, privptr: ft_priv_data);
969 if (offset <= 0) {
970 counter_inc(&oslog_p_boot_dropped_msgcount);
971 return 0;
972 }
973
974 return firehose_chunk_tracepoint_begin(fc: &firehose_boot_chunk,
975 stamp: lp->lp_timestamp, pubsize: pub_data_size, thread_id: thread_tid(thread: current_thread()),
976 offset);
977}
978
979static inline void
980firehose_trace_finish(firehose_tracepoint_t ft, firehose_tracepoint_id_u ftid)
981{
982 if (__probable(oslog_boot_done)) {
983 __firehose_buffer_tracepoint_flush(vat: ft, vatid: ftid);
984 } else {
985 firehose_chunk_tracepoint_end(fc: &firehose_boot_chunk, ft, ftid);
986 }
987}
988
989static inline void
990firehose_trace_save_payload(const log_payload_s *lp, const uint8_t *lp_data,
991 firehose_tracepoint_t ft, uint8_t *ft_priv_data)
992{
993 const size_t priv_data_size = log_payload_priv_data_size(lp);
994 uint8_t *ft_data = ft->ft_data;
995
996 if (priv_data_size > 0) {
997 assert(FIREHOSE_TRACE_ID_HAS_FLAG(lp->lp_ftid, log, has_private_data));
998 memcpy(dst: ft_priv_data, src: log_payload_priv_data(lp, lp_data), n: priv_data_size);
999
1000 firehose_chunk_t fc = firehose_chunk_for_address(addr: ft);
1001 struct firehose_buffer_range_s range = {
1002 .fbr_offset = (uint16_t)(ft_priv_data - fc->fc_start),
1003 .fbr_length = (uint16_t)priv_data_size
1004 };
1005 memcpy(dst: ft_data, src: &range, n: sizeof(range));
1006 ft_data += sizeof(range);
1007 }
1008 memcpy(dst: ft_data, src: lp_data, n: lp->lp_pub_data_size);
1009}
1010
1011static inline void
1012log_stats_update_saved(firehose_stream_t stream)
1013{
1014 if (__improbable(!oslog_boot_done)) {
1015 stream = firehose_stream_persist;
1016 }
1017
1018 switch (stream) {
1019 case firehose_stream_metadata:
1020 counter_inc(&oslog_p_metadata_saved_msgcount);
1021 break;
1022 case firehose_stream_persist:
1023 case firehose_stream_memory:
1024 counter_inc(&oslog_p_saved_msgcount);
1025 break;
1026 case firehose_stream_signpost:
1027 counter_inc(&oslog_p_signpost_saved_msgcount);
1028 break;
1029 default:
1030 panic("Unexpected firehose stream type %u", stream);
1031 }
1032}
1033
1034static inline firehose_tracepoint_id_t
1035firehose_trace(const log_payload_s *lp, const uint8_t *lp_data)
1036{
1037 uint8_t *ft_priv_data = NULL;
1038 firehose_tracepoint_t ft = firehose_trace_start(lp, ft_priv_data: &ft_priv_data);
1039
1040 if (fastpath(ft)) {
1041 firehose_trace_save_payload(lp, lp_data, ft, ft_priv_data);
1042 firehose_trace_finish(ft, ftid: lp->lp_ftid);
1043 log_stats_update_saved(stream: lp->lp_stream);
1044 return lp->lp_ftid.ftid_value;
1045 }
1046 return 0;
1047}
1048
1049static firehose_tracepoint_code_t
1050coproc_reg_type_to_firehost_code(os_log_coproc_reg_t reg_type)
1051{
1052 switch (reg_type) {
1053 case os_log_coproc_register_memory:
1054 return firehose_tracepoint_code_load_memory;
1055 case os_log_coproc_register_harvest_fs_ftab:
1056 return firehose_tracepoint_code_load_filesystem_ftab;
1057 default:
1058 return firehose_tracepoint_code_invalid;
1059 }
1060}
1061
1062void
1063os_log_coprocessor_register_with_type(const char *uuid, const char *file_path, os_log_coproc_reg_t reg_type)
1064{
1065 size_t path_size = strlen(s: file_path) + 1;
1066 size_t uuid_info_len = sizeof(struct firehose_trace_uuid_info_s) + path_size;
1067
1068 if (os_log_disabled() || path_size > PATH_MAX) {
1069 return;
1070 }
1071
1072 __attribute__((uninitialized))
1073 union {
1074 struct firehose_trace_uuid_info_s uuid_info;
1075 char path[PATH_MAX + sizeof(struct firehose_trace_uuid_info_s)];
1076 } buf;
1077
1078 // write metadata to uuid_info
1079 memcpy(dst: buf.uuid_info.ftui_uuid, src: uuid, n: sizeof(uuid_t));
1080 buf.uuid_info.ftui_size = 1;
1081 buf.uuid_info.ftui_address = 1;
1082
1083 uint64_t stamp = firehose_tracepoint_time(flags: firehose_activity_flags_default);
1084
1085 // create tracepoint id
1086 firehose_tracepoint_id_u trace_id;
1087 trace_id.ftid_value = FIREHOSE_TRACE_ID_MAKE(firehose_tracepoint_namespace_metadata,
1088 _firehose_tracepoint_type_metadata_coprocessor, (firehose_tracepoint_flags_t)0,
1089 coproc_reg_type_to_firehost_code(reg_type));
1090
1091 // write path to buffer
1092 memcpy(dst: buf.uuid_info.ftui_path, src: file_path, n: path_size);
1093
1094 // send metadata tracepoint to firehose for coprocessor registration in logd
1095 os_log_encoded_metadata(ftid: trace_id, ts: stamp, msg: (void *)&buf, msg_size: uuid_info_len);
1096}
1097
1098bool
1099log_payload_send(log_payload_t lp, const void *lp_data, bool use_stream)
1100{
1101 if (use_stream) {
1102 bool is_metadata = (lp->lp_stream == firehose_stream_metadata);
1103 oslog_stream(is_metadata, lp->lp_ftid, lp->lp_timestamp, lp_data, lp->lp_data_size);
1104 }
1105 return firehose_trace(lp, lp_data) != 0;
1106}
1107
1108void
1109__firehose_buffer_push_to_logd(firehose_buffer_t fb __unused, bool for_io __unused)
1110{
1111 oslogwakeup();
1112 return;
1113}
1114
1115void
1116__firehose_allocate(vm_offset_t *addr, vm_size_t size __unused)
1117{
1118 firehose_chunk_t kernel_buffer = (firehose_chunk_t)kernel_firehose_addr;
1119
1120 if (kernel_firehose_addr) {
1121 *addr = kernel_firehose_addr;
1122 } else {
1123 *addr = 0;
1124 return;
1125 }
1126 // Now that we are done adding logs to this chunk, set the number of writers to 0
1127 // Without this, logd won't flush when the page is full
1128 firehose_boot_chunk.fc_pos.fcp_refcnt = 0;
1129 memcpy(dst: &kernel_buffer[FIREHOSE_BUFFER_KERNEL_CHUNK_COUNT - 1], src: (const void *)&firehose_boot_chunk, FIREHOSE_CHUNK_SIZE);
1130 return;
1131}
1132// There isnt a lock held in this case.
1133void
1134__firehose_critical_region_enter(void)
1135{
1136 disable_preemption();
1137 return;
1138}
1139
1140void
1141__firehose_critical_region_leave(void)
1142{
1143 enable_preemption();
1144 return;
1145}
1146
1147#ifdef CONFIG_XNUPOST
1148
1149static_assert(&_os_log_default == OS_LOG_DEFAULT,
1150 "OS_LOG_DEFAULT is an alias to _os_log_default");
1151static_assert(OS_LOG_DISABLED == NULL,
1152 "OS_LOG_DISABLED handle is defined as NULL");
1153
1154#include <dev/random/randomdev.h>
1155#include <tests/xnupost.h>
1156
1157typedef struct {
1158 size_t total;
1159 size_t saved;
1160 size_t dropped;
1161 size_t truncated;
1162 size_t errors;
1163 size_t errors_kc;
1164 size_t errors_fmt;
1165 size_t errors_max_args;
1166} log_stats_t;
1167
1168#define TESTBUFLEN 256
1169#define TESTOSLOGFMT(fn_name) "%u^%llu/%llu^kernel^0^test^" fn_name
1170#define TESTOSLOGPFX "TESTLOG:%u#"
1171#define TESTOSLOG(fn_name) TESTOSLOGPFX TESTOSLOGFMT(fn_name "#")
1172
1173#define LOG_STAT_CMP(cmp, b, a, e, stat, msg, test) \
1174 { \
1175 size_t n##stat = (a)->stat - (b)->stat; \
1176 size_t n##expected = (e)->stat; \
1177 cmp(n##stat, n##expected, (msg), (test), n##expected); \
1178 }
1179#define LOG_STAT_EQ(b, a, e, stat, msg, test) \
1180 LOG_STAT_CMP(T_EXPECT_EQ_UINT, b, a, e, stat, msg, test)
1181#define LOG_STAT_GE(b, a, e, stat, msg, test) \
1182 LOG_STAT_CMP(T_EXPECT_GE_UINT, b, a, e, stat, msg, test)
1183
1184#define GENOSLOGHELPER(fname, ident, callout_f) \
1185 static void \
1186 fname(uint32_t uniqid, uint64_t count, log_stats_t *before, log_stats_t *after) \
1187 { \
1188 uint32_t checksum = 0; \
1189 char pattern[TESTBUFLEN]; \
1190 T_LOG("Testing " ident "() with %d logs", count); \
1191 log_stats_get(before); \
1192 for (uint64_t i = 0; i < count; i++) { \
1193 (void) save_pattern(pattern, &checksum, TESTOSLOGFMT(ident), uniqid, i + 1, count); \
1194 callout_f(OS_LOG_DEFAULT, TESTOSLOG(ident), checksum, uniqid, i + 1, count); \
1195 } \
1196 log_stats_get(after); \
1197 }
1198
1199extern size_t find_pattern_in_buffer(const char *, size_t, size_t);
1200
1201void test_oslog_handleOSLogCtl(int32_t *, int32_t *, int32_t);
1202kern_return_t test_printf(void);
1203kern_return_t test_os_log(void);
1204kern_return_t test_os_log_handles(void);
1205kern_return_t test_os_log_parallel(void);
1206
1207SCALABLE_COUNTER_DECLARE(oslog_p_fmt_invalid_msgcount);
1208SCALABLE_COUNTER_DECLARE(oslog_p_fmt_max_args_msgcount);
1209SCALABLE_COUNTER_DECLARE(oslog_p_truncated_msgcount);
1210SCALABLE_COUNTER_DECLARE(log_queue_cnt_received);
1211
1212static void
1213log_stats_get(log_stats_t *stats)
1214{
1215 if (!stats) {
1216 return;
1217 }
1218 stats->total = counter_load(&oslog_p_total_msgcount);
1219 stats->saved = counter_load(&log_queue_cnt_received);
1220 stats->dropped = counter_load(&oslog_p_dropped_msgcount);
1221 stats->truncated = counter_load(&oslog_p_truncated_msgcount);
1222 stats->errors = counter_load(&oslog_p_error_count);
1223 stats->errors_kc = counter_load(&oslog_p_unresolved_kc_msgcount);
1224 stats->errors_fmt = counter_load(&oslog_p_fmt_invalid_msgcount);
1225 stats->errors_max_args = counter_load(&oslog_p_fmt_max_args_msgcount);
1226}
1227
1228static void
1229log_stats_diff(const log_stats_t *before, const log_stats_t *after, log_stats_t *diff)
1230{
1231 log_stats_t d = {};
1232
1233 if (before) {
1234 d = *before;
1235 }
1236 if (after) {
1237 d.total = after->total - d.total;
1238 d.saved = after->saved - d.saved;
1239 d.dropped = after->dropped - d.dropped;
1240 d.truncated = after->truncated - d.truncated;
1241 d.errors = after->errors - d.errors;
1242 d.errors_kc = after->errors_kc - d.errors_kc;
1243 d.errors_fmt = after->errors_fmt - d.errors_fmt;
1244 d.errors_max_args = after->errors_max_args - d.errors_max_args;
1245 }
1246 *diff = d;
1247}
1248
1249static void
1250log_stats_check_errors(const log_stats_t *before, const log_stats_t *after, const log_stats_t *expected,
1251 const char *test)
1252{
1253 LOG_STAT_EQ(before, after, expected, errors, "%s: Expected %lu encoding errors", test);
1254 LOG_STAT_EQ(before, after, expected, errors_kc, "%s: Expected %lu DSO errors", test);
1255 LOG_STAT_EQ(before, after, expected, errors_fmt, "%s: Expected %lu bad format errors", test);
1256 LOG_STAT_EQ(before, after, expected, errors_max_args, "%s: Expected %lu max arguments errors", test);
1257}
1258
1259static void
1260log_stats_check(const log_stats_t *before, const log_stats_t *after, const log_stats_t *expected,
1261 const char *test)
1262{
1263 /*
1264 * The comparison is >= (_GE) for total and saved counters because tests
1265 * are running while the system is up and potentially logging. Test and
1266 * regular logs interfere rather rarely but can make the test flaky
1267 * which is not desired.
1268 */
1269 LOG_STAT_GE(before, after, expected, total, "%s: Expected %lu logs total", test);
1270 LOG_STAT_GE(before, after, expected, saved, "%s: Expected %lu saved logs", test);
1271 LOG_STAT_EQ(before, after, expected, dropped, "%s: Expected %lu logs dropped", test);
1272 log_stats_check_errors(before, after, expected, test);
1273}
1274
1275static void
1276log_stats_report(const log_stats_t *before, const log_stats_t *after, const char *test)
1277{
1278 log_stats_t diff = {};
1279 log_stats_diff(before, after, &diff);
1280
1281 T_LOG("\n%s: Logging stats:\n\ttotal: %u\n\tsaved: %u\n\tdropped: %u\n"
1282 "\terrors: %u\n\terrors_kc: %u\n\terrors_fmt: %u\n\terrors_max_args: %u",
1283 test, diff.total, diff.saved, diff.dropped,
1284 diff.errors, diff.errors_kc, diff.errors_fmt, diff.errors_max_args);
1285}
1286
1287static int
1288save_pattern(char buf[static TESTBUFLEN], uint32_t *crc, const char *fmt, ...)
1289{
1290 va_list va;
1291
1292 va_start(va, fmt);
1293#pragma clang diagnostic push
1294#pragma clang diagnostic ignored "-Wformat-nonliteral"
1295 int n = vscnprintf(buf, TESTBUFLEN, fmt, va);
1296#pragma clang diagnostic pop
1297 va_end(va);
1298 if (crc) {
1299 *crc = crc32(0, buf, n);
1300 }
1301 return n;
1302}
1303
1304/*
1305 * Actual GENOSLOGHELPER() 2nd argument values below are expected by libtrace
1306 * test_kern_oslog test suite and shall not be changed without updating given
1307 * test suite.
1308 */
1309GENOSLOGHELPER(test_oslog_info, "oslog_info_helper", os_log_info);
1310GENOSLOGHELPER(test_oslog_fault, "oslog_fault_helper", os_log_fault);
1311GENOSLOGHELPER(test_oslog_debug, "oslog_debug_helper", os_log_debug);
1312GENOSLOGHELPER(test_oslog_error, "oslog_error_helper", os_log_error);
1313GENOSLOGHELPER(test_oslog_default, "oslog_default_helper", os_log);
1314
1315kern_return_t
1316test_printf(void)
1317{
1318 const uint32_t uniqid = RandomULong();
1319 T_ASSERT_NE_UINT(0, uniqid, "Random number should not be zero");
1320
1321 uint64_t stamp = mach_absolute_time();
1322 T_ASSERT_NE_ULLONG(0, stamp, "Absolute time should not be zero");
1323
1324 T_LOG("Validating with atm_diagnostic_config=%#x uniqid=%u stamp=%llu",
1325 atm_get_diagnostic_config(), uniqid, stamp);
1326
1327 __attribute__((uninitialized))
1328 char pattern[TESTBUFLEN];
1329 log_stats_t before = {}, after = {};
1330 uint32_t checksum = 0;
1331
1332 log_stats_get(&before);
1333
1334 (void) save_pattern(pattern, &checksum, TESTOSLOGFMT("printf_only"), uniqid, 1LL, 2LL);
1335 printf(TESTOSLOG("printf_only") "mat%llu\n", checksum, uniqid, 1LL, 2LL, stamp);
1336
1337 (void) save_pattern(pattern, &checksum, TESTOSLOGFMT("printf_only"), uniqid, 2LL, 2LL);
1338 printf(TESTOSLOG("printf_only") "mat%llu\n", checksum, uniqid, 2LL, 2LL, stamp);
1339
1340 size_t saved = save_pattern(pattern, NULL, "kernel^0^test^printf_only#mat%llu", stamp);
1341 size_t match_count = find_pattern_in_buffer(pattern, saved, 2LL);
1342 T_EXPECT_EQ_ULONG(match_count, 2LL, "printf() logs to msgbuf");
1343
1344 log_stats_get(&after);
1345
1346 if (!os_log_turned_off()) {
1347 // printf() should log to OSLog with OSLog enabled.
1348 log_stats_t expected = { .total = 2, .saved = 2 };
1349 log_stats_check(&before, &after, &expected, "printf() logs to oslog");
1350 }
1351
1352 log_stats_report(&before, &after, __FUNCTION__);
1353
1354 return KERN_SUCCESS;
1355}
1356
1357static void
1358verify_os_log(struct os_log_s *h, char *sub, char *cat)
1359{
1360 const size_t sub_len = os_log_subsystem_name_size(sub);
1361 const size_t cat_len = os_log_subsystem_name_size(cat);
1362
1363 struct os_log_subsystem_s *s = &h->ol_subsystem;
1364
1365 T_ASSERT_EQ_STR(s->ols_name, sub, "Log subsystem name is %s", sub);
1366 T_ASSERT_EQ_ULONG(s->ols_sub_size, sub_len, "Log subsystem size is %lu", sub_len);
1367 T_ASSERT_EQ_ULONG(strlen(s->ols_name), sub_len - 1, "Log subsystem length is %lu", sub_len - 1);
1368
1369 T_ASSERT_EQ_STR(&s->ols_name[sub_len], cat, "Log category name is %s", cat);
1370 T_ASSERT_EQ_ULONG(s->ols_cat_size, cat_len, "Log category length is %lu", cat_len);
1371 T_ASSERT_EQ_ULONG(strlen(&s->ols_name[sub_len]), cat_len - 1, "Log category size is %lu", cat_len - 1);
1372}
1373
1374static os_log_t
1375create_verified_os_log(char *sub, char *cat)
1376{
1377 os_log_t h = os_log_create(sub, cat);
1378 verify_os_log(h, sub, cat);
1379 return h;
1380}
1381
1382kern_return_t
1383test_os_log_handles(void)
1384{
1385 os_log_t h1 = create_verified_os_log("xnu_post_subsystem1", "xnu_post_category1");
1386 if (os_log_disabled()) {
1387 T_ASSERT_EQ_PTR(h1, OS_LOG_DISABLED, "Disabled logging uses OS_LOG_DISABLED");
1388 return KERN_SUCCESS;
1389 }
1390 T_ASSERT_NE_PTR(h1, OS_LOG_DEFAULT, "Custom log handle is not OS_LOG_DEFAULT");
1391
1392 os_log_t h2 = create_verified_os_log("xnu_post_subsystem1", "xnu_post_category1");
1393 T_ASSERT_EQ_PTR(h1, h2, "os_log_create() finds an existing log handle in the cache");
1394
1395 h2 = create_verified_os_log("xnu_post_subsystem1", "xnu_post_category2");
1396 T_ASSERT_NE_PTR(h1, h2, "Subsystem is not enough to identify a log handle");
1397
1398 h2 = create_verified_os_log("xnu_post_subsystem2", "xnu_post_category1");
1399 T_ASSERT_NE_PTR(h1, h2, "Category is not enough to identify a log handle");
1400
1401 h2 = create_verified_os_log("xnu_post_subsystem3", "xnu_post_category3");
1402 T_ASSERT_NE_PTR(h1, h2, "Different subsystem and category yield a different handle");
1403
1404 h1 = h2;
1405 h2 = create_verified_os_log("xnu_post", "_subsystem3xnu_post_category3");
1406 T_ASSERT_NE_PTR(h1, h2, "Subsystem and category cannot be mixed");
1407
1408 const size_t name_size = sizeof(h1->ol_subsystem.ols_name) / 2;
1409
1410 char super_long_sub[name_size] = {
1411 [0 ... sizeof(super_long_sub) - 1] = 'X'
1412 };
1413
1414 char super_long_cat[name_size] = {
1415 [0 ... sizeof(super_long_sub) - 1] = 'Y'
1416 };
1417
1418 h1 = os_log_create(super_long_sub, super_long_cat);
1419 T_ASSERT_NE_PTR(h1, OS_LOG_DEFAULT, "Custom log handle is not OS_LOG_DEFAULT");
1420
1421 super_long_sub[name_size - 1] = '\0';
1422 super_long_cat[name_size - 1] = '\0';
1423
1424 verify_os_log(h1, super_long_sub, super_long_cat);
1425
1426 return KERN_SUCCESS;
1427}
1428
1429kern_return_t
1430test_os_log(void)
1431{
1432 const uint32_t uniqid = RandomULong();
1433 T_ASSERT_NE_UINT(0, uniqid, "Random number should not be zero");
1434
1435 uint64_t stamp = mach_absolute_time();
1436 T_ASSERT_NE_ULLONG(0, stamp, "Absolute time should not be zero");
1437
1438 T_LOG("Validating with atm_diagnostic_config=%#x uniqid=%u stamp=%llu",
1439 atm_get_diagnostic_config(), uniqid, stamp);
1440
1441 os_log_t log_handle = os_log_create("com.apple.xnu.test.t1", "kpost");
1442 T_ASSERT_NE_PTR(OS_LOG_DEFAULT, log_handle, "Log handle is not OS_LOG_DEFAULT");
1443
1444 const bool enabled = !os_log_turned_off();
1445 T_ASSERT_EQ_INT(enabled, os_log_info_enabled(log_handle), "Info log level is enabled");
1446 T_ASSERT_EQ_INT(enabled, os_log_debug_enabled(log_handle), "Debug log level is enabled");
1447
1448 __attribute__((uninitialized))
1449 char pattern[TESTBUFLEN];
1450 uint32_t checksum = 0;
1451
1452 (void) save_pattern(pattern, &checksum, TESTOSLOGFMT("oslog_info"), uniqid, 1LL, 1LL);
1453 os_log_info(log_handle, TESTOSLOG("oslog_info") "mat%llu", checksum, uniqid, 1LL, 1LL, stamp);
1454 size_t saved = save_pattern(pattern, NULL, "kernel^0^test^oslog_info#mat%llu", stamp);
1455 size_t match_count = find_pattern_in_buffer(pattern, saved, 1LL);
1456 T_EXPECT_EQ_ULONG(match_count, 1LL, "oslog_info() logs to system message buffer");
1457
1458 const size_t n = 10;
1459
1460 log_stats_t expected = {
1461 .total = enabled ? n : 0,
1462 .saved = enabled ? n : 0
1463 };
1464
1465 log_stats_t before = {}, after = {};
1466
1467 test_oslog_info(uniqid, n, &before, &after);
1468 log_stats_check(&before, &after, &expected, "test_oslog_info");
1469
1470 test_oslog_debug(uniqid, n, &before, &after);
1471 log_stats_check(&before, &after, &expected, "test_oslog_debug");
1472
1473 test_oslog_error(uniqid, n, &before, &after);
1474 log_stats_check(&before, &after, &expected, "test_oslog_error");
1475
1476 test_oslog_default(uniqid, n, &before, &after);
1477 log_stats_check(&before, &after, &expected, "test_oslog_default");
1478
1479 test_oslog_fault(uniqid, n, &before, &after);
1480 log_stats_check(&before, &after, &expected, "test_oslog_fault");
1481
1482 log_stats_report(&before, &after, __FUNCTION__);
1483
1484 return KERN_SUCCESS;
1485}
1486
1487static size_t _test_log_loop_count = 0;
1488
1489static void
1490_test_log_loop(void *arg __unused, wait_result_t wres __unused)
1491{
1492 test_oslog_debug(RandomULong(), 100, NULL, NULL);
1493 os_atomic_add(&_test_log_loop_count, 100, relaxed);
1494}
1495
1496kern_return_t
1497test_os_log_parallel(void)
1498{
1499 if (os_log_turned_off()) {
1500 T_LOG("Logging disabled, skipping tests.");
1501 return KERN_SUCCESS;
1502 }
1503
1504 thread_t thread[2];
1505 kern_return_t kr;
1506 log_stats_t after, before, expected = {};
1507
1508 log_stats_get(&before);
1509
1510 kr = kernel_thread_start(_test_log_loop, NULL, &thread[0]);
1511 T_ASSERT_EQ_INT(kr, KERN_SUCCESS, "kernel_thread_start returned successfully");
1512
1513 kr = kernel_thread_start(_test_log_loop, NULL, &thread[1]);
1514 T_ASSERT_EQ_INT(kr, KERN_SUCCESS, "kernel_thread_start returned successfully");
1515
1516 test_oslog_info(RandomULong(), 100, NULL, NULL);
1517
1518 /* wait until other thread has also finished */
1519 while (_test_log_loop_count < 200) {
1520 delay(1000);
1521 }
1522
1523 thread_deallocate(thread[0]);
1524 thread_deallocate(thread[1]);
1525
1526 log_stats_get(&after);
1527 log_stats_check_errors(&before, &after, &expected, __FUNCTION__);
1528 log_stats_report(&before, &after, __FUNCTION__);
1529
1530 return KERN_SUCCESS;
1531}
1532
1533static kern_return_t
1534test_stresslog_dropmsg(const uint32_t uniqid)
1535{
1536 if (os_log_turned_off()) {
1537 T_LOG("Logging disabled, skipping tests.");
1538 return KERN_SUCCESS;
1539 }
1540
1541 log_stats_t after, before, expected = {};
1542
1543 test_oslog_debug(uniqid, 100, &before, &after);
1544 while ((after.dropped - before.dropped) == 0) {
1545 test_oslog_debug(uniqid, 100, NULL, &after);
1546 }
1547
1548 log_stats_check_errors(&before, &after, &expected, __FUNCTION__);
1549 log_stats_report(&before, &after, __FUNCTION__);
1550
1551 return KERN_SUCCESS;
1552}
1553
1554void
1555test_oslog_handleOSLogCtl(int32_t *in, int32_t *out, int32_t len)
1556{
1557 if (!in || !out || len != 4) {
1558 return;
1559 }
1560 switch (in[0]) {
1561 case 1:
1562 {
1563 /* send out counters */
1564 out[1] = counter_load(&oslog_p_total_msgcount);
1565 out[2] = counter_load(&oslog_p_saved_msgcount);
1566 out[3] = counter_load(&oslog_p_dropped_msgcount);
1567 out[0] = KERN_SUCCESS;
1568 break;
1569 }
1570 case 2:
1571 {
1572 /* mini stress run */
1573 out[0] = test_os_log_parallel();
1574 break;
1575 }
1576 case 3:
1577 {
1578 /* drop msg tests */
1579 out[1] = RandomULong();
1580 out[0] = test_stresslog_dropmsg(out[1]);
1581 break;
1582 }
1583 case 4:
1584 {
1585 /* invoke log helpers */
1586 uint32_t uniqid = in[3];
1587 int32_t msgcount = in[2];
1588 if (uniqid == 0 || msgcount == 0) {
1589 out[0] = KERN_INVALID_VALUE;
1590 return;
1591 }
1592
1593 switch (in[1]) {
1594 case OS_LOG_TYPE_INFO:
1595 test_oslog_info(uniqid, msgcount, NULL, NULL);
1596 break;
1597 case OS_LOG_TYPE_DEBUG:
1598 test_oslog_debug(uniqid, msgcount, NULL, NULL);
1599 break;
1600 case OS_LOG_TYPE_ERROR:
1601 test_oslog_error(uniqid, msgcount, NULL, NULL);
1602 break;
1603 case OS_LOG_TYPE_FAULT:
1604 test_oslog_fault(uniqid, msgcount, NULL, NULL);
1605 break;
1606 case OS_LOG_TYPE_DEFAULT:
1607 default:
1608 test_oslog_default(uniqid, msgcount, NULL, NULL);
1609 break;
1610 }
1611 out[0] = KERN_SUCCESS;
1612 break;
1613 /* end of case 4 */
1614 }
1615 default:
1616 {
1617 out[0] = KERN_INVALID_VALUE;
1618 break;
1619 }
1620 }
1621 return;
1622}
1623
1624#endif /* CONFIG_XNUPOST */
1625