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

TOR takes long time to recover #10915

Open
onvej-sl opened this issue Jun 20, 2023 · 7 comments
Open

TOR takes long time to recover #10915

onvej-sl opened this issue Jun 20, 2023 · 7 comments

Comments

@onvej-sl
Copy link
Contributor

onvej-sl commented Jun 20, 2023 •
edited by kiminuo

@szymonlesisz found out and tested that your wallet is affected by trezor/trezor-suite#8661 (comment) which he had discovered.

In short, when your internet connection is temporarily off but the network you are connected to is working, it takes TOR 30 minutes to recover. The solution is to detect when this happens and remove the affected circuits.

Although this is not directly related to coinjoin, if it occurs during the critical phase, it disrupts the round.
@turbolay
Copy link
Collaborator

FTR I also experienced this behavior, even if not sure about the exact disruption duration. An easy way to test is switch on/off internet connection

@szymonlesisz
Copy link

szymonlesisz commented Jun 21, 2023 •
edited

Thanks @onvej-sl for opening this issue for me :)

To be precise, only opened/recycled circuits are affected like for example identity used for fetching /status or synchronization.
Circuits created dynamically in coinjoin session are working fine, although they also might be recycled and become "useless" (input-registration + ready-to-sign or /connection-confirmation)

offline duration doesn't even matter, if you have two hotspots available (home wifi + mobile hotspot) it's enough just to switch between them while loading the wallet.

i believe it can happen even without user interaction or knowledge.
For example in my case router keeps randomly switching outgoing gateways.

@kiminuo
Copy link
Collaborator

kiminuo commented Jul 12, 2023

I've been working on this. So far I have only a few findings but I still don't understand the issue fully.

@kiminuo
Copy link
Collaborator

kiminuo commented Jul 14, 2023

I have this test branch: https://github.com/kiminuo/WalletWasabi/tree/feature/2023-07-10-Tor-n-net-down and my test scenario is as follows:

Initial setup:

  • Set up a mobile hotspot on your Android device and connect your machine to this wifi network.

Test scenario:

  1. Kill Tor (or set up that Tor is to be shut down after WW terminates in WW settings)
  2. Delete your WalletWasabi\Client\BitcoinStore\TestNet\IndexStore\IndexStorage.sqlite
  3. Run Wasabi wallet
    • I use the following powershell command: dotnet build && dotnet run --framework net7.0 -- --LogLevel=trace | select-string "FilterProcessor.ProcessAsync","INFO","DEBUG","XXX:"
  4. Log in to your wallet
  5. Now filters are being downloaded
  6. Turn off mobile data on your android device so that effectively your laptop/desktop machine is not connected to the Internet
  7. Wait a minute or so.
  8. Turn on mobile data on your android device again
  9. Grep logs using select-String -Raw -Path .\Logs.txt "FilterProcessor.ProcessAsync","INFO","DEBUG","XXX:" -NoEmphasis >Logs.filtered.txt (fgrep -e "FilterProcessor.ProcessAsync" -e "INFO" -e "DEBUG" -e "XXX:" >Logs.filtered.txt on linux/macOS)

Now this gives me on Windows:

