fix(server): capture all server log sinks in --log-file, gated on explicit flag (#2313)

Previously --log-file only captured LOG()/LOG_TEE() macro output; the
LLAMA_LOG_* engine lines, server_log() output, and common_log (SLT_*/SRV_*)
slot/checkpoint lines all went to stderr only.

Route all three sinks to --log-file:
- llama_log_tee_callback tees raw llama/ggml output to the file and stderr
- server_log() mirrors its stdout line to the file
- common_log_set_file_ptr() shares LOG_TARGET's FILE* with the common_log
  worker, which natively tees to stderr and file (so the SLT_*/SRV_* macros
  stay untouched and bare LOG_*/QUE_*/RES_* calls are captured too)

Gate every sink on log_target_changed() (set only by log_set_target_impl(),
the wrapper --log-file calls) plus a != stdout && != stderr guard mirroring
LOG_TEE_IMPL. LOG_TARGET is non-null by default (log_handler() lazily opens
llama.log), so a plain null check would capture every line into a surprise
llama.log with no flag, and on a non-writable cwd would double-print to
stderr. log_target_changed() is marked at the wrapper rather than inside
log_handler1_impl because --log-file is parsed before any LOG() call, making
the first invocation's filename comparison vacuously false.

common_log_set_file_ptr shares the already-opened FILE* rather than calling
common_log_set_file, whose own fopen("w") would open a second handle on the
same path and let the two writes corrupt each other.
This commit is contained in:
Skelectric 2026-08-26 13:34:25 -04:00 committed by GitHub
parent 2f068b5d87
commit 1d76336eeb
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
4 changed files with 98 additions and 7 deletions

View File

@ -146,6 +146,7 @@ struct common_log {
common_log(size_t capacity) { common_log(size_t capacity) {
file = nullptr; file = nullptr;
file_owned = false;
prefix = false; prefix = false;
timestamps = false; timestamps = false;
running = false; running = false;
@ -165,7 +166,7 @@ struct common_log {
~common_log() { ~common_log() {
pause(); pause();
if (file) { if (file && file_owned) {
fclose(file); fclose(file);
} }
} }
@ -176,6 +177,7 @@ private:
std::condition_variable cv; std::condition_variable cv;
FILE * file; FILE * file;
bool file_owned;
bool prefix; bool prefix;
bool timestamps; bool timestamps;
@ -330,19 +332,35 @@ public:
void set_file(const char * path) { void set_file(const char * path) {
pause(); pause();
if (file) { if (file && file_owned) {
fclose(file); fclose(file);
} }
if (path) { if (path) {
file = fopen(path, "w"); file = fopen(path, "w");
file_owned = true;
} else { } else {
file = nullptr; file = nullptr;
file_owned = false;
} }
resume(); resume();
} }
// Use an externally-owned FILE* (no fopen, no fclose on destruction).
void set_file_ptr(FILE * f) {
pause();
if (file && file_owned) {
fclose(file);
}
file = f;
file_owned = false;
resume();
}
void set_colors(bool colors) { void set_colors(bool colors) {
pause(); pause();
@ -420,6 +438,13 @@ void common_log_set_file(struct common_log * log, const char * file) {
log->set_file(file); log->set_file(file);
} }
// Share an externally-opened FILE* (e.g. log_handler's LOG_TARGET) so common_log
// tees to it without a second fopen() on the same path. common_log will not
// close it on destruction (the caller owns the handle).
void common_log_set_file_ptr(struct common_log * log, FILE * file) {
log->set_file_ptr(file);
}
void common_log_set_colors(struct common_log * log, log_colors colors) { void common_log_set_colors(struct common_log * log, log_colors colors) {
if (colors == LOG_COLORS_AUTO) { if (colors == LOG_COLORS_AUTO) {
log->set_colors(common_log_should_use_colors_auto()); log->set_colors(common_log_should_use_colors_auto());

View File

@ -91,6 +91,9 @@ void common_log_add(struct common_log* log, enum ggml_log_level level, const cha
// //
void common_log_set_file(struct common_log* log, const char* file); // not thread-safe void common_log_set_file(struct common_log* log, const char* file); // not thread-safe
// Share an externally-opened FILE* (e.g. LOG_TARGET) so common_log tees to it
// without a second fopen() on the same path; common_log will not close it.
void common_log_set_file_ptr(struct common_log* log, FILE* file); // not thread-safe
void common_log_set_colors(struct common_log* log, log_colors colors); // not thread-safe void common_log_set_colors(struct common_log* log, log_colors colors); // not thread-safe
void common_log_set_prefix(struct common_log* log, bool prefix); // whether to output prefix to each log void common_log_set_prefix(struct common_log* log, bool prefix); // whether to output prefix to each log
void common_log_set_timestamps(struct common_log* log, bool timestamps); // whether to output timestamps in the prefix void common_log_set_timestamps(struct common_log* log, bool timestamps); // whether to output timestamps in the prefix
@ -441,6 +444,18 @@ inline std::string log_filename_generator_impl(LogTriState multilog, const std::
#define LOG_TEELN(str, ...) LOG_TEE_IMPL("%s" str, "", ##__VA_ARGS__, "\n") #define LOG_TEELN(str, ...) LOG_TEE_IMPL("%s" str, "", ##__VA_ARGS__, "\n")
#endif #endif
// True only when the log target was explicitly set via log_set_target() (e.g.
// by --log-file). LOG_TARGET is non-null by default (log_handler() lazily opens
// "llama.log"), so a null check cannot tell a user-requested file from the
// default. Tee callers should gate on this instead of `LOG_TARGET != nullptr`.
inline bool log_target_changed(bool mark_changed = false) {
static bool changed = false;
if (mark_changed) {
changed = true;
}
return changed;
}
// INTERNAL, DO NOT USE // INTERNAL, DO NOT USE
inline FILE *log_handler1_impl(bool change = false, LogTriState append = LogTriStateSame, LogTriState disable = LogTriStateSame, const std::string & filename = LOG_DEFAULT_FILE_NAME, FILE *target = nullptr) inline FILE *log_handler1_impl(bool change = false, LogTriState append = LogTriStateSame, LogTriState disable = LogTriStateSame, const std::string & filename = LOG_DEFAULT_FILE_NAME, FILE *target = nullptr)
{ {
@ -561,8 +576,12 @@ inline FILE *log_enable_impl()
#define log_set_target(target) log_set_target_impl(target) #define log_set_target(target) log_set_target_impl(target)
// INTERNAL, DO NOT USE // INTERNAL, DO NOT USE
inline FILE *log_set_target_impl(const std::string & filename) { return log_handler1_impl(true, LogTriStateSame, LogTriStateSame, filename); } // Mark log_target_changed() here (not inside log_handler1_impl): when --log-file
inline FILE *log_set_target_impl(FILE *target) { return log_handler2_impl(true, LogTriStateSame, LogTriStateSame, target); } // is parsed before any LOG() call, this is the first invocation, so
// log_handler1_impl's static filename initializes to the requested name and its
// `!= filename` check never fires.
inline FILE *log_set_target_impl(const std::string & filename) { log_target_changed(true); return log_handler1_impl(true, LogTriStateSame, LogTriStateSame, filename); }
inline FILE *log_set_target_impl(FILE *target) { log_target_changed(true); return log_handler2_impl(true, LogTriStateSame, LogTriStateSame, target); }
// INTERNAL, DO NOT USE // INTERNAL, DO NOT USE
inline FILE *log_handler() { return log_handler1_impl(); } inline FILE *log_handler() { return log_handler1_impl(); }

View File

@ -1,6 +1,7 @@
#include "server-common.h" #include "server-common.h"
#include <algorithm> #include <algorithm>
#include <cstdio>
using raw_buffer = std::vector<uint8_t>; using raw_buffer = std::vector<uint8_t>;
@ -33,6 +34,7 @@ void server_log(const char* level, const char* function, int line, const char* m
{"timestamp", time(nullptr)}, {"timestamp", time(nullptr)},
}; };
std::string out;
if (server_log_json) { if (server_log_json) {
log.merge_patch({ log.merge_patch({
{"level", level}, {"level", level},
@ -45,7 +47,7 @@ void server_log(const char* level, const char* function, int line, const char* m
log.merge_patch(extra); log.merge_patch(extra);
} }
printf("%s\n", log.dump(-1, ' ', false, json::error_handler_t::replace).c_str()); out = log.dump(-1, ' ', false, json::error_handler_t::replace);
} }
else { else {
char buf[1024]; char buf[1024];
@ -62,10 +64,19 @@ void server_log(const char* level, const char* function, int line, const char* m
ss << " " << el.key() << "=" << value; ss << " " << el.key() << "=" << value;
} }
const std::string str = ss.str(); out = ss.str();
printf("%.*s\n", (int)str.size(), str.data());
} }
printf("%s\n", out.c_str());
fflush(stdout); fflush(stdout);
// Mirror to --log-file when explicitly set (see log_target_changed()).
if (log_target_changed()) {
FILE * tgt = LOG_TARGET;
if (tgt != nullptr && tgt != stdout && tgt != stderr) {
fprintf(tgt, "%s\n", out.c_str());
fflush(tgt);
}
}
} }
// //

View File

@ -17,6 +17,25 @@
// mime type for sending response // mime type for sending response
#define MIMETYPE_JSON "application/json; charset=utf-8" #define MIMETYPE_JSON "application/json; charset=utf-8"
// Tee llama/ggml log output to --log-file (when set) and stderr. Gated on
// log_target_changed() so it's a no-op unless --log-file was passed (LOG_TARGET
// is non-null by default). The stdout/stderr guard mirrors LOG_TEE_IMPL and
// avoids doubled output when fopen() falls back to stderr.
static void llama_log_tee_callback(enum ggml_log_level level, const char * text, void * /*user_data*/) {
if (text == nullptr) {
return;
}
if (log_target_changed()) {
FILE * tgt = LOG_TARGET;
if (tgt != nullptr && tgt != stdout && tgt != stderr) {
fprintf(tgt, "%s", text);
fflush(tgt);
}
}
fputs(text, stderr);
fflush(stderr);
}
#ifndef NDEBUG #ifndef NDEBUG
// crash the server in debug mode, otherwise send an http 500 error // crash the server in debug mode, otherwise send an http 500 error
@ -466,6 +485,23 @@ int main(int argc, char ** argv) {
// parse arguments from environment variables // parse arguments from environment variables
gpt_params_parse_from_env(params); gpt_params_parse_from_env(params);
// Tee llama/ggml logs to --log-file; installed before model load so that
// load-time logs are captured too.
llama_log_set(llama_log_tee_callback, nullptr);
// Route common_log (SLT_*/SRV_*/QUE_*/RES_*/bare LOG_* slot+queue output) to
// --log-file via its native file sink. The worker tees to stderr and file
// (common/log.cpp), so this captures every common_log line in one call
// instead of mirroring each macro. Share LOG_TARGET's already-opened FILE*
// so there's a single handle on the file (a second fopen would truncate and
// the two handles' writes would corrupt each other).
if (log_target_changed()) {
FILE * tgt = LOG_TARGET;
if (tgt != nullptr && tgt != stdout && tgt != stderr) {
common_log_set_file_ptr(common_log_main(), tgt);
}
}
// TODO: not great to use extern vars // TODO: not great to use extern vars
server_log_json = params.log_json; server_log_json = params.log_json;
server_verbose = params.verbosity > 0; server_verbose = params.verbosity > 0;