Previous Page
Next Page

Working with Logging Step-by-Step Exercises

In this section, we will use WMI logging capabilities to assist in troubleshooting a scripting problem. To do this, we will increase the logging level to Verbose and run two scripts that have a few problems in them. We will conclude the exercise by running a good script and comparing the information that is logged from this script with the results from the bad scripts.

1.
Increase the WMI logging level. Click Start and then click Run.

2.
In Open dialog box, type wmimgmt.msc and then click OK.

3.
Right-click WMI Control (Local).

4.
Select Properties.

5.
Select the Logging tab.

6.
Change the logging level to Verbose.

7.
Increase the maximum log size to 256,000 or more.

8.
Click OK and close the MMC.

9.
Open the WMI logging directory in Windows Explorer. The directory is listed below:

C:\WINDOWS\system32\wbem\Logs

10.
Sort the file view by date. You can do this by clicking the Date Modified tab at the top of the Date column. Ensure that the most recent dates are on the top.

11.
Open the \My Documents\Microsoft Press\VBScriptSBS\ch21\StepByStep\BadScript1.vbs script and run it. (Don't worry, it will not break anything.) Do not close the script output window. You will need the time stamp that is returned from the Now function.

12.
When the script completes, make a note of the exact date and time the script completed.

13.
Go to the WMI log file directory and press the F5 function key to refresh the view of the file dates. Examine the file dates closely. Do you see any that match (or are very close) to the time stamp that was produced by running BadScript1.vbs? You should see at least three files with time stamps very near the time indicated by the running of the BadScript1.vbs file. The three files should be WinMgmt.log, Wbemprox.log, and WbemCore.log.

14.
If you do not see any recent files with a recent date modified time stamp, you can refresh the folder view by pressing F5. If you still do not see any log files with a date modified time stamp close to the one resulting from running BadScript1.vbs, then go back and double-check to ensure the Verbose WMI logging level is properly set. If you are using an operating system earlier than Windows XP, you will need to restart the WMI service for the logging level change to take effect. Windows XP and Windows Server 2003 dynamically apply the changes.

15.
Once you have found the log files, open WinMgmt.log with Notepad and scroll to the bottom of the file. Look for the time stamp that matches (or at least is within a few seconds of) the time produced by BadScript1.vbs. You will see some errors that look similar to the following:

(Sat Jul 30 06:41:16 2005.36668000) : Got a provider can unload event
(Sat Jul 30 06:41:46 2005.36698000) : Got a TIMEOUT work item
(Sat Jul 30 06:41:46 2005.36698000) : Got a FinalCoreShutdown work item
(Sat Jul 30 06:41:59 2005.36710921) : CForwardFactory::CreateInstance
(Sat Jul 30 06:42:01 2005.36713000) : Got a provider can unload event

16.
Open the Wbemprox.log file with Notepad and scroll to the bottom of the file. Again look for the time stamp. You will see some errors that look like the following:

(Sat Jul 30 06:41:59 2005.36710921) : Using the principal -RPCSS/
Acapulco.NWTraders.MSFT-
(Sat Jul 30 06:41:59 2005.36710921) : ConnectViaDCOM, CoCreateInstanceEx resulted in h
r = 0x0
(Sat Jul 30 06:41:59 2005.36710921) : NTLMLogin resulted in hr = 0x8004100e

17.
Once you find the NTLMLogin resulted in line, note that it says hr = 0x8004100e. This is the result code that is returned from trying to connect to WMI. If we look up the error 0x8004100e using the Err.exe tool, we might be able to find more information. The Err.exe tool does not provide answers to all error codes, but if the error is in the WMI files, the tool should find a match.

18.
Open up a command prompt and change to the directory where you have the Err.exe tool installed. Type the following command:

Err 0x8004100e

19.
Examine the output from the Err tool. The output looks like the following:

C:\Utils>err 0x8004100e
# for hex 0x8004100e / decimal -2147217394 :
 WBEM_E_INVALID_NAMESPACE                   wbemcli.h
# 1 matches found for "0x8004100e"

From the output we can see that part of the problem is related to an invalid namespace.

20.
Open the WbemCore.log file and find the time stamp that is close in time to when you ran BadScript1.vbs. You will find an entry that looks similar to the one listed below:

Sat Jul 30 06:41:59 2005.36710921) : CALL ConnectionLogin::NTLMLogin
  wszNetworkResource = \\.\root\cimv1
  pPreferredLocale = (null)
  lFlags = 0x0
(Sat Jul 30 06:41:59 2005.36710921) : DCOM connection from NWtraders\LondonAdmin at au
thentiction level Privacy, AuthnSvc = 10, AuthzSvc = 0, Capabilities = 0
(Sat Jul 30 06:42:01 2005.36713000) : + DllCanUnloadNow()
(Sat Jul 30 06:42:01 2005.36713000) : - DllCanUnloadNow() S_FALSE
(Sat Jul 30 06:42:01 2005.36713000) : + DllCanUnloadNow()
(Sat Jul 30 06:42:01 2005.36713000) : - DllCanUnloadNow() S_FALSE

From examining the output, can you determine the problem with the script? Can you see the reason for the failed login reported in the Wbemprox.log file? Do you see why the error that was reported was invalid namespace? The namespace is specified as root\cimv1. WMI is unable to authenticate a user against a WMI namespace that does not exist.

21.
Run the BadScript2.vbs script. Retain the time stamp from the script.

22.
Open the WinMgmt.log file and locate the time that is closest to the time stamp retrieved from running BadScript2.vbs. The error messages should be near the bottom of the script. Compare the results from BadScript1.vbs in the WinMgmt.log file with the results from BadScript2.vbs. What is the difference between the two results? The BadScript2.vbs script should not record any errors in the WinMgmt.log file. The entry from BadScript2.vbs should look like the following:

