privoxy-log-parser.pl: Align the client-HTTP-version distribution like other distribu...
[privoxy.git] / tools / privoxy-log-parser.pl
index b22896b..5a1ebca 100755 (executable)
@@ -6,9 +6,7 @@
 # A parser for Privoxy log messages. For incomplete documentation run
 # perldoc privoxy-log-parser(.pl), for fancy screenshots see:
 #
-# http://www.fabiankeil.de/sourcecode/privoxy-log-parser/
-#
-# $Id: privoxy-log-parser.pl,v 1.154 2013/01/13 15:38:54 fabiankeil Exp $
+# https://www.fabiankeil.de/sourcecode/privoxy-log-parser/
 #
 # TODO:
 #       - LOG_LEVEL_CGI, LOG_LEVEL_ERROR, LOG_LEVEL_WRITE content highlighting
@@ -25,7 +23,7 @@
 #         hash key as input.
 #       - Add --compress and --decompress options.
 #
-# Copyright (c) 2007-2012 Fabian Keil <fk@fabiankeil.de>
+# Copyright (c) 2007-2020 Fabian Keil <fk@fabiankeil.de>
 #
 # Permission to use, copy, modify, and distribute this software for any
 # purpose with or without fee is hereby granted, provided that the above
@@ -45,7 +43,7 @@ use warnings;
 use Getopt::Long;
 
 use constant {
-    PRIVOXY_LOG_PARSER_VERSION => '0.7',
+    PRIVOXY_LOG_PARSER_VERSION => '0.9.1',
     # Feel free to mess with these ...
     DEFAULT_BACKGROUND => 'black',  # Choose registered colour (like 'black')
     DEFAULT_TEXT_COLOUR => 'white', # Choose registered colour (like 'black')
@@ -59,7 +57,6 @@ use constant {
     CLI_OPTION_NO_SYNTAX_HIGHLIGHTING => 0,
     CLI_OPTION_SHORTEN_THREAD_IDS => 0,
     CLI_OPTION_SHOW_INEFFECTIVE_FILTERS => 0,
-    CLI_OPTION_ACCEPT_UNKNOWN_MESSAGES => 0,
     CLI_OPTION_STATISTICS => 0,
     CLI_OPTION_STRICT_CHECKS => 0,
     CLI_OPTION_UNBREAK_LINES_ONLY => 0,
@@ -555,7 +552,7 @@ sub found_unknown_content ($) {
     my $unknown = shift;
     my $message;
 
-    return if cli_option_is_set('accept-unknown-messages');
+    return unless cli_option_is_set('strict-checks');
 
     return if ($unknown =~ /\[too long, truncated\]$/);
 
@@ -647,7 +644,7 @@ sub highlight_request_line ($) {
 
         $rl = h('invalid-request') . $rl . h('Standard');
 
-    } elsif ($rl =~ m/^([-\w]+) (.*) (HTTP\/\d\.\d)/) {
+    } elsif ($rl =~ m/^([-\w]+) (.*) (HTTP\/\d+\.\d+)/) {
 
         # XXX: might not match in case of HTTP method fuzzing.
         # XXX: save these: ($method, $path, $http_version) = ($1, $2, $3);
@@ -1983,6 +1980,39 @@ sub handle_loglevel_ignore ($) {
     return shift;
 }
 
+sub gather_loglevel_clf_stats ($) {
+
+    my $content = shift;
+    my ($method, $resource, $http_version, $status_code, $size);
+    our %stats;
+    our %cli_options;
+
+    # +0200] "GET https://www.youtube.com/watch?v=JmcA9LIIXWw HTTP/1.1" 200 68004
+    $content =~ m/^[+-]\d{4}\] "(\w+) (.+) (HTTP\/\d\.\d)" (\d+) (\d+)/;
+    $method       = $1;
+    $resource     = $2;
+    $http_version = $3;
+    $status_code  = $4;
+    $size         = $5;
+
+    unless (defined $method) {
+        print("Failed to parse: $content\n");
+        return;
+    }
+    $stats{'method'}{$method}++;
+    if ($cli_options{'url-statistics-threshold'} != 0) {
+        $stats{'resource'}{$resource}++;
+    }
+    $stats{'http-version'}{$http_version}++;
+
+    if ($cli_options{'host-statistics-threshold'} != 0) {
+        $resource =~ m@(?:http[s]://)([^/]+)/?@;
+        $stats{'hosts'}{$1}++;
+    }
+    $stats{'content-size-total'} += $size;
+    $stats{'status-code'}{$status_code}++;
+}
+
 sub gather_loglevel_request_stats ($$) {
     my $c = shift;
     my $thread = shift;
@@ -1996,7 +2026,6 @@ sub gather_loglevel_crunch_stats ($$) {
     my $thread = shift;
     our %stats;
 
-    $stats{requests}++;
     $stats{crunches}++;
 
     if ($c =~ m/^Redirected:/) {
@@ -2006,6 +2035,14 @@ sub gather_loglevel_crunch_stats ($$) {
     } elsif ($c =~ m/^Blocked:/) {
         # Blocked: blogger.googleusercontent.com:443
         $stats{'blocked'}++;
+
+    } elsif ($c =~ m/^Connection timeout:/) {
+        # Connection timeout: http://c.tile.openstreetmap.org/18/136116/87842.png
+        $stats{'connection-timeout'}++;
+
+    } elsif ($c =~ m/^Connection failure:/) {
+        # Connection failure: http://127.0.0.1:8080/
+        $stats{'connection-failure'}++;
     }
 }
 
@@ -2075,6 +2112,7 @@ sub gather_loglevel_header_stats ($$) {
 
     my ($c, $thread) = @_;
     our %stats;
+    our %cli_options;
 
     if ($c =~ m/^A HTTP\/1\.1 response without/ or
         $c =~ m/^Keeping the server header 'Connection: keep-alive' around./)
@@ -2082,18 +2120,6 @@ sub gather_loglevel_header_stats ($$) {
         # A HTTP/1.1 response without Connection header implies keep-alive.
         # Keeping the server header 'Connection: keep-alive' around.
         $stats{'server-keep-alive'}++;
-
-    } elsif ($c =~ m/^scan: ((\w+) (.+) (HTTP\/\d\.\d))/) {
-
-        # scan: HTTP/1.1 200 OK
-        $stats{'method'}{$2}++;
-        $stats{'resource'}{$3}++;
-        $stats{'http-version'}{$4}++;
-
-    } elsif ($c =~ m/^scan: Host: ([^\s]+)/) {
-
-        # scan: Host: p.p
-        $stats{'hosts'}{$1}++;
     }
 }
 
@@ -2108,9 +2134,12 @@ sub init_stats () {
         'empty-responses-on-reused-connections' => 0,
         'fast-redirections' => 0,
         'blocked' => 0,
+        'connection-failure' => 0,
+        'connection-timeout' => 0,
         'reused-connections' => 0,
         'server-keep-alive' => 0,
         'closed-client-connections' => 0,
+        'content-size-total' => 0,
         );
         $stats{'client-requests-on-connection'}{1} = 0;
 }
@@ -2150,6 +2179,10 @@ sub print_stats () {
         get_percentage($stats{requests}, $stats{'blocked'}) . ")\n";
     print "Fast redirections: " . $stats{'fast-redirections'} . " (" .
         get_percentage($stats{requests}, $stats{'fast-redirections'}) . ")\n";
+    print "Connection timeouts: " . $stats{'connection-timeout'} . " (" .
+        get_percentage($stats{requests}, $stats{'connection-timeout'}) . ")\n";
+    print "Connection failures: " . $stats{'connection-failure'} . " (" .
+        get_percentage($stats{requests}, $stats{'connection-failure'}) . ")\n";
     print "Outgoing requests: " . $outgoing_requests . " (" .
         get_percentage($stats{requests}, $outgoing_requests) . ")\n";
     print "Server keep-alive offers: " . $stats{'server-keep-alive'} . " (" .
@@ -2171,7 +2204,9 @@ sub print_stats () {
         get_percentage($stats{requests}, $stats{'empty-responses-on-reused-connections'}) .
         ")\n";
     print "Client connections: " .  $stats{'closed-client-connections'} . "\n";
-
+    if ($stats{'content-size-total'}) {
+        print "Bytes transfered excluding headers: " .  $stats{'content-size-total'} . "\n";
+    }
     my $lines_printed = 0;
     print "Client requests per connection distribution:\n";
     foreach my $client_requests (sort {
@@ -2189,19 +2224,28 @@ sub print_stats () {
     unless ($cli_options{'show-complete-request-distribution'}) {
         printf "Enable --show-complete-request-distribution to get less common numbers as well.\n";
     }
-    printf "Unaccounted requests: ~%d\n", $stats{requests} - $client_requests_checksum;
+    # Due to log rotation we may not have a complete picture for all the requests
+    printf "Improperly accounted requests: ~%d\n", abs($stats{requests} - $client_requests_checksum);
 
-    if ($stats{method} eq 0) {
-        print "No response lines parsed yet yet.\n";
-        return;
-    }
-    print "Method distribution:\n";
-    foreach my $method (sort {$stats{'method'}{$b} <=> $stats{'method'}{$a}} keys %{$stats{'method'}}) {
-        printf "%8d : %-8s\n", $stats{'method'}{$method}, $method;
+    if (exists $stats{method}) {
+        print "Method distribution:\n";
+        foreach my $method (sort {$stats{'method'}{$b} <=> $stats{'method'}{$a}} keys %{$stats{'method'}}) {
+            printf "%8d : %-8s\n", $stats{'method'}{$method}, $method;
+        }
+    } else {
+        print "Method distribution unknown. No CLF message parsed yet. Is 'debug 512' enabled?\n";
     }
     print "Client HTTP versions:\n";
     foreach my $http_version (sort {$stats{'http-version'}{$b} <=> $stats{'http-version'}{$a}} keys %{$stats{'http-version'}}) {
-        printf "%d : %s\n",  $stats{'http-version'}{$http_version}, $http_version;
+        printf "%8d : %-8s\n",  $stats{'http-version'}{$http_version}, $http_version;
+    }
+    if (exists $stats{'status-code'}) {
+        print "HTTP status codes:\n";
+        foreach my $status_code (sort {$stats{'status-code'}{$b} <=> $stats{'status-code'}{$a}} keys %{$stats{'status-code'}}) {
+            printf "%8d : %-8d\n",  $stats{'status-code'}{$status_code}, $status_code;
+        }
+    } else {
+        print "Status code distribution unknown. No CLF message parsed yet. Is 'debug 512' enabled?\n";
     }
 
     if ($cli_options{'url-statistics-threshold'} == 0) {
@@ -2425,10 +2469,14 @@ sub stats_loop () {
     while (<>) {
         (undef, $time_stamp, $thread, $log_level, $content) = split(/ /, $_, 5);
 
-        # Skip LOG_LEVEL_CLF
-        next if ($time_stamp eq "-");
 
-        if (defined($log_level_handlers{$log_level})) {
+        next if (not defined($log_level));
+
+        if ($time_stamp eq "-") {
+
+            gather_loglevel_clf_stats($content);
+
+        } elsif (defined($log_level_handlers{$log_level})) {
 
             $content = $log_level_handlers{$log_level}($content, $thread);
 
@@ -2470,8 +2518,7 @@ sub VersionMessage {
     my $version_message;
 
     $version_message .= 'Privoxy-Log-Parser ' . PRIVOXY_LOG_PARSER_VERSION  . "\n";
-    $version_message .= 'Copyright (C) 2007-2010 Fabian Keil <fk@fabiankeil.de>' . "\n";
-    $version_message .= 'http://www.fabiankeil.de/sourcecode/privoxy-log-parser/' . "\n";
+    $version_message .= 'https://www.fabiankeil.de/sourcecode/privoxy-log-parser/' . "\n";
 
     print $version_message;
 }
@@ -2486,7 +2533,6 @@ sub get_cli_options () {
         'no-msecs'                 => CLI_OPTION_NO_MSECS,
         'shorten-thread-ids'       => CLI_OPTION_SHORTEN_THREAD_IDS,
         'show-ineffective-filters' => CLI_OPTION_SHOW_INEFFECTIVE_FILTERS,
-        'accept-unknown-messages'  => CLI_OPTION_ACCEPT_UNKNOWN_MESSAGES,
         'statistics'               => CLI_OPTION_STATISTICS,
         'strict-checks'            => CLI_OPTION_STRICT_CHECKS,
         'url-statistics-threshold' => CLI_OPTION_URL_STATISTICS_THRESHOLD,
@@ -2503,7 +2549,6 @@ sub get_cli_options () {
         'no-msecs'                 => \$cli_options{'no-msecs'},
         'shorten-thread-ids'       => \$cli_options{'shorten-thread-ids'},
         'show-ineffective-filters' => \$cli_options{'show-ineffective-filters'},
-        'accept-unknown-messages'  => \$cli_options{'accept-unknown-messages'},
         'statistics'               => \$cli_options{'statistics'},
         'strict-checks'            => \$cli_options{'strict-checks'},
         'unbreak-lines-only'       => \$cli_options{'unbreak-lines-only'},
@@ -2529,7 +2574,6 @@ sub help () {
     print << "    EOF"
 
 Options and their default values if they have any:
-    [--accept-unknown-messages]
     [--host-statistics-threshold $cli_options{'host-statistics-threshold'}]
     [--html-output]
     [--no-embedded-css]
@@ -2580,7 +2624,7 @@ B<privoxy-log-parser> - A parser and syntax-highlighter for Privoxy log messages
 
 =head1 SYNOPSIS
 
-B<privoxy-log-parser> [B<--accept-unknown-messages>] [B<--html-output>]
+B<privoxy-log-parser> [B<--html-output>]
 [B<--no-msecs>] [B<--no-syntax-higlighting>] [B<--statistics>]
 [B<--shorten-thread-ids>] [B<--show-ineffective-filters>]
 [B<--url-statistics-threshold>] [B<--version>]
@@ -2607,9 +2651,6 @@ will hide the "filter foo caused 0 hits" message.
 
 =head1 OPTIONS
 
-[B<--accept-unknown-messages>] Don't print warnings in case of unknown messages,
-just don't highlight them.
-
 [B<--host-statistics-threshold>] Only show the request count for a host
 if it's above or equal to the given threshold. If the threshold is 0, host
 statistics are disabled.
@@ -2646,6 +2687,8 @@ to be incorrect if Privoxy and Privoxy-Log-Parser aren't in sync.
 input data and abort if it is unexpected, even if it doesn't affect the
 results. Significantly slows the parsing down and is not expected to catch
 any problems that matter.
+When highlighting, print warnings in case of unknown messages which can't be
+properly highlighted.
 
 [B<--unbreak-lines-only>] Tries to fix lines that got messed up by a broken or
 interestingly configured mail client and thus are no longer recognized properly.