Scan Slowness #901

TheTechromancer · 2023-12-08T16:10:58Z

During some very large scans, the scan can gradually slow to a crawl. I ran into this issue use_previous from the asset_inventory module, where after a certain point, the events slowed to the point of being output in small spurts of ~25 every 5-10 seconds.

The text was updated successfully, but these errors were encountered:

TheTechromancer · 2023-12-08T20:11:54Z

[INFO] asset_inventory: Modules running (incoming:processing:outgoing) nmap(93,408:2:20,929), asset_inventory(5:0:64,583), csv(5:0:0), human(5:0:0), json(5:0:0)                                                                                                                                                             
[INFO] asset_inventory: Events produced so far: IP_ADDRESS: 144009, OPEN_TCP_PORT: 124869, DNS_NAME: 12149, DNS_NAME_UNRESOLVED: 2500, IP_RANGE: 1727                                                                                                                                                                        
[INFO] asset_inventory: 85,513 events in queue (DNS_NAME: 32,443, IP_ADDRESS: 32,141, OPEN_TCP_PORT: 20,929)                                                                                                                                                                                                                 
[DBUG] scan._finished_init: True                                                                                                                                                                                                                                                                                             
[DBUG] manager.active: True                                                                                                                                                                                                                                                                                                  
[DBUG]     manager.running: True                                                                                                                                                                                                                                                                                             
[DBUG]         manager._task_counter.value: 25                                                                                                                                                                                                                                                                               
[DBUG]         manager._task_counter.tasks:                                                                                                                                                                                                                                                                                  
[DBUG]             - emit_event(IP_ADDRESS("1.2.3.4", module=A, tags={'ipv4', 'distance-1'})) running for 5 seconds:                                                                                                                                                                                                  
[DBUG]             - emit_event(DNS_NAME("a.evilcorp.com", module=PTR, tags={'distance-1', 'subdomain'})) running for 5 seconds:                                                                                                                                                                                
[DBUG]             - emit_event(DNS_NAME("b.evilcorp.com", module=PTR, tags={'distance-1', 'subdomain'})) running for 5 seconds:                                                                                                                                                                                     
[DBUG]             - emit_event(DNS_NAME("c.evilcorp.com", module=PTR, tags={'distance-1', 'subdomain'})) running for 5 seconds:                                                                                                                                                                                   
[DBUG]             - emit_event(DNS_NAME("c.evilcorp.com", module=PTR, tags={'distance-1', 'subdomain'})) running for 5 seconds:                                                                                                                                                                                   
[DBUG]             - emit_event(IP_ADDRESS("4.3.2.1", module=asset_inventory, tags={'ipv4', 'distance-1'})) running for 5 seconds:                                                                                                                                                                                      
[DBUG]             - emit_event(DNS_NAME("d.evilcorp.com", module=PTR, tags={'distance-1', 'subdomain'})) running for 4 seconds:                                                                                                                                                                                   
[DBUG]             - emit_event(DNS_NAME("f.evilcorp.com", module=PTR, tags={'distance-1', 'subdomain'})) running for 4 seconds:                                                                                                                                                                                     
[DBUG]             - emit_event(IP_ADDRESS("5.6.6.8", module=asset_inventory, tags={'ipv4', 'distance-1'})) running for 4 seconds:                                                                                                                                                                                     
[DBUG]             - emit_event(IP_ADDRESS("2.3.4.5", module=asset_inventory, tags={'ipv4', 'distance-1'})) running for 3 seconds:                                                                                                                                                                                     
[DBUG]             - emit_event(OPEN_TCP_PORT("10.20.19.113:5985", module=nmap, tags={'in-scope'})) running for 3 seconds:                                                                                                                                                                                                   
[DBUG]             - emit_event(OPEN_TCP_PORT("10.20.19.113:8089", module=nmap, tags={'in-scope'})) running for 3 seconds:                                                                                                                                                                                                   
[DBUG]             - emit_event(IP_ADDRESS("7.5.4.3", module=asset_inventory, tags={'ipv4', 'distance-1'})) running for 3 seconds:                                                                                                                                                                                     
[DBUG]             - emit_event(IP_ADDRESS("8.7.6.5", module=asset_inventory, tags={'ipv4', 'distance-1'})) running for 3 seconds:                                                                                                                                                                                     
[DBUG]             - emit_event(OPEN_TCP_PORT("10.20.19.113:47001", module=nmap, tags={'in-scope'})) running for 3 seconds:                                                                                                                                                                                                  
[DBUG]             - emit_event(OPEN_TCP_PORT("10.20.19.114:80", module=nmap, tags={'in-scope'})) running for 3 seconds:                                                                                                                                                                                                     
[DBUG]             - emit_event(OPEN_TCP_PORT("10.20.19.114:443", module=nmap, tags={'in-scope'})) running for 3 seconds:                                                                                                                                                                                                    
[DBUG]             - emit_event(OPEN_TCP_PORT("10.20.19.114:445", module=nmap, tags={'in-scope'})) running for 3 seconds:                                                                                                                                                                                                    
[DBUG]             - emit_event(OPEN_TCP_PORT("10.20.19.114:3389", module=nmap, tags={'in-scope'})) running for 3 seconds:                                                                                                                                                                                                   
[DBUG]             - emit_event(DNS_NAME("g.evilcorp.com", module=PTR, tags={'distance-1', 'subdomain'})) running for 2 seconds:                                                                                                                                                                         
[DBUG]             - emit_event(OPEN_TCP_PORT("10.20.19.114:5985", module=nmap, tags={'in-scope'})) running for 1 second:                                                                                                                                                                                                    
[DBUG]             - emit_event(DNS_NAME("h.evilcorp.com", module=PTR, tags={'distance-1', 'subdomain'})) running for 1 second:                                                                                                                                                                          
[DBUG]             - emit_event(OPEN_TCP_PORT("10.20.19.114:8089", module=nmap, tags={'in-scope'})) running for 1 second:                                                                                                                                                                                                    
[DBUG]             - emit_event(IP_ADDRESS("9.8.7.6", module=asset_inventory, tags={'ipv4', 'distance-1'})) running for 1 second:                                                                                                                                                                                      
[DBUG]             - emit_event(OPEN_TCP_PORT("10.20.19.114:47001", module=nmap, tags={'in-scope'})) running for 1 second:

