Author Archives: Michael Karsyan

The fastest way to filter events by description

Filtering events by description is one of the most asked questions to us. Some time ago I wrote an article devoted to this problem.

Recently we had to check all events in the security log linked with a certain file (let’s say, it’s winword.exe, C:\Program Files (x86)\Microsoft Office\root\Office16\WINWORD.EXE). The easiest solution was to use Filter command and type file name in the “Text in description” line.

Filter by description

Commonly this works fine, but it scans all records in the log, forms event description for each event and looks for this phrase in the description. Forming event descriptions may require loading extra modules from the target computer (or a computer you designated as a description server) to load the description template. And although Event Log Explorer caches and reuses description templates, such filtering may take long time on large logs.

As a rule, security log stores file names, process names and other details in separate XML elements under  EventData and all these elements are named “Data”.

XML Record

So, we can make an XPath query to a log which compares each Data element with our search string. This query will look like:

*[EventData[Data="C:\Program Files (x86)\Microsoft Office\root\Office16\WINWORD.EXE"]]

To apply this filter, open Security event log, select View->XML Query, type your XPath expression and click OK.

XPath Query Data Filter

It executes swiftly and doesn’t load network when connecting a remote computer.

But what about the other logs? Many Windows events doesn’t have EventData element, but have UserData (some events have DebugData, BinaryEventData, or ProcessingErrorData instead). UserData commonly has an extra level of XML elements, so to query event by UserData, we should use the following XPath request:

*[UserData[*[*="C:\Program Files (x86)\Microsoft Office\root\Office16\WINWORD.EXE"]]]

And what if you want to check for the same file name in several logs, e.g. in Security, System and Application logs? It can be also done with one XML query:

<QueryList>
  <Query Id="0">
    <Select Path="Security">*[EventData[Data=
"C:\Program Files (x86)\Microsoft Office\root\Office16\WINWORD.EXE"]] or 
    *[UserData[*[*=
"C:\Program Files (x86)\Microsoft Office\root\Office16\WINWORD.EXE"]]]
    </Select>

    <Select Path="System">*[EventData[Data=
"C:\Program Files (x86)\Microsoft Office\root\Office16\WINWORD.EXE"]] or 
    *[UserData[*[*=
"C:\Program Files (x86)\Microsoft Office\root\Office16\WINWORD.EXE"]]]
    </Select>

    <Select Path="Application">*[EventData[Data=
"C:\Program Files (x86)\Microsoft Office\root\Office16\WINWORD.EXE"]] or 
    *[UserData[*[*=
"C:\Program Files (x86)\Microsoft Office\root\Office16\WINWORD.EXE"]]]
    </Select>
  </Query>
</QueryList>

Here is the result of this query on my machine:

XML Query result (3 logs)

Advantages of this method

Such XML query provides great performance and works not only with Event Log Explorer, but with Windows Event Viewer or other event log programs which support XML queries.

Some applications and services logs don’t display all the information about event in the description, but still store their details under UserData or EventData elements (I described one of such logs in this article). So, filtering by description won’t work for such events,  but the XPath queries will.

Limitations

Although this approach lets you filter quickly by description details, it is limited by XPath 1.0 implementation for event logs. E.g. you can use only 3 functions: “position”, “Band” (binary and) and “timediff”. Function “contains” is not supported, so it’s impossible to filter just by filename (winword.exe). If you need to filter just by file name, you should use general filter by description.

Can we do something to bypass these limitations? I think so. Filtering by description parameters during log loading stage (and without forming descriptions) should work faster than general filter by description and it will be more flexible than Xpath. But it would be really great if Microsoft extends XPath functionality for event logs.

Facebooktwitterredditpinterestlinkedinmail

Troubleshooting unplanned Windows automatic wake-ups

Whenever I finish working with my computer, I almost never power it off. Instead I send the computer into sleep or hibernate state. This saves lots of time at startup – I can easily continue working without reloading all the projects. However I discovered that recently my Windows 10 laptop started to wake up unexpectedly.  Such unplanned wake-ups can damage computers, e.g. if a laptop left on a sofa, its air vents can be blocked, which leads to overheating.

First, I thought that it’s a Windows automatic maintenance issue and I should look into it. Let’s check it out.

Open Windows Control Panel, Security and Maintenance, Maintenance:

Automatic-Maintenance

Well, it looks like Windows started scheduled maintenance at night and that was the reason for the issue. Click Change maintenance settings.

Schedule-Maintenance-Settings

That’s quite strange. The scheduled time is different from the last run time and wake-up option is not ticked (if this option is ticked on your computer, untick it or change the maintenance time).

So, we need to investigate the problem deeper and check event logs. Start Event Log Explorer and open System log on a local computer. We can set filter by Microsoft-Windows-Kernel-Power, event id = 107 to get resume from sleep events, but this is not a very good way. The event time is almost equal to the sleep time because Windows hasn’t synchronized its clock with the hardware clock yet. We can get the hardware (real) time from XML details of this event (ProgrammedWakeTimeAc or ProgrammedWakeTimeDc), but it’s written in UTC format, so you will have to convert it into your local time.

