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

CoreConnectTimeoutError: Can't get Core API port value within 30 seconds #7351

Closed
kozlovsky opened this issue Apr 5, 2023 · 7 comments
Closed

CoreConnectTimeoutError: Can't get Core API port value within 30 seconds #7351

kozlovsky opened this issue Apr 5, 2023 · 7 comments
Assignees
@kozlovsky
Labels
type: blocker type: bug
Milestone
7.13.0

Comments

@kozlovsky
Copy link
Contributor

kozlovsky commented Apr 5, 2023 •
edited
Loading

This bug is a reincarnation of #7137, but now we are better prepared to fix it.

We have four reports from the same user:

In the last one, the user adds a comment:

This happens all the time - at the start and also when ending a tribler instance

In the attached logs, we can see that the Core process started the RESTManager, and the last log lines from the RESTManager are:

[tribler-core PID:6038] 2023-04-03 17:07:57,938 - INFO - RESTManager(131) - Http enabled
[tribler-core PID:6038] 2023-04-03 17:07:57,938 - INFO - RESTManager(139) - Searching for a free port starting from 52194
@kozlovsky kozlovsky added this to the 7.13.0 milestone Apr 5, 2023
@kozlovsky kozlovsky self-assigned this Apr 5, 2023
@sentry-for-tribler
Copy link

Sentry issue: TRIBLER-14P

@xoriole
Copy link
Contributor

xoriole commented May 1, 2023

I was able to reproduce a similar issue today.

GUI Log

