I don't understand why the spool file is disappearing, but I have a workaround.
I modified the get_filename method as follows:
sub get_filename {
my $self = shift;
my $transaction = shift || $self->qp->transaction;
my $filename = $transaction->body_filename;
if ( ! $filename ) {
$self->log( LOGWARN, "Cannot process due to lack of filename" );
return;
}
if ( ! -f $filename ) {
$self->log( LOGERROR, "spool file missing! Attempting to respool" );
$transaction->body_spool;
$filename = $transaction->body_filename;
if ( ! -f $filename ) {
$self->log( LOGERROR, "skip: failed spool to $filename! Giving up"
);
return;
};
$self->log( LOGINFO, "Spooled successfully as $filename" );
}
return $filename;
};
Instead of failing to scan about 2/3 of the messages, they get respooled and
scanned as they should. But why is respooling necessary?
Matt
On May 29, 2012, at 10:03 PM, Matt Simerson wrote:
>
> For quite a long time (as long as I've used qpsmtpd), I've been getting chmod
> errors in my logs from the clamdscan plugin. The errors look like this:
>
> (data_post) virus::clamdscan: chmod:
> /usr/home/qpsmtpd/tmp/1338343891:23427:0: No such file or directory
>
> I've also received a few virus emails, that I expected clamav to have caught.
> I'm 99% certain the reason they snuck through is because under some
> circumstances, the clamdscan plugin isn't working. Today I did some research.
>
> To make it easier to test, I abstracted the portions of the clamdscan plugin
> code that extract the filename and test it. The subroutine looks like this:
>
> sub get_filename {
> my $self = shift;
>
> my $filename = $self->qp->transaction->body_filename;
>
> if ( ! $filename ) {
> $self->log( LOGWARN, "Cannot process due to lack of filename" );
> return;
> }
>
> if ( ! -f $filename ) {
> $self->log( LOGERROR, "skip, $filename not on disk?" );
> return;
> }
>
> $self->log( LOGINFO, "pass, found $filename on disk." );
> return $filename;
> };
>
> Then I waited for a ham to get delivered, and I posted the full logs here:
> http://www.tnpi.net/internet/mail/qpsmtpd.html
> The most relevant portions are:
> 92028 354 go ahead
> 92028 spooling message to disk
> 92028 (data_post) bogus_bounce: pass, not a bounce
> 92028 (data_post) basicheaders: pass
> 92028 (data_post) domainkeys: pass, good
> 92028 (data_post) spamassassin: pass, Ham, -0.2 < 100
> 92028 (data_post) dspam: pass, agree, Innocent, 0.99 c
> 92028 (data_post) virus::clamdscan: skip,
> /usr/home/qpsmtpd/tmp/1338351693:92028:0 not on disk?
> 92038 (queue) queue::qmail_2dqueue: (for 92028 ) Queuing qp 92038 to
> /var/qmail/bin/qmail-queue
>
> In tracking this down, I read through Transaction.pm, where I found this pod:
>
> =head2 body_filename ( )
>
> Returns the temporary filename used to store the message contents; useful for
> virus scanners so that an additional copy doesn't need to be made.
>
> Calling C<body_filename()> also forces spooling to disk. A message is not
> spooled to disk if it's size is smaller than
> I<$self-E<gt>config("size_threshold")>, default threshold is 0, the sample
> config file sets this to 10000.
>
> and this code:
>
> sub body_filename {
> my $self = shift;
> $self->body_spool() unless $self->{_filename};
> $self->{_body_file}->flush(); # so contents won't be cached
> return $self->{_filename};
> }
>
> And it sure looks like that code is working as advertised. But why is the
> file disappearing from the spool directory before the clamdscan plugin can
> get at it? Or is it ever written there at all? So I copied and pasted that
> same get_filename() into the dspam plugin, and added a call to it. Here's the
> results:
>
> 2768 354 go ahead
> 2768 spooling message to disk
> 2768 (data_post) bogus_bounce: pass, not a bounce
> 2768 (data_post) basicheaders: pass
> 2768 (data_post) domainkeys: skip: unsigned
> 2768 (data_post) spamassassin: pass, Ham, 1.0 < 100
> 2768 (data_post) dspam: pass, found /usr/home/qpsmtpd/tmp/1338352889:2768:0
> on disk.
> 2768 (data_post) dspam: pass, agree, Innocent, 0.99 c
> 2768 (data_post) virus::clamdscan: skip,
> /usr/home/qpsmtpd/tmp/1338352889:2768:0 not on disk?
> 2779 (queue) queue::qmail_2dqueue: (for 2768 ) Queuing qp 2779 to
> /var/qmail/bin/qmail-queue
> 2768 250 Queued! 1338352891 qp 2779
> <b77c472e-2cb4-4c9f-8096-81866b1b0...@cox.net>
> 2768 dispatching QUIT
> 2768 221 mail.theartfarm.com closing connection. Have a wonderful day.
> 2768 click, disconnecting
>
> Huh? The file is there when dspam runs but it's gone when the clamdscan
> plugin runs.
>
> Ideas?
>
> Matt
>
> PS: I am not running async. Yet.
>
> `````````````````````````````````````````````````````````````````````````
> Matt Simerson http://matt.simerson.net/
> Systems Engineer http://www.tnpi.net/
>
> Mail::Toaster - http://mail-toaster.org/
> NicTool - http://www.nictool.com/
> `````````````````````````````````````````````````````````````````````````
>
