Normalize logging levels (#8579)

Author: cwfitzgerald

CHANGELOG.md

@@ -106,6 +106,20 @@ One other breaking change worth noting is that in WGSL `@builtin(view_index)` no
 
 By @SupaMaggie70Incorporated in [#8206](https://github.com/gfx-rs/wgpu/pull/8206).
 
+#### Log Levels
+
+We have received complaints about wgpu being way too log spammy at log levels `info`/`warn`/`error`. We have
+adjusted our log policy and changed logging such that `info` and above should be silent unless some exceptional
+event happens. Our new log policy is as follows:
+
+- Error: if we can’t (for some reason, usually a bug) communicate an error any other way.
+- Warning: similar, but there may be one-shot warnings about almost certainly sub-optimal.
+- Info: do not use
+- Debug: Used for interesting events happening inside wgpu.
+- Trace: Used for all events that might be useful to either `wgpu` or application developers.
+
+By @cwfitzgerald in [#8579](https://github.com/gfx-rs/wgpu/pull/8579).
+
 ### New Features
 
 - Added support for transient textures on Vulkan and Metal. By @opstic in [#8247](https://github.com/gfx-rs/wgpu/pull/8247)

examples/features/src/framework.rs

@@ -60,16 +60,11 @@ fn init_logger() {
             let query_level: Option<log::LevelFilter> = parse_url_query_string(&query_string, "RUST_LOG")
                 .and_then(|x| x.parse().ok());
 
-            // We keep wgpu at Error level, as it's very noisy.
             let base_level = query_level.unwrap_or(log::LevelFilter::Info);
-            let wgpu_level = query_level.unwrap_or(log::LevelFilter::Error);
 
             // On web, we use fern, as console_log doesn't have filtering on a per-module level.
             fern::Dispatch::new()
                 .level(base_level)
-                .level_for("wgpu_core", wgpu_level)
-                .level_for("wgpu_hal", wgpu_level)
-                .level_for("naga", wgpu_level)
                 .chain(fern::Output::call(console_log::log))
                 .apply()
                 .unwrap();
@@ -79,10 +74,6 @@ fn init_logger() {
             // of these default filters.
             env_logger::builder()
                 .filter_level(log::LevelFilter::Info)
-                // We keep wgpu at Error level, as it's very noisy.
-                .filter_module("wgpu_core", log::LevelFilter::Info)
-                .filter_module("wgpu_hal", log::LevelFilter::Error)
-                .filter_module("naga", log::LevelFilter::Error)
                 .parse_default_env()
                 .init();
         }

naga/src/back/hlsl/writer.rs

@@ -441,7 +441,7 @@ impl<'a, W: fmt::Write> super::Writer<'a, W> {
                             _ => false,
                         })
                 {
-                    log::info!(
+                    log::debug!(
                         "Skipping function {:?} (name {:?}) because global {:?} is inaccessible",
                         handle,
                         function.name,
@@ -945,7 +945,7 @@ impl<'a, W: fmt::Write> super::Writer<'a, W> {
 
         if let Some(ref binding) = global.binding {
             if let Err(err) = self.options.resolve_resource_binding(binding) {
-                log::info!(
+                log::debug!(
                     "Skipping global {:?} (name {:?}) for being inaccessible: {}",
                     handle,
                     global.name,
@@ -1187,7 +1187,7 @@ impl<'a, W: fmt::Write> super::Writer<'a, W> {
         {
             Ok(bindings) => bindings,
             Err(err) => {
-                log::info!(
+                log::debug!(
                     "Skipping global {:?} (name {:?}) for being inaccessible: {}",
                     handle,
                     global.name,

naga/src/back/spv/writer.rs

@@ -2666,7 +2666,7 @@ impl Writer {
                 // because the entry point and its callees didn't use them,
                 // then we must skip it.
                 if !ep_info.dominates_global_use(info) {
-                    log::info!("Skip function {:?}", ir_function.name);
+                    log::debug!("Skip function {:?}", ir_function.name);
                     continue;
                 }
 

naga/src/front/glsl/builtins.rs

@@ -1669,7 +1669,7 @@ impl MacroCall {
                         num_args += 1;
 
                         if shadow {
-                            log::warn!("Assuming LOD {:?} is zero", args[2],);
+                            log::debug!("Assuming LOD {:?} is zero", args[2],);
 
                             SampleLevel::Zero
                         } else {
@@ -1681,7 +1681,7 @@ impl MacroCall {
                         num_args += 2;
 
                         if shadow {
-                            log::warn!(
+                            log::debug!(
                                 "Assuming gradients {:?} and {:?} are not greater than 1",
                                 args[2],
                                 args[3],

naga/src/front/spv/mod.rs

@@ -799,7 +799,15 @@ impl<I: Iterator<Item = u32>> Frontend<I> {
                 dec.specialization_constant_id = Some(self.next()?);
             }
             other => {
-                log::warn!("Unknown decoration {other:?}");
+                let level = match other {
+                    // Block decorations show up everywhere and we don't
+                    // really care about them, so to prevent log spam
+                    // we demote them to debug level.
+                    spirv::Decoration::Block => log::Level::Debug,
+                    _ => log::Level::Warn,
+                };
+
+                log::log!(level, "Unknown decoration {other:?}");
                 for _ in base_words + 1..inst.wc {
                     let _var = self.next()?;
                 }
@@ -4746,7 +4754,7 @@ impl<I: Iterator<Item = u32>> Frontend<I> {
             let generator = self.next()?;
             let _bound = self.next()?;
             let _schema = self.next()?;
-            log::info!("Generated by {generator} version {version_raw:x}");
+            log::debug!("Generated by {generator} version {version_raw:x}");
             crate::Module::default()
         };
 
@@ -4816,7 +4824,7 @@ impl<I: Iterator<Item = u32>> Frontend<I> {
         }
 
         if !self.upgrade_atomics.is_empty() {
-            log::info!("Upgrading atomic pointers...");
+            log::debug!("Upgrading atomic pointers...");
             module.upgrade_atomics(&self.upgrade_atomics)?;
         }
 
@@ -4826,7 +4834,7 @@ impl<I: Iterator<Item = u32>> Frontend<I> {
             self.process_entry_point(&mut module, ep, fun_id)?;
         }
 
-        log::info!("Patching...");
+        log::debug!("Patching...");
         {
             let mut nodes = petgraph::algo::toposort(&self.function_call_graph, None)
                 .map_err(|cycle| Error::FunctionCallCycle(cycle.node_id()))?;
@@ -4866,11 +4874,11 @@ impl<I: Iterator<Item = u32>> Frontend<I> {
         }
 
         if !self.future_decor.is_empty() {
-            log::warn!("Unused item decorations: {:?}", self.future_decor);
+            log::debug!("Unused item decorations: {:?}", self.future_decor);
             self.future_decor.clear();
         }
         if !self.future_member_decor.is_empty() {
-            log::warn!("Unused member decorations: {:?}", self.future_member_decor);
+            log::debug!("Unused member decorations: {:?}", self.future_member_decor);
             self.future_member_decor.clear();
         }
 

naga/src/valid/interface.rs

@@ -65,8 +65,8 @@ pub enum VaryingError {
     MissingInterpolation,
     #[error("Built-in {0:?} is not available at this stage")]
     InvalidBuiltInStage(crate::BuiltIn),
-    #[error("Built-in type for {0:?} is invalid")]
-    InvalidBuiltInType(crate::BuiltIn),
+    #[error("Built-in type for {0:?} is invalid. Found {1:?}")]
+    InvalidBuiltInType(crate::BuiltIn, crate::TypeInner),
     #[error("Entry point arguments and return values must all have bindings")]
     MissingBinding,
     #[error("Struct member {0} is missing a binding")]
@@ -426,8 +426,7 @@ impl VaryingContext<'_> {
                     return Err(VaryingError::InvalidBuiltInStage(built_in));
                 }
                 if !type_good {
-                    log::warn!("Wrong builtin type: {ty_inner:?}");
-                    return Err(VaryingError::InvalidBuiltInType(built_in));
+                    return Err(VaryingError::InvalidBuiltInType(built_in, ty_inner.clone()));
                 }
             }
             crate::Binding::Location {

naga/tests/naga/wgsl_errors.rs

@@ -4090,7 +4090,7 @@ fn invalid_clip_distances() {
         Err(naga::valid::ValidationError::EntryPoint {
             stage: naga::ShaderStage::Vertex,
             source: naga::valid::EntryPointError::Result(
-                naga::valid::VaryingError::InvalidBuiltInType(naga::ir::BuiltIn::ClipDistance)
+                naga::valid::VaryingError::InvalidBuiltInType(naga::ir::BuiltIn::ClipDistance, _)
             ),
             ..
         }),

wgpu-core/src/command/ray_tracing.rs

@@ -340,7 +340,7 @@ pub(crate) fn build_acceleration_structures(
     } in &tlas_storage
     {
         if tlas.update_mode == wgt::AccelerationStructureUpdateMode::PreferUpdate {
-            log::info!("only rebuild implemented")
+            log::warn!("build_acceleration_structures called with PreferUpdate, but only rebuild is implemented");
         }
         tlas_descriptors.push(hal::BuildAccelerationStructureDescriptor {
             entries,
@@ -941,7 +941,7 @@ fn map_blas<'a>(
         scratch_buffer_offset,
     } = storage;
     if blas.update_mode == wgt::AccelerationStructureUpdateMode::PreferUpdate {
-        log::info!("only rebuild implemented")
+        log::debug!("only rebuild implemented")
     }
     let raw = blas.try_raw(snatch_guard)?;
 

wgpu-core/src/device/resource.rs

@@ -2306,9 +2306,6 @@ impl Device {
         self.check_is_valid()?;
         self.require_features(wgt::Features::EXPERIMENTAL_PASSTHROUGH_SHADERS)?;
 
-        // TODO: when we get to use if-let chains, this will be a little nicer!
-
-        log::info!("Backend: {}", self.backend());
         let hal_shader = match self.backend() {
             wgt::Backend::Vulkan => hal::ShaderInput::SpirV(
                 descriptor
@@ -4433,7 +4430,7 @@ impl Device {
                         )?;
                     }
                     _ => {
-                        log::warn!(
+                        log::debug!(
                             "The fragment stage {:?} output @location({}) values are ignored",
                             fragment_stage
                                 .as_ref()