CPU during this time is 100%, and I suspect this is the issue.

TheTechromancer · 2023-12-08T20:20:27Z

I heavily suspect the priorityqueues.

EDIT: did some testing on priorityqueue and it is performant even up to very large sizes. I think the problem is that we're iterating through them in order to provide status messages.

TheTechromancer · 2023-12-08T21:40:53Z

Removing the status messages did not speed up the scan. In my tests, iterating through 200K+ objects was basically instantaneous. CPU is still at 100%, so I think it will pay to do some profiling to find the top offending function calls.

TheTechromancer · 2023-12-20T04:10:03Z

Ran a baseline test where I loaded a bunch of IP addresses from asset_inventory with use_previous=true and dns_resolution=false. 230K events in 10 minutes with no sign of slowdown. Roughly that is 23K per minute, or ~380 per second, which is pretty good.

CPU was 100% during this time and cProfile reveals that the vast majority of CPU time was taken up by the ipaddress library:

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     5121    4.614    0.001    4.614    0.001 {method 'poll' of 'select.epoll' objects}
  2836076    2.075    0.000    2.635    0.000 ipaddress.py:1209(_parse_octet)
  2354797    1.584    0.000    2.159    0.000 ipaddress.py:736(__hash__)
   596446    1.481    0.000    7.374    0.000 ipaddress.py:1475(__init__)
  2071040    0.996    0.000    3.002    0.000 cidr.py:32(__contains__)
  1217496    0.901    0.000    5.260    0.000 ipaddress.py:1282(__init__)
7731367/7730573    0.804    0.000    1.104    0.000 {built-in method builtins.isinstance}
     8090    0.736    0.000    8.937    0.001 __init__.py:63(check_ip)
   837322    0.699    0.000    3.334    0.000 {built-in method from_bytes}
   711682    0.617    0.000    4.097    0.000 ipaddress.py:1183(_ip_int_from_string)
   196702    0.578    0.000    0.773    0.000 base.py:700(__str__)
  6416412    0.544    0.000    0.544    0.000 ipaddress.py:574(__int__)
     8092    0.530    0.000    5.469    0.001 target.py:186(get)
  2071040    0.529    0.000    3.531    0.000 base.py:129(__contains__)
   599135    0.506    0.000    1.331    0.000 ipaddress.py:533(_split_addr_prefix)
6167358/6146576    0.461    0.000    0.467    0.000 {built-in method builtins.len}
   637676    0.419    0.000    0.904    0.000 ipaddress.py:1245(_string_from_ip_int)
688772/684807    0.401    0.000    0.431    0.000 {method 'join' of 'str' objects}
    13816    0.342    0.000    1.056    0.000 misc.py:2412(weighted_shuffle)

