search

blacklanternsecurity / bbot

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

Tests Occasionally Hang #847

Closed TheTechromancer closed 6 months ago

TheTechromancer commented 8 months ago

This happened once on Python 3.9. Two events apparently got stuck in emit_event():

2023-11-13T22:40:48.4702711Z INFO     bbot.scanner:scanner.py:902 test_cli_scan: No modules running
2023-11-13T22:40:48.4704758Z INFO     bbot.scanner:scanner.py:902 test_cli_scan: No events produced yet
2023-11-13T22:40:48.4708905Z INFO     bbot.scanner:scanner.py:902 test_cli_scan: No events in queue
2023-11-13T22:40:48.4712468Z DEBUG    bbot.scanner:scanner.py:887 scan._finished_init: True
2023-11-13T22:40:48.4715243Z DEBUG    bbot.scanner:scanner.py:887 manager.active: True
2023-11-13T22:40:48.4717658Z DEBUG    bbot.scanner:scanner.py:887     manager.running: True
2023-11-13T22:40:48.4720343Z DEBUG    bbot.scanner:scanner.py:887         manager._task_counter.value: 2
2023-11-13T22:40:48.4723061Z DEBUG    bbot.scanner:scanner.py:887         manager._task_counter.tasks:
2023-11-13T22:40:48.4726858Z DEBUG    bbot.scanner:scanner.py:887             - emit_event(IP_ADDRESS("127.0.0.1", module=TARGET, tags={'private', 'in-scope', 'distance-0', 'ipv4', 'target'})) running for 10 minutes:
2023-11-13T22:40:48.4729288Z DEBUG    bbot.scanner:scanner.py:887             - emit_event(DNS_NAME("www.example.com", module=TARGET, tags={'subdomain', 'in-scope', 'distance-0', 'target'})) running for 10 minutes:
2023-11-13T22:40:48.4731470Z DEBUG    bbot.scanner:scanner.py:887         manager.incoming_event_queue.qsize: 0
2023-11-13T22:40:48.4734025Z DEBUG    bbot.scanner:scanner.py:887     manager.modules_finished: True
2023-11-13T22:40:48.4736587Z DEBUG    bbot.scanner:scanner.py:887         csv.finished: True
2023-11-13T22:40:48.4739199Z DEBUG    bbot.scanner:scanner.py:887             running: False
2023-11-13T22:40:48.4741846Z DEBUG    bbot.scanner:scanner.py:887             num_incoming_events: 0
2023-11-13T22:40:48.4744491Z DEBUG    bbot.scanner:scanner.py:887             outgoing_event_queue.qsize: 0
2023-11-13T22:40:48.4747062Z DEBUG    bbot.scanner:scanner.py:887         human.finished: True
2023-11-13T22:40:48.4749716Z DEBUG    bbot.scanner:scanner.py:887             running: False
2023-11-13T22:40:48.4752389Z DEBUG    bbot.scanner:scanner.py:887             num_incoming_events: 0
2023-11-13T22:40:48.4755126Z DEBUG    bbot.scanner:scanner.py:887             outgoing_event_queue.qsize: 0
2023-11-13T22:40:48.4757682Z DEBUG    bbot.scanner:scanner.py:887         json.finished: True
2023-11-13T22:40:48.4760250Z DEBUG    bbot.scanner:scanner.py:887             running: False
2023-11-13T22:40:48.4762879Z DEBUG    bbot.scanner:scanner.py:887             num_incoming_events: 0
2023-11-13T22:40:48.4765730Z DEBUG    bbot.scanner:scanner.py:887             outgoing_event_queue.qsize: 0
2023-11-13T22:40:48.4777274Z DEBUG    bbot.scanner:scanner.py:887 MODULE MEMORY USAGE:
2023-11-13T22:40:48.4780171Z DEBUG    bbot.scanner:scanner.py:887     - csv: 2.97KB
2023-11-13T22:40:48.4782954Z DEBUG    bbot.scanner:scanner.py:887     - human: 2.48KB
2023-11-13T22:40:48.4785709Z DEBUG    bbot.scanner:scanner.py:887     - json: 2.48KB

5_Run tests.txt

TheTechromancer commented 8 months ago

The issue appears to be a regression of an old DNS hanging bug:

DEBUG    bbot.core.helpers.dns:dns.py:1030 Resolving cgeaoufzdi.domain.com with kwargs={'rdtype': 'MX', 'use_cache': False}
DEBUG    bbot.core.helpers.dns:dns.py:1030 Resolving duwffbrdhq.domain.com with kwargs={'rdtype': 'MX', 'use_cache': False}
DEBUG    bbot.core.helpers.dns:dns.py:1030 Resolving kzveoiuvlq.domain.com with kwargs={'rdtype': 'MX', 'use_cache': False}
DEBUG    bbot.core.helpers.dns:dns.py:1030 Resolving pwjmpdpmdy.domain.com with kwargs={'rdtype': 'MX', 'use_cache': False}
DEBUG    bbot.core.helpers.dns:dns.py:1030 Resolving qwujkzlgju.domain.com with kwargs={'rdtype': 'MX', 'use_cache': False}
DEBUG    bbot.core.helpers.dns:dns.py:1030 Resolving awibqwpfbl.domain.com with kwargs={'rdtype': 'MX', 'use_cache': False}
DEBUG    bbot.core.helpers.dns:dns.py:1030 Resolving dxxignzqou.domain.com with kwargs={'rdtype': 'MX', 'use_cache': False}
DEBUG    bbot.core.helpers.dns:dns.py:1030 Resolving dgmlyfwhtb.domain.com with kwargs={'rdtype': 'MX', 'use_cache': False}
DEBUG    bbot.core.helpers.dns:dns.py:1030 Resolving tgvalirqmr.domain.com with kwargs={'rdtype': 'MX', 'use_cache': False}
DEBUG    bbot.core.helpers.dns:dns.py:1030 Resolving wbkrjxtpyp.domain.com with kwargs={'rdtype': 'MX', 'use_cache': False}
DEBUG    bbot.core.helpers.dns:dns.py:1030 Results for cgeaoufzdi.domain.com with kwargs={'type': 'MX', 'use_cache': False}: {'mx.domain.com'}
DEBUG    bbot.core.helpers.dns:dns.py:1030 Results for dgmlyfwhtb.domain.com with kwargs={'type': 'MX', 'use_cache': False}: {'mx.domain.com'}
DEBUG    bbot.core.helpers.dns:dns.py:1030 Results for duwffbrdhq.domain.com with kwargs={'type': 'MX', 'use_cache': False}: {'mx.domain.com'}
DEBUG    bbot.core.helpers.dns:dns.py:1030 Results for wbkrjxtpyp.domain.com with kwargs={'type': 'MX', 'use_cache': False}: {'mx.domain.com'}
DEBUG    bbot.core.helpers.dns:dns.py:1030 Results for kzveoiuvlq.domain.com with kwargs={'type': 'MX', 'use_cache': False}: {'mx.domain.com'}
DEBUG    bbot.core.helpers.dns:dns.py:1030 Results for awibqwpfbl.domain.com with kwargs={'type': 'MX', 'use_cache': False}: {'mx.domain.com'}
DEBUG    bbot.core.helpers.dns:dns.py:1030 Results for qwujkzlgju.domain.com with kwargs={'type': 'MX', 'use_cache': False}: {'mx.domain.com'}
DEBUG    bbot.core.helpers.dns:dns.py:1030 Results for dxxignzqou.domain.com with kwargs={'type': 'MX', 'use_cache': False}: {'mx.domain.com'}
DEBUG    bbot.core.helpers.dns:dns.py:1030 Results for tgvalirqmr.domain.com with kwargs={'type': 'MX', 'use_cache': False}: {'mx.domain.com'}

Notice here during the wildcard check, only 9/10 hostnames are successfully resolved, and the 10th one (pwjmpdpmdy.domain.com) never finishes.

EDIT: On further investigation, this was just a symptom of a broken pipe in github's streaming output. The hostname was actually resolved.

TheTechromancer commented 8 months ago

Potentially a long time spent here:

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 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    asyncio:selector_events.py:853 <_SelectorSocketTransport fd=62 read=idle write=<idle, bufsize=0>> pauses reading
DEBUG    httpcore.http11:_trace.py:85 receive_response_headers.complete return_value=(b'HTTP/1.0', 404, b'NOT FOUND', [(b'Server', b'Werkzeug/2.3.7 Python/3.12.0'), (b'Date', b'Thu, 16 Nov 2023 20:14:00 GMT'), (b'Content-Type', b'text/plain; charset=utf-8'), (b'Content-Length', b'33'), (b'Connection', b'close')])
INFO     httpx:_client.py:1729 HTTP Request: GET http://127.0.0.1:8888/%42%4c%53%4a%2a%7e%31%2a/a.aspx "HTTP/1.0 404 NOT FOUND"
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    asyncio:selector_events.py:861 <_SelectorSocketTransport fd=41 read=polling write=<idle, bufsize=0>> resumes reading
DEBUG    httpcore.http11:_trace.py:85 response_closed.complete
DEBUG    asyncio:selector_events.py:853 <_SelectorSocketTransport fd=63 read=idle write=<idle, bufsize=0>> pauses reading
TheTechromancer commented 8 months ago

