Repository navigation
log, server: self contained colors, split child commands from logs in router mode - #29895
Conversation
The logger writes the color reset after the trailing newline, so the reset opens the next line. On the shared pipe of a router child it lands in front of the next state command, which the router then misses, and the line break that works around it shows up as an empty log line on every progress update. The reset now goes before the trailing newlines, so every line is self contained and the command goes back to its plain framing. The router passes its effective color setting to its children, whose output ends up in its terminal, and leaves that option out when comparing presets on reload.
A Windows console renders ANSI sequences only in virtual terminal mode, which nothing turns on for the logger, so llama-server prints raw escape codes on the Windows 10 console while llama-cli, whose console code enables it, shows colors. The logger now enables virtual terminal mode on stdout and stderr when it turns colors on, and keeps colors off when a console cannot render them. Pipes and files take the sequences as is.
|
Tested on Windows 10 and 11 (cmd and PowerShell), macOS and Linux, screenshots below; the empty lines are gone too, easiest to check by redirecting stdout/stderr to a file, same result on every OS. Color bug example :Windows 10 is the special case: its console only renders colors once virtual terminal mode is enabled, which tty_enable_ansi() now does when the logger turns colors on, while Windows 11 terminals render them out of the box. 
Regression tests :
Windows 10 old powershell 5 Windows 11 powershell MacOS Linux Debian |
|
I think we should keep the |
This PR fixes the cause: every log line now closes its own colors, so nothing written to the shared pipe is left unterminated before a command. The known partial writers are covered too, since the loading dots and the download progress bar never print in a child. Validated with the #28747 repro and its negative control, no empty lines on Linux, macOS and Windows, and the router tests passing. Keeping "\n%s%s\n" only works together with a filter that hides the empty lines it creates, and that filter would also swallow the empty lines children log on purpose. It would add a safety net for a case that doesn't exist in the repo today, a third party writing to stderr without a trailing newline, whose worst outcome would be one lost command as before #28747. The way to remove that risk by construction is the TODO at the spawn in server-models.cpp: separate stdout for commands from stderr for logs, so no framing is needed at all. Would you rather keep the code clean at the source and leave the remaining risk to that TODO, or keep the framing and the filter as a guard in the meantime? |
|
What bothers me with the filter is that the router stops forwarding the child output as is: the same log reads differently standalone and behind the router. That said, if you really want that extra safety net, I'll add the leading newline and the filter back to this PR. |
|
The current approach is very fragile, so I guess there will have regression every time we touch that code. |
The TODO at the spawn is resolved in ServeurpersoCom@58627fc, tested successfully on Linux, macOS, Windows 10 and Windows 11, so the fragility is gone: commands and logs no longer share a pipe. It builds on this PR, would you rather have it pushed here? |
|
This seems to fix the blank-line issue I reported. However, I asked my Astra for a review and it pointed out that not all log output ends with a newline today (e.g. the warning at
|
Thanks for testing and for the catch, you're right, a few log calls don't end with a newline. That's exactly what the follow-up fixes by construction, commands get their own pipe so nothing written to the log can end up in front of them: ServeurpersoCom@58627fc So I think the scope of this PR should grow a bit: I'm bringing the TODO in here, so the whole topic is handled at once, the empty lines, the colors, and the related technical debt. |
The child sent its state commands on the same pipe as its logs, so the router had to pick them out of the log stream by a line prefix, and any unterminated write in front of a command made the router miss it. This resolves the TODO at the spawn that called for splitting stdout and stderr. The child now keeps stdout for the commands and points everything else written to stdout at stderr, before anything is written. The router reads both pipes, handles the commands from stdout and forwards stderr as the log, and warns about any other line on the command pipe.
ServeurpersoCom
changed the title
The pipe split is now pushed to this PR, could you give it another try in your setup when you have a moment? Thanks again for the review! |
|
This now fixes the code review issue and mostly fixes the blank line issue. Interestingly as of the latest commit I now get a single blank log line when loading a model in router mode, right between |
|
Astra tracked this down to |
Yes, that one is intended: the router now forwards the child output exactly as is, so this empty line comes from clip.cpp itself and shows up the same way in standalone mode. Whether to keep that kind of spacing or rework those logs is a separate choice, and it's now entirely up to each log call, the router stays out of it. |
|
Way better like this! Thanks @ServeurpersoCom |
| static bool is_child(); | ||
|
|
||
| // keep stdout for the commands to the router, called before anything else is written; | ||
| // everything else written to stdout goes to stderr with the logs | ||
| static void init(); |
There was a problem hiding this comment.
I don't quite comfortable spreading the static across the code base. It's just not an elegant solution, making it unclear about the ownership of the object
Instead, should avoid static whenever possible
There was a problem hiding this comment.
Done, the command stream is now a member of the single server_child instance, no static anymore.
| if (server_child::is_child()) { | ||
| server_child::init(); | ||
| } | ||
|
|
There was a problem hiding this comment.
an instance of server_child will be created later in this function anyway, why need to make it singleton here?
There was a problem hiding this comment.
Right, the instance is now created first in the entry point and passed down, so there is only one.
There was a problem hiding this comment.
having both setup() and init() is confusing
There was a problem hiding this comment.
init() is gone, the constructor does it, so only setup() remains.
The single server_child is now created first in the entry point and its constructor keeps stdout for the commands, so the stream is a member of the instance instead of a static, and init() is gone. The instance is passed down to the server, while the CLI entry point creates its own.
4 participants
Overview
This fixes two problems and the technical debt behind them. Since #28747, router mode prints an empty log line on every loading and download progress update of a child, and console colors behave differently depending on the platform.
The logger now writes the color reset before the trailing newline, so every line carries its own colors. The router passes its color setting to its children, whose output ends up in its terminal, and the logger enables virtual terminal mode on the Windows console, as llama-cli already does.
The child no longer sends its state commands on the same pipe as its logs, which resolves the TODO at the spawn. It keeps stdout for the commands and points everything else written to stdout at stderr before anything is written, so no log line, library print or progress output can end up in front of a command, and the command goes back to its plain framing with no empty lines. The router reads both pipes, handles the commands from stdout, forwards stderr as the log, and warns about any other line on the command pipe.
Colors now work the same way everywhere, for every tool that logs through common: Windows 10 and 11, cmd and PowerShell, macOS and Linux, with no empty lines and no workaround.
Additional information
Reproduced with an unterminated write on stdout and stderr right before download_finished: without the pipe split the command is logged instead of handled and the model stays stuck downloading, with it every command is handled and the stray bytes land in the log. Also checked model load and unload, download, --log-jsonl, colored logs and the router tests. Thanks @eapache for spotting the log calls that don't end with a newline.
Follow-up #28747
Fixes #29878
Requirements