Attachment 80433 Details for Bug 115369 – sa323_1.txt

sa323_1.txt

sa323_1.txt (text/plain; format=flowed), 51.74 KB, created by Michael Scheidell on 2007-08-10 18:52:19 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Michael Scheidell

Created: 2007-08-10 18:52:19 UTC

Size: 51.74 KB

patch

obsolete

>diff -bBru /var/tmp/p5-Mail-SpamAssassin/Makefile ./Makefile
>--- /var/tmp/p5-Mail-SpamAssassin/Makefile	Sun Jul 22 18:40:58 2007
>+++ ./Makefile	Fri Aug 10 13:47:04 2007
>@@ -6,8 +6,7 @@
> #
> 
> PORTNAME=	Mail-SpamAssassin
>-PORTVERSION=	3.2.1
>-PORTREVISION=	1
>+PORTVERSION=	3.2.3
> CATEGORIES=	mail perl5
> MASTER_SITES=	${MASTER_SITE_APACHE:S/$/:apache/} ${MASTER_SITE_PERL_CPAN:S/$/:cpan/}
> MASTER_SITE_SUBDIR=	spamassassin/source/:apache Mail/:cpan
>@@ -27,7 +26,8 @@
> RUN_DEPENDS=	${BUILD_DEPENDS} \
> 		${SITE_PERL}/Bundle/LWP.pm:${PORTSDIR}/www/p5-libwww \
> 		p5-Archive-Tar>=1.23:${PORTSDIR}/archivers/p5-Archive-Tar \
>-		${SITE_PERL}/mach/Encode/Detect.pm:${PORTSDIR}/converters/p5-Encode-Detect
>+		${SITE_PERL}/mach/Encode/Detect.pm:${PORTSDIR}/converters/p5-Encode-Detect \
>+		p5-Time-HiRes>=0:${PORTSDIR}/devel/p5-Time-HiRes
> 
> PERL_CONFIGURE=	yes
> USE_LDCONFIG=	yes
>@@ -97,7 +97,7 @@
> .if defined(WITH_DKIM)
> RUN_DEPENDS+=	p5-Mail-DKIM>=.20:${PORTSDIR}/mail/p5-Mail-DKIM
> RUN_DEPENDS+=	${SITE_PERL}/IO/Socket/SSL.pm:${PORTSDIR}/security/p5-IO-Socket-SSL
>-RUN_DEPENDS+=	p5-Mail-DomainKeys>=0.80:${PORTSDIR}/mail/p5-Mail-DomainKeys
>+RUN_DEPENDS+=	p5-Crypt-OpenSSL-RSA>=0.24:${PORTSDIR}/security/p5-Crypt-OpenSSL-RSA
> .endif
> 
> .if defined(WITH_SACOMPILE)
>@@ -212,7 +212,6 @@
> .endif
> .if defined(WITH_DKIM)
> 	${REINPLACE_CMD} -e '/DKIM/s/^#loadplugin/loadplugin/' ${WRKSRC}/rules/v312.pre
>-	${REINPLACE_CMD} -e '/DomainKeys/s/^#loadplugin/loadplugin/' ${WRKSRC}/rules/v310.pre
> .endif
> .if !defined(WITH_SPF_QUERY)
> 	${REINPLACE_CMD} -e '/SPF/s/^loadplugin/#loadplugin/' ${WRKSRC}/rules/init.pre
>@@ -266,10 +265,5 @@
> 
> .endif
> 	@${SED} -e 's#PREFIX#${PREFIX}#' ${PKGMESSAGE}
>-
>-.if ${PERL_LEVEL} < 500800
>-BUILD_DEPENDS+=	${SITE_PERL}/${PERL_ARCH}/MIME/Base64.pm:${PORTSDIR}/converters/p5-MIME-Base64 \
>-		${SITE_PERL}/${PERL_ARCH}/Storable.pm:${PORTSDIR}/devel/p5-Storable
>-.endif
> 
> .include <bsd.port.post.mk>
>diff -bBru /var/tmp/p5-Mail-SpamAssassin/distinfo ./distinfo
>--- /var/tmp/p5-Mail-SpamAssassin/distinfo	Sat Jun 16 18:17:03 2007
>+++ ./distinfo	Thu Aug  9 19:28:55 2007
>@@ -1,3 +1,3 @@
>-MD5 (Mail-SpamAssassin-3.2.1.tar.gz) = a7d51294c565999da01f212e5ad2a031
>-SHA256 (Mail-SpamAssassin-3.2.1.tar.gz) = e0925d9c490bb8f1e56c3b850b50b12b124536dfe581b23d3c25715b1ce9ebf7
>-SIZE (Mail-SpamAssassin-3.2.1.tar.gz) = 1193561
>+MD5 (Mail-SpamAssassin-3.2.3.tar.gz) = 2e356b70b9458b44a828c19f6e816521
>+SHA256 (Mail-SpamAssassin-3.2.3.tar.gz) = 2bf7635555dea4912512a32c7c567094ef264770b86029c49f653e97352efad8
>+SIZE (Mail-SpamAssassin-3.2.3.tar.gz) = 1202082
>diff -bBru /var/tmp/p5-Mail-SpamAssassin/files/patch-ImageInfo.pm ./files/patch-ImageInfo.pm
>--- /var/tmp/p5-Mail-SpamAssassin/files/patch-ImageInfo.pm	Sat Jun  2 03:09:46 2007
>+++ ./files/patch-ImageInfo.pm	Sun Jul 29 19:47:26 2007
>@@ -1,98 +1,17 @@
> --- ImageInfo.pm.orig	Tue May  1 09:54:09 2007
> +++ lib/Mail/SpamAssassin/Plugin/ImageInfo.pm	Thu May  3 16:08:29 2007
>-@@ -1,10 +1,9 @@
>- # <@LICENSE>
>--# Licensed to the Apache Software Foundation (ASF) under one or more
>--# contributor license agreements.  See the NOTICE file distributed with
>--# this work for additional information regarding copyright ownership.
>--# The ASF licenses this file to you under the Apache License, Version 2.0
>--# (the "License"); you may not use this file except in compliance with
>--# the License.  You may obtain a copy of the License at:
>-+# Copyright 2004 Apache Software Foundation
>-+# 
>-+# Licensed under the Apache License, Version 2.0 (the "License");
>-+# you may not use this file except in compliance with the License.
>-+# You may obtain a copy of the License at
>- # 
>- #     http://www.apache.org/licenses/LICENSE-2.0
>- # 
>-@@ -16,6 +15,36 @@
>- # </@LICENSE>
>- #
>- # -------------------------------------------------------
>-+# ImageInfo Plugin for SpamAssassin
>-+# Version: 0.7
>-+# Current Home: http://www.rulesemporium.com/plugins.htm#imageinfo
>-+# Created: 2006-08-02
>-+# Modified: 2007-01-17
>-+# By: Dallas Engelken <dallase@uribl.com>
>-+#
>-+# Changes: 
>-+#   0.7 - added image_name_regex to allow pattern matching on the image name
>-+#       - added support for image/pjpeg content types (progressive jpeg)
>-+#       - updated imageinfo.cf with a few sample rules for using image_name_regex()
>-+#   0.6 - fixed dems_ bug in image_size_range_
>-+#   0.5 - added image_named and image_to_text_ratio
>-+#   0.4 - added image_size_exact and image_size_range
>-+#   0.3 - added jpeg support
>-+#   0.2 - optimized by theo
>-+#   0.1 - added gif/png support
>-+#
>-+# Files:
>-+#   ImageInfo.pm (plugin)  - http://www.rulesemporium.com/plugins/ImageInfo.pm
>-+#   imageinfo.cf (ruleset) - http://www.rulesemporium.com/plugins/imageinfo.cf
>-+#   
>-+# Install:
>-+#   1) place ruleset in your local config dir
>-+#   2) place plugin in your plugins dir 
>-+#   3) add to init.pre (or v310.pre) the following line
>-+#      loadplugin Mail::SpamAssassin::Plugin::ImageInfo
>-+#           or if not in plugin dir..
>-+#      loadplugin Mail::SpamAssassin::Plugin::ImageInfo /path/to/plugin
>-+#    4) restart spamd (if necessary)
>- #
>- # Usage:
>- #  image_count()
>-@@ -27,7 +56,7 @@
>- #        max: optional, if specified, message must not 
>- #             contain more than this number of images
>+@@ -49,6 +49,10 @@
>+ #     body LARGE_IMAGE_AREA  eval:pixel_coverage('all',150000)
>+ #     body SMALL_GIF_AREA  eval:pixel_coverage('gif',1,40000)
>  #
>--#  examples
>-+#  image_count() examples
>- # 
>- #     body ONE_IMAGE  eval:image_count('all',1,1) 
>- #     body ONE_OR_MORE_IMAGES  eval:image_count('all',1)
>-@@ -44,13 +73,24 @@
>- #        max: optional, if specified, message must not
>- #             contain more than this much pixel area
>- #
>--#  examples
>-+#   pixel_coverage() examples
>-+#
>-+#     body LARGE_IMAGE_AREA  eval:pixel_coverage('all',150000)  # catches any images that are 150k pixel/sq or higher
>-+#     body SMALL_GIF_AREA  eval:pixel_coverage('gif',1,40000)   # catches only gifs that 1 to 40k pixel/sql
>-+#
>-+#  image_name_regex()
>-+# 
>-+#     body RULENAME  eval:image_name_regex(<regex>) 
>-+#        regex: full quoted regexp, see examples below
>-+#
> +#  image_name_regex() examples
> +#
> +#     body CG_DOUBLEDOT_GIF  eval:image_name_regex('/^\w{2,9}\.\.gif$/i') # catches double dot gifs  abcd..gif
>++#
>+ #  See the ruleset for ways to meta image_count() 
>+ #  and pixel_coverage() together.  
>  #
>--#     body LARGE_IMAGE_AREA  eval:pixel_coverage('all',150000)
>--#     body SMALL_GIF_AREA  eval:pixel_coverage('gif',1,40000)
>-+#  See the ruleset for more examples that arent documented here.
>- #
>--#  See the ruleset for ways to meta image_count() 
>--#  and pixel_coverage() together.  
>-+#  New functions added in v0.5+ need some documentation here.  Or just 
>-+#  see .cf for sample rules.
>- #
>- # -------------------------------------------------------
>- 
>-@@ -80,6 +120,7 @@
>+@@ -80,6 +84,7 @@
>    $self->register_eval_rule ("image_size_exact");
>    $self->register_eval_rule ("image_size_range");
>    $self->register_eval_rule ("image_named");
>@@ -100,10 +19,13 @@
>    $self->register_eval_rule ("image_to_text_ratio");
>  
>    return $self;
>-@@ -244,6 +285,34 @@
>- 
>- # -----------------------------------------
>+@@ -272,6 +277,33 @@
>  
>+   # dbg("imageinfo: pc_$type: $min, ".($max ? $max:'').", $type, ".$pms->{'imageinfo'}->{"pc_$type"});
>+   return result_check($min, $max, $pms->{'imageinfo'}->{"pc_$type"});
>++}
>++
>++# -----------------------------------------
> +sub image_name_regex {
> +  my ($self,$pms,$body,$re) = @_;
> +  return unless (defined $re);
>@@ -128,20 +50,7 @@
> +  }
> +  return 0;
> +
>-+}
>-+
>-+# -----------------------------------------
>-+
>- sub image_count {
>-   my ($self,$pms,$body,$type,$min,$max) = @_;
>-   
>-@@ -323,7 +392,8 @@
>-     $self->_get_images($pms);
>    }
>  
>--  return unless (exists $pms->{'imageinfo'}->{"dems_$type"});
>-+  my $name = 'dems_'.$type;
>-+  return unless (exists $pms->{'imageinfo'}->{$name});
>+ # -----------------------------------------
>  
>-   foreach my $dem ( keys %{$pms->{'imageinfo'}->{"dems_$type"}}) {
>-     my ($h,$w) = split(/x/,$dem);
>diff -bBru /var/tmp/p5-Mail-SpamAssassin/files/patch-dnsbug-multiple ./files/patch-dnsbug-multiple
>--- /var/tmp/p5-Mail-SpamAssassin/files/patch-dnsbug-multiple	Fri Aug 10 13:47:50 2007
>+++ ./files/patch-dnsbug-multiple	Fri Aug 10 13:31:38 2007
>@@ -0,0 +1,1170 @@
>+--- Mail/SpamAssassin/AsyncLoop.pm	Mon Jul 23 16:46:40 2007
>++++ lib/Mail/SpamAssassin/AsyncLoop.pm	Fri Aug 10 16:10:56 2007
>+@@ -43,4 +43,10 @@
>+ our @ISA = qw();
>+ 
>++# Load Time::HiRes if it's available
>++BEGIN {
>++  eval { require Time::HiRes };
>++  Time::HiRes->import( qw(time) ) unless $@;
>++}
>++
>+ #############################################################################
>+ 
>+@@ -52,9 +58,10 @@
>+   my $self = {
>+     main                => $main,
>+-    last_count          => 0,
>+-    times_count_was_same => 0,
>+     queries_started     => 0,
>+     queries_completed   => 0,
>+-    pending_lookups     => { }
>++    total_queries_started   => 0,
>++    total_queries_completed => 0,
>++    pending_lookups     => { },
>++    timing_by_query     => { },
>+   };
>+ 
>+@@ -117,11 +124,25 @@
>+   my ($self, $ent) = @_;
>+ 
>+-  die "oops, no id"  unless $ent->{id};
>+-  die "oops, no key" unless $ent->{key};
>+-  die "oops, no type" unless $ent->{type};
>++  die "oops, no id"   unless $ent->{id}   ne '';
>++  die "oops, no key"  unless $ent->{key}  ne '';
>++  die "oops, no type" unless $ent->{type} ne '';
>++
>++  my $now = time;
>++  my $key = $ent->{key};
>++  my $id  = $ent->{id};
>++  $ent->{start_time} = $now  if !defined $ent->{start_time};
>++  $ent->{timeout} =
>++    $self->{main}->{conf}->{rbl_timeout}  if !defined $ent->{timeout};
>++  $ent->{display_id} =  # identifies entry in debug logging and similar
>++    join(", ", grep { defined }
>++               map { ref $ent->{$_} ? @{$ent->{$_}} : $ent->{$_} }
>++               qw(sets rules rulename type key) ),
>+ 
>+   $self->{queries_started}++;
>+-  $self->{pending_lookups}->{$ent->{key}} = $ent;
>+-  $self->{last_start_lookup_time} = time;
>++  $self->{total_queries_started}++;
>++  $self->{pending_lookups}->{$key} = $ent;
>++
>++  dbg("async: starting: %s (timeout %.1f s)",
>++      $ent->{display_id}, $ent->{timeout});
>+   $ent;
>+ }
>+@@ -165,4 +186,20 @@
>+ # ---------------------------------------------------------------------------
>+ 
>++=item $async->log_lookups_timing()
>++
>++Log sorted timing for all completed lookups.
>++
>++=cut
>++
>++sub log_lookups_timing {
>++  my ($self) = @_;
>++  my $timings = $self->{timing_by_query};
>++  for my $key (sort { $timings->{$a} <=> $timings->{$b} } keys %$timings) {
>++    dbg("async: timing: %.3f %s", $timings->{$key}, $key);
>++  }
>++}
>++
>++# ---------------------------------------------------------------------------
>++
>+ =item $alldone = $async->complete_lookups()
>+ 
>+@@ -177,13 +214,12 @@
>+ 
>+ sub complete_lookups {
>+-  my ($self, $timeout) = @_;
>+-  my %typecount = ();
>+-  my $stillwaiting = 0;
>++  my ($self, $timeout, $allow_aborting_of_expired) = @_;
>++  my $alldone = 0;
>++  my $anydone = 0;
>++  my $waiting_time = 0;
>++  my $allexpired = 1;
>++  my %typecount;
>+ 
>+   my $pending = $self->{pending_lookups};
>+-  if (scalar keys %{$pending} <= 0) {
>+-    return 1;           # nothing left to do
>+-  }
>+-
>+   $self->{queries_started} = 0;
>+   $self->{queries_completed} = 0;
>+@@ -193,11 +229,17 @@
>+   # thrown die()s before (bug 3794).
>+   eval {
>++    my $now = time;
>+ 
>+-    my $nfound = $self->{main}->{resolver}->poll_responses($timeout);
>+-    $nfound ||= 'no';
>+-    dbg ("async: select found $nfound socks ready");
>++    if (%$pending) {  # anything to do?
>++      # dbg("async: before select, timeout=%.1f", $timeout)  if $timeout > 0;
>++      $self->{last_poll_responses_time} = $now;
>++      my $nfound;
>++      ($nfound, $waiting_time) =
>++        $self->{main}->{resolver}->poll_responses($timeout);
>++      dbg("async: select found %s responses ready", !$nfound ? 'no' : $nfound);
>++    }
>+ 
>+-    foreach my $key (keys %{$pending}) {
>+-      my $ent = $pending->{$key};
>++    while (my($key,$ent) = each %$pending) {
>++      my $id = $ent->{id};
>+ 
>+       # call a "poll_callback" sub, if one exists
>+@@ -205,62 +247,66 @@
>+         $ent->{poll_callback}->($ent);
>+       }
>++      if (exists $self->{finished}->{$id}) {
>++        $anydone = 1;
>++        $ent->{finish_time} = $now  if !defined $ent->{finish_time};
>++        $ent->{response_packet} = delete $self->{finished}->{$id};
>+ 
>+-      my $type = $ent->{type};
>+-      if (!exists ($self->{finished}->{$ent->{id}})) {
>+-        $typecount{$type}++;
>+-        next;
>+-      }
>++        dbg("async: query completed in %.3f s: %s",
>++            $ent->{finish_time} - $ent->{start_time}, $ent->{display_id});
>+ 
>+-      $ent->{response_packet} = delete $self->{finished}->{$ent->{id}};
>+-      if (defined $ent->{completed_callback}) {
>+-        $ent->{completed_callback}->($ent);
>++        if (defined $ent->{completed_callback}) {
>++          $ent->{completed_callback}->($ent);
>++        }
>++        $self->{queries_completed}++;
>++        $self->{total_queries_completed}++;
>++        $self->{timing_by_query}->{". $key"} +=
>++          $ent->{finish_time} - $ent->{start_time};
>++        delete $pending->{$key};
>+       }
>+-
>+-      $self->{queries_completed}++;
>+-      delete $self->{pending_lookups}->{$key};
>+     }
>+ 
>+-    dbg("async: queries completed: ".$self->{queries_completed}.
>+-                  " started: ".$self->{queries_started});
>+-
>+-    if (1) {
>+-      dbg("async: queries active: ".
>+-          join (' ', map { "$_=$typecount{$_}" } sort keys %typecount)." at ".
>+-          localtime(time));
>++    if (%$pending) {  # still any requests outstanding? are they expired?
>++      my $timeout_shrink_factor =
>++        !$allow_aborting_of_expired || !$self->{total_queries_started} ? 1.0
>++          :  1 - 0.7 * ( ($self->{total_queries_completed} /
>++                          $self->{total_queries_started}) ** 2 );
>++      dbg("async: timeout shrink factor: %.2f",
>++          $timeout_shrink_factor)  if $timeout_shrink_factor != 1;
>++
>++      while (my($key,$ent) = each %$pending) {
>++        $typecount{$ent->{type}}++;
>++        my $dt = $ent->{timeout} * $timeout_shrink_factor;
>++        $dt = 1.0  if $dt < 1.0;  # don't shrink allowed time below 1 second
>++        $allexpired = 0  if $now <= $ent->{start_time} + $dt;
>++      }
>++      dbg("async: queries completed: %d, started: %d",
>++          $self->{queries_completed}, $self->{queries_started});
>+     }
>+ 
>+     # ensure we don't get stuck if a request gets lost in the ether.
>+-    if (!$stillwaiting) {
>+-      my $numkeys = scalar keys %{$self->{pending_lookups}};
>+-      if ($numkeys == 0) {
>+-        $stillwaiting = 0;
>+-
>+-      } else {
>+-        $stillwaiting = 1;
>+-
>+-        # avoid looping forever if we haven't got all results.
>+-        if ($self->{last_count} == $numkeys) {
>+-          $self->{times_count_was_same}++;
>+-          if ($self->{times_count_was_same} > 20)
>+-          {
>+-            dbg("async: escaping: must have lost requests");
>+-            $self->abort_remaining_lookups();
>+-            $stillwaiting = 0;
>+-          }
>+-        } else {
>+-          $self->{last_count} = $numkeys;
>+-          $self->{times_count_was_same} = 0;
>+-        }
>+-      }
>++    if (! %$pending) {
>++      $alldone = 1;
>++    }
>++    elsif ($allexpired && $allow_aborting_of_expired) {
>++      # avoid looping forever if we haven't got all results.
>++      dbg("async: escaping: lost or timed out requests or responses");
>++      $self->abort_remaining_lookups();
>++      $alldone = 1;
>+     }
>++    else {
>++      dbg("async: queries active: %s%s at %s",
>++          join (' ', map { "$_=$typecount{$_}" } sort keys %typecount),
>++          $allexpired ? ', all expired' : '', scalar(localtime(time)));
>++      $alldone = 0;
>++    }
>++    1;
>+ 
>++  } or do {
>++    my $eval_stat = $@ ne '' ? $@ : "errno=$!";  chomp $eval_stat;
>++    dbg("async: caught complete_lookups death, aborting: %s", $eval_stat);
>++    $alldone = 1;      # abort remaining
>+   };
>+ 
>+-  if ($@) {
>+-    dbg("async: caught complete_lookups death, aborting: $@");
>+-    $stillwaiting = 0;      # abort remaining
>+-  }
>+-
>+-  return (!$stillwaiting);
>++  return wantarray ? ($alldone,$anydone,$waiting_time) : $alldone;
>+ }
>+ 
>+@@ -277,16 +323,20 @@
>+ 
>+   my $pending = $self->{pending_lookups};
>+-  my $foundone = 0;
>+-  foreach my $key (keys %{$pending})
>+-  {
>+-    if (!$foundone) {
>+-      dbg("async: aborting remaining lookups");
>+-      $foundone = 1;
>+-    }
>+-
>++  my $foundcnt = 0;
>++  my $now = time;
>++  while (my($key,$ent) = each %$pending) {
>++    dbg("async: aborting after %.3f s, %s: %s",
>++        $now - $ent->{start_time},
>++        defined $ent->{timeout} && $now > $ent->{start_time} + $ent->{timeout}
>++          ? 'past original deadline' : 'shrunk deadline',
>++        $ent->{display_id} );
>++    $foundcnt++;
>++    $self->{timing_by_query}->{"X $key"} = $now - $ent->{start_time};
>+     delete $pending->{$key};
>+   }
>+-  delete $self->{last_start_lookup_time};
>++  dbg("async: aborted %d remaining lookups", $foundcnt)  if $foundcnt > 0;
>++  delete $self->{last_poll_responses_time};
>+   $self->{main}->{resolver}->bgabort();
>++  1;
>+ }
>+ 
>+@@ -308,9 +358,15 @@
>+ 
>+ sub set_response_packet {
>+-  my ($self, $id, $pkt) = @_;
>++  my ($self, $id, $pkt, $key, $timestamp) = @_;
>+   $self->{finished}->{$id} = $pkt;
>++  $timestamp = time  if !defined $timestamp;
>++  my $ent = $self->{pending_lookups}->{$key};
>++  $id eq $ent->{id}
>++    or die "set_response_packet: PANIC - mismatched id $id, $ent->{id}";
>++  $ent->{finish_time} = $timestamp;
>++  1;
>+ }
>+ 
>+-=item $async->report_id_complete($id)
>++=item $async->report_id_complete($id,$key)
>+ 
>+ Register that a query has completed, and is no longer "pending". C<$id> is the
>+@@ -323,24 +379,29 @@
>+ 
>+ sub report_id_complete {
>+-  my ($self, $id) = @_;
>++  my ($self, $id, $key, $timestamp) = @_;
>+   $self->{finished}->{$id} = undef;
>++  $timestamp = time  if !defined $timestamp;
>++  my $ent = $self->{pending_lookups}->{$key};
>++  $id eq $ent->{id}
>++    or die "report_id_complete: PANIC - mismatched id $id, $ent->{id}";
>++  $ent->{finish_time} = $timestamp;
>++  1;
>+ }
>+ 
>+ # ---------------------------------------------------------------------------
>+ 
>+-=item $time = $async->get_last_start_lookup_time()
>++=item $time = $async->last_poll_responses_time()
>+ 
>+-Get the time of the last call to C<start_lookup()>.  If C<start_lookup()> was
>+-never called or C<abort_remaining_lookups()> has been called
>+-C<get_last_start_lookup_time()> will return undef.
>++Get the time of the last call to C<poll_responses()> (which is called
>++from C<complete_lookups()).  If C<poll_responses()> was never called or
>++C<abort_remaining_lookups()> has been called C<last_poll_responses_time()>
>++will return undef.
>+ 
>+ =cut
>+ 
>+-sub get_last_start_lookup_time {
>++sub last_poll_responses_time {
>+   my ($self) = @_;
>+-  return $self->{last_start_lookup_time};
>++  return $self->{last_poll_responses_time};
>+ }  
>+-
>+-# ---------------------------------------------------------------------------
>+ 
>+ 1;
>+--- Mail/SpamAssassin/Dns.pm	Mon Jul 23 16:46:40 2007
>++++ lib/Mail/SpamAssassin/Dns.pm	Fri Aug 10 01:53:40 2007
>+@@ -104,8 +104,9 @@
>+   # only make a specific query once
>+   if (!$existing) {
>+-    dbg("dns: launching DNS $type query for $host in background");
>++    dbg("dns: launching DNS %s query for %s in background", $type,$host);
>+ 
>+     my $ent = {
>+       key => $key,
>++      timeout => $self->{conf}->{rbl_timeout},
>+       type => "DNSBL-".$type,
>+       sets => [ ],  # filled in below
>+@@ -115,8 +116,7 @@
>+ 
>+     my $id = $self->{resolver}->bgsend($host, $type, undef, sub {
>+-        my $pkt = shift;
>+-        my $id = shift;
>++        my ($pkt, $id, $timestamp) = @_;
>+         $self->process_dnsbl_result($ent, $pkt);
>+-        $self->{async}->report_id_complete($id);
>++        $self->{async}->report_id_complete($id,$key,$timestamp);
>+       });
>+ 
>+@@ -153,8 +153,9 @@
>+   return if $self->{async}->get_lookup($key);
>+ 
>+-  dbg("dns: launching DNS $type query for $host in background");
>++  dbg("dns: launching DNS %s query for %s in background", $type,$host);
>+ 
>+   my $ent = {
>+     key => $key,
>++    timeout => $self->{conf}->{rbl_timeout},
>+     type => "DNSBL-".$type,
>+     rules => [ $rule ],
>+@@ -163,8 +164,7 @@
>+ 
>+   my $id = $self->{resolver}->bgsend($host, $type, undef, sub {
>+-      my $pkt = shift;
>+-      my $id = shift;
>++      my ($pkt, $id, $timestamp) = @_;
>+       $self->process_dnsbl_result($ent, $pkt);
>+-      $self->{async}->report_id_complete($id);
>++      $self->{async}->report_id_complete($id,$key,$timestamp);
>+     });
>+ 
>+@@ -223,8 +223,9 @@
>+     push @{ $self->{dnsuri}->{$uri} }, $rdatastr;
>+ 
>+-    dbg ("dns: hit <$uri> $rdatastr");
>++    dbg("dns: hit <%s> %s", $uri,$rdatastr);
>+   }
>+ }
>+ 
>++# called as a completion routine to bgsend by DnsResolver::poll_responses;
>+ # returns 1 on successful packet processing
>+ sub process_dnsbl_result {
>+@@ -285,5 +286,5 @@
>+       # SB rules are not available to users
>+       if ($self->{conf}->{user_defined_rules}->{$rule}) {
>+-        dbg("dns: skipping rule '$rule': not supported when user-defined");
>++        dbg("dns: skipping rule '%s': not supported when user-defined", $rule);
>+         next;
>+       }
>+@@ -329,41 +330,25 @@
>+   my ($self, $rule) = @_;
>+ 
>+-  return if !defined $self->{async}->get_last_start_lookup_time();
>++  dbg("dns: harvest_until_rule_completes");
>++  my $result = 0;
>++  my $total_waiting_time = 0;
>++
>++  for (my $first=1;  ; $first=0) {
>++    # complete_lookups() may call completed_callback(), which may
>++    # call start_lookup() again (like in Plugin::URIDNSBL)
>++    my ($alldone,$anydone,$waiting_time) =
>++      $self->{async}->complete_lookups($first ? 0 : 1.0,  1);
>++    $total_waiting_time += $waiting_time;
>+ 
>+-  my $deadline = $self->{conf}->{rbl_timeout} + $self->{async}->get_last_start_lookup_time();
>+-  my $now = time;
>+-
>+-  # should not give up before at least attempting to collect some responses
>+-  # even if previous checks already exceeded rbl_timeout
>+-  my $notbefore = $now + 1.2;  # at least 1 second from now (time is integer)
>+-
>+-  my @left = $self->{async}->get_pending_lookups();
>+-  my $total = scalar @left;
>+-
>+-  while ( (($now < $deadline) || ($now < $notbefore)) &&
>+-          !$self->{async}->complete_lookups(1))
>+-  {
>+-    dbg(sprintf("dns: harvest_until_rule_completes: on extended time, ".
>+-                "overdue by %.3f s, still %.3f s",
>+-        $now-$deadline, $notbefore-$now))  if $now >= $deadline;
>+-
>+-    if ($self->is_rule_complete($rule)) {
>+-      return 1;
>+-    }
>++    $result = 1  if $self->is_rule_complete($rule);
>++    last  if $result || $alldone;
>+ 
>++    dbg("dns: harvest_until_rule_completes - check_tick");
>+     $self->{main}->call_plugins ("check_tick", { permsgstatus => $self });
>+-    @left = $self->{async}->get_pending_lookups();
>+-
>+-    # complete_lookups could cause a change in get_last_start_lookup_time
>+-    $deadline = $self->{conf}->{rbl_timeout} +
>+-                $self->{async}->get_last_start_lookup_time();
>+-
>+-    # dynamic timeout
>+-    my $dynamic = (int($self->{conf}->{rbl_timeout}
>+-                      * (1 - 0.7*(($total - @left) / $total) ** 2) + 1)
>+-                  + $self->{async}->get_last_start_lookup_time());
>+-    $deadline = $dynamic if ($dynamic < $deadline);
>+-    $now = time;
>+   }
>++  dbg("dns: timing: %.3f s sleeping in harvest_until_rule_completes",
>++      $total_waiting_time)  if $total_waiting_time > 0;
>++
>++  return $result;
>+ }
>+ 
>+@@ -371,57 +356,50 @@
>+   my ($self) = @_;
>+ 
>+-  return if !defined $self->{async}->get_last_start_lookup_time();
>++  dbg("dns: harvest_dnsbl_queries");
>++  my $total_waiting_time = 0;
>+ 
>+-  my $deadline = $self->{conf}->{rbl_timeout} + $self->{async}->get_last_start_lookup_time();
>+-  my $now = time;
>++  for (my $first=1;  ; $first=0) {
>+ 
>+-  # should not give up before at least attempting to collect some responses
>+-  # (which may have arrived by now), even if previous checks (like Razor,
>+-  # dcc, Botnet, rules) already exceeded rbl_timeout
>+-  my $notbefore = $now + 1.2;  # at least 1 second from now (time is integer)
>++    # complete_lookups() may call completed_callback(), which may
>++    # call start_lookup() again (like in Plugin::URIDNSBL)
>+ 
>+-  my @left = $self->{async}->get_pending_lookups();
>+-  my $total = scalar @left;
>++    # the first time around we specify a 0 timeout, which gives
>++    # complete_lookups a chance to ripe any available results and
>++    # abort overdue requests, without needlessly waiting for more
>+ 
>+-  while ( (($now < $deadline) || ($now < $notbefore)) &&
>+-          !$self->{async}->complete_lookups(1))
>+-  {
>+-    dbg(sprintf("dns: harvest_dnsbl_queries: on extended time, ".
>+-                "overdue by %.3f s, still %.3f s",
>+-        $now-$deadline, $notbefore-$now))  if $now >= $deadline;
>++    my ($alldone,$anydone,$waiting_time) =
>++      $self->{async}->complete_lookups($first ? 0 : 1.0,  1);
>++    $total_waiting_time += $waiting_time;
>+ 
>+-    $self->{main}->call_plugins ("check_tick", { permsgstatus => $self });
>+-    @left = $self->{async}->get_pending_lookups();
>++    last  if $alldone;
>+ 
>+-    # complete_lookups() may have called completed_callback, which may call
>+-    # start_lookup() again (like in URIDNSBL), so get_last_start_lookup_time
>+-    # may have changed and deadline needs to be recomputed
>+-    $deadline = $self->{conf}->{rbl_timeout} +
>+-                $self->{async}->get_last_start_lookup_time();
>+-
>+-    # dynamic timeout
>+-    my $dynamic = (int($self->{conf}->{rbl_timeout}
>+-                      * (1 - 0.7*(($total - @left) / $total) ** 2) + 1)
>+-                  + $self->{async}->get_last_start_lookup_time());
>+-    $deadline = $dynamic if ($dynamic < $deadline);
>+-    $now = time;    # and loop again
>+-  }
>+-
>+-  dbg("dns: success for " . ($total - @left) . " of $total queries");
>+-
>+-  # timeouts
>+-  @left = $self->{async}->get_pending_lookups();
>+-  $now = time;
>+-  for my $query (@left) {
>+-    my $string = join(", ", grep { defined }
>+-                      map { ref $query->{$_} ? @{$query->{$_}} : $query->{$_} }
>+-                      qw(sets rules rulename type key) );
>+-    my $delay = $now - $self->{async}->get_last_start_lookup_time();
>+-    dbg("dns: timeout for $string after $delay seconds");
>++    dbg("dns: harvest_dnsbl_queries - check_tick");
>++    $self->{main}->call_plugins ("check_tick", { permsgstatus => $self });
>+   }
>+ 
>+-  # and explicitly abort anything left
>++  # explicitly abort anything left
>+   $self->{async}->abort_remaining_lookups();
>++  $self->{async}->log_lookups_timing();
>+   $self->mark_all_async_rules_complete();
>++  dbg("dns: timing: %.3f s sleeping in harvest_dnsbl_queries",
>++      $total_waiting_time)  if $total_waiting_time > 0;
>++  1;
>++}
>++
>++# collect and process whatever DNS responses have already arrived,
>++# don't waste time waiting for more, don't poll too often.
>++# don't abort any queries even if overdue, 
>++sub harvest_completed_queries {
>++  my ($self) = @_;
>++
>++  # don't bother collecting responses too often
>++  my $last_poll_time = $self->{async}->last_poll_responses_time();
>++  return if defined $last_poll_time && time - $last_poll_time < 0.1;
>++
>++  my ($alldone,$anydone) = $self->{async}->complete_lookups(0, 0);
>++  if ($anydone) {
>++    dbg("dns: harvested completed queries");
>++#   $self->{main}->call_plugins ("check_tick", { permsgstatus => $self });
>++  }
>+ }
>+ 
>+@@ -466,5 +444,5 @@
>+ 
>+   my $nsrecords;
>+-  dbg("dns: looking up NS for '$dom'");
>++  dbg("dns: looking up NS for '%s'", $dom);
>+ 
>+   if (exists $self->{dnscache}->{NS}->{$dom}) {
>+@@ -474,5 +452,5 @@
>+     eval {
>+       my $query = $self->{resolver}->send($dom, 'NS');
>+-      my @nses = ();
>++      my @nses;
>+       if ($query) {
>+ 	foreach my $rr ($query->answer) {
>+@@ -481,9 +459,10 @@
>+       }
>+       $nsrecords = $self->{dnscache}->{NS}->{$dom} = [ @nses ];
>+-    };
>+-    if ($@) {
>+-      dbg("dns: NS lookup failed horribly, perhaps bad resolv.conf setting? ($@)");
>++      1;
>++    } or do {
>++      my $eval_stat = $@ ne '' ? $@ : "errno=$!";  chomp $eval_stat;
>++      dbg("dns: NS lookup failed horribly, perhaps bad resolv.conf setting? (%s)", $eval_stat);
>+       return undef;
>+-    }
>++    };
>+   }
>+ 
>+@@ -498,5 +477,5 @@
>+ 
>+   my $mxrecords;
>+-  dbg("dns: looking up MX for '$dom'");
>++  dbg("dns: looking up MX for '%s'", $dom);
>+ 
>+   if (exists $self->{dnscache}->{MX}->{$dom}) {
>+@@ -506,5 +485,5 @@
>+     eval {
>+       my $query = $self->{resolver}->send($dom, 'MX');
>+-      my @ips = ();
>++      my @ips;
>+       if ($query) {
>+ 	foreach my $rr ($query->answer) {
>+@@ -513,11 +492,11 @@
>+ 	}
>+       }
>+-
>+       $mxrecords = $self->{dnscache}->{MX}->{$dom} = [ @ips ];
>+-    };
>+-    if ($@) {
>+-      dbg("dns: MX lookup failed horribly, perhaps bad resolv.conf setting? ($@)");
>++      1;
>++    } or do {
>++      my $eval_stat = $@ ne '' ? $@ : "errno=$!";  chomp $eval_stat;
>++      dbg("dns: MX lookup failed horribly, perhaps bad resolv.conf setting? (%s)", $eval_stat);
>+       return undef;
>+-    }
>++    };
>+   }
>+ 
>+@@ -533,5 +512,5 @@
>+   if (scalar @{$recs}) { $ret = 1; }
>+ 
>+-  dbg("dns: MX for '$dom' exists? $ret");
>++  dbg("dns: MX for '%s' exists? %s", $dom,$ret);
>+   return $ret;
>+ }
>+@@ -549,5 +528,5 @@
>+ 
>+   if ($dom =~ /${IP_PRIVATE}/) {
>+-    dbg("dns: IP is private, not looking up PTR: $dom");
>++    dbg("dns: IP is private, not looking up PTR: %s", $dom);
>+     return undef;
>+   }
>+@@ -555,5 +534,5 @@
>+   return if ($self->server_failed_to_respond_for_domain ($dom));
>+ 
>+-  dbg("dns: looking up PTR record for '$dom'");
>++  dbg("dns: looking up PTR record for '%s'", $dom);
>+   my $name = '';
>+ 
>+@@ -571,14 +550,13 @@
>+ 	}
>+       }
>+-
>+       $name = $self->{dnscache}->{PTR}->{$dom} = $name;
>+-    };
>+-
>+-    if ($@) {
>+-      dbg("dns: PTR lookup failed horribly, perhaps bad resolv.conf setting? ($@)");
>++      1;
>++    } or do {
>++      my $eval_stat = $@ ne '' ? $@ : "errno=$!";  chomp $eval_stat;
>++      dbg("dns: PTR lookup failed horribly, perhaps bad resolv.conf setting? (%s)", $eval_stat);
>+       return undef;
>+-    }
>++    };
>+   }
>+-  dbg("dns: PTR for '$dom': '$name'");
>++  dbg("dns: PTR for '%s': '%s'", $dom,$name);
>+ 
>+   # note: undef is never returned, unless DNS is unavailable.
>+@@ -597,6 +575,6 @@
>+   return if ($self->server_failed_to_respond_for_domain ($name));
>+ 
>+-  dbg("dns: looking up A records for '$name'");
>+-  my @addrs = ();
>++  dbg("dns: looking up A records for '%s'", $name);
>++  my @addrs;
>+ 
>+   if (exists $self->{dnscache}->{A}->{$name}) {
>+@@ -615,13 +593,13 @@
>+       }
>+       $self->{dnscache}->{A}->{$name} = [ @addrs ];
>+-    };
>+-
>+-    if ($@) {
>+-      dbg("dns: A lookup failed horribly, perhaps bad resolv.conf setting? ($@)");
>++      1;
>++    } or do {
>++      my $eval_stat = $@ ne '' ? $@ : "errno=$!";  chomp $eval_stat;
>++      dbg("dns: A lookup failed horribly, perhaps bad resolv.conf setting? (%s)", $eval_stat);
>+       return undef;
>+-    }
>++    };
>+   }
>+ 
>+-  dbg("dns: A records for '$name': ".join (' ', @addrs));
>++  dbg("dns: A records for '%s': %s", $name, join(' ',@addrs));
>+   return @addrs;
>+ }
>+@@ -640,5 +618,6 @@
>+   if ($dnsopt eq "test" && $diff > $dnsint) {
>+     $IS_DNS_AVAILABLE = undef;
>+-    dbg("dns: is_dns_available() last checked $diff seconds ago; re-checking");
>++    dbg("dns: is_dns_available() last checked %.1f seconds ago; re-checking",
>++        $diff);
>+   }
>+ 
>+@@ -682,7 +661,8 @@
>+   if ($dnsopt =~ /test:\s+(.+)$/) {
>+     my $servers=$1;
>+-    dbg("dns: servers: $servers");
>++    dbg("dns: servers: %s", $servers);
>+     @domains = split (/\s+/, $servers);
>+-    dbg("dns: looking up NS records for user specified servers: ".join(", ", @domains));
>++    dbg("dns: looking up NS records for user specified servers: %s",
>++        join(", ", @domains));
>+   } else {
>+     @domains = @EXISTING_DOMAINS;
>+@@ -698,24 +678,27 @@
>+   
>+   my @nameservers = $self->{resolver}->nameservers();
>+-  dbg("dns: testing resolver nameservers: ".join(", ", @nameservers));
>++  dbg("dns: testing resolver nameservers: %s", join(", ", @nameservers));
>+   my $ns;
>+   while( $ns  = shift(@nameservers)) {
>+     for(my $retry = 3; $retry > 0 and $#domains>-1; $retry--) {
>+       my $domain = splice(@domains, rand(@domains), 1);
>+-      dbg("dns: trying ($retry) $domain...");
>++      dbg("dns: trying (%d) %s...", $retry,$domain);
>+       my $result = $self->lookup_ns($domain);
>+       if(defined $result) {
>+         if (scalar @$result > 0) {
>+-          dbg("dns: NS lookup of $domain using $ns succeeded => DNS available (set dns_available to override)");
>++          dbg("dns: NS lookup of %s using %s succeeded => DNS available ".
>++              "(set dns_available to override)", $domain,$ns);
>+           $IS_DNS_AVAILABLE = 1;
>+           last;
>+         }
>+         else {
>+-          dbg("dns: NS lookup of $domain using $ns failed, no results found");
>++          dbg("dns: NS lookup of %s using %s failed, no results found",
>++              $domain,$ns);
>+           next;
>+         }
>+       }
>+       else {
>+-        dbg("dns: NS lookup of $domain using $ns failed horribly, may not be a valid nameserver");
>++        dbg("dns: NS lookup of %s using %s failed horribly, ".
>++            "may not be a valid nameserver", $domain,$ns);
>+         $IS_DNS_AVAILABLE = 0; # should already be 0, but let's be sure.
>+         last; 
>+@@ -723,5 +706,5 @@
>+     }
>+     last if $IS_DNS_AVAILABLE;
>+-    dbg("dns: NS lookups failed, removing nameserver $ns from list");
>++    dbg("dns: NS lookups failed, removing nameserver %s from list", $ns);
>+     $self->{resolver}->nameservers(@nameservers);
>+     $self->{resolver}->connect_sock(); # reconnect socket to new nameserver
>+@@ -732,5 +715,5 @@
>+ done:
>+   # jm: leaving this in!
>+-  dbg("dns: is DNS available? $IS_DNS_AVAILABLE");
>++  dbg("dns: is DNS available? %s", $IS_DNS_AVAILABLE);
>+   return $IS_DNS_AVAILABLE;
>+ }
>+@@ -741,5 +724,6 @@
>+   my ($self, $dom) = @_;
>+   if ($self->{dns_server_too_slow}->{$dom}) {
>+-    dbg("dns: server for '$dom' failed to reply previously, not asking again");
>++    dbg("dns: server for '%s' failed to reply previously, not asking again",
>++        $dom);
>+     return 1;
>+   }
>+@@ -749,5 +733,5 @@
>+ sub set_server_failed_to_respond_for_domain {
>+   my ($self, $dom) = @_;
>+-  dbg("dns: server for '$dom' failed to reply, marking as bad");
>++  dbg("dns: server for '%s' failed to reply, marking as bad", $dom);
>+   $self->{dns_server_too_slow}->{$dom} = 1;
>+ }
>+@@ -823,5 +807,5 @@
>+ sub register_async_rule_start {
>+   my ($self, $rule) = @_;
>+-  dbg ("dns: $rule lookup start");
>++  dbg("dns: %s lookup start", $rule);
>+   $self->{rule_to_rblkey}->{$rule} = '*ASYNC_START';
>+ }
>+@@ -829,5 +813,5 @@
>+ sub register_async_rule_finish {
>+   my ($self, $rule) = @_;
>+-  dbg ("dns: $rule lookup finished");
>++  dbg("dns: %s lookup finished", $rule);
>+   delete $self->{rule_to_rblkey}->{$rule};
>+ }
>+@@ -843,10 +827,10 @@
>+   my $key = $self->{rule_to_rblkey}->{$rule};
>+   if (!defined $key) {
>+-    # dbg("dns: $rule lookup complete, not in list");
>++    # dbg("dns: %s lookup complete, not in list", $rule);
>+     return 1;
>+   }
>+ 
>+   if ($key eq '*ASYNC_START') {
>+-    dbg("dns: $rule lookup not yet complete");
>++    dbg("dns: %s lookup not yet complete", $rule);
>+     return 0;       # not yet complete
>+   }
>+@@ -854,9 +838,9 @@
>+   my $obj = $self->{async}->get_lookup($key);
>+   if (!defined $obj) {
>+-    dbg("dns: $rule lookup complete, $key no longer pending");
>++    dbg("dns: %s lookup complete, $key no longer pending", $rule);
>+     return 1;
>+   }
>+ 
>+-  dbg("dns: $rule lookup not yet complete");
>++  dbg("dns: %s lookup not yet complete", $rule);
>+   return 0;         # not yet complete
>+ }
>+--- Mail/SpamAssassin/DnsResolver.pm	Mon Jul 23 16:46:40 2007
>++++ lib/Mail/SpamAssassin/DnsResolver.pm	Fri Aug 10 11:48:34 2007
>+@@ -50,4 +50,10 @@
>+ our @ISA = qw();
>+ 
>++# Load Time::HiRes if it's available
>++BEGIN {
>++  eval { require Time::HiRes };
>++  Time::HiRes->import( qw(time) ) unless $@;
>++}
>++
>+ ###########################################################################
>+ 
>+@@ -131,8 +137,8 @@
>+ 
>+   dbg("dns: no ipv6") if $force_ipv4;
>+-  dbg("dns: is Net::DNS::Resolver available? " .
>+-       ($self->{no_resolver} ? "no" : "yes"));
>++  dbg("dns: is Net::DNS::Resolver available? %s",
>++      $self->{no_resolver} ? "no" : "yes" );
>+   if (!$self->{no_resolver} && defined $Net::DNS::VERSION) {
>+-    dbg("dns: Net::DNS version: ".$Net::DNS::VERSION);
>++    dbg("dns: Net::DNS version: %s", $Net::DNS::VERSION);
>+   }
>+ 
>+@@ -197,5 +203,5 @@
>+   }
>+ 
>+-  dbg("dns: name server: $ns, LocalAddr: $srcaddr");
>++  dbg("dns: name server: %s, LocalAddr: %s", $ns,$srcaddr);
>+ 
>+   # find next available unprivileged port (1024 - 65535)
>+@@ -223,5 +229,5 @@
>+       last;
>+     } elsif ($! == EADDRINUSE || $! == EACCES) {  # in use, let's try another source port
>+-      dbg("dns: UDP port $lport already in use, trying another port");
>++      dbg("dns: UDP port %s already in use, trying another port", $lport);
>+     } else {
>+       warn "Error creating a DNS resolver socket: $errno";
>+@@ -293,12 +299,14 @@
>+ 
>+     # a bit noisy, so commented by default...
>+-    #dbg("dns: new DNS packet time=".time()." host=$host type=$type id=".$packet->id);
>+-  };
>+-
>+-  if ($@) {
>++    #dbg("dns: new DNS packet time=%s host=%s type=%s id=%s",
>++    #    time, $host, $type, $packet->id);
>++    1;
>++  } or do {
>++    my $eval_stat = $@ ne '' ? $@ : "errno=$!";  chomp $eval_stat;
>+     # this can happen if Net::DNS isn't available -- but in this
>+     # case this function should never be called!
>+-    warn "dns: cannot create Net::DNS::Packet, but new_dns_packet() was called: $@ $!";
>+-  }
>++    warn "dns: cannot create Net::DNS::Packet, but new_dns_packet() was called: $eval_stat";
>++  };
>++
>+   return $packet;
>+ }
>+@@ -339,16 +347,17 @@
>+ will default to C<A> and C<IN>, respectively.
>+ 
>+-The callback sub will be called with two arguments -- the packet that was
>+-delivered and an id string that fingerprints the query packet and the expected reply.
>+-It is expected that a closure callback be used, like so:
>++The callback sub will be called with three arguments -- the packet that was
>++delivered, and an id string that fingerprints the query packet and the expected
>++reply. The third argument is a timestamp (Unix time, floating point), captured
>++at the time the packet was collected. It is expected that a closure callback
>++be used, like so:
>+ 
>+   my $id = $self->{resolver}->bgsend($host, $type, undef, sub {
>+-        my $reply = shift;
>+-        my $reply_id = shift;
>++        my ($reply, $reply_id, $timestamp) = @_;
>+         $self->got_a_reply ($reply, $reply_id);
>+       });
>+ 
>+-The callback can ignore the reply as an invalid packet sent to the listening port
>+-if the reply id does not match the return value from bgsend.
>++The callback can ignore the reply as an invalid packet sent to the listening
>++port if the reply id does not match the return value from bgsend.
>+ 
>+ =cut
>+@@ -385,44 +394,51 @@
>+   return if $self->{no_resolver};
>+   return if !$self->{sock};
>++  my $cnt = 0;
>++  my $waiting_time = 0;
>+ 
>+   my $rin = $self->{sock_as_vec};
>+   my $rout;
>+-  my ($nfound, $timeleft) = select($rout=$rin, undef, undef, $timeout);
>+ 
>+-  if (!defined $nfound || $nfound < 0) {
>+-    warn "dns: select failed: $!";
>+-    return;
>+-  }
>++  for (;;) {
>++    my $now_before = time;
>++    my ($nfound, $timeleft) = select($rout=$rin, undef, undef, $timeout);
>++    if (!defined $nfound || $nfound < 0) {
>++      warn "dns: select failed: $!";
>++      return;
>++    }
>+ 
>+-  if ($nfound == 0) {
>+-    return 0;           # nothing's ready yet
>+-  }
>++    my $now = time;
>++    if ($now > $now_before && (!defined($timeout) || $timeout > 0)) {
>++      $waiting_time += $now - $now_before;
>++    }
>++    $timeout = 0;  # next time around collect whatever is available, then exit
>++    last  if $nfound == 0;
>+ 
>+-  my $packet = $self->{res}->bgread($self->{sock});
>+-  my $err = $self->{res}->errorstring;
>++    my $packet = $self->{res}->bgread($self->{sock});
>++    my $err = $self->{res}->errorstring;
>+ 
>+-  if (defined $packet &&
>+-      defined $packet->header &&
>+-      defined $packet->question &&
>+-      defined $packet->answer)
>+-  {
>+-    my $id = $self->_packet_id($packet);
>+-
>+-    my $cb = delete $self->{id_to_callback}->{$id};
>+-    if (!$cb) {
>+-      dbg("dns: no callback for id: $id, ignored; packet: ".
>+-                    ($packet ? $packet->string : "undef"));
>+-      return 0;
>++    if (defined $packet &&
>++        defined $packet->header &&
>++        defined $packet->question &&
>++        defined $packet->answer)
>++    {
>++      my $id = $self->_packet_id($packet);
>++
>++      my $cb = delete $self->{id_to_callback}->{$id};
>++      if (!$cb) {
>++        dbg("dns: no callback for id: %s, ignored; packet: %s",
>++            $id,  $packet ? $packet->string : "undef" );
>++      } else {
>++        $cb->($packet, $id, $now);
>++        $cnt++;
>++      }
>++    }
>++    else {
>++      dbg("dns: no packet! err=%s packet=%s",
>++          $err,  $packet ? $packet->string : "undef" );
>+     }
>+-
>+-    $cb->($packet, $id);
>+-    return 1;
>+-  }
>+-  else {
>+-    dbg("dns: no packet! err=$err packet=".
>+-                    ($packet ? $packet->string : "undef"));
>+   }
>+ 
>+-  return 0;
>++  return wantarray ? ($cnt, $waiting_time) : $cnt;
>+ }
>+ 
>+@@ -458,4 +474,5 @@
>+   my $timeout = $retrans;
>+   my $answerpkt;
>++  my $answerpkt_avail = 0;
>+   for (my $i = 0;
>+        (($i < $retries) && !defined($answerpkt));
>+@@ -465,5 +482,6 @@
>+     # note nifty use of a closure here.  I love closures ;)
>+     $self->bgsend($name, $type, $class, sub {
>+-      $answerpkt = shift;
>++      my ($reply, $reply_id, $timestamp) = @_;
>++      $answerpkt = $reply; $answerpkt_avail = 1;
>+     });
>+ 
>+@@ -471,10 +489,9 @@
>+     my $deadline = $now + $timeout;
>+ 
>+-    while (($now < $deadline) && (!defined($answerpkt))) {
>++    while (!$answerpkt_avail) {
>++      if ($now >= $deadline) { $self->{send_timed_out} = 1; last }
>+       $self->poll_responses(1);
>+-      last if defined $answerpkt;
>+       $now = time;
>+     }
>+-    $self->{send_timed_out} = 1 unless ($now < $deadline);
>+   }
>+   return $answerpkt;
>+@@ -540,6 +557,9 @@
>+   foreach my $sock (@fhlist) {
>+     my $fno = fileno($sock);
>+-    warn "dns: oops! fileno now undef for $sock" unless defined($fno);
>+-    vec ($rin, $fno, 1) = 1;
>++    if (!defined $fno) {
>++      warn "dns: oops! fileno now undef for $sock";
>++    } else {
>++      vec ($rin, $fno, 1) = 1;
>++    }
>+   }
>+   return $rin;
>+--- Mail/SpamAssassin/Logger.pm	Mon Jul 23 16:46:40 2007
>++++ lib/Mail/SpamAssassin/Logger.pm	Tue Aug  7 16:34:30 2007
>+@@ -195,7 +195,7 @@
>+ # remember to avoid deep recursion, my friend
>+ sub _log {
>+-  my ($level, $message) = @_;
>+-
>++  my ($level, $message, @args) = @_;
>+   my $facility = "generic";
>++  local ($1,$2);
>+   if ($message =~ /^(\S+?): (.*)/s) {
>+     $facility = $1;
>+@@ -210,4 +210,5 @@
>+   }
>+ 
>++  if (@args && index($message,'%') >= 0) { $message = sprintf($message,@args) }
>+   $message =~ s/\n+$//s;
>+   $message =~ s/^/${facility}: /mg;
>+--- Mail/SpamAssassin/Plugin/ASN.pm	Mon Jul 23 16:46:39 2007
>++++ lib/Mail/SpamAssassin/Plugin/ASN.pm	Fri Aug 10 12:30:40 2007
>+@@ -191,5 +191,5 @@
>+     if (defined $relay->{ip} && $relay->{ip} =~ /^(\d+)\.(\d+)\.(\d+)\.(\d+)$/) {
>+       $reversed_ip_quad = "$4.$3.$2.$1";
>+-      dbg("asn: using first external relay IP for lookups: $relay->{ip}");
>++      dbg("asn: using first external relay IP for lookups: %s", $relay->{ip});
>+     } else {
>+       dbg("asn: could not parse IP from first external relay, skipping ASN check");
>+@@ -213,11 +213,17 @@
>+     # do the DNS query, have the callback process the result rather than poll for them later
>+     my $zone_index = $index;
>++    my $key = "asnlookup-${zone_index}-$entry->{zone}";
>+     my $id = $scanner->{main}->{resolver}->bgsend("${reversed_ip_quad}.$entry->{zone}", 'TXT', undef, sub {
>+-      my $pkt = shift;
>++      my ($pkt, $id, $timestamp) = @_;
>++      $scanner->{async}->set_response_packet($id, $pkt, $key, $timestamp);
>+       $self->process_dns_result($scanner, $pkt, $zone_index);
>+     });
>+-
>+-    $scanner->{async}->start_lookup({ key=>"asnlookup-${zone_index}-$entry->{zone}", id=>$id, type=>'TXT' });
>+-    dbg("asn: launched DNS TXT query for ${reversed_ip_quad}.$entry->{zone} in background");
>++    my $ent = {
>++      key=>$key, id=>$id, type=>'TXT',
>++    # timeout => ...   # defaults to $scanner->{conf}->{rbl_timeout}
>++    };
>++    $scanner->{async}->start_lookup($ent);
>++    dbg("asn: launched DNS TXT query for %s.%s in background",
>++        $reversed_ip_quad, $entry->{zone});
>+ 
>+     $index++;
>+@@ -237,9 +243,10 @@
>+ 
>+   foreach my $rr (@answer) {
>+-    dbg("asn: $zone: lookup result packet: '".$rr->string."'");
>++    dbg("asn: %s: lookup result packet: '%s'", $zone, $rr->string);
>+     if ($rr->type eq 'TXT') {
>+       my @items = split(/ /, $rr->txtdata);
>+       unless ($#items == 2) {
>+-        dbg("asn: TXT query response format unknown, ignoring zone: $zone response: '".$rr->txtdata."'");
>++        dbg("asn: TXT query response format unknown, ignoring zone: %s, ".
>++            "response: '%s'", $zone, $rr->txtdata);
>+         next;
>+       }
>+--- Mail/SpamAssassin/Plugin/Check.pm	Mon Jul 23 16:46:39 2007
>++++ lib/Mail/SpamAssassin/Plugin/Check.pm	Wed Aug  8 16:50:40 2007
>+@@ -92,4 +92,5 @@
>+     }
>+ 
>++    $pms->harvest_completed_queries();
>+     # allow other, plugin-defined rule types to be called here
>+     $self->{main}->call_plugins ("check_rules_at_priority",
>+@@ -98,21 +99,32 @@
>+     # do head tests
>+     $self->do_head_tests($pms, $priority);
>++    $pms->harvest_completed_queries();
>+     $self->do_head_eval_tests($pms, $priority);
>++    $pms->harvest_completed_queries();
>+ 
>+     $self->do_body_tests($pms, $priority, $decoded);
>++    $pms->harvest_completed_queries();
>+     $self->do_uri_tests($pms, $priority, @uris);
>++    $pms->harvest_completed_queries();
>+     $self->do_body_eval_tests($pms, $priority, $decoded);
>++    $pms->harvest_completed_queries();
>+   
>+     $self->do_rawbody_tests($pms, $priority, $bodytext);
>++    $pms->harvest_completed_queries();
>+     $self->do_rawbody_eval_tests($pms, $priority, $bodytext);
>++    $pms->harvest_completed_queries();
>+   
>+     $self->do_full_tests($pms, $priority, \$fulltext);
>++    $pms->harvest_completed_queries();
>+     $self->do_full_eval_tests($pms, $priority, \$fulltext);
>++    $pms->harvest_completed_queries();
>+ 
>+     $self->do_meta_tests($pms, $priority);
>++    $pms->harvest_completed_queries();
>+ 
>+     # we may need to call this more often than once through the loop, but
>+     # it needs to be done at least once, either at the beginning or the end.
>+     $self->{main}->call_plugins ("check_tick", { permsgstatus => $pms });
>++    $pms->harvest_completed_queries();
>+   }
>+ 
>+--- Mail/SpamAssassin/Plugin/URIDNSBL.pm	Mon Jul 23 16:46:39 2007
>++++ lib/Mail/SpamAssassin/Plugin/URIDNSBL.pm	Thu Aug  9 17:34:51 2007
>+@@ -474,5 +474,7 @@
>+ 
>+   # dig $dom ns
>+-  my $ent = $self->start_lookup ($scanner, 'NS', $self->res_bgsend($scanner, $dom, 'NS'), $key);
>++  my $ent = $self->start_lookup($scanner, 'NS',
>++                                $self->res_bgsend($scanner, $dom, 'NS', $key),
>++                                $key);
>+   $ent->{obj} = $obj;
>+ }
>+@@ -518,5 +520,7 @@
>+ 
>+   # dig $hname a
>+-  my $ent = $self->start_lookup ($scanner, 'A', $self->res_bgsend($scanner, $hname, 'A'), $key);
>++  my $ent = $self->start_lookup($scanner, 'A',
>++                                $self->res_bgsend($scanner, $hname, 'A', $key),
>++                                $key);
>+   $ent->{obj} = $obj;
>+ }
>+@@ -559,6 +563,7 @@
>+ 
>+   # dig $ip txt
>+-  my $ent = $self->start_lookup ($scanner, 'DNSBL',
>+-        $self->res_bgsend($scanner, $item, $qtype), $key);
>++  my $ent = $self->start_lookup($scanner, 'DNSBL',
>++                              $self->res_bgsend($scanner, $item, $qtype, $key),
>++                              $key);
>+   $ent->{obj} = $obj;
>+   $ent->{rulename} = $rulename;
>+@@ -650,4 +655,5 @@
>+   my $ent = {
>+     key => $key,
>++    timeout => $scanner->{conf}->{rbl_timeout},
>+     type => "URI-".$type,
>+     id => $id,
>+@@ -675,7 +681,4 @@
>+   elsif ($type eq 'URI-DNSBL') {
>+     $self->complete_dnsbl_lookup ($scanner, $ent, $val);
>+-    my $totalsecs = (time - $ent->{obj}->{querystart});
>+-    dbg("uridnsbl: query for ".$ent->{obj}->{dom}." took ".
>+-              $totalsecs." seconds to look up ($val)");
>+   }
>+ }
>+@@ -684,10 +687,9 @@
>+ 
>+ sub res_bgsend {
>+-  my ($self, $scanner, $host, $type) = @_;
>++  my ($self, $scanner, $host, $type, $key) = @_;
>+ 
>+   return $self->{main}->{resolver}->bgsend($host, $type, undef, sub {
>+-        my $pkt = shift;
>+-        my $id = shift;
>+-        $scanner->{async}->set_response_packet($id, $pkt);
>++        my ($pkt, $id, $timestamp) = @_;
>++        $scanner->{async}->set_response_packet($id, $pkt, $key, $timestamp);
>+       });
>+ }
>+--- Mail/SpamAssassin/Util/DependencyInfo.pm	Mon Jul 23 16:46:37 2007
>++++ lib/Mail/SpamAssassin/Util/DependencyInfo.pm	Fri Aug 10 11:44:15 2007
>+@@ -140,6 +140,7 @@
>+   module => 'Time::HiRes',
>+   version => '0.00',
>+-  desc => 'If this module is installed, the processing times are logged/reported
>+-  more precisely in spamd.',
>++  desc => 'If this module is installed, asynchronous DNS lookup timeouts operate
>++  with subsecond precision and the processing times are logged/reported
>++  more accurately. Other modules and plugins may benefit too.',
>+ },
>+ {
>+
>diff -bBru /var/tmp/p5-Mail-SpamAssassin/files/patch-sa-compile.raw ./files/patch-sa-compile.raw
>--- /var/tmp/p5-Mail-SpamAssassin/files/patch-sa-compile.raw	Sat Jun 16 18:17:03 2007
>+++ ./files/patch-sa-compile.raw	Wed Jul 25 20:23:48 2007
>@@ -1,6 +1,6 @@
>---- sa-compile.raw.orig	Tue May  1 09:54:33 2007
>-+++ sa-compile.raw	Thu May  3 13:35:23 2007
>-@@ -643,7 +643,7 @@
>+--- sa-compile.raw.orig	Mon Jul 23 10:47:06 2007
>++++ sa-compile.raw	Wed Jul 25 20:23:14 2007
>+@@ -659,9 +659,9 @@
>    -p prefs, --prefspath=file, --prefs-file=file
>                                  Set user preferences file
>    --siteconfigpath=path         Path for site configs
>@@ -10,7 +10,9 @@
> -                     (default: /var/lib/spamassassin/compiled/<version>)
> +                     (default: @@LOCAL_STATE_DIR@@/compiled/<version>)
>    --cf='config line'            Additional line of configuration
>-@@ -692,12 +692,12 @@
>+   -D, --debug [area=n,...]	Print debugging messages
>+   -V, --version			Print version
>+@@ -708,12 +708,12 @@
>  =item B<-C> I<path>, B<--configpath>=I<path>, B<--config-file>=I<path>
>  
>  Use the specified path for locating the distributed configuration files.
>diff -bBru /var/tmp/p5-Mail-SpamAssassin/pkg-install ./pkg-install
>--- /var/tmp/p5-Mail-SpamAssassin/pkg-install	Sun Jul 22 18:40:58 2007
>+++ ./pkg-install	Mon Jul 23 08:11:12 2007
>@@ -1,5 +1,5 @@
> #!/bin/sh
>-PKG_PREFIX=${PKG_PREFIX:=/usr/local}
>+PKG_PREFIX=${PKG_PREFIX:-/usr/local}
> 
> ask() {
>         local question default answer

Actions: View

Attachments on bug 115369: 80432 | 80433