(Sat Jul 30 07:39:35 2005.40167562) : CForwardFactory::CreateInstance

23.
Open Wbemprox.log and locate the entries closest in time to the time stamp retrieved from BadScript2.vbs. The entries should be near the bottom of the file.

24.
Do you find any errors listed in the Wbemprox.log file? No.

25.
Compare the results in Wbemprox.log from BadScript2.vbs to the results generated by BadScript1.vbs. Are there any differences? Yes. The following line was generated by BadScript1.vbs, but not generated by BadScript2.vbs:

(Sat Jul 30 06:41:59 2005.36710921) : NTLMLogin resulted in hr = 0x8004100e

26.
What does the absence of an error here mean? It indicates that the NTLMLogin operation succeeded. The connection to root\cimv2 was successful.

27.
Open the WbemCore.log file and find the time stamp from the BadScript2.vbs run. It should be near the bottom. Compare the results from running BadScript2.vbs to the results from running BadScript1.vbs in the log file. Notice there are far more entries in the log file. You should find entries that look similar to the following:

(Sat Jul 30 07:39:35 2005.40167562) : CALL ConnectionLogin::NTLMLogin
  wszNetworkResource = \\.\root\cimv2
  pPreferredLocale = (null)
  lFlags = 0x0
(Sat Jul 30 07:39:35 2005.40167562) : DCOM connection from NWTRADERS\LondonAdmin at au
thentiction level Privacy, AuthnSvc = 10, AuthzSvc = 0, Capabilities = 0
(Sat Jul 30 07:39:35 2005.40167562) : CALL CWbemNamespace::ExecQuery
  BSTR QueryFormat = WQL
  BSTR Query = Select * from win32_Processer
  IEnumWbemClassObject **pEnum = 0x28FD0C8
(Sat Jul 30 07:39:35 2005.40167562) : CALL CWbemNamespace::ExecQueryAsync
  BSTR QueryFormat = WQL
  BSTR Query = Select * from win32_Processer
  IWbemObjectSink* pHandler = 0x0
(Sat Jul 30 07:39:35 2005.40167562) : STARTING a main queue thread 548 for a total of
1
(Sat Jul 30 07:39:35 2005.40167578) : CALL CWbemNamespace::ExecQuery
  BSTR QueryFormat = Wql
  BSTR Query = Select * from __ClassProviderRegistration
  IEnumWbemClassObject **pEnum = 0xF7F9C0
(Sat Jul 30 07:39:35 2005.40167578) : CALL CWbemNamespace::ExecQueryAsync
  BSTR QueryFormat = Wql
  BSTR Query = Select * from __ClassProviderRegistration
  IWbemObjectSink* pHandler = 0x0
(Sat Jul 30 07:39:35 2005.40167578) : STARTING a main queue thread 2032 for a total of
 2
(Sat Jul 30 07:39:47 2005.40179578) : STOPPING a main queue thread 548 for a total of
1
(Sat Jul 30 07:39:47 2005.40179578) : STOPPING a main queue thread 2032 for a total of
 0

In examining the log file, were we able to parse a WQL query? Yes. This is indicated by the following line in the log file:

(Sat Jul 30 07:39:35 2005.40167562) : CALL CWbemNamespace::ExecQuery
  BSTR QueryFormat = WQL
  BSTR Query = Select * from win32_Processer
  IEnumWbemClassObject **pEnum = 0x28FD0C8

28.
Did BadScript1.vbs succeed in parsing a WQL query? No. There is no entry similar to the one above listed in WbemCore.log around the time the BadScript1.vbs script ran.

29.
After the query is parsed, it now tries to find the class that is referenced in the query. Locate the entries that try to identify the class provider. The entries will look like the following:

(Sat Jul 30 07:39:35 2005.40167578) : CALL CWbemNamespace::ExecQuery
  BSTR QueryFormat = Wql
  BSTR Query = Select * from __ClassProviderRegistration
  IEnumWbemClassObject **pEnum = 0xF7F9C0

30.
Examine the WbemCore.log file. Did the query for the class provider succeed? No. There is no indication in the log file that the query succeeded. The next entry in the log indicates the main thread queue stops, this is a normal log file entry, and it indicates WMI has finished processing the request. This is seen below:

(Sat Jul 30 07:39:47 2005.40179578) : STOPPING a main queue thread 548 for a total of
1

31.
To compare our results from bad scripts with the results of a good script, run the GoodScript1.vbs script. Pay attention to the script complete time stamp.

32.
Open Winmgmt.log and find the time stamp from running GoodScript1.vbs. Compare your results from running GoodScript1.vbs with the results from running BadScript2.vbs. They are similar.

33.
Open Wbemprox.log and find the time stamp from running GoodScript1.vbs. Compare the results from running BadScript2.vbs. They are similar. This indicates that both BadScript2.vbs and GoodScript1.vbs were able to make a connection into WMI and have the query parsed.

34.
Open WbemCore.log and compare the results from running BadScript2.vbs and the results from running GoodScript1.vbs. What do you notice? There are far more entries from GoodScript1.vbs. Why is this the case? The good script ran to completion. You may notice some errors in the log files, but these are not necessarily related to GoodScript1.vbs. WMI is used for many activities and there could be other processes logging at the same time. If you are having trouble locating the logging from your script, you can look at \My Documents\Microsoft Press\VBScriptSBS\ch21\StepByStep\GoodScript1Events.txt.

35.
Can you identify the name of the provider that supplies WIN32_Processor? Yes. It is CIMWin32.


Previous Page
Next Page