fix: don't block a node process from exiting (#157)

* fix: don't block a node process from exiting
* fix: respect `logLevel` and `logger` params when using `"lastBuild"`
* fix: print logs on the same event loop cycle

Author: giladgd

.github/workflows/build.yml

@@ -243,14 +243,16 @@ jobs:
         run: npm ci
 
       - name: Build binary
-        run: node ./dist/cli/cli.js build
+        run: node ./dist/cli/cli.js build --noUsageExample
 
       - name: Run standalone tests
         run: npm run test:standalone
 
   model-dependent-tests:
     name: Model dependent tests
-    runs-on: macos-13
+    runs-on: macos-14
+    env:
+      NODE_LLAMA_CPP_METAL: false
     needs:
       - build
     steps:
@@ -280,7 +282,7 @@ jobs:
         run: npm ci
 
       - name: Build binary
-        run: node ./dist/cli/cli.js build
+        run: node ./dist/cli/cli.js build --noUsageExample
 
       - name: Cache models
         id: cache-test-models

llama/addon.cpp

@@ -9,16 +9,28 @@
 #include "llama.h"
 #include "napi.h"
 
-Napi::FunctionReference loggerCallbackFunctionReference;
-Napi::ThreadSafeFunction threadSafeLoggerCallback;
-bool loggerCallbackSet = false;
-int addonLoggerLogLevel = 5;
-
 struct addon_logger_log {
     const int logLevelNumber;
     const std::stringstream* stringStream;
 };
 
