oxidecomputer / humility

Debugger for Hubris
Mozilla Public License 2.0
529 stars 51 forks source link

humility fails silently on Windows when a FTDI dongle is plugged in #163

Open Aaron-Hartwig opened 2 years ago

Aaron-Hartwig commented 2 years ago

I have an ST-LINK connected to the SP and also an Adafruit FTDI dongle connected to a target FPGA. When attempting to use humility with both dongles present, humility will fail silently. Removing the FTDI dongle fixes this.

c:\oxide\humility\target\release (master -> origin)
λ humility probe

<Eric unplugs FTDI dongle>

c:\oxide\humility\target\release (master -> origin)
λ humility probe
humility: attached via ST-Link
humility:        probe => STLink V3, VID 0483, PID 374e
humility: probe serial => 000B000C5553500820393256
humility:         core => Cortex-M7
humility: manufacturer => STMicroelectronics
humility:         chip => STM32H7, revision 0x2003
humility:       status => executing
humility:  debug units => CSTF(x2) CTI(x2) DWT ETM FPB ITM SCS SWO TMC TPIU
humility:         CSTF => 0x5c004000, 0x5c013000
humility:          CTI => 0x5c011000, 0xe0043000
humility:          DWT => 0xe0001000
humility:          ETM => 0xe0041000
humility:          FPB => 0xe0002000
humility:          ITM => 0xe0000000
humility:          SCS => 0xe000e000
humility:          SWO => 0x5c003000
humility:          TMC => 0x5c014000
humility:         TPIU => 0x5c015000
humility:   ITM status => TRCENA enabled, TCR disabled, TER=0x0
humility:           R0 => 0x20015100
humility:           R1 => 0x20015100
humility:           R2 => 0x0         <- _TASK_SLOT_TABLE_RCC+0x0
humility:           R3 => 0x0         <- _TASK_SLOT_TABLE_RCC+0x0
humility:           R4 => 0x0         <- _TASK_SLOT_TABLE_RCC+0x0
humility:           R5 => 0x0         <- _TASK_SLOT_TABLE_RCC+0x0
humility:           R6 => 0x0         <- _TASK_SLOT_TABLE_RCC+0x0
humility:           R7 => 0x200150f8
humility:           R8 => 0x0         <- _TASK_SLOT_TABLE_RCC+0x0
humility:           R9 => 0x0         <- _TASK_SLOT_TABLE_RCC+0x0
humility:          R10 => 0x0         <- _TASK_SLOT_TABLE_RCC+0x0
humility:          R11 => 0x0         <- _TASK_SLOT_TABLE_RCC+0x0
humility:          R12 => 0x0         <- _TASK_SLOT_TABLE_RCC+0x0
humility:           SP => 0x200150f8
humility:           LR => 0x804c04f   <- idle:_start+0x4f
humility:           PC => 0x804c056   <- idle:main+0x6
humility:         xPSR => 0x61000000
humility:          MSP => 0x20000350
humility:          PSP => 0x200150f8
humility:          SPR => 0x7000000
C:\Users\Aaron\Oxide\git\hubris (master -> origin)
λ humility -a target\gimletlet\dist\build-gimletlet.zip flash

<Aaron unplugs the adafruit FTDI dongle>

C:\Users\Aaron\Oxide\git\hubris (master -> origin)
λ humility -a target\gimletlet\dist\build-gimletlet.zip flash
humility: attached via ST-Link V3
humility: specifying serial 001F003A4741500520383733
xPack OpenOCD, x86_64 Open On-Chip Debugger 0.10.0+dev (2020-10-13-17:29)
Licensed under GNU GPL v2
For bug reports, read
        http://openocd.org/doc/doxygen/bugs.html
