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

20 seconds is not always enough to start Core #4678

Closed
vi opened this issue Jul 15, 2019 · 8 comments · Fixed by #4686
Closed

20 seconds is not always enough to start Core #4678

vi opened this issue Jul 15, 2019 · 8 comments · Fixed by #4686
Milestone
7.6.0 November: S...

Comments

@vi
Copy link
Contributor

vi commented Jul 15, 2019

Tribler version/branch+revision:

7.3.0-beta6 + patches

Operating system and version:

Linux Debian Buster running on slow-ish laptop without SSD storage.

Steps to reproduce the behavior:
  1. Reboot system or clear filesystem caches on slow computer.
  2. Start ./tribler.sh
  3. Wait minute-two of thrashing of various Python modules though filesystem
Expected behavior:

Eventually it starts like usual

Actual behavior:

GUI gets tired of waiting for core and bails out. Subsequent attempt to start Tribler works, as caches are hot.

Relevant log file output:

Here is startup log. The log looks like usual, except of the exception.

$ ./tribler.sh 
ERROR:root:Fault Handler module not found.
INFO    1563223077.62        single_application:28   (root)  __init__()
QStandardPaths: XDG_RUNTIME_DIR not set, defaulting to '/tmp/runtime-tribler'
INFO    1563223078.44        single_application:54   (root)    self._outSocket.error() = '2'
INFO    1563223078.44        single_application:64   (root)  __init__(): returning
QFont::setPointSize: Point size <= 0 (-1), must be greater than 0
QFont::setPointSize: Point size <= 0 (-1), must be greater than 0
[000056384cd70200] vlcpulse audio output error: PulseAudio server connection failure: Connection refused
[000056384cd6fa30] vlcpulse audio output error: PulseAudio server connection failure: Connection refused
INFO    1563223124.31     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223124.60     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223125.12     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223125.12     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223125.65     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223125.65     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223126.17     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223126.17     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223126.67     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223126.67     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223127.17     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223127.17     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223127.67     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223127.68     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223128.17     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223128.18     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223128.67     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223128.67     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223129.17     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223129.17     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223129.67     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223129.67     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223130.17     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223130.18     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223130.67     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223130.68     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223131.17     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223131.17     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223131.67     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223131.67     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223132.17     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223132.17     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223132.67     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223132.67     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223133.17     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223133.18     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223133.67     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223133.67     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223134.17     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223134.17     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223134.67     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223134.67     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223135.17     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223135.17     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223135.67     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223135.67     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223136.17     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223136.17     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223136.67     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223136.67     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223137.17     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223137.17     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223137.67     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223137.67     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223138.17     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223138.17     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223138.67     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223138.68     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223139.17     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223139.17     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223139.67     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223139.68     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223140.17     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223140.17     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223140.67     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223140.68     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223141.17     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223141.17     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223141.67     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223141.67     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223142.17     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223142.17     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223142.67     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223142.67     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223143.17     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223143.17     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223143.67     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223143.68     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223144.17     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223144.17     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
INFO    1563223144.67     event_request_manager:132  (TriblerGUI)  Will connect to events endpoint
INFO    1563223144.67     event_request_manager:79   (TriblerGUI)  Got Tribler core error: 1
ERROR   1563223144.78            tribler_window:74   (root)  Traceback (most recent call last):
  File "/home/tribler/tribler/TriblerGUI/event_request_manager.py", line 136, in <lambda>
    self.reply.error.connect(lambda error: self.on_error(error, reschedule_on_err=reschedule_on_err))
  File "/home/tribler/tribler/TriblerGUI/event_request_manager.py", line 81, in on_error
    raise RuntimeError("Could not connect with the Tribler Core within 20 seconds")
RuntimeError: Could not connect with the Tribler Core within 20 seconds

