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
41struct 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.
51static inline
52int
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
93static
94void
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
175static inline OS_CONST
176struct os_debug_log_globals_s *
177os_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
185static __attribute__((always_inline))
186uint64_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
193static inline
194bool
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
218static __attribute__((__noinline__))
219void
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
231static inline
232void
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
253static __attribute__((always_inline))
254void
255_os_debug_logv(int level, const char *msg, va_list ap)
256{
257	if (os_slowpath(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(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
290void
291_os_debug_log_error_str(char *msg)
292{
293	_os_debug_log_write(LOG_ERR, msg);
294}
295
296OS_FORMAT_PRINTF(1, 2)
297void
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}
305