diff --git a/llama/addon/globals/addonLog.cpp b/llama/addon/globals/addonLog.cpp index 488bab1c..1d7eabb2 100644 --- a/llama/addon/globals/addonLog.cpp +++ b/llama/addon/globals/addonLog.cpp @@ -6,6 +6,7 @@ AddonThreadSafeLogCallbackFunction addonThreadSafeLoggerCallback; bool addonJsLoggerCallbackSet = false; +AddonThreadSafeLogCallbackFunctionContext* addonCurrentLoggerContext = nullptr; std::atomic addonLoggerLogLevel(5); std::atomic> addonLoggerLogLevelOverride(std::nullopt); std::atomic addonLastLoggerLogLevel(6); @@ -103,17 +104,26 @@ void addonLlamaCppLogCallback(ggml_log_level level, const char* text, void* user } Napi::Value setLogger(const Napi::CallbackInfo& info) { - if (addonJsLoggerCallbackSet) { - addonJsLoggerCallbackSet = false; - addonThreadSafeLoggerCallback.Release(); - } - if (info.Length() < 1 || !info[0].IsFunction()) { + if (addonJsLoggerCallbackSet) { + addonJsLoggerCallbackSet = false; + addonCurrentLoggerContext = nullptr; + addonThreadSafeLoggerCallback.Release(); + } + return info.Env().Undefined(); } auto addonLoggerJSCallback = info[0].As(); AddonThreadSafeLogCallbackFunctionContext* context = new Napi::Reference(Napi::Persistent(info.This())); + + // install the new logger before releasing the previous one, so that the previous logger's + // deferred finalizer cannot disable the new logger (the finalizer only disables logging + // when its context is still the current one) + const bool hadPreviousLogger = addonJsLoggerCallbackSet; + auto previousLoggerCallback = addonThreadSafeLoggerCallback; + + addonCurrentLoggerContext = context; addonThreadSafeLoggerCallback = AddonThreadSafeLogCallbackFunction::New( info.Env(), addonLoggerJSCallback, @@ -122,7 +132,10 @@ Napi::Value setLogger(const Napi::CallbackInfo& info) { 1, context, [](Napi::Env, void*, AddonThreadSafeLogCallbackFunctionContext* ctx) { - addonJsLoggerCallbackSet = false; + if (addonCurrentLoggerContext == ctx) { + addonJsLoggerCallbackSet = false; + addonCurrentLoggerContext = nullptr; + } delete ctx; } @@ -132,6 +145,9 @@ Napi::Value setLogger(const Napi::CallbackInfo& info) { // prevent blocking the main node process from exiting due to active resources addonThreadSafeLoggerCallback.Unref(info.Env()); + if (hadPreviousLogger) + previousLoggerCallback.Release(); + return info.Env().Undefined(); } diff --git a/test/modelDependent/llama/logger.test.ts b/test/modelDependent/llama/logger.test.ts new file mode 100644 index 00000000..d3161283 --- /dev/null +++ b/test/modelDependent/llama/logger.test.ts @@ -0,0 +1,38 @@ +import {describe, expect, test} from "vitest"; +import {getModelFile} from "../../utils/modelFiles.js"; +import {getLlama, LlamaLogLevel} from "../../../src/index.js"; + +describe("llama", () => { + describe("logger", () => { + test("a custom logger keeps receiving llama.cpp log lines after a second getLlama() call", {timeout: 1000 * 60 * 60 * 2}, async () => { + const modelPath = await getModelFile("bge-small-en-v1.5-q8_0.gguf"); + const lines1: string[] = []; + const lines2: string[] = []; + + const llama1 = await getLlama({ + logLevel: LlamaLogLevel.debug, + logger(level, message) { + lines1.push(message); + } + }); + await llama1.loadModel({modelPath}); + + const llama2 = await getLlama({ + logLevel: LlamaLogLevel.debug, + logger(level, message) { + lines2.push(message); + } + }); + await new Promise((resolve) => setTimeout(resolve, 100)); + await llama2.loadModel({modelPath}); + + // llama.cpp emits native log lines through the logger of the most recently created instance. + // Only TS-side logs would reach `lines2` if the native log sink was broken. + expect(lines1.some((line) => line.includes("llama_model_loader"))).toBe(true); + expect(lines2.some((line) => line.includes("llama_model_loader"))).toBe(true); + + await llama2.dispose(); + await llama1.dispose(); + }); + }); +});