INFO    1563223151.07                   Session:74   (Session)  Session is using state directory: /home/tribler/.Tribler
INFO    1563223151.20              rest_manager:55   (RESTManager)  Starting REST API on port 8085
INFO    1563223152.24           tracker_manager:40   (TrackerManager)  No tracker blacklist file found at /home/tribler/.Tribler/tracker_blacklist.txt.
ERROR   1563223152.31            LaunchManyCore:276  (TriblerLaunchMany)  bitcoinlib library cannot be loaded: No module named bitcoinlib.wallets


INFO    1563223159.82                 community:120  (DHTDiscoveryCommunity)  DHT community initialized (peer mid 9b6c9511a3748019a009b2fc16247e0a4568f434)
INFO    1563223160.52          order_repository:122  (DatabaseOrderRepository)  Memory order repository used
INFO    1563223160.52    transaction_repository:112  (DatabaseTransactionRepository)  Database transaction repository used
INFO    1563223160.52             order_manager:17   (OrderManager)  Market order manager initialized
INFO    1563223160.52       transaction_manager:19   (TransactionManager)  Transaction manager initialized
INFO    1563223160.52                 community:408  (MarketCommunity)  Market community initialized with mid 9b6c9511a3748019a009b2fc16247e0a4568f434
INFO    1563223160.96       CreditMiningManager:77   (CreditMiningManager)  Starting CreditMiningManager