The thing to do now is to add DNS resolution and see if anything changes.

TheTechromancer · 2023-12-20T04:23:22Z

On enabling DNS, CPU ceases to be the bottleneck. I suspect the answer here is just to run a giant internet scan and profile it.

TheTechromancer · 2023-12-23T21:17:10Z

Ran a simple scan on a Linode with 2 CPUs and 4GB RAM:

poetry run bbot -t targets.txt -f subdomain-enum email-enum cloud-enum

Almost immediately the scan became unresponsive. CPU was at 0%, no memory usage to speak of. Pressing enter on the console had no effect, but after thirty seconds or so there would be a flurry of DNS timeouts relating to wildcard detection and the scan would register the keypresses, then it would return to being unresponsive.

There is no good reason it should be behaving this way. I suspect it's something to do with the asyncio event loop getting overwhelmed; but I'm not sure how this is possible.

I intend to start ripping out locks and rate limits until it starts to behave more properly.

[DBUG] scan._finished_init: True
[DBUG] manager.active: True
[DBUG]     manager.running: True
[DBUG]         manager._task_counter.value: 25
[DBUG]         manager._task_counter.tasks:
[DBUG]             - emit_event(DNS_NAME("vote.evilcorp.net", module=TARGET, tags={'target', 'subdomain', 'in-scope'})) running for 4 minutes, 44 seconds:
[DBUG]             - emit_event(DNS_NAME("dro.evilcorp.net", module=TARGET, tags={'target', 'subdomain', 'in-scope'})) running for 4 minutes, 44 seconds:
[DBUG]             - emit_event(DNS_NAME("ifs.evilcorp.net", module=TARGET, tags={'target', 'subdomain', 'in-scope'})) running for 4 minutes, 44 seconds:
[DBUG]             - emit_event(DNS_NAME("iga.evilcorp.net", module=TARGET, tags={'target', 'subdomain', 'in-scope'})) running for 4 minutes, 44 seconds:
[DBUG]             - emit_event(DNS_NAME("phs.evilcorp.net", module=TARGET, tags={'target', 'subdomain', 'in-scope'})) running for 4 minutes, 44 seconds:
[DBUG]             - emit_event(DNS_NAME("cn2.evilcorp.net", module=TARGET, tags={'target', 'subdomain', 'in-scope'})) running for 4 minutes, 44 seconds:
[DBUG]             - emit_event(DNS_NAME("pts.evilcorp.net", module=TARGET, tags={'target', 'subdomain', 'in-scope'})) running for 4 minutes, 44 seconds:
[DBUG]             - emit_event(DNS_NAME("hsg.evilcorp.net", module=TARGET, tags={'target', 'subdomain', 'in-scope'})) running for 4 minutes, 44 seconds:
[DBUG]             - emit_event(DNS_NAME("hcfcd.co.evilcorp.tx.us", module=TARGET, tags={'target', 'subdomain', 'in-scope'})) running for 4 minutes, 44 seconds:
[DBUG]             - emit_event(DNS_NAME("itc.co.evilcorp.tx.us", module=TARGET, tags={'target', 'subdomain', 'in-scope'})) running for 4 minutes, 44 seconds:
[DBUG]             - emit_event(DNS_NAME("cd4.evilcorp.net", module=TARGET, tags={'target', 'subdomain', 'in-scope'})) running for 4 minutes, 44 seconds:
[DBUG]             - emit_event(DNS_NAME("vso.evilcorp.net", module=TARGET, tags={'target', 'subdomain', 'in-scope'})) running for 4 minutes, 44 seconds:
[DBUG]             - emit_event(DNS_NAME("pct2.evilcorp.net", module=TARGET, tags={'target', 'subdomain', 'in-scope'})) running for 4 minutes, 42 seconds:
[DBUG]             - emit_event(URL_UNVERIFIED("https://adfs.hc.evilcorp.net/adfs/ls/", module=azure_realm, tags={'affiliate', 'distance-1', 'dir', 'ms-auth-url'})) running for 4 minutes, 36 seconds:
[DBUG]             - emit_event(DNS_NAME("www.evilcorp.org", module=leakix, tags={'subdomain', 'distance-1'})) running for 2 minutes, 41 seconds:
[DBUG]             - emit_event(DNS_NAME("www.evilcorp.org", module=sitedossier, tags={'subdomain', 'distance-1'})) running for 2 minutes, 41 seconds:
[DBUG]             - emit_event(DNS_NAME("www.evilcorp.org", module=otx, tags={'subdomain', 'distance-1'})) running for 2 minutes, 41 seconds:
[DBUG]             - emit_event(DNS_NAME("www.evilcorp.org", module=wayback, tags={'subdomain', 'distance-1'})) running for 2 minutes, 41 seconds:
[DBUG]             - emit_event(DNS_NAME("www.co.evilcorp.tx.us", module=urlscan, tags={'subdomain', 'distance-1'})) running for 2 minutes:
[DBUG]             - emit_event(DNS_NAME("ds9.hchcda.co.evilcorp.tx.us", module=hackertarget, tags={'subdomain', 'distance-1'})) running for 2 minutes:
[DBUG]             - emit_event(DNS_NAME("ftp.evilcorp.org", module=massdns, tags={'subdomain', 'distance-1'})) running for 2 minutes:
[DBUG]             - emit_event(DNS_NAME("www.evilcorp.org", module=columbus, tags={'subdomain', 'distance-1'})) running for 2 minutes:
[DBUG]             - emit_event(DNS_NAME("www.co.evilcorp.tx.us", module=urlscan, tags={'subdomain', 'distance-1'})) running for 1 minute, 40 seconds:
[DBUG]             - emit_event(DNS_NAME("azure-mobile.net", module=sslcert, tags={'distance-1', 'domain'})) running for 20 seconds:
[DBUG]             - emit_event(DNS_NAME("hco.hc.evilcorp.net", module=TARGET, tags={'target', 'subdomain', 'in-scope'})) running for 20 seconds:
[DBUG]         manager.incoming_event_queue.qsize: 218
[DBUG]     manager.modules_finished: False
[DBUG]         aggregate.finished: True
[DBUG]             running: False
[DBUG]             num_incoming_events: 0
[DBUG]             outgoing_event_queue.qsize: 0
[DBUG]         anubisdb.finished: False
[DBUG]             running: True
[DBUG]             tasks:
[DBUG]                 - event_postcheck(DNS_NAME("hcfcd.evilcorp.net", module=TARGET, tags={'mx-record', 'ns-error', 'mx-error', 'in-scope', 'soa-error', 'txt-error', 'subdomain', 'a-error', 'cname-error', 'aaaa-error', 'srv-error', 'target', 'resolved', 'txt-record'})) running for 2 minutes, 41 seconds:
[DBUG]             num_incoming_events: 19
[DBUG]             outgoing_event_queue.qsize: 0
[DBUG]         asn.finished: True
[DBUG]             running: False
[DBUG]             num_incoming_events: 0
[DBUG]             outgoing_event_queue.qsize: 0
[DBUG]         azure_realm.finished: True
[DBUG]             running: False
[DBUG]             num_incoming_events: 0
[DBUG]             outgoing_event_queue.qsize: 0
[DBUG]         azure_tenant.finished: False
[DBUG]             running: True
[DBUG]             tasks:
[DBUG]                 - azure_tenant.handle_event(DNS_NAME("evilcorp.org", module=TARGET, tags={'mx-record', 'ns-record', 'a-record', 'mx-error', 'in-scope', 'cname-error', 'soa-record', 'target', 'resolved', 'txt-record', 'domain'})) running for 2 minutes:
[DBUG]             num_incoming_events: 5
[DBUG]             outgoing_event_queue.qsize: 366
[DBUG]         bucket_amazon.finished: False
[DBUG]             running: True
[DBUG]             tasks:
[DBUG]                 - bucket_amazon.handle_event(DNS_NAME("csd.evilcorp.net", module=azure_tenant, tags={'azure-tenant', 'ns-record', 'in-scope', 'subdomain', 'a-error', 'aaaa-error', 'srv-error', 'soa-record', 'cname-error', 'txt-record', 'resolved', 'mx-record'})) running for 2 minutes:
[DBUG]             num_incoming_events: 14
[DBUG]             outgoing_event_queue.qsize: 0
[DBUG]         bucket_azure.finished: False
[DBUG]             running: True
[DBUG]             tasks:
[DBUG]                 - bucket_azure.handle_event(DNS_NAME("fpm.evilcorp.net", module=azure_tenant, tags={'azure-tenant', 'ns-error', 'ns-record', 'mx-error', 'in-scope', 'soa-error', 'subdomain', 'aaaa-error', 'cname-error', 'soa-record', 'txt-record', 'resolved', 'mx-record'})) running for 20 seconds:
[DBUG]             num_incoming_events: 1
[DBUG]             outgoing_event_queue.qsize: 0
[DBUG]         bucket_digitalocean.finished: False
[DBUG]             running: True
[DBUG]             tasks:
[DBUG]                 - bucket_digitalocean.handle_event(DNS_NAME("cn5.evilcorp.net", module=TARGET, tags={'mx-record', 'ns-error', 'ns-record', 'in-scope', 'subdomain', 'srv-error', 'soa-record', 'target', 'resolved', 'txt-record'})) running for 2 minutes, 1 second:
[DBUG]             num_incoming_events: 19
[DBUG]             outgoing_event_queue.qsize: 0
[DBUG]         bucket_file_enum.finished: True
[DBUG]             running: False
[DBUG]             num_incoming_events: 0
[DBUG]             outgoing_event_queue.qsize: 0
[DBUG]         bucket_firebase.finished: False
[DBUG]             running: True
[DBUG]             tasks:
[DBUG]                 - bucket_firebase.handle_event(DNS_NAME("csc.evilcorp.net", module=TARGET, tags={'mx-record', 'ns-record', 'in-scope', 'soa-error', 'txt-error', 'subdomain', 'cname-error', 'srv-error', 'target', 'resolved', 'txt-record'})) running for 2 minutes:
[DBUG]             num_incoming_events: 16
[DBUG]             outgoing_event_queue.qsize: 0
[DBUG]         bucket_google.finished: False
[DBUG]             running: True
[DBUG]             tasks:
[DBUG]                 - bucket_google.handle_event(DNS_NAME("cn5.evilcorp.net", module=TARGET, tags={'mx-record', 'ns-error', 'ns-record', 'in-scope', 'subdomain', 'srv-error', 'soa-record', 'target', 'resolved', 'txt-record'})) running for 2 minutes:
[DBUG]             num_incoming_events: 18
[DBUG]             outgoing_event_queue.qsize: 0
[DBUG]         certspotter.finished: False
[DBUG]             running: True
[DBUG]             tasks:
[DBUG]                 - event_postcheck(DNS_NAME("cn5.evilcorp.net", module=TARGET, tags={'mx-record', 'ns-error', 'ns-record', 'in-scope', 'subdomain', 'srv-error', 'soa-record', 'target', 'resolved', 'txt-record'})) running for 2 minutes, 41 seconds:
[DBUG]             num_incoming_events: 18
[DBUG]             outgoing_event_queue.qsize: 0
[DBUG]         columbus.finished: False
[DBUG]             running: True
[DBUG]             tasks:
[DBUG]                 - event_postcheck(DNS_NAME("csc.evilcorp.net", module=TARGET, tags={'mx-record', 'ns-record', 'in-scope', 'soa-error', 'txt-error', 'subdomain', 'cname-error', 'srv-error', 'target', 'resolved', 'txt-record'})) running for 2 minutes:
[DBUG]             num_incoming_events: 25
[DBUG]             outgoing_event_queue.qsize: 0
[DBUG]         crt.finished: False
[DBUG]             running: False
[DBUG]             num_incoming_events: 26
[DBUG]             outgoing_event_queue.qsize: 7
[DBUG]         csv.finished: True
[DBUG]             running: False
[DBUG]             num_incoming_events: 0
[DBUG]             outgoing_event_queue.qsize: 0
[DBUG]         digitorus.finished: False
[DBUG]             running: False
[DBUG]             num_incoming_events: 20
[DBUG]             outgoing_event_queue.qsize: 2
[DBUG]         dnscommonsrv.finished: False
[DBUG]             running: True
[DBUG]             tasks:
[DBUG]                 - dnscommonsrv.handle_event(DNS_NAME("webdisk.evilcorp.org", module=crt, tags={'a-record', 'in-scope', 'subdomain', 'resolved'})) running for 1 minute, 50 seconds:
[DBUG]                 - event_postcheck(DNS_NAME("hcfcd.evilcorp.net", module=TARGET, tags={'mx-record', 'ns-error', 'mx-error', 'in-scope', 'soa-error', 'txt-error', 'subdomain', 'a-error', 'cname-error', 'aaaa-error', 'srv-error', 'target', 'resolved', 'txt-record'})) running for 1 minute, 10 seconds:
[DBUG]                 - event_postcheck(DNS_NAME("hcjpd.evilcorp.net", module=TARGET, tags={'ns-error', 'mx-error', 'in-scope', 'soa-error', 'txt-error', 'subdomain', 'cname-error', 'soa-record', 'target', 'resolved', 'txt-record'})) running for 1 minute, 10 seconds:
[DBUG]                 - event_postcheck(DNS_NAME("cpcalendars.evilcorp.org", module=dnsdumpster, tags={'a-record', 'in-scope', 'subdomain', 'resolved'})) running for 1 minute, 10 seconds:
[DBUG]                 - event_postcheck(DNS_NAME("webdisk.evilcorp.org", module=subdomaincenter, tags={'a-record', 'in-scope', 'subdomain', 'resolved'})) running for 20 seconds:
[DBUG]             num_incoming_events: 9
[DBUG]             outgoing_event_queue.qsize: 8
[DBUG]         dnsdumpster.finished: False
[DBUG]             running: False
[DBUG]             num_incoming_events: 26
[DBUG]             outgoing_event_queue.qsize: 1

