X-Git-Url: https://git.saurik.com/apple/xnu.git/blobdiff_plain/0a7de7458d150b5d4dffc935ba399be265ef0a1a..eb6b6ca394357805f2bdba989abae309f718b4d8:/libkern/os/log.c?ds=sidebyside diff --git a/libkern/os/log.c b/libkern/os/log.c index 8a64d5e32..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 @@ -56,7 +59,7 @@ extern void bsd_log_lock(void); extern void bsd_log_unlock(void); extern void logwakeup(struct msgbuf *); -decl_lck_spin_data(extern, oslog_stream_lock) +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) @@ -106,19 +109,19 @@ oslog_stream_create_buf_entry(oslog_stream_link_type_t type, firehose_tracepoint 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) @@ -152,13 +155,63 @@ _os_log_internal(void *dso, os_log_t log, uint8_t type, const char *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); 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 @@ -169,12 +222,12 @@ os_log_with_args(os_log_t oslog, os_log_type_t type, const char *format, va_list 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; @@ -194,16 +247,16 @@ _os_log_with_args_internal(os_log_t oslog, os_log_type_t type, } if (oslog != &_os_log_replay) { - _os_log_to_msgbuf_internal(format, args, safe, logging); + _os_log_to_msgbuf_internal(format, args, safe, logging, addcr); } if (safe && logging) { - _os_log_to_log_internal(oslog, type, format, args, addr, dso); + _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; @@ -279,7 +332,7 @@ _os_log_to_msgbuf_internal(const char *format, va_list args, bool safe, bool log } va_copy(args_copy, args); - vprintf_log_locked(format, args_copy); + vprintf_log_locked(format, args_copy, addcr); va_end(args_copy); #if DEVELOPMENT || DEBUG @@ -297,7 +350,7 @@ _os_log_to_msgbuf_internal(const char *format, va_list args, bool safe, bool log 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))); @@ -322,10 +375,11 @@ _os_log_to_log_internal(os_log_t oslog, os_log_type_t type, if (!_os_trace_addr_in_text_segment(dso, format)) { return; } - - void *dso_addr = (void *) OSKextKextForAddress(addr); - if (dso != dso_addr) { - return; + if (!driverKit) { + void *dso_addr = (void *) OSKextKextForAddress(addr); + if (dso != dso_addr) { + return; + } } #endif /* FIREHOSE_USES_SHARED_CACHE */ @@ -340,11 +394,11 @@ _os_log_to_log_internal(os_log_t oslog, os_log_type_t type, va_copy(args_copy, args); - (void)hw_atomic_add(&oslog_p_total_msgcount, 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); + _os_log_actual(oslog, type, format, dso, addr, &context, driverKit); } else { - (void)hw_atomic_add(&oslog_p_error_count, 1); + os_atomic_inc(&oslog_p_error_count, relaxed); } va_end(args_copy); @@ -352,26 +406,37 @@ _os_log_to_log_internal(os_log_t oslog, os_log_type_t type, 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[]){ (uintptr_t)address - (uintptr_t)dso }, + 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 @@ -402,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; @@ -413,7 +478,7 @@ _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); if (buffdata_sz == 0) { @@ -424,9 +489,16 @@ _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, @@ -452,7 +524,7 @@ _firehose_trace(firehose_stream_t stream, firehose_tracepoint_id_u ftid, 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; } @@ -474,11 +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); + 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; } @@ -489,7 +561,7 @@ out: offset = firehose_chunk_tracepoint_try_reserve(fbc, stamp, 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; } @@ -497,7 +569,7 @@ out: 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) { @@ -507,9 +579,9 @@ out: __firehose_buffer_tracepoint_flush(ft, ftid); if (stream == firehose_stream_metadata) { - (void)hw_atomic_add(&oslog_p_metadata_saved_msgcount, 1); + os_atomic_inc(&oslog_p_metadata_saved_msgcount, relaxed); } else { - (void)hw_atomic_add(&oslog_p_saved_msgcount, 1); + os_atomic_inc(&oslog_p_saved_msgcount, relaxed); } return ftid.ftid_value; } @@ -567,7 +639,7 @@ firehose_trace_metadata(firehose_stream_t stream, firehose_tracepoint_id_u ftid, m_entry = oslog_stream_create_buf_entry(oslog_stream_link_type_metadata, ftid, 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; } @@ -681,7 +753,7 @@ kern_return_t test_os_log_parallel(void); T_LOG("Doing os_log of %llu TESTLOG msgs for fn " ident, count); \ for (uint64_t i = 0; i < count; i++) \ { \ - datalen = snprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT(ident), uniqid, i + 1, count); \ + 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);*/ \ @@ -725,16 +797,16 @@ test_os_log() 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 = snprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT("printf_only"), uniqid, seqno, total_seqno); + 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 = snprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT("printf_only"), uniqid, seqno, total_seqno); + 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 = snprintf(databuffer, sizeof(databuffer), "kernel^0^test^printf_only#mat%llu", 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"); @@ -755,12 +827,12 @@ test_os_log() total_msg = oslog_p_total_msgcount; saved_msg = oslog_p_saved_msgcount; dropped_msg = oslog_p_dropped_msgcount; - datalen = snprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT("oslog_info"), uniqid, seqno, total_seqno); + 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 = snprintf(databuffer, sizeof(databuffer), "kernel^0^test^oslog_info#mat%llu", a); + 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"); @@ -796,7 +868,7 @@ _test_log_loop(void * arg __unused, wait_result_t wres __unused) { uint32_t uniqid = RandomULong(); test_oslog_debug_helper(uniqid, 100); - (void)hw_atomic_add(&_test_log_loop_count, 100); + os_atomic_add(&_test_log_loop_count, 100, relaxed); } kern_return_t