RFD - Enable module-specific debug

[nickandrew]

Debugging firmware errors with #define DEVELOP_VERSION results in excessive and unwanted debugging messages through the NODE_DBG() macro which is defined as c_printf when enabled, and nothing when disabled.

I suggest splitting NODE_DBG into one macro per module, which can be individually enabled in app/include/user_config.h. There'd be 30-40 of these macros, so a naming standard is required, and I suggest using DEBUG_MODULE_MODULENAME.

To start, I edited net.c:

#define DEBUG_MODULE_NET

and bulk-changed NODE_DBG to DEBUG_MODULE_NET

--- a/app/modules/net.c
+++ b/app/modules/net.c
@@ -59,7 +59,7 @@ typedef struct lnet_userdata

 static void net_server_disconnected(void *arg)    // for tcp server only
 {
-  NODE_DBG("net_server_disconnected is called.\n");
+  DEBUG_MODULE_NET("net_server_disconnected is called.\n");
   struct espconn *pesp_conn = arg;
   if(pesp_conn == NULL)
     return;

and that had the desired effect of eliminating just those messages, while leaving other debugging (which I added according to issue #795) intact.

[jmattsson]

Something like this would be a nice quality of life improvement. I never build with DEVELOP_VERSION precisely because it is far too noisy.

Would we really need to put all these macros into user_config.h though? Might it not be better to have the module debugging fully contained inside each module? My reasoning is that if someone is wanting to debug a module, they're probably building locally anyway, and changing a #define in the .c would be just as easy (if not easier).

[nickandrew]

The macro definitions could be moved into each module, but on the other hand, having them all in the same .h file promotes naming consistency and makes them easier to find.

Rather than clutter user_config.h, I could put them all into user_debug.h.

The main argument I can see for not clustering the macros is build dependencies; enable debugging on any macro and every module file will be rebuilt.

[pjsg]

However, rebuilding the entire image doesn't take that long anyway (from clean). I'd stick them in a single file. Also, would you consider putting the lua_assert stuff in there as well to make it easy to include?

[nickandrew]

@pjsg Might as well. Re #795, do you have code to print a call traceback or stack dump?

[pjsg]

#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 have a more sophisticated version that make node.assertfails() return the count of assert failures since startup. However, that may be more than what you want....

[nickandrew]

@pjsg I'm just hoping to find out how you got the exact call sequence from tostring to G(L)->frealloc.

[pjsg]

I did that by looking at the code. The problem was that the assert fired at the top level. However, knowing which assert fires is a big step forwards to finding the issue.

In your case with the mysterious closure issues, I would hope that a funky assert would fire, and this might help narrow the problem down.

[marcelstoer]

My 2 cents...

excessive and unwanted debugging messages

Excessive yes but unwanted? I never found myself in a situation of needing debug messages but if I did wouldn't I be interested in more than just the messages from the module I suspect of being fishy? Just because my CoAP code fails doesn't necessarily mean I should be looking at CoAP debug messages in particular - or is it? More questions than answers, sorry.

I suggest splitting NODE_DBG into one macro per module, which can be individually enabled in app/include/user_config.h.

What do you guys suggest I do in the cloud build once a PR like this would land? I currently have a single checkbox with a "warning" label that says:

turn it on only if you're troubleshooting an issue with NodeMCU developers as it will increase the size of the firmware and decrease its performance

We seem to agree that such a feature isn't for the general public at least 😉

[pjsg]

One of the problems with the current debug code is that (as far as I can tell) you can no longer upload code to the nodemcu as there is so much debugging output that the uploader gets confused and thinks that the upload doesn't work.

On a bigger platform, I'd have a 32-bit field, and each bit would control debug output from each of 32 subsystems. This way, output could be disabled/enabled individually. Given that this is just debug code, maybe this is the way to go here as well. The extra overhead of testing a bit is not huge. I'd be inclined to still have (up to 32) different DEBUG macros which implicitly perform the bit test and then call the underlying debug output call. I'd also be inclined to include in the debug strings the file and line number.

[nickandrew]

@marcelstoer The debug messages appear to be of two main types - the lua_assert which are only triggered when something wrong is detected, and NODE_DBG() which are more logging what the system is doing (although they may be inside a conditional and so appear only in error situations).

I think a developer doing debugging would generally want all the assert checks enabled, but not necessarily a whole bunch of log messages which denote normal system behaviour. So I'm just coming into this from the point of view of making the NODE_DBG() messages optional, and doing it on a per-module basis seems the most rational.

For your build service, I suggest removing the debug checkbox, as the messages are for people debugging the firmware, which can't be done effectively unless those people also have the ability to modify the firmware and build it themselves with patches. If a firmware developer needs logging information from a general user (because a problem can't be reproduced without the right hardware configuration, say) then the developer can build a 1-off firmware and send it to the user.

[nickandrew]

@pjsg Using a bitfield and testing it at runtime means all potential messages must be compiled-in, whereas they just vanish with a disabled macro. Also I expect we'll exceed 32 categories, and what to do when we run out?

Adding file and line number is a good idea, I think it could be done in macros.

[pjsg]

I would definitely want to leave the debug checkbox present and have the lua_assert messages all enabled. In particular, I have only seen the hardware fault messages with the debug builds that I have done. This seems useful -- in fact so useful, I would want them enabled under all circumstances (unless the code space required is prohibitive). I haven't looked to see where those are generated.

Also, it would be good to fix the various uart speed changes that happen. It appears that the early boot messages come out at 115000 and then (in develop mode) it drops to a lower speed. For non-debug builds the speed is 9600 after some point. [As a side note, the uploader that I use cannot upload at the debug speed (78k??) so I have to switch it to 9600 before doing an upload. If we want to encourage debug builds, then having the speed set to 9600 would be a good start. If (by default) all the NODE_DBG calls are disabled, then there will be no(?) additional output and hence the slow speed won't matter.]

[pjsg]

@nickandrew Currently, if you do a debug build, you get all the debug messages compiled in. This scheme is only slightly worse (as each message would get the FILE and LINE number prefixed). [The lua_assert macro above does include the preprocessor trickery to get the file an dline number prefixed onto each message]

I guess it depends on what the purpose of the debug build is. My take is that they serve two purposes:

1: A user has a problem with the regular code. A nodemcu dev tells them to build a debug version (using the online builder) and try running their code again. Maybe enable a few categories of debug message -- but that can be done once the user is running the debug firmware. Yes, this may not work if the user has a 512K esp8266.

2: A dev wants to debug something very particular and is adding extra debug messages/asserts. In this case, they are building their own images. They can disable whatever they like -- they are probably hacking header files anyway.

What is important is that the debug messages should not burn up precious RAM!

[nickandrew]

@pjsg I think you and I are only seeing the hardware fault messages now because DEVELOP_VERSION sets bitrate to 74880 and that's the same speed the hardware faults are emitted.

Funnily, even though the bitrate is 74880, I see the messages at 38400. I have no idea why, except that 74880 is roughly twice 38400.

[nickandrew]

This explains why 74880, the non-standard baud rate in particular: arduino/Arduino#3389 (comment)

The 74880 baudrate is directly related to the quartz used on ESP8266, if you use a 40MHz clock the standard baud is 115200, but on all ESP8266 that we have on ebay and other manufacter is used a clock of 26MHz and automatically the baudrate become 74880

I still have no idea why I can see the output at 38400.