soyMAIL 2.1.0 requires JavaScript
soyMAIL @ wasd.vsm.com.au
       info-WASD Mailing List 2024 

Thu 19:11:40 Message "2024 / 0009" opened.  MIME.  utf-8.  1 attachment(s).  2 part(s).  284 kbytes.    JavaScript

Subject:Quick and Dirty LOG STATisticS0009 / 0000
From:mark.daniel@wasd.vsm.com.au
Date:Thu, 25 Jul 2024 20:48:28 +0930  [25-JUL-2024 20:48]
To:info-WASD@vsm.com.au

QDLOGSTATS  is a command-line and web application for collecting data from
~~~~~~~~~~  common and combined ꙳꙳ access log files. ⁑

This article shows the versatility in generating ad hoc reports of interest
to the web administrator.  In particular, for combinations of potentially
revealing request and response characteristics.

It provides from simple statistics to more complex queries using filters.

  |$ qdlogstats == "$wasd_exe:qdlogstats"
  |$ qdlogstats
  |Usage for Quick and Dirty LOG STATisticS
  |
  |$ QDLOGSTATS <log-file-spec> [<filters>] [<other qualifiers>]
  |
  |Utility to extract very elementary statistics from Web server common/combined
  |format log files.  A number of filters allow subsets of the log contents to be
  |selected using simple wildcard expressions.  Strings are NOT case-sensitive.
  |Optionally, log file records can be viewed as processed, or a simple progress
  |indicator can be displayed ("+" for each file, "." per 1000 records thereof).
  |
  |/ALL /AUTHUSER=filter /BEFORE=time /CLIENT=filter /DATETIME=filter
  |/DECODE[=keyword] /DTBEFORE=time /DTSINCE=time /IP=[4|6] /[NO]GEOLOCATE[=string] ††
  |/LOG /LOOKUP[=integer] /METHOD=filter /NOWASD /OUTPUT=file /PATH=filter
  |/PROGRESS[=integer] /PROTOCOL=filter /QUERY=filter /REFERER=filter
  |/RESOLVE /RESPONSE=filter /SINCE=time /SIZE=[MIN=,MAX=] /SOFTWAREID
  |/USERAGENT=filter /VERSION /VIEW[=MATCH(D)|ALL|NOMATCH|LOG|SUSPECT]

Providing a log file specification results in the matching files being processed.

  |$ qdlogstats wasd_logs:*.log
  |QDLOGSTATS IA64-2.1.0 (CGILIB IA64-2.1.2), 07-JUL-2024 10:49
  |
  |Log ........... WASD_LOGS:*.LOG  (16578 matched)
   8< snip 8<
  |Statistics .... time:30:44.66 cpu:261.55 dio:1428868 bio:99480 faults:22 rec/sec:25688
  |Records ....... 47386252  (5221 suspect, 0 common, 47381031 combined)
  |Requests ...... 47381031
  |Methods ....... CONNECT:7398036 (16%)  COPY:0 (0%)  DELETE:31 (0%)  GET:36223063 (76%)
  ↩HEAD:369719 (1%)  LOCK:58 (0%)  MKCOL:19 (0%)  MOVE:1 (0%) OPTIONS:2731 (0%)
  ↩POST:3356240 (7%)  PROPFIND:20549 (0%)  PROPPATCH:169 (0%)  PUT:1488 (0%)
  ↩TRACE:48 (0%)  UNLOCK:17 (0%)  ?:8862 (0%)
  |Responses ..... 1nn:3721 (0%) 2nn:37326304 (79%) 3nn:1057651 (2%) 4nn:8095901 (17%)
  ↩5nn:702672 (1%) ?:194782 (0%)
  |Tx GBytes .... 2581.395

Yes, that's 30¾ minutes — all available access logs, all 16578 files, all 12.21GB.

This site uses WASD tunnels extensively and so a significant proportion of CONNECTs.

WebDAV is NOT supported on the site but hasn't stopped some from attempting
DELETE, LOCK, MKCOL, MOVE, PROPFIND, PROPPATCH and UNLOCK -ing.