Fortunately, there is a better way to get sleep/wake-up details. Set filter by Source = Microsoft-Windows-Power-Troubleshooter.

Microsoft-Windows-Power-Troubleshooter-FIlter

Now we can see sleep/resume events in the list. And here is our event along with the reason for waking up. It is NT TASK\Microsoft\Windows\UpdateOrchestrator\Reboot scheduled task.

Power-events-filtered

Let’s find this task.

Run Windows Task Scheduler.

In the left pane browse for Task Scheduler Library\Microsoft\Windows\UpdateOrchestrator

Double click on Reboot in the right pane.

Switch to Condition tab and disable Wake the computer to run the task.

UpdateOrchestrator-Reboot-NoWakeup

That’s it.  Now the computer won’t wake up unexpectedly.

UPDATE

After several days, the problem came back. It appears that Windows modifies Reboot task on its own and enables Wake option. I found some discussions about this issue on Microsoft’s forums, but didn’t get a reasonable solution.

So, I’ve created my own tool: UpdateOrchestrator\Reboot fix.

This tiny program disables Wake option for Update Orchestrator\Reboot task. When you run it, it checks if this option enabled. If so, it switches it off. You should run it elevated or it will fail to update the task.

To run it on regular basis, just create a new task in Task Scheduler. I scheduled to run it every hour and it’s more than enough.

Don’t forget that the program must be run elevated. I scheduled to run it from SYSTEM account:

FixUpdateOrch-SYSTEM

The program is available at http://eventlogxp.com/download/utils/UpdateOrchFix.exe and it’s free for any usage.

Facebooktwitterredditpinterestlinkedinmail

Access event logs from Windows recovery mode

Sometimes this happens. Your computer stops booting correctly and needs to be fixed. Even safe mode doesn’t help. You don’t know the reason of the fault – it may be a hardware failure or a driver bug, but you don’t want to reinstall the operating system. There is a good chance that Windows logs may contain some useful information for troubleshooting. However, you cannot boot into the system to read the logs. What can you do?

As a rule, you can disconnect your hard drive, connect it to another computer and read event logs as files there. But sometimes it is impossible (e.g. your drive is unremovable, inaccessible or you don’t have another computer with the same connection interface).

You may try to start your PC with the recovery console and then use Command Prompt.

The easiest way to access recovery console on Windows 7 is:

  1. Remove all removable disks (CDs, DVDs) from your computer, power on your computer.
  2. Press and hold the F8 key as your computer starts. You need to press F8 before the Windows logo appears. If the Windows logo appears, you need switch your PC off and restart it again.
    Windows 7 advanced boot options
  3. Select Repair Your Computer
    Windows 7 recovery options

Now you can click on Command Prompt. Voila, you may run Windows applications now!

You may get more information at
https://support.microsoft.com/en-us/help/17101/windows-7-system-recovery-options

Unfortunately, this approach commonly may fail with Windows 8 and Windows 10 (although it’s worth to try!). Please check this article which explains this issue:
https://blogs.msdn.microsoft.com/b8/2012/05/22/designing-for-pcs-that-boot-faster-than-ever-before/

To load into recovery console Microsoft suggests to boot your computer either with previously created recovery drive or use the installation media.
However I discovered that if you forcibly restart your computer several times when booting, Windows detects that something goes wrong and suggests to repair.
Windows didn't load correctly - repair options

Click “See advanced repair option”, then click Troubleshoot and then click “Advanced Options”.

On Advanced Options screen you can see different options to recover your PC, but since we decided to check logs first, select Command Prompt Option.

Now you are in.
Command Prompt

You may be surprised, but you will see X: drive in the command prompt.  This is a recovery drive and you can see it only in the recovery session.

Another surprise is that C: drive contains no data!

Your original C: drive would be probably drive D: now. You can check it by viewing its contents e.g. by typing
DIR D:\

Let’s try to view events. First we need to run Event Log Explorer. You may think that you can run Event Viewer, but Windows won’t be able to start neither eventvwr.exe nor eventvwr.msc.

If you have Event Log Explorer originally installed in C:\Program Files (x86)\Event Log Explorer, it’s now on D: drive and you can run it as follows:

“D:\Program Files (x86)\Event Log Explorer\elex.exe” (don’t forget to use double quotes or such paths).
event log explorer in recovery console

You can see a strange computer name in the tree and you will see no logs under this name. This happens because you are in recovery mode and Windows started in minimal configuration (eventlog service is disabled, Windows gives a random name to the PC).

However you can still access the original event logs as files. They are on the system drive in \Windows\System32\winevt\Logs\  folder.

So let’s try to open System log. It will be D:\Windows\System32\winevt\Logs\System.evtx file. You can use any open method – all of them should work correctly. I would recommend use New API since it’s a native method for modern Windows.
Viewing event files from recovery mode

Now you can explore your event logs and hopefully you will be able to locate and troubleshoot the problem.

 

Facebooktwitterredditpinterestlinkedinmail

Filtering all the way

