Insecure dependency when using sql for Log Reporting

[Tom GF]

Binary package hint: amavisd-new

When using @storage_sql_dsn Amavis complains on the log file:

WARN save_info_preliminary: sql execute: sts=, Insecure dependency in parameter 10 of DBI::st=HASH(0xa077aec)->execute method call while running with -T switch at (eval 41) line 127, <GEN22> line 25. at (eval 41) line 131, <GEN22> line 25.

---
lsb_release -rd:
  Description: Ubuntu 6.06.2 LTS
  Release: 6.06

apt-cache policy amavisd-new
amavisd-new:
  Installed: 1:2.3.3-3
  Candidate: 1:2.3.3-3
  Version table:
 *** 1:2.3.3-3 0
        500 http://gb.archive.ubuntu.com dapper/universe Packages
        100 /var/lib/dpkg/status

[Adam Sommer (asommer)]

Thank you for reporting this bug and helping to make Ubuntu better. Which database are you using?

[Tom GF (tomasgarciaferrari)]

I am running MySQL 4.1.

  Source: mysql-dfsg-4.1
  Version: 4.1.15-1ubuntu5

[Adam Sommer (asommer)]

I've setup a test machine and I'm not seeing the error. Just to make sure I'm looking in the right place, you're seeing the error in /var/log/mail.log?

Also, what version of libdbd-mysql-perl are you using? I'm using libdbd-mysql-perl-3.002-2build1. I also set the Amavisd-new log level to 5 using the $log_level = 5; options in /etc/amavis/conf.d/50-user. Please let me know if it should be set differently.

Thanks again.

[Tom GF (tomasgarciaferrari)]

libdbd-mysql-perl:
Version: 3.0002-2build1

The error on /var/log/mail.log:

... amavis[22796]: (22796-01) sql begin transaction
... amavis[22796]: (22796-01) sql: executing clause: SELECT id FROM maddr WHERE email=?
... amavis[22796]: (22796-01) sql: executing clause: INSERT INTO maddr (email, domain) VALUES (?,?)
... amavis[22796]: (22796-01) save_info_preliminary: 8, <email address hidden>, new
... amavis[22796]: (22796-01) sql: executing clause: INSERT INTO msgs (mail_id, secret_id, am_id, time_num, time_iso, sid, policy, client_addr, size, host) VALUES (?,?,?,?,?,?,?,?,?,?)
... amavis[22796]: (22796-01) sql rollback
... amavis[22796]: (22796-01) save_info_preliminary: rollback done
... amavis[22796]: (22796-01) WARN save_info_preliminary: sql execute: sts=, Insecure dependency in parameter 10 of DBI::st=HASH(0xa025714)->execute method call while running with -T switch at (eval 41) line 127, <GEN22> line 25. at (eval 41) line 131, <GEN22> line 25.
... amavis[22796]: (22796-01) sql_storage: retrying prelim., 3 attempts remain

in /etc/amavis/conf.d/50-user:
# SQL Lookup
@lookup_sql_dsn = ( ['DBI:mysql:database=db;host=host;', 'user', 'pass'] );
@storage_sql_dsn = @lookup_sql_dsn; # none, same, or separate database

$log_level = 5; # after your suggestion

The DB schema is coming from /usr/share/doc/amavisd-new/README.sql.gz.

Thanks for helping to solve this issue.

[Tom GF (tomasgarciaferrari)]

An extra note:

The command "INSERT INTO msgs..." never touch MySQL. The msgs table is empty and the mysql log file doesn't say a thing about 'INSERT INTO msgs...'.

[Adam Sommer (asommer)]

Hello,

From these lines:

  ... amavis[22796]: (22796-01) sql rollback
  ... amavis[22796]: (22796-01) save_info_preliminary: rollback done

It appears that the transaction is not being committed to the database.
This is what those two lines look like in my log:

  ... amavis[21515]: (21515-01) sql: preparing and executing: INSERT INTO
msgs (mail_id, secret_id, am_id, time_num, time_iso, sid, policy,
client_addr, size, host) VALUES (?,?,?,?,?,?,?,?,?,?)
  ... amavis[21515]: (21515-01) sql commit

Can you double check the schema of your msgs table? Here is what mine looks
like:

  show create table msgs;
    | msgs | CREATE TABLE `msgs` (
    `mail_id` varchar(12) NOT NULL default '',
    `secret_id` varchar(12) default '',
    `am_id` varchar(20) NOT NULL default '',
    `time_num` int(10) unsigned NOT NULL default '0',
    `time_iso` varchar(16) NOT NULL default '',
    `sid` int(10) unsigned NOT NULL default '0',
    `policy` varchar(255) default '',
    `client_addr` varchar(255) default '',
    `size` int(10) unsigned NOT NULL default '0',
    `content` char(1) default NULL,
    `quar_type` char(1) default NULL,
    `dsn_sent` char(1) default NULL,
    `spam_level` float default NULL,
    `message_id` varchar(255) default '',
    `from_addr` varchar(255) default '',
    `subject` varchar(255) default '',
    `host` varchar(255) NOT NULL default '',
    PRIMARY KEY (`mail_id`),
    KEY `sid` (`sid`),
    KEY `msgs_idx_sid` (`sid`)
  ) ENGINE=InnoDB DEFAULT CHARSET=latin1 |