[tribler-gui PID:4252] 2023-05-01 14:33:01,717 - INFO - tribler.core.logger.logger(80) - Config loaded for app_mode=tribler-gui
[tribler-gui PID:4252] 2023-05-01 14:33:01,717 - INFO - tribler.core.check_os(109) - Check and enable code tracing. Process name: "gui". Log dir: "C:\Users\tribler\AppData\Roaming\.Tribler"
[tribler-gui PID:4252] 2023-05-01 14:33:01,717 - INFO - tribler.core.check_os(91) - Enable fault handler: "C:\Users\tribler\AppData\Roaming\.Tribler"
[tribler-gui PID:4252] 2023-05-01 14:33:01,717 - INFO - tribler.core.check_os(44) - Check environment
[tribler-gui PID:4252] 2023-05-01 14:33:01,717 - INFO - tribler.core.check_os(49) - Check free space
[tribler-gui PID:4252] 2023-05-01 14:33:01,717 - INFO - TriblerApplication(25) - Start Tribler application. Win id: "triblerapp". Sys argv: "['C:\\Program Files\\Tribler\\tribler.exe']"
[tribler-gui PID:4252] 2023-05-01 14:33:01,733 - INFO - TriblerApplication(51) - No running instances (socket error: 2)
[tribler-gui PID:4252] 2023-05-01 14:33:02,311 - INFO - tribler.gui.utilities(494) - Available Tribler translations {'Spanish': 'es_ES', 'Portuguese': 'pt_BR', 'Russian': 'ru_RU', 'Chinese': 'zh_CN', 'English': 'en_US'}
[tribler-gui PID:4252] 2023-05-01 14:33:02,311 - INFO - tribler.gui.utilities(495) - System language: ['en-US'], Tribler language: ['en', 'en-US', 'en-Latn-US']
[tribler-gui PID:4252] 2023-05-01 14:33:02,311 - INFO - tribler.gui.start_gui(72) - Start Tribler Window
[tribler-gui PID:4252] 2023-05-01 14:33:02,327 - INFO - NetworkUtils(46) - Looking for first free port in range [20100..65535]
[tribler-gui PID:4252] 2023-05-01 14:33:02,358 - INFO - NetworkUtils(50) - 20100 is free
[tribler-gui PID:4252] 2023-05-01 14:33:02,405 - INFO - Tribler Config(86) - Init. State dir: C:\Users\tribler\AppData\Roaming\.Tribler. File: C:\Users\tribler\AppData\Roaming\.Tribler\triblerd.conf
[tribler-gui PID:4252] 2023-05-01 14:33:02,405 - INFO - VersionHistory(290) - Files to copy: ['ec_multichain.pem', 'ecpub_multichain.pem', 'secondary_key.pem', 'ec_trustchain_testnet.pem', 'triblerd.conf', 'lt.state']
[tribler-gui PID:4252] 2023-05-01 14:33:02,405 - INFO - VersionHistory(298) - Load: C:\Users\tribler\AppData\Roaming\.Tribler\version_history.json
[tribler-gui PID:4252] 2023-05-01 14:33:02,405 - INFO - VersionHistory(317) - Loaded versions: OrderedDict([((7, 12), <TriblerVersion{7.12.1-742-g35d38420b}>), ((7, 13), <TriblerVersion{7.13.0-RC1-63-g35d38420b}>)])
[tribler-gui PID:4252] 2023-05-01 14:33:02,420 - INFO - VersionHistory(232) - Current Tribler version is 7.13.0-RC1-63-g35d38420b
[tribler-gui PID:4252] 2023-05-01 14:33:02,420 - INFO - VersionHistory(239) - The previously started version is the same as the current one
[tribler-gui PID:4252] 2023-05-01 14:33:11,936 - INFO - TriblerWindow(409) - Available screen geometry: PyQt5.QtCore.QRect(0, 0, 1920, 1040)
[tribler-gui PID:4252] 2023-05-01 14:33:11,936 - INFO - TriblerWindow(410) - Restored window size: PyQt5.QtCore.QSize(1365, 880)
[tribler-gui PID:4252] 2023-05-01 14:33:11,936 - INFO - TriblerWindow(416) - Resize window to the bounded size: PyQt5.QtCore.QSize(1365, 880)
[tribler-gui PID:4252] 2023-05-01 14:33:11,936 - INFO - TriblerWindow(421) - Restored window position: PyQt5.QtCore.QPoint(238, 33)
[tribler-gui PID:4252] 2023-05-01 14:33:11,936 - INFO - TriblerWindow(427) - Is window outside the screen: False
[tribler-gui PID:4252] 2023-05-01 14:33:11,936 - INFO - TriblerWindow(430) - Move the window to the: PyQt5.QtCore.QPoint(238, 33)
[tribler-gui PID:4252] 2023-05-01 14:33:13,202 - INFO - EventRequestManager(198) - Connecting to events endpoint (without retrying)
[tribler-gui PID:4252] 2023-05-01 14:33:15,671 - INFO - EventRequestManager(138) - Error ConnectionRefusedError while trying to connect to Tribler Core, will not retry
[tribler-gui PID:4252] 2023-05-01 14:33:15,671 - INFO - UpgradeManager(191) - Start upgrade process
[tribler-gui PID:4252] 2023-05-01 14:33:15,671 - INFO - UpgradeManager(148) - Should cleanup old versions
[tribler-gui PID:4252] 2023-05-01 14:33:15,671 - INFO - UpgradeManager(151) - Last run version is the same as the current version. Exit cleanup procedure.
[tribler-gui PID:4252] 2023-05-01 14:33:15,749 - INFO - StateDirUpgradeWorker(46) - Run
[tribler-gui PID:4252] 2023-05-01 14:33:15,749 - INFO - StateDirUpgradeWorker(61) - Upgrade state dir for <VersionHistory[(7, 13), (7, 12)]>
[tribler-gui PID:4252] 2023-05-01 14:33:15,749 - INFO - VersionHistory(349) - State directory should not be copied
[tribler-gui PID:4252] 2023-05-01 14:33:15,749 - INFO - Tribler Config(100) - Load: C:\Users\tribler\AppData\Roaming\.Tribler\7.13\triblerd.conf. State dir: C:\Users\tribler\AppData\Roaming\.Tribler\7.13. Reset config on error: True
[tribler-gui PID:4252] 2023-05-01 14:33:15,827 - INFO - Tribler Config(86) - Init. State dir: None. File: None
[tribler-gui PID:4252] 2023-05-01 14:33:16,170 - INFO - TriblerUpgrader(95) - Run
[tribler-gui PID:4252] 2023-05-01 14:33:16,170 - INFO - TriblerUpgrader(378) - Upgrading GigaChannel DB from version 8 to 10
[tribler-gui PID:4252] 2023-05-01 14:33:16,561 - INFO - TriblerUpgrader(197) - Upgrade Pony DB 10 to 11
[tribler-gui PID:4252] 2023-05-01 14:33:16,655 - INFO - tribler.core.upgrade.config_converter(12) - Upgrade config to 7.6
[tribler-gui PID:4252] 2023-05-01 14:33:16,655 - INFO - TriblerUpgrader(214) - Upgrade bandwidth accounting DB 8 to 9
[tribler-gui PID:4252] 2023-05-01 14:33:16,749 - INFO - TriblerUpgrader(181) - Upgrade Pony DB 11 to 12
[tribler-gui PID:4252] 2023-05-01 14:33:16,842 - INFO - TriblerUpgrader(166) - Upgrade Pony DB 12 to 13
[tribler-gui PID:4252] 2023-05-01 14:33:16,858 - INFO - TriblerUpgrader(146) - Upgrade Pony DB from version 13 to version 14
[tribler-gui PID:4252] 2023-05-01 14:33:16,874 - INFO - TriblerUpgrader(130) - Upgrade tags to knowledge
[tribler-gui PID:4252] 2023-05-01 14:33:16,874 - INFO - MigrationTagsToKnowledge(29) - Tags DB path: C:\Users\tribler\AppData\Roaming\.Tribler\7.13\sqlite\tags.db
[tribler-gui PID:4252] 2023-05-01 14:33:16,874 - INFO - MigrationTagsToKnowledge(30) - Knowledge DB path: C:\Users\tribler\AppData\Roaming\.Tribler\7.13\sqlite\knowledge.db
[tribler-gui PID:4252] 2023-05-01 14:33:16,874 - INFO - MigrationTagsToKnowledge(33) - Starting upgrade procedure for tags DB
[tribler-gui PID:4252] 2023-05-01 14:33:16,874 - INFO - MigrationTagsToKnowledge(36) - Tags DB doesn't exist. Stop procedure.
[tribler-gui PID:4252] 2023-05-01 14:33:16,874 - INFO - TriblerUpgrader(109) - Remove old logs
[tribler-gui PID:4252] 2023-05-01 14:33:42,180 - INFO - TriblerUpgrader(135) - Upgrade Pony DB from version 14 to version 15
[tribler-gui PID:4252] 2023-05-01 14:33:42,890 - INFO - StateDirUpgradeWorker(56) - Finished
[tribler-gui PID:4252] 2023-05-01 14:33:43,957 - INFO - CoreManager(129) - Start Tribler core process C:\Program Files\Tribler\tribler.exe with arguments: ['--core']
[tribler-gui PID:4252] 2023-05-01 14:33:44,310 - INFO - CoreManager(133) - Core process started
[tribler-gui PID:4252] 2023-05-01 14:34:14,370 - INFO - ErrorHandler(35) - Processing GUI error: <class 'tribler.gui.exceptions.CoreConnectTimeoutError'>
[tribler-gui PID:4252] 2023-05-01 14:34:14,378 - ERROR - ErrorHandler(40) - tribler.gui.utilities.CreationTraceback: 
  File "run_tribler.py", line 103, in <module>
  File "tribler\gui\start_gui.py", line 73, in run_gui
  File "tribler\gui\tribler_window.py", line 203, in __init__
  File "tribler\gui\core_manager.py", line 47, in __init__


