`nix store optimise` and `nix store gc` (and possibly other progress reporting commands) drop output #774

New issue

Open

opened 2025-03-26 19:45:21 +00:00 by lunaphied · 2 comments

lunaphied commented

2025-03-26 19:45:21 +00:00

Owner

Describe the bug

There seems to be an issue with progress reporting nix3 commands in that if they print a final message after they complete, sometimes that message gets eaten. This clearly shouldn't happen as these commands are often long-running and when the user returns to the CLI they will not see what was completed.

Steps To Reproduce

Run nix store optimise or nix store gc
Observe the lacking multiple lines of output that should happen after the progress reporting has been completed.

Expected behavior

The final output messages (which for both are already specified in the code) should actually be displayed.

`nix --version` output

nix (Lix, like Nix) 2.93.0-dev (rev: f270d3ebe)

## Describe the bug There seems to be an issue with progress reporting nix3 commands in that if they print a final message after they complete, sometimes that message gets eaten. This clearly shouldn't happen as these commands are often long-running and when the user returns to the CLI they will not see what was completed. ## Steps To Reproduce 1. Run `nix store optimise` or `nix store gc` 2. Observe the lacking multiple lines of output that should happen after the progress reporting has been completed. ## Expected behavior The final output messages (which for both are already specified in the code) should actually be displayed. ## `nix --version` output `nix (Lix, like Nix) 2.93.0-dev` (rev: f270d3ebe)

lunaphied added the

labels

2025-03-26 19:45:21 +00:00

lunaphied self-assigned this

2025-03-26 19:45:22 +00:00

lunaphied removed their assignment

2025-03-26 19:45:54 +00:00

rootile commented

2026-01-04 10:50:02 +00:00

Member

does this only happen with the default logging or also with other logging formats?

squeakybeaver commented

2026-02-11 18:55:31 +00:00

I can confirm this happens with all logging formats.

I think the reason for this issue is this block of code in lix/nix/main.cc:

    // FIXME: stop messing about with log verbosity depending on if it is interactive use
    if (isatty(STDERR_FILENO)) {
        verbosity = lvlNotice;
    } else {
        verbosity = lvlInfo;
    }

Since nix store optimise and nix store gc use printInfo to show the output like XXMib freed by hard-linking y files (link) or deleting garbage... (link), setting the verbosity level to lvlNotice will hide these messages.
However, removing this block of code causes issues #362 and #367 to reappear.

The way I see it, we have a few options:

Change some of the printInfo calls to printNotice or similar for the more important messages (like the results).
Change the result messages to be printed with logger->cout() like nix search does. Personally, I don't think this is a good solution.
Remove the block of code in main.cc that changes the log level. If we do this, we should reevaluate some of the logged messages. For instance, if we want to keep the nix store optimise messages at the info still, we will need to change the level of some messages in nix search to the talkative level or something similar.

I think option 3 would be the best, especially if we go through and enforce log levels. Say, for instance, result messages should be at the notice level, less verbose progress messages like deleting garbage... should be at the info level and any more verbose progress messages should be at the talkative or lower level. The major downside to this that I can foresee is that a change like this would be pretty large, since we would likely want to do this to a lot of the nix 3 commands.

I can confirm this happens with all logging formats. I think the reason for this issue is [this block of code](https://git.lix.systems/lix-project/lix/src/commit/f09ed729b5dcacbbff5e1ae6f85bc93933ecf2f1/lix/nix/main.cc#L513) in `lix/nix/main.cc`: ```cpp // FIXME: stop messing about with log verbosity depending on if it is interactive use if (isatty(STDERR_FILENO)) { verbosity = lvlNotice; } else { verbosity = lvlInfo; } ``` Since `nix store optimise` and `nix store gc` use `printInfo` to show the output like `XXMib freed by hard-linking y files` ([link](https://git.lix.systems/lix-project/lix/src/commit/505d0669dcb47e5f8b054cbb17543ab2186c496a/lix/libstore/optimise-store.cc#L332)) or `deleting garbage...` ([link](https://git.lix.systems/lix-project/lix/src/commit/505d0669dcb47e5f8b054cbb17543ab2186c496a/lix/libstore/gc.cc#L847)), setting the verbosity level to `lvlNotice` will hide these messages. However, removing this block of code causes issues #362 and #367 to reappear. The way I see it, we have a few options: 1. Change some of the `printInfo` calls to `printNotice` or similar for the more important messages (like the results). 2. Change the result messages to be printed with `logger->cout()` like [`nix search` does](https://git.lix.systems/lix-project/lix/src/commit/505d0669dcb47e5f8b054cbb17543ab2186c496a/lix/nix/search.cc#L166). Personally, I don't think this is a good solution. 3. Remove the block of code in `main.cc` that changes the log level. If we do this, we should reevaluate some of the logged messages. For instance, if we want to keep the `nix store optimise` messages at the info still, we will need to change the level of some messages in `nix search` to the talkative level or something similar. I think option 3 would be the best, especially if we go through and enforce log levels. Say, for instance, result messages should be at the notice level, less verbose progress messages like `deleting garbage...` should be at the info level and any more verbose progress messages should be at the talkative or lower level. The major downside to this that I can foresee is that a change like this would be pretty large, since we would likely want to do this to a lot of the nix 3 commands.