1/*
2 * Copyright 2017, Data61
3 * Commonwealth Scientific and Industrial Research Organisation (CSIRO)
4 * ABN 41 687 119 230.
5 *
6 * This software may be distributed and modified according to the terms of
7 * the BSD 2-Clause license. Note that NO WARRANTY is provided.
8 * See "LICENSE_BSD2.txt" for details.
9 *
10 * @TAG(DATA61_BSD)
11 */
12#include <utils/zf_log_config.h>
13
14/* Controls Android log (android/log.h) support. When defined, must be 1
15 * (enable) or 0 (disable). Disabled by default.
16 */
17#ifndef ZF_LOG_ANDROID_LOG
18	#define ZF_LOG_ANDROID_LOG 0
19#endif
20/* Controls Apple log (asl.h) support. When defined, must be 1 (enable) or 0
21 * (disable). Disabled by default. Doesn't use asl directly, but piggybacks on
22 * non-public CFLog() function.
23 */
24#ifndef ZF_LOG_APPLE_LOG
25	#define ZF_LOG_APPLE_LOG 0
26#endif
27/* Controls whether to add timestamp, pid, tid and level in the log message.
28 * When defined, must be 1 (enable) or 0 (disable). If not defined, default
29 * will be used.
30 */
31#ifndef ZF_LOG_PUT_CTX
32	#if ZF_LOG_ANDROID_LOG || ZF_LOG_APPLE_LOG
33		#define ZF_LOG_PUT_CTX 0
34	#else
35		#define ZF_LOG_PUT_CTX 1
36	#endif
37#endif
38/* Size of the log line buffer. The buffer is allocated on the stack. It limits
39 * the maximum length of the log line.
40 */
41#ifndef ZF_LOG_BUF_SZ
42	#define ZF_LOG_BUF_SZ 256
43#endif
44/* String to put in the end of each log line when necessary (can be empty).
45 */
46#ifndef ZF_LOG_EOL
47	#define ZF_LOG_EOL "\n"
48#endif
49/* Number of bytes to reserve for EOL in the log line buffer (must be >0).
50 */
51#ifndef ZF_LOG_EOL_SZ
52	#define ZF_LOG_EOL_SZ sizeof(ZF_LOG_EOL)
53#endif
54/* Default number of bytes in one line of memory output. For large values
55 * ZF_LOG_BUF_SZ also must be increased.
56 */
57#ifndef ZF_LOG_MEM_WIDTH
58	#define ZF_LOG_MEM_WIDTH 32
59#endif
60/* Compile instrumented version of the library to facilitate unit testing.
61 */
62#ifndef ZF_LOG_INSTRUMENTED
63	#define ZF_LOG_INSTRUMENTED 0
64#endif
65
66#include <assert.h>
67#include <string.h>
68#include <stdarg.h>
69#include <stddef.h>
70#include <stdlib.h>
71#include <stdio.h>
72#include <ctype.h>
73#include <unistd.h>
74#include <time.h>
75#include <sys/time.h>
76#include <utils/zf_log.h>
77
78#if defined(__linux__)
79	#include <sys/prctl.h>
80	#include <sys/types.h>
81#endif
82#if defined(__linux__) && !defined(__ANDROID__)
83	#include <sys/syscall.h>
84	/* avoid defining _GNU_SOURCE */
85	int syscall(int number, ...);
86#endif
87#if defined(__MACH__) && ZF_LOG_PUT_CTX
88	#include <pthread.h>
89#endif
90
91#if ZF_LOG_ANDROID_LOG
92	#include <android/log.h>
93#endif
94#if ZF_LOG_APPLE_LOG
95	#include <CoreFoundation/CoreFoundation.h>
96	CF_EXPORT void CFLog(int32_t level, CFStringRef format, ...);
97#endif
98
99#if ZF_LOG_INSTRUMENTED
100	#define INSTRUMENTED_CONST
101#else
102	#define INSTRUMENTED_CONST const
103#endif
104
105#define STATIC_ASSERT(name, cond) \
106	typedef char assert_##name[(cond)? 1: -1]
107
108typedef void (*time_cb)(struct tm *const tm, unsigned *const usec);
109typedef void (*pid_cb)(int *const pid, int *const tid);
110typedef void (*buffer_cb)(zf_log_output_ctx *ctx, char *buf);
111
112#if ZF_LOG_PUT_CTX
113static void time_callback(struct tm *const tm, unsigned *const usec);
114static void pid_callback(int *const pid, int *const tid);
115#endif
116static void buffer_callback(zf_log_output_ctx *ctx, char *buf);
117static void output_callback(zf_log_output_ctx *const ctx);
118
119STATIC_ASSERT(eol_fits_eol_sz, sizeof(ZF_LOG_EOL) <= ZF_LOG_EOL_SZ);
120STATIC_ASSERT(eol_sz_greater_than_zero, 0 < ZF_LOG_EOL_SZ);
121static const char c_hex[] = "0123456789abcdef";
122
123static const char *g_tag_prefix = 0;
124static size_t g_mem_width = ZF_LOG_MEM_WIDTH;
125static INSTRUMENTED_CONST unsigned g_buf_sz = ZF_LOG_BUF_SZ - ZF_LOG_EOL_SZ;
126#if ZF_LOG_PUT_CTX
127static INSTRUMENTED_CONST time_cb g_time_cb = time_callback;
128static INSTRUMENTED_CONST pid_cb g_pid_cb = pid_callback;
129#endif
130static INSTRUMENTED_CONST buffer_cb g_buffer_cb = buffer_callback;
131static zf_log_output_cb g_output_cb = output_callback;
132
133int _zf_log_output_lvl = 0;
134
135#if ZF_LOG_ANDROID_LOG
136static int android_lvl(const int lvl)
137{
138	switch (lvl)
139	{
140	case ZF_LOG_VERBOSE:
141		return ANDROID_LOG_VERBOSE;
142	case ZF_LOG_DEBUG:
143		return ANDROID_LOG_DEBUG;
144	case ZF_LOG_INFO:
145		return ANDROID_LOG_INFO;
146	case ZF_LOG_WARN:
147		return ANDROID_LOG_WARN;
148	case ZF_LOG_ERROR:
149		return ANDROID_LOG_ERROR;
150	case ZF_LOG_FATAL:
151		return ANDROID_LOG_FATAL;
152	default:
153		assert(!"Bad log level");
154		return ANDROID_LOG_UNKNOWN;
155	}
156}
157#endif
158
159#if ZF_LOG_APPLE_LOG
160static int apple_lvl(const int lvl)
161{
162	switch (lvl)
163	{
164	case ZF_LOG_VERBOSE:
165		return 7; /* ASL_LEVEL_DEBUG / kCFLogLevelDebug */;
166	case ZF_LOG_DEBUG:
167		return 7; /* ASL_LEVEL_DEBUG / kCFLogLevelDebug */;
168	case ZF_LOG_INFO:
169		return 6; /* ASL_LEVEL_INFO / kCFLogLevelInfo */;
170	case ZF_LOG_WARN:
171		return 4; /* ASL_LEVEL_WARNING / kCFLogLevelWarning */;
172	case ZF_LOG_ERROR:
173		return 3; /* ASL_LEVEL_ERR / kCFLogLevelError */;
174	case ZF_LOG_FATAL:
175		return 0; /* ASL_LEVEL_EMERG / kCFLogLevelEmergency */;
176	default:
177		assert(!"Bad log level");
178		return 0; /* ASL_LEVEL_EMERG / kCFLogLevelEmergency */;
179	}
180}
181#endif
182
183#if ZF_LOG_PUT_CTX
184static char lvl_char(const int lvl)
185{
186	switch (lvl)
187	{
188	case ZF_LOG_VERBOSE:
189		return 'V';
190	case ZF_LOG_DEBUG:
191		return 'D';
192	case ZF_LOG_INFO:
193		return 'I';
194	case ZF_LOG_WARN:
195		return 'W';
196	case ZF_LOG_ERROR:
197		return 'E';
198	case ZF_LOG_FATAL:
199		return 'F';
200	default:
201		assert(!"Bad log level");
202		return '?';
203	}
204}
205
206static void time_callback(struct tm *const tm, unsigned *const usec)
207{
208	struct timeval tv;
209	gettimeofday(&tv, 0);
210	const time_t t = tv.tv_sec;
211	*tm = *localtime(&t);
212	*usec = tv.tv_usec;
213}
214
215static void pid_callback(int *const pid, int *const tid)
216{
217	*pid = getpid();
218#if defined(__ANDROID__)
219	*tid = gettid();
220#elif defined(__linux__)
221	*tid = syscall(SYS_gettid);
222#elif defined(__MACH__)
223	*tid = pthread_mach_thread_np(pthread_self());
224#else
225	#define Platform not supported
226#endif
227}
228#endif // ZF_LOG_PUT_CTX
229
230static void buffer_callback(zf_log_output_ctx *ctx, char *buf)
231{
232	ctx->e = (ctx->p = ctx->buf = buf) + g_buf_sz;
233}
234
235static void output_callback(zf_log_output_ctx *const ctx)
236{
237#if ZF_LOG_ANDROID_LOG
238	*ctx->p = 0;
239	const char *tag = ctx->p;
240	if (ctx->tag_e != ctx->tag_b)
241	{
242		tag = ctx->tag_b;
243		*ctx->tag_e = 0;
244	}
245	__android_log_print(android_lvl(ctx->lvl), tag, "%s", ctx->msg_b);
246#elif ZF_LOG_APPLE_LOG
247	*ctx->p = 0;
248	CFLog(apple_lvl(ctx->lvl), CFSTR("%s"), ctx->tag_b);
249#else
250	strcpy(ctx->p, ZF_LOG_EOL);
251	fputs(ctx->buf, stderr);
252#endif
253	if (ZF_LOG_FATAL == ctx->lvl)
254	{
255		fflush(stderr);
256		abort();
257	}
258}
259
260static const char *filename(const char *file)
261{
262	const char *f = file;
263	for (const char *p = file; 0 != *p; ++p)
264	{
265		if ('/' == *p || '\\' == *p)
266		{
267			f = p + 1;
268		}
269	}
270	return f;
271}
272
273static inline size_t nprintf_size(zf_log_output_ctx *const ctx)
274{
275	// *nprintf() always puts 0 in the end when input buffer is not empty. This
276	// 0 is not desired because its presence sets (ctx->p) to (ctx->e - 1) which
277	// leaves space for one more character. Some put_xxx() functions don't use
278	// *nprintf() and could use that last character. In that case log line will
279	// have multiple (two) half-written parts which is confusing. To workaround
280	// that we allow *nprintf() to write its 0 in the eol area (which is always
281	// not empty).
282	return ctx->e - ctx->p + 1;
283}
284
285static inline void put_nprintf(zf_log_output_ctx *const ctx, const int n)
286{
287	if (0 < n && ctx->e < (ctx->p += n))
288	{
289		ctx->p = ctx->e;
290	}
291}
292
293static void put_ctx(zf_log_output_ctx *const ctx)
294{
295#if ZF_LOG_PUT_CTX
296	int n;
297	struct tm tm;
298	unsigned usec;
299	int pid, tid;
300	g_time_cb(&tm, &usec);
301	g_pid_cb(&pid, &tid);
302	n = snprintf(ctx->p, nprintf_size(ctx),
303				 "%02u-%02u %02u:%02u:%02u.%03u %5i %5i %c ",
304				 (unsigned)tm.tm_mon, (unsigned)tm.tm_mday,
305				 (unsigned)tm.tm_hour, (unsigned)tm.tm_min, (unsigned)tm.tm_sec,
306				 (unsigned)(usec / 1000),
307				 pid, tid, (char)lvl_char(ctx->lvl));
308	put_nprintf(ctx, n);
309#else
310	(void)ctx;
311#endif
312}
313
314static void put_tag(zf_log_output_ctx *const ctx, const char *const tag)
315{
316	const char *ch;
317	ctx->tag_b = ctx->p;
318	if (0 != (ch = g_tag_prefix))
319	{
320		for (;ctx->e != ctx->p && 0 != (*ctx->p = *ch); ++ctx->p, ++ch)
321		{
322		}
323	}
324	if (0 != (ch = tag) && 0 != tag[0])
325	{
326		if (ctx->tag_b != ctx->p && ctx->e != ctx->p)
327		{
328			*ctx->p++ = '.';
329		}
330		for (;ctx->e != ctx->p && 0 != (*ctx->p = *ch); ++ctx->p, ++ch)
331		{
332		}
333	}
334	ctx->tag_e = ctx->p;
335	if (ctx->tag_b != ctx->p && ctx->e != ctx->p)
336	{
337		*ctx->p++ = ' ';
338	}
339}
340
341static void put_src(zf_log_output_ctx *const ctx, const char *const func,
342					const char *const file, const unsigned line)
343{
344	int n;
345	n = snprintf(ctx->p, nprintf_size(ctx), "%s@%s:%u ",
346				 func, filename(file), line);
347	put_nprintf(ctx, n);
348}
349
350static void put_msg(zf_log_output_ctx *const ctx,
351					const char *const fmt, va_list va)
352{
353	int n;
354	ctx->msg_b = ctx->p;
355	n = vsnprintf(ctx->p, nprintf_size(ctx), fmt, va);
356	put_nprintf(ctx, n);
357}
358
359static void output_mem(zf_log_output_ctx *const ctx,
360					   const void *const d, const unsigned d_sz)
361{
362	if (0 == d || 0 == d_sz)
363	{
364		return;
365	}
366	const unsigned char *mem_p = (const unsigned char *)d;
367	const unsigned char *const mem_e = mem_p + d_sz;
368	const unsigned char *mem_cut;
369	const ptrdiff_t mem_width = g_mem_width;
370	char *const hex_b = ctx->msg_b;
371	char *const ascii_b = hex_b + 2 * mem_width + 2;
372	char *const ascii_e = ascii_b + mem_width;
373	if (ctx->e < ascii_e)
374	{
375		return;
376	}
377	while (mem_p != mem_e)
378	{
379		char *hex = hex_b;
380		char *ascii = ascii_b;
381		for (mem_cut = mem_width < mem_e - mem_p? mem_p + mem_width: mem_e;
382			 mem_cut != mem_p; ++mem_p)
383		{
384			const char ch = *mem_p;
385			*hex++ = c_hex[(0xf0 & ch) >> 4];
386			*hex++ = c_hex[(0x0f & ch)];
387			*ascii++ = isprint(ch)? ch: '?';
388		}
389		while (hex != ascii_b)
390		{
391			*hex++ = ' ';
392		}
393		ctx->p = ascii;
394		g_output_cb(ctx);
395	}
396}
397
398void zf_log_set_tag_prefix(const char *const prefix)
399{
400	g_tag_prefix = prefix;
401}
402
403void zf_log_set_mem_width(const unsigned w)
404{
405	g_mem_width = w;
406}
407
408void zf_log_set_output_level(const int lvl)
409{
410	_zf_log_output_lvl = lvl;
411}
412
413void zf_log_set_output_callback(const zf_log_output_cb cb)
414{
415	g_output_cb = cb;
416}
417
418#define CTX(lvl_, tag_) \
419	zf_log_output_ctx ctx; \
420	char buf[ZF_LOG_BUF_SZ]; \
421	ctx.lvl = (lvl_); \
422	ctx.tag = (tag_); \
423	g_buffer_cb(&ctx, buf); \
424	(void)0
425
426
427void _zf_log_write_d(const char *const func,
428					 const char *const file, const unsigned line,
429					 const int lvl, const char *const tag,
430					 const char *const fmt, ...)
431{
432	CTX(lvl, tag);
433	va_list va;
434	va_start(va, fmt);
435	put_ctx(&ctx);
436	put_tag(&ctx, tag);
437	put_src(&ctx, func, file, line);
438	put_msg(&ctx, fmt, va);
439	g_output_cb(&ctx);
440	va_end(va);
441}
442
443void _zf_log_write(const int lvl, const char *const tag,
444				   const char *const fmt, ...)
445{
446	CTX(lvl, tag);
447	va_list va;
448	va_start(va, fmt);
449	put_ctx(&ctx);
450	put_tag(&ctx, tag);
451	put_msg(&ctx, fmt, va);
452	g_output_cb(&ctx);
453	va_end(va);
454}
455
456void _zf_log_write_mem_d(const char *const func,
457						 const char *const file, const unsigned line,
458						 const int lvl, const char *const tag,
459						 const void *const d, const unsigned d_sz,
460						 const char *const fmt, ...)
461{
462	CTX(lvl, tag);
463	va_list va;
464	va_start(va, fmt);
465	put_ctx(&ctx);
466	put_tag(&ctx, tag);
467	put_src(&ctx, func, file, line);
468	put_msg(&ctx, fmt, va);
469	g_output_cb(&ctx);
470	output_mem(&ctx, d, d_sz);
471	va_end(va);
472}
473
474void _zf_log_write_mem(const int lvl, const char *const tag,
475					   const void *const d, const unsigned d_sz,
476					   const char *const fmt, ...)
477{
478	CTX(lvl, tag);
479	va_list va;
480	va_start(va, fmt);
481	put_ctx(&ctx);
482	put_tag(&ctx, tag);
483	put_msg(&ctx, fmt, va);
484	g_output_cb(&ctx);
485	output_mem(&ctx, d, d_sz);
486	va_end(va);
487}
488