The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "tribler\gui\utilities.py", line 438, in trackback_wrapper
  File "tribler\gui\utilities.py", line 435, in trackback_wrapper
  File "tribler\gui\core_manager.py", line 168, in check_core_api_port
tribler.gui.exceptions.CoreConnectTimeoutError: Can't get Core API port value within 30 seconds

[tribler-gui PID:4252] 2023-05-01 14:34:14,447 - INFO - SentryReporter(388) - Before send strategy: SentryStrategy.SEND_SUPPRESSED
[tribler-gui PID:4252] 2023-05-01 14:34:14,448 - INFO - ErrorHandler(64) - It is a subclass of CoreError exception
[tribler-gui PID:4252] 2023-05-01 14:34:14,448 - INFO - ErrorHandler(68) - Last Core output:
> [tribler-core PID:7328] 2023-05-01 14:34:13,029 - INFO - asyncio(1340) - Datagram endpoint local_addr=('0.0.0.0', 0) remote_addr=None created: (<_SelectorDatagramTransport fd=1460 read=idle write=<idle, bufsize=0>>, <tribler.core.components.torrent_checker.torrent_checker.torrentchecker_session.UdpSocketManager object at 0x00000246CB7FA4F0>)[tribler-core PID:7328] 2023-05-01 14:34:13,030 - INFO - TunnelsComponent(153) - TunnelsComponent: waiting for SocksServersComponent[tribler-core PID:7328] 2023-05-01 14:34:13,043 - INFO - TriblerTunnelCommunity(135) - Exit settings: BT=False, IPv8=False[tribler-core PID:7328] 2023-05-01 14:34:13,056 - INFO - TunnelsComponent(153) - TunnelsComponent: started in 13.4520s[tribler-core PID:7328] 2023-05-01 14:34:13,170 - WARNING - asyncio(1854) - Executing <Handle _SelectorSocketTransport._read_ready() created at asyncio\selector_events.py:257> took 0.109 seconds[tribler-core PID:7328] 2023-05-01 14:34:13,175 - INFO - DownloadManager(630) - Start handle. Download: Download <name: 'b'6a475a4ad302a4d20fb202b07cea40e91b257ce25a18bddd'' hops: 0 checkpoint_disabled: 0>. Atp: {'save_path': 'C:\\Users\\tribler\\AppData\\Roaming\\.Tribler\\7.12\\channels', 'storage_mode': libtorrent.storage_mode_t.storage_mode_sparse, 'flags': 208, 'ti': <libtorrent.torrent_info object at 0x00000246CB7F07F0>, 'resume_data': '<skipped in log>'}[tribler-core PID:7328] 2023-05-01 14:34:13,288 - WARNING - asyncio(1854) - Executing <Task finished name='GigaChannelManager:Check and regen personal channels' coro=<GigaChannelManager.check_and_regen_personal_channels() done, defined at tribler\core\components\gigachannel_manager\gigachannel_manager.py:62> result=None created at ipv8\taskmanager.py:114> took 0.109 seconds[tribler-core PID:7328] 2023-05-01 14:34:13,302 - INFO - RESTComponent(153) - RESTComponent: waiting for TorrentCheckerComponent[tribler-core PID:7328] 2023-05-01 14:34:13,307 - INFO - tribler.core.components.gui_process_watcher.gui_process_watcher(39) - GUI process checked, it is still working[tribler-core PID:7328] 2023-05-01 14:34:13,310 - INFO - KnowledgeRulesProcessor(78) - Processing batch [36356...37356]
[tribler-gui PID:4252] 2023-05-01 14:34:14,448 - INFO - CoreManager(220) - Stopping Core manager
[tribler-gui PID:4252] 2023-05-01 14:34:14,448 - WARNING - CoreManager(225) - Core is not connected during the CoreManager shutdown, killing it...
[tribler-gui PID:4252] 2023-05-01 14:34:14,508 - INFO - CoreManager(280) - Core process finished
[tribler-gui PID:4252] 2023-05-01 14:34:34,500 - INFO - tribler.gui.start_gui(87) - Shutting down Tribler

