Fails to connect to ESP32

[kevinkk525]

I know there was a similar issue #67 but this is lightly different.
I can connect to the esp32 directly after flashing it but after that, I'm unable to do so.
Putty connects fine every time so I'm sure there isn't a hardware problem.

I'm using a "doit esp32 devkit v1" (at least that's what's written on its back) with the mainline esp32 daily firmware.
I'm not running a main.py and I use the precompiled firmware available for download.

This is my error trace:

 rshell -p /dev/ttyS5 -a --buffer-size=30
Using buffer-size of 30
Connecting to /dev/ttyS5 (buffer-size 30)...
Testing if ubinascii.unhexlify exists ... b'\x1b[0;32mI (426) cpu_start: Pro cpu up.\x1b[0m\r\n\x1b[0;32mI (427) cpu_start: Application information:\x1b[0m\r\n\x1b[0;32mI (427) cpu_start: Compile time:     00:43:59\x1b[0m\r\n\x1b[0;32mI (429) cpu_start: Compile date:     Mar 25 2019\x1b[0m\r\n\x1b[0;32mI (434) cpu_start: ESP-IDF:          v3.3-beta1-268-g5c88c5996\x1b[0m\r\n\x1b[0;32mI (441) cpu_start: Single core mode\x1b[0m\r\n\x1b[0;32mI (445) heap_init: Initializing. RAM available for dynamic allocation:\x1b[0m\r\n\x1b[0;32mI (452) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM\x1b[0m\r\n\x1b[0;32mI (458) heap_init: At 3FFB92B0 len 00026D50 (155 KiB): DRAM\x1b[0m\r\n\x1b[0;32mI (464) heap_init: At 3FFE0440 len 0001FBC0 (126 KiB): D/IRAM\x1b[0m\r\n\x1b[0;32mI (471) heap_init: At 40078000 len 00008000 (32 KiB): IRAM\x1b[0m\r\n\x1b[0;32mI (477) heap_init: At 400928AC len 0000D754 (53 KiB): IRAM\x1b[0m\r\n\x1b[0;32mI (483) cpu_start: Pro cpu start user code\x1b[0m\r\n\x1b[0;32mI (54) cpu_start: Starting scheduler on PRO CPU.\x1b[0m\r\n\x1b[0;32mI (98) modsocket: Initializing\x1b[0m\r\nI (118) wifi: wifi driver task: 3ffe44ec, prio:23, stack:3584, core=0\r\nI (118) wifi: wifi firmware version: 38e2484\r\nI (118) wifi: config NVS flash: enabled\r\nI (118) wifi: config nano formating: disabled\r\n\x1b[0;32mI (128) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE\x1b[0m\r\n\x1b[0;32mI (138) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE\x1b[0m\r\nI (148) wifi: Init dynamic tx buffer num: 32\r\nI (148) wifi: Init data frame dynamic rx buffer num: 32\r\nI (148) wifi: Init management frame dynamic rx buffer num: 32\r\nI (158) wifi: Init static rx buffer size: 1600\r\nI (158) wifi: Init static rx buffer num: 10\r\nI (168) wifi: Init dynamic rx buffer num: 32\r\nStarted webrepl in normal mode\r\nOSError: [Errno 2] ENOENT\r\nMicroPython v1.10-230-ge0c6dfe90 on 2019-03-25; ESP32 module with ESP32\r\nType "help()" for more information.\r\n>>> '
Traceback (most recent call last):
  File "/home/kevin/.local/lib/python3.6/site-packages/rshell/main.py", line 1255, in connect
    ip_address = socket.gethostbyname(port)
socket.gaierror: [Errno -5] No address associated with hostname

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/kevin/.local/bin/rshell", line 11, in <module>
    sys.exit(main())
  File "/home/kevin/.local/lib/python3.6/site-packages/rshell/command_line.py", line 4, in main
    rshell.main.main()
  File "/home/kevin/.local/lib/python3.6/site-packages/rshell/main.py", line 2827, in main
    real_main()
  File "/home/kevin/.local/lib/python3.6/site-packages/rshell/main.py", line 2789, in real_main
    connect(args.port, baud=args.baud, wait=args.wait, user=args.user, password=args.password)
  File "/home/kevin/.local/lib/python3.6/site-packages/rshell/main.py", line 1261, in connect
    connect_serial(port, baud=baud, wait=wait)
  File "/home/kevin/.local/lib/python3.6/site-packages/rshell/main.py", line 1285, in connect_serial
    dev = DeviceSerial(port, baud, wait)
  File "/home/kevin/.local/lib/python3.6/site-packages/rshell/main.py", line 1549, in __init__
    Device.__init__(self, pyb)
  File "/home/kevin/.local/lib/python3.6/site-packages/rshell/main.py", line 1339, in __init__
    unhexlify_exists = self.remote_eval(test_unhexlify)
  File "/home/kevin/.local/lib/python3.6/site-packages/rshell/main.py", line 1459, in remote_eval
    return eval(self.remote(func, *args, **kwargs))
  File "/home/kevin/.local/lib/python3.6/site-packages/rshell/main.py", line 1437, in remote
    self.pyb.enter_raw_repl()
  File "/home/kevin/.local/lib/python3.6/site-packages/rshell/pyboard.py", line 187, in enter_raw_repl
    raise PyboardError('could not enter raw repl')
rshell.pyboard.PyboardError: could not enter raw repl

To me it looks like the board doesn't start in raw_repl after a reset but goes straight to repl. As rshell expects it to start in raw_repl, it fails.

[dhylands]

rshell doesn't need it to start in the raw repl. It sends Control-C to interrupt any running program and a Control-D to enter the raw reply. So far I've only tested with the loboris port. I'll try with the official port and see what happens.

