Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Bridge crash if session is released while reading from USB #248

Open
matejcik opened this issue May 25, 2022 · 0 comments
Open

Bridge crash if session is released while reading from USB #248

matejcik opened this issue May 25, 2022 · 0 comments

Comments

@matejcik
Copy link

matejcik commented May 25, 2022 •
edited
Loading

the following script (requires trezorlib and a plugged in Trezor device) will reliably crash Bridge on MacOS M1

script 
from threading import Thread
from time import sleep

from trezorlib.log import enable_debug_output
from trezorlib.transport.bridge import BridgeTransport
from trezorlib import messages
from trezorlib.mapping import DEFAULT_MAPPING

enable_debug_output()

device = next(iter(BridgeTransport.enumerate()))

ping_msg = DEFAULT_MAPPING.encode(messages.Ping(message="ping"))

def do_write():
    sleep(1)
    device.write(*ping_msg)
    device._call("release")

bgtask = Thread(target=do_write)
bgtask.start()
device.begin_session()

device.read()

bgtask.join()

This is the sequence of events, in plain language:

  1. acquire a session
  2. call a /read while the device is not writing anything
  3. while waiting, call a /post, sending data which will trigger a response for the pending read
  4. immediately after writing, /release the session

This is the full list of calls to Bridge:

http://127.0.0.1:21325/configure
http://127.0.0.1:21325/enumerate
http://127.0.0.1:21325/acquire/1/null
http://127.0.0.1:21325/read/1
http://127.0.0.1:21325/post/1
http://127.0.0.1:21325/release/1

It seems that Bridge dislikes disconnecting while actively receiving data from USB.