Selected access logs ‡‡ can narrow the data collection and reduce search expense.
This file specification selects only port 443 in July 2024.

  |$ qdlogstats wasd_logs:*443*202407*.log
  |QDLOGSTATS IA64-2.1.0 (CGILIB IA64-2.1.2), 07-JUL-2024 11:56
  |
  |Log ........... WASD_LOGS:*443*202407*.LOG  (14 matched)
   8< snip 8<
  |Statistics .... time:0.39 cpu:0.28 dio:1470 bio:89 faults:20 rec/sec:134770
  |Records ....... 52965  (0 suspect, 0 common, 52965 combined)
  |Requests ...... 52965
  |Methods ....... CONNECT:437 (1%)  COPY:0 (0%)  DELETE:0 (0%)  GET:50299 (95%)
  ↩HEAD:39 (0%)  LOCK:0 (0%)  MKCOL:0 (0%)  MOVE:0 (0%) OPTIONS:4 (0%)  POST:2165 (4%)
  ↩PROPFIND:0 (0%)  PROPPATCH:0 (0%)  PUT:0 (0%)  TRACE:0 (0%)  UNLOCK:0 (0%)  ?:21 (0%)
  |Responses ..... 1nn:2 (0%) 2nn:47620 (90%) 3nn:1613 (3%) 4nn:3602 (7%) 5nn:117 (0%) ?:11 (0%)
  |Tx GBytes ..... 1.566

Using the /VIEW and the /USERAGENT filter all matching access log entries are displayed.

  |$ qdlogstats wasd_logs:*443*202407*.log /view /useragent=*curl*
  |QDLOGSTATS IA64-2.1.0 (CGILIB IA64-2.1.2), 08-JUL-2024 09:12
  |165.154.129.201 - - [04/Jul/2024:02:37:53 +0930] "GET / HTTP/1.1" 403 5205 "-" "curl/7.29.0"
  |165.154.206.223 - - [05/Jul/2024:16:52:29 +0930] "GET / HTTP/1.1" 403 5199 "-" "curl/7.29.0"
  |152.32.134.89 - - [08/Jul/2024:04:57:59 +0930] "GET / HTTP/1.1" 302 4708 "-" "curl/7.29.0"
  |152.32.208.169 - - [06/Jul/2024:02:11:59 +0930] "GET / HTTP/1.1" 302 4693 "-" "curl/7.29.0"
  |128.199.161.158 - - [06/Jul/2024:02:39:43 +0930] "GET / HTTP/2" 200 1911 "-" "curl/7.81.0"
  |128.199.161.158 - - [07/Jul/2024:06:48:17 +0930] "GET / HTTP/2" 200 9898 "-" "curl/7.81.0"
  |
  |Log ........... WASD_LOGS:*443*202407*.LOG  (14 matched)
   8< snip 8<
  |User Agent .... *curl*  (60509 nomatch)
   8< snip 8<
  |Statistics .... time:8.28 cpu:2.89 dio:1697 bio:101 faults:28 rec/sec:7305
  |Records ....... 60515  (0 suspect, 0 common, 60515 combined)
  |Requests ...... 6
  |Methods ....... CONNECT:0 (0%)  COPY:0 (0%)  DELETE:0 (0%)  GET:6 (100%)  HEAD:0 (0%)  LOCK:0 (0%)
  ↩MKCOL:0 (0%) MOVE:0 (0%) OPTIONS:0 (0%)  POST:0 (0%)  PROPFIND:0 (0%)  PROPPATCH:0 (0%)  PUT:0 (0%)
  ↩TRACE:0 (0%) UNLOCK:0 (0%)  ?:0 (0%)
  |Responses ..... 1nn:0 (0%) 2nn:2 (33%) 3nn:2 (33%) 4nn:2 (33%) 5nn:0  (0%) ?:0 (0%)
  |Tx KBytes ..... 31.614

