From 03898a27c3dd93efcce20643cd69a925218b010f Mon Sep 17 00:00:00 2001 From: Microck Date: Thu, 5 Mar 2026 09:09:55 +0000 Subject: [PATCH] docs: add logging quality audit Add comprehensive logging audit report identifying gaps and recommendations. - Documents current logging infrastructure and existing log statements - Identifies critical gaps in scan lifecycle, external service calls, and detector execution - Provides prioritized recommendations with code examples - Establishes logging convention for future development Nightshift-Task: logging-audit Nightshift-Ref: https://github.com/marcus/nightshift --- docs/logging-audit.md | 322 ++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 322 insertions(+) create mode 100644 docs/logging-audit.md diff --git a/docs/logging-audit.md b/docs/logging-audit.md new file mode 100644 index 0000000..a1bca16 --- /dev/null +++ b/docs/logging-audit.md @@ -0,0 +1,322 @@ +# Logging Quality Audit + +## Overview + +This audit evaluates the logging infrastructure and practices in the Jarspect codebase as of commit ``. + +## Current Logging Setup + +### Infrastructure +- **Framework**: `tracing` crate for structured logging +- **Initialization**: `tracing_subscriber` in `src/main.rs:79-83` +- **Default Log Level**: `jarspect=info,tower_http=info` (configurable via `RUST_LOG` env var) + +### Existing Log Statements by Module + +#### `src/main.rs` (HTTP server) +- Line 102: `info!` - Loaded signature and YARA rulepacks (with rulepack names) +- Line 116: `info!` - Configured upload limits (upload_max_bytes, body_max_bytes) +- Line 143: `info!` - Server listening address + +#### `src/scan.rs` (Core scan orchestrator) +- Line 114: `warn!` - Archive parsing failed, attempting raw fallback scan (with error) +- Line 286: `warn!` - AI verdict failed, falling back to heuristic verdict (with error) +- Line 410: `warn!` - MalwareBazaar lookup failed, continuing with local analysis (with error) + +#### `src/verdict.rs` (AI verdict generation) +- Lines 409-415: `tracing::warn!` - AI request failed (with api_calls, transient_attempts, backoff, error) +- Lines 437-443: `tracing::warn!` - Failed to decode AI response payload (with api_calls, transient_attempts, backoff, error) +- Lines 457-463: `tracing::warn!` - AI rate limited for too long (with api_calls, waited_secs, wait_secs, body) +- Line 468: `tracing::warn!` - AI rate limited (429), waiting then retrying (with api_calls, wait_secs, body) +- Line 474: `tracing::warn!` - AI API returned non-200 status (with status, body) + +## Critical Gaps + +### 1. Scan Lifecycle Logging (HIGH PRIORITY) +**Location**: `src/scan.rs:run_scan()` + +**Missing**: +- Scan initiation: Log when a scan starts (upload_id, scan_id) +- SHA256 hash computation: Log hash for correlation +- MalwareBazaar check result: Log whether hash matched or not found +- Static analysis summary: Log number of files analyzed, class files, patterns matched, YARA hits +- Verdict determination: Log final verdict (CLEAN/SUSPICIOUS/MALICIOUS), method, confidence +- Scan completion: Log total scan duration + +**Impact**: No visibility into scan progress or results in production logs. Cannot correlate scans with outcomes. + +--- + +### 2. External Service Call Logging (HIGH PRIORITY) +**Location**: `src/malwarebazaar.rs` + +**Missing**: +- MalwareBazaar API call initiation: Log hash being checked +- MalwareBazaar response: Log result (found/not found), family if available +- HTTP request/response timing: Add timing metrics for API calls + +**Impact**: Cannot diagnose API issues or performance problems. + +--- + +### 3. Detector Execution Logging (MEDIUM PRIORITY) +**Location**: `src/detectors/mod.rs:run_capability_detectors()` + +**Missing**: +- Detector execution summary: Log total findings count by category and severity +- Individual detector results (debug level): Which detectors found evidence + +**Impact**: Hard to debug detection behavior or understand which capabilities contributed to verdicts. + +--- + +### 4. YARA Scan Logging (MEDIUM PRIORITY) +**Location**: `src/analysis/yara.rs` (module exists but not read) + +**Missing**: +- YARA scan initiation: Log scanning entries with YARA rules +- YARA scan summary: Log number of rule hits by severity and pack (demo/prod) + +**Impact**: Cannot verify YARA rule execution or correlate YARA hits with verdicts. + +--- + +### 5. Profile Building Logging (MEDIUM PRIORITY) +**Location**: `src/profile.rs:build_profile()` + +**Missing**: +- Mod metadata extraction result: Log which loader detected (fabric/forge/neoforge/spigot), mod_id, name, version +- Capability summary: Log which capabilities were detected as present + +**Impact**: Cannot verify mod metadata parsing or understand capability profiling behavior. + +--- + +### 6. Archive Parsing Logging (MEDIUM PRIORITY) +**Location**: `src/analysis/archive.rs` (module exists but not read) + +**Missing**: +- Archive structure: Log number of entries, class files detected +- Archive parsing errors: More detailed error context when parsing fails + +**Impact**: Limited visibility into archive analysis. + +--- + +### 7. Error Context Logging (LOW-MEDIUM PRIORITY) +**General Issue**: Many error returns use `anyhow::Error` without structured logging before bubbling up. + +**Examples**: +- File read errors +- Serialization/deserialization errors +- YARA compilation errors + +**Impact**: When errors occur at top level, root cause context may be lost. + +## Logging Quality Issues + +### 1. Inconsistent Structured Field Usage +- Some logs use field syntax: `warn!(error = %error, ...)` +- Some logs use positional: `warn!("AI request failed; retrying")` (later lines in verdict.rs) +- Missing correlation IDs (scan_id) across most logs + +**Recommendation**: Use consistent structured logging with scan_id/upload_id as trace correlation. + +### 2. No Request/Response Correlation +- HTTP endpoints in `main.rs` don't log incoming request IDs +- No way to correlate scan initiation with scan completion logs + +**Recommendation**: Generate request ID at HTTP handler entry and propagate through scan. + +### 3. No Performance Metrics +- No timing metrics for scan phases (intake, static analysis, YARA scan, AI verdict) +- No timing for external API calls + +**Recommendation**: Use `tracing::Instrument` span durations or manual timing logs. + +### 4. Severity Level Concerns +- Some potentially actionable conditions use `warn!` when `info!` or `debug!` might be appropriate +- No `debug!` level logs for detailed tracing during troubleshooting + +**Recommendation**: +- `info!`: Key business events (scan started/finished, verdict produced) +- `warn!`: Recoverable errors and fallbacks (already well-used) +- `debug!`: Detailed detector findings, YARA rule execution, file-by-file analysis +- `error!`: Unrecoverable errors that require intervention + +## Recommendations + +### Priority 1: Add Scan Lifecycle Logging + +Add to `src/scan.rs`: + +```rust +use tracing::{info, instrument}; + +#[instrument(skip_all, fields(upload_id = %request.upload_id))] +pub async fn run_scan( + state: &AppState, + request: ScanRequest, + scan_id_override: Option<&str>, +) -> Result { + let scan_id = build_scan_id(scan_id_override)?; + tracing::Span::current().record("scan_id", &scan_id); + + info!("scan initiated"); + + // ... existing code ... + + info!( + sha256 = %sha256_hash, + file_count = entries.len(), + class_file_count = intake.class_file_count, + pattern_matches = static_findings.matched_pattern_ids.len(), + signature_matches = static_findings.matched_signature_ids.len(), + yara_hits = static_findings.matches.iter().filter(|i| i.source == "yara").count(), + "static analysis completed" + ); + + // ... verdict logic ... + + info!( + verdict = %ai_verdict.result, + confidence = ai_verdict.confidence, + risk_score = ai_verdict.risk_score, + method = %method, + duration_ms = started_at.elapsed().as_millis(), + "scan completed" + ); + + Ok(response) +} +``` + +### Priority 2: Add External Service Call Logging + +Add to `src/malwarebazaar.rs`: + +```rust +use tracing::{info, instrument}; + +#[instrument(skip_all, fields(sha256))] +pub async fn check_hash(sha256: &str, api_key: &str) -> Result> { + // ... existing API call code ... + + match result { + Some(ref malware) => { + info!( + family = ?malware.family.as_deref(), + tags = malware.tags.len(), + "malwarebazaar hash match found" + ); + } + None => { + info!("malwarebazaar hash not found"); + } + } + + Ok(result) +} +``` + +### Priority 3: Add Detector Execution Summary + +Add to `src/detectors/mod.rs`: + +```rust +use tracing::debug; + +pub fn run_capability_detectors( + evidence: &BytecodeEvidence, + entries: &[ArchiveEntry], +) -> Vec { + // ... existing code ... + + let findings = dedup_findings(findings); + + debug!( + total_findings = findings.len(), + by_category = %format!("{:?}", summarize_by_category(&findings)), + "detector execution completed" + ); + + findings +} +``` + +### Priority 4: Establish Logging Convention + +Create `src/logging.rs` with helpers: + +```rust +use tracing::{info, warn, error}; + +/// Scan lifecycle events +pub fn log_scan_start(scan_id: &str, upload_id: &str) { + info!(scan_id, upload_id, "scan initiated"); +} + +pub fn log_scan_complete(scan_id: &str, verdict: &str, confidence: f64, duration_ms: u64) { + info!( + scan_id, + verdict, + confidence, + duration_ms, + "scan completed" + ); +} + +/// External service events +pub fn log_malwarebazaar_check(sha256: &str) { + info!(sha256, "checking malwarebazaar"); +} + +pub fn log_malwarebazaar_result(sha256: &str, found: bool, family: Option<&str>) { + if found { + info!(sha256, family, "malwarebazaar match found"); + } else { + info!(sha256, "malwarebazaar no match"); + } +} + +/// AI service events +pub fn log_ai_verdict_request(scan_id: &str) { + info!(scan_id, "requesting AI verdict"); +} + +pub fn log_ai_verdict_result(scan_id: &str, verdict: &str, confidence: f64) { + info!(scan_id, verdict, confidence, "AI verdict received"); +} +``` + +## Summary Statistics + +| Metric | Count | +|--------|-------| +| Total source files | ~25 | +| Files with logging | 3 (main.rs, scan.rs, verdict.rs) | +| Total log statements | ~11 | +| Info-level logs | 3 | +| Warn-level logs | 7+ | +| Error-level logs | 0 (explicit) | +| Debug-level logs | 0 | +| Logs with structured fields | ~8 | +| Logs with trace correlation (scan_id) | 0 | + +## Action Items + +1. **HIGH**: Add scan lifecycle logging (init, static analysis complete, verdict, complete) +2. **HIGH**: Add MalwareBazaar API call logging (request initiated, result) +3. **MEDIUM**: Add detector execution summary logs +4. **MEDIUM**: Add YARA scan logging (initiation, summary) +5. **MEDIUM**: Add profile building logs (metadata extraction, capability summary) +6. **LOW**: Create logging convention helpers in dedicated module +7. **LOW**: Add debug-level logs for detailed troubleshooting +8. **LOW**: Add request/response correlation IDs to HTTP handlers + +## Notes + +- This audit is based on static analysis. Runtime verification of log output was not performed. +- The project already uses structured logging with `tracing`, which is excellent for observability. +- Current logging focuses on error/warning conditions. Adding info/debug logs would significantly improve operational visibility. +- Consider adding log sampling or rate limiting for high-volume debug logs in production.