2023-07-14 13:55:13.017 [1] DEBUG	WasabiAppBuilder..ctor (33)	Wasabi was started with these argument(s): --LogLevel=trace.
2023-07-14 13:55:13.044 [1] DEBUG	TerminateService.Activate (44)	TerminateService subscribed to SystemEvents
2023-07-14 13:55:13.058 [1] INFO	WasabiAppBuilder.BeforeStarting (81)	Wasabi GUI started (0bc6c269-bfe1-4893-b07d-cc6f18e60a88).
2023-07-14 13:55:13.136 [1] INFO	FileSystemBlockRepository.Dispose (23)	.ctor finished in 11 milliseconds.
2023-07-14 13:55:13.380 [1] INFO	WalletManager.Dispose (35)	.ctor finished in 229 milliseconds.
2023-07-14 13:55:13.419 [1] INFO	Program.RunAsGuiAsync (170)	Wasabi GUI started.
2023-07-14 13:55:14.337 [1] INFO	Program.RunAsGuiAsync (190)	Renderer: ANGLE (Intel(R) UHD Graphics Direct3D11 vs_5_0 ps_5_0)
2023-07-14 13:55:15.675 [1] DEBUG	IndexStore.InitializeFiltersNoLockAsync (203)	Loaded 1 lines from the mature index file.
2023-07-14 13:55:15.677 [1] DEBUG	IndexStore.Dispose (186)	Block filters loading finished in 6 milliseconds.
2023-07-14 13:55:15.682 [1] INFO	IndexStore.Dispose (83)	InitializeAsync finished in 11 milliseconds.
2023-07-14 13:55:15.713 [9] INFO	TransactionStore.Dispose (43)	MempoolStore.InitializeAsync finished in 28 milliseconds.
2023-07-14 13:55:15.720 [9] INFO	TransactionStore.Dispose (43)	ConfirmedStore.InitializeAsync finished in 24 milliseconds.
2023-07-14 13:55:15.728 [9] INFO	AllTransactionStore.Dispose (39)	InitializeAsync finished in 44 milliseconds.
2023-07-14 13:55:15.729 [9] INFO	BitcoinStore.Dispose (47)	InitializeAsync finished in 60 milliseconds.
2023-07-14 13:55:15.732 [7] DEBUG	TorProcessManager.StartAsync (79)	Attempt #1 to start Tor.
2023-07-14 13:55:15.732 [20] INFO	TorProcessManager.RestartingLoopAsync (126)	Tor is already running on 127.0.0.1:37150
2023-07-14 13:55:15.765 [20] TRACE	TorControlClient.SendCommandNoLockAsync (191)	Client: About to send command: 'GETINFO process/pid'
2023-07-14 13:55:15.769 [20] INFO	TorProcessManager.RestartingLoopAsync (161)	Tor is running.
2023-07-14 13:55:15.771 [20] INFO	Global.StartTorProcessManagerAsync (259)	TorProcessManager is initialized.
2023-07-14 13:55:15.773 [20] INFO	Global.Dispose (255)	TorProcessManager.Start finished in 68 milliseconds.
2023-07-14 13:55:15.859 [20] INFO	P2pNetwork..ctor (55)	Loaded AddressManager from `C:\Users\kimi\AppData\Roaming\WalletWasabi\Client\BitcoinP2pNetwork\AddressManagerTestNet.dat`.
2023-07-14 13:55:15.913 [9] INFO	HostedServices.StartAllAsync (61)	Started Software Update Checker.
2023-07-14 13:55:15.917 [20] INFO	TorMonitor.MonitorEventsAsync (109)	Starting Tor bootstrap monitor…
2023-07-14 13:55:15.931 [9] INFO	HostedServices.StartAllAsync (61)	Started TorMonitor.
2023-07-14 13:55:15.940 [21] INFO	HostedServices.StartAllAsync (61)	Started Tor Network Checker.
2023-07-14 13:55:15.943 [21] INFO	HostedServices.StartAllAsync (61)	Started Bitcoin P2P Network.
2023-07-14 13:55:15.946 [21] INFO	HostedServices.StartAllAsync (61)	Started Blockstream.info Fee Provider.
2023-07-14 13:55:15.949 [9] INFO	HostedServices.StartAllAsync (61)	Started Third Party Fee Provider.
2023-07-14 13:55:15.953 [9] INFO	HostedServices.StartAllAsync (61)	Started Hybrid Fee Provider.
2023-07-14 13:55:15.963 [23] DEBUG	BestEffortEndpointConnector.AllowOnlyTorEndpoints (106)	Connections: 0, Currently allow only onions: False.
2023-07-14 13:55:16.008 [9] INFO	HostedServices.StartAllAsync (61)	Started Round info updater.
2023-07-14 13:55:16.016 [9] INFO	HostedServices.StartAllAsync (61)	Started CoinJoin Manager.
2023-07-14 13:55:16.022 [9] INFO	HostedServices.StartAllAsync (61)	Started Sleep Inhibitor.
2023-07-14 13:55:16.024 [9] INFO	Global.InitializeNoWalletAsync (206)	Start synchronizing filters...
2023-07-14 13:55:16.031 [7] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 13:55:16.504 [9] INFO	TorMonitor.MonitorEventsAsync (150)	Tor circuit was established.
2023-07-14 13:55:18.878 [7] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2846 ms.
2023-07-14 13:55:19.047 [7] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 828576 to 838575.
2023-07-14 13:55:19.062 [7] INFO	HybridFeeProvider.OnAllFeeEstimateArrived (132)	Accurate fee rates are acquired from WasabiSynchronizer ranging from target 2 blocks at 6 sat/vByte to target 3 blocks at 2 sat/vByte.
2023-07-14 13:55:19.062 [7] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 13:55:20.966 [20] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 1903 ms.
2023-07-14 13:55:21.089 [20] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 838576 to 848575.
2023-07-14 13:55:21.091 [20] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 13:55:22.967 [19] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 1875 ms.
2023-07-14 13:55:23.078 [19] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 848576 to 858575.
2023-07-14 13:55:23.079 [19] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 13:55:24.874 [19] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 1795 ms.
2023-07-14 13:55:24.997 [19] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 858576 to 868575.
2023-07-14 13:55:24.999 [19] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 13:55:26.837 [19] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 1837 ms.
2023-07-14 13:55:26.967 [19] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 868576 to 878575.
2023-07-14 13:55:26.968 [19] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 13:55:29.236 [19] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2268 ms.
2023-07-14 13:55:29.382 [19] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 878576 to 888575.
2023-07-14 13:55:29.384 [19] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 13:55:31.875 [9] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2491 ms.
2023-07-14 13:55:31.984 [9] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 888576 to 898575.
2023-07-14 13:55:31.986 [9] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 13:55:34.284 [9] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2298 ms.
2023-07-14 13:55:34.378 [9] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 898576 to 908575.
2023-07-14 13:55:34.378 [9] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 13:55:36.559 [20] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2180 ms.
2023-07-14 13:55:36.679 [20] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 908576 to 918575.
2023-07-14 13:55:36.680 [20] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 13:56:00.791 [20] ERROR	WasabiSynchronizer.Start (155)	XXX: [TorException] Took 24110 ms.
2023-07-14 13:56:03.798 [20] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 13:56:35.495 [9] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 31697 ms.
2023-07-14 13:56:35.632 [9] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 918576 to 928575.
2023-07-14 13:56:35.633 [9] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 13:56:42.743 [44] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 7110 ms.
2023-07-14 13:56:42.845 [44] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 928576 to 938575.
2023-07-14 13:56:42.846 [44] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 13:56:51.935 [20] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 9089 ms.
2023-07-14 13:56:52.032 [20] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 938576 to 948575.
2023-07-14 13:56:52.033 [20] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 13:56:57.396 [20] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 5363 ms.
2023-07-14 13:56:57.516 [20] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 948576 to 958575.
2023-07-14 13:56:57.517 [20] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request

