tools/privoxy-log-parser.pl

   1 #!/usr/bin/perl
   2
   3 ################################################################################
   4 # privoxy-log-parser
   5 #
   6 # A parser for Privoxy log messages. For incomplete documentation run
   7 # perldoc privoxy-log-parser(.pl), for fancy screenshots see:
   8 #
   9 # https://www.fabiankeil.de/sourcecode/privoxy-log-parser/
  10 #
  11 # TODO:
  12 #       - LOG_LEVEL_CGI, LOG_LEVEL_ERROR, LOG_LEVEL_WRITE content highlighting
  13 #       - create fancy statistics
  14 #       - grep through Privoxy sources to find unsupported log messages
  15 #       - hunt down substitutions that match content from variables which
  16 #         can contain stuff like ()?'[]
  17 #       - replace $h{'foo'} with h('foo') where possible
  18 #       - hunt down XXX comments instead of just creating them
  19 #       - add example log lines for every regex and mark them up for
  20 #         regression testing
  21 #       - Handle incomplete input without Perl warning about undefined variables.
  22 #       - Use generic highlighting function that takes a regex and the
  23 #         hash key as input.
  24 #       - Add --compress and --decompress options.
  25 #
  26 # Copyright (c) 2007-2021 Fabian Keil <fk@fabiankeil.de>
  27 #
  28 # Permission to use, copy, modify, and distribute this software for any
  29 # purpose with or without fee is hereby granted, provided that the above
  30 # copyright notice and this permission notice appear in all copies.
  31 #
  32 # THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES
  33 # WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF
  34 # MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR
  35 # ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES
  36 # WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN
  37 # ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF
  38 # OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
  39 ################################################################################
  40
  41 use strict;
  42 use warnings;
  43 use Getopt::Long;
  44
  45 use constant {
  46     PRIVOXY_LOG_PARSER_VERSION => '0.9.4',
  47     # Feel free to mess with these ...
  48     DEFAULT_BACKGROUND => 'black',  # Choose registered colour (like 'black')
  49     DEFAULT_TEXT_COLOUR => 'white', # Choose registered colour (like 'black')
  50     HEADER_DEFAULT_COLOUR => 'yellow',
  51     REGISTER_HEADERS_WITH_THE_SAME_COLOUR => 1,
  52
  53     CLI_OPTION_DETECT_INACTIVITY => 0,
  54     CLI_OPTION_DEFAULT_TO_HTML_OUTPUT => 0,
  55     CLI_OPTION_TITLE => 'Privoxy-Log-Parser in da house',
  56     CLI_OPTION_INACTIVITY_THRESHOLD => 100,
  57     CLI_OPTION_KEEP_DATE => 0,
  58     CLI_OPTION_NO_EMBEDDED_CSS => 0,
  59     CLI_OPTION_NO_MSECS => 0,
  60     CLI_OPTION_NO_SYNTAX_HIGHLIGHTING => 0,
  61     CLI_OPTION_SHORTEN_THREAD_IDS => 0,
  62     CLI_OPTION_SHOW_INEFFECTIVE_FILTERS => 0,
  63     CLI_OPTION_STATISTICS => 0,
  64     CLI_OPTION_STRICT_CHECKS => 0,
  65     CLI_OPTION_UNBREAK_LINES_ONLY => 0,
  66     CLI_OPTION_URL_STATISTICS_THRESHOLD => 0,
  67     CLI_OPTION_HOST_STATISTICS_THRESHOLD => 0,
  68     CLI_OPTION_SHOW_COMPLETE_REQUEST_DISTRIBUTION => 0,
  69
  70     SUPPRESS_SUCCEEDED_FILTER_ADDITIONS => 1,
  71     SHOW_SCAN_INTRO => 0,
  72     SHOW_FILTER_READIN_IN => 0,
  73     SUPPRESS_EMPTY_LINES => 1,
  74     SUPPRESS_SUCCESSFUL_CONNECTIONS => 1,
  75     SUPPRESS_GIF_NOT_CHANGED => 1,
  76     SUPPRESS_NEED_TO_DE_CHUNK_FIRST => 1,
  77
  78     DEBUG_HEADER_REGISTERING => 0,
  79     DEBUG_HEADER_HIGHLIGHTING => 0,
  80     DEBUG_TICKS => 0,
  81     DEBUG_PAINT_IT => 0,
  82     DEBUG_SUPPRESS_LOG_MESSAGES => 0,
  83
  84     PUNISH_MISSING_LOG_KNOWLEDGE_WITH_DEATH => 0,
  85     PUNISH_MISSING_HIGHLIGHT_KNOWLEDGE_WITH_DEATH => 1,
  86
  87     LOG_UNPARSED_LINES_TO_EXTRA_FILE => 0,
  88     ERROR_LOG_FILE => '/var/log/privoxy-log-parser',
  89
  90     # You better leave these alone unless you know what you're doing.
  91     COLOUR_RESET      => "\033[0;0m",
  92     ESCAPE => "\033[",
  93 };
  94
  95 # For performance reasons, these are global.
  96
  97 my $t;
  98 my %req; # request data from previous lines
  99 my %h;
 100 my %thread_colours;
 101 my @all_colours;
 102 my @time_colours;
 103 my $thread_colour_index = 0;
 104 my $header_colour_index = 0;
 105 my $time_colour_index = 0;
 106 my %header_colours;
 107 my $no_special_header_highlighting;
 108 my %reason_colours;
 109 my %h_colours;
 110 my $header_highlight_regex = '';
 111
 112 my $html_output_mode;
 113 my $keep_date_mode;
 114 my $no_msecs_mode; # XXX: should probably be removed
 115 my $shorten_thread_ids;
 116 my $line_end;
 117
 118 sub prepare_our_stuff() {
 119
 120     # Syntax Higlight hash
 121     @all_colours = (
 122         'red', 'green', 'brown', 'blue', 'purple', 'cyan',
 123         'light_gray', 'light_red', 'light_green', 'yellow',
 124         'light_blue', 'pink', 'light_cyan', 'white'
 125     );
 126
 127     %h = (
 128         # LOG_LEVEL
 129         Info            => 'blue',
 130         Header          => 'green',
 131         Filter          => 'purple', # XXX: Used?
 132         'Re-Filter'     => 'purple',
 133         Connect         => 'brown',
 134         Request         => 'light_cyan',
 135         Tagging         => 'purple',
 136         CGI             => 'light_green',
 137         Redirect        => 'cyan',
 138         Error           => 'light_red',
 139         Crunch          => 'cyan',
 140         'Fatal error'   => 'light_red',
 141         'Gif-Deanimate' => 'blue',
 142         Force           => 'red',
 143         Writing         => 'light_green',
 144         Received        => 'yellow',
 145         Actions         => 'yellow',
 146         # ----------------------
 147         URL                  => 'yellow',
 148         path                 => 'brown',
 149         request_             => 'brown', # host+path but no protocol
 150         'ip-address'         => 'yellow',
 151         Number               => 'yellow',
 152         Standard             => 'reset',
 153         Truncation           => 'light_red',
 154         Status               => 'brown',
 155         Timestamp            => 'brown',
 156         Crunching            => 'light_red',
 157         crunched             => 'light_red',
 158         'Request-Line'       => 'pink',
 159         method               => 'purple',
 160         destination          => 'yellow',
 161         'http-version'       => 'pink',
 162         'crunch-pattern'     => 'pink',
 163         not                  => 'brown',
 164         file                 => 'brown',
 165         signal               => 'yellow',
 166         version              => 'green',
 167         'program-name'       => 'cyan',
 168         port                 => 'red',
 169         host                 => 'red',
 170         warning              => 'light_red',
 171         debug                => 'light_red',
 172         filter               => 'green',
 173         tag                  => 'green',
 174         tagger               => 'green',
 175         'status-message'     => 'light_cyan',
 176         'status-code'        => 'yellow',
 177         'invalid-request'    => 'light_red',
 178         'hits'               => 'yellow',
 179         error                => 'light_red',
 180         'rewritten-URL'      => 'light_red',
 181         'pcrs-delimiter'     => 'light_red',
 182         'ignored'            => 'light_red',
 183         'action-bits-update' => 'light_red',
 184         'http-downgrade'     => 'light_red',
 185         'configuration-line' => 'red',
 186         'content-type'       => 'yellow',
 187         'HOST'               => HEADER_DEFAULT_COLOUR,
 188     );
 189
 190     %h_colours = %h;
 191
 192     # Header colours need their own hash so the keys can be accessed properly
 193     %header_colours = (
 194         # Prefilled with headers that should not appear with default header colours
 195         Cookie => 'light_red',
 196         'Set-Cookie' => 'light_red',
 197         Warning => 'light_red',
 198         Default => HEADER_DEFAULT_COLOUR,
 199     );
 200
 201     # Crunch reasons need their own hash as well
 202     %reason_colours = (
 203         'Unsupported HTTP feature'               => 'light_red',
 204         Blocked                                  => 'light_red',
 205         Untrusted                                => 'light_red',
 206         Redirected                               => 'green',
 207         'CGI Call'                               => 'white',
 208         'DNS failure'                            => 'red',
 209         'Forwarding failed'                      => 'light_red',
 210         'Connection failure'                     => 'light_red',
 211         'Out of memory (may mask other reasons)' => 'light_red',
 212         'No reason recorded'                     => 'light_red',
 213     );
 214
 215     @time_colours = ('white', 'light_gray');
 216
 217     # Translate highlight strings into highlight code
 218     prepare_highlight_hash(\%header_colours);
 219     prepare_highlight_hash(\%reason_colours);
 220     prepare_highlight_hash(\%h);
 221     prepare_colour_array(\@all_colours);
 222     prepare_colour_array(\@time_colours);
 223     init_css_colours();
 224
 225     init_stats();
 226 }
 227
 228 sub paint_it($) {
 229 ###############################################################
 230 # Takes a colour string and returns an ANSI escape sequence
 231 # (unless --no-syntax-highlighting is used).
 232 # XXX: The Rolling Stones reference has to go.
 233 ###############################################################
 234
 235     my $colour = shift;
 236
 237     return "" if cli_option_is_set('no-syntax-highlighting');
 238
 239     my %light = (
 240         black       => 0,
 241         red         => 0,
 242         green       => 0,
 243         brown       => 0,
 244         blue        => 0,
 245         purple      => 0,
 246         cyan        => 0,
 247         light_gray  => 0,
 248         gray        => 0,
 249         dark_gray   => 1,
 250         light_red   => 1,
 251         light_green => 1,
 252         yellow      => 1,
 253         light_blue  => 1,
 254         pink        => 1,
 255         light_cyan  => 1,
 256         white       => 1,
 257     );
 258
 259     my %text = (
 260         black       => 30,
 261         red         => 31,
 262         green       => 32,
 263         brown       => 33,
 264         blue        => 34,
 265         purple      => 35,
 266         cyan        => 36,
 267         gray        => 37,
 268         light_gray  => 37,
 269         dark_gray   => 30,
 270         light_red   => 31,
 271         light_green => 32,
 272         yellow      => 33,
 273         light_blue  => 34,
 274         pink        => 35,
 275         light_cyan  => 36,
 276         white       => 37,
 277     );
 278
 279     my $bg_code = get_background();
 280     my $colour_code;
 281     our $default = default_colours();
 282
 283     if (defined($text{$colour})) {
 284         $colour_code  = ESCAPE;
 285         $colour_code .= $text{$colour};
 286         $colour_code .= ";";
 287         $colour_code .= $light{$colour} ? "1" : "2";
 288         $colour_code .= ";";
 289         $colour_code .= $bg_code;
 290         $colour_code .= "m";
 291         debug_message $colour . " is \'" . $colour_code . $colour . $default . "\'" if DEBUG_PAINT_IT;
 292
 293     } elsif ($colour =~ /reset/) {
 294
 295         $colour_code = default_colours();
 296
 297     } else {
 298
 299         die "What's $colour supposed to mean?\n";
 300     }
 301
 302     return $colour_code;
 303 }
 304
 305 sub get_semantic_html_markup($) {
 306 ###############################################################
 307 # Takes a string and returns a span element
 308 ###############################################################
 309
 310     my $type = shift;
 311     my $code;
 312
 313     if ($type =~ /Standard/) {
 314         $code = '</span>';
 315     } else {
 316         $type = lc($type);
 317         $code = '<span title="' . $type . '" class="' . $type . '">';
 318     }
 319
 320     return $code;
 321 }
 322
 323 sub cli_option_is_set($) {
 324
 325     our %cli_options;
 326     my $cli_option = shift;
 327
 328     die "Unknown CLI option: $cli_option" unless defined $cli_options{$cli_option};
 329
 330     return $cli_options{$cli_option};
 331 }
 332
 333 sub get_html_title() {
 334
 335     our %cli_options;
 336     return $cli_options{'title'};
 337
 338 }
 339
 340 sub init_css_colours() {
 341
 342     our %css_colours = (
 343         black       => "000",
 344         red         => "F00",
 345         green       => "0F0",
 346         brown       => "C90",
 347         blue        => "0F0",
 348         purple      => "F06", # XXX: wrong
 349         cyan        => "F09", # XXX: wrong
 350         light_gray  => "999",
 351         gray        => "333",
 352         dark_gray   => "222",
 353         light_red   => "F33",
 354         light_green => "33F",
 355         yellow      => "FF0",
 356         light_blue  => "30F",
 357         pink        => "F0F",
 358         light_cyan  => "66F",
 359         white       => "FFF",
 360     );
 361 }
 362
 363 sub get_css_colour($) {
 364
 365    our %css_colours;
 366    my $colour = shift;
 367
 368    die "What's $colour supposed to mean?\n" unless defined($css_colours{$colour});
 369
 370    return '#' . $css_colours{$colour};
 371 }
 372
 373 sub get_css_line($) {
 374
 375     my $class = shift;
 376     my $css_line;
 377
 378     $css_line .= '.' . lc($class) . ' {'; # XXX: lc() shouldn't be necessary
 379     die "What's $class supposed to mean?\n" unless defined($h_colours{$class});
 380     $css_line .= 'color:' . get_css_colour($h_colours{$class}) . ';';
 381     $css_line .= 'background-color:' . get_css_colour(DEFAULT_BACKGROUND) . ';';
 382     $css_line .= '}' . "\n";
 383
 384     return $css_line;
 385 }
 386
 387 sub get_css_line_for_colour($) {
 388
 389     my $colour = shift;
 390     my $css_line;
 391
 392     $css_line .= '.' . lc($colour) . ' {'; # XXX: lc() shouldn't be necessary
 393     $css_line .= 'color:' . get_css_colour($colour) . ';';
 394     $css_line .= 'background-color:' . get_css_colour(DEFAULT_BACKGROUND) . ';';
 395     $css_line .= '}' . "\n";
 396
 397     return $css_line;
 398 }
 399
 400 # XXX: Wrong solution
 401 sub get_missing_css_lines() {
 402
 403     my $css_line;
 404
 405     $css_line .= '.' . 'default' . ' {';
 406     $css_line .= 'color:' . HEADER_DEFAULT_COLOUR . ';';
 407     $css_line .= 'background-color:' . get_css_colour(DEFAULT_BACKGROUND) . ';';
 408     $css_line .= '}' . "\n";
 409
 410     return $css_line;
 411 }
 412
 413 sub get_css() {
 414
 415     our %css_colours; #XXX: Wrong solution
 416
 417     my $css = '';
 418
 419     $css .= '.privoxy-log {';
 420     $css .= 'color:' . get_css_colour(DEFAULT_TEXT_COLOUR) . ';';
 421     $css .= 'background-color:' . get_css_colour(DEFAULT_BACKGROUND) . ';';
 422     $css .= '}' . "\n";
 423
 424     foreach my $key (keys %h_colours) {
 425
 426         next if ($h_colours{$key} =~ m/reset/); #XXX: Wrong solution.
 427         $css .= get_css_line($key);
 428
 429     }
 430
 431     foreach my $colour (keys %css_colours) {
 432
 433         $css .= get_css_line_for_colour($colour);
 434
 435     }
 436
 437     $css .= get_missing_css_lines(); #XXX: Wrong solution
 438
 439     return $css;
 440 }
 441
 442 sub print_intro() {
 443
 444     my $intro = '';
 445
 446     if (cli_option_is_set('html-output')) {
 447
 448         my $title = get_html_title();
 449
 450         $intro .= '<html><head>';
 451         $intro .= '<title>' . $title . '</title>';
 452         $intro .= '<style>' . get_css() . '</style>' unless cli_option_is_set('no-embedded-css');
 453         $intro .= '</head><body>';
 454         $intro .= '<h1>' . $title . '</h1><p class="privoxy-log">';
 455
 456         print $intro;
 457     }
 458 }
 459
 460 sub print_outro() {
 461
 462     my $outro = '';
 463
 464     if (cli_option_is_set('html-output')) {
 465
 466         $outro = '</p></body></html>';
 467         print $outro;
 468
 469     }
 470 }
 471
 472 sub get_line_end() {
 473     return cli_option_is_set('html-output') ? "<br>\n" : "\n";
 474 }
 475
 476 sub get_colour_html_markup($) {
 477 ###############################################################
 478 # Takes a colour string a span element. XXX: WHAT?
 479 # XXX: This function shouldn't be necessary, the
 480 # markup should always be semantically correct.
 481 ###############################################################
 482
 483     my $type = shift;
 484     my $code;
 485
 486     if ($type =~ /Standard/) {
 487         $code = '</span>';
 488     } else {
 489         $code = '<span class="' . lc($type) . '">';
 490     }
 491
 492     return $code;
 493 }
 494
 495 sub default_colours() {
 496     # XXX: Properly
 497     our $bg_code;
 498     return reset_colours();
 499 }
 500
 501 sub show_colours() {
 502     # XXX: Implement
 503 }
 504
 505 sub reset_colours() {
 506     return ESCAPE . "0m";
 507 }
 508
 509 sub set_background($) {
 510
 511     my $colour = shift;
 512     our $bg_code;
 513     my %backgrounds = (
 514               black       => "40",
 515               red         => "41",
 516               green       => "42",
 517               brown       => "43",
 518               blue        => "44",
 519               magenta     => "45",
 520               cyan        => "46",
 521               white       => "47",
 522               default     => "49",
 523     );
 524
 525     if (defined($backgrounds{$colour})) {
 526         $bg_code = $backgrounds{$colour};
 527     } else {
 528         die "Invalid background colour: " . $colour;
 529     }
 530 }
 531
 532 sub get_background() {
 533     return our $bg_code;
 534 }
 535
 536 sub prepare_highlight_hash($) {
 537     my $ref = shift;
 538
 539     foreach my $key (keys %$ref) {
 540         $$ref{$key} = $html_output_mode ?
 541             get_semantic_html_markup($key) :
 542             paint_it($$ref{$key});
 543     }
 544 }
 545
 546 sub prepare_colour_array($) {
 547     my $ref = shift;
 548
 549     foreach my $i (0 ... @$ref - 1) {
 550         $$ref[$i] = $html_output_mode ?
 551             get_colour_html_markup($$ref[$i]) :
 552             paint_it($$ref[$i]);
 553     }
 554 }
 555
 556 sub found_unknown_content($) {
 557
 558     my $unknown = shift;
 559     my $message;
 560
 561     return unless cli_option_is_set('strict-checks');
 562
 563     return if ($unknown =~ /\[too long, truncated\]$/);
 564
 565     $message = "found_unknown_content: Don't know how to highlight: ";
 566     # Break line so the log file can later be parsed as Privoxy log file again
 567     $message .= '"' . $unknown . '"' . " in:\n";
 568     $message .= $req{$t}{'log-message'};
 569     debug_message($message);
 570     log_parse_error($req{$t}{'log-message'});
 571
 572     die "Unworthy content parser" if PUNISH_MISSING_LOG_KNOWLEDGE_WITH_DEATH;
 573 }
 574
 575 sub log_parse_error($) {
 576
 577     my $message = shift;
 578
 579     if (LOG_UNPARSED_LINES_TO_EXTRA_FILE) {
 580         open(my $errorlog_fd, ">>", ERROR_LOG_FILE) || die "Writing " . ERROR_LOG_FILE . " failed";
 581         print $errorlog_fd $message;
 582         close($errorlog_fd);
 583     }
 584 }
 585
 586 sub debug_message(@) {
 587     my @message = @_;
 588
 589     print $h{'debug'} . "@message" . $h{'Standard'} . "\n";
 590 }
 591
 592 ################################################################################
 593 # highlighter functions that aren't loglevel-specific
 594 ################################################################################
 595
 596 sub h($) {
 597
 598     # Get highlight marker
 599     my $highlight = shift; # XXX: Stupid name;
 600     my $result = '';
 601     my $message;
 602
 603     if (defined($highlight)) {
 604
 605         $result = $h{$highlight};
 606
 607     } else {
 608
 609         $message = "h: Don't recognize highlighter $highlight.";
 610         debug_message($message);
 611         log_parser_error($message);
 612         die "Unworthy highlighter function" if PUNISH_MISSING_HIGHLIGHT_KNOWLEDGE_WITH_DEATH;
 613     }
 614
 615     return $result;
 616 }
 617
 618 sub highlight_known_headers($) {
 619
 620     my $content = shift;
 621
 622     debug_message("Searching $content for things to highlight.") if DEBUG_HEADER_HIGHLIGHTING;
 623
 624     if ($content =~ m/(?<=\s)($header_highlight_regex):/) {
 625         my $header = $1;
 626         $content =~ s@(?<=[\s|'])($header)(?=:)@$header_colours{$header}$1$h{'Standard'}@ig;
 627         debug_message("Highlighted '$header' in '$content'") if DEBUG_HEADER_HIGHLIGHTING;
 628     }
 629
 630     return $content;
 631 }
 632
 633 sub highlight_matched_request_line($$) {
 634
 635     my $result = shift; # XXX: Stupid name;
 636     my $regex = shift;
 637     if ($result =~ m@(.*)($regex)(.*)@) {
 638         $result = $1 . highlight_request_line($2) . $3
 639     }
 640     return $result;
 641 }
 642
 643 sub highlight_request_line($) {
 644
 645     my $rl = shift;
 646     my ($method, $url, $http_version);
 647
 648     #GET http://images.sourceforge.net/sfx/icon_warning.gif HTTP/1.1
 649     if ($rl =~ m/Invalid request/ or $rl =~ m/Failed reading chunked client body/) {
 650
 651         $rl = h('invalid-request') . $rl . h('Standard');
 652
 653     } elsif ($rl =~ m/^([-\w]+) (.*) (HTTP\/\d+\.\d+)/) {
 654
 655         # XXX: might not match in case of HTTP method fuzzing.
 656         # XXX: save these: ($method, $path, $http_version) = ($1, $2, $3);
 657         $rl =~ s@^(\w+)@$h{'method'}$1$h{'Standard'}@;
 658         if ($rl =~ /http:\/\//) {
 659             $rl = highlight_matched_url($rl, '[^\s]*(?=\sHTTP)');
 660         } else {
 661             $rl = highlight_matched_pattern($rl, 'request_', '[^\s]*(?=\sHTTP)');
 662         }
 663
 664         $rl =~ s@(HTTP\/\d\.\d)$@$h{'http-version'}$1$h{'Standard'}@;
 665
 666     } elsif ($rl =~ m/\.\.\. \[too long, truncated\]$/) {
 667
 668         $rl =~ s@^(\w+)@$h{'method'}$1$h{'Standard'}@;
 669         $rl = highlight_matched_url($rl, '[^\s]*(?=\.\.\.)');
 670
 671     } elsif ($rl =~ m/^ $/) {
 672
 673         $rl = h('error') . "No request line specified!" . h('Standard');
 674
 675     } else {
 676
 677         debug_message ("Can't parse request line: $rl");
 678
 679     }
 680
 681     return $rl;
 682 }
 683
 684 sub highlight_response_line($) {
 685
 686     my $rl = shift;
 687     my ($http_version, $status_code, $status_message);
 688
 689     #HTTP/1.1 200 OK
 690     #ICY 200 OK
 691
 692     # TODO: Mark different status codes differently
 693
 694     if ($rl =~ m/((?:HTTP\/\d\.\d|ICY)) (\d+) (.*)/) {
 695         ($http_version, $status_code, $status_message) = ($1, $2, $3);
 696     } else {
 697         debug_message ("Can't parse response line: $rl") and die 'Fix this';
 698     }
 699
 700     # Rebuild highlighted
 701     $rl= "";
 702     $rl .= h('http-version') . $http_version . h('Standard');
 703     $rl .= " ";
 704     $rl .= h('status-code') . $status_code . h('Standard');
 705     $rl .= " ";
 706     $rl .= h('status-message') . $status_message . h('Standard');
 707
 708     return $rl;
 709 }
 710
 711 sub highlight_matched_url($$) {
 712
 713     my $result = shift; # XXX: Stupid name;
 714     my $regex = shift;
 715
 716     #print "Got $result, regex ($regex)\n";
 717
 718     if ($result =~ m@(.*?)($regex)(.*)@) {
 719         $result = $1 . highlight_url($2) . $3;
 720         #print "Now the result is $result\n";
 721     }
 722
 723     return $result;
 724 }
 725
 726 sub highlight_matched_host($$) {
 727
 728     my ($result, $regex) = @_; # XXX: result ist stupid name;
 729
 730     if ($result =~ m@(.*?)($regex)(.*)@) {
 731         $result = $1 . $h{host} . $2 . $h{Standard} . $3;
 732     }
 733
 734     return $result;
 735 }
 736
 737 sub highlight_matched_pattern($$$) {
 738
 739     my $result = shift; # XXX: Stupid name;
 740     my $key = shift;
 741     my $regex = shift;
 742
 743     die "Unknown key $key" unless defined $h{$key};
 744
 745     if ($result =~ m@(.*?)($regex)(.*)@) {
 746         $result = $1 . h($key) . $2 . h('Standard') . $3;
 747     }
 748
 749     return $result;
 750 }
 751
 752 sub highlight_matched_path($$) {
 753
 754     my $result = shift; # XXX: Stupid name;
 755     my $regex = shift;
 756
 757     if ($result =~ m@(.*?)($regex)(.*)@) {
 758         $result = $1 . h('path') . $2 . h('Standard') . $3;
 759     }
 760
 761     return $result;
 762 }
 763
 764 sub highlight_url($) {
 765
 766     my $url = shift;
 767
 768     if ($html_output_mode) {
 769
 770         $url = '<a href="' . $url . '">' . $url . '</a>';
 771
 772     } else {
 773
 774         $url = h('URL') . $url . h('Standard');
 775
 776     }
 777
 778     return $url;
 779 }
 780
 781 sub update_header_highlight_regex($) {
 782
 783     my $header = shift;
 784     my $headers = join ('|', keys %header_colours);
 785
 786     $header_highlight_regex = qr/$headers/;
 787     print "Registering '$header'\n" if DEBUG_HEADER_HIGHLIGHTING;
 788 }
 789
 790 ################################################################################
 791 # loglevel-specific highlighter functions
 792 ################################################################################
 793
 794 sub handle_loglevel_header($) {
 795
 796     my $c = shift;
 797
 798     if ($c =~ /^scan:/) {
 799
 800         if ($c =~ m/^scan: ([^: ]+):/) {
 801
 802             # Register new headers
 803             # scan: Accept: image/png,image/*;q=0.8,*/*;q=0.5
 804             my $header = $1;
 805             if (!defined($header_colours{$header}) and $header =~ /^[\d\w-]*$/) {
 806                 debug_message "Registering previously unknown header $1" if DEBUG_HEADER_REGISTERING;
 807
 808                 if (REGISTER_HEADERS_WITH_THE_SAME_COLOUR) {
 809                     $header_colours{$header} =  $header_colours{'Default'};
 810                 } else {
 811                     $header_colours{$header} = $all_colours[$header_colour_index % @all_colours];
 812                     $header_colour_index++;
 813                 }
 814                 update_header_highlight_regex($header);
 815             }
 816
 817         } elsif ($c =~ m/^(scan: )(\w+ .+ HTTP\/\d\.\d)/) {
 818
 819             # scan: GET http://p.p/ HTTP/1.1
 820             $c = $1 . highlight_request_line($2);
 821
 822         } elsif ($c =~ m/^(scan: )((?:HTTP\/\d\.\d|ICY) (\d+) (.*))/) {
 823
 824             # scan: HTTP/1.1 200 OK
 825             $req{$t}{'response_line'} = $2;
 826             $req{$t}{'status_code'} = $3;
 827             $req{$t}{'status_message'} = $4;
 828             $c = $1 . highlight_response_line($req{$t}{'response_line'});
 829         }
 830
 831     } elsif ($c =~ m/^Crunching (?:server|client) header: .* \(contains: ([^\)]*)\)/) {
 832
 833         # Crunching server header: Set-Cookie: trac_form_token=d5308c34e16d15e9e301a456; (contains: Cookie:)
 834         $c =~ s@(?<=contains: )($1)@$h{'crunch-pattern'}$1$h{'Standard'}@;
 835         $c =~ s@(Crunching)@$h{$1}$1$h{'Standard'}@;
 836
 837     } elsif ($c =~ m/^New host is: ([^\s]*)\./) {
 838
 839         # New host is: trac.vidalia-project.net. Crunching Referer: http://www.vidalia-project.net/!
 840         $c = highlight_matched_host($c, '(?<=New host is: )[^\s]+(?=\.)');
 841         $c = highlight_matched_url($c, '(?<=Crunching Referer: )[^\s!]+');
 842
 843     } elsif ($c =~ m/^Text mode enabled by force. (Take cover)!/) {
 844
 845         # Text mode enabled by force. Take cover!
 846         $c =~ s@($1)@$h{'warning'}$1$h{'Standard'}@;
 847
 848     } elsif ($c =~ m/^(New HTTP Request-Line: )(.*)/) {
 849
 850         # New HTTP Request-Line: GET http://www.privoxy.org/ HTTP/1.1
 851         $c = $1 . highlight_request_line($2);
 852
 853     } elsif ($c =~ m/^Adjust(ed)? Content-Length to \d+/) {
 854
 855         # Adjusted Content-Length to 2132
 856         # Adjust Content-Length to 33533
 857         $c =~ s@(?<=Content-Length to )(\d+)@$h{'Number'}$1$h{'Standard'}@;
 858         $c = highlight_known_headers($c);
 859
 860     } elsif ($c =~ m/^Destination extracted from "Host:" header. New request URL:/) {
 861
 862         # Destination extracted from "Host:" header. New request URL: http://www.cccmz.de/~ridcully/blog/
 863         $c = highlight_matched_url($c, '(?<=New request URL: ).*');
 864
 865     } elsif ($c =~ m/^Couldn\'t parse:/) {
 866
 867         # XXX: These should probable be logged with LOG_LEVEL_ERROR
 868         # Couldn't parse: If-Modified-Since: Wed, 21 Mar 2007 16:34:50 GMT (crunching!)
 869         # Couldn't parse: at, 24 Mar 2007 13:46:21 GMT in If-Modified-Since: Sat, 24 Mar 2007 13:46:21 GMT (crunching!)
 870         $c =~ s@^(Couldn\'t parse)@$h{'error'}$1$h{'Standard'}@;
 871
 872     } elsif ($c =~ /^Tagger \'([^\']*)\' added tag \'([^\']*)\'/ or
 873              $c =~ m/^Adding tag \'([^\']*)\' created by header tagger \'([^\']*)\'/) {
 874
 875         # Adding tag 'GET request' created by header tagger 'method-man' (XXX: no longer used)
 876         # Tagger 'revalidation' added tag 'REVALIDATION-REQUEST'. No action bit update necessary.
 877         # Tagger 'revalidation' added tag 'REVALIDATION-REQUEST'. Action bits updated accordingly.
 878
 879         # XXX: Save tag and tagger
 880
 881         $c =~ s@(?<=^Tagger \')([^\']*)@$h{'tagger'}$1$h{'Standard'}@;
 882         $c =~ s@(?<=added tag \')([^\']*)@$h{'tag'}$1$h{'Standard'}@;
 883         $c =~ s@(?<=Action bits )(updated)@$h{'action-bits-update'}$1$h{'Standard'}@;
 884         $no_special_header_highlighting = 1;
 885
 886     } elsif ($c =~ /^Tagger \'([^\']*)\' didn['']t add tag \'([^\']*)\'/) {
 887
 888         # Tagger 'revalidation' didn't add tag 'REVALIDATION-REQUEST'. Tag already present
 889         # XXX: Save tag and tagger
 890
 891         $c =~ s@(?<=^Tagger \')([^\']*)@$h{'tag'}$1$h{'Standard'}@;
 892         $c =~ s@(?<=didn['']t add tag \')([^\']*)@$h{'tagger'}$1$h{'Standard'}@;
 893
 894     } elsif ($c =~ m/^(?:scan:|Randomiz|addh:|Adding:|Removing:|Referer:|Modified:|Accept-Language header|[Cc]ookie)/
 895           or $c =~ m/^(Text mode is already enabled|Denied request with NULL byte|Replaced:|add-unique:)/
 896           or $c =~ m/^(Crunched (incoming|outgoing) cookie|Suppressed offer|Accepted the client)/
 897           or $c =~ m/^(addh-unique|Referer forged to)/
 898           or $c =~ m/^Downgraded answer to HTTP\/1.0/
 899           or $c =~ m/^Parameter: \+hide-referrer\{[^\}]*\} is a bad idea, but I don\'t care./
 900           or $c =~ m/^Referer (?:overwritten|replaced) with: Referer: / #XXX: should this be highlighted?
 901           or $c =~ m/^Referer crunched!/
 902           or $c =~ m/^crunched x-forwarded-for!/
 903           or $c =~ m/^crunched From!/
 904           or $c =~ m/^ modified$/
 905           or $c =~ m/^Content filtering is enabled. Crunching:/
 906           or $c =~ m/^force-text-mode overruled the client/
 907           or $c =~ m/^Server time in the future\./
 908           or $c =~ m/^content-disposition header crunched and replaced with:/i
 909           or $c =~ m/^Reducing white space in /
 910           or $c =~ m/^Ignoring single quote in /
 911           or $c =~ m/^Converting tab to space in /
 912           or $c =~ m/A HTTP\/1\.1 response without/
 913           or $c =~ m/Disabled filter mode on behalf of the client/
 914           or $c =~ m/Keeping the (?:server|client) header /
 915           or $c =~ m/Content modified with no Content-Length header set/
 916           or $c =~ m/^Appended client IP address to/
 917           or $c =~ m/^Removing 'Connection: close' to imply keep-alive./
 918           or $c =~ m/^keep-alive support is disabled/
 919           or $c =~ m/^Continue hack in da house/
 920           or $c =~ m/^Merged multiple header lines to:/
 921           or $c =~ m/^Added header: /
 922           or $c =~ m/^Enlisting (?:sorted|left-over) header/
 923           or $c =~ m/^Multiple Content-Type headers detected. Removing and ignoring: Content-Type:/
 924             )
 925     {
 926         # XXX: Some of these may need highlighting
 927
 928         # Modified: User-Agent: Mozilla/5.0 (X11; U; SunOS i86pc; pl-PL; rv:1.8.1.1) Gecko/20070214 Firefox/2.0.0.1
 929         # Accept-Language header crunched and replaced with: Accept-Language: pl-pl
 930         # cookie 'Set-Cookie: eZSessionCookie=07bfec287c197440d299f81580593c3d; \
 931         #  expires=Thursday, 12-Apr-07 15:16:18 GMT; path=/' send by \
 932         #  http://wirres.net/article/articleview/4265/1/6/ appears to be using time format 1 (XXX: gone with the wind)
 933         # Cookie rewritten to a temporary one: Set-Cookie: NSC_gffe-iuuq-mc-wtfswfs=8efb33a53660;path=/
 934         # Text mode is already enabled
 935         # Denied request with NULL byte(s) turned into line break(s)
 936         # Replaced: 'Connection: Yo, home to Bel Air' with 'Connection: close'
 937         # addh-unique: Host: people.freebsd.org
 938         # Suppressed offer to compress content
 939         # Crunched incoming cookie -- yum!
 940         # Accepted the client's request to fetch without filtering.
 941         # Crunched outgoing cookie: Cookie: PREF=ID=6cf0abd347b30262:TM=1173357617:LM=1173357617:S=jZypyyJ7LPiwFi1_
 942         # addh-unique: Host: subkeys.pgp.net:11371
 943         # Referer forged to: Referer: http://10.0.0.1/
 944         # Downgraded answer to HTTP/1.0
 945         # Parameter: +hide-referrer{pille-palle} is a bad idea, but I don't care.
 946         # Referer overwritten with: Referer: pille-palle
 947         # Referer replaced with: Referer: pille-palle
 948         # crunched x-forwarded-for!
 949         # crunched From!
 950         #  modified # XXX: pretty stupid log message
 951         # Content filtering is enabled. Crunching: 'Range: 1234-5678' to prevent range-mismatch problems
 952         # force-text-mode overruled the client's request to fetch without filtering!
 953         # Server time in the future.
 954         # content-disposition header crunched and replaced with: content-disposition: filename=baz
 955         # Content-Disposition header crunched and replaced with: content-disposition: filename=baz
 956         # Reducing white space in 'X-LWS-Test: "This  is  quoted" this is not "this  is  " but " this again   is  not'
 957         # Ignoring single quote in 'X-LWS-Test: "This  is  quoted" this is not "this  is  " but "  this again   is  not'
 958         # Converting tab to space in 'X-LWS-Test:   "This  is  quoted" this   is  not "this  is  "  but  "\
 959         #  this again   is  not'
 960         # A HTTP/1.1 response without Connection header implies keep-alive.
 961         # Disabled filter mode on behalf of the client.
 962         # Keeping the server header 'Connection: keep-alive' around.
 963         # Keeping the client header 'Connection: close' around. The connection will not be kept alive.
 964         # Keeping the client header 'Connection: keep-alive' around. The connection will be kept alive if possible.
 965         # Content modified with no Content-Length header set. Creating a fake one for adjustment later on.
 966         # Appended client IP address to X-Forwarded-For: 10.0.0.2, 10.0.0.1
 967         # Removing 'Connection: close' to imply keep-alive.
 968         # keep-alive support is disabled. Crunching: Keep-Alive: 300.
 969         # Continue hack in da house.
 970         # Merged multiple header lines to: 'X-FORWARDED-PROTO: http X-HOST: 127.0.0.1'
 971         # Added header: Content-Encoding: deflate
 972         # Enlisting sorted header User-Agent: Mozilla/5.0 (X11; SunOS i86pc; rv:10.0.3) Gecko/20100101 Firefox/10.0.3
 973         # Enlisting left-over header Connection: close
 974         # Multiple Content-Type headers detected. Removing and ignoring: Content-Type: text/html
 975
 976     } elsif ($c =~ m/^scanning headers for:/) {
 977
 978         return '' unless SHOW_SCAN_INTRO;
 979
 980     } elsif ($c =~ m/^[Cc]runch(ing|ed)|crumble crunched:/) {
 981         # crunched User-Agent!
 982         # Crunching: Content-Encoding: gzip
 983
 984         $c =~ s@(Crunching|crunched)@$h{$1}$1$h{'Standard'}@;
 985
 986     } elsif ($c =~ m/^Offending request data with NULL bytes turned into \'°\' characters:/) {
 987
 988         # Offending request data with NULL bytes turned into '°' characters: °°n°°(°°°
 989
 990         $c = h('warning') . $c . h('Standard');
 991
 992     } elsif ($c =~ m/^(Transforming \")(.*?)(\" to \")(.*?)(\")/) {
 993
 994         # Transforming "Proxy-Authenticate: Basic realm="Correos Proxy Server"" to\
 995         #  "Proxy-Authenticate: Basic realm="Correos Proxy Server""
 996
 997        $c =~ s@(?<=^Transforming \")(.*)(?=\" to)@$h{'Header'}$1$h{'Standard'}@;
 998        $c =~ s@(?<=to \")(.*)(?=\")@$h{'Header'}$1$h{'Standard'}@;
 999
1000     } elsif ($c =~ m/^Removing empty header/) {
1001
1002         # Removing empty header
1003         # Ignore for now
1004
1005     } elsif ($c =~ m/^Content-Type: .* not replaced/) {
1006
1007         # Content-Type: application/octet-stream not replaced. It doesn't look like text.\
1008         #  Enable force-text-mode if you know what you're doing.
1009         # XXX: Could highlight more here.
1010         $c =~ s@(?<=^Content-Type: )(.*)(?= not replaced)@$h{'content-type'}$1$h{'Standard'}@;
1011
1012     } elsif ($c =~ m/^(Server|Client) keep-alive timeout is/) {
1013
1014        # Server keep-alive timeout is 5. Sticking with 10.
1015        # Client keep-alive timeout is 20. Sticking with 10.
1016
1017        $c =~ s@(?<=timeout is )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1018        $c =~ s@(?<=Sticking with )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1019
1020     } elsif ($c =~ m/^Reducing keep-alive timeout/) {
1021
1022        # Reducing keep-alive timeout from 60 to 10.
1023
1024        $c =~ s@(?<= from )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1025        $c =~ s@(?<= to )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1026
1027     } elsif ($c =~ m/^Killed all-caps Host header line: HOST:/) {
1028
1029        # Killed all-caps Host header line: HOST: bestproxydb.com
1030        $c = highlight_matched_host($c, '(?<=HOST: )[^\s]+');
1031        $c = highlight_matched_pattern($c, 'HOST', 'HOST');
1032
1033     } else {
1034
1035         found_unknown_content($c);
1036     }
1037
1038     # Highlight headers
1039     unless ($c =~ m/^Transforming/) {
1040         $c = highlight_known_headers($c) unless $no_special_header_highlighting;
1041     }
1042
1043     return $c;
1044 }
1045
1046 sub handle_loglevel_re_filter($) {
1047
1048     my $content = shift;
1049     my $c = $content;
1050     my $key;
1051
1052     if ($c =~ m/^(?:re_)?filtering ([^\s]+) \(size (\d+)\) with (?:filter )?\'?([^\s]+?)\'? produced (\d+) hits \(new size (\d+)\)/) {
1053
1054         # XXX: only the second version gets highlighted properly.
1055         # re_filtering www.lfk.de/favicon.ico (size 209) with filter untrackable-hulk produced 0 hits (new size 209).
1056         # filtering aci.blogg.de/ (size 37988) with 'blogg.de' produced 3 hits (new size 38057)
1057         $req{$t}{'content_source'} = $1;
1058         $req{$t}{'content_size'}   = $2;
1059         $req{$t}{'content_filter'} = $3;
1060         $req{$t}{'content_hits'}   = $4;
1061         $req{$t}{'new_content_size'} = $5;
1062         $req{$t}{'content_size_change'} = $req{$t}{'new_content_size'} - $req{$t}{'content_size'};
1063         #return '' if ($req{$t}{'content_hits'} == 0 && !cli_option_is_set('show-ineffective-filters'));
1064         if ($req{$t}{'content_hits'} == 0 and
1065             not (cli_option_is_set('show-ineffective-filters')
1066                  or ($req{$t}{'content_filter'} =~ m/^privoxy-filter-test$/))) {
1067                 return '';
1068         }
1069
1070         $c =~ s@(?<=\(size )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1071         $c =~ s@(?<=\(new size )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1072         $c =~ s@(?<=produced )(\d+)(?= hits)@$h{'Number'}$1$h{'Standard'}@;
1073
1074         $c =~ s@([^\s]+?)(\'? produced)@$h{'filter'}$1$h{'Standard'}$2@;
1075         $c = highlight_matched_host($c, '(?<=filtering )[^\s]+');
1076
1077         $c =~ s@\.$@ @;
1078         $c .= "(" . $h{'Number'};
1079         $c .= "+" if ($req{$t}{'content_size_change'} >= 0);
1080         $c .= $req{$t}{'content_size_change'} . $h{'Standard'} . ")";
1081         $content = $c;
1082
1083     } elsif ($c =~ m/^filtering request body from client /) {
1084
1085         # filtering request body from client 127.0.0.1 (size 958) with 'null-filter' produced 0 hits (new size 958).
1086
1087         $c =~ s@(?<=from client )([^\s]+)@$h{'ip-address'}$1$h{'Standard'}@;
1088         $c =~ s@(?<=\(size )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1089         $c =~ s@([^\s]+?)(\'? produced)@$h{'filter'}$1$h{'Standard'}$2@;
1090         $c =~ s@(?<=\(new size )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1091         $c =~ s@(?<=produced )(\d+)(?= hits)@$h{'Number'}$1$h{'Standard'}@;
1092         $content = $c;
1093
1094   } elsif ($c =~ /\.{3}$/
1095         and $c =~ m/^(?:re_)?filtering \'?(.*?)\'? \(size (\d*)\) with (?:filter )?\'?([^\s]*?)\'? ?\.{3}$/) {
1096
1097         # Used by Privoxy 3.0.5 and 3.0.6:
1098         # XXX: Fill in ...
1099         # Used by Privoxy 3.0.7:
1100         # filtering 'Connection: close' (size 17) with 'generic-content-ads' ...
1101
1102         $req{$t}{'filtered_header'} = $1;
1103         $req{$t}{'old_header_size'} = $2;
1104         $req{$t}{'header_filter_name'} = $3;
1105
1106         unless (cli_option_is_set('show-ineffective-filters') or
1107                 $req{$t}{'header_filter_name'} =~ m/^privoxy-filter-test$/) {
1108             return '';
1109         }
1110         $content =~ s@(?<=\(size )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1111         $content =~ s@($req{$t}{'header_filter_name'})@$h{'filter'}$1$h{'Standard'}@;
1112
1113     } elsif ($c =~ m/^ ?\.\.\. ?produced (\d*) hits \(new size (\d*)\)\./) {
1114
1115         # ...produced 0 hits (new size 23).
1116         #... produced 1 hits (new size 54).
1117
1118         $req{$t}{'header_filter_hits'} = $1;
1119         $req{$t}{'new_header_size'} = $2;
1120
1121         unless (cli_option_is_set('show-ineffective-filters') or
1122                 (defined($req{$t}{'header_filter_name'}) and
1123                  $req{$t}{'header_filter_name'} =~ m/^privoxy-filter-test$/)) {
1124
1125             if ($req{$t}{'header_filter_hits'} == 0 and
1126                 not (defined($req{$t}{'header_filter_name'}) and
1127                  $req{$t}{'header_filter_name'} =~ m/^privoxy-filter-test$/)) {
1128                 return '';
1129             }
1130             # Reformat including information from the intro
1131             $c = "'" . h('filter') . $req{$t}{'header_filter_name'} . h('Standard') . "'";
1132             $c .= " hit ";
1133             # XXX: Hide behind constant, it may be interesting if LOG_LEVEL_HEADER isn't enabled as well.
1134             # $c .= $req{$t}{'filtered_header'} . " ";
1135             $c .= h('Number') . $req{$t}{'header_filter_hits'}. h('Standard');
1136             $c .= ($req{$t}{'header_filter_hits'} == 1) ? " time, " : " times, ";
1137
1138             if ($req{$t}{'old_header_size'} !=  $req{$t}{'new_header_size'}) {
1139
1140                 $c .= "changing size from ";
1141                 $c .=  h('Number') . $req{$t}{'old_header_size'} . h('Standard');
1142                 $c .= " to ";
1143                 $c .= h('Number') . $req{$t}{'new_header_size'} . h('Standard');
1144                 $c .= ".";
1145
1146             } else {
1147
1148                 $c .= "keeping the size at " . $req{$t}{'old_header_size'};
1149
1150             }
1151
1152             # Highlight from last line (XXX: What?)
1153             # $c =~ s@(?<=produced )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1154             # $c =~ s@($req{$t}{'header_filter_name'})@$h{'filter'}$1$h{'Standard'}@;
1155
1156         } else {
1157
1158            # XXX: Untested
1159            $c =~ s@(?<=produced )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1160            $c =~ s@(?<=new size )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1161
1162         }
1163         $content = $c;
1164
1165     } elsif ($c =~ m/^(Tagger|Filter) ([^\s]*) has empty joblist. Nothing to do./) {
1166
1167         # Filter privoxy-filter-test has empty joblist. Nothing to do.
1168         # Tagger variable-test has empty joblist. Nothing to do.
1169
1170         $content =~ s@(?<=$1 )([^\s]*)@$h{'filter'}$1$h{'Standard'}@;
1171
1172     } elsif ($c =~ m/^De-chunking successful. Shrunk from (\d+) to (\d+)/) {
1173
1174         $req{$t}{'chunked-size'} = $1;
1175         $req{$t}{'dechunked-size'} = $2;
1176         $req{$t}{'dechunk-change'} = $req{$t}{'dechunked-size'} - $req{$t}{'chunked-size'};
1177
1178         $content .= " (" . h('Number') . $req{$t}{'dechunk-change'} . h('Standard') . ")";
1179
1180         $content =~ s@(?<=from )($req{$t}{'chunked-size'})@$h{'Number'}$1$h{'Standard'}@;
1181         $content =~ s@(?<=to )($req{$t}{'dechunked-size'})@$h{'Number'}$1$h{'Standard'}@;
1182
1183     } elsif ($c =~ m/^Decompression successful. Old size: (\d+), new size: (\d+)./) {
1184
1185         # Decompression successful. Old size: 670, new size: 1166.
1186
1187         $req{$t}{'size-compressed'} = $1;
1188         $req{$t}{'size-decompressed'} = $2;
1189         $req{$t}{'decompression-gain'} = $req{$t}{'size-decompressed'} - $req{$t}{'size-compressed'};
1190
1191         $content =~ s@(?<=Old size: )($req{$t}{'size-compressed'})@$h{'Number'}$1$h{'Standard'}@;
1192         $content =~ s@(?<=new size: )($req{$t}{'size-decompressed'})@$h{'Number'}$1$h{'Standard'}@;
1193
1194         # XXX: Create sub get_percentage()
1195         if ($req{$t}{'size-decompressed'}) {
1196             $req{$t}{'decompression-gain-percent'} =
1197                 $req{$t}{'decompression-gain'} / $req{$t}{'size-decompressed'} * 100;
1198
1199             $content .= " (saved: ";
1200             #$content .= h('Number') . $req{$t}{'decompression-gain'} . h('Standard');
1201             #$content .= "/";
1202             $content .= h('Number') . sprintf("%.2f%%", $req{$t}{'decompression-gain-percent'}) . h('Standard');
1203             $content .= ")";
1204         }
1205
1206     } elsif ($c =~ m/^(Need to de-chunk first)/) {
1207
1208         # Need to de-chunk first
1209         return '' if SUPPRESS_NEED_TO_DE_CHUNK_FIRST;
1210
1211     } elsif ($c =~ m/^(Adding (?:dynamic )?re_filter job)/) {
1212
1213         return ''  if (SUPPRESS_SUCCEEDED_FILTER_ADDITIONS && m/succeeded/);
1214
1215         # Adding re_filter job ...
1216         # Adding dynamic re_filter job s@^(?:\w*)\s+.*\s+HTTP/\d\.\d\s*@IP-ADDRESS: $origin@D\
1217         #  to filter client-ip-address succeeded.
1218
1219     } elsif ($c =~ m/^Compressed content from /) {
1220
1221         # Compressed content from 29258 to 8630 bytes. Compression level: 3
1222         $content =~ s@(?<=from )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1223         $content =~ s@(?<=to )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1224         $content =~ s@(?<=level: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1225
1226     } elsif ($c =~ m/^Reading in filter/) {
1227
1228         return '' unless SHOW_FILTER_READIN_IN;
1229
1230     } elsif ($c =~ m/^Decompression didn't result/) {
1231
1232         # Decompression didn't result in any content.
1233
1234         # Nothing to highlight.
1235
1236     } else {
1237
1238         found_unknown_content($content);
1239
1240     }
1241
1242     return $content;
1243 }
1244
1245 sub handle_loglevel_tagging($) {
1246
1247     my $c = shift;
1248
1249     if ($c =~ /^Tagger \'([^\']*)\' added tag \'([^\']*)\'/ or
1250         $c =~ m/^Adding tag \'([^\']*)\' created by header tagger \'([^\']*)\'/) {
1251
1252         # Adding tag 'GET request' created by header tagger 'method-man' (XXX: no longer used)
1253         # Tagger 'revalidation' added tag 'REVALIDATION-REQUEST'. No action bit update necessary.
1254         # Tagger 'revalidation' added tag 'REVALIDATION-REQUEST'. Action bits updated accordingly.
1255
1256         # XXX: Save tag and tagger
1257
1258         $c =~ s@(?<=^Tagger \')([^\']*)@$h{'tagger'}$1$h{'Standard'}@;
1259         $c =~ s@(?<=added tag \')([^\']*)@$h{'tag'}$1$h{'Standard'}@;
1260         $c =~ s@(?<=Action bits )(updated)@$h{'action-bits-update'}$1$h{'Standard'}@;
1261
1262     } elsif ($c =~ /^Enlisting tag/) {
1263
1264         # Enlisting tag 'forward-directly' for client 127.0.0.1.
1265
1266         $c =~ s@(?<=tag \')([^\']*)@$h{'tag'}$1$h{'Standard'}@;
1267         $c = highlight_matched_host($c, '[^\s]+(?=\.$)');
1268
1269     } elsif ($c =~ /^Tag/) {
1270
1271         # Tag 'change-tor-socks-port' for client 127.0.0.1 expired 1 seconds ago. Deleting it.
1272
1273         $c =~ s@(?<=Tag \')([^\']*)@$h{'tag'}$1$h{'Standard'}@;
1274         $c =~ s@(?<=expired )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1275         $c = highlight_matched_host($c, '(?<=client )[^\s]+');
1276
1277     } elsif ($c =~ /^Evaluating/) {
1278
1279         # Evaluating tag 'change-tor-socks-port' for client 127.0.0.1. End of life 1613162302.
1280
1281         $c =~ s@(?<=tag \')([^\']*)@$h{'tag'}$1$h{'Standard'}@;
1282         $c = highlight_matched_host($c, '(?<=client )[^\s]+(?=\.)');
1283         $c =~ s@(?<=life )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1284
1285     } elsif ($c =~ /^Client tag/) {
1286
1287         # Client tag 'forward-directly' matches
1288
1289         $c =~ s@(?<=tag \')([^\']*)@$h{'tag'}$1$h{'Standard'}@;
1290
1291     }
1292
1293     return $c;
1294 }
1295
1296 sub handle_loglevel_redirect($) {
1297
1298     my $c = shift;
1299
1300     if ($c =~ m/^Decoding "([^""]*)"/) {
1301
1302          $req{$t}{'original-destination'} = $1;
1303          $c = highlight_matched_path($c, '(?<=Decoding ")[^"]*');
1304          $c =~ s@\"@@g;
1305
1306     } elsif ($c =~ m/^Checking/) {
1307
1308          # Checking /_ylt=A0geu.Z76BRGR9k/**http://search.yahoo.com/search?p=view+odb+presentation+on+freebsd\
1309          #  &ei=UTF-8&xargs=0&pstart=1&fr=moz2&b=11 for redirects.
1310
1311          # TODO: Change colour if really url-decoded
1312          $req{$t}{'decoded-original-destination'} = $1;
1313          $c = highlight_matched_path($c, '(?<=Checking ")[^"]*');
1314          $c =~ s@\"@@g;
1315
1316     } elsif ($c =~ m/^pcrs command "([^""]*)" changed /) {
1317
1318         # pcrs command "s@&from=rss@@" changed \
1319         #  "http://it.slashdot.org/article.pl?sid=07/03/02/1657247&from=rss"\
1320         #  to "http://it.slashdot.org/article.pl?sid=07/03/02/1657247" (1 hit).
1321         $c =~ s@(?<=pcrs command )"([^""]*)"@$h{'filter'}$1$h{'Standard'}@;
1322         $c = highlight_matched_url($c, '(?<=changed ")[^""]*');
1323         $c =~ s@(?<=changed )"([^""]*)"@$1@; # Remove quotes
1324         $c = highlight_matched_url($c, '(?<=to ")[^""]*');
1325         $c =~ s@(?<=to )"([^""]*)"@$1@; # Remove quotes
1326         $c =~ s@(\d+)(?= hits?)@$h{'hits'}$1$h{'Standard'}@;
1327
1328     } elsif ($c =~ m/^pcrs command "([^""]*)" didn\'t change/) {
1329
1330         # pcrs command "s@^http://([^.]+?)/?$@http://www.bing.com/search?q=$1@" didn't \
1331         #  change "http://www.example.org/".
1332         $c =~ s@(?<=pcrs command )"([^""]*)"@$h{'filter'}$1$h{'Standard'}@;
1333         $c = highlight_matched_url($c, '(?<=change ")[^""]*');
1334
1335     } elsif ($c =~ m/(^New URL is: )(.*)/) {
1336
1337         # New URL is: http://it.slashdot.org/article.pl?sid=07/03/04/1511210
1338         # XXX: Use URL highlighter
1339         # XXX: Save?
1340         $c = $1 . h('rewritten-URL') . $2 . h('Standard');
1341
1342     } elsif ($c =~ m/No pcrs command recognized, assuming that/) {
1343         # No pcrs command recognized, assuming that "http://config.privoxy.org/user-manual/favicon.png"\
1344         #  is already properly formatted.
1345         # XXX: assume the same?
1346         $c = highlight_matched_url($c, '(?<=assuming that \")[^"]*');
1347
1348     } elsif ($c =~ m/^Percent-encoding redirect/) {
1349
1350         # Percent-encoding redirect URL: http://www.example.org/\x02
1351         $c = highlight_matched_url($c, '(?<=redirect URL: ).*');
1352
1353     } elsif ($c =~ m/^Rewrite detected:/) {
1354
1355         # Rewrite detected: GET http://10.0.0.2:88/blah.txt HTTP/1.1
1356         # Rewrite detected: GET https://www.electrobsd.org/CommonJS/ajax/libs/jquery/3.4.1/jquery.min.js HTTP/1.1
1357         $c = highlight_matched_request_line($c, '(?<=^Rewrite detected: ).*');
1358
1359     } elsif ($c =~ m/^Rewritten request line results in downgrade to http/) {
1360
1361         # Rewritten request line results in downgrade to http
1362         $c =~ s@(downgrade)@$h{'http-downgrade'}$1$h{'Standard'}@;
1363
1364     } else {
1365
1366         found_unknown_content($c);
1367
1368     }
1369
1370     return $c;
1371 }
1372
1373 sub handle_loglevel_gif_deanimate($) {
1374
1375     my $content = shift;
1376
1377     if ($content =~ m/Success! GIF shrunk from (\d+) bytes to (\d+)\./) {
1378
1379         my $bytes_from = $1;
1380         my $bytes_to = $2;
1381         # Gif-Deanimate: Success! GIF shrunk from 205 bytes to 133.
1382         $content =~ s@$bytes_from@$h{'Number'}$bytes_from$h{'Standard'}@;
1383         # XXX: Do we need g in case of ($1 == $2)?
1384         $content =~ s@$bytes_to@$h{'Number'}$bytes_to$h{'Standard'}@;
1385
1386     } elsif ($content =~ m/GIF (not) changed/) {
1387
1388         # Gif-Deanimate: GIF not changed.
1389         return '' if SUPPRESS_GIF_NOT_CHANGED;
1390         $content =~ s@($1)@$h{'not'}$1$h{'Standard'}@;
1391
1392     } elsif ($content =~ m/^failed! \(gif parsing\)/) {
1393
1394         # failed! (gif parsing)
1395         # XXX: Replace this error message with something less stupid
1396         $content =~ s@(failed!)@$h{'error'}$1$h{'Standard'}@;
1397
1398     } elsif ($content =~ m/^Need to de-chunk first/) {
1399
1400         # Need to de-chunk first
1401         return '' if SUPPRESS_NEED_TO_DE_CHUNK_FIRST;
1402
1403     } elsif ($content =~ m/^(?:No GIF header found|failed while parsing)/) {
1404
1405         # No GIF header found (XXX: Did I ever commit this?)
1406         # failed while parsing 195 134747048 (XXX: never committed)
1407
1408         # Ignore these for now
1409
1410     } else {
1411
1412         found_unknown_content($content);
1413
1414     }
1415
1416     return $content;
1417 }
1418
1419 sub handle_loglevel_request($) {
1420
1421     my $content = shift;
1422
1423     if ($content =~ m/crunch! /) {
1424
1425         # config.privoxy.org/send-stylesheet crunch! (CGI Call)
1426
1427         # Highlight crunch reasons
1428         foreach my $reason (keys %reason_colours) {
1429             $content =~ s@\(($reason)\)@$reason_colours{$reason}($1)$h{'Standard'}@g;
1430         }
1431         # Highlight request URL domain and ditch 'crunch!'
1432         $content = highlight_matched_pattern($content, 'request_', '[^ ]*(?= crunch!)');
1433         $content =~ s@ crunch!@@;
1434
1435     } elsif ($content =~ m/\[too long, truncated\]$/) {
1436
1437         # config.privoxy.org/edit-actions-submit?f=3&v=1176116716&s=7&Submit=Submit[...]&filter... [too long, truncated]
1438         $content = highlight_matched_pattern($content, 'request_', '^.*(?=\.\.\. \[too long, truncated\]$)');
1439
1440     } elsif ($content =~ m/(.*)/) { # XXX: Pretty stupid
1441
1442         # trac.vidalia-project.net/wiki/Volunteer?format=txt
1443         $content = h('request_') . $content . h('Standard');
1444
1445     } else {  # XXX: Nop
1446
1447         found_unknown_content($content);
1448
1449     }
1450
1451     return $content;
1452 }
1453
1454 sub handle_loglevel_crunch($) {
1455
1456     my $content = shift;
1457
1458     # Highlight crunch reason
1459     foreach my $reason (keys %reason_colours) {
1460         $content =~ s@($reason)@$reason_colours{$reason}$1$h{'Standard'}@g;
1461     }
1462
1463     if ($content =~ m/\[too long, truncated\]$/) {
1464
1465         # Blocked: config.privoxy.org/edit-actions-submit?f=3&v=1176116716&s=7&Submit=Submit\
1466         #  [...]&filter... [too long, truncated]
1467         $content = highlight_matched_pattern($content, 'request_', '^.*(?=\.\.\. \[too long, truncated\]$)');
1468
1469     } elsif ($content =~ m/Certificate error:/) {
1470
1471         # Certificate error: ASN date error, current date after: https://expired.badssl.com/
1472         $content = highlight_matched_pattern($content, 'request_', 'https://.*');
1473
1474     } else {
1475
1476         # Blocked: http://ads.example.org/
1477         $content = highlight_matched_pattern($content, 'request_', '(?<=: ).*');
1478     }
1479
1480     return $content;
1481 }
1482
1483 sub handle_loglevel_connect($) {
1484
1485     my $c = shift;
1486
1487     if ($c =~ m/^via [^\s]+ to: [^\s]+/) {
1488
1489         # Connect: via 10.0.0.1:8123 to: www.example.org.noconnect
1490
1491         $c = highlight_matched_host($c, '(?<=via )[^\s]+');
1492         $c = highlight_matched_host($c, '(?<=to: )[^\s]+');
1493
1494     } elsif ($c =~ m/^connect to: .* failed: .*/) {
1495
1496         # connect to: www.example.org.noconnect failed: Operation not permitted
1497
1498         $c = highlight_matched_host($c, '(?<=connect to: )[^\s]+');
1499
1500         $c =~ s@(?<=failed: )(.*)@$h{'error'}$1$h{'Standard'}@;
1501
1502     } elsif ($c =~ m/^to ([^\s]*)( successful)?$/) {
1503
1504         # Connect: to www.nzherald.co.nz successful
1505         # Connect: to archiv.radiotux.de
1506
1507         return '' if SUPPRESS_SUCCESSFUL_CONNECTIONS;
1508         $c = highlight_matched_host($c, '(?<=to )[^\s]+');
1509
1510     } elsif ($c =~ m/^to ([^\s]*)$/) {
1511
1512         # Connect: to lists.sourceforge.net:443
1513
1514         $c = highlight_matched_host($c, '(?<=to )[^\s]+');
1515
1516     } elsif ($c =~ m/^[Aa]ccepted connection from .*/ or
1517              $c =~ m/^OK/) {
1518
1519         # Privoxy 3.0.20:
1520         # Accepted connection from 10.0.0.1 on socket 5
1521         # Privoxy between 3.0.20 and 3.0.6:
1522         # accepted connection from 10.0.0.1( on socket 5)?
1523         # Privoxy 3.0.6 and earlier just say:
1524         # OK
1525         $c = highlight_matched_host($c, '(?<=connection from )[^ ]*');
1526         $c = highlight_matched_pattern($c, 'Number', '(?<=socket )\d+');
1527
1528     } elsif ($c =~ m/^Closing client socket/) {
1529
1530         # Closing client socket 5. Keep-alive: 0, Socket alive: 1. Data available: 0.
1531         # Privoxy 3.0.20 and later
1532         # Closing client socket 8. Keep-alive: 1. Socket alive: 0. Data available: 0. \
1533         #  Configuration file change detected: 0. Requests received: 11.
1534
1535         $c = highlight_matched_pattern($c, 'Number', '(?<=socket )\d+');
1536         $c = highlight_matched_pattern($c, 'Number', '(?<=Keep-alive: )\d+');
1537         $c = highlight_matched_pattern($c, 'Number', '(?<=Socket alive: )\d+');
1538         $c = highlight_matched_pattern($c, 'Number', '(?<=available: )\d+');
1539         $c = highlight_matched_pattern($c, 'Number', '(?<=detected: )\d+');
1540         $c = highlight_matched_pattern($c, 'Number', '(?<=received: )\d+');
1541
1542     } elsif ($c =~ m/^write header to: .* failed:/) {
1543
1544         # write header to: 10.0.0.1 failed: Broken pipe
1545
1546         $c = highlight_matched_host($c, '(?<=write header to: )[^\s]*');
1547         $c =~ s@(?<=failed: )(.*)@$h{'Error'}$1$h{'Standard'}@;
1548
1549     } elsif ($c =~ m/^write header to client failed:/) {
1550
1551         # write header to client failed: Broken pipe
1552         # XXX: Stil in use?
1553         $c =~ s@(?<=failed: )(.*)@$h{'Error'}$1$h{'Standard'}@;
1554
1555     } elsif ($c =~ m/^socks4_connect:/) {
1556
1557         # socks4_connect: SOCKS request rejected or failed.
1558         $c =~ s@(?<=socks4_connect: )(.*)@$h{'Error'}$1$h{'Standard'}@;
1559
1560     } elsif ($c =~ m/^Listening for new connections/ or
1561              $c =~ m/^accept connection/) {
1562         # XXX: Highlight?
1563         # Privoxy versions above 3.0.6 say:
1564         # Listening for new connections ...
1565         # earlier versions say:
1566         # accept connection ...
1567         return '';
1568
1569     } elsif ($c =~ m/^accept failed:/) {
1570
1571         $c =~ s@(?<=accept failed: )(.*)@$h{'Error'}$1$h{'Standard'}@;
1572
1573     } elsif ($c =~ m/^Overriding forwarding settings/) {
1574
1575         # Overriding forwarding settings based on 'forward 10.0.0.1:8123'
1576         $c =~ s@(?<=based on \')(.*)(?=\')@$h{'configuration-line'}$1$h{'Standard'}@;
1577
1578     } elsif ($c =~ m/^Denying suspicious CONNECT request from/) {
1579
1580         # Denying suspicious CONNECT request from 10.0.0.1
1581         $c = highlight_matched_host($c, '(?<=from )[^\s]+'); # XXX: not an URL
1582
1583     } elsif ($c =~ m/^socks5_connect:/) {
1584
1585         $c =~ s@(?<=socks5_connect: )(.*)@$h{'error'}$1$h{'Standard'}@;
1586
1587     } elsif ($c =~ m/^Created new connection to/) {
1588
1589         # Created new connection to www.privoxy.org:80 on socket 11.
1590         $c = highlight_matched_host($c, '(?<=connection to )[^\s]+');
1591         $c =~ s@(?<=on socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1592
1593     } elsif ($c =~ m/^Found reusable socket/) {
1594
1595         # Found reusable socket 9 for www.privoxy.org:80 in slot 0.
1596         # 3.0.15 and later:
1597         # Found reusable socket 8 for www.privoxy.org:80 in slot 2.\
1598         #  Timestamp made 0 seconds ago. Timeout: 1. Latency: 0.
1599         $c =~ s@(?<=Found reusable socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1600         $c = highlight_matched_host($c, '(?<=for )[^\s]+');
1601         $c =~ s@(?<=in slot )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1602         $c =~ s@(?<=made )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1603         $c =~ s@(?<=Timeout: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1604         $c =~ s@(?<=Latency: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1605
1606     } elsif ($c =~ m/^Marking open socket/) {
1607
1608         # Marking open socket 9 for www.privoxy.org:80 in slot 0 as unused.
1609         $c =~ s@(?<=Marking open socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1610         $c = highlight_matched_host($c, '(?<=for )[^\s]+');
1611         $c =~ s@(?<=in slot )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1612
1613     } elsif ($c =~ m/^No reusable/) {
1614
1615         # No reusable socket for addons.mozilla.org:443 found. Opening a new one.
1616         $c = highlight_matched_host($c, '(?<=for )[^\s]+');
1617
1618     } elsif ($c =~ m/^(Remembering|Forgetting) socket/) {
1619
1620         # Remembering socket 13 for www.privoxy.org:80 in slot 0.
1621         # Forgetting socket 38 for www.privoxy.org:80 in slot 5.
1622
1623         $c =~ s@(?<=socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1624         $c = highlight_matched_host($c, '(?<=for )[^\s]+');
1625         $c =~ s@(?<=in slot )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1626
1627     } elsif ($c =~ m/^Socket/) {
1628
1629         # Socket 16 already forgotten or never remembered.
1630         $c =~ s@(?<=Socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1631
1632     } elsif ($c =~ m/^The connection to/) {
1633
1634         # The connection to www.privoxy.org:80 in slot 6 timed out. Closing socket 19. Timeout is: 61.
1635         # 3.0.15 and later:
1636         # The connection to 1.bp.blogspot.com:80 in slot 0 timed out. Closing socket 5.\
1637         #  Timeout is: 1. Assumed latency: 4.
1638         # The connection to 10.0.0.1:80 in slot 0 is no longer usable. Closing socket 4.
1639         $c = highlight_matched_host($c, '(?<=connection to )[^\s]+');
1640         $c =~ s@(?<=in slot )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1641         $c =~ s@(?<=Closing socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1642         $c =~ s@(?<=Timeout is: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1643         $c =~ s@(?<=Assumed latency: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1644
1645     } elsif ($c =~ m/^Stopped waiting for the request line/ or
1646              $c =~ m/^No request line on socket \d received in time/ or
1647              $c =~ m/^The client side of the connection on socket \d/) {
1648
1649         # Stopped waiting for the request line. Timeout: 121.
1650         # Privoxy 3.0.19 and later:
1651         # No request line on socket 5 received in time. Timeout: 1.
1652         # The client side of the connection on socket 5 got closed \
1653         #  without sending a complete request line.
1654         $c =~ s@(?<=Timeout: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1655         $c =~ s@(?<=socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1656
1657     } elsif ($c =~ m/^Waiting for \d/) {
1658
1659         # Waiting for 1 connections to timeout.
1660         $c =~ s@(?<=^Waiting for )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1661
1662     } elsif ($c =~ m/^Initialized/) {
1663
1664         # Initialized 20 socket slots.
1665         $c =~ s@(?<=Initialized )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1666
1667     } elsif ($c =~ m/^Done reading from server/) {
1668
1669         # Done reading from server. Expected content length: 24892. \
1670         #  Actual content length: 24892. Most recently received: 4412.
1671         # 3.0.15 and later:
1672         # Done reading from server. Expected content length: 24892. \
1673         #  Actual content length: 24892. Bytes most recently read: 4412.
1674         # Done reading from server. Content length: 6018 as expected. \
1675         #  Bytes most recently read: 294.
1676         $c =~ s@(?<=ontent length: )(\d+)@$h{'Number'}$1$h{'Standard'}@g;
1677         $c =~ s@(?<=received: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1678         $c =~ s@(?<=read: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1679
1680     } elsif ($c =~ m/^Continuing buffering (?:server )?headers/) {
1681
1682         # Continuing buffering headers. byte_count: 19. header_offset: 517. len: 536.
1683         $c =~ s@(?<=byte_count: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1684         $c =~ s@(?<=header_offset: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1685         $c =~ s@(?<=len: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1686         # 3.0.15 up to 3.0.19:
1687         # Continuing buffering headers. Bytes most recently read: 498.
1688         $c =~ s@(?<=read: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1689         # 3.0.20 and later:
1690         # Continuing buffering server headers from socket 5. Bytes most recently read: 498.
1691         $c =~ s@(?<=socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1692
1693     } elsif ($c =~ m/^Received \d+ bytes while/) {
1694
1695         # Received 206 bytes while expecting 12103.
1696         $c =~ s@(?<=Received )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1697         $c =~ s@(?<=expecting )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1698
1699     } elsif ($c =~ m/^(Rejecting c|C)onnection from/) {
1700
1701         # Connection from 81.163.28.218 dropped due to ACL
1702         # Rejecting connection from 178.63.152.227. Maximum number of connections reached.
1703         # Connection from 192.168.2.1 on 127.0.1.1:8118 (socket 3) dropped due to ACL
1704         $c = highlight_matched_host($c, '(?<=onnection from )[\d.:]+');
1705         $c = highlight_matched_host($c, '(?<=on )[\d.:]+');
1706         $c =~ s@(?<=socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1707
1708     } elsif ($c =~ m/^(?:Reusing|Closing) server socket / or
1709              $c =~ m/^No additional client request/) {
1710
1711         # Reusing server socket 4. Opened for 10.0.0.1.
1712         # Closing server socket 2. Opened for 10.0.0.1.
1713         # No additional client request received in time. \
1714         #  Closing server socket 4, initially opened for 10.0.0.1.
1715         # No additional client request received in time on socket 29.
1716         # Privoxy 3.0.20 and later
1717         # Reusing server socket 7 connected to www.privoxy.org. Total requests: 2.
1718         # Closing server socket 6 connected to d.asset.soup.io. Keep-alive: 0.\
1719         #  Tainted: 1. Socket alive: 1. Timeout: 60. Configuration file change detected: 0.
1720         # Reusing server socket 35 connected to nl.wikipedia.org. Requests already sent: 5.
1721
1722         $c =~ s@(?<= socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1723         $c = highlight_matched_host($c, '(?<=for )[^\s]+(?=\.)');
1724         $c = highlight_matched_host($c, '(?<=connected to )[^\s]+(?=\.)');
1725         for my $number_pattern ('requests', 'Keep-alive', 'Tainted', ' alive', 'Timeout', 'detected') {
1726             $c = highlight_matched_pattern($c, 'Number', '(?<='. $number_pattern . ': )\d+');
1727         }
1728         $c =~ s@(?<=already sent: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1729
1730     } elsif ($c =~ m/^Connected to /) {
1731
1732         # Connected to tor-jail[10.0.0.2]:9050.
1733
1734         $c = highlight_matched_host($c, '(?<=\[)[^\]]+');
1735         $c = highlight_matched_host($c, '(?<=Connected to )[^\[\s]+');
1736         $c =~ s@(?<=\]:)(\d+)@$h{'Number'}$1$h{'Standard'}@;
1737
1738     } elsif ($c =~ m/^Could not connect to /) {
1739
1740         # Could not connect to [10.0.0.1]:80.
1741
1742         $c = highlight_matched_host($c, '(?<=\[)[^\]]+');
1743         $c =~ s@(?<=\]:)(\d+)@$h{'Number'}$1$h{'Standard'}@;
1744
1745     } elsif ($c =~ m/^Waiting for the next client request/ or
1746              $c =~ m/^The connection on server socket/ or
1747              $c =~ m/^Client request (?:\d+ )?(?:arrived in time|has been pipelined) /) {
1748
1749         # Waiting for the next client request on socket 3. Keeping the server \
1750         #  socket 12 to a.fsdn.com open.
1751         # The connection on server socket 6 to upload.wikimedia.org isn't reusable. Closing.
1752         # Privoxy 3.0.20 and later:
1753         # Client request 4 arrived in time on socket 7.
1754         # Used by Privoxy 3.0.18 and 3.0.19:
1755         # Client request arrived in time on socket 21.
1756         # Used by earlier version:
1757         # Client request arrived in time or the client closed the connection on socket 12.
1758         # Client request 8 has been pipelined on socket 7 and the socket is still alive.
1759
1760         $c =~ s@(?<=request )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1761         $c =~ s@(?<=on socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1762         $c =~ s@(?<=server socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1763         $c = highlight_matched_host($c, '(?<=to )[^\s]+');
1764
1765     } elsif ($c =~ m/^Marking the server socket/) {
1766
1767         # Marking the server socket 7 tainted.
1768
1769         $c =~ s@(?<=server socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1770
1771     } elsif ($c =~ m/^Reduced expected bytes to /) {
1772
1773         # Reduced expected bytes to 0 to account for the 1542 ones we already got.
1774         $c =~ s@(?<=bytes to )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1775         $c =~ s@(?<=for the )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1776
1777     } elsif ($c =~ m/^The client closed socket /) {
1778
1779         # The client closed socket 2 while the server socket 4 is still open.
1780         $c =~ s@(?<=closed socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1781         $c =~ s@(?<=server socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1782
1783     } elsif ($c =~ m/^Expected client content length set /) {
1784
1785         # Expected client content length set to 667325411 after reading 4999 bytes.
1786         $c =~ s@(?<=set to )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1787         $c =~ s@(?<=reading )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1788
1789     } elsif ($c =~ m/^Reducing expected bytes to /) {
1790
1791         # Reducing expected bytes to 0. Marking the server socket tainted after throwing 4 bytes away.
1792         $c =~ s@(?<=bytes to )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1793         $c =~ s@(?<=after throwing )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1794
1795     } elsif ($c =~ m/^Waiting for up to /) {
1796
1797         # Waiting for up to 4999 bytes from the client.
1798         $c =~ s@(?<=up to )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1799
1800     } elsif ($c =~ m/^Optimistically sending /) {
1801
1802         # Optimistically sending 318 bytes of client headers intended for www.privoxy.org
1803         $c =~ s@(?<=sending )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1804         $c = highlight_matched_host($c, '(?<=for )[^\s]+');
1805
1806     } elsif ($c =~ m/^Stopping to watch the client socket/) {
1807
1808         # Stopping to watch the client socket. There's already another request waiting.
1809         # Privoxy 3.0.20 and later:
1810         # Stopping to watch the client socket 5. There's already another request waiting.
1811         $c =~ s@(?<=client socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1812
1813     } elsif ($c =~ m/^Drained \d+ bytes before closing/) {
1814
1815         # Drained 180 bytes before closing socket 6
1816         $c =~ s@(?<=Drained )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1817         $c =~ s@(?<=socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1818
1819     } elsif ($c =~ m/^Tainting client socket/ or
1820              $c =~ m/^Failed to shutdown socket/) {
1821
1822         # Tainting client socket 7 due to unread data.
1823         # Failed to shutdown socket 11: Connection reset by peer
1824
1825         $c =~ s@(?<=socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1826
1827     } elsif ($c =~ m/^Shifting \d+ pipelined bytes/) {
1828
1829         # Shifting 360 pipelined bytes by 360 bytes
1830         $c =~ s@(?<=Shifting )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1831         $c =~ s@(?<=by )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1832
1833     } elsif ($c =~ m/^Flushed (\d+) bytes of request body while expecting (\d+)/) {
1834
1835         # Flushed 30 bytes of request body while expecting 30
1836         $c =~ s@(?<=Flushed )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1837         $c =~ s@(?<=expecting )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1838
1839     } elsif ($c =~ m/^Performing the TLS\/SSL handshake with client. Hash of host:/) {
1840
1841         # Performing the TLS/SSL handshake with client. Hash of host: bab5296b25e256c7b06b92b17b56bcae
1842         $c = highlight_matched_host($c, '(?<=Hash of host: ).+');
1843
1844     } elsif ($c =~ m/^Forwarding \d+ bytes of encrypted POST data/) {
1845
1846         # Forwarding 1954 bytes of encrypted POST data
1847         $c =~ s@(?<=Forwarding )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1848
1849     } elsif ($c =~ m/^Forwarded the last \d+ bytes/) {
1850
1851         # Forwarded the last 1954 bytes
1852         $c =~ s@(?<=the last )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1853
1854     } elsif ($c =~ m/^Waiting for the next client connection. Currently active threads:/) {
1855
1856         # Waiting for the next client connection. Currently active threads: 30
1857         $c =~ s@(?<=threads: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1858
1859     } elsif ($c =~ m/^Data arrived in time on client socket/) {
1860
1861         # Data arrived in time on client socket 6. Requests so far: 3
1862         $c =~ s@(?<=client socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1863         $c =~ s@(?<=Requests so far: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1864
1865     } elsif ($c =~ m/^Dropping the client connection on socket/) {
1866
1867         # Dropping the client connection on socket 71. The server connection has not been established yet.
1868         # Dropping the client connection on socket 23 with server socket 24 connected to \
1869         #  www.reddit.com. The forwarder has changed.
1870         $c =~ s@(?<=on socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1871         $c =~ s@(?<=server socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1872         $c = highlight_matched_host($c, '(?<=connected to )[^ ]+(?=\.)');
1873
1874     } elsif ($c =~ m/^The client socket \d+ has become unusable while the server/) {
1875
1876         # The client socket 16 has become unusable while the server socket 24 is still open.
1877         $c =~ s@(?<=client socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1878         $c =~ s@(?<=server socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1879
1880     } elsif ($c =~ m/^The last \d+ bytes of the request body have been read/) {
1881
1882         # The last 12078 bytes of the request body have been read
1883         $c =~ s@(?<=The last )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1884
1885     } elsif ($c =~ m/^Flushed \d+ bytes of request body/) {
1886
1887         # Flushed 3153 bytes of request body
1888         $c =~ s@(?<=Flushed )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1889
1890     } elsif ($c =~ m/^Complete client request followed by/) {
1891
1892         # Complete client request followed by 59 bytes of pipelined data received.
1893         $c =~ s@(?<=followed by )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1894
1895     } elsif ($c =~ m/^The peer notified us that the connection on socket/) {
1896
1897         # The peer notified us that the connection on socket 11 is going to be closed
1898         $c =~ s@(?<=socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1899
1900     } elsif ($c =~ m/^Client socket \d is no longer usable/) {
1901
1902         # Client socket 7 is no longer usable. The server socket has been closed.
1903         $c =~ s@(?<=socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
1904
1905     } elsif ($c =~ m/^Looks like we / or
1906              $c =~ m/^Unsetting keep-alive flag/ or
1907              $c =~ m/^No connections to wait/ or
1908              $c =~ m/^Complete client request received/ or
1909              $c =~ m/^Possible pipeline attempt detected./ or
1910              $c =~ m/^POST request detected. The connection will not be kept alive./ or
1911              $c =~ m/^The server still wants to talk, but the client hung up on us./ or
1912              $c =~ m/^The server didn't specify how long the connection will stay open/ or
1913              $c =~ m/^There might be a request body. The connection will not be kept alive/ or
1914              $c =~ m/^There better be a request body./ or
1915              $c =~ m/^Done reading from the client\.$/) {
1916
1917         # Looks like we reached the end of the last chunk. We better stop reading.
1918         # Looks like we read the end of the last chunk together with the server \
1919         #  headers. We better stop reading.
1920         # Looks like we got the last chunk together with the server headers. \
1921         #  We better stop reading.
1922         # Unsetting keep-alive flag.
1923         # No connections to wait for left.
1924         # Client request arrived in time or the client closed the connection.
1925         # Complete client request received
1926         # Possible pipeline attempt detected. The connection will not be \
1927         #  kept alive and we will only serve the first request.
1928         # POST request detected. The connection will not be kept alive.
1929         # The server still wants to talk, but the client hung up on us.
1930         # The server didn't specify how long the connection will stay open. Assume it's only a second.
1931         # There might be a request body. The connection will not be kept alive.
1932         # Privoxy 3.0.20 and later
1933         # There better be a request body.
1934         # Done reading from the client.
1935
1936     } else {
1937
1938         found_unknown_content($c);
1939
1940     }
1941
1942     return $c;
1943 }
1944
1945
1946 sub handle_loglevel_info($) {
1947
1948     my $c = shift;
1949
1950     if ($c =~ m/^Rewrite detected:/) {
1951
1952         # Rewrite detected: GET http://10.0.0.2:88/blah.txt HTTP/1.1
1953         $c = highlight_matched_request_line($c, '(?<=^Rewrite detected: ).*');
1954
1955     } elsif ($c =~ m/^Decompress(ing deflated|ion didn)/ or
1956              $c =~ m/^Compressed content detected/ or
1957              $c =~ m/^SDCH-compressed content detected/ or
1958              $c =~ m/^Tagger/
1959             ) {
1960         # Decompressing deflated iob: 117
1961         # Decompression didn't result in any content.
1962         # Compressed content detected, content filtering disabled. Consider recompiling Privoxy\
1963         #  with zlib support or enable the prevent-compression action.
1964         # SDCH-compressed content detected, content filtering disabled.\
1965         #  Consider suppressing SDCH offers made by the client.
1966         # Tagger 'complete-url' created empty tag. Ignored.
1967
1968         # Ignored for now
1969
1970     } elsif ($c =~ m/^(Re)?loading configuration file /) {
1971
1972         # loading configuration file '/usr/local/etc/privoxy/config':
1973         # Reloading configuration file '/usr/local/etc/privoxy/config'
1974         $c =~ s@(?<=loading configuration file \')([^\']*)@$h{'file'}$1$h{'Standard'}@;
1975
1976     } elsif ($c =~ m/^Loading (actions|filter|trust) file: /) {
1977
1978         # Loading actions file: /usr/local/etc/privoxy/default.action
1979         # Loading filter file: /usr/local/etc/privoxy/default.filter
1980         # Loading trust file: /usr/local/etc/privoxy/trust
1981
1982         $c =~ s@(?<= file: )(.*)$@$h{'file'}$1$h{'Standard'}@;
1983
1984     } elsif ($c =~ m/^exiting by signal/) {
1985
1986         # exiting by signal 15 .. bye
1987         $c =~ s@(?<=exiting by signal )(\d+)@$h{'signal'}$1$h{'Standard'}@;
1988
1989     } elsif ($c =~ m/^Privoxy version/) {
1990
1991         # Privoxy version 3.0.7
1992         $c =~ s@(?<=^Privoxy version )(\d+\.\d+\.\d+)$@$h{'version'}$1$h{'Standard'}@;
1993
1994     } elsif ($c =~ m/^Program name: /) {
1995
1996         # Program name: /usr/local/sbin/privoxy
1997         $c =~ s@(?<=Program name: )(.*)@$h{'program-name'}$1$h{'Standard'}@;
1998
1999     } elsif ($c =~ m/^Listening on port /) {
2000
2001         # Listening on port 8118 on IP address 10.0.0.1
2002         $c =~ s@(?<=Listening on port )(\d+)@$h{'port'}$1$h{'Standard'}@;
2003         $c =~ s@(?<=on IP address )(.*)@$h{'ip-address'}$1$h{'Standard'}@;
2004
2005     } elsif ($c =~ m/^\(Re-\)Open(?:ing)? logfile/) {
2006
2007         # (Re-)Open logfile /var/log/privoxy/privoxy.log
2008         $c =~ s@(?<=Open logfile )(.*)@$h{'file'}$1$h{'Standard'}@;
2009
2010     } elsif ($c =~ m/^(Request from|Malformed server response detected)/) {
2011
2012         # Request from 10.0.0.1 denied. limit-connect{,} doesn't allow CONNECT requests to port 443.
2013         # Request from 10.0.0.1 marked for blocking. limit-connect{,} doesn't allow CONNECT requests to port 443.
2014         # 3.0.18 and later:
2015         # Request from 10.0.0.1 marked for blocking. limit-connect{0} doesn't allow CONNECT requests to www.example.org:443
2016         # Malformed server response detected. Downgrading to HTTP/1.0 impossible.
2017
2018         $c =~ s@(?<=Request from )([^\s]*)@$h{'ip-address'}$1$h{'Standard'}@;
2019         $c =~ s@(denied|blocking)@$h{'warning'}$1$h{'Standard'}@;
2020         $c =~ s@(CONNECT)@$h{'method'}$1$h{'Standard'}@;
2021         $c =~ s@(?<=to port )(\d+)@$h{'port'}$1$h{'Standard'}@;
2022         $c =~ s@(?<=to )([^\s]+)@$h{'request_'}$1$h{'Standard'}@;
2023
2024     } elsif ($c =~ m/^Status code/) {
2025
2026         # Status code 304 implies no body.
2027         $c =~ s@(?<=Status code )(\d+)@$h{'status-code'}$1$h{'Standard'}@;
2028
2029     } elsif ($c =~ m/^Method/) {
2030
2031         # Method HEAD implies no body.
2032         $c =~ s@(?<=Method )([^\s]+)@$h{'method'}$1$h{'Standard'}@;
2033
2034     } elsif ($c =~ m/^Buffer limit reached while extending /) {
2035
2036         # Buffer limit reached while extending the buffer (iob). Needed: 4197470. Limit: 4194304
2037         $c =~ s@(?<=Needed: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
2038         $c =~ s@(?<=Limit: )(\d+)@$h{'Number'}$1$h{'Standard'}@;
2039
2040     } elsif ($c =~ m/^File modification detected: /) {
2041
2042         # File modification detected: /usr/local/etc/privoxy/user-agent.action
2043         $c =~ s@(?<= detected: )(.*)$@$h{'file'}$1$h{'Standard'}@;
2044
2045     } elsif ($c =~ m/^No logfile configured/ or
2046              $c =~ m/^Malformerd HTTP headers detected and MS IIS5 hack enabled/ or
2047              $c =~ m/^Invalid \"chunked\" transfer/ or
2048              $c =~ m/^Support for/ or
2049              $c =~ m/^Flushing header and buffers/ or
2050              $c =~ m/^Can not resolve/
2051              ) {
2052
2053         # No logfile configured. Please enable it before reporting any problems.
2054         # Malformerd HTTP headers detected and MS IIS5 hack enabled. Expect an invalid \
2055         #  response or even no response at all.
2056         # No logfile configured. Logging disabled.
2057         # Invalid "chunked" transfer encoding detected and ignored.
2058         # Support for 'Connection: keep-alive' is experimental, incomplete and\
2059         #  known not to work properly in some situations.
2060         # Flushing header and buffers. Stepping back from filtering.
2061         # Can not resolve doesnotexist: hostname nor servname provided, or not known
2062
2063     } else {
2064
2065         found_unknown_content($c);
2066
2067     }
2068
2069     return $c;
2070 }
2071
2072 sub handle_loglevel_cgi($) {
2073
2074     my $c = shift;
2075
2076     if ($c =~ m/^Granting access to/) {
2077
2078         #Granting access to http://config.privoxy.org/send-stylesheet, referrer http://p.p/ is trustworthy.
2079
2080     } elsif ($c =~ m/^Substituting: s(.)/) {
2081
2082         # Substituting: s/@else-not-FEATURE_ZLIB@.*@endif-FEATURE_ZLIB@//sigTU
2083         # XXX: prone to span several lines
2084
2085         my $delimiter = $1;
2086         #$c =~ s@(?<=failed: )(.*)@$h{'error'}$1$h{'Standard'}@;
2087         $c =~ s@(?!<=\\)($delimiter)@$h{'pcrs-delimiter'}$1$h{'Standard'}@g; # XXX: Too aggressive
2088         #$c =~ s@(?!<=\\)($1)@$h{'pcrs-delimiter'}$1$h{'Standard'}@g;
2089     }
2090
2091     return $c;
2092 }
2093
2094 sub handle_loglevel_force($) {
2095
2096     my $c = shift;
2097
2098     if ($c =~ m/^Ignored force prefix in request:/) {
2099
2100         # Ignored force prefix in request: "GET http://10.0.0.1/PRIVOXY-FORCE/block HTTP/1.1"
2101         $c =~ s@^(Ignored)@$h{'ignored'}$1$h{'Standard'}@;
2102         $c = highlight_matched_request_line($c, '(?<=request: ")[^"]*');
2103
2104     } elsif ($c =~ m/^Enforcing request:/) {
2105
2106         # Enforcing request: "GET http://10.0.0.1/block HTTP/1.1".
2107         $c = highlight_matched_request_line($c, '(?<=request: ")[^"]*');
2108
2109     } else {
2110
2111         found_unknown_content($c);
2112
2113     }
2114
2115     return $c;
2116 }
2117
2118 sub handle_loglevel_error($) {
2119
2120     my $c = shift;
2121
2122     if ($c =~ m/^(?:Empty|No) server or forwarder response received on socket \d+\./) {
2123
2124         # Empty server or forwarder response received on socket 4.
2125         # Empty server or forwarder response received on socket 3. \
2126         #  Closing client socket 15 without sending data.
2127         # Used by Privoxy 3.0.18 and later:
2128         # No server or forwarder response received on socket 8. \
2129         #  Closing client socket 10 without sending data.
2130
2131         $c =~ s@(?<=on socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
2132         $c =~ s@(?<=client socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
2133
2134     } elsif ($c =~ m/^Didn't receive data in time:/) {
2135
2136         # Didn't receive data in time: a.fsdn.com:443
2137         $c =~ s@(?<=in time: )(.*)@$h{'destination'}$1$h{'Standard'}@;
2138
2139     } elsif ($c =~ m/^Sending data on socket \d+ over TLS/) {
2140
2141         # Sending data on socket 33 over TLS/SSL failed: no TLS/SSL errors detected
2142         $c =~ s@(?<=on socket )(\d+)@$h{'Number'}$1$h{'Standard'}@;
2143
2144     } elsif ($c =~ m/^Chunk size \d+ exceeds buffered data left/) {
2145
2146         # Chunk size 291 exceeds buffered data left. Already digested 69894 of 69957 buffered bytes.
2147         $c =~ s@(?<=size )(\d+)@$h{'Number'}$1$h{'Standard'}@;
2148         $c =~ s@(?<=digested )(\d+)@$h{'Number'}$1$h{'Standard'}@;
2149         $c =~ s@(?<=of )(\d+)@$h{'Number'}$1$h{'Standard'}@;
2150
2151     }
2152
2153     # XXX: There are probably more messages that deserve highlighting.
2154
2155     return $c;
2156 }
2157
2158
2159 sub handle_loglevel_ignore($) {
2160     return shift;
2161 }
2162
2163 sub gather_loglevel_clf_stats($) {
2164
2165     my $content = shift;
2166     my ($method, $resource, $http_version, $status_code, $size);
2167     our %stats;
2168     our %cli_options;
2169
2170     # +0200] "GET https://www.youtube.com/watch?v=JmcA9LIIXWw HTTP/1.1" 200 68004
2171     # +0200] "VERSION-CONTROL http://p.p/ HTTP/1.1" 200 2787
2172     $content =~ m/^[+-]\d{4}\] "([^ ]+) (.+) (HTTP\/\d\.\d)" (\d+) (\d+)/;
2173     $method       = $1;
2174     $resource     = $2;
2175     $http_version = $3;
2176     $status_code  = $4;
2177     $size         = $5;
2178
2179     $stats{requests_clf}++;
2180
2181     unless (defined $method) {
2182         # +0200] "Invalid request" 400 0
2183         return if ($content =~ m/^[+-]\d{4}\] "Invalid request"/);
2184         # +0100] "Failed reading chunked client body" 400 0
2185         return if ($content =~ m/^[+-]\d{4}\] "Failed reading chunked client body"/);
2186         # +0100] "GET https://securepubads.g.doubleclick.net/gampad/ads?gd[...]... [too long, truncated]
2187         if ($content =~ m/\[too long, truncated\]$/) {
2188             print("Skipped LOG_LEVEL_CLF message that got truncated by Privoxy. Statistics will be inprecise.\n");
2189         } else {
2190             print("Failed to parse: $content\n");
2191         }
2192         return;
2193     }
2194     $stats{'method'}{$method}++;
2195     if ($cli_options{'url-statistics-threshold'} != 0) {
2196         $stats{'resource'}{$resource}++;
2197     }
2198     $stats{'http-version'}{$http_version}++;
2199
2200     if ($cli_options{'host-statistics-threshold'} != 0) {
2201         $resource =~ m@(?:https?://)?([^/]+)/?@;
2202         $stats{'hosts'}{$1}++;
2203     }
2204     $stats{'content-size-total'} += $size;
2205     $stats{'status-code'}{$status_code}++;
2206 }
2207
2208 sub gather_loglevel_request_stats($$) {
2209     my $c = shift;
2210     my $thread = shift;
2211     our %stats;
2212
2213     $stats{requests}++;
2214 }
2215
2216 sub gather_loglevel_crunch_stats($$) {
2217     my $c = shift;
2218     my $thread = shift;
2219     our %stats;
2220
2221     $stats{crunches}++;
2222
2223     if ($c =~ m/^Redirected:/) {
2224         # Redirected: http://www.example.org/http://p.p/
2225         $stats{'fast-redirections'}++;
2226
2227     } elsif ($c =~ m/^Blocked:/) {
2228         # Blocked: blogger.googleusercontent.com:443
2229         $stats{'blocked'}++;
2230
2231     } elsif ($c =~ m/^Connection timeout:/) {
2232         # Connection timeout: http://c.tile.openstreetmap.org/18/136116/87842.png
2233         $stats{'connection-timeout'}++;
2234
2235     } elsif ($c =~ m/^Connection failure:/) {
2236         # Connection failure: http://127.0.0.1:8080/
2237         $stats{'connection-failure'}++;
2238     }
2239 }
2240
2241
2242 sub gather_loglevel_error_stats($$) {
2243
2244     my $c = shift;
2245     my $thread = shift;
2246     our %stats;
2247     our %thread_data;
2248
2249     if ($c =~ m/^Empty server or forwarder response received on socket \d+./) {
2250
2251         # Empty server or forwarder response received on socket 4.
2252         $stats{'empty-responses'}++;
2253         if ($thread_data{$thread}{'new_connection'}) {
2254             $stats{'empty-responses-on-new-connections'}++;
2255         } else {
2256             $stats{'empty-responses-on-reused-connections'}++;
2257         }
2258     }
2259 }
2260
2261 sub gather_loglevel_connect_stats($$) {
2262
2263     my ($c, $thread) = @_;
2264     our %thread_data;
2265     our %stats;
2266
2267     if ($c =~ m/^via ([^\s]+) to: [^\s]+/) {
2268
2269         # Connect: via 10.0.0.1:8123 to: www.example.org.noconnect
2270         $thread_data{$thread}{'forwarder'} = $1; # XXX: is this missue?
2271
2272     } elsif ($c =~ m/^to ([^\s]*)$/) {
2273
2274         # Connect: to lists.sourceforge.net:443
2275
2276         $thread_data{$thread}{'forwarder'} = 'direct connection';
2277
2278     } elsif ($c =~ m/^Created new connection to/) {
2279
2280         # Created new connection to www.privoxy.org:80 on socket 11.
2281
2282         $thread_data{$thread}{'new_connection'} = 1;
2283
2284     } elsif ($c =~ m/^Reusing server socket \d./ or
2285              $c =~ m/^Found reusable socket/) {
2286
2287         # Reusing server socket 4. Opened for 10.0.0.1.
2288         # Found reusable socket 9 for www.privoxy.org:80 in slot 0.
2289
2290         $thread_data{$thread}{'new_connection'} = 0;
2291         $stats{'reused-connections'}++;
2292
2293     } elsif ($c =~ m/^Closing client socket \d+. .* Requests received: (\d+)\.$/) {
2294
2295         # Closing client socket 12. Keep-alive: 1. Socket alive: 1. Data available: 0. \
2296         #  Configuration file change detected: 0. Requests received: 14.
2297
2298         $stats{'client-requests-on-connection'}{$1}++;
2299         $stats{'closed-client-connections'}++;
2300     }
2301 }
2302
2303 sub gather_loglevel_header_stats($$) {
2304
2305     my ($c, $thread) = @_;
2306     our %stats;
2307     our %cli_options;
2308
2309     if ($c =~ m/^A HTTP\/1\.1 response without/ or
2310         $c =~ m/^Keeping the server header 'Connection: keep-alive' around./)
2311     {
2312         # A HTTP/1.1 response without Connection header implies keep-alive.
2313         # Keeping the server header 'Connection: keep-alive' around.
2314         $stats{'server-keep-alive'}++;
2315     }
2316 }
2317
2318 sub init_stats() {
2319     our %stats = (
2320         requests => 0,
2321         requests_clf => 0,
2322         crunches => 0,
2323         'server-keep-alive' => 0,
2324         'reused-connections' => 0,
2325         'empty-responses' => 0,
2326         'empty-responses-on-new-connections' => 0,
2327         'empty-responses-on-reused-connections' => 0,
2328         'fast-redirections' => 0,
2329         'blocked' => 0,
2330         'connection-failure' => 0,
2331         'connection-timeout' => 0,
2332         'reused-connections' => 0,
2333         'server-keep-alive' => 0,
2334         'closed-client-connections' => 0,
2335         'content-size-total' => 0,
2336         );
2337         $stats{'client-requests-on-connection'}{1} = 0;
2338 }
2339
2340 sub get_percentage($$) {
2341     my $big = shift;
2342     my $small = shift;
2343
2344     # If small is 0 the percentage is always 0%.
2345     # Make sure it works even if big is 0 as well.
2346     return "0.00%" if ($small eq 0);
2347
2348     # Prevent division by zero.
2349     # XXX: Is this still supposed to be reachable?
2350     return "NaN" if ($big eq 0);
2351
2352     return sprintf("%.2f%%", $small / $big * 100);
2353 }
2354
2355 sub print_stats() {
2356
2357     our %stats;
2358     our %cli_options;
2359     my $new_connections = $stats{requests} - $stats{crunches} - $stats{'reused-connections'};
2360     my $client_requests_checksum = 0;
2361     my $requests_total;
2362
2363     if ($stats{requests_clf} && $stats{requests}
2364         && $stats{requests_clf} != $stats{requests}) {
2365         print "Inconsistent request counts: " . $stats{requests} . "/" . $stats{requests_clf} . "\n";
2366     }
2367
2368     # To get the total number of requests we can use either the number
2369     # of Common-Log-Format lines or the number of "Request:" messages.
2370     # We prefer the number of CLF lines if available because using
2371     # it works when analysing old log files from Privoxy versions before 3.0.29.
2372     # In Privoxy 3.0.28 and earlier "Request:" messages excluded
2373     # crunched messages.
2374     $requests_total = $stats{requests_clf} ? $stats{requests_clf} : $stats{requests};
2375
2376     if ($requests_total eq 0) {
2377         print "No requests yet.\n";
2378         return;
2379     }
2380
2381     print "Client requests total: " . $requests_total . "\n";
2382     if ($stats{crunches}) {
2383         my $outgoing_requests = $requests_total - $stats{crunches};
2384         print "Crunches: " . $stats{crunches} . " (" .
2385             get_percentage($requests_total, $stats{crunches}) . ")\n";
2386         print "Blocks: " . $stats{'blocked'} . " (" .
2387             get_percentage($requests_total, $stats{'blocked'}) . ")\n";
2388         print "Fast redirections: " . $stats{'fast-redirections'} . " (" .
2389             get_percentage($requests_total, $stats{'fast-redirections'}) . ")\n";
2390         print "Connection timeouts: " . $stats{'connection-timeout'} . " (" .
2391             get_percentage($requests_total, $stats{'connection-timeout'}) . ")\n";
2392         print "Connection failures: " . $stats{'connection-failure'} . " (" .
2393             get_percentage($requests_total, $stats{'connection-failure'}) . ")\n";
2394         print "Outgoing requests: " . $outgoing_requests . " (" .
2395             get_percentage($requests_total, $outgoing_requests) . ")\n";
2396     } else {
2397         print "No crunches detected. Is 'debug 1024' enabled?\n";
2398     }
2399
2400     print "Server keep-alive offers: " . $stats{'server-keep-alive'} . " (" .
2401         get_percentage($requests_total, $stats{'server-keep-alive'}) . ")\n";
2402     print "New outgoing connections: " . $new_connections . " (" .
2403         get_percentage($requests_total, $new_connections) . ")\n";
2404     print "Reused server connections: " . $stats{'reused-connections'} . " (" .
2405         get_percentage($requests_total, $stats{'reused-connections'}) .
2406         "; server offers accepted: " .
2407         get_percentage($stats{'server-keep-alive'}, $stats{'reused-connections'}) . ")\n";
2408     print "Empty responses: " . $stats{'empty-responses'} . " (" .
2409         get_percentage($requests_total, $stats{'empty-responses'}) . ")\n";
2410     print "Empty responses on new connections: "
2411          . $stats{'empty-responses-on-new-connections'} . " (" .
2412         get_percentage($requests_total, $stats{'empty-responses-on-new-connections'})
2413         . ")\n";
2414     print "Empty responses on reused connections: " .
2415         $stats{'empty-responses-on-reused-connections'} . " (" .
2416         get_percentage($requests_total, $stats{'empty-responses-on-reused-connections'}) .
2417         ")\n";
2418     print "Client connections: " .  $stats{'closed-client-connections'} . "\n";
2419     if ($stats{'content-size-total'}) {
2420         print "Bytes of content transferred to the client: " .  $stats{'content-size-total'} . "\n";
2421     }
2422     my $lines_printed = 0;
2423     print "Client requests per connection distribution:\n";
2424     foreach my $client_requests (sort {
2425         $stats{'client-requests-on-connection'}{$b} <=> $stats{'client-requests-on-connection'}{$a}}
2426                                   keys %{$stats{'client-requests-on-connection'}
2427                                   })
2428     {
2429         my $count = $stats{'client-requests-on-connection'}{$client_requests};
2430         $client_requests_checksum += $count * $client_requests;
2431         if ($cli_options{'show-complete-request-distribution'} or ($lines_printed < 10)) {
2432             printf "%8d: %d\n", $count, $client_requests;
2433             $lines_printed++;
2434         }
2435     }
2436     unless ($cli_options{'show-complete-request-distribution'}) {
2437         printf "Enable --show-complete-request-distribution to get less common numbers as well.\n";
2438     }
2439     # Due to log rotation we may not have a complete picture for all the requests
2440     printf "Improperly accounted requests: ~%d\n", abs($requests_total - $client_requests_checksum);
2441
2442     if (exists $stats{method}) {
2443         print "Method distribution:\n";
2444         foreach my $method (sort {$stats{'method'}{$b} <=> $stats{'method'}{$a}} keys %{$stats{'method'}}) {
2445             printf "%8d : %-8s\n", $stats{'method'}{$method}, $method;
2446         }
2447     } else {
2448         print "Method distribution unknown. No CLF message parsed yet. Is 'debug 512' enabled?\n";
2449     }
2450     if (exists $stats{'http-version'}) {
2451         print "Client HTTP versions:\n";
2452         foreach my $http_version (sort {$stats{'http-version'}{$b} <=> $stats{'http-version'}{$a}} keys %{$stats{'http-version'}}) {
2453             printf "%8d : %-8s\n",  $stats{'http-version'}{$http_version}, $http_version;
2454         }
2455     } else {
2456         print "HTTP version distribution unknown. No CLF message parsed yet. Is 'debug 512' enabled?\n";
2457     }
2458     if (exists $stats{'status-code'}) {
2459         print "HTTP status codes according to 'debug 512' (status codes sent by the server may differ):\n";
2460         foreach my $status_code (sort {$stats{'status-code'}{$b} <=> $stats{'status-code'}{$a}} keys %{$stats{'status-code'}}) {
2461             printf "%8d : %-8d\n",  $stats{'status-code'}{$status_code}, $status_code;
2462         }
2463     } else {
2464         print "Status code distribution unknown. No CLF message parsed yet. Is 'debug 512' enabled?\n";
2465     }
2466
2467     if ($cli_options{'url-statistics-threshold'} == 0) {
2468         print "URL statistics are disabled. Increase --url-statistics-threshold to enable them.\n";
2469     } else {
2470         print "Requested URLs:\n";
2471         foreach my $resource (sort {$stats{'resource'}{$b} <=> $stats{'resource'}{$a}} keys %{$stats{'resource'}}) {
2472             if ($stats{'resource'}{$resource} < $cli_options{'url-statistics-threshold'}) {
2473                 print "Skipped statistics for URLs below the treshold.\n";
2474                 last;
2475             }
2476             printf "%d : %s\n", $stats{'resource'}{$resource}, $resource;
2477         }
2478     }
2479
2480     if ($cli_options{'host-statistics-threshold'} == 0) {
2481         print "Host statistics are disabled. Increase --host-statistics-threshold to enable them.\n";
2482     } else {
2483         print "Requested Hosts:\n";
2484         foreach my $host (sort {$stats{'hosts'}{$b} <=> $stats{'hosts'}{$a}} keys %{$stats{'hosts'}}) {
2485             if ($stats{'hosts'}{$host} < $cli_options{'host-statistics-threshold'}) {
2486                 print "Skipped statistics for Hosts below the treshold.\n";
2487                 last;
2488             }
2489             printf "%d : %s\n", $stats{'hosts'}{$host}, $host;
2490         }
2491     }
2492 }
2493
2494
2495 ################################################################################
2496 # Functions that actually print stuff
2497 ################################################################################
2498
2499 sub print_clf_message() {
2500
2501     our ($ip, $timestamp, $request_line, $status_code, $size);
2502     my $output = '';
2503
2504     return if DEBUG_SUPPRESS_LOG_MESSAGES;
2505
2506     # Rebuild highlighted
2507     $output .= $h{'Number'} . $ip . $h{'Standard'};
2508     $output .= " - - ";
2509     $output .= "[" . $h{'Timestamp'} . $timestamp . $h{'Standard'} . "]";
2510     $output .= " ";
2511     $output .= "\"" . highlight_request_line("$request_line") . "\"";
2512     $output .= " ";
2513     $output .= $h{'Status'} . $status_code . $h{'Standard'};
2514     $output .= " ";
2515     $output .= $h{'Number'} . $size . $h{'Standard'};
2516     $output .= $line_end;
2517
2518     print $output;
2519 }
2520
2521 sub print_non_clf_message($) {
2522
2523     my $content = shift;
2524     my $date_string = $keep_date_mode ? $req{$t}{'day'} . ' ' : '';
2525     my $msec_string = $no_msecs_mode ? '' : '.' . $req{$t}{'msecs'};
2526     my $line_start = $html_output_mode ? '' : $h{"Standard"};
2527
2528     return if DEBUG_SUPPRESS_LOG_MESSAGES;
2529
2530     print $line_start
2531         . $date_string
2532         . $time_colours[$time_colour_index % 2]
2533         . $req{$t}{'time-stamp'}
2534         . $msec_string
2535         . $h{Standard} . " "
2536         . $thread_colours{$t}
2537         . $t
2538         . $h{Standard}
2539         . " "
2540         . $h{$req{$t}{'log-level'}}
2541         . $req{$t}{'log-level'}
2542         . $h{Standard}
2543         . ": "
2544         . $content
2545         . $line_end;
2546 }
2547
2548 sub shorten_thread_id($) {
2549
2550     my $thread_id = shift;
2551
2552     our %short_thread_ids;
2553     our $max_threadid;
2554
2555     unless (defined $short_thread_ids{$thread_id}) {
2556         $short_thread_ids{$thread_id} = sprintf "%.3d", $max_threadid++;
2557     }
2558
2559     return $short_thread_ids{$thread_id}
2560 }
2561
2562 sub parse_loop() {
2563
2564     my ($day, $time_stamp, $thread, $log_level, $content, $c, $msecs);
2565     my $last_msecs  = 0;
2566     my $last_thread = 0;
2567     my $last_timestamp = 0;
2568     my $filters_that_did_nothing;
2569     my $key;
2570     my $time_colour;
2571     $time_colour = paint_it('white');
2572
2573     my %log_level_handlers = (
2574         'Re-Filter'         => \&handle_loglevel_re_filter,
2575         'Header'            => \&handle_loglevel_header,
2576         'Connect'           => \&handle_loglevel_connect,
2577         'Redirect'          => \&handle_loglevel_redirect,
2578         'Request'           => \&handle_loglevel_request,
2579         'Crunch'            => \&handle_loglevel_crunch,
2580         'Gif-Deanimate'     => \&handle_loglevel_gif_deanimate,
2581         'Info'              => \&handle_loglevel_info,
2582         'CGI'               => \&handle_loglevel_cgi,
2583         'Force'             => \&handle_loglevel_force,
2584         'Error'             => \&handle_loglevel_error,
2585         'Fatal error'       => \&handle_loglevel_ignore,
2586         'Writing'           => \&handle_loglevel_ignore,
2587         'Received'          => \&handle_loglevel_ignore,
2588         'Tagging'           => \&handle_loglevel_tagging,
2589         'Actions'           => \&handle_loglevel_ignore,
2590         'Unknown log level' => \&handle_loglevel_ignore,
2591     );
2592
2593     while (<>) {
2594
2595         if (m/^(\d{4}-\d{2}-\d{2}|\w{3} \d{2}) (\d\d:\d\d:\d\d)\.?(\d+)? (?:Privoxy\()?([^\)\s]*)[\)]? ([\w -]*): (.*?)\r?$/) {
2596             $thread = $t = ($shorten_thread_ids) ? shorten_thread_id($4) : $4;
2597             $req{$t}{'day'} = $day = $1;
2598             $req{$t}{'time-stamp'} = $time_stamp = $2;
2599             $req{$t}{'msecs'} = $msecs = $3 ? $3 : 0; # Only the cool kids have micro second resolution;
2600             $req{$t}{'log-level'} = $log_level = $5;
2601             $req{$t}{'content'} = $content = $c = $6;
2602             $req{$t}{'log-message'} = $_;
2603             $no_special_header_highlighting = 0;
2604
2605             if (defined($log_level_handlers{$log_level})) {
2606
2607                 $content = $log_level_handlers{$log_level}($content);
2608
2609             } else {
2610
2611                 die "No handler found for log level \"$log_level\"\n";
2612             }
2613
2614             # Highlight Truncations
2615             if (length($_) > 4000) {
2616                 $content =~ s@(too long, truncated)]$@$h{'Truncation'}$1$h{'Standard'}]@g;
2617             }
2618
2619             next unless $content;
2620
2621             # Register threads to keep the colour constant
2622             if (!defined($thread_colours{$thread})) {
2623                 $thread_colours{$thread} = $all_colours[$thread_colour_index % @all_colours];
2624                 $thread_colour_index++;
2625             }
2626
2627             # Switch timestamp colour if timestamps differ
2628             if (($msecs ne $last_msecs) || ($time_stamp ne $last_timestamp)) {
2629                debug_message("Tick tack!") if DEBUG_TICKS;
2630                $time_colour = $time_colours[$time_colour_index % 2];
2631                $time_colour_index++;
2632                $last_msecs = $msecs;
2633                $last_timestamp = $time_stamp;
2634             }
2635
2636             $last_thread = $thread;
2637
2638             print_non_clf_message($content);
2639
2640         } elsif (m/^((?:\d+\.\d+\.\d+\.\d+|[:\d]+)) - - \[(.*)\] "(.*)" (\d+) (\d+)/) {
2641
2642             # LOG_LEVEL_CLF lines look like this
2643             # 61.152.239.32 - - [04/Mar/2007:18:28:23 +0100] "GET \
2644             #  http://ad.yieldmanager.com/imp?z=1&Z=120x600&s=109339&u=http%3A%2F%2Fwww.365loan.co.uk%2F&r=1\
2645             #  HTTP/1.1" 403 1730
2646             our ($ip, $timestamp, $request_line, $status_code, $size) = ($1, $2, $3, $4, $5);
2647
2648             print_clf_message();
2649
2650         } else {
2651
2652             # Some Privoxy log messages span more than one line,
2653             # usually to dump lots of content that doesn't need any syntax highlighting.
2654             # XXX: add mechanism to forward these lines to the right handler anyway.
2655             chomp();
2656             unless (DEBUG_SUPPRESS_LOG_MESSAGES or (SUPPRESS_EMPTY_LINES and m/^\s+$/)) {
2657                 print and print get_line_end(); # unless (SUPPRESS_EMPTY_LINES and m/^\s+$/);
2658             }
2659         }
2660     }
2661 }
2662
2663 sub stats_loop() {
2664
2665     my ($day, $time_stamp, $thread, $log_level, $content);
2666     my $strict_checks = cli_option_is_set('strict-checks');
2667     my %log_level_handlers = (
2668          'Connect:'           => \&gather_loglevel_connect_stats,
2669          'Crunch:'            => \&gather_loglevel_crunch_stats,
2670          'Error:'             => \&gather_loglevel_error_stats,
2671          'Header:'            => \&gather_loglevel_header_stats,
2672          'Request:'           => \&gather_loglevel_request_stats,
2673     );
2674     my %ignored_log_levels = (
2675          'Actions:'           => \&handle_loglevel_ignore,
2676          'CGI:'               => \&handle_loglevel_ignore,
2677          'Fatal error:'       => \&handle_loglevel_ignore,
2678          'Force:'             => \&handle_loglevel_ignore,
2679          'Gif-Deanimate:'     => \&handle_loglevel_ignore,
2680          'Info:'              => \&handle_loglevel_ignore,
2681          'Re-Filter:'         => \&handle_loglevel_ignore,
2682          'Received:'          => \&handle_loglevel_ignore,
2683          'Redirect:'          => \&handle_loglevel_ignore,
2684          'Unknown log level:' => \&handle_loglevel_ignore,
2685          'Writing:'           => \&handle_loglevel_ignore,
2686          'Tagging:'           => \&handle_loglevel_ignore,
2687     );
2688
2689     while (<>) {
2690         (undef, $time_stamp, $thread, $log_level, $content) = split(/ /, $_, 5);
2691
2692
2693         next if (not defined($log_level));
2694
2695         if ($time_stamp eq "-") {
2696
2697             gather_loglevel_clf_stats($content);
2698
2699         } elsif (defined($log_level_handlers{$log_level})) {
2700
2701             $content = $log_level_handlers{$log_level}($content, $thread);
2702
2703         } elsif ($strict_checks and not defined($ignored_log_levels{$log_level})) {
2704
2705             die "No handler found for: $_";
2706         }
2707     }
2708
2709     print_stats();
2710
2711 }
2712
2713 # Convert a timestamp like 18:07:28.733 into miliseconds
2714 sub time_stamp_to_msecs($) {
2715     my $time_stamp = shift;
2716
2717     if ($time_stamp =~ /(\d\d):(\d\d):(\d\d)\.(\d{3})/) {
2718         my ($hours, $minutes, $seconds, $msecs) = ($1, $2, $3, $4);
2719
2720         $msecs += $seconds * 1000;
2721         $msecs += $minutes * 1000 * 60;
2722         $msecs += $hours   * 1000 * 60 * 60;
2723
2724         return $msecs;
2725     }
2726     return undef;
2727 }
2728
2729 sub inactivity_detection_loop() {
2730
2731     our %cli_options;
2732     my ($time_stamp, $thread, $log_level, $content);
2733     my ($msecs, $previous_msecs, $inactivity);
2734     my $inactivity_threshold = $cli_options{'inactivity-threshold'};
2735     my $previous_message;
2736     my $log_message_out_of_order = 0;
2737
2738     while (<>) {
2739         (undef, $time_stamp, $thread, $log_level, $content) = split(/ /, $_, 5);
2740
2741         next if (not defined($log_level));
2742         next if ($time_stamp eq "-");
2743         $msecs = time_stamp_to_msecs($time_stamp);
2744         unless (defined $msecs) {
2745             print "Failed to convert $time_stamp into miliseconds\n";
2746             next;
2747         }
2748         unless (defined $previous_msecs) {
2749             $previous_msecs = $msecs;
2750             next;
2751         }
2752         $inactivity = $msecs - $previous_msecs;
2753         if ($inactivity < 0) {
2754             # This can happen if there's a high load in which case
2755             # a Privoxy thread may be moved off schedule between
2756             # getting the timestamp for the log message and actually
2757             # writing it.
2758             $log_message_out_of_order++;
2759         }
2760         if ($inactivity > $inactivity_threshold) {
2761             #print "$previous_message";
2762             print "Detected inactivity: $inactivity msecs\n";
2763         }
2764         print "$_";
2765         $previous_msecs = $msecs;
2766         $previous_message = $_;
2767     }
2768     if ($log_message_out_of_order) {
2769         print "At least $log_message_out_of_order messages were written out of the chronological order.\n";
2770         print "This can result in false positives. Consider sorting the log first.\n";
2771     }
2772 }
2773
2774 sub unbreak_lines_only_loop() {
2775     my $log_messages_reached = 0;
2776     while (<>) {
2777         chomp;
2778
2779             # Log level other than LOG_LEVEL_CLF?
2780         if (m/^(\d{4}-\d{2}-\d{2}|\w{3} \d{2}) (\d\d:\d\d:\d\d)\.?(\d+)? (?:Privoxy\()?([^\)\s]*)[\)]? ([\w -]*): (.*?)\r?$/ or
2781             # LOG_LEVEL_CLF?
2782             m/^((?:\d+\.\d+\.\d+\.\d+)) - - \[(.*)\] "(.*)" (\d+) (\d+)/) {
2783             $log_messages_reached = 1;
2784             print "\n";
2785
2786         } else {
2787             # Wrapped message
2788             $_ = "\n". $_  if /^(?:\d+\.\d+\.\d+\.\d+)/;
2789             $_ = " " . $_;
2790         }
2791         s@<BR>$@@;
2792         print;
2793         print "\n" unless $log_messages_reached;
2794     }
2795     print "\n";
2796 }
2797
2798 sub VersionMessage {
2799     my $version_message;
2800
2801     $version_message .= 'Privoxy-Log-Parser ' . PRIVOXY_LOG_PARSER_VERSION  . "\n";
2802     $version_message .= 'https://www.fabiankeil.de/sourcecode/privoxy-log-parser/' . "\n";
2803
2804     print $version_message;
2805 }
2806
2807 sub get_cli_options() {
2808
2809     our %cli_options = (
2810         'detect-inactivity'        => CLI_OPTION_DETECT_INACTIVITY,
2811         'inactivity-threshold'     => CLI_OPTION_INACTIVITY_THRESHOLD,
2812         'html-output'              => CLI_OPTION_DEFAULT_TO_HTML_OUTPUT,
2813         'title'                    => CLI_OPTION_TITLE,
2814         'keep-date'                => CLI_OPTION_KEEP_DATE,
2815         'no-syntax-highlighting'   => CLI_OPTION_NO_SYNTAX_HIGHLIGHTING,
2816         'no-embedded-css'          => CLI_OPTION_NO_EMBEDDED_CSS,
2817         'no-msecs'                 => CLI_OPTION_NO_MSECS,
2818         'shorten-thread-ids'       => CLI_OPTION_SHORTEN_THREAD_IDS,
2819         'show-ineffective-filters' => CLI_OPTION_SHOW_INEFFECTIVE_FILTERS,
2820         'statistics'               => CLI_OPTION_STATISTICS,
2821         'strict-checks'            => CLI_OPTION_STRICT_CHECKS,
2822         'url-statistics-threshold' => CLI_OPTION_URL_STATISTICS_THRESHOLD,
2823         'unbreak-lines-only'       => CLI_OPTION_UNBREAK_LINES_ONLY,
2824         'host-statistics-threshold'=> CLI_OPTION_HOST_STATISTICS_THRESHOLD,
2825         'show-complete-request-distribution' => CLI_OPTION_SHOW_COMPLETE_REQUEST_DISTRIBUTION,
2826     );
2827
2828     GetOptions (
2829         'detect-inactivity'        => \$cli_options{'detect-inactivity'},
2830         'inactivity-threshold=i'   => \$cli_options{'inactivity-threshold'},
2831         'html-output'              => \$cli_options{'html-output'},
2832         'title'                    => \$cli_options{'title'},
2833         'keep-date'                => \$cli_options{'keep-date'},
2834         'no-syntax-highlighting'   => \$cli_options{'no-syntax-highlighting'},
2835         'no-embedded-css'          => \$cli_options{'no-embedded-css'},
2836         'no-msecs'                 => \$cli_options{'no-msecs'},
2837         'shorten-thread-ids'       => \$cli_options{'shorten-thread-ids'},
2838         'show-ineffective-filters' => \$cli_options{'show-ineffective-filters'},
2839         'statistics'               => \$cli_options{'statistics'},
2840         'strict-checks'            => \$cli_options{'strict-checks'},
2841         'unbreak-lines-only'       => \$cli_options{'unbreak-lines-only'},
2842         'url-statistics-threshold=i'=> \$cli_options{'url-statistics-threshold'},
2843         'host-statistics-threshold=i'=> \$cli_options{'host-statistics-threshold'},
2844         'show-complete-request-distribution' => \$cli_options{'show-complete-request-distribution'},
2845         'version'                  => sub { VersionMessage && exit(0) },
2846         'help'                     => \&help,
2847    ) or exit(1);
2848
2849    $html_output_mode = cli_option_is_set('html-output');
2850    $no_msecs_mode = cli_option_is_set('no-msecs');
2851    $keep_date_mode = cli_option_is_set('keep-date');
2852    $shorten_thread_ids = cli_option_is_set('shorten-thread-ids');
2853    $line_end = get_line_end();
2854 }
2855
2856 sub help() {
2857
2858     our %cli_options;
2859
2860     VersionMessage();
2861
2862     print << "    EOF"
2863
2864 Options and their default values if they have any:
2865     [--detect-innactivity]
2866     [--inactivity-threshold $cli_options{'inactivity-threshold'}]
2867     [--host-statistics-threshold $cli_options{'host-statistics-threshold'}]
2868     [--html-output]
2869     [--no-embedded-css]
2870     [--no-msecs]
2871     [--no-syntax-highlighting]
2872     [--shorten-thread-ids]
2873     [--show-ineffective-filters]
2874     [--show-complete-request-distribution]
2875     [--statistics]
2876     [--unbreak-lines-only]
2877     [--url-statistics-threshold $cli_options{'url-statistics-threshold'}]
2878     [--title $cli_options{'title'}]
2879     [--version]
2880 see "perldoc $0" for more information
2881     EOF
2882     ;
2883     exit(0);
2884 }
2885
2886 ################################################################################
2887 # main
2888 ################################################################################
2889 sub main() {
2890
2891     get_cli_options();
2892     set_background(DEFAULT_BACKGROUND);
2893     prepare_our_stuff();
2894
2895     # XXX: should explicitly reject incompatible argument combinations
2896     if (cli_option_is_set('unbreak-lines-only')) {
2897         unbreak_lines_only_loop();
2898     } elsif (cli_option_is_set('statistics')) {
2899         stats_loop();
2900     } elsif (cli_option_is_set('detect-inactivity')) {
2901         inactivity_detection_loop();
2902     } else {
2903         print_intro();
2904         parse_loop();
2905         print_outro();
2906     }
2907 }
2908
2909 main();
2910
2911 =head1 NAME
2912
2913 B<privoxy-log-parser> - A parser and syntax-highlighter for Privoxy log messages
2914
2915 =head1 SYNOPSIS
2916
2917 B<privoxy-log-parser> [B<--detect-inactivity>] [B<--inactivity-threshold msecs>]
2918 [B<--html-output>]
2919 [B<--no-msecs>] [B<--no-syntax-higlighting>] [B<--statistics>]
2920 [B<--shorten-thread-ids>] [B<--show-ineffective-filters>]
2921 [B<--url-statistics-threshold>] [B<--version>]
2922
2923 =head1 DESCRIPTION
2924
2925 B<privoxy-log-parser> reads Privoxy log messages and
2926
2927 - syntax-highlights recognized lines,
2928
2929 - reformats some of them for easier comprehension,
2930
2931 - filters out less useful messages, and
2932
2933 - (in some cases) calculates additional information,
2934   like the compression ratio or how a filter affected
2935   the content size.
2936
2937 With B<privoxy-log-parser> you should be able to increase Privoxy's log level
2938 without getting confused by the resulting amount of output. For example for
2939 "debug 64" B<privoxy-log-parser> will (by default) only show messages that
2940 affect the content. If a filter doesn't cause any hits, B<privoxy-log-parser>
2941 will hide the "filter foo caused 0 hits" message.
2942
2943 =head1 OPTIONS
2944
2945 [B<--detect-inactivity>] Instead of syntax highlighting, detect inactivities
2946 of more than B<inactivity-threshold> miliseconds. Mainly useful for debugging.
2947
2948 [B<--host-statistics-threshold>] Only show the request count for a host
2949 if it's above or equal to the given threshold. If the threshold is 0, host
2950 statistics are disabled.
2951
2952 [B<--html-output>] Use HTML and CSS when syntax highlighting. If this option is
2953 omitted, ANSI escape sequences are used unless B<--no-syntax-highlighting> is active.
2954 This option is only intended to make embedding log excerpts in web pages easier.
2955 It does not escape any input!
2956
2957 [B<--inactivity-threshold>] Specifies the number of miliseconds between log
2958 messages to consider inactivity when running in [B<--detect-inactivity>] mode.
2959
2960 [B<--keep-date>] Don't remove the date when printing highlighted log messages.
2961 Useful when parsing multiple log files at once.
2962
2963 [B<--no-msecs>] Don't expect millisecond resolution
2964
2965 [B<--no-syntax-highlighting>] Disable syntax-highlighting. Useful when
2966 the filtered output is piped into less in which case the ANSI control
2967 codes don't work, or if the terminal itself doesn't support the control
2968 codes.
2969
2970 [B<--shorten-thread-ids>] Shorten the thread ids to a three-digit decimal number.
2971 Note that the mapping from thread ids to shortened ids is created at run-time
2972 and thus varies with the input.
2973
2974 [B<--show-ineffective-filters>] Don't suppress log lines for filters
2975 that didn't modify the content.
2976
2977 [B<--show-complete-request-distribution>] Show the complete client request
2978 distribution in the B<--statistics> output. Without this option only the
2979 ten most common numbers are shown.
2980
2981 [B<--statistics>] Gather various statistics instead of syntax highlighting
2982 log messages. This is an experimental feature, if the results look wrong
2983 they very well might be. Also note that the results are pretty much guaranteed
2984 to be incorrect if Privoxy and Privoxy-Log-Parser aren't in sync.
2985
2986 [B<--strict-checks>] When generating statistics, look more careful at the
2987 input data and abort if it is unexpected, even if it doesn't affect the
2988 results. Significantly slows the parsing down and is not expected to catch
2989 any problems that matter.
2990 When highlighting, print warnings in case of unknown messages which can't be
2991 properly highlighted.
2992
2993 [B<--unbreak-lines-only>] Tries to fix lines that got messed up by a broken or
2994 interestingly configured mail client and thus are no longer recognized properly.
2995 Only fixes some breakage, but may be good enough or at least better than nothing.
2996 Doesn't do anything else, so you probably want to pipe the output into
2997 B<privoxy-log-parser> again.
2998
2999 [B<--url-statistics-threshold>] Only show the request count for a resource
3000 if it's above or equal to the given threshold. If the threshold is 0, URL
3001 statistics are disabled.
3002
3003 [B<--version>] Print version and exit.
3004
3005 =head1 EXAMPLES
3006
3007 To monitor a log file:
3008
3009 tail -F /usr/jails/privoxy-jail/var/log/privoxy/privoxy.log | B<privoxy-log-parser>
3010
3011 Replace '-F' with '-f' if your tail implementation lacks '-F' support
3012 or if the log won't get rotated anyway. The log file location depends
3013 on your system (Doh!).
3014
3015 To monitor Privoxy without having it write to a log file:
3016
3017 privoxy --no-daemon /usr/jails/privoxy-jail/usr/local/etc/privoxy/config 2>&1 | B<privoxy-log-parser>
3018
3019 Again, the config file location depends on your system. Output redirection
3020 depends on your shell, the above works with bourne shells.
3021
3022 To read a processed Privoxy log file from top to bottom, letting the content
3023 scroll by slightly faster than you can read:
3024
3025 B<privoxy-log-parser> < /usr/jails/privoxy-jail/var/log/privoxy/privoxy.log
3026
3027 This is probably only useful to fill screens in the background of haxor movies.
3028
3029 =head1 CAVEATS
3030
3031 Syntax highlighting with ANSI escape sequences will look strange
3032 if your background color isn't black.
3033
3034 Some messages aren't recognized yet and will not be fully highlighted.
3035
3036 B<privoxy-log-parser> is developed with Privoxy 3.0.7 or later in mind,
3037 using earlier Privoxy versions will probably result in an increased amount
3038 of unrecognized log lines.
3039
3040 Privoxy's log files tend to be rather large. If you use HTML
3041 highlighting some browsers can't handle them, get confused and
3042 will eventually crash because of segmentation faults or unexpected
3043 exceptions. This is a problem in the browser and not B<privoxy-log-parser>'s
3044 fault.
3045
3046 =head1 BUGS
3047
3048 Many settings can't be controlled through command line options yet.
3049
3050 =head1 SEE ALSO
3051
3052 privoxy(8)
3053
3054 =head1 AUTHOR
3055
3056 Fabian Keil <fk@fabiankeil.de>
3057
3058 =cut