TheTechromancer · 2023-12-23T21:51:12Z

Keeping track of my troubleshooting steps here:

rebooted server, updated bbot
- no difference
set 4x standard dns servers in /etc/resolv.conf, made immutable, still encountered issue.
- no difference
disabled all dns locks and rate limiter
- no difference
disabled first half of modules: anubisdb,asn,azure_realm,azure_tenant,bevigil,binaryedge,bucket_amazon,bucket_azure,bucket_digitalocean,bucket_file_enum,bucket_firebase,bucket_google,builtwith,c99,censys,certspotter,chaos,columbus,crt,dehashed,digitorus,dnscommonsrv,dnsdumpster,dnszonetransfer,emailformat
- huge difference - scan is much faster!
disabled second half of modules: fullhunt,github_codesearch,github_org,hackertarget,httpx,hunterio,ipneighbor,leakix,massdns,myssl,nsec,oauth,otx,passivetotal,pgp,rapiddns,riddler,securitytrails,shodan_dns,sitedossier,skymem,sslcert,subdomain_hijack,subdomaincenter,threatminer,urlscan,virustotal,wayback,zoomeye
- no difference

This indicates that one of the modules is causing the issue, most likely it is holding up the event loop (naughty naughty!)

TheTechromancer · 2023-12-23T22:07:58Z