Core Log:

[tribler-core PID:7328] 2023-05-01 14:34:13,029 - INFO - asyncio(1340) - Datagram endpoint local_addr=('0.0.0.0', 0) remote_addr=None created: (<_SelectorDatagramTransport fd=1460 read=idle write=<idle, bufsize=0>>, <tribler.core.components.torrent_checker.torrent_checker.torrentchecker_session.UdpSocketManager object at 0x00000246CB7FA4F0>)
[tribler-core PID:7328] 2023-05-01 14:34:13,030 - INFO - TunnelsComponent(153) - TunnelsComponent: waiting for SocksServersComponent
[tribler-core PID:7328] 2023-05-01 14:34:13,043 - INFO - TriblerTunnelCommunity(135) - Exit settings: BT=False, IPv8=False
[tribler-core PID:7328] 2023-05-01 14:34:13,056 - INFO - TunnelsComponent(153) - TunnelsComponent: started in 13.4520s
[tribler-core PID:7328] 2023-05-01 14:34:13,170 - WARNING - asyncio(1854) - Executing <Handle _SelectorSocketTransport._read_ready() created at asyncio\selector_events.py:257> took 0.109 seconds
[tribler-core PID:7328] 2023-05-01 14:34:13,175 - INFO - DownloadManager(630) - Start handle. Download: Download <name: 'b'6a475a4ad302a4d20fb202b07cea40e91b257ce25a18bddd'' hops: 0 checkpoint_disabled: 0>. Atp: {'save_path': 'C:\\Users\\tribler\\AppData\\Roaming\\.Tribler\\7.12\\channels', 'storage_mode': libtorrent.storage_mode_t.storage_mode_sparse, 'flags': 208, 'ti': <libtorrent.torrent_info object at 0x00000246CB7F07F0>, 'resume_data': '<skipped in log>'}
[tribler-core PID:7328] 2023-05-01 14:34:13,288 - WARNING - asyncio(1854) - Executing <Task finished name='GigaChannelManager:Check and regen personal channels' coro=<GigaChannelManager.check_and_regen_personal_channels() done, defined at tribler\core\components\gigachannel_manager\gigachannel_manager.py:62> result=None created at ipv8\taskmanager.py:114> took 0.109 seconds
[tribler-core PID:7328] 2023-05-01 14:34:13,302 - INFO - RESTComponent(153) - RESTComponent: waiting for TorrentCheckerComponent
[tribler-core PID:7328] 2023-05-01 14:34:13,307 - INFO - tribler.core.components.gui_process_watcher.gui_process_watcher(39) - GUI process checked, it is still working
[tribler-core PID:7328] 2023-05-01 14:34:13,310 - INFO - KnowledgeRulesProcessor(78) - Processing batch [36356...37356]