macOS

2023-07-14 14:26:50.057 [1] DEBUG	WasabiAppBuilder..ctor (33)	Wasabi was started with these argument(s): none.
2023-07-14 14:26:50.084 [1] INFO	WasabiAppBuilder.BeforeStarting (81)	Wasabi GUI started (83a77798-0201-441a-9f3f-9c9bf1287c69).
2023-07-14 14:26:50.490 [1] INFO	FileSystemBlockRepository.Dispose (23)	.ctor finished in 5 milliseconds.
2023-07-14 14:26:50.710 [1] INFO	WalletManager.Dispose (35)	.ctor finished in 172 milliseconds.
2023-07-14 14:26:50.749 [1] INFO	Program.RunAsGuiAsync (170)	Wasabi GUI started.
2023-07-14 14:26:51.937 [1] INFO	Program.RunAsGuiAsync (190)	Renderer: Apple M1
2023-07-14 14:26:51.970 [1] INFO	Program.RunAsGuiAsync (194)	Renderer: X1
2023-07-14 14:26:52.969 [1] DEBUG	IndexStore.InitializeFiltersNoLockAsync (203)	Loaded 1 lines from the mature index file.
2023-07-14 14:26:52.969 [1] DEBUG	IndexStore.Dispose (186)	Block filters loading finished in 3 milliseconds.
2023-07-14 14:26:52.969 [1] INFO	IndexStore.Dispose (83)	InitializeAsync finished in 4 milliseconds.
2023-07-14 14:26:52.974 [1] INFO	TransactionStore.Dispose (43)	MempoolStore.InitializeAsync finished in 3 milliseconds.
2023-07-14 14:26:53.333 [6] DEBUG	TorProcessManager.StartAsync (79)	Attempt #1 to start Tor.
2023-07-14 14:26:53.336 [20] INFO	TransactionStore.Dispose (43)	ConfirmedStore.InitializeAsync finished in 361 milliseconds.
2023-07-14 14:26:53.338 [20] INFO	AllTransactionStore.Dispose (39)	InitializeAsync finished in 367 milliseconds.
2023-07-14 14:26:53.338 [20] INFO	BitcoinStore.Dispose (47)	InitializeAsync finished in 373 milliseconds.
2023-07-14 14:26:53.352 [8] DEBUG	TorProcessManager.StartProcess (333)	Environment variable 'LD_LIBRARY_PATH' set to: '/Users/box/work/WalletWasabi/WalletWasabi/WalletWasabi.Fluent.Desktop/bin/Release/net7.0/Microservices/Binaries/osx64/Tor'.
2023-07-14 14:26:53.352 [8] INFO	TorProcessManager.StartProcess (336)	Starting Tor process…
2023-07-14 14:26:54.476 [8] INFO	TorProcessManager.RestartingLoopAsync (161)	Tor is running.
2023-07-14 14:26:54.477 [8] INFO	Global.StartTorProcessManagerAsync (259)	TorProcessManager is initialized.
2023-07-14 14:26:54.477 [8] INFO	Global.Dispose (255)	TorProcessManager.Start finished in 1.26 seconds.
2023-07-14 14:26:54.521 [8] INFO	P2pNetwork..ctor (55)	Loaded AddressManager from `/Users/box/.walletwasabi/client/BitcoinP2pNetwork/AddressManagerMain.dat`.
2023-07-14 14:26:54.555 [20] INFO	HostedServices.StartAllAsync (61)	Started Software Update Checker.
2023-07-14 14:26:54.557 [8] INFO	TorMonitor.MonitorEventsAsync (109)	Starting Tor bootstrap monitor…
2023-07-14 14:26:54.587 [9] INFO	HostedServices.StartAllAsync (61)	Started TorMonitor.
2023-07-14 14:26:54.592 [6] INFO	HostedServices.StartAllAsync (61)	Started Tor Network Checker.
2023-07-14 14:26:54.593 [6] INFO	HostedServices.StartAllAsync (61)	Started Bitcoin P2P Network.
2023-07-14 14:26:54.595 [9] INFO	HostedServices.StartAllAsync (61)	Started Blockstream.info Fee Provider.
2023-07-14 14:26:54.596 [6] INFO	HostedServices.StartAllAsync (61)	Started Third Party Fee Provider.
2023-07-14 14:26:54.596 [6] INFO	HostedServices.StartAllAsync (61)	Started Hybrid Fee Provider.
2023-07-14 14:26:54.602 [21] DEBUG	BestEffortEndpointConnector.AllowOnlyTorEndpoints (106)	Connections: 0, Currently allow only onions: False.
2023-07-14 14:26:54.608 [9] INFO	TorMonitor.MonitorEventsAsync (165)	XXX: Tor network liveness event: NetworkLivenessEvent { IsUp = True, IsDown = False, Status = UP }.
2023-07-14 14:26:54.613 [6] INFO	HostedServices.StartAllAsync (61)	Started Round info updater.
2023-07-14 14:26:54.616 [9] INFO	TorMonitor.MonitorEventsAsync (128)	Bootstrap progress: 14/100 (tag=handshake: Handshaking with a relay)
2023-07-14 14:26:54.617 [6] INFO	HostedServices.StartAllAsync (61)	Started CoinJoin Manager.
2023-07-14 14:26:54.623 [19] INFO	HostedServices.StartAllAsync (61)	Started Sleep Inhibitor.
2023-07-14 14:26:54.631 [19] INFO	Global.InitializeNoWalletAsync (206)	Start synchronizing filters...
2023-07-14 14:26:54.636 [17] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:26:54.763 [20] TRACE	PipeReaderLineReaderExtension.ReadLineAsync (61)	Read message: '650 STATUS_CLIENT NOTICE BOOTSTRAP PROGRESS=75 TAG=enough_dirinfo SUMMARY="Loaded enough directory info to build circuits"'
2023-07-14 14:26:54.763 [18] INFO	TorMonitor.MonitorEventsAsync (128)	Bootstrap progress: 15/100 (tag=handshake_done: Handshake with a relay done)
2023-07-14 14:26:54.763 [18] INFO	TorMonitor.MonitorEventsAsync (128)	Bootstrap progress: 75/100 (tag=enough_dirinfo: Loaded enough directory info to build)
2023-07-14 14:26:54.764 [18] INFO	TorMonitor.MonitorEventsAsync (128)	Bootstrap progress: 90/100 (tag=ap_handshake_done: Handshake finished with a relay to build circuits)
2023-07-14 14:26:54.764 [18] INFO	TorMonitor.MonitorEventsAsync (128)	Bootstrap progress: 95/100 (tag=circuit_create: Establishing a[n internal] Tor circuit)
2023-07-14 14:26:54.898 [20] INFO	TorMonitor.MonitorEventsAsync (150)	Tor circuit was established.
2023-07-14 14:26:55.169 [18] INFO	TorMonitor.MonitorEventsAsync (128)	Bootstrap progress: 100/100 (tag=done: Done)
2023-07-14 14:27:09.802 [17] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 15166 ms.
2023-07-14 14:27:10.494 [17] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 481825 to 482824.
2023-07-14 14:27:10.542 [17] INFO	HybridFeeProvider.OnAllFeeEstimateArrived (132)	Accurate fee rates are acquired from WasabiSynchronizer ranging from target 2 blocks at 10 sat/vByte to target 432 blocks at 4 sat/vByte.
2023-07-14 14:27:10.543 [17] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:27:12.771 [9] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2227 ms.
2023-07-14 14:27:12.780 [9] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 482825 to 483824.
2023-07-14 14:27:12.780 [9] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:27:14.905 [32] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2124 ms.
2023-07-14 14:27:14.913 [32] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 483825 to 484824.
2023-07-14 14:27:14.913 [32] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:27:17.033 [6] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2120 ms.
2023-07-14 14:27:17.052 [6] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 484825 to 485824.
2023-07-14 14:27:17.052 [6] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:27:19.200 [22] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2148 ms.
2023-07-14 14:27:19.212 [22] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 485825 to 486824.
2023-07-14 14:27:19.213 [22] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:27:21.116 [9] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 1903 ms.
2023-07-14 14:27:21.133 [9] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 486825 to 487824.
2023-07-14 14:27:21.133 [9] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:27:23.544 [9] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2411 ms.
2023-07-14 14:27:23.566 [9] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 487825 to 488824.
2023-07-14 14:27:23.566 [9] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:27:25.533 [9] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 1967 ms.
2023-07-14 14:27:25.545 [9] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 488825 to 489824.
2023-07-14 14:27:25.545 [9] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:27:28.006 [22] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2460 ms.
2023-07-14 14:27:28.019 [22] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 489825 to 490824.
2023-07-14 14:27:28.019 [22] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:27:30.451 [22] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2431 ms.
2023-07-14 14:27:30.484 [22] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 490825 to 491824.
2023-07-14 14:27:30.484 [22] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:27:32.848 [9] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2363 ms.
2023-07-14 14:27:32.862 [9] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 491825 to 492824.
2023-07-14 14:27:32.863 [9] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:27:35.080 [9] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2217 ms.
2023-07-14 14:27:35.152 [9] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 492825 to 493824.
2023-07-14 14:27:35.153 [9] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:27:37.376 [6] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2223 ms.
2023-07-14 14:27:37.393 [6] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 493825 to 494824.
2023-07-14 14:27:37.394 [6] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:27:40.197 [17] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2803 ms.
2023-07-14 14:27:40.207 [17] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 494825 to 495824.
2023-07-14 14:27:40.207 [17] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:27:43.063 [17] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2855 ms.
2023-07-14 14:27:43.086 [17] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 495825 to 496824.
2023-07-14 14:27:43.086 [17] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:27:45.667 [6] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2580 ms.
2023-07-14 14:27:45.678 [6] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 496825 to 497824.
2023-07-14 14:27:45.679 [6] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:27:47.942 [8] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2263 ms.
2023-07-14 14:27:47.962 [8] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 497825 to 498824.
2023-07-14 14:27:47.962 [8] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:27:50.476 [17] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2514 ms.
2023-07-14 14:27:50.489 [17] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 498825 to 499824.
2023-07-14 14:27:50.490 [17] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:27:53.331 [20] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 2841 ms.
2023-07-14 14:27:53.351 [20] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 499825 to 500824.
2023-07-14 14:27:53.351 [20] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:28:54.383 [29] ERROR	WasabiSynchronizer.Start (155)	XXX: [TorException] Took 61033 ms.
2023-07-14 14:28:57.421 [32] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:29:12.476 [27] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 15055 ms.
2023-07-14 14:29:12.562 [27] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 500825 to 501824.
2023-07-14 14:29:12.563 [27] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:29:19.982 [39] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 7419 ms.
2023-07-14 14:29:19.995 [39] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 501825 to 502824.
2023-07-14 14:29:19.995 [39] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:29:24.487 [38] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 4491 ms.
2023-07-14 14:29:24.503 [38] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 502825 to 503824.
2023-07-14 14:29:24.503 [38] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:29:28.490 [39] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 3986 ms.
2023-07-14 14:29:28.503 [39] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 503825 to 504824.
2023-07-14 14:29:28.503 [39] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:29:33.088 [9] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 4585 ms.
2023-07-14 14:29:33.099 [9] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 504825 to 505824.
2023-07-14 14:29:33.099 [9] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:29:48.521 [39] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 15422 ms.
2023-07-14 14:29:48.557 [39] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 505825 to 506824.
2023-07-14 14:29:48.557 [39] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:29:53.711 [38] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 5153 ms.
2023-07-14 14:29:53.733 [38] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 506825 to 507824.
2023-07-14 14:29:53.735 [38] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:30:01.287 [9] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 7552 ms.
2023-07-14 14:30:01.309 [9] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 507825 to 508824.
2023-07-14 14:30:01.309 [9] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:30:10.530 [30] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 9221 ms.
2023-07-14 14:30:10.543 [30] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 508825 to 509824.
2023-07-14 14:30:10.544 [30] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:30:21.322 [38] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 10778 ms.
2023-07-14 14:30:21.340 [38] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 509825 to 510824.
2023-07-14 14:30:21.340 [38] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:30:33.631 [38] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 12291 ms.
2023-07-14 14:30:33.643 [38] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 510825 to 511824.
2023-07-14 14:30:33.643 [38] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:30:43.374 [38] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 9730 ms.
2023-07-14 14:30:43.400 [38] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 511825 to 512824.
2023-07-14 14:30:43.400 [38] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:30:52.827 [30] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 9426 ms.
2023-07-14 14:30:52.869 [30] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 512825 to 513824.
2023-07-14 14:30:52.870 [30] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request
2023-07-14 14:31:02.035 [33] ERROR	WasabiSynchronizer.Start (146)	XXX: [OK] Took 9165 ms.
2023-07-14 14:31:02.045 [33] INFO	FilterProcessor.ProcessAsync (59)	Downloaded filters for blocks from 513825 to 514824.
2023-07-14 14:31:02.045 [33] ERROR	WasabiSynchronizer.Start (140)	XXX: About to send GetSynchronizeAsync request

