How do I read the WebMarshal WMProxy log?

This article applies to:

• WebMarshal 6.X and 7.X

Question:

• How do I read the WebMarshal WMProxy log?

Information

This article provides an overview of how to read the WebMarshal WMProxy log file. By default it is found in the Logging folder within the WebMarshal directory (for locations, see Related Articles below). The logs contain detailed information about the ongoing operation of the WMProxy service. Familiarity with these logs is key to achieving a quick and successful understanding of WebMarshal issues.

Each WebMarshal service generates a text log file which is created on at least a daily basis. If the log reaches 32mb a new file is created.

Use Word Wrap wisely in Notepad.
Typically we view WebMarshal logs in Notepad. Sometimes it is important to clearly see the columns in the log - if so turn off Word Wrap. Each service log will have three columns - the columns are Thread Number, Time, and Logged Data. At other times, it is more important to see all the Logged Data on-screen - in this case turn on Word Wrap. Also use Notepad in full screen mode.

Below is a WMProxy log when advanced full logging has been enabled. The log is a single session for a user trying to reach: http://tools.google.com/service/update2. The log is broken up into its significant sections and with an explanation of the function of that section.

WMProxy Log

2008-09-17 01:29:59.277 9600 Checking socket 0 for connection...
2008-09-17 01:29:59.277 9600 Accepting connection...
2008-09-17 01:29:59.277 9600 Checking LAT.
2008-09-17 01:29:59.277 9600 Assigning thread.
2008-09-17 01:29:59.277 9600 Checking socket 1 for connection...
2008-09-17 01:29:59.277 9600 No connection.
2008-09-17 01:29:59.277 9600 Checking socket 2 for connection...
2008-09-17 01:29:59.277 9600 No connection.
2008-09-17 01:29:59.277 9600 Checking socket 3 for connection...
2008-09-17 01:29:59.277 9600 No connection.
2008-09-17 01:29:59.277 9600 Waiting for connection...
2008-09-17 01:29:59.277 7332 35999.45 (11): Getting host name took 0 ms.
2008-09-17 01:29:59.277 7332 35999.45 (11): Connection begins from client01.
2008-09-17 01:29:59.277 7332 Request {F64874AC-A2D4-49EE-9771-26E69936BDAD} is starting

• In the section of the log above WebMarshal is negotiating the connection sequence. The main listening thread: 9600 has detected a connection and is looking at the sockets it is configured to use. The user is checked against the local address table and if they are allowed to connect then a thread is started for the connection, thread 7332.
• The columns displayed in the log are the date and time, the thread ID as assigned by windows,the amount of seconds the WebMarshal Proxy has been running and the amount of requests that have passed through WebMarshal (In this case 11).   