bridge log 
2022/05/26 12:08:03 trezord v2.0.31 (rev unknown) is starting
[0.000256 : 12:08:03] [trezord.go 77 main.initUsb] Initing libusb
[0.000452 : 12:08:03] [usb/libusb.go 63 usb.InitLibUSB] init
[0.003055 : 12:08:03] [usb/libusb.go 74 usb.InitLibUSB] init done
[0.003066 : 12:08:03] [trezord.go 88 main.initUsb] Initing hidapi
[0.003074 : 12:08:03] [trezord.go 179 main.main] UDP port count - 0
[0.003080 : 12:08:03] [trezord.go 201 main.main] Creating core
[0.003089 : 12:08:03] [trezord.go 203 main.main] Creating HTTP server
[0.003136 : 12:08:03] [server/http.go 35 server.New] starting
[0.003388 : 12:08:03] [server/http.go 68 server.New] server created
[0.003396 : 12:08:03] [trezord.go 210 main.main] Running HTTP server
POST /configure
[5.313582 : 12:08:08] POST /configure
[5.314281 : 12:08:08] [server/api/api.go 58 server/api.(*api).Info] version 2.0.31 (rev unknown)
127.0.0.1 - - [26/May/2022:12:08:08 +0200] "POST /configure HTTP/1.1" 200 41
[5.314738 : 12:08:08] 127.0.0.1 - - [26/May/2022:12:08:08 +0200] "POST /configure HTTP/1.1" 200 41
POST /enumerate
[5.315775 : 12:08:08] POST /enumerate
[5.315794 : 12:08:08] [server/api/api.go 102 server/api.(*api).Enumerate] start
[5.315804 : 12:08:08] [core/core.go 254 core.(*Core).Enumerate] callsInProgress 0
[5.315811 : 12:08:08] [core/core.go 256 core.(*Core).Enumerate] bus
[5.315820 : 12:08:08] [usb/libusb.go 121 usb.(*LibUSB).Enumerate] low level enumerating
[5.315861 : 12:08:08] [usb/libusb.go 127 usb.(*LibUSB).Enumerate] low level enumerating done
[5.315868 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.315877 : 12:08:08] [usb/libusb.go 360 usb.(*LibUSB).match] matched, get active config
[5.315895 : 12:08:08] [usb/libusb.go 367 usb.(*LibUSB).match] let's test
[5.315901 : 12:08:08] [usb/libusb.go 389 usb.(*LibUSB).match] matched
[5.315907 : 12:08:08] [usb/libusb.go 147 usb.(*LibUSB).Enumerate] getting device descriptor
[5.315916 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.315923 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.315929 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.315935 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.315940 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.315946 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.315952 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.315958 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.315963 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.315969 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.315974 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.315980 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.315986 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.315992 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.315997 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.316003 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.316008 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.316014 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.316020 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.316026 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.316031 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.316037 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.316042 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.316051 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.316057 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.316063 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.316069 : 12:08:08] [usb/libusb.go 130 usb.(*LibUSB).Enumerate.func1] freeing device list
[5.316075 : 12:08:08] [usb/libusb.go 132 usb.(*LibUSB).Enumerate.func1] freeing device list done
[5.316081 : 12:08:08] [usb/hidapi.go 41 usb.(*HIDAPI).Enumerate] low level
[5.318646 : 12:08:08] [usb/hidapi.go 44 usb.(*HIDAPI).Enumerate] low level done
[5.318670 : 12:08:08] [core/core.go 266 core.(*Core).Enumerate] release disconnected
[5.318686 : 12:08:08] [server/api/api.go 108 server/api.(*api).Enumerate] encoding and exiting
127.0.0.1 - - [26/May/2022:12:08:08 +0200] "POST /enumerate HTTP/1.1" 200 93
[5.318722 : 12:08:08] 127.0.0.1 - - [26/May/2022:12:08:08 +0200] "POST /enumerate HTTP/1.1" 200 93
POST /acquire/1/null
[5.321627 : 12:08:08] POST /acquire/1/null
[5.321673 : 12:08:08] [core/core.go 434 core.(*Core).Acquire] input path 1 prev 
[5.321680 : 12:08:08] [core/core.go 438 core.(*Core).Acquire] actually previous 
[5.321685 : 12:08:08] [core/core.go 471 core.(*Core).Acquire] trying to connect
[5.321690 : 12:08:08] [core/core.go 500 core.(*Core).tryConnect] try number 0
[5.321695 : 12:08:08] [usb/libusb.go 180 usb.(*LibUSB).Connect] low level enumerating
[5.321719 : 12:08:08] [usb/libusb.go 186 usb.(*LibUSB).Connect] low level enumerating done
[5.321724 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.321729 : 12:08:08] [usb/libusb.go 360 usb.(*LibUSB).match] matched, get active config
[5.321738 : 12:08:08] [usb/libusb.go 367 usb.(*LibUSB).match] let's test
[5.321745 : 12:08:08] [usb/libusb.go 389 usb.(*LibUSB).match] matched
[5.321750 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.321755 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.321759 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.321764 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.321768 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.321772 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.321776 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.321781 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.321785 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.321789 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.321793 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.321797 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.321802 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.321806 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.321810 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.321815 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.321819 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.321824 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.321828 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.321832 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.321836 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.321841 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.321845 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.321849 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.321853 : 12:08:08] [usb/libusb.go 346 usb.(*LibUSB).match] start
[5.321858 : 12:08:08] [usb/libusb.go 356 usb.(*LibUSB).match] unmatched
[5.321863 : 12:08:08] [usb/libusb.go 286 usb.(*LibUSB).connect] detect old BL
[5.321869 : 12:08:08] [usb/libusb.go 292 usb.(*LibUSB).connect] low level
[5.321939 : 12:08:08] [usb/libusb.go 297 usb.(*LibUSB).connect] reset
[5.428120 : 12:08:08] [usb/libusb.go 223 usb.(*LibUSB).setConfiguration] current configuration 1
[5.428145 : 12:08:08] [usb/libusb.go 226 usb.(*LibUSB).setConfiguration] not setting config, same
[5.428150 : 12:08:08] [usb/libusb.go 271 usb.(*LibUSB).claimInterface] claiming interface
[5.434888 : 12:08:08] [usb/libusb.go 279 usb.(*LibUSB).claimInterface] claiming interface done
[5.434896 : 12:08:08] [usb/libusb.go 189 usb.(*LibUSB).Connect.func1] freeing device list
[5.434901 : 12:08:08] [usb/libusb.go 191 usb.(*LibUSB).Connect.func1] freeing device list done
[5.434915 : 12:08:08] [core/core.go 486 core.(*Core).Acquire] new session is 1
127.0.0.1 - - [26/May/2022:12:08:08 +0200] "POST /acquire/1/null HTTP/1.1" 200 16
[5.434946 : 12:08:08] 127.0.0.1 - - [26/May/2022:12:08:08 +0200] "POST /acquire/1/null HTTP/1.1" 200 16
POST /read/1
[5.436385 : 12:08:08] POST /read/1
[5.436421 : 12:08:08] [server/api/api.go 196 server/api.(*api).call] start
[5.436428 : 12:08:08] [core/core.go 568 core.(*Core).Call] checking other call on same session
[5.436435 : 12:08:08] [core/core.go 574 core.(*Core).Call] checking other call on same session done
[5.436443 : 12:08:08] [core/core.go 599 core.(*Core).Call] before actual logic
[5.436464 : 12:08:08] [core/core.go 639 core.(*Core).readWriteDev] skipping write
[5.436471 : 12:08:08] [core/core.go 619 core.(*Core).readDev] readFrom
[5.436477 : 12:08:08] [wire/v1.go 76 wire.ReadFrom] start
[5.436784 : 12:08:08] [usb/libusb.go 569 usb.(*LibUSBDevice).Read] read start
[5.436792 : 12:08:08] [usb/libusb.go 505 usb.(*LibUSBDevice).readWrite] start
[5.436797 : 12:08:08] [usb/libusb.go 507 usb.(*LibUSBDevice).readWrite] checking closed
[5.436802 : 12:08:08] [usb/libusb.go 515 usb.(*LibUSBDevice).readWrite] actual interrupt transport
[5.514160 : 12:08:08] [core/core.go 184 core.(*Core).backgroundListen] background enum runs
[5.514200 : 12:08:08] [core/core.go 254 core.(*Core).Enumerate] callsInProgress 1
[5.514221 : 12:08:08] [core/core.go 266 core.(*Core).Enumerate] release disconnected
[6.015346 : 12:08:09] [core/core.go 184 core.(*Core).backgroundListen] background enum runs
[6.015441 : 12:08:09] [core/core.go 254 core.(*Core).Enumerate] callsInProgress 1
[6.015484 : 12:08:09] [core/core.go 266 core.(*Core).Enumerate] release disconnected
POST /post/1
[6.329380 : 12:08:09] POST /post/1
[6.329462 : 12:08:09] [server/api/api.go 196 server/api.(*api).call] start
[6.329512 : 12:08:09] [core/core.go 599 core.(*Core).Call] before actual logic
[6.329533 : 12:08:09] [core/core.go 607 core.(*Core).writeDev] decodeRaw
[6.329549 : 12:08:09] [core/core.go 659 core.(*Core).decodeRaw] readAll
[6.329563 : 12:08:09] [core/core.go 661 core.(*Core).decodeRaw] decodeString
[6.329579 : 12:08:09] [core/core.go 681 core.(*Core).decodeRaw] returning
[6.329595 : 12:08:09] [core/core.go 613 core.(*Core).writeDev] writeTo
[6.329611 : 12:08:09] [wire/v1.go 25 wire.(*Message).WriteTo] start
[6.329626 : 12:08:09] [wire/v1.go 39 wire.(*Message).WriteTo] actually writing
[6.329641 : 12:08:09] [usb/libusb.go 555 usb.(*LibUSBDevice).Write] write start
[6.329655 : 12:08:09] [usb/libusb.go 505 usb.(*LibUSBDevice).readWrite] start
[6.329682 : 12:08:09] [usb/libusb.go 507 usb.(*LibUSBDevice).readWrite] checking closed
[6.329698 : 12:08:09] [usb/libusb.go 515 usb.(*LibUSBDevice).readWrite] actual interrupt transport
[6.331292 : 12:08:09] [usb/libusb.go 519 usb.(*LibUSBDevice).readWrite] single transfer done
[6.331341 : 12:08:09] [usb/libusb.go 535 usb.(*LibUSBDevice).readWrite] single transfer successful
[6.331365 : 12:08:09] [core/core.go 650 core.(*Core).readWriteDev] skipping read
[6.331385 : 12:08:09] [core/core.go 601 core.(*Core).Call] after actual logic
127.0.0.1 - - [26/May/2022:12:08:09 +0200] "POST /post/1 HTTP/1.1" 200 0
[6.331418 : 12:08:09] 127.0.0.1 - - [26/May/2022:12:08:09 +0200] "POST /post/1 HTTP/1.1" 200 0
POST /release/1
[6.335022 : 12:08:09] POST /release/1
[6.335085 : 12:08:09] [server/api/api.go 154 server/api.(*api).release] start
[6.335117 : 12:08:09] [core/core.go 359 core.(*Core).release] session 1
[6.335134 : 12:08:09] [core/core.go 368 core.(*Core).release] bus close
[6.335149 : 12:08:09] [usb/libusb.go 436 usb.(*LibUSBDevice).Close] storing d.closed
[6.335163 : 12:08:09] [usb/libusb.go 444 usb.(*LibUSBDevice).Close] canceling previous transfers
crash backtrace 
Assertion failed: (pthread_mutex_lock(mutex) == 0), function usbi_mutex_lock, file threads_posix.h, line 46.
SIGABRT: abort
PC=0x1c46acdb8 m=3 sigcode=0
signal arrived during cgo execution