View all requests resulting in a 5nn (server error) response.

  |$ qdlogstats wasd_logs:*443*202407*.log /view /response=5*
  |QDLOGSTATS IA64-2.1.0 (CGILIB IA64-2.1.2), 08-JUN-2024 09:28
  |165.154.129.201 - - [05/Jul/2024:02:37:55 +0930] "t3 12.1.2" 501 4909 "-" "-"
   8< snip 8<
  |scanner-07.ch1.censys-scanner.com - - [04/Jul/2024:01:13:22 +0930] "PRI *" 505 4585 "-" "-"
  |petalbot-114-119-153-16.petalsearch.com - - [04/Jul/2024:09:31:27 +0930] "GET /cgi-bin/8<8<8< HTTP/1.1" 
  ↩501 4928 "https://8<8<8<" "Mozilla/5.0 (Linux; Android 7.0;) AppleWebKit/537.36 (KHTML, like Gecko)
  ↩Mobile Safari/537.36 (compatible; PetalBot;+https://webmaster.petalsearch.com/site/petalbot)"
   8< snip 8<
  |175.97.187.35.bc.googleusercontent.com - - [05/Jul/2024:14:05:47 +0930] "GET /HyperShelf/8<8<8< HTTP/1.1"
  ↩500 1039 "-" "Mozilla/5.0 (compatible; VelenPublicWebCrawler/1.0; +https://velen.io)"
  |
  |Log ........... WASD_LOGS:*443*202406*.LOG  (14 matched)
  |
  |Response ...... 5*  (60375 nomatch)
   8< snip 8<
  |Statistics .... time:0.42 cpu:0.36 dio:1578 bio:441 faults:23 rec/sec:143485
  |Records ....... 60551  (0 suspect, 0 common, 60551 combined)
  |Requests ...... 176
  |Methods ....... CONNECT:0 (0%)  COPY:0 (0%)  DELETE:0 (0%)  GET:163 (93%)  HEAD:0 (0%)  LOCK:0 (0%)
  ↩MKCOL:0 (0%)  MOVE:0 (0%) OPTIONS:0 (0%)  POST:1 (1%)  PROPFIND:0 (0%)  PROPPATCH:0 (0%)  PUT:0 (0%)
  ↩TRACE:0 (0%)  UNLOCK:0 (0%)  ?:12 (7%)
  |Responses ..... 1nn:0 (0%) 2nn:0 (0%) 3nn:0 (0%) 4nn:0 (0%) 5nn:176  (100%) ?:0 (0%)
  |Tx KBytes ..... 639.889

View all POST requests resulting in a 403 (forbidden) response.
Usual suspects obvious (e.g. path traversal, PHP).

  |$ qdlogstats wasd_logs:*443*202407*.log /view /response=403 /method=post
  |QDLOGSTATS IA64-2.1.0 (CGILIB IA64-2.1.2), 08-JUL-2024 09:45
  |164.92.71.158 - - [03/Jul/2024:14:47:52 +0930] "POST /cgi-bin/.%2e/.%2e/.%2e/.%2e/.%2e/.%2e/
  ↩.%2e/.%2e/.%2e/.%2e/bin/sh HTTP/1.1" 403 5205 "-" "Custom-AsyncHttpClient"
  |167.71.45.76 - - [04/Jul/2024:08:55:27 +0930] "POST /sdk HTTP/1.1" 403 5224 "-" "Mozilla/5.0
  ↩(compatible; Odin; https://docs.getodin.com/)"
   8< snip 8<
  |128.199.161.158 - - [07/Jul/2024:06:48:19 +0930] "POST /vendor/phpunit/phpunit/src/Util/PHP/
  ↩eval-stdin.php HTTP/2" 403 273 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36
  ↩(KHTML, like Gecko) Chrome/99.0.4859.172 Safari/537.36"
  |128.199.161.158 - - [07/Jul/2024:06:48:23 +0930] "POST /alfacgiapi/perl.alfa HTTP/2" 403 273 "-"
  ↩"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/99.0.4859.172
  ↩Safari/537.36"
  |
  |Log ........... WASD_LOGS:*443*202407*.LOG  (14 matched)
  |Method ........ post  (57905 nomatch)
   8< snip 8<
  |Response ...... 403  (2657 nomatch)
   8< snip 8<
  |Statistics .... time:0.40 cpu:0.35 dio:1696 bio:169 faults:23 rec/sec:150751
  |Records ....... 60602  (0 suspect, 0 common, 60602 combined)
  |Requests ...... 40
  |Methods ....... CONNECT:0 (0%)  COPY:0 (0%)  DELETE:0 (0%)  GET:0 (0%)  HEAD:0 (0%)  LOCK:0 (0%)
  ↩MKCOL:0 (0%) MOVE:0 (0%) OPTIONS:0 (0%)  POST:40 (100%)  PROPFIND:0 (0%)  PROPPATCH:0 (0%)  PUT:0 (0%)
  ↩TRACE:0 (0%) UNLOCK:0 (0%)  ?:0 (0%)
  |Responses ..... 1nn:0 (0%) 2nn:0 (0%) 3nn:0 (0%) 4nn:40 (100%) 5nn:0  (0%) ?:0 (0%)
  |Tx KBytes ..... 146.392

List all accesses by a specific authenticated user.

  |$ qdlogstats wasd_logs:*443*202407*.LOG /view /authuser=mgd
  |QDLOGSTATS IA64-2.1.0 (CGILIB IA64-2.1.2), 10-JUL-2024 10:05
  |41.239.119.22 - MGD [08/Jul/2024:00:05:42 +0930] "GET /cgiplus-bin/soymail/~?5136 HTTP/2" 204 299
  ↩"https://wasd.vsm.com.au/cgiplus-bin/soymail/~" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) 8<8<8<
   8< snip 8<
  |41.239.119.22 - MGD [09/Jul/2024:08:28:28 +0930] "GET /httpd/-/admin/ HTTP/2" 200 24423
  ↩"https://wasd.vsm.com.au/httpd/-/admin/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) 8<8<8<"
  |41.239.119.22 - MGD [09/Jul/2024:08:28:31 +0930] "GET /httpd/-/admin/report/activity?of=1 HTTP/2" 200 5792
  ↩"https://wasd.vsm.com.au/httpd/-/admin/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) 8<8<8<"
   8< snip 8<
  |41.239.119.22 - MGD [10/Jul/2024:08:38:00 +0930] "POST /cgiplus-bin/soymail/~ HTTP/2" 200 201
  ↩"https://wasd.vsm.com.au/cgiplus-bin/soymail/~" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) 8<8<8<"
  |
  |Log ........... WASD_LOGS:*443*202407*.LOG  (14 matched)
   8< snip 8<
  |Auth User ..... mgd  (58839 nomatch)
   8< snip 8<
  |Statistics .... time:0.37 cpu:0.27 dio:1059 bio:2433 faults:21 rec/sec:79706
  |Records ....... 60011  (0 suspect, 0 common, 60011 combined)
  |Requests ...... 1172
  |Methods ....... CONNECT:0 (0%)  COPY:0 (0%)  DELETE:0 (0%)  GET:1022 (87%)  HEAD:0 (0%)  LOCK:0 (0%)
  ↩MKCOL:0 (0%) MOVE:0 (0%) OPTIONS:0 (0%)  POST:150 (13%)  PROPFIND:0 (0%)  PROPPATCH:0 (0%)  PUT:0 (0%)
  ↩TRACE:0 (0%)  UNLOCK:0 (0%)  ?:0 (0%)
  |Responses ..... 1nn:0 (0%) 2nn:1172 (100%) 3nn:0 (0%) 4nn:0 (0%) 5nn:0  (0%) ?:0 (0%)
  |Tx MBytes ..... 7.126