You probably read in the documentation that Event Log Explorer provides 5 ways to filter events. In this article, I will try to explain when you should use one or the other way of filtering.

First, we can arrange filters on applying time:

  1. Pre-load filter. This filter applies to the event log before loading. Only the required events will be loaded.
  2. On-load filter. This filter applies to the event log at the loading stage. While loading, Event Log Explorer will check if an event fits the condition and filters event out.
  3. After-load. This filter applies to the event log after loading.

Pre-load filter is implemented as an XML structured query. Select View->XML Query from the main menu to set this filter. Like Windows Event Viewer you can use a full form of XML Query, but you can also use a short XPath expression. You can find more information about XML Queries at https://msdn.microsoft.com/en-us/library/windows/desktop/dd996910(v=vs.85).aspx

Pros: Works fast and relies on Windows Event Log service. Minimizes network traffic and memory consumption.

Cons: It’s easy to make mistakes when creating complex filters.

When to use: Use it mainly to create a base filter to filter inessential events out.

Example:

*[System[(Level=1  or Level=2 or Level=3)]]

XML filter

This filter displays only Warning, Error and Critical events.

On-load filter is implemented as log loading options feature. Use View->Log Loading Options to access Log Loading Options dialog. Alternatively you can enable default log loading options in Preferences.

Pros: Works fast, minimizes memory consumption.

Cons: Doesn’t filter by descriptions.

When to use: Like XML filter, you can use On-load filter as a base filter. I would recommend use this filter events by age. If you need to display a number of the latest events, On-load filter is the only option for you.

Example:

log loading filter

This filter displays events with Event ID between 4680 and 4689 registered within the last 7 days.

After-load filters are implemented as a general filter, linked filter and quick filters.

Select View->Filter to set a general filter or Advanced->Linked Event Filter to set a linked filter. You should use linked filters only for events that has one common field in event description. You can read more about linked filter usages in this article.

When using after-load filters, Event Log Explorer loads event first and then applies the filter. This gives you ability to reapply or remove filters to the originally loaded list of events. E.g. if you loaded a list from another computer and then this computer goes offline, you can still work with the log and filter events.

Pros: You can filter by virtually any criteria, including event description. You can reuse filters and manage filter library.

Cons: It doesn’t work as fast as pre-load or on-load filters because it loads all events first and then filters them. Consumes more memory than On-load filter.

When to use: You should use this filter whenever you are unable to use other filters (e.g. when you filter by descriptions) or when you need to apply different filters to the same event log.

Example:

general filter

This filter displays events with ID=4689 (process termination) for process name=chrome.exe

Quick filter is a special kind of after-load filter to refine events by a single criterion you can see on the screen. Just click right mouse button on a cell in the list view and use this cell as a template. After applying quick filter, you can continue applying quick filters – they will be applying altogether.

Pros: Easy to use and quick to apply. Non-persistent.

Cons: You can create only simple filters. Non-persistent.

As you can see, I attributed “Non-persistent” to both pros and cons. After each refresh of event log view or applying general or linked filters, Event Log Explorer resets quick filters. Sometimes it’s good because quick filters are commonly used to display specific data just for a short time, but sometimes users may want to keep filtered data between refreshes or event between Event Log Explorer sessions.

When to use: We recommend using quick filters when you browse events, find an interesting event and you want to check the other occurrences of this event.

quick filter

This filter displays events with EventID = 1001

Combining filters

All these filters work independently, so you can combine them. E.g. you can filter out informational events using XML query (   *[System[(Level  != 0 and Level  != 4)  ]]   ). Then you can set on-load filter by a specific event source, e.g. Microsoft Antimalware. Then using general filter you can filter by event description, specifying path to a file as a filter criterion. And finally, you apply quick filters using event date to view how many events of such a kind was recorded in the log.

Facebooktwitterredditpinterestlinkedinmail

Saving event logs to one event log file

When working with event logs, you may find that you have dozens of saved event log files, which you need to review sometimes. And it’s annoying to open each log to check it. Of course, you can open all these files at once (“Open log file” dialog lets you open multiple files) or you can just drag your files from Windows Explorer into Event Log Explorer window. But if you check these log files regularly, it is better to have a single file that contains all the events from these saved event logs. Windows utilities (Event Viewer, wevtutil.exe) don’t let you save (backup) several event logs in one file. As a workaround, you can configure forwarding and collecting events into one log, but in this case, it will collect only new events.

How Event Log Explorer may help you

First, you should merge different event logs in one view. It doesn’t matter whether these logs belong to one computer or to different PCs, domain or workgroup members. You can even mix event logs from Windows XP machines with Windows 10. Or you can merge saved event log files (or mix files with live event logs). To merge event logs, just open any of them, and then right click on the other logs in the tree and select Merge with Current View. If you want to merge files, you should select File->Merge Log File from the main menu. When logs are merged, you can see an icon with stack of logs merged event log view. If you hover mouse over this icon, you will see log names in the merged view.

