Re: spool file not present on disk

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 <[email protected]>
> 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/
> `````````````````````````````````````````````````````````````````````````
>