Let's play a game: which of these modules is the naughty one?

BAD:
  GOOD:
    anubisdb asn azure_realm azure_tenant badsecrets bevigil binaryedge bucket_amazon bucket_azure bucket_digitalocean bucket_file_enum bucket_firebase bucket_google  
  BAD:
    GOOD:
      c99 censys certspotter chaos columbus crt dehashed digitorus
    BAD:
      GOOD:
        filedownload fullhunt git github_codesearch
      BAD:
        GOOD:
          dnscommonsrv dnsdumpster
        BAD:
          GOOD:
            emailformat
          BAD:
            dnszonetransfer

dnszonetransfer....you motherfucker.

TheTechromancer · 2023-12-26T00:09:47Z

Ran a big internet scan with PYTHONASYNCIODEBUG=1, and these are the problematic function calls:

    122 DNSHelper.resolve_raw()
    107 DNSHelper.resolve()
     95 DNSHelper._resolve_batch_coro_wrapper()
     89 ScanManager._worker_loop()
     44 bucket_template._check_bucket_exists()
     24 excavate.handle_event()
     17 telerik.test_detector()
     17 dnscommonsrv.handle_event()
     13 BaseModule._worker()
      7 telerik.handle_event()
      6 subdomain_enum.handle_event()
      6 httpx.handle_batch()
      5 url_manipulation.handle_event()
      4 wayback.handle_event()
      4 wappalyzer.handle_event()
      4 filedownload.handle_event()
      4 connect_tcp.
      4 bucket_template.handle_event()
      3 sslcert.handle_event()
      3 generic_ssrf.handle_event()
      2 ipneighbor.handle_event()
      2 host_header.handle_event()
      2 bypass403.handle_event()
      1 massdns.handle_event()
      1 _main()
      1 git.get_url()

