X-Git-Url: http://www.privoxy.org/gitweb/?p=privoxy.git;a=blobdiff_plain;f=tools%2Fprivoxy-log-parser.pl;h=9558544ac2a09d1da0ca2b7226ff5e3a5bd29ea9;hp=c6b52b8eda9c08e2631b9db11fd4a01cb5928d05;hb=8875cc0bd68dd60dfc150adf6d147eec216789ec;hpb=aaae1ec002be4f185d9bdfa15333b04cc3ac4f33 diff --git a/tools/privoxy-log-parser.pl b/tools/privoxy-log-parser.pl index c6b52b8e..9558544a 100755 --- a/tools/privoxy-log-parser.pl +++ b/tools/privoxy-log-parser.pl @@ -6,9 +6,7 @@ # A parser for Privoxy log messages. For incomplete documentation run # perldoc privoxy-log-parser(.pl), for fancy screenshots see: # -# http://www.fabiankeil.de/sourcecode/privoxy-log-parser/ -# -# $Id: privoxy-log-parser.pl,v 1.73 2010/01/05 23:36:43 fabiankeil Exp $ +# https://www.fabiankeil.de/sourcecode/privoxy-log-parser/ # # TODO: # - LOG_LEVEL_CGI, LOG_LEVEL_ERROR, LOG_LEVEL_WRITE content highlighting @@ -23,8 +21,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 +# Copyright (c) 2007-2017 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 +43,7 @@ use warnings; use Getopt::Long; use constant { - PRIVOXY_LOG_PARSER_VERSION => '0.6', + PRIVOXY_LOG_PARSER_VERSION => '0.9', # Feel free to mess with these ... DEFAULT_BACKGROUND => 'black', # Choose registered colour (like 'black') DEFAULT_TEXT_COLOUR => 'white', # Choose registered colour (like 'black') @@ -56,16 +55,20 @@ 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, + CLI_OPTION_STRICT_CHECKS => 0, + CLI_OPTION_UNBREAK_LINES_ONLY => 0, + CLI_OPTION_URL_STATISTICS_THRESHOLD => 0, + CLI_OPTION_HOST_STATISTICS_THRESHOLD => 0, + CLI_OPTION_SHOW_COMPLETE_REQUEST_DISTRIBUTION => 0, SUPPRESS_SUCCEEDED_FILTER_ADDITIONS => 1, SHOW_SCAN_INTRO => 0, 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, @@ -105,6 +108,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 +136,8 @@ sub prepare_our_stuff () { 'Gif-Deanimate' => 'blue', Force => 'red', Writing => 'light_green', + Received => 'yellow', + Actions => 'yellow', # ---------------------- URL => 'yellow', path => 'brown', @@ -172,6 +178,7 @@ sub prepare_our_stuff () { 'action-bits-update' => 'light_red', 'configuration-line' => 'red', 'content-type' => 'yellow', + 'HOST' => HEADER_DEFAULT_COLOUR, ); %h_colours = %h; @@ -219,7 +226,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'); @@ -294,7 +301,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/) { @@ -467,7 +474,7 @@ sub get_colour_html_markup ($) { # markup should always be semantically correct. ############################################################### - my $type = shift @_; + my $type = shift; my $code; if ($type =~ /Standard/) { @@ -545,7 +552,7 @@ sub found_unknown_content ($) { my $unknown = shift; my $message; - return if cli_option_is_set('accept-unknown-messages'); + return unless cli_option_is_set('strict-checks'); return if ($unknown =~ /\[too long, truncated\]$/); @@ -564,9 +571,9 @@ sub log_parse_error ($) { my $message = shift; if (LOG_UNPARSED_LINES_TO_EXTRA_FILE) { - open(ERRORLOG, ">>" . ERROR_LOG_FILE) || die "Writing " . ERROR_LOG_FILE . " failed"; - print ERRORLOG $message; - close(ERRORLOG); + open(my $errorlog_fd, ">>", ERROR_LOG_FILE) || die "Writing " . ERROR_LOG_FILE . " failed"; + print $errorlog_fd $message; + close($errorlog_fd); } } @@ -637,7 +644,7 @@ sub highlight_request_line ($) { $rl = h('invalid-request') . $rl . h('Standard'); - } elsif ($rl =~ m/^([-\w]+) (.*) (HTTP\/\d\.\d)/) { + } elsif ($rl =~ m/^([-\w]+) (.*) (HTTP\/\d+\.\d+)/) { # XXX: might not match in case of HTTP method fuzzing. # XXX: save these: ($method, $path, $http_version) = ($1, $2, $3); @@ -801,19 +808,14 @@ 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: GET http://p.p/ HTTP/1.1 + $c = $1 . highlight_request_line($2); } elsif ($c =~ m/^(scan: )((?:HTTP\/\d\.\d|ICY) (\d+) (.*))/) { - # Server response line + # scan: HTTP/1.1 200 OK $req{$t}{'response_line'} = $2; $req{$t}{'status_code'} = $3; $req{$t}{'status_message'} = $4; @@ -908,6 +910,11 @@ 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/ + or $c =~ m/^Merged multiple header lines to:/ + or $c =~ m/^Added header: / + or $c =~ m/^Enlisting (?:sorted|left-over) header/ + or $c =~ m/^Multiple Content-Type headers detected. Removing and ignoring: Content-Type:/ ) { # XXX: Some of these may need highlighting @@ -953,6 +960,12 @@ 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. + # 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 + # Multiple Content-Type headers detected. Removing and ignoring: Content-Type: text/html } elsif ($c =~ m/^scanning headers for:/) { @@ -1005,6 +1018,12 @@ sub handle_loglevel_header ($) { $c =~ s@(?<= from )(\d+)@$h{'Number'}$1$h{'Standard'}@; $c =~ s@(?<= to )(\d+)@$h{'Number'}$1$h{'Standard'}@; + } elsif ($c =~ m/^Killed all-caps Host header line: HOST:/) { + + # Killed all-caps Host header line: HOST: bestproxydb.com + $c = highlight_matched_host($c, '(?<=HOST: )[^\s]+'); + $c = highlight_matched_pattern($c, 'HOST', 'HOST'); + } else { found_unknown_content($c); @@ -1180,6 +1199,13 @@ sub handle_loglevel_re_filter ($) { # Adding dynamic re_filter job s@^(?:\w*)\s+.*\s+HTTP/\d\.\d\s*@IP-ADDRESS: $origin@D\ # to filter client-ip-address succeeded. + } elsif ($c =~ m/^Compressed content from /) { + + # Compressed content from 29258 to 8630 bytes. Compression level: 3 + $content =~ s@(?<=from )(\d+)@$h{'Number'}$1$h{'Standard'}@; + $content =~ s@(?<=to )(\d+)@$h{'Number'}$1$h{'Standard'}@; + $content =~ s@(?<=level: )(\d+)@$h{'Number'}$1$h{'Standard'}@; + } elsif ($c =~ m/^Reading in filter/) { return '' unless SHOW_FILTER_READIN_IN; @@ -1245,6 +1271,11 @@ sub handle_loglevel_redirect ($) { # XXX: assume the same? $c = highlight_matched_url($c, '(?<=assuming that \")[^"]*'); + } elsif ($c =~ m/^Percent-encoding redirect/) { + + # Percent-encoding redirect URL: http://www.example.org/\x02 + $c = highlight_matched_url($c, '(?<=redirect URL: ).*'); + } else { found_unknown_content($c); @@ -1287,7 +1318,7 @@ sub handle_loglevel_gif_deanimate ($) { } elsif ($content =~ m/^(?:No GIF header found|failed while parsing)/) { # No GIF header found (XXX: Did I ever commit this?) - # failed while parsing 195 134747048 (XXX: never commited) + # failed while parsing 195 134747048 (XXX: never committed) # Ignore these for now @@ -1392,14 +1423,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:/) { @@ -1504,10 +1552,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/) { @@ -1532,15 +1587,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/) { @@ -1548,12 +1606,13 @@ 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 + } elsif ($c =~ m/^(?:Reusing|Closing) server socket / or $c =~ m/^No additional client request/) { # Reusing server socket 4. Opened for 10.0.0.1. @@ -1561,9 +1620,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 /) { @@ -1582,13 +1649,20 @@ 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 or the client closed the connection/) { + $c =~ m/^Client request (?:\d+ )?(?:arrived in time|has been pipelined) /) { # 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. + # 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. + # Client request 8 has been pipelined on socket 7 and the socket is still alive. + $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]+'); @@ -1617,12 +1691,51 @@ sub handle_loglevel_connect ($) { $c =~ s@(?<=set to )(\d+)@$h{'Number'}$1$h{'Standard'}@; $c =~ s@(?<=reading )(\d+)@$h{'Number'}$1$h{'Standard'}@; + } elsif ($c =~ m/^Reducing expected bytes to /) { + + # Reducing expected bytes to 0. Marking the server socket tainted after throwing 4 bytes away. + $c =~ s@(?<=bytes to )(\d+)@$h{'Number'}$1$h{'Standard'}@; + $c =~ s@(?<=after throwing )(\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 + } 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. + # Privoxy 3.0.20 and later: + # 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/ or + $c =~ m/^Failed to shutdown socket/) { + + # Tainting client socket 7 due to unread data. + # Failed to shutdown socket 11: Connection reset by peer + + $c =~ s@(?<=socket )(\d+)@$h{'Number'}$1$h{'Standard'}@; + + } elsif ($c =~ m/^Shifting \d+ pipelined bytes/) { + + # Shifting 360 pipelined bytes by 360 bytes + $c =~ s@(?<=Shifting )(\d+)@$h{'Number'}$1$h{'Standard'}@; + $c =~ s@(?<=by )(\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 $c =~ m/^Complete client request received/ or @@ -1631,12 +1744,14 @@ sub handle_loglevel_connect ($) { $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./ or + $c =~ m/^There better be a request body./ 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 \ # 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. @@ -1647,8 +1762,9 @@ 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. - # Done reading from the client\. + # Privoxy 3.0.20 and later + # There better be a request body. + # Done reading from the client. } else { @@ -1671,12 +1787,15 @@ sub handle_loglevel_info ($) { } elsif ($c =~ m/^Decompress(ing deflated|ion didn)/ or $c =~ m/^Compressed content detected/ or + $c =~ m/^SDCH-compressed content detected/ or $c =~ m/^Tagger/ ) { # Decompressing deflated iob: 117 # Decompression didn't result in any content. # Compressed content detected, content filtering disabled. Consider recompiling Privoxy\ # with zlib support or enable the prevent-compression action. + # SDCH-compressed content detected, content filtering disabled.\ + # Consider suppressing SDCH offers made by the client. # Tagger 'complete-url' created empty tag. Ignored. # Ignored for now @@ -1687,6 +1806,14 @@ 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|trust) file: /) { + + # Loading actions file: /usr/local/etc/privoxy/default.action + # Loading filter file: /usr/local/etc/privoxy/default.filter + # Loading trust file: /usr/local/etc/privoxy/trust + + $c =~ s@(?<= file: )(.*)$@$h{'file'}$1$h{'Standard'}@; + } elsif ($c =~ m/^exiting by signal/) { # exiting by signal 15 .. bye @@ -1717,12 +1844,15 @@ sub handle_loglevel_info ($) { # Request from 10.0.0.1 denied. limit-connect{,} doesn't allow CONNECT requests to port 443. # Request from 10.0.0.1 marked for blocking. limit-connect{,} doesn't allow CONNECT requests to port 443. + # 3.0.18 and later: + # Request from 10.0.0.1 marked for blocking. limit-connect{0} doesn't allow CONNECT requests to www.example.org:443 # Malformed server response detected. Downgrading to HTTP/1.0 impossible. $c =~ s@(?<=Request from )([^\s]*)@$h{'ip-address'}$1$h{'Standard'}@; $c =~ s@(denied|blocking)@$h{'warning'}$1$h{'Standard'}@; $c =~ s@(CONNECT)@$h{'method'}$1$h{'Standard'}@; $c =~ s@(?<=to port )(\d+)@$h{'port'}$1$h{'Standard'}@; + $c =~ s@(?<=to )([^\s]+)@$h{'request_'}$1$h{'Standard'}@; } elsif ($c =~ m/^Status code/) { @@ -1740,11 +1870,17 @@ sub handle_loglevel_info ($) { $c =~ s@(?<=Needed: )(\d+)@$h{'Number'}$1$h{'Standard'}@; $c =~ s@(?<=Limit: )(\d+)@$h{'Number'}$1$h{'Standard'}@; + } elsif ($c =~ m/^File modification detected: /) { + + # File modification detected: /usr/local/etc/privoxy/user-agent.action + $c =~ s@(?<= detected: )(.*)$@$h{'file'}$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/ 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 +1891,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 { @@ -1815,14 +1952,24 @@ sub handle_loglevel_error ($) { my $c = shift; - if ($c =~ m/^Empty server or forwarder response received on socket \d+./) { + if ($c =~ m/^(?:Empty|No) 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. + # Used by Privoxy 3.0.18 and later: + # No server or forwarder response received on socket 8. \ + # Closing client socket 10 without sending data. + $c =~ s@(?<=on socket )(\d+)@$h{'Number'}$1$h{'Standard'}@; $c =~ s@(?<=client socket )(\d+)@$h{'Number'}$1$h{'Standard'}@; + + } elsif ($c =~ m/^Didn't receive data in time:/) { + + # Didn't receive data in time: a.fsdn.com:443 + $c =~ s@(?<=in time: )(.*)@$h{'destination'}$1$h{'Standard'}@; } + # XXX: There are probably more messages that deserve highlighting. return $c; @@ -1848,6 +1995,23 @@ sub gather_loglevel_crunch_stats ($$) { $stats{requests}++; $stats{crunches}++; + + if ($c =~ m/^Redirected:/) { + # Redirected: http://www.example.org/http://p.p/ + $stats{'fast-redirections'}++; + + } elsif ($c =~ m/^Blocked:/) { + # Blocked: blogger.googleusercontent.com:443 + $stats{'blocked'}++; + + } elsif ($c =~ m/^Connection timeout:/) { + # Connection timeout: http://c.tile.openstreetmap.org/18/136116/87842.png + $stats{'connection-timeout'}++; + + } elsif ($c =~ m/^Connection failure:/) { + # Connection failure: http://127.0.0.1:8080/ + $stats{'connection-failure'}++; + } } @@ -1872,8 +2036,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; @@ -1902,14 +2065,22 @@ sub gather_loglevel_connect_stats ($$) { $thread_data{$thread}{'new_connection'} = 0; $stats{'reused-connections'}++; + + } elsif ($c =~ m/^Closing client socket \d+. .* Requests received: (\d+)\.$/) { + + # Closing client socket 12. Keep-alive: 1. Socket alive: 1. Data available: 0. \ + # Configuration file change detected: 0. Requests received: 14. + + $stats{'client-requests-on-connection'}{$1}++; + $stats{'closed-client-connections'}++; } } -sub gather_loglevel_header_stats ($) { +sub gather_loglevel_header_stats ($$) { - my $c = shift; - my $thread = shift; + my ($c, $thread) = @_; our %stats; + our %cli_options; if ($c =~ m/^A HTTP\/1\.1 response without/ or $c =~ m/^Keeping the server header 'Connection: keep-alive' around./) @@ -1917,6 +2088,21 @@ 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}++; + if ($cli_options{'url-statistics-threshold'} != 0) { + $stats{'resource'}{$3}++; + } + $stats{'http-version'}{$4}++; + + } elsif ($cli_options{'host-statistics-threshold'} != 0 and + $c =~ m/^scan: Host: ([^\s]+)/) { + + # scan: Host: p.p + $stats{'hosts'}{$1}++; } } @@ -1929,21 +2115,39 @@ sub init_stats () { 'empty-responses' => 0, 'empty-responses-on-new-connections' => 0, 'empty-responses-on-reused-connections' => 0, + 'fast-redirections' => 0, + 'blocked' => 0, + 'connection-failure' => 0, + 'connection-timeout' => 0, + 'reused-connections' => 0, + 'server-keep-alive' => 0, + 'closed-client-connections' => 0, ); + $stats{'client-requests-on-connection'}{1} = 0; } 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); } sub print_stats () { our %stats; + our %cli_options; my $new_connections = $stats{requests} - $stats{crunches} - $stats{'reused-connections'}; my $outgoing_requests = $stats{requests} - $stats{crunches}; + my $client_requests_checksum = 0; if ($stats{requests} eq 0) { print "No requests yet.\n"; @@ -1953,6 +2157,14 @@ sub print_stats () { print "Client requests total: " . $stats{requests} . "\n"; print "Crunches: " . $stats{crunches} . " (" . get_percentage($stats{requests}, $stats{crunches}) . ")\n"; + print "Blocks: " . $stats{'blocked'} . " (" . + get_percentage($stats{requests}, $stats{'blocked'}) . ")\n"; + print "Fast redirections: " . $stats{'fast-redirections'} . " (" . + get_percentage($stats{requests}, $stats{'fast-redirections'}) . ")\n"; + print "Connection timeouts: " . $stats{'connection-timeout'} . " (" . + get_percentage($stats{requests}, $stats{'connection-timeout'}) . ")\n"; + print "Connection failures: " . $stats{'connection-failure'} . " (" . + get_percentage($stats{requests}, $stats{'connection-failure'}) . ")\n"; print "Outgoing requests: " . $outgoing_requests . " (" . get_percentage($stats{requests}, $outgoing_requests) . ")\n"; print "Server keep-alive offers: " . $stats{'server-keep-alive'} . " (" . @@ -1960,7 +2172,9 @@ sub print_stats () { 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"; + get_percentage($stats{requests}, $stats{'reused-connections'}) . + "; server offers accepted: " . + get_percentage($stats{'server-keep-alive'}, $stats{'reused-connections'}) . ")\n"; print "Empty responses: " . $stats{'empty-responses'} . " (" . get_percentage($stats{requests}, $stats{'empty-responses'}) . ")\n"; print "Empty responses on new connections: " @@ -1971,6 +2185,66 @@ sub print_stats () { $stats{'empty-responses-on-reused-connections'} . " (" . get_percentage($stats{requests}, $stats{'empty-responses-on-reused-connections'}) . ")\n"; + print "Client connections: " . $stats{'closed-client-connections'} . "\n"; + + my $lines_printed = 0; + print "Client requests per connection distribution:\n"; + foreach my $client_requests (sort { + $stats{'client-requests-on-connection'}{$b} <=> $stats{'client-requests-on-connection'}{$a}} + keys %{$stats{'client-requests-on-connection'} + }) + { + my $count = $stats{'client-requests-on-connection'}{$client_requests}; + $client_requests_checksum += $count * $client_requests; + if ($cli_options{'show-complete-request-distribution'} or ($lines_printed < 10)) { + printf "%8d: %d\n", $count, $client_requests; + $lines_printed++; + } + } + unless ($cli_options{'show-complete-request-distribution'}) { + printf "Enable --show-complete-request-distribution to get less common numbers as well.\n"; + } + # Due to log rotation we may not have a complete picture for all the requests + printf "Improperly accounted requests: ~%d\n", abs($stats{requests} - $client_requests_checksum); + + if (exists $stats{method}) { + 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; + } + } else { + print "Method distribution unknown. No response headers parsed yet. Is 'debug 8' enabled?\n"; + } + 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; + } + + if ($cli_options{'url-statistics-threshold'} == 0) { + print "URL statistics are disabled. Increase --url-statistics-threshold to enable them.\n"; + } else { + print "Requested URLs:\n"; + foreach my $resource (sort {$stats{'resource'}{$b} <=> $stats{'resource'}{$a}} keys %{$stats{'resource'}}) { + if ($stats{'resource'}{$resource} < $cli_options{'url-statistics-threshold'}) { + print "Skipped statistics for URLs below the treshold.\n"; + last; + } + printf "%d : %s\n", $stats{'resource'}{$resource}, $resource; + } + } + + if ($cli_options{'host-statistics-threshold'} == 0) { + print "Host statistics are disabled. Increase --host-statistics-threshold to enable them.\n"; + } else { + print "Requested Hosts:\n"; + foreach my $host (sort {$stats{'hosts'}{$b} <=> $stats{'hosts'}{$a}} keys %{$stats{'hosts'}}) { + if ($stats{'hosts'}{$host} < $cli_options{'host-statistics-threshold'}) { + print "Skipped statistics for Hosts below the treshold.\n"; + last; + } + printf "%d : %s\n", $stats{'hosts'}{$host}, $host; + } + } } @@ -2003,7 +2277,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; @@ -2025,6 +2299,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 +2338,15 @@ sub parse_loop () { 'Error' => \&handle_loglevel_error, 'Fatal error' => \&handle_loglevel_ignore, 'Writing' => \&handle_loglevel_ignore, + 'Received' => \&handle_loglevel_ignore, + 'Actions' => \&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; + if (m/^(\d{4}-\d{2}-\d{2}|\w{3} \d{2}) (\d\d:\d\d:\d\d)\.?(\d+)? (?:Privoxy\()?([^\)\s]*)[\)]? ([\w -]*): (.*?)\r?$/) { + $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,42 +2415,42 @@ 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 $strict_checks = cli_option_is_set('strict-checks'); 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 + 'Connect:' => \&gather_loglevel_connect_stats, + 'Crunch:' => \&gather_loglevel_crunch_stats, + 'Error:' => \&gather_loglevel_error_stats, + 'Header:' => \&gather_loglevel_header_stats, + 'Request:' => \&gather_loglevel_request_stats, + ); + my %ignored_log_levels = ( + 'Actions:' => \&handle_loglevel_ignore, + 'CGI:' => \&handle_loglevel_ignore, + 'Fatal error:' => \&handle_loglevel_ignore, + 'Force:' => \&handle_loglevel_ignore, + 'Gif-Deanimate:' => \&handle_loglevel_ignore, + 'Info:' => \&handle_loglevel_ignore, + 'Re-Filter:' => \&handle_loglevel_ignore, + 'Received:' => \&handle_loglevel_ignore, + 'Redirect:' => \&handle_loglevel_ignore, + 'Unknown log level:' => \&handle_loglevel_ignore, + 'Writing:' => \&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; + (undef, $time_stamp, $thread, $log_level, $content) = split(/ /, $_, 5); - if (defined($log_level_handlers{$log_level})) { + # Skip LOG_LEVEL_CLF + next if (not defined($log_level) or $time_stamp eq "-"); - $content = $log_level_handlers{$log_level}($content, $thread); + if (defined($log_level_handlers{$log_level})) { - } else { + $content = $log_level_handlers{$log_level}($content, $thread); - die "No handler found for log level \"$log_level\"\n"; + } elsif ($strict_checks and not defined($ignored_log_levels{$log_level})) { - } + die "No handler found for: $_"; } } @@ -2168,12 +2458,35 @@ sub stats_loop () { } +sub unbreak_lines_only_loop() { + my $log_messages_reached = 0; + while (<>) { + chomp; + + # Log level other than LOG_LEVEL_CLF? + if (m/^(\d{4}-\d{2}-\d{2}|\w{3} \d{2}) (\d\d:\d\d:\d\d)\.?(\d+)? (?:Privoxy\()?([^\)\s]*)[\)]? ([\w -]*): (.*?)\r?$/ or + # LOG_LEVEL_CLF? + m/^((?:\d+\.\d+\.\d+\.\d+)) - - \[(.*)\] "(.*)" (\d+) (\d+)/) { + $log_messages_reached = 1; + print "\n"; + + } else { + # Wrapped message + $_ = "\n". $_ if /^(?:\d+\.\d+\.\d+\.\d+)/; + $_ = " " . $_; + } + s@
$@@; + print; + print "\n" unless $log_messages_reached; + } + print "\n"; +} + sub VersionMessage { my $version_message; $version_message .= 'Privoxy-Log-Parser ' . PRIVOXY_LOG_PARSER_VERSION . "\n"; - $version_message .= 'Copyright (C) 2007-2009 Fabian Keil ' . "\n"; - $version_message .= 'http://www.fabiankeil.de/sourcecode/privoxy-log-parser/' . "\n"; + $version_message .= 'https://www.fabiankeil.de/sourcecode/privoxy-log-parser/' . "\n"; print $version_message; } @@ -2186,9 +2499,14 @@ 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, + 'strict-checks' => CLI_OPTION_STRICT_CHECKS, + 'url-statistics-threshold' => CLI_OPTION_URL_STATISTICS_THRESHOLD, + 'unbreak-lines-only' => CLI_OPTION_UNBREAK_LINES_ONLY, + 'host-statistics-threshold'=> CLI_OPTION_HOST_STATISTICS_THRESHOLD, + 'show-complete-request-distribution' => CLI_OPTION_SHOW_COMPLETE_REQUEST_DISTRIBUTION, ); GetOptions ( @@ -2197,15 +2515,21 @@ 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'}, + 'strict-checks' => \$cli_options{'strict-checks'}, + 'unbreak-lines-only' => \$cli_options{'unbreak-lines-only'}, + 'url-statistics-threshold=i'=> \$cli_options{'url-statistics-threshold'}, + 'host-statistics-threshold=i'=> \$cli_options{'host-statistics-threshold'}, + 'show-complete-request-distribution' => \$cli_options{'show-complete-request-distribution'}, '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'); + $shorten_thread_ids = cli_option_is_set('shorten-thread-ids'); $line_end = get_line_end(); } @@ -2218,13 +2542,17 @@ sub help () { print << " EOF" Options and their default values if they have any: - [--accept-unknown-messages] + [--host-statistics-threshold $cli_options{'host-statistics-threshold'}] [--html-output] [--no-embedded-css] [--no-msecs] [--no-syntax-highlighting] + [--shorten-thread-ids] [--show-ineffective-filters] + [--show-complete-request-distribution] [--statistics] + [--unbreak-lines-only] + [--url-statistics-threshold $cli_options{'url-statistics-threshold'}] [--title $cli_options{'title'}] [--version] see "perldoc $0" for more information @@ -2244,7 +2572,10 @@ sub main () { print_intro(); - if (cli_option_is_set('statistics')) { + # XXX: should explicitly reject incompatible argument combinations + if (cli_option_is_set('unbreak-lines-only')) { + unbreak_lines_only_loop(); + } elsif (cli_option_is_set('statistics')) { stats_loop(); } else { parse_loop(); @@ -2261,9 +2592,10 @@ B - A parser and syntax-highlighter for Privoxy log messages =head1 SYNOPSIS -B [B<--accept-unknown-messages>] [B<--html-output>] -[B<--no-msecs>] [B<--no-syntax-higlighting>] [B<--show-ineffective-filters>] -[B<--version>] +B [B<--html-output>] +[B<--no-msecs>] [B<--no-syntax-higlighting>] [B<--statistics>] +[B<--shorten-thread-ids>] [B<--show-ineffective-filters>] +[B<--url-statistics-threshold>] [B<--version>] =head1 DESCRIPTION @@ -2287,8 +2619,9 @@ will hide the "filter foo caused 0 hits" message. =head1 OPTIONS -[B<--accept-unknown-messages>] Don't print warnings in case of unknown messages, -just don't highlight them. +[B<--host-statistics-threshold>] Only show the request count for a host +if it's above or equal to the given threshold. If the threshold is 0, host +statistics are disabled. [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. @@ -2302,14 +2635,39 @@ 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<--show-complete-request-distribution>] Show the complete client request +distribution in the B<--statistics> output. Without this option only the +ten most common numbers are shown. + [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<--strict-checks>] When generating statistics, look more careful at the +input data and abort if it is unexpected, even if it doesn't affect the +results. Significantly slows the parsing down and is not expected to catch +any problems that matter. +When highlighting, print warnings in case of unknown messages which can't be +properly highlighted. + +[B<--unbreak-lines-only>] Tries to fix lines that got messed up by a broken or +interestingly configured mail client and thus are no longer recognized properly. +Only fixes some breakage, but may be good enough or at least better than nothing. +Doesn't do anything else, so you probably want to pipe the output into +B again. + +[B<--url-statistics-threshold>] Only show the request count for a resource +if it's above or equal to the given threshold. If the threshold is 0, URL +statistics are disabled. + [B<--version>] Print version and exit. =head1 EXAMPLES