Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Engine Occasionally Hangs #1616

Closed
TheTechromancer opened this issue Aug 2, 2024 · 21 comments
Closed

Engine Occasionally Hangs #1616

TheTechromancer opened this issue Aug 2, 2024 · 21 comments
Assignees
@TheTechromancer
Labels
bug Something isn't working high-priority
Milestone
BBOT 2.0.1 - unho...

Comments

@TheTechromancer
Copy link
Collaborator 

[DBUG]     dnsresolve.finished: False
[DBUG]         running: True
[DBUG]         tasks:
[DBUG]             - dnsresolve.handle_event((DNS_NAME("us1.dev.emm.dell.com", module=subdomaincenter, tags={'in-scope', 'subdomain'}), {'abort_if': <bound method subdomain_enum.abort_if of
<bbot.modules.subdomaincenter.subdomaincenter object at 0x721cebfd6540>>})) running for 10 hours, 36 minutes, 39 seconds:
[DBUG]             - dnsresolve.handle_event((DNS_NAME("securemail.vsu.edu", module=sslcert, tags={'distance-2', 'subdomain'}), {})) running for 9 hours, 56 minutes, 54 seconds:
[DBUG]             - dnsresolve.handle_event((DNS_NAME("dell.cz", module=speculate, tags={'domain', 'distance-2'}), {})) running for 9 hours, 49 minutes, 25 seconds:

[DBUG] EngineClient DNSHelper: Timeout waiting for response for waiting for return value from is_wildcard((), {'query': 'us1.dev.emm.dell.com', 'ips': None, 'rdtype': None}), retrying...
[DBUG] EngineClient DNSHelper: Timeout waiting for response for waiting for new iteration from resolve_raw_batch((), {'queries': [('dell.cz', 'A'), ('dell.cz', 'AAAA'), ('dell.cz', 'SRV'), ('dell.cz', 'MX'), ('dell.cz', 'NS'), ('dell.cz', 'SOA'), ('dell.cz', 'CNAME'), ('dell.cz', 'TXT')]}), retrying...
[DBUG] EngineClient DNSHelper: Timeout waiting for response for waiting for new iteration from resolve_raw_batch((), {'queries': [('securemail.vsu.edu', 'A'), ('securemail.vsu.edu', 'AAAA'), ('securemail.vsu.edu', 'SRV'), ('securemail.vsu.edu', 'MX'), ('securemail.vsu.edu', 'NS'), ('securemail.vsu.edu', 'SOA'), ('securemail.vsu.edu', 'CNAME'), ('securemail.vsu.edu', 'TXT')]}), retrying...
@TheTechromancer TheTechromancer added the bug Something isn't working label Aug 2, 2024
@TheTechromancer TheTechromancer self-assigned this Aug 2, 2024
@TheTechromancer
Copy link
Collaborator Author

Two functions timed out here: is_wildcard() and resolve_batch(). There weren't any errors in debug.log, so it's hard to say what exactly happened on the server side. But since one was a generator and one was a return-function, we can be pretty sure it wasn't specific to run-and-return() or run-and-yield().

@TheTechromancer
Copy link
Collaborator Author

TheTechromancer commented Aug 2, 2024 •
edited
Loading

All three of these domains have timeout issues:

us1.dev.emm.dell.com:

