WASD VMS Web Services - Features and Facilities

10 - WATCH Facility

10.1 - Server Instances 10.2 - Event Categories 10.3 - Request Filtering 10.4 - Report Format 10.5 - Usage Suggestions 10.6 - Command-Line Use
next previous contents full-page

The WATCH facility is a powerful adjunct in server administration. From the Server Administration facility (9 - Server Administration) it provides an online, real-time, in-browser-window view of request processing in the running server. The ability to observe live request processing on an ad hoc basis, without changing server configuration or shutting-down/restarting the server process, makes this facility a great configuration and problem resolution tool. It allows (amongst other uses)

assessment of mapping rules
assessment of authorization rules
investigation of request processing problems
observation of script interaction
general observation of server behaviour

A single client per server process can access the WATCH facility at any one time. It can be used in one of two modes.

Options immediately below the duration selector allows the WATCH output to concurrently be included in the server process log. This allows a permanent record (at least as permanent as server logs) to be simply produced.

10.1 - Server Instances

With a single instance (see 8.1 - Server Instances) access to WATCH is always through the one server process. If multiple instances are configured WATCH requests, in common with all others, will be serviced by any one of the associated processes depending on the momentary state of the round-robin distribution.

This is often an issue for request WATCHing. The simplest scenario involves two instances. When the WATCH report is activated it will be serviced by the first process, when the request wishing to be WATCHed is accessed it (in the absence of any other server activity) will be serviced by the other process and will not be reported by WATCH on the first.

The solution is to suspend the round-robin request processing for the period of the WATCH activity. This does not shut any instance down but instead makes all but the supervisor instance quiescent. (Technically, it dequeues all the listening I/Os from non-supervisor instance server sockets, making the TCP/IP network driver send all connection requests to the one instance left with listening I/Os.) It is just a matter of making the non-supervisor instances active again when the WATCH activity is concluded.

This may be done from the command-line using

$ HTTPD /DO=INSTANCE=PASSIVE
$ HTTPD /DO=INSTANCE=ACTIVE
or using the Server Administration facility (9 - Server Administration) where there are [Active] and [Passive] buttons available when multiple instances are in use. Neither transition disrupts any requests being established or in-progress.

10.2 - Event Categories

An event is considered any significant point for which the server code has a reporting call provided. These have been selected to provide maximum information with minimum clutter and impact on server performance. Obvious examples are connection acceptance and closure, request path resolution, error report generation, network reads and writes, etc. Events are collected together into groupings to allow clearly defined areas of interest to be selected for reporting.

[graphic]  WATCH Selection Graphic

The report menu provides for the inclusion of any combination of the following categories.

Request

Response

General

Network

Other

Proxy

Code Modules

If the server has been compiled using the WATCH_MOD=1 macro a set of module WATCHing statements is included. These provide far more detailed processing information than available with the generic WATCH, are intended primarily for debugging the server during development and testing. This is considered a specialized tool, with the quantity and level of detail produced most likely proving counter-productive in addressing general site configuration issues. The module items are shown below the usual WATCH items.

10.3 - Request Filtering

By default all requests to all services are WATCHed. Fine control may be exercised over exactly which requests are reported, allowing only a selected portion of all requests being processed to be concentrated on, even on a live and busy server. This is done by filtering requests according the following criteria.

In addition there are in and out selectors against each of the filters which include or exclude the particular request based on it matching the filter.

These filters are controlled using fully-specified, wildcarded strings or using regular expression patterns (see WASD Web Services - Install and Config document, "Request Processing Configuration" section). In common with all WASD processing, filter matching is case-insensitive. Of course, due to the point of application of a particular filter during request processing, some information may or may not be displayed. When a request is into or out of the report because of a matching filter a FILTER informational item is reported.

