1 | #include <stddef.h> |
2 | #undef offset |
3 | |
4 | #include <kern/cpu_data.h> |
5 | #include <os/base.h> |
6 | #include <os/object.h> |
7 | #include <os/log.h> |
8 | #include <stdbool.h> |
9 | #include <stdint.h> |
10 | |
11 | #include <vm/vm_kern.h> |
12 | #include <mach/vm_statistics.h> |
13 | #include <kern/debug.h> |
14 | #include <libkern/libkern.h> |
15 | #include <libkern/kernel_mach_header.h> |
16 | #include <pexpert/pexpert.h> |
17 | #include <uuid/uuid.h> |
18 | #include <sys/msgbuf.h> |
19 | |
20 | #include <mach/mach_time.h> |
21 | #include <kern/thread.h> |
22 | #include <kern/simple_lock.h> |
23 | #include <kern/kalloc.h> |
24 | #include <kern/clock.h> |
25 | #include <kern/assert.h> |
26 | |
27 | #include <firehose/tracepoint_private.h> |
28 | #include <firehose/chunk_private.h> |
29 | #include <os/firehose_buffer_private.h> |
30 | #include <os/firehose.h> |
31 | |
32 | #include <os/log_private.h> |
33 | #include "trace_internal.h" |
34 | |
35 | #include "log_encode.h" |
36 | |
37 | /* on embedded, with no kext loading or unloads, |
38 | * make the kernel use the libtrace shared cache path for logging |
39 | */ |
40 | #define FIREHOSE_USES_SHARED_CACHE NO_KEXTD |
41 | |
42 | #if FIREHOSE_USES_SHARED_CACHE |
43 | extern vm_offset_t segLOWESTTEXT; |
44 | #endif |
45 | |
46 | struct os_log_s { |
47 | int a; |
48 | }; |
49 | |
50 | struct os_log_s _os_log_default; |
51 | struct os_log_s _os_log_replay; |
52 | extern vm_offset_t kernel_firehose_addr; |
53 | extern firehose_chunk_t firehose_boot_chunk; |
54 | |
55 | extern void bsd_log_lock(void); |
56 | extern void bsd_log_unlock(void); |
57 | extern void logwakeup(struct msgbuf *); |
58 | |
59 | decl_lck_spin_data(extern, oslog_stream_lock) |
60 | extern void oslog_streamwakeup(void); |
61 | void oslog_streamwrite_locked(firehose_tracepoint_id_u ftid, |
62 | uint64_t stamp, const void *pubdata, size_t publen); |
63 | extern void oslog_streamwrite_metadata_locked(oslog_stream_buf_entry_t m_entry); |
64 | |
65 | extern int oslog_stream_open; |
66 | |
67 | extern void *OSKextKextForAddress(const void *); |
68 | |
69 | /* Counters for persistence mode */ |
70 | uint32_t oslog_p_total_msgcount = 0; |
71 | uint32_t oslog_p_metadata_saved_msgcount = 0; |
72 | uint32_t oslog_p_metadata_dropped_msgcount = 0; |
73 | uint32_t oslog_p_error_count = 0; |
74 | uint32_t oslog_p_saved_msgcount = 0; |
75 | uint32_t oslog_p_dropped_msgcount = 0; |
76 | uint32_t oslog_p_boot_dropped_msgcount = 0; |
77 | |
78 | /* Counters for streaming mode */ |
79 | uint32_t oslog_s_total_msgcount = 0; |
80 | uint32_t oslog_s_error_count = 0; |
81 | uint32_t oslog_s_metadata_msgcount = 0; |
82 | |
83 | static bool oslog_boot_done = false; |
84 | extern boolean_t early_boot_complete; |
85 | |
86 | #ifdef XNU_KERNEL_PRIVATE |
87 | bool startup_serial_logging_active = true; |
88 | uint64_t startup_serial_num_procs = 300; |
89 | #endif /* XNU_KERNEL_PRIVATE */ |
90 | |
91 | // XXX |
92 | firehose_tracepoint_id_t |
93 | firehose_debug_trace(firehose_stream_t stream, firehose_tracepoint_id_t trace_id, |
94 | uint64_t timestamp, const char *format, const void *pubdata, size_t publen); |
95 | |
96 | static inline firehose_tracepoint_id_t |
97 | _firehose_trace(firehose_stream_t stream, firehose_tracepoint_id_u ftid, |
98 | uint64_t stamp, const void *pubdata, size_t publen); |
99 | |
100 | static oslog_stream_buf_entry_t |
101 | oslog_stream_create_buf_entry(oslog_stream_link_type_t type, firehose_tracepoint_id_u ftid, |
102 | uint64_t stamp, const void* pubdata, size_t publen); |
103 | |
104 | static void |
105 | _os_log_with_args_internal(os_log_t oslog __unused, os_log_type_t type __unused, |
106 | const char *format, va_list args, void *addr, void *dso); |
107 | |
108 | static void |
109 | _os_log_to_msgbuf_internal(const char *format, va_list args, bool safe, bool logging); |
110 | |
111 | static void |
112 | _os_log_to_log_internal(os_log_t oslog, os_log_type_t type, |
113 | const char *format, va_list args, void *addr, void *dso); |
114 | |
115 | |
116 | static void |
117 | _os_log_actual(os_log_t oslog, os_log_type_t type, const char *format, void |
118 | *dso, void *addr, os_log_buffer_context_t context); |
119 | |
120 | bool |
121 | os_log_info_enabled(os_log_t log __unused) |
122 | { |
123 | return true; |
124 | } |
125 | |
126 | bool |
127 | os_log_debug_enabled(os_log_t log __unused) |
128 | { |
129 | return true; |
130 | } |
131 | |
132 | os_log_t |
133 | os_log_create(const char *subsystem __unused, const char *category __unused) |
134 | { |
135 | return &_os_log_default; |
136 | } |
137 | |
138 | bool |
139 | _os_log_string_is_public(const char *str __unused) |
140 | { |
141 | return true; |
142 | } |
143 | |
144 | __attribute__((noinline,not_tail_called)) void |
145 | _os_log_internal(void *dso, os_log_t log, uint8_t type, const char *message, ...) |
146 | { |
147 | va_list args; |
148 | void *addr = __builtin_return_address(0); |
149 | |
150 | va_start(args, message); |
151 | |
152 | _os_log_with_args_internal(log, type, message, args, addr, dso); |
153 | |
154 | va_end(args); |
155 | |
156 | return; |
157 | } |
158 | |
159 | #pragma mark - shim functions |
160 | |
161 | __attribute__((noinline,not_tail_called)) void |
162 | os_log_with_args(os_log_t oslog, os_log_type_t type, const char *format, va_list args, void *addr) |
163 | { |
164 | // if no address passed, look it up |
165 | if (addr == NULL) { |
166 | addr = __builtin_return_address(0); |
167 | } |
168 | |
169 | _os_log_with_args_internal(oslog, type, format, args, addr, NULL); |
170 | } |
171 | |
172 | static void |
173 | _os_log_with_args_internal(os_log_t oslog, os_log_type_t type, |
174 | const char *format, va_list args, void *addr, void *dso) |
175 | { |
176 | uint32_t logging_config = atm_get_diagnostic_config(); |
177 | boolean_t safe; |
178 | boolean_t logging; |
179 | |
180 | if (format[0] == '\0') { |
181 | return; |
182 | } |
183 | |
184 | /* early boot can log to dmesg for later replay (27307943) */ |
185 | safe = (!early_boot_complete || oslog_is_safe()); |
186 | |
187 | if (logging_config & ATM_TRACE_DISABLE || logging_config & ATM_TRACE_OFF) { |
188 | logging = false; |
189 | } else { |
190 | logging = true; |
191 | } |
192 | |
193 | if (oslog != &_os_log_replay) { |
194 | _os_log_to_msgbuf_internal(format, args, safe, logging); |
195 | } |
196 | |
197 | if (safe && logging) { |
198 | _os_log_to_log_internal(oslog, type, format, args, addr, dso); |
199 | } |
200 | } |
201 | |
202 | static void |
203 | _os_log_to_msgbuf_internal(const char *format, va_list args, bool safe, bool logging) |
204 | { |
205 | static int msgbufreplay = -1; |
206 | va_list args_copy; |
207 | |
208 | #if DEVELOPMENT || DEBUG |
209 | if (safe) { |
210 | bsd_log_lock(); |
211 | } |
212 | #else |
213 | bsd_log_lock(); |
214 | #endif |
215 | |
216 | if (!safe) { |
217 | if (-1 == msgbufreplay) msgbufreplay = msgbufp->msg_bufx; |
218 | } else if (logging && (-1 != msgbufreplay)) { |
219 | uint32_t i; |
220 | uint32_t localbuff_size; |
221 | int newl, position; |
222 | char *localbuff, *p, *s, *next, ch; |
223 | |
224 | position = msgbufreplay; |
225 | msgbufreplay = -1; |
226 | localbuff_size = (msgbufp->msg_size + 2); /* + '\n' + '\0' */ |
227 | /* Size for non-blocking */ |
228 | if (localbuff_size > 4096) localbuff_size = 4096; |
229 | bsd_log_unlock(); |
230 | /* Allocate a temporary non-circular buffer */ |
231 | if ((localbuff = (char *)kalloc_noblock(localbuff_size))) { |
232 | /* in between here, the log could become bigger, but that's fine */ |
233 | bsd_log_lock(); |
234 | /* |
235 | * The message buffer is circular; start at the replay pointer, and |
236 | * make one loop up to write pointer - 1. |
237 | */ |
238 | p = msgbufp->msg_bufc + position; |
239 | for (i = newl = 0; p != msgbufp->msg_bufc + msgbufp->msg_bufx - 1; ++p) { |
240 | if (p >= msgbufp->msg_bufc + msgbufp->msg_size) |
241 | p = msgbufp->msg_bufc; |
242 | ch = *p; |
243 | if (ch == '\0') continue; |
244 | newl = (ch == '\n'); |
245 | localbuff[i++] = ch; |
246 | if (i >= (localbuff_size - 2)) break; |
247 | } |
248 | bsd_log_unlock(); |
249 | |
250 | if (!newl) localbuff[i++] = '\n'; |
251 | localbuff[i++] = 0; |
252 | |
253 | s = localbuff; |
254 | while ((next = strchr(s, '\n'))) { |
255 | next++; |
256 | ch = next[0]; |
257 | next[0] = 0; |
258 | os_log(&_os_log_replay, "%s" , s); |
259 | next[0] = ch; |
260 | s = next; |
261 | } |
262 | kfree(localbuff, localbuff_size); |
263 | } |
264 | bsd_log_lock(); |
265 | } |
266 | |
267 | va_copy(args_copy, args); |
268 | vprintf_log_locked(format, args_copy); |
269 | va_end(args_copy); |
270 | |
271 | #if DEVELOPMENT || DEBUG |
272 | if (safe) { |
273 | bsd_log_unlock(); |
274 | logwakeup(msgbufp); |
275 | } |
276 | #else |
277 | bsd_log_unlock(); |
278 | if (safe) logwakeup(msgbufp); |
279 | #endif |
280 | } |
281 | |
282 | static void |
283 | _os_log_to_log_internal(os_log_t oslog, os_log_type_t type, |
284 | const char *format, va_list args, void *addr, void *dso) |
285 | { |
286 | struct os_log_buffer_context_s context; |
287 | unsigned char buffer_data[OS_LOG_BUFFER_MAX_SIZE] __attribute__((aligned(8))); |
288 | os_log_buffer_t buffer = (os_log_buffer_t)buffer_data; |
289 | uint8_t pubdata[OS_LOG_BUFFER_MAX_SIZE]; |
290 | va_list args_copy; |
291 | |
292 | if (addr == NULL) { |
293 | return; |
294 | } |
295 | |
296 | #if FIREHOSE_USES_SHARED_CACHE |
297 | dso = (void *) segLOWESTTEXT; |
298 | #else /* FIREHOSE_USES_SHARED_CACHE */ |
299 | if (dso == NULL) { |
300 | dso = (void *) OSKextKextForAddress(format); |
301 | if (dso == NULL) { |
302 | return; |
303 | } |
304 | } |
305 | |
306 | if (!_os_trace_addr_in_text_segment(dso, format)) { |
307 | return; |
308 | } |
309 | |
310 | void *dso_addr = (void *) OSKextKextForAddress(addr); |
311 | if (dso != dso_addr) { |
312 | return; |
313 | } |
314 | #endif /* FIREHOSE_USES_SHARED_CACHE */ |
315 | |
316 | memset(&context, 0, sizeof(context)); |
317 | memset(buffer, 0, OS_LOG_BUFFER_MAX_SIZE); |
318 | |
319 | context.shimmed = true; |
320 | context.buffer = buffer; |
321 | context.content_sz = OS_LOG_BUFFER_MAX_SIZE - sizeof(*buffer); |
322 | context.pubdata = pubdata; |
323 | context.pubdata_sz = sizeof(pubdata); |
324 | |
325 | va_copy(args_copy, args); |
326 | |
327 | (void)hw_atomic_add(&oslog_p_total_msgcount, 1); |
328 | if (_os_log_encode(format, args_copy, 0, &context)) { |
329 | _os_log_actual(oslog, type, format, dso, addr, &context); |
330 | } |
331 | else { |
332 | (void)hw_atomic_add(&oslog_p_error_count, 1); |
333 | } |
334 | |
335 | va_end(args_copy); |
336 | } |
337 | |
338 | static inline size_t |
339 | _os_trace_write_location_for_address(uint8_t buf[static sizeof(uint64_t)], |
340 | void *dso, const void *address, firehose_tracepoint_flags_t *flags) |
341 | { |
342 | #if FIREHOSE_USES_SHARED_CACHE |
343 | *flags = _firehose_tracepoint_flags_pc_style_shared_cache; |
344 | memcpy(buf, (uint32_t[]){ (uintptr_t)address - (uintptr_t)dso }, |
345 | sizeof(uint32_t)); |
346 | return sizeof(uint32_t); |
347 | |
348 | #else /* FIREHOSE_USES_SHARED_CACHE */ |
349 | kernel_mach_header_t *mh = dso; |
350 | |
351 | if (mh->filetype == MH_EXECUTE) { |
352 | *flags = _firehose_tracepoint_flags_pc_style_main_exe; |
353 | |
354 | memcpy(buf, (uint32_t[]){ (uintptr_t)address - (uintptr_t)dso }, |
355 | sizeof(uint32_t)); |
356 | return sizeof(uint32_t); |
357 | } else { |
358 | *flags = _firehose_tracepoint_flags_pc_style_absolute; |
359 | memcpy(buf, (uintptr_t[]){ VM_KERNEL_UNSLIDE(address) }, sizeof(uintptr_t)); |
360 | #if __LP64__ |
361 | return 6; // 48 bits are enough |
362 | #else |
363 | return sizeof(uintptr_t); |
364 | #endif |
365 | } |
366 | #endif /* !FIREHOSE_USES_SHARED_CACHE */ |
367 | } |
368 | |
369 | |
370 | OS_ALWAYS_INLINE |
371 | static inline size_t |
372 | _os_log_buffer_pack(uint8_t *buffdata, size_t buffdata_sz, |
373 | os_log_buffer_context_t ctx) |
374 | { |
375 | os_log_buffer_t buffer = ctx->buffer; |
376 | size_t buffer_sz = sizeof(*ctx->buffer) + ctx->content_sz; |
377 | size_t total_sz = buffer_sz + ctx->pubdata_sz; |
378 | |
379 | if (total_sz > buffdata_sz) { |
380 | return 0; |
381 | } |
382 | |
383 | memcpy(buffdata, buffer, buffer_sz); |
384 | memcpy(&buffdata[buffer_sz], ctx->pubdata, ctx->pubdata_sz); |
385 | return total_sz; |
386 | } |
387 | |
388 | static void |
389 | _os_log_actual(os_log_t oslog __unused, os_log_type_t type, const char *format, |
390 | void *dso, void *addr, os_log_buffer_context_t context) |
391 | { |
392 | firehose_stream_t stream; |
393 | firehose_tracepoint_flags_t flags = 0; |
394 | firehose_tracepoint_id_u trace_id; |
395 | uint8_t buffdata[OS_LOG_BUFFER_MAX_SIZE]; |
396 | size_t addr_len = 0, buffdata_sz; |
397 | uint64_t timestamp; |
398 | uint64_t thread_id; |
399 | |
400 | // dso == the start of the binary that was loaded |
401 | addr_len = _os_trace_write_location_for_address(buffdata, dso, addr, &flags); |
402 | buffdata_sz = _os_log_buffer_pack(buffdata + addr_len, |
403 | sizeof(buffdata) - addr_len, context); |
404 | if (buffdata_sz == 0) { |
405 | return; |
406 | } |
407 | buffdata_sz += addr_len; |
408 | |
409 | timestamp = firehose_tracepoint_time(firehose_activity_flags_default); |
410 | thread_id = thread_tid(current_thread()); |
411 | |
412 | // create trace_id after we've set additional flags |
413 | trace_id.ftid_value = FIREHOSE_TRACE_ID_MAKE(firehose_tracepoint_namespace_log, |
414 | type, flags, _os_trace_offset(dso, format, flags)); |
415 | |
416 | if (FALSE) { |
417 | firehose_debug_trace(stream, trace_id.ftid_value, timestamp, |
418 | format, buffdata, buffdata_sz); |
419 | } |
420 | if (type == OS_LOG_TYPE_INFO || type == OS_LOG_TYPE_DEBUG) { |
421 | stream = firehose_stream_memory; |
422 | } |
423 | else { |
424 | stream = firehose_stream_persist; |
425 | } |
426 | _firehose_trace(stream, trace_id, timestamp, buffdata, buffdata_sz); |
427 | } |
428 | |
429 | static inline firehose_tracepoint_id_t |
430 | _firehose_trace(firehose_stream_t stream, firehose_tracepoint_id_u ftid, |
431 | uint64_t stamp, const void *pubdata, size_t publen) |
432 | { |
433 | const uint16_t ft_size = offsetof(struct firehose_tracepoint_s, ft_data); |
434 | const size_t _firehose_chunk_payload_size = |
435 | sizeof(((struct firehose_chunk_s *)0)->fc_data); |
436 | |
437 | firehose_tracepoint_t ft; |
438 | |
439 | if (slowpath(ft_size + publen > _firehose_chunk_payload_size)) { |
440 | // We'll need to have some handling here. For now - return 0 |
441 | (void)hw_atomic_add(&oslog_p_error_count, 1); |
442 | return 0; |
443 | } |
444 | |
445 | if (oslog_stream_open && (stream != firehose_stream_metadata)) { |
446 | |
447 | lck_spin_lock(&oslog_stream_lock); |
448 | if (!oslog_stream_open) { |
449 | lck_spin_unlock(&oslog_stream_lock); |
450 | goto out; |
451 | } |
452 | |
453 | oslog_s_total_msgcount++; |
454 | oslog_streamwrite_locked(ftid, stamp, pubdata, publen); |
455 | lck_spin_unlock(&oslog_stream_lock); |
456 | oslog_streamwakeup(); |
457 | } |
458 | |
459 | out: |
460 | ft = __firehose_buffer_tracepoint_reserve(stamp, stream, (uint16_t)publen, 0, NULL); |
461 | if (!fastpath(ft)) { |
462 | if (oslog_boot_done) { |
463 | if (stream == firehose_stream_metadata) { |
464 | (void)hw_atomic_add(&oslog_p_metadata_dropped_msgcount, 1); |
465 | } |
466 | else { |
467 | // If we run out of space in the persistence buffer we're |
468 | // dropping the message. |
469 | (void)hw_atomic_add(&oslog_p_dropped_msgcount, 1); |
470 | } |
471 | return 0; |
472 | } |
473 | firehose_chunk_t fbc = firehose_boot_chunk; |
474 | long offset; |
475 | |
476 | //only stream available during boot is persist |
477 | offset = firehose_chunk_tracepoint_try_reserve(fbc, stamp, |
478 | firehose_stream_persist, 0, publen, 0, NULL); |
479 | if (offset <= 0) { |
480 | (void)hw_atomic_add(&oslog_p_boot_dropped_msgcount, 1); |
481 | return 0; |
482 | } |
483 | |
484 | ft = firehose_chunk_tracepoint_begin(fbc, stamp, publen, |
485 | thread_tid(current_thread()), offset); |
486 | memcpy(ft->ft_data, pubdata, publen); |
487 | firehose_chunk_tracepoint_end(fbc, ft, ftid); |
488 | (void)hw_atomic_add(&oslog_p_saved_msgcount, 1); |
489 | return ftid.ftid_value; |
490 | } |
491 | if (!oslog_boot_done) { |
492 | oslog_boot_done = true; |
493 | } |
494 | memcpy(ft->ft_data, pubdata, publen); |
495 | |
496 | __firehose_buffer_tracepoint_flush(ft, ftid); |
497 | if (stream == firehose_stream_metadata) { |
498 | (void)hw_atomic_add(&oslog_p_metadata_saved_msgcount, 1); |
499 | } |
500 | else { |
501 | (void)hw_atomic_add(&oslog_p_saved_msgcount, 1); |
502 | } |
503 | return ftid.ftid_value; |
504 | } |
505 | |
506 | static oslog_stream_buf_entry_t |
507 | oslog_stream_create_buf_entry(oslog_stream_link_type_t type, firehose_tracepoint_id_u ftid, |
508 | uint64_t stamp, const void* pubdata, size_t publen) |
509 | { |
510 | oslog_stream_buf_entry_t m_entry = NULL; |
511 | firehose_tracepoint_t ft = NULL; |
512 | size_t m_entry_len = 0; |
513 | |
514 | if (!pubdata) { |
515 | return NULL; |
516 | } |
517 | |
518 | m_entry_len = sizeof(struct oslog_stream_buf_entry_s) + |
519 | sizeof(struct firehose_tracepoint_s) + publen; |
520 | m_entry = (oslog_stream_buf_entry_t) kalloc(m_entry_len); |
521 | if (!m_entry) { |
522 | return NULL; |
523 | } |
524 | |
525 | m_entry->type = type; |
526 | m_entry->timestamp = stamp; |
527 | m_entry->size = sizeof(struct firehose_tracepoint_s) + publen; |
528 | |
529 | ft = m_entry->metadata; |
530 | ft->ft_thread = thread_tid(current_thread()); |
531 | ft->ft_id.ftid_value = ftid.ftid_value; |
532 | ft->ft_length = publen; |
533 | memcpy(ft->ft_data, pubdata, publen); |
534 | |
535 | return m_entry; |
536 | } |
537 | |
538 | #ifdef KERNEL |
539 | void |
540 | firehose_trace_metadata(firehose_stream_t stream, firehose_tracepoint_id_u ftid, |
541 | uint64_t stamp, const void *pubdata, size_t publen) |
542 | { |
543 | oslog_stream_buf_entry_t m_entry = NULL; |
544 | |
545 | // If streaming mode is not on, only log the metadata |
546 | // in the persistence buffer |
547 | |
548 | lck_spin_lock(&oslog_stream_lock); |
549 | if (!oslog_stream_open) { |
550 | lck_spin_unlock(&oslog_stream_lock); |
551 | goto finish; |
552 | } |
553 | lck_spin_unlock(&oslog_stream_lock); |
554 | |
555 | // Setup and write the stream metadata entry |
556 | m_entry = oslog_stream_create_buf_entry(oslog_stream_link_type_metadata, ftid, |
557 | stamp, pubdata, publen); |
558 | if (!m_entry) { |
559 | (void)hw_atomic_add(&oslog_s_error_count, 1); |
560 | goto finish; |
561 | } |
562 | |
563 | lck_spin_lock(&oslog_stream_lock); |
564 | if (!oslog_stream_open) { |
565 | lck_spin_unlock(&oslog_stream_lock); |
566 | kfree(m_entry, sizeof(struct oslog_stream_buf_entry_s) + |
567 | sizeof(struct firehose_tracepoint_s) + publen); |
568 | goto finish; |
569 | } |
570 | oslog_s_metadata_msgcount++; |
571 | oslog_streamwrite_metadata_locked(m_entry); |
572 | lck_spin_unlock(&oslog_stream_lock); |
573 | |
574 | finish: |
575 | _firehose_trace(stream, ftid, stamp, pubdata, publen); |
576 | } |
577 | #endif |
578 | |
579 | firehose_tracepoint_id_t |
580 | firehose_debug_trace(firehose_stream_t stream, firehose_tracepoint_id_t trace_id, |
581 | uint64_t timestamp, const char *format, const void *pubdata, size_t publen) |
582 | { |
583 | kprintf("[os_log stream 0x%x trace_id 0x%llx timestamp %llu format '%s' data %p len %lu]\n" , |
584 | (unsigned int)stream, (unsigned long long)trace_id, timestamp, |
585 | format, pubdata, publen); |
586 | size_t i; |
587 | const unsigned char *cdata = (const unsigned char *)pubdata; |
588 | for (i=0; i < publen; i += 8) { |
589 | kprintf(">oslog 0x%08x: 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x 0x%02x\n" , |
590 | (unsigned int)i, |
591 | (i+0) < publen ? cdata[i+0] : 0, |
592 | (i+1) < publen ? cdata[i+1] : 0, |
593 | (i+2) < publen ? cdata[i+2] : 0, |
594 | (i+3) < publen ? cdata[i+3] : 0, |
595 | (i+4) < publen ? cdata[i+4] : 0, |
596 | (i+5) < publen ? cdata[i+5] : 0, |
597 | (i+6) < publen ? cdata[i+6] : 0, |
598 | (i+7) < publen ? cdata[i+7] : 0 |
599 | ); |
600 | } |
601 | return trace_id; |
602 | } |
603 | |
604 | void |
605 | __firehose_buffer_push_to_logd(firehose_buffer_t fb __unused, bool for_io __unused) { |
606 | oslogwakeup(); |
607 | return; |
608 | } |
609 | |
610 | void |
611 | __firehose_allocate(vm_offset_t *addr, vm_size_t size __unused) |
612 | { |
613 | firehose_chunk_t kernel_buffer = (firehose_chunk_t)kernel_firehose_addr; |
614 | |
615 | if (kernel_firehose_addr) { |
616 | *addr = kernel_firehose_addr; |
617 | } |
618 | else { |
619 | *addr = 0; |
620 | return; |
621 | } |
622 | // Now that we are done adding logs to this chunk, set the number of writers to 0 |
623 | // Without this, logd won't flush when the page is full |
624 | firehose_boot_chunk->fc_pos.fcp_refcnt = 0; |
625 | memcpy(&kernel_buffer[FIREHOSE_BUFFER_KERNEL_CHUNK_COUNT - 1], (const void *)firehose_boot_chunk, FIREHOSE_CHUNK_SIZE); |
626 | return; |
627 | } |
628 | // There isnt a lock held in this case. |
629 | void |
630 | __firehose_critical_region_enter(void) { |
631 | disable_preemption(); |
632 | return; |
633 | } |
634 | |
635 | void |
636 | __firehose_critical_region_leave(void) { |
637 | enable_preemption(); |
638 | return; |
639 | } |
640 | |
641 | #ifdef CONFIG_XNUPOST |
642 | |
643 | #include <tests/xnupost.h> |
644 | #define TESTOSLOGFMT(fn_name) "%u^%llu/%llu^kernel^0^test^" fn_name |
645 | #define TESTOSLOGPFX "TESTLOG:%u#" |
646 | #define TESTOSLOG(fn_name) TESTOSLOGPFX TESTOSLOGFMT(fn_name "#") |
647 | |
648 | extern u_int32_t RandomULong(void); |
649 | extern uint32_t find_pattern_in_buffer(char * pattern, uint32_t len, int expected_count); |
650 | void test_oslog_default_helper(uint32_t uniqid, uint64_t count); |
651 | void test_oslog_info_helper(uint32_t uniqid, uint64_t count); |
652 | void test_oslog_debug_helper(uint32_t uniqid, uint64_t count); |
653 | void test_oslog_error_helper(uint32_t uniqid, uint64_t count); |
654 | void test_oslog_fault_helper(uint32_t uniqid, uint64_t count); |
655 | void _test_log_loop(void * arg __unused, wait_result_t wres __unused); |
656 | void test_oslog_handleOSLogCtl(int32_t * in, int32_t * out, int32_t len); |
657 | kern_return_t test_stresslog_dropmsg(uint32_t uniqid); |
658 | |
659 | kern_return_t test_os_log(void); |
660 | kern_return_t test_os_log_parallel(void); |
661 | |
662 | #define GENOSLOGHELPER(fname, ident, callout_f) \ |
663 | void fname(uint32_t uniqid, uint64_t count) \ |
664 | { \ |
665 | int32_t datalen = 0; \ |
666 | uint32_t checksum = 0; \ |
667 | char databuffer[256]; \ |
668 | T_LOG("Doing os_log of %llu TESTLOG msgs for fn " ident, count); \ |
669 | for (uint64_t i = 0; i < count; i++) \ |
670 | { \ |
671 | datalen = snprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT(ident), uniqid, i + 1, count); \ |
672 | checksum = crc32(0, databuffer, datalen); \ |
673 | callout_f(OS_LOG_DEFAULT, TESTOSLOG(ident), checksum, uniqid, i + 1, count); \ |
674 | /*T_LOG(TESTOSLOG(ident), checksum, uniqid, i + 1, count);*/ \ |
675 | } \ |
676 | } |
677 | |
678 | GENOSLOGHELPER(test_oslog_info_helper, "oslog_info_helper" , os_log_info); |
679 | GENOSLOGHELPER(test_oslog_fault_helper, "oslog_fault_helper" , os_log_fault); |
680 | GENOSLOGHELPER(test_oslog_debug_helper, "oslog_debug_helper" , os_log_debug); |
681 | GENOSLOGHELPER(test_oslog_error_helper, "oslog_error_helper" , os_log_error); |
682 | GENOSLOGHELPER(test_oslog_default_helper, "oslog_default_helper" , os_log); |
683 | |
684 | kern_return_t test_os_log() |
685 | { |
686 | char databuffer[256]; |
687 | uint32_t uniqid = RandomULong(); |
688 | uint32_t match_count = 0; |
689 | uint32_t checksum = 0; |
690 | uint32_t total_msg = 0; |
691 | uint32_t saved_msg = 0; |
692 | uint32_t dropped_msg = 0; |
693 | int datalen = 0; |
694 | uint64_t a = mach_absolute_time(); |
695 | uint64_t seqno = 1; |
696 | uint64_t total_seqno = 2; |
697 | |
698 | os_log_t log_handle = os_log_create("com.apple.xnu.test.t1" , "kpost" ); |
699 | |
700 | T_ASSERT_EQ_PTR(&_os_log_default, log_handle, "os_log_create returns valid value." ); |
701 | T_ASSERT_EQ_INT(TRUE, os_log_info_enabled(log_handle), "os_log_info is enabled" ); |
702 | T_ASSERT_EQ_INT(TRUE, os_log_debug_enabled(log_handle), "os_log_debug is enabled" ); |
703 | T_ASSERT_EQ_PTR(&_os_log_default, OS_LOG_DEFAULT, "ensure OS_LOG_DEFAULT is _os_log_default" ); |
704 | |
705 | total_msg = oslog_p_total_msgcount; |
706 | saved_msg = oslog_p_saved_msgcount; |
707 | dropped_msg = oslog_p_dropped_msgcount; |
708 | T_LOG("oslog internal counters total %u , saved %u, dropped %u" , total_msg, saved_msg, dropped_msg); |
709 | |
710 | T_LOG("Validating with uniqid %u u64 %llu" , uniqid, a); |
711 | T_ASSERT_NE_UINT(0, uniqid, "random number should not be zero" ); |
712 | T_ASSERT_NE_ULLONG(0, a, "absolute time should not be zero" ); |
713 | |
714 | datalen = snprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT("printf_only" ), uniqid, seqno, total_seqno); |
715 | checksum = crc32(0, databuffer, datalen); |
716 | printf(TESTOSLOG("printf_only" ) "mat%llu\n" , checksum, uniqid, seqno, total_seqno, a); |
717 | |
718 | seqno += 1; |
719 | datalen = snprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT("printf_only" ), uniqid, seqno, total_seqno); |
720 | checksum = crc32(0, databuffer, datalen); |
721 | printf(TESTOSLOG("printf_only" ) "mat%llu\n" , checksum, uniqid, seqno, total_seqno, a); |
722 | |
723 | datalen = snprintf(databuffer, sizeof(databuffer), "kernel^0^test^printf_only#mat%llu" , a); |
724 | match_count = find_pattern_in_buffer(databuffer, datalen, total_seqno); |
725 | T_EXPECT_EQ_UINT(match_count, 2, "verify printf_only goes to systemlog buffer" ); |
726 | |
727 | uint32_t logging_config = atm_get_diagnostic_config(); |
728 | T_LOG("checking atm_diagnostic_config 0x%X" , logging_config); |
729 | |
730 | if ((logging_config & ATM_TRACE_OFF) || (logging_config & ATM_TRACE_DISABLE)) |
731 | { |
732 | T_LOG("ATM_TRACE_OFF / ATM_TRACE_DISABLE is set. Would not see oslog messages. skipping the rest of test." ); |
733 | return KERN_SUCCESS; |
734 | } |
735 | |
736 | /* for enabled logging printfs should be saved in oslog as well */ |
737 | T_EXPECT_GE_UINT((oslog_p_total_msgcount - total_msg), 2, "atleast 2 msgs should be seen by oslog system" ); |
738 | |
739 | a = mach_absolute_time(); |
740 | total_seqno = 1; |
741 | seqno = 1; |
742 | total_msg = oslog_p_total_msgcount; |
743 | saved_msg = oslog_p_saved_msgcount; |
744 | dropped_msg = oslog_p_dropped_msgcount; |
745 | datalen = snprintf(databuffer, sizeof(databuffer), TESTOSLOGFMT("oslog_info" ), uniqid, seqno, total_seqno); |
746 | checksum = crc32(0, databuffer, datalen); |
747 | os_log_info(log_handle, TESTOSLOG("oslog_info" ) "mat%llu" , checksum, uniqid, seqno, total_seqno, a); |
748 | T_EXPECT_GE_UINT((oslog_p_total_msgcount - total_msg), 1, "total message count in buffer" ); |
749 | |
750 | datalen = snprintf(databuffer, sizeof(databuffer), "kernel^0^test^oslog_info#mat%llu" , a); |
751 | match_count = find_pattern_in_buffer(databuffer, datalen, total_seqno); |
752 | T_EXPECT_EQ_UINT(match_count, 1, "verify oslog_info does not go to systemlog buffer" ); |
753 | |
754 | total_msg = oslog_p_total_msgcount; |
755 | test_oslog_info_helper(uniqid, 10); |
756 | T_EXPECT_GE_UINT(oslog_p_total_msgcount - total_msg, 10, "test_oslog_info_helper: Should have seen 10 msgs" ); |
757 | |
758 | total_msg = oslog_p_total_msgcount; |
759 | test_oslog_debug_helper(uniqid, 10); |
760 | T_EXPECT_GE_UINT(oslog_p_total_msgcount - total_msg, 10, "test_oslog_debug_helper:Should have seen 10 msgs" ); |
761 | |
762 | total_msg = oslog_p_total_msgcount; |
763 | test_oslog_error_helper(uniqid, 10); |
764 | T_EXPECT_GE_UINT(oslog_p_total_msgcount - total_msg, 10, "test_oslog_error_helper:Should have seen 10 msgs" ); |
765 | |
766 | total_msg = oslog_p_total_msgcount; |
767 | test_oslog_default_helper(uniqid, 10); |
768 | T_EXPECT_GE_UINT(oslog_p_total_msgcount - total_msg, 10, "test_oslog_default_helper:Should have seen 10 msgs" ); |
769 | |
770 | total_msg = oslog_p_total_msgcount; |
771 | test_oslog_fault_helper(uniqid, 10); |
772 | T_EXPECT_GE_UINT(oslog_p_total_msgcount - total_msg, 10, "test_oslog_fault_helper:Should have seen 10 msgs" ); |
773 | |
774 | T_LOG("oslog internal counters total %u , saved %u, dropped %u" , oslog_p_total_msgcount, oslog_p_saved_msgcount, |
775 | oslog_p_dropped_msgcount); |
776 | |
777 | return KERN_SUCCESS; |
778 | } |
779 | |
780 | static uint32_t _test_log_loop_count = 0; |
781 | void _test_log_loop(void * arg __unused, wait_result_t wres __unused) |
782 | { |
783 | uint32_t uniqid = RandomULong(); |
784 | test_oslog_debug_helper(uniqid, 100); |
785 | (void)hw_atomic_add(&_test_log_loop_count, 100); |
786 | } |
787 | |
788 | kern_return_t test_os_log_parallel(void) |
789 | { |
790 | thread_t thread[2]; |
791 | kern_return_t kr; |
792 | uint32_t uniqid = RandomULong(); |
793 | |
794 | printf("oslog internal counters total %u , saved %u, dropped %u" , oslog_p_total_msgcount, oslog_p_saved_msgcount, |
795 | oslog_p_dropped_msgcount); |
796 | |
797 | kr = kernel_thread_start(_test_log_loop, NULL, &thread[0]); |
798 | T_ASSERT_EQ_INT(kr, KERN_SUCCESS, "kernel_thread_start returned successfully" ); |
799 | |
800 | kr = kernel_thread_start(_test_log_loop, NULL, &thread[1]); |
801 | T_ASSERT_EQ_INT(kr, KERN_SUCCESS, "kernel_thread_start returned successfully" ); |
802 | |
803 | test_oslog_info_helper(uniqid, 100); |
804 | |
805 | /* wait until other thread has also finished */ |
806 | while (_test_log_loop_count < 200) |
807 | { |
808 | delay(1000); |
809 | } |
810 | |
811 | thread_deallocate(thread[0]); |
812 | thread_deallocate(thread[1]); |
813 | |
814 | T_LOG("oslog internal counters total %u , saved %u, dropped %u" , oslog_p_total_msgcount, oslog_p_saved_msgcount, |
815 | oslog_p_dropped_msgcount); |
816 | T_PASS("parallel_logging tests is now complete" ); |
817 | |
818 | return KERN_SUCCESS; |
819 | } |
820 | |
821 | void test_oslog_handleOSLogCtl(int32_t * in, int32_t * out, int32_t len) |
822 | { |
823 | if (!in || !out || len != 4) |
824 | return; |
825 | switch (in[0]) { |
826 | case 1: |
827 | { |
828 | /* send out counters */ |
829 | out[1] = oslog_p_total_msgcount; |
830 | out[2] = oslog_p_saved_msgcount; |
831 | out[3] = oslog_p_dropped_msgcount; |
832 | out[0] = KERN_SUCCESS; |
833 | break; |
834 | } |
835 | case 2: |
836 | { |
837 | /* mini stress run */ |
838 | out[0] = test_os_log_parallel(); |
839 | break; |
840 | } |
841 | case 3: |
842 | { |
843 | /* drop msg tests */ |
844 | out[1] = RandomULong(); |
845 | out[0] = test_stresslog_dropmsg(out[1]); |
846 | break; |
847 | } |
848 | case 4: |
849 | { |
850 | /* invoke log helpers */ |
851 | uint32_t uniqid = in[3]; |
852 | int32_t msgcount = in[2]; |
853 | if (uniqid == 0 || msgcount == 0) |
854 | { |
855 | out[0] = KERN_INVALID_VALUE; |
856 | return; |
857 | } |
858 | |
859 | switch (in[1]) { |
860 | case OS_LOG_TYPE_INFO: test_oslog_info_helper(uniqid, msgcount); break; |
861 | case OS_LOG_TYPE_DEBUG: test_oslog_debug_helper(uniqid, msgcount); break; |
862 | case OS_LOG_TYPE_ERROR: test_oslog_error_helper(uniqid, msgcount); break; |
863 | case OS_LOG_TYPE_FAULT: test_oslog_fault_helper(uniqid, msgcount); break; |
864 | case OS_LOG_TYPE_DEFAULT: |
865 | default: test_oslog_default_helper(uniqid, msgcount); break; |
866 | } |
867 | out[0] = KERN_SUCCESS; |
868 | break; |
869 | /* end of case 4 */ |
870 | } |
871 | default: |
872 | { |
873 | out[0] = KERN_INVALID_VALUE; |
874 | break; |
875 | } |
876 | } |
877 | return; |
878 | } |
879 | |
880 | kern_return_t test_stresslog_dropmsg(uint32_t uniqid) |
881 | { |
882 | uint32_t total, saved, dropped; |
883 | total = oslog_p_total_msgcount; |
884 | saved = oslog_p_saved_msgcount; |
885 | dropped = oslog_p_dropped_msgcount; |
886 | uniqid = RandomULong(); |
887 | test_oslog_debug_helper(uniqid, 100); |
888 | while ((oslog_p_dropped_msgcount - dropped) == 0) |
889 | { |
890 | test_oslog_debug_helper(uniqid, 100); |
891 | } |
892 | printf("test_stresslog_dropmsg: logged %u msgs, saved %u and caused a drop of %u msgs. \n" , oslog_p_total_msgcount - total, |
893 | oslog_p_saved_msgcount - saved, oslog_p_dropped_msgcount - dropped); |
894 | return KERN_SUCCESS; |
895 | } |
896 | |
897 | #endif |
898 | |