Lead Scout crashes/hangs with Wi-Fi debug output enabled

[amcjen]

This is with the following defines set:

#define GS_LOG_ERRORS_VERBOSE
#define GS_DUMP_LINES

Specifically, it looks like Bitlash is experiencing an overflow or something?, there's an overflow and then an unexpected number and then the board resets.

Also, is Discarding non-escaped byte, no synchronous response expected expected, when it's returning valid data like IP address/subnet/etc?

At the end of this second run, the board is locked up and requires a reset.

Hello from Pinoccio!
 (Shell based on Bitlash v2.0 (c) 2014 Bill Roy)
 14371 bytes free
 Build 2014021701
 Lead Scout ready
> >>= ATV0
<<| Read async header: <ESC>A701
<<| Read async data: 7
<<= 0
>>= ATE0
<<= 0
>>= AT+BDATA=1
<<= 0
>>= AT+ASYNCMSGFMT=1
<<= 0
>>= AT+TCERTADD=hq.ca,0,997,1
<<= 0
<<= OK
>>= AT+NCMAUTO=0,0,0,1
<<= 0
>>= AT+NCMAUTOCONF=11,0
<<= 0
>>= ATS6=1000
<<= 0
>>= ATS7=0
<<= 0
>>= AT+NAUTO=0,1,api.pinocc.io,22757
<<= 0
>>= AT+NCMAUTO=0,1,1,1
<<= 0
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x49 (I)
Discarding non-escaped byte, no synchronous response expected: 0x50 (P)
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x53 (S)
Discarding non-escaped byte, no synchronous response expected: 0x75 (u)
Discarding non-escaped byte, no synchronous response expected: 0x62 (b)
Discarding non-escaped byte, no synchronous response expected: 0x4E (N)
Discarding non-escaped byte, no synchronous response expected: 0x65 (e)
Discarding non-escaped byte, no synchronous response expected: 0x74 (t)
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x47 (G)
Discarding non-escaped byte, no synchronous response expected: 0x61 (a)
Discarding non-escaped byte, no synchronous response expected: 0x74 (t)
Discarding non-escaped byte, no synchronous response expected: 0x65 (e)
Discarding non-escaped byte, no synchronous response expected: 0x77 (w)
Discarding non-escaped byte, no synchronous response expected: 0x61 (a)
Discarding non-escaped byte, no synchronous response expected: 0x79 (y)
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x31 (1)
Discarding non-escaped byte, no synchronous response expected: 0x30 (0)
Discarding non-escaped byte, no synchronous response expected: 0x2E (.)
Discarding non-escaped byte, no synchronous response expected: 0x30 (0)
Discarding non-escaped byte, no synchronous response expected: 0x2E (.)
Discarding non-escaped byte, no synchronous response expected: 0x31 (1)
Discarding non-escaped byte, no synchronous response expected: 0x2E (.)
Discarding non-escaped byte, no synchronous response expected: 0x31 (1)
Discarding non-escaped byte, no synchronous response expected: 0x31 (1)
Discarding non-escaped byte, no synchronous response expected: 0x34 (4)
Discarding non-escaped byte, no synchronous response expected: 0x3A (:)
Discarding non-escaped byte, no synchronous response expected: 0x32 (2)
Discarding non-escaped byte, no synchronous response expected: 0x35 (5)
Discarding non-escaped byte, no synchronous response expected: 0x35 (5)
Discarding non-escaped byte, no synchronous response expected: 0x2E (.)
Discarding non-escaped byte, no synchronous response expected: 0x32 (2)
Discarding non-escaped byte, no synchronous response expected: 0x35 (5)
Discarding non-escaped byte, no synchronous response expected: 0x35 (5)
Discarding non-escaped byte, no synchronous response expected: 0x2E (.)
Discarding non-escaped byte, no synchronous response expected: 0x32 (2)
Discarding non-escaped byte, no synchronous response expected: 0x35 (5)
Discarding non-escaped byte, no synchronous response expected: 0x35 (5)
Discarding non-escaped byte, no synchronous response expected: 0x2E (.)
Discarding non-escaped byte, no synchronous response expected: 0x30 (0)
Discarding non-escaped byte, no synchronous response expected: 0x3A (:)
Discarding non-escaped byte, no synchronous response expected: 0x31 (1)
Discarding non-escaped byte, no synchronous response expected: 0x30 (0)
Discarding non-escaped byte, no synchronous response expected: 0x2E (.)
Discarding non-escaped byte, no synchronous response expected: 0x30 (0)
Discarding non-escaped byte, no synchronous response expected: 0x2E (.)
Discarding non-escaped byte, no synchronous response expected: 0x31 (1)
Discarding non-escaped byte, no synchronous response expected: 0x2E (.)
Discarding non-escaped byte, no synchronous response expected: 0x31 (1)
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
<<| Read async header: <ESC>Ac01
<<| Read async data: c
>>= AT+DNSLOOKUP=pool.ntp.org
<<= IP:174.36.71.205
<<= 0
>>= AT+NTIMESYNC=1,174.36.71.205,10,0
<<| Read async header: <ESC>A103
<<| Read async data: 1 0
<<= 0
>>= AT+NTIMESYNC=1,174.36.71.205,10,1,20864
<<= 0
>>= AT+SSLOPEN=0,hq.ca
<<= 0
>>| Writing bulk data frame for cid 0 containing 60 bytes
<<| Read data OK response
>>| Writing bulk data frame for cid 0 containing 108 bytes
<<| Read data OK response
<<| Read bulk data frame for cid 0 containing 18 bytes
>>| Writing bulk data frame for cid 0 containing 137 bytes
<<| Read data OK response
>>| Writing bulk data frame for cid 0 containing 116 bytes
<<| Read data OK response
>>| Writing bulk data frame for cid 0 containing 108 bytes
<<| Read data OK response
>>| Writing bulk data frame for cid 0 containing 86 bytes
<<| Read data OK response
>>| Writing bulk data frame for cid 0 containing 116 bytes
<<| Read data OK response
>>| Writing bulk data frame for cid 0 containing 121 bytes
<<| Read data OK response
>>| Writing bulk data frame for cid 0 containing 137 bytes
<<| Read data OK response
>>| Writing bulk data frame for cid 0 containing 84 bytes
<<| Read data OK response
>>| Writing bulk data frame for cid 0 containing 87 bytes
<<| Read data OK response
>>| Writing bulk data frame for cid 0 containing 85 bytes
<<| Read data OK response
<<| Read bulk data frame for cid 0 containing 75 bytes
1
>>| Writing bulk data frame for cid 0 containing 58 bytes
<<| Read bulk data frame for cid 0 containing 75 bytes
<<| Read data OK response
<<| Read bulk data frame for cid 0 containing 75 bytes
<<| Read bulk data frame for cid 0 containing 75 bytes
>>| Writing bulk data frame for cid 0 containing 59 bytes
<<| Read bulk data frame for cid 0 containing 75 bytes
<<| Read data OK response
>>| Writing bulk data frame for cid 0 containing 59 bytes
<<| Read data OK response
��� overflow
�>>| Writing bulk data frame for cid 0 containing 121 bytes
<<| Read data OK response
unexpected number

Hello from Pinoccio!
 (Shell based on Bitlash v2.0 (c) 2014 Bill Roy)
 14371 bytes free
 Build 2014021701
 Lead Scout ready
> >>= ATV0
<<| Read async header: <ESC>A701
<<| Read async data: 7
<<= 0
>>= ATE0
<<= 0
>>= AT+BDATA=1
<<= 0
>>= AT+ASYNCMSGFMT=1
<<= 0
>>= AT+TCERTADD=hq.ca,0,997,1
<<= 0
<<= OK
>>= AT+NCMAUTO=0,0,0,1
<<= 0
>>= AT+NCMAUTOCONF=11,0
<<= 0
>>= ATS6=1000
<<= 0
>>= ATS7=0
<<= 0
>>= AT+NAUTO=0,1,api.pinocc.io,22757
<<= 0
>>= AT+NCMAUTO=0,1,1,1
<<= 0
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x49 (I)
Discarding non-escaped byte, no synchronous response expected: 0x50 (P)
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x53 (S)
Discarding non-escaped byte, no synchronous response expected: 0x75 (u)
Discarding non-escaped byte, no synchronous response expected: 0x62 (b)
Discarding non-escaped byte, no synchronous response expected: 0x4E (N)
Discarding non-escaped byte, no synchronous response expected: 0x65 (e)
Discarding non-escaped byte, no synchronous response expected: 0x74 (t)
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x47 (G)
Discarding non-escaped byte, no synchronous response expected: 0x61 (a)
Discarding non-escaped byte, no synchronous response expected: 0x74 (t)
Discarding non-escaped byte, no synchronous response expected: 0x65 (e)
Discarding non-escaped byte, no synchronous response expected: 0x77 (w)
Discarding non-escaped byte, no synchronous response expected: 0x61 (a)
Discarding non-escaped byte, no synchronous response expected: 0x79 (y)
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
Discarding non-escaped byte, no synchronous response expected: 0x31 (1)
Discarding non-escaped byte, no synchronous response expected: 0x30 (0)
Discarding non-escaped byte, no synchronous response expected: 0x2E (.)
Discarding non-escaped byte, no synchronous response expected: 0x30 (0)
Discarding non-escaped byte, no synchronous response expected: 0x2E (.)
Discarding non-escaped byte, no synchronous response expected: 0x31 (1)
Discarding non-escaped byte, no synchronous response expected: 0x2E (.)
Discarding non-escaped byte, no synchronous response expected: 0x31 (1)
Discarding non-escaped byte, no synchronous response expected: 0x31 (1)
Discarding non-escaped byte, no synchronous response expected: 0x34 (4)
Discarding non-escaped byte, no synchronous response expected: 0x3A (:)
Discarding non-escaped byte, no synchronous response expected: 0x32 (2)
Discarding non-escaped byte, no synchronous response expected: 0x35 (5)
Discarding non-escaped byte, no synchronous response expected: 0x35 (5)
Discarding non-escaped byte, no synchronous response expected: 0x2E (.)
Discarding non-escaped byte, no synchronous response expected: 0x32 (2)
Discarding non-escaped byte, no synchronous response expected: 0x35 (5)
Discarding non-escaped byte, no synchronous response expected: 0x35 (5)
Discarding non-escaped byte, no synchronous response expected: 0x2E (.)
Discarding non-escaped byte, no synchronous response expected: 0x32 (2)
Discarding non-escaped byte, no synchronous response expected: 0x35 (5)
Discarding non-escaped byte, no synchronous response expected: 0x35 (5)
Discarding non-escaped byte, no synchronous response expected: 0x2E (.)
Discarding non-escaped byte, no synchronous response expected: 0x30 (0)
Discarding non-escaped byte, no synchronous response expected: 0x3A (:)
Discarding non-escaped byte, no synchronous response expected: 0x31 (1)
Discarding non-escaped byte, no synchronous response expected: 0x30 (0)
Discarding non-escaped byte, no synchronous response expected: 0x2E (.)
Discarding non-escaped byte, no synchronous response expected: 0x30 (0)
Discarding non-escaped byte, no synchronous response expected: 0x2E (.)
Discarding non-escaped byte, no synchronous response expected: 0x31 (1)
Discarding non-escaped byte, no synchronous response expected: 0x2E (.)
Discarding non-escaped byte, no synchronous response expected: 0x31 (1)
Discarding non-escaped byte, no synchronous response expected: 0x20 ( )
<<| Read async header: <ESC>Ac01
<<| Read async data: c
>>= AT+DNSLOOKUP=pool.ntp.org
<<| Read async header: <ESC>A103
<<| Read async data: 1 0
<<= IP:174.36.71.205
<<= 0
>>= AT+NTIMESYNC=1,174.36.71.205,10,0
<<= 0
>>= AT+NTIMESYNC=1,174.36.71.205,10,1,20864
<<= 0
>>= AT+SSLOPEN=0,hq.ca
<<= 0
>>| Writing bulk data frame for cid 0 containing 60 bytes
<<| Read data OK response
<<| Read bulk data frame for cid 0 containing 18 bytes
>>| Writing bulk data frame for cid 0 containing 137 bytes
<<| Read data OK response
>>| Writing bulk data frame for cid 0 containing 127 bytes
<<| Read data OK response
>>| Writing bulk data frame for cid 0 containing 108 bytes
<<| Read data OK response
>>| Writing bulk data frame for cid 0 containing 86 bytes
<<| Read data OK response
>>| Writing bulk data frame for cid 0 containing 116 bytes
<<| Read data OK response
>>| Writing bulk data frame for cid 0 containing 121 bytes
<<| Read data OK response
>>| Writing bulk data frame for cid 0 containing 137 bytes
<<| Read data OK response
>>| Writing bulk data frame for cid 0 containing 84 bytes
<<| Read data OK response
>>| Writing bulk data frame for cid 0 containing 87 bytes
<<| Read bulk data frame for cid 0 containing 75 bytes
<<| Read bulk data frame for cid 0 containing 75 bytes
<<| Read data OK response
<<| Read bulk data frame for cid 0 containing 75 bytes
1
>>| Writing bulk data frame for cid 0 containing 58 bytes
<<| Read bulk data frame for cid 0 containing 75 bytes
<<| Read data OK response
<<| Read bulk data frame for cid 0 containing 75 bytes
>>| Writing bulk data frame for cid 0 containing 37 bytes
<<| Read data OK response

[matthijskooijman]

Good to know it also happens with DUMP_LINES, I've mostly tested with SPI_BYTES also enabled.

Also, is Discarding non-escaped byte, no synchronous response expected expected, when it's returning valid data like IP address/subnet/etc?

Yes, this is data that precedes the asynchronous "now associated" response, but when reading it there is no way to actually know that async response is coming. This is the same stuff you get before the "OK" when manually (synchronously) connecting, but for asynchronous they also just randomly print that data. This is one of those weird parts of the serial interface...

Specifically, it looks like Bitlash is experiencing an overflow or something?, there's an overflow and then an unexpected number and then the board resets.

I've seen the unexpected number part before, often just after a (re)boot. Hadn't really payed attention to it before. I wonder if it's because there is not a real reset, so perhaps something is not properly initialized?

[amcjen]

If I comment out GS_DUMP_LINES and only leave GS_LOG_ERRORS_VERBOSE defined, the board runs and does not hang after several minutes.

[amcjen]

Would it make sense to enable the watchdog timer in case of a hung board?

This was discussed before and agreed it would be a good idea, but we didn't actually implement it. Would this be a good extra protection around hung boards? Not sure it'd actually solve the bad resets though unless we check the last-reset-cause via the bootloader work, and always WDT reset on "unknown cause" resets.

[matthijskooijman]

A did a quick review of all GS_DUMP_LINES related code, but there is not anything obviously wrong (or even complicated) about that...

Wrt the WDT - that would only solve lockups if the main loop actually stops running, which I'm not sure of yet (just thought of a way to test this, though, put a digitalWrite(LED_RED, digitalRead(3)) in loop() and you can find out if it's still looping without any extra serial output spam and delays etc.). Also, having a watchdog timer limits the amount of time we can spend blocking on, e.g., a wifi.list command. Not blocking is a good idea anyway, but makes implementation of things harder...

[amcjen]

Agreed. The blocking part of NCM makes this an iffy proposition. Unless we did something like 30 seconds or more

[amcjen]

I also see strange behavior, including hangs, when I have this as a bitlash startup function and I have GS_DUMP_LINES defined:

function startup { led.red(1000, 1); }

My hypothesis is that when led state changes, it fires off a report, and it is a) bitlash's handling of the report data destined to HQ getting hosed up with the Wifi loop, or b) the Wifi loop is blocking too long and bitlash gets corrupted or loses information.

When I remove this startup function and still have GS_DUMP_LINES defined, it runs without crashing.