Now you can save this log view to a file. Although you cannot do backup (due to Windows restrictions), you can simply save the event view to file. However, Event Log Explorer has allows you to save the event view as EVT file. Select File->Save Log As->Save Displayed Events. Moreover, unlike backup you can even filter merged event log before saving. Note that this option lets you save event log view only as EVT log file. It cannot save it in EVTX format. Now you can open this one saved event log and view events from different sources.

Facebooktwitterredditpinterestlinkedinmail

Process tracking with Event Log Explorer

When performing forensic analysis or system audit activities, you may want to track what programs ran on the investigated computers. Windows security auditing lets you enable process tracking and monitor process creation and process termination. To enable process auditing you should use Group Policy Editor (gpedit.msc) or Local Security Policy (secpol.msc). You should configure Security Settings -> Audit Policy -> Audit Process Tracking or use Advanced Audit Policy Configuration -> System Audit Policy -> Detailed Tracking. After enabling process auditing, Windows will register the following events in Security log:

4688 – A new process has been created.
4689 – A process has exited.

Let’s check what events generated when we run an application. I will run Event Log Explorer (elex.exe) for test. Running this application generates a number of events. First, as expected, event 4688 was registered in Security log:

A new process has been created.
Subject:
            Security ID:                  S-1-5-21-1388294503-2733603710-2753204785-1000
            Account Name:                 Michael
            Account Domain:               MIKE-HP
            Logon ID:                     000332DD

Process Information:
            New Process ID:               0000254C
            New Process Name:             C:\Program Files (x86)\Event Log Explorer\elex.exe
            Token Elevation Type:         TokenElevationTypeLimited (3)
            Creator Process ID:           00001010
            Process Command Line:

Token Elevation Type indicates the type of token that was assigned to the new process in accordance with User Account Control policy.

Type 1 is a full token with no privileges removed or groups disabled.  A full token is only used if User Account Control is disabled or if the user is the built-in Administrator account or a service account.

Type 2 is an elevated token with no privileges removed or groups disabled.  An elevated token is used when User Account Control is enabled and the user chooses to start the program using Run as administrator.  An elevated token is also used when an application is configured to always require administrative privilege or to always require maximum privilege, and the user is a member of the Administrators group.

Type 3 is a limited token with administrative privileges removed and administrative groups disabled.  The limited token is used when User Account Control is enabled, the application does not require administrative privilege, and the user does not choose to start the program using Run as administrator.

However, the next event (event id 4689) shows that this process has exit immediately:

A process has exited.

Subject:
            Security ID:              S-1-5-21-1388294503-2733603710-2753204785-1000
            Account Name:             Michael
            Account Domain:           MIKE-HP
            Logon ID:                 000332DD

Process Information:
            Process ID:               0000254C
            Process Name:             C:\Program Files (x86)\Event Log Explorer\elex.exe
            Exit Status:              C000042C

Let’s explore fields in the event descriptions. Subject group is quite clear. Just pay attention to Logon ID – using this ID you can link these events with event 4624 (account logon, New Logon\Logon ID). Process Information group is more interesting for process tracking.

New Process ID (Process ID for 4689 event) defines the ID of Windows process (created or terminated). Note that it is in hexadecimal format, so you need to match with process IDs in Task Manager or other programs, you need to convert it into decimal value.

New Process Name (Process Name) the full path to the executable.

Token Elevation Type defines how the process runs under UAC (User Account Control). Token Elevation Types are described in the event description. “1” means that UAC is disabled (set to Never Notify) or your run the program from Administrator account or a service account (e.g. when system services start, they will register 4688 event with elevation type = 1). “2” means that the user ran the process elevated. This happens when the program manifests itself to run elevated or the user explicitly ran the program using Run as Administrator option. “3” means that the process has been ran without elevation.

Creator Process ID defines a process ID of the process that started this new process. Note that it is in hexadecimal format as well as New Process ID.

Process Command Line defines a command line used to start the process. It includes the full path to the executable along with command line parameters. By default, Process Command Line is empty (because it may contains sensitive data like passwords). To enable command line logging you should enable policy “Include command line in process creation events”. This policy is available at Administrative Templates -> System -> Audit Process Creation.

Exist status (in event 4689) – the process exit code. Zero value commonly means that the process has exited normally.

In my example we can see that elex.exe has been terminated immediately after start with exit code C000042C. This code indicates that the process required elevation. Why this happens. The program (elex.exe) is designed to run elevated. When I started it by clicking on its icon, Windows tried to run it first and only then detected the program requires elevation. That’s why it terminated current instance.

What’s next? The next event is 4688 and Windows starts consent.exe process. This program displays Window UAC dialog and prompts the user for permissions to run our program elevated. Then (if the user accepts elevation) Windows starts dllhost.exe process (event 4688) to provide running COM+ components, terminates consent.exe (event 4689) and at last starts elex.exe (event 4688 with Token Elevation Type = 2). This means that we can ignore processes that terminated immediately with exist status of C000042C and when tracking the processes, I would recommend to exclude the helper processes like consent.exe, dllhost.exe, conhost.exe, svchost.exe, taskhost.exe.

