HELP: Eval web server access log, 2007-12-10
Instructions
This tool helps to analyse LogWeb/Ajax transactions found in
web server access log files
as generated by the servlet container (such as Tomcat)
or by a http demon or proxy (such as Apache).
The tool can be very useful - not because of the complexity of such a log file
(in fact, the log lines are very well structured and each line is easy to decode),
but because of the sheer size of the log files
(it is quite common to have a log file of some million lines per day).
In most practical cases it is simply not possible
to read the whole access log file into an editor program
and then "click here and there and look what happened".
The intended usage of the tool is interactive:
- First get an overview of the whole file (file summary, LogWeb/Ajax sessions, Client IP list, HTTP errors, server load).
- Then select and check the details of the "problematic" session(s),
- and/or select and check the details of the "problematic" time intervals,
- and/or select and check the details of the "problematic" lines containing some specific string patterns.
The first step is always choosing the access log file in question:
- Choose open access log file to select a log file,
or right-click in the file summary view.
- Select the access log file from the file dialog.
- The file will be read.
Log files may be quite long (some million lines),
so there is a progress indicator line.
You may interrupt processing by choosing stop at any time.
The result of the first step is presented in five different views:
- File Summary
Shows file specific items like number of lines
- Sessions Summary
Each LogWeb/Ajax session is presented in 1 line.
- Client IP list
Each client IP address is presented in 1 line.
- HTTP Errors
Lists all HTTP errors, such as "file not found".
- Server Load
In intervals of 1 minute,
shows server hits/sec and number of concurrent sessions.
Each of these sections may be hidden by clicking the respective checkbox.
In many cases it is helpful to view the transactions of one (or more) session(s) in detail:
- To get details of a specific LogWeb/Ajax session,
right click the session ID in the sessions summary.
Alternatively, check the session id(s) in the session summary,
and then choose extract session(s).
- The log file will be read again,
resulting in an additional details view.
You may interrupt processing by choosing stop at any time.
- Session Details shows all log lines produced by the specified session(s).
In other cases it is helpful to view all consecutive log lines of a specific time period:
- To get details of a time period,
right-click in the details view,
and then select the time interval from the popup input box.
You may interrupt processing by choosing stop at any time.
- The log file will be read again,
resulting in an additional details view.
- Lines Details shows all log lines produced in the specified time interval.
- Alternatively, you may filter the lines according to any string (regular expression).
For your analysis, you may produce several details views.
You can hide each of these views by clicking the respective check box,
or you can remove a details view altogether, if you do not need it any more.
The left frame of the window serves as a quick access toolbar to the various views.
The following sections explain the information of the different views
and give some guidelines for interpreting the data:
Web Server Access Log
The web server access log shows one HTTP transaction per line.
The line format is standardized and looks like
100.0.1.14 - - [14/Jun/2007:06:24:56 +0200] "GET /logwebVT/include/style.css HTTP/1.1" 200 2542
100.0.1.14 - - [14/Jun/2007:06:24:56 +0200] "GET /logwebVT/include/dialog.css HTTP/1.1" 200 1251
100.0.1.14 - - [14/Jun/2007:06:24:56 +0200] "GET /logwebVT/classes/ajaxversion.js HTTP/1.1" 200 29
100.0.1.10 - - [14/Jun/2007:06:24:56 +0200] "GET /logwebVT/include/style.css HTTP/1.1" 304 -
Each line consists of the fields
- Originating IP address (first line here: 100.0.1.14)
Depending on your server,
the IP address may be denoted in "dotted decimal notation",
or as a symbolic name such as www.logics.de.
Please note: Depending on your system environment,
the address shown is not necessarily the client IP address,
but may be the IP address of some proxy server.
- Server time stamp (first line here: [14/Jun/2007:06:24:56 +0200]
Please note: Depending on your configuration,
this may be the time
- when a proxy relay server received the client request
- or when the server received the client request
- or when the server committed the response to the client
Since servers usually produce log lines when they commit the response to the client,
it is quite common to find log lines with a lower time stamp
after log lines with a higher time stamp.
- HTTP command line enclosed in " (first line here: GET /logwebVT/include/style.css HTTP/1.1)
- HTTP return code (first line here: 200)
Most common return codes:
- 200: "OK; requested URL was served"
- 304: "OK; requested URL vas not served because it was not modified"
Most other return codes are error codes such as
- 404: "Error: URL not found"
- Number of bytes returned to the client (first line here: 2542 bytes)
For running LogWeb/Ajax sessions,
the URL shown in the log file may contain additional useful info
in the leading "URL path info", or in the "URL parameters":
100.0.1.10 - - [14/Jun/2007:06:29:28 +0200] "GET /logwebVT/LogWeb/1181795374484/94?_Action=Peek&_ScreenID=3/1&_SessionID=9878bc3b113287e3e87 HTTP/1.1" 200 554
- path info (here: /1181795374484/94)
shows client request time in internal format (here: 1181795374484),
and request-response delay of previous request in milli seconds (here: 94)
- Parameter _SessionID (here: 9878bc3b113287e3e87)
The unique Session ID for this LogWeb/Ajax session
Note: Depending on the client, this info is not always available.
The raw access log lines are shown as text in the
Details view only if they cannot be decoded as LogWeb/Ajax session input.
For more details on web server log-files, see
http://de.selfhtml.org/projekt/kontrollieren.htm#logdateien
File Summary
Shows the file summary:
- file name
- number of lines read from file
- number of lines skipped (no LogWeb/Ajax session request)
- number of LogWeb Ajax sessions in file
- first and last server time stamp encountered in file
- processing time
Note: a right-click in the file summary re-opens the file selection dialog
(just like choosing open access log file).
LogWeb/Ajax Sessions
The sessions overview shows one line per LogWeb/Ajax session:
- #ID
Counts the sessions.
Note: the sessions are sorted descending by max server request interval,
so the "worst" sessions appear first.
- session ID
The unique LogWeb/Ajax session ID.
Session IDs may be checked and thus selected for extraction of session details.
- ip
The originating IP address for this session as seen by the server.
This may be
- a client ip address (such as a Windows PC)
running one or more sessions concurrently
- a Windows Terminal Server or a Unix system
running one or more sessions concurrently for one or more concurrent users
- a http proxy ip address
connecting one or more PCs, terminal servers.. concurrently
As a result there may be far more than just one concurrent LogWeb/Ajax per IP address.
- User
The LogWeb login name for this session, if any.
- RemoteAddr
The originating remote address as detected by the LogWeb runtime.
The LogWeb runtime tries to resolve a proxy chain back to the originating client IP address;
so, this IP address is a "better guess" for the client IP than the server supplied IP address above.
- Admin
true if the administrator hooked up to this session.
- Stop
Lists (max one) special LogWeb session event, such as
- _Request: the client detected (at least) one missing cient request situation,
usually cause by a connection loss.
- _Response: the client detected (at least) one missing server response
- Stop: the session was terminated regularily by the user
- transactions first, transactions last
The server time stamp of the first and last occurence of this session
- transactions total
The number of LogWeb/Ajax transactions for this session.
Note: this does not include "simple" http requests such as loading a GIF.
- server request interval
All LogWeb/Ajax sessions contact the server regularily
in intervals of 15..20 seconds.
Due to delays/congestions/problems on the client, the network, the server or the host system,
this interval may be longer than expected.
Here, the maximum interval encountered is shown,
and the sessions are sorted in descending order of their max interval.
- max sec
Shows the maximum time between two successive server transactions (in seconds).
Note: values greater than ..20.. seconds indicate a problem.
- at time
Shows the server time stamp of the maximum request interval
- hits/sec
Shows the server load (hits per second) at that time
- sessions
Shows the server load (concurrently running LogWeb/Ajax sessions) at that time
- client response delay
Shows the maximum request-response delay (milli seconds) as reported by the client;
should be well below 1000 millis.
- max millis
Shows the maximum delay (in milli seconds).
Note: values greater than ..1000.. millis indicate a problem.
Note: a value of -1 indicates that the client does not support this feature.
- at time
Shows the server time stamp of the maximum delay
Note: a double-click in the column header of the table
sorts that column in ascending or descending order.
Note: a right-click in the Sessions view opens the details filter input prompt:
- Session filter:
Extracts all lines containing the specified session ID
Similar to checking the session ID and then choosing extract
- Time interval filter:
Extracts all lines of the specified time interval.
Time interval format is hh:mm:ss-hh:mm:ss
- String filter:
Extracts all lines containing the specified string.
The specified string is interpreted as a regular expression.
Sessions: Example
The following shows an example Sessions view;
note: the columns
User,
RemoteAddr,
Admin and
Stop
are omitted here:
- The first session (count=1) shows a problem session.
- The session originated from ip=100.0.1.12;
it was running from 06:40:24 thru 10:35:39
with a total of 1377 transactions.
- The server request interval is very bad (max=35 sec) at 10:23:05.
At that time, the server was not busy
(19 hits/sec for a total of 52 concurrent LogWeb/Ajax sessions).
- The client response delay is very bad as well (max ..18.. sec) at the same time.
- This does not really look like a server problem.
- The next five sessions (count=2 thru count=6) show the same symptoms,
and all originate from the same ip address
- According to the system administrator,
the originating ip address resolves to a Windows Terminal Server system.
For a closer look, see
Session Details: Unexpected Delay
and Lines Details: All lines enclosing the Unexpected Delay .
- The last session in this example (count=8) looks normal.
The max client response is 516 millis, which looks quite large.
This, however, is normal for Unix hosts:
There are cases when the Unix application does not respond to user input at all,
for example when a user enters a login password;
these situations result in a time-out "delay" of ..500.. millis.
Client IP
The client IP list shows one line per client IP:
- ip
The remote IP address for this session.
This may be
- a client ip address (such as a Windows PC)
running one or more sessions concurrently
- a Windows Terminal Server or a Unix system
running one or more sessions concurrently for one or more concurrent users
- a http proxy ip address
connecting one or more PCs, terminal servers.. concurrently
So: there may be far more than just one concurrent LogWeb/Ajax per ip address!
- transactions first, transactions last
The server time stamp of the first and last occurence of a session entry for this IP address.
- transactions total
The number of LogWeb/Ajax transactions for this IP address.
Note: this does not include "simple" http requests such as loading a GIF.
- Log/Web Ajax sessions
The number of Log/Web Ajax sessions
that originated from this IP address.
HTTP Errors
The HTTP Errors view shows 1 line per (specific) http error:
| URL | http rc |
first |
last |
total |
| /logwebVT/ |
302 |
06:33:39 |
08:44:26 |
13 |
| /logwebVT/__login/de/logics/ajax/JSBridgeBeanInfo.class |
404 |
10:20:59 |
10:20:59 |
1 |
- URL
The URL causing HTTP error code,
- http rc
The HTTP error code.
All returncodes except 200 ("response delivered") and 304 ("resource not changed)
are considered errors.
- first, last
The server time stamp of the first and last occurence of this error URL
- count
The number of occurences of this error (same URL and HTTP returncode).
For details on HTTP error codes, see
http://de.selfhtml.org/servercgi/server/httpstatuscodes.htm
Server Load
This view shows the server load for intervals of 1 minute:
= 1 server hit per second
= 10 concurrent sessions
time sess hits
06:24 0 1
06:26 1 1
06:29 1 1
06:30 2 3
06:31 2 3
06:32 3 3
06:33 6 7
06:34 6 2
06:35 6 1
06:36 6 3
06:37 6 2
time
She server time, in minute intervals.
sess
The number of concurrently running sessions at that minute.
hits
The average number of hits/second at that minute.
display
Shows a simple bar graph of sessions and hits/second at that minute
Notes:
- If there is less than 1 hit/sec, the line is omitted.
So there are no entries before 06.24, and for 06:25, 06:27, 06:28..
- There is a certain relation between the number concurrent sessions and the number of server hits per second.
But the correlation is not simple:
- An "inactive" Unix session (user does not enter data) produces 1 hit every ..20.. sec ("Slow Poll")
- An active Unix session (user is entering data) may produce 3..5 hits per second
- After data entry, the client switches to "Fast Poll", and then reverts to Slow Poll again
- So for Unix sessions, there may be factor of 100
comparing the server hits produced by an "active" session to the hits of a "parked" session.
Details View
The details view shows one access log line per line.
Each line is prefixed by some additional information:
---server-- ---------access log---------- --bytes-- ---interval-- --client- ---delay ms-- --------------AJAX--------------
line sess hits time ip verb in out server client ---time-- client server Action SessionID ScreenID Admin PARAMS
12669 4 3 09:21:39 10.222.111.142 POST 1574 3 2 281.175 181 Send #39 115/44 __15001001.0: %3CENTER%3E
12712 4 3 09:21:55 10.222.111.141 GET 166 ==== 10.222.111.141 - - [11/Dec/2007:09:21:55 +0100] "GET /as400/_empty.jsp HTTP/1.1" 200 166
Common fields:
- line (here: 12669)
The line number in the access log file
- server sessions (here: 4)
The average number of concurrently running LogWeb/Ajax server sessions for this line
Some hundred concurrently running LogWeb/Ajax sessions on one "standard" server is quite common
- server hits (here: 3)
The average number of server hits/second for this line
Finding 100 server hits/sec is not exceptional for one "standard" server
- access log time (here: 09:21:39)
The access log time stamp
- access log ip (here: 10.222.111.142)
The access log originating ip address
- access log verb (here: POST)
The http access verb, usually GET or POST
- bytes in (here: empty)
LogWeb/Ajax Unix sessions only: The number of input bytes sent from the client to the server
- bytes out (here: 1574)
The number of bytes sent from the server to the client
The following fields are relevant for LogWeb/Ajax sessions only;
other log lines will be shown here without modifications (as in the second line of this example):
- interval server (here: 3)
The difference in server time stamp to the previous line of the same session, in seconds.
Should be less than ..20.. sec,
since the clients issue a "Slow Poll" to the server at that rate
- interval client (here: 2)
The difference in client time stamp to the previous line of the same session, in seconds.
Missing for first line of session,
or if client did not support this feature.
Should be less than ..20.. sec,
since the clients issue a "Slow Poll" to the server at that rate
- client time (here: 281.175)
The client time since session start, in milli seconds.
- client delay (here: 181)
The client request-response delay for the previous request, in milli seconds.
- server delay (here: empty)
The server request-response delay for this request, in milli seconds.
Requires server option "show delay time".
- AJAX Action (here: Send)
The LogWeb/Ajax _Action verb for this line.
- AJAX SessionID (here: #39)
The LogWeb/Ajax _SessionID.
- AJAX ScreenID (here: 115/44)
The LogWeb/Ajax _ScreenID.
For mainframe sessions, shows the LogWeb session ID (here: 115),
and the LogWeb screen ID (here: 44).
- AJAX Admin (here: empty)
True if the Admin hooked up to this session.
- PARAMS (here: __15001001.0: %3CENTER%3E)
Additional LogWeb/Ajax parameters for this line
(here: the cursor position and the host transmit key for this Send request).
Note: a right-clickin the details view opens the details filter input prompt:
- Session filter:
Extracts all lines containing the specified session ID
Similar to checking the session ID and then choosing extract
- Time interval filter:
Extracts all lines of the specified time interval.
Time interval format is hh:mm:ss-hh:mm:ss
- String filter:
Extracts all lines containing the specified string.
The specified string is interpreted as a regular expression.