2024-08-02 16:28:21,487 [DEBUG] bbot.core.dnsengine engine.py:392 EngineServer DNSEngine run-and-return is_wildcard((), {'query': 'us1.dev.emm.dell.com', 'ips': None, 'rdtype': None})
2024-08-02 16:28:21,576 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Resolving us1.dev.emm.dell.com with kwargs={'rdtype': 'A'}
2024-08-02 16:28:21,578 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Resolving us1.dev.emm.dell.com with kwargs={'rdtype': 'AAAA'}
2024-08-02 16:28:21,579 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Resolving us1.dev.emm.dell.com with kwargs={'rdtype': 'SRV'}
2024-08-02 16:28:21,580 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Resolving us1.dev.emm.dell.com with kwargs={'rdtype': 'MX'}
2024-08-02 16:28:21,580 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Resolving us1.dev.emm.dell.com with kwargs={'rdtype': 'NS'}
2024-08-02 16:28:21,581 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Resolving us1.dev.emm.dell.com with kwargs={'rdtype': 'SOA'}
2024-08-02 16:28:21,581 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Resolving us1.dev.emm.dell.com with kwargs={'rdtype': 'CNAME'}
2024-08-02 16:28:21,582 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Resolving us1.dev.emm.dell.com with kwargs={'rdtype': 'TXT'}
2024-08-02 16:28:26,579 [DEBUG] bbot.core.helpers.dns.engine.server engine.py:426 DNS query with args=('us1.dev.emm.dell.com',), kwargs={'rdtype': 'A'} timed out after 5 seconds
2024-08-02 16:28:26,580 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 DNS error or timeout for A query "us1.dev.emm.dell.com" (1 so far): The resolution lifetime expired after 5.002 seconds: Server Do53:1.0.0.1@53 answered The DNS operation timed out after 4.995 seconds
2024-08-02 16:28:26,580 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Retry (#1) resolving us1.dev.emm.dell.com with kwargs={'rdtype': 'A'}
2024-08-02 16:28:26,580 [DEBUG] bbot.core.helpers.dns.engine.server engine.py:426 DNS query with args=('us1.dev.emm.dell.com',), kwargs={'rdtype': 'AAAA'} timed out after 5 seconds
2024-08-02 16:28:26,580 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 DNS error or timeout for AAAA query "us1.dev.emm.dell.com" (1 so far): The resolution lifetime expired after 5.001 seconds: Server Do53:1.0.0.1@53 answered The DNS operation timed out after 4.996 seconds
2024-08-02 16:28:26,580 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Retry (#1) resolving us1.dev.emm.dell.com with kwargs={'rdtype': 'AAAA'}
2024-08-02 16:28:26,582 [DEBUG] bbot.core.helpers.dns.engine.server engine.py:426 DNS query with args=('us1.dev.emm.dell.com',), kwargs={'rdtype': 'SRV'} timed out after 5 seconds
2024-08-02 16:28:26,582 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 DNS error or timeout for SRV query "us1.dev.emm.dell.com" (1 so far): The resolution lifetime expired after 5.002 seconds: Server Do53:1.0.0.1@53 answered The DNS operation timed out after 4.996 seconds
2024-08-02 16:28:26,582 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Retry (#1) resolving us1.dev.emm.dell.com with kwargs={'rdtype': 'SRV'}
2024-08-02 16:28:26,583 [DEBUG] bbot.core.helpers.dns.engine.server engine.py:426 DNS query with args=('us1.dev.emm.dell.com',), kwargs={'rdtype': 'NS'} timed out after 5 seconds
2024-08-02 16:28:26,583 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 DNS error or timeout for NS query "us1.dev.emm.dell.com" (1 so far): The resolution lifetime expired after 5.002 seconds: Server Do53:1.0.0.1@53 answered The DNS operation timed out after 4.997 seconds
2024-08-02 16:28:26,583 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Retry (#1) resolving us1.dev.emm.dell.com with kwargs={'rdtype': 'NS'}
2024-08-02 16:28:26,583 [DEBUG] bbot.core.helpers.dns.engine.server engine.py:426 DNS query with args=('us1.dev.emm.dell.com',), kwargs={'rdtype': 'SOA'} timed out after 5 seconds
2024-08-02 16:28:26,583 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 DNS error or timeout for SOA query "us1.dev.emm.dell.com" (1 so far): The resolution lifetime expired after 5.002 seconds: Server Do53:1.1.1.1@53 answered The DNS operation timed out after 4.998 seconds
2024-08-02 16:28:26,583 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Retry (#1) resolving us1.dev.emm.dell.com with kwargs={'rdtype': 'SOA'}
2024-08-02 16:28:26,583 [DEBUG] bbot.core.helpers.dns.engine.server engine.py:426 DNS query with args=('us1.dev.emm.dell.com',), kwargs={'rdtype': 'CNAME'} timed out after 5 seconds
2024-08-02 16:28:26,584 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 DNS error or timeout for CNAME query "us1.dev.emm.dell.com" (1 so far): The resolution lifetime expired after 5.002 seconds: Server Do53:1.1.1.1@53 answered The DNS operation timed out after 4.998 seconds
2024-08-02 16:28:26,584 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Retry (#1) resolving us1.dev.emm.dell.com with kwargs={'rdtype': 'CNAME'}
2024-08-02 16:28:26,585 [DEBUG] bbot.core.helpers.dns.engine.server engine.py:426 DNS query with args=('us1.dev.emm.dell.com',), kwargs={'rdtype': 'TXT'} timed out after 5 seconds
2024-08-02 16:28:26,585 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 DNS error or timeout for TXT query "us1.dev.emm.dell.com" (1 so far): The resolution lifetime expired after 5.002 seconds: Server Do53:1.1.1.1@53 answered The DNS operation timed out after 4.999 seconds
2024-08-02 16:28:26,585 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Retry (#1) resolving us1.dev.emm.dell.com with kwargs={'rdtype': 'TXT'}
2024-08-02 16:28:26,683 [DEBUG] bbot.core.helpers.dns.engine.server engine.py:426 DNS query with args=('us1.dev.emm.dell.com',), kwargs={'rdtype': 'MX'} timed out after 5 seconds
2024-08-02 16:28:26,683 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 DNS error or timeout for MX query "us1.dev.emm.dell.com" (1 so far): The resolution lifetime expired after 5.103 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 1.040 seconds
2024-08-02 16:28:26,683 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Retry (#1) resolving us1.dev.emm.dell.com with kwargs={'rdtype': 'MX'}
2024-08-02 16:28:30,652 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Errors for us1.dev.emm.dell.com with kwargs={'rdtype': 'MX'}: [LifetimeTimeout('The resolution lifetime expired after 5.103 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 1.040 seconds'), NoNameservers('All nameservers failed to answer the query us1.dev.emm.dell.com. IN MX: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered SERVFAIL')]
2024-08-02 16:28:31,487 [DEBUG] bbot.core.dnshelper engine.py:73 EngineClient DNSHelper: Timeout waiting for response for waiting for return value from is_wildcard((), {'query': 'us1.dev.emm.dell.com', 'ips': None, 'rdtype': None}), retrying...
2024-08-02 16:28:31,519 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Errors for us1.dev.emm.dell.com with kwargs={'rdtype': 'TXT'}: [LifetimeTimeout('The resolution lifetime expired after 5.002 seconds: Server Do53:1.1.1.1@53 answered The DNS operation timed out after 4.999 seconds'), NoNameservers('All nameservers failed to answer the query us1.dev.emm.dell.com. IN TXT: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered SERVFAIL')]
2024-08-02 16:28:31,581 [DEBUG] bbot.core.helpers.dns.engine.server engine.py:426 DNS query with args=('us1.dev.emm.dell.com',), kwargs={'rdtype': 'A'} timed out after 5 seconds
2024-08-02 16:28:31,581 [VERBOSE] bbot.core.helpers.dns.engine.server logger.py:132 DNS error or timeout for A query "us1.dev.emm.dell.com" (2 so far): The resolution lifetime expired after 5.001 seconds: Server Do53:1.1.1.1@53 answered The DNS operation timed out after 4.998 seconds
2024-08-02 16:28:31,581 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Errors for us1.dev.emm.dell.com with kwargs={'rdtype': 'A'}: [LifetimeTimeout('The resolution lifetime expired after 5.002 seconds: Server Do53:1.0.0.1@53 answered The DNS operation timed out after 4.995 seconds'), LifetimeTimeout('The resolution lifetime expired after 5.001 seconds: Server Do53:1.1.1.1@53 answered The DNS operation timed out after 4.998 seconds')]
2024-08-02 16:28:31,583 [DEBUG] bbot.core.helpers.dns.engine.server engine.py:426 DNS query with args=('us1.dev.emm.dell.com',), kwargs={'rdtype': 'SRV'} timed out after 5 seconds
2024-08-02 16:28:31,583 [VERBOSE] bbot.core.helpers.dns.engine.server logger.py:132 DNS error or timeout for SRV query "us1.dev.emm.dell.com" (2 so far): The resolution lifetime expired after 5.001 seconds: Server Do53:1.1.1.1@53 answered The DNS operation timed out after 5.000 seconds
2024-08-02 16:28:31,583 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Errors for us1.dev.emm.dell.com with kwargs={'rdtype': 'SRV'}: [LifetimeTimeout('The resolution lifetime expired after 5.002 seconds: Server Do53:1.0.0.1@53 answered The DNS operation timed out after 4.996 seconds'), LifetimeTimeout('The resolution lifetime expired after 5.001 seconds: Server Do53:1.1.1.1@53 answered The DNS operation timed out after 5.000 seconds')]
2024-08-02 16:28:31,683 [DEBUG] bbot.core.helpers.dns.engine.server engine.py:426 DNS query with args=('us1.dev.emm.dell.com',), kwargs={'rdtype': 'AAAA'} timed out after 5 seconds
2024-08-02 16:28:31,683 [VERBOSE] bbot.core.helpers.dns.engine.server logger.py:132 DNS error or timeout for AAAA query "us1.dev.emm.dell.com" (2 so far): The resolution lifetime expired after 5.102 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 0.083 seconds
2024-08-02 16:28:31,683 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Errors for us1.dev.emm.dell.com with kwargs={'rdtype': 'AAAA'}: [LifetimeTimeout('The resolution lifetime expired after 5.001 seconds: Server Do53:1.0.0.1@53 answered The DNS operation timed out after 4.996 seconds'), LifetimeTimeout('The resolution lifetime expired after 5.102 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 0.083 seconds')]
2024-08-02 16:28:31,685 [DEBUG] bbot.core.helpers.dns.engine.server engine.py:426 DNS query with args=('us1.dev.emm.dell.com',), kwargs={'rdtype': 'NS'} timed out after 5 seconds
2024-08-02 16:28:31,685 [VERBOSE] bbot.core.helpers.dns.engine.server logger.py:132 DNS error or timeout for NS query "us1.dev.emm.dell.com" (2 so far): The resolution lifetime expired after 5.102 seconds: Server Do53:1.1.1.1@53 answered SERVFAIL; Server Do53:1.0.0.1@53 answered The DNS operation timed out after 1.041 seconds
2024-08-02 16:28:31,685 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Errors for us1.dev.emm.dell.com with kwargs={'rdtype': 'NS'}: [LifetimeTimeout('The resolution lifetime expired after 5.002 seconds: Server Do53:1.0.0.1@53 answered The DNS operation timed out after 4.997 seconds'), LifetimeTimeout('The resolution lifetime expired after 5.102 seconds: Server Do53:1.1.1.1@53 answered SERVFAIL; Server Do53:1.0.0.1@53 answered The DNS operation timed out after 1.041 seconds')]
2024-08-02 16:28:31,685 [DEBUG] bbot.core.helpers.dns.engine.server engine.py:426 DNS query with args=('us1.dev.emm.dell.com',), kwargs={'rdtype': 'SOA'} timed out after 5 seconds
2024-08-02 16:28:31,685 [VERBOSE] bbot.core.helpers.dns.engine.server logger.py:132 DNS error or timeout for SOA query "us1.dev.emm.dell.com" (2 so far): The resolution lifetime expired after 5.102 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 1.043 seconds
2024-08-02 16:28:31,685 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Errors for us1.dev.emm.dell.com with kwargs={'rdtype': 'SOA'}: [LifetimeTimeout('The resolution lifetime expired after 5.002 seconds: Server Do53:1.1.1.1@53 answered The DNS operation timed out after 4.998 seconds'), LifetimeTimeout('The resolution lifetime expired after 5.102 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 1.043 seconds')]
2024-08-02 16:28:31,685 [DEBUG] bbot.core.helpers.dns.engine.server engine.py:426 DNS query with args=('us1.dev.emm.dell.com',), kwargs={'rdtype': 'CNAME'} timed out after 5 seconds
2024-08-02 16:28:31,685 [VERBOSE] bbot.core.helpers.dns.engine.server logger.py:132 DNS error or timeout for CNAME query "us1.dev.emm.dell.com" (2 so far): The resolution lifetime expired after 5.101 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 0.086 seconds
2024-08-02 16:28:31,685 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Errors for us1.dev.emm.dell.com with kwargs={'rdtype': 'CNAME'}: [LifetimeTimeout('The resolution lifetime expired after 5.002 seconds: Server Do53:1.1.1.1@53 answered The DNS operation timed out after 4.998 seconds'), LifetimeTimeout('The resolution lifetime expired after 5.101 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 0.086 seconds')]
2024-08-02 16:28:31,686 [DEBUG] bbot.core.dnsengine engine.py:403 EngineServer DNSEngine: Sending response to is_wildcard((), {'query': 'us1.dev.emm.dell.com', 'ips': None, 'rdtype': None}): {}
2024-08-02 16:28:31,686 [DEBUG] bbot.core.dnsengine engine.py:411 EngineServer DNSEngine finished run-and-return is_wildcard((), {'query': 'us1.dev.emm.dell.com', 'ips': None, 'rdtype': None})
2024-08-02 16:28:31,686 [DEBUG] bbot.core.dnshelper engine.py:158 EngineClient DNSHelper: is_wildcard((), {'query': 'us1.dev.emm.dell.com', 'ips': None, 'rdtype': None}) got return value: {}
2024-08-02 16:28:31,686 [DEBUG] bbot.modules.dnsresolve base.py:1235 Finished handle_wildcard_event(DNS_NAME("us1.dev.emm.dell.com", module=TARGET, tags={'target', 'in-scope', 'subdomain'}))

securemail.vsu.edu:

2024-08-02 18:40:00,829 [DEBUG] bbot.core.dnshelper engine.py:185 EngineClient DNSHelper resolve_raw_batch got iteration: (('securemail.vsu.edu', 'CNAME'), (<DNS IN CNAME rdata: pe-0019bc01.gslb.pphosted.com.>, []))
2024-08-02 18:40:00,831 [DEBUG] bbot.core.dnshelper engine.py:185 EngineClient DNSHelper resolve_raw_batch got iteration: (('securemail.vsu.edu', 'A'), (<DNS IN A rdata: 148.163.157.44>, []))
2024-08-02 18:40:00,907 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 The DNS response does not contain an answer to the question: securemail.vsu.edu. IN TXT (args=('securemail.vsu.edu',), kwargs={'rdtype': 'TXT'})
2024-08-02 18:40:00,918 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 The DNS response does not contain an answer to the question: securemail.vsu.edu. IN MX (args=('securemail.vsu.edu',), kwargs={'rdtype': 'MX'})
2024-08-02 18:40:00,943 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 The DNS response does not contain an answer to the question: securemail.vsu.edu. IN SOA (args=('securemail.vsu.edu',), kwargs={'rdtype': 'SOA'})
2024-08-02 18:40:04,911 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 The DNS response does not contain an answer to the question: securemail.vsu.edu. IN SRV (args=('securemail.vsu.edu',), kwargs={'rdtype': 'SRV'})
2024-08-02 18:40:05,928 [DEBUG] bbot.core.helpers.dns.engine.server engine.py:426 DNS query with args=('securemail.vsu.edu',), kwargs={'rdtype': 'AAAA'} timed out after 5 seconds
2024-08-02 18:40:05,928 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 DNS error or timeout for AAAA query "securemail.vsu.edu" (2 so far): The resolution lifetime expired after 5.102 seconds: Server Do53:1.1.1.1@53 answered SERVFAIL; Server Do53:1.0.0.1@53 answered The DNS operation timed out after 1.042 seconds
2024-08-02 18:40:05,928 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Retry (#1) resolving securemail.vsu.edu with kwargs={'rdtype': 'AAAA'}
2024-08-02 18:40:05,929 [DEBUG] bbot.core.helpers.dns.engine.server engine.py:426 DNS query with args=('securemail.vsu.edu',), kwargs={'rdtype': 'NS'} timed out after 5 seconds
2024-08-02 18:40:05,929 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 DNS error or timeout for NS query "securemail.vsu.edu" (1 so far): The resolution lifetime expired after 5.102 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 1.043 seconds
2024-08-02 18:40:05,929 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Retry (#1) resolving securemail.vsu.edu with kwargs={'rdtype': 'NS'}
2024-08-02 18:40:06,020 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 The DNS response does not contain an answer to the question: securemail.vsu.edu. IN NS (args=('securemail.vsu.edu',), kwargs={'rdtype': 'NS'})
2024-08-02 18:40:06,020 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Errors for securemail.vsu.edu with kwargs={'rdtype': 'NS'}: [LifetimeTimeout('The resolution lifetime expired after 5.102 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 1.043 seconds')]
2024-08-02 18:40:09,930 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 The DNS response does not contain an answer to the question: securemail.vsu.edu. IN AAAA (args=('securemail.vsu.edu',), kwargs={'rdtype': 'AAAA'})
2024-08-02 18:40:09,930 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Errors for securemail.vsu.edu with kwargs={'rdtype': 'AAAA'}: [LifetimeTimeout('The resolution lifetime expired after 5.102 seconds: Server Do53:1.1.1.1@53 answered SERVFAIL; Server Do53:1.0.0.1@53 answered The DNS operation timed out after 1.042 seconds')]
2024-08-02 18:40:09,930 [DEBUG] bbot.core.dnsengine engine.py:429 EngineServer DNSEngine reached end of run-and-yield iteration for resolve_raw_batch()
2024-08-02 18:40:09,930 [DEBUG] bbot.core.dnsengine engine.py:439 EngineServer DNSEngine finished run-and-yield resolve_raw_batch()
2024-08-02 18:40:09,931 [DEBUG] bbot.core.dnshelper engine.py:185 EngineClient DNSHelper resolve_raw_batch got iteration: {'_s': None}

dell.cz:

[DBUG] EngineServer DNSEngine run-and-yield resolve_raw_batch((), {'queries': [('dell.cz', 'A'), ('dell.cz', 'AAAA'), ('dell.cz', 'SRV'), ('dell.cz', 'MX'), ('dell.cz', 'NS'), ('dell.cz', 'SOA'), ('dell.cz', 'CNAME'), ('dell.cz', 'TXT')]})                                
[TRCE] Resolving dell.cz with kwargs={'rdtype': 'A'}                                                                                                                                                                                                                           
[TRCE] Resolving dell.cz with kwargs={'rdtype': 'AAAA'}                                                                                                                                                                                                                        
[TRCE] Resolving dell.cz with kwargs={'rdtype': 'SRV'}                                                                                                                                                                                                                         
[TRCE] Resolving dell.cz with kwargs={'rdtype': 'MX'}                                                                                                                                                                                                                          
[TRCE] Resolving dell.cz with kwargs={'rdtype': 'NS'}                                                                                                                                                                                                                          
[TRCE] Resolving dell.cz with kwargs={'rdtype': 'SOA'}                                                                                                                                                                                                                         
[TRCE] Resolving dell.cz with kwargs={'rdtype': 'CNAME'}                                                                                                                                                                                                                       
[TRCE] Resolving dell.cz with kwargs={'rdtype': 'TXT'}                                                                                                                                                                                                                         
[TRCE] Errors for dell.cz with kwargs={'rdtype': 'AAAA'}: [NoNameservers('All nameservers failed to answer the query dell.cz. IN AAAA: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered SERVFAIL')]                                                   
[TRCE] Errors for dell.cz with kwargs={'rdtype': 'SOA'}: [NoNameservers('All nameservers failed to answer the query dell.cz. IN SOA: Server Do53:1.1.1.1@53 answered SERVFAIL; Server Do53:1.0.0.1@53 answered SERVFAIL')]                                                     
[TRCE] Errors for dell.cz with kwargs={'rdtype': 'NS'}: [NoNameservers('All nameservers failed to answer the query dell.cz. IN NS: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered SERVFAIL')]                                                       
[DBUG] DNS query with args=('dell.cz',), kwargs={'rdtype': 'A'} timed out after 5 seconds                                                                                                                                                                                      
[TRCE] DNS error or timeout for A query "dell.cz" (1 so far): The resolution lifetime expired after 5.102 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 1.039 seconds                                   
[TRCE] Retry (#1) resolving dell.cz with kwargs={'rdtype': 'A'}                                                                                                                                                                                                                
[DBUG] DNS query with args=('dell.cz',), kwargs={'rdtype': 'SRV'} timed out after 5 seconds                                                                                                                                                                                    
[TRCE] DNS error or timeout for SRV query "dell.cz" (1 so far): The resolution lifetime expired after 5.102 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 1.040 seconds                                 
[TRCE] Retry (#1) resolving dell.cz with kwargs={'rdtype': 'SRV'}                                                                                                                                                                                                              
[DBUG] DNS query with args=('dell.cz',), kwargs={'rdtype': 'MX'} timed out after 5 seconds                                                                                                                                                                                     
[TRCE] DNS error or timeout for MX query "dell.cz" (1 so far): The resolution lifetime expired after 5.103 seconds: Server Do53:1.1.1.1@53 answered SERVFAIL; Server Do53:1.0.0.1@53 answered The DNS operation timed out after 1.043 seconds                                  
[TRCE] Retry (#1) resolving dell.cz with kwargs={'rdtype': 'MX'}                                                                                                                                                                                                               
[DBUG] DNS query with args=('dell.cz',), kwargs={'rdtype': 'CNAME'} timed out after 5 seconds                                                                                                                                                                                  
[TRCE] DNS error or timeout for CNAME query "dell.cz" (1 so far): The resolution lifetime expired after 5.103 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 1.041 seconds                               
[TRCE] Retry (#1) resolving dell.cz with kwargs={'rdtype': 'CNAME'}                                                                                                                                                                                                            
[DBUG] DNS query with args=('dell.cz',), kwargs={'rdtype': 'TXT'} timed out after 5 seconds                                                                                                                                                                                    
[TRCE] DNS error or timeout for TXT query "dell.cz" (1 so far): The resolution lifetime expired after 5.103 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 1.043 seconds                                 
[TRCE] Retry (#1) resolving dell.cz with kwargs={'rdtype': 'TXT'}                                                                                                                                                                                                              
[TRCE] Errors for dell.cz with kwargs={'rdtype': 'MX'}: [LifetimeTimeout('The resolution lifetime expired after 5.103 seconds: Server Do53:1.1.1.1@53 answered SERVFAIL; Server Do53:1.0.0.1@53 answered The DNS operation timed out after 1.043 seconds'), NoNameservers('All 
nameservers failed to answer the query dell.cz. IN MX: Server Do53:1.1.1.1@53 answered SERVFAIL; Server Do53:1.0.0.1@53 answered SERVFAIL')]                                                                                                                                   
[TRCE] Errors for dell.cz with kwargs={'rdtype': 'A'}: [LifetimeTimeout('The resolution lifetime expired after 5.102 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 1.039 seconds'), NoNameservers('All n
ameservers failed to answer the query dell.cz. IN A: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered SERVFAIL')]                                                                                                                                     
[DBUG] EngineClient DNSHelper: Timeout waiting for response for waiting for new iteration from resolve_raw_batch((), {'queries': [('dell.cz', 'A'), ('dell.cz', 'AAAA'), ('dell.cz', 'SRV'), ('dell.cz', 'MX'), ('dell.cz', 'NS'), ('dell.cz', 'SOA'), ('dell.cz', 'CNAME'), ('
dell.cz', 'TXT')]}), retrying...                                                                                                                                                                                                                                               
[DBUG] DNS query with args=('dell.cz',), kwargs={'rdtype': 'SRV'} timed out after 5 seconds                                                                                                                                                                                    
[VERB] DNS error or timeout for SRV query "dell.cz" (2 so far): The resolution lifetime expired after 5.103 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 1.042 seconds                                 
[TRCE] Errors for dell.cz with kwargs={'rdtype': 'SRV'}: [LifetimeTimeout('The resolution lifetime expired after 5.102 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 1.040 seconds'), LifetimeTimeout('T
he resolution lifetime expired after 5.103 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 1.042 seconds')]                                                                                               
[DNS_NAME_UNRESOLVED]   dell.cz TARGET  (domain, in-scope, target, unresolved)                                                                                                                                                                                                 
[DBUG] DNS query with args=('dell.cz',), kwargs={'rdtype': 'CNAME'} timed out after 5 seconds                                                                                                                                                                                  
[VERB] DNS error or timeout for CNAME query "dell.cz" (2 so far): The resolution lifetime expired after 5.101 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 1.043 seconds                               
[TRCE] Errors for dell.cz with kwargs={'rdtype': 'CNAME'}: [LifetimeTimeout('The resolution lifetime expired after 5.103 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 1.041 seconds'), LifetimeTimeout(
'The resolution lifetime expired after 5.101 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 1.043 seconds')]                                                                                             
[DBUG] DNS query with args=('dell.cz',), kwargs={'rdtype': 'TXT'} timed out after 5 seconds                                                                                                                                                                                    
[VERB] DNS error or timeout for TXT query "dell.cz" (2 so far): The resolution lifetime expired after 5.101 seconds: Server Do53:1.1.1.1@53 answered SERVFAIL; Server Do53:1.0.0.1@53 answered The DNS operation timed out after 1.044 seconds                                 
[TRCE] Errors for dell.cz with kwargs={'rdtype': 'TXT'}: [LifetimeTimeout('The resolution lifetime expired after 5.103 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 1.043 seconds'), LifetimeTimeout('T
he resolution lifetime expired after 5.101 seconds: Server Do53:1.1.1.1@53 answered SERVFAIL; Server Do53:1.0.0.1@53 answered The DNS operation timed out after 1.044 seconds')]                                                                                               
[DBUG] EngineServer DNSEngine reached end of run-and-yield iteration for resolve_raw_batch()

@TheTechromancer
Copy link
Collaborator Author

This is almost guaranteed to be a bug in resolve_raw_batch(), since is_wildcard() also uses it indirectly.

@TheTechromancer
Copy link
Collaborator Author

TheTechromancer commented Aug 2, 2024 •
edited
Loading 

[DBUG]     dnsresolve.finished: False                                                                                                                                                                              
[DBUG]         running: True                                                                                                                                                                                       
[DBUG]         tasks:                                                                                                                                                                                              
[DBUG]             - dnsresolve.handle_event((DNS_NAME("ns2.xmn-gslbicorp.dell.com", module=PTR, tags={'in-scope', 'subdomain'}), {})) running for 1 hour, 13 minutes, 13 seconds:
[DBUG]             - dnsresolve.handle_event((DNS_NAME("amer-gslbinet.dell.com", module=speculate, tags={'in-scope', 'subdomain'}), {})) running for 1 hour, 5 minutes, 13 seconds:
[DBUG]             - dnsresolve.handle_event((DNS_NAME("oob.devops.dell.com", module=subdomaincenter, tags={'in-scope', 'subdomain'}), {'abort_if': <bound method subdomain_enum.abort_if of <bbot.modules.subdomaincenter.subdomaincenter object at 0x7af8cc29c4d0>>})) running for 1 hour, 4 minutes, 40 seconds:
[DBUG]             - dnsresolve.handle_event((DNS_NAME("ospctrx.ospnetscaler.ap.dell.com", module=CNAME, tags={'in-scope', 'subdomain'}), {})) running for 47 minutes, 32 seconds:
[DBUG]             - dnsresolve.handle_event((DNS_NAME("ospctrx.ospnetscaler.ap.dell.com", module=CNAME, tags={'in-scope', 'subdomain'}), {})) running for 47 minutes, 27 seconds:
[DBUG]             - dnsresolve.handle_event((DNS_NAME("www.rebecca.users.ameremea-gslbinet.dell.com", module=dnsbrute, tags={'in-scope', 'subdomain'}), {})) running for 22 minutes, 37 seconds:
[DBUG]         incoming_queue_size: 0
[DBUG]         outgoing_queue_size: 0
[DBUG]     internetdb.finished: False
[DBUG]         running: True
[DBUG]         tasks:
[DBUG]             - internetdb.handle_event(DNS_NAME("wipeout.us.dell.com", module=PTR, tags={'a-record', 'in-scope', 'subdomain'})) running for 41 minutes, 5 seconds:
[DBUG]         incoming_queue_size: 172025
[DBUG]         outgoing_queue_size: 0

@TheTechromancer
Copy link
Collaborator Author

GDB traceback for WebHelper process:

  File "/usr/lib/python3.12/multiprocessing/spawn.py", line 122, in spawn_main
    exitcode = _main(fd, parent_sentinel)
  File "/usr/lib/python3.12/multiprocessing/spawn.py", line 135, in _main
    return self._bootstrap(parent_sentinel)
  File "/usr/lib/python3.12/multiprocessing/process.py", line 314, in _bootstrap
    self.run()
  File "/root/bbot/bbot/core/helpers/process.py", line 55, in run
    super().run()
  File "/usr/lib/python3.12/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "/root/bbot/bbot/core/engine.py", line 286, in server_process
    asyncio.run(engine_server.worker())
  File "/usr/lib/python3.12/asyncio/runners.py", line 194, in run
    return runner.run(main)
  File "/usr/lib/python3.12/asyncio/runners.py", line 118, in run
    return self._loop.run_until_complete(task)
  File "/usr/lib/python3.12/asyncio/base_events.py", line 674, in run_until_complete
    self.run_forever()
  File "/usr/lib/python3.12/asyncio/base_events.py", line 641, in run_forever
    self._run_once()
  File "/usr/lib/python3.12/asyncio/base_events.py", line 1949, in _run_once
    event_list = self._selector.select(timeout)
  File "/usr/lib/python3.12/selectors.py", line 468, in select
    fd_event_list = self._selector.poll(timeout, max_ev)

Doesn't seem to reveal anything interesting.

@TheTechromancer
Copy link
Collaborator Author

Same for DNSEngine:

  File "/usr/lib/python3.12/multiprocessing/spawn.py", line 122, in spawn_main
    exitcode = _main(fd, parent_sentinel)
  File "/usr/lib/python3.12/multiprocessing/spawn.py", line 135, in _main
    return self._bootstrap(parent_sentinel)
  File "/usr/lib/python3.12/multiprocessing/process.py", line 314, in _bootstrap
    self.run()
  File "/root/bbot/bbot/core/helpers/process.py", line 55, in run
    super().run()
  File "/usr/lib/python3.12/multiprocessing/process.py", line 108, in run
    self._target(*self._args, **self._kwargs)
  File "/root/bbot/bbot/core/engine.py", line 286, in server_process
    asyncio.run(engine_server.worker())
  File "/usr/lib/python3.12/asyncio/runners.py", line 194, in run
    return runner.run(main)
  File "/usr/lib/python3.12/asyncio/runners.py", line 118, in run
    return self._loop.run_until_complete(task)
  File "/usr/lib/python3.12/asyncio/base_events.py", line 674, in run_until_complete
    self.run_forever()
  File "/usr/lib/python3.12/asyncio/base_events.py", line 641, in run_forever
    self._run_once()
  File "/usr/lib/python3.12/asyncio/base_events.py", line 1949, in _run_once
    event_list = self._selector.select(timeout)
  File "/usr/lib/python3.12/selectors.py", line 468, in select
    fd_event_list = self._selector.poll(timeout, max_ev)

@TheTechromancer
Copy link
Collaborator Author

So it's not a true deadlock. This is good.

@TheTechromancer
Copy link
Collaborator Author

Sending SIGINT to the engine processes:

dell.com-4 $ kill -SIGINT 28521
dell.com-4 $ ps -ef | grep DNS
root       28521   28504 50 19:22 pts/0    01:37:32 [BBOT DNSHelper] <defunct>
root       35619    5810  0 22:35 pts/2    00:00:00 grep DNS
dell.com-4 $ ps -ef | grep Web
root       28512   28504  0 19:22 pts/0    00:00:58 BBOT WebHelper
root       35627    5810  0 22:36 pts/2    00:00:00 grep Web
dell.com-4 $ kill -SIGINT 28512
dell.com-4 $ ps -ef | grep Web
root       28512   28504  0 19:22 pts/0    00:00:58 BBOT WebHelper
root       35633    5810  0 22:36 pts/2    00:00:00 grep Web

@TheTechromancer
Copy link
Collaborator Author

TheTechromancer commented Aug 2, 2024 •
edited
Loading

In the DNSEngine, resolution errors always seem to precede the hang:

2024-08-02 22:55:23,070 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Errors for 8bk29y1.server.oob.devops.dell.com with kwargs={'rdtype': 'NS'}: [LifetimeTimeout('The resolution lifetime expired after 5.103 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 0.987 seconds'), LifetimeTimeout('The resolution lifetime expired after 5.101 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 0.993 seconds')]
2024-08-02 22:55:23,071 [DEBUG] bbot.core.helpers.dns.engine.server engine.py:426 DNS query with args=('8bk29y1.server.oob.devops.dell.com',), kwargs={'rdtype': 'CNAME'} timed out after 5 seconds
2024-08-02 22:55:23,071 [VERBOSE] bbot.core.helpers.dns.engine.server logger.py:132 DNS error or timeout for CNAME query "8bk29y1.server.oob.devops.dell.com" (19 so far): The resolution lifetime expired after 5.101 seconds: Server Do53:1.1.1.1@53 answered SERVFAIL; Server Do53:1.0.0.1@53 answered The DNS operation timed out after 2.049 seconds
2024-08-02 22:55:23,071 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Errors for 8bk29y1.server.oob.devops.dell.com with kwargs={'rdtype': 'CNAME'}: [LifetimeTimeout('The resolution lifetime expired after 5.103 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 0.989 seconds'), LifetimeTimeout('The resolution lifetime expired after 5.101 seconds: Server Do53:1.1.1.1@53 answered SERVFAIL; Server Do53:1.0.0.1@53 answered The DNS operation timed out after 2.049 seconds')]
2024-08-02 22:55:23,071 [DEBUG] bbot.core.helpers.dns.engine.server engine.py:426 DNS query with args=('8bk29y1.server.oob.devops.dell.com',), kwargs={'rdtype': 'TXT'} timed out after 5 seconds
2024-08-02 22:55:23,071 [VERBOSE] bbot.core.helpers.dns.engine.server logger.py:132 DNS error or timeout for TXT query "8bk29y1.server.oob.devops.dell.com" (18 so far): The resolution lifetime expired after 5.101 seconds: Server Do53:1.1.1.1@53 answered SERVFAIL; Server Do53:1.0.0.1@53 answered The DNS operation timed out after 2.049 seconds
2024-08-02 22:55:23,072 [TRACE] bbot.core.helpers.dns.engine.server logger.py:132 Errors for 8bk29y1.server.oob.devops.dell.com with kwargs={'rdtype': 'TXT'}: [LifetimeTimeout('The resolution lifetime expired after 5.103 seconds: Server Do53:1.0.0.1@53 answered SERVFAIL; Server Do53:1.1.1.1@53 answered The DNS operation timed out after 2.169 seconds'), LifetimeTimeout('The resolution lifetime expired after 5.101 seconds: Server Do53:1.1.1.1@53 answered SERVFAIL; Server Do53:1.0.0.1@53 answered The DNS operation timed out after 2.049 seconds')]
2024-08-02 22:55:02,442 [DEBUG] bbot.core.dnshelper engine.py:138 EngineClient DNSHelper: executing run-and-return is_wildcard((), {'query': '8bk29y1.server.oob.devops.dell.com', 'ips': None, 'rdtype': None})
2024-08-02 22:55:12,838 [DEBUG] bbot.core.dnshelper engine.py:73 EngineClient DNSHelper: Timeout waiting for response for waiting for return value from is_wildcard((), {'query': '8bk29y1.server.oob.devops.dell.com', 'ips': None, 'rdtype': None}), retrying...
2024-08-02 22:55:12,840 [DEBUG] bbot.core.dnshelper engine.py:158 EngineClient DNSHelper: is_wildcard((), {'query': '8bk29y1.server.oob.devops.dell.com', 'ips': None, 'rdtype': None}) got return value: {}
2024-08-02 22:55:12,840 [DEBUG] bbot.core.dnshelper engine.py:166 EngineClient DNSHelper: executing run-and-yield resolve_raw_batch((), {'queries': [('8bk29y1.server.oob.devops.dell.com', 'A'), ('8bk29y1.server.oob.devops.dell.com', 'AAAA'), ('8bk29y1.server.oob.devops.dell.com', 'SRV'), ('8bk29y1.server.oob.devops.dell.com', 'MX'), ('8bk29y1.server.oob.devops.dell.com', 'NS'), ('8bk29y1.server.oob.devops.dell.com', 'SOA'), ('8bk29y1.server.oob.devops.dell.com', 'CNAME'), ('8bk29y1.server.oob.devops.dell.com', 'TXT')]})
2024-08-02 22:55:23,794 [DEBUG] bbot.core.dnshelper engine.py:73 EngineClient DNSHelper: Timeout waiting for response for waiting for new iteration from resolve_raw_batch((), {'queries': [('8bk29y1.server.oob.devops.dell.com', 'A'), ('8bk29y1.server.oob.devops.dell.com', 'AAAA'), ('8bk29y1.server.oob.devops.dell.com', 'SRV'), ('8bk29y1.server.oob.devops.dell.com', 'MX'), ('8bk29y1.server.oob.devops.dell.com', 'NS'), ('8bk29y1.server.oob.devops.dell.com', 'SOA'), ('8bk29y1.server.oob.devops.dell.com', 'CNAME'), ('8bk29y1.server.oob.devops.dell.com', 'TXT')]}), retrying...

@TheTechromancer TheTechromancer changed the title DNS Engine Occasionally Hangs Engine Occasionally Hangs Aug 10, 2024
@TheTechromancer
Copy link
Collaborator Author

TheTechromancer commented Aug 10, 2024 •
edited
Loading

Per @liquidsec this seems to be a bug in the engine itself and not specific to DNS. It is also happening with web requests.

[ERRR] Error in lightfuzz.handle_event(WEB_PARAMETER("{'host': 'spil-offer-service-preprod.salespil.xfinity.com', 'type': 'SPECULATIVE', 'name': 'errorMessage', 'original_value': 'Invalid request. Authorization failed; No Bearer Authorization token passe...", module=excavate, tags={'cloud-amazon', 'in-scope'})): /root/bbot/bbot/core/engine.py:79:_infinite_retry(): Timed out after 300 seconds waiting for return value from request(('https://spil-offer-service-preprod.salespil.xfinity.com/',), {'timeout': 10})

Traceback (most recent call last):                                                                                                                                                                 File "/root/bbot/bbot/core/engine.py", line 74, in _infinite_retry                                                                                                                                 return await asyncio.wait_for(callback(*args, **kwargs), timeout=interval)                                                                                                                              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^                                                                                                                     File "/usr/lib/python3.11/asyncio/tasks.py", line 497, in wait_for                                                                                                                                 raise exceptions.TimeoutError() from exc                                                                                                                                                     TimeoutError                                                                                                                                                                                                                                                                                                                                                                                      During handling of the above exception, another exception occurred:                                                                                                                                                                                                                                                                                                                               Traceback (most recent call last):                                                                                                                                                                 File "/root/bbot/bbot/scanner/scanner.py", line 1178, in _acatch                                                                                                                                   yield                                                                                                                                                                                          File "/root/bbot/bbot/modules/base.py", line 637, in _worker                                                                                                                                       await self.handle_event(event)                                                                                                                                                                 File "/root/bbot/bbot/modules/internetdb.py", line 67, in handle_event                                                                                                                             r = await self.request_with_fail_count(url)                                                                                                                                                          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^                                                                                                                                                    File "/root/bbot/bbot/modules/base.py", line 1085, in request_with_fail_count                                                                                                                      r = await self.helpers.request(*args, **kwargs)                                                                                                                                                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^                                                                                                                                                File "/root/bbot/bbot/core/helpers/web/web.py", line 111, in request                                                                                                                               return await self.run_and_return("request", *args, **kwargs)                                                                                                                                            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^                                                                                                                                   File "/usr/lib/python3.11/contextlib.py", line 222, in __aexit__                                                                                                                                   await self.gen.athrow(typ, value, traceback)                                                                                                                                                   File "/root/bbot/bbot/core/engine.py", line 315, in new_socket                                                                                                                                     yield socket                                                                                                                                                                                   File "/root/bbot/bbot/core/engine.py", line 154, in run_and_return                                                                                                                                 binary = await self._infinite_retry(socket.recv, _context=f"waiting for return value from {fn_str}")                                                                                                      ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^                                                                                           File "/root/bbot/bbot/core/engine.py", line 79, in _infinite_retry                                                                                                                                 raise TimeoutError(f"Timed out after {max_retries*interval:,} seconds {context}")                                                                                                            TimeoutError: Timed out after 300 seconds waiting for return value from request(('https://internetdb.shodan.io/35.82.142.14',), {})

@TheTechromancer TheTechromancer mentioned this issue Aug 15, 2024
Closed
@TheTechromancer
Copy link
Collaborator Author

TheTechromancer commented Aug 19, 2024 •
edited
Loading 

2024-08-18 22:42:26,134 [DEBUG] bbot.core.webhelper engine.py:84 EngineClient WebHelper: executing run-and-return request(('https://internetdb.shodan.io/143.166.39.38',), {})
2024-08-18 22:42:26,153 [DEBUG] bbot.core.httpengine engine.py:84 EngineServer HTTPEngine: run-and-return request(('https://internetdb.shodan.io/143.166.39.38',), {})
2024-08-18 23:31:57,482 [DEBUG] bbot.core.webhelper engine.py:77 EngineClient WebHelper: Timeout after 15 secondswaiting for return value from request(('https://internetdb.shodan.io/143.166.39.38',), {}), retrying...
2024-08-18 23:33:48,054 [VERBOSE] bbot.core.helpers.web.engine logger.py:132 HTTP timeout to URL: https://internetdb.shodan.io/143.166.39.38
2024-08-18 23:33:48,055 [DEBUG] bbot.core.httpengine engine.py:84 EngineServer HTTPEngine: Sending response to request(('https://internetdb.shodan.io/143.166.39.38',), {}): None
2024-08-18 23:33:48,055 [DEBUG] bbot.core.httpengine engine.py:84 EngineServer HTTPEngine finished run-and-return request(('https://internetdb.shodan.io/143.166.39.38',), {})
2024-08-18 23:33:55,203 [DEBUG] bbot.core.webhelper engine.py:77 EngineClient WebHelper: Timeout after 15 secondswaiting for return value from request(('https://internetdb.shodan.io/143.166.39.38',), {}), retrying...
...
2024-08-18 23:38:35,716 [DEBUG] bbot.core.webhelper engine.py:77 EngineClient WebHelper: Timeout after 15 secondswaiting for return value from request(('https://internetdb.shodan.io/143.166.39.38',), {}), retrying...
2024-08-18 23:38:51,076 [DEBUG] bbot.core.webhelper engine.py:77 EngineClient WebHelper: Timeout after 15 secondswaiting for return value from request(('https://internetdb.shodan.io/143.166.39.38',), {}), retrying...
2024-08-18 23:38:51,614 [ERROR] bbot.scanner scanner.py:1195 Error in internetdb.handle_event(DNS_NAME("pc1okcmedpro1.us.dell.com", module=PTR, tags={'a-record', 'in-scope', 'subdomain'})): /root/bbot/bbot/core/engine.py:80:_infinite_retry(): Timed out after 300 seconds waiting for return value from request(('https://internetdb.shodan.io/143.166.39.38',), {})
TimeoutError: Timed out after 300 seconds waiting for return value from request(('https://internetdb.shodan.io/143.166.39.38',), {})

In this case, the server very clearly sent a response, which the client never received. This indicates a bug in zmq.

@TheTechromancer
Copy link
Collaborator Author 

2024-08-19 02:19:51,796 [DEBUG] bbot.core.dnshelper engine.py:84 EngineClient DNSHelper: executing run-and-yield resolve_raw_batch((), {'queries': [('150.105.79.46', 'PTR')]})
2024-08-19 02:20:07,437 [DEBUG] bbot.core.dnshelper engine.py:77 EngineClient DNSHelper: Timeout after 15 seconds waiting for new iteration from resolve_raw_batch((), {'queries': [('150.105.79.46', 'PTR')]}), retrying...
2024-08-19 02:20:22,914 [DEBUG] bbot.core.dnshelper engine.py:77 EngineClient DNSHelper: Timeout after 15 seconds waiting for new iteration from resolve_raw_batch((), {'queries': [('150.105.79.46', 'PTR')]}), retrying...
...
2024-08-19 02:25:02,965 [DEBUG] bbot.core.dnshelper engine.py:77 EngineClient DNSHelper: Timeout after 15 seconds waiting for new iteration from resolve_raw_batch((), {'queries': [('150.105.79.46', 'PTR')]}), retrying...
2024-08-19 02:25:18,218 [DEBUG] bbot.core.dnshelper engine.py:77 EngineClient DNSHelper: Timeout after 15 seconds waiting for new iteration from resolve_raw_batch((), {'queries': [('150.105.79.46', 'PTR')]}), retrying...
2024-08-19 02:25:18,220 [ERROR] bbot.scanner scanner.py:1195 Error in dnsresolve.handle_event((IP_ADDRESS("150.105.79.46", module=A, tags={'distance-1', 'ipv4'}), {})): /root/bbot/bbot/core/engine.py:80:_infinite_retry(): Timed out after 300 seconds waiting for new iteration from resolve_raw_batch((), {'queries': [('150.105.79.46', 'PTR')]})
TimeoutError: Timed out after 300 seconds waiting for new iteration from resolve_raw_batch((), {'queries': [('150.105.79.46', 'PTR')]})

In this case, it seems like the message never made it to the server. So we have unreliable communication in both directions.

@TheTechromancer
Copy link
Collaborator Author

I've discovered that the default HWM (High-Water-Mark) has recently been changed from unlimited to 1000, and that the default action for ROUTER when the HWM is reached is to start dropping messages:

When a ZMQ_ROUTER socket enters the mute state due to having reached the high water mark for all peers, then any messages sent to the socket shall be dropped until the mute state ends. Likewise, any messages routed to a peer for which the individual high water mark has been reached shall also be dropped.

This sounds a lot like our culprit. I'll try increasing the HWMs.

@TheTechromancer
Copy link
Collaborator Author

TheTechromancer commented Aug 19, 2024 •
edited
Loading

Still experiencing the 300-second timeouts even after increasing the HWM. The most consistent example, which happens on every single scan, is wayback. The wayback request has a timeout of 20 seconds but never times out properly on the server side. I tested it in isolation and the 20-second timeout works fine. So I'm not sure what's happening there.

But I think there's still a deep mystery to be unwrapped:

2024-08-19 06:28:45,648 [TRACE] bbot.core.dnshelper logger.py:132 EngineClient DNSHelper: executing run-and-return is_wildcard((), {'query': 'vbv.dell.com', 'ips': None, 'rdtype': None})
2024-08-19 06:28:45,726 [TRACE] bbot.core.dnsengine logger.py:132 EngineServer DNSEngine got message: {'c': 4, 'k': {'query': 'vbv.dell.com', 'ips': None, 'rdtype': None}}
2024-08-19 06:28:45,966 [TRACE] bbot.core.dnsengine logger.py:132 is_wildcard((), {'query': 'vbv.dell.com', 'ips': None, 'rdtype': None})
2024-08-19 06:28:45,966 [TRACE] bbot.core.dnsengine logger.py:132 EngineServer DNSEngine: starting run-and-return is_wildcard((), {'query': 'vbv.dell.com', 'ips': None, 'rdtype': None})
2024-08-19 06:28:46,799 [TRACE] bbot.core.dnsengine logger.py:132 EngineServer DNSEngine: sending response to is_wildcard((), {'query': 'vbv.dell.com', 'ips': None, 'rdtype': None}): {'A': (False, 'vbv.dell.com')}
2024-08-19 06:28:46,800 [TRACE] bbot.core.dnsengine logger.py:132 EngineServer DNSEngine finished run-and-return is_wildcard((), {'query': 'vbv.dell.com', 'ips': None, 'rdtype': None})
2024-08-19 06:28:47,170 [TRACE] bbot.core.dnshelper logger.py:132 EngineClient DNSHelper: is_wildcard((), {'query': 'vbv.dell.com', 'ips': None, 'rdtype': None}) got return value: {'A': (False, 'vbv.dell.com')}
2024-08-19 06:30:31,877 [TRACE] bbot.core.dnshelper logger.py:132 EngineClient DNSHelper: executing run-and-return is_wildcard((), {'query': 'vbv.dell.com', 'ips': None, 'rdtype': None})
2024-08-19 06:30:32,011 [TRACE] bbot.core.dnsengine logger.py:132 EngineServer DNSEngine got message: {'c': 4, 'k': {'query': 'vbv.dell.com', 'ips': None, 'rdtype': None}}
2024-08-19 06:30:32,103 [TRACE] bbot.core.dnsengine logger.py:132 is_wildcard((), {'query': 'vbv.dell.com', 'ips': None, 'rdtype': None})
2024-08-19 06:30:32,103 [TRACE] bbot.core.dnsengine logger.py:132 EngineServer DNSEngine: starting run-and-return is_wildcard((), {'query': 'vbv.dell.com', 'ips': None, 'rdtype': None})
2024-08-19 06:30:32,850 [TRACE] bbot.core.dnsengine logger.py:132 EngineServer DNSEngine: sending response to is_wildcard((), {'query': 'vbv.dell.com', 'ips': None, 'rdtype': None}): {'A': (False, 'vbv.dell.com')}
2024-08-19 06:30:32,850 [TRACE] bbot.core.dnsengine logger.py:132 EngineServer DNSEngine finished run-and-return is_wildcard((), {'query': 'vbv.dell.com', 'ips': None, 'rdtype': None})
2024-08-19 06:30:51,420 [DEBUG] bbot.core.dnshelper engine.py:77 EngineClient DNSHelper: Timeout after 15 seconds waiting for return value from is_wildcard((), {'query': 'vbv.dell.com', 'ips': None, 'rdtype': None}), retrying...
2024-08-19 06:31:06,854 [DEBUG] bbot.core.dnshelper engine.py:77 EngineClient DNSHelper: Timeout after 15 seconds waiting for return value from is_wildcard((), {'query': 'vbv.dell.com', 'ips': None, 'rdtype': None}), retrying...
...
2024-08-19 06:35:56,070 [DEBUG] bbot.core.dnshelper engine.py:77 EngineClient DNSHelper: Timeout after 15 seconds waiting for return value from is_wildcard((), {'query': 'vbv.dell.com', 'ips': None, 'rdtype': None}), retrying...
2024-08-19 06:36:11,190 [DEBUG] bbot.core.dnshelper engine.py:77 EngineClient DNSHelper: Timeout after 15 seconds waiting for return value from is_wildcard((), {'query': 'vbv.dell.com', 'ips': None, 'rdtype': None}), retrying...
2024-08-19 06:36:11,646 [ERROR] bbot.scanner scanner.py:1195 Error in dnsresolve.handle_event((DNS_NAME("vbv.dell.com", module=columbus, tags={'subdomain', 'in-scope'}), {'abort_if': <bound method subdomain_enum.abort_if of <bbot.modules.columbus.columbus object at 0x7250c47cecf0>>})): /root/bbot/bbot/core/engine.py:80:_infinite_retry(): Timed out after 300 seconds waiting for return value from is_wildcard((), {'query': 'vbv.dell.com', 'ips': None, 'rdtype': None})
TimeoutError: Timed out after 300 seconds waiting for return value from is_wildcard((), {'query': 'vbv.dell.com', 'ips': None, 'rdtype': None})

@TheTechromancer TheTechromancer mentioned this issue Aug 19, 2024
Merged
@TheTechromancer
Copy link
Collaborator Author

This might be a race condition where _infinite_retry()'s timeout is cancelling the task before it can grab the return value from the socket. This would result in the return value being retrieved but never actually used.

The chances of this happening would probably increase as the async event loop gets more congested.

To test this theory, I'm going to try raising the timeout interval and see if we get fewer instances of the bug.

@TheTechromancer
Copy link
Collaborator Author

TheTechromancer commented Aug 20, 2024 •
edited
Loading

Raising the timeout interval seemed to fix it. 🎉🎉🎉🎉🎉🫠

@TheTechromancer
Copy link
Collaborator Author

Fixed in #1678.

@Sh4d0wHunt3rX
Copy link
Contributor

Sh4d0wHunt3rX commented Sep 28, 2024 •
edited
Loading

It's more than 30 minutes bbot hanged : ( Debug was not enabled.

Scan duration 4 hours.

image
image

@TheTechromancer
Copy link
Collaborator Author

@Sh4d0wHunt3rX were the status messages frozen as well?

@Sh4d0wHunt3rX
Copy link
Contributor

Yes, nothing printed on both debug.log or terminal.

@TheTechromancer
Copy link
Collaborator Author

Next time that happens would it be possible to give me ssh access? I need to attach to the process with gdb to see where it hung.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@TheTechromancer TheTechromancer

Labels
bug Something isn't working high-priority
Projects
None yet
Milestone
BBOT 2.0.1 - unholy_ned
Development

No branches or pull requests
2 participants
@Sh4d0wHunt3rX @TheTechromancer