search

trabucayre / openFPGALoader

Universal utility for programming FPGA
https://trabucayre.github.io/openFPGALoader/
Apache License 2.0
1.16k stars 249 forks source link

"usb bulk write failed" errors flashing Tang Nano 9k #415

Open silversquirl opened 8 months ago

silversquirl commented 8 months ago

This definitely worked a few months ago, but I've changed laptops since then and now it doesn't:

$ openFPGALoader -b tangnano9k --verbose-level=2 build/counter.fs
empty
Jtag frequency : requested 6.00MHz   -> real 6.00MHz  
Raw IDCODE:
- 0 -> 0x1100481b
- 1 -> 0xffffffff
Fetched TDI, end-of-chain
found 1 devices
index 0:
        idcode 0x100481b
        manufacturer Gowin
        family GW1N
        model  GW1N(R)-9C
        irlength 8
File type : fs
Parse file Parse build/counter.fs: 
checksum 0x76e7
Done
DONE
bitstream header infos
CRCCheck: ON
Compress: OFF
ConfDataLength: 712
LoadingRate: 2500000
ProgramDoneBypass: OFF
SPIAddr: 00fff000
SecurityBit: ON
idcode: 1100481b
before program sram: displayReadReg 0003f020
        Memory Erase
        Gowin VLD
        Done Final
        Security Final
        Ready
        POR
        FLASH lock
Erase SRAM before erase sram: displayReadReg 0003f020
        Memory Erase
        Gowin VLD
        Done Final
        Security Final
        Ready
        POR
        FLASH lock
pollFlag: 3f0a0 (80)
pollFlag: 3d080 (0)
pollFlag: 3d080 (0)
pollFlag: 3d080 (0)
pollFlag: 390a0 (20)
after erase sram: displayReadReg 000390a0
        Memory Erase
        System Edit Mode
        Gowin VLD
        Ready
        POR
        FLASH lock
pollFlag: 39020 (0)
Load SRAM before write sram: displayReadReg 00039020
        Memory Erase
        Gowin VLD
        Ready
        POR
        FLASH lock
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
[... continues indefinitely ...]
silversquirl commented 8 months ago

If left alone for several minutes, it finally does actually stop and print this:

mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_read: fail to store with error: -1 (usb bulk write failed)
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_read: fail to store with error: -1 (usb bulk write failed)
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
after write sram: displayReadReg 00000000
FAIL
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_read: fail to store with error: -1 (usb bulk write failed)
Loopback failed, expect problems on later runs -1
unable to config pins : -1 unable to configure bitbang mode. Perhaps not a BM/2232C type chip?

I've tried with multiple different known-good cables, so it's unlikely to be that. Not really sure how to debug this.

loopj commented 7 months ago

I'm seeing this exact same issue on an M2 Macbook Air and openFPGALoader v0.11.0

trabucayre commented 7 months ago

Could you paste dmesg output when you plug the device? This problem seems related to low level layer.

loopj commented 7 months ago

This seems to be related to using a usb hub, plugging into the computer directly with a known good cable solves the issue.

trabucayre commented 7 months ago

Weird: I have bought an 9k to do some tests. I have a long USB extender and and usb switch + usb cable and not seen anything like that. Problem is definitively related to hardware...

hackguy25 commented 4 months ago

I'm having the same issue on the Raspberry Pi 4 with 64-bit Raspberry Pi OS. I tried different USB cables and flashing fails in a similar manner on all of them. I will try with a laptop instead, and post an update.

trabucayre commented 4 months ago

Could you share dmesg output. By the past FTDI implementation was really unstable with raspberryPI.

hackguy25 commented 4 months ago

Sometimes it works:

[  172.736329] usb 1-1.3: new full-speed USB device number 3 using xhci_hcd
[  172.838286] usb 1-1.3: not running at top speed; connect to a high speed hub
[  172.846288] usb 1-1.3: New USB device found, idVendor=0403, idProduct=6010, bcdDevice= 5.00
[  172.846308] usb 1-1.3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[  172.846321] usb 1-1.3: Product: JTAG Debugger
[  172.846331] usb 1-1.3: Manufacturer: SIPEED
[  172.846340] usb 1-1.3: SerialNumber: FactoryAIOT Pro
[  172.973783] usbcore: registered new interface driver usbserial_generic
[  172.973831] usbserial: USB Serial support registered for generic
[  172.983869] usbcore: registered new interface driver ftdi_sio
[  172.983939] usbserial: USB Serial support registered for FTDI USB Serial Device
[  172.984059] ftdi_sio 1-1.3:1.0: FTDI USB Serial Device converter detected
[  172.984246] usb 1-1.3: Detected FT2232C/D
[  172.989666] usb 1-1.3: FTDI USB Serial Device converter now attached to ttyUSB0
[  172.989880] ftdi_sio 1-1.3:1.1: FTDI USB Serial Device converter detected
[  172.989931] usb 1-1.3: Detected FT2232C/D
[  172.993157] usb 1-1.3: FTDI USB Serial Device converter now attached to ttyUSB1