If I start the program  using “Run as administrator” option, Windows will not register first run/exit events, but register all the rest events (consent, dllhost, and elevated elex.exe).

Let’s practice

First we should filter Security log by event id = 4688, 4689. I will use Log Loading filter – but you can use general filter instead.

process-tracking-filter-4688-4689

Now we can display process name (path to the executable) in the list as custom columns. I will add 2 custom columns – Process started and Process Terminated.

process-tracking-custom-column

Let’s remove helper processes from the list. We can filter by description parameters:

 Process Information\Process Name  does not contain host.exe
 Process Information\New Process Name  does not contain host.exe
 Process Information\Process Name  does not contain consent.exe
 Process Information\New Process Name  does not contain consent.exe

process-tracking-filter-helper

Now we can see the result:

process-tracking-result

Windows 10

Windows 10 (and forthcoming Windows 2016) comes with modified details of event 4688. The most significant addition is that the event description contains Creator Process Name field. It defines the name of the process that started this new process.

Facebooktwitterredditpinterestlinkedinmail

Automating event log backup

Recently we received a question from our customer who asked about regular backing up of system and application event logs. He wanted to backup only local logs, but let’s extend the task for remote logs as well. So our task is to backup System and Application event logs from a local computer and remote machine (SERV1) into a folder two times a week.

Let’s try to do it using standard tools. Windows event viewer lets you backup event log – there is a command in Event Viewer – “Save all event as” and you should save them into evtx format. However, it doesn’t allow you to backup an event log from a remote server to a local computer or visa-versa.  You will get a message:

An error occurred while Event Viewer was saving a log file in .evtx format from SERVER to PATH.
Events from the remote computer cannot be saved into .evtx format files on the local computer. If you want to save the events to the local computer, select a different file format. To save the events in .evtx format, save them onto the remote computer.

Why this happens? Windows Event Log Service (eventlog), which is responsible for all main event log functionality is running under LocalService account. LocalService presents anonymous credentials on the network, so it has no permissions to backup event log anywhere, but computer on which the service is running. The same limitation has wevtutil.exe command. It works with local event logs only.

What about Event Log Explorer? We designed Event Log Explorer to backup remote event logs as easy as local ones. When backing up a remote logs, it saves the log into a shared folder on a remove computer and then moves it into the target folder.

Just click right mouse button a log you wish to backup in the tree and select Save log as. Event Log Explorer will do the rest.

event log explorer backup

Note that you must have administrative permissions on the server Serv1 or you won’t be able to access files from ADMIN$ resource.

Of course, you can backup event logs manually, but our user asked us to automate process. Event Log Explorer comes with ELBACK utility which can be located in the application folder (default location is “C:\Program Files (x86)\Event Log Explorer\elback.exe”). This utility developed exactly for batch backup of event logs. Detailed information about this utility available in Event Log Explorer help.

Here is our command line to backup Application and System logs from a local PC and Serv1:

elback.exe D:\backup Application System \\Serv1\Application \\Serv1\System /clear

Remove /clear option if you don’t want to empty log automatically after backup.

Run this command to test it. If it works correctly, you will see 4 new files in D:\Backup folder that looks like Serv1-System-2016-05-18-10-56-056.evt.

Now we can automate the process. I will use Windows Scheduler. In article Exporting event logs with Windows PowerShell I described how to create Windows Scheduler task with PowerShell. Here I will just use Windows UI for this.

Click Windows Start button, then All Programs->Accessories->System Tools->Task Scheduler
Select Task Scheduler Library in the tree.
Create Basic Task from the menu.
Give any name to the task, e.g. “Logs backup”.
Click Next.
On Task Trigger page select Weekly.
Click Next.
Specify when you want to run the task.
Click Next.
Select “Start a program”
click Next.
In Program/Script line type
“C:\Program Files (x86)\Event Log Explorer\elback.exe”
In Add arguments type
D:\backup Application System \\Serv1\Application \\Serv1\System /clear
Click Next
Click Finish.

Now you can find your task in the list.
Click right mouse button on the task and select Run to test it.
Check “D:\Backup” folder if new evtx files appear.

Important note: if you decide to backup a local Security event log, you will probably need to elevate permissions to access the security log. To do so, click right mouse button on Logs backup task in Windows Scheduler and select Properties. In the Properties dialog enable checkbox “Run with highest privileges”.

Scheduling event log backup

Don’t forget to the task before going production.

Facebooktwitterredditpinterestlinkedinmail

Tracking down who removed files

Let’s assume you have a shared folder on a server which is accessible by all employees in your company. The users commonly copy some documents into this folder to let the others to work with these shared documents. One day you discover that some files unexpectedly disappeared from the shared folder. Usually this means that someone deleted these files (consciously or unconsciously). Now we need to detect the person who removed the files.

First, you need to setup Windows security auditing to monitor file access (and optionally logon) events. Of course, you should do it right after creating a shared folder and granting access to it (post factum setup won’t help you) . This article describes how to setup security auditing and audit file access and logon events.

If you correctly setup file access auditing for your shared folder, “File system” events will appear in Security log on every attempt to open file inside the folder.

