https://toitlang.org/ logo
Powered by
Quite often my `jag run` commands hang, and I'm tr...
# help
a
Sometimes my jag run commands hang for quite a while, sometimes they are super quick, and sometimes they are supre slow. Recently I got this set of traces from one that was hanging and ultimately failed Any thoughts on the best way to help possibly identify what is going on, and make it go away?
f
Do you know if the issue is on the cli or device side?
Iirc the log of the device shows when it gets a request (but I'm not 100% sure right now).
a
So the most recent one failed with this https://gist.githubusercontent.com/addshore/dbf2d2e7909f60dddae0fecef5eeae9c/raw/be68079e71a9bbc77687d2e7403d33b1e6210e7b/gistfile1.txt And running 
jag run
again right after worked after a few seconds
f
Ok. This looks like the CLI didn't send the full program.
As if it was interrupted.
a
or it got lost in the network? (I'm not sure how these comms really look under the hood)
But I find I can reproduce this using 
jag run
probably 8 in 10 times to some degree (either slowly, or failing)
f
The device sends out UDP broadcasts to signal its presence, but once Jaguar connects to the device it goes through http with tcp/ip.
Package loss should be handled by the tcp/ip layer.
Is there any output on the CLI side?
80% of the time is a lot.
Definitely not something we have been seeing.
When you get the "UNEXPECTED_END_OF_READER" is that happening after a long time?
Could the CLI have given up at that point?
Do you know if it could be spotty WiFi? If you have laptop, you can test this, by creating a hotspot with your phone and connecting your laptop and the device to it).
a
only output on the CLI side would be like this
Copy code
~/dev/lb/io/toit (main) jag run ./pkg/lightbug/examples/httpmsg-raw.toit --device 192.168.68.65 -D lb-localdocs=1
Scanning for  device with address: '192.168.68.65'
Error: Get "http://192.168.68.65:9000/identify": context deadline exceeded
f
At the moment (with the information I have), I'm guessing the device has a hard time connecting to the WiFi hotspot and, despite the TCP/IP retransmissions, doesn't manage to get the data. Eventually the CLI gives up, and the device gets the stacktrace.
a
managed to get this this time
Copy code
Scanning for  device with address: '192.168.68.65'
Running './pkg/lightbug/examples/httpmsg-raw.toit' on 'working-heat' ...
Error: got non-OK from device: 500 Internal Server error - DEADLINE_EXCEEDED
so, is that 500 error actually comes from the esp?
f
Good question. Could be from our sources. Let me grep.
a
Got this from the ESP side
Copy code
[jaguar.http] INFO: Internal Server error - DEADLINE_EXCEEDED {peer: 192.168.68.61:28407, method: PUT, path: /run}
[jaguar.http] INFO: Internal Server error - request not fully read {peer: 192.168.68.61:28407, method: PUT, path: /run}
While doing the 
run
my continual stream of ICMP pings to the ESP seem to get through fine, though there is some lag Pre run it was 5-20ms, During run it is 1000-10000ms
f
Are you doing something else (like BLE) on the device while updating?
I have experienced similar issues during firmware updates. If there is little memory left, and the BLE is using lots of CPU the firmware update was a bad experience.
a
nope, I'm only ever running this 1 script on the devic currently, so the first thing it does before trying to run the new one is stop the old one
f
I can imagine the same happening for 
run
.
good to know.
a
ble certainly wasn't turned on by the old one The only thing it does is I2C comms
f
that shouldn't cost anything.
I haven't found the DEADLINE_EXCEEDED yet. I'm pretty sure it's from our code, but I don't know which one yet.
a
so, after failing to do the run a few misn ago, http://192.168.68.61:9000/ and /identify now currenlty don't load in a browser
f
a
oooooh
Copy code
Scanning for  device with address: '192.168.68.65'
Running './pkg/lightbug/examples/httpmsg-raw.toit' on 'working-heat' ...
Success: Sent 127KB code to 'working-heat'
on the esp
Copy code
Heap report @ out of memory in primitive 3:4:
  ┌───────────┬──────────┬─────────────────────────────────────────────────────┐
  │   Bytes   │  Count   │  Type
            │
  ├───────────┼──────────┼─────────────────────────────────────────────────────┤
  │    5360   │    477   │  heap overhead
            │
  │  171248   │    433   │  untagged
            │
  └───────────┴──────────┴─────────────────────────────────────────────────────┘
  Total: 176608 bytes in 433 allocations (52%), largest free 128k, total free 157k
[jaguar] INFO: program 1d0bb989-0dd5-a5ed-eafb-499af7a7d41f started
[lb-comms] INFO: Comms starting
But it took a very long time to flash
not seen that OOM report either before, thats a first I have spotted that
k
Is it a new problem?
f
k
We did increase 
CONFIG_LWIP_TCP_MSS
from 1410 to 1440 recently.
a
This has generally been happening for some weeks, I have just chosen to mostly ignore it until today 😉 It's one of the reasons that I was interested in the proxy command for jag things, but realized in the past day or so that also might not resolve the issue
k
I think the bump to 1440 landed last week.
f
It would probably solve the issue, but the uart is generally slower, and the experience with WiFi should be better.
k
So it is unlikely to be the cause.
a
I'm likelly not using that bumped value then
jag 
v1.47.0
from Dec
f
From what I can see the program isn't super big either.
If possible please test with a cellphone hotspot.
a
yeah, I can give that a go!
f
It would give us some information on whether it's depending on the WiFi connection or not.
k
Maybe reboot your AP? Would be interesting to see if that helps.
We've had cases where the AP became really unstable after a while, but mostly when we had many devices.
Rebooting it made those issues go away for a while.
f
Another easy test: in the beginning of your main:
Copy code
if Time.monotonic-us > 0: return
Then reboot the device, and 
jag run
this program multiple times.
If we don't see any issues anymore, then Toit doesn't clean up correctly when it stops the container before installing the next one.
If we still see the issue, then we can exclude anything from your program.
And doing it this way (with the 
if
) ensures that the program size stays the same.
a
I will try all of the above and report back 🙂 Thanks for the insights
f
I looked through the code, and I'm pretty sure the DEADLINE_EXCEEDED comes from a lower layer; maybe the Socket layer.
Could still be Toit, but also C++.
a
Interesting, 
if Time.monotonic-us > 0: return
at the top of the same program, and I ran it 6 times in a row no issue
k
a
Also interesting,
Copy code
main:
  yield
also worked 5 times in a row Now I am suspicious
f
hmm. That could also be the case. I somehow excluded it because the number looked so big. But it's just 2 minutes. So maybe yes.
a
I did also just start using 
main
of jag
k
I think that is the simplest explanation. Somehow it takes more than 2 minutes to get the data across and we time out.
Consequently we throw DEADLINE_EXCEEDED from somewhere deep in the http server code or something, something.
f
we should probably reset the timeout every time we get data.
a
I'll report back later throughout the day, but as far as I can tell, using 
main
or jag, and thus also newer 
toit
seems to have made it all go away?
f
that would be nice 🙂
k
Latest Toit for the win.
a
it always seems to run in sub 5s now
I read your changelog, and I wonder if perhaps it might have been sometihng to do with I2c then? as you did tweak some things? but no idea!
f
I don't think so, but you could still do the 
if Time.monotonic-us
test from above on an older 
jag
.
a
I will do that now
k
It could also be weirder. Like reflashing the device helped because you don't have a crap ton of stuff already installed in the programs section that needs to be deleted as we install new things.
2 minutes is a long time though, so I can't quite make that explanation fit.
If that is somehow part of the explanation, going back to an older version should not make this more reproducible.
a
So, a fresh flash on the older toit and jag, same hardware, and its currently hung, and i expect it to fail
Copy code
Scanning for  device with address: '192.168.68.65'
Running './pkg/lightbug/examples/httpmsg-raw.toit' on 'glad-ear' ...
k
Nice.
a
ooh, it did run after about 20 seconds, but on the stuff i was getting under 5 always
k
Would love to know what we fixed.
a
If you want, I can probably bisect it at some point for you 🙂
k
That'd be cool. For now, I guess stress testing the latest bits and making sure it's better for you also seems like a nice thing - and productive for you.
PreviousNext
Powered by