I also got the table schema from /usr/share/doc/amavisd-new/README.sql.gz,
copied the SQL statements into a file named amavis.sql and did:

  mysql -u root -p amavis < amavis.sql

My db name being amavis. Just wanted to double check if you followed a
similar approach?

--
Party On,
Adam

[Tom GF (tomasgarciaferrari)]

Yes, I also recognized that the transaction is not being comitted to the DB.

This is the schema of msgs on my server:

show create table msgs;

| msgs | CREATE TABLE `msgs` (
  `mail_id` varchar(12) NOT NULL default '',
  `secret_id` varchar(12) default '',
  `am_id` varchar(20) NOT NULL default '',
  `time_num` int(10) unsigned NOT NULL default '0',
  `time_iso` varchar(16) NOT NULL default '',
  `sid` int(10) unsigned NOT NULL default '0',
  `policy` varchar(255) default '',
  `client_addr` varchar(255) default '',
  `size` int(10) unsigned NOT NULL default '0',
  `content` char(1) default NULL,
  `quar_type` char(1) default NULL,
  `dsn_sent` char(1) default NULL,
  `spam_level` float default NULL,
  `message_id` varchar(255) default '',
  `from_addr` varchar(255) default '',
  `subject` varchar(255) default '',
  `host` varchar(255) NOT NULL default '',
  PRIMARY KEY (`mail_id`),
  KEY `sid` (`sid`),
  KEY `msgs_idx_sid` (`sid`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 |

The only difference is the DEFAULT CHARSET... But I don't think that this could make this difference, am I right?

I took all the tables from /usr/share/doc/amavisd-new/README.sql.gz:

mysql> show tables;
+------------------+
| Tables_in_amavis |
+------------------+
| maddr |
| mailaddr |
| msgrcpt |
| msgs |
| policy |
| quarantine |
| users |
| wblist |
+------------------+

Thanks for helping me to solve this issue.

[Adam Sommer (asommer)]

Nope, shouldn't have anything to do with the charset, I recreated my
mssgs table using utf8 and it worked fine. Can you connect to the
database using the the username and password used in the
configuration?

I'd think that there would be a more detailed error if that were the
case, but you may want to double check that. I executed:

  grant all on amavis.* to amavis@'localhost' identified by 'passwd';

--
Party On,
Adam

[Tom GF (tomasgarciaferrari)]

Yes, I can connect to the DB using this user and password. I can write to the msgs table. I granted all the privileges to the amavis user on tables on the amavis DB (exactly the same that you sent). Exactly the same result.

This is coming from the save_info_preliminary subroutine on amavisd-new. Is there any way to obtain a more detailed error there?

[Tom GF (tomasgarciaferrari)]

I have found a solution.

First I have noticed another log in /var/log/mail.err:

...amavis[23324]: (23324-03) ERROR sql_storage: too many retries on storing preliminary, info not saved

which confirmed that nothing went into the DB.

Googling about this error, I found a message from Mark Martinec that gave me a clue:

> Could it be that $myhostname is tainted?
>
> Try to set it explicitly in amavisd.conf, e.g.:
> $myhostname = 'host.example.com';

See <http://readlist.com/lists/lists.sourceforge.net/amavis-user/0/416.html>.

I add this to 50-user, restarted amavisd-new and... now is not complaining and storing the data into the msgs table.

Do you have a further explanation?

[Adam Sommer (asommer)]

>
> Do you have a further explanation?
>
>
That's great news! My thought is, and I'm far from an expert, amavisd-new
didn't know what host to accept mail for. Did you try amavisd-new without
using a database to store the messages?

Either way it's great that it's working now :-).

--
Party On,
Adam

[Scott Kitterman (kitterman)]

On Monday 07 April 2008 00:13:32 Adam Sommer wrote:
> > Do you have a further explanation?
>
> That's great news! My thought is, and I'm far from an expert, amavisd-new
> didn't know what host to accept mail for. Did you try amavisd-new without
> using a database to store the messages?
>
There are open bugs in Ubuntu where the hostname does not get correctly set
sometimes. For Gutsy and later I've patched amavisd-new to give the user
some warning about this.

[Adam Sommer (asommer)]

Cool, thanks Scott. I'm not quite sure what the status of this bug should then be?

[Scott Kitterman (kitterman)]

I'm not sure if it's wontfix or invalid. Either way I don't think there's any actual amavisd-new fix needed. Perhaps the reporter could suggest documentation changes that would have made this easier to solve/prevent?

[Tom GF (tomasgarciaferrari)]

My only suggestion would be to say clearly that if $myhostname is not explicitely declared there are warnings on the log files and the messages are not stored into the DB (MySQL at least).

Maybe to produce a newer package is not absolutely needed yet...

[Adam Sommer (asommer)]

Assigning to me and added to ubuntu-doc so that I don't forget to add information regarding $myhostname to the Server Guide.

[Connor Imes (ckimes)]

Moving to ubuntu-docs package for doc team policy, keeping Adam assigned.

Adam, has this been documented in the serverguide yet?

[Adam Sommer (asommer)]

Great apologies there has been a note about manually setting the $myhostname variable since at least the 8.10 release. The specific revision is number 344.

I must have forgot to add this bug number to the commit message, so marking as fix released now. Thanks Connor and Thierry for the reminder.

[Adam Sommer (asommer)]

Fix committed to revision 344.