file system auditing

So be sure that the maximum log size for Security log is set to a reasonable value (or you have a chance to lose old events). Microsoft recommends 4GB for most of Windows, but this depends on different factors – I prefer much smaller sizes with autobackup option.

Event 4660 occurs when someone removes a file or a folder. But its event description doesn’t contain the file name:

An object was deleted.

Subject:
            Security ID:                  S-1-5-21-3946697505-1589476648-2597793080-1114
            Account Name:                 mike
            Account Domain:               FSPRO
            Logon ID:                     0084C195

Object:
            Object Server:   Security
            Handle ID:        00000AC8

Process Information:
            Process ID:       00000004
            Process Name: 
            Transaction ID: {00000000-0000-0000-0000-000000000000}

In fact, when a user deletes file, Windows registers several events: 4663 and then 4660. It can also register event 4656 before 4663).

Here is a sample of 4663 event description:

An attempt was made to access an object.

Subject:
            Security ID:                  S-1-5-21-3946697505-1589476648-2597793080-1114
            Account Name:                 mike
            Account Domain:               FSPRO
            Logon ID:                     0084C195

Object:
            Object Server:   Security
            Object Type:     File
            Object Name:     C:\shared\Data\_DSC9978.JPG
            Handle ID:       00000AC8

Process Information:
            Process ID:      00000004
            Process Name: 

Access Request Information:
            Accesses:        DELETE
            Access Mask:     10000

You can notice that “Access Request Information” group contains Accesses: DELETE and Access Mask: 10000 parameters.

So we can just filter security event log by Event ID = 4663 and Access Request Information\Accesses = DELETE (and if you enabled auditing for several folders, but want to check a specific one, you should also add filter by Object\Object Name):

event 4663 - filter deleted events

Now we can see all “file delete” events with file names.

This method works most of time, but I wouldn’t call it perfect. First, nobody guaranty that Accesses will be DELETE all the time (although you can try Access Request Information\Accesses Contains DELETE). Second, 4663 event occurs on access attempt. In some cases, e.g. if your file is protected, event 4660 won’t appear. So to get more accurate picture, we should rely upon 4663 events and get details from the previous events. Event Log Explorer features Linked Filter, which allows you to link events in security log by description parameter. Look again at 4660 and 4663 event samples. You can link them by Object\Handle ID parameter. Note that Linked Filter scans events from top to bottom, so make sure that you sorted events from new to old (our base event will be 4660).

linked filter - events 4660-4663

Here I got the same result as before.

Now you can just display who deleted files. Event description keeps these details in “subject” group. I will use custom columns to show these details in the list:

custom columns-deleted files

Here is the result of adding custom columns:

showing-users who deleted files

You probably noticed that I added Logon ID along with User name. Using the Logon ID, we can detect from which machine user FSPRO\mike deleted files.

Just set a new filter for event id = 4624 (An account was successfully logged on):

looking for machine - filter by event 4624

And we are getting the machine name and its IP address

workstation name and ip address

 

Facebooktwitterredditpinterestlinkedinmail

Windows boot performance diagnostics. Part 2

If you read the previous part of this article, you already know what Microsoft-Windows-Diagnostics-Performance log is for, why similar events have different event types and what information is “hidden” in the event details.

Now it’s time to practice. First, we need to decide what we will try to optimize. Let’s display only startup, shutdown and standby/resume events. The event IDs are 100, 200 and 300 respectfully. So let’s filter by event id = 100, 200, 300:
eventfilter-100-200-300

You can optionally switch warnings off in the filter to get error and critical events, but I will leave it checked.

Now we can view statistics of the events. Select Advanced from the main menu, click Analytical Reports. Then in the Analytical Report window click Report and select Event ID stats. I switched to Pivot chart for better view:
boot performance analytical report - standby

As you can see, I have just got a few Windows startup events in this log (and only 1 shutdown event). Most of events here are Standby/Resume events. There are several reasons for this – I switch off/reboot the computer very rarely, most of the time I use hibernate or sleep commands to switch off the computer. My primary drive is a SSD drive so I don’t have problems with prefetch at startup, so My PC commonly starts up in about 10 seconds.  And I don’t have too many autorun programs or services.

However, I really have performance issues with hibernation and resume. So let’s check what the reason of such performance degradation can be. Event 300 contains lots of parameters (similar to event 100 described in the previous post), but they don’t describe the source of the problem. As you may remember, the details of the problems are listed in the events that follow the “basic” events. For standby/resume – they are 3xx. So let’s filter by event id = 301-399 (Note that if you troubleshoot boot up events, it will be 101-110 or 101-199).
eventfilter-301-399

We can build event ID stats diagram again (it is not necessary, but we may find out common reasons of the problems):
degradation-reasons-general

We can see that the typical reasons of the degradations are the device driver issues (302, 351) and application issues (301).

So, let’s concentrate only on these events: set event filter to Event ID = 301, 302, 351
eventfilter-301-302-351

