blacklanternsecurity / bbot

A recursive internet scanner for hackers.
https://www.blacklanternsecurity.com/bbot/
GNU General Public License v3.0
4.71k stars 424 forks source link

Tests take a long time in 3.12 #1609

Open TheTechromancer opened 3 months ago

TheTechromancer commented 3 months ago

The 3.12 tests have started to misbehave again. The test_modules_basic_perdomainonly test is the culprit; it takes 20 minutes to complete.

2024-07-28T18:42:51.4914989Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:43:01.4942649Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:43:11.4968067Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:43:21.4988874Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:43:31.5015883Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:43:41.5040196Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:43:51.5061231Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:44:01.5083974Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:44:11.5112221Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:44:21.5138445Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:44:31.5161221Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:44:41.5187975Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:44:51.5213345Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:45:01.5237286Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:45:11.5260819Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:45:21.5286775Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:45:31.5311258Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:45:41.5338130Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:45:51.5356192Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:46:01.5383094Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:46:11.5396913Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:46:21.5432501Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:46:31.5451182Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:46:41.5472818Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:46:51.5497769Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:47:01.5521986Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:47:11.5535491Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:47:21.5552336Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:47:31.5564800Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:47:41.5578533Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:47:51.5596268Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:48:01.5611952Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:48:11.5637703Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:48:21.5649160Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:48:31.5663916Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:48:41.5690660Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:48:51.5705695Z DEBUG    bbot.core.webhelper:engine.py:69 EngineClient WebHelper: Timeout waiting for response for recv((), {}), retrying...
2024-07-28T18:48:55.4690437Z +++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++
2024-07-28T18:48:55.4691615Z ~~~~~~~~~~~~~~~~~~~~~ Stack of asyncio_5 (139954042693184) ~~~~~~~~~~~~~~~~~~~~~
2024-07-28T18:48:55.4693266Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1030, in _bootstrap
2024-07-28T18:48:55.4695516Z     self._bootstrap_inner()
2024-07-28T18:48:55.4696831Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1073, in _bootstrap_inner
2024-07-28T18:48:55.4697861Z     self.run()
2024-07-28T18:48:55.4698648Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1010, in run
2024-07-28T18:48:55.4699422Z     self._target(*self._args, **self._kwargs)
2024-07-28T18:48:55.4700527Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/concurrent/futures/thread.py", line 89, in _worker
2024-07-28T18:48:55.4701611Z     work_item = work_queue.get(block=True)
2024-07-28T18:48:55.4702381Z ~~~~~~~~~~~~~~~~~~~~~ Stack of asyncio_4 (139954059474496) ~~~~~~~~~~~~~~~~~~~~~
2024-07-28T18:48:55.4703683Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1030, in _bootstrap
2024-07-28T18:48:55.4704300Z     self._bootstrap_inner()
2024-07-28T18:48:55.4704900Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1073, in _bootstrap_inner
2024-07-28T18:48:55.4705496Z     self.run()
2024-07-28T18:48:55.4706134Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1010, in run
2024-07-28T18:48:55.4706760Z     self._target(*self._args, **self._kwargs)
2024-07-28T18:48:55.4707478Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/concurrent/futures/thread.py", line 89, in _worker
2024-07-28T18:48:55.4708294Z     work_item = work_queue.get(block=True)
2024-07-28T18:48:55.4708732Z ~~~~~~~~~~~~~~~~~~~~~ Stack of asyncio_3 (139954350970432) ~~~~~~~~~~~~~~~~~~~~~
2024-07-28T18:48:55.4709447Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1030, in _bootstrap
2024-07-28T18:48:55.4710044Z     self._bootstrap_inner()
2024-07-28T18:48:55.4710638Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1073, in _bootstrap_inner
2024-07-28T18:48:55.4711231Z     self.run()
2024-07-28T18:48:55.4711713Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1010, in run
2024-07-28T18:48:55.4712284Z     self._target(*self._args, **self._kwargs)
2024-07-28T18:48:55.4712965Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/concurrent/futures/thread.py", line 89, in _worker
2024-07-28T18:48:55.4713621Z     work_item = work_queue.get(block=True)
2024-07-28T18:48:55.4714046Z ~~~~~~~~~~~~~~~~~~~~~ Stack of asyncio_2 (139954378237504) ~~~~~~~~~~~~~~~~~~~~~
2024-07-28T18:48:55.4714827Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1030, in _bootstrap
2024-07-28T18:48:55.4715418Z     self._bootstrap_inner()
2024-07-28T18:48:55.4716006Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1073, in _bootstrap_inner
2024-07-28T18:48:55.4716594Z     self.run()
2024-07-28T18:48:55.4717062Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1010, in run
2024-07-28T18:48:55.4717636Z     self._target(*self._args, **self._kwargs)
2024-07-28T18:48:55.4718427Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/concurrent/futures/thread.py", line 89, in _worker
2024-07-28T18:48:55.4719454Z     work_item = work_queue.get(block=True)
2024-07-28T18:48:55.4719886Z ~~~~~~~~~~~~~~~~~~~~~ Stack of asyncio_1 (139954395018816) ~~~~~~~~~~~~~~~~~~~~~
2024-07-28T18:48:55.4720599Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1030, in _bootstrap
2024-07-28T18:48:55.4721185Z     self._bootstrap_inner()
2024-07-28T18:48:55.4721775Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1073, in _bootstrap_inner
2024-07-28T18:48:55.4722365Z     self.run()
2024-07-28T18:48:55.4722840Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1010, in run
2024-07-28T18:48:55.4723413Z     self._target(*self._args, **self._kwargs)
2024-07-28T18:48:55.4724080Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/concurrent/futures/thread.py", line 89, in _worker
2024-07-28T18:48:55.4724728Z     work_item = work_queue.get(block=True)
2024-07-28T18:48:55.4725160Z ~~~~~~~~~~~~~~~~~~~~~ Stack of asyncio_0 (139954633020992) ~~~~~~~~~~~~~~~~~~~~~
2024-07-28T18:48:55.4725856Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1030, in _bootstrap
2024-07-28T18:48:55.4726546Z     self._bootstrap_inner()
2024-07-28T18:48:55.4727138Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1073, in _bootstrap_inner
2024-07-28T18:48:55.4727731Z     self.run()
2024-07-28T18:48:55.4728201Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1010, in run
2024-07-28T18:48:55.4728772Z     self._target(*self._args, **self._kwargs)
2024-07-28T18:48:55.4729431Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/concurrent/futures/thread.py", line 89, in _worker
2024-07-28T18:48:55.4730326Z     work_item = work_queue.get(block=True)
2024-07-28T18:48:55.4730913Z ~~~~~~~~~~~~ Stack of Thread-83 (server_process) (139954709583424) ~~~~~~~~~~~~~
2024-07-28T18:48:55.4731759Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1030, in _bootstrap
2024-07-28T18:48:55.4732345Z     self._bootstrap_inner()
2024-07-28T18:48:55.4732941Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1073, in _bootstrap_inner
2024-07-28T18:48:55.4733535Z     self.run()
2024-07-28T18:48:55.4734074Z   File "/home/runner/work/bbot/bbot/bbot/core/helpers/process.py", line 27, in run
2024-07-28T18:48:55.4734586Z     super().run()
2024-07-28T18:48:55.4735076Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1010, in run
2024-07-28T18:48:55.4735652Z     self._target(*self._args, **self._kwargs)
2024-07-28T18:48:55.4736220Z   File "/home/runner/work/bbot/bbot/bbot/core/engine.py", line 279, in server_process
2024-07-28T18:48:55.4736739Z     future.result()
2024-07-28T18:48:55.4737322Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/concurrent/futures/_base.py", line 451, in result
2024-07-28T18:48:55.4738364Z     self._condition.wait(timeout)
2024-07-28T18:48:55.4739129Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 355, in wait
2024-07-28T18:48:55.4739898Z     waiter.acquire()
2024-07-28T18:48:55.4740392Z ~~~~~~~~~~~~~~~~~ Stack of QueueFeederThread (139955486975552) ~~~~~~~~~~~~~~~~~
2024-07-28T18:48:55.4741437Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1030, in _bootstrap
2024-07-28T18:48:55.4742595Z     self._bootstrap_inner()
2024-07-28T18:48:55.4743502Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1073, in _bootstrap_inner
2024-07-28T18:48:55.4744652Z     self.run()
2024-07-28T18:48:55.4745236Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1010, in run
2024-07-28T18:48:55.4745840Z     self._target(*self._args, **self._kwargs)
2024-07-28T18:48:55.4746520Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/multiprocessing/queues.py", line 251, in _feed
2024-07-28T18:48:55.4747131Z     nwait()
2024-07-28T18:48:55.4747623Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 355, in wait
2024-07-28T18:48:55.4748188Z     waiter.acquire()
2024-07-28T18:48:55.4748666Z ~~~~~~~~~~~~~~~~ Stack of Thread-1 (_monitor) (139955528554048) ~~~~~~~~~~~~~~~~
2024-07-28T18:48:55.4749401Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1030, in _bootstrap
2024-07-28T18:48:55.4749987Z     self._bootstrap_inner()
2024-07-28T18:48:55.4750578Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1073, in _bootstrap_inner
2024-07-28T18:48:55.4751173Z     self.run()
2024-07-28T18:48:55.4751646Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/threading.py", line 1010, in run
2024-07-28T18:48:55.4752225Z     self._target(*self._args, **self._kwargs)
2024-07-28T18:48:55.4752876Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/logging/handlers.py", line 1574, in _monitor
2024-07-28T18:48:55.4753494Z     record = self.dequeue(True)
2024-07-28T18:48:55.4754094Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/logging/handlers.py", line 1523, in dequeue
2024-07-28T18:48:55.4754835Z     return self.queue.get(block)
2024-07-28T18:48:55.4755442Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/multiprocessing/queues.py", line 103, in get
2024-07-28T18:48:55.4756052Z     res = self._recv_bytes()
2024-07-28T18:48:55.4756704Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/multiprocessing/connection.py", line 216, in recv_bytes
2024-07-28T18:48:55.4757376Z     buf = self._recv_bytes(maxlength)
2024-07-28T18:48:55.4758057Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/multiprocessing/connection.py", line 430, in _recv_bytes
2024-07-28T18:48:55.4758714Z     buf = self._recv(4)
2024-07-28T18:48:55.4759351Z   File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/multiprocessing/connection.py", line 395, in _recv
2024-07-28T18:48:55.4760002Z     chunk = read(handle, remaining)
2024-07-28T18:48:55.4760469Z +++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++
TheTechromancer commented 3 months ago

Added a debug message: 0726d96e

TheTechromancer commented 3 weeks ago

It's still unclear why this is happening; but it's not a big deal. Closing the issue for now.