mirror of
https://github.com/okieselbach/AutopilotMonitor.git
synced 2026-10-25 13:10:13 +00:00
Compare commits
12 Commits
| Author | SHA1 | Date | |
|---|---|---|---|
 Oliver Kieselbach
|
d1063f17cb | ||
|
Oliver Kieselbach
|
ed517b5b40 | ||
|
Oliver Kieselbach
|
46058ffb90 | ||
|
Oliver Kieselbach
|
81d0fe6ed3 | ||
|
Oliver Kieselbach
|
a26cd5edf7 | ||
|
Oliver Kieselbach
|
48e9702fd2 | ||
|
Oliver Kieselbach
|
b560cb13b6 | ||
|
Oliver Kieselbach
|
b0f866dc7d | ||
|
Oliver Kieselbach
|
f3460ea828 | ||
|
Oliver Kieselbach
|
d88d4a143b | ||
|
Oliver Kieselbach
|
913dfa13fe | ||
|
Oliver Kieselbach
|
51345718c6 |
+1
-1
Submodule internal updated: fd299a3c0d...11c68982fa
@@ -0,0 +1,118 @@
|
||||
{
|
||||
"$schema": "../schema/analyze-rule.schema.json",
|
||||
"ruleId": "ANALYZE-DEV-013",
|
||||
"title": "OOBE Quality Update Failed",
|
||||
"description": "Detects that the Windows quality update page at the end of OOBE (Enrollment Status Page setting \"Install Windows quality updates\") reported a failed download or install and recorded no successful install afterwards — the page's own failure names on the oobe_update_page events. Setup usually continues, so the failure is otherwise invisible: the device finishes OOBE without the monthly security update. An OS build change across a restart (os_build_changed) vetoes the finding, and so does the agent's names_capped marker — once the page's event names were capped, a missing success name proves nothing. A downloadInstallFailureHelper entry alone is no failure: updates that installed fine log it too.",
|
||||
"severity": "warning",
|
||||
"category": "device",
|
||||
"version": "1.0.0",
|
||||
"enabled": true,
|
||||
"evaluateOn": [
|
||||
"enrollment_end"
|
||||
],
|
||||
"trigger": "single",
|
||||
"baseConfidence": 75,
|
||||
"confidenceThreshold": 60,
|
||||
"conditions": [
|
||||
{
|
||||
"signal": "update_failure",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "name",
|
||||
"operator": "in",
|
||||
"value": "SdxWebAppCloudNDUP_processStatusChangeFromHandler_downloadFailedError,SdxWebAppCloudNDUP_processStatusChangeFromHandler_installFailedError,ExpeditedUpdate_commitExpeditionDownloadInstallAsyncFailure",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "no_install_success",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "name",
|
||||
"operator": "not_exists",
|
||||
"value": "",
|
||||
"filterField": "name",
|
||||
"filterOperator": "regex",
|
||||
"filterValue": "installSucceededRebootRequired|commitExpeditionDownloadInstallAsyncSucceeded",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "os_build_unchanged",
|
||||
"source": "event_type",
|
||||
"eventType": "os_build_changed",
|
||||
"operator": "not_exists",
|
||||
"value": "",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "page_names_complete",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "cxhEvent",
|
||||
"operator": "not_exists",
|
||||
"value": "",
|
||||
"filterField": "cxhEvent",
|
||||
"filterOperator": "equals",
|
||||
"filterValue": "names_capped",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "update_page_failed",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "result",
|
||||
"operator": "equals",
|
||||
"value": "fail",
|
||||
"filterField": "page",
|
||||
"filterOperator": "equals",
|
||||
"filterValue": "OobeNDUP",
|
||||
"required": false
|
||||
},
|
||||
{
|
||||
"signal": "update_skipped",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "name",
|
||||
"operator": "regex",
|
||||
"value": "SkipDownloadInstallButtonClicked$",
|
||||
"required": false
|
||||
}
|
||||
],
|
||||
"confidenceFactors": [
|
||||
{
|
||||
"signal": "update_page_failed",
|
||||
"condition": "exists",
|
||||
"weight": 10
|
||||
}
|
||||
],
|
||||
"explanation": "The Windows quality update page at the end of OOBE reported `{{update_failure}}`, and no successful install was recorded afterwards. When the download or install of the update fails, the page gives up and setup continues, so the enrollment itself can still succeed — but the device most likely finished OOBE without the monthly security update and installs it only later, through the Windows Update policy that applies after enrollment. Selecting Skip on the page after the failure leads to the same result.",
|
||||
"remediation": [
|
||||
{
|
||||
"title": "Find out why the update failed",
|
||||
"steps": [
|
||||
"Open the oobe_update_page events around the failure in the session timeline: the download progress before it shows how far the download got, and a Skip after it shows that someone chose to continue.",
|
||||
"Check the network path the device uses during OOBE for Windows Update and Delivery Optimization: proxy, TLS inspection and firewall rules for the Windows Update endpoints.",
|
||||
"Compare with other devices: the same failure on many devices of one site points at the network path, on one model at the device, and across the fleet at the update itself."
|
||||
]
|
||||
},
|
||||
{
|
||||
"title": "Make sure the device gets the update",
|
||||
"steps": [
|
||||
"Verify the device's patch level after enrollment; the update ring assigned to the device installs the missing monthly security update on its normal schedule.",
|
||||
"Where the OOBE quality update keeps failing for one network or device group, decide per Enrollment Status Page profile whether \"Install Windows quality updates\" should stay on."
|
||||
]
|
||||
}
|
||||
],
|
||||
"relatedDocs": [
|
||||
{
|
||||
"title": "Microsoft Learn: Install Windows quality updates during OOBE (Enrollment Status Page)",
|
||||
"url": "https://learn.microsoft.com/en-us/intune/device-enrollment/windows/setup-status-page#windows-monthly-security-update-release-details"
|
||||
}
|
||||
],
|
||||
"markSessionAsFailedDefault": false,
|
||||
"tags": [
|
||||
"device",
|
||||
"windows-update",
|
||||
"oobe",
|
||||
"quality-update"
|
||||
]
|
||||
}
|
||||
@@ -0,0 +1,119 @@
|
||||
{
|
||||
"$schema": "../schema/analyze-rule.schema.json",
|
||||
"ruleId": "ANALYZE-DEV-014",
|
||||
"title": "OOBE Quality Update Not Offered After an Earlier Failure",
|
||||
"description": "Detects that the Windows quality update page at the end of OOBE found no update to install although the device is out of date, on a device whose update page counts an earlier failed download or install (oobe_update_page: NDUPDownloadInstallPreviousFailureCount above 0, osUpdatesWithNDUPPI false, getDaysOutOfDateSucceeded above 0). No failure and no install success are recorded in this session — a failure in this session is ANALYZE-DEV-013 — and the agent's names_capped marker vetoes the finding, because a missing name proves nothing once the page's names were capped. The device finishes OOBE without the monthly security update.",
|
||||
"severity": "warning",
|
||||
"category": "device",
|
||||
"version": "1.0.0",
|
||||
"enabled": true,
|
||||
"evaluateOn": [
|
||||
"enrollment_end"
|
||||
],
|
||||
"trigger": "single",
|
||||
"baseConfidence": 75,
|
||||
"confidenceThreshold": 60,
|
||||
"conditions": [
|
||||
{
|
||||
"signal": "previous_failures",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "value",
|
||||
"operator": "gt",
|
||||
"value": "0",
|
||||
"filterField": "name",
|
||||
"filterOperator": "equals",
|
||||
"filterValue": "SdxWebAppCloudNDUP_initialize_NDUPDownloadInstallPreviousFailureCount",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "nothing_offered",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "value",
|
||||
"operator": "equals",
|
||||
"value": "false",
|
||||
"filterField": "name",
|
||||
"filterOperator": "equals",
|
||||
"filterValue": "SdxWebAppCloudNDUP_updateManager_processUpdatesMetadata_osUpdatesWithNDUPPI",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "days_out_of_date",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "value",
|
||||
"operator": "gt",
|
||||
"value": "0",
|
||||
"filterField": "name",
|
||||
"filterOperator": "equals",
|
||||
"filterValue": "ExpeditedUpdate_getDaysOutOfDateSucceeded",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "no_update_failure",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "name",
|
||||
"operator": "not_exists",
|
||||
"value": "",
|
||||
"filterField": "name",
|
||||
"filterOperator": "in",
|
||||
"filterValue": "SdxWebAppCloudNDUP_processStatusChangeFromHandler_downloadFailedError,SdxWebAppCloudNDUP_processStatusChangeFromHandler_installFailedError,ExpeditedUpdate_commitExpeditionDownloadInstallAsyncFailure",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "no_install_success",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "name",
|
||||
"operator": "not_exists",
|
||||
"value": "",
|
||||
"filterField": "name",
|
||||
"filterOperator": "regex",
|
||||
"filterValue": "installSucceededRebootRequired|commitExpeditionDownloadInstallAsyncSucceeded",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "page_names_complete",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "cxhEvent",
|
||||
"operator": "not_exists",
|
||||
"value": "",
|
||||
"filterField": "cxhEvent",
|
||||
"filterOperator": "equals",
|
||||
"filterValue": "names_capped",
|
||||
"required": true
|
||||
}
|
||||
],
|
||||
"explanation": "The Windows quality update page at the end of OOBE checked for updates and found none to install, although Windows reports the device as {{days_out_of_date}} days out of date. The page's failure counter for this device stands at {{previous_failures}}: an earlier download or install of an OOBE quality update on this device failed. The device finished OOBE without the monthly security update and installs it only later, through the Windows Update policy that applies after enrollment.",
|
||||
"remediation": [
|
||||
{
|
||||
"title": "Check the earlier attempt",
|
||||
"steps": [
|
||||
"Look at the device's earlier enrollment sessions — the failed attempt and its ANALYZE-DEV-013 finding are usually there.",
|
||||
"Verify the device's patch level after enrollment; the update ring assigned to the device installs the missing monthly security update on its normal schedule."
|
||||
]
|
||||
},
|
||||
{
|
||||
"title": "Reduce how far behind devices start",
|
||||
"steps": [
|
||||
"Devices that start OOBE many months behind need a long update during setup; a current OS image or factory build shortens it and gives a failed attempt less to repeat."
|
||||
]
|
||||
}
|
||||
],
|
||||
"relatedDocs": [
|
||||
{
|
||||
"title": "Microsoft Learn: Install Windows quality updates during OOBE (Enrollment Status Page)",
|
||||
"url": "https://learn.microsoft.com/en-us/intune/device-enrollment/windows/setup-status-page#windows-monthly-security-update-release-details"
|
||||
}
|
||||
],
|
||||
"markSessionAsFailedDefault": false,
|
||||
"tags": [
|
||||
"device",
|
||||
"windows-update",
|
||||
"oobe",
|
||||
"quality-update"
|
||||
]
|
||||
}
|
||||
@@ -0,0 +1,117 @@
|
||||
{
|
||||
"$schema": "../schema/analyze-rule.schema.json",
|
||||
"ruleId": "ANALYZE-DEV-015",
|
||||
"title": "OOBE Update Check Ended Without a Result",
|
||||
"description": "Detects that the Windows quality update page at the end of OOBE started its Windows Update scan but ended without a scan result (oobe_update_page: startWUScanStartedSuccedded, an OobeNDUP stop and no ExpeditedUpdate_getUpdateResults name), on a device that is out of date and allowed to update. In the observed sessions the page ended two minutes after the scan started, on devices more than a year behind. The device finishes OOBE without the monthly security update. The agent's names_capped marker vetoes the finding: once the page's event names were capped, a missing scan result proves nothing.",
|
||||
"severity": "warning",
|
||||
"category": "device",
|
||||
"version": "1.0.0",
|
||||
"enabled": true,
|
||||
"evaluateOn": [
|
||||
"enrollment_end"
|
||||
],
|
||||
"trigger": "single",
|
||||
"baseConfidence": 75,
|
||||
"confidenceThreshold": 60,
|
||||
"conditions": [
|
||||
{
|
||||
"signal": "update_allowed",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "value",
|
||||
"operator": "equals",
|
||||
"value": "true",
|
||||
"filterField": "name",
|
||||
"filterOperator": "equals",
|
||||
"filterValue": "ExpeditedUpdate_isNDUPAllowedByCSPSucceeded",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "scan_started",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "name",
|
||||
"operator": "equals",
|
||||
"value": "ExpeditedUpdate_startWUScanStartedSuccedded",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "no_scan_result",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "name",
|
||||
"operator": "not_exists",
|
||||
"value": "",
|
||||
"filterField": "name",
|
||||
"filterOperator": "regex",
|
||||
"filterValue": "^ExpeditedUpdate_getUpdateResults",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "update_page_ended",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "cxhEvent",
|
||||
"operator": "equals",
|
||||
"value": "page_stopped",
|
||||
"filterField": "page",
|
||||
"filterOperator": "equals",
|
||||
"filterValue": "OobeNDUP",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "days_out_of_date",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "value",
|
||||
"operator": "gt",
|
||||
"value": "0",
|
||||
"filterField": "name",
|
||||
"filterOperator": "equals",
|
||||
"filterValue": "ExpeditedUpdate_getDaysOutOfDateSucceeded",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "page_names_complete",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "cxhEvent",
|
||||
"operator": "not_exists",
|
||||
"value": "",
|
||||
"filterField": "cxhEvent",
|
||||
"filterOperator": "equals",
|
||||
"filterValue": "names_capped",
|
||||
"required": true
|
||||
}
|
||||
],
|
||||
"explanation": "The Windows quality update page at the end of OOBE started a Windows Update scan, but no scan result arrived before the page ended. The device is {{days_out_of_date}} days out of date, so an update was due — the device finished OOBE without the monthly security update and installs it only later, through the Windows Update policy that applies after enrollment. The page waits only a short time for the scan (two minutes in the observed sessions): a scan that takes longer, or cannot reach Windows Update, ends the page without an update.",
|
||||
"remediation": [
|
||||
{
|
||||
"title": "Check the path to Windows Update during OOBE",
|
||||
"steps": [
|
||||
"Verify that devices in OOBE reach the Windows Update service: proxy, TLS inspection and firewall rules for the Windows Update endpoints.",
|
||||
"Check whether an update policy applied during the Enrollment Status Page points the scan at another source, such as WSUS."
|
||||
]
|
||||
},
|
||||
{
|
||||
"title": "Shorten the scan",
|
||||
"steps": [
|
||||
"Devices far behind scan longer; a current OS image or factory build keeps the OOBE scan short.",
|
||||
"Verify the device's patch level after enrollment; the update ring assigned to the device installs the missing monthly security update on its normal schedule."
|
||||
]
|
||||
}
|
||||
],
|
||||
"relatedDocs": [
|
||||
{
|
||||
"title": "Microsoft Learn: Install Windows quality updates during OOBE (Enrollment Status Page)",
|
||||
"url": "https://learn.microsoft.com/en-us/intune/device-enrollment/windows/setup-status-page#windows-monthly-security-update-release-details"
|
||||
}
|
||||
],
|
||||
"markSessionAsFailedDefault": false,
|
||||
"tags": [
|
||||
"device",
|
||||
"windows-update",
|
||||
"oobe",
|
||||
"quality-update"
|
||||
]
|
||||
}
|
||||
+351
@@ -1930,6 +1930,357 @@
|
||||
"environment"
|
||||
]
|
||||
},
|
||||
{
|
||||
"ruleId": "ANALYZE-DEV-013",
|
||||
"title": "OOBE Quality Update Failed",
|
||||
"description": "Detects that the Windows quality update page at the end of OOBE (Enrollment Status Page setting \"Install Windows quality updates\") reported a failed download or install and recorded no successful install afterwards — the page's own failure names on the oobe_update_page events. Setup usually continues, so the failure is otherwise invisible: the device finishes OOBE without the monthly security update. An OS build change across a restart (os_build_changed) vetoes the finding, and so does the agent's names_capped marker — once the page's event names were capped, a missing success name proves nothing. A downloadInstallFailureHelper entry alone is no failure: updates that installed fine log it too.",
|
||||
"severity": "warning",
|
||||
"category": "device",
|
||||
"version": "1.0.0",
|
||||
"enabled": true,
|
||||
"evaluateOn": [
|
||||
"enrollment_end"
|
||||
],
|
||||
"trigger": "single",
|
||||
"baseConfidence": 75,
|
||||
"confidenceThreshold": 60,
|
||||
"conditions": [
|
||||
{
|
||||
"signal": "update_failure",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "name",
|
||||
"operator": "in",
|
||||
"value": "SdxWebAppCloudNDUP_processStatusChangeFromHandler_downloadFailedError,SdxWebAppCloudNDUP_processStatusChangeFromHandler_installFailedError,ExpeditedUpdate_commitExpeditionDownloadInstallAsyncFailure",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "no_install_success",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "name",
|
||||
"operator": "not_exists",
|
||||
"value": "",
|
||||
"filterField": "name",
|
||||
"filterOperator": "regex",
|
||||
"filterValue": "installSucceededRebootRequired|commitExpeditionDownloadInstallAsyncSucceeded",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "os_build_unchanged",
|
||||
"source": "event_type",
|
||||
"eventType": "os_build_changed",
|
||||
"operator": "not_exists",
|
||||
"value": "",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "page_names_complete",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "cxhEvent",
|
||||
"operator": "not_exists",
|
||||
"value": "",
|
||||
"filterField": "cxhEvent",
|
||||
"filterOperator": "equals",
|
||||
"filterValue": "names_capped",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "update_page_failed",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "result",
|
||||
"operator": "equals",
|
||||
"value": "fail",
|
||||
"filterField": "page",
|
||||
"filterOperator": "equals",
|
||||
"filterValue": "OobeNDUP",
|
||||
"required": false
|
||||
},
|
||||
{
|
||||
"signal": "update_skipped",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "name",
|
||||
"operator": "regex",
|
||||
"value": "SkipDownloadInstallButtonClicked$",
|
||||
"required": false
|
||||
}
|
||||
],
|
||||
"confidenceFactors": [
|
||||
{
|
||||
"signal": "update_page_failed",
|
||||
"condition": "exists",
|
||||
"weight": 10
|
||||
}
|
||||
],
|
||||
"explanation": "The Windows quality update page at the end of OOBE reported `{{update_failure}}`, and no successful install was recorded afterwards. When the download or install of the update fails, the page gives up and setup continues, so the enrollment itself can still succeed — but the device most likely finished OOBE without the monthly security update and installs it only later, through the Windows Update policy that applies after enrollment. Selecting Skip on the page after the failure leads to the same result.",
|
||||
"remediation": [
|
||||
{
|
||||
"title": "Find out why the update failed",
|
||||
"steps": [
|
||||
"Open the oobe_update_page events around the failure in the session timeline: the download progress before it shows how far the download got, and a Skip after it shows that someone chose to continue.",
|
||||
"Check the network path the device uses during OOBE for Windows Update and Delivery Optimization: proxy, TLS inspection and firewall rules for the Windows Update endpoints.",
|
||||
"Compare with other devices: the same failure on many devices of one site points at the network path, on one model at the device, and across the fleet at the update itself."
|
||||
]
|
||||
},
|
||||
{
|
||||
"title": "Make sure the device gets the update",
|
||||
"steps": [
|
||||
"Verify the device's patch level after enrollment; the update ring assigned to the device installs the missing monthly security update on its normal schedule.",
|
||||
"Where the OOBE quality update keeps failing for one network or device group, decide per Enrollment Status Page profile whether \"Install Windows quality updates\" should stay on."
|
||||
]
|
||||
}
|
||||
],
|
||||
"relatedDocs": [
|
||||
{
|
||||
"title": "Microsoft Learn: Install Windows quality updates during OOBE (Enrollment Status Page)",
|
||||
"url": "https://learn.microsoft.com/en-us/intune/device-enrollment/windows/setup-status-page#windows-monthly-security-update-release-details"
|
||||
}
|
||||
],
|
||||
"markSessionAsFailedDefault": false,
|
||||
"tags": [
|
||||
"device",
|
||||
"windows-update",
|
||||
"oobe",
|
||||
"quality-update"
|
||||
]
|
||||
},
|
||||
{
|
||||
"ruleId": "ANALYZE-DEV-014",
|
||||
"title": "OOBE Quality Update Not Offered After an Earlier Failure",
|
||||
"description": "Detects that the Windows quality update page at the end of OOBE found no update to install although the device is out of date, on a device whose update page counts an earlier failed download or install (oobe_update_page: NDUPDownloadInstallPreviousFailureCount above 0, osUpdatesWithNDUPPI false, getDaysOutOfDateSucceeded above 0). No failure and no install success are recorded in this session — a failure in this session is ANALYZE-DEV-013 — and the agent's names_capped marker vetoes the finding, because a missing name proves nothing once the page's names were capped. The device finishes OOBE without the monthly security update.",
|
||||
"severity": "warning",
|
||||
"category": "device",
|
||||
"version": "1.0.0",
|
||||
"enabled": true,
|
||||
"evaluateOn": [
|
||||
"enrollment_end"
|
||||
],
|
||||
"trigger": "single",
|
||||
"baseConfidence": 75,
|
||||
"confidenceThreshold": 60,
|
||||
"conditions": [
|
||||
{
|
||||
"signal": "previous_failures",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "value",
|
||||
"operator": "gt",
|
||||
"value": "0",
|
||||
"filterField": "name",
|
||||
"filterOperator": "equals",
|
||||
"filterValue": "SdxWebAppCloudNDUP_initialize_NDUPDownloadInstallPreviousFailureCount",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "nothing_offered",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "value",
|
||||
"operator": "equals",
|
||||
"value": "false",
|
||||
"filterField": "name",
|
||||
"filterOperator": "equals",
|
||||
"filterValue": "SdxWebAppCloudNDUP_updateManager_processUpdatesMetadata_osUpdatesWithNDUPPI",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "days_out_of_date",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "value",
|
||||
"operator": "gt",
|
||||
"value": "0",
|
||||
"filterField": "name",
|
||||
"filterOperator": "equals",
|
||||
"filterValue": "ExpeditedUpdate_getDaysOutOfDateSucceeded",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "no_update_failure",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "name",
|
||||
"operator": "not_exists",
|
||||
"value": "",
|
||||
"filterField": "name",
|
||||
"filterOperator": "in",
|
||||
"filterValue": "SdxWebAppCloudNDUP_processStatusChangeFromHandler_downloadFailedError,SdxWebAppCloudNDUP_processStatusChangeFromHandler_installFailedError,ExpeditedUpdate_commitExpeditionDownloadInstallAsyncFailure",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "no_install_success",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "name",
|
||||
"operator": "not_exists",
|
||||
"value": "",
|
||||
"filterField": "name",
|
||||
"filterOperator": "regex",
|
||||
"filterValue": "installSucceededRebootRequired|commitExpeditionDownloadInstallAsyncSucceeded",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "page_names_complete",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "cxhEvent",
|
||||
"operator": "not_exists",
|
||||
"value": "",
|
||||
"filterField": "cxhEvent",
|
||||
"filterOperator": "equals",
|
||||
"filterValue": "names_capped",
|
||||
"required": true
|
||||
}
|
||||
],
|
||||
"explanation": "The Windows quality update page at the end of OOBE checked for updates and found none to install, although Windows reports the device as {{days_out_of_date}} days out of date. The page's failure counter for this device stands at {{previous_failures}}: an earlier download or install of an OOBE quality update on this device failed. The device finished OOBE without the monthly security update and installs it only later, through the Windows Update policy that applies after enrollment.",
|
||||
"remediation": [
|
||||
{
|
||||
"title": "Check the earlier attempt",
|
||||
"steps": [
|
||||
"Look at the device's earlier enrollment sessions — the failed attempt and its ANALYZE-DEV-013 finding are usually there.",
|
||||
"Verify the device's patch level after enrollment; the update ring assigned to the device installs the missing monthly security update on its normal schedule."
|
||||
]
|
||||
},
|
||||
{
|
||||
"title": "Reduce how far behind devices start",
|
||||
"steps": [
|
||||
"Devices that start OOBE many months behind need a long update during setup; a current OS image or factory build shortens it and gives a failed attempt less to repeat."
|
||||
]
|
||||
}
|
||||
],
|
||||
"relatedDocs": [
|
||||
{
|
||||
"title": "Microsoft Learn: Install Windows quality updates during OOBE (Enrollment Status Page)",
|
||||
"url": "https://learn.microsoft.com/en-us/intune/device-enrollment/windows/setup-status-page#windows-monthly-security-update-release-details"
|
||||
}
|
||||
],
|
||||
"markSessionAsFailedDefault": false,
|
||||
"tags": [
|
||||
"device",
|
||||
"windows-update",
|
||||
"oobe",
|
||||
"quality-update"
|
||||
]
|
||||
},
|
||||
{
|
||||
"ruleId": "ANALYZE-DEV-015",
|
||||
"title": "OOBE Update Check Ended Without a Result",
|
||||
"description": "Detects that the Windows quality update page at the end of OOBE started its Windows Update scan but ended without a scan result (oobe_update_page: startWUScanStartedSuccedded, an OobeNDUP stop and no ExpeditedUpdate_getUpdateResults name), on a device that is out of date and allowed to update. In the observed sessions the page ended two minutes after the scan started, on devices more than a year behind. The device finishes OOBE without the monthly security update. The agent's names_capped marker vetoes the finding: once the page's event names were capped, a missing scan result proves nothing.",
|
||||
"severity": "warning",
|
||||
"category": "device",
|
||||
"version": "1.0.0",
|
||||
"enabled": true,
|
||||
"evaluateOn": [
|
||||
"enrollment_end"
|
||||
],
|
||||
"trigger": "single",
|
||||
"baseConfidence": 75,
|
||||
"confidenceThreshold": 60,
|
||||
"conditions": [
|
||||
{
|
||||
"signal": "update_allowed",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "value",
|
||||
"operator": "equals",
|
||||
"value": "true",
|
||||
"filterField": "name",
|
||||
"filterOperator": "equals",
|
||||
"filterValue": "ExpeditedUpdate_isNDUPAllowedByCSPSucceeded",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "scan_started",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "name",
|
||||
"operator": "equals",
|
||||
"value": "ExpeditedUpdate_startWUScanStartedSuccedded",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "no_scan_result",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "name",
|
||||
"operator": "not_exists",
|
||||
"value": "",
|
||||
"filterField": "name",
|
||||
"filterOperator": "regex",
|
||||
"filterValue": "^ExpeditedUpdate_getUpdateResults",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "update_page_ended",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "cxhEvent",
|
||||
"operator": "equals",
|
||||
"value": "page_stopped",
|
||||
"filterField": "page",
|
||||
"filterOperator": "equals",
|
||||
"filterValue": "OobeNDUP",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "days_out_of_date",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "value",
|
||||
"operator": "gt",
|
||||
"value": "0",
|
||||
"filterField": "name",
|
||||
"filterOperator": "equals",
|
||||
"filterValue": "ExpeditedUpdate_getDaysOutOfDateSucceeded",
|
||||
"required": true
|
||||
},
|
||||
{
|
||||
"signal": "page_names_complete",
|
||||
"source": "event_data",
|
||||
"eventType": "oobe_update_page",
|
||||
"dataField": "cxhEvent",
|
||||
"operator": "not_exists",
|
||||
"value": "",
|
||||
"filterField": "cxhEvent",
|
||||
"filterOperator": "equals",
|
||||
"filterValue": "names_capped",
|
||||
"required": true
|
||||
}
|
||||
],
|
||||
"explanation": "The Windows quality update page at the end of OOBE started a Windows Update scan, but no scan result arrived before the page ended. The device is {{days_out_of_date}} days out of date, so an update was due — the device finished OOBE without the monthly security update and installs it only later, through the Windows Update policy that applies after enrollment. The page waits only a short time for the scan (two minutes in the observed sessions): a scan that takes longer, or cannot reach Windows Update, ends the page without an update.",
|
||||
"remediation": [
|
||||
{
|
||||
"title": "Check the path to Windows Update during OOBE",
|
||||
"steps": [
|
||||
"Verify that devices in OOBE reach the Windows Update service: proxy, TLS inspection and firewall rules for the Windows Update endpoints.",
|
||||
"Check whether an update policy applied during the Enrollment Status Page points the scan at another source, such as WSUS."
|
||||
]
|
||||
},
|
||||
{
|
||||
"title": "Shorten the scan",
|
||||
"steps": [
|
||||
"Devices far behind scan longer; a current OS image or factory build keeps the OOBE scan short.",
|
||||
"Verify the device's patch level after enrollment; the update ring assigned to the device installs the missing monthly security update on its normal schedule."
|
||||
]
|
||||
}
|
||||
],
|
||||
"relatedDocs": [
|
||||
{
|
||||
"title": "Microsoft Learn: Install Windows quality updates during OOBE (Enrollment Status Page)",
|
||||
"url": "https://learn.microsoft.com/en-us/intune/device-enrollment/windows/setup-status-page#windows-monthly-security-update-release-details"
|
||||
}
|
||||
],
|
||||
"markSessionAsFailedDefault": false,
|
||||
"tags": [
|
||||
"device",
|
||||
"windows-update",
|
||||
"oobe",
|
||||
"quality-update"
|
||||
]
|
||||
},
|
||||
{
|
||||
"ruleId": "ANALYZE-ENRL-001",
|
||||
"title": "Enrollment Failed",
|
||||
|
||||
+336
@@ -0,0 +1,336 @@
|
||||
using System;
|
||||
using System.IO;
|
||||
using System.Linq;
|
||||
using System.Text;
|
||||
using System.Threading.Tasks;
|
||||
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
|
||||
using Xunit;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
{
|
||||
/// <summary>
|
||||
/// B-96m: IME re-runs a failed platform script on later check-ins, so AgentExecutor.log can hold several runs of one
|
||||
/// policy before the tracker has read IME's result of the first — always on the agent's first pass (the agent starts
|
||||
/// mid-enrollment and reads all of AgentExecutor.log before IntuneManagementExtension.log), after a restart, and
|
||||
/// whenever a result line surfaces late. With one slot per policy the second executor start reused the first run's
|
||||
/// slot and its end block overwrote the first one: the first IME result went out with the LAST run's exit code and
|
||||
/// output (session eff1b413: the bootstrap script "Failed (exit 0)" with the stdout of its successful retry), every
|
||||
/// later result without an end block. These tests pin one run per executor start, each IME result paired with the
|
||||
/// run of its policy that started last before it, each run carrying its own end block.
|
||||
/// </summary>
|
||||
public sealed partial class ImeLogTrackerOverwriteRewindTests
|
||||
{
|
||||
private const string RetryPolicyId = "4c2d8e1a-7b3f-4a9e-8d21-6f0b5c3e9a74";
|
||||
private const string RetryUser = "00000000-0000-0000-0000-000000000000";
|
||||
|
||||
private static string ImeEntryAt(string time, string message)
|
||||
=> $"<![LOG[{message}]LOG]!><time=\"{time}\" date=\"9-10-2026\" component=\"IntuneManagementExtension\" context=\"\" type=\"1\" thread=\"12\" file=\"\">\r\n";
|
||||
|
||||
/// <summary>One executor run's start block: banner, the platform argument line, paths, launch.</summary>
|
||||
private static string RunStart(string time, string pid, string policyId = RetryPolicyId, string userId = RetryUser)
|
||||
{
|
||||
var path = $@"{ImeDir}\Policies\Scripts\{userId}_{policyId}.ps1";
|
||||
var results = $@"{ImeDir}\Policies\Results\{userId}_{policyId}";
|
||||
return ExecutorBanner(time)
|
||||
+ EntryAt(time, $"Adding argument powershell with value {path} to the named argument list.")
|
||||
+ EntryAt(time, "Powershell option gets invoked")
|
||||
+ EntryAt(time, path)
|
||||
+ EntryAt(time, results + ".output")
|
||||
+ EntryAt(time, results + ".error")
|
||||
+ EntryAt(time, results + ".timeout")
|
||||
+ ExecutorLaunch(time, path, pid);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// One executor run's end block in AgentExecutor's order. "error from script =" logs the stderr buffer before the
|
||||
/// output readers finished (<paramref name="stderrSnapshot"/>); "write output done" logs the final texts, the
|
||||
/// error part being exactly the error file IME judges.
|
||||
/// </summary>
|
||||
private static string RunEnd(string time, int exitCode, string stdout, string stderr, string? stderrSnapshot = null)
|
||||
=> EntryAt(time, $"Powershell exit code is {exitCode}")
|
||||
+ EntryAt(time, $"length of out={stdout.Length}")
|
||||
+ EntryAt(time, $"length of error={stderr.Length}")
|
||||
+ EntryAt(time, "error from script =" + (stderrSnapshot ?? stderr))
|
||||
+ EntryAt(time, exitCode == 0 ? "Powershell script is successfully executed." : "Powershell script is failed to execute")
|
||||
+ EntryAt(time, $"write output done. output = {stdout}, error = {stderr}")
|
||||
+ EntryAt(time, "Revert Wow64FsRedirection")
|
||||
+ EntryAt(time, "Agent executor completed.");
|
||||
|
||||
private static string ImeRunStart(string time, string policyId = RetryPolicyId, string userId = RetryUser)
|
||||
=> ImeEntryAt(time, $@"Script file {ImeDir}\Policies\Scripts\{userId}_{policyId}.ps1 is generated.");
|
||||
|
||||
private static string ImeRunResult(string time, string result, string policyId = RetryPolicyId, string userId = RetryUser)
|
||||
=> ImeEntryAt(time, $"[PowerShell] User Id = {userId}, Policy id = {policyId}, policy result = {result}");
|
||||
|
||||
private static void AppendImeLog(Harness h, string text)
|
||||
=> File.AppendAllText(Path.Combine(Path.GetDirectoryName(h.LogPath)!, "IntuneManagementExtension.log"), text, new UTF8Encoding(false));
|
||||
|
||||
/// <summary>Result | exit | stdout | stderr — readable in an assertion failure; "-" no exit code, "~" never read.</summary>
|
||||
private static string Shape(ScriptExecutionState s)
|
||||
=> $"{s.Result}|{(s.ExitCode.HasValue ? s.ExitCode.Value.ToString() : "-")}|{s.Stdout ?? "~"}|{s.Stderr ?? "~"}";
|
||||
|
||||
/// <summary>
|
||||
/// Two poll passes as the agent runs them (read the files, then the flushes), the second past the result hold:
|
||||
/// a result missing its end block goes out by then.
|
||||
/// </summary>
|
||||
private static async Task PassAndSettle(Harness h)
|
||||
{
|
||||
await h.Tracker.RunPollPassAsync(default);
|
||||
h.Now = h.Now.AddSeconds(6);
|
||||
await h.Tracker.RunPollPassAsync(default);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task First_pass_pairs_each_ime_result_with_the_end_block_of_its_own_run()
|
||||
{
|
||||
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
|
||||
// IME's first run and two retries on later check-ins, all written before the agent started.
|
||||
h.Append(RunStart("12:00:10.0000000", "1001") + RunEnd("12:00:12.0000000", 1, "", "Run A failed")
|
||||
+ RunStart("12:10:10.0000000", "1002") + RunEnd("12:10:12.0000000", 1, "Run B output", "")
|
||||
+ RunStart("12:20:10.0000000", "1003") + RunEnd("12:20:12.0000000", 0, "Run C output", ""));
|
||||
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunResult("12:00:12.1000000", "Failed")
|
||||
+ ImeRunStart("12:10:08.0000000") + ImeRunResult("12:10:12.1000000", "Success")
|
||||
+ ImeRunStart("12:20:08.0000000") + ImeRunResult("12:20:12.1000000", "Success"));
|
||||
|
||||
await PassAndSettle(h);
|
||||
|
||||
Assert.Equal(new[] { "Failed|1||Run A failed", "Success|1|Run B output|", "Success|0|Run C output|" },
|
||||
h.Completed.Select(Shape).ToArray());
|
||||
Assert.All(h.Completed, s => Assert.Equal("ime_policy_result", s.ResultSource));
|
||||
Assert.True(h.Completed[0].StartedAtUtc < h.Completed[1].StartedAtUtc && h.Completed[1].StartedAtUtc < h.Completed[2].StartedAtUtc);
|
||||
Assert.Equal(3, h.Completed.Select(s => s.RunId).Distinct().Count());
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Retry_of_the_bootstrap_script_never_lends_its_success_output_to_the_failed_first_attempt()
|
||||
{
|
||||
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
|
||||
h.Append(RunStart("12:00:10.0000000", "2001") + RunEnd("12:00:20.0000000", 1, "attempt 1: download failed", "Invoke-WebRequest : The remote name could not be resolved")
|
||||
+ RunStart("12:10:10.0000000", "2002") + RunEnd("12:10:20.0000000", 0, "===== Bootstrap Completed Successfully =====", ""));
|
||||
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunResult("12:00:20.1000000", "Failed")
|
||||
+ ImeRunStart("12:10:08.0000000") + ImeRunResult("12:10:20.1000000", "Success"));
|
||||
|
||||
await PassAndSettle(h);
|
||||
|
||||
Assert.Equal(new[]
|
||||
{
|
||||
"Failed|1|attempt 1: download failed|Invoke-WebRequest : The remote name could not be resolved",
|
||||
"Success|0|===== Bootstrap Completed Successfully =====|",
|
||||
}, h.Completed.Select(Shape).ToArray());
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Run_killed_at_the_timeout_reports_failed_without_the_next_runs_end_block()
|
||||
{
|
||||
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
|
||||
// IME killed the first executor after 1800 s: its start block is all AgentExecutor.log holds of it.
|
||||
h.Append(RunStart("12:00:10.0000000", "3001")
|
||||
+ RunStart("12:40:10.0000000", "3002") + RunEnd("12:40:12.0000000", 0, "Run B output", ""));
|
||||
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunResult("12:30:10.5000000", "Failed")
|
||||
+ ImeRunStart("12:40:08.0000000") + ImeRunResult("12:40:12.1000000", "Success"));
|
||||
|
||||
await PassAndSettle(h);
|
||||
|
||||
Assert.Equal(new[] { "Failed|-|~|~", "Success|0|Run B output|" }, h.Completed.Select(Shape).ToArray());
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Run_whose_result_never_surfaced_falls_back_on_imes_rule_before_the_next_run()
|
||||
{
|
||||
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
|
||||
h.Append(RunStart("12:00:10.0000000", "4001") + RunEnd("12:00:12.0000000", 0, "Run A output", "Run A wrote an error")
|
||||
+ RunStart("12:10:10.0000000", "4002") + RunEnd("12:10:12.0000000", 0, "Run B output", ""));
|
||||
// Run A's result line was lost; run B's is there.
|
||||
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunStart("12:10:08.0000000") + ImeRunResult("12:10:12.1000000", "Success"));
|
||||
|
||||
await PassAndSettle(h);
|
||||
|
||||
Assert.Equal(new[] { "Failed|0|Run A output|Run A wrote an error", "Success|0|Run B output|" }, h.Completed.Select(Shape).ToArray());
|
||||
Assert.Equal(new[] { "agentexecutor_fallback", "ime_policy_result" }, h.Completed.Select(s => s.ResultSource).ToArray());
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Run_in_flight_survives_the_emit_of_the_run_before_it()
|
||||
{
|
||||
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
|
||||
h.Append(RunStart("12:00:10.0000000", "5001") + RunEnd("12:00:12.0000000", 0, "Run A output", "")
|
||||
+ RunStart("12:10:10.0000000", "5002"));
|
||||
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunResult("12:00:12.1000000", "Success") + ImeRunStart("12:10:08.0000000"));
|
||||
await PassAndSettle(h);
|
||||
h.Now = h.Now.AddSeconds(30);
|
||||
await h.Pass();
|
||||
|
||||
// Run B ends minutes later.
|
||||
h.Append(RunEnd("12:10:40.0000000", 0, "Run B output", ""));
|
||||
AppendImeLog(h, ImeRunResult("12:10:40.1000000", "Success"));
|
||||
await PassAndSettle(h);
|
||||
|
||||
Assert.Equal(new[] { "Success|0|Run A output|", "Success|0|Run B output|" }, h.Completed.Select(Shape).ToArray());
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Shutdown_between_the_two_logs_flushes_each_run_with_its_own_end_block()
|
||||
{
|
||||
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
|
||||
h.Append(RunStart("12:00:10.0000000", "6001") + RunEnd("12:00:12.0000000", 1, "", "Run A failed")
|
||||
+ RunStart("12:10:10.0000000", "6002") + RunEnd("12:10:12.0000000", 0, "Run B output", ""));
|
||||
// The pass is cancelled after AgentExecutor.log; the shutdown flush follows.
|
||||
await h.Pass();
|
||||
h.Tracker.FlushPendingPlatformScriptResults(h.Now, force: true);
|
||||
|
||||
h.Restart();
|
||||
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunResult("12:00:12.1000000", "Failed")
|
||||
+ ImeRunStart("12:10:08.0000000") + ImeRunResult("12:10:12.1000000", "Success"));
|
||||
await PassAndSettle(h);
|
||||
|
||||
// Each run went out with its own block and IME's verdict on it; the results read after the restart are
|
||||
// the same runs and change nothing.
|
||||
Assert.Equal(new[] { "Failed|1||Run A failed", "Success|0|Run B output|" }, h.Completed.Select(Shape).ToArray());
|
||||
Assert.All(h.Completed, s => Assert.Equal("agentexecutor_fallback", s.ResultSource));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task End_block_line_recovered_after_the_next_run_started_stays_with_its_own_run()
|
||||
{
|
||||
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
|
||||
h.Append(RunStart("12:00:10.0000000", "7001"));
|
||||
var exitLineAt = h.Length;
|
||||
h.Append(RunEnd("12:00:12.0000000", 1, "", "Run A failed")
|
||||
+ RunStart("12:10:10.0000000", "7002") + RunEnd("12:10:12.0000000", 0, "Run B output", ""));
|
||||
await h.Pass();
|
||||
|
||||
// A stale writer rewrites run A's exit line in place: the ledger check re-reads it behind run B's start.
|
||||
h.Overwrite(exitLineAt, EntryAt("12:00:12.0000000", "Powershell exit code is 7"));
|
||||
h.Tracker.RequestOverwriteCheckForTest();
|
||||
h.Now = h.Now.AddSeconds(2);
|
||||
await h.Pass();
|
||||
|
||||
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunResult("12:00:12.1000000", "Failed")
|
||||
+ ImeRunStart("12:10:08.0000000") + ImeRunResult("12:10:12.1000000", "Success"));
|
||||
await PassAndSettle(h);
|
||||
|
||||
Assert.Equal(new[] { "Failed|7||Run A failed", "Success|0|Run B output|" }, h.Completed.Select(Shape).ToArray());
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Run_without_result_or_end_block_is_dropped_once_a_later_run_has_its_result()
|
||||
{
|
||||
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
|
||||
h.Append(RunStart("12:00:10.0000000", "9001")
|
||||
+ RunStart("12:10:10.0000000", "9002") + RunEnd("12:10:12.0000000", 0, "Run B output", ""));
|
||||
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunStart("12:10:08.0000000") + ImeRunResult("12:10:12.1000000", "Success"));
|
||||
|
||||
await PassAndSettle(h);
|
||||
|
||||
Assert.Equal(new[] { "Success|0|Run B output|" }, h.Completed.Select(Shape).ToArray());
|
||||
Assert.Equal(0, h.Tracker.ParkedPlatformScriptCountForTest);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Reading_the_same_executor_start_line_again_never_parks_its_run()
|
||||
{
|
||||
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
|
||||
var line = $@"Adding argument powershell with value {ImeDir}\Policies\Scripts\{RetryUser}_{RetryPolicyId}.ps1 to the named argument list.";
|
||||
var at = T0.AddMinutes(-30);
|
||||
|
||||
h.Tracker.ProcessLogMessageForTest(line, at, "AgentExecutor.log");
|
||||
h.Tracker.ProcessLogMessageForTest(line, at, "AgentExecutor.log");
|
||||
Assert.Equal(0, h.Tracker.ParkedPlatformScriptCountForTest);
|
||||
|
||||
h.Tracker.ProcessLogMessageForTest(line, at.AddMinutes(10), "AgentExecutor.log");
|
||||
Assert.Equal(1, h.Tracker.ParkedPlatformScriptCountForTest);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Run_without_end_block_keeps_waiting_for_its_result_across_a_shutdown()
|
||||
{
|
||||
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
|
||||
h.Append(RunStart("12:00:10.0000000", "9101") + RunStart("12:40:10.0000000", "9102"));
|
||||
await h.Pass();
|
||||
h.Tracker.FlushPendingPlatformScriptResults(h.Now, force: true);
|
||||
Assert.Empty(h.Completed);
|
||||
|
||||
h.Restart();
|
||||
Assert.Equal(1, h.Tracker.ParkedPlatformScriptCountForTest);
|
||||
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunResult("12:30:10.5000000", "Failed"));
|
||||
await PassAndSettle(h);
|
||||
|
||||
Assert.Equal(new[] { "Failed|-|~|~" }, h.Completed.Select(Shape).ToArray());
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Earlier_run_emitted_while_a_later_one_runs_never_takes_the_later_runs_register_entry()
|
||||
{
|
||||
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
|
||||
h.Append(RunStart("12:00:10.0000000", "9201") + RunEnd("12:00:12.0000000", 1, "", "Run A failed")
|
||||
+ RunStart("12:10:10.0000000", "9202"));
|
||||
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunResult("12:00:12.1000000", "Failed") + ImeRunStart("12:10:08.0000000"));
|
||||
await PassAndSettle(h);
|
||||
Assert.Single(h.Completed);
|
||||
|
||||
// A save of this key is the latest run's, and that one is still running.
|
||||
h.Tracker.ScriptRuns.NotePassCompleted(h.Now);
|
||||
Assert.Equal(PlatformRunClaim.Wait, h.Tracker.ScriptRuns.TryClaim(RetryUser, RetryPolicyId, h.Now.AddSeconds(-10), out _));
|
||||
|
||||
h.Append(RunEnd("12:10:40.0000000", 0, "Run B output", ""));
|
||||
AppendImeLog(h, ImeRunResult("12:10:40.1000000", "Success"));
|
||||
await PassAndSettle(h);
|
||||
h.Tracker.ScriptRuns.NotePassCompleted(h.Now);
|
||||
|
||||
Assert.Equal(PlatformRunClaim.Claimed, h.Tracker.ScriptRuns.TryClaim(RetryUser, RetryPolicyId, h.Now.AddSeconds(-10), out var run));
|
||||
Assert.Equal(h.Completed[1].RunId, run!.RunId);
|
||||
Assert.Equal("Run B output", run.Stdout);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Run_of_another_user_keeps_its_own_register_entry_when_it_waited_for_its_result()
|
||||
{
|
||||
const string otherUser = "2b7e5c91-3d4a-4f80-b6e2-9a1c7d3f5e08";
|
||||
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
|
||||
h.Append(RunStart("12:00:10.0000000", "9301") + RunEnd("12:00:12.0000000", 1, "", "Run A failed")
|
||||
+ RunStart("12:10:10.0000000", "9302", userId: otherUser));
|
||||
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunResult("12:00:12.1000000", "Failed")
|
||||
+ ImeRunStart("12:10:08.0000000", userId: otherUser));
|
||||
await PassAndSettle(h);
|
||||
h.Tracker.ScriptRuns.NotePassCompleted(h.Now);
|
||||
|
||||
Assert.Equal(PlatformRunClaim.Claimed, h.Tracker.ScriptRuns.TryClaim(RetryUser, RetryPolicyId, h.Now.AddSeconds(-10), out var run));
|
||||
Assert.Equal(h.Completed[0].RunId, run!.RunId);
|
||||
Assert.Equal(PlatformRunClaim.Wait, h.Tracker.ScriptRuns.TryClaim(otherUser, RetryPolicyId, h.Now.AddSeconds(-10), out _));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Start_line_read_again_stays_a_late_line_after_an_earlier_run_of_another_user_went_out()
|
||||
{
|
||||
const string otherUser = "2b7e5c91-3d4a-4f80-b6e2-9a1c7d3f5e08";
|
||||
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
|
||||
h.Append(RunStart("12:00:10.0000000", "9401") + RunEnd("12:00:12.0000000", 0, "Run A output", "")
|
||||
+ RunStart("12:10:10.0000000", "9402", userId: otherUser) + RunEnd("12:10:12.0000000", 0, "Run B output", ""));
|
||||
// Run A's result surfaces after run B's (its line was hidden by a concurrent writer).
|
||||
AppendImeLog(h, ImeRunResult("12:10:12.1000000", "Success", userId: otherUser) + ImeRunResult("12:00:12.1000000", "Success"));
|
||||
await PassAndSettle(h);
|
||||
Assert.Equal(new[] { "Success|0|Run B output|", "Success|0|Run A output|" }, h.Completed.Select(Shape).ToArray());
|
||||
|
||||
// Run B's executor start line read again (a rewind): a late line of the emitted run B, never a new run.
|
||||
var started = 0;
|
||||
h.Tracker.OnScriptStarted = _ => started++;
|
||||
h.Tracker.ProcessLogMessageForTest(
|
||||
$@"Adding argument powershell with value {ImeDir}\Policies\Scripts\{otherUser}_{RetryPolicyId}.ps1 to the named argument list.",
|
||||
h.Completed[0].StartedAtUtc, "AgentExecutor.log");
|
||||
Assert.Equal(0, started);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Final_stderr_of_the_end_block_replaces_the_early_snapshot_even_without_stdout()
|
||||
{
|
||||
using var h = new Harness("AgentExecutor.log", ScriptPatterns());
|
||||
// The snapshot was taken before the error reader finished; IME judged the full error file.
|
||||
h.Append(RunStart("12:00:10.0000000", "8001") + RunEnd("12:00:12.0000000", 0, "", "Remove-AppxPackage : Cannot process argument", stderrSnapshot: ""));
|
||||
AppendImeLog(h, ImeRunStart("12:00:08.0000000") + ImeRunResult("12:00:12.1000000", "Failed"));
|
||||
|
||||
await PassAndSettle(h);
|
||||
|
||||
Assert.Equal(new[] { "Failed|0||Remove-AppxPackage : Cannot process argument" }, h.Completed.Select(Shape).ToArray());
|
||||
}
|
||||
}
|
||||
}
|
||||
+139
@@ -0,0 +1,139 @@
|
||||
using System;
|
||||
using System.IO;
|
||||
using System.Linq;
|
||||
using System.Text;
|
||||
using System.Threading.Tasks;
|
||||
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime;
|
||||
using AutopilotMonitor.Agent.V2.Core.SignalAdapters;
|
||||
using Xunit;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
{
|
||||
/// <summary>
|
||||
/// Sessions d29e27e3 and 4377911b: a concurrent IME writer overwrote the result line of a platform script, and the
|
||||
/// overwrite check recovered it one pass later. Recovered lines were never fresh, so they resolved in the agent's own
|
||||
/// cached zone (+60) instead of anchoring themselves (+120): the end stamp landed an hour ahead of the clock and the
|
||||
/// run duration was omitted. Bytes that read differently at a position than at the last look were written after that
|
||||
/// look, so when the replaced bytes were confirmed seconds ago the new line's age is bounded like an appended line's —
|
||||
/// these tests pin that it anchors itself then, and only then.
|
||||
/// </summary>
|
||||
public sealed partial class ImeLogTrackerOverwriteRewindTests
|
||||
{
|
||||
private static void AppendExecutorLog(Harness h, string text)
|
||||
=> File.AppendAllText(Path.Combine(Path.GetDirectoryName(h.LogPath)!, "AgentExecutor.log"), text, new UTF8Encoding(false));
|
||||
|
||||
/// <summary>An IME log entry with the byte length of <paramref name="sameLengthAs"/>: what a stale writer's line replaces exactly.</summary>
|
||||
private static string FillerLike(string time, string sameLengthAs)
|
||||
{
|
||||
var bare = ImeEntryAt(time, "[Win32App] checking ");
|
||||
Assert.True(sameLengthAs.Length > bare.Length);
|
||||
return ImeEntryAt(time, "[Win32App] checking " + new string('x', sameLengthAs.Length - bare.Length));
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// A platform run whose IME writer lives in +120 (local = UTC + 2 h; the harness clock is 19:30Z): both logs are
|
||||
/// observed empty first, so what follows is read fresh. Returns the IME log position where the filler line sits.
|
||||
/// </summary>
|
||||
private static async Task<long> StartRunAndReadFiller(Harness h, string fillerTime, string resultEntry)
|
||||
{
|
||||
h.Append(string.Empty);
|
||||
AppendExecutorLog(h, string.Empty);
|
||||
await h.Tracker.RunPollPassAsync(default);
|
||||
|
||||
AppendExecutorLog(h, RunStart("21:29:50.0000000", "1001"));
|
||||
h.Append(ImeRunStart("21:29:48.0000000"));
|
||||
await h.Tracker.RunPollPassAsync(default);
|
||||
|
||||
// Another IME writer appends a line; the tracker reads it.
|
||||
var at = h.Length;
|
||||
h.Append(FillerLike(fillerTime, resultEntry));
|
||||
h.Now = h.Now.AddSeconds(1);
|
||||
await h.Tracker.RunPollPassAsync(default);
|
||||
return at;
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Result_line_recovered_seconds_after_its_bytes_were_read_anchors_itself_like_a_fresh_line()
|
||||
{
|
||||
using var h = new Harness("IntuneManagementExtension.log", ScriptPatterns());
|
||||
var result = ImeRunResult("21:30:01.1000000", "Success");
|
||||
var at = await StartRunAndReadFiller(h, "21:30:00.5000000", result);
|
||||
|
||||
// The script ends: its end block, then the stale IME service writes the result over the filler.
|
||||
AppendExecutorLog(h, RunEnd("21:30:01.0000000", 0, "done", ""));
|
||||
h.Overwrite(at, result);
|
||||
h.Now = h.Now.AddSeconds(1);
|
||||
await PassAndSettle(h);
|
||||
|
||||
Assert.Equal(1, h.Health.OverwriteRewinds);
|
||||
var script = Assert.Single(h.Completed);
|
||||
Assert.Equal(CmTraceOffsetOrigin.LineAnchored, script.ResultProvenance!.Origin);
|
||||
Assert.Equal(120, script.ResultProvenance.OffsetMinutes);
|
||||
Assert.Equal(ImeLogTrackerAdapter.DurationPairVerdict.Verified, ImeLogTrackerAdapter.JudgeDurationPair(
|
||||
script.StartedAtProvenance, script.ResultProvenance, false, script.ResultObservedAtUtc!.Value - script.StartedAtUtc!.Value, out _));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Verification_passes_keep_the_replaced_bytes_current_for_a_script_that_runs_longer()
|
||||
{
|
||||
using var h = new Harness("IntuneManagementExtension.log", ScriptPatterns());
|
||||
var result = ImeRunResult("21:30:41.1000000", "Success");
|
||||
var at = await StartRunAndReadFiller(h, "21:30:00.5000000", result);
|
||||
|
||||
// The script runs 40 s; the cadence check verifies the ledger every 10 s while the run is in flight.
|
||||
for (var i = 0; i < 4; i++)
|
||||
{
|
||||
h.Now = h.Now.AddSeconds(10);
|
||||
await h.Tracker.RunPollPassAsync(default);
|
||||
}
|
||||
|
||||
AppendExecutorLog(h, RunEnd("21:30:41.0000000", 0, "done", ""));
|
||||
h.Overwrite(at, result);
|
||||
h.Now = h.Now.AddSeconds(1);
|
||||
await PassAndSettle(h);
|
||||
|
||||
var script = Assert.Single(h.Completed);
|
||||
Assert.Equal(CmTraceOffsetOrigin.LineAnchored, script.ResultProvenance!.Origin);
|
||||
Assert.Equal(120, script.ResultProvenance.OffsetMinutes);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task Overwrite_does_not_move_the_files_measured_writer_offset()
|
||||
{
|
||||
using var h = new Harness("IntuneManagementExtension.log", ScriptPatterns());
|
||||
var result = ImeRunResult("21:30:01.1000000", "Success");
|
||||
var at = await StartRunAndReadFiller(h, "21:30:00.5000000", result);
|
||||
Assert.True(h.Tracker.OffsetCalibrator.TryGetOffset("IntuneManagementExtension.log", out var before));
|
||||
|
||||
AppendExecutorLog(h, RunEnd("21:30:01.0000000", 0, "done", ""));
|
||||
h.Overwrite(at, result);
|
||||
h.Now = h.Now.AddSeconds(1);
|
||||
await PassAndSettle(h);
|
||||
|
||||
Assert.True(h.Tracker.OffsetCalibrator.TryGetOffset("IntuneManagementExtension.log", out var after));
|
||||
Assert.Equal(before, after);
|
||||
}
|
||||
|
||||
[Theory]
|
||||
// Replaced bytes confirmed 1 s / 30 s ago: written since, age bounded like an appended line's.
|
||||
[InlineData(true, true, 1, true)]
|
||||
[InlineData(true, true, 30, true)]
|
||||
// Confirmed longer ago: the new bytes could be minutes old — their age may round onto the 15-minute grid.
|
||||
[InlineData(true, true, 31, false)]
|
||||
// The clock stepped back since the confirmation: the age is unknown.
|
||||
[InlineData(true, true, -1, false)]
|
||||
// The divergence lies in bytes the ledger never held (dropped by a cap): nothing dates them.
|
||||
[InlineData(true, false, 1, false)]
|
||||
// The pass itself is not fresh — the first pass after a restart never anchors.
|
||||
[InlineData(false, true, 1, false)]
|
||||
// Nothing was replaced.
|
||||
[InlineData(true, true, null, false)]
|
||||
public void Rewound_entry_is_fresh_only_when_the_bytes_it_replaced_were_confirmed_within_the_fresh_window(
|
||||
bool passLinesAreFresh, bool entryAtRewindPointReplaced, int? secondsSinceConfirmed, bool expected)
|
||||
{
|
||||
var now = new DateTime(2026, 10, 4, 19, 2, 0, DateTimeKind.Utc);
|
||||
DateTime? confirmed = secondsSinceConfirmed.HasValue ? now.AddSeconds(-secondsSinceConfirmed.Value) : (DateTime?)null;
|
||||
Assert.Equal(expected, ImeLogTracker.RewoundEntryIsFresh(passLinesAreFresh, entryAtRewindPointReplaced, confirmed, now));
|
||||
}
|
||||
}
|
||||
}
|
||||
+4
@@ -502,6 +502,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
public async Task Ime_result_line_hidden_by_an_executor_start_line_is_recovered_from_the_ime_log()
|
||||
{
|
||||
using var h = new Harness("IntuneManagementExtension.log", ScriptPatterns());
|
||||
// Seen empty first: the start lines are fresh and anchor themselves like the recovered result line will,
|
||||
// so start and result sit on one timeline whatever the host's own zone is.
|
||||
h.Append(string.Empty);
|
||||
await h.Pass();
|
||||
h.Append(Entry(GeneratedLine, "17") + Entry("Launch powershell executor in user session", "17") + Entry("process id = 10608", "17"));
|
||||
await h.Pass();
|
||||
var servicePosition = h.Length;
|
||||
|
||||
+26
-1
@@ -83,8 +83,33 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
Assert.Single(emitted);
|
||||
}
|
||||
|
||||
[Theory]
|
||||
// IME's verdict is Success exactly when the error file is empty, whatever the exit code. Judged by the exit
|
||||
// code, session 67ae751c showed exit 0 with the script's own stderr as Success, and 46a41a0a an exit 1 without
|
||||
// stderr as Failed, a run IME reported as Success one cycle earlier.
|
||||
[InlineData(0, "Invoke-WebRequest : The remote name could not be resolved", "Failed")]
|
||||
[InlineData(1, "", "Success")]
|
||||
[InlineData(1, " \n", "Success")]
|
||||
[InlineData(0, "", "Success")]
|
||||
[InlineData(1, null, "Failed")]
|
||||
[InlineData(0, null, "Success")]
|
||||
public void Fallback_judges_like_ime_by_the_stderr_it_read(int exitCode, string? stderr, string expected)
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var tracker = BuildTracker(tmp, out var emitted);
|
||||
var observedAt = new DateTime(2026, 6, 19, 12, 59, 4, DateTimeKind.Utc);
|
||||
|
||||
tracker.SeedPendingPlatformScriptForTesting("0d2294bf", exitCode: exitCode, exitObservedAtUtc: observedAt, stderr: stderr);
|
||||
tracker.FlushPendingPlatformScriptResults(observedAt.AddSeconds(20));
|
||||
|
||||
var script = Assert.Single(emitted);
|
||||
Assert.Equal(expected, script.Result);
|
||||
Assert.Equal(exitCode, script.ExitCode);
|
||||
Assert.Equal("agentexecutor_fallback", script.ResultSource);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Nonzero_exit_code_emits_failed_result()
|
||||
public void Nonzero_exit_code_without_a_stderr_line_emits_failed_result()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var tracker = BuildTracker(tmp, out var emitted);
|
||||
|
||||
+27
@@ -108,6 +108,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
|
||||
var tracker = BuildTracker(tmp, out var emitted);
|
||||
tracker.LoadStateForTest(); // must not throw
|
||||
Assert.Equal(0, tracker.ParkedPlatformScriptCountForTest);
|
||||
|
||||
// Degrades to pre-fix behavior: no markers restored, normal emission works (the
|
||||
// result waits for its end block until the shutdown flush).
|
||||
@@ -116,6 +117,32 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.Ime
|
||||
Assert.Single(emitted);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Pending_slot_from_a_state_file_without_executor_start_loads_and_completes()
|
||||
{
|
||||
using var tmp = new TempDirectory();
|
||||
var started = new DateTime(2026, 10, 4, 9, 0, 0, DateTimeKind.Utc);
|
||||
|
||||
// A pending slot written by an agent before runs carried their executor start and run id.
|
||||
var persistence = new ImeTrackerStatePersistence(tmp.Path, new AgentLogger(tmp.Path, AgentLogLevel.Info));
|
||||
persistence.Save(new ImeTrackerStateData
|
||||
{
|
||||
PendingPlatformScripts = new List<ScriptExecutionState>
|
||||
{
|
||||
new ScriptExecutionState { PolicyId = "policyF", ScriptType = "platform", StartedAtUtc = started, ExitCode = 0, ExitObservedAtUtc = started.AddSeconds(5), Stdout = "done", Stderr = "" },
|
||||
},
|
||||
});
|
||||
|
||||
var tracker = BuildTracker(tmp, out var emitted);
|
||||
tracker.LoadStateForTest();
|
||||
tracker.CompletePlatformScriptFromImeResultForTesting("policyF", "Success", started.AddSeconds(6));
|
||||
|
||||
var script = Assert.Single(emitted);
|
||||
Assert.Equal("Success", script.Result);
|
||||
Assert.Equal(0, script.ExitCode);
|
||||
Assert.False(string.IsNullOrEmpty(script.RunId));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void Stale_result_older_than_current_run_start_is_dropped()
|
||||
{
|
||||
|
||||
+225
@@ -0,0 +1,225 @@
|
||||
#nullable enable
|
||||
using System;
|
||||
using System.Collections.Generic;
|
||||
using System.IO;
|
||||
using System.Linq;
|
||||
using AutopilotMonitor.Agent.V2.Core.Logging;
|
||||
using AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals;
|
||||
using AutopilotMonitor.Agent.V2.Core.Orchestration;
|
||||
using AutopilotMonitor.Agent.V2.Core.Tests.Harness;
|
||||
using AutopilotMonitor.Agent.V2.Core.Tests.Orchestration;
|
||||
using AutopilotMonitor.DecisionCore.Engine;
|
||||
using AutopilotMonitor.DecisionCore.Signals;
|
||||
using AutopilotMonitor.Shared;
|
||||
using Xunit;
|
||||
|
||||
namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring
|
||||
{
|
||||
/// <summary>
|
||||
/// The first run's update page backfill (<see cref="ShellCoreTracker.BackfillUpdatePageTelemetry"/>)
|
||||
/// and the page a stop belongs to across backfill and live records. The first run has no
|
||||
/// replay — its backfill is telemetry and nothing else, so a Hello-wizard start, an ESP exit
|
||||
/// or an ESP failure in the window must not leave the tracker on any rail.
|
||||
/// </summary>
|
||||
public sealed class ShellCoreTrackerUpdatePageBackfillTests : IDisposable
|
||||
{
|
||||
private static readonly DateTime At = new DateTime(2026, 10, 5, 13, 10, 0, DateTimeKind.Utc);
|
||||
|
||||
private const string NdupStarted = "CloudExperienceHost Web App Activity started. CXID: 'OobeNDUP'.";
|
||||
private const string RebootNdupStarted = "CloudExperienceHost Web App Activity started. CXID: 'RebootNDUP'.";
|
||||
private const string AadHelloStarted = "CloudExperienceHost Web App Activity started. CXID: 'AADHello'.";
|
||||
private const string PageStopped = "CloudExperienceHost Web App Activity stopped. Result: 'success'.";
|
||||
private const string DownloadSucceeded =
|
||||
"CloudExperienceHost Web App Event 1. Name: 'SdxWebAppCloudNDUP_processStatusChangeFromHandler_downloadSucceeded'.";
|
||||
private const string EspExit = "CommercialOOBE_ESPProgress_Page_Exiting";
|
||||
private const string EspFailure = "CommercialOOBE_ESPProgress_Failure";
|
||||
private const string WhiteGloveSuccess = "CommercialOOBE_ESPProgress_WhiteGlove_Success";
|
||||
|
||||
private readonly TempDirectory _tmp = new TempDirectory();
|
||||
private readonly FakeSignalIngressSink _sink = new FakeSignalIngressSink();
|
||||
private int _registryReads;
|
||||
|
||||
public void Dispose() => _tmp.Dispose();
|
||||
|
||||
private ShellCoreTracker Build() =>
|
||||
new ShellCoreTracker("S1", "T1",
|
||||
new InformationalEventPost(_sink, new VirtualClock(At)),
|
||||
new AgentLogger(_tmp.Path, AgentLogLevel.Info),
|
||||
helloTracker: null,
|
||||
oobeUpdateRegistryReader: () => { _registryReads++; return Array.Empty<OobeUpdateRegistrySnapshot.KeyState>(); },
|
||||
stateDirectory: Path.Combine(_tmp.Path, "state"));
|
||||
|
||||
private static void Live(ShellCoreTracker tracker, int eventId, string description, DateTime at, long recordId) =>
|
||||
tracker.ProcessEvent(eventId, description, at, "Microsoft-Windows-Shell-Core", isBackfill: false, recordId: recordId);
|
||||
|
||||
private static ShellCoreRecord Record(int eventId, string description, DateTime at, long recordId) =>
|
||||
new ShellCoreRecord(eventId, description, at, recordId);
|
||||
|
||||
private IReadOnlyList<IReadOnlyDictionary<string, object>> Pages() =>
|
||||
_sink.Posted
|
||||
.Where(p => p.Kind == DecisionSignalKind.InformationalEvent
|
||||
&& p.Payload != null
|
||||
&& p.Payload.TryGetValue(SignalPayloadKeys.EventType, out var et)
|
||||
&& et == Constants.EventTypes.OobeUpdatePage)
|
||||
.Select(p => (IReadOnlyDictionary<string, object>)p.TypedPayload!)
|
||||
.ToList();
|
||||
|
||||
// ------------------------------------------------------------ first run ----
|
||||
|
||||
[Fact]
|
||||
public void FirstRunBackfill_ReportsTheUpdatePage_AndNothingElse()
|
||||
{
|
||||
using var tracker = Build();
|
||||
var raised = new List<string>();
|
||||
tracker.HelloWizardStarted += (_, _) => raised.Add("hello");
|
||||
tracker.FinalizingSetupPhaseTriggered += (_, reason) => raised.Add($"finalizing:{reason}");
|
||||
tracker.EspExited += (_, _) => raised.Add("exit");
|
||||
tracker.EspFailureDetected += (_, _) => raised.Add("failure");
|
||||
tracker.WhiteGloveCompleted += (_, _) => raised.Add("whiteglove");
|
||||
|
||||
tracker.ReplayUpdatePageTelemetry(new[]
|
||||
{
|
||||
Record(ShellCoreTracker.EventId_ShellCore_WebAppEvent, EspExit, At.AddMinutes(-41), 95),
|
||||
Record(ShellCoreTracker.EventId_ShellCore_WebAppEvent, EspFailure, At.AddSeconds(-2430), 96),
|
||||
Record(ShellCoreTracker.EventId_ShellCore_WebAppEvent, WhiteGloveSuccess, At.AddSeconds(-2420), 97),
|
||||
Record(ShellCoreTracker.EventId_ShellCore_WebAppStarted, NdupStarted, At.AddMinutes(-40), 100),
|
||||
Record(ShellCoreTracker.EventId_ShellCore_WebAppEventName, DownloadSucceeded, At.AddMinutes(-30), 101),
|
||||
Record(ShellCoreTracker.EventId_ShellCore_WebAppStarted, AadHelloStarted, At.AddMinutes(-2), 110),
|
||||
});
|
||||
|
||||
Assert.Empty(raised);
|
||||
Assert.False(tracker.IsEspExitedForTest);
|
||||
Assert.False(tracker.IsWhiteGloveDetectedForTest);
|
||||
var pages = Pages();
|
||||
Assert.Equal(new object[] { "page_started", "event_name" }, pages.Select(d => d["cxhEvent"]).ToArray());
|
||||
Assert.All(pages, d => Assert.Equal(true, d["backfill"]));
|
||||
// No agent_trace, no ESP or Hello event — only the two page rows.
|
||||
Assert.Equal(2, _sink.Posted.Count);
|
||||
// The registry shows the state now, not at the records' time.
|
||||
Assert.Equal(0, _registryReads);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void FirstRunBackfill_KeepsTheEventTimes()
|
||||
{
|
||||
using var tracker = Build();
|
||||
|
||||
tracker.ReplayUpdatePageTelemetry(new[]
|
||||
{
|
||||
Record(ShellCoreTracker.EventId_ShellCore_WebAppStarted, NdupStarted, At.AddMinutes(-40), 100),
|
||||
});
|
||||
|
||||
var posted = Assert.Single(_sink.Posted);
|
||||
Assert.Equal(At.AddMinutes(-40), posted.OccurredAtUtc);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void LiveStop_FindsThePageThatStartedBeforeTheAgent()
|
||||
{
|
||||
using var tracker = Build();
|
||||
tracker.ReplayUpdatePageTelemetry(new[]
|
||||
{
|
||||
Record(ShellCoreTracker.EventId_ShellCore_WebAppStarted, NdupStarted, At.AddMinutes(-40), 100),
|
||||
});
|
||||
|
||||
Live(tracker, ShellCoreTracker.EventId_ShellCore_WebAppStopped, PageStopped, At.AddMinutes(5), 120);
|
||||
|
||||
var stop = Pages().Last();
|
||||
Assert.Equal("page_stopped", stop["cxhEvent"]);
|
||||
Assert.Equal("OobeNDUP", stop["page"]);
|
||||
Assert.Equal(false, stop["backfill"]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void SameRecord_FromTheLiveWatcherAndTheFirstRunBackfill_IsReportedOnce()
|
||||
{
|
||||
// The live watcher is armed before the backfill reads, so both can deliver a record.
|
||||
using var tracker = Build();
|
||||
Live(tracker, ShellCoreTracker.EventId_ShellCore_WebAppStarted, NdupStarted, At, 700);
|
||||
tracker.ReplayUpdatePageTelemetry(new[]
|
||||
{
|
||||
Record(ShellCoreTracker.EventId_ShellCore_WebAppStarted, NdupStarted, At, 700),
|
||||
});
|
||||
|
||||
Assert.Single(Pages(), d => (string)d["cxhEvent"] == "page_started");
|
||||
}
|
||||
|
||||
// ---------------------------------------------------- the page of a stop ----
|
||||
|
||||
[Fact]
|
||||
public void ReplayedOlderStart_DoesNotTakeOverTheNextLiveStop()
|
||||
{
|
||||
// A restart replay reads records older than the live watcher's; before, its page start
|
||||
// overwrote the live page and the next live stop was attributed to the old page.
|
||||
using var tracker = Build();
|
||||
Live(tracker, ShellCoreTracker.EventId_ShellCore_WebAppStarted, RebootNdupStarted, At, 900);
|
||||
tracker.ReplayBackfillRecords(new[]
|
||||
{
|
||||
Record(ShellCoreTracker.EventId_ShellCore_WebAppStarted, NdupStarted, At.AddMinutes(-20), 850),
|
||||
Record(ShellCoreTracker.EventId_ShellCore_WebAppEventName, DownloadSucceeded, At.AddMinutes(-19), 851),
|
||||
});
|
||||
|
||||
Live(tracker, ShellCoreTracker.EventId_ShellCore_WebAppStopped, PageStopped, At.AddMinutes(1), 901);
|
||||
|
||||
var stop = Pages().Last();
|
||||
Assert.Equal("page_stopped", stop["cxhEvent"]);
|
||||
Assert.Equal("RebootNDUP", stop["page"]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void BackfilledStop_BelongsToTheStartOfItsOwnBatch()
|
||||
{
|
||||
using var tracker = Build();
|
||||
Live(tracker, ShellCoreTracker.EventId_ShellCore_WebAppStarted, RebootNdupStarted, At, 900);
|
||||
|
||||
tracker.ReplayUpdatePageTelemetry(new[]
|
||||
{
|
||||
Record(ShellCoreTracker.EventId_ShellCore_WebAppStarted, NdupStarted, At.AddMinutes(-20), 850),
|
||||
Record(ShellCoreTracker.EventId_ShellCore_WebAppStopped, PageStopped, At.AddMinutes(-18), 852),
|
||||
});
|
||||
|
||||
var stop = Pages().Last();
|
||||
Assert.Equal("page_stopped", stop["cxhEvent"]);
|
||||
Assert.Equal("OobeNDUP", stop["page"]);
|
||||
Assert.Equal(true, stop["backfill"]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void BackfilledStopWithoutItsStart_IsNotGivenTheLivePage()
|
||||
{
|
||||
using var tracker = Build();
|
||||
Live(tracker, ShellCoreTracker.EventId_ShellCore_WebAppStarted, NdupStarted, At, 900);
|
||||
|
||||
tracker.ReplayUpdatePageTelemetry(new[]
|
||||
{
|
||||
Record(ShellCoreTracker.EventId_ShellCore_WebAppStopped, PageStopped, At.AddMinutes(-18), 852),
|
||||
});
|
||||
|
||||
Assert.DoesNotContain(Pages(), d => (string)d["cxhEvent"] == "page_stopped");
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void NewerBackfilledStart_MovesTheLivePageForward()
|
||||
{
|
||||
// Records written between arming the watcher and the backfill's read are newer than
|
||||
// the last live start the watcher delivered before them.
|
||||
using var tracker = Build();
|
||||
Live(tracker, ShellCoreTracker.EventId_ShellCore_WebAppStarted, NdupStarted, At, 900);
|
||||
tracker.ReplayUpdatePageTelemetry(new[]
|
||||
{
|
||||
Record(ShellCoreTracker.EventId_ShellCore_WebAppStarted, RebootNdupStarted, At.AddSeconds(30), 905),
|
||||
});
|
||||
|
||||
Live(tracker, ShellCoreTracker.EventId_ShellCore_WebAppStopped, PageStopped, At.AddMinutes(1), 906);
|
||||
|
||||
Assert.Equal("RebootNDUP", Pages().Last()["page"]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void UpdatePageLookback_IsInsideTheReplayClamp()
|
||||
{
|
||||
Assert.Equal(ShellCoreTracker.UpdatePageBackfillLookbackMinutes,
|
||||
ShellCoreTracker.ClampLookbackMinutes(ShellCoreTracker.UpdatePageBackfillLookbackMinutes));
|
||||
}
|
||||
}
|
||||
}
|
||||
+32
-5
@@ -101,15 +101,41 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.SystemSignals
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void PageEvents_AreCappedPerRun()
|
||||
public void PageEvents_AreCappedPerRun_AndTheCapIsMarkedOnce()
|
||||
{
|
||||
var telemetry = Build();
|
||||
for (var i = 0; i < OobeUpdateTelemetry.MaxPageEventsPerRun + 20; i++)
|
||||
{
|
||||
telemetry.ReportPage(new OobeUpdatePageRecord(OobeUpdatePageRecord.EventName, 62406, name: $"ExpeditedUpdate_step{i}"), At, isBackfill: false);
|
||||
telemetry.ReportPage(new OobeUpdatePageRecord(OobeUpdatePageRecord.EventName, 62406, name: $"ExpeditedUpdate_step{i}"), At.AddSeconds(i), isBackfill: false);
|
||||
}
|
||||
|
||||
Assert.Equal(OobeUpdateTelemetry.MaxPageEventsPerRun, ByType(Constants.EventTypes.OobeUpdatePage).Count);
|
||||
var pages = ByType(Constants.EventTypes.OobeUpdatePage);
|
||||
Assert.Equal(OobeUpdateTelemetry.MaxPageEventsPerRun + 1, pages.Count);
|
||||
// A name missing after the marker proves nothing — the rules check for it.
|
||||
var marker = Data(pages.Last());
|
||||
Assert.Equal(OobeUpdatePageRecord.NamesCapped, marker["cxhEvent"]);
|
||||
Assert.Equal(false, marker["backfill"]);
|
||||
Assert.Equal(OobeUpdateTelemetry.MaxPageEventsPerRun, marker["limit"]);
|
||||
Assert.Equal(At.AddSeconds(OobeUpdateTelemetry.MaxPageEventsPerRun), pages.Last().OccurredAtUtc); // the first name over the budget
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void BackfilledNames_HaveTheirOwnBudget()
|
||||
{
|
||||
// The records from before the agent started cannot spend the live page's budget.
|
||||
var telemetry = Build();
|
||||
for (var i = 0; i < OobeUpdateTelemetry.MaxBackfillPageEventsPerRun + 5; i++)
|
||||
{
|
||||
telemetry.ReportPage(new OobeUpdatePageRecord(OobeUpdatePageRecord.EventName, 62406, name: $"ExpeditedUpdate_old{i}"), At.AddMinutes(-30), isBackfill: true);
|
||||
}
|
||||
|
||||
Assert.True(telemetry.ReportPage(new OobeUpdatePageRecord(OobeUpdatePageRecord.EventName, 62406, name: "ExpeditedUpdate_live"), At, isBackfill: false));
|
||||
|
||||
var markers = ByType(Constants.EventTypes.OobeUpdatePage)
|
||||
.Where(p => (string)Data(p)["cxhEvent"] == OobeUpdatePageRecord.NamesCapped).ToList();
|
||||
var marker = Assert.Single(markers);
|
||||
Assert.Equal(true, Data(marker)["backfill"]);
|
||||
Assert.Equal(OobeUpdateTelemetry.MaxBackfillPageEventsPerRun, Data(marker)["limit"]);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
@@ -123,12 +149,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Tests.Monitoring.SystemSignals
|
||||
}
|
||||
|
||||
Assert.False(telemetry.ReportPage(new OobeUpdatePageRecord(OobeUpdatePageRecord.EventName, 62406, name: "ExpeditedUpdate_late"), At, isBackfill: false));
|
||||
Assert.False(telemetry.ReportPage(new OobeUpdatePageRecord(OobeUpdatePageRecord.EventName, 62406, name: "ExpeditedUpdate_later"), At, isBackfill: false));
|
||||
Assert.True(telemetry.ReportPage(new OobeUpdatePageRecord(OobeUpdatePageRecord.PageStarted, 62404, page: "RebootNDUP"), At.AddMinutes(1), isBackfill: false));
|
||||
Assert.True(telemetry.ReportPage(new OobeUpdatePageRecord(OobeUpdatePageRecord.PageStopped, 62405, page: "RebootNDUP", result: "success"), At.AddMinutes(2), isBackfill: false));
|
||||
|
||||
var pages = ByType(Constants.EventTypes.OobeUpdatePage);
|
||||
Assert.Equal(OobeUpdateTelemetry.MaxPageEventsPerRun + 2, pages.Count);
|
||||
Assert.Equal(new object[] { "page_started", "page_stopped" },
|
||||
Assert.Equal(OobeUpdateTelemetry.MaxPageEventsPerRun + 3, pages.Count);
|
||||
Assert.Equal(new object[] { OobeUpdatePageRecord.NamesCapped, "page_started", "page_stopped" },
|
||||
pages.Skip(OobeUpdateTelemetry.MaxPageEventsPerRun).Select(p => Data(p)["cxhEvent"]).ToArray());
|
||||
}
|
||||
|
||||
|
||||
+254
-57
@@ -306,6 +306,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
var currentStartTs = LastMatchedLogTimestamp ?? UtcNowProvider();
|
||||
var currentStartProvenance = CaptureLastMatchedProvenance();
|
||||
var fromExecutor = string.Equals(source, "agentexecutor", StringComparison.OrdinalIgnoreCase);
|
||||
|
||||
// A start line older than the result this policy already emitted is the late start
|
||||
// line of THAT run: its AgentExecutor block surfaced after the IME result — the two
|
||||
@@ -318,7 +319,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// never tie; a low-resolution clock in a test may).
|
||||
if (_platformScriptResultEmitted.TryGetValue(id, out var emittedResultTs) && currentStartTs < emittedResultTs)
|
||||
{
|
||||
RecordInvocationMarker(id, isClose: false);
|
||||
RecordInvocationMarker(id, isClose: false, EmittedRunId);
|
||||
NoteInvocationActivity();
|
||||
_logger.Debug($"ImeLogTracker: platform script start line for {id} (source: {source ?? "ime"}) predates its emitted result — late line of that run, not a new one");
|
||||
return;
|
||||
@@ -326,7 +327,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
if (_pendingPlatformScripts.TryGetValue(id, out var pendingSlot))
|
||||
{
|
||||
if (pendingSlot.StartedAtUtc.HasValue && currentStartTs - pendingSlot.StartedAtUtc.Value > TimeSpan.FromHours(24))
|
||||
if (pendingSlot.StartedAtUtc.HasValue && currentStartTs - pendingSlot.StartedAtUtc.Value > StalePlatformRunAge)
|
||||
{
|
||||
// Stale-slot hardening (session eaf3d8c4): a replayed start line from a previous
|
||||
// enrollment whose matching result never appeared (script was mid-run when that
|
||||
@@ -343,6 +344,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// Emit what the held run has; its end block did not surface in time.
|
||||
EmitPlatformScriptResult(pendingSlot, "the next run of this policy started");
|
||||
}
|
||||
else if (fromExecutor && LastMatchedLogTimestamp.HasValue && pendingSlot.Result == null
|
||||
&& pendingSlot.ExecutorStartedAtUtc.HasValue && pendingSlot.ExecutorStartedAtUtc.Value < currentStartTs)
|
||||
{
|
||||
// Every executor process writes its start line once: a later one is the next run
|
||||
// (IME re-runs a failed script on a later check-in), whose end block must not
|
||||
// overwrite this one's. This run waits for its IME result — on the first pass
|
||||
// AgentExecutor.log is read in full before the IME log (session eff1b413).
|
||||
ParkPlatformRun(pendingSlot);
|
||||
}
|
||||
else if (!pendingSlot.StartedAtUtc.HasValue)
|
||||
{
|
||||
// The slot was opened by its result while the start block was still hidden;
|
||||
@@ -351,9 +361,17 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
pendingSlot.StartedAtProvenance = currentStartProvenance;
|
||||
_stateDirty = true;
|
||||
}
|
||||
if (pendingSlot.UserId == null && userId != null) pendingSlot.UserId = userId;
|
||||
}
|
||||
if (!_pendingPlatformScripts.ContainsKey(id))
|
||||
if (_pendingPlatformScripts.TryGetValue(id, out var slot))
|
||||
{
|
||||
if (slot.UserId == null && userId != null) slot.UserId = userId;
|
||||
if (fromExecutor && !slot.ExecutorStartedAtUtc.HasValue)
|
||||
{
|
||||
slot.ExecutorStartedAtUtc = currentStartTs;
|
||||
_stateDirty = true;
|
||||
}
|
||||
}
|
||||
else
|
||||
{
|
||||
// A fresh start for this policy (no pending entry) begins a NEW execution.
|
||||
// Clear any emitted-marker from a prior run so IME re-evaluations / retries of
|
||||
@@ -361,18 +379,21 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// deduped away. A start line of the emitted run itself never reaches this point
|
||||
// (the guard above), so this never clears the current run's own marker.
|
||||
_platformScriptResultEmitted.Remove(id);
|
||||
_pendingPlatformScripts[id] = new ScriptExecutionState
|
||||
slot = new ScriptExecutionState
|
||||
{
|
||||
PolicyId = id,
|
||||
ScriptType = "platform",
|
||||
UserId = userId,
|
||||
RunId = NewRunId(),
|
||||
// Prefer the source CMTrace timestamp so a script that started before the
|
||||
// agent launched (replayed log content) is dated to its real start, not now.
|
||||
// Set only at slot creation: the start line fires twice (agentexecutor + ime
|
||||
// source) but the earliest wins.
|
||||
StartedAtUtc = currentStartTs,
|
||||
StartedAtProvenance = currentStartProvenance,
|
||||
ExecutorStartedAtUtc = fromExecutor ? currentStartTs : (DateTime?)null,
|
||||
};
|
||||
_pendingPlatformScripts[id] = slot;
|
||||
ScriptRuns.NoteStarted(userId, id, UtcNowProvider());
|
||||
// Live "running" indicator — same signal health scripts emit. Gated on slot
|
||||
// creation so the duplicate start line (agentexecutor + ime source) doesn't
|
||||
@@ -380,7 +401,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
try { OnScriptStarted?.Invoke(new ScriptStartedInfo { PolicyId = id, ScriptType = "platform" }); }
|
||||
catch (Exception ex) { _logger.Warning($"ImeLogTracker: OnScriptStarted handler threw: {ex.Message}"); }
|
||||
}
|
||||
RecordInvocationMarker(id, isClose: false);
|
||||
RecordInvocationMarker(id, isClose: false, LastMatchedLogTimestamp.HasValue ? RunIdOfStartLine(slot, fromExecutor, currentStartTs) : slot.RunId);
|
||||
NoteInvocationActivity();
|
||||
// Started lines fire twice per script (agentexecutor + ime source) and carry no
|
||||
// outcome — the matching `platform script completed` line below carries result+exit
|
||||
@@ -388,6 +409,34 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
_logger.Debug($"ImeLogTracker: platform script started: {id} (source: {source ?? "ime"})");
|
||||
}
|
||||
|
||||
/// <summary>How long after IME's "Script file … is generated" line its executor writes its start line (about 2 s).</summary>
|
||||
private static readonly TimeSpan ImeLaunchWindow = TimeSpan.FromMinutes(1);
|
||||
|
||||
/// <summary>
|
||||
/// The run a timestamped start line belongs to, for its invocation marker. An executor start line belongs to the
|
||||
/// slot unless it is older than the slot's executor start — re-read behind a later run — then to the parked run
|
||||
/// it started. IME's "Script file … is generated" precedes its executor: it belongs to the live run whose
|
||||
/// executor started within <see cref="ImeLaunchWindow"/> after it, else to a slot whose executor has not
|
||||
/// started yet; otherwise its run is not known (yet) and the lines behind it go nowhere.
|
||||
/// </summary>
|
||||
private string RunIdOfStartLine(ScriptExecutionState slot, bool fromExecutor, DateTime lineTs)
|
||||
{
|
||||
if (fromExecutor)
|
||||
{
|
||||
if (!slot.ExecutorStartedAtUtc.HasValue || slot.ExecutorStartedAtUtc.Value <= lineTs) return slot.RunId;
|
||||
var parked = _parkedPlatformScripts.FirstOrDefault(r =>
|
||||
string.Equals(r.PolicyId, slot.PolicyId, StringComparison.OrdinalIgnoreCase) && r.ExecutorStartedAtUtc == lineTs);
|
||||
return parked?.RunId ?? EmittedRunId;
|
||||
}
|
||||
|
||||
var launched = LivePlatformRuns(slot.PolicyId)
|
||||
.Where(r => r.ExecutorStartedAtUtc.HasValue && r.ExecutorStartedAtUtc.Value >= lineTs && r.ExecutorStartedAtUtc.Value - lineTs <= ImeLaunchWindow)
|
||||
.OrderBy(r => r.ExecutorStartedAtUtc.Value)
|
||||
.FirstOrDefault();
|
||||
if (launched != null) return launched.RunId;
|
||||
return slot.ExecutorStartedAtUtc.HasValue ? EmittedRunId : slot.RunId;
|
||||
}
|
||||
|
||||
// Routes line-by-line script-data handlers (context / exitCode / output) to the right
|
||||
// accumulator based on the pattern's scriptType parameter. Health-script lines feed the
|
||||
// single-slot _pendingHealthScript (the HS-NEW-RESULT JSON delivers the full cycle in one
|
||||
@@ -502,13 +551,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
// PS-AGENT-OUTPUT captures both stdout and stderr in one pattern
|
||||
var output = match.Groups["output"]?.Value;
|
||||
var error = match.Groups["error"]?.Value;
|
||||
var error = match.Groups["error"];
|
||||
|
||||
if (!string.IsNullOrEmpty(output) && !string.IsNullOrEmpty(error))
|
||||
if (error != null && error.Success)
|
||||
{
|
||||
// Combined pattern (write output done. output = ..., error = ...)
|
||||
script.Stdout = TruncateOutput(output.Trim());
|
||||
script.Stderr = TruncateOutput(error.Trim());
|
||||
// Combined pattern (write output done. output = ..., error = ...): both texts as
|
||||
// AgentExecutor wrote them to the result files — the error part is the error file
|
||||
// IME judges. The "error from script" line before it is a snapshot taken before the
|
||||
// output readers finished, so this one replaces it, an empty stdout included.
|
||||
script.Stdout = TruncateOutput(output?.Trim());
|
||||
script.Stderr = TruncateOutput(error.Value.Trim());
|
||||
}
|
||||
else if (string.Equals(outputType, "stderr", StringComparison.OrdinalIgnoreCase))
|
||||
{
|
||||
@@ -556,49 +608,44 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// </summary>
|
||||
internal void CompletePlatformScriptFromImeResult(string policyId, string result, DateTime? resultLineTimestampUtc, string patternId, CmTraceLineProvenance resultProvenance, string userId = null)
|
||||
{
|
||||
// Dedup: the deadline-based fallback (FlushPendingPlatformScriptResults) may already have
|
||||
// emitted this script from its AgentExecutor exit code because IME's authoritative
|
||||
// PS-SCRIPT-RESULT line arrived late. The fallback carries the same exit code + stdout,
|
||||
// so re-emitting here would duplicate the timeline entry and inflate counts. Drop the
|
||||
// now-redundant pending entry and skip.
|
||||
if (_platformScriptResultEmitted.ContainsKey(policyId))
|
||||
// The result belongs to the run of this policy that started last before its line —
|
||||
// the run in flight, or an earlier one that waits for its result while a later run
|
||||
// already started (ParkPlatformRun).
|
||||
var script = FindRunForResult(policyId, userId, resultLineTimestampUtc);
|
||||
if (script == null)
|
||||
{
|
||||
_logger.Debug($"ImeLogTracker: platform script {policyId} PS-SCRIPT-RESULT arrived after fallback emit — skipping duplicate");
|
||||
_pendingPlatformScripts.Remove(policyId);
|
||||
return;
|
||||
}
|
||||
// Dedup: the deadline-based fallback (FlushPendingPlatformScriptResults) may already
|
||||
// have emitted this run from its AgentExecutor end block because IME's authoritative
|
||||
// PS-SCRIPT-RESULT line arrived late, or the same result line is read again.
|
||||
// Re-emitting would duplicate the timeline entry and inflate counts.
|
||||
if (_platformScriptResultEmitted.ContainsKey(policyId))
|
||||
{
|
||||
_logger.Debug($"ImeLogTracker: platform script {policyId} PS-SCRIPT-RESULT arrived after its run was emitted — skipping duplicate");
|
||||
return;
|
||||
}
|
||||
|
||||
// Merge with pending AgentExecutor data if available
|
||||
if (_pendingPlatformScripts.TryGetValue(policyId, out var script))
|
||||
{
|
||||
// Stale-result guard: on an intra-lifetime re-run of the same policy, run 1's
|
||||
// late PS-SCRIPT-RESULT can arrive after run 2's start line already created a
|
||||
// fresh slot (the start clears the emitted-marker). Merging would pair run 2's
|
||||
// StartedAtUtc/state with run 1's result and then drop run 2's genuine result at
|
||||
// the marker check above. A result line always postdates its own run's start
|
||||
// line in the source log, so a result older than the pending slot's start
|
||||
// belongs to a previous run — drop it and keep the live slot intact.
|
||||
if (script.StartedAtUtc.HasValue
|
||||
&& resultLineTimestampUtc.HasValue
|
||||
&& resultLineTimestampUtc.Value < script.StartedAtUtc.Value)
|
||||
// Stale-result guard: every run of this policy in flight started after the result
|
||||
// line — a result line always postdates its own run's start line in the source log,
|
||||
// so it belongs to a previous run. Keep the live runs intact.
|
||||
if (HasLivePlatformRun(policyId))
|
||||
{
|
||||
_logger.Debug($"ImeLogTracker: platform script {policyId} result predates the current run's start — stale result from a previous run, skipping");
|
||||
return;
|
||||
}
|
||||
}
|
||||
else
|
||||
{
|
||||
|
||||
script = new ScriptExecutionState
|
||||
{
|
||||
PolicyId = policyId,
|
||||
ScriptType = "platform",
|
||||
UserId = userId,
|
||||
RunId = NewRunId(),
|
||||
};
|
||||
_pendingPlatformScripts[policyId] = script;
|
||||
ScriptRuns.NoteStarted(userId, policyId, UtcNowProvider());
|
||||
}
|
||||
|
||||
if (script.UserId == null && userId != null) script.UserId = userId;
|
||||
ResolveParkedRunsBefore(script);
|
||||
script.Result = result;
|
||||
script.ResultSource = "ime_policy_result";
|
||||
script.ResultObservedAtUtc = resultLineTimestampUtc ?? UtcNowProvider();
|
||||
@@ -627,21 +674,150 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
private void EmitPlatformScriptResult(ScriptExecutionState script, string note = null)
|
||||
{
|
||||
_logger.Info($"ImeLogTracker: platform script completed: {script.PolicyId}, result={script.Result}, exit={script.ExitCode}{(note != null ? $" ({note})" : string.Empty)}");
|
||||
if (string.IsNullOrEmpty(script.RunId)) script.RunId = Guid.NewGuid().ToString("D");
|
||||
if (string.IsNullOrEmpty(script.RunId)) script.RunId = NewRunId();
|
||||
EmitScriptEvent(script);
|
||||
ScriptRuns.NoteEmitted(script, UtcNowProvider());
|
||||
// The register keeps the latest run per (user, policy) for the registry reconciliation:
|
||||
// a run that waited for its result while a later one started must not take that later
|
||||
// run's entry.
|
||||
if (!HasLaterLivePlatformRun(script)) ScriptRuns.NoteEmitted(script, UtcNowProvider());
|
||||
// The run's source stamp, capped at the clock: a result line cannot be read before it
|
||||
// was written, so a stamp ahead of the clock is a wrong zone assumption on that line
|
||||
// (a rewound result resolved in the reader's zone, session 4377911b: +1 h). Left
|
||||
// uncapped, the marker made the genuine NEXT run's start line read as a late line of
|
||||
// this run and its result a duplicate.
|
||||
// this run and its result a duplicate. Only ever raised: a run emitted after a later
|
||||
// one must not move the reference back.
|
||||
var runStamp = script.ResultObservedAtUtc ?? script.ExitObservedAtUtc ?? UtcNowProvider();
|
||||
var nowUtc = UtcNowProvider();
|
||||
_platformScriptResultEmitted[script.PolicyId] = runStamp > nowUtc ? nowUtc : runStamp;
|
||||
_pendingPlatformScripts.Remove(script.PolicyId);
|
||||
var stamp = runStamp > nowUtc ? nowUtc : runStamp;
|
||||
if (!_platformScriptResultEmitted.TryGetValue(script.PolicyId, out var previousStamp) || stamp > previousStamp)
|
||||
_platformScriptResultEmitted[script.PolicyId] = stamp;
|
||||
if (_pendingPlatformScripts.TryGetValue(script.PolicyId, out var current) && ReferenceEquals(current, script))
|
||||
_pendingPlatformScripts.Remove(script.PolicyId);
|
||||
else
|
||||
_parkedPlatformScripts.Remove(script);
|
||||
_stateDirty = true;
|
||||
}
|
||||
|
||||
private static string NewRunId() => Guid.NewGuid().ToString("D");
|
||||
|
||||
/// <summary>A run older than this by source time is from a previous enrollment, not a run in flight.</summary>
|
||||
private static readonly TimeSpan StalePlatformRunAge = TimeSpan.FromHours(24);
|
||||
|
||||
private static bool SameUserOrUnknown(string a, string b)
|
||||
=> a == null || b == null || string.Equals(a, b, StringComparison.OrdinalIgnoreCase);
|
||||
|
||||
private static DateTime StartOf(ScriptExecutionState run) => run.StartedAtUtc ?? DateTime.MinValue;
|
||||
|
||||
/// <summary>The runs of a policy that are not emitted yet: the earlier ones waiting for their IME result, then the one in flight.</summary>
|
||||
private IEnumerable<ScriptExecutionState> LivePlatformRuns(string policyId)
|
||||
{
|
||||
foreach (var run in _parkedPlatformScripts)
|
||||
{
|
||||
if (string.Equals(run.PolicyId, policyId, StringComparison.OrdinalIgnoreCase)) yield return run;
|
||||
}
|
||||
if (_pendingPlatformScripts.TryGetValue(policyId, out var current)) yield return current;
|
||||
}
|
||||
|
||||
private bool HasLivePlatformRun(string policyId) => LivePlatformRuns(policyId).Any();
|
||||
|
||||
/// <summary>The live run a start marker names, or null once that run was emitted.</summary>
|
||||
private ScriptExecutionState FindLivePlatformRun(string policyId, string runId)
|
||||
=> LivePlatformRuns(policyId).FirstOrDefault(r => string.Equals(r.RunId, runId, StringComparison.Ordinal));
|
||||
|
||||
private bool HasLaterLivePlatformRun(ScriptExecutionState script)
|
||||
=> LivePlatformRuns(script.PolicyId).Any(r => !ReferenceEquals(r, script)
|
||||
&& SameUserOrUnknown(r.UserId, script.UserId) && StartOf(r) > StartOf(script));
|
||||
|
||||
/// <summary>
|
||||
/// The live run an IME result line belongs to: of the runs of its policy that started at or before the line,
|
||||
/// the latest — one of the same IME user when there is one.
|
||||
/// </summary>
|
||||
private ScriptExecutionState FindRunForResult(string policyId, string userId, DateTime? resultLineTimestampUtc)
|
||||
{
|
||||
ScriptExecutionState sameUser = null, anyUser = null;
|
||||
foreach (var run in LivePlatformRuns(policyId))
|
||||
{
|
||||
if (resultLineTimestampUtc.HasValue && run.StartedAtUtc.HasValue && run.StartedAtUtc.Value > resultLineTimestampUtc.Value) continue;
|
||||
if (anyUser == null || StartOf(run) > StartOf(anyUser)) anyUser = run;
|
||||
if (SameUserOrUnknown(run.UserId, userId) && (sameUser == null || StartOf(run) > StartOf(sameUser))) sameUser = run;
|
||||
}
|
||||
return sameUser ?? anyUser;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Moves the run in flight aside when the next executor run of its policy starts: it keeps its own end block and
|
||||
/// waits for its IME result (<see cref="FindRunForResult"/>), the exit-code fallback, or a later run's result.
|
||||
/// </summary>
|
||||
private void ParkPlatformRun(ScriptExecutionState run)
|
||||
{
|
||||
_pendingPlatformScripts.Remove(run.PolicyId);
|
||||
_parkedPlatformScripts.Add(run);
|
||||
_stateDirty = true;
|
||||
if (_parkedPlatformScripts.Count > MaxParkedPlatformScripts)
|
||||
{
|
||||
var oldest = _parkedPlatformScripts.OrderBy(StartOf).First();
|
||||
_logger.Warning($"ImeLogTracker: more than {MaxParkedPlatformScripts} platform runs wait for their IME result — resolving the oldest ({oldest.PolicyId}, started {oldest.StartedAtUtc:o}) now");
|
||||
ResolveParkedRun(oldest, "too many runs waiting for their IME result");
|
||||
}
|
||||
_logger.Debug($"ImeLogTracker: platform script {run.PolicyId}: the next executor run started before IME's result of run {run.RunId} was read — that run keeps its end block and waits for its result");
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Results arrive in run order: a parked run of the same IME user that started before the run a result belongs to
|
||||
/// gets none any more (its result line was lost) — it goes out now, ahead of the later run.
|
||||
/// </summary>
|
||||
private void ResolveParkedRunsBefore(ScriptExecutionState owner)
|
||||
{
|
||||
if (_parkedPlatformScripts.Count == 0 || !owner.StartedAtUtc.HasValue) return;
|
||||
var earlier = _parkedPlatformScripts
|
||||
.Where(r => !ReferenceEquals(r, owner)
|
||||
&& string.Equals(r.PolicyId, owner.PolicyId, StringComparison.OrdinalIgnoreCase)
|
||||
&& SameUserOrUnknown(r.UserId, owner.UserId)
|
||||
&& r.StartedAtUtc.HasValue && r.StartedAtUtc.Value < owner.StartedAtUtc.Value)
|
||||
.OrderBy(StartOf)
|
||||
.ToList();
|
||||
foreach (var run in earlier) ResolveParkedRun(run, "a later run of this policy got its IME result first");
|
||||
}
|
||||
|
||||
/// <summary>A parked run that will not get its IME result: out with what it has, or dropped when it has nothing.</summary>
|
||||
private void ResolveParkedRun(ScriptExecutionState run, string why)
|
||||
{
|
||||
if (run.Result != null)
|
||||
{
|
||||
EmitPlatformScriptResult(run, why);
|
||||
}
|
||||
else if (run.ExitCode.HasValue)
|
||||
{
|
||||
EmitFromExecutorEndBlock(run, why);
|
||||
}
|
||||
else
|
||||
{
|
||||
_parkedPlatformScripts.Remove(run);
|
||||
_stateDirty = true;
|
||||
_logger.Debug($"ImeLogTracker: platform script {run.PolicyId} run {run.RunId} has neither IME result nor executor end block — dropped ({why})");
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// IME's own verdict from a run's end block: Success exactly when the error file was empty
|
||||
/// (<c>IsNullOrEmpty(errorFile.Trim())</c> in IME), whatever the exit code — PowerShell returns 0 after a
|
||||
/// non-terminating error and any code a script exits with. Only when the stderr line was never read does the
|
||||
/// exit code stand in.
|
||||
/// </summary>
|
||||
internal static string ImeResultFromEndBlock(ScriptExecutionState script)
|
||||
{
|
||||
if (script.Stderr != null) return string.IsNullOrWhiteSpace(script.Stderr) ? "Success" : "Failed";
|
||||
return script.ExitCode == 0 ? "Success" : "Failed";
|
||||
}
|
||||
|
||||
private void EmitFromExecutorEndBlock(ScriptExecutionState script, string why)
|
||||
{
|
||||
script.Result = ImeResultFromEndBlock(script);
|
||||
script.ResultSource = "agentexecutor_fallback";
|
||||
var basis = script.Stderr == null ? $"exit code {script.ExitCode}, stderr not read" : script.Stderr.Trim().Length == 0 ? "empty stderr" : "stderr present";
|
||||
EmitPlatformScriptResult(script, $"{why} — {script.Result} from the executor end block ({basis}) (fallback)");
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Grace period after a platform script's AgentExecutor exit code is observed before
|
||||
/// <see cref="FlushPendingPlatformScriptResults"/> emits a completion from that exit code.
|
||||
@@ -679,29 +855,48 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// out once its executor end block has been read — the block arrives within one pass, so
|
||||
/// stdout/stderr are in by now — or after <see cref="PlatformScriptEndBlockGrace"/>.</item>
|
||||
/// <item>A script with a known AgentExecutor exit code but no IME <c>PS-SCRIPT-RESULT</c>
|
||||
/// line within <see cref="PlatformScriptResultGrace"/> is emitted from the exit code
|
||||
/// (0 → Success, else Failed), tagged <c>resultSource=agentexecutor_fallback</c> so the
|
||||
/// data is honest about its provenance. Without this, scripts that completed shortly
|
||||
/// before the agent terminates were silently dropped.</item>
|
||||
/// line within <see cref="PlatformScriptResultGrace"/> is emitted from its end block by
|
||||
/// IME's own rule (<see cref="ImeResultFromEndBlock"/>), tagged
|
||||
/// <c>resultSource=agentexecutor_fallback</c> so the data is honest about its provenance.
|
||||
/// Without this, scripts that completed shortly before the agent terminates were silently
|
||||
/// dropped.</item>
|
||||
/// </list>
|
||||
/// Parked runs go first, oldest first, so a policy's runs leave in run order; one without
|
||||
/// result and end block keeps waiting — across a shutdown too — until a later run's result
|
||||
/// resolves it or it is a day old.
|
||||
/// Runs on the single-threaded polling loop (no locking needed, same as the handlers).
|
||||
/// <paramref name="force"/> bypasses both grace checks for the final pass on shutdown.
|
||||
/// </summary>
|
||||
internal void FlushPendingPlatformScriptResults(DateTime nowUtc, bool force = false)
|
||||
{
|
||||
if (_pendingPlatformScripts.Count == 0) return;
|
||||
if (_pendingPlatformScripts.Count == 0 && _parkedPlatformScripts.Count == 0) return;
|
||||
|
||||
var fallbackEmitted = false;
|
||||
foreach (var script in _pendingPlatformScripts.Values.ToList())
|
||||
foreach (var run in _parkedPlatformScripts.OrderBy(StartOf).ToList())
|
||||
{
|
||||
// Already emitted by the authoritative path — just drop the stale buffer entry.
|
||||
if (_platformScriptResultEmitted.ContainsKey(script.PolicyId))
|
||||
if (run.Result != null)
|
||||
{
|
||||
_pendingPlatformScripts.Remove(script.PolicyId);
|
||||
_stateDirty = true;
|
||||
if (run.ExitCode.HasValue || force || !run.ResultHeldSinceUtc.HasValue || nowUtc - run.ResultHeldSinceUtc.Value >= PlatformScriptEndBlockGrace)
|
||||
EmitPlatformScriptResult(run, run.ExitCode.HasValue ? "executor end block read after the result" : $"no executor end block within {PlatformScriptEndBlockGrace.TotalSeconds:F0}s");
|
||||
continue;
|
||||
}
|
||||
if (run.ExitCode.HasValue)
|
||||
{
|
||||
if (!force && (!run.ExitObservedAtUtc.HasValue || nowUtc - run.ExitObservedAtUtc.Value < PlatformScriptResultGrace)) continue;
|
||||
EmitFromExecutorEndBlock(run, $"result not seen within {PlatformScriptResultGrace.TotalSeconds:F0}s{(force ? ", shutdown flush" : string.Empty)}");
|
||||
fallbackEmitted = true;
|
||||
continue;
|
||||
}
|
||||
if (run.StartedAtUtc.HasValue && nowUtc - run.StartedAtUtc.Value > StalePlatformRunAge)
|
||||
{
|
||||
_parkedPlatformScripts.Remove(run);
|
||||
_stateDirty = true;
|
||||
_logger.Debug($"ImeLogTracker: platform script {run.PolicyId} run {run.RunId} waited a day without IME result or executor end block — dropped");
|
||||
}
|
||||
}
|
||||
|
||||
foreach (var script in _pendingPlatformScripts.Values.ToList())
|
||||
{
|
||||
if (script.Result != null)
|
||||
{
|
||||
if (script.ExitCode.HasValue)
|
||||
@@ -720,10 +915,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
if (nowUtc - script.ExitObservedAtUtc.Value < PlatformScriptResultGrace) continue;
|
||||
}
|
||||
|
||||
script.Result = script.ExitCode.Value == 0 ? "Success" : "Failed";
|
||||
script.ResultSource = "agentexecutor_fallback";
|
||||
EmitPlatformScriptResult(script,
|
||||
$"result not seen within {PlatformScriptResultGrace.TotalSeconds:F0}s{(force ? ", shutdown flush" : string.Empty)} — emitted from AgentExecutor exit code {script.ExitCode.Value} (fallback)");
|
||||
EmitFromExecutorEndBlock(script, $"result not seen within {PlatformScriptResultGrace.TotalSeconds:F0}s{(force ? ", shutdown flush" : string.Empty)}");
|
||||
fallbackEmitted = true;
|
||||
}
|
||||
|
||||
@@ -735,7 +927,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// <summary>Test seam: inject a pending platform script as if AgentExecutor.log had reported
|
||||
/// its start + exit code, without an IME PS-SCRIPT-RESULT line.</summary>
|
||||
internal void SeedPendingPlatformScriptForTesting(string policyId, int? exitCode, DateTime? exitObservedAtUtc, string stdout = null, DateTime? startedAtUtc = null,
|
||||
CmTraceLineProvenance startedAtProvenance = null, CmTraceLineProvenance exitProvenance = null)
|
||||
CmTraceLineProvenance startedAtProvenance = null, CmTraceLineProvenance exitProvenance = null, string stderr = null)
|
||||
{
|
||||
// Mirrors a fresh execution start: a new run clears any prior emitted-marker (see
|
||||
// HandleScriptStarted) so re-runs of the same policy within one lifetime emit again.
|
||||
@@ -744,9 +936,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
PolicyId = policyId,
|
||||
ScriptType = "platform",
|
||||
RunId = NewRunId(),
|
||||
ExitCode = exitCode,
|
||||
ExitObservedAtUtc = exitObservedAtUtc,
|
||||
Stdout = stdout,
|
||||
Stderr = stderr,
|
||||
StartedAtUtc = startedAtUtc,
|
||||
StartedAtProvenance = startedAtProvenance,
|
||||
ExitProvenance = exitProvenance,
|
||||
@@ -755,6 +949,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
RecordInvocationMarker(policyId, isClose: false);
|
||||
}
|
||||
|
||||
/// <summary>Test seam: earlier runs waiting for their IME result while a later run of their policy is in flight.</summary>
|
||||
internal int ParkedPlatformScriptCountForTest => _parkedPlatformScripts.Count;
|
||||
|
||||
/// <summary>Test seam: the authoritative IME PS-SCRIPT-RESULT path for a platform script
|
||||
/// (the production handler minus regex extraction). <paramref name="resultLineTimestampUtc"/>
|
||||
/// stands in for the CMTrace timestamp of the PS-SCRIPT-RESULT line (production reads it
|
||||
|
||||
+11
-6
@@ -123,8 +123,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
var ledger = IsMultiWriterLogFile(fileName) ? GetLedger(fileName) : null;
|
||||
|
||||
// Set by a rewind: entries that still read unchanged behind the old bookmark are
|
||||
// skipped (their invocation markers are given back), and nothing below the old
|
||||
// bookmark is fresh or a calibration anchor.
|
||||
// skipped (their invocation markers are given back); a changed entry below the old
|
||||
// bookmark is fresh only when the bytes it replaced were seen moments ago, and never a
|
||||
// calibration anchor.
|
||||
RewindState rewind = null;
|
||||
long oldBookmark = -1;
|
||||
var writerBoundaries = IsWriterBoundaryLogFile(fileName);
|
||||
@@ -171,12 +172,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
var guardFrom = ledger.OffsetOfEntryAtOrAfter(startPos - OverwriteGuardBytes);
|
||||
if (guardFrom >= 0 && guardFrom < startPos)
|
||||
{
|
||||
var divergence = await FindOverwriteAsync(stream, ledger, guardFrom, startPos, token);
|
||||
var divergence = await FindOverwriteAsync(stream, ledger, guardFrom, startPos, passNowUtc, token);
|
||||
_verifiedBytes += startPos - guardFrom;
|
||||
if (divergence >= 0)
|
||||
{
|
||||
// The guard saw only the tail of the ledger; the block may start earlier.
|
||||
var earliest = await FindOverwriteAsync(stream, ledger, ledger.StartOffset, startPos, token);
|
||||
var earliest = await FindOverwriteAsync(stream, ledger, ledger.StartOffset, startPos, passNowUtc, token);
|
||||
_verifiedBytes += startPos - ledger.StartOffset;
|
||||
_verifyPasses++;
|
||||
if (earliest >= 0) divergence = earliest;
|
||||
@@ -271,7 +272,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
}
|
||||
}
|
||||
|
||||
if (ledger != null) ledger.Record(entry);
|
||||
if (ledger != null) ledger.Record(entry, passNowUtc);
|
||||
var unchanged = rewind != null && rewind.IsUnchanged(entry);
|
||||
if (unchanged) RestoreInvocationMarkers(rewind, entry.Offset);
|
||||
|
||||
@@ -287,7 +288,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
if (unchanged) continue; // unchanged behind the old bookmark — processed before the rewind
|
||||
|
||||
_currentPassLinesAreFresh = passLinesAreFresh && entry.Offset >= oldBookmark;
|
||||
// Behind the old bookmark only changed entries arrive here: fresh when the bytes they replaced
|
||||
// were seen moments ago (RewoundEntryIsFresh), never a calibration anchor.
|
||||
_currentPassLinesAreFresh = entry.Offset >= oldBookmark
|
||||
? passLinesAreFresh
|
||||
: rewind != null && RewoundEntryIsFresh(passLinesAreFresh, rewind.EntryAtRewindPointReplaced, rewind.OldestReplacedSeenUtc, passNowUtc);
|
||||
|
||||
// --- Normal processing (single-line or completed multiline) ---
|
||||
CmTraceLogEntry parsed;
|
||||
|
||||
+55
-11
@@ -62,6 +62,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
public long Offset;
|
||||
public int Length;
|
||||
public ulong Hash;
|
||||
/// <summary>
|
||||
/// When these bytes were last seen as they are (read, seeded or verified unchanged): bytes found different
|
||||
/// at this position later were written after it. Not part of the identity.
|
||||
/// </summary>
|
||||
public DateTime SeenUtc;
|
||||
|
||||
// Identity is (offset, hash): a tail first read unterminated and later completed
|
||||
// keeps its hash but grows by its terminator.
|
||||
@@ -100,11 +105,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
return idx < Entries.Count ? Entries[idx].Offset : -1;
|
||||
}
|
||||
|
||||
public void Record(AssembledEntry e)
|
||||
public void Record(AssembledEntry e, DateTime seenUtc)
|
||||
{
|
||||
var idx = IndexOfFirstAtOrAfter(e.Offset);
|
||||
if (idx < Entries.Count) Entries.RemoveRange(idx, Entries.Count - idx);
|
||||
Entries.Add(new LedgerEntry { Offset = e.Offset, Length = e.Length, Hash = e.Hash });
|
||||
Entries.Add(new LedgerEntry { Offset = e.Offset, Length = e.Length, Hash = e.Hash, SeenUtc = seenUtc });
|
||||
}
|
||||
|
||||
/// <summary>Drops everything from <paramref name="offset"/> on and returns it — the entries a rewind must not process twice.</summary>
|
||||
@@ -197,7 +202,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
ledger.Seeded = true;
|
||||
if (ledger.Entries.Count == 0 && bookmark > 0)
|
||||
await SeedLedgerAsync(filePath, ledger, bookmark, token).ConfigureAwait(false);
|
||||
await SeedLedgerAsync(filePath, ledger, bookmark, nowUtc, token).ConfigureAwait(false);
|
||||
}
|
||||
|
||||
var due = ledger.VerifyRequested || (InContention(nowUtc) && nowUtc >= ledger.NextCadenceVerifyUtc);
|
||||
@@ -213,7 +218,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
|
||||
long divergence;
|
||||
using (var stream = new FileStream(filePath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite))
|
||||
divergence = await FindOverwriteAsync(stream, ledger, from, bookmark, token).ConfigureAwait(false);
|
||||
divergence = await FindOverwriteAsync(stream, ledger, from, bookmark, nowUtc, token).ConfigureAwait(false);
|
||||
if (token.IsCancellationRequested) return -1;
|
||||
|
||||
ledger.VerifyRequested = false;
|
||||
@@ -228,8 +233,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// Re-reads [fromOffset, toOffset) with the read loop's assembler and compares against the
|
||||
/// ledger. Returns the offset of the first entry whose bytes changed — a ledger entry not
|
||||
/// reproduced, or an entry the ledger never had — or -1 when everything reads as before.
|
||||
/// Every entry found unchanged is stamped seen at <paramref name="nowUtc"/>.
|
||||
/// </summary>
|
||||
private async Task<long> FindOverwriteAsync(FileStream stream, FileLedger ledger, long fromOffset, long toOffset, CancellationToken token)
|
||||
private async Task<long> FindOverwriteAsync(FileStream stream, FileLedger ledger, long fromOffset, long toOffset, DateTime nowUtc, CancellationToken token)
|
||||
{
|
||||
var entries = ledger.Entries;
|
||||
var idx = ledger.IndexOfFirstAtOrAfter(fromOffset);
|
||||
@@ -255,6 +261,9 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
if (idx < entries.Count && entries[idx].Offset == e.Offset)
|
||||
{
|
||||
if (entries[idx].Hash != e.Hash) return e.Offset;
|
||||
var confirmed = entries[idx];
|
||||
confirmed.SeenUtc = nowUtc;
|
||||
entries[idx] = confirmed;
|
||||
idx++;
|
||||
continue;
|
||||
}
|
||||
@@ -265,7 +274,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
}
|
||||
|
||||
/// <summary>After a restart the ledger is empty: fingerprint the entries just behind the persisted bookmark without processing them.</summary>
|
||||
private async Task SeedLedgerAsync(string filePath, FileLedger ledger, long bookmark, CancellationToken token)
|
||||
private async Task SeedLedgerAsync(string filePath, FileLedger ledger, long bookmark, DateTime nowUtc, CancellationToken token)
|
||||
{
|
||||
var from = Math.Max(0, bookmark - RestartSeedBytes);
|
||||
using (var stream = new FileStream(filePath, FileMode.Open, FileAccess.Read, FileShare.ReadWrite))
|
||||
@@ -288,7 +297,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
if (assembler.Feed(line, reader.LastLineStart, reader.Position, reader.LastLineTruncated, reader.LastLineHash, out e)
|
||||
== CmTraceEntryAssembler.Outcome.Entry
|
||||
&& e.Offset + e.Length <= bookmark)
|
||||
ledger.Record(e);
|
||||
ledger.Record(e, nowUtc);
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -300,12 +309,17 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// </summary>
|
||||
private sealed class RewindState
|
||||
{
|
||||
public RewindState(string fileName, HashSet<LedgerEntry> unchanged, List<InvocationMarker> markers, InvocationMarker lastPlatformMarker)
|
||||
public RewindState(string fileName, HashSet<LedgerEntry> unchanged, List<InvocationMarker> markers, InvocationMarker lastPlatformMarker, long rewindTo)
|
||||
{
|
||||
FileName = fileName;
|
||||
Unchanged = unchanged;
|
||||
Markers = markers;
|
||||
LastPlatformMarker = lastPlatformMarker;
|
||||
foreach (var replaced in unchanged)
|
||||
{
|
||||
if (replaced.Offset == rewindTo) EntryAtRewindPointReplaced = true;
|
||||
if (!OldestReplacedSeenUtc.HasValue || replaced.SeenUtc < OldestReplacedSeenUtc.Value) OldestReplacedSeenUtc = replaced.SeenUtc;
|
||||
}
|
||||
}
|
||||
|
||||
public string FileName { get; }
|
||||
@@ -315,10 +329,29 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// <summary>The tracker-wide last platform marker, when it was among the set-aside ones.</summary>
|
||||
public InvocationMarker LastPlatformMarker { get; }
|
||||
public int Next { get; set; }
|
||||
/// <summary>The ledger held the entry at the rewind point: the changed bytes lie where something was seen before.</summary>
|
||||
public bool EntryAtRewindPointReplaced { get; }
|
||||
/// <summary>The earliest time any of the replaced bytes was last seen as it was: every changed byte was written after it.</summary>
|
||||
public DateTime? OldestReplacedSeenUtc { get; }
|
||||
|
||||
public bool IsUnchanged(AssembledEntry entry) => Unchanged.Contains(new LedgerEntry { Offset = entry.Offset, Hash = entry.Hash });
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Whether an entry a rewind re-processes (it reads differently than before) is fresh. Its bytes were written after
|
||||
/// the bytes it replaced were last seen as they were — IME stamps a line when it writes it — so when that was at
|
||||
/// most <see cref="FreshLineMaxAge"/> ago the entry's age is bounded like an appended line's and it may anchor
|
||||
/// itself (session d29e27e3: recovered result lines fell back to the agent's stale zone and lost their duration).
|
||||
/// Not fresh when the pass is not (the first pass after a restart never anchors), when the divergence lies in bytes
|
||||
/// the ledger never held (nothing dates them), or when the clock stepped back since.
|
||||
/// </summary>
|
||||
internal static bool RewoundEntryIsFresh(bool passLinesAreFresh, bool entryAtRewindPointReplaced, DateTime? oldestReplacedSeenUtc, DateTime passNowUtc)
|
||||
{
|
||||
if (!passLinesAreFresh || !entryAtRewindPointReplaced || !oldestReplacedSeenUtc.HasValue) return false;
|
||||
var sinceSeen = passNowUtc - oldestReplacedSeenUtc.Value;
|
||||
return sinceSeen >= TimeSpan.Zero && sinceSeen <= FreshLineMaxAge;
|
||||
}
|
||||
|
||||
/// <summary>Moves the bookmark back to the first changed entry; returns what the re-read needs to skip and to give back.</summary>
|
||||
private RewindState ApplyRewind(string filePath, string fileName, FileLedger ledger, long rewindTo, long bookmark)
|
||||
{
|
||||
@@ -341,7 +374,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
_logger.Debug(message);
|
||||
}
|
||||
return new RewindState(fileName, removed, markers, tookLastPlatformMarker ? lastPlatformMarker : null);
|
||||
return new RewindState(fileName, removed, markers, tookLastPlatformMarker ? lastPlatformMarker : null, rewindTo);
|
||||
}
|
||||
|
||||
private long RetentionFloor(string fileName, long bookmark)
|
||||
@@ -380,11 +413,20 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
{
|
||||
public long Offset;
|
||||
public string PolicyId;
|
||||
/// <summary>
|
||||
/// The platform run the start line belongs to: the lines behind it go to that run while it is pending or
|
||||
/// waits for its IME result, and nowhere once it was emitted — never to a later run of the same policy.
|
||||
/// Null only on seeded test markers, which resolve by policy.
|
||||
/// </summary>
|
||||
public string RunId;
|
||||
public bool IsClose;
|
||||
/// <summary>Set on a writer boundary: the platform invocation it closed.</summary>
|
||||
public string ClosedPolicyId;
|
||||
}
|
||||
|
||||
/// <summary>Run id of a start line whose run was emitted already (a late line): owns its lines, matches no live run.</summary>
|
||||
private const string EmittedRunId = "emitted";
|
||||
|
||||
private const string ExecutorLogFileName = "AgentExecutor.log";
|
||||
|
||||
private readonly Dictionary<string, List<InvocationMarker>> _invocationMarkers =
|
||||
@@ -437,7 +479,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
list.Add(marker);
|
||||
}
|
||||
|
||||
private void RecordInvocationMarker(string policyId, bool isClose)
|
||||
private void RecordInvocationMarker(string policyId, bool isClose, string runId = null)
|
||||
{
|
||||
if (_currentEntryOffset < 0) return;
|
||||
var file = _currentSourceFileName ?? TestSourceFileName;
|
||||
@@ -451,6 +493,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
if (!isClose && policyId != null && last.ClosedPolicyId == null)
|
||||
{
|
||||
last.PolicyId = policyId;
|
||||
last.RunId = runId;
|
||||
last.IsClose = false;
|
||||
_lastPlatformMarker = last;
|
||||
_platformMarkerFiles.Add(file);
|
||||
@@ -458,7 +501,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
return;
|
||||
}
|
||||
|
||||
var marker = new InvocationMarker { Offset = _currentEntryOffset, PolicyId = policyId, IsClose = isClose };
|
||||
var marker = new InvocationMarker { Offset = _currentEntryOffset, PolicyId = policyId, RunId = runId, IsClose = isClose };
|
||||
AppendInvocationMarker(list, marker);
|
||||
if (!isClose && policyId != null)
|
||||
{
|
||||
@@ -526,6 +569,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
if (marker == null || marker.IsClose || marker.PolicyId == null) return null;
|
||||
|
||||
ownerPolicyId = marker.PolicyId;
|
||||
if (marker.RunId != null) return FindLivePlatformRun(marker.PolicyId, marker.RunId);
|
||||
ScriptExecutionState state;
|
||||
return _pendingPlatformScripts.TryGetValue(marker.PolicyId, out state) ? state : null;
|
||||
}
|
||||
|
||||
@@ -182,6 +182,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
private readonly Dictionary<string, ScriptExecutionState> _pendingPlatformScripts =
|
||||
new Dictionary<string, ScriptExecutionState>(StringComparer.OrdinalIgnoreCase);
|
||||
|
||||
// Earlier runs of a policy whose next executor run started before IME's result of them was
|
||||
// read (IME re-runs a failed script on later check-ins; the first pass reads all of
|
||||
// AgentExecutor.log before the IME log). Each keeps its own end block until its result
|
||||
// arrives — session eff1b413 lost that and paired the first result with the last run's block.
|
||||
private readonly List<ScriptExecutionState> _parkedPlatformScripts = new List<ScriptExecutionState>();
|
||||
private const int MaxParkedPlatformScripts = 64;
|
||||
|
||||
/// <summary>
|
||||
/// The platform runs this tracker started and emitted, for the registry reconciliation that
|
||||
/// checks them against IME's saved results (D-316). Shared with the registry host's thread.
|
||||
@@ -1191,6 +1198,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
}
|
||||
}
|
||||
|
||||
_parkedPlatformScripts.Clear();
|
||||
if (state.ParkedPlatformScripts != null)
|
||||
{
|
||||
foreach (var parked in state.ParkedPlatformScripts)
|
||||
{
|
||||
if (!string.IsNullOrEmpty(parked?.PolicyId) && _parkedPlatformScripts.Count < MaxParkedPlatformScripts)
|
||||
_parkedPlatformScripts.Add(parked);
|
||||
}
|
||||
}
|
||||
|
||||
_scriptTimeoutSuspectedPosted.Clear();
|
||||
if (state.ScriptTimeoutSuspectedPosted != null)
|
||||
{
|
||||
@@ -1276,6 +1293,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// must survive restarts — see the LoadState comment for the duplicate scenario.
|
||||
PlatformScriptResultEmittedAt = new Dictionary<string, DateTime>(_platformScriptResultEmitted, StringComparer.OrdinalIgnoreCase),
|
||||
PendingPlatformScripts = _pendingPlatformScripts.Values.ToList(),
|
||||
ParkedPlatformScripts = _parkedPlatformScripts.ToList(),
|
||||
ScriptTimeoutSuspectedPosted = _scriptTimeoutSuspectedPosted.ToList(),
|
||||
RecurringScripts = _recurringScripts.ToPersisted(),
|
||||
};
|
||||
|
||||
+4
@@ -151,6 +151,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
// that run from the start of the next one.
|
||||
public Dictionary<string, DateTime> PlatformScriptResultEmittedAt { get; set; }
|
||||
public List<ScriptExecutionState> PendingPlatformScripts { get; set; }
|
||||
// Earlier runs that wait for their IME result while a later run of the same policy is in
|
||||
// flight; a restart between reading AgentExecutor.log and the IME log must keep them. Null on
|
||||
// older state files → none.
|
||||
public List<ScriptExecutionState> ParkedPlatformScripts { get; set; }
|
||||
public List<string> ScriptTimeoutSuspectedPosted { get; set; }
|
||||
|
||||
// Recurring health-script runs collapsed per policy. Saved in the same write as
|
||||
|
||||
+6
-3
@@ -41,9 +41,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.Ime
|
||||
/// Written on the tracker's poll thread, claimed on the registry host's timer thread: every member
|
||||
/// locks, and nothing calls out while holding the lock.
|
||||
/// <para>
|
||||
/// A save belongs to the latest run of its key: IME runs a policy once per batch and saves the
|
||||
/// batch after its last script, so the next run of the same key starts minutes later at the
|
||||
/// earliest. A save is paired only after the tracker completed a pass that started
|
||||
/// A save belongs to the latest run of its key: IME runs a policy at most once per check-in and
|
||||
/// saves after reporting that check-in's batch, so the next run of the key comes with a later
|
||||
/// check-in. (Overlapping check-ins can run a key twice at once; then IME itself shares the key's
|
||||
/// result files and the judge's foreign verdict is the safety net.) A run that waited for its IME
|
||||
/// result while a later run of its key already started is emitted without touching that later
|
||||
/// run's entry. A save is paired only after the tracker completed a pass that started
|
||||
/// <see cref="TrackerCatchUp"/> after the save was seen — every line written before the save, the
|
||||
/// run's start among them, has been read by then, a stalled poll loop included.
|
||||
/// </para>
|
||||
|
||||
+11
-2
@@ -23,11 +23,20 @@ public class ScriptExecutionState
|
||||
public string UserId { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// Identity of one emitted platform-script run, surfaced as <c>runId</c> on the event: what a
|
||||
/// later <c>script_output_reconciliation</c> names when it corrects that run.
|
||||
/// Identity of one platform-script run, given when its slot opens and surfaced as <c>runId</c> on
|
||||
/// the event: the invocation markers bind the run's executor lines to it, and a later
|
||||
/// <c>script_output_reconciliation</c> names it when it corrects that run.
|
||||
/// </summary>
|
||||
public string RunId { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// Source timestamp of the run's AgentExecutor start line (<c>Adding argument powershell with
|
||||
/// value …</c>). Every executor process writes that line once, so a later one for the same
|
||||
/// policy starts the next run, never this one. Null until the line is read, and on state files
|
||||
/// from before the field.
|
||||
/// </summary>
|
||||
public System.DateTime? ExecutorStartedAtUtc { get; set; }
|
||||
|
||||
/// <summary>
|
||||
/// UTC timestamp of the script's first observed start line, taken from the source CMTrace log
|
||||
/// timestamp (so it dates correctly even when the agent replays historic IME log content that
|
||||
|
||||
+7
@@ -366,6 +366,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
public void BackfillRecentHelloWizardStart(int lookbackMinutes)
|
||||
=> _shellCoreTracker?.BackfillRecentHelloWizardStart(lookbackMinutes);
|
||||
|
||||
/// <summary>
|
||||
/// First run only: the update page's records from before the agent started, as telemetry
|
||||
/// and nothing else — see <see cref="ShellCoreTracker.BackfillUpdatePageTelemetry"/>.
|
||||
/// </summary>
|
||||
public void BackfillUpdatePageTelemetry(int lookbackMinutes)
|
||||
=> _shellCoreTracker?.BackfillUpdatePageTelemetry(lookbackMinutes);
|
||||
|
||||
/// <summary>
|
||||
/// sits-d Cloud-PC fix (2026-08-19) — re-check the user-apps-settled AccountSetup
|
||||
/// synthesis after the ESP exit has already been observed. Wired to the IME tracker's
|
||||
|
||||
+77
-20
@@ -18,6 +18,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
public const string PageStopped = "page_stopped";
|
||||
public const string EventName = "event_name";
|
||||
|
||||
/// <summary>
|
||||
/// Not a record: the <c>cxhEvent</c> of the marker <see cref="OobeUpdateTelemetry"/> sends
|
||||
/// once per budget when the event names of a run start staying in agent.log.
|
||||
/// </summary>
|
||||
public const string NamesCapped = "names_capped";
|
||||
|
||||
public OobeUpdatePageRecord(string cxhEvent, int windowsEventId, string page = null, string result = null, string name = null, string value = null)
|
||||
{
|
||||
CxhEvent = cxhEvent;
|
||||
@@ -54,6 +60,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
internal sealed class OobeUpdateTelemetry
|
||||
{
|
||||
internal const int MaxPageEventsPerRun = 150;
|
||||
|
||||
/// <summary>
|
||||
/// Event names the backfills (first run, restart) report per run — their own budget, so
|
||||
/// the records from before the agent started cannot spend the live page's.
|
||||
/// </summary>
|
||||
internal const int MaxBackfillPageEventsPerRun = 150;
|
||||
|
||||
internal const int MaxPageEventsPerKey = 3;
|
||||
internal const int MaxStateEventsPerRun = 6;
|
||||
internal const int MaxStateLineLength = 1000;
|
||||
@@ -67,7 +80,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
public const string AgentStop = "agent_stop";
|
||||
}
|
||||
|
||||
private const string Source = "ShellCoreTracker";
|
||||
private const string Source = Constants.EventSources.ShellCoreTracker;
|
||||
|
||||
private readonly string _sessionId;
|
||||
private readonly string _tenantId;
|
||||
@@ -77,8 +90,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
|
||||
private readonly object _lock = new object();
|
||||
private readonly Dictionary<string, int> _pageEventsPerKey = new Dictionary<string, int>(StringComparer.Ordinal);
|
||||
private int _pageEvents;
|
||||
private bool _pageCapLogged;
|
||||
private int _livePageEvents;
|
||||
private int _backfillPageEvents;
|
||||
private bool _liveCapReported;
|
||||
private bool _backfillCapReported;
|
||||
private int _stateEvents;
|
||||
private string _lastStateContent;
|
||||
|
||||
@@ -99,9 +114,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
/// <summary>
|
||||
/// One <c>oobe_update_page</c> per update-page record, at most
|
||||
/// <see cref="MaxPageEventsPerKey"/> per page/name — a page that logs the same name in a
|
||||
/// loop cannot flood the session. Event names also share <see cref="MaxPageEventsPerRun"/>
|
||||
/// per run; a page start or stop is outside that budget, because the time attribution
|
||||
/// reads the update's span from them. True when the record was reported.
|
||||
/// loop cannot flood the session. Event names also share a budget per run: live ones
|
||||
/// <see cref="MaxPageEventsPerRun"/>, backfilled ones <see cref="MaxBackfillPageEventsPerRun"/>;
|
||||
/// the first name over a budget sends the <see cref="OobeUpdatePageRecord.NamesCapped"/>
|
||||
/// marker. A page start or stop is outside the budgets, because the time attribution reads
|
||||
/// the update's span from them. True when the record was reported.
|
||||
/// </summary>
|
||||
public bool ReportPage(OobeUpdatePageRecord record, DateTime occurredAtUtc, bool isBackfill)
|
||||
{
|
||||
@@ -109,23 +126,37 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
|
||||
var isEventName = record.CxhEvent == OobeUpdatePageRecord.EventName;
|
||||
var key = $"{record.CxhEvent}:{record.Page ?? record.Name}";
|
||||
int occurrence;
|
||||
var budget = isBackfill ? MaxBackfillPageEventsPerRun : MaxPageEventsPerRun;
|
||||
var occurrence = 0;
|
||||
bool overBudget;
|
||||
var firstOverBudget = false;
|
||||
lock (_lock)
|
||||
{
|
||||
if (isEventName && _pageEvents >= MaxPageEventsPerRun)
|
||||
overBudget = isEventName && (isBackfill ? _backfillPageEvents : _livePageEvents) >= budget;
|
||||
if (overBudget)
|
||||
{
|
||||
if (!_pageCapLogged)
|
||||
{
|
||||
_pageCapLogged = true;
|
||||
_logger.Info($"OOBE update page telemetry: {MaxPageEventsPerRun} event names reached, the rest of this run stays in agent.log");
|
||||
}
|
||||
return false;
|
||||
firstOverBudget = isBackfill ? !_backfillCapReported : !_liveCapReported;
|
||||
if (isBackfill) _backfillCapReported = true;
|
||||
else _liveCapReported = true;
|
||||
}
|
||||
_pageEventsPerKey.TryGetValue(key, out occurrence);
|
||||
if (occurrence >= MaxPageEventsPerKey) return false;
|
||||
occurrence++;
|
||||
_pageEventsPerKey[key] = occurrence;
|
||||
if (isEventName) _pageEvents++;
|
||||
else
|
||||
{
|
||||
_pageEventsPerKey.TryGetValue(key, out occurrence);
|
||||
if (occurrence >= MaxPageEventsPerKey) return false;
|
||||
occurrence++;
|
||||
_pageEventsPerKey[key] = occurrence;
|
||||
if (isEventName)
|
||||
{
|
||||
if (isBackfill) _backfillPageEvents++;
|
||||
else _livePageEvents++;
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
if (overBudget)
|
||||
{
|
||||
if (firstOverBudget) ReportNamesCapped(budget, occurredAtUtc, isBackfill);
|
||||
return false;
|
||||
}
|
||||
|
||||
var data = new Dictionary<string, object>
|
||||
@@ -141,6 +172,32 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
if (record.Name != null) data["name"] = record.Name;
|
||||
if (record.Value != null) data["value"] = record.Value;
|
||||
|
||||
return EmitPage(occurredAtUtc, DescribePage(record), data);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// The marker that a budget is spent: from here on this run's live or backfilled event
|
||||
/// names stay in agent.log, so a name missing from the session proves nothing — the
|
||||
/// analyze rules that read an absent name check for this marker first.
|
||||
/// </summary>
|
||||
private void ReportNamesCapped(int budget, DateTime occurredAtUtc, bool isBackfill)
|
||||
{
|
||||
var kind = isBackfill ? "backfilled " : string.Empty;
|
||||
_logger.Info($"OOBE update page telemetry: {budget} {kind}event names reached, the rest of this run stays in agent.log");
|
||||
|
||||
EmitPage(occurredAtUtc,
|
||||
$"OOBE update page: {budget} {kind}event names reached, later ones of this agent run are not sent",
|
||||
new Dictionary<string, object>
|
||||
{
|
||||
{ "cxhEvent", OobeUpdatePageRecord.NamesCapped },
|
||||
{ "eventTime", occurredAtUtc.ToString("o") },
|
||||
{ "backfill", isBackfill },
|
||||
{ "limit", budget },
|
||||
});
|
||||
}
|
||||
|
||||
private bool EmitPage(DateTime occurredAtUtc, string message, Dictionary<string, object> data)
|
||||
{
|
||||
try
|
||||
{
|
||||
_post.Emit(new EnrollmentEvent
|
||||
@@ -152,7 +209,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
Severity = EventSeverity.Debug,
|
||||
Source = Source,
|
||||
Phase = EnrollmentPhase.Unknown,
|
||||
Message = DescribePage(record),
|
||||
Message = message,
|
||||
Data = data,
|
||||
ImmediateUpload = false,
|
||||
});
|
||||
|
||||
+111
-33
@@ -51,6 +51,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
/// </summary>
|
||||
internal const int BackfillLookbackMaxMinutes = 360;
|
||||
|
||||
/// <summary>
|
||||
/// Lookback of the first run's update page backfill (<see cref="BackfillUpdatePageTelemetry"/>)
|
||||
/// — the hour the servicing watcher reads back, so the page's records and the update's
|
||||
/// servicing steps cover the same time.
|
||||
/// </summary>
|
||||
internal const int UpdatePageBackfillLookbackMinutes = 60;
|
||||
|
||||
private static readonly HashSet<int> TrackedShellCoreEventIds = new HashSet<int>
|
||||
{
|
||||
EventId_ShellCore_WebAppStarted,
|
||||
@@ -100,7 +107,10 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
private bool _espExitDetected;
|
||||
private bool _whiteGloveDetected;
|
||||
private bool _helloWizardStartDetected;
|
||||
private string _lastCxhPage; // 62405 names no page, it ends the last one started
|
||||
// 62405 names no page, it ends the last one started. The live watcher's page; a backfill
|
||||
// moves it only with a newer record (see ObserveCxhRecord).
|
||||
private string _lastCxhPage;
|
||||
private long _lastCxhPageRecordId = -1;
|
||||
private readonly object _stateLock = new object();
|
||||
|
||||
/// <summary>
|
||||
@@ -194,7 +204,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
// WhiteGlove success — indistinguishable on the backend from a real no-signal
|
||||
// enrollment. Surface it as one-shot telemetry.
|
||||
CollectorDegradationReporter.Report(_post, _sessionId, _tenantId,
|
||||
collectorName: "ShellCoreTracker", reason: "watcher_arm_failed", ex: ex);
|
||||
collectorName: Constants.EventSources.ShellCoreTracker, reason: "watcher_arm_failed", ex: ex);
|
||||
}
|
||||
}
|
||||
|
||||
@@ -258,7 +268,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
IReadOnlyList<string> properties = null)
|
||||
{
|
||||
var fields = ReadCxhFields(eventId, description, properties);
|
||||
ObserveCxhRecord(eventId, fields, timestamp, isBackfill, recordId);
|
||||
ObserveCxhRecord(eventId, fields, timestamp, isBackfill, recordId, backfillPage: null);
|
||||
if (eventId == EventId_ShellCore_WebAppStopped || eventId == EventId_ShellCore_WebAppEventName) return;
|
||||
|
||||
string eventType;
|
||||
@@ -459,31 +469,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
{
|
||||
try
|
||||
{
|
||||
var lookbackMs = ClampLookbackMinutes(lookbackMinutes) * 60 * 1000;
|
||||
var query = new EventLogQuery(
|
||||
ShellCoreEventLogChannel,
|
||||
PathType.LogName,
|
||||
$"*[System[{WatchedEventIdsXPath} and TimeCreated[timediff(@SystemTime) <= {lookbackMs}]]]");
|
||||
|
||||
var records = new List<ShellCoreRecord>();
|
||||
using (var reader = new EventLogReader(query))
|
||||
{
|
||||
for (EventRecord record = reader.ReadEvent(); record != null; record = reader.ReadEvent())
|
||||
{
|
||||
using (record)
|
||||
{
|
||||
var description = record.FormatDescription() ?? "";
|
||||
// Preserve the historical event time across backfill so subscribers
|
||||
// (EspAndHelloTrackerAdapter) can stamp signals with the source time
|
||||
// rather than collapsing to wall-clock-now.
|
||||
var timestamp = (record.TimeCreated ?? DateTime.UtcNow).ToUniversalTime();
|
||||
records.Add(new ShellCoreRecord(record.Id, description, timestamp,
|
||||
record.RecordId ?? -1, ReadProperties(record)));
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
ReplayBackfillRecords(records);
|
||||
ReplayBackfillRecords(ReadRecentRecords(lookbackMinutes));
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
@@ -491,6 +477,76 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// The FIRST run's counterpart of the restart replay, for telemetry only: the update
|
||||
/// page's records of the last <paramref name="lookbackMinutes"/> minutes (clamped like
|
||||
/// the replay) become <c>oobe_update_page</c> rows. The agent is installed during the ESP
|
||||
/// and can start after the update page began; without this its time attribution has no
|
||||
/// page start to begin the update with (field: a first run 7 min after the update's
|
||||
/// restart saw neither the page start nor the update's first half).
|
||||
/// <para>
|
||||
/// Nothing else is looked at: no Hello-wizard replay, no ESP exit or failure count, no
|
||||
/// <c>agent_trace</c>. The first run keeps its decision behaviour exactly — see
|
||||
/// <see cref="ReplayBackfillRecords"/> for why no replayed record may reach the engine and
|
||||
/// <c>DefaultComponentFactory.ResolveEspExitBackfillLookbackMinutes</c> for why the first
|
||||
/// run has no replay. No boot bound: an agent that first starts after the update's restart
|
||||
/// is exactly the case to cover; the RecordId watermark keeps it from re-sending.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public void BackfillUpdatePageTelemetry(int lookbackMinutes)
|
||||
{
|
||||
try
|
||||
{
|
||||
ReplayUpdatePageTelemetry(ReadRecentRecords(lookbackMinutes));
|
||||
}
|
||||
catch (Exception ex)
|
||||
{
|
||||
_logger.Warning($"Shell-Core update page backfill failed: {ex.Message}");
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>The update page telemetry of a chronological batch of Shell-Core records — nothing else.</summary>
|
||||
internal void ReplayUpdatePageTelemetry(IReadOnlyList<ShellCoreRecord> records)
|
||||
{
|
||||
if (records == null || records.Count == 0) return;
|
||||
|
||||
var page = new BackfillPageCursor();
|
||||
foreach (var record in records)
|
||||
{
|
||||
var fields = ReadCxhFields(record.Id, record.Description ?? string.Empty, record.Properties);
|
||||
ObserveCxhRecord(record.Id, fields, record.OccurredAtUtc, isBackfill: true, recordId: record.RecordId, backfillPage: page);
|
||||
}
|
||||
}
|
||||
|
||||
/// <summary>The watched Shell-Core records of the last minutes, oldest first, with their original event time.</summary>
|
||||
private List<ShellCoreRecord> ReadRecentRecords(int lookbackMinutes)
|
||||
{
|
||||
var lookbackMs = ClampLookbackMinutes(lookbackMinutes) * 60 * 1000;
|
||||
var query = new EventLogQuery(
|
||||
ShellCoreEventLogChannel,
|
||||
PathType.LogName,
|
||||
$"*[System[{WatchedEventIdsXPath} and TimeCreated[timediff(@SystemTime) <= {lookbackMs}]]]");
|
||||
|
||||
var records = new List<ShellCoreRecord>();
|
||||
using (var reader = new EventLogReader(query))
|
||||
{
|
||||
for (EventRecord record = reader.ReadEvent(); record != null; record = reader.ReadEvent())
|
||||
{
|
||||
using (record)
|
||||
{
|
||||
var description = record.FormatDescription() ?? "";
|
||||
// Preserve the historical event time across backfill so subscribers
|
||||
// (EspAndHelloTrackerAdapter) can stamp signals with the source time
|
||||
// rather than collapsing to wall-clock-now.
|
||||
var timestamp = (record.TimeCreated ?? DateTime.UtcNow).ToUniversalTime();
|
||||
records.Add(new ShellCoreRecord(record.Id, description, timestamp,
|
||||
record.RecordId ?? -1, ReadProperties(record)));
|
||||
}
|
||||
}
|
||||
}
|
||||
return records;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Replays a chronological batch of Shell-Core records. <b>Only the Hello-wizard start
|
||||
/// (62404) is replayed.</b> ESP exits and ESP failures (62407) are counted and reported,
|
||||
@@ -546,12 +602,13 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
var skippedFailures = 0;
|
||||
DateTime? oldestSkipped = null;
|
||||
DateTime? newestSkipped = null;
|
||||
var page = new BackfillPageCursor();
|
||||
|
||||
foreach (var record in records)
|
||||
{
|
||||
var description = record.Description ?? string.Empty;
|
||||
var fields = ReadCxhFields(record.Id, description, record.Properties);
|
||||
ObserveCxhRecord(record.Id, fields, record.OccurredAtUtc, isBackfill: true, recordId: record.RecordId);
|
||||
ObserveCxhRecord(record.Id, fields, record.OccurredAtUtc, isBackfill: true, recordId: record.RecordId, backfillPage: page);
|
||||
|
||||
if (record.Id == EventId_ShellCore_WebAppStarted)
|
||||
{
|
||||
@@ -594,7 +651,7 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
TenantId = _tenantId,
|
||||
EventType = Constants.EventTypes.AgentTrace,
|
||||
Severity = EventSeverity.Info,
|
||||
Source = "ShellCoreTracker",
|
||||
Source = Constants.EventSources.ShellCoreTracker,
|
||||
Phase = EnrollmentPhase.Unknown,
|
||||
Message =
|
||||
$"Shell-Core replay skipped {skippedExits} ESP exit(s) and {skippedFailures} ESP failure(s) " +
|
||||
@@ -662,6 +719,12 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
// CloudExperienceHost navigation: breadcrumbs and OOBE update page telemetry (D-310)
|
||||
// =====================================================================
|
||||
|
||||
/// <summary>The last page started within one backfill batch.</summary>
|
||||
private sealed class BackfillPageCursor
|
||||
{
|
||||
public string Page;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Writes one agent.log line per CloudExperienceHost page start/stop and per update-page
|
||||
/// event name, so a diagnostics package shows the OOBE navigation. Records of the update
|
||||
@@ -669,8 +732,16 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
/// are also reported as <c>oobe_update_page</c> — once across agent runs, by RecordId — and
|
||||
/// at the page's live start and stop the registry state behind it as
|
||||
/// <c>oobe_update_state</c>. No decision.
|
||||
/// <para>
|
||||
/// A stop (62405) belongs to the page started last. A backfill batch
|
||||
/// (<paramref name="backfillPage"/>) reads records older than the live watcher's, which is
|
||||
/// armed first, so it keeps its own last page; it moves the live watcher's only with a
|
||||
/// record of a higher RecordId — a replayed older start must not take over the next live
|
||||
/// stop, and a first run's live stop still finds the page that started before the agent.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
private void ObserveCxhRecord(int eventId, CxhFields fields, DateTime occurredAtUtc, bool isBackfill, long recordId)
|
||||
private void ObserveCxhRecord(int eventId, CxhFields fields, DateTime occurredAtUtc, bool isBackfill, long recordId,
|
||||
BackfillPageCursor backfillPage)
|
||||
{
|
||||
try
|
||||
{
|
||||
@@ -678,8 +749,15 @@ namespace AutopilotMonitor.Agent.V2.Core.Monitoring.Enrollment.SystemSignals
|
||||
lock (_stateLock)
|
||||
{
|
||||
if (eventId == EventId_ShellCore_WebAppStarted && fields.Primary != null)
|
||||
_lastCxhPage = fields.Primary;
|
||||
page = _lastCxhPage;
|
||||
{
|
||||
if (backfillPage != null) backfillPage.Page = fields.Primary;
|
||||
if (backfillPage == null || (recordId >= 0 && recordId > _lastCxhPageRecordId))
|
||||
{
|
||||
_lastCxhPage = fields.Primary;
|
||||
if (recordId >= 0) _lastCxhPageRecordId = recordId;
|
||||
}
|
||||
}
|
||||
page = backfillPage != null ? backfillPage.Page : _lastCxhPage;
|
||||
}
|
||||
|
||||
var crumb = FormatCxhBreadcrumb(eventId, fields, page);
|
||||
|
||||
@@ -142,6 +142,11 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
/// replayed 62407 cannot be placed in time; see
|
||||
/// <c>ShellCoreTracker.ReplayBackfillRecords</c>.
|
||||
/// </para>
|
||||
/// <para>
|
||||
/// The first run reads the last hour for the OOBE update page telemetry instead — no
|
||||
/// replay, nothing that reaches the decision engine; see
|
||||
/// <c>ShellCoreTracker.BackfillUpdatePageTelemetry</c>.
|
||||
/// </para>
|
||||
/// </summary>
|
||||
public void Start()
|
||||
{
|
||||
@@ -149,6 +154,8 @@ namespace AutopilotMonitor.Agent.V2.Core.Orchestration
|
||||
|
||||
if (_espExitBackfillLookbackMinutes > 0)
|
||||
_tracker.BackfillRecentHelloWizardStart(_espExitBackfillLookbackMinutes);
|
||||
else
|
||||
_tracker.BackfillUpdatePageTelemetry(ShellCoreTracker.UpdatePageBackfillLookbackMinutes);
|
||||
}
|
||||
|
||||
public void Stop() => _tracker.Stop();
|
||||
|
||||
@@ -0,0 +1,481 @@
|
||||
using AutopilotMonitor.Functions.Services;
|
||||
using AutopilotMonitor.Shared.DataAccess;
|
||||
using AutopilotMonitor.Shared.Models;
|
||||
using Microsoft.Extensions.Logging.Abstractions;
|
||||
using Moq;
|
||||
|
||||
namespace AutopilotMonitor.Functions.Tests;
|
||||
|
||||
/// <summary>
|
||||
/// The OOBE quality update page (oobe_update_page, D-310) — pins the built-in analyze rules for
|
||||
/// the update that did not happen:
|
||||
/// - ANALYZE-DEV-013: the page reported a failed download or install and no install success
|
||||
/// (field shapes e7551b82, cb1992b8). Only the explicit failure names count: an update that
|
||||
/// installed logs downloadInstallFailureHelper and a start timeout too (e4ecd6f8).
|
||||
/// - ANALYZE-DEV-014: nothing offered to an out-of-date device whose page counts an earlier
|
||||
/// failure, without a failure in this session (b2d9f12c).
|
||||
/// - ANALYZE-DEV-015: the scan started and the page ended without a scan result (c5b20dfa).
|
||||
/// Every absence condition is vetoed by the agent's names_capped marker. Sequences follow the
|
||||
/// field sessions of 2026-10-03..05 (synthetic times, no customer data); a session never fires
|
||||
/// two of the three.
|
||||
/// </summary>
|
||||
public class OobeUpdateRuleTests
|
||||
{
|
||||
private const string TenantId = "a1b2c3d4-e5f6-7890-abcd-ef1234567890";
|
||||
private const string SessionId = "11111111-2222-3333-4444-555555555555";
|
||||
|
||||
private static readonly DateTime T0 = new(2026, 10, 3, 16, 56, 59, DateTimeKind.Utc);
|
||||
|
||||
private const string DownloadFailed = "SdxWebAppCloudNDUP_processStatusChangeFromHandler_downloadFailedError";
|
||||
private const string InstallFailed = "SdxWebAppCloudNDUP_processStatusChangeFromHandler_installFailedError";
|
||||
private const string CommitFailed = "ExpeditedUpdate_commitExpeditionDownloadInstallAsyncFailure";
|
||||
|
||||
private static readonly string[] RuleIds = { "ANALYZE-DEV-013", "ANALYZE-DEV-014", "ANALYZE-DEV-015" };
|
||||
|
||||
// ── the rules ───────────────────────────────────────────────────────────
|
||||
|
||||
[Theory]
|
||||
[InlineData("ANALYZE-DEV-013")]
|
||||
[InlineData("ANALYZE-DEV-014")]
|
||||
[InlineData("ANALYZE-DEV-015")]
|
||||
public void Rules_are_enabled_warnings_that_never_fail_the_session(string ruleId)
|
||||
{
|
||||
var rule = Rule(ruleId);
|
||||
Assert.True(rule.Enabled);
|
||||
Assert.Equal("warning", rule.Severity);
|
||||
Assert.Equal("device", rule.Category);
|
||||
Assert.False(rule.MarkSessionAsFailedDefault); // the enrollment continues without the update
|
||||
}
|
||||
|
||||
// ── ANALYZE-DEV-013: failed ─────────────────────────────────────────────
|
||||
|
||||
[Fact]
|
||||
public async Task DEV_013_fires_on_a_failed_download_and_names_the_failure()
|
||||
{
|
||||
var outcome = await RunAsync(FailedDownload());
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
Assert.Equal("ANALYZE-DEV-013", result.RuleId);
|
||||
Assert.Equal(DownloadFailed, Value(result, "update_failure")); // {{update_failure}}
|
||||
Assert.Equal("fail", Value(result, "update_page_failed"));
|
||||
Assert.Equal(85, result.ConfidenceScore);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task DEV_013_fires_when_the_update_is_skipped_after_the_failure()
|
||||
{
|
||||
var outcome = await RunAsync(FailureThenSkip());
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
Assert.Equal("ANALYZE-DEV-013", result.RuleId);
|
||||
Assert.Equal(DownloadFailed, Value(result, "update_failure"));
|
||||
Assert.Equal("CloudNDUPSkipDownloadInstallButtonClicked", Value(result, "update_skipped"));
|
||||
}
|
||||
|
||||
[Theory]
|
||||
[InlineData(InstallFailed)]
|
||||
[InlineData(CommitFailed)]
|
||||
public async Task DEV_013_fires_on_every_explicit_failure_name(string failureName)
|
||||
{
|
||||
var events = Visit(days: 120, previousFailures: 0);
|
||||
events.AddRange(new[] { Name("ExpeditedUpdate_getUpdateResultsSucceeded"), Name(failureName), PageStop("OobeNDUP", "fail") });
|
||||
|
||||
var result = Assert.Single((await RunAsync(events)).Results);
|
||||
Assert.Equal(failureName, Value(result, "update_failure"));
|
||||
}
|
||||
|
||||
[Theory]
|
||||
[InlineData(true)]
|
||||
[InlineData(false)]
|
||||
public async Task DEV_013_stays_silent_on_an_update_that_installed_despite_the_failure_helper(bool buildChangeObserved)
|
||||
{
|
||||
// Field shape e4ecd6f8: the failure helper and a start timeout after "restart required",
|
||||
// then the update installed — with or without the build change on record.
|
||||
var events = InstalledDespiteFailureHelper();
|
||||
if (!buildChangeObserved) events.RemoveAll(e => e.EventType == "os_build_changed");
|
||||
|
||||
Assert.Empty((await RunAsync(events)).Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task DEV_013_stays_silent_when_a_retry_installed_the_update()
|
||||
{
|
||||
var events = FailedDownload();
|
||||
events.AddRange(new[]
|
||||
{
|
||||
PageStart("OobeNDUP"),
|
||||
Name("ExpeditedUpdate_commitExpeditionDownloadInstallAsyncStarted"),
|
||||
Name("SdxWebAppCloudNDUP_processStatusChangeFromHandler_installSucceededRebootRequired_lcu"),
|
||||
});
|
||||
|
||||
Assert.Empty((await RunAsync(events)).Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task DEV_013_is_vetoed_by_an_os_build_change()
|
||||
{
|
||||
var events = FailedDownload();
|
||||
events.Add(OsBuildChanged());
|
||||
|
||||
Assert.Empty((await RunAsync(events)).Results);
|
||||
}
|
||||
|
||||
// ── ANALYZE-DEV-014: not offered after an earlier failure ───────────────
|
||||
|
||||
[Fact]
|
||||
public async Task DEV_014_fires_when_nothing_is_offered_after_an_earlier_failure()
|
||||
{
|
||||
var outcome = await RunAsync(NothingOfferedAfterFailure());
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
Assert.Equal("ANALYZE-DEV-014", result.RuleId);
|
||||
Assert.Equal("137", Value(result, "days_out_of_date")); // {{days_out_of_date}}
|
||||
Assert.Equal("1", Value(result, "previous_failures")); // {{previous_failures}}
|
||||
}
|
||||
|
||||
[Theory]
|
||||
[InlineData(0, 1)] // the device is current: nothing to offer
|
||||
[InlineData(137, 0)] // no earlier failure on record
|
||||
public async Task DEV_014_stays_silent_without_both_the_backlog_and_the_earlier_failure(int days, int previousFailures)
|
||||
{
|
||||
var events = Visit(days, previousFailures);
|
||||
events.AddRange(new[]
|
||||
{
|
||||
Name("ExpeditedUpdate_getUpdateResultsSucceeded"),
|
||||
Name("SdxWebAppCloudNDUP_updateManager_processUpdatesMetadata_osUpdatesWithNDUPPI", "false"),
|
||||
PageStop("OobeNDUP", "cancel"),
|
||||
});
|
||||
|
||||
Assert.Empty((await RunAsync(events)).Results);
|
||||
}
|
||||
|
||||
// ── ANALYZE-DEV-015: scan without a result ──────────────────────────────
|
||||
|
||||
[Fact]
|
||||
public async Task DEV_015_fires_when_the_page_ends_without_a_scan_result()
|
||||
{
|
||||
var outcome = await RunAsync(ScanWithoutResult());
|
||||
|
||||
var result = Assert.Single(outcome.Results);
|
||||
Assert.Equal("ANALYZE-DEV-015", result.RuleId);
|
||||
Assert.Equal("438", Value(result, "days_out_of_date"));
|
||||
Assert.Equal("page_stopped", Value(result, "update_page_ended"));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task DEV_015_stays_silent_while_the_page_still_runs()
|
||||
{
|
||||
// The session ended during the scan: no page end, so no claim that the page gave up.
|
||||
var events = ScanWithoutResult();
|
||||
events.RemoveAll(e => e.EventType == "oobe_update_page" && (string)e.Data["cxhEvent"] == "page_stopped");
|
||||
|
||||
Assert.Empty((await RunAsync(events)).Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task DEV_015_stays_silent_when_the_agent_missed_the_scan_start()
|
||||
{
|
||||
// A late agent sees the page end but not the scan: the missing result proves nothing.
|
||||
var events = ScanWithoutResult();
|
||||
events.RemoveAll(e => e.EventType == "oobe_update_page" && (e.Data.TryGetValue("name", out var n) ? (string)n : "").StartsWith("ExpeditedUpdate_startWUScan"));
|
||||
|
||||
Assert.Empty((await RunAsync(events)).Results);
|
||||
}
|
||||
|
||||
// ── shared vetoes and the sessions that fire nothing ────────────────────
|
||||
|
||||
[Theory]
|
||||
[MemberData(nameof(FiringShapes))]
|
||||
public async Task The_names_capped_marker_vetoes_every_rule(string shape)
|
||||
{
|
||||
// Once the agent capped the page's names, a missing success or scan result proves nothing.
|
||||
var events = Shapes[shape]();
|
||||
events.Add(NamesCapped());
|
||||
|
||||
Assert.Empty((await RunAsync(events)).Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task A_page_the_policy_switched_off_fires_nothing()
|
||||
{
|
||||
var events = new List<EnrollmentEvent>
|
||||
{
|
||||
PageStart("OobeNDUP"),
|
||||
Name("ExpeditedUpdate_isNDUPAllowedByCSPSucceeded", "false"),
|
||||
PageStop("OobeNDUP", "cancel"),
|
||||
PageStart("RebootNDUP"),
|
||||
PageStop("RebootNDUP", "success"),
|
||||
};
|
||||
|
||||
Assert.Empty((await RunAsync(events)).Results);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public async Task An_installed_update_fires_nothing()
|
||||
{
|
||||
Assert.Empty((await RunAsync(Installed())).Results);
|
||||
}
|
||||
|
||||
[Theory]
|
||||
[MemberData(nameof(AllShapes))]
|
||||
public async Task No_session_fires_more_than_one_of_the_three(string shape)
|
||||
{
|
||||
var outcome = await RunAsync(Shapes[shape]());
|
||||
|
||||
Assert.True(outcome.Results.Count <= 1, $"{shape}: {string.Join(", ", outcome.Results.Select(r => r.RuleId))}");
|
||||
}
|
||||
|
||||
// ── session shapes (field sessions, synthetic times) ────────────────────
|
||||
|
||||
private static readonly Dictionary<string, Func<List<EnrollmentEvent>>> Shapes = new()
|
||||
{
|
||||
["failed_download"] = FailedDownload,
|
||||
["failure_then_skip"] = FailureThenSkip,
|
||||
["installed_despite_failure_helper"] = InstalledDespiteFailureHelper,
|
||||
["nothing_offered_after_failure"] = NothingOfferedAfterFailure,
|
||||
["scan_without_result"] = ScanWithoutResult,
|
||||
["installed"] = Installed,
|
||||
};
|
||||
|
||||
public static IEnumerable<object[]> AllShapes() => Shapes.Keys.Select(k => new object[] { k });
|
||||
|
||||
public static IEnumerable<object[]> FiringShapes() =>
|
||||
new[] { "failed_download", "failure_then_skip", "nothing_offered_after_failure", "scan_without_result" }
|
||||
.Select(k => new object[] { k });
|
||||
|
||||
/// <summary>The names every visit logs before its scan.</summary>
|
||||
private static List<EnrollmentEvent> Visit(int days, int previousFailures) => new()
|
||||
{
|
||||
PageStart("OobeNDUP"),
|
||||
Name("ExpeditedUpdate_isNDUPAllowedByCSPSucceeded", "true"),
|
||||
Name("ExpeditedUpdate_getDaysOutOfDateSucceeded", days.ToString()),
|
||||
Name("SdxWebAppCloudNDUP_initialize_NDUPInstallCanceledInOptOut", "false"),
|
||||
Name("SdxWebAppCloudNDUP_initialize_NDUPDownloadInstallPreviousFailureCount", previousFailures.ToString()),
|
||||
Name("ExpeditedUpdate_startWUScanStarted"),
|
||||
Name("ExpeditedUpdate_startWUScanStartedSuccedded"),
|
||||
};
|
||||
|
||||
/// <summary>e7551b82: only the servicing stack staged, the download failed after 25 min; the second visit found nothing to offer.</summary>
|
||||
private static List<EnrollmentEvent> FailedDownload()
|
||||
{
|
||||
var events = Visit(days: 136, previousFailures: 0);
|
||||
events.AddRange(new[]
|
||||
{
|
||||
Name("ExpeditedUpdate_getUpdateResultsStarted"),
|
||||
Name("ExpeditedUpdate_getUpdateResultsSucceeded"),
|
||||
Name("SdxWebAppCloudNDUP_updateManager_processUpdatesMetadata_osUpdatesWithNDUPPI"), // a list: no safe value
|
||||
Name("ExpeditedUpdate_commitExpeditionDownloadInstallAsyncStarted"),
|
||||
Name(DownloadFailed),
|
||||
Name(CommitFailed),
|
||||
Name("SdxWebAppCloudNDUP_downloadInstallFailureHelper"),
|
||||
PageStop("OobeNDUP", "fail"),
|
||||
PageStart("RebootNDUP"),
|
||||
});
|
||||
events.AddRange(Visit(days: 137, previousFailures: 1));
|
||||
events.AddRange(new[]
|
||||
{
|
||||
Name("ExpeditedUpdate_getUpdateResultsSucceeded"),
|
||||
Name("SdxWebAppCloudNDUP_updateManager_processUpdatesMetadata_osUpdatesWithNDUPPI", "false"),
|
||||
PageStop("OobeNDUP", "cancel"),
|
||||
PageStart("RebootNDUP"),
|
||||
PageStop("RebootNDUP", "success"),
|
||||
});
|
||||
return events;
|
||||
}
|
||||
|
||||
/// <summary>cb1992b8: visit 1 failed; visit 2 downloaded again and someone selected Skip before the install.</summary>
|
||||
private static List<EnrollmentEvent> FailureThenSkip()
|
||||
{
|
||||
var events = Visit(days: 438, previousFailures: 0);
|
||||
events.AddRange(new[]
|
||||
{
|
||||
Name("ExpeditedUpdate_getUpdateResultsSucceeded"),
|
||||
Name("ExpeditedUpdate_commitExpeditionDownloadInstallAsyncStarted"),
|
||||
Name(DownloadFailed),
|
||||
Name(CommitFailed),
|
||||
Name(InstallFailed),
|
||||
PageStop("OobeNDUP", "fail"),
|
||||
PageStart("RebootNDUP"),
|
||||
});
|
||||
events.AddRange(Visit(days: 438, previousFailures: 1));
|
||||
events.AddRange(new[]
|
||||
{
|
||||
Name("ExpeditedUpdate_getUpdateResultsSucceeded"),
|
||||
Name("SdxWebAppCloudNDUP_updateManager_processUpdatesMetadata_osUpdatesWithNDUPPI"),
|
||||
Name("ExpeditedUpdate_commitExpeditionDownloadInstallAsyncStarted"),
|
||||
Name("CloudNDUPOptoutLinkClicked", "0"),
|
||||
Name("SdxWebAppCloudNDUP_processStatusChangeFromHandler_downloadSucceeded"),
|
||||
Name("SdxWebAppCloudNDUP_updateUSOProgressBar_DownloadPhase_progress100"),
|
||||
Name("SdxWebAppCloudNDUP_manageProgressBars_waitingForInstallStartError"),
|
||||
Name("CloudNDUPSkipDownloadInstallButtonClicked", "0"),
|
||||
PageStop("OobeNDUP", "cancel"),
|
||||
PageStart("RebootNDUP"),
|
||||
PageStop("RebootNDUP", "success"),
|
||||
});
|
||||
return events;
|
||||
}
|
||||
|
||||
/// <summary>e4ecd6f8: the failure helper and a start timeout after "restart required" — the update installed after three restarts.</summary>
|
||||
private static List<EnrollmentEvent> InstalledDespiteFailureHelper()
|
||||
{
|
||||
var events = Visit(days: 99, previousFailures: 0);
|
||||
events.AddRange(new[]
|
||||
{
|
||||
Name("ExpeditedUpdate_getUpdateResultsSucceeded"),
|
||||
Name("ExpeditedUpdate_commitExpeditionDownloadInstallAsyncStarted"),
|
||||
Name("SdxWebAppCloudNDUP_updateUSOProgressBar_installPhase_progress100"),
|
||||
Name("SdxWebAppCloudNDUP_downloadInstallFailureHelper"),
|
||||
Name("SdxWebAppCloudNDUP_startEventArrivalTimeout_TimerExpired"),
|
||||
PageStart("RebootNDUP"),
|
||||
OsBuildChanged(),
|
||||
PageStart("OobeNDUP"),
|
||||
PageStop("OobeNDUP", "success"),
|
||||
});
|
||||
return events;
|
||||
}
|
||||
|
||||
/// <summary>b2d9f12c: the same device the next day — out of date, an earlier failure on record, nothing offered.</summary>
|
||||
private static List<EnrollmentEvent> NothingOfferedAfterFailure()
|
||||
{
|
||||
var events = Visit(days: 137, previousFailures: 1);
|
||||
events.AddRange(new[]
|
||||
{
|
||||
Name("ExpeditedUpdate_getUpdateResultsStarted"),
|
||||
Name("ExpeditedUpdate_getUpdateResultsSucceeded"),
|
||||
Name("SdxWebAppCloudNDUP_updateManager_processUpdatesMetadata_osUpdatesWithNDUPPI", "false"),
|
||||
Name("SdxWebAppCloudNDUP_exit_appResult"),
|
||||
PageStop("OobeNDUP", "cancel"),
|
||||
PageStart("RebootNDUP"),
|
||||
PageStop("RebootNDUP", "success"),
|
||||
});
|
||||
return events;
|
||||
}
|
||||
|
||||
/// <summary>c5b20dfa: 438 days behind; the page ended two minutes after the scan started, without a result.</summary>
|
||||
private static List<EnrollmentEvent> ScanWithoutResult()
|
||||
{
|
||||
var events = Visit(days: 438, previousFailures: 0);
|
||||
events.AddRange(new[]
|
||||
{
|
||||
Name("SdxWebAppCloudNDUP_processStatusChangeFromHandler_installSucceededNoReboot"), // the language check, every visit
|
||||
Name("SdxWebAppCloudNDUP_exit_appResult"),
|
||||
PageStop("OobeNDUP", "cancel"),
|
||||
PageStart("RebootNDUP"),
|
||||
PageStop("RebootNDUP", "success"),
|
||||
});
|
||||
return events;
|
||||
}
|
||||
|
||||
/// <summary>6a7d241d: downloaded, installed, restarted.</summary>
|
||||
private static List<EnrollmentEvent> Installed()
|
||||
{
|
||||
var events = Visit(days: 120, previousFailures: 0);
|
||||
events.AddRange(new[]
|
||||
{
|
||||
Name("ExpeditedUpdate_getUpdateResultsSucceeded"),
|
||||
Name("SdxWebAppCloudNDUP_updateManager_processUpdatesMetadata_osUpdatesWithNDUPPI"),
|
||||
Name("ExpeditedUpdate_commitExpeditionDownloadInstallAsyncStarted"),
|
||||
Name("SdxWebAppCloudNDUP_processStatusChangeFromHandler_downloadSucceeded"),
|
||||
Name("SdxWebAppCloudNDUP_processStatusChangeFromHandler_installSucceededRebootRequired"),
|
||||
Name("ExpeditedUpdate_commitExpeditionDownloadInstallAsyncSucceeded"),
|
||||
Name("SdxWebAppCloudNDUP_rebootCountdown_starting"),
|
||||
PageStart("RebootNDUP"),
|
||||
OsBuildChanged(),
|
||||
});
|
||||
return events;
|
||||
}
|
||||
|
||||
// ── event builders — mirror the agent's OobeUpdateTelemetry payload ─────
|
||||
|
||||
private static long _seq;
|
||||
|
||||
private static EnrollmentEvent Evt(string eventType, Dictionary<string, object> data)
|
||||
{
|
||||
var seq = Interlocked.Increment(ref _seq);
|
||||
return new EnrollmentEvent
|
||||
{
|
||||
EventId = Guid.NewGuid().ToString(),
|
||||
TenantId = TenantId,
|
||||
SessionId = SessionId,
|
||||
EventType = eventType,
|
||||
Timestamp = T0.AddSeconds(seq),
|
||||
Sequence = seq,
|
||||
Data = data,
|
||||
};
|
||||
}
|
||||
|
||||
private static Dictionary<string, object> PageData(string cxhEvent, int windowsEventId) => new()
|
||||
{
|
||||
["cxhEvent"] = cxhEvent,
|
||||
["windowsEventId"] = windowsEventId,
|
||||
["backfill"] = false,
|
||||
["occurrence"] = 1,
|
||||
};
|
||||
|
||||
private static EnrollmentEvent PageStart(string page)
|
||||
{
|
||||
var data = PageData("page_started", 62404);
|
||||
data["page"] = page;
|
||||
return Evt("oobe_update_page", data);
|
||||
}
|
||||
|
||||
private static EnrollmentEvent PageStop(string page, string result)
|
||||
{
|
||||
var data = PageData("page_stopped", 62405);
|
||||
data["page"] = page;
|
||||
data["result"] = result;
|
||||
return Evt("oobe_update_page", data);
|
||||
}
|
||||
|
||||
private static EnrollmentEvent Name(string name, string? value = null)
|
||||
{
|
||||
var data = PageData("event_name", value == null ? 62406 : 62407);
|
||||
data["name"] = name;
|
||||
if (value != null) data["value"] = value;
|
||||
return Evt("oobe_update_page", data);
|
||||
}
|
||||
|
||||
private static EnrollmentEvent NamesCapped()
|
||||
{
|
||||
var data = PageData("names_capped", 0);
|
||||
data.Remove("windowsEventId");
|
||||
data.Remove("occurrence");
|
||||
data["limit"] = 150;
|
||||
return Evt("oobe_update_page", data);
|
||||
}
|
||||
|
||||
private static EnrollmentEvent OsBuildChanged() => Evt("os_build_changed", new Dictionary<string, object>
|
||||
{
|
||||
["previousBuild"] = "26200.8037",
|
||||
["currentBuild"] = "26200.8655",
|
||||
});
|
||||
|
||||
// ── harness (as WindowsUpdateRuleTests) ─────────────────────────────────
|
||||
|
||||
private static AnalyzeRule Rule(string ruleId) => BuiltInAnalyzeRules.GetAll().First(r => r.RuleId == ruleId);
|
||||
|
||||
private static string Value(RuleResult result, string signal)
|
||||
{
|
||||
var evidence = Assert.IsType<Dictionary<string, object>>(result.MatchedConditions[signal]);
|
||||
return evidence["value"]?.ToString() ?? string.Empty;
|
||||
}
|
||||
|
||||
private static async Task<AnalysisOutcome> RunAsync(List<EnrollmentEvent> events)
|
||||
{
|
||||
var rules = RuleIds.Select(Rule).ToList();
|
||||
|
||||
var ruleRepo = new Mock<IRuleRepository>();
|
||||
ruleRepo.Setup(r => r.GetAnalyzeRulesAsync("global")).ReturnsAsync(rules);
|
||||
ruleRepo.Setup(r => r.GetAnalyzeRulesAsync(TenantId)).ReturnsAsync(new List<AnalyzeRule>());
|
||||
ruleRepo.Setup(r => r.GetRuleStatesAsync(It.IsAny<string>())).ReturnsAsync(new Dictionary<string, RuleState>());
|
||||
ruleRepo.Setup(r => r.GetRuleResultsAsync(It.IsAny<string>(), It.IsAny<string>())).ReturnsAsync(new List<RuleResult>());
|
||||
|
||||
var sessionRepo = new Mock<ISessionRepository>();
|
||||
sessionRepo.Setup(s => s.GetSessionEventsStrictAsync(TenantId, SessionId, It.IsAny<int>())).ReturnsAsync(events);
|
||||
|
||||
var ruleService = new AnalyzeRuleService(ruleRepo.Object, NullLogger<AnalyzeRuleService>.Instance);
|
||||
var engine = new RuleEngine(ruleService, ruleRepo.Object, sessionRepo.Object, NullLogger<OobeUpdateRuleTests>.Instance);
|
||||
|
||||
return await engine.AnalyzeSessionAsync(TenantId, SessionId);
|
||||
}
|
||||
}
|
||||
@@ -21,6 +21,7 @@ public class SessionAnchorSourceTests
|
||||
[InlineData("SystemTimelineWatcher")]
|
||||
[InlineData("WindowsUpdateWatcher")]
|
||||
[InlineData("ServicingWatcher")]
|
||||
[InlineData("ShellCoreTracker")] // the update page, read back an hour on an agent's first run
|
||||
public void Backfill_sources_are_not_anchor_eligible(string source)
|
||||
{
|
||||
Assert.False(Constants.EventSources.IsSessionAnchorEligible(source));
|
||||
@@ -30,6 +31,7 @@ public class SessionAnchorSourceTests
|
||||
[InlineData("ImeLogTracker")]
|
||||
[InlineData("Agent")]
|
||||
[InlineData("MdmRebootPolicyWatcher")]
|
||||
[InlineData("EspAndHelloTracker")] // the ESP and Hello signals from the same Shell-Core log
|
||||
[InlineData("windowsupdatewatcher")] // ordinal: a differently cased source is not the watcher
|
||||
[InlineData(null)] // legacy row without a source
|
||||
public void Activity_sources_are_anchor_eligible(string? source)
|
||||
|
||||
@@ -92,6 +92,8 @@ public sealed class SharedManifestParityTests
|
||||
["appInstallSources"] = AppInstallSources.All,
|
||||
// Event sources whose rows never set a session's start; the portal's session duration applies them.
|
||||
["sessionAnchorIneligibleSources"] = Constants.EventSources.SessionAnchorIneligible,
|
||||
// How an OOBE quality update ended (OsUpdateSpan.Outcome in the time attribution).
|
||||
["osUpdateOutcomes"] = OsUpdateOutcomes.All,
|
||||
// Community rule submissions: kinds, effective statuses (incl. the derived "published"),
|
||||
// attribution modes and reviewer decisions — the MCP tool schemas enumerate these.
|
||||
["ruleSubmissionKinds"] = RuleSubmissionKinds.All,
|
||||
|
||||
@@ -6,10 +6,12 @@ namespace AutopilotMonitor.Functions.Tests;
|
||||
|
||||
/// <summary>
|
||||
/// Golden fixtures for the OOBE quality update in the time attribution (AttributionVersion 4,
|
||||
/// D-314): <c>os_update</c> from the update page start whose visit holds update evidence to the
|
||||
/// last update evidence before the user is back, then — after a restart — <c>awaiting_sign_in</c>
|
||||
/// until the user is back. Sequences follow the field sessions of 2026-10-02 (synthetic times, no
|
||||
/// customer data). EVERY fixture asserts the exact-partition invariant.
|
||||
/// D-314; v5): <c>os_update</c> from the update page start whose visit holds update evidence — or,
|
||||
/// when the agent missed the start, from the update's first evidence — to the last update evidence
|
||||
/// before the user is back, then — after a restart — <c>awaiting_sign_in</c> until the user is back;
|
||||
/// the latest outcome evidence names the outcome. Sequences follow the field sessions of
|
||||
/// 2026-10-02..05 (synthetic times, no customer data). EVERY fixture asserts the exact-partition
|
||||
/// invariant.
|
||||
/// </summary>
|
||||
public class TimeAttributionOsUpdateTests
|
||||
{
|
||||
@@ -131,7 +133,7 @@ public class TimeAttributionOsUpdateTests
|
||||
var b = TimeAttributionCalculator.Compute(Input(LongUpdateWithSecondVisit(), At(125), 7500))!;
|
||||
|
||||
AssertExactPartition(b);
|
||||
Assert.Equal(4, b.AttributionVersion);
|
||||
Assert.Equal(TimeAttributionCalculator.CurrentVersion, b.AttributionVersion);
|
||||
Assert.Equal(120, Total(b, TimeAttributionSegments.DevicePrep));
|
||||
Assert.Equal(18 * 60 + 5, Total(b, TimeAttributionSegments.EspApps)); // +2m → page start
|
||||
Assert.Equal(100 * 60 + 31, Total(b, TimeAttributionSegments.OsUpdate)); // page start → second visit ends
|
||||
@@ -144,7 +146,11 @@ public class TimeAttributionOsUpdateTests
|
||||
Assert.Equal(At(120, 36), update.EndUtc);
|
||||
Assert.Equal(100 * 60 + 31, update.Seconds);
|
||||
Assert.Equal(new[] { "KB5129195" }, update.Kbs);
|
||||
Assert.Empty(update.NotInstalledKbs);
|
||||
Assert.Equal(3, update.RebootCount);
|
||||
// downloadInstallFailureHelper and a start timeout after "restart required" are no failure:
|
||||
// the package reached Installed after the restarts (field shape e4ecd6f8).
|
||||
Assert.Equal(OsUpdateOutcomes.Installed, update.Outcome);
|
||||
|
||||
// The update's restarts sit in its own segment.
|
||||
Assert.Equal(3, b.RebootSpans.Count);
|
||||
@@ -363,6 +369,348 @@ public class TimeAttributionOsUpdateTests
|
||||
Assert.Equal(23 * 60, Total(b, TimeAttributionSegments.EspApps)); // the hole until the first step stays the phase's
|
||||
}
|
||||
|
||||
// ── the agent started after the page (v5) ───────────────────────────────
|
||||
|
||||
/// <summary>
|
||||
/// Field shape 6a7d241d: the agent's first run began after the device ESP and after the page
|
||||
/// start — it saw neither (a first run reads no Shell-Core history), only the update's later
|
||||
/// page names and the servicing steps the watcher backfills an hour.
|
||||
/// </summary>
|
||||
private static List<EnrollmentEvent> LateAgentUpdate()
|
||||
{
|
||||
var events = new List<EnrollmentEvent>
|
||||
{
|
||||
Evt(T0, "agent_started", EnrollmentPhase.DeviceSetup),
|
||||
Evt(At(2), "esp_phase_changed", EnrollmentPhase.AppsDevice),
|
||||
// A package the OOBE itself finished during the ESP: no part of the update.
|
||||
Servicing(At(5), "initiating", package: "KB5128942", targetState: "Staged"),
|
||||
Servicing(At(6), "state_reached", package: "KB5128942", targetState: "Staged"),
|
||||
Servicing(At(6, 5), "initiating", package: "KB5128942"),
|
||||
Servicing(At(7), "state_reached", package: "KB5128942"),
|
||||
// The update's servicing stack, staged before the agent ran.
|
||||
Servicing(At(20), "initiating", package: "KB5124007", targetState: "Staged"),
|
||||
Servicing(At(20, 5), "state_reached", package: "KB5124007", targetState: "Staged"),
|
||||
// The agent runs from here on.
|
||||
PageName(At(27, 40), "SdxWebAppCloudNDUP_processStatusChangeFromHandler_downloadSucceeded"),
|
||||
Servicing(At(32, 25), "initiating", package: "KB5124007"),
|
||||
Servicing(At(33, 22), "state_reached", package: "KB5124007"),
|
||||
Servicing(At(34), "initiating", package: "KB5129195", targetState: "Staged"),
|
||||
Servicing(At(36), "state_reached", package: "KB5129195", targetState: "Staged"),
|
||||
Servicing(At(36, 10), "initiating", package: "KB5054156", targetState: "Staged"),
|
||||
Servicing(At(38), "state_reached", package: "KB5054156", targetState: "Staged"),
|
||||
Servicing(At(38, 10), "initiating", package: "KB5129195"),
|
||||
Servicing(At(38, 20), "initiating", package: "KB5054156"),
|
||||
Servicing(At(43, 5), "reboot_required", package: "KB5129195"),
|
||||
Servicing(At(43, 6), "reboot_required", package: "KB5054156"),
|
||||
PageName(At(43, 10), "SdxWebAppCloudNDUP_processStatusChangeFromHandler_installSucceededRebootRequired"),
|
||||
PageName(At(43, 12), "ExpeditedUpdate_commitExpeditionDownloadInstallAsyncSucceeded"),
|
||||
PageName(At(43, 30), "SdxWebAppCloudNDUP_rebootCountdown_starting"),
|
||||
PageStart(At(43, 35), "RebootNDUP"),
|
||||
RebootDetected(At(46), lastBoot: At(45)),
|
||||
Servicing(At(50), "state_reached", package: "KB5129195"),
|
||||
Evt(At(52), "agent_shutting_down"),
|
||||
// The second restart; the backfilled servicing step is the first event after it.
|
||||
Servicing(At(59, 17), "state_reached", package: "KB5054156"),
|
||||
RebootDetected(At(59, 30), lastBoot: At(58)),
|
||||
Evt(At(62, 10), "desktop_arrived"),
|
||||
Evt(At(63), "enrollment_complete"),
|
||||
};
|
||||
return events;
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void LateAgent_UpdateBeginsAtTheFirstStepOfAPackageItAlsoServiced()
|
||||
{
|
||||
var b = TimeAttributionCalculator.Compute(Input(LateAgentUpdate(), At(63), 63 * 60))!;
|
||||
|
||||
AssertExactPartition(b);
|
||||
var update = Assert.Single(b.OsUpdates);
|
||||
// Not the OOBE's own package at 5 min: it has no step after the update's first name.
|
||||
Assert.Equal(At(20), update.StartUtc);
|
||||
Assert.Equal(At(59, 17), update.EndUtc); // the last step, where the second restart ends
|
||||
Assert.Equal(39 * 60 + 17, Total(b, TimeAttributionSegments.OsUpdate));
|
||||
Assert.Equal(2 * 60 + 53, Total(b, TimeAttributionSegments.AwaitingSignIn)); // → desktop
|
||||
Assert.Equal(18 * 60, Total(b, TimeAttributionSegments.EspApps));
|
||||
Assert.Equal(new[] { "KB5124007", "KB5129195", "KB5054156" }, update.Kbs);
|
||||
Assert.Empty(update.NotInstalledKbs);
|
||||
Assert.Equal(2, update.RebootCount);
|
||||
Assert.Equal(OsUpdateOutcomes.Installed, update.Outcome);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void LateAgent_WithoutItsNames_StaysTheAppsPhase()
|
||||
{
|
||||
// Without its names the update is invisible to a window without an observed exit (v4 saw
|
||||
// it so even with them): the servicing steps alone never begin an update there.
|
||||
var withoutNames = LateAgentUpdate().Where(e => e.EventType != "oobe_update_page").ToList();
|
||||
|
||||
var b = TimeAttributionCalculator.Compute(Input(withoutNames, At(63), 63 * 60))!;
|
||||
|
||||
AssertExactPartition(b);
|
||||
Assert.Empty(b.OsUpdates);
|
||||
Assert.Equal((62 * 60 + 10) - 2 * 60, Total(b, TimeAttributionSegments.EspApps));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void LateAgent_NamesWithoutServicing_BeginAtTheFirstName()
|
||||
{
|
||||
var events = new List<EnrollmentEvent>
|
||||
{
|
||||
Evt(T0, "agent_started", EnrollmentPhase.DeviceSetup),
|
||||
Evt(At(2), "esp_phase_changed", EnrollmentPhase.AppsDevice),
|
||||
PageName(At(24), "SdxWebAppCloudNDUP_updateUSOProgressBar_DownloadPhase_progress40"),
|
||||
PageName(At(29), "ExpeditedUpdate_commitExpeditionDownloadInstallAsyncSucceeded"),
|
||||
PageStop(At(29, 20), "OobeNDUP", "success"),
|
||||
Evt(At(31), "desktop_arrived"),
|
||||
Evt(At(32), "enrollment_complete"),
|
||||
};
|
||||
|
||||
var b = TimeAttributionCalculator.Compute(Input(events, At(32), 32 * 60))!;
|
||||
|
||||
AssertExactPartition(b);
|
||||
var update = Assert.Single(b.OsUpdates);
|
||||
Assert.Equal(At(24), update.StartUtc);
|
||||
Assert.Equal(At(29, 20), update.EndUtc);
|
||||
Assert.Equal(0, update.RebootCount);
|
||||
Assert.Equal(0, Total(b, TimeAttributionSegments.AwaitingSignIn)); // no restart: nobody was signed out
|
||||
Assert.Equal(OsUpdateOutcomes.Installed, update.Outcome);
|
||||
Assert.Empty(update.Kbs);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void MissedFirstVisit_BeginsAtItsNames_NotAtTheSecondVisit()
|
||||
{
|
||||
// The agent missed visit 1 (it updated and restarted) and saw the confirmation visit,
|
||||
// which holds no evidence of its own: v4 found no update at all.
|
||||
var events = DeviceEsp();
|
||||
events.RemoveAll(e => e.EventType == "esp_exiting");
|
||||
events.AddRange(new[]
|
||||
{
|
||||
Servicing(At(21), "initiating", targetState: "Staged"),
|
||||
PageName(At(23), "ExpeditedUpdate_commitExpeditionDownloadInstallAsyncStarted"),
|
||||
Servicing(At(30), "state_reached", targetState: "Staged"),
|
||||
Servicing(At(30, 10), "initiating"),
|
||||
Servicing(At(36), "reboot_required"),
|
||||
PageName(At(36, 5), "SdxWebAppCloudNDUP_rebootCountdown_starting"),
|
||||
PageStart(At(36, 10), "RebootNDUP"),
|
||||
RebootDetected(At(38), lastBoot: At(37)),
|
||||
Servicing(At(39), "state_reached"),
|
||||
PageStart(At(39, 10), "OobeNDUP"),
|
||||
PageStop(At(39, 30), "OobeNDUP", "success"),
|
||||
Evt(At(41), "desktop_arrived"),
|
||||
Evt(At(42), "enrollment_complete"),
|
||||
});
|
||||
|
||||
var b = TimeAttributionCalculator.Compute(Input(events, At(42), 42 * 60))!;
|
||||
|
||||
AssertExactPartition(b);
|
||||
var update = Assert.Single(b.OsUpdates);
|
||||
Assert.Equal(At(21), update.StartUtc); // the package's first step, before the name
|
||||
Assert.Equal(At(39, 30), update.EndUtc);
|
||||
Assert.Equal(new[] { "KB5129195" }, update.Kbs);
|
||||
Assert.Equal(1, update.RebootCount);
|
||||
Assert.Equal(90, Total(b, TimeAttributionSegments.AwaitingSignIn));
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void EspExitAfterTheNames_DoesNotBoundTheBegin()
|
||||
{
|
||||
// An exit the agent saw after the update's names belongs to a later handoff; the begin
|
||||
// comes from the packages the update serviced, as without an exit.
|
||||
var events = LateAgentUpdate();
|
||||
events.Add(Evt(At(44), "esp_exiting"));
|
||||
|
||||
var b = TimeAttributionCalculator.Compute(Input(events, At(63), 63 * 60))!;
|
||||
|
||||
AssertExactPartition(b);
|
||||
Assert.Equal(At(20), Assert.Single(b.OsUpdates).StartUtc);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void EspExitBeforeTheNames_BoundsTheBeginAsInV4()
|
||||
{
|
||||
// A known exit before the names: the first servicing step after it begins the update —
|
||||
// the KB staged during the ESP stays out, whatever the update did with it later.
|
||||
var events = LateAgentUpdate();
|
||||
events.Add(Evt(At(25), "esp_exiting"));
|
||||
|
||||
var b = TimeAttributionCalculator.Compute(Input(events, At(63), 63 * 60))!;
|
||||
|
||||
AssertExactPartition(b);
|
||||
var update = Assert.Single(b.OsUpdates);
|
||||
Assert.Equal(At(27, 40), update.StartUtc); // no step between the exit and the first name
|
||||
Assert.Equal(new[] { "KB5124007", "KB5129195", "KB5054156" }, update.Kbs);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void NamesAfterTheUserIsBack_AreNoUpdate()
|
||||
{
|
||||
var events = WithAccountPhase(new[]
|
||||
{
|
||||
PageName(At(28, 30), "SdxWebAppCloudNDUP_processStatusChangeFromHandler_downloadSucceeded"),
|
||||
PageName(At(29), "ExpeditedUpdate_commitExpeditionDownloadInstallAsyncSucceeded"),
|
||||
});
|
||||
|
||||
var b = TimeAttributionCalculator.Compute(Input(events, At(30), 1800))!;
|
||||
|
||||
AssertExactPartition(b);
|
||||
Assert.Empty(b.OsUpdates);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void WhiteGlove_PartOneExit_DoesNotBeginAnUpdateInPartTwo()
|
||||
{
|
||||
// v4 took the session's first exit: part 1's let a servicing step in part 2 begin an
|
||||
// update. Part 2 here has no exit, no page and no update name — no update.
|
||||
var part1End = At(30);
|
||||
var resumedAt = T0.AddDays(2);
|
||||
var completedAt = resumedAt.AddMinutes(20);
|
||||
var events = new List<EnrollmentEvent>
|
||||
{
|
||||
Evt(T0, "agent_started", EnrollmentPhase.DeviceSetup),
|
||||
Evt(At(2), "esp_phase_changed", EnrollmentPhase.AppsDevice),
|
||||
Evt(At(25), "esp_exiting"),
|
||||
Evt(part1End, "whiteglove_part1_complete"),
|
||||
Evt(resumedAt.AddSeconds(30), "agent_started", EnrollmentPhase.DeviceSetup),
|
||||
Evt(resumedAt.AddMinutes(1), "esp_phase_changed", EnrollmentPhase.AppsDevice),
|
||||
Servicing(resumedAt.AddMinutes(5), "initiating", targetState: "Staged"),
|
||||
Servicing(resumedAt.AddMinutes(8), "state_reached", targetState: "Staged"),
|
||||
Evt(resumedAt.AddMinutes(15), "esp_phase_changed", EnrollmentPhase.AccountSetup),
|
||||
Evt(resumedAt.AddMinutes(16), "hello_wizard_started"),
|
||||
Evt(resumedAt.AddMinutes(19), "desktop_arrived"),
|
||||
Evt(completedAt, "enrollment_complete"),
|
||||
};
|
||||
|
||||
var b = TimeAttributionCalculator.Compute(
|
||||
Input(events, completedAt, durationSeconds: 30 * 60 + 20 * 60, wg: true, resumedAt: resumedAt))!;
|
||||
|
||||
AssertExactPartition(b);
|
||||
Assert.Empty(b.OsUpdates);
|
||||
}
|
||||
|
||||
// ── outcome ─────────────────────────────────────────────────────────────
|
||||
|
||||
[Fact]
|
||||
public void FailedDownload_IsFailed_AndTheStagedKbIsNotInstalled()
|
||||
{
|
||||
// Field shape e7551b82: only the servicing stack staged; the download failed after 25
|
||||
// minutes, the page restarted the device, and the second visit found nothing to offer.
|
||||
var events = DeviceEsp();
|
||||
events.AddRange(new[]
|
||||
{
|
||||
PageStart(At(20, 2), "OobeNDUP"),
|
||||
PageName(At(20, 3), "ExpeditedUpdate_isNDUPAllowedByCSPSucceeded", "true"),
|
||||
PageName(At(21, 42), "ExpeditedUpdate_commitExpeditionDownloadInstallAsyncStarted"),
|
||||
Servicing(At(22), "initiating", package: "KB5124007", targetState: "Staged"),
|
||||
Servicing(At(26), "state_reached", package: "KB5124007", targetState: "Staged"),
|
||||
PageName(At(45, 10), "SdxWebAppCloudNDUP_processStatusChangeFromHandler_downloadFailedError"),
|
||||
PageName(At(45, 12), "ExpeditedUpdate_commitExpeditionDownloadInstallAsyncFailure"),
|
||||
PageName(At(45, 13), "SdxWebAppCloudNDUP_downloadInstallFailureHelper"),
|
||||
PageStop(At(45, 20), "OobeNDUP", "fail"),
|
||||
PageStart(At(45, 20), "RebootNDUP"),
|
||||
RebootDetected(At(46, 30), lastBoot: At(45, 50)),
|
||||
PageStart(At(46, 51), "OobeNDUP"),
|
||||
PageName(At(46, 52), "SdxWebAppCloudNDUP_initialize_NDUPDownloadInstallPreviousFailureCount", "1"),
|
||||
PageName(At(47, 10), "SdxWebAppCloudNDUP_updateManager_processUpdatesMetadata_osUpdatesWithNDUPPI", "false"),
|
||||
PageStop(At(47, 13), "OobeNDUP", "cancel"),
|
||||
Evt(At(48, 15), "desktop_arrived"),
|
||||
Evt(At(50), "enrollment_complete"),
|
||||
});
|
||||
|
||||
var b = TimeAttributionCalculator.Compute(Input(events, At(50), 3000))!;
|
||||
|
||||
AssertExactPartition(b);
|
||||
var update = Assert.Single(b.OsUpdates);
|
||||
Assert.Equal(At(20, 2), update.StartUtc);
|
||||
Assert.Equal(At(47, 13), update.EndUtc);
|
||||
Assert.Equal(OsUpdateOutcomes.Failed, update.Outcome);
|
||||
Assert.Empty(update.Kbs);
|
||||
Assert.Equal(new[] { "KB5124007" }, update.NotInstalledKbs);
|
||||
Assert.Equal(1, update.RebootCount);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void FailureThenSkip_IsSkipped()
|
||||
{
|
||||
// Field shape cb1992b8: visit 1 failed; visit 2 downloaded again, and someone selected
|
||||
// Skip before the install began.
|
||||
var events = DeviceEsp();
|
||||
events.AddRange(new[]
|
||||
{
|
||||
PageStart(At(20, 2), "OobeNDUP"),
|
||||
PageName(At(21), "ExpeditedUpdate_commitExpeditionDownloadInstallAsyncStarted"),
|
||||
PageName(At(30), "SdxWebAppCloudNDUP_processStatusChangeFromHandler_downloadFailedError"),
|
||||
PageName(At(30, 2), "ExpeditedUpdate_commitExpeditionDownloadInstallAsyncFailure"),
|
||||
PageStop(At(30, 10), "OobeNDUP", "fail"),
|
||||
PageStart(At(30, 10), "RebootNDUP"),
|
||||
RebootDetected(At(31, 30), lastBoot: At(30, 40)),
|
||||
PageStart(At(32), "OobeNDUP"),
|
||||
PageName(At(32, 1), "SdxWebAppCloudNDUP_initialize_NDUPDownloadInstallPreviousFailureCount", "1"),
|
||||
PageName(At(33), "SdxWebAppCloudNDUP_processStatusChangeFromHandler_downloadSucceeded"),
|
||||
PageName(At(40), "SdxWebAppCloudNDUP_manageProgressBars_waitingForInstallStartError"),
|
||||
PageName(At(41), "CloudNDUPSkipDownloadInstallButtonClicked", "0"),
|
||||
PageStop(At(41, 5), "OobeNDUP", "cancel"),
|
||||
Evt(At(43), "desktop_arrived"),
|
||||
Evt(At(44), "enrollment_complete"),
|
||||
});
|
||||
|
||||
var b = TimeAttributionCalculator.Compute(Input(events, At(44), 2640))!;
|
||||
|
||||
AssertExactPartition(b);
|
||||
var update = Assert.Single(b.OsUpdates);
|
||||
Assert.Equal(OsUpdateOutcomes.Skipped, update.Outcome);
|
||||
Assert.Equal(At(41, 5), update.EndUtc);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void FailureRetriedAndInstalled_IsInstalled()
|
||||
{
|
||||
var events = DeviceEsp();
|
||||
events.AddRange(new[]
|
||||
{
|
||||
PageStart(At(20, 2), "OobeNDUP"),
|
||||
PageName(At(21), "ExpeditedUpdate_commitExpeditionDownloadInstallAsyncStarted"),
|
||||
PageName(At(25), "SdxWebAppCloudNDUP_processStatusChangeFromHandler_downloadFailedError"),
|
||||
PageName(At(26), "SdxWebAppCloudNDUP_processStatusChangeFromHandler_downloadSucceeded"),
|
||||
Servicing(At(27), "initiating"),
|
||||
Servicing(At(30), "state_reached"),
|
||||
PageName(At(30, 5), "ExpeditedUpdate_commitExpeditionDownloadInstallAsyncSucceeded"),
|
||||
PageStop(At(30, 10), "OobeNDUP", "success"),
|
||||
Evt(At(32), "desktop_arrived"),
|
||||
Evt(At(33), "enrollment_complete"),
|
||||
});
|
||||
|
||||
var b = TimeAttributionCalculator.Compute(Input(events, At(33), 1980))!;
|
||||
|
||||
AssertExactPartition(b);
|
||||
var update = Assert.Single(b.OsUpdates);
|
||||
Assert.Equal(OsUpdateOutcomes.Installed, update.Outcome);
|
||||
Assert.Equal(new[] { "KB5129195" }, update.Kbs);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void FailedServicingStep_IsFailed()
|
||||
{
|
||||
var events = DeviceEsp();
|
||||
events.AddRange(new[]
|
||||
{
|
||||
PageStart(At(20, 2), "OobeNDUP"),
|
||||
Servicing(At(22), "initiating"),
|
||||
Servicing(At(28), "failed"),
|
||||
PageStop(At(28, 30), "OobeNDUP", "cancel"),
|
||||
Evt(At(30), "desktop_arrived"),
|
||||
Evt(At(31), "enrollment_complete"),
|
||||
});
|
||||
|
||||
var b = TimeAttributionCalculator.Compute(Input(events, At(31), 1860))!;
|
||||
|
||||
AssertExactPartition(b);
|
||||
var update = Assert.Single(b.OsUpdates);
|
||||
Assert.Equal(OsUpdateOutcomes.Failed, update.Outcome);
|
||||
Assert.Empty(update.Kbs);
|
||||
Assert.Equal(new[] { "KB5129195" }, update.NotInstalledKbs);
|
||||
}
|
||||
|
||||
[Theory]
|
||||
[InlineData("ExpeditedUpdate_commitExpeditionDownloadInstallAsyncStarted", true)]
|
||||
[InlineData("SdxWebAppCloudNDUP_processStatusChangeFromHandler_downloadSucceeded", true)]
|
||||
@@ -448,6 +796,9 @@ public class TimeAttributionOsUpdateTests
|
||||
var update = Assert.Single(b.OsUpdates);
|
||||
Assert.Equal(At(25), update.EndUtc); // the step after the failure is not attributed
|
||||
Assert.Equal(4 * 60 + 58, Total(b, TimeAttributionSegments.OsUpdate));
|
||||
Assert.Empty(update.Kbs); // only staged before the bound
|
||||
Assert.Equal(new[] { "KB5129195" }, update.NotInstalledKbs);
|
||||
Assert.Equal(OsUpdateOutcomes.Unknown, update.Outcome);
|
||||
Assert.Equal(0, Total(b, TimeAttributionSegments.AwaitingSignIn));
|
||||
Assert.True(b.UnattributedSeconds >= 10 * 60); // the post-failure tail stays unattributed
|
||||
}
|
||||
|
||||
+23
-1
@@ -53,7 +53,12 @@ public class TimeAttributionPersistenceAndAggregationTests
|
||||
},
|
||||
OsUpdates = new List<OsUpdateSpan>
|
||||
{
|
||||
new() { StartUtc = T0.AddMinutes(9), EndUtc = T0.AddMinutes(19), Seconds = 600, Kbs = new List<string> { "KB5129195", "KB5054156" }, RebootCount = 2 },
|
||||
new()
|
||||
{
|
||||
StartUtc = T0.AddMinutes(9), EndUtc = T0.AddMinutes(19), Seconds = 600,
|
||||
Kbs = new List<string> { "KB5129195", "KB5054156" }, NotInstalledKbs = new List<string> { "KB5124007" },
|
||||
Outcome = OsUpdateOutcomes.Failed, RebootCount = 2,
|
||||
},
|
||||
},
|
||||
BlockingApps = new List<BlockingAppInterval>
|
||||
{
|
||||
@@ -98,6 +103,8 @@ public class TimeAttributionPersistenceAndAggregationTests
|
||||
Assert.Equal(T0.AddMinutes(19), update.EndUtc);
|
||||
Assert.Equal(600, update.Seconds);
|
||||
Assert.Equal(new[] { "KB5129195", "KB5054156" }, update.Kbs);
|
||||
Assert.Equal(new[] { "KB5124007" }, update.NotInstalledKbs);
|
||||
Assert.Equal(OsUpdateOutcomes.Failed, update.Outcome);
|
||||
Assert.Equal(2, update.RebootCount);
|
||||
|
||||
var app = Assert.Single(mapped.BlockingApps);
|
||||
@@ -117,6 +124,21 @@ public class TimeAttributionPersistenceAndAggregationTests
|
||||
Assert.Empty(TableStorageService.MapToSessionTimeBreakdown(entity).OsUpdates);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void BreakdownEntity_OsUpdateWrittenBeforeTheOutcome_MapsToUnknown()
|
||||
{
|
||||
// v4 spans carry no Outcome/NotInstalledKbs until the sweep recomputes them.
|
||||
var entity = TableStorageService.BuildSessionTimeBreakdownEntity(
|
||||
new SessionTimeBreakdown { TenantId = TenantA, SessionId = "s-1", WallClockSeconds = 600 });
|
||||
entity["OsUpdatesJson"] =
|
||||
"[{\"StartUtc\":\"2026-10-02T14:00:00Z\",\"EndUtc\":\"2026-10-02T14:10:00Z\",\"Seconds\":600,\"Kbs\":[\"KB5129195\"],\"RebootCount\":1}]";
|
||||
|
||||
var update = Assert.Single(TableStorageService.MapToSessionTimeBreakdown(entity).OsUpdates);
|
||||
Assert.Equal(OsUpdateOutcomes.Unknown, update.Outcome);
|
||||
Assert.Empty(update.NotInstalledKbs);
|
||||
Assert.Equal(new[] { "KB5129195" }, update.Kbs);
|
||||
}
|
||||
|
||||
[Fact]
|
||||
public void BreakdownEntity_OccupancyTriState_AbsentColumnMapsToNull_NeverZero()
|
||||
{
|
||||
|
||||
@@ -67,10 +67,11 @@ public sealed class TimeAttributionInput
|
||||
/// <c>system_reboot_detected</c> event is detection-time-stamped by the next run and never used
|
||||
/// as the reboot moment (audit Q7). Reboots are a cross-cutting annotation, not a segment.</item>
|
||||
/// <item><b>The OOBE quality update takes its time from the phase segments</b> (v4, D-314):
|
||||
/// <c>os_update</c> from the start of the update page that installed an update to the last
|
||||
/// update evidence before the user is back, then — after a restart — <c>awaiting_sign_in</c>
|
||||
/// until the first evidence of the user. Without update evidence (the page cancelled or found
|
||||
/// nothing) the partition is the phase partition unchanged.</item>
|
||||
/// <c>os_update</c> from the start of the update page that worked on an update — or, when the
|
||||
/// agent started after the page, from the update's first evidence (v5) — to the last update
|
||||
/// evidence before the user is back, then — after a restart — <c>awaiting_sign_in</c> until the
|
||||
/// first evidence of the user. Without update evidence (the page cancelled or found nothing) the
|
||||
/// partition is the phase partition unchanged. The latest outcome evidence names the outcome.</item>
|
||||
/// </list>
|
||||
/// </summary>
|
||||
public static class TimeAttributionCalculator
|
||||
@@ -82,7 +83,9 @@ public static class TimeAttributionCalculator
|
||||
// annotations mirroring RebootSpans; the maintenance sweep recomputes older rows.
|
||||
// v4: os_update + awaiting_sign_in — the OOBE quality update and the wait for the user after
|
||||
// its restart, cut out of the phase segment they overlap (D-314), with OsUpdates naming the KBs.
|
||||
public const int CurrentVersion = 4;
|
||||
// v5: an update whose page start the agent missed begins at its first evidence; the device-ESP
|
||||
// exit is the window's own; OsUpdates carry the outcome and split installed from not installed KBs.
|
||||
public const int CurrentVersion = 5;
|
||||
|
||||
/// <summary>
|
||||
/// Enrollment class for fleet aggregation — classes are NEVER mixed in one aggregate (a
|
||||
@@ -217,6 +220,8 @@ public static class TimeAttributionCalculator
|
||||
EndUtc = u.End,
|
||||
Seconds = ClampToWindows(u.Start, u.End, windows)?.Seconds ?? 0,
|
||||
Kbs = u.Kbs,
|
||||
NotInstalledKbs = u.NotInstalledKbs,
|
||||
Outcome = u.Outcome,
|
||||
RebootCount = u.RebootCount,
|
||||
})
|
||||
.ToList(),
|
||||
@@ -774,28 +779,55 @@ public static class TimeAttributionCalculator
|
||||
public DateTime? AwaitingSignInEnd;
|
||||
|
||||
public List<string> Kbs = new();
|
||||
public List<string> NotInstalledKbs = new();
|
||||
public string Outcome = OsUpdateOutcomes.Unknown;
|
||||
public int RebootCount;
|
||||
}
|
||||
|
||||
private readonly struct PageRecord
|
||||
{
|
||||
public PageRecord(DateTime at, string cxhEvent, string? page, string? name)
|
||||
public PageRecord(DateTime at, string cxhEvent, string? page, string? name, string? result)
|
||||
{
|
||||
At = at;
|
||||
CxhEvent = cxhEvent;
|
||||
Page = page;
|
||||
Name = name;
|
||||
Result = result;
|
||||
}
|
||||
|
||||
public DateTime At { get; }
|
||||
public string CxhEvent { get; }
|
||||
public string? Page { get; }
|
||||
public string? Name { get; }
|
||||
public string? Result { get; }
|
||||
|
||||
public bool IsStartOf(string page) => CxhEvent == "page_started" && string.Equals(Page, page, StringComparison.OrdinalIgnoreCase);
|
||||
public bool IsStopOf(string page) => CxhEvent == "page_stopped" && string.Equals(Page, page, StringComparison.OrdinalIgnoreCase);
|
||||
}
|
||||
|
||||
/// <summary>One CBS servicing step (<c>windows_update_servicing</c>) of an OS package.</summary>
|
||||
private readonly struct ServicingStep
|
||||
{
|
||||
public ServicingStep(DateTime at, string? package, string? step, string? targetState)
|
||||
{
|
||||
At = at;
|
||||
Package = package;
|
||||
Step = step;
|
||||
TargetState = targetState;
|
||||
}
|
||||
|
||||
public DateTime At { get; }
|
||||
public string? Package { get; }
|
||||
public string? Step { get; }
|
||||
public string? TargetState { get; }
|
||||
|
||||
public bool ReachedInstalled =>
|
||||
string.Equals(Step, "state_reached", StringComparison.OrdinalIgnoreCase) &&
|
||||
string.Equals(TargetState, "Installed", StringComparison.OrdinalIgnoreCase);
|
||||
|
||||
public bool Failed => string.Equals(Step, "failed", StringComparison.OrdinalIgnoreCase);
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Page names that only an update in progress writes (field data 2026-10-02). Every visit
|
||||
/// logs init names such as <c>initialize_NDUPInstallCanceledInOptOut</c> and
|
||||
@@ -818,21 +850,48 @@ public static class TimeAttributionCalculator
|
||||
/// The update page's own record of a download or an install — evidence of an update next to
|
||||
/// the servicing steps (an agent caps the page names per run, so this is the weaker of the two).
|
||||
/// </summary>
|
||||
internal static bool IsUpdateActivityName(string? name) =>
|
||||
internal static bool IsUpdateActivityName(string? name) => HasMarker(name, UpdateActivityMarkers);
|
||||
|
||||
// Outcome evidence on the update page (field data 2026-10-03/05). Only the explicit failures
|
||||
// count: an update that installed fine can still log downloadInstallFailureHelper and a start
|
||||
// timeout after its "restart required" (session shape e4ecd6f8).
|
||||
private static readonly string[] UpdateSucceededMarkers =
|
||||
{
|
||||
"installSucceededRebootRequired", // also the _lcu twin
|
||||
"commitExpeditionDownloadInstallAsyncSucceeded",
|
||||
};
|
||||
|
||||
private static readonly string[] UpdateFailedMarkers =
|
||||
{
|
||||
"downloadFailedError",
|
||||
"installFailedError",
|
||||
"commitExpeditionDownloadInstallAsyncFailure",
|
||||
};
|
||||
|
||||
private static readonly string[] UpdateSkippedMarkers =
|
||||
{
|
||||
"SkipDownloadInstallButtonClicked", // someone selected Skip on the page
|
||||
};
|
||||
|
||||
private static bool HasMarker(string? name, string[] markers) =>
|
||||
name != null &&
|
||||
UpdateActivityMarkers.Any(marker => name.IndexOf(marker, StringComparison.OrdinalIgnoreCase) >= 0);
|
||||
markers.Any(marker => name.IndexOf(marker, StringComparison.OrdinalIgnoreCase) >= 0);
|
||||
|
||||
/// <summary>
|
||||
/// At most one update per observation window. <b>Begin:</b> the start of the update page
|
||||
/// (<see cref="UpdatePage"/>) whose visit holds update evidence — a servicing step or an
|
||||
/// At most one update per observation window. <b>Begin:</b> update-activity names the agent
|
||||
/// saw before the first observed start of the update page (<see cref="UpdatePage"/>) — it
|
||||
/// started after the visit they belong to — begin at the earliest of the first such name and
|
||||
/// the update's first servicing step (see <see cref="FindUpdateBegin"/>). Otherwise the start
|
||||
/// of the update page whose visit holds update evidence — a servicing step or an
|
||||
/// update-activity name before the visit ends (its stop, the <see cref="UpdateRestartPage"/>
|
||||
/// start or the next visit). Only when no page start was observed in the window: the first
|
||||
/// servicing step after the device-ESP exit. Never after the user is back. <b>Bound:</b> the first evidence of the
|
||||
/// user (user ESP apps, desktop, Hello wizard, a Complete declaration), the end of
|
||||
/// attribution (Failed) or the window end. <b>End:</b> the latest update evidence before the
|
||||
/// bound — page record, servicing step, or the end of a restart that began in the interval.
|
||||
/// With a restart in the interval the user is signed out: <c>awaiting_sign_in</c> runs from
|
||||
/// the end to the bound.
|
||||
/// start or the next visit). Only when no page start and no such name was observed in the
|
||||
/// window: the first servicing step after the window's device-ESP exit. Never after the user
|
||||
/// is back. <b>Bound:</b> the first evidence of the user (user ESP apps, desktop, Hello
|
||||
/// wizard, a Complete declaration), the end of attribution (Failed) or the window end.
|
||||
/// <b>End:</b> the latest update evidence before the bound — page record, servicing step, or
|
||||
/// the end of a restart that began in the interval. With a restart in the interval the user
|
||||
/// is signed out: <c>awaiting_sign_in</c> runs from the end to the bound. <b>Outcome:</b> the
|
||||
/// latest outcome evidence in [begin, bound) — see <see cref="ResolveOutcome"/>.
|
||||
/// </summary>
|
||||
private static List<OsUpdate> BuildOsUpdates(
|
||||
List<EnrollmentEvent> events, List<Window> windows, List<Anchor> anchors,
|
||||
@@ -841,7 +900,7 @@ public static class TimeAttributionCalculator
|
||||
var result = new List<OsUpdate>();
|
||||
|
||||
var pages = new List<PageRecord>();
|
||||
var servicing = new List<(DateTime At, string? Package)>();
|
||||
var servicing = new List<ServicingStep>();
|
||||
foreach (var evt in events)
|
||||
{
|
||||
if (evt.EventType == Constants.EventTypes.OobeUpdatePage && evt.Data != null)
|
||||
@@ -849,11 +908,14 @@ public static class TimeAttributionCalculator
|
||||
pages.Add(new PageRecord(evt.Timestamp,
|
||||
DataString(evt.Data, "cxhEvent") ?? string.Empty,
|
||||
DataString(evt.Data, "page"),
|
||||
DataString(evt.Data, "name")));
|
||||
DataString(evt.Data, "name"),
|
||||
DataString(evt.Data, "result")));
|
||||
}
|
||||
else if (evt.EventType == Constants.EventTypes.WindowsUpdateServicing)
|
||||
{
|
||||
servicing.Add((evt.Timestamp, evt.Data != null ? DataString(evt.Data, "package") : null));
|
||||
servicing.Add(evt.Data != null
|
||||
? new ServicingStep(evt.Timestamp, DataString(evt.Data, "package"), DataString(evt.Data, "step"), DataString(evt.Data, "targetState"))
|
||||
: new ServicingStep(evt.Timestamp, null, null, null));
|
||||
}
|
||||
}
|
||||
if (servicing.Count == 0 && !pages.Any(p => IsUpdateActivityName(p.Name))) return result;
|
||||
@@ -874,11 +936,17 @@ public static class TimeAttributionCalculator
|
||||
.OrderBy(t => t)
|
||||
.ToList();
|
||||
var attributionEnd = anchors.FirstOrDefault(a => a.Bucket == null)?.Ts;
|
||||
var deviceEspExit = events.FirstOrDefault(e => e.EventType == Constants.EventTypes.EspExiting)?.Timestamp;
|
||||
// esp_exiting fires for the Device→Account handoff AND the final exit and is never
|
||||
// replayed; each window picks its own (a WhiteGlove part-1 exit never bounds part 2).
|
||||
var espExits = events
|
||||
.Where(e => e.EventType == Constants.EventTypes.EspExiting)
|
||||
.Select(e => e.Timestamp)
|
||||
.OrderBy(t => t)
|
||||
.ToList();
|
||||
|
||||
foreach (var window in windows)
|
||||
{
|
||||
var begin = FindUpdateBegin(window, pages, evidence, servicing, deviceEspExit, userBack);
|
||||
var begin = FindUpdateBegin(window, pages, evidence, servicing, espExits, userBack, attributionEnd);
|
||||
if (!begin.HasValue) continue;
|
||||
|
||||
var bound = window.End;
|
||||
@@ -896,13 +964,22 @@ public static class TimeAttributionCalculator
|
||||
{
|
||||
if (page.At > update.End && page.At < bound) update.End = page.At;
|
||||
}
|
||||
foreach (var (at, package) in servicing)
|
||||
var servicedKbs = new List<string>();
|
||||
var installedKbs = new HashSet<string>(StringComparer.OrdinalIgnoreCase);
|
||||
foreach (var step in servicing)
|
||||
{
|
||||
if (at < begin.Value || at >= bound) continue;
|
||||
if (at > update.End) update.End = at;
|
||||
var kb = ExtractKb(package);
|
||||
if (kb != null && !update.Kbs.Contains(kb)) update.Kbs.Add(kb);
|
||||
if (step.At < begin.Value || step.At >= bound) continue;
|
||||
if (step.At > update.End) update.End = step.At;
|
||||
var kb = ExtractKb(step.Package);
|
||||
if (kb == null) continue;
|
||||
if (!servicedKbs.Contains(kb)) servicedKbs.Add(kb);
|
||||
if (step.ReachedInstalled) installedKbs.Add(kb);
|
||||
}
|
||||
// A KB counts as installed only once its package reached "Installed"; a failed
|
||||
// update can leave packages staged.
|
||||
update.Kbs = servicedKbs.Where(installedKbs.Contains).ToList();
|
||||
update.NotInstalledKbs = servicedKbs.Where(kb => !installedKbs.Contains(kb)).ToList();
|
||||
update.Outcome = ResolveOutcome(pages, servicing, begin.Value, bound);
|
||||
foreach (var (gapStart, gapEnd) in rebootGaps)
|
||||
{
|
||||
if (gapStart < begin.Value || gapStart >= bound) continue;
|
||||
@@ -923,11 +1000,86 @@ public static class TimeAttributionCalculator
|
||||
}
|
||||
|
||||
private static DateTime? FindUpdateBegin(
|
||||
Window window, List<PageRecord> pages, List<DateTime> evidence,
|
||||
List<(DateTime At, string? Package)> servicing, DateTime? deviceEspExit, List<DateTime> userBack)
|
||||
Window window, List<PageRecord> pages, List<DateTime> evidence, List<ServicingStep> servicing,
|
||||
List<DateTime> espExits, List<DateTime> userBack, DateTime? attributionEnd)
|
||||
{
|
||||
// An update after the user is back runs beside the enrollment, not instead of it.
|
||||
bool UserBackBy(DateTime t) => userBack.Any(u => u > window.Start && u <= t);
|
||||
bool InWindow(DateTime t) => t >= window.Start && t < window.End;
|
||||
|
||||
// This window's device-ESP exit before the given moment, if one was observed.
|
||||
DateTime? EspExitBefore(DateTime before)
|
||||
{
|
||||
foreach (var exit in espExits)
|
||||
{
|
||||
if (exit < window.Start) continue;
|
||||
if (exit >= window.End || exit >= before) break;
|
||||
return exit;
|
||||
}
|
||||
return null;
|
||||
}
|
||||
|
||||
DateTime? firstPageStart = null;
|
||||
foreach (var page in pages)
|
||||
{
|
||||
if (!page.IsStartOf(UpdatePage) || !InWindow(page.At)) continue;
|
||||
firstPageStart = page.At;
|
||||
break;
|
||||
}
|
||||
|
||||
// Update-activity names before the first observed page start: the agent started after
|
||||
// the visit they belong to (a first run reads no Shell-Core history), so its start is
|
||||
// missing. Evaluated first — their visit lies before any observed one.
|
||||
DateTime? firstOrphanName = null;
|
||||
foreach (var page in pages)
|
||||
{
|
||||
if (firstPageStart.HasValue && page.At >= firstPageStart.Value) break;
|
||||
if (!InWindow(page.At) || !IsUpdateActivityName(page.Name) || UserBackBy(page.At)) continue;
|
||||
firstOrphanName = page.At;
|
||||
break;
|
||||
}
|
||||
if (firstOrphanName.HasValue)
|
||||
{
|
||||
var firstName = firstOrphanName.Value;
|
||||
DateTime? firstStep = null;
|
||||
var exitBefore = EspExitBefore(firstName);
|
||||
if (exitBefore.HasValue)
|
||||
{
|
||||
// A known exit bounds it as in v4: the first servicing step after the exit.
|
||||
foreach (var step in servicing)
|
||||
{
|
||||
if (step.At < exitBefore.Value || step.At < window.Start) continue;
|
||||
if (step.At < firstName) firstStep = step.At;
|
||||
break;
|
||||
}
|
||||
}
|
||||
else
|
||||
{
|
||||
// No exit observed: the earliest step of a package this update also serviced at or
|
||||
// after its first name — the servicing watcher backfills an hour, so the update's
|
||||
// early staging is there; a package finished before (the OOBE's own) is not.
|
||||
var limit = window.End;
|
||||
if (attributionEnd.HasValue && attributionEnd.Value < limit) limit = attributionEnd.Value;
|
||||
foreach (var u in userBack)
|
||||
{
|
||||
if (u <= firstName) continue;
|
||||
if (u < limit) limit = u;
|
||||
break;
|
||||
}
|
||||
var members = new HashSet<string>(
|
||||
servicing.Where(s => s.At >= firstName && s.At < limit && !string.IsNullOrEmpty(s.Package)).Select(s => s.Package!),
|
||||
StringComparer.OrdinalIgnoreCase);
|
||||
foreach (var step in servicing)
|
||||
{
|
||||
if (step.At < window.Start) continue;
|
||||
if (step.At >= firstName) break;
|
||||
if (string.IsNullOrEmpty(step.Package) || !members.Contains(step.Package!)) continue;
|
||||
firstStep = step.At;
|
||||
break;
|
||||
}
|
||||
}
|
||||
return firstStep.HasValue && firstStep.Value < firstName ? firstStep.Value : firstName;
|
||||
}
|
||||
|
||||
var pageStartSeen = false;
|
||||
for (var i = 0; i < pages.Count; i++)
|
||||
@@ -963,17 +1115,62 @@ public static class TimeAttributionCalculator
|
||||
// a servicing step beside it is some other update.
|
||||
if (pageStartSeen) return null;
|
||||
|
||||
// Fallback: the page start was not observed (the agent started after it). The first
|
||||
// servicing step after the device-ESP exit — without the download before it.
|
||||
if (!deviceEspExit.HasValue) return null;
|
||||
foreach (var (at, _) in servicing)
|
||||
// Fallback: neither the page start nor an update name was observed (the agent started
|
||||
// after the page and saw only CBS). The first servicing step after this window's
|
||||
// device-ESP exit before the user is back — without the download before it.
|
||||
DateTime? deviceEspExit = null;
|
||||
foreach (var exit in espExits)
|
||||
{
|
||||
if (at < deviceEspExit.Value || at < window.Start || at >= window.End) continue;
|
||||
return UserBackBy(at) ? null : at;
|
||||
if (exit < window.Start) continue;
|
||||
if (exit >= window.End || UserBackBy(exit)) break;
|
||||
deviceEspExit = exit;
|
||||
break;
|
||||
}
|
||||
if (!deviceEspExit.HasValue) return null;
|
||||
foreach (var step in servicing)
|
||||
{
|
||||
if (step.At < deviceEspExit.Value || step.At < window.Start || step.At >= window.End) continue;
|
||||
return UserBackBy(step.At) ? null : step.At;
|
||||
}
|
||||
return null;
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// How the update in [begin, bound) ended: the latest outcome evidence decides — a package
|
||||
/// reaching "Installed" or the page's install success (installed), an explicit download or
|
||||
/// install failure, a failed servicing step or a page stop with result "fail" (failed), or the
|
||||
/// page's Skip button (skipped). A later attempt overrides an earlier one (a failure retried
|
||||
/// and installed is installed; a failure followed by Skip is skipped). No evidence: unknown.
|
||||
/// </summary>
|
||||
private static string ResolveOutcome(List<PageRecord> pages, List<ServicingStep> servicing, DateTime begin, DateTime bound)
|
||||
{
|
||||
DateTime? latest = null;
|
||||
var outcome = OsUpdateOutcomes.Unknown;
|
||||
void Consider(DateTime at, string kind)
|
||||
{
|
||||
if (latest.HasValue && at < latest.Value) return;
|
||||
latest = at;
|
||||
outcome = kind;
|
||||
}
|
||||
|
||||
foreach (var page in pages)
|
||||
{
|
||||
if (page.At < begin || page.At >= bound) continue;
|
||||
if (HasMarker(page.Name, UpdateSucceededMarkers)) Consider(page.At, OsUpdateOutcomes.Installed);
|
||||
else if (HasMarker(page.Name, UpdateFailedMarkers)) Consider(page.At, OsUpdateOutcomes.Failed);
|
||||
else if (HasMarker(page.Name, UpdateSkippedMarkers)) Consider(page.At, OsUpdateOutcomes.Skipped);
|
||||
else if (page.IsStopOf(UpdatePage) && string.Equals(page.Result, "fail", StringComparison.OrdinalIgnoreCase))
|
||||
Consider(page.At, OsUpdateOutcomes.Failed);
|
||||
}
|
||||
foreach (var step in servicing)
|
||||
{
|
||||
if (step.At < begin || step.At >= bound) continue;
|
||||
if (step.ReachedInstalled) Consider(step.At, OsUpdateOutcomes.Installed);
|
||||
else if (step.Failed) Consider(step.At, OsUpdateOutcomes.Failed);
|
||||
}
|
||||
return outcome;
|
||||
}
|
||||
|
||||
private static string? ExtractKb(string? package)
|
||||
{
|
||||
if (string.IsNullOrEmpty(package)) return null;
|
||||
|
||||
@@ -3060,8 +3060,12 @@ export interface OsUpdateSpan {
|
||||
endUtc: string;
|
||||
/** In-window seconds of the interval. */
|
||||
seconds: number;
|
||||
/** KB numbers of the packages Windows serviced in the interval ("KB5129195"), in order of first appearance; empty when no package named one. */
|
||||
/** KB numbers of the packages that reached "Installed" in the interval ("KB5129195"), in order of first appearance; empty when none did or no package named one. */
|
||||
kbs: string[];
|
||||
/** KB numbers of the packages Windows serviced in the interval without reaching "Installed" (for example only staged before a failed download). */
|
||||
notInstalledKbs: string[];
|
||||
/** How the update ended — one of OsUpdateOutcomes; the latest outcome evidence in the interval decides. */
|
||||
outcome: string;
|
||||
/** Restarts that began inside the interval. */
|
||||
rebootCount: number;
|
||||
}
|
||||
|
||||
@@ -2060,8 +2060,8 @@ export function registerAdminTools(server: McpServer, ga: boolean, strictGa: boo
|
||||
'time breakdown — wall-clock partition into device_prep / esp_apps / os_update / awaiting_sign_in / ' +
|
||||
'identity_hello / user_esp / desktop_handoff spans plus an EXPLICIT unattributed remainder (sums are exact ' +
|
||||
'against the session\'s authoritative duration; the WhiteGlove pause is excluded by design; os_update = the ' +
|
||||
'OOBE quality update, its KBs and restarts in osUpdates; awaiting_sign_in = after that update\'s restart ' +
|
||||
'until the user is back), the ESP-blocking app install ' +
|
||||
'OOBE quality update, its outcome, installed and not installed KBs and restarts in osUpdates; ' +
|
||||
'awaiting_sign_in = after that update\'s restart until the user is back), the ESP-blocking app install ' +
|
||||
'intervals with critical-path occupancy (an app\'s seconds = its ACTIVE install time summed across all ' +
|
||||
'IME passes/attempts — deliberately broader than get_app_install_metrics\' final-attempt duration, ' +
|
||||
'because a failed attempt and an evaluation pass still occupied the critical path), reboot outage ' +
|
||||
|
||||
@@ -658,7 +658,7 @@ namespace AutopilotMonitor.Shared
|
||||
// update page (CXID OobeNDUP / RebootNDUP) and its ExpeditedUpdate_* event names, plus the
|
||||
// registry state behind it (NDUP keys and both ESP "Install Windows quality updates"
|
||||
// policy paths). Bounded per agent run.
|
||||
public const string OobeUpdatePage = "oobe_update_page"; // Shell-Core 62404/62405 of an NDUP page, 62406/62407 update-page names — Data.cxhEvent+page+result+name(+value: boolean/integer/HRESULT only)
|
||||
public const string OobeUpdatePage = "oobe_update_page"; // Shell-Core 62404/62405 of an NDUP page, 62406/62407 update-page names — Data.cxhEvent+page+result+name(+value: boolean/integer/HRESULT only); cxhEvent names_capped = the run's later names were not sent
|
||||
public const string OobeUpdateState = "oobe_update_state"; // NDUP + ESP-policy registry values at agent start/stop and at the update page — Data.moment + one entry per key alias; only when values exist and changed
|
||||
// Corroboration snapshots (gather rules, config-delivered). Secondary evidence that an
|
||||
// update landed during enrollment even when the watcher's backfill window missed it.
|
||||
@@ -930,19 +930,28 @@ namespace AutopilotMonitor.Shared
|
||||
/// <summary>CBS servicing steps from the Setup log.</summary>
|
||||
public const string ServicingWatcher = "ServicingWatcher";
|
||||
|
||||
/// <summary>
|
||||
/// The OOBE update page telemetry from the Shell-Core log (<c>oobe_update_page</c>,
|
||||
/// <c>oobe_update_state</c>). The ESP and Hello signals read from the same log carry
|
||||
/// the source "EspAndHelloTracker".
|
||||
/// </summary>
|
||||
public const string ShellCoreTracker = "ShellCoreTracker";
|
||||
|
||||
/// <summary>
|
||||
/// Sources whose rows never set a session's start. Their watchers backfill the Windows
|
||||
/// event logs with the original event time — clock steps and sleep up to 24 h, update
|
||||
/// and servicing activity up to 60 min before the agent started — so their earliest row
|
||||
/// is environment observation from before the enrollment, not its first step. Every
|
||||
/// place that derives the start from events applies this list: backend ingest and the
|
||||
/// Events-table probe, and the portal's session duration via shared-manifests.json.
|
||||
/// and servicing activity and the update page up to 60 min before the agent started —
|
||||
/// so their earliest row is environment observation from before the enrollment, not
|
||||
/// its first step. Every place that derives the start from events applies this list:
|
||||
/// backend ingest and the Events-table probe, and the portal's session duration via
|
||||
/// shared-manifests.json.
|
||||
/// </summary>
|
||||
public static readonly string[] SessionAnchorIneligible =
|
||||
{
|
||||
SystemTimelineWatcher,
|
||||
WindowsUpdateWatcher,
|
||||
ServicingWatcher,
|
||||
ShellCoreTracker,
|
||||
};
|
||||
|
||||
/// <summary>
|
||||
|
||||
@@ -18,10 +18,11 @@ namespace AutopilotMonitor.Shared.Models
|
||||
public const string EspApps = "esp_apps";
|
||||
|
||||
/// <summary>
|
||||
/// The OOBE quality update (D-310): from the start of the update page that installed an
|
||||
/// update to the last update evidence before the user is back — download, install, the
|
||||
/// restarts and the servicing after them. Takes the time from the phase segment it
|
||||
/// overlaps; one <see cref="OsUpdateSpan"/> per interval names the packages.
|
||||
/// The OOBE quality update (D-310): from the start of the update page that worked on an
|
||||
/// update — or, when the agent started after the page, from the update's first evidence —
|
||||
/// to the last update evidence before the user is back: download, install, the restarts
|
||||
/// and the servicing after them. Takes the time from the phase segment it overlaps; one
|
||||
/// <see cref="OsUpdateSpan"/> per interval names the packages and the outcome.
|
||||
/// </summary>
|
||||
public const string OsUpdate = "os_update";
|
||||
|
||||
@@ -196,13 +197,40 @@ namespace AutopilotMonitor.Shared.Models
|
||||
/// <summary>In-window seconds of the interval.</summary>
|
||||
public int Seconds { get; set; }
|
||||
|
||||
/// <summary>KB numbers of the packages Windows serviced in the interval ("KB5129195"), in order of first appearance; empty when no package named one.</summary>
|
||||
/// <summary>KB numbers of the packages that reached "Installed" in the interval ("KB5129195"), in order of first appearance; empty when none did or no package named one.</summary>
|
||||
public List<string> Kbs { get; set; } = new List<string>();
|
||||
|
||||
/// <summary>KB numbers of the packages Windows serviced in the interval without reaching "Installed" (for example only staged before a failed download).</summary>
|
||||
public List<string> NotInstalledKbs { get; set; } = new List<string>();
|
||||
|
||||
/// <summary>How the update ended — one of <see cref="OsUpdateOutcomes"/>; the latest outcome evidence in the interval decides.</summary>
|
||||
public string Outcome { get; set; } = OsUpdateOutcomes.Unknown;
|
||||
|
||||
/// <summary>Restarts that began inside the interval.</summary>
|
||||
public int RebootCount { get; set; }
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Outcome of an OOBE quality update (<see cref="OsUpdateSpan.Outcome"/>), decided by the
|
||||
/// latest outcome evidence in its interval. Exported to the portal via shared-manifests.json.
|
||||
/// </summary>
|
||||
public static class OsUpdateOutcomes
|
||||
{
|
||||
/// <summary>A package reached "Installed", or the update page reported the install as succeeded.</summary>
|
||||
public const string Installed = "installed";
|
||||
|
||||
/// <summary>The update page or servicing reported the download or install as failed.</summary>
|
||||
public const string Failed = "failed";
|
||||
|
||||
/// <summary>Someone selected Skip on the update page; the update was not installed.</summary>
|
||||
public const string Skipped = "skipped";
|
||||
|
||||
/// <summary>No outcome evidence before the interval ended (for example the session ended first).</summary>
|
||||
public const string Unknown = "unknown";
|
||||
|
||||
public static readonly string[] All = { Installed, Failed, Skipped, Unknown };
|
||||
}
|
||||
|
||||
/// <summary>
|
||||
/// Per-session enrollment time attribution (F1, insights spec) — an exact partition of the
|
||||
/// session's authoritative wall clock into named segments plus an explicit unattributed
|
||||
|
||||
+8
-4
@@ -88,6 +88,10 @@ function formatByKind(kind: RowKind | undefined, value: unknown): string {
|
||||
|
||||
// ── Row and section primitives ───────────────────────────────────────────────
|
||||
|
||||
// Heavier rule between grouped rows. It sits on the cell: the section tbody's divide utility overrides
|
||||
// a row's border width and color, while the collapsed table border keeps the wider cell edge.
|
||||
const GROUP_SEPARATOR = 'border-t-2 border-gray-200 dark:border-gray-600';
|
||||
|
||||
interface ConfigRowProps {
|
||||
label: string;
|
||||
display: string;
|
||||
@@ -185,8 +189,8 @@ function ChannelRows({ config }: { config: TenantConfiguration }) {
|
||||
return (
|
||||
<>
|
||||
{channels.map((ch, i) => (
|
||||
<tr key={ch.id ?? i} className={i > 0 ? 'border-t-2 border-gray-200 dark:border-gray-600' : ''}>
|
||||
<td colSpan={2} className="p-0">
|
||||
<tr key={ch.id ?? i}>
|
||||
<td colSpan={2} className={`p-0 ${i > 0 ? GROUP_SEPARATOR : ''}`}>
|
||||
<table className="w-full">
|
||||
<tbody className="divide-y divide-gray-100 dark:divide-gray-700">
|
||||
<ConfigRow label="Channel" display={`${ch.name || ch.id}${ch.enabled === false ? ' (disabled)' : ''}`} />
|
||||
@@ -214,8 +218,8 @@ function SelfHostedAiClientRows({ list }: { list: McpClientRegistrationListRespo
|
||||
<ConfigRow label="Self-hosted AI (platform switch)" display={list.enabled ? 'On' : 'Off'} />
|
||||
{list.registrations.length === 0 && <ConfigRow label="Self-hosted AI Clients" display="—" />}
|
||||
{list.registrations.map((r) => (
|
||||
<tr key={r.registrationId} className="border-t-2 border-gray-200 dark:border-gray-600">
|
||||
<td colSpan={2} className="p-0">
|
||||
<tr key={r.registrationId}>
|
||||
<td colSpan={2} className={`p-0 ${GROUP_SEPARATOR}`}>
|
||||
<table className="w-full">
|
||||
<tbody className="divide-y divide-gray-100 dark:divide-gray-700">
|
||||
<ConfigRow label="Self-hosted AI Client" display={r.name} />
|
||||
|
||||
@@ -436,8 +436,8 @@ export default function GeographicPerformancePage() {
|
||||
key={loc.locationKey}
|
||||
id={`loc-${loc.locationKey.replace(/[^a-zA-Z0-9]/g, "-")}`}
|
||||
className={`hover:bg-gray-50 transition-colors cursor-pointer ${
|
||||
loc.isOutlier ? "border-l-4 border-l-red-400" : ""
|
||||
} ${selectedLocation === loc.locationKey ? "bg-blue-50" : ""}`}
|
||||
selectedLocation === loc.locationKey ? "bg-blue-50" : ""
|
||||
}`}
|
||||
onClick={() => {
|
||||
const days = timeRange === "7d" ? 7 : timeRange === "30d" ? 30 : 90;
|
||||
// Carry the selected tenant into the drill-in so a cross-tenant caller (GA override
|
||||
@@ -447,7 +447,8 @@ export default function GeographicPerformancePage() {
|
||||
}}
|
||||
onMouseEnter={() => setSelectedLocation(loc.locationKey)}
|
||||
>
|
||||
<td className="px-4 py-3 text-sm text-gray-900">
|
||||
{/* Outlier accent on the cell, not the row: the tbody's divide color overrides a row's border-color. */}
|
||||
<td className={`px-4 py-3 text-sm text-gray-900 ${loc.isOutlier ? "border-l-4 border-l-red-400" : ""}`}>
|
||||
<div className="flex items-center">
|
||||
<span className="font-medium">{loc.locationKey}</span>
|
||||
{loc.isOutlier && (
|
||||
|
||||
@@ -2,6 +2,7 @@
|
||||
|
||||
import React from "react";
|
||||
import type { SessionTimeBreakdown } from "@/utils/wire-types.generated";
|
||||
import { osUpdateDetail } from "./timeAttributionLogic";
|
||||
|
||||
/**
|
||||
* F1 time attribution (insights spec §F1): renders the PRE-COMPUTED breakdown row of a
|
||||
@@ -85,15 +86,9 @@ export default function TimeAttributionLane({ breakdown }: { breakdown: SessionT
|
||||
}
|
||||
totals.set("unattributed", breakdown.unattributedSeconds);
|
||||
|
||||
// What the OOBE quality update installed and how often it restarted — named on the
|
||||
// Windows Update slice (the server computed it; the client only joins the lists).
|
||||
const osUpdates = breakdown.osUpdates ?? [];
|
||||
const updateKbs = Array.from(new Set(osUpdates.flatMap(u => u.kbs ?? [])));
|
||||
const updateRestarts = osUpdates.reduce((sum, u) => sum + (u.rebootCount ?? 0), 0);
|
||||
const updateDetail = [
|
||||
updateKbs.join(", "),
|
||||
updateRestarts > 0 ? `${updateRestarts} restart${updateRestarts !== 1 ? "s" : ""}` : "",
|
||||
].filter(Boolean).join(" · ");
|
||||
// How the OOBE quality update ended, what it installed and how often it restarted — named on
|
||||
// the Windows Update slice.
|
||||
const updateDetail = osUpdateDetail(breakdown.osUpdates ?? []);
|
||||
|
||||
const parts = SEGMENT_META
|
||||
.map(meta => ({
|
||||
|
||||
+39
@@ -0,0 +1,39 @@
|
||||
import { describe, expect, it } from "vitest";
|
||||
import { SHARED_MANIFEST } from "@/utils/shared-manifests.generated";
|
||||
import { osUpdateDetail } from "../timeAttributionLogic";
|
||||
|
||||
describe("osUpdateDetail", () => {
|
||||
it("names the outcome, the installed KBs and the restarts of an installed update", () => {
|
||||
expect(osUpdateDetail([
|
||||
{ outcome: "installed", kbs: ["KB5124007", "KB5129195", "KB5054156"], notInstalledKbs: [], rebootCount: 2 },
|
||||
])).toBe("installed · KB5124007, KB5129195, KB5054156 · 2 restarts");
|
||||
});
|
||||
|
||||
it("names a failed update's staged KB as not installed", () => {
|
||||
// Field shape e7551b82: only the servicing stack was staged before the download failed.
|
||||
expect(osUpdateDetail([
|
||||
{ outcome: "failed", kbs: [], notInstalledKbs: ["KB5124007"], rebootCount: 1 },
|
||||
])).toBe("failed · not installed: KB5124007 · 1 restart");
|
||||
});
|
||||
|
||||
it("names a skipped update", () => {
|
||||
expect(osUpdateDetail([{ outcome: "skipped", kbs: [], notInstalledKbs: [], rebootCount: 0 }])).toBe("skipped");
|
||||
});
|
||||
|
||||
it("names no outcome for an unknown one or a row written before the outcome existed", () => {
|
||||
expect(osUpdateDetail([{ outcome: "unknown", kbs: ["KB5129195"], rebootCount: 0 }])).toBe("KB5129195");
|
||||
expect(osUpdateDetail([{ kbs: ["KB5129195"], rebootCount: 3 }])).toBe("KB5129195 · 3 restarts");
|
||||
});
|
||||
|
||||
it("is empty without updates", () => {
|
||||
expect(osUpdateDetail([])).toBe("");
|
||||
});
|
||||
|
||||
it("labels every outcome the backend can send", () => {
|
||||
// A new backend outcome must get its words here, not fall through as unnamed.
|
||||
for (const outcome of SHARED_MANIFEST.osUpdateOutcomes) {
|
||||
const detail = osUpdateDetail([{ outcome, kbs: [], notInstalledKbs: [], rebootCount: 0 }]);
|
||||
expect(detail).toBe(outcome === "unknown" ? "" : outcome);
|
||||
}
|
||||
});
|
||||
});
|
||||
@@ -0,0 +1,37 @@
|
||||
import type { OsUpdateSpan } from "@/utils/wire-types.generated";
|
||||
import { SHARED_MANIFEST } from "@/utils/shared-manifests.generated";
|
||||
|
||||
/** How an OOBE quality update ended (backend `OsUpdateOutcomes`). */
|
||||
export type OsUpdateOutcome = (typeof SHARED_MANIFEST.osUpdateOutcomes)[number];
|
||||
|
||||
/** The words the Windows Update slice names an outcome with; "unknown" names nothing. */
|
||||
const OUTCOME_LABELS: Record<OsUpdateOutcome, string | null> = {
|
||||
installed: "installed",
|
||||
failed: "failed",
|
||||
skipped: "skipped",
|
||||
unknown: null,
|
||||
};
|
||||
|
||||
/**
|
||||
* What the OOBE quality update did, for the Windows Update slice: the outcome, the KBs that
|
||||
* reached "Installed", the ones it serviced without installing, and its restarts — e.g.
|
||||
* "failed · not installed: KB5124007 · 1 restart". The server computed every part; this only
|
||||
* joins the lists. Rows written before the outcome existed carry none and name no outcome.
|
||||
*/
|
||||
export function osUpdateDetail(osUpdates: ReadonlyArray<Partial<OsUpdateSpan>>): string {
|
||||
const outcomes = distinct(osUpdates.map(u => OUTCOME_LABELS[u.outcome as OsUpdateOutcome] ?? null));
|
||||
const installed = distinct(osUpdates.flatMap(u => u.kbs ?? []));
|
||||
const notInstalled = distinct(osUpdates.flatMap(u => u.notInstalledKbs ?? []));
|
||||
const restarts = osUpdates.reduce((sum, u) => sum + (u.rebootCount ?? 0), 0);
|
||||
|
||||
return [
|
||||
outcomes.join(", "),
|
||||
installed.join(", "),
|
||||
notInstalled.length > 0 ? `not installed: ${notInstalled.join(", ")}` : "",
|
||||
restarts > 0 ? `${restarts} restart${restarts !== 1 ? "s" : ""}` : "",
|
||||
].filter(Boolean).join(" · ");
|
||||
}
|
||||
|
||||
function distinct(values: ReadonlyArray<string | null>): string[] {
|
||||
return Array.from(new Set(values.filter((v): v is string => !!v)));
|
||||
}
|
||||
@@ -298,9 +298,10 @@ export default function Navbar() {
|
||||
</div>
|
||||
) : (
|
||||
<div className="divide-y divide-gray-100">
|
||||
{/* Row accents are inset shadows, not border-l: the divide color overrides a child's border-color on every row but the first. */}
|
||||
{/* Tenant-scoped persistent notifications (e.g. hardware rejections) — top */}
|
||||
{tenantNotifications.map((tn) => (
|
||||
<div key={`tn-${tn.id}`} className={`px-4 py-3 hover:bg-blue-50/50 dark:hover:bg-blue-900/45 transition-colors border-l-4 border-blue-500 bg-blue-50/30 dark:bg-blue-900/20 ${tn.href ? 'cursor-pointer' : ''}`} onClick={() => { if (tn.href) openNotificationHref(tn.href); }}>
|
||||
<div key={`tn-${tn.id}`} className={`px-4 py-3 hover:bg-blue-50/50 dark:hover:bg-blue-900/45 transition-colors shadow-[inset_4px_0_0_0] shadow-blue-500 bg-blue-50/30 dark:bg-blue-900/20 ${tn.href ? 'cursor-pointer' : ''}`} onClick={() => { if (tn.href) openNotificationHref(tn.href); }}>
|
||||
<div className="flex items-start justify-between">
|
||||
<div className="flex items-start space-x-2.5 flex-1">
|
||||
<span className="text-lg">{tn.type === 'hardware_rejection' ? '🖥️' : '🔔'}</span>
|
||||
@@ -333,7 +334,7 @@ export default function Navbar() {
|
||||
))}
|
||||
{/* Persistent Global Admin Notifications */}
|
||||
{visibleGlobal.map((gn) => (
|
||||
<div key={`ga-${gn.id}`} className={`px-4 py-3 hover:bg-purple-50/50 dark:hover:bg-purple-900/45 transition-colors border-l-4 border-purple-500 bg-purple-50/30 dark:bg-purple-900/20 ${gn.href ? 'cursor-pointer' : ''}`} onClick={() => { if (gn.href) openNotificationHref(gn.href); }}>
|
||||
<div key={`ga-${gn.id}`} className={`px-4 py-3 hover:bg-purple-50/50 dark:hover:bg-purple-900/45 transition-colors shadow-[inset_4px_0_0_0] shadow-purple-500 bg-purple-50/30 dark:bg-purple-900/20 ${gn.href ? 'cursor-pointer' : ''}`} onClick={() => { if (gn.href) openNotificationHref(gn.href); }}>
|
||||
<div className="flex items-start justify-between">
|
||||
<div className="flex items-start space-x-2.5 flex-1">
|
||||
<span className="text-lg">{gn.type === 'session_report' ? '\uD83D\uDCCB' : '\uD83C\uDF1F'}</span>
|
||||
|
||||
@@ -95,13 +95,15 @@ describe("enrollmentWindowOf", () => {
|
||||
expect(w).toEqual({ startMs: Date.parse("2026-09-09T06:32:46Z"), endMs: Date.parse("2026-09-09T06:40:00Z") });
|
||||
});
|
||||
|
||||
it("ignores update and servicing rows backfilled from before the agent started", () => {
|
||||
// D-315: the update watchers deliver rows with their event-log time up to 60 min before the agent.
|
||||
it("ignores update, servicing and update-page rows backfilled from before the agent started", () => {
|
||||
// D-315: the update watchers deliver rows with their event-log time up to 60 min before the agent;
|
||||
// so does the update page telemetry on an agent's first run.
|
||||
const w = enrollmentWindowOf([
|
||||
activity(1, "2026-10-03T08:51:58Z", "windows_update_started", "WindowsUpdateWatcher"),
|
||||
activity(2, "2026-10-03T08:52:37Z", "windows_update_servicing", "ServicingWatcher"),
|
||||
activity(3, "2026-10-03T08:56:46Z", "ime_agent_version", "ImeLogTracker"),
|
||||
activity(4, "2026-10-03T10:08:09Z", "enrollment_complete", "DecisionEngine"),
|
||||
activity(3, "2026-10-03T08:53:10Z", "oobe_update_page", "ShellCoreTracker"),
|
||||
activity(4, "2026-10-03T08:56:46Z", "ime_agent_version", "ImeLogTracker"),
|
||||
activity(5, "2026-10-03T10:08:09Z", "enrollment_complete", "DecisionEngine"),
|
||||
]);
|
||||
expect(w).toEqual({ startMs: Date.parse("2026-10-03T08:56:46Z"), endMs: Date.parse("2026-10-03T10:08:09Z") });
|
||||
});
|
||||
|
||||
@@ -12,7 +12,7 @@ export interface StandbyWindow {
|
||||
/**
|
||||
* The enrollment window as the session page measures its duration: first activity event →
|
||||
* `enrollment_complete`, or the last activity event while no verdict exists. Backfilled
|
||||
* environment rows (clock steps, sleep, update and servicing activity) are excluded, as in the
|
||||
* environment rows (clock steps, sleep, update and servicing activity, the update page) are excluded, as in the
|
||||
* backend's session anchor — they carry Windows event-log timestamps from before the agent
|
||||
* started and would drag the start into pre-enrollment time. Null when the session has no
|
||||
* activity events.
|
||||
|
||||
@@ -506,7 +506,14 @@ export const SHARED_MANIFEST = {
|
||||
"sessionAnchorIneligibleSources": [
|
||||
"SystemTimelineWatcher",
|
||||
"WindowsUpdateWatcher",
|
||||
"ServicingWatcher"
|
||||
"ServicingWatcher",
|
||||
"ShellCoreTracker"
|
||||
],
|
||||
"osUpdateOutcomes": [
|
||||
"installed",
|
||||
"failed",
|
||||
"skipped",
|
||||
"unknown"
|
||||
],
|
||||
"ruleSubmissionKinds": [
|
||||
"gather",
|
||||
|
||||
@@ -502,7 +502,14 @@
|
||||
"sessionAnchorIneligibleSources": [
|
||||
"SystemTimelineWatcher",
|
||||
"WindowsUpdateWatcher",
|
||||
"ServicingWatcher"
|
||||
"ServicingWatcher",
|
||||
"ShellCoreTracker"
|
||||
],
|
||||
"osUpdateOutcomes": [
|
||||
"installed",
|
||||
"failed",
|
||||
"skipped",
|
||||
"unknown"
|
||||
],
|
||||
"ruleSubmissionKinds": [
|
||||
"gather",
|
||||
@@ -14410,7 +14417,26 @@
|
||||
"name": "string"
|
||||
}
|
||||
},
|
||||
"doc": "KB numbers of the packages Windows serviced in the interval (\"KB5129195\"), in order of first appearance; empty when no package named one."
|
||||
"doc": "KB numbers of the packages that reached \"Installed\" in the interval (\"KB5129195\"), in order of first appearance; empty when none did or no package named one."
|
||||
},
|
||||
{
|
||||
"name": "notInstalledKbs",
|
||||
"type": {
|
||||
"kind": "array",
|
||||
"element": {
|
||||
"kind": "primitive",
|
||||
"name": "string"
|
||||
}
|
||||
},
|
||||
"doc": "KB numbers of the packages Windows serviced in the interval without reaching \"Installed\" (for example only staged before a failed download)."
|
||||
},
|
||||
{
|
||||
"name": "outcome",
|
||||
"type": {
|
||||
"kind": "primitive",
|
||||
"name": "string"
|
||||
},
|
||||
"doc": "How the update ended — one of OsUpdateOutcomes; the latest outcome evidence in the interval decides."
|
||||
},
|
||||
{
|
||||
"name": "rebootCount",
|
||||
|
||||
@@ -3060,8 +3060,12 @@ export interface OsUpdateSpan {
|
||||
endUtc: string;
|
||||
/** In-window seconds of the interval. */
|
||||
seconds: number;
|
||||
/** KB numbers of the packages Windows serviced in the interval ("KB5129195"), in order of first appearance; empty when no package named one. */
|
||||
/** KB numbers of the packages that reached "Installed" in the interval ("KB5129195"), in order of first appearance; empty when none did or no package named one. */
|
||||
kbs: string[];
|
||||
/** KB numbers of the packages Windows serviced in the interval without reaching "Installed" (for example only staged before a failed download). */
|
||||
notInstalledKbs: string[];
|
||||
/** How the update ended — one of OsUpdateOutcomes; the latest outcome evidence in the interval decides. */
|
||||
outcome: string;
|
||||
/** Restarts that began inside the interval. */
|
||||
rebootCount: number;
|
||||
}
|
||||
|
||||
Reference in New Issue
Block a user