Skip to content

HDRP runtime logging on NLog #32

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
freezy merged 2 commits into from
Oct 15, 2026
Merged

HDRP runtime logging on NLog #32

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
8f91122
logging: HDRP runtime on NLog.
freezy Oct 15, 2026
6869f5b
logging: Warn when a diffusion profile's hash can't be read for any r…
freezy Oct 15, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
16 changes: 10 additions & 6 deletions Runtime/AutoFocusComponent.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -14,10 +14,12 @@
// You should have received a copy of the GNU General Public License
// along with this program. If not, see <https://www.gnu.org/licenses/>.

using NLog;
using Unity.Mathematics;
using UnityEngine;
using UnityEngine.Rendering;
using UnityEngine.Rendering.HighDefinition;
using Logger = NLog.Logger;

namespace VisualPinball.Engine.Unity.Hdrp
{
Expand All @@ -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;

Expand Down Expand Up @@ -92,15 +96,15 @@ private void OnEnable()
{
_camera = GetComponent<Camera>();
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;
}

// only a volume on one of the camera's volume layers changes what it renders
var volumeLayers = _camera.TryGetComponent<HDAdditionalCameraData>(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;
}

Expand All @@ -110,7 +114,7 @@ private void OnEnable()
_dof = profile.Add<DepthOfField>();
}
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;
}
Expand Down Expand Up @@ -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<HDAdditionalCameraData>();
if (hdCamera == null) {
Expand All @@ -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;
Expand All @@ -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;
Expand Down
73 changes: 50 additions & 23 deletions Runtime/HdrpMaterialResolver.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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<string> TemplateFallbackLog = new();
private const bool VerboseResolverLogs = false;
private readonly Material _litOpaqueTemplate;
private readonly Material _litTransparentTemplate;
Expand Down Expand Up @@ -447,10 +448,9 @@ private static void ApplyTransmissionDiffusionProfile(Material material, string
var setAssetVector = SetDiffusionProfileHashOnly(material, profile);
var key = $"{profileName ?? "<unnamed>"}|{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");
}
}

Expand All @@ -476,24 +476,39 @@ 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,
int i => unchecked((uint)i),
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 {
} catch (Exception e) {
Logger.Warn(e, "Could not read the hash of diffusion profile {DiffusionProfile}, materials using it get no subsurface scattering.", profile.name);
hashAsFloat = 0f;
Comment thread
greptile-apps[bot] marked this conversation as resolved.
}
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;
Expand Down Expand Up @@ -712,8 +727,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 : "<null>");
}
}
}

Expand Down Expand Up @@ -949,7 +967,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" +
Expand All @@ -969,22 +987,27 @@ 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:
return _litOpaqueTemplate;

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;
}
Expand Down Expand Up @@ -1093,8 +1116,8 @@ private static void LogMissingImportedBaseColorMap(Material importedMaterial, st
var props = importedMaterial ? importedMaterial.GetTexturePropertyNames() : System.Array.Empty<string>();
var propDump = props != null && props.Length > 0 ? string.Join(", ", props) : "<none>";
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)
Expand Down Expand Up @@ -1128,7 +1151,7 @@ private static void LogApronBaseAssignment(string profileName, Material imported
sourceProps = matched.ToArray();
}
var src = sourceProps.Length > 0 ? string.Join(", ", sourceProps) : "<unknown>";
Logger.Warn(
Logger.Debug(
$"HdrpMaterialResolver apron base assignment: profile='{profileName}', imported='{importedName}', " +
$"shader='{shaderName}', texture='{textureName}', fromImported={fromImported}, sourceProps=[{src}]");
}
Expand All @@ -1143,7 +1166,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;
}

Expand All @@ -1164,7 +1187,7 @@ private static void LogApronImportedMaterial(string profileName, Material import
rows.Add($"{p}={(t ? t.name : "<null>")}");
}
var dump = rows.Count > 0 ? string.Join(", ", rows) : "<none>";
Logger.Warn(
Logger.Debug(
$"HdrpMaterialResolver apron imported material: profile='{profileName}', imported='{imported.name}', " +
$"shader='{shader}', mainTexture={(imported.mainTexture ? imported.mainTexture.name : "<null>")}, textures=[{dump}]");
}
Expand Down Expand Up @@ -1320,7 +1343,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;
}
}
Expand Down Expand Up @@ -1402,7 +1429,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;
}
Expand Down Expand Up @@ -1450,7 +1477,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);
Expand Down
79 changes: 30 additions & 49 deletions Runtime/VpeMaterialResolverBootstrap.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -15,8 +15,10 @@
// along with this program. If not, see <https://www.gnu.org/licenses/>.

using System.Collections.Generic;
using NLog;
using UnityEngine;
using VisualPinball.Unity;
using Logger = NLog.Logger;

namespace VisualPinball.Engine.Unity.Hdrp
{
Expand All @@ -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";
Expand Down Expand Up @@ -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 : "<missing>")}, " +
$"translucent-thin={(litTranslucentThin ? litTranslucentThin.name : "<missing>")}, " +
$"translucent-planar={(litTranslucentPlanar ? litTranslucentPlanar.name : "<missing>")}, " +
$"translucent-sphere={(litTranslucentSphere ? litTranslucentSphere.name : "<missing>")}, " +
$"fabric-silk={(fabricSilk ? fabricSilk.name : "<missing>")}, " +
$"decal={(decalTemplate ? decalTemplate.name : "<missing>")}, " +
$"insert-hybrid={(insertHybrid ? insertHybrid.name : "<missing>")}, " +
$"insert-cover={(insertCover ? insertCover.name : "<missing>")}.");
VpeMaterialResolver.Register(new HdrpMaterialResolver(
litOpaque,
litTransparent,
Expand All @@ -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 : "<missing>";

private static void RegisterMaterialOverride(Dictionary<string, Material> overrides, string profileName, string resourcePath)
{
var material = UnityEngine.Resources.Load<Material>(resourcePath);
Expand Down