1

Topic: Amavisd refusing connections on reboot

==== Required information ====
- iRedMail version (check /etc/iredmail-release): 0.9.3
- Linux/BSD distribution name and version: CentOS Linux 7.2.1511 64bit
- Store mail accounts in which backend (LDAP/MySQL/PGSQL): MySQL
- Web server (Apache or Nginx): Nginx
====

On a clean install of iRedmail on Centos 7.2 (minimal hosted on OpenVZ 4GB RAM) I noticed that amavisd refuses connections until restarted. Log example:
Dec 26 19:22:38 mail postfix/smtp[1260]: connect to 127.0.0.1[127.0.0.1]:10024: Connection refused
Dec 26 19:22:38 mail postfix/smtp[1260]: CCF52240BD9: to=<user1@domain.com>, relay=none, delay=0.16, delays=0.14/0.01/0/0, dsn=4.4.1, status=deferred (connect to 127.0.0.1[127.0.0.1]:10024: Connection refused)

The mail sent is internal: user2@domain.com to user1@domain.com
After "service amavisd restart", the mail que runs and connections are possible again.

----

Spider Email Archiver: On-Premises, lightweight email archiving software developed by iRedMail team. Supports Amazon S3 compatible storage and custom branding.

2

Re: Amavisd refusing connections on reboot

How much RAM do you have on this server? The minimal requirement is 2GB for full spam/virus scanning feature.

3

Re: Amavisd refusing connections on reboot

ZhangHuangbin wrote:

How much RAM do you have on this server? The minimal requirement is 2GB for full spam/virus scanning feature.

4GB RAM

4

Re: Amavisd refusing connections on reboot

Did this issue occur just once, or frequently? Any other related log in Postfix log file?

5 (edited by dsp3 2015-12-28 19:35:21)

Re: Amavisd refusing connections on reboot

ZhangHuangbin wrote:

Did this issue occur just once, or frequently? Any other related log in Postfix log file?