In this version, I had set asyncio debug to True.

@xoriole
Copy link
Contributor

xoriole commented May 2, 2023 •
edited
Loading

Here is a summary of slow coroutines detected by @kozlovsky' asyncio patch reproduced on Win10 64bit machine. The last log is where it freezes.

  • KnowledgeRulesProcessor:process_batch
  • GigaChannelCommunity:take step
  • Task-1522 coro=<RequestHandler._handle_request() running at aiohttp\web_protocol.py:433 (this is not clear which request)
[tribler-core PID:4752] 2023-05-02 13:30:56,562 - ERROR - tribler.core.utilities.slow_coro_detection(77) - Slow coroutine is occupying the loop for 1.102 seconds already: <Task pending name='KnowledgeRulesProcessor:process_batch' coro=<interval_runner() running at ipv8\taskmanager.py:18> cb=[TaskManager.register_task.<locals>.done_cb() at ipv8\taskmanager.py:128]>
Stack for <Task pending name='KnowledgeRulesProcessor:process_batch' coro=<interval_runner() running at ipv8\taskmanager.py:18> cb=[TaskManager.register_task.<locals>.done_cb() at ipv8\taskmanager.py:128]> (most recent call last):
  File "asyncio\events.py", line 81, in _run
  File "ipv8\taskmanager.py", line 18, in interval_runner

[tribler-core PID:4752] 2023-05-02 13:30:57,654 - ERROR - tribler.core.utilities.slow_coro_detection(68) - Slow coroutine step execution (duration=2.198 seconds): <Task pending name='KnowledgeRulesProcessor:process_batch' coro=<interval_runner() running at ipv8\taskmanager.py:19> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x00000191F12049D0>()]> cb=[TaskManager.register_task.<locals>.done_cb() at ipv8\taskmanager.py:128]>
Stack for <Task pending name='KnowledgeRulesProcessor:process_batch' coro=<interval_runner() running at ipv8\taskmanager.py:19> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x00000191F12049D0>()]> cb=[TaskManager.register_task.<locals>.done_cb() at ipv8\taskmanager.py:128]> (most recent call last):
  File "ipv8\taskmanager.py", line 19, in interval_runner

[tribler-core PID:4752] 2023-05-02 13:31:00,394 - ERROR - tribler.core.utilities.slow_coro_detection(68) - Slow coroutine step execution (duration=1.136 seconds): <Task pending name='GigaChannelCommunity:take step' coro=<interval_runner() running at ipv8\taskmanager.py:19> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x00000191F106F880>()]> cb=[TaskManager.register_task.<locals>.done_cb() at ipv8\taskmanager.py:128]>
Stack for <Task pending name='GigaChannelCommunity:take step' coro=<interval_runner() running at ipv8\taskmanager.py:19> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x00000191F106F880>()]> cb=[TaskManager.register_task.<locals>.done_cb() at ipv8\taskmanager.py:128]> (most recent call last):
  File "ipv8\taskmanager.py", line 19, in interval_runner

