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..a9df3160 --- /dev/null +++ b/changes/+logging-fixes.bugfix @@ -0,0 +1,29 @@ +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``), 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 + 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/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). 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..8dae438d 100644 --- a/include/asdf/log.h +++ b/include/asdf/log.h @@ -8,13 +8,23 @@ * 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 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`` * under CMake or ``--disable-logging`` under the Autotools build). The public @@ -38,11 +48,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 +73,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 +137,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 +153,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); + * takes precedence over the ``ASDF_LOG_COLOR`` environment variable + */ bool no_color; } asdf_log_cfg_t; 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: 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 1afa8d33..2098d832 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,38 @@ 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; + + // 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; + + 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 = 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,58 +116,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); - 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; } @@ -186,6 +244,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..dbec13f6 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: 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/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; 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-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}" 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..86d0667f --- /dev/null +++ b/tests/test-log.c @@ -0,0 +1,307 @@ +#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_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 + */ +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_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); + 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 ``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}; + 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, false, "1"); + log_capture_close(&cap); +#ifdef ASDF_LOG_COLOR + assert_true(colored); +#else + 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); + 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, false, "1")); +#else + assert_false(log_is_colored(stream, master_fd, NULL, false, NULL)); + 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); + close(master_fd); + return MUNIT_OK; +} + + +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), + 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);