We are one step closer:

2023-11-21T18:15:06.2671820Z DEBUG    bbot.scanner.manager:manager.py:104 Module "TARGET" raised IP_ADDRESS("127.0.0.1", module=TARGET, tags={'ipv4', 'target', 'in-scope', 'private'})
2023-11-21T18:15:06.2675197Z DEBUG    bbot.scanner.manager:manager.py:172 Emitting IP_ADDRESS("127.0.0.1", module=TARGET, tags={'ipv4', 'target', 'in-scope', 'private'})
2023-11-21T18:15:06.2678329Z DEBUG    bbot.scanner.manager:manager.py:178 EMIT IP_ADDRESS("127.0.0.1", module=TARGET, tags={'ipv4', 'target', 'in-scope', 'private'}) 1
2023-11-21T18:15:06.2681568Z DEBUG    bbot.scanner.manager:manager.py:203 EMIT IP_ADDRESS("127.0.0.1", module=TARGET, tags={'ipv4', 'target', 'in-scope', 'private'}) 2
2023-11-21T18:15:06.2684755Z DEBUG    bbot.scanner.manager:manager.py:213 EMIT IP_ADDRESS("127.0.0.1", module=TARGET, tags={'ipv4', 'target', 'in-scope', 'private'}) 3
2023-11-21T18:15:06.2695597Z DEBUG    bbot.scanner.manager:manager.py:231 EMIT IP_ADDRESS("127.0.0.1", module=TARGET, tags={'ipv4', 'target', 'in-scope', 'resolved', 'private'}) 4
2023-11-21T18:15:06.2721147Z DEBUG    bbot.scanner.manager:manager.py:104 Module "TARGET" raised DNS_NAME("www.example.com", module=TARGET, tags={'in-scope', 'subdomain', 'target'})
2023-11-21T18:15:06.2724243Z DEBUG    bbot.scanner.manager:manager.py:172 Emitting DNS_NAME("www.example.com", module=TARGET, tags={'in-scope', 'subdomain', 'target'})
2023-11-21T18:15:06.2727493Z DEBUG    bbot.scanner.manager:manager.py:178 EMIT DNS_NAME("www.example.com", module=TARGET, tags={'in-scope', 'subdomain', 'target'}) 1
2023-11-21T18:15:06.2730626Z DEBUG    bbot.scanner.manager:manager.py:203 EMIT DNS_NAME("www.example.com", module=TARGET, tags={'in-scope', 'subdomain', 'target'}) 2
2023-11-21T18:15:06.2733706Z DEBUG    bbot.scanner.manager:manager.py:213 EMIT DNS_NAME("www.example.com", module=TARGET, tags={'in-scope', 'subdomain', 'target'}) 3
2023-11-21T18:15:06.2740764Z DEBUG    bbot.scanner.manager:manager.py:231 EMIT DNS_NAME("www.example.com", module=TARGET, tags={'subdomain', 'target', 'in-scope', 'resolved'}) 4
2023-11-21T18:15:21.1678064Z INFO     bbot.scanner:scanner.py:897 test_cli_scan: No modules running
2023-11-21T18:15:21.1681357Z INFO     bbot.scanner:scanner.py:897 test_cli_scan: No events produced yet
2023-11-21T18:15:21.1685337Z INFO     bbot.scanner:scanner.py:897 test_cli_scan: No events in queue
2023-11-21T18:15:21.1689450Z DEBUG    bbot.scanner:scanner.py:882 scan._finished_init: True
2023-11-21T18:15:21.1692121Z DEBUG    bbot.scanner:scanner.py:882 manager.active: True
2023-11-21T18:15:21.1695084Z DEBUG    bbot.scanner:scanner.py:882     manager.running: True
2023-11-21T18:15:21.1698095Z DEBUG    bbot.scanner:scanner.py:882         manager._task_counter.value: 2
2023-11-21T18:15:21.1701047Z DEBUG    bbot.scanner:scanner.py:882         manager._task_counter.tasks:
2023-11-21T18:15:21.1705046Z DEBUG    bbot.scanner:scanner.py:882             - emit_event(IP_ADDRESS("127.0.0.1", module=TARGET, tags={'ipv4', 'target', 'in-scope', 'private'})) running for 14 seconds:
2023-11-21T18:15:21.1708103Z DEBUG    bbot.scanner:scanner.py:882             - emit_event(DNS_NAME("www.example.com", module=TARGET, tags={'in-scope', 'subdomain', 'target'})) running for 14 seconds:
2023-11-21T18:15:21.1709929Z DEBUG    bbot.scanner:scanner.py:882         manager.incoming_event_queue.qsize: 0
2023-11-21T18:15:21.1712298Z DEBUG    bbot.scanner:scanner.py:882     manager.modules_finished: True
2023-11-21T18:15:21.1714954Z DEBUG    bbot.scanner:scanner.py:882         csv.finished: True
2023-11-21T18:15:21.1717376Z DEBUG    bbot.scanner:scanner.py:882             running: False
2023-11-21T18:15:21.1719782Z DEBUG    bbot.scanner:scanner.py:882             num_incoming_events: 0
2023-11-21T18:15:21.1722190Z DEBUG    bbot.scanner:scanner.py:882             outgoing_event_queue.qsize: 0
2023-11-21T18:15:21.1724579Z DEBUG    bbot.scanner:scanner.py:882         human.finished: True
2023-11-21T18:15:21.1726892Z DEBUG    bbot.scanner:scanner.py:882             running: False
2023-11-21T18:15:21.1729273Z DEBUG    bbot.scanner:scanner.py:882             num_incoming_events: 0
2023-11-21T18:15:21.1731796Z DEBUG    bbot.scanner:scanner.py:882             outgoing_event_queue.qsize: 0
2023-11-21T18:15:21.1734211Z DEBUG    bbot.scanner:scanner.py:882         json.finished: True
2023-11-21T18:15:21.1736734Z DEBUG    bbot.scanner:scanner.py:882             running: False
2023-11-21T18:15:21.1739226Z DEBUG    bbot.scanner:scanner.py:882             num_incoming_events: 0
2023-11-21T18:15:21.1741659Z DEBUG    bbot.scanner:scanner.py:882             outgoing_event_queue.qsize: 0
2023-11-21T18:15:21.1764022Z DEBUG    bbot.scanner:scanner.py:882 MODULE MEMORY USAGE:
2023-11-21T18:15:21.1767099Z DEBUG    bbot.scanner:scanner.py:882     - csv: 3.25KB
2023-11-21T18:15:21.1769669Z DEBUG    bbot.scanner:scanner.py:882     - human: 2.76KB
2023-11-21T18:15:21.1772288Z DEBUG    bbot.scanner:scanner.py:882     - json: 2.76KB

