From f236c9e7f91f8844d004164d6202915a5c78e6d6 Mon Sep 17 00:00:00 2001 From: rl1987 Date: Sun, 18 Mar 2018 14:56:59 +0100 Subject: [PATCH 1/7] Introduce tor_assertf() to allow logging extra error message on assert failure With format string support! --- src/lib/log/util_bug.c | 17 ++++++++++++++--- src/lib/log/util_bug.h | 16 ++++++++++++---- 2 files changed, 26 insertions(+), 7 deletions(-) diff --git a/src/lib/log/util_bug.c b/src/lib/log/util_bug.c index f42d2d2ab4..93a460156d 100644 --- a/src/lib/log/util_bug.c +++ b/src/lib/log/util_bug.c @@ -70,14 +70,25 @@ tor_set_failed_assertion_callback(void (*fn)(void)) /** Helper for tor_assert: report the assertion failure. */ void tor_assertion_failed_(const char *fname, unsigned int line, - const char *func, const char *expr) + const char *func, const char *expr, + const char *fmt, ...) { char buf[256]; + char *extra = NULL; + va_list ap; + + if (fmt) { + va_start(ap,fmt); + tor_vasprintf(&extra, fmt, ap); + va_end(ap); + } + log_err(LD_BUG, "%s:%u: %s: Assertion %s failed; aborting.", fname, line, func, expr); tor_snprintf(buf, sizeof(buf), - "Assertion %s failed in %s at %s:%u", - expr, func, fname, line); + "Assertion %s failed in %s at %s:%u: %s", + expr, func, fname, line, extra ? extra : ""); + tor_free(extra); log_backtrace(LOG_ERR, LD_BUG, buf); } diff --git a/src/lib/log/util_bug.h b/src/lib/log/util_bug.h index 18d40bbf39..c0670a50a4 100644 --- a/src/lib/log/util_bug.h +++ b/src/lib/log/util_bug.h @@ -92,13 +92,20 @@ #define tor_assert(a) STMT_BEGIN \ (void)(a); \ STMT_END +#define tor_assertf(a, fmt, ...) STMT_BEGIN \ + (void)(a); \ + (void)(fmt); \ + STMT_END #else /** Like assert(3), but send assertion failures to the log as well as to * stderr. */ -#define tor_assert(expr) STMT_BEGIN \ +#define tor_assert(expr) tor_assertf(expr, NULL) + +#define tor_assertf(expr, fmt, ...) STMT_BEGIN \ if (ASSERT_PREDICT_LIKELY_(expr)) { \ } else { \ - tor_assertion_failed_(SHORT_FILE__, __LINE__, __func__, #expr); \ + tor_assertion_failed_(SHORT_FILE__, __LINE__, __func__, #expr, \ + fmt, ##__VA_ARGS__); \ abort(); \ } STMT_END #endif /* defined(TOR_UNIT_TESTS) && defined(DISABLE_ASSERTS_IN_UNIT_TESTS) */ @@ -106,7 +113,7 @@ #define tor_assert_unreached() \ STMT_BEGIN { \ tor_assertion_failed_(SHORT_FILE__, __LINE__, __func__, \ - "line should be unreached"); \ + "line should be unreached", NULL); \ abort(); \ } STMT_END @@ -221,7 +228,8 @@ #define tor_fragile_assert() tor_assert_nonfatal_unreached_once() void tor_assertion_failed_(const char *fname, unsigned int line, - const char *func, const char *expr); + const char *func, const char *expr, + const char *fmt, ...); void tor_bug_occurred_(const char *fname, unsigned int line, const char *func, const char *expr, int once); From b6813845cf3140475f72f1f52638fa04b44c3a1b Mon Sep 17 00:00:00 2001 From: rl1987 Date: Tue, 5 Mar 2019 16:37:14 +0200 Subject: [PATCH 2/7] Also add tor_assertf_nonfatal() --- src/lib/log/util_bug.c | 17 ++++++++++++++--- src/lib/log/util_bug.h | 28 ++++++++++++++++++++-------- 2 files changed, 34 insertions(+), 11 deletions(-) diff --git a/src/lib/log/util_bug.c b/src/lib/log/util_bug.c index 93a460156d..bbc744f0cc 100644 --- a/src/lib/log/util_bug.c +++ b/src/lib/log/util_bug.c @@ -96,7 +96,7 @@ tor_assertion_failed_(const char *fname, unsigned int line, void tor_bug_occurred_(const char *fname, unsigned int line, const char *func, const char *expr, - int once) + int once, const char *fmt, ...) { char buf[256]; const char *once_str = once ? @@ -116,11 +116,22 @@ tor_bug_occurred_(const char *fname, unsigned int line, add_captured_bug(expr); return; } + + va_list ap; + char *extra = NULL; + + if (fmt) { + va_start(ap,fmt); + tor_vasprintf(&extra, fmt, ap); + va_end(ap); + } + log_warn(LD_BUG, "%s:%u: %s: Non-fatal assertion %s failed.%s", fname, line, func, expr, once_str); tor_snprintf(buf, sizeof(buf), - "Non-fatal assertion %s failed in %s at %s:%u", - expr, func, fname, line); + "Non-fatal assertion %s failed in %s at %s:%u%s%s", + expr, func, fname, line, fmt ? " : " : "", extra); + tor_free(extra); } log_backtrace(LOG_WARN, LD_BUG, buf); diff --git a/src/lib/log/util_bug.h b/src/lib/log/util_bug.h index c0670a50a4..63c5309c98 100644 --- a/src/lib/log/util_bug.h +++ b/src/lib/log/util_bug.h @@ -143,6 +143,7 @@ #ifdef ALL_BUGS_ARE_FATAL #define tor_assert_nonfatal_unreached() tor_assert(0) #define tor_assert_nonfatal(cond) tor_assert((cond)) +#define tor_assertf_nonfatal(cond, fmt, ...) tor_assertf(cond, fmt, ...) #define tor_assert_nonfatal_unreached_once() tor_assert(0) #define tor_assert_nonfatal_once(cond) tor_assert((cond)) #define BUG(cond) \ @@ -153,24 +154,35 @@ #elif defined(TOR_UNIT_TESTS) && defined(DISABLE_ASSERTS_IN_UNIT_TESTS) #define tor_assert_nonfatal_unreached() STMT_NIL #define tor_assert_nonfatal(cond) ((void)(cond)) +#define tor_assertf_nonfatal(cond, fmt, ...) STMT_BEGIN \ + (void)cond; \ + (void)fmt; \ + STMT_END #define tor_assert_nonfatal_unreached_once() STMT_NIL #define tor_assert_nonfatal_once(cond) ((void)(cond)) #define BUG(cond) (ASSERT_PREDICT_UNLIKELY_(cond) ? 1 : 0) #else /* Normal case, !ALL_BUGS_ARE_FATAL, !DISABLE_ASSERTS_IN_UNIT_TESTS */ #define tor_assert_nonfatal_unreached() STMT_BEGIN \ - tor_bug_occurred_(SHORT_FILE__, __LINE__, __func__, NULL, 0); \ + tor_bug_occurred_(SHORT_FILE__, __LINE__, __func__, NULL, 0, NULL); \ STMT_END #define tor_assert_nonfatal(cond) STMT_BEGIN \ if (ASSERT_PREDICT_LIKELY_(cond)) { \ } else { \ - tor_bug_occurred_(SHORT_FILE__, __LINE__, __func__, #cond, 0); \ + tor_bug_occurred_(SHORT_FILE__, __LINE__, __func__, #cond, 0, NULL);\ + } \ + STMT_END +#define tor_assertf_nonfatal(cond, fmt, ...) STMT_BEGIN \ + if (ASSERT_PREDICT_UNLIKELY_(cond)) { \ + } else { \ + tor_bug_occurred_(SHORT_FILE__, __LINE__, __func__, #cond, 0, \ + fmt, ##__VA_ARGS__); \ } \ STMT_END #define tor_assert_nonfatal_unreached_once() STMT_BEGIN \ static int warning_logged__ = 0; \ if (!warning_logged__) { \ warning_logged__ = 1; \ - tor_bug_occurred_(SHORT_FILE__, __LINE__, __func__, NULL, 1); \ + tor_bug_occurred_(SHORT_FILE__, __LINE__, __func__, NULL, 1, NULL); \ } \ STMT_END #define tor_assert_nonfatal_once(cond) STMT_BEGIN \ @@ -178,12 +190,12 @@ if (ASSERT_PREDICT_LIKELY_(cond)) { \ } else if (!warning_logged__) { \ warning_logged__ = 1; \ - tor_bug_occurred_(SHORT_FILE__, __LINE__, __func__, #cond, 1); \ + tor_bug_occurred_(SHORT_FILE__, __LINE__, __func__, #cond, 1, NULL);\ } \ STMT_END #define BUG(cond) \ (ASSERT_PREDICT_UNLIKELY_(cond) ? \ - (tor_bug_occurred_(SHORT_FILE__,__LINE__,__func__,"!("#cond")",0), 1) \ + (tor_bug_occurred_(SHORT_FILE__,__LINE__,__func__,"!("#cond")",1,NULL),1) \ : 0) #endif /* defined(ALL_BUGS_ARE_FATAL) || ... */ @@ -195,7 +207,7 @@ if (bool_result && !var) { \ var = 1; \ tor_bug_occurred_(SHORT_FILE__, __LINE__, __func__, \ - "!("#cond")", 1); \ + "!("#cond")", 1, NULL); \ } \ bool_result; } )) #else /* !(defined(__GNUC__)) */ @@ -205,7 +217,7 @@ (var ? 1 : \ (var=1, \ tor_bug_occurred_(SHORT_FILE__, __LINE__, __func__, \ - "!("#cond")", 1), \ + "!("#cond")", 1, NULL), \ 1)) \ : 0) #endif /* defined(__GNUC__) */ @@ -232,7 +244,7 @@ void tor_assertion_failed_(const char *fname, unsigned int line, const char *fmt, ...); void tor_bug_occurred_(const char *fname, unsigned int line, const char *func, const char *expr, - int once); + int once, const char *fmt, ...); #ifdef _WIN32 #define SHORT_FILE__ (tor_fix_source_file(__FILE__)) From f66a17444e4a83e548985784956f321e9e1e1ab2 Mon Sep 17 00:00:00 2001 From: rl1987 Date: Tue, 5 Mar 2019 17:02:03 +0200 Subject: [PATCH 3/7] Silence compiler warnings --- src/lib/log/util_bug.c | 16 ++++++++++++++++ 1 file changed, 16 insertions(+) diff --git a/src/lib/log/util_bug.c b/src/lib/log/util_bug.c index bbc744f0cc..1ce48c0ebb 100644 --- a/src/lib/log/util_bug.c +++ b/src/lib/log/util_bug.c @@ -69,6 +69,7 @@ tor_set_failed_assertion_callback(void (*fn)(void)) /** Helper for tor_assert: report the assertion failure. */ void +CHECK_PRINTF(5, 6) tor_assertion_failed_(const char *fname, unsigned int line, const char *func, const char *expr, const char *fmt, ...) @@ -77,11 +78,18 @@ tor_assertion_failed_(const char *fname, unsigned int line, char *extra = NULL; va_list ap; +#ifdef __clang__ +#pragma clang diagnostic push +#pragma clang diagnostic ignored "-Wformat-nonliteral" +#endif if (fmt) { va_start(ap,fmt); tor_vasprintf(&extra, fmt, ap); va_end(ap); } +#ifdef __clang__ +#pragma clang diagnostic pop +#endif log_err(LD_BUG, "%s:%u: %s: Assertion %s failed; aborting.", fname, line, func, expr); @@ -94,6 +102,7 @@ tor_assertion_failed_(const char *fname, unsigned int line, /** Helper for tor_assert_nonfatal: report the assertion failure. */ void +CHECK_PRINTF(6, 7) tor_bug_occurred_(const char *fname, unsigned int line, const char *func, const char *expr, int once, const char *fmt, ...) @@ -120,11 +129,18 @@ tor_bug_occurred_(const char *fname, unsigned int line, va_list ap; char *extra = NULL; +#ifdef __clang__ +#pragma clang diagnostic push +#pragma clang diagnostic ignored "-Wformat-nonliteral" +#endif if (fmt) { va_start(ap,fmt); tor_vasprintf(&extra, fmt, ap); va_end(ap); } +#ifdef __clang__ +#pragma clang diagnostic pop +#endif log_warn(LD_BUG, "%s:%u: %s: Non-fatal assertion %s failed.%s", fname, line, func, expr, once_str); From a959d7cb98ed0e5b6e2fabf36301accd28f0641c Mon Sep 17 00:00:00 2001 From: rl1987 Date: Tue, 5 Mar 2019 17:58:31 +0200 Subject: [PATCH 4/7] Use tor_assertf{_nonfatal} in code --- src/core/or/circuituse.c | 4 +++- src/test/test_bt_cl.c | 2 +- src/test/testing_rsakeys.c | 3 ++- 3 files changed, 6 insertions(+), 3 deletions(-) diff --git a/src/core/or/circuituse.c b/src/core/or/circuituse.c index 2fdf6f7e8c..f77decf530 100644 --- a/src/core/or/circuituse.c +++ b/src/core/or/circuituse.c @@ -3117,7 +3117,9 @@ circuit_sent_valid_data(origin_circuit_t *circ, uint16_t relay_body_len) { if (!circ) return; - tor_assert_nonfatal(relay_body_len <= RELAY_PAYLOAD_SIZE); + tor_assertf_nonfatal(relay_body_len <= RELAY_PAYLOAD_SIZE, + "Wrong relay_body_len: %d (should be at most %d)", + relay_body_len, RELAY_PAYLOAD_SIZE); circ->n_delivered_written_circ_bw = tor_add_u32_nowrap(circ->n_delivered_written_circ_bw, relay_body_len); diff --git a/src/test/test_bt_cl.c b/src/test/test_bt_cl.c index 08b08ba423..b29c2c6cbc 100644 --- a/src/test/test_bt_cl.c +++ b/src/test/test_bt_cl.c @@ -46,7 +46,7 @@ crash(int x) *(volatile int *)0 = 0; #endif /* defined(__clang_analyzer__) || defined(__COVERITY__) */ } else if (crashtype == 1) { - tor_assert(1 == 0); + tor_assertf(1 == 0, "%d != %d", 1, 0); } else if (crashtype == -1) { ; } diff --git a/src/test/testing_rsakeys.c b/src/test/testing_rsakeys.c index 0f22d4e01b..8ba6bf9fe4 100644 --- a/src/test/testing_rsakeys.c +++ b/src/test/testing_rsakeys.c @@ -448,7 +448,8 @@ static int next_key_idx_2048; static crypto_pk_t * pk_generate_internal(int bits) { - tor_assert(bits == 2048 || bits == 1024); + tor_assertf(bits == 2048 || bits == 1024, + "Wrong key size: %d", bits); #ifdef USE_PREGENERATED_RSA_KEYS int *idxp; From bf953fe602a973259723dacb4389d3c4bee7e0a4 Mon Sep 17 00:00:00 2001 From: rl1987 Date: Tue, 5 Mar 2019 18:02:24 +0200 Subject: [PATCH 5/7] Add changes file --- changes/ticket29662 | 5 +++++ 1 file changed, 5 insertions(+) create mode 100644 changes/ticket29662 diff --git a/changes/ticket29662 b/changes/ticket29662 new file mode 100644 index 0000000000..872df9ad82 --- /dev/null +++ b/changes/ticket29662 @@ -0,0 +1,5 @@ + o Minor features (debugging): + - Introduce tor_assertf() and tor_assertf_nonfatal() to enable logging of + additional information during assert failure. Now we can use format + strings to include pieces of information that are relevant for trouble + shooting. Resolves ticket 29662. From 9c132a5f9e87a2cd0f59bd8d21226ba2256f7bce Mon Sep 17 00:00:00 2001 From: rl1987 Date: Fri, 22 Mar 2019 13:44:02 +0200 Subject: [PATCH 6/7] Refrain from using static buffer for assert failure message; call tor_asprintf() instead --- src/lib/log/util_bug.c | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/src/lib/log/util_bug.c b/src/lib/log/util_bug.c index 1ce48c0ebb..e5d5a2958c 100644 --- a/src/lib/log/util_bug.c +++ b/src/lib/log/util_bug.c @@ -74,7 +74,7 @@ tor_assertion_failed_(const char *fname, unsigned int line, const char *func, const char *expr, const char *fmt, ...) { - char buf[256]; + char *buf = NULL; char *extra = NULL; va_list ap; @@ -93,11 +93,11 @@ tor_assertion_failed_(const char *fname, unsigned int line, log_err(LD_BUG, "%s:%u: %s: Assertion %s failed; aborting.", fname, line, func, expr); - tor_snprintf(buf, sizeof(buf), - "Assertion %s failed in %s at %s:%u: %s", + tor_asprintf(&buf, "Assertion %s failed in %s at %s:%u: %s", expr, func, fname, line, extra ? extra : ""); tor_free(extra); log_backtrace(LOG_ERR, LD_BUG, buf); + tor_free(buf); } /** Helper for tor_assert_nonfatal: report the assertion failure. */ @@ -107,7 +107,7 @@ tor_bug_occurred_(const char *fname, unsigned int line, const char *func, const char *expr, int once, const char *fmt, ...) { - char buf[256]; + char *buf = NULL; const char *once_str = once ? " (Future instances of this warning will be silenced.)": ""; if (! expr) { @@ -144,12 +144,12 @@ tor_bug_occurred_(const char *fname, unsigned int line, log_warn(LD_BUG, "%s:%u: %s: Non-fatal assertion %s failed.%s", fname, line, func, expr, once_str); - tor_snprintf(buf, sizeof(buf), - "Non-fatal assertion %s failed in %s at %s:%u%s%s", + tor_asprintf(&buf, "Non-fatal assertion %s failed in %s at %s:%u%s%s", expr, func, fname, line, fmt ? " : " : "", extra); tor_free(extra); } log_backtrace(LOG_WARN, LD_BUG, buf); + tor_free(buf); #ifdef TOR_UNIT_TESTS if (failed_assertion_cb) { From 537ad0bca3479c10fc7d1093aff534be11800dcb Mon Sep 17 00:00:00 2001 From: rl1987 Date: Fri, 29 Mar 2019 18:38:27 +0200 Subject: [PATCH 7/7] Check for NULL in tor_assertf_nonfatal() --- src/lib/log/util_bug.c | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/lib/log/util_bug.c b/src/lib/log/util_bug.c index e5d5a2958c..b9dc296fc6 100644 --- a/src/lib/log/util_bug.c +++ b/src/lib/log/util_bug.c @@ -145,7 +145,8 @@ tor_bug_occurred_(const char *fname, unsigned int line, log_warn(LD_BUG, "%s:%u: %s: Non-fatal assertion %s failed.%s", fname, line, func, expr, once_str); tor_asprintf(&buf, "Non-fatal assertion %s failed in %s at %s:%u%s%s", - expr, func, fname, line, fmt ? " : " : "", extra); + expr, func, fname, line, fmt ? " : " : "", + extra ? extra : ""); tor_free(extra); } log_backtrace(LOG_WARN, LD_BUG, buf);