created_partsdir FAILED

[HoUsECAt]

hi all...

great tutorial on virtual postfix tutorial ... it all works great and mail gets delivered and scanned ....

Only even now and then a message appears in mail.log and amavisd.log like:


Apr 14 10:09:57 adam amavisd-new[18705]: (18705-07) lookup_sql: 2013, Lost connection to MySQL server during query
Apr 14 10:09:57 adam amavisd-new[18705]: (18705-07) NOTICE: Disconnected from SQL server
Apr 14 10:09:57 adam amavisd-new[18705]: (18705-07) TROUBLE in check_mail: creating_partsdir FAILED: DBD::mysql::st execute failed: Lost connection to MySQL server during query at (eval 41) line 238, <GEN16> line 2855.
Apr 14 10:09:57 adam amavisd-new[18705]: (18705-07) PRESERVING EVIDENCE in /var/lib/amavis/amavis-20060413T084946-18705


this particular mail got in the mailq and when i requed it, it got delivered. Any ideas what this can be?

[falko]

You can tryto remove all the proxy: strings in /etc/postfix/main.cf, e.g. replace

virtual_mailbox_domains = proxy:mysql:/etc/postfix/mysql-virtual_domains.cf
with
virtual_mailbox_domains = mysql:/etc/postfix/mysql-virtual_domains.cfand do the same for all other lines with proxy:
Restart Postfix afterwards.

[HoUsECAt]

thanks.. i wil test that... can you explain to me what proxy: does?

[falko]

If you use proxy:, then Postfix uses only one persistent MySQL connection; if you don't use it, Postfix creates a new connection everytime.

[HoUsECAt]

which can't hurt much in a small business server?

[falko]

Unless you're running a high-traffic mail server, it doesn't matter at all. :)

[HoUsECAt]

this morning i again saw the error message again

Apr 20 08:59:23 adam amavisd-new[2374]: (02374-04) lookup_sql: 2013, Lost connection to MySQL server during query
Apr 20 08:59:23 adam amavisd-new[2374]: (02374-04) NOTICE: Disconnected from SQL server
Apr 20 08:59:23 adam amavisd-new[2374]: (02374-04) TROUBLE in check_mail: creating_partsdir FAILED: DBD::mysql::st execute failed: Lost connection to MySQL adam during query at (eval 41) line 238, <GEN16> line 2833.
Apr 20 08:59:23 adam amavisd-new[2374]: (02374-04) PRESERVING EVIDENCE in /var/lib/amavis/amavis-20060419T160329-02374

this mail also appears in the mailq, and i have to requeue it.....

any ideas?

[falko]

Seems to be a problem with amavisd. Maybe a bug? :confused:

[HoUsECAt]

alright... thanks... i will go and try to gather some information with amavisd....

will keep you posted

[HoUsECAt]

i figured out a little bit what the cause is, I haven't got a very busy mailserver and it mostly happens in the night, due the 'inactivitiy' of amavisd it loses the connection to the database. When i restart amavisd it is solved.

so i can solve this by a cron restart of amavisd, but for now i'm happy as it is :)

[Mustang Matt]

How did you figure out that amavis was dropping it's connection to the database and not re-establishing it?

I followed the tutorial and I'm ending up with this when I try to send:

Jul 29 00:29:16 localhost amavis[11979]: (11961-01) run_command: child process [11979] failed to exec /usr/bin/file /var/lib/amavis/amavis-20060729T002916-11961/parts/part-00001: Can't close main::stdin: Bad file descriptor at /usr/sbin/amavisd-new line 1131.
Jul 29 00:29:16 localhost amavis[11961]: (11961-01) TROUBLE in check_mail: decoding2-get-file-types FAILED: 'file' utility (/usr/bin/file) failed, status=1 (256 ) at /usr/sbin/amavisd-new line 3853.
Jul 29 00:29:16 localhost amavis[11961]: (11961-01) PRESERVING EVIDENCE in /var/lib/amavis/amavis-20060729T002916-11961
Jul 29 00:29:16 localhost postfix/smtp[11977]: 7386A9B0C14: to=<email>, relay=127.0.0.1[127.0.0.1], delay=0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.5.0 Error in processing, id=11961-01, decoding2-get-file-types FAILED: 'file' utility (/usr/bin/file) failed, status=1 (256 ) at /usr/sbin/amavisd-new line 3853. (in reply to end of DATA command))

[falko]

Jul 29 00:29:16 localhost amavis[11979]: (11961-01) run_command: child process [11979] failed to exec /usr/bin/file /var/lib/amavis/amavis-20060729T002916-11961/parts/part-00001: Can't close main::stdin: Bad file descriptor at /usr/sbin/amavisd-new line 1131.Please restart amavisd, and if that doesn't help, reboot your server.

[Mustang Matt]

Actually the solution was to make mysql use a tcp port by commenting out the skip-networking line in /etc/mysql/my.cnf

For some reason smptd absolutely couldn't access mysql otherwise.