Using a regular expression it is possible to list all uncommon responses.

  |$ qdlogstats wasd_logs:*443*202407*.log /view /response="!^(1[0-9]{2})|(2[0-9]{2})|(301)|(302)|(304)
  ↩|(401)|(403)|(404))"
  |QDLOGSTATS IA64-2.1.0 (CGILIB IA64-2.1.2), 10-JUL-2024 10:56
  |154.44.30.158 - - [07/Jul/2024:00:15:02 +0930] "POST -" 408 1028 "-" "-"
  |unused-space.coop.net - - [07/Jul/2024:01:19:19 +0930] "PRI *" 505 4585 "-" "-"
  |scanner-27.ch1.censys-scanner.com - - [07/Jul/2024:03:05:29 +0930] "PRI *" 505 4585 "-" "-"
  |123.145.4.68 - - [07/Jul/2024:17:49:33 +0930] "GET / HTTP/1.1" 500 4562 "-" "-"
   8< snip 8<
  |petalbot-114-119-134-49.petalsearch.com - - [10/Jul/2024:16:27:42 +0930] "GET /help/sys$common/
  ↩syshlp/ncphelp.hlb?key=LOAD~NODE&=yes HTTP/1.1" 400 5267 "https://8<8<8<ncphelp.hlbkey=LOAD~NODE
  ↩"Mozilla/5.0 (Linux; Android 7.0;) 8<8<8< PetalBot;+https://webmaster.petalsearch.com/site/petalbot)"
  |ec2-54-218-99-251.us-west-2.compute.amazonaws.com - - [10/Jul/2024:19:28:04 +0930] "GET /py-bin/
  ↩pyrte_test3.py HTTP/1.1" 502 1482 "-" "Mozilla/5.0 (Linux; U; Android 7.0; LG-H900 Build/NRD90M)8<8<8<
  |fwdproxy-cco-001.fbsv.net - - [11/Jul/2024:06:45:47 +0930] "GET /cgiplus-bin/postCGI.class HTTP/2"
  ↩502 562 "-" "facebookexternalhit/1.1 (+http://www.facebook.com/externalhit_uatext.php)"
   8< snip 8<
  |38.33.175.139 - - [10/Jul/2024:09:10:12 +0930] "GET / HTTP/1.1" 500 6558 "-" "Mozilla/4.0 (compatible;
  ↩MSIE 7.0; Windows NT 6.1; 8<8<8< .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media
  ↩Center PC 6.0; .NET4.0C; .NET4.0E; McAfee; InfoPath.3; GWX:DOWNLOADED; GWX:RESERVED)"
  |
  |Log ........... WASD_LOGS:*443*20240610*.LOG  (14 matched)
   8< snip 8<
  |Response ...... !^(1[0-9]{2})|(2[0-9]{2})|(301)|(302)|(304)|(401)|(403)|(404)  (60531 nomatch)
   8< snip 8<
  |Statistics .... time:0.35 cpu:0.32 dio:981 bio:445 faults:26 rec/sec:59034
  |Records ....... 60709  (0 suspect, 0 common, 60709 combined)
  |Requests ...... 178
  |Methods ....... CONNECT:7 (4%)  COPY:0 (0%)  DELETE:0 (0%)  GET:160 (90%)  HEAD:0 (0%)  LOCK:0 (0%)
  ↩MKCOL:0 (0%)  MOVE:0 (0%)  OPTIONS:0 (0%)  POST:9 (5%)  PROPFIND:0 (0%)  PROPPATCH:0 (0%)  PUT:0 (0%)
  ↩TRACE:0 (0%)  UNLOCK:0 (0%)  ?:2 (1%)
  |Responses ..... 1nn:0 (0%) 2nn:0 (0%) 3nn:0 (0%) 4nn:27 (15%) 5nn:151  (85%) ?:0 (0%)
  |Tx MBytes ..... 637.462