Now we should somehow display the source of the problem. In this article, I showed how to use custom columns. Fortunately for all these events, the sources of the problem have the same sequence numbers:
3 – an application file name or a driver name
5 – friendly name of an application or a driver
11 – full path to an application or a driver.

These numbers you can get from the XML view of these events (double click on event and switch to XML).

I will use friendly name (but you should be aware that some applications may have no friendly name):

Go to View->Custom columns and add a new column from PARAM[5]:
ProblemSource-CustomColumn

Now you can see the problem source as a column in the event list.
performance-diagnostics with custom column displaying faulty app

Let’s create a new pivot chart for this table, event log view to get statistics for “Problem source” column. Go to Advanced->Analytical reports. Then select “CustomColumn1 stats” from the Report menu.
diagnostic performance - reasons of degradation

Now I can see that I should check if a new version of ACPI Driver for NT available (and I should pay attention to Default Hub Driver for USB and several other drivers and applications).

Although I could stop at this point, I will show one more way of detecting the sources of performance issues. When researching events 101+, 201+ and 301+, you can find two parameters under EventData. They are TotalTime and DegradationTime. Totaltime is the time in milliseconds it took for processing (time to initialize a service, start an application, unload application etc). DegradationTime is the time meaning how much longer than usual it took for processing. So, we can exclude some unnecessary events that took not too much time, but are in the list. Let’s display only events that took 300 or more milliseconds. Do not close the pivot chart, just switch back to Event Log Explorer window to set filter. In the article “Advanced filtering. How to filter events by event description” I mentioned about setting XML query filters using XPath syntax. Now we can use it to refine events. Select View->XML query and type

*[EventData[Data[@Name='TotalTime']>'300']]

In my case, the number of displayed events reduced 8 times. Switch back to Analytical Report window and click Reconcile button.
performance diagnostics - refined degradation reasons

And we see a different picture – BlueSoleilCS and ATAPI miniport make contribution to the performance degradation.

I hope that not only you learned about Microsoft-Windows-Diagnostic-Performance events, but also got helpful information about the advanced usage of Event Log Explorer. The article covered several topics that our users often miss: XML view of an event, Analytical reports, custom columns and XML query filter.

Facebooktwitterredditpinterestlinkedinmail

Windows boot performance diagnostics. Part 1

Have you ever seen that your computer starts booting slowly? Or it slowly restores its state from hibernation. Maybe you observe performance issues when shutdown or hibernate process? In this article, I will show you how you can use Event Log Explorer to find performance problems linked with the startup/shutdown/hibernate/resume processes.

Starting from Windows Vista, Microsoft provides a bunch of event logs for different system purposes. In Windows Event Viewer, these logs are located in a special branch: “Applications and Services Logs”. Windows records performance diagnostics events into Microsoft-Windows-Diagnostics-Performance/Operational event log. To open this log in Windows Event Viewer, open Applications and Services Logs branch, then open Microsoft, then open Windows, then select Diagnostics-Performance and click on Operational.  In Event Log Explorer you can do it easier: open your computer in the tree, then open Microsoft-Windows folder and then click  Microsoft-Windows-Diagnostics-Performance/Operational.

Microsoft-Windows-Diagnostics-Performance

Now you can see a list of different diagnostic events. As you can see, events with the same event ID may have different types – Warning, Error and Critical. It looks like these event types depend on the duration of the startup/shutdown process. Another observation – theses events contain many important parameters internally, but you can’t see them in the event description (Windows Event Viewer doesn’t display them as well). The only way to display these parameters is to double click on the event to display event properties and switch to XML tab.

Compare:
diagnostics-performance event details

Unfortunately, I didn’t find a detailed documentation about all these events, so I did some research. First, I got meaning of events in Microsoft-Windows-Diagnostics-Performance:

Event ID Event Description
Boot Performance Monitoring
100 Windows has started up
101 This application took longer than usual to start up, resulting in a performance degradation in the system startup process
102 This driver took longer to initialize, resulting in a performance degradation in the system start up process
103 This startup service took longer than expected to startup, resulting in a performance degradation in the system start up process
104 Core system took longer to initialize, resulting in a performance degradation in the system start up process
105 Foreground optimizations (prefetching) took longer to complete, resulting in a performance degradation in the system start up process
106 Background optimizations (prefetching) took longer to complete, resulting in a performance degradation in the system start up process
107 Application of machine policy caused a slow down in the system start up process
108 Application of user policy caused a slow down in the system start up process
109 This device took longer to initialize, resulting in a performance degradation in the system start up process
110 Session manager initialization caused a slow down in the startup process
Shutdown Performance Monitoring
200 Windows has shutdown
201 This application caused a delay in the system shutdown process
202 This device caused a delay in the system shutdown process
203 This service caused a delay in the system shutdown process
Standby Performance Monitoring
300 Windows has resumed from standby
301 This application caused a delay during standby
302 This driver caused a delay during standby while servicing a device
303 This service caused a delay during hybrid-sleep
304 Creation of the hiber-file was slower than expected
305 Persisting disk caches was slower than expected
306 Preparing the video subsystem for sleep was slower than expected
307 Preparing Winlogon for sleep was slower than expected
308 Preparing system memory for sleep was slower than expected
309 Preparing core system for sleep was slower than expected
310 Preparing system worker threads for sleep was slower than expected
350 Bios initialization time was greater than 250ms (logo requirement) during system resume
351 This driver responded slower than expected to the resume request while servicing this device
352 Reading the hiber-file was slower than expected
System Performance Monitoring
400 Information about the system performance monitoring event
401 This process is using up processor time and is impacting the performance of Windows
402 This process is doing excessive disk activities and is impacting the performance of Windows
403 This driver is using up too many resources and is impacting the performance of Windows
404 This driver is waiting longer than expected on a device
405 This file is fragmented and is impacting the performance of Windows
406 Disk IO to this file is taking longer than expected
407 This process is using up too much system memory
408 Many processes are using too much system memory
Desktop Window Manager Monitoring
500 The Desktop Window Manager is experiencing heavy resource contention
501 The Desktop Window Manager is experiencing heavy resource contention

