1 /**
2 * Copyright (C) Mellanox Technologies Ltd. 2001-2014. ALL RIGHTS RESERVED.
3 *
4 * See file LICENSE for terms.
5 */
6
7 #ifdef HAVE_CONFIG_H
8 # include "config.h"
9 #endif
10
11 #include "log.h"
12
13 #include <ucs/debug/debug.h>
14 #include <ucs/sys/compiler.h>
15 #include <ucs/sys/checker.h>
16 #include <ucs/sys/string.h>
17 #include <ucs/sys/sys.h>
18 #include <ucs/sys/math.h>
19 #include <ucs/config/parser.h>
20
21 #define UCS_MAX_LOG_HANDLERS 32
22
23 #define UCS_LOG_TIME_FMT "[%lu.%06lu]"
24 #define UCS_LOG_FILE_FMT "%16s:%-4u"
25 #define UCS_LOG_METADATA_FMT "%-4s %-5s"
26 #define UCS_LOG_PROC_DATA_FMT "[%s:%-5d:%d]"
27 #define UCS_LOG_SHORT_FMT UCS_LOG_TIME_FMT" "UCS_LOG_FILE_FMT" " \
28 UCS_LOG_METADATA_FMT" ""%s\n"
29 #define UCS_LOG_FMT UCS_LOG_TIME_FMT" "UCS_LOG_PROC_DATA_FMT" " \
30 UCS_LOG_FILE_FMT" "UCS_LOG_METADATA_FMT" ""%s\n"
31
32 #define UCS_LOG_TIME_ARG(_tv) (_tv)->tv_sec, (_tv)->tv_usec
33 #define UCS_LOG_SHORT_ARG(_short_file, _line, _level, _comp_conf, _tv, _message) \
34 UCS_LOG_TIME_ARG(_tv), _short_file, _line, (_comp_conf)->name, \
35 ucs_log_level_names[_level], _message
36 #define UCS_LOG_ARG(_short_file, _line, _level, _comp_conf, _tv, _message) \
37 UCS_LOG_TIME_ARG(_tv), ucs_log_hostname, ucs_log_pid, \
38 ucs_log_get_thread_num(),_short_file, _line, (_comp_conf)->name, \
39 ucs_log_level_names[_level], _message
40
41 const char *ucs_log_level_names[] = {
42 [UCS_LOG_LEVEL_FATAL] = "FATAL",
43 [UCS_LOG_LEVEL_ERROR] = "ERROR",
44 [UCS_LOG_LEVEL_WARN] = "WARN",
45 [UCS_LOG_LEVEL_DIAG] = "DIAG",
46 [UCS_LOG_LEVEL_INFO] = "INFO",
47 [UCS_LOG_LEVEL_DEBUG] = "DEBUG",
48 [UCS_LOG_LEVEL_TRACE] = "TRACE",
49 [UCS_LOG_LEVEL_TRACE_REQ] = "REQ",
50 [UCS_LOG_LEVEL_TRACE_DATA] = "DATA",
51 [UCS_LOG_LEVEL_TRACE_ASYNC] = "ASYNC",
52 [UCS_LOG_LEVEL_TRACE_FUNC] = "FUNC",
53 [UCS_LOG_LEVEL_TRACE_POLL] = "POLL",
54 [UCS_LOG_LEVEL_LAST] = NULL,
55 [UCS_LOG_LEVEL_PRINT] = "PRINT"
56 };
57
58 static unsigned ucs_log_handlers_count = 0;
59 static int ucs_log_initialized = 0;
60 static char ucs_log_hostname[HOST_NAME_MAX] = {0};
61 static int ucs_log_pid = 0;
62 static FILE *ucs_log_file = NULL;
63 static char *ucs_log_file_base_name = NULL;
64 static int ucs_log_file_close = 0;
65 static int ucs_log_file_last_idx = 0;
66 static unsigned threads_count = 0;
67 static pthread_spinlock_t threads_lock = 0;
68 static pthread_t threads[128] = {0};
69 static ucs_log_func_t ucs_log_handlers[UCS_MAX_LOG_HANDLERS];
70
71
ucs_log_get_thread_num(void)72 static int ucs_log_get_thread_num(void)
73 {
74 pthread_t self = pthread_self();
75 int i;
76
77 for (i = 0; i < threads_count; ++i) {
78 if (threads[i] == self) {
79 return i;
80 }
81 }
82
83 pthread_spin_lock(&threads_lock);
84
85 for (i = 0; i < threads_count; ++i) {
86 if (threads[i] == self) {
87 goto unlock_and_return_i;
88 }
89 }
90
91 if (threads_count >= ucs_static_array_size(threads)) {
92 i = -1;
93 goto unlock_and_return_i;
94 }
95
96 i = threads_count;
97 ++threads_count;
98 threads[i] = self;
99
100 unlock_and_return_i:
101 pthread_spin_unlock(&threads_lock);
102 return i;
103 }
104
ucs_log_flush()105 void ucs_log_flush()
106 {
107 if (ucs_log_file != NULL) {
108 fflush(ucs_log_file);
109 fsync(fileno(ucs_log_file));
110 }
111 }
112
ucs_log_get_buffer_size()113 size_t ucs_log_get_buffer_size()
114 {
115 return ucs_config_memunits_get(ucs_global_opts.log_buffer_size,
116 256, UCS_ALLOCA_MAX_SIZE);
117 }
118
ucs_log_get_file_name(char * log_file_name,size_t max,int idx)119 static void ucs_log_get_file_name(char *log_file_name, size_t max, int idx)
120 {
121 ucs_assert(idx <= ucs_global_opts.log_file_rotate);
122
123 if (idx == 0) {
124 ucs_strncpy_zero(log_file_name, ucs_log_file_base_name, max);
125 return;
126 }
127
128 ucs_snprintf_zero(log_file_name, max, "%s.%d",
129 ucs_log_file_base_name, idx);
130 }
131
ucs_log_file_rotate()132 static void ucs_log_file_rotate()
133 {
134 char old_log_file_name[PATH_MAX];
135 char new_log_file_name[PATH_MAX];
136 int idx, ret;
137
138 if (ucs_log_file_last_idx == ucs_global_opts.log_file_rotate) {
139 /* remove the last file and log rotation from the
140 * `log_file_rotate - 1` file */
141 ucs_log_get_file_name(old_log_file_name,
142 sizeof(old_log_file_name),
143 ucs_log_file_last_idx);
144 unlink(old_log_file_name);
145 } else {
146 ucs_log_file_last_idx++;
147 }
148
149 ucs_assert(ucs_log_file_last_idx <= ucs_global_opts.log_file_rotate);
150
151 for (idx = ucs_log_file_last_idx - 1; idx >= 0; --idx) {
152 ucs_log_get_file_name(old_log_file_name,
153 sizeof(old_log_file_name), idx);
154 ucs_log_get_file_name(new_log_file_name,
155 sizeof(new_log_file_name), idx + 1);
156
157 if (access(old_log_file_name, W_OK) != 0) {
158 ucs_fatal("unable to write to %s", old_log_file_name);
159 }
160
161 /* coverity[toctou] */
162 ret = rename(old_log_file_name, new_log_file_name);
163 if (ret) {
164 ucs_fatal("failed to rename %s to %s: %m",
165 old_log_file_name, new_log_file_name);
166 }
167
168
169 if (access(old_log_file_name, F_OK) != -1) {
170 ucs_fatal("%s must not exist on the filesystem", old_log_file_name);
171 }
172
173 if (access(new_log_file_name, W_OK) != 0) {
174 ucs_fatal("unable to write to %s", new_log_file_name);
175 }
176 }
177 }
178
ucs_log_handle_file_max_size(int log_entry_len)179 static void ucs_log_handle_file_max_size(int log_entry_len)
180 {
181 const char *next_token;
182
183 /* check if it is necessary to find a new storage for logs */
184 if ((log_entry_len + ftell(ucs_log_file)) < ucs_global_opts.log_file_size) {
185 return;
186 }
187
188 fclose(ucs_log_file);
189
190 if (ucs_global_opts.log_file_rotate != 0) {
191 ucs_log_file_rotate();
192 } else {
193 unlink(ucs_log_file_base_name);
194 }
195
196 ucs_open_output_stream(ucs_log_file_base_name, UCS_LOG_LEVEL_FATAL,
197 &ucs_log_file, &ucs_log_file_close,
198 &next_token, NULL);
199 }
200
ucs_log_print(size_t buffer_size,const char * short_file,int line,ucs_log_level_t level,const ucs_log_component_config_t * comp_conf,const struct timeval * tv,const char * message)201 static void ucs_log_print(size_t buffer_size, const char *short_file, int line,
202 ucs_log_level_t level,
203 const ucs_log_component_config_t *comp_conf,
204 const struct timeval *tv, const char *message)
205 {
206 char *log_buf;
207 int log_entry_len;
208
209 if (RUNNING_ON_VALGRIND) {
210 log_buf = ucs_alloca(buffer_size + 1);
211 snprintf(log_buf, buffer_size, UCS_LOG_SHORT_FMT,
212 UCS_LOG_SHORT_ARG(short_file, line, level,
213 comp_conf, tv, message));
214 VALGRIND_PRINTF("%s", log_buf);
215 } else if (ucs_log_initialized) {
216 if (ucs_log_file_close) { /* non-stdout/stderr */
217 /* get log entry size */
218 log_entry_len = snprintf(NULL, 0, UCS_LOG_FMT,
219 UCS_LOG_ARG(short_file, line, level,
220 comp_conf, tv, message));
221 ucs_log_handle_file_max_size(log_entry_len);
222 }
223
224 fprintf(ucs_log_file, UCS_LOG_FMT,
225 UCS_LOG_ARG(short_file, line, level,
226 comp_conf, tv, message));
227 } else {
228 fprintf(stdout, UCS_LOG_SHORT_FMT,
229 UCS_LOG_SHORT_ARG(short_file, line, level,
230 comp_conf, tv, message));
231 }
232 }
233
234 ucs_log_func_rc_t
ucs_log_default_handler(const char * file,unsigned line,const char * function,ucs_log_level_t level,const ucs_log_component_config_t * comp_conf,const char * format,va_list ap)235 ucs_log_default_handler(const char *file, unsigned line, const char *function,
236 ucs_log_level_t level,
237 const ucs_log_component_config_t *comp_conf,
238 const char *format, va_list ap)
239 {
240 size_t buffer_size = ucs_log_get_buffer_size();
241 char *saveptr = "";
242 char *log_line;
243 struct timeval tv;
244 char *buf;
245
246 if (!ucs_log_component_is_enabled(level, comp_conf) && (level != UCS_LOG_LEVEL_PRINT)) {
247 return UCS_LOG_FUNC_RC_CONTINUE;
248 }
249
250 buf = ucs_alloca(buffer_size + 1);
251 buf[buffer_size] = 0;
252 vsnprintf(buf, buffer_size, format, ap);
253
254 if (level <= ucs_global_opts.log_level_trigger) {
255 ucs_fatal_error_message(file, line, function, buf);
256 } else {
257 gettimeofday(&tv, NULL);
258
259 log_line = strtok_r(buf, "\n", &saveptr);
260 while (log_line != NULL) {
261 ucs_log_print(buffer_size, ucs_basename(file), line, level, comp_conf,
262 &tv, log_line);
263 log_line = strtok_r(NULL, "\n", &saveptr);
264 }
265 }
266
267 /* flush the log file if the log_level of this message is fatal or error */
268 if (level <= UCS_LOG_LEVEL_ERROR) {
269 ucs_log_flush();
270 }
271
272 return UCS_LOG_FUNC_RC_CONTINUE;
273 }
274
ucs_log_push_handler(ucs_log_func_t handler)275 void ucs_log_push_handler(ucs_log_func_t handler)
276 {
277 if (ucs_log_handlers_count < UCS_MAX_LOG_HANDLERS) {
278 ucs_log_handlers[ucs_log_handlers_count++] = handler;
279 }
280 }
281
ucs_log_pop_handler()282 void ucs_log_pop_handler()
283 {
284 if (ucs_log_handlers_count > 0) {
285 --ucs_log_handlers_count;
286 }
287 }
288
ucs_log_num_handlers()289 unsigned ucs_log_num_handlers()
290 {
291 return ucs_log_handlers_count;
292 }
293
ucs_log_dispatch(const char * file,unsigned line,const char * function,ucs_log_level_t level,ucs_log_component_config_t * comp_conf,const char * format,...)294 void ucs_log_dispatch(const char *file, unsigned line, const char *function,
295 ucs_log_level_t level, ucs_log_component_config_t *comp_conf,
296 const char *format, ...)
297 {
298 ucs_log_func_rc_t rc;
299 unsigned idx;
300 va_list ap;
301
302 /* Call handlers in reverse order */
303 rc = UCS_LOG_FUNC_RC_CONTINUE;
304 idx = ucs_log_handlers_count;
305 while ((idx > 0) && (rc == UCS_LOG_FUNC_RC_CONTINUE)) {
306 --idx;
307 va_start(ap, format);
308 rc = ucs_log_handlers[idx](file, line, function,
309 level, comp_conf, format, ap);
310 va_end(ap);
311 }
312 }
313
ucs_log_fatal_error(const char * format,...)314 void ucs_log_fatal_error(const char *format, ...)
315 {
316 size_t buffer_size = ucs_log_get_buffer_size();
317 FILE *stream = stderr;
318 char *buffer, *p;
319 va_list ap;
320 int ret;
321
322 buffer = ucs_alloca(buffer_size + 1);
323 p = buffer;
324
325 /* Print hostname:pid */
326 snprintf(p, buffer_size, "[%s:%-5d:%d:%d] ", ucs_log_hostname, ucs_log_pid,
327 ucs_log_get_thread_num(), ucs_get_tid());
328 buffer_size -= strlen(p);
329 p += strlen(p);
330
331 /* Print rest of the message */
332 va_start(ap, format);
333 vsnprintf(p, buffer_size, format, ap);
334 va_end(ap);
335 buffer_size -= strlen(p);
336 p += strlen(p);
337
338 /* Newline */
339 snprintf(p, buffer_size, "\n");
340
341 /* Flush stderr, and write the message directly to the pipe */
342 fflush(stream);
343 ret = write(fileno(stream), buffer, strlen(buffer));
344 (void)ret;
345 }
346
347 /**
348 * Print a bitmap as a list of ranges.
349 *
350 * @param n Number equivalent to the first bit in the bitmap.
351 * @param bitmap Compressed array of bits.
352 * @param length Number of bits in the bitmap.
353 */
ucs_log_bitmap_to_str(unsigned n,uint8_t * bitmap,size_t length)354 const char *ucs_log_bitmap_to_str(unsigned n, uint8_t *bitmap, size_t length)
355 {
356 static char buf[512] = {0};
357 int first, in_range;
358 unsigned prev = 0, end = 0;
359 char *p, *endp;
360 size_t i;
361
362 p = buf;
363 endp = buf + sizeof(buf) - 4;
364
365 first = 1;
366 in_range = 0;
367 for (i = 0; i < length; ++i) {
368 if (bitmap[i / 8] & UCS_BIT(i % 8)) {
369 if (first) {
370 p += snprintf(p, endp - p, "%d", n);
371 if (p > endp) {
372 goto overflow;
373 }
374 } else if (n == prev + 1) {
375 in_range = 1;
376 end = n;
377 } else {
378 if (in_range) {
379 p += snprintf(p, endp - p, "-%d", end);
380 if (p > endp) {
381 goto overflow;
382 }
383 }
384 in_range = 0;
385 p += snprintf(p, endp - p, ",%d", n);
386 if (p > endp) {
387 goto overflow;
388 }
389 }
390 first = 0;
391 prev = n;
392 }
393 ++n;
394 }
395 if (in_range) {
396 p += snprintf(p, endp - p, "-%d", end);
397 if (p > endp) {
398 goto overflow;
399 }
400 }
401 return buf;
402
403 overflow:
404 strcpy(p, "...");
405 return buf;
406 }
407
ucs_log_early_init()408 void ucs_log_early_init()
409 {
410 ucs_log_initialized = 0;
411 ucs_log_hostname[0] = 0;
412 ucs_log_pid = getpid();
413 ucs_log_file = NULL;
414 ucs_log_file_last_idx = 0;
415 ucs_log_file_close = 0;
416 threads_count = 0;
417 pthread_spin_init(&threads_lock, 0);
418 }
419
ucs_log_init()420 void ucs_log_init()
421 {
422 const char *next_token;
423
424 if (ucs_log_initialized) {
425 return;
426 }
427
428 ucs_log_initialized = 1; /* Set this to 1 immediately to avoid infinite recursion */
429
430 if (ucs_global_opts.log_file_size < ucs_log_get_buffer_size()) {
431 ucs_fatal("the maximal log file size (%zu) has to be >= %zu",
432 ucs_global_opts.log_file_size,
433 ucs_log_get_buffer_size());
434 }
435
436 if (ucs_global_opts.log_file_rotate > INT_MAX) {
437 ucs_fatal("the log file rotate (%u) has to be <= %d",
438 ucs_global_opts.log_file_rotate, INT_MAX);
439 }
440
441
442 strcpy(ucs_log_hostname, ucs_get_host_name());
443 ucs_log_file = stdout;
444 ucs_log_file_base_name = NULL;
445 ucs_log_file_close = 0;
446 ucs_log_file_last_idx = 0;
447
448 ucs_log_push_handler(ucs_log_default_handler);
449
450 if (strlen(ucs_global_opts.log_file) != 0) {
451 ucs_open_output_stream(ucs_global_opts.log_file, UCS_LOG_LEVEL_FATAL,
452 &ucs_log_file, &ucs_log_file_close,
453 &next_token, &ucs_log_file_base_name);
454 }
455 }
456
ucs_log_cleanup()457 void ucs_log_cleanup()
458 {
459 ucs_assert(ucs_log_initialized);
460
461 ucs_log_flush();
462 if (ucs_log_file_close) {
463 fclose(ucs_log_file);
464 }
465 pthread_spin_destroy(&threads_lock);
466
467 ucs_free(ucs_log_file_base_name);
468 ucs_log_file_base_name = NULL;
469 ucs_log_file = NULL;
470 ucs_log_file_last_idx = 0;
471 ucs_log_initialized = 0;
472 ucs_log_handlers_count = 0;
473 }
474
ucs_log_print_backtrace(ucs_log_level_t level)475 void ucs_log_print_backtrace(ucs_log_level_t level)
476 {
477 backtrace_h bckt;
478 backtrace_line_h bckt_line;
479 int i;
480 char buf[1024];
481 ucs_status_t status;
482
483 status = ucs_debug_backtrace_create(&bckt, 1);
484 if (status != UCS_OK) {
485 return;
486 }
487
488 ucs_log(level, "==== backtrace (tid:%7d) ====\n", ucs_get_tid());
489 for (i = 0; ucs_debug_backtrace_next(bckt, &bckt_line); ++i) {
490 ucs_debug_print_backtrace_line(buf, sizeof(buf), i, bckt_line);
491 ucs_log(level, "%s", buf);
492 }
493 ucs_log(level, "=================================\n");
494
495 ucs_debug_backtrace_destroy(bckt);
496 }
497