[kevinkk525]

Oh then I did not look at the code carefully enough and I'm out of ideas.
Thanks for taking a look.

[dhylands]

Some people have added a small sleep to pyboard.py, which I think works around the problem that you're running into. I haven't been able to reproduce the problem locally. In particular, see this comment: #27 (comment)

I have some ideas on how to improve this so that it will work without an explicit delay but rather waits for the REPL, and I just need to find some time to implement and test it.

[dhylands]

I'm wondering if the esp32's that people are having issues with are being reset when the serial port is opened. I've been unable to reproduce this on my SparkFun Esp32 Thing.

I've ordered a DOIT ESP32 DEVKIT V1 so that I can see if I can reproduce this.

[kevinkk525]

This workaround indeed works! Thanks a lot.

My ESP certainly resets everytime I connect to the repl, doesn't matter if I use rshell or putty.

[dhylands]

ok - that helps to understand what's going on then. My SparkFun ESP32 Thing doesn't reset when I connect to it.

When the ESP32 resets, it prints out a bunch of text similar to the following:

ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0018,len:4
load:0x3fff001c,len:4928
ho 0 tail 12 room 4
load:0x40078000,len:9332
load:0x40080400,len:6216
entry 0x400806e8
I (442) cpu_start: Pro cpu up.
I (442) cpu_start: Application information:
I (442) cpu_start: Compile time:     13:09:22
I (445) cpu_start: Compile date:     Mar 27 2019
I (450) cpu_start: ESP-IDF:          v3.3-beta1-268-g5c88c5996
I (456) cpu_start: Starting app cpu, entry point is 0x40082950
I (0) cpu_start: App cpu up.
I (467) heap_init: Initializing. RAM available for dynamic allocation:
I (474) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM
I (480) heap_init: At 3FFB9B90 len 00026470 (153 KiB): DRAM
I (486) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (492) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (499) heap_init: At 40093434 len 0000CBCC (50 KiB): IRAM
I (505) cpu_start: Pro cpu start user code
I (76) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.

and rshell is trying to talk to the board while that reset process is happening. Since the way rshell works is essentially to type some commands and parse the response, it gets confused by this initial burst of text. And this is evident in your very first comment:

Testing if ubinascii.unhexlify exists ... b'\x1b[0;32mI (426) cpu_start: Pro cpu up.\x1b[0m\r\n\x1b[0;32mI (427) cpu_start: Application information:\x1b[0m\r\n\x1b[0;32mI (427) cpu_start: Compile time:     00:43:59\x1b[0m\r\n\x1b[0;32mI (429) cpu_start: Compile date:     Mar 25 2019\x1b[0m\r\n\x1b[0;32mI (434) cpu_start: ESP-IDF:          v3.3-beta1-268-g5c88c5996\x1b[0m\r\n\x1b[0;32mI (441) cpu_start: Single core mode\x1b[0m\r\n\x1b[0;32mI (445) heap_init: Initializing. RAM available for dynamic allocation:\x1b[0m\r\n\x1b[0;32mI (452) heap_init: At 3FFAE6E0 len 00001920 (6 KiB): DRAM\x1b[0m\r\n\x1b[0;32mI (458) heap_init: At 3FFB92B0 len 00026D50 (155 KiB): DRAM\x1b[0m\r\n\x1b[0;32mI (464) heap_init: At 3FFE0440 len 0001FBC0 (126 KiB): D/IRAM\x1b[0m\r\n\x1b[0;32mI (471) heap_init: At 40078000 len 00008000 (32 KiB): IRAM\x1b[0m\r\n\x1b[0;32mI (477) heap_init: At 400928AC len 0000D754 (53 KiB): IRAM\x1b[0m\r\n\x1b[0;32mI (483) cpu_start: Pro cpu start user code\x1b[0m\r\n\x1b[0;32mI (54) cpu_start: Starting scheduler on PRO CPU.\x1b[0m\r\n\x1b[0;32mI (98) modsocket: Initializing\x1b[0m\r\nI (118) wifi: wifi driver task: 3ffe44ec, prio:23, stack:3584, core=0\r\nI (118) wifi: wifi firmware version: 38e2484\r\nI (118) wifi: config NVS flash: enabled\r\nI (118) wifi: config nano formating: disabled\r\n\x1b[0;32mI (128) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE\x1b[0m\r\n\x1b[0;32mI (138) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE\x1b[0m\r\nI (148) wifi: Init dynamic tx buffer num: 32\r\nI (148) wifi: Init data frame dynamic rx buffer num: 32\r\nI (148) wifi: Init management frame dynamic rx buffer num: 32\r\nI (158) wifi: Init static rx buffer size: 1600\r\nI (158) wifi: Init static rx buffer num: 10\r\nI (168) wifi: Init dynamic rx buffer num: 32\r\nStarted webrepl in normal mode\r\nOSError: [Errno 2] ENOENT\r\nMicroPython v1.10-230-ge0c6dfe90 on 2019-03-25; ESP32 module with ESP32\r\nType "help()" for more information.\r\n>>> '

In the comment this prints as a very long single line. Adding the delay allows this text to go by, but I think that a better solution is to wait for the '>>>' prompt so that we don't delay when we don't need to.

[dhylands]

I just released 0.0.21 which now tries to get a REPL prompt before continuing, I was able to simulate a device which resets (by twiddling the RTS & DTR lines just after opening the serial port) and it now skips that text looking for the >>> prompt.

[kevinkk525]

Thanks for the quick fix! It works great now.

Interesting observation: I had some things connected and it didn't reset on serial connect, so there's some interference from pin usages/states.