goroutine 73 [syscall]:
runtime.cgocall(0x103279eac, 0x140001c9288)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/runtime/cgocall.go:157 +0x54 fp=0x140001c9250 sp=0x140001c9210 pc=0x102f67994
github.com/trezor/trezord-go/usb/lowlevel/libusb._Cfunc_libusb_cancel_sync_transfers_on_device(0x150008000)
	_cgo_gotypes.go:580 +0x38 fp=0x140001c9280 sp=0x140001c9250 pc=0x103261b68
github.com/trezor/trezord-go/usb/lowlevel/libusb.Cancel_Sync_Transfers_On_Device.func1(0x1035be6e0?)
	/Users/matejcik/projekty/prace/trezord-go/usb/lowlevel/libusb/libusb.go:1438 +0x44 fp=0x140001c92c0 sp=0x140001c9280 pc=0x1032646e4
github.com/trezor/trezord-go/usb/lowlevel/libusb.Cancel_Sync_Transfers_On_Device(0x1033f3d09?)
	/Users/matejcik/projekty/prace/trezord-go/usb/lowlevel/libusb/libusb.go:1438 +0x20 fp=0x140001c92e0 sp=0x140001c92c0 pc=0x103264680
github.com/trezor/trezord-go/usb.(*LibUSBDevice).Close(0x140001b9940, 0x0)
	/Users/matejcik/projekty/prace/trezord-go/usb/libusb.go:445 +0x74 fp=0x140001c9330 sp=0x140001c92e0 pc=0x1032679e4
