os/debug_private.c

   1 /* Copyright (c) 2012-2013 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/assumes.h>
  30 #include <os/debug_private.h>
  31 #include <_simple.h>
  32 #include <stdarg.h>
  33 #include <stdbool.h>
  34 #include <stdio.h>
  35 #include <stdlib.h>
  36 #include <string.h>
  37 #include <syslog.h>
  38 #include <sys/time.h>
  39 #include <unistd.h>
  40
  41 struct os_debug_log_globals_s {
  42         uint64_t start;
  43         os_redirect_t redirect;
  44         int logfd;
  45         bool prepend_timestamp : 1;
  46         bool errors_only : 1;
  47 };
  48
  49 // If user picked a filename, use it and only it.
  50 // Otherwise, first try /var/tmp, then $TMPDIR, then give up.
  51 static inline
  52 int
  53 _os_debug_log_open_file(const char *suggestion)
  54 {
  55         if (suggestion) {
  56                 return open(suggestion, O_WRONLY | O_APPEND | O_CREAT | O_NOFOLLOW |
  57                                         O_EXCL | O_CLOEXEC, 0644);
  58         }
  59
  60         int fd;
  61         char filename[PATH_MAX];
  62         char path[PATH_MAX];
  63
  64         snprintf(filename, sizeof(filename), "os_debug_log.%s.%d.log", getprogname(),
  65                          getpid());
  66
  67         strlcpy(path, "/var/tmp/", sizeof(path));
  68         if (access(path, W_OK) == 0) {
  69                 strlcat(path, filename, sizeof(path));
  70                 fd = open(path, O_WRONLY | O_APPEND | O_CREAT | O_NOFOLLOW | O_EXCL |
  71                                   O_CLOEXEC, 0644);
  72                 if (fd >= 0) {
  73                         return fd;
  74                 }
  75         }
  76
  77         const char *tmpdir = getenv("TMPDIR");
  78         if (tmpdir) {
  79                 strlcpy(path, tmpdir, sizeof(path));
  80                 if (access(path, W_OK) == 0) {
  81                         strlcat(path, filename, sizeof(path));
  82                         fd = open(path, O_WRONLY | O_APPEND | O_CREAT | O_NOFOLLOW |
  83                                           O_EXCL | O_CLOEXEC, 0644);
  84                         if (fd >= 0) {
  85                                 return fd;
  86                         }
  87                 }
  88         }
  89
  90         return -1;
  91 }
  92
  93 static
  94 void
  95 _os_debug_log_init(void *globals)
  96 {
  97         struct os_debug_log_globals_s *g = globals;
  98
  99         g->errors_only = false;
 100
 101         g->redirect = dlsym(RTLD_MAIN_ONLY, "_os_debug_log_redirect_func");
 102
 103         // This is a bit of a hack. LIBDISPATCH_LOG is part of dispatch's API.
 104         // But now all dispatch logging goes through os_debug_log. So we have to
 105         // recognize this env var here in Libc.
 106         // rdar://problem/11685359 tracks deprecating LIBDISPATCH_LOG from dispatch.
 107         char *e = getenv("LIBDISPATCH_LOG");
 108         if (!e) {
 109                 e = getenv("OS_DEBUG_LOG");
 110         }
 111
 112         // Default log destination
 113         if (!e || strcmp(e, "YES") == 0) {
 114 #if DEBUG
 115                 e = "file";
 116 #else
 117                 e = "syslog";
 118 #endif
 119         }
 120
 121         if (strcmp(e, "NO") == 0) {
 122                 g->logfd = -1;
 123                 g->errors_only = true;
 124         } else if (strcmp(e, "syslog") == 0) {
 125                 g->logfd = -1;
 126         } else if (strcmp(e, "stderr") == 0) {
 127                 g->logfd = STDERR_FILENO;
 128         } else if (strcmp(e, "stdout") == 0) {
 129                 g->logfd = STDOUT_FILENO;
 130         } else if (strcmp(e, "file") == 0) {
 131                 g->logfd = _os_debug_log_open_file(NULL);
 132                 if (g->logfd == -1) {
 133                         g->errors_only = true;
 134                 }
 135         } else {
 136                 g->logfd = _os_debug_log_open_file(e);
 137                 if (g->logfd == -1) {
 138                         g->errors_only = true;
 139                 }
 140         }
 141
 142         // From now on, g->logfd == -1 means syslog; anything >= 0 is the
 143         // fd to use. Remember that file descriptor 0 is a perfectly valid
 144         // value for open() to return if you closed (or never had) stdin.
 145
 146         // Timestamp every log message if logging directly to file and no
 147         // redirector is set up.
 148         if (g->logfd >= 0 && !g->redirect) {
 149                 g->prepend_timestamp = true;
 150
 151                 struct timeval tv;
 152                 gettimeofday(&tv, NULL);
 153
 154                 g->start = mach_absolute_time();
 155
 156                 dprintf(g->logfd,
 157                                 "=== os_debug_log log file opened for %s[%u] at %ld.%06u",
 158                                 getprogname(), getpid(),
 159                                 tv.tv_sec, tv.tv_usec);
 160                 if (g->prepend_timestamp) {
 161                         mach_timebase_info_data_t tbi;
 162                         if (mach_timebase_info(&tbi) == 0) {
 163                                 dprintf(g->logfd, " [ns=ticks*%u/%u]",
 164                                                 tbi.numer, tbi.denom);
 165                         }
 166                 }
 167                 dprintf(g->logfd, " ===\n");
 168         }
 169 }
 170
 171 #ifndef OS_ALLOC_ONCE_KEY_OS_DEBUG_LOG
 172 #define OS_ALLOC_ONCE_KEY_OS_DEBUG_LOG OS_ALLOC_ONCE_KEY_OS_TRACE
 173 #endif
 174
 175 static inline OS_CONST
 176 struct os_debug_log_globals_s *
 177 os_debug_log_globals(void)
 178 {
 179         return (struct os_debug_log_globals_s *)
 180                 os_alloc_once(OS_ALLOC_ONCE_KEY_OS_DEBUG_LOG,
 181                                           sizeof(struct os_debug_log_globals_s),
 182                                           _os_debug_log_init);
 183 }
 184
 185 static __attribute__((always_inline))
 186 uint64_t
 187 _os_debug_log_ticks_since_start(void)
 188 {
 189         return mach_absolute_time() - os_debug_log_globals()->start;
 190 }
 191
 192 // False on error writing to file
 193 static inline
 194 bool
 195 _os_debug_log_write_fd(int level __attribute__((__unused__)),
 196                     char *str, int fd)
 197 {
 198         size_t len = strlen(str);
 199
 200         str[len++] = '\n'; // overwrite null - don't use str*() anymore
 201
 202         ssize_t rc, wlen = 0;
 203         do {
 204                 rc = write(fd, &str[wlen], len - wlen);
 205                 if (os_slowpath(rc == -1)) {
 206                         if(errno == EINTR) {
 207                                 rc = 0;
 208                         } else {
 209                                 return false;
 210                         }
 211                 }
 212                 wlen += rc;
 213         } while (wlen < len);
 214
 215         return true;
 216 }
 217
 218 static __attribute__((__noinline__))
 219 void
 220 _os_debug_log_write_error(void)
 221 {
 222         char err_str[256];
 223         const char *pfx = "os_debug_log() :";
 224         size_t pfxlen = strlen(pfx);
 225
 226         strlcpy(err_str, pfx, sizeof(err_str));
 227         strerror_r(errno, err_str+pfxlen, sizeof(err_str)-pfxlen);
 228         _simple_asl_log(LOG_ERR, "com.apple.os_debug_log", err_str);
 229 }
 230
 231 static inline
 232 void
 233 _os_debug_log_write(int level, char *str)
 234 {
 235         int fd = os_debug_log_globals()->logfd;
 236         os_redirect_t rdr = os_debug_log_globals()->redirect;
 237         // true = redirect has fully handled, don't log
 238         if (os_slowpath(rdr) && os_fastpath(rdr(str))) {
 239                 return;
 240         }
 241         if (os_slowpath(fd >= 0)) {
 242                 if (os_fastpath(_os_debug_log_write_fd(level, str, fd))) {
 243                         return;
 244                 } else {
 245                         _os_debug_log_write_error();
 246                         os_debug_log_globals()->logfd = -1;
 247                         // Don't return, fall out to syslog().
 248                 }
 249         }
 250         _simple_asl_log(level, "com.apple.os_debug_log", str);
 251 }
 252
 253 static __attribute__((always_inline))
 254 void
 255 _os_debug_logv(int level, const char *msg, va_list ap)
 256 {
 257         if (os_slowpath((bool)os_debug_log_globals()->errors_only) && level > LOG_ERR) {
 258                 // more important = lower integer
 259                 return;
 260         }
 261         char *buf, *freebuf;
 262         size_t len;
 263
 264         len = vasprintf(&buf, msg, ap);
 265         if (!buf) {
 266                 return;
 267         }
 268         freebuf = buf;
 269
 270         // The os_debug_log macros prepend many spaces to the format string.
 271         // Overwrite them with a timestamp, *or* skip them.
 272         const size_t pfxlen = strlen(_OS_DEBUG_LOG_PREFIX);
 273         const size_t timelen = 16;
 274         __OS_COMPILETIME_ASSERT__(pfxlen >= timelen);
 275
 276         if (os_fastpath(len > pfxlen)) {
 277                 if (os_slowpath((bool)os_debug_log_globals()->prepend_timestamp)) {
 278                         char tmp = buf[timelen];
 279                         snprintf(buf, timelen + 1, "%16llu", _os_debug_log_ticks_since_start());
 280                         buf[timelen] = tmp; // snprintf's null
 281                 } else {
 282                         buf += pfxlen;
 283                 }
 284         }
 285
 286         _os_debug_log_write(level, buf);
 287         free(freebuf);
 288 }
 289
 290 void
 291 _os_debug_log_error_str(char *msg)
 292 {
 293         _os_debug_log_write(LOG_ERR, msg);
 294 }
 295
 296 OS_FORMAT_PRINTF(1, 2)
 297 void
 298 _os_debug_log(const char *msg, ...)
 299 {
 300         va_list ap;
 301         va_start(ap, msg);
 302         _os_debug_logv(LOG_DEBUG, msg, ap);
 303         va_end(ap);
 304 }