2008-09-17 01:29:59.293 7332 35999.46 (11): Read request completed. Duration: 0 ms.
2008-09-17 01:29:59.293 7332 35999.46 (11): Authenticating using SSPI (Negotiate).
2008-09-17 01:29:59.293 7332 35999.46 (11): Request received with incomplete authentication (Negotiate), Sending challenge. (A href="http://tools.google.com/service/update2?w=ctlnA1qdKWlJBBju5PebJQ5g">http://tools.google.com/service/update2?w=ctlnA1qdKWlJBBju5PebJQ5g)
2008-09-17 01:29:59.293 7332 35999.46 (11): Request took 0 ms
2008-09-17 01:29:59.293 7332 Request {476D9FCD-2E5E-4E87-B1C3-06D5ED117B5C} is starting
2008-09-17 01:29:59.293 7332 35999.46 (11): Read request completed. Duration: 0 ms.
2008-09-17 01:29:59.293 7332 35999.46 (11): Authenticating using SSPI (Negotiate).
2008-09-17 01:29:59.293 7332 35999.46 (11): Successfully authenticated with Negotiate.
2008-09-17 01:29:59.293 7332 35999.46 (11): User fetched using GetFullUserName.
2008-09-17 01:29:59.293 7332 35999.46 (11): Request(1)(MYDOMAIN\User01) POST http://tools.google.com/service/update2?w=ctlnA1qdKWlJBBju5PebJQ5g HTTP/1.1
2008-09-17 01:29:59.293 7332 35999.46 (11): Authentication completed. Duration: 0 ms.

• Above is the authentication sequence. SSPI indicates the user is using NTLM authentication.
• A request is made to the server that is hosting the web page the user has requested.

2008-09-17 01:29:59.293 7332 35999.46 (11): Request Headers:

If-Match: "_1iQSUqFjV-QQW9X0W45VnLlqPs"
Cookie: c=ANcH4TKTWzOry93aS2lQRVusDtUfIMx1gUYxxRgtAeBcFdbn9
User-Agent: Google Update/1.2.131.11;winhttp;cup
Host: tools.google.com
Cache-Control: no-cache
Pragma: no-cache
Content-Length: 786
Connection: keep-alive
Via: 1.1 CLIENT01

• Above shows the header of the webpage that has been requested.
• An un-cached web page is requested and the connection to the website is not to be closed after its transfer. The length of the headers sent in the request is shown, in this case 786 bytes.
  

2008-09-17 01:29:59.620 7332 35999.79 (11): Mapping Address tools.google.com to 209.85.171.100
2008-09-17 01:29:59.620 7332 35999.79 (11): Attempting connect to 209.85.171.100:80
2008-09-17 01:29:59.620 7332 35999.79 (11): Connected.
2008-09-17 01:29:59.620 7332 35999.79 (11): Connection to server established. Duration: 298 ms.
2008-09-17 01:29:59.620 7332 35999.79 (11): Request headers written to server socket. Duration: 0 ms.
2008-09-17 01:29:59.620 7332 35999.79 (11): Read 786 of 786 bytes
2008-09-17 01:30:10.197 7332 36010.37 (11): # Forwarding 786 bytes of post data to the remote server.
2008-09-17 01:30:10.197 7332 36010.37 (11): Received 786 bytes of POST data.
2008-09-17 01:30:10.197 7332 36010.37 (11): Request data written to server socket. Duration: 10576 ms.
2008-09-17 01:30:10.384 7332 36010.55 (11): Faking keep-alive
2008-09-17 01:30:10.384 7332 36010.55 (11): Response headers received. Duration: 181 ms.

• The part of the log above shows WebMarshal resolving the IP of the website and connecting to it.
• Faking keep alive means the web server has closed the connection between itself and WebMarshal but the connection between WebMarshal and the user is kept active.

2008-09-17 01:30:10.384 7332 36010.55 (11): Response Headers:

HTTP/1.1 200 OK

Date: Tue, 16 Sep 2008 13:30:10 GMT

Content-Type: text/html; charset=UTF-8

Server: GFE/1.3

Content-Length: 4132

Connection: keep-alive

Proxy-Connection: keep-alive

Via: 1.1 CLIENT01

• Above is the response header which is sent to the user from the web server.
• It shows the type of content being sent back, in this case HTML and text.
• The connections between the user and WebMarshal and the web server are kept open.
  

2008-09-17 01:30:10.384 7332 36010.55 (11): @2 Content-Length: 4132
2008-09-17 01:30:10.384 7332 36010.55 (11):# Trickle rate set to 10%
2008-09-17 01:30:10.384 7332 36010.55 (11): Response header send to client. Duration: 0 ms.
2008-09-17 01:30:10.384 7332 36010.55 (11): Sending data to client.
2008-09-17 01:30:10.384 7332 36010.55 (11): # Temp file: C:\Program Files\Marshal\WebMarshal\Temp\Proxy\WM_2896_update2
2008-09-17 01:30:10.384 7332 36010.55 (11): # Complete file has been received.
2008-09-17 01:30:10.384 7332 36010.55 (11): Request completed, 4132 bytes. Keep-alive is enabled.
2008-09-17 01:30:10.384 7332 36010.55 (11): #### Fire_OnEndRequest ####
2008-09-17 01:30:10.384 7332 36010.55 (11): # OnEndRequest
2008-09-17 01:30:12.334 7332 36012.50 (11): # Complete
2008-09-17 01:30:12.334 7332 36012.50 (11): # Forwarding remainder to client: 0 - 4132 of 4132 bytes.
2008-09-17 01:30:12.334 7332 36012.50 (11): Response data sent to client. Send: succeeded. End: succeeded. Connection: keep-alive.
2008-09-17 01:30:12.334 7332 36012.50 (11): Disconnected from server.
2008-09-17 01:30:12.334 7332 36012.50 (11): Request took 13055 ms

• The section of the log above shows the trickle rate configured in Download Options on the WebMarshal Server and Array Properties window.
• Fire_OnEndRequest ### means the entire file requested by the user has been downloaded to WebMarshal and passed through any Standard or Content analysis rules. If the
• file is allowed it will be sent to the user.
• The response from the web server is sent to the user. WebMarshal and the Web Server are no longer connected and the log shows how many milliseconds the request.

For information on how to read the WMProxy log see the article below:

• Q12186 : How do I read the WebMarshal WMNodeEngine log?