Sometimes it errors out:

[  488.070602] usb 1-1.2: new full-speed USB device number 4 using xhci_hcd
[  488.172511] usb 1-1.2: not running at top speed; connect to a high speed hub
[  488.176511] usb 1-1.2: config index 0 descriptor too short (expected 55, got 9)
[  488.176518] usb 1-1.2: config 1 has 0 interfaces, different from the descriptor's value: 2
[  488.179767] usb 1-1.2: string descriptor 0 read error: -75
[  488.179774] usb 1-1.2: New USB device found, idVendor=0403, idProduct=6010, bcdDevice= 5.00
[  488.179779] usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[  488.180760] usb 1-1.2: can't set config #1, error -75

I used a different USB port here, but it doesn't seem to be linked to a specific USB port.

DavidVentura commented 3 months ago

I'm hitting the same issue on a Framework laptop:

dmesg on plug

[987306.248589] usb 1-1: new full-speed USB device number 13 using xhci_hcd
[987306.405238] usb 1-1: not running at top speed; connect to a high speed hub
[987306.433236] usb 1-1: New USB device found, idVendor=0403, idProduct=6010, bcdDevice= 5.00
[987306.433243] usb 1-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[987306.433245] usb 1-1: Product: JTAG Debugger
[987306.433247] usb 1-1: Manufacturer: SIPEED
[987306.433248] usb 1-1: SerialNumber: FactoryAIOT Pro
[987306.439273] ftdi_sio 1-1:1.0: FTDI USB Serial Device converter detected
[987306.439301] usb 1-1: Detected FT2232C/D
[987306.446300] usb 1-1: FTDI USB Serial Device converter now attached to ttyUSB0
[987306.446724] ftdi_sio 1-1:1.1: FTDI USB Serial Device converter detected
[987306.446741] usb 1-1: Detected FT2232C/D
[987306.452288] usb 1-1: FTDI USB Serial Device converter now attached to ttyUSB1

Error on flash:

$ openFPGALoader -m -b tangnano9k --verbose-level=2  /home/david/git/TangNano-9K-example/hdmi/impl/pnr/hdmi.fs 
Jtag frequency : requested 6.00MHz   -> real 6.00MHz  
Raw IDCODE:
- 0 -> 0x1100481b
- 1 -> 0xffffffff
Fetched TDI, end-of-chain
found 1 devices
index 0:
        idcode 0x100481b
        manufacturer Gowin
        family GW1N
        model  GW1N(R)-9C
        irlength 8
File type : fs
Parse file Parse /home/david/git/TangNano-9K-example/hdmi/impl/pnr/hdmi.fs: 
checksum 0xee33
Done
DONE
bitstream header infos
CRCCheck: ON
Compress: OFF
ConfDataLength: 1224
LoadingRate: 2500000
ProgramDoneBypass: OFF
SPIAddr: 00000000
SecurityBit: ON
idcode: 1100481b
before program sram: displayReadReg 0003f020
        Memory Erase
        Gowin VLD
        Done Final
        Security Final
        Ready
        POR
        FLASH lock
Erase SRAM before erase sram: displayReadReg 0003f020
        Memory Erase
        Gowin VLD
        Done Final
        Security Final
        Ready
        POR
        FLASH lock
pollFlag: 3f0a0 (80)
pollFlag: 3d080 (0)
pollFlag: 3d080 (0)
pollFlag: 3d080 (0)
pollFlag: 3d080 (0)
pollFlag: 81faf3fa (20)
after erase sram: displayReadReg 7d02fa02
        Bad Command
        Reserved9
        Bypass
        Gowin VLD
        Done Final
        Security Final
        Ready
        FLASH lock
pollFlag: 82fa00fa (80)
pollFlag: 7d73fa02 (0)
Load SRAM before write sram: displayReadReg fffa00fa
        Bad Command
        Timeout
        Reserved4
        Memory Erase
        Preamble
        System Edit Mode
        FLASH lock
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed

Before seeing the first mpsse_write: fail to write with error -1 (usb bulk write failed), the kernel logs also show the device getting disconnected:

[987311.723449] ftdi_sio ttyUSB0: FTDI USB Serial Device converter now disconnected from ttyUSB0
[987311.723461] ftdi_sio 1-1:1.0: device disconnected
trabucayre commented 3 months ago

The two lines mentioned are perfectly normal. To be able to take control to the FTDI (or clone) from userspace, it's required first to detach the driver. For a different board but using an FTDI device I have these two lines:

