esptool timeout with KVM QEMU virtual machine

[mreutman]

Summary

I have a VM that I'm trying to set up with a static/encapsulated development environment for some ESP32 work and I'm having a hard time getting esptool to talk correctly to my ESP32. I have USB pass-through enabled on the host OS (another Debian 9.6 install) so the VM can see the USB port and is able to do some signaling to the ESP32 itself, but it looks like some timing issue is in place that causes the ESP32 to reboot before esptool can run its commands. In the capture below, you can see the ESP32's bootloader dumping info to the console while esptool is trying to sync to the chip. I tried extending some of the sleep calls in esptool to see if that would help, but I've had no luck thus far; maybe I'm just not hitting the correct timeout value?

General Information

• Operating system: Debian 9.6 (Virtual Machine KVM/QEMU)
• Python version: 2.7.13
• ESP hardware in use: Dev Kit C

Full esptool.py command line as run:

./esptool.py --trace read_mac

Full output from esptool.py (please copy and paste all lines of output)

esptool.py v2.7-dev
Found 2 serial ports
Serial port /dev/ttyUSB0
Connecting...TRACE +0.000 command op=0x08 data len=36 wait_response=1 timeout=1.000 data=
    0707122055555555 5555555555555555 | ... UUUUUUUUUUUU
    5555555555555555 5555555555555555 | UUUUUUUUUUUUUUUU
    55555555                          | UUUU
TRACE +0.000 Write 46 bytes: 
    c000082400000000 0007071220555555 | ...$........ UUU
    5555555555555555 5555555555555555 | UUUUUUUUUUUUUUUU
    5555555555555555 5555555555c0     | UUUUUUUUUUUUU.
