BBOT Scan Fails to Finish Due to Internal Task Counter

[TheTechromancer]

We need to figure out why the task counter is failing to decrement in some cases.

[INFO] Setting log level to DEBUG
[INFO] suspicious_debra: Events produced so far: IP_ADDRESS: 106521, DNS_NAME: 26187, URL_UNVERIFIED: 22955, OPEN_TCP_PORT: 19598, TECHNOLOGY: 12940, URL: 11885, HTTP_RESPONSE: 11885, DNS_NAME_UNRESOLVED: 9831, FINDING: 2776, EMAIL_ADDRESS: 1940, VULNERABILITY: 549, ASN: 306, STORAGE_BUCKET: 124, IP_RANGE: 20, PROTOCOL: 7
[VERB] suspicious_debra: Modules errored: 1 (hackertarget)
[INFO] suspicious_debra: No events in queue
[DBUG] scan._finished_init: True
[DBUG] manager.active: True
[DBUG]     manager.running: True
[DBUG]         manager._task_counter.value: 13   <-----------------------------------------
[DBUG]         manager.incoming_event_queue.qsize(): 0
[DBUG]     manager.modules_finished: True
[DBUG]         httpx.finished: True
[DBUG]             running: False
[DBUG]             num_incoming_events: 0
[DBUG]             outgoing_event_queue.qsize(): 0
[DBUG]         naabu.finished: True
[DBUG]             running: False
[DBUG]             num_incoming_events: 0
[DBUG]             outgoing_event_queue.qsize(): 0
[DBUG]         sslcert.finished: True
[DBUG]             running: False
[DBUG]             num_incoming_events: 0
[DBUG]             outgoing_event_queue.qsize(): 0

[TheTechromancer]

This should hopefully be fixed in 492e9e14af4aa63e10b6712d837073c63ff85f4b. Leaving open for a while until we're sure it's fixed.

[TheTechromancer]

On closer examination this issue appears to be due to an unexpected asyncio.CancelledError which is causing modules to stop.

$ cat -n pink_taylor | grep -i 'worker cancel' 
 13009  2023-07-24 18:14:16,943 [TRACE] bbot.modules.asn logger.py:90 Worker cancelled
 13029  2023-07-24 18:14:17,082 [TRACE] bbot.modules.emailformat logger.py:90 Worker cancelled
 13030  2023-07-24 18:14:17,085 [TRACE] bbot.modules.iis_shortnames logger.py:90 Worker cancelled
 13035  2023-07-24 18:14:17,140 [TRACE] bbot.modules.iis_shortnames logger.py:90 Worker cancelled
 13036  2023-07-24 18:14:17,154 [TRACE] bbot.modules.iis_shortnames logger.py:90 Worker cancelled
 13037  2023-07-24 18:14:17,157 [TRACE] bbot.modules.azure_tenant logger.py:90 Worker cancelled
 13038  2023-07-24 18:14:17,161 [TRACE] bbot.modules.bucket_firebase logger.py:90 Worker cancelled
 13041  2023-07-24 18:14:17,210 [TRACE] bbot.modules.iis_shortnames logger.py:90 Worker cancelled
 13042  2023-07-24 18:14:17,212 [TRACE] bbot.modules.iis_shortnames logger.py:90 Worker cancelled
 13043  2023-07-24 18:14:17,232 [TRACE] bbot.modules.azure_realm logger.py:90 Worker cancelled
 13044  2023-07-24 18:14:17,362 [TRACE] bbot.modules.bucket_gcp logger.py:90 Worker cancelled
579178  2023-07-24 18:46:34,631 [TRACE] bbot.modules.bucket_digitalocean logger.py:90 Worker cancelled
579226  2023-07-24 18:46:35,343 [TRACE] bbot.modules.iis_shortnames logger.py:90 Worker cancelled
716013  2023-07-24 18:58:22,261 [TRACE] bbot.modules.iis_shortnames logger.py:90 Worker cancelled
1308279 2023-07-24 19:30:53,277 [TRACE] bbot.modules.bucket_aws logger.py:90 Worker cancelled
1559799 2023-07-24 19:39:47,426 [TRACE] bbot.modules.git logger.py:90 Worker cancelled
2511949 2023-07-24 20:19:18,268 [TRACE] bbot.modules.iis_shortnames logger.py:90 Worker cancelled

Each of these modules are using the request() helper, however they are also using as_completed(), which is interesting . I think we may have found a rare race condition in that function.

[TheTechromancer]

Okay. This was due to a rare race condition bug in Python's built-in asyncio.as_completed(), which apparently has already caused so many problems they've decided to deprecate it rather than fix it.

This is fixed in https://github.com/blacklanternsecurity/bbot/pull/607/commits/f58167d3a7cae0faf2bd804417875c7ed218f870.

The solution was to write our own custom asynchronous as_completed(). This should actually result in a considerable performance boost. 🔥