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
45typedef struct {
46 uint8_t *tp_buf;
47 size_t tp_size;
48} tracepoint_buf_t;
49
50SCALABLE_COUNTER_DEFINE(oslog_p_fmt_invalid_msgcount);
51SCALABLE_COUNTER_DEFINE(oslog_p_fmt_max_args_msgcount);
52SCALABLE_COUNTER_DEFINE(oslog_p_truncated_msgcount);
53
54extern boolean_t doprnt_hide_pointers;
55
56static bool
57is_digit(char ch)
58{
59 return (ch >= '0') && (ch <= '9');
60}
61
62static bool
63is_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(dst: &value, src: arg, n: 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
84static void
85log_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
91static bool
92log_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
97static bool
98log_fits_cmd(os_log_context_t ctx, size_t data_size)
99{
100 return log_fits(ctx, data_size: sizeof(*ctx->ctx_hdr) + data_size);
101}
102
103static void
104log_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 */
121static void
122log_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(dst: cmd->cmd_data, src: arg, n: cmd->cmd_size);
136
137 assert(cmd_sz == sizeof(*cmd) + cmd->cmd_size);
138 log_context_cursor_advance(ctx, amount: cmd_sz);
139}
140
141/*
142 * Collect details about argument which needs to be stored in the pubdata
143 * section.
144 */
145static void
146log_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
152static void
153log_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), src: arg, n: range->length);
157 log_context_cursor_advance(ctx, amount: range->length);
158}
159
160static struct os_log_fmt_range_s
161log_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
172static int
173log_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, data_size: 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: &range, arg);
190 }
191 log_add_cmd(ctx, type, flags, arg: &range, arg_size: 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 */
200static int
201log_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, data_size: arg_len)) {
207 log_add_cmd(ctx, type, flags: OSLF_CMD_FLAG_PUBLIC, arg, arg_size: arg_len);
208 ctx->ctx_hdr->hdr_cmd_cnt++;
209 return 0;
210 }
211
212 return ENOMEM;
213}
214
215static void
216log_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, offset: 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, arg: ctx->ctx_pubdata[pub_i++]);
241 }
242}
243
244static bool
245log_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(dst: buf, src: ctx->ctx_buffer, n: 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
280static int
281log_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, flags: OSLF_CMD_FLAG_PRIVATE, NULL, arg_len: 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, flags: 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
307static int
308log_encode_fmt(os_log_context_t ctx, const char *format, va_list args)
309{
310 const char *position = format;
311
312 while ((position = strchr(s: position, c: '%'))) {
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(ch: 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(arg: &precision, arg_len: sizeof(precision), type: 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(arg: &value.ch, arg_len: sizeof(value.ch), type: 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(arg: &value.s, arg_len: sizeof(value.s), type: 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(arg: &value.i, arg_len: sizeof(value.i), type: 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(arg: &value.l, arg_len: sizeof(value.l), type: 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(arg: &value.ll, arg_len: sizeof(value.ll), type: 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(arg: &value.z, arg_len: sizeof(value.z), type: 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(arg: &value.im, arg_len: sizeof(value.im), type: 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(arg: &value.pd, arg_len: sizeof(value.pd), type: 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(arg: &value.p, arg_len: sizeof(value.p), type: 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(arg: &value.ch, arg_len: sizeof(value.ch), type: 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(s: value.pch, n: precision);
458 } else {
459 str_length = strlen(s: value.pch) + 1;
460 }
461 err = log_encode_fmt_arg(arg: value.pch, arg_len: str_length, type: 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(arg: &value.i, arg_len: sizeof(value.i), type: 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
488OS_ALWAYS_INLINE
489static inline void
490tracepoint_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(dst: &tp->tp_buf[tp->tp_size], src: data, n: size);
494 tp->tp_size += size;
495}
496
497static void
498tracepoint_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(tp: tpb, data: (uintptr_t[]){ loc }, size: loc_size);
505 } else {
506 assert(loc_size == sizeof(uint32_t));
507 tracepoint_buf_add(tp: tpb, data: (uint32_t[]){ (uint32_t)loc }, size: loc_size);
508 }
509}
510
511static void
512os_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(s: ctx->ctx_hdr, n: 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 */
526bool
527os_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: &tpb, loc, loc_size);
536 if (os_log_subsystem_id_valid(subsystem_id)) {
537 tracepoint_buf_add(tp: &tpb, data: &subsystem_id, size: sizeof(subsystem_id));
538 }
539 os_log_context_prepare_header(ctx, hdr_size: tpb.tp_size);
540
541 va_list args_copy;
542 va_copy(args_copy, args);
543
544 int rc = log_encode_fmt(ctx, format: 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, data_size: 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, new_size: space_needed);
580 }
581
582 log_encode_public_data(ctx);
583
584 if (ctx->ctx_truncated) {
585 counter_inc(&oslog_p_truncated_msgcount);
586 }
587finish:
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
593void
594os_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(s: ctx, n: sizeof(*ctx));
601 ctx->ctx_logmem = logmem;
602 ctx->ctx_buffer = buffer;
603 ctx->ctx_buffer_sz = buffer_sz;
604}
605
606void
607os_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