darlinghq/darling
1
0
Fork 0
mirror of https://github.com/darlinghq/darling.git synced 2024-11-23 20:29:47 +00:00
Code Issues Actions Packages Projects Releases Wiki Activity

Many improvements for xtrace

Browse Source 
The biggest improvement is the ability to log xtrace's output to a separate file for each thread. Jumbled output has been a big reason why xtrace is hard to use with multi-threaded programs, but this provides a nice optional solution to that problem. It doesn't come without its drawbacks, however: because xtrace has to open descriptors for the logfiles, it can affect program behavior, especially if the program sees the descriptors and decides to do something with them (like close them, which some programs do).

xtrace no longer buffers output on the stack (which could lead to stack overflows or truncated output). Actually, it doesn't buffer output at all anymore, which might be an issue (it means more potentially jumbled output when using the normal output method). If turns out to be a signifcant issue, we can re-add buffering in xtrace_log using a per-thread buffer rather than an on-stack one.

The kevent family of syscalls is now properly described! This means that those calls will now print much more useful output.

Also, to work around a stack overflow issue when running within signal handlers, xtrace now overrides the default sigstack with its own larger one. It's not apparent why xtrace is using so much stack space, but it seems like 16KiB is enough for now (rather than the default of 8KiB).

Executing the xtrace command with no arguments now produces a help message describing the various environment variables that can be used to modify xtrace's behavior.

Also, the simple printf family of functions in libsystem_kernel now support various argument sizes.

Finally, there's no reason to call the wrapper for `semaphore_signal_trap` in `bsdthread_terminate` (causing unnecessary xtrace output), so call our implementation directly instead.
This commit is contained in:
Ariel Abreu 2021-11-14 00:52:12 -05:00
parent 7d753e4203
commit 7fc8b6d04c
No known key found for this signature in database
GPG Key ID: D67AE16CCEA85B70
20 changed files with 1156 additions and 313 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
Developer/Platforms/MacOSX.platform/Developer/SDKs/MacOSX.sdk/usr/include/darling/emulation/signal/sigaltstack.h Symbolic link
View File

@ -0,0 +1 @@
../../../../../../../../../../../src/kernel/emulation/linux/signal/sigaltstack.h

4
src/kernel/emulation/linux/bsdthread/bsdthread_terminate.c
View File

@ -14,7 +14,7 @@ int bsdthread_terminate_trap(
unsigned long freesize,
int thread,
int sem);
int semaphore_signal_trap(int signal_name);
int semaphore_signal_trap_impl(int signal_name);
long sys_bsdthread_terminate(void* stackaddr, unsigned long freesize, int port,
int join_sem)
@ -26,7 +26,7 @@ long sys_bsdthread_terminate(void* stackaddr, unsigned long freesize, int port,
unsigned long freesize, unsigned long pthobj_size);
extern int lkm_call(int, void*);
semaphore_signal_trap(join_sem);
semaphore_signal_trap_impl(join_sem);
lkm_call(NR_thread_death_announce, 0);
return __darling_thread_terminate(stackaddr, freesize, pthread_obj_size);

23
src/kernel/emulation/linux/ext/for-xtrace.c
View File

