fix(opctreemanager): make the log a technical record

NtoLib/OpcTreeManager/Entities/LinkEntry.cs

@@ -3,7 +3,7 @@
 namespace NtoLib.OpcTreeManager.Entities;
 
 /// <summary>
-/// Represents one directed link: <see cref="LocalPinPath"/> ↔ <see cref="ExternalPinPath"/>.
+/// Represents one directed link from <see cref="LocalPinPath"/> to <see cref="ExternalPinPath"/>.
 /// <see cref="LocalPinPath"/> is the OPC-side pin; <see cref="ExternalPinPath"/> is the
 /// consumer/producer pin outside the OPC subtree.
 /// </summary>

NtoLib/OpcTreeManager/Facade/OpcTreeManagerService.cs

@@ -1,5 +1,6 @@
 using System;
 using System.Collections.Generic;
+using System.Globalization;
 using System.IO;
 using System.Linq;
 
@@ -15,6 +16,7 @@
 
 using Serilog;
 using Serilog.Core;
+using Serilog.Events;
 
 namespace NtoLib.OpcTreeManager.Facade;
 
@@ -33,7 +35,7 @@ public OpcTreeManagerService(IProjectHlp project, ILogger logger)
 			throw new ArgumentNullException(nameof(logger));
 		}
 
-		_logger = logger.ForContext<OpcTreeManagerService>();
+		_logger = logger;
 		var disconnector = new ProjectSubtreeDisconnector(project, logger);
 		_planExecutor = new PlanExecutor(project, disconnector, logger);
 	}
