search

trezor / trezord-go

:smiling_imp: Trezor Communication Daemon (written in Go)
GNU Lesser General Public License v3.0
245 stars 148 forks source link

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

Open matejcik opened 2 years ago

matejcik commented 2 years ago

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

script ```python 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?) :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/mux@v1.8.0/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/handlers@v1.5.1/logging.go:47 +0xa0 fp=0x140001c9950 sp=0x140001c9700 pc=0x10325d180 github.com/gorilla/handlers.(*loggingHandler).ServeHTTP(0x1032819c0?, {0x1033ceba8?, 0x140001180e0?}, 0x10?) :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/lumberjack.v2@v2.0.0/lumberjack.go:379 +0x48 created by gopkg.in/natefinch/lumberjack%2ev2.(*Logger).mill.func1 /Users/matejcik/go/pkg/mod/gopkg.in/natefinch/lumberjack.v2@v2.0.0/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/mux@v1.8.0/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/handlers@v1.5.1/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 ```