DEPRECATED! use 'adapter driver' not 'interface'
Warn : Interface already configured, ignoring
Info : auto-selecting first available session transport "hla_swd". To override use 'transport select <transport>'.
Info : The selected transport took over low-level target control. The results might differ compared to plain JTAG/SWDInfo : clock speed 1800 kHz
Info : STLINK V3J8M3 (API v3) VID:PID 0483:374E
Info : Target voltage: 3.319149
Info : stm32h7x.cpu0: hardware has 8 breakpoints, 4 watchpoints
Info : starting gdb server for stm32h7x.cpu0 on 3343
Info : Listening on port 3343 for gdb connections
target halted due to debug-request, current mode: Thread
xPSR: 0x01000000 pc: 0x08000298 msp: 0x20000400
Info : Unable to match requested speed 4000 kHz, using 3300 kHz
Info : Unable to match requested speed 4000 kHz, using 3300 kHz
** Programming Started **
Info : Device: STM32H74x/75x
Info : flash size probed value 2048
Info : STM32H7 flash has dual banks
Info : Bank (0) size is 1024 kb, base address is 0x08000000
Info : Padding image section 0 at 0x0800c008 with 8 bytes
Info : Padding image section 1 at 0x0801bf98 with 8 bytes
Info : Padding image section 2 at 0x08021a4c with 4 bytes
Info : Padding image section 3 at 0x08025e7c with 4 bytes
Info : Padding image section 4 at 0x08029ae4 with 12 bytes
Info : Padding image section 5 at 0x0802f59c with 4 bytes
Info : Padding image section 6 at 0x08034fd8 with 8 bytes
Info : Padding image section 7 at 0x0803724c with 4 bytes
Info : Padding image section 8 at 0x08038634 with 12 bytes
Warn : Adding extra erase range, 0x08039480 .. 0x0803ffff
** Programming Finished **
** Verify Started **
** Verified OK **
** Resetting Target **

Here's a verbose log of the flash attempt.

C:\Users\Aaron\Oxide\git\hubris (master -> origin)
λ humility -v -a target\gimletlet\dist\build-gimletlet.zip flash
[2022-06-17T17:24:43Z TRACE humility_core::hubris] loading kernel as object 0
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x00000a4c
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x0000e238
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x00012e8d
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x00022caf
[2022-06-17T17:24:43Z TRACE humility_core::hubris] loading jefe as object 1
[2022-06-17T17:24:43Z TRACE humility_core::hubris] loading sys as object 2
[2022-06-17T17:24:43Z TRACE humility_core::hubris] loading i2c_driver as object 3
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x00013f19 (object 3)
[2022-06-17T17:24:43Z TRACE humility_core::hubris] loading spi_driver as object 4
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x000146f3 (object 4)
[2022-06-17T17:24:43Z TRACE humility_core::hubris] loading user_leds as object 5
[2022-06-17T17:24:43Z TRACE humility_core::hubris] loading pong as object 6
[2022-06-17T17:24:43Z TRACE humility_core::hubris] loading uartecho as object 7
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x000100f1 (object 7)
[2022-06-17T17:24:43Z TRACE humility_core::hubris] loading hiffy as object 8
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x00017506 (object 8)
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x000175bb (object 8)
[2022-06-17T17:24:43Z TRACE humility_core::hubris] loading hf as object 9
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x00013ef0 (object 9)
[2022-06-17T17:24:43Z TRACE humility_core::hubris] loading net as object 10
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x00020e20 (object 10)
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x00038789 (object 10)
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x000457bf (object 10)
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x00045b7b (object 10)
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x00046221 (object 10)
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x000462fe (object 10)
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x000468f2 (object 10)
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x0004692b (object 10)
[2022-06-17T17:24:43Z TRACE humility_core::hubris] loading udpecho as object 11
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x0000878b (object 11)
[2022-06-17T17:24:43Z TRACE humility_core::hubris] loading validate as object 12
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x0001a9c8 (object 12)
[2022-06-17T17:24:43Z TRACE humility_core::hubris] loading idle as object 13
[2022-06-17T17:24:43Z TRACE humility_core::hubris] loading rng_driver as object 14
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x0000dd6e (object 14)
[2022-06-17T17:24:43Z TRACE humility_core::hubris] loading update_server as object 15
[2022-06-17T17:24:43Z TRACE humility_core::hubris] no name found for GOFF 0x0000e10d (object 15)
[2022-06-17T17:24:43Z DEBUG probe_rs::probe::cmsisdap::tools] Searching for CMSIS-DAP probes using libusb
Aaron-Hartwig commented 2 years ago

Probably this? https://github.com/probe-rs/probe-rs/issues/935

Aaron-Hartwig commented 2 years ago

Although I'm a little skeptical the aforementioned probe-rs issue fixes the problem given it doesn't bump rusb >= 0.9.1 as the author seems to intend, it bumps it to 0.9.0

bcantrill commented 2 years ago