The web application basically provides the same functionality.  See attachment.

NOTES:

꙳꙳ Combined and common access log formats only.
   User-defined formats not supported.

 ⁑ With atypical (for me) working at the command-line a couple
   of typos and a couple of bugs have been corrected for v2.1.1

†† Geolocation available only with geolocate build.
   Location data displayed between braces.
   Lookup adds noticeable latency.

   |fwdproxy-ldc-013.fbsv.net {United States, Virginia, Ashburn} - - [10/Jul/2024:14:31:07 +0930]
   ↩"GET /cgi-bin/liner/wasd _root/src/wcme/libtls/OBJ_IA64/tls_verify.OBJ HTTP/2" 501 1028 "-" 
   ↩"facebookexternalhit/1.1 (+http://www.facebook.com/externalhit_uatext.php)"
   |69-165-220-127.dsl.teksavvy.com {Canada, Ontario, Toronto} - - [10/Jul/2024:16:44:47 +0930]
   ↩"GET /HyperShelf/HyperShelf/HyperShelf/HyperShelf/HyperShelf/HyperShelf/reference/openvms.decw$bookshelf
   ↩HTTP/1.1" 500 1045 "https://www.vsm.com.au/resources/" "Mozilla/5.0 (X11; Linux x86_64; rv:127.0) 8<8<8<"

   $ SET DEFAULT WASD_ROOT:[SRC.UTILS]
   $ @BUILD_QDLOGSTATS_GEOLOCATE [LINK]

‡‡ Access log file specifications rely on [LogNaming] and [LogPeriod] directives.

8< Example log entries edited for clarity and privacy.

 ↩ Long lines continued but wrapped for clarity.

This item is one of a collection at
https://wasd.vsm.com.au/other/#occasional

  ¤¤¤       
  ¤¤¤     
  ¤¤¤     
Image: 1st click 100%, 2nd actual size, 3rd default again