Multiple occurances during a trace() output request along with suggested fix

Wed 2020.04.29

While attempting to resolve a low memory error condition, I stumbled across an infinite while
condition during a trace() operation. Initially, I thought I was up against a garbage collection
process anomaly, until I obsereved a weird dump() output. Attempting to also capture a trace at
the same time, allowed this oversight to be revealed.

I attempted to resolve this in post #9 thinking this was specific to the online IDE

post #9   Sanity check for Wifi and http modules

but a resolution to capture the trace output was never responded to, and during the wait, I ended up having to stitch what I could.

// many iterations of the following as one contiguous block


                  #489[r1,l2] Name String [1 blocks] "w"                    #490[r1,l0] Function {
                      #491[r1,l2] Name Param "\xFFa"                         undefined
                      #492[r1,l2] Name Param "\xFFb"                         undefined
                      #494[r1,l2] Name String [1 blocks] "\xFFcod"                        #493[r1,l0] NativeString [1 blocks] "if(b)return a(b);f.cmd(\"AT+CWMODE=\"+p+\"\\r\\n\",1E3,function(b){\"no change\"!=b&&\"OK\"!=b&&\"WIFI DISCONNECT\"!=b?a(\"CWMODE failed: \"+(b?b:\"Timeout\")):a(null)})"



// many more deleted - included in attached file

EDIT: Just uncovered that there are characters in the output that prevent rendering here, so will provide the text output as an upload.

The best I could do, as there was a massive amount of characters in the console text area I attempted to copy to the clipboard, and that process was flawed, limited by what could be seen as mouse scroll prevented more than around twenty at a time. I even attempted to just move to the top of the console window, but the sequence of events that led up to the decision to perform the dump() and trace() were forever gone to the Goddess of byte reclaim heaven.

@Gordon 's assistance in post #6 and #8

Help needed on trace()

allowed me to look into the underlying code that produces the trace output. To those curious onlookers, I highly recommend spending an hour and follow all the links presented to get a better grasp on how stuff works under the hood, and maybe down the road have some insight to locate the code line and provide assistance in providing a suitable fix for your issues that are uncovered.

Posted a suggested fix in issue #1809 at GitHub

Endless while loop inside trace() suggested fix #1809

Now back to the vain attempt to make this condition repeatable in order to provide an example and it's resulting trace output.

---

1 Attachment

• TraceRepeatForum.txt

Do you have the actual code and steps to create the error? I'm afraid that small section of trace output isn't enough to get any useful information.

If Espruino is constantly writing to the terminal, you can also just disconnect, then it stops updating and you can copy/paste all you like.

Thr 2020.04.30

'that small section of trace output isn't enough to get any useful information'

I was also under the same assumption as I attempted to get at the culprit from the console. As I explained while using the online IDE, that browser tab instance became corrupt, not allowing easy drag through (similar to Ctrl+A) forcing me to attempt to stitch what I could back together. Felt that the observation of endless while trap was more important, and provided the best I could to get at least something documented.

'Do you have the actual code and steps'

Pretty much spelled that out in the last line of the post. I'm fearful of just providing what I 'knew' at the time as I'll guess you'll want to 'know', that burning desire to get at it right now, will start down a path of no such luck, when focussing on Bangle is where your skills are currently needed. But to placate you for a bit, the first link in post #1 points to the code block I started with. Under a hunch to initially find out if the templated string issue had been merged into the online IDE, as I also wanted to test some templated code, I loaded that up instead of the native .exe WebIDE, also knowing that the native IDE will eventually be replaced, so wanted to compare their also.

What I was in the process of doing, was to upload that code block from a file that I had been editing in notepad++ as I have done for all projects. I then cut-n-paste working code snippets into the console side, which 99% of the time don't require editing, as they have worked in other projects. I had been using dump() and trace() to copy to a file for ease of review in notepad++ as I saw an anomaly within dump(). In my haste, as I knew trace() would be needed, I bypassed grabbing the dump() on it's own. To my surprise, when I ran trace(), the output was just updating as slow as a BLE upload might look, so I walked away for a bit. Came back and it was still updating, even though there were only a hundred lines or so of code. As I had a fair amount of experience using trace(), knew that couln't be the case so attempted to grab what I could, but mouse highlighting wouldn't allow a similar Ctrl+A grab. The rest is outlined in the initial post.

As what I really needed were the steps and snippets, what I had entered initially but as indicated had scrolled North, so the actual steps are gone, but I had pencil'd a few notes and as I pointed out in the last line, will make a vain attempt.

Sun 2020.05.03

'Do you have the actual code and steps to create the error'

Ask and ye shall receive . . .

The following is a challenge to @Gordon, @allObjects, @AkosLukacs, @MaBe, etal to reveal possible reasons for this anomaly before actually reading on, and no peeking with tools or accessing the console until some thought is given.   Game anyone?

When performing your individual test, it will be necessary to modify the code file to supply your known IP and p/w - Espruino WiFi required

