(SOLVED) Random crashes with log listener callback

Questions
#1

Putting this in #questions since I’m not 100% sure if it’s me or Defold doing something wrong.

A library that I’m working on uses a native extension to register a log listener that passes the messages to a Lua callback for it to handle. This all works great, except that it eventually crashes the engine with a different error message each time! It’s usually a failed DM_LUA_STACK_CHECK() or a similar Lua-related assertion. Sometimes you get fun errors like this where the render script can’t access render functions :upside_down_face: :

ERROR:SCRIPT: builtins/render/default.render_script:82: You can only access render.* functions and values from a render script instance (.render_script file)
stack traceback:
  [C]:-1: in function clear
  builtins/render/default.render_script:82: in function <builtins/render/default.render_script:71>

Anyways, almost all of the code is from official examples and I (a non-C++ programmer) can’t see anything wrong after looking for quite a while. Here’s the relevant extension code:

dmScript::LuaCallbackInfo* cb = 0;

static void LogListener(LogSeverity severity, const char* domain, const char* message) {
    if (!dmScript::IsCallbackValid(cb))
        return;

    lua_State* L = dmScript::GetCallbackLuaContext(cb);
    DM_LUA_STACK_CHECK(L, 0);

    if (!dmScript::SetupCallback(cb)) {
        dmLogError("Failed to set up callback");
        return;
    }

    lua_pushstring(L, domain);
    lua_pushstring(L, message);

    dmScript::PCall(L, 3, 0);
    dmScript::TeardownCallback(cb);
}

static int LuaRegisterCallback(lua_State* L) {
    DM_LUA_STACK_CHECK(L, 0);

    cb = dmScript::CreateCallback(L, 1);

    return 0;
}

I’ve also made a minimal project that has the same error, just run it and wait a few seconds:
example.zip (4.0 KB)

In case it’s important, I’m running the latest Fedora Silverblue (37.20230227.0) and Defold 1.4.3:
Screenshot from 2023-03-01 21-08-03

1 Like
#2

It could possibly be logs generated from a different thread than the main thread. I can’t remember if you need to handle thread safety yourself or if we do this for you. @JCash will know. I can look it up this evening if @JCash is busy at DevGAMM all day.

1 Like
#3

It’s probably what @britzl says.
You get the callback from the log thread, so you need to make sure that you only call to Lua from the Lua (main) thread, or you’ll thrash the Lua context.

I’ll have a look at the repro later today.

1 Like
#4

Correct.
After looking at the code, this is the case.

To solve it, you need to store the log strings that you get from the log thread.
Then in your UpdateMyExtension(), which is run on the main game thread (where Lua runs), you can invoke your Lua callback with those strings you stored.

Make sure you copy the strings, not just keeping the pointers to the strings.

And, yes, this should be more clearly stated in the documentation :slight_smile:

2 Likes
#5

FYI There is an example of how it can be done, i.e. the extension uses a queue for log messages:

5 Likes
#6

Thanks all! I’ve managed to get a working version based on the project @aglitchman linked.

Are there any docs for the different threads Defold has? I’ve had a similar issue where I was using dmHID on the wrong thread.

2 Likes
#7

No, we do not have this documented. Searching for dmThread or similar should give an indication.

1 Like