privoxy-log-parser: Bump version to 0.9.4
[privoxy.git] / tools / privoxy-log-parser.pl
index 10a5b3e..f6ee2f4 100755 (executable)
@@ -23,7 +23,7 @@
 #         hash key as input.
 #       - Add --compress and --decompress options.
 #
-# Copyright (c) 2007-2020 Fabian Keil <fk@fabiankeil.de>
+# Copyright (c) 2007-2021 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
@@ -43,7 +43,7 @@ use warnings;
 use Getopt::Long;
 
 use constant {
-    PRIVOXY_LOG_PARSER_VERSION => '0.9.1',
+    PRIVOXY_LOG_PARSER_VERSION => '0.9.4',
     # Feel free to mess with these ...
     DEFAULT_BACKGROUND => 'black',  # Choose registered colour (like 'black')
     DEFAULT_TEXT_COLOUR => 'white', # Choose registered colour (like 'black')
@@ -52,6 +52,7 @@ use constant {
 
     CLI_OPTION_DEFAULT_TO_HTML_OUTPUT => 0,
     CLI_OPTION_TITLE => 'Privoxy-Log-Parser in da house',
+    CLI_OPTION_KEEP_DATE => 0,
     CLI_OPTION_NO_EMBEDDED_CSS => 0,
     CLI_OPTION_NO_MSECS => 0,
     CLI_OPTION_NO_SYNTAX_HIGHLIGHTING => 0,
@@ -107,6 +108,7 @@ my %h_colours;
 my $header_highlight_regex = '';
 
 my $html_output_mode;
+my $keep_date_mode;
 my $no_msecs_mode; # XXX: should probably be removed
 my $shorten_thread_ids;
 my $line_end;
@@ -128,6 +130,7 @@ sub prepare_our_stuff() {
         'Re-Filter'     => 'purple',
         Connect         => 'brown',
         Request         => 'light_cyan',
+        Tagging         => 'purple',
         CGI             => 'light_green',
         Redirect        => 'cyan',
         Error           => 'light_red',
@@ -176,6 +179,7 @@ sub prepare_our_stuff() {
         'pcrs-delimiter'     => 'light_red',
         'ignored'            => 'light_red',
         'action-bits-update' => 'light_red',
+        'http-downgrade'     => 'light_red',
         'configuration-line' => 'red',
         'content-type'       => 'yellow',
         'HOST'               => HEADER_DEFAULT_COLOUR,
@@ -640,7 +644,7 @@ sub highlight_request_line($) {
     my ($method, $url, $http_version);
 
     #GET http://images.sourceforge.net/sfx/icon_warning.gif HTTP/1.1
-    if ($rl =~ m/Invalid request/) {
+    if ($rl =~ m/Invalid request/ or $rl =~ m/Failed reading chunked client body/) {
 
         $rl = h('invalid-request') . $rl . h('Standard');
 
@@ -1074,6 +1078,17 @@ sub handle_loglevel_re_filter($) {
         $c .= $req{$t}{'content_size_change'} . $h{'Standard'} . ")";
         $content = $c;
 
+    } elsif ($c =~ m/^filtering request body from client /) {
+
+        # filtering request body from client 127.0.0.1 (size 958) with 'null-filter' produced 0 hits (new size 958).
+
+        $c =~ s@(?<=from client )([^\s]+)@$h{'ip-address'}$1$h{'Standard'}@;
+        $c =~ s@(?<=\(size )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+        $c =~ s@([^\s]+?)(\'? produced)@$h{'filter'}$1$h{'Standard'}$2@;
+        $c =~ s@(?<=\(new size )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+        $c =~ s@(?<=produced )(\d+)(?= hits)@$h{'Number'}$1$h{'Standard'}@;
+        $content = $c;
+
   } elsif ($c =~ /\.{3}$/
         and $c =~ m/^(?:re_)?filtering \'?(.*?)\'? \(size (\d*)\) with (?:filter )?\'?([^\s]*?)\'? ?\.{3}$/) {
 
@@ -1225,6 +1240,57 @@ sub handle_loglevel_re_filter($) {
     return $content;
 }
 
+sub handle_loglevel_tagging($) {
+
+    my $c = shift;
+
+    if ($c =~ /^Tagger \'([^\']*)\' added tag \'([^\']*)\'/ or
+        $c =~ m/^Adding tag \'([^\']*)\' created by header tagger \'([^\']*)\'/) {
+
+        # Adding tag 'GET request' created by header tagger 'method-man' (XXX: no longer used)
+        # Tagger 'revalidation' added tag 'REVALIDATION-REQUEST'. No action bit update necessary.
+        # Tagger 'revalidation' added tag 'REVALIDATION-REQUEST'. Action bits updated accordingly.
+
+        # XXX: Save tag and tagger
+
+        $c =~ s@(?<=^Tagger \')([^\']*)@$h{'tagger'}$1$h{'Standard'}@;
+        $c =~ s@(?<=added tag \')([^\']*)@$h{'tag'}$1$h{'Standard'}@;
+        $c =~ s@(?<=Action bits )(updated)@$h{'action-bits-update'}$1$h{'Standard'}@;
+
+    } elsif ($c =~ /^Enlisting tag/) {
+
+        # Enlisting tag 'forward-directly' for client 127.0.0.1.
+
+        $c =~ s@(?<=tag \')([^\']*)@$h{'tag'}$1$h{'Standard'}@;
+        $c = highlight_matched_host($c, '[^\s]+(?=\.$)');
+
+    } elsif ($c =~ /^Tag/) {
+
+        # Tag 'change-tor-socks-port' for client 127.0.0.1 expired 1 seconds ago. Deleting it.
+
+        $c =~ s@(?<=Tag \')([^\']*)@$h{'tag'}$1$h{'Standard'}@;
+        $c =~ s@(?<=expired )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+        $c = highlight_matched_host($c, '(?<=client )[^\s]+');
+
+    } elsif ($c =~ /^Evaluating/) {
+
+        # Evaluating tag 'change-tor-socks-port' for client 127.0.0.1. End of life 1613162302.
+
+        $c =~ s@(?<=tag \')([^\']*)@$h{'tag'}$1$h{'Standard'}@;
+        $c = highlight_matched_host($c, '(?<=client )[^\s]+(?=\.)');
+        $c =~ s@(?<=life )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+
+    } elsif ($c =~ /^Client tag/) {
+
+        # Client tag 'forward-directly' matches
+
+        $c =~ s@(?<=tag \')([^\']*)@$h{'tag'}$1$h{'Standard'}@;
+
+    }
+
+    return $c;
+}
+
 sub handle_loglevel_redirect($) {
 
     my $c = shift;
@@ -1282,6 +1348,17 @@ sub handle_loglevel_redirect($) {
         # Percent-encoding redirect URL: http://www.example.org/\x02
         $c = highlight_matched_url($c, '(?<=redirect URL: ).*');
 
+    } elsif ($c =~ m/^Rewrite detected:/) {
+
+        # Rewrite detected: GET http://10.0.0.2:88/blah.txt HTTP/1.1
+        # Rewrite detected: GET https://www.electrobsd.org/CommonJS/ajax/libs/jquery/3.4.1/jquery.min.js HTTP/1.1
+        $c = highlight_matched_request_line($c, '(?<=^Rewrite detected: ).*');
+
+    } elsif ($c =~ m/^Rewritten request line results in downgrade to http/) {
+
+        # Rewritten request line results in downgrade to http
+        $c =~ s@(downgrade)@$h{'http-downgrade'}$1$h{'Standard'}@;
+
     } else {
 
         found_unknown_content($c);
@@ -1387,6 +1464,11 @@ sub handle_loglevel_crunch($) {
         #  [...]&filter... [too long, truncated]
         $content = highlight_matched_pattern($content, 'request_', '^.*(?=\.\.\. \[too long, truncated\]$)');
 
+    } elsif ($content =~ m/Certificate error:/) {
+
+        # Certificate error: ASN date error, current date after: https://expired.badssl.com/
+        $content = highlight_matched_pattern($content, 'request_', 'https://.*');
+
     } else {
 
         # Blocked: http://ads.example.org/
@@ -1778,6 +1860,46 @@ sub handle_loglevel_connect($) {
         $c =~ s@(?<=client socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
         $c =~ s@(?<=Requests so far: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
 
+    } elsif ($c =~ m/^Dropping the client connection on socket/) {
+
+        # Dropping the client connection on socket 71. The server connection has not been established yet.
+        # Dropping the client connection on socket 23 with server socket 24 connected to \
+        #  www.reddit.com. The forwarder has changed.
+        $c =~ s@(?<=on socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+        $c =~ s@(?<=server socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+        $c = highlight_matched_host($c, '(?<=connected to )[^ ]+(?=\.)');
+
+    } elsif ($c =~ m/^The client socket \d+ has become unusable while the server/) {
+
+        # The client socket 16 has become unusable while the server socket 24 is still open.
+        $c =~ s@(?<=client socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+        $c =~ s@(?<=server socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+
+    } elsif ($c =~ m/^The last \d+ bytes of the request body have been read/) {
+
+        # The last 12078 bytes of the request body have been read
+        $c =~ s@(?<=The last )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+
+    } elsif ($c =~ m/^Flushed \d+ bytes of request body/) {
+
+        # Flushed 3153 bytes of request body
+        $c =~ s@(?<=Flushed )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+
+    } elsif ($c =~ m/^Complete client request followed by/) {
+
+        # Complete client request followed by 59 bytes of pipelined data received.
+        $c =~ s@(?<=followed by )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+
+    } elsif ($c =~ m/^The peer notified us that the connection on socket/) {
+
+        # The peer notified us that the connection on socket 11 is going to be closed
+        $c =~ s@(?<=socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+
+    } elsif ($c =~ m/^Client socket \d is no longer usable/) {
+
+        # Client socket 7 is no longer usable. The server socket has been closed.
+        $c =~ s@(?<=socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+
     } elsif ($c =~ m/^Looks like we / or
              $c =~ m/^Unsetting keep-alive flag/ or
              $c =~ m/^No connections to wait/ or
@@ -2011,6 +2133,19 @@ sub handle_loglevel_error($) {
 
         # Didn't receive data in time: a.fsdn.com:443
         $c =~ s@(?<=in time: )(.*)@$h{'destination'}$1$h{'Standard'}@;
+
+    } elsif ($c =~ m/^Sending data on socket \d+ over TLS/) {
+
+        # Sending data on socket 33 over TLS/SSL failed: no TLS/SSL errors detected
+        $c =~ s@(?<=on socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+
+    } elsif ($c =~ m/^Chunk size \d+ exceeds buffered data left/) {
+
+        # Chunk size 291 exceeds buffered data left. Already digested 69894 of 69957 buffered bytes.
+        $c =~ s@(?<=size )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+        $c =~ s@(?<=digested )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+        $c =~ s@(?<=of )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+
     }
 
     # XXX: There are probably more messages that deserve highlighting.
@@ -2044,7 +2179,14 @@ sub gather_loglevel_clf_stats($) {
     unless (defined $method) {
         # +0200] "Invalid request" 400 0
         return if ($content =~ m/^[+-]\d{4}\] "Invalid request"/);
-        print("Failed to parse: $content\n");
+        # +0100] "Failed reading chunked client body" 400 0
+        return if ($content =~ m/^[+-]\d{4}\] "Failed reading chunked client body"/);
+        # +0100] "GET https://securepubads.g.doubleclick.net/gampad/ads?gd[...]... [too long, truncated]
+        if ($content =~ m/\[too long, truncated\]$/) {
+            print("Skipped LOG_LEVEL_CLF message that got truncated by Privoxy. Statistics will be inprecise.\n");
+        } else {
+            print("Failed to parse: $content\n");
+        }
         return;
     }
     $stats{'method'}{$method}++;
@@ -2257,7 +2399,7 @@ sub print_stats() {
         get_percentage($requests_total, $stats{'server-keep-alive'}) . ")\n";
     print "New outgoing connections: " . $new_connections . " (" .
         get_percentage($requests_total, $new_connections) . ")\n";
-    print "Reused connections: " . $stats{'reused-connections'} . " (" .
+    print "Reused server connections: " . $stats{'reused-connections'} . " (" .
         get_percentage($requests_total, $stats{'reused-connections'}) .
         "; server offers accepted: " .
         get_percentage($stats{'server-keep-alive'}, $stats{'reused-connections'}) . ")\n";
@@ -2273,7 +2415,7 @@ sub print_stats() {
         ")\n";
     print "Client connections: " .  $stats{'closed-client-connections'} . "\n";
     if ($stats{'content-size-total'}) {
-        print "Bytes of content transfered to the client: " .  $stats{'content-size-total'} . "\n";
+        print "Bytes of content transferred to the client: " .  $stats{'content-size-total'} . "\n";
     }
     my $lines_printed = 0;
     print "Client requests per connection distribution:\n";
@@ -2312,7 +2454,7 @@ sub print_stats() {
         print "HTTP version distribution unknown. No CLF message parsed yet. Is 'debug 512' enabled?\n";
     }
     if (exists $stats{'status-code'}) {
-        print "HTTP status codes:\n";
+        print "HTTP status codes according to 'debug 512' (status codes sent by the server may differ):\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;
         }
@@ -2377,12 +2519,14 @@ sub print_clf_message() {
 sub print_non_clf_message($) {
 
     my $content = shift;
+    my $date_string = $keep_date_mode ? $req{$t}{'day'} . ' ' : '';
     my $msec_string = $no_msecs_mode ? '' : '.' . $req{$t}{'msecs'};
     my $line_start = $html_output_mode ? '' : $h{"Standard"};
 
     return if DEBUG_SUPPRESS_LOG_MESSAGES;
 
     print $line_start
+        . $date_string
         . $time_colours[$time_colour_index % 2]
         . $req{$t}{'time-stamp'}
         . $msec_string
@@ -2439,6 +2583,7 @@ sub parse_loop() {
         'Fatal error'       => \&handle_loglevel_ignore,
         'Writing'           => \&handle_loglevel_ignore,
         'Received'          => \&handle_loglevel_ignore,
+        'Tagging'           => \&handle_loglevel_tagging,
         'Actions'           => \&handle_loglevel_ignore,
         'Unknown log level' => \&handle_loglevel_ignore,
     );
@@ -2515,7 +2660,7 @@ sub parse_loop() {
 
 sub stats_loop() {
 
-    my ($day, $time_stamp, $msecs, $thread, $log_level, $content);
+    my ($day, $time_stamp, $thread, $log_level, $content);
     my $strict_checks = cli_option_is_set('strict-checks');
     my %log_level_handlers = (
          'Connect:'           => \&gather_loglevel_connect_stats,
@@ -2536,6 +2681,7 @@ sub stats_loop() {
          'Redirect:'          => \&handle_loglevel_ignore,
          'Unknown log level:' => \&handle_loglevel_ignore,
          'Writing:'           => \&handle_loglevel_ignore,
+         'Tagging:'           => \&handle_loglevel_ignore,
     );
 
     while (<>) {
@@ -2600,6 +2746,7 @@ sub get_cli_options() {
     our %cli_options = (
         'html-output'              => CLI_OPTION_DEFAULT_TO_HTML_OUTPUT,
         'title'                    => CLI_OPTION_TITLE,
+        'keep-date'                => CLI_OPTION_KEEP_DATE,
         'no-syntax-highlighting'   => CLI_OPTION_NO_SYNTAX_HIGHLIGHTING,
         'no-embedded-css'          => CLI_OPTION_NO_EMBEDDED_CSS,
         'no-msecs'                 => CLI_OPTION_NO_MSECS,
@@ -2616,6 +2763,7 @@ sub get_cli_options() {
     GetOptions (
         'html-output'              => \$cli_options{'html-output'},
         'title'                    => \$cli_options{'title'},
+        'keep-date'                => \$cli_options{'keep-date'},
         'no-syntax-highlighting'   => \$cli_options{'no-syntax-highlighting'},
         'no-embedded-css'          => \$cli_options{'no-embedded-css'},
         'no-msecs'                 => \$cli_options{'no-msecs'},
@@ -2633,6 +2781,7 @@ sub get_cli_options() {
 
    $html_output_mode = cli_option_is_set('html-output');
    $no_msecs_mode = cli_option_is_set('no-msecs');
+   $keep_date_mode = cli_option_is_set('keep-date');
    $shorten_thread_ids = cli_option_is_set('shorten-thread-ids');
    $line_end = get_line_end();
 }
@@ -2674,18 +2823,16 @@ sub main() {
     set_background(DEFAULT_BACKGROUND);
     prepare_our_stuff();
 
-    print_intro();
-
     # XXX: should explicitly reject incompatible argument combinations
     if (cli_option_is_set('unbreak-lines-only')) {
         unbreak_lines_only_loop();
     } elsif (cli_option_is_set('statistics')) {
         stats_loop();
     } else {
+        print_intro();
         parse_loop();
+        print_outro();
     }
-
-    print_outro();
 }
 
 main();
@@ -2727,12 +2874,15 @@ will hide the "filter foo caused 0 hits" message.
 if it's above or equal to the given threshold. If the threshold is 0, host
 statistics are disabled.
 
-[B<--html-output>] Use HTML and CSS for the syntax highlighting. If this option is
+[B<--html-output>] Use HTML and CSS when syntax highlighting. If this option is
 omitted, ANSI escape sequences are used unless B<--no-syntax-highlighting> is active.
 This option is only intended to make embedding log excerpts in web pages easier.
 It does not escape any input!
 
-[B<--no-msecs>] Don't expect milisecond resolution
+[B<--keep-date>] Don't remove the date when printing highlighted log messages.
+Useful when parsing multiple log files at once.
+
+[B<--no-msecs>] Don't expect millisecond resolution
 
 [B<--no-syntax-highlighting>] Disable syntax-highlighting. Useful when
 the filtered output is piped into less in which case the ANSI control
@@ -2821,7 +2971,7 @@ Many settings can't be controlled through command line options yet.
 
 =head1 SEE ALSO
 
-privoxy(1)
+privoxy(8)
 
 =head1 AUTHOR