|
| 1 | +//===- ptreetime_interpose.c ----------------------------------------------===// |
| 2 | +// |
| 3 | +// This source file is part of the Swift.org open source project |
| 4 | +// |
| 5 | +// Copyright (c) 2017 Apple Inc. and the Swift project authors |
| 6 | +// Licensed under Apache License v2.0 with Runtime Library Exception |
| 7 | +// |
| 8 | +// See http://swift.org/LICENSE.txt for license information |
| 9 | +// See http://swift.org/CONTRIBUTORS.txt for the list of Swift project authors |
| 10 | +// |
| 11 | +//===----------------------------------------------------------------------===// |
| 12 | + |
| 13 | +/* This file defines a simple interposition library which is intended for use |
| 14 | + * with `ptreetime`. |
| 15 | + * |
| 16 | + * The library is not intended to be used directly, rather it is automatically |
| 17 | + * inserted using ``DYLD_INSERT_LIBRARIES``. |
| 18 | + * |
| 19 | + * The library itself interpositions on ``_exit``, ``execve``, and |
| 20 | + * ``posix_spawn``. The library also inserts a static constructor which will be |
| 21 | + * run at load time. Due to the way ``dyld`` executes static constructors, the |
| 22 | + * startup constructor will be run after all of ``libSystem``'s initializers |
| 23 | + * (because the library itself needs to load libSystem), but will always be run |
| 24 | + * before any of the primary application constructors. |
| 25 | + * |
| 26 | + * The library logs various events to an output file specified by the |
| 27 | + * ``PTREETIME_LOG_PATH`` environment variable. The events are written with |
| 28 | + * timestamps defined by gettimeofday(), which allows the events to be properly |
| 29 | + * ordered with respect to dtrace events. |
| 30 | + */ |
| 31 | + |
| 32 | +#include <errno.h> |
| 33 | +#include <fcntl.h> |
| 34 | +#include <mach/mach_time.h> |
| 35 | +#include <spawn.h> |
| 36 | +#include <stdarg.h> |
| 37 | +#include <stdio.h> |
| 38 | +#include <stdlib.h> |
| 39 | +#include <string.h> |
| 40 | +#include <sys/resource.h> |
| 41 | +#include <sys/time.h> |
| 42 | +#include <sys/uio.h> |
| 43 | +#include <unistd.h> |
| 44 | + |
| 45 | +#define DYLD_INTERPOSE(_src,_dst) \ |
| 46 | + __attribute__((used)) static struct { \ |
| 47 | + const void* src; \ |
| 48 | + const void* dst; \ |
| 49 | + } _interpose_##_dst __attribute__ ((section ("__DATA,__interpose"))) = { \ |
| 50 | + (const void*)(uintptr_t)&_src, \ |
| 51 | + (const void*)(uintptr_t)&_dst \ |
| 52 | + }; |
| 53 | + |
| 54 | +const char *ptreetime_log_path = 0; |
| 55 | +static int ptreetime_log_file = -1; |
| 56 | + |
| 57 | +static void error(const char *fmt, ...) { |
| 58 | + /* Get the current time of day. */ |
| 59 | + struct timeval t; |
| 60 | + gettimeofday(&t, NULL); |
| 61 | + |
| 62 | + char buffer[1024]; |
| 63 | + va_list ap; |
| 64 | + |
| 65 | + va_start(ap, fmt); |
| 66 | + vsnprintf(buffer, sizeof(buffer), fmt, ap); |
| 67 | + va_end(ap); |
| 68 | + |
| 69 | + fprintf(stderr, |
| 70 | + "PTREETIME { \"ts\" : %lld, \"error\" : '%s', \"errno\" : %d }\n", |
| 71 | + (uint64_t) t.tv_sec * 1000000 + t.tv_usec, buffer, errno); |
| 72 | +} |
| 73 | + |
| 74 | +static void ptreetime_write_buffer(const char *buffer, int size, |
| 75 | + int allow_reopen) { |
| 76 | + /* If the log file hasn't been opened, open it. */ |
| 77 | + if (ptreetime_log_file == -1) { |
| 78 | + /* Only log if the PTREETIME_LOG_PATH environment variable is set. */ |
| 79 | + ptreetime_log_path = getenv("PTREETIME_LOG_PATH"); |
| 80 | + if (!ptreetime_log_path) { |
| 81 | + errno = 0; |
| 82 | + error("no PTREETIME_LOG_PATH variable set"); |
| 83 | + return; |
| 84 | + } |
| 85 | + |
| 86 | + ptreetime_log_file = open(ptreetime_log_path, O_WRONLY|O_CREAT|O_APPEND, |
| 87 | + 0664); |
| 88 | + if (ptreetime_log_file == -1) { |
| 89 | + error("unable to open log file '%s' (%s)", ptreetime_log_path, |
| 90 | + strerror(errno)); |
| 91 | + return; |
| 92 | + } |
| 93 | + } |
| 94 | + |
| 95 | + struct iovec iov = { (void*) buffer, size }; |
| 96 | + if (writev(ptreetime_log_file, &iov, 1) == -1) { |
| 97 | + /* If the write failed with a bad file descriptor, retry with a reopen, in |
| 98 | + case someone decided to close our output file descriptor. */ |
| 99 | + if (allow_reopen && errno == EBADF) { |
| 100 | + ptreetime_log_file = -1; |
| 101 | + ptreetime_write_buffer(buffer, size, /*allow_reopen=*/0); |
| 102 | + return; |
| 103 | + } |
| 104 | + |
| 105 | + /* Otherwise, report the error. */ |
| 106 | + error("unable to write to log file '%s' (%s)", ptreetime_log_path, |
| 107 | + strerror(errno)); |
| 108 | + } |
| 109 | +} |
| 110 | + |
| 111 | +static void write_log_entry(const char *event) { |
| 112 | + /* Get the program's resource usage. */ |
| 113 | + struct rusage usage; |
| 114 | + getrusage(RUSAGE_SELF, &usage); |
| 115 | + |
| 116 | + /* Get the current time of day. */ |
| 117 | + struct timeval t; |
| 118 | + gettimeofday(&t, NULL); |
| 119 | + |
| 120 | + /* Write the log event. */ |
| 121 | + char buffer[1024]; |
| 122 | + int size = snprintf(buffer, sizeof(buffer), |
| 123 | + ("PTREETIME { \"ts\" : %lld, \"evt\" : \"%-14s\", " |
| 124 | + "\"pid\" : %d, \"parent\" : %d, " |
| 125 | + "\"utime\" : [%ld, %d], \"stime\" : [%ld, %d] }\n"), |
| 126 | + (uint64_t) t.tv_sec * 1000000 + t.tv_usec, event, |
| 127 | + getpid(), getppid(), |
| 128 | + usage.ru_utime.tv_sec, usage.ru_utime.tv_usec, |
| 129 | + usage.ru_stime.tv_sec, usage.ru_stime.tv_usec); |
| 130 | + |
| 131 | + /* Use writev to get an atomic write. */ |
| 132 | + ptreetime_write_buffer(buffer, size, /*allow_reopen=*/1); |
| 133 | +} |
| 134 | + |
| 135 | +static int clean_arg(const char *arg, char *dst, unsigned dst_size) { |
| 136 | + unsigned pos = 0; |
| 137 | + |
| 138 | + for (unsigned i = 0; ; ++i) { |
| 139 | + char c = arg[i]; |
| 140 | + |
| 141 | + /* If we have an unclean character, escape it. */ |
| 142 | + if (arg[i] == '\\' || arg[i] == '"') { |
| 143 | + if (pos == dst_size) |
| 144 | + return 0; |
| 145 | + dst[pos++] = '\\'; |
| 146 | + } |
| 147 | + |
| 148 | + if (pos == dst_size) |
| 149 | + return 0; |
| 150 | + dst[pos++] = c; |
| 151 | + |
| 152 | + if (c == '\0') |
| 153 | + return 1; |
| 154 | + } |
| 155 | +} |
| 156 | + |
| 157 | +static void write_create_log_entry(const char *event, char *const argv[]) { |
| 158 | + /* Get the program's resource usage. */ |
| 159 | + struct rusage usage; |
| 160 | + getrusage(RUSAGE_SELF, &usage); |
| 161 | + |
| 162 | + /* Get the current time of day. */ |
| 163 | + struct timeval t; |
| 164 | + gettimeofday(&t, NULL); |
| 165 | + |
| 166 | + /* Write the log event start. */ |
| 167 | + char buffer[4096]; |
| 168 | + int size = snprintf(buffer, sizeof(buffer), |
| 169 | + ("PTREETIME { \"ts\" : %lld, \"evt\" : \"%-14s\", " |
| 170 | + "\"pid\" : %d, \"parent\" : %d, " |
| 171 | + "\"utime\" : [%ld, %d], \"stime\" : [%ld, %d], " |
| 172 | + "\"args\" : ["), |
| 173 | + (uint64_t) t.tv_sec * 1000000 + t.tv_usec, event, |
| 174 | + getpid(), getppid(), |
| 175 | + usage.ru_utime.tv_sec, usage.ru_utime.tv_usec, |
| 176 | + usage.ru_stime.tv_sec, usage.ru_stime.tv_usec); |
| 177 | + |
| 178 | + if (size >= sizeof(buffer)) |
| 179 | + abort(); |
| 180 | + |
| 181 | + /* Write the arguments (or as many will fit). */ |
| 182 | + unsigned safe_space = strlen("\"...\"") + strlen("] }\n"); |
| 183 | + for (unsigned i = 0; argv[i]; ++i) { |
| 184 | + /* Clean the argument, to escape any characters for JSON. */ |
| 185 | + char arg_buffer[1024]; |
| 186 | + if (!clean_arg(argv[i], arg_buffer, sizeof(arg_buffer))) { |
| 187 | + size += snprintf(&buffer[size], sizeof(buffer) - size, "\"...\""); |
| 188 | + break; |
| 189 | + } |
| 190 | + |
| 191 | + /* Write the argument into the buffer, if we have enough room. */ |
| 192 | + int bytes = snprintf(&buffer[size], sizeof(buffer) - size - safe_space, |
| 193 | + "\"%s\"%s", arg_buffer, argv[i+1] ? ", " : ""); |
| 194 | + |
| 195 | + /* If we are out of space, break. */ |
| 196 | + if (bytes >= sizeof(buffer) - size - safe_space) { |
| 197 | + size += snprintf(&buffer[size], sizeof(buffer) - size, "\"...\""); |
| 198 | + break; |
| 199 | + } |
| 200 | + |
| 201 | + size += bytes; |
| 202 | + } |
| 203 | + |
| 204 | + /* Write the log event end. */ |
| 205 | + size += snprintf(&buffer[size], sizeof(buffer) - size, "] }\n"); |
| 206 | + |
| 207 | + /* Write the event. */ |
| 208 | + ptreetime_write_buffer(buffer, size, /*allow_reopen=*/1); |
| 209 | +} |
| 210 | + |
| 211 | +void interposed_exit(int status) { |
| 212 | + write_log_entry("user exit"); |
| 213 | + |
| 214 | + return _exit(status); |
| 215 | +} |
| 216 | +DYLD_INTERPOSE(interposed_exit, _exit); |
| 217 | + |
| 218 | +static void interposed_startup() \ |
| 219 | + __attribute__((used)) __attribute__((constructor)); |
| 220 | +static void interposed_startup() { |
| 221 | + write_log_entry("user startup"); |
| 222 | +} |
| 223 | + |
| 224 | +int interposed_execve(const char *path, char *const argv[], |
| 225 | + char *const envp[]) { |
| 226 | + /* On Darwin, execvp will call execve in a loop. Only write the log entry if |
| 227 | + we see we have execute permission on the file. */ |
| 228 | + if (access(path, X_OK) == 0) |
| 229 | + write_create_log_entry("user exec", argv); |
| 230 | + |
| 231 | + return execve(path, argv, envp); |
| 232 | +} |
| 233 | +DYLD_INTERPOSE(interposed_execve, execve); |
| 234 | + |
| 235 | +int interposed_posix_spawn(pid_t *restrict pid, const char *restrict path, |
| 236 | + const posix_spawn_file_actions_t *file_actions, |
| 237 | + const posix_spawnattr_t *restrict attrp, |
| 238 | + char *const argv[], |
| 239 | + char *const envp[restrict]) { |
| 240 | + write_create_log_entry("user spawn", argv); |
| 241 | + return posix_spawn(pid, path, file_actions, attrp, argv, envp); |
| 242 | +} |
| 243 | +DYLD_INTERPOSE(interposed_posix_spawn, posix_spawn); |
| 244 | + |
0 commit comments