amavis loads the LDAP driver, but fails to connect. Have you tried to make the same connect and query on command line using the ldapsearch command?
p@rick * Joy via amavis-users <[email protected]>: > Dear Expert, > I am trying to setup amavisd-new against ldap on local > system. my ldap is working perfectly against all module like smtp, imap and > pop3 but when configuring amavisd-new to use ldap getting the following > error in mail delivery:- > > Please help me to resolve the issue ... > > Oct 13 21:08:21.930 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) ESMTP< RCPT TO:<[email protected]> ORCPT= > rfc822;[email protected]\r\n > Oct 13 21:08:21.930 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) get_deadline switch_to_my_time(rx SMTP RCPT) - deadline in 480.0 > s, set to 336.000 s > Oct 13 21:08:21.930 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) prolong_timer switch_to_my_time(rx SMTP RCPT): timer 336, was > 480, deadline in 480.0 s > Oct 13 21:08:21.931 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) lookup => undef, "[email protected]", no lookup tables > Oct 13 21:08:21.931 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) lookup_acl([email protected]) matches key " > springbirds.co.in", result=1 > Oct 13 21:08:21.932 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) lookup [local_domains] => true, "[email protected]" > matches, result="1", matching_key="springbirds.co.in" > Oct 13 21:08:21.932 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) query_keys: [email protected], postmaster, @ > springbirds.co.in, @.springbirds.co.in, @.co.in, @.in, @. > Oct 13 21:08:21.933 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) lookup_ldap "[email protected]", query keys: " > [email protected]", "postmaster", "@springbirds.co.in", "@. > springbirds.co.in", "@.co.in", "@.in", "@.", base: > o=domains,dc=silvereye,dc=co, filter: > (&(objectClass=mailUser)(objectClass=amavisAccount)(accountStatus=active)(|(mail=%m)(shadowAddress=%m))) > Oct 13 21:08:21.933 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) ldap begin_work > Oct 13 21:08:21.933 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) Connecting to LDAP server > Oct 13 21:08:21.933 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) connect_to_ldap: trying 127.0.0.1 > Oct 13 21:08:21.934 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) (!)connect_to_ldap: unable to connect to host 127.0.0.1 > Oct 13 21:08:21.935 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) (!!)TROUBLE in process_request: connect_to_ldap: unable to > connect at (eval 116) line 145. > Oct 13 21:08:21.935 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) (!)Requesting process rundown after fatal error > Oct 13 21:08:21.935 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) ESMTP> 421 4.3.2 Service shutting down, closing channel > Oct 13 21:08:21.935 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) switch_to_client_time 480 s, smtp response sent > Oct 13 21:08:21.935 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) TempDir::DESTROY called > Oct 13 21:08:21.936 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) TempDir removal: empty tempdir is being removed: > /var/lib/amavis/tmp/amavis-20131013T210821-04014-BIHk8Dzm, nothing to > preserve > Oct 13 21:08:21.936 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) rmdir_recursively: > /var/lib/amavis/tmp/amavis-20131013T210821-04014-BIHk8Dzm, excl= > Oct 13 21:08:21.939 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) exiting process_request > Oct 13 21:08:21.939 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) idle_proc, bye: was busy, 9.6 ms, total idle 0.002 s, busy 0.028 > s > Oct 13 21:08:21.940 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) load: 95 %, total idle 0.002 s, busy 0.028 s > Oct 13 21:08:21.940 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) SA rundown_child (0) > Oct 13 21:08:21.941 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) SpamControl: rundown_child on SpamAssassin done > Oct 13 21:08:21.941 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) child_finish_hook: invoking DESTROY methods > Oct 13 21:08:21.942 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) Amavis::Out::SQL::Log DESTROY called > Oct 13 21:08:21.942 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) Amavis::Out::SQL::Connection DESTROY called > Oct 13 21:08:21.942 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) Amavis::DB::SNMP DESTROY called > Oct 13 21:08:21.995 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) Net::Server: Child leaving (20) > Oct 13 21:08:22.001 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) Amavis::LDAP::Connection DESTROY called > Oct 13 21:08:22.001 mx1.silvereye.co /usr/sbin/amavisd-new[4014]: > (04014-01) Amavis::Lookup::LDAP DESTROY called > Oct 13 21:08:22.051 mx1.silvereye.co /usr/sbin/amavisd-new[4003]: > Net::Server: Starting "1" children > Oct 13 21:08:22.057 mx1.silvereye.co /usr/sbin/amavisd-new[4021]: > Net::Server: Child Preforked (4021) > Oct 13 21:08:22.058 mx1.silvereye.co /usr/sbin/amavisd-new[4021]: entered > child_init_hook > Oct 13 21:08:22.066 mx1.silvereye.co /usr/sbin/amavisd-new[4021]: only > storage connections to SQL, no lookups > Oct 13 21:08:22.067 mx1.silvereye.co /usr/sbin/amavisd-new[4021]: > SpamControl: init_child on SpamAssassin done > > Here is the Startup details of amavisd-new :- > > Oct 13 21:11:43 mx1 amavis[4039]: starting. /usr/sbin/amavisd-new at > mx1.silvereye.co amavisd-new-2.7.1 (20120429), Unicode aware, LANG="en_IN" > Oct 13 21:11:43 mx1 amavis[4046]: Net::Server: Group Not Defined. > Defaulting to EGID '111 111' > Oct 13 21:11:43 mx1 amavis[4046]: Net::Server: User Not Defined. > Defaulting to EUID '107' > Oct 13 21:11:43 mx1 amavis[4046]: Module Amavis::Conf 2.303 > Oct 13 21:11:43 mx1 amavis[4046]: Module Archive::Zip 1.30 > Oct 13 21:11:43 mx1 amavis[4046]: Module Authen::SASL 2.16 > Oct 13 21:11:43 mx1 amavis[4046]: Module BerkeleyDB 0.51 > Oct 13 21:11:43 mx1 amavis[4046]: Module Compress::Zlib 2.033 > Oct 13 21:11:43 mx1 amavis[4046]: Module Convert::TNEF 0.17 > Oct 13 21:11:43 mx1 amavis[4046]: Module Convert::UUlib 1.4 > Oct 13 21:11:43 mx1 amavis[4046]: Module Crypt::OpenSSL::RSA 0.28 > Oct 13 21:11:43 mx1 amavis[4046]: Module DBD::mysql 4.021 > Oct 13 21:11:43 mx1 amavis[4046]: Module DBI 1.628 > Oct 13 21:11:43 mx1 amavis[4046]: Module DB_File 1.821 > Oct 13 21:11:43 mx1 amavis[4046]: Module Digest::MD5 2.51 > Oct 13 21:11:43 mx1 amavis[4046]: Module Digest::SHA 5.61 > Oct 13 21:11:43 mx1 amavis[4046]: Module File::Temp 0.22 > Oct 13 21:11:43 mx1 amavis[4046]: Module IO::Socket::INET6 2.71 > Oct 13 21:11:43 mx1 amavis[4046]: Module MIME::Entity 5.503 > Oct 13 21:11:43 mx1 amavis[4046]: Module MIME::Parser 5.503 > Oct 13 21:11:43 mx1 amavis[4046]: Module MIME::Tools 5.503 > Oct 13 21:11:43 mx1 amavis[4046]: Module Mail::DKIM::Signer 0.4 > Oct 13 21:11:43 mx1 amavis[4046]: Module Mail::DKIM::Verifier 0.4 > Oct 13 21:11:43 mx1 amavis[4046]: Module Mail::Header 2.09 > Oct 13 21:11:43 mx1 amavis[4046]: Module Mail::Internet 2.09 > Oct 13 21:11:43 mx1 amavis[4046]: Module Mail::SPF v2.009 > Oct 13 21:11:43 mx1 amavis[4046]: Module Mail::SpamAssassin 3.003002 > Oct 13 21:11:43 mx1 amavis[4046]: Module Net::DNS 0.72 > Oct 13 21:11:43 mx1 amavis[4046]: Module Net::LDAP 0.57 > Oct 13 21:11:43 mx1 amavis[4046]: Module Net::Server 2.006 > Oct 13 21:11:43 mx1 amavis[4046]: Module NetAddr::IP 4.071 > Oct 13 21:11:43 mx1 amavis[4046]: Module Socket6 0.23 > Oct 13 21:11:43 mx1 amavis[4046]: Module Time::HiRes 1.972101 > Oct 13 21:11:43 mx1 amavis[4046]: Module URI 1.60 > Oct 13 21:11:43 mx1 amavis[4046]: Module Unix::Syslog 1.1 > Oct 13 21:11:43 mx1 amavis[4046]: Amavis::DB code loaded > Oct 13 21:11:43 mx1 amavis[4046]: SQL base code loaded > Oct 13 21:11:43 mx1 amavis[4046]: SQL::Log code loaded > Oct 13 21:11:43 mx1 amavis[4046]: SQL::Quarantine NOT loaded > Oct 13 21:11:43 mx1 amavis[4046]: Lookup::SQL code NOT loaded > Oct 13 21:11:43 mx1 amavis[4046]: Lookup::LDAP code loaded > Oct 13 21:11:43 mx1 amavis[4046]: AM.PDP-in proto code loaded > Oct 13 21:11:43 mx1 amavis[4046]: SMTP-in proto code loaded > Oct 13 21:11:43 mx1 amavis[4046]: Courier proto code NOT loaded > Oct 13 21:11:43 mx1 amavis[4046]: SMTP-out proto code loaded > Oct 13 21:11:43 mx1 amavis[4046]: Pipe-out proto code NOT loaded > Oct 13 21:11:43 mx1 amavis[4046]: BSMTP-out proto code NOT loaded > Oct 13 21:11:43 mx1 amavis[4046]: Local-out proto code loaded > Oct 13 21:11:43 mx1 amavis[4046]: OS_Fingerprint code NOT loaded > Oct 13 21:11:43 mx1 amavis[4046]: ANTI-VIRUS code loaded > Oct 13 21:11:43 mx1 amavis[4046]: ANTI-SPAM code loaded > Oct 13 21:11:43 mx1 amavis[4046]: ANTI-SPAM-EXT code NOT loaded > Oct 13 21:11:43 mx1 amavis[4046]: ANTI-SPAM-C code NOT loaded > Oct 13 21:11:43 mx1 amavis[4046]: ANTI-SPAM-SA code loaded > Oct 13 21:11:43 mx1 amavis[4046]: Unpackers code loaded > Oct 13 21:11:43 mx1 amavis[4046]: DKIM code loaded > Oct 13 21:11:43 mx1 amavis[4046]: Tools code NOT loaded > Oct 13 21:11:43 mx1 amavis[4046]: Found $file at /usr/bin/file > Oct 13 21:11:43 mx1 amavis[4046]: Found $altermime at > /usr/bin/altermime > Oct 13 21:11:43 mx1 amavis[4046]: Internal decoder for .mail > Oct 13 21:11:43 mx1 amavis[4046]: No decoder for .F > Oct 13 21:11:43 mx1 amavis[4046]: Found decoder for .Z at > /bin/uncompress > Oct 13 21:11:43 mx1 amavis[4046]: Internal decoder for .gz > Oct 13 21:11:43 mx1 amavis[4046]: Found decoder for .bz2 at /bin/bzip2 > -d > Oct 13 21:11:43 mx1 amavis[4046]: Found decoder for .xz at /usr/bin/xz > -dc > Oct 13 21:11:43 mx1 amavis[4046]: Found decoder for .lzma at /usr/bin/xz > -dc --format=lzma > Oct 13 21:11:43 mx1 amavis[4046]: Found decoder for .lzo at > /usr/bin/lzop -d > Oct 13 21:11:43 mx1 amavis[4046]: No decoder for .rpm tried: > rpm2cpio.pl, rpm2cpio > Oct 13 21:11:43 mx1 amavis[4046]: Found decoder for .cpio at /bin/pax > Oct 13 21:11:43 mx1 amavis[4046]: Found decoder for .tar at /bin/pax > Oct 13 21:11:43 mx1 amavis[4046]: Found decoder for .deb at /usr/bin/ar > Oct 13 21:11:43 mx1 amavis[4046]: Internal decoder for .zip > Oct 13 21:11:43 mx1 amavis[4046]: Internal decoder for .kmz > Oct 13 21:11:43 mx1 amavis[4046]: Found decoder for .7z at /usr/bin/7zr > Oct 13 21:11:43 mx1 amavis[4046]: Found decoder for .rar at > /usr/bin/unrar-free > Oct 13 21:11:43 mx1 amavis[4046]: Found decoder for .arj at /usr/bin/arj > Oct 13 21:11:43 mx1 amavis[4046]: Found decoder for .arc at > /usr/bin/nomarch > Oct 13 21:11:43 mx1 amavis[4046]: Found decoder for .zoo at /usr/bin/zoo > Oct 13 21:11:43 mx1 amavis[4046]: Found decoder for .doc at > /usr/bin/ripole > Oct 13 21:11:43 mx1 amavis[4046]: Found decoder for .cab at > /usr/bin/cabextract > Oct 13 21:11:43 mx1 amavis[4046]: No decoder for .tnef > Oct 13 21:11:43 mx1 amavis[4046]: Internal decoder for .tnef > Oct 13 21:11:43 mx1 amavis[4046]: Found decoder for .exe at > /usr/bin/unrar-free; /usr/bin/arj > Oct 13 21:11:43 mx1 amavis[4046]: Using primary internal av scanner code > for ClamAV-clamd > Oct 13 21:11:43 mx1 amavis[4046]: Found secondary av scanner > ClamAV-clamscan at /usr/local/bin/clamscan > Oct 13 21:11:43 mx1 amavis[4046]: Deleting db files > __db.003,__db.002,snmp.db,__db.004,__db.001,nanny.db in /var/lib/amavis/db > Oct 13 21:11:43 mx1 amavis[4046]: Creating db in /var/lib/amavis/db/; > BerkeleyDB 0.51, libdb 5.1 -- [*] sys4 AG http://sys4.de, +49 (89) 30 90 46 64 Franziskanerstraße 15, 81669 München Sitz der Gesellschaft: München, Amtsgericht München: HRB 199263 Vorstand: Patrick Ben Koetter, Axel von der Ohe, Marc Schiffbauer Aufsichtsratsvorsitzender: Florian Kirstein