TRACE +0.021 Read 1 bytes: 20
TRACE +0.000 Read invalid data: 20
TRACE +0.000 Remaining data in serial buffer: 
    535049204d6f6465 202020202020203a | SPI Mode       :
    2044494f1b5b306d 0d0a1b5b303b3332 |  DIO.[0m...[0;32
    6d49202834352920 626f6f743a205350 | mI (45) boot: SP
    4920466c61736820 53697a65203a2034 | I Flash Size : 4
    4d421b5b306d0d0a 1b5b303b33326d49 | MB.[0m...[0;32mI
    202834392920626f 6f743a2050617274 |  (49) boot: Part
    6974696f6e205461 626c653a1b5b306d | ition Table:.[0m
    0d0a1b5b303b3332 6d49202835322920 | ...[0;32mI (52) 
    626f6f743a202323 204c6162656c2020 | boot: ## Label  
    2020202020202020 2020557361676520 |           Usage 
    2020202020202020 2054797065205354 |          Type ST
    204f666673657420 20204c656e677468 |  Offset   Length
    1b5b306d0d0a1b5b 303b33326d492028 | .[0m...[0;32mI (
    36302920626f6f74 3a202030206e7673 | 60) boot:  0 nvs
    2020202020202020 2020202020205769 |               Wi
    4669206461746120 20202020202020   | Fi data        
.TRACE +0.051 command op=0x08 data len=36 wait_response=1 timeout=1.000 data=
    0707122055555555 5555555555555555 | ... UUUUUUUUUUUU
    5555555555555555 5555555555555555 | UUUUUUUUUUUUUUUU
    55555555                          | UUUU
TRACE +0.000 Write 46 bytes: 
    c000082400000000 0007071220555555 | ...$........ UUU
    5555555555555555 5555555555555555 | UUUUUUUUUUUUUUUU
    5555555555555555 5555555555c0     | UUUUUUUUUUUUU.
TRACE +0.016 Read 1 bytes: 3d
TRACE +0.000 Read invalid data: 3d
TRACE +0.000 Remaining data in serial buffer: 
    3078336666383030 30302073697a653d | 0x3ff80000 size=
    3078303030303020 2820202020203029 | 0x00000 (     0)
    206c6f61641b5b30 6d0d0a1b5b303b33 |  load.[0m...[0;3
    326d492028313133 29206573705f696d | 2mI (113) esp_im
    6167653a20736567 6d656e7420333a20 | age: segment 3: 
    70616464723d3078 3030303137356530 | paddr=0x000175e0
    2076616464723d30 7833666662303030 |  vaddr=0x3ffb000
    302073697a653d30 7830316539302028 | 0 size=0x01e90 (
    2020373832342920 6c6f61641b5b306d |   7824) load.[0m
    0d0a1b5b303b3332 6d49202831323529 | ...[0;32mI (125)
    206573705f696d61 67653a207365676d |  esp_image: segm
    656e7420343a2070 616464723d307830 | ent 4: paddr=0x0
    3030313934373820 76616464723d3078 | 0019478 vaddr=0x
    3366666231653930 2073697a653d3078 | 3ffb1e90 size=0x
    3030303030202820 202020203029206c | 00000 (     0) l
    6f61641b5b306d0d 0a1b5b303b3332   | oad.[0m...[0;32
.TRACE +0.051 command op=0x08 data len=36 wait_response=1 timeout=1.000 data=
    0707122055555555 5555555555555555 | ... UUUUUUUUUUUU
    5555555555555555 5555555555555555 | UUUUUUUUUUUUUUUU
    55555555                          | UUUU
TRACE +0.000 Write 46 bytes: 
    c000082400000000 0007071220555555 | ...$........ UUU
    5555555555555555 5555555555555555 | UUUUUUUUUUUUUUUU
    5555555555555555 5555555555c0     | UUUUUUUUUUUUU.
TRACE +0.015 Read 1 bytes: 1b
TRACE +0.000 Read invalid data: 1b
TRACE +0.000 Remaining data in serial buffer: 
    5b303b33326d4920 2831383629206573 | [0;32mI (186) es
    705f696d6167653a 207365676d656e74 | p_image: segment
    20383a2070616464 723d307830303033 |  8: paddr=0x0003
    3235613820766164 64723d3078343030 | 25a8 vaddr=0x400
    3836623838207369 7a653d3078303133 | 86b88 size=0x013
    6430202820203530 373229206c6f6164 | d0 (  5072) load
    1b5b306d0d0a1b5b 303b33326d492028 | .[0m...[0;32mI (
    3138392920657370 5f696d6167653a20 | 189) esp_image: 
    7365676d656e7420 393a207061646472 | segment 9: paddr
    3d30783030303333 3938302076616464 | =0x00033980 vadd
    723d307834303063 303030302073697a | r=0x400c0000 siz
    653d307830303030 3020282020202020 | e=0x00000 (     
    3029206c6f61641b 5b306d0d0a1b5b30 | 0) load.[0m...[0
    3b33326d49202831 393329206573705f | ;32mI (193) esp_
    696d6167653a2073 65676d656e742031 | image: segment 1
    303a207061646472 3d307830303033   | 0: paddr=0x0003
.TRACE +0.051 command op=0x08 data len=36 wait_response=1 timeout=1.000 data=
    0707122055555555 5555555555555555 | ... UUUUUUUUUUUU
    5555555555555555 5555555555555555 | UUUUUUUUUUUUUUUU
    55555555                          | UUUU

What is the expected behaviour?

The esptool reads MAC address of ESP32 chip.

Do you have any other information from investigating this?

This is being run in a QEMU/KVM virtual machine, so timing is probably way worse than if I was running this on a native Linux box.

[projectgus]

Hi @mreutman ,

Sorry for the slow reply.

This is being run in a QEMU/KVM virtual machine, so timing is probably way worse than if I was running this on a native Linux box.

This is the root cause here. Unfortunately the RTS & DTR timing for the GPIO0 & EN pins, combined with the automatic reset circuit, require quite tight timing. esptool.py has to send two separate commands - one to assert DTR (GPIO0 low) and one to release RTS (EN high) to boot the chip in download mode. If there is too long of a delay between them, the automatic reset circuit sees DTR & RTS asserted together and boots the ESP32 into normal running mode.

There's some more discussion of the overall issue here:
https://esp32.com/viewtopic.php?t=8219
#383

Including some workarounds for different platforms (to udpate DTR & RTS simultaneously). However there's nothing which doesn't require significant modifications of pyserial.

Another workaround that will work is to hold down the BOOT button on Dev Kit C when flashing.

[mreutman]

Thanks for the information! I guess with this in mind, I'll go ahead and close the issue. I'll just stick to doing flash operations using the host OS rather than the guest.