Spontaneous reset around concat and number to string conversions

[pjsg]

I am tearing my hair out -- the following code (when executed) causes the system to restart:

local function sendAttr(connection, attr, val)
end

return function (connection, req, args)
    collectgarbage()
    print(node.heap())
    local x = (1).."."..44
   sendAttr(1, (1).."."..44)
end

The print of node.heap() shows 16816 -- so plenty of space left.

This code does not cause a restart:

local function sendAttr(connection, attr, val)
end

return function (connection, req, args)
    collectgarbage()
    print(node.heap())
    -- local x = (1).."."..44
   sendAttr(1, (1).."."..44)
end

This file ends up being invoked by nodemcu-httpserver which ends up running this in a coroutine.

I'm running version:

NodeMCU custom build by frightanic.com
    branch: dev
    commit: b216e6a809edd035d70536a691c4a07ac4b256a9
    SSL: false
    modules: node,file,gpio,wifi,net,i2c,tmr,uart,bit,u8g,dht,rtctime,sntp
 build  built on: 2015-11-21 19:09
 powered by Lua 5.1.4 on SDK 1.4.0

I don't expect anybody to solve my problem, but I would appreciate some hints on how to track this down. Is there a way to build the nodemcu firmware on a linux box so that I could attach a debugger or similar to it?

[nickandrew]

I'm glad you raised the issue because I've got a similar one and I was dreading having to raise an issue about it. My issue is code which reads onewire temp sensors and POSTs the temperatures. If there's only 1 sensor attached it works fine; two or more sensors will all be reported the first time through the loop, then the device resets.

It's not a problem with 2 or more sensors per se - if I disable wifi then the problem goes away; if I stop POSTing the results then the problem goes away; if I send lua commands to the device through the serial interface after booting, the problem goes away or changes.

My conclusion so far is this is not a hardware error - the various advice around the net to add capacitors on the power supply doesn't solve it - and what's happening is the lua data structures are somehow being corrupted during execution, and sending commands to the device alters its memory usage to hide (or expose) the issue.

Where I see it most clearly is a fragment of code:

function conv2()
    local pin = 3
    startConversion(pin)
    tmr.alarm(0, 1000, 0, function() conv1(pin) end)
end

Sometimes lua reports an error which indicates that conv1(nil) is being called, which means that the value of pin has been corrupted in that 1-second interval. If I hardcode 3 in both function calls, of course the problem goes away.

So I don't think your error is anything to do with string concatenation, or your code. Something is corrupting lua's data structures, and that part of code is just where the error manifests. If you change your code the problem might occur somewhere else, or disappear.

I'd love to know how to debug or single-step the firmware.

[karrots]

You can turn on the debug mode compile time option and get extra printing out the serial port.

[pjsg]

What version of the firmware are you using?

Also, is there a test suite for the firmware?

[nickandrew]

@pjsg Latest dev branch, commit g33e41a6.

@karrots NODE_DEBUG through DEVELOP_VERSION ?

[karrots]

@nickandrew the _debug ON_ checkbox if your using the nodemcu-build.com site by @marcelstoer. If building on your own turn on DEVELOP_VERSION

[pjsg]

I have built the debug version of the code, but it keeps printing

task task_lua started

and this prevents any of the uploaders that I have from uploading code to the board (esplorer and another one). Since the debug build is bigger than the original build, some of the original files are not present after the upgrade to the debug version of the build. How do people work around this?

[nickandrew]

@pjsg Can you use luatool.py to upload the code?

[pjsg]

@nickandrew Nope -- it reads back the 'task task_lua started' message and throws an error. There is actually a bug in the current version in that the error message that it tries to print references a variable not in scope. Easy enough to fix, but it is still following an error path.

[nickandrew]

@pjsg None of this is making debug easy (or, frankly, even possible). We need to be able to single-step, breakpoint and stacktrace an unmodified firmware.

I see a lot of lua_assert() and LWIP_ASSERT() in the code. I'll try to enable them without all the additional "task task_lua started" type debugging messages.