[127777.428335] ftdi_sio ttyUSB0: FTDI USB Serial Device converter now disconnected from ttyUSB0
[127777.428352] ftdi_sio 3-1.4:1.0: device disconnected

The real problem here are errors (usb bulk write failed) returned by the libusb (used by the libftdi). I have no real idea why this occur: it's usual with FTDI clone, I have sometime similars errors with an USB hub or with one connector partly physically broken. Maybe power is not enough and device reboot?

DavidVentura commented 3 months ago

Other log lines I've gotten:

Jtag frequency : requested 6.00MHz   -> real 6.00MHz  
Raw IDCODE:
- 0 -> 0xfffafffa
JTAG init failed with: Unknown device with IDCODE: 0xfffafffa (manufacturer: 0x7fd (), part: 0x7f vers: 0xf
FTDI flush buffer error with code -2 (FTDI purge of RX buffer failed)
JTAG init failed with: low level FTDI init failed
Can't read iProduct field from FTDI: considered as empty string
FTDI reset error with code -1 (FTDI reset failed)
JTAG init failed with: low level FTDI init failed

another run got a bit farther:

Jtag frequency : requested 6.00MHz   -> real 6.00MHz  
Raw IDCODE:
- 0 -> 0x1100481b
- 1 -> 0xffffffff
- 2 -> 0xffffffff
- 3 -> 0xffffffff
- 4 -> 0xffffffff
found 1 devices
index 0:
        idcode 0x100481b
        manufacturer Gowin
        family GW1N
        model  GW1N(R)-9C
        irlength 8
File type : fs
Parse file Parse /home/david/git/TangNano-9K-example/hdmi/impl/pnr/hdmi.fs: 
checksum 0xee33
Done
DONE
bitstream header infos
CRCCheck: ON
Compress: OFF
ConfDataLength: 1224
ProgramDoneBypass: OFF
SPIAddr: 00000000
SecurityBit: ON
idcode: 1100481b
loading_rate: 0
Jtag frequency : requested 2.50MHz   -> real 2.00MHz  
displayReadReg 0003f020
        Memory Erase
        Gowin VLD
        Done Final
        Security Final
        Ready
        POR
        Flash Lock
pollFlag: ffffff01
pollFlag: 1f0a080
erase SRAM pollFlag: 78200100
pollFlag: 78200000
pollFlag: 78200000
pollFlag: 78200000
pollFlag: 78200000
pollFlag: 78200000
pollFlag: 78200000
pollFlag: 78200000
pollFlag: 78200000
pollFlag: 78200000
pollFlag: 78200000
pollFlag: 78200000
pollFlag: 78200000
pollFlag: 90030000
pollFlag: 90000003
pollFlag: 90000003
pollFlag: 90000003
pollFlag: 90000003
pollFlag: 90000003
pollFlag: fa0003
pollFlag: 3f020
Done
pollFlag: 3f020
pollFlag: 3f020
pollFlag: 3f0a0
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
Flash SRAM: [==                                                ] 3.92%
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
mpsse_store: fails to first flush -1 usb bulk write failed
mpsse_write: fail to write with error -1 (usb bulk write failed)
...

The first 3 also logged in dmesg:

[1051876.507788] ftdi_sio ttyUSB1: Unable to read latency timer: -71
[1051876.509786] usb 1-1: FTDI USB Serial Device converter now attached to ttyUSB1
[1051884.019900] ftdi_sio ttyUSB0: FTDI USB Serial Device converter now disconnected from ttyUSB0
[1051884.019916] ftdi_sio 1-1:1.0: device disconnected
[1051901.567938] ftdi_sio 1-1:1.0: FTDI USB Serial Device converter detected
[1051901.568034] usb 1-1: Detected FT2232C/D
[1051901.570530] ftdi_sio ttyUSB0: Unable to read latency timer: -121
[1051904.483129] ftdi_sio ttyUSB0: Unable to write latency timer: -71
[1051904.483499] usb 1-1: FTDI USB Serial Device converter now attached to ttyUSB0
[1051955.828615] ftdi_sio ttyUSB0: FTDI USB Serial Device converter now disconnected from ttyUSB0
[1051955.828631] ftdi_sio 1-1:1.0: device disconnected
[1051956.653034] ftdi_sio 1-1:1.0: FTDI USB Serial Device converter detected
[1051956.653131] usb 1-1: Detected FT2232C/D
[1051957.747695] ftdi_sio ttyUSB0: Unable to write latency timer: -71

another try got up to 39% while logging the mpsse_* messages way quicker

I've tried two cables that have worked with other devices, but after replacing it again with an USB-C charging cable (thicker, rated to 60W), it succeeded repeatedly.

trabucayre commented 3 months ago

Yes: cables are not always good or enough. I don't know the exact reason (maybe to electrical noise, or lost of current). It's usual to have to switch between cables...