I'm having a problem where one of my users can't receive emails with
attachments from a single customer. When the message first comes in I get the
following in /var/log/qmail/smtpd/current:
2013-03-29 09:42:33.680656500.s:@400000005155c38507dbecbc tcpserver: pid 21905
from 192.104.67.3
2013-03-29 09:42:33.680656500.s:@400000005155c38507df963c tcpserver: ok 21905
relay.davistl.com:192.168.200.25:25 mail2.eaton.com:192.104.67.3::29629
2013-03-29 09:42:33.680656500.s:@400000005155c3862bf16d84 mailfront[21905]:
MAIL FROM:<garyshoj...@eaton.com> SIZE=7823876
2013-03-29 09:42:33.680656500.s:@400000005155c3862bf17554 mailfront[21905]:
RCPT TO:<mi...@davistl.com>
2013-03-29 09:42:33.680656500.s:@400000005155c3a0379e1b14 mailfront[21905]: 451
4.3.0 Temporary qmail-queue failure.
2013-03-29 09:42:33.680656500.s:@400000005155c3a0379e1efc mailfront[21905]:
bytes in: 7823992 bytes out: 285
2013-03-29 09:42:33.680656500.s:@400000005155c3a037a097cc tcpserver: end 21905
status 0
Initially I thought softlimit might not be high enough, but increasing it
didn't help and emailing a file with an even larger attachment from one of my
accounts worked fine:
2013-03-29 09:52:39.069600500 tcpserver: pid 23160 from 205.188.105.147
2013-03-29 09:52:39.165676500 tcpserver: ok 23160
relay.davistl.com:192.168.200.25:25 imr-da05.mx.aol.com:205.188.105.147::64354
2013-03-29 09:52:41.803962500 mailfront[23160]: MAIL FROM:<blue9st...@aol.com>
SIZE=11808740
2013-03-29 09:52:41.803964500 mailfront[23160]: RCPT TO:<mi...@davistl.com>
2013-03-29 09:53:12.182697500 mailfront[23160]: 2.6.0 Accepted message qp 23162
bytes 11657485
2013-03-29 09:53:12.182698500 mailfront[23160]: bytes in: 11808855 bytes out:
295
2013-03-29 09:53:12.182819500 tcpserver: end 23160 status 0
After reading some of the mailfront code it didn't look like the problem was
there, so I looked at /var/spool/qscan/qmail-queue.log and found messages like
this:
Fri, 29 Mar 2013 10:13:19 PDT:24830: +++ starting debugging for process 24830
by uid=1003
Fri, 29 Mar 2013 10:13:19 PDT:24830: setting UID to EUID so subprocesses can
access files generated by this script
Fri, 29 Mar 2013 10:13:19 PDT:24830: program name is qmail-scanner-queue.pl,
version 2.10
Fri, 29 Mar 2013 10:13:19 PDT:24830: w_c: mkdir
/var/spool/qscan/tmp/relay136457719958624830
Fri, 29 Mar 2013 10:13:19 PDT:24830: w_c: start dumping incoming msg into
/var/spool/qscan/working/tmp/relay136457719958624830 [0.000262]
Fri, 29 Mar 2013 10:13:19 PDT:24830: c_a_g: found MIME attachment
Fri, 29 Mar 2013 10:13:19 PDT:24830: w_c: primary Content-Type of
multipart/mixed found
Fri, 29 Mar 2013 10:13:19 PDT:24830: w_c: found a top-level boundary definition
of _004_5137F0726DAB194A9D1D9AC87004F6D309F90ASIMTCSMB06napaade_
Fri, 29 Mar 2013 10:13:19 PDT:24830: w_c: attachment 1: Content-Type of
multipart/alternative found
Fri, 29 Mar 2013 10:13:19 PDT:24830: w_c: attachment 2: Content-Type of
text/plain found
Fri, 29 Mar 2013 10:13:19 PDT:24830: w_c: attachment 3: Content-Type of
text/html found
Fri, 29 Mar 2013 10:13:19 PDT:24830: found C-T attachment filename
"1c17784.zip"
Fri, 29 Mar 2013 10:13:19 PDT:24830: w_c: attachment 5: Content-Type of
application/x-zip-compressed found
Fri, 29 Mar 2013 10:13:19 PDT:24830: w_c: base64 looks like a zip file,
filename=1c17784.zip,type=application/x-zip-compressed
Fri, 29 Mar 2013 10:13:38 PDT:24830: w_c: rename new msg from
/var/spool/qscan/working/tmp/relay136457719958624830 to
/var/spool/qscan/working/new/relay136457719958624830
Fri, 29 Mar 2013 10:13:38 PDT:24830: w_c: total time between DATA command and
"." was 18.987336 secs
Fri, 29 Mar 2013 10:13:38 PDT:24830: w_c: (this is basically the time it took
the client to send the message over the network
Fri, 29 Mar 2013 10:13:38 PDT:24830: w_c: resetting timer so as to measure
actual Qmail-Scanner processing time
Fri, 29 Mar 2013 10:13:38 PDT:24830: incoming SMTP connection from via SMTP
from mail2.eaton.com
Fri, 29 Mar 2013 10:13:38 PDT:24830: d_m: starting /usr/bin/reformime
-x/var/spool/qscan/tmp/relay136457719958624830/
</var/spool/qscan/working/new/relay136457719958624830 [0.000246]
Fri, 29 Mar 2013 10:13:38 PDT:24830: d_m: finished /usr/bin/reformime
-x/var/spool/qscan/tmp/relay136457719958624830/ [0.06757]
Fri, 29 Mar 2013 10:13:38 PDT:24830: d_m: Checking all attachments to see if
they're MS-TNEF
Fri, 29 Mar 2013 10:13:38 PDT:24830: d_m: is
/var/spool/qscan/tmp/relay136457719958624830/1C17784.zip is a TNEF file?: 256
[0.001004]
Fri, 29 Mar 2013 10:13:38 PDT:24830: d_m: is
/var/spool/qscan/tmp/relay136457719958624830/1364577218.24865-0.relay is a TNEF
file?: 256 [0.000773]
Fri, 29 Mar 2013 10:13:38 PDT:24830: d_m: is
/var/spool/qscan/tmp/relay136457719958624830/1364577218.24865-1.relay is a TNEF
file?: 256 [0.000746]
Fri, 29 Mar 2013 10:13:38 PDT:24830: d_m: Check for zip files...
Fri, 29 Mar 2013 10:13:38 PDT:24830: u_f: potential zip archive file found
(1C17784.zip).
Fri, 29 Mar 2013 10:13:38 PDT:24830: u_f: it is possibly a zip file, run unzip
-Pxx1518412100xx -t /var/spool/qscan/tmp/relay136457719958624830/1C17784.zip
Fri, 29 Mar 2013 10:13:38 PDT:24830: u_f: it is a zip file
Fri, 29 Mar 2013 10:13:38 PDT:24830: u_f: check size of contents before
unzipping to disk
Fri, 29 Mar 2013 10:13:38 PDT:24830: u_f: this zip file unpacks to 4585272
bytes of content
Fri, 29 Mar 2013 10:13:38 PDT:24830: u_f: run /usr/bin/unzip -Pxx1518412100xx
/var/spool/qscan/tmp/relay136457719958624830/1C17784.zip 2>&1
Fri, 29 Mar 2013 10:13:38 PDT:24830: u_f: 0, and successfully unzipped
Fri, 29 Mar 2013 10:13:38 PDT:24830: u_f: using chmod to ensure files are
readable ()
Fri, 29 Mar 2013 10:13:38 PDT:24830: d_m: unpacking message took 0.147106
seconds
Fri, 29 Mar 2013 10:13:38 PDT:24830: unsetting QMAILQUEUE env var
Fri, 29 Mar 2013 10:13:38 PDT:24830: g_e_h: return-path is
"garyshoj...@eaton.com", recips is "mi...@davistl.com,cbe...@davistl.com"
Fri, 29 Mar 2013 10:13:38 PDT:24830: from=<garyshoj...@eaton.com>,subj=RE:
Davis Tool Contact Info.,
x-qmail-scanner-message-id=<5137f0726dab194a9d1d9ac87004f6d309f...@simtcsmb06.napa.ad.etn.com>
via SMTP from mail2.eaton.com
Fri, 29 Mar 2013 10:13:38 PDT:24830: ini_sc: start scanning
Fri, 29 Mar 2013 10:13:38 PDT:24830: ini_sc: recursively scan the directory
/var/spool/qscan/tmp/relay136457719958624830/
Fri, 29 Mar 2013 10:13:38 PDT:24830: scanloop(virus): starting scan of
directory "/var/spool/qscan/tmp/relay136457719958624830"...
Fri, 29 Mar 2013 10:13:38 PDT:24830: scanloop:
scanner=clamdscan_scanner,plain_text_msg=0
Fri, 29 Mar 2013 10:13:38 PDT:24830: clamdscan: starting scan of directory
"/var/spool/qscan/tmp/relay136457719958624830"...
Fri, 29 Mar 2013 10:13:38 PDT:24830: run /usr/bin/clamdscan --no-summary
/var/spool/qscan/tmp/relay136457719958624830 2>&1
Fri, 29 Mar 2013 10:13:39 PDT:24830: --output of clamdscan was:
/var/spool/qscan/tmp/relay136457719958624830: OK
--
Fri, 29 Mar 2013 10:13:39 PDT:24830: clamdscan: finished scan of dir
"/var/spool/qscan/tmp/relay136457719958624830" in 1.280143 secs
Fri, 29 Mar 2013 10:13:39 PDT:24830: scanloop:
scanner=mhr_scanner,plain_text_msg=0
Fri, 29 Mar 2013 10:13:39 PDT:24830: mhr: starting scan of directory
"/var/spool/qscan/tmp/relay136457719958624830"...
Fri, 29 Mar 2013 10:13:39 PDT:24830: error_condition: X-Qmail-Scanner-2.10:
Requeuing: Read failed: Is a directory at /var/qmail/bin/qmail-scanner-queue.pl
line 2761
The last line looks like a problem. I saw the note in the 2.11 release (I'm on
2.10) about mhr so I double checked that Digest::SHA and Digest::SHA1 were
installed and working:
relay:/var/log/qmail/smtpd # perl -MDigest::SHA -el
relay:/var/log/qmail/smtpd # perl -MDigest::SHA1 -el
The permissions and ownership of the /var/spool/qscan/tmp folder look ok:
relay:/var/spool/qscan # ls -alh | grep tmp
drwxr-x--- 2 qscand qscand 4.0K Mar 29 13:30 tmp
It appears that my config thinks it should be using MHR:
relay:/var/spool/qscan # cat /var/qmail/bin/qmail-scanner-queue.pl | grep
@scanner_array=
my @scanner_array=("clamdscan_scanner","mhr_scanner","spamassassin");
I don't remember turning that on, but I see from the 2.10 change log notes that
perhaps it's a new default? Since it's failing near there I'm wondering if
that might be the problem. Any thoughts?
Chris Berry
Linux Systems Administrator
Davis Tool
x521
------------------------------------------------------------------------------
Own the Future-Intel(R) Level Up Game Demo Contest 2013
Rise to greatness in Intel's independent game demo contest. Compete
for recognition, cash, and the chance to get your game on Steam.
$5K grand prize plus 10 genre and skill prizes. Submit your demo
by 6/6/13. http://altfarm.mediaplex.com/ad/ck/12124-176961-30367-2
_______________________________________________
Qmail-scanner-general mailing list
Qmail-scanner-general@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/qmail-scanner-general
