search

blacklanternsecurity / bbot

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

Pytest sometimes fails to exit after tests have passed #1563

Closed TheTechromancer closed 1 month ago

TheTechromancer commented 1 month ago

After tests have passed, pytest sometimes fails to exit:

2024-07-16T00:58:54.0119865Z VERBOSE  bbot.core.httpengine:engine.py:399 Got shutdown signal, shutting down...
2024-07-16T00:58:54.1244609Z HUGESUCCESS bbot.scanner:scanner.py:1048 Scan testsubdomainenumlowestparent_test_063fkfrkz6 completed in 1 second with status FINISHED
2024-07-16T00:58:54.1258900Z -------------------------------- live log call ---------------------------------
2024-07-16T00:58:54.1260041Z INFO     bbot.test.subdomainenumlowestparent:base.py:117 Finished subdomainenumlowestparent module test
2024-07-16T00:58:59.5732394Z PASSED                                                                   [100%]
2024-07-16T00:58:59.5733139Z 
2024-07-16T00:58:59.5733393Z Test Session Summary:
2024-07-16T00:58:59.5733954Z Total tests run: 288
2024-07-16T00:58:59.5735151Z Passed: 288, Failed: 0, Skipped: 0, Errors: 0
2024-07-16T00:58:59.5735901Z 
2024-07-16T00:58:59.5736471Z ---------- coverage: platform linux, python 3.10.14-final-0 ----------
2024-07-16T00:58:59.5737244Z Coverage XML written to file cov.xml
2024-07-16T00:58:59.5737635Z 
2024-07-16T00:58:59.5737643Z 
2024-07-16T00:58:59.5738004Z ================ 288 passed, 16 warnings in 2105.73s (0:35:05) =================
2024-07-16T01:59:50.9542776Z ##[error]The operation was canceled.
2024-07-16T01:59:50.9624816Z Post job cleanup.
2024-07-16T01:59:51.0373010Z [command]/usr/bin/git version
2024-07-16T01:59:51.0409191Z git version 2.45.2
2024-07-16T01:59:51.0453157Z Temporarily overriding HOME='/home/runner/work/_temp/558d561e-0164-49ee-b40c-621635db4df7' before making global git config changes
2024-07-16T01:59:51.0455049Z Adding repository directory to the temporary git global config as a safe directory
2024-07-16T01:59:51.0457826Z [command]/usr/bin/git config --global --add safe.directory /home/runner/work/bbot/bbot
2024-07-16T01:59:51.0491045Z [command]/usr/bin/git config --local --name-only --get-regexp core\.sshCommand
2024-07-16T01:59:51.0521431Z [command]/usr/bin/git submodule foreach --recursive sh -c "git config --local --name-only --get-regexp 'core\.sshCommand' && git config --local --unset-all 'core.sshCommand' || :"
2024-07-16T01:59:51.0784917Z [command]/usr/bin/git config --local --name-only --get-regexp http\.https\:\/\/github\.com\/\.extraheader
2024-07-16T01:59:51.0807195Z http.https://github.com/.extraheader
2024-07-16T01:59:51.0818501Z [command]/usr/bin/git config --local --unset-all http.https://github.com/.extraheader
2024-07-16T01:59:51.0849304Z [command]/usr/bin/git submodule foreach --recursive sh -c "git config --local --name-only --get-regexp 'http\.https\:\/\/github\.com\/\.extraheader' && git config --local --unset-all 'http.https://github.com/.extraheader' || :"
2024-07-16T01:59:51.1325297Z Cleaning up orphan processes
2024-07-16T01:59:51.1574958Z Terminate orphan process: pid (1829) (pytest)
2024-07-16T01:59:51.1618416Z Terminate orphan process: pid (1835) (python)
TheTechromancer commented 1 month ago

Some possibly related issues:

TheTechromancer commented 1 month ago

Historically this has happened a lot with pytest, and there have been a lot of different culprits. It's impossible to say what the cause is, but it probably has something to do with the engine processes we're spawning.