(Reboot the server?! :eek: This isn't windows! lol)

Beyond that, amavis was still having problems:

These errors were found in the syslog.
Jul 29 16:14:33 localhost amavis[16341]: (16092-07) run_command: child process [16341] failed to exec /usr/bin/file /var/lib/amavis/amavis-20060729T161433-16092/parts/part-00001: Can't close main::stdin: Bad file descriptor at /usr/sbin/amavisd-new line 1131.
Jul 29 16:14:33 localhost amavis[16092]: (16092-07) TROUBLE in check_mail: decoding2-get-file-types FAILED: 'file' utility (/usr/bin/file) failed, status=1 (256 ) at /usr/sbin/amavisd-new line 3853.

So a friend and I traced it down as far as we could and ultimately filed a debian bug report.

http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=380409

I should add to that bug report all the amavis info I suppose:

Jul 30 09:05:26 localhost amavis[2535]: Perl version 5.008004
Jul 30 09:05:26 localhost amavis[2535]: Module Amavis::Conf 1.15
Jul 30 09:05:26 localhost amavis[2535]: Module Archive::Tar 1.29
Jul 30 09:05:26 localhost amavis[2535]: Module Archive::Zip 1.16
Jul 30 09:05:26 localhost amavis[2535]: Module Compress::Zlib 1.42
Jul 30 09:05:26 localhost amavis[2535]: Module Convert::TNEF 0.17
Jul 30 09:05:26 localhost amavis[2535]: Module Convert::UUlib 1.06
Jul 30 09:05:26 localhost amavis[2535]: Module DBI 1.51
Jul 30 09:05:26 localhost amavis[2535]: Module MIME::Entity 5.420
Jul 30 09:05:26 localhost amavis[2535]: Module MIME::Parser 5.420
Jul 30 09:05:26 localhost amavis[2535]: Module MIME::Tools 5.420
Jul 30 09:05:26 localhost amavis[2535]: Module Mail::Header 1.74
Jul 30 09:05:26 localhost amavis[2535]: Module Mail::Internet 1.74
Jul 30 09:05:26 localhost amavis[2535]: Module Net::Cmd 2.26
Jul 30 09:05:26 localhost amavis[2535]: Module Net::SMTP 2.29
Jul 30 09:05:26 localhost amavis[2535]: Module Net::Server 0.94
Jul 30 09:05:26 localhost amavis[2535]: Module Time::HiRes 1.87
Jul 30 09:05:26 localhost amavis[2535]: Module Unix::Syslog 0.99
Jul 30 09:05:26 localhost amavis[2536]: Found $file at /usr/bin/file
Jul 30 09:05:26 localhost amavis[2536]: No $arc, not using it
Jul 30 09:05:26 localhost amavis[2536]: Found $gzip at /bin/gzip
Jul 30 09:05:26 localhost amavis[2536]: Found $bzip2 at /usr/bin/bzip2
Jul 30 09:05:26 localhost amavis[2536]: No $lzop, not using it
Jul 30 09:05:26 localhost amavis[2536]: No $lha, not using it
Jul 30 09:05:26 localhost amavis[2536]: Found $unarj at /usr/bin/arj
Jul 30 09:05:26 localhost amavis[2536]: Found $uncompress at /bin/uncompress
Jul 30 09:05:26 localhost amavis[2536]: No $unfreeze, not using it
Jul 30 09:05:26 localhost amavis[2536]: No $unrar, not using it
Jul 30 09:05:26 localhost amavis[2536]: Found $zoo at /usr/bin/zoo
Jul 30 09:05:26 localhost amavis[2536]: Found $cpio at /bin/cpio
Jul 30 09:05:26 localhost amavis[2536]: Using internal av scanner code for (primary) Clam Antivirus-clamd
Jul 30 09:05:26 localhost amavis[2536]: Found secondary av scanner Clam Antivirus - clamscan at /usr/bin/clamscan


For the time being I've commented out the amavis line in /etc/postfix/main.cf to disable it and so far everything seems to be working. (minus virus scanning)

In all honesty, I've never had amavis work 100% correctly on any machine I've used it. I'd be interested in hearing alternative ways to get clamav scanning.

[Mustang Matt]

I may have found the solution here:
http://www.freespamfilter.org/forum/viewtopic.php?p=1342&sid=9284826f3bda10e476c0a9f23c0947ee

Downgrade Net::Server to 0.90. I'm about to try it as soon as I figure out how to do that with cpan. I'll post my results.

Update: It worked! amavisd-new-20030616-p10 REQUIRES Net::Server 0.90 and not something newer.

Onto the next error:

Jul 30 10:06:07 localhost amavis[5072]: (05072-01) Clam Antivirus-clamd FAILED - unknown status: /var/lib/amavis/amavis-20060730T100607-05072/parts: lstat() failed. ERROR\n
Jul 30 10:06:07 localhost amavis[5072]: (05072-01) WARN: all primary virus scanners failed, considering backups

[falko]

Are you sure you followed the tutorial as close as possible? It has always worked for me exactly as described there.

I may have found the solution here:
Onto the next error:

Jul 30 10:06:07 localhost amavis[5072]: (05072-01) Clam Antivirus-clamd FAILED - unknown status: /var/lib/amavis/amavis-20060730T100607-05072/parts: lstat() failed. ERROR\n
Jul 30 10:06:07 localhost amavis[5072]: (05072-01) WARN: all primary virus scanners failed, considering backupsIt seems as if clamd isn't running. You can check with ps auxStart it, if necessary.

[Mustang Matt]

I believe I followed it very closely and I've gone through it several times double checking but it's certainly possible I've missed something.

clamav is running and I do get a different error if I shut it down.

I'm not too concerned since the backup scanner is working but I'm going to try and trouble shoot it a bit more tonight.

A couple of questions for you though... I had to change a line in /etc/default/spamassassin. I can't remember the variable off the top of my head but I had to change it from 0 to 1 for spamd to start. Did I miss this from the tutorial?

I'm also not seeing the spamassassin header in received emails. I do see the amavis header. Should I see a spamassassin header? I was assuming it would write the score.

It almost seems as if email isn't getting filtered through SA.

[Mustang Matt]

The solution to my clamav-daemon error was to add a line to the bottom of /etc/clamav/clamd.conf:
AllowSupplementaryGroups

Now I need to go re-read the tutorial and see if that was missing or if I messed up. :)