INFO    1563223172.38                connection:84   (Socks5Connection)  Client has sent METHOD REQUEST
INFO    1563223172.38                connection:84   (Socks5Connection)  Client has sent METHOD REQUEST
INFO    1563223177.17           torrent_checker:150  (TorrentChecker)  Selected 1 new torrents to check on tracker: http://8.ehtracker.org/520906/announce
INFO    1563223177.19                connection:168  (Socks5Connection)  Accepting UDP ASSOCIATE request to 127.0.0.1:53815
INFO    1563223177.19                connection:168  (Socks5Connection)  Accepting UDP ASSOCIATE request to 127.0.0.1:34728
INFO    1563223181.39       CreditMiningManager:342  (CreditMiningManager)  Downloading: 0, Uploading: 0, Stopped: 0
INFO    1563223181.39       CreditMiningManager:344  (CreditMiningManager)  0 active download(s), 0.000 MB uploaded, 0.000 MB downloaded
INFO    1563223181.40                connection:84   (Socks5Connection)  Client has sent METHOD REQUEST
INFO    1563223182.01                connection:198  (Socks5Connection)  Closing session, reason unspecified
WARNING 1563223182.01            udp_connection:41   (SocksUDPConnection)  Received an IPV6 udp datagram, dropping it (Not implemented yet)
WARNING 1563223182.01            udp_connection:41   (SocksUDPConnection)  Received an IPV6 udp datagram, dropping it (Not implemented yet)
WARNING 1563223182.01            udp_connection:41   (SocksUDPConnection)  Received an IPV6 udp datagram, dropping it (Not implemented yet)
WARNING 1563223182.02            udp_connection:41   (SocksUDPConnection)  Received an IPV6 udp datagram, dropping it (Not implemented yet)
INFO    1563223182.02                connection:84   (Socks5Connection)  Client has sent METHOD REQUEST
INFO    1563223182.03                connection:131  (Socks5Connection)  TCP req to tracker2.wasabii.com.tw:6969 support it. Returning HOST UNREACHABLE
INFO    1563223182.03                connection:198  (Socks5Connection)  Closing session, reason unspecified
INFO    1563223182.03                connection:84   (Socks5Connection)  Client has sent METHOD REQUEST
INFO    1563223182.03                connection:131  (Socks5Connection)  TCP req to tracker.mg64.net:6881 support it. Returning HOST UNREACHABLE
INFO    1563223182.03                connection:198  (Socks5Connection)  Closing session, reason unspecified
INFO    1563223182.03                connection:84   (Socks5Connection)  Client has sent METHOD REQUEST
INFO    1563223182.03                connection:131  (Socks5Connection)  TCP req to bt.artvid.ru:6969 support it. Returning HOST UNREACHABLE
INFO    1563223182.03                connection:198  (Socks5Connection)  Closing session, reason unspecified
INFO    1563223182.03                connection:84   (Socks5Connection)  Client has sent METHOD REQUEST
INFO    1563223182.03                connection:131  (Socks5Connection)  TCP req to tracker1.wasabii.com.tw:6969 support it. Returning HOST UNREACHABLE
INFO    1563223182.03                connection:198  (Socks5Connection)  Closing session, reason unspecified
INFO    1563223182.03                connection:84   (Socks5Connection)  Client has sent METHOD REQUEST
INFO    1563223182.03                connection:131  (Socks5Connection)  TCP req to open.acgtracker.com:1096 support it. Returning HOST UNREACHABLE
INFO    1563223182.03                connection:198  (Socks5Connection)  Closing session, reason unspecified
INFO    1563223190.22       CreditMiningManager:342  (CreditMiningManager)  Downloading: 0, Uploading: 0, Stopped: 0
INFO    1563223190.22       CreditMiningManager:344  (CreditMiningManager)  0 active download(s), 0.000 MB uploaded, 0.000 MB downloaded
WARNING 1563223190.26            udp_connection:41   (SocksUDPConnection)  Received an IPV6 udp datagram, dropping it (Not implemented yet)
WARNING 1563223190.26            udp_connection:41   (SocksUDPConnection)  Received an IPV6 udp datagram, dropping it (Not implemented yet)
INFO    1563223206.32           torrent_checker:150  (TorrentChecker)  Selected 1 new torrents to check on tracker: http://ehtracker.org/934141/664122xR1hO6zZ9LC/announce
INFO    1563223206.33                    caches:155  (CrawlRequestCache)  Timeout for crawl with id 46634
ERROR   1563223206.35                 community:443  (DHTDiscoveryCommunity)  Got find-response with unknown identifier, dropping packet
ERROR   1563223206.35                 community:443  (DHTDiscoveryCommunity)  Got find-response with unknown identifier, dropping packet
ERROR   1563223206.35                 community:443  (DHTDiscoveryCommunity)  Got find-response with unknown identifier, dropping packet
ERROR   1563223206.35                 community:443  (DHTDiscoveryCommunity)  Got find-response with unknown identifier, dropping packet
INFO    1563223208.51                connection:84   (Socks5Connection)  Client has sent METHOD REQUEST
INFO    1563223208.53                connection:198  (Socks5Connection)  Closing session, reason unspecified
INFO    1563223208.53                connection:84   (Socks5Connection)  Client has sent METHOD REQUEST
INFO    1563223208.53                connection:84   (Socks5Connection)  Client has sent METHOD REQUEST
INFO    1563223208.53                connection:84   (Socks5Connection)  Client has sent METHOD REQUEST
INFO    1563223208.53                connection:84   (Socks5Connection)  Client has sent METHOD REQUEST
INFO    1563223208.53                connection:84   (Socks5Connection)  Client has sent METHOD REQUEST
INFO    1563223208.53                connection:84   (Socks5Connection)  Client has sent METHOD REQUEST
INFO    1563223208.53                connection:198  (Socks5Connection)  Closing session, reason unspecified
INFO    1563223208.53                connection:198  (Socks5Connection)  Closing session, reason unspecified
INFO    1563223208.53                connection:198  (Socks5Connection)  Closing session, reason unspecified
INFO    1563223208.53                connection:198  (Socks5Connection)  Closing session, reason unspecified
INFO    1563223208.53                connection:198  (Socks5Connection)  Closing session, reason unspecified
INFO    1563223208.53                connection:198  (Socks5Connection)  Closing session, reason unspecified
INFO    1563223210.38       CreditMiningManager:342  (CreditMiningManager)  Downloading: 0, Uploading: 0, Stopped: 0
INFO    1563223210.38       CreditMiningManager:344  (CreditMiningManager)  0 active download(s), 0.000 MB uploaded, 0.000 MB downloaded
INFO    1563223213.13           torrent_checker:150  (TorrentChecker)  Selected 1 new torrents to check on tracker: http://ehtracker.org/937997/664122xR1hO6zZ9LC/announce
INFO    1563223214.18       CreditMiningManager:342  (CreditMiningManager)  Downloading: 0, Uploading: 0, Stopped: 0
INFO    1563223214.18       CreditMiningManager:344  (CreditMiningManager)  0 active download(s), 0.000 MB uploaded, 0.000 MB downloaded
INFO    1563223215.46               run_tribler:142  (root)  Shutting down Tribler
tribler@vi-notebook:~/tribler$ 
tribler@vi-notebook:~/tribler$ 
tribler@vi-notebook:~/tribler$ 
tribler@vi-notebook:~/tribler$ INFO    1563223218.03                connection:84   (Socks5Connection)  Client has sent METHOD REQUEST
INFO    1563223218.03                connection:131  (Socks5Connection)  TCP req to announce.torrentsmd.com:6969 support it. Returning HOST UNREACHABLE
INFO    1563223218.03                connection:198  (Socks5Connection)  Closing session, reason unspecified
INFO    1563223218.20       CreditMiningManager:342  (CreditMiningManager)  Downloading: 0, Uploading: 0, Stopped: 0
INFO    1563223218.20       CreditMiningManager:344  (CreditMiningManager)  0 active download(s), 0.000 MB uploaded, 0.000 MB downloaded
@qstokkink
Copy link
Contributor

