alpha2_gpu/
validation_log.rs

1//! Collects the validation messages `wgpu-hal` sends only to the `log` crate, so tests can report
2//! or fail on them.
3//!
4//! `wgpu-hal` logs Vulkan, GL and D3D12 debug messages inside `catch_unwind`, so a panicking
5//! logger is ignored and without a logger they are dropped. [`install`] makes this module the
6//! logger; it keeps `wgpu_hal` records at `Error` and `Warn` and echoes them to standard error.
7//!
8//! The D3D12 debug layer reaches `wgpu-hal` only with a debugger attached, but always stores
9//! messages in the device's `ID3D12InfoQueue`. Once installed, every adopted DX12 device's queue
10//! is read at each checkpoint and the debugger-route records are dropped to avoid duplicates.
11//! Watched devices are kept until process exit.
12//!
13//! Tests read their records with a [`Checkpoint`] or a [`TestTurn`], which reports or fails per
14//! `ALPHA2_VALIDATION_LOG` ([`ValidationMode`]). Intentional errors go through [`expect_errors`].
15
16use std::fmt::Write as _;
17use std::io::Write as _;
18use std::path::PathBuf;
19use std::sync::atomic::{AtomicU64, AtomicUsize, Ordering};
20use std::sync::{Mutex, MutexGuard, OnceLock, PoisonError};
21
22/// One message a `wgpu_hal` target logged at `Error` or `Warn`.
23#[derive(Clone, Debug, PartialEq, Eq)]
24pub struct ValidationRecord {
25    /// The level it was logged at.
26    pub level: log::Level,
27    /// The module that logged it, such as `wgpu_hal::vulkan::instance`.
28    pub target: String,
29    /// The message.
30    pub message: String,
31    /// The logging thread's name (the test name on a test thread).
32    pub thread: Option<String>,
33}
34
35/// What a [`TestTurn`] does with the records of its turn, from `ALPHA2_VALIDATION_LOG`.
36#[derive(Clone, Copy, PartialEq, Eq, Debug)]
37pub enum ValidationMode {
38    /// `off`: nothing is installed or collected.
39    Off,
40    /// `report` (the default): records go to standard error and to `ALPHA2_VALIDATION_REPORT`
41    /// when set.
42    Report,
43    /// `fail`: as `report`, then an `Error` record fails the turn.
44    Fail,
45}
46
47/// The `ALPHA2_VALIDATION_LOG` mode, read once: `off`, `report` or `fail`, default `report`.
48///
49/// # Panics
50/// On any other value, so a misspelt mode never runs blind.
51#[must_use]
52pub fn mode() -> ValidationMode {
53    static MODE: OnceLock<ValidationMode> = OnceLock::new();
54    *MODE.get_or_init(|| {
55        match std::env::var("ALPHA2_VALIDATION_LOG")
56            .unwrap_or_default()
57            .as_str()
58        {
59            "" | "report" => ValidationMode::Report,
60            "off" => ValidationMode::Off,
61            "fail" => ValidationMode::Fail,
62            other => panic!("ALPHA2_VALIDATION_LOG must be off, report or fail, not {other:?}"),
63        }
64    })
65}
66
67/// Why [`install`] could not make the collector the process's logger.
68#[derive(Clone, Copy, Debug, PartialEq, Eq)]
69#[non_exhaustive]
70pub enum InstallError {
71    /// Another logger was installed first, so `wgpu-hal`'s messages go there.
72    AlreadySet,
73}
74
75impl std::fmt::Display for InstallError {
76    fn fmt(&self, formatter: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
77        match self {
78            Self::AlreadySet => formatter.write_str(
79                "another logger was installed before the validation collector, so validation \
80                 messages would not be collected",
81            ),
82        }
83    }
84}
85
86impl std::error::Error for InstallError {}
87
88/// Makes the collector the process logger at `Warn` level. Idempotent; a no-op on wasm.
89///
90/// # Errors
91/// [`InstallError::AlreadySet`] when another logger was installed first.
92pub fn install() -> Result<(), InstallError> {
93    static INSTALLED: OnceLock<Result<(), InstallError>> = OnceLock::new();
94    if cfg!(target_arch = "wasm32") {
95        return Ok(());
96    }
97    *INSTALLED.get_or_init(|| {
98        log::set_logger(&SINK).map_err(|_| InstallError::AlreadySet)?;
99        log::set_max_level(log::LevelFilter::Warn);
100        SINK.installed.store(1, Ordering::Release);
101        Ok(())
102    })
103}
104
105/// Installs the collector unless [`mode`] is [`ValidationMode::Off`]. Call before the first
106/// device so its D3D12 queue is watched.
107///
108/// # Panics
109/// When another logger was installed first ([`InstallError::AlreadySet`]).
110pub fn install_unless_off() {
111    if mode() != ValidationMode::Off {
112        install().unwrap_or_else(|error| panic!("{error}"));
113    }
114}
115
116fn installed() -> bool {
117    SINK.installed.load(Ordering::Acquire) == 1
118}
119
120/// Records logged between [`Checkpoint::begin`] and [`Checkpoint::finish`], plus earlier
121/// unclaimed records labelled with this checkpoint's name.
122#[derive(Debug)]
123pub struct Checkpoint {
124    name: String,
125    earlier: Vec<ValidationRecord>,
126}
127
128impl Checkpoint {
129    /// Begins a checkpoint called `name`, installing the collector unless the mode is
130    /// [`ValidationMode::Off`].
131    ///
132    /// # Panics
133    /// When another logger was installed first ([`InstallError::AlreadySet`]).
134    #[must_use]
135    pub fn begin(name: &str) -> Self {
136        install_unless_off();
137        let earlier = take_records()
138            .into_iter()
139            .map(|mut record| {
140                // Logged outside any checkpoint, such as a late driver callback.
141                record.message = format!("before {name}: {}", record.message);
142                record
143            })
144            .collect();
145        Self {
146            name: name.to_owned(),
147            earlier,
148        }
149    }
150
151    /// The name the checkpoint was begun with.
152    #[must_use]
153    pub fn name(&self) -> &str {
154        &self.name
155    }
156
157    /// Ends the checkpoint and returns its records, oldest first.
158    #[must_use]
159    pub fn finish(mut self) -> Vec<ValidationRecord> {
160        let mut records = std::mem::take(&mut self.earlier);
161        records.extend(take_records());
162        records
163    }
164}
165
166/// Runs `test`, which causes validation errors on purpose, and returns the records it logged
167/// instead of reporting them. The caller must hold the GPU turn.
168pub fn expect_errors<R>(test: impl FnOnce() -> R) -> (R, Vec<ValidationRecord>) {
169    drain_watched();
170    let first = SINK.next.load(Ordering::Acquire);
171    SINK.expecting.fetch_add(1, Ordering::AcqRel);
172    let result = test();
173    drain_watched();
174    SINK.expecting.fetch_sub(1, Ordering::AcqRel);
175    let mut records = SINK.records();
176    let (expected, other): (Vec<_>, Vec<_>) = records
177        .drain(..)
178        .partition(|(sequence, _)| *sequence >= first);
179    *records = other;
180    (
181        result,
182        expected.into_iter().map(|(_, record)| record).collect(),
183    )
184}
185
186/// What a [`TestTurn`] does when its turn ends.
187#[derive(Clone, Debug, PartialEq, Eq)]
188pub struct TurnSettings {
189    /// Whether records are reported, fail the turn, or are not collected.
190    pub mode: ValidationMode,
191    /// A file each record is appended to as a JSON line `{"test", "level", "target", "message"}`.
192    pub report: Option<PathBuf>,
193}
194
195impl TurnSettings {
196    /// [`mode`] and a non-empty `ALPHA2_VALIDATION_REPORT`.
197    #[must_use]
198    pub fn from_environment() -> Self {
199        Self {
200            mode: mode(),
201            report: std::env::var_os("ALPHA2_VALIDATION_REPORT")
202                .filter(|path| !path.is_empty())
203                .map(PathBuf::from),
204        }
205    }
206}
207
208/// A test's GPU turn: the suite's serializing `guard` plus a [`Checkpoint`] named after the test,
209/// which reports or fails before the guard is released.
210pub struct TestTurn<G> {
211    checkpoint: Option<Checkpoint>,
212    settings: TurnSettings,
213    _guard: G,
214}
215
216impl<G> TestTurn<G> {
217    /// A turn holding `guard`, with environment settings and the current thread's test name.
218    ///
219    /// # Panics
220    /// As [`Checkpoint::begin`], and on a mode `ALPHA2_VALIDATION_LOG` does not name.
221    #[must_use]
222    pub fn new(guard: G) -> Self {
223        Self::with_settings(guard, TurnSettings::from_environment())
224    }
225
226    /// A turn holding `guard` with `settings`, whatever the environment says.
227    ///
228    /// # Panics
229    /// As [`Checkpoint::begin`].
230    #[must_use]
231    pub fn with_settings(guard: G, settings: TurnSettings) -> Self {
232        let checkpoint = (settings.mode != ValidationMode::Off).then(|| {
233            install().unwrap_or_else(|error| panic!("{error}"));
234            let thread = std::thread::current();
235            Checkpoint::begin(thread.name().unwrap_or("an unnamed thread"))
236        });
237        Self {
238            checkpoint,
239            settings,
240            _guard: guard,
241        }
242    }
243}
244
245impl<G> Drop for TestTurn<G> {
246    fn drop(&mut self) {
247        let Some(checkpoint) = self.checkpoint.take() else {
248            return;
249        };
250        let test = checkpoint.name().to_owned();
251        let records = checkpoint.finish();
252        if records.is_empty() {
253            return;
254        }
255        if let Some(path) = &self.settings.report {
256            append_report(path, &test, &records);
257        }
258        let errors = records
259            .iter()
260            .filter(|record| record.level == log::Level::Error)
261            .count();
262        if self.settings.mode == ValidationMode::Fail && errors > 0 && !std::thread::panicking() {
263            let listed = records
264                .iter()
265                .map(|record| format!("  {} {}: {}", record.level, record.target, record.message))
266                .collect::<Vec<_>>()
267                .join("\n");
268            panic!("{test}: {errors} validation error(s) during the test:\n{listed}");
269        }
270    }
271}
272
273/// Appends one JSON line per record to `path`; write failures are reported, not fatal.
274fn append_report(path: &std::path::Path, test: &str, records: &[ValidationRecord]) {
275    let mut lines = String::new();
276    for record in records {
277        let _ = writeln!(
278            lines,
279            "{{\"test\":{},\"level\":{},\"target\":{},\"message\":{}}}",
280            json_string(test),
281            json_string(record.level.as_str()),
282            json_string(&record.target),
283            json_string(&record.message),
284        );
285    }
286    let written = std::fs::OpenOptions::new()
287        .create(true)
288        .append(true)
289        .open(path)
290        .and_then(|mut file| file.write_all(lines.as_bytes()));
291    if let Err(error) = written {
292        note(format_args!(
293            "validation: could not append to {}: {error}",
294            path.display()
295        ));
296    }
297}
298
299/// `text` as a JSON string literal.
300fn json_string(text: &str) -> String {
301    let mut quoted = String::with_capacity(text.len() + 2);
302    quoted.push('"');
303    for character in text.chars() {
304        match character {
305            '"' => quoted.push_str("\\\""),
306            '\\' => quoted.push_str("\\\\"),
307            '\n' => quoted.push_str("\\n"),
308            '\r' => quoted.push_str("\\r"),
309            '\t' => quoted.push_str("\\t"),
310            control if u32::from(control) < 0x20 => {
311                let _ = write!(quoted, "\\u{:04x}", u32::from(control));
312            }
313            other => quoted.push(other),
314        }
315    }
316    quoted.push('"');
317    quoted
318}
319
320struct Sink {
321    records: Mutex<Vec<(u64, ValidationRecord)>>,
322    next: AtomicU64,
323    /// Running [`expect_errors`] calls, whose records are marked as expected.
324    expecting: AtomicUsize,
325    /// 1 once [`install`] made this the logger.
326    installed: AtomicUsize,
327}
328
329static SINK: Sink = Sink {
330    records: Mutex::new(Vec::new()),
331    next: AtomicU64::new(0),
332    expecting: AtomicUsize::new(0),
333    installed: AtomicUsize::new(0),
334};
335
336impl Sink {
337    fn records(&self) -> MutexGuard<'_, Vec<(u64, ValidationRecord)>> {
338        self.records.lock().unwrap_or_else(PoisonError::into_inner)
339    }
340
341    /// Keeps `record` and echoes it. Tab-indented continuation lines that `wgpu-hal` logs after a
342    /// Vulkan message join that message's record.
343    fn keep(&self, record: ValidationRecord) {
344        if record.message.starts_with('\t') {
345            let mut records = self.records();
346            if let Some((_, last)) = records.last_mut()
347                && last.target == record.target
348                && last.thread == record.thread
349            {
350                last.message.push('\n');
351                last.message.push_str(&record.message);
352                return;
353            }
354        }
355        let expected = if self.expecting.load(Ordering::Acquire) > 0 {
356            " (expected)"
357        } else {
358            ""
359        };
360        note(format_args!(
361            "validation{expected}: {} {}: {}",
362            record.level, record.target, record.message
363        ));
364        let mut records = self.records();
365        let sequence = self.next.fetch_add(1, Ordering::AcqRel);
366        records.push((sequence, record));
367    }
368}
369
370impl log::Log for Sink {
371    fn enabled(&self, metadata: &log::Metadata<'_>) -> bool {
372        metadata.level() <= log::Level::Warn && metadata.target().starts_with("wgpu_hal")
373    }
374
375    fn log(&self, record: &log::Record<'_>) {
376        if !self.enabled(record.metadata()) {
377            return;
378        }
379        // D3D12 messages are read from the watched queues instead.
380        if record.target().starts_with(DEBUGGER_ROUTE) && watching() {
381            return;
382        }
383        self.keep(ValidationRecord {
384            level: record.level(),
385            target: record.target().to_owned(),
386            message: record.args().to_string(),
387            thread: std::thread::current().name().map(str::to_owned),
388        });
389    }
390
391    fn flush(&self) {}
392}
393
394/// Like `eprintln!` (so libtest captures it) but does not panic when standard error is closed.
395fn note(line: std::fmt::Arguments<'_>) {
396    let _ = std::panic::catch_unwind(std::panic::AssertUnwindSafe(|| eprintln!("{line}")));
397}
398
399/// Target of `wgpu-hal` records from the D3D12 debugger output.
400const DEBUGGER_ROUTE: &str = "wgpu_hal::auxil::dxgi::exception";
401
402/// Takes every record the collector holds, reading the watched devices' queues first.
403fn take_records() -> Vec<ValidationRecord> {
404    drain_watched();
405    SINK.records().drain(..).map(|(_, record)| record).collect()
406}
407
408/// When the collector is installed, logs `gpu tests on <summary>` and starts watching the
409/// D3D12 debug queue of a DX12 `device`. Called for every adopted device.
410pub(crate) fn watch_device(device: &wgpu::Device, summary: &str) {
411    if !installed() {
412        return;
413    }
414    note(format_args!("gpu tests on {summary}"));
415    #[cfg(windows)]
416    d3d12::watch(device);
417    #[cfg(not(windows))]
418    let _ = device;
419}
420
421fn watching() -> bool {
422    #[cfg(windows)]
423    {
424        d3d12::watching()
425    }
426    #[cfg(not(windows))]
427    {
428        false
429    }
430}
431
432/// Reads what the watched D3D12 queues stored since the last read into the collector.
433fn drain_watched() {
434    #[cfg(windows)]
435    d3d12::drain();
436}
437
438/// The D3D12 debug layer's message queues.
439#[cfg(windows)]
440#[allow(unsafe_code)]
441mod d3d12 {
442    use std::sync::{Mutex, PoisonError};
443
444    use windows::Win32::Graphics::Direct3D12::{
445        D3D12_MESSAGE, D3D12_MESSAGE_SEVERITY_CORRUPTION, D3D12_MESSAGE_SEVERITY_ERROR,
446        D3D12_MESSAGE_SEVERITY_WARNING, ID3D12InfoQueue,
447    };
448    use windows::core::Interface as _;
449
450    use super::{SINK, ValidationRecord};
451
452    /// The target of the records read from a queue.
453    const TARGET: &str = "wgpu_hal::dx12::info_queue";
454
455    /// A watched queue and its read count, which includes discarded messages so it only grows.
456    struct Watched {
457        queue: ID3D12InfoQueue,
458        read: u64,
459    }
460
461    static WATCHED: Mutex<Vec<Watched>> = Mutex::new(Vec::new());
462
463    pub(super) fn watching() -> bool {
464        !WATCHED
465            .lock()
466            .unwrap_or_else(PoisonError::into_inner)
467            .is_empty()
468    }
469
470    pub(super) fn watch(device: &wgpu::Device) {
471        // SAFETY: the raw device is only queried for another interface, which takes a reference
472        // of its own; nothing is destroyed through it.
473        let Some(hal) = (unsafe { device.as_hal::<wgpu::hal::api::Dx12>() }) else {
474            return;
475        };
476        // Without the debug layer the device has no info queue.
477        let Ok(queue) = hal.raw_device().cast::<ID3D12InfoQueue>() else {
478            return;
479        };
480        let mut watched = WATCHED.lock().unwrap_or_else(PoisonError::into_inner);
481        // D3D12 has one device per adapter, so contexts may share a queue.
482        if watched.iter().any(|known| known.queue == queue) {
483            return;
484        }
485        // Messages stored before the device was watched belong to no test.
486        let read = total(&queue);
487        watched.push(Watched { queue, read });
488    }
489
490    /// Stored plus discarded message count.
491    fn total(queue: &ID3D12InfoQueue) -> u64 {
492        // SAFETY: two counter reads on a live queue.
493        unsafe { queue.GetNumStoredMessages() + queue.GetNumMessagesDiscardedByMessageCountLimit() }
494    }
495
496    pub(super) fn drain() {
497        let mut watched = WATCHED.lock().unwrap_or_else(PoisonError::into_inner);
498        for known in watched.iter_mut() {
499            let total = total(&known.queue);
500            // The queue was cleared, so the count restarts.
501            if total < known.read {
502                known.read = 0;
503            }
504            // SAFETY: a counter read on a live queue.
505            let discarded = unsafe { known.queue.GetNumMessagesDiscardedByMessageCountLimit() };
506            for absolute in known.read.max(discarded)..total {
507                if let Some(record) = message(&known.queue, absolute - discarded) {
508                    SINK.keep(record);
509                }
510            }
511            known.read = total;
512        }
513    }
514
515    /// The stored message at `index` if it is an error, corruption or warning.
516    fn message(queue: &ID3D12InfoQueue, index: u64) -> Option<ValidationRecord> {
517        let mut length = 0;
518        // SAFETY: a live queue; asked for the length only.
519        unsafe { queue.GetMessage(index, None, &raw mut length) }.ok()?;
520        if length == 0 {
521            return None;
522        }
523        // Aligned for the structure; the description follows it in the same buffer.
524        let mut storage = vec![0_u64; length.div_ceil(8)];
525        let message = storage.as_mut_ptr().cast::<D3D12_MESSAGE>();
526        // SAFETY: `storage` holds the `length` bytes the call writes.
527        unsafe { queue.GetMessage(index, Some(message), &raw mut length) }.ok()?;
528        // SAFETY: the call wrote a message, whose description points into `storage`.
529        let message = unsafe { &*message };
530        let level = match message.Severity {
531            D3D12_MESSAGE_SEVERITY_CORRUPTION | D3D12_MESSAGE_SEVERITY_ERROR => log::Level::Error,
532            D3D12_MESSAGE_SEVERITY_WARNING => log::Level::Warn,
533            _ => return None,
534        };
535        // SAFETY: the description is `DescriptionByteLength` bytes inside `storage`.
536        let text = unsafe {
537            std::slice::from_raw_parts(message.pDescription, message.DescriptionByteLength)
538        };
539        Some(ValidationRecord {
540            level,
541            target: TARGET.to_owned(),
542            message: String::from_utf8_lossy(text)
543                .trim_end_matches('\0')
544                .to_owned(),
545            thread: None,
546        })
547    }
548}
alpha2_gpu/validation_log.rs

alpha2_gpu/
validation_log.rs
