Also gather statistics for ressources, methods, and HTTP versions used by the client.
[privoxy.git] / tools / privoxy-log-parser.pl
index c6b52b8..0fdc1d2 100755 (executable)
@@ -8,7 +8,7 @@
 #
 # http://www.fabiankeil.de/sourcecode/privoxy-log-parser/
 #
-# $Id: privoxy-log-parser.pl,v 1.73 2010/01/05 23:36:43 fabiankeil Exp $
+# $Id: privoxy-log-parser.pl,v 1.89 2010/08/28 13:20:23 fabiankeil Exp $
 #
 # TODO:
 #       - LOG_LEVEL_CGI, LOG_LEVEL_ERROR, LOG_LEVEL_WRITE content highlighting
@@ -23,8 +23,9 @@
 #       - Handle incomplete input without Perl warning about undefined variables.
 #       - Use generic highlighting function that takes a regex and the
 #         hash key as input.
+#       - Add --compress and --decompress options.
 #
-# Copyright (c) 2007-2009 Fabian Keil <fk@fabiankeil.de>
+# Copyright (c) 2007-2010 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
@@ -56,6 +57,7 @@ use constant {
     CLI_OPTION_NO_EMBEDDED_CSS => 0,
     CLI_OPTION_NO_MSECS => 0,
     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,
@@ -105,6 +107,7 @@ my $header_highlight_regex = '';
 
 my $html_output_mode;
 my $no_msecs_mode; # XXX: should probably be removed
+my $shorten_thread_ids;
 my $line_end;
 
 sub prepare_our_stuff () {
@@ -132,6 +135,7 @@ sub prepare_our_stuff () {
         'Gif-Deanimate' => 'blue',
         Force           => 'red',
         Writing         => 'light_green',
+        Received        => 'yellow',
         # ----------------------
         URL                  => 'yellow',
         path                 => 'brown',
@@ -801,15 +805,10 @@ sub handle_loglevel_header ($) {
                 update_header_highlight_regex($header);
             }
 
-        } elsif ($c =~ m/^scan: ((\w+) (.+) (HTTP\/\d\.\d))/) {
+        } elsif ($c =~ m/^(scan: )(\w+ .+ HTTP\/\d\.\d)/) {
 
-            # Client request line
-            # Save for statistics (XXX: Not implemented yet)
-            $req{$t}{'method'} = $2;
-            $req{$t}{'destination'} = $3;
-            $req{$t}{'http-version'} = $4;
-
-            $c = highlight_request_line($1);
+            # scan: HTTP/1.1 200 OK
+            $c = $1 . highlight_request_line($2);
 
         } elsif ($c =~ m/^(scan: )((?:HTTP\/\d\.\d|ICY) (\d+) (.*))/) {
 
@@ -908,6 +907,7 @@ sub handle_loglevel_header ($) {
           or $c =~ m/^Appended client IP address to/
           or $c =~ m/^Removing 'Connection: close' to imply keep-alive./
           or $c =~ m/^keep-alive support is disabled/
+          or $c =~ m/^Continue hack in da house/
             )
     {
         # XXX: Some of these may need highlighting
@@ -953,6 +953,7 @@ sub handle_loglevel_header ($) {
         # Appended client IP address to X-Forwarded-For: 10.0.0.2, 10.0.0.1
         # Removing 'Connection: close' to imply keep-alive.
         # keep-alive support is disabled. Crunching: Keep-Alive: 300.
+        # Continue hack in da house.
 
     } elsif ($c =~ m/^scanning headers for:/) {
 
@@ -1548,10 +1549,11 @@ sub handle_loglevel_connect ($) {
         $c =~ s@(?<=Received )(\d+)@$h{'Number'}$1$h{'Standard'}@;
         $c =~ s@(?<=expecting )(\d+)@$h{'Number'}$1$h{'Standard'}@;
 
-    } elsif ($c =~ m/^Connection from/) {
+    } elsif ($c =~ m/^(Rejecting c|C)onnection from/) {
 
         # Connection from 81.163.28.218 dropped due to ACL
-        $c =~ s@(?<=^Connection from )((?:\d+\.?){4})@$h{'Number'}$1$h{'Standard'}@;
+        # Rejecting connection from 178.63.152.227. Maximum number of connections reached.
+        $c =~ s@(?<=onnection from )((?:\d+\.?){3}\d+)@$h{'Number'}$1$h{'Standard'}@;
 
     } elsif ($c =~ m/^(?:Reusing|Closing) server socket \d./ or
              $c =~ m/^No additional client request/) {
@@ -1622,7 +1624,7 @@ sub handle_loglevel_connect ($) {
         # Waiting for up to 4999 bytes from the client.
         $c =~ s@(?<=up to )(\d+)@$h{'Number'}$1$h{'Standard'}@;
 
-    } elsif ($c =~ m/^Looks like we rea/ or
+    } elsif ($c =~ m/^Looks like we / or
              $c =~ m/^Unsetting keep-alive flag/ or
              $c =~ m/^No connections to wait/ or
              $c =~ m/^Complete client request received/ or
@@ -1637,6 +1639,8 @@ sub handle_loglevel_connect ($) {
         # Looks like we reached the end of the last chunk. We better stop reading.
         # Looks like we read the end of the last chunk together with the server \
         #  headers. We better stop reading.
+        # Looks like we got the last chunk together with the server headers. \
+        #  We better stop reading.
         # Unsetting keep-alive flag.
         # No connections to wait for left.
         # Client request arrived in time or the client closed the connection.
@@ -1687,6 +1691,12 @@ sub handle_loglevel_info ($) {
         # Reloading configuration file '/usr/local/etc/privoxy/config'
         $c =~ s@(?<=loading configuration file \')([^\']*)@$h{'file'}$1$h{'Standard'}@;
 
+    } elsif ($c =~ m/^Loading (actions|filter) file: /) {
+
+        # Loading actions file: /usr/local/etc/privoxy/default.action
+        # Loading filter file: /usr/local/etc/privoxy/default.filter
+        $c =~ s@(?<= file: )(.*)$@$h{'file'}$1$h{'Standard'}@;
+
     } elsif ($c =~ m/^exiting by signal/) {
 
         # exiting by signal 15 .. bye
@@ -1744,7 +1754,8 @@ sub handle_loglevel_info ($) {
              $c =~ m/^Malformerd HTTP headers detected and MS IIS5 hack enabled/ or
              $c =~ m/^Invalid \"chunked\" transfer/ or
              $c =~ m/^Support for/ or
-             $c =~ m/^Flushing header and buffers/
+             $c =~ m/^Flushing header and buffers/ or
+             $c =~ m/^Can not resolve/
              ) {
 
         # No logfile configured. Please enable it before reporting any problems.
@@ -1755,6 +1766,7 @@ sub handle_loglevel_info ($) {
         # Support for 'Connection: keep-alive' is experimental, incomplete and\
         #  known not to work properly in some situations.
         # Flushing header and buffers. Stepping back from filtering.
+        # Can not resolve doesnotexist: hostname nor servname provided, or not known
 
     } else {
 
@@ -1872,8 +1884,7 @@ sub gather_loglevel_error_stats ($$) {
 
 sub gather_loglevel_connect_stats ($$) {
 
-    my $c = shift;
-    my $thread = shift;
+    my ($c, $thread) = @_;
     our %thread_data;
     our %stats;
 
@@ -1905,10 +1916,9 @@ sub gather_loglevel_connect_stats ($$) {
     }
 }
 
-sub gather_loglevel_header_stats ($) {
+sub gather_loglevel_header_stats ($$) {
 
-    my $c = shift;
-    my $thread = shift;
+    my ($c, $thread) = @_;
     our %stats;
 
     if ($c =~ m/^A HTTP\/1\.1 response without/ or
@@ -1917,6 +1927,13 @@ 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{'ressource'}{$3}++;
+        $stats{'http-version'}{$4}++;
     }
 }
 
@@ -1971,6 +1988,23 @@ sub print_stats () {
         $stats{'empty-responses-on-reused-connections'} . " (" .
         get_percentage($stats{requests}, $stats{'empty-responses-on-reused-connections'}) .
         ")\n";
+
+    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;
+    }
+    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;
+    }
+    print "Requested ressources:\n";
+    foreach my $ressource (sort {$stats{'ressource'}{$b} <=> $stats{'ressource'}{$a}} keys %{$stats{'ressource'}}) {
+        printf "%d : %s\n", $stats{'ressource'}{$ressource}, $ressource;
+    }
 }
 
 
@@ -2025,6 +2059,20 @@ sub print_non_clf_message ($) {
         . $line_end;
 }
 
+sub shorten_thread_id ($) {
+
+    my $thread_id = shift;
+
+    our %short_thread_ids;
+    our $max_threadid;
+
+    unless (defined $short_thread_ids{$thread_id}) {
+        $short_thread_ids{$thread_id} = sprintf "%.3d", $max_threadid++;
+    }
+
+    return $short_thread_ids{$thread_id}
+}
+
 sub parse_loop () {
 
     my ($day, $time_stamp, $thread, $log_level, $content, $c, $msecs);
@@ -2050,13 +2098,14 @@ sub parse_loop () {
         'Error'             => \&handle_loglevel_error,
         'Fatal error'       => \&handle_loglevel_ignore,
         'Writing'           => \&handle_loglevel_ignore,
+        'Received'          => \&handle_loglevel_ignore,
         'Unknown log level' => \&handle_loglevel_ignore,
     );
 
     while (<>) {
 
         if (m/^(\w{3} \d{2}) (\d\d:\d\d:\d\d)\.?(\d+)? (?:Privoxy\()?([^\)\s]*)[\)]? ([\w -]*): (.*?)\r?$/) {
-            $thread = $t = $4;
+            $thread = $t = ($shorten_thread_ids) ? shorten_thread_id($4) : $4;
             $req{$t}{'day'} = $day = $1;
             $req{$t}{'time-stamp'} = $time_stamp = $2;
             $req{$t}{'msecs'} = $msecs = $3 ? $3 : 0; # Only the cool kids have micro second resolution;
@@ -2125,7 +2174,7 @@ sub parse_loop () {
 
 sub stats_loop () {
 
-    my ($day, $time_stamp, $thread, $log_level, $content, $c, $msecs);
+    my ($day, $time_stamp, $msecs, $thread, $log_level, $content);
     my %log_level_handlers = (
          'Re-Filter'         => \&handle_loglevel_ignore,
          'Header'            => \&gather_loglevel_header_stats,
@@ -2148,9 +2197,9 @@ sub stats_loop () {
             $day = $1;
             $time_stamp = $2;
             $msecs = $3 ? $3 : 0;
-            $log_level = $5;
-            $content = $c = $6;
             $thread = $4;
+            $log_level = $5;
+            $content = $6;
 
             if (defined($log_level_handlers{$log_level})) {
 
@@ -2172,7 +2221,7 @@ sub VersionMessage {
     my $version_message;
 
     $version_message .= 'Privoxy-Log-Parser ' . PRIVOXY_LOG_PARSER_VERSION  . "\n";
-    $version_message .= 'Copyright (C) 2007-2009 Fabian Keil <fk@fabiankeil.de>' . "\n";
+    $version_message .= 'Copyright (C) 2007-2010 Fabian Keil <fk@fabiankeil.de>' . "\n";
     $version_message .= 'http://www.fabiankeil.de/sourcecode/privoxy-log-parser/' . "\n";
 
     print $version_message;
@@ -2186,6 +2235,7 @@ sub get_cli_options () {
         'no-syntax-highlighting'   => CLI_OPTION_NO_SYNTAX_HIGHLIGHTING,
         'no-embedded-css'          => CLI_OPTION_NO_EMBEDDED_CSS,
         '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,
@@ -2197,6 +2247,7 @@ sub get_cli_options () {
         'no-syntax-highlighting'   => \$cli_options{'no-syntax-highlighting'},
         'no-embedded-css'          => \$cli_options{'no-embedded-css'},
         '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'},
@@ -2206,6 +2257,7 @@ sub get_cli_options () {
 
    $html_output_mode = cli_option_is_set('html-output');
    $no_msecs_mode = cli_option_is_set('no-msecs');
+   $shorten_thread_ids = cli_option_is_set('shorten-thread-ids');
    $line_end = get_line_end();
 }
 
@@ -2223,6 +2275,7 @@ Options and their default values if they have any:
     [--no-embedded-css]
     [--no-msecs]
     [--no-syntax-highlighting]
+    [--shorten-thread-ids]
     [--show-ineffective-filters]
     [--statistics]
     [--title $cli_options{'title'}]
@@ -2262,8 +2315,8 @@ 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<--no-msecs>] [B<--no-syntax-higlighting>] [B<--show-ineffective-filters>]
-[B<--version>]
+[B<--no-msecs>] [B<--no-syntax-higlighting>] [B<--statistics>]
+[B<--shorten-thread-ids>] [B<--show-ineffective-filters>] [B<--version>]
 
 =head1 DESCRIPTION
 
@@ -2302,12 +2355,16 @@ the filtered output is piped into less in which case the ANSI control
 codes don't work, or if the terminal itself doesn't support the control
 codes.
 
+[B<--shorten-thread-ids>] Shorten the thread ids to a three-digit decimal number.
+Note that the mapping from thread ids to shortened ids is created at run-time
+and thus varies with the input.
+
 [B<--show-ineffective-filters>] Don't suppress log lines for filters
 that didn't modify the content.
 
 [B<--statistics>] Gather various statistics instead of syntax highlighting
 log messages. This is an experimental feature, if the results look wrong
-they very well might be. Also note that the results a pretty much guaranteed
+they very well might be. Also note that the results are pretty much guaranteed
 to be incorrect if Privoxy and Privoxy-Log-Parser aren't in sync.
 
 [B<--version>] Print version and exit.