weixin_39553600
weixin_39553600
2021-01-09 03:46

Tribler gets stuck at startup for a long time

It mostly happens if Tribler was not running for some time (e.g. a 20 minutes to few hours). The GUI/Core is stuck on "spinning gears screen". Parts of the log:

python
[PID:262508] 2020-10-03 23:06:28,515 - WARNING - Download(638) - Either file does not exist or is not file
[PID:262508] 2020-10-03 23:06:28,538 - WARNING - Download(638) - Either file does not exist or is not file
[PID:262508] 2020-10-03 23:06:28,540 - WARNING - SocksUDPConnection(44) - Received an IPV6 udp datagram, dropping it (Not implemented yet)
[PID:262508] 2020-10-03 23:06:28,545 - INFO - TrustChainCommunity(463) - Requesting crawl of node b'43b0678b' (blocks 43 to 43) with id 30023
[PID:262508] 2020-10-03 23:06:28,547 - INFO - TrustChainCommunity(463) - Requesting crawl of node b'12823d41' (blocks 132 to 132) with id 52056
[PID:262508] 2020-10-03 23:06:28,548 - INFO - TrustChainCommunity(463) - Requesting crawl of node b'4444b5c0' (blocks 68 to 68) with id 52707
[PID:262508] 2020-10-03 23:06:28,552 - WARNING - Download(638) - Either file does not exist or is not file
[PID:262508] 2020-10-03 23:06:28,564 - WARNING - Download(638) - Either file does not exist or is not file
[PID:262508] 2020-10-03 23:06:28,572 - INFO - TrustChainCommunity(463) - Requesting crawl of node b'cb62a1ea' (blocks 1 to 1) with id 33093
[PID:262508] 2020-10-03 23:06:28,592 - WARNING - Download(638) - Either file does not exist or is not file

>>>
STUCK HERE FOR 30 SECONDS !!!
>>>