And the problematic files:

    319 running at /root/bbot/bbot/core/helpers/dns.py
     89 running at /root/bbot/bbot/scanner/manager.py
     48 running at /root/bbot/bbot/modules/templates/bucket.py
     24 running at /root/bbot/bbot/modules/telerik.py
     24 running at /root/bbot/bbot/modules/internal/excavate.py
     17 running at /root/bbot/bbot/modules/dnscommonsrv.py
     13 running at /root/bbot/bbot/modules/base.py
      6 running at /root/bbot/bbot/modules/httpx.py
      4 running at /root/.cache/pypoetry/virtualenvs/bbot-aKeTQkGo-py3.11/lib/python3.11/site-packages/anyio/_core/_sockets.py
      4 running at /root/bbot/bbot/modules/wappalyzer.py
      4 running at /root/bbot/bbot/modules/filedownload.py
      3 running at /root/bbot/bbot/modules/wayback.py
      3 running at /root/bbot/bbot/modules/sslcert.py
      3 running at /root/bbot/bbot/modules/generic_ssrf.py
      2 running at /root/bbot/bbot/modules/url_manipulation.py
      2 running at /root/bbot/bbot/modules/templates/subdomain_enum.py
      2 running at /root/bbot/bbot/modules/host_header.py
      2 running at /root/bbot/bbot/modules/bypass403.py
      1 running at /root/bbot/bbot/modules/massdns.py
      1 running at /root/bbot/bbot/modules/git.py
      1 running at /root/bbot/bbot/cli.py

