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_internal.h"
39 #include "log_mem.h"
40
41 #define LOG_FMT_MAX_PRECISION (1024)
42 #define log_context_cursor(ctx) &(ctx)->ctx_hdr->hdr_data[(ctx)->ctx_content_off]
43 #define TRACEPOINT_BUF_MAX_SIZE (64)
44
45 typedef struct {
46 uint8_t *tp_buf;
47 size_t tp_size;
48 } tracepoint_buf_t;
49
50 SCALABLE_COUNTER_DEFINE(oslog_p_fmt_invalid_msgcount);
51 SCALABLE_COUNTER_DEFINE(oslog_p_fmt_max_args_msgcount);
52 SCALABLE_COUNTER_DEFINE(oslog_p_truncated_msgcount);
53
54 extern boolean_t doprnt_hide_pointers;
55
56 static bool
is_digit(char ch)57 is_digit(char ch)
58 {
59 return (ch >= '0') && (ch <= '9');
60 }
61
62 static bool
is_kernel_pointer(void * arg,size_t arg_len)63 is_kernel_pointer(void *arg, size_t arg_len)
64 {
65 if (arg_len < sizeof(void *)) {
66 return false;
67 }
68
69 unsigned long long value = 0;
70 assert(arg_len <= sizeof(value));
71 (void) memcpy(&value, arg, arg_len);
72
73 #if __has_feature(ptrauth_calls)
74 /**
75 * Strip out the pointer authentication code before
76 * checking whether the pointer is a kernel address.
77 */
78 value = (unsigned long long)VM_KERNEL_STRIP_PTR(value);
79 #endif /* __has_feature(ptrauth_calls) */
80
81 return value >= VM_MIN_KERNEL_AND_KEXT_ADDRESS && value <= VM_MAX_KERNEL_ADDRESS;
82 }
83
84 static void
log_context_cursor_advance(os_log_context_t ctx,size_t amount)85 log_context_cursor_advance(os_log_context_t ctx, size_t amount)
86 {
87 ctx->ctx_content_off += amount;
88 assert(log_context_cursor(ctx) <= (ctx->ctx_buffer + ctx->ctx_buffer_sz));
89 }
90
91 static bool
log_fits(os_log_context_t ctx,size_t data_size)92 log_fits(os_log_context_t ctx, size_t data_size)
93 {
94 return (ctx->ctx_content_off + data_size) <= ctx->ctx_content_sz;
95 }
96
97 static bool
log_fits_cmd(os_log_context_t ctx,size_t data_size)98 log_fits_cmd(os_log_context_t ctx, size_t data_size)
99 {
100 return log_fits(ctx, sizeof(*ctx->ctx_hdr) + data_size);
101 }
102
103 static void
log_range_update(os_log_fmt_range_t range,uint16_t offset,uint16_t length)104 log_range_update(os_log_fmt_range_t range, uint16_t offset, uint16_t length)
105 {
106 range->offset = offset;
107 /*
108 * Truncated flag may have already been set earlier, hence do not
109 * overwrite it blindly.
110 */
111 if (length < range->length) {
112 range->truncated = true;
113 }
114 range->length = length;
115 }
116
117 /*
118 * Stores a command in the main section. The value itself is wrapped in
119 * the os_log_fmt_cmd_t struct.
120 */
121 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)122 log_add_cmd(os_log_context_t ctx, os_log_fmt_cmd_type_t type, uint8_t flags,
123 void *arg, size_t arg_size)
124 {
125 os_log_fmt_cmd_t cmd;
126 const size_t cmd_sz = sizeof(*cmd) + arg_size;
127
128 assert(log_fits_cmd(ctx, cmd_sz));
129 assert(arg_size <= UINT8_MAX);
130
131 cmd = (os_log_fmt_cmd_t)log_context_cursor(ctx);
132 cmd->cmd_type = type;
133 cmd->cmd_flags = flags;
134 cmd->cmd_size = (uint8_t)arg_size;
135 (void) memcpy(cmd->cmd_data, arg, cmd->cmd_size);
136
137 assert(cmd_sz == sizeof(*cmd) + cmd->cmd_size);
138 log_context_cursor_advance(ctx, cmd_sz);
139 }
140
141 /*
142 * Collect details about argument which needs to be stored in the pubdata
143 * section.
144 */
145 static void
log_collect_public_range_data(os_log_context_t ctx,os_log_fmt_range_t range,void * arg)146 log_collect_public_range_data(os_log_context_t ctx, os_log_fmt_range_t range, void *arg)
147 {
148 ctx->ctx_pubdata[ctx->ctx_pubdata_cnt++] = (char *)arg;
149 ctx->ctx_pubdata_sz += range->length;
150 }
151
152 static void
log_add_range_data(os_log_context_t ctx,os_log_fmt_range_t range,void * arg)153 log_add_range_data(os_log_context_t ctx, os_log_fmt_range_t range, void *arg)
154 {
155 assert(log_fits(ctx, range->length));
156 (void) memcpy(log_context_cursor(ctx), arg, range->length);
157 log_context_cursor_advance(ctx, range->length);
158 }
159
160 static struct os_log_fmt_range_s
log_create_range(os_log_context_t ctx,size_t arg_len)161 log_create_range(os_log_context_t ctx, size_t arg_len)
162 {
163 const size_t final_arg_len = MIN(arg_len, UINT16_MAX);
164
165 return (struct os_log_fmt_range_s) {
166 .offset = ctx->ctx_pubdata_sz,
167 .length = (uint16_t)final_arg_len,
168 .truncated = (final_arg_len < arg_len)
169 };
170 }
171
172 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)173 log_add_range_arg(os_log_context_t ctx, os_log_fmt_cmd_type_t type, os_log_fmt_cmd_flags_t flags,
174 void *arg, size_t arg_len)
175 {
176 struct os_log_fmt_range_s range;
177
178 if (!log_fits_cmd(ctx, sizeof(range))) {
179 return ENOMEM;
180 }
181
182 range = log_create_range(ctx, arg_len);
183
184 if (flags == OSLF_CMD_FLAG_PUBLIC) {
185 if (ctx->ctx_pubdata_cnt == OS_LOG_MAX_PUB_ARGS) {
186 return ENOMEM;
187 }
188 assert(ctx->ctx_pubdata_cnt < OS_LOG_MAX_PUB_ARGS);
189 log_collect_public_range_data(ctx, &range, arg);
190 }
191 log_add_cmd(ctx, type, flags, &range, sizeof(range));
192 ctx->ctx_hdr->hdr_cmd_cnt++;
193
194 return 0;
195 }
196
197 /*
198 * Adds a scalar argument value to the main section.
199 */
200 static int
log_add_arg(os_log_context_t ctx,os_log_fmt_cmd_type_t type,void * arg,size_t arg_len)201 log_add_arg(os_log_context_t ctx, os_log_fmt_cmd_type_t type, void *arg, size_t arg_len)
202 {
203 assert(type == OSLF_CMD_TYPE_COUNT || type == OSLF_CMD_TYPE_SCALAR);
204 assert(arg_len < UINT16_MAX);
205
206 if (log_fits_cmd(ctx, arg_len)) {
207 log_add_cmd(ctx, type, OSLF_CMD_FLAG_PUBLIC, arg, arg_len);
208 ctx->ctx_hdr->hdr_cmd_cnt++;
209 return 0;
210 }
211
212 return ENOMEM;
213 }
214
215 static void
log_encode_public_data(os_log_context_t ctx)216 log_encode_public_data(os_log_context_t ctx)
217 {
218 const uint16_t orig_content_off = ctx->ctx_content_off;
219 os_log_fmt_hdr_t const hdr = ctx->ctx_hdr;
220 os_log_fmt_cmd_t cmd = (os_log_fmt_cmd_t)hdr->hdr_data;
221
222 assert(ctx->ctx_pubdata_cnt <= hdr->hdr_cmd_cnt);
223
224 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)) {
225 if (cmd->cmd_type != OSLF_CMD_TYPE_STRING) {
226 continue;
227 }
228
229 os_log_fmt_range_t const range __attribute__((aligned(8))) = (os_log_fmt_range_t)&cmd->cmd_data;
230
231 // Fix offset and length of the argument data in the hdr.
232 log_range_update(range, ctx->ctx_content_off - orig_content_off,
233 MIN(range->length, ctx->ctx_content_sz - ctx->ctx_content_off));
234
235 if (range->truncated) {
236 ctx->ctx_truncated = true;
237 }
238
239 assert(pub_i < ctx->ctx_pubdata_cnt);
240 log_add_range_data(ctx, range, ctx->ctx_pubdata[pub_i++]);
241 }
242 }
243
244 static bool
log_expand(os_log_context_t ctx,size_t new_size)245 log_expand(os_log_context_t ctx, size_t new_size)
246 {
247 assert(new_size > ctx->ctx_buffer_sz);
248
249 if (!oslog_is_safe()) {
250 return false;
251 }
252
253 size_t final_size = new_size;
254
255 void *buf = logmem_alloc_locked(ctx->ctx_logmem, &final_size);
256 if (!buf) {
257 return false;
258 }
259 assert(final_size >= new_size);
260
261 // address length header + already stored data
262 const size_t hdr_size = (uint8_t *)ctx->ctx_hdr - ctx->ctx_buffer;
263 const size_t copy_size = hdr_size + sizeof(*ctx->ctx_hdr) + ctx->ctx_content_sz;
264 assert(copy_size <= new_size);
265 (void) memcpy(buf, ctx->ctx_buffer, copy_size);
266
267 if (ctx->ctx_allocated) {
268 logmem_free_locked(ctx->ctx_logmem, ctx->ctx_buffer, ctx->ctx_buffer_sz);
269 }
270
271 ctx->ctx_buffer = buf;
272 ctx->ctx_buffer_sz = final_size;
273 ctx->ctx_content_sz = (uint16_t)(ctx->ctx_buffer_sz - hdr_size - sizeof(*ctx->ctx_hdr));
274 ctx->ctx_hdr = (os_log_fmt_hdr_t)&ctx->ctx_buffer[hdr_size];
275 ctx->ctx_allocated = true;
276
277 return true;
278 }
279
280 static int
log_encode_fmt_arg(void * arg,size_t arg_len,os_log_fmt_cmd_type_t type,os_log_context_t ctx)281 log_encode_fmt_arg(void *arg, size_t arg_len, os_log_fmt_cmd_type_t type, os_log_context_t ctx)
282 {
283 int rc = 0;
284
285 switch (type) {
286 case OSLF_CMD_TYPE_COUNT:
287 case OSLF_CMD_TYPE_SCALAR:
288 // Scrub kernel pointers.
289 if (doprnt_hide_pointers && is_kernel_pointer(arg, arg_len)) {
290 rc = log_add_range_arg(ctx, type, OSLF_CMD_FLAG_PRIVATE, NULL, 0);
291 ctx->ctx_hdr->hdr_flags |= OSLF_HDR_FLAG_HAS_PRIVATE;
292 } else {
293 rc = log_add_arg(ctx, type, arg, arg_len);
294 }
295 break;
296 case OSLF_CMD_TYPE_STRING:
297 rc = log_add_range_arg(ctx, type, OSLF_CMD_FLAG_PUBLIC, arg, arg_len);
298 ctx->ctx_hdr->hdr_flags |= OSLF_HDR_FLAG_HAS_NON_SCALAR;
299 break;
300 default:
301 panic("Unsupported log value type");
302 }
303
304 return rc;
305 }
306
307 static int
log_encode_fmt(os_log_context_t ctx,const char * format,va_list args)308 log_encode_fmt(os_log_context_t ctx, const char *format, va_list args)
309 {
310 const char *position = format;
311
312 while ((position = strchr(position, '%'))) {
313 position++; // Look at character(s) after %.
314
315 int type = OST_INT;
316 boolean_t has_precision = false;
317 int precision = 0;
318
319 for (bool done = false; !done; position++) {
320 union os_log_fmt_types_u value;
321 size_t str_length;
322 int err = 0;
323
324 switch (position[0]) {
325 case '%':
326 // %% prints % character
327 done = true;
328 break;
329
330 /* type of types or other */
331 case 'l': // longer
332 type++;
333 break;
334
335 case 'h': // shorter
336 type--;
337 break;
338
339 case 'z':
340 type = OST_SIZE;
341 break;
342
343 case 'j':
344 type = OST_INTMAX;
345 break;
346
347 case 't':
348 type = OST_PTRDIFF;
349 break;
350
351 case 'q':
352 type = OST_LONGLONG;
353 break;
354
355 case '.': // precision
356 if (position[1] == '*') {
357 // Dynamic precision, argument holds actual value.
358 precision = va_arg(args, int);
359 position++;
360 } else {
361 // Static precision, the value follows in the fmt.
362 precision = 0;
363 while (is_digit(position[1])) {
364 if (precision < LOG_FMT_MAX_PRECISION) {
365 precision = 10 * precision + (position[1] - '0');
366 }
367 position++;
368 }
369 precision = MIN(precision, LOG_FMT_MAX_PRECISION);
370 }
371 err = log_encode_fmt_arg(&precision, sizeof(precision), OSLF_CMD_TYPE_COUNT, ctx);
372 // A negative precision is treated as though it were missing.
373 if (precision >= 0) {
374 has_precision = true;
375 }
376 break;
377
378 case '-': // left-align
379 case '+': // force sign
380 case ' ': // prefix non-negative with space
381 case '#': // alternate
382 case '\'': // group by thousands
383 break;
384
385 /* fixed types */
386 case 'd': // integer
387 case 'i': // integer
388 case 'o': // octal
389 case 'u': // unsigned
390 case 'x': // hex
391 case 'X': // upper-hex
392 switch (type) {
393 case OST_CHAR:
394 value.ch = (char) va_arg(args, int);
395 err = log_encode_fmt_arg(&value.ch, sizeof(value.ch), OSLF_CMD_TYPE_SCALAR, ctx);
396 break;
397
398 case OST_SHORT:
399 value.s = (short) va_arg(args, int);
400 err = log_encode_fmt_arg(&value.s, sizeof(value.s), OSLF_CMD_TYPE_SCALAR, ctx);
401 break;
402
403 case OST_INT:
404 value.i = va_arg(args, int);
405 err = log_encode_fmt_arg(&value.i, sizeof(value.i), OSLF_CMD_TYPE_SCALAR, ctx);
406 break;
407
408 case OST_LONG:
409 value.l = va_arg(args, long);
410 err = log_encode_fmt_arg(&value.l, sizeof(value.l), OSLF_CMD_TYPE_SCALAR, ctx);
411 break;
412
413 case OST_LONGLONG:
414 value.ll = va_arg(args, long long);
415 err = log_encode_fmt_arg(&value.ll, sizeof(value.ll), OSLF_CMD_TYPE_SCALAR, ctx);
416 break;
417
418 case OST_SIZE:
419 value.z = va_arg(args, size_t);
420 err = log_encode_fmt_arg(&value.z, sizeof(value.z), OSLF_CMD_TYPE_SCALAR, ctx);
421 break;
422
423 case OST_INTMAX:
424 value.im = va_arg(args, intmax_t);
425 err = log_encode_fmt_arg(&value.im, sizeof(value.im), OSLF_CMD_TYPE_SCALAR, ctx);
426 break;
427
428 case OST_PTRDIFF:
429 value.pd = va_arg(args, ptrdiff_t);
430 err = log_encode_fmt_arg(&value.pd, sizeof(value.pd), OSLF_CMD_TYPE_SCALAR, ctx);
431 break;
432
433 default:
434 return EINVAL;
435 }
436 done = true;
437 break;
438
439 case 'p': // pointer
440 value.p = va_arg(args, void *);
441 err = log_encode_fmt_arg(&value.p, sizeof(value.p), OSLF_CMD_TYPE_SCALAR, ctx);
442 done = true;
443 break;
444
445 case 'c': // char
446 value.ch = (char) va_arg(args, int);
447 err = log_encode_fmt_arg(&value.ch, sizeof(value.ch), OSLF_CMD_TYPE_SCALAR, ctx);
448 done = true;
449 break;
450
451 case 's': // string
452 value.pch = va_arg(args, char *);
453 if (!value.pch) {
454 str_length = 0;
455 } else if (has_precision) {
456 assert(precision >= 0);
457 str_length = strnlen(value.pch, precision);
458 } else {
459 str_length = strlen(value.pch) + 1;
460 }
461 err = log_encode_fmt_arg(value.pch, str_length, OSLF_CMD_TYPE_STRING, ctx);
462 done = true;
463 break;
464
465 case 'm':
466 value.i = 0; // Does %m make sense in the kernel?
467 err = log_encode_fmt_arg(&value.i, sizeof(value.i), OSLF_CMD_TYPE_SCALAR, ctx);
468 done = true;
469 break;
470
471 case '0' ... '9':
472 // Skipping field width, libtrace takes care of it.
473 break;
474
475 default:
476 return EINVAL;
477 }
478
479 if (slowpath(err)) {
480 return err;
481 }
482 }
483 }
484
485 return 0;
486 }
487
488 OS_ALWAYS_INLINE
489 static inline void
tracepoint_buf_add(tracepoint_buf_t * tp,const void * data,size_t size)490 tracepoint_buf_add(tracepoint_buf_t *tp, const void *data, size_t size)
491 {
492 assert((tp->tp_size + size) <= TRACEPOINT_BUF_MAX_SIZE);
493 memcpy(&tp->tp_buf[tp->tp_size], data, size);
494 tp->tp_size += size;
495 }
496
497 static void
tracepoint_buf_location(tracepoint_buf_t * tpb,uintptr_t loc,size_t loc_size)498 tracepoint_buf_location(tracepoint_buf_t *tpb, uintptr_t loc, size_t loc_size)
499 {
500 if (loc_size == sizeof(uintptr_t)) {
501 #if __LP64__
502 loc_size = 6; // 48 bits are enough
503 #endif
504 tracepoint_buf_add(tpb, (uintptr_t[]){ loc }, loc_size);
505 } else {
506 assert(loc_size == sizeof(uint32_t));
507 tracepoint_buf_add(tpb, (uint32_t[]){ (uint32_t)loc }, loc_size);
508 }
509 }
510
511 static void
os_log_context_prepare_header(os_log_context_t ctx,size_t hdr_size)512 os_log_context_prepare_header(os_log_context_t ctx, size_t hdr_size)
513 {
514 assert(hdr_size > 0 && hdr_size <= TRACEPOINT_BUF_MAX_SIZE);
515 ctx->ctx_hdr = (os_log_fmt_hdr_t)&ctx->ctx_buffer[hdr_size];
516 bzero(ctx->ctx_hdr, sizeof(*ctx->ctx_hdr));
517 ctx->ctx_content_sz = (uint16_t)(ctx->ctx_buffer_sz - hdr_size - sizeof(*ctx->ctx_hdr));
518 }
519
520 /*
521 * Encodes argument (meta)data into a format consumed by libtrace. Stores
522 * metadada for all arguments first. Metadata also include scalar argument
523 * values. Second step saves data which are encoded separately from respective
524 * metadata (like strings).
525 */
526 bool
os_log_context_encode(os_log_context_t ctx,const char * fmt,va_list args,uintptr_t loc,size_t loc_size,uint16_t subsystem_id)527 os_log_context_encode(os_log_context_t ctx, const char *fmt, va_list args,
528 uintptr_t loc, size_t loc_size, uint16_t subsystem_id)
529 {
530 tracepoint_buf_t tpb = {
531 .tp_buf = ctx->ctx_buffer,
532 .tp_size = 0
533 };
534
535 tracepoint_buf_location(&tpb, loc, loc_size);
536 if (os_log_subsystem_id_valid(subsystem_id)) {
537 tracepoint_buf_add(&tpb, &subsystem_id, sizeof(subsystem_id));
538 }
539 os_log_context_prepare_header(ctx, tpb.tp_size);
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