TheTechromancer commented 1 month ago 
2024-07-16T21:47:35.8053534Z === Detailed Thread and Process Information ===
2024-07-16T21:47:35.8054061Z 
2024-07-16T21:47:35.8054222Z === Threads ===
2024-07-16T21:47:35.8054637Z Thread Name: MainThread
2024-07-16T21:47:35.8055109Z Thread ID: 140522262014848
2024-07-16T21:47:35.8055578Z Is Alive: True
2024-07-16T21:47:35.8055970Z Daemon: False
2024-07-16T21:47:35.8056363Z Target Function: None
2024-07-16T21:47:35.8056663Z 
2024-07-16T21:47:35.8056934Z Thread Name: Thread-1 (_monitor)
2024-07-16T21:47:35.8057461Z Thread ID: 140522208863808
2024-07-16T21:47:35.8057984Z Is Alive: True
2024-07-16T21:47:35.8058369Z Daemon: True
2024-07-16T21:47:35.8058939Z Target Function: logging.handlers.QueueListener._monitor
2024-07-16T21:47:35.8059645Z Arguments:
2024-07-16T21:47:35.8059870Z 
2024-07-16T21:47:35.8060162Z Thread Name: Thread-75 (server_process)
2024-07-16T21:47:35.8060749Z Thread ID: 140521766901312
2024-07-16T21:47:35.8061203Z Is Alive: True
2024-07-16T21:47:35.8061587Z Daemon: True
2024-07-16T21:47:35.8062191Z Target Function: bbot.core.engine.EngineClient.server_process
2024-07-16T21:47:35.8062937Z Arguments:
2024-07-16T21:47:35.8063830Z   server_class: <class 'bbot.core.helpers.dns.engine.DNSEngine'>
2024-07-16T21:47:35.8064661Z   socket_path: /tmp/zmq_3k202yp4.sock
2024-07-16T21:47:35.8065070Z 
2024-07-16T21:47:35.8065362Z Thread Name: Thread-76 (server_process)
2024-07-16T21:47:35.8065945Z Thread ID: 140521342211648
2024-07-16T21:47:35.8066407Z Is Alive: True
2024-07-16T21:47:35.8066792Z Daemon: True
2024-07-16T21:47:35.8067387Z Target Function: bbot.core.engine.EngineClient.server_process
2024-07-16T21:47:35.8068143Z Arguments:
2024-07-16T21:47:35.8068846Z   server_class: <class 'bbot.core.helpers.dns.engine.DNSEngine'>
2024-07-16T21:47:35.8069657Z   socket_path: /tmp/zmq_ck1jzkkm.sock
2024-07-16T21:47:35.8070071Z 
2024-07-16T21:47:35.8070355Z Thread Name: Thread-81 (server_process)
2024-07-16T21:47:35.8070949Z Thread ID: 140521291867712
2024-07-16T21:47:35.8071409Z Is Alive: True
2024-07-16T21:47:35.8071788Z Daemon: True
2024-07-16T21:47:35.8072404Z Target Function: bbot.core.engine.EngineClient.server_process
2024-07-16T21:47:35.8073154Z Arguments:
2024-07-16T21:47:35.8073848Z   server_class: <class 'bbot.core.helpers.dns.engine.DNSEngine'>
2024-07-16T21:47:35.8074645Z   socket_path: /tmp/zmq_16668snp.sock
2024-07-16T21:47:35.8075061Z 
2024-07-16T21:47:35.8075375Z Thread Name: Thread-102 (server_process)
2024-07-16T21:47:35.8075970Z Thread ID: 140521372624448
2024-07-16T21:47:35.8076431Z Is Alive: True
2024-07-16T21:47:35.8076809Z Daemon: True
2024-07-16T21:47:35.8077428Z Target Function: bbot.core.engine.EngineClient.server_process
2024-07-16T21:47:35.8078180Z Arguments:
2024-07-16T21:47:35.8079288Z   server_class: <class 'bbot.test.test_step_1.test_engine.test_engine.<locals>.TestEngineServer'>
2024-07-16T21:47:35.8080359Z   socket_path: /tmp/zmq_ynnr8pj1.sock
2024-07-16T21:47:35.8080930Z 
2024-07-16T21:47:35.8081232Z Thread Name: Thread-172 (server_process)
2024-07-16T21:47:35.8081828Z Thread ID: 140520525395520
2024-07-16T21:47:35.8082297Z Is Alive: True
2024-07-16T21:47:35.8082674Z Daemon: True
2024-07-16T21:47:35.8083285Z Target Function: bbot.core.engine.EngineClient.server_process
2024-07-16T21:47:35.8084042Z Arguments:
2024-07-16T21:47:35.8084758Z   server_class: <class 'bbot.core.helpers.web.engine.HTTPEngine'>
2024-07-16T21:47:35.8085576Z   socket_path: /tmp/zmq_wrvc0sy9.sock
2024-07-16T21:47:35.8085995Z 
2024-07-16T21:47:35.8086163Z Thread Name: asyncio_0
2024-07-16T21:47:35.8086611Z Thread ID: 140520777049664
2024-07-16T21:47:35.8087067Z Is Alive: True
2024-07-16T21:47:35.8087602Z Daemon: True
2024-07-16T21:47:35.8088125Z Target Function: concurrent.futures.thread._worker
2024-07-16T21:47:35.8088786Z Arguments:
2024-07-16T21:47:35.8089768Z   executor_reference: <weakref at 0x7fcdd5521b70; to 'ThreadPoolExecutor' at 0x7fcdc69a00d0>
2024-07-16T21:47:35.8090915Z   work_queue: <_queue.SimpleQueue object at 0x7fcdd5521800>
2024-07-16T21:47:35.8091643Z   initializer: None
2024-07-16T21:47:35.8092067Z   initargs: ()
2024-07-16T21:47:35.8092306Z 
2024-07-16T21:47:35.8092474Z Thread Name: asyncio_1
2024-07-16T21:47:35.8093130Z Thread ID: 140520508614208
2024-07-16T21:47:35.8093611Z Is Alive: True
2024-07-16T21:47:35.8094003Z Daemon: True
2024-07-16T21:47:35.8094552Z Target Function: concurrent.futures.thread._worker
2024-07-16T21:47:35.8095215Z Arguments:
2024-07-16T21:47:35.8096181Z   executor_reference: <weakref at 0x7fcdd4b8da30; to 'ThreadPoolExecutor' at 0x7fcdc69a00d0>
2024-07-16T21:47:35.8097330Z   work_queue: <_queue.SimpleQueue object at 0x7fcdd5521800>
2024-07-16T21:47:35.8098042Z   initializer: None
2024-07-16T21:47:35.8098461Z   initargs: ()
2024-07-16T21:47:35.8098706Z 
2024-07-16T21:47:35.8098881Z Thread Name: asyncio_2
2024-07-16T21:47:35.8099343Z Thread ID: 140520491832896
2024-07-16T21:47:35.8099795Z Is Alive: True
2024-07-16T21:47:35.8100177Z Daemon: True
2024-07-16T21:47:35.8100698Z Target Function: concurrent.futures.thread._worker
2024-07-16T21:47:35.8101349Z Arguments:
2024-07-16T21:47:35.8102220Z   executor_reference: <weakref at 0x7fcdd4baae80; to 'ThreadPoolExecutor' at 0x7fcdc69a00d0>
2024-07-16T21:47:35.8103353Z   work_queue: <_queue.SimpleQueue object at 0x7fcdd5521800>
2024-07-16T21:47:35.8104214Z   initializer: None
2024-07-16T21:47:35.8104665Z   initargs: ()
2024-07-16T21:47:35.8104923Z 
2024-07-16T21:47:35.8105255Z Thread Name: Thread-238 (server_process)
2024-07-16T21:47:35.8105881Z Thread ID: 140519636198976
2024-07-16T21:47:35.8106376Z Is Alive: True
2024-07-16T21:47:35.8106774Z Daemon: True
2024-07-16T21:47:35.8107371Z Target Function: bbot.core.engine.EngineClient.server_process
2024-07-16T21:47:35.8108047Z Arguments:
2024-07-16T21:47:35.8108685Z   server_class: <class 'bbot.core.helpers.web.engine.HTTPEngine'>
2024-07-16T21:47:35.8109392Z   socket_path: /tmp/zmq_gw6eagr0.sock
2024-07-16T21:47:35.8109742Z 
2024-07-16T21:47:35.8109996Z Thread Name: Thread-240 (server_process)
2024-07-16T21:47:35.8110527Z Thread ID: 140519519422016
2024-07-16T21:47:35.8110917Z Is Alive: True
2024-07-16T21:47:35.8111239Z Daemon: True
2024-07-16T21:47:35.8111763Z Target Function: bbot.core.engine.EngineClient.server_process
2024-07-16T21:47:35.8112411Z Arguments:
2024-07-16T21:47:35.8113021Z   server_class: <class 'bbot.core.helpers.web.engine.HTTPEngine'>
2024-07-16T21:47:35.8113732Z   socket_path: /tmp/zmq_g9e6m0ds.sock
2024-07-16T21:47:35.8114087Z 
2024-07-16T21:47:35.8114340Z Thread Name: Thread-241 (server_process)
2024-07-16T21:47:35.8114848Z Thread ID: 140519435515456
2024-07-16T21:47:35.8115238Z Is Alive: True
2024-07-16T21:47:35.8115565Z Daemon: True
2024-07-16T21:47:35.8116087Z Target Function: bbot.core.engine.EngineClient.server_process
2024-07-16T21:47:35.8116797Z Arguments:
2024-07-16T21:47:35.8117564Z   server_class: <class 'bbot.core.helpers.web.engine.HTTPEngine'>
2024-07-16T21:47:35.8118290Z   socket_path: /tmp/zmq_srd1z3da.sock
2024-07-16T21:47:35.8118781Z 
2024-07-16T21:47:35.8119069Z Thread Name: Thread-242 (server_process)
2024-07-16T21:47:35.8119668Z Thread ID: 140519283873344
2024-07-16T21:47:35.8120138Z Is Alive: True
2024-07-16T21:47:35.8120514Z Daemon: True
2024-07-16T21:47:35.8121126Z Target Function: bbot.core.engine.EngineClient.server_process
2024-07-16T21:47:35.8121888Z Arguments:
2024-07-16T21:47:35.8122601Z   server_class: <class 'bbot.core.helpers.web.engine.HTTPEngine'>
2024-07-16T21:47:35.8123420Z   socket_path: /tmp/zmq_es9juox9.sock
2024-07-16T21:47:35.8123824Z 
2024-07-16T21:47:35.8124133Z Thread Name: Thread-244 (server_process)
2024-07-16T21:47:35.8124728Z Thread ID: 140518830892608
2024-07-16T21:47:35.8125276Z Is Alive: True
2024-07-16T21:47:35.8125831Z Daemon: True
2024-07-16T21:47:35.8126440Z Target Function: bbot.core.engine.EngineClient.server_process
2024-07-16T21:47:35.8127187Z Arguments:
2024-07-16T21:47:35.8127928Z   server_class: <class 'bbot.core.helpers.web.engine.HTTPEngine'>
2024-07-16T21:47:35.8128758Z   socket_path: /tmp/zmq_gfr7bs9l.sock
2024-07-16T21:47:35.8129169Z 
2024-07-16T21:47:35.8129348Z Thread Name: asyncio_0
2024-07-16T21:47:35.8129803Z Thread ID: 140518663112256
2024-07-16T21:47:35.8130266Z Is Alive: True
2024-07-16T21:47:35.8130658Z Daemon: True
2024-07-16T21:47:35.8131174Z Target Function: concurrent.futures.thread._worker
2024-07-16T21:47:35.8131829Z Arguments:
2024-07-16T21:47:35.8132774Z   executor_reference: <weakref at 0x7fcdb0b0c040; to 'ThreadPoolExecutor' at 0x7fcdcda5df90>
2024-07-16T21:47:35.8134152Z   work_queue: <_queue.SimpleQueue object at 0x7fcdcff8db70>
2024-07-16T21:47:35.8134867Z   initializer: None
2024-07-16T21:47:35.8135288Z   initargs: ()
2024-07-16T21:47:35.8135540Z 
2024-07-16T21:47:35.8135872Z Thread Name: Thread-246 (server_process)
2024-07-16T21:47:35.8136474Z Thread ID: 140519652980288
2024-07-16T21:47:35.8136941Z Is Alive: True
2024-07-16T21:47:35.8137322Z Daemon: True
2024-07-16T21:47:35.8137940Z Target Function: bbot.core.engine.EngineClient.server_process
2024-07-16T21:47:35.8138701Z Arguments:
2024-07-16T21:47:35.8139453Z   server_class: <class 'bbot.core.helpers.web.engine.HTTPEngine'>
2024-07-16T21:47:35.8140291Z   socket_path: /tmp/zmq_ex4fbbq8.sock
2024-07-16T21:47:35.8140728Z 
2024-07-16T21:47:35.8141084Z Thread Name: Thread-249 (server_process)
2024-07-16T21:47:35.8141863Z Thread ID: 140518545643072
2024-07-16T21:47:35.8142371Z Is Alive: True
2024-07-16T21:47:35.8142770Z Daemon: True
2024-07-16T21:47:35.8143379Z Target Function: bbot.core.engine.EngineClient.server_process
2024-07-16T21:47:35.8144109Z Arguments:
2024-07-16T21:47:35.8144811Z   server_class: <class 'bbot.core.helpers.web.engine.HTTPEngine'>
2024-07-16T21:47:35.8145600Z   socket_path: /tmp/zmq_5rezw4kr.sock
2024-07-16T21:47:35.8145999Z 
2024-07-16T21:47:35.8146273Z Thread Name: Thread-252 (server_process)
2024-07-16T21:47:35.8146831Z Thread ID: 140518562424384
2024-07-16T21:47:35.8147264Z Is Alive: True
2024-07-16T21:47:35.8147631Z Daemon: True
2024-07-16T21:47:35.8148210Z Target Function: bbot.core.engine.EngineClient.server_process
2024-07-16T21:47:35.8148936Z Arguments:
2024-07-16T21:47:35.8149616Z   server_class: <class 'bbot.core.helpers.web.engine.HTTPEngine'>
2024-07-16T21:47:35.8150421Z   socket_path: /tmp/zmq_g2w7xha2.sock
2024-07-16T21:47:35.8150825Z 
2024-07-16T21:47:35.8151127Z Thread Name: Thread-253 (server_process)
2024-07-16T21:47:35.8151478Z Thread ID: 140518394611264
2024-07-16T21:47:35.8151736Z Is Alive: True
2024-07-16T21:47:35.8151956Z Daemon: True
2024-07-16T21:47:35.8152298Z Target Function: bbot.core.engine.EngineClient.server_process
2024-07-16T21:47:35.8152712Z Arguments:
2024-07-16T21:47:35.8153103Z   server_class: <class 'bbot.core.helpers.web.engine.HTTPEngine'>
2024-07-16T21:47:35.8153836Z   socket_path: /tmp/zmq_qqzjhn2d.sock
2024-07-16T21:47:35.8154067Z 
2024-07-16T21:47:35.8154244Z Thread Name: Thread-254 (server_process)
2024-07-16T21:47:35.8154713Z Thread ID: 140518579205696
2024-07-16T21:47:35.8154974Z Is Alive: True
2024-07-16T21:47:35.8155194Z Daemon: True
2024-07-16T21:47:35.8155609Z Target Function: bbot.core.engine.EngineClient.server_process
2024-07-16T21:47:35.8156017Z Arguments:
2024-07-16T21:47:35.8156416Z   server_class: <class 'bbot.core.helpers.web.engine.HTTPEngine'>
2024-07-16T21:47:35.8156871Z   socket_path: /tmp/zmq_pv23lxv4.sock
2024-07-16T21:47:35.8157097Z 
2024-07-16T21:47:35.8157243Z Thread Name: Thread-1524 (_serve)
2024-07-16T21:47:35.8157535Z Thread ID: 140519602636352
2024-07-16T21:47:35.8157791Z Is Alive: True
2024-07-16T21:47:35.8158055Z Daemon: True
2024-07-16T21:47:35.8158436Z Target Function: multiprocessing.resource_sharer._ResourceSharer._serve
2024-07-16T21:47:35.8158886Z Arguments:
2024-07-16T21:47:35.8159019Z 
2024-07-16T21:47:35.8159201Z === Processes ===
2024-07-16T21:47:35.8159441Z Process ID: 1830
2024-07-16T21:47:35.8159672Z Name: python
2024-07-16T21:47:35.8159879Z Status: sleeping
2024-07-16T21:47:35.8160352Z CPU Times: pcputimes(user=0.14, system=0.04, children_user=0.0, children_system=0.0, iowait=0.0)
2024-07-16T21:47:35.8161150Z Memory Info: pmem(rss=22638592, vms=30322688, shared=10616832, text=4096, lib=0, data=12746752, dirty=0)
2024-07-16T21:47:35.8161618Z 
2024-07-16T21:47:35.8161721Z === Current Process ===
2024-07-16T21:47:35.8161973Z Process ID: 1825
2024-07-16T21:47:35.8162197Z Name: pytest
2024-07-16T21:47:35.8162404Z Status: running
2024-07-16T21:47:35.8162895Z CPU Times: pcputimes(user=779.69, system=20.95, children_user=517.15, children_system=97.27, iowait=0.0)
2024-07-16T21:47:35.8163717Z Memory Info: pmem(rss=734044160, vms=3791843328, shared=51773440, text=4096, lib=0, data=1730809856, dirty=0)
2024-07-16T21:47:35.8164201Z
TheTechromancer commented 1 month ago

Sometimes tests halt before finishing:

