X-Git-Url: https://git.saurik.com/apple/xnu.git/blobdiff_plain/813fb2f63a553c957e917ede5f119b021d6ce391..eb6b6ca394357805f2bdba989abae309f718b4d8:/libkern/os/log.c?ds=sidebyside diff --git a/libkern/os/log.c b/libkern/os/log.c index a2638fee5..dd4478913 100644 --- a/libkern/os/log.c +++ b/libkern/os/log.c @@ -1,3 +1,5 @@ +/* * Copyright (c) 2019 Apple Inc. All rights reserved. */ + #include #undef offset @@ -23,6 +25,7 @@ #include #include #include +#include #include #include @@ -34,6 +37,15 @@ #include "log_encode.h" +/* on embedded, with no kext loading or unloads, + * make the kernel use the libtrace shared cache path for logging + */ +#define FIREHOSE_USES_SHARED_CACHE NO_KEXTD + +#if FIREHOSE_USES_SHARED_CACHE +extern vm_offset_t segLOWESTTEXT; +#endif + struct os_log_s { int a; }; @@ -45,12 +57,15 @@ extern firehose_chunk_t firehose_boot_chunk; extern void bsd_log_lock(void); extern void bsd_log_unlock(void); -extern void logwakeup(void); +extern void logwakeup(struct msgbuf *); + +decl_lck_spin_data(extern, oslog_stream_lock); +#define stream_lock() lck_spin_lock(&oslog_stream_lock) +#define stream_unlock() lck_spin_unlock(&oslog_stream_lock) -decl_lck_spin_data(extern, oslog_stream_lock) extern void oslog_streamwakeup(void); void oslog_streamwrite_locked(firehose_tracepoint_id_u ftid, - uint64_t stamp, const void *pubdata, size_t publen); + uint64_t stamp, const void *pubdata, size_t publen); extern void oslog_streamwrite_metadata_locked(oslog_stream_buf_entry_t m_entry); extern int oslog_stream_open; @@ -72,36 +87,41 @@ uint32_t oslog_s_error_count = 0; uint32_t oslog_s_metadata_msgcount = 0; static bool oslog_boot_done = false; -extern boolean_t oslog_early_boot_complete; +extern boolean_t early_boot_complete; + +#ifdef XNU_KERNEL_PRIVATE +bool startup_serial_logging_active = true; +uint64_t startup_serial_num_procs = 300; +#endif /* XNU_KERNEL_PRIVATE */ // XXX firehose_tracepoint_id_t firehose_debug_trace(firehose_stream_t stream, firehose_tracepoint_id_t trace_id, - uint64_t timestamp, const char *format, const void *pubdata, size_t publen); + uint64_t timestamp, const char *format, const void *pubdata, size_t publen); static inline firehose_tracepoint_id_t _firehose_trace(firehose_stream_t stream, firehose_tracepoint_id_u ftid, - uint64_t stamp, const void *pubdata, size_t publen); + uint64_t stamp, const void *pubdata, size_t publen); static oslog_stream_buf_entry_t oslog_stream_create_buf_entry(oslog_stream_link_type_t type, firehose_tracepoint_id_u ftid, - uint64_t stamp, const void* pubdata, size_t publen); + uint64_t stamp, const void* pubdata, size_t publen); static void _os_log_with_args_internal(os_log_t oslog __unused, os_log_type_t type __unused, - const char *format, va_list args, void *addr, void *dso); + const char *format, va_list args, void *addr, void *dso, bool driverKit, bool addcr); static void -_os_log_to_msgbuf_internal(const char *format, va_list args, bool safe, bool logging); +_os_log_to_msgbuf_internal(const char *format, va_list args, bool safe, bool logging, bool addcr); static void _os_log_to_log_internal(os_log_t oslog, os_log_type_t type, - const char *format, va_list args, void *addr, void *dso); + const char *format, va_list args, void *addr, void *dso, bool driverKit); static void _os_log_actual(os_log_t oslog, os_log_type_t type, const char *format, void - *dso, void *addr, os_log_buffer_context_t context); + *dso, void *addr, os_log_buffer_context_t context, bool driverKit); bool os_log_info_enabled(os_log_t log __unused) @@ -127,205 +147,310 @@ _os_log_string_is_public(const char *str __unused) return true; } -__attribute__((noinline,not_tail_called)) void +__attribute__((noinline, not_tail_called)) void _os_log_internal(void *dso, os_log_t log, uint8_t type, const char *message, ...) { - va_list args; - void *addr = __builtin_return_address(0); + va_list args; + void *addr = __builtin_return_address(0); - va_start(args, message); + va_start(args, message); - _os_log_with_args_internal(log, type, message, args, addr, dso); + _os_log_with_args_internal(log, type, message, args, addr, dso, FALSE, FALSE); - va_end(args); + va_end(args); - return; + return; +} + +__attribute__((noinline, not_tail_called)) int +_os_log_internal_driverKit(void *dso, os_log_t log, uint8_t type, const char *message, ...) +{ + va_list args; + void *addr = __builtin_return_address(0); + bool driverKitLog = FALSE; + + /* + * 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 dextis are supposed to use this log path. + */ + 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, message); + + _os_log_with_args_internal(log, type, message, args, addr, dso, driverKitLog, true); + + va_end(args); + + return 0; } #pragma mark - shim functions -__attribute__((noinline,not_tail_called)) void +__attribute__((noinline, not_tail_called)) void os_log_with_args(os_log_t oslog, os_log_type_t type, const char *format, va_list args, void *addr) { - // if no address passed, look it up - if (addr == NULL) { - addr = __builtin_return_address(0); - } + // if no address passed, look it up + if (addr == NULL) { + addr = __builtin_return_address(0); + } - _os_log_with_args_internal(oslog, type, format, args, addr, NULL); + _os_log_with_args_internal(oslog, type, format, args, addr, NULL, FALSE, FALSE); } static void _os_log_with_args_internal(os_log_t oslog, os_log_type_t type, - const char *format, va_list args, void *addr, void *dso) + const char *format, va_list args, void *addr, void *dso, bool driverKit, bool addcr) { - uint32_t logging_config = atm_get_diagnostic_config(); - boolean_t safe; - boolean_t logging; + uint32_t logging_config = atm_get_diagnostic_config(); + boolean_t safe; + boolean_t logging; - if (format[0] == '\0') { - return; - } - /* cf. r24974766 & r25201228*/ - safe = (!oslog_early_boot_complete || oslog_is_safe()); - logging = (!(logging_config & ATM_TRACE_DISABLE) || !(logging_config & ATM_TRACE_OFF)); + if (format[0] == '\0') { + return; + } - if (oslog != &_os_log_replay) { - _os_log_to_msgbuf_internal(format, args, safe, logging); - } + /* early boot can log to dmesg for later replay (27307943) */ + safe = (!early_boot_complete || oslog_is_safe()); - if (safe && logging) { - _os_log_to_log_internal(oslog, type, format, args, addr, dso); - } + if (logging_config & ATM_TRACE_DISABLE || logging_config & ATM_TRACE_OFF) { + logging = false; + } else { + logging = true; + } + + if (oslog != &_os_log_replay) { + _os_log_to_msgbuf_internal(format, args, safe, logging, addcr); + } + + if (safe && logging) { + _os_log_to_log_internal(oslog, type, format, args, addr, dso, driverKit); + } } static void -_os_log_to_msgbuf_internal(const char *format, va_list args, bool safe, bool logging) +_os_log_to_msgbuf_internal(const char *format, va_list args, bool safe, bool logging, bool addcr) { - static int msgbufreplay = -1; - va_list args_copy; - - bsd_log_lock(); - - 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 */ - if ((localbuff = (char *)kalloc_noblock(localbuff_size))) { - /* in between here, the log could become bigger, but that's fine */ - bsd_log_lock(); - /* - * 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(localbuff, localbuff_size); - } - bsd_log_lock(); - } + static int msgbufreplay = -1; + va_list args_copy; + +#if DEVELOPMENT || DEBUG + if (safe) { + bsd_log_lock(); + } +#else + bsd_log_lock(); +#endif - va_copy(args_copy, args); - vprintf_log_locked(format, args_copy); - va_end(args_copy); + 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 */ + if ((localbuff = (char *)kalloc_noblock(localbuff_size))) { + /* in between here, the log could become bigger, but that's fine */ + bsd_log_lock(); + /* + * 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(); - 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(localbuff, localbuff_size); + } + bsd_log_lock(); + } - if (safe) logwakeup(); + va_copy(args_copy, args); + vprintf_log_locked(format, args_copy, addcr); + va_end(args_copy); + +#if DEVELOPMENT || DEBUG + if (safe) { + bsd_log_unlock(); + logwakeup(msgbufp); + } +#else + bsd_log_unlock(); + if (safe) { + logwakeup(msgbufp); + } +#endif } static void _os_log_to_log_internal(os_log_t oslog, os_log_type_t type, - const char *format, va_list args, void *addr, void *dso) + const char *format, va_list args, void *addr, void *dso, bool driverKit) { - struct os_log_buffer_context_s context; - unsigned char buffer_data[OS_LOG_BUFFER_MAX_SIZE] __attribute__((aligned(8))); - os_log_buffer_t buffer = (os_log_buffer_t)buffer_data; - uint8_t pubdata[OS_LOG_BUFFER_MAX_SIZE]; - va_list args_copy; - - if (dso == NULL) { - dso = (void *) OSKextKextForAddress(format); - if (dso == NULL) { - return; - } - } + struct os_log_buffer_context_s context; + unsigned char buffer_data[OS_LOG_BUFFER_MAX_SIZE] __attribute__((aligned(8))); + os_log_buffer_t buffer = (os_log_buffer_t)buffer_data; + uint8_t pubdata[OS_LOG_BUFFER_MAX_SIZE]; + va_list args_copy; - if (!_os_trace_addr_in_text_segment(dso, format)) { - return; - } + if (addr == NULL) { + return; + } - if (addr == NULL) { - return; - } +#if FIREHOSE_USES_SHARED_CACHE + dso = (void *) segLOWESTTEXT; +#else /* FIREHOSE_USES_SHARED_CACHE */ + if (dso == NULL) { + dso = (void *) OSKextKextForAddress(format); + if (dso == NULL) { + return; + } + } - void *dso_addr = (void *) OSKextKextForAddress(addr); - if (dso != dso_addr) { - return; - } + if (!_os_trace_addr_in_text_segment(dso, format)) { + return; + } + if (!driverKit) { + void *dso_addr = (void *) OSKextKextForAddress(addr); + if (dso != dso_addr) { + return; + } + } +#endif /* FIREHOSE_USES_SHARED_CACHE */ - memset(&context, 0, sizeof(context)); - memset(buffer, 0, OS_LOG_BUFFER_MAX_SIZE); + memset(&context, 0, sizeof(context)); + memset(buffer, 0, OS_LOG_BUFFER_MAX_SIZE); - context.shimmed = true; - context.buffer = buffer; - context.content_sz = OS_LOG_BUFFER_MAX_SIZE - sizeof(*buffer); - context.pubdata = pubdata; - context.pubdata_sz = sizeof(pubdata); + context.shimmed = true; + context.buffer = buffer; + context.content_sz = OS_LOG_BUFFER_MAX_SIZE - sizeof(*buffer); + context.pubdata = pubdata; + context.pubdata_sz = sizeof(pubdata); - va_copy(args_copy, args); + va_copy(args_copy, args); - (void)hw_atomic_add(&oslog_p_total_msgcount, 1); - if (_os_log_encode(format, args_copy, 0, &context)) { - _os_log_actual(oslog, type, format, dso, addr, &context); - } - else { - (void)hw_atomic_add(&oslog_p_error_count, 1); - } + os_atomic_inc(&oslog_p_total_msgcount, relaxed); + if (_os_log_encode(format, args_copy, 0, &context)) { + _os_log_actual(oslog, type, format, dso, addr, &context, driverKit); + } else { + os_atomic_inc(&oslog_p_error_count, relaxed); + } - va_end(args_copy); + va_end(args_copy); } static inline size_t _os_trace_write_location_for_address(uint8_t buf[static sizeof(uint64_t)], - void *dso, const void *address, firehose_tracepoint_flags_t *flags) + void *dso, const void *address, firehose_tracepoint_flags_t *flags, __unused bool driverKit) { + uintptr_t shift_addr = (uintptr_t)address - (uintptr_t)dso; +#if FIREHOSE_USES_SHARED_CACHE + + *flags = _firehose_tracepoint_flags_pc_style_shared_cache; + memcpy(buf, (uint32_t[]){ shift_addr }, + sizeof(uint32_t)); + return sizeof(uint32_t); + +#else /* FIREHOSE_USES_SHARED_CACHE */ kernel_mach_header_t *mh = dso; - if (mh->filetype == MH_EXECUTE) { + /* + * 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. + */ + if (mh->filetype == MH_EXECUTE && !driverKit) { *flags = _firehose_tracepoint_flags_pc_style_main_exe; - memcpy(buf, (uint32_t[]){ (uintptr_t)address - (uintptr_t)dso }, - sizeof(uint32_t)); + memcpy(buf, (uint32_t[]){ shift_addr}, sizeof(uint32_t)); return sizeof(uint32_t); } else { *flags = _firehose_tracepoint_flags_pc_style_absolute; - memcpy(buf, (uintptr_t[]){ VM_KERNEL_UNSLIDE(address) }, sizeof(uintptr_t)); + if (!driverKit) { + shift_addr = VM_KERNEL_UNSLIDE(address); + } else { + shift_addr = (uintptr_t) address; + } + memcpy(buf, (uintptr_t[]){ shift_addr }, sizeof(uintptr_t)); #if __LP64__ return 6; // 48 bits are enough #else return sizeof(uintptr_t); #endif } +#endif /* !FIREHOSE_USES_SHARED_CACHE */ } OS_ALWAYS_INLINE static inline size_t _os_log_buffer_pack(uint8_t *buffdata, size_t buffdata_sz, - os_log_buffer_context_t ctx) + os_log_buffer_context_t ctx) { os_log_buffer_t buffer = ctx->buffer; size_t buffer_sz = sizeof(*ctx->buffer) + ctx->content_sz; @@ -342,7 +467,7 @@ _os_log_buffer_pack(uint8_t *buffdata, size_t buffdata_sz, static void _os_log_actual(os_log_t oslog __unused, os_log_type_t type, const char *format, - void *dso, void *addr, os_log_buffer_context_t context) + void *dso, void *addr, os_log_buffer_context_t context, bool driverKit) { firehose_stream_t stream; firehose_tracepoint_flags_t flags = 0; @@ -353,9 +478,9 @@ _os_log_actual(os_log_t oslog __unused, os_log_type_t type, const char *format, uint64_t thread_id; // dso == the start of the binary that was loaded - addr_len = _os_trace_write_location_for_address(buffdata, dso, addr, &flags); + addr_len = _os_trace_write_location_for_address(buffdata, dso, addr, &flags, driverKit); buffdata_sz = _os_log_buffer_pack(buffdata + addr_len, - sizeof(buffdata) - addr_len, context); + sizeof(buffdata) - addr_len, context); if (buffdata_sz == 0) { return; } @@ -364,18 +489,24 @@ _os_log_actual(os_log_t oslog __unused, os_log_type_t type, const char *format, timestamp = firehose_tracepoint_time(firehose_activity_flags_default); thread_id = thread_tid(current_thread()); - // create trace_id after we've set additional flags - trace_id.ftid_value = FIREHOSE_TRACE_ID_MAKE(firehose_tracepoint_namespace_log, - type, flags, _os_trace_offset(dso, format, flags)); + if (driverKit) { + // set FIREHOSE_TRACEPOINT_PC_DYNAMIC_BIT so logd will not try to find the format string in + // the executable text + trace_id.ftid_value = FIREHOSE_TRACE_ID_MAKE(firehose_tracepoint_namespace_log, + type, flags, (uintptr_t) addr | FIREHOSE_TRACEPOINT_PC_DYNAMIC_BIT); + } else { + // create trace_id after we've set additional flags + trace_id.ftid_value = FIREHOSE_TRACE_ID_MAKE(firehose_tracepoint_namespace_log, + type, flags, _os_trace_offset(dso, format, (_firehose_tracepoint_flags_activity_t)flags)); + } if (FALSE) { firehose_debug_trace(stream, trace_id.ftid_value, timestamp, - format, buffdata, buffdata_sz); + format, buffdata, buffdata_sz); } if (type == OS_LOG_TYPE_INFO || type == OS_LOG_TYPE_DEBUG) { stream = firehose_stream_memory; - } - else { + } else { stream = firehose_stream_persist; } _firehose_trace(stream, trace_id, timestamp, buffdata, buffdata_sz); @@ -383,31 +514,30 @@ _os_log_actual(os_log_t oslog __unused, os_log_type_t type, const char *format, static inline firehose_tracepoint_id_t _firehose_trace(firehose_stream_t stream, firehose_tracepoint_id_u ftid, - uint64_t stamp, const void *pubdata, size_t publen) + uint64_t stamp, const void *pubdata, size_t publen) { const uint16_t ft_size = offsetof(struct firehose_tracepoint_s, ft_data); const size_t _firehose_chunk_payload_size = - sizeof(((struct firehose_chunk_s *)0)->fc_data); + sizeof(((struct firehose_chunk_s *)0)->fc_data); firehose_tracepoint_t ft; if (slowpath(ft_size + publen > _firehose_chunk_payload_size)) { // We'll need to have some handling here. For now - return 0 - (void)hw_atomic_add(&oslog_p_error_count, 1); + os_atomic_inc(&oslog_p_error_count, relaxed); return 0; } if (oslog_stream_open && (stream != firehose_stream_metadata)) { - - lck_spin_lock(&oslog_stream_lock); + stream_lock(); if (!oslog_stream_open) { - lck_spin_unlock(&oslog_stream_lock); + stream_unlock(); goto out; } oslog_s_total_msgcount++; oslog_streamwrite_locked(ftid, stamp, pubdata, publen); - lck_spin_unlock(&oslog_stream_lock); + stream_unlock(); oslog_streamwakeup(); } @@ -416,12 +546,11 @@ out: if (!fastpath(ft)) { if (oslog_boot_done) { if (stream == firehose_stream_metadata) { - (void)hw_atomic_add(&oslog_p_metadata_dropped_msgcount, 1); - } - else { + os_atomic_inc(&oslog_p_metadata_dropped_msgcount, relaxed); + } else { // If we run out of space in the persistence buffer we're // dropping the message. - (void)hw_atomic_add(&oslog_p_dropped_msgcount, 1); + os_atomic_inc(&oslog_p_dropped_msgcount, relaxed); } return 0; } @@ -430,17 +559,17 @@ out: //only stream available during boot is persist offset = firehose_chunk_tracepoint_try_reserve(fbc, stamp, - firehose_stream_persist, 0, publen, 0, NULL); + firehose_stream_persist, 0, publen, 0, NULL); if (offset <= 0) { - (void)hw_atomic_add(&oslog_p_boot_dropped_msgcount, 1); + os_atomic_inc(&oslog_p_boot_dropped_msgcount, relaxed); return 0; } ft = firehose_chunk_tracepoint_begin(fbc, stamp, publen, - thread_tid(current_thread()), offset); + thread_tid(current_thread()), offset); memcpy(ft->ft_data, pubdata, publen); firehose_chunk_tracepoint_end(fbc, ft, ftid); - (void)hw_atomic_add(&oslog_p_saved_msgcount, 1); + os_atomic_inc(&oslog_p_saved_msgcount, relaxed); return ftid.ftid_value; } if (!oslog_boot_done) { @@ -450,17 +579,16 @@ out: __firehose_buffer_tracepoint_flush(ft, ftid); if (stream == firehose_stream_metadata) { - (void)hw_atomic_add(&oslog_p_metadata_saved_msgcount, 1); - } - else { - (void)hw_atomic_add(&oslog_p_saved_msgcount, 1); + os_atomic_inc(&oslog_p_metadata_saved_msgcount, relaxed); + } else { + os_atomic_inc(&oslog_p_saved_msgcount, relaxed); } return ftid.ftid_value; } static oslog_stream_buf_entry_t oslog_stream_create_buf_entry(oslog_stream_link_type_t type, firehose_tracepoint_id_u ftid, - uint64_t stamp, const void* pubdata, size_t publen) + uint64_t stamp, const void* pubdata, size_t publen) { oslog_stream_buf_entry_t m_entry = NULL; firehose_tracepoint_t ft = NULL; @@ -471,7 +599,7 @@ oslog_stream_create_buf_entry(oslog_stream_link_type_t type, firehose_tracepoint } m_entry_len = sizeof(struct oslog_stream_buf_entry_s) + - sizeof(struct firehose_tracepoint_s) + publen; + sizeof(struct firehose_tracepoint_s) + publen; m_entry = (oslog_stream_buf_entry_t) kalloc(m_entry_len); if (!m_entry) { return NULL; @@ -493,38 +621,38 @@ oslog_stream_create_buf_entry(oslog_stream_link_type_t type, firehose_tracepoint #ifdef KERNEL void firehose_trace_metadata(firehose_stream_t stream, firehose_tracepoint_id_u ftid, - uint64_t stamp, const void *pubdata, size_t publen) + uint64_t stamp, const void *pubdata, size_t publen) { oslog_stream_buf_entry_t m_entry = NULL; // If streaming mode is not on, only log the metadata // in the persistence buffer - lck_spin_lock(&oslog_stream_lock); + stream_lock(); if (!oslog_stream_open) { - lck_spin_unlock(&oslog_stream_lock); + stream_unlock(); goto finish; } - lck_spin_unlock(&oslog_stream_lock); + stream_unlock(); // Setup and write the stream metadata entry m_entry = oslog_stream_create_buf_entry(oslog_stream_link_type_metadata, ftid, - stamp, pubdata, publen); + stamp, pubdata, publen); if (!m_entry) { - (void)hw_atomic_add(&oslog_s_error_count, 1); + os_atomic_inc(&oslog_s_error_count, relaxed); goto finish; } - lck_spin_lock(&oslog_stream_lock); + stream_lock(); if (!oslog_stream_open) { - lck_spin_unlock(&oslog_stream_lock); + stream_unlock(); kfree(m_entry, sizeof(struct oslog_stream_buf_entry_s) + - sizeof(struct firehose_tracepoint_s) + publen); + sizeof(struct firehose_tracepoint_s) + publen); goto finish; } oslog_s_metadata_msgcount++; oslog_streamwrite_metadata_locked(m_entry); - lck_spin_unlock(&oslog_stream_lock); + stream_unlock(); finish: _firehose_trace(stream, ftid, stamp, pubdata, publen); @@ -533,63 +661,324 @@ finish: firehose_tracepoint_id_t firehose_debug_trace(firehose_stream_t stream, firehose_tracepoint_id_t trace_id, - uint64_t timestamp, const char *format, const void *pubdata, size_t publen) + uint64_t timestamp, const char *format, const void *pubdata, size_t publen) { kprintf("[os_log stream 0x%x trace_id 0x%llx timestamp %llu format '%s' data %p len %lu]\n", - (unsigned int)stream, (unsigned long long)trace_id, timestamp, - format, pubdata, publen); + (unsigned int)stream, (unsigned long long)trace_id, timestamp, + format, pubdata, publen); size_t i; const unsigned char *cdata = (const unsigned char *)pubdata; - for (i=0; i < publen; i += 8) { + for (i = 0; i < publen; i += 8) { kprintf(">oslog 0x%08x: 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x\n", - (unsigned int)i, - (i+0) < publen ? cdata[i+0] : 0, - (i+1) < publen ? cdata[i+1] : 0, - (i+2) < publen ? cdata[i+2] : 0, - (i+3) < publen ? cdata[i+3] : 0, - (i+4) < publen ? cdata[i+4] : 0, - (i+5) < publen ? cdata[i+5] : 0, - (i+6) < publen ? cdata[i+6] : 0, - (i+7) < publen ? cdata[i+7] : 0 - ); + (unsigned int)i, + (i + 0) < publen ? cdata[i + 0] : 0, + (i + 1) < publen ? cdata[i + 1] : 0, + (i + 2) < publen ? cdata[i + 2] : 0, + (i + 3) < publen ? cdata[i + 3] : 0, + (i + 4) < publen ? cdata[i + 4] : 0, + (i + 5) < publen ? cdata[i + 5] : 0, + (i + 6) < publen ? cdata[i + 6] : 0, + (i + 7) < publen ? cdata[i + 7] : 0 + ); } return trace_id; } void -__firehose_buffer_push_to_logd(firehose_buffer_t fb __unused, bool for_io __unused) { - oslogwakeup(); - return; +__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; + 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; +__firehose_critical_region_enter(void) +{ + disable_preemption(); + return; +} + +void +__firehose_critical_region_leave(void) +{ + enable_preemption(); + return; +} + +#ifdef CONFIG_XNUPOST + +#include +#define TESTOSLOGFMT(fn_name) "%u^%llu/%llu^kernel^0^test^" fn_name +#define TESTOSLOGPFX "TESTLOG:%u#" +#define TESTOSLOG(fn_name) TESTOSLOGPFX TESTOSLOGFMT(fn_name "#") + +extern u_int32_t RandomULong(void); +extern uint32_t find_pattern_in_buffer(char * pattern, uint32_t len, int expected_count); +void test_oslog_default_helper(uint32_t uniqid, uint64_t count); +void test_oslog_info_helper(uint32_t uniqid, uint64_t count); +void test_oslog_debug_helper(uint32_t uniqid, uint64_t count); +void test_oslog_error_helper(uint32_t uniqid, uint64_t count); +void test_oslog_fault_helper(uint32_t uniqid, uint64_t count); +void _test_log_loop(void * arg __unused, wait_result_t wres __unused); +void test_oslog_handleOSLogCtl(int32_t * in, int32_t * out, int32_t len); +kern_return_t test_stresslog_dropmsg(uint32_t uniqid); + +kern_return_t test_os_log(void); +kern_return_t test_os_log_parallel(void); + +#define GENOSLOGHELPER(fname, ident, callout_f) \ + void fname(uint32_t uniqid, uint64_t count) \ + { \ + int32_t datalen = 0; \ + uint32_t checksum = 0; \ + char databuffer[256]; \ + T_LOG("Doing os_log of %llu TESTLOG msgs for fn " ident, count); \ + for (uint64_t i = 0; i < count; i++) \ + { \ + datalen = scnprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT(ident), uniqid, i + 1, count); \ + checksum = crc32(0, databuffer, datalen); \ + callout_f(OS_LOG_DEFAULT, TESTOSLOG(ident), checksum, uniqid, i + 1, count); \ + /*T_LOG(TESTOSLOG(ident), checksum, uniqid, i + 1, count);*/ \ + } \ + } + +GENOSLOGHELPER(test_oslog_info_helper, "oslog_info_helper", os_log_info); +GENOSLOGHELPER(test_oslog_fault_helper, "oslog_fault_helper", os_log_fault); +GENOSLOGHELPER(test_oslog_debug_helper, "oslog_debug_helper", os_log_debug); +GENOSLOGHELPER(test_oslog_error_helper, "oslog_error_helper", os_log_error); +GENOSLOGHELPER(test_oslog_default_helper, "oslog_default_helper", os_log); + +kern_return_t +test_os_log() +{ + char databuffer[256]; + uint32_t uniqid = RandomULong(); + uint32_t match_count = 0; + uint32_t checksum = 0; + uint32_t total_msg = 0; + uint32_t saved_msg = 0; + uint32_t dropped_msg = 0; + int datalen = 0; + uint64_t a = mach_absolute_time(); + uint64_t seqno = 1; + uint64_t total_seqno = 2; + + os_log_t log_handle = os_log_create("com.apple.xnu.test.t1", "kpost"); + + T_ASSERT_EQ_PTR(&_os_log_default, log_handle, "os_log_create returns valid value."); + T_ASSERT_EQ_INT(TRUE, os_log_info_enabled(log_handle), "os_log_info is enabled"); + T_ASSERT_EQ_INT(TRUE, os_log_debug_enabled(log_handle), "os_log_debug is enabled"); + T_ASSERT_EQ_PTR(&_os_log_default, OS_LOG_DEFAULT, "ensure OS_LOG_DEFAULT is _os_log_default"); + + total_msg = oslog_p_total_msgcount; + saved_msg = oslog_p_saved_msgcount; + dropped_msg = oslog_p_dropped_msgcount; + T_LOG("oslog internal counters total %u , saved %u, dropped %u", total_msg, saved_msg, dropped_msg); + + T_LOG("Validating with uniqid %u u64 %llu", uniqid, a); + T_ASSERT_NE_UINT(0, uniqid, "random number should not be zero"); + T_ASSERT_NE_ULLONG(0, a, "absolute time should not be zero"); + + datalen = scnprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT("printf_only"), uniqid, seqno, total_seqno); + checksum = crc32(0, databuffer, datalen); + printf(TESTOSLOG("printf_only") "mat%llu\n", checksum, uniqid, seqno, total_seqno, a); + + seqno += 1; + datalen = scnprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT("printf_only"), uniqid, seqno, total_seqno); + checksum = crc32(0, databuffer, datalen); + printf(TESTOSLOG("printf_only") "mat%llu\n", checksum, uniqid, seqno, total_seqno, a); + + datalen = scnprintf(databuffer, sizeof(databuffer), "kernel^0^test^printf_only#mat%llu", a); + match_count = find_pattern_in_buffer(databuffer, datalen, total_seqno); + T_EXPECT_EQ_UINT(match_count, 2, "verify printf_only goes to systemlog buffer"); + + uint32_t logging_config = atm_get_diagnostic_config(); + T_LOG("checking atm_diagnostic_config 0x%X", logging_config); + + if ((logging_config & ATM_TRACE_OFF) || (logging_config & ATM_TRACE_DISABLE)) { + T_LOG("ATM_TRACE_OFF / ATM_TRACE_DISABLE is set. Would not see oslog messages. skipping the rest of test."); + return KERN_SUCCESS; + } + + /* for enabled logging printfs should be saved in oslog as well */ + T_EXPECT_GE_UINT((oslog_p_total_msgcount - total_msg), 2, "atleast 2 msgs should be seen by oslog system"); + + a = mach_absolute_time(); + total_seqno = 1; + seqno = 1; + total_msg = oslog_p_total_msgcount; + saved_msg = oslog_p_saved_msgcount; + dropped_msg = oslog_p_dropped_msgcount; + datalen = scnprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT("oslog_info"), uniqid, seqno, total_seqno); + checksum = crc32(0, databuffer, datalen); + os_log_info(log_handle, TESTOSLOG("oslog_info") "mat%llu", checksum, uniqid, seqno, total_seqno, a); + T_EXPECT_GE_UINT((oslog_p_total_msgcount - total_msg), 1, "total message count in buffer"); + + datalen = scnprintf(databuffer, sizeof(databuffer), "kernel^0^test^oslog_info#mat%llu", a); + match_count = find_pattern_in_buffer(databuffer, datalen, total_seqno); + T_EXPECT_EQ_UINT(match_count, 1, "verify oslog_info does not go to systemlog buffer"); + + total_msg = oslog_p_total_msgcount; + test_oslog_info_helper(uniqid, 10); + T_EXPECT_GE_UINT(oslog_p_total_msgcount - total_msg, 10, "test_oslog_info_helper: Should have seen 10 msgs"); + + total_msg = oslog_p_total_msgcount; + test_oslog_debug_helper(uniqid, 10); + T_EXPECT_GE_UINT(oslog_p_total_msgcount - total_msg, 10, "test_oslog_debug_helper:Should have seen 10 msgs"); + + total_msg = oslog_p_total_msgcount; + test_oslog_error_helper(uniqid, 10); + T_EXPECT_GE_UINT(oslog_p_total_msgcount - total_msg, 10, "test_oslog_error_helper:Should have seen 10 msgs"); + + total_msg = oslog_p_total_msgcount; + test_oslog_default_helper(uniqid, 10); + T_EXPECT_GE_UINT(oslog_p_total_msgcount - total_msg, 10, "test_oslog_default_helper:Should have seen 10 msgs"); + + total_msg = oslog_p_total_msgcount; + test_oslog_fault_helper(uniqid, 10); + T_EXPECT_GE_UINT(oslog_p_total_msgcount - total_msg, 10, "test_oslog_fault_helper:Should have seen 10 msgs"); + + T_LOG("oslog internal counters total %u , saved %u, dropped %u", oslog_p_total_msgcount, oslog_p_saved_msgcount, + oslog_p_dropped_msgcount); + + return KERN_SUCCESS; +} + +static uint32_t _test_log_loop_count = 0; +void +_test_log_loop(void * arg __unused, wait_result_t wres __unused) +{ + uint32_t uniqid = RandomULong(); + test_oslog_debug_helper(uniqid, 100); + os_atomic_add(&_test_log_loop_count, 100, relaxed); +} + +kern_return_t +test_os_log_parallel(void) +{ + thread_t thread[2]; + kern_return_t kr; + uint32_t uniqid = RandomULong(); + + printf("oslog internal counters total %u , saved %u, dropped %u", oslog_p_total_msgcount, oslog_p_saved_msgcount, + oslog_p_dropped_msgcount); + + 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_helper(uniqid, 100); + + /* wait until other thread has also finished */ + while (_test_log_loop_count < 200) { + delay(1000); + } + + thread_deallocate(thread[0]); + thread_deallocate(thread[1]); + + T_LOG("oslog internal counters total %u , saved %u, dropped %u", oslog_p_total_msgcount, oslog_p_saved_msgcount, + oslog_p_dropped_msgcount); + T_PASS("parallel_logging tests is now complete"); + + return KERN_SUCCESS; } void -__firehose_critical_region_leave(void) { - enable_preemption(); - return; +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] = oslog_p_total_msgcount; + out[2] = oslog_p_saved_msgcount; + out[3] = 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_helper(uniqid, msgcount); break; + case OS_LOG_TYPE_DEBUG: test_oslog_debug_helper(uniqid, msgcount); break; + case OS_LOG_TYPE_ERROR: test_oslog_error_helper(uniqid, msgcount); break; + case OS_LOG_TYPE_FAULT: test_oslog_fault_helper(uniqid, msgcount); break; + case OS_LOG_TYPE_DEFAULT: + default: test_oslog_default_helper(uniqid, msgcount); break; + } + out[0] = KERN_SUCCESS; + break; + /* end of case 4 */ + } + default: + { + out[0] = KERN_INVALID_VALUE; + break; + } + } + return; +} + +kern_return_t +test_stresslog_dropmsg(uint32_t uniqid) +{ + uint32_t total, saved, dropped; + total = oslog_p_total_msgcount; + saved = oslog_p_saved_msgcount; + dropped = oslog_p_dropped_msgcount; + uniqid = RandomULong(); + test_oslog_debug_helper(uniqid, 100); + while ((oslog_p_dropped_msgcount - dropped) == 0) { + test_oslog_debug_helper(uniqid, 100); + } + printf("test_stresslog_dropmsg: logged %u msgs, saved %u and caused a drop of %u msgs. \n", oslog_p_total_msgcount - total, + oslog_p_saved_msgcount - saved, oslog_p_dropped_msgcount - dropped); + return KERN_SUCCESS; } +#endif