github.com/trezor/trezord-go/core.(*Core).release(0x140000b4b60, {0x140001dc09e, 0x1}, 0x7?, 0x0)
	/Users/matejcik/projekty/prace/trezord-go/core/core.go:369 +0x13c fp=0x140001c93c0 sp=0x140001c9330 pc=0x10305aa0c
github.com/trezor/trezord-go/core.(*Core).Release(...)
	/Users/matejcik/projekty/prace/trezord-go/core/core.go:351
github.com/trezor/trezord-go/server/api.(*api).release(0x14000090c60, {0x1033cf118?, 0x14000110140}, 0x10324bf08?, 0x8?)
	/Users/matejcik/projekty/prace/trezord-go/server/api/api.go:159 +0x90 fp=0x140001c9470 sp=0x140001c93c0 pc=0x1031f2bb0
github.com/trezor/trezord-go/server/api.(*api).Release(0x14000058901?, {0x1033cf118?, 0x14000110140?}, 0x0?)
	/Users/matejcik/projekty/prace/trezord-go/server/api/api.go:146 +0x2c fp=0x140001c94b0 sp=0x140001c9470 pc=0x1031f2a6c
github.com/trezor/trezord-go/server/api.(*api).Release-fm({0x1033cf118?, 0x14000110140?}, 0x14000110001?)
	<autogenerated>:1 +0x44 fp=0x140001c94e0 sp=0x140001c94b0 pc=0x1031f3d64
