From 4a790522565657826098404e423906312063a9fe Mon Sep 17 00:00:00 2001 From: Christine Caulfield Date: Fri, 28 Sep 2018 13:48:14 +0100 Subject: [PATCH 1/7] log: Add high-resolution timestamps to log files --- examples/simplelog.c | 2 +- include/qb/qblog.h | 7 ++++--- lib/log.c | 8 ++++---- lib/log_blackbox.c | 2 +- lib/log_file.c | 2 +- lib/log_format.c | 20 ++++++++++++++++++-- lib/log_int.h | 6 +++--- lib/log_syslog.c | 4 ++-- lib/log_thread.c | 8 ++++---- tests/check_log.c | 4 ++-- 10 files changed, 40 insertions(+), 23 deletions(-) diff --git a/examples/simplelog.c b/examples/simplelog.c index eec00539e..cb256f902 100644 --- a/examples/simplelog.c +++ b/examples/simplelog.c @@ -113,7 +113,7 @@ my_tags_stringify(uint32_t tags) static void trace_logger(int32_t t, - struct qb_log_callsite *cs, time_t timestamp, const char *msg) + struct qb_log_callsite *cs, struct timespec *timestamp, const char *msg) { char output_buffer[QB_LOG_MAX_LEN]; output_buffer[0] = '\0'; diff --git a/include/qb/qblog.h b/include/qb/qblog.h index a2366fcb1..3d9c275f2 100644 --- a/include/qb/qblog.h +++ b/include/qb/qblog.h @@ -478,11 +478,11 @@ enum qb_log_filter_conf { typedef void (*qb_log_logger_fn)(int32_t t, struct qb_log_callsite *cs, - time_t timestamp, + struct timespec *timestamp, const char *msg); typedef void (*qb_log_vlogger_fn)(int32_t t, struct qb_log_callsite *cs, - time_t timestamp, + struct timespec *timestamp, va_list ap); typedef void (*qb_log_close_fn)(int32_t t); @@ -630,6 +630,7 @@ void qb_log_tags_stringify_fn_set(qb_log_tags_stringify_fn fn); * %l FILELINE * %p PRIORITY * %t TIMESTAMP + * %T TIMESTAMP with milliseconds * %b BUFFER * %g TAGS * %N name (passed into qb_log_init) @@ -733,7 +734,7 @@ int32_t qb_log_target_user_data_set(int32_t t, void *user_data); */ void qb_log_target_format(int32_t target, struct qb_log_callsite *cs, - time_t timestamp, + struct timespec *timestamp, const char* formatted_message, char *output_buffer); diff --git a/lib/log.c b/lib/log.c index 952c42753..8ab6aa8c0 100644 --- a/lib/log.c +++ b/lib/log.c @@ -274,7 +274,7 @@ qb_log_real_va_(struct qb_log_callsite *cs, va_list ap) } else if (t->vlogger) { va_copy(ap_copy, ap); - t->vlogger(t->pos, cs, tv.tv_sec, ap_copy); + t->vlogger(t->pos, cs, &tv, ap_copy); va_end(ap_copy); } else if (t->logger) { @@ -283,13 +283,13 @@ qb_log_real_va_(struct qb_log_callsite *cs, va_list ap) formatted = QB_TRUE; } qb_do_extended(str, t->extended, - t->logger(t->pos, cs, tv.tv_sec, str)); + t->logger(t->pos, cs, &tv, str)); } } } if (found_threaded) { - qb_log_thread_log_post(cs, tv.tv_sec, str); + qb_log_thread_log_post(cs, &tv, str); } qb_atomic_int_set(&in_logger, QB_FALSE); @@ -310,7 +310,7 @@ qb_log_real_(struct qb_log_callsite *cs, ...) void qb_log_thread_log_write(struct qb_log_callsite *cs, - time_t timestamp, const char *buffer) + struct timespec *timestamp, const char *buffer) { struct qb_log_target *t; enum qb_log_target_slot pos; diff --git a/lib/log_blackbox.c b/lib/log_blackbox.c index f9f90fb86..de9074eaf 100644 --- a/lib/log_blackbox.c +++ b/lib/log_blackbox.c @@ -53,7 +53,7 @@ _blackbox_reload(int32_t target) */ static void _blackbox_vlogger(int32_t target, - struct qb_log_callsite *cs, time_t timestamp, va_list ap) + struct qb_log_callsite *cs, struct timespec *timestamp, va_list ap) { size_t max_size; size_t actual_size; diff --git a/lib/log_file.c b/lib/log_file.c index 8019a405d..eff54628d 100644 --- a/lib/log_file.c +++ b/lib/log_file.c @@ -23,7 +23,7 @@ static void _file_logger(int32_t t, - struct qb_log_callsite *cs, time_t timestamp, const char *msg) + struct qb_log_callsite *cs, struct timespec *timestamp, const char *msg) { char buffer[QB_LOG_MAX_LEN]; char *output_buffer = buffer; diff --git a/lib/log_format.c b/lib/log_format.c index d02690b89..d7b5d8423 100644 --- a/lib/log_format.c +++ b/lib/log_format.c @@ -309,19 +309,22 @@ qb_log_target_format_static(int32_t target, const char * format, * %l FILELINE * %p PRIORITY * %t TIMESTAMP + * %T TIMESTAMP with milliseconds * %b BUFFER * %g SUBSYSTEM * * any number between % and character specify field length to pad or chop */ + void qb_log_target_format(int32_t target, struct qb_log_callsite *cs, - time_t current_time, + struct timespec *the_ts, const char *formatted_message, char *output_buffer) { char tmp_buf[128]; struct tm tm_res; + time_t time_sec; unsigned int format_buffer_idx = 0; unsigned int output_buffer_idx = 0; size_t cutoff; @@ -392,7 +395,8 @@ qb_log_target_format(int32_t target, break; case 't': - (void)localtime_r(¤t_time, &tm_res); + time_sec = the_ts->tv_sec; + (void)localtime_r(&time_sec, &tm_res); snprintf(tmp_buf, TIME_STRING_SIZE, "%s %02d %02d:%02d:%02d", log_month_name[tm_res.tm_mon], @@ -401,6 +405,18 @@ qb_log_target_format(int32_t target, p = tmp_buf; break; + case 'T': + time_sec = the_ts->tv_sec; + (void)localtime_r(&time_sec, &tm_res); + snprintf(tmp_buf, TIME_STRING_SIZE, + "%s %02d %02d:%02d:%02d.%03lld", + log_month_name[tm_res.tm_mon], + tm_res.tm_mday, tm_res.tm_hour, + tm_res.tm_min, tm_res.tm_sec, + the_ts->tv_nsec/QB_TIME_NS_IN_MSEC); + p = tmp_buf; + break; + case 'b': p = formatted_message; break; diff --git a/lib/log_int.h b/lib/log_int.h index ef8811703..9ae818fa6 100644 --- a/lib/log_int.h +++ b/lib/log_int.h @@ -66,7 +66,7 @@ struct qb_log_filter { struct qb_log_record { struct qb_log_callsite *cs; - time_t timestamp; + struct timespec timestamp; char *buffer; struct qb_list_head list; }; @@ -114,10 +114,10 @@ int32_t qb_log_blackbox_open(struct qb_log_target *t); void qb_log_thread_stop(void); void qb_log_thread_log_post(struct qb_log_callsite *cs, - time_t current_time, + struct timespec *current_time, const char *buffer); void qb_log_thread_log_write(struct qb_log_callsite *cs, - time_t current_time, + struct timespec *current_time, const char *buffer); void qb_log_thread_pause(struct qb_log_target *t); void qb_log_thread_resume(struct qb_log_target *t); diff --git a/lib/log_syslog.c b/lib/log_syslog.c index 14f3f9e7a..d2ced8697 100644 --- a/lib/log_syslog.c +++ b/lib/log_syslog.c @@ -1,4 +1,4 @@ -/* +* * Copyright (C) 2011 Red Hat, Inc. * * All rights reserved. @@ -32,7 +32,7 @@ static void _syslog_logger(int32_t target, - struct qb_log_callsite *cs, time_t timestamp, const char *msg) + struct qb_log_callsite *cs, struct timespec *timestamp, const char *msg) { char buffer[QB_LOG_MAX_LEN]; char *output_buffer = buffer; diff --git a/lib/log_thread.c b/lib/log_thread.c index de96ba8e1..ac146dcc5 100644 --- a/lib/log_thread.c +++ b/lib/log_thread.c @@ -97,7 +97,7 @@ qb_logt_worker_thread(void *data) printf("%d messages lost\n", dropped); } - qb_log_thread_log_write(rec->cs, rec->timestamp, rec->buffer); + qb_log_thread_log_write(rec->cs, &rec->timestamp, rec->buffer); (void)qb_thread_unlock(logt_wthread_lock); free(rec->buffer); @@ -216,7 +216,7 @@ qb_log_thread_resume(struct qb_log_target *t) void qb_log_thread_log_post(struct qb_log_callsite *cs, - time_t timestamp, const char *buffer) + struct timespec *timestamp, const char *buffer) { struct qb_log_record *rec; size_t buf_size; @@ -237,7 +237,7 @@ qb_log_thread_log_post(struct qb_log_callsite *cs, } memcpy(rec->buffer, buffer, buf_size); - rec->timestamp = timestamp; + memcpy(&rec->timestamp, ×tamp, sizeof(struct timespec)); qb_list_init(&rec->list); (void)qb_thread_lock(logt_wthread_lock); @@ -289,7 +289,7 @@ qb_log_thread_stop(void) strlen(rec->buffer) - sizeof(struct qb_log_record) - 1; - qb_log_thread_log_write(rec->cs, rec->timestamp, + qb_log_thread_log_write(rec->cs, &rec->timestamp, rec->buffer); (void)qb_thread_unlock(logt_wthread_lock); free(rec->buffer); diff --git a/tests/check_log.c b/tests/check_log.c index a3f987606..91a485dfb 100644 --- a/tests/check_log.c +++ b/tests/check_log.c @@ -202,7 +202,7 @@ static size_t last_length; static void _test_logger(int32_t t, struct qb_log_callsite *cs, - time_t timestamp, const char *msg) + struct timespec *timestamp, const char *msg) { test_buf[0] = '\0'; qb_log_target_format(t, cs, timestamp, msg, test_buf); @@ -214,7 +214,7 @@ _test_logger(int32_t t, static void _test_length_logger(int32_t t, struct qb_log_callsite *cs, - time_t timestamp, const char *msg) + struct timespec *timestamp, const char *msg) { strcpy(test_buf, msg); qb_log_target_format(t, cs, timestamp, msg, test_buf); From 48d7d79e15d8201a3bbc6c7b75acb2d59cf92851 Mon Sep 17 00:00:00 2001 From: Christine Caulfield Date: Mon, 1 Oct 2018 12:26:47 +0100 Subject: [PATCH 2/7] test: Test log timestamps --- tests/check_log.c | 34 ++++++++++++++++++++++++++++++++++ 1 file changed, 34 insertions(+) diff --git a/tests/check_log.c b/tests/check_log.c index 91a485dfb..166894337 100644 --- a/tests/check_log.c +++ b/tests/check_log.c @@ -344,6 +344,38 @@ START_TEST(test_file_logging) } END_TEST +START_TEST(test_timestamps) +{ + int32_t t; + int32_t rc; + int a,b,c,d; + + qb_log_init("test", LOG_USER, LOG_EMERG); + qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_ENABLED, QB_FALSE); + + t = qb_log_custom_open(_test_logger, NULL, NULL, NULL); + rc = qb_log_filter_ctl(t, QB_LOG_FILTER_ADD, + QB_LOG_FILTER_FILE, "*", LOG_INFO); + ck_assert_int_eq(rc, 0); + + /* normal timestamp */ + qb_log_format_set(t, "%t %b"); + rc = qb_log_ctl(t, QB_LOG_CONF_ENABLED, QB_TRUE); + ck_assert_int_eq(rc, 0); + + qb_log(LOG_INFO, "The time now is (see left)"); + rc = sscanf(test_buf+7, "%d:%d:%d.%d", &a, &b, &c, &d); + ck_assert_int_eq(rc, 3); + + /* millisecond timestamp */ + qb_log_format_set(t, "%T %b"); + qb_log(LOG_INFO, "The time now is precisely (see left)"); + rc = sscanf(test_buf+7, "%d:%d:%d.%d", &a, &b, &c, &d); + ck_assert_int_eq(rc, 4); +} +END_TEST + + START_TEST(test_line_length) { int32_t t; @@ -1069,6 +1101,7 @@ log_suite(void) #ifdef HAVE_PTHREAD_SETSCHEDPARAM add_tcase(s, tc, test_threaded_logging_bad_sched_params); #endif + add_tcase(s, tc, test_timestamps); add_tcase(s, tc, test_extended_information); add_tcase(s, tc, test_zero_tags); /* @@ -1097,3 +1130,4 @@ main(void) srunner_free(sr); return (number_failed == 0) ? EXIT_SUCCESS : EXIT_FAILURE; } + From a3d9e533cbf5a697974507549a00dd46badecf0d Mon Sep 17 00:00:00 2001 From: Christine Caulfield Date: Thu, 18 Oct 2018 10:49:38 +0100 Subject: [PATCH 3/7] check: Splint is *very* stupid Plus some misc tidying --- lib/Makefile.am | 13 +++++++++---- lib/log_format.c | 1 - lib/log_syslog.c | 2 +- tests/check_log.c | 1 - 4 files changed, 10 insertions(+), 7 deletions(-) diff --git a/lib/Makefile.am b/lib/Makefile.am index 3fc036b88..e56a062c0 100644 --- a/lib/Makefile.am +++ b/lib/Makefile.am @@ -123,10 +123,15 @@ ALL_LINT_FLAGS = $(DEFS) $(DEFAULT_INCLUDES) $(INCLUDES) $(DEB_INCLUDES) \ $(libqb_la_CPPFLAGS) $(CPPFLAGS) $(AM_CPPFLAGS) \ $(LINT_FLAGS) # expected for the time being (but SHOULD be fixed eventually): -# ipc_setup.c: (in function qb_ipcc_us_setup_connect) -# ipc_setup.c:479:2: Return value (type int32_t) ignored: qb_ipc_us_ready(... -# ipc_setup.c:494:2: Return value (type int32_t) ignored: qb_ipc_auth_cred... -SPLINT_SUMMARY_EXP = " 2 code warnings" +# ipc_setup.c: (in function qb_ipcc_us_setup_connect) +# ipc_setup.c:479:2: Return value (type int32_t) ignored: qb_ipc_us_ready(... +# ipc_setup.c:494:2: Return value (type int32_t) ignored: qb_ipc_auth_cred... +# splint is stupid: +# log_format.c:397:22: Arrow access field of non-struct or union pointer (struct +# log_format.c:408:22: Arrow access field of non-struct or union pointer (struct +# log_format.c:415:13: Arrow access field of non-struct or union pointer (struct + +SPLINT_SUMMARY_EXP = " 5 code warnings" run_splint.sh: $(top_srcdir)/configure.ac @echo '$(SPLINT) $(ALL_LINT_FLAGS) \' > $@-t diff --git a/lib/log_format.c b/lib/log_format.c index d7b5d8423..6a3480d8a 100644 --- a/lib/log_format.c +++ b/lib/log_format.c @@ -315,7 +315,6 @@ qb_log_target_format_static(int32_t target, const char * format, * * any number between % and character specify field length to pad or chop */ - void qb_log_target_format(int32_t target, struct qb_log_callsite *cs, diff --git a/lib/log_syslog.c b/lib/log_syslog.c index d2ced8697..a2ebf01ae 100644 --- a/lib/log_syslog.c +++ b/lib/log_syslog.c @@ -1,4 +1,4 @@ -* +/* * Copyright (C) 2011 Red Hat, Inc. * * All rights reserved. diff --git a/tests/check_log.c b/tests/check_log.c index 166894337..994bda962 100644 --- a/tests/check_log.c +++ b/tests/check_log.c @@ -1130,4 +1130,3 @@ main(void) srunner_free(sr); return (number_failed == 0) ? EXIT_SUCCESS : EXIT_FAILURE; } - From aa6bc9f208c0374f1812d1e0f3c6865e9e8d526d Mon Sep 17 00:00:00 2001 From: Christine Caulfield Date: Fri, 26 Oct 2018 12:35:59 +0100 Subject: [PATCH 4/7] log: Add a feature-test macro for hi-res timestamps There is otherwise no straightforward way for an application to know if hi-res timestamps are implemented --- include/qb/qblog.h | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/include/qb/qblog.h b/include/qb/qblog.h index 3d9c275f2..42eaa4ea6 100644 --- a/include/qb/qblog.h +++ b/include/qb/qblog.h @@ -622,6 +622,13 @@ int32_t qb_log_filter_fn_set(qb_log_filter_fn fn); */ void qb_log_tags_stringify_fn_set(qb_log_tags_stringify_fn fn); + +/* This is a Feature Test macro so that calling applications know that + * millisdecond timestamps are implemented. Because %T a string in + * function call withn an indirect effect, there is no easy test for it + * beyond the library version (which is a ver blunt instrument) + */ +#define QB_FEATURE_LOG_HIRES_TIMESTAMPS 1 /** * Set the format specifiers. * From 6bfba48d0987c48ff36de58c0b0e7ade3a1ed6a1 Mon Sep 17 00:00:00 2001 From: Christine Caulfield Date: Mon, 29 Oct 2018 09:59:07 +0000 Subject: [PATCH 5/7] log: Fix threaded logging and blackbox timestamps --- lib/log_blackbox.c | 2 +- lib/log_thread.c | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/log_blackbox.c b/lib/log_blackbox.c index de9074eaf..590f18825 100644 --- a/lib/log_blackbox.c +++ b/lib/log_blackbox.c @@ -102,7 +102,7 @@ _blackbox_vlogger(int32_t target, chunk += fn_size; /* timestamp */ - memcpy(chunk, ×tamp, sizeof(time_t)); + memcpy(chunk, timestamp, sizeof(time_t)); chunk += sizeof(time_t); /* log message length */ diff --git a/lib/log_thread.c b/lib/log_thread.c index ac146dcc5..27a24b6fe 100644 --- a/lib/log_thread.c +++ b/lib/log_thread.c @@ -237,7 +237,7 @@ qb_log_thread_log_post(struct qb_log_callsite *cs, } memcpy(rec->buffer, buffer, buf_size); - memcpy(&rec->timestamp, ×tamp, sizeof(struct timespec)); + memcpy(&rec->timestamp, timestamp, sizeof(struct timespec)); qb_list_init(&rec->list); (void)qb_thread_lock(logt_wthread_lock); From e53201d81375687a072f52d7cf96226c5669a532 Mon Sep 17 00:00:00 2001 From: Christine Caulfield Date: Mon, 29 Oct 2018 12:32:11 +0000 Subject: [PATCH 6/7] blackbox: Add hi-res timestamps to blackbox. I'm going to do anothe patch to add to this that makes qb_blackbox backwards compatible with old BB files, so this new file format is interim. --- include/qb/qblog.h | 2 +- lib/log_blackbox.c | 39 +++++++++++++++++++++++++-------------- 2 files changed, 26 insertions(+), 15 deletions(-) diff --git a/include/qb/qblog.h b/include/qb/qblog.h index 42eaa4ea6..d93da7355 100644 --- a/include/qb/qblog.h +++ b/include/qb/qblog.h @@ -702,7 +702,7 @@ ssize_t qb_log_blackbox_write_to_file(const char *filename); /** * Read the blackbox for file and print it out. */ -void qb_log_blackbox_print_from_file(const char* filename); +int qb_log_blackbox_print_from_file(const char* filename); /** * Open a custom log target. diff --git a/lib/log_blackbox.c b/lib/log_blackbox.c index 590f18825..e369a05b2 100644 --- a/lib/log_blackbox.c +++ b/lib/log_blackbox.c @@ -69,7 +69,7 @@ _blackbox_vlogger(int32_t target, fn_size = strlen(cs->function) + 1; - actual_size = 4 * sizeof(uint32_t) + sizeof(uint8_t) + fn_size + sizeof(time_t); + actual_size = 4 * sizeof(uint32_t) + sizeof(uint8_t) + fn_size + sizeof(struct timespec); max_size = actual_size + t->max_line_length; chunk = qb_rb_chunk_alloc(t->instance, max_size); @@ -102,8 +102,8 @@ _blackbox_vlogger(int32_t target, chunk += fn_size; /* timestamp */ - memcpy(chunk, timestamp, sizeof(time_t)); - chunk += sizeof(time_t); + memcpy(chunk, timestamp, sizeof(struct timespec)); + chunk += sizeof(struct timespec); /* log message length */ msg_len_pt = chunk; @@ -182,7 +182,7 @@ qb_log_blackbox_write_to_file(const char *filename) return written_size; } -void +int qb_log_blackbox_print_from_file(const char *bb_filename) { qb_ringbuffer_t *instance; @@ -190,17 +190,18 @@ qb_log_blackbox_print_from_file(const char *bb_filename) int max_size = 2 * QB_LOG_MAX_LEN; char *chunk; int fd; + int err = 0; char time_buf[64]; fd = open(bb_filename, 0); if (fd < 0) { qb_util_perror(LOG_ERR, "qb_log_blackbox_print_from_file"); - return; + return -1; } instance = qb_rb_create_from_file(fd, 0); close(fd); if (instance == NULL) { - return; + return -1; } chunk = malloc(max_size); @@ -212,7 +213,8 @@ qb_log_blackbox_print_from_file(const char *bb_filename) uint32_t fn_size; char *function; uint32_t len; - time_t timestamp; + struct timespec timestamp; + time_t time_sec; uint32_t msg_len; struct tm *tm; char message[QB_LOG_MAX_LEN]; @@ -221,10 +223,12 @@ qb_log_blackbox_print_from_file(const char *bb_filename) if (bytes_read >= 0 && bytes_read < BB_MIN_ENTRY_SIZE) { printf("ERROR Corrupt file: blackbox header too small.\n"); + err = -1; goto cleanup; } else if (bytes_read < 0) { errno = -bytes_read; perror("ERROR: qb_rb_chunk_read failed"); + err = -1; goto cleanup; } ptr = chunk; @@ -246,12 +250,14 @@ qb_log_blackbox_print_from_file(const char *bb_filename) if ((fn_size + BB_MIN_ENTRY_SIZE) > bytes_read) { #ifndef S_SPLINT_S printf("ERROR Corrupt file: fn_size way too big %" PRIu32 "\n", fn_size); + err = -1; #endif /* S_SPLINT_S */ goto cleanup; } if (fn_size <= 0) { #ifndef S_SPLINT_S printf("ERROR Corrupt file: fn_size negative %" PRIu32 "\n", fn_size); + err = -1; #endif /* S_SPLINT_S */ goto cleanup; } @@ -261,22 +267,26 @@ qb_log_blackbox_print_from_file(const char *bb_filename) ptr += fn_size; /* timestamp size & content */ - memcpy(×tamp, ptr, sizeof(time_t)); - ptr += sizeof(time_t); - tm = localtime(×tamp); + memcpy(×tamp, ptr, sizeof(struct timespec)); + ptr += sizeof(struct timespec); + time_sec = timestamp.tv_sec; + + tm = localtime(&time_sec); if (tm) { - (void)strftime(time_buf, - sizeof(time_buf), "%b %d %T", - tm); + int slen = strftime(time_buf, + sizeof(time_buf), "%b %d %T", + tm); + snprintf(time_buf+slen, sizeof(time_buf - slen), ".%03lld", (timestamp.tv_nsec/QB_TIME_NS_IN_MSEC)); } else { snprintf(time_buf, sizeof(time_buf), "%ld", - (long int)timestamp); + (long int)time_sec); } /* message length */ memcpy(&msg_len, ptr, sizeof(uint32_t)); if (msg_len > QB_LOG_MAX_LEN || msg_len <= 0) { #ifndef S_SPLINT_S printf("ERROR Corrupt file: msg_len out of bounds %" PRIu32 "\n", msg_len); + err = -1; #endif /* S_SPLINT_S */ goto cleanup; } @@ -302,4 +312,5 @@ qb_log_blackbox_print_from_file(const char *bb_filename) cleanup: qb_rb_close(instance); free(chunk); + return err; } From c1c75500dd1430bfdb477f6356b80795939cf8b9 Mon Sep 17 00:00:00 2001 From: Christine Caulfield Date: Mon, 29 Oct 2018 16:35:02 +0000 Subject: [PATCH 7/7] blackbox: Allow qb-blackbox to read new and old blackbox files --- include/qb/qblog.h | 10 +++--- lib/log_blackbox.c | 88 ++++++++++++++++++++++++++++++++++++++++------ 2 files changed, 83 insertions(+), 15 deletions(-) diff --git a/include/qb/qblog.h b/include/qb/qblog.h index d93da7355..96b9c52c7 100644 --- a/include/qb/qblog.h +++ b/include/qb/qblog.h @@ -623,12 +623,14 @@ int32_t qb_log_filter_fn_set(qb_log_filter_fn fn); void qb_log_tags_stringify_fn_set(qb_log_tags_stringify_fn fn); -/* This is a Feature Test macro so that calling applications know that - * millisdecond timestamps are implemented. Because %T a string in - * function call withn an indirect effect, there is no easy test for it - * beyond the library version (which is a ver blunt instrument) +/** + *This is a Feature Test macro so that calling applications know that + * millisecond timestamps are implemented. Because %T a string in + * function call with an indirect effect, there is no easy test for it + * beyond the library version (which is a very blunt instrument) */ #define QB_FEATURE_LOG_HIRES_TIMESTAMPS 1 + /** * Set the format specifiers. * diff --git a/lib/log_blackbox.c b/lib/log_blackbox.c index e369a05b2..97f2bf456 100644 --- a/lib/log_blackbox.c +++ b/lib/log_blackbox.c @@ -161,19 +161,54 @@ qb_log_blackbox_open(struct qb_log_target *t) return 0; } +/* + * This is designed to look as much like the ringbuffer header + * as possible so that we can distinguish an old RB dump + * from a new one with this header. + */ + +struct _blackbox_file_header { + uint32_t word_size; + uint32_t read_pt; + uint32_t write_pt; + uint32_t version; + uint32_t hash; +} __attribute__((packed)); + +/* Values we expect for a 'new' header */ +#define QB_BLACKBOX_HEADER_WORDSIZE 0 +#define QB_BLACKBOX_HEADER_READPT 0xCCBBCCBB +#define QB_BLACKBOX_HEADER_WRITEPT 0xBBCCBBCC +#define QB_BLACKBOX_HEADER_VERSION 2 +#define QB_BLACKBOX_HEADER_HASH 0 + ssize_t qb_log_blackbox_write_to_file(const char *filename) { ssize_t written_size = 0; struct qb_log_target *t; + struct _blackbox_file_header header; int fd = open(filename, O_CREAT | O_RDWR, 0700); if (fd < 0) { return -errno; } + + /* Write header, so we know this is a 'new' format blackbox */ + header.word_size = QB_BLACKBOX_HEADER_WORDSIZE; + header.read_pt = QB_BLACKBOX_HEADER_READPT; + header.write_pt = QB_BLACKBOX_HEADER_WRITEPT; + header.version = QB_BLACKBOX_HEADER_VERSION; + header.hash = QB_BLACKBOX_HEADER_HASH; + written_size = write(fd, &header, sizeof(header)); + if (written_size < sizeof(header)) { + close(fd); + return written_size; + } + t = qb_log_target_get(QB_LOG_BLACKBOX); if (t->instance) { - written_size = qb_rb_write_to_file(t->instance, fd); + written_size += qb_rb_write_to_file(t->instance, fd); } else { written_size = -ENOENT; } @@ -191,17 +226,42 @@ qb_log_blackbox_print_from_file(const char *bb_filename) char *chunk; int fd; int err = 0; + int saved_errno; + struct _blackbox_file_header header; + int have_timespecs = 0; char time_buf[64]; fd = open(bb_filename, 0); if (fd < 0) { + saved_errno = errno; qb_util_perror(LOG_ERR, "qb_log_blackbox_print_from_file"); - return -1; + return -saved_errno; + } + + /* Read the header. If it looks like one of ours then + we know we have hi-res timestamps */ + err = read(fd, &header, sizeof(header)); + if (err < sizeof(header)) { + saved_errno = errno; + close(fd); + return -saved_errno; + } + + if (header.word_size == QB_BLACKBOX_HEADER_WORDSIZE && + header.read_pt == QB_BLACKBOX_HEADER_READPT && + header.write_pt == QB_BLACKBOX_HEADER_WRITEPT && + header.version == QB_BLACKBOX_HEADER_VERSION && + header.hash == QB_BLACKBOX_HEADER_HASH) { + have_timespecs = 1; + } else { + lseek(fd, 0, SEEK_SET); } + + instance = qb_rb_create_from_file(fd, 0); close(fd); if (instance == NULL) { - return -1; + return -EIO; } chunk = malloc(max_size); @@ -228,7 +288,7 @@ qb_log_blackbox_print_from_file(const char *bb_filename) } else if (bytes_read < 0) { errno = -bytes_read; perror("ERROR: qb_rb_chunk_read failed"); - err = -1; + err = -EIO; goto cleanup; } ptr = chunk; @@ -250,14 +310,14 @@ qb_log_blackbox_print_from_file(const char *bb_filename) if ((fn_size + BB_MIN_ENTRY_SIZE) > bytes_read) { #ifndef S_SPLINT_S printf("ERROR Corrupt file: fn_size way too big %" PRIu32 "\n", fn_size); - err = -1; + err = -EIO; #endif /* S_SPLINT_S */ goto cleanup; } if (fn_size <= 0) { #ifndef S_SPLINT_S printf("ERROR Corrupt file: fn_size negative %" PRIu32 "\n", fn_size); - err = -1; + err = -EIO; #endif /* S_SPLINT_S */ goto cleanup; } @@ -267,16 +327,22 @@ qb_log_blackbox_print_from_file(const char *bb_filename) ptr += fn_size; /* timestamp size & content */ - memcpy(×tamp, ptr, sizeof(struct timespec)); - ptr += sizeof(struct timespec); - time_sec = timestamp.tv_sec; + if (have_timespecs) { + memcpy(×tamp, ptr, sizeof(struct timespec)); + ptr += sizeof(struct timespec); + time_sec = timestamp.tv_sec; + } else { + memcpy(&time_sec, ptr, sizeof(time_t)); + ptr += sizeof(time_t); + timestamp.tv_nsec = 0LL; + } tm = localtime(&time_sec); if (tm) { int slen = strftime(time_buf, sizeof(time_buf), "%b %d %T", tm); - snprintf(time_buf+slen, sizeof(time_buf - slen), ".%03lld", (timestamp.tv_nsec/QB_TIME_NS_IN_MSEC)); + snprintf(time_buf+slen, sizeof(time_buf - slen), ".%03lld", timestamp.tv_nsec/QB_TIME_NS_IN_MSEC); } else { snprintf(time_buf, sizeof(time_buf), "%ld", (long int)time_sec); @@ -286,7 +352,7 @@ qb_log_blackbox_print_from_file(const char *bb_filename) if (msg_len > QB_LOG_MAX_LEN || msg_len <= 0) { #ifndef S_SPLINT_S printf("ERROR Corrupt file: msg_len out of bounds %" PRIu32 "\n", msg_len); - err = -1; + err = -EIO; #endif /* S_SPLINT_S */ goto cleanup; }