ESP-PROG debug fails in PIO with all boards, LIBUSB_ERROR_PIPE

ntwallace · June 5, 2020, 8:01pm

I am having an issue debugging ESP32 wrover based boards using the esp-prog and PIO. In all cases, running debug fails with the following errors after running for a minute and successfully reading and writing:

Error: ftdi device did not return all data: 0, expected 12
Error: error while flushing MPSSE queue: -4
Error: libusb_handle_events() failed with LIBUSB_ERROR_PIPE

I haven’t been able to find anything similar searching the forums. This happens no matter what code I use (including Blink), and no matter what board I use. I have tried:

Changing ESP32 Wrover boards, tried both Lolin D32 Pro and a custom board

Changing the adapter speed to 200Khz, 2Mhz, 5Mhz, 10Mhz, and 20Mhz

Powering the ESP boards via the esp-prog at 5v or 3.3v

Powering the ESP boards via USB

PIO ini:

platform = espressif32
board = esp-wrover-kit
framework = arduino

build_flags =
-w
-DBOARD_HAS_PSRAM
-mfix-esp32-psram-cache-issue

src_build_flags =
-Wall
board_build.f_cpu = 240000000L
board_build.f_flash = 80000000L

monitor_speed = 115200

debug_tool = esp-prog
debug_init_break = tbreak setup

Full log:

--------------------------------------------------------------------------------
Verbose mode can be enabled via `-v, --verbose` option
CONFIGURATION: https://docs.platformio.org/page/boards/espressif32/esp-wrover-kit.html
PLATFORM: Espressif 32 1.12.2 > Espressif ESP-WROVER-KIT
HARDWARE: ESP32 240MHz, 320KB RAM, 4MB Flash
DEBUG: Current (esp-prog) On-board (ftdi) External (esp-prog, iot-bus-jtag, jlink, minimodule, olimex-arm-usb-ocd, olimex-arm-usb-ocd-h, olimex-arm-usb-tiny-h, olimex-jtag-tiny, tumpa)
PACKAGES:
 - framework-arduinoespressif32 3.10004.200129 (1.0.4)
 - tool-esptoolpy 1.20600.0 (2.6.0)
 - toolchain-xtensa32 2.50200.80 (5.2.0)
LDF: Library Dependency Finder -> http://bit.ly/configure-pio-ldf
LDF Modes: Finder ~ chain, Compatibility ~ soft
Found 29 compatible libraries
Scanning dependencies...
Dependency Graph
Building in debug mode
Retrieving maximum program size .pio/build/esp-wrover-kit/firmware.elf
Checking size .pio/build/esp-wrover-kit/firmware.elf
Advanced Memory Usage is available via "PlatformIO Home > Project Inspect"
RAM:   [=         ]  13.6% (used 44440 bytes from 327680 bytes)
Flash: [=======   ]  65.8% (used 862398 bytes from 1310720 bytes)
========================= [SUCCESS] Took 3.57 seconds =========================
Reading symbols from /Users/.../Documents/.../.pio/build/esp-wrover-kit/firmware.elf...
done.
PlatformIO Unified Debugger -> http://bit.ly/pio-debug
PlatformIO: debug_tool = esp-prog
PlatformIO: Initializing remote target...
Open On-Chip Debugger  v0.10.0-esp32-20190708 (2019-07-08-11:04)
Licensed under GNU GPL v2
For bug reports, read
	http://openocd.org/doc/doxygen/bugs.html