net/http.HandlerFunc.ServeHTTP(0x10339d600?, {0x1033cf118?, 0x14000110140?}, 0x1b?)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/http/server.go:2084 +0x3c fp=0x140001c9510 sp=0x140001c94e0 pc=0x1031a57fc
github.com/trezor/trezord-go/server/api.(*cors).ServeHTTP(0x1400000e018, {0x1033cf118, 0x14000110140}, 0x1400021a200)
	/Users/matejcik/projekty/prace/trezord-go/server/api/cors.go:69 +0x26c fp=0x140001c95d0 sp=0x140001c9510 pc=0x1031f391c
github.com/gorilla/mux.(*Router).ServeHTTP(0x140000f0000, {0x1033cf118, 0x14000110140}, 0x1400021a000)
	/Users/matejcik/go/pkg/mod/github.com/gorilla/[email protected]/mux.go:210 +0x1a0 fp=0x140001c9700 sp=0x140001c95d0 pc=0x1031e9440
github.com/gorilla/handlers.loggingHandler.ServeHTTP({{0x1033cc788, 0x140000a80a8}, {0x1033cc608, 0x140000f0000}, 0x1033ca4b8}, {0x1033ceba8, 0x140001180e0}, 0x1400021a000)
	/Users/matejcik/go/pkg/mod/github.com/gorilla/[email protected]/logging.go:47 +0xa0 fp=0x140001c9950 sp=0x140001c9700 pc=0x10325d180
github.com/gorilla/handlers.(*loggingHandler).ServeHTTP(0x1032819c0?, {0x1033ceba8?, 0x140001180e0?}, 0x10?)
	<autogenerated>:1 +0x7c fp=0x140001c99d0 sp=0x140001c9950 pc=0x10325ea6c
github.com/trezor/trezord-go/server.(*Server).logRequest.func1({0x1033ceba8, 0x140001180e0}, 0x1400021a000)
	/Users/matejcik/projekty/prace/trezord-go/server/http.go:80 +0x138 fp=0x140001c9a50 sp=0x140001c99d0 pc=0x10325f408
net/http.HandlerFunc.ServeHTTP(0x0?, {0x1033ceba8?, 0x140001180e0?}, 0x102fa23ac?)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/http/server.go:2084 +0x3c fp=0x140001c9a80 sp=0x140001c9a50 pc=0x1031a57fc
net/http.serverHandler.ServeHTTP({0x140004aac90?}, {0x1033ceba8, 0x140001180e0}, 0x1400021a000)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/http/server.go:2916 +0x3fc fp=0x140001c9b40 sp=0x140001c9a80 pc=0x1031a89bc
net/http.(*conn).serve(0x140004c0000, {0x1033cf460, 0x140004aa930})
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/http/server.go:1966 +0x56c fp=0x140001c9fa0 sp=0x140001c9b40 pc=0x1031a453c
net/http.(*Server).Serve.func3()
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/http/server.go:3071 +0x34 fp=0x140001c9fd0 sp=0x140001c9fa0 pc=0x1031a9204
runtime.goexit()
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/runtime/asm_arm64.s:1263 +0x4 fp=0x140001c9fd0 sp=0x140001c9fd0 pc=0x102fc69f4
created by net/http.(*Server).Serve
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/http/server.go:3071 +0x450