[PID:262508] 2020-10-03 23:07:02,312 - INFO - TrustChainCommunity(377) - Block validation result <function validationresult.partial_next at>, [], (Block b'd802feb6' from ...b'cb62a1ea':1 links ...b'f1dc48fb':0 for {b'up': 0, b'down': 104629130, b'total_up': 0, b'total_down': 104629130} type b'tribler_bandwidth')
[PID:262508] 2020-10-03 23:07:02,315 - INFO - CrawlRequestCache(148) - Timeout for crawl with id 30023
[PID:262508] 2020-10-03 23:07:02,315 - INFO - CrawlRequestCache(148) - Timeout for crawl with id 52056
[PID:262508] 2020-10-03 23:07:02,315 - INFO - CrawlRequestCache(148) - Timeout for crawl with id 52707
[PID:262508] 2020-10-03 23:07:02,321 - INFO - TorrentChecker(132) - Selected 1 new torrents to check on tracker: http://...
[PID:262508] 2020-10-03 23:07:02,332 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,332 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,332 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,332 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,332 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,332 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,332 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,333 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,333 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,333 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,333 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,333 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,333 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,333 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,333 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,333 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,333 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,333 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,333 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,333 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,333 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,333 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,333 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,333 - WARNING - DownloadManager(578) - Timeout waiting for libtorrent DHT getting enough peers
[PID:262508] 2020-10-03 23:07:02,341 - INFO - TrustChainCommunity(377) - Block validation result <function validationresult.partial_next at>, [], (Block b'5f9afbfa' from ...b'4444b5c0':68 links ...b'545f08b3':3394 for {b'down': 0, b'total_down': 61470840, b'up': 9215304, b'total_up': 2223316865} type b'tribler_bandwidth')
[PID:262508] 2020-10-03 23:07:02,347 - INFO - TrustChainCommunity(377) - Block validation result <function validationresult.partial_next at>, [], (Block b'974c4f78' from ...b'12823d41':132 links ...b'c789f76b':407 for {b'down': 0, b'total_down': 162260596, b'up': 20919567, b'total_up': 3580222864} type b'tribler_bandwidth')
[PID:262508] 2020-10-03 23:07:02,420 - INFO - TrustChainCommunity(377) - Block validation result <function validationresult.partial_next at>, [], (Block b'94322ea2' from ...b'43b0678b':43 links ...b'8bdc834e':412 for {b'down': 0, b'total_down': 329972418, b'up': 17544604, b'total_up': 1617509082} type b'tribler_bandwidth')
[PID:262508] 2020-10-03 23:07:02,422 - INFO - TrustChainCommunity(377) - Block validation result <function validationresult.partial at>, [], (Block b'aee04c34' from ...b'66232246':43 links ...b'43b0678b':0 for {b'down': 17083471, b'total_down': 1701426807, b'up': 0, b'total_up': 0} type b'tribler_bandwidth')
[PID:262508] 2020-10-03 23:07:02,423 - INFO - TrustChainCommunity(463) - Requesting crawl of node b'fbf70d4b' (blocks 1 to 1) with id 12151
[PID:262508] 2020-10-03 23:07:02,652 - INFO - TrustChainCommunity(463) - Requesting crawl of node b'3ddd0e04' (blocks 27 to 27) with id 21482
[PID:262508] 2020-10-03 23:07:02,666 - INFO - TrustChainCommunity(463) - Requesting crawl of node b'47a1c909' (blocks 1 to 1) with id 57164
[PID:262508] 2020-10-03 23:07:02,683 - INFO - TrustChainCommunity(377) - Block validation result <function validationresult.partial_next at>, [], (Block b'85f19760' from ...b'fbf70d4b':1 links ...b'19284910':0 for {b'up': 0, b'down': 265450538, b'total_up': 0, b'total_down': 265450538} type b'tribler_bandwidth')
[PID:262508] 2020-10-03 23:07:02,708 - INFO - TrustChainCommunity(377) - Block validation result <function validationresult.partial_next at>, [], (Block b'dfe3c257' from ...b'3ddd0e04':27 links ...b'4a6d5744':0 for {b'down': 45282088, b'total_down': 49640784, b'up': 0, b'total_up': 1082397580} type b'tribler_bandwidth')
[PID:262508] 2020-10-03 23:07:02,709 - INFO - TrustChainCommunity(377) - Block validation result <function validationresult.partial at>, [], (Block b'199d2596' from ...b'2a4875b9':27 links ...b'3ddd0e04':0 for {b'down': 26551119, b'total_down': 310558277, b'up': 0, b'total_up': 16729880} type b'tribler_bandwidth')
[PID:262508] 2020-10-03 23:07:02,741 - INFO - TrustChainCommunity(377) - Block validation result <function validationresult.partial_next at>, [], (Block b'c2c77725' from ...b'47a1c909':1 links ...b'd28b29d6':0 for {b'up': 0, b'down': 270638430, b'total_up': 0, b'total_down': 270638430} type b'tribler_bandwidth')
[PID:262508] 2020-10-03 23:07:03,330 - WARNING - SocksUDPConnection(44) - Received an IPV6 udp datagram, dropping it (Not implemented yet)
[PID:262508] 2020-10-03 23:07:03,331 - INFO - Socks5Connection(90) - Client has sent METHOD REQUEST
[PID:262508] 2020-10-03 23:07:03,331 - INFO - Socks5Connection(90) - Client has sent METHOD REQUEST
[PID:262508] 2020-10-03 23:07:03,331 - INFO - Socks5Connection(90) - Client has sent METHOD REQUEST
[PID:262508] 2020-10-03 23:07:03,331 - INFO - Socks5Connection(90) - Client has sent METHOD REQUEST
[PID:262508] 2020-10-03 23:07:03,331 - INFO - Socks5Connection(136) - Accepting TCP CONNECT request to bt4.t-ru.org:80
[PID:262508] 2020-10-03 23:07:03,331 - INFO - Socks5Connection(136) - Accepting TCP CONNECT request to bt4.t-ru.org:80
[PID:262508] 2020-10-03 23:07:03,331 - INFO - Socks5Connection(136) - Accepting TCP CONNECT request to bt4.t-ru.org:80
[PID:262508] 2020-10-03 23:07:03,331 - INFO - Socks5Connection(136) - Accepting TCP CONNECT request to bt.t-ru.org:80
[PID:262508] 2020-10-03 23:07:03,331 - WARNING - SocksUDPConnection(44) - Received an IPV6 udp datagram, dropping it (Not implemented yet)
[PID:262508] 2020-10-03 23:07:03,331 - INFO - TriblerTunnelCommunity(253) - Creating a new circuit of length 1 (type: DATA)
[PID:262508] 2020-10-03 23:07:03,331 - INFO - TriblerTunnelCommunity(278) - First hop is required exit
[PID:262508] 2020-10-03 23:07:03,332 - INFO - TriblerTunnelCommunity(311) - Adding first hop 37.48.77.235:35005 to circuit 4263830153
[PID:262508] 2020-10-03 23:07:03,332 - INFO - TriblerTunnelCommunity(253) - Creating a new circuit of length 1 (type: DATA)
[PID:262508] 2020-10-03 23:07:03,332 - INFO - TriblerTunnelCommunity(278) - First hop is required exit
[PID:262508] 2020-10-03 23:07:03,332 - INFO - TriblerTunnelCommunity(311) - Adding first hop 37.48.77.235:35005 to circuit 2364779785
[PID:262508] 2020-10-03 23:07:03,332 - INFO - TriblerTunnelCommunity(253) - Creating a new circuit of length 1 (type: DATA)
[PID:262508] 2020-10-03 23:07:03,332 - INFO - TriblerTunnelCommunity(278) - First hop is required exit
[PID:262508] 2020-10-03 23:07:03,332 - INFO - TriblerTunnelCommunity(311) - Adding first hop 37.48.77.235:35005 to circuit 2512302430
[PID:262508] 2020-10-03 23:07:03,332 - INFO - TriblerTunnelCommunity(253) - Creating a new circuit of length 1 (type: DATA)
[PID:262508] 2020-10-03 23:07:03,332 - INFO - TriblerTunnelCommunity(278) - First hop is required exit
[PID:262508] 2020-10-03 23:07:03,332 - INFO - TriblerTunnelCommunity(311) - Adding first hop 37.48.77.235:35005 to circuit 280089885
[PID:262508] 2020-10-03 23:07:03,333 - WARNING - SocksUDPConnection(44) - Received an IPV6 udp datagram, dropping it (Not implemented yet)
[PID:262508] 2020-10-03 23:07:03,333 - WARNING - SocksUDPConnection(44) - Received an IPV6 udp datagram, dropping it (Not implemented yet)
[PID:262508] 2020-10-03 23:07:03,333 - WARNING - SocksUDPConnection(44) - Received an IPV6 udp datagram, dropping it (Not implemented yet)
[PID:262508] 2020-10-03 23:07:03,357 - INFO - TrustChainCommunity(463) - Requesting crawl of node b'fca6e6d9' (blocks 138 to 138) with id 16995
[PID:262508] 2020-10-03 23:07:03,438 - INFO - TrustChainCommunity(377) - Block validation result <function validationresult.partial_next at>, [], (Block b'37221628' from ...b'fca6e6d9':138 links ...b'e11cc837':120 for {b'down': 0, b'total_down': 1098715084, b'up': 27815577, b'total_up': 6798853836} type b'tribler_bandwidth')
[PID:262508] 2020-10-03 23:07:05,424 - INFO - TriblerTunnelCommunity(507) - Create introducing circuit for 727047e0ae044c2b8bf3164772df605dd42e6846
</function></function></function></function></function></function></function></function></function></function>