[tribler-core PID:4752] 2023-05-02 13:31:08,740 - ERROR - tribler.core.utilities.slow_coro_detection(77) - Slow coroutine is occupying the loop for 1.017 seconds already: <Task pending name='KnowledgeRulesProcessor:process_batch' coro=<interval_runner() running at ipv8\taskmanager.py:18> cb=[TaskManager.register_task.<locals>.done_cb() at ipv8\taskmanager.py:128]>
Stack for <Task pending name='KnowledgeRulesProcessor:process_batch' coro=<interval_runner() running at ipv8\taskmanager.py:18> cb=[TaskManager.register_task.<locals>.done_cb() at ipv8\taskmanager.py:128]> (most recent call last):
  File "asyncio\events.py", line 81, in _run
  File "ipv8\taskmanager.py", line 18, in interval_runner

[tribler-core PID:4752] 2023-05-02 13:31:10,595 - ERROR - tribler.core.utilities.slow_coro_detection(68) - Slow coroutine step execution (duration=2.875 seconds): <Task pending name='KnowledgeRulesProcessor:process_batch' coro=<interval_runner() running at ipv8\taskmanager.py:19> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x00000191F1191580>()]> cb=[TaskManager.register_task.<locals>.done_cb() at ipv8\taskmanager.py:128]>
Stack for <Task pending name='KnowledgeRulesProcessor:process_batch' coro=<interval_runner() running at ipv8\taskmanager.py:19> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x00000191F1191580>()]> cb=[TaskManager.register_task.<locals>.done_cb() at ipv8\taskmanager.py:128]> (most recent call last):
  File "ipv8\taskmanager.py", line 19, in interval_runner
  
[tribler-core PID:4752] 2023-05-02 13:31:13,790 - ERROR - tribler.core.utilities.slow_coro_detection(68) - Slow coroutine step execution (duration=1.218 seconds): <Task pending name='GigaChannelCommunity:take step' coro=<interval_runner() running at ipv8\taskmanager.py:19> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x00000191F148DDC0>()]> cb=[TaskManager.register_task.<locals>.done_cb() at ipv8\taskmanager.py:128]>
Stack for <Task pending name='GigaChannelCommunity:take step' coro=<interval_runner() running at ipv8\taskmanager.py:19> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x00000191F148DDC0>()]> cb=[TaskManager.register_task.<locals>.done_cb() at ipv8\taskmanager.py:128]> (most recent call last):
  File "ipv8\taskmanager.py", line 19, in interval_runner

[tribler-core PID:4752] 2023-05-02 13:31:22,934 - ERROR - tribler.core.utilities.slow_coro_detection(77) - Slow coroutine is occupying the loop for 1.980 seconds already: <Task pending name='KnowledgeRulesProcessor:process_batch' coro=<interval_runner() running at ipv8\taskmanager.py:18> cb=[TaskManager.register_task.<locals>.done_cb() at ipv8\taskmanager.py:128]>
Stack for <Task pending name='KnowledgeRulesProcessor:process_batch' coro=<interval_runner() running at ipv8\taskmanager.py:18> cb=[TaskManager.register_task.<locals>.done_cb() at ipv8\taskmanager.py:128]> (most recent call last):
  File "asyncio\events.py", line 81, in _run
  File "ipv8\taskmanager.py", line 18, in interval_runner

[tribler-core PID:4752] 2023-05-02 13:31:23,581 - ERROR - tribler.core.utilities.slow_coro_detection(68) - Slow coroutine step execution (duration=2.625 seconds): <Task pending name='KnowledgeRulesProcessor:process_batch' coro=<interval_runner() running at ipv8\taskmanager.py:19> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x00000191F12F6370>()]> cb=[TaskManager.register_task.<locals>.done_cb() at ipv8\taskmanager.py:128]>
Stack for <Task pending name='KnowledgeRulesProcessor:process_batch' coro=<interval_runner() running at ipv8\taskmanager.py:19> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x00000191F12F6370>()]> cb=[TaskManager.register_task.<locals>.done_cb() at ipv8\taskmanager.py:128]> (most recent call last):
  File "ipv8\taskmanager.py", line 19, in interval_runner