goroutine 1 [IO wait]:
internal/poll.runtime_pollWait(0x12a5ef898, 0x72)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/runtime/netpoll.go:302 +0xa4
internal/poll.(*pollDesc).wait(0x140000a6400?, 0x4?, 0x0)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/internal/poll/fd_poll_runtime.go:83 +0x2c
internal/poll.(*pollDesc).waitRead(...)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/internal/poll/fd_poll_runtime.go:88
internal/poll.(*FD).Accept(0x140000a6400)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/internal/poll/fd_unix.go:614 +0x1d0
net.(*netFD).accept(0x140000a6400)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/fd_unix.go:172 +0x28
net.(*TCPListener).accept(0x140000a8138)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/tcpsock_posix.go:139 +0x2c
net.(*TCPListener).Accept(0x140000a8138)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/tcpsock.go:288 +0x30
net/http.(*Server).Serve(0x140000ee000, {0x1033ce9c8, 0x140000a8138})
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/http/server.go:3039 +0x318
net/http.(*Server).ListenAndServe(0x140000ee000)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/http/server.go:2968 +0x88
github.com/trezor/trezord-go/server.(*Server).Run(...)
	/Users/matejcik/projekty/prace/trezord-go/server/http.go:85
main.main()
	/Users/matejcik/projekty/prace/trezord-go/trezord.go:211 +0x924

goroutine 34 [chan receive]:
gopkg.in/natefinch/lumberjack%2ev2.(*Logger).millRun(0x1400008e420)
	/Users/matejcik/go/pkg/mod/gopkg.in/natefinch/[email protected]/lumberjack.go:379 +0x48
created by gopkg.in/natefinch/lumberjack%2ev2.(*Logger).mill.func1
	/Users/matejcik/go/pkg/mod/gopkg.in/natefinch/[email protected]/lumberjack.go:390 +0xa8

goroutine 35 [sleep]:
time.Sleep(0x1dcd6500)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/runtime/time.go:194 +0x11c
github.com/trezor/trezord-go/core.(*Core).backgroundListen(0x140000b4b60)
	/Users/matejcik/projekty/prace/trezord-go/core/core.go:178 +0x2c
created by github.com/trezor/trezord-go/core.New
	/Users/matejcik/projekty/prace/trezord-go/core/core.go:160 +0x104

goroutine 36 [syscall]:
github.com/trezor/trezord-go/usb/lowlevel/libusb._Cfunc_libusb_interrupt_transfer(0x150008000, 0x81, 0x140001aef80, 0x40, 0x140001b5168, 0x0)
	_cgo_gotypes.go:1196 +0x3c
github.com/trezor/trezord-go/usb/lowlevel/libusb.Interrupt_Transfer.func1(0x1035be790?, 0x20?, {0x140001aef80, 0x40, 0x10342ffd0?}, 0x3a?, 0x0)
	/Users/matejcik/projekty/prace/trezord-go/usb/lowlevel/libusb/libusb.go:1429 +0x8c
github.com/trezor/trezord-go/usb/lowlevel/libusb.Interrupt_Transfer(0x1035be898?, 0x84?, {0x140001aef80, 0x40, 0x40}, 0x35?)
	/Users/matejcik/projekty/prace/trezord-go/usb/lowlevel/libusb/libusb.go:1429 +0x64