Use the online WebIDE first, to also observe the corrupt console Window. Caveat, my tests are only on Windows10, so it could be that this is only related to MS. Same results with native .exe WebIDE.

https://www.espruino.com/ide/

Symptom: Performing a trace() loops indefinitely.

Do the following:

• Load code file codetinyMQTT20200503FORUM.js
• execute function c() in order to connect - wait five seconds for "connected!" response
• *(should the response not occur, don't continue as results will differ)*
• execute trace() and observe the endless loop

Why would the following code snippet cause the symptom above?

var server = "192.168.1.70";
//var server = "127.0.0.1";
//var server = "0.0.0.0";

var mqtt = require("tinyMQTT").create(server);
//mqtt.connect(); // Connects on default port of 1883

mqtt.on("connected", function(){
  console.log("connected");
});


var wifi = require("Wifi");

function c() {

wifi.connect("2WIRE", {password: "33212052"},
  function(err){
  if(err) {
    console.log(err);
  } else {
    mqtt.connect();
    console.log("connected!");
  }  
  });

}

Syntactically nothing. So before reading on, what might cause trace() to loop indefinitely?

No peeking - withdraw and ponder for an hour before continuing okay?

Okay, you peeked. Now, while I might concede that extra steps may/should be used by the end user/developer before final implementation, I took the examples right off the site tutorials and plugged away. Others might/will do the same.

What I discovered may/might also be the reason for my 400 JsVars of memory just evaporating (see rationale later), but won't be able to confirm until this is resolved.

Now, before peeking, I originally thought this to be specific to tinyMQTT as there is an outstanding GitHub issue #1583, but what is there, isn't related to the conditions here.

So, lets try just a basic http fetch, without MQTT

• Load code file codeWiFi20200503FORUM.js
• execute function c() in order to connect - wait five seconds for "connected!" response
• *(should the response not occur, don't continue as results will differ)*
• execute function g() to allow a get fetch of the resultant text file
• execute trace() and observe the endless loop

Before moving on to review of the output, realize that I have had intermittent issues for over two years, and I am pushing the memory limits of Espruino to be able to use the WebIDE console as an interactive interface for users. This means lots of console.log() statements, and the need for short function names to avoid having to type things like process.memory() out every two minutes.

To get around that I've been using a short function name for common commands. Stuff like s() for setup, r() for run, t() for test, v() for verify, w() for watch, p() for process.memory().

Now ask yourself what is the pattern here that would allow those to work, yet with the same practice, is now problematic?

Think about that before taking a peek at dump() and trace()

Now, the proper sequence to reveal needed detail as one will discover is to:

• reset(1)
• Load code file
• dump()
• trace()
• c()
• dump() - this is where the observant will gain the insight
• g()
• trace() - opt as will loop endlessly

So, figured it out? - surprising, isn't it!

Reviewing:

https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Statements/var

and specifically heading 'Initialization of several variables'

  var x = y = 1; // Declares x locally; declares y globally

confirms what I had observed a week ago.

View attached file 'wifi.connect.txt' for unminified detail

If one takes a peek at the .connect function() and yes, reverse minification is a real pain, even with online tools, I believe I've found the culprit, but wanted to provide the opportunity for others to discover also.

I've spent nearly a hundred hours testing and comparing just to identify what is happening and have 6Meg of data comprising of around three hundred dump and code files, should any of that be required. Why so long you ask? Well as the console either locks with a low memory situation or as in this case trace() causes an endless loop, it is not possible to get at the console to peek around. So, developing a technique ahead of time and comparing with a ton of data was the only way achievable. Now that I have discovered a repeatable situation, it is easy enough to build your own.

GitHub issue #1811 Anomaly in deployed module corrupts user namespace global scope #1811

Case revealed, but not solved.

Pardon me, back to a twelve year Rye I've been sippin' on . . . .

---

3 Attachments

• codetinyMQTT20200503FORUM.js
• codeWiFi20200503FORUM.js
• wifi.connect.txt

but a resolution to capture the trace output was never responded to

I did respond. Literally all you have to do it click 'disconnect' if data is being printed to the console - then you can scroll back, highlight and copy however much you want.

If one takes a peek at the .connect function() ... I believe I've found the culprit,

Please can you point to exactly what you believe is the issue?

Symptom: Performing a trace() loops indefinitely.

Are you sure? Because I just tried this exactly as you said and it appears to be dumping a lot of data, but it does finish eventually. The issue is a lot of functions store their declaration scope in "\xFFsco" which gets printed as well, so that is duplicated each time (because they're all defined in the same scope) but you can see the function name changes each time.

How long did you wait for it to finish?

Perhaps you could post up the a of an infinite trace that you do have (or part of it).

Tue 2020.05.05

I've done one better. Here is what I see in each of two twenty second clips. I think you'll agree that isn't how it should be working, right?

In the first pass trace takes about five seconds and I note that the it outputs it's pound ID references up to around ~#600. During the second pass, as shown in the clips, the IDs are now in the thousands, and it takes more than ten minutes to output at which time noting the repeating data, I just abort.

As it appears your Linux developer station is unable to replicate, lets verify that. Follow the last sequence of steps in #4 post, placing ten or more carriage returns between each step so that I'll be able to examine quicker, but for the first file, don't include the last trace(). That'll create around 100K which will be able to be captured from the console using the mouse drag select process. Should the error be there, then performing the last trace() will need at least two more passes, to grab anything of use, but it will push the first steps North, the reason to save that content first.

With that, I should be able to point to exact lines within your file, and then show a line by line comparrison in my file. We'll then know if it is a Windows only or reproduceable on Linux then.

---

4 Attachments

• trace1.swf
• trace1.swf.html
• trace2.swf
• trace2.swf.html

This is what you'd expect, and what I see too. The slow trace speed is because trace is a debug tool, and at each step Espruino is searching through all variables to see if it can figure out if any of them have a 'global' name. Normally it's pretty quick but the Wifi code is complex enough that it takes a while to scan through everything.

Let's look at trace2.swf - it seems the video wasn't left running long enough to show any of the repetition, but...

You can see what I think is the mqtt.connect function being dumped, with its scope as "\xFFsco" (mentioned above) which is the big area you're seeing repeated.

You can then see subscribe which is another mqtt function. The video stopped here, but since it's a function declared in the same scope you'd see another identical "\xFFsco"

But it's pretty obvious it's not getting in an endless loop, because each time the function name being printed is different each time.

Wed 2020.05.06

@Gordon, and your output is also taking ten minutes and that is normal for a ten+ lines of code? Why does it take five seconds the first time but ten minutes the second? Please provide the output as I requested in #6 post and I'll show what is being missed. The twenty second .avi file capture was over 500M. Ten minutes of output would be 15G.

and your output is also taking ten minutes and that is normal for a ten+ lines of code?

Yes. When you're calling a debug command that's designed for looking at small sections of code in detail, and you then apply it to an entire WiFi and MQTT driver on a small embedded device, that's what happens.

It's not 10 lines of code. It's at least 700 lines of very dense JS.

Please provide the output as I requested in #6 post

No. I actually did this before in order to test what was going on. I'm not doing it again just so I can record it for you.

I've already wasted a vast amount of time trying to help you, and trying out your suggestions to reproduce and figure out what's going on.

But as I suspected there's no problem. This is very obviously NOT and "infinite while
condition" as you mentioned, and you obviously neglected to mention the fact that your infinite loop did in fact end, it just took a while.

At this point it seems obvious you haven't taken on board anything I've been saying in the past few posts, and you're just wasting my time even more.

If anyone else wants to jump in here you're welcome, but I'm done with this.

Wed 2021.10.27

I am not appending to this thread with the intent to solve the original post #1 inquiry.

What was attempted to be solved then was a result of chasing the symptom, and not the actaul cause as I shall explain.

It became evident that the way in which the Trace output behaved was a direct result of the corruption caused by the underlying task that has just recently resurfaced again.

re: 'It's not 10 lines of code. It's at least 700 lines of very dense JS.'

It is amazing that 18 months have elapsed and no others have stumbled across what I spent many weekends of countless hours testing and documenting then, that is until now.

@skm recent post again reported this discovery

using c.test in E.showMenu

The endless anomaly above occurs after my source gets clobbered just using the Wifi or tinyMQTT module functions in a similar manner to how @skm did in the above thread link.

It appears that user defined single character function names and var declarations are affected. In the following link, several single char objects up to letter 'f' get clobbered, so my hunch is that it is for all letters of the alphabet that minification may produce it's own instance. From using Google's closure compiler, I've had the full range of the alphabet in resultant output, so this is quite possible.

Back on Sun 2020.04.26, I had provided unique example code snippets using the Wifi module demonstrating this:

Sanity check for Wifi and http modules please getIP getAPIP

and another

Multiple occurances during a trace() output

Which included an example using a Wifi method in post #4 with steps to reproduce.

post #4    code blocks to create the anomaly

You'll note that I pared down the snippet to a basic example that coincidentally has the same single char function that gets clobbered when those moudles are loaded as did @skm in his example.

I even filed a issue #1811 with an exact descriptive title on Sun 2020.05.03 which was dismissed

Issue #1811

Anomaly in deployed module corrupts user namespace global scope

Interesting how one may be blinded by simplicity and incorrect conclusions drawn while observing the symptom and not the cause.

It appears what I discovered then is now understood.

Hi Robin, I don't want to waste too much time responding to this as I have tried to explain multiple times in the past. These are not related at all.

It appears what I discovered then is now understood.

http://forum.espruino.com/conversations/346486/

I posted the fix a few comments later at http://forum.espruino.com/comments/15238576/ - you were using the function incorrectly.

http://forum.espruino.com/conversations/346667/

Is not a bug, it's just that if you include a whole bunch of code with libraries, then try and run a low level trace() you will see a lot of information being output. It's expected.

Yes, minification renames variables to single characters, a..z

No, if you see a single character, it does not mean you have the same problem. It just means you're looking at minified code