mirror of
https://github.com/okieselbach/AutopilotMonitor.git
synced 2026-10-30 15:35:48 +00:00
Compare commits
46 Commits
| Author | SHA1 | Date | |
|---|---|---|---|
| fec4bcc6c5 | |||
| 6ce2176aa0 | |||
| 1fe4e6711e | |||
| 61947c416c | |||
| 25c65f1837 | |||
| eb287248c6 | |||
| 738a349710 | |||
| 73525f1d34 | |||
| b7c6b11909 | |||
| 74d489b51e | |||
| dff69b4d73 | |||
| 9c654983d1 | |||
| 0bc82fd719 | |||
| 783b390448 | |||
| 5c75155293 | |||
| 7588286787 | |||
| 0d6797275c | |||
| 17f98f5c56 | |||
| f53fdf86f6 | |||
| b57f9312ce | |||
| 5136d33c2c | |||
| 5589ca42c7 | |||
| 8f9cf6e153 | |||
| eebbc895c8 | |||
| 7d19a71230 | |||
| 77569e0dfb | |||
| 7a457b5d63 | |||
| 1ea366c419 | |||
| bba8a0d6b4 | |||
| 6abe450388 | |||
| fe193268ea | |||
| ef6cf8e3f4 | |||
| e06a687ddd | |||
| 1ee13de7a8 | |||
| 8cb061784e | |||
| 7fd4a4fe62 | |||
| 8929f1c5b4 | |||
| ff04137d0a | |||
| ff8bc7927f | |||
| 8a53c6233f | |||
| f3a4ce6ed8 | |||
| 42dae1b38c | |||
| b58830ddcb | |||
| caac165172 | |||
| d25f2286b4 | |||
| 1dd4a477c5 |
+1
-1
Submodule .claude/commands updated: c67c475a62...c5604145b3
@@ -1,13 +1,50 @@
|
||||
name: Bootstrap script gates
|
||||
|
||||
# Quality gate for the customer-facing PowerShell scripts, factored out so it exists
|
||||
# once and both callers run the identical checks:
|
||||
# * pester.yml -- pull requests (reports, does not block the merge button)
|
||||
# * publish-scripts.yml -- pushes to main, where it BLOCKS the upload to the
|
||||
# download alias. Devices execute these scripts as SYSTEM
|
||||
# during enrollment, so a red suite must never ship.
|
||||
# Quality gate for the customer-facing PowerShell scripts. Devices execute them as SYSTEM
|
||||
# during enrollment, so a red suite must never ship. It runs in two roles:
|
||||
# * on its own, on every pull request and push to main that changes an input of these
|
||||
# checks (reports, does not block the merge button);
|
||||
# * called as the gates job that BLOCKS every signing or upload of bootstrap code:
|
||||
# publish-scripts.yml, build-agent.yml (stable releases), build-msi.yml. Those runs
|
||||
# show under the caller.
|
||||
#
|
||||
# Both path lists are the checks' complete inputs and stay identical. They cover every
|
||||
# push path of publish-scripts.yml, which leaves the check of a [skip publish] push to
|
||||
# this workflow.
|
||||
#
|
||||
# No concurrency group: it would also bind the runs called by the publishers, and a
|
||||
# cancel there would block a publish.
|
||||
|
||||
on:
|
||||
push:
|
||||
branches: [main]
|
||||
paths:
|
||||
- 'scripts/Bootstrap/**'
|
||||
- 'scripts/CustomerSetup/**'
|
||||
- '.github/scripts/Publish-BootstrapScripts.ps1'
|
||||
- '.github/scripts/Get-Endpoints.ps1'
|
||||
- '.github/scripts/Invoke-BootstrapSystemPass.ps1'
|
||||
- '.github/scripts/Test-BootstrapAttacker.ps1'
|
||||
- '.github/workflows/bootstrap-script-gates.yml'
|
||||
# The integration tests run the generated OOBE script and the MSI's custom action; the
|
||||
# contract tests also read the MSI build.
|
||||
- 'src/Backend/AutopilotMonitor.Functions.Tests/TestData/oobe-bootstrap-golden.ps1'
|
||||
- 'src/Agent/AutopilotMonitor.BootstrapMsi/Package.wxs'
|
||||
- '.github/workflows/build-msi.yml'
|
||||
pull_request:
|
||||
branches: [main]
|
||||
paths:
|
||||
- 'scripts/Bootstrap/**'
|
||||
- 'scripts/CustomerSetup/**'
|
||||
- '.github/scripts/Publish-BootstrapScripts.ps1'
|
||||
- '.github/scripts/Get-Endpoints.ps1'
|
||||
- '.github/scripts/Invoke-BootstrapSystemPass.ps1'
|
||||
- '.github/scripts/Test-BootstrapAttacker.ps1'
|
||||
- '.github/workflows/bootstrap-script-gates.yml'
|
||||
- 'src/Backend/AutopilotMonitor.Functions.Tests/TestData/oobe-bootstrap-golden.ps1'
|
||||
- 'src/Agent/AutopilotMonitor.BootstrapMsi/Package.wxs'
|
||||
- '.github/workflows/build-msi.yml'
|
||||
workflow_dispatch:
|
||||
workflow_call:
|
||||
|
||||
permissions:
|
||||
|
||||
@@ -254,6 +254,12 @@ jobs:
|
||||
if-no-files-found: error
|
||||
retention-days: 1
|
||||
|
||||
# A stable release publishes the customer scripts as well, so it waits for the gates their
|
||||
# own publish waits for. Next to the build; skipped when nothing goes out as stable.
|
||||
gates:
|
||||
if: inputs.publish_as_stable
|
||||
uses: $/.github/workflows/bootstrap-script-gates.yml
|
||||
|
||||
# Trust zone: only this repository's scripts, pinned actions and the pinned signing tool
|
||||
# run here -- never a restore or build. The build output arrives as data. The runner
|
||||
# image's Windows SDK signtool is used read-only, to verify third-party signatures.
|
||||
@@ -263,7 +269,9 @@ jobs:
|
||||
# sign nor write storage, whatever its permissions say.
|
||||
release:
|
||||
name: Sign and publish
|
||||
needs: [reserve, build]
|
||||
needs: [reserve, build, gates]
|
||||
# A skipped gates job (no stable publish) lets the release run; a failed or cancelled one stops it.
|
||||
if: ${{ !cancelled() && needs.build.result == 'success' && (needs.gates.result == 'success' || needs.gates.result == 'skipped') }}
|
||||
runs-on: windows-latest
|
||||
environment: release
|
||||
permissions:
|
||||
@@ -726,9 +734,9 @@ jobs:
|
||||
Send-Blob -Local $env:VERSIONED_ZIP -BlobName $env:STABLE_ZIP -ContentType "application/zip"
|
||||
Send-Blob -Local $env:MANIFEST_NAME -BlobName $env:STABLE_MANIFEST -ContentType "application/json"
|
||||
|
||||
# Customer-facing scripts: same publisher publish-scripts.yml runs on every push
|
||||
# to main, so a release lands a set that is consistent with what is already live
|
||||
# (dev render, version-bump guard, bootstrapVersion oracles, alias verification).
|
||||
# Customer-facing scripts: same publisher and same gates (the gates job) as
|
||||
# publish-scripts.yml, so a release lands a set that is consistent with what is
|
||||
# already live (dev render, version-bump guard, bootstrapVersion oracles, alias verification).
|
||||
# Runs AFTER version.json so its bootstrapVersion read sees this build's manifest.
|
||||
# Signed with the same identity: the device-side loader verifies the publisher
|
||||
# of what it downloads, and the publisher refuses to upload unsigned scripts.
|
||||
|
||||
@@ -34,6 +34,12 @@ env:
|
||||
CODE_SIGN_EXPECTED_SUBJECT: ${{ vars.CODE_SIGN_EXPECTED_SUBJECT }}
|
||||
|
||||
jobs:
|
||||
# The loader executes as SYSTEM on every enrolling device, and the MSI's custom action runs
|
||||
# it: nothing is signed before the bootstrap gates pass on this commit, since a signed copy
|
||||
# of ours is trusted wherever it lands.
|
||||
gates:
|
||||
uses: $/.github/workflows/bootstrap-script-gates.yml
|
||||
|
||||
# Signs the loader BEFORE the build: wix embeds the file as it finds it, so a loader signed
|
||||
# afterwards would leave the copy inside the MSI unsigned. Devices under an AllSigned policy
|
||||
# need the embedded loader to carry a signature of its own.
|
||||
@@ -42,6 +48,7 @@ jobs:
|
||||
# here. The `release` environment is the only subject the code-signing identity trusts.
|
||||
sign-loader:
|
||||
name: Sign bootstrap loader
|
||||
needs: gates
|
||||
runs-on: windows-latest
|
||||
environment: release
|
||||
permissions:
|
||||
@@ -59,22 +66,6 @@ jobs:
|
||||
shell: pwsh
|
||||
run: ./.github/scripts/Get-Endpoints.ps1 -ExportToGitHubEnv
|
||||
|
||||
# The loader executes as SYSTEM on every enrolling device — a parse error or
|
||||
# non-ASCII mojibake (PS 5.1 codepage roulette) must fail the build, not the fleet.
|
||||
# bootstrap-script-gates.yml runs the same checks plus Pester on pushes; this job
|
||||
# stands on its own because it can be dispatched at any time.
|
||||
- name: Validate runner script (parse + ASCII-only)
|
||||
shell: pwsh
|
||||
run: |
|
||||
$errs = $null
|
||||
[System.Management.Automation.Language.Parser]::ParseFile((Resolve-Path $env:RUNNER_SCRIPT), [ref]$null, [ref]$errs) | Out-Null
|
||||
if ($errs) { $errs | ForEach-Object { Write-Error $_.ToString() }; exit 1 }
|
||||
if ((Get-Content $env:RUNNER_SCRIPT -Raw) -match '[^\x00-\x7F]') {
|
||||
Write-Error "Runner script contains non-ASCII characters"
|
||||
exit 1
|
||||
}
|
||||
Write-Host "Runner script parse + ASCII check passed"
|
||||
|
||||
# Every published MSI is signed; a missing variable stops the run before the build.
|
||||
- name: Check code-signing configuration
|
||||
shell: pwsh
|
||||
|
||||
@@ -46,7 +46,6 @@ on:
|
||||
- '.github/workflows/deploy-mcp.yml'
|
||||
- '.github/workflows/deploy-web.yml'
|
||||
- '.github/workflows/indexnow-notify.yml'
|
||||
- '.github/workflows/pester.yml'
|
||||
- '.github/workflows/publish-scripts.yml'
|
||||
pull_request:
|
||||
branches: [main]
|
||||
@@ -79,7 +78,6 @@ on:
|
||||
- '.github/workflows/deploy-mcp.yml'
|
||||
- '.github/workflows/deploy-web.yml'
|
||||
- '.github/workflows/indexnow-notify.yml'
|
||||
- '.github/workflows/pester.yml'
|
||||
- '.github/workflows/publish-scripts.yml'
|
||||
workflow_dispatch:
|
||||
|
||||
|
||||
@@ -38,7 +38,6 @@ on:
|
||||
- '.github/workflows/deploy-mcp.yml'
|
||||
- '.github/workflows/deploy-web.yml'
|
||||
- '.github/workflows/indexnow-notify.yml'
|
||||
- '.github/workflows/pester.yml'
|
||||
- '.github/workflows/publish-scripts.yml'
|
||||
pull_request:
|
||||
branches: [main]
|
||||
@@ -70,7 +69,6 @@ on:
|
||||
- '.github/workflows/deploy-mcp.yml'
|
||||
- '.github/workflows/deploy-web.yml'
|
||||
- '.github/workflows/indexnow-notify.yml'
|
||||
- '.github/workflows/pester.yml'
|
||||
- '.github/workflows/publish-scripts.yml'
|
||||
schedule:
|
||||
# Weekly, so advisories published after a merge still surface. Deliberately
|
||||
|
||||
@@ -1,35 +0,0 @@
|
||||
name: Pester (Bootstrap scripts)
|
||||
|
||||
# Pull-request view of the bootstrap script gates. Like ci.yml it reports rather than
|
||||
# blocks the merge button.
|
||||
#
|
||||
# There is deliberately no push trigger: publish-scripts.yml runs the very same
|
||||
# reusable gate workflow on every push to main and blocks the upload to the download
|
||||
# alias on it. A push trigger here would only duplicate that run, with no consequence.
|
||||
|
||||
on:
|
||||
pull_request:
|
||||
branches: [main]
|
||||
paths:
|
||||
- 'scripts/Bootstrap/**'
|
||||
- 'scripts/CustomerSetup/**'
|
||||
- '.github/scripts/Publish-BootstrapScripts.ps1'
|
||||
- '.github/scripts/Invoke-BootstrapSystemPass.ps1'
|
||||
- '.github/scripts/Test-BootstrapAttacker.ps1'
|
||||
- '.github/workflows/bootstrap-script-gates.yml'
|
||||
# The integration tests run the generated OOBE script and the MSI's command line.
|
||||
- 'src/Backend/AutopilotMonitor.Functions.Tests/TestData/oobe-bootstrap-golden.ps1'
|
||||
- 'src/Agent/AutopilotMonitor.BootstrapMsi/Package.wxs'
|
||||
workflow_dispatch:
|
||||
|
||||
permissions:
|
||||
contents: read
|
||||
|
||||
concurrency:
|
||||
group: pester-${{ github.ref }}
|
||||
cancel-in-progress: true
|
||||
|
||||
jobs:
|
||||
# $/ is the self-repository form: this repository at the running commit.
|
||||
gates:
|
||||
uses: $/.github/workflows/bootstrap-script-gates.yml
|
||||
@@ -55,7 +55,12 @@ env:
|
||||
jobs:
|
||||
# $/ is the self-repository form: this repository at the running commit, never a
|
||||
# path some earlier step could have written to the workspace.
|
||||
#
|
||||
# A push with [skip publish] in one of its commit messages runs neither job and uploads
|
||||
# nothing; the gates' own push trigger, whose paths cover these, still checks it. Never
|
||||
# [skip actions] for that: it drops every check of the push, CI and these gates included.
|
||||
gates:
|
||||
if: github.event_name != 'push' || !contains(join(github.event.commits.*.message, ' '), '[skip publish]')
|
||||
uses: $/.github/workflows/bootstrap-script-gates.yml
|
||||
|
||||
publish:
|
||||
|
||||
+1
-1
Submodule infra updated: 0085deab45...7589909f54
+1
-1
Submodule internal updated: ffb7595c02...2609b9f3e5
@@ -1,56 +1,63 @@
|
||||
{
|
||||
"$schema": "../schema/analyze-rule.schema.json",
|
||||
"ruleId": "ANALYZE-APP-001",
|
||||
"title": "Win32 App Detection Script Failure",
|
||||
"description": "Detects when a Win32 app detection script fails or returns unexpected results.",
|
||||
"title": "App Not Detected After Install (0x87D1041C)",
|
||||
"description": "Detects when Intune's detection check right after an app's installer finished did not find the app, so Intune reports the install as failed (0x87D1041C).",
|
||||
"severity": "warning",
|
||||
"category": "apps",
|
||||
"version": "1.3.0",
|
||||
"version": "2.0.0",
|
||||
"enabled": true,
|
||||
"evaluateOn": [
|
||||
"enrollment_end",
|
||||
"whiteglove_sealed"
|
||||
],
|
||||
"baseConfidence": 60,
|
||||
"baseConfidence": 90,
|
||||
"conditions": [
|
||||
{
|
||||
"signal": "detection_failure",
|
||||
"source": "event_type",
|
||||
"eventType": "app_install_failed",
|
||||
"dataField": "detectionResult",
|
||||
"operator": "equals",
|
||||
"value": "NotDetected",
|
||||
"required": true,
|
||||
"suppressByEvent": {
|
||||
"eventType": "app_install_completed",
|
||||
"joinField": "appId"
|
||||
}
|
||||
"dataField": "errorCode",
|
||||
"operator": "regex",
|
||||
"value": "^(-2016345060|0x87d1041c)$",
|
||||
"required": true
|
||||
}
|
||||
],
|
||||
"explanation": "A Win32 app detection script failed or did not detect the app after installation. This causes the app to appear as 'not installed' despite successful installation. Detection failures that were later resolved by a successful install of the same app are suppressed and do not raise this finding.",
|
||||
"explanation": "The Intune Management Extension runs an app's detection twice: before the install, to decide whether the install is needed, and right after the installer finishes. Here the installer finished, but the check afterwards did not find the app. Intune therefore reports the install as failed with **0x87D1041C** (*application not detected after installation completed successfully*), even though the installer itself succeeded.\n\nFor Win32 apps the detection rule does not match what the installer left on the device. Common causes:\n\n- The rule checks a path or registry key the installer does not create (wrong path, version folder or bitness, e.g. HKLM\\SOFTWARE\\... versus HKLM\\SOFTWARE\\WOW6432Node\\...).\n- The installer finishes its work later (an async task, a service, or a restart it needs but does not request with a restart return code), after the check has run.\n- A detection script exits 0 without writing to stdout, which Intune treats as not detected.\n- The installer writes to the user profile while the rule looks in system scope, or the other way round.\n\nMicrosoft Store (WinGet) apps have no detection rule to edit: Intune asks WinGet whether the package is installed in the app's install context.\n\nWhen the installer requests a restart with its return code, Intune checks again after the restart; this finding then means the app was still missing afterwards.",
|
||||
"remediation": [
|
||||
{
|
||||
"title": "Fix detection rules",
|
||||
"title": "Check the detection rule against an installed device",
|
||||
"steps": [
|
||||
"Review the app's detection rules in Intune",
|
||||
"Verify file/registry paths are correct",
|
||||
"Test detection script manually on a device"
|
||||
"Open the app in Intune → Properties → Detection rules and note exactly what the rule checks",
|
||||
"Install the app on a test device outside Autopilot and confirm that the file, registry key or script result exists right after the installer exits",
|
||||
"For registry rules, check both HKLM\\SOFTWARE\\... and HKLM\\SOFTWARE\\WOW6432Node\\... depending on the installer's bitness",
|
||||
"For script rules, run the script as SYSTEM: it must write at least one line to stdout and exit 0 when the app is present",
|
||||
"If the installer completes its work later, detect something it writes synchronously, such as the MSI product code under HKLM\\SOFTWARE\\Microsoft\\Windows\\CurrentVersion\\Uninstall\\"
|
||||
]
|
||||
},
|
||||
{
|
||||
"title": "Microsoft Store (WinGet) apps",
|
||||
"steps": [
|
||||
"Check the package identifier and the install behavior (System or User) of the app in Intune",
|
||||
"Install the package manually in the same context on a test device and confirm it is reported as installed"
|
||||
]
|
||||
}
|
||||
],
|
||||
"relatedDocs": [
|
||||
{
|
||||
"title": "Win32 app detection rules in Intune",
|
||||
"url": "https://learn.microsoft.com/en-us/mem/intune/apps/apps-win32-add#step-4-detection-rules"
|
||||
}
|
||||
],
|
||||
"presentation": {
|
||||
"role": "cause",
|
||||
"summary": "{{detection_failure.appName}} was not detected after its install",
|
||||
"summary": "{{detection_failure.appName}} was not detected after its installer finished",
|
||||
"subject": {
|
||||
"kind": "app",
|
||||
"key": "{{detection_failure.appId}}",
|
||||
"name": "{{detection_failure.appName}}"
|
||||
},
|
||||
"facts": [
|
||||
{
|
||||
"label": "Detection",
|
||||
"value": "{{detection_failure.value}}"
|
||||
},
|
||||
{
|
||||
"label": "Error",
|
||||
"value": "{{detection_failure.errorCode}}",
|
||||
@@ -61,6 +68,8 @@
|
||||
"tags": [
|
||||
"apps",
|
||||
"detection",
|
||||
"win32"
|
||||
"win32",
|
||||
"winget",
|
||||
"0x87d1041c"
|
||||
]
|
||||
}
|
||||
|
||||
@@ -1,87 +0,0 @@
|
||||
{
|
||||
"$schema": "../schema/analyze-rule.schema.json",
|
||||
"ruleId": "ANALYZE-APP-010",
|
||||
"version": "1.1.0",
|
||||
"title": "App Reverted to Error After Successful Install",
|
||||
"description": "Detects when a specific app (matched by appId) was first reported as successfully installed but subsequently reported an IME enforcement error — while enrollment completed successfully. The app may be broken post-enrollment.",
|
||||
"severity": "warning",
|
||||
"category": "apps",
|
||||
"enabled": true,
|
||||
"trigger": "correlation",
|
||||
"baseConfidence": 75,
|
||||
"conditions": [
|
||||
{
|
||||
"signal": "app_regression",
|
||||
"source": "event_correlation",
|
||||
"eventType": "app_install_completed",
|
||||
"correlateEventType": "app_install_failed",
|
||||
"joinField": "appId",
|
||||
"dataField": "errorPatternId",
|
||||
"operator": "equals",
|
||||
"value": "IME-ERROR-REPORT",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "enrollment_succeeded",
|
||||
"source": "event_type",
|
||||
"eventType": "enrollment_complete",
|
||||
"operator": "exists",
|
||||
"value": "",
|
||||
"required": true
|
||||
}
|
||||
],
|
||||
"confidenceThreshold": 70,
|
||||
"explanation": "An app was initially reported as **successfully installed** (`app_install_completed`) but the IME (Intune Management Extension) subsequently reported an **Error** state for the same app via an `IME-ERROR-REPORT` event — while the overall enrollment completed successfully.\n\nThis pattern occurs when the IME re-evaluates enforcement state after the initial install report and detects a failure, e.g. `EnforcementState` transitions from `Success` → `Error`. The affected app and its details are captured in the matched evidence.\n\nCommon causes:\n- A post-install detection check fails (detection rule mismatch)\n- The enforcement error code `-2016345060` (0x87D13B9C) indicates the app state diverged from expected\n- The app may appear installed in the ESP summary but is in an error state on the device\n\n**The enrollment succeeded, but the affected app requires attention.**",
|
||||
"remediation": [
|
||||
{
|
||||
"title": "Investigate the app's post-install enforcement state",
|
||||
"steps": [
|
||||
"Note the appId and appName from the rule finding — these identify the exact affected app",
|
||||
"Check the Intune portal: Devices > [Device] > Apps — confirm the current enforcement state of the app",
|
||||
"Review IME logs on the device: C:\\ProgramData\\Microsoft\\IntuneManagementExtension\\Logs\\IntuneManagementExtension.log",
|
||||
"Search the log for the appId and look for 'EnforcementState' transitions (Success → Error) near the enrollment time",
|
||||
"Error -2016345060 (0x87D13B9C) typically indicates a detection failure after install — verify the app's detection rule in Intune",
|
||||
"Trigger a manual sync (Company Portal or Settings > Accounts > Access work or school > Sync) to force re-evaluation"
|
||||
]
|
||||
},
|
||||
{
|
||||
"title": "Fix detection or installation issues",
|
||||
"steps": [
|
||||
"If detection fails: correct the detection rule (file path, registry key, or PowerShell script) in the Intune app configuration",
|
||||
"If the app itself is broken: redeploy or reassign the app to trigger a fresh install",
|
||||
"Consider adding a post-install validation script to catch this scenario proactively"
|
||||
]
|
||||
}
|
||||
],
|
||||
"relatedDocs": [
|
||||
{ "title": "Troubleshoot Win32 app installations", "url": "https://learn.microsoft.com/en-us/troubleshoot/mem/intune/app-management/troubleshoot-win32-app-install" },
|
||||
{ "title": "Intune Management Extension logs", "url": "https://learn.microsoft.com/en-us/mem/intune/apps/intune-management-extension" }
|
||||
],
|
||||
"presentation": {
|
||||
"role": "cause",
|
||||
"summary": "{{app_regression.eventA_appName}} installed, then reported an error",
|
||||
"subject": {
|
||||
"kind": "app",
|
||||
"key": "{{app_regression.joinValue}}",
|
||||
"name": "{{app_regression.eventA_appName}}"
|
||||
},
|
||||
"facts": [
|
||||
{
|
||||
"label": "Installed",
|
||||
"value": "{{app_regression.eventA_timestamp}}",
|
||||
"format": "timestamp"
|
||||
},
|
||||
{
|
||||
"label": "Error after",
|
||||
"value": "{{app_regression.timeDeltaSeconds}}",
|
||||
"format": "duration"
|
||||
},
|
||||
{
|
||||
"label": "Error",
|
||||
"value": "{{app_regression.eventB_errorCode}}",
|
||||
"format": "errorCode"
|
||||
}
|
||||
]
|
||||
},
|
||||
"tags": ["apps", "win32", "enforcement", "post-install", "correlation"]
|
||||
}
|
||||
@@ -5,7 +5,7 @@
|
||||
"description": "Detects when the Enrollment Status Page failed because Intune could not verify an app was installed (HRESULT 0x87D1041C). The installer ran but the detection rule did not match afterwards.",
|
||||
"severity": "critical",
|
||||
"category": "apps",
|
||||
"version": "1.3.0",
|
||||
"version": "1.4.0",
|
||||
"enabled": true,
|
||||
"evaluateOn": [
|
||||
"enrollment_end",
|
||||
@@ -27,9 +27,9 @@
|
||||
"signal": "app_with_detection_failure",
|
||||
"source": "event_type",
|
||||
"eventType": "app_install_failed",
|
||||
"dataField": "detectionResult",
|
||||
"operator": "equals",
|
||||
"value": "NotDetected",
|
||||
"dataField": "errorCode",
|
||||
"operator": "regex",
|
||||
"value": "^(-2016345060|0x87d1041c)$",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
@@ -42,7 +42,7 @@
|
||||
"required": false
|
||||
}
|
||||
],
|
||||
"explanation": "App **{{appName}}** failed during the Enrollment Status Page with HRESULT **{{errorCode}}** — *Application not detected after installation completed successfully*. The installer reported success but the Intune detection rule (file/registry/script) did not find the app afterwards, so the ESP Apps subcategory failed and the device's enrollment terminated.\n\nThis is a confirmed detection-rule mismatch, NOT an install timeout — the install itself most likely completed (or the installer exited 0). Common root causes:\n\n- The detection rule looks for a registry/file path that the installer doesn't create (wrong path, wrong bitness — e.g. checking HKLM\\SOFTWARE\\... on a 32-bit installer that lands under WOW6432Node).\n- The installer writes the detection artefact AFTER the ESP's detection probe runs (e.g. async post-install task, requires reboot).\n- The detection script returns 0 with no stdout (Intune treats empty stdout as \"not detected\").\n- The installer wrote files to a user profile but the rule looks in System scope (or vice-versa).",
|
||||
"explanation": "App **{{app_with_detection_failure.appName}}** failed during the Enrollment Status Page with HRESULT **0x87D1041C** — *Application not detected after installation completed successfully*. The installer reported success but the Intune detection rule (file/registry/script) did not find the app afterwards, so the ESP Apps subcategory failed and the device's enrollment terminated.\n\nThis is a confirmed detection-rule mismatch, NOT an install timeout — the install itself most likely completed (or the installer exited 0). Common root causes:\n\n- The detection rule looks for a registry/file path that the installer doesn't create (wrong path, wrong bitness — e.g. checking HKLM\\SOFTWARE\\... on a 32-bit installer that lands under WOW6432Node).\n- The installer finishes its work later (an async task, a service, or a restart it needs but does not request with a restart return code), after Intune's check has run.\n- The detection script returns 0 with no stdout (Intune treats empty stdout as \"not detected\").\n- The installer wrote files to a user profile but the rule looks in System scope (or vice-versa).",
|
||||
"remediation": [
|
||||
{
|
||||
"title": "Validate the detection rule against an installed device",
|
||||
@@ -66,7 +66,7 @@
|
||||
{
|
||||
"title": "Cross-check the agent's per-app event",
|
||||
"steps": [
|
||||
"Look at the app_install_failed event in this session for DataJson.detectionResult — NotDetected confirms Intune's detection probe ran and returned negative",
|
||||
"Look at the app_install_failed event of this app: errorCode 0x87D1041C (the IME log writes it as -2016345060) is Intune's own verdict that its check right after the installer did not find the app",
|
||||
"Look at app_install_failed.bytesDownloaded vs bytesTotal — if they match, the package downloaded fully (install error vs. download error)",
|
||||
"Cross-reference DataJson.exitCode and hresultFromWin32 — these come from the installer itself and may explain why the detection artefact was not written"
|
||||
]
|
||||
@@ -95,10 +95,6 @@
|
||||
"label": "ESP error",
|
||||
"value": "{{esp_failure_errorcode.value}}",
|
||||
"format": "errorCode"
|
||||
},
|
||||
{
|
||||
"label": "Detection",
|
||||
"value": "{{app_with_detection_failure.value}}"
|
||||
}
|
||||
]
|
||||
},
|
||||
|
||||
+38
-131
@@ -3,56 +3,63 @@
|
||||
"rules": [
|
||||
{
|
||||
"ruleId": "ANALYZE-APP-001",
|
||||
"title": "Win32 App Detection Script Failure",
|
||||
"description": "Detects when a Win32 app detection script fails or returns unexpected results.",
|
||||
"title": "App Not Detected After Install (0x87D1041C)",
|
||||
"description": "Detects when Intune's detection check right after an app's installer finished did not find the app, so Intune reports the install as failed (0x87D1041C).",
|
||||
"severity": "warning",
|
||||
"category": "apps",
|
||||
"version": "1.3.0",
|
||||
"version": "2.0.0",
|
||||
"enabled": true,
|
||||
"evaluateOn": [
|
||||
"enrollment_end",
|
||||
"whiteglove_sealed"
|
||||
],
|
||||
"baseConfidence": 60,
|
||||
"baseConfidence": 90,
|
||||
"conditions": [
|
||||
{
|
||||
"signal": "detection_failure",
|
||||
"source": "event_type",
|
||||
"eventType": "app_install_failed",
|
||||
"dataField": "detectionResult",
|
||||
"operator": "equals",
|
||||
"value": "NotDetected",
|
||||
"required": true,
|
||||
"suppressByEvent": {
|
||||
"eventType": "app_install_completed",
|
||||
"joinField": "appId"
|
||||
}
|
||||
"dataField": "errorCode",
|
||||
"operator": "regex",
|
||||
"value": "^(-2016345060|0x87d1041c)$",
|
||||
"required": true
|
||||
}
|
||||
],
|
||||
"explanation": "A Win32 app detection script failed or did not detect the app after installation. This causes the app to appear as 'not installed' despite successful installation. Detection failures that were later resolved by a successful install of the same app are suppressed and do not raise this finding.",
|
||||
"explanation": "The Intune Management Extension runs an app's detection twice: before the install, to decide whether the install is needed, and right after the installer finishes. Here the installer finished, but the check afterwards did not find the app. Intune therefore reports the install as failed with **0x87D1041C** (*application not detected after installation completed successfully*), even though the installer itself succeeded.\n\nFor Win32 apps the detection rule does not match what the installer left on the device. Common causes:\n\n- The rule checks a path or registry key the installer does not create (wrong path, version folder or bitness, e.g. HKLM\\SOFTWARE\\... versus HKLM\\SOFTWARE\\WOW6432Node\\...).\n- The installer finishes its work later (an async task, a service, or a restart it needs but does not request with a restart return code), after the check has run.\n- A detection script exits 0 without writing to stdout, which Intune treats as not detected.\n- The installer writes to the user profile while the rule looks in system scope, or the other way round.\n\nMicrosoft Store (WinGet) apps have no detection rule to edit: Intune asks WinGet whether the package is installed in the app's install context.\n\nWhen the installer requests a restart with its return code, Intune checks again after the restart; this finding then means the app was still missing afterwards.",
|
||||
"remediation": [
|
||||
{
|
||||
"title": "Fix detection rules",
|
||||
"title": "Check the detection rule against an installed device",
|
||||
"steps": [
|
||||
"Review the app's detection rules in Intune",
|
||||
"Verify file/registry paths are correct",
|
||||
"Test detection script manually on a device"
|
||||
"Open the app in Intune → Properties → Detection rules and note exactly what the rule checks",
|
||||
"Install the app on a test device outside Autopilot and confirm that the file, registry key or script result exists right after the installer exits",
|
||||
"For registry rules, check both HKLM\\SOFTWARE\\... and HKLM\\SOFTWARE\\WOW6432Node\\... depending on the installer's bitness",
|
||||
"For script rules, run the script as SYSTEM: it must write at least one line to stdout and exit 0 when the app is present",
|
||||
"If the installer completes its work later, detect something it writes synchronously, such as the MSI product code under HKLM\\SOFTWARE\\Microsoft\\Windows\\CurrentVersion\\Uninstall\\"
|
||||
]
|
||||
},
|
||||
{
|
||||
"title": "Microsoft Store (WinGet) apps",
|
||||
"steps": [
|
||||
"Check the package identifier and the install behavior (System or User) of the app in Intune",
|
||||
"Install the package manually in the same context on a test device and confirm it is reported as installed"
|
||||
]
|
||||
}
|
||||
],
|
||||
"relatedDocs": [
|
||||
{
|
||||
"title": "Win32 app detection rules in Intune",
|
||||
"url": "https://learn.microsoft.com/en-us/mem/intune/apps/apps-win32-add#step-4-detection-rules"
|
||||
}
|
||||
],
|
||||
"presentation": {
|
||||
"role": "cause",
|
||||
"summary": "{{detection_failure.appName}} was not detected after its install",
|
||||
"summary": "{{detection_failure.appName}} was not detected after its installer finished",
|
||||
"subject": {
|
||||
"kind": "app",
|
||||
"key": "{{detection_failure.appId}}",
|
||||
"name": "{{detection_failure.appName}}"
|
||||
},
|
||||
"facts": [
|
||||
{
|
||||
"label": "Detection",
|
||||
"value": "{{detection_failure.value}}"
|
||||
},
|
||||
{
|
||||
"label": "Error",
|
||||
"value": "{{detection_failure.errorCode}}",
|
||||
@@ -63,7 +70,9 @@
|
||||
"tags": [
|
||||
"apps",
|
||||
"detection",
|
||||
"win32"
|
||||
"win32",
|
||||
"winget",
|
||||
"0x87d1041c"
|
||||
]
|
||||
},
|
||||
{
|
||||
@@ -541,104 +550,6 @@
|
||||
],
|
||||
"version": "1.2.0"
|
||||
},
|
||||
{
|
||||
"ruleId": "ANALYZE-APP-010",
|
||||
"version": "1.1.0",
|
||||
"title": "App Reverted to Error After Successful Install",
|
||||
"description": "Detects when a specific app (matched by appId) was first reported as successfully installed but subsequently reported an IME enforcement error — while enrollment completed successfully. The app may be broken post-enrollment.",
|
||||
"severity": "warning",
|
||||
"category": "apps",
|
||||
"enabled": true,
|
||||
"trigger": "correlation",
|
||||
"baseConfidence": 75,
|
||||
"conditions": [
|
||||
{
|
||||
"signal": "app_regression",
|
||||
"source": "event_correlation",
|
||||
"eventType": "app_install_completed",
|
||||
"correlateEventType": "app_install_failed",
|
||||
"joinField": "appId",
|
||||
"dataField": "errorPatternId",
|
||||
"operator": "equals",
|
||||
"value": "IME-ERROR-REPORT",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "enrollment_succeeded",
|
||||
"source": "event_type",
|
||||
"eventType": "enrollment_complete",
|
||||
"operator": "exists",
|
||||
"value": "",
|
||||
"required": true
|
||||
}
|
||||
],
|
||||
"confidenceThreshold": 70,
|
||||
"explanation": "An app was initially reported as **successfully installed** (`app_install_completed`) but the IME (Intune Management Extension) subsequently reported an **Error** state for the same app via an `IME-ERROR-REPORT` event — while the overall enrollment completed successfully.\n\nThis pattern occurs when the IME re-evaluates enforcement state after the initial install report and detects a failure, e.g. `EnforcementState` transitions from `Success` → `Error`. The affected app and its details are captured in the matched evidence.\n\nCommon causes:\n- A post-install detection check fails (detection rule mismatch)\n- The enforcement error code `-2016345060` (0x87D13B9C) indicates the app state diverged from expected\n- The app may appear installed in the ESP summary but is in an error state on the device\n\n**The enrollment succeeded, but the affected app requires attention.**",
|
||||
"remediation": [
|
||||
{
|
||||
"title": "Investigate the app's post-install enforcement state",
|
||||
"steps": [
|
||||
"Note the appId and appName from the rule finding — these identify the exact affected app",
|
||||
"Check the Intune portal: Devices > [Device] > Apps — confirm the current enforcement state of the app",
|
||||
"Review IME logs on the device: C:\\ProgramData\\Microsoft\\IntuneManagementExtension\\Logs\\IntuneManagementExtension.log",
|
||||
"Search the log for the appId and look for 'EnforcementState' transitions (Success → Error) near the enrollment time",
|
||||
"Error -2016345060 (0x87D13B9C) typically indicates a detection failure after install — verify the app's detection rule in Intune",
|
||||
"Trigger a manual sync (Company Portal or Settings > Accounts > Access work or school > Sync) to force re-evaluation"
|
||||
]
|
||||
},
|
||||
{
|
||||
"title": "Fix detection or installation issues",
|
||||
"steps": [
|
||||
"If detection fails: correct the detection rule (file path, registry key, or PowerShell script) in the Intune app configuration",
|
||||
"If the app itself is broken: redeploy or reassign the app to trigger a fresh install",
|
||||
"Consider adding a post-install validation script to catch this scenario proactively"
|
||||
]
|
||||
}
|
||||
],
|
||||
"relatedDocs": [
|
||||
{
|
||||
"title": "Troubleshoot Win32 app installations",
|
||||
"url": "https://learn.microsoft.com/en-us/troubleshoot/mem/intune/app-management/troubleshoot-win32-app-install"
|
||||
},
|
||||
{
|
||||
"title": "Intune Management Extension logs",
|
||||
"url": "https://learn.microsoft.com/en-us/mem/intune/apps/intune-management-extension"
|
||||
}
|
||||
],
|
||||
"presentation": {
|
||||
"role": "cause",
|
||||
"summary": "{{app_regression.eventA_appName}} installed, then reported an error",
|
||||
"subject": {
|
||||
"kind": "app",
|
||||
"key": "{{app_regression.joinValue}}",
|
||||
"name": "{{app_regression.eventA_appName}}"
|
||||
},
|
||||
"facts": [
|
||||
{
|
||||
"label": "Installed",
|
||||
"value": "{{app_regression.eventA_timestamp}}",
|
||||
"format": "timestamp"
|
||||
},
|
||||
{
|
||||
"label": "Error after",
|
||||
"value": "{{app_regression.timeDeltaSeconds}}",
|
||||
"format": "duration"
|
||||
},
|
||||
{
|
||||
"label": "Error",
|
||||
"value": "{{app_regression.eventB_errorCode}}",
|
||||
"format": "errorCode"
|
||||
}
|
||||
]
|
||||
},
|
||||
"tags": [
|
||||
"apps",
|
||||
"win32",
|
||||
"enforcement",
|
||||
"post-install",
|
||||
"correlation"
|
||||
]
|
||||
},
|
||||
{
|
||||
"ruleId": "ANALYZE-APP-012",
|
||||
"title": "Enforcement Error Resolved by Successful Detection",
|
||||
@@ -724,7 +635,7 @@
|
||||
"description": "Detects when the Enrollment Status Page failed because Intune could not verify an app was installed (HRESULT 0x87D1041C). The installer ran but the detection rule did not match afterwards.",
|
||||
"severity": "critical",
|
||||
"category": "apps",
|
||||
"version": "1.3.0",
|
||||
"version": "1.4.0",
|
||||
"enabled": true,
|
||||
"evaluateOn": [
|
||||
"enrollment_end",
|
||||
@@ -746,9 +657,9 @@
|
||||
"signal": "app_with_detection_failure",
|
||||
"source": "event_type",
|
||||
"eventType": "app_install_failed",
|
||||
"dataField": "detectionResult",
|
||||
"operator": "equals",
|
||||
"value": "NotDetected",
|
||||
"dataField": "errorCode",
|
||||
"operator": "regex",
|
||||
"value": "^(-2016345060|0x87d1041c)$",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
@@ -761,7 +672,7 @@
|
||||
"required": false
|
||||
}
|
||||
],
|
||||
"explanation": "App **{{appName}}** failed during the Enrollment Status Page with HRESULT **{{errorCode}}** — *Application not detected after installation completed successfully*. The installer reported success but the Intune detection rule (file/registry/script) did not find the app afterwards, so the ESP Apps subcategory failed and the device's enrollment terminated.\n\nThis is a confirmed detection-rule mismatch, NOT an install timeout — the install itself most likely completed (or the installer exited 0). Common root causes:\n\n- The detection rule looks for a registry/file path that the installer doesn't create (wrong path, wrong bitness — e.g. checking HKLM\\SOFTWARE\\... on a 32-bit installer that lands under WOW6432Node).\n- The installer writes the detection artefact AFTER the ESP's detection probe runs (e.g. async post-install task, requires reboot).\n- The detection script returns 0 with no stdout (Intune treats empty stdout as \"not detected\").\n- The installer wrote files to a user profile but the rule looks in System scope (or vice-versa).",
|
||||
"explanation": "App **{{app_with_detection_failure.appName}}** failed during the Enrollment Status Page with HRESULT **0x87D1041C** — *Application not detected after installation completed successfully*. The installer reported success but the Intune detection rule (file/registry/script) did not find the app afterwards, so the ESP Apps subcategory failed and the device's enrollment terminated.\n\nThis is a confirmed detection-rule mismatch, NOT an install timeout — the install itself most likely completed (or the installer exited 0). Common root causes:\n\n- The detection rule looks for a registry/file path that the installer doesn't create (wrong path, wrong bitness — e.g. checking HKLM\\SOFTWARE\\... on a 32-bit installer that lands under WOW6432Node).\n- The installer finishes its work later (an async task, a service, or a restart it needs but does not request with a restart return code), after Intune's check has run.\n- The detection script returns 0 with no stdout (Intune treats empty stdout as \"not detected\").\n- The installer wrote files to a user profile but the rule looks in System scope (or vice-versa).",
|
||||
"remediation": [
|
||||
{
|
||||
"title": "Validate the detection rule against an installed device",
|
||||
@@ -785,7 +696,7 @@
|
||||
{
|
||||
"title": "Cross-check the agent's per-app event",
|
||||
"steps": [
|
||||
"Look at the app_install_failed event in this session for DataJson.detectionResult — NotDetected confirms Intune's detection probe ran and returned negative",
|
||||
"Look at the app_install_failed event of this app: errorCode 0x87D1041C (the IME log writes it as -2016345060) is Intune's own verdict that its check right after the installer did not find the app",
|
||||
"Look at app_install_failed.bytesDownloaded vs bytesTotal — if they match, the package downloaded fully (install error vs. download error)",
|
||||
"Cross-reference DataJson.exitCode and hresultFromWin32 — these come from the installer itself and may explain why the detection artefact was not written"
|
||||
]
|
||||
@@ -814,10 +725,6 @@
|
||||
"label": "ESP error",
|
||||
"value": "{{esp_failure_errorcode.value}}",
|
||||
"format": "errorCode"
|
||||
},
|
||||
{
|
||||
"label": "Detection",
|
||||
"value": "{{app_with_detection_failure.value}}"
|
||||
}
|
||||
]
|
||||
},
|
||||
|
||||
+22
-3
@@ -195,7 +195,7 @@
|
||||
"category": "always",
|
||||
"pattern": "^\\[Win32App\\]\\[DetectionActionHandler\\] Detection for policy with id: (?<id>{GUID}) resulted in action status: Success and detection state: (?<detection>DetectedDifferentVersion|NotDetected|Detected)",
|
||||
"action": "captureDetectionResult",
|
||||
"description": "Captures the detection rule result after IME runs detection for an app. 'Detected' means the detection rule matched (app is installed), 'NotDetected' means it did not, 'DetectedDifferentVersion' means a different version was found (supersedence / WinGet version mismatch). DetectedDifferentVersion must come first in the alternation so the unanchored regex does not mis-capture its 'Detected' prefix. Excludes [SimulatedDetectionActionHandler] which fires during applicability pre-checks.",
|
||||
"description": "Captures the result of every IME detection run for an app: the check before the install (NotDetected is what starts the install) and the check right after it. App events therefore carry the check before the install; IME's verdict after the install is the enforcement error 0x87D1041C on failure. 'Detected' means the detection rule matched (app is installed), 'NotDetected' means it did not, 'DetectedDifferentVersion' means a different version was found (supersedence / WinGet version mismatch). DetectedDifferentVersion must come first in the alternation so the unanchored regex does not mis-capture its 'Detected' prefix. Excludes [SimulatedDetectionActionHandler] which fires during applicability pre-checks.",
|
||||
"enabled": true
|
||||
},
|
||||
{
|
||||
@@ -285,12 +285,12 @@
|
||||
{
|
||||
"patternId": "IME-ERROR-REPORT",
|
||||
"category": "currentPhase",
|
||||
"pattern": "^\\[Win32App\\]\\[ReportingManager\\] Execution state for app with id: {GUID} has been updated\\. Report delta: \\{\"{1,2}EnforcementState\"{1,2}:\\{\"{1,2}OldValue\"{1,2}:(?:\"{1,2}(?<from>\\w+)\"{1,2}|null),\"{1,2}NewValue\"{1,2}:\"{1,2}(?<to>\\w+)\"{1,2}",
|
||||
"pattern": "^\\[Win32App\\]\\[ReportingManager\\] Execution state for app with id: {GUID} has been updated\\. Report delta: \\{\"{1,2}EnforcementState\"{1,2}:\\{\"{1,2}OldValue\"{1,2}:(?:\"{1,2}(?<from>\\w+)\"{1,2}|null),\"{1,2}NewValue\"{1,2}:\"{1,2}(?<to>\\w+)\"{1,2}(?:\\},\"{1,2}EnforcementErrorCode\"{1,2}:\\{\"{1,2}OldValue\"{1,2}:(?:-?\\d+|null),\"{1,2}NewValue\"{1,2}:(?<errorCode>-?\\d+))?",
|
||||
"action": "updateStateError",
|
||||
"parameters": {
|
||||
"checkTo": "true"
|
||||
},
|
||||
"description": "Captures enforcement state transitions via ReportingManager. Only triggers error when 'to' value indicates an error state. OldValue may be the unquoted JSON literal null on the first-ever write of a reporting state — transitions straight from the initial state (e.g. first write directly to an error state) would otherwise be invisible (IME 1.97 audit 2026-08-17). Quote-flexible since 2026-08-17: IME 1.104 serializes the report-delta JSON with single quotes ({\"Key\":...) where older versions logged doubled quotes ({\"\"Key\"\":...) - every literal quote in the delta is matched as \"{1,2} to cover both.",
|
||||
"description": "Captures enforcement state transitions via ReportingManager. Only triggers error when 'to' value indicates an error state. OldValue may be the unquoted JSON literal null on the first-ever write of a reporting state — transitions straight from the initial state (e.g. first write directly to an error state) would otherwise be invisible (IME 1.97 audit 2026-08-17). Quote-flexible since 2026-08-17: IME 1.104 serializes the report-delta JSON with single quotes ({\"Key\":...) where older versions logged doubled quotes ({\"\"Key\"\":...) - every literal quote in the delta is matched as \"{1,2} to cover both. The optional errorCode group takes EnforcementErrorCode.NewValue, which IME logs as a signed decimal right after the state object (e.g. -2016345060 = 0x87D1041C: IME's check after the install did not find the app); the code reaches app_install_failed only when this line is the app's first move to Error.",
|
||||
"enabled": true
|
||||
},
|
||||
{
|
||||
@@ -487,6 +487,25 @@
|
||||
"description": "Captures the JSON policies list discovered by IME, used to build the app inventory.",
|
||||
"enabled": true
|
||||
},
|
||||
{
|
||||
"patternId": "IME-POST-INSTALL-DETECTION",
|
||||
"category": "always",
|
||||
"pattern": "^\\[Win32App\\]\\[DetectionActionHandler\\] Policy with id: {GUID} is expected to have enforcement state: Detected\\.",
|
||||
"action": "markPostInstallDetection",
|
||||
"description": "Marks IME's check right after an install. IME logs this line only for the app it has just installed, before that check's result line; the agent reports that result (IME-DETECTION-RESULT) as app_post_install_detection and keeps detectionResult as the check before the install. Other apps of the same dependency chain are checked in the same run without this line. A failed check is IME's error 0x87D1041C (IME-ERROR-REPORT).",
|
||||
"enabled": true
|
||||
},
|
||||
{
|
||||
"patternId": "IME-POST-REBOOT-DETECTION",
|
||||
"category": "always",
|
||||
"pattern": "^\\[Win32App\\]\\[ReportingManager\\] Execution state for app with id: {GUID} has been updated\\. Report delta: \\{\"{1,2}EnforcementState\"{1,2}:\\{\"{1,2}OldValue\"{1,2}:\"{1,2}InProgressPendingReboot\"{1,2},\"{1,2}NewValue\"{1,2}:\"{1,2}Success\"{1,2}",
|
||||
"action": "markPostInstallDetection",
|
||||
"parameters": {
|
||||
"afterReboot": "true"
|
||||
},
|
||||
"description": "Marks IME's check after the restart an installer requested. After an exit code mapped to SoftReboot or HardReboot the check right after the install decides nothing; after the restart IME moves the app from InProgressPendingReboot to Success (held back like after a clean install) and checks again without the IME-POST-INSTALL-DETECTION line. That check's result is reported as app_post_install_detection with afterReboot=true. Quote-flexible like IME-ENFORCEMENT-SUCCESS.",
|
||||
"enabled": true
|
||||
},
|
||||
{
|
||||
"patternId": "IME-RESTART-STOP-PROCESSING",
|
||||
"category": "currentPhase",
|
||||
|
||||
@@ -292,6 +292,7 @@
|
||||
"app_install_completed",
|
||||
"app_install_failed",
|
||||
"app_install_skipped",
|
||||
"app_post_install_detection",
|
||||
"app_download_started",
|
||||
"app_tracking_summary",
|
||||
"download_progress",
|
||||
|
||||
@@ -4,6 +4,6 @@
|
||||
"category": "always",
|
||||
"pattern": "^\\[Win32App\\]\\[DetectionActionHandler\\] Detection for policy with id: (?<id>{GUID}) resulted in action status: Success and detection state: (?<detection>DetectedDifferentVersion|NotDetected|Detected)",
|
||||
"action": "captureDetectionResult",
|
||||
"description": "Captures the detection rule result after IME runs detection for an app. 'Detected' means the detection rule matched (app is installed), 'NotDetected' means it did not, 'DetectedDifferentVersion' means a different version was found (supersedence / WinGet version mismatch). DetectedDifferentVersion must come first in the alternation so the unanchored regex does not mis-capture its 'Detected' prefix. Excludes [SimulatedDetectionActionHandler] which fires during applicability pre-checks.",
|
||||
"description": "Captures the result of every IME detection run for an app: the check before the install (NotDetected is what starts the install) and the check right after it. App events therefore carry the check before the install; IME's verdict after the install is the enforcement error 0x87D1041C on failure. 'Detected' means the detection rule matched (app is installed), 'NotDetected' means it did not, 'DetectedDifferentVersion' means a different version was found (supersedence / WinGet version mismatch). DetectedDifferentVersion must come first in the alternation so the unanchored regex does not mis-capture its 'Detected' prefix. Excludes [SimulatedDetectionActionHandler] which fires during applicability pre-checks.",
|
||||
"enabled": true
|
||||
}
|
||||
|
||||
@@ -2,11 +2,11 @@
|
||||
"$schema": "../schema/ime-log-pattern.schema.json",
|
||||
"patternId": "IME-ERROR-REPORT",
|
||||
"category": "currentPhase",
|
||||
"pattern": "^\\[Win32App\\]\\[ReportingManager\\] Execution state for app with id: {GUID} has been updated\\. Report delta: \\{\"{1,2}EnforcementState\"{1,2}:\\{\"{1,2}OldValue\"{1,2}:(?:\"{1,2}(?<from>\\w+)\"{1,2}|null),\"{1,2}NewValue\"{1,2}:\"{1,2}(?<to>\\w+)\"{1,2}",
|
||||
"pattern": "^\\[Win32App\\]\\[ReportingManager\\] Execution state for app with id: {GUID} has been updated\\. Report delta: \\{\"{1,2}EnforcementState\"{1,2}:\\{\"{1,2}OldValue\"{1,2}:(?:\"{1,2}(?<from>\\w+)\"{1,2}|null),\"{1,2}NewValue\"{1,2}:\"{1,2}(?<to>\\w+)\"{1,2}(?:\\},\"{1,2}EnforcementErrorCode\"{1,2}:\\{\"{1,2}OldValue\"{1,2}:(?:-?\\d+|null),\"{1,2}NewValue\"{1,2}:(?<errorCode>-?\\d+))?",
|
||||
"action": "updateStateError",
|
||||
"parameters": {
|
||||
"checkTo": "true"
|
||||
},
|
||||
"description": "Captures enforcement state transitions via ReportingManager. Only triggers error when 'to' value indicates an error state. OldValue may be the unquoted JSON literal null on the first-ever write of a reporting state — transitions straight from the initial state (e.g. first write directly to an error state) would otherwise be invisible (IME 1.97 audit 2026-08-17). Quote-flexible since 2026-08-17: IME 1.104 serializes the report-delta JSON with single quotes ({\"Key\":...) where older versions logged doubled quotes ({\"\"Key\"\":...) - every literal quote in the delta is matched as \"{1,2} to cover both.",
|
||||
"description": "Captures enforcement state transitions via ReportingManager. Only triggers error when 'to' value indicates an error state. OldValue may be the unquoted JSON literal null on the first-ever write of a reporting state — transitions straight from the initial state (e.g. first write directly to an error state) would otherwise be invisible (IME 1.97 audit 2026-08-17). Quote-flexible since 2026-08-17: IME 1.104 serializes the report-delta JSON with single quotes ({\"Key\":...) where older versions logged doubled quotes ({\"\"Key\"\":...) - every literal quote in the delta is matched as \"{1,2} to cover both. The optional errorCode group takes EnforcementErrorCode.NewValue, which IME logs as a signed decimal right after the state object (e.g. -2016345060 = 0x87D1041C: IME's check after the install did not find the app); the code reaches app_install_failed only when this line is the app's first move to Error.",
|
||||
"enabled": true
|
||||
}
|
||||
|
||||
@@ -0,0 +1,9 @@
|
||||
{
|
||||
"$schema": "../schema/ime-log-pattern.schema.json",
|
||||
"patternId": "IME-POST-INSTALL-DETECTION",
|
||||
"category": "always",
|
||||
"pattern": "^\\[Win32App\\]\\[DetectionActionHandler\\] Policy with id: {GUID} is expected to have enforcement state: Detected\\.",
|
||||
"action": "markPostInstallDetection",
|
||||
"description": "Marks IME's check right after an install. IME logs this line only for the app it has just installed, before that check's result line; the agent reports that result (IME-DETECTION-RESULT) as app_post_install_detection and keeps detectionResult as the check before the install. Other apps of the same dependency chain are checked in the same run without this line. A failed check is IME's error 0x87D1041C (IME-ERROR-REPORT).",
|
||||
"enabled": true
|
||||
}
|
||||
@@ -0,0 +1,12 @@
|
||||
{
|
||||
"$schema": "../schema/ime-log-pattern.schema.json",
|
||||
"patternId": "IME-POST-REBOOT-DETECTION",
|
||||
"category": "always",
|
||||
"pattern": "^\\[Win32App\\]\\[ReportingManager\\] Execution state for app with id: {GUID} has been updated\\. Report delta: \\{\"{1,2}EnforcementState\"{1,2}:\\{\"{1,2}OldValue\"{1,2}:\"{1,2}InProgressPendingReboot\"{1,2},\"{1,2}NewValue\"{1,2}:\"{1,2}Success\"{1,2}",
|
||||
"action": "markPostInstallDetection",
|
||||
"parameters": {
|
||||
"afterReboot": "true"
|
||||
},
|
||||
"description": "Marks IME's check after the restart an installer requested. After an exit code mapped to SoftReboot or HardReboot the check right after the install decides nothing; after the restart IME moves the app from InProgressPendingReboot to Success (held back like after a clean install) and checks again without the IME-POST-INSTALL-DETECTION line. That check's result is reported as app_post_install_detection with afterReboot=true. Quote-flexible like IME-ENFORCEMENT-SUCCESS.",
|
||||
"enabled": true
|
||||
}
|
||||
@@ -82,7 +82,8 @@
|
||||
"captureAppTypeMsi",
|
||||
"captureAttemptNumber",
|
||||
"captureDetectionResult",
|
||||
"captureExitCodeClass"
|
||||
"captureExitCodeClass",
|
||||
"markPostInstallDetection"
|
||||
]
|
||||
},
|
||||
"parameters": {
|
||||
|
||||
Generated
+3
-3
@@ -53,9 +53,9 @@
|
||||
"license": "MIT"
|
||||
},
|
||||
"node_modules/fast-uri": {
|
||||
"version": "3.1.8",
|
||||
"resolved": "https://registry.npmjs.org/fast-uri/-/fast-uri-3.1.8.tgz",
|
||||
"integrity": "sha512-GZMtZUTNRpOVIECoXwLNZS5xUGE+mVNbTB8h/7Rwh2TFWcBQiPzTgyZi05BF9UMZKkLJv8XBRJTlU7zg8+ZfMg==",
|
||||
"version": "3.1.9",
|
||||
"resolved": "https://registry.npmjs.org/fast-uri/-/fast-uri-3.1.9.tgz",
|
||||
"integrity": "sha512-hS/0Wt3Ya043oKXs0sIxrMpKQITXhMLIrVAKKXi4gozGC9v7YRWVnXIZzjNPTO02M9BdxLCWqK1yRXgNziVyJQ==",
|
||||
"dev": true,
|
||||
"funding": [
|
||||
{
|
||||
|
||||
@@ -0,0 +1,80 @@
|
||||
#nullable enable
|
||||
using System;
|
||||
using System.Collections.Generic;
|
||||
using System.IO;
|
||||
using System.Linq;
|
||||
using System.Threading;
|
||||
using System.Threading.Tasks;
|
||||
using AutopilotMonitor.Agent.V2.Core.Logging;
|
||||
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
using Newtonsoft.Json;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Tests.Harness
|
||||
{
|
||||
/// <summary>
|
||||
/// An <see cref="ImeLogTracker"/> fed the shipped IME pattern pack (<c>rules/ime-log-patterns</c>,
|
||||
/// sorted as combine.js embeds it) and a CMTrace <c>IntuneManagementExtension.log</c> the test
|
||||
/// appends to, so a test drives the real patterns end to end.
|
||||
/// </summary>
|
||||
internal sealed class ShippedImePackHarness : IDisposable
|
||||
{
|
||||
private readonly TempDirectory _tmp = new TempDirectory();
|
||||
|
||||
public ImeLogTracker Tracker { get; }
|
||||
public string StateDir { get; }
|
||||
public DateTime Now { get; } = new DateTime(2026, 9, 6, 12, 0, 0, DateTimeKind.Utc);
|
||||
|
||||
public ShippedImePackHarness()
|
||||
{
|
||||
StateDir = Path.Combine(_tmp.Path, "State");
|
||||
Tracker = Build();
|
||||
}
|
||||
|
||||
public static List<ImeLogPattern> Pack()
|
||||
=> Directory.GetFiles(Path.Combine(RepoPaths.Root(), "rules", "ime-log-patterns"), "*.json")
|
||||
.OrderBy(f => f, StringComparer.Ordinal)
|
||||
.Select(f => JsonConvert.DeserializeObject<ImeLogPattern>(File.ReadAllText(f))!)
|
||||
.ToList();
|
||||
|
||||
/// <summary>A second tracker on the same log and state folder (an agent restart).</summary>
|
||||
public ImeLogTracker Build()
|
||||
{
|
||||
var tracker = new ImeLogTracker(
|
||||
logFolder: _tmp.Path,
|
||||
patterns: Pack(),
|
||||
logger: new AgentLogger(_tmp.Path, AgentLogLevel.Info),
|
||||
stateDirectory: StateDir);
|
||||
// The historic-replay guard skips app-mutating actions for lines older than 24 h
|
||||
// relative to "now": pin both so the appended entries are always fresh.
|
||||
tracker.UtcNowProvider = () => Now;
|
||||
return tracker;
|
||||
}
|
||||
|
||||
public void Append(params string[] messages) => AppendAt(Now.AddSeconds(-60), messages);
|
||||
|
||||
/// <summary>Entries one second apart from <paramref name="firstUtc"/> (an older instant replays a previous enrollment).</summary>
|
||||
public void AppendAt(DateTime firstUtc, params string[] messages)
|
||||
{
|
||||
var lines = messages.Select((m, i) => Entry(m, firstUtc.AddSeconds(i)));
|
||||
File.AppendAllText(Path.Combine(_tmp.Path, "IntuneManagementExtension.log"),
|
||||
string.Join(Environment.NewLine, lines) + Environment.NewLine);
|
||||
}
|
||||
|
||||
public Task Pass() => Tracker.CheckLogFilesAsync(CancellationToken.None);
|
||||
|
||||
public void Dispose()
|
||||
{
|
||||
Tracker.Dispose();
|
||||
_tmp.Dispose();
|
||||
}
|
||||
|
||||
private static string Entry(string message, DateTime utcInstant)
|
||||
{
|
||||
// CMTrace line with a zero writer offset: the tracker reads the local time and
|
||||
// resolves it against the reader zone; only freshness (< 24 h) matters here.
|
||||
return $"<![LOG[{message}]LOG]!><time=\"{utcInstant:HH:mm:ss.fffffff}\" date=\"{utcInstant:M-d-yyyy}\" " +
|
||||
"component=\"IntuneManagementExtension\" context=\"\" type=\"1\" thread=\"1\" file=\"\">";
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -125,5 +125,74 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Logging
|
||||
// No assertion needed beyond "did not throw"; the regression we guard against is
|
||||
// the original swallow-all behaviour, which the rotation refactor must preserve.
|
||||
}
|
||||
|
||||
[Theory]
|
||||
[InlineData(AgentLogLevel.Info, "INFO")]
|
||||
[InlineData(AgentLogLevel.Debug, "INFO,DEBUG")]
|
||||
[InlineData(AgentLogLevel.Verbose, "INFO,DEBUG,VERBOSE")]
|
||||
[InlineData(AgentLogLevel.Trace, "INFO,DEBUG,VERBOSE,TRACE")]
|
||||
public void Each_level_adds_to_the_one_before_it(AgentLogLevel level, string expectedTags)
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var logger = new AgentLogger(tmp.Path, level);
|
||||
|
||||
logger.Info("line");
|
||||
logger.Debug("line");
|
||||
logger.Verbose("line");
|
||||
logger.Trace("line");
|
||||
|
||||
var tags = ReadLines(tmp.Path).Select(Tag);
|
||||
Assert.Equal(expectedTags, string.Join(",", tags));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void RepeatKey_sends_an_identical_repeat_to_trace_and_a_change_back_to_its_level()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var logger = new AgentLogger(tmp.Path, AgentLogLevel.Trace);
|
||||
|
||||
logger.Info("rule A ran", repeatKey: "rule:A");
|
||||
logger.Info("rule A ran", repeatKey: "rule:A");
|
||||
logger.Info("rule A ran again with new data", repeatKey: "rule:A");
|
||||
logger.Info("rule A ran", repeatKey: "rule:A");
|
||||
|
||||
Assert.Equal(new[] { "INFO", "TRACE", "INFO", "INFO" }, ReadLines(tmp.Path).Select(Tag).ToArray());
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void RepeatKey_keeps_subjects_apart()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var logger = new AgentLogger(tmp.Path, AgentLogLevel.Trace);
|
||||
|
||||
logger.Debug("scan failed: access denied", repeatKey: "scan:System");
|
||||
logger.Debug("scan failed: access denied", repeatKey: "scan:Application");
|
||||
logger.Debug("scan failed: access denied", repeatKey: "scan:System");
|
||||
|
||||
Assert.Equal(new[] { "DEBUG", "DEBUG", "TRACE" }, ReadLines(tmp.Path).Select(Tag).ToArray());
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void RepeatKey_does_not_remember_a_line_its_level_did_not_write()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var logger = new AgentLogger(tmp.Path, AgentLogLevel.Info);
|
||||
|
||||
logger.Debug("waiting for the policy", repeatKey: "hello.poll");
|
||||
logger.SetLogLevel(AgentLogLevel.Debug);
|
||||
logger.Debug("waiting for the policy", repeatKey: "hello.poll");
|
||||
|
||||
Assert.Equal(new[] { "DEBUG" }, ReadLines(tmp.Path).Select(Tag).ToArray());
|
||||
}
|
||||
|
||||
private static string[] ReadLines(string dir) =>
|
||||
File.ReadAllLines(Path.Combine(dir, BaseName + ".log"));
|
||||
|
||||
// "[2026-10-30 12:00:00.000] [INFO] message" -> "INFO"
|
||||
private static string Tag(string line)
|
||||
{
|
||||
var open = line.IndexOf("] [", StringComparison.Ordinal) + 3;
|
||||
return line.Substring(open, line.IndexOf(']', open) - open);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
+31
@@ -164,5 +164,36 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring
|
||||
var info = f.InfoEvent("hello_pin_status");
|
||||
Assert.Equal("false", info.Payload![SignalPayloadKeys.ImmediateUpload]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void A_throwing_HelloCompleted_handler_is_logged_and_the_completion_stands()
|
||||
{
|
||||
// The handler carries the Hello resolution to the decision engine; a fault there used
|
||||
// to vanish without a trace.
|
||||
using var f = new Fixture();
|
||||
f.Tracker.HelloCompleted += (_, _) => throw new InvalidOperationException("handler bug");
|
||||
|
||||
f.Tracker.ProcessHelloEvent(300, Fixed, "Microsoft-Windows-User Device Registration", isBackfill: false);
|
||||
|
||||
Assert.True(f.Tracker.IsHelloCompleted);
|
||||
f.InfoEvent("hello_provisioning_completed");
|
||||
Assert.Contains("[WARN] HelloTracker: HelloCompleted handler threw: handler bug", ReadLog(f));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void A_repeated_terminal_event_logs_COMPLETED_once()
|
||||
{
|
||||
// Live plus backfill deliver event 300 twice; only the first one completes Hello.
|
||||
using var f = new Fixture();
|
||||
|
||||
f.Tracker.ProcessHelloEvent(300, Fixed, "Microsoft-Windows-User Device Registration", isBackfill: false);
|
||||
f.Tracker.ProcessHelloEvent(300, Fixed, "Microsoft-Windows-User Device Registration", isBackfill: true);
|
||||
|
||||
var log = ReadLog(f);
|
||||
Assert.Single(log.Split('\n'), l => l.Contains("Windows Hello provisioning COMPLETED successfully"));
|
||||
}
|
||||
|
||||
private static string ReadLog(Fixture f) =>
|
||||
System.IO.File.ReadAllText(System.IO.Path.Combine(f.Tmp.Path, "agent.log"));
|
||||
}
|
||||
}
|
||||
|
||||
+18
@@ -270,6 +270,24 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
new[] { "id=" + Guid1, "to=InProgress" }
|
||||
};
|
||||
yield return new object[]
|
||||
{
|
||||
"IME-ERROR-REPORT",
|
||||
"[Win32App][ReportingManager] Execution state for app with id: " + Guid1 + " has been updated. Report delta: {\"EnforcementState\":{\"OldValue\":\"Success\",\"NewValue\":\"Error\"},\"EnforcementErrorCode\":{\"OldValue\":null,\"NewValue\":-2016345060}}",
|
||||
new[] { "id=" + Guid1, "from=Success", "to=Error", "errorCode=-2016345060" }
|
||||
};
|
||||
yield return new object[]
|
||||
{
|
||||
"IME-POST-INSTALL-DETECTION",
|
||||
"[Win32App][DetectionActionHandler] Policy with id: " + Guid1 + " is expected to have enforcement state: Detected.",
|
||||
new[] { "id=" + Guid1 }
|
||||
};
|
||||
yield return new object[]
|
||||
{
|
||||
"IME-POST-REBOOT-DETECTION",
|
||||
"[Win32App][ReportingManager] Execution state for app with id: " + Guid1 + " has been updated. Report delta: {\"EnforcementState\":{\"OldValue\":\"InProgressPendingReboot\",\"NewValue\":\"Success\"}}",
|
||||
new[] { "id=" + Guid1 }
|
||||
};
|
||||
yield return new object[]
|
||||
{
|
||||
"IME-TOKEN-FAILURE",
|
||||
"Failed to get AAD token. len = 34 using client id fc0f3af4-6835-4174-b806-f7db311fd2f3 and resource id 26a4ae64-5862-427f-a9b0-044e62572a4f, errorCode = 3399548929",
|
||||
|
||||
+229
@@ -0,0 +1,229 @@
|
||||
#nullable enable
|
||||
using System.Collections.Generic;
|
||||
using System.Linq;
|
||||
using System.Threading.Tasks;
|
||||
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
|
||||
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
|
||||
using Xunit;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
{
|
||||
/// <summary>
|
||||
/// IME's sequence per app, driven through the shipped pattern pack: the check before the
|
||||
/// install, the installer, "Execution state … Success", the check right after the install,
|
||||
/// and the final state (D-392).
|
||||
/// <list type="bullet">
|
||||
/// <item>When the check after the install does not find the app, IME flips Success → Error
|
||||
/// with EnforcementErrorCode -2016345060 (0x87D1041C) BEFORE it logs the check's
|
||||
/// result line; that code is IME's verdict and must reach the error transition.</item>
|
||||
/// <item>The check after the install is marked ("expected to have enforcement state:
|
||||
/// Detected"); its result is reported through OnPostInstallDetection, and
|
||||
/// detectionResult stays the check before the install.</item>
|
||||
/// <item>After an exit code that asked for a restart, that check decides nothing; the check
|
||||
/// after the restart (InProgressPendingReboot → Success) is the one reported.</item>
|
||||
/// </list>
|
||||
/// </summary>
|
||||
public sealed class ImeLogTrackerDetectionAfterInstallTests
|
||||
{
|
||||
private const string AppId = "5c95bf94-1cf4-4629-88d1-3f616e7a405c";
|
||||
private const string DependencyId = "9d2b8a71-4e0c-4f5a-a3c6-71b0e2d5c8f4";
|
||||
|
||||
private static string PhaseLine => "[Win32App] In EspPhase: DeviceSetup.";
|
||||
private static string CurrentAppLine => @"[Win32App] SetCurrentDirectory: C:\Windows\IMECache\" + AppId + "_1";
|
||||
|
||||
private static string DetectionResult(string state, string appId = AppId)
|
||||
=> "[Win32App][DetectionActionHandler] Detection for policy with id: " + appId +
|
||||
" resulted in action status: Success and detection state: " + state + ".";
|
||||
|
||||
private static string[] CheckAfterInstallMarkers() => new[]
|
||||
{
|
||||
"[Win32App][DetectionActionHandler] Detection running for policy with id: " + AppId + ".",
|
||||
"[Win32App][DetectionActionHandler] The last enforcement action was on policy with id: " + AppId + ".",
|
||||
"[Win32App][DetectionActionHandler] Policy with id: " + AppId + " is expected to have enforcement state: Detected.",
|
||||
};
|
||||
|
||||
private static string ExecutionDelta(string from, string to, string? errorCode = null)
|
||||
=> "[Win32App][ReportingManager] Execution state for app with id: " + AppId + " has been updated. Report delta: " +
|
||||
"{\"EnforcementState\":{\"OldValue\":\"" + from + "\",\"NewValue\":\"" + to + "\"}" +
|
||||
(errorCode == null ? "" : ",\"EnforcementErrorCode\":{\"OldValue\":null,\"NewValue\":" + errorCode + "}") + "}";
|
||||
|
||||
private sealed class Run
|
||||
{
|
||||
public ShippedImePackHarness Harness { get; } = new ShippedImePackHarness();
|
||||
public AppPackageState Package { get; } = new AppPackageState(AppId, 0);
|
||||
public List<(AppInstallationState To, string? Code)> Transitions { get; } = new List<(AppInstallationState, string?)>();
|
||||
public List<(string Detection, bool AfterReboot)> ChecksAfterInstall { get; } = new List<(string, bool)>();
|
||||
|
||||
public Run()
|
||||
{
|
||||
Package.UpdateState(AppInstallationState.Installing);
|
||||
Harness.Tracker.PackageStates.Add(Package);
|
||||
Harness.Tracker.OnAppStateChanged = (p, _, to) => { if (p.Id == AppId) Transitions.Add((to, p.ErrorCode)); };
|
||||
Harness.Tracker.OnPostInstallDetection = (p, detection, afterReboot, _) => ChecksAfterInstall.Add((detection, afterReboot));
|
||||
}
|
||||
|
||||
public void Lines(params string[] lines) => Harness.Append(lines);
|
||||
}
|
||||
|
||||
private static string[] CleanInstallThen(params string[] tail)
|
||||
{
|
||||
var lines = new List<string>
|
||||
{
|
||||
PhaseLine,
|
||||
DetectionResult("NotDetected"), // the check before the install
|
||||
ExecutionDelta("InProgress", "Success"), // IME holds this back until its check
|
||||
};
|
||||
lines.AddRange(CheckAfterInstallMarkers());
|
||||
lines.AddRange(tail);
|
||||
return lines.ToArray();
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Check_after_install_failing_carries_IMEs_code_on_the_error_transition()
|
||||
{
|
||||
var run = new Run();
|
||||
using (run.Harness)
|
||||
{
|
||||
run.Lines(CleanInstallThen(
|
||||
ExecutionDelta("Success", "Error", "-2016345060"),
|
||||
DetectionResult("NotDetected"))); // the check's own result line comes last
|
||||
|
||||
await run.Harness.Pass();
|
||||
|
||||
Assert.Equal(new[] { AppInstallationState.Installed, AppInstallationState.Error }, run.Transitions.Select(t => t.To));
|
||||
Assert.Equal("-2016345060", run.Transitions.Last().Code);
|
||||
Assert.Equal(AppInstallationState.Error, run.Package.InstallationState);
|
||||
Assert.Equal("IME-ERROR-REPORT", run.Package.ErrorPatternId);
|
||||
Assert.Equal(new[] { ("NotDetected", false) }, run.ChecksAfterInstall);
|
||||
Assert.Equal("NotDetected", run.Package.DetectionResult);
|
||||
}
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Check_after_a_clean_install_is_reported_and_detectionResult_stays_the_check_before()
|
||||
{
|
||||
var run = new Run();
|
||||
using (run.Harness)
|
||||
{
|
||||
run.Lines(CleanInstallThen(DetectionResult("Detected")));
|
||||
|
||||
await run.Harness.Pass();
|
||||
|
||||
Assert.Equal(new[] { ("Detected", false) }, run.ChecksAfterInstall);
|
||||
Assert.Equal("NotDetected", run.Package.DetectionResult);
|
||||
Assert.Equal(AppInstallationState.Installed, run.Package.InstallationState);
|
||||
}
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task A_different_version_found_after_the_install_is_reported_as_such()
|
||||
{
|
||||
var run = new Run();
|
||||
using (run.Harness)
|
||||
{
|
||||
run.Lines(CleanInstallThen(DetectionResult("DetectedDifferentVersion")));
|
||||
|
||||
await run.Harness.Pass();
|
||||
|
||||
Assert.Equal(new[] { ("DetectedDifferentVersion", false) }, run.ChecksAfterInstall);
|
||||
}
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task A_dependency_checked_in_the_same_run_is_no_check_after_its_install()
|
||||
{
|
||||
// IME checks every app of the dependency chain in the run after an install; only the
|
||||
// installed app carries the markers.
|
||||
var run = new Run();
|
||||
using (run.Harness)
|
||||
{
|
||||
var dependency = new AppPackageState(DependencyId, 1);
|
||||
run.Harness.Tracker.PackageStates.Add(dependency);
|
||||
run.Lines(CleanInstallThen(
|
||||
DetectionResult("Detected", DependencyId),
|
||||
DetectionResult("Detected")));
|
||||
|
||||
await run.Harness.Pass();
|
||||
|
||||
Assert.Equal(new[] { ("Detected", false) }, run.ChecksAfterInstall);
|
||||
Assert.Equal("Detected", dependency.DetectionResult);
|
||||
}
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task The_check_before_a_requested_restart_is_not_reported_the_one_after_it_is()
|
||||
{
|
||||
var run = new Run();
|
||||
using (run.Harness)
|
||||
{
|
||||
var beforeRestart = new List<string>
|
||||
{
|
||||
PhaseLine,
|
||||
CurrentAppLine,
|
||||
"[Win32App] lpExitCode 3010",
|
||||
"[Win32App] lpExitCode is defined as SoftReboot",
|
||||
ExecutionDelta("InProgress", "InProgressPendingReboot"),
|
||||
};
|
||||
beforeRestart.AddRange(CheckAfterInstallMarkers());
|
||||
beforeRestart.Add(DetectionResult("NotDetected")); // provisional: IME sets no error
|
||||
run.Lines(beforeRestart.ToArray());
|
||||
|
||||
await run.Harness.Pass();
|
||||
Assert.Empty(run.ChecksAfterInstall);
|
||||
|
||||
run.Lines(
|
||||
ExecutionDelta("InProgressPendingReboot", "Success"), // after the restart
|
||||
DetectionResult("Detected"));
|
||||
|
||||
await run.Harness.Pass();
|
||||
Assert.Equal(new[] { ("Detected", true) }, run.ChecksAfterInstall);
|
||||
}
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Lines_from_a_previous_enrollment_mark_nothing()
|
||||
{
|
||||
var run = new Run();
|
||||
using (run.Harness)
|
||||
{
|
||||
run.Harness.AppendAt(run.Harness.Now.AddDays(-2), CleanInstallThen(DetectionResult("Detected")));
|
||||
|
||||
await run.Harness.Pass();
|
||||
|
||||
Assert.Empty(run.ChecksAfterInstall);
|
||||
Assert.Null(run.Package.DetectionResult);
|
||||
}
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Other_IME_error_reports_carry_their_code_too()
|
||||
{
|
||||
// A download that fails is the app's first move to Error through the same line.
|
||||
var run = new Run();
|
||||
using (run.Harness)
|
||||
{
|
||||
run.Lines(PhaseLine, ExecutionDelta("InProgressDownloadCompleted", "Error", "-2145091577"));
|
||||
|
||||
await run.Harness.Pass();
|
||||
|
||||
Assert.Equal(AppInstallationState.Error, Assert.Single(run.Transitions).To);
|
||||
Assert.Equal("-2145091577", run.Package.ErrorCode);
|
||||
}
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Error_report_without_a_code_leaves_the_code_empty()
|
||||
{
|
||||
var run = new Run();
|
||||
using (run.Harness)
|
||||
{
|
||||
run.Lines(PhaseLine, ExecutionDelta("InProgress", "Error"));
|
||||
|
||||
await run.Harness.Pass();
|
||||
|
||||
Assert.Equal(AppInstallationState.Error, run.Package.InstallationState);
|
||||
Assert.True(string.IsNullOrEmpty(run.Package.ErrorCode));
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
+5
-79
@@ -1,15 +1,10 @@
|
||||
#nullable enable
|
||||
using System;
|
||||
using System.Collections.Generic;
|
||||
using System.IO;
|
||||
using System.Linq;
|
||||
using System.Threading;
|
||||
using System.Threading.Tasks;
|
||||
using AutopilotMonitor.Agent.V2.Core.Logging;
|
||||
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
|
||||
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
using Newtonsoft.Json;
|
||||
using Xunit;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
@@ -70,82 +65,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
|
||||
// ---------------------------------------------------------------- shipped pack, end to end
|
||||
|
||||
private static string FindRulesPatternDir()
|
||||
{
|
||||
var dir = new DirectoryInfo(AppContext.BaseDirectory);
|
||||
while (dir != null)
|
||||
{
|
||||
var candidate = Path.Combine(dir.FullName, "rules", "ime-log-patterns");
|
||||
if (Directory.Exists(candidate)) return candidate;
|
||||
dir = dir.Parent;
|
||||
}
|
||||
throw new DirectoryNotFoundException($"Could not locate rules/ime-log-patterns walking up from {AppContext.BaseDirectory}");
|
||||
}
|
||||
|
||||
/// <summary>The shipped pack, exactly as combine.js embeds it (sorted by file name).</summary>
|
||||
private static List<ImeLogPattern> ShippedPack()
|
||||
=> Directory.GetFiles(FindRulesPatternDir(), "*.json")
|
||||
.OrderBy(f => f, StringComparer.Ordinal)
|
||||
.Select(f => JsonConvert.DeserializeObject<ImeLogPattern>(File.ReadAllText(f))!)
|
||||
.ToList();
|
||||
|
||||
private static string Entry(string message, DateTime utcInstant)
|
||||
{
|
||||
// CMTrace line with a zero writer offset: the tracker reads the local time and
|
||||
// resolves it against the reader zone; only freshness (< 24 h) matters here.
|
||||
return $"<![LOG[{message}]LOG]!><time=\"{utcInstant:HH:mm:ss.fffffff}\" date=\"{utcInstant:M-d-yyyy}\" " +
|
||||
"component=\"IntuneManagementExtension\" context=\"\" type=\"1\" thread=\"1\" file=\"\">";
|
||||
}
|
||||
|
||||
private sealed class Harness : IDisposable
|
||||
{
|
||||
private readonly TempDirectory _tmp = new TempDirectory();
|
||||
public ImeLogTracker Tracker { get; }
|
||||
public string StateDir { get; }
|
||||
public DateTime Now { get; } = new DateTime(2026, 9, 6, 12, 0, 0, DateTimeKind.Utc);
|
||||
|
||||
public Harness()
|
||||
{
|
||||
StateDir = Path.Combine(_tmp.Path, "State");
|
||||
Tracker = Build();
|
||||
}
|
||||
|
||||
public ImeLogTracker Build()
|
||||
{
|
||||
var tracker = new ImeLogTracker(
|
||||
logFolder: _tmp.Path,
|
||||
patterns: ShippedPack(),
|
||||
logger: new AgentLogger(_tmp.Path, AgentLogLevel.Info),
|
||||
stateDirectory: StateDir);
|
||||
// The historic-replay guard skips app-mutating actions for lines older than 24 h
|
||||
// relative to "now": pin both so the CMTrace entries below are always fresh.
|
||||
tracker.UtcNowProvider = () => Now;
|
||||
return tracker;
|
||||
}
|
||||
|
||||
public void Append(params string[] messages)
|
||||
{
|
||||
var lines = messages.Select((m, i) => Entry(m, Now.AddSeconds(-60 + i)));
|
||||
File.AppendAllText(Path.Combine(_tmp.Path, "IntuneManagementExtension.log"),
|
||||
string.Join(Environment.NewLine, lines) + Environment.NewLine);
|
||||
}
|
||||
|
||||
public Task Pass() => Tracker.CheckLogFilesAsync(CancellationToken.None);
|
||||
|
||||
public void Dispose()
|
||||
{
|
||||
Tracker.Dispose();
|
||||
_tmp.Dispose();
|
||||
}
|
||||
}
|
||||
|
||||
private static string PhaseLine => "[Win32App] In EspPhase: DeviceSetup.";
|
||||
private static string CurrentAppLine => @"[Win32App] SetCurrentDirectory: C:\Windows\IMECache\" + AppId + "_1";
|
||||
|
||||
[Fact]
|
||||
public async Task Shipped_pattern_captures_the_class_for_the_current_app()
|
||||
{
|
||||
using var h = new Harness();
|
||||
using var h = new ShippedImePackHarness();
|
||||
h.Tracker.PackageStates.Add(new AppPackageState(AppId, 0));
|
||||
h.Append(
|
||||
PhaseLine, // activates the currentPhase pack (IME-EXITCODE, IME-EXITCODE-CLASS)
|
||||
@@ -165,7 +91,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
[Fact]
|
||||
public async Task Retry_loop_that_ends_in_success_reports_the_last_class()
|
||||
{
|
||||
using var h = new Harness();
|
||||
using var h = new ShippedImePackHarness();
|
||||
h.Tracker.PackageStates.Add(new AppPackageState(AppId, 0));
|
||||
h.Append(
|
||||
PhaseLine, CurrentAppLine,
|
||||
@@ -188,7 +114,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
{
|
||||
// IME-EXITCODE-CLASS and IME-EXITCODE-MAPPED-FAILED both match the Failed line: the
|
||||
// class is captured and the existing error path stays intact.
|
||||
using var h = new Harness();
|
||||
using var h = new ShippedImePackHarness();
|
||||
var pkg = new AppPackageState(AppId, 0);
|
||||
pkg.UpdateState(AppInstallationState.Installing);
|
||||
h.Tracker.PackageStates.Add(pkg);
|
||||
@@ -207,7 +133,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
[Fact]
|
||||
public async Task Default_branch_and_raw_numeric_types_leave_the_class_unset()
|
||||
{
|
||||
using var h = new Harness();
|
||||
using var h = new ShippedImePackHarness();
|
||||
h.Tracker.PackageStates.Add(new AppPackageState(AppId, 0));
|
||||
h.Append(
|
||||
PhaseLine, CurrentAppLine,
|
||||
@@ -228,7 +154,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
{
|
||||
// A SoftReboot/HardReboot app completes only after the reboot; the restarted agent
|
||||
// must still know the class when the post-reboot Success line arrives.
|
||||
using var h = new Harness();
|
||||
using var h = new ShippedImePackHarness();
|
||||
h.Tracker.PackageStates.Add(new AppPackageState(AppId, 0));
|
||||
h.Append(
|
||||
PhaseLine, CurrentAppLine,
|
||||
|
||||
+59
@@ -1,5 +1,6 @@
|
||||
using System;
|
||||
using System.Collections.Generic;
|
||||
using System.Linq;
|
||||
using AutopilotMonitor.Agent.V2.Core.Logging;
|
||||
using AutopilotMonitor.Agent.V2.Core.Orchestration;
|
||||
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
|
||||
@@ -304,6 +305,64 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Orchestration
|
||||
Assert.Same(step.NewState, sut.CurrentState);
|
||||
}
|
||||
|
||||
// ========================================================================= Step log levels
|
||||
|
||||
[Fact]
|
||||
public void ApplyStep_logs_a_stage_change_at_info()
|
||||
{
|
||||
using var rig = new Rig();
|
||||
rig.Logger.SetLogLevel(AgentLogLevel.Trace);
|
||||
var sut = rig.Build();
|
||||
var (step, signal) = rig.ReduceAbort(); // SessionStarted -> Failed
|
||||
|
||||
sut.ApplyStep(step, signal);
|
||||
|
||||
Assert.Contains(StepLines(rig), l => l.Contains("[INFO] DecisionStep:") && l.Contains("stage=SessionStarted->Failed"));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void ApplyStep_logs_informational_pass_through_and_no_op_at_trace()
|
||||
{
|
||||
using var rig = new Rig();
|
||||
rig.Logger.SetLogLevel(AgentLogLevel.Trace);
|
||||
var sut = rig.Build();
|
||||
|
||||
var (noOp, noOpSignal) = rig.ReduceSessionStarted(ordinal: 0);
|
||||
sut.ApplyStep(noOp, noOpSignal);
|
||||
var (info, infoSignal) = rig.ReduceInformational(sut, ordinal: 1);
|
||||
sut.ApplyStep(info, infoSignal);
|
||||
|
||||
var lines = StepLines(rig);
|
||||
Assert.Equal(2, lines.Length);
|
||||
Assert.All(lines, l => Assert.Contains("[TRACE] DecisionStep:", l));
|
||||
Assert.Contains("(no-op)", lines[0]);
|
||||
Assert.Contains("kind=InformationalEvent", lines[1]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void ApplyStep_logs_informational_pass_through_with_failed_effect_at_debug()
|
||||
{
|
||||
using var rig = new Rig();
|
||||
rig.Logger.SetLogLevel(AgentLogLevel.Trace);
|
||||
rig.Effects.ScriptResult(new EffectRunResult(
|
||||
sessionMustAbort: false,
|
||||
abortReason: null,
|
||||
failures: new[] { new EffectFailure(DecisionEffectKind.EmitEventTimelineEntry, "emit failed", isTransient: false, exhaustedRetries: true) },
|
||||
classifierInvocations: 0,
|
||||
classifierSkippedByAntiLoop: 0));
|
||||
var sut = rig.Build();
|
||||
var (step, signal) = rig.ReduceInformational(sut, ordinal: 0);
|
||||
|
||||
sut.ApplyStep(step, signal);
|
||||
|
||||
Assert.Contains(StepLines(rig), l => l.Contains("[DEBUG] DecisionStep:") && l.Contains("failures=1"));
|
||||
}
|
||||
|
||||
private static string[] StepLines(Rig rig) =>
|
||||
System.IO.File.ReadAllLines(System.IO.Path.Combine(rig.Tmp.Path, "agent.log"))
|
||||
.Where(l => l.Contains("DecisionStep:"))
|
||||
.ToArray();
|
||||
|
||||
// ========================================================================= Argument validation
|
||||
|
||||
[Fact]
|
||||
|
||||
+45
@@ -0,0 +1,45 @@
|
||||
using System;
|
||||
using System.IO;
|
||||
using System.Linq;
|
||||
using AutopilotMonitor.Agent.V2.Core.Logging;
|
||||
using AutopilotMonitor.Agent.V2.Core.Orchestration;
|
||||
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
using Xunit;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Tests.Orchestration
|
||||
{
|
||||
/// <summary>
|
||||
/// <see cref="TimelineEventStream.Publish"/> isolates subscribers: a throwing one must neither
|
||||
/// break the emit path nor starve the subscribers after it, and its fault must reach the log
|
||||
/// (Debug once, an identical repeat on Trace).
|
||||
/// </summary>
|
||||
public sealed class TimelineEventStreamTests
|
||||
{
|
||||
[Fact]
|
||||
public void A_throwing_subscriber_is_logged_and_the_next_one_still_runs()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var logger = new AgentLogger(tmp.Path, AgentLogLevel.Trace);
|
||||
var sut = new TimelineEventStream(logger);
|
||||
var delivered = 0;
|
||||
sut.EventEmitted += ThrowingSubscriber;
|
||||
sut.EventEmitted += (_, _, _) => delivered++;
|
||||
|
||||
sut.Publish("app_install_started", EnrollmentPhase.Unknown, "ImeLogTracker");
|
||||
sut.Publish("app_install_completed", EnrollmentPhase.Unknown, "ImeLogTracker");
|
||||
|
||||
Assert.Equal(2, delivered);
|
||||
var lines = File.ReadAllLines(Path.Combine(tmp.Path, "agent.log"))
|
||||
.Where(l => l.Contains("TimelineEventStream: subscriber"))
|
||||
.ToArray();
|
||||
Assert.Equal(2, lines.Length);
|
||||
Assert.Contains("[DEBUG]", lines[0]);
|
||||
Assert.Contains("ThrowingSubscriber threw: subscriber bug", lines[0]);
|
||||
Assert.Contains("[TRACE]", lines[1]);
|
||||
}
|
||||
|
||||
private static void ThrowingSubscriber(string eventType, EnrollmentPhase phase, string source) =>
|
||||
throw new InvalidOperationException("subscriber bug");
|
||||
}
|
||||
}
|
||||
@@ -2,7 +2,9 @@ using System;
|
||||
using System.Diagnostics;
|
||||
using System.Threading;
|
||||
using System.Threading.Tasks;
|
||||
using AutopilotMonitor.Agent.V2.Core.Logging;
|
||||
using AutopilotMonitor.Agent.V2.Core.Security;
|
||||
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
|
||||
using Xunit;
|
||||
|
||||
// xUnit1031 (no blocking Task.Wait in tests) intentionally suppressed — the API
|
||||
@@ -22,9 +24,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Security
|
||||
/// Drives <see cref="TenantIdAwaiter.WaitForTenantIdCore"/> through every interesting
|
||||
/// path with a fake <see cref="IRegistryChangeSignal"/> + scripted probe so the
|
||||
/// orchestration logic is verified without touching the registry. The public
|
||||
/// <see cref="TenantIdAwaiter.WaitForTenantId"/> wrapper isn't covered here — the
|
||||
/// HKCU integration test in <c>RegistryWatcherIntegrationTests</c> proves the
|
||||
/// CompositeRegistryChangeSignal / RegNotifyChangeKeyValue plumbing separately.
|
||||
/// <c>WaitForTenantId</c> wrapper is covered through its internal overload with a scripted
|
||||
/// resolver (which probes log); the HKCU integration test in
|
||||
/// <c>RegistryWatcherIntegrationTests</c> proves the CompositeRegistryChangeSignal /
|
||||
/// RegNotifyChangeKeyValue plumbing separately.
|
||||
/// <para>
|
||||
/// Single-threaded collection: these tests use <c>Thread.Sleep</c> as a synchronisation
|
||||
/// primitive (waiting for the awaiter to enter its WaitAny loop before triggering the
|
||||
@@ -258,5 +261,44 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Security
|
||||
logger: null!,
|
||||
ct: CancellationToken.None));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Initial_miss_never_probes_with_the_logger()
|
||||
{
|
||||
// AgentBootstrap probes with its logger before it calls the awaiter; the resolver's
|
||||
// miss block must not land a second time from the awaiter's own first check.
|
||||
using var tmp = new TempDirectory();
|
||||
var logger = new AgentLogger(tmp.Path, AgentLogLevel.Info);
|
||||
int loggedProbes = 0, silentProbes = 0;
|
||||
|
||||
var result = TenantIdAwaiter.WaitForTenantId(
|
||||
timeoutSeconds: 1,
|
||||
logger: logger,
|
||||
ct: CancellationToken.None,
|
||||
resolve: l => { if (l != null) loggedProbes++; else silentProbes++; return null!; },
|
||||
signalFactory: () => new FakeSignal());
|
||||
|
||||
Assert.Null(result);
|
||||
Assert.Equal(0, loggedProbes);
|
||||
Assert.True(silentProbes >= 1, $"expected a silent first check, saw {silentProbes}");
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Initial_hit_probes_once_more_with_the_logger_for_the_source_line()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var logger = new AgentLogger(tmp.Path, AgentLogLevel.Info);
|
||||
var loggedProbes = 0;
|
||||
|
||||
var result = TenantIdAwaiter.WaitForTenantId(
|
||||
timeoutSeconds: 600,
|
||||
logger: logger,
|
||||
ct: CancellationToken.None,
|
||||
resolve: l => { if (l != null) loggedProbes++; return "tenant-1"; },
|
||||
signalFactory: () => throw new InvalidOperationException("no wait expected on a hit"));
|
||||
|
||||
Assert.Equal("tenant-1", result);
|
||||
Assert.Equal(1, loggedProbes);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
+6
-1
@@ -258,13 +258,18 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.SignalAdapters
|
||||
using var f = new Fixture();
|
||||
using var adapter = new AadJoinWatcherAdapter(
|
||||
f.Watcher, f.Ingress, f.Clock,
|
||||
onRealUserJoined: () => throw new InvalidOperationException("boom"));
|
||||
onRealUserJoined: () => throw new InvalidOperationException("boom"),
|
||||
logger: f.Logger);
|
||||
|
||||
// The signal post completes BEFORE the callback fires — even if the callback
|
||||
// throws, the decision signal must already be on the bus.
|
||||
adapter.TriggerFromTest("alice@contoso.com", "x");
|
||||
|
||||
Assert.Single(f.Ingress.Posted, p => p.Kind == DecisionSignalKind.AadUserJoinedLate);
|
||||
// ...and the fault is in the log instead of vanishing.
|
||||
Assert.Contains(
|
||||
"[WARN] AadJoinWatcherAdapter: onRealUserJoined callback threw: boom",
|
||||
System.IO.File.ReadAllText(System.IO.Path.Combine(f.Tmp.Path, "agent.log")));
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
+15
@@ -92,6 +92,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.SignalAdapters
|
||||
Assert.Equal(ClockNow.AddMinutes(-1), info.OccurredAtUtc);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Stale_post_install_detection_is_suppressed_fresh_emits()
|
||||
{
|
||||
using var f = new ImeLogTrackerAdapterFixture(ClockNow);
|
||||
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
|
||||
var app = new AppPackageState("app-check", 0);
|
||||
|
||||
adapter.TriggerPostInstallDetectionFromTest(app, "Detected", afterReboot: false, ClockNow.AddDays(-7));
|
||||
Assert.Empty(f.InfoEvents(SharedEventTypes.AppPostInstallDetection));
|
||||
|
||||
adapter.TriggerPostInstallDetectionFromTest(app, "Detected", afterReboot: false, ClockNow.AddMinutes(-1));
|
||||
var info = Assert.Single(f.InfoEvents(SharedEventTypes.AppPostInstallDetection));
|
||||
Assert.Equal(ClockNow.AddMinutes(-1), info.OccurredAtUtc);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Poll_driven_do_telemetry_stamps_clock_ignoring_unrelated_last_matched_line()
|
||||
{
|
||||
|
||||
+44
@@ -663,6 +663,50 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.SignalAdapters
|
||||
Assert.Equal("00:01:45.159", info.Payload["doDownloadDuration"]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void PostInstallDetection_emits_the_check_after_the_install_as_its_own_info_event()
|
||||
{
|
||||
using var f = new ImeLogTrackerAdapterFixture();
|
||||
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
|
||||
var app = AppPackageState.Restore(
|
||||
"0e3be4ce-790b-4081-831c-d72d92f3cc9b", 0, "Contoso VPN",
|
||||
AppRunAs.System, AppIntent.Install, AppTargeted.Device,
|
||||
new HashSet<string>(),
|
||||
AppInstallationState.Installed, true, 100, 0, 0,
|
||||
exitCode: "0", exitCodeClass: "Success");
|
||||
|
||||
adapter.TriggerPostInstallDetectionFromTest(app, "Detected", afterReboot: false, f.Clock.UtcNow.AddSeconds(-5));
|
||||
|
||||
var info = Assert.Single(f.InfoEvents(SharedEventTypes.AppPostInstallDetection));
|
||||
Assert.Equal("ImeLogTracker", info.Payload![SignalPayloadKeys.Source]);
|
||||
Assert.Equal(EventSeverity.Info.ToString(), info.Payload[SignalPayloadKeys.Severity]);
|
||||
Assert.Equal(app.Id, info.Payload["appId"]);
|
||||
Assert.Equal("Contoso VPN", info.Payload["appName"]);
|
||||
Assert.Equal("Detected", info.Payload["postInstallDetection"]);
|
||||
Assert.Equal("false", info.Payload["afterReboot"]);
|
||||
Assert.Equal("Success", info.Payload["exitCodeClass"]);
|
||||
// detectionResult is the check before the install; this event never carries it.
|
||||
Assert.False(info.Payload.ContainsKey("detectionResult"));
|
||||
// Informational only: no app state signal.
|
||||
Assert.Empty(f.DecisionSignals(DecisionSignalKind.AppInstallCompleted));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void PostInstallDetection_not_detected_is_a_warning_and_the_check_after_a_restart_says_so()
|
||||
{
|
||||
using var f = new ImeLogTrackerAdapterFixture();
|
||||
using var adapter = new ImeLogTrackerAdapter(f.Tracker, f.Ingress, f.Clock);
|
||||
var app = new AppPackageState("8a1c2f6e-5b7d-4e93-9c4a-0f2d6b8e1a37", 0);
|
||||
|
||||
adapter.TriggerPostInstallDetectionFromTest(app, "NotDetected", afterReboot: true, f.Clock.UtcNow.AddSeconds(-5));
|
||||
|
||||
var info = Assert.Single(f.InfoEvents(SharedEventTypes.AppPostInstallDetection));
|
||||
Assert.Equal(EventSeverity.Warning.ToString(), info.Payload![SignalPayloadKeys.Severity]);
|
||||
Assert.Equal("NotDetected", info.Payload["postInstallDetection"]);
|
||||
Assert.Equal("true", info.Payload["afterReboot"]);
|
||||
Assert.Contains("after the restart", info.Payload[SignalPayloadKeys.Message]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void DoTelemetry_null_app_or_empty_id_is_ignored()
|
||||
{
|
||||
|
||||
+41
@@ -126,6 +126,47 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Telemetry
|
||||
Assert.Equal(2, collector.CollectInvocationCount);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Stop_then_Dispose_logs_Stopped_once()
|
||||
{
|
||||
// Hosts call Stop and then Dispose, which stops again; the log used to show
|
||||
// "[X] Stopped" twice in the same millisecond.
|
||||
using var tmp = new TempDirectory();
|
||||
var collector = new BlockingCollector(NewPost(), NewLogger(tmp));
|
||||
|
||||
collector.Start();
|
||||
collector.Stop();
|
||||
collector.Dispose();
|
||||
|
||||
var log = File.ReadAllText(Path.Combine(tmp.Path, "logs", "agent.log"));
|
||||
Assert.Equal(1, CountOccurrences(log, "[BlockingCollector] Stopped"));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Dispose_without_Start_logs_no_Stopped_line()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var logger = NewLogger(tmp);
|
||||
var collector = new BlockingCollector(NewPost(), logger);
|
||||
logger.Info("marker"); // make sure the log file exists
|
||||
|
||||
collector.Dispose();
|
||||
|
||||
var log = File.ReadAllText(Path.Combine(tmp.Path, "logs", "agent.log"));
|
||||
Assert.DoesNotContain("[BlockingCollector] Stopped", log);
|
||||
}
|
||||
|
||||
private static int CountOccurrences(string text, string value)
|
||||
{
|
||||
int count = 0, index = 0;
|
||||
while ((index = text.IndexOf(value, index, StringComparison.Ordinal)) >= 0)
|
||||
{
|
||||
count++;
|
||||
index += value.Length;
|
||||
}
|
||||
return count;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Test-only collector subclass: signals when <see cref="Collect"/> is entered and
|
||||
/// blocks until the test releases it, so we can exercise the reentrancy gate
|
||||
|
||||
+32
-9
@@ -14,8 +14,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Transport
|
||||
{
|
||||
/// <summary>
|
||||
/// <see cref="BackendTelemetryUploader"/> emits upload-cadence log lines (flushing / ingest
|
||||
/// OK / ingest TRANSIENT / ingest PERMANENT) so the transport path is observable. The
|
||||
/// success-path lines (flushing, ingest OK) are pipeline mechanics and live on Debug;
|
||||
/// OK / ingest TRANSIENT / ingest PERMANENT) so the transport path is observable. The send
|
||||
/// ("flushing") is mechanics and lives on Trace, the success record ("ingest OK") on Verbose;
|
||||
/// failures (TRANSIENT/PERMANENT/TIMEOUT/NETWORK) live on Warning/Error and remain
|
||||
/// visible at the default Info level. We assert on log-file content because AgentLogger
|
||||
/// writes to disk; checking the file is the most faithful production proxy.
|
||||
@@ -54,11 +54,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Transport
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task UploadBatch_logs_flush_start_and_ingest_OK_on_success_at_debug()
|
||||
public async Task UploadBatch_logs_flush_start_at_trace_and_ingest_OK_at_verbose()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
// Success-path transport lines live on Debug; capture at that level to assert them.
|
||||
var logger = new AgentLogger(tmp.Path, AgentLogLevel.Debug);
|
||||
var logger = new AgentLogger(tmp.Path, AgentLogLevel.Trace);
|
||||
|
||||
var handler = new RecordingHttpMessageHandler();
|
||||
handler.QueueStatus(HttpStatusCode.OK);
|
||||
@@ -75,11 +74,35 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Transport
|
||||
|
||||
// AgentLogger writes each line with File.AppendAllText — content is already on disk.
|
||||
var logContent = ReadLogs(tmp.Path);
|
||||
Assert.Contains("BackendTelemetryUploader: flushing 2 item(s)", logContent);
|
||||
// Each upload now carries a per-request correlation id (X-Correlation-ID) for
|
||||
// end-to-end tracing; it precedes the item count in the cadence log lines.
|
||||
Assert.Contains("[TRACE] BackendTelemetryUploader: flushing 2 item(s)", logContent);
|
||||
// Each upload carries a per-request correlation id (X-Correlation-ID) for end-to-end
|
||||
// tracing; the success record carries the batch's item range so it stands alone.
|
||||
Assert.Contains("[VERBOSE] BackendTelemetryUploader: ingest OK (corr=", logContent);
|
||||
Assert.Contains("items=2, firstId=1, lastId=2, bytes=", logContent);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task UploadBatch_success_at_verbose_logs_the_record_without_the_send_line()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var logger = new AgentLogger(tmp.Path, AgentLogLevel.Verbose);
|
||||
|
||||
var handler = new RecordingHttpMessageHandler();
|
||||
handler.QueueStatus(HttpStatusCode.OK);
|
||||
using var http = new HttpClient(handler) { Timeout = TimeSpan.FromSeconds(30) };
|
||||
|
||||
var sut = new BackendTelemetryUploader(
|
||||
httpClient: http,
|
||||
baseUrl: "https://backend.test",
|
||||
tenantId: "T1",
|
||||
logger: logger);
|
||||
|
||||
var result = await sut.UploadBatchAsync(new[] { NewEventItem(1) }, CancellationToken.None);
|
||||
Assert.True(result.Success);
|
||||
|
||||
var logContent = ReadLogs(tmp.Path);
|
||||
Assert.DoesNotContain("BackendTelemetryUploader: flushing", logContent);
|
||||
Assert.Contains("BackendTelemetryUploader: ingest OK (corr=", logContent);
|
||||
Assert.Contains("items=2", logContent);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
|
||||
+10
-3
@@ -3,6 +3,7 @@ using System;
|
||||
using System.Collections.Generic;
|
||||
using System.Threading;
|
||||
using System.Threading.Tasks;
|
||||
using AutopilotMonitor.Agent.V2.Core.Logging;
|
||||
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
|
||||
using AutopilotMonitor.Agent.V2.Core.Transport.Telemetry;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
@@ -33,10 +34,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Transport
|
||||
public FakeBackendTelemetryUploader Uploader { get; } = new FakeBackendTelemetryUploader();
|
||||
public TelemetryUploadOrchestrator Sut { get; }
|
||||
|
||||
public Rig()
|
||||
public Rig(AgentLogger? logger = null)
|
||||
{
|
||||
Spool = new TelemetrySpool(Tmp.Path, Clock);
|
||||
Sut = new TelemetryUploadOrchestrator(Spool, Uploader, Clock, batchSize: 10, retryBackoffs: new[] { TimeSpan.Zero });
|
||||
Sut = new TelemetryUploadOrchestrator(Spool, Uploader, Clock, batchSize: 10, retryBackoffs: new[] { TimeSpan.Zero }, logger: logger);
|
||||
}
|
||||
|
||||
public void Dispose() { Sut.Dispose(); Tmp.Dispose(); }
|
||||
@@ -140,7 +141,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Transport
|
||||
[Fact]
|
||||
public async Task Handler_exception_does_not_break_drain_cursor()
|
||||
{
|
||||
using var rig = new Rig();
|
||||
using var logTmp = new TempDirectory();
|
||||
var logger = new AgentLogger(logTmp.Path, AgentLogLevel.Info);
|
||||
using var rig = new Rig(logger);
|
||||
rig.Sut.Enqueue(Draft());
|
||||
rig.Uploader.QueueOkWithSignals(deviceKillSignal: true);
|
||||
|
||||
@@ -150,6 +153,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Transport
|
||||
// Upload still succeeded — the cursor moves, drain returns success.
|
||||
Assert.Equal(1, drain.UploadedItems);
|
||||
Assert.Equal(0, drain.FailedBatches);
|
||||
// The handler fault is no longer silent.
|
||||
Assert.Contains(
|
||||
"[WARN] TelemetryUploadOrchestrator: ServerResponseReceived handler threw: handler bug",
|
||||
System.IO.File.ReadAllText(System.IO.Path.Combine(logTmp.Path, "agent.log")));
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
|
||||
@@ -53,7 +53,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Configuration
|
||||
|
||||
|
||||
/// <summary>
|
||||
/// Log verbosity level: Info (default), Debug, Verbose.
|
||||
/// Log verbosity level: Info (default), Debug, Verbose, Trace (see <see cref="AgentLogLevel"/>).
|
||||
/// Overridable via remote config.
|
||||
/// </summary>
|
||||
public AgentLogLevel LogLevel { get; set; } = AgentLogLevel.Info;
|
||||
|
||||
@@ -151,9 +151,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Configuration
|
||||
try
|
||||
{
|
||||
if (attempt == 1)
|
||||
_logger.Info("Fetching remote configuration from backend...");
|
||||
_logger.Debug("Fetching remote configuration from backend...");
|
||||
else
|
||||
_logger.Info($"Fetching remote configuration from backend (attempt {attempt}/{maxAttempts})...");
|
||||
_logger.Debug($"Fetching remote configuration from backend (attempt {attempt}/{maxAttempts})...");
|
||||
|
||||
var config = await CallBackendAsync();
|
||||
|
||||
@@ -208,7 +208,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Configuration
|
||||
if (attempt < maxAttempts)
|
||||
{
|
||||
var delay = InitialFetchRetryBackoff[attempt - 1];
|
||||
_logger.Info($"Retrying remote config fetch in {delay.TotalSeconds:0}s...");
|
||||
_logger.Debug($"Retrying remote config fetch in {delay.TotalSeconds:0}s...");
|
||||
try { await DelayBetweenAttemptsAsync(delay); }
|
||||
catch (TaskCanceledException) { break; }
|
||||
}
|
||||
|
||||
@@ -1,13 +1,24 @@
|
||||
using System;
|
||||
using System.Collections.Concurrent;
|
||||
using System.IO;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Logging
|
||||
{
|
||||
/// <summary>
|
||||
/// Log verbosity levels for the agent.
|
||||
/// Info = normal operational messages (default)
|
||||
/// Debug = includes DEBUG-tagged lines (component state, config, decisions)
|
||||
/// Verbose = includes VERBOSE-tagged lines (per-event details, hot-path tracing)
|
||||
/// Log verbosity levels for the agent. Each level adds to the one before it.
|
||||
/// Info = the enrollment flow an admin follows: one line per thing that happened
|
||||
/// (state change, milestone, result), repeated only when its content changed.
|
||||
/// Debug = why and how: decision details, extra attributes, suppression decisions,
|
||||
/// attempts in retry loops. Grows with the number of apps, scripts and phases,
|
||||
/// not with elapsed time.
|
||||
/// Verbose = everything known about one thing: full payloads, raw JSON, adapter mappings,
|
||||
/// the record of each upload batch. Every line carries content of its own.
|
||||
/// Trace = the mechanics: watcher arm/fire, poll ticks without a result, debounce,
|
||||
/// per-item enqueue, per-signal pass-through. Grows with time or with the number
|
||||
/// of notifications; one line alone says almost nothing.
|
||||
/// An identical repeat of a line goes to Trace after its first occurrence (repeatKey).
|
||||
/// A caught unexpected exception is never logged below Debug. Warning and Error are always
|
||||
/// written.
|
||||
/// </summary>
|
||||
public enum AgentLogLevel
|
||||
{
|
||||
@@ -32,6 +43,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Logging
|
||||
private AgentLogLevel _logLevel;
|
||||
private readonly object _lockObject = new object();
|
||||
|
||||
// Last message written under each repeatKey; bounded because callers key by call site
|
||||
// plus subject (rule, category, file, policy).
|
||||
private readonly ConcurrentDictionary<string, string> _lastMessageByRepeatKey =
|
||||
new ConcurrentDictionary<string, string>(StringComparer.Ordinal);
|
||||
|
||||
private readonly long _maxFileSizeBytes;
|
||||
private readonly string _logDirectory;
|
||||
private readonly string _logFileBaseName; // "agent"
|
||||
@@ -122,21 +138,48 @@ namespace AutopilotMonitor.Agent.V2.Core.Logging
|
||||
Log("TRACE", message);
|
||||
}
|
||||
|
||||
public void Verbose(string message)
|
||||
/// <param name="repeatKey">Names the call site and its subject. A message equal to the
|
||||
/// last one written under this key goes to Trace instead.</param>
|
||||
public void Verbose(string message, string repeatKey = null)
|
||||
{
|
||||
if (_logLevel >= AgentLogLevel.Verbose)
|
||||
Log("VERBOSE", message);
|
||||
if (_logLevel < AgentLogLevel.Verbose) return;
|
||||
if (IsRepeat(repeatKey, message)) Trace(message);
|
||||
else Log("VERBOSE", message);
|
||||
}
|
||||
|
||||
public void Debug(string message)
|
||||
/// <param name="repeatKey">Names the call site and its subject. A message equal to the
|
||||
/// last one written under this key goes to Trace instead.</param>
|
||||
public void Debug(string message, string repeatKey = null)
|
||||
{
|
||||
if (_logLevel >= AgentLogLevel.Debug)
|
||||
Log("DEBUG", message);
|
||||
if (_logLevel < AgentLogLevel.Debug) return;
|
||||
if (IsRepeat(repeatKey, message)) Trace(message);
|
||||
else Log("DEBUG", message);
|
||||
}
|
||||
|
||||
public void Info(string message)
|
||||
/// <param name="repeatKey">Names the call site and its subject. A message equal to the
|
||||
/// last one written under this key goes to Trace instead.</param>
|
||||
public void Info(string message, string repeatKey = null)
|
||||
{
|
||||
Log("INFO", message);
|
||||
if (IsRepeat(repeatKey, message)) Trace(message);
|
||||
else Log("INFO", message);
|
||||
}
|
||||
|
||||
// Records the message under the key and reports whether it equals the previous one.
|
||||
// Only reached once the requested level is enabled, so a line that was never written
|
||||
// cannot turn its first visible occurrence into a repeat.
|
||||
private bool IsRepeat(string repeatKey, string message)
|
||||
{
|
||||
if (repeatKey == null) return false;
|
||||
var repeat = false;
|
||||
_lastMessageByRepeatKey.AddOrUpdate(
|
||||
repeatKey,
|
||||
message,
|
||||
(_, previous) =>
|
||||
{
|
||||
repeat = string.Equals(previous, message, StringComparison.Ordinal);
|
||||
return message;
|
||||
});
|
||||
return repeat;
|
||||
}
|
||||
|
||||
public void Warning(string message)
|
||||
|
||||
+5
-1
@@ -114,7 +114,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
public string AppType { get; private set; }
|
||||
/// <summary>Install attempt number (1 = first try). Increments on each "Execute retry N" line per check-in cycle.</summary>
|
||||
public int AttemptNumber { get; private set; }
|
||||
/// <summary>Detection rule result: "Detected" or "NotDetected". From DetectionActionHandler log lines.</summary>
|
||||
/// <summary>
|
||||
/// IME's detection check outside the check right after an install: Detected, NotDetected or
|
||||
/// DetectedDifferentVersion — for an app being installed, the check before the install. The
|
||||
/// check after the install is reported through OnPostInstallDetection instead (D-392).
|
||||
/// </summary>
|
||||
public string DetectionResult { get; private set; }
|
||||
|
||||
// Delivery Optimization telemetry (populated from [DO TEL] log entries OR Get-DeliveryOptimizationStatus poll)
|
||||
|
||||
+1
-1
@@ -426,7 +426,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
if (_logger == null) return;
|
||||
var stateList = string.Join(", ", this.Select(x => $"{x.Name ?? x.Id}:{x.InstallationState}"));
|
||||
_logger.Debug($"App states [{Count}]: {stateList}");
|
||||
_logger.Verbose($"App states [{Count}]: {stateList}");
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
+62
-25
@@ -19,7 +19,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
public partial class ImeLogTracker
|
||||
{
|
||||
// PR3-A2: dedup state for `IME impersonation` lines. ~24 identical per session at
|
||||
// DEBUG flooded the log; we now emit on user change + a 60s rollup with the count.
|
||||
// DEBUG flooded the log; a user change logs at Debug, the 60s rollup with the count at Trace.
|
||||
private string _lastImpersonationUser;
|
||||
private int _impersonationRepeatCount;
|
||||
private DateTime _impersonationLastRollupUtc = DateTime.MinValue;
|
||||
@@ -111,12 +111,45 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
var now = DateTime.UtcNow;
|
||||
if (now - _impersonationLastRollupUtc >= ImpersonationRollupInterval)
|
||||
{
|
||||
_logger.Debug($"IME impersonation: same as before (user='{current}', n={_impersonationRepeatCount} since last rollup)");
|
||||
_logger.Trace($"IME impersonation: same as before (user='{current}', n={_impersonationRepeatCount} since last rollup)");
|
||||
_impersonationLastRollupUtc = now;
|
||||
_impersonationRepeatCount = 0;
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Info for what a line of this enrollment reports. A line replayed from a previous
|
||||
/// enrollment's log (historic-replay guard) is context, not progress: Debug. Only for
|
||||
/// handlers that run while that line is processed, since the flag describes the line.
|
||||
/// </summary>
|
||||
private void LogLineActivity(string message, string repeatKey = null)
|
||||
{
|
||||
if (_currentLineIsHistoricReplay) _logger.Debug(message + " (historic line)", repeatKey);
|
||||
else _logger.Info(message, repeatKey);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Result of IME's check right after an install (D-392). After an exit code that asked for a
|
||||
/// restart that check decides nothing: IME sets no error then and checks again after the
|
||||
/// restart (IME-POST-REBOOT-DETECTION marks that check), so it is not reported.
|
||||
/// </summary>
|
||||
private void HandlePostInstallDetection(string appId, string detection, bool afterReboot)
|
||||
{
|
||||
var pkg = _packageStates.GetPackage(appId);
|
||||
if (pkg == null) return;
|
||||
if (!afterReboot
|
||||
&& (string.Equals(pkg.ExitCodeClass, "SoftReboot", StringComparison.OrdinalIgnoreCase)
|
||||
|| string.Equals(pkg.ExitCodeClass, "HardReboot", StringComparison.OrdinalIgnoreCase)))
|
||||
{
|
||||
_logger.Debug($"ImeLogTracker: check after the install of {pkg.Name ?? appId} precedes the requested restart ({detection}), IME decides after it");
|
||||
return;
|
||||
}
|
||||
|
||||
_logger.Info($"ImeLogTracker: check after the install of {pkg.Name ?? appId}: {detection}{(afterReboot ? " (after the restart)" : string.Empty)}");
|
||||
try { OnPostInstallDetection?.Invoke(pkg, detection, afterReboot, LastMatchedLogTimestamp); }
|
||||
catch (Exception ex) { _logger.Warning($"OnPostInstallDetection handler threw: {ex.Message}"); }
|
||||
}
|
||||
|
||||
private void HandleDoTelemetry(string json)
|
||||
{
|
||||
try
|
||||
@@ -254,7 +287,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// map). Prefer the source CMTrace timestamp; latest start wins on a policy re-run.
|
||||
var startedAtUtc = LastMatchedLogTimestamp ?? UtcNowProvider();
|
||||
_healthScriptStartTimes[id] = (startedAtUtc, CaptureLastMatchedProvenance());
|
||||
_logger.Info($"ImeLogTracker: health script started: {id}");
|
||||
LogLineActivity($"ImeLogTracker: health script started: {id}", repeatKey: "ImeLogTracker.hsStarted:" + id);
|
||||
|
||||
// A replayed line of a previous enrollment bypasses the recurrence gate: the
|
||||
// adapter drops its event, and a dropped run must not count as the policy's
|
||||
@@ -263,7 +296,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
&& !_recurringScripts.OnStart(id, startedAtUtc, policyType, LastMatchedPatternId))
|
||||
{
|
||||
_stateDirty = true;
|
||||
_logger.Debug($"ImeLogTracker: health script {id} is a recurring policy — start held until its result is known");
|
||||
_logger.Debug($"ImeLogTracker: health script {id} is a recurring policy — start held until its result is known", repeatKey: "ImeLogTracker.hsStartHeld:" + id);
|
||||
return;
|
||||
}
|
||||
_stateDirty = true;
|
||||
@@ -479,7 +512,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
RecordInvocationMarker(null, isClose: false);
|
||||
NoteInvocationActivity();
|
||||
if (!string.IsNullOrEmpty(kind) && !string.Equals(kind, "powershell", StringComparison.OrdinalIgnoreCase))
|
||||
_logger.Debug($"ImeLogTracker: AgentExecutor invocation of kind '{kind}' — exit/output lines not captured as a platform script");
|
||||
_logger.Trace($"ImeLogTracker: AgentExecutor invocation of kind '{kind}' — exit/output lines not captured as a platform script");
|
||||
}
|
||||
|
||||
private void HandleAgentExecutorCompleted()
|
||||
@@ -1054,10 +1087,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
DurationBasis = "script_runtime",
|
||||
};
|
||||
|
||||
_logger.Info($"ImeLogTracker: health-script {scriptPart} early-signal for {id}: " +
|
||||
$"compliance={compliance}, exit={exitCode}, " +
|
||||
$"stdout={(stdout == null ? "n/a" : stdout.Length + " chars")}, " +
|
||||
$"stderr={(stderr == null ? "n/a" : stderr.Length + " chars")}");
|
||||
LogLineActivity($"ImeLogTracker: health-script {scriptPart} early-signal for {id}: " +
|
||||
$"compliance={compliance}, exit={exitCode}, " +
|
||||
$"stdout={(stdout == null ? "n/a" : stdout.Length + " chars")}, " +
|
||||
$"stderr={(stderr == null ? "n/a" : stderr.Length + " chars")}",
|
||||
repeatKey: "ImeLogTracker.hsEarly:" + scriptPart + ":" + id);
|
||||
|
||||
EmitScriptEvent(enriched);
|
||||
|
||||
@@ -1281,11 +1315,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
EmitScriptEvent(postDetection);
|
||||
}
|
||||
|
||||
_logger.Info($"ImeLogTracker: health-script result emitted for {policyId} " +
|
||||
$"(status={remediationStatus?.ToString() ?? "?"}, " +
|
||||
$"firstDetectExit={firstDetectExit?.ToString() ?? "n/a"}, " +
|
||||
$"remediationExit={remediationExit?.ToString() ?? "n/a"}, " +
|
||||
$"lastDetectExit={lastDetectExit?.ToString() ?? "n/a"})");
|
||||
// "result for", not "emitted": the recurrence gate in EmitScriptEvent may hold a
|
||||
// repeat back and logs that itself.
|
||||
LogLineActivity($"ImeLogTracker: health-script result for {policyId} " +
|
||||
$"(status={remediationStatus?.ToString() ?? "?"}, " +
|
||||
$"firstDetectExit={firstDetectExit?.ToString() ?? "n/a"}, " +
|
||||
$"remediationExit={remediationExit?.ToString() ?? "n/a"}, " +
|
||||
$"lastDetectExit={lastDetectExit?.ToString() ?? "n/a"})",
|
||||
repeatKey: "ImeLogTracker.hsResult:" + policyId);
|
||||
}
|
||||
|
||||
private static ScriptExecutionState BuildHealthScriptPhase(
|
||||
@@ -1355,7 +1392,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
_stateDirty = true;
|
||||
if (!emit)
|
||||
{
|
||||
_logger.Debug($"ImeLogTracker: health script {script.PolicyId} {script.ScriptPart} repeats its last reported result — counted, not emitted");
|
||||
_logger.Debug($"ImeLogTracker: health script {script.PolicyId} {script.ScriptPart} repeats its last reported result — counted, not emitted", repeatKey: "ImeLogTracker.hsRepeat:" + script.PolicyId + ":" + script.ScriptPart);
|
||||
return;
|
||||
}
|
||||
if (releasedStart != null) RaiseScriptStarted(releasedStart);
|
||||
@@ -1411,7 +1448,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
private void HandleImeStarted()
|
||||
{
|
||||
_logger.Info("ImeLogTracker: IME Agent Started detected");
|
||||
LogLineActivity("ImeLogTracker: IME Agent Started detected");
|
||||
|
||||
// Log any currently active app — it will be re-evaluated by new log entries after IME restart.
|
||||
// We intentionally do NOT mark it as Installed here because IME may retry the app.
|
||||
@@ -1487,11 +1524,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
_logger.Debug(
|
||||
"ImeLogTracker: zero-app user session observed before the user ESP phase " +
|
||||
$"(current phase: {_lastEspPhaseDetected ?? "(none)"}) - deferring until AccountSetup");
|
||||
$"(current phase: {_lastEspPhaseDetected ?? "(none)"}) - deferring until AccountSetup", repeatKey: "ImeLogTracker.zeroAppDeferred");
|
||||
return;
|
||||
}
|
||||
|
||||
_logger.Info("ImeLogTracker: user session enumerated with zero targeted apps - treating as user session completed");
|
||||
_logger.Info("ImeLogTracker: user session enumerated with zero targeted apps - treating as user session completed", repeatKey: "ImeLogTracker.zeroAppUserSession");
|
||||
OnUserSessionCompleted?.Invoke();
|
||||
}
|
||||
|
||||
@@ -1509,7 +1546,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// which would corrupt tracking if we allowed it to trigger a phase change.
|
||||
if (phaseOrd < _currentPhaseOrder)
|
||||
{
|
||||
_logger.Debug($"ImeLogTracker: ignoring backward phase transition to {espPhaseString} (current phase order: {_currentPhaseOrder})");
|
||||
_logger.Trace($"ImeLogTracker: ignoring backward phase transition to {espPhaseString} (current phase order: {_currentPhaseOrder})");
|
||||
return;
|
||||
}
|
||||
|
||||
@@ -1550,7 +1587,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
_phasePackageSnapshots[_lastEspPhaseDetected] =
|
||||
new List<AppPackageState>(_packageStates);
|
||||
_logger.Info($"ImeLogTracker: Snapshotted {_packageStates.CountAll} package states from {_lastEspPhaseDetected} phase");
|
||||
_logger.Debug($"ImeLogTracker: Snapshotted {_packageStates.CountAll} package states from {_lastEspPhaseDetected} phase");
|
||||
}
|
||||
|
||||
_packageStates.Clear();
|
||||
@@ -1564,12 +1601,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
// First detection of any phase OR a real transition into a new phase: surface on Info
|
||||
// so phase boundaries are visible without enabling Debug. Re-matches of the same phase
|
||||
// (IME re-emits the phase string periodically as it re-evaluates app sets) stay on
|
||||
// Debug to avoid Info repetition.
|
||||
// (IME re-emits the phase string periodically as it re-evaluates app sets) are
|
||||
// identical repeats and go to Trace (D-394).
|
||||
if (isFirstOrChangedPhase)
|
||||
_logger.Info($"ImeLogTracker: ESP phase detected: {espPhaseString}");
|
||||
else
|
||||
_logger.Debug($"ImeLogTracker: ESP phase detected: {espPhaseString}");
|
||||
_logger.Trace($"ImeLogTracker: ESP phase detected: {espPhaseString}");
|
||||
ActivatePatterns(logPhaseIsCurrentPhase);
|
||||
|
||||
OnEspPhaseChanged?.Invoke(espPhaseString);
|
||||
@@ -1623,7 +1660,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
// Ignore user-targeted packages during device setup (we only track device phase in general)
|
||||
_packageStates.AddUpdateFromJsonPolicies(policies, ignoreUserTargeted: false);
|
||||
_logger.Info($"ImeLogTracker: discovered {policies.Count} policies, tracking {_packageStates.Count} packages");
|
||||
_logger.Info($"ImeLogTracker: discovered {policies.Count} policies, tracking {_packageStates.Count} packages", repeatKey: "ImeLogTracker.policies");
|
||||
OnPoliciesDiscovered?.Invoke(policiesJson);
|
||||
}
|
||||
}
|
||||
@@ -1687,7 +1724,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
if (changed)
|
||||
{
|
||||
_logger.Debug($"ImeLogTracker: {pkg.Name ?? id} downloading: {bytes}/{ofbytes}");
|
||||
_logger.Verbose($"ImeLogTracker: {pkg.Name ?? id} downloading: {bytes}/{ofbytes}");
|
||||
OnAppStateChanged?.Invoke(pkg, oldState, AppInstallationState.Downloading);
|
||||
}
|
||||
}
|
||||
|
||||
+23
-5
@@ -83,7 +83,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
catch (FileNotFoundException) { }
|
||||
catch (IOException ex)
|
||||
{
|
||||
_logger.Debug($"ImeLogTracker: IO error reading {filePath}: {ex.Message}");
|
||||
_logger.Debug($"ImeLogTracker: IO error reading {filePath}: {ex.Message}", repeatKey: "ImeLogTracker.ioError:" + filePath);
|
||||
}
|
||||
}
|
||||
|
||||
@@ -516,7 +516,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
"updatestateskipped", "updatestateerror", "updatestatepostponed",
|
||||
"captureexitcode", "capturehresult", "captureexitcodeclass", "captureappversion",
|
||||
"captureapptypewinget", "captureapptypemsi", "captureattemptnumber",
|
||||
"capturedetectionresult", "esptrackstatus", "policiesdiscovered",
|
||||
"capturedetectionresult", "markpostinstalldetection", "esptrackstatus", "policiesdiscovered",
|
||||
"ignorecompletedapp", "updatename", "updatewin32appstate",
|
||||
"cancelstuckandsetcurrent", "updatedotelemetry",
|
||||
// Not app-mutating, but a stale token-failure replayed from a previous
|
||||
@@ -588,7 +588,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
_currentLineIsHistoricReplay = isStaleReplayLine;
|
||||
if (isStaleReplayLine && AppMutatingActions.Contains(pattern.Action?.ToLower() ?? string.Empty))
|
||||
{
|
||||
_logger.Debug($"ImeLogTracker: skipped app action '{pattern.Action}' for historic line ({ResolveEntryUtc(entry):o})");
|
||||
_logger.Trace($"ImeLogTracker: skipped app action '{pattern.Action}' for historic line ({ResolveEntryUtc(entry):o})");
|
||||
return;
|
||||
}
|
||||
|
||||
@@ -684,7 +684,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
break;
|
||||
|
||||
case "enrollmentcompleted":
|
||||
_logger.Info("ImeLogTracker: User session completed detected");
|
||||
LogLineActivity("ImeLogTracker: User session completed detected", repeatKey: "ImeLogTracker.userSessionCompleted");
|
||||
OnUserSessionCompleted?.Invoke();
|
||||
break;
|
||||
|
||||
@@ -790,10 +790,28 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
}
|
||||
break;
|
||||
|
||||
case "markpostinstalldetection":
|
||||
// The check right after an install starts (D-392); its result line follows.
|
||||
if (!string.IsNullOrEmpty(id))
|
||||
_postInstallCheckPending[id] = pattern.Parameters.ContainsKey("afterReboot")
|
||||
&& pattern.Parameters["afterReboot"] == "true";
|
||||
break;
|
||||
|
||||
case "capturedetectionresult":
|
||||
var detectionVal = match.Groups["detection"]?.Value;
|
||||
if (!string.IsNullOrEmpty(id) && !string.IsNullOrEmpty(detectionVal))
|
||||
if (string.IsNullOrEmpty(id) || string.IsNullOrEmpty(detectionVal))
|
||||
break;
|
||||
bool afterReboot;
|
||||
if (_postInstallCheckPending.TryGetValue(id, out afterReboot))
|
||||
{
|
||||
// detectionResult stays the check before the install.
|
||||
_postInstallCheckPending.Remove(id);
|
||||
HandlePostInstallDetection(id, detectionVal, afterReboot);
|
||||
}
|
||||
else
|
||||
{
|
||||
_packageStates.GetPackage(id)?.UpdateDetectionResult(detectionVal);
|
||||
}
|
||||
break;
|
||||
|
||||
case "updatestatepostponed":
|
||||
|
||||
@@ -50,6 +50,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// because setcurrentapp, esptrackstatus etc. see IDs that never enter packageStates.
|
||||
private readonly HashSet<string> _seenAppIds = new HashSet<string>(StringComparer.OrdinalIgnoreCase);
|
||||
|
||||
// IME's check right after an install (D-392): app id → "after the restart the installer
|
||||
// requested". Set by IME-POST-INSTALL-DETECTION / IME-POST-REBOOT-DETECTION, consumed by
|
||||
// the app's next detection result line, which IME always logs last in that check.
|
||||
// Transient on purpose: a marker whose result line was never read must not survive an
|
||||
// agent restart and turn a later ordinary check into a post-install result.
|
||||
private readonly Dictionary<string, bool> _postInstallCheckPending = new Dictionary<string, bool>(StringComparer.OrdinalIgnoreCase);
|
||||
|
||||
// Forward-only phase progression: prevents accidental phase bounce (e.g. DeviceSetup
|
||||
// re-detected during AccountSetup if IME re-evaluates device apps and logs the old phase).
|
||||
private static readonly Dictionary<string, int> EspPhaseOrder = new Dictionary<string, int>(StringComparer.OrdinalIgnoreCase)
|
||||
@@ -513,6 +520,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// consumer must stamp poll-driven telemetry with the clock — inheriting an unrelated
|
||||
// line's LastMatchedLogTimestamp put a tz-skewed time on the event (session df1fcf47).
|
||||
public Action<AppPackageState, DateTime?> OnDoTelemetryReceived { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// IME's check right after an install found its result (D-392): the package, the detection
|
||||
/// state (Detected, NotDetected, DetectedDifferentVersion), whether the check followed the
|
||||
/// restart the installer requested, and the result line's timestamp. Not raised for the
|
||||
/// check before a requested restart: IME decides only after it.
|
||||
/// </summary>
|
||||
public Action<AppPackageState, string, bool, DateTime?> OnPostInstallDetection { get; set; }
|
||||
public Action<ScriptExecutionState> OnScriptCompleted { get; set; }
|
||||
|
||||
/// <summary>
|
||||
|
||||
+7
-7
@@ -225,7 +225,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
// Check against exclusion list
|
||||
if (IsExcludedUser(owner))
|
||||
{
|
||||
_logger.Debug($"DesktopArrivalDetector: explorer.exe PID {proc.Id} owned by excluded user '{owner}' — skipping");
|
||||
_logger.Debug($"DesktopArrivalDetector: explorer.exe PID {proc.Id} owned by excluded user '{owner}' — skipping", repeatKey: "DesktopArrivalDetector.excludedUser");
|
||||
|
||||
// Trace this decision once so it's visible in the backend
|
||||
if (!_excludedUserTraced)
|
||||
@@ -238,7 +238,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
$"explorer.exe found but owned by excluded user '{owner}' — not a real user desktop",
|
||||
new Dictionary<string, object> { { "pid", proc.Id }, { "session", proc.SessionId }, { "owner", owner } });
|
||||
}
|
||||
catch (Exception ex) { _logger.Verbose($"DesktopArrivalDetector: OnTraceEvent failed: {ex.Message}"); }
|
||||
catch (Exception ex) { _logger.Debug($"DesktopArrivalDetector: OnTraceEvent failed: {ex.Message}"); }
|
||||
}
|
||||
continue;
|
||||
}
|
||||
@@ -254,7 +254,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
$"Real user desktop detected (explorer.exe PID {proc.Id}, user '[redacted]')",
|
||||
new Dictionary<string, object> { { "pid", proc.Id }, { "session", proc.SessionId }, { "owner", "[redacted]" } });
|
||||
}
|
||||
catch (Exception ex) { _logger.Verbose($"DesktopArrivalDetector: OnTraceEvent failed: {ex.Message}"); }
|
||||
catch (Exception ex) { _logger.Debug($"DesktopArrivalDetector: OnTraceEvent failed: {ex.Message}"); }
|
||||
|
||||
// First-poll observability snapshot still fires before we stop polling —
|
||||
// there is value in distinguishing "found on first poll" (Stage already
|
||||
@@ -335,7 +335,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
{ "wtsErrorCount", _wtsErrorCountSinceStart },
|
||||
});
|
||||
}
|
||||
catch (Exception ex) { _logger.Verbose($"DesktopArrivalDetector: first-poll emit failed: {ex.Message}"); }
|
||||
catch (Exception ex) { _logger.Debug($"DesktopArrivalDetector: first-poll emit failed: {ex.Message}"); }
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -371,7 +371,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
{ "wtsErrorCount", _wtsErrorCountSinceStart },
|
||||
});
|
||||
}
|
||||
catch (Exception ex) { _logger.Verbose($"DesktopArrivalDetector: no-candidate emit failed: {ex.Message}"); }
|
||||
catch (Exception ex) { _logger.Debug($"DesktopArrivalDetector: no-candidate emit failed: {ex.Message}"); }
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -393,7 +393,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
{ "startReason", startReason },
|
||||
});
|
||||
}
|
||||
catch (Exception ex) { _logger.Verbose($"DesktopArrivalDetector: detector-started emit failed: {ex.Message}"); }
|
||||
catch (Exception ex) { _logger.Debug($"DesktopArrivalDetector: detector-started emit failed: {ex.Message}"); }
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
@@ -445,7 +445,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Verbose($"DesktopArrivalDetector: OOBE state check failed: {ex.Message}");
|
||||
_logger.Debug($"DesktopArrivalDetector: OOBE state check failed: {ex.Message}", repeatKey: "DesktopArrivalDetector.oobeCheckFailed");
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
+3
-1
@@ -471,7 +471,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
|
||||
public void Stop()
|
||||
{
|
||||
_logger.Info("Stopping ESP and Hello tracker");
|
||||
// Hosts call Stop and then Dispose, which stops again; the second pass finds nothing.
|
||||
if (_helloTracker != null || _shellCoreTracker != null || _provisioningTracker != null || _modernDeploymentTracker != null)
|
||||
_logger.Info("Stopping ESP and Hello tracker");
|
||||
|
||||
DisposeTracker(ref _modernDeploymentTracker, "ModernDeployment", t => t.Stop());
|
||||
DisposeProvisioningTracker();
|
||||
|
||||
+1
-1
@@ -98,7 +98,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
{
|
||||
if (rootKey == null)
|
||||
{
|
||||
logger?.Debug("EspPolicyProviderProbe: EnrollmentStatusTracking registry key not found");
|
||||
logger?.Debug("EspPolicyProviderProbe: EnrollmentStatusTracking registry key not found", repeatKey: "EspPolicyProviderProbe.noTrackingKey");
|
||||
return EspPolicyProviderSnapshot.Empty;
|
||||
}
|
||||
|
||||
|
||||
+11
-8
@@ -418,7 +418,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
}
|
||||
else
|
||||
{
|
||||
_logger.Debug("Periodic Hello policy check: No WHfB policy found yet - will check again");
|
||||
_logger.Trace("Periodic Hello policy check: No WHfB policy found yet - will check again");
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -636,7 +636,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
severity = EventSeverity.Info;
|
||||
message = "Windows Hello for Business provisioned successfully - NGC key registered";
|
||||
shouldTriggerHelloCompleted = MarkHelloCompleted();
|
||||
_logger.Info("Windows Hello provisioning COMPLETED successfully");
|
||||
// A repeat (live plus backfill) is already reported by MarkHelloCompleted.
|
||||
if (shouldTriggerHelloCompleted) _logger.Info("Windows Hello provisioning COMPLETED successfully");
|
||||
break;
|
||||
|
||||
case EventId_NgcKeyRegistrationFailed: // 301
|
||||
@@ -644,7 +645,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
severity = EventSeverity.Error;
|
||||
message = "Windows Hello for Business provisioning failed - NGC key registration error";
|
||||
shouldTriggerHelloCompleted = MarkHelloCompleted();
|
||||
_logger.Info("Windows Hello provisioning COMPLETED with failure");
|
||||
if (shouldTriggerHelloCompleted) _logger.Info("Windows Hello provisioning COMPLETED with failure");
|
||||
break;
|
||||
|
||||
case EventId_ProvisioningWillNotLaunch: // 360
|
||||
@@ -658,7 +659,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
severity = EventSeverity.Warning;
|
||||
message = "Windows Hello for Business provisioning blocked";
|
||||
shouldTriggerHelloCompleted = MarkHelloCompleted();
|
||||
_logger.Info("Windows Hello provisioning COMPLETED (blocked)");
|
||||
if (shouldTriggerHelloCompleted) _logger.Info("Windows Hello provisioning COMPLETED (blocked)");
|
||||
break;
|
||||
|
||||
case EventId_PinStatus: // 376
|
||||
@@ -719,12 +720,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
|| eventType == Constants.EventTypes.DeviceRegistrationEvent
|
||||
});
|
||||
|
||||
_logger.Info($"Hello event detected: {eventType} (EventID {eventId}{(isBackfill ? ", backfill" : "")})");
|
||||
_logger.Debug($"Hello event detected: {eventType} (EventID {eventId}{(isBackfill ? ", backfill" : "")})");
|
||||
|
||||
if (shouldTriggerHelloCompleted)
|
||||
{
|
||||
EmitHelloPolicyDetectionMismatch(eventType, eventId, timestamp);
|
||||
try { HelloCompleted?.Invoke(this, EventArgs.Empty); } catch { }
|
||||
try { HelloCompleted?.Invoke(this, EventArgs.Empty); }
|
||||
catch (Exception ex) { _logger.Warning($"HelloTracker: HelloCompleted handler threw: {ex.Message}"); }
|
||||
}
|
||||
}
|
||||
|
||||
@@ -969,12 +971,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
ImmediateUpload = shouldTriggerHelloCompleted
|
||||
});
|
||||
|
||||
_logger.Info($"HelloForBusiness event detected: {eventType} (EventID {eventId}{(isBackfill ? ", backfill" : "")})");
|
||||
_logger.Debug($"HelloForBusiness event detected: {eventType} (EventID {eventId}{(isBackfill ? ", backfill" : "")})");
|
||||
|
||||
if (shouldTriggerHelloCompleted)
|
||||
{
|
||||
EmitHelloPolicyDetectionMismatch(eventType, eventId, timestamp);
|
||||
try { HelloCompleted?.Invoke(this, EventArgs.Empty); } catch { }
|
||||
try { HelloCompleted?.Invoke(this, EventArgs.Empty); }
|
||||
catch (Exception ex) { _logger.Warning($"HelloTracker: HelloCompleted handler threw: {ex.Message}"); }
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
+2
-2
@@ -545,7 +545,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
|
||||
if (description.IndexOf("WhiteGlove", StringComparison.OrdinalIgnoreCase) < 0)
|
||||
{
|
||||
_logger.Trace($"ManagementService Event 509 without WhiteGlove keyword — ignoring: {description}");
|
||||
_logger.Debug($"ManagementService Event 509 without WhiteGlove keyword — ignoring: {description}", repeatKey: "ModernDeploymentTracker.nonWhiteGlove509");
|
||||
return;
|
||||
}
|
||||
|
||||
@@ -624,7 +624,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
using (record)
|
||||
{
|
||||
found++;
|
||||
_logger.Info($"Backfill found ManagementService Event {record.Id} at {record.TimeCreated:O}");
|
||||
_logger.Debug($"Backfill found ManagementService Event {record.Id} at {record.TimeCreated:O}");
|
||||
ProcessRecord(record, "ManagementService", ManagementChannel, isBackfill: true);
|
||||
}
|
||||
}
|
||||
|
||||
+6
-3
@@ -97,7 +97,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
hasValues: entries.Any(e => !oobeOnly || IsOobeName(e.Key)), line: line);
|
||||
}
|
||||
|
||||
/// <summary>One agent.log line per present key, one naming the absent keys.</summary>
|
||||
/// <summary>
|
||||
/// One agent.log line per present key, one naming the absent keys. Debug: registry detail
|
||||
/// behind the update page; the oobe_update_state event carries the content.
|
||||
/// </summary>
|
||||
public static void Log(AgentLogger logger, string moment, IReadOnlyList<KeyState> states)
|
||||
{
|
||||
if (logger == null || states == null) return;
|
||||
@@ -110,11 +113,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
absent.Add(state.Path);
|
||||
continue;
|
||||
}
|
||||
logger.Info($"OOBE update registry ({moment}): HKLM\\{state.Path}: {state.Line}");
|
||||
logger.Debug($"OOBE update registry ({moment}): HKLM\\{state.Path}: {state.Line}");
|
||||
}
|
||||
|
||||
if (absent.Count > 0)
|
||||
logger.Info($"OOBE update registry ({moment}): absent: {string.Join(", ", absent)}");
|
||||
logger.Debug($"OOBE update registry ({moment}): absent: {string.Join(", ", absent)}");
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
|
||||
+8
-11
@@ -514,13 +514,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
changedCount++;
|
||||
bool isNew = !_lastProvisioningJson.ContainsKey(categoryName);
|
||||
// Guard: the raw-JSON interpolation is materialized regardless of log
|
||||
// level (Trace() only drops the string after it is built), and this runs
|
||||
// per changed category every poll — skip the alloc when Trace is off.
|
||||
if (_logger.LogLevel >= AgentLogLevel.Trace)
|
||||
{
|
||||
_logger.Trace($"CheckProvisioningStatus: {categoryName} — {(isNew ? "NEW" : "CHANGED")} (json length={jsonValue.Length})");
|
||||
_logger.Trace($"CheckProvisioningStatus: {categoryName} — raw JSON: {jsonValue}");
|
||||
}
|
||||
// level (Verbose() only drops the string after it is built), and this runs
|
||||
// per changed category every poll — skip the alloc when Verbose is off.
|
||||
if (_logger.LogLevel >= AgentLogLevel.Verbose)
|
||||
_logger.Verbose($"CheckProvisioningStatus: {categoryName} {(isNew ? "new" : "changed")}, raw JSON: {jsonValue}");
|
||||
|
||||
_lastProvisioningJson[categoryName] = jsonValue;
|
||||
// TryFireProvisioningFailure (inside ProcessCategoryStatus) arms the
|
||||
@@ -1007,7 +1004,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
bool isFirstSeen = !_provisioningCategorySeen.Contains(categoryName);
|
||||
bool categorySucceededChanged = HasCategorySucceededChanged(categoryName, categorySucceeded);
|
||||
|
||||
_logger.Trace($"ProcessCategory: {categoryLabel} — succeeded={categorySucceeded?.ToString() ?? "null"}, " +
|
||||
_logger.Verbose($"ProcessCategory: {categoryLabel} — succeeded={categorySucceeded?.ToString() ?? "null"}, " +
|
||||
$"isFirstSeen={isFirstSeen}, succeededChanged={categorySucceededChanged}, " +
|
||||
$"subcategories={subcategories.Count} [{string.Join(", ", subcategories.Select(s => $"{s.Name}={s.State}"))}]");
|
||||
|
||||
@@ -1050,7 +1047,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
var failureTransitions = transitions.Where(t => t.IsFailure).ToList();
|
||||
if (transitions.Count > 0)
|
||||
{
|
||||
_logger.Trace($"ProcessCategory: {categoryLabel} — subcategory transitions: " +
|
||||
_logger.Debug($"ProcessCategory: {categoryLabel} — subcategory transitions: " +
|
||||
string.Join(", ", transitions.Select(t => $"{t.SubcategoryName}: {t.OldState}→{t.NewState} (failure={t.IsFailure})")));
|
||||
}
|
||||
|
||||
@@ -1115,7 +1112,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
|
||||
var errorCode = TryExtractErrorCode(failedSubcategoryInfo?.StatusText);
|
||||
|
||||
_logger.Info(
|
||||
_logger.Debug(
|
||||
$"Provisioning subcategory failure: {categoryLabel}/{failedSubcategoryName ?? "category-level"} — " +
|
||||
$"escalating as {failureTypeName} (errorCode={errorCode ?? "n/a"})");
|
||||
_logger.Warning($"Provisioning failure detected: {failureTypeName}");
|
||||
@@ -1886,7 +1883,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
Data = eventData
|
||||
});
|
||||
|
||||
_logger.Info($"Provisioning status event: {categoryLabel} — {statusText} (succeeded={succeeded?.ToString() ?? "in_progress"})");
|
||||
_logger.Info($"Provisioning status event: {categoryLabel} — {statusText} (succeeded={succeeded?.ToString() ?? "in_progress"})", repeatKey: "ProvisioningStatus.event:" + categoryLabel);
|
||||
}
|
||||
|
||||
private void EmitRawRegistryDump(string categoryLabel, string rawJson, string trigger)
|
||||
|
||||
+15
-11
@@ -266,24 +266,27 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
{
|
||||
try
|
||||
{
|
||||
var stoppedAny = false;
|
||||
lock (_stateLock)
|
||||
{
|
||||
DisposeAndNull(ref _servicesAppearanceWatcher);
|
||||
DisposeAndNull(ref _machineSoftwareAppearanceWatcher);
|
||||
DisposeAndNull(ref _userSoftwareAppearanceWatcher);
|
||||
DisposeAndNull(ref _uninstallAppearanceWatcher);
|
||||
stoppedAny |= DisposeAndNull(ref _servicesAppearanceWatcher);
|
||||
stoppedAny |= DisposeAndNull(ref _machineSoftwareAppearanceWatcher);
|
||||
stoppedAny |= DisposeAndNull(ref _userSoftwareAppearanceWatcher);
|
||||
stoppedAny |= DisposeAndNull(ref _uninstallAppearanceWatcher);
|
||||
|
||||
_serviceRealmjoinDebounce?.Dispose(); _serviceRealmjoinDebounce = null;
|
||||
_machineRealmJoinDebounce?.Dispose(); _machineRealmJoinDebounce = null;
|
||||
_userRealmJoinDebounce?.Dispose(); _userRealmJoinDebounce = null;
|
||||
_uninstallDebounce?.Dispose(); _uninstallDebounce = null;
|
||||
|
||||
DisposeAndNull(ref _serviceRealmjoinWatcher);
|
||||
DisposeAndNull(ref _machineRealmJoinWatcher);
|
||||
DisposeAndNull(ref _userRealmJoinWatcher);
|
||||
DisposeAndNull(ref _uninstallWatcher);
|
||||
stoppedAny |= DisposeAndNull(ref _serviceRealmjoinWatcher);
|
||||
stoppedAny |= DisposeAndNull(ref _machineRealmJoinWatcher);
|
||||
stoppedAny |= DisposeAndNull(ref _userRealmJoinWatcher);
|
||||
stoppedAny |= DisposeAndNull(ref _uninstallWatcher);
|
||||
}
|
||||
_logger.Info($"RealmJoinWatcher: stopped ({reason})");
|
||||
// Hosts call Stop and then Dispose, which stops again; only the pass that
|
||||
// stopped a watcher logs.
|
||||
if (stoppedAny) _logger.Info($"RealmJoinWatcher: stopped ({reason})");
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
@@ -913,11 +916,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
}
|
||||
}
|
||||
|
||||
private static void DisposeAndNull(ref RegistryWatcher? w)
|
||||
private static bool DisposeAndNull(ref RegistryWatcher? w)
|
||||
{
|
||||
if (w == null) return;
|
||||
if (w == null) return false;
|
||||
try { w.Dispose(); } catch { }
|
||||
w = null;
|
||||
return true;
|
||||
}
|
||||
|
||||
// Test seams — drive the read paths deterministically without touching the real registry.
|
||||
|
||||
+1
-1
@@ -384,7 +384,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
ImmediateUpload = true
|
||||
});
|
||||
|
||||
_logger.Info($"Shell-Core event detected: {eventType} (EventID {eventId})");
|
||||
_logger.Debug($"Shell-Core event detected: {eventType} (EventID {eventId})");
|
||||
|
||||
// Set the source-event timestamp BEFORE each event raise so adapters / coordinators
|
||||
// can read it during their synchronous handler. Cleared in finally so a stale value
|
||||
|
||||
+1
-1
@@ -568,7 +568,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Trace($"StallProbeCollector: eventlog scan of {channel} failed: {ex.Message}");
|
||||
_logger.Debug($"StallProbeCollector: eventlog scan of {channel} failed: {ex.Message}", repeatKey: "StallProbeCollector.scanFailed:" + channel);
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
+5
-5
@@ -344,7 +344,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
_logger.Info($"Diagnostics package created: {zipFileName} ({zipBytes.Length / 1024} KB)");
|
||||
|
||||
// Fetch a short-lived upload URL just before uploading — never stored in config or on disk
|
||||
_logger.Info("Requesting diagnostics upload URL from backend...");
|
||||
_logger.Debug("Requesting diagnostics upload URL from backend...");
|
||||
var uploadUrlResponse = await _apiClient.GetDiagnosticsUploadUrlAsync(
|
||||
_configuration.TenantId,
|
||||
_configuration.SessionId,
|
||||
@@ -708,7 +708,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
// Expected outcome, not a packaging problem: the subtree is off limits by design.
|
||||
foreach (var refused in refusedDirectories)
|
||||
{
|
||||
_logger.Info($"Diagnostics subfolder skipped by guard: {refused}");
|
||||
_logger.Debug($"Diagnostics subfolder skipped by guard: {refused}");
|
||||
ManifestLine($"SKIPPED DIR (path guard): {refused}");
|
||||
}
|
||||
|
||||
@@ -800,7 +800,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
}
|
||||
|
||||
tracker.RecordIncluded(length);
|
||||
_logger.Debug($"Added to diagnostics package: {entryName} ({length / 1024} KB)");
|
||||
_logger.Verbose($"Added to diagnostics package: {entryName} ({length / 1024} KB)");
|
||||
ManifestLine($"ADDED: {entryName} ({length} bytes)");
|
||||
}
|
||||
}
|
||||
@@ -1066,7 +1066,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
{
|
||||
try
|
||||
{
|
||||
_logger.Info($"Uploading diagnostics package (attempt {attempt}/{maxRetries}, {data.Length / 1024} KB)...");
|
||||
_logger.Debug($"Uploading diagnostics package (attempt {attempt}/{maxRetries}, {data.Length / 1024} KB)...");
|
||||
|
||||
using var content = new ByteArrayContent(data);
|
||||
content.Headers.Add("x-ms-blob-type", "BlockBlob");
|
||||
@@ -1101,7 +1101,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
if (attempt < maxRetries)
|
||||
{
|
||||
var delay = TimeSpan.FromSeconds(Math.Pow(2, attempt)); // 2s, 4s, 8s
|
||||
_logger.Info($"Retrying blob upload in {delay.TotalSeconds}s...");
|
||||
_logger.Debug($"Retrying blob upload in {delay.TotalSeconds}s...");
|
||||
await Task.Delay(delay);
|
||||
}
|
||||
}
|
||||
|
||||
+1
-1
@@ -97,7 +97,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
var dedupKey = BuildDedupKey(action);
|
||||
if (!_seenActionIds.TryAdd(dedupKey, 0))
|
||||
{
|
||||
_logger.Debug($"ServerActionDispatcher: duplicate action '{action.Type}' ({dedupKey}) — skipping");
|
||||
_logger.Debug($"ServerActionDispatcher: duplicate action '{action.Type}' ({dedupKey}) — skipping", repeatKey: "ServerActionDispatcher.duplicate:" + dedupKey);
|
||||
continue;
|
||||
}
|
||||
|
||||
|
||||
+7
-7
@@ -50,7 +50,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
using (explorerProcess)
|
||||
{
|
||||
sessionId = (uint)explorerProcess.SessionId;
|
||||
logger.Info($"UserSessionProcessLauncher: Found explorer.exe PID {explorerProcess.Id} in session {sessionId}");
|
||||
logger.Debug($"UserSessionProcessLauncher: Found explorer.exe PID {explorerProcess.Id} in session {sessionId}");
|
||||
}
|
||||
|
||||
// Get the interactive session token via WTS.
|
||||
@@ -80,7 +80,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
return false;
|
||||
}
|
||||
|
||||
logger.Info($"UserSessionProcessLauncher: Token duplicated and stamped to session {sessionId}");
|
||||
logger.Debug($"UserSessionProcessLauncher: Token duplicated and stamped to session {sessionId}");
|
||||
|
||||
// Create an environment block for the user (using session-stamped token)
|
||||
if (!ProcessNativeMethods.CreateEnvironmentBlock(out environment, dupToken, false))
|
||||
@@ -121,7 +121,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
{
|
||||
cxhProcess = FindProcessInSession("CloudExperienceHost", sessionId);
|
||||
if (cxhProcess != null)
|
||||
logger.Info($"UserSessionProcessLauncher: CloudExperienceHost PID {cxhProcess.Id} running " +
|
||||
logger.Debug($"UserSessionProcessLauncher: CloudExperienceHost PID {cxhProcess.Id} running " +
|
||||
$"in session {sessionId} — will monitor for exit during retries");
|
||||
}
|
||||
catch { }
|
||||
@@ -162,7 +162,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
}
|
||||
|
||||
ProcessNativeMethods.CloseHandle(pi.hThread);
|
||||
logger.Info($"UserSessionProcessLauncher: Attempt {attempt} — created PID {pi.dwProcessId}" +
|
||||
logger.Debug($"UserSessionProcessLauncher: Attempt {attempt} — created PID {pi.dwProcessId}" +
|
||||
$" [{(useExplicitDesktop ? "explicit" : "default")} desktop], verifying startup...");
|
||||
|
||||
// Wait 3s to verify the process survives DLL init + CLR bootstrap.
|
||||
@@ -190,10 +190,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
// On 23H2: CXH never exits → WaitForExit times out → same as regular retry interval.
|
||||
if (cxhProcess != null)
|
||||
{
|
||||
logger.Info($"UserSessionProcessLauncher: Attempt {attempt} — 0x8007045A, waiting for CXH exit (up to {retryIntervalSeconds}s)...");
|
||||
logger.Debug($"UserSessionProcessLauncher: Attempt {attempt} — 0x8007045A, waiting for CXH exit (up to {retryIntervalSeconds}s)...");
|
||||
if (cxhProcess.WaitForExit(retryIntervalSeconds * 1000))
|
||||
{
|
||||
logger.Info("UserSessionProcessLauncher: CloudExperienceHost exited — desktop should be available");
|
||||
logger.Debug("UserSessionProcessLauncher: CloudExperienceHost exited — desktop should be available");
|
||||
cxhProcess.Dispose();
|
||||
cxhProcess = null;
|
||||
System.Threading.Thread.Sleep(500); // brief delay for desktop init
|
||||
@@ -201,7 +201,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Runtime
|
||||
}
|
||||
else
|
||||
{
|
||||
logger.Info($"UserSessionProcessLauncher: Attempt {attempt} — 0x8007045A (desktop locked?) — retrying in {retryIntervalSeconds}s...");
|
||||
logger.Debug($"UserSessionProcessLauncher: Attempt {attempt} — 0x8007045A (desktop locked?) — retrying in {retryIntervalSeconds}s...");
|
||||
System.Threading.Thread.Sleep(retryIntervalSeconds * 1000);
|
||||
}
|
||||
continue;
|
||||
|
||||
+2
-2
@@ -81,7 +81,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Analyzers
|
||||
/// <summary>Final-shutdown scan — captures any AutoLogon written during the user phase.</summary>
|
||||
public void AnalyzeAtShutdown()
|
||||
{
|
||||
_logger.Info($"{Name}: Running shutdown AutoLogon scan");
|
||||
_logger.Debug($"{Name}: Running shutdown AutoLogon scan");
|
||||
RunScan("shutdown");
|
||||
}
|
||||
|
||||
@@ -91,7 +91,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Analyzers
|
||||
/// </summary>
|
||||
public void AnalyzeAtDeviceSetupComplete()
|
||||
{
|
||||
_logger.Info($"{Name}: Running device-setup-complete AutoLogon scan");
|
||||
_logger.Debug($"{Name}: Running device-setup-complete AutoLogon scan");
|
||||
RunScan("device_setup_complete");
|
||||
}
|
||||
|
||||
|
||||
+1
-1
@@ -81,7 +81,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Analyzers
|
||||
|
||||
public void AnalyzeAtStartup()
|
||||
{
|
||||
_logger.Info($"{Name}: scanning prefetch for a post-boot cmd.exe console artifact");
|
||||
_logger.Debug($"{Name}: scanning prefetch for a post-boot cmd.exe console artifact");
|
||||
try { RunScan(); }
|
||||
catch (Exception ex) { _logger.Error($"{Name}: scan failed unexpectedly", ex); }
|
||||
}
|
||||
|
||||
+1
-1
@@ -80,7 +80,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Analyzers
|
||||
|
||||
public void AnalyzeAtStartup()
|
||||
{
|
||||
_logger.Info($"{Name}: Running startup analysis");
|
||||
_logger.Debug($"{Name}: Running startup analysis");
|
||||
RunAnalysis("startup");
|
||||
}
|
||||
|
||||
|
||||
+2
-2
@@ -114,13 +114,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Analyzers
|
||||
|
||||
public void AnalyzeAtStartup()
|
||||
{
|
||||
_logger.Info($"{Name}: Running startup analysis");
|
||||
_logger.Debug($"{Name}: Running startup analysis");
|
||||
RunAnalysis("startup", EnrollmentPhase.Unknown);
|
||||
}
|
||||
|
||||
public void AnalyzeAtShutdown()
|
||||
{
|
||||
_logger.Info($"{Name}: Running shutdown analysis");
|
||||
_logger.Debug($"{Name}: Running shutdown analysis");
|
||||
|
||||
// At shutdown a user has logged in — their profile folder is expected. Detect logged-in
|
||||
// users via explorer.exe owner (same technique as DesktopArrivalDetector); RunAnalysis
|
||||
|
||||
+5
-5
@@ -92,7 +92,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Analyzers
|
||||
|
||||
public void AnalyzeAtStartup()
|
||||
{
|
||||
_logger.Info($"{Name}: Running startup analysis (baseline inventory)");
|
||||
_logger.Debug($"{Name}: Running startup analysis (baseline inventory)");
|
||||
try
|
||||
{
|
||||
// The collection ALWAYS runs — _startupInventory is the in-memory base for the
|
||||
@@ -106,7 +106,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Analyzers
|
||||
Constants.EventTypes.SoftwareInventoryAnalysis + ":startup",
|
||||
BuildInventoryFingerprint(_startupInventory)))
|
||||
{
|
||||
_logger.Info($"{Name}: baseline inventory unchanged since last emission — startup events suppressed (restart dedup), delta base kept in memory");
|
||||
_logger.Debug($"{Name}: baseline inventory unchanged since last emission — startup events suppressed (restart dedup), delta base kept in memory");
|
||||
return;
|
||||
}
|
||||
|
||||
@@ -156,7 +156,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Analyzers
|
||||
{
|
||||
if (Interlocked.CompareExchange(ref _part1ShutdownSnapshotEmitted, 1, 0) != 0)
|
||||
{
|
||||
_logger.Info($"{Name}: AnalyzeAtShutdown(whiteGlovePart=1) skipped — Part-1 snapshot already emitted (likely by WhiteGloveInventoryTrigger)");
|
||||
_logger.Debug($"{Name}: AnalyzeAtShutdown(whiteGlovePart=1) skipped — Part-1 snapshot already emitted (likely by WhiteGloveInventoryTrigger)");
|
||||
return;
|
||||
}
|
||||
}
|
||||
@@ -164,12 +164,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Analyzers
|
||||
{
|
||||
if (Interlocked.CompareExchange(ref _part2ShutdownSnapshotEmitted, 1, 0) != 0)
|
||||
{
|
||||
_logger.Info($"{Name}: AnalyzeAtShutdown(whiteGlovePart=2) skipped — Part-2 snapshot already emitted");
|
||||
_logger.Debug($"{Name}: AnalyzeAtShutdown(whiteGlovePart=2) skipped — Part-2 snapshot already emitted");
|
||||
return;
|
||||
}
|
||||
}
|
||||
|
||||
_logger.Info($"{Name}: Running shutdown analysis (delta detection, whiteGlovePart={whiteGlovePart?.ToString() ?? "none"})");
|
||||
_logger.Debug($"{Name}: Running shutdown analysis (delta detection, whiteGlovePart={whiteGlovePart?.ToString() ?? "none"})");
|
||||
try
|
||||
{
|
||||
var currentInventory = CollectAndNormalize();
|
||||
|
||||
@@ -62,9 +62,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry
|
||||
/// <summary>Stops the collection timer without disposing the collector.</summary>
|
||||
public void Stop()
|
||||
{
|
||||
// Hosts call Stop and then Dispose, which stops again; only a running timer logs.
|
||||
var wasRunning = _timer != null;
|
||||
_timer?.Dispose();
|
||||
_timer = null;
|
||||
Logger.Info($"[{GetType().Name}] Stopped");
|
||||
if (wasRunning) Logger.Info($"[{GetType().Name}] Stopped");
|
||||
OnAfterStop();
|
||||
}
|
||||
|
||||
@@ -117,7 +119,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry
|
||||
// duration of any single slow Collect.
|
||||
if (Interlocked.CompareExchange(ref _collecting, 1, 0) != 0)
|
||||
{
|
||||
Logger.Debug($"[{GetType().Name}] tick skipped — previous Collect still running");
|
||||
Logger.Trace($"[{GetType().Name}] tick skipped — previous Collect still running");
|
||||
return;
|
||||
}
|
||||
|
||||
|
||||
+6
-6
@@ -209,7 +209,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
default: modeLabel = $"{autopilotMode}"; break;
|
||||
}
|
||||
data["autopilotModeLabel"] = modeLabel;
|
||||
_logger.Info($"EnrollmentTracker: AutopilotMode={autopilotMode} ({modeLabel})");
|
||||
_logger.Info($"EnrollmentTracker: AutopilotMode={autopilotMode} ({modeLabel})", repeatKey: "DeviceInfo.autopilotMode");
|
||||
}
|
||||
|
||||
// --- Interpret CloudAssignedDomainJoinMethod ---
|
||||
@@ -238,7 +238,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Trace($"EnrollmentTracker: Failed to parse PolicyJsonCache for DomainJoinMethod: {ex.Message}");
|
||||
_logger.Debug($"EnrollmentTracker: Failed to parse PolicyJsonCache for DomainJoinMethod: {ex.Message}");
|
||||
}
|
||||
}
|
||||
|
||||
@@ -261,10 +261,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
|
||||
if (isHybridJoin)
|
||||
{
|
||||
_logger.Info("EnrollmentTracker: Hybrid Azure AD Join profile detected");
|
||||
_logger.Info("EnrollmentTracker: Hybrid Azure AD Join profile detected", repeatKey: "DeviceInfo.hybridProfile");
|
||||
}
|
||||
|
||||
_logger.Info($"EnrollmentTracker: Read {data.Count} values from AutopilotPolicyCache");
|
||||
_logger.Info($"EnrollmentTracker: Read {data.Count} values from AutopilotPolicyCache", repeatKey: "DeviceInfo.policyCache");
|
||||
}
|
||||
else
|
||||
{
|
||||
@@ -390,7 +390,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
{ "detectionRule", detectionRule }
|
||||
});
|
||||
|
||||
_logger.Info($"EnrollmentTracker: enrollment type detected: {detectedType}");
|
||||
_logger.Info($"EnrollmentTracker: enrollment type detected: {detectedType}", repeatKey: "DeviceInfo.enrollmentType");
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
@@ -810,7 +810,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
if (hasAnyEspEvidence)
|
||||
{
|
||||
var summary = BuildSummary(snapshot, tracking);
|
||||
_logger.Info($"EnrollmentTracker: ESP configuration detected — {summary}");
|
||||
_logger.Info($"EnrollmentTracker: ESP configuration detected — {summary}", repeatKey: "DeviceInfo.espConfig");
|
||||
EmitDeviceInfoEvent(Constants.EventTypes.EspConfigDetected, $"ESP configuration: {summary}", data);
|
||||
PostEspConfigDetectedSignal(snapshot);
|
||||
}
|
||||
|
||||
+4
-4
@@ -89,7 +89,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
/// </summary>
|
||||
public (string enrollmentType, bool isHybridJoin, bool? skipUserStatusPage, bool? skipDeviceStatusPage, int? autopilotMode, bool hasAadJoinedUser, bool isFooUserDetected) CollectAll()
|
||||
{
|
||||
_logger.Info("EnrollmentTracker: collecting device info (at start)");
|
||||
_logger.Debug("EnrollmentTracker: collecting device info (at start)");
|
||||
|
||||
CollectOSInfoAndBootTime();
|
||||
CollectNetworkAndDnsConfiguration();
|
||||
@@ -113,7 +113,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
/// </summary>
|
||||
public void CollectAtEnrollmentStart()
|
||||
{
|
||||
_logger.Info("EnrollmentTracker: collecting device info (at enrollment start)");
|
||||
_logger.Debug("EnrollmentTracker: collecting device info (at enrollment start)");
|
||||
|
||||
CollectAadJoinStatus();
|
||||
CollectAutopilotProfile();
|
||||
@@ -134,7 +134,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
/// </summary>
|
||||
public void RefreshEspConfiguration(string trigger)
|
||||
{
|
||||
_logger.Info($"EnrollmentTracker: re-collecting ESP configuration (trigger={trigger})");
|
||||
_logger.Debug($"EnrollmentTracker: re-collecting ESP configuration (trigger={trigger})");
|
||||
CollectEspConfiguration();
|
||||
}
|
||||
|
||||
@@ -144,7 +144,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
/// </summary>
|
||||
public void CollectAtEnd()
|
||||
{
|
||||
_logger.Info("EnrollmentTracker: collecting device info (at end)");
|
||||
_logger.Debug("EnrollmentTracker: collecting device info (at end)");
|
||||
|
||||
// BitLocker can be enabled during enrollment via policy
|
||||
CollectBitLockerStatus();
|
||||
|
||||
+1
-1
@@ -171,7 +171,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.DeviceInfo
|
||||
values[valueName] = value.ToString();
|
||||
}
|
||||
|
||||
logger.Info($"ZtdEvidence: read {values.Count} values from Diagnostics\\Autopilot");
|
||||
logger.Info($"ZtdEvidence: read {values.Count} values from Diagnostics\\Autopilot", repeatKey: "ZtdEvidence.read");
|
||||
return values.Count > 0 ? values : null;
|
||||
}
|
||||
}
|
||||
|
||||
+3
-3
@@ -130,7 +130,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors
|
||||
var resolvedPaths = ResolveLogPaths(filePath, rule.RuleId, context);
|
||||
if (resolvedPaths.Count == 0)
|
||||
{
|
||||
context.Logger.Debug($"LogParser rule {rule.RuleId}: no files found for: {filePath}");
|
||||
context.Logger.Debug($"LogParser rule {rule.RuleId}: no files found for: {filePath}", repeatKey: "LogParserCollector.noFiles:" + rule.RuleId + "|" + filePath);
|
||||
context.DebugLog(rule.RuleId, GatherRuleDebugLog.StageLogParser,
|
||||
$"no files matched target {filePath}" + (HasWildcard(Path.GetFileName(filePath)) ? " (wildcard)" : "") + " — nothing to parse");
|
||||
return null;
|
||||
@@ -456,7 +456,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors
|
||||
state.CommitLogPosition(rule.RuleId, filePath, endPosition, lineNumberBase + committedLines, head, heldTailStart);
|
||||
|
||||
if (matchCount > 0)
|
||||
context.Logger.Debug($"LogParser rule {rule.RuleId}: {matchCount} matches from {linesRead} lines in {fileName}");
|
||||
context.Logger.Verbose($"LogParser rule {rule.RuleId}: {matchCount} matches from {linesRead} lines in {fileName}");
|
||||
|
||||
// Per-file outcome — always written so a "matched 0" run is visible too.
|
||||
context.DebugLog(rule.RuleId, GatherRuleDebugLog.StageLogParser,
|
||||
@@ -496,7 +496,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather.Collectors
|
||||
}
|
||||
else if (start == LogReadStart.Replaced)
|
||||
{
|
||||
context.Logger.Info($"LogParser rule {rule.RuleId}: {fileName} was replaced since the last read — reading it from the beginning");
|
||||
context.Logger.Debug($"LogParser rule {rule.RuleId}: {fileName} was replaced since the last read — reading it from the beginning");
|
||||
context.DebugLog(rule.RuleId, GatherRuleDebugLog.StageLogParser,
|
||||
$"{fileName}: file start changed since the last read (replaced or rewritten) — saved position {known.Position} discarded, reading from the beginning");
|
||||
}
|
||||
|
||||
+8
-8
@@ -261,7 +261,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather
|
||||
interval
|
||||
);
|
||||
_intervalTimers[intervalRule.RuleId] = timer;
|
||||
_logger.Info($" Interval rule {intervalRule.RuleId} scheduled every {intervalRule.IntervalSeconds}s");
|
||||
_logger.Debug($" Interval rule {intervalRule.RuleId} scheduled every {intervalRule.IntervalSeconds}s");
|
||||
DebugLog(intervalRule.RuleId, GatherRuleDebugLog.StageTrigger,
|
||||
$"interval timer scheduled every {intervalRule.IntervalSeconds}s (first run after one full interval — no immediate execution)");
|
||||
}
|
||||
@@ -321,7 +321,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather
|
||||
continue;
|
||||
}
|
||||
|
||||
_logger.Info($"Phase exit triggered rule {rule.RuleId} (left phase: {previousPhaseName}, now: {phaseName})");
|
||||
_logger.Debug($"Phase exit triggered rule {rule.RuleId} (left phase: {previousPhaseName}, now: {phaseName})");
|
||||
exitRules.Add(rule);
|
||||
}
|
||||
}
|
||||
@@ -374,7 +374,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather
|
||||
foreach (var rule in deferredStartup)
|
||||
{
|
||||
var deferredRule = rule;
|
||||
_logger.Info($"Phase {phaseName} activated deferred startup rule {deferredRule.RuleId}");
|
||||
_logger.Debug($"Phase {phaseName} activated deferred startup rule {deferredRule.RuleId}");
|
||||
DebugLog(deferredRule.RuleId, GatherRuleDebugLog.StageTrigger,
|
||||
$"phase {phaseName} activated deferred startup rule");
|
||||
ThreadPool.QueueUserWorkItem(_ => ExecuteRule(deferredRule));
|
||||
@@ -405,7 +405,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather
|
||||
continue;
|
||||
}
|
||||
|
||||
_logger.Info($"Phase change triggered rule {rule.RuleId} (phase: {phaseName})");
|
||||
_logger.Debug($"Phase change triggered rule {rule.RuleId} (phase: {phaseName})");
|
||||
DebugLog(rule.RuleId, GatherRuleDebugLog.StageTrigger, $"phase_change to {phaseName} fired");
|
||||
ThreadPool.QueueUserWorkItem(_ => ExecuteRule(rule));
|
||||
}
|
||||
@@ -450,7 +450,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather
|
||||
continue;
|
||||
}
|
||||
|
||||
_logger.Info($"Event triggered rule {rule.RuleId} (event: {eventType})");
|
||||
_logger.Debug($"Event triggered rule {rule.RuleId} (event: {eventType})");
|
||||
DebugLog(rule.RuleId, GatherRuleDebugLog.StageTrigger, $"on_event {eventType} fired");
|
||||
ThreadPool.QueueUserWorkItem(_ => ExecuteRule(rule));
|
||||
}
|
||||
@@ -461,7 +461,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather
|
||||
{
|
||||
try
|
||||
{
|
||||
_logger.Info($"Executing gather rule: {rule.RuleId} ({rule.Title})");
|
||||
_logger.Info($"Executing gather rule: {rule.RuleId} ({rule.Title})", repeatKey: "GatherRuleExecutor.exec:" + rule.RuleId);
|
||||
DebugLog(rule.RuleId, GatherRuleDebugLog.StageExec, $"executing: collector={rule.CollectorType}, target={rule.Target}");
|
||||
|
||||
var collectorType = rule.CollectorType?.ToLower();
|
||||
@@ -673,7 +673,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather
|
||||
&& (int)_currentPhase >= (int)fromPhase)
|
||||
{
|
||||
_fromPhaseLatched.Add(rule.RuleId);
|
||||
_logger.Info($"Gather rule {rule.RuleId}: from-phase scope latched at {_currentPhase} (activeFromPhase={rule.ActiveFromPhase})");
|
||||
_logger.Debug($"Gather rule {rule.RuleId}: from-phase scope latched at {_currentPhase} (activeFromPhase={rule.ActiveFromPhase})");
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -755,7 +755,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather
|
||||
}
|
||||
|
||||
if (!emit)
|
||||
_logger.Debug($"Gather rule {rule.RuleId}: result unchanged, emit suppressed (on_change)");
|
||||
_logger.Trace($"Gather rule {rule.RuleId}: result unchanged, emit suppressed (on_change)");
|
||||
return emit;
|
||||
}
|
||||
|
||||
|
||||
+1
-1
@@ -356,7 +356,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather
|
||||
{
|
||||
var oldest = files.OrderBy(file => file.Value.LastTouched).First();
|
||||
files.Remove(oldest.Key);
|
||||
_logger.Info($"GatherRuleSessionState: rule {ruleId} tracks more than {MaxLogFilesPerRule} files — forgot the position of {Path.GetFileName(oldest.Key)}");
|
||||
_logger.Debug($"GatherRuleSessionState: rule {ruleId} tracks more than {MaxLogFilesPerRule} files — forgot the position of {Path.GetFileName(oldest.Key)}");
|
||||
}
|
||||
|
||||
private static string Prefix(string hash) => hash.Length > 8 ? hash.Substring(0, 8) : hash;
|
||||
|
||||
+1
-1
@@ -91,7 +91,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Gather
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Debug($"[{SourceName}] failed to save state: {ex.Message}");
|
||||
_logger.Debug($"[{SourceName}] failed to save state: {ex.Message}", repeatKey: "GatherRuleStatePersistence.save:" + SourceName);
|
||||
return false;
|
||||
}
|
||||
}
|
||||
|
||||
+1
-1
@@ -196,7 +196,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Office
|
||||
var leaf = Path.GetFileName(relativeName);
|
||||
if (!string.IsNullOrEmpty(leaf) && _binaries.Contains(leaf))
|
||||
{
|
||||
_logger.Info($"[OfficeBinaryWatcher] core Office binary appeared: {leaf}");
|
||||
_logger.Info($"[OfficeBinaryWatcher] core Office binary appeared: {leaf}", repeatKey: "OfficeBinaryWatcher.appeared:" + leaf);
|
||||
Raise();
|
||||
}
|
||||
}
|
||||
|
||||
+1
-1
@@ -194,7 +194,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Office
|
||||
{
|
||||
// Debounce: C2R may start another short-lived worker after a small gap. Only
|
||||
// close the window if none reappears within the settle period.
|
||||
_logger.Debug($"[OfficeProcessWatcher] last worker exited — settling {_settleSeconds}s before closing the install window");
|
||||
_logger.Trace($"[OfficeProcessWatcher] last worker exited — settling {_settleSeconds}s before closing the install window");
|
||||
StartSettleTimer();
|
||||
}
|
||||
}
|
||||
|
||||
+1
-1
@@ -121,7 +121,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Office
|
||||
}
|
||||
_watchedKey = ancestor;
|
||||
_mode = WatchMode.Bootstrap;
|
||||
_logger.Debug($"[RegistryChangeWatcher] target HKLM\\{_targetSubKey} absent — bootstrap-watching HKLM\\{ancestorPath} (name-only)");
|
||||
_logger.Debug($"[RegistryChangeWatcher] target HKLM\\{_targetSubKey} absent — bootstrap-watching HKLM\\{ancestorPath} (name-only)", repeatKey: "RegistryChangeWatcher.bootstrap:" + _targetSubKey);
|
||||
if (!ArmNotify(subtree: false, BootstrapFilter)) return;
|
||||
|
||||
// TOCTOU: the target may have been created between TryOpen and arming the ancestor watch.
|
||||
|
||||
+5
-5
@@ -127,7 +127,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Logger.Debug($"Process metrics read failed: {ex.Message}");
|
||||
Logger.Debug($"Process metrics read failed: {ex.Message}", repeatKey: "AgentSelfMetricsCollector.process");
|
||||
}
|
||||
|
||||
// --- Spool stats (P2 telemetry) ---
|
||||
@@ -155,7 +155,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Logger.Debug($"Spool metrics read failed: {ex.Message}");
|
||||
Logger.Debug($"Spool metrics read failed: {ex.Message}", repeatKey: "AgentSelfMetricsCollector.spool");
|
||||
}
|
||||
}
|
||||
|
||||
@@ -186,7 +186,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Logger.Debug($"Network metrics read failed: {ex.Message}");
|
||||
Logger.Debug($"Network metrics read failed: {ex.Message}", repeatKey: "AgentSelfMetricsCollector.network");
|
||||
}
|
||||
|
||||
// --- IME log tracker health ---
|
||||
@@ -224,7 +224,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Logger.Debug($"IME tracker health read failed: {ex.Message}");
|
||||
Logger.Debug($"IME tracker health read failed: {ex.Message}", repeatKey: "AgentSelfMetricsCollector.imeTracker");
|
||||
}
|
||||
}
|
||||
|
||||
@@ -262,7 +262,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Logger.Debug($"Signal pipeline health read failed: {ex.Message}");
|
||||
Logger.Debug($"Signal pipeline health read failed: {ex.Message}", repeatKey: "AgentSelfMetricsCollector.signalPipeline");
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
+11
-8
@@ -153,7 +153,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
{
|
||||
if (_permanentlyDisabled || !_dormant) return;
|
||||
_dormant = false;
|
||||
Logger.Info("[DeliveryOptimizationCollector] Waking up — download activity detected");
|
||||
Logger.Debug("[DeliveryOptimizationCollector] Waking up — download activity detected");
|
||||
ResumeTimer();
|
||||
}
|
||||
|
||||
@@ -167,7 +167,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
_officeActive = active;
|
||||
if (active)
|
||||
{
|
||||
Logger.Info("[DeliveryOptimizationCollector] Office install active — sampling DO for Office CDN jobs");
|
||||
Logger.Debug("[DeliveryOptimizationCollector] Office install active — sampling DO for Office CDN jobs");
|
||||
WakeUp();
|
||||
}
|
||||
}
|
||||
@@ -243,7 +243,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
|
||||
if (!hasActiveDownloads && !hasPendingEnrichment && !officeKeepAwake)
|
||||
{
|
||||
Logger.Info("[DeliveryOptimizationCollector] Going dormant — no active downloads, pending enrichment or Office install");
|
||||
Logger.Debug("[DeliveryOptimizationCollector] Going dormant — no active downloads, pending enrichment or Office install");
|
||||
_dormant = true;
|
||||
PauseTimer();
|
||||
// Natural persistence point: all downloads are done — which is exactly when an
|
||||
@@ -278,7 +278,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
{
|
||||
_runspace = RunspaceFactory.CreateRunspace();
|
||||
_runspace.Open();
|
||||
Logger.Info("[DeliveryOptimizationCollector] PowerShell Runspace opened");
|
||||
Logger.Debug("[DeliveryOptimizationCollector] PowerShell Runspace opened");
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
@@ -343,7 +343,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
_permanentlyDisabled = true;
|
||||
return null;
|
||||
}
|
||||
Logger.Debug($"[DeliveryOptimizationCollector] PS error stream: {firstError}");
|
||||
Logger.Debug($"[DeliveryOptimizationCollector] PS error stream: {firstError}", repeatKey: "DeliveryOptimizationCollector.psError");
|
||||
}
|
||||
|
||||
return results;
|
||||
@@ -386,7 +386,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
{
|
||||
if (results.Count == 0)
|
||||
{
|
||||
Logger.Verbose("[DeliveryOptimizationCollector] No DO entries returned");
|
||||
Logger.Trace("[DeliveryOptimizationCollector] No DO entries returned");
|
||||
return;
|
||||
}
|
||||
|
||||
@@ -568,8 +568,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
WriteToLogFile(logEntries);
|
||||
}
|
||||
|
||||
Logger.Verbose($"[DeliveryOptimizationCollector] Poll: {results.Count} entries, " +
|
||||
$"{progressCount} progress updates, {matchCount} new matches ({_enrichedAppIds.Count} total enriched)");
|
||||
var pollSummary = $"[DeliveryOptimizationCollector] Poll: {results.Count} entries, " +
|
||||
$"{progressCount} progress updates, {matchCount} new matches ({_enrichedAppIds.Count} total enriched)";
|
||||
// A poll that found nothing new is a tick (Trace); one with progress or matches is content.
|
||||
if (progressCount > 0 || matchCount > 0) Logger.Verbose(pollSummary);
|
||||
else Logger.Trace(pollSummary);
|
||||
}
|
||||
|
||||
// Office C2R content CDN hosts — version-independent (a FileId build marker like "_16_0_" would
|
||||
|
||||
+3
-1
@@ -80,6 +80,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
|
||||
public void Stop()
|
||||
{
|
||||
// Hosts call Stop and then Dispose, which stops again; only a started detector logs.
|
||||
var wasRunning = _connectivityCheckClient != null;
|
||||
NetworkChange.NetworkAddressChanged -= OnNetworkAddressChanged;
|
||||
|
||||
lock (_stateLock)
|
||||
@@ -91,7 +93,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
_connectivityCheckClient?.Dispose();
|
||||
_connectivityCheckClient = null;
|
||||
|
||||
_logger.Info("NetworkChangeDetector: stopped");
|
||||
if (wasRunning) _logger.Info("NetworkChangeDetector: stopped");
|
||||
}
|
||||
|
||||
public void Dispose()
|
||||
|
||||
+6
-6
@@ -123,7 +123,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Logger.Debug($"CPU counter read failed: {ex.Message}");
|
||||
Logger.Debug($"CPU counter read failed: {ex.Message}", repeatKey: "PerformanceCollector.cpu");
|
||||
}
|
||||
|
||||
// Memory info via GlobalMemoryStatusEx (kernel32)
|
||||
@@ -138,12 +138,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
}
|
||||
else
|
||||
{
|
||||
Logger.Debug("GlobalMemoryStatusEx returned no data");
|
||||
Logger.Debug("GlobalMemoryStatusEx returned no data", repeatKey: "PerformanceCollector.memoryNoData");
|
||||
}
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Logger.Debug($"Memory query failed: {ex.Message}");
|
||||
Logger.Debug($"Memory query failed: {ex.Message}", repeatKey: "PerformanceCollector.memory");
|
||||
}
|
||||
|
||||
// Disk queue length
|
||||
@@ -154,7 +154,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Logger.Debug($"Disk queue counter read failed: {ex.Message}");
|
||||
Logger.Debug($"Disk queue counter read failed: {ex.Message}", repeatKey: "PerformanceCollector.diskQueue");
|
||||
}
|
||||
|
||||
// Disk free space on system drive
|
||||
@@ -181,7 +181,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Logger.Debug($"Disk space query failed: {ex.Message}");
|
||||
Logger.Debug($"Disk space query failed: {ex.Message}", repeatKey: "PerformanceCollector.diskSpace");
|
||||
}
|
||||
|
||||
// Network throughput (bytes sent/received delta + rate)
|
||||
@@ -271,7 +271,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Periodic
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
Logger.Debug($"Network throughput collection failed: {ex.Message}");
|
||||
Logger.Debug($"Network throughput collection failed: {ex.Message}", repeatKey: "PerformanceCollector.network");
|
||||
}
|
||||
|
||||
if (data.Count > 0)
|
||||
|
||||
+6
-1
@@ -174,7 +174,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Telemetry.Security
|
||||
lock (_lock) { _startWatcher = null; }
|
||||
// Surface the dead live detector so the backend can distinguish it from a clean run.
|
||||
var handler = WatcherArmFailed;
|
||||
try { handler?.Invoke(this, ex); } catch { /* never throw from Start */ }
|
||||
try { handler?.Invoke(this, ex); }
|
||||
catch (Exception handlerEx)
|
||||
{
|
||||
// Never throw from Start.
|
||||
_logger.Warning($"[ConsoleBypassWatcher] WatcherArmFailed handler threw: {handlerEx.Message}");
|
||||
}
|
||||
}
|
||||
|
||||
// 2) Startup probe — catch a console already open before the watcher armed. Win32_Process
|
||||
|
||||
@@ -93,7 +93,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Transport
|
||||
attempt.PrimaryError = error;
|
||||
|
||||
// Retry ipinfo.io once after a short delay (network may still be initializing during Autopilot)
|
||||
logger?.Info($"GeoLocation: Retrying ipinfo.io after {RetryDelay.TotalSeconds}s...");
|
||||
logger?.Debug($"GeoLocation: Retrying ipinfo.io after {RetryDelay.TotalSeconds}s...");
|
||||
await Task.Delay(RetryDelay);
|
||||
|
||||
(result, error) = await TryProvider("ipinfo.io", IpInfoUrl, ParseIpInfo, logger);
|
||||
@@ -131,7 +131,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Transport
|
||||
{
|
||||
try
|
||||
{
|
||||
logger?.Info($"GeoLocation: Querying {name}...");
|
||||
logger?.Debug($"GeoLocation: Querying {name}...");
|
||||
|
||||
using (var httpResponse = await SharedHttpClient.GetAsync(url))
|
||||
{
|
||||
|
||||
+1
-1
@@ -29,7 +29,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Transport
|
||||
|
||||
try
|
||||
{
|
||||
logger.Info($"NTP time check: querying {ntpServer}");
|
||||
logger.Debug($"NTP time check: querying {ntpServer}");
|
||||
|
||||
// NTP request packet: 48 bytes, first byte = 0x1B (LI=0, VN=3, Mode=3)
|
||||
var ntpData = new byte[48];
|
||||
|
||||
@@ -47,7 +47,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Transport
|
||||
}
|
||||
|
||||
// Execute tzutil /s to set the timezone
|
||||
logger.Info($"Timezone auto-set: setting timezone to {windowsId} (IANA: {ianaTimezone}, previous: {result.PreviousTimezone})");
|
||||
logger.Debug($"Timezone auto-set: setting timezone to {windowsId} (IANA: {ianaTimezone}, previous: {result.PreviousTimezone})");
|
||||
|
||||
var psi = new ProcessStartInfo
|
||||
{
|
||||
|
||||
@@ -190,7 +190,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
if (_transitionEmitter != null)
|
||||
{
|
||||
try { _transitionEmitter.Emit(step.Transition); }
|
||||
catch { /* best-effort upload; local state already consistent */ }
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Best-effort upload; the local journal already holds the transition.
|
||||
_logger.Debug($"DecisionStepProcessor: transition not handed to the upload spool: {ex.Message}", repeatKey: "DecisionStepProcessor.transitionEmit");
|
||||
}
|
||||
}
|
||||
|
||||
// 2) EffectRunner — Async-Methode vom Ingress-Worker-Thread sync ausführen.
|
||||
@@ -271,21 +275,28 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
_currentState = step.NewState;
|
||||
_consecutiveJournalFailures = 0;
|
||||
|
||||
// PR3-D1: per-step observability. Stage transitions and effect-bearing steps fire
|
||||
// at DEBUG (operator-relevant); pure no-op steps (Stage unchanged + no effects)
|
||||
// fire at VERBOSE so a steady stream of e.g. ClassifierTick + InformationalEvent
|
||||
// pass-throughs doesn't drown the log.
|
||||
// PR3-D1: per-step observability. A stage change is the enrollment flow (Info); other
|
||||
// effect-bearing steps and dead ends are decision detail (Debug); InformationalEvent
|
||||
// pass-throughs, the self-re-arming classifier tick and no-op steps are mechanics
|
||||
// (Trace). The journal keeps every step either way.
|
||||
var newStage = step.NewState.Stage;
|
||||
if (previousStage != newStage || step.Effects.Count > 0)
|
||||
{
|
||||
_logger.Debug(
|
||||
var line =
|
||||
$"DecisionStep: ord={signal.SessionSignalOrdinal} kind={signal.Kind} " +
|
||||
$"stage={previousStage}->{newStage} effects=[{string.Join(",", step.Effects.Select(e => e.Kind))}] " +
|
||||
$"abort={effectResult.SessionMustAbort} failures={effectResult.Failures.Count}");
|
||||
$"abort={effectResult.SessionMustAbort} failures={effectResult.Failures.Count}";
|
||||
if (previousStage != newStage) _logger.Info(line);
|
||||
else if (IsRoutineStep(signal, effectResult)) _logger.Trace(line);
|
||||
else _logger.Debug(line);
|
||||
}
|
||||
else if (step.Transition.DeadEndReason != null)
|
||||
{
|
||||
_logger.Debug($"DecisionStep: ord={signal.SessionSignalOrdinal} kind={signal.Kind} stage={previousStage} dead end ({step.Transition.DeadEndReason})");
|
||||
}
|
||||
else
|
||||
{
|
||||
_logger.Verbose($"DecisionStep: ord={signal.SessionSignalOrdinal} kind={signal.Kind} stage={previousStage} (no-op)");
|
||||
_logger.Trace($"DecisionStep: ord={signal.SessionSignalOrdinal} kind={signal.Kind} stage={previousStage} (no-op)");
|
||||
}
|
||||
|
||||
// 5) Terminal-stage detection (M4.6.β). Fires exactly once per agent run when the
|
||||
@@ -505,6 +516,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
return _passThroughStepsSinceSnapshot >= SnapshotPassThroughFloor;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// A step that runs for every informational event, or for the classifier tick that re-arms
|
||||
/// itself every 30 s, without changing the stage. Decided by the signal, not the effect:
|
||||
/// real decisions emit timeline entries too. A failed effect run is never routine.
|
||||
/// </summary>
|
||||
private static bool IsRoutineStep(DecisionSignal signal, EffectRunResult effectResult)
|
||||
{
|
||||
if (effectResult.SessionMustAbort || effectResult.Failures.Count > 0) return false;
|
||||
if (signal.Kind == DecisionSignalKind.InformationalEvent) return true;
|
||||
return signal.Kind == DecisionSignalKind.DeadlineFired
|
||||
&& signal.Payload != null
|
||||
&& signal.Payload.TryGetValue(SignalPayloadKeys.Deadline, out var deadline)
|
||||
&& string.Equals(deadline, DeadlineNames.ClassifierTick, StringComparison.Ordinal);
|
||||
}
|
||||
|
||||
private void TryTriggerQuarantine(string reason)
|
||||
{
|
||||
try
|
||||
|
||||
@@ -206,7 +206,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
!string.IsNullOrEmpty(lastVerdictId) &&
|
||||
snapshotHash == lastVerdictId)
|
||||
{
|
||||
_logger?.Debug(
|
||||
_logger?.Trace(
|
||||
$"EffectRunner: classifier {effect.ClassifierId} skipped (snapshotHash unchanged: {ShortHash(snapshotHash)})");
|
||||
return new ClassifierEffectOutcome(invoked: false, skippedByAntiLoop: true, failure: null);
|
||||
}
|
||||
|
||||
@@ -456,7 +456,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
// (eventType, phase) here. Fed to the collector-host factory at step 14 so gather-rule
|
||||
// phase_change/on_event triggers key off the ENGINE-REDUCED timeline (RealmJoin gate
|
||||
// et al. respected) instead of raw pre-reduce signals — see TimelineEventStream doc.
|
||||
_timelineEvents = new TimelineEventStream();
|
||||
_timelineEvents = new TimelineEventStream(_logger);
|
||||
_timelineEmitter = new EventTimelineEmitter(eventEmitter, _timelineEvents);
|
||||
_backPressureObserver = new BackPressureEventObserver(eventEmitter, _clock);
|
||||
|
||||
@@ -836,7 +836,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
}),
|
||||
payload: payload);
|
||||
|
||||
_logger.Info(
|
||||
_logger.Debug(
|
||||
$"EnrollmentOrchestrator: EspConfigDetected bootstrap posted (SkipUser={snapshot.SkipUser?.ToString() ?? "unknown"}, SkipDevice={snapshot.SkipDevice?.ToString() ?? "unknown"}, AllowContinueAnyway={snapshot.AllowContinueAnyway?.ToString() ?? "unknown"}, SyncFailureTimeoutMinutes={snapshot.SyncFailureTimeoutMinutes?.ToString() ?? "unknown"}).");
|
||||
}
|
||||
catch (Exception ex)
|
||||
|
||||
@@ -33,7 +33,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
Func<bool>? isHybridJoinProbe = null)
|
||||
{
|
||||
_watcher = new AadJoinWatcher(logger);
|
||||
_adapter = new AadJoinWatcherAdapter(_watcher, ingress, clock, onRealUserJoined: onRealUserJoined);
|
||||
_adapter = new AadJoinWatcherAdapter(_watcher, ingress, clock, onRealUserJoined: onRealUserJoined, logger: logger);
|
||||
var post = new InformationalEventPost(ingress, clock);
|
||||
_hybridLoginPendingDetector = new HybridLoginPendingDetector(
|
||||
watcher: _watcher,
|
||||
|
||||
+1
-1
@@ -50,7 +50,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
{
|
||||
if (Interlocked.Exchange(ref _fired, 1) == 1)
|
||||
{
|
||||
_logger.Info("AutoLogonDeviceSetupTrigger: duplicate DeviceSetupProvisioningComplete ignored (already fired)");
|
||||
_logger.Debug("AutoLogonDeviceSetupTrigger: duplicate DeviceSetupProvisioningComplete ignored (already fired)");
|
||||
return;
|
||||
}
|
||||
|
||||
|
||||
@@ -108,13 +108,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
try { _collector.CollectAll(); }
|
||||
catch (Exception ex) { _logger.Warning($"DeviceInfoHost: CollectAll threw: {ex.Message}"); }
|
||||
});
|
||||
_logger.Info("DeviceInfoHost: CollectAll scheduled on background thread.");
|
||||
_logger.Debug("DeviceInfoHost: CollectAll scheduled on background thread.");
|
||||
|
||||
if (_observableIngress != null && _handler == null)
|
||||
{
|
||||
_handler = OnSignalPosted;
|
||||
_observableIngress.SignalPosted += _handler;
|
||||
_logger.Info("DeviceInfoHost: armed phase-driven re-collections (DeviceSetup → enrollment refresh; FinalizingSetup/desktop → end collect).");
|
||||
_logger.Debug("DeviceInfoHost: armed phase-driven re-collections (DeviceSetup → enrollment refresh; FinalizingSetup/desktop → end collect).");
|
||||
}
|
||||
}
|
||||
|
||||
@@ -134,7 +134,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
if (!runStartRefresh && !runEndCollect) return;
|
||||
|
||||
var trigger = kind == DecisionSignalKind.DesktopArrived ? "desktop_arrived" : "esp_phase_changed";
|
||||
_logger.Info($"DeviceInfoHost: trigger '{trigger}' — scheduling re-collect (enrollmentStart={runStartRefresh}, end={runEndCollect}).");
|
||||
_logger.Debug($"DeviceInfoHost: trigger '{trigger}' — scheduling re-collect (enrollmentStart={runStartRefresh}, end={runEndCollect}).");
|
||||
|
||||
// Offload WMI/registry IO off the ingress writer thread. The gate suppresses
|
||||
// everything that did not actually change.
|
||||
@@ -170,7 +170,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
if (!_espConfigRefreshesFired.Add(trigger)) return;
|
||||
}
|
||||
|
||||
_logger.Info($"DeviceInfoHost: ESP-config refresh trigger '{trigger}' — scheduling re-collect.");
|
||||
_logger.Debug($"DeviceInfoHost: ESP-config refresh trigger '{trigger}' — scheduling re-collect.");
|
||||
Task.Run(() =>
|
||||
{
|
||||
try { _collector.RefreshEspConfiguration(trigger); }
|
||||
|
||||
+1
-1
@@ -133,7 +133,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Verbose($"GatherRuleExecutorHost: timeline-trigger dispatch failed: {ex.Message}");
|
||||
_logger.Debug($"GatherRuleExecutorHost: timeline-trigger dispatch failed: {ex.Message}", repeatKey: "GatherRuleExecutorHost.dispatchFailed");
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
+2
-2
@@ -80,7 +80,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
filter: RegistryNativeMethods.RegChangeNotifyFilter.Name
|
||||
| RegistryNativeMethods.RegChangeNotifyFilter.LastSet
|
||||
| RegistryNativeMethods.RegChangeNotifyFilter.ThreadAgnostic,
|
||||
trace: msg => _logger?.Debug($"ImeRegistryAppState watcher: {msg}"));
|
||||
trace: msg => _logger?.Trace($"ImeRegistryAppState watcher: {msg}"));
|
||||
_watcher.Changed += (_, __) => ScheduleDebouncedTick();
|
||||
_watcher.Error += (_, ex) =>
|
||||
{
|
||||
@@ -131,7 +131,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Observer.Tick is itself fail-soft; this is the last-resort belt.
|
||||
_logger?.Debug($"ImeRegistryAppState tick failed: {ex.Message}");
|
||||
_logger?.Debug($"ImeRegistryAppState tick failed: {ex.Message}", repeatKey: "ImeRegistryAppStateHost.tickFailed");
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
+2
-2
@@ -205,7 +205,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
catch (Exception ex)
|
||||
{
|
||||
error = ex;
|
||||
_logger.Info($"[{Name}] arm attempt '{modeLabel}' failed ({ex.GetType().Name}: {ex.Message})");
|
||||
_logger.Debug($"[{Name}] arm attempt '{modeLabel}' failed ({ex.GetType().Name}: {ex.Message})");
|
||||
lock (_lock) { _watcher = null; }
|
||||
return false;
|
||||
}
|
||||
@@ -264,7 +264,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Debug($"[{Name}] debounced power tick failed: {ex.Message}");
|
||||
_logger.Debug($"[{Name}] debounced power tick failed: {ex.Message}", repeatKey: "PowerStateWatcherHost.tickFailed");
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
+1
-1
@@ -199,7 +199,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Verbose($"UserEspKeepAwakeHost: signal dispatch failed: {ex.Message}");
|
||||
_logger.Debug($"UserEspKeepAwakeHost: signal dispatch failed: {ex.Message}", repeatKey: "UserEspKeepAwakeHost.dispatchFailed");
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
+1
-1
@@ -58,7 +58,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
{
|
||||
if (Interlocked.Exchange(ref _fired, 1) == 1)
|
||||
{
|
||||
_logger.Info("WhiteGloveInventoryTrigger: duplicate WhiteGloveCompleted ignored (already fired)");
|
||||
_logger.Debug("WhiteGloveInventoryTrigger: duplicate WhiteGloveCompleted ignored (already fired)");
|
||||
return;
|
||||
}
|
||||
|
||||
|
||||
@@ -142,13 +142,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
payload: payload,
|
||||
typedPayload: typedPayload);
|
||||
|
||||
// PR3-D5: lifecycle-event observability — DEBUG so it doesn't dominate at INFO,
|
||||
// but every event that hits the timeline has a matching agent-log line. First
|
||||
// PR3-D5: lifecycle-event observability — VERBOSE (per-item detail, D-394), so every
|
||||
// event that hits the timeline has a matching agent-log line at that level. First
|
||||
// 8 payload keys are usually enough to identify the event variant.
|
||||
if (_logger != null)
|
||||
{
|
||||
var keys = string.Join(",", payload.Keys.Take(8));
|
||||
_logger.Debug(
|
||||
_logger.Verbose(
|
||||
$"InformationalEventPost: emit eventType={eventType} source={source} " +
|
||||
$"immediate={immediateUpload} severity={severity?.ToString() ?? "default"} " +
|
||||
$"dataKeys=[{keys}]");
|
||||
|
||||
@@ -383,11 +383,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
var handler = SignalPosted;
|
||||
if (handler == null) return;
|
||||
try { handler(kind, payload); }
|
||||
catch
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Observer exceptions MUST NOT disrupt the production ingress path. The idle-
|
||||
// activity observer (Codex Finding 4) is advisory — dropping one observation
|
||||
// is strictly better than surfacing a mid-Post exception to a collector thread.
|
||||
_logger?.Debug($"SignalIngress: SignalPosted observer threw: {ex.Message}", repeatKey: "SignalIngress.signalPostedObserver");
|
||||
}
|
||||
}
|
||||
|
||||
@@ -413,9 +414,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
{
|
||||
_observer.OnBackPressure(origin, _channelCapacity, queueLengthAtBlock, blockedFor);
|
||||
}
|
||||
catch
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Observer-Fehler dürfen den Produktions-Pfad nicht aufhalten. Weglucken.
|
||||
// An observer fault must not hold up the production path.
|
||||
_logger?.Debug($"SignalIngress: back-pressure observer threw: {ex.Message}", repeatKey: "SignalIngress.backPressureObserver");
|
||||
}
|
||||
}
|
||||
|
||||
@@ -518,9 +520,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
|
||||
_nextSignalOrdinal = signalOrdinal + 1;
|
||||
// PR3-D2: 1:1 correlation marker for D1 (DecisionStepProcessor logs the same ord +
|
||||
// kind on the receive side). Verbose because the steady-state happy-path is the
|
||||
// dominant cardinality.
|
||||
_logger?.Verbose($"SignalIngress: processed ord={signalOrdinal} kind={item.Kind} origin={item.SourceOrigin}.");
|
||||
// kind on the receive side). Trace: one line per signal is mechanics (D-394).
|
||||
_logger?.Trace($"SignalIngress: processed ord={signalOrdinal} kind={item.Kind} origin={item.SourceOrigin}.");
|
||||
Interlocked.Increment(ref _processedCount);
|
||||
|
||||
// Project the signal onto the telemetry transport for backend upload. Local
|
||||
@@ -530,7 +531,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
if (_signalEmitter != null)
|
||||
{
|
||||
try { _signalEmitter.Emit(signal); }
|
||||
catch { /* best-effort upload; local state already consistent */ }
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Best-effort upload; the local SignalLog already holds the signal.
|
||||
_logger?.Debug($"SignalIngress: signal not handed to the upload spool: {ex.Message}", repeatKey: "SignalIngress.signalEmit");
|
||||
}
|
||||
}
|
||||
|
||||
var state = _processor.CurrentState;
|
||||
@@ -544,9 +549,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
}
|
||||
catch
|
||||
{
|
||||
// Processor-Fehler (z.B. Journal-Write, Effect-Transient-Exhaust) werden in
|
||||
// M4.4.5 vom Orchestrator geloggt + ggf. Quarantine ausgelöst. M4.4.0
|
||||
// verschluckt bewusst, damit der Ingress-Worker nicht verstummt.
|
||||
// ApplyStep logs its own failures (a journal append fault at Error, before it
|
||||
// rethrows and counts towards quarantine); swallowed here so the worker keeps running.
|
||||
}
|
||||
|
||||
// Codex follow-up (post-#50 #B): inline durable-abort path. When the step's
|
||||
@@ -649,7 +653,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
if (_signalEmitter != null)
|
||||
{
|
||||
try { _signalEmitter.Emit(syntheticSignal); }
|
||||
catch { /* best-effort upload */ }
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Best-effort upload; the local SignalLog already holds the signal.
|
||||
_logger?.Debug($"SignalIngress: signal not handed to the upload spool: {ex.Message}", repeatKey: "SignalIngress.signalEmit");
|
||||
}
|
||||
}
|
||||
|
||||
var state = _processor.CurrentState;
|
||||
@@ -662,8 +670,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
catch
|
||||
{
|
||||
// Processor fault on the terminal transition — Journal has the abort
|
||||
// transition committed (reducer produces Stage=Failed unconditionally).
|
||||
// Swallowed by convention; worker must not die from this path.
|
||||
// transition committed (reducer produces Stage=Failed unconditionally), and
|
||||
// ApplyStep has logged the fault. Swallowed so the worker does not die here.
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@@ -1,5 +1,6 @@
|
||||
#nullable enable
|
||||
using System;
|
||||
using AutopilotMonitor.Agent.V2.Core.Logging;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
@@ -24,11 +25,19 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
/// <b>Threading</b>: <see cref="Publish"/> runs on the ingress worker thread (the effect
|
||||
/// execution path). Subscribers must stay fast and must not block; subscriber exceptions are
|
||||
/// swallowed per handler so the emit path can never throw (an exception here would surface
|
||||
/// as an EffectRunner transient retry and duplicate the emitted event).
|
||||
/// as an EffectRunner transient retry and duplicate the emitted event). They are logged at
|
||||
/// Debug, an identical repeat at Trace.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public sealed class TimelineEventStream
|
||||
{
|
||||
private readonly AgentLogger? _logger;
|
||||
|
||||
public TimelineEventStream(AgentLogger? logger = null)
|
||||
{
|
||||
_logger = logger;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Raised once per emitted timeline event with its <see cref="EnrollmentEvent.EventType"/>
|
||||
/// and parsed <see cref="EnrollmentEvent.Phase"/> (<see cref="EnrollmentPhase.Unknown"/>
|
||||
@@ -48,9 +57,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
foreach (Action<string, EnrollmentPhase, string> subscriber in handler.GetInvocationList())
|
||||
{
|
||||
try { subscriber(eventType, phase, source); }
|
||||
catch
|
||||
catch (Exception ex)
|
||||
{
|
||||
// Subscriber isolation — see class doc: the emit path must never throw.
|
||||
var name = $"{subscriber.Method.DeclaringType?.Name}.{subscriber.Method.Name}";
|
||||
_logger?.Debug($"TimelineEventStream: subscriber {name} threw: {ex.Message}", repeatKey: "TimelineEventStream.subscriber:" + name);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
@@ -249,7 +249,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Persistence
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Debug($"StartupEventGate: failed to save state: {ex.Message}");
|
||||
_logger.Debug($"StartupEventGate: failed to save state: {ex.Message}", repeatKey: "StartupEventGate.save");
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@@ -64,7 +64,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Runtime
|
||||
_logger,
|
||||
_analyzerConfig.LocalAdminAllowedAccounts,
|
||||
_startupEventGate));
|
||||
_logger.Info("LocalAdminAnalyzer registered");
|
||||
_logger.Debug("LocalAdminAnalyzer registered");
|
||||
}
|
||||
else
|
||||
{
|
||||
@@ -79,7 +79,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Runtime
|
||||
_post,
|
||||
_logger,
|
||||
_startupEventGate));
|
||||
_logger.Info("SoftwareInventoryAnalyzer registered");
|
||||
_logger.Debug("SoftwareInventoryAnalyzer registered");
|
||||
}
|
||||
else
|
||||
{
|
||||
@@ -94,7 +94,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Runtime
|
||||
_post,
|
||||
_logger,
|
||||
_startupEventGate));
|
||||
_logger.Info("IntegrityBypassAnalyzer registered");
|
||||
_logger.Debug("IntegrityBypassAnalyzer registered");
|
||||
}
|
||||
else
|
||||
{
|
||||
@@ -113,7 +113,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Runtime
|
||||
_post,
|
||||
_logger,
|
||||
_startupEventGate));
|
||||
_logger.Info("ConsolePrefetchScanner registered");
|
||||
_logger.Debug("ConsolePrefetchScanner registered");
|
||||
}
|
||||
else
|
||||
{
|
||||
@@ -128,7 +128,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Runtime
|
||||
_configuration.TenantId,
|
||||
_post,
|
||||
_logger));
|
||||
_logger.Info("AutoLogonAnalyzer registered (always-on)");
|
||||
_logger.Debug("AutoLogonAnalyzer registered (always-on)");
|
||||
|
||||
_logger.Info($"Analyzers initialized: {_analyzers.Count} active");
|
||||
}
|
||||
@@ -144,7 +144,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Runtime
|
||||
if (_analyzers.Count == 0) return;
|
||||
|
||||
var snapshot = new List<IAgentAnalyzer>(_analyzers);
|
||||
_logger.Info($"Scheduling {snapshot.Count} startup analyzer(s) on background thread");
|
||||
_logger.Debug($"Scheduling {snapshot.Count} startup analyzer(s) on background thread");
|
||||
|
||||
Task.Run(() =>
|
||||
{
|
||||
@@ -166,7 +166,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Runtime
|
||||
if (!_initialised) Initialize();
|
||||
if (_analyzers.Count == 0) return;
|
||||
|
||||
_logger.Info($"Running {_analyzers.Count} shutdown analyzer(s) (whiteGlovePart={whiteGlovePart?.ToString() ?? "none"})");
|
||||
_logger.Debug($"Running {_analyzers.Count} shutdown analyzer(s) (whiteGlovePart={whiteGlovePart?.ToString() ?? "none"})");
|
||||
|
||||
foreach (var analyzer in _analyzers)
|
||||
{
|
||||
@@ -202,7 +202,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Runtime
|
||||
|
||||
try
|
||||
{
|
||||
_logger.Info("DeviceSetup complete — running AutoLogonAnalyzer.AnalyzeAtDeviceSetupComplete()");
|
||||
_logger.Debug("DeviceSetup complete — running AutoLogonAnalyzer.AnalyzeAtDeviceSetupComplete()");
|
||||
autoLogonAnalyzer.AnalyzeAtDeviceSetupComplete();
|
||||
}
|
||||
catch (Exception ex)
|
||||
@@ -241,7 +241,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Runtime
|
||||
|
||||
try
|
||||
{
|
||||
_logger.Info("WhiteGlove Part 1 inventory snapshot — running SoftwareInventoryAnalyzer.AnalyzeAtShutdown(whiteGlovePart: 1)");
|
||||
_logger.Debug("WhiteGlove Part 1 inventory snapshot — running SoftwareInventoryAnalyzer.AnalyzeAtShutdown(whiteGlovePart: 1)");
|
||||
softwareAnalyzer.AnalyzeAtShutdown(whiteGlovePart: 1);
|
||||
}
|
||||
catch (Exception ex)
|
||||
|
||||
@@ -136,7 +136,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Security
|
||||
{
|
||||
if (_distressReporter != null && Volatile.Read(ref _distressDispatched) == 0)
|
||||
{
|
||||
_logger.Info(
|
||||
_logger.Debug(
|
||||
$"AuthFailureTracker: distress report suppressed for {operation} (http {statusCode}) — " +
|
||||
"endpoint unavailable (platform error page), a report cannot reach a stopped endpoint.");
|
||||
}
|
||||
@@ -212,7 +212,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Security
|
||||
$"{operation} http {statusCode} {classification.ForeignReason}; " +
|
||||
$"page \"{classification.PageTitle ?? "(none)"}\"; " +
|
||||
$"server cert issuer \"{classification.ServerCertIssuer ?? "(unknown)"}\"";
|
||||
_logger.Info($"AuthFailureTracker: answer did not come from the backend — not an authentication failure, not counted ({finding}).");
|
||||
_logger.Info($"AuthFailureTracker: answer did not come from the backend — not an authentication failure, not counted ({finding}).", repeatKey: "AuthFailureTracker.notBackend");
|
||||
|
||||
if (_distressReporter == null || Interlocked.CompareExchange(ref _foreignDistressDispatched, 1, 0) != 0)
|
||||
return;
|
||||
|
||||
@@ -17,8 +17,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Security
|
||||
/// </summary>
|
||||
/// <param name="thumbprint">Optional specific thumbprint to search for</param>
|
||||
/// <param name="logger">Logger for diagnostic output</param>
|
||||
/// <param name="logNotFound">False where "not found" is expected, e.g. the await-enrollment poll.</param>
|
||||
/// <returns>The MDM certificate, or null if not found</returns>
|
||||
public static X509Certificate2 FindMdmCertificate(string thumbprint = null, AgentLogger logger = null)
|
||||
public static X509Certificate2 FindMdmCertificate(string thumbprint = null, AgentLogger logger = null, bool logNotFound = true)
|
||||
{
|
||||
try
|
||||
{
|
||||
@@ -35,7 +36,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Security
|
||||
{
|
||||
store.Open(OpenFlags.ReadOnly);
|
||||
|
||||
logger?.Debug($"Searching for MDM certificate in {storeInfo.Location}\\{storeInfo.Name}");
|
||||
logger?.Trace($"Searching for MDM certificate in {storeInfo.Location}\\{storeInfo.Name}");
|
||||
|
||||
// If thumbprint specified, search by thumbprint
|
||||
if (!string.IsNullOrEmpty(thumbprint))
|
||||
@@ -47,7 +48,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Security
|
||||
|
||||
if (cert != null)
|
||||
{
|
||||
logger?.Info($"Found certificate by thumbprint: {thumbprint}");
|
||||
logger?.Debug($"Found certificate by thumbprint: {thumbprint}");
|
||||
return cert;
|
||||
}
|
||||
}
|
||||
@@ -59,14 +60,14 @@ namespace AutopilotMonitor.Agent.V2.Core.Security
|
||||
var cert = SelectMdmCertificate(store.Certificates.OfType<X509Certificate2>());
|
||||
if (cert != null)
|
||||
{
|
||||
logger?.Info($"Found MDM certificate: Issuer={cert.Issuer}, Subject={cert.Subject}, Thumbprint={cert.Thumbprint}");
|
||||
logger?.Debug($"Found MDM certificate: Issuer={cert.Issuer}, Subject={cert.Subject}, Thumbprint={cert.Thumbprint}");
|
||||
return cert;
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
logger?.Warning("No MDM certificate found");
|
||||
if (logNotFound) logger?.Warning("No MDM certificate found");
|
||||
return null;
|
||||
}
|
||||
catch (Exception ex)
|
||||
|
||||
Some files were not shown because too many files have changed in this diff Show More
Reference in New Issue
Block a user