github.com/trezor/trezord-go/usb.(*LibUSBDevice).readWrite(0x140001b9940, {0x140001aef80, 0x40, 0x40}, 0x40?, {0x1033ce318, 0x140001b994c})
	/Users/matejcik/projekty/prace/trezord-go/usb/libusb.go:517 +0xe0
github.com/trezor/trezord-go/usb.(*LibUSBDevice).Read(0x140001b9940, {0x140001aef80, 0x40, 0x40})
	/Users/matejcik/projekty/prace/trezord-go/usb/libusb.go:576 +0x90
github.com/trezor/trezord-go/wire.ReadFrom({0x12a7b6f18, 0x140001b9940}, 0x140000a6100)
	/Users/matejcik/projekty/prace/trezord-go/wire/v1.go:81 +0x68
github.com/trezor/trezord-go/core.(*Core).readDev(0x140000b4b60, {0x12a7b6f18, 0x140001b9940})
	/Users/matejcik/projekty/prace/trezord-go/core/core.go:620 +0x54
github.com/trezor/trezord-go/core.(*Core).readWriteDev(0x140000b4b60, {0x0?, 0x13?, 0x103045d14?}, 0x1400018e4b0, 0x0)
	/Users/matejcik/projekty/prace/trezord-go/core/core.go:655 +0x2ac
github.com/trezor/trezord-go/core.(*Core).Call(0x140000b4b60, {0x0, 0x0, 0x0}, {0x1400002d7ab, 0x1}, 0x0, 0x0, {0x1033cf460?, 0x140004aaba0})
	/Users/matejcik/projekty/prace/trezord-go/core/core.go:600 +0x400
github.com/trezor/trezord-go/server/api.(*api).call(0x14000090c60, {0x1033cf118, 0x140000c42d0}, 0x14000108900, 0x0, 0x7c?)
	/Users/matejcik/projekty/prace/trezord-go/server/api/api.go:215 +0x170
github.com/trezor/trezord-go/server/api.(*api).Read(0x14000080001?, {0x1033cf118?, 0x140000c42d0?}, 0x0?)
	/Users/matejcik/projekty/prace/trezord-go/server/api/api.go:180 +0x30
net/http.HandlerFunc.ServeHTTP(0x10339d600?, {0x1033cf118?, 0x140000c42d0?}, 0x1b?)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/http/server.go:2084 +0x3c
github.com/trezor/trezord-go/server/api.(*cors).ServeHTTP(0x140000a8228, {0x1033cf118, 0x140000c42d0}, 0x14000108900)
	/Users/matejcik/projekty/prace/trezord-go/server/api/cors.go:69 +0x26c
github.com/gorilla/mux.(*Router).ServeHTTP(0x140000f0000, {0x1033cf118, 0x140000c42d0}, 0x14000108700)
	/Users/matejcik/go/pkg/mod/github.com/gorilla/[email protected]/mux.go:210 +0x1a0
github.com/gorilla/handlers.loggingHandler.ServeHTTP({{0x1033cc788, 0x140000a80a8}, {0x1033cc608, 0x140000f0000}, 0x1033ca4b8}, {0x1033ceba8, 0x140000ee2a0}, 0x14000108700)
	/Users/matejcik/go/pkg/mod/github.com/gorilla/[email protected]/logging.go:47 +0xa0
github.com/trezor/trezord-go/server.(*Server).logRequest.func1({0x1033ceba8, 0x140000ee2a0}, 0x14000108700)
	/Users/matejcik/projekty/prace/trezord-go/server/http.go:80 +0x138
net/http.HandlerFunc.ServeHTTP(0x0?, {0x1033ceba8?, 0x140000ee2a0?}, 0x102fa23ac?)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/http/server.go:2084 +0x3c
net/http.serverHandler.ServeHTTP({0x140004aaa20?}, {0x1033ceba8, 0x140000ee2a0}, 0x14000108700)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/http/server.go:2916 +0x3fc
net/http.(*conn).serve(0x140004c0140, {0x1033cf460, 0x140004aa930})
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/http/server.go:1966 +0x56c
created by net/http.(*Server).Serve
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/http/server.go:3071 +0x450