@@ -59,10 +61,6 @@ public Result ScanAndValidate(
 
 		var config = configResult.Value;
 
-		_logger.Information(
-			"Tree scan begin; OpcFbPath={OpcFbPath} GroupName={GroupName} TargetProject={TargetProject}",
-			opcFbPath, groupName, targetProject);
-
 		var groupResult = ResolveGroup(opcFbPath, groupName);
 
 		if (groupResult.IsFailed)
@@ -71,17 +69,17 @@ public Result ScanAndValidate(
 		}
 
 		_logger.Information(
-			"Group '{GroupName}' resolved at '{GroupRelativePath}'",
+			"Group '{GroupName}' resolved at '{GroupRelativePath}' for Execute",
 			groupName, groupResult.Value.RelativePath);
 
 		var snapshotResult = TreeSnapshotLoader.Load(treeJsonPath);
 
 		if (snapshotResult.IsFailed)
 		{
-			var reason = File.Exists(treeJsonPath)
-				? $"Failed to load snapshot from '{treeJsonPath}': {string.Join("; ", snapshotResult.Errors)}"
-				: $"Snapshot file not found at '{treeJsonPath}'.";
-			return LogAndFail(new[] { new Error(reason) });
+			var notLoaded = new Error($"Snapshot of group '{groupName}' was not loaded from '{treeJsonPath}'")
+				.CausedBy(snapshotResult.Errors);
+
+			return LogAndFail(new[] { notLoaded });
 		}
 
 		var snapshot = snapshotResult.Value;
@@ -91,10 +89,12 @@ public Result ScanAndValidate(
 		if (droppedLinks > 0)
 		{
 			_logger.Warning(
-				"Snapshot load dropped {DroppedLinkCount} invalid link(s) with blank pin paths from '{Path}'",
-				droppedLinks, treeJsonPath);
+				"Snapshot '{TreeJsonPath}': {DroppedLinkCount} links with a blank pin path ignored",
+				treeJsonPath, droppedLinks);
 		}
 
+		LogSnapshotLoaded(snapshot, treeJsonPath);
+
 		var currentTopLevelNames = groupResult.Value.Group.Items.Select(i => i.Name).ToList();
 		var planResult = PlanBuilder.Build(opcFbPath, groupName, targetProject, config, snapshot, currentTopLevelNames, _logger);
 
@@ -125,7 +125,7 @@ public void Cancel()
 	{
 		if (PendingPlan != null)
 		{
-			_logger.Information("Operation cancelled by user");
+			_logger.Information("Pending rebuild of group '{GroupName}' cancelled", PendingPlan.GroupName);
 			PendingPlan = null;
 		}
 	}
@@ -142,7 +142,7 @@ private Result<Dictionary<string, NodeSnapshot>> BuildSnapshot(string opcFbPath,
 		var (groupItem, groupRelativePath) = groupResult.Value;
 
 		_logger.Information(
-			"Group '{GroupName}' resolved at '{GroupRelativePath}'",
+			"Group '{GroupName}' resolved at '{GroupRelativePath}' for ExecuteSnapshot",
 			groupName, groupRelativePath);
 
 		var items = groupItem.Items.AsReadOnly();
@@ -153,6 +153,14 @@ private Result<Dictionary<string, NodeSnapshot>> BuildSnapshot(string opcFbPath,
 			var fullPath = JoinPath(opcFbPath, groupRelativePath, item.Name);
 			var node = _project.SafeItem<ITreeItemHlp>(fullPath);
 
+			if (node == null)
+			{
+				_logger.Error(
+					"Node '{NodeName}' captured with no links: '{NodePath}' did not resolve in the "
+					+ "project; check OpcFbPath",
+					item.Name, fullPath);
+			}
+
 			var links = node != null
 				? LinkCollector.CollectAllLinks(node, _logger)
 				: Array.Empty<LinkEntry>();
@@ -166,10 +174,6 @@ private Result<Dictionary<string, NodeSnapshot>> BuildSnapshot(string opcFbPath,
 			snapshot[item.Name] = nodeSnapshot;
 		}
 
-		_logger.Information(
-			"Snapshot built; {NodeCount} nodes scanned from group '{GroupName}'",
-			snapshot.Count, groupName);
-
 		return Result.Ok(snapshot);
 	}
 
@@ -181,22 +185,110 @@ public Result CaptureAndWriteSnapshot(string opcFbPath, string groupName, string
 			return Result.Fail(snapshotResult.Errors);
 		}
 
-		var writeResult = TreeSnapshotWriter.Write(snapshotResult.Value, treeJsonPath);
+		var snapshot = snapshotResult.Value;
+		var writeResult = TreeSnapshotWriter.Write(snapshot, treeJsonPath);
+
 		if (writeResult.IsFailed)
 		{
-			var reason = string.Join("; ", writeResult.Errors);
-			return LogAndFail(new[] { new Error($"Snapshot of group '{groupName}' was not written: {reason}") });
+			var notWritten = new Error($"Snapshot of group '{groupName}' was not written to '{treeJsonPath}'")
+				.CausedBy(writeResult.Errors);
+
+			return LogAndFail(new[] { notWritten });
 		}
 
-		_logger.Information("Snapshot written to '{Path}'", treeJsonPath);
+		LogSnapshotWritten(groupName, treeJsonPath, snapshot, _logger);
+
 		return Result.Ok();
 	}
 
+	/// <summary>Terminal record of a capture: the count of nodes written with no links sets the level,
+	/// and deliberately not the <c>Failed</c> pin (Docs/opc-tree-manager.md section 8.4).</summary>
+	internal static void LogSnapshotWritten(
+		string groupName,
+		string treeJsonPath,
+		IReadOnlyDictionary<string, NodeSnapshot> snapshot,
+		ILogger logger)
+	{
+		var nodesWithoutLinks = snapshot.Values.Count(node => node.Links.Count == 0);
+
+		var nextRebuild = nodesWithoutLinks > 0
+			? "; the next rebuild constructs those nodes unwired"
+			: string.Empty;
+
+		logger.Write(
+			nodesWithoutLinks > 0 ? LogEventLevel.Error : LogEventLevel.Information,
+			"Snapshot of group '{GroupName}' written to '{TreeJsonPath}': {NodeCount} nodes, "
+			+ "{LinkCount} links, {NodesWithoutLinks} without links" + nextRebuild,
+			groupName,
+			treeJsonPath,
+			snapshot.Count,
+			CountLinks(snapshot),
+			nodesWithoutLinks);
+	}
+
 	private Result LogAndFail(IEnumerable<IError> errors)
 	{
-		var message = string.Join("; ", errors);
-		_logger.Error("{ErrorMessage}", message);
-		return Result.Fail(message);
+		var errorList = errors.ToList();
+		var flattened = Flatten(errorList).ToList();
+		var message = string.Join("; ", flattened.Select(e => e.Message));
+		var exception = flattened.OfType<ExceptionalError>().FirstOrDefault()?.Exception;
+
+		if (exception == null)
+		{
+			_logger.Error("{ErrorMessage}", message);
+		}
+		else
+		{
+			_logger.Error(exception, "{ErrorMessage}", message);
+		}
+
+		return Result.Fail(errorList);
+	}
+
+	/// <summary>Walks an error and its CausedBy chain so every cause reaches the log line.</summary>
+	internal static IEnumerable<IError> Flatten(IEnumerable<IError> errors)
+	{
+		foreach (var error in errors)
+		{
+			yield return error;
+
+			foreach (var nested in Flatten(error.Reasons.OfType<IError>()))
+			{
+				yield return nested;
+			}
+		}
+	}
+
+	private void LogSnapshotLoaded(Dictionary<string, NodeSnapshot> snapshot, string treeJsonPath)
+	{
+		_logger.Information(
+			"Snapshot '{TreeJsonPath}' loaded: {NodeCount} nodes, {LinkCount} links, "
+			+ "file written {SnapshotWrittenAt}",
+			treeJsonPath, snapshot.Count, CountLinks(snapshot), DescribeWriteTime(treeJsonPath));
+	}
+
+	/// <summary>Never throws: <c>ScanAndValidate</c> runs out of <c>UpdateData</c> unguarded, so a date
+	/// the file system refuses and the 1601 sentinel it returns instead both read as unknown.</summary>
+	private static string DescribeWriteTime(string path)
+	{
+		try
+		{
+			var writtenAt = File.GetLastWriteTime(path);
+
+			return writtenAt.Year <= 1601
+				? "unknown"
+				: writtenAt.ToString("O", CultureInfo.InvariantCulture);
+		}
+		catch (Exception ex) when (ex is IOException or UnauthorizedAccessException or ArgumentException
+			or NotSupportedException)
+		{
+			return "unknown";
+		}
+	}
+
+	private static int CountLinks(IReadOnlyDictionary<string, NodeSnapshot> snapshot)
+	{
+		return snapshot.Values.Sum(node => node.Links.Count);
 	}
 
 	private Result<(OpcUaScadaItem Group, string RelativePath)> ResolveGroup(

NtoLib/OpcTreeManager/Facade/PlanBuilder.cs

@@ -45,7 +45,9 @@ internal static class PlanBuilder
 	{
 		if (!config.Projects.TryGetValue(targetProject, out var nodeNames) || nodeNames == null || nodeNames.Count == 0)
 		{
-			return Result.Fail($"Project '{targetProject}' not found in config or has no nodes.");
+			return Result.Fail(
+				$"Project '{targetProject}' not found in config or has no nodes; "
+				+ $"projects present: [{string.Join(", ", config.Projects.Keys)}].");
 		}
 
 		var desiredTree = nodeNames
@@ -62,7 +64,7 @@ internal static class PlanBuilder
 		if (CurrentContentsAlreadyMatch(desiredTree, currentTopLevelNames))
 		{
 			logger?.Information(
-				"No operations required for group '{GroupName}' — current contents already match target project '{TargetProject}'.",
+				"Group '{GroupName}' top-level node names already match project '{TargetProject}'; no rebuild",
 				groupName, targetProject);
 
 			return Result.Ok<RebuildPlan?>(null);
@@ -75,17 +77,17 @@ internal static class PlanBuilder
 			return resolvable;
 		}
 
-		if (currentTopLevelNames.Count == 0)
-		{
-			var restorable = CheckEmptyGroupRestoresSomething(desiredTree, snapshot, targetProject, groupName, logger);
+		var missingFromSnapshot = FindNamesMissingFromSnapshot(desiredTree, snapshot);
 
-			if (restorable.IsFailed)
-			{
-				return restorable;
-			}
+		if (currentTopLevelNames.Count == 0 && missingFromSnapshot.Count == desiredTree.Count)
+		{
+			return Result.Fail(
+				$"Group '{groupName}' is empty and no desired node of project '{targetProject}' is "
+				+ "present in the snapshot; refusing to build a plan that would restore nothing. "
+				+ "Re-capture with ExecuteSnapshot or drop the nodes from config.yaml.");
 		}
 
-		logger?.Information("Top-level desired nodes: {Count}", desiredTree.Count);
+		LogPlan(groupName, targetProject, desiredTree, snapshot, currentTopLevelNames, missingFromSnapshot, logger);
 
 		return Result.Ok<RebuildPlan?>(new RebuildPlan(opcFbPath, groupName, desiredTree, snapshot));
 	}
@@ -121,49 +123,68 @@ private static Result CheckDesiredTreeResolves(
 			? Result.Ok()
 			: Result.Fail(
 				$"Desired node '{unresolvable}' for project '{targetProject}' is not present in the "
-				+ "snapshot; refusing to build a plan that would abort mid-rebuild.");
+				+ "snapshot; refusing to build a plan that would abort mid-rebuild. Re-capture with "
+				+ "ExecuteSnapshot or drop the node from config.yaml.");
 	}
 
-	/// <summary>Fails when an empty group has no desired node the snapshot can restore.</summary>
-	private static Result CheckEmptyGroupRestoresSomething(
+	/// <summary>
+	/// An entry whose ScadaItem is null resolves to a null DTO at execute time, so the key alone does
+	/// not make the node restorable.
+	/// </summary>
+	private static List<string> FindNamesMissingFromSnapshot(
 		IReadOnlyList<NodeSpec> desiredTree,
-		IReadOnlyDictionary<string, NodeSnapshot> snapshot,
-		string targetProject,
-		string groupName,
-		ILogger? logger)
+		IReadOnlyDictionary<string, NodeSnapshot> snapshot)
 	{
-		// An entry whose ScadaItem is null resolves to a null DTO at execute time, so the key
-		// alone does not make the node restorable.
-		var missingFromSnapshot = desiredTree
+		return desiredTree
 			.Where(s => !snapshot.TryGetValue(s.Name, out var entry) || entry.ScadaItem == null)
 			.Select(s => s.Name)
 			.ToList();
+	}
 
-		if (missingFromSnapshot.Count == desiredTree.Count)
+	private static void LogPlan(
+		string groupName,
+		string targetProject,
+		IReadOnlyList<NodeSpec> desiredTree,
+		IReadOnlyDictionary<string, NodeSnapshot> snapshot,
+		IReadOnlyList<string> currentTopLevelNames,
+		IReadOnlyList<string> missingFromSnapshot,
+		ILogger? logger)
+	{
+		if (logger == null)
 		{
-			return Result.Fail(
-				$"Group '{groupName}' is empty and no desired node of project '{targetProject}' is "
-				+ "present in the snapshot; refusing to build a plan that would restore nothing.");
+			return;
 		}
 
-		foreach (var missingName in missingFromSnapshot)
+		var currentNames = new HashSet<string>(currentTopLevelNames, StringComparer.Ordinal);
+		var desiredNames = new HashSet<string>(desiredTree.Select(s => s.Name), StringComparer.Ordinal);
+		var unrestorableNames = new HashSet<string>(missingFromSnapshot, StringComparer.Ordinal);
+
+		var removeNodes = currentTopLevelNames.Where(n => !desiredNames.Contains(n)).ToList();
+		var preserveNodes = desiredTree.Select(s => s.Name).Where(currentNames.Contains).ToList();
+		var absentNames = desiredTree.Select(s => s.Name).Where(n => !currentNames.Contains(n)).ToList();
+		var constructNodes = absentNames.Where(n => !unrestorableNames.Contains(n)).ToList();
+
+		foreach (var missingName in absentNames.Where(unrestorableNames.Contains))
 		{
-			logger?.Error(
-				"Desired node '{NodeName}' of project '{TargetProject}' is absent from the snapshot "
-				+ "and group '{GroupName}' is empty, so the node cannot be restored.",
+			logger.Error(
+				"Node '{NodeName}' of project '{TargetProject}' will not be restored: not in group "
+				+ "'{GroupName}', not in the snapshot; re-capture with ExecuteSnapshot or drop it "
+				+ "from config.yaml",
 				missingName, targetProject, groupName);
 		}
 
-		return Result.Ok();
+		var linkCount = constructNodes.Sum(n => snapshot[n].Links.Count);
+
+		logger.Information(
+			"Plan for group '{GroupName}', project '{TargetProject}': remove {RemoveNodes}; "
+			+ "construct {ConstructNodes} ({LinkCount} links under them in the snapshot); "
+			+ "preserve {PreserveNodes}",
+			groupName, targetProject, removeNodes, constructNodes, linkCount, preserveNodes);
 	}
 
-	/// <summary>
-	/// Walks the desired spec against the snapshot DTO tree and returns the path of the first node
-	/// that does not resolve, or <c>null</c> when the whole spec resolves. Mirrors the runtime
-	/// resolver in <see cref="TreeOperations.PlanExecutor"/>: the top level resolves through
-	/// <c>snapshot.TryGetValue(name).ScadaItem</c>, nested nodes by descending the parent DTO's
-	/// <c>Items</c> and matching children by ordinal <c>Name</c>.
-	/// </summary>
+	/// <summary>Mirrors the runtime resolver in <see cref="TreeOperations.PlanExecutor"/>: the top
+	/// level through <c>snapshot.TryGetValue(name).ScadaItem</c>, nested nodes by ordinal <c>Name</c>
+	/// down <c>Items</c>.</summary>
 	private static string? FindUnresolvableNode(
 		IReadOnlyList<NodeSpec> desired,
 		IReadOnlyDictionary<string, NodeSnapshot> snapshot,
@@ -174,7 +195,7 @@ private static Result CheckEmptyGroupRestoresSomething(
 			var dto = snapshot.TryGetValue(spec.Name, out var s) ? s.ScadaItem : null;
 
 			// A top-level node absent from the snapshot resolves to a null DTO at runtime and is
-			// skipped-with-warning, never pruned — no throw. Only descend where the DTO resolved.
+			// skipped, never pruned - no throw; the plan line records it.
 			if (dto == null || spec.Children == null)
 			{
 				continue;