10 Replies Latest reply on Jun 15, 2016 3:20 PM by Landon Winburn

    Easily Displaying Logon Times

    Landon Winburn Expert
      I was working on a way to break down logon times to more accurately report on them than a stop watch without having to enable logging and dive into a log each logon. I didn't want to lose this code so I figured I'd post it here. The attached EM Policy templates will pull the following information:

      LogonStart - This is the time that the user logged in according to the security event logs 4624 event that is generated when the user authenticates.
      EMUserStart - This is the time at which EMUser fires and starts holding the shell. The time before this and after LogonStart is when AD GPO is applied and unfortunately I couldn't find a way to pull the 8001 event from the GPO logs. If someone knows how to do that and could post that I'd appreciate it! :)
      LogonTriggerTime - This requires auditing in the EM policy set to audit to the "AppSense" event log and trigger action times (9662) enabled.
      LogonComplete - This the time when EMUser finishes the logon trigger and releases the shell for the OS to load.
      TotalAppSenseTime - This is the time from EMUser start to LogonComplete. The difference in the LogonTriggerTime and the TotalAppSenseTime is basically how long it took to parse the config and download desktop settings.
      DesktopFinished - This is created by a dummy exe being fired in via the RUN key and lets us know the shell is fully loaded and we are in windows.
      UserInitStart - Just threw this in there, don't know why but its when userinit is launched to load the shell.


      C:\Users\landon>set a
      ALLUSERSPROFILE=C:\ProgramData
      APPDATA=C:\Users\landon\AppData\Roaming
      AppSense-DesktopFinished=2/23/2015 2:46:12 PM
      AppSense-EMUserStart=2/23/2015 2:46:03 PM
      AppSense-LogonComplete=2/23/2015 2:46:06 PM
      AppSense-LogonStart=2/23/2015 2:46:00 PM
      AppSense-LogonTriggerTime=1796ms
      AppSense-TotalAppSenseTime=3
      AppSense-UserInitStart=2/23/2015 2:46:09 PM
      AppSenseHome=\\profiles\profiles\landon
      AppSenseRedirections=\\profiles\profiles\landon

      From this output you can see the total logon time was 9 seconds. ~3 seconds was profile loading and GPO, ~1 second of config loading and desktop settings, ~2 seconds of logon trigger items, and ~3 seconds of desktop loading.

      These environment variables are set upon logon and can be consumed by something like BGInfo to display this information on the desktop each logon.
        • 1. Re: Easily Displaying Logon Times
          Landon Winburn Expert
          lol, already updated it...

          I've added the DesktopLoadTime in seconds and the TotalLogonTime in seconds so you don't have to calculate those out. Also tossed the Desktop Created trigger to eliminate any race conditions.


          C:\Users\landon>set a
          ALLUSERSPROFILE=C:\ProgramData
          APPDATA=C:\Users\landon\AppData\Roaming
          AppSense-DesktopFinished=2/23/2015 4:25:05 PM
          AppSense-DesktopLoadTime=4
          AppSense-EMUserStart=2/23/2015 4:24:57 PM
          AppSense-LogonComplete=2/23/2015 4:25:01 PM
          AppSense-LogonStart=2/23/2015 4:24:54 PM
          AppSense-LogonTriggerTime=2419ms
          AppSense-SessionLoadTime=3
          AppSense-TotalAppSenseTime=4
          AppSense-TotalLogonTime=11
          AppSense-UserInitStart=2/23/2015 4:25:02 PM
          AppSenseHome=\\profiles\profiles\landon
          AppSenseRedirections=\\profiles\profiles\landon
          • 2. Re: Easily Displaying Logon Times
            gregf SupportEmployee
            Here's a custom action - to be executed as System - that retrieves the time of the most recent 8001 event from the GP event log. The only thing I didn't manage to do yet was to expose the retrieved time as an environment variable for the current user.

            Maybe you could do something with 8.5 to set the value to a Session Variable then have another action that sets a user environment variable to the value of that session variable.

            # get the Session ID of this process - the same as that of the user
            $sessionId = Get-Process -id $pid | select-object -expand SessionId
            
            # get the output of 'query.exe user' for that session ID
            $quOutput = query.exe user $sessionId
            
            # parse the output of query.exe to get the user ID only
            $userId = $quOutput[1] -replace '^>([^\s]+)+.*$','$1'
            
            # get the SID based on that user ID
            $userSID = Get-WmiObject -Class win32_userprofile -filter "localpath LIKE '%\\users\\$userId'" | select-object -expand sid 
            
            # retrieve the user's %userdomain% folder location
            $userDomain = (Get-ItemProperty "Registry::\HKEY_USERS\$userSID\Volatile Environment").USERDOMAIN
            
            # our event log query for GPO event 8001
            $query = @'
            <QueryList>
              <Query Id="0" Path="Microsoft-Windows-GroupPolicy/Operational">
                <Select Path="Microsoft-Windows-GroupPolicy/Operational">
                
                
                 *[EventData[Data[@Name='PrincipalSamName'] and (Data='domain_and_username')]] 
                             and 
                             *[System[(EventID='8001')]] 
                
                </Select>
              </Query>
            </QueryList>
            '@
            
            # prepare the query for the current user
            $query = $query -replace 'domain_and_username', "$userDomain\$userId"
            
            # retrieve the time of the most recent matching event
            $t = (Get-WinEvent -FilterXml $query -MaxEvents 1).TimeCreated
            
            
            • 3. Re: Easily Displaying Logon Times
              Landon Winburn Expert
              Thanks, I'll play with this. I tried setting a session variable from a script running as system and it wasn't available for the user in the same session. Had to dump everything to HKLM and pick it up from there.
              • 4. Re: Easily Displaying Logon Times
                Landon Winburn Expert
                Thanks Greg. Updated now with GPO times from the 8001 event... :)

                C:\Users\landon>set a
                ALLUSERSPROFILE=C:\ProgramData
                APPDATA=C:\Users\landon\AppData\Roaming
                AppSense-DesktopFinished=2/23/2015 5:53:57 PM
                AppSense-DesktopLoadTime=5
                AppSense-EMUserStart=2/23/2015 5:53:49 PM
                AppSense-GPOTime=1
                AppSense-LogonComplete=2/23/2015 5:53:52 PM
                AppSense-LogonStart=2/23/2015 5:53:47 PM
                AppSense-LogonTriggerTime=1967ms
                AppSense-SessionLoadTime=2
                AppSense-TotalAppSenseTime=3
                AppSense-TotalLogonTime=10
                AppSense-UserInitStart=2/23/2015 5:53:53 PM
                AppSenseHome=\\profiles\profiles\landon
                AppSenseRedirections=\\profiles\profiles\landon
                • 5. Re: Easily Displaying Logon Times
                  JeffGonzalez Employee
                  Took a quick look at this tonight.  Pretty information and useful.  Thanks for sharing. 

                  C:\Users\user3>set a
                  ALLUSERSPROFILE=C:\ProgramData
                  APPDATA=C:\Users\user3\AppData\Roaming
                  AppSense-DesktopFinished=3/10/2015 9:37:44 PM
                  AppSense-DesktopLoadTime=7207
                  AppSense-EMUserStart=3/10/2015 9:37:38 PM
                  AppSense-GPOTime=3
                  AppSense-LogonComplete=3/10/2015 7:37:37 PM
                  AppSense-LogonStart=3/10/2015 7:37:37 PM
                  AppSense-LogonTriggerTime=An account was successfully logged on

                  Subject:
                          Security ID:            S-1-5-18
                          Account Name:           W7VDT02$
                          Account Domain:         AUV
                          Logon ID:               0x3e7

                  Logon Type:                     10

                  New Logon:
                          Security ID:            S-1-5-21-2366837556-3064423009-3497790031-1605
                          Account Name:           user3
                          Account Domain:         AUV
                          Logon ID:               0x145c72
                          Logon GUID:             {3E1867DA-03A7-1CF1-5E69-A45396B88560}

                  Process Information:
                          Process ID:             0x270
                          Process Name:           C:\Windows\System32\winlogonexe

                  Network Information:
                          Workstation Name:       W7VDT02
                          Source Network Address: 1921681871
                          Source Port:            52684

                  Detailed Authentication Information:
                          Logon Process:          User32
                          Authentication Package: Negotiate
                          Transited Services:     -
                          Package Name (NTLM only):       -
                          Key Length:             0

                  This event is generated when a logon session is created It is generated on the c
                  omputer that was accessed

                  The subject fields indicate the account on the local system which requested the
                  logon This is most commonly a service such as the Server service, or a local pro
                  cess such as Winlogonexe or Servicesexe

                  The logon type field indicates the kind of logon that occurred The most common t
                  ypes are 2 (interactive) and 3 (network)

                  The New Logon fields indicate the account for whom the new logon was created, ie
                  the account that was logged on

                  The network fields indicate where a remote logon request originated Workstation
                  name is not always available and may be left blank in some cases

                  The authentication information fields provide detailed information about this sp
                  ecific logon request
                          - Logon GUID is a unique identifier that can be used to correlate this e
                  vent with a KDC event
                          - Transited services indicate which intermediate services have participa
                  ted in this logon request
                          - Package name indicates which sub-protocol was used among the NTLM prot
                  ocols
                          - Key length indicates the length of the generated session key This will
                  be 0 if no session key was requested
                  AppSense-SessionLoadTime=7201
                  AppSense-TotalAppSenseTime=-7201
                  AppSense-TotalLogonTime=7207
                  AppSense-UserInitStart=3/10/2015 9:37:39 PM
                  • 6. Re: Easily Displaying Logon Times
                    tgtech Rookie
                    This is useful information.  I do have an issue where my servers i'm logging in to our in Central time and my computer i'm connecting from is in Eastern time.  At some point during the login process it switches to the Eastern time as it should but that effects the results of the total time. 

                    Any thoughts?

                    AppSense-DesktopFinished=03/11/2015 10:59:18 AM
                    AppSense-DesktopLoadTime=7209
                    AppSense-EMUserStart=3/11/2015 8:58:59 AM
                    AppSense-GPOTime=5
                    AppSense-LogonComplete=3/11/2015 8:59:09 AM
                    AppSense-LogonStart=3/11/2015 8:58:49 AM
                    AppSense-LogonTriggerTime=6725ms
                    AppSense-SessionLoadTime=10
                    AppSense-TotalAppSenseTime=10
                    AppSense-TotalLogonTime=7229
                    AppSense-UserInitStart=3/11/2015 8:59:13 AM
                    • 7. Re: Easily Displaying Logon Times
                      Landon Winburn Expert
                      Sorry, my bad. I should have noted that. In the custom action named "Get Logon times" replace -6 in line 34 and 53 with your time zone. This action is in the process start node.

                      Lnadon.
                      • 8. Re: Easily Displaying Logon Times
                        raged Rookie
                        Landon,

                        Can you go through how I import these into EM Policy Configuration?

                        I would appreciate it.

                        Thanks.
                        • 9. Re: Easily Displaying Logon Times
                          raged Rookie

                          Landon wrote:

                           

                          Sorry, my bad. I should have noted that. In the custom action named "Get Logon times" replace -6 in line 34 and 53 with your time zone. This action is in the process start node.

                          Lnadon.



                          Landon,

                          Can you go through how I import these into EM Policy Configuration?

                          I would appreciate it.

                          Thanks.
                          • 10. Re: Easily Displaying Logon Times
                            Landon Winburn Expert
                            You just right click on a particular trigger and choose appsense policy templates/import.