Date: Fri, 10 Aug 2007 18:00:11 GMT From: "Michael Scheidell" <scheidell@secnap.net> To: freebsd-ports-bugs@FreeBSD.org Subject: Re: ports/115369: [MAINTAINER UPDATE] mail/p5-Mail-SpamAssassin from 3.2.1 to 3.2.3 Message-ID: <200708101800.l7AI0Br7026717@freefall.freebsd.org>
next in thread | raw e-mail | index | archive | help
The following reply was made to PR ports/115369; it has been noted by GNATS. From: "Michael Scheidell" <scheidell@secnap.net> To: <bug-followup@FreeBSD.org>, "Michael Scheidell" <scheidell@secnap.net> Cc: Subject: Re: ports/115369: [MAINTAINER UPDATE] mail/p5-Mail-SpamAssassin from 3.2.1 to 3.2.3 Date: Fri, 10 Aug 2007 13:52:19 -0400 This is a multi-part message in MIME format. ------=_NextPart_000_0002_01C7DB55.AB82D610 Content-Type: text/plain; format=flowed; charset="iso-8859-1"; reply-type=original Content-Transfer-Encoding: 7bit Last minuite bug found, bug in 3.2.2 and 3.2.3. attached patch replaces previous patch. added Time::HiRes as dependency mentioned in SA bug 5589. added this file: files/patch-dnsbug-multiple removed this file: Only in /var/tmp/p5-Mail-SpamAssassin/files: patch-spamc-Makefile.in (already fixed in 3.2.2) If you have applied 115369, please add PORTREVISION= 1 to Makefile, if not, no need. bug described here, and slows down ASN plugin by 3 seconds each email. http://issues.apache.org/SpamAssassin/show_bug.cgi?id=5589 ------=_NextPart_000_0002_01C7DB55.AB82D610 Content-Type: text/plain; format=flowed; name="sa323_1.txt"; reply-type=original Content-Transfer-Encoding: quoted-printable Content-Disposition: attachment; filename="sa323_1.txt" 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 @@ # =20 PORTNAME=3D Mail-SpamAssassin -PORTVERSION=3D 3.2.1 -PORTREVISION=3D 1 +PORTVERSION=3D 3.2.3 CATEGORIES=3D mail perl5 MASTER_SITES=3D ${MASTER_SITE_APACHE:S/$/:apache/} = ${MASTER_SITE_PERL_CPAN:S/$/:cpan/} MASTER_SITE_SUBDIR=3D spamassassin/source/:apache Mail/:cpan @@ -27,7 +26,8 @@ RUN_DEPENDS=3D ${BUILD_DEPENDS} \ ${SITE_PERL}/Bundle/LWP.pm:${PORTSDIR}/www/p5-libwww \ p5-Archive-Tar>=3D1.23:${PORTSDIR}/archivers/p5-Archive-Tar \ - = ${SITE_PERL}/mach/Encode/Detect.pm:${PORTSDIR}/converters/p5-Encode-Detec= t + = ${SITE_PERL}/mach/Encode/Detect.pm:${PORTSDIR}/converters/p5-Encode-Detec= t \ + p5-Time-HiRes>=3D0:${PORTSDIR}/devel/p5-Time-HiRes =20 PERL_CONFIGURE=3D yes USE_LDCONFIG=3D yes @@ -97,7 +97,7 @@ .if defined(WITH_DKIM) RUN_DEPENDS+=3D p5-Mail-DKIM>=3D.20:${PORTSDIR}/mail/p5-Mail-DKIM RUN_DEPENDS+=3D = ${SITE_PERL}/IO/Socket/SSL.pm:${PORTSDIR}/security/p5-IO-Socket-SSL -RUN_DEPENDS+=3D = p5-Mail-DomainKeys>=3D0.80:${PORTSDIR}/mail/p5-Mail-DomainKeys +RUN_DEPENDS+=3D = p5-Crypt-OpenSSL-RSA>=3D0.24:${PORTSDIR}/security/p5-Crypt-OpenSSL-RSA .endif =20 .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 @@ =20 .endif @${SED} -e 's#PREFIX#${PREFIX}#' ${PKGMESSAGE} - -.if ${PERL_LEVEL} < 500800 -BUILD_DEPENDS+=3D = ${SITE_PERL}/${PERL_ARCH}/MIME/Base64.pm:${PORTSDIR}/converters/p5-MIME-B= ase64 \ - ${SITE_PERL}/${PERL_ARCH}/Storable.pm:${PORTSDIR}/devel/p5-Storable -.endif =20 .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) =3D = a7d51294c565999da01f212e5ad2a031 -SHA256 (Mail-SpamAssassin-3.2.1.tar.gz) =3D = e0925d9c490bb8f1e56c3b850b50b12b124536dfe581b23d3c25715b1ce9ebf7 -SIZE (Mail-SpamAssassin-3.2.1.tar.gz) =3D 1193561 +MD5 (Mail-SpamAssassin-3.2.3.tar.gz) =3D = 2e356b70b9458b44a828c19f6e816521 +SHA256 (Mail-SpamAssassin-3.2.3.tar.gz) =3D = 2bf7635555dea4912512a32c7c567094ef264770b86029c49f653e97352efad8 +SIZE (Mail-SpamAssassin-3.2.3.tar.gz) =3D 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 -+#=20 -+# 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 - #=20 - # http://www.apache.org/licenses/LICENSE-2.0 - #=20 -@@ -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:=20 -+# 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 -+# =20 -+# Install: -+# 1) place ruleset in your local config dir -+# 2) place plugin in your plugins dir=20 -+# 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=20 - # 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 - #=20 - # body ONE_IMAGE eval:image_count('all',1,1)=20 - # 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() -+#=20 -+# body RULENAME eval:image_name_regex(<regex>)=20 -+# 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()=20 + # and pixel_coverage() together. =20 # --# 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()=20 --# and pixel_coverage() together. =20 -+# New functions added in v0.5+ need some documentation here. Or just = -+# see .cf for sample rules. - # - # ------------------------------------------------------- -=20 -@@ -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"); =20 return $self; -@@ -244,6 +285,34 @@ -=20 - # ----------------------------------------- +@@ -272,6 +277,33 @@ =20 + # 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) =3D @_; + return unless (defined $re); @@ -128,20 +50,7 @@ + } + return 0; + -+} -+ -+# ----------------------------------------- -+ - sub image_count { - my ($self,$pms,$body,$type,$min,$max) =3D @_; - =20 -@@ -323,7 +392,8 @@ - $self->_get_images($pms); } =20 -- return unless (exists $pms->{'imageinfo'}->{"dems_$type"}); -+ my $name =3D 'dems_'.$type; -+ return unless (exists $pms->{'imageinfo'}->{$name}); + # ----------------------------------------- =20 - foreach my $dem ( keys %{$pms->{'imageinfo'}->{"dems_$type"}}) { - my ($h,$w) =3D 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 =3D qw(); +=20 ++# Load Time::HiRes if it's available ++BEGIN { ++ eval { require Time::HiRes }; ++ Time::HiRes->import( qw(time) ) unless $@; ++} ++ + = #########################################################################= #### +=20 +@@ -52,9 +58,10 @@ + my $self =3D { + main =3D> $main, +- last_count =3D> 0, +- times_count_was_same =3D> 0, + queries_started =3D> 0, + queries_completed =3D> 0, +- pending_lookups =3D> { } ++ total_queries_started =3D> 0, ++ total_queries_completed =3D> 0, ++ pending_lookups =3D> { }, ++ timing_by_query =3D> { }, + }; +=20 +@@ -117,11 +124,25 @@ + my ($self, $ent) =3D @_; +=20 +- 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 =3D time; ++ my $key =3D $ent->{key}; ++ my $id =3D $ent->{id}; ++ $ent->{start_time} =3D $now if !defined $ent->{start_time}; ++ $ent->{timeout} =3D ++ $self->{main}->{conf}->{rbl_timeout} if !defined $ent->{timeout}; ++ $ent->{display_id} =3D # identifies entry in debug logging and = similar ++ join(", ", grep { defined } ++ map { ref $ent->{$_} ? @{$ent->{$_}} : $ent->{$_} } ++ qw(sets rules rulename type key) ), +=20 + $self->{queries_started}++; +- $self->{pending_lookups}->{$ent->{key}} =3D $ent; +- $self->{last_start_lookup_time} =3D time; ++ $self->{total_queries_started}++; ++ $self->{pending_lookups}->{$key} =3D $ent; ++ ++ dbg("async: starting: %s (timeout %.1f s)", ++ $ent->{display_id}, $ent->{timeout}); + $ent; + } +@@ -165,4 +186,20 @@ + # = -------------------------------------------------------------------------= -- +=20 ++=3Ditem $async->log_lookups_timing() ++ ++Log sorted timing for all completed lookups. ++ ++=3Dcut ++ ++sub log_lookups_timing { ++ my ($self) =3D @_; ++ my $timings =3D $self->{timing_by_query}; ++ for my $key (sort { $timings->{$a} <=3D> $timings->{$b} } keys = %$timings) { ++ dbg("async: timing: %.3f %s", $timings->{$key}, $key); ++ } ++} ++ ++# = -------------------------------------------------------------------------= -- ++ + =3Ditem $alldone =3D $async->complete_lookups() +=20 +@@ -177,13 +214,12 @@ +=20 + sub complete_lookups { +- my ($self, $timeout) =3D @_; +- my %typecount =3D (); +- my $stillwaiting =3D 0; ++ my ($self, $timeout, $allow_aborting_of_expired) =3D @_; ++ my $alldone =3D 0; ++ my $anydone =3D 0; ++ my $waiting_time =3D 0; ++ my $allexpired =3D 1; ++ my %typecount; +=20 + my $pending =3D $self->{pending_lookups}; +- if (scalar keys %{$pending} <=3D 0) { +- return 1; # nothing left to do +- } +- + $self->{queries_started} =3D 0; + $self->{queries_completed} =3D 0; +@@ -193,11 +229,17 @@ + # thrown die()s before (bug 3794). + eval { ++ my $now =3D time; +=20 +- my $nfound =3D = $self->{main}->{resolver}->poll_responses($timeout); +- $nfound ||=3D 'no'; +- dbg ("async: select found $nfound socks ready"); ++ if (%$pending) { # anything to do? ++ # dbg("async: before select, timeout=3D%.1f", $timeout) if = $timeout > 0; ++ $self->{last_poll_responses_time} =3D $now; ++ my $nfound; ++ ($nfound, $waiting_time) =3D ++ $self->{main}->{resolver}->poll_responses($timeout); ++ dbg("async: select found %s responses ready", !$nfound ? 'no' : = $nfound); ++ } +=20 +- foreach my $key (keys %{$pending}) { +- my $ent =3D $pending->{$key}; ++ while (my($key,$ent) =3D each %$pending) { ++ my $id =3D $ent->{id}; +=20 + # call a "poll_callback" sub, if one exists +@@ -205,62 +247,66 @@ + $ent->{poll_callback}->($ent); + } ++ if (exists $self->{finished}->{$id}) { ++ $anydone =3D 1; ++ $ent->{finish_time} =3D $now if !defined $ent->{finish_time}; ++ $ent->{response_packet} =3D delete $self->{finished}->{$id}; +=20 +- my $type =3D $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}); +=20 +- $ent->{response_packet} =3D 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"} +=3D ++ $ent->{finish_time} - $ent->{start_time}; ++ delete $pending->{$key}; + } +- +- $self->{queries_completed}++; +- delete $self->{pending_lookups}->{$key}; + } +=20 +- dbg("async: queries completed: ".$self->{queries_completed}. +- " started: ".$self->{queries_started}); +- +- if (1) { +- dbg("async: queries active: ". +- join (' ', map { "$_=3D$typecount{$_}" } sort keys = %typecount)." at ". +- localtime(time)); ++ if (%$pending) { # still any requests outstanding? are they = expired? ++ my $timeout_shrink_factor =3D ++ !$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 !=3D 1; ++ ++ while (my($key,$ent) =3D each %$pending) { ++ $typecount{$ent->{type}}++; ++ my $dt =3D $ent->{timeout} * $timeout_shrink_factor; ++ $dt =3D 1.0 if $dt < 1.0; # don't shrink allowed time below = 1 second ++ $allexpired =3D 0 if $now <=3D $ent->{start_time} + $dt; ++ } ++ dbg("async: queries completed: %d, started: %d", ++ $self->{queries_completed}, $self->{queries_started}); + } +=20 + # ensure we don't get stuck if a request gets lost in the ether. +- if (!$stillwaiting) { +- my $numkeys =3D scalar keys %{$self->{pending_lookups}}; +- if ($numkeys =3D=3D 0) { +- $stillwaiting =3D 0; +- +- } else { +- $stillwaiting =3D 1; +- +- # avoid looping forever if we haven't got all results. +- if ($self->{last_count} =3D=3D $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 =3D 0; +- } +- } else { +- $self->{last_count} =3D $numkeys; +- $self->{times_count_was_same} =3D 0; +- } +- } ++ if (! %$pending) { ++ $alldone =3D 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 =3D 1; + } ++ else { ++ dbg("async: queries active: %s%s at %s", ++ join (' ', map { "$_=3D$typecount{$_}" } sort keys = %typecount), ++ $allexpired ? ', all expired' : '', = scalar(localtime(time))); ++ $alldone =3D 0; ++ } ++ 1; +=20 ++ } or do { ++ my $eval_stat =3D $@ ne '' ? $@ : "errno=3D$!"; chomp $eval_stat; ++ dbg("async: caught complete_lookups death, aborting: %s", = $eval_stat); ++ $alldone =3D 1; # abort remaining + }; +=20 +- if ($@) { +- dbg("async: caught complete_lookups death, aborting: $@"); +- $stillwaiting =3D 0; # abort remaining +- } +- +- return (!$stillwaiting); ++ return wantarray ? ($alldone,$anydone,$waiting_time) : $alldone; + } +=20 +@@ -277,16 +323,20 @@ +=20 + my $pending =3D $self->{pending_lookups}; +- my $foundone =3D 0; +- foreach my $key (keys %{$pending}) +- { +- if (!$foundone) { +- dbg("async: aborting remaining lookups"); +- $foundone =3D 1; +- } +- ++ my $foundcnt =3D 0; ++ my $now =3D time; ++ while (my($key,$ent) =3D 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"} =3D $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; + } +=20 +@@ -308,9 +358,15 @@ +=20 + sub set_response_packet { +- my ($self, $id, $pkt) =3D @_; ++ my ($self, $id, $pkt, $key, $timestamp) =3D @_; + $self->{finished}->{$id} =3D $pkt; ++ $timestamp =3D time if !defined $timestamp; ++ my $ent =3D $self->{pending_lookups}->{$key}; ++ $id eq $ent->{id} ++ or die "set_response_packet: PANIC - mismatched id $id, = $ent->{id}"; ++ $ent->{finish_time} =3D $timestamp; ++ 1; + } +=20 +-=3Ditem $async->report_id_complete($id) ++=3Ditem $async->report_id_complete($id,$key) +=20 + Register that a query has completed, and is no longer "pending". = C<$id> is the +@@ -323,24 +379,29 @@ +=20 + sub report_id_complete { +- my ($self, $id) =3D @_; ++ my ($self, $id, $key, $timestamp) =3D @_; + $self->{finished}->{$id} =3D undef; ++ $timestamp =3D time if !defined $timestamp; ++ my $ent =3D $self->{pending_lookups}->{$key}; ++ $id eq $ent->{id} ++ or die "report_id_complete: PANIC - mismatched id $id, = $ent->{id}"; ++ $ent->{finish_time} =3D $timestamp; ++ 1; + } +=20 + # = -------------------------------------------------------------------------= -- +=20 +-=3Ditem $time =3D $async->get_last_start_lookup_time() ++=3Ditem $time =3D $async->last_poll_responses_time() +=20 +-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. +=20 + =3Dcut +=20 +-sub get_last_start_lookup_time { ++sub last_poll_responses_time { + my ($self) =3D @_; +- return $self->{last_start_lookup_time}; ++ return $self->{last_poll_responses_time}; + } =20 +- +-# = -------------------------------------------------------------------------= -- +=20 + 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); +=20 + my $ent =3D { + key =3D> $key, ++ timeout =3D> $self->{conf}->{rbl_timeout}, + type =3D> "DNSBL-".$type, + sets =3D> [ ], # filled in below +@@ -115,8 +116,7 @@ +=20 + my $id =3D $self->{resolver}->bgsend($host, $type, undef, sub { +- my $pkt =3D shift; +- my $id =3D shift; ++ my ($pkt, $id, $timestamp) =3D @_; + $self->process_dnsbl_result($ent, $pkt); +- $self->{async}->report_id_complete($id); ++ $self->{async}->report_id_complete($id,$key,$timestamp); + }); +=20 +@@ -153,8 +153,9 @@ + return if $self->{async}->get_lookup($key); +=20 +- dbg("dns: launching DNS $type query for $host in background"); ++ dbg("dns: launching DNS %s query for %s in background", = $type,$host); +=20 + my $ent =3D { + key =3D> $key, ++ timeout =3D> $self->{conf}->{rbl_timeout}, + type =3D> "DNSBL-".$type, + rules =3D> [ $rule ], +@@ -163,8 +164,7 @@ +=20 + my $id =3D $self->{resolver}->bgsend($host, $type, undef, sub { +- my $pkt =3D shift; +- my $id =3D shift; ++ my ($pkt, $id, $timestamp) =3D @_; + $self->process_dnsbl_result($ent, $pkt); +- $self->{async}->report_id_complete($id); ++ $self->{async}->report_id_complete($id,$key,$timestamp); + }); +=20 +@@ -223,8 +223,9 @@ + push @{ $self->{dnsuri}->{$uri} }, $rdatastr; +=20 +- dbg ("dns: hit <$uri> $rdatastr"); ++ dbg("dns: hit <%s> %s", $uri,$rdatastr); + } + } +=20 ++# 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) =3D @_; +=20 +- return if !defined $self->{async}->get_last_start_lookup_time(); ++ dbg("dns: harvest_until_rule_completes"); ++ my $result =3D 0; ++ my $total_waiting_time =3D 0; ++ ++ for (my $first=3D1; ; $first=3D0) { ++ # complete_lookups() may call completed_callback(), which may ++ # call start_lookup() again (like in Plugin::URIDNSBL) ++ my ($alldone,$anydone,$waiting_time) =3D ++ $self->{async}->complete_lookups($first ? 0 : 1.0, 1); ++ $total_waiting_time +=3D $waiting_time; +=20 +- my $deadline =3D $self->{conf}->{rbl_timeout} + = $self->{async}->get_last_start_lookup_time(); +- my $now =3D time; +- +- # should not give up before at least attempting to collect some = responses +- # even if previous checks already exceeded rbl_timeout +- my $notbefore =3D $now + 1.2; # at least 1 second from now (time is = integer) +- +- my @left =3D $self->{async}->get_pending_lookups(); +- my $total =3D 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 >=3D $deadline; +- +- if ($self->is_rule_complete($rule)) { +- return 1; +- } ++ $result =3D 1 if $self->is_rule_complete($rule); ++ last if $result || $alldone; +=20 ++ dbg("dns: harvest_until_rule_completes - check_tick"); + $self->{main}->call_plugins ("check_tick", { permsgstatus =3D> = $self }); +- @left =3D $self->{async}->get_pending_lookups(); +- +- # complete_lookups could cause a change in = get_last_start_lookup_time +- $deadline =3D $self->{conf}->{rbl_timeout} + +- $self->{async}->get_last_start_lookup_time(); +- +- # dynamic timeout +- my $dynamic =3D (int($self->{conf}->{rbl_timeout} +- * (1 - 0.7*(($total - @left) / $total) ** 2) + = 1) +- + $self->{async}->get_last_start_lookup_time()); +- $deadline =3D $dynamic if ($dynamic < $deadline); +- $now =3D time; + } ++ dbg("dns: timing: %.3f s sleeping in harvest_until_rule_completes", ++ $total_waiting_time) if $total_waiting_time > 0; ++ ++ return $result; + } +=20 +@@ -371,57 +356,50 @@ + my ($self) =3D @_; +=20 +- return if !defined $self->{async}->get_last_start_lookup_time(); ++ dbg("dns: harvest_dnsbl_queries"); ++ my $total_waiting_time =3D 0; +=20 +- my $deadline =3D $self->{conf}->{rbl_timeout} + = $self->{async}->get_last_start_lookup_time(); +- my $now =3D time; ++ for (my $first=3D1; ; $first=3D0) { +=20 +- # 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 =3D $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) +=20 +- my @left =3D $self->{async}->get_pending_lookups(); +- my $total =3D 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 +=20 +- 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 >=3D $deadline; ++ my ($alldone,$anydone,$waiting_time) =3D ++ $self->{async}->complete_lookups($first ? 0 : 1.0, 1); ++ $total_waiting_time +=3D $waiting_time; +=20 +- $self->{main}->call_plugins ("check_tick", { permsgstatus =3D> = $self }); +- @left =3D $self->{async}->get_pending_lookups(); ++ last if $alldone; +=20 +- # 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 =3D $self->{conf}->{rbl_timeout} + +- $self->{async}->get_last_start_lookup_time(); +- +- # dynamic timeout +- my $dynamic =3D (int($self->{conf}->{rbl_timeout} +- * (1 - 0.7*(($total - @left) / $total) ** 2) + = 1) +- + $self->{async}->get_last_start_lookup_time()); +- $deadline =3D $dynamic if ($dynamic < $deadline); +- $now =3D time; # and loop again +- } +- +- dbg("dns: success for " . ($total - @left) . " of $total queries"); +- +- # timeouts +- @left =3D $self->{async}->get_pending_lookups(); +- $now =3D time; +- for my $query (@left) { +- my $string =3D join(", ", grep { defined } +- map { ref $query->{$_} ? @{$query->{$_}} : = $query->{$_} } +- qw(sets rules rulename type key) ); +- my $delay =3D $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 =3D> = $self }); + } +=20 +- # 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,=20 ++sub harvest_completed_queries { ++ my ($self) =3D @_; ++ ++ # don't bother collecting responses too often ++ my $last_poll_time =3D $self->{async}->last_poll_responses_time(); ++ return if defined $last_poll_time && time - $last_poll_time < 0.1; ++ ++ my ($alldone,$anydone) =3D $self->{async}->complete_lookups(0, 0); ++ if ($anydone) { ++ dbg("dns: harvested completed queries"); ++# $self->{main}->call_plugins ("check_tick", { permsgstatus =3D> = $self }); ++ } + } +=20 +@@ -466,5 +444,5 @@ +=20 + my $nsrecords; +- dbg("dns: looking up NS for '$dom'"); ++ dbg("dns: looking up NS for '%s'", $dom); +=20 + if (exists $self->{dnscache}->{NS}->{$dom}) { +@@ -474,5 +452,5 @@ + eval { + my $query =3D $self->{resolver}->send($dom, 'NS'); +- my @nses =3D (); ++ my @nses; + if ($query) { + foreach my $rr ($query->answer) { +@@ -481,9 +459,10 @@ + } + $nsrecords =3D $self->{dnscache}->{NS}->{$dom} =3D [ @nses ]; +- }; +- if ($@) { +- dbg("dns: NS lookup failed horribly, perhaps bad resolv.conf = setting? ($@)"); ++ 1; ++ } or do { ++ my $eval_stat =3D $@ ne '' ? $@ : "errno=3D$!"; chomp = $eval_stat; ++ dbg("dns: NS lookup failed horribly, perhaps bad resolv.conf = setting? (%s)", $eval_stat); + return undef; +- } ++ }; + } +=20 +@@ -498,5 +477,5 @@ +=20 + my $mxrecords; +- dbg("dns: looking up MX for '$dom'"); ++ dbg("dns: looking up MX for '%s'", $dom); +=20 + if (exists $self->{dnscache}->{MX}->{$dom}) { +@@ -506,5 +485,5 @@ + eval { + my $query =3D $self->{resolver}->send($dom, 'MX'); +- my @ips =3D (); ++ my @ips; + if ($query) { + foreach my $rr ($query->answer) { +@@ -513,11 +492,11 @@ + } + } +- + $mxrecords =3D $self->{dnscache}->{MX}->{$dom} =3D [ @ips ]; +- }; +- if ($@) { +- dbg("dns: MX lookup failed horribly, perhaps bad resolv.conf = setting? ($@)"); ++ 1; ++ } or do { ++ my $eval_stat =3D $@ ne '' ? $@ : "errno=3D$!"; chomp = $eval_stat; ++ dbg("dns: MX lookup failed horribly, perhaps bad resolv.conf = setting? (%s)", $eval_stat); + return undef; +- } ++ }; + } +=20 +@@ -533,5 +512,5 @@ + if (scalar @{$recs}) { $ret =3D 1; } +=20 +- dbg("dns: MX for '$dom' exists? $ret"); ++ dbg("dns: MX for '%s' exists? %s", $dom,$ret); + return $ret; + } +@@ -549,5 +528,5 @@ +=20 + if ($dom =3D~ /${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)); +=20 +- dbg("dns: looking up PTR record for '$dom'"); ++ dbg("dns: looking up PTR record for '%s'", $dom); + my $name =3D ''; +=20 +@@ -571,14 +550,13 @@ + } + } +- + $name =3D $self->{dnscache}->{PTR}->{$dom} =3D $name; +- }; +- +- if ($@) { +- dbg("dns: PTR lookup failed horribly, perhaps bad resolv.conf = setting? ($@)"); ++ 1; ++ } or do { ++ my $eval_stat =3D $@ ne '' ? $@ : "errno=3D$!"; 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); +=20 + # note: undef is never returned, unless DNS is unavailable. +@@ -597,6 +575,6 @@ + return if ($self->server_failed_to_respond_for_domain ($name)); +=20 +- dbg("dns: looking up A records for '$name'"); +- my @addrs =3D (); ++ dbg("dns: looking up A records for '%s'", $name); ++ my @addrs; +=20 + if (exists $self->{dnscache}->{A}->{$name}) { +@@ -615,13 +593,13 @@ + } + $self->{dnscache}->{A}->{$name} =3D [ @addrs ]; +- }; +- +- if ($@) { +- dbg("dns: A lookup failed horribly, perhaps bad resolv.conf = setting? ($@)"); ++ 1; ++ } or do { ++ my $eval_stat =3D $@ ne '' ? $@ : "errno=3D$!"; chomp = $eval_stat; ++ dbg("dns: A lookup failed horribly, perhaps bad resolv.conf = setting? (%s)", $eval_stat); + return undef; +- } ++ }; + } +=20 +- 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 =3D 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); + } +=20 +@@ -682,7 +661,8 @@ + if ($dnsopt =3D~ /test:\s+(.+)$/) { + my $servers=3D$1; +- dbg("dns: servers: $servers"); ++ dbg("dns: servers: %s", $servers); + @domains =3D 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 =3D @EXISTING_DOMAINS; +@@ -698,24 +678,27 @@ + =20 + my @nameservers =3D $self->{resolver}->nameservers(); +- dbg("dns: testing resolver nameservers: ".join(", ", @nameservers)); ++ dbg("dns: testing resolver nameservers: %s", join(", ", = @nameservers)); + my $ns; + while( $ns =3D shift(@nameservers)) { + for(my $retry =3D 3; $retry > 0 and $#domains>-1; $retry--) { + my $domain =3D splice(@domains, rand(@domains), 1); +- dbg("dns: trying ($retry) $domain..."); ++ dbg("dns: trying (%d) %s...", $retry,$domain); + my $result =3D $self->lookup_ns($domain); + if(defined $result) { + if (scalar @$result > 0) { +- dbg("dns: NS lookup of $domain using $ns succeeded =3D> DNS = available (set dns_available to override)"); ++ dbg("dns: NS lookup of %s using %s succeeded =3D> DNS = available ". ++ "(set dns_available to override)", $domain,$ns); + $IS_DNS_AVAILABLE =3D 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 =3D 0; # should already be 0, but let's be = sure. + last;=20 +@@ -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) =3D @_; + 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) =3D @_; +- 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} =3D 1; + } +@@ -823,5 +807,5 @@ + sub register_async_rule_start { + my ($self, $rule) =3D @_; +- dbg ("dns: $rule lookup start"); ++ dbg("dns: %s lookup start", $rule); + $self->{rule_to_rblkey}->{$rule} =3D '*ASYNC_START'; + } +@@ -829,5 +813,5 @@ + sub register_async_rule_finish { + my ($self, $rule) =3D @_; +- dbg ("dns: $rule lookup finished"); ++ dbg("dns: %s lookup finished", $rule); + delete $self->{rule_to_rblkey}->{$rule}; + } +@@ -843,10 +827,10 @@ + my $key =3D $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; + } +=20 + 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 =3D $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; + } +=20 +- 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 =3D qw(); +=20 ++# Load Time::HiRes if it's available ++BEGIN { ++ eval { require Time::HiRes }; ++ Time::HiRes->import( qw(time) ) unless $@; ++} ++ + = #########################################################################= ## +=20 +@@ -131,8 +137,8 @@ +=20 + 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); + } +=20 +@@ -197,5 +203,5 @@ + } +=20 +- dbg("dns: name server: $ns, LocalAddr: $srcaddr"); ++ dbg("dns: name server: %s, LocalAddr: %s", $ns,$srcaddr); +=20 + # find next available unprivileged port (1024 - 65535) +@@ -223,5 +229,5 @@ + last; + } elsif ($! =3D=3D EADDRINUSE || $! =3D=3D 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 @@ +=20 + # a bit noisy, so commented by default... +- #dbg("dns: new DNS packet time=3D".time()." host=3D$host = type=3D$type id=3D".$packet->id); +- }; +- +- if ($@) { ++ #dbg("dns: new DNS packet time=3D%s host=3D%s type=3D%s id=3D%s", ++ # time, $host, $type, $packet->id); ++ 1; ++ } or do { ++ my $eval_stat =3D $@ ne '' ? $@ : "errno=3D$!"; 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. +=20 +-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: +=20 + my $id =3D $self->{resolver}->bgsend($host, $type, undef, sub { +- my $reply =3D shift; +- my $reply_id =3D shift; ++ my ($reply, $reply_id, $timestamp) =3D @_; + $self->got_a_reply ($reply, $reply_id); + }); +=20 +-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. +=20 + =3Dcut +@@ -385,44 +394,51 @@ + return if $self->{no_resolver}; + return if !$self->{sock}; ++ my $cnt =3D 0; ++ my $waiting_time =3D 0; +=20 + my $rin =3D $self->{sock_as_vec}; + my $rout; +- my ($nfound, $timeleft) =3D select($rout=3D$rin, undef, undef, = $timeout); +=20 +- if (!defined $nfound || $nfound < 0) { +- warn "dns: select failed: $!"; +- return; +- } ++ for (;;) { ++ my $now_before =3D time; ++ my ($nfound, $timeleft) =3D select($rout=3D$rin, undef, undef, = $timeout); ++ if (!defined $nfound || $nfound < 0) { ++ warn "dns: select failed: $!"; ++ return; ++ } +=20 +- if ($nfound =3D=3D 0) { +- return 0; # nothing's ready yet +- } ++ my $now =3D time; ++ if ($now > $now_before && (!defined($timeout) || $timeout > 0)) { ++ $waiting_time +=3D $now - $now_before; ++ } ++ $timeout =3D 0; # next time around collect whatever is available, = then exit ++ last if $nfound =3D=3D 0; +=20 +- my $packet =3D $self->{res}->bgread($self->{sock}); +- my $err =3D $self->{res}->errorstring; ++ my $packet =3D $self->{res}->bgread($self->{sock}); ++ my $err =3D $self->{res}->errorstring; +=20 +- if (defined $packet && +- defined $packet->header && +- defined $packet->question && +- defined $packet->answer) +- { +- my $id =3D $self->_packet_id($packet); +- +- my $cb =3D 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 =3D $self->_packet_id($packet); ++ ++ my $cb =3D 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=3D%s packet=3D%s", ++ $err, $packet ? $packet->string : "undef" ); + } +- +- $cb->($packet, $id); +- return 1; +- } +- else { +- dbg("dns: no packet! err=3D$err packet=3D". +- ($packet ? $packet->string : "undef")); + } +=20 +- return 0; ++ return wantarray ? ($cnt, $waiting_time) : $cnt; + } +=20 +@@ -458,4 +474,5 @@ + my $timeout =3D $retrans; + my $answerpkt; ++ my $answerpkt_avail =3D 0; + for (my $i =3D 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 =3D shift; ++ my ($reply, $reply_id, $timestamp) =3D @_; ++ $answerpkt =3D $reply; $answerpkt_avail =3D 1; + }); +=20 +@@ -471,10 +489,9 @@ + my $deadline =3D $now + $timeout; +=20 +- while (($now < $deadline) && (!defined($answerpkt))) { ++ while (!$answerpkt_avail) { ++ if ($now >=3D $deadline) { $self->{send_timed_out} =3D 1; last } + $self->poll_responses(1); +- last if defined $answerpkt; + $now =3D time; + } +- $self->{send_timed_out} =3D 1 unless ($now < $deadline); + } + return $answerpkt; +@@ -540,6 +557,9 @@ + foreach my $sock (@fhlist) { + my $fno =3D fileno($sock); +- warn "dns: oops! fileno now undef for $sock" unless defined($fno); +- vec ($rin, $fno, 1) =3D 1; ++ if (!defined $fno) { ++ warn "dns: oops! fileno now undef for $sock"; ++ } else { ++ vec ($rin, $fno, 1) =3D 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) =3D @_; +- ++ my ($level, $message, @args) =3D @_; + my $facility =3D "generic"; ++ local ($1,$2); + if ($message =3D~ /^(\S+?): (.*)/s) { + $facility =3D $1; +@@ -210,4 +210,5 @@ + } +=20 ++ if (@args && index($message,'%') >=3D 0) { $message =3D = sprintf($message,@args) } + $message =3D~ s/\n+$//s; + $message =3D~ 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} =3D~ = /^(\d+)\.(\d+)\.(\d+)\.(\d+)$/) { + $reversed_ip_quad =3D "$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 =3D $index; ++ my $key =3D "asnlookup-${zone_index}-$entry->{zone}"; + my $id =3D = $scanner->{main}->{resolver}->bgsend("${reversed_ip_quad}.$entry->{zone}"= , 'TXT', undef, sub { +- my $pkt =3D shift; ++ my ($pkt, $id, $timestamp) =3D @_; ++ $scanner->{async}->set_response_packet($id, $pkt, $key, = $timestamp); + $self->process_dns_result($scanner, $pkt, $zone_index); + }); +- +- $scanner->{async}->start_lookup({ = key=3D>"asnlookup-${zone_index}-$entry->{zone}", id=3D>$id, = type=3D>'TXT' }); +- dbg("asn: launched DNS TXT query for = ${reversed_ip_quad}.$entry->{zone} in background"); ++ my $ent =3D { ++ key=3D>$key, id=3D>$id, type=3D>'TXT', ++ # timeout =3D> ... # 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}); +=20 + $index++; +@@ -237,9 +243,10 @@ +=20 + 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 =3D split(/ /, $rr->txtdata); + unless ($#items =3D=3D 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 @@ + } +=20 ++ $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(); +=20 + $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(); + =20 + $self->do_rawbody_tests($pms, $priority, $bodytext); ++ $pms->harvest_completed_queries(); + $self->do_rawbody_eval_tests($pms, $priority, $bodytext); ++ $pms->harvest_completed_queries(); + =20 + $self->do_full_tests($pms, $priority, \$fulltext); ++ $pms->harvest_completed_queries(); + $self->do_full_eval_tests($pms, $priority, \$fulltext); ++ $pms->harvest_completed_queries(); +=20 + $self->do_meta_tests($pms, $priority); ++ $pms->harvest_completed_queries(); +=20 + # 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 =3D> = $pms }); ++ $pms->harvest_completed_queries(); + } +=20 +--- 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 @@ +=20 + # dig $dom ns +- my $ent =3D $self->start_lookup ($scanner, 'NS', = $self->res_bgsend($scanner, $dom, 'NS'), $key); ++ my $ent =3D $self->start_lookup($scanner, 'NS', ++ $self->res_bgsend($scanner, $dom, = 'NS', $key), ++ $key); + $ent->{obj} =3D $obj; + } +@@ -518,5 +520,7 @@ +=20 + # dig $hname a +- my $ent =3D $self->start_lookup ($scanner, 'A', = $self->res_bgsend($scanner, $hname, 'A'), $key); ++ my $ent =3D $self->start_lookup($scanner, 'A', ++ $self->res_bgsend($scanner, $hname, = 'A', $key), ++ $key); + $ent->{obj} =3D $obj; + } +@@ -559,6 +563,7 @@ +=20 + # dig $ip txt +- my $ent =3D $self->start_lookup ($scanner, 'DNSBL', +- $self->res_bgsend($scanner, $item, $qtype), $key); ++ my $ent =3D $self->start_lookup($scanner, 'DNSBL', ++ $self->res_bgsend($scanner, $item, = $qtype, $key), ++ $key); + $ent->{obj} =3D $obj; + $ent->{rulename} =3D $rulename; +@@ -650,4 +655,5 @@ + my $ent =3D { + key =3D> $key, ++ timeout =3D> $scanner->{conf}->{rbl_timeout}, + type =3D> "URI-".$type, + id =3D> $id, +@@ -675,7 +681,4 @@ + elsif ($type eq 'URI-DNSBL') { + $self->complete_dnsbl_lookup ($scanner, $ent, $val); +- my $totalsecs =3D (time - $ent->{obj}->{querystart}); +- dbg("uridnsbl: query for ".$ent->{obj}->{dom}." took ". +- $totalsecs." seconds to look up ($val)"); + } + } +@@ -684,10 +687,9 @@ +=20 + sub res_bgsend { +- my ($self, $scanner, $host, $type) =3D @_; ++ my ($self, $scanner, $host, $type, $key) =3D @_; +=20 + return $self->{main}->{resolver}->bgsend($host, $type, undef, sub { +- my $pkt =3D shift; +- my $id =3D shift; +- $scanner->{async}->set_response_packet($id, $pkt); ++ my ($pkt, $id, $timestamp) =3D @_; ++ $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 =3D> 'Time::HiRes', + version =3D> '0.00', +- desc =3D> 'If this module is installed, the processing times are = logged/reported +- more precisely in spamd.', ++ desc =3D> '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=3Dfile, --prefs-file=3Dfile Set user preferences file --siteconfigpath=3Dpath Path for site configs @@ -10,7 +10,9 @@ - (default: = /var/lib/spamassassin/compiled/<version>) + (default: @@LOCAL_STATE_DIR@@/compiled/<version>) --cf=3D'config line' Additional line of configuration -@@ -692,12 +692,12 @@ + -D, --debug [area=3Dn,...] Print debugging messages + -V, --version Print version +@@ -708,12 +708,12 @@ =3Ditem B<-C> I<path>, B<--configpath>=3DI<path>, = B<--config-file>=3DI<path> =20 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=3D${PKG_PREFIX:=3D/usr/local} +PKG_PREFIX=3D${PKG_PREFIX:-/usr/local} =20 ask() { local question default answer ------=_NextPart_000_0002_01C7DB55.AB82D610--
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?200708101800.l7AI0Br7026717>