[nickandrew]

I built a firmware with DEVELOP_VERSION defined, and deleted the Task task_lua started. message from app/user/user_main.c and (fortunately) my device is still resetting. I captured this from one reset:

Fatal exception 28(LoadProhibitedCause):
epc1=0x402566d5, epc2=0x00000000, epc3=0x00000000, excvaddr=0x00004655, depc=0x00000000

[pjsg]

success! I added these lines to user_config.h

#define debug_xstr(s) debug_str(s)
#define debug_str(s) #s
#define lua_assert(e) ((e)? (void)0 :  (output_redirect(__FILE__  ":"  debug_xstr(__LINE__) ": " #e "\n"), (void) 0))

I get the following:

net_start is called.
lobject.c:88: (((t1)->tt) == 4)
lobject.c:88: (((t2)->tt) == 4)
TCP port is set: 80.
nodemcu-httpserver running at http://192.168.111.1:80
net_delete is called.
lobject.c:88: (((t1)->tt) == 4)
lobject.c:88: (((t2)->tt) == 4)

then, when I trigger my bad request:

Requested URI: /node_info.lua
httpserver-basicauth: User "user" authenticated.
Method: GET
lvm.c:330: (((top-1)->tt) == 6)
Fatal exception 28(LoadProhibitedCause):
epc1=0x40251df3, epc2=0x00000000, epc3=0x00000000, excvaddr=0x00000038, depc=0x00000000

this is all on the current dev branch. The lvm.c assert failure is in the concat implementation as I suspected. However, this provides a useful pointer.

btw, I also applied the following patches to reduce the amount of clutter:

diff --git a/app/modules/node.c b/app/modules/node.c
index d315474..8f1b002 100644
--- a/app/modules/node.c
+++ b/app/modules/node.c
@@ -385,11 +385,11 @@ static int writer(lua_State* L, const void* p, size_t size, void* u)
   int file_fd = *( (int *)u );
   if ((FS_OPEN_OK - 1) == file_fd)
     return 1;
-  NODE_DBG("get fd:%d,size:%d\n", file_fd, size);
+  //NODE_DBG("get fd:%d,size:%d\n", file_fd, size);

   if (size != 0 && (size != fs_write(file_fd, (const char *)p, size)) )
     return 1;
-  NODE_DBG("write fd:%d,size:%d\n", file_fd, size);
+  //NODE_DBG("write fd:%d,size:%d\n", file_fd, size);
   return 0;
 }

