X-Git-Url: http://www.privoxy.org/gitweb/?a=blobdiff_plain;f=tools%2Fprivoxy-log-parser.pl;h=5215267eb9da3c8f27ed99a978490e4749fbb969;hb=01f2086bd873575156c3a96abb8abaf567a556fc;hp=30da968537f917872f9ffff31a22910891097d35;hpb=7e074c16ee589ae96521cb2b4d19f3e8d9f1d665;p=privoxy.git diff --git a/tools/privoxy-log-parser.pl b/tools/privoxy-log-parser.pl index 30da9685..5215267e 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.46 2009/09/10 15:02:25 fabiankeil Exp $ +# $Id: privoxy-log-parser.pl,v 1.53 2009/10/08 11:45:56 fabiankeil Exp $ # # TODO: # - LOG_LEVEL_CGI, LOG_LEVEL_ERROR, LOG_LEVEL_WRITE content highlighting @@ -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, @@ -187,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 ($) { @@ -1521,6 +1523,11 @@ 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./) { + + # 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. @@ -1538,8 +1545,9 @@ sub handle_loglevel_connect ($) { # 3.0.15 and later: # Done reading from server. Expected content length: 24892. \ # Actual content length: 24892. Bytes most recently read: 4412. - $c =~ s@(?<=Expected content length: )(\d+)@$h{'Number'}$1$h{'Standard'}@; - $c =~ s@(?<=Actual content length: )(\d+)@$h{'Number'}$1$h{'Standard'}@; + # 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'}@; @@ -1611,6 +1619,12 @@ sub handle_loglevel_connect ($) { $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 @@ -1620,7 +1634,8 @@ sub handle_loglevel_connect ($) { $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/) { + $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 \ @@ -1635,6 +1650,7 @@ sub handle_loglevel_connect ($) { # 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 { @@ -1826,6 +1842,147 @@ 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 ################################################################################ @@ -1910,7 +2067,6 @@ 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, @@ -1950,8 +2106,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); @@ -2009,12 +2163,51 @@ sub parse_loop () { } } } +} + +sub stats_loop () { - if (cli_option_is_set('statistic')) { - foreach (keys %log_level_count) { - print $_ . ": " . $log_level_count{$_} . " "; + 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 + ); + + 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 { @@ -2037,7 +2230,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 ( @@ -2048,7 +2241,7 @@ 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'}, + 'statistics' => \$cli_options{'statistics'}, 'version' => sub { VersionMessage && exit(0) } ); } @@ -2066,7 +2259,11 @@ sub main () { print_intro(); - parse_loop(); + if (cli_option_is_set('statistics')) { + stats_loop(); + } else { + parse_loop(); + } print_outro(); } @@ -2123,6 +2320,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