From 5dadb2eb04d1ed4b10efcf410a7fd46ad0c1c2c1 Mon Sep 17 00:00:00 2001 From: "E. Madison Bray" <676149+embray@users.noreply.github.com> Date: Wed, 14 Oct 2026 18:33:11 +0200 Subject: [PATCH 1/8] fix: lower some of these scalar type inference logs from DEBUG to TRACE When debug logging is enabled these messages produce the vast majority of noise, for practically every value read from the YAML. I don't have a well-articulated policy for when to use TRACE vs DEBUG, but I feel that DEBUG should still be informative to users while TRACE is strictly for the lowest-level info mostly for debugging the library, as opposed to debugging *uses* of the library, if that makes sense... --- src/value.c | 18 +++++++++--------- 1 file changed, 9 insertions(+), 9 deletions(-) diff --git a/src/value.c b/src/value.c index 0079d11d..822a2b39 100644 --- a/src/value.c +++ b/src/value.c @@ -1461,7 +1461,7 @@ static asdf_value_err_t asdf_value_infer_extension_type(asdf_value_t *value) { // TODO: Possibly enable the case of implicit extensions based on path return ASDF_VALUE_ERR_TYPE_MISMATCH; - ASDF_LOG(value->file, ASDF_LOG_DEBUG, "inferring value as extension type for %s", tag); + ASDF_LOG(value->file, ASDF_LOG_TRACE, "inferring value as extension type for %s", tag); const asdf_extension_t *ext = asdf_extension_get(value->file, tag); if (!ext) @@ -1793,7 +1793,7 @@ static asdf_value_err_t asdf_value_infer_scalar_type(asdf_value_t *value) { if (tag != ASDF_YAML_COMMON_TAG_UNKNOWN) { ASDF_LOG( value->file, - ASDF_LOG_DEBUG, + ASDF_LOG_TRACE, "inferring value type from YAML Common Schema tag: %s", tag_str); } @@ -1830,7 +1830,7 @@ static asdf_value_err_t asdf_value_infer_scalar_type(asdf_value_t *value) { /* Untagged -> core schema heuristics (plain style only) */ if (ASDF_VALUE_OK == asdf_value_infer_null(value, scalar, len)) { - ASDF_LOG(value->file, ASDF_LOG_DEBUG, "inferred %.*s as null", len, scalar); + ASDF_LOG(value->file, ASDF_LOG_TRACE, "inferred %.*s as null", len, scalar); return ASDF_VALUE_OK; } @@ -1840,15 +1840,15 @@ static asdf_value_err_t asdf_value_infer_scalar_type(asdf_value_t *value) { #ifdef ASDF_LOG_ENABLED if (ASDF_VALUE_ERR_OVERFLOW == err) ASDF_LOG( - value->file, ASDF_LOG_DEBUG, "inferred %.*s as int (with overflow)", len, scalar); + value->file, ASDF_LOG_TRACE, "inferred %.*s as int (with overflow)", len, scalar); else - ASDF_LOG(value->file, ASDF_LOG_DEBUG, "inferred %.*s as int", len, scalar); + ASDF_LOG(value->file, ASDF_LOG_TRACE, "inferred %.*s as int", len, scalar); #endif return err; } if (ASDF_VALUE_OK == asdf_value_infer_bool(value, scalar, len)) { - ASDF_LOG(value->file, ASDF_LOG_DEBUG, "inferred %.*s as bool", len, scalar); + ASDF_LOG(value->file, ASDF_LOG_TRACE, "inferred %.*s as bool", len, scalar); return ASDF_VALUE_OK; } @@ -1858,15 +1858,15 @@ static asdf_value_err_t asdf_value_infer_scalar_type(asdf_value_t *value) { #ifdef ASDF_LOG_ENABLED if (ASDF_VALUE_ERR_OVERFLOW == err) ASDF_LOG( - value->file, ASDF_LOG_DEBUG, "inferred %.*s as float (with overflow)", len, scalar); + value->file, ASDF_LOG_TRACE, "inferred %.*s as float (with overflow)", len, scalar); else - ASDF_LOG(value->file, ASDF_LOG_DEBUG, "inferred %.*s as float", len, scalar); + ASDF_LOG(value->file, ASDF_LOG_TRACE, "inferred %.*s as float", len, scalar); #endif return err; } /* Otherwise treat as a string */ - ASDF_LOG(value->file, ASDF_LOG_DEBUG, "inferred %.*s as string", len, scalar); + ASDF_LOG(value->file, ASDF_LOG_TRACE, "inferred %.*s as string", len, scalar); value->type = ASDF_VALUE_STRING; value->err = ASDF_VALUE_OK; return ASDF_VALUE_OK; From fd7e4a2f5d02ae0728a6fed2a2c8adb8f3aa8b5a Mon Sep 17 00:00:00 2001 From: "E. Madison Bray" <676149+embray@users.noreply.github.com> Date: Wed, 14 Oct 2026 18:40:12 +0200 Subject: [PATCH 2/8] fix: flush the stream after each log message is written especially important if the underlying stream is buffered, so that log messages don't get lost, or come out clumped together. --- src/log.c | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/log.c b/src/log.c index 1afa8d33..4e8e97b4 100644 --- a/src/log.c +++ b/src/log.c @@ -103,6 +103,7 @@ static void asdf_log_impl( vfprintf(stream, fmt, args); fputc('\n', stream); + fflush(stream); return; } #endif @@ -126,6 +127,7 @@ static void asdf_log_impl( vfprintf(stream, fmt, args); fputc('\n', stream); + fflush(stream); } From ec38416c8c3d1da3cd8d3cfded839291c8ed393d Mon Sep 17 00:00:00 2001 From: "E. Madison Bray" <676149+embray@users.noreply.github.com> Date: Wed, 14 Oct 2026 19:20:24 +0200 Subject: [PATCH 3/8] tests: add new logging tests; clean up log capture in tests Add several new tests for the logging system, especially some regression tests for bugs that need to be fixed (errno saving, tty color handling, malformatting of messages when certain fields are disabled). Several existing tests that tested for specific log messages each used some different mechanisms for capturing the log. This standardizes that as well into a single log capture utility (though hopefully this will be less needed once gh-279 is implemented). --- tests/CMakeLists.txt | 4 +- tests/Makefile.am | 11 ++ tests/test-event.c | 15 +-- tests/test-log.c | 252 +++++++++++++++++++++++++++++++++++++++++++ tests/test-ndarray.c | 20 +--- tests/test-parser.c | 15 ++- tests/util.c | 26 +++++ tests/util.h | 29 +++++ 8 files changed, 341 insertions(+), 31 deletions(-) create mode 100644 tests/test-log.c diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index b5674481..5a3a1973 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -72,7 +72,9 @@ target_include_directories(run-dir SYSTEM PRIVATE ${STATGRAB_INCLUDEDIR}) target_link_directories(run-dir PRIVATE ${STATGRAB_LIBDIR}) target_link_libraries(run-dir PRIVATE util ${STATGRAB_LIBRARIES}) -set(runtime "WITH_CMAKE=set:YES;OBJC_DISABLE_INITIALIZE_FORK_SAFETY=set:YES;srcdir=set:${CMAKE_CURRENT_SOURCE_DIR};top_srcdir=set:${CMAKE_SOURCE_DIR};top_builddir=set:${CMAKE_BINARY_DIR};LD_LIBRARY_PATH=path_list_prepend:${CMAKE_BINARY_DIR}/src") +# ASDF_LOG_LEVEL/ASDF_LOG_COLOR are cleared so a developer's settings can't +# change test outcomes; tests that exercise them set them explicitly +set(runtime "ASDF_LOG_LEVEL=unset:;ASDF_LOG_COLOR=unset:;WITH_CMAKE=set:YES;OBJC_DISABLE_INITIALIZE_FORK_SAFETY=set:YES;srcdir=set:${CMAKE_CURRENT_SOURCE_DIR};top_srcdir=set:${CMAKE_SOURCE_DIR};top_builddir=set:${CMAKE_BINARY_DIR};LD_LIBRARY_PATH=path_list_prepend:${CMAKE_BINARY_DIR}/src") set(sanitizer_options "ASAN_OPTIONS=detect_leaks=1:suppressions=${CMAKE_CURRENT_SOURCE_DIR}/libfyaml.asan.supp;LSAN_OPTIONS=suppressions=${CMAKE_CURRENT_SOURCE_DIR}/libfyaml.lsan.supp") diff --git a/tests/Makefile.am b/tests/Makefile.am index de1ecada..bf9b5146 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -35,6 +35,7 @@ unit_tests = \ test-event.unit \ test-extension.unit \ test-file.unit \ + test-log.unit \ test-ndarray.unit \ test-parse-util.unit \ test-parser.unit \ @@ -52,6 +53,9 @@ unit_tests = \ # check_PROGRAMS (built by `make check`) but not in TESTS. check_PROGRAMS = $(unit_tests) run-dir +# Clear libasdf's logging environment variables so a developer's settings +# can't change test outcomes; tests that exercise them set them explicitly +AM_TESTS_ENVIRONMENT = unset ASDF_LOG_LEVEL ASDF_LOG_COLOR; TESTS_ENVIRONMENT = top_builddir=$(top_builddir) top_srcdir=$(top_srcdir) if UBSAN @@ -177,6 +181,13 @@ test_file_unit_CFLAGS = $(unit_test_cflags) test_file_unit_LDFLAGS = $(unit_test_ldflags) test_file_unit_LDADD = $(unit_test_ldadd) +# test-log.unit +test_log_unit_SOURCES = test-log.c +test_log_unit_CPPFLAGS = $(unit_test_cppflags) +test_log_unit_CFLAGS = $(unit_test_cflags) +test_log_unit_LDFLAGS = $(unit_test_ldflags) +test_log_unit_LDADD = $(unit_test_ldadd) + # test-ndarray.unit test_ndarray_unit_SOURCES = test-ndarray.c test_ndarray_unit_CPPFLAGS = $(unit_test_cppflags) diff --git a/tests/test-event.c b/tests/test-event.c index 4e9d4324..f7cebc97 100644 --- a/tests/test-event.c +++ b/tests/test-event.c @@ -489,12 +489,11 @@ MU_TEST(basic_buffer_yaml) { MU_TEST(test_asdf_event_summary) { const char *filename = get_reference_file_path("1.6.0/basic.asdf"); - const char *log_file = get_temp_file_path(fixture->tempfile_prefix, ".log"); - FILE *log_stream = fopen(log_file, "w"); - assert_not_null(log_stream); + log_capture_t cap = {0}; + assert_true(log_capture_open(&cap)); asdf_log_cfg_t log_config = { .level = ASDF_LOG_TRACE, .fields = ASDF_LOG_FIELD_ALL ^ ASDF_LOG_FIELD_LINE, - .stream = log_stream, .no_color = true}; + .stream = cap.stream, .no_color = true}; asdf_parser_cfg_t parser_cfg = {.flags = ASDF_PARSER_OPT_EMIT_YAML_EVENTS, .log=&log_config}; asdf_parser_t *parser = asdf_parser_create(&parser_cfg); @@ -502,9 +501,11 @@ MU_TEST(test_asdf_event_summary) { assert_int(asdf_parser_set_input_file(parser, filename), ==, 0); while (asdf_event_iterate(parser)); asdf_parser_destroy(parser); - fclose(log_stream); - const char *expected_log_file = get_fixture_file_path("events/basic.log"); - assert_true(compare_files(log_file, expected_log_file)); + char *expected = read_file(get_fixture_file_path("events/basic.log"), NULL); + assert_not_null(expected); + assert_string_equal(log_capture_text(&cap), expected); + free(expected); + log_capture_close(&cap); return MUNIT_OK; } diff --git a/tests/test-log.c b/tests/test-log.c new file mode 100644 index 00000000..0aa7f616 --- /dev/null +++ b/tests/test-log.c @@ -0,0 +1,252 @@ +#include +#include +#include +#include +#include +#include +#include + +#include "asdf/file.h" +#include "asdf/log.h" + +#include "config.h" + +#include "munit.h" +#include "util.h" + + +#define ANSI_ESCAPE "\033[" + + +/* + * Open an in-memory file logging with the given configuration to ``stream`` + */ +static asdf_file_t *open_with_log(asdf_log_cfg_t log_cfg, FILE *stream) { + asdf_config_t config = {0}; + config.log = log_cfg; + config.log.stream = stream; + return asdf_open_mem_ex(NULL, 0, &config); +} + + +/* + * An explicitly configured log level takes precedence over ASDF_LOG_LEVEL, + * including when it equals the built-in default (WARN) + */ +MU_TEST(level_explicit_overrides_env) { + asdf_log_cfg_t log_cfg = {.level = ASDF_LOG_WARN, .fields = ASDF_LOG_FIELD_MSG}; + log_capture_t cap = {0}; + assert_true(log_capture_open(&cap)); + + setenv("ASDF_LOG_LEVEL", "DEBUG", 1); + asdf_file_t *file = open_with_log(log_cfg, cap.stream); + unsetenv("ASDF_LOG_LEVEL"); + assert_not_null(file); + + asdf_file_log(file, ASDF_LOG_INFO, "src.c", 1, "info"); + asdf_file_log(file, ASDF_LOG_WARN, "src.c", 2, "warn"); + assert_string_equal(log_capture_text(&cap), "warn\n"); + asdf_close(file); + log_capture_close(&cap); + return MUNIT_OK; +} + + +/* + * ASDF_LOG_LEVEL=NONE in the environment disables logging entirely + */ +MU_TEST(level_env_none) { + asdf_log_cfg_t log_cfg = {0}; + log_capture_t cap = {0}; + assert_true(log_capture_open(&cap)); + + setenv("ASDF_LOG_LEVEL", "NONE", 1); + asdf_file_t *file = open_with_log(log_cfg, cap.stream); + unsetenv("ASDF_LOG_LEVEL"); + assert_not_null(file); + + asdf_file_log(file, ASDF_LOG_FATAL, "src.c", 1, "fatal"); + assert_string_equal(log_capture_text(&cap), ""); + asdf_close(file); + log_capture_close(&cap); + return MUNIT_OK; +} + + +/* + * Messages with a level that is not a real severity are dropped rather than + * looked up out of bounds + */ +MU_TEST(message_level_out_of_range) { + asdf_log_cfg_t log_cfg = {.level = ASDF_LOG_TRACE, .fields = ASDF_LOG_FIELD_ALL}; + log_capture_t cap = {0}; + assert_true(log_capture_open(&cap)); + asdf_file_t *file = open_with_log(log_cfg, cap.stream); + assert_not_null(file); + + asdf_file_log(file, ASDF_LOG_NONE, "src.c", 1, "none"); + asdf_file_log(file, (asdf_log_level_t)ASDF_LOG_NUM_LEVELS, "src.c", 2, "too high"); + assert_string_equal(log_capture_text(&cap), ""); + asdf_close(file); + log_capture_close(&cap); + return MUNIT_OK; +} + + +/* + * Logging a message does not clobber errno + */ +MU_TEST(errno_preserved) { + asdf_log_cfg_t log_cfg = {.level = ASDF_LOG_WARN}; + log_capture_t cap = {0}; + assert_true(log_capture_open(&cap)); + asdf_file_t *file = open_with_log(log_cfg, cap.stream); + assert_not_null(file); + + errno = ERANGE; + asdf_file_log(file, ASDF_LOG_ERROR, "src.c", 1, "message"); + assert_int(errno, ==, ERANGE); + asdf_close(file); + log_capture_close(&cap); + return MUNIT_OK; +} + + +/* + * Each combination of log fields is separated by exactly one space, with no + * color codes since the stream is not a terminal (regression test). + */ +MU_TEST(fields_format) { + struct { + asdf_log_fields_t fields; + const char *expected; + } cases[] = { + {ASDF_LOG_FIELD_ALL, "[ERROR] (" PACKAGE_NAME ")src.c:12: message\n"}, + {ASDF_LOG_FIELD_LEVEL | ASDF_LOG_FIELD_MSG, "[ERROR] message\n"}, + {ASDF_LOG_FIELD_FILE | ASDF_LOG_FIELD_LINE | ASDF_LOG_FIELD_MSG, "src.c:12: message\n"}, + {ASDF_LOG_FIELD_MSG, "message\n"}, + {ASDF_LOG_FIELD_LEVEL | ASDF_LOG_FIELD_FILE, "[ERROR] src.c:\n"}, + }; + log_capture_t cap = {0}; + + for (size_t idx = 0; idx < sizeof(cases) / sizeof(cases[0]); idx++) { + asdf_log_cfg_t log_cfg = {.level = ASDF_LOG_WARN, .fields = cases[idx].fields}; + assert_true(log_capture_open(&cap)); + asdf_file_t *file = open_with_log(log_cfg, cap.stream); + assert_not_null(file); + asdf_file_log(file, ASDF_LOG_ERROR, "src.c", 12, "message"); + assert_string_equal(log_capture_text(&cap), cases[idx].expected); + asdf_close(file); + log_capture_close(&cap); + } + + return MUNIT_OK; +} + + +/* + * Log one message to ``stream`` with the given ``no_color`` setting and + * ASDF_LOG_COLOR value (NULL to leave it unset), returning whether it was + * colorized + * + * ``read_fd`` is where the output can be read back from: the master side of a + * pseudo-terminal, or -1 to read it from ``cap`` instead. + */ +static bool log_is_colored( + FILE *stream, int read_fd, log_capture_t *cap, bool no_color, const char *env_color) { + asdf_log_cfg_t log_cfg = {.level = ASDF_LOG_WARN, .no_color = no_color}; + char buf[512] = {0}; + const char *text = buf; + + if (env_color) + setenv("ASDF_LOG_COLOR", env_color, 1); + + asdf_file_t *file = open_with_log(log_cfg, stream); + unsetenv("ASDF_LOG_COLOR"); + assert_not_null(file); + asdf_file_log(file, ASDF_LOG_ERROR, "src.c", 1, "message"); + asdf_close(file); + + if (read_fd >= 0) + assert_int(read(read_fd, buf, sizeof(buf) - 1), >, 0); + else + text = log_capture_text(cap); + + return strstr(text, ANSI_ESCAPE) != NULL; +} + + +/* + * Color is decided by the stream being a terminal, ``no_color``, and the + * ASDF_LOG_COLOR environment variable (which overrides both); builds without + * color support never colorize + */ +MU_TEST(color_not_tty) { + log_capture_t cap = {0}; + bool colored = false; + + assert_true(log_capture_open(&cap)); + colored = log_is_colored(cap.stream, -1, &cap, false, NULL); + log_capture_close(&cap); + assert_false(colored); + + assert_true(log_capture_open(&cap)); + colored = log_is_colored(cap.stream, -1, &cap, true, "1"); + log_capture_close(&cap); +#ifdef ASDF_LOG_COLOR + assert_true(colored); +#else + assert_false(colored); +#endif + + assert_true(log_capture_open(&cap)); + colored = log_is_colored(cap.stream, -1, &cap, false, "0"); + log_capture_close(&cap); + assert_false(colored); + return MUNIT_OK; +} + + +MU_TEST(color_tty) { + int master_fd = posix_openpt(O_RDWR | O_NOCTTY); + + if (master_fd < 0 || grantpt(master_fd) != 0 || unlockpt(master_fd) != 0) { + if (master_fd >= 0) + close(master_fd); + return MUNIT_SKIP; + } + + int slave_fd = open(ptsname(master_fd), O_RDWR | O_NOCTTY); + assert_int(slave_fd, >=, 0); + FILE *stream = fdopen(slave_fd, "w"); + assert_not_null(stream); + +#ifdef ASDF_LOG_COLOR + assert_true(log_is_colored(stream, master_fd, NULL, false, NULL)); + assert_true(log_is_colored(stream, master_fd, NULL, true, "1")); +#else + assert_false(log_is_colored(stream, master_fd, NULL, false, NULL)); + assert_false(log_is_colored(stream, master_fd, NULL, true, "1")); +#endif + assert_false(log_is_colored(stream, master_fd, NULL, true, NULL)); + assert_false(log_is_colored(stream, master_fd, NULL, false, "0")); + + fclose(stream); + close(master_fd); + return MUNIT_OK; +} + + +MU_TEST_SUITE( + logging, + MU_RUN_TEST(level_explicit_overrides_env), + MU_RUN_TEST(level_env_none), + MU_RUN_TEST(message_level_out_of_range), + MU_RUN_TEST(errno_preserved), + MU_RUN_TEST(fields_format), + MU_RUN_TEST(color_not_tty), + MU_RUN_TEST(color_tty) +); + + +MU_RUN_SUITE(logging); diff --git a/tests/test-ndarray.c b/tests/test-ndarray.c index 832e9917..3e9e2c67 100644 --- a/tests/test-ndarray.c +++ b/tests/test-ndarray.c @@ -975,16 +975,11 @@ MU_TEST(ndarray_inline_warning_thresh) { memset(data, 0, (size_t)shape[0]); asdf_ndarray_storage_set(&ndarray, ASDF_ARRAY_STORAGE_INLINE); - /* Redirect warnings to a temp log file. get_temp_file_path returns a - * static buffer, so duplicate the path before calling it again. */ - const char *log_path_tmp = get_temp_file_path(fixture->tempfile_prefix, ".log"); - char *log_path = strdup(log_path_tmp); - assert_not_null(log_path); - FILE *log_stream = fopen(log_path, "w"); - assert_not_null(log_stream); + log_capture_t cap = {0}; + assert_true(log_capture_open(&cap)); asdf_config_t config = { - .log = {.stream = log_stream, .level = ASDF_LOG_WARN, .no_color = true}, + .log = {.stream = cap.stream, .level = ASDF_LOG_WARN, .no_color = true}, .emitter = {.inline_ndarray_warning_thresh = 99} }; asdf_file_t *file = asdf_open_mem_ex(NULL, 0, &config); @@ -997,16 +992,11 @@ MU_TEST(ndarray_inline_warning_thresh) { const char *out_path = get_temp_file_path(fixture->tempfile_prefix, "-thresh.asdf"); assert_int(asdf_write_to(file, out_path), ==, 0); asdf_close(file); - fclose(log_stream); asdf_ndarray_data_dealloc(&ndarray); /* Verify that the warning was written to the log */ - size_t log_len = 0; - char *log_content = read_file(log_path, &log_len); - free(log_path); - assert_not_null(log_content); - assert_not_null(strstr(log_content, "exceeding the threshold of 99")); - free(log_content); + assert_not_null(strstr(log_capture_text(&cap), "exceeding the threshold of 99")); + log_capture_close(&cap); return MUNIT_OK; } diff --git a/tests/test-parser.c b/tests/test-parser.c index 2bb625f3..78f096a0 100644 --- a/tests/test-parser.c +++ b/tests/test-parser.c @@ -191,17 +191,15 @@ static char *capture_parse_log(const char *filename, asdf_log_level_t level, boo (void)had_error; return NULL; #else - char *log_buf = NULL; - size_t log_size = 0; - FILE *log_stream = open_memstream(&log_buf, &log_size); + log_capture_t cap = {0}; - if (!log_stream) - munit_error("failed to open memstream for log capture"); + if (!log_capture_open(&cap)) + munit_error("failed to open log capture"); // Only the message text, so the assertions below don't depend on the // source location or on whether color is enabled asdf_log_cfg_t log_cfg = { - .stream = log_stream, + .stream = cap.stream, .level = level, .fields = ASDF_LOG_FIELD_MSG, .no_color = true}; @@ -218,8 +216,9 @@ static char *capture_parse_log(const char *filename, asdf_log_level_t level, boo *had_error = asdf_parser_has_error(parser); asdf_parser_destroy(parser); - fclose(log_stream); - return log_buf; + char *log = strdup(log_capture_text(&cap)); + log_capture_close(&cap); + return log; #endif } diff --git a/tests/util.c b/tests/util.c index 97b0af15..4882154d 100644 --- a/tests/util.c +++ b/tests/util.c @@ -437,3 +437,29 @@ bool compare_files(const char *filename_a, const char *filename_b) { free(contents_b); return ret; } + + +bool log_capture_open(log_capture_t *cap) { + cap->buf = NULL; + cap->size = 0; + cap->stream = open_memstream(&cap->buf, &cap->size); + return cap->stream != NULL; +} + + +const char *log_capture_text(log_capture_t *cap) { + // Deliberately not flushed here: libasdf flushes after every message, so + // reading the buffer without flushing also checks that it does + return cap->buf ? cap->buf : ""; +} + + +void log_capture_close(log_capture_t *cap) { + if (cap->stream) + fclose(cap->stream); + + free(cap->buf); + cap->stream = NULL; + cap->buf = NULL; + cap->size = 0; +} diff --git a/tests/util.h b/tests/util.h index 2ac83f6d..7d4122a9 100644 --- a/tests/util.h +++ b/tests/util.h @@ -1,6 +1,9 @@ +#pragma once + #include #include #include +#include #ifndef REFERENCE_FILES_DIR #error "REFERENCE_FILES_DIR not defined" @@ -23,3 +26,29 @@ char *read_file(const char *filename, size_t *out_len); char *tail_file(const char *filename, uint32_t skip, size_t *out_len); /** Compare the contents of two files byte-for-byte */ bool compare_files(const char *filename_a, const char *filename_b); + + +/** + * In-memory capture of libasdf log output + * + * Pass ``stream`` as the ``stream`` of an `asdf_log_cfg_t`. The stream is not + * a terminal, so the captured text has no color codes unless color is forced + * on with ``ASDF_LOG_COLOR=1``. + */ +typedef struct { + FILE *stream; + char *buf; + size_t size; +} log_capture_t; + +/** Open a log capture; returns false if the stream could not be opened */ +bool log_capture_open(log_capture_t *cap); +/** + * Return the text logged so far (always NUL-terminated, possibly empty) + * + * The stream is not flushed first; this relies on libasdf flushing after each + * message. + */ +const char *log_capture_text(log_capture_t *cap); +/** Close the capture stream and free the captured text */ +void log_capture_close(log_capture_t *cap); From 0cc30f8feb8a0268c9702803ca0722a241e5ddd7 Mon Sep 17 00:00:00 2001 From: "E. Madison Bray" <676149+embray@users.noreply.github.com> Date: Wed, 14 Oct 2026 19:41:57 +0200 Subject: [PATCH 4/8] fix: several logging bugs surfaced while trying to integrate into SE++ Trying to integrate libasdf's logging mechanism into a separate application like SourceXtractor++ (see gh-24) surfaced a number of small bugs and necessary enhancements. What it really wants is a new structured logging interface as explained in gh-279. However, with or without that these bugs are all relevant, even just for libasdf itself. The details are listed in the changelog fragment. --- abi/libasdf-x86_64.abi | 47 ++++++------- changes/+logging-fixes.bugfix | 26 +++++++ docs/usage/opening.rst | 6 +- include/asdf/log.h | 43 ++++++++++-- src/context.c | 9 +-- src/file.c | 2 +- src/log.c | 124 +++++++++++++++++++++++++--------- src/log.h | 9 +++ tests/test-log.c | 52 +++++++++++++- 9 files changed, 246 insertions(+), 72 deletions(-) create mode 100644 changes/+logging-fixes.bugfix diff --git a/abi/libasdf-x86_64.abi b/abi/libasdf-x86_64.abi index 8a7f57b4..94666e36 100644 --- a/abi/libasdf-x86_64.abi +++ b/abi/libasdf-x86_64.abi @@ -396,7 +396,7 @@ - + @@ -458,13 +458,14 @@ - + + @@ -1198,6 +1199,7 @@ + @@ -1299,7 +1301,6 @@ - @@ -1307,7 +1308,7 @@ - + @@ -1623,7 +1624,7 @@ - + @@ -1756,7 +1757,7 @@ - + @@ -1815,7 +1816,7 @@ - + @@ -1877,7 +1878,7 @@ - + @@ -2162,7 +2163,7 @@ - + @@ -2230,7 +2231,7 @@ - + @@ -2298,7 +2299,7 @@ - + @@ -2364,7 +2365,7 @@ - + @@ -2406,7 +2407,7 @@ - + @@ -2418,7 +2419,7 @@ - + @@ -2436,7 +2437,7 @@ - + @@ -2835,7 +2836,7 @@ - + @@ -2846,7 +2847,7 @@ - + @@ -2859,7 +2860,7 @@ - + @@ -2917,7 +2918,7 @@ - + @@ -2937,13 +2938,13 @@ - + - + @@ -3728,7 +3729,7 @@ - + @@ -3742,7 +3743,7 @@ - + diff --git a/changes/+logging-fixes.bugfix b/changes/+logging-fixes.bugfix new file mode 100644 index 00000000..69110d7c --- /dev/null +++ b/changes/+logging-fixes.bugfix @@ -0,0 +1,26 @@ +Several fixes to logging: + +- Setting `asdf_log_cfg_t.level` to `ASDF_LOG_NONE` now disables logging. + Previously ``ASDF_LOG_NONE`` was ``0``, the same as an unset level, so it + selected the default level instead. The default is now the new + ``ASDF_LOG_DEFAULT=0``, implying to use the global default (`ASDF_LOG_WARN`) + and `ASDF_LOG_NONE` is higher than every message severity. + + This also fixes building with ``--with-log-default=NONE`` (or + ``-DLOG_DEFAULT=NONE``), which logged everything instead of nothing. +- Explicitly setting `asdf_log_cfg_t.level` to `ASDF_LOG_WARN` was + treated as unset, so the ``ASDF_LOG_LEVEL`` environment variable took + precedence over it. +- Log output is colorized only when the stream is a terminal, rather than + always in builds with color support, which wrote escape codes into log + files and pipes. The new ``ASDF_LOG_COLOR`` environment variable forces + color on (``1``) or off (``0``). +- Fixed doubled or trailing spaces in log lines when some of the log fields + are disabled. +- The log stream is flushed after every message, so messages are not lost or + delayed when it is buffered. +- Logging no longer clobbers ``errno``. +- ``asdf_file_log`` with an invalid level no longer reads out of bounds; the + message is dropped. +- Lowered the very frequent YAML scalar type inference messages from ``DEBUG`` + to ``TRACE``, so ``DEBUG`` logging is no longer dominated by them. diff --git a/docs/usage/opening.rst b/docs/usage/opening.rst index cdcf4091..1dbfbf10 100644 --- a/docs/usage/opening.rst +++ b/docs/usage/opening.rst @@ -156,8 +156,10 @@ Messages are emitted only if their severity meets the configured the destination defaults to ``stderr``, the included fields to `ASDF_LOG_FIELD_ALL`, and the level to the value of the ``ASDF_LOG_LEVEL`` environment variable (one of ``NONE``, ``TRACE``, ``DEBUG``, ``INFO``, -``WARN``, ``ERROR``, ``FATAL``), or ``WARN`` if it is unset. This makes it -possible to raise the log level of an application without recompiling it:: +``WARN``, ``ERROR``, ``FATAL``), or ``WARN`` if it is unset. Setting the level +to ``ASDF_LOG_NONE`` disables logging for the file. Leaving the level unset +makes it possible to raise the log level of an application without +recompiling it:: ASDF_LOG_LEVEL=debug ./my-program observation.asdf diff --git a/include/asdf/log.h b/include/asdf/log.h index 5e7b6472..b0180bd2 100644 --- a/include/asdf/log.h +++ b/include/asdf/log.h @@ -8,13 +8,21 @@ * be provided up front through the ``log`` field of `asdf_config_t` when opening * a file with `asdf_open_ex`. Messages at or above the configured * `asdf_log_level_t` are written to the configured stream (``stderr`` by - * default), optionally colorized and with a configurable set of prefix fields. + * default), with a configurable set of prefix fields. The stream is flushed + * after every message. * * If no level is set explicitly the default is taken from the ``ASDF_LOG_LEVEL`` * environment variable (one of ``NONE``, ``TRACE``, ``DEBUG``, ``INFO``, * ``WARN``, ``ERROR``, or ``FATAL``, case-insensitive), falling back to * ``WARN``. * + * When the build supports color, output is colorized only if the stream is a + * terminal and `asdf_log_cfg_t.no_color` is not set. The ``ASDF_LOG_COLOR`` + * environment variable overrides both: ``ASDF_LOG_COLOR=1`` forces color on + * (even when the stream is not a terminal) and ``ASDF_LOG_COLOR=0`` forces it + * off; any other value is ignored. Builds without color support ignore it. + * The environment is read once, when a file is opened. + * * The library's own internal log statements are compiled in only when libasdf * is built with logging enabled (the default; disable with ``-DENABLE_LOG=NO`` * under CMake or ``--disable-logging`` under the Autotools build). The public @@ -38,11 +46,19 @@ * Severity levels for log messages, in increasing order of severity * * A configured level acts as a threshold: only messages at that level or higher - * are emitted. `ASDF_LOG_NONE` disables logging entirely. + * are emitted. `ASDF_LOG_NONE` is higher than every message severity, so as a + * threshold it disables logging entirely. */ typedef enum { - /** Emit no messages */ - ASDF_LOG_NONE = 0, + /** + * Use the default level: the value of the ``ASDF_LOG_LEVEL`` environment + * variable if set, otherwise ``ASDF_LOG_DEFAULT_LEVEL`` (``ASDF_LOG_WARN`` + * unless libasdf was built with a different default) + * + * This is the zero value, so it is what a zero-initialized + * `asdf_log_cfg_t` selects. It is not a message severity. + */ + ASDF_LOG_DEFAULT = 0, /** Very fine-grained tracing messages */ ASDF_LOG_TRACE, /** Debugging messages */ @@ -55,9 +71,17 @@ typedef enum { ASDF_LOG_ERROR, /** Fatal, unrecoverable errors */ ASDF_LOG_FATAL, + /** Emit no messages; only meaningful as a threshold, not a severity */ + ASDF_LOG_NONE, } asdf_log_level_t; -/** The number of distinct `asdf_log_level_t` values */ +/** + * One past the highest message severity (`ASDF_LOG_FATAL`) + * + * Message severities are the values from `ASDF_LOG_TRACE` up to, but not + * including, this. It does not count `ASDF_LOG_NONE`, which is a threshold + * only. + */ #define ASDF_LOG_NUM_LEVELS (ASDF_LOG_FATAL + 1) @@ -111,7 +135,8 @@ typedef uint64_t asdf_log_fields_t; * to control logging for a file. Any field left zero-initialized is filled in * with a default: the stream defaults to ``stderr``, the level to the value of * the ``ASDF_LOG_LEVEL`` environment variable (or ``ASDF_LOG_WARN``), and the - * fields to `ASDF_LOG_FIELD_ALL`. + * fields to `ASDF_LOG_FIELD_ALL`. Set ``level`` to `ASDF_LOG_NONE` to disable + * logging for the file. */ typedef struct { /** Destination stream for log output (defaults to ``stderr``) */ @@ -126,7 +151,11 @@ typedef struct { * enabled / disabled; see `asdf_log_field_t`. */ asdf_log_fields_t fields; - /** Disable colorized output even when the build supports it */ + /** + * Disable colorized output even when the build supports it and ``stream`` + * is a terminal (output to any other stream is not colorized by default); + * overridden by the ``ASDF_LOG_COLOR`` environment variable + */ bool no_color; } asdf_log_cfg_t; diff --git a/src/context.c b/src/context.c index f667b906..ba7d400d 100644 --- a/src/context.c +++ b/src/context.c @@ -12,7 +12,7 @@ static atomic_bool global_ctx_initialized = false; static asdf_log_cfg_t asdf_context_log_config_default = { - .stream = NULL, .level = ASDF_LOG_NONE, .no_color = false}; + .stream = NULL, .level = ASDF_LOG_DEFAULT, .no_color = false}; asdf_context_t *asdf_context_create(const asdf_log_cfg_t *log_config) { @@ -28,11 +28,12 @@ asdf_context_t *asdf_context_create(const asdf_log_cfg_t *log_config) { if (!log_config) log_config = &asdf_context_log_config_default; - ctx->log.level = log_config->level == ASDF_LOG_NONE ? asdf_log_level_from_env() - : log_config->level; + ctx->log.level = log_config->level == ASDF_LOG_DEFAULT ? asdf_log_level_from_env() + : log_config->level; ctx->log.fields = log_config->fields ? log_config->fields : ASDF_LOG_FIELD_ALL; ctx->log.stream = log_config->stream ? log_config->stream : stderr; - ctx->log.no_color = log_config->no_color; + // Resolved once here, so no_color in the context is the final decision + ctx->log.no_color = !asdf_log_use_color(ctx->log.stream, log_config->no_color); return ctx; } diff --git a/src/file.c b/src/file.c index b2bf4836..824e682d 100644 --- a/src/file.c +++ b/src/file.c @@ -62,7 +62,7 @@ static asdf_config_t *asdf_config_build(asdf_config_t *user_config) { if (user_config) { ASDF_CONFIG_OVERRIDE(config, user_config, log.stream, stderr); - ASDF_CONFIG_OVERRIDE(config, user_config, log.level, ASDF_LOG_WARN); + ASDF_CONFIG_OVERRIDE(config, user_config, log.level, ASDF_LOG_DEFAULT); ASDF_CONFIG_OVERRIDE(config, user_config, log.fields, 0); ASDF_CONFIG_OVERRIDE(config, user_config, log.no_color, false); ASDF_CONFIG_OVERRIDE(config, user_config, parser.flags, 0); diff --git a/src/log.c b/src/log.c index 4e8e97b4..4e5659db 100644 --- a/src/log.c +++ b/src/log.c @@ -1,6 +1,10 @@ +#include #include +#include #include #include +#include +#include #ifdef HAVE_CONFIG_H #include "config.h" @@ -25,9 +29,12 @@ #define DIM(str) ANSI_DIM str ANSI_RESET #define ASDF_LOG_LEVEL_ENV_VAR "ASDF_LOG_LEVEL" +#define ASDF_LOG_COLOR_ENV_VAR "ASDF_LOG_COLOR" -static const char *level_names[] = {"NONE", "TRACE", "DEBUG", "INFO", "WARN", "ERROR", "FATAL"}; +// Indexed by message severity; ASDF_LOG_DEFAULT is never a message severity +// so its slot is unused, and ASDF_LOG_NONE is past the end +static const char *level_names[] = {"DEFAULT", "TRACE", "DEBUG", "INFO", "WARN", "ERROR", "FATAL"}; _Static_assert( @@ -45,7 +52,10 @@ _Static_assert( static asdf_log_level_t asdf_log_level_from_string(const char *str) { - for (unsigned int idx = 1; idx < ASDF_LOG_NUM_LEVELS; idx++) { + if (0 == strcasecmp(str, "NONE")) + return ASDF_LOG_NONE; + + for (unsigned int idx = ASDF_LOG_TRACE; idx < ASDF_LOG_NUM_LEVELS; idx++) { if (0 == strcasecmp(str, level_names[idx])) return (asdf_log_level_t)idx; } @@ -65,6 +75,32 @@ asdf_log_level_t asdf_log_level_from_env() { } +bool asdf_log_use_color(FILE *stream, bool no_color) { +#ifdef ASDF_LOG_COLOR + const char *env = getenv(ASDF_LOG_COLOR_ENV_VAR); + int saved_errno = errno; + bool color = false; + + if (env && 0 == strcmp(env, "1")) + return true; + + if (env && 0 == strcmp(env, "0")) + return false; + + // Otherwise only colorize when writing to a terminal; for any other stream + // (a file, a pipe, or a non-file stream with no descriptor at all) the + // escape codes would end up in the output verbatim + color = !no_color && isatty(fileno(stream)); + errno = saved_errno; + return color; +#else + (void)stream; + (void)no_color; + return false; +#endif +} + + static void asdf_log_impl( FILE *stream, asdf_log_level_t level, @@ -74,60 +110,74 @@ static void asdf_log_impl( int lineno, const char *fmt, va_list args) { + // Logging must not clobber errno for callers that log before reporting it + int saved_errno = errno; + bool color = false; + bool sep = false; + + // Messages can only be logged at a real severity; this also keeps the + // level_names lookup in bounds + if (UNLIKELY(level < ASDF_LOG_TRACE || level >= ASDF_LOG_NUM_LEVELS)) + return; + // Don't allow logging "nothing" (logging should simply be disabled for // that); if fields is empty enable all fields fields = fields ? fields : ASDF_LOG_FIELD_ALL; + #ifdef ASDF_LOG_COLOR - if (!no_color) { - if (fields & ASDF_LOG_FIELD_LEVEL) + color = !no_color; +#else + (void)no_color; +#endif + + if (fields & ASDF_LOG_FIELD_LEVEL) { +#ifdef ASDF_LOG_COLOR + if (color) fprintf( stream, - DIM("[") COLOR("%s", "%s") DIM("]") " ", + DIM("[") COLOR("%s", "%s") DIM("]"), level_colors[level], level_names[level]); + else +#endif + fprintf(stream, "[%-5s]", level_names[level]); + + sep = true; + } + + if (fields & (ASDF_LOG_FIELD_PACKAGE | ASDF_LOG_FIELD_FILE | ASDF_LOG_FIELD_LINE)) { + if (sep) + fputc(' ', stream); + + if (color) + fputs(COLOR_DIM_GREY, stream); if (fields & ASDF_LOG_FIELD_PACKAGE) - fputs(COLOR(COLOR_DIM_GREY, "(" PACKAGE_NAME ")"), stream); + fputs("(" PACKAGE_NAME ")", stream); if (fields & ASDF_LOG_FIELD_FILE) - fprintf(stream, COLOR(COLOR_DIM_GREY, "%s:"), file); + fprintf(stream, "%s:", file); if (fields & ASDF_LOG_FIELD_LINE) - fprintf(stream, COLOR(COLOR_DIM_GREY, "%d:"), lineno); + fprintf(stream, "%d:", lineno); - if (fields > ASDF_LOG_FIELD_MSG) - fputc(' ', stream); - - if (fields & ASDF_LOG_FIELD_MSG) - // NOLINTNEXTLINE(clang-analyzer-valist.Uninitialized) - vfprintf(stream, fmt, args); + if (color) + fputs(ANSI_RESET, stream); - fputc('\n', stream); - fflush(stream); - return; + sep = true; } -#endif - if (fields & ASDF_LOG_FIELD_LEVEL) - fprintf(stream, "[%-5s] ", level_names[level]); - - if (fields & ASDF_LOG_FIELD_PACKAGE) - fputs("(" PACKAGE_NAME ")", stream); - - if (fields & ASDF_LOG_FIELD_FILE) - fprintf(stream, "%s:", file); - - if (fields & ASDF_LOG_FIELD_LINE) - fprintf(stream, "%d:", lineno); - if (fields > ASDF_LOG_FIELD_MSG) - fputc(' ', stream); + if (fields & ASDF_LOG_FIELD_MSG) { + if (sep) + fputc(' ', stream); - if (fields & ASDF_LOG_FIELD_MSG) // NOLINTNEXTLINE(clang-analyzer-valist.Uninitialized) vfprintf(stream, fmt, args); + } fputc('\n', stream); fflush(stream); + errno = saved_errno; } @@ -188,6 +238,14 @@ void asdf_log_fallback(asdf_log_level_t level, const char *file, int lineno, con // NOLINTNEXTLINE(clang-analyzer-valist.Uninitialized) va_list args; va_start(args, fmt); - asdf_log_impl(stderr, level, ASDF_LOG_FIELD_ALL, false, file, lineno, fmt, args); + asdf_log_impl( + stderr, + level, + ASDF_LOG_FIELD_ALL, + !asdf_log_use_color(stderr, false), + file, + lineno, + fmt, + args); va_end(args); } diff --git a/src/log.h b/src/log.h index 5974bba1..3f8292e0 100644 --- a/src/log.h +++ b/src/log.h @@ -72,3 +72,12 @@ ASDF_LOCAL void asdf_log_fallback( ASDF_LOCAL asdf_log_level_t asdf_log_level_from_env(void); + + +/* + * Decide whether log output to ``stream`` is colorized: ``ASDF_LOG_COLOR=1`` + * or ``0`` in the environment forces it on or off; otherwise it is colorized + * only if ``no_color`` is false and ``stream`` is a terminal. Always false in + * builds without color support. + */ +ASDF_LOCAL bool asdf_log_use_color(FILE *stream, bool no_color); diff --git a/tests/test-log.c b/tests/test-log.c index 0aa7f616..5102d4e5 100644 --- a/tests/test-log.c +++ b/tests/test-log.c @@ -52,6 +52,51 @@ MU_TEST(level_explicit_overrides_env) { } +/* + * ASDF_LOG_DEFAULT (the zero value) takes the level from ASDF_LOG_LEVEL + */ +MU_TEST(level_default_uses_env) { + asdf_log_cfg_t log_cfg = {.level = ASDF_LOG_DEFAULT, .fields = ASDF_LOG_FIELD_MSG}; + log_capture_t cap = {0}; + assert_true(log_capture_open(&cap)); + + setenv("ASDF_LOG_LEVEL", "DEBUG", 1); + asdf_file_t *file = open_with_log(log_cfg, cap.stream); + unsetenv("ASDF_LOG_LEVEL"); + assert_not_null(file); + + asdf_file_log(file, ASDF_LOG_TRACE, "src.c", 1, "trace"); + asdf_file_log(file, ASDF_LOG_DEBUG, "src.c", 2, "debug"); + assert_string_equal(log_capture_text(&cap), "debug\n"); + asdf_close(file); + log_capture_close(&cap); + return MUNIT_OK; +} + + +/* + * ASDF_LOG_NONE in the configuration disables logging entirely, even if + * ASDF_LOG_LEVEL is set (regression test: it used to be 0 and so was + * indistinguishable from an unset level) + */ +MU_TEST(level_config_none) { + asdf_log_cfg_t log_cfg = {.level = ASDF_LOG_NONE}; + log_capture_t cap = {0}; + assert_true(log_capture_open(&cap)); + + setenv("ASDF_LOG_LEVEL", "TRACE", 1); + asdf_file_t *file = open_with_log(log_cfg, cap.stream); + unsetenv("ASDF_LOG_LEVEL"); + assert_not_null(file); + + asdf_file_log(file, ASDF_LOG_FATAL, "src.c", 1, "fatal"); + assert_string_equal(log_capture_text(&cap), ""); + asdf_close(file); + log_capture_close(&cap); + return MUNIT_OK; +} + + /* * ASDF_LOG_LEVEL=NONE in the environment disables logging entirely */ @@ -84,8 +129,9 @@ MU_TEST(message_level_out_of_range) { asdf_file_t *file = open_with_log(log_cfg, cap.stream); assert_not_null(file); - asdf_file_log(file, ASDF_LOG_NONE, "src.c", 1, "none"); - asdf_file_log(file, (asdf_log_level_t)ASDF_LOG_NUM_LEVELS, "src.c", 2, "too high"); + asdf_file_log(file, ASDF_LOG_DEFAULT, "src.c", 1, "default"); + asdf_file_log(file, ASDF_LOG_NONE, "src.c", 2, "none"); + asdf_file_log(file, (asdf_log_level_t)(ASDF_LOG_NONE + 1), "src.c", 3, "too high"); assert_string_equal(log_capture_text(&cap), ""); asdf_close(file); log_capture_close(&cap); @@ -240,6 +286,8 @@ MU_TEST(color_tty) { MU_TEST_SUITE( logging, MU_RUN_TEST(level_explicit_overrides_env), + MU_RUN_TEST(level_default_uses_env), + MU_RUN_TEST(level_config_none), MU_RUN_TEST(level_env_none), MU_RUN_TEST(message_level_out_of_range), MU_RUN_TEST(errno_preserved), From f9baa80670e0a3fe7e32dee26a4fd0584b1463c5 Mon Sep 17 00:00:00 2001 From: "E. Madison Bray" <676149+embray@users.noreply.github.com> Date: Wed, 14 Oct 2026 19:44:58 +0200 Subject: [PATCH 5/8] fix: churn in test-abi.sh when re-generating the abidw database Depending on the build path location it would generate relative paths from the build directory to the top_srcdir, resulting in noisy diffs if re-running from different build directories. --- tests/test-abi.sh | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) diff --git a/tests/test-abi.sh b/tests/test-abi.sh index 199ef4a5..34eb13a3 100755 --- a/tests/test-abi.sh +++ b/tests/test-abi.sh @@ -91,11 +91,21 @@ trap 'rm -f "${tmp}"' EXIT HUP INT TERM # The sed strips AddressSanitizer's ODR-violation aliases (__odr_asan., # one per global) from the symbol table. They are build instrumentation, not # ABI. +# +# It also makes each translation unit's path relative to the source root: the +# path is whatever the compiler was given, which is absolute for an +# out-of-tree build configured with an absolute srcdir and ../-relative for a +# build directory inside the source tree. abidiff ignores these paths, but +# normalizing them keeps the regenerated baseline from churning when rebuilding +# it from different build VPATHs. +abs_top_srcdir=$(cd "${top_srcdir}" && pwd -P) || exit 1 abidw --no-show-locs --no-comp-dir-path --no-corpus-path \ --drop-private-types --headers-dir "${top_srcdir}/include" \ --exported-interfaces-only --type-id-style hash \ "${lib}" 2>/dev/null \ - | sed -e "/]*path='\)${abs_top_srcdir}/|\1|" \ + -e "s|\(]*path='\)\(\.\./\)*|\1|" > "${tmp}" if [ ! -s "${tmp}" ]; then skip_or_die "abidw produced nothing for ${lib}" From a97fa2386ab18757467588daef59ef1777f7e468 Mon Sep 17 00:00:00 2001 From: "E. Madison Bray" <676149+embray@users.noreply.github.com> Date: Thu, 15 Oct 2026 12:05:01 +0200 Subject: [PATCH 6/8] docs: fix changelog formatting --- changes/+logging-fixes.bugfix | 10 ++++++---- changes/274.bugfix | 22 +++++++++++----------- changes/276.bugfix | 6 +++--- 3 files changed, 20 insertions(+), 18 deletions(-) diff --git a/changes/+logging-fixes.bugfix b/changes/+logging-fixes.bugfix index 69110d7c..fa981760 100644 --- a/changes/+logging-fixes.bugfix +++ b/changes/+logging-fixes.bugfix @@ -3,8 +3,9 @@ Several fixes to logging: - Setting `asdf_log_cfg_t.level` to `ASDF_LOG_NONE` now disables logging. Previously ``ASDF_LOG_NONE`` was ``0``, the same as an unset level, so it selected the default level instead. The default is now the new - ``ASDF_LOG_DEFAULT=0``, implying to use the global default (`ASDF_LOG_WARN`) - and `ASDF_LOG_NONE` is higher than every message severity. + ``ASDF_LOG_DEFAULT=0``, implying to use the global default + (`ASDF_LOG_WARN`) and `ASDF_LOG_NONE` is higher than every message + severity. This also fixes building with ``--with-log-default=NONE`` (or ``-DLOG_DEFAULT=NONE``), which logged everything instead of nothing. @@ -22,5 +23,6 @@ Several fixes to logging: - Logging no longer clobbers ``errno``. - ``asdf_file_log`` with an invalid level no longer reads out of bounds; the message is dropped. -- Lowered the very frequent YAML scalar type inference messages from ``DEBUG`` - to ``TRACE``, so ``DEBUG`` logging is no longer dominated by them. +- Lowered the very frequent YAML scalar type inference messages from + ``DEBUG`` to ``TRACE``, so ``DEBUG`` logging is no longer dominated by + them. diff --git a/changes/274.bugfix b/changes/274.bugfix index 42f84be9..115c3bd5 100644 --- a/changes/274.bugfix +++ b/changes/274.bugfix @@ -3,22 +3,22 @@ Several fixes to compressed block data reading: Fixed reading compressed arrays. Every access to a compressed block's data after the first returned the raw compressed bytes instead of the decompressed data, so that, for example, reading successive tiles with -``asdf_ndarray_read_tile_2d`` returned garbage and could crash reading past the -end of the compressed data. +``asdf_ndarray_read_tile_2d`` returned garbage and could crash reading past +the end of the compressed data. Fixed lazy decompression of LZ4-compressed arrays larger than 4 MB, which -returned zeros for all data past the first 4 MB, and could read past the end of -a buffer for the last, partial chunk. Tile reads now return +returned zeros for all data past the first 4 MB, and could read past the end +of a buffer for the last, partial chunk. Tile reads now return ``ASDF_NDARRAY_ERR_OUT_OF_BOUNDS`` rather than reading out of bounds when the array's data is smaller than its shape requires. Finally, fixed a race condition if multiple threads are reading the same decompressed data buffer (e.g. as returned by `asdf_block_data` or `asdf_ndarray_data`), and each encounter page faults. If multiple threads -cause page faults in the same range handled by a UFFD, the kernel queues these -and handles one at a time, even if the faulting address has had its page filled -by a previous fault handler call for one one of the other threads. In this -case the subsequent page faults, which have already been handled, should just -wake the faulting thread and allow it to resume. Instead it fell through to -attempting to copy the data again, resulting in an error (``EEXIST`` from -``ioctl``) causing the fault handler thread to exit. +cause page faults in the same range handled by a UFFD, the kernel queues +these and handles one at a time, even if the faulting address has had its +page filled by a previous fault handler call for one one of the other +threads. In this case the subsequent page faults, which have already been +handled, should just wake the faulting thread and allow it to resume. +Instead it fell through to attempting to copy the data again, resulting in an +error (``EEXIST`` from ``ioctl``) causing the fault handler thread to exit. diff --git a/changes/276.bugfix b/changes/276.bugfix index 75d07816..97e63040 100644 --- a/changes/276.bugfix +++ b/changes/276.bugfix @@ -1,3 +1,3 @@ -Fixed auto-selection of decompression mode. Lazy decompression was only being -used if explicitly requested and not as the default on supported platforms -(i.e. Linux). +Fixed auto-selection of decompression mode. Lazy decompression was only +being used if explicitly requested and not as the default on supported +platforms (i.e. Linux). From 7279a53eb59f0da7d59aace3d3ed8ff6242f79c6 Mon Sep 17 00:00:00 2001 From: "E. Madison Bray" <676149+embray@users.noreply.github.com> Date: Thu, 15 Oct 2026 12:23:40 +0200 Subject: [PATCH 7/8] fix: better if an explicitly set no_color takes precedence over ASDF_LOG_COLOR SE++ needs uncolored logs so it can parse them easily and feed them into its own logger without having to wade through ANSI escapes, and we shouldn't let the user override that via a stray environment variable either. An application setting no_color has a stronger claim here. Instead the ASDF_LOG_COLOR env var just overrides the isatty detection for the default behavior. Will be less relevant once gh-279 is done though. --- changes/+logging-fixes.bugfix | 3 ++- include/asdf/log.h | 12 +++++++----- src/log.c | 8 +++++++- src/log.h | 8 ++++---- tests/test-log.c | 19 +++++++++++++------ 5 files changed, 33 insertions(+), 17 deletions(-) diff --git a/changes/+logging-fixes.bugfix b/changes/+logging-fixes.bugfix index fa981760..a9df3160 100644 --- a/changes/+logging-fixes.bugfix +++ b/changes/+logging-fixes.bugfix @@ -15,7 +15,8 @@ Several fixes to logging: - Log output is colorized only when the stream is a terminal, rather than always in builds with color support, which wrote escape codes into log files and pipes. The new ``ASDF_LOG_COLOR`` environment variable forces - color on (``1``) or off (``0``). + color on (``1``) or off (``0``), but `asdf_log_cfg_t.no_color` takes + precedence if set explicitly. - Fixed doubled or trailing spaces in log lines when some of the log fields are disabled. - The log stream is flushed after every message, so messages are not lost or diff --git a/include/asdf/log.h b/include/asdf/log.h index b0180bd2..8dae438d 100644 --- a/include/asdf/log.h +++ b/include/asdf/log.h @@ -18,10 +18,12 @@ * * When the build supports color, output is colorized only if the stream is a * terminal and `asdf_log_cfg_t.no_color` is not set. The ``ASDF_LOG_COLOR`` - * environment variable overrides both: ``ASDF_LOG_COLOR=1`` forces color on - * (even when the stream is not a terminal) and ``ASDF_LOG_COLOR=0`` forces it - * off; any other value is ignored. Builds without color support ignore it. - * The environment is read once, when a file is opened. + * environment variable overrides the terminal check: ``ASDF_LOG_COLOR=1`` + * forces color on (even when the stream is not a terminal) and + * ``ASDF_LOG_COLOR=0`` forces it off; any other value is ignored. It does not + * override `asdf_log_cfg_t.no_color`, so an application that disables color + * always gets uncolored output. Builds without color support ignore it. The + * environment is read once, when a file is opened. * * The library's own internal log statements are compiled in only when libasdf * is built with logging enabled (the default; disable with ``-DENABLE_LOG=NO`` @@ -154,7 +156,7 @@ typedef struct { /** * Disable colorized output even when the build supports it and ``stream`` * is a terminal (output to any other stream is not colorized by default); - * overridden by the ``ASDF_LOG_COLOR`` environment variable + * takes precedence over the ``ASDF_LOG_COLOR`` environment variable */ bool no_color; } asdf_log_cfg_t; diff --git a/src/log.c b/src/log.c index 4e5659db..2098d832 100644 --- a/src/log.c +++ b/src/log.c @@ -81,6 +81,12 @@ bool asdf_log_use_color(FILE *stream, bool no_color) { int saved_errno = errno; bool color = false; + // Eexplicitly disabled color in the config has the strongest claim: + // it may be parsing the output, and escape codes would break that, + // for example. + if (no_color) + return false; + if (env && 0 == strcmp(env, "1")) return true; @@ -90,7 +96,7 @@ bool asdf_log_use_color(FILE *stream, bool no_color) { // Otherwise only colorize when writing to a terminal; for any other stream // (a file, a pipe, or a non-file stream with no descriptor at all) the // escape codes would end up in the output verbatim - color = !no_color && isatty(fileno(stream)); + color = isatty(fileno(stream)); errno = saved_errno; return color; #else diff --git a/src/log.h b/src/log.h index 3f8292e0..dbec13f6 100644 --- a/src/log.h +++ b/src/log.h @@ -75,9 +75,9 @@ ASDF_LOCAL asdf_log_level_t asdf_log_level_from_env(void); /* - * Decide whether log output to ``stream`` is colorized: ``ASDF_LOG_COLOR=1`` - * or ``0`` in the environment forces it on or off; otherwise it is colorized - * only if ``no_color`` is false and ``stream`` is a terminal. Always false in - * builds without color support. + * Decide whether log output to ``stream`` is colorized: never if ``no_color`` + * is true; otherwise ``ASDF_LOG_COLOR=1`` or ``0`` in the environment forces + * it on or off, and failing that it is colorized only if ``stream`` is a + * terminal. Always false in builds without color support. */ ASDF_LOCAL bool asdf_log_use_color(FILE *stream, bool no_color); diff --git a/tests/test-log.c b/tests/test-log.c index 5102d4e5..86d0667f 100644 --- a/tests/test-log.c +++ b/tests/test-log.c @@ -223,9 +223,9 @@ static bool log_is_colored( /* - * Color is decided by the stream being a terminal, ``no_color``, and the - * ASDF_LOG_COLOR environment variable (which overrides both); builds without - * color support never colorize + * Color is decided by ``no_color``, then the ASDF_LOG_COLOR environment + * variable, then whether the stream is a terminal; builds without color + * support never colorize */ MU_TEST(color_not_tty) { log_capture_t cap = {0}; @@ -237,7 +237,7 @@ MU_TEST(color_not_tty) { assert_false(colored); assert_true(log_capture_open(&cap)); - colored = log_is_colored(cap.stream, -1, &cap, true, "1"); + colored = log_is_colored(cap.stream, -1, &cap, false, "1"); log_capture_close(&cap); #ifdef ASDF_LOG_COLOR assert_true(colored); @@ -245,6 +245,12 @@ MU_TEST(color_not_tty) { assert_false(colored); #endif + // An explicit no_color wins over ASDF_LOG_COLOR=1 (regression test) + assert_true(log_capture_open(&cap)); + colored = log_is_colored(cap.stream, -1, &cap, true, "1"); + log_capture_close(&cap); + assert_false(colored); + assert_true(log_capture_open(&cap)); colored = log_is_colored(cap.stream, -1, &cap, false, "0"); log_capture_close(&cap); @@ -269,12 +275,13 @@ MU_TEST(color_tty) { #ifdef ASDF_LOG_COLOR assert_true(log_is_colored(stream, master_fd, NULL, false, NULL)); - assert_true(log_is_colored(stream, master_fd, NULL, true, "1")); + assert_true(log_is_colored(stream, master_fd, NULL, false, "1")); #else assert_false(log_is_colored(stream, master_fd, NULL, false, NULL)); - assert_false(log_is_colored(stream, master_fd, NULL, true, "1")); + assert_false(log_is_colored(stream, master_fd, NULL, false, "1")); #endif assert_false(log_is_colored(stream, master_fd, NULL, true, NULL)); + assert_false(log_is_colored(stream, master_fd, NULL, true, "1")); assert_false(log_is_colored(stream, master_fd, NULL, false, "0")); fclose(stream); From 6fccdb587afa21c0165cef697d28126284d3ec9a Mon Sep 17 00:00:00 2001 From: "E. Madison Bray" <676149+embray@users.noreply.github.com> Date: Thu, 15 Oct 2026 12:53:52 +0200 Subject: [PATCH 8/8] docs: fix how unwrap_rst.py handles list items List items following normal paragraphs *without* a blank line where just merged into that paragraph and incorrectly wrapped, rather than being treated as its own paragraph-like block in the first place. Ideally this would work better if it used the docutils rst outputter, but that would require an extra dependency I don't want to deal with right now. --- scripts/unwrap_rst.py | 23 ++++++++++++++++------- 1 file changed, 16 insertions(+), 7 deletions(-) diff --git a/scripts/unwrap_rst.py b/scripts/unwrap_rst.py index be263ed4..a0c31bcd 100755 --- a/scripts/unwrap_rst.py +++ b/scripts/unwrap_rst.py @@ -18,10 +18,13 @@ explicit markup (``.. directive::``) and indented literal blocks are all left alone. Hopefully that covers most of the common cases. -Lists are deliberately left alone too: towncrier indents every wrapped line of -a bullet to the paragraph indent rather than to a hanging indent. -Hand-wrapped list items already come through towncrier intact, so there is -nothing to fix there anyway. +Lists, and anything else indented within the fragment, are deliberately left +alone too: towncrier indents every wrapped line to the same 2-space indent +(the indent of the fragment's own bullet) rather than to a hanging indent, so +it can only re-wrap text at the fragment's base indent. Hand-wrapped list +items already come through towncrier intact, so there is nothing to fix there +anyway, but it's kind of annoying how towncrier makes its own assumptions that +have to be fought against; it should be fixed upstream. """ import argparse @@ -83,6 +86,10 @@ def unwrap_paragraph(lines: list[str]) -> list[str]: def paragraphs(lines: list[str]): """ Yield ``(is_blank, group)`` runs of consecutive blank / non-blank lines + + A list item always starts a new non-blank group, even without a blank line + before it, so a group is either a single list item (with any continuation + lines) or contains no list items at all. """ group: list[str] = [] @@ -90,8 +97,9 @@ def paragraphs(lines: list[str]): for line in lines: line_blank = not line.strip() + new_item = not line_blank and blank is False and LIST_ITEM_RE.match(line) - if blank is None or line_blank == blank: + if blank is None or (line_blank == blank and not new_item): group.append(line) else: yield blank, group @@ -131,9 +139,10 @@ def unwrap(text: str) -> str: elif EXPLICIT_MARKUP_RE.match(group[0]): verbatim = True literal_indent = base - elif LIST_ITEM_RE.match(group[0]): + elif base > 0 or LIST_ITEM_RE.match(group[0]): # See the module docstring: towncrier cannot re-wrap a long list - # item without breaking the hanging indent, so leave lists as-is + # item, or a paragraph indented under one, without breaking its + # hanging indent, so leave those as-is verbatim = True literal_indent = None else: