CircuitPython writes to serial console over USB stop working after lots of output

[kevinjwalters]

I noticed one occasion where leaving an Adafruit CLUE running 5.0.0 beta 5 with some very verbose output to stdout for over an hour caused the terminal output to stop but the application continues merrily. I've just reproduced this with the same application/library code on 5.0.0 but it took approximately 130 minutes to do it.

• 5.0.0 beta 5 with PuTTY 0.70 (this version misses various security fixes, not recommended for general use) on Windows 8.1 desktop
• 5.0.0 with PuTTY 0.73 on Windows 10 laptop (left YT video running in browser to stop it from hibernating/screen saving)

The application is reading analogue values from P0-P2 and graphing them. It does not have the serial console active on the display. In both cases the application continued to run. PuTTY does not indicate the serial connection has closed. Control-C still works and takes the CLUE to the serial output on the LCD but with no output over USB. It says KeyboardInterrupt: as it normally does but does not respond to further typing, e.g. can't interact with REPL. Control-C and Control-D do nothing. In both cases the CIRCUITPY drive remains accessible. In the first case the writes stopped after the first of two arguments to print which made me more suspicious of CP than the terminal program.

I could continue interacting with the CLUE on both occasions. I could restart the code by coping a file onto CIRCUITPY. I could stop it with Control-C but still with no output to serial console, just the LCD when I hit Control-C. I've tried a Reset Terminal in PuTTY - nothing changed. I can disconnect COM5 then reconnect and everything's then back to normal. The special treatment here for Control-C makes it feel less likely to be a terminal program issue too.

Briefly discussed this with @dhalbert in Discord.

[kevinjwalters]

Code is here (messy and unfinished), both files needed, strip the .txt off. once it starts graphing click left button until Pad: graph appears to get the same output I left it running with.
code.py.txt
plot_source.py.txt

I was using libraries from a bundle that looks like 22-Feb-2020 but seems unlikely these would have much impact on this type of bug?

[kevinjwalters]

BTW, no implication here that this is guaranateed to be (up)time related, could be volume or flow control or something else... Control-C still functioning must be indicative of something.

[kevinjwalters]

Just had this happen again after about maybe 30 mins. I'd added loads of print style debugging to some code. Stopped after printing the first of five arguments to print().

This time around (on Win8.1) it's a little different. Reconnecting the terminal does not help. Control-C still works from the new session to COM18, REPL prompt/etc can't be seen over USB but the LCD does show it.

I plugged a battery in (to keep device powered), then disconnected the USB at CLUE end and reconnected it and then reconnected. COM18 is now working again with terminal.

[kevinjwalters]

I've been doing a bit of tweaking to CP code any copying code.py and two extra .py files onto a CLUE running 5.0.0. In general this works fine but I've just noticed the terminal session lock-up over USB. The screen output for USB was slightly more than appeared on the LCD.

Traceback (most recent call last):
  File "code.py", line 169, in <module>
NameError: name 'MU_PLOTTER_OUTPUT' is not defined



Press any key to enter the REPL. Use CTRL-D to reload.

The displayio-driven LCD output finished at the line that says is not defined. That line was split over two lines half way through is. Reconnecting serial terminal over USB didn't work, did my battery in, unplug usb, replug usb, battery out trick. I can now connected again to serial console.

[kevinjwalters]

I just had this happen with very low volume printing. I'm starting to wonder if this is related to using displayio ...

Oh, I might be wrong there on the volume.

[kevinjwalters]

I had a variant of this recently on 5.2.0. I've never seen this before b[ut I scrolled back a few hundred lines and a single line had some junk on it that looks like line noise.

Quantize 454.051 440.0
(1.48047, 4.81685)
4583 302.296 1480.47 4.81685 1480.87 1.48158 1.48158
Quantize 190.122 184.997
(1.48231, 5.04943)
4584 302.328 1482.31 5.04943 1481.75 1.48158 1.48158
Quantize 232.561 220.0
(1.48164, 5.0496)
4585 302.426 1481.64 5.0496 1481.84 1.48155 1.48155
Quantize 289.543 311.127
(1.48206, 5.13418)
4586 302.458 1482.06 5.13418 1481.93 1.48155 1.48155
Quantize 232.561232.561e3480.051_Xu�y▒▒▒▒0▒}▒220.0
(1.48096, 5.20833)
4587 302.524 1480.96 5.20833 1481.29 1.48155 1.48155
Quantize 166.042 155.563
(1.482, 5.36208)
4588 302.555 1482.0 5.36208 1481.69 1.48155 1.48155
Quantize 635.488 622.254
(1.48289, 4.93547)
4589 302.658 1482.89 4.93547 1482.63 1.48155 1.48155
Quantize 904.186 879.999
(1.48328, 5.21683)
4590 302.709 1483.28 5.21683 1483.16 1.48157 1.48157
Quantize 342.233 369.994
(1.48153, 4.76986)

On closer inspection:

0000000   Q   u   a   n   t   i   z   e       2   3   2   .   5   6   1
0000010   2   3   2   .   5   6   1   e   3   4   8   0   .   0   5   1
0000020   _   X   u 357 277 275   y 342 226 222 342 226 222 342 226 222
0000030 342 226 222   0 342 226 222   } 342 226 222   2   2   0   .   0
0000040  \n
0000041

The 232.561 gets mysteriously repeated where the space character should be and a load of junk probably from wrong or not terminated buffer gets included. The values I believe would have been printed there are print("Quantize", 232.561, 220.0) - last two are actually variables in the code. The actual statement is d_print(3, "Quantize", freq, note_freq) which is calling:

def d_print(level, *args, **kwargs):
    """A simple conditional print for debugging based on global debug level."""
    if not isinstance(level, int):
        print(level, *args, **kwargs)
    elif debug >= level:
        print(*args, **kwargs)

[kevinjwalters]

Just got this after a mere 15 seconds on a CLUE after a copying code.py triggered application reload. This is on 5.2.0.

[kevinjwalters]

And a CPB running 5.2.0 just did this after 5-10 minutes of running from power-up.

[kevinjwalters]

I just had a variant of this on 5.3.0 on a Circuit Playground Bluefruit (CPB). This is what was on the serial console.

wins 0, losses 0, draws 2, void 0
soft reboot

Auto-reload is on. Simply save files over USB to run them or enter REPL to disable.
code.py output:
TXing soft reboot

Auto-reload is on. Simply save files over USB to run them or enter REPL to disable.
code.py output:
Traceback (most recent call last):
Traceback (most recent call last):
s over USB to run them or en786
IndentationError: unexpected indent

That double Traceback feels familiar (I was thinking of micropython#2056 but that's different), I think there's a ticket about something similar elsewhere. More interestingly there's some "random" junk in there, s over USB to run them or en786 is not part of my application code. The string is a partial one from the CircuitPython interpreter, maybe 29 bytes of it plus 3 bytes of other junk?

$ fgrep 's over USB to run them or en' main.c
            serial_write_compressed(translate("Auto-reload is on. Simply save files over USB to run them or enter REPL to disable.\n"));
                    serial_write_compressed(translate("Auto-reload is on. Simply save files over USB to run them or enter REPL to disable.\n"));

I accessed a file and that triggered a reload and the application worked fine so code.py was intact.

I had to reset the board to be able to reconnect to the serial console over USB.

[kevinjwalters]

FYI, I put something in the forums mainly to see if anyone else has come across this: Adafruit Forums: Garbled exception on code.py reload and broken serial consol.

[kevinjwalters]

I just experienced this on 5.3.0 on a CLUE with a busy application but the possible trigger was lots of output over an hour or so plus it died during a powershell dir -Recurse on the CIRCUITPY and that dir had a pause in it of maybe 10-15 seconds about 4/5th of the way through - the dir did complete after that.

[kevinjwalters]

This has occurred a few times today with a Feather nRF52840 Express running CircuitPython 6.0.0 with minimal output across serial. It happens to be plugged into a Pimoroni Enviro+ FeatherWing with a PMS5003.