Just for anyone else that hits this or similar issue on Windows, we looked at the status code by examining the %errorlevel% variable:

λ echo %ERRORLEVEL%
-1073741819

Going into the Windows Event Viewer, we were able to extract a WER file:

Version=1
EventType=APPCRASH
EventTime=132999661321760364
ReportType=2
Consent=1
UploadTime=132999661323610952
ReportStatus=268435456
ReportIdentifier=34b2c0b5-db6d-4f70-bb79-d2f7a4a06b47
IntegratorReportIdentifier=49a96d2a-ae5f-4a2b-b54d-eb53401da77e
Wow64Host=34404
NsAppName=humility.exe
AppSessionGuid=00001eb8-0001-0084-33d5-b7bf7c82d801
TargetAppId=W:0006d3f647e0a9e38b6e96e95bbf63e7e4d20000ffff!0000b0ca054ef6d8418866eb1971de3ac2fc31df3ec2!humility.exe
TargetAppVer=2022//06//17:16:52:43!0!humility.exe
BootId=4294967295
TargetAsId=8656
IsFatal=1
EtwNonCollectReason=1
Response.BucketId=1513d8c2ffbede1dc70c37ecf1114ff6
Response.BucketTable=4
Response.LegacyBucketId=1660763853389123574
Response.type=4
Sig[0].Name=Application Name
Sig[0].Value=humility.exe
Sig[1].Name=Application Version
Sig[1].Value=0.0.0.0
Sig[2].Name=Application Timestamp
Sig[2].Value=62acb15b
Sig[3].Name=Fault Module Name
Sig[3].Value=humility.exe
Sig[4].Name=Fault Module Version
Sig[4].Value=0.0.0.0
Sig[5].Name=Fault Module Timestamp
Sig[5].Value=62acb15b
Sig[6].Name=Exception Code
Sig[6].Value=c0000005
Sig[7].Name=Exception Offset
Sig[7].Value=000000000062a8e2
DynamicSig[1].Name=OS Version
DynamicSig[1].Value=10.0.19044.2.0.0.256.48
DynamicSig[2].Name=Locale ID
DynamicSig[2].Value=1033
DynamicSig[22].Name=Additional Information 1
DynamicSig[22].Value=6996
DynamicSig[23].Name=Additional Information 2
DynamicSig[23].Value=699687fe92400ce861386f9e043d4e93
DynamicSig[24].Name=Additional Information 3
DynamicSig[24].Value=29ea
DynamicSig[25].Name=Additional Information 4
DynamicSig[25].Value=29ea27f8f39ae6dca3442971bd67cc50
UI[2]=C:\Users\Aaron\Oxide\git\humility\target\release\humility.exe
LoadedModule[0]=C:\Users\Aaron\Oxide\git\humility\target\release\humility.exe
LoadedModule[1]=C:\Windows\SYSTEM32\ntdll.dll
LoadedModule[2]=C:\Windows\System32\KERNEL32.DLL
LoadedModule[3]=C:\Windows\System32\KERNELBASE.dll
LoadedModule[4]=C:\Windows\System32\WS2_32.dll
LoadedModule[5]=C:\Windows\System32\RPCRT4.dll
LoadedModule[6]=C:\Windows\System32\bcrypt.dll
LoadedModule[7]=C:\Windows\System32\ucrtbase.dll
LoadedModule[8]=C:\Windows\SYSTEM32\VCRUNTIME140.dll
LoadedModule[9]=C:\tools\Cmder\vendor\conemu-maximus5\ConEmu\ConEmuHk64.dll
LoadedModule[10]=C:\Windows\System32\USER32.dll
LoadedModule[11]=C:\Windows\System32\win32u.dll
LoadedModule[12]=C:\Windows\System32\GDI32.dll
LoadedModule[13]=C:\Windows\System32\gdi32full.dll
LoadedModule[14]=C:\Windows\System32\msvcp_win.dll
LoadedModule[15]=C:\Windows\System32\IMM32.DLL
LoadedModule[16]=C:\Windows\System32\bcryptprimitives.dll
LoadedModule[17]=C:\Windows\system32\mswsock.dll
LoadedModule[18]=C:\Windows\System32\Cfgmgr32.dll
LoadedModule[19]=C:\Windows\System32\AdvAPI32.dll
LoadedModule[20]=C:\Windows\System32\msvcrt.dll
LoadedModule[21]=C:\Windows\System32\sechost.dll
LoadedModule[22]=C:\Windows\System32\OLE32.dll
LoadedModule[23]=C:\Windows\System32\combase.dll
LoadedModule[24]=C:\Windows\System32\SetupAPI.dll
LoadedModule[25]=C:\Windows\system32\WinUSB.dll
LoadedModule[26]=C:\Windows\system32\libusbK.dll
LoadedModule[27]=C:\Windows\System32\wintrust.DLL
LoadedModule[28]=C:\Windows\System32\CRYPT32.dll
LoadedModule[29]=C:\Windows\SYSTEM32\MSASN1.dll
LoadedModule[30]=C:\Windows\system32\hid.dll
LoadedModule[31]=C:\Windows\SYSTEM32\kernel.appcore.dll
LoadedModule[32]=C:\Windows\SYSTEM32\DEVOBJ.dll
State[0].Key=Transport.DoneStage1
State[0].Value=1
OsInfo[0].Key=vermaj
OsInfo[0].Value=10
OsInfo[1].Key=vermin
OsInfo[1].Value=0
OsInfo[2].Key=verbld
OsInfo[2].Value=19044
OsInfo[3].Key=ubr
OsInfo[3].Value=1741
OsInfo[4].Key=versp
OsInfo[4].Value=0
OsInfo[5].Key=arch
OsInfo[5].Value=9
OsInfo[6].Key=lcid
OsInfo[6].Value=1033
OsInfo[7].Key=geoid
OsInfo[7].Value=244
OsInfo[8].Key=sku
OsInfo[8].Value=48
OsInfo[9].Key=domain
OsInfo[9].Value=0
OsInfo[10].Key=prodsuite
OsInfo[10].Value=256
OsInfo[11].Key=ntprodtype
OsInfo[11].Value=1
OsInfo[12].Key=platid
OsInfo[12].Value=10
OsInfo[13].Key=sr
OsInfo[13].Value=0
OsInfo[14].Key=tmsi
OsInfo[14].Value=221663343
OsInfo[15].Key=osinsty
OsInfo[15].Value=1
OsInfo[16].Key=iever
OsInfo[16].Value=11.789.19041.0-11.0.1000
OsInfo[17].Key=portos
OsInfo[17].Value=0
OsInfo[18].Key=ram
OsInfo[18].Value=32486
OsInfo[19].Key=svolsz
OsInfo[19].Value=952
OsInfo[20].Key=wimbt
OsInfo[20].Value=0
OsInfo[21].Key=blddt
OsInfo[21].Value=191206
OsInfo[22].Key=bldtm
OsInfo[22].Value=1406
OsInfo[23].Key=bldbrch
OsInfo[23].Value=vb_release
OsInfo[24].Key=bldchk
OsInfo[24].Value=0
OsInfo[25].Key=wpvermaj
OsInfo[25].Value=0
OsInfo[26].Key=wpvermin
OsInfo[26].Value=0
OsInfo[27].Key=wpbuildmaj
OsInfo[27].Value=0
OsInfo[28].Key=wpbuildmin
OsInfo[28].Value=0
OsInfo[29].Key=osver
OsInfo[29].Value=10.0.19041.1741.amd64fre.vb_release.191206-1406
OsInfo[30].Key=buildflightid
OsInfo[31].Key=edition
OsInfo[31].Value=Professional
OsInfo[32].Key=ring
OsInfo[32].Value=Retail
OsInfo[33].Key=expid
OsInfo[34].Key=fconid
OsInfo[35].Key=containerid
OsInfo[36].Key=containertype
OsInfo[37].Key=edu
OsInfo[37].Value=0
FriendlyEventName=Stopped working
ConsentKey=APPCRASH
AppName=humility.exe
AppPath=C:\Users\Aaron\Oxide\git\humility\target\release\humility.exe
NsPartner=windows
NsGroup=windows8
ApplicationIdentity=5B57490550F7BE41A7D87100D822CB90

This is indeed https://github.com/probe-rs/probe-rs/issues/935 -- which itself is fixed by https://github.com/libusb/libusb/commit/f5275f9a87db898af56060958df182ef7e5c1240. The fix here is to bump the vendored libusb in rusb from 1.0.24 to 1.0.26.