This is xnu-11215.1.10. See this file in:
/*
* Copyright (c) 2019-2024 Apple Inc. All rights reserved.
*/
#undef offset
#include <kern/cpu_data.h>
#include <os/base.h>
#include <os/hash.h>
#include <os/object.h>
#include <os/log.h>
#include <stdbool.h>
#include <stddef.h>
#include <stdint.h>
#include <vm/vm_kern_xnu.h>
#include <mach/vm_statistics.h>
#include <kern/debug.h>
#include <libkern/libkern.h>
#include <libkern/kernel_mach_header.h>
#include <pexpert/pexpert.h>
#include <uuid/uuid.h>
#include <sys/msgbuf.h>
#include <mach/mach_time.h>
#include <kern/thread.h>
#include <kern/simple_lock.h>
#include <kern/kalloc.h>
#include <kern/clock.h>
#include <kern/assert.h>
#include <kern/smr_hash.h>
#include <kern/startup.h>
#include <kern/task.h>
#include <firehose/firehose_types_private.h>
#include <firehose/tracepoint_private.h>
#include <firehose/chunk_private.h>
#include <os/firehose_buffer_private.h>
#include <os/firehose.h>
#include <os/log_private.h>
#include "log_encode.h"
#include "log_internal.h"
#include "log_mem.h"
#include "log_queue.h"
#include "trace_internal.h"
#define OS_LOGMEM_BUF_ORDER 14
#define OS_LOGMEM_MIN_LOG_ORDER 9
#define OS_LOGMEM_MAX_LOG_ORDER (OS_LOG_MAX_SIZE_ORDER)
#define OS_LOG_SUBSYSTEM_MAX_CNT 1024
#define OS_LOG_SUBSYSTEM_NONE 0xffff
#define OS_LOG_SUBSYSTEM_BASE 0x0001 // OS_LOG_DEFAULT takes 0 by definition
#define OS_LOG_SUBSYSTEM_LAST (OS_LOG_SUBSYSTEM_BASE + OS_LOG_SUBSYSTEM_MAX_CNT)
#define OS_LOG_SUBSYSTEM_NAME_MAX_LEN 128
/*
* OSLog subsystem type. The struct layout matches its libtrace counterpart
* and also matches what libtrace (logd) expects from subsystem registration
* metadata payload.
*/
struct os_log_subsystem_s {
uint16_t ols_id;
union {
struct {
uint8_t ols_sub_size;
uint8_t ols_cat_size;
};
uint16_t ols_sizes;
};
char ols_name[2 * OS_LOG_SUBSYSTEM_NAME_MAX_LEN];
};
struct os_log_s {
struct os_log_subsystem_s ol_subsystem;
struct smrq_slink ol_hash_link;
};
struct os_log_s _os_log_default;
struct os_log_s _os_log_replay;
/* Counters for persistence mode */
SCALABLE_COUNTER_DEFINE(oslog_p_total_msgcount);
SCALABLE_COUNTER_DEFINE(oslog_p_metadata_saved_msgcount);
SCALABLE_COUNTER_DEFINE(oslog_p_metadata_dropped_msgcount);
SCALABLE_COUNTER_DEFINE(oslog_p_signpost_saved_msgcount);
SCALABLE_COUNTER_DEFINE(oslog_p_signpost_dropped_msgcount);
SCALABLE_COUNTER_DEFINE(oslog_p_error_count);
SCALABLE_COUNTER_DEFINE(oslog_p_saved_msgcount);
SCALABLE_COUNTER_DEFINE(oslog_p_dropped_msgcount);
SCALABLE_COUNTER_DEFINE(oslog_p_boot_dropped_msgcount);
SCALABLE_COUNTER_DEFINE(oslog_p_coprocessor_total_msgcount);
SCALABLE_COUNTER_DEFINE(oslog_p_coprocessor_dropped_msgcount);
SCALABLE_COUNTER_DEFINE(oslog_p_unresolved_kc_msgcount);
/* Counters for msgbuf logging */
SCALABLE_COUNTER_DEFINE(oslog_msgbuf_msgcount)
SCALABLE_COUNTER_DEFINE(oslog_msgbuf_dropped_msgcount)
/* Log subsystem counters */
SCALABLE_COUNTER_DEFINE(oslog_subsystem_count);
SCALABLE_COUNTER_DEFINE(oslog_subsystem_found);
SCALABLE_COUNTER_DEFINE(oslog_subsystem_dropped);
LCK_GRP_DECLARE(oslog_cache_lock_grp, "oslog_cache_lock_grp");
LCK_TICKET_DECLARE(oslog_cache_lock, &oslog_cache_lock_grp);
static bool oslog_boot_done = false;
static SECURITY_READ_ONLY_LATE(bool) oslog_disabled = false;
static uint16_t os_log_subsystem_id = OS_LOG_SUBSYSTEM_BASE;
static struct logmem_s os_log_mem;
static struct smr_hash os_log_cache;
static struct firehose_chunk_s firehose_boot_chunk = {
.fc_pos = {
.fcp_next_entry_offs = offsetof(struct firehose_chunk_s, fc_data),
.fcp_private_offs = FIREHOSE_CHUNK_SIZE,
.fcp_refcnt = 1, // Indicate that there is a writer to this chunk
.fcp_stream = firehose_stream_persist,
.fcp_flag_io = 1, // Lets assume this is coming from the io bank
},
};
bool os_log_disabled(void);
extern vm_offset_t kernel_firehose_addr;
extern bool bsd_log_lock(bool);
extern void bsd_log_unlock(void);
extern void logwakeup(void);
extern void oslog_stream(bool, firehose_tracepoint_id_u, uint64_t, const void *, size_t);
extern void *OSKextKextForAddress(const void *);
static bool
os_log_safe(void)
{
return oslog_is_safe() || startup_phase < STARTUP_SUB_EARLY_BOOT;
}
static bool
os_log_turned_off(void)
{
return oslog_disabled || (atm_get_diagnostic_config() & ATM_TRACE_OFF);
}
bool
os_log_info_enabled(os_log_t log __unused)
{
return !os_log_turned_off();
}
bool
os_log_debug_enabled(os_log_t log __unused)
{
return !os_log_turned_off();
}
bool
os_log_disabled(void)
{
return oslog_disabled;
}
static inline size_t
log_payload_priv_data_size(const log_payload_s *lp)
{
assert3u(lp->lp_pub_data_size, <=, lp->lp_data_size);
return lp->lp_data_size - lp->lp_pub_data_size;
}
static inline const uint8_t *
log_payload_priv_data(const log_payload_s *lp, const uint8_t *lp_data)
{
if (log_payload_priv_data_size(lp) == 0) {
return NULL;
}
return &lp_data[lp->lp_pub_data_size];
}
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, size_t pub_data_size)
{
assert3u(pub_data_size, <=, data_size);
assert3u(data_size, <, UINT16_MAX);
lp->lp_stream = stream;
lp->lp_ftid = ftid;
lp->lp_timestamp = timestamp;
lp->lp_pub_data_size = (uint16_t)pub_data_size;
lp->lp_data_size = (uint16_t)data_size;
}
static firehose_stream_t
firehose_stream(os_log_type_t type)
{
return (type == OS_LOG_TYPE_INFO || type == OS_LOG_TYPE_DEBUG) ?
firehose_stream_memory : firehose_stream_persist;
}
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)
{
uint32_t off;
if (driverKit) {
/*
* Set FIREHOSE_TRACEPOINT_PC_DYNAMIC_BIT so logd will not try
* to find the format string in the executable text.
*/
off = (uint32_t)((uintptr_t)addr | FIREHOSE_TRACEPOINT_PC_DYNAMIC_BIT);
} else {
off = _os_trace_offset(dso, fmt, (_firehose_tracepoint_flags_activity_t)flags);
}
return FIREHOSE_TRACE_ID_MAKE(firehose_tracepoint_namespace_log, type, flags, off);
}
static firehose_tracepoint_flags_t
firehose_ftid_flags(const void *dso, bool driverKit)
{
kc_format_t kcformat = KCFormatUnknown;
__assert_only bool result = PE_get_primary_kc_format(&kcformat);
assert(result);
if (kcformat == KCFormatStatic || kcformat == KCFormatKCGEN) {
return _firehose_tracepoint_flags_pc_style_shared_cache;
}
/*
* driverKit will have the dso set as MH_EXECUTE (it is logging from a
* syscall in the kernel) but needs logd to parse the address as an
* absolute pc.
*/
const kernel_mach_header_t *mh = dso;
if (mh->filetype == MH_EXECUTE && !driverKit) {
return _firehose_tracepoint_flags_pc_style_main_exe;
}
return _firehose_tracepoint_flags_pc_style_absolute;
}
static void *
resolve_dso(const char *fmt, void *dso, void *addr, bool driverKit)
{
kc_format_t kcformat = KCFormatUnknown;
if (!addr || !PE_get_primary_kc_format(&kcformat)) {
return NULL;
}
switch (kcformat) {
case KCFormatStatic:
case KCFormatKCGEN:
dso = PE_get_kc_baseaddress(KCKindPrimary);
break;
case KCFormatDynamic:
case KCFormatFileset:
if (!dso && (dso = (void *)OSKextKextForAddress(fmt)) == NULL) {
return NULL;
}
if (!_os_trace_addr_in_text_segment(dso, fmt)) {
return NULL;
}
if (!driverKit && (dso != (void *)OSKextKextForAddress(addr))) {
return NULL;
}
break;
default:
panic("unknown KC format type");
}
return dso;
}
static inline uintptr_t
resolve_location(firehose_tracepoint_flags_t flags, uintptr_t dso, uintptr_t addr,
bool driverKit, size_t *loc_size)
{
switch (flags & _firehose_tracepoint_flags_pc_style_mask) {
case _firehose_tracepoint_flags_pc_style_shared_cache:
case _firehose_tracepoint_flags_pc_style_main_exe:
*loc_size = sizeof(uint32_t);
return addr - dso;
case _firehose_tracepoint_flags_pc_style_absolute:
*loc_size = sizeof(uintptr_t);
return driverKit ? addr : VM_KERNEL_UNSLIDE(addr);
default:
panic("Unknown firehose tracepoint flags %x", flags);
}
}
__startup_func
static void
oslog_init(void)
{
/*
* Disable kernel logging if ATM_TRACE_DISABLE set. ATM_TRACE_DISABLE
* bit is not supposed to change during a system run but nothing really
* prevents userspace from unintentionally doing so => we stash initial
* value in a dedicated variable for a later reference, just in case.
*/
oslog_disabled = atm_get_diagnostic_config() & ATM_TRACE_DISABLE;
if (!oslog_disabled) {
smr_hash_init(&os_log_cache, OS_LOG_SUBSYSTEM_MAX_CNT / 4);
}
}
STARTUP(OSLOG, STARTUP_RANK_FIRST, oslog_init);
__startup_func
static void
oslog_init_logmem(void)
{
if (os_log_disabled()) {
printf("Long logs support disabled: Logging disabled by ATM\n");
return;
}
const size_t logmem_size = logmem_required_size(OS_LOGMEM_BUF_ORDER, OS_LOGMEM_MIN_LOG_ORDER);
vm_offset_t addr;
if (kmem_alloc(kernel_map, &addr, logmem_size + ptoa(2),
KMA_KOBJECT | KMA_PERMANENT | KMA_ZERO | KMA_GUARD_FIRST | KMA_GUARD_LAST,
VM_KERN_MEMORY_LOG) == KERN_SUCCESS) {
logmem_init(&os_log_mem, (void *)(addr + PAGE_SIZE), logmem_size,
OS_LOGMEM_BUF_ORDER, OS_LOGMEM_MIN_LOG_ORDER, OS_LOGMEM_MAX_LOG_ORDER);
printf("Long logs support configured: size: %u\n", os_log_mem.lm_cnt_free);
} else {
printf("Long logs support disabled: Not enough memory\n");
}
}
STARTUP(OSLOG, STARTUP_RANK_SECOND, oslog_init_logmem);
bool
os_log_encoded_metadata(firehose_tracepoint_id_u ftid, uint64_t ts, const void *msg,
size_t msg_size)
{
assert(ftid.ftid._namespace == firehose_tracepoint_namespace_metadata);
counter_inc(&oslog_p_total_msgcount);
if (!os_log_safe() || os_log_disabled()) {
counter_inc(&oslog_p_metadata_dropped_msgcount);
return false;
}
log_payload_s log;
log_payload_init(&log, firehose_stream_metadata, ftid, ts, msg_size, msg_size);
if (log_queue_log(&log, msg, true)) {
return true;
}
counter_inc(&oslog_p_metadata_dropped_msgcount);
return false;
}
bool
os_log_encoded_log(firehose_stream_t stream, firehose_tracepoint_id_u ftid,
uint64_t ts, const void *msg, size_t msg_size, size_t pub_data_size)
{
assert(ftid.ftid._namespace == firehose_tracepoint_namespace_log);
counter_inc(&oslog_p_total_msgcount);
if (!os_log_safe() || os_log_disabled()) {
counter_inc(&oslog_p_dropped_msgcount);
return false;
}
log_payload_s log;
log_payload_init(&log, stream, ftid, ts, msg_size, pub_data_size);
if (log_queue_log(&log, msg, true)) {
return true;
}
counter_inc(&oslog_p_dropped_msgcount);
return false;
}
bool
os_log_encoded_signpost(firehose_stream_t stream, firehose_tracepoint_id_u ftid,
uint64_t ts, const void *msg, size_t msg_size, size_t pub_data_size)
{
assert(ftid.ftid._namespace == firehose_tracepoint_namespace_signpost);
counter_inc(&oslog_p_total_msgcount);
if (!os_log_safe() || os_log_disabled()) {
counter_inc(&oslog_p_signpost_dropped_msgcount);
return false;
}
log_payload_s log;
log_payload_init(&log, stream, ftid, ts, msg_size, pub_data_size);
if (log_queue_log(&log, msg, true)) {
return true;
}
counter_inc(&oslog_p_signpost_dropped_msgcount);
return false;
}
static inline size_t
os_log_subsystem_name_size(const char *name)
{
return MIN(strlen(name) + 1, OS_LOG_SUBSYSTEM_NAME_MAX_LEN);
}
bool
os_log_subsystem_id_valid(uint16_t sid)
{
return sid >= OS_LOG_SUBSYSTEM_BASE && sid <= os_log_subsystem_id;
}
static inline size_t
os_log_subsystem_id_length(const struct os_log_subsystem_s *sub)
{
return sub->ols_sub_size + sub->ols_cat_size;
}
static inline size_t
os_log_subsystem_size(const struct os_log_subsystem_s *tbs)
{
assert(tbs->ols_sub_size <= OS_LOG_SUBSYSTEM_NAME_MAX_LEN);
assert(tbs->ols_cat_size <= OS_LOG_SUBSYSTEM_NAME_MAX_LEN);
return sizeof(*tbs) - sizeof(tbs->ols_name) + os_log_subsystem_id_length(tbs);
}
static void
os_log_subsystem_init(struct os_log_subsystem_s *ols, uint16_t sid, const char *sub, const char *cat)
{
ols->ols_sub_size = os_log_subsystem_name_size(sub);
ols->ols_cat_size = os_log_subsystem_name_size(cat);
strlcpy(&ols->ols_name[0], sub, OS_LOG_SUBSYSTEM_NAME_MAX_LEN);
strlcpy(&ols->ols_name[ols->ols_sub_size], cat, OS_LOG_SUBSYSTEM_NAME_MAX_LEN);
ols->ols_id = sid;
}
static void
os_log_subsystem_register(const struct os_log_subsystem_s *ols, uint64_t stamp)
{
assert(os_log_subsystem_id_valid(ols->ols_id));
firehose_tracepoint_id_u trace_id;
trace_id.ftid_value = FIREHOSE_TRACE_ID_MAKE(firehose_tracepoint_namespace_metadata,
_firehose_tracepoint_type_metadata_subsystem, 0, ols->ols_id);
os_log_encoded_metadata(trace_id, stamp, ols, os_log_subsystem_size(ols));
}
#if DEVELOPMENT || DEBUG
static bool
os_log_valid(const struct os_log_s *log)
{
return os_log_subsystem_id_valid(log->ol_subsystem.ols_id);
}
#endif // DEVELOPMENT || DEBUG
static smrh_key_t
os_log_key(const struct os_log_subsystem_s *sub)
{
return (smrh_key_t) {
.smrk_opaque = sub->ols_name,
.smrk_len = os_log_subsystem_id_length(sub)
};
}
static uint32_t
os_log_key_hash(smrh_key_t key, uint32_t seed)
{
return smrh_key_hash_mem(key, seed);
}
static bool
os_log_key_equ(smrh_key_t k1, smrh_key_t k2)
{
return k1.smrk_len == k2.smrk_len ? smrh_key_equ_mem(k1, k2) : false;
}
static uint32_t
os_log_hash(const struct smrq_slink *link, uint32_t seed)
{
const os_log_t log = __container_of(link, struct os_log_s, ol_hash_link);
return os_log_key_hash(os_log_key(&log->ol_subsystem), seed);
}
static bool
os_log_equ(const struct smrq_slink *link, smrh_key_t key)
{
const os_log_t h = __container_of(link, struct os_log_s, ol_hash_link);
return os_log_key_equ(os_log_key(&h->ol_subsystem), key);
}
static bool
oslog_try_get(void *oslog __unused)
{
return true;
}
SMRH_TRAITS_DEFINE(os_log_cache_traits, struct os_log_s, ol_hash_link,
.domain = &smr_oslog,
.key_hash = os_log_key_hash,
.key_equ = os_log_key_equ,
.obj_hash = os_log_hash,
.obj_equ = os_log_equ,
.obj_try_get = oslog_try_get
);
static os_log_t
os_log_cache_find_by_sub(const struct os_log_subsystem_s *sub)
{
os_log_t log = smr_hash_get(&os_log_cache, os_log_key(sub), &os_log_cache_traits);
assert(!log || os_log_valid(log));
return log;
}
static os_log_t
os_log_cache_insert(os_log_t log)
{
assert(os_log_subsystem_id_valid(log->ol_subsystem.ols_id));
os_log_t found = smr_hash_serialized_get_or_insert(&os_log_cache,
os_log_key(&log->ol_subsystem), &log->ol_hash_link,
&os_log_cache_traits);
assert(!found || os_log_valid(found));
return found;
}
static os_log_t
os_log_allocate(const struct os_log_subsystem_s *subsystem)
{
os_log_t new = kalloc_type(struct os_log_s, Z_WAITOK_ZERO);
if (new) {
new->ol_subsystem = *subsystem;
}
return new;
}
static uint16_t
os_log_subsystem_id_next(void)
{
assert(os_log_subsystem_id_valid(os_log_subsystem_id));
if (__improbable(os_log_subsystem_id == OS_LOG_SUBSYSTEM_LAST)) {
return OS_LOG_SUBSYSTEM_NONE;
}
return os_log_subsystem_id++;
}
static void
os_log_subsystem_id_revert(uint16_t __assert_only sid)
{
assert(os_log_subsystem_id_valid(os_log_subsystem_id));
assert3u(os_log_subsystem_id, ==, sid + 1);
os_log_subsystem_id--;
}
static os_log_t
os_log_create_impl(const char *subsystem, const char *category, uint64_t stamp)
{
if (os_log_disabled()) {
return OS_LOG_DISABLED;
}
struct os_log_subsystem_s new_sub;
os_log_subsystem_init(&new_sub, OS_LOG_SUBSYSTEM_NONE, subsystem, category);
os_log_t log = os_log_cache_find_by_sub(&new_sub);
if (log) {
counter_inc(&oslog_subsystem_found);
return log;
}
if (!(log = os_log_allocate(&new_sub))) {
counter_inc(&oslog_subsystem_dropped);
return OS_LOG_DEFAULT;
}
lck_ticket_lock(&oslog_cache_lock, &oslog_cache_lock_grp);
log->ol_subsystem.ols_id = os_log_subsystem_id_next();
if (__improbable(log->ol_subsystem.ols_id == OS_LOG_SUBSYSTEM_NONE)) {
lck_ticket_unlock(&oslog_cache_lock);
kfree_type(struct os_log_s, log);
counter_inc(&oslog_subsystem_dropped);
return OS_LOG_DEFAULT;
}
os_log_t found = os_log_cache_insert(log);
if (__improbable(found)) {
os_log_subsystem_id_revert(log->ol_subsystem.ols_id);
lck_ticket_unlock(&oslog_cache_lock);
kfree_type(struct os_log_s, log);
counter_inc(&oslog_subsystem_found);
return found;
}
lck_ticket_unlock(&oslog_cache_lock);
os_log_subsystem_register(&log->ol_subsystem, stamp);
counter_inc(&oslog_subsystem_count);
return log;
}
os_log_t
os_log_create(const char *subsystem, const char *category)
{
uint64_t stamp = firehose_tracepoint_time(firehose_activity_flags_default);
return os_log_create_impl(subsystem, category, stamp);
}
static void
_os_log_to_msgbuf_internal(const char *format, va_list args, uint64_t timestamp,
bool safe, bool logging, bool addcr)
{
/*
* The following threshold was determined empirically as the point where
* it would be more advantageous to be able to fit in more log lines than
* to know exactly when a log line was printed out. We don't want to use up
* a large percentage of the log buffer on timestamps in a memory-constricted
* environment.
*/
const int MSGBUF_TIMESTAMP_THRESHOLD = 4096;
static int msgbufreplay = -1;
static bool newlogline = true;
va_list args_copy;
if (!bsd_log_lock(safe)) {
counter_inc(&oslog_msgbuf_dropped_msgcount);
return;
}
if (!safe) {
if (-1 == msgbufreplay) {
msgbufreplay = msgbufp->msg_bufx;
}
} else if (logging && (-1 != msgbufreplay)) {
uint32_t i;
uint32_t localbuff_size;
int newl, position;
char *localbuff, *p, *s, *next, ch;
position = msgbufreplay;
msgbufreplay = -1;
localbuff_size = (msgbufp->msg_size + 2); /* + '\n' + '\0' */
/* Size for non-blocking */
if (localbuff_size > 4096) {
localbuff_size = 4096;
}
bsd_log_unlock();
/* Allocate a temporary non-circular buffer */
localbuff = kalloc_data(localbuff_size, Z_NOWAIT);
if (localbuff != NULL) {
/* in between here, the log could become bigger, but that's fine */
bsd_log_lock(true);
/*
* The message buffer is circular; start at the replay pointer, and
* make one loop up to write pointer - 1.
*/
p = msgbufp->msg_bufc + position;
for (i = newl = 0; p != msgbufp->msg_bufc + msgbufp->msg_bufx - 1; ++p) {
if (p >= msgbufp->msg_bufc + msgbufp->msg_size) {
p = msgbufp->msg_bufc;
}
ch = *p;
if (ch == '\0') {
continue;
}
newl = (ch == '\n');
localbuff[i++] = ch;
if (i >= (localbuff_size - 2)) {
break;
}
}
bsd_log_unlock();
if (!newl) {
localbuff[i++] = '\n';
}
localbuff[i++] = 0;
s = localbuff;
while ((next = strchr(s, '\n'))) {
next++;
ch = next[0];
next[0] = 0;
os_log(&_os_log_replay, "%s", s);
next[0] = ch;
s = next;
}
kfree_data(localbuff, localbuff_size);
}
bsd_log_lock(true);
}
/* Do not prepend timestamps when we are memory-constricted */
if (newlogline && (msgbufp->msg_size > MSGBUF_TIMESTAMP_THRESHOLD)) {
clock_sec_t secs;
clock_usec_t microsecs;
absolutetime_to_microtime(timestamp, &secs, µsecs);
printf_log_locked(FALSE, "[%5lu.%06u]: ", (unsigned long)secs, microsecs);
}
#pragma clang diagnostic push
#pragma clang diagnostic ignored "-Wformat-nonliteral"
va_copy(args_copy, args);
newlogline = vprintf_log_locked(format, args_copy, addcr);
va_end(args_copy);
#pragma clang diagnostic pop
bsd_log_unlock();
logwakeup();
counter_inc(&oslog_msgbuf_msgcount);
}
static void
_os_log_to_log_internal(uint16_t sid, os_log_type_t type, const char *fmt, va_list args,
uint64_t ts, void *addr, void *dso, bool driverKit)
{
dso = resolve_dso(fmt, dso, addr, driverKit);
if (__improbable(!dso)) {
counter_inc(&oslog_p_unresolved_kc_msgcount);
return;
}
firehose_tracepoint_flags_t flags = firehose_ftid_flags(dso, driverKit);
if (sid != 0) {
flags |= _firehose_tracepoint_flags_log_has_subsystem;
}
size_t loc_sz = 0;
uintptr_t loc = resolve_location(flags, (uintptr_t)dso, (uintptr_t)addr,
driverKit, &loc_sz);
firehose_tracepoint_id_u ftid = {
.ftid_value = firehose_ftid(type, fmt, flags, dso, addr, driverKit)
};
__attribute__((uninitialized, aligned(8)))
uint8_t buffer[OS_LOG_BUFFER_MAX_SIZE];
struct os_log_context_s ctx;
os_log_context_init(&ctx, &os_log_mem, buffer, sizeof(buffer));
if (!os_log_context_encode(&ctx, fmt, args, loc, loc_sz, sid)) {
counter_inc(&oslog_p_error_count);
os_log_context_free(&ctx);
return;
}
log_payload_s log;
log_payload_init(&log, firehose_stream(type), ftid, ts, ctx.ctx_content_sz, ctx.ctx_content_sz);
if (!log_queue_log(&log, ctx.ctx_buffer, true)) {
counter_inc(&oslog_p_dropped_msgcount);
}
os_log_context_free(&ctx);
}
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)
{
counter_inc(&oslog_p_total_msgcount);
if (oslog == OS_LOG_DISABLED) {
counter_inc(&oslog_p_dropped_msgcount);
return;
}
if (__improbable(fmt[0] == '\0')) {
counter_inc(&oslog_p_error_count);
return;
}
/* early boot can log to dmesg for later replay (27307943) */
bool safe = os_log_safe();
bool logging = !os_log_turned_off();
if (oslog != &_os_log_replay) {
_os_log_to_msgbuf_internal(fmt, args, ts, safe, logging, addcr);
}
if (safe && logging) {
const uint16_t sid = oslog->ol_subsystem.ols_id;
_os_log_to_log_internal(sid, type, fmt, args, ts, addr, dso, driverKit);
}
}
__attribute__((noinline, not_tail_called)) void
_os_log_internal(void *dso, os_log_t log, uint8_t type, const char *fmt, ...)
{
uint64_t ts = firehose_tracepoint_time(firehose_activity_flags_default);
void *addr = __builtin_return_address(0);
va_list args;
va_start(args, fmt);
_os_log_with_args_internal(log, type, fmt, args, ts, addr, dso, FALSE, FALSE);
va_end(args);
}
__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, ...)
{
void *addr = __builtin_return_address(0);
va_list args;
va_start(args, fmt);
_os_log_with_args_internal(log, type, fmt, args, ts, addr, dso, FALSE, FALSE);
va_end(args);
}
__attribute__((noinline, not_tail_called)) int
_os_log_internal_driverKit(void *dso, os_log_t log, uint8_t type, const char *fmt, ...)
{
uint64_t ts = firehose_tracepoint_time(firehose_activity_flags_default);
void *addr = __builtin_return_address(0);
bool driverKitLog = FALSE;
va_list args;
/*
* We want to be able to identify dexts from the logs.
*
* Usually the addr is used to understand if the log line
* was generated by a kext or the kernel main executable.
* Logd uses copyKextUUIDForAddress with the addr specified
* in the log line to retrieve the kext UUID of the sender.
*
* Dext however are not loaded in kernel space so they do not
* have a kernel range of addresses.
*
* To make the same mechanism work, OSKext fakes a kernel
* address range for dexts using the loadTag,
* so we just need to use the loadTag as addr here
* to allow logd to retrieve the correct UUID.
*
* NOTE: loadTag is populated in the task when the dext is matching,
* so if log lines are generated before the matching they will be
* identified as kernel main executable.
*/
task_t self_task = current_task();
/*
* Only dexts are supposed to use this log path. Verified in log_data()
* but worth of another check here in case this function gets called
* directly.
*/
if (!task_is_driver(self_task)) {
return EPERM;
}
uint64_t loadTag = get_task_loadTag(self_task);
if (loadTag != 0) {
driverKitLog = TRUE;
addr = (void *)loadTag;
}
va_start(args, fmt);
_os_log_with_args_internal(log, type, fmt, args, ts, addr, dso, driverKitLog, true);
va_end(args);
return 0;
}
__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)
{
uint64_t ts = firehose_tracepoint_time(firehose_activity_flags_default);
// if no address passed, look it up
if (addr == NULL) {
addr = __builtin_return_address(0);
}
_os_log_with_args_internal(oslog, type, fmt, args, ts, addr, NULL, FALSE, FALSE);
}
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)
{
counter_inc(&oslog_p_coprocessor_total_msgcount);
if (os_log_turned_off() || !os_log_safe()) {
counter_inc(&oslog_p_coprocessor_dropped_msgcount);
return false;
}
if (buff_len + 16 + sizeof(uint32_t) > OS_LOG_BUFFER_MAX_SIZE) {
counter_inc(&oslog_p_coprocessor_dropped_msgcount);
return false;
}
__attribute__((uninitialized))
uint8_t pubdata[OS_LOG_BUFFER_MAX_SIZE];
size_t wr_pos = 0;
memcpy(pubdata, &offset, sizeof(uint32_t));
wr_pos += sizeof(uint32_t);
memcpy(pubdata + wr_pos, uuid, 16);
wr_pos += 16;
memcpy(pubdata + wr_pos, buff, buff_len);
wr_pos += buff_len;
/*
* Unlike KEXTs, where PC is used to find UUID, in coprocessor logs the UUID
* is passed as part of the tracepoint.
*/
firehose_tracepoint_namespace_t ns = firehose_tracepoint_namespace_log;
firehose_tracepoint_flags_t flags = _firehose_tracepoint_flags_pc_style_uuid_relative;
firehose_tracepoint_id_u trace_id = {
.ftid_value = FIREHOSE_TRACE_ID_MAKE(ns, type, flags, offset)
};
log_payload_s log;
log_payload_init(&log, firehose_stream(type), trace_id, timestamp, wr_pos, wr_pos);
if (!log_queue_log(&log, pubdata, stream_log)) {
counter_inc(&oslog_p_coprocessor_dropped_msgcount);
return false;
}
return true;
}
static inline firehose_tracepoint_t
firehose_trace_start(const log_payload_s *lp, uint8_t **ft_priv_data)
{
uint16_t priv_data_size = (uint16_t)log_payload_priv_data_size(lp);
uint16_t pub_data_size = (uint16_t)lp->lp_pub_data_size;
if (priv_data_size > 0) {
pub_data_size += sizeof(struct firehose_buffer_range_s);
}
assert3u(offsetof(struct firehose_tracepoint_s, ft_data) +
pub_data_size + priv_data_size, <=, sizeof(((firehose_chunk_t)0)->fc_data));
firehose_tracepoint_t ft = __firehose_buffer_tracepoint_reserve(lp->lp_timestamp,
lp->lp_stream, pub_data_size, priv_data_size, ft_priv_data);
if (fastpath(ft)) {
oslog_boot_done = true;
return ft;
}
if (fastpath(oslog_boot_done)) {
return 0;
}
/*
* Early boot logging when kernel logging is up and running but logd is
* not yet ready. Only the persist firehose stream is available.
*/
long offset = firehose_chunk_tracepoint_try_reserve(&firehose_boot_chunk,
lp->lp_timestamp, firehose_stream_persist, 0, pub_data_size,
priv_data_size, ft_priv_data);
if (offset <= 0) {
counter_inc(&oslog_p_boot_dropped_msgcount);
return 0;
}
return firehose_chunk_tracepoint_begin(&firehose_boot_chunk,
lp->lp_timestamp, pub_data_size, thread_tid(current_thread()),
offset);
}
static inline void
firehose_trace_finish(firehose_tracepoint_t ft, firehose_tracepoint_id_u ftid)
{
if (__probable(oslog_boot_done)) {
__firehose_buffer_tracepoint_flush(ft, ftid);
} else {
firehose_chunk_tracepoint_end(&firehose_boot_chunk, ft, ftid);
}
}
static inline void
firehose_trace_save_payload(const log_payload_s *lp, const uint8_t *lp_data,
firehose_tracepoint_t ft, uint8_t *ft_priv_data)
{
const size_t priv_data_size = log_payload_priv_data_size(lp);
uint8_t *ft_data = ft->ft_data;
if (priv_data_size > 0) {
assert(FIREHOSE_TRACE_ID_HAS_FLAG(lp->lp_ftid, log, has_private_data));
memcpy(ft_priv_data, log_payload_priv_data(lp, lp_data), priv_data_size);
firehose_chunk_t fc = firehose_chunk_for_address(ft);
struct firehose_buffer_range_s range = {
.fbr_offset = (uint16_t)(ft_priv_data - fc->fc_start),
.fbr_length = (uint16_t)priv_data_size
};
memcpy(ft_data, &range, sizeof(range));
ft_data += sizeof(range);
}
memcpy(ft_data, lp_data, lp->lp_pub_data_size);
}
static inline void
log_stats_update_saved(firehose_stream_t stream)
{
if (__improbable(!oslog_boot_done)) {
stream = firehose_stream_persist;
}
switch (stream) {
case firehose_stream_metadata:
counter_inc(&oslog_p_metadata_saved_msgcount);
break;
case firehose_stream_persist:
case firehose_stream_memory:
counter_inc(&oslog_p_saved_msgcount);
break;
case firehose_stream_signpost:
counter_inc(&oslog_p_signpost_saved_msgcount);
break;
default:
panic("Unexpected firehose stream type %u", stream);
}
}
static inline firehose_tracepoint_id_t
firehose_trace(const log_payload_s *lp, const uint8_t *lp_data)
{
uint8_t *ft_priv_data = NULL;
firehose_tracepoint_t ft = firehose_trace_start(lp, &ft_priv_data);
if (fastpath(ft)) {
firehose_trace_save_payload(lp, lp_data, ft, ft_priv_data);
firehose_trace_finish(ft, lp->lp_ftid);
log_stats_update_saved(lp->lp_stream);
return lp->lp_ftid.ftid_value;
}
return 0;
}
static firehose_tracepoint_code_t
coproc_reg_type_to_firehost_code(os_log_coproc_reg_t reg_type)
{
switch (reg_type) {
case os_log_coproc_register_memory:
return firehose_tracepoint_code_load_memory;
case os_log_coproc_register_harvest_fs_ftab:
return firehose_tracepoint_code_load_filesystem_ftab;
default:
return firehose_tracepoint_code_invalid;
}
}
void
os_log_coprocessor_register_with_type(const char *uuid, const char *file_path, os_log_coproc_reg_t reg_type)
{
size_t path_size = strlen(file_path) + 1;
size_t uuid_info_len = sizeof(struct firehose_trace_uuid_info_s) + path_size;
if (os_log_disabled() || path_size > PATH_MAX) {
return;
}
__attribute__((uninitialized))
union {
struct firehose_trace_uuid_info_s uuid_info;
char path[PATH_MAX + sizeof(struct firehose_trace_uuid_info_s)];
} buf;
// write metadata to uuid_info
memcpy(buf.uuid_info.ftui_uuid, uuid, sizeof(uuid_t));
buf.uuid_info.ftui_size = 1;
buf.uuid_info.ftui_address = 1;
uint64_t stamp = firehose_tracepoint_time(firehose_activity_flags_default);
// create tracepoint id
firehose_tracepoint_id_u trace_id;
trace_id.ftid_value = FIREHOSE_TRACE_ID_MAKE(firehose_tracepoint_namespace_metadata,
_firehose_tracepoint_type_metadata_coprocessor, (firehose_tracepoint_flags_t)0,
coproc_reg_type_to_firehost_code(reg_type));
// write path to buffer
memcpy(buf.uuid_info.ftui_path, file_path, path_size);
// send metadata tracepoint to firehose for coprocessor registration in logd
os_log_encoded_metadata(trace_id, stamp, (void *)&buf, uuid_info_len);
}
bool
log_payload_send(log_payload_t lp, const void *lp_data, bool use_stream)
{
if (use_stream) {
bool is_metadata = (lp->lp_stream == firehose_stream_metadata);
oslog_stream(is_metadata, lp->lp_ftid, lp->lp_timestamp, lp_data, lp->lp_data_size);
}
return firehose_trace(lp, lp_data) != 0;
}
void
__firehose_buffer_push_to_logd(firehose_buffer_t fb __unused, bool for_io __unused)
{
oslogwakeup();
return;
}
void
__firehose_allocate(vm_offset_t *addr, vm_size_t size __unused)
{
firehose_chunk_t kernel_buffer = (firehose_chunk_t)kernel_firehose_addr;
if (kernel_firehose_addr) {
*addr = kernel_firehose_addr;
} else {
*addr = 0;
return;
}
// Now that we are done adding logs to this chunk, set the number of writers to 0
// Without this, logd won't flush when the page is full
firehose_boot_chunk.fc_pos.fcp_refcnt = 0;
memcpy(&kernel_buffer[FIREHOSE_BUFFER_KERNEL_CHUNK_COUNT - 1], (const void *)&firehose_boot_chunk, FIREHOSE_CHUNK_SIZE);
return;
}
// There isnt a lock held in this case.
void
__firehose_critical_region_enter(void)
{
disable_preemption();
return;
}
void
__firehose_critical_region_leave(void)
{
enable_preemption();
return;
}
#ifdef CONFIG_XNUPOST
static_assert(&_os_log_default == OS_LOG_DEFAULT,
"OS_LOG_DEFAULT is an alias to _os_log_default");
static_assert(OS_LOG_DISABLED == NULL,
"OS_LOG_DISABLED handle is defined as NULL");
#include <dev/random/randomdev.h>
#include <tests/xnupost.h>
typedef struct {
size_t total;
size_t saved;
size_t dropped;
size_t truncated;
size_t errors;
size_t errors_kc;
size_t errors_fmt;
size_t errors_max_args;
} log_stats_t;
#define TESTBUFLEN 256
#define TESTOSLOGFMT(fn_name) "%u^%llu/%llu^kernel^0^test^" fn_name
#define TESTOSLOGPFX "TESTLOG:%u#"
#define TESTOSLOG(fn_name) TESTOSLOGPFX TESTOSLOGFMT(fn_name "#")
#define LOG_STAT_CMP(cmp, b, a, e, stat, msg, test) \
{ \
size_t n##stat = (a)->stat - (b)->stat; \
size_t n##expected = (e)->stat; \
cmp(n##stat, n##expected, (msg), (test), n##expected); \
}
#define LOG_STAT_EQ(b, a, e, stat, msg, test) \
LOG_STAT_CMP(T_EXPECT_EQ_UINT, b, a, e, stat, msg, test)
#define LOG_STAT_GE(b, a, e, stat, msg, test) \
LOG_STAT_CMP(T_EXPECT_GE_UINT, b, a, e, stat, msg, test)
#define GENOSLOGHELPER(fname, ident, callout_f) \
static void \
fname(uint32_t uniqid, uint64_t count, log_stats_t *before, log_stats_t *after) \
{ \
uint32_t checksum = 0; \
char pattern[TESTBUFLEN]; \
T_LOG("Testing " ident "() with %d logs", count); \
log_stats_get(before); \
for (uint64_t i = 0; i < count; i++) { \
(void) save_pattern(pattern, &checksum, TESTOSLOGFMT(ident), uniqid, i + 1, count); \
callout_f(OS_LOG_DEFAULT, TESTOSLOG(ident), checksum, uniqid, i + 1, count); \
} \
log_stats_get(after); \
}
extern size_t find_pattern_in_buffer(const char *, size_t, size_t);
void test_oslog_handleOSLogCtl(int32_t *, int32_t *, int32_t);
kern_return_t test_printf(void);
kern_return_t test_os_log(void);
kern_return_t test_os_log_handles(void);
kern_return_t test_os_log_parallel(void);
SCALABLE_COUNTER_DECLARE(oslog_p_fmt_invalid_msgcount);
SCALABLE_COUNTER_DECLARE(oslog_p_fmt_max_args_msgcount);
SCALABLE_COUNTER_DECLARE(oslog_p_truncated_msgcount);
SCALABLE_COUNTER_DECLARE(log_queue_cnt_received);
static void
log_stats_get(log_stats_t *stats)
{
if (!stats) {
return;
}
stats->total = counter_load(&oslog_p_total_msgcount);
stats->saved = counter_load(&log_queue_cnt_received);
stats->dropped = counter_load(&oslog_p_dropped_msgcount);
stats->truncated = counter_load(&oslog_p_truncated_msgcount);
stats->errors = counter_load(&oslog_p_error_count);
stats->errors_kc = counter_load(&oslog_p_unresolved_kc_msgcount);
stats->errors_fmt = counter_load(&oslog_p_fmt_invalid_msgcount);
stats->errors_max_args = counter_load(&oslog_p_fmt_max_args_msgcount);
}
static void
log_stats_diff(const log_stats_t *before, const log_stats_t *after, log_stats_t *diff)
{
log_stats_t d = {};
if (before) {
d = *before;
}
if (after) {
d.total = after->total - d.total;
d.saved = after->saved - d.saved;
d.dropped = after->dropped - d.dropped;
d.truncated = after->truncated - d.truncated;
d.errors = after->errors - d.errors;
d.errors_kc = after->errors_kc - d.errors_kc;
d.errors_fmt = after->errors_fmt - d.errors_fmt;
d.errors_max_args = after->errors_max_args - d.errors_max_args;
}
*diff = d;
}
static void
log_stats_check_errors(const log_stats_t *before, const log_stats_t *after, const log_stats_t *expected,
const char *test)
{
LOG_STAT_EQ(before, after, expected, errors, "%s: Expected %lu encoding errors", test);
LOG_STAT_EQ(before, after, expected, errors_kc, "%s: Expected %lu DSO errors", test);
LOG_STAT_EQ(before, after, expected, errors_fmt, "%s: Expected %lu bad format errors", test);
LOG_STAT_EQ(before, after, expected, errors_max_args, "%s: Expected %lu max arguments errors", test);
}
static void
log_stats_check(const log_stats_t *before, const log_stats_t *after, const log_stats_t *expected,
const char *test)
{
/*
* The comparison is >= (_GE) for total and saved counters because tests
* are running while the system is up and potentially logging. Test and
* regular logs interfere rather rarely but can make the test flaky
* which is not desired.
*/
LOG_STAT_GE(before, after, expected, total, "%s: Expected %lu logs total", test);
LOG_STAT_GE(before, after, expected, saved, "%s: Expected %lu saved logs", test);
LOG_STAT_EQ(before, after, expected, dropped, "%s: Expected %lu logs dropped", test);
log_stats_check_errors(before, after, expected, test);
}
static void
log_stats_report(const log_stats_t *before, const log_stats_t *after, const char *test)
{
log_stats_t diff = {};
log_stats_diff(before, after, &diff);
T_LOG("\n%s: Logging stats:\n\ttotal: %u\n\tsaved: %u\n\tdropped: %u\n"
"\terrors: %u\n\terrors_kc: %u\n\terrors_fmt: %u\n\terrors_max_args: %u",
test, diff.total, diff.saved, diff.dropped,
diff.errors, diff.errors_kc, diff.errors_fmt, diff.errors_max_args);
}
static int
save_pattern(char buf[static TESTBUFLEN], uint32_t *crc, const char *fmt, ...)
{
va_list va;
va_start(va, fmt);
#pragma clang diagnostic push
#pragma clang diagnostic ignored "-Wformat-nonliteral"
int n = vscnprintf(buf, TESTBUFLEN, fmt, va);
#pragma clang diagnostic pop
va_end(va);
if (crc) {
*crc = crc32(0, buf, n);
}
return n;
}
/*
* Actual GENOSLOGHELPER() 2nd argument values below are expected by libtrace
* test_kern_oslog test suite and shall not be changed without updating given
* test suite.
*/
GENOSLOGHELPER(test_oslog_info, "oslog_info_helper", os_log_info);
GENOSLOGHELPER(test_oslog_fault, "oslog_fault_helper", os_log_fault);
GENOSLOGHELPER(test_oslog_debug, "oslog_debug_helper", os_log_debug);
GENOSLOGHELPER(test_oslog_error, "oslog_error_helper", os_log_error);
GENOSLOGHELPER(test_oslog_default, "oslog_default_helper", os_log);
kern_return_t
test_printf(void)
{
const uint32_t uniqid = RandomULong();
T_ASSERT_NE_UINT(0, uniqid, "Random number should not be zero");
uint64_t stamp = mach_absolute_time();
T_ASSERT_NE_ULLONG(0, stamp, "Absolute time should not be zero");
T_LOG("Validating with atm_diagnostic_config=%#x uniqid=%u stamp=%llu",
atm_get_diagnostic_config(), uniqid, stamp);
__attribute__((uninitialized))
char pattern[TESTBUFLEN];
log_stats_t before = {}, after = {};
uint32_t checksum = 0;
log_stats_get(&before);
(void) save_pattern(pattern, &checksum, TESTOSLOGFMT("printf_only"), uniqid, 1LL, 2LL);
printf(TESTOSLOG("printf_only") "mat%llu\n", checksum, uniqid, 1LL, 2LL, stamp);
(void) save_pattern(pattern, &checksum, TESTOSLOGFMT("printf_only"), uniqid, 2LL, 2LL);
printf(TESTOSLOG("printf_only") "mat%llu\n", checksum, uniqid, 2LL, 2LL, stamp);
size_t saved = save_pattern(pattern, NULL, "kernel^0^test^printf_only#mat%llu", stamp);
size_t match_count = find_pattern_in_buffer(pattern, saved, 2LL);
T_EXPECT_EQ_ULONG(match_count, 2LL, "printf() logs to msgbuf");
log_stats_get(&after);
if (!os_log_turned_off()) {
// printf() should log to OSLog with OSLog enabled.
log_stats_t expected = { .total = 2, .saved = 2 };
log_stats_check(&before, &after, &expected, "printf() logs to oslog");
}
log_stats_report(&before, &after, __FUNCTION__);
return KERN_SUCCESS;
}
static void
verify_os_log(struct os_log_s *h, char *sub, char *cat)
{
const size_t sub_len = os_log_subsystem_name_size(sub);
const size_t cat_len = os_log_subsystem_name_size(cat);
struct os_log_subsystem_s *s = &h->ol_subsystem;
T_ASSERT_EQ_STR(s->ols_name, sub, "Log subsystem name is %s", sub);
T_ASSERT_EQ_ULONG(s->ols_sub_size, sub_len, "Log subsystem size is %lu", sub_len);
T_ASSERT_EQ_ULONG(strlen(s->ols_name), sub_len - 1, "Log subsystem length is %lu", sub_len - 1);
T_ASSERT_EQ_STR(&s->ols_name[sub_len], cat, "Log category name is %s", cat);
T_ASSERT_EQ_ULONG(s->ols_cat_size, cat_len, "Log category length is %lu", cat_len);
T_ASSERT_EQ_ULONG(strlen(&s->ols_name[sub_len]), cat_len - 1, "Log category size is %lu", cat_len - 1);
}
static os_log_t
create_verified_os_log(char *sub, char *cat)
{
os_log_t h = os_log_create(sub, cat);
verify_os_log(h, sub, cat);
return h;
}
kern_return_t
test_os_log_handles(void)
{
os_log_t h1 = create_verified_os_log("xnu_post_subsystem1", "xnu_post_category1");
if (os_log_disabled()) {
T_ASSERT_EQ_PTR(h1, OS_LOG_DISABLED, "Disabled logging uses OS_LOG_DISABLED");
return KERN_SUCCESS;
}
T_ASSERT_NE_PTR(h1, OS_LOG_DEFAULT, "Custom log handle is not OS_LOG_DEFAULT");
os_log_t h2 = create_verified_os_log("xnu_post_subsystem1", "xnu_post_category1");
T_ASSERT_EQ_PTR(h1, h2, "os_log_create() finds an existing log handle in the cache");
h2 = create_verified_os_log("xnu_post_subsystem1", "xnu_post_category2");
T_ASSERT_NE_PTR(h1, h2, "Subsystem is not enough to identify a log handle");
h2 = create_verified_os_log("xnu_post_subsystem2", "xnu_post_category1");
T_ASSERT_NE_PTR(h1, h2, "Category is not enough to identify a log handle");
h2 = create_verified_os_log("xnu_post_subsystem3", "xnu_post_category3");
T_ASSERT_NE_PTR(h1, h2, "Different subsystem and category yield a different handle");
h1 = h2;
h2 = create_verified_os_log("xnu_post", "_subsystem3xnu_post_category3");
T_ASSERT_NE_PTR(h1, h2, "Subsystem and category cannot be mixed");
const size_t name_size = sizeof(h1->ol_subsystem.ols_name) / 2;
char super_long_sub[name_size] = {
[0 ... sizeof(super_long_sub) - 1] = 'X'
};
char super_long_cat[name_size] = {
[0 ... sizeof(super_long_sub) - 1] = 'Y'
};
h1 = os_log_create(super_long_sub, super_long_cat);
T_ASSERT_NE_PTR(h1, OS_LOG_DEFAULT, "Custom log handle is not OS_LOG_DEFAULT");
super_long_sub[name_size - 1] = '\0';
super_long_cat[name_size - 1] = '\0';
verify_os_log(h1, super_long_sub, super_long_cat);
return KERN_SUCCESS;
}
kern_return_t
test_os_log(void)
{
const uint32_t uniqid = RandomULong();
T_ASSERT_NE_UINT(0, uniqid, "Random number should not be zero");
uint64_t stamp = mach_absolute_time();
T_ASSERT_NE_ULLONG(0, stamp, "Absolute time should not be zero");
T_LOG("Validating with atm_diagnostic_config=%#x uniqid=%u stamp=%llu",
atm_get_diagnostic_config(), uniqid, stamp);
os_log_t log_handle = os_log_create("com.apple.xnu.test.t1", "kpost");
T_ASSERT_NE_PTR(OS_LOG_DEFAULT, log_handle, "Log handle is not OS_LOG_DEFAULT");
const bool enabled = !os_log_turned_off();
T_ASSERT_EQ_INT(enabled, os_log_info_enabled(log_handle), "Info log level is enabled");
T_ASSERT_EQ_INT(enabled, os_log_debug_enabled(log_handle), "Debug log level is enabled");
__attribute__((uninitialized))
char pattern[TESTBUFLEN];
uint32_t checksum = 0;
(void) save_pattern(pattern, &checksum, TESTOSLOGFMT("oslog_info"), uniqid, 1LL, 1LL);
os_log_info(log_handle, TESTOSLOG("oslog_info") "mat%llu", checksum, uniqid, 1LL, 1LL, stamp);
size_t saved = save_pattern(pattern, NULL, "kernel^0^test^oslog_info#mat%llu", stamp);
size_t match_count = find_pattern_in_buffer(pattern, saved, 1LL);
T_EXPECT_EQ_ULONG(match_count, 1LL, "oslog_info() logs to system message buffer");
const size_t n = 10;
log_stats_t expected = {
.total = enabled ? n : 0,
.saved = enabled ? n : 0
};
log_stats_t before = {}, after = {};
test_oslog_info(uniqid, n, &before, &after);
log_stats_check(&before, &after, &expected, "test_oslog_info");
test_oslog_debug(uniqid, n, &before, &after);
log_stats_check(&before, &after, &expected, "test_oslog_debug");
test_oslog_error(uniqid, n, &before, &after);
log_stats_check(&before, &after, &expected, "test_oslog_error");
test_oslog_default(uniqid, n, &before, &after);
log_stats_check(&before, &after, &expected, "test_oslog_default");
test_oslog_fault(uniqid, n, &before, &after);
log_stats_check(&before, &after, &expected, "test_oslog_fault");
log_stats_report(&before, &after, __FUNCTION__);
return KERN_SUCCESS;
}
static size_t _test_log_loop_count = 0;
static void
_test_log_loop(void *arg __unused, wait_result_t wres __unused)
{
test_oslog_debug(RandomULong(), 100, NULL, NULL);
os_atomic_add(&_test_log_loop_count, 100, relaxed);
}
kern_return_t
test_os_log_parallel(void)
{
if (os_log_turned_off()) {
T_LOG("Logging disabled, skipping tests.");
return KERN_SUCCESS;
}
thread_t thread[2];
kern_return_t kr;
log_stats_t after, before, expected = {};
log_stats_get(&before);
kr = kernel_thread_start(_test_log_loop, NULL, &thread[0]);
T_ASSERT_EQ_INT(kr, KERN_SUCCESS, "kernel_thread_start returned successfully");
kr = kernel_thread_start(_test_log_loop, NULL, &thread[1]);
T_ASSERT_EQ_INT(kr, KERN_SUCCESS, "kernel_thread_start returned successfully");
test_oslog_info(RandomULong(), 100, NULL, NULL);
/* wait until other thread has also finished */
while (_test_log_loop_count < 200) {
delay(1000);
}
thread_deallocate(thread[0]);
thread_deallocate(thread[1]);
log_stats_get(&after);
log_stats_check_errors(&before, &after, &expected, __FUNCTION__);
log_stats_report(&before, &after, __FUNCTION__);
return KERN_SUCCESS;
}
static kern_return_t
test_stresslog_dropmsg(const uint32_t uniqid)
{
if (os_log_turned_off()) {
T_LOG("Logging disabled, skipping tests.");
return KERN_SUCCESS;
}
log_stats_t after, before, expected = {};
test_oslog_debug(uniqid, 100, &before, &after);
while ((after.dropped - before.dropped) == 0) {
test_oslog_debug(uniqid, 100, NULL, &after);
}
log_stats_check_errors(&before, &after, &expected, __FUNCTION__);
log_stats_report(&before, &after, __FUNCTION__);
return KERN_SUCCESS;
}
void
test_oslog_handleOSLogCtl(int32_t *in, int32_t *out, int32_t len)
{
if (!in || !out || len != 4) {
return;
}
switch (in[0]) {
case 1:
{
/* send out counters */
out[1] = counter_load(&oslog_p_total_msgcount);
out[2] = counter_load(&oslog_p_saved_msgcount);
out[3] = counter_load(&oslog_p_dropped_msgcount);
out[0] = KERN_SUCCESS;
break;
}
case 2:
{
/* mini stress run */
out[0] = test_os_log_parallel();
break;
}
case 3:
{
/* drop msg tests */
out[1] = RandomULong();
out[0] = test_stresslog_dropmsg(out[1]);
break;
}
case 4:
{
/* invoke log helpers */
uint32_t uniqid = in[3];
int32_t msgcount = in[2];
if (uniqid == 0 || msgcount == 0) {
out[0] = KERN_INVALID_VALUE;
return;
}
switch (in[1]) {
case OS_LOG_TYPE_INFO:
test_oslog_info(uniqid, msgcount, NULL, NULL);
break;
case OS_LOG_TYPE_DEBUG:
test_oslog_debug(uniqid, msgcount, NULL, NULL);
break;
case OS_LOG_TYPE_ERROR:
test_oslog_error(uniqid, msgcount, NULL, NULL);
break;
case OS_LOG_TYPE_FAULT:
test_oslog_fault(uniqid, msgcount, NULL, NULL);
break;
case OS_LOG_TYPE_DEFAULT:
default:
test_oslog_default(uniqid, msgcount, NULL, NULL);
break;
}
out[0] = KERN_SUCCESS;
break;
/* end of case 4 */
}
default:
{
out[0] = KERN_INVALID_VALUE;
break;
}
}
return;
}
#endif /* CONFIG_XNUPOST */