2024-07-17T02:12:23.2766804Z INFO     bbot.scanner:scanner.py:1033 Loaded 16/16 output modules, (asset_inventory,csv,discord,emails,http,json,neo4j,python,slack,splunk,stdout,subdomains,teams,txt,web_report,websocket)
2024-07-17T02:12:23.3088191Z WARNING  asyncio:base_events.py:1900 Executing <Task finished name='Task-5409' coro=<test_module_loading() done, defined at /home/runner/work/bbot/bbot/bbot/test/test_step_1/test_modules_basic.py:425> result=None created at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:900> took 21.029 seconds
2024-07-17T02:12:23.3091890Z DEBUG    bbot.scanner:scanner.py:1018 Setting scan status to RUNNING
2024-07-17T02:12:23.3096777Z [INFO] Loaded 16/16 output modules, (asset_inventory,csv,discord,emails,http,json,neo4j,python,slack,splunk,stdout,subdomains,teams,txt,web_report,websocket)
2024-07-17T02:12:23.3154244Z [WARN] Executing <Task finished name='Task-5409' coro=<test_module_loading() done, defined at /home/runner/work/bbot/bbot/bbot/test/test_step_1/test_modules_basic.py:425> result=None created at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:900> took 21.029 seconds
2024-07-17T02:12:23.4105956Z PASSED                                                                   [ 14%]
2024-07-17T02:12:26.6484543Z bbot/test/test_step_1/test_presets.py::test_preset_descriptions PASSED   [ 14%]
2024-07-17T02:12:27.5524804Z bbot/test/test_step_1/test_presets.py::test_core PASSED                  [ 14%]
2024-07-17T02:12:29.8915533Z bbot/test/test_step_1/test_presets.py::test_preset_yaml PASSED           [ 15%]
2024-07-17T02:12:30.0617453Z bbot/test/test_step_1/test_presets.py::test_preset_cache PASSED          [ 15%]
2024-07-17T02:25:31.5085918Z ##[error]The operation was canceled.
2024-07-17T02:25:31.5174324Z Post job cleanup.
2024-07-17T02:25:31.5940152Z [command]/usr/bin/git version
2024-07-17T02:25:31.5979791Z git version 2.45.2
2024-07-17T02:25:31.6182035Z Temporarily overriding HOME='/home/runner/work/_temp/e0527829-521f-40fe-b888-81af7606adcd' before making global git config changes
2024-07-17T02:25:31.6184270Z Adding repository directory to the temporary git global config as a safe directory
2024-07-17T02:25:31.6186411Z [command]/usr/bin/git config --global --add safe.directory /home/runner/work/bbot/bbot
2024-07-17T02:25:31.6189687Z [command]/usr/bin/git config --local --name-only --get-regexp core\.sshCommand
2024-07-17T02:25:31.6193479Z [command]/usr/bin/git submodule foreach --recursive sh -c "git config --local --name-only --get-regexp 'core\.sshCommand' && git config --local --unset-all 'core.sshCommand' || :"
2024-07-17T02:25:31.6386837Z [command]/usr/bin/git config --local --name-only --get-regexp http\.https\:\/\/github\.com\/\.extraheader
2024-07-17T02:25:31.6413212Z http.https://github.com/.extraheader
2024-07-17T02:25:31.6427067Z [command]/usr/bin/git config --local --unset-all http.https://github.com/.extraheader
2024-07-17T02:25:31.6470223Z [command]/usr/bin/git submodule foreach --recursive sh -c "git config --local --name-only --get-regexp 'http\.https\:\/\/github\.com\/\.extraheader' && git config --local --unset-all 'http.https://github.com/.extraheader' || :"
2024-07-17T02:25:31.7065837Z Cleaning up orphan processes
2024-07-17T02:25:31.7531091Z Terminate orphan process: pid (1820) (pytest)
2024-07-17T02:25:31.7581260Z Terminate orphan process: pid (1825) (python)
2024-07-17T03:23:30.9441180Z [VERB] Completed finish()
2024-07-17T03:23:31.0457963Z VERBOSE  bbot.scanner:scanner.py:1023 Completed final finish()
2024-07-17T03:23:31.0566530Z DEBUG    httpx:_config.py:78 load_ssl_context verify=<ssl.SSLContext object at 0x7f6dc080b3c0> cert=None trust_env=True http2=False
2024-07-17T03:23:31.0666183Z HUGESUCCESS bbot.scanner:scanner.py:1048 Scan testbaddns_cname_nxdomain_test_3ckvfdseyi completed in 0 seconds with status FINISHED
2024-07-17T03:23:31.0684992Z -------------------------------- live log call ---------------------------------
2024-07-17T03:23:31.0686258Z [INFO] Finished baddns_cname_nxdomain module test
2024-07-17T03:23:31.0687445Z INFO     bbot.test.baddns_cname_nxdomain:base.py:117 Finished baddns_cname_nxdomain module test
2024-07-17T03:23:31.5540846Z PASSED                                                                   [ 30%]
2024-07-17T03:23:32.5613575Z bbot/test/test_step_2/module_tests/test_module_baddns.py::TestBaddns_cname_signature::test_module_run 
2024-07-17T03:23:32.5615141Z -------------------------------- live log setup --------------------------------
2024-07-17T03:23:32.5615938Z VERBOSE  bbot.core.target:target.py:29 Creating events from 1 targets
2024-07-17T03:23:32.5651127Z WARNING  bbot.scanner:scanner.py:1053 You have enabled custom HTTP headers. These will be attached to all in-scope requests and all requests made by httpx.
2024-07-17T03:23:32.5660165Z INFO     bbot.test.baddns_cname_signature:base.py:106 Starting baddns_cname_signature module test
2024-07-17T03:23:33.0579471Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-7385' coro=<_wrap_asyncgen_fixture.<locals>._asyncgen_fixture_wrapper.<locals>.setup() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:326> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f6dc8acac10>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:626> took 1.498 seconds
2024-07-17T03:28:16.5669834Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-7385' coro=<_wrap_asyncgen_fixture.<locals>._asyncgen_fixture_wrapper.<locals>.setup() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:326> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f6da396e610>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:626> took 0.103 seconds
2024-07-17T03:42:36.4656050Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-7385' coro=<_wrap_asyncgen_fixture.<locals>._asyncgen_fixture_wrapper.<locals>.setup() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:326> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f6da396e610>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:626> took 0.103 seconds
2024-07-17T03:53:14.5309278Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-7385' coro=<_wrap_asyncgen_fixture.<locals>._asyncgen_fixture_wrapper.<locals>.setup() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:326> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f6da396e7c0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:626> took 0.108 seconds
2024-07-17T04:14:43.6799373Z ##[error]The operation was canceled.
2024-07-17T10:45:12.8090716Z -------------------------------- live log call ---------------------------------
2024-07-17T10:45:12.8091651Z INFO     bbot.test.url_manipulation:base.py:117 Finished url_manipulation module test
2024-07-17T10:45:12.8092752Z [INFO] Finished url_manipulation module test
2024-07-17T10:45:13.1608858Z PASSED                                                                   [ 94%]
2024-07-17T10:45:14.1623268Z bbot/test/test_step_2/module_tests/test_module_urlscan.py::TestUrlScan::test_module_run 
2024-07-17T10:45:14.1624427Z -------------------------------- live log setup --------------------------------
2024-07-17T10:45:14.1625646Z VERBOSE  bbot.core.target:target.py:29 Creating events from 1 targets
2024-07-17T10:45:14.1666813Z WARNING  bbot.scanner:scanner.py:1053 You have enabled custom HTTP headers. These will be attached to all in-scope requests and all requests made by httpx.
2024-07-17T10:45:14.1675150Z INFO     bbot.test.urlscan:base.py:106 Starting urlscan module test
2024-07-17T10:45:14.8369393Z [WARN] Executing <Task pending name='Task-21309' coro=<_wrap_asyncgen_fixture.<locals>._asyncgen_fixture_wrapper.<locals>.setup() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:326> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f32d3ef15e0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:626> took 1.133 seconds
2024-07-17T10:45:14.8379285Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-21309' coro=<_wrap_asyncgen_fixture.<locals>._asyncgen_fixture_wrapper.<locals>.setup() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:326> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f32d3ef15e0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:626> took 1.133 seconds
2024-07-17T10:45:35.2278792Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-21309' coro=<_wrap_asyncgen_fixture.<locals>._asyncgen_fixture_wrapper.<locals>.setup() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:326> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f32d30d97c0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:626> took 0.108 seconds
2024-07-17T10:45:55.5801238Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-21309' coro=<_wrap_asyncgen_fixture.<locals>._asyncgen_fixture_wrapper.<locals>.setup() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:326> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f32d30d97c0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:626> took 0.103 seconds
2024-07-17T10:47:37.0891482Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-21309' coro=<_wrap_asyncgen_fixture.<locals>._asyncgen_fixture_wrapper.<locals>.setup() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:326> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f32d30d94f0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:626> took 0.128 seconds
2024-07-17T10:48:48.1437367Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-21309' coro=<_wrap_asyncgen_fixture.<locals>._asyncgen_fixture_wrapper.<locals>.setup() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:326> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f32d30d95e0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:626> took 0.103 seconds
2024-07-17T10:54:12.4900165Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-21309' coro=<_wrap_asyncgen_fixture.<locals>._asyncgen_fixture_wrapper.<locals>.setup() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:326> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f32d30d93a0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:626> took 0.103 seconds
2024-07-17T11:06:41.9322260Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-21309' coro=<_wrap_asyncgen_fixture.<locals>._asyncgen_fixture_wrapper.<locals>.setup() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:326> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f32d30d95b0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:626> took 0.108 seconds
2024-07-17T11:08:41.5270672Z ##[error]The operation was canceled.
2024-07-17T11:07:02.3968257Z DEBUG    bbot.modules.emailformat:base.py:1234 Finished setting up module emailformat
2024-07-17T11:07:02.4072078Z [WARN] Executing <Task pending name='Task-5369' coro=<BaseModule._setup() running at /home/runner/work/bbot/bbot/bbot/modules/base.py:563> wait_for=<Future pending cb=[Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/asyncio/base_events.py:429> cb=[_wait.<locals>._on_completion() at /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/asyncio/tasks.py:475] created at /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/asyncio/tasks.py:337> took 223.716 seconds
2024-07-17T11:07:02.4330669Z DEBUG    bbot.modules.ffuf:base.py:1234 Setting up module ffuf
2024-07-17T11:07:02.4335925Z DEBUG    bbot.modules.ffuf:base.py:1234 Using wordlist [https://raw.githubusercontent.com/danielmiessler/SecLists/master/Discovery/Web-Content/raft-small-directories.txt]
2024-07-17T11:07:02.5127825Z DEBUG    bbot.modules.ffuf_shortnames:base.py:1234 Setting up module ffuf_shortnames
2024-07-17T11:07:02.5133992Z DEBUG    bbot.modules.ffuf_shortnames:base.py:1234 Using [/home/runner/work/bbot/bbot/bbot/wordlists/ffuf_shortname_candidates.txt] for shortname candidate list
2024-07-17T11:07:02.9773533Z DEBUG    bbot.modules.ffuf_shortnames:base.py:1234 Using [/home/runner/work/bbot/bbot/bbot/wordlists/raft-small-extensions-lowercase_CLEANED.txt] for shortname candidate extension list
2024-07-17T11:07:03.0190473Z DEBUG    bbot.modules.ffuf_shortnames:base.py:1234 Using custom extensions: []
2024-07-17T11:07:03.0246289Z DEBUG    bbot.modules.ffuf_shortnames:base.py:1234 Finished setting up module ffuf_shortnames
2024-07-17T11:07:03.0253067Z WARNING  asyncio:base_events.py:1904 Executing <Task finished name='Task-5372' coro=<BaseModule._setup() done, defined at /home/runner/work/bbot/bbot/bbot/modules/base.py:536> result=(<bbot.modules...x7f73fac48d00>, True, 'success') created at /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/asyncio/tasks.py:337> took 0.512 seconds
2024-07-17T11:07:03.0255833Z DEBUG    bbot.modules.filedownload:base.py:1234 Setting up module filedownload
2024-07-17T11:07:03.3571340Z WARNING  asyncio:base_events.py:1904 Executing <Task pending name='Task-5373' coro=<BaseModule._setup() running at /home/runner/work/bbot/bbot/bbot/modules/base.py:563> wait_for=<Future pending cb=[Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/asyncio/base_events.py:429> cb=[_wait.<locals>._on_completion() at /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/asyncio/tasks.py:475] created at /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/asyncio/tasks.py:337> took 0.331 seconds
2024-07-17T11:07:03.3574204Z DEBUG    bbot.modules.fullhunt:base.py:1234 Setting up module fullhunt
2024-07-17T11:07:03.3577152Z DEBUG    bbot.modules.fullhunt:base.py:1234 Finished setting up module fullhunt
2024-07-17T11:07:03.3940200Z DEBUG    bbot.modules.generic_ssrf:base.py:1234 Setting up module generic_ssrf
2024-07-17T11:08:41.3719427Z ##[error]The operation was canceled.
2024-07-17T21:30:40.0849933Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='_scan_ingress._worker()' coro=<InterceptModule._worker() running at /home/runner/work/bbot/bbot/bbot/modules/base.py:1447> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7243e8d670>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361> took 0.103 seconds
2024-07-17T21:30:40.3876255Z WARNING  asyncio:base_events.py:1900 Executing <TimerHandle when=4623.256047395001 _set_result_unless_cancelled(<Future finis...events.py:429>, None) at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/futures.py:308 created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:648> took 0.128 seconds
2024-07-17T21:30:40.8947868Z WARNING  asyncio:base_events.py:1900 Executing <TimerHandle when=4623.658268904001 _set_result_unless_cancelled(<Future finis...events.py:429>, None) at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/futures.py:308 created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:648> took 0.265 seconds
2024-07-17T21:30:41.1877473Z WARNING  asyncio:base_events.py:1900 Executing <TimerHandle when=4624.123275986 _set_result_unless_cancelled(<Future finis...events.py:429>, None) at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/futures.py:308 created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:648> took 0.133 seconds
2024-07-17T21:30:41.1929768Z [WARN] Executing <TimerHandle when=4624.123275986 _set_result_unless_cancelled(<Future finis...events.py:429>, None) at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/futures.py:308 created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:648> took 0.133 seconds
2024-07-17T21:30:41.3490033Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-5563' coro=<test_python_api() running at /home/runner/work/bbot/bbot/bbot/test/test_step_1/test_python_api.py:16> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7243e8d970>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:900> took 0.113 seconds
2024-07-17T21:30:41.4262913Z INFO     bbot.scanner:scanner.py:1033 python_api_test: Modules running (incoming:processing:outgoing) dnsresolve(0:1:0)
2024-07-17T21:30:41.4265033Z INFO     bbot.scanner:scanner.py:1033 python_api_test: Events produced so far: SCAN: 1
2024-07-17T21:30:41.4269157Z INFO     bbot.scanner:scanner.py:1033 python_api_test: No events in queue (5 processed in the past minute)
2024-07-17T21:30:41.7826266Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-5563' coro=<test_python_api() running at /home/runner/work/bbot/bbot/bbot/test/test_step_1/test_python_api.py:16> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7246ac09a0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:900> took 0.235 seconds
2024-07-17T21:30:42.3559722Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-5563' coro=<test_python_api() running at /home/runner/work/bbot/bbot/bbot/test/test_step_1/test_python_api.py:16> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7243e8d310>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:900> took 0.449 seconds
2024-07-17T21:30:42.6694733Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='_scan_ingress._worker()' coro=<InterceptModule._worker() running at /home/runner/work/bbot/bbot/bbot/modules/base.py:1447> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7243e8d310>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361> took 0.113 seconds
2024-07-17T21:30:43.1202900Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='_scan_ingress._worker()' coro=<InterceptModule._worker() running at /home/runner/work/bbot/bbot/bbot/modules/base.py:1447> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7243e8dd30>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361> took 0.108 seconds
2024-07-17T21:30:43.4016493Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-5563' coro=<test_python_api() running at /home/runner/work/bbot/bbot/bbot/test/test_step_1/test_python_api.py:16> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f723ba4f0a0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:900> took 0.281 seconds
2024-07-17T21:30:44.2165550Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-5563' coro=<test_python_api() running at /home/runner/work/bbot/bbot/bbot/test/test_step_1/test_python_api.py:16> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7243e8d940>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:900> took 0.353 seconds
2024-07-17T21:30:44.5965372Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-5563' coro=<test_python_api() running at /home/runner/work/bbot/bbot/bbot/test/test_step_1/test_python_api.py:16> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7243e8d490>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:900> took 0.138 seconds
2024-07-17T21:30:45.2123450Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='_scan_ingress._worker()' coro=<InterceptModule._worker() running at /home/runner/work/bbot/bbot/bbot/modules/base.py:1447> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7243e8d760>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361> took 0.103 seconds
2024-07-17T21:30:45.3301493Z WARNING  asyncio:base_events.py:1900 Executing <TimerHandle when=4628.231724308001 _set_result_unless_cancelled(<Future finis...events.py:429>, None) at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/futures.py:308 created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:648> took 0.112 seconds
2024-07-17T21:30:45.5609949Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-5563' coro=<test_python_api() running at /home/runner/work/bbot/bbot/bbot/test/test_step_1/test_python_api.py:16> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7243e8d9a0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:900> took 0.230 seconds
2024-07-17T21:30:45.9034671Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='_scan_ingress._worker()' coro=<InterceptModule._worker() running at /home/runner/work/bbot/bbot/bbot/modules/base.py:1447> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7239bb9ee0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361> took 0.281 seconds
2024-07-17T21:30:46.3085008Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='_scan_ingress._worker()' coro=<InterceptModule._worker() running at /home/runner/work/bbot/bbot/bbot/modules/base.py:1447> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7243e8d9a0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361> took 0.225 seconds
2024-07-17T21:30:46.4492658Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='_scan_ingress._worker()' coro=<InterceptModule._worker() running at /home/runner/work/bbot/bbot/bbot/modules/base.py:1447> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f723ba4f0a0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361> took 0.108 seconds
2024-07-17T21:30:47.1380622Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-5563' coro=<test_python_api() running at /home/runner/work/bbot/bbot/bbot/test/test_step_1/test_python_api.py:16> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f723ba4f040>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:900> took 0.439 seconds
2024-07-17T21:30:47.1436723Z [WARN] Executing <Task pending name='Task-5563' coro=<test_python_api() running at /home/runner/work/bbot/bbot/bbot/test/test_step_1/test_python_api.py:16> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f723ba4f040>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:900> took 0.439 seconds
2024-07-17T21:30:47.5589455Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-5563' coro=<test_python_api() running at /home/runner/work/bbot/bbot/bbot/test/test_step_1/test_python_api.py:16> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7243e8d520>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:900> took 0.286 seconds
2024-07-17T21:30:48.1997464Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='_scan_ingress._worker()' coro=<InterceptModule._worker() running at /home/runner/work/bbot/bbot/bbot/modules/base.py:1447> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7243e8d5e0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361> took 0.454 seconds
2024-07-17T21:30:48.7496686Z WARNING  asyncio:base_events.py:1900 Executing <TimerHandle when=4631.619100469 _set_result_unless_cancelled(<Future finis...events.py:429>, None) at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/futures.py:308 created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:648> took 0.117 seconds
2024-07-17T21:30:49.2184307Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='_scan_ingress._worker()' coro=<InterceptModule._worker() running at /home/runner/work/bbot/bbot/bbot/modules/base.py:1447> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7243e8dfd0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361> took 0.179 seconds
2024-07-17T21:30:49.7458487Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='dnsresolve._worker()' coro=<InterceptModule._worker() running at /home/runner/work/bbot/bbot/bbot/modules/base.py:1480> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f723ba4f070>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361> took 0.113 seconds
2024-07-17T21:30:49.8907791Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='_scan_ingress._worker()' coro=<InterceptModule._worker() running at /home/runner/work/bbot/bbot/bbot/modules/base.py:1447> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f72565be8b0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361> took 0.102 seconds
2024-07-17T21:30:50.1843923Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-5563' coro=<test_python_api() running at /home/runner/work/bbot/bbot/bbot/test/test_step_1/test_python_api.py:16> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7243e8d7f0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:900> took 0.103 seconds
2024-07-17T21:30:50.5350153Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-5563' coro=<test_python_api() running at /home/runner/work/bbot/bbot/bbot/test/test_step_1/test_python_api.py:16> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f723ba4f880>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:900> took 0.133 seconds
2024-07-17T21:30:51.0134413Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-5563' coro=<test_python_api() running at /home/runner/work/bbot/bbot/bbot/test/test_step_1/test_python_api.py:16> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7240e15040>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:900> took 0.179 seconds
2024-07-17T21:30:52.5047573Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-5563' coro=<test_python_api() running at /home/runner/work/bbot/bbot/bbot/test/test_step_1/test_python_api.py:16> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7239bb9d60>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:900> took 0.118 seconds
2024-07-17T21:30:52.9205458Z WARNING  asyncio:base_events.py:1900 Executing <TimerHandle when=4635.780254086 _set_result_unless_cancelled(<Future finis...events.py:429>, None) at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/futures.py:308 created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:648> took 0.168 seconds
2024-07-17T21:30:53.4477116Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='_scan_ingress._worker()' coro=<InterceptModule._worker() running at /home/runner/work/bbot/bbot/bbot/modules/base.py:1447> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7243e8d5e0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361> took 0.480 seconds
2024-07-17T21:30:53.9250754Z WARNING  asyncio:base_events.py:1900 Executing <TimerHandle when=4636.896712746 _set_result_unless_cancelled(<Future finis...events.py:429>, None) at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/futures.py:308 created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:648> took 0.112 seconds
2024-07-17T21:30:54.1203388Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='_scan_ingress._worker()' coro=<InterceptModule._worker() running at /home/runner/work/bbot/bbot/bbot/modules/base.py:1447> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f723ba4f880>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361> took 0.189 seconds
2024-07-17T21:30:54.3206895Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-5563' coro=<test_python_api() running at /home/runner/work/bbot/bbot/bbot/test/test_step_1/test_python_api.py:16> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f723ba4f0a0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:900> took 0.138 seconds
2024-07-17T21:30:54.9519881Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='_scan_ingress._worker()' coro=<InterceptModule._worker() running at /home/runner/work/bbot/bbot/bbot/modules/base.py:1447> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7243e8d4c0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361> took 0.138 seconds
2024-07-17T21:30:55.1315552Z WARNING  asyncio:base_events.py:1900 Executing <TimerHandle when=4638.1181918560005 _set_result_unless_cancelled(<Future finis...events.py:429>, None) at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/futures.py:308 created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:648> took 0.102 seconds
2024-07-17T21:30:55.3315831Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='_scan_ingress._worker()' coro=<InterceptModule._worker() running at /home/runner/work/bbot/bbot/bbot/modules/base.py:1447> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f723ba4f040>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361> took 0.199 seconds
2024-07-17T21:30:55.9020938Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-5563' coro=<test_python_api() running at /home/runner/work/bbot/bbot/bbot/test/test_step_1/test_python_api.py:16> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f7243e8d460>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:900> took 0.261 seconds
2024-07-17T21:30:56.1585017Z WARNING  asyncio:base_events.py:1900 Executing <TimerHandle when=4638.930590048 _set_result_unless_cancelled(<Future finis...events.py:429>, None) at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/futures.py:308 created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:648> took 0.163 seconds
2024-07-17T21:30:56.3688356Z WARNING  asyncio:base_events.py:1900 Executing <TimerHandle when=4639.18170808 _set_result_unless_cancelled(<Future finis...events.py:429>, None) at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/futures.py:308 created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:648> took 0.173 seconds
2024-07-17T21:30:56.5078267Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='_scan_ingress._worker()' coro=<InterceptModule._worker() running at /home/runner/work/bbot/bbot/bbot/modules/base.py:1447> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f72457e9fd0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361> took 0.139 seconds
2024-07-17T21:30:56.7947198Z WARNING  asyncio:base_events.py:1900 Executing <Task pending name='Task-5563' coro=<test_python_api() running at /home/runner/work/bbot/bbot/bbot/test/test_step_1/test_python_api.py:16> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f72457e9400>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:184] created at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/pytest_asyncio/plugin.py:900> took 0.250 seconds
2024-07-17T21:30:56.8618336Z INFO     bbot.scanner:scanner.py:1033 python_api_test: Modules running (incoming:processing:outgoing) dnsresolve(0:1:0)
2024-07-17T21:30:56.8620956Z INFO     bbot.scanner:scanner.py:1033 python_api_test: Events produced so far: SCAN: 1
2024-07-17T21:30:56.8624624Z INFO     bbot.scanner:scanner.py:1033 python_api_test: No events in queue (5 processed in the past minute)
TheTechromancer commented 1 month ago

Tests where it froze:

What do these have in common?

TheTechromancer commented 1 month ago

After unifying the threads into a single event loop, the bug seems worse. All 4 tests stalled before completion:

3.9

HUGESUCCESS bbot.scanner:scanner.py:1048 Scan testntlm_test_zq98i47k8r completed in 2 seconds with status FINISHED
[SUCC] Scan testntlm_test_zq98i47k8r completed in 2 seconds with status FINISHED
DEBUG    httpcore.connection:_trace.py:85 connect_tcp.started host='127.0.0.1' port=8888 local_address=None timeout=10 socket_options=None
DEBUG    httpcore.connection:_trace.py:85 connect_tcp.complete return_value=<httpcore._backends.anyio.AnyIOStream object at 0x7f312c86ec70>
DEBUG    httpcore.http11:_trace.py:85 response_closed.complete
DEBUG    httpcore.http11:_trace.py:85 receive_response_headers.complete return_value=(b'HTTP/1.0', 500, b'INTERNAL SERVER ERROR', [(b'Server', b'Werkzeug/3.0.3 Python/3.9.19'), (b'Date', b'Thu, 18 Jul 2024 21:39:16 GMT'), (b'Content-Type', b'text/plain; charset=utf-8'), (b'Content-Length', b'486'), (b'Connection', b'close')])
INFO     httpx:_client.py:1758 HTTP Request: GET http://127.0.0.1:8888/meeting/ "HTTP/1.0 500 INTERNAL SERVER ERROR"
DEBUG    httpcore.http11:_trace.py:85 receive_response_body.started request=<Request [b'GET']>
DEBUG    httpcore.http11:_trace.py:85 receive_response_body.complete
DEBUG    httpcore.http11:_trace.py:85 response_closed.started
[INFO] HTTP Request: GET http://127.0.0.1:8888/meeting/ "HTTP/1.0 500 INTERNAL SERVER ERROR"
-------------------------------- live log call ---------------------------------
DEBUG    httpcore.http11:_trace.py:85 send_request_headers.started request=<Request [b'GET']>
DEBUG    httpcore.connection:_trace.py:85 connect_tcp.started host='127.0.0.1' port=8888 local_address=None timeout=10 socket_options=None
INFO     bbot.test.ntlm:base.py:123 Finished ntlm module test
INFO     bbot.test.ntlm:base.py:127 Unfinished tasks detected: [<Task pending name='Task-15739' coro=<HTTPEngine.request() running at /home/runner/work/bbot/bbot/bbot/core/helpers/web/engine.py:79> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f3101081cd0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_wait.<locals>._on_completion() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:509] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361>, <Task pending name='Task-15727' coro=<HTTPEngine.request() running at /home/runner/work/bbot/bbot/bbot/core/helpers/web/engine.py:79> cb=[_wait.<locals>._on_completion() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:509] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361>, <Task pending name='Task-15636' coro=<EngineServer.worker() running at /home/runner/work/bbot/bbot/bbot/core/engine.py:411> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f3137e80a60>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_chain_future.<locals>._call_set_state() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/futures.py:391] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:927>, <Task pending name='Task-15731' coro=<HTTPEngine.request() running at /home/runner/work/bbot/bbot/bbot/core/helpers/web/engine.py:79> wait_for=<Future finished result=None created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_wait.<locals>._on_completion() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:509] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361>, <Task pending name='Task-15742' coro=<HTTPEngine.request() running at /home/runner/work/bbot/bbot/bbot/core/helpers/web/engine.py:44> cb=[_wait.<locals>._on_completion() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:509] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361>, <Task pending name='Task-15733' coro=<HTTPEngine.request() running at /home/runner/work/bbot/bbot/bbot/core/helpers/web/engine.py:79> wait_for=<Future cancelled created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_wait.<locals>._on_completion() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:509] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361>, <Task pending name='Task-15736' coro=<HTTPEngine.request() running at /home/runner/work/bbot/bbot/bbot/core/helpers/web/engine.py:79> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f30f88a3e20>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_wait.<locals>._on_completion() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:509] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361>, <Task pending name='anyio._core._sockets.connect_tcp.<locals>.try_connect' coro=<connect_tcp.<locals>.try_connect() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/anyio/_core/_sockets.py:165> wait_for=<Future pending cb=[BaseSelectorEventLoop._sock_write_done(28, handle=<Handle BaseS...events.py:291>)(), <TaskWakeupMethWrapper object at 0x7f314eba30d0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[TaskGroup._spawn.<locals>.task_done() at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/anyio/_backends/_asyncio.py:701] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361>, <Task pending name='Task-15637' coro=<EngineServer.run_and_yield() running at /home/runner/work/bbot/bbot/bbot/core/engine.py:362> wait_for=<Future pending cb=[<TaskWakeupMethWrapper object at 0x7f3101081af0>()] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/base_events.py:429> cb=[_release_waiter(<Future pendi...events.py:429>)() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:416] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361>, <Task pending name='anyio._core._sockets.connect_tcp.<locals>.try_connect' coro=<connect_tcp.<locals>.try_connect() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/anyio/_core/_sockets.py:162> cb=[TaskGroup._spawn.<locals>.task_done() at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.9/lib/python3.9/site-packages/anyio/_backends/_asyncio.py:701] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361>, <Task pending name='Task-15729' coro=<HTTPEngine.request() running at /home/runner/work/bbot/bbot/bbot/core/helpers/web/engine.py:79> cb=[_wait.<locals>._on_completion() at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:509] created at /opt/hostedtoolcache/Python/3.9.19/x64/lib/python3.9/asyncio/tasks.py:361>]
DEBUG    httpcore.http11:_trace.py:85 send_request_headers.complete
DEBUG    httpcore.http11:_trace.py:85 send_request_body.started request=<Request [b'GET']>
DEBUG    httpcore.http11:_trace.py:85 send_request_body.complete
DEBUG    httpcore.http11:_trace.py:85 receive_response_headers.started request=<Request [b'GET']>
DEBUG    httpcore.connection:_trace.py:85 connect_tcp.complete return_value=<httpcore._backends.anyio.AnyIOStream object at 0x7f31000c6670>
DEBUG    httpcore.http11:_trace.py:85 response_closed.complete

