Error: Loading takes too long

sentry-io[bot] commented 3 years ago

Error: Loading takes too long

This error pops out every time something get stuck and user would wait forever. It basically acts as a timeout (30s), if suite won't load til the limit, there is something wrong and we throw this error.

There will be multiple reasons why it may happen (take with a grain of salt, I am going by memory):

[x] botched DB migration/upgrade (or lack of db migration) https://github.com/trezor/trezor-suite/pull/3462
[x] multiple instances of electron app running https://github.com/trezor/trezor-suite/pull/3467
[ ] I think we used to have some problems with TOR that would also lead to timeout
[ ] Trouble communicating with bridge/connect (suite is basically waiting for right set of fields and it will wait till this condition is satisfied)
- happened here https://sentry.io/organizations/satoshilabs/issues/2278799388/
- bridge responds with error 400, connect didn't send TRANSPORT.START or TRANSPORT.ERROR events
- suite timeouts after 90s on loading takes too long, because we are waiting for transport info object to be set, but since these events above are never dispatched we'll get stuck at initial loading of suite.

bridge logs: log (1).gz

[106.954810 : 16:37:27] [00000e92] libusb: debug [libusb_get_device_list] 
[106.954774 : 16:37:27] [usb/libusb.go 121 usb.(*LibUSB).Enumerate] low level enumerating
[106.954746 : 16:37:27] [core/core.go 255 core.(*Core).Enumerate] bus
[106.954709 : 16:37:27] [core/core.go 253 core.(*Core).Enumerate] callsInProgress 0
[106.954673 : 16:37:27] [core/core.go 240 core.(*Core).Enumerate] locking callMutex
[106.954643 : 16:37:27] 127.0.0.1 - - [17/Mar/2021:16:37:27 +0100] "POST /acquire/1/null HTTP/1.1" 400 32
[106.954553 : 16:37:27] [server/api/api.go 270 server/api.(*api).respondError] Returning error: LIBUSB_ERROR_ACCESS
[106.954516 : 16:37:27] [core/core.go 493 core.(*Core).tryConnect] tryConnect - too many times, exiting
[106.954499 : 16:37:27] [usb/libusb.go 191 usb.(*LibUSB).Connect.func1] freeing device list done
[106.954480 : 16:37:27] [usb/libusb.go 189 usb.(*LibUSB).Connect.func1] freeing device list
[106.954458 : 16:37:27] [00000e7b] libusb: debug [libusb_open] open 1.4 returns -3
[106.954445 : 16:37:27] [00000e7b] libusb: error [_get_usbfs_fd] libusb requires write access to USB device nodes.
[106.954432 : 16:37:27] [00000e7b] libusb: error [_get_usbfs_fd] libusb couldn't open USB device /dev/bus/usb/001/004: Permission denied
[106.954386 : 16:37:27] [00000e7b] libusb: debug [libusb_open] open 1.4
[106.954372 : 16:37:27] [usb/libusb.go 292 usb.(*LibUSB).connect] low level
[106.954341 : 16:37:27] [00000e7b] libusb: debug [libusb_get_config_descriptor] index 0
[106.954328 : 16:37:27] [usb/libusb.go 286 usb.(*LibUSB).connect] detect old BL

old wallet shows libusb error

We most likely can't really fix the root cause right away, but introducing new errors that would clearly explain what happened would help a lot.

slowbackspace commented 3 years ago

updated original description with more detailed breakdown, @bosomt managed to trigger "Loading takes too long" due to problems with connect-bridge communication which led to timeout (on nixos, mint and win worked fine). Please take a look at last item in the list in original description for more info.

cc @szymonlesisz @tsusanka you will probably be able to tell what's happening here. I think part of the issue is related to bridge, main question is why it didn't respond? Could be some problem on OS-level though. Second part is connect, why it didn't emit TRANSPORT.ERROR if there is a problem with bridge communication?

tsusanka commented 3 years ago

Uf. If this would be 2.0.31 bridge a not 2.0.27 as it is (see log) I would dig way deeper, but since it happened on 27 and:

27 is stable for quite some time already
it happened only on NixOS (correct?)
we do not have a clear reproducible steps (do we?)

I am a bit inclined into dealing with this later when we are able to reproduce it or we are sure it concerns more people.

bosomt commented 3 years ago

@tsusanka

it happened in latest version of Fedora. And yes it was built in 2.0.27 Trezor Bridge. But I removed 2.0.31 version before with command that ignored dependencies /RPM packaging was causing some issues/

slowbackspace commented 3 years ago

Uf. If this would be 2.0.31 bridge a not 2.0.27 as it is (see log) I would dig way deeper, but since it happened on 27 and:

27 is stable for quite some time already

it happened only on NixOS (correct?)

we do not have a clear reproducible steps (do we?)

I am a bit inclined into dealing with this later when we are able to reproduce it or we are sure it concerns more people.

yeah I agree, it really looks like it was some OS/system setup failure, as it worked in other linux distros just fine. In the end we just need to make sure connect handles these bridge errors correctly (mytrezor properly detects libusb error, connect does not). Bridge issue itself could be solved later if needed, I just wanted to be sure we didn't miss anything so I wrote it down too.

tsusanka commented 3 years ago

In the end we just need to make sure connect handles these bridge errors correctly (mytrezor properly detects libusb error, connect does not).

Great, I totally agree.

slowbackspace commented 3 years ago

@alex-jerechinsky I'll assign this to you till you figure out if @szymonlesisz should take this someone else, the problem lies probably somewhere in trezor-connect.

matejkriz commented 3 years ago

It looks like the first checkbox (https://github.com/trezor/trezor-suite/pull/3462) is not resolved properly: https://sentry.io/organizations/satoshilabs/issues/1730980450/events/dce5c836bece43c98d20ef173fa6f194

Some of the events has Migrating database from version 23 to 24 in breadcrumbs and then throw error Loading takes too long.

tomasklim commented 2 years ago

Related to #4657

tomasklim commented 2 years ago

Related also to this #4267

matejkriz commented 2 years ago

waiting for some inputs on https://github.com/trezor/trezor-suite/issues/4657

matejkriz commented 11 months ago

One more case https://satoshilabs.slack.com/archives/CKZHV2G13/p1702920330989569

trezor / trezor-suite

Error: Loading takes too long #3431