Strange message !
Rick Cooper
rcooper at dwford.com
Tue Mar 11 19:46:36 GMT 2008
Now that you have the trace log set to something that is writable are you
still seeing the garbage in your clamd output? If so comment it out (as it
should be). I have seen perl progs that spew to stdout when they are
supposed to be writing to a file and don't get the file opened properly.
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 2:48 PM
> To: MailScanner discussion
> Subject: Re: Strange message !
>
> 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