Private/Kinds/Logon.ps1
|
# The Logon Kind: where the time goes between signing in and a desktop that is ready. # # "It takes forever until I can work" is told to a Technician in one sentence, and Windows # keeps what it would take to answer it in three logs, none of which needs admin rights: # # Microsoft-Windows-Winlogon/Operational # 2 authentication ended, with a result: 0 is accepted # 811, 812 a notification subscriber began, and finished, handling an event. The # subscribers are the parts of Windows a sign-in waits for, one after the # other: Profiles loads the User Profile, GPClient applies Group Policy, # SessionEnv, TermSrv and Sens set the session up. Payload: the number of # the event, and the subscriber's name. The sign-in is event 2: observed # to the millisecond beside the User Profile Service's "logon notification # received". # Microsoft-Windows-Shell-Core/Operational # 62170, 62171 a logon task of the shell began, and finished: AllLogonTasks spans # them all. Logged by the Explorer of the account that signed in. # 9707, 9708 a command of a Run key was started, and finished. Windows starts the # programs of the Run keys one after the other: seen on the machine # this was written on, twelve of them thirty seconds apart, the last # six minutes after the sign-in. What the thirty seconds are, Microsoft # does not say, and the Report says what was measured. # Microsoft-Windows-User Profile Service/Operational # 5 the registry of an account is loaded, under its SID: whose sign-in it is # # Verified against the event manifests: docs/research/logon-events.md. # # A sign-in is put together from them: the subscribers of event 2 in one Winlogon # process, the shell's tasks that began next, by the Explorer of one account, and that # Explorer's Run keys. What the Report shows of the commands is the name of the program, # which is an autostart entry and state (ADR-0006); of the sign-ins of other accounts it # shows when, and how long to the desktop, and no programs. # # What the Gatherer returns: # Days, Since, UnreadableLogs, ScannedLogs, LogCoverage as the NetworkDisruption Kind # SignIns newest first, each # { Time, Account, Own, NotifyMs, Subscribers = { Name, Ms }, ShellSeen, # ShellStartMs, ShellTasksMs, DesktopMs, Tasks = { Name, StartMs, Ms }, # Commands = { Name, StartMs, Ms }, AutostartLastStartMs } # Times in milliseconds from the sign-in; $null where a log does not say. # Tasks, Commands and AutostartLastStartMs only of the User's own sign-ins. # # Not in any log a Run without admin rights can read, and so not a phase here: how long # the sign-in waited for the network, and how long logon scripts ran. Both are in the # Group Policy log, which is the GroupPolicy Kind's. $script:LogonDefaultDays = 30 $script:LogonWinlogonLog = 'Microsoft-Windows-Winlogon/Operational' $script:LogonShellLog = 'Microsoft-Windows-Shell-Core/Operational' $script:LogonProfileLog = 'Microsoft-Windows-User Profile Service/Operational' # The number Winlogon gives the sign-in among the events it notifies its subscribers of. $script:LogonSignInEvent = '2' # How long after a sign-in its shell may begin and still be that sign-in's, and how long # after the shell its Run keys may be gone through: Windows holds the programs of the Run # keys back, and the last of many starts minutes later. $script:LogonShellWithinSeconds = 300 $script:LogonAutostartWithinSeconds = 1800 function Get-LogonProgramName { <# .SYNOPSIS The program a command of a Run key starts, by its file name. Pure. .DESCRIPTION A command is a path with arguments, and the arguments are nobody's to read: a file a program is told to open is content (ADR-0006). The name of the program is the autostart entry: the first file the command names. Where that is rundll32, the library it loads is the program. Where it is another interpreter - cmd, PowerShell, the script hosts - the interpreter is all that is named: what it is handed may be a document on somebody's desktop. #> [CmdletBinding()] [OutputType([string])] param([AllowNull()][AllowEmptyString()][string]$Command) $text = "$Command".Trim() if (-not $text) { return '' } $files = @([regex]::Matches($text, '(?i)([^\\/"\s,]+\.(?:exe|dll|cmd|bat|vbs|ps1|lnk|com|msc))') | ForEach-Object { $_.Groups[1].Value }) if (-not $files.Count) { return '' } if ("$($files[0])" -match '^(?i)rundll32\.exe$') { $library = @($files | Where-Object { $_ -match '(?i)\.dll$' })[0] if ($library) { return "$library" } } "$($files[0])" } function ConvertTo-LogonPair { <# .SYNOPSIS Events that begin something and events that finish it, as what was begun with how long it took. Pure. .DESCRIPTION Paired by a key the caller reads out of each: a "finished" with the "begun" of the same key that came last before it. A "begun" that nothing finished comes back too, with no end and no length: a task that hangs is the one somebody asks about. What finished without having begun in what was read is left out. In the order of time, then of the record's number, then of the id: two events of one millisecond are otherwise in whatever order they were handed over, and a "finished" ahead of its "begun" pairs everything after it wrongly. The id of a "begun" is the lower one in every pair this Kind reads. #> [CmdletBinding()] [OutputType([psobject])] param( [AllowNull()][AllowEmptyCollection()]$LogEntry, [Parameter(Mandatory)][int[]]$BeginId, [Parameter(Mandatory)][int[]]$EndId, [Parameter(Mandatory)][scriptblock]$Key ) $open = [ordered]@{} foreach ($entry in @($LogEntry | Where-Object { $_ } | Sort-Object TimeCreated, RecordId, Id)) { $name = "$(& $Key $entry)" if (-not $name) { continue } if ($BeginId -contains [int]$entry.Id) { # What began again without having finished is given back as it stands. if ($open.Contains($name)) { [pscustomobject]@{ Name = $name; Start = [datetime]$open[$name]; End = $null; Ms = $null } } $open[$name] = $entry.TimeCreated } elseif ($EndId -contains [int]$entry.Id -and $open.Contains($name)) { [pscustomobject]@{ Name = $name Start = [datetime]$open[$name] End = [datetime]$entry.TimeCreated Ms = [double]([datetime]$entry.TimeCreated - [datetime]$open[$name]).TotalMilliseconds } $open.Remove($name) } } foreach ($name in @($open.Keys)) { [pscustomobject]@{ Name = "$name"; Start = [datetime]$open[$name]; End = $null; Ms = $null } } } function Get-LogonOffset { <# .SYNOPSIS How long after a sign-in something happened, in whole milliseconds. Pure. #> [CmdletBinding()] [OutputType([double])] param([datetime]$From, [AllowNull()]$At) if ($null -eq $At) { return $null } [math]::Round(([datetime]$At - $From).TotalMilliseconds) } function ConvertTo-LogonSignIn { <# .SYNOPSIS The sign-ins that the events of Winlogon, of the User Profile Service and of the shell amount to. Pure. .DESCRIPTION A sign-in is where the subscriber Profiles begins to handle the sign-in event in a Winlogon process. It is counted from the authentication that was accepted in that process within the five seconds before, where there was one. Its subscribers are those of the sign-in event in that process from then on, for no longer than ten minutes and not beyond the next sign-in of that process. Whose it is, the User Profile Service says: while Profiles works, it loads the registry of the account, and logs under which SID. The shell of the sign-in is the Explorer of that account whose logon tasks begin next. Where the account is not known - the service's log does not reach back - the shell is the next one that begins before any other sign-in does: on a terminal server two people sign in within a minute, and a shell taken from the wrong one is somebody else's sign-in under this one's name. Account is the SID; the Gatherer puts the name there. #> [CmdletBinding()] [OutputType([psobject])] param( [AllowNull()][AllowEmptyCollection()]$Winlogon, [AllowNull()][AllowEmptyCollection()]$Shell, [AllowNull()][AllowEmptyCollection()]$UserProfile ) $notify = @($Winlogon | Where-Object { $_ -and [int]$_.Id -in 811, 812 } | Sort-Object TimeCreated, RecordId, Id) $accepted = @($Winlogon | Where-Object { $_ -and [int]$_.Id -eq 2 -and "$(Get-EventPayload -LogEntry $_ -Index 0)" -eq '0' } | Sort-Object TimeCreated) $shellLog = @($Shell | Where-Object { $_ } | Sort-Object TimeCreated, RecordId, Id) # The registry of an account being loaded: its SID, without what marks its classes. $loaded = @($UserProfile | Where-Object { $_ -and [int]$_.Id -eq 5 } | Sort-Object TimeCreated | ForEach-Object { $sid = "$(Get-EventPayload -LogEntry $_ -Index 1)" -replace '(?i)_Classes$', '' if ($sid -match '^S-\d-\d+(-\d+)+$') { [pscustomobject]@{ Time = [datetime]$_.TimeCreated; Sid = $sid } } }) $starts = @($notify | Where-Object { [int]$_.Id -eq 811 -and "$(Get-EventPayload -LogEntry $_ -Index 0)" -eq $script:LogonSignInEvent -and "$(Get-EventPayload -LogEntry $_ -Index 1)" -eq 'Profiles' }) # The shells that began, each by the Explorer that logged it. $shells = [System.Collections.Generic.List[psobject]]::new() foreach ($entry in @($shellLog | Where-Object { [int]$_.Id -eq 62170 -and "$(Get-EventPayload -LogEntry $_ -Index 1)" -eq 'AllLogonTasks' })) { $shells.Add($entry) } $index = -1 foreach ($start in $starts) { $index++ $process = "$($start.ProcessId)" $began = [datetime]$start.TimeCreated $later = @($starts | Select-Object -Skip ($index + 1)) $nextOwn = @($later | Where-Object { "$($_.ProcessId)" -eq $process })[0] $nextAny = $later[0] $time = $began $auth = @($accepted | Where-Object { "$($_.ProcessId)" -eq $process -and $_.TimeCreated -le $began -and ($began - [datetime]$_.TimeCreated).TotalSeconds -le 5 })[-1] if ($auth) { $time = [datetime]$auth.TimeCreated } $until = $time.AddMinutes(10) if ($nextOwn -and [datetime]$nextOwn.TimeCreated -lt $until) { $until = [datetime]$nextOwn.TimeCreated } # From the authentication on, or two seconds before Profiles: SessionEnv is # notified ahead of it. $from = $began.AddSeconds(-2) if ($auth) { $from = $time } $handled = @($notify | Where-Object { "$($_.ProcessId)" -eq $process -and $_.TimeCreated -ge $from -and $_.TimeCreated -lt $until -and "$(Get-EventPayload -LogEntry $_ -Index 0)" -eq $script:LogonSignInEvent }) $pairs = @(ConvertTo-LogonPair -LogEntry $handled -BeginId 811 -EndId 812 -Key { param($e) Get-EventPayload -LogEntry $e -Index 1 } | Where-Object { $null -ne $_.Ms }) # A subscriber is notified more than once: what it took is all of it. $subscribers = @($pairs | Group-Object Name | ForEach-Object { [pscustomobject]@{ Name = "$($_.Name)"; Ms = [math]::Round(($_.Group | Measure-Object Ms -Sum).Sum); Start = ($_.Group | Sort-Object Start)[0].Start } } | Sort-Object Start | ForEach-Object { [pscustomobject]@{ Name = $_.Name; Ms = $_.Ms } }) $notifyMs = $null if ($pairs.Count) { $notifyMs = Get-LogonOffset -From $time -At ($pairs | Sort-Object End)[-1].End } # Whose it is: the registry loaded while Profiles worked. $profilesDone = @($pairs | Where-Object { $_.Name -eq 'Profiles' } | Sort-Object End)[-1] $loadedUntil = $began.AddSeconds(60) if ($profilesDone) { $loadedUntil = $profilesDone.End.AddSeconds(1) } $account = "$(@($loaded | Where-Object { $_.Time -ge $began.AddSeconds(-1) -and $_.Time -le $loadedUntil })[0].Sid)" # The shell: that account's, or the next one before anybody else signs in. $shellUntil = $time.AddSeconds($script:LogonShellWithinSeconds) $candidates = @($shells | Where-Object { $_.TimeCreated -ge $time -and $_.TimeCreated -le $shellUntil }) $explorer = $null if ($account) { $explorer = @($candidates | Where-Object { "$($_.UserId)" -eq $account })[0] } else { $explorer = @($candidates | Where-Object { -not $nextAny -or $_.TimeCreated -lt $nextAny.TimeCreated })[0] if ($explorer) { $account = "$($explorer.UserId)" } } $shellStartMs = $null; $shellTasksMs = $null; $desktopMs = $null $tasks = @(); $commands = @() $lastStartMs = $null if ($explorer) { $null = $shells.Remove($explorer) $limit = ([datetime]$explorer.TimeCreated).AddSeconds($script:LogonAutostartWithinSeconds) $theirs = @($shellLog | Where-Object { "$($_.ProcessId)" -eq "$($explorer.ProcessId)" -and $_.TimeCreated -ge $explorer.TimeCreated -and $_.TimeCreated -le $limit }) $shellStartMs = Get-LogonOffset -From $time -At $explorer.TimeCreated $taskPairs = @(ConvertTo-LogonPair -LogEntry @($theirs | Where-Object { [int]$_.Id -in 62170, 62171 }) -BeginId 62170 -EndId 62171 ` -Key { param($e) Get-EventPayload -LogEntry $e -Index 1 }) $whole = @($taskPairs | Where-Object { $_.Name -eq 'AllLogonTasks' -and $null -ne $_.Ms })[0] if ($whole) { $shellTasksMs = [math]::Round($whole.Ms) $desktopMs = Get-LogonOffset -From $time -At $whole.End } $tasks = @($taskPairs | Where-Object { $_.Name -ne 'AllLogonTasks' } | Sort-Object Start | ForEach-Object { [pscustomobject]@{ Name = $_.Name; StartMs = (Get-LogonOffset -From $time -At $_.Start); Ms = $(if ($null -ne $_.Ms) { [math]::Round($_.Ms) }) } }) # Every command that was started, also one that never "finished": the last # of them is when the last program came. $commandPairs = @(ConvertTo-LogonPair -LogEntry @($theirs | Where-Object { [int]$_.Id -in 9707, 9708 }) -BeginId 9707 -EndId 9708 -Key { param($e) if ([int]$e.Id -eq 9707) { Get-EventPayload -LogEntry $e -Index 0 } else { Get-EventPayload -LogEntry $e -Index 1 } }) $commands = @($commandPairs | Sort-Object Start | ForEach-Object { [pscustomobject]@{ Name = (Get-LogonProgramName -Command $_.Name); StartMs = (Get-LogonOffset -From $time -At $_.Start); Ms = $(if ($null -ne $_.Ms) { [math]::Round($_.Ms) }) } } | Where-Object { $_.Name }) if ($commands.Count) { $lastStartMs = ($commands | Sort-Object StartMs)[-1].StartMs } } [pscustomobject]@{ Time = $time Account = $account Own = $false NotifyMs = $notifyMs Subscribers = $subscribers # Whether the shell's log holds this sign-in at all: where it does and the # shell's tasks never finished, how long it took is not known, and not short. ShellSeen = [bool]$explorer ShellStartMs = $shellStartMs ShellTasksMs = $shellTasksMs DesktopMs = $desktopMs Tasks = $tasks Commands = $commands AutostartLastStartMs = $lastStartMs # Where the domain's name led while this sign-in ran. See Set-LogonDomainAddress. DomainAddresses = @() # The domain controller Group Policy used at this sign-in. See Set-LogonPolicyController. PolicyController = '' } } } function Set-LogonDomainAddress { <# .SYNOPSIS Gives each sign-in the addresses the domain's own name led to while it ran, from what the SMB client logged. Pure. .DESCRIPTION A drive mapped as \\contoso.example\... is connected at sign-in to whichever domain controller the name gave, and the SMB client's events of that connection name the address. Held against the sign-ins it says which controller a slow one went to and which a quick one - which no later measurement can. An event counts for a sign-in from just before it to half a minute after its desktop, or three minutes where that is not known. #> [CmdletBinding()] [OutputType([psobject])] param([AllowNull()][AllowEmptyCollection()]$SignIn, [AllowNull()][AllowEmptyCollection()]$Disruption, [AllowNull()][AllowEmptyString()][string]$Domain) $full = "$Domain".Trim().TrimEnd('.') $short = ($full -split '\.')[0] $named = @() if ($full) { $named = @($Disruption | Where-Object { $_ } | ForEach-Object { $server = "$(Get-DataProperty $_ 'Server')".Trim() $address = "$(Get-DataProperty $_ 'Address')".Trim() $at = ConvertTo-DataTime (Get-DataProperty $_ 'Time') if ($address -and $null -ne $at -and ($server -eq $full -or $server -eq $short)) { [pscustomobject]@{ Time = $at; Address = $address } } }) } foreach ($one in @($SignIn | Where-Object { $_ })) { $from = ConvertTo-DataTime (Get-DataProperty $one 'Time') $found = @() if ($null -ne $from -and $named.Count) { $ms = Get-LogonDesktopMs -SignIn $one if ($null -eq $ms) { $ms = 150000 } $until = $from.AddMilliseconds([double]$ms + 30000) $found = @($named | Where-Object { $_.Time -ge $from.AddSeconds(-5) -and $_.Time -le $until } | ForEach-Object { $_.Address } | Sort-Object -Unique) } $one.DomainAddresses = $found $one } } function Set-LogonPolicyController { <# .SYNOPSIS Gives each sign-in the domain controller Group Policy used for it, from what the Group Policy Check read. Pure. .DESCRIPTION The SMB client names an address only where a session was lost and came back, and a machine in order logs none: its column stays empty for every sign-in. Group Policy writes down the controller of every run. That is the controller that answered for policy, which is not always the address the drives went by - so it is a column of its own, and not put into the other. A run counts for a sign-in where it is one at a logon and lies between just before the sign-in and half a minute after its desktop. #> [CmdletBinding()] [OutputType([psobject])] param([AllowNull()][AllowEmptyCollection()]$SignIn, [AllowNull()]$GroupPolicy) # The runs at a logon, by their activity: 8001 ends the user's. $atLogon = @{} foreach ($run in @((Get-DataCollection $GroupPolicy 'Processing') | ForEach-Object { $_ })) { $activity = "$(Get-DataProperty $run 'Activity')".Trim() if ($activity -and (ConvertTo-Number (Get-DataProperty $run 'Id')) -eq 8001) { $atLogon[$activity] = $true } } $used = @((Get-DataCollection $GroupPolicy 'Controllers') | ForEach-Object { $at = ConvertTo-DataTime (Get-DataProperty $_ 'Time') $activity = "$(Get-DataProperty $_ 'Activity')".Trim() if ($null -ne $at -and $activity -and $atLogon.ContainsKey($activity)) { [pscustomobject]@{ Time = $at; Name = "$(Get-DataProperty $_ 'Name')".Trim(); Address = "$(Get-DataProperty $_ 'Address')".Trim() } } } | Sort-Object Time) foreach ($one in @($SignIn | Where-Object { $_ })) { $from = ConvertTo-DataTime (Get-DataProperty $one 'Time') $text = '' if ($null -ne $from -and $used.Count) { $ms = Get-LogonDesktopMs -SignIn $one if ($null -eq $ms) { $ms = 150000 } $until = $from.AddMilliseconds([double]$ms + 30000) $mine = @($used | Where-Object { $_.Time -ge $from.AddSeconds(-5) -and $_.Time -le $until })[0] if ($mine) { $short = (("$($mine.Name)" -split '\.')[0]).ToUpperInvariant() $text = $(if ($short -and $mine.Address) { '{0} ({1})' -f $short, $mine.Address } elseif ($short) { $short } else { "$($mine.Address)" }) } } $one.PolicyController = $text $one } } function Get-LogonAddressSplit { <# .SYNOPSIS Whether the slow sign-ins went to other addresses of the domain than the quick ones: both lists, or nothing where they do not part cleanly. Pure. .DESCRIPTION Only where it is known of a slow and of a quick sign-in, and no address is in both: one shared address and the controller is not what tells them apart. #> [CmdletBinding()] [OutputType([psobject])] param([AllowNull()][AllowEmptyCollection()]$Slow, [AllowNull()][AllowEmptyCollection()]$Quick) $slowAt = @($Slow | ForEach-Object { (Get-DataCollection $_ 'DomainAddresses') | ForEach-Object { "$_" } } | Where-Object { $_ } | Sort-Object -Unique) $quickAt = @($Quick | ForEach-Object { (Get-DataCollection $_ 'DomainAddresses') | ForEach-Object { "$_" } } | Where-Object { $_ } | Sort-Object -Unique) if (-not $slowAt.Count -or -not $quickAt.Count) { return } if (@($slowAt | Where-Object { $quickAt -contains $_ }).Count) { return } # How many sign-ins that is said of, and of how many it is not known: "all thirteen" # is another statement than "both". $known = { param($List) @($List | Where-Object { @((Get-DataCollection $_ 'DomainAddresses') | ForEach-Object { "$_" } | Where-Object { $_ }).Count }).Count } $slowKnown = & $known $Slow $quickKnown = & $known $Quick [pscustomobject]@{ Slow = $slowAt; Quick = $quickAt; SlowCount = $slowKnown; QuickCount = $quickKnown Unknown = (@($Slow).Count + @($Quick).Count - $slowKnown - $quickKnown) } } function Set-LogonOwner { <# .SYNOPSIS Marks the sign-ins of the User, and takes from the others what is not this Run's to keep: which tasks and programs started for somebody else, and when the last of them did. Pure. #> [CmdletBinding()] [OutputType([psobject])] param([AllowNull()][AllowEmptyCollection()]$SignIn, [AllowNull()][AllowEmptyString()][string]$User) foreach ($one in @($SignIn | Where-Object { $_ })) { $one.Own = [bool]("$User".Trim() -and "$($one.Account)" -eq "$User".Trim()) if (-not $one.Own) { $one.Tasks = @() $one.Commands = @() $one.AutostartLastStartMs = $null } $one } } function Get-LogonData { <# .SYNOPSIS Reads the sign-ins of the period out of the logs of Winlogon, of the User Profile Service and of the shell. Judges none of them. .DESCRIPTION Whose sign-ins are the User's is what the Run handed over as 'RunUser': the account at the machine, or the one the Run runs as where nobody is. Not worked out here a second time. Of the sign-ins of other accounts only when, whose, and how long to the desktop are kept: which tasks and programs start for somebody else, and how many, is not this Run's to gather (ADR-0006). .PARAMETER Observed What the Run knows before this Check: 'RunUser', see ConvertTo-RunUserObserved, and what the NetworkDisruption Check read with admin rights, where it ran. #> [CmdletBinding()] [OutputType([psobject])] param([hashtable]$Parameters = @{}, [AllowNull()][hashtable]$Observed = @{}) $days = [int](Get-Parameter $Parameters 'Days' $script:LogonDefaultDays) $since = (Get-Date).AddDays(-$days) $unreadable = @{} $scanned = @() $read = @{} $registration = Get-NetworkDisruptionRegistration foreach ($wanted in @( @{ Log = $script:LogonWinlogonLog; Id = @(2, 811, 812) } @{ Log = $script:LogonProfileLog; Id = @(5) } @{ Log = $script:LogonShellLog; Id = @(62170, 62171, 9707, 9708) })) { $read[$wanted.Log] = @() if ($registration -and -not $registration.Log.Contains($wanted.Log)) { continue } $scanned += $wanted.Log $read[$wanted.Log] = @(Get-StabilityEvent -Log $wanted.Log -Id $wanted.Id -Since $since -Unreadable $unreadable) } $runUser = $null if ($Observed -and $Observed.ContainsKey('RunUser')) { $runUser = $Observed['RunUser'] } $user = "$(Get-DataProperty $runUser 'LoggedOnUser')".Trim() if (-not $user) { $user = "$(Get-DataProperty $runUser 'RunningAs')".Trim() } if (-not $user) { try { $user = "$([System.Security.Principal.WindowsIdentity]::GetCurrent().Name)" } catch { } } $signIns = @(ConvertTo-LogonSignIn -Winlogon $read[$script:LogonWinlogonLog] -Shell $read[$script:LogonShellLog] ` -UserProfile $read[$script:LogonProfileLog] | Sort-Object Time -Descending) foreach ($signIn in $signIns) { $sid = "$($signIn.Account)" if (-not $sid) { continue } $named = Resolve-AccountName -Sid $sid if ($named.Name) { $signIn.Account = $named.Name } } $signIns = @(Set-LogonOwner -SignIn $signIns -User $user) # Where the domain's name led at each sign-in: from what the Elevated Part read out # of the SMB client's log. Without it, or outside a domain, nothing. $domain = '' try { $system = Get-CimInstance Win32_ComputerSystem -ErrorAction Stop if ([bool]$system.PartOfDomain) { $domain = "$($system.Domain)".Trim() } } catch { } $disruptions = @() $disruptionsRead = [bool]($Observed -and $Observed.ContainsKey('NetworkDisruption')) if ($Observed -and $Observed.ContainsKey('NetworkDisruption')) { $disruptions = @((Get-DataCollection $Observed['NetworkDisruption'] 'Disruptions') | ForEach-Object { $_ }) } $signIns = @(Set-LogonDomainAddress -SignIn $signIns -Disruption $disruptions -Domain $domain) # And the controller Group Policy used at each, from the Group Policy Check. $policy = $null if ($Observed -and $Observed.ContainsKey('GroupPolicy')) { $policy = $Observed['GroupPolicy'] } $signIns = @(Set-LogonPolicyController -SignIn $signIns -GroupPolicy $policy) $coverage = @(foreach ($log in $scanned) { if ($unreadable.ContainsKey($log)) { continue } [pscustomobject]@{ Log = $log; Oldest = Get-NetworkDisruptionLogOldest -Log $log } }) [pscustomobject]@{ PSTypeName = 'Gutcheck.Data.Logon' Domain = $domain # Whether what the SMB client logged was there to hold against the sign-ins. DisruptionsRead = $disruptionsRead PolicyRead = ($null -ne $policy) Days = $days Since = $since SignIns = $signIns UnreadableLogs = @($unreadable.Keys | Sort-Object) ScannedLogs = [string[]]@($scanned) LogCoverage = $coverage } } function Format-LogonSeconds { <# .SYNOPSIS A length of time as the Report shows it: "0,7 s" below ten seconds, whole seconds up to two minutes, minutes and seconds from there. Empty for none. Pure. #> [CmdletBinding()] [OutputType([string])] param([AllowNull()]$Milliseconds) $number = ConvertTo-Number $Milliseconds if ($null -eq $number) { return '' } if ($number -lt 0) { $number = 0 } $seconds = [double]$number / 1000 if ($seconds -lt 10) { return (Get-Text 'Value.Logon.SecondsTenth' $seconds) } if ($seconds -lt 120) { return (Get-Text 'Value.Logon.Seconds' ([int][math]::Round($seconds))) } $whole = [int][math]::Round($seconds) Get-Text 'Value.Logon.Minutes' ([int][math]::Floor($whole / 60)) ($whole % 60) } function Get-LogonSubscriberText { <# .SYNOPSIS What the Report calls a part of Windows a sign-in waits for. One this has no word for is shown under its own name: that is what Windows calls it. Pure. #> [CmdletBinding()] [OutputType([string])] param([AllowNull()][AllowEmptyString()][string]$Name) switch ("$Name") { 'Profiles' { return (Get-Text 'Value.Logon.Subscriber.Profiles') } 'GPClient' { return (Get-Text 'Value.Logon.Subscriber.GPClient') } 'SessionEnv' { return (Get-Text 'Value.Logon.Subscriber.SessionEnv') } 'TermSrv' { return (Get-Text 'Value.Logon.Subscriber.TermSrv') } 'Sens' { return (Get-Text 'Value.Logon.Subscriber.Sens') } } "$Name" } function Get-LogonPhase { <# .SYNOPSIS A sign-in as the phases a Finding names: loading the profile, Group Policy, the other parts of Windows, getting to the shell, and the shell's own tasks. Pure. .DESCRIPTION Each with what it took, in milliseconds, and in the order they happen. A phase a log said nothing of is left out. "Shell" is the time from the last part of Windows to the shell beginning its tasks: Explorer being started. #> [CmdletBinding()] [OutputType([psobject])] param([AllowNull()]$SignIn) $subscribers = @((Get-DataCollection $SignIn 'Subscribers') | ForEach-Object { $_ }) $profileMs = 0; $policyMs = 0; $otherMs = 0 foreach ($subscriber in $subscribers) { $took = [double](ConvertTo-Number (Get-DataProperty $subscriber 'Ms')) switch ("$(Get-DataProperty $subscriber 'Name')") { 'Profiles' { $profileMs += $took } 'GPClient' { $policyMs += $took } default { $otherMs += $took } } } if ($subscribers.Count) { [pscustomobject]@{ Phase = 'Profile'; Ms = [int]$profileMs } [pscustomobject]@{ Phase = 'Policy'; Ms = [int]$policyMs } [pscustomobject]@{ Phase = 'Other'; Ms = [int]$otherMs } } $notify = ConvertTo-Number (Get-DataProperty $SignIn 'NotifyMs') $shell = ConvertTo-Number (Get-DataProperty $SignIn 'ShellStartMs') if ($null -ne $shell) { $from = 0 if ($null -ne $notify) { $from = [double]$notify } [pscustomobject]@{ Phase = 'Shell'; Ms = [int][math]::Max(0, [double]$shell - $from) } } $tasks = ConvertTo-Number (Get-DataProperty $SignIn 'ShellTasksMs') if ($null -ne $tasks) { [pscustomobject]@{ Phase = 'Tasks'; Ms = [int]$tasks } } } function Get-LogonPhaseText { <# .SYNOPSIS What the Report calls a phase, and what to do where it is the slow one. Pure. #> [CmdletBinding()] [OutputType([string])] param([AllowNull()][AllowEmptyString()][string]$Phase, [Parameter(Mandatory)][ValidateSet('Name', 'Hint')][string]$Part) switch ("$Phase|$Part") { 'Profile|Name' { return (Get-Text 'Value.Logon.Phase.Profile') } 'Profile|Hint' { return (Get-Text 'Hint.Logon.Phase.Profile') } 'Policy|Name' { return (Get-Text 'Value.Logon.Phase.Policy') } 'Policy|Hint' { return (Get-Text 'Hint.Logon.Phase.Policy') } 'Other|Name' { return (Get-Text 'Value.Logon.Phase.Other') } 'Other|Hint' { return (Get-Text 'Hint.Logon.Phase.Other') } 'Shell|Name' { return (Get-Text 'Value.Logon.Phase.Shell') } 'Shell|Hint' { return (Get-Text 'Hint.Logon.Phase.Shell') } 'Tasks|Name' { return (Get-Text 'Value.Logon.Phase.Tasks') } 'Tasks|Hint' { return (Get-Text 'Hint.Logon.Phase.Tasks') } } "$Phase" } function Get-LogonDesktopMs { <# .SYNOPSIS How long a sign-in took to the desktop: to the shell having done its tasks. Where the shell's log does not hold the sign-in at all, to the last part of Windows. $null where neither is known - and where the shell began and its tasks never finished: that sign-in hung, and is not one that took two seconds. Pure. #> [CmdletBinding()] [OutputType([double])] param([AllowNull()]$SignIn) $desktop = ConvertTo-Number (Get-DataProperty $SignIn 'DesktopMs') if ($null -ne $desktop) { return [double]$desktop } if ([bool](Get-DataProperty $SignIn 'ShellSeen') -or $null -ne (ConvertTo-Number (Get-DataProperty $SignIn 'ShellStartMs'))) { return $null } $notify = ConvertTo-Number (Get-DataProperty $SignIn 'NotifyMs') if ($null -ne $notify) { return [double]$notify } $null } function New-LogonDesktopFinding { <# .SYNOPSIS How long the User's sign-ins take to the desktop, how many of the last ones were slow, and where the time of a slow one went. .DESCRIPTION A warning where two of the last ten sign-ins were slow, or the middle one of the last five is. The middle one alone was the rule, and it lost a machine on which every second sign-in took ninety seconds: two quick sign-ins after a restart, and the Finding was in order. What comes and goes is counted. The phases shown are those of the newest slow sign-in where there is one: the last sign-in may be one of the quick ones, and its phases say nothing of the problem. Never a FAIL unless a Check Definition says so. #> [CmdletBinding()] param([hashtable]$Parameters, [AllowNull()][AllowEmptyCollection()]$SignIn, [switch]$ControllerNotRead) $check = Get-Text 'Check.Logon.Desktop' $timed = @($SignIn | Where-Object { $null -ne (Get-LogonDesktopMs -SignIn $_) }) if (-not $timed.Count) { # The shell began its tasks and never logged them done: how long the sign-in # took is not known, and that is not the same as nothing to report. $newest = @($SignIn | Where-Object { $_ })[0] if (-not $newest) { return } return New-Finding -Category Startup -Check $check -Severity WARN ` -Value ((Get-Text 'Value.Logon.NeverFinished') -f (ConvertTo-DataTime (Get-DataProperty $newest 'Time'))) ` -Meaning (Get-Text 'Meaning.Logon.NeverFinished') -Hint (Get-Text 'Hint.Logon.NeverFinished') ` -Reference @(New-Reference -Section 'Title.Logon.Steps') } $warn = [double](Get-Parameter $Parameters 'DesktopWarnSeconds' 60) $fail = [double](Get-Parameter $Parameters 'DesktopFailSeconds' ([double]::MaxValue)) $enough = [double](Get-Parameter $Parameters 'DesktopSlowSignIns' 2) $last = $timed[0] $took = @($timed | Select-Object -First 5 | ForEach-Object { Get-LogonDesktopMs -SignIn $_ } | Sort-Object) $typical = $took[[int][math]::Floor(($took.Count - 1) / 2)] $recent = @($timed | Select-Object -First 10) $slow = @($recent | Where-Object { ((Get-LogonDesktopMs -SignIn $_) / 1000) -gt $warn }) $severity = Get-Severity ($typical / 1000) $warn $fail if ($severity -eq 'OK' -and $slow.Count -ge $enough) { $severity = 'WARN' } # The sign-in whose phases are shown: the newest slow one, or the last. $shown = $last if ($slow.Count) { $shown = $slow[0] } $phases = @(Get-LogonPhase -SignIn $shown) $named = @($phases | Where-Object { $_.Ms -ge 100 } | ForEach-Object { '{0} {1}' -f (Get-LogonPhaseText -Phase $_.Phase -Part Name), (Format-LogonSeconds $_.Ms) }) -join '; ' $value = @((Get-Text 'Value.Logon.Desktop') -f (Format-LogonSeconds (Get-LogonDesktopMs -SignIn $last)), (ConvertTo-DataTime (Get-DataProperty $last 'Time'))) if ($timed.Count -gt 1) { $value += (Get-Text 'Value.Logon.Typical') -f (Format-LogonSeconds $typical), $took.Count } if ($slow.Count) { $value += (Get-Text 'Value.Logon.Slow') -f $slow.Count, $recent.Count, [int]$warn, (ConvertTo-DataTime (Get-DataProperty $shown 'Time')), (Format-LogonSeconds (Get-LogonDesktopMs -SignIn $shown)) if ($named) { $value += (Get-Text 'Value.Logon.PhasesOfSlow') -f $named } } elseif ($named) { $value += (Get-Text 'Value.Logon.Phases') -f $named } # Slow by one domain controller and quick by another: the answer to "why only on # some days", where the SMB client's log gave it. # Over every sign-in the logs hold, not the last ten: the more of them part the same # way, the less it is chance. $slowAll = @($timed | Where-Object { ((Get-LogonDesktopMs -SignIn $_) / 1000) -gt $warn }) $split = Get-LogonAddressSplit -Slow $slowAll -Quick @($timed | Where-Object { $slowAll -notcontains $_ }) if ($split) { $value += (Get-Text 'Value.Logon.Split') -f $split.SlowCount, ($split.Slow -join ', '), $split.QuickCount, ($split.Quick -join ', ') if ($split.Unknown) { $value += (Get-Text 'Value.Logon.SplitUnknown') -f $split.Unknown } } # Slow on some days, in a domain, and nobody read which controller it was: said, # so that no answer is not taken for "it makes no difference". elseif ($ControllerNotRead -and $slow.Count) { $value += Get-Text 'Value.Logon.ControllerNotRead' } $table = @((New-Reference -Section 'Title.Logon.SignIns'), (New-Reference -Section 'Title.Logon.Steps')) if ($severity -eq 'OK') { return New-Finding -Category Startup -Check $check -Severity OK -Value ($value -join ' | ') -Reference $table } # What to do is about the phase that took longest in the sign-in shown. $slowest = @($phases | Sort-Object Ms -Descending)[0] $meaning = @(Get-Text 'Meaning.Logon.Desktop') $hint = @() if ($slowest) { $meaning += (Get-Text 'Meaning.Logon.Slowest') -f (Get-LogonPhaseText -Phase $slowest.Phase -Part Name), (Format-LogonSeconds $slowest.Ms), (ConvertTo-DataTime (Get-DataProperty $shown 'Time')) $hint += Get-LogonPhaseText -Phase $slowest.Phase -Part Hint } # Some slow and some not is a finding of its own: something is there at one sign-in # and not at the next. if ($split) { $meaning += (Get-Text 'Meaning.Logon.Split') -f ($split.Slow -join ', ') $hint += (Get-Text 'Hint.Logon.Split') -f ($split.Slow -join ', ') } elseif ($slow.Count -and $slow.Count -lt $recent.Count) { $meaning += Get-Text 'Meaning.Logon.Intermittent' $hint += Get-Text 'Hint.Logon.Intermittent' } $hint += Get-Text 'Hint.Logon.Desktop' # What comes and goes, and by which controller: for what reads Findings together. $signal = @() if ($slow.Count -and $slow.Count -lt $recent.Count) { $signal += 'sign-in-intermittent' } if ($split) { $signal += 'sign-in-by-controller' } # The newest slow sign-in: when what this warns of last happened. $newestSlow = $null if ($slow.Count) { $newestSlow = ConvertTo-DataTime (Get-DataProperty $slow[0] 'Time') } New-Finding -Category Startup -Check $check -Severity $severity -Value ($value -join ' | ') ` -Meaning ($meaning -join ' | ') -Hint ($hint -join ' | ') -Reference $table -Signal $signal -LastSeen $newestSlow } function New-LogonAutostartFinding { <# .SYNOPSIS When the last of the programs of the Run keys was started after the User's last sign-in. Nothing where the shell's log holds none. .DESCRIPTION Windows starts them one after the other and gives each up to thirty seconds, so the tenth is there five minutes after the desktop - and "Teams is not there when I sign in" is that, and no fault of Teams. #> [CmdletBinding()] param([hashtable]$Parameters, [AllowNull()]$SignIn) $commands = @((Get-DataCollection $SignIn 'Commands') | ForEach-Object { $_ }) $lastStart = ConvertTo-Number (Get-DataProperty $SignIn 'AutostartLastStartMs') if (-not $commands.Count -or $null -eq $lastStart) { return } $warn = [double](Get-Parameter $Parameters 'AutostartWarnSeconds' 180) $severity = Get-Severity ([double]$lastStart / 1000) $warn ([double]::MaxValue) if ($severity -eq 'OK') { $severity = 'INFO' } $late = @($commands | Sort-Object { [double](ConvertTo-Number (Get-DataProperty $_ 'StartMs')) } -Descending | Select-Object -First 3 | ForEach-Object { (Get-Text 'Value.Logon.CommandAfter') -f "$(Get-DataProperty $_ 'Name')", (Format-LogonSeconds (Get-DataProperty $_ 'StartMs')) }) New-Finding -Category Startup -Check (Get-Text 'Check.Logon.Autostart') -Severity $severity ` -Value (@( ((Get-Text 'Value.Logon.Autostart') -f $commands.Count, (Format-LogonSeconds $lastStart)) ((Get-Text 'Value.Logon.AutostartLate') -f ($late -join '; '))) -join ' | ') ` -Meaning (Get-Text 'Meaning.Logon.Autostart') -Hint (Get-Text 'Hint.Logon.Autostart') ` -Reference @(New-Reference -Section 'Title.Logon.Steps') } function ConvertTo-LogonFinding { [CmdletBinding()] [OutputType([psobject])] param([AllowNull()]$Data, [hashtable]$Parameters = @{}) $signIns = @((Get-DataCollection $Data 'SignIns') | ForEach-Object { $_ }) $own = @($signIns | Where-Object { [bool](Get-DataProperty $_ 'Own') }) $desktop = $null if (-not $own.Count) { $check = Get-Text 'Check.Logon.Desktop' $unreadable = @((Get-DataCollection $Data 'UnreadableLogs') | ForEach-Object { $_ }) if ($unreadable.Count) { New-Finding -Category Startup -Check $check -Severity INFO ` -Value ((Get-Text 'Value.NetworkDisruption.NotAssessable') -f ($unreadable -join ', ')) ` -Meaning (Get-Text 'Meaning.Logon.Unreadable') -Hint (Get-Text 'Hint.Logon.Unreadable') } else { # No sign-in of this account in what the logs hold: a machine that is not # restarted for weeks has one sign-in, and the log may have let it go. New-Finding -Category Startup -Check $check -Severity INFO ` -Value ((Get-Text 'Value.Logon.None') -f (Get-NetworkDisruptionDays -Data $Data)) ` -Meaning (Get-Text 'Meaning.Logon.None') -Hint (Get-Text 'Hint.Logon.None') } } else { $unread = [bool]("$(Get-DataProperty $Data 'Domain')" -and (Get-DataProperty $Data 'DisruptionsRead') -eq $false) $desktop = New-LogonDesktopFinding -Parameters $Parameters -SignIn $own -ControllerNotRead:$unread $desktop New-LogonAutostartFinding -Parameters $Parameters -SignIn $own[0] } New-UnreadableLogFinding -Data $Data -Parameters $Parameters # The sign-ins on the 30 days, beside the network's events. ADR-0010. ConvertTo-LogonTimedEvent -Data $Data -Finding $desktop } function ConvertTo-LogonTimedEvent { <# .SYNOPSIS Each sign-in as a marker of the timeline, with whose it was and how long it took to the desktop, and how far back the logs reach. Pure. ADR-0010. .DESCRIPTION The User's sign-ins are judged by the Finding about how long they take; another account's by none, and are drawn grey. Whose and when is what the Report already holds of every sign-in (ADR-0006). .PARAMETER Finding The Finding about the User's sign-ins, where there is one. #> [CmdletBinding()] [OutputType([psobject])] param([AllowNull()]$Data, [AllowNull()]$Finding) foreach ($signIn in @((Get-DataCollection $Data 'SignIns') | Where-Object { $_ })) { $at = ConvertTo-DataTime (Get-DataProperty $signIn 'Time') if ($null -eq $at) { continue } $took = Format-LogonSeconds (Get-LogonDesktopMs -SignIn $signIn) $by = $null if ([bool](Get-DataProperty $signIn 'Own')) { $by = $Finding } New-TimedEvent -Time $at -Lane Marker -Mark SignIn -Subject "$(Get-DataProperty $signIn 'Account')" ` -Detail $(if ($took) { (Get-Text 'Value.Timeline.SignInDesktop') -f $took } else { '' }) ` -Log $script:LogonWinlogonLog -Finding $by } ConvertTo-LogCoverageTimedEvent -Coverage (Get-DataCollection $Data 'LogCoverage') -Unreadable (Get-DataCollection $Data 'UnreadableLogs') } function ConvertTo-LogonSection { [CmdletBinding()] [OutputType([psobject])] param([AllowNull()]$Data) $signIns = @((Get-DataCollection $Data 'SignIns') | ForEach-Object { $_ }) $time = Get-Text 'Column.NetworkDisruption.Time' $inDomain = [bool]"$(Get-DataProperty $Data 'Domain')" $disruptionsRead = [bool](Get-DataProperty $Data 'DisruptionsRead') $policyRead = [bool](Get-DataProperty $Data 'PolicyRead') New-Section -Title (Get-Text 'Title.Logon.SignIns') -Help (Get-Text 'Help.Logon.SignIns') -Row @( $signIns | Select-Object -First 50 | ForEach-Object { $phases = @{} foreach ($phase in @(Get-LogonPhase -SignIn $_)) { $phases[$phase.Phase] = $phase.Ms } $row = [ordered]@{} $row[$time] = Get-DataProperty $_ 'Time' $row[(Get-Text 'Column.RemoteDesktop.Account')] = "$(Get-DataProperty $_ 'Account')" $row[(Get-Text 'Column.Logon.Desktop')] = Format-LogonSeconds (Get-LogonDesktopMs -SignIn $_) foreach ($phase in 'Profile', 'Policy', 'Other', 'Shell', 'Tasks') { $row[(Get-LogonPhaseText -Phase $phase -Part Name)] = $(if ($phases.ContainsKey($phase)) { Format-LogonSeconds $phases[$phase] } else { '' }) } $row[(Get-Text 'Column.Logon.LastAutostart')] = Format-LogonSeconds (Get-DataProperty $_ 'AutostartLastStartMs') # An empty cell was read as something broken. It is one of two things, and # says which: nobody read the log, or the log holds nothing for this sign-in - # the SMB client writes an address only where a session was lost and came back. $went = @((Get-DataCollection $_ 'DomainAddresses') | ForEach-Object { "$_" }) -join ', ' if (-not $went -and $inDomain) { $went = $(if ($disruptionsRead) { Get-Text 'Value.Logon.NoDrop' } else { Get-Text 'Value.Logon.NotRead' }) } $row[(Get-Text 'Column.Logon.DomainAddress')] = $went $by = "$(Get-DataProperty $_ 'PolicyController')" if (-not $by -and $inDomain) { $by = $(if ($policyRead) { Get-Text 'Value.Logon.NothingLogged' } else { Get-Text 'Value.Logon.NotRead' }) } $row[(Get-Text 'Column.Logon.PolicyController')] = $by [pscustomobject]$row } ) # The last sign-in of the User, step by step. $last = @($signIns | Where-Object { [bool](Get-DataProperty $_ 'Own') })[0] if (-not $last) { return } # Named apart from the parameters of the block below: a variable's name is the same # in any case, and "$kind" would be the block's "$Kind". $stepColumn = Get-Text 'Column.Logon.Step' $kindColumn = Get-Text 'Column.NetworkDisruption.Kind' $afterColumn = Get-Text 'Column.Logon.After' $tookColumn = Get-Text 'Column.Logon.Took' $line = { param([string]$Name, [string]$What, $StartMs, $Ms) $row = [ordered]@{} $row[$stepColumn] = $Name $row[$kindColumn] = $What $row[$afterColumn] = Format-LogonSeconds $StartMs $row[$tookColumn] = Format-LogonSeconds $Ms [pscustomobject]$row } New-Section -Title (Get-Text 'Title.Logon.Steps') -Help (Get-Text 'Help.Logon.Steps') -Row @( foreach ($subscriber in (Get-DataCollection $last 'Subscribers')) { & $line (Get-LogonSubscriberText -Name "$(Get-DataProperty $subscriber 'Name')") (Get-Text 'Value.Logon.Step.Windows') $null (Get-DataProperty $subscriber 'Ms') } # The shell's tasks that took a moment: there are fifty, and most take none. foreach ($task in @((Get-DataCollection $last 'Tasks') | Where-Object { [double](ConvertTo-Number (Get-DataProperty $_ 'Ms')) -ge 200 })) { & $line "$(Get-DataProperty $task 'Name')" (Get-Text 'Value.Logon.Step.Shell') (Get-DataProperty $task 'StartMs') (Get-DataProperty $task 'Ms') } foreach ($command in (Get-DataCollection $last 'Commands')) { & $line "$(Get-DataProperty $command 'Name')" (Get-Text 'Value.Logon.Step.Autostart') (Get-DataProperty $command 'StartMs') (Get-DataProperty $command 'Ms') } ) } |