Skip to content

Commit ff00619

Browse files
hahwulhahwul
authored
refactor(logging): unify debug logging into a single stderr dbg_log! macro (#1145)
Debug logging was split two ways. ~19 call sites hand-rolled `if crate::DEBUG.load(..) { eprintln!("[DBG] ..") }` (stderr, no timestamp, repeated boilerplate), while the short-lived `log_dbg` helper rendered `{ts} DBG` but routed through `cprintln!` — i.e. **stdout**. Any unguarded `log_dbg` under `--debug` therefore interleaved a DBG line into JSON / JSONL / SARIF output on stdout (the v3.1 TLS-insecure diagnostic was exactly such a site). Introduce `crate::dbg_log!` (src/utils/log.rs): gates on `crate::DEBUG`, writes to **stderr** via `ceprintln!` (so structured stdout is never polluted and ANSI is stripped under `--no-color`/`NO_COLOR`), and renders the `{ts} DBG <msg>` format. The macro is lazy — the message is only formatted when `--debug` is active — so it stays cheap in hot per-request paths (reflection / scanning) where a function taking `&format!(..)` would not. - Migrate all `[DBG]` eprintln sites (payload, preflight, discovery, parameter_analysis, oob poller, xss_blind, check_reflection, scanning, waf) to `dbg_log!`, dropping the per-site DEBUG guard and `[DBG]` prefix. - Remove `log_dbg` from cmd::scan::logging; its callers (TLS diagnostic, reqs-sent/estimated) now use `dbg_log!`. Verified: `dalfox url --url https://… --format json --debug` keeps stdout valid JSON with zero DBG lines; the `{ts} DBG` line lands on stderr and strips ANSI under NO_COLOR. clippy clean, 1756 lib tests pass.
1 parent a44b13a commit ff00619

15 files changed

Lines changed: 119 additions & 116 deletions

File tree

‎src/cmd/payload.rs‎

Lines changed: 4 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -89,9 +89,7 @@ fn fetch_and_print_remote(provider: &str) -> bool {
8989
for p in list.iter() {
9090
println!("{}", p);
9191
}
92-
if crate::DEBUG.load(std::sync::atomic::Ordering::Relaxed) {
93-
eprintln!("[DBG] {}: {} payloads", provider, count);
94-
}
92+
crate::dbg_log!("{}: {} payloads", provider, count);
9593
ok_clone.store(true, std::sync::atomic::Ordering::Relaxed);
9694
} else {
9795
eprintln!(
@@ -121,19 +119,15 @@ pub fn run_payload(args: PayloadArgs) -> ScanOutcome {
121119
for ev in list.iter() {
122120
println!("{}", ev);
123121
}
124-
if crate::DEBUG.load(std::sync::atomic::Ordering::Relaxed) {
125-
eprintln!("[DBG] event-handlers: {} items", list.len());
126-
}
122+
crate::dbg_log!("event-handlers: {} items", list.len());
127123
ScanOutcome::Clean
128124
}
129125
Some("useful-tags") => {
130126
let list = crate::payload::xss_html::useful_html_tag_names();
131127
for t in list.iter() {
132128
println!("{}", t);
133129
}
134-
if crate::DEBUG.load(std::sync::atomic::Ordering::Relaxed) {
135-
eprintln!("[DBG] useful-tags: {} items", list.len());
136-
}
130+
crate::dbg_log!("useful-tags: {} items", list.len());
137131
ScanOutcome::Clean
138132
}
139133
Some("payloadbox") => {
@@ -155,9 +149,7 @@ pub fn run_payload(args: PayloadArgs) -> ScanOutcome {
155149
for payload in list {
156150
println!("{}", payload);
157151
}
158-
if crate::DEBUG.load(std::sync::atomic::Ordering::Relaxed) {
159-
eprintln!("[DBG] uri-scheme: {} payloads", list.len());
160-
}
152+
crate::dbg_log!("uri-scheme: {} payloads", list.len());
161153
ScanOutcome::Clean
162154
}
163155
Some(other) => {

‎src/cmd/scan/analysis.rs‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -6,7 +6,7 @@
66
77
use super::ScanState;
88
use super::args::ScanArgs;
9-
use super::logging::{log_dbg, start_spinner};
9+
use super::logging::start_spinner;
1010
use super::preflight::{PreflightOutcome, is_allowed_content_type, preflight_content_type};
1111
use crate::parameter_analysis::analyze_parameters;
1212
use crate::target_parser::Target;
@@ -652,7 +652,7 @@ pub(crate) async fn run_preflight_and_analysis(
652652
);
653653
}
654654
if args_clone.format == "plain" && !args_clone.silence {
655-
log_dbg(&format!("{} test cases (reqs) estimated", total));
655+
crate::dbg_log!("{} test cases (reqs) estimated", total);
656656
}
657657
}
658658
}

‎src/cmd/scan/logging.rs‎

Lines changed: 0 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -4,7 +4,6 @@
44
55
use super::args::ScanArgs;
66
use std::io::{self, Write};
7-
use std::sync::atomic::Ordering;
87
use std::time::Duration;
98
use tokio::sync::oneshot;
109

@@ -29,14 +28,6 @@ pub(crate) fn log_warn(args: &ScanArgs, msg: &str) {
2928
}
3029
}
3130

32-
/// DBG log line, gated on the global `--debug` flag (independent of format).
33-
pub(crate) fn log_dbg(msg: &str) {
34-
if crate::DEBUG.load(Ordering::Relaxed) {
35-
let ts = chrono::Local::now().format("%-I:%M%p").to_string();
36-
crate::cprintln!("\x1b[90m{}\x1b[0m \x1b[35mDBG\x1b[0m {}", ts, msg);
37-
}
38-
}
39-
4031
/// Ephemeral animated spinner for progress (returns `(stop_tx, done_rx)`).
4132
/// Suppressed when:
4233
/// - caller passes `enabled = false`

‎src/cmd/scan/mod.rs‎

Lines changed: 11 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -47,7 +47,7 @@ pub use args::{
4747
DEFAULT_RATE_LIMIT, DEFAULT_RETRIES, DEFAULT_RETRY_DELAY_MS, DEFAULT_TIMEOUT_SECS,
4848
DEFAULT_WAF_MIN_CONFIDENCE, DEFAULT_WORKERS, PreflightOptions, ScanArgs,
4949
};
50-
pub(crate) use logging::{log_dbg, log_info, log_warn};
50+
pub(crate) use logging::{log_info, log_warn};
5151
pub(crate) use validation::validate_numeric_args;
5252

5353
static GLOBAL_ENCODERS: OnceLock<Vec<String>> = OnceLock::new();
@@ -326,14 +326,17 @@ pub async fn run_scan(args: &ScanArgs) -> ScanOutcome {
326326
// isn't news. Operators triaging a MITM/TLS scenario can still surface it
327327
// with `--debug`, where it lands as a DBG line for any https target in
328328
// insecure mode. When validation is opted into (`--insecure=false`), nothing
329-
// is emitted. `log_dbg` ignores `--silence` (it gates on `--debug` only), so
330-
// a deliberately-quiet scan still shows it under debug.
329+
// is emitted. `dbg_log!` ignores `--silence` (it gates on `--debug` only) and
330+
// writes to stderr, so a deliberately-quiet or JSON scan still shows it under
331+
// debug without polluting structured stdout.
331332
if args.insecure.unwrap_or(true)
332333
&& parsed_targets
333334
.iter()
334335
.any(|t| t.url.scheme().eq_ignore_ascii_case("https"))
335336
{
336-
log_dbg("TLS validation disabled (--insecure default); use --insecure=false to enforce");
337+
crate::dbg_log!(
338+
"TLS validation disabled (--insecure default); use --insecure=false to enforce"
339+
);
337340
}
338341
// Track targets that were skipped during preflight (content-type mismatch etc.)
339342
// Map of skipped target URL -> error code explaining why it was skipped.
@@ -608,12 +611,10 @@ pub async fn run_scan(args: &ScanArgs) -> ScanOutcome {
608611
args,
609612
&format!("scan completed in {:.3} seconds", __dalfox_elapsed),
610613
);
611-
if crate::DEBUG.load(Ordering::Relaxed) {
612-
log_dbg(&format!(
613-
"{} test cases (reqs) sent",
614-
crate::REQUEST_COUNT.load(Ordering::Relaxed)
615-
));
616-
}
614+
crate::dbg_log!(
615+
"{} test cases (reqs) sent",
616+
crate::REQUEST_COUNT.load(Ordering::Relaxed)
617+
);
617618
}
618619

619620
// A scan where every supplied target failed reachability checks

‎src/cmd/scan/preflight.rs‎

Lines changed: 12 additions & 17 deletions
Original file line numberDiff line numberDiff line change
@@ -139,12 +139,11 @@ pub(crate) async fn preflight_content_type(
139139
let client = match target.build_client() {
140140
Ok(c) => c,
141141
Err(e) => {
142-
if crate::DEBUG.load(std::sync::atomic::Ordering::Relaxed) {
143-
eprintln!(
144-
"[DBG] preflight: failed to build HTTP client for {}: {}",
145-
target.url, e
146-
);
147-
}
142+
crate::dbg_log!(
143+
"preflight: failed to build HTTP client for {}: {}",
144+
target.url,
145+
e
146+
);
148147
return PreflightOutcome::Unreachable(crate::cmd::error_codes::CONNECTION_FAILED);
149148
}
150149
};
@@ -172,14 +171,12 @@ pub(crate) async fn preflight_content_type(
172171
Err(e) => {
173172
let transient = e.is_connect() || e.is_timeout();
174173
if transient && attempt < PREFLIGHT_MAX_ATTEMPTS {
175-
if crate::DEBUG.load(std::sync::atomic::Ordering::Relaxed) {
176-
eprintln!(
177-
"[DBG] preflight transient {} (attempt {}): {} — retrying",
178-
describe_reqwest_failure(&e),
179-
attempt,
180-
target.url
181-
);
182-
}
174+
crate::dbg_log!(
175+
"preflight transient {} (attempt {}): {} — retrying",
176+
describe_reqwest_failure(&e),
177+
attempt,
178+
target.url
179+
);
183180
tokio::time::sleep(Duration::from_millis(PREFLIGHT_RETRY_BACKOFF_MS)).await;
184181
continue;
185182
}
@@ -188,9 +185,7 @@ pub(crate) async fn preflight_content_type(
188185
// distinguish a quiet scan from an unreachable target. Suppressed
189186
// when --silence is on; the debug channel always carries it.
190187
let reason = describe_reqwest_failure(&e);
191-
if crate::DEBUG.load(std::sync::atomic::Ordering::Relaxed) {
192-
eprintln!("[DBG] preflight unreachable: {} ({})", target.url, reason);
193-
}
188+
crate::dbg_log!("preflight unreachable: {} ({})", target.url, reason);
194189
if !args.silence {
195190
let ts = chrono::Local::now().format("%-I:%M%p").to_string();
196191
crate::ceprintln!(

‎src/cmd/scan/tests.rs‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,4 @@
1-
use super::logging::{log_dbg, log_info, log_warn, start_spinner};
1+
use super::logging::{log_info, log_warn, start_spinner};
22
use super::output::{render_dry_run, render_only_discovery, render_results};
33
use super::poc::{build_ast_dom_message, generate_poc, render_finding_block};
44
use super::postprocess::{dedupe_ast_results, extract_context};
@@ -1454,9 +1454,9 @@ fn test_log_helpers_emit_in_plain_mode() {
14541454
args.silence = false;
14551455
log_info(&args, "info line");
14561456
log_warn(&args, "warn line");
1457-
// log_dbg is gated on the global DEBUG flag, which defaults to off here;
1458-
// calling it exercises the early-return branch without touching globals.
1459-
log_dbg("debug line");
1457+
// dbg_log! is gated on the global DEBUG flag, which defaults to off here;
1458+
// invoking it exercises the gate without touching globals (no stderr output).
1459+
crate::dbg_log!("debug line");
14601460
}
14611461

14621462
#[test]

‎src/oob/poller.rs‎

Lines changed: 1 addition & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -112,9 +112,7 @@ async fn poll_once(
112112
let interactions = match session.poll().await {
113113
Ok(v) => v,
114114
Err(e) => {
115-
if crate::DEBUG.load(Ordering::Relaxed) {
116-
eprintln!("[DBG] OOB poll failed: {e}");
117-
}
115+
crate::dbg_log!("OOB poll failed: {e}");
118116
return;
119117
}
120118
};

‎src/parameter_analysis/discovery.rs‎

Lines changed: 4 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -780,12 +780,10 @@ pub async fn check_header_discovery(
780780
// because the operator explicitly asked for them.
781781
let blanket_echo = detect_blanket_header_echo(target).await;
782782
if blanket_echo {
783-
if crate::DEBUG.load(std::sync::atomic::Ordering::Relaxed) {
784-
eprintln!(
785-
"[DBG] blanket header echo detected (guard reflected); skipping {} common header probes",
786-
COMMON_PROBE_HEADERS.len()
787-
);
788-
}
783+
crate::dbg_log!(
784+
"blanket header echo detected (guard reflected); skipping {} common header probes",
785+
COMMON_PROBE_HEADERS.len()
786+
);
789787
} else {
790788
for &hdr in COMMON_PROBE_HEADERS {
791789
if existing_names.insert(hdr.to_ascii_lowercase()) {

‎src/parameter_analysis/mod.rs‎

Lines changed: 1 addition & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -523,9 +523,7 @@ async fn send_probe_request_for_param(
523523
let body_text = match crate::utils::http::read_body(resp).await {
524524
Ok(body) => Some(body),
525525
Err(e) => {
526-
if crate::DEBUG.load(std::sync::atomic::Ordering::Relaxed) {
527-
eprintln!("[DBG] discovery response body read failed: {}", e);
528-
}
526+
crate::dbg_log!("discovery response body read failed: {}", e);
529527
None
530528
}
531529
};

‎src/scanning/check_reflection.rs‎

Lines changed: 25 additions & 30 deletions
Original file line numberDiff line numberDiff line change
@@ -1580,12 +1580,11 @@ async fn fetch_injection_response_with_client(
15801580
.and_then(|v| v.to_str().ok())
15811581
.unwrap_or("");
15821582
if crate::utils::content_type_is_inert_data(ct) {
1583-
if crate::DEBUG.load(std::sync::atomic::Ordering::Relaxed) {
1584-
eprintln!(
1585-
"[DBG] suppressing reflection on inert-data content-type (param={}, content-type={})",
1586-
param.name, ct
1587-
);
1588-
}
1583+
crate::dbg_log!(
1584+
"suppressing reflection on inert-data content-type (param={}, content-type={})",
1585+
param.name,
1586+
ct
1587+
);
15891588
return None;
15901589
}
15911590
}
@@ -1598,12 +1597,11 @@ async fn fetch_injection_response_with_client(
15981597
// browsers render it as data, not markup.
15991598
if matches!(param.location, Location::Path) {
16001599
if (300..400).contains(&status_code) {
1601-
if crate::DEBUG.load(std::sync::atomic::Ordering::Relaxed) {
1602-
eprintln!(
1603-
"[DBG] suppressing path reflection on 3xx redirect (param={}, status={})",
1604-
param.name, status_code
1605-
);
1606-
}
1600+
crate::dbg_log!(
1601+
"suppressing path reflection on 3xx redirect (param={}, status={})",
1602+
param.name,
1603+
status_code
1604+
);
16071605
return None;
16081606
}
16091607
let ct = resp
@@ -1619,12 +1617,11 @@ async fn fetch_injection_response_with_client(
16191617
let executes_as_markup = crate::utils::is_htmlish_content_type(ct)
16201618
|| crate::utils::content_type_primary(ct).as_deref() == Some("image/svg+xml");
16211619
if !ct.is_empty() && !executes_as_markup {
1622-
if crate::DEBUG.load(std::sync::atomic::Ordering::Relaxed) {
1623-
eprintln!(
1624-
"[DBG] suppressing path-injection reflection on non-HTML content-type (param={}, content-type={})",
1625-
param.name, ct
1626-
);
1627-
}
1620+
crate::dbg_log!(
1621+
"suppressing path-injection reflection on non-HTML content-type (param={}, content-type={})",
1622+
param.name,
1623+
ct
1624+
);
16281625
return None;
16291626
}
16301627
}
@@ -1666,23 +1663,21 @@ async fn fetch_injection_response_with_client(
16661663
&body,
16671664
payload,
16681665
) {
1669-
if crate::DEBUG.load(std::sync::atomic::Ordering::Relaxed) {
1670-
eprintln!(
1671-
"[DBG] suppressing url-echo-only path reflection (param={}, status={})",
1672-
param.name, status_code
1673-
);
1674-
}
1666+
crate::dbg_log!(
1667+
"suppressing url-echo-only path reflection (param={}, status={})",
1668+
param.name,
1669+
status_code
1670+
);
16751671
return None;
16761672
}
16771673
Some(body)
16781674
}
16791675
Err(e) => {
1680-
if crate::DEBUG.load(std::sync::atomic::Ordering::Relaxed) {
1681-
eprintln!(
1682-
"[DBG] reflection response body read failed (param={}): {}",
1683-
param.name, e
1684-
);
1685-
}
1676+
crate::dbg_log!(
1677+
"reflection response body read failed (param={}): {}",
1678+
param.name,
1679+
e
1680+
);
16861681
None
16871682
}
16881683
}

0 commit comments

Comments
 (0)