This happens on every reboot. Here is an example of postfix logs before amavisd is restarted after the boot process (IP's and users obfuscated):

Dec 26 22:14:21 mail postfix/submission/smtpd[1357]: connect from unknown[51.103.133.102]
Dec 26 22:14:21 mail postfix/submission/smtpd[1364]: connect from unknown[51.103.133.102]
Dec 26 22:14:21 mail postfix/submission/smtpd[1357]: disconnect from unknown[51.103.133.102]
Dec 26 22:14:21 mail postfix/submission/smtpd[1364]: disconnect from unknown[51.103.133.102]

Dec 26 22:17:41 mail postfix/anvil[1365]: statistics: max connection rate 2/60s for (submission:51.103.133.102) at Dec 26 22:14:21
Dec 26 22:17:41 mail postfix/anvil[1365]: statistics: max connection count 2 for (submission:51.103.133.102) at Dec 26 22:14:21
Dec 26 22:17:41 mail postfix/anvil[1365]: statistics: max cache size 1 at Dec 26 22:14:21

Then restart amavisd:

Dec 27 00:08:39 mail postfix/submission/smtpd[3122]: connect from localhost.localdomain[127.0.0.1]
Dec 27 00:08:39 mail postfix/submission/smtpd[3122]: DF37C240C0E: client=localhost.localdomain[127.0.0.1], sasl_method=LOGIN, sasl_username=user1@domain.com
Dec 27 00:08:39 mail postfix/cleanup[3136]: DF37C240C0E: message-id=<375fed2ac55f28c1ee90c172b08cca15@domain.com
Dec 27 00:08:39 mail postfix/qmgr[686]: DF37C240C0E: from=<user1@domain.com>, size=540, nrcpt=1 (queue active)
Dec 27 00:08:39 mail roundcube[200]: <trp79utq> User user1@domain.com [51.103.133.102]; Message for user2@domain2.com; 250: 2.0.0 Ok: queued as DF37C240C0E
Dec 27 00:08:40 mail postfix/submission/smtpd[3122]: disconnect from localhost.localdomain[127.0.0.1]
Dec 27 00:08:41 mail postfix/smtpd[3155]: connect from localhost.localdomain[127.0.0.1]
Dec 27 00:08:41 mail postfix/smtpd[3155]: 373D8240C13: client=localhost.localdomain[127.0.0.1]
Dec 27 00:08:41 mail postfix/cleanup[3136]: 373D8240C13: message-id=<375fed2ac55f28c1ee90c172b08cca15@domain.com>
Dec 27 00:08:41 mail postfix/qmgr[686]: 373D8240C13: from=<user1@domain.com>, size=1572, nrcpt=1 (queue active)
Dec 27 00:08:41 mail amavis[3096]: (03096-01) Passed CLEAN {RelayedInternal}, ORIGINATING/MYNETS LOCAL [127.0.0.1]:54131 <user1@domain.com> -> <user2@domain2.com>, Queue-
Dec 27 00:08:41 mail postfix/smtpd[3155]: disconnect from localhost.localdomain[127.0.0.1]
Dec 27 00:08:41 mail postfix/smtp[3141]: DF37C240C0E: to=<user2@domain2.com>, relay=127.0.0.1[127.0.0.1]:10026, delay=1.4, delays=0.1/0.02/0.01/1.2, dsn=2.0.0, status=sent (250 2.0
Dec 27 00:08:41 mail postfix/qmgr[686]: DF37C240C0E: removed
Dec 27 00:08:41 mail postfix/pipe[3156]: 373D8240C13: to=<user2@domain2.com>, relay=dovecot, delay=0.1, delays=0.02/0.02/0/0.06, dsn=2.0.0, status=sent (delivered via dovecot servi
Dec 27 00:08:41 mail postfix/qmgr[686]: 373D8240C13: removed

Then the que runs fine.
I also thought this was a RAM issue as with 1 GB it wasn't working. I have since installed a clean system and clean iRedmail install, but same result. (4GB)
Centos 7.2 Minimal install. It was missing rsyslog amongst other packages (sudo bzip2), but they were installed before iRedmail.

6

Re: Amavisd refusing connections on reboot

Did you use 'systemctl' command to set Amavisd service to start automatically after server reboot?
e.g.

systemctl enable amavisd

7

Re: Amavisd refusing connections on reboot

ZhangHuangbin wrote:

Did you use 'systemctl' command to set Amavisd service to start automatically after server reboot?
e.g.

systemctl enable amavisd

I didn't, but I will test and see if it alters the behaviour

8

Re: Amavisd refusing connections on reboot

dsp3 wrote:
ZhangHuangbin wrote:

Did you use 'systemctl' command to set Amavisd service to start automatically after server reboot?
e.g.

systemctl enable amavisd

I didn't, but I will test and see if it alters the behaviour

I have now tested this after a server update and reboot. Amavisd does start at boot, but it refuses connections until it is restarted.

9

Re: Amavisd refusing connections on reboot

When server starts up, amavisd will be started, so there must be some log in /var/log/maillog. Please extract them and paste here so that others can help.

10

Re: Amavisd refusing connections on reboot

ZhangHuangbin wrote:

When server starts up, amavisd will be started, so there must be some log in /var/log/maillog. Please extract them and paste here so that others can help.

Here is the maillog from startup with first mail refusal:

Jan  7 14:15:12 mail clamd[146]: clamd daemon 0.98.7 (OS: linux-gnu, ARCH: x86_64, CPU: x86_64)                              
Jan  7 14:15:12 mail clamd[146]: Running as user amavis (UID 991, GID 989)                                                   
Jan  7 14:15:12 mail clamd[146]: Log file size limited to 1048576 bytes.                                                     
Jan  7 14:15:12 mail clamd[146]: Reading databases from /var/lib/clamav                                                      
Jan  7 14:15:12 mail clamd[146]: Not loading PUA signatures.                                                                 
Jan  7 14:15:12 mail clamd[146]: Bytecode: Security mode set to "TrustSigned".                                               
Jan  7 14:15:16 mail postfix/postfix-script[690]: warning: /var/spool/postfix/etc/localtime and /etc/localtime differ        
Jan  7 14:15:16 mail postfix/postfix-script[725]: starting the Postfix mail system                                           
Jan  7 14:15:16 mail postfix/master[737]: daemon started -- version 2.10.1, configuration /etc/postfix                       
Jan  7 14:15:16 mail amavis[147]: starting. /usr/sbin/amavisd at mail.domain1.com amavisd-new-2.10.1 (20141025), Unicode aware, L
Jan  7 14:15:18 mail amavis[852]: Net::Server: Group Not Defined.  Defaulting to EGID '989 989'                              
Jan  7 14:15:18 mail amavis[852]: Net::Server: User Not Defined.  Defaulting to EUID '991'                                   
Jan  7 14:15:18 mail amavis[852]: Module Amavis::Conf        2.404                                                           
Jan  7 14:15:18 mail amavis[852]: Module Archive::Zip        1.30                                                            
Jan  7 14:15:18 mail amavis[852]: Module BerkeleyDB          0.51                                                            
Jan  7 14:15:18 mail amavis[852]: Module Compress::Raw::Zlib 2.061                                                           
Jan  7 14:15:18 mail amavis[852]: Module Compress::Zlib      2.061                                                           
Jan  7 14:15:18 mail amavis[852]: Module Crypt::OpenSSL::RSA 0.28                                                            
Jan  7 14:15:18 mail amavis[852]: Module DBD::mysql          4.023                                                           
Jan  7 14:15:18 mail amavis[852]: Module DBI                 1.627                                                           
Jan  7 14:15:18 mail amavis[852]: Module DB_File             1.83                                                            
Jan  7 14:15:18 mail amavis[852]: Module Digest::MD5         2.52                                                            
Jan  7 14:15:18 mail amavis[852]: Module Digest::SHA         5.85                                                            
Jan  7 14:15:18 mail amavis[852]: Module Encode              2.51                                                            
Jan  7 14:15:18 mail amavis[852]: Module File::Temp          0.2301                                                          
Jan  7 14:15:18 mail amavis[852]: Module IO::Socket::INET6   2.69                                                            
Jan  7 14:15:18 mail amavis[852]: Module IO::Socket::IP      0.21                                                            
Jan  7 14:15:18 mail amavis[852]: Module MIME::Entity        5.505                                                           
Jan  7 14:15:18 mail amavis[852]: Module MIME::Parser        5.505                                                           
Jan  7 14:15:18 mail amavis[852]: Module MIME::Tools         5.505                                                           
Jan  7 14:15:18 mail amavis[852]: Module Mail::DKIM::Signer  0.39                                                            
Jan  7 14:15:18 mail amavis[852]: Module Mail::DKIM::Verifier 0.39                                                           
Jan  7 14:15:18 mail amavis[852]: Module Mail::Header        2.12                                                            
Jan  7 14:15:18 mail amavis[852]: Module Mail::Internet      2.12
Jan  7 14:15:18 mail amavis[852]: Module Mail::SPF           v2.008                                                          
Jan  7 14:15:18 mail amavis[852]: Module Mail::SpamAssassin  3.004000                                                        
Jan  7 14:15:18 mail amavis[852]: Module Net::DNS            0.72                                                            
Jan  7 14:15:18 mail amavis[852]: Module Net::LibIDN         0.12                                                            
Jan  7 14:15:18 mail amavis[852]: Module Net::Server         2.007                                                           
Jan  7 14:15:18 mail amavis[852]: Module NetAddr::IP         4.069                                                           
Jan  7 14:15:18 mail amavis[852]: Module Razor2::Client::Version 2.84                                                        
Jan  7 14:15:18 mail amavis[852]: Module Scalar::Util        1.27                                                            
Jan  7 14:15:18 mail amavis[852]: Module Socket              2.010                                                           
Jan  7 14:15:18 mail amavis[852]: Module Socket6             0.23                                                            
Jan  7 14:15:18 mail amavis[852]: Module Time::HiRes         1.9725                                                          
Jan  7 14:15:18 mail amavis[852]: Module URI                 1.60                                                            
Jan  7 14:15:18 mail amavis[852]: Module Unix::Syslog        1.1                                                             
Jan  7 14:15:18 mail amavis[852]: Amavis::ZMQ code     NOT loaded                                                            
Jan  7 14:15:18 mail amavis[852]: Amavis::DB code      loaded                                                                
Jan  7 14:15:18 mail amavis[852]: SQL base code        loaded                                                                
Jan  7 14:15:18 mail amavis[852]: SQL::Log code        loaded                                                                
Jan  7 14:15:18 mail amavis[852]: SQL::Quarantine      loaded                                                                
Jan  7 14:15:18 mail amavis[852]: Lookup::SQL code     loaded                                                                
Jan  7 14:15:18 mail amavis[852]: Lookup::LDAP code    NOT loaded                                                            
Jan  7 14:15:18 mail amavis[852]: AM.PDP-in proto code loaded                                                                
Jan  7 14:15:18 mail amavis[852]: SMTP-in proto code   loaded                                                                
Jan  7 14:15:18 mail amavis[852]: Courier proto code   NOT loaded                                                            
Jan  7 14:15:18 mail amavis[852]: SMTP-out proto code  loaded                                                                
Jan  7 14:15:18 mail amavis[852]: Pipe-out proto code  NOT loaded                                                            
Jan  7 14:15:18 mail amavis[852]: BSMTP-out proto code NOT loaded                                                            
Jan  7 14:15:18 mail amavis[852]: Local-out proto code NOT loaded                                                            
Jan  7 14:15:18 mail amavis[852]: OS_Fingerprint code  NOT loaded                                                            
Jan  7 14:15:18 mail amavis[852]: ANTI-VIRUS code      loaded                                                                
Jan  7 14:15:18 mail amavis[852]: ANTI-SPAM code       loaded                                                                
Jan  7 14:15:18 mail amavis[852]: ANTI-SPAM-EXT code   NOT loaded                                                            
Jan  7 14:15:18 mail amavis[852]: ANTI-SPAM-C code     NOT loaded                                                            
Jan  7 14:15:18 mail amavis[852]: ANTI-SPAM-SA code    loaded                                                                
Jan  7 14:15:18 mail amavis[852]: Unpackers code       loaded                                                                
Jan  7 14:15:18 mail amavis[852]: DKIM code            loaded                                                                
Jan  7 14:15:18 mail amavis[852]: Tools code           NOT loaded                                                            
Jan  7 14:15:18 mail amavis[852]: Found $file            at /usr/bin/file                                                    
Jan  7 14:15:18 mail amavis[852]: Found $altermime       at /usr/bin/altermime                                               
Jan  7 14:15:18 mail amavis[852]: Internal decoder for .mail                                                                 
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .F    at /usr/bin/unfreeze
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .Z    at /usr/bin/gzip -d                                             
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .gz   at /usr/bin/gzip -d                                             
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .bz2  at /usr/bin/bzip2 -d                                            
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .xz   at /usr/bin/xzdec                                               
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .lzma at /usr/bin/xz -dc --format=lzma                                
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .lrz  at /usr/bin/lrzip -q -k -d -o -                                 
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .lzo  at /usr/bin/lzop -d                                             
Jan  7 14:15:18 mail amavis[852]: No ext program for   .lz4, tried: lz4c -d                                                  
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .rpm  at /usr/bin/rpm2cpio                                            
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .cpio at /usr/bin/pax                                                 
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .tar  at /usr/bin/pax                                                 
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .deb  at /usr/bin/ar                                                  
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .rar  at /usr/bin/unrar                                               
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .arj  at /usr/bin/unarj                                               
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .arc  at /usr/bin/nomarch                                             
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .zoo  at /usr/bin/unzoo                                               
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .cab  at /usr/bin/cabextract                                          
Jan  7 14:15:18 mail amavis[852]: Internal decoder for .tnef                                                                 
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .zip  at /usr/bin/7za                                                 
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .kmz  at /usr/bin/7za                                                 
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .7z   at /usr/bin/7za                                                 
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .jar  at /usr/bin/7z                                                  
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .swf  at /usr/bin/7z                                                  
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .lha  at /usr/bin/7z                                                  
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .iso  at /usr/bin/7z                                                  
Jan  7 14:15:18 mail amavis[852]: Found decoder for    .exe  at /usr/bin/unrar; /usr/bin/unarj                               
Jan  7 14:15:18 mail amavis[852]: No decoder for       .lz4                                                                  
Jan  7 14:15:18 mail amavis[852]: Using primary internal av scanner code for ClamAV-clamd                                    
Jan  7 14:15:18 mail amavis[852]: Found secondary av scanner ClamAV-clamscan at /usr/bin/clamscan                            
Jan  7 14:15:18 mail amavis[852]: Deleting db files __db.002,__db.001,nanny.db,__db.003,snmp.db in /var/spool/amavisd/db     
Jan  7 14:15:18 mail amavis[852]: Creating db in /var/spool/amavisd/db/; BerkeleyDB 0.51, libdb 5.3                          
Jan  7 14:15:26 mail clamd[146]: Loaded 4207813 signatures.                                                                  
Jan  7 14:15:27 mail clamd[146]: LOCAL: Unix socket file /var/run/clamd.amavisd/clamd.socket                                 
Jan  7 14:15:27 mail clamd[146]: LOCAL: Setting connection queue length to 200                                               
Jan  7 14:15:27 mail clamd[146]: Limits: Global size limit set to 104857600 bytes.                                           
Jan  7 14:15:27 mail clamd[146]: Limits: File size limit set to 26214400 bytes.                                              
Jan  7 14:15:27 mail clamd[146]: Limits: Recursion level limit set to 16.                                                    
Jan  7 14:15:27 mail clamd[146]: Limits: Files limit set to 10000.                                                           
Jan  7 14:15:27 mail clamd[146]: Limits: MaxEmbeddedPE limit set to 10485760 bytes.                                          
Jan  7 14:15:27 mail clamd[146]: Limits: MaxHTMLNormalize limit set to 10485760 bytes.
Jan  7 14:15:27 mail clamd[146]: Limits: MaxZipTypeRcg limit set to 1048576 bytes.                                           
Jan  7 14:15:27 mail clamd[146]: Limits: MaxPartitions limit set to 50.                                                      
Jan  7 14:15:27 mail clamd[146]: Limits: MaxIconsPE limit set to 100.                                                        
Jan  7 14:15:27 mail clamd[146]: Archive support enabled.                                                                   
Jan  7 14:15:27 mail clamd[146]: Algorithmic detection enabled.                                                              
Jan  7 14:15:27 mail clamd[146]: Portable Executable support enabled.                                                        
Jan  7 14:15:27 mail clamd[146]: ELF support enabled.                                                                        
Jan  7 14:15:27 mail clamd[146]: Mail files support enabled.                                                                 
Jan  7 14:15:27 mail clamd[146]: OLE2 support enabled.                                                                       
Jan  7 14:15:27 mail clamd[146]: PDF support enabled.                                                                        
Jan  7 14:15:27 mail clamd[146]: SWF support enabled.                                                                        
Jan  7 14:15:27 mail clamd[146]: HTML support enabled.                                                                       
Jan  7 14:15:27 mail clamd[146]: Self checking every 600 seconds.                                                            
Jan  7 14:18:15 mail postfix/postscreen[1297]: CONNECT from [127.0.0.1]:33408 to [127.0.0.1]:25                              
Jan  7 14:18:15 mail postfix/postscreen[1297]: WHITELISTED [127.0.0.1]:33408                                                 
Jan  7 14:18:15 mail postfix/smtpd[1298]: connect from localhost.localdomain[127.0.0.1]                                      
Jan  7 14:18:16 mail postfix/smtpd[1298]: 29611240742: client=localhost.localdomain[127.0.0.1]                               
Jan  7 14:18:16 mail postfix/cleanup[1311]: 29611240742: message-id=<18b-568e5780-1-9fde790@165879340>                       
Jan  7 14:18:16 mail postfix/qmgr[751]: 29611240742: from=<user1@domain1.com>, size=530, nrcpt=1 (queue active)
Jan  7 14:18:16 mail postfix/smtpd[1298]: disconnect from localhost.localdomain[127.0.0.1]
Jan  7 14:18:16 mail postfix/smtp[1316]: connect to 127.0.0.1[127.0.0.1]:10024: Connection refused
Jan  7 14:18:16 mail postfix/smtp[1316]: 29611240742: to=<user2@domain2.com>, relay=none, delay=0.47, delays=0.44/0.03/0/0,

Then after restarting amavisd:

Jan  7 14:19:02 mail amavis[1329]: starting. /usr/sbin/amavisd at mail.domain1.com amavisd-new-2.10.1 (20141025), Unicode aware,
Jan  7 14:19:02 mail amavis[1339]: Net::Server: Group Not Defined.  Defaulting to EGID '989 989'                             
Jan  7 14:19:02 mail amavis[1339]: Net::Server: User Not Defined.  Defaulting to EUID '991'                                  
Jan  7 14:19:02 mail amavis[1339]: Module Amavis::Conf        2.404                                                          
Jan  7 14:19:02 mail amavis[1339]: Module Archive::Zip        1.30                                                           
Jan  7 14:19:02 mail amavis[1339]: Module BerkeleyDB          0.51                                                           
Jan  7 14:19:02 mail amavis[1339]: Module Compress::Raw::Zlib 2.061                                                          
Jan  7 14:19:02 mail amavis[1339]: Module Compress::Zlib      2.061                                                          
Jan  7 14:19:02 mail amavis[1339]: Module Crypt::OpenSSL::RSA 0.28                                                           
Jan  7 14:19:02 mail amavis[1339]: Module DBD::mysql          4.023                                                          
Jan  7 14:19:02 mail amavis[1339]: Module DBI                 1.627                                                          
Jan  7 14:19:02 mail amavis[1339]: Module DB_File             1.83                                                           
Jan  7 14:19:02 mail amavis[1339]: Module Digest::MD5         2.52                                                           
Jan  7 14:19:02 mail amavis[1339]: Module Digest::SHA         5.85                                                           
Jan  7 14:19:02 mail amavis[1339]: Module Encode              2.51                                                           
Jan  7 14:19:02 mail amavis[1339]: Module File::Temp          0.2301                                                         
Jan  7 14:19:02 mail amavis[1339]: Module IO::Socket::INET6   2.69                                                           
Jan  7 14:19:02 mail amavis[1339]: Module IO::Socket::IP      0.21                                                           
Jan  7 14:19:02 mail amavis[1339]: Module MIME::Entity        5.505                                                          
Jan  7 14:19:02 mail amavis[1339]: Module MIME::Parser        5.505                                                          
Jan  7 14:19:02 mail amavis[1339]: Module MIME::Tools         5.505                                                          
Jan  7 14:19:02 mail amavis[1339]: Module Mail::DKIM::Signer  0.39                                                           
Jan  7 14:19:02 mail amavis[1339]: Module Mail::DKIM::Verifier 0.39                                                          
Jan  7 14:19:02 mail amavis[1339]: Module Mail::Header        2.12                                                           
Jan  7 14:19:02 mail amavis[1339]: Module Mail::Internet      2.12                                                           
Jan  7 14:19:02 mail amavis[1339]: Module Mail::SPF           v2.008                                                         
Jan  7 14:19:02 mail amavis[1339]: Module Mail::SpamAssassin  3.004000                                                       
Jan  7 14:19:02 mail amavis[1339]: Module Net::DNS            0.72                                                           
Jan  7 14:19:02 mail amavis[1339]: Module Net::LibIDN         0.12                                                           
Jan  7 14:19:02 mail amavis[1339]: Module Net::Server         2.007                                                          
Jan  7 14:19:02 mail amavis[1339]: Module NetAddr::IP         4.069                                                          
Jan  7 14:19:02 mail amavis[1339]: Module Razor2::Client::Version 2.84                                                       
Jan  7 14:19:02 mail amavis[1339]: Module Scalar::Util        1.27                                                           
Jan  7 14:19:02 mail amavis[1339]: Module Socket              2.010                                                          
Jan  7 14:19:02 mail amavis[1339]: Module Socket6             0.23                                                           
Jan  7 14:19:02 mail amavis[1339]: Module Time::HiRes         1.9725                                                         
Jan  7 14:19:02 mail amavis[1339]: Module URI                 1.60                                                           
Jan  7 14:19:02 mail amavis[1339]: Module Unix::Syslog        1.1                                                            
Jan  7 14:19:02 mail amavis[1339]: Amavis::ZMQ code     NOT loaded
Jan  7 14:19:02 mail amavis[1339]: SQL::Quarantine      loaded                                                               
Jan  7 14:19:02 mail amavis[1339]: Lookup::SQL code     loaded                                                               
Jan  7 14:19:02 mail amavis[1339]: Lookup::LDAP code    NOT loaded                                                           
Jan  7 14:19:02 mail amavis[1339]: AM.PDP-in proto code loaded                                                               
Jan  7 14:19:02 mail amavis[1339]: SMTP-in proto code   loaded                                                              
Jan  7 14:19:02 mail amavis[1339]: Courier proto code   NOT loaded                                                           
Jan  7 14:19:02 mail amavis[1339]: SMTP-out proto code  loaded                                                               
Jan  7 14:19:02 mail amavis[1339]: Pipe-out proto code  NOT loaded                                                           
Jan  7 14:19:02 mail amavis[1339]: BSMTP-out proto code NOT loaded                                                           
Jan  7 14:19:02 mail amavis[1339]: Local-out proto code NOT loaded                                                           
Jan  7 14:19:02 mail amavis[1339]: OS_Fingerprint code  NOT loaded                                                           
Jan  7 14:19:02 mail amavis[1339]: ANTI-VIRUS code      loaded                                                              
Jan  7 14:19:02 mail amavis[1339]: ANTI-SPAM code       loaded                                                               
Jan  7 14:19:02 mail amavis[1339]: ANTI-SPAM-EXT code   NOT loaded                                                           
Jan  7 14:19:02 mail amavis[1339]: ANTI-SPAM-C code     NOT loaded                                                           
Jan  7 14:19:02 mail amavis[1339]: ANTI-SPAM-SA code    loaded                                                               
Jan  7 14:19:02 mail amavis[1339]: Unpackers code       loaded                                                               
Jan  7 14:19:02 mail amavis[1339]: DKIM code            loaded                                                               
Jan  7 14:19:02 mail amavis[1339]: Tools code           NOT loaded                                                           
Jan  7 14:19:02 mail amavis[1339]: Found $file            at /usr/bin/file                                                   
Jan  7 14:19:02 mail amavis[1339]: Found $altermime       at /usr/bin/altermime                                              
Jan  7 14:19:02 mail amavis[1339]: Internal decoder for .mail                                                                
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .F    at /usr/bin/unfreeze                                           
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .Z    at /usr/bin/gzip -d                                            
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .gz   at /usr/bin/gzip -d                                            
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .bz2  at /usr/bin/bzip2 -d                                           
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .xz   at /usr/bin/xzdec                                              
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .lzma at /usr/bin/xz -dc --format=lzma                               
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .lrz  at /usr/bin/lrzip -q -k -d -o -                                
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .lzo  at /usr/bin/lzop -d                                            
Jan  7 14:19:02 mail amavis[1339]: No ext program for   .lz4, tried: lz4c -d                                                 
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .rpm  at /usr/bin/rpm2cpio                                           
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .cpio at /usr/bin/pax                                                
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .tar  at /usr/bin/pax                                                
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .deb  at /usr/bin/ar                                                 
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .rar  at /usr/bin/unrar                                              
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .arj  at /usr/bin/unarj                                              
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .arc  at /usr/bin/nomarch                                            
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .zoo  at /usr/bin/unzoo                                              
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .cab  at /usr/bin/cabextract
Jan  7 14:19:02 mail amavis[1339]: Internal decoder for .tnef                                                                
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .zip  at /usr/bin/7za                                                
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .kmz  at /usr/bin/7za                                                
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .7z   at /usr/bin/7za                                                
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .jar  at /usr/bin/7z                                                 
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .swf  at /usr/bin/7z                                                 
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .lha  at /usr/bin/7z                                                
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .iso  at /usr/bin/7z                                                 
Jan  7 14:19:02 mail amavis[1339]: Found decoder for    .exe  at /usr/bin/unrar; /usr/bin/unarj                              
Jan  7 14:19:02 mail amavis[1339]: No decoder for       .lz4                                                                 
Jan  7 14:19:02 mail amavis[1339]: Using primary internal av scanner code for ClamAV-clamd                                   
Jan  7 14:19:02 mail amavis[1339]: Found secondary av scanner ClamAV-clamscan at /usr/bin/clamscan                           
Jan  7 14:19:02 mail amavis[1339]: Deleting db files __db.002,__db.001,nanny.db,__db.003,snmp.db in /var/spool/amavisd/db    
Jan  7 14:19:02 mail amavis[1339]: Creating db in /var/spool/amavisd/db/; BerkeleyDB 0.51, libdb 5.3                         
Jan  7 14:20:32 mail postfix/smtp[1436]: 619D2240606: to=<user1@domain1.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=1.6, delays
Jan  7 14:20:32 mail postfix/qmgr[751]: 619D2240606: removed                                                                 
Jan  7 14:20:33 mail postfix/pipe[1442]: E47C924074D: to=<user1@domain1.com>, relay=dovecot, delay=0.19, delays=0.02/0.02/0/0.15,
Jan  7 14:20:33 mail postfix/qmgr[751]: E47C924074D: removed                                                                 
Jan  7 14:23:51 mail postfix/anvil[1427]: statistics: max connection rate 1/60s for (smtpd:83.69.111.55) at Jan  7 14:20:31  
Jan  7 14:23:51 mail postfix/anvil[1427]: statistics: max connection count 1 for (smtpd:83.69.111.55) at Jan  7 14:20:31     
Jan  7 14:23:51 mail postfix/anvil[1427]: statistics: max cache size 1 at Jan  7 14:20:31                                    
Jan  7 14:25:16 mail postfix/qmgr[751]: 29611240742: from=<user1@domain1.com>, size=530, nrcpt=1 (queue active)                  
Jan  7 14:25:16 mail postfix/smtpd[1527]: connect from localhost.localdomain[127.0.0.1]                                      
Jan  7 14:25:16 mail postfix/smtpd[1527]: DCE2C24074E: client=localhost.localdomain[127.0.0.1]                               
Jan  7 14:25:16 mail postfix/cleanup[1530]: DCE2C24074E: message-id=<18b-568e5780-1-9fde790@165879340>                       
Jan  7 14:25:16 mail postfix/qmgr[751]: DCE2C24074E: from=<user1@domain1.com>, size=1572, nrcpt=1 (queue active)                 
Jan  7 14:25:16 mail postfix/smtpd[1527]: disconnect from localhost.localdomain[127.0.0.1] 
Jan  7 14:25:16 mail amavis[1340]: (01340-01) Passed CLEAN {RelayedInternal}, MYNETS LOCAL [127.0.0.1]:33408 <user1@domain1.com> 
Jan  7 14:25:16 mail postfix/smtp[1522]: 29611240742: to=<user2@domain2.com>, relay=127.0.0.1[127.0.0.1]:10024, delay=421, d
Jan  7 14:25:16 mail postfix/qmgr[751]: 29611240742: removed                                                                 
Jan  7 14:25:24 mail postfix/smtp[1531]: DCE2C24074E: to=<user2@domain2.com>, relay=mx1.domain2.com[83.69.111.55]:25, d
Jan  7 14:25:24 mail postfix/qmgr[751]: DCE2C24074E: removed

11

Re: Amavisd refusing connections on reboot

ZhangHuangbin wrote:

When server starts up, amavisd will be started, so there must be some log in /var/log/maillog. Please extract them and paste here so that others can help.

I'm also seeing this in the logs:

 Jan  7 12:20:44 mail amavis[21140]: (21140-08) NOTICE: reconnecting in response to: err=2006, HY000, DBD::mysql::st execute failed: MySQL server has gone away at (eval 128) line 172, <GEN19> line 25405. 

However, this doesn't appear to prevent mail delivery.

12

Re: Amavisd refusing connections on reboot

No error in Amavisd log, it seems just normal and it should work as expected.

Can you check which service starts first? Amavisd or MySQL?

13

Re: Amavisd refusing connections on reboot

ZhangHuangbin wrote:

No error in Amavisd log, it seems just normal and it should work as expected.

Can you check which service starts first? Amavisd or MySQL?

It appears that MySQL (MariaDB) starts first:

Jan 07 14:15:12 mail systemd[1]: Started Amavisd clean tmp timer.
Jan 07 14:15:12 mail systemd[1]: Starting Amavisd clean tmp timer.
Jan 07 14:15:12 mail systemd[1]: Reached target Basic System.
Jan 07 14:15:12 mail systemd[1]: Starting Basic System.
Jan 07 14:15:12 mail systemd[1]: Starting MariaDB database server...
Jan 07 14:15:12 mail systemd[1]: Starting SOGo is a groupware server...
Jan 07 14:15:12 mail systemd[1]: Started D-Bus System Message Bus.
Jan 07 14:15:12 mail systemd[1]: Starting D-Bus System Message Bus...
Jan 07 14:15:12 mail systemd[1]: Starting Login Service...
Jan 07 14:15:12 mail systemd[1]: Started Memcached.
Jan 07 14:15:12 mail systemd[1]: Starting Memcached...
Jan 07 14:15:12 mail systemd[1]: Starting Postfix Mail Transport Agent...
Jan 07 14:15:12 mail systemd[1]: Starting System Logging Service...
Jan 07 14:15:12 mail systemd[1]: Starting The PHP FastCGI Process Manager...
Jan 07 14:15:12 mail systemd[1]: Starting Dump dmesg to /var/log/dmesg...
Jan 07 14:15:12 mail systemd[1]: Started OpenSSH Server Key Generation.
Jan 07 14:15:12 mail systemd[1]: Starting uWSGI Emperor Service...
Jan 07 14:15:12 mail systemd[1]: Started OpenSSH server daemon.
Jan 07 14:15:12 mail systemd[1]: Starting OpenSSH server daemon...
Jan 07 14:15:12 mail systemd[1]: Starting LSB: Bring up/down networking...
Jan 07 14:15:12 mail systemd[1]: Starting firewalld - dynamic firewall daemon...
Jan 07 14:15:12 mail systemd[1]: Starting The nginx HTTP and reverse proxy server...
Jan 07 14:15:12 mail systemd[1]: Starting Dovecot IMAP/POP3 email server...
Jan 07 14:15:12 mail systemd[1]: Started clamd scanner (amavisd) daemon.
Jan 07 14:15:12 mail systemd[1]: Starting clamd scanner (amavisd) daemon...
Jan 07 14:15:12 mail systemd[1]: Starting Amavisd-new is an interface between MTA and content checkers....

14 (edited by SteveLuxe 2016-01-08 21:22:23)

Re: Amavisd refusing connections on reboot

From looking at your logs, it appears that you have postfix configured with two different port numbers for Amavis. In one log file, it's listed as 10024, and in another, it's 10026. (Your machine is obviously configured to use port 10026 for Amavis.) Make sure that Amavis' port is configured correctly in /etc/postfix/main.cf and /etc/postfix/master.cf. Also check your configuration files in /etc/amavis/ to make sure of what port Amavis is configured to use on startup. For some reason, I had the same issue with my server. It was trying to use both ports 10026 and 10024. My server had Amavis configured to use 10024, so I had to change the port numbers in main.cf and master.cf for Amavis to work correctly, and to not refuse connections.

Hope that's of some help to you! smile

Dec 26 19:22:38 mail postfix/smtp[1260]: CCF52240BD9: to=<user1@domain.com>, relay=none, delay=0.16, delays=0.14/0.01/0/0, dsn=4.4.1, status=deferred (connect to 127.0.0.1[127.0.0.1]:10024: Connection refused)

Dec 27 00:08:41 mail postfix/smtp[3141]: DF37C240C0E: to=<user2@domain2.com>, relay=127.0.0.1[127.0.0.1]:10026, delay=1.4, delays=0.1/0.02/0.01/1.2, dsn=2.0.0, status=sent (250 2.0

Excerpts from my system: (Yours should be 10026, since that's how your system is configured).

From my /etc/postfix/master.cf:

submission inet n       -       n       -       -       smtpd
  -o smtpd_tls_security_level=encrypt
  -o smtpd_sasl_auth_enable=yes
  -o smtpd_client_restrictions=permit_mynetworks,permit_sasl_authenticated,reject
  -o content_filter=smtp-amavis:[127.0.0.1]:10024

From /etc/postfix/main.cf:

content_filter = smtp-amavis:[127.0.0.1]:10024

15

Re: Amavisd refusing connections on reboot

Dear SteveLuxe,

Your configuration is WRONG.

*) In main.cf, we use port no. 10024 for incoming emails.
*) in master.cf, we use port no. 10026 for outgoing emails (sent by authenticated users).

Amavisd is able to listen on multiple ports. Default setting in Amavisd config file (/etc/amavisd/amavisd.conf) should be:

$inet_socket_port = [10024, 10026, 9998];

16

Re: Amavisd refusing connections on reboot

Hey Zhang,

Thanks for letting me know that my configuration is wrong. I could only seem to get things to work if I ended up matching up the two with port 10024. I will try it the other way around, but I'm pretty sure that I was getting a "refused connection" error when I had it set up that way, as well... Let me test it and get back to you. I'll try changing it now and see if it works correctly. I hate to give bad information, so thanks for setting the record straight...

17

Re: Amavisd refusing connections on reboot

That didn't work for me... I'm using debian...

Jan  8 11:28:27 mail postfix/smtp[18131]: connect to 127.0.0.1[127.0.0.1]:10026: Connection refused

However, when I went into /etc/amavis/conf.d/ and edited 20-debian_defaults, I had to manually add 10026 to the "$inet_socket_port =" variables. Once I added port 10026 into that file, and restarted postfix and amavis, everything seemed to work. Obviously I must have missed a step in setting up amavis in that particular file. I'm not sure how that happened, but I found it and changed it on my end, and now it appears to be working.

Sorry to have given bad information. I feel a bit like a stooge now.

Now that I'm doing a netstat -nat, I can see the following ports are open:

tcp        0      0 127.0.0.1:10024         0.0.0.0:*               LISTEN     
tcp        0      0 127.0.0.1:10025         0.0.0.0:*               LISTEN     
tcp        0      0 127.0.0.1:10026         0.0.0.0:*               LISTEN     
tcp        0      0 127.0.0.1:9998          0.0.0.0:*               LISTEN

Thanks for straightening ME out, Zhang! I had no clue that it was misconfigured.

18

Re: Amavisd refusing connections on reboot

Was there ever a solution to the original problem posted here?  I am seeing the same.  Fortunately server restarts are so rare that having to deal with it is infrequent.  Yet there it is and I thought I'd do a search since I'm dealing with that now.  Thus I landed here.

19

Re: Amavisd refusing connections on reboot

SteveLuxe wrote:

However, when I went into /etc/amavis/conf.d/ and edited 20-debian_defaults, I had to manually add 10026 to the "$inet_socket_port =" variables.

Please update /etc/amavis/conf.d/50-user instead, don't edit any other files under /etc/amavis/conf.d/.

20

Re: Amavisd refusing connections on reboot

ZhangHuangbin wrote:
SteveLuxe wrote:

However, when I went into /etc/amavis/conf.d/ and edited 20-debian_defaults, I had to manually add 10026 to the "$inet_socket_port =" variables.

Please update /etc/amavis/conf.d/50-user instead, don't edit any other files under /etc/amavis/conf.d/.

Is this something new?  The only things I have beneath /etc/amavis/ are two plain files (amavisd.conf and amavisd.conf.2016.05.27.19.50.51).  Doing a "find /etc -name 50-user.conf" locates only /etc/fonts/conf.d/50-user.conf.

21

Re: Amavisd refusing connections on reboot

NightStorm wrote:

The only things I have beneath /etc/amavis/ are two plain files (amavisd.conf and amavisd.conf.2016.05.27.19.50.51).

Please check this tutorial to find the correct config file:
http://www.iredmail.org/docs/file.locat … ml#amavisd