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