Re: [AMaViS-user] status=deferred
Hi, I don't know what has happened to my Solaris 9 (built-in) Perl 5.6.1 install but switching back to the older Digest::MD5 (2.33) and trying to get my old, formerly working Amavisd-new 2.33 (A coincidence, I assure you) setup running was a failure. I upgraded a bunch of Perl modules at the beginning of this exercise to just be at the latest level of everything before trying to get Amavisd-new 2.4.0 to work. I did eliminate BerkeleyDB as a suspect by turning off db in the amavisd.conf. I've since turned it back on. I'm at a loss for tracking this one down exactly but the problem has been traced to something in Digest::MD5 being broken or incompatible with Perl 5.6.1. That being the case, I went to SunFreeware.com and downloaded the latest Perl (5.8.7 as of 13 April 2006), put /usr/local/bin at the front of my $PATH, renamed /usr/bin/perl to /usr/bin/perl.sun, linked /usr/bin/perl to /usr/local/bin/perl and began the loong process of installing perl modules to get amavisd-new 2.4.0 in a working state. I am getting some errors/warnings with SpamAssassin which I need to track down but Amavisd-new 2.40 is now working. Maybe this is for the best, so I will stick with this SunFreeware Perl package for the time being. Marc, thanks for all you help through this process. Cheers, Mark Martinec wrote: Gordon, Hi, I re-installed Digest::MD5 from scratch - make, make test, make install Ok, thanks, that eliminates one of the likely possiblities. The other is: Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Creating db in /var/amavis/db/; BerkeleyDB 0.27, libdb 3.3 Most people are now running libdb 4.2 or later. It may even work with 3.3, but experience is scarce. Also, there might be a discrepancy between the library and include files of libdb, so that BerkeleyDB installation may have gotten it wrong. Apr 11 10:23:16 isis.eng.fsu.edu /usr/local/sbin/amavisd[15532]: (15532-01) ESMTP< MAIL FROM:<[EMAIL PROTECTED]> SIZE=4323\r\n Apr 11 10:23:16 isis.eng.fsu.edu /usr/local/sbin/amavisd[15532]: (15532-01) prolong_timer SMTP MAIL received: timer set to = 300 s Apr 11 10:23:16 isis.eng.fsu.edu /usr/local/sbin/amavisd[15532]: (15532-01) check_mail_begin_task: task_count=1 Apr 11 10:23:16 isis.eng.fsu.edu /usr/local/sbin/amavisd[15532]: (15532-01) TempDir::prepare: creating directory /var/amavis/tmp/amavis-20060411T102316-15532 Hm, the next thing should have been: TempDir::prepare_file: creating file Apr 11 10:23:16 isis.eng.fsu.edu /usr/local/sbin/amavisd[15534]: Net::Server: 2006/04/11-10:23:16 CONNECT TCP Peer: "127.0.0.1:41876" Something fatal happened to process 15532, and a substitute process was created automatically after it vanished. Was your log collected from a (syslog)file or did you run 'amavisd debug'? The later may be able to utter some final message on stderr. Running with strace -f could show what were the last system calls before a process crash. Mark --- This SF.Net email is sponsored by xPML, a groundbreaking scripting language that extends applications into web and mobile media. Attend the live webcast and join the prime developer group breaking into this new coding territory! http://sel.as-us.falkag.net/sel?cmd=lnk&kid=110944&bid=241720&dat=121642 ___ AMaViS-user mailing list AMaViS-user@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/amavis-user AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3 AMaViS-HowTos:http://www.amavis.org/howto/
Re: [AMaViS-user] status=deferred
Gordon,
> Interestingly, if I test things from a logon window I see the following:
> Apr 11 14:25:54 isis genunix: NOTICE: core_log: amavisd[27426] setid
> process, core not dumped:
It is just a confirmation of what we already know,
that a process is crashing of unnatural death.
> > Most weird. Between "creating file" and returning a SMTP status
> > there is hardly any significant processing going on.
> > If policy bank MYNETS exists and @mynetworks_maps is defined
> > there would be a call to lookup_ip_acl() with its own log entry,
> > and after that a lookup on sender address against @debug_sender_maps.
>
> I don't define MYNETS or debug_sender_maps. I just took the
> amavisd.conf-sample and set hostname, domain, Postfix MTA, ClamAV,
> logging, policy for SPAM=PASS, and set banned to warn sender/receiver.
> That's about it. Everything else I left as-is.
Mail hasn't even been received yet, the event occurs
just after sender's address has been received.
> # truss -f amavisd -u amavis debug
Yes, this is the most promising way to go about diagnosing
that particular problem.
> 8248: fcntl(11, F_SETFD, 0x0001) = 0
> 8248: fstat64(11, 0xFFBFF4F0) = 0
> 8248: time() = 1144780741
> Apr 11 14:39:01 isis.eng.fsu.edu /usr/local/sbin/amavisd[8248]: 8248:
> write(2, " A p r 1 1 1 4 : 3 9".., 64) = 64
> TIMING [total 32 ms] - bdb-open: 32 (100%)100, rundown: 0 (0%)1008248:
> write(2, " T I M I N G [ t o t a".., 65) = 65
> 8248: write(2, "\n", 1) = 1
> 8248: sigaction(SIGCLD, 0xFFBFF7A0, 0xFFBFF820) = 0
> 8248: open64("/var/amavis/amavisd.lock", O_WRONLY|O_CREAT|O_TRUNC,
> 0666) = 12
> 8248: fstat64(12, 0xFF31D390) = 0
> 8248: fcntl(12, F_SETFD, 0x0001) = 0
> 8246: poll(0xFFBFF900, 2, -1) (sleeping...)
> 8243: poll(0xFFBFF940, 0, 1) (sleeping...)
Yes, and what comes next when a message starts arriving?
This can amount to a lengthy trace, so either select and post only the
relevant part, just after client logs "TempDir::prepare_file: creating file",
or put it on some http/ftp server for pickup. (private mail is another
option).
Mark
---
This SF.Net email is sponsored by xPML, a groundbreaking scripting language
that extends applications into web and mobile media. Attend the live webcast
and join the prime developer group breaking into this new coding territory!
http://sel.as-us.falkag.net/sel?cmd=lnk&kid=110944&bid=241720&dat=121642
___
AMaViS-user mailing list
AMaViS-user@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/
Re: [AMaViS-user] status=deferred
Hi, Mark Martinec wrote: Apr 11 13:49:04 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Net::Server: Starting "1" children Most weird. Between "creating file" and returning a SMTP status there is hardly any significant processing going on. If policy bank MYNETS exists and @mynetworks_maps is defined there would be a call to lookup_ip_acl() with its own log entry, and after that a lookup on sender address against @debug_sender_maps. I don't define MYNETS or debug_sender_maps. I just took the amavisd.conf-sample and set hostname, domain, Postfix MTA, ClamAV, logging, policy for SPAM=PASS, and set banned to warn sender/receiver. That's about it. Everything else I left as-is. --- This SF.Net email is sponsored by xPML, a groundbreaking scripting language that extends applications into web and mobile media. Attend the live webcast and join the prime developer group breaking into this new coding territory! http://sel.as-us.falkag.net/sel?cmd=lnk&kid=110944&bid=241720&dat=121642 ___ AMaViS-user mailing list AMaViS-user@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/amavis-user AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3 AMaViS-HowTos:http://www.amavis.org/howto/
Re: [AMaViS-user] status=deferred
Gordon, > Hi, I've upgraded to BerkeleyDB-4.2 but still the problem persists. > Basically, I downloaded the db4.2 package from sunfreeware, installed > it, created a symlink from /usr/local/Berkeley-4.2 to > /usr/local/BerkeleyDB, then added more symlinks to the relevant libs and > includes in /usr/local/lib (libdb-4.2.a, libdb-4.2.so, libdb-4.so, > libdb.a and libdb.so) and /usr/local/include (db.h and db_185.h), as > compiling under Solaris finds things better using this method > (BerkeleyDB and OpensSSL specifically). I have removed the old > BerkeleyDB-3x symlinks. > Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Creating > db in /var/amavis/db/; BerkeleyDB 0.27, libdb 4.2 Looks good. (for the archive: as a quick test, $enable_db=0 would also eliminate the possibility that libdb/BerkeleyDB is broken) > Apr 11 13:49:04 isis.eng.fsu.edu /usr/local/sbin/amavisd[8987]: > (08987-01) TempDir::prepare: creating directory > /var/amavis/tmp/amavis-20060411T134904-08987 > Apr 11 13:49:04 isis.eng.fsu.edu /usr/local/sbin/amavisd[8987]: > (08987-01) TempDir::prepare_file: creating file > /var/amavis/tmp/amavis-20060411T134904-08987/email.txt We have "TempDir::prepare_file: creating file" this time. Could have been just lost in the buffer in your previous log. > Apr 11 13:49:04 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: > Net::Server: Starting "1" children Most weird. Between "creating file" and returning a SMTP status there is hardly any significant processing going on. If policy bank MYNETS exists and @mynetworks_maps is defined there would be a call to lookup_ip_acl() with its own log entry, and after that a lookup on sender address against @debug_sender_maps. All this processing is pure Perl code, so unless there is a bug in Perl itself (yours is 5.6.1, pretty ancient), there couldn't be any process crash provoked by pure Perl code. I'm running out of ideas. Is there anything like truss or strace on Solaris to trace system calls in the child process? Perhaps you are running out of some tight resource limit. Mark --- This SF.Net email is sponsored by xPML, a groundbreaking scripting language that extends applications into web and mobile media. Attend the live webcast and join the prime developer group breaking into this new coding territory! http://sel.as-us.falkag.net/sel?cmd=lnk&kid=110944&bid=241720&dat=121642 ___ AMaViS-user mailing list AMaViS-user@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/amavis-user AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3 AMaViS-HowTos:http://www.amavis.org/howto/
Re: [AMaViS-user] status=deferred
# truss -f amavisd -u amavis debug
<... blah blah blah
... startup stuff
... towards the end of initialization of amavisd >
Apr 11 14:39:01 isis.eng.fsu.edu /usr/local/sbin/amavisd[8243]: 8243:
write(2, " A p r 1 1 1 4 : 3 9".., 64) = 64
Net::Server: Starting "2" children8243: write(2, " N e t : : S e r v e r
:".., 34) = 34
8243: write(2, "\n", 1) = 1
8243: sigaction(SIGCLD, 0xFFBFF7A0, 0xFFBFF820) = 0
8243: llseek(4, 0, SEEK_CUR) Err#29 ESPIPE
8243: llseek(7, 0, SEEK_CUR) Err#29 ESPIPE
8243: fork() = 8246
8246: fork() (returning as child ...)= 8243
8246: getpid()= 8246 [8243]
8243: llseek(4, 0, SEEK_CUR) Err#29 ESPIPE
8243: llseek(7, 0, SEEK_CUR) Err#29 ESPIPE
8246: sigaction(SIGQUIT, 0xFFBFF800, 0xFFBFF880) = 0
8246: sigaction(SIGTERM, 0xFFBFF800, 0xFFBFF880) = 0
8246: sigaction(SIGINT, 0xFFBFF800, 0xFFBFF880) = 0
8246: sigaction(SIGPIPE, 0xFFBFF800, 0xFFBFF880) = 0
8246: sigaction(SIGCLD, 0xFFBFF800, 0xFFBFF880) = 0
8246: sigaction(SIGHUP, 0xFFBFF800, 0xFFBFF880) = 0
8246: sigaction(SIGCLD, 0xFFBFF798, 0xFFBFF818) = 0
8246: sigaction(SIGCLD, 0xFFBFF800, 0xFFBFF880) = 0
8243: fork() = 8248
8246: time() = 1144780741
Apr 11 14:39:01 isis.eng.fsu.edu /usr/local/sbin/amavisd[8246]: 8246:
write(2, " A p r 1 1 1 4 : 3 9".., 64) = 64
Net::Server: Child Preforked (8246)8246:write(2, " N e t : : S e
r v e r :".., 35) = 35
8246: write(2, "\n", 1) = 1
8246: sigaction(SIGCLD, 0xFFBFF7A0, 0xFFBFF820) = 0
8246: sigaction(SIGCLD, 0xFFBFF798, 0xFFBFF818) = 0
8246: sigaction(SIGCLD, 0xFFBFF800, 0xFFBFF880) = 0
8246: fstat(3, 0xFFBFF878)= 0
8246: close(3)= 0
8246: fstat(-1, 0xFFBFF870) Err#9 EBADF
8246: open("/dev/conslog", O_WRONLY) = 3
8246: fcntl(3, F_SETFD, 0x0001) = 0
8246: fstat(3, 0xFFBFF870)= 0
8248: fork() (returning as child ...)= 8243
8248: getpid()= 8248 [8243]
8246: sysconfig(_CONFIG_NPROC_ONLN) = 2
8246: stat64("/var/amavis/db/DB_CONFIG", 0xFFBFF5D8) Err#2 ENOENT
8246: open64("/var/amavis/db/DB_CONFIG", O_RDONLY)Err#2 ENOENT
8246: stat64("/var/tmp", 0xFFBFF5D8) = 0
8246: stat64("/var/amavis/db/__db.001", 0xFFBFF640) = 0
8246: open64("/var/amavis/db/__db.001", O_RDWR) = 8
8246: fcntl(8, F_SETFD, 0x0001) = 0
8246: ioctl(8, 0x2000664C, 0x0001)= 0
8246: fstat64(8, 0xFFBFF6B8) = 0
8246: close(8)= 0
8246: open64("/var/amavis/db/__db.001", O_RDWR) = 8
8246: fcntl(8, F_SETFD, 0x0001) = 0
8246: ioctl(8, 0x2000664C, 0x0001)= 0
8246: mmap64(0x, 8192, PROT_READ|PROT_WRITE, MAP_SHARED, 8, 0)
= 0xFF33
8246: close(8)= 0
8246: stat64("/var/amavis/db/__db.002", 0xFFBFF620) = 0
8246: open64("/var/amavis/db/__db.002", O_RDWR) = 8
8246: fcntl(8, F_SETFD, 0x0001) = 0
8246: ioctl(8, 0x2000664C, 0x0001)= 0
8246: mmap64(0x, 270336, PROT_READ|PROT_WRITE, MAP_SHARED, 8,
0) = 0xFEA6
8246: close(8)= 0
8246: stat64("/var/amavis/db/__db.003", 0xFFBFF640) = 0
8246: open64("/var/amavis/db/__db.003", O_RDWR) = 8
8246: fcntl(8, F_SETFD, 0x0001) = 0
8246: ioctl(8, 0x2000664C, 0x0001)= 0
8246: mmap64(0x, 409600, PROT_READ|PROT_WRITE, MAP_SHARED, 8,
0) = 0xFE9F
8246: close(8)= 0
8248: sigaction(SIGQUIT, 0xFFBFF800, 0xFFBFF880) = 0
8248: sigaction(SIGTERM, 0xFFBFF800, 0xFFBFF880) = 0
8248: sigaction(SIGINT, 0xFFBFF800, 0xFFBFF880) = 0
8248: sigaction(SIGPIPE, 0xFFBFF800, 0xFFBFF880) = 0
8248: sigaction(SIGCLD, 0xFFBFF800, 0xFFBFF880) = 0
8248: sigaction(SIGHUP, 0xFFBFF800, 0xFFBFF880) = 0
8246: stat64("/var/amavis/db/snmp.db", 0xFFBFF348)= 0
8246: stat64("/var/amavis/db/snmp.db", 0xFFBFF3C0)= 0
8246: open64("/var/amavis/db/snmp.db", O_RDWR)= 8
8246: fcntl(8, F_SETFD, 0x0001) = 0
8246: read(8, "\0\0\0\0\0\0\001\0\0\0\0".., 512) = 512
8246: close(8)= 0
8246: stat64("/var/amavis
Re: [AMaViS-user] status=deferred
Interestingly, if I test things from a logon window I see the following: # postsuper -r ALL postsuper: Requeued: 6 messages Apr 11 14:25:54 isis genunix: NOTICE: core_log: amavisd[27426] setid process, core not dumped: /var/core/core.amavisd.27426.isis.11369.184.1144779954 Apr 11 14:25:54 isis genunix: NOTICE: core_log: amavisd[27427] setid process, core not dumped: /var/core/core.amavisd.27427.isis.11369.184.1144779954 Apr 11 14:25:54 isis genunix: NOTICE: core_log: amavisd[28213] setid process, core not dumped: /var/core/core.amavisd.28213.isis.11369.184.1144779954 Apr 11 14:25:55 isis genunix: NOTICE: core_log: amavisd[28212] setid process, core not dumped: /var/core/core.amavisd.28212.isis.11369.184.1144779955 Apr 11 14:25:55 isis genunix: NOTICE: core_log: amavisd[28215] setid process, core not dumped: /var/core/core.amavisd.28215.isis.11369.184.1144779955 --- This SF.Net email is sponsored by xPML, a groundbreaking scripting language that extends applications into web and mobile media. Attend the live webcast and join the prime developer group breaking into this new coding territory! http://sel.as-us.falkag.net/sel?cmd=lnk&kid=110944&bid=241720&dat=121642 ___ AMaViS-user mailing list AMaViS-user@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/amavis-user AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3 AMaViS-HowTos:http://www.amavis.org/howto/
Re: [AMaViS-user] status=deferred
Solaris 9 Amavisd-New 2.4.0 Hi, I've upgraded to BerkeleyDB-4.2 but still the problem persists. Basically, I downloaded the db4.2 package from sunfreeware, installed it, created a symlink from /usr/local/Berkeley-4.2 to /usr/local/BerkeleyDB, then added more symlinks to the relevant libs and includes in /usr/local/lib (libdb-4.2.a, libdb-4.2.so, libdb-4.so, libdb.a and libdb.so) and /usr/local/include (db.h and db_185.h), as compiling under Solaris finds things better using this method (BerkeleyDB and OpensSSL specifically). I have removed the old BerkeleyDB-3x symlinks. To make this point clear: # ls -l /usr/local/lib/libdb* lrwxrwxrwx 1 root other 37 Apr 11 13:04 /usr/local/lib/libdb-4.2.a -> /usr/local/BerkeleyDB/lib/libdb-4.2.a lrwxrwxrwx 1 root other 38 Apr 11 13:04 /usr/local/lib/libdb-4.2.so -> /usr/local/BerkeleyDB/lib/libdb-4.2.so* lrwxrwxrwx 1 root other 36 Apr 11 13:04 /usr/local/lib/libdb-4.so -> /usr/local/BerkeleyDB/lib/libdb-4.so* lrwxrwxrwx 1 root other 33 Apr 11 13:04 /usr/local/lib/libdb.a -> /usr/local/BerkeleyDB/lib/libdb.a lrwxrwxrwx 1 root other 34 Apr 11 13:04 /usr/local/lib/libdb.so -> /usr/local/BerkeleyDB/lib/libdb.so* # ls -l /usr/local/include/db.h /usr/local/include/db_185.h lrwxrwxrwx 1 root other 34 Jun 3 2005 /usr/local/include/db.h -> /usr/local/BerkeleyDB/include/db.h lrwxrwxrwx 1 root other 38 Jun 3 2005 /usr/local/include/db_185.h -> /usr/local/BerkeleyDB/include/db_185.h I've always been testing using amavisd debug. Here is the latest output with logging set to level 5: # amavisd -u amavis debug Apr 11 13:22:08 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: starting. /usr/local/sbin/amavisd at isis.eng.fsu.edu amavisd-new-2.4.0 (20060403) Apr 11 13:22:08 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: user=amavis, EUID: 11369 (11369); group=184, EGID: 184 184 (184 184); log_level=5 Apr 11 13:22:08 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Perl version 5.006001 Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: INFO: no optional modules: DBD::mysql Sys::Hostname::Long Mail::SPF::Query Net::CIDR::Lite Mail::SpamAssassin::Plugin::DomainKeys Mail::DomainKeys::Header Mail::DomainKeys::Message Mail::DomainKeys::Policy Mail::DomainKeys::Signature Mail::DomainKeys::Key Mail::DomainKeys::Key::Public Crypt::OpenSSL::RSA auto::Crypt::OpenSSL::RSA::new_public_key auto::Crypt::OpenSSL::RSA::load_public_key auto::Crypt::OpenSSL::RSA::_new auto::Crypt::OpenSSL::RSA::DESTROY IP::Country::Fast Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: SpamControl: init_pre_chroot done Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Net::Server: 2006/04/11-13:22:09 Amavis (type Net::Server::PreForkSimple) starting! pid(8984)Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Net::Server: Binding to UNIX socket file /var/amavis/amavisd.sock using SOCK_STREAM Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Net::Server: Binding to TCP port 10024 on host 127.0.0.1 Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Net::Server: Group Not Defined. Defaulting to EGID '184 184' Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Net::Server: User Not Defined. Defaulting to EUID '11369' Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Net::Server: Setting up serialization via flock Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Module Amavis::Conf2.062 Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Module Archive::Tar1.29 Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Module Archive::Zip1.16 Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Module BerkeleyDB 0.27 Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Module Compress::Zlib 1.41 Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Module Convert::TNEF 0.17 Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Module Convert::UUlib 1.06 Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Module DBI 1.47 Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Module DB_File 1.814 Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Module Digest::MD5 2.36 Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Module MIME::Entity5.420 Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Module MIME::Parser5.420 Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Module MIME::Tools 5.420 Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Module Mail::Header1.74 Apr 11 13:22:09 isis.eng.fsu.edu /usr/local/sbin/amavisd[8984]: Module Mail::Internet 1.74 Apr 11
Re: [AMaViS-user] status=deferred
Gordon, > Hi, I re-installed Digest::MD5 from scratch - make, make test, make > install Ok, thanks, that eliminates one of the likely possiblities. The other is: > Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: > Creating db in /var/amavis/db/; BerkeleyDB 0.27, libdb 3.3 Most people are now running libdb 4.2 or later. It may even work with 3.3, but experience is scarce. Also, there might be a discrepancy between the library and include files of libdb, so that BerkeleyDB installation may have gotten it wrong. > Apr 11 10:23:16 isis.eng.fsu.edu /usr/local/sbin/amavisd[15532]: > (15532-01) ESMTP< MAIL FROM:<[EMAIL PROTECTED]> SIZE=4323\r\n > Apr 11 10:23:16 isis.eng.fsu.edu /usr/local/sbin/amavisd[15532]: > (15532-01) prolong_timer SMTP MAIL received: timer set to = 300 s > Apr 11 10:23:16 isis.eng.fsu.edu /usr/local/sbin/amavisd[15532]: > (15532-01) check_mail_begin_task: task_count=1 > Apr 11 10:23:16 isis.eng.fsu.edu /usr/local/sbin/amavisd[15532]: > (15532-01) TempDir::prepare: creating directory > /var/amavis/tmp/amavis-20060411T102316-15532 Hm, the next thing should have been: TempDir::prepare_file: creating file > Apr 11 10:23:16 isis.eng.fsu.edu /usr/local/sbin/amavisd[15534]: > Net::Server: 2006/04/11-10:23:16 CONNECT TCP Peer: "127.0.0.1:41876" Something fatal happened to process 15532, and a substitute process was created automatically after it vanished. Was your log collected from a (syslog)file or did you run 'amavisd debug'? The later may be able to utter some final message on stderr. Running with strace -f could show what were the last system calls before a process crash. Mark --- This SF.Net email is sponsored by xPML, a groundbreaking scripting language that extends applications into web and mobile media. Attend the live webcast and join the prime developer group breaking into this new coding territory! http://sel.as-us.falkag.net/sel?cmd=lnk&kid=110944&bid=241720&dat=121642 ___ AMaViS-user mailing list AMaViS-user@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/amavis-user AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3 AMaViS-HowTos:http://www.amavis.org/howto/
Re: [AMaViS-user] status=deferred
Hi, I re-installed Digest::MD5 from scratch - make, make test, make install - all went well but still the same problem: Apr 11 10:23:16 isis postfix/smtp[16296]: [ID 197553 mail.info] 5533D2E8BA: to=<[EMAIL PROTECTED]>, orig_to=<[EMAIL PROTECTED]>, relay=127.0.0.1[127.0.0.1], delay=-541, status=deferred (lost connection with 127.0.0.1[127.0.0.1] while sending MAIL FROM) Apr 11 10:23:16 isis postfix/smtp[16297]: [ID 197553 mail.info] 6B2902E943: to=<[EMAIL PROTECTED]>, relay=127.0.0.1[127.0.0.1], delay=-590, status=deferred (lost connection with 127.0.0.1[127.0.0.1] while sending MAIL FROM) Apr 11 10:23:16 isis postfix/smtp[16296]: [ID 197553 mail.info] 5533D2E8BA: to=<[EMAIL PROTECTED]>, orig_to=<[EMAIL PROTECTED]>, relay=127.0.0.1[127.0.0.1], delay=-541, status=deferred (lost connection with 127.0.0.1[127.0.0.1] while sending MAIL FROM) Apr 11 10:23:17 isis postfix/smtp[16297]: [ID 197553 mail.info] 812082EA32: to=<[EMAIL PROTECTED]>, relay=127.0.0.1[127.0.0.1], delay=-833, status=deferred (lost connection with 127.0.0.1[127.0.0.1] while sending end of data -- message may be sent more than once) Mark Martinec wrote: It looks like a process 24132 dies or a horrible sudden death just before mail checking starts. Could be a problem in crypto library. Try reinstalling module Digest::MD5 and make sure to run its self-diagnostics at installation time. Mark Here is the new output from amavisd debug: # amavisd -u amavis debug Apr 11 10:22:36 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: starting. /usr/local/sbin/amavisd at isis.eng.fsu.edu amavisd-new-2.4.0 (20060403) Apr 11 10:22:36 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: user=amavis, EUID: 11369 (11369); group=184, EGID: 184 184 (184 184); log_level=4 Apr 11 10:22:36 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Perl version 5.006001 Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: INFO: no optional modules: DBD::mysql Sys::Hostname::Long Mail::SPF::Query Net::CIDR::Lite Mail::SpamAssassin::Plugin::DomainKeys Mail::DomainKeys::Header Mail::DomainKeys::Message Mail::DomainKeys::Policy Mail::DomainKeys::Signature Mail::DomainKeys::Key Mail::DomainKeys::Key::Public Crypt::OpenSSL::RSA auto::Crypt::OpenSSL::RSA::new_public_key auto::Crypt::OpenSSL::RSA::load_public_key auto::Crypt::OpenSSL::RSA::_new auto::Crypt::OpenSSL::RSA::DESTROY IP::Country::Fast Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: SpamControl: init_pre_chroot done Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Net::Server: 2006/04/11-10:22:37 Amavis (type Net::Server::PreForkSimple) starting! pid(15523) Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Net::Server: Binding to UNIX socket file /var/amavis/amavisd.sock using SOCK_STREAM Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Net::Server: Binding to TCP port 10024 on host 127.0.0.1 Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Net::Server: Group Not Defined. Defaulting to EGID '184 184' Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Net::Server: User Not Defined. Defaulting to EUID '11369' Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Net::Server: Setting up serialization via flock Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Module Amavis::Conf2.062 Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Module Archive::Tar1.29 Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Module Archive::Zip1.16 Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Module BerkeleyDB 0.27 Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Module Compress::Zlib 1.41 Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Module Convert::TNEF 0.17 Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Module Convert::UUlib 1.06 Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Module DBI 1.47 Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Module DB_File 1.811 Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Module Digest::MD5 2.36 Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Module MIME::Entity5.420 Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Module MIME::Parser5.420 Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Module MIME::Tools 5.420 Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Module Mail::Header1.74 Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Module Mail::Internet 1.74 Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Module Mail::SpamAssassin 3.001001 Apr 11 10:22:37 isis.eng.fsu.edu /usr/local/sbin/amavisd[15523]: Module Net::Cmd2.26
Re: [AMaViS-user] status=deferred
Gordon, > amavisd-new 2.4.0 > > Hi, I'm trying to debug amavisd but am a bit confused. If I telnet to > localhost 10024 or 10025 everything looks good. But the actually logs > tell a different story and mail is just building in the queue. > Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24132]: > (24132-01-2) Original mail size: 5816; quota set to: 2908000 bytes > Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[22583]: > Net::Server: Starting "1" children It looks like a process 24132 dies or a horrible sudden death just before mail checking starts. Could be a problem in crypto library. Try reinstalling module Digest::MD5 and make sure to run its self-diagnostics at installation time. Mark --- This SF.Net email is sponsored by xPML, a groundbreaking scripting language that extends applications into web and mobile media. Attend the live webcast and join the prime developer group breaking into this new coding territory! http://sel.as-us.falkag.net/sel?cmd=lnk&kid=110944&bid=241720&dat=121642 ___ AMaViS-user mailing list AMaViS-user@lists.sourceforge.net https://lists.sourceforge.net/lists/listinfo/amavis-user AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3 AMaViS-HowTos:http://www.amavis.org/howto/
[AMaViS-user] status=deferred (sorry, i forgot to include relevant info)
Sorry, here is the start of the amavisd debug output: Apr 10 15:51:40 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: starting. /usr/local/sbin/amavisd at isis.eng.fsu.edu amavisd-new-2.4.0 (20060403) Apr 10 15:51:40 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: user=amavis, EUID: 11369 (11369); group=184, EGID: 184 184 (184 184); log_level=2 Apr 10 15:51:40 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Perl version 5.006001 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: INFO: no optional modules: DBD::mysql Sys::Hostname::Long Mail::SPF::Query Net::CIDR::Lite Mail::SpamAssassin::Plugin::DomainKeys Mail::DomainKeys::Header Mail::DomainKeys::Message Mail::DomainKeys::Policy Mail::DomainKeys::Signature Mail::DomainKeys::Key Mail::DomainKeys::Key::Public Crypt::OpenSSL::RSA auto::Crypt::OpenSSL::RSA::new_public_key auto::Crypt::OpenSSL::RSA::load_public_key auto::Crypt::OpenSSL::RSA::_new auto::Crypt::OpenSSL::RSA::DESTROY IP::Country::Fast Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: SpamControl: init_pre_chroot done Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Net::Server: 2006/04/10-15:51:41 Amavis (type Net::Server::PreForkSimple) starting! pid(2669)Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Net::Server: Binding to UNIX socket file /var/amavis/amavisd.sock using SOCK_STREAM Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Net::Server: Binding to TCP port 10024 on host 127.0.0.1 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Net::Server: Group Not Defined. Defaulting to EGID '184 184' Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Net::Server: User Not Defined. Defaulting to EUID '11369' Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Net::Server: Setting up serialization via flock Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module Amavis::Conf2.062 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module Archive::Tar1.29 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module Archive::Zip1.16 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module BerkeleyDB 0.27 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module Compress::Zlib 1.41 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module Convert::TNEF 0.17 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module Convert::UUlib 1.06 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module DBI 1.47 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module DB_File 1.811 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module Digest::MD5 2.36 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module MIME::Entity5.420 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module MIME::Parser5.420 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module MIME::Tools 5.420 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module Mail::Header1.74 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module Mail::Internet 1.74 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module Mail::SpamAssassin 3.001001 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module Net::Cmd2.26 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module Net::DNS0.48 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module Net::SMTP 2.29 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module Net::Server 0.93 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module Razor2::Client::Version 2.75 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module Time::HiRes 1.66 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Module Unix::Syslog0.100 Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Amavis::DB code loaded Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Amavis::Cache code loaded Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: SQL base codeNOT loaded Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: SQL::Log codeNOT loaded Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: SQL::Quarantine NOT loaded Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Lookup::SQL code NOT loaded Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: Lookup::LDAP codeNOT loaded Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: AM.PDP-in proto code loaded Apr 10 15:51:41 isis.eng.fsu.edu /usr/local/sbin/amavisd[2669]: SMTP-in proto code lo
[AMaViS-user] status=deferred
amavisd-new 2.4.0 Hi, I'm trying to debug amavisd but am a bit confused. If I telnet to localhost 10024 or 10025 everything looks good. But the actually logs tell a different story and mail is just building in the queue. Below are the syslog output and debug output. Any help on this would be greatly appreciated. LOG MESSAGE: relay=none, delay=0, status=deferred (delivery temporarily suspended: lost connection with 127.0.0.1[127.0.0.1] while sending MAIL FROM) AMAVISD -U AMAVIS DEBUG OUTPUT: Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24134]: (24134-01) prolong_timer smtp response sent: timer set to = 120 s Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24134]: (24134-01) idle_proc, 6: was busy, 1.7 ms, total idle 0.002 s, busy 0.031 s Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24134]: (24134-01) idle_proc, 5: was idle, 0.3 ms, total idle 0.002 s, busy 0.031 s Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24132]: Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24134]: (24134-01) ESMTP< MAIL FROM:<[EMAIL PROTECTED]> SIZE=8842\r\n (24132-01-2) Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24134]: (24134-01) prolong_timer SMTP MAIL received: timer set to = 300 s ESMTP< RCPT TO:<[EMAIL PROTECTED]>\r\n Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24134]: (24134-01) check_mail_begin_task: task_count=1 Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24132]: (24132-01-2) prolong_timer SMTP RCPT received: timer set to = 300 s Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24134]: (24134-01) TempDir::prepare: creating directory /var/amavis/tmp/amavis-20060410T150216-24134Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24132]: (24132-01-2) ESMTP> 250 2.1.5 Recipient [EMAIL PROTECTED] OK Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24132]: (24132-01-2) prolong_timer smtp response sent: timer set to = 120 s Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24132]: (24132-01-2) idle_proc, 6: was busy, 5.6 ms, total idle 0.032 s, busy 2.397 s Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24132]: (24132-01-2) idle_proc, 5: was idle, 0.3 ms, total idle 0.032 s, busy 2.397 s Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24132]: (24132-01-2) ESMTP< DATA\r\n Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24132]: (24132-01-2) prolong_timer SMTP DATA received: timer set to = 300 s Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24132]: (24132-01-2) ESMTP::10024 /var/amavis/tmp/amavis-20060410T150214-24132: <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]> SIZE=5824 Received: from mymachine.mydomain ([127.0.0.1]) by localhost (mymachine.mydomain [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for <[EMAIL PROTECTED]>; Mon, 10 Apr 2006 15:02:16 -0400 (EDT) Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24132]: (24132-01-2) ESMTP> 354 End data with . Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24132]: (24132-01-2) prolong_timer smtp response sent: timer set to = 120 s Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24132]: (24132-01-2) prolong_timer receiving data: timer set to = 120 s Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24132]: (24132-01-2) prolong_timer data-end received: timer set to = 300 s Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24132]: (24132-01-2) ESMTP< . Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24132]: (24132-01-2) Actual message size 5816 B, declared 5824 B Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24132]: (24132-01-2) setting body type: 7BIT (h=0, b=0) Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24132]: (24132-01-2) body hash: 428d1d892d001710d376248b4a449d6b Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24132]: (24132-01-2) Original mail size: 5816; quota set to: 2908000 bytes Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[22583]: Net::Server: Starting "1" children Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24141]: Net::Server: Child Preforked (24141) Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[24141]: TIMING [total 15 ms] - bdb-open: 15 (99%)99, rundown: 0 (1%)100 Apr 10 15:02:16 mymachine.mydomain /usr/local/sbin/amavisd[22583]: Net::Server: Starting "1" children Apr 10 15:02:17 mymachine.mydomain /usr/local/sbin/amavisd[24142]: Net::Server: Child Preforked (24142) Apr 10 15:02:17 mymachine.mydomain /usr/local/sbin/amavisd[24142]: TIMING [total 18 ms] - bdb-open: 18 (99%)99, rundown: 0 (1%)100 --- This SF.Net email is sponsored by xPML, a groundbreaking scripting language that extends applications into web and mobile media. Attend the live webcast and join the prime developer group breaking into this new coding territory! http://sel.as-us
