I like log files. A good log file can tell you a lot about what happened, be it whether a package was successfully installed, why a user could not check mail, or who tried to connect to our voip server. As a result I use log monitoring a lot on Linux/Unix/OSX. You'll always find me with a session running tail, and sometimes grep, against the appropriate log files. That's how I roll.
On Windows, it seems the status quo when something goes boink is to restart services or host, or hope the error message in the dialog box that popped up is useful enough to be googled. But, Windows has log files just like the other programs. Yes, a lot of application developers do not bother to write good logs for their apps, but the OS itself has a metric buttload of logs which might have caught error messages from those applications. So, let's talk a bit about those logs and how to monitor them. I will warn you that as I come from Unix/Linux, I am very command line-oriented, so expect this discussion to be a bit clickety-click challenged.
The way of the land
Windows does create quite a few log files and has directories (or folders if you will). Here is some of what I see in my rather boring default Windows 7 desktop:
C:\>dir Windows\*.log
Volume in drive C has no label.
Volume Serial Number is 705E-722F
Directory of C:\Windows
12/21/2013 05:53 AM 1,774 DtcInstall.log
01/14/2014 02:15 PM 9,640 IE10_main.log
02/17/2014 07:21 PM 26,875 IE11_main.log
12/20/2013 07:19 PM 3,792 IE9_main.log
12/15/2014 07:39 PM 6,564 PFRO.log
12/15/2014 07:39 PM 16,716 setupact.log
07/13/2009 11:51 PM 0 setuperr.log
12/21/2013 05:53 AM 1,313 TSSysprep.log
01/04/2015 02:07 AM 1,455,242 WindowsUpdate.log
9 File(s) 1,521,916 bytes
0 Dir(s) 14,102,495,232 bytes free
C:\>dir Windows\System32\LogFiles
Volume in drive C has no label.
Volume Serial Number is 705E-722F
Directory of C:\Windows\System32\LogFiles
09/23/2014 02:35 AM <DIR> .
09/23/2014 02:35 AM <DIR> ..
07/14/2009 12:32 AM <DIR> Fax
07/13/2009 09:34 PM <DIR> Firewall
09/23/2014 02:35 AM <DIR> HTTPERR
12/15/2014 07:50 PM <DIR> Scm
12/21/2013 04:00 PM <DIR> SQM
07/14/2009 12:32 AM <DIR> Windows Portable Devices
07/13/2009 11:45 PM <DIR> WMI
07/13/2009 09:36 PM <DIR> WUDF
0 File(s) 0 bytes
10 Dir(s) 14,102,495,232 bytes free
C:\>Let's say you want to probulate the WindowsUpdate.log file since it sounds interesting. You open it in notepad, which will get unhappy as it is rather large, or wordpad. Or get notepad++ which I personally recommend.
What if you want to see the file in the command line? The equivalent of the Unix/Linux/OSX cat command it type, but you really do not want to run it on that file. Trust me; I just did it and it scrolled long enough for me to write this and the last paragraph. That does not sound impressing but I am a slow typist. I even had time to get the link for notepad++. Next option is to use more, which is just like the same command in the other operating systems. So you would then be able to see (without them just zooming past your eyes) entries like
2014-12-17 00:54:32:864 920 a3c Agent Update {E0A75066-D16E-44
D0-8B6E-2B4708ABE781}.201 is pruned out due to potential supersedence
2014-12-17 00:54:32:864 920 a3c Agent * Added update {9FF3F8
7F-0DC5-4484-B757-37C4C25D4965}.201 to search result
2014-12-17 00:54:32:864 920 a3c Agent * Found 49 updates and
77 categories in search; evaluated appl. rules of 1876 out of 2659 deployed ent
ities
2014-12-17 00:54:32:911 920 a3c Agent *********
2014-12-17 00:54:32:911 920 a3c Agent ** END ** Agent: Find
ing updates [CallerId = AutomaticUpdates]
2014-12-17 00:54:32:911 920 a3c Agent *************
2014-12-17 00:54:32:942 920 a3c Report REPORT EVENT: {EFE8CD74-
F8C9-4D59-8F52-63D3EA18D227} 2014-12-17 00:54:32:895-0500 1 147
101 {00000000-0000-0000-0000-000000000000} 0 0 AutomaticUpdates
Success Software Synchronization Windows Update Client successful
ly detected 49 updates.
2014-12-17 00:54:32:942 920 a3c Report CWERReporter finishing e
vent handling. (00000000)
2014-12-17 00:54:32:942 920 a3c Report CWERReporter finishing e
vent handling. (00000000)
2014-12-17 00:54:32:942 920 a3c Report CWERReporter finishing e
vent handling. (00000000)
2014-12-17 00:54:32:942 920 a3c Report CWERReporter finishing e
vent handling. (00000000)
2014-12-17 00:54:32:942 920 a3c Report CWERReporter finishing e
vent handling. (00000000)
2014-12-17 00:54:32:942 920 874 AU >>## RESUMED ## AU: Se
arch for updates [CallId = {544A18F0-EC84-497E-ADEE-F8DEF8F09585}]
2014-12-17 00:54:32:942 920 874 AU # 49 updates detected
2014-12-17 00:54:32:942 920 874 AU #########
2014-12-17 00:54:32:942 920 874 AU ## END ## AU: Search
for updates [CallId = {544A18F0-EC84-497E-ADEE-F8DEF8F09585}]
2014-12-17 00:54:32:942 920 874 AU #############
2014-12-17 00:54:32:942 920 874 AU Successfully wrote event
for AU health state:0
2014-12-17 00:54:32:942 920 874 AU #############
2014-12-17 00:54:32:942 920 874 AU ## START ## AU: Refresh
featured updates info
-- More (0%) --At this point you might be better off opening this massive file in wordpad or notepad++ and use its search features. But you get the point. However, sometimes you want to see what is being added to a log file in real time. And that dovetails to...
Monitoring
As I mentioned before, when tracking down issues I like to see what a log file spits out as I do something. I will use here a real example that happened today: let's say you have two Windows servers where serverA runs a service on port, say, 8002 that a program on serverB connects to. And example to this setup would be a web server reaching a database server. Problem is that the two servers are not talking to each other. Since both programs/services are commercial products, you contact both vendors. VendorB states it must be a firewall issue or misconfiguration on serverA. You run netstat on serverA and see that the process is running:
Active Connections
Proto Local Address Foreign Address State
TCP 0.0.0.0:135 0.0.0.0:0 LISTENING
RpcSs
[svchost.exe]
TCP 0.0.0.0:445 0.0.0.0:0 LISTENING
Can not obtain ownership information
TCP 0.0.0.0:3389 0.0.0.0:0 LISTENING
TermService
[svchost.exe]
TCP 0.0.0.0:5985 0.0.0.0:0 LISTENING
Can not obtain ownership information
TCP 0.0.0.0:8002 0.0.0.0:0 LISTENING
[probltr.exe]
TCP 0.0.0.0:47001 0.0.0.0:0 LISTENING
Can not obtain ownership information
TCP 0.0.0.0:49152 0.0.0.0:0 LISTENING
[wininit.exe]
TCP 0.0.0.0:49153 0.0.0.0:0 LISTENING
EventLog
[svchost.exe]
Next step you do is connect from a machine which is allowed by the network firewall to reach serverA using telnet or nmap or netcat or even your own crafted Powershell script; pick your poison. It works. Then you do the same from serverA, and get the same results. So, then next step now is to see if vendorB's program is talking to serverA.
We could install wireshark, but then we look at the name of this blog entry and decided to use only what comes with Windows. Since we have network questions, let's make the firewall log on both servers a bit more verbose
PS C:\Windows\system32> netsh firewall set logging droppedpackets = enable connections= enable
IMPORTANT: Command executed successfully.
However, "netsh firewall" is deprecated;
use "netsh advfirewall firewall" instead.
For more information on using "netsh advfirewall firewall" commands
instead of "netsh firewall", see KB article 947709
at http://go.microsoft.com/fwlink/?linkid=121488 .
Ok.
PS C:\Windows\system32>
What we told it to do is to log every time a packet is dropped and a connection is started no matter the outcome. We should be good to go but I would sleep better at night by verifying:
PS C:\Windows\system32> netsh firewall show logging
Log configuration:
-------------------------------------------------------------------
File location = C:\Windows\system32\LogFiles\Firewall\pfirewall.log
Max file size = 4096 KB
Dropped packets = Enable
Connections = Enable
IMPORTANT: Command executed successfully.
However, "netsh firewall" is deprecated;
use "netsh advfirewall firewall" instead.
For more information on using "netsh advfirewall firewall" commands
instead of "netsh firewall", see KB article 947709
at http://go.microsoft.com/fwlink/?linkid=121488 .
PS C:\Windows\system32>
Note that it even told us the path to the firewall log, but we kinda new that from earlier on, right?
So let's do some monitoring, and to do that we need to get some help from Powershell. Now there are many ways to run powershell, but if you are still on the DOS prompt, how about if you just type powershell there? You will know you are in powershell because your prompt is now PS C:\> (note the PS in the front)
C:\>powershell
Windows PowerShell
Copyright (C) 2009 Microsoft Corporation. All rights reserved.
PS C:\>
As this blog entry is getting long, and because I know the outcome, I will focus only on
serverB.
If you want to emulate
tail -f C:\Windows\system32\LogFiles\Firewall\pfirewall.log
in Powershell, you can do something like
Get-Content -Path "C:\Windows\System32\LogFiles\Firewall\pfirewall.log" -wait
Since I only care about the entries that go to serverA whose IP (192.168.1.5) I happen to know, I can emulate
tail -f C:\Windows\system32\LogFiles\Firewall\pfirewall.log | grep '192.168.1.5'
By doing
PS C:\Windows\system32> Get-Content -Path "C:\Windows\System32\LogFiles\Firewall\pfirewall.log" -wait| Select-String -pa
ttern "192.168.1.5"
2015-01-02 07:50:09 ALLOW TCP 192.168.2.7 192.168.1.5 34414 5001 0 - 0 0 0 - - - SEND
2015-01-02 09:54:45 ALLOW TCP 192.168.1.5 192.168.2.7 57842 5000 0 - 0 0 0 - - - RECEIVE
2015-01-02 10:08:09 ALLOW TCP 192.168.2.7 192.168.1.5 38365 5001 0 - 0 0 0 - - - SEND
2015-01-02 10:09:09 ALLOW TCP 192.168.2.7 192.168.1.5 38403 5001 0 - 0 0 0 - - - SEND
2015-01-02 10:10:52 ALLOW TCP 192.168.1.5 192.168.2.7 57973 5000 0 - 0 0 0 - - - RECEIVE
2015-01-02 10:13:09 ALLOW TCP 192.168.2.7 192.168.1.5 38525 5001 0 - 0 0 0 - - - SEND
2015-01-02 10:15:09 ALLOW TCP 192.168.2.7 192.168.1.5 38584 5001 0 - 0 0 0 - - - SEND
2015-01-02 10:16:09 ALLOW TCP 192.168.2.7 192.168.1.5 38613 5001 0 - 0 0 0 - - - SEND
2015-01-02 10:19:09 ALLOW TCP 192.168.2.7 192.168.1.5 38674 5001 0 - 0 0 0 - - - SEND
2015-01-02 10:26:09 ALLOW TCP 192.168.2.7 192.168.1.5 38853 5001 0 - 0 0 0 - - - SEND
2015-01-02 10:28:09 ALLOW TCP 192.168.2.7 192.168.1.5 38919 5001 0 - 0 0 0 - - - SEND
2015-01-02 10:34:09 ALLOW TCP 192.168.2.7 192.168.1.5 39090 5001 0 - 0 0 0 - - - SEND
2015-01-02 10:36:09 ALLOW TCP 192.168.2.7 192.168.1.5 39146 5001 0 - 0 0 0 - - - SEND
2015-01-02 10:46:09 ALLOW TCP 192.168.2.7 192.168.1.5 39497 5001 0 - 0 0 0 - - - SEND
2015-01-02 10:47:12 ALLOW TCP 192.168.2.7 192.168.1.5 39528 5001 0 - 0 0 0 - - - SEND
2015-01-02 10:50:09 ALLOW TCP 192.168.2.7 192.168.1.5 39625 5001 0 - 0 0 0 - - - SEND
2015-01-02 10:52:09 ALLOW TCP 192.168.2.7 192.168.1.5 39701 5001 0 - 0 0 0 - - - SEND
2015-01-02 10:54:09 ALLOW TCP 192.168.2.7 192.168.1.5 39770 5001 0 - 0 0 0 - - - SEND
2015-01-02 11:05:40 ALLOW TCP 192.168.2.7 192.168.1.5 40057 5001 0 - 0 0 0 - - - SEND
2015-01-02 11:08:09 ALLOW TCP 192.168.2.7 192.168.1.5 40145 5001 0 - 0 0 0 - - - SEND
2015-01-02 11:13:09 ALLOW TCP 192.168.2.7 192.168.1.5 40306 5001 0 - 0 0 0 - - - SEND
2015-01-02 11:45:09 ALLOW TCP 192.168.2.7 192.168.1.5 41218 5001 0 - 0 0 0 - - - SEND
2015-01-02 11:51:15 ALLOW TCP 192.168.1.5 192.168.2.7 59024 5000 0 - 0 0 0 - - - RECEIVE
2015-01-02 12:22:09 ALLOW TCP 192.168.2.7 192.168.1.5 42375 8002 0 - 0 0 0 - - - SEND
Note that the only time serverB (192.168.2.7) ever connected today to serverA (192.168.1.5) was when I tried to connect to it, in this case using telnet. So, I sent the above to VendorB, which agreed (admited?) their software was misconfigured, and corrected that.
Once you verify both servers are talking to each other, you could then reset the firewall by typing
netsh firewall set logging droppedpackets = disable connections= disable