Examples

  1. This first example shows various strings and patterns that could be applied to the client filter.
    alpha.example.com
    *.example.com  
    131.185.250.202
    131.185.250.*
    ^10.68.250.*|10.68.251.*
    
  2. This example various filters applied to the service (virtual server).
    beta.example.com:8000
    beta.example.com:*
    http://*
    https:*
    *:80
    
  3. The request filter contains the entire HTTP request header. This includes multiple, newline-delimited fields. Filtering can be simple or quite complex. These examples filter all POST requests (either in or out of the report depending on the respective selector), and all POSTs to the specified script respectively.
    POST *
    POST /cgi-bin/example*
    

    These are the equivalent regular expressions but also will stop comparing at the end of the initial request line. The second, in this case, will also only filter against HTTP/1.1 version requests (note the final period matching the <CR> of the <CR><LF> carriage control).

    ^^POST .*$
    ^^POST */cgi-bin/example *HTTP/1\.1.$
    

    This example uses a regular expression to constrain the match to a single header field (line, or newline-delimited string), matching all requests where the user agent reports using the "Gecko" browser component (Mozilla, Firefox, etc.)

    ^^User-agent:.*Gecko.*$
    

  4. The path and track filter. The path contains a proxied origin server request and so can be used to filter proxy requests to specific sites.
    /wasd_root/src/*
    /cgi-bin/*
    /web/*/cyrillic/*
    $ORoKJAOef8sAAAkuACc
    http://proxied.host.name/*
    
  5. The authentication filters, realm and user, can be used to select requests for a particular authenticated user, all authenticated requests or all non-authenticated requests, amongst other application. The realm field allows the authenticated user to be further narrowed as necessary. All of the following examples show only the user field with the default in selector set.

    Authenticated requests for user DANIEL.

    DANIEL
    

    All authenticated requests.

    %*
    

10.4 - Report Format

The following example illustrates the format of the WATCH report. It begins with multi-line heading. The first two record the date, time and official server name, with underline. The third provides the WASD server version. The fourth provides some TCP/IP agent information. Lines following can show OpenSSL version (if deployed), system information, server startup command-line, and then current server process quotas. The last three lines of the header provide a list of the categories being recorded, the filters in use, and the last, column headings described as follows:

time the event was recorded
the module name of the originating source code
the line in the code module
a unique item number for each thread being WATCHed
event category name
free-form, but generally interpretable event data

[graphic]  WATCH Report Graphic

Note that some items also include a block of data. The request header category does this, providing the blank-line terminated text comprising the HTTP header. Rule mapping also provides a block of information representing each rule as it is interpreted. Generally WATCH-generated information can be distinguished from other data by the uniform format and delimiting vertical bars. Initiative and imagination is sometimes required to interpret the free-form data but a basic understanding of HTTP serving and a little consideration is generally all that is required to deduce the essentials of any report.

HTTPd-WASD/11.0.0 OpenVMS/AXP SSL (24-FEB-2016 12:02:29.57)
HP TCPIP$IPC_SHR V5.7-ECO1 (21-MAY-2010 14:44:46.64)
OpenSSL 1.0.2f  28 Jan 2016 (30-JAN-2016 09:50:05.33) [WASD_ROOT.SRC.OPENSSL-1_0_2F.INCLUDE.OPENSSL]*.H WASD [ALPHA.EXE.SSL]SSL_LIBSSL32.OLB
$ CC (V8.3/70390009) /DECC /STAND=RELAXED_ANSI /PREFIX=ALL /OPTIMIZE /NODEBUG /WARNING=(NOINFORM,DISABLE=(PREOPTW)) /FLOAT=IEEE /IEEE=DENORM /DEFINE=(WASD_VMS_V7,SESOLA,WATCH_CAT=1,WATCH_MOD=0,WASD_ACME=1)
Digital Personal WorkStation  with 1 CPU and 1536MB running VMS V8.3 (ODS-5 enabled, VMS NAML, VMS FIB, ZLIB disabled, REGEX enabled, lksb$b_valblk[64])
$ HTTPD /PRIORITY=4 /SYSUAF=(ID,SSL)/PERSONA=RELAXED/PROFILE
AST:1983/2000 BIO:1986/2000 BYT:49966656/49999424 DIO:5000/5000 ENQ:453/500 FIL:294/300 PGFL:451216/500000 PRC:0/100 TQ:97/100
DCL Scripting: detached, as HTTP$NOBODY, PERSONA enabled
Process: WASD:80 OTHER $1$DKA0:[wasd_root.][STARTUP]STARTUP_SERVER.COM;44
$1$DKA0:[wasd_root.][LOG_SERVER]KLAATU_20160224171154.LOG;1
Instances: KLAATU::WASD:80
Watching: connect, request, req-header, response, res-header, error (603) via HTTP/2
Filter: NONE
|Time_______|Module__|Line|Item|Category__|Event...|
|01:57:59.30 WATCH    1713 0001 CONNECT    HTTP/2 with 192.168.1.2,58855 on https://wasd.*****.***,443 (0.0.0.0)|
|++++++++++++++++++++++++++++++++++++++++++
|01:57:59.30 HTTP2REQ 0235 0001 REQ-HEADER HEADER 463 bytes|
GET /httpd/-/admin/ HTTP/1.1
cache-control: max-age=0
authorization: Basic ************************
accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
upgrade-insecure-requests: 1
user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/48.0.2564.116 Safari/537.36
dnt: 1
accept-encoding: gzip, deflate, sdch
accept-language: en-US,en;q=0.8
host: wasd.*****.***:443

|01:57:59.32 REQUEST  2980 0001 REQ-HEADER DATA|
ENTRY 001 [012] $ {12}request_line={28}GET /httpd/-/admin/ HTTP/1.1
ENTRY 002 [024] > {13}cache-control={9}max-age=0
ENTRY 003 [031] > {13}authorization={30}Basic ************************
ENTRY 004 [014] > {6}accept={74}text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
ENTRY 005 [010] > {25}upgrade-insecure-requests={1}1
ENTRY 006 [001] > {10}user-agent={121}Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/48.0.2564.116 Safari/537.36
ENTRY 007 [004] > {3}dnt={1}1
ENTRY 008 [018] > {15}accept-encoding={19}gzip, deflate, sdch
ENTRY 009 [007] > {15}accept-language={14}en-US,en;q=0.8
ENTRY 010 .024. > {4}host={22}wasd.*****.***:443
|01:57:59.35 SERVICE  1721 0001 CONNECT    VIRTUAL wasd.*****.***:443|
|01:57:59.35 REQUEST  3640 0001 REQUEST    GET /httpd/-/admin/|
|01:57:59.38 ADMIN    0250 0001 RESPONSE   ADMIN /httpd/-/admin/|
|01:57:59.39 NET      2308 0001 RES-HEADER DATA|
ENTRY 001 .018. $ {15}response_status={3}200
ENTRY 002 [028] < {12}x-user-agent={121}Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/48.0.2564.116 Safari/537.36
ENTRY 003 .011. < {6}server={34}HTTPd-WASD/11.0.0 OpenVMS/AXP SSL
ENTRY 004 [002] < {4}date={29}Wed, 24 Feb 2016 15:27:59 GMT
ENTRY 005 .005. < {13}accept-ranges={5}bytes
ENTRY 006 [008] < {15}accept-encoding={13}gzip, deflate
ENTRY 007 [020] < {25}strict-transport-security={16}max-age=16416000
ENTRY 008 .004. < {7}expires={29}Fri, 13 Jan 1978 14:00:00 GMT
ENTRY 009 [030] < {13}cache-control={18}no-cache, no-store
ENTRY 010 .028. < {6}pragma={8}no-cache
ENTRY 011 .030. < {12}content-type={29}text/html; charset=ISO-8859-1
ENTRY 012 [006] < {14}content-length={5}15719
|01:57:59.40 HTTP2REQ 0713 0001 RES-HEADER HEADER 497 bytes|
HTTP/1.1 200 OK
x-user-agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_3) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/48.0.2564.116 Safari/537.36
server: HTTPd-WASD/11.0.0 OpenVMS/AXP SSL
date: Wed, 24 Feb 2016 15:27:59 GMT
accept-ranges: bytes
accept-encoding: gzip, deflate
strict-transport-security: max-age=16416000
expires: Fri, 13 Jan 1978 14:00:00 GMT
cache-control: no-cache, no-store
pragma: no-cache
content-type: text/html; charset=ISO-8859-1
content-length: 15719

|01:57:59.41 REQUEST  1143 0001 REQUEST    STATUS 200 (OK) rx:29 tx:15809 bytes 0.109368 seconds 144,813 B/s|
|------------------------------------------
|01:58:50.58 end|

10.5 - Usage Suggestions

The following provides a brief explanation on the way WATCH operates and any usage implications.

A single client may be connected to the WATCH facility at any given time. When connecting the client is sent an HTTP response header and the WATCH report heading lines. The request then remains connected until the WATCH duration expires or the client overtly aborts the connection. During this period the browser behaves as if receiving a sometimes very slow, sometimes stalled, plain-text document. As the server processes WATCHable events the text generated is sent to the WATCH-connected client.

If the connection is aborted by the user some browsers will consider document retrieval to be incomplete and attempt to reconnect to the service if an attempt is made to print or save the resulting document. As the printing of WATCH information is often quite valuable during problem resolution this behaviour can result in loss of information and generally be quite annoying. Appropriate use of the duration selector when requesting a report can work around this, as at expiry the server disconnects, browsers generally interpreting this as legitimate end-of-document (when no content-length has been specified).

During report processing some browsers may not immediately update the on-screen information to reflect received data without some application activity. If scroll-bars are present on the document window manipulating either the horizonal or vertical slider will often accomplish this. Failing that minimizing then restoring the application will usually result in the most recent information being visible.

Browser reload/refresh may be used to restart the report. A browser will quite commonly attempt to remain at the current position in the document, which with a WATCH report's sustained but largely indeterminate data stream may take some time to reach. It is suggested the user ensure that any vertical scroll-bar is at the beginning of the current report, then refresh the report.

Selecting a large number of categories, those that generate copious output for a single event (e.g. response body) or collecting for extended periods can all result in the receipt of massive reports. Some browsers do not cope well with documents megabytes in size.

NOTE

WATCH reports are written using blocking I/O (with HTTP/1.n, HTTP/2 is completely asynchronous). This means when large bursts of data are being generated (e.g. when WATCHing network data, response bodies, etc.) significant granularity may be introduced to server processing. Also if the WATCH client fails or blocks completely server processing could halt completely! (This has been seen when WATCHing through a firewall.)

When supplying WATCH output as part of a problem report please ZIP the file and include it an an e-mail attachment. Mailers often mangle the report format making it difficult to interpret.

10.6 - Command-Line Use

Although intended primarily as a tool for online use WATCH can be deployed at server startup with a command-line qualifier and provide report output to the server process log. This is slightly more cumbersome than the Web interface but may still be useful in some circumstances. Full control over event categories and filters is possible.

The following examples illustrate the command-line WATCH specification.

/NOWATCH
/WATCH=NOSTARTUP,ITEMS=(REQUEST,RESPONSE,MAPPING)
/WATCH="ITEMS=(REQUEST,RESPONSE,ERROR),*,*,/cgi-bin/*"
/WATCH=LIST


next previous contents full-page