Accept and highlight: Optimistically sending 318 bytes of client headers intended...
[privoxy.git] / tools / privoxy-log-parser.pl
index 482fe74..aa0b626 100755 (executable)
@@ -8,7 +8,7 @@
 #
 # http://www.fabiankeil.de/sourcecode/privoxy-log-parser/
 #
-# $Id: privoxy-log-parser.pl,v 1.128 2012/03/10 11:15:15 fabiankeil Exp $
+# $Id: privoxy-log-parser.pl,v 1.144 2012/10/29 11:59:08 fabiankeil Exp $
 #
 # TODO:
 #       - LOG_LEVEL_CGI, LOG_LEVEL_ERROR, LOG_LEVEL_WRITE content highlighting
@@ -70,7 +70,6 @@ use constant {
     SHOW_FILTER_READIN_IN => 0,
     SUPPRESS_EMPTY_LINES => 1,
     SUPPRESS_SUCCESSFUL_CONNECTIONS => 1,
-    SUPPRESS_ACCEPTED_CONNECTIONS => 1,
     SUPPRESS_GIF_NOT_CHANGED => 1,
     SUPPRESS_NEED_TO_DE_CHUNK_FIRST => 1,
 
@@ -139,6 +138,7 @@ sub prepare_our_stuff () {
         Force           => 'red',
         Writing         => 'light_green',
         Received        => 'yellow',
+        Actions         => 'yellow',
         # ----------------------
         URL                  => 'yellow',
         path                 => 'brown',
@@ -227,7 +227,7 @@ sub paint_it ($) {
 # XXX: The Rolling Stones reference has to go.
 ###############################################################
 
-    my $colour = shift @_;
+    my $colour = shift;
 
     return "" if cli_option_is_set('no-syntax-highlighting');
 
@@ -302,7 +302,7 @@ sub get_semantic_html_markup ($) {
 # Takes a string and returns a span element
 ###############################################################
 
-    my $type = shift @_;
+    my $type = shift;
     my $code;
 
     if ($type =~ /Standard/) {
@@ -475,7 +475,7 @@ sub get_colour_html_markup ($) {
 # markup should always be semantically correct.
 ###############################################################
 
-    my $type = shift @_;
+    my $type = shift;
     my $code;
 
     if ($type =~ /Standard/) {
@@ -914,6 +914,7 @@ sub handle_loglevel_header ($) {
           or $c =~ m/^Continue hack in da house/
           or $c =~ m/^Merged multiple header lines to:/
           or $c =~ m/^Added header: /
+          or $c =~ m/^Enlisting (?:sorted|left-over) header/
             )
     {
         # XXX: Some of these may need highlighting
@@ -962,6 +963,8 @@ sub handle_loglevel_header ($) {
         # Continue hack in da house.
         # Merged multiple header lines to: 'X-FORWARDED-PROTO: http X-HOST: 127.0.0.1'
         # Added header: Content-Encoding: deflate
+        # Enlisting sorted header User-Agent: Mozilla/5.0 (X11; SunOS i86pc; rv:10.0.3) Gecko/20100101 Firefox/10.0.3
+        # Enlisting left-over header Connection: close
 
     } elsif ($c =~ m/^scanning headers for:/) {
 
@@ -1419,14 +1422,31 @@ sub handle_loglevel_connect ($) {
 
         $c = highlight_matched_host($c, '(?<=to )[^\s]+');
 
-    } elsif ($c =~ m/^accepted connection from .*/ or
+    } elsif ($c =~ m/^[Aa]ccepted connection from .*/ or
              $c =~ m/^OK/) {
 
-        # accepted connection from 10.0.0.1
+        # Privoxy 3.0.20:
+        # Accepted connection from 10.0.0.1 on socket 5
+        # Privoxy between 3.0.20 and 3.0.6:
+        # accepted connection from 10.0.0.1( on socket 5)?
         # Privoxy 3.0.6 and earlier just say:
         # OK
-        return '' if SUPPRESS_ACCEPTED_CONNECTIONS;
-        $c = highlight_matched_host($c, '(?<=connection from ).*');
+        $c = highlight_matched_host($c, '(?<=connection from )[^ ]*');
+        $c = highlight_matched_pattern($c, 'Number', '(?<=socket )\d+');
+
+    } elsif ($c =~ m/^Closing client socket/) {
+
+        # Closing client socket 5. Keep-alive: 0, Socket alive: 1. Data available: 0.
+        # Privoxy 3.0.20 and later
+        # Closing client socket 8. Keep-alive: 1. Socket alive: 0. Data available: 0. \
+        #  Configuration file change detected: 0. Requests received: 11.
+
+        $c = highlight_matched_pattern($c, 'Number', '(?<=socket )\d+');
+        $c = highlight_matched_pattern($c, 'Number', '(?<=Keep-alive: )\d+');
+        $c = highlight_matched_pattern($c, 'Number', '(?<=Socket alive: )\d+');
+        $c = highlight_matched_pattern($c, 'Number', '(?<=available: )\d+');
+        $c = highlight_matched_pattern($c, 'Number', '(?<=detected: )\d+');
+        $c = highlight_matched_pattern($c, 'Number', '(?<=received: )\d+');
 
     } elsif ($c =~ m/^write header to: .* failed:/) {
 
@@ -1531,10 +1551,17 @@ sub handle_loglevel_connect ($) {
         $c =~ s@(?<=Timeout is: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
         $c =~ s@(?<=Assumed latency: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
 
-    } elsif ($c =~ m/^Stopped waiting for the request line./) {
+    } elsif ($c =~ m/^Stopped waiting for the request line/ or
+             $c =~ m/^No request line on socket \d received in time/ or
+             $c =~ m/^The client side of the connection on socket \d/) {
 
         # Stopped waiting for the request line. Timeout: 121.
+        # Privoxy 3.0.19 and later:
+        # No request line on socket 5 received in time. Timeout: 1.
+        # The client side of the connection on socket 5 got closed \
+        #  without sending a complete request line.
         $c =~ s@(?<=Timeout: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+        $c =~ s@(?<=socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
 
     } elsif ($c =~ m/^Waiting for \d/) {
 
@@ -1559,15 +1586,18 @@ sub handle_loglevel_connect ($) {
         $c =~ s@(?<=received: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
         $c =~ s@(?<=read: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
 
-    } elsif ($c =~ m/^Continuing buffering headers/) {
+    } elsif ($c =~ m/^Continuing buffering (?:server )?headers/) {
 
         # Continuing buffering headers. byte_count: 19. header_offset: 517. len: 536.
         $c =~ s@(?<=byte_count: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
         $c =~ s@(?<=header_offset: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
         $c =~ s@(?<=len: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
-        # 3.0.15 and later:
-        # Continuing buffering headers. Bytes most recently read: %d.
+        # 3.0.15 up to 3.0.19:
+        # Continuing buffering headers. Bytes most recently read: 498.
         $c =~ s@(?<=read: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+        # 3.0.20 and later:
+        # Continuing buffering server headers from socket 5. Bytes most recently read: 498.
+        $c =~ s@(?<=socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
 
     } elsif ($c =~ m/^Received \d+ bytes while/) {
 
@@ -1581,7 +1611,7 @@ sub handle_loglevel_connect ($) {
         # 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
+    } elsif ($c =~ m/^(?:Reusing|Closing) server socket / or
              $c =~ m/^No additional client request/) {
 
         # Reusing server socket 4. Opened for 10.0.0.1.
@@ -1589,9 +1619,17 @@ sub handle_loglevel_connect ($) {
         # No additional client request received in time. \
         #  Closing server socket 4, initially opened for 10.0.0.1.
         # No additional client request received in time on socket 29.
+        # Privoxy 3.0.20 and later
+        # Reusing server socket 7 connected to www.privoxy.org. Total requests: 2.
+        # Closing server socket 6 connected to d.asset.soup.io. Keep-alive: 0.\
+        #  Tainted: 1. Socket alive: 1. Timeout: 60. Configuration file change detected: 0.
 
         $c =~ s@(?<= socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
-        $c = highlight_matched_host($c, '(?<=for )[^\s]+(?=\.$)');
+        $c = highlight_matched_host($c, '(?<=for )[^\s]+(?=\.)');
+        $c = highlight_matched_host($c, '(?<=connected to )[^\s]+(?=\.)');
+        for my $number_pattern ('requests', 'Keep-alive', 'Tainted', ' alive', 'Timeout', 'detected') {
+            $c = highlight_matched_pattern($c, 'Number', '(?<='. $number_pattern . ': )\d+');
+        }
 
     } elsif ($c =~ m/^Connected to /) {
 
@@ -1610,16 +1648,19 @@ sub handle_loglevel_connect ($) {
 
     } elsif ($c =~ m/^Waiting for the next client request/ or
              $c =~ m/^The connection on server socket/ or
-             $c =~ m/^Client request arrived in time /) {
+             $c =~ m/^Client request (?:\d+ )?arrived in time /) {
 
         # Waiting for the next client request on socket 3. Keeping the server \
         #  socket 12 to a.fsdn.com open.
         # The connection on server socket 6 to upload.wikimedia.org isn't reusable. Closing.
-        # Used by Privoxy 3.0.18 and later:
+        # Privoxy 3.0.20 and later:
+        # Client request 4 arrived in time on socket 7.
+        # Used by Privoxy 3.0.18 and 3.0.19:
         # Client request arrived in time on socket 21.
         # Used by earlier version:
         # Client request arrived in time or the client closed the connection on socket 12.
 
+        $c =~ s@(?<=request )(\d+)@$h{'Number'}$1$h{'Standard'}@;
         $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, '(?<=to )[^\s]+');
@@ -1659,6 +1700,12 @@ 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/^Optimistically sending /) {
+
+        # Optimistically sending 318 bytes of client headers intended for www.privoxy.org
+        $c =~ s@(?<=sending )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+        $c = highlight_matched_host($c, '(?<=for )[^\s]+');
+
     } elsif ($c =~ m/^Stopping to watch the client socket/) {
 
         # Stopping to watch the client socket. There's already another request waiting.
@@ -1666,6 +1713,17 @@ sub handle_loglevel_connect ($) {
         # Stopping to watch the client socket 5. There's already another request waiting.
         $c =~ s@(?<=client socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
 
+    } elsif ($c =~ m/^Drained \d+ bytes before closing/) {
+
+        # Drained 180 bytes before closing socket 6
+        $c =~ s@(?<=Drained )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+        $c =~ s@(?<=socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+
+    } elsif ($c =~ m/^Tainting client socket/) {
+
+        # Tainting client socket 7 due to unread data.
+        $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
@@ -2031,7 +2089,15 @@ sub init_stats () {
 sub get_percentage ($$) {
     my $big = shift;
     my $small = shift;
+
+    # If small is 0 the percentage is always 0%.
+    # Make sure it works even if big is 0 as well.
+    return "0.00%" if ($small eq 0);
+
+    # Prevent division by zero.
+    # XXX: Is this still supposed to be reachable?
     return "NaN" if ($big eq 0);
+
     return sprintf("%.2f%%", $small / $big * 100);
 }
 
@@ -2145,7 +2211,7 @@ sub print_clf_message () {
 sub print_non_clf_message ($) {
 
     my $content = shift;
-    my $msec_string = "." . $req{$t}{'msecs'} unless $no_msecs_mode;
+    my $msec_string = $no_msecs_mode ? '' : '.' . $req{$t}{'msecs'};
     my $line_start = $html_output_mode ? '' : $h{"Standard"};
 
     return if DEBUG_SUPPRESS_LOG_MESSAGES;
@@ -2207,6 +2273,7 @@ sub parse_loop () {
         'Fatal error'       => \&handle_loglevel_ignore,
         'Writing'           => \&handle_loglevel_ignore,
         'Received'          => \&handle_loglevel_ignore,
+        'Actions'           => \&handle_loglevel_ignore,
         'Unknown log level' => \&handle_loglevel_ignore,
     );
 
@@ -2298,6 +2365,7 @@ sub stats_loop () {
          'Fatal error'       => \&handle_loglevel_ignore,
          'Writing'           => \&handle_loglevel_ignore,
          'Received'          => \&handle_loglevel_ignore,
+         'Actions'           => \&handle_loglevel_ignore,
          'Unknown log level' => \&handle_loglevel_ignore
     );