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..96b9c52c7 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); @@ -622,6 +622,15 @@ 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 + * 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. * @@ -630,6 +639,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) @@ -694,7 +704,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. @@ -733,7 +743,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/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.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..97f2bf456 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; @@ -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, ×tamp, sizeof(time_t)); - chunk += sizeof(time_t); + memcpy(chunk, timestamp, sizeof(struct timespec)); + chunk += sizeof(struct timespec); /* log message length */ msg_len_pt = chunk; @@ -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; } @@ -182,7 +217,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 +225,43 @@ 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; + 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; + 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; + return -EIO; } chunk = malloc(max_size); @@ -212,7 +273,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 +283,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 = -EIO; goto cleanup; } ptr = chunk; @@ -246,12 +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 = -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 = -EIO; #endif /* S_SPLINT_S */ goto cleanup; } @@ -261,22 +327,32 @@ 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); + 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) { - (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 = -EIO; #endif /* S_SPLINT_S */ goto cleanup; } @@ -302,4 +378,5 @@ qb_log_blackbox_print_from_file(const char *bb_filename) cleanup: qb_rb_close(instance); free(chunk); + return err; } 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..6a3480d8a 100644 --- a/lib/log_format.c +++ b/lib/log_format.c @@ -309,6 +309,7 @@ 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 * @@ -317,11 +318,12 @@ qb_log_target_format_static(int32_t target, const char * format, 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 +394,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 +404,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..a2ebf01ae 100644 --- a/lib/log_syslog.c +++ b/lib/log_syslog.c @@ -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..27a24b6fe 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, timestamp, 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..994bda962 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); @@ -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); /*