Since we research boot/shutdown/standby/resume performance, we should pay attention to 1xx, 2xx and 3xx events. We can see that events 100, 200 and 300 are basic events followed by 1xx, 2xx and 3xx which give extra information about the problem.

E.g. I can see two events

Event 100 :

Windows has started up:
    Boot Duration        :              34857ms
    IsDegradation        :              0
    Incident Time (UTC)  :              18.11.2015 23:58:10

 

Event 102:

This driver took longer to initialize, resulting in a performance degradation in the system start up process:
    File Name             :              mssmbios
    Friendly Name         :              System Management BIOS Driver
    Version               :              6.1.7600.16385 (win7_rtm.090713-1255)
    Total Time            :              1027ms
    Degradation Time      :              1026ms
    Incident Time (UTC)   :              18.11.2015 23:58:10

So we can see that System Management BIOS Driver caused the delay in the system boot up.

Unfortunately sometimes events 100, 200 and 300 occur alone without followed events. In this case it is impossible to detect the reason of the delay using Diagnostics-Performance event log.

You should pay attention to parameters of Event 100 (Microsoft-Windows-Diagnostics-Performance):

                 
 System
 ...
 EventData          
                 BootTsVersion 2
                 BootStartTime  2015-11-18T20:58:10.671600300Z
                 BootEndTime    2015-11-18T20:58:10.671600300Z
                 SystemBootInstance     89
                 UserBootInstance          84
                 BootTime           34857
                 MainPathBootTime       12657
                 BootKernelInitTime      21
                 BootDriverInitTime       3101
                 BootDevicesInitTime    18
                 BootPrefetchInitTime  0
                 BootPrefetchBytes        0
                 BootAutoChkTime         0
                 BootSmssInitTime          5084
                 BootCriticalServicesInitTime    436
                 BootUserProfileProcessingTime             2683
                 BootMachineProfileProcessingTime    0
                 BootExplorerInitTime   848
                 BootNumStartupApps  24
                 BootPostBootTime        22200
                 BootIsRebootAfterInstall           false
                 BootRootCauseStepImprovementBits 0
                 BootRootCauseGradualImprovementBits          0
                 BootRootCauseStepDegradationBits    4
                 BootRootCauseGradualDegradationBits             0
                 BootIsDegradation         False
                 BootIsStepDegradation               false
                 BootIsGradualDegradation        false
                 BootImprovementDelta              0
                 BootDegradationDelta 0
                 BootIsRootCauseIdentified       true
                 OSLoaderDuration         735
                 BootPNPInitStartTimeMS           21
                 BootPNPInitDuration    1342
                 OtherKernelInitDuration            332
                 SystemPNPInitStartTimeMS     1665
                 SystemPNPInitDuration              1776
                 SessionInitStartTimeMS             3451
                 Session0InitDuration    2088
                 Session1InitDuration    339
                 SessionInitOtherDuration          2656
                 WinLogonStartTimeMS               8536
                 OtherLogonInitActivityDuration             587
                 UserLogonWaitDuration             3551

Most of parameters are self-descriptive.

Pay attention that BootTime= MainPathBootTime + BootPostBootTime

MainPathBootTime is the time (in milliseconds)  from when the Windows Logo first appears on screen and until your desktop or logon prompt is presented.

BootPostBootTime is the time (in milliseconds) from the logon screen or desktop showing up and until the system become actually usable (the system has reached 80% idle).

In  many cases (but not in my sample), the problem with long boot time is linked with Windows Prefetcher – you will see that BootPrefetchInitTime is set to a large value, e.g. 60000 or more. In this case you can play with Superfetch service and Superfetch caching parameters (registry key HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Control\Session Manager\Memory Management\PrefetchParameters). If you have just changed your HDD or SSD, you should re-run the assessment in Performance Information and Tools applet (or just run Winsat command as winsat.exe diskformal) to make Windows use the best prefetch strategy.

Now you have some background information about Diagnostics-Performance events. In the next part I will show how Event Log Explorer helps to detect boot performance issues.

Facebooktwitterredditpinterestlinkedinmail