------------------------------ live log teardown -------------------------------
DEBUG    httpcore.connection:_trace.py:85 connect_tcp.started host='127.0.0.1' port=8888 local_address=None timeout=10 socket_options=None
DEBUG    httpcore.http11:_trace.py:85 send_request_headers.started request=<Request [b'GET']>
DEBUG    httpcore.http11:_trace.py:85 send_request_headers.complete
DEBUG    httpcore.http11:_trace.py:85 send_request_body.started request=<Request [b'GET']>
DEBUG    httpcore.http11:_trace.py:85 send_request_body.complete
DEBUG    httpcore.http11:_trace.py:85 receive_response_headers.started request=<Request [b'GET']>
DEBUG    httpcore.connection:_trace.py:85 connect_tcp.complete return_value=<httpcore._backends.anyio.AnyIOStream object at 0x7f3144ae8f40>
DEBUG    httpcore.http11:_trace.py:85 receive_response_headers.complete return_value=(b'HTTP/1.0', 500, b'INTERNAL SERVER ERROR', [(b'Server', b'Werkzeug/3.0.3 Python/3.9.19'), (b'Date', b'Thu, 18 Jul 2024 21:39:16 GMT'), (b'Content-Type', b'text/plain; charset=utf-8'), (b'Content-Length', b'483'), (b'Connection', b'close')])
INFO     httpx:_client.py:1758 HTTP Request: GET http://127.0.0.1:8888/meet/ "HTTP/1.0 500 INTERNAL SERVER ERROR"
DEBUG    httpcore.http11:_trace.py:85 receive_response_body.started request=<Request [b'GET']>
DEBUG    httpcore.http11:_trace.py:85 receive_response_body.complete
DEBUG    httpcore.http11:_trace.py:85 response_closed.started
Error: The operation was canceled.

