X-Git-Url: http://www.privoxy.org/gitweb/?a=blobdiff_plain;f=tools%2Fprivoxy-log-parser.pl;h=d0851f55c6e2d1ab1f58488aff533a3fa4234ed2;hb=f1e6c169ab2e79df35ffc7299e67566b3b48ba7b;hp=d7c3dcb83537e37479adbaf0cc1ef943ec82e4a8;hpb=ee0914cfd79f008738c6abe482435a85c6bf7e9c;p=privoxy.git diff --git a/tools/privoxy-log-parser.pl b/tools/privoxy-log-parser.pl index d7c3dcb8..d0851f55 100755 --- a/tools/privoxy-log-parser.pl +++ b/tools/privoxy-log-parser.pl @@ -8,7 +8,7 @@ # # http://www.fabiankeil.de/sourcecode/privoxy-log-parser/ # -# $Id: privoxy-log-parser.pl,v 1.120 2008/11/04 17:33:28 fk Exp $ +# $Id: privoxy-log-parser.pl,v 1.55 2009/10/08 11:47:12 fabiankeil Exp $ # # TODO: # - LOG_LEVEL_CGI, LOG_LEVEL_ERROR, LOG_LEVEL_WRITE content highlighting @@ -24,7 +24,7 @@ # - Use generic highlighting function that takes a regex and the # hash key as input. # -# Copyright (c) 2007-2008 Fabian Keil +# Copyright (c) 2007-2009 Fabian Keil # # Permission to use, copy, modify, and distribute this software for any # purpose with or without fee is hereby granted, provided that the above @@ -44,7 +44,7 @@ use warnings; use Getopt::Long; use constant { - PRIVOXY_LOG_PARSER_VERSION => '0.4', + PRIVOXY_LOG_PARSER_VERSION => '0.5', # 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 +59,7 @@ use constant { CLI_OPTION_ERROR_LOG_FILE => '/var/log/privoxy-log.log', CLI_OPTION_SHOW_INEFFECTIVE_FILTERS => 0, CLI_OPTION_ACCEPT_UNKNOWN_MESSAGES => 0, - CLI_OPTION_STATISTIC => 0, + CLI_OPTION_STATISTICS => 0, SUPPRESS_SUCCEEDED_FILTER_ADDITIONS => 1, SHOW_SCAN_INTRO => 0, @@ -106,6 +106,7 @@ sub prepare_our_stuff () { CGI => 'light_green', Redirect => 'cyan', Error => 'light_red', + Crunch => 'cyan', 'Fatal error' => 'light_red', 'Gif-Deanimate' => 'blue', Force => 'red', @@ -186,6 +187,8 @@ sub prepare_our_stuff () { prepare_colour_array(\@all_colours); prepare_colour_array(\@time_colours); init_css_colours(); + + init_stats(); } sub paint_it ($) { @@ -265,7 +268,6 @@ sub paint_it ($) { return $colour_code; } - sub get_semantic_html_markup ($) { ############################################################### # Takes a string and returns a span element @@ -370,7 +372,7 @@ sub get_missing_css_lines () { my $css_line; - $css_line .= '.' . 'default' . ' {'; # XXX: lc() shouldn't be necessary + $css_line .= '.' . 'default' . ' {'; $css_line .= 'color:' . HEADER_DEFAULT_COLOUR . ';'; $css_line .= 'background-color:' . get_css_colour(DEFAULT_BACKGROUND) . ';'; $css_line .= '}' . "\n"; @@ -438,7 +440,6 @@ sub print_outro () { } } - sub get_line_end () { my $line_end = "\n"; @@ -467,7 +468,6 @@ sub get_colour_html_markup ($) { return $code; } - sub default_colours () { # XXX: Properly our $bg_code; @@ -752,7 +752,6 @@ sub highlight_matched_pattern ($$$) { return $result; } - sub highlight_matched_path ($$) { my $result = shift; # XXX: Stupid name; @@ -765,7 +764,6 @@ sub highlight_matched_path ($$) { return $result; } - sub highlight_url ($) { my $url = shift; @@ -803,7 +801,7 @@ sub handle_loglevel_header ($) { # scan: Accept: image/png,image/*;q=0.8,*/*;q=0.5 if ($c =~ m/^scan: ((?>[^:]+)):/) { my $header = $1; - if (!defined($header_colours{$header})) { + if (!defined($header_colours{$header}) and $header =~ /^[\d\w-]*$/) { debug_message "Registering previously unknown header $1" if DEBUG_HEADER_REGISTERING; if (REGISTER_HEADERS_WITH_THE_SAME_COLOUR) { @@ -915,6 +913,11 @@ sub handle_loglevel_header ($) { or $c =~ m/^Ignoring single quote in / or $c =~ m/^Converting tab to space in / or $c =~ m/A HTTP\/1\.1 response without/ + or $c =~ m/Disabled filter mode on behalf of the client/ + or $c =~ m/Keeping the (?:server|client) header / + or $c =~ m/Content modified with no Content-Length header set/ + or $c =~ m/^Appended client IP address to/ + or $c =~ m/^Removing 'Connection: close' to imply keep-alive./ ) { # XXX: Some of these may need highlighting @@ -952,6 +955,13 @@ sub handle_loglevel_header ($) { # Converting tab to space in 'X-LWS-Test: "This is quoted" this is not "this is " but "\ # this again is not' # A HTTP/1.1 response without Connection header implies keep-alive. + # Disabled filter mode on behalf of the client. + # Keeping the server header 'Connection: keep-alive' around. + # Keeping the client header 'Connection: close' around. The connection will not be kept alive. + # Keeping the client header 'Connection: keep-alive' around. The connection will be kept alive if possible. + # Content modified with no Content-Length header set. Creating a fake one for adjustment later on. + # Appended client IP address to X-Forwarded-For: 10.0.0.2, 10.0.0.1 + # Removing 'Connection: close' to imply keep-alive. } elsif ($c =~ m/^scanning headers for:/) { @@ -989,6 +999,21 @@ sub handle_loglevel_header ($) { # XXX: Could highlight more here. $content =~ s@(?<=^Content-Type: )(.*)(?= not replaced)@$h{'content-type'}$1$h{'Standard'}@; + } elsif ($c =~ m/^(Server|Client) keep-alive timeout is/) { + + # Server keep-alive timeout is 5. Sticking with 10. + # Client keep-alive timeout is 20. Sticking with 10. + + $content =~ s@(?<=timeout is )(\d+)@$h{'Number'}$1$h{'Standard'}@; + $content =~ s@(?<=Sticking with )(\d+)@$h{'Number'}$1$h{'Standard'}@; + + } elsif ($c =~ m/^Reducing keep-alive timeout/) { + + # Reducing keep-alive timeout from 60 to 10. + + $content =~ s@(?<= from )(\d+)@$h{'Number'}$1$h{'Standard'}@; + $content =~ s@(?<= to )(\d+)@$h{'Number'}$1$h{'Standard'}@; + } else { found_unknown_content($content); @@ -1183,7 +1208,6 @@ sub handle_loglevel_re_filter ($) { return $content; } - sub handle_loglevel_redirect ($) { my $c = shift; @@ -1292,7 +1316,6 @@ sub handle_loglevel_gif_deanimate ($) { return $content; } - sub handle_loglevel_request ($) { my $content = shift; @@ -1332,6 +1355,32 @@ sub handle_loglevel_request ($) { return $content; } +sub handle_loglevel_crunch ($) { + + my $content = shift; + our %h; + our %reason_colours; + + # Highlight crunch reason + foreach my $reason (keys %reason_colours) { + $content =~ s@($reason)@$reason_colours{$reason}$1$h{'Standard'}@g; + } + + if ($content =~ m/\[too long, truncated\]$/) { + + # Blocked: config.privoxy.org/edit-actions-submit?f=3&v=1176116716&s=7&Submit=Submit\ + # [...]&filter... [too long, truncated] + $content = highlight_matched_pattern($content, 'request_', '^.*(?=\.\.\. \[too long, truncated\]$)'); + + } else { + + # Blocked: http://ads.example.org/ + $content = highlight_matched_pattern($content, 'request_', '(?<=: ).*'); + } + + return $content; +} + sub handle_loglevel_connect ($) { my $c = shift; @@ -1339,14 +1388,14 @@ sub handle_loglevel_connect ($) { our %req; our %h; - if ($c =~ m/via [^\s]+ to: [^\s]+/) { + if ($c =~ m/^via [^\s]+ to: [^\s]+/) { # Connect: via 10.0.0.1:8123 to: www.example.org.noconnect $c = highlight_matched_host($c, '(?<=via )[^\s]+'); $c = highlight_matched_host($c, '(?<=to: )[^\s]+'); - } elsif ($c =~ m/connect to: .* failed: .*/) { + } elsif ($c =~ m/^connect to: .* failed: .*/) { # connect to: www.example.org.noconnect failed: Operation not permitted @@ -1354,14 +1403,15 @@ sub handle_loglevel_connect ($) { $c =~ s@(?<=failed: )(.*)@$h{'error'}$1$h{'Standard'}@; - } elsif ($c =~ m/to ([^\s]*) successful$/) { + } elsif ($c =~ m/^to ([^\s]*)( successful)?$/) { # Connect: to www.nzherald.co.nz successful + # Connect: to archiv.radiotux.de return '' if SUPPRESS_SUCCESSFUL_CONNECTIONS; $c = highlight_matched_host($c, '(?<=to )[^\s]+'); - } elsif ($c =~ m/to ([^\s]*)$/) { + } elsif ($c =~ m/^to ([^\s]*)$/) { # Connect: to lists.sourceforge.net:443 @@ -1421,12 +1471,24 @@ sub handle_loglevel_connect ($) { $c =~ s@(?<=socks5_connect: )(.*)@$h{'error'}$1$h{'Standard'}@; + } elsif ($c =~ m/^Created new connection to/) { + + # Created new connection to www.privoxy.org:80 on socket 11. + $c = highlight_matched_host($c, '(?<=connection to )[^\s]+'); + $c =~ s@(?<=on socket )(\d+)@$h{'Number'}$1$h{'Standard'}@; + } elsif ($c =~ m/^Found reusable socket/) { # Found reusable socket 9 for www.privoxy.org:80 in slot 0. + # 3.0.15 and later: + # Found reusable socket 8 for www.privoxy.org:80 in slot 2.\ + # Timestamp made 0 seconds ago. Timeout: 1. Latency: 0. $c =~ s@(?<=Found reusable socket )(\d+)@$h{'Number'}$1$h{'Standard'}@; $c = highlight_matched_host($c, '(?<=for )[^\s]+'); $c =~ s@(?<=in slot )(\d+)@$h{'Number'}$1$h{'Standard'}@; + $c =~ s@(?<=made )(\d+)@$h{'Number'}$1$h{'Standard'}@; + $c =~ s@(?<=Timeout: )(\d+)@$h{'Number'}$1$h{'Standard'}@; + $c =~ s@(?<=Latency: )(\d+)@$h{'Number'}$1$h{'Standard'}@; } elsif ($c =~ m/^Marking open socket/) { @@ -1444,23 +1506,38 @@ sub handle_loglevel_connect ($) { # Remembering socket 13 for www.privoxy.org:80 in slot 0. # Forgetting socket 38 for www.privoxy.org:80 in slot 5. + $c =~ s@(?<=socket )(\d+)@$h{'Number'}$1$h{'Standard'}@; $c = highlight_matched_host($c, '(?<=for )[^\s]+'); $c =~ s@(?<=in slot )(\d+)@$h{'Number'}$1$h{'Standard'}@; } elsif ($c =~ m/^Socket/) { - # Socket 18 for www.privoxy.org:80 in slot 0 is no longer usable. Closing. # Socket 16 already forgotten or never remembered. $c =~ s@(?<=Socket )(\d+)@$h{'Number'}$1$h{'Standard'}@; - $c = highlight_matched_host($c, '(?<=for )[^\s]+'); - $c =~ s@(?<=in slot )(\d+)@$h{'Number'}$1$h{'Standard'}@; } elsif ($c =~ m/^The connection to/) { - # The connection to www.privoxy.org:80 in slot 0 timed out. Closing. + # The connection to www.privoxy.org:80 in slot 6 timed out. Closing socket 19. Timeout is: 61. + # 3.0.15 and later: + # The connection to 1.bp.blogspot.com:80 in slot 0 timed out. Closing socket 5.\ + # Timeout is: 1. Assumed latency: 4. + # The connection to 10.0.0.1:80 in slot 0 is no longer usable. Closing socket 4. $c = highlight_matched_host($c, '(?<=connection to )[^\s]+'); $c =~ s@(?<=in slot )(\d+)@$h{'Number'}$1$h{'Standard'}@; + $c =~ s@(?<=Closing socket )(\d+)@$h{'Number'}$1$h{'Standard'}@; + $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./) { + + # Stopped waiting for the request line. Timeout: 121. + $c =~ s@(?<=Timeout: )(\d+)@$h{'Number'}$1$h{'Standard'}@; + + } elsif ($c =~ m/^Waiting for \d/) { + + # Waiting for 1 connections to timeout. + $c =~ s@(?<=^Waiting for )(\d+)@$h{'Number'}$1$h{'Standard'}@; } elsif ($c =~ m/^Initialized/) { @@ -1471,15 +1548,115 @@ sub handle_loglevel_connect ($) { # Done reading from server. Expected content length: 24892. \ # Actual content length: 24892. Most recently received: 4412. - $c =~ s@(?<=Expected content length: )(\d+)@$h{'Number'}$1$h{'Standard'}@; - $c =~ s@(?<=Actual content length: )(\d+)@$h{'Number'}$1$h{'Standard'}@; + # 3.0.15 and later: + # Done reading from server. Expected content length: 24892. \ + # Actual content length: 24892. Bytes most recently read: 4412. + # Done reading from server. Content length: 6018 as expected. \ + # Bytes most recently read: 294. + $c =~ s@(?<=ontent length: )(\d+)@$h{'Number'}$1$h{'Standard'}@g; $c =~ s@(?<=received: )(\d+)@$h{'Number'}$1$h{'Standard'}@; + $c =~ s@(?<=read: )(\d+)@$h{'Number'}$1$h{'Standard'}@; - } elsif ($c =~ m/^Looks like we reached/ or - $c =~ m/^Unsetting keep-alive flag/) { + } elsif ($c =~ m/^Continuing buffering 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. + $c =~ s@(?<=read: )(\d+)@$h{'Number'}$1$h{'Standard'}@; + + } elsif ($c =~ m/^Received \d+ bytes while/) { + + # Received 206 bytes while expecting 12103. + $c =~ s@(?<=Received )(\d+)@$h{'Number'}$1$h{'Standard'}@; + $c =~ s@(?<=expecting )(\d+)@$h{'Number'}$1$h{'Standard'}@; + + } elsif ($c =~ m/^Connection from/) { + + # Connection from 81.163.28.218 dropped due to ACL + $c =~ s@(?<=^Connection from )((?:\d+\.?){4})@$h{'Number'}$1$h{'Standard'}@; + + } elsif ($c =~ m/^(?:Reusing|Closing) server socket \d./ or + $c =~ m/^No additional client request/) { + + # Reusing server socket 4. Opened for 10.0.0.1. + # Closing server socket 2. Opened for 10.0.0.1. + # No additional client request received in time. \ + # Closing server socket 4, initially opened for 10.0.0.1. + + $c =~ s@(?<=server socket )(\d+)@$h{'Number'}$1$h{'Standard'}@; + $c = highlight_matched_host($c, '(?<=for )[^\s]+(?=\.$)'); + + } elsif ($c =~ m/^Connected to /) { + + # Connected to tor-jail[10.0.0.2]:9050. + + $c = highlight_matched_host($c, '(?<=\[)[^\]]+'); + $c = highlight_matched_host($c, '(?<=Connected to )[^\[\s]+'); + $c =~ s@(?<=\]:)(\d+)@$h{'Number'}$1$h{'Standard'}@; + + } elsif ($c =~ m/^Could not connect to /) { + + # Could not connect to [10.0.0.1]:80. + + $c = highlight_matched_host($c, '(?<=\[)[^\]]+'); + $c =~ s@(?<=\]:)(\d+)@$h{'Number'}$1$h{'Standard'}@; + + } elsif ($c =~ m/^Waiting for the next client request/ or + $c =~ m/^The connection on server socket/ ) { + + # Waiting for the next client request. Keeping the server socket 5 to 10.0.0.1 open. + # The connection on server socket 6 to upload.wikimedia.org isn't reusable. Closing. + + $c =~ s@(?<=server socket )(\d+)@$h{'Number'}$1$h{'Standard'}@; + $c = highlight_matched_host($c, '(?<=to )[^\s]+'); + + } elsif ($c =~ m/^Marking the server socket/) { + + # Marking the server socket 7 tainted. + + $c =~ s@(?<=server socket )(\d+)@$h{'Number'}$1$h{'Standard'}@; + + } elsif ($c =~ m/^Reduced expected bytes to /) { + + # Reduced expected bytes to 0 to account for the 1542 ones we already got. + $c =~ s@(?<=bytes to )(\d+)@$h{'Number'}$1$h{'Standard'}@; + $c =~ s@(?<=for the )(\d+)@$h{'Number'}$1$h{'Standard'}@; + + } elsif ($c =~ m/^The client closed socket /) { + + # The client closed socket 2 while the server socket 4 is still open. + $c =~ s@(?<=closed socket )(\d+)@$h{'Number'}$1$h{'Standard'}@; + $c =~ s@(?<=server socket )(\d+)@$h{'Number'}$1$h{'Standard'}@; + + } elsif ($c =~ m/^Looks like we rea/ or + $c =~ m/^Unsetting keep-alive flag/ or + $c =~ m/^No connections to wait/ or + $c =~ m/^Client request arrived in time or the client closed the connection/ or + $c =~ m/^Complete client request received/ or + $c =~ m/^Possible pipeline attempt detected./ or + $c =~ m/^POST request detected. The connection will not be kept alive./ or + $c =~ m/^The server still wants to talk, but the client hung up on us./ or + $c =~ m/^The server didn't specify how long the connection will stay open/ or + $c =~ m/^There might be a request body. The connection will not be kept alive/ or + $c =~ m/^Stopping to watch the client socket. There's already another request waiting./) { # 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. # Unsetting keep-alive flag. + # No connections to wait for left. + # Client request arrived in time or the client closed the connection. + # Complete client request received + # Possible pipeline attempt detected. The connection will not be \ + # kept alive and we will only serve the first request. + # POST request detected. The connection will not be kept alive. + # The server still wants to talk, but the client hung up on us. + # The server didn't specify how long the connection will stay open. Assume it's only a second. + # There might be a request body. The connection will not be kept alive. + # Stopping to watch the client socket. There's already another request waiting. } else { @@ -1568,10 +1745,17 @@ sub handle_loglevel_info ($) { # Method HEAD implies no body. $c =~ s@(?<=Method )([^\s]+)@$h{'method'}$1$h{'Standard'}@; + } elsif ($c =~ m/^Buffer limit reached while extending /) { + + # Buffer limit reached while extending the buffer (iob). Needed: 4197470. Limit: 4194304 + $c =~ s@(?<=Needed: )(\d+)@$h{'Number'}$1$h{'Standard'}@; + $c =~ s@(?<=Limit: )(\d+)@$h{'Number'}$1$h{'Standard'}@; + } elsif ($c =~ m/^No logfile configured/ or $c =~ m/^Malformerd HTTP headers detected and MS IIS5 hack enabled/ or $c =~ m/^Invalid \"chunked\" transfer/ or - $c =~ m/^Support for/ + $c =~ m/^Support for/ or + $c =~ m/^Flushing header and buffers/ ) { # No logfile configured. Please enable it before reporting any problems. @@ -1581,6 +1765,7 @@ sub handle_loglevel_info ($) { # Invalid "chunked" transfer encoding detected and ignored. # 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. } else { @@ -1643,10 +1828,167 @@ sub handle_loglevel_force ($) { return $c; } +sub handle_loglevel_error ($) { + + my $c = shift; + our %h; + + if ($c =~ m/^Empty server or forwarder response received on socket \d+./) { + + # Empty server or forwarder response received on socket 4. + $c =~ s@(?<=on socket )(\d+)@$h{'Number'}$1$h{'Standard'}@; + } + # XXX: There are probably more messages that deserve highlighting. + + return $c; +} + + sub handle_loglevel_ignore ($) { return shift; } +sub gather_loglevel_request_stats ($$) { + my $c = shift; + my $thread = shift; + our %stats; + + $stats{requests}++; +} + +sub gather_loglevel_crunch_stats ($$) { + my $c = shift; + my $thread = shift; + our %stats; + + $stats{requests}++; + $stats{crunches}++; +} + + +sub gather_loglevel_error_stats ($$) { + + my $c = shift; + my $thread = shift; + our %stats; + our %thread_data; + + if ($c =~ m/^Empty server or forwarder response received on socket \d+./) { + + # Empty server or forwarder response received on socket 4. + $stats{'empty-responses'}++; + if ($thread_data{$thread}{'new_connection'}) { + $stats{'empty-responses-on-new-connections'}++; + } else { + $stats{'empty-responses-on-reused-connections'}++; + } + } +} + +sub gather_loglevel_connect_stats ($$) { + + my $c = shift; + my $thread = shift; + our %thread_data; + our %stats; + + if ($c =~ m/^via ([^\s]+) to: [^\s]+/) { + + # Connect: via 10.0.0.1:8123 to: www.example.org.noconnect + $thread_data{$thread}{'forwarder'} = $1; # XXX: is this missue? + + } elsif ($c =~ m/^to ([^\s]*)$/) { + + # Connect: to lists.sourceforge.net:443 + + $thread_data{$thread}{'forwarder'} = 'direct connection'; + + } elsif ($c =~ m/^Created new connection to/) { + + # Created new connection to www.privoxy.org:80 on socket 11. + + $thread_data{$thread}{'new_connection'} = 1; + + } elsif ($c =~ m/^Reusing server socket \d./ or + $c =~ m/^Found reusable socket/) { + + # Reusing server socket 4. Opened for 10.0.0.1. + # Found reusable socket 9 for www.privoxy.org:80 in slot 0. + + $thread_data{$thread}{'new_connection'} = 0; + $stats{'reused-connections'}++; + } +} + +sub gather_loglevel_header_stats ($) { + + my $c = shift; + my $thread = shift; + our %stats; + + if ($c =~ m/^A HTTP\/1\.1 response without/ or + $c =~ m/^Keeping the server header 'Connection: keep-alive' around./) + { + # A HTTP/1.1 response without Connection header implies keep-alive. + # Keeping the server header 'Connection: keep-alive' around. + $stats{'server-keep-alive'}++; + } +} + +sub init_stats () { + our %stats = ( + requests => 0, + crunches => 0, + 'server-keep-alive' => 0, + 'reused-connections' => 0, + 'empty-responses' => 0, + 'empty-responses-on-new-connections' => 0, + 'empty-responses-on-reused-connections' => 0, + ); +} + +sub get_percentage ($$) { + my $big = shift; + my $small = shift; + return "NaN" if ($big eq 0); + return sprintf("%.2f%%", $small / $big * 100); +} + +sub print_stats () { + + our %stats; + my $new_connections = $stats{requests} - $stats{crunches} - $stats{'reused-connections'}; + my $outgoing_requests = $stats{requests} - $stats{crunches}; + + if ($stats{requests} eq 0) { + print "No requests yet.\n"; + return; + } + + print "Client requests total: " . $stats{requests} . "\n"; + print "Crunches: " . $stats{crunches} . " (" . + get_percentage($stats{requests}, $stats{crunches}) . ")\n"; + print "Outgoing requests: " . $outgoing_requests . " (" . + get_percentage($stats{requests}, $outgoing_requests) . ")\n"; + print "Server keep-alive offers: " . $stats{'server-keep-alive'} . " (" . + get_percentage($stats{requests}, $stats{'server-keep-alive'}) . ")\n"; + print "New outgoing connections: " . $new_connections . " (" . + get_percentage($stats{requests}, $new_connections) . ")\n"; + print "Reused connections: " . $stats{'reused-connections'} . " (" . + get_percentage($stats{requests}, $stats{'reused-connections'}) . ")\n"; + print "Empty responses: " . $stats{'empty-responses'} . " (" . + get_percentage($stats{requests}, $stats{'empty-responses'}) . ")\n"; + print "Empty responses on new connections: " + . $stats{'empty-responses-on-new-connections'} . " (" . + get_percentage($stats{requests}, $stats{'empty-responses-on-new-connections'}) + . ")\n"; + print "Empty responses on reused connections: " . + $stats{'empty-responses-on-reused-connections'} . " (" . + get_percentage($stats{requests}, $stats{'empty-responses-on-reused-connections'}) . + ")\n"; +} + + ################################################################################ # Functions that actually print stuff ################################################################################ @@ -1731,28 +2073,29 @@ sub parse_loop () { my $time_colour; our $no_special_header_highlighting; $time_colour = paint_it('white'); - my %log_level_count; my %log_level_handlers = ( - 'Re-Filter' => \&handle_loglevel_re_filter, - 'Header' => \&handle_loglevel_header, - 'Connect' => \&handle_loglevel_connect, - 'Redirect' => \&handle_loglevel_redirect, - 'Request' => \&handle_loglevel_request, - 'Gif-Deanimate' => \&handle_loglevel_gif_deanimate, - 'Info' => \&handle_loglevel_info, - 'CGI' => \&handle_loglevel_cgi, - 'Force' => \&handle_loglevel_force, - 'Error' => \&handle_loglevel_ignore, - 'Fatal error' => \&handle_loglevel_ignore, - 'Writing' => \&handle_loglevel_ignore, + 'Re-Filter' => \&handle_loglevel_re_filter, + 'Header' => \&handle_loglevel_header, + 'Connect' => \&handle_loglevel_connect, + 'Redirect' => \&handle_loglevel_redirect, + 'Request' => \&handle_loglevel_request, + 'Crunch' => \&handle_loglevel_crunch, + 'Gif-Deanimate' => \&handle_loglevel_gif_deanimate, + 'Info' => \&handle_loglevel_info, + 'CGI' => \&handle_loglevel_cgi, + 'Force' => \&handle_loglevel_force, + 'Error' => \&handle_loglevel_error, + 'Fatal error' => \&handle_loglevel_ignore, + 'Writing' => \&handle_loglevel_ignore, + 'Unknown log level' => \&handle_loglevel_ignore, ); while (<>) { $output = ''; - if (m/^(\w{3} \d{2}) (\d\d:\d\d:\d\d)\.?(\d+)? (?:Privoxy\(([^\)]*)\)) ([\w -]*): (.*)$/) { + if (m/^(\w{3} \d{2}) (\d\d:\d\d:\d\d)\.?(\d+)? (?:Privoxy\()?([^\)\s]*)[\)]? ([\w -]*): (.*?)\r?$/) { # XXX: Put in req hash? $day = $1; $time_stamp = $2; @@ -1769,8 +2112,6 @@ sub parse_loop () { $req{$t}{'log-message'} = $_; $no_special_header_highlighting = 0; - $log_level_count{$log_level}++; - if (defined($log_level_handlers{$log_level})) { $content = $log_level_handlers{$log_level}($content); @@ -1807,7 +2148,7 @@ sub parse_loop () { print_non_clf_message($content); - } elsif (m/^(\d+\.\d+\.\d+\.\d+) - - \[(.*)\] "(.*)" (\d+) (\d+)/) { + } elsif (m/^((?:\d+\.\d+\.\d+\.\d+|[:\d]+)) - - \[(.*)\] "(.*)" (\d+) (\d+)/) { # LOG_LEVEL_CLF lines look like this # 61.152.239.32 - - [04/Mar/2007:18:28:23 +0100] "GET \ @@ -1828,19 +2169,58 @@ sub parse_loop () { } } } +} + +sub stats_loop () { + + my ($day, $time_stamp, $thread, $log_level, $content, $c, $msecs); + my %log_level_handlers = ( + 'Re-Filter' => \&handle_loglevel_ignore, + 'Header' => \&gather_loglevel_header_stats, + 'Connect' => \&gather_loglevel_connect_stats, + 'Redirect' => \&handle_loglevel_ignore, + 'Request' => \&gather_loglevel_request_stats, + 'Crunch' => \&gather_loglevel_crunch_stats, + 'Gif-Deanimate' => \&handle_loglevel_ignore, + 'Info' => \&handle_loglevel_ignore, + 'CGI' => \&handle_loglevel_ignore, + 'Force' => \&handle_loglevel_ignore, + 'Error' => \&gather_loglevel_error_stats, + 'Fatal error' => \&handle_loglevel_ignore, + 'Writing' => \&handle_loglevel_ignore, + 'Unknown log level' => \&handle_loglevel_ignore + ); - if (cli_option_is_set('statistic')) { - foreach (keys %log_level_count) { - print $_ . ": " . $log_level_count{$_} . " "; + while (<>) { + if (m/^(\w{3} \d{2}) (\d\d:\d\d:\d\d)\.?(\d+)? (?:Privoxy\()?([^\)\s]*)[\)]? ([\w -]*): (.*?)\r?$/) { + $day = $1; + $time_stamp = $2; + $msecs = $3 ? $3 : 0; + $log_level = $5; + $content = $c = $6; + $thread = $4; + + if (defined($log_level_handlers{$log_level})) { + + $content = $log_level_handlers{$log_level}($content, $thread); + + } else { + + die "No handler found for log level \"$log_level\"\n"; + + } } } + + print_stats(); + } sub VersionMessage { my $version_message; $version_message .= 'Privoxy-Log-Parser ' . PRIVOXY_LOG_PARSER_VERSION . "\n"; - $version_message .= 'Copyright (C) 2007-2008 Fabian Keil ' . "\n"; + $version_message .= 'Copyright (C) 2007-2009 Fabian Keil ' . "\n"; $version_message .= 'http://www.fabiankeil.de/sourcecode/privoxy-log-parser/' . "\n"; print $version_message; @@ -1856,7 +2236,7 @@ sub get_cli_options () { 'no-msecs' => CLI_OPTION_NO_MSECS, 'show-ineffective-filters' => CLI_OPTION_SHOW_INEFFECTIVE_FILTERS, 'accept-unknown-messages' => CLI_OPTION_ACCEPT_UNKNOWN_MESSAGES, - 'statistic' => CLI_OPTION_STATISTIC, + 'statistics' => CLI_OPTION_STATISTICS, ); GetOptions ( @@ -1867,12 +2247,35 @@ sub get_cli_options () { 'no-msecs' => \$cli_options{'no-msecs'}, 'show-ineffective-filters' => \$cli_options{'show-ineffective-filters'}, 'accept-unknown-messages' => \$cli_options{'accept-unknown-messages'}, - 'statistic' => \$cli_options{'statistic'}, - 'version' => sub { VersionMessage && exit(0) } + 'statistics' => \$cli_options{'statistics'}, + 'version' => sub { VersionMessage && exit(0) }, + 'help' => \&help, ); } +sub help () { + + our %cli_options; + VersionMessage(); + + print << " EOF" + +Options and their default values if they have any: + [--accept-unknown-messages] + [--html-output] + [--no-embedded-css] + [--no-msecs] + [--no-syntax-highlighting] + [--show-ineffective-filters] + [--statistics] + [--title $cli_options{'title'}] + [--version] +see "perldoc $0" for more information + EOF + ; + exit(0); +} ################################################################################ # main @@ -1885,7 +2288,11 @@ sub main () { print_intro(); - parse_loop(); + if (cli_option_is_set('statistics')) { + stats_loop(); + } else { + parse_loop(); + } print_outro(); } @@ -1930,7 +2337,7 @@ just don't highlight them. [B<--html-output>] Use HTML and CSS for the 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 excape any input! +It does not escape any input! [B<--no-msecs>] Don't expect milisecond resolution @@ -1942,6 +2349,11 @@ codes. [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 +to be incorrect if Privoxy and Privoxy-Log-Parser aren't in sync. + [B<--version>] Print version and exit. =head1 EXAMPLES