Hmm.. this seems like a symptom of a deeper problem. The trivial fix would be to just increase the timeout. However, the deeper problem would be that we do too much disk I/O before startup.

We should investigate the amount of disk I/O we perform before starting up.

@synctext Maybe we can turn this into a longer term student project?

@vi
Copy link
Contributor Author

vi commented Jul 16, 2019

Typically opening Python console and pasting a bunch of imports Tribler uses takes significant amount of time (especially with cold filesystem caches).

@ichorid
Copy link
Contributor

ichorid commented Jul 16, 2019

I suggest postponing fixing this for 7.5, when we will refactor the core startup system and Libtorrent Wrapper.

@ichorid ichorid added this to the V7.5: core refactoring milestone Jul 16, 2019
@synctext
Copy link
Member

Seems too low on science for a student project..
Btw would you accept a 'fix' for this by a bsc student? They would need a few months of training for that first. Any volunteers? :-)

@qstokkink qstokkink mentioned this issue Jul 17, 2019
Closed
@qstokkink
Copy link
Contributor

I moved the trivial solution, which we can easily fix, to #4680.

We can get back to this issue (lazy loading dependencies) in the https://github.com/Tribler/tribler/milestone/31 milestone.

@ichorid ichorid mentioned this issue Jul 18, 2019
Merged
@devos50 devos50 reopened this Jul 18, 2019
@devos50 devos50 mentioned this issue Jul 20, 2019
Closed
@ichorid
Copy link
Contributor

ichorid commented Jan 4, 2020

Related to #4953

@devos50
Copy link
Contributor

devos50 commented Jun 23, 2020

We already increased this timeout to 60 seconds. We also noticed that errors related to this traceback are usually because the core failed to start (e.g., due to an ImportError).

@devos50 devos50 closed this as completed Jun 23, 2020
@vi
Copy link
Contributor Author

vi commented Jun 23, 2020 •
edited
Loading

60 seconds may be not enough either.

When system is significantly swapped to HDD, it may take around 5 minutes to thrash through those files. So it may fail to start twice because of 60-second timeout, then start successfully on the third attempt (with startup taking about 30 seconds).

As a minimum, the timeout should be configurable in settings. As a maximum, Core should report some startup progress (such as number of Python modules imported) startup not timing out if starting up is progressing (although slow), only when it is actually stuck.

Also when startup is taking a long time, it may ask for additional user confirmation before taking any action (like with "Forced shutdown" button).

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
Milestone
7.6.0 November: Stability, usability,...
Development

Successfully merging a pull request may close this issue.

Increase wait for core to 60 sec ichorid/tribler
5 participants
@vi @synctext @devos50 @ichorid @qstokkink