3.10

INFO     bbot.test.azure_realm:base.py:123 Finished azure_realm module test
PASSED                                                                   [ 30%]
bbot/test/test_step_2/module_tests/test_module_azure_tenant.py::TestAzure_Tenant::test_module_run 
-------------------------------- live log setup --------------------------------
[INFO] Starting azure_tenant module test
INFO     bbot:base.py:103 Starting azure_tenant module test
VERBOSE  bbot.core.target:target.py:29 Creating events from 1 targets
WARNING  bbot.scanner:scanner.py:1053 You have enabled custom HTTP headers. These will be attached to all in-scope requests and all requests made by httpx.
WARNING  asyncio:base_events.py:1904 Executing <Task pending name='Task-6980' coro=<_wrap_asyncgen_fixture.<locals>._asyncgen_fixture_wrapper.<locals>.setup() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.10/lib/python3.10/site-packages/pytest_asyncio/plugin.py:326> wait_for=<Future pending cb=[Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/asyncio/base_events.py:184] created at /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/asyncio/tasks.py:636> took 1.108 seconds
HUGEINFO bbot.scanner:scanner.py:1038 Scan with 1 modules seeded with 1 targets (1 in whitelist)
VERBOSE  bbot.scanner:scanner.py:1023 Loading 1 scan modules: azure_tenant
VERBOSE  bbot.scanner:scanner.py:1023 Loaded module "azure_tenant"
INFO     bbot.scanner:scanner.py:1033 Loaded 1/1 scan modules (azure_tenant)
VERBOSE  bbot.scanner:scanner.py:1023 Loading 1 internal modules: dnsresolve
VERBOSE  bbot.scanner:scanner.py:1023 Loaded module "dnsresolve"
INFO     bbot.scanner:scanner.py:1033 Loaded 1/1 internal modules (dnsresolve)
VERBOSE  bbot.scanner:scanner.py:1023 Loading 1 output modules: python
VERBOSE  bbot.scanner:scanner.py:1023 Loaded module "python"
INFO     bbot.scanner:scanner.py:1033 Loaded 1/1 output modules, (python)
VERBOSE  bbot.scanner:scanner.py:1023 Setting up modules
[WARN] Executing <Task finished name='Task-6984' coro=<BaseModule._setup() done, defined at /home/runner/work/bbot/bbot/bbot/modules/base.py:536> result=(<bbot.modules...x7fea5c7f51e0>, True, 'success') created at /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/asyncio/tasks.py:337> took 0.181 seconds
WARNING  asyncio:base_events.py:1904 Executing <Task finished name='Task-6984' coro=<BaseModule._setup() done, defined at /home/runner/work/bbot/bbot/bbot/modules/base.py:536> result=(<bbot.modules...x7fea5c7f51e0>, True, 'success') created at /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/asyncio/tasks.py:337> took 0.181 seconds
SUCCESS  bbot.scanner:scanner.py:1043 Setup succeeded for 5/5 modules.
[SUCC] Setup succeeded for 5/5 modules.
TRACE    bbot.scanner:scanner.py:1073 Ran BBOT v0.0.0 at 2024-07-18 21:28:57.050767, command: /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.10/bin/pytest --exitfirst --reruns 2 -o timeout_func_only=true --timeout 1200 --disable-warnings --log-cli-level=DEBUG --cov-config=bbot/test/coverage.cfg --cov-report xml:cov.xml --cov=bbot .
TRACE    bbot.scanner:scanner.py:1073 Target: {'seeds': ['blacklanternsecurity.com'], 'whitelist': ['blacklanternsecurity.com'], 'blacklist': [], 'strict_scope': False, 'hash': 'cffefd70a4eac5b8389a3c16987fb2ae91328c4c', 'seed_hash': '29b7be19a3f7633571a48c40f320d465c918c26b', 'whitelist_hash': '29b7be19a3f7633571a48c40f320d465c918c26b', 'blacklist_hash': 'da39a3ee5e6b4b0d3255bfef95601890afd80709', 'scope_hash': 'ef4a64d445f60a4ae47d81411d8994e40c3382d1'}
TRACE    bbot.scanner:scanner.py:1073 Preset: {'config': {'home': '/tmp/.bbot_test', 'keep_scans': 20, 'status_frequency': 15, 'file_blobs': False, 'folder_blobs': False, 'scope': {'report_distance': 0, 'search_distance': 0}, 'dns': {'disable': False, 'minimal': True, 'threads': 20, 'brute_threads': 1000, 'search_distance': 1, 'runaway_limit': 5, 'timeout': 1, 'retries': 1, 'wildcard_disable': False, 'wildcard_ignore': ['blacklanternsecurity.com', 'fakedomain', 'notreal', 'google', 'google.com', 'example.com', 'evilcorp.com', 'one'], 'wildcard_tests': 10, 'abort_threshold': 50, 'filter_ptrs': True, 'debug': False, 'omit_queries': ['SRV:mail.protection.outlook.com', 'CNAME:mail.protection.outlook.com', 'TXT:mail.protection.outlook.com']}, 'web': {'http_proxy': None, 'user_agent': 'BBOT Test User-Agent', 'spider_distance': 0, 'spider_depth': 1, 'spider_links_per_page': 25, 'http_timeout': 10, 'httpx_timeout': 5, 'http_headers': {'test': 'header'}, 'http_retries': 1, 'httpx_retries': 1, 'debug': False, 'http_max_redirects': 5, 'ssl_verify': False}, 'deps': {'ffuf': {'version': '2.1.0'}}, 'module_paths': [], 'speculate': False, 'excavate': False, 'aggregate': False, 'dnsresolve': True, 'cloudcheck': False, 'deps_behavior': 'abort_on_failure', 'url_querystring_remove': True, 'url_querystring_collapse': True, 'url_extension_blacklist': ['png', 'jpg', 'bmp', 'ico', 'jpeg', 'gif', 'svg', 'webp', 'css', 'woff', 'woff2', 'ttf', 'eot', 'sass', 'scss', 'mp3', 'm4a', 'wav', 'flac', 'mp4', 'mkv', 'avi', 'wmv', 'mov', 'flv', 'webm'], 'url_extension_httpx_only': ['js'], 'omit_event_types': [], 'interactsh_server': None, 'interactsh_disable': False, 'modules': {'massdns': {'wordlist': 'https://raw.githubusercontent.com/danielmiessler/SecLists/master/Discovery/DNS/deepmagic.com-prefixes-top500.txt'}, 'ffuf': {'prefix_busting': True, 'wordlist': 'https://raw.githubusercontent.com/danielmiessler/SecLists/master/Discovery/Web-Content/raft-small-directories.txt', 'lines': 5000, 'max_depth': 0, 'extensions': ''}, 'http': {'url': '', 'bearer': '', 'method': 'POST', 'timeout': 10, 'siem_friendly': False}, 'websocket': {'url': '', 'preserve_graph': True}, 'neo4j': {'uri': 'bolt://localhost:7687'}, 'dastardly': {}, 'vhost': {'wordlist': 'https://raw.githubusercontent.com/danielmiessler/SecLists/master/Discovery/DNS/subdomains-top1million-5000.txt', 'force_basehost': '', 'lines': 5000}, 'nuclei': {'version': '3.2.0', 'tags': '', 'templates': '', 'severity': '', 'ratelimit': 150, 'concurrency': 25, 'mode': 'manual', 'etags': '', 'budget': 1, 'silent': False, 'directory_only': True, 'retries': 0, 'batch_size': 200}, 'speculate': {'max_hosts': 65536, 'ports': '80,443'}, 'excavate': {'retain_querystring': False, 'yara_max_match_data': 2000, 'custom_yara_rules': ''}, 'cloudcheck': {}, 'dnsresolve': {}, 'aggregate': {}, 'anubisdb': {'limit': 1000}, 'gitlab': {}, 'trufflehog': {'version': '3.75.1', 'only_verified': True, 'concurrency': 8}, 'httpx': {'threads': 50, 'in_scope_only': True, 'version': '1.2.5', 'max_response_size': 5242880, 'store_responses': False, 'probe_all_ips': False}, 'chaos': {}, 'threatminer': {}, 'shodan_dns': {}, 'bucket_google': {'permutations': False}, 'crt': {}, 'git': {}, 'bucket_azure': {'permutations': False}, 'docker_pull': {'all_tags': False, 'output_folder': ''}, 'sitedossier': {}, 'portscan': {'top_ports': 100, 'ports': '', 'rate': 300, 'wait': 5, 'ping_first': False, 'ping_only': False, 'adapter': '', 'adapter_ip': '', 'adapter_mac': '', 'router_mac': ''}, 'ntlm': {'try_all': False}, 'smuggler': {}, 'dehashed': {}, 'newsletters': {}, 'hackertarget': {}, 'bucket_digitalocean': {'permutations': False}, 'hunt': {}, 'git_clone': {'output_folder': ''}, 'wayback': {'urls': False, 'garbage_threshold': 10}, 'wappalyzer': {}, 'url_manipulation': {'allow_redirects': True}, 'rapiddns': {}, 'ipstack': {}, 'c99': {}, 'censys': {'max_pages': 5}, 'leakix': {}, 'emailformat': {}, 'paramminer_getparams': {'wordlist': '', 'recycle_words': False, 'skip_boring_words': True}, 'badsecrets': {}, 'bucket_amazon': {'permutations': False}, 'ffuf_shortnames': {'wordlist': '', 'wordlist_extensions': '', 'lines': 1000000, 'max_depth': 1, 'version': '2.0.0', 'extensions': '', 'ignore_redirects': True, 'find_common_prefixes': False, 'find_delimiters': True}, 'hunterio': {}, 'dockerhub': {}, 'binaryedge': {'max_records': 1000}, 'subdomaincenter': {}, 'wafw00f': {'generic_detect': True}, 'github_org': {'include_members': True, 'include_member_repos': False}, 'riddler': {}, 'crobat': {}, 'otx': {}, 'telerik': {'exploit_RAU_crypto': False}, 'credshed': {'credshed_url': ''}, 'iis_shortnames': {'detect_only': True, 'max_node_count': 50}, 'baddns': {'custom_nameservers': [], 'only_high_confidence': False, 'enable_references': False}, 'sublist3r': {}, 'virustotal': {}, 'columbus': {}, 'dnscaa': {'in_scope_only': True, 'dns_names': True, 'emails': True, 'urls': True}, 'generic_ssrf': {}, 'certspotter': {}, 'github_codesearch': {'limit': 100}, 'azure_realm': {}, 'dnscommonsrv': {'max_depth': 2}, 'myssl': {}, 'pgp': {'search_urls': ['https://keyserver.ubuntu.com/pks/lookup?fingerprint=on&op=vindex&search=<query>', 'http://the.earth.li:11371/pks/lookup?fingerprint=on&op=vindex&search=<query>', 'https://pgpkeys.eu/pks/lookup?search=<query>&op=index', 'https://pgp.mit.edu/pks/lookup?search=<query>&op=index']}, 'wpscan': {'enumerate': 'vp,vt,tt,cb,dbe,u,m', 'threads': 5, 'request_timeout': 60, 'connection_timeout': 30, 'disable_tls_checks': True, 'force': False}, 'gowitness': {'version': '2.4.2', 'threads': 0, 'timeout': 10, 'resolution_x': 1440, 'resolution_y': 900, 'output_path': '', 'social': False, 'idle_timeout': 1800}, 'social': {}, 'dnsdumpster': {}, 'viewdns': {}, 'bucket_file_enum': {'file_limit': 50}, 'github_workflows': {'num_logs': 1}, 'securitytrails': {}, 'oauth': {'try_all': False}, 'internetdb': {'show_open_ports': False}, 'bucket_firebase': {'permutations': False}, 'host_header': {}, 'baddns_zone': {'custom_nameservers': [], 'only_high_confidence': False}, 'code_repository': {}, 'azure_tenant': {}, 'ip2location': {'lang': ''}, 'bypass403': {}, 'fullhunt': {}, 'dnsbrute': {'wordlist': 'https://raw.githubusercontent.com/danielmiessler/SecLists/master/Discovery/DNS/subdomains-top1million-5000.txt', 'max_depth': 5}, 'secretsdb': {'min_confidence': 99, 'signatures': 'https://raw.githubusercontent.com/blacklanternsecurity/secrets-patterns-db/master/db/rules-stable.yml'}, 'zoomeye': {'max_pages': 20, 'include_related': False}, 'robots': {'include_sitemap': False, 'include_allow': True, 'include_disallow': True}, 'paramminer_headers': {'wordlist': '', 'recycle_words': False, 'skip_boring_words': True}, 'ipneighbor': {'num_bits': 4}, 'unstructured': {'extensions': ['bak', 'bash', 'bashrc', 'conf', 'cfg', 'crt', 'csv', 'db', 'sqlite', 'doc', 'docx', 'ica', 'indd', 'ini', 'key', 'pub', 'log', 'markdown', 'md', 'odg', 'odp', 'ods', 'odt', 'pdf', 'pem', 'pps', 'ppsx', 'ppt', 'pptx', 'ps1', 'rdp', 'sh', 'sql', 'swp', 'sxw', 'txt', 'vbs', 'wpd', 'xls', 'xlsx', 'xml', 'yml', 'yaml'], 'ignore_folders': ['.git']}, 'postman': {}, 'sslcert': {'timeout': 5.0, 'skip_non_ssl': True}, 'filedownload': {'extensions': ['bak', 'bash', 'bashrc', 'conf', 'cfg', 'crt', 'csv', 'db', 'sqlite', 'doc', 'docx', 'exe', 'ica', 'indd', 'ini', 'jar', 'key', 'pub', 'log', 'markdown', 'md', 'msi', 'odg', 'odp', 'ods', 'odt', 'pdf', 'pem', 'pps', 'ppsx', 'ppt', 'pptx', 'ps1', 'raw', 'rdp', 'sh', 'sql', 'swp', 'sxw', 'tar', 'tar.gz', 'zip', 'txt', 'vbs', 'wpd', 'xls', 'xlsx', 'xml', 'yml', 'yaml'], 'max_filesize': '10MB', 'base_64_encoded_file': 'false'}, 'ajaxpro': {}, 'dnsbrute_mutations': {'max_mutations': 100}, 'dotnetnuke': {}, 'digitorus': {}, 'skymem': {}, 'passivetotal': {}, 'builtwith': {'redirects': True}, 'urlscan': {'urls': False}, 'bevigil': {'urls': False}, 'paramminer_cookies': {'wordlist': '', 'recycle_words': False, 'skip_boring_words': True}, 'fingerprintx': {'version': '1.1.4', 'skip_common_web': True}, 'discord': {'webhook_url': '', 'event_types': ['VULNERABILITY', 'FINDING'], 'min_severity': 'LOW'}, 'slack': {'webhook_url': '', 'event_types': ['VULNERABILITY', 'FINDING'], 'min_severity': 'LOW'}, 'splunk': {'url': '', 'index': '', 'source': '', 'timeout': 10}, 'teams': {'webhook_url': '', 'event_types': ['VULNERABILITY', 'FINDING'], 'min_severity': 'LOW'}, 'subdomains': {'output_file': '', 'include_unresolved': False}, 'emails': {'output_file': ''}, 'txt': {'output_file': ''}, 'web_report': {'output_file': '', 'css_theme_file': 'https://cdnjs.cloudflare.com/ajax/libs/github-markdown-css/5.1.0/github-markdown.min.css'}, 'python': {}, 'csv': {'output_file': ''}, 'stdout': {'format': 'text', 'event_types': [], 'event_fields': [], 'in_scope_only': False, 'accept_dupes': True}, 'json': {'output_file': '', 'siem_friendly': False}, 'asset_inventory': {'output_file': '', 'use_previous': False, 'recheck': False, 'summary_netmask': 16}, 'asn': {}, 'affiliates': {}, 'testmodule1': {}, 'testmodule3': {}, 'testmodule2': {}, 'testmodule4': {}}, 'agent_url': 'ws://127.0.0.1:8765', 'debug': True}, 'modules': ['azure_tenant'], 'output_modules': ['python'], 'scan_name': 'testazure_tenant_test_vfl5rgsdc0', 'output_dir': None}
HUGESUCCESS bbot.scanner:scanner.py:1048 Starting scan testazure_tenant_test_vfl5rgsdc0
VERBOSE  bbot.scanner:scanner.py:1023 Starting module worker loops
[VERB] 5 modules started
VERBOSE  bbot.scanner:scanner.py:1023 5 modules started
WARNING  asyncio:base_events.py:1904 Executing <Task pending name='Task-6980' coro=<_wrap_asyncgen_fixture.<locals>._asyncgen_fixture_wrapper.<locals>.setup() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.10/lib/python3.10/site-packages/pytest_asyncio/plugin.py:326> wait_for=<Future pending cb=[Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/asyncio/base_events.py:184] created at /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/asyncio/tasks.py:636> took 0.222 seconds
[WARN] Executing <Task pending name='Task-6980' coro=<_wrap_asyncgen_fixture.<locals>._asyncgen_fixture_wrapper.<locals>.setup() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.10/lib/python3.10/site-packages/pytest_asyncio/plugin.py:326> wait_for=<Future pending cb=[Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/asyncio/base_events.py:429> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/asyncio/base_events.py:184] created at /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/asyncio/tasks.py:636> took 0.222 seconds
VERBOSE  bbot.modules._scan_ingress:base.py:1250 Target: SCAN("{'id': 'SCAN:e4a0891b60714544ad4e02cdac5a99646f75be51', 'name': 'testazure_tenan...", module=TARGET, tags={'target', 'in-scope'})
[VERB] _scan_ingress: Target: SCAN("{'id': 'SCAN:e4a0891b60714544ad4e02cdac5a99646f75be51', 'name': 'testazure_tenan...", module=TARGET, tags={'target', 'in-scope'})
VERBOSE  bbot.modules._scan_ingress:base.py:1250 Target: DNS_NAME("blacklanternsecurity.com", module=TARGET, tags={'target', 'distance-1', 'domain'})
WARNING  asyncio:base_events.py:1904 Executing <Task pending name='_scan_ingress._worker()' coro=<InterceptModule._worker() running at /home/runner/work/bbot/bbot/bbot/modules/base.py:1447> wait_for=<Future pending cb=[Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/asyncio/base_events.py:429> created at /opt/hostedtoolcache/Python/3.10.14/x64/lib/python3.10/asyncio/tasks.py:337> took 0.186 seconds
VERBOSE  bbot.core.target:target.py:29 Creating events from 1 targets
[VERB] Creating events from 1 targets
VERBOSE  bbot.core.target:target.py:34 Creating events from 1 whitelist entries
[VERB] Creating events from 1 whitelist entries
DEBUG    httpx:_config.py:78 load_ssl_context verify=<ssl.SSLContext object at 0x7feab42905c0> cert=None trust_env=True http2=False
Error: The operation was canceled.

3.11

HUGESUCCESS bbot.scanner:logger.py:132 Scan testntlm_test_8shymrkjm0 completed in 2 seconds with status FINISHED
DEBUG    httpcore.connection:_trace.py:85 connect_tcp.complete return_value=<httpcore._backends.anyio.AnyIOStream object at 0x7fbd4b83f650>
DEBUG    httpcore.http11:_trace.py:85 receive_response_headers.complete return_value=(b'HTTP/1.0', 500, b'INTERNAL SERVER ERROR', [(b'Server', b'Werkzeug/3.0.3 Python/3.11.9'), (b'Date', b'Thu, 18 Jul 2024 21:38:56 GMT'), (b'Content-Type', b'text/plain; charset=utf-8'), (b'Content-Length', b'482'), (b'Connection', b'close')])
INFO     httpx:_client.py:1758 HTTP Request: GET http://127.0.0.1:8888/rgs/ "HTTP/1.0 500 INTERNAL SERVER ERROR"
[INFO] HTTP Request: GET http://127.0.0.1:8888/rgs/ "HTTP/1.0 500 INTERNAL SERVER ERROR"
DEBUG    httpcore.http11:_trace.py:85 receive_response_body.started request=<Request [b'GET']>
DEBUG    httpcore.http11:_trace.py:85 receive_response_body.complete
DEBUG    httpcore.http11:_trace.py:85 response_closed.started
DEBUG    httpcore.connection:_trace.py:85 connect_tcp.started host='127.0.0.1' port=8888 local_address=None timeout=10 socket_options=None
DEBUG    httpcore.http11:_trace.py:85 send_request_headers.started request=<Request [b'GET']>
-------------------------------- live log call ---------------------------------
DEBUG    httpcore.http11:_trace.py:85 send_request_headers.complete
DEBUG    httpcore.http11:_trace.py:85 send_request_body.started request=<Request [b'GET']>
DEBUG    httpcore.http11:_trace.py:85 send_request_body.complete
DEBUG    httpcore.http11:_trace.py:85 receive_response_headers.started request=<Request [b'GET']>
DEBUG    httpcore.http11:_trace.py:85 response_closed.complete
DEBUG    httpcore.http11:_trace.py:85 receive_response_headers.complete return_value=(b'HTTP/1.0', 500, b'INTERNAL SERVER ERROR', [(b'Server', b'Werkzeug/3.0.3 Python/3.11.9'), (b'Date', b'Thu, 18 Jul 2024 21:38:56 GMT'), (b'Content-Type', b'text/plain; charset=utf-8'), (b'Content-Length', b'482'), (b'Connection', b'close')])
INFO     httpx:_client.py:1758 HTTP Request: GET http://127.0.0.1:8888/owa/ "HTTP/1.0 500 INTERNAL SERVER ERROR"
DEBUG    httpcore.http11:_trace.py:85 receive_response_body.started request=<Request [b'GET']>
DEBUG    httpcore.http11:_trace.py:85 receive_response_body.complete
DEBUG    httpcore.http11:_trace.py:85 response_closed.started
INFO     bbot.test.ntlm:base.py:123 Finished ntlm module test
INFO     bbot.test.ntlm:base.py:127 Unfinished tasks detected: [<Task cancelling name='Task-15704' coro=<HTTPEngine.request() running at /home/runner/work/bbot/bbot/bbot/core/helpers/web/engine.py:79> wait_for=<Future cancelled created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/base_events.py:428> created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:384>, <Task pending name='Task-15707' coro=<HTTPEngine.request() running at /home/runner/work/bbot/bbot/bbot/core/helpers/web/engine.py:79> wait_for=<Future pending cb=[Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/base_events.py:428> created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:384>, <Task pending name='Task-15702' coro=<HTTPEngine.request() running at /home/runner/work/bbot/bbot/bbot/core/helpers/web/engine.py:79> wait_for=<Future finished result=None created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/base_events.py:428> created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:384>, <Task pending name='Task-15709' coro=<HTTPEngine.request() running at /home/runner/work/bbot/bbot/bbot/core/helpers/web/engine.py:79> wait_for=<Future pending cb=[Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/base_events.py:428> created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:384>, <Task pending name='anyio._core._sockets.connect_tcp.<locals>.try_connect' coro=<connect_tcp.<locals>.try_connect() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.11/lib/python3.11/site-packages/anyio/_core/_sockets.py:165> wait_for=<Future pending cb=[BaseSelectorEventLoop._sock_write_done(28, handle=<Handle BaseS...events.py:304>)(), Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/base_events.py:428> cb=[TaskGroup._spawn.<locals>.task_done() at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.11/lib/python3.11/site-packages/anyio/_backends/_asyncio.py:701] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:384>, <Task pending name='Task-15698' coro=<HTTPEngine.request() running at /home/runner/work/bbot/bbot/bbot/core/helpers/web/engine.py:79> created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:384>, <Task cancelling name='Task-15636' coro=<EngineServer.run_and_yield() running at /home/runner/work/bbot/bbot/bbot/core/engine.py:363> wait_for=<Future finished result=None created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/base_events.py:428> cb=[_release_waiter(<Future pendi...events.py:428>)() at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:431] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:384>, <Task pending name='anyio._core._sockets.connect_tcp.<locals>.try_connect' coro=<connect_tcp.<locals>.try_connect() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.11/lib/python3.11/site-packages/anyio/_core/_sockets.py:165> wait_for=<Future pending cb=[Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/base_events.py:428> cb=[TaskGroup._spawn.<locals>.task_done() at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.11/lib/python3.11/site-packages/anyio/_backends/_asyncio.py:701] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:384>, <Task pending name='Task-15700' coro=<HTTPEngine.request() running at /home/runner/work/bbot/bbot/bbot/core/helpers/web/engine.py:79> wait_for=<Future pending cb=[Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/base_events.py:428> created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:384>, <Task pending name='Task-15635' coro=<EngineServer.worker() running at /home/runner/work/bbot/bbot/bbot/core/engine.py:411> wait_for=<Future pending cb=[Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/base_events.py:428> cb=[_chain_future.<locals>._call_set_state() at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/futures.py:394] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:680>]
[INFO] Finished ntlm module test
DEBUG    httpcore.connection:_trace.py:85 connect_tcp.complete return_value=<httpcore._backends.anyio.AnyIOStream object at 0x7fbd5dd672d0>

------------------------------ live log teardown -------------------------------
DEBUG    httpcore.http11:_trace.py:85 send_request_headers.started request=<Request [b'GET']>
DEBUG    httpcore.http11:_trace.py:85 response_closed.complete
DEBUG    httpcore.http11:_trace.py:85 receive_response_headers.complete return_value=(b'HTTP/1.0', 500, b'INTERNAL SERVER ERROR', [(b'Server', b'Werkzeug/3.0.3 Python/3.11.9'), (b'Date', b'Thu, 18 Jul 2024 21:38:56 GMT'), (b'Content-Type', b'text/plain; charset=utf-8'), (b'Content-Length', b'485'), (b'Connection', b'close')])
INFO     httpx:_client.py:1758 HTTP Request: GET http://127.0.0.1:8888/public/ "HTTP/1.0 500 INTERNAL SERVER ERROR"
DEBUG    httpcore.http11:_trace.py:85 receive_response_body.started request=<Request [b'GET']>
DEBUG    httpcore.http11:_trace.py:85 receive_response_body.complete
DEBUG    httpcore.http11:_trace.py:85 response_closed.started
[INFO] HTTP Request: GET http://127.0.0.1:8888/public/ "HTTP/1.0 500 INTERNAL SERVER ERROR"
DEBUG    httpcore.connection:_trace.py:85 connect_tcp.started host='127.0.0.1' port=8888 local_address=None timeout=10 socket_options=None
DEBUG    httpcore.http11:_trace.py:85 send_request_headers.complete
DEBUG    httpcore.http11:_trace.py:85 send_request_body.started request=<Request [b'GET']>
DEBUG    httpcore.http11:_trace.py:85 send_request_body.complete
DEBUG    httpcore.http11:_trace.py:85 receive_response_headers.started request=<Request [b'GET']>
DEBUG    httpcore.connection:_trace.py:85 connect_tcp.complete return_value=<httpcore._backends.anyio.AnyIOStream object at 0x7fbd4b6da610>
Error: The operation was canceled.

3.12

PASSED                                                                   [ 18%]
bbot/test/test_step_1/test_python_api.py::test_python_api_sync 
-------------------------------- live log call ---------------------------------
VERBOSE  bbot.core.target:logger.py:132 Creating events from 1 targets
WARNING  bbot.scanner:scanner.py:1053 You have enabled custom HTTP headers. These will be attached to all in-scope requests and all requests made by httpx.
HUGEINFO bbot.scanner:logger.py:132 Scan with 0 modules seeded with 1 targets (1 in whitelist)
[INFO] Scan with 0 modules seeded with 1 targets (1 in whitelist)
WARNING  bbot.scanner:scanner.py:1053 No scan modules to load
VERBOSE  bbot.scanner:logger.py:132 Loading 0 scan modules: 
VERBOSE  bbot.scanner:logger.py:132 Loading 1 internal modules: dnsresolve
VERBOSE  bbot.scanner:logger.py:132 Loaded module "dnsresolve"
INFO     bbot.scanner:scanner.py:1033 Loaded 1/1 internal modules (dnsresolve)
VERBOSE  bbot.scanner:logger.py:132 Loading 4 output modules: csv,json,python,txt
VERBOSE  bbot.scanner:logger.py:132 Loaded module "csv"
VERBOSE  bbot.scanner:logger.py:132 Loaded module "json"
VERBOSE  bbot.scanner:logger.py:132 Loaded module "python"
VERBOSE  bbot.scanner:logger.py:132 Loaded module "txt"
INFO     bbot.scanner:scanner.py:1033 Loaded 4/4 output modules, (csv,json,python,txt)
VERBOSE  bbot.scanner:logger.py:132 Setting up modules
WARNING  asyncio:base_events.py:1982 Executing <Task pending name='Task-5278' coro=<async_to_sync_gen.<locals>.runner() running at /home/runner/work/bbot/bbot/bbot/core/helpers/async_helpers.py:105> wait_for=<Future pending cb=[Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/asyncio/base_events.py:449> cb=[_run_until_complete_cb() at /opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/asyncio/base_events.py:182] created at /opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/asyncio/runners.py:100> took 0.149 seconds
SUCCESS  bbot.scanner:logger.py:132 Setup succeeded for 7/7 modules.
TRACE    bbot.scanner:logger.py:132 Ran BBOT v0.0.0 at 2024-07-18 21:29:57.714009, command: /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.12/bin/pytest --exitfirst --reruns 2 -o timeout_func_only=true --timeout 1200 --disable-warnings --log-cli-level=DEBUG --cov-config=bbot/test/coverage.cfg --cov-report xml:cov.xml --cov=bbot .
TRACE    bbot.scanner:logger.py:132 Target: {'seeds': ['127.0.0.1'], 'whitelist': ['127.0.0.1'], 'blacklist': [], 'strict_scope': False, 'hash': '5e15b225a494952ed99317d88ff53d84726208ec', 'seed_hash': '306f9dee732268504604f53a55c1fdbf7949b3f7', 'whitelist_hash': '306f9dee732268504604f53a55c1fdbf7949b3f7', 'blacklist_hash': 'da39a3ee5e6b4b0d3255bfef95601890afd80709', 'scope_hash': '82d01722ef215f063844f17caf5012b49db106e9'}
TRACE    bbot.scanner:logger.py:132 Preset: {}
HUGESUCCESS bbot.scanner:logger.py:132 Starting scan evil_william
VERBOSE  bbot.scanner:logger.py:132 Starting module worker loops
[VERB] Starting module worker loops
VERBOSE  bbot.scanner:logger.py:132 7 modules started
VERBOSE  bbot.modules._scan_ingress:logger.py:132 Target: SCAN("{'id': 'SCAN:d6dd717a2a06060220ccc292646fb06359778c57', 'name': 'evil_william', ...", module=TARGET, tags={'in-scope', 'target'})
VERBOSE  bbot.modules._scan_ingress:logger.py:132 Target: IP_ADDRESS("127.0.0.1", module=TARGET, tags={'ipv4', 'target', 'private-ip', 'distance-1'})
INFO     bbot.scanner:scanner.py:715 Finishing scan
[INFO] Finishing scan
VERBOSE  bbot.scanner:logger.py:132 Completed finish()
[VERB] Completed finish()
VERBOSE  bbot.scanner:logger.py:132 Completed final finish()
[VERB] Completed final finish()
INFO     bbot.modules.output.csv:base.py:1282 Saved CSV output to /tmp/.bbot_test/scans/evil_william/output.csv
INFO     bbot.modules.output.json:base.py:1282 Saved JSON output to /tmp/.bbot_test/scans/evil_william/output.json
INFO     bbot.modules.output.txt:base.py:1282 Saved TXT output to /tmp/.bbot_test/scans/evil_william/output.txt
[INFO] output.csv: Saved CSV output to /tmp/.bbot_test/scans/evil_william/output.csv
VERBOSE  bbot.core.target:logger.py:132 Creating events from 1 targets
VERBOSE  bbot.core.target:logger.py:132 Creating events from 1 whitelist entries
DEBUG    httpx:_config.py:78 load_ssl_context verify=<ssl.SSLContext object at 0x7f7d9d233a50> cert=None trust_env=True http2=False
HUGESUCCESS bbot.scanner:logger.py:132 Scan evil_william completed in 0 seconds with status FINISHED
CRITICAL bbot.core.engine.server:engine.py:245 Unhandled error in DNSEngine server process: Traceback (most recent call last):
  File "/home/runner/work/bbot/bbot/bbot/core/engine.py", line 236, in server_process
    future.result()
  File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/concurrent/futures/_base.py", line 454, in result
    raise CancelledError()
concurrent.futures._base.CancelledError

[CRIT] Unhandled error in DNSEngine server process: Traceback (most recent call last):
  File "/home/runner/work/bbot/bbot/bbot/core/engine.py", line 236, in server_process
    future.result()
  File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/concurrent/futures/_base.py", line 454, in result
    raise CancelledError()
concurrent.futures._base.CancelledError

CRITICAL bbot.core.engine.server:engine.py:245 Unhandled error in HTTPEngine server process: Traceback (most recent call last):
  File "/home/runner/work/bbot/bbot/bbot/core/engine.py", line 236, in server_process
    future.result()
  File "/opt/hostedtoolcache/Python/3.12.4/x64/lib/python3.12/concurrent/futures/_base.py", line 454, in result
    raise CancelledError()
concurrent.futures._base.CancelledError

Error: The operation was canceled.

Based on these logs, it seems like the freeze might be related to unfinished HTTP request tasks.

TheTechromancer commented 1 month ago

Very strange behavior. The code is now consistently hanging on this line:

self._config = OmegaConf.merge(self.default_config, self.custom_config)

In isolation this works perfectly fine, even with the exact same arguments. So I'm not sure what could be causing it.

TheTechromancer commented 1 month ago

Traced this down into the omegaconf library, and found that the freeze is happening during the deep copy operation on the first config:

target = copy.deepcopy(configs[0])

The plot thickens 🤔🤔🤔

TheTechromancer commented 1 month ago

This only occurs on the second scan run. The first always completes fine, the second always freezes.

TheTechromancer commented 1 month ago

I think part of the reason this bug is so puzzling is because it's multiple bugs. The first bug was with deepcopy, where somehow subsequent deepcopying of the same global variable across multiple threads caused a deadlock. This would happen during preset.bake(). I tried unsuccessfully to reproduce this bug in isolation. But sync_to_async() seemed to be the culprit. Simplifying this function (by not spawning a dedicated thread with its own asyncio.run() event loop) seemed to fix the issue.

The second bug seems to be more related to the engines. It happens during module tests like ntlm or iis_shortnames. This seems to indicate an issue with request_batch():

2024-07-19T06:49:20.3520729Z [INFO] Finished ntlm module test
2024-07-19T06:49:20.3546750Z [INFO] Unfinished tasks detected: [
    <Task pending name='Task-15721' coro=<HTTPEngine.request() running at /home/runner/work/bbot/bbot/bbot/core/helpers/web/engine.py:79> created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:384>,
    <Task pending name='anyio._core._sockets.connect_tcp.<locals>.try_connect' coro=<connect_tcp.<locals>.try_connect() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.11/lib/python3.11/site-packages/anyio/_core/_sockets.py:162> cb=[TaskGroup._spawn.<locals>.task_done() at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.11/lib/python3.11/site-packages/anyio/_backends/_asyncio.py:701] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:384>,
    <Task cancelling name='Task-15629' coro=<EngineServer.run_and_yield() running at /home/runner/work/bbot/bbot/bbot/core/engine.py:370> wait_for=<Future pending cb=[Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/base_events.py:428> cb=[_release_waiter(<Future pendi...events.py:428>)() at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:431] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:384>,
    <Task pending name='Task-15728' coro=<HTTPEngine.request() running at /home/runner/work/bbot/bbot/bbot/core/helpers/web/engine.py:79> wait_for=<Future pending cb=[Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/base_events.py:428> created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:384>,
    <Task pending name='Task-15726' coro=<HTTPEngine.request() running at /home/runner/work/bbot/bbot/bbot/core/helpers/web/engine.py:79> wait_for=<Future pending cb=[Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/base_events.py:428> created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:384>,
    <Task pending name='anyio._core._sockets.connect_tcp.<locals>.try_connect' coro=<connect_tcp.<locals>.try_connect() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.11/lib/python3.11/site-packages/anyio/_core/_sockets.py:165> wait_for=<Future pending cb=[BaseSelectorEventLoop._sock_write_done(35, handle=<Handle BaseS...events.py:304>)(), Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/base_events.py:428> cb=[TaskGroup._spawn.<locals>.task_done() at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.11/lib/python3.11/site-packages/anyio/_backends/_asyncio.py:701] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:384>,
    <Task pending name='anyio._core._sockets.connect_tcp.<locals>.try_connect' coro=<connect_tcp.<locals>.try_connect() running at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.11/lib/python3.11/site-packages/anyio/_core/_sockets.py:165> wait_for=<Future finished result=None created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/base_events.py:428> cb=[TaskGroup._spawn.<locals>.task_done() at /home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.11/lib/python3.11/site-packages/anyio/_backends/_asyncio.py:701] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:384>,
    <Task pending name='Task-15719' coro=<HTTPEngine.request() running at /home/runner/work/bbot/bbot/bbot/core/helpers/web/engine.py:79> wait_for=<Future pending cb=[Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/base_events.py:428> created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:384>,
    <Task pending name='Task-15717' coro=<HTTPEngine.request() running at /home/runner/work/bbot/bbot/bbot/core/helpers/web/engine.py:79> created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:384>,
    <Task pending name='Task-15723' coro=<HTTPEngine.request() running at /home/runner/work/bbot/bbot/bbot/core/helpers/web/engine.py:79> wait_for=<Future pending cb=[Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/base_events.py:428> created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:384>,
    <Task pending name='Task-15628' coro=<EngineServer.worker() running at /home/runner/work/bbot/bbot/bbot/core/engine.py:418> wait_for=<Future pending cb=[Task.task_wakeup()] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/base_events.py:428> cb=[_chain_future.<locals>._call_set_state() at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/futures.py:394] created at /opt/hostedtoolcache/Python/3.11.9/x64/lib/python3.11/asyncio/tasks.py:680>
]
2024-07-19T06:49:20.3573711Z DEBUG    httpcore.http11:_trace.py:85 send_request_headers.started request=<Request [b'GET']>

Both of these modules use request_batch(), which is an async generator, and cancel/abort the generator before it's finished. Yep, pretty clear this is the issue.

TheTechromancer commented 1 month ago

I fixed the unfinished tasks in hope that was the main issue, but sadly it didn't fix it. (I can reproduce the hang locally about 50% of the time on the ntlm test, and cancelling or not cancelling asyncio tasks has no effect on it).

I tried changing the pytest-httpserver threads to daemon=True, which had no effect.

The one thing that fixes the issue 100%, is to remove the agen.aclose() in ntlm.py that closes the the async generator. Removing this fixes the hanging and causes the tests to pass.

This is definitely a race condition, since it only happens about 50% of the time. The detailed thread/process info is the same whether or not the hang happens.

Basically, this is still a huge mystery. Probably the next step is to remove the cancellation temporarily, and meanwhile write some stress tests to try and reproduce the issue in isolation, and narrow down its cause so we can open an issue upstream in python, httpx, or wherever the culprit turns out to be.

TheTechromancer commented 1 month ago

Appears to be a bug in pytest-httpserver. Upstream issue: https://github.com/csernazs/pytest-httpserver/issues/347

TheTechromancer commented 1 month ago

Fixed in https://github.com/blacklanternsecurity/bbot/pull/1555.