From 8710b13f93581c44399eff1992fd1fc557c8473e Mon Sep 17 00:00:00 2001 From: Oleg <18466855+EvaTheSalmon@users.noreply.github.com> Date: Tue, 22 Sep 2026 18:29:48 +0300 Subject: [PATCH] fix(opctreemanager): make the log a technical record The log claimed outcomes it could not observe and hid the ones it could. A run that logged errors still ended with "Deferred execution completed successfully", and the operator had no way to see which nodes came back unwired; the 119 unresolved links of the 2026-09-22 run were only findable by scripting over tree.json. The deferred pass cannot raise the Failed pin, because the host replaces the FB instance between runtime cycles, so the log is the only channel and every line now states exactly what the code observed: - one rebuild summary with the verdict taken from the counters, and an action clause naming what the operator should do - a per-node tally at Error: links, resolved, unresolved - the snapshot line carries node count, link count and the file's write date - the plan is stated before it runs, not after - a construction with no links says so instead of passing silently - connects report issued and threw; "issued" is the strongest claim available, because connections cannot be read back in-process (known_issues/11) - errors cross the service as errors, with the CausedBy chain flattened into the message instead of the FluentResults wrapper text - SourceContext left the log template: it read PlanExecutor on 1231 of 1233 Debug lines --- Docs/opc-tree-manager.md | 240 ++++++- ...-opctreemanager-log-as-technical-record.md | 591 ++++++++++++++++++ NtoLib/OpcTreeManager/Entities/LinkEntry.cs | 2 +- .../Facade/OpcTreeManagerService.cs | 142 ++++- NtoLib/OpcTreeManager/Facade/PlanBuilder.cs | 95 +-- .../Logging/OpcLoggerFactory.cs | 4 +- NtoLib/OpcTreeManager/OpcTreeManagerFB.cs | 19 +- .../TreeOperations/ConnectRunner.cs | 22 +- .../TreeOperations/DeferredExecutor.cs | 69 +- .../TreeOperations/ISubtreeDisconnector.cs | 9 +- .../TreeOperations/LinkCollector.cs | 57 +- .../TreeOperations/PlanExecutor.cs | 195 ++++-- .../ProjectSubtreeDisconnector.cs | 79 ++- .../TreeOperations/TreeReshaper.cs | 103 ++- Tests/OpcTreeManager/CapturingSink.cs | 21 +- .../Integration/ApplyDesiredSpecTests.cs | 361 ++++++++++- .../Fakes/FakeSubtreeDisconnector.cs | 34 +- .../OpcTreeManager/Unit/BuildCommandsTests.cs | 223 +++++++ .../OpcTreeManager/Unit/ConnectRunnerTests.cs | 66 +- .../OpcTreeManager/Unit/ErrorFlattenTests.cs | 36 ++ .../OpcTreeManager/Unit/LinkCollectorTests.cs | 93 +-- .../Unit/OpcLoggerFactoryTests.cs | 69 ++ .../Unit/PlanBuilderValidationTests.cs | 92 ++- .../Unit/ProjectSubtreeDisconnectorTests.cs | 62 ++ .../Unit/RebuildSummaryTests.cs | 173 +++++ .../Unit/SnapshotSummaryTests.cs | 74 +++ 26 files changed, 2566 insertions(+), 365 deletions(-) create mode 100644 Docs/plans/completed/20260921-opctreemanager-log-as-technical-record.md create mode 100644 Tests/OpcTreeManager/Unit/BuildCommandsTests.cs create mode 100644 Tests/OpcTreeManager/Unit/ErrorFlattenTests.cs create mode 100644 Tests/OpcTreeManager/Unit/OpcLoggerFactoryTests.cs create mode 100644 Tests/OpcTreeManager/Unit/ProjectSubtreeDisconnectorTests.cs create mode 100644 Tests/OpcTreeManager/Unit/RebuildSummaryTests.cs create mode 100644 Tests/OpcTreeManager/Unit/SnapshotSummaryTests.cs 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(); + } +}