os/trace.c

   1 /* Copyright (c) 2012 Apple Inc. All rights reserved.
   2  *
   3  * @APPLE_LICENSE_HEADER_START@
   4  *
   5  * This file contains Original Code and/or Modifications of Original Code
   6  * as defined in and that are subject to the Apple Public Source License
   7  * Version 2.0 (the 'License'). You may not use this file except in
   8  * compliance with the License. Please obtain a copy of the License at
   9  * http://www.opensource.apple.com/apsl/ and read it before using this
  10  * file.
  11  *
  12  * The Original Code and all software distributed under the License are
  13  * distributed on an 'AS IS' basis, WITHOUT WARRANTY OF ANY KIND, EITHER
  14  * EXPRESS OR IMPLIED, AND APPLE HEREBY DISCLAIMS ALL SUCH WARRANTIES,
  15  * INCLUDING WITHOUT LIMITATION, ANY WARRANTIES OF MERCHANTABILITY,
  16  * FITNESS FOR A PARTICULAR PURPOSE, QUIET ENJOYMENT OR NON-INFRINGEMENT.
  17  * Please see the License for the specific language governing rights and
  18  * limitations under the License.
  19  *
  20  * @APPLE_LICENSE_HEADER_END@
  21  */
  22
  23 #include <dlfcn.h>
  24 #include <errno.h>
  25 #include <fcntl.h>
  26 #include <limits.h>
  27 #include <mach/mach_time.h>
  28 #include <os/alloc_once_private.h>
  29 #include <os/trace.h>
  30 #include <_simple.h>
  31 #include <stdarg.h>
  32 #include <stdbool.h>
  33 #include <stdio.h>
  34 #include <stdlib.h>
  35 #include <string.h>
  36 #include <syslog.h>
  37 #include <sys/time.h>
  38 #include <unistd.h>
  39
  40 // Move this to trace.h when it's removed from assumes.h
  41 typedef bool (*os_redirect_t)(const char *);
  42
  43 struct os_trace_globals_s {
  44         uint64_t start;
  45         os_redirect_t redirect;
  46         int logfd;
  47         bool prepend_timestamp : 1;
  48         bool errors_only : 1;
  49 };
  50
  51 // If user picked a filename, use it and only it.
  52 // Otherwise, first try /var/tmp, then $TMPDIR, then give up.
  53 static inline
  54 int
  55 _os_trace_open_file(const char *suggestion)
  56 {
  57         if (suggestion) {
  58                 return open(suggestion, O_WRONLY | O_APPEND | O_CREAT | O_NOFOLLOW |
  59                                         O_EXCL | O_CLOEXEC, 0644);
  60         }
  61
  62         int fd;
  63         char filename[PATH_MAX];
  64         char path[PATH_MAX];
  65
  66         snprintf(filename, sizeof(filename), "os_trace.%s.%d.log", getprogname(),
  67                          getpid());
  68
  69         strlcpy(path, "/var/tmp/", sizeof(path));
  70         if (access(path, W_OK) == 0) {
  71                 strlcat(path, filename, sizeof(path));
  72                 fd = open(path, O_WRONLY | O_APPEND | O_CREAT | O_NOFOLLOW | O_EXCL |
  73                                   O_CLOEXEC, 0644);
  74                 if (fd >= 0) {
  75                         return fd;
  76                 }
  77         }
  78
  79         const char *tmpdir = getenv("TMPDIR");
  80         if (tmpdir) {
  81                 strlcpy(path, tmpdir, sizeof(path));
  82                 if (access(path, W_OK) == 0) {
  83                         strlcat(path, filename, sizeof(path));
  84                         fd = open(path, O_WRONLY | O_APPEND | O_CREAT | O_NOFOLLOW |
  85                                           O_EXCL | O_CLOEXEC, 0644);
  86                         if (fd >= 0) {
  87                                 return fd;
  88                         }
  89                 }
  90         }
  91
  92         return -1;
  93 }
  94
  95 static
  96 void
  97 _os_trace_init(void *globals)
  98 {
  99         struct os_trace_globals_s *g = globals;
 100
 101         g->errors_only = false;
 102
 103         g->redirect = dlsym(RTLD_MAIN_ONLY, "_os_trace_redirect_func");
 104
 105         // This is a bit of a hack. LIBDISPATCH_LOG is part of dispatch's API.
 106         // But now all dispatch logging goes through os_trace. So we have to
 107         // recognize this env var here in Libc.
 108         // rdar://problem/11685359 tracks deprecating LIBDISPATCH_LOG from dispatch.
 109         char *e = getenv("LIBDISPATCH_LOG");
 110         if (!e) {
 111                 e = getenv("OS_TRACE");
 112         }
 113
 114         // Default log destination
 115         if (!e || strcmp(e, "YES") == 0) {
 116 #if DEBUG
 117                 e = "file";
 118 #else
 119                 e = "syslog";
 120 #endif
 121         }
 122
 123         if (strcmp(e, "NO") == 0) {
 124                 g->logfd = -1;
 125                 g->errors_only = true;
 126         } else if (strcmp(e, "syslog") == 0) {
 127                 g->logfd = -1;
 128         } else if (strcmp(e, "stderr") == 0) {
 129                 g->logfd = STDERR_FILENO;
 130         } else if (strcmp(e, "stdout") == 0) {
 131                 g->logfd = STDOUT_FILENO;
 132         } else if (strcmp(e, "file") == 0) {
 133                 g->logfd = _os_trace_open_file(NULL);
 134                 if (g->logfd == -1) {
 135                         g->errors_only = true;
 136                 }
 137         } else {
 138                 g->logfd = _os_trace_open_file(e);
 139                 if (g->logfd == -1) {
 140                         g->errors_only = true;
 141                 }
 142         }
 143
 144         // From now on, g->logfd == -1 means syslog; anything >= 0 is the
 145         // fd to use. Remember that file descriptor 0 is a perfectly valid
 146         // value for open() to return if you closed (or never had) stdin.
 147
 148         // Timestamp every log message if logging directly to file and no
 149         // redirector is set up.
 150         if (g->logfd >= 0 && !g->redirect) {
 151                 g->prepend_timestamp = true;
 152
 153                 struct timeval tv;
 154                 gettimeofday(&tv, NULL);
 155
 156                 g->start = mach_absolute_time();
 157
 158                 dprintf(g->logfd,
 159                                 "=== os_trace log file opened for %s[%u] at %ld.%06u",
 160                                 getprogname(), getpid(),
 161                                 tv.tv_sec, tv.tv_usec);
 162                 if (g->prepend_timestamp) {
 163                         mach_timebase_info_data_t tbi;
 164                         if (mach_timebase_info(&tbi) == 0) {
 165                                 dprintf(g->logfd, " [ns=ticks*%u/%u]",
 166                                                 tbi.numer, tbi.denom);
 167                         }
 168                 }
 169                 dprintf(g->logfd, " ===\n");
 170         }
 171 }
 172
 173 static inline __OS_CONST
 174 struct os_trace_globals_s *
 175 os_trace_globals(void)
 176 {
 177         return (struct os_trace_globals_s *)
 178                 os_alloc_once(OS_ALLOC_ONCE_KEY_OS_TRACE,
 179                                           sizeof(struct os_trace_globals_s),
 180                                           _os_trace_init);
 181 }
 182
 183 static __attribute__((always_inline))
 184 uint64_t
 185 _os_trace_ticks_since_start(void)
 186 {
 187         return mach_absolute_time() - os_trace_globals()->start;
 188 }
 189
 190 // False on error writing to file
 191 static inline
 192 bool
 193 _os_trace_write_fd(int level __attribute__((__unused__)),
 194                     char *str, int fd)
 195 {
 196         size_t len = strlen(str);
 197
 198         str[len++] = '\n'; // overwrite null - don't use str*() anymore
 199
 200         ssize_t rc, wlen = 0;
 201         do {
 202                 rc = write(fd, &str[wlen], len - wlen);
 203                 if (os_slowpath(rc == -1)) {
 204                         if(errno == EINTR) {
 205                                 rc = 0;
 206                         } else {
 207                                 return false;
 208                         }
 209                 }
 210                 wlen += rc;
 211         } while (wlen < len);
 212
 213         return true;
 214 }
 215
 216 static __attribute__((__noinline__))
 217 void
 218 _os_trace_write_error(void)
 219 {
 220         char err_str[256];
 221         const char *pfx = "os_trace() :";
 222         size_t pfxlen = strlen(pfx);
 223
 224         strlcpy(err_str, pfx, sizeof(err_str));
 225         strerror_r(errno, err_str+pfxlen, sizeof(err_str)-pfxlen);
 226         _simple_asl_log(LOG_ERR, "com.apple.os_trace", err_str);
 227 }
 228
 229 static inline
 230 void
 231 _os_trace_write(int level, char *str)
 232 {
 233         int fd = os_trace_globals()->logfd;
 234         os_redirect_t rdr = os_trace_globals()->redirect;
 235         // true = redirect has fully handled, don't log
 236         if (os_slowpath(rdr) && os_fastpath(rdr(str))) {
 237                 return;
 238         }
 239         if (os_slowpath(fd >= 0)) {
 240                 if (os_fastpath(_os_trace_write_fd(level, str, fd))) {
 241                         return;
 242                 } else {
 243                         _os_trace_write_error();
 244                         os_trace_globals()->logfd = -1;
 245                         // Don't return, fall out to syslog().
 246                 }
 247         }
 248         _simple_asl_log(level, "com.apple.os_trace", str);
 249 }
 250
 251 static __attribute__((always_inline))
 252 void
 253 _os_tracev(int level, const char *msg, va_list ap)
 254 {
 255         if (os_slowpath(os_trace_globals()->errors_only) && level > LOG_ERR) {
 256                 // more important = lower integer
 257                 return;
 258         }
 259         char *buf, *freebuf;
 260         size_t len;
 261
 262         len = vasprintf(&buf, msg, ap);
 263         if (!buf) {
 264                 return;
 265         }
 266         freebuf = buf;
 267
 268         // The os_trace macros prepend many spaces to the format string.
 269         // Overwrite them with a timestamp, *or* skip them.
 270         const size_t pfxlen = strlen(_OS_TRACE_PREFIX);
 271         const size_t timelen = 16;
 272         __OS_COMPILETIME_ASSERT__(pfxlen >= timelen);
 273
 274         if (os_fastpath(len > pfxlen)) {
 275                 if (os_slowpath(os_trace_globals()->prepend_timestamp)) {
 276                         char tmp = buf[timelen];
 277                         snprintf(buf, timelen + 1, "%16llu", _os_trace_ticks_since_start());
 278                         buf[timelen] = tmp; // snprintf's null
 279                 } else {
 280                         buf += pfxlen;
 281                 }
 282         }
 283
 284         _os_trace_write(level, buf);
 285         free(freebuf);
 286 }
 287
 288 void
 289 _os_trace_error_str(char *msg)
 290 {
 291         _os_trace_write(LOG_ERR, msg);
 292 }
 293
 294 __OS_PRINTFLIKE(1, 2)
 295 void
 296 _os_trace(const char *msg, ...)
 297 {
 298         va_list ap;
 299         va_start(ap, msg);
 300         _os_tracev(LOG_DEBUG, msg, ap);
 301         va_end(ap);
 302 }