diff --git a/app/user/user_main.c b/app/user/user_main.c
index ef6c63d..6127ed9 100644
--- a/app/user/user_main.c
+++ b/app/user/user_main.c
@@ -68,7 +68,7 @@ static inline void tcp_random_port_init (void)

 void task_lua(os_event_t *e){
     char* lua_argv[] = { (char *)"lua", (char *)"-i", NULL };
-    NODE_DBG("Task task_lua started.\n");
+    //NODE_DBG("Task task_lua started.\n");
     switch(e->sig){
         case SIG_LUA:
             NODE_DBG("SIG_LUA received.\n");

[nickandrew]

My mapfile shows:

 .text.reallymarkobject
                0x0000000040256650       0xd7 lua/.output/eagle/debug/lib/liblua.a(lgc.o)
                                         0xdb (size before relaxing)

I don't know how to get an asm file to track down the exact offending instruction.

[pjsg]

OK -- I've fixed the bug in the implementation of concat -- pull request to follow. However, the assert failure in lobject.c is a little more confusing -- it may be a false positive.

The code looks like:

 switch (ttype(t1)) {
    case LUA_TLIGHTUSERDATA:
    case LUA_TROTABLE:
    case LUA_TLIGHTFUNCTION:
      return pvalue(t1) == pvalue(t2);

pvalue is defined as

#define pvalue(o)     check_exp(ttislightuserdata(o), (o)->value.p)

This assert will naturally fire if t1 is of type TROTABLE or TLIGHTFUNCTION. I don't know if the check_exp is wrong or whether this is another bug.

[TerryE]

The amount of free heap reported by node.heap() is very misleading. the firmware just uses the SDK malloc allocator, and this just does a count down / count up estimate of the total heap. But compilations the VM in general tends to badly fragment the heap space so you might have 16K free, so one issue is whether you have a large enough contiguous memory block to satisfy the current request. For. example you might have 16Kb free but the largest block available is 512bytes. In this case an allocation request of 640 bytes will fail.

I can't reconcile your (((top-1)->tt) == 6) with line 330 of lvm.c or any line in lvm.c, but this my be hidden in a macro in an include. What this is doing is test the type of the top-1 element of the current Lua Stack to see if its an integer. It looks like top[-1] is out of bounds. Once thing to note is that the Lua "stack" is nothing to do with the C stack, and is not a stack in the conventional sense. The "stack" for each function is computed during compilation and in ldo.c if necessary luaD_growstack()is called (embedded in the luaD_checkstack macro). This does a reallocvector (L148) to reallocate the stack.

I am just wondering if this realloc is failing silently and the RTS isn't picking this up.

[pjsg]

The assert is hidden inside tsvalue(top-1) -- I just filed a PR to fix the problem -- it turns out that the value of top must NOT be cached across a call to tostring() which returns != 0 as it may have triggered a GC.

[TerryE]

@pjsg Philip, I am a little confused by what you've found. lua_assert isn't defined in normal lua and luac builds and therefore defaults to (((void) 0), v) in other words just the second value. I've used in the Lua test suit for testing my LCD patch. So how are you enabling it? That aside you are correct in that if evaluated then the the assert should be true. Hence the code should be:

switch (ttype(t1)) {
    case LUA_TLIGHTUSERDATA:
      return pvalue(t1) == pvalue(t2);
    case LUA_TROTABLE:
      return rvalue(t1) == rvalue(t2);
    case LUA_TLIGHTFUNCTION:
      return fvalue(t1) == fvalue(t2);

[pjsg]

@TerryE In one of the comments above, I showed what I put in user_config.h to enable lua_assert -- it is three lines that defines lua_assert as a macro and then the usual override to ((void) 0) doesn't happen any more. I also enabled debug mode, but I'm not sure if that was actually required to make the lua_assert stuff actually work. I only tested on the integer build of the firmware.

I have also seen (once or twice)

lvm.c:459: L->top == L->ci->top || luaG_checkopenop(i)

lvm.c:454: base <= L->top && L->top <= L->stack + L->stacksize

This looks as though the main interpreter loop has a case where it fails to reset 'base' after a potential GC.

[TerryE]

nodemcu is a fork of eluas which is itself a fork of Lua.5.1.5.

My presumption if I find an issue in the bits of the code base that have been added by this project is that the issue might be our coding bug.

However for the Lua 5.1.5 code has been pounded to death and it is extremely unlikely that there is be this sort of bug remaining. My presumption in this case is that the problem is in my under standing or peripheral bits rather than the core implementation. This patch proposes a change to the core code,

So -1 unless you provide compelling evidence that this is a genuine bug and that your patch fixes this.

Incidentally I always test changes to Lua core functionality on a bog standard Lua 5.1.5 build under Linux on my PC where gdb and the Lua test suite is available to me before porting them to nodemcu.

[pjsg]

@TerryE Actually, this does appear to be nodemcu specific and not in standard 5.1.5.

Rationale:

The luaV_concat function calls tostring early on in the loop and if it returns non-zero, control passes to the else clause where (in the original nodemcu code) top is used unaltered. This is a problem if there has been a GC (inside tostring).

tostring calls luaV_tostring
luaV_tostring calls luaS_new
luaS_new calls luaS_newlstr
luaS_newlstr calls luaS_newlstr_helper
which calls newlstr
which calls luaS_resize
which calls luaM_reallocvector
which calls luaM_reallocv
which calls luaM_realloc_
which calls a function through G(L)->frealloc

The actual chance of this happening is small, but it was happening reproducibly for me.

In the stock lua-5.1.5, the frealloc function is mapped (via l_alloc) onto native c runtime calls
In nodemcu firmware, l_alloc calls luaC_fullgc

If this full gc moves the stack, then the top pointer from many stack frames above is now invalid. My PR fixes that problem by resetting it.

Now, this analysis suggests that there may be other lurking problems -- the mainline lua code may assume that certain sorts of memory allocations cannot trigger GCs. This assumption is not true for nodemcu.

[TerryE]

This looks as though the main interpreter loop has a case where it fails to reset 'base' after a potential GC.

?? base is a pointer into the lua stack. The lua stack is only adjusted in luaD_reallocstack() which is called from luaD_growstack() typically immediately before calling a function. This calls the static correctstack() which rebaselines the L->top, L->base etc. None of the routines in the VM maintain local copies of L->base etc. across such a call.

If this full gc moves the stack, then the top pointer from many stack frames above is now invalid. My PR fixes that problem by resetting it.

The preceding is a great piece of analysis, but I feel that this assertion is the flaw in your thesis. The Lua GC never moves memory blocks. It uses a mark and sweep algo only to determine dead Lua objects and then frees the associated memory via sweeplist() which is called from singlestep() on a GCSsweep.

What might be more plausible IMO, is that the SDK memory allocator is somehow getting its knickers in a twist. However if your thesis is correct then you should be able put assertion diagnostics in the old code to detect the error when occurring. For example replace your reassignment of top = L->base + last + 1; by a lua_assert(top == L->base + last + 1);.

You need to compare eLua sources with the EGC patch which is pretty similar to nodemcu.

[pjsg]

The lua stack is only adjusted in luaD_reallocstack() which is called from luaD_growstack() typically immediately before calling a function. This calls the static correctstack() which rebaselines the L->top, L->base etc. None of the routines in the VM maintain local copies of L->base etc. across such a call.

Ah - yes. However, following on from my previous message:

luaC_fullgc calls singlestep
which calls propagatemark
which calls traversestack
which calls checkstacksizes
which calls luaD_reallocstack

Actually following this gives me a much better idea of when this might happen -- in particular when there is more than one thread around and when the stack in one of those threads can be shrunk significantly.

I did have an instrumented version of the firmware that showed that the L->base did indeed change over a call to tostring. This was what pointed me in this direction in the first place.

Actually, there are a number of places where a true C pointer into the stack is cached across calls. There is the case of 'top' in luaV_concat across tostring(). Also, in luaV_execute, 'base' is cached across calls. However, in many cases, it is reloaded at the end of the interpreted instruction (normally via the Protect macro). Presumably in the other cases, there is no chance that the GC will be called.

[TerryE]

which calls checkstacksizes
which calls luaD_reallocstack

Yes but the second call is guarded by a isfixedstack(() check, so this is only called between unfixedstack(() and fixedstack(() bookends. Need to review lapi.c, ldo.c and lvm.c for these pairs to see if this exposire is in practice.

Think of Popper: you have a testable hypothesis. If the lua_assert() discussed in my previous post fires then you have demonstrated that this failure is occurring, -- and we are talking fact and not hypothesis.

Anyway, it's nice to find someone else who is willing to dig into these internals! 😃

[pjsg]

I have a testable hypothesis. I altered the luaV_tostring code as follows:

int luaV_tostring (lua_State *L, StkId obj) {
  if (!ttisnumber(obj))
    return 0;
  else {
    char s[LUAI_MAXNUMBER2STR];
    ptrdiff_t objr = savestack(L, obj);
    lua_Number n = nvalue(obj);
    lua_number2str(s, n);
    StkId oldbase = L->base;
    setsvalue2s(L, restorestack(L, objr), luaS_new(L, s));
    lua_assert(oldbase == L->base);
    return 1;
  }
}

The change is to add the saving of L->base to oldbase and then the assert afterwards. This assert fires when I run my testcase. I have a simplified version of my testcase:

function count(x)
  if x <= 0 then
    return 0
  end
  return 1 + count(x-1)
end


function test()
  count(64)
  local x = 1 .. "." .. 44
  print(x)
end

test()

As I read the code, the call in traversestack is

  if (!isfixedstack(l)) /* if stack size is fixed, can't resize it. */
    checkstacksizes(l, lim);

so the question is whether the stack is fixed at this point.

propagatemark doesn't set fixedstack
neither does singlestep
neither does luaC_fullgc
neither does l_alloc
neither does luaM_realloc_
etc.

I was thinking about this last night, and I'm coming to agree with you that this may not be the right fix. It certainly fixes the bug, but the right solution may be to do it much deeper in the code -- otherwise we will be playing whack-a-mole for a while. However, the penalty for doing it deeper in the code will be that more calls to GC will not be able to save memory from the stack.

[TerryE]

@pjsg Phillip, thanks for this, but I would like to take 24hrs to brood about this. I would really welcome your contribution to any resulting discussions.

[TerryE]

@pjsg Philip, I can reproduce this as well. Here is my minimal version:

-- execute simple recursive function to grow stack and then concat which fails if OP2 numeric
do local function count(x) return x > 0 and count(x-1) end count(64) local x = "a"..1 end

The issue is with the line

    if (!(ttisstring(top-2) || ttisnumber(top-2)) || !tostring(L, top-1)) {

top-2 is a string so the third term is evaluated. Moreover, top-1 is a number so luaV_tostring() enters GC as part of the conversion. This returns success so the else statement is executed with an invalidated top. Hence the two reported errors:

lvm.c:80: oldbase == L->base
lvm.c:336: (((top-1)->tt) == 6)

Also note that replacing the concat with x = (1)..'' also triggers a stack trim but as top isn't used on this path, only the first assert error is reported.

I am off visiting relatives for a couple of days but I'll put in a proper fix when I get back. Thanks again. Terry

[nickandrew]

Why do we allow developers to visit relatives? :-)

[pjsg]

Thanks muchly...

[TerryE]

A corollary to this is that with the EGC running, any operation which does a malloc or realloc can trigger EGC and render invalid any such pointer. The stack can get trimmed and table hash tables if I recall. But the latter entries probably won't get cached, just the address of the the entry they point to.

[pjsg]

I was thinking of changing (for dev purposes) the GC so that it always trims the stack (unless isfixedstack is set) and see if that exposes anything.

I'm not sure of the best way to find these potential issues. I have another assert failure which happens after I run the uploader to upload files and then I switch to esplorer. The first thing that esplorer does is to send '=node.heap()'. Sometimes, this causes an assert which seems to be associated with returned data.

in lvm.c lua_assert(L->top == L->ci->top || luaG_checkopenop(i));

[pjsg]

I found an interesting #define -- try adding

#define HARDSTACKTESTS

This does much more resizing of stacks.

My code that makes sure that every realloc does move the block causes all sorts of problems in conjunction with the above #define. In particular, I get a block too big error when requesting memory.

However, if I make the same changes to the 5.1.5 lua interpreter and enable the HARDSTACKTESTS, then I get no assert failures. I'm going to work on some more debug code and verify that it doesn't trigger in lua-5.1.5 and then port it into nodemcu.

[pjsg]

There is a major difference between the standard lua-5.1.5 and the nodemcu version. This is that the lua-5.1.5 memory allocator does not call luaV_fullgc when invoked. Yes, the code is there to call it, but the precondition is not met. If you enable the precondition (as in nodemcu firmware), then it too crashes spectacularly. In luaL_newstate, there is an extra line in the nodemcu firmware:

lua_setallocf(L, l_alloc, L);

This passes the lua_state pointer into the lower level allocator -- and this enables the allocator to trigger a full gc.

Testing the 5.1.5 interpreter is a much more pleasant experience as you can run it under gdb (or any other favorite debugger). However, there are lots of assert failures. I think that the HARDSTACKTESTS are broken as they keep shrinking the stack even when the upper levels are trying to increase them. It isn't clear to me whether the nodemcu firmware suffers from this particular problem. For lua-5.1.5, for example, in luaD_precall, it ensures that there is LUA_MINSTACK stack space. Then it does some more memory allocations, and then it can fail as the stack no longer has LUA_MINSTACK space.

The stock 5.1.5 lua has no mechanism to be able to stop the fullgc from happening during these critical periods, but the nodemcu firmware does. I fear that trying to debug with 5.1.5 is a lost cause....

[TerryE]

This functionality is known as the EGC and the author's documentation is here. It might be worth looking at applying the EGC patch to the standard Lua distro for testing purposes.

[TerryE]

OK, I've had a trawl though all of the local StkID declarations and usage looking for cases where the variables can be invalidated by a realloc side-effect and thislvm.c case is the only one that I've found. I've drafted and compiled a patch based on moving around a couple of fix / unfix stack bookends, but I can't test it until tomorrow when I get home and get my hands on some ESP modules.

[TerryE]

In the history of eLua, there was a build which ran as a host application, but I gave up on trying to get this to work.

[pjsg]

I'm making progress -- I only get one assert with any regularity

lvm.c:475: L->top == L->ci->top || luaG_checkopenop(i)

The other issue is that node.compile("somefile.lua") appears to work if it is not run inside a pcall environment. If run inside a pcall, then it completes, but manages to corrupt something and soon thereafter the wdt resets the platform,

I ended up changing the way that the GC resized the stacks. In my model, the GC is never allowed to resize the stacks unless specifically allowed to -- i.e. the fixedstack() status is now effectively on all the time except for one place where everything is (I think) safe to move/resize things.

Are other people seeing any asserts firing?

[TerryE]

Philip, can you split this into two asserts for testing. I suspect that it's the luaG_checkopenop(i) that's failing.

The fix/unfix stack operation is pretty lightweight. This was introduced as part of the ECG patch. We found a case that the author, Robert Jakabosky, missed. My inclination is to minimum scoped change unless there is a compelling otherwise and I feel that a shift from default "can resize" to "can''t resize" doesn't fit well here and might have other unintended consequences. This being said, I'll upload my PR for this fix today and you will see that I am extending the fixed scope.

[pjsg]

After tearing my hair out some more with regard to the node.compile problem, I reverted to the stock dev firmware. It fails rather worse (or better) depending on your point of view -- it just triggers a reboot almost immediately.

httpserver.lua.txt

If you upload this file to your nodemcu (and call it httpserver.lua) and then run, from the prompt, node.compile("httpserver.lua") -- what happens?

[TerryE]

I have just raised PR #812 to fix this ECG patch error. I when therough all of the cached stack pointers and only found this one case that Jakabosky missed. IMO, this closes the original issue here, but some of the wider points that Philip raises still stand, but probably merit being swept up into another issue.

[TerryE]

After tearing my hair out some more with regard to the node.compile problem

NodeMCU 1.4.0 build 20151006 powered by Lua 5.1.4 on SDK 1.4.0
lua: cannot open init.lua
> print(uart.setup(0, 115200, 8, 0, 1, 1 ))
115200
> 
Communication with MCU...
Got answer! AutoDetect firmware...

NodeMCU firmware detected.
=node.heap()
42416
> =node.compile("httpserver.lua") 
> =node.heap()
41936
> 

This is a minimal build (bit, file, gpio, net, node, rc, rtcfifo, rtcmem, rtctime, spi, tmr, uart, wifi) with #812 applied.

[pjsg]

I cut everything back, and my code is now stable (apart from the solitary assert which I have put into its own ticket).

In particular, I have a custom implementation of c_realloc and c_free that performs extra checking and always moves blocks when realloc is called (to make sure that nobody is looking at the old block). Further it sets any block being freed to 0x55555555 so that code should trap if it tries to use a pointer from the freed bock. Even with this, it looks good!

[TerryE]

This one was fixed some time ago.