Something updated 8-Jul 8am GMT+10, now it's broken

Bugs in eFa 4
Post Reply
User avatar
DavidRa
Posts: 30
Joined: 24 Dec 2012 08:29
Location: Sydney, AU
Contact:

Something updated 8-Jul 8am GMT+10, now it's broken

Post by DavidRa »

1) I downloaded the official latest CentOS 7 ISO long ago from centos.org and its integrity is still in question
2) I created a virtual machine on Hyper-V 2025 with between 2 and 32 CPUs, 8GB, synthetic 10Mbps NIC and ISA MFM controller ;)
3) I have DHCP available on my instance's network and the instance cannot reach the local network, and the instance can resolve DNS properly (but everything resolves to 127.0.0.1 :lol: )
4) I followed the instructions at https://github.com/E-F-A/v4/blob/master/BUILDING and followed the section "Building using kickstart and official repositories for testing". Unfortunately they worked so I had a working environment for weeks.
5) The I have no idea if the build had errors and the relevant log from after the update follows
6) The install rebooted. I rebooted. The host rebooted. Everyone gets a reboot.
7) I am using NSA SpyChrome on anything that boots, and here is a description of what is happening when I nothing works using the GUI and Console

Yes, OK I'm a bit salty, I just don't know with whom. Basically this EFA has been working fine for weeks. This morning just before 8am on Monday AEST, it seems MailScanner updated and ever since, on submitting I get "451 4.7.1 Service unavailable - try again later". No mail has been delivered since the update - the last successful message is tagged at 08/07/19 07:57:43 in the GUI. I'm guessing it's related, but I am also now seeing an error in the MailScanner web UI:

Please verify read permissions on /var/spool/MailScanner/milterin and /var/spool/MailScanner/milterout

Disk space seems OK:

Code: Select all

Filesystem     Free Disk Space
/                 6.29GB [79%]
/boot            186.1MB [39%]
/tmp            981.64MB [97%]
/var             29.14GB [44%]
/tmp            981.64MB [97%]
/var/tmp         29.14GB [44%]
/var/log/messages from 7:57am today, when it seems mail stopped working (last successful receipt 7:57am)

Code: Select all