goroutine 71 [IO wait]:
internal/poll.runtime_pollWait(0x12a5ef7a8, 0x72)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/runtime/netpoll.go:302 +0xa4
internal/poll.(*pollDesc).wait(0x140000a6480?, 0x140004aaa31?, 0x0)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/internal/poll/fd_poll_runtime.go:83 +0x2c
internal/poll.(*pollDesc).waitRead(...)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/internal/poll/fd_poll_runtime.go:88
internal/poll.(*FD).Read(0x140000a6480, {0x140004aaa31, 0x1, 0x1})
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/internal/poll/fd_unix.go:167 +0x1e4
net.(*netFD).Read(0x140000a6480, {0x140004aaa31?, 0x140000e7f48?, 0x10319ebdc?})
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/fd_posix.go:55 +0x2c
net.(*conn).Read(0x1400009c238, {0x140004aaa31?, 0x140000c4230?, 0x0?})
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/net.go:183 +0x38
net/http.(*connReader).backgroundRead(0x140004aaa20)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/http/server.go:672 +0x48
created by net/http.(*connReader).startBackgroundRead
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/http/server.go:668 +0xd0

goroutine 39 [IO wait]:
internal/poll.runtime_pollWait(0x12a5ef6b8, 0x72)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/runtime/netpoll.go:302 +0xa4
internal/poll.(*pollDesc).wait(0x140000a6280?, 0x140004aaca1?, 0x0)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/internal/poll/fd_poll_runtime.go:83 +0x2c
internal/poll.(*pollDesc).waitRead(...)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/internal/poll/fd_poll_runtime.go:88
internal/poll.(*FD).Read(0x140000a6280, {0x140004aaca1, 0x1, 0x1})
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/internal/poll/fd_unix.go:167 +0x1e4
net.(*netFD).Read(0x140000a6280, {0x140004aaca1?, 0x0?, 0x102fc69f4?})
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/fd_posix.go:55 +0x2c
net.(*conn).Read(0x1400009c050, {0x140004aaca1?, 0x1033cf460?, 0x100010000?})
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/net.go:183 +0x38
net/http.(*connReader).backgroundRead(0x140004aac90)
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/http/server.go:672 +0x48
created by net/http.(*connReader).startBackgroundRead
	/opt/homebrew/Cellar/go/1.18.2/libexec/src/net/http/server.go:668 +0xd0

goroutine 72 [select]:
github.com/trezor/trezord-go/core.(*Core).Call.func4()
	/Users/matejcik/projekty/prace/trezord-go/core/core.go:586 +0x8c
created by github.com/trezor/trezord-go/core.(*Core).Call
	/Users/matejcik/projekty/prace/trezord-go/core/core.go:585 +0x3cc

r0      0x0
r1      0x0
r2      0x0
r3      0x0
r4      0x0
r5      0x140000830d0
r6      0x10363ac56
r7      0x1
r8      0x7e8c83cf21b044d2
r9      0x7e8c83ce4d4b74d2
r10     0xcccccccccccccccd
r11     0xa
r12     0x0
r13     0x34
r14     0x343434206f672e62
r15     0x4c2a282e62737520
r16     0x148
r17     0x21e54f640
r18     0x0
r19     0x6
r20     0x16cfb3000
r21     0x2803
r22     0x16cfb30e0
r23     0x1033290a2
r24     0x21a646000
r25     0x1c20
r26     0x140001c9070
r27     0x860
r28     0x14000002d00
r29     0x16cfb2e00
lr      0x1c46e1ee0
sp      0x16cfb2de0
pc      0x1c46acdb8
fault   0x1c46acdb8
@matejcik matejcik changed the title Bridge crash when two callers are releasing over one another Bridge crash if session is released while reading from USB May 26, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@matejcik