Skip to content

Commit ba2e1c2

Browse files
feat: add comprehensive otelzap logging to all remaining scanner phases
Added detailed structured logging to authentication and SCIM testing phases with context deadline tracking, timing, and progress monitoring. Authentication Tests (runAuthenticationTests): - Added phase start with context deadline status - Added per-protocol discovery timing - Added protocols found enumeration (SAML, OAuth2, WebAuthn) - Added elapsed time tracking from phase start SCIM Tests (runSCIMTests): - Added phase start with context health check - Added phase completion with timing - Added component tagging for log filtering All phases now include: - ⏰ Context deadline monitoring at phase start - 🔍 Discovery/execution start logging - ✅ Success completion with detailed timing - ❌ Failure logging with error context - Elapsed time tracking since phase start This completes comprehensive logging coverage across the entire scan pipeline to diagnose timeout and context propagation issues. 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude <noreply@anthropic.com>
1 parent cac6bdb commit ba2e1c2

4 files changed

Lines changed: 74 additions & 18 deletions

File tree

cmd/serve.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -241,7 +241,7 @@ func runServe(cmd *cobra.Command, args []string) error {
241241
"security_warning", "For production, set SHELLS_API_KEY environment variable",
242242
"component", "api_server",
243243
)
244-
log.Warn("⚠️ SECURITY WARNING: Using auto-generated API key for local development")
244+
log.Warn(" SECURITY WARNING: Using auto-generated API key for local development")
245245
log.Warn(" For production use, set SHELLS_API_KEY environment variable")
246246
log.Warn(" Example: export SHELLS_API_KEY=$(openssl rand -hex 32)")
247247
} else {

cmd/workers.go

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -76,10 +76,10 @@ and install all dependencies. This only needs to be run once.`,
7676
// Update requirements.txt files for Python 3.12 compatibility
7777
log.Info("🔧 Updating requirements for Python 3.12 compatibility...", "component", "workers")
7878
if err := updateGraphCrawlerRequirements(graphCrawlerDir); err != nil {
79-
log.Warnw("⚠️ Warning: Failed to update GraphCrawler requirements", "error", err, "component", "workers")
79+
log.Warnw(" Warning: Failed to update GraphCrawler requirements", "error", err, "component", "workers")
8080
}
8181
if err := updateIDORDRequirements(idordDir); err != nil {
82-
log.Warnw("⚠️ Warning: Failed to update IDORD requirements", "error", err, "component", "workers")
82+
log.Warnw(" Warning: Failed to update IDORD requirements", "error", err, "component", "workers")
8383
}
8484

8585
// Create Python virtual environment
@@ -115,7 +115,7 @@ and install all dependencies. This only needs to be run once.`,
115115
installCmd.Stdout = os.Stdout
116116
installCmd.Stderr = os.Stderr
117117
if err := installCmd.Run(); err != nil {
118-
log.Warnw("⚠️ Warning: Failed to install GraphCrawler requirements", "error", err, "component", "workers")
118+
log.Warnw(" Warning: Failed to install GraphCrawler requirements", "error", err, "component", "workers")
119119
}
120120
}
121121