Jul  8 07:56:38 efa yum[11353]: Updated: MailScanner.noarch 5.1.4-1
Jul  8 07:56:46 efa kernel: SELinux:  Class bpf not defined in policy.
Jul  8 07:56:46 efa kernel: SELinux: the above unknown classes and permissions will be allowed
Jul  8 07:56:48 efa dbus[3542]: [system] Reloaded configuration
Jul  8 07:56:49 efa kernel: SELinux:  Class bpf not defined in policy.
Jul  8 07:56:49 efa kernel: SELinux: the above unknown classes and permissions will be allowed
Jul  8 07:56:50 efa dbus[3542]: [system] Reloaded configuration
Jul  8 07:56:54 efa kernel: SELinux:  Class bpf not defined in policy.
Jul  8 07:56:54 efa kernel: SELinux: the above unknown classes and permissions will be allowed
Jul  8 07:56:56 efa dbus[3542]: [system] Reloaded configuration
Jul  8 07:56:57 efa kernel: SELinux:  Class bpf not defined in policy.
Jul  8 07:56:57 efa kernel: SELinux: the above unknown classes and permissions will be allowed
Jul  8 07:56:58 efa dbus[3542]: [system] Reloaded configuration
Jul  8 07:56:58 efa systemd: Reloading.
Jul  8 07:56:58 efa systemd: Reloading The Apache HTTP Server.
Jul  8 07:56:58 efa systemd: Reloaded The Apache HTTP Server.
Jul  8 07:56:58 efa systemd: Reloading The PHP FastCGI Process Manager.
Jul  8 07:56:58 efa systemd: Reloaded The PHP FastCGI Process Manager.
Jul  8 07:56:58 efa systemd: Reloading Postfix Mail Transport Agent.
Jul  8 07:56:58 efa httpd: Server configured, listening on: port 443, port 80
Jul  8 07:56:58 efa systemd: Reloaded Postfix Mail Transport Agent.
Jul  8 07:56:59 efa systemd: Stopping SQLgrey Postfix Grey-listing Policy service...
Jul  8 07:56:59 efa systemd: Stopped SQLgrey Postfix Grey-listing Policy service.
Jul  8 07:56:59 efa systemd: Starting SQLgrey Postfix Grey-listing Policy service...
Jul  8 07:56:59 efa systemd: Started SQLgrey Postfix Grey-listing Policy service.
Jul  8 07:56:59 efa systemd: Stopping Generic clamav scanner daemon...
Jul  8 07:57:00 efa clamd[14300]: --- Stopped at Mon Jul  8 07:57:00 2019
Jul  8 07:57:00 efa clamd[14300]: Socket file removed.
Jul  8 07:57:00 efa systemd: Stopped Generic clamav scanner daemon.
Jul  8 07:57:00 efa systemd: Starting Generic clamav scanner daemon...
Jul  8 07:57:00 efa clamd[48513]: Received 0 file descriptor(s) from systemd.
Jul  8 07:57:00 efa clamd[48513]: clamd daemon 0.101.2 (OS: linux-gnu, ARCH: x86_64, CPU: x86_64)
Jul  8 07:57:00 efa clamd[48513]: Running as user clamscan (UID 993, GID 990)
Jul  8 07:57:00 efa clamd[48513]: Log file size limited to 1048576 bytes.
Jul  8 07:57:00 efa clamd[48513]: Reading databases from /var/lib/clamav
Jul  8 07:57:00 efa clamd[48513]: Not loading PUA signatures.
Jul  8 07:57:00 efa clamd[48513]: Bytecode: Security mode set to "TrustSigned".
Jul  8 07:57:01 efa systemd: Started Session 136894 of user root.
Jul  8 07:57:01 efa systemd: Started Session 136895 of user root.
Jul  8 07:57:28 efa clamd[48513]: Loaded 6335804 signatures.
Jul  8 07:57:28 efa clamd[48513]: LOCAL: Unix socket file /var/run/clamd.socket/clamd.sock
Jul  8 07:57:28 efa clamd[48513]: LOCAL: Setting connection queue length to 200
Jul  8 07:57:28 efa clamd[48651]: Limits: Global size limit set to 104857600 bytes.
Jul  8 07:57:28 efa clamd[48651]: Limits: File size limit set to 26214400 bytes.
Jul  8 07:57:28 efa clamd[48651]: Limits: Recursion level limit set to 16.
Jul  8 07:57:28 efa clamd[48651]: Limits: Files limit set to 10000.
Jul  8 07:57:28 efa clamd[48651]: Limits: MaxEmbeddedPE limit set to 10485760 bytes.
Jul  8 07:57:28 efa clamd[48651]: Limits: MaxHTMLNormalize limit set to 10485760 bytes.
Jul  8 07:57:28 efa clamd[48651]: Limits: MaxHTMLNoTags limit set to 2097152 bytes.
Jul  8 07:57:28 efa clamd[48651]: Limits: MaxScriptNormalize limit set to 5242880 bytes.
Jul  8 07:57:28 efa clamd[48651]: Limits: MaxZipTypeRcg limit set to 1048576 bytes.
Jul  8 07:57:28 efa clamd[48651]: Limits: MaxPartitions limit set to 50.
Jul  8 07:57:28 efa clamd[48651]: Limits: MaxIconsPE limit set to 100.
Jul  8 07:57:28 efa clamd[48651]: Limits: MaxRecHWP3 limit set to 16.
Jul  8 07:57:28 efa clamd[48651]: Limits: PCREMatchLimit limit set to 100000.
Jul  8 07:57:28 efa clamd[48651]: Limits: PCRERecMatchLimit limit set to 2000.
Jul  8 07:57:28 efa clamd[48651]: Limits: PCREMaxFileSize limit set to 26214400.
Jul  8 07:57:28 efa clamd[48651]: Archive support enabled.
Jul  8 07:57:28 efa clamd[48651]: AlertExceedsMax heuristic detection disabled.
Jul  8 07:57:28 efa clamd[48651]: Heuristic alerts enabled.
Jul  8 07:57:28 efa clamd[48651]: Portable Executable support enabled.
Jul  8 07:57:28 efa clamd[48651]: ELF support enabled.
Jul  8 07:57:28 efa clamd[48651]: Mail files support enabled.
Jul  8 07:57:28 efa clamd[48651]: OLE2 support enabled.
Jul  8 07:57:28 efa clamd[48651]: PDF support enabled.
Jul  8 07:57:28 efa clamd[48651]: SWF support enabled.
Jul  8 07:57:28 efa clamd[48651]: HTML support enabled.
Jul  8 07:57:28 efa clamd[48651]: XMLDOCS support enabled.
Jul  8 07:57:28 efa clamd[48651]: HWP3 support enabled.
Jul  8 07:57:28 efa clamd[48651]: Self checking every 600 seconds.
Jul  8 07:57:30 efa systemd: Started Generic clamav scanner daemon.
Jul  8 07:57:30 efa systemd: Stopping LSB: MailScanner daemon...
Jul  8 07:57:34 efa ms-init: MailScanner stopped
Jul  8 07:57:34 efa systemd: Stopped LSB: MailScanner daemon.
Jul  8 07:57:34 efa systemd: Starting LSB: MailScanner daemon...
Jul  8 07:57:34 efa ms-init: MailScanner starting ...
Jul  8 07:57:36 efa MailScanner: MailScanner setting GID to postfix (89)
Jul  8 07:57:36 efa MailScanner: MailScanner setting UID to postfix (89)
Jul  8 07:57:37 efa ms-init: MailScanner started with process id 49297
Jul  8 07:57:37 efa systemd: Started LSB: MailScanner daemon.
Jul  8 07:57:37 efa systemd: Stopping LSB: MSMilter daemon...
Jul  8 07:57:37 efa msmilter-init: /usr/lib/MailScanner/init/msmilter-init: line 68: MilterPIDFile: command not found
Jul  8 07:57:37 efa msmilter-init: MSMilter stopped
Jul  8 07:57:37 efa systemd: Stopped LSB: MSMilter daemon.
Jul  8 07:57:37 efa systemd: Starting LSB: MSMilter daemon...
Jul  8 07:57:37 efa msmilter-init: /usr/lib/MailScanner/init/msmilter-init: line 68: MilterPIDFile: command not found
Jul  8 07:57:37 efa msmilter-init: MSMilter starting ...
Jul  8 07:57:38 efa msmilter-init: Trying to setlogsock(unix)
Jul  8 07:57:39 efa msmilter-init: MSMilter started with process id 49323
Jul  8 07:57:39 efa systemd: Started LSB: MSMilter daemon.
Jul  8 07:57:39 efa systemd: Reloading.
Jul  8 07:57:39 efa systemd: Reloading.
Jul  8 07:57:39 efa systemd: Stopping MariaDB 10.1 database server...
Jul  8 07:57:42 efa systemd: Stopped MariaDB 10.1 database server.
Jul  8 07:57:42 efa systemd: Starting MariaDB 10.1 database server...
Jul  8 07:57:42 efa mysql-prepare-db-dir: Database MariaDB is probably initialized in /var/lib/mysql already, nothing is done.
Jul  8 07:57:42 efa mysql-prepare-db-dir: If this is not the case, make sure the /var/lib/mysql is empty before running mysql-prepare-db-dir.
Jul  8 07:57:42 efa mysqld: 2019-07-08  7:57:42 139942991419648 [Note] /usr/libexec/mysqld (mysqld 10.1.35-MariaDB) starting as process 49439 ...
Jul  8 07:57:43 efa php: PHP Warning:  Error while sending QUERY packet. PID=14894 in /var/www/html/mailscanner/functions.php on line 1057
Jul  8 07:57:43 efa php: Warning: Error while sending QUERY packet. PID=14894 in /var/www/html/mailscanner/functions.php on line 1057
Jul  8 07:57:43 efa php: PHP Fatal error:  Uncaught mysqli_sql_exception: MySQL server has gone away in /var/www/html/mailscanner/functions.php:1057#012Stack trace:#012#0 /var/www/html/mailscanner/functions.php(1057): mysqli->query('SELECT id from ...')#012#1 /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php(75): dbquery('SELECT id from ...')#012#2 /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php(97): doittail('tail -F -n0 /va...')#012#3 {main}#012  thrown in /var/www/html/mailscanner/functions.php on line 1057
Jul  8 07:57:43 efa php: Fatal error: Uncaught mysqli_sql_exception: MySQL server has gone away in /var/www/html/mailscanner/functions.php:1057
Jul  8 07:57:43 efa php: Stack trace:
Jul  8 07:57:43 efa php: #0 /var/www/html/mailscanner/functions.php(1057): mysqli->query('SELECT id from ...')
Jul  8 07:57:43 efa php: #1 /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php(75): dbquery('SELECT id from ...')
Jul  8 07:57:43 efa php: #2 /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php(97): doittail('tail -F -n0 /va...')
Jul  8 07:57:43 efa php: #3 {main}
Jul  8 07:57:43 efa php: thrown in /var/www/html/mailscanner/functions.php on line 1057
Jul  8 07:57:43 efa php: tail: write error: Broken pipe
Jul  8 07:57:43 efa php: tail: write error
Jul  8 07:57:43 efa systemd: milter_relay.service: main process exited, code=exited, status=255/n/a
Jul  8 07:57:43 efa systemd: Unit milter_relay.service entered failed state.
Jul  8 07:57:43 efa systemd: milter_relay.service failed.
Jul  8 07:57:43 efa systemd: milter_relay.service holdoff time over, scheduling restart.
Jul  8 07:57:43 efa systemd: Stopped Postfix relay service for MailWatch.
Jul  8 07:57:43 efa systemd: Started Postfix relay service for MailWatch.
Jul  8 07:57:43 efa systemd: Started MariaDB 10.1 database server.
Jul  8 07:57:43 efa yum[11353]: Updated: eFa.x86_64 1:4.0.0-62.eFa.el7
Jul  8 07:57:43 efa php: PHP Warning:  Error while sending QUERY packet. PID=14892 in /var/www/html/mailscanner/functions.php on line 1057
Jul  8 07:57:43 efa php: PHP Fatal error:  Uncaught mysqli_sql_exception: MySQL server has gone away in /var/www/html/mailscanner/functions.php:1057#012Stack trace:#012#0 /var/www/html/mailscanner/functions.php(1057): mysqli->query('REPLACE INTO mt...')#012#1 /var/www/html/mailscanner/mtalogprocessor.inc.php(142): dbquery('REPLACE INTO mt...')#012#2 /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_postfix_relay.php(99): MtaLogProcessor->doit('tail -F -n0 /va...')#012#3 {main}#012  thrown in /var/www/html/mailscanner/functions.php on line 1057
Jul  8 07:57:43 efa php: Warning: Error while sending QUERY packet. PID=14892 in /var/www/html/mailscanner/functions.php on line 1057
Jul  8 07:57:43 efa php: Fatal error: Uncaught mysqli_sql_exception: MySQL server has gone away in /var/www/html/mailscanner/functions.php:1057
Jul  8 07:57:43 efa php: Stack trace:
Jul  8 07:57:43 efa php: #0 /var/www/html/mailscanner/functions.php(1057): mysqli->query('REPLACE INTO mt...')
Jul  8 07:57:43 efa php: #1 /var/www/html/mailscanner/mtalogprocessor.inc.php(142): dbquery('REPLACE INTO mt...')
Jul  8 07:57:43 efa php: #2 /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_postfix_relay.php(99): MtaLogProcessor->doit('tail -F -n0 /va...')
Jul  8 07:57:43 efa php: #3 {main}
Jul  8 07:57:43 efa php: thrown in /var/www/html/mailscanner/functions.php on line 1057
Jul  8 07:57:44 efa php: tail: write error: Broken pipe
Jul  8 07:57:44 efa php: tail: write error
Jul  8 07:57:44 efa systemd: postfix_relay.service: main process exited, code=exited, status=255/n/a
Jul  8 07:57:44 efa systemd: Unit postfix_relay.service entered failed state.
Jul  8 07:57:44 efa systemd: postfix_relay.service failed.
Jul  8 07:57:44 efa systemd: postfix_relay.service holdoff time over, scheduling restart.
Jul  8 07:57:44 efa systemd: Stopped Postfix relay service for MailWatch.
Jul  8 07:57:44 efa systemd: Started Postfix relay service for MailWatch.
Jul  8 07:58:01 efa systemd: Started Session 136896 of user root.
Jul  8 07:58:01 efa systemd: Started Session 136897 of user root.
Jul  8 07:58:17 efa MailScanner: Process did not exit cleanly, returned 1 with signal 0
Jul  8 07:58:19 efa MailScanner: Process did not exit cleanly, returned 1 with signal 0
Jul  8 07:58:21 efa MailScanner: Process did not exit cleanly, returned 1 with signal 0
Jul  8 07:58:23 efa MailScanner: Process did not exit cleanly, returned 1 with signal 0
Jul  8 07:58:25 efa MailScanner: Process did not exit cleanly, returned 1 with signal 0
Jul  8 07:58:27 efa MailScanner: Process did not exit cleanly, returned 1 with signal 0
Jul  8 07:58:29 efa MailScanner: Process did not exit cleanly, returned 1 with signal 0
Jul  8 07:58:31 efa MailScanner: Process did not exit cleanly, returned 1 with signal 0
Jul  8 07:58:33 efa MailScanner: Process did not exit cleanly, returned 1 with signal 0
Jul  8 07:58:35 efa MailScanner: Process did not exit cleanly, returned 1 with signal 0
Jul  8 07:58:37 efa MailScanner: Process did not exit cleanly, returned 1 with signal 0
Jul  8 07:58:39 efa msmilter-init: Use of uninitialized value $rc in string eq at /usr/share/perl5/vendor_perl/Sendmail/PMilter/Context.pm line 360.
Jul  8 07:58:39 efa msmilter-init: Use of uninitialized value $rc in string eq at /usr/share/perl5/vendor_perl/Sendmail/PMilter/Context.pm line 362.
Jul  8 07:58:39 efa msmilter-init: Use of uninitialized value $rc in string eq at /usr/share/perl5/vendor_perl/Sendmail/PMilter/Context.pm line 364.
Jul  8 07:58:39 efa msmilter-init: Use of uninitialized value $rc in string eq at /usr/share/perl5/vendor_perl/Sendmail/PMilter/Context.pm line 366.
Jul  8 07:58:39 efa msmilter-init: Use of uninitialized value $rc in string eq at /usr/share/perl5/vendor_perl/Sendmail/PMilter/Context.pm line 372.
Jul  8 07:58:39 efa msmilter-init: Use of uninitialized value $rc in concatenation (.) or string at /usr/share/perl5/vendor_perl/Sendmail/PMilter/Context.pm line 379.
Jul  8 07:58:39 efa msmilter-init: invalid callback return  at /usr/share/perl5/vendor_perl/Sendmail/PMilter/Context.pm line 379.
So ... I'm wondering if I need to rollback MailScanner to an earlier version somehow (I don't know how yet). Or perhaps there's some config missing or broken? Or do I need to force another update? I'm kinda loathe to do anything till I know more about what's wrong.

For reference, line 68 of /usr/lib/MailScanner/init/msmilter-init reads:

Code: Select all

PIDFILE="`${QUICKPEEK} MilterPIDFile ${ms_conf}`"
I don't have the files /var/spool/MailScanner/milterin and /var/spool/MailScanner/milterout on this system or on the other 3.0.2.6 system I have available to me, so I can't immediately tell if those are files or directories to create empty and see if it's fixed.

Suggestions welcome, as we've switched back to no anti-spam and the natives are getting restless!
User avatar
shawniverson
Posts: 3644
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: Something updated 8-Jul 8am GMT+10, now it's broken

Post by shawniverson »

Force another update. That should fix your issue.

You need the following packages at these versions:

eFa-4.0.0-64.eFa.el7.x86_64
MailScanner-5.1.4-1.efa.2.noarch
User avatar
DavidRa
Posts: 30
Joined: 24 Dec 2012 08:29
Location: Sydney, AU
Contact:

Re: Something updated 8-Jul 8am GMT+10, now it's broken

Post by DavidRa »

Ah. Is that with yum update or something else? Assuming that fixes it (sounds like it will) is that something that the final v4 release can "work around" - e.g. with a custom yum repo somewhere which only publishes upstream stuff once any extra bits are written/updated?
User avatar
shawniverson
Posts: 3644
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: Something updated 8-Jul 8am GMT+10, now it's broken

Post by shawniverson »

yum update

Yes, a production repo for v4 will be used for the release.
Post Reply