The culprit appears to be cloudcheck:

log.debug(f"EMIT {event} 4")

# DNS_NAME --> DNS_NAME_UNRESOLVED
if event.type == "DNS_NAME" and "unresolved" in event.tags and not "target" in event.tags:
    event.type = "DNS_NAME_UNRESOLVED"

# Cloud tagging
await self.scan.helpers.cloud.tag_event(event)

log.debug(f"EMIT {event} 5")

The call to cloudcheck happens here:

async def tag_event(self, event):
    """
    Tags an event according to cloud provider
    """
    async with self._update_lock:
        if not self._updated:
            await self.providers.update()
            self._updated = True

I have tried very hard to replicate this by stress-testing httpx, both with very large files, small timeouts, and an unreliable network connection. But I can't get it to trigger.

I've considered various other possibilities, like maybe it's a bug in pytest or pytest-httpx (I've stress-tested these, too), or the cancellation of a previous scan during the agent tests somehow contributed to it. I've also thought that maybe the large number of hostnames got from a PTR query against 127.0.0.1 could be causing the issue.

TheTechromancer commented 8 months ago

Today this happened again on python 3.11. The following traceback was printed when the test_cli_scan test timed out:

+++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++

~~~~~~~~~~~~~~~~~~~~~ Stack of asyncio_0 (140696529573440) ~~~~~~~~~~~~~~~~~~~~~
  File "/opt/hostedtoolcache/Python/3.11.6/x64/lib/python3.11/threading.py", line 1002, in _bootstrap
    self._bootstrap_inner()
  File "/opt/hostedtoolcache/Python/3.11.6/x64/lib/python3.11/threading.py", line 1045, in _bootstrap_inner
    self.run()
  File "/opt/hostedtoolcache/Python/3.11.6/x64/lib/python3.11/threading.py", line 982, in run
    self._target(*self._args, **self._kwargs)
  File "/opt/hostedtoolcache/Python/3.11.6/x64/lib/python3.11/concurrent/futures/thread.py", line 81, in _worker
    work_item = work_queue.get(block=True)

+++++++++++++++++++++++++++++++++++ Timeout ++++++++++++++++++++++++++++++++++++
TheTechromancer commented 6 months ago

Finally was able to track this down!

WARNING  bbot.scanner.manager:manager.py:119 Timeout after 300 seconds while emitting event DNS_NAME("www.example.com", module=TARGET, tags={'subdomain', 'in-scope', 'resolved', 'target'}) (args=(), kwargs={})
TRACE    bbot.scanner:scanner.py:937 Traceback (most recent call last):
  File "/home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.10/lib/python3.10/site-packages/anyio/_core/_synchronization.py", line 125, in acquire
    self.acquire_nowait()
  File "/home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.10/lib/python3.10/site-packages/anyio/_core/_synchronization.py", line 161, in acquire_nowait
    raise WouldBlock
anyio.WouldBlock

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/runner/work/bbot/bbot/bbot/scanner/manager.py", line 238, in _emit_event
    await self.scan.helpers.cloud.tag_event(event)
  File "/home/runner/work/bbot/bbot/bbot/core/helpers/cloud.py", line 83, in tag_event
    await self.providers.update()
  File "/home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.10/lib/python3.10/site-packages/cloudcheck/providers/__init__.py", line 80, in update
    response = await self.httpx_client.get(self.json_url)
  File "/home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.10/lib/python3.10/site-packages/httpx/_client.py", line 1757, in get
    return await self.request(
  File "/home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.10/lib/python3.10/site-packages/httpx/_client.py", line 1530, in request
    return await self.send(request, auth=auth, follow_redirects=follow_redirects)
  File "/home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.10/lib/python3.10/site-packages/httpx/_client.py", line 1617, in send
    response = await self._send_handling_auth(
  File "/home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.10/lib/python3.10/site-packages/httpx/_client.py", line 1645, in _send_handling_auth
    response = await self._send_handling_redirects(
  File "/home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.10/lib/python3.10/site-packages/httpx/_client.py", line 1682, in _send_handling_redirects
    response = await self._send_single_request(request)
  File "/home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.10/lib/python3.10/site-packages/httpx/_client.py", line 1719, in _send_single_request
    response = await transport.handle_async_request(request)
  File "/home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.10/lib/python3.10/site-packages/httpx/_transports/default.py", line 366, in handle_async_request
    resp = await self._pool.handle_async_request(req)
  File "/home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.10/lib/python3.10/site-packages/httpcore/_async/connection_pool.py", line 224, in handle_async_request
    async with self._pool_lock:
  File "/home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.10/lib/python3.10/site-packages/httpcore/_synchronization.py", line 53, in __aenter__
    await self._anyio_lock.acquire()
  File "/home/runner/.cache/pypoetry/virtualenvs/bbot-pd-UZ8Fz-py3.10/lib/python3.10/site-packages/anyio/_core/_synchronization.py", line 132, in acquire
    await event.wait()
  File "/opt/hostedtoolcache/Python/3.10.13/x64/lib/python3.10/asyncio/locks.py", line 214, in wait
    await fut
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/hostedtoolcache/Python/3.10.13/x64/lib/python3.10/asyncio/tasks.py", line 456, in wait_for
    return fut.result()
asyncio.exceptions.CancelledError

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

Traceback (most recent call last):
  File "/home/runner/work/bbot/bbot/bbot/scanner/manager.py", line 110, in emit_event
    await asyncio.wait_for(
  File "/opt/hostedtoolcache/Python/3.10.13/x64/lib/python3.10/asyncio/tasks.py", line 458, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError
TheTechromancer commented 6 months ago

Fixed by upgrading httpx/anyio version (https://github.com/blacklanternsecurity/bbot/pull/980). Interestingly, this also reduced the amount of test time from ~30 minutes to ~20, with the exception of Python 3.12, which still takes 30 minutes.