none separate
adapter speed: 10000 kHz
Info : Configured 2 cores
esp32 interrupt mask on
Info : tcl server disabled
Info : telnet server disabled
Info : ftdi: if you experience problems at higher adapter clocks, try the command "ftdi_tdo_sample_edge falling"
Info : clock speed 10000 kHz
Info : JTAG tap: esp32.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : esp32: Debug controller 0 was reset (pwrstat=0x5F, after clear 0x0F).
Info : esp32: Core 0 was reset (pwrstat=0x5F, after clear 0x0F).
Info : esp32: Debug controller 1 was reset (pwrstat=0x5F, after clear 0x0F).
Info : esp32: Core 1 was reset (pwrstat=0x5F, after clear 0x0F).
Info : Detected debug stubs @ 3ffc2efc on core0 of target 'esp32'
Info : accepting 'gdb' connection from pipe
Error: No symbols for FreeRTOS
Info : Target halted. PRO_CPU: PC=0x4014F472 (active)    APP_CPU: PC=0x400D747E
Info : Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x400D747E
Info : Flash mapping 0: 0x10020 -> 0x3f400020, 198 KB
Info : Flash mapping 1: 0x50018 -> 0x400d0018, 513 KB
Info : Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x400D747E
Info : Auto-detected flash size 8192 KB
Info : Using flash size 8192 KB
Info : Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x400D747E
Info : Flash mapping 0: 0x10020 -> 0x3f400020, 198 KB
Info : Flash mapping 1: 0x50018 -> 0x400d0018, 513 KB
Info : Using flash size 516 KB
Info : Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x400D747E
Info : Flash mapping 0: 0x10020 -> 0x3f400020, 198 KB
Info : Flash mapping 1: 0x50018 -> 0x400d0018, 513 KB
Info : Using flash size 200 KB
0x4014f472 in pm_rx_beacon_process ()
Info : JTAG tap: esp32.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
JTAG tap: esp32.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
JTAG tap: esp32.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : esp32: Debug controller 0 was reset (pwrstat=0x5F, after clear 0x0F).
Info : esp32: Core 0 was reset (pwrstat=0x5F, after clear 0x0F).
esp32: Debug controller 0 was reset (pwrstat=0x5F, after clear 0x0F).
esp32: Core 0 was reset (pwrstat=0x5F, after clear 0x0F).
Info : Target halted. PRO_CPU: PC=0x5000004B (active)    APP_CPU: PC=0x00000000
Target halted. PRO_CPU: PC=0x5000004B (active)    APP_CPU: PC=0x00000000
Info : esp32: Core 0 was reset (pwrstat=0x1F, after clear 0x0F).
Info : esp32: Debug controller 1 was reset (pwrstat=0x5F, after clear 0x0F).
Info : esp32: Core 1 was reset (pwrstat=0x5F, after clear 0x0F).
esp32: Core 0 was reset (pwrstat=0x1F, after clear 0x0F).
esp32: Debug controller 1 was reset (pwrstat=0x5F, after clear 0x0F).
esp32: Core 1 was reset (pwrstat=0x5F, after clear 0x0F).
Info : Target halted. PRO_CPU: PC=0x40000400 (active)    APP_CPU: PC=0x40000400
Target halted. PRO_CPU: PC=0x40000400 (active)    APP_CPU: PC=0x40000400
** Programming Started **
** Programming Started **
auto erase enabled
auto erase enabled
Info : Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x40000400
Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x40000400
Info : Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x40000400
Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x40000400
wrote 16384 bytes from file /Users/nick/.platformio/packages/framework-arduinoespressif32/tools/sdk/bin/bootloader_dio_80m.bin in 0.860183s (18.601 KiB/s)
wrote 16384 bytes from file /Users/nick/.platformio/packages/framework-arduinoespressif32/tools/sdk/bin/bootloader_dio_80m.bin in 0.860183s (18.601 KiB/s)
** Programming Finished **
** Programming Finished **
** Verify Started **
** Verify Started **
Info : Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x40000400
Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x40000400
read 15856 bytes from file /Users/nick/.platformio/packages/framework-arduinoespressif32/tools/sdk/bin/bootloader_dio_80m.bin and flash bank 0 at offset 0x00001000 in 0.326285s (47.457 KiB/s)
contents match
read 15856 bytes from file /Users/nick/.platformio/packages/framework-arduinoespressif32/tools/sdk/bin/bootloader_dio_80m.bin and flash bank 0 at offset 0x00001000 in 0.326285s (47.457 KiB/s)
contents match
** Verified OK **
** Verified OK **
Info : JTAG tap: esp32.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
JTAG tap: esp32.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
JTAG tap: esp32.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : esp32: Debug controller 0 was reset (pwrstat=0x5F, after clear 0x0F).
Info : esp32: Core 0 was reset (pwrstat=0x5F, after clear 0x0F).
esp32: Debug controller 0 was reset (pwrstat=0x5F, after clear 0x0F).
esp32: Core 0 was reset (pwrstat=0x5F, after clear 0x0F).
Info : Target halted. PRO_CPU: PC=0x5000004B (active)    APP_CPU: PC=0x00000000
Target halted. PRO_CPU: PC=0x5000004B (active)    APP_CPU: PC=0x00000000
Info : esp32: Core 0 was reset (pwrstat=0x1F, after clear 0x0F).
Info : esp32: Debug controller 1 was reset (pwrstat=0x5F, after clear 0x0F).
Info : esp32: Core 1 was reset (pwrstat=0x5F, after clear 0x0F).
esp32: Core 0 was reset (pwrstat=0x1F, after clear 0x0F).
esp32: Debug controller 1 was reset (pwrstat=0x5F, after clear 0x0F).
esp32: Core 1 was reset (pwrstat=0x5F, after clear 0x0F).
Info : Target halted. PRO_CPU: PC=0x40000400 (active)    APP_CPU: PC=0x40000400
Target halted. PRO_CPU: PC=0x40000400 (active)    APP_CPU: PC=0x40000400
** Programming Started **
** Programming Started **
auto erase enabled
auto erase enabled
Info : Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x40000400
Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x40000400
Info : Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x40000400
Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x40000400
wrote 4096 bytes from file /Users/nick/Documents/ESPLED/Arduino/ESP32_Artnet/.pio/build/esp-wrover-kit/partitions.bin in 0.659934s (6.061 KiB/s)
wrote 4096 bytes from file /Users/nick/Documents/ESPLED/Arduino/ESP32_Artnet/.pio/build/esp-wrover-kit/partitions.bin in 0.659934s (6.061 KiB/s)
** Programming Finished **
** Programming Finished **
** Verify Started **
** Verify Started **
Info : Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x40000400
Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x40000400
read 3072 bytes from file /Users/nick/Documents/ESPLED/Arduino/ESP32_Artnet/.pio/build/esp-wrover-kit/partitions.bin and flash bank 0 at offset 0x00008000 in 0.290918s (10.312 KiB/s)
contents match
read 3072 bytes from file /Users/nick/Documents/ESPLED/Arduino/ESP32_Artnet/.pio/build/esp-wrover-kit/partitions.bin and flash bank 0 at offset 0x00008000 in 0.290918s (10.312 KiB/s)
contents match
** Verified OK **
** Verified OK **
Info : JTAG tap: esp32.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
JTAG tap: esp32.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
JTAG tap: esp32.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : esp32: Debug controller 0 was reset (pwrstat=0x5F, after clear 0x0F).
Info : esp32: Core 0 was reset (pwrstat=0x5F, after clear 0x0F).
esp32: Debug controller 0 was reset (pwrstat=0x5F, after clear 0x0F).
esp32: Core 0 was reset (pwrstat=0x5F, after clear 0x0F).
Info : Target halted. PRO_CPU: PC=0x5000004B (active)    APP_CPU: PC=0x00000000
Target halted. PRO_CPU: PC=0x5000004B (active)    APP_CPU: PC=0x00000000
Info : esp32: Core 0 was reset (pwrstat=0x1F, after clear 0x0F).
Info : esp32: Debug controller 1 was reset (pwrstat=0x5F, after clear 0x0F).
Info : esp32: Core 1 was reset (pwrstat=0x5F, after clear 0x0F).
esp32: Core 0 was reset (pwrstat=0x1F, after clear 0x0F).
esp32: Debug controller 1 was reset (pwrstat=0x5F, after clear 0x0F).
esp32: Core 1 was reset (pwrstat=0x5F, after clear 0x0F).
Info : Target halted. PRO_CPU: PC=0x40000400 (active)    APP_CPU: PC=0x40000400
Target halted. PRO_CPU: PC=0x40000400 (active)    APP_CPU: PC=0x40000400
** Programming Started **
** Programming Started **
auto erase enabled
auto erase enabled
Info : Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x40000400
Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x40000400
Info : Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x40000400
Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x40000400
wrote 8192 bytes from file /Users/nick/.platformio/packages/framework-arduinoespressif32/tools/partitions/boot_app0.bin in 0.727178s (11.001 KiB/s)
wrote 8192 bytes from file /Users/nick/.platformio/packages/framework-arduinoespressif32/tools/partitions/boot_app0.bin in 0.727178s (11.001 KiB/s)
** Programming Finished **
** Programming Finished **
** Verify Started **
** Verify Started **
Info : Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x40000400
Target halted. PRO_CPU: PC=0x400916EE (active)    APP_CPU: PC=0x40000400
read 8192 bytes from file /Users/nick/.platformio/packages/framework-arduinoespressif32/tools/partitions/boot_app0.bin and flash bank 0 at offset 0x0000e000 in 0.299664s (26.697 KiB/s)
contents match
read 8192 bytes from file /Users/nick/.platformio/packages/framework-arduinoespressif32/tools/partitions/boot_app0.bin and flash bank 0 at offset 0x0000e000 in 0.299664s (26.697 KiB/s)
contents match
** Verified OK **
** Verified OK **
Info : JTAG tap: esp32.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : JTAG tap: esp32.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
JTAG tap: esp32.cpu0 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
JTAG tap: esp32.cpu1 tap/device found: 0x120034e5 (mfg: 0x272 (Tensilica), part: 0x2003, ver: 0x1)
Info : esp32: Debug controller 0 was reset (pwrstat=0x5F, after clear 0x0F).
Info : esp32: Core 0 was reset (pwrstat=0x5F, after clear 0x0F).
esp32: Debug controller 0 was reset (pwrstat=0x5F, after clear 0x0F).
esp32: Core 0 was reset (pwrstat=0x5F, after clear 0x0F).
Info : Target halted. PRO_CPU: PC=0x5000004B (active)    APP_CPU: PC=0x00000000
Target halted. PRO_CPU: PC=0x5000004B (active)    APP_CPU: PC=0x00000000
Info : esp32: Core 0 was reset (pwrstat=0x1F, after clear 0x0F).
Info : esp32: Debug controller 1 was reset (pwrstat=0x5F, after clear 0x0F).
Info : esp32: Core 1 was reset (pwrstat=0x5F, after clear 0x0F).
esp32: Core 0 was reset (pwrstat=0x1F, after clear 0x0F).
esp32: Debug controller 1 was reset (pwrstat=0x5F, after clear 0x0F).
esp32: Core 1 was reset (pwrstat=0x5F, after clear 0x0F).
Info : Target halted. PRO_CPU: PC=0x40000400 (active)    APP_CPU: PC=0x40000400
Target halted. PRO_CPU: PC=0x40000400 (active)    APP_CPU: PC=0x40000400
** Programming Started **
** Programming Started **
auto erase enabled
auto erase enabled
Error: ftdi device did not return all data: 0, expected 12
ftdi device did not return all data: 0, expected 12
Error: error while flushing MPSSE queue: -4
error while flushing MPSSE queue: -4
Error: libusb_handle_events() failed with LIBUSB_ERROR_PIPE
libusb_handle_events() failed with LIBUSB_ERROR_PIPE
.pioinit:15: Error in sourced command file:

maxgerhardt · June 5, 2020, 8:34pm

Googling "ftdi device did not return all data: 0" returns a grand total 3 results – none of which are concluding to an accepted answer.

I’d say “lower clock” or “power all boards with a good external power supply” but you’ve tried that already…

You may try something exotic like changing the OS / running Linux in a VM and see if the behaviour changes. Otherwise I’d recommend asking the openocd devs directly at OpenOCD - Open On-Chip Debugger / Tickets for this seemly exotic / rarely encountered error.

ntwallace · June 5, 2020, 8:50pm

Thanks @maxgerhardt, will do.

Going to spin up a Linux VM later and will confirm if that works or not. I’m starting to wonder if it’s a hardware issue with the ESP-PROG itself.

ntwallace · June 5, 2020, 10:26pm

@maxgerhardt the same setup works flawlessly on Ubuntu 20…so looks to be a driver issue on my end in MacOS. I’ll troubleshoot later and update this thread.

maxgerhardt · June 5, 2020, 10:27pm

Good that you’ve narrowed down the error. Could be that proprietary FTDI drivers are outdated or too new, or Apple provided ones are bad, maybe.