diff --git a/Docs/opc-tree-manager.md b/Docs/opc-tree-manager.md index 75e02f4..bba4b88 100644 --- a/Docs/opc-tree-manager.md +++ b/Docs/opc-tree-manager.md @@ -132,7 +132,9 @@ projects: Если узел отсутствует: * он не будет создан при выполнении -* в логе появится запись о пропуске +* узел верхнего уровня называется в логе на уровне ошибки при построении плана, а при выполнении + повторяется на уровне Debug +* вложенный узел план не проверяет, поэтому его называет только запись уровня ошибки при выполнении При добавлении новых узлов: @@ -147,8 +149,9 @@ projects: потомков, сохраняется без изменений: восстановление не спускается внутрь и не восстанавливает его связи. Пустая или частично заполненная папка остаётся в прежнем состоянии. Восстанавливается только узел, отсутствующий целиком. Последовательность -«создать папки вручную, затем выполнить `Execute`» результата не даёт; в журнале при этом -появляется запись вида `preserved=N newlyConstructed=0` и нулевое число связей. +«создать папки вручную, затем выполнить `Execute`» результата не даёт: если имена верхнего +уровня после этого совпали, план не строится вовсе и в журнале появляется запись `Group +'<группа>' top-level node names already match project '<проект>'; no rebuild`. **Снимок привязан к таблице namespace сервера, с которого снят.** Сохранённые `NodeId` содержат индекс namespace, являющийся позицией в таблице сервера. При добавлении или @@ -195,7 +198,7 @@ namespace, на которой он будет применён. * изменения применяются рекурсивно * существующие узлы не переподключаются -* замена состава происходит атомарно на каждом уровне дерева отдельно; отката всего плана при сбое в середине нет — см. 6.2 +* замена состава происходит атомарно на каждом уровне дерева отдельно; отката всего плана при сбое в середине нет — см. раздел 6 --- @@ -252,7 +255,23 @@ namespace, на которой он будет применён. * ошибка фиксируется в логе * выполнение продолжается -Откат изменений не предусмотрен. +Откат изменений не предусмотрен. Перестройка при этом доходит до конца и возвращает успех, хотя +узлы остались без части связей. Что с этим делать, говорит итоговая запись: она заканчивается +состоянием дерева и действием оператора (см. 8.2). + +### Исключение после начала перестройки + +Отдельный случай: отказ или исключение, пойманные уже после первой записи в дерево. Часть узлов +к этому моменту отключена и заменена, часть нет, и привести дерево в согласованное состояние +нечем. В логе это одна запись: + +``` +Rebuild of group '<группа>' failed after the reshape began; the tree is partially changed, +close the project without saving: <причина> +``` + +Действие по ней одно: закрыть проект без сохранения. Сохранение зафиксирует наполовину +перестроенное дерево. --- @@ -277,15 +296,202 @@ namespace, на которой он будет применён. * **Файл:** задаётся параметром `LogFilePath` * **Ротация:** по размеру, 5 МБ на файл, удержание 5 файлов * **Библиотека:** Serilog -* **Содержимое:** - - * загрузка конфигурации - * путь найденной группы относительно `ScadaRootNode` (Information) - * список изменений - * операции со связями (Debug) - * итоговая статистика (Information) - * при неудачном поиске группы — состав `ScadaRootNode` с именем, `IsNode` и числом - потомков по каждому узлу, до трёх уровней и до 20 потомков у каждого узла (Error). Узлы, - скрытые этими двумя ограничениями, отмечены строкой по месту обрыва. Весь дамп ограничен - 200 строками, и если этот предел сработал, в конце добавляется строка с числом узлов, - отброшенных именно им \ No newline at end of file +* **Строка:** метка времени, уровень, сообщение. Имени класса в строке нет. Если запись несёт + объект исключения, его текст и стек идут следующими строками +* **Кодировка:** шаблоны сообщений целиком ASCII, связь обозначена как `<->`. Значения приходят + из проекта и ASCII не ограничены: путь `Система.АРМ.OPC UA Siemens` попадает в файл как есть + +Недоступный для записи `LogFilePath` отключает логирование и больше ничего. `WriteTo.File` +перехватывает отказ при создании приёмника и подставляет пустой, поэтому FB работает дальше, +а `Failed` остаётся низким: ни одна операция не сбоила. Файл при этом не создаётся. + +### 8.1. Уровни + +* **Error** — доменный объект (узел, связь, группа, файл), который не окажется в + запланированном состоянии, или операция, которая не выполнилась. Строка называет + идентификаторы этого объекта. Перестройка целиком — такой же доменный объект: итоговая + запись пишется на уровне Error, когда хоть один её счётчик отличен от нуля, и дублирует по + уровню ошибки отдельных объектов намеренно. Отложенный этап не может поднять `Failed` + (см. 8.4), поэтому вердикт о перестройке есть только в этой строке +* **Warning** — факт, который может оставить объект в незапланированном состоянии, и код + различить этого не может +* **Information** — граница операции: вход в режим исполнения, найденная группа, загрузка и + запись снимка, план, постановка перестройки в очередь, перестроенный контейнер, завершение + перестройки без сбоев. Плюс по строке на каждый узел, состав которого изменился +* **Debug** — по строке на связь плюс сохранённые узлы + +### 8.2. Содержимое + +Режим исполнения: + +* вход в режим исполнения со значениями `OpcFbPath`, `GroupName`, `TargetProject`, + `TreeJsonPath`, `ConfigYamlPath` (Information). Пишется первой, до остальной инициализации, + чтобы следующая строка имела контекст +* срыв инициализации: `Initialization failed` (Error, с объектом исключения). Отключает ФБ до + следующего входа в режим исполнения и поднимает `Failed` +* ошибки загрузки конфигурации и снапшота (Error). Успешная загрузка `config.yaml` не + пишется. Если целевой проект не найден, сообщение перечисляет имена проектов, которые в + `config.yaml` есть +* путь найденной группы относительно `ScadaRootNode`: `Group '<группа>' resolved at '<путь>' for + Execute` (Information). `ExecuteSnapshot` пишет ту же строку, но заканчивает её на `for + ExecuteSnapshot` +* `Snapshot '<файл>' loaded: N nodes, M links, file written <дата>` (Information). Дату даёт + `File.GetLastWriteTime`; если файловая система её не отдала, вместо даты стоит `unknown` +* связи снимка с пустым путём пина: `Snapshot '<файл>': N links with a blank pin path + ignored` (Warning) +* план до применения: `Plan for group '<группа>', project '<проект>': remove <имена>; + construct <имена> (N links under them in the snapshot); preserve <имена>` (Information). Это и + есть список изменений, по которому решают, применять план или нет. `N` — сколько связей снимок + держит под этими узлами целиком; если `config.yaml` ограничивает состав потомков, восстановлено + будет меньше, и с итогами по узлам это число напрямую не сходится +* узел целевого проекта, которого нет ни в группе, ни в снимке: `Node '<имя>' of project + '<проект>' will not be restored: not in group '<группа>', not in the snapshot; re-capture with + ExecuteSnapshot or drop it from config.yaml` (Error). Пишется для непустой группы и для пустой, + в которой нашлась хотя бы часть узлов; если в пустой группе не нашлось ни одного, план + отклоняется целиком и пишется только отказ +* совпадение состава: `Group '<группа>' top-level node names already match project + '<проект>'; no rebuild` (Information). Сверяются только имена узлов верхнего уровня +* отмена по входу `Cancel`: `Pending rebuild of group '<группа>' cancelled` (Information) + +Отложенный этап: + +* постановка в очередь: `Rebuild of group '<группа>' queued; waits for the host to leave + runtime, timeout 20s` (Information). Единственная запись о том, что FB увидел `ToDesign` с + готовым планом +* отказ до первой мутации: `Rebuild of group '<группа>' not started, the tree is unchanged: + <причина>` (Error). Эту же строку пишет исключение, брошенное до перестройки: поиск + протокола и группы идёт до первой мутации, и совет закрыть проект там был бы вреден +* отказ или исключение после начала перестройки: `Rebuild of group '<группа>' failed after the + reshape began; the tree is partially changed, close the project without saving: <причина>` + (Error, с объектом исключения, если он был). Границу между двумя строками задаёт сам + исполнитель: флаг поднимается на первой записи в дерево — первом `Disconnect` или первой + замене состава контейнера, — а не на чтениях, которые ей предшествуют. Перестройка, которая + флаг не подняла, и связей не выдавала: команды на подключение даёт только построенный узел, а + он появляется только вместе с заменой состава +* срыв таймера: `Rebuild of group '<группа>' abandoned` (Error, с объектом исключения) +* хост не вышел из режима исполнения: `Rebuild of group '<группа>' not started: the host + stayed in runtime 20s after ToDesign; the plan is discarded` (Error) + +Что изменилось, по узлам: + +* удаляемый узел: `Removed '<узел>': N disconnects issued, M threw` (Information) +* удаляемый узел, которого в проекте нет: `Remove '<узел>': node not found in the project, + links not disconnected` (Error). Такой узел считается пропущенным узлом, а не сбойной + связью, и строки `Removed ...` для него нет: отключать было нечего +* построенный узел: `Constructed '<узел>': N links to connect` (Information) +* построенный узел, которому нечего подключать: `Constructed '<узел>': no links to connect; the + snapshot holds none under the kept nodes, so the node comes back unwired` (Error). Узел + восстановлен, но остался без связей: ни одной связи снимок под ним не держит либо все они + отсеклись ограничением состава потомков из `config.yaml`. Счётчиками связей такой узел не + виден — до сборки команд ни одна связь не дошла, поэтому у него свой счётчик `noLinks` +* сохранённый узел: `Preserved '<узел>'` (Debug) +* узел, которого нет ни в контейнере, ни в снимке: `Not restored '<узел>': not in the + container, not in the snapshot`. Для узла верхнего уровня — Debug, потому что тот же факт на + уровне ошибки уже записан при построении плана. Для вложенного — Error: план сверяет со снимком + только верхний уровень, поэтому другой записи о нём нет +* контейнер: `Reshaped '<контейнер>': removed=N constructed=N preserved=N skipped=N` + (Information). Счётчики относятся к одному уровню дерева, не накапливаются по рекурсии. + Контейнер, состав которого не менялся, такой строки не пишет + +Связи: + +* итог по узлу: `Node '<узел>': N links, K resolved, U unresolved` (Error). Пишется только + тогда, когда хоть одна связь не разрешилась в вызов; обе половины счёта относятся к моменту + сборки команд, до первого вызова вендора, поэтому `K` не обязано совпадать с + `connects issued=` в итоговой записи. Узел, построенный без связей, сюда не попадает: его + называет своя строка `Constructed ...: no links to connect` и счётчик `noLinks` +* невыданная связь: `Link not issued, <причина>: <локальный пин> <-> <внешний пин> (<тип>)` + (Error). Причины: `local pin missing`, `external pin missing`, `unknown link type + '<тип>'`. Оба конца названы в каждой строке. Строка про внешний пин добавляет, что снимок мог + устареть или потребитель был переименован +* выданные вызовы: `Connect issued <локальный пин> <-> <внешний пин> (<тип>)` и `Disconnect + issued <локальный пин> <-> <внешний пин> (<тип>)` (Debug). Число таких строк совпадает с + `connects issued=` и `disconnects issued=` в итоговых записях: вызов, бросивший исключение, + выданным не считается +* исключение вендорского вызова: `Connect ... threw` и `Disconnect ... threw` (Error, с + объектом исключения) + +`ExecuteSnapshot`: + +* путь найденной группы: `Group '<группа>' resolved at '<путь>' for ExecuteSnapshot` + (Information) +* по узлу: `Captured '<узел>': N links` (Information). `tree.json` перезаписывается каждым + снимком, поэтому лог остаётся единственной историей того, что было в снимке раньше +* узел группы, путь которого не разрешился в проекте: `Node '<имя>' captured with no links: + '<путь>' did not resolve in the project; check OpcFbPath` (Error). Такой узел попадает в + `tree.json` без связей, и снимок перезаписывает единственный эталон +* по связи: `Captured <тип> <локальный пин> <-> <внешний пин>` (Debug) +* захват iconnect-связи через соседний пин: `Iconnect ...: input sibling '<пин>' captured to + '<путь>'` (Debug) либо `Iconnect ... captured without an input link on '<пин>'` (Warning). + Вторая строка означает, что входная половина пары не прочиталась; причина и обход — + [known_issues/11](known_issues/11-opc-pinpout-sibling-and-iconnect-connect.md) +* результат: `Snapshot of group '<группа>' written to '<файл>': N nodes, M links, K without + links` (Information при `K = 0`). Когда `K` не ноль, та же строка пишется на уровне Error и + заканчивается на `; the next rebuild constructs those nodes unwired`: узел без связей попал в + `tree.json`, и следующая перестройка построит его неподключённым. `Failed` при этом остаётся + низким (см. 8.4) + +Итог перестройки — одна запись, и её уровень задают её же счётчики. Когда все они нулевые: + +``` +Rebuild of group '<группа>' finished without failures: removed=N constructed=N noLinks=N +notRestored=N; disconnects issued=N threw=N nodesMissing=N; connects issued=N threw=N +unresolved=N +``` + +Когда хоть один из `noLinks`, `notRestored`, `threw`, `nodesMissing`, `unresolved` не нулевой, +та же строка пишется на уровне Error, начинается с `finished with failures:` и заканчивается +состоянием дерева и действием оператора. Счётчики делят это на два случая: + +* не разрешились только связи (`unresolved`, `noLinks`): `; the nodes are in the tree with links + missing, close the project without saving, then re-capture the snapshot or repair the + consumers`. Разрушительная половина при этом отработала: узлы заменены, старая разводка + снята, `Execute` вернул успех. Снимок устарел или потребители переехали +* сбоил кто-то ещё (`threw`, `nodesMissing`, `notRestored`, с любыми связями): `; the tree is + partially rebuilt, close the project without saving`. Что именно не встало на место, называют + строки Error выше + +Сохранение в обоих случаях фиксирует недостроенное дерево. `notRestored` — это те же узлы, что +дали строки `Not restored ...` при перестройке и `... will not be restored` при построении +плана, поэтому ни один такой узел не остаётся без вердикта. Другого признака неуспешной +перестройки нет: `Failed` отложенный этап поднять не может (см. 8.4). + +Счётчики отвечают за действия самой перестройки, а не за содержимое снимка. Связь, отброшенную +при загрузке `tree.json` (пустой путь пина), называет только запись `Snapshot '<файл>': N links +with a blank pin path ignored` уровня Warning: до перестройки такая связь не доходит и в +`unresolved` попасть не может. В итог она входит косвенно — через `noLinks`, если из-за неё узел +восстановился без связей. + +Диагностика поиска группы: + +* при неудачном поиске группы — состав `ScadaRootNode` с именем, `IsNode` и числом + потомков по каждому узлу, до трёх уровней и до 20 потомков у каждого узла (Error). Узлы, + скрытые этими двумя ограничениями, отмечены строкой по месту обрыва. Весь дамп ограничен + 200 строками, и если этот предел сработал, в конце добавляется строка с числом узлов, + отброшенных именно им + +### 8.3. Чего в логе нет + +Ни одна строка не утверждает, что связь установлена. Подключённая связь читается из того же +процесса как отсутствующая, обратное чтение невозможно; см. +[known_issues/11](known_issues/11-opc-pinpout-sibling-and-iconnect-connect.md). Самое +сильное, что пишется, — `issued`: вызов вендора выполнен и не бросил исключения. То же на +стороне отключения. + +### 8.4. Лог и выход `Failed` + +`Failed` поднимают три операции режима исполнения: инициализация FB, `Execute` (сканирование +и построение плана) и `ExecuteSnapshot`. + +У `ExecuteSnapshot` из этого есть изъятие: узлы, записанные в `tree.json` без связей, `Failed` +не поднимают. Снимок сделан и файл записан, а узел без связей бывает и законным — у него просто +нет потребителей. Отличить его от узла, путь которого не разрешился, может только лог: сам +неразрешившийся путь называет строка `Node '<имя>' captured with no links`, а счётчик `K +without links` в итоговой записи поднимает её уровень до Error. `Failed` остаётся низким, и +смотреть надо в лог. + +Отложенная перестройка `Failed` поднять не может. Между циклами исполнения хост заменяет +инстанс FB, и запись в пин после `ToDesign` уходит в выброшенный объект — +[known_issues/07](known_issues/07-fb-instance-replacement.md). Неудачная перестройка +оставляет `Failed = 0` и `IsPending = 0`. Результат отложенного этапа есть только в логе, и +ждать от `Failed` сигнала о плохой перестройке бесполезно. diff --git a/Docs/plans/completed/20260921-opctreemanager-log-as-technical-record.md b/Docs/plans/completed/20260921-opctreemanager-log-as-technical-record.md new file mode 100644 index 0000000..bd9ab91 --- /dev/null +++ b/Docs/plans/completed/20260921-opctreemanager-log-as-technical-record.md @@ -0,0 +1,591 @@ +# OpcTreeManager: the log as a technical record + +## Overview + +The log is the only record of a rebuild: the destructive half runs deferred, after the host leaves +runtime, with no UI and no debugger. A commissioning engineer has to answer four questions from the +file alone, and today can answer none of them without the source and `tree.json`: what was planned, +what changed, what failed, what to do next. + +Two defects carry most of that. The 21 September run failed to issue 119 links and closed with +`Deferred execution completed successfully`, a claim nothing verified. Every one of those 119 error +lines names only the external end, so no line attributes a single failure to the OPC node that owns +it. + +This plan holds the log to one standard: every line is a claim that is true at the instant it is +written, worded minimally, emitted where the fact becomes known, naming domain things. It deletes +what fails that standard, rewrites what can meet it, and adds the small number of facts the module +knows and never records. It does not turn the log into a report: no summaries for management, no +banners, no reassurance, no new abstractions. + +Scope is `NtoLib/OpcTreeManager` plus its tests and `Docs/opc-tree-manager.md` section 8. + +## Context (from discovery) + +The module has **40 logging call sites** (41 grep hits; `Logging/OpcLoggerFactory.cs:22` is +`.MinimumLevel.Debug()`, a config call). `Config/*.cs` and `TreeOperations/OpcProtocolAccessor.cs` +carry none: their facts surface through `Result` and are logged by the service. Measured +distribution on this branch: **13 Information, 6 Warning, 12 Error, 9 Debug**. + +Evidence, all re-measured against the production log +`C:/DISTR/Logs/OpcTreeManager/opc-tree-manager.log` (6124 lines, five runs, 2026-08-03 to +2026-09-21; the last run starts at line 4763): + +- The 119 unresolved links of the last run, mapped against the snapshot the run used: `CBr4` 94 of + 94 not issued, `Water` 12 of 12, `GasLine` 8 of 14, `Shutters` 5 of 13. Two nodes came back with + no links at all. None of that is derivable from the file; it took a script over `tree.json`. +- `DeferredExecutor.cs:95` logs `Deferred execution completed successfully` whenever `Execute` + returned `Ok`, which it did with `unresolved=119`. It carries the same timestamp as the summary + line, `14:36:11.7391778`. +- `PlanExecutor.cs:223` logs only `link.ExternalPinPath`. The 119 lines hold 93 distinct paths, so 26 + read as exact duplicates: a base pin and its `$` sibling target the same external element. +- The output template is + `{Timestamp:O} [{Level:u3}] {SourceContext}: {Message:lj}{NewLine}{Exception}` + (`OpcLoggerFactory.cs:16`). `PlanExecutor` hands its own contextual logger to `TreeReshaper` and + `ConnectRunner`, so `SourceContext` reads `PlanExecutor` on 1231 of the 1233 Debug lines in the + last run, at 49 characters per line. +- `ProjectSubtreeDisconnector.cs:35` returns `(1, 0, 1)` for a node missing from the project, so the + summary's `disconnect links fail=1` counts a node as a link. Visible at log lines 123 and 4760. +- FluentResults' `Error with Message='...'` wrapper reaches the file from three places. + `OpcTreeManagerService.cs:198` joins `IError` directly, which is witnessed at log line 1966. + `:81-84` and `:186-187` each flatten an already-failed `Result` into a string, wrap it in a new + `Error`, and let `LogAndFail` join it again; both are latent, because no run in the file + exercises a snapshot load or write failure. The FB-level re-log that used to double it a fourth + time was removed on this branch (`OpcTreeManagerFB.cs:167-168` carries the comment). +- `LinkCollector.cs:185` and `:197` are Warnings for a lossless deduplication. Neither fired once in + five runs (`grep -c dedup` over the whole log returns 0). +- `PlanBuilder.cs:149-155` logs one Error per unrestorable node, but the block sits inside + `CheckEmptyGroupRestoresSomething`, so for a non-empty group the same fact goes unlogged at plan + time and surfaces only during execution as a Warning at `TreeReshaper.cs:107`. +- `TreeReshaper.cs:63-70` already computes `(total, success, fail)` per removed node and records only + the aggregate. That aggregate lives on `ReshapeResult` and accumulates across the whole recursive + walk, so it cannot be reused for a per-container line. +- `Config/*.cs` contains no logging call, while `Docs/opc-tree-manager.md:282` lists "загрузка + конфигурации" as log content. The document is wrong there. `:284` lists "список изменений", which + the code does not produce; there the document is right and the code is wrong. +- The reference snapshot `C:/DISTR/Config/OpcTreeManager/tree.json` is dated 2026-08-11 and the + failing run is 2026-09-21. A 41-day-old snapshot is a live candidate cause of the 119 missing + externals, and no line in the file records which snapshot content a rebuild used. +- `InitializeRuntime` assigns `_logger = OpcLoggerFactory.Build(LogFilePath)` as the first statement + inside its `try` (`OpcTreeManagerFB.cs:106`). An unwritable path was expected to make + `CreateLogger()` throw there, disabling the block for the rest of the session. Measured on this + branch, it does not: `WriteTo.File` catches a sink construction failure, reports it to `SelfLog` + and installs a null sink, so `Build` returns a working sink-less logger and the first write throws + nothing. Four unopenable paths were driven through `Build` and a write (a file used as a directory + component, `CON`, a path holding `|`, a file held open with `FileShare.None`); none threw, and the + first and third produced no file. `AuditTo.File` is the propagating variant, and the module does + not use it. The FB therefore already keeps running with logging off; what is missing is a test + pinning that. + +## Development Approach + +- **testing approach**: regular, code first, tests in the same task +- one task per coherent group of call sites; complete each fully before the next +- run `dotnet format NtoLib.sln` after each code change +- keep this plan in sync when scope changes + +## Testing Strategy + +`Tests/OpcTreeManager/CapturingSink.cs` captures `LogEvent` objects, so a test asserts level, +rendered message and structured properties. What that reaches, and what it does not, decides the +acceptance criteria: + +- **Reachable today**: `TreeReshaper` (`ApplyDesiredSpecTests` already drives it and passes + `Logger.None`), `ConnectRunner` (driven through the `ConnectCommand` delegate seam with fakes), + `PlanBuilder` (pure), `OpcLoggerFactory` (build against a temp file and read the first line back, + the pattern `TreeSnapshotWriterTests` already uses). +- **Not reachable**: `DeferredExecutor.Post` needs `IProjectHlp.InRuntime`, a concrete + `PlanExecutor` and a WinForms timer tick; `OpcTreeManagerService` needs the FB host. +- **Reachable only after this plan's seam**: `PlanExecutor.BuildCommands` resolves pins through + `_project.SafeItem`. Task 2 threads that resolution in as a delegate, the same shape + `TreeReshaper.Reshape` uses for `resolveChild` and `ConnectCommand` uses for the connect call. It + is an existing house pattern, not a new abstraction, and it is what makes the not-issued lines and + the per-node tally testable. + +Assert only lines that carry a decision. A test per surviving line would pin wording no one reads. + +## Acceptance Evidence + +Automated: + +```powershell +dotnet test NtoLib.sln --filter "FullyQualifiedName~OpcTreeManager" +``` + +Four assertions define the change, each on a seam the harness can drive: + +- `BuildCommands_ExternalPinMissing_LineNamesBothEnds`: the not-issued event carries `LocalPin`, + `ExternalPin` and `LinkType` as structured properties. Today the same site logs one path. +- `BuildCommands_NodeWithNoResolvableLink_LogsTheNodeTally`: a construction whose links all fail to + resolve produces one Error naming the node with its resolved and unresolved counts. This is the + line that would have read `CBr4: 94 links, 0 resolved, 94 unresolved`. +- `Reshape_NodeConstructedWithLinks_LogsOneInformationPerNode`: one Information event per node whose + membership changed, carrying `NodePath` and `LinkCount`. Its sibling + `Reshape_NodeConstructedWithoutLinks_IsRecordedAtErrorAndCounted` pins the other half: a node + constructed with nothing to connect is an Error and feeds the summary's `noLinks`. +- `Build_OutputTemplate_OmitsSourceContext`: a logger built by `OpcLoggerFactory` writes a first + line matching `^\S+ \[\w{3}\] `, with no class name between the level and the message. + +Manual, in the MasterSCADA host, re-running the 21 September scenario against the same project: + +1. Raise `Execute`, leave runtime, let the deferred pass finish +2. The file must answer, without opening `tree.json`: what the plan was before the destructive half + ran, which nodes were constructed, that `CBr4` received 0 of its 94 links and `Water` 0 of 12, + which snapshot file and which write date the rebuild used, and that the run did not succeed +3. No line claims a link is connected, and no line claims success + +The old file answers none of 2. The clustering of missing externals under +`MBE_Avangard2.Установка.Шкаф CBr4` is the one thing it does show, which is why the criterion above +is the attribution to the OPC node, not the clustering. + +## Progress Tracking + +- mark completed items `[x]` when done +- new tasks get a ➕ prefix, blockers a ⚠️ prefix + +## Solution Overview + +**Level policy**, three lines, and every rewrite follows from it: + +- **Error**: one line per domain item (node, link, group, file) that will not be in the planned + state, or per operation that did not run; carries that item's identifiers. The rebuild as a whole + is such an item: its terminal summary goes to Error whenever any of its counters is non-zero, and + the duplication with the per-item Errors above it is deliberate, because the deferred pass cannot + raise `Failed` and that line is the operator's only verdict. +- **Warning**: a fact that may leave an item in an unplanned state where the code cannot tell. +- **Information**: one line per operation boundary (runtime entered, group resolved, snapshot loaded + or written, plan, container reshaped, rebuild finished) plus one per node whose membership + changed. **Debug**: one line per link, plus lifecycle. + +Nine call sites contradict it today: `ConnectRunner.cs:44` (Warning for a definite non-issue), +`TreeReshaper.cs:107` (Warning for a node that will not exist), `LinkCollector.cs:185` and `:197` +(Warning for a lossless fold), `LinkCollector.cs:32` and `TreeReshaper.cs:121` (Debug for per-node +membership facts), `DeferredExecutor.cs:95` (Information for an unverified outcome), +`PlanExecutor.cs:76` (Information for a restatement), `ProjectSubtreeDisconnector.cs:80` +(`Disconnected` claims an outcome nobody read back). + +The per-task checkboxes are the complete list of verdicts; there is no separate tally to keep in +sync with them. + +**What a link line may claim.** `Docs/known_issues/11` establishes that a connection cannot be read +back in-process: a connected link reads back as absent. So no line may say a link *is* connected. +`issued` is the strongest available claim and stays, on both the connect and the disconnect side. + +**Decision: the log file is ASCII.** Link lines use `<->`, not `↔` or `←`. The file is read by +`Select-String`, `grep` and by whatever an engineer has to hand; a symbol that survives none of +those reliably buys nothing. This also removes the last non-ASCII character the module writes into +its own output. + +**Decision: drop `{SourceContext}` from the output template.** It is wrong on 1231 of 1233 Debug +lines, costs 49 bytes each, and names a class rather than a domain thing. The alternative, giving +`TreeReshaper` and `ConnectRunner` their own contextual loggers, makes the field correct but keeps a +55-character namespace prefix on every line to identify something the rewritten messages already +name. Rejected on width. + +**Decision: errors travel as `IError`, not as text.** The three wrapper sites flatten a failed +`Result` into a string and re-wrap it, which is what produces `Error with Message='...'`. The fix is +to keep the original error objects and attach context through `CausedBy`, so `LogAndFail` renders +messages once, from real errors. `Result.Try` does not apply here: it converts a throwing delegate +into a failed `Result`, and these sites have no exception to capture. It is already used where it +belongs, in `OpcConfigLoader.cs:24`, `TreeSnapshotLoader.cs:26` and `TreeSnapshotWriter.cs:32`. + +**Decision: the deferred outcome reaches the operator through the log and nothing else.** Not a +preference: `ExecuteDeferred` hands `DeferredExecutor.Post` only `onFinished: () => PendingPlan = +null` (`OpcTreeManagerService.cs:121`), and no `SetPinValue` exists on that path. +`Docs/known_issues/07-fb-instance-replacement.md` explains why one cannot be added: the host +replaces the FB instance between runtime cycles, so a pin written after `ToDesign` is discarded. A +rebuild that fails therefore leaves `Failed` low and `IsPending` low, and the file is the only +record. Section 8 of the user document has to say so. + +**Decision: the terminal line ends with the tree's state and the operator's next step** (added in +review). `Execute` returns `Ok` when the reshape succeeded and only the connects failed, which is the +21 September path, so the `close the project without saving` clause on `DeferredExecutor`'s exception +path never reaches that run. The `with failures` line therefore carries its own clause, and the +counters split it in two: unresolved links or `noLinks` alone mean the wiring is incomplete +(re-capture the snapshot or repair the consumers); `threw`, `nodesMissing` or `notRestored` mean the +tree itself is half built, and only the Error lines above say which part. + +**Decision: `ExecuteSnapshot` counts nodes captured without links and leaves `Failed` low** (added in +review). The count enters the terminal capture line and raises it to Error, by the same rule the +rebuild summary follows. `Failed` stays low on purpose: the file was written, and a node with no +consumers legitimately has no links, so raising the pin would fire on a healthy capture. Section 8.4 +of the user document carries the carve-out explicitly. + +**Decision: the two failure states are separated by control flow, not by wording.** Failing to +resolve the protocol or the group returns before anything mutates; `CommitStructuralChange` returns +after the reshape has already swapped `Items` and fired live disconnects. Task 1 moves the FB item +lookup ahead of the reshape, which removes that second return site, leaving one post-mutation exit: +an exception. The failed-`Result` line can then state the tree is unchanged as a fact, and the catch +states the opposite. The fuller version of this, a `RebuildTarget` record and an `Apply` that +returns `void` so the compiler forbids a post-mutation `Result`, is rejected here: it is a refactor +of the execution path, and this plan is about what the file says. Revisit it if that path is opened +for another reason. + +**Decision: throws stay in the summary, not in the per-node tally.** `ConnectRunner.ConnectAll` +returns `(Issued, Threw)` and nothing per command, so attributing a throw to its node means changing +that return type and threading per-command results back. The tally counts what `BuildCommands` +knows, links resolvable and not, and the summary keeps the throw count. Revisit only if a throw is +ever observed in production; across five runs `threw=0` every time. + +## Technical Details + +`PlanExecutor.BuildCommands` already iterates `foreach (var construction in constructions) foreach +(var link in construction.Links)`, so the per-node tally needs no new field on `ConnectCommand` and +no new type: count resolvable and unresolvable per construction inside that loop and emit one line +at its end. The pin resolution moves behind a delegate parameter so the loop is drivable from a +test; `TryBuildCommand` keeps its shape. + +`TreeReshaper.cs:126` cannot reuse `result.ShrinkCount` for a per-container line: `ReshapeResult` +accumulates across the whole recursive walk (`ApplyDesiredSpec` recurses at `:90`), so the field +holds a running total. The reshaped line needs two per-invocation locals, one for removals and one +for skips; the skip count is not tracked anywhere today. + +`DeferredExecutor.cs:124` and `:139` sit in the static helpers `RunTickGuarded` and +`AbortWithTimeout`, which never receive the plan. The `ForContext("GroupName", plan.GroupName)` +enrichment this plan first chose was replaced during review: it left `{GroupName}` and +`{TimeoutSeconds}` unbound in two templates, three frames from the only thing that filled them, and +dropping the enrichment would have written a literal `{GroupName}` into the file. Both helpers now +take the group name as a parameter and bind every token positionally. + +`ProjectSubtreeDisconnector.DisconnectPinConnections` iterates `EConnectionTypeMask` values and has +no `LinkTypes` value in scope; the disconnect line needs a small mask-to-type mapping. + +The snapshot write date comes from `File.GetLastWriteTime`, not from the file's content: `tree.json` +is a bare `Dictionary` with `links` and `scadaItem` only. + +## What Goes Where + +- **Implementation Steps**: code, tests and documentation in this repository +- **Post-Completion**: the host run, which no test can stand in for + +## Implementation Steps + +### Task 1: Stop the run claiming an outcome it never verified + +**Files:** +- Modify: `NtoLib/OpcTreeManager/TreeOperations/DeferredExecutor.cs` +- Modify: `NtoLib/OpcTreeManager/TreeOperations/PlanExecutor.cs` + +- [x] delete `DeferredExecutor.cs:95`, `Deferred execution completed successfully`; the tally line + emitted 0 ms earlier is the true terminal record +- [x] delete `:85`, `InRuntime=false; executing plan`; the first reshape line carries the execution + timestamp +- [x] bind the group name onto the logger in `Post` so every message below can name it without a new + parameter on the static helpers +- [x] rewrite `:61` as `Rebuild of group '{GroupName}' queued; waits for the host to leave runtime, + timeout {TimeoutSeconds}s`, the only record that the FB saw `ToDesign` with a plan pending, and + what separates "never left runtime" from "left runtime, process died" +- [x] inline `CommitStructuralChange` into `PlanExecutor.Execute`. The lookup could not be hoisted + ahead of the reshape: the vendor takes the handle after `SynchWihSysTree`, so `Execute` still + returns `Result.Fail` there, after the reshape. A post-mutation failed `Result` therefore + exists, and what makes the next two lines true is the `onTreeMutationStarting` flag, not the + removal of that exit +- [x] rewrite `:91` as `Rebuild of group '{GroupName}' not started, the tree is unchanged: + {Reason}`, with `Reason` from the error objects. The flag picks the wording: a failed `Result` + raised before the first write gets this line, one raised after it gets the partially-changed + line below +- [x] rewrite `:100` as `Rebuild of group '{GroupName}' failed after the reshape began; the tree is + partially changed, close the project without saving: {Reason}`, passing the exception object + when there is one. Both a throw and a post-mutation failed `Result` land here, and the state is + concrete: at the throwing level the removed subtrees are already live-disconnected + (`TreeReshaper.cs:63-70` runs before any construction) while `Items` is not yet swapped + (`:135` is last), and deeper levels of earlier siblings are already swapped (`:90`) +- [x] rewrite `:124` as `Rebuild of group '{GroupName}' abandoned`, exception object, dropping the + timer aside +- [x] rewrite `:139` as `Rebuild of group '{GroupName}' not started: the host stayed in runtime + {TimeoutSeconds}s after ToDesign; the plan is discarded`. The discard is the fact the operator + needs and the current line omits it +- [x] delete `PlanExecutor.cs:76`: every value restates `Initialized`, `Group resolved` or the plan + line, and `{Count}` is anonymous +- [x] no test: every site in this task is inside `DeferredExecutor.Post`, which needs a live + `IProjectHlp` and a timer tick. Verified by the host run in Acceptance Evidence +- [x] run `dotnet format NtoLib.sln` and the OpcTreeManager test filter + +### Task 2: Make every not-issued link name both ends, and stop counting a node as a link + +**Files:** +- Modify: `NtoLib/OpcTreeManager/TreeOperations/PlanExecutor.cs` +- Modify: `NtoLib/OpcTreeManager/TreeOperations/ConnectRunner.cs` +- Modify: `NtoLib/OpcTreeManager/TreeOperations/ProjectSubtreeDisconnector.cs` +- Modify: `NtoLib/OpcTreeManager/TreeOperations/ISubtreeDisconnector.cs` +- Modify: `NtoLib/OpcTreeManager/TreeOperations/TreeReshaper.cs` +- Modify: `Tests/OpcTreeManager/Integration/Fakes/FakeSubtreeDisconnector.cs` +- Modify: `Tests/OpcTreeManager/Unit/ConnectRunnerTests.cs` +- Create: `Tests/OpcTreeManager/Unit/BuildCommandsTests.cs` + +- [x] thread pin resolution into `BuildCommands` as a delegate so the loop runs without + `IProjectHlp`, mirroring `TreeReshaper.Reshape`'s `resolveChild` +- [x] rewrite `PlanExecutor.cs:216` as `Link not issued, local pin missing: {LocalPin} <-> + {ExternalPin} ({LinkType})`, one grep prefix for all three not-issued cases +- [x] rewrite `:223` the same way with `external pin missing`; this is the line that appeared 119 + times naming only one end +- [x] rewrite `:230` as `Link not issued, unknown link type '{LinkType}': {LocalPin} <-> + {ExternalPin}` +- [x] raise `ConnectRunner.cs:44` to Error and pass the exception object instead of `ex.Message`: a + vendor rejection leaves the link out of its planned state, and the HRESULT is the only handle + on it +- [x] rewrite `ProjectSubtreeDisconnector.cs:80` as `Disconnect issued {LocalPin} <-> {ExternalPin} + ({LinkType})` with a mask-to-type mapping. `Disconnected` claims a read-back nobody performed +- [x] rewrite `:88` to pass the exception object, same template shape +- [x] rewrite `:35` as `Remove '{NodePath}': node not found in the project, links not disconnected` +- [x] widen `ISubtreeDisconnector.DisconnectSubtree` with a missing-node count so `(1, 0, 1)` stops + reporting a node as a failed link, and thread it through `ReshapeResult` and the summary; + update `FakeSubtreeDisconnector` +- [x] rewrite the summary at `PlanExecutor.cs:136` against the final tuple: `Rebuild of group + '{GroupName}' finished: removed={RemovedCount} constructed={ConstructedCount}; disconnects + issued={DisconnectsIssued} threw={DisconnectsThrew} nodesMissing={NodesMissing}; connects + issued={ConnectsIssued} threw={ConnectsThrew} unresolved={LinksUnresolved}`; drop `total` (it + is `ok + fail`) and the read-back aside +- [x] write `BuildCommands_ExternalPinMissing_LineNamesBothEnds` and the local-pin and unknown-type + cases against the new delegate +- [x] write a test that a throwing connect is logged at Error with its exception object +- [x] run `dotnet format NtoLib.sln` and the OpcTreeManager test filter + +### Task 3: Record what changed, per node + +**Files:** +- Modify: `NtoLib/OpcTreeManager/TreeOperations/TreeReshaper.cs` +- Modify: `NtoLib/OpcTreeManager/TreeOperations/PlanExecutor.cs` +- Modify: `Tests/OpcTreeManager/Integration/ApplyDesiredSpecTests.cs` +- Modify: `Tests/OpcTreeManager/Unit/BuildCommandsTests.cs` + +- [x] raise `TreeReshaper.cs:121` to Information and reword as `Constructed '{NodePath}': + {LinkCount} links to connect` +- [x] rewrite `:86` as `Preserved '{NodePath}'` at Debug; `links intact` is unverified +- [x] reword `:107` as `Not restored '{NodePath}': not in the container, not in the snapshot`, at + Debug for a top-level node and at Error for a nested one. After Task 4 the plan-time line owns + the top-level fact, and two Errors for one fact breaks the standard this plan sets; but the + plan checks only top-level names against the snapshot, so a nested node has no other record + and keeps its Error (corrected during review: the original checkbox dropped every level to + Debug and left nested losses with no Error anywhere) +- [x] rewrite `:126` as `Reshaped '{ContainerPath}': removed={RemovedCount} + constructed={ConstructedCount} preserved={PreservedCount} skipped={SkippedCount}` using two new + per-invocation locals; `result.ShrinkCount` accumulates across the recursive walk and would + print a running total +- [x] add an Information line in the removal loop at `:63-70`: `Disconnect issued for '{NodePath}': + links={IssuedCount} threw={ThrewCount}`. Removal is the destructive half and has no per-node + record at all today +- [x] count resolvable and unresolvable links per construction inside `BuildCommands` and emit + `Node '{NodePath}': {LinkCount} links, {ResolvedCount} resolved, {UnresolvedCount} unresolved`, + at Error when any is unresolved. Both halves are build-time words: the line is emitted inside + `BuildCommands`, before any connect is attempted (corrected during review: the original + checkbox said `issued`, a connect-time word for a number counted at build time) +- [x] write `Reshape_NodeConstructedWithLinks_LogsOneInformationPerNode` (it shipped under that name, + with `Reshape_NodeConstructedWithoutLinks_IsRecordedAtErrorAndCounted` beside it) and a + per-container reshaped-line + test that would fail on the running-total bug +- [x] write `BuildCommands_NodeWithNoResolvableLink_LogsTheNodeTally` +- [x] run `dotnet format NtoLib.sln` and the OpcTreeManager test filter + +### Task 4: State the plan before the operator commits to it + +**Files:** +- Modify: `NtoLib/OpcTreeManager/Facade/PlanBuilder.cs` +- Modify: `Tests/OpcTreeManager/Unit/PlanBuilderValidationTests.cs` + +- [x] replace `PlanBuilder.cs:88` with `Plan for group '{GroupName}', project '{TargetProject}': + remove {RemoveNodes}; construct {ConstructNodes} ({LinkCount} links in the snapshot); preserve + {PreserveNodes}`, the three name lists computed from `desiredTree` against + `currentTopLevelNames` +- [x] rewrite `:64` as `Group '{GroupName}' top-level node names already match project + '{TargetProject}'; no rebuild`. The check compares names only, and `contents already match` + overclaims to a reader whose links are broken +- [x] rewrite `:151` as `Node '{NodePath}' of project '{TargetProject}' will not be restored: not in + the group, not in the snapshot` +- [x] restructure so that record is emitted for a non-empty group too: `missingFromSnapshot` also + feeds the empty-group refusal at `:142`, so compute it once above the gate and log below it +- [x] append the available project keys to the failure message at `:48`, `projects present: [...]`, + so the property can be corrected without opening the YAML +- [x] write tests for the plan line's three lists and for the non-empty-container case now logging + the unrestorable node at plan time +- [x] run `dotnet format NtoLib.sln` and the OpcTreeManager test filter + +### Task 5: Carry errors as errors across the service boundary + +**Files:** +- Modify: `NtoLib/OpcTreeManager/Facade/OpcTreeManagerService.cs` +- Modify: `NtoLib/OpcTreeManager/OpcTreeManagerFB.cs` + +- [x] stop flattening failed results into strings at `:81-84` and `:186-187`: pass the original + errors on and attach context with `CausedBy`, so `LogAndFail` renders them once +- [x] fix `:198` to render `IError.Message` rather than `IError.ToString()`, which is what prints + the `Error with Message='...'` wrapper +- [x] delete `:62`: `Tree scan begin` restates three properties from the initialization line, and the + only new fact arrives 6 ms later +- [x] delete `:169`: `Snapshot built` is emitted 0 ms before `Snapshot written`; its count folds into + that line +- [x] rewrite `:191` as `Snapshot of group '{GroupName}' written to '{TreeJsonPath}': {NodeCount} + nodes, {LinkCount} links` +- [x] rewrite `:93` as `Snapshot '{TreeJsonPath}': {DroppedLinkCount} links with a blank pin path + ignored` +- [x] rewrite `:128` as `Pending rebuild of group '{GroupName}' cancelled`; `by user` is unverified, + the `Cancel` pin can be driven by logic +- [x] add after the snapshot load: `Snapshot '{TreeJsonPath}' loaded: {NodeCount} nodes, + {LinkCount} links, file written {SnapshotWrittenAt:O}` from `File.GetLastWriteTime`, and state + what the line says when the timestamp cannot be read +- [x] rewrite `OpcTreeManagerFB.cs:116` as `Runtime entered; OpcFbPath={OpcFbPath} + GroupName={GroupName} TargetProject={TargetProject} TreeJsonPath={TreeJsonPath} + ConfigYamlPath={ConfigYamlPath}`; the two file paths are never recorded today +- [x] no test: `OpcTreeManagerService` needs the FB host, as the Testing Strategy states. Verified by + reading and by the host run +- [x] run `dotnet format NtoLib.sln` and the OpcTreeManager test filter + +### Task 6: Cut the capture-path noise + +**Files:** +- Modify: `NtoLib/OpcTreeManager/TreeOperations/LinkCollector.cs` +- Modify: `Tests/OpcTreeManager/Unit/LinkCollectorTests.cs` + +- [x] delete `:185` and `:197`: both are Warnings for a lossless deduplication, neither fired once in + five production runs, and a Warning for a no-loss event trains the reader to ignore Warnings +- [x] keep `:144` at Debug and shorten it to `Iconnect {LocalPin} <-> {ExternalPin}: input sibling + '{Sibling}' captured to '{SiblingExternal}'`. It fired in production (log line 4720) and this + shape is the signature of the `DedupByWire` defect in `known_issues/11`, so the fact stays; + only the prose about the expected shape goes +- [x] rewrite `:151` as `Iconnect {LocalPin} <-> {ExternalPin} captured without an input link on + '{Sibling}'`, dropping the alternatives and the document pointer +- [x] raise `:32` to Information and reword as `Captured '{NodePath}': {LinkCount} links`: the + per-node tally at capture is what a later rebuild is compared against +- [x] rewrite `:219` as `Captured {LinkType} {LocalPin} <-> {ExternalPin}` and keep it: `tree.json` + is overwritten by the next capture, so the log is the only history of what an earlier snapshot + held +- [x] update the tests that assert on the deleted warnings +- [x] run `dotnet format NtoLib.sln` and the OpcTreeManager test filter + +### Task 7: Template and property hygiene + +**Files:** +- Modify: `NtoLib/OpcTreeManager/Logging/OpcLoggerFactory.cs` +- Modify: every file touched in Tasks 1-6 +- Create: `Tests/OpcTreeManager/Unit/OpcLoggerFactoryTests.cs` + +- [x] drop `{SourceContext}` from the output template at `OpcLoggerFactory.cs:16` +- [x] give `{Path}` a distinct name per thing it names: `TreeJsonPath`, `LocalPin`, `ExternalPin` +- [x] rename `{NodeFullName}` to `{NodePath}`, the name used everywhere else +- [x] remove `{Message}` as a property name: it collides with the output template's built-in token; + both sites that used it now pass the exception object instead +- [x] replace every `↔` and `←` in a message template with `<->`, so the file the module writes is + ASCII throughout +- [x] confirm no anonymous `{Count}` remains +- [x] write `Build_OutputTemplate_OmitsSourceContext` against a temp file, the pattern + `TreeSnapshotWriterTests` already uses +- [x] run `dotnet format NtoLib.sln` and the full suite + +### Task 8: A log that cannot be written must not stop the FB + +Failing to log is not a failed operation. The FB must keep working with logging off. + +Measured before writing any fix, against four unopenable paths: `Build` does not throw and neither +does the first write. `WriteTo.File` already installs a null sink when it cannot open the file, so +`Build` is total as written, `InitializeRuntime`'s catch never fires for this cause and +`_isRuntimeInitialized` stays true. The task is therefore a test that pins the behaviour, plus the +one-line note that says which Serilog contract it rests on. + +**Files:** +- Modify: `NtoLib/OpcTreeManager/Logging/OpcLoggerFactory.cs` +- Modify: `Tests/OpcTreeManager/Unit/OpcLoggerFactoryTests.cs` + +- [x] measure where the failure lands before changing anything: `Build` returns, the write returns, + no file appears, nothing throws. The plan's assumption of an eager open was wrong and the + Context bullet is corrected +- [x] `Build` needs no change to be total; note on it that `WriteTo.File` swallows sink construction + failures, because nothing in the method body says so and `AuditTo.File` behaves the opposite way +- [x] leave `OpcTreeManagerFB.InitializeRuntime` untouched: its catch does not fire for this cause, + `_isRuntimeInitialized` stays true and the `Failed` pin stays low, which is correct because no + operation failed +- [x] do not add a fallback file, a second path or a pin: the log is either at the configured path or + absent, and nothing else in the module changes behaviour on that +- [x] write `Build_UnwritablePath_ReturnsLoggerThatWritesNothing`: `Build` against a path whose + directory component is a file returns a logger, writing to it throws nothing, and neither the + directory nor the file appears +- [x] run `dotnet format NtoLib.sln` and the OpcTreeManager test filter + +### Task 9: Make section 8 describe the shipped log + +**Files:** +- Modify: `Docs/opc-tree-manager.md` + +- [x] correct `:282`: nothing logs a successful config load and nothing should; it becomes "ошибки + загрузки конфигурации и снапшота" +- [x] state the level policy in three lines so a reader knows what a Warning means in this file +- [x] describe the plan line, the per-node construction and removal records, and the per-node link + tally, which is what `:284` "список изменений" has always promised +- [x] state that no line claims a link is connected, and why, pointing at `known_issues/11` +- [x] state that an unwritable `LogFilePath` disables logging and nothing else: the FB keeps running + and `Failed` stays low +- [x] state that `Failed` reports scan and snapshot failures only. The deferred rebuild cannot raise + it, because the host replaces the FB instance between runtime cycles + (`known_issues/07-fb-instance-replacement.md`), so its outcome is in the log and nowhere else. + An operator waiting for `Failed` to tell them a rebuild went wrong is waiting for something + that cannot happen +- [x] confirm the remaining bullets still match the code + +### Task 10: Verify acceptance criteria + +- [x] confirm every requirement in the Overview is implemented +- [x] run the full suite: `dotnet test NtoLib.sln` +- [x] run `dotnet format NtoLib.sln`; every file this branch touches is clean. `--verify-no-changes` + still exits 2 on a pre-existing IDE1006 in + `Tests/MbeTable/Infrastructure/EditorRuntimeOptionsProviderTests.cs:74`, outside this branch + and not fixed here +- [x] confirm each of the four Acceptance Evidence assertions exists and passes +- [x] confirm every message template the module writes is ASCII. The values are not and cannot be: + `OpcFbPath` defaults to `Система.АРМ.OPC UA Siemens` and reaches the file through `Runtime + entered` +- [x] reread every comment added by Tasks 1-9: English, ASCII, one paragraph, no restating of what + the code already says + +## Verify it yourself + +The change is a change to a file nobody can unit-test end to end, so the demonstration is a +before-and-after on the same input. + +Automated, and it fails before the change: + +```powershell +dotnet test NtoLib.sln --filter "FullyQualifiedName~BuildCommands_NodeWithNoResolvableLink_LogsTheNodeTally" +``` + +The test does not compile before Task 2, because `BuildCommands` has no seam to drive; it fails on +its assertion before Task 3, because no line names the node. Both are the point. + +By hand, on the two logs: + +```powershell +Select-String -Path C:\DISTR\Logs\OpcTreeManager\opc-tree-manager.log -Pattern 'ServerInterfaces\.MBE\.CBr4' +``` + +The pattern is the OPC-side path, which is what the old lines never carry: filtering on the +external end instead (`-notmatch 'Шкаф CBr4'`) would drop the new lines too, because each of them +names `Шкаф CBr4...` as its external end. + +Within the 21 September run this returns exactly one line, the construction record: the 94 +not-issued lines of that run name only the external end (measured: 95 lines of the run hold +`CBr4`, 94 of them only as `Шкаф CBr4`). After the change the same query returns 96 lines for that +run: the construction record, the per-node tally reading 94 links 0 resolved 94 unresolved, and 94 +not-issued lines that each name `...ServerInterfaces.MBE.CBr4...` as the local end. Earlier runs in +the same file also match the pattern, so scope the query to the run under test. + +## Post-Completion + +**Manual verification:** + +- the two-step host run in Acceptance Evidence, on a project copy, re-running the 21 September + scenario so the same 119 unresolved links are produced against the new lines +- read the resulting file end to end once as a technician would, and check that the four questions + are answerable from it alone: what was planned, what changed, what failed, what to do next + +**Branching:** + +- this plan edits the same files as `opctreemanager-empty-group-resolution`, which is not yet + delivered. Branch from that branch's tip, or from `master` after it merges; do not run the two in + parallel + +**Executed by exec:** + +- branch: `opctreemanager-log-as-technical-record`, stacked on + `opctreemanager-empty-group-resolution`. Deliver the parent first; every review in this run diffed + against it rather than `master` +- `Docs/plans/20260921-opctreemanager-opcfbpath-resolution.md`, the queued backlog plan, is + committed on this branch. It belongs to a different change and the delivery step decides whether + to split it out; this run could not, because removing it needs a history rewrite diff --git a/NtoLib/OpcTreeManager/Entities/LinkEntry.cs b/NtoLib/OpcTreeManager/Entities/LinkEntry.cs index 5433cbc..eda51c3 100644 --- a/NtoLib/OpcTreeManager/Entities/LinkEntry.cs +++ b/NtoLib/OpcTreeManager/Entities/LinkEntry.cs @@ -3,7 +3,7 @@ namespace NtoLib.OpcTreeManager.Entities; /// -/// Represents one directed link: ↔ . +/// Represents one directed link from to . /// is the OPC-side pin; is the /// consumer/producer pin outside the OPC subtree. /// diff --git a/NtoLib/OpcTreeManager/Facade/OpcTreeManagerService.cs b/NtoLib/OpcTreeManager/Facade/OpcTreeManagerService.cs index 173adc8..7cae91c 100644 --- a/NtoLib/OpcTreeManager/Facade/OpcTreeManagerService.cs +++ b/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(); + _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> 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> BuildSnapshot(string opcFbPath, var fullPath = JoinPath(opcFbPath, groupRelativePath, item.Name); var node = _project.SafeItem(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(); @@ -166,10 +174,6 @@ private Result> 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(); } + /// Terminal record of a capture: the count of nodes written with no links sets the level, + /// and deliberately not the Failed pin (Docs/opc-tree-manager.md section 8.4). + internal static void LogSnapshotWritten( + string groupName, + string treeJsonPath, + IReadOnlyDictionary 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 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().FirstOrDefault()?.Exception; + + if (exception == null) + { + _logger.Error("{ErrorMessage}", message); + } + else + { + _logger.Error(exception, "{ErrorMessage}", message); + } + + return Result.Fail(errorList); + } + + /// Walks an error and its CausedBy chain so every cause reaches the log line. + internal static IEnumerable Flatten(IEnumerable errors) + { + foreach (var error in errors) + { + yield return error; + + foreach (var nested in Flatten(error.Reasons.OfType())) + { + yield return nested; + } + } + } + + private void LogSnapshotLoaded(Dictionary snapshot, string treeJsonPath) + { + _logger.Information( + "Snapshot '{TreeJsonPath}' loaded: {NodeCount} nodes, {LinkCount} links, " + + "file written {SnapshotWrittenAt}", + treeJsonPath, snapshot.Count, CountLinks(snapshot), DescribeWriteTime(treeJsonPath)); + } + + /// Never throws: ScanAndValidate runs out of UpdateData unguarded, so a date + /// the file system refuses and the 1601 sentinel it returns instead both read as unknown. + 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 snapshot) + { + return snapshot.Values.Sum(node => node.Links.Count); } private Result<(OpcUaScadaItem Group, string RelativePath)> ResolveGroup( diff --git a/NtoLib/OpcTreeManager/Facade/PlanBuilder.cs b/NtoLib/OpcTreeManager/Facade/PlanBuilder.cs index c2fa555..fa522ba 100644 --- a/NtoLib/OpcTreeManager/Facade/PlanBuilder.cs +++ b/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(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(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."); } - /// Fails when an empty group has no desired node the snapshot can restore. - private static Result CheckEmptyGroupRestoresSomething( + /// + /// An entry whose ScadaItem is null resolves to a null DTO at execute time, so the key alone does + /// not make the node restorable. + /// + private static List FindNamesMissingFromSnapshot( IReadOnlyList desiredTree, - IReadOnlyDictionary snapshot, - string targetProject, - string groupName, - ILogger? logger) + IReadOnlyDictionary 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 desiredTree, + IReadOnlyDictionary snapshot, + IReadOnlyList currentTopLevelNames, + IReadOnlyList 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(currentTopLevelNames, StringComparer.Ordinal); + var desiredNames = new HashSet(desiredTree.Select(s => s.Name), StringComparer.Ordinal); + var unrestorableNames = new HashSet(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); } - /// - /// Walks the desired spec against the snapshot DTO tree and returns the path of the first node - /// that does not resolve, or null when the whole spec resolves. Mirrors the runtime - /// resolver in : the top level resolves through - /// snapshot.TryGetValue(name).ScadaItem, nested nodes by descending the parent DTO's - /// Items and matching children by ordinal Name. - /// + /// Mirrors the runtime resolver in : the top + /// level through snapshot.TryGetValue(name).ScadaItem, nested nodes by ordinal Name + /// down Items. private static string? FindUnresolvableNode( IReadOnlyList desired, IReadOnlyDictionary 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; diff --git a/NtoLib/OpcTreeManager/Logging/OpcLoggerFactory.cs b/NtoLib/OpcTreeManager/Logging/OpcLoggerFactory.cs index 036b8da..51921c6 100644 --- a/NtoLib/OpcTreeManager/Logging/OpcLoggerFactory.cs +++ b/NtoLib/OpcTreeManager/Logging/OpcLoggerFactory.cs @@ -11,9 +11,11 @@ internal static class OpcLoggerFactory private const long MaxFileSizeBytes = 5L * 1024 * 1024; private const int RetainedFileCount = 5; + /// Never throws: Serilog's WriteTo.File swallows sink construction failures, so an + /// unwritable path yields a sink-less logger rather than an exception. public static Logger Build(string logFilePath) { - const string Template = "{Timestamp:O} [{Level:u3}] {SourceContext}: {Message:lj}{NewLine}{Exception}"; + const string Template = "{Timestamp:O} [{Level:u3}] {Message:lj}{NewLine}{Exception}"; var invariant = CultureInfo.InvariantCulture; TryEnsureDirectory(logFilePath); diff --git a/NtoLib/OpcTreeManager/OpcTreeManagerFB.cs b/NtoLib/OpcTreeManager/OpcTreeManagerFB.cs index 34ff068..a8e2d28 100644 --- a/NtoLib/OpcTreeManager/OpcTreeManagerFB.cs +++ b/NtoLib/OpcTreeManager/OpcTreeManagerFB.cs @@ -9,7 +9,6 @@ using NtoLib.OpcTreeManager.Facade; using NtoLib.OpcTreeManager.Logging; -using Serilog; using Serilog.Core; namespace NtoLib.OpcTreeManager; @@ -34,7 +33,6 @@ public sealed class OpcTreeManagerFB : StaticFBBase [NonSerialized] private bool _previousCancel; [NonSerialized] private bool _previousExecuteSnapshot; [NonSerialized] private Logger? _logger; - [NonSerialized] private ILogger? _log; [NonSerialized] private OpcTreeManagerService? _service; [DisplayName("Целевой проект")] @@ -104,7 +102,12 @@ private void InitializeRuntime() try { _logger = OpcLoggerFactory.Build(LogFilePath); - _log = _logger.ForContext(); + + _logger.Information( + "Runtime entered; OpcFbPath={OpcFbPath} GroupName={GroupName} TargetProject={TargetProject} " + + "TreeJsonPath={TreeJsonPath} ConfigYamlPath={ConfigYamlPath}", + OpcFbPath, GroupName, TargetProject, TreeJsonPath, ConfigYamlPath); + _service = new OpcTreeManagerService(TreeItemHlp!.Project, _logger); _previousExecute = false; _previousCancel = false; @@ -113,17 +116,13 @@ private void InitializeRuntime() SetPinValue(IsPendingPinId, false, DateTime.UtcNow); SetPinValue(FailedPinId, false, DateTime.UtcNow); - _log.Information( - "Initialized; OpcFbPath={OpcFbPath} GroupName={GroupName} TargetProject={TargetProject}", - OpcFbPath, GroupName, TargetProject); } catch (Exception ex) { _isRuntimeInitialized = false; - _log?.Error(ex, "Initialization failed"); + _logger?.Error(ex, "Initialization failed"); _logger?.Dispose(); _logger = null; - _log = null; SetPinValue(IsPendingPinId, false, DateTime.UtcNow); SetPinValue(FailedPinId, true, DateTime.UtcNow); } @@ -135,7 +134,6 @@ private void CleanupRuntime() _service = null; _logger?.Dispose(); _logger = null; - _log = null; } private bool ConsumeRisingEdge(int pinId, ref bool previousState) @@ -221,10 +219,9 @@ private void FlushPendingPlan() // Transfer ownership of the concrete root Logger to the deferred executor: its timer fires // after ToDesign (post-runtime) and disposes the logger once the plan finishes. Null the - // fields so CleanupRuntime cannot double-dispose the same Logger. + // field so CleanupRuntime cannot double-dispose the same Logger. var logger = _logger; _logger = null; - _log = null; _service.ExecuteDeferred(logger); } } diff --git a/NtoLib/OpcTreeManager/TreeOperations/ConnectRunner.cs b/NtoLib/OpcTreeManager/TreeOperations/ConnectRunner.cs index 6e74f5c..2174ea6 100644 --- a/NtoLib/OpcTreeManager/TreeOperations/ConnectRunner.cs +++ b/NtoLib/OpcTreeManager/TreeOperations/ConnectRunner.cs @@ -7,16 +7,16 @@ namespace NtoLib.OpcTreeManager.TreeOperations; /// /// Connect-all pass: invoke every command's in order, tolerating -/// a throwing command (caught, counted, and the pass continues to the rest). Returns an honest tally +/// a throwing command (caught, logged at Error, and the pass continues to the rest). Returns an honest tally /// of connects issued and how many threw — no read-back verdict; success is judged by the SCADA tree /// on reload. /// internal static class ConnectRunner { /// - /// Invokes every command's connect in order and returns (Issued, Threw): Issued is the - /// command count (every command is attempted), Threw is how many raised. A throw is caught, - /// logged at Warning, and the pass continues to the remaining commands. + /// Invokes every command's connect in order and returns (Issued, Threw), which sum to the + /// command count: Issued counts the calls that returned, Threw the calls that raised, + /// matching what the per-link Connect issued record claims. /// public static (int Issued, int Threw) ConnectAll(IReadOnlyList commands, ILogger logger) { @@ -25,6 +25,7 @@ public static (int Issued, int Threw) ConnectAll(IReadOnlyList c throw new ArgumentNullException(nameof(commands)); } + var issued = 0; var threw = 0; foreach (var command in commands) @@ -32,8 +33,9 @@ public static (int Issued, int Threw) ConnectAll(IReadOnlyList c try { command.Connect(); + issued++; logger.Debug( - "Connect issued {LocalPin} ↔ {ExternalPin} ({LinkType})", + "Connect issued {LocalPin} <-> {ExternalPin} ({LinkType})", command.LocalPinPath, command.ExternalPinPath, command.LinkType); @@ -41,15 +43,15 @@ public static (int Issued, int Threw) ConnectAll(IReadOnlyList c catch (Exception ex) { threw++; - logger.Warning( - "Connect {LocalPin} ↔ {ExternalPin} ({LinkType}) threw during connect — {Message}", + logger.Error( + ex, + "Connect {LocalPin} <-> {ExternalPin} ({LinkType}) threw", command.LocalPinPath, command.ExternalPinPath, - command.LinkType, - ex.Message); + command.LinkType); } } - return (commands.Count, threw); + return (issued, threw); } } diff --git a/NtoLib/OpcTreeManager/TreeOperations/DeferredExecutor.cs b/NtoLib/OpcTreeManager/TreeOperations/DeferredExecutor.cs index 85c684f..1e25923 100644 --- a/NtoLib/OpcTreeManager/TreeOperations/DeferredExecutor.cs +++ b/NtoLib/OpcTreeManager/TreeOperations/DeferredExecutor.cs @@ -1,4 +1,5 @@ using System; +using System.Linq; using System.Windows.Forms; using MasterSCADA.Hlp; @@ -19,8 +20,8 @@ internal static class DeferredExecutor /// /// Posts a single-tick deferred execution. On the first timer tick after /// drops to false it runs - /// — which connects every link - /// in-pass — and then finishes. The InRuntime==false wait is required because a + /// , which connects every link + /// in-pass, and then finishes. The InRuntime==false wait is required because a /// deferred-execution FB may not mutate the tree while the host is still in runtime /// (see the deferred-execution known issue). /// @@ -36,8 +37,6 @@ public static void Post( IProjectHlp project, Action onFinished) { - var log = logger?.ForContext(typeof(DeferredExecutor)); - // Once-only release: disposes the logger and calls onFinished exactly once, whichever // terminal branch reaches it first. WinForms timers tick on the STA pump (single thread), // so a plain bool guard is sufficient — no locking needed. @@ -58,12 +57,13 @@ void Release() var timer = new Timer { Interval = RetryIntervalMs }; var polls = MaxPolls; - log?.Debug( - "Deferred execution posted; waiting for InRuntime=false (max {MaxPolls} × {IntervalMs}ms)", - MaxPolls, RetryIntervalMs); + logger?.Information( + "Rebuild of group '{GroupName}' queued; waits for the host to leave runtime, " + + "timeout {TimeoutSeconds}s", + plan.GroupName, TotalTimeoutSeconds); // The whole tick body runs inside RunTickGuarded so any escape stops the timer and releases once. - timer.Tick += (_, _) => RunTickGuarded(timer, log, Release, () => + timer.Tick += (_, _) => RunTickGuarded(timer, logger, plan.GroupName, Release, () => { if (project.InRuntime) { @@ -74,30 +74,27 @@ void Release() return; } - AbortWithTimeout(timer, log, Release); + AbortWithTimeout(timer, logger, plan.GroupName, Release); return; } FinishTimer(timer); + var treeChanged = false; + try { - log?.Debug("InRuntime=false; executing plan"); - var result = executor.Execute(plan); + var result = executor.Execute(plan, () => treeChanged = true); if (result.IsFailed) { - var errorMessage = string.Join("; ", result.Errors); - log?.Error("Deferred execution failed: {ErrorMessage}", errorMessage); - } - else - { - log?.Information("Deferred execution completed successfully"); + var reason = string.Join("; ", result.Errors.Select(error => error.Message)); + LogRebuildFailed(logger, plan.GroupName, treeChanged, reason, exception: null); } } catch (Exception exception) { - log?.Error(exception, "Deferred execution failed with exception"); + LogRebuildFailed(logger, plan.GroupName, treeChanged, exception.Message, exception); } finally { @@ -108,12 +105,33 @@ void Release() timer.Start(); } + private static void LogRebuildFailed( + ILogger? logger, + string groupName, + bool treeChanged, + string reason, + Exception? exception) + { + var template = treeChanged + ? "Rebuild of group '{GroupName}' failed after the reshape began; the tree is partially " + + "changed, close the project without saving: {Reason}" + : "Rebuild of group '{GroupName}' not started, the tree is unchanged: {Reason}"; + + if (exception == null) + { + logger?.Error(template, groupName, reason); + return; + } + + logger?.Error(exception, template, groupName, reason); + } + /// /// Runs a tick body and guarantees that ANY escape from it stops+disposes the timer and calls /// exactly once ( carries its own idempotency /// guard). A normal return does nothing, so a body that keeps the timer running just returns. /// - private static void RunTickGuarded(Timer timer, ILogger? log, Action release, Action body) + private static void RunTickGuarded(Timer timer, ILogger? logger, string groupName, Action release, Action body) { try { @@ -121,7 +139,7 @@ private static void RunTickGuarded(Timer timer, ILogger? log, Action release, Ac } catch (Exception exception) { - log?.Error(exception, "Deferred execution tick handler threw; stopping timer and releasing"); + logger?.Error(exception, "Rebuild of group '{GroupName}' abandoned", groupName); FinishTimer(timer); release(); } @@ -129,17 +147,18 @@ private static void RunTickGuarded(Timer timer, ILogger? log, Action release, Ac private static void AbortWithTimeout( Timer timer, - ILogger? log, + ILogger? logger, + string groupName, Action release) { FinishTimer(timer); try { - log?.Error( - "Deferred execution aborted: IProjectHlp.InRuntime is still true after {MaxPolls} polls ({TotalSeconds}s)", - MaxPolls, - TotalTimeoutSeconds); + logger?.Error( + "Rebuild of group '{GroupName}' not started: the host stayed in runtime " + + "{TimeoutSeconds}s after ToDesign; the plan is discarded", + groupName, TotalTimeoutSeconds); } finally { diff --git a/NtoLib/OpcTreeManager/TreeOperations/ISubtreeDisconnector.cs b/NtoLib/OpcTreeManager/TreeOperations/ISubtreeDisconnector.cs index aa2fa71..df12c64 100644 --- a/NtoLib/OpcTreeManager/TreeOperations/ISubtreeDisconnector.cs +++ b/NtoLib/OpcTreeManager/TreeOperations/ISubtreeDisconnector.cs @@ -1,6 +1,11 @@ -namespace NtoLib.OpcTreeManager.TreeOperations; +using System; + +namespace NtoLib.OpcTreeManager.TreeOperations; internal interface ISubtreeDisconnector { - (int Total, int Success, int Fail) DisconnectSubtree(string nodePath); + /// A missing node is not a link: it counts into NodesMissing (0 or 1), never into + /// Threw. Raises immediately before the first + /// Disconnect and never earlier; the caller makes the callback once-only. + (int Issued, int Threw, int NodesMissing) DisconnectSubtree(string nodePath, Action onTreeMutationStarting); } diff --git a/NtoLib/OpcTreeManager/TreeOperations/LinkCollector.cs b/NtoLib/OpcTreeManager/TreeOperations/LinkCollector.cs index 77a686c..126ef68 100644 --- a/NtoLib/OpcTreeManager/TreeOperations/LinkCollector.cs +++ b/NtoLib/OpcTreeManager/TreeOperations/LinkCollector.cs @@ -21,15 +21,22 @@ public static IReadOnlyList CollectAllLinks(ITreeItemHlp node, ILogge throw new ArgumentNullException(nameof(node)); } - var log = logger?.ForContext(typeof(LinkCollector)); var pinViews = node .EnumAllChilds(TreeMasks.AllPinKinds, 0) .OfType() .Select(CreatePinView); - var links = BuildLinks(pinViews, log); + return CollectLinks(node.FullName, pinViews, logger); + } + + internal static IReadOnlyList CollectLinks( + string nodePath, + IEnumerable pins, + ILogger? logger) + { + var links = BuildLinks(pins, logger); - log?.Debug("Collected {LinkCount} links from node '{NodeFullName}'", links.Count, node.FullName); + logger?.Information("Captured '{NodePath}': {LinkCount} links", nodePath, links.Count); return links; } @@ -89,7 +96,7 @@ internal static IReadOnlyList BuildLinks(IEnumerable pins, I AppendLinks(pin, EConnectionTypeMask.ctIConnect, LinkTypes.IConnect, rawLinks, log); } - var links = DedupByWire(rawLinks, log); + var links = DedupByWire(rawLinks); WarnTwinlessIConnects(links, log); return links; } @@ -102,8 +109,9 @@ internal static IReadOnlyList BuildLinks(IEnumerable pins, I /// only alarms on the one shape that has ever meant lost data: /// /// sibling captured to the same external — both halves present; silent. - /// sibling captured to a different external — the expected shape for a pin whose input - /// and feedback target different nodes (feedback-only pins); logged at Debug. + /// sibling captured to a different external: either a feedback-only pin whose input + /// and feedback target different nodes, or the signature of the fold + /// described in known-issue 11; logged at Debug. /// sibling has no captured row at all — the only shape a dropped or blind/partial /// capture takes (the old fold, or the read-back blindness of /// known-issue 11); logged at Warning. @@ -139,19 +147,19 @@ private static void WarnTwinlessIConnects(IReadOnlyList links, ILogge continue; } - if (siblingExternals.Any()) + var siblingExternal = siblingExternals.FirstOrDefault(); + + if (siblingExternal != null) { log.Debug( - "Feedback-only iconnect '{LocalPin}' → '{ExternalPin}': input sibling '{Sibling}' is " + - "captured to a different external — expected PinPout shape", - row.LocalPinPath, row.ExternalPinPath, sibling); + "Iconnect {LocalPin} <-> {ExternalPin}: input sibling '{Sibling}' captured to " + + "'{SiblingExternal}'", + row.LocalPinPath, row.ExternalPinPath, sibling, siblingExternal); continue; } log.Warning( - "Capture check: iconnect '{LocalPin}' → '{ExternalPin}' has no captured link on input " + - "sibling '{Sibling}' — the input is either genuinely unconnected or was not captured " + - "(partial/blind capture; see Docs/known_issues/11)", + "Iconnect {LocalPin} <-> {ExternalPin} captured without an input link on '{Sibling}'", row.LocalPinPath, row.ExternalPinPath, sibling); } } @@ -169,32 +177,17 @@ private static void WarnTwinlessIConnects(IReadOnlyList links, ILogge /// pin came back with only its feedback half and never persisted. /// /// - private static List DedupByWire(List rows, ILogger? log) + private static List DedupByWire(List rows) { var result = new List(rows.Count); var seen = new HashSet<(string Local, string External, string LinkType)>(); - var dropped = 0; foreach (var row in rows) { - var key = (row.LocalPinPath, row.ExternalPinPath, row.LinkType); - - if (!seen.Add(key)) + if (seen.Add((row.LocalPinPath, row.ExternalPinPath, row.LinkType))) { - dropped++; - log?.Warning( - "Exact-duplicate dedup: dropped ({LocalPin}, {ExternalPin}, {LinkType}) — " + - "an identical surviving triple already carries this wire", - row.LocalPinPath, row.ExternalPinPath, row.LinkType); - continue; + result.Add(row); } - - result.Add(row); - } - - if (dropped > 0) - { - log?.Warning("Exact-duplicate dedup: {DroppedCount} rows removed", dropped); } return result; @@ -217,7 +210,7 @@ private static void AppendLinks( }); log?.Debug( - "CollectLink {LinkType} {LocalPin} ↔ {ExternalPin}", + "Captured {LinkType} {LocalPin} <-> {ExternalPin}", linkType, pin.FullName, externalFullName); } } diff --git a/NtoLib/OpcTreeManager/TreeOperations/PlanExecutor.cs b/NtoLib/OpcTreeManager/TreeOperations/PlanExecutor.cs index 9702024..a2120f9 100644 --- a/NtoLib/OpcTreeManager/TreeOperations/PlanExecutor.cs +++ b/NtoLib/OpcTreeManager/TreeOperations/PlanExecutor.cs @@ -1,5 +1,6 @@ using System; using System.Collections.Generic; +using System.Linq; using FluentResults; @@ -13,6 +14,7 @@ using OpcUaClient.Client.Common.Data; using Serilog; +using Serilog.Events; namespace NtoLib.OpcTreeManager.TreeOperations; @@ -32,7 +34,7 @@ public PlanExecutor(IProjectHlp project, ISubtreeDisconnector disconnector, ILog throw new ArgumentNullException(nameof(logger)); } - _logger = logger.ForContext(); + _logger = logger; } /// @@ -48,7 +50,7 @@ public PlanExecutor(IProjectHlp project, ISubtreeDisconnector disconnector, ILog /// as absent), so the summary reports only what is known — connects issued and how many threw. /// See Docs/known_issues/11. /// - public Result Execute(RebuildPlan plan) + public Result Execute(RebuildPlan plan, Action onTreeMutationStarting) { if (plan == null) { @@ -73,10 +75,19 @@ public Result Execute(RebuildPlan plan) var (group, groupRelativePath) = groupResult.Value; var groupPath = plan.OpcFbPath + "." + groupRelativePath; - _logger.Information( - "Executing plan for OPC FB {OpcFbPath}, group {GroupName} resolved at '{GroupRelativePath}' " - + "({Count} top-level nodes desired)", - plan.OpcFbPath, plan.GroupName, groupRelativePath, plan.DesiredTree.Count); + // Raised by the reshape at its first write, from any depth and from inside the disconnector. + var mutationFlagged = false; + + void FlagTreeMutation() + { + if (mutationFlagged) + { + return; + } + + mutationFlagged = true; + onTreeMutationStarting(); + } // Top-level: each desired child resolves through plan.Snapshot (keyed by // top-level name). Links for each top-level subtree live in the same @@ -89,75 +100,92 @@ public Result Execute(RebuildPlan plan) ? (s.ScadaItem, s.Links) : (null, Array.Empty()), disconnector: _disconnector, + onTreeMutationStarting: FlagTreeMutation, logger: _logger); ResetScadaItemsMap(protocol); protocol.SynchWihSysTree(); - var commitResult = CommitStructuralChange(plan.OpcFbPath); - if (commitResult.IsFailed) + // Resolved after SynchWihSysTree, not before the reshape: the vendor UI's + // OpcUaGroupPropPageWindow.ApplyChanges() takes the handle in that order, and ApplyChange commits + // the new pin slots into the native name registry vavobj's ConnectByName resolves against. + var opcFbItem = _project.SafeItem(plan.OpcFbPath); + if (opcFbItem == null) { - return commitResult; + return Result.Fail($"OPC FB tree item not found for ApplyChange: {plan.OpcFbPath}"); } - var (commands, resolveFail) = BuildCommands(reshape.Constructions); + opcFbItem.ApplyChange(); + + var (commands, linksUnresolved) = BuildCommands( + reshape.Constructions, + path => _project.SafeItem(path), + _logger); var orderedCommands = CommandOrdering.OrderCommandsDirectFirst(commands); var (connectsIssued, connectsThrew) = ConnectRunner.ConnectAll(orderedCommands, _logger); - LogExecutionComplete( - shrinkCount: reshape.ShrinkCount, - constructionsCount: reshape.Constructions.Count, - shrinkTotal: reshape.ShrinkTotal, - shrinkSuccess: reshape.ShrinkSuccess, - shrinkFail: reshape.ShrinkFail, - resolveFail: resolveFail, + LogRebuildFinished( + groupName: plan.GroupName, + reshape: reshape, connectsIssued: connectsIssued, - connectsThrew: connectsThrew); + connectsThrew: connectsThrew, + linksUnresolved: linksUnresolved, + logger: _logger); return Result.Ok(); } - /// - /// Emits the single Execution complete summary. counts commands - /// that failed to build (pin unresolved or unknown link type) and so were never issued. - /// - private void LogExecutionComplete( - int shrinkCount, - int constructionsCount, - int shrinkTotal, - int shrinkSuccess, - int shrinkFail, - int resolveFail, + internal static void LogRebuildFinished( + string groupName, + ReshapeResult reshape, int connectsIssued, - int connectsThrew) + int connectsThrew, + int linksUnresolved, + ILogger logger) { - _logger.Information( - "Execution complete: shrink={ShrinkCount} expand={ExpandCount}; " - + "disconnect links total={ShrinkTotal} ok={ShrinkSuccess} fail={ShrinkFail}; " - + "connects issued={ConnectsIssued} threw={ConnectsThrew} unresolved={ResolveFail} " - + "(success judged by the SCADA tree on reload, not by read-back)", - shrinkCount, constructionsCount, shrinkTotal, shrinkSuccess, shrinkFail, - connectsIssued, connectsThrew, resolveFail); - } + var constructionsWithoutLinks = reshape.Constructions.Count(c => c.Links.Count == 0); - /// - /// Commits the structural change into the project's native name registry so that - /// vavobj's ConnectByName can resolve the new pin slots. Matches the vendor UI's - /// OpcUaGroupPropPageWindow.ApplyChanges() and the working scripts/OpcGroup example, - /// which is the only officially-supported template for dynamic add-and-connect. - /// - private Result CommitStructuralChange(string opcFbPath) - { - var opcFbItem = _project.SafeItem(opcFbPath); - if (opcFbItem == null) + var wiringIncomplete = linksUnresolved > 0 || constructionsWithoutLinks > 0; + + var structureIncomplete = connectsThrew > 0 + || reshape.DisconnectsThrew > 0 + || reshape.NodesMissing > 0 + || reshape.NodesNotRestored > 0; + + var failed = wiringIncomplete || structureIncomplete; + var verdict = failed ? "with failures" : "without failures"; + + // The destructive half can succeed while the connects fail, and Execute still returns Ok, so + // this line is the only place that states what is on screen and what the operator does with it. + var nextStep = (wiringIncomplete, structureIncomplete) switch { - return Result.Fail($"OPC FB tree item not found for ApplyChange: {opcFbPath}"); - } + (false, false) => string.Empty, + (true, false) => "; the nodes are in the tree with links missing, close the project " + + "without saving, then re-capture the snapshot or repair the consumers", + _ => "; the tree is partially rebuilt, close the project without saving", + }; - opcFbItem.ApplyChange(); - return Result.Ok(); + logger.Write( + failed ? LogEventLevel.Error : LogEventLevel.Information, + "Rebuild of group '{GroupName}' finished " + verdict + ": removed={RemovedCount} " + + "constructed={ConstructedCount} noLinks={ConstructionsWithoutLinks} " + + "notRestored={NodesNotRestored}; disconnects issued={DisconnectsIssued} " + + "threw={DisconnectsThrew} nodesMissing={NodesMissing}; connects " + + "issued={ConnectsIssued} threw={ConnectsThrew} unresolved={LinksUnresolved}" + + nextStep, + groupName, + reshape.RemovedCount, + reshape.Constructions.Count, + constructionsWithoutLinks, + reshape.NodesNotRestored, + reshape.DisconnectsIssued, + reshape.DisconnectsThrew, + reshape.NodesMissing, + connectsIssued, + connectsThrew, + linksUnresolved); } /// @@ -178,29 +206,50 @@ private static void ResetScadaItemsMap(OpcUaProtocol protocol) /// /// Builds a for every resolvable link across all constructions. Links /// whose pins do not resolve or whose type is unknown fail in (already - /// logged) and are counted into ResolveFail rather than reaching the connect pass. + /// logged) and are counted into LinksUnresolved rather than reaching the connect pass. /// - private (List Commands, int ResolveFail) BuildCommands(IReadOnlyList constructions) + internal static (List Commands, int LinksUnresolved) BuildCommands( + IReadOnlyList constructions, + Func resolvePin, + ILogger logger) { var commands = new List(); - var resolveFail = 0; + var linksUnresolved = 0; foreach (var construction in constructions) { + var resolved = 0; + var unresolved = 0; + foreach (var link in construction.Links) { - var command = TryBuildCommand(link); + var command = TryBuildCommand(link, resolvePin, logger); if (command == null) { - resolveFail++; + unresolved++; continue; } commands.Add(command.Value); + resolved++; + } + + linksUnresolved += unresolved; + + if (unresolved == 0) + { + continue; } + + logger.Error( + "Node '{NodePath}': {LinkCount} links, {ResolvedCount} resolved, {UnresolvedCount} unresolved", + construction.Path, + construction.Links.Count, + resolved, + unresolved); } - return (commands, resolveFail); + return (commands, linksUnresolved); } /// @@ -208,30 +257,42 @@ private static void ResetScadaItemsMap(OpcUaProtocol protocol) /// . Returns null (an already-logged failure) when either pin /// is missing or the link type is unknown. /// - private ConnectCommand? TryBuildCommand(LinkEntry link) + private static ConnectCommand? TryBuildCommand( + LinkEntry link, + Func resolvePin, + ILogger logger) { - var localPin = _project.SafeItem(link.LocalPinPath); + var localPin = resolvePin(link.LocalPinPath); if (localPin == null) { - _logger.Error("Connect — local pin not found: {Path}", link.LocalPinPath); + logger.Error( + "Link not issued, local pin missing: {LocalPin} <-> {ExternalPin} ({LinkType})", + link.LocalPinPath, + link.ExternalPinPath, + link.LinkType); return null; } - var externalPin = _project.SafeItem(link.ExternalPinPath); + var externalPin = resolvePin(link.ExternalPinPath); if (externalPin == null) { - _logger.Error("Connect — external pin not found: {Path}", link.ExternalPinPath); + logger.Error( + "Link not issued, external pin missing: {LocalPin} <-> {ExternalPin} ({LinkType}); " + + "the snapshot may be stale or the consumer renamed", + link.LocalPinPath, + link.ExternalPinPath, + link.LinkType); return null; } var connect = BuildConnectAction(link, localPin, externalPin); if (connect == null) { - _logger.Error( - "Connect {LocalPin} ↔ {ExternalPin} — unknown link type '{LinkType}'", + logger.Error( + "Link not issued, unknown link type '{LinkType}': {LocalPin} <-> {ExternalPin}", + link.LinkType, link.LocalPinPath, - link.ExternalPinPath, - link.LinkType); + link.ExternalPinPath); return null; } diff --git a/NtoLib/OpcTreeManager/TreeOperations/ProjectSubtreeDisconnector.cs b/NtoLib/OpcTreeManager/TreeOperations/ProjectSubtreeDisconnector.cs index 067f26e..92043ed 100644 --- a/NtoLib/OpcTreeManager/TreeOperations/ProjectSubtreeDisconnector.cs +++ b/NtoLib/OpcTreeManager/TreeOperations/ProjectSubtreeDisconnector.cs @@ -5,6 +5,8 @@ using MasterSCADALib; +using NtoLib.OpcTreeManager.Entities; + using Serilog; namespace NtoLib.OpcTreeManager.TreeOperations; @@ -23,23 +25,36 @@ public ProjectSubtreeDisconnector(IProjectHlp project, ILogger logger) throw new ArgumentNullException(nameof(logger)); } - _logger = logger.ForContext(); + _logger = logger; } - public (int Total, int Success, int Fail) DisconnectSubtree(string nodePath) + public (int Issued, int Threw, int NodesMissing) DisconnectSubtree(string nodePath, Action onTreeMutationStarting) { - var node = _project.SafeItem(nodePath); + return RunDisconnectPass( + nodePath, + path => _project.SafeItem(path), + onTreeMutationStarting, + _logger); + } + + internal static (int Issued, int Threw, int NodesMissing) RunDisconnectPass( + string nodePath, + Func resolveNode, + Action onTreeMutationStarting, + ILogger logger) + { + var node = resolveNode(nodePath); if (node == null) { - _logger.Error("Disconnect — node not found: {NodePath}", nodePath); - return (1, 0, 1); + logger.Error("Remove '{NodePath}': node not found in the project, links not disconnected", nodePath); + return (0, 0, 1); } var allPins = node.EnumAllChilds(TreeMasks.AllPinKinds, 0); - var success = 0; - var fail = 0; + var issued = 0; + var threw = 0; foreach (var child in allPins) { @@ -48,18 +63,21 @@ public ProjectSubtreeDisconnector(IProjectHlp project, ILogger logger) continue; } - var (s, f) = DisconnectPinConnections(localPin); - success += s; - fail += f; + var (pinIssued, pinThrew) = DisconnectPinConnections(localPin, onTreeMutationStarting, logger); + issued += pinIssued; + threw += pinThrew; } - return (success + fail, success, fail); + return (issued, threw, 0); } - private (int Success, int Fail) DisconnectPinConnections(ITreePinHlp localPin) + private static (int Issued, int Threw) DisconnectPinConnections( + ITreePinHlp localPin, + Action onTreeMutationStarting, + ILogger logger) { - var success = 0; - var fail = 0; + var issued = 0; + var threw = 0; foreach (var mask in new[] { @@ -74,27 +92,42 @@ public ProjectSubtreeDisconnector(IProjectHlp project, ILogger logger) foreach (var externalPin in connections) { + onTreeMutationStarting(); + try { localPin.Disconnect(externalPin); - _logger.Debug( - "Disconnected {LocalPin} ← {ExternalPin}", + logger.Debug( + "Disconnect issued {LocalPin} <-> {ExternalPin} ({LinkType})", localPin.FullName, - externalPin.FullName); - success++; + externalPin.FullName, + LinkTypeOf(mask)); + issued++; } catch (Exception ex) { - _logger.Error( - "Disconnect {LocalPin} ← {ExternalPin} — {Message}", + logger.Error( + ex, + "Disconnect {LocalPin} <-> {ExternalPin} ({LinkType}) threw", localPin.FullName, externalPin.FullName, - ex.Message); - fail++; + LinkTypeOf(mask)); + threw++; } } } - return (success, fail); + return (issued, threw); + } + + private static string LinkTypeOf(EConnectionTypeMask mask) + { + return mask switch + { + EConnectionTypeMask.ctGenericPin => LinkTypes.DirectPin, + EConnectionTypeMask.ctGenericPout => LinkTypes.DirectPout, + EConnectionTypeMask.ctIConnect => LinkTypes.IConnect, + _ => mask.ToString(), + }; } } diff --git a/NtoLib/OpcTreeManager/TreeOperations/TreeReshaper.cs b/NtoLib/OpcTreeManager/TreeOperations/TreeReshaper.cs index d02a078..1bde548 100644 --- a/NtoLib/OpcTreeManager/TreeOperations/TreeReshaper.cs +++ b/NtoLib/OpcTreeManager/TreeOperations/TreeReshaper.cs @@ -7,6 +7,7 @@ using OpcUaClient.Client.Common.Data; using Serilog; +using Serilog.Events; namespace NtoLib.OpcTreeManager.TreeOperations; @@ -22,7 +23,10 @@ internal static class TreeReshaper /// /// Rebuilds 's Items to match at every /// nesting level, disconnecting removed subtrees and constructing missing ones pruned to the spec. - /// Returns the constructions to reconnect plus the disconnect (shrink) tally. + /// Returns the constructions to reconnect plus the removal tally. + /// is raised at each first-write point - the first + /// Disconnect of a subtree and every container swap - and never by the reads that precede + /// them; the caller makes it once-only. /// public static ReshapeResult Reshape( OpcUaScadaItem container, @@ -30,10 +34,22 @@ public static ReshapeResult Reshape( string containerPath, Func Links)> resolveChild, ISubtreeDisconnector disconnector, + Action onTreeMutationStarting, ILogger logger) { var result = new ReshapeResult(); - ApplyDesiredSpec(container, desired, containerPath, resolveChild, result, disconnector, logger); + + ApplyDesiredSpec( + container, + desired, + containerPath, + resolveChild, + result, + disconnector, + onTreeMutationStarting, + logger, + topLevel: true); + return result; } @@ -55,18 +71,34 @@ private static void ApplyDesiredSpec( Func Links)> resolveChild, ReshapeResult result, ISubtreeDisconnector disconnector, - ILogger logger) + Action onTreeMutationStarting, + ILogger logger, + bool topLevel) { var currentByName = container.Items.ToDictionary(i => i.Name, i => i, StringComparer.Ordinal); var desiredNames = new HashSet(desired.Select(s => s.Name), StringComparer.Ordinal); + // Counted per invocation, not off result: ReshapeResult accumulates across the recursive walk, + // so its fields hold a running total and cannot feed a per-container line. + var removedCount = 0; + var skippedCount = 0; + foreach (var name in currentByName.Keys.Where(n => !desiredNames.Contains(n)).ToList()) { - var (total, success, fail) = disconnector.DisconnectSubtree(containerPath + "." + name); - result.ShrinkCount++; - result.ShrinkTotal += total; - result.ShrinkSuccess += success; - result.ShrinkFail += fail; + var removedPath = containerPath + "." + name; + var (issued, threw, nodesMissing) = disconnector.DisconnectSubtree(removedPath, onTreeMutationStarting); + removedCount++; + result.RemovedCount++; + result.DisconnectsIssued += issued; + result.DisconnectsThrew += threw; + result.NodesMissing += nodesMissing; + + if (nodesMissing == 0) + { + logger.Information( + "Removed '{NodePath}': {IssuedCount} disconnects issued, {ThrewCount} threw", + removedPath, issued, threw); + } } var newItems = new List(desired.Count); @@ -83,7 +115,7 @@ private static void ApplyDesiredSpec( newItems.Add(existing); preservedCount++; - logger.Debug("BuildNewItems — preserved '{NodePath}' (links intact, no reconnect)", childPath); + logger.Debug("Preserved '{NodePath}'", childPath); if (spec.Children != null) { @@ -96,7 +128,9 @@ private static void ApplyDesiredSpec( : (null, Array.Empty()), result, disconnector, - logger); + onTreeMutationStarting, + logger, + topLevel: false); } continue; @@ -104,8 +138,14 @@ private static void ApplyDesiredSpec( if (childDto == null) { - logger.Warning( - "BuildNewItems — node '{NodePath}' not in current container and not in snapshot; skipped.", + skippedCount++; + result.NodesNotRestored++; + + // Only a top-level name is checked against the snapshot when the plan is built, so + // only there does an earlier Error already own this node. + logger.Write( + topLevel ? LogEventLevel.Debug : LogEventLevel.Error, + "Not restored '{NodePath}': not in the container, not in the snapshot", childPath); continue; } @@ -118,21 +158,32 @@ private static void ApplyDesiredSpec( var filteredLinks = LinkCollector.FilterForSubtree(childLinks, keptPaths); result.Constructions.Add(new Construction(childPath, filteredLinks)); - logger.Debug( - "BuildNewItems — newly constructed '{NodePath}' ({LinkCount} links to reconnect)", + if (filteredLinks.Count == 0) + { + logger.Error( + "Constructed '{NodePath}': no links to connect; the snapshot holds none under the " + + "kept nodes, so the node comes back unwired", + childPath); + continue; + } + + logger.Information( + "Constructed '{NodePath}': {LinkCount} links to connect", childPath, filteredLinks.Count); } - logger.Information( - "BuildNewItems at '{ContainerPath}' — desired={DesiredCount} preserved={PreservedCount} newlyConstructed={NewlyConstructedCount}", - containerPath, desired.Count, preservedCount, constructedCount); - if (ItemsReferenceEqual(container.Items, newItems)) { return; } + onTreeMutationStarting(); SwapContainerItems(container, newItems); + + logger.Information( + "Reshaped '{ContainerPath}': removed={RemovedCount} constructed={ConstructedCount} " + + "preserved={PreservedCount} skipped={SkippedCount}", + containerPath, removedCount, constructedCount, preservedCount, skippedCount); } private static bool ItemsReferenceEqual(IList current, List candidate) @@ -178,14 +229,18 @@ private static void SwapContainerItems(OpcUaScadaItem container, List /// Mutable accumulator for a pass, returned as its result: the -/// constructions to reconnect plus the disconnect (shrink) tally. The four shrink numbers are each -/// consumed by the execution summary — do not reduce them to one count. +/// constructions to reconnect plus the removal tally. A node absent from the project counts into +/// , never into . /// internal sealed class ReshapeResult { + public int RemovedCount { get; set; } + public int DisconnectsIssued { get; set; } + public int DisconnectsThrew { get; set; } + public int NodesMissing { get; set; } + public List Constructions { get; } = new(); - public int ShrinkCount { get; set; } - public int ShrinkTotal { get; set; } - public int ShrinkSuccess { get; set; } - public int ShrinkFail { get; set; } + + /// Desired nodes the walk could not construct, at any depth. + public int NodesNotRestored { get; set; } } diff --git a/Tests/OpcTreeManager/CapturingSink.cs b/Tests/OpcTreeManager/CapturingSink.cs index 094da25..ab75504 100644 --- a/Tests/OpcTreeManager/CapturingSink.cs +++ b/Tests/OpcTreeManager/CapturingSink.cs @@ -1,4 +1,5 @@ -using Serilog.Core; +using Serilog; +using Serilog.Core; using Serilog.Events; namespace Tests.OpcTreeManager; @@ -7,17 +8,23 @@ internal sealed class CapturingSink : ILogEventSink { public List Events { get; } = new(); - public IEnumerable Warnings => MessagesAt(LogEventLevel.Warning); - - public IEnumerable Debugs => MessagesAt(LogEventLevel.Debug); - public void Emit(LogEvent logEvent) { Events.Add(logEvent); } - private IEnumerable MessagesAt(LogEventLevel level) + /// A logger that captures every level into this sink. + public Logger ToLogger() + { + return new LoggerConfiguration() + .MinimumLevel.Verbose() + .WriteTo.Sink(this) + .CreateLogger(); + } + + /// Renders one structured property, the assertion target that survives template edits. + public static string Property(LogEvent logEvent, string name) { - return Events.Where(e => e.Level == level).Select(e => e.RenderMessage()); + return ((ScalarValue)logEvent.Properties[name]).Value?.ToString() ?? string.Empty; } } diff --git a/Tests/OpcTreeManager/Integration/ApplyDesiredSpecTests.cs b/Tests/OpcTreeManager/Integration/ApplyDesiredSpecTests.cs index 277ae20..d7d3b1a 100644 --- a/Tests/OpcTreeManager/Integration/ApplyDesiredSpecTests.cs +++ b/Tests/OpcTreeManager/Integration/ApplyDesiredSpecTests.cs @@ -11,6 +11,8 @@ using OpcUaClient.Client.Common.Data; +using Serilog.Events; + using Tests.OpcTreeManager.Integration.Fakes; using Xunit; @@ -100,9 +102,38 @@ private static void Invoke( ? (s.ScadaItem, s.Links) : (null, Array.Empty()), disconnector, + () => { }, Serilog.Core.Logger.None); constructions = result.Constructions; - shrinkCount = result.ShrinkCount; + shrinkCount = result.RemovedCount; + } + + private static CapturingSink ReshapeCapturingLog( + FakeSubtreeDisconnector disconnector, + OpcUaScadaItem container, + IReadOnlyList desired, + string containerPath, + IReadOnlyDictionary snapshot) + { + var sink = new CapturingSink(); + + TreeReshaper.Reshape( + container, + desired, + containerPath, + name => snapshot.TryGetValue(name, out var s) + ? (s.ScadaItem, s.Links) + : (null, Array.Empty()), + disconnector, + () => { }, + sink.ToLogger()); + + return sink; + } + + private static List EventsOf(CapturingSink sink, string messageTemplate) + { + return sink.Events.Where(e => e.MessageTemplate.Text == messageTemplate).ToList(); } // ────────────────────────────────────────────────────────────────────── @@ -422,4 +453,332 @@ public void PlannedRebuild_EmptyContainer_ReshapesFromTheBuiltPlan() container.Items.Select(i => i.Name).Should().Equal("A", "Valves"); constructions.Should().HaveCount(2, "a plan that builds must also construct"); } + + [Fact] + public void Reshape_NodeConstructedWithLinks_LogsOneInformationPerNode() + { + var container = ScadaItem("Group"); + + var desired = new[] { Leaf("A") }; + var snapshot = new Dictionary + { + ["A"] = Snapshot(DtoNode("A"), Link("Root.Group.A.Pin1", "Consumers.FB.Input")), + }; + + var sink = ReshapeCapturingLog(MakeDisconnector(), container, desired, "Root.Group", snapshot); + + var constructed = EventsOf(sink, "Constructed '{NodePath}': {LinkCount} links to connect").Single(); + + constructed.Level.Should().Be(LogEventLevel.Information); + CapturingSink.Property(constructed, "NodePath").Should().Be("Root.Group.A"); + CapturingSink.Property(constructed, "LinkCount").Should().Be("1"); + } + + [Fact] + public void Reshape_NodeConstructedWithoutLinks_IsRecordedAtErrorAndCounted() + { + var container = ScadaItem("Group"); + + var desired = new[] { Leaf("A"), Leaf("B") }; + var snapshot = new Dictionary + { + ["A"] = Snapshot(DtoNode("A"), Link("Root.Group.A.Pin1", "Consumers.FB.Input")), + ["B"] = Snapshot(DtoNode("B")), + }; + + var sink = new CapturingSink(); + + var result = TreeReshaper.Reshape( + container, + desired, + "Root.Group", + name => snapshot.TryGetValue(name, out var s) + ? (s.ScadaItem, s.Links) + : (null, Array.Empty()), + MakeDisconnector(), + () => { }, + sink.ToLogger()); + + var unwired = EventsOf( + sink, + "Constructed '{NodePath}': no links to connect; the snapshot holds none under the " + + "kept nodes, so the node comes back unwired").Single(); + + unwired.Level.Should().Be(LogEventLevel.Error); + CapturingSink.Property(unwired, "NodePath").Should().Be("Root.Group.B"); + result.Constructions.Count(c => c.Links.Count == 0) + .Should().Be(1, "only B came back with no links"); + result.Constructions.Should().HaveCount(2, "an unwired node is still constructed"); + } + + [Fact] + public void Reshape_ConstructOnlyPlan_FlagsTheMutationBeforeTheSwapAndNotEarlier() + { + var container = ScadaItem("Group"); + + var desired = new[] { Leaf("A"), Leaf("B") }; + var snapshot = new Dictionary + { + ["A"] = Snapshot(DtoNode("A")), + ["B"] = Snapshot(DtoNode("B")), + }; + + var itemCountsAtFlag = new List(); + + TreeReshaper.Reshape( + container, + desired, + "Root.Group", + name => snapshot.TryGetValue(name, out var s) + ? (s.ScadaItem, s.Links) + : (null, Array.Empty()), + MakeDisconnector(), + () => itemCountsAtFlag.Add(container.Items.Count), + Serilog.Core.Logger.None); + + container.Items.Should().HaveCount(2); + itemCountsAtFlag.Should().Equal( + new[] { 0 }, + "the construction loop only reads; the swap is the first write"); + } + + [Fact] + public void Reshape_ContainerAlreadyMatchesTheSpec_NeverFlagsAMutation() + { + var container = ScadaItem("Group", ScadaItem("A"), ScadaItem("B")); + + var desired = new[] { Leaf("A"), Leaf("B") }; + var snapshot = new Dictionary + { + ["A"] = Snapshot(DtoNode("A")), + ["B"] = Snapshot(DtoNode("B")), + }; + + var flagged = false; + + TreeReshaper.Reshape( + container, + desired, + "Root.Group", + name => snapshot.TryGetValue(name, out var s) + ? (s.ScadaItem, s.Links) + : (null, Array.Empty()), + MakeDisconnector(), + () => flagged = true, + Serilog.Core.Logger.None); + + flagged.Should().BeFalse("a run that swapped nothing left the tree untouched"); + } + + [Fact] + public void Reshape_RemovalDisconnects_FlagsTheMutationFromTheDisconnectorFirst() + { + var container = ScadaItem("Group", ScadaItem("Valves"), ScadaItem("Legacy")); + + var desired = new[] { Leaf("Valves") }; + var snapshot = new Dictionary + { + ["Valves"] = Snapshot(DtoNode("Valves")), + }; + + var itemCountsAtFlag = new List(); + + TreeReshaper.Reshape( + container, + desired, + "Root.Group", + name => snapshot.TryGetValue(name, out var s) + ? (s.ScadaItem, s.Links) + : (null, Array.Empty()), + MakeDisconnector().Returns(".Legacy", issued: 7, threw: 0, nodesMissing: 0), + () => itemCountsAtFlag.Add(container.Items.Count), + Serilog.Core.Logger.None); + + itemCountsAtFlag.Should().HaveCountGreaterThan(0, "a disconnect was issued"); + itemCountsAtFlag[0].Should().Be(2, "the first flag came from the disconnect, before the swap"); + } + + [Fact] + public void Reshape_NestedContainers_ReshapedLineCountsPerContainerNotRunningTotal() + { + var container = ScadaItem("Group", + ScadaItem("Valves", ScadaItem("VPG1"), ScadaItem("VPG4")), + ScadaItem("Legacy")); + + var desired = new[] { Branch("Valves", Leaf("VPG1")), Leaf("Ghost") }; + var snapshot = new Dictionary + { + ["Valves"] = Snapshot(DtoNode("Valves", DtoNode("VPG1"), DtoNode("VPG4"))), + }; + + var disconnector = MakeDisconnector(); + var sink = ReshapeCapturingLog(disconnector, container, desired, "Root.Group", snapshot); + + var reshaped = EventsOf( + sink, + "Reshaped '{ContainerPath}': removed={RemovedCount} constructed={ConstructedCount} " + + "preserved={PreservedCount} skipped={SkippedCount}"); + + reshaped.Should().HaveCount(2); + reshaped.Should().OnlyContain(e => e.Level == LogEventLevel.Information); + + var inner = reshaped.Single(e => CapturingSink.Property(e, "ContainerPath") == "Root.Group.Valves"); + CapturingSink.Property(inner, "RemovedCount").Should().Be("1"); + CapturingSink.Property(inner, "ConstructedCount").Should().Be("0"); + CapturingSink.Property(inner, "PreservedCount").Should().Be("1"); + CapturingSink.Property(inner, "SkippedCount").Should().Be("0"); + + var outer = reshaped.Single(e => CapturingSink.Property(e, "ContainerPath") == "Root.Group"); + CapturingSink.Property(outer, "RemovedCount").Should().Be("1"); + CapturingSink.Property(outer, "ConstructedCount").Should().Be("0"); + CapturingSink.Property(outer, "PreservedCount").Should().Be("1"); + CapturingSink.Property(outer, "SkippedCount").Should().Be("1"); + + var disconnects = EventsOf( + sink, + "Removed '{NodePath}': {IssuedCount} disconnects issued, {ThrewCount} threw"); + + disconnects.Should().OnlyContain(e => e.Level == LogEventLevel.Information); + disconnects.Select(e => CapturingSink.Property(e, "NodePath")) + .Should().BeEquivalentTo("Root.Group.Legacy", "Root.Group.Valves.VPG4"); + } + + [Fact] + public void Reshape_RemovedNodes_AccumulateTheDisconnectorTallyAndRecordEachNode() + { + var container = ScadaItem("Group", ScadaItem("Valves"), ScadaItem("Legacy")); + + var desired = new[] { Leaf("Valves") }; + var snapshot = new Dictionary + { + ["Valves"] = Snapshot(DtoNode("Valves")), + }; + + var disconnector = MakeDisconnector().Returns(".Legacy", issued: 7, threw: 2, nodesMissing: 0); + var sink = ReshapeCapturingLog(disconnector, container, desired, "Root.Group", snapshot); + + var removed = EventsOf( + sink, + "Removed '{NodePath}': {IssuedCount} disconnects issued, {ThrewCount} threw").Single(); + + CapturingSink.Property(removed, "NodePath").Should().Be("Root.Group.Legacy"); + CapturingSink.Property(removed, "IssuedCount").Should().Be("7"); + CapturingSink.Property(removed, "ThrewCount").Should().Be("2"); + } + + [Fact] + public void Reshape_RemovedNodeMissingFromProject_WritesNoRemovalRecordAndCountsItMissing() + { + var container = ScadaItem("Group", ScadaItem("Valves"), ScadaItem("Legacy")); + + var desired = new[] { Leaf("Valves") }; + var snapshot = new Dictionary + { + ["Valves"] = Snapshot(DtoNode("Valves")), + }; + + var disconnector = MakeDisconnector().Returns(".Legacy", issued: 0, threw: 0, nodesMissing: 1); + var sink = new CapturingSink(); + + var result = TreeReshaper.Reshape( + container, + desired, + "Root.Group", + name => snapshot.TryGetValue(name, out var s) + ? (s.ScadaItem, s.Links) + : (null, Array.Empty()), + disconnector, + () => { }, + sink.ToLogger()); + + EventsOf(sink, "Removed '{NodePath}': {IssuedCount} disconnects issued, {ThrewCount} threw") + .Should().BeEmpty(); + + result.NodesMissing.Should().Be(1); + result.DisconnectsThrew.Should().Be(0, "a missing node is not a failed disconnect"); + } + + [Fact] + public void Reshape_NestedNodeAbsentFromContainerAndSnapshot_IsRecordedAtError() + { + var container = ScadaItem("Group", ScadaItem("Valves", ScadaItem("VPG1"))); + + var desired = new[] { Branch("Valves", Leaf("VPG1"), Leaf("VPG2")) }; + + // Valves is in the container but absent from the snapshot, so its children resolve to a null DTO. + var snapshot = new Dictionary(); + + var sink = ReshapeCapturingLog(MakeDisconnector(), container, desired, "Root.Group", snapshot); + + var notRestored = EventsOf( + sink, + "Not restored '{NodePath}': not in the container, not in the snapshot").Single(); + + notRestored.Level.Should().Be(LogEventLevel.Error); + CapturingSink.Property(notRestored, "NodePath").Should().Be("Root.Group.Valves.VPG2"); + } + + [Fact] + public void Reshape_TopLevelNodeAbsentFromContainerAndSnapshot_StaysAtDebug() + { + var container = ScadaItem("Group", ScadaItem("A")); + + var desired = new[] { Leaf("A"), Leaf("Ghost") }; + var snapshot = new Dictionary + { + ["A"] = Snapshot(DtoNode("A")), + }; + + var sink = ReshapeCapturingLog(MakeDisconnector(), container, desired, "Root.Group", snapshot); + + var notRestored = EventsOf( + sink, + "Not restored '{NodePath}': not in the container, not in the snapshot").Single(); + + notRestored.Level.Should().Be(LogEventLevel.Debug, "the plan-time Error already names a top-level node"); + CapturingSink.Property(notRestored, "NodePath").Should().Be("Root.Group.Ghost"); + } + + [Fact] + public void Reshape_NodesSkippedAtBothLevels_AreCountedOntoTheResult() + { + var container = ScadaItem("Group", ScadaItem("Valves", ScadaItem("VPG1"))); + + var desired = new[] { Branch("Valves", Leaf("VPG1"), Leaf("VPG2")), Leaf("Ghost") }; + var snapshot = new Dictionary(); + + var result = TreeReshaper.Reshape( + container, + desired, + "Root.Group", + name => snapshot.TryGetValue(name, out var s) + ? (s.ScadaItem, s.Links) + : (null, Array.Empty()), + MakeDisconnector(), + () => { }, + new CapturingSink().ToLogger()); + + result.NodesNotRestored.Should().Be(2, "Ghost at the top level and VPG2 under Valves"); + } + + [Fact] + public void Reshape_ContainerAlreadyMatchesTheSpec_WritesNoReshapedLine() + { + var container = ScadaItem("Group", ScadaItem("A"), ScadaItem("B")); + + var desired = new[] { Leaf("A"), Leaf("B") }; + var snapshot = new Dictionary + { + ["A"] = Snapshot(DtoNode("A")), + ["B"] = Snapshot(DtoNode("B")), + }; + + var sink = ReshapeCapturingLog(MakeDisconnector(), container, desired, "Root.Group", snapshot); + + EventsOf( + sink, + "Reshaped '{ContainerPath}': removed={RemovedCount} constructed={ConstructedCount} " + + "preserved={PreservedCount} skipped={SkippedCount}") + .Should().BeEmpty("a container whose items were not swapped was not reshaped"); + } } diff --git a/Tests/OpcTreeManager/Integration/Fakes/FakeSubtreeDisconnector.cs b/Tests/OpcTreeManager/Integration/Fakes/FakeSubtreeDisconnector.cs index 1ecaf64..05a1b09 100644 --- a/Tests/OpcTreeManager/Integration/Fakes/FakeSubtreeDisconnector.cs +++ b/Tests/OpcTreeManager/Integration/Fakes/FakeSubtreeDisconnector.cs @@ -1,16 +1,46 @@ -using System.Collections.Generic; +using System; +using System.Collections.Generic; using NtoLib.OpcTreeManager.TreeOperations; namespace Tests.OpcTreeManager.Integration.Fakes; +/// +/// Records the paths it was asked to disconnect and returns a per-path tally the test sets up. +/// internal sealed class FakeSubtreeDisconnector : ISubtreeDisconnector { + private readonly Dictionary _resultsBySuffix = new(); + public List RecordedPaths { get; } = new(); - public (int Total, int Success, int Fail) DisconnectSubtree(string nodePath) + /// Keyed by path suffix so a test names the node, not the container it hangs under. + public FakeSubtreeDisconnector Returns(string pathSuffix, int issued, int threw, int nodesMissing) + { + _resultsBySuffix[pathSuffix] = (issued, threw, nodesMissing); + return this; + } + + /// Mirrors the real disconnector's flag point. + public (int Issued, int Threw, int NodesMissing) DisconnectSubtree(string nodePath, Action onTreeMutationStarting) { RecordedPaths.Add(nodePath); + + foreach (var entry in _resultsBySuffix) + { + if (!nodePath.EndsWith(entry.Key, StringComparison.Ordinal)) + { + continue; + } + + if (entry.Value.Issued > 0 || entry.Value.Threw > 0) + { + onTreeMutationStarting(); + } + + return entry.Value; + } + return (0, 0, 0); } } diff --git a/Tests/OpcTreeManager/Unit/BuildCommandsTests.cs b/Tests/OpcTreeManager/Unit/BuildCommandsTests.cs new file mode 100644 index 0000000..f567cf0 --- /dev/null +++ b/Tests/OpcTreeManager/Unit/BuildCommandsTests.cs @@ -0,0 +1,223 @@ +using System; +using System.Collections.Generic; +using System.Linq; + +using FluentAssertions; + +using MasterSCADA.Hlp; + +using NtoLib.OpcTreeManager.Entities; +using NtoLib.OpcTreeManager.TreeOperations; + +using Serilog.Events; + +using Xunit; + +namespace Tests.OpcTreeManager.Unit; + +public sealed class BuildCommandsTests +{ + [Fact] + public void BuildCommands_ExternalPinMissing_LineNamesBothEnds() + { + var sink = new CapturingSink(); + var pins = new Dictionary { ["Opc.CBr4.Kp"] = Pin() }; + + var (commands, unresolved) = PlanExecutor.BuildCommands( + Constructions(Link("Opc.CBr4.Kp", "Cabinet.CBr4.Kp", LinkTypes.IConnect)), + path => pins.TryGetValue(path, out var pin) ? pin : null, + sink.ToLogger()); + + commands.Should().BeEmpty(); + unresolved.Should().Be(1); + + var error = SingleLinkError(sink); + error.MessageTemplate.Text.Should().Be( + "Link not issued, external pin missing: {LocalPin} <-> {ExternalPin} ({LinkType}); " + + "the snapshot may be stale or the consumer renamed"); + CapturingSink.Property(error, "LocalPin").Should().Be("Opc.CBr4.Kp"); + CapturingSink.Property(error, "ExternalPin").Should().Be("Cabinet.CBr4.Kp"); + CapturingSink.Property(error, "LinkType").Should().Be(LinkTypes.IConnect); + } + + [Fact] + public void BuildCommands_LocalPinMissing_LineNamesBothEnds() + { + var sink = new CapturingSink(); + var pins = new Dictionary { ["Cabinet.CBr4.Kp"] = Pin() }; + + var (commands, unresolved) = PlanExecutor.BuildCommands( + Constructions(Link("Opc.CBr4.Kp", "Cabinet.CBr4.Kp", LinkTypes.DirectPin)), + path => pins.TryGetValue(path, out var pin) ? pin : null, + sink.ToLogger()); + + commands.Should().BeEmpty(); + unresolved.Should().Be(1); + + var error = SingleLinkError(sink); + error.MessageTemplate.Text.Should().Be( + "Link not issued, local pin missing: {LocalPin} <-> {ExternalPin} ({LinkType})"); + CapturingSink.Property(error, "LocalPin").Should().Be("Opc.CBr4.Kp"); + CapturingSink.Property(error, "ExternalPin").Should().Be("Cabinet.CBr4.Kp"); + CapturingSink.Property(error, "LinkType").Should().Be(LinkTypes.DirectPin); + } + + [Fact] + public void BuildCommands_UnknownLinkType_LineNamesTypeAndBothEnds() + { + var sink = new CapturingSink(); + var pins = new Dictionary + { + ["Opc.CBr4.Kp"] = Pin(), + ["Cabinet.CBr4.Kp"] = Pin(), + }; + + var (commands, unresolved) = PlanExecutor.BuildCommands( + Constructions(Link("Opc.CBr4.Kp", "Cabinet.CBr4.Kp", "sideways")), + path => pins.TryGetValue(path, out var pin) ? pin : null, + sink.ToLogger()); + + commands.Should().BeEmpty(); + unresolved.Should().Be(1); + + var error = SingleLinkError(sink); + error.MessageTemplate.Text.Should().Be( + "Link not issued, unknown link type '{LinkType}': {LocalPin} <-> {ExternalPin}"); + CapturingSink.Property(error, "LinkType").Should().Be("sideways"); + CapturingSink.Property(error, "LocalPin").Should().Be("Opc.CBr4.Kp"); + CapturingSink.Property(error, "ExternalPin").Should().Be("Cabinet.CBr4.Kp"); + } + + [Fact] + public void BuildCommands_BothPinsResolve_YieldsACommandAndLogsNoError() + { + var sink = new CapturingSink(); + var pins = new Dictionary + { + ["Opc.CBr4.Kp"] = Pin(), + ["Cabinet.CBr4.Kp"] = Pin(), + }; + + var (commands, unresolved) = PlanExecutor.BuildCommands( + Constructions(Link("Opc.CBr4.Kp", "Cabinet.CBr4.Kp", LinkTypes.IConnect)), + path => pins.TryGetValue(path, out var pin) ? pin : null, + sink.ToLogger()); + + unresolved.Should().Be(0); + commands.Should().ContainSingle(); + commands[0].LocalPinPath.Should().Be("Opc.CBr4.Kp"); + commands[0].ExternalPinPath.Should().Be("Cabinet.CBr4.Kp"); + sink.Events.Should().NotContain(e => e.Level == LogEventLevel.Error); + NodeTallies(sink).Should().BeEmpty("a node whose links all resolve has nothing to report"); + } + + [Fact] + public void BuildCommands_NodeWithNoResolvableLink_LogsTheNodeTally() + { + var sink = new CapturingSink(); + + var (commands, unresolved) = PlanExecutor.BuildCommands( + Constructions( + Link("Opc.CBr4.Kp", "Cabinet.CBr4.Kp", LinkTypes.IConnect), + Link("Opc.CBr4.Ki", "Cabinet.CBr4.Ki", LinkTypes.DirectPin)), + _ => null, + sink.ToLogger()); + + commands.Should().BeEmpty(); + unresolved.Should().Be(2); + + var tally = NodeTallies(sink).Single(); + tally.Level.Should().Be(LogEventLevel.Error); + tally.MessageTemplate.Text.Should().Be( + "Node '{NodePath}': {LinkCount} links, {ResolvedCount} resolved, {UnresolvedCount} unresolved", + "the tally is written before any connect is attempted, so both halves are build-time words"); + CapturingSink.Property(tally, "NodePath").Should().Be("Opc.CBr4"); + CapturingSink.Property(tally, "LinkCount").Should().Be("2"); + CapturingSink.Property(tally, "ResolvedCount").Should().Be("0"); + CapturingSink.Property(tally, "UnresolvedCount").Should().Be("2"); + } + + [Fact] + public void BuildCommands_SeveralConstructions_TallyCountsPerConstruction() + { + var sink = new CapturingSink(); + var pins = new Dictionary + { + ["Opc.CBr4.Kp"] = Pin(), + ["Cabinet.CBr4.Kp"] = Pin(), + }; + + var constructions = new[] + { + new TreeReshaper.Construction( + "Opc.CBr4", + new[] + { + Link("Opc.CBr4.Kp", "Cabinet.CBr4.Kp", LinkTypes.IConnect), + Link("Opc.CBr4.Ki", "Cabinet.CBr4.Ki", LinkTypes.DirectPin), + }), + new TreeReshaper.Construction( + "Opc.Water", + new[] { Link("Opc.Water.Flow", "Cabinet.Water.Flow", LinkTypes.DirectPin) }), + }; + + var (commands, unresolved) = PlanExecutor.BuildCommands( + constructions, + path => pins.TryGetValue(path, out var pin) ? pin : null, + sink.ToLogger()); + + commands.Should().ContainSingle(); + unresolved.Should().Be(2); + + var tallies = NodeTallies(sink); + tallies.Should().HaveCount(2); + + CapturingSink.Property(tallies[0], "NodePath").Should().Be("Opc.CBr4"); + CapturingSink.Property(tallies[0], "LinkCount").Should().Be("2"); + CapturingSink.Property(tallies[0], "ResolvedCount").Should().Be("1"); + CapturingSink.Property(tallies[0], "UnresolvedCount").Should().Be("1"); + + CapturingSink.Property(tallies[1], "NodePath").Should().Be("Opc.Water"); + CapturingSink.Property(tallies[1], "LinkCount").Should().Be("1"); + CapturingSink.Property(tallies[1], "ResolvedCount").Should().Be("0"); + CapturingSink.Property(tallies[1], "UnresolvedCount").Should().Be("1"); + } + + private static LinkEntry Link(string localPinPath, string externalPinPath, string linkType) + { + return new LinkEntry + { + LocalPinPath = localPinPath, + ExternalPinPath = externalPinPath, + LinkType = linkType, + }; + } + + private static IReadOnlyList Constructions(params LinkEntry[] links) + { + return new[] { new TreeReshaper.Construction("Opc.CBr4", links) }; + } + + /// + /// A pin stand-in: the build pass only checks it for null and captures it into a lambda it never + /// invokes, and the wrapper's constructor accepts a null COM pin. + /// + private static ITreePinHlp Pin() + { + return new ITreePinHlp(null!); + } + + private static LogEvent SingleLinkError(CapturingSink sink) + { + return sink.Events.Single(e => + e.Level == LogEventLevel.Error + && e.MessageTemplate.Text.StartsWith("Link not issued", StringComparison.Ordinal)); + } + + private static IReadOnlyList NodeTallies(CapturingSink sink) + { + return sink.Events + .Where(e => e.MessageTemplate.Text.StartsWith("Node '{NodePath}'", StringComparison.Ordinal)) + .ToList(); + } +} diff --git a/Tests/OpcTreeManager/Unit/ConnectRunnerTests.cs b/Tests/OpcTreeManager/Unit/ConnectRunnerTests.cs index 7588546..4491936 100644 --- a/Tests/OpcTreeManager/Unit/ConnectRunnerTests.cs +++ b/Tests/OpcTreeManager/Unit/ConnectRunnerTests.cs @@ -7,8 +7,6 @@ using NtoLib.OpcTreeManager.Entities; using NtoLib.OpcTreeManager.TreeOperations; -using Serilog; -using Serilog.Core; using Serilog.Events; using Xunit; @@ -20,15 +18,15 @@ namespace Tests.OpcTreeManager.Unit; /// seam with fakes, so the connect pass is exercised without a live IProjectHlp. There is no /// read-back verdict: GetConnections is blind after the structural commit (a connected link /// reads back as absent), so success is judged by the SCADA tree on reload. These tests assert only -/// what the pass actually knows — every command is issued, in order, a throwing command is caught and -/// counted while the rest still run, and the honest issued/threw tally is returned. +/// what the pass actually knows: every command is attempted, in order, a throwing command is logged at +/// Error with its exception while the rest still run, and the honest issued/threw tally is returned. /// public sealed class ConnectRunnerTests { [Fact] public void ConnectAll_IssuesEveryCommand_InOrder() { - var logger = MakeLogger(new CapturingSink()); + var logger = new CapturingSink().ToLogger(); var issued = new List(); var commands = new[] @@ -38,9 +36,9 @@ public void ConnectAll_IssuesEveryCommand_InOrder() MakeRecordingCommand(LinkTypes.IConnect, "Root.CH17.Kp", issued), }; - var (total, threw) = ConnectRunner.ConnectAll(commands, logger); + var (issuedCount, threw) = ConnectRunner.ConnectAll(commands, logger); - total.Should().Be(3); + issuedCount.Should().Be(3); threw.Should().Be(0); issued.Should().Equal("Root.CH17.Kp$", "Root.CH17.StatusWord", "Root.CH17.Kp"); } @@ -49,7 +47,7 @@ public void ConnectAll_IssuesEveryCommand_InOrder() public void ConnectAll_ThrowingCommand_IsCaughtCountedAndTheRestStillRun() { var sink = new CapturingSink(); - var logger = MakeLogger(sink); + var logger = sink.ToLogger(); var issued = new List(); var commands = new[] @@ -63,24 +61,32 @@ public void ConnectAll_ThrowingCommand_IsCaughtCountedAndTheRestStillRun() MakeRecordingCommand(LinkTypes.IConnect, "Root.C", issued), }; - var (total, threw) = ConnectRunner.ConnectAll(commands, logger); + var (issuedCount, threw) = ConnectRunner.ConnectAll(commands, logger); - total.Should().Be(3); + issuedCount.Should().Be(2, "a command that threw was not issued"); threw.Should().Be(1); // The throw does not abort the pass — the command after the throwing one still ran. issued.Should().Equal("Root.A", "Root.C"); - // A throw surfaces as exactly one Warning; there is no read-back Error path any more. - sink.Events.Count(e => e.Level == LogEventLevel.Warning).Should().Be(1); - sink.Events.Should().NotContain(e => e.Level == LogEventLevel.Error); + var errors = sink.Events.Where(e => e.Level == LogEventLevel.Error).ToList(); + errors.Should().ContainSingle(); + errors[0].Exception.Should().BeOfType(); + errors[0].MessageTemplate.Text.Should() + .Be("Connect {LocalPin} <-> {ExternalPin} ({LinkType}) threw"); + CapturingSink.Property(errors[0], "LocalPin").Should().Be("Root.B"); + CapturingSink.Property(errors[0], "ExternalPin").Should().Be("Ext.B"); + sink.Events.Should().NotContain(e => e.Level == LogEventLevel.Warning); + + sink.Events.Count(e => e.MessageTemplate.Text.StartsWith("Connect issued", StringComparison.Ordinal)) + .Should().Be(issuedCount, "the summary counter and the per-link records must agree"); } [Fact] public void ConnectAll_NoThrows_ReportsZeroThrewAndNoWarning() { var sink = new CapturingSink(); - var logger = MakeLogger(sink); + var logger = sink.ToLogger(); var commands = new[] { @@ -88,18 +94,18 @@ public void ConnectAll_NoThrows_ReportsZeroThrewAndNoWarning() MakeCommand(LinkTypes.DirectPin, "Root.CH17.Kp$"), }; - var (total, threw) = ConnectRunner.ConnectAll(commands, logger); + var (issuedCount, threw) = ConnectRunner.ConnectAll(commands, logger); - total.Should().Be(2); + issuedCount.Should().Be(2); threw.Should().Be(0); - sink.Events.Should().NotContain(e => e.Level == LogEventLevel.Warning); + sink.Events.Should().NotContain(e => e.Level == LogEventLevel.Error); } [Fact] - public void ConnectAll_EveryCommandThrows_TallyMatchesTotalAndOneWarningEach() + public void ConnectAll_EveryCommandThrows_IssuesNothingAndLogsOneErrorEach() { var sink = new CapturingSink(); - var logger = MakeLogger(sink); + var logger = sink.ToLogger(); var commands = new[] { @@ -107,21 +113,23 @@ public void ConnectAll_EveryCommandThrows_TallyMatchesTotalAndOneWarningEach() MakeThrowingCommand("Root.B"), }; - var (total, threw) = ConnectRunner.ConnectAll(commands, logger); + var (issuedCount, threw) = ConnectRunner.ConnectAll(commands, logger); - total.Should().Be(2); + issuedCount.Should().Be(0); threw.Should().Be(2); - sink.Events.Count(e => e.Level == LogEventLevel.Warning).Should().Be(2); + sink.Events.Count(e => e.Level == LogEventLevel.Error).Should().Be(2); + sink.Events.Should().NotContain(e => + e.MessageTemplate.Text.StartsWith("Connect issued", StringComparison.Ordinal)); } [Fact] public void ConnectAll_EmptyCommandSet_ReturnsZeroTally() { - var logger = MakeLogger(new CapturingSink()); + var logger = new CapturingSink().ToLogger(); - var (total, threw) = ConnectRunner.ConnectAll(Array.Empty(), logger); + var (issuedCount, threw) = ConnectRunner.ConnectAll(Array.Empty(), logger); - total.Should().Be(0); + issuedCount.Should().Be(0); threw.Should().Be(0); } @@ -151,12 +159,4 @@ private static ConnectCommand MakeThrowingCommand(string localPinPath) ExternalPinPath: "Ext." + localPinPath, Connect: () => throw new InvalidOperationException("COM no-op")); } - - private static Logger MakeLogger(CapturingSink sink) - { - return new LoggerConfiguration() - .MinimumLevel.Verbose() - .WriteTo.Sink(sink) - .CreateLogger(); - } } diff --git a/Tests/OpcTreeManager/Unit/ErrorFlattenTests.cs b/Tests/OpcTreeManager/Unit/ErrorFlattenTests.cs new file mode 100644 index 0000000..d9ec017 --- /dev/null +++ b/Tests/OpcTreeManager/Unit/ErrorFlattenTests.cs @@ -0,0 +1,36 @@ +using System.Linq; + +using FluentAssertions; + +using FluentResults; + +using NtoLib.OpcTreeManager.Facade; + +using Xunit; + +namespace Tests.OpcTreeManager.Unit; + +public sealed class ErrorFlattenTests +{ + [Fact] + public void Flatten_CausedByChain_YieldsEveryMessageOnceInOrder() + { + var root = new Error("snapshot not loaded") + .CausedBy(new Error("file missing").CausedBy(new Error("C:/tree.json"))); + + var messages = OpcTreeManagerService.Flatten(new[] { root }).Select(e => e.Message).ToList(); + + messages.Should().Equal("snapshot not loaded", "file missing", "C:/tree.json"); + } + + [Fact] + public void Flatten_SeveralRootsEachWithACause_YieldsEveryMessageInOrder() + { + var first = new Error("scan failed").CausedBy(new Error("config unreadable")); + var second = new Error("capture failed").CausedBy(new Error("path denied")); + + var messages = OpcTreeManagerService.Flatten(new[] { first, second }).Select(e => e.Message).ToList(); + + messages.Should().Equal("scan failed", "config unreadable", "capture failed", "path denied"); + } +} diff --git a/Tests/OpcTreeManager/Unit/LinkCollectorTests.cs b/Tests/OpcTreeManager/Unit/LinkCollectorTests.cs index 4f97a77..e70a110 100644 --- a/Tests/OpcTreeManager/Unit/LinkCollectorTests.cs +++ b/Tests/OpcTreeManager/Unit/LinkCollectorTests.cs @@ -1,10 +1,12 @@ -using FluentAssertions; +using System; + +using FluentAssertions; using MasterSCADALib; using NtoLib.OpcTreeManager.TreeOperations; -using Serilog; +using Serilog.Events; using Xunit; @@ -35,7 +37,7 @@ public void BuildLinks_IConnectAndDollarDirectPinToSameExternal_KeepsBoth() } [Fact] - public void BuildLinks_ExactDuplicateRows_CollapsedToOne() + public void BuildLinks_ExactDuplicateRows_CollapsedToOneWithNoWarning() { // The only rows dedup removes: identical (local, external, linkType) triples produced when // one pin matches more than one enumerated mask and the same wire surfaces twice. @@ -46,12 +48,15 @@ public void BuildLinks_ExactDuplicateRows_CollapsedToOne() [EConnectionTypeMask.ctGenericPin] = new[] { "Producer.Output", "Producer.Output" }, }); - var result = LinkCollector.BuildLinks(new[] { pin }, log: null); + var sink = new CapturingSink(); + + var result = LinkCollector.BuildLinks(new[] { pin }, sink.ToLogger()); result.Should().HaveCount(1); result[0].LocalPinPath.Should().Be("Root.Signal"); result[0].ExternalPinPath.Should().Be("Producer.Output"); result[0].LinkType.Should().Be("directPin"); + sink.Events.Should().NotContain(e => e.Level == LogEventLevel.Warning); } [Fact] @@ -167,25 +172,26 @@ public void BuildLinks_SiblingsWithDifferentExternals_BothKept() } [Fact] - public void BuildLinks_ExactDuplicateRows_LogsWarningNamingDroppedTriple() + public void CollectLinks_LogsThePerNodeTallyAtInformation() { - var pin = FakePin.FromMaskMap( - "Root.Signal", - new Dictionary - { - [EConnectionTypeMask.ctGenericPin] = new[] { "Producer.Output", "Producer.Output" }, - }); + var pins = new[] + { + FakePin.WithIConnect("Root.CBr4.Kp", "Plant.Kp"), + FakePin.WithDirectPin("Root.CBr4.Kp$", "Plant.Kp"), + }; var sink = new CapturingSink(); - var logger = BuildLogger(sink); - LinkCollector.BuildLinks(new[] { pin }, logger); + var result = LinkCollector.CollectLinks("Root.CBr4", pins, sink.ToLogger()); + + result.Should().HaveCount(2); - sink.Warnings.Should().ContainSingle(m => - m.Contains("Root.Signal") - && m.Contains("Producer.Output") - && m.Contains("directPin") - && m.Contains("dropped")); + var tally = sink.Events.Single(e => + e.MessageTemplate.Text == "Captured '{NodePath}': {LinkCount} links"); + + tally.Level.Should().Be(LogEventLevel.Information); + tally.Properties["NodePath"].ToString().Trim('"').Should().Be("Root.CBr4"); + tally.Properties["LinkCount"].ToString().Should().Be("2"); } [Fact] @@ -200,12 +206,12 @@ public void BuildLinks_IConnectWithMatchingDollarTwin_Silent() }; var sink = new CapturingSink(); - var logger = BuildLogger(sink); + var logger = sink.ToLogger(); LinkCollector.BuildLinks(pins, logger); - sink.Warnings.Should().NotContain(m => m.Contains("Capture check")); - sink.Debugs.Should().NotContain(m => m.Contains("Feedback-only")); + sink.Events.Should().NotContain(e => + e.MessageTemplate.Text.StartsWith("Iconnect ", StringComparison.Ordinal)); } [Fact] @@ -220,24 +226,25 @@ public void BuildLinks_IConnectWithNoInputSiblingRow_LogsWarning() }; var sink = new CapturingSink(); - var logger = BuildLogger(sink); + var logger = sink.ToLogger(); LinkCollector.BuildLinks(pins, logger); - sink.Warnings.Should().ContainSingle(m => - m.Contains("Capture check") - && m.Contains("Root.Setpoint") - && m.Contains("Plant.TemperatureSP") - && m.Contains("no captured link")); + var warning = sink.Events.Single(e => e.Level == LogEventLevel.Warning); + warning.MessageTemplate.Text.Should().Be( + "Iconnect {LocalPin} <-> {ExternalPin} captured without an input link on '{Sibling}'"); + CapturingSink.Property(warning, "LocalPin").Should().Be("Root.Setpoint"); + CapturingSink.Property(warning, "ExternalPin").Should().Be("Plant.TemperatureSP"); + CapturingSink.Property(warning, "Sibling").Should().Be("Root.Setpoint$"); } [Fact] public void BuildLinks_IConnectWithDollarTwinToDifferentExternal_LogsDebugNotWarning() { // The Setpoint feedback-only case: the $ directPin sibling IS captured, but routes to a - // DIFFERENT external (Setpoint$ → …Setpoints.Setpoint) than the iconnect (Setpoint → - // …TemperatureSP). The input half is present, so this is the expected PinPout shape — Debug, - // NOT a Warning. + // DIFFERENT external (Setpoint$ to Setpoints.Setpoint) than the iconnect (Setpoint to + // TemperatureSP). The input half is present; known-issue 11 reads this shape as the fold + // signature. var pins = new[] { FakePin.WithIConnect("Root.Setpoint", "Plant.TemperatureSP"), @@ -245,23 +252,21 @@ public void BuildLinks_IConnectWithDollarTwinToDifferentExternal_LogsDebugNotWar }; var sink = new CapturingSink(); - var logger = BuildLogger(sink); + var logger = sink.ToLogger(); LinkCollector.BuildLinks(pins, logger); - sink.Warnings.Should().NotContain(m => m.Contains("Capture check")); - sink.Debugs.Should().ContainSingle(m => - m.Contains("Feedback-only") - && m.Contains("Root.Setpoint") - && m.Contains("Plant.TemperatureSP")); - } - - private static ILogger BuildLogger(CapturingSink sink) - { - return new LoggerConfiguration() - .MinimumLevel.Verbose() - .WriteTo.Sink(sink) - .CreateLogger(); + sink.Events.Should().NotContain(e => e.Level == LogEventLevel.Warning); + + var debug = sink.Events.Single(e => + e.MessageTemplate.Text.StartsWith("Iconnect ", StringComparison.Ordinal)); + debug.Level.Should().Be(LogEventLevel.Debug); + debug.MessageTemplate.Text.Should().Be( + "Iconnect {LocalPin} <-> {ExternalPin}: input sibling '{Sibling}' captured to '{SiblingExternal}'"); + CapturingSink.Property(debug, "LocalPin").Should().Be("Root.Setpoint"); + CapturingSink.Property(debug, "ExternalPin").Should().Be("Plant.TemperatureSP"); + CapturingSink.Property(debug, "Sibling").Should().Be("Root.Setpoint$"); + CapturingSink.Property(debug, "SiblingExternal").Should().Be("Plant.Setpoints.Setpoint"); } private static class FakePin diff --git a/Tests/OpcTreeManager/Unit/OpcLoggerFactoryTests.cs b/Tests/OpcTreeManager/Unit/OpcLoggerFactoryTests.cs new file mode 100644 index 0000000..043a5b0 --- /dev/null +++ b/Tests/OpcTreeManager/Unit/OpcLoggerFactoryTests.cs @@ -0,0 +1,69 @@ +using System; +using System.IO; + +using FluentAssertions; + +using NtoLib.OpcTreeManager.Logging; + +using Xunit; + +namespace Tests.OpcTreeManager.Unit; + +public sealed class OpcLoggerFactoryTests +{ + [Fact] + public void Build_OutputTemplate_OmitsSourceContext() + { + var path = TempPath(); + + try + { + using (var logger = OpcLoggerFactory.Build(path)) + { + logger.ForContext().Information("Runtime entered"); + } + + var firstLine = File.ReadAllLines(path)[0]; + + firstLine.Should().MatchRegex(@"^\S+ \[INF\] Runtime entered$"); + } + finally + { + File.Delete(path); + } + } + + [Fact] + public void Build_UnwritablePath_ReturnsLoggerThatWritesNothing() + { + var blocker = TempPath(); + File.WriteAllText(blocker, "not a directory"); + var unwritablePath = Path.Combine(blocker, "sub", "opc-tree-manager.log"); + + try + { + var logger = OpcLoggerFactory.Build(unwritablePath); + + logger.Should().NotBeNull(); + + Action write = () => + { + logger.Information("Runtime entered"); + logger.Dispose(); + }; + + write.Should().NotThrow(); + Directory.Exists(blocker).Should().BeFalse(); + File.ReadAllText(blocker).Should().Be("not a directory"); + } + finally + { + File.Delete(blocker); + } + } + + private static string TempPath() + { + return Path.Combine(Path.GetTempPath(), $"opc-logger-factory-{Guid.NewGuid():N}.log"); + } +} diff --git a/Tests/OpcTreeManager/Unit/PlanBuilderValidationTests.cs b/Tests/OpcTreeManager/Unit/PlanBuilderValidationTests.cs index ee8c502..c949718 100644 --- a/Tests/OpcTreeManager/Unit/PlanBuilderValidationTests.cs +++ b/Tests/OpcTreeManager/Unit/PlanBuilderValidationTests.cs @@ -7,7 +7,6 @@ using NtoLib.OpcTreeManager.Entities; using NtoLib.OpcTreeManager.Facade; -using Serilog; using Serilog.Events; using Xunit; @@ -114,7 +113,7 @@ public void Build_EmptyContainerAndPartialSnapshot_BuildsPlanAndLogsEveryMiss() Node("Valves", Node("VPG1"))); var sink = new CapturingSink(); - using var logger = new LoggerConfiguration().MinimumLevel.Verbose().WriteTo.Sink(sink).CreateLogger(); + using var logger = sink.ToLogger(); var result = PlanBuilder.Build( opcFbPath: OpcFbPath, @@ -134,7 +133,94 @@ public void Build_EmptyContainerAndPartialSnapshot_BuildsPlanAndLogsEveryMiss() var errors = sink.Events.Where(e => e.Level == LogEventLevel.Error).ToList(); errors.Should().HaveCount(2, "each unrestorable node is reported once"); errors.Select(e => e.Properties["NodeName"].ToString().Trim('"')).Should() - .BeEquivalentTo(new[] { "Cameras", "Heaters" }, "each error names the node it is about"); + .BeEquivalentTo(new[] { "Cameras", "Heaters" }, + "each error names the node it is about"); + errors.Should().OnlyContain(e => e.Properties["GroupName"].ToString().Trim('"') == GroupName); + } + + [Fact] + public void Build_NonEmptyContainerAndUnrestorableNode_LogsItAtPlanTime() + { + var config = ConfigFor( + new NodeSpec("Valves", null), + new NodeSpec("Heaters", null)); + + var snapshot = SnapshotOf( + Node("Valves", Node("VPG1"))); + + var sink = new CapturingSink(); + using var logger = sink.ToLogger(); + + var result = PlanBuilder.Build( + opcFbPath: OpcFbPath, + groupName: GroupName, + targetProject: Project, + config: config, + snapshot: snapshot, + currentTopLevelNames: new List { "Cameras" }, + logger: logger); + + result.IsSuccess.Should().BeTrue("a non-empty group still rebuilds what the snapshot covers"); + + var errors = sink.Events.Where(e => e.Level == LogEventLevel.Error).ToList(); + errors.Should().HaveCount(1, "only the node absent from both the group and the snapshot"); + errors[0].Properties["NodeName"].ToString().Trim('"').Should().Be("Heaters"); + errors[0].Properties["GroupName"].ToString().Trim('"').Should().Be(GroupName); + } + + [Fact] + public void Build_PlanLine_NamesRemovedConstructedAndPreservedNodes() + { + var config = ConfigFor( + new NodeSpec("Valves", null), + new NodeSpec("Cameras", null), + new NodeSpec("Heaters", null)); + + var snapshot = new Dictionary + { + ["Valves"] = new NodeSnapshot { ScadaItem = Node("Valves", Node("VPG1")), Links = LinksOf(3) }, + ["Cameras"] = new NodeSnapshot { ScadaItem = Node("Cameras"), Links = LinksOf(2) }, + }; + + var sink = new CapturingSink(); + using var logger = sink.ToLogger(); + + var result = PlanBuilder.Build( + opcFbPath: OpcFbPath, + groupName: GroupName, + targetProject: Project, + config: config, + snapshot: snapshot, + currentTopLevelNames: new List { "Valves", "Axes" }, + logger: logger); + + result.IsSuccess.Should().BeTrue("the plan is buildable"); + + var planLine = sink.Events.Single(e => e.MessageTemplate.Text.StartsWith("Plan for group")); + + planLine.Level.Should().Be(LogEventLevel.Information); + NamesIn(planLine, "RemoveNodes").Should() + .Equal(new[] { "Axes" }, "the group holds a node the project does not"); + NamesIn(planLine, "ConstructNodes").Should() + .Equal(new[] { "Cameras" }, "Heaters is desired but the snapshot cannot restore it"); + NamesIn(planLine, "PreserveNodes").Should() + .Equal(new[] { "Valves" }, "Valves is already in the group"); + planLine.Properties["LinkCount"].ToString().Should().Be("2", "only constructed nodes bring links"); + } + + private static IReadOnlyList NamesIn(LogEvent logEvent, string propertyName) + { + return ((SequenceValue)logEvent.Properties[propertyName]) + .Elements + .Select(e => e.ToString().Trim('"')) + .ToList(); + } + + private static IReadOnlyList LinksOf(int count) + { + return Enumerable.Range(0, count) + .Select(i => new LinkEntry { LocalPinPath = "local" + i, ExternalPinPath = "external" + i }) + .ToList(); } [Fact] diff --git a/Tests/OpcTreeManager/Unit/ProjectSubtreeDisconnectorTests.cs b/Tests/OpcTreeManager/Unit/ProjectSubtreeDisconnectorTests.cs new file mode 100644 index 0000000..2a0f2d4 --- /dev/null +++ b/Tests/OpcTreeManager/Unit/ProjectSubtreeDisconnectorTests.cs @@ -0,0 +1,62 @@ +using System.Linq; + +using FluentAssertions; + +using NtoLib.OpcTreeManager.TreeOperations; + +using Serilog.Events; + +using Xunit; + +namespace Tests.OpcTreeManager.Unit; + +public sealed class ProjectSubtreeDisconnectorTests +{ + [Fact] + public void RunDisconnectPass_NodeMissingFromProject_CountsOneMissingNodeAndNoFailedLink() + { + var sink = new CapturingSink(); + + var (issued, threw, nodesMissing) = ProjectSubtreeDisconnector.RunDisconnectPass( + "Root.Group.Legacy", + _ => null, + () => { }, + sink.ToLogger()); + + issued.Should().Be(0); + threw.Should().Be(0, "no disconnect was attempted, so none could fail"); + nodesMissing.Should().Be(1); + } + + [Fact] + public void RunDisconnectPass_NodeMissingFromProject_NeverFlagsAMutation() + { + var flagged = false; + + ProjectSubtreeDisconnector.RunDisconnectPass( + "Root.Group.Legacy", + _ => null, + () => flagged = true, + new CapturingSink().ToLogger()); + + flagged.Should().BeFalse(); + } + + [Fact] + public void RunDisconnectPass_NodeMissingFromProject_NamesTheNodeAtError() + { + var sink = new CapturingSink(); + + ProjectSubtreeDisconnector.RunDisconnectPass( + "Root.Group.Legacy", + _ => null, + () => { }, + sink.ToLogger()); + + var error = sink.Events.Single(e => e.Level == LogEventLevel.Error); + + error.MessageTemplate.Text.Should() + .Be("Remove '{NodePath}': node not found in the project, links not disconnected"); + ((ScalarValue)error.Properties["NodePath"]).Value.Should().Be("Root.Group.Legacy"); + } +} diff --git a/Tests/OpcTreeManager/Unit/RebuildSummaryTests.cs b/Tests/OpcTreeManager/Unit/RebuildSummaryTests.cs new file mode 100644 index 0000000..68a80a3 --- /dev/null +++ b/Tests/OpcTreeManager/Unit/RebuildSummaryTests.cs @@ -0,0 +1,173 @@ +using System; +using System.Linq; + +using FluentAssertions; + +using NtoLib.OpcTreeManager.Entities; +using NtoLib.OpcTreeManager.TreeOperations; + +using Serilog.Events; + +using Xunit; + +namespace Tests.OpcTreeManager.Unit; + +public sealed class RebuildSummaryTests +{ + [Fact] + public void LogRebuildFinished_NothingFailed_IsInformationAndSaysSo() + { + var sink = new CapturingSink(); + var reshape = new ReshapeResult { RemovedCount = 2, DisconnectsIssued = 9 }; + + PlanExecutor.LogRebuildFinished( + groupName: "MBE", + reshape: reshape, + connectsIssued: 14, + connectsThrew: 0, + linksUnresolved: 0, + logger: sink.ToLogger()); + + var summary = Summary(sink); + + summary.Level.Should().Be(LogEventLevel.Information); + summary.MessageTemplate.Text.Should().StartWith( + "Rebuild of group '{GroupName}' finished without failures:"); + summary.MessageTemplate.Text.Should().EndWith("unresolved={LinksUnresolved}"); + CapturingSink.Property(summary, "GroupName").Should().Be("MBE"); + CapturingSink.Property(summary, "RemovedCount").Should().Be("2"); + CapturingSink.Property(summary, "DisconnectsIssued").Should().Be("9"); + CapturingSink.Property(summary, "ConnectsIssued").Should().Be("14"); + } + + [Fact] + public void LogRebuildFinished_LinksUnresolved_IsErrorAndSaysTheRunDidNotSucceed() + { + var sink = new CapturingSink(); + + PlanExecutor.LogRebuildFinished( + groupName: "MBE", + reshape: new ReshapeResult(), + connectsIssued: 0, + connectsThrew: 0, + linksUnresolved: 119, + logger: sink.ToLogger()); + + var summary = Summary(sink); + + summary.Level.Should().Be(LogEventLevel.Error); + summary.MessageTemplate.Text.Should().StartWith( + "Rebuild of group '{GroupName}' finished with failures:"); + summary.MessageTemplate.Text.Should().EndWith( + "; the nodes are in the tree with links missing, close the project without saving, " + + "then re-capture the snapshot or repair the consumers"); + CapturingSink.Property(summary, "LinksUnresolved").Should().Be("119"); + } + + [Fact] + public void LogRebuildFinished_NodeMissingAndLinksUnresolved_TellsTheStructuralAction() + { + var sink = new CapturingSink(); + + PlanExecutor.LogRebuildFinished( + groupName: "MBE", + reshape: new ReshapeResult { RemovedCount = 1, NodesMissing = 1 }, + connectsIssued: 0, + connectsThrew: 0, + linksUnresolved: 119, + logger: sink.ToLogger()); + + Summary(sink).MessageTemplate.Text.Should().EndWith( + "; the tree is partially rebuilt, close the project without saving"); + } + + [Fact] + public void LogRebuildFinished_NodeMissingFromProject_IsError() + { + var sink = new CapturingSink(); + + PlanExecutor.LogRebuildFinished( + groupName: "MBE", + reshape: new ReshapeResult { RemovedCount = 1, NodesMissing = 1 }, + connectsIssued: 0, + connectsThrew: 0, + linksUnresolved: 0, + logger: sink.ToLogger()); + + var summary = Summary(sink); + + summary.Level.Should().Be(LogEventLevel.Error); + CapturingSink.Property(summary, "NodesMissing").Should().Be("1"); + } + + [Fact] + public void LogRebuildFinished_NodeNotRestored_IsError() + { + var sink = new CapturingSink(); + + PlanExecutor.LogRebuildFinished( + groupName: "MBE", + reshape: new ReshapeResult { NodesNotRestored = 1 }, + connectsIssued: 0, + connectsThrew: 0, + linksUnresolved: 0, + logger: sink.ToLogger()); + + var summary = Summary(sink); + + summary.Level.Should().Be(LogEventLevel.Error); + summary.MessageTemplate.Text.Should().StartWith( + "Rebuild of group '{GroupName}' finished with failures:"); + CapturingSink.Property(summary, "NodesNotRestored").Should().Be("1"); + } + + [Fact] + public void LogRebuildFinished_ConstructionWithoutLinks_IsError() + { + var sink = new CapturingSink(); + var reshape = new ReshapeResult(); + reshape.Constructions.Add(new TreeReshaper.Construction("Root.Group.A", Array.Empty())); + reshape.Constructions.Add(new TreeReshaper.Construction("Root.Group.B", Array.Empty())); + + PlanExecutor.LogRebuildFinished( + groupName: "MBE", + reshape: reshape, + connectsIssued: 0, + connectsThrew: 0, + linksUnresolved: 0, + logger: sink.ToLogger()); + + var summary = Summary(sink); + + summary.Level.Should().Be(LogEventLevel.Error); + summary.MessageTemplate.Text.Should().StartWith( + "Rebuild of group '{GroupName}' finished with failures:"); + summary.MessageTemplate.Text.Should().EndWith("repair the consumers"); + CapturingSink.Property(summary, "ConstructionsWithoutLinks").Should().Be("2"); + } + + [Fact] + public void LogRebuildFinished_ConnectThrew_IsError() + { + var sink = new CapturingSink(); + + PlanExecutor.LogRebuildFinished( + groupName: "MBE", + reshape: new ReshapeResult(), + connectsIssued: 3, + connectsThrew: 1, + linksUnresolved: 0, + logger: sink.ToLogger()); + + var summary = Summary(sink); + + summary.Level.Should().Be(LogEventLevel.Error); + summary.MessageTemplate.Text.Should().EndWith( + "; the tree is partially rebuilt, close the project without saving"); + } + + private static LogEvent Summary(CapturingSink sink) + { + return sink.Events.Single(); + } +} diff --git a/Tests/OpcTreeManager/Unit/SnapshotSummaryTests.cs b/Tests/OpcTreeManager/Unit/SnapshotSummaryTests.cs new file mode 100644 index 0000000..288d133 --- /dev/null +++ b/Tests/OpcTreeManager/Unit/SnapshotSummaryTests.cs @@ -0,0 +1,74 @@ +using System.Collections.Generic; +using System.Linq; + +using FluentAssertions; + +using NtoLib.OpcTreeManager.Entities; +using NtoLib.OpcTreeManager.Facade; + +using Serilog.Events; + +using Xunit; + +namespace Tests.OpcTreeManager.Unit; + +public sealed class SnapshotSummaryTests +{ + [Fact] + public void LogSnapshotWritten_EveryNodeHasLinks_IsInformation() + { + var sink = new CapturingSink(); + + OpcTreeManagerService.LogSnapshotWritten( + groupName: "MBE", + treeJsonPath: @"C:\Config\tree.json", + snapshot: Snapshot(("CBr4", 2), ("Water", 1)), + logger: sink.ToLogger()); + + var summary = sink.Events.Single(); + + summary.Level.Should().Be(LogEventLevel.Information); + summary.MessageTemplate.Text.Should().EndWith("{NodesWithoutLinks} without links"); + CapturingSink.Property(summary, "NodeCount").Should().Be("2"); + CapturingSink.Property(summary, "LinkCount").Should().Be("3"); + CapturingSink.Property(summary, "NodesWithoutLinks").Should().Be("0"); + } + + [Fact] + public void LogSnapshotWritten_NodeWithoutLinks_IsErrorAndCounted() + { + var sink = new CapturingSink(); + + OpcTreeManagerService.LogSnapshotWritten( + groupName: "MBE", + treeJsonPath: @"C:\Config\tree.json", + snapshot: Snapshot(("CBr4", 2), ("Water", 0)), + logger: sink.ToLogger()); + + var summary = sink.Events.Single(); + + summary.Level.Should().Be(LogEventLevel.Error); + summary.MessageTemplate.Text.Should().EndWith( + "; the next rebuild constructs those nodes unwired"); + CapturingSink.Property(summary, "NodesWithoutLinks").Should().Be("1"); + } + + private static Dictionary Snapshot(params (string Name, int LinkCount)[] nodes) + { + return nodes.ToDictionary( + node => node.Name, + node => new NodeSnapshot { Links = Links(node.Name, node.LinkCount) }); + } + + private static IReadOnlyList Links(string nodeName, int count) + { + return Enumerable.Range(0, count) + .Select(i => new LinkEntry + { + LocalPinPath = $"Opc.{nodeName}.Pin{i}", + ExternalPinPath = $"Cabinet.{nodeName}.Pin{i}", + LinkType = LinkTypes.DirectPin, + }) + .ToList(); + } +}