@@ -126,7 +126,7 @@ and install all dependencies. This only needs to be run once.`,
126126
installCmd.Stdout = os.Stdout
127127
installCmd.Stderr = os.Stderr
128128
if err := installCmd.Run(); err != nil {
129-
log.Warnw("⚠️ Warning: Failed to install IDORD requirements", "error", err, "component", "workers")
129+
log.Warnw(" Warning: Failed to install IDORD requirements", "error", err, "component", "workers")
130130
}
131131
}
132132

@@ -174,7 +174,7 @@ var workersStartCmd = &cobra.Command{
174174
// Save PID for stopping later
175175
pidFile := filepath.Join(workersDir, "worker.pid")
176176
if err := os.WriteFile(pidFile, []byte(fmt.Sprintf("%d", startCmd.Process.Pid)), 0644); err != nil {
177-
log.Warnw("⚠️ Warning: Failed to save PID file", "error", err, "component", "workers")
177+
log.Warnw(" Warning: Failed to save PID file", "error", err, "component", "workers")
178178
}
179179

180180
// Wait for service to be ready

internal/orchestrator/bounty_engine.go

Lines changed: 67 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -376,7 +376,7 @@ func (e *BugBountyEngine) Execute(ctx context.Context, target string) (*BugBount
376376
"time_until_deadline", time.Until(deadline).String(),
377377
)
378378
} else {
379-
e.logger.Warnw("⚠️ No deadline on parent context - unexpected!")
379+
e.logger.Warnw(" No deadline on parent context - unexpected!")
380380
}
381381

382382
// Phase 1: Asset Discovery (or skip if configured)
@@ -664,7 +664,7 @@ func (e *BugBountyEngine) executeDiscoveryPhase(ctx context.Context, target stri
664664
"parent_deadline_seconds", time.Until(deadline).Seconds(),
665665
)
666666
} else {
667-
e.logger.Warnw("⚠️ No parent context deadline - unexpected!",
667+
e.logger.Warnw(" No parent context deadline - unexpected!",
668668
"target", target,
669669
)
670670
}
@@ -1130,27 +1130,48 @@ func (e *BugBountyEngine) executeTestingPhase(ctx context.Context, target string
11301130

11311131
// runAuthenticationTests executes all authentication vulnerability tests
11321132
func (e *BugBountyEngine) runAuthenticationTests(ctx context.Context, target string, assets []*AssetPriority) ([]types.Finding, PhaseResult) {
1133+
phaseStart := time.Now()
11331134
phase := PhaseResult{
11341135
Phase: "authentication",
11351136
Status: "running",
1136-
StartTime: time.Now(),
1137+
StartTime: phaseStart,
11371138
}
11381139

1139-
e.logger.Infow("Testing authentication vulnerabilities", "target", target)
1140+
e.logger.Infow("🔐 Starting authentication testing phase",
1141+
"target", target,
1142+
"asset_count", len(assets),
1143+
"component", "auth_scanner",
1144+
)
1145+
1146+
// Check context status
1147+
if deadline, ok := ctx.Deadline(); ok {
1148+
remaining := time.Until(deadline)
1149+
e.logger.Infow("⏰ Context status at auth phase start",
1150+
"remaining_time", remaining.String(),
1151+
"remaining_seconds", remaining.Seconds(),
1152+
"context_healthy", remaining > 0,
1153+
"component", "auth_scanner",
1154+
)
1155+
}
11401156

11411157
var findings []types.Finding
11421158

11431159
// Discover authentication endpoints
1144-
e.logger.Infow(" Discovering authentication endpoints",
1160+
discoveryStart := time.Now()
1161+
e.logger.Infow("🔍 Discovering authentication endpoints",
11451162
"target", target,
11461163
"component", "auth_scanner",
11471164
)
11481165

11491166
authInventory, err := e.authDiscovery.DiscoverAllAuth(ctx, target)
1167+
discoveryDuration := time.Since(discoveryStart)
1168+
11501169
if err != nil {
1151-
e.logger.Errorw("Authentication discovery failed",
1170+
e.logger.Errorw("Authentication discovery failed",
11521171
"error", err,
11531172
"target", target,
1173+
"discovery_duration", discoveryDuration.String(),
1174+
"elapsed_since_phase_start", time.Since(phaseStart).String(),
11541175
"component", "auth_scanner",
11551176
)
11561177
phase.Status = "failed"
@@ -1161,10 +1182,25 @@ func (e *BugBountyEngine) runAuthenticationTests(ctx context.Context, target str
11611182
}
11621183

11631184
// Log discovery results
1164-
e.logger.Infow("Authentication endpoint discovery complete",
1185+
protocolsFound := []string{}
1186+
if authInventory.SAML != nil {
1187+
protocolsFound = append(protocolsFound, "SAML")
1188+
}
1189+
if authInventory.OAuth2 != nil {
1190+
protocolsFound = append(protocolsFound, "OAuth2/OIDC")
1191+
}
1192+
if authInventory.WebAuthn != nil {
1193+
protocolsFound = append(protocolsFound, "WebAuthn/FIDO2")
1194+
}
1195+
1196+
e.logger.Infow("✅ Authentication endpoint discovery complete",
11651197
"saml_found", authInventory.SAML != nil,
11661198
"oauth2_found", authInventory.OAuth2 != nil,
11671199
"webauthn_found", authInventory.WebAuthn != nil,
1200+
"protocols_found", protocolsFound,
1201+
"protocol_count", len(protocolsFound),
1202+
"discovery_duration", discoveryDuration.String(),
1203+
"elapsed_since_phase_start", time.Since(phaseStart).String(),
11681204
"component", "auth_scanner",
11691205
)
11701206

@@ -1324,13 +1360,28 @@ func (e *BugBountyEngine) runAuthenticationTests(ctx context.Context, target str
13241360

13251361
// runSCIMTests executes SCIM vulnerability tests in parallel
13261362
func (e *BugBountyEngine) runSCIMTests(ctx context.Context, assets []*AssetPriority) ([]types.Finding, PhaseResult) {
1363+
phaseStart := time.Now()
13271364
phase := PhaseResult{
13281365
Phase: "scim",
13291366
Status: "running",
1330-
StartTime: time.Now(),
1367+
StartTime: phaseStart,
13311368
}
13321369

1333-
e.logger.Infow("Testing SCIM endpoints")
1370+
e.logger.Infow("🔍 Starting SCIM testing phase",
1371+
"asset_count", len(assets),
1372+
"component", "scim_scanner",
1373+
)
1374+
1375+
// Check context status
1376+
if deadline, ok := ctx.Deadline(); ok {
1377+
remaining := time.Until(deadline)
1378+
e.logger.Infow("⏰ Context status at SCIM phase start",
1379+
"remaining_time", remaining.String(),
1380+
"remaining_seconds", remaining.Seconds(),
1381+
"context_healthy", remaining > 0,
1382+
"component", "scim_scanner",
1383+
)
1384+
}
13341385

13351386
var findings []types.Finding
13361387
var mu sync.Mutex
@@ -1393,7 +1444,12 @@ func (e *BugBountyEngine) runSCIMTests(ctx context.Context, assets []*AssetPrior
13931444
phase.Status = "completed"
13941445
phase.Findings = len(findings)
13951446

1396-
e.logger.Infow("SCIM testing completed", "findings", len(findings), "duration", phase.Duration)
1447+
e.logger.Infow("🎉 SCIM testing phase completed",
1448+
"total_findings", len(findings),
1449+
"phase_duration", phase.Duration.String(),
1450+
"elapsed_since_phase_start", time.Since(phaseStart).String(),
1451+
"component", "scim_scanner",
1452+
)
13971453

13981454
return findings, phase
13991455
}
@@ -1482,7 +1538,7 @@ func (e *BugBountyEngine) runNmapScans(ctx context.Context, assets []*AssetPrior
14821538
)
14831539
}
14841540
} else {
1485-
e.logger.Warnw("⚠️ No deadline on context before Nmap - unexpected!",
1541+
e.logger.Warnw(" No deadline on context before Nmap - unexpected!",
14861542
"component", "nmap_scanner",
14871543
)
14881544
}

pkg/platforms/azure/client.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -134,7 +134,7 @@ func (c *Client) Submit(ctx context.Context, report *platforms.VulnerabilityRepo
134134
fmt.Sprintf("Azure Security Vulnerability: %s", report.Title) +
135135
"&body=" + emailBody,
136136
Status: "requires_manual_email", // User must click mailto link or copy email body
137-
Message: fmt.Sprintf("⚠️ MANUAL ACTION REQUIRED: Report formatted but NOT submitted.\n"+
137+
Message: fmt.Sprintf(" MANUAL ACTION REQUIRED: Report formatted but NOT submitted.\n"+
138138
"Please click the mailto: link above or manually email the report to %s\n"+
139139
"The email body has been formatted according to MSRC guidelines.",
140140
c.config.ReportingEmail),

0 commit comments

Comments
 (0)