So my tests lead to recovery. However, @szymonlesisz sent me his logs and I can see that the recovery was not so smooth in his case. It took about 12 minutes. But he tested on linux.

So no conclusion so far but if anyone would be willing to test, it would be very helpful. There is still something I don't understand I guess.

@molnard
Copy link
Collaborator

molnard commented Aug 7, 2023

But he tested on linux.

@kiminuo does it makes sense to set up a Linux virtualbox and test it? If yes then can you do it? If the problems do not occur there we close the issue until no further clue.

@kiminuo
Copy link
Collaborator

kiminuo commented Aug 14, 2023

Yeah, this is something I want to focus on this week.

@kiminuo
Copy link
Collaborator

kiminuo commented Aug 21, 2023

I have set up a linux VM and tried the test scenario mentioned here #10915 (comment) but I can see that WW recovers as well. I have tried that multiple times with various intervals for when the Internet connection was down.

So the question is what is the next step here.

  1. I think it's important to know what version of Tor is used in Trezor. Could @szymonlesisz please comment on this? Personally, I'm rather skeptical that this just upgrading would fix an issue like this but for the sake of complenetess it's good to know.
  2. I can try to add a test in TorTests and try to reproduce the issue there. Seems like a good next step.
  3. We had a chat with David Goulet (Tor dev) regarding this topic in general and the response was in the sense that "Tor in C might contain such bugs". In a sense, everyone hopes that Arti will fix many bugs that are hard to fix in Tor C. Given we are stuck with Tor in C for some time, we still need to fix what we can.
  4. Maybe @szymonlesisz can test TOR takes long time to recover #10915 (comment) on his machine as well so we would have more information.
  5. Maybe @turbolay can test TOR takes long time to recover #10915 (comment) as well given his comment TOR takes long time to recover #10915 (comment).

@kiminuo kiminuo removed their assignment Jun 7, 2024
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
5 participants
@szymonlesisz @molnard @turbolay @onvej-sl @kiminuo