+using AddonThreadSafeLogCallbackFunctionContext = Napi::Reference<Napi::Value>;
+void addonCallJsLogCallback(
+    Napi::Env env,
+    Napi::Function callback,
+    AddonThreadSafeLogCallbackFunctionContext *context,
+    addon_logger_log* data
+);
+using AddonThreadSafeLogCallbackFunction = Napi::TypedThreadSafeFunction<
+    AddonThreadSafeLogCallbackFunctionContext,
+    addon_logger_log,
+    addonCallJsLogCallback
+>;
+
+AddonThreadSafeLogCallbackFunction addonThreadSafeLoggerCallback;
+bool addonJsLoggerCallbackSet = false;
+int addonLoggerLogLevel = 5;
+
 std::string addon_model_token_to_piece(const struct llama_model * model, llama_token token) {
     std::vector<char> result(8, 0);
     const int n_tokens = llama_token_to_piece(model, token, result.data(), result.size());
@@ -820,14 +832,31 @@ int addonGetGgmlLogLevelNumber(ggml_log_level level) {
     return 1;
 }
 
-static void addonWrapperJSLogCallback(Napi::Env env, Napi::Function jsCallback, addon_logger_log* data) {
-    auto status = jsCallback.Call({
-        Napi::Number::New(env, data->logLevelNumber),
-        Napi::String::New(env, data->stringStream->str())
-    });
+void addonCallJsLogCallback(
+    Napi::Env env,
+    Napi::Function callback,
+    AddonThreadSafeLogCallbackFunctionContext * context,
+    addon_logger_log * data
+) {
+    if (env != nullptr && callback != nullptr) {
+        callback.Call({
+            Napi::Number::New(env, data->logLevelNumber),
+            Napi::String::New(env, data->stringStream->str())
+        });
+    } else if (data != nullptr) {
+        if (data->logLevelNumber == 2) {
+            fputs(data->stringStream->str().c_str(), stderr);
+            fflush(stderr);
+        } else {
+            fputs(data->stringStream->str().c_str(), stdout);
+            fflush(stdout);
+        }
+    }
 
-    delete data->stringStream;
-    delete data;
+    if (data != nullptr) {
+        delete data->stringStream;
+        delete data;
+    }
 }
 
 static void addonLlamaCppLogCallback(ggml_log_level level, const char * text, void * user_data) {
@@ -837,7 +866,7 @@ static void addonLlamaCppLogCallback(ggml_log_level level, const char * text, vo
         return;
     }
 
-    if (loggerCallbackSet) {
+    if (addonJsLoggerCallbackSet) {
         std::stringstream* stringStream = new std::stringstream();
         if (text != nullptr) {
             *stringStream << text;
@@ -848,14 +877,14 @@ static void addonLlamaCppLogCallback(ggml_log_level level, const char * text, vo
             stringStream
         };
 
-        auto status = threadSafeLoggerCallback.NonBlockingCall(data, addonWrapperJSLogCallback);
+        auto status = addonThreadSafeLoggerCallback.NonBlockingCall(data);
 
         if (status == napi_ok) {
             return;
         }
     }
 
-    if (level == GGML_LOG_LEVEL_ERROR) {
+    if (level == 2) {
         fputs(text, stderr);
         fflush(stderr);
     } else {
@@ -866,28 +895,41 @@ static void addonLlamaCppLogCallback(ggml_log_level level, const char * text, vo
 
 Napi::Value setLogger(const Napi::CallbackInfo& info) {
     if (info.Length() < 1 || !info[0].IsFunction()) {
-        if (loggerCallbackSet) {
-            threadSafeLoggerCallback.Release();
-            threadSafeLoggerCallback = nullptr;
-            loggerCallbackFunctionReference.Unref();
-            loggerCallbackSet = false;
+        if (addonJsLoggerCallbackSet) {
+            addonJsLoggerCallbackSet = false;
+            addonThreadSafeLoggerCallback.Release();
         }
 
         return info.Env().Undefined();
     }
 
-    loggerCallbackFunctionReference = Napi::Persistent(info[0].As<Napi::Function>());
-    loggerCallbackFunctionReference.Ref();
-    threadSafeLoggerCallback = Napi::ThreadSafeFunction::New(info.Env(), loggerCallbackFunctionReference.Value(), "loggerCallback", 0, 1);
-    loggerCallbackSet = true;
+    auto addonLoggerJSCallback = info[0].As<Napi::Function>();
+    AddonThreadSafeLogCallbackFunctionContext *context = new Napi::Reference<Napi::Value>(Napi::Persistent(info.This()));
+    addonThreadSafeLoggerCallback = AddonThreadSafeLogCallbackFunction::New(
+        info.Env(),
+        addonLoggerJSCallback,
+        "loggerCallback",
+        0,
+        1,
+        context,
+        []( Napi::Env, void *, AddonThreadSafeLogCallbackFunctionContext *ctx ) {
+            addonJsLoggerCallbackSet = false;
+
+            delete ctx;
+        }
+    );
+    addonJsLoggerCallbackSet = true;
+
+    // prevent blocking the main node process from exiting due to active resources
+    addonThreadSafeLoggerCallback.Unref(info.Env());
 
     return info.Env().Undefined();
 }
 
 Napi::Value setLoggerLogLevel(const Napi::CallbackInfo& info) {
     if (info.Length() < 1 || !info[0].IsNumber()) {
         addonLoggerLogLevel = 5;
-        
+
         return info.Env().Undefined();
     }
 

src/bindings/Llama.ts

@@ -30,12 +30,11 @@ export class Llama {
     /** @internal */ private _logLevel: LlamaLogLevel;
     /** @internal */ private _pendingLog: string | null = null;
     /** @internal */ private _pendingLogLevel: LlamaLogLevel | null = null;
-    /** @internal */ private _logDispatchTimeout: ReturnType<typeof setTimeout> | undefined = undefined;
+    /** @internal */ private _logDispatchQueuedMicrotasks: number = 0;
     /** @internal */ private _previousLog: string | null = null;
     /** @internal */ private _previousLogLevel: LlamaLogLevel | null = null;
     /** @internal */ private _nextLogNeedNewLine: boolean = false;
 
-
     private constructor({
         bindings, metal, cuda, logLevel, logger, buildType, cmakeOptions, llamaCppRelease
     }: {
@@ -63,38 +62,13 @@ export class Llama {
             release: llamaCppRelease.release
         });
 
-        this._dispatchPendingLog = this._dispatchPendingLog.bind(this);
+        this._dispatchPendingLogMicrotask = this._dispatchPendingLogMicrotask.bind(this);
         this._onAddonLog = this._onAddonLog.bind(this);
 
         this._bindings.setLogger(this._onAddonLog);
         this._bindings.setLoggerLogLevel(LlamaLogLevelToAddonLogLevel.get(this._logLevel) ?? defaultLogLevel);
     }
 
-    /** @internal */
-    public static async _create({
-        bindings, buildType, buildMetadata, logLevel, logger
-    }: {
-        bindings: BindingModule
-        buildType: "localBuild" | "prebuilt",
-        buildMetadata: BuildMetadataFile,
-        logLevel: LlamaLogLevel,
-        logger: (level: LlamaLogLevel, message: string) => void,
-    }) {
-        return new Llama({
-            bindings,
-            buildType,
-            metal: buildMetadata.buildOptions.computeLayers.metal,
-            cuda: buildMetadata.buildOptions.computeLayers.cuda,
-            cmakeOptions: buildMetadata.buildOptions.customCmakeOptions,
-            llamaCppRelease: {
-                repo: buildMetadata.buildOptions.llamaCpp.repo,
-                release: buildMetadata.buildOptions.llamaCpp.release
-            },
-            logLevel,
-            logger
-        });
-    }
-
     public get metal() {
         return this._metal;
     }
@@ -142,11 +116,10 @@ export class Llama {
         return this._bindings.systemInfo();
     }
 
+    /** @internal */
     private _onAddonLog(level: number, message: string) {
         const llamaLogLevel = addonLogLevelToLlamaLogLevel.get(level) ?? LlamaLogLevel.fatal;
 
-        clearTimeout(this._logDispatchTimeout);
-
         if (this._pendingLog != null && this._pendingLogLevel != null && this._pendingLogLevel != llamaLogLevel) {
             this._callLogger(this._pendingLogLevel, this._pendingLog);
             this._pendingLog = null;
@@ -168,21 +141,26 @@ export class Llama {
         if (nextLog !== "") {
             this._pendingLog = nextLog;
             this._pendingLogLevel = llamaLogLevel;
-            clearTimeout(this._logDispatchTimeout);
-            this._logDispatchTimeout = setTimeout(this._dispatchPendingLog, 0);
+
+            queueMicrotask(this._dispatchPendingLogMicrotask);
+            this._logDispatchQueuedMicrotasks++;
         } else
             this._pendingLog = null;
     }
 
-    private _dispatchPendingLog() {
-        clearTimeout(this._logDispatchTimeout);
+    /** @internal */
+    private _dispatchPendingLogMicrotask() {
+        this._logDispatchQueuedMicrotasks--;
+        if (this._logDispatchQueuedMicrotasks !== 0)
+            return;
 
         if (this._pendingLog != null && this._pendingLogLevel != null) {
             this._callLogger(this._pendingLogLevel, this._pendingLog);
             this._pendingLog = null;
         }
     }
 
+    /** @internal */
     private _callLogger(level: LlamaLogLevel, message: string) {
         // llama.cpp uses dots to indicate progress, so we don't want to print them as different lines,
         // and instead, append to the same log line
@@ -210,6 +188,31 @@ export class Llama {
         this._previousLogLevel = level;
     }
 
+    /** @internal */
+    public static async _create({
+        bindings, buildType, buildMetadata, logLevel, logger
+    }: {
+        bindings: BindingModule
+        buildType: "localBuild" | "prebuilt",
+        buildMetadata: BuildMetadataFile,
+        logLevel: LlamaLogLevel,
+        logger: (level: LlamaLogLevel, message: string) => void,
+    }) {
+        return new Llama({
+            bindings,
+            buildType,
+            metal: buildMetadata.buildOptions.computeLayers.metal,
+            cuda: buildMetadata.buildOptions.computeLayers.cuda,
+            cmakeOptions: buildMetadata.buildOptions.customCmakeOptions,
+            llamaCppRelease: {
+                repo: buildMetadata.buildOptions.llamaCpp.repo,
+                release: buildMetadata.buildOptions.llamaCpp.release
+            },
+            logLevel,
+            logger
+        });
+    }
+
     public static defaultConsoleLogger(level: LlamaLogLevel, message: string) {
         switch (level) {
             case LlamaLogLevel.disabled: