Jakiś czas temu miałem przyjemność borykać się z dziwnym problemem pakietu AMaViS’a komunikującego się z Postfix’em na portach 10024 (nasłuchiwanie AMaViS’a) i 10025 (wysyłanie odpowiedzi do Postfix’a).
Przy uruchamianiu procesu amavisd pojawia się błąd:
fox# /usr/local/etc/rc.d/amavisd start
ERROR: MISSING REQUIRED BASIC MODULES:
IO::Wrap
IO::Stringy
Unix::Syslog
Compress::Zlib
MIME::Entity
MIME::Parser
Net::Server
Net::Server::PreFork
BEGIN failed-compilation aborted at /usr/local/sbin/amavisd line 232.
Dziwnym trafem (to zapewne sprawka upgrade’owania innych portów) brakuje kilku modułów Perl’a do prawidłowego funkcjonowania pakietu AMaViS.
By rozwiązać ten problem należy wejść do konsoli Perl’a poleceniem:
perl -MCPAN -e shell
i w CPAN’ie (konsola Perl’a) instalujemy brakujące moduły (z listy powyżej) zgodnie z poleceniem
install [nazwa modułu], np. install Net::Server
Po ponownym skompilowaniu brakujących modułów (startując amavisa można zweryfikować jakich jeszcze brakuje) sprawdzamy czy nasz proces działa:
fox# /usr/local/etc/rc.d/amavisd start
Starting amavisd.
Problem in Amavis::DKIM code: Can’t locate Crypt/OpenSSL/RSA.pm in @INC (@INC contains: /usr/local/lib/perl5/5.8.9/BSDPAN /usr/local/lib/perl5/site_perl/5.8.9/mach /usr/local/lib/perl5/site_perl/5.8.9 /usr/local/lib/perl5/5.8.9/mach /usr/local/lib/perl5/5.8.9) at (eval 99) line 25.
BEGIN failed-compilation aborted at (eval 99) line 25.
Wydawać się mogło, że ponowna instalacja brakujących modułów rozwiąże problem, a tu jednak zonk.
Wobec powyższego wynika, że wsiąkł również specjalny moduł odpowiedzialny za realizację tzw. DomainKeys Identified Mail (DKIM).
Doinstalowujemy więc port
cd /usr/ports/
make search name=mail-DKIM
(…)
cd /usr/ports/mail/p5-Mail-DKIM
make install clean
I ponownie sprawdzamy czy amavisd działa
fox# /usr/local/etc/rc.d/amavisd start
Starting amavisd.
Problem in antispam SA code: Can’t locate Mail/SpamAssassin.pm in @INC (@INC contains: /usr/local/lib/perl5/5.8.9/BSDPAN /usr/local/lib/perl5/site_perl/5.8.9/mach /usr/local/lib/perl5/site_perl/5.8.9 /usr/local/lib/perl5/5.8.9/mach /usr/local/lib/perl5/5.8.9) at (eval 118) line 63.
BEGIN failed-compilation aborted at (eval 118) line 63.
Teraz łapiemy się za głowę, bowiem okazuje się, że brakuje SA (SpamAssasin’a).
Wchodzimy ponownie do konsoli Perl’a i instalujemy SA
perl -MCPAN -e shell
install Mail:SpamAssassin
Po instalacji SA uruchamiamy proces amavisd kolejny raz aby przekonać się czy jest już wszystko OK.
fox# /usr/local/etc/rc.d/amavisd start
Starting amavisd.
i sprawdzamy czy widać proces
fox# ps aux | grep amavisd
vscan 83335 3.1 3.5 79112 72304 ?? Ss 10:02AM 0:08.15 amavisd (master) (perl)
vscan 83351 0.7 3.6 82116 75068 ?? I 10:03AM 0:01.22 amavisd (ch1-avail) (perl)
vscan 83352 0.0 3.5 79744 72304 ?? I 10:03AM 0:00.03 amavisd (virgin child) (perl)
root 83359 0.0 0.0 1632 844 p0 RL+ 10:03AM 0:00.00 grep amavisdfox# /usr/local/etc/rc.d/amavisd status
amavisd is running as pid 83335 83351 83352.
Hurra, jest sukces! Udało się! Ale… czy na pewno?
Proces działa, ale poczta nie zostaje dostarczona.
Patrzymy na logi Postfix’a
tail -f /var/log/maillog
i starając się wysłać dowolnego maila widzimy w logach następujące błędy
Oct 13 05:36:16 fox amavis[25159]: (25159-14) (!!)TROUBLE in check_mail: delivery-notification FAILED: temporarily unable to send DSN to : 450 4.4.1 Can’t connect to INET4 socket 127.0.0.1: Connection refused, MTA([127.0.0.1]:10025), id=25159-14 at /usr/local/sbin/amavisd line 11386.
Oct 13 05:36:16 fox amavis[25159]: (25159-14) (!)PRESERVING EVIDENCE in /var/amavis/tmp/amavis-20091013T030230-25159
Oct 13 05:36:16 fox postfix/smtp[29075]: 5FF9B6D42B: to=, relay=127.0.0.1[127.0.0.1]:10024, delay=1689, delays=1683/0.01/0.01/5.9, dsn=4.5.0, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.5.0 Error in processing, id=25159-14, delivery-notification FAILED: temporarily unable to send DSN to : 450 4.4.1 Can’t connect to INET4 socket 127.0.0.1: Connection refused, MTA([127.0.0.1]:10025), id=25159-14 at /usr/local/sbin/amavisd line 11386. (in reply to end of DATA command))Oct 13 06:05:14 fox amavis[28132]: (28132-10) (!)FWD via SMTP: -> , 450 4.4.1 Can’t connect to INET4 socket 127.0.0.1: Connection refused, MTA([127.0.0.1]:10025), id=28132-10
Oct 13 06:05:14 fox amavis[28132]: (28132-10) Blocked MTA-BLOCKED, -> , Message-ID: <[email protected]>, mail_id: i8vzB+cdas+V, Hits: -2.235, size: 7058466, 127353 ms
Oct 13 06:05:15 fox postfix/smtp[29514]: 2B90C6D425: to=, orig_to=, relay=127.0.0.1[127.0.0.1]:10024, delay=21915, delays=21778/9.7/0.02/127, dsn=4.4.1, status=deferred (host 127.0.0.1[127.0.0.1] said: 450 4.4.1 id=28132-10 - Temporary MTA failure on relaying, Can’t connect to INET4 socket 127.0.0.1: Connection refused, MTA([127.0.0.1]:10025), id=28132-10 (in reply to end of DATA command))
Z powyższych błędów wynika, że jest jakiś problem przy połączeniu na porcie 10024.
Tutaj przyznam się bez bicia, że w configu Postfix’a zmieniłem wcześniej w celach testowych port z 10024 na 10025.
Aby nie mieszać, ustawienia plików konfiguracyjnych powinny być następujące
amavisd.conf
# Port na którym będzie nasłuchiwał AMaViS:
$inet_socket_port = 10024;
# Dopuszczaj połączenia jedynie poprzez lokalny adres IP:
@inet_acl = qw( 127.0.0.1 );
main.cf
# AMaViS
content_filter=smtp-amavis:[127.0.0.1]:10024
master.cf
smtp-amavis unix - - n - 2 smtp
-o smtp_data_done_timeout=1200
-o smtp_send_xforward_command=yes
-o disable_dns_lookups=yes127.0.0.1:10025 inet n - n - - smtpd
-o content_filter=
-o local_recipient_maps=
-o relay_recipient_maps=
-o smtpd_restriction_classes=
-o smtpd_client_restrictions=
-o smtpd_helo_restrictions=
-o smtpd_sender_restrictions=
-o smtpd_recipient_restrictions=permit_mynetworks,reject
-o mynetworks=127.0.0.0/8
-o strict_rfc821_envelopes=yes
-o smtpd_error_sleep_time=0
-o smtpd_soft_error_limit=1001
-o smtpd_hard_error_limit=1000
Po doprowadzeniu konfiguracji pakietów Postfix + AMaViS do porządku, wszystko wróciło do normy
Oct 13 06:45:44 fox postfix/cleanup[83006]: 7DDC36D41B: message-id=<000d01ca6824$a61bc6b0$6400a8c0@morozov>
Oct 13 06:45:44 fox postfix/qmgr[38715]: 7DDC36D41B: from=, size=10257, nrcpt=1 (queue active)
Oct 13 06:45:44 fox amavis[80899]: (80899-04) (!!)WARN: all primary virus scanners failed, considering backups
Oct 13 06:45:49 fox postfix/smtpd[83003]: disconnect from unknown[113.169.91.43]
Oct 13 06:45:50 fox amavis[80899]: (80899-04) Blocked SPAM, [113.169.91.43] [113.169.91.43] -> , quarantine: spam-gAJtMJQua0NH.gz, Message-ID: <000d01ca6824$a61bc6b0$6400a8c0@morozov>, mail_id: gAJtMJQua0NH, Hits: 14.836, size: 10257, 11290 ms
Oct 13 06:45:50 fox postfix/smtp[83007]: 7DDC36D41B: to=, relay=127.0.0.1[127.0.0.1]:10024, delay=13, delays=1.6/0/0.01/11, dsn=2.5.0, status=sent (250 2.5.0 Ok, id=80899-04, DISCARD(bounce.suppressed))
Oct 13 06:45:50 fox postfix/qmgr[38715]: 7DDC36D41B: removed
Oct 13 06:45:55 fox postfix/anvil[83004]: statistics: max connection rate 1/60s for (smtp:113.23.24.227) at Oct 13 06:45:44
Oct 13 06:45:55 fox postfix/anvil[83004]: statistics: max connection count 1 for (smtp:113.23.24.227) at Oct 13 06:45:44
Oct 13 06:45:51 fox postfix/anvil[83004]: statistics: max cache size 1 at Oct 13 06:45:44
Po takim długim leczeniu choroby nasuwa się myśl: uwaga na upgrade portów 🙂
3mam kciuki. Pozdrawiam.