Bug: Improve error logging #1687
Description
Description:
We are experiencing a file ingest issue which has been difficult to debug due to output.
Initially, uploading our zip was returning a 1 file failed to ingest as JSON Content so had to spend a bit of time uploading the JSON files individually to find the culprit. I can see the offending line here:
BloodHound/cmd/api/src/services/job/jobs.go
Line 144 in a240baf
Ideally this would print the filename or reference to assist rather than a count.
Uploading this file in isolation doesn't provide any errors so difficult to understand what that cause of the failed ingestion is.
I also have a follow-on issue where there is a discrepancy between the data-quality-stats numbers and the ['meta']['count'] values in the raw JSON
Mismatch for domain - groups: BHCE=20947, RAW=20964
Mismatch for domain - groups: BHCE=22963, RAW=22969
Mismatch for domain - containers: BHCE=241, RAW=295
Mismatch for domain - rootcas: BHCE=0, RAW=6
Mismatch for domain - enterprisecas: BHCE=0, RAW=3
Mismatch for domain - ntauthstores: BHCE=0, RAW=1
Mismatch for domain - groups: BHCE=337, RAW=355
Mismatch for domain - groups: BHCE=268, RAW=286
Mismatch for domain - groups: BHCE=3369, RAW=3387
Mismatch for domain - groups: BHCE=2381, RAW=2385
Are you intending to fix this bug?
No - happy to assist where I can.
Component(s) Affected:
- UI
- API
- Neo4j
- PostgreSQL
Steps to Reproduce:
- Unfortunately I am unable to provide the JSON file, but I have attached a snippet of the debug logs below
Expected Behavior:
Verbose error messaging to assist with debugging
Actual Behavior:
No errors or warnings relating to failed ingestion
Screenshots/Code Snippets/Sample Files:
--SNIP--
bloodhound-1 | {"time":"2025-07-16T13:07:23.489851385Z","level":"WARN","message":"skipping unresolved relationship","source":"","target":"S-1-5-21-XXX-XXX-XXX-XXX","resolved_source":false,"resolved_target":true}
--SNIP--
bloodhound-1 | {"time":"2025-07-16T13:07:28.19326938Z","level":"DEBUG","message":"Analysis","measurement_id":4}
bloodhound-1 | {"time":"2025-07-16T13:07:28.195689072Z","level":"INFO","message":"Graph Analysis","measurement_id":5}
bloodhound-1 | {"time":"2025-07-16T13:07:29.110307011Z","level":"INFO","message":"Expanding all AD group and local group memberships"}
bloodhound-1 | {"time":"2025-07-16T13:07:29.217531136Z","level":"INFO","message":"Collected 21701 groups to resolve"}
bloodhound-1 | {"time":"2025-07-16T13:07:32.14977449Z","level":"INFO","message":"GET /api/v2/file-upload?skip=0&limit=10&sort_by=-id","proto":"HTTP/1.1","referer":"http://127.0.0.1:8080/ui/administration/file-ingest","user_agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/138.0.0.0 Safari/537.36","request_bytes":0,"response_bytes":296,"status":200,"elapsed":3.415591,"request_id":"1633b71e-4a3f-4774-b146-1de3bd684b68","request_ip":"10.10.1.1","remote_addr":"10.10.1.1:60066","user_id":"d0d05f9a-4303-4235-9096-f243eabb7f79"}
bloodhound-1 | {"time":"2025-07-16T13:07:37.201766817Z","level":"INFO","message":"GET /api/v2/file-upload?skip=0&limit=10&sort_by=-id","proto":"HTTP/1.1","referer":"http://127.0.0.1:8080/ui/administration/file-ingest","user_agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/138.0.0.0 Safari/537.36","request_bytes":0,"response_bytes":296,"status":200,"elapsed":2.601965,"request_id":"e0a64c88-d24a-46cd-934d-10cfa33669b8","request_ip":"10.10.1.1","remote_addr":"10.10.1.1:60066","user_id":"d0d05f9a-4303-4235-9096-f243eabb7f79"}
bloodhound-1 | {"time":"2025-07-16T13:07:42.257621249Z","level":"INFO","message":"GET /api/v2/file-upload?skip=0&limit=10&sort_by=-id","proto":"HTTP/1.1","referer":"http://127.0.0.1:8080/ui/administration/file-ingest","user_agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/138.0.0.0 Safari/537.36","request_bytes":0,"response_bytes":296,"status":200,"elapsed":4.686674,"request_id":"6c636d8a-46d7-4778-943a-a2df1fa8b87e","request_ip":"10.10.1.1","remote_addr":"10.10.1.1:60066","user_id":"d0d05f9a-4303-4235-9096-f243eabb7f79"}
bloodhound-1 | {"time":"2025-07-16T13:07:47.308380105Z","level":"INFO","message":"GET /api/v2/file-upload?skip=0&limit=10&sort_by=-id","proto":"HTTP/1.1","referer":"http://127.0.0.1:8080/ui/administration/file-ingest","user_agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/138.0.0.0 Safari/537.36","request_bytes":0,"response_bytes":296,"status":200,"elapsed":5.191948,"request_id":"e7207e07-d418-4d09-b4cd-71d0a0255c1c","request_ip":"10.10.1.1","remote_addr":"10.10.1.1:60066","user_id":"d0d05f9a-4303-4235-9096-f243eabb7f79"}
bloodhound-1 | {"time":"2025-07-16T13:07:47.934092416Z","level":"INFO","message":"ResolveAllGroupMemberships","elapsed":18823.736684}
bloodhound-1 | {"time":"2025-07-16T13:07:48.335796745Z","level":"INFO","message":"Finished post-processing 1392 active directory computers"}
bloodhound-1 | {"time":"2025-07-16T13:07:48.36913262Z","level":"INFO","message":"Finished building adcs cache"}
bloodhound-1 | {"time":"2025-07-16T13:07:48.466587563Z","level":"DEBUG","message":"Calculating pathMembers cardinality for 1 targets"}
bloodhound-1 | {"time":"2025-07-16T13:07:48.466672447Z","level":"DEBUG","message":"Calculating pathMembers cardinality for 1 targets"}
bloodhound-1 | {"time":"2025-07-16T13:07:50.399817663Z","level":"INFO","message":"PostOwnsAndWriteOwner","elapsed":2023.419486}
bloodhound-1 | {"time":"2025-07-16T13:07:51.84537111Z","level":"DEBUG","message":"Calculating pathMembers cardinality for 1 targets"}
bloodhound-1 | {"time":"2025-07-16T13:07:52.091343477Z","level":"INFO","message":"Started Data Quality Stats Collection"}
bloodhound-1 | {"time":"2025-07-16T13:07:52.123730479Z","level":"INFO","message":"Cache successfully reset by datapipe daemon"}
bloodhound-1 | {"time":"2025-07-16T13:07:52.124349589Z","level":"INFO","message":"Graph Analysis","measurement_id":5,"elapsed":23928.658897}
bloodhound-1 | {"time":"2025-07-16T13:07:52.124375161Z","level":"DEBUG","message":"Analysis","measurement_id":4,"elapsed":23931.107391}
bloodhound-1 | {"time":"2025-07-16T13:07:52.373335988Z","level":"DEBUG","message":"No data found in X-Forwarded-For header"}
bloodhound-1 | {"time":"2025-07-16T13:07:52.37854891Z","level":"INFO","message":"GET /api/v2/file-upload?skip=0&limit=10&sort_by=-id","proto":"HTTP/1.1","referer":"http://127.0.0.1:8080/ui/administration/file-ingest","user_agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/138.0.0.0 Safari/537.36","request_bytes":0,"response_bytes":320,"status":200,"elapsed":5.224428,"request_id":"3b00990e-312d-42de-9f22-9032128f0d0f","request_ip":"10.10.1.1","remote_addr":"10.10.1.1:60066","user_id":"d0d05f9a-4303-4235-9096-f243eabb7f79"}
Environment Information:
BloodHound: v7.6.1
Collector: RustHound-CE
OS: Ubuntu 24.04
Docker (if using Docker): 28.1.1
Additional Information:
Happy to provide as much as I can.
Potential Solution (optional):
N/A
Related Issues:
N/A
Contributor Checklist:
- I have searched the issue tracker to ensure this bug hasn't been reported before or is not already being addressed.
- I have provided clear steps to reproduce the issue.
- I have included relevant environment information details.
- I have attached necessary supporting documents.
- I have checked that any JSON files I am attempting to upload to BloodHound are valid.