Lots of DNS-related stuff. Most of these were only .1 or .2 seconds, and CPU was bumping up against 100% during this time, so it's possible there isn't any bug here, and that the combination of high CPU and such a large volume of DNS requests was the cause of the delays.

TheTechromancer · 2023-12-26T02:19:04Z

cProfile from a long scan:

1696537783 function calls (1690391124 primitive calls) in 1257.065 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
5209300/5208088    6.909    0.000 2467.405    0.000 {method 'run' of '_contextvars.Context' objects}
317026/316999    9.706    0.000 1253.208    0.004 base_events.py:1845(_run_once)
5209299/5208073    4.958    0.000 1216.225    0.000 events.py:78(_run)
1359618/1359428    3.196    0.000  692.357    0.001 dns.py:187(resolve_raw)
1353232/1353043    4.842    0.000  672.900    0.000 dns.py:245(_resolve_hostname)
  1344147    5.552    0.000  609.922    0.000 dns.py:744(_catch)
  1344147    2.491    0.000  594.977    0.000 dns.py:44(resolve)
1056218/1056028    3.432    0.000  584.769    0.001 asyncresolver.py:45(resolve)
  1066723    2.389    0.000  540.482    0.001 dns.py:149(resolve)
1061058/1060868    1.371    0.000  400.416    0.000 nameserver.py:121(async_query)
1039180/1038993    5.032    0.000  393.738    0.000 asyncquery.py:154(udp)
692821/692636    2.416    0.000  237.915    0.000 asyncquery.py:113(receive_udp)
   350561    1.210    0.000  217.554    0.001 message.py:1227(from_wire)
   350561    3.657    0.000  214.164    0.001 message.py:1192(read)
  1051683    4.287    0.000  172.346    0.000 message.py:1096(_get_section)
   435517    0.572    0.000  166.116    0.000 web.py:149(request)
   121637    0.792    0.000  164.176    0.001 manager.py:131(_emit_event)
12652582/12212916   15.370    0.000  141.847    0.000 _immutable_ctx.py:36(nf)
  1815555   22.080    0.000  129.779    0.000 name.py:639(to_wire)
 12212916   11.633    0.000  111.558    0.000 _immutable_ctx.py:62(__init__)
  1712405    5.738    0.000   96.734    0.000 misc.py:193(split_host_port)
   364789    0.628    0.000   96.019    0.000 _client.py:1705(_send_single_request)
   364789    0.639    0.000   94.627    0.000 default.py:347(handle_async_request)
 11820477   19.697    0.000   94.123    0.000 name.py:363(__init__)
   367343    0.610    0.000   92.086    0.000 connection_pool.py:206(handle_async_request)
   592273    1.571    0.000   91.558    0.000 misc.py:260(parent_domain)
   350699    1.880    0.000   91.530    0.000 resolver.py:772(query_result)
  3096516   14.102    0.000   81.641    0.000 message.py:340(find_rrset)
   345677    0.999    0.000   80.670    0.000 resolver.py:261(__init__)
   345677    5.704    0.000   79.568    0.000 message.py:926(resolve_chaining)
   392436    1.314    0.000   79.015    0.000 rdataset.py:100(add)
  3505733    9.310    0.000   76.615    0.000 ipaddress.py:57(ip_network)
   392436    0.574    0.000   76.121    0.000 set.py:49(add)
   321348    0.555    0.000   75.671    0.000 connection.py:60(handle_async_request)
   784872    0.759    0.000   75.546    0.000 rdata.py:390(__hash__)
   784872    0.546    0.000   74.578    0.000 rdata.py:250(to_digestable)
   784872    1.026    0.000   74.032    0.000 rdata.py:220(to_wire)
   350735    2.811    0.000   73.469    0.000 message.py:524(to_wire)
  1475407    1.106    0.000   71.013    0.000 wire.py:54(get_name)
  1475407   11.896    0.000   69.907    0.000 name.py:1028(from_wire_parser)
   685438    1.623    0.000   67.053    0.000 SOA.py:75(_to_wire)
   350735    2.586    0.000   66.429    0.000 renderer.py:137(add_question)
  1752952    8.729    0.000   63.589    0.000 misc.py:593(make_ip_type)
  5002718   14.964    0.000   60.197    0.000 ipaddress.py:28(ip_address)
    20259    3.894    0.000   60.075    0.003 __init__.py:63(check_ip)
   793138    1.047    0.000   57.083    0.000 misc.py:75(is_subdomain)
   618300    2.967    0.000   56.636    0.000 resolver.py:676(next_request)
   392436    2.094    0.000   55.830    0.000 rdata.py:774(from_wire_parser)
    68306    2.436    0.000   51.564    0.001 target.py:186(get)
   145623    2.031    0.000   50.007    0.000 base.py:550(_worker)

