From 8f911225253fd23c24e79e1ff10c5696372635dd Mon Sep 17 00:00:00 2001 From: freezy Date: Thu, 15 Oct 2026 17:51:06 +0200 Subject: [PATCH 1/2] logging: HDRP runtime on NLog. Material resolver and auto focus log through NLog at the right levels; probes that fail on purpose log at debug, and losing subsurface scattering is a warning once per profile. --- Runtime/AutoFocusComponent.cs | 16 +++-- Runtime/HdrpMaterialResolver.cs | 55 ++++++++++------- Runtime/VpeMaterialResolverBootstrap.cs | 79 ++++++++++--------------- 3 files changed, 75 insertions(+), 75 deletions(-) diff --git a/Runtime/AutoFocusComponent.cs b/Runtime/AutoFocusComponent.cs index fd4adf4e..5e866653 100644 --- a/Runtime/AutoFocusComponent.cs +++ b/Runtime/AutoFocusComponent.cs @@ -14,10 +14,12 @@ // You should have received a copy of the GNU General Public License // along with this program. If not, see . +using NLog; using Unity.Mathematics; using UnityEngine; using UnityEngine.Rendering; using UnityEngine.Rendering.HighDefinition; +using Logger = NLog.Logger; namespace VisualPinball.Engine.Unity.Hdrp { @@ -39,6 +41,8 @@ namespace VisualPinball.Engine.Unity.Hdrp [DisallowMultipleComponent] public class AutoFocusComponent : MonoBehaviour { + private static readonly Logger Logger = LogManager.GetCurrentClassLogger(); + [Tooltip("The volume whose depth of field is driven. If empty, the active global volume with the highest priority is used.")] public Volume PostProcessVolume; @@ -92,7 +96,7 @@ private void OnEnable() { _camera = GetComponent(); if (DepthProbeShader == null) { - Debug.LogWarning($"[AutoFocus] No depth probe shader assigned on {name}, cannot focus.", this); + Logger.Warn("[AutoFocus] No depth probe shader assigned on {Camera}, cannot focus.", name); return; } @@ -100,7 +104,7 @@ private void OnEnable() var volumeLayers = _camera.TryGetComponent(out var cameraData) ? (int)cameraData.volumeLayerMask : ~0; var volume = PostProcessVolume != null ? PostProcessVolume : HdrpGraphicsApplier.FindGlobalVolume(volumeLayers); if (volume == null) { - Debug.LogWarning($"[AutoFocus] No post process volume found for {name}, cannot focus.", this); + Logger.Warn("[AutoFocus] No post process volume found for {Camera}, cannot focus.", name); return; } @@ -110,7 +114,7 @@ private void OnEnable() _dof = profile.Add(); } if (Owners.TryGetValue(_dof, out var owner) && owner != null && owner != this && owner.isActiveAndEnabled) { - Debug.LogWarning($"[AutoFocus] {owner.name} already drives the depth of field of {volume.name}; {name} leaves it alone. Give it a volume of its own.", this); + Logger.Warn("[AutoFocus] {Owner} already drives the depth of field of {Volume}, {Camera} leaves it alone. Give it a volume of its own.", owner.name, volume.name, name); _dof = null; return; } @@ -159,7 +163,7 @@ private void OnDisable() private void EnableCustomPasses() { if (GraphicsSettings.currentRenderPipeline is HDRenderPipelineAsset asset && !asset.currentPlatformRenderPipelineSettings.supportCustomPass) { - Debug.LogWarning($"[AutoFocus] Custom passes are disabled in the HDRP asset \"{asset.name}\", auto focus won't work. Enable Rendering > Custom Pass in the asset.", this); + Logger.Warn("[AutoFocus] Custom passes are disabled in the HDRP asset {Asset}, auto focus won't work. Enable Rendering > Custom Pass in the asset.", asset.name); } var hdCamera = GetComponent(); if (hdCamera == null) { @@ -178,7 +182,7 @@ private void Update() } if (!_hasMeasurement) { if (!_warnedNoMeasurement && Time.unscaledTime - _enabledTime > 3f) { - Debug.LogWarning($"[AutoFocus] No depth measured on {name} yet, is the custom pass running? Check that Custom Pass is enabled in the HDRP asset.", this); + Logger.Warn("[AutoFocus] No depth measured on {Camera} yet, is the custom pass running? Check that Custom Pass is enabled in the HDRP asset.", name); _warnedNoMeasurement = true; } return; @@ -203,7 +207,7 @@ private void Probe(CustomPassContext ctx) if (ctx.hdCamera.msaaEnabled) { // the depth buffer is multisampled and can't be loaded as a plain texture. if (!_warnedMsaa) { - Debug.LogWarning("[AutoFocus] MSAA is enabled on the camera, auto focus is not supported.", this); + Logger.Warn("[AutoFocus] MSAA is enabled on camera {Camera}, auto focus is not supported.", name); _warnedMsaa = true; } return; diff --git a/Runtime/HdrpMaterialResolver.cs b/Runtime/HdrpMaterialResolver.cs index e7f53c5a..91cbae45 100644 --- a/Runtime/HdrpMaterialResolver.cs +++ b/Runtime/HdrpMaterialResolver.cs @@ -41,6 +41,7 @@ namespace VisualPinball.Engine.Unity.Hdrp public sealed class HdrpMaterialResolver : IVpeMaterialResolver, IVpeMaterialResolverDiagnostics { private static readonly Logger Logger = LogManager.GetCurrentClassLogger(); + private static readonly LogOncePerKey TemplateFallbackLog = new(); private const bool VerboseResolverLogs = false; private readonly Material _litOpaqueTemplate; private readonly Material _litTransparentTemplate; @@ -447,10 +448,9 @@ private static void ApplyTransmissionDiffusionProfile(Material material, string var setAssetVector = SetDiffusionProfileHashOnly(material, profile); var key = $"{profileName ?? ""}|{profile.name}"; if (VerboseResolverLogs && _loggedDiffusionAssignments.Add(key)) { - Debug.Log( - $"HdrpMaterialResolver: assigned diffusion profile '{profile.name}' to '{profileName}' " + - $"(v1 payload does not serialize diffusion profile binding; hash-only runtime assignment, " + - $"assetVector={(setAssetVector ? "set" : "missing")})."); + Logger.Debug( + "Assigned diffusion profile {DiffusionProfile} to {Profile} (v1 payload does not serialize the diffusion profile binding; hash-only runtime assignment, assetVector={AssetVector}).", + profile.name, profileName, setAssetVector ? "set" : "missing"); } } @@ -491,7 +491,10 @@ private static float GetDiffusionProfileHash(DiffusionProfileSettings profile) hashAsFloat = BitConverter.ToSingle(BitConverter.GetBytes(hash), 0); } } - } catch { + } catch (Exception e) { + // reads HDRP internals through reflection, so an HDRP update can break it; cached + // per profile, so this logs once per profile + Logger.Warn(e, "Could not read the hash of diffusion profile {DiffusionProfile}, materials using it get no subsurface scattering.", profile.name); hashAsFloat = 0f; } @@ -712,8 +715,11 @@ private static void SetShaderPassEnabledSafe(Material material, string passName, // if HDRP renames a pass across major versions. try { material.SetShaderPassEnabled(passName, enabled); - } catch { + } catch (Exception e) { // Intentionally ignore; pass name not available in this shader version. + if (Logger.IsDebugEnabled) { + Logger.Debug(e, "Shader pass {Pass} is not available on material {Material}.", passName, material ? material.name : ""); + } } } @@ -949,7 +955,7 @@ private static void LogFirstOfEach(string surfaceType, string refractionModel, s var prePass = material.GetShaderPassEnabled("TransparentDepthPrepass"); var postPass = material.GetShaderPassEnabled("TransparentDepthPostpass"); var kws = string.Join(",", material.shaderKeywords); - Debug.Log( + Logger.Debug( $"HdrpMaterialResolver first sample [{surfaceType}|{refractionModel}] '{profileName}' on template '{templateName}':\n" + $" baseColor={baseColor} queue={material.renderQueue} shader={material.shader.name}\n" + $" _SurfaceType={surfType} _MaterialID={matId} _RefractionModel={refMode} _Ior={ior} _Thickness={thickness} _TransmissionEnable={tx}\n" + @@ -969,14 +975,17 @@ private Material PickLitTemplate(VpeLitProfile lit, string profileName) if (translucent) { return translucent; } - Debug.LogWarning( - $"HdrpMaterialResolver: '{profileName}' requests transmission/refraction ({lit.RefractionModel}) " + - "but no translucent template is configured. Falling back to simple transparent."); + if (Logger.IsDebugEnabled && TemplateFallbackLog.ShouldLog("translucent|" + profileName)) { + Logger.Debug("Profile {Profile} requests transmission/refraction ({RefractionModel}), but no translucent template is configured. Falling back to simple transparent.", + profileName, lit.RefractionModel); + } } if (_litTransparentTemplate) { return _litTransparentTemplate; } - Debug.LogWarning($"HdrpMaterialResolver: '{profileName}' transparent but no transparent template; using opaque."); + if (Logger.IsDebugEnabled && TemplateFallbackLog.ShouldLog("transparent|" + profileName)) { + Logger.Debug("Profile {Profile} is transparent, but there is no transparent template. Using opaque.", profileName); + } return _litOpaqueTemplate; case VpeSurfaceTypes.AlphaTest: @@ -984,7 +993,9 @@ private Material PickLitTemplate(VpeLitProfile lit, string profileName) default: if (!_litOpaqueTemplate) { - Debug.LogWarning($"HdrpMaterialResolver: no lit-opaque template configured; profile '{profileName}' not applied."); + if (Logger.IsDebugEnabled && TemplateFallbackLog.ShouldLog("opaque|" + profileName)) { + Logger.Debug("No lit-opaque template configured, profile {Profile} not applied.", profileName); + } } return _litOpaqueTemplate; } @@ -1093,8 +1104,8 @@ private static void LogMissingImportedBaseColorMap(Material importedMaterial, st var props = importedMaterial ? importedMaterial.GetTexturePropertyNames() : System.Array.Empty(); var propDump = props != null && props.Length > 0 ? string.Join(", ", props) : ""; Logger.Warn( - $"HdrpMaterialResolver: failed to resolve imported _BaseColorMap for profile '{profileName}' " + - $"from source material '{importedName}' (shader='{shaderName}', mainTexture={(hasMainTex ? "yes" : "no")}, textureProps=[{propDump}])."); + "Failed to resolve the imported _BaseColorMap for profile {Profile} from source material {Material} (shader {Shader}, mainTexture={HasMainTexture}, texture properties [{Properties:l}]).", + profileName, importedName, shaderName, hasMainTex ? "yes" : "no", propDump); } private static void LogApronBaseAssignment(string profileName, Material importedMaterial, Texture assignedTexture, bool fromImported) @@ -1128,7 +1139,7 @@ private static void LogApronBaseAssignment(string profileName, Material imported sourceProps = matched.ToArray(); } var src = sourceProps.Length > 0 ? string.Join(", ", sourceProps) : ""; - Logger.Warn( + Logger.Debug( $"HdrpMaterialResolver apron base assignment: profile='{profileName}', imported='{importedName}', " + $"shader='{shaderName}', texture='{textureName}', fromImported={fromImported}, sourceProps=[{src}]"); } @@ -1143,7 +1154,7 @@ private static void LogApronImportedMaterial(string profileName, Material import return; } if (!imported) { - Logger.Warn($"HdrpMaterialResolver apron imported material is null for profile '{profileName}'."); + Logger.Debug("Apron imported material is null for profile {Profile}.", profileName); return; } @@ -1164,7 +1175,7 @@ private static void LogApronImportedMaterial(string profileName, Material import rows.Add($"{p}={(t ? t.name : "")}"); } var dump = rows.Count > 0 ? string.Join(", ", rows) : ""; - Logger.Warn( + Logger.Debug( $"HdrpMaterialResolver apron imported material: profile='{profileName}', imported='{imported.name}', " + $"shader='{shader}', mainTexture={(imported.mainTexture ? imported.mainTexture.name : "")}, textures=[{dump}]"); } @@ -1320,7 +1331,11 @@ private static Texture GetMainTextureSafe(Material material) try { return material.mainTexture; - } catch { + } catch (Exception e) { + // probing: the shader may have no main texture + if (Logger.IsDebugEnabled) { + Logger.Debug(e, "Material {Material} has no readable main texture.", material.name); + } return null; } } @@ -1402,7 +1417,7 @@ private static Material GetOrCreateNormalRepackMaterial() if (!shader) { if (!_loggedMissingNormalRepackShader) { _loggedMissingNormalRepackShader = true; - Logger.Warn($"HdrpMaterialResolver: failed to load Resources/{NormalRepackShaderResourcePath}. Falling back to CPU normal repack."); + Logger.Warn("Failed to load the shader Resources/{Path:l}. Falling back to CPU normal repack.", NormalRepackShaderResourcePath); } return null; } @@ -1450,7 +1465,7 @@ private static Texture2D RepackNormalMapForHdrpCpuFallback( try { repacked.Compress(highQuality: true); } catch (Exception e) { - Logger.Warn(e, $"HdrpMaterialResolver: failed compressing normal map '{repacked.name}'. Keeping uncompressed texture."); + Logger.Warn(e, "Failed compressing normal map {Texture}. Keeping the uncompressed texture.", repacked.name); } } repacked.Apply(true, true); diff --git a/Runtime/VpeMaterialResolverBootstrap.cs b/Runtime/VpeMaterialResolverBootstrap.cs index d30700e4..70a310c2 100644 --- a/Runtime/VpeMaterialResolverBootstrap.cs +++ b/Runtime/VpeMaterialResolverBootstrap.cs @@ -15,8 +15,10 @@ // along with this program. If not, see . using System.Collections.Generic; +using NLog; using UnityEngine; using VisualPinball.Unity; +using Logger = NLog.Logger; namespace VisualPinball.Engine.Unity.Hdrp { @@ -26,6 +28,8 @@ namespace VisualPinball.Engine.Unity.Hdrp // combination is what the build compiler keeps on HDRP/Lit. public static class VpeMaterialResolverBootstrap { + private static readonly Logger Logger = LogManager.GetCurrentClassLogger(); + private const string LitOpaqueTemplatePath = "Materials/VpeLitOpaqueTemplate"; private const string LitTransparentTemplatePath = "Materials/VpeLitTransparentTemplate"; private const string LitTranslucentThinTemplatePath = "Materials/VpeLitTranslucentThinTemplate"; @@ -58,58 +62,26 @@ private static void Register() RegisterMaterialOverride(materialOverrides, "RubberDirt White", RubberDirtWhiteOverridePath); RegisterMaterialOverride(materialOverrides, "Dot Matrix Display (SRP)", DotMatrixDisplayOverridePath); if (!litOpaque) { - Debug.LogError( - $"VpeMaterialResolverBootstrap: could not load '{LitOpaqueTemplatePath}' from Resources. " + - "Imported tables will fall back to the glTF-imported materials."); + // the templates ship with this package, so a missing one is a packaging bug + Logger.Error("Could not load the material template {Path:l} from Resources. Imported tables will fall back to the glTF-imported materials.", + LitOpaqueTemplatePath); return; } - if (!litTransparent) { - Debug.LogWarning( - $"VpeMaterialResolverBootstrap: could not load '{LitTransparentTemplatePath}' from Resources. " + - "Transparent surfaces will fall back to the opaque template."); - } - if (!litTranslucentThin) { - Debug.LogWarning( - $"VpeMaterialResolverBootstrap: could not load '{LitTranslucentThinTemplatePath}' from Resources. " + - "Thin translucent (ramp plastics) will fall back to plain transparent."); - } - if (!litTranslucentPlanar) { - Debug.LogWarning( - $"VpeMaterialResolverBootstrap: could not load '{LitTranslucentPlanarTemplatePath}' from Resources. " + - "Planar translucent (inserts, hard plastics) will fall back to plain transparent."); - } - if (!litTranslucentSphere) { - Debug.LogWarning( - $"VpeMaterialResolverBootstrap: could not load '{LitTranslucentSphereTemplatePath}' from Resources. " + - "Sphere translucent (posts, rounded plastics) will fall back to planar/thin."); - } - if (!fabricSilk) { - Debug.LogWarning( - $"VpeMaterialResolverBootstrap: could not load '{FabricSilkTemplatePath}' from Resources. " + - "vpe.fabric.silk profiles will fall back to glTF-imported materials."); - } - if (!decalTemplate) { - Debug.LogWarning( - $"VpeMaterialResolverBootstrap: could not load '{DecalTemplatePath}' from Resources. " + - "vpe.decal profiles will fall back to glTF-imported materials."); - } - if (!insertHybrid) { - Debug.LogWarning($"VpeMaterialResolverBootstrap: could not load '{InsertHybridTemplatePath}' from Resources. Insert bodies will use their glTF materials."); + WarnIfMissing(litTransparent, LitTransparentTemplatePath, "Transparent surfaces will fall back to the opaque template."); + WarnIfMissing(litTranslucentThin, LitTranslucentThinTemplatePath, "Thin translucent (ramp plastics) will fall back to plain transparent."); + WarnIfMissing(litTranslucentPlanar, LitTranslucentPlanarTemplatePath, "Planar translucent (inserts, hard plastics) will fall back to plain transparent."); + WarnIfMissing(litTranslucentSphere, LitTranslucentSphereTemplatePath, "Sphere translucent (posts, rounded plastics) will fall back to planar/thin."); + WarnIfMissing(fabricSilk, FabricSilkTemplatePath, "vpe.fabric.silk profiles will fall back to glTF-imported materials."); + WarnIfMissing(decalTemplate, DecalTemplatePath, "vpe.decal profiles will fall back to glTF-imported materials."); + WarnIfMissing(insertHybrid, InsertHybridTemplatePath, "Insert bodies will use their glTF materials."); + WarnIfMissing(insertCover, InsertCoverTemplatePath, "Insert covers will use their glTF materials."); + if (Logger.IsDebugEnabled) { + Logger.Debug( + "Material templates loaded: opaque={Opaque}, transparent={Transparent}, translucent-thin={Thin}, translucent-planar={Planar}, " + + "translucent-sphere={Sphere}, fabric-silk={Silk}, decal={Decal}, insert-hybrid={InsertHybrid}, insert-cover={InsertCover}, {Overrides} override(s).", + litOpaque.name, NameOf(litTransparent), NameOf(litTranslucentThin), NameOf(litTranslucentPlanar), NameOf(litTranslucentSphere), + NameOf(fabricSilk), NameOf(decalTemplate), NameOf(insertHybrid), NameOf(insertCover), materialOverrides.Count); } - if (!insertCover) { - Debug.LogWarning($"VpeMaterialResolverBootstrap: could not load '{InsertCoverTemplatePath}' from Resources. Insert covers will use their glTF materials."); - } - Debug.Log( - $"VpeMaterialResolverBootstrap: templates loaded. " + - $"opaque={litOpaque.name}, " + - $"transparent={(litTransparent ? litTransparent.name : "")}, " + - $"translucent-thin={(litTranslucentThin ? litTranslucentThin.name : "")}, " + - $"translucent-planar={(litTranslucentPlanar ? litTranslucentPlanar.name : "")}, " + - $"translucent-sphere={(litTranslucentSphere ? litTranslucentSphere.name : "")}, " + - $"fabric-silk={(fabricSilk ? fabricSilk.name : "")}, " + - $"decal={(decalTemplate ? decalTemplate.name : "")}, " + - $"insert-hybrid={(insertHybrid ? insertHybrid.name : "")}, " + - $"insert-cover={(insertCover ? insertCover.name : "")}."); VpeMaterialResolver.Register(new HdrpMaterialResolver( litOpaque, litTransparent, @@ -124,6 +96,15 @@ private static void Register() )); } + private static void WarnIfMissing(Material template, string path, string consequence) + { + if (!template) { + Logger.Warn("Could not load the material template {Path:l} from Resources. {Consequence:l}", path, consequence); + } + } + + private static string NameOf(Material material) => material ? material.name : ""; + private static void RegisterMaterialOverride(Dictionary overrides, string profileName, string resourcePath) { var material = UnityEngine.Resources.Load(resourcePath); From 6869f5b6cea43bff067e9c2120c53b9f27757af9 Mon Sep 17 00:00:00 2001 From: freezy Date: Thu, 15 Oct 2026 20:22:23 +0200 Subject: [PATCH 2/2] logging: Warn when a diffusion profile's hash can't be read for any reason. Besides an exception, HDRP renaming its internal fields or returning no hash now warns too, instead of silently losing subsurface scattering. --- Runtime/HdrpMaterialResolver.cs | 22 +++++++++++++++++----- 1 file changed, 17 insertions(+), 5 deletions(-) diff --git a/Runtime/HdrpMaterialResolver.cs b/Runtime/HdrpMaterialResolver.cs index 91cbae45..34622006 100644 --- a/Runtime/HdrpMaterialResolver.cs +++ b/Runtime/HdrpMaterialResolver.cs @@ -476,11 +476,18 @@ private static float GetDiffusionProfileHash(DiffusionProfileSettings profile) return cached; } + // Reads HDRP internals through reflection, so an HDRP update can break it, by throwing + // or by renaming what's read. Cached per profile, so either logs once per profile. float hashAsFloat = 0f; + string problem = null; try { - if (_diffusionProfileField != null && _diffusionHashField != null) { + if (_diffusionProfileField == null || _diffusionHashField == null) { + problem = "HDRP's internal profile or hash field wasn't found"; + } else { var profileStruct = _diffusionProfileField.GetValue(profile); - if (profileStruct != null) { + if (profileStruct == null) { + problem = "the profile has no settings"; + } else { var rawHash = _diffusionHashField.GetValue(profileStruct); uint hash = rawHash switch { uint u => u, @@ -488,15 +495,20 @@ private static float GetDiffusionProfileHash(DiffusionProfileSettings profile) long l => unchecked((uint)l), _ => 0u, }; - hashAsFloat = BitConverter.ToSingle(BitConverter.GetBytes(hash), 0); + if (hash == 0) { + problem = "its hash is 0 or of an unknown type"; + } else { + hashAsFloat = BitConverter.ToSingle(BitConverter.GetBytes(hash), 0); + } } } } catch (Exception e) { - // reads HDRP internals through reflection, so an HDRP update can break it; cached - // per profile, so this logs once per profile Logger.Warn(e, "Could not read the hash of diffusion profile {DiffusionProfile}, materials using it get no subsurface scattering.", profile.name); hashAsFloat = 0f; } + if (problem != null) { + Logger.Warn("Could not read the hash of diffusion profile {DiffusionProfile} ({Reason:l}), materials using it get no subsurface scattering.", profile.name, problem); + } _diffusionProfileHashByInstance[id] = hashAsFloat; return hashAsFloat;