该提问来源于开源项目:Tribler/tribler

  • 点赞
  • 写回答
  • 关注问题
  • 收藏
  • 复制链接分享
  • 邀请回答

8条回答

  • weixin_39553600 weixin_39553600 4月前

    Looks like DHT timeout.

    点赞 评论 复制链接分享
  • weixin_39553600 weixin_39553600 4月前

    Or the timeout is the result and not the cause? , what would you say, can it be the block validation?

    
    [PID:262508] 2020-10-03 23:07:02,312 - INFO - TrustChainCommunity(377) - Block validation result <function validationresult.partial_next at>, [], (Block b'd802feb6' from ...b'cb62a1ea':1 links ...b'f1dc48fb':0 for {b'up': 0, b'down': 104629130, b'total_up': 0, b'total_down': 104629130} type b'tribler_bandwidth')
    </function>
    点赞 评论 复制链接分享
  • weixin_40000131 weixin_40000131 4月前

    it's always possible, but it seems unlikely as this code hasn't changed in a year (we should've probably seen that happen before). I can't give you any conclusive answer from this output though.

    If you can reproduce this reliably, you have a fighting chance to debug this. You can hook into the new IPv8 health monitor and check if the history is empty (if the history is empty, the core is flatlining), after this line: https://github.com/Tribler/tribler/blob/devel/src/tribler-core/tribler_core/modules/ipv8_health_monitor.py#L68 You can then print the sys._current_frames() to see what all the threads are stuck on. Something like this:

    python
    if not history:
        from asyncio import all_tasks
        import sys
        print(sys._current_frames().items())
        print(all_tasks())
    

    EDIT: Actually, that assumes nothing is hard-blocking the main thread. It would probably be better to just print the asyncio tasks and sys frames periodically in an actual Thread.

    点赞 评论 复制链接分享
  • weixin_40000131 weixin_40000131 4月前

    Actually, I'm complicating this way too much.. just press Ctrl+C when it's stuck and you'll get a KeyboardInterrupt traceback 😃

    Something like this:

    python
    Traceback (most recent call last):
      File "/home/quinten/Documents/tribler/src/run_tribler.py", line 102, in <module>
        start_tribler_core(base_path, api_port, api_key, root_state_dir, core_test_mode=core_test_mode)
      File "/home/quinten/Documents/tribler/src/run_tribler.py", line 85, in start_tribler_core
        get_event_loop().run_forever()
      File "/usr/lib/python3.8/asyncio/base_events.py", line 570, in run_forever
        self._run_once()
      File "/usr/lib/python3.8/asyncio/base_events.py", line 1859, in _run_once
        handle._run()
      File "/usr/lib/python3.8/asyncio/events.py", line 81, in _run
        self._context.run(self._callback, *self._args)
      File "/home/quinten/Documents/tribler/src/run_tribler.py", line 81, in start_tribler
        await session.start()
      File "/home/quinten/Documents/tribler/src/tribler-core/tribler_core/session.py", line 402, in start
        self.gigachannel_manager.start()
      File "/home/quinten/Documents/tribler/src/tribler-core/tribler_core/modules/metadata_store/gigachannel_manager.py", line 45, in start
        for channel in self.session.mds.ChannelMetadata.get_my_channels().where(
      File "/home/quinten/.local/lib/python3.8/site-packages/pony/orm/core.py", line 6275, in next
        qr._items = qr._query._actual_fetch(qr._limit, qr._offset)
      File "/home/quinten/.local/lib/python3.8/site-packages/pony/orm/core.py", line 5831, in _actual_fetch
        cursor = database._exec_sql(sql, arguments)
      File "/home/quinten/.local/lib/python3.8/site-packages/pony/orm/core.py", line 947, in _exec_sql
        try: new_id = provider.execute(cursor, sql, arguments, returning_id)
      File "<string>", line 2, in execute
      File "/home/quinten/.local/lib/python3.8/site-packages/pony/orm/dbapiprovider.py", line 55, in wrap_dbapi_exceptions
        try: return func(provider, *args, **kwargs)
      File "/home/quinten/.local/lib/python3.8/site-packages/pony/orm/dbapiprovider.py", line 279, in execute
        else: cursor.execute(sql, arguments)
    KeyboardInterrupt
    </string></module>
    点赞 评论 复制链接分享
  • weixin_39807541 weixin_39807541 4月前

    I highly doubt this is caused the TrustChain validation logic - that piece of logic is just a few lines where the validity of a block is checked. Of course, it could be stuck in a database lookup or something, but that can also happen during the execution of metadata store logic.

    点赞 评论 复制链接分享
  • weixin_40000131 weixin_40000131 4月前

    We could use an external process to launch Tribler and keep an eye on its log statements. Then, if no logging output is captured from the process (for 10 seconds or something), send it a SIGINT. That should be a fairly reproducible way to capture what is getting stuck.

    点赞 评论 复制链接分享
  • weixin_39553600 weixin_39553600 4月前

    Still there...

    点赞 评论 复制链接分享
  • weixin_39553600 weixin_39553600 4月前

    Confirmed by in #5665

    点赞 评论 复制链接分享

相关推荐