TheTechromancer · 2023-12-26T02:34:02Z

The main issue was dnszonetransfer. This has been fixed in #943.

TheTechromancer · 2023-12-26T03:23:11Z

Reopening this because I realized something about the dns calls.

At first I dismissed the high CPU time of the DNS-related functions because there were over 1.3 million calls to _resolve_hostname, and the average percall time was 0.000. But I think there might be a real bug hiding here.

When we enabled PYTHONASYNCIODEBUG, we saw that sometimes the DNS resolutions blocked for an unusual amount of time. I'm thinking it's possible that these problematic ones are hiding amidst all the normal ones.

TheTechromancer · 2024-01-09T20:02:13Z

False alarm on the DNS stuff. Closing, will reopen if needed.

TheTechromancer added the bug Something isn't working label Dec 8, 2023

TheTechromancer added this to the BBOT 1.1.4 - fierce_lantern milestone Dec 8, 2023

TheTechromancer self-assigned this Dec 8, 2023

TheTechromancer mentioned this issue Dec 20, 2023

Speed Improvements #881

Closed

TheTechromancer mentioned this issue Dec 26, 2023

Fix Event Loop Blocks #943

Merged

TheTechromancer closed this as completed Dec 26, 2023

TheTechromancer reopened this Dec 26, 2023

TheTechromancer closed this as completed Jan 9, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Scan Slowness #901

Scan Slowness #901

TheTechromancer commented Dec 8, 2023 •

edited

Loading

TheTechromancer commented Dec 8, 2023 •

edited

Loading

TheTechromancer commented Dec 8, 2023 •

edited

Loading

TheTechromancer commented Dec 8, 2023 •

edited

Loading

TheTechromancer commented Dec 20, 2023

TheTechromancer commented Dec 20, 2023

TheTechromancer commented Dec 23, 2023 •

edited

Loading

TheTechromancer commented Dec 23, 2023 •

edited

Loading

TheTechromancer commented Dec 23, 2023 •

edited

Loading

TheTechromancer commented Dec 26, 2023 •

edited

Loading

TheTechromancer commented Dec 26, 2023

TheTechromancer commented Dec 26, 2023

TheTechromancer commented Dec 26, 2023

TheTechromancer commented Jan 9, 2024

Scan Slowness #901

Scan Slowness #901

Comments

TheTechromancer commented Dec 8, 2023 • edited Loading

TheTechromancer commented Dec 8, 2023 • edited Loading

TheTechromancer commented Dec 8, 2023 • edited Loading

TheTechromancer commented Dec 8, 2023 • edited Loading

TheTechromancer commented Dec 20, 2023

TheTechromancer commented Dec 20, 2023

TheTechromancer commented Dec 23, 2023 • edited Loading

TheTechromancer commented Dec 23, 2023 • edited Loading

TheTechromancer commented Dec 23, 2023 • edited Loading

TheTechromancer commented Dec 26, 2023 • edited Loading

TheTechromancer commented Dec 26, 2023

TheTechromancer commented Dec 26, 2023

TheTechromancer commented Dec 26, 2023

TheTechromancer commented Jan 9, 2024

TheTechromancer commented Dec 8, 2023 •

edited

Loading

TheTechromancer commented Dec 8, 2023 •

edited

Loading

TheTechromancer commented Dec 8, 2023 •

edited

Loading

TheTechromancer commented Dec 8, 2023 •

edited

Loading

TheTechromancer commented Dec 23, 2023 •

edited

Loading

TheTechromancer commented Dec 23, 2023 •

edited

Loading

TheTechromancer commented Dec 23, 2023 •

edited

Loading

TheTechromancer commented Dec 26, 2023 •

edited

Loading