Strange message !

Rick Cooper rcooper at dwford.com
Tue Mar 11 20:14:46 GMT 2008


Well I guess I should have read the next one before my last post. Actually
that line is commented by default. And yes, while mailwatch is doing
something during or just before the scan output (which comes after the scan,
from the parser) the trace log hasn't been opened properly so the output is
headed to, I think, stdout (might be stderr as that is redirected iirc) and
it's getting fed to the parser as clamd output.

If the original poster would comment out the trace line in MailWatch.pm I
believe his issues would go away too. There are a lot of incidental warnings
and undef errors that DBI doesn't choke on unless -w is used and don't think
MailScanner uses that switch a all, or at least not for the most part. The
trace log would show those errors however. 

Rick

 > -----Original Message-----
 > From: mailscanner-bounces at lists.mailscanner.info 
 > [mailto:mailscanner-bounces at lists.mailscanner.info] On Behalf Of tlum
 > Sent: Tuesday, March 11, 2008 3:14 PM
 > To: MailScanner discussion
 > Subject: Re: Strange message !
 > 
 > Actually, this whole problem is caused by 
 > "DBI->trace(2,'/root/dbitrace.log');" in MailWatch.pm. 
 > Unless you run 
 > MailScanner as root this will fail. You MUST point the file to some 
 > place where the MailScanner process user can write otherwise 
 > you will 
 > get this error. As long as I point to /tmp or comment the 
 > line out there 
 > are no more report of issues in maillog.
 > 
 > Of corse now I'm a little curious about this "!! ERROR: 1 
 > 'table cache 
 > already exists(1) at dbdimp.c line 271' (err#0)", but at least the 
 > original problem is gone.
 > 
 > tlum wrote:
 > > MailWatch.pm might also be found @ 
 > > ./usr/lib/MailScanner/MailScanner/CustomFunctions/MailWatch.pm
 > >
 > > MailWatch is logging where it says "Logging message 
 > xxxxxxxxxx.xxxxx 
 > > to SQL" - after the whole clam issue. However, MailWatch makes 
 > > frequent database calls to pull white and black lists, for example.
 > >
 > > There is no output to the console and all debug output 
 > goes to syslog, 
 > > and as far as I can see has already been posted here.
 > >
 > > DBI->trace(2,'/root/dbitrace.log'); is already uncommented but 
 > > generates no output. This is because the whole thing is running as 
 > > postfix and can't write to /root. Pointed it to /tmp and get the 
 > > following:
 > >
 > >    -> 
 > > 
 > DBI->connect(dbi:SQLite:/var/spool/MailScanner/incoming/SpamA
 > ssassin.cache.db, 
 > > , ****, HASH(0xa664b7c))
 > >    -> DBI->install_driver(SQLite) for linux perl=5.008008 
 > pid=16827 
 > > ruid=89 euid=89
 > >       install_driver: DBD::SQLite version 1.14 loaded from 
 > > 
 > /usr/lib/perl5/site_perl/5.8.8/i386-linux-thread-multi/DBD/SQLite.pm
 > >    <- install_driver= DBI::dr=HASH(0xa66f0a4)
 > >    !! warn: 0 CLEARED by call to connect method
 > >    -> connect for DBD::SQLite::dr 
 > (DBI::dr=HASH(0xa66f0a4)~0xa66f0ec 
 > > '/var/spool/MailScanner/incoming/SpamAssassin.cache.db' '' **** 
 > > HASH(0x974e594)) thr#8cd2008
 > >    <- connect= DBI::db=HASH(0xa66f4dc) at DBI.pm line 637
 > >    -> STORE for DBD::SQLite::db (DBI::db=HASH(0xa66f4ac)~INNER 
 > > 'PrintError' 0) thr#8cd2008
 > >    <- STORE= 1 at DBI.pm line 689
 > >    -> STORE for DBD::SQLite::db (DBI::db=HASH(0xa66f4ac)~INNER 
 > > 'AutoCommit' 1) thr#8cd2008
 > >    <- STORE= 1 at DBI.pm line 689
 > >    -> STORE for DBD::SQLite::db (DBI::db=HASH(0xa66f4ac)~INNER 
 > > 'InactiveDestroy' 1) thr#8cd2008
 > >    <- STORE= 1 at DBI.pm line 692
 > >    -> FETCH for DBD::SQLite::db (DBI::db=HASH(0xa66f4ac)~INNER 
 > > 'InactiveDestroy') thr#8cd2008
 > >    <- FETCH= 1 at DBI.pm line 692
 > >    -> STORE for DBD::SQLite::db (DBI::db=HASH(0xa66f4ac)~INNER 
 > > 'Username' '') thr#8cd2008
 > >    <- STORE= 1 at DBI.pm line 692
 > >    <> FETCH= '' ('Username' from cache) at DBI.pm line 692
 > >    -> connected in DBD::_::db for DBD::SQLite::db 
 > > (DBI::db=HASH(0xa66f4dc)~0xa66f4ac 
 > > 
 > 'dbi:SQLite:/var/spool/MailScanner/incoming/SpamAssassin.cach
 > e.db' '' 
 > > '' HASH(0xa664b7c)) thr#8cd2008
 > >    <- connected= undef at DBI.pm line 698
 > >    <- connect= DBI::db=HASH(0xa66f4dc)
 > >    -> STORE for DBD::SQLite::db (DBI::db=HASH(0xa66f4ac)~INNER 
 > > 'dbi_connect_closure' CODE(0xa66f068)) thr#8cd2008
 > >    <- STORE= 1 at DBI.pm line 707
 > >    -> do in DBD::_::db for DBD::SQLite::db 
 > > (DBI::db=HASH(0xa66f4dc)~0xa66f4ac 'CREATE TABLE cache (md5 TEXT, 
 > > count INTEGER, last TIMESTAMP, first TIMESTAMP, sasaysspam INT, 
 > > sahighscoring INT, sascore FLOAT, saheader BLOB, 
 > salongreport BLOB, 
 > > virusinfected INT)') thr#8cd2008
 > > 1   -> prepare for DBD::SQLite::db (DBI::db=HASH(0xa66f4ac)~INNER 
 > > 'CREATE TABLE cache (md5 TEXT, count INTEGER, last 
 > TIMESTAMP, first 
 > > TIMESTAMP, sasaysspam INT, sahighscoring INT, sascore 
 > FLOAT, saheader 
 > > BLOB, salongreport BLOB, virusinfected INT)' undef) thr#8cd2008
 > > sqlite trace: prepare statement: CREATE TABLE cache (md5 
 > TEXT, count 
 > > INTEGER, last TIMESTAMP, first TIMESTAMP, sasaysspam INT, 
 > > sahighscoring INT, sascore FLOAT, saheader BLOB, 
 > salongreport BLOB, 
 > > virusinfected INT) at dbdimp.c line 258
 > >    -> DESTROY for DBD::SQLite::st (DBI::st=HASH(0xa66f674)~INNER) 
 > > thr#8cd2008
 > >         DESTROY for DBI::st=HASH(0xa66f674) ignored - handle not 
 > > initialised
 > >       ERROR: 1 'table cache already exists(1) at dbdimp.c 
 > line 271' 
 > > (err#0)
 > >    <- DESTROY= undef at DBI.pm line 1561
 > >    !! ERROR: 1 'table cache already exists(1) at dbdimp.c 
 > line 271' 
 > > (err#0)
 > > 1   <- prepare= undef at DBI.pm line 1561
 > >    !! ERROR: 1 'table cache already exists(1) at dbdimp.c 
 > line 271' 
 > > (err#0)
 > >    <- do= undef at SA.pm line 215
 > >    !! ERROR: 1 CLEARED by call to do method
 > >    -> do for DBD::SQLite::db (DBI::db=HASH(0xa66f4dc)~0xa66f4ac 
 > > 'CREATE UNIQUE INDEX md5_uniq ON cache(md5)') thr#8cd2008
 > > 1   -> prepare for DBD::SQLite::db (DBI::db=HASH(0xa66f4ac)~INNER 
 > > 'CREATE UNIQUE INDEX md5_uniq ON cache(md5)' undef) thr#8cd2008
 > > sqlite trace: prepare statement: CREATE UNIQUE INDEX md5_uniq ON 
 > > cache(md5) at dbdimp.c line 258
 > >    -> DESTROY for DBD::SQLite::st (DBI::st=HASH(0x9fab1c8)~INNER) 
 > > thr#8cd2008
 > >         DESTROY for DBI::st=HASH(0x9fab1c8) ignored - handle not 
 > > initialised
 > >       ERROR: 1 'index md5_uniq already exists(1) at 
 > dbdimp.c line 271' 
 > > (err#0)
 > >    <- DESTROY= undef at DBI.pm line 1561
 > >    !! ERROR: 1 'index md5_uniq already exists(1) at 
 > dbdimp.c line 271' 
 > > (err#0)
 > > 1   <- prepare= undef at DBI.pm line 1561
 > >    !! ERROR: 1 'index md5_uniq already exists(1) at 
 > dbdimp.c line 271' 
 > > (err#0)
 > >    <- do= undef at SA.pm line 216
 > >    !! ERROR: 1 CLEARED by call to do method
 > >    -> do for DBD::SQLite::db (DBI::db=HASH(0xa66f4dc)~0xa66f4ac 
 > > 'CREATE INDEX last_seen_idx ON cache(last)') thr#8cd2008
 > > 1   -> prepare for DBD::SQLite::db (DBI::db=HASH(0xa66f4ac)~INNER 
 > > 'CREATE INDEX last_seen_idx ON cache(last)' undef) thr#8cd2008
 > > sqlite trace: prepare statement: CREATE INDEX last_seen_idx ON 
 > > cache(last) at dbdimp.c line 258
 > >    -> DESTROY for DBD::SQLite::st (DBI::st=HASH(0x9ebaa8c)~INNER) 
 > > thr#8cd2008
 > >         DESTROY for DBI::st=HASH(0x9ebaa8c) ignored - handle not 
 > > initialised
 > >       ERROR: 1 'index last_seen_idx already exists(1) at 
 > dbdimp.c line 
 > > 271' (err#0)
 > >    <- DESTROY= undef at DBI.pm line 1561
 > >    !! ERROR: 1 'index last_seen_idx already exists(1) at 
 > dbdimp.c line 
 > > 271' (err#0)
 > > 1   <- prepare= undef at DBI.pm line 1561
 > >    !! ERROR: 1 'index last_seen_idx already exists(1) at 
 > dbdimp.c line 
 > > 271' (err#0)
 > >    <- do= undef at SA.pm line 217
 > >    !! ERROR: 1 CLEARED by call to do method
 > >    -> do for DBD::SQLite::db (DBI::db=HASH(0xa66f4dc)~0xa66f4ac 
 > > 'CREATE INDEX first_seen_idx ON cache(first)') thr#8cd2008
 > > 1   -> prepare for DBD::SQLite::db (DBI::db=HASH(0xa66f4ac)~INNER 
 > > 'CREATE INDEX first_seen_idx ON cache(first)' undef) thr#8cd2008
 > > sqlite trace: prepare statement: CREATE INDEX first_seen_idx ON 
 > > cache(first) at dbdimp.c line 258
 > >    -> DESTROY for DBD::SQLite::st (DBI::st=HASH(0xa66f74c)~INNER) 
 > > thr#8cd2008
 > >         DESTROY for DBI::st=HASH(0xa66f74c) ignored - handle not 
 > > initialised
 > >       ERROR: 1 'index first_seen_idx already exists(1) at dbdimp.c 
 > > line 271' (err#0)
 > >    <- DESTROY= undef at DBI.pm line 1561
 > >    !! ERROR: 1 'index first_seen_idx already exists(1) at dbdimp.c 
 > > line 271' (err#0)
 > > 1   <- prepare= undef at DBI.pm line 1561
 > >    !! ERROR: 1 'index first_seen_idx already exists(1) at dbdimp.c 
 > > line 271' (err#0)
 > >    <- do= undef at SA.pm line 218
 > >    !! ERROR: 1 CLEARED by call to prepare method
 > >    -> prepare for DBD::SQLite::db 
 > (DBI::db=HASH(0xa66f4dc)~0xa66f4ac '
 > >   DELETE FROM cache WHERE (
 > >   (sasaysspam=0 AND virusinfected<1 AND 
 > > first<=(strftime('%s','now')-?)) OR
 > >   (sasaysspam>0 AND sahighscoring=0 AND virusinfected<1 AND 
 > > first<=(strftime('%s','now')-?)) OR
 > >   (sasaysspam>0 AND sahighscoring>0 AND virusinfected<1 AND 
 > > last<=(strftime('%s','now')-?)) OR
 > >   (virusinfected>=1 AND last<=(strftime('%s','now')-?))
 > >  )') thr#8cd2008
 > > sqlite trace: prepare statement:
 > >   DELETE FROM cache WHERE (
 > >   (sasaysspam=0 AND virusinfected<1 AND 
 > > first<=(strftime('%s','now')-?)) OR
 > >   (sasaysspam>0 AND sahighscoring=0 AND virusinfected<1 AND 
 > > first<=(strftime('%s','now')-?)) OR
 > >   (sasaysspam>0 AND sahighscoring>0 AND virusinfected<1 AND 
 > > last<=(strftime('%s','now')-?)) OR
 > >   (virusinfected>=1 AND last<=(strftime('%s','now')-?))
 > >  ) at dbdimp.c line 258
 > >    <- prepare= DBI::st=HASH(0xa66f7dc) at SA.pm line 730
 > >    -> execute for DBD::SQLite::st 
 > (DBI::st=HASH(0xa66f7dc)~0xa66f818 
 > > '1800' '300' '10800' '172800') thr#8cd2008
 > >    <- execute= '0E0' at SA.pm line 738
 > >    -> finish for DBD::SQLite::st 
 > (DBI::st=HASH(0xa66f7dc)~0xa66f818) 
 > > thr#8cd2008
 > >    <- finish= 1 at SA.pm line 739
 > >    -> DESTROY for DBD::SQLite::st (DBI::st=HASH(0xa66f818)~INNER) 
 > > thr#8cd2008
 > >    <- DESTROY= undef at SA.pm line 222
 > >
 > >
 > >
 > >
 > >
 > >
 > >
 > >
 > >
 > > Rick Cooper wrote:
 > >> First off, this appears to be a perl error being directed 
 > to stderr 
 > >> and that is why it's showing up in your clamd parsing. I 
 > am not sure 
 > >> where in the process mailwatch is logging, and the 
 > mailwatch people 
 > >> might know right off the bat, however; Perhaps you should 
 > look at the 
 > >> debug output (both console and logging) and post those 
 > here and also 
 > >> look at the top of 
 > >> /opt/MailScanner/lib/MailScanner/CustomFunctions/MailWatch.pm for:
 > >>  
 > >> # DBI->trace(2,'/root/dbitrace.log');
 > >>  
 > >> and uncomment that and check the trace log.
 > >>  
 > >> Also run MailScanner -v and post/check the output
 > >>  
 > >> Rick
 > >>
 > >>     
 > >> 
 > -------------------------------------------------------------
 > -----------
 > >>     *From:* mailscanner-bounces at lists.mailscanner.info
 > >>     [mailto:mailscanner-bounces at lists.mailscanner.info] 
 > *On Behalf Of
 > >>     *Thiago Henrique
 > >>     *Sent:* Tuesday, March 11, 2008 10:51 AM
 > >>     *To:* MailScanner discussion
 > >>     *Subject:* Re: Strange message !
 > >>
 > >>     Rick,
 > >>
 > >>     I'm using MailWatch for parse logs, every message 
 > have logged in
 > >>     mysql data base. The strange messages occur after a 
 > virus scanner
 > >>     start:
 > >>
 > >>     Mar 11 08:49:20 morpheus MailScanner[20893]: Virus and Content
 > >>     Scanning: Starting
 > >>     Mar 11 08:49:20 morpheus MailScanner[20893]: Clamd::    --
 > >>     DBI::END ($@: , $!: )
 > >>     Mar 11 08:49:21 morpheus MailScanner[20893]: Clamd::    ->
 > >>     disconnect_all for DBD::mysql::dr 
 > >> (DBI::dr=HASH(0x932a7ec)~0x932cac4)
 > >>     Mar 11 08:49:21 morpheus MailScanner[20893]: Clamd::    <-
 > >>     disconnect_all= (not implemented) at DBI.pm line 718
 > >>     Mar 11 08:49:21 morpheus MailScanner[20893]: Clamd::    ->
 > >>     disconnect_all for DBD::SQLite::dr 
 > >> (DBI::dr=HASH(0x98d6e64)~0x98d6eac)
 > >>     Mar 11 08:49:21 morpheus MailScanner[20893]: Clamd::    <-
 > >>     disconnect_all= '' at DBI.pm line 718
 > >>     Mar 11 08:49:21 morpheus MailScanner[20893]: Clamd::! 
 >   -> DESTROY
 > >>     for DBD::SQLite::db (DBI::db=HASH(0x98dab98)~INNER)
 > >>     Mar 11 08:49:21 morpheus MailScanner[20893]: Clamd::  
 >           
 > >> DESTROY DBI::db=HASH(0x98dab98) skipped due to InactiveDestroy
 > >>     Mar 11 08:49:21 morpheus MailScanner[20893]: Clamd::!   <-
 > >>     DESTROY= undef during global destruction
 > >>     Mar 11 08:49:21 morpheus MailScanner[20893]: Clamd::! 
 >   -> DESTROY
 > >>     in DBD::_::common for DBD::SQLite::dr 
 > >> (DBI::dr=HASH(0x98d6eac)~INNER)
 > >>     Mar 11 08:49:21 morpheus MailScanner[20893]: Clamd::!   <-
 > >>     DESTROY= undef during global destruction
 > >>     Mar 11 08:49:21 morpheus MailScanner[20893]: Clamd::! 
 >   -> DESTROY
 > >>     in DBD::_::dr for DBD::mysql::dr 
 > (DBI::dr=HASH(0x932cac4)~INNER)
 > >>     Mar 11 08:49:21 morpheus MailScanner[20893]: Clamd::!   <-
 > >>     DESTROY= undef during global destruction
 > >>     Mar 11 08:49:21 morpheus MailScanner[20893]: Virus 
 > Scanning: Clamd
 > >>     found 12 infections
 > >>     Mar 11 08:49:21 morpheus MailScanner[20893]: Virus 
 > Scanning: Found
 > >>     12 viruses
 > >>     Mar 11 08:49:21 morpheus MailScanner[20893]: Requeue:
 > >>     2E48351F14.1A77F to 9FF1B778CA
 > >>     Mar 11 08:49:21 morpheus MailScanner[20893]: 
 > Uninfected: Delivered
 > >>     1 messages
 > >>     Mar 11 08:49:21 morpheus MailScanner[20893]: Logging message
 > >>     2E48351F14.1A77F to SQL
 > >>
 > >>     The mail is sent normally to the user, but every 12 
 > lines of error
 > >>     is considered virus for MailScanner.
 > >>
 > >>
 > >>
 > >>     On Tue, Mar 11, 2008 at 10:49 AM, Rick Cooper 
 > <rcooper at dwford.com
 > >>     <mailto:rcooper at dwford.com>> wrote:
 > >>
 > >>         
 > >>             
 > >> 
 > -------------------------------------------------------------
 > -----------
 > >>             *From:* mailscanner-bounces at lists.mailscanner.info
 > >>             <mailto:mailscanner-bounces at lists.mailscanner.info>
 > >>             [mailto:mailscanner-bounces at lists.mailscanner.info
 > >>             
 > <mailto:mailscanner-bounces at lists.mailscanner.info>] *On
 > >>             Behalf Of *Thiago Henrique
 > >>             *Sent:* Monday, March 10, 2008 8:53 PM
 > >>             *To:* mailscanner at lists.mailscanner.info
 > >>             <mailto:mailscanner at lists.mailscanner.info>
 > >>             *Subject:* Strange message !
 > >>
 > >>             Hy All,
 > >>
 > >>             After a upgrade for MailScanner 4.66.5, and configured
 > >>             MailScanner to use CLAMD, i have the 
 > following message in
 > >>             mail.log on every mail scanned:
 > >>
 > >>             Mar 10 21:48:51 morpheus MailScanner[30706]: 
 > Clamd::    --
 > >>             DBI::END ($@: , $!: )
 > >>             Mar 10 21:48:51 morpheus MailScanner[30706]: 
 > Clamd::    ->
 > >>             disconnect_all for DBD::mysql::dr
 > >>             (DBI::dr=HASH(0x932a67c)~0x932c954)
 > >>             Mar 10 21:48:51 morpheus MailScanner[30706]: 
 > Clamd::    <-
 > >>             disconnect_all= (not implemented) at DBI.pm line 718
 > >>             Mar 10 21:48:51 morpheus MailScanner[30706]: 
 > Clamd::    ->
 > >>             disconnect_all for DBD::SQLite::dr
 > >>             (DBI::dr=HASH(0x98d6e34)~0x98d6e7c)
 > >>             Mar 10 21:48:51 morpheus MailScanner[30706]: 
 > Clamd::    <-
 > >>             disconnect_all= '' at DBI.pm line 718
 > >>             Mar 10 21:48:51 morpheus MailScanner[30706]: 
 > Clamd::!   ->
 > >>             DESTROY for DBD::SQLite::db 
 > (DBI::db=HASH(0x98dab60)~INNER)
 > >>             Mar 10 21:48:51 morpheus MailScanner[30706]:
 > >>             Clamd::         DESTROY 
 > DBI::db=HASH(0x98dab60) skipped
 > >>             due to InactiveDestroy
 > >>             Mar 10 21:48:51 morpheus MailScanner[30706]: 
 > Clamd::!   <-
 > >>             DESTROY= undef during global destruction
 > >>             Mar 10 21:48:51 morpheus MailScanner[30706]: 
 > Clamd::!   ->
 > >>             DESTROY in DBD::_::common for DBD::SQLite::dr
 > >>             (DBI::dr=HASH(0x98d6e7c)~INNER)
 > >>             Mar 10 21:48:51 morpheus MailScanner[30706]: 
 > Clamd::!   <-
 > >>             DESTROY= undef during global destruction
 > >>             Mar 10 21:48:51 morpheus MailScanner[30706]: 
 > Clamd::!   ->
 > >>             DESTROY in DBD::_::dr for DBD::mysql::dr
 > >>             (DBI::dr=HASH(0x932c954)~INNER)
 > >>             Mar 10 21:48:51 morpheus MailScanner[30706]: 
 > Clamd::!   <-
 > >>             DESTROY= undef during global destruction
 > >>             Mar 10 21:48:51 morpheus MailScanner[30706]: Virus
 > >>             Scanning: Clamd found 12 infections
 > >>             Mar 10 21:48:51 morpheus MailScanner[30706]: Virus
 > >>             Scanning: Found 12 viruses
 > >>
 > >>
 > >>
 > >>             [Rick Cooper]             Are you using sql 
 > logging, or 
 > >> is this a mailwatch issue?
 > >>                          Rick
 > >>
 > >>         --         This message has been scanned for viruses and
 > >>         dangerous content by *MailScanner*
 > >>         <http://www.mailscanner.info/>, and is
 > >>         believed to be clean.
 > >>
 > >>         --
 > >>         MailScanner mailing list
 > >>         mailscanner at lists.mailscanner.info
 > >>         <mailto:mailscanner at lists.mailscanner.info>
 > >>         http://lists.mailscanner.info/mailman/listinfo/mailscanner
 > >>
 > >>         Before posting, read http://wiki.mailscanner.info/posting
 > >>
 > >>         Support MailScanner development - buy the book 
 > off the website!
 > >>
 > >>
 > >>
 > >>     --     This message has been scanned for viruses and
 > >>     dangerous content by *MailScanner* 
 > <http://www.mailscanner.info/>,
 > >>     and is
 > >>     believed to be clean.
 > >>
 > >> -- 
 > >> This message has been scanned for viruses and
 > >> dangerous content by *MailScanner* 
 > <http://www.mailscanner.info/>, 
 > >> and is
 > >> believed to be clean.
 > >> -- 
 > >> This message has been scanned for viruses and
 > >> dangerous content by *MailScanner* 
 > <http://www.mailscanner.info/>, 
 > >> and is
 > >> believed to be clean. 
 > >
 > >
 > 
 > 
 > -- 
 > This message has been scanned for viruses and
 > dangerous content by MailScanner, and is
 > believed to be clean.
 > 
 > -- 
 > MailScanner mailing list
 > mailscanner at lists.mailscanner.info
 > http://lists.mailscanner.info/mailman/listinfo/mailscanner
 > 
 > Before posting, read http://wiki.mailscanner.info/posting
 > 
 > Support MailScanner development - buy the book off the website! 
 > 
 > --
 > This message has been scanned for viruses and
 > dangerous content by MailScanner, and is
 > believed to be clean.
 > 
 > 


--
This message has been scanned for viruses and
dangerous content by MailScanner, and is
believed to be clean.




More information about the MailScanner mailing list