@ -1,6 +1,8 @@
#include "for-xtrace.h"
#include "../mman/mman.h"
#include "../misc/abort_with_payload.h"
#include "../fcntl/open.h"
#include "../unistd/close.h"
VISIBLE
void* _mmap_for_xtrace(void* start, unsigned long len, int prot, int flags, int fd, long pos) {
@ -16,3 +18,24 @@ VISIBLE
long _abort_with_payload_for_xtrace(unsigned int reason_namespace, unsigned long long reason_code, void *payload, unsigned int payload_size, const char *reason_string, unsigned long long reason_flags) {
return sys_abort_with_payload(reason_namespace, reason_code, payload, payload_size, reason_string, reason_flags);
};
// __write_for_xtrace is in unistd/write.c
long _open_for_xtrace(const char* filename, int flags, unsigned int mode) {
return sys_open_nocancel(filename, flags, mode);
};
long _close_for_xtrace(int fd) {
return sys_close_nocancel(fd);
};
extern size_t default_sigaltstack_size;
long _sigaltstack_set_default_size_for_xtrace(size_t new_size) {
default_sigaltstack_size = new_size;
return 0;
};
long _sigaltstack_for_xtrace(const struct bsd_stack* ss, struct bsd_stack* oss) {
return sys_sigaltstack(ss, oss);
};

17
src/kernel/emulation/linux/ext/for-xtrace.h
View File

@ -3,6 +3,7 @@
#include <darling/emulation/base.h>
#include <darling/emulation/mman/duct_mman.h>
#include <darling/emulation/signal/sigaltstack.h>
VISIBLE
void* _mmap_for_xtrace(void* start, unsigned long len, int prot, int flags, int fd, long pos);
@ -13,4 +14,20 @@ long _munmap_for_xtrace(void* addr, unsigned long len);
VISIBLE
long _abort_with_payload_for_xtrace(unsigned int reason_namespace, unsigned long long reason_code, void *payload, unsigned int payload_size, const char *reason_string, unsigned long long reason_flags);
VISIBLE
long __write_for_xtrace(int fd, const void* mem, int len);
VISIBLE
long _open_for_xtrace(const char* filename, int flags, unsigned int mode);
VISIBLE
long _close_for_xtrace(int fd);
VISIBLE
long _sigaltstack_set_default_size_for_xtrace(size_t new_size);
// used to bypass the sigaltstack size requirements imposed by libc
VISIBLE
long _sigaltstack_for_xtrace(const struct bsd_stack* ss, struct bsd_stack* oss);
#endif // _DARLING_EMULATION_FOR_XTRACE_H_

24
src/kernel/emulation/linux/signal/sigexc.c
View File

@ -30,6 +30,7 @@ void darling_sigexc_uninstall(void);
void sigrt_handler(int signum, struct linux_siginfo* info, void* ctxt);
static char sigexc_altstack[8*1024];
size_t default_sigaltstack_size = sizeof(sigexc_altstack);
#if defined(__x86_64__)
static void mcontext_to_thread_state(const struct linux_gregset* regs, x86_thread_state64_t* s);
@ -73,7 +74,7 @@ static void dump_gregs(const struct linux_gregset* regs)
unsigned long long* p = (unsigned long long*) regs;
for (int i = 0; i < 23; i++)
{
kern_printf("sigexc: gregs 0x%x\n", p[i]);
kern_printf("sigexc: gregs 0x%llx\n", p[i]);
}
}
@ -226,7 +227,7 @@ void sigexc_handler(int linux_signum, struct linux_siginfo* info, struct linux_u
memcpy(&sigprocess.linux_siginfo, info, sizeof(*info));
#ifdef __x86_64__
kern_printf("sigexc: have RIP 0x%x\n", ctxt->uc_mcontext.gregs.rip);
kern_printf("sigexc: have RIP 0x%llx\n", ctxt->uc_mcontext.gregs.rip);
#endif
thread_t thread = mach_thread_self();
@ -302,7 +303,7 @@ void sigexc_handler(int linux_signum, struct linux_siginfo* info, struct linux_u
kern_printf("sigexc: handler (%d) returning\n", linux_signum);
}
#define DUMPREG(regname) kern_printf("sigexc: " #regname ": 0x%x\n", regs->regname);
#define DUMPREG(regname) kern_printf("sigexc: " #regname ": 0x%llx\n", regs->regname);
#if defined(__x86_64__)
void mcontext_to_thread_state(const struct linux_gregset* regs, x86_thread_state64_t* s)
@ -493,12 +494,19 @@ void float_state_to_mcontext(const x86_float_state32_t* s, linux_fpregset_t fx)
void sigexc_thread_setup(void)
{
struct bsd_stack newstack = {
.ss_size = sizeof(sigexc_altstack),
.ss_size = default_sigaltstack_size,
.ss_flags = 0
};
newstack.ss_sp = (void*) sys_mmap(NULL, sizeof(sigexc_altstack), PROT_READ | PROT_WRITE,
#if SIGALTSTACK_GUARD
newstack.ss_sp = (void*) sys_mmap(NULL, newstack.ss_size + 4096, PROT_READ | PROT_WRITE,
MAP_ANON | MAP_PRIVATE, -1, 0);
sys_mprotect(newstack.ss_sp, 4096, PROT_NONE);
newstack.ss_sp = (char*)newstack.ss_sp + 4096;
#else
newstack.ss_sp = (void*) sys_mmap(NULL, newstack.ss_size, PROT_READ | PROT_WRITE,
MAP_ANON | MAP_PRIVATE, -1, 0);
#endif
sys_sigaltstack(&newstack, NULL);
}
@ -507,6 +515,10 @@ void sigexc_thread_exit(void)
struct bsd_stack oldstack;
sys_sigaltstack(NULL, &oldstack);
sys_munmap(oldstack.ss_sp, oldstack.ss_flags);
#if SIGALTSTACK_GUARD
sys_munmap((char*)oldstack.ss_sp - 4096, oldstack.ss_size + 4096);
#else
sys_munmap(oldstack.ss_sp, oldstack.ss_size);
#endif
}

195
src/kernel/emulation/linux/simple.c
View File

@ -30,12 +30,60 @@ int __simple_vsnprintf(char* buf, size_t max_length, const char* format, va_list
{
if (*format == '%')
{
enum format_size {
format_size_default,
format_size_short_short,
format_size_short,
format_size_long,
format_size_long_long,
format_size_max,
format_size_size_type,
format_size_ptrdiff,
};
enum format_size format_size = format_size_default;
format++;
if (!*format)
break;
if (*format == 'l')
format++;
switch (*format) {
case 'l':
format++;
if (*format == 'l') {
format++;
format_size = format_size_long_long;
} else {
format_size = format_size_long;
}
break;
case 'h':
format++;
if (*format == 'h') {
format++;
format_size = format_size_short;
} else {
format_size = format_size_short_short;
}
break;
case 'j':
format++;
format_size = format_size_max;
break;
case 'z':
format++;
format_size = format_size_size_type;
break;
case 't':
format++;
format_size = format_size_ptrdiff;
break;
}
switch (*format)
{
case '%':
@ -60,10 +108,33 @@ int __simple_vsnprintf(char* buf, size_t max_length, const char* format, va_list
}
case 'd':
{
int num = va_arg(vl, int);
char temp[16];
intmax_t num = 0;
char temp[20];
int count = 0;
switch (format_size) {
case format_size_short:
case format_size_short_short:
case format_size_default:
num = va_arg(vl, int);
break;
case format_size_long:
num = va_arg(vl, long int);
break;
case format_size_long_long:
num = va_arg(vl, long long int);
break;
case format_size_max:
num = va_arg(vl, intmax_t);
break;
case format_size_size_type:
num = va_arg(vl, size_t);
break;
case format_size_ptrdiff:
num = va_arg(vl, ptrdiff_t);
break;
}
if (num < 0)
{
if (offset < max_length)
@ -90,10 +161,33 @@ int __simple_vsnprintf(char* buf, size_t max_length, const char* format, va_list
}
case 'u':
{
unsigned int num = va_arg(vl, unsigned int);
char temp[16];
uintmax_t num = 0;
char temp[20];
int count = 0;
switch (format_size) {
case format_size_short:
case format_size_short_short:
case format_size_default:
num = va_arg(vl, unsigned int);
break;
case format_size_long:
num = va_arg(vl, unsigned long int);
break;
case format_size_long_long:
num = va_arg(vl, unsigned long long int);
break;
case format_size_max:
num = va_arg(vl, uintmax_t);
break;
case format_size_size_type:
num = va_arg(vl, size_t);
break;
case format_size_ptrdiff:
num = va_arg(vl, ptrdiff_t);
break;
}
do
{
temp[count++] = '0' + (num % 10);
@ -113,10 +207,37 @@ int __simple_vsnprintf(char* buf, size_t max_length, const char* format, va_list
case 'p':
case 'x':
{
unsigned long num = va_arg(vl, unsigned long);
uintmax_t num = 0;
char temp[40];
int count = 0;
if (*format == 'p') {
num = va_arg(vl, void*);
} else {
switch (format_size) {
case format_size_short:
case format_size_short_short:
case format_size_default:
num = va_arg(vl, unsigned int);
break;
case format_size_long:
num = va_arg(vl, unsigned long int);
break;
case format_size_long_long:
num = va_arg(vl, unsigned long long int);
break;
case format_size_max:
num = va_arg(vl, uintmax_t);
break;
case format_size_size_type:
num = va_arg(vl, size_t);
break;
case format_size_ptrdiff:
num = va_arg(vl, ptrdiff_t);
break;
}
}
if (*format == 'p')
{
if (offset < max_length)
@ -152,10 +273,33 @@ int __simple_vsnprintf(char* buf, size_t max_length, const char* format, va_list
case 'o':
{
unsigned int num = va_arg(vl, unsigned int);
uintmax_t num = 0;
char temp[16];
int count = 0;
switch (format_size) {
case format_size_short:
case format_size_short_short:
case format_size_default:
num = va_arg(vl, unsigned int);
break;
case format_size_long:
num = va_arg(vl, unsigned long int);
break;
case format_size_long_long:
num = va_arg(vl, unsigned long long int);
break;
case format_size_max:
num = va_arg(vl, uintmax_t);
break;
case format_size_size_type:
num = va_arg(vl, size_t);
break;
case format_size_ptrdiff:
num = va_arg(vl, ptrdiff_t);
break;
}
do
{
temp[count++] = '0' + (num % 8);
@ -172,6 +316,15 @@ int __simple_vsnprintf(char* buf, size_t max_length, const char* format, va_list
break;
}
case 'c':
{
int num = va_arg(vl, int);
if (offset < max_length)
buf[offset] = (char)num;
offset++;
break;
}
}
format++;
@ -242,6 +395,30 @@ void __simple_fprintf(int fd, const char* format, ...)
LINUX_SYSCALL3(__NR_write, fd, buffer, __simple_strlen(buffer));
}
__attribute__ ((visibility ("default")))
void __simple_vprintf(const char* format, va_list args)
{
char buffer[512];
__simple_vsnprintf(buffer, sizeof(buffer), format, args);
LINUX_SYSCALL3(__NR_write, 1, buffer, __simple_strlen(buffer));
}
__attribute__ ((visibility ("default")))
void __simple_vkprintf(const char* format, va_list args)
{
char buffer[512];
__simple_vsnprintf(buffer, sizeof(buffer), format, args);
lkm_call(NR_kernel_printk, buffer);
}
__attribute__ ((visibility ("default")))
void __simple_vfprintf(int fd, const char* format, va_list args)
{
char buffer[512];
__simple_vsnprintf(buffer, sizeof(buffer), format, args);
LINUX_SYSCALL3(__NR_write, fd, buffer, __simple_strlen(buffer));
}
__attribute__ ((visibility ("default")))
int __simple_sprintf(char *buffer, const char* format, ...)
{

3
src/kernel/emulation/linux/simple.h
View File

@ -18,6 +18,9 @@ int __simple_strlen(const char* str);
int __simple_vsprintf(char* buf, const char* format, va_list vl) __attribute__((format(printf, 2, 0)));
int __simple_vsnprintf(char* buffer, size_t max_length, const char* format, va_list args) __attribute__((format(printf, 3, 0)));
int __simple_snprintf(char* buffer, size_t max_length, const char* format, ...) __attribute__((format(printf, 3, 4)));
void __simple_vprintf(const char* format, va_list args) __attribute__((format(printf, 1, 0)));
void __simple_vkprintf(const char* format, va_list args) __attribute__((format(printf, 1, 0)));
void __simple_vfprintf(int fd, const char* format, va_list args) __attribute__((format(printf, 2, 0)));
unsigned long long __simple_atoi(const char* str, const char** endp);
unsigned long long __simple_atoi16(const char* str, const char** endp);

639
src/xtrace/bsd_trace.cpp
View File

@ -6,15 +6,26 @@
#define PRIVATE 1
#include <spawn_private.h>
#include <sys/event.h>
#include "xtracelib.h"
#include "bsd_trace.h"
#include "tls.h"
static void print_errno(char* buf, int nr, uintptr_t rv);
static void print_errno_num(char* buf, int nr, uintptr_t rv);
static void print_errno_ptr(char* buf, int nr, uintptr_t rv);
static void print_errno(int nr, uintptr_t rv);
static void print_errno_num(int nr, uintptr_t rv);
static void print_errno_ptr(int nr, uintptr_t rv);
static void print_args(char* buf, int nr, void* args[]);
static void print_args(int nr, void* args[]);
static void print_kevent_return(int nr, uintptr_t rv);
static void print_kevent_args(int nr, void* args[]);
static void print_kevent64_return(int nr, uintptr_t rv);
static void print_kevent64_args(int nr, void* args[]);
static void print_kevent_qos_return(int nr, uintptr_t rv);
static void print_kevent_qos_args(int nr, void* args[]);
static void print_timespec(const struct timespec* timespec);
// awk '/^[0-9]/ { if ($6 !~ "nosys") { split($6, a, "("); print "[" $1 "] = { \"" a[1] "\", print_args, print_errno }," } }'
@ -289,17 +300,26 @@ static const struct calldef bsd_defs[600] = {
[360] = { "bsdthread_create", print_args, print_errno_num },
[361] = { "bsdthread_terminate", print_args, print_errno_num },
[362] = { "kqueue", print_args, print_errno_num },
[363] = { "kevent", print_args, print_errno_num },
// kevent is special
[363] = { "kevent", print_kevent_args, print_kevent_return },
[364] = { "lchown", print_args, print_errno_num },
[366] = { "bsdthread_register", print_args, print_errno_num },
[367] = { "workq_open", print_args, print_errno_num },
[368] = { "workq_kernreturn", print_args, print_errno_num },
[369] = { "kevent64", print_args, print_errno_num },
// kevent64 is special
[369] = { "kevent64", print_kevent64_args, print_kevent64_return },
[370] = { "__old_semwait_signal", print_args, print_errno_num },
[371] = { "__old_semwait_signal_nocancel", print_args, print_errno_num },
[372] = { "thread_selfid", print_args, print_errno_num },
[373] = { "ledger", print_args, print_errno_num },
[374] = { "kevent_qos", print_args, print_errno_num },
// kevent_qos is special
[374] = { "kevent_qos", print_kevent_qos_args, print_kevent_qos_return },
[380] = { "__mac_execve", print_args, print_errno_num },
[381] = { "__mac_syscall", print_args, print_errno_num },
[382] = { "__mac_get_file", print_args, print_errno_num },
@ -421,105 +441,94 @@ static const struct calldef bsd_defs[600] = {
[521] = { "abort_with_payload", print_args, print_errno_num },
};
static int print_arg_int(char* buf, void* arg)
static void print_arg_int(void* arg)
{
return __simple_sprintf(buf, "%d", (int) (long) arg);
xtrace_log("%d", (int) (long) arg);
}
static int print_arg_ptr(char* buf, void* arg)
static void print_arg_ptr(void* arg)
{
if (arg == NULL)
return __simple_sprintf(buf, "NULL");
return __simple_sprintf(buf, "%p", arg);
xtrace_log("NULL");
else
xtrace_log("%p", arg);
}
extern "C"
int xtrace_format_string_literal(char* buf, const char* str)
{
const char* initial_buf = buf;
if (str == NULL)
{
return __simple_sprintf(buf, "NULL");
void xtrace_print_string_literal(const char* str) {
if (str == NULL) {
xtrace_log("NULL");
return;
}
if (!xtrace_no_color)
buf += __simple_sprintf(buf, "\033[;1m"); // bold
xtrace_log("\033[;1m"); // bold
*buf++ = '"';
xtrace_log("\"");
for (; *str; str++)
{
switch (*str)
{
case '\\':
*buf++ = '\\';
*buf++ = '\\';
xtrace_log("\\\\");
break;
case '\n':
*buf++ = '\\';
*buf++ = 'n';
xtrace_log("\\n");
break;
case '\t':
*buf++ = '\\';
*buf++ = 't';
xtrace_log("\\t");
break;
default:
*buf++ = *str;
xtrace_log("%c", *str);
break;
}
}
*buf++ = '"';
xtrace_log("\"");
if (!xtrace_no_color)
buf += __simple_sprintf(buf, "\033[0m"); // reset
return buf - initial_buf;
xtrace_log("\033[0m"); // reset
}
static int print_arg_str(char* buf, void* arg)
static void print_arg_str(void* arg)
{
const char* str = (const char*) arg;
return xtrace_format_string_literal(buf, str);
xtrace_print_string_literal(str);
}
static int print_arg_prot(char* buf, void* arg)
static void print_arg_prot(void* arg)
{
const char* initial_buf = buf;
int cnt = 0;
int prot = (int) (long) arg;
int prot = (int)(long)arg;
if (prot & PROT_READ)
{
buf += __simple_sprintf(buf, "PROT_READ");
xtrace_log("PROT_READ");
cnt++;
}
if (prot & PROT_WRITE)
{
if (cnt > 0)
*buf++ = '|';
buf += __simple_sprintf(buf, "PROT_WRITE");
xtrace_log("|");
xtrace_log("PROT_WRITE");
cnt++;
}
if (prot & PROT_EXEC)
{
if (cnt > 0)
*buf++ = '|';
buf += __simple_sprintf(buf, "PROT_EXEC");
xtrace_log("|");
xtrace_log("PROT_EXEC");
cnt++;
}
if (cnt == 0)
{
buf += __simple_sprintf(buf, "PROT_NONE");
xtrace_log("PROT_NONE");
}
return buf - initial_buf;
}
static int print_mmap_flags(char* buf, void* arg)
static void print_mmap_flags(void* arg)
{
const char* initial_buf = buf;
int cnt = 0;
int flags = (int) (long) arg;
@ -541,24 +550,21 @@ static int print_mmap_flags(char* buf, void* arg)
if (flags & all_flags[i].flag)
{
if (cnt > 0)
*buf++ = '|';
buf += __simple_sprintf(buf, "%s", all_flags[i].name);
xtrace_log("|");
xtrace_log("%s", all_flags[i].name);
cnt++;
}
}
if (cnt == 0)
{
buf += __simple_sprintf(buf, "MAP_FILE");
xtrace_log("MAP_FILE");
}
return buf - initial_buf;
}
extern "C"
int print_open_flags(char* buf, void* arg)
void print_open_flags(void* arg)
{
const char* initial_buf = buf;
int cnt = 0;
int flags = (int) (long) arg;
@ -589,43 +595,39 @@ int print_open_flags(char* buf, void* arg)
if (flags & all_flags[i].flag)
{
if (cnt > 0)
*buf++ = '|';
buf += __simple_sprintf(buf, "%s", all_flags[i].name);
xtrace_log("|");
xtrace_log("%s", all_flags[i].name);
cnt++;
}
}
if (cnt == 0)
{
buf += __simple_sprintf(buf, "O_RDONLY");
xtrace_log("O_RDONLY");
}
return buf - initial_buf;
}
extern "C" int print_arg_posix_spawn_args(char* buf, void* arg);
extern "C" void print_arg_posix_spawn_args(void* arg);
static int print_arg_string_array(char* buf, void* arg) {
const char* initial_buf = buf;
const char* const* argv = (const char* const*)arg;
static void print_arg_string_array(void* arg) {
const char* const* array = (const char* const*)arg;
bool is_first = true;
*buf++ = '{';
xtrace_log("{");
for (const char* const* ptr = argv; *ptr != NULL; ++ptr) {
if (is_first) {
is_first = false;
} else {
*buf++ = ',';
*buf++ = ' ';
if (array) {
for (const char* const* ptr = array; *ptr != NULL; ++ptr) {
if (is_first) {
is_first = false;
} else {
xtrace_log(", ");
}
xtrace_print_string_literal(*ptr);
}
buf += xtrace_format_string_literal(buf, *ptr);
}
*buf++ = '}';
return buf - initial_buf;
xtrace_log("}");
};
// TODO: output more specific information for certain calls
@ -634,7 +636,7 @@ static int print_arg_string_array(char* buf, void* arg) {
static const struct {
int args_cnt;
int (*print_arg[8])(char* buf, void* arg);
void (*print_arg[8])(void* arg);
} args_info[] = {
[1] = { 1, { print_arg_int } }, // exit
[2] = { 0, { } }, // fork
@ -906,17 +908,17 @@ static const struct {
[360] = { 5, { print_arg_ptr, print_arg_ptr, print_arg_ptr, print_arg_ptr, print_arg_int } }, // bsdthread_create
[361] = { 4, { print_arg_ptr, print_arg_int, print_arg_int, print_arg_int } }, // bsdthread_terminate
[362] = { 0, { } }, // kqueue
[363] = { 6, { print_arg_int, print_arg_ptr, print_arg_int, print_arg_ptr, print_arg_int, print_arg_ptr } }, // kevent
// kevent is special
[364] = { 3, { print_arg_str, print_arg_int, print_arg_int } }, // lchown
[366] = { 7, { print_arg_ptr, print_arg_ptr, print_arg_int, print_arg_ptr, print_arg_ptr, print_arg_int, print_arg_int } }, // bsdthread_register
[367] = { 0, { } }, // workq_open
[368] = { 4, { print_arg_int, print_arg_ptr, print_arg_int, print_arg_int } }, // workq_kernreturn
[369] = { 7, { print_arg_int, print_arg_ptr, print_arg_int, print_arg_ptr, print_arg_int, print_arg_int, print_arg_ptr } }, // kevent64
// kevent64 is special
[370] = { 5, { print_arg_int, print_arg_int, print_arg_int, print_arg_int, print_arg_ptr } }, // __old_semwait_signal
[371] = { 5, { print_arg_int, print_arg_int, print_arg_int, print_arg_int, print_arg_ptr } }, // __old_semwait_signal_nocancel
[372] = { 0, { } }, // thread_selfid
[373] = { 4, { print_arg_int, print_arg_ptr, print_arg_ptr, print_arg_ptr } }, // ledger
[374] = { 8, { print_arg_int, print_arg_ptr, print_arg_int, print_arg_ptr, print_arg_int, print_arg_ptr, print_arg_ptr, print_arg_int } }, // kevent_qos
// kevent_qos is special
[380] = { 4, { print_arg_ptr, print_arg_ptr, print_arg_ptr, print_arg_ptr } }, // __mac_execve
[381] = { 3, { print_arg_ptr, print_arg_int, print_arg_ptr } }, // __mac_syscall
[382] = { 2, { print_arg_ptr, print_arg_ptr } }, // __mac_get_file
@ -1038,16 +1040,15 @@ static const struct {
[521] = { 6, { print_arg_int, print_arg_int, print_arg_ptr, print_arg_int, print_arg_str, print_arg_int } }, // abort_with_payload
};
static void print_args(char* buf, int nr, void* args[])
static void print_args(int nr, void* args[])
{
int cnt = args_info[nr].args_cnt;
for (int i = 0; i < cnt; i++)
{
if (i > 0)
buf += __simple_sprintf(buf, ", ");
buf += (*args_info[nr].print_arg[i])(buf, args[i]);
xtrace_log(", ");
(*args_info[nr].print_arg[i])(args[i]);
}
*buf = 0;
}
@ -1060,7 +1061,7 @@ void darling_bsd_syscall_entry_print(int nr, void* args[])
{
// For exit() or execve(), print an extra newline,
// as we're likely not going to see the return.
xtrace_printf("\n");
xtrace_log("\n");
}
}
@ -1179,37 +1180,489 @@ const char* error_strings[128] = {
[106] = "EQFULL",
};
static void print_errno_num(char* buf, int nr, uintptr_t rv)
static void print_errno_num(int nr, uintptr_t rv)
{
intptr_t v = (intptr_t)rv;
if (v >= 0 || v < -4095)
{
__simple_sprintf(buf, "%ld", rv);
xtrace_log("%ld", rv);
}
else
print_errno(buf, nr, rv);
print_errno(nr, rv);
}
static void print_errno_ptr(char* buf, int nr, uintptr_t rv)
static void print_errno_ptr(int nr, uintptr_t rv)
{
intptr_t v = (intptr_t)rv;
if (v >= 0 || v < -4095)
{
__simple_sprintf(buf, "%p", (void*) rv);
xtrace_log("%p", (void*) rv);
}
else
print_errno(buf, nr, rv);
print_errno(nr, rv);
}
static void print_errno(char* buf, int nr, uintptr_t rv)
static void print_errno(int nr, uintptr_t rv)
{
const char* error = NULL;
intptr_t v = (intptr_t) rv;
if (-v < 128)
error = error_strings[-v];
if (error != NULL)
__simple_sprintf(buf, "%s", error);
xtrace_log("%s", error);
else
__simple_sprintf(buf, "%ld", v);
xtrace_log("%ld", v);
}
static const char* const filter_names[] = {
"EVFILT_READ",
"EVFILT_WRITE",
"EVFILT_AIO",
"EVFILT_VNODE",
"EVFILT_PROC",
"EVFILT_SIGNAL",
"EVFILT_TIMER",
"EVFILT_MACHPORT",
"EVFILT_FS",
"EVFILT_USER",
NULL,
"EVFILT_VM",
"EVFILT_SOCK",
"EVFILT_MEMORYSTATUS",
"EVFILT_EXCEPT",
NULL,
"EVFILT_WORKLOOP",
};
static const char* const signal_names[] = {
"SIGHUP",
"SIGINT",
"SIGQUIT",
"SIGILL",
"SIGTRAP",
"SIGABRT",
"SIGEMT",
"SIGFPE",
"SIGKILL",
"SIGBUS",
"SIGSEGV",
"SIGSYS",
"SIGPIPE",
"SIGALRM",
"SIGTERM",
"SIGURG",
"SIGSTOP",
"SIGTSTP",
"SIGCONT",
"SIGCHLD",
"SIGTTIN",
"SIGTTOU",
"SIGIO",
"SIGXCPU",
"SIGXFSZ",
"SIGVTALR",
"SIGPROF",
"SIGWINCH",
"SIGINFO",
"SIGUSR1",
"SIGUSR2",
};
static const struct {
uint16_t flag;
const char* name;
} kevent_flag_names[] = {
#define FLAG(_name) { _name, #_name }
FLAG(EV_ADD),
FLAG(EV_ENABLE),
FLAG(EV_DISABLE),
FLAG(EV_DELETE),
FLAG(EV_RECEIPT),
FLAG(EV_ONESHOT),
FLAG(EV_CLEAR),
FLAG(EV_DISPATCH),
FLAG(EV_UDATA_SPECIFIC),
FLAG(EV_FLAG0),
FLAG(EV_FLAG1),
FLAG(EV_EOF),
FLAG(EV_ERROR),
#undef KEVENT_FLAG
};
static const struct {
uint32_t flag;
const char* name;
} kevent_filter_flag_names[][16] = {
#define FLAG(_name) { _name, #_name }
[~EVFILT_READ] = {
FLAG(NOTE_LOWAT),
},
[~EVFILT_EXCEPT] = {
FLAG(NOTE_OOB),
},
[~EVFILT_VNODE] = {
FLAG(NOTE_DELETE),
FLAG(NOTE_WRITE),
FLAG(NOTE_EXTEND),
FLAG(NOTE_ATTRIB),
FLAG(NOTE_LINK),
FLAG(NOTE_RENAME),
FLAG(NOTE_REVOKE),
FLAG(NOTE_NONE),
FLAG(NOTE_FUNLOCK),
},
[~EVFILT_PROC] = {
FLAG(NOTE_EXIT),
FLAG(NOTE_FORK),
FLAG(NOTE_EXEC),
FLAG(NOTE_REAP),
FLAG(NOTE_SIGNAL),
FLAG(NOTE_EXITSTATUS),
FLAG(NOTE_EXIT_DETAIL),
},
[~EVFILT_TIMER] = {
FLAG(NOTE_SECONDS),
FLAG(NOTE_USECONDS),
FLAG(NOTE_NSECONDS),
FLAG(NOTE_MACHTIME),
FLAG(NOTE_ABSOLUTE),
FLAG(NOTE_MACH_CONTINUOUS_TIME),
FLAG(NOTE_CRITICAL),
FLAG(NOTE_BACKGROUND),
FLAG(NOTE_LEEWAY),
FLAG(NOTE_TRACK),
FLAG(NOTE_TRACKERR),
FLAG(NOTE_CHILD),
},
[~EVFILT_SOCK] = {
FLAG(NOTE_CONNRESET),
FLAG(NOTE_READCLOSED),
FLAG(NOTE_WRITECLOSED),
FLAG(NOTE_TIMEOUT),
FLAG(NOTE_NOSRCADDR),
FLAG(NOTE_IFDENIED),
FLAG(NOTE_SUSPEND),
FLAG(NOTE_RESUME),
FLAG(NOTE_KEEPALIVE),
FLAG(NOTE_ADAPTIVE_WTIMO),
FLAG(NOTE_ADAPTIVE_RTIMO),
FLAG(NOTE_CONNECTED),
FLAG(NOTE_DISCONNECTED),
FLAG(NOTE_CONNINFO_UPDATED),
FLAG(NOTE_NOTIFY_ACK),
},
[~EVFILT_MACHPORT] = {
FLAG(MACH_RCV_MSG),
},
#undef FLAG
};
static void print_kevent_common(int16_t filter, uintptr_t ident, uint16_t flags, uint32_t fflags, intptr_t data, void* udata) {
int filt_index = ~filter;
bool printed_something = false;
xtrace_log("%s { ident = ", (filt_index < 0 || filt_index >= sizeof(filter_names) / sizeof(*filter_names)) ? "EVFILT_UNKNOWN" : filter_names[filt_index]);
switch (filter) {
case EVFILT_READ:
case EVFILT_WRITE:
case EVFILT_EXCEPT:
case EVFILT_VNODE:
case EVFILT_SOCK:
xtrace_log("fd %lu", ident);
break;
case EVFILT_PROC:
xtrace_log("pid %lu", ident);
break;
case EVFILT_SIGNAL:
xtrace_log("signal %s (%lu)", (ident < sizeof(signal_names) / sizeof(*signal_names)) ? signal_names[ident] : "SIGUNKNOWN", ident);
break;
case EVFILT_TIMER:
xtrace_log("timer %lu", ident);
break;
case EVFILT_MACHPORT:
// officially, only portsets can be used with EVFILT_MACHPORT. however, Apple introduced support for single ports in 10.13 or something around that time.
xtrace_log("port/portset %lu", ident);
break;
case EVFILT_FS:
case EVFILT_USER:
case EVFILT_VM:
case EVFILT_MEMORYSTATUS:
case EVFILT_WORKLOOP:
// notes:
// * EVFILT_VM is unsupported on macOS.
// * do EVFILT_FS, EVFILT_MEMORYSTATUS, and EVFILT_WORKLOOP even use `ident`?
xtrace_log("%lu", ident);
break;
default:
xtrace_log("%lu", ident);
break;
}
xtrace_log(", flags = ");
for (size_t i = 0; i < sizeof(kevent_flag_names) / sizeof(*kevent_flag_names); ++i) {
if ((flags & kevent_flag_names[i].flag) == 0) {
continue;
}
if (!printed_something) {
printed_something = true;
} else {
xtrace_log("|");
}
xtrace_log("%s", kevent_flag_names[i].name);
}
xtrace_log("%s(0x%x), fflags = ", printed_something ? " " : "", flags);
printed_something = false;
if (filt_index < sizeof(kevent_filter_flag_names) / sizeof(*kevent_filter_flag_names)) {
for (size_t i = 0; i < sizeof(*kevent_filter_flag_names) / sizeof(**kevent_filter_flag_names); ++i) {
if (!kevent_filter_flag_names[filt_index][i].name) {
break;
}
if ((fflags & kevent_filter_flag_names[filt_index][i].flag) == 0) {
continue;
}
if (!printed_something) {
printed_something = true;
} else {
xtrace_log("|");
}
xtrace_log("%s", kevent_filter_flag_names[filt_index][i].name);
}
}
xtrace_log("%s(0x%x), udata = %p, data = 0x%lx", printed_something ? " " : "", fflags, udata, data);
};
static void print_kevent_structure(const struct kevent* event) {
print_kevent_common(event->filter, event->ident, event->flags, event->fflags, event->data, event->udata);
xtrace_log(" }");
};
static void print_kevent64_structure(const struct kevent64_s* event) {
print_kevent_common(event->filter, event->ident, event->flags, event->fflags, event->data, (void*)(uintptr_t)event->udata);
xtrace_log(", ext[0] = 0x%llx, ext[1] = 0x%llx }", event->ext[0], event->ext[1]);
};
static void print_kevent_qos_structure(const struct kevent_qos_s* event) {
print_kevent_common(event->filter, event->ident, event->flags, event->fflags, event->data, (void*)(uintptr_t)event->udata);
xtrace_log(", ext[0] = 0x%llx, ext[1] = 0x%llx, ext[2] = 0x%llx, ext[3] = 0x%llx, qos = %d, xflags = 0x%x }", event->ext[0], event->ext[1], event->ext[2], event->ext[3], event->qos, event->xflags);
};
DEFINE_XTRACE_TLS_VAR(void*, kevent_stored_list, NULL);
enum class kevent_type {
kevent,
kevent64,
kevent_qos,
};
static void print_kevent_return_common(int nr, uintptr_t rv, kevent_type type) {
void* event_list = get_kevent_stored_list();
int ret = (intptr_t)rv;
set_kevent_stored_list(NULL);
if (ret < 0) {
print_errno(nr, rv);
return;
}
xtrace_log("%d events {", ret);
for (int i = 0; i < ret; ++i) {
if (i == 0) {
xtrace_log(" ");
} else {
xtrace_log(", ");
}
switch (type) {
case kevent_type::kevent:
print_kevent_structure(&((struct kevent*)event_list)[i]);
break;
case kevent_type::kevent64:
print_kevent64_structure(&((struct kevent64_s*)event_list)[i]);
break;
case kevent_type::kevent_qos:
print_kevent_qos_structure(&((struct kevent_qos_s*)event_list)[i]);
break;
}
}
xtrace_log("%s}", ret > 0 ? " " : "");
};
static void print_kevent_return(int nr, uintptr_t rv) {
print_kevent_return_common(nr, rv, kevent_type::kevent);
};
static void print_kevent_args(int nr, void* args[]) {
int kq = (intptr_t)args[0];
const struct kevent* change_list = (const struct kevent*)args[1];
int nchanges = (intptr_t)args[2];
struct kevent* event_list = (struct kevent*)args[3];
int nevents = (intptr_t)args[4];
const struct timespec* timeout = (const struct timespec*)args[5];
set_kevent_stored_list(event_list);
xtrace_log("%d, change_list = {", kq);
for (int i = 0; i < nchanges; ++i) {
if (i == 0) {
xtrace_log(" ");
} else {
xtrace_log(", ");
}
print_kevent_structure(&change_list[i]);
}
xtrace_log("%s}, nchanges = %d, event_list = %p, nevents = %d, timeout = ", nchanges > 0 ? " " : "", nchanges, event_list, nevents);
print_timespec(timeout);
};
static void print_kevent64_return(int nr, uintptr_t rv) {
print_kevent_return_common(nr, rv, kevent_type::kevent64);
};
static struct {
unsigned int flag;
const char* name;
} kevent_call_flags[] = {
#define FLAG(_name) { _name, #_name }
FLAG(KEVENT_FLAG_NONE),
FLAG(KEVENT_FLAG_IMMEDIATE),
FLAG(KEVENT_FLAG_ERROR_EVENTS),
FLAG(KEVENT_FLAG_STACK_DATA),
FLAG(KEVENT_FLAG_WORKQ),
FLAG(KEVENT_FLAG_WORKQ_MANAGER),
FLAG(KEVENT_FLAG_WORKLOOP),
FLAG(KEVENT_FLAG_PARKING),
FLAG(KEVENT_FLAG_WORKLOOP_SERVICER_ATTACH),
FLAG(KEVENT_FLAG_WORKLOOP_SERVICER_DETACH),
FLAG(KEVENT_FLAG_DYNAMIC_KQ_MUST_EXIST),
FLAG(KEVENT_FLAG_DYNAMIC_KQ_MUST_NOT_EXIST),
FLAG(KEVENT_FLAG_WORKLOOP_NO_WQ_THREAD),
#undef FLAG
};
static void print_kevent64_args(int nr, void* args[]) {
int kq = (intptr_t)args[0];
const struct kevent64_s* change_list = (const struct kevent64_s*)args[1];
int nchanges = (intptr_t)args[2];
struct kevent64_s* event_list = (struct kevent64_s*)args[3];
int nevents = (intptr_t)args[4];
unsigned int flags = (uintptr_t)args[5];
const struct timespec* timeout = (const struct timespec*)args[6];
bool printed_something = false;
set_kevent_stored_list(event_list);
xtrace_log("%d, change_list = {", kq);
for (int i = 0; i < nchanges; ++i) {
if (i == 0) {
xtrace_log(" ");
} else {
xtrace_log(", ");
}
print_kevent64_structure(&change_list[i]);
}
xtrace_log("%s}, nchanges = %d, event_list = %p, nevents = %d, flags = ", nchanges > 0 ? " " : "", nchanges, event_list, nevents);
for (size_t i = 0; i < sizeof(kevent_call_flags) / sizeof(*kevent_call_flags); ++i) {
if ((flags & kevent_call_flags[i].flag) == 0) {
continue;
}
if (!printed_something) {
printed_something = true;
} else {
xtrace_log("|");
}
xtrace_log("%s", kevent_call_flags[i].name);
}
if (!printed_something) {
xtrace_log("0");
}
xtrace_log(", timeout = ");
print_timespec(timeout);
};
static void print_kevent_qos_return(int nr, uintptr_t rv) {
print_kevent_return_common(nr, rv, kevent_type::kevent_qos);
};
static void print_kevent_qos_args(int nr, void* args[]) {
int kq = (intptr_t)args[0];
const struct kevent_qos_s* change_list = (const struct kevent_qos_s*)args[1];
int nchanges = (intptr_t)args[2];
struct kevent_qos_s* event_list = (struct kevent_qos_s*)args[3];
int nevents = (intptr_t)args[4];
void* data_out = args[5];
size_t* data_available = (size_t*)args[6];
unsigned int flags = (uintptr_t)args[7];
bool printed_something = false;
set_kevent_stored_list(event_list);
xtrace_log("%d, change_list = {", kq);
for (int i = 0; i < nchanges; ++i) {
if (i == 0) {
xtrace_log(" ");
} else {
xtrace_log(", ");
}
print_kevent_qos_structure(&change_list[i]);
}
xtrace_log("%s}, nchanges = %d, event_list = %p, nevents = %d, data_out = %p, data_available = %p (%ld), flags = ", nchanges > 0 ? " " : "", nchanges, event_list, nevents, data_out, data_available, data_available ? *data_available : 0);
for (size_t i = 0; i < sizeof(kevent_call_flags) / sizeof(*kevent_call_flags); ++i) {
if ((flags & kevent_call_flags[i].flag) == 0) {
continue;
}
if (!printed_something) {
printed_something = true;
} else {
xtrace_log("|");
}
xtrace_log("%s", kevent_call_flags[i].name);
}
if (!printed_something) {
xtrace_log("0");
}
};
static void print_timespec(const struct timespec* timespec) {
if (timespec) {
xtrace_log("(%ld s, %ld ns)", timespec->tv_sec, timespec->tv_nsec);
} else {
xtrace_log("NULL");
}
};

2
src/xtrace/bsd_trace.h
View File

@ -2,7 +2,7 @@
extern "C" {
#endif
extern int xtrace_format_string_literal(char* buf, const char* str);
extern void xtrace_print_string_literal(const char* str);
#ifdef __cplusplus
}

2
src/xtrace/lock.c
View File

@ -10,7 +10,7 @@
#endif
#if XTRACE_LOCK_DEBUG
#define xtrace_lock_debug_internal(x, ...) xtrace_printf(x "\n", ## __VA_ARGS__)
#define xtrace_lock_debug_internal(x, ...) xtrace_log(x "\n", ## __VA_ARGS__)
#undef XTRACE_INLINE
#define XTRACE_INLINE
#else

157
src/xtrace/mach_trace.cpp
View File

@ -13,29 +13,29 @@
#include "mig_trace.h"
#include "tls.h"
DEFINE_XTRACE_TLS_VAR(int, mach_call_nr);
DEFINE_XTRACE_TLS_VAR(void*, argument_ptr);
DEFINE_XTRACE_TLS_VAR(mach_port_name_t, request_port);
DEFINE_XTRACE_TLS_VAR(int, mach_call_nr, -1);
DEFINE_XTRACE_TLS_VAR(void*, argument_ptr, NULL);
DEFINE_XTRACE_TLS_VAR(mach_port_name_t, request_port, MACH_PORT_NULL);
static void print_kern_return(char* buf, int nr, uintptr_t rv);
static void print_port_return(char* buf, int nr, uintptr_t rv);
static void print_int_return(char* buf, int nr, uintptr_t rv);
static void print_empty(char* buf, int nr, void* args[]);
static void print_port_ptr_return(char* buf, int nr, uintptr_t rv);
static void print_kern_return(int nr, uintptr_t rv);
static void print_port_return(int nr, uintptr_t rv);
static void print_int_return(int nr, uintptr_t rv);
static void print_empty(int nr, void* args[]);
static void print_port_ptr_return(int nr, uintptr_t rv);
static void print_mach_msg_args(char* buf, int nr, void* args[]);
static void print_mach_port_insert_right_args(char* buf, int nr, void* args[]);
static void print_mach_msg_args(int nr, void* args[]);
static void print_mach_port_insert_right_args(int nr, void* args[]);
static void print_mach_port_member_args(char* buf, int nr, void* args[]);
static void print_mach_port_member_args(int nr, void* args[]);
static void print_mach_timebase_info_args(char* buf, int nr, void* args[]);
static void print_mach_timebase_info_res(char* buf, int nr, uintptr_t rv);
static void print_mach_timebase_info_args(int nr, void* args[]);
static void print_mach_timebase_info_res(int nr, uintptr_t rv);
static void print_mach_port_allocate_args(char* buf, int nr, void* args[]);
static void print_task_for_pid_args(char* buf, int nr, void* args[]);
static void print_mach_port_allocate_args(int nr, void* args[]);
static void print_task_for_pid_args(int nr, void* args[]);
static void print_pid_for_task_args(char* buf, int nr, void* args[]);
static void print_pid_for_task_res(char* buf, int nr, uintptr_t rv);
static void print_pid_for_task_args(int nr, void* args[]);
static void print_pid_for_task_res(int nr, uintptr_t rv);
static void print_mach_msg_entry(void* args[]);
static void print_mach_msg_exit(void);
@ -47,7 +47,7 @@ static const struct calldef mach_defs[128] = {
[15] = { "_kernelrpc_mach_vm_map_trap", NULL, print_kern_return },
[16] = { "_kernelrpc_mach_port_allocate_trap", print_mach_port_allocate_args, print_port_ptr_return },
[17] = { "_kernelrpc_mach_port_destroy_trap", NULL, print_kern_return },
[18] = { "_kernelrpc_mach_port_deallocate_trap", [](char* buf, int nr, void* args[]) { __simple_sprintf(buf, "task %u, port name %u", (unsigned int) (unsigned long) args[0], (unsigned int) (unsigned long) args[1]); }, print_kern_return },
[18] = { "_kernelrpc_mach_port_deallocate_trap", [](int nr, void* args[]) { xtrace_log("task %u, port name %u", (unsigned int) (unsigned long) args[0], (unsigned int) (unsigned long) args[1]); }, print_kern_return },
[19] = { "_kernelrpc_mach_port_mod_refs_trap", NULL, print_kern_return },
[20] = { "_kernelrpc_mach_port_move_member_trap", print_mach_port_member_args, print_kern_return },
[21] = { "_kernelrpc_mach_port_insert_right_trap", print_mach_port_insert_right_args, print_kern_return },
@ -226,56 +226,55 @@ void darling_mach_syscall_exit_print(uintptr_t retval)
set_mach_call_nr(-1);
}
int xtrace_kern_return_to_str(char* buf, kern_return_t kr)
void xtrace_print_kern_return(kern_return_t kr)
{
if (kr >= MACH_RCV_IN_PROGRESS && kr <= MACH_RCV_INVALID_TRAILER)
return __simple_sprintf(buf, "%s", mach_rcv_errors[kr - MACH_RCV_IN_PROGRESS]);
xtrace_log("%s", mach_rcv_errors[kr - MACH_RCV_IN_PROGRESS]);
else if (kr >= MACH_SEND_IN_PROGRESS && kr <= MACH_SEND_INVALID_TRAILER)
return __simple_sprintf(buf, "%s", mach_send_errors[kr - MACH_SEND_IN_PROGRESS]);
xtrace_log("%s", mach_send_errors[kr - MACH_SEND_IN_PROGRESS]);
else if (kr >= KERN_SUCCESS && kr <= KERN_INSUFFICIENT_BUFFER_SIZE)
return __simple_sprintf(buf, "%s", kern_return_values[kr]);
xtrace_log("%s", kern_return_values[kr]);
else if (kr >= BOOTSTRAP_NOT_PRIVILEGED && kr <= BOOTSTRAP_NO_CHILDREN)
return __simple_sprintf(buf, "%s", bootstrap_errors[kr - BOOTSTRAP_NOT_PRIVILEGED]);
xtrace_log("%s", bootstrap_errors[kr - BOOTSTRAP_NOT_PRIVILEGED]);
else if (kr <= MIG_TYPE_ERROR && kr >= MIG_TRAILER_ERROR)
return __simple_sprintf(buf, "%s", mig_errors[MIG_TYPE_ERROR - kr]);
xtrace_log("%s", mig_errors[MIG_TYPE_ERROR - kr]);
else
return __simple_sprintf(buf, "(kern_return_t) %x", kr);
xtrace_log("(kern_return_t) %x", kr);
}
static void print_kern_return(char* buf, int nr, uintptr_t rv)
static void print_kern_return(int nr, uintptr_t rv)
{
xtrace_kern_return_to_str(buf, (kern_return_t) rv);
xtrace_print_kern_return((kern_return_t) rv);
}
static void print_port_return(char* buf, int nr, uintptr_t rv)
static void print_port_return(int nr, uintptr_t rv)
{
__simple_sprintf(buf, "port right %d", (unsigned int) (unsigned long) rv);
xtrace_log("port right %d", (unsigned int) (unsigned long) rv);
}
static void print_int_return(char* buf, int nr, uintptr_t rv)
{
__simple_sprintf(buf, "%d", (int) (long) rv);
xtrace_log("%d", (int) (long) rv);
}
static void print_empty(char* buf, int nr, void* args[])
static void print_empty(int nr, void* args[])
{
*buf = 0;
}
static void print_port_ptr_return(char* buf, int nr, uintptr_t rv)
static void print_port_ptr_return(int nr, uintptr_t rv)
{
if (rv != KERN_SUCCESS)
{
print_kern_return(buf, nr, rv);
print_kern_return(nr, rv);
set_argument_ptr(NULL);
return;
}
if (get_argument_ptr() == NULL)
{
*buf = 0;
return;
}
__simple_sprintf(buf, "port right %d", *(mach_port_name_t*)get_argument_ptr());
xtrace_log("port right %d", *(mach_port_name_t*)get_argument_ptr());
set_argument_ptr(NULL);
}
@ -289,7 +288,7 @@ static const char* const port_right_names[] = {
"MACH_PORT_RIGHT_NUMBER"
};
static void print_mach_port_allocate_args(char* buf, int nr, void* args[])
static void print_mach_port_allocate_args(int nr, void* args[])
{
mach_port_name_t target = (mach_port_name_t) (long) args[0];
mach_port_right_t right = (mach_port_right_t) (long) args[1];
@ -301,7 +300,7 @@ static void print_mach_port_allocate_args(char* buf, int nr, void* args[])
else
right_name = port_right_names[right];
__simple_sprintf(buf, "task %d, %s", target, right_name);
xtrace_log("task %d, %s", target, right_name);
}
static const char* const port_dispositions[] = {
@ -318,7 +317,7 @@ static const char* const port_dispositions[] = {
"MACH_MSG_TYPE_DISPOSE_SEND_ONCE"
};
static void print_mach_port_insert_right_args(char* buf, int nr, void* args[])
static void print_mach_port_insert_right_args(int nr, void* args[])
{
mach_port_name_t target = (mach_port_name_t) (long) args[0];
mach_port_name_t name = (mach_port_name_t) (long) args[1];
@ -331,75 +330,69 @@ static void print_mach_port_insert_right_args(char* buf, int nr, void* args[])
else
disp = port_dispositions[disposition - MACH_MSG_TYPE_PORT_NAME];
__simple_sprintf(buf, "task %d, new name %d, port right %d, %s", target, name, right, disp);
xtrace_log("task %d, new name %d, port right %d, %s", target, name, right, disp);
}
static void print_mach_port_member_args(char* buf, int nr, void* args[])
static void print_mach_port_member_args(int nr, void* args[])
{
mach_port_name_t target = (mach_port_name_t) (long) args[0];
mach_port_name_t name = (mach_port_name_t) (long) args[1];
mach_port_name_t pset = (mach_port_name_t) (long) args[2];
__simple_sprintf(buf, "task %d, port right %d, port set %d", target, name, pset);
xtrace_log("task %d, port right %d, port set %d", target, name, pset);
}
static void print_mach_timebase_info_args(char* buf, int nr, void* args[])
static void print_mach_timebase_info_args(int nr, void* args[])
{
set_argument_ptr(args[0]);
if (get_argument_ptr() == NULL)
__simple_sprintf(buf, "NULL");
else
*buf = 0;
xtrace_log("NULL");
}
static void print_mach_timebase_info_res(char* buf, int nr, uintptr_t rv)
static void print_mach_timebase_info_res(int nr, uintptr_t rv)
{
if (rv != KERN_SUCCESS)
{
print_kern_return(buf, nr, rv);
print_kern_return(nr, rv);
set_argument_ptr(NULL);
return;
}
if (get_argument_ptr() != NULL)
{
mach_timebase_info_t timebase = (mach_timebase_info_t)get_argument_ptr();
__simple_sprintf(buf, "numer = %d, denom = %d", timebase->numer, timebase->denom);
xtrace_log("numer = %d, denom = %d", timebase->numer, timebase->denom);
}
else
*buf = 0;
set_argument_ptr(NULL);
}
static void print_task_for_pid_args(char* buf, int nr, void* args[])
static void print_task_for_pid_args(int nr, void* args[])
{
mach_port_name_t target = (mach_port_name_t) (long) args[0];
int pid = (int) (long) args[1];
set_argument_ptr(args[2]);
__simple_sprintf(buf, "task %d, pid %d", target, pid);
xtrace_log("task %d, pid %d", target, pid);
}
static void print_pid_for_task_args(char* buf, int nr, void* args[])
static void print_pid_for_task_args(int nr, void* args[])
{
mach_port_name_t task = (mach_port_name_t) (long) args[0];
set_argument_ptr(args[1]);
__simple_sprintf(buf, "task %d", task);
xtrace_log("task %d", task);
}
static void print_pid_for_task_res(char* buf, int nr, uintptr_t rv)
static void print_pid_for_task_res(int nr, uintptr_t rv)
{
if (rv != KERN_SUCCESS)
{
print_kern_return(buf, nr, rv);
print_kern_return(nr, rv);
set_argument_ptr(NULL);
return;
}
if (get_argument_ptr() != NULL)
__simple_sprintf(buf, "pid %d", * (int*)get_argument_ptr());
else
*buf = 0;
xtrace_log("pid %d", * (int*)get_argument_ptr());
set_argument_ptr(NULL);
}
@ -427,23 +420,23 @@ const char* xtrace_msg_type_to_str(mach_msg_type_name_t type_name, int full)
static void print_mach_msg(const mach_msg_header_t* msg, mach_msg_size_t size)
{
xtrace_printf("{");
xtrace_log("{");
mach_msg_bits_t bits = msg->msgh_bits;
if (MACH_MSGH_BITS_HAS_REMOTE(bits))
xtrace_printf("remote = %s %u, ", xtrace_msg_type_to_str(MACH_MSGH_BITS_REMOTE(bits), 0), msg->msgh_remote_port);
xtrace_log("remote = %s %u, ", xtrace_msg_type_to_str(MACH_MSGH_BITS_REMOTE(bits), 0), msg->msgh_remote_port);
if (MACH_MSGH_BITS_HAS_LOCAL(bits))
xtrace_printf("local = %s %u, ", xtrace_msg_type_to_str(MACH_MSGH_BITS_LOCAL(bits), 0), msg->msgh_local_port);
xtrace_log("local = %s %u, ", xtrace_msg_type_to_str(MACH_MSGH_BITS_LOCAL(bits), 0), msg->msgh_local_port);
if (MACH_MSGH_BITS_HAS_VOUCHER(bits))
xtrace_printf("voucher = %s %u, ", xtrace_msg_type_to_str(MACH_MSGH_BITS_VOUCHER(bits), 0), msg->msgh_voucher_port);
xtrace_log("voucher = %s %u, ", xtrace_msg_type_to_str(MACH_MSGH_BITS_VOUCHER(bits), 0), msg->msgh_voucher_port);
if (MACH_MSGH_BITS_IS_COMPLEX(bits))
xtrace_printf("complex, ");
xtrace_log("complex, ");
xtrace_printf("id = %d}", msg->msgh_id);
xtrace_log("id = %d}", msg->msgh_id);
if (!MACH_MSGH_BITS_IS_COMPLEX(bits))
{
xtrace_printf(", %lu bytes of inline data\n", size - sizeof(mach_msg_header_t));
xtrace_log(", %lu bytes of inline data\n", size - sizeof(mach_msg_header_t));
return;
}
@ -456,31 +449,31 @@ static void print_mach_msg(const mach_msg_header_t* msg, mach_msg_size_t size)
if (type == MACH_MSG_PORT_DESCRIPTOR)
{
mach_msg_port_descriptor_t* port = (mach_msg_port_descriptor_t*) ptr;
xtrace_printf(", %s %u", xtrace_msg_type_to_str(port->disposition, 0), port->name);
xtrace_log(", %s %u", xtrace_msg_type_to_str(port->disposition, 0), port->name);
ptr = (mach_msg_descriptor_t*) (port + 1);
}
else if (type == MACH_MSG_OOL_DESCRIPTOR || type == MACH_MSG_OOL_VOLATILE_DESCRIPTOR)
{
mach_msg_ool_descriptor_t* ool = (mach_msg_ool_descriptor_t*) ptr;
xtrace_printf(", ool [%p; %u]", ool->address, ool->size);
xtrace_log(", ool [%p; %u]", ool->address, ool->size);
ptr = (mach_msg_descriptor_t*) (ool + 1);
}
else if (type == MACH_MSG_OOL_PORTS_DESCRIPTOR)
{
mach_msg_ool_ports_descriptor_t* ool_ports = (mach_msg_ool_ports_descriptor_t*) ptr;
xtrace_printf(", ool ports %s [%p; x%u]",
xtrace_log(", ool ports %s [%p; x%u]",
xtrace_msg_type_to_str(ool_ports->disposition, 0),
ool_ports->address, ool_ports->count);
ptr = (mach_msg_descriptor_t*) (ool_ports + 1);
}
else
{
xtrace_printf(", ???");
xtrace_log(", ???");
ptr++;
}
}
xtrace_printf(", %lu bytes of inline data\n", size - ((const char*) ptr - (const char*) msg));
xtrace_log(", %lu bytes of inline data\n", size - ((const char*) ptr - (const char*) msg));
}
static void print_mach_msg_entry(void* args[])
@ -492,12 +485,12 @@ static void print_mach_msg_entry(void* args[])
if (options & MACH_SEND_MSG)
{
set_request_port(message->msgh_remote_port);
xtrace_printf("\n");
xtrace_log("\n");
xtrace_start_line(8);
print_mach_msg(message, send_size);
xtrace_start_line(8);
xtrace_print_mig_message(message, get_request_port());
xtrace_printf("\n");
xtrace_log("\n");
}
if (options & MACH_RCV_MSG)
@ -515,7 +508,7 @@ static void print_mach_msg_entry(void* args[])
set_argument_ptr(args[0]);
break;
default:
xtrace_printf("Unexpected mach_call_nr");
xtrace_log("Unexpected mach_call_nr");
return;
}
}
@ -531,12 +524,12 @@ static void print_mach_msg_exit()
print_mach_msg(message, message->msgh_size);
xtrace_start_line(8);
xtrace_print_mig_message(message, get_request_port());
xtrace_printf("\n");
xtrace_log("\n");
set_argument_ptr(NULL);
set_request_port(MACH_PORT_NULL);
}
static void print_mach_msg_args(char* buf, int nr, void* args[])
static void print_mach_msg_args(int nr, void* args[])
{
mach_msg_header_t* msg = (mach_msg_header_t*) args[0];
mach_msg_option_t options = (mach_msg_option_t) (unsigned long) args[1];
@ -546,15 +539,15 @@ static void print_mach_msg_args(char* buf, int nr, void* args[])
mach_msg_timeout_t timeout = (mach_msg_timeout_t) (unsigned long) args[5];
mach_port_name_t notify = (mach_port_name_t) (unsigned long) args[6];
buf += __simple_sprintf(buf, "%p, ", msg);
xtrace_log("%p, ", msg);
int options_cnt = 0;
#define OPTION(OPT) if (options & OPT) \
{ \
if (options_cnt > 0) \
*buf++ = '|'; \
buf += __simple_sprintf(buf, #OPT); \
xtrace_log("|"); \
xtrace_log(#OPT); \
options_cnt++; \
}
@ -579,7 +572,7 @@ static void print_mach_msg_args(char* buf, int nr, void* args[])
#undef OPTION
if (options_cnt == 0)
buf += __simple_sprintf(buf, "MACH_MSG_OPTION_NONE");
xtrace_log("MACH_MSG_OPTION_NONE");
__simple_sprintf(buf, ", %d, %d, port %d, %d, port %d", send_size, rcv_size, rcv_name, timeout, notify);
xtrace_log(", %d, %d, port %d, %d, port %d", send_size, rcv_size, rcv_name, timeout, notify);
}

2
src/xtrace/mach_trace.h
View File

@ -3,7 +3,7 @@ extern "C" {
#endif
const char* xtrace_msg_type_to_str(mach_msg_type_name_t type_name, int full);
int xtrace_kern_return_to_str(char* buf, kern_return_t kr);
void xtrace_print_kern_return(kern_return_t kr);
#ifdef __cplusplus
}

2
src/xtrace/malloc.c
View File

@ -16,7 +16,7 @@
#endif
#if XTRACE_MALLOC_DEBUG
#define xtrace_malloc_debug(x, ...) xtrace_printf(x "\n", ## __VA_ARGS__)
#define xtrace_malloc_debug(x, ...) xtrace_log(x "\n", ## __VA_ARGS__)
#undef XTRACE_INLINE
#define XTRACE_INLINE
#else

58
src/xtrace/mig_trace.c
View File

@ -61,14 +61,14 @@ void xtrace_setup_mig_tracing(void)
void* dylib_handle = dlopen(path, RTLD_LOCAL);
if (dylib_handle == NULL)
{
xtrace_fprintf(fileno(stderr), "xtrace: failed to dlopen %s: %s\n", path, dlerror());
xtrace_error("xtrace: failed to dlopen %s: %s\n", path, dlerror());
subsystems[i] = NULL;
continue;
}
subsystems[i] = (struct xtrace_mig_subsystem*) dlsym(dylib_handle, "xtrace_mig_subsystem");
if (subsystems[i] == NULL)
{
xtrace_fprintf(fileno(stderr), "xtrace: failed to dlsym(%s, \"xtrace_mig_subsystem\"): %s\n", path, dlerror());
xtrace_error("xtrace: failed to dlsym(%s, \"xtrace_mig_subsystem\"): %s\n", path, dlerror());
// Leave NULL subsystem in place and continue.
}
}
@ -76,9 +76,9 @@ void xtrace_setup_mig_tracing(void)
closedir(xtrace_mig_dir);
}
DEFINE_XTRACE_TLS_VAR(bool, is_first_arg);
DEFINE_XTRACE_TLS_VAR(bool, is_first_arg, false);
#define BEFORE if (!get_is_first_arg()) xtrace_printf(", ")
#define BEFORE if (!get_is_first_arg()) xtrace_log(", ")
#define AFTER set_is_first_arg(false)
static void add_raw_arg(const char* format, ...)
@ -97,23 +97,21 @@ static void add_raw_arg(const char* format, ...)
static void add_num_arg(unsigned long long n)
{
BEFORE;
xtrace_printf("%llu", n);
xtrace_log("%llu", n);
AFTER;
}
static void add_ptr_arg(void* ptr)
{
BEFORE;
xtrace_printf("%p", ptr);
xtrace_log("%p", ptr);
AFTER;
}
static void add_string_arg(const char* s)
{
BEFORE;
char buf[1024];
xtrace_format_string_literal(buf, s);
xtrace_printf("%s", buf);
xtrace_print_string_literal(s);
AFTER;
}
@ -121,39 +119,37 @@ static void add_bytes_arg(const void* bytes, unsigned long cnt)
{
BEFORE;
const unsigned char* b = (const unsigned char*) bytes;
xtrace_printf("bytes ");
xtrace_log("bytes ");
for (int i = 0; i < cnt; i++)
xtrace_printf("%x", b[i]);
xtrace_log("%x", b[i]);
AFTER;
}
static void add_return_code_arg(kern_return_t code)
{
BEFORE;
char buf[100];
xtrace_kern_return_to_str(buf, code);
xtrace_printf("return %s", buf);
xtrace_print_kern_return(code);
AFTER;
}
static void add_port_arg(mach_port_name_t port_name, mach_msg_type_name_t disposition)
{
BEFORE;
xtrace_printf("%s %u", xtrace_msg_type_to_str(disposition, 0), port_name);
xtrace_log("%s %u", xtrace_msg_type_to_str(disposition, 0), port_name);
AFTER;
}
static void add_ool_mem_arg(const void* ptr, unsigned long size)
{
BEFORE;
xtrace_printf("mem [%p; %lu]", ptr, size);
xtrace_log("mem [%p; %lu]", ptr, size);
AFTER;
}
static void add_ool_ports_arg(const void* ptr, unsigned long cnt, mach_msg_type_name_t disposition)
{
BEFORE;
xtrace_printf("%s [%p; x%lu]", xtrace_msg_type_to_str(disposition, 0), ptr, cnt);
xtrace_log("%s [%p; x%lu]", xtrace_msg_type_to_str(disposition, 0), ptr, cnt);
AFTER;
}
@ -182,15 +178,15 @@ static void add_struct_arg(const void* ptr, unsigned long cnt, unsigned long ite
{
BEFORE;
unsigned char* p = (unsigned char*) ptr;
xtrace_printf("{");
xtrace_log("{");
for (unsigned long i = 0; i < cnt; i++)
{
if (i != 0)
xtrace_printf(", ");
xtrace_printf("%llu", read_integer((void*) p, item_size));
xtrace_log(", ");
xtrace_log("%llu", read_integer((void*) p, item_size));
p += item_size;
}
xtrace_printf("}");
xtrace_log("}");
AFTER;
}
@ -198,24 +194,22 @@ static void add_array_arg(const void* ptr, unsigned long cnt, unsigned long item
{
BEFORE;
unsigned char* p = (unsigned char*) ptr;
xtrace_printf("[");
xtrace_log("[");
for (unsigned long i = 0; i < cnt; i++)
{
if (i != 0)
xtrace_printf(", ");
xtrace_printf("%llu", read_integer((void*) p, item_size));
xtrace_log(", ");
xtrace_log("%llu", read_integer((void*) p, item_size));
p += item_size;
}
xtrace_printf("]");
xtrace_log("]");
AFTER;
}
static void set_return_code(kern_return_t code)
{
BEFORE;
char buf[100];
xtrace_kern_return_to_str(buf, code);
xtrace_printf("%s", buf);
xtrace_print_kern_return(code);
AFTER;
}
@ -343,11 +337,11 @@ void xtrace_print_mig_message(const mach_msg_header_t* message, mach_port_name_t
return;
if (!is_reply)
xtrace_printf("%s::%s(", s->name, r->name);
xtrace_log("%s::%s(", s->name, r->name);
else
{
xtrace_set_gray_color();
xtrace_printf("%s::%s() -> ", s->name, r->name);
xtrace_log("%s::%s() -> ", s->name, r->name);
xtrace_reset_color();
}
@ -355,7 +349,7 @@ void xtrace_print_mig_message(const mach_msg_header_t* message, mach_port_name_t
r->routine(message, is_reply, &callbacks);
if (!is_reply)
xtrace_printf(")");
xtrace_log(")");
else
xtrace_printf(" ");
xtrace_log(" ");
}

55
src/xtrace/posix_spawn_args.c
View File

@ -8,9 +8,11 @@
#include <spawn_private.h>
#include <darling/emulation/simple.h>
#include "bsd_trace.h"
extern int xtrace_format_string_literal(char* buf, const char* str);
extern int print_open_flags(char* buf, void* arg);
#include "xtracelib.h"
extern void print_open_flags(void* arg);
static struct {
unsigned short flag;
@ -33,12 +35,11 @@ static struct {
#undef POSIX_SPAWN_ATTR_ENTRY
};
int print_arg_posix_spawn_args(char* buf, void* arg) {
const char* initial_buf = buf;
void print_arg_posix_spawn_args(void* arg) {
const struct _posix_spawn_args_desc* args = (const struct _posix_spawn_args_desc*)(arg);
bool is_first = true;
buf += __simple_sprintf(buf, "{ attributes = ");
xtrace_log("{ attributes = ");
if (args && args->attrp) {
for (size_t i = 0; all_posix_spawn_attrs[i].name != NULL; i++) {
@ -46,75 +47,71 @@ int print_arg_posix_spawn_args(char* buf, void* arg) {
if (is_first) {
is_first = false;
} else {
*buf++ = '|';
xtrace_log("|");
}
buf += __simple_sprintf(buf, "%s", all_posix_spawn_attrs[i].name);
xtrace_log("%s", all_posix_spawn_attrs[i].name);
}
}
}
if (is_first) {
*buf++ = '0';
xtrace_log("0");
}
buf += __simple_sprintf(buf, ", file_actions = {");
xtrace_log(", file_actions = {");
if (args && args->file_actions) {
for (size_t i = 0; i < args->file_actions->psfa_act_count; ++i) {
const struct _psfa_action* action = &args->file_actions->psfa_act_acts[i];
if (i != 0) {
*buf++ = ',';
*buf++ = ' ';
xtrace_log(", ");
}
switch (action->psfaa_type) {
case PSFA_OPEN:
buf += __simple_sprintf(buf, "open(");
buf += xtrace_format_string_literal(buf, action->psfaa_openargs.psfao_path);
*buf++ = ',';
*buf++ = ' ';
buf += print_open_flags(buf, (void*)(intptr_t)(action->psfaa_openargs.psfao_oflag));
buf += __simple_sprintf(buf, ", 0%o) to %d", action->psfaa_openargs.psfao_mode, action->psfaa_filedes);
xtrace_log("open(");
xtrace_print_string_literal(action->psfaa_openargs.psfao_path);
xtrace_log(", ");
print_open_flags((void*)(intptr_t)(action->psfaa_openargs.psfao_oflag));
xtrace_log(", 0%o) to %d", action->psfaa_openargs.psfao_mode, action->psfaa_filedes);
break;
case PSFA_CLOSE:
buf += __simple_sprintf(buf, "close(%d)", action->psfaa_filedes);
xtrace_log("close(%d)", action->psfaa_filedes);
break;
case PSFA_DUP2:
buf += __simple_sprintf(buf, "dup2(%d, %d)", action->psfaa_filedes, action->psfaa_dup2args.psfad_newfiledes);
xtrace_log("dup2(%d, %d)", action->psfaa_filedes, action->psfaa_dup2args.psfad_newfiledes);
break;
case PSFA_INHERIT:
buf += __simple_sprintf(buf, "inherit(%d)", action->psfaa_filedes);
xtrace_log("inherit(%d)", action->psfaa_filedes);
break;
case PSFA_FILEPORT_DUP2:
// NOTE: if we see this in the output, that's an issue;
// we don't have this implemented right now
buf += __simple_sprintf(buf, "dup2_fileport(port right %d, %d)", action->psfaa_fileport, action->psfaa_dup2args.psfad_newfiledes);
xtrace_log("dup2_fileport(port right %d, %d)", action->psfaa_fileport, action->psfaa_dup2args.psfad_newfiledes);
break;
case PSFA_CHDIR:
buf += __simple_sprintf(buf, "chdir(");
buf += xtrace_format_string_literal(buf, action->psfaa_chdirargs.psfac_path);
*buf++ = ')';
xtrace_log("chdir(");
xtrace_print_string_literal(action->psfaa_chdirargs.psfac_path);
xtrace_log(")");
break;
case PSFA_FCHDIR:
buf += __simple_sprintf(buf, "fchdir(%d)", action->psfaa_filedes);
xtrace_log("fchdir(%d)", action->psfaa_filedes);
break;
default:
buf += __simple_sprintf(buf, "???");
xtrace_log("???");
break;
}
}
}
buf += __simple_sprintf(buf, "} }");
return buf - initial_buf;
xtrace_log("} }");
};

15
src/xtrace/tls.c
View File

@ -5,13 +5,14 @@
#include "lock.h"
#include <darling/emulation/simple.h>
#include <pthread/tsd_private.h>
#include "xtracelib.h"
#ifndef XTRACE_TLS_DEBUG
#define XTRACE_TLS_DEBUG 0
#endif
#if XTRACE_TLS_DEBUG
#define xtrace_tls_debug(x, ...) xtrace_printf(x "\n", ## __VA_ARGS__)
#define xtrace_tls_debug(x, ...) xtrace_log(x "\n", ## __VA_ARGS__)
#else
#define xtrace_tls_debug(x, ...)
#endif
@ -50,7 +51,7 @@ static void tls_table_destructor(void* _table) {
};
#endif
void* xtrace_tls(void* key, size_t size) {
void* xtrace_tls(void* key, size_t size, bool* created) {
xtrace_tls_debug("looking up tls variable for key %p", key);
tls_table_t table = _pthread_getspecific_direct(__PTK_XTRACE_TLS);
@ -62,7 +63,7 @@ void* xtrace_tls(void* key, size_t size) {
xtrace_tls_debug("table is NULL, creating now...");
table = xtrace_malloc(sizeof(struct tls_table));
if (table == NULL) {
_abort_with_payload_for_xtrace(0, 0, NULL, 0, "xtrace: failed TLS table memory allocation", 0);
xtrace_abort("xtrace: failed TLS table memory allocation");
}
table->size = 0;
_pthread_setspecific_direct(__PTK_XTRACE_TLS, table);
@ -72,6 +73,9 @@ void* xtrace_tls(void* key, size_t size) {
for (size_t i = 0; i < table->size; ++i) {
if (table->table[i][0] == key) {
xtrace_tls_debug("found entry in table for key %p with value %p", key, table->table[i][1]);
if (created) {
*created = false;
}
return table->table[i][1];
}
}
@ -82,8 +86,11 @@ void* xtrace_tls(void* key, size_t size) {
table->table[index][0] = key;
table->table[index][1] = xtrace_malloc(size);
if (table->table[index][1] == NULL) {
_abort_with_payload_for_xtrace(0, 0, NULL, 0, "xtrace: failed TLS variable memory allocation", 0);
xtrace_abort("xtrace: failed TLS variable memory allocation");
}
xtrace_tls_debug("new table entry created for key %p with value %p", key, table->table[index][1]);
if (created) {
*created = true;
}
return table->table[index][1];
};

29
src/xtrace/tls.h
View File

@ -1,27 +1,44 @@
#ifndef _XTRACE_TLS_H_
#define _XTRACE_TLS_H_
#include <stddef.h>
#include <stdbool.h>
#include <mach/port.h>
#include "base.h"
XTRACE_DECLARATIONS_BEGIN;
#define DEFINE_XTRACE_TLS_VAR(type, name) \
char name ## _key = '\0'; \
#define DEFINE_XTRACE_TLS_VAR(type, name, default_value) \
static char name ## _key = '\0'; \
XTRACE_INLINE \
type get_ ## name(void) { \
return *(type*)xtrace_tls(&(name ## _key), sizeof(type)); \
bool created = false; \
type* var = (type*)xtrace_tls(&(name ## _key), sizeof(type), &created); \
if (created) { \
*var = default_value; \
} \
return *var; \
}; \
XTRACE_INLINE \
void set_ ## name(type value) { \
*(type*)xtrace_tls(&(name ## _key), sizeof(type)) = value; \
bool created = false; \
type* var = (type*)xtrace_tls(&(name ## _key), sizeof(type), NULL); \
if (created) { \
*var = default_value; \
} \
*var = value; \
}; \
XTRACE_INLINE \
type* get_ptr_ ## name(void) { \
return (type*)xtrace_tls(&(name ## _key), sizeof(type)); \
bool created = false; \
type* var = (type*)xtrace_tls(&(name ## _key), sizeof(type), &created); \
if (created) { \
*var = default_value; \
} \
return var; \
};
void* xtrace_tls(void* key, size_t size);
void* xtrace_tls(void* key, size_t size, bool* created);
XTRACE_DECLARATIONS_END;

20
src/xtrace/xtrace
View File

@ -1,5 +1,25 @@
#!/bin/sh
if [ "$#" -eq 0 ]; then
cat <<-'EOF'
Usage: xtrace <command-to-trace> [arguments]...
Useful environment variables:
XTRACE_SPLIT_ENTRY_AND_EXIT - boolean - Used to print function entry (e.g. arguments) separately from function exit (e.g. return value). The normal format is "foo(arg1, arg2, etc) -> return_value". With this option, calls are formatted instead as "foo(arg1, arg2)" and then later (when they return) "foo() -> return_value".
XTRACE_NO_COLOR - boolean - By default, xtrace produces colored output using ANSI escape codes; this option disables that.
XTRACE_KPRINTF - boolean - xtrace normally prints to the standard console output. However, sometimes you would like to trace background processes, ones that don't have a console output. In that case, you can use XTRACE_KPRINTF to tell xtrace to print to the kernel console instead. All of xtrace's messages will be prefixed with `xtrace: `; that way, you can easily search for them in the kernel log.
XTRACE_LOG_FILE - string (path) - This option serves the same purpose as XTRACE_KPRINTF: to log messages for background processes. However, instead of logging to the kernel console, it instead logs to the file at the path specified by this variable. NOTE: this option may affect program behavior, as a descriptor must be kept in-use for the logfile. It may also fail to log (and therefore abort) if the process is using all of its descriptors. There is a chance that it will affect program behavior if another thread sees the descriptor or tries to open a new one that would exceed the limit of descriptors only when the logfile is open.
XTRACE_LOG_FILE_PER_THREAD - boolean - By default, xtrace outputs all of its messages into a single log stream (whether that's the standard console output, kernel console, or a log file). However, when this option is given and XTRACE_LOG_FILE is also specified, each thread will have a separate log file, each one named like "${XTRACE_LOG_FILE}.${THREAD_ID}". Note that without XTRACE_LOG_FILE, this option has no effect.
EOF
exit 0
fi
export DYLD_INSERT_LIBRARIES="/usr/lib/darling/libxtrace.dylib"
exec "$@"

195
src/xtrace/xtracelib.c
View File

@ -8,6 +8,12 @@
#include "xtracelib.h"
#include "mig_trace.h"
#include "tls.h"
#include "lock.h"
#include <limits.h>
#include <darling/emulation/ext/for-xtrace.h>
#include <fcntl.h>
#include <signal.h>
// Defined in assembly
extern void darling_mach_syscall_entry_trampoline(void);
@ -39,6 +45,10 @@ static void xtrace_setup_options(void);
static int xtrace_ignore = 1;
// whether to use a sigaltstack guard page below the stack
// (this should probably be left on)
#define SIGALTSTACK_GUARD 1
__attribute__((constructor))
void xtrace_setup()
{
@ -47,6 +57,35 @@ void xtrace_setup()
xtrace_setup_mach();
xtrace_setup_bsd();
// override the default sigaltstack used by libsystem_kernel for the main thread
// (we need more than the default 8KiB; testing has shown that 16KiB seems to be enough)
struct bsd_stack custom_altstack = {
.ss_size = 16 * 1024,
.ss_flags = 0,
};
#if SIGALTSTACK_GUARD
custom_altstack.ss_sp = (void*)mmap(NULL, custom_altstack.ss_size + 4096, PROT_READ | PROT_WRITE, MAP_ANON | MAP_PRIVATE, -1, 0);
if (custom_altstack.ss_sp == MAP_FAILED) {
xtrace_abort("xtrace: failed to allocate larger sigstack for main thread");
}
mprotect(custom_altstack.ss_sp, 4096, PROT_NONE);
custom_altstack.ss_sp = (char*)custom_altstack.ss_sp + 4096;
#else
custom_altstack.ss_sp = (void*)mmap(NULL, custom_altstack.ss_size, PROT_READ | PROT_WRITE, MAP_ANON | MAP_PRIVATE, -1, 0);
if (custom_altstack.ss_sp == MAP_FAILED) {
xtrace_abort("xtrace: failed to allocate larger sigstack for main thread");
}
#endif
if (_sigaltstack_for_xtrace(&custom_altstack, NULL) < 0) {
xtrace_abort("failed to override sigaltstack");
}
// and set the size to allocate for future threads
_sigaltstack_set_default_size_for_xtrace(custom_altstack.ss_size);
xtrace_ignore = 0;
}
@ -54,14 +93,34 @@ static int xtrace_split_entry_and_exit = 0;
int xtrace_no_color = 0;
int xtrace_kprintf = 0;
static int xtrace_use_logfile = 0;
static int xtrace_use_per_thread_logfile = 0;
static char xtrace_logfile_base[PATH_MAX] = {0};
static xtrace_once_t xtrace_common_logfile_once = XTRACE_ONCE_INITIALIZER;
int xtrace_common_logfile = -1;
DEFINE_XTRACE_TLS_VAR(int, xtrace_per_thread_logfile, -1);
static void xtrace_setup_options(void)
{
const char* xtrace_log_file = getenv("XTRACE_LOG_FILE");
if (getenv("XTRACE_SPLIT_ENTRY_AND_EXIT") != NULL)
xtrace_split_entry_and_exit = 1;
if (getenv("XTRACE_NO_COLOR") != NULL)
xtrace_no_color = 1;
if (getenv("XTRACE_KPRINTF") != NULL)
xtrace_kprintf = 1;
if (getenv("XTRACE_LOG_FILE_PER_THREAD") != NULL)
xtrace_use_per_thread_logfile = 1;
if (xtrace_log_file != NULL) {
xtrace_use_logfile = 1;
strlcpy(xtrace_logfile_base, xtrace_log_file, sizeof(xtrace_logfile_base));
}
}
@ -121,7 +180,7 @@ void xtrace_set_gray_color(void)
if (xtrace_no_color)
return;
xtrace_printf("\033[37m");
xtrace_log("\033[37m");
}
void xtrace_reset_color(void)
@ -129,16 +188,16 @@ void xtrace_reset_color(void)
if (xtrace_no_color)
return;
xtrace_printf("\033[0m");
xtrace_log("\033[0m");
}
void xtrace_start_line(int indent)
{
xtrace_set_gray_color();
xtrace_printf("[%d]", sys_thread_selfid());
xtrace_log("[%d]", sys_thread_selfid());
for (int i = 0; i < indent + 1; i++)
xtrace_printf(" ");
xtrace_log(" ");
xtrace_reset_color();
}
@ -151,9 +210,9 @@ static void print_call(const struct calldef* defs, const char* type, int nr, int
xtrace_set_gray_color();
if (defs[nr].name != NULL)
xtrace_printf("%s", defs[nr].name);
xtrace_log("%s", defs[nr].name);
else
xtrace_printf("%s %d", type, nr);
xtrace_log("%s %d", type, nr);
// Leaves gray color on!
}
@ -170,7 +229,7 @@ struct nested_call_struct {
int nrs[64];
};
DEFINE_XTRACE_TLS_VAR(struct nested_call_struct, nested_call);
DEFINE_XTRACE_TLS_VAR(struct nested_call_struct, nested_call, (struct nested_call_struct) {0});
void handle_generic_entry(const struct calldef* defs, const char* type, int nr, void* args[])
{
@ -180,7 +239,7 @@ void handle_generic_entry(const struct calldef* defs, const char* type, int nr,
if (get_ptr_nested_call()->previous_level < get_ptr_nested_call()->current_level && !xtrace_split_entry_and_exit)
{
// We are after an earlier entry without an exit.
xtrace_printf("\n");
xtrace_log("\n");
}
int indent = 4 * get_ptr_nested_call()->current_level;
@ -188,20 +247,17 @@ void handle_generic_entry(const struct calldef* defs, const char* type, int nr,
print_call(defs, type, nr, indent, 0);
if (defs[nr].name != NULL)
if (defs[nr].name != NULL && defs[nr].print_args != NULL)
{
char args_buf[4096];
if (defs[nr].print_args != NULL)
defs[nr].print_args(args_buf, nr, args);
else
strcpy(args_buf, "...");
xtrace_printf("(%s)", args_buf);
xtrace_log("(");
defs[nr].print_args(nr, args);
xtrace_log(")");
}
else
xtrace_printf("(...)");
xtrace_log("(...)");
if (xtrace_split_entry_and_exit)
xtrace_printf("\n");
xtrace_log("\n");
get_ptr_nested_call()->previous_level = get_ptr_nested_call()->current_level++;
}
@ -224,23 +280,108 @@ void handle_generic_exit(const struct calldef* defs, const char* type, uintptr_t
{
int indent = 4 * get_ptr_nested_call()->current_level;
print_call(defs, type, nr, indent, 1);
xtrace_printf("()");
xtrace_log("()");
}
xtrace_set_gray_color();
xtrace_printf(" -> ");
xtrace_log(" -> ");
xtrace_reset_color();
if (defs[nr].name != NULL)
if (defs[nr].name != NULL && defs[nr].print_retval != NULL)
{
char args_buf[4096];
if (defs[nr].print_retval != NULL)
defs[nr].print_retval(args_buf, nr, retval);
else
__simple_sprintf(args_buf, "0x%lx\n", retval);
xtrace_printf("%s\n", args_buf);
defs[nr].print_retval(nr, retval);
xtrace_log("\n");
}
else
xtrace_printf("0x%lx\n", retval);
xtrace_log("0x%lx\n", retval);
}
void xtrace_log(const char* format, ...) {
va_list args;
va_start(args, format);
xtrace_log_v(format, args);
va_end(args);
};
// TODO: we should add guarded FD support so that we can make FDs like these logfile descriptors guarded.
// it would also be very useful to guard the special LKM descriptor.
static void xtrace_common_logfile_init(void) {
xtrace_common_logfile = _open_for_xtrace(xtrace_logfile_base, O_WRONLY | O_APPEND | O_CLOEXEC | O_CREAT, S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH);
};
static void ensure_logfile(void) {
bool created = false;
int fd = -1;
if (!xtrace_use_logfile) {
xtrace_abort("xtrace: tried to use logfile when not enabled");
}
if (get_xtrace_per_thread_logfile() != -1) {
return;
}
if (xtrace_use_per_thread_logfile) {
char filename[sizeof(xtrace_logfile_base)];
char append[32] = {0};
strlcpy(filename, xtrace_logfile_base, PATH_MAX);
__simple_snprintf(append, sizeof(append), ".%d", sys_thread_selfid());
strlcat(filename, append, PATH_MAX);
fd = _open_for_xtrace(filename, O_WRONLY | O_APPEND | O_CLOEXEC | O_CREAT, S_IRUSR | S_IWUSR | S_IRGRP | S_IROTH);
} else {
xtrace_once(&xtrace_common_logfile_once, xtrace_common_logfile_init);
fd = xtrace_common_logfile;
}
if (fd < 0) {
xtrace_abort("xtrace: failed to open logfile");
}
set_xtrace_per_thread_logfile(fd);
};
void xtrace_log_v(const char* format, va_list args) {
if (xtrace_kprintf) {
char real_format[512] = "xtrace: ";
strlcpy(&real_format[0] + (sizeof("xtrace: ") - 1), format, sizeof(real_format) - (sizeof("xtrace: ") - 1));
__simple_vkprintf(real_format, args);
} else if (xtrace_use_logfile) {
char output[512];
ensure_logfile();
__simple_vsnprintf(output, sizeof(output), format, args);
__write_for_xtrace(get_xtrace_per_thread_logfile(), output, __simple_strlen(output));
} else {
__simple_vprintf(format, args);
}
};
void xtrace_error(const char* format, ...) {
va_list args;
va_start(args, format);
xtrace_error_v(format, args);
va_end(args);
};
void xtrace_error_v(const char* format, va_list args) {
if (xtrace_kprintf) {
char real_format[512] = "xtrace: ";
strlcpy(real_format + (sizeof("xtrace: ") - 1), format, sizeof(real_format) - (sizeof("xtrace: ") - 1));
__simple_vkprintf(real_format, args);
} else if (xtrace_use_logfile) {
char output[512];
ensure_logfile();
__simple_vsnprintf(output, sizeof(output), format, args);
__write_for_xtrace(get_xtrace_per_thread_logfile(), output, __simple_strlen(output));
} else {
__simple_vfprintf(STDERR_FILENO, format, args);
}
};
void xtrace_abort(const char* message) {
_abort_with_payload_for_xtrace(0, 0, NULL, 0, message, 0);
__builtin_unreachable();
};

26
src/xtrace/xtracelib.h
View File

@ -6,8 +6,8 @@
struct calldef
{
const char* name;
void (*print_args)(char*, int nr, void* args[]);
void (*print_retval)(char*, int nr, uintptr_t rv);
void (*print_args)(int nr, void* args[]);
void (*print_retval)(int nr, uintptr_t rv);
};
#ifdef __cplusplus
@ -18,29 +18,17 @@ void handle_generic_entry(const struct calldef* defs, const char* type, int nr,
void handle_generic_exit(const struct calldef* defs, const char* type, uintptr_t retval, int force_split);
extern int xtrace_no_color;
extern int xtrace_kprintf;
void xtrace_set_gray_color(void);
void xtrace_reset_color(void);
void xtrace_start_line(int indent);
// the kprintf output is prefixed with "xtrace: " for easy grepping on dmesg
void xtrace_log(const char* format, ...) __attribute__((format(printf, 1, 2)));
void xtrace_log_v(const char* format, va_list args) __attribute__((format(printf, 1, 0)));
void xtrace_error(const char* format, ...) __attribute__((format(printf, 1, 2)));
void xtrace_error_v(const char* format, va_list args) __attribute__((format(printf, 1, 0)));
#define xtrace_printf(format, ...) ({ \
if (xtrace_kprintf) { \
__simple_kprintf("xtrace: " format, ##__VA_ARGS__); \
} else { \
__simple_printf(format, ##__VA_ARGS__); \
} \
})
#define xtrace_fprintf(fd, format, ...) ({ \
if (xtrace_kprintf) { \
__simple_kprintf("xtrace: " format, ##__VA_ARGS__); \
} else { \
__simple_fprintf(fd, format, ##__VA_ARGS__); \
} \
})
void xtrace_abort(const char* message) __attribute__((noreturn));
#ifdef __cplusplus
}