1 /*
2 * Copyright (c) 2015-2020 Apple Inc. All rights reserved.
3 *
4 * @APPLE_LICENSE_HEADER_START@
5 *
6 * This file contains Original Code and/or Modifications of Original Code
7 * as defined in and that are subject to the Apple Public Source License
8 * Version 2.0 (the 'License'). You may not use this file except in
9 * compliance with the License. Please obtain a copy of the License at
10 * http://www.opensource.apple.com/apsl/ and read it before using this
11 * file.
12 *
13 * The Original Code and all software distributed under the License are
14 * distributed on an 'AS IS' basis, WITHOUT WARRANTY OF ANY KIND, EITHER
15 * EXPRESS OR IMPLIED, AND APPLE HEREBY DISCLAIMS ALL SUCH WARRANTIES,
16 * INCLUDING WITHOUT LIMITATION, ANY WARRANTIES OF MERCHANTABILITY,
17 * FITNESS FOR A PARTICULAR PURPOSE, QUIET ENJOYMENT OR NON-INFRINGEMENT.
18 * Please see the License for the specific language governing rights and
19 * limitations under the License.
20 *
21 * @APPLE_LICENSE_HEADER_END@
22 */
23
24 #include <stdbool.h>
25 #include <firehose/tracepoint_private.h>
26 #include <kern/assert.h>
27 #include <kern/counter.h>
28 #include <kern/locks.h>
29 #include <pexpert/pexpert.h>
30 #include <sys/param.h>
31
32 #if __has_feature(ptrauth_calls)
33 #include <mach/vm_param.h>
34 #include <ptrauth.h>
35 #endif /* __has_feature(ptrauth_calls) */
36
37 #include "log_encode.h"
38 #include "log_mem.h"
39
40 #define LOG_FMT_MAX_PRECISION (1024)
41 #define log_context_cursor(ctx) &(ctx)->ctx_hdr->hdr_data[(ctx)->ctx_content_off]
42
43 extern boolean_t doprnt_hide_pointers;
44
45 SCALABLE_COUNTER_DEFINE(oslog_p_fmt_invalid_msgcount);
46 SCALABLE_COUNTER_DEFINE(oslog_p_fmt_max_args_msgcount);
47 SCALABLE_COUNTER_DEFINE(oslog_p_truncated_msgcount);
48
49 static bool
is_digit(char ch)50 is_digit(char ch)
51 {
52 return (ch >= '0') && (ch <= '9');
53 }
54
55 static bool
is_kernel_pointer(void * arg,size_t arg_len)56 is_kernel_pointer(void *arg, size_t arg_len)
57 {
58 if (arg_len < sizeof(void *)) {
59 return false;
60 }
61
62 unsigned long long value = 0;
63 assert(arg_len <= sizeof(value));
64 (void) memcpy(&value, arg, arg_len);
65
66 #if __has_feature(ptrauth_calls)
67 /**
68 * Strip out the pointer authentication code before
69 * checking whether the pointer is a kernel address.
70 */
71 value = (unsigned long long)VM_KERNEL_STRIP_PTR(value);
72 #endif /* __has_feature(ptrauth_calls) */
73
74 return value >= VM_MIN_KERNEL_AND_KEXT_ADDRESS && value <= VM_MAX_KERNEL_ADDRESS;
75 }
76
77 static void
log_context_cursor_advance(os_log_context_t ctx,size_t amount)78 log_context_cursor_advance(os_log_context_t ctx, size_t amount)
79 {
80 ctx->ctx_content_off += amount;
81 assert(log_context_cursor(ctx) <= (ctx->ctx_buffer + ctx->ctx_buffer_sz));
82 }
83
84 static bool
log_fits(os_log_context_t ctx,size_t data_size)85 log_fits(os_log_context_t ctx, size_t data_size)
86 {
87 return (ctx->ctx_content_off + data_size) <= ctx->ctx_content_sz;
88 }
89
90 static bool
log_fits_cmd(os_log_context_t ctx,size_t data_size)91 log_fits_cmd(os_log_context_t ctx, size_t data_size)
92 {
93 return log_fits(ctx, sizeof(*ctx->ctx_hdr) + data_size);
94 }
95
96 static void
log_range_update(os_log_fmt_range_t range,uint16_t offset,uint16_t length)97 log_range_update(os_log_fmt_range_t range, uint16_t offset, uint16_t length)
98 {
99 range->offset = offset;
100 /*
101 * Truncated flag may have already been set earlier, hence do not
102 * overwrite it blindly.
103 */
104 if (length < range->length) {
105 range->truncated = true;
106 }
107 range->length = length;
108 }
109
110 /*
111 * Stores a command in the main section. The value itself is wrapped in
112 * the os_log_fmt_cmd_t struct.
113 */
114 static void
log_add_cmd(os_log_context_t ctx,os_log_fmt_cmd_type_t type,uint8_t flags,void * arg,size_t arg_size)115 log_add_cmd(os_log_context_t ctx, os_log_fmt_cmd_type_t type, uint8_t flags,
116 void *arg, size_t arg_size)
117 {
118 os_log_fmt_cmd_t cmd;
119 const size_t cmd_sz = sizeof(*cmd) + arg_size;
120
121 assert(log_fits_cmd(ctx, cmd_sz));
122 assert(arg_size <= UINT8_MAX);
123
124 cmd = (os_log_fmt_cmd_t)log_context_cursor(ctx);
125 cmd->cmd_type = type;
126 cmd->cmd_flags = flags;
127 cmd->cmd_size = (uint8_t)arg_size;
128 (void) memcpy(cmd->cmd_data, arg, cmd->cmd_size);
129
130 assert(cmd_sz == sizeof(*cmd) + cmd->cmd_size);
131 log_context_cursor_advance(ctx, cmd_sz);
132 }
133
134 /*
135 * Collect details about argument which needs to be stored in the pubdata
136 * section.
137 */
138 static void
log_collect_public_range_data(os_log_context_t ctx,os_log_fmt_range_t range,void * arg)139 log_collect_public_range_data(os_log_context_t ctx, os_log_fmt_range_t range, void *arg)
140 {
141 ctx->ctx_pubdata[ctx->ctx_pubdata_cnt++] = (char *)arg;
142 ctx->ctx_pubdata_sz += range->length;
143 }
144
145 static void
log_add_range_data(os_log_context_t ctx,os_log_fmt_range_t range,void * arg)146 log_add_range_data(os_log_context_t ctx, os_log_fmt_range_t range, void *arg)
147 {
148 assert(log_fits(ctx, range->length));
149 (void) memcpy(log_context_cursor(ctx), arg, range->length);
150 log_context_cursor_advance(ctx, range->length);
151 }
152
153 static struct os_log_fmt_range_s
log_create_range(os_log_context_t ctx,size_t arg_len)154 log_create_range(os_log_context_t ctx, size_t arg_len)
155 {
156 const size_t final_arg_len = MIN(arg_len, UINT16_MAX);
157
158 return (struct os_log_fmt_range_s) {
159 .offset = ctx->ctx_pubdata_sz,
160 .length = (uint16_t)final_arg_len,
161 .truncated = (final_arg_len < arg_len)
162 };
163 }
164
165 static int
log_add_range_arg(os_log_context_t ctx,os_log_fmt_cmd_type_t type,os_log_fmt_cmd_flags_t flags,void * arg,size_t arg_len)166 log_add_range_arg(os_log_context_t ctx, os_log_fmt_cmd_type_t type, os_log_fmt_cmd_flags_t flags,
167 void *arg, size_t arg_len)
168 {
169 struct os_log_fmt_range_s range;
170
171 if (!log_fits_cmd(ctx, sizeof(range))) {
172 return ENOMEM;
173 }
174
175 range = log_create_range(ctx, arg_len);
176
177 if (flags == OSLF_CMD_FLAG_PUBLIC) {
178 if (ctx->ctx_pubdata_cnt == OS_LOG_MAX_PUB_ARGS) {
179 return ENOMEM;
180 }
181 assert(ctx->ctx_pubdata_cnt < OS_LOG_MAX_PUB_ARGS);
182 log_collect_public_range_data(ctx, &range, arg);
183 }
184 log_add_cmd(ctx, type, flags, &range, sizeof(range));
185 ctx->ctx_hdr->hdr_cmd_cnt++;
186
187 return 0;
188 }
189
190 /*
191 * Adds a scalar argument value to the main section.
192 */
193 static int
log_add_arg(os_log_context_t ctx,os_log_fmt_cmd_type_t type,void * arg,size_t arg_len)194 log_add_arg(os_log_context_t ctx, os_log_fmt_cmd_type_t type, void *arg, size_t arg_len)
195 {
196 assert(type == OSLF_CMD_TYPE_COUNT || type == OSLF_CMD_TYPE_SCALAR);
197 assert(arg_len < UINT16_MAX);
198
199 if (log_fits_cmd(ctx, arg_len)) {
200 log_add_cmd(ctx, type, OSLF_CMD_FLAG_PUBLIC, arg, arg_len);
201 ctx->ctx_hdr->hdr_cmd_cnt++;
202 return 0;
203 }
204
205 return ENOMEM;
206 }
207
208 static void
log_encode_public_data(os_log_context_t ctx)209 log_encode_public_data(os_log_context_t ctx)
210 {
211 const uint16_t orig_content_off = ctx->ctx_content_off;
212 os_log_fmt_hdr_t const hdr = ctx->ctx_hdr;
213 os_log_fmt_cmd_t cmd = (os_log_fmt_cmd_t)hdr->hdr_data;
214
215 assert(ctx->ctx_pubdata_cnt <= hdr->hdr_cmd_cnt);
216
217 for (int i = 0, pub_i = 0; i < hdr->hdr_cmd_cnt; i++, cmd = (os_log_fmt_cmd_t)(cmd->cmd_data + cmd->cmd_size)) {
218 if (cmd->cmd_type != OSLF_CMD_TYPE_STRING) {
219 continue;
220 }
221
222 os_log_fmt_range_t const range __attribute__((aligned(8))) = (os_log_fmt_range_t)&cmd->cmd_data;
223
224 // Fix offset and length of the argument data in the hdr.
225 log_range_update(range, ctx->ctx_content_off - orig_content_off,
226 MIN(range->length, ctx->ctx_content_sz - ctx->ctx_content_off));
227
228 if (range->truncated) {
229 ctx->ctx_truncated = true;
230 }
231
232 assert(pub_i < ctx->ctx_pubdata_cnt);
233 log_add_range_data(ctx, range, ctx->ctx_pubdata[pub_i++]);
234 }
235 }
236
237 static bool
log_expand(os_log_context_t ctx,size_t new_size)238 log_expand(os_log_context_t ctx, size_t new_size)
239 {
240 assert(new_size > ctx->ctx_buffer_sz);
241
242 if (!oslog_is_safe()) {
243 return false;
244 }
245
246 size_t final_size = new_size;
247
248 void *buf = logmem_alloc_locked(ctx->ctx_logmem, &final_size);
249 if (!buf) {
250 return false;
251 }
252 assert(final_size >= new_size);
253
254 // address length header + already stored data
255 const size_t hdr_size = (uint8_t *)ctx->ctx_hdr - ctx->ctx_buffer;
256 const size_t copy_size = hdr_size + sizeof(*ctx->ctx_hdr) + ctx->ctx_content_sz;
257 assert(copy_size <= new_size);
258 (void) memcpy(buf, ctx->ctx_buffer, copy_size);
259
260 if (ctx->ctx_allocated) {
261 logmem_free_locked(ctx->ctx_logmem, ctx->ctx_buffer, ctx->ctx_buffer_sz);
262 }
263
264 ctx->ctx_buffer = buf;
265 ctx->ctx_buffer_sz = final_size;
266 ctx->ctx_content_sz = (uint16_t)(ctx->ctx_buffer_sz - hdr_size - sizeof(*ctx->ctx_hdr));
267 ctx->ctx_hdr = (os_log_fmt_hdr_t)&ctx->ctx_buffer[hdr_size];
268 ctx->ctx_allocated = true;
269
270 return true;
271 }
272
273 static int
log_encode_fmt_arg(void * arg,size_t arg_len,os_log_fmt_cmd_type_t type,os_log_context_t ctx)274 log_encode_fmt_arg(void *arg, size_t arg_len, os_log_fmt_cmd_type_t type, os_log_context_t ctx)
275 {
276 int rc = 0;
277
278 switch (type) {
279 case OSLF_CMD_TYPE_COUNT:
280 case OSLF_CMD_TYPE_SCALAR:
281 // Scrub kernel pointers.
282 if (doprnt_hide_pointers && is_kernel_pointer(arg, arg_len)) {
283 rc = log_add_range_arg(ctx, type, OSLF_CMD_FLAG_PRIVATE, NULL, 0);
284 ctx->ctx_hdr->hdr_flags |= OSLF_HDR_FLAG_HAS_PRIVATE;
285 } else {
286 rc = log_add_arg(ctx, type, arg, arg_len);
287 }
288 break;
289 case OSLF_CMD_TYPE_STRING:
290 rc = log_add_range_arg(ctx, type, OSLF_CMD_FLAG_PUBLIC, arg, arg_len);
291 ctx->ctx_hdr->hdr_flags |= OSLF_HDR_FLAG_HAS_NON_SCALAR;
292 break;
293 default:
294 panic("Unsupported log value type");
295 }
296
297 return rc;
298 }
299
300 static int
log_encode_fmt(os_log_context_t ctx,const char * format,va_list args)301 log_encode_fmt(os_log_context_t ctx, const char *format, va_list args)
302 {
303 const char *position = format;
304
305 while ((position = strchr(position, '%'))) {
306 position++; // Look at character(s) after %.
307
308 int type = OST_INT;
309 boolean_t has_precision = false;
310 int precision = 0;
311
312 for (bool done = false; !done; position++) {
313 union os_log_fmt_types_u value;
314 size_t str_length;
315 int err = 0;
316
317 switch (position[0]) {
318 case '%':
319 // %% prints % character
320 done = true;
321 break;
322
323 /* type of types or other */
324 case 'l': // longer
325 type++;
326 break;
327
328 case 'h': // shorter
329 type--;
330 break;
331
332 case 'z':
333 type = OST_SIZE;
334 break;
335
336 case 'j':
337 type = OST_INTMAX;
338 break;
339
340 case 't':
341 type = OST_PTRDIFF;
342 break;
343
344 case 'q':
345 type = OST_LONGLONG;
346 break;
347
348 case '.': // precision
349 if (position[1] == '*') {
350 // Dynamic precision, argument holds actual value.
351 precision = va_arg(args, int);
352 position++;
353 } else {
354 // Static precision, the value follows in the fmt.
355 precision = 0;
356 while (is_digit(position[1])) {
357 if (precision < LOG_FMT_MAX_PRECISION) {
358 precision = 10 * precision + (position[1] - '0');
359 }
360 position++;
361 }
362 precision = MIN(precision, LOG_FMT_MAX_PRECISION);
363 }
364 err = log_encode_fmt_arg(&precision, sizeof(precision), OSLF_CMD_TYPE_COUNT, ctx);
365 // A negative precision is treated as though it were missing.
366 if (precision >= 0) {
367 has_precision = true;
368 }
369 break;
370
371 case '-': // left-align
372 case '+': // force sign
373 case ' ': // prefix non-negative with space
374 case '#': // alternate
375 case '\'': // group by thousands
376 break;
377
378 /* fixed types */
379 case 'd': // integer
380 case 'i': // integer
381 case 'o': // octal
382 case 'u': // unsigned
383 case 'x': // hex
384 case 'X': // upper-hex
385 switch (type) {
386 case OST_CHAR:
387 value.ch = (char) va_arg(args, int);
388 err = log_encode_fmt_arg(&value.ch, sizeof(value.ch), OSLF_CMD_TYPE_SCALAR, ctx);
389 break;
390
391 case OST_SHORT:
392 value.s = (short) va_arg(args, int);
393 err = log_encode_fmt_arg(&value.s, sizeof(value.s), OSLF_CMD_TYPE_SCALAR, ctx);
394 break;
395
396 case OST_INT:
397 value.i = va_arg(args, int);
398 err = log_encode_fmt_arg(&value.i, sizeof(value.i), OSLF_CMD_TYPE_SCALAR, ctx);
399 break;
400
401 case OST_LONG:
402 value.l = va_arg(args, long);
403 err = log_encode_fmt_arg(&value.l, sizeof(value.l), OSLF_CMD_TYPE_SCALAR, ctx);
404 break;
405
406 case OST_LONGLONG:
407 value.ll = va_arg(args, long long);
408 err = log_encode_fmt_arg(&value.ll, sizeof(value.ll), OSLF_CMD_TYPE_SCALAR, ctx);
409 break;
410
411 case OST_SIZE:
412 value.z = va_arg(args, size_t);
413 err = log_encode_fmt_arg(&value.z, sizeof(value.z), OSLF_CMD_TYPE_SCALAR, ctx);
414 break;
415
416 case OST_INTMAX:
417 value.im = va_arg(args, intmax_t);
418 err = log_encode_fmt_arg(&value.im, sizeof(value.im), OSLF_CMD_TYPE_SCALAR, ctx);
419 break;
420
421 case OST_PTRDIFF:
422 value.pd = va_arg(args, ptrdiff_t);
423 err = log_encode_fmt_arg(&value.pd, sizeof(value.pd), OSLF_CMD_TYPE_SCALAR, ctx);
424 break;
425
426 default:
427 return EINVAL;
428 }
429 done = true;
430 break;
431
432 case 'p': // pointer
433 value.p = va_arg(args, void *);
434 err = log_encode_fmt_arg(&value.p, sizeof(value.p), OSLF_CMD_TYPE_SCALAR, ctx);
435 done = true;
436 break;
437
438 case 'c': // char
439 value.ch = (char) va_arg(args, int);
440 err = log_encode_fmt_arg(&value.ch, sizeof(value.ch), OSLF_CMD_TYPE_SCALAR, ctx);
441 done = true;
442 break;
443
444 case 's': // string
445 value.pch = va_arg(args, char *);
446 if (!value.pch) {
447 str_length = 0;
448 } else if (has_precision) {
449 assert(precision >= 0);
450 str_length = strnlen(value.pch, precision);
451 } else {
452 str_length = strlen(value.pch) + 1;
453 }
454 err = log_encode_fmt_arg(value.pch, str_length, OSLF_CMD_TYPE_STRING, ctx);
455 done = true;
456 break;
457
458 case 'm':
459 value.i = 0; // Does %m make sense in the kernel?
460 err = log_encode_fmt_arg(&value.i, sizeof(value.i), OSLF_CMD_TYPE_SCALAR, ctx);
461 done = true;
462 break;
463
464 case '0' ... '9':
465 // Skipping field width, libtrace takes care of it.
466 break;
467
468 default:
469 return EINVAL;
470 }
471
472 if (slowpath(err)) {
473 return err;
474 }
475 }
476 }
477
478 return 0;
479 }
480
481 static inline size_t
write_address_location(uint8_t buf[static sizeof (uint64_t)],void * dso,const void * address,firehose_tracepoint_flags_t * flags,bool driverKit)482 write_address_location(uint8_t buf[static sizeof(uint64_t)],
483 void *dso, const void *address, firehose_tracepoint_flags_t *flags, bool driverKit)
484 {
485 uintptr_t shift_addr = (uintptr_t)address - (uintptr_t)dso;
486
487 kc_format_t kcformat = KCFormatUnknown;
488 __assert_only bool result = PE_get_primary_kc_format(&kcformat);
489 assert(result);
490
491 if (kcformat == KCFormatStatic || kcformat == KCFormatKCGEN) {
492 *flags = _firehose_tracepoint_flags_pc_style_shared_cache;
493 memcpy(buf, (uint32_t[]){ (uint32_t)shift_addr }, sizeof(uint32_t));
494 return sizeof(uint32_t);
495 }
496
497 /*
498 * driverKit will have the dso set as MH_EXECUTE (it is logging from a
499 * syscall in the kernel) but needs logd to parse the address as an
500 * absolute pc.
501 */
502 kernel_mach_header_t *mh = dso;
503 if (mh->filetype == MH_EXECUTE && !driverKit) {
504 *flags = _firehose_tracepoint_flags_pc_style_main_exe;
505 memcpy(buf, (uint32_t[]){ (uint32_t)shift_addr }, sizeof(uint32_t));
506 return sizeof(uint32_t);
507 }
508
509 *flags = _firehose_tracepoint_flags_pc_style_absolute;
510 shift_addr = driverKit ? (uintptr_t)address : VM_KERNEL_UNSLIDE(address);
511 size_t len = sizeof(uintptr_t);
512
513 #if __LP64__
514 len = 6; // 48 bits are enough
515 #endif
516 memcpy(buf, (uintptr_t[]){ shift_addr }, len);
517
518 return len;
519 }
520
521 static void
os_log_encode_location(os_log_context_t ctx,void * addr,void * dso,bool driverKit,firehose_tracepoint_flags_t * ft_flags)522 os_log_encode_location(os_log_context_t ctx, void *addr, void *dso, bool driverKit,
523 firehose_tracepoint_flags_t *ft_flags)
524 {
525 const size_t hdr_size = write_address_location(ctx->ctx_buffer, dso, addr, ft_flags, driverKit);
526 ctx->ctx_hdr = (os_log_fmt_hdr_t)&ctx->ctx_buffer[hdr_size];
527 ctx->ctx_content_sz = (uint16_t)(ctx->ctx_buffer_sz - hdr_size - sizeof(*ctx->ctx_hdr));
528 }
529
530 /*
531 * Encodes argument (meta)data into a format consumed by libtrace. Stores
532 * metadada for all arguments first. Metadata also include scalar argument
533 * values. Second step saves data which are encoded separately from respective
534 * metadata (like strings).
535 */
536 bool
os_log_context_encode(os_log_context_t ctx,const char * fmt,va_list args,void * addr,void * dso,bool driverKit)537 os_log_context_encode(os_log_context_t ctx, const char *fmt, va_list args, void *addr, void *dso, bool driverKit)
538 {
539 os_log_encode_location(ctx, addr, dso, driverKit, &ctx->ctx_ft_flags);
540
541 va_list args_copy;
542 va_copy(args_copy, args);
543
544 int rc = log_encode_fmt(ctx, fmt, args);
545
546 va_end(args_copy);
547
548 switch (rc) {
549 case EINVAL:
550 // Bogus/Unsupported fmt string
551 counter_inc(&oslog_p_fmt_invalid_msgcount);
552 return false;
553 case ENOMEM:
554 /*
555 * The fmt contains unreasonable number of arguments (> 32) and
556 * we ran out of space. We could call log_expand()
557 * here and retry. However, using such formatting strings rather
558 * seem like a misuse of the logging system, hence error.
559 */
560 counter_inc(&oslog_p_fmt_max_args_msgcount);
561 return false;
562 case 0:
563 break;
564 default:
565 panic("unhandled return value");
566 }
567
568 if (ctx->ctx_pubdata_sz == 0) {
569 goto finish;
570 }
571
572 /*
573 * Logmem may not have been set up yet when logging very early during
574 * the boot. Be sure to check its state.
575 */
576 if (!log_fits(ctx, ctx->ctx_pubdata_sz) && logmem_ready(ctx->ctx_logmem)) {
577 size_t space_needed = log_context_cursor(ctx) + ctx->ctx_pubdata_sz - ctx->ctx_buffer;
578 space_needed = MIN(space_needed, logmem_max_size(ctx->ctx_logmem));
579 (void) log_expand(ctx, space_needed);
580 }
581
582 log_encode_public_data(ctx);
583
584 if (ctx->ctx_truncated) {
585 counter_inc(&oslog_p_truncated_msgcount);
586 }
587 finish:
588 ctx->ctx_content_sz = (uint16_t)(log_context_cursor(ctx) - ctx->ctx_buffer);
589 ctx->ctx_content_off = 0;
590 return true;
591 }
592
593 void
os_log_context_init(os_log_context_t ctx,logmem_t * logmem,uint8_t * buffer,size_t buffer_sz)594 os_log_context_init(os_log_context_t ctx, logmem_t *logmem, uint8_t *buffer, size_t buffer_sz)
595 {
596 assert(logmem);
597 assert(buffer);
598 assert(buffer_sz > 0);
599
600 bzero(ctx, sizeof(*ctx));
601 ctx->ctx_logmem = logmem;
602 ctx->ctx_buffer = buffer;
603 ctx->ctx_buffer_sz = buffer_sz;
604 }
605
606 void
os_log_context_free(os_log_context_t ctx)607 os_log_context_free(os_log_context_t ctx)
608 {
609 if (ctx->ctx_allocated) {
610 logmem_free_locked(ctx->ctx_logmem, ctx->ctx_buffer, ctx->ctx_buffer_sz);
611 }
612 }
613