[tribler-core PID:4752] 2023-05-02 13:31:24,947 - ERROR - tribler.core.utilities.slow_coro_detection(77) - Slow coroutine is occupying the loop for 1.048 seconds already: <Task pending name='Task-1522' coro=<RequestHandler._handle_request() running at aiohttp\web_protocol.py:433> cb=[<TaskWakeupMethWrapper object at 0x00000191F116EEE0>()]>
Stack for <Task pending name='Task-1522' coro=<RequestHandler._handle_request() running at aiohttp\web_protocol.py:433> cb=[<TaskWakeupMethWrapper object at 0x00000191F116EEE0>()]> (most recent call last):
  File "asyncio\events.py", line 81, in _run
  File "aiohttp\web_protocol.py", line 433, in _handle_request

The original log files are
tribler-core-info.log.1.txt
tribler-core-info.log.txt

@qstokkink
Copy link
Contributor

I did some research a few years ago on different ways to get rid of long blocking calls in asyncio: Tribler/py-ipv8#752 (comment)

@kozlovsky kozlovsky mentioned this issue May 12, 2023
Merged
@kozlovsky
Copy link
Contributor Author

In the attached logs, we can see that the Core process started the RESTManager, and the last log lines from the RESTManager are:

INFO - RESTManager(131) - Http enabled
Searching for a free port starting from 52194

It is possible that the bug was fixed by #7565, as now we do not search for a free port anymore. Let's close the bug for now and reopen it later if the error is reported again in Tribler >= 7.13.0

@kozlovsky kozlovsky mentioned this issue Aug 14, 2023
Closed
@synctext synctext mentioned this issue Sep 27, 2023
Open
@drew2a
Copy link
Contributor

drew2a commented Jan 5, 2024 •
edited
Loading

Occurred again:

EVENTS
125

USERS
0

image

Last core output:

[tribler-core PID:1704] 2024-01-05 10:03:39,679 - ERROR <watching_thread:96> tribler.core.utilities.slow_coro_detection._report_freeze(): Still executing <Task pending name='Task-9' coro=<Component.start() running at tribler\core\components\component.py:42> cb=[gather.<locals>._done_callback() at asyncio\tasks.py:751]>
Stack for <Task pending name='Task-9' coro=<Component.start() running at tribler\core\components\component.py:42> cb=[gather.<locals>._done_callback() at asyncio\tasks.py:751]> (most recent call last):
  File "asyncio\events.py", line 81, in _run
  File "tribler\core\components\component.py", line 42, in start[tribler-core PID:1704] 2024-01-05 10:03:40,679 - ERROR <watching_thread:96> tribler.core.utilities.slow_coro_detection._report_freeze(): Still executing <Task pending name='Task-9' coro=<Component.start() running at tribler\core\components\component.py:42> cb=[gather.<locals>._done_callback() at asyncio\tasks.py:751]>
Stack for <Task pending name='Task-9' coro=<Component.start() running at tribler\core\components\component.py:42> cb=[gather.<locals>._done_callback() at asyncio\tasks.py:751]> (most recent call last):
  File "asyncio\events.py", line 81, in _run
  File "tribler\core\components\component.py", line 42, in start[tribler-core PID:1704] 2024-01-05 10:03:41,679 - ERROR <watching_thread:96> tribler.core.utilities.slow_coro_detection._report_freeze(): Still executing <Task pending name='Task-9' coro=<Component.start() running at tribler\core\components\component.py:42> cb=[gather.<locals>._done_callback() at asyncio\tasks.py:751]>
Stack for <Task pending name='Task-9' coro=<Component.start() running at tribler\core\components\component.py:42> cb=[gather.<locals>._done_callback() at asyncio\tasks.py:751]> (most recent call last):
  File "asyncio\events.py", line 81, in _run
  File "tribler\core\components\component.py", line 42, in start[tribler-core PID:1704] 2024-01-05 10:03:42,679 - ERROR <watching_thread:96> tribler.core.utilities.slow_coro_detection._report_freeze(): Still executing <Task pending name='Task-9' coro=<Component.start() running at tribler\core\components\component.py:42> cb=[gather.<locals>._done_callback() at asyncio\tasks.py:751]>
Stack for <Task pending name='Task-9' coro=<Component.start() running at tribler\core\components\component.py:42> cb=[gather.<locals>._done_callback() at asyncio\tasks.py:751]> (most recent call last):
  File "asyncio\events.py", line 81, in _run
  File "tribler\core\components\component.py", line 42, in start[tribler-core PID:1704] 2024-01-05 10:03:43,679 - ERROR <watching_thread:96> tribler.core.utilities.slow_coro_detection._report_freeze(): Still executing <Task pending name='Task-9' coro=<Component.start() running at tribler\core\components\component.py:42> cb=[gather.<locals>._done_callback() at asyncio\tasks.py:751]>
Stack for <Task pending name='Task-9' coro=<Component.start() running at tribler\core\components\component.py:42> cb=[gather.<locals>._done_callback() at asyncio\tasks.py:751]> (most recent call last):
  File "asyncio\events.py", line 81, in _run
  File "tribler\core\components\component.py", line 42, in start[tribler-core PID:1704] 2024-01-05 10:03:44,679 - ERROR <watching_thread:96> tribler.core.utilities.slow_coro_detection._report_freeze(): Still executing <Task pending name='Task-9' coro=<Component.start() running at tribler\core\components\component.py:42> cb=[gather.<locals>._done_callback() at asyncio\tasks.py:751]>
Stack for <Task pending name='Task-9' coro=<Component.start() running at tribler\core\components\component.py:42> cb=[gather.<locals>._done_callback() at asyncio\tasks.py:751]> (most recent call last):
  File "asyncio\events.py", line 81, in _run
  File "tribler\core\components\component.py", line 42, in start[tribler-core PID:1704] 2024-01-05 10:03:45,679 - ERROR <watching_thread:96> tribler.core.utilities.slow_coro_detection._report_freeze(): Still executing <Task pending name='Task-9' coro=<Component.start() running at tribler\core\components\component.py:42> cb=[gather.<locals>._done_callback() at asyncio\tasks.py:751]>
Stack for <Task pending name='Task-9' coro=<Component.start() running at tribler\core\components\component.py:42> cb=[gather.<locals>._done_callback() at asyncio\tasks.py:751]> (most recent call last):
  File "asyncio\events.py", line 81, in _run
  File "tribler\core\components\component.py", line 42, in start[tribler-core PID:1704] 2024-01-05 10:03:46,679 - ERROR <watching_thread:96> tribler.core.utilities.slow_coro_detection._report_freeze(): Still executing <Task pending name='Task-9' coro=<Component.start() running at tribler\core\components\component.py:42> cb=[gather.<locals>._done_callback() at asyncio\tasks.py:751]>
Stack for <Task pending name='Task-9' coro=<Component.start() running at tribler\core\components\component.py:42> cb=[gather.<locals>._done_callback() at asyncio\tasks.py:751]> (most recent call last):
  File "asyncio\events.py", line 81, in _run
  File "tribler\core\components\component.py", line 42, in start[tribler-core PID:1704] 2024-01-05 10:03:47,679 - ERROR <watching_thread:96> tribler.core.utilities.slow_coro_detection._report_freeze(): Still executing <Task pending name='Task-9' coro=<Component.start() running at tribler\core\components\component.py:42> cb=[gather.<locals>._done_callback() at asyncio\tasks.py:751]>
Stack for <Task pending name='Task-9' coro=<Component.start() running at tribler\core\components\component.py:42> cb=[gather.<locals>._done_callback() at asyncio\tasks.py:751]> (most recent call last):
  File "asyncio\events.py", line 81, in _run
  File "tribler\core\components\component.py", line 42, in start[tribler-core PID:1704] 2024-01-05 10:03:48,679 - ERROR <watching_thread:96> tribler.core.utilities.slow_coro_detection._report_freeze(): Still executing <Task pending name='Task-9' coro=<Component.start() running at tribler\core\components\component.py:42> cb=[gather.<locals>._done_callback() at asyncio\tasks.py:751]>
Stack for <Task pending name='Task-9' coro=<Component.start() running at tribler\core\components\component.py:42> cb=[gather.<locals>._done_callback() at asyncio\tasks.py:751]> (most recent call last):
  File "asyncio\events.py", line 81, in _run
  File "tribler\core\components\component.py", line 42, in start

@drew2a drew2a reopened this Jan 5, 2024
@qstokkink
Copy link
Contributor

With the new web-based GUI implementation, this issue is no longer relevant and I will close it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@kozlovsky kozlovsky

Labels
type: blocker type: bug
Milestone
7.13.0
Development

No branches or pull requests
4 participants
@xoriole @kozlovsky @qstokkink @drew2a