#
# http://www.fabiankeil.de/sourcecode/privoxy-log-parser/
#
-# $Id: privoxy-log-parser.pl,v 1.48 2009/09/12 12:36:02 fabiankeil Exp $
+# $Id: privoxy-log-parser.pl,v 1.214 2009/12/30 14:08:09 fk Exp $
#
# TODO:
# - LOG_LEVEL_CGI, LOG_LEVEL_ERROR, LOG_LEVEL_WRITE content highlighting
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,
ESCAPE => "\033[",
};
+# For performance reasons, these are global.
+
+my $t;
+my %req; # request data from previous lines
+my %h;
+my %thread_colours;
+my @all_colours;
+my @time_colours;
+my $thread_colour_index = 0;
+my $header_colour_index = 0;
+my $time_colour_index = 0;
+my %header_colours;
+my $no_special_header_highlighting;
+my %reason_colours;
+my %h_colours;
+my $header_highlight_regex = '';
+
+my $html_output_mode;
+my $no_msecs_mode; # XXX: should probably be removed
+my $line_end;
+
sub prepare_our_stuff () {
# Syntax Higlight hash
- our @all_colours = (
+ @all_colours = (
'red', 'green', 'brown', 'blue', 'purple', 'cyan',
'light_gray', 'light_red', 'light_green', 'yellow',
'light_blue', 'pink', 'light_cyan', 'white'
);
- our %h = (
+ %h = (
# LOG_LEVEL
Info => 'blue',
Header => 'green',
'content-type' => 'yellow',
);
- our %h_colours = %h;
+ %h_colours = %h;
# Header colours need their own hash so the keys can be accessed properly
- our %header_colours = (
+ %header_colours = (
# Prefilled with headers that should not appear with default header colours
Cookie => 'light_red',
'Set-Cookie' => 'light_red',
);
# Crunch reasons need their own hash as well
- our %reason_colours = (
+ %reason_colours = (
'Unsupported HTTP feature' => 'light_red',
Blocked => 'light_red',
Untrusted => 'light_red',
'No reason recorded' => 'light_red',
);
- our @time_colours = ('white', 'light_gray');
+ @time_colours = ('white', 'light_gray');
# Translate highlight strings into highlight code
prepare_highlight_hash(\%header_colours);
prepare_colour_array(\@all_colours);
prepare_colour_array(\@time_colours);
init_css_colours();
+
+ init_stats();
}
sub paint_it ($) {
sub get_css_line ($) {
- our %h_colours;
-
my $class = shift;
my $css_line;
sub get_css_line_for_colour ($) {
- our %h_colours;
-
my $colour = shift;
my $css_line;
sub get_css () {
- our %h_colours;
our %css_colours; #XXX: Wrong solution
my $css = '';
}
sub get_line_end () {
-
- my $line_end = "\n";
-
- $line_end = '<br>' . $line_end if cli_option_is_set('html-output');
-
- return $line_end;
+ return cli_option_is_set('html-output') ? "<br>\n" : "\n";
}
sub get_colour_html_markup ($) {
sub prepare_highlight_hash ($) {
my $ref = shift;
- if (!cli_option_is_set('html-output')) {
+ if (!$html_output_mode) {
foreach my $key (keys %$ref) {
$$ref{$key} = paint_it($$ref{$key});
sub prepare_colour_array ($) {
my $ref = shift;
- if (!cli_option_is_set('html-output')) {
+ if (!$html_output_mode) {
foreach my $i (0 ... @$ref - 1) {
$$ref[$i] = paint_it($$ref[$i]);
my $unknown = shift;
my $message;
- our %req;
- our $t;
-
return if cli_option_is_set('accept-unknown-messages');
return if ($unknown =~ /\[too long, truncated\]$/);
sub debug_message (@) {
my @message = @_;
- our %h;
print $h{'debug'} . "@message" . $h{'Standard'} . "\n";
}
sub h ($) {
# Get highlight marker
- our %h;
my $highlight = shift; # XXX: Stupid name;
my $result = '';
my $message;
sub highlight_known_headers ($) {
my $content = shift;
- our %header_colours;
- our %h;
- my $headers = join ('|', keys %header_colours);
debug_message("Searching $content for things to highlight.") if DEBUG_HEADER_HIGHLIGHTING;
- if ($content =~ m/(?<=\s)($headers):/) {
+ if ($content =~ m/(?<=\s)($header_highlight_regex):/) {
my $header = $1;
$content =~ s@(?<=[\s|'])($header)(?=:)@$header_colours{$header}$1$h{'Standard'}@ig;
- debug_message("Highlighted $content") if DEBUG_HEADER_HIGHLIGHTING;
+ debug_message("Highlighted '$header' in '$content'") if DEBUG_HEADER_HIGHLIGHTING;
}
return $content;
my $rl = shift;
my ($method, $url, $http_version);
- our %h;
#GET http://images.sourceforge.net/sfx/icon_warning.gif HTTP/1.1
if ($rl =~ m/Invalid request/) {
sub highlight_matched_host ($$) {
- my $result = shift; # XXX: Stupid name;
- my $regex = shift;
+ my ($result, $regex) = @_; # XXX: result ist stupid name;
if ($result =~ m@(.*?)($regex)(.*)@) {
- $result = $1 . h('host') . $2 . h('Standard') . $3;
+ $result = $1 . $h{host} . $2 . $h{Standard} . $3;
}
return $result;
sub highlight_matched_pattern ($$$) {
- our %h;
my $result = shift; # XXX: Stupid name;
my $key = shift;
my $regex = shift;
my $url = shift;
- if (cli_option_is_set('html-output')) {
+ if ($html_output_mode) {
$url = '<a href="' . $url . '">' . $url . '</a>';
return $url;
}
+sub update_header_highlight_regex ($) {
+
+ my $header = shift;
+ my $headers = join ('|', keys %header_colours);
+
+ $header_highlight_regex = qr/$headers/;
+ print "Registering '$header'\n" if DEBUG_HEADER_HIGHLIGHTING;
+}
+
################################################################################
# loglevel-specific highlighter functions
################################################################################
my $content = shift;
my $c = $content;
- our $t;
- our %req;
- our %h;
- our %header_colours;
- our @all_colours;
- our $header_colour_index;
- our $no_special_header_highlighting;
-
- # Register new headers
- # scan: Accept: image/png,image/*;q=0.8,*/*;q=0.5
- if ($c =~ m/^scan: ((?>[^:]+)):/) {
- my $header = $1;
- 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) {
- $header_colours{$header} = $header_colours{'Default'};
- } else {
- $header_colours{$header} = $all_colours[$header_colour_index % @all_colours];
- $header_colour_index++;
- }
- }
- }
+ if ($c =~ /^scan:/) {
- if ($c =~ m/^scan: ((\w*) (.*) (HTTP\/\d\.\d))/) {
+ if ($c =~ m/^scan: ((\w+) (.+) (HTTP\/\d\.\d))/) {
# Client request line
# Save for statistics (XXX: Not implemented yet)
$content = highlight_request_line($1);
- } elsif ($c =~ m/^(scan: )((?:HTTP\/\d\.\d|ICY) (\d+) (.*))/) {
+ } elsif ($c =~ m/^(scan: )((?:HTTP\/\d\.\d|ICY) (\d+) (.*))/) {
# Server response line
$req{$t}{'response_line'} = $2;
$req{$t}{'status_message'} = $4;
$content = $1 . highlight_response_line($req{$t}{'response_line'});
+ } elsif ($c =~ m/^scan: ((?>[^:]+)):/) {
+
+ # Register new headers
+ # scan: Accept: image/png,image/*;q=0.8,*/*;q=0.5
+ my $header = $1;
+ 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) {
+ $header_colours{$header} = $header_colours{'Default'};
+ } else {
+ $header_colours{$header} = $all_colours[$header_colour_index % @all_colours];
+ $header_colour_index++;
+ }
+ update_header_highlight_regex($header);
+ }
+
+ }
+
} elsif ($c =~ m/^Crunching (?:server|client) header: .* \(contains: ([^\)]*)\)/) {
# Crunching server header: Set-Cookie: trac_form_token=d5308c34e16d15e9e301a456; (contains: Cookie:)
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./
+ or $c =~ m/^keep-alive support is disabled/
)
{
# XXX: Some of these may need highlighting
# 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.
+ # keep-alive support is disabled. Crunching: Keep-Alive: 300.
} elsif ($c =~ m/^scanning headers for:/) {
my $content = shift;
my $c = $content;
my $key;
- our $t;
- our %req;
- our %h;
- our %header_colours;
- our @all_colours;
- our $header_colour_index;
-
- if ($c =~ /\.{3}$/
+
+ if ($c =~ m/^(?:re_)?filtering ([^\s]+) \(size (\d+)\) with (?:filter )?\'?([^\s]+?)\'? produced (\d+) hits \(new size (\d+)\)/) {
+
+ # XXX: only the second version gets highlighted properly.
+ # re_filtering www.lfk.de/favicon.ico (size 209) with filter untrackable-hulk produced 0 hits (new size 209).
+ # filtering aci.blogg.de/ (size 37988) with 'blogg.de' produced 3 hits (new size 38057)
+ $req{$t}{'content_source'} = $1;
+ $req{$t}{'content_size'} = $2;
+ $req{$t}{'content_filter'} = $3;
+ $req{$t}{'content_hits'} = $4;
+ $req{$t}{'new_content_size'} = $5;
+ $req{$t}{'content_size_change'} = $req{$t}{'new_content_size'} - $req{$t}{'content_size'};
+ #return '' if ($req{$t}{'content_hits'} == 0 && !cli_option_is_set('show-ineffective-filters'));
+ if ($req{$t}{'content_hits'} == 0 and
+ not (cli_option_is_set('show-ineffective-filters')
+ or ($req{$t}{'content_filter'} =~ m/^privoxy-filter-test$/))) {
+ return '';
+ }
+
+ $c =~ s@(?<=\(size )(\d+)\)(?= with)@$h{'Number'}$1$h{'Standard'}@;
+ $c =~ s@(?<=\(new size )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+ $c =~ s@(?<=produced )(\d+)(?= hits)@$h{'Number'}$1$h{'Standard'}@;
+
+ $c =~ s@([^\s]+?)(\'? produced)@$h{'filter'}$1$h{'Standard'}$2@;
+ $c = highlight_matched_host($c, '(?<=filtering )[^\s]+');
+
+ $c =~ s@\.$@ @;
+ $c .= "(" . $h{'Number'};
+ $c .= "+" if ($req{$t}{'content_size_change'} >= 0);
+ $c .= $req{$t}{'content_size_change'} . $h{'Standard'} . ")";
+ $content = $c;
+
+ } elsif ($c =~ /\.{3}$/
and $c =~ m/^(?:re_)?filtering \'?(.*?)\'? \(size (\d*)\) with (?:filter )?\'?([^\s]*?)\'? ?\.{3}$/) {
# Used by Privoxy 3.0.5 and 3.0.6:
$content =~ s@(?<=$1 )([^\s]*)@$h{'filter'}$1$h{'Standard'}@;
- } elsif ($c =~ m/^(?:re_)?filtering ([^\s]+) \(size (\d+)\) with (?:filter )?\'?([^\s]+?)\'? produced (\d+) hits \(new size (\d+)\)/) {
-
- # XXX: only the second version gets highlighted properly.
- # re_filtering www.lfk.de/favicon.ico (size 209) with filter untrackable-hulk produced 0 hits (new size 209).
- # filtering aci.blogg.de/ (size 37988) with 'blogg.de' produced 3 hits (new size 38057)
- $req{$t}{'content_source'} = $1;
- $req{$t}{'content_size'} = $2;
- $req{$t}{'content_filter'} = $3;
- $req{$t}{'content_hits'} = $4;
- $req{$t}{'new_content_size'} = $5;
- $req{$t}{'content_size_change'} = $req{$t}{'new_content_size'} - $req{$t}{'content_size'};
- #return '' if ($req{$t}{'content_hits'} == 0 && !cli_option_is_set('show-ineffective-filters'));
- if ($req{$t}{'content_hits'} == 0 and
- not (cli_option_is_set('show-ineffective-filters')
- or ($req{$t}{'content_filter'} =~ m/^privoxy-filter-test$/))) {
- return '';
- }
-
- $c =~ s@(?<=\(size )(\d+)\)(?= with)@$h{'Number'}$1$h{'Standard'}@;
- $c =~ s@(?<=\(new size )(\d+)@$h{'Number'}$1$h{'Standard'}@;
- $c =~ s@(?<=produced )(\d+)(?= hits)@$h{'Number'}$1$h{'Standard'}@;
-
- $c =~ s@([^\s]+?)(\'? produced)@$h{'filter'}$1$h{'Standard'}$2@;
- $c = highlight_matched_host($c, '(?<=filtering )[^\s]+');
-
- $c =~ s@\.$@ @;
- $c .= "(" . $h{'Number'};
- $c .= "+" if ($req{$t}{'content_size_change'} >= 0);
- $c .= $req{$t}{'content_size_change'} . $h{'Standard'} . ")";
- $content = $c;
-
} elsif ($c =~ m/^De-chunking successful. Shrunk from (\d+) to (\d+)/) {
$req{$t}{'chunked-size'} = $1;
sub handle_loglevel_redirect ($) {
my $c = shift;
- our $t;
- our %req;
- our %h;
if ($c =~ m/^Decoding "([^""]*)"/) {
$c = highlight_matched_path($c, '(?<=Checking ")[^"]*');
$c =~ s@\"@@g;
- } elsif ($c =~ m/^pcrs command "([^""]*)" changed "([^""]*)" to "([^""]*)" \((\d+) hits?\)/) {
+ } elsif ($c =~ m/^pcrs command "([^""]*)" changed /) {
- # pcrs command "s@&from=rss@@" changed "http://it.slashdot.org/article.pl?sid=07/03/02/1657247&from=rss"\
+ # pcrs command "s@&from=rss@@" changed \
+ # "http://it.slashdot.org/article.pl?sid=07/03/02/1657247&from=rss"\
# to "http://it.slashdot.org/article.pl?sid=07/03/02/1657247" (1 hit).
-
- my ($pcrs_command, $url_before, $url_after, $hits) = ($1, $2, $3, $4); # XXX: save these?
-
$c =~ s@(?<=pcrs command )"([^""]*)"@$h{'filter'}$1$h{'Standard'}@;
$c = highlight_matched_url($c, '(?<=changed ")[^""]*');
$c =~ s@(?<=changed )"([^""]*)"@$1@; # Remove quotes
$c =~ s@(?<=to )"([^""]*)"@$1@; # Remove quotes
$c =~ s@(\d+)(?= hits?)@$h{'hits'}$1$h{'Standard'}@;
+ } elsif ($c =~ m/^pcrs command "([^""]*)" didn\'t change/) {
+
+ # pcrs command "s@^http://([^.]+?)/?$@http://www.bing.com/search?q=$1@" didn't \
+ # change "http://www.example.org/".
+ $c =~ s@(?<=pcrs command )"([^""]*)"@$h{'filter'}$1$h{'Standard'}@;
+ $c = highlight_matched_url($c, '(?<=change ")[^""]*');
+
} elsif ($c =~ m/(^New URL is: )(.*)/) {
# New URL is: http://it.slashdot.org/article.pl?sid=07/03/04/1511210
sub handle_loglevel_gif_deanimate ($) {
my $content = shift;
- our $t;
- our %req;
- our %h;
if ($content =~ m/Success! GIF shrunk from (\d+) bytes to (\d+)\./) {
sub handle_loglevel_request ($) {
my $content = shift;
- our $t;
- our %req;
- our %h;
- our %reason_colours;
if ($content =~ m/crunch! /) {
sub handle_loglevel_crunch ($) {
my $content = shift;
- our %h;
- our %reason_colours;
# Highlight crunch reason
foreach my $reason (keys %reason_colours) {
sub handle_loglevel_connect ($) {
my $c = shift;
- our $t;
- our %req;
- our %h;
if ($c =~ m/^via [^\s]+ to: [^\s]+/) {
} 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/) {
$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.
# 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'}@;
# 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.
+ # No additional client request received in time on socket 29.
- $c =~ s@(?<=server socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+ $c =~ s@(?<= socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
$c = highlight_matched_host($c, '(?<=for )[^\s]+(?=\.$)');
} elsif ($c =~ m/^Connected to /) {
$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/ ) {
+ $c =~ m/^The connection on server socket/ or
+ $c =~ m/^Client request arrived in time or the client closed the connection/) {
- # Waiting for the next client request. Keeping the server socket 5 to 10.0.0.1 open.
+ # 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.
+ # Client request arrived in time or the client closed the connection on socket 12.
+ $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]+');
$c =~ s@(?<=closed socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
$c =~ s@(?<=server socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+ } elsif ($c =~ m/^Expected client content length set /) {
+
+ # Expected client content length set to 667325411 after reading 4999 bytes.
+ $c =~ s@(?<=set to )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+ $c =~ s@(?<=reading )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+
+ } elsif ($c =~ m/^Waiting for up to /) {
+
+ # 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
$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./) {
+ $c =~ m/^Stopping to watch the client socket. There's already another request waiting./ or
+ $c =~ m/^Done reading from the client\.$/) {
# 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 \
# 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.
+ # Done reading from the client\.
} else {
sub handle_loglevel_info ($) {
my $c = shift;
- our $t;
- our %req;
- our %h;
if ($c =~ m/^Rewrite detected:/) {
sub handle_loglevel_cgi ($) {
my $c = shift;
- our $t;
- our %req;
- our %h;
if ($c =~ m/^Granting access to/) {
sub handle_loglevel_force ($) {
my $c = shift;
- our $t;
- our %req;
- our %h;
if ($c =~ m/^Ignored force prefix in request:/) {
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.
+ # Empty server or forwarder response received on socket 3. \
+ # Closing client socket 15 without sending data.
$c =~ s@(?<=on socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
+ $c =~ s@(?<=client socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
}
# XXX: There are probably more messages that deserve highlighting.
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
################################################################################
sub print_clf_message () {
our ($ip, $timestamp, $request_line, $status_code, $size);
- our %h;
my $output = '';
return if DEBUG_SUPPRESS_LOG_MESSAGES;
$output .= $h{'Status'} . $status_code . $h{'Standard'};
$output .= " ";
$output .= $h{'Number'} . $size . $h{'Standard'};
- $output .= get_line_end();
+ $output .= $line_end;
print $output;
}
sub print_non_clf_message ($) {
- our %req;
- our %thread_colours;
- our %h;
- our $t;
- our $time_colour_index;
- our @time_colours;
- my $output;
my $content = shift;
- my ($day, $time_stamp, $msecs, $thread, $log_level)
- = ($req{$t}{'day'}, $req{$t}{'time-stamp'}, $req{$t}{'msecs'}, $t, $req{$t}{'log-level'} );
+ my $msec_string = "." . $req{$t}{'msecs'} unless $no_msecs_mode;
+ my $line_start = $html_output_mode ? '' : $h{"Standard"};
return if DEBUG_SUPPRESS_LOG_MESSAGES;
- $output .= $h{"Standard"} unless cli_option_is_set('html-output');
- # $output .= "$day ";
- $output .= $time_colours[$time_colour_index % 2];
-
- $output .= $time_stamp;
- $output .= ".$msecs" unless cli_option_is_set('no-msecs');
- $output .= $h{"Standard"};
- $output .= " ";
- $output .= $thread_colours{$thread} if (defined($thread_colours{$thread}));
- $output .= $thread;
- $output .= $h{"Standard"} . " ";
- $output .= $h{$log_level} if (defined($h{$log_level}));
- $output .= $log_level;
- $output .= $h{"Standard"} . ": ";
- $output .= "$content";
- $output .= get_line_end();
-
- print $output;
+ print $line_start
+ . $time_colours[$time_colour_index % 2]
+ . $req{$t}{'time-stamp'}
+ . $msec_string
+ . $h{Standard} . " "
+ . $thread_colours{$t}
+ . $t
+ . $h{Standard}
+ . " "
+ . $h{$req{$t}{'log-level'}}
+ . $req{$t}{'log-level'}
+ . $h{Standard}
+ . ": "
+ . $content
+ . $line_end;
}
sub parse_loop () {
- our $t;
- our %req; # request data from previous lines
- our %h;
- our %thread_colours;
- our @all_colours;
- our @time_colours;
- our $thread_colour_index = 0;
- our $header_colour_index = 0;
- our $time_colour_index = 0;
-
my ($day, $time_stamp, $thread, $log_level, $content, $c, $msecs);
my $last_msecs = 0;
my $last_thread = 0;
my $last_timestamp = 0;
- my $output;
my $filters_that_did_nothing;
my $key;
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,
while (<>) {
- $output = '';
-
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;
- $msecs = $3 ? $3 : 0; # Only the cool kids have micro second resolution
- $log_level = $5;
- $content = $c = $6;
$thread = $t = $4;
-
- $req{$t}{'day'} = $day;
- $req{$t}{'time-stamp'} = $time_stamp;
- $req{$t}{'msecs'} = $msecs; # Only the cool kids have micro second resolution;
- $req{$t}{'log-level'} = $log_level;
- $req{$t}{'content'} = $content;
+ $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;
+ $req{$t}{'log-level'} = $log_level = $5;
+ $req{$t}{'content'} = $content = $c = $6;
$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);
}
# Switch timestamp colour if timestamps differ
- if ($msecs != $last_msecs || !($time_stamp =~ m/$last_timestamp/)) {
+ if (($msecs ne $last_msecs) || ($time_stamp ne $last_timestamp)) {
debug_message("Tick tack!") if DEBUG_TICKS;
$time_colour = $time_colours[$time_colour_index % 2];
- $time_colour_index++
+ $time_colour_index++;
+ $last_msecs = $msecs;
+ $last_timestamp = $time_stamp;
}
- $last_msecs = $msecs;
$last_thread = $thread;
- $last_timestamp = $time_stamp;
print_non_clf_message($content);
}
}
}
+}
- if (cli_option_is_set('statistic')) {
- foreach (keys %log_level_count) {
- print $_ . ": " . $log_level_count{$_} . " ";
+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
+ );
+
+ 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 {
'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 (
'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,
+ ) or exit(1);
+
+ $html_output_mode = cli_option_is_set('html-output');
+ $no_msecs_mode = cli_option_is_set('no-msecs');
+ $line_end = get_line_end();
}
+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
print_intro();
- parse_loop();
+ if (cli_option_is_set('statistics')) {
+ stats_loop();
+ } else {
+ parse_loop();
+ }
print_outro();
}
[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
projects / privoxy.git / blobdiff