Page 1 of 1
MailWatch periodically stops logs to DB
Posted: 09 Nov 2020 10:00
by kit400
First of all, thanks for a great product.
I installed the latest version on Centos 8. Works fine, but MailWatch periodically stops logs to the database. Once every few days, this happens for 2-3 hours. The system works and processes messages correctly.
Only the log to the database and quarantine does not work. After that, it will restore itself and work as usual.
Restarting the services like:
service mailscanner start
service mailscanner status
service mailscanner stop
did not fix this.
What logs to watch and where to get debug info?
Sorry for the stupid questions, I'm new to the system
MailWatch Version: 1.2.15
Operating System Version: CentOS Linux 8 (Core)
Postfix Version: 3.4.8
MailScanner Version: 5.3.3
ClamAV Version: 0.102.4
SpamAssassin Version: 3.4.4
PHP Version: 7.2.24
MySQL Version: 10.3.17-MariaDB
GeoIP Database Version: GeoLite2 Country database 2018-06-07 23:38:29
Rebooting the OS fixes this
Re: MailWatch periodically stops logs to DB
Posted: 12 Nov 2020 08:50
by pdwalker
Without more information, it's very hard to debug this.
Is there anything in the mysql log files? how about the System log files? Is the database still running? what does "mysqladmin processlist" show?
Re: MailWatch periodically stops logs to DB
Posted: 14 Nov 2020 09:49
by kit400
>Is there anything in the mysql log files? Is the database still running?
Mysql OK
Code: Select all
service mysql status
Redirecting to /bin/systemctl status mysql.service
● mariadb.service - MariaDB 10.3 database server
Loaded: loaded (/usr/lib/systemd/system/mariadb.service; enabled; vendor preset: disabled)
Drop-In: /etc/systemd/system/mariadb.service.d
└─limit.conf, override.conf
Active: active (running) since Sun 2020-11-08 23:22:50 EET; 5 days ago
Docs: man:mysqld(8)
https://mariadb.com/kb/en/library/systemd/
Main PID: 1360 (mysqld)
Status: "Taking your SQL requests now..."
Tasks: 37 (limit: 49583)
Memory: 829.1M
CGroup: /system.slice/mariadb.service
└─1360 /usr/libexec/mysqld --basedir=/usr
MailWath web interface works good.
postfix and MailScanner - ok
Nov 14 11:32:10 ms postfix/smtpd[1828992]: disconnect from smtp479.emlone.com[84.237.210.165] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Nov 14 11:32:13 ms MailScanner[1816991]: New Batch: Scanning 1 messages, 110890 bytes
Nov 14 11:32:13 ms MailScanner[1816991]: Virus and Content Scanning: Starting
Nov 14 11:32:13 ms MailScanner[1816991]: <A> tag found in message 4CY98n2JQZzP3FRk from
postman221788@emluni.com
Nov 14 11:32:13 ms MailScanner[1816991]: HTML Img tag found in message 4CY98n2JQZzP3FRk from
postman221788@emluni.com
Nov 14 11:32:13 ms MailScanner[1816991]: Spam Checks: Starting
Nov 14 11:32:13 ms MailScanner[1816991]: Message 4CY98n2JQZzP3FRk from 84.237.210.165 (
postman221788@emluni.com) to ukrpack.net is spam (blacklisted)
Nov 14 11:32:13 ms MailScanner[1816991]: Spam Checks: Found 1 spam messages
Nov 14 11:32:13 ms MailScanner[1816991]: Spam Actions: message 4CY98n2JQZzP3FRk actions are store
Nov 14 11:32:13 ms MailScanner[1816991]: Deleted 1 messages from processing-database
Nov 14 11:32:13 ms MailScanner[1816991]: MailWatch: DEBUG: var reports: $VAR1 = '';
Nov 14 11:32:13 ms MailScanner[1816991]: MailWatch: Logging message 4CY98n2JQZzP3FRk to SQL
>how about the System log files?
All clear.
what does "mysqladmin processlist" show?
Code: Select all
mysql -e " show processlist"
+--------+-------------+-----------+-------------+---------+------+--------------------------+------------------+----------+
| Id | User | Host | db | Command | Time | State | Info | Progress |
+--------+-------------+-----------+-------------+---------+------+--------------------------+------------------+----------+
| 1 | system user | | NULL | Daemon | NULL | InnoDB purge coordinator | NULL | 0.000 |
| 2 | system user | | NULL | Daemon | NULL | InnoDB purge worker | NULL | 0.000 |
| 3 | system user | | NULL | Daemon | NULL | InnoDB purge worker | NULL | 0.000 |
| 4 | system user | | NULL | Daemon | NULL | InnoDB purge worker | NULL | 0.000 |
| 5 | system user | | NULL | Daemon | NULL | InnoDB shutdown handler | NULL | 0.000 |
| 15946 | mailwatch | localhost | mailscanner | Sleep | 6 | | NULL | 0.000 |
| 184574 | mailwatch | localhost | mailscanner | Sleep | 17 | | NULL | 0.000 |
| 184575 | root | localhost | NULL | Query | 0 | Init | show processlist | 0.000 |
+--------+-------------+-----------+-------------+---------+------+--------------------------+------------------+----------+
Re: MailWatch periodically stops logs to DB
Posted: 14 Nov 2020 13:26
by kit400
systemctl --type=service
Code: Select all
UNIT LOAD ACTIVE SUB DESCRIPTION
adcc.service loaded active exited LSB: DCC daemons providing mail filtering
atd.service loaded active running Job spooling tools
auditd.service loaded active running Security Auditing Service
chronyd.service loaded active running NTP client/server
clamd@scan.service loaded active running clamd scanner (scan) daemon
crond.service loaded active running Command Scheduler
dbus.service loaded active running D-Bus System Message Bus
dovecot.service loaded active running Dovecot IMAP/POP3 email server
dracut-shutdown.service loaded active exited Restore /run/initramfs on shutdown
fail2ban.service loaded active running Fail2Ban Service
firewalld.service loaded active running firewalld - dynamic firewall daemon
getty@tty1.service loaded active running Getty on tty1
httpd.service loaded active running The Apache HTTP Server
import-state.service loaded active exited Import network configuration from initramfs
irqbalance.service loaded active running irqbalance daemon
kdump.service loaded active exited Crash recovery kernel arming
kmod-static-nodes.service loaded active exited Create list of required static device nodes for the current kernel
libstoragemgmt.service loaded active running libstoragemgmt plug-in server daemon
lvm2-monitor.service loaded active exited Monitoring of LVM2 mirrors, snapshots etc. using dmeventd or progress polling
mailscanner.service loaded active running LSB: MailScanner daemon
mariadb.service loaded active running MariaDB 10.3 database server
mcelog.service loaded active running Machine Check Exception Logging Daemon
milter_relay.service loaded active running Postfix relay service for MailWatch
msmilter.service loaded active running LSB: MSMilter daemon
NetworkManager-wait-online.service loaded active exited Network Manager Wait Online
NetworkManager.service loaded active running Network Manager
nis-domainname.service loaded active exited Read and set NIS domainname from /etc/sysconfig/network
opendkim.service loaded active running DomainKeys Identified Mail (DKIM) Milter
opendmarc.service loaded active running Domain-based Message Authentication, Reporting & Conformance (DMARC) Milter
php-fpm.service loaded active running The PHP FastCGI Process Manager
polkit.service loaded active running Authorization Manager
postfix.service loaded active running Postfix Mail Transport Agent
postfix_relay.service loaded active running Postfix relay service for MailWatch
rc-local.service loaded active exited /etc/rc.d/rc.local Compatibility
rngd-wake-threshold.service loaded active exited Hardware RNG Entropy Gatherer Wake threshold service
rngd.service loaded active running Hardware RNG Entropy Gatherer Daemon
rsyslog.service loaded active running System Logging Service
selinux-autorelabel-mark.service loaded active exited Mark the need to relabel after reboot
smartd.service loaded active running Self Monitoring and Reporting Technology (SMART) Daemon
smb.service loaded active running Samba SMB Daemon
sshd.service loaded active running OpenSSH server daemon
sssd.service loaded active running System Security Services Daemon
sysstat.service loaded active exited Resets System Activity Logs
systemd-fsck@dev-disk-by\x2duuid-5d20c330\x2df9f0\x2d4a4e\x2da63d\x2de2b7ab372e0f.service loaded active exited File System Check on /dev/disk/by-uuid/5d20c330-f9f0-4a4e-a63d-e2b7ab372e0f
systemd-fsck@dev-disk-by\x2duuid-93A5\x2d15B1.service loaded active exited File System Check on /dev/disk/by-uuid/93A5-15B1
systemd-journal-flush.service loaded active exited Flush Journal to Persistent Storage
systemd-journald.service loaded active running Journal Service
systemd-logind.service loaded active running Login Service
systemd-modules-load.service loaded active exited Load Kernel Modules
systemd-random-seed.service loaded active exited Load/Save Random Seed
systemd-remount-fs.service loaded active exited Remount Root and Kernel File Systems
systemd-resolved.service loaded active running Network Name Resolution
systemd-sysctl.service loaded active exited Apply Kernel Variables
systemd-tmpfiles-setup-dev.service loaded active exited Create Static Device Nodes in /dev
systemd-tmpfiles-setup.service loaded active exited Create Volatile Files and Directories
systemd-udev-trigger.service loaded active exited udev Coldplug all Devices
systemd-udevd.service loaded active running udev Kernel Device Manager
systemd-update-utmp.service loaded active exited Update UTMP about System Boot/Shutdown
systemd-user-sessions.service loaded active exited Permit User Sessions
tuned.service loaded active running Dynamic System Tuning Daemon
unbound.service loaded active running Unbound recursive Domain Name Server
user-runtime-dir@0.service loaded active exited /run/user/0 mount wrapper
user-runtime-dir@1000.service loaded active exited /run/user/1000 mount wrapper
user-runtime-dir@1001.service loaded active exited /run/user/1001 mount wrapper
user@0.service loaded active running User Manager for UID 0
user@1000.service loaded active running User Manager for UID 1000
user@1001.service loaded active running User Manager for UID 1001
vdo.service loaded active exited VDO volume services
vgauthd.service loaded active running VGAuth Service for open-vm-tools
vmtoolsd.service loaded active running Service for virtual machines hosted on VMware
LOAD = Reflects whether the unit definition was properly loaded.
ACTIVE = The high-level unit activation state, i.e. generalization of SUB.
SUB = The low-level unit activation state, values depend on unit type.
70 loaded units listed. Pass --all to see loaded but inactive units, too.
To show all installed unit files use 'systemctl list-unit-files'.
Re: MailWatch periodically stops logs to DB
Posted: 14 Nov 2020 16:10
by shawniverson
Any SELinux denials in /var/log/audit ?
Re: MailWatch periodically stops logs to DB
Posted: 14 Nov 2020 16:16
by shawniverson
That everything else is operating normally narrows this problem to something going on between mailscanner and/or mariadb.
Try to identify a pattern. When it fails for this period, is it during the same window of time?
Capture logs around and during the time the logging stops.
Here are the relevant log locations:
/var/log/audit
/var/log/mariadb
/var/log/messages
/var/log/maillog
/var/log/cron
/var/log/dnf
Re: MailWatch periodically stops logs to DB
Posted: 14 Nov 2020 16:18
by shawniverson
Also, check the system date and time during the failure for any time anomalies such as an unexpected jump in the system clock
Re: MailWatch periodically stops logs to DB
Posted: 14 Nov 2020 18:07
by kit400
shawniverson wrote: ↑14 Nov 2020 16:10
Any SELinux denials in /var/log/audit ?
disabled at all
Code: Select all
[root@ms ~]# sestatus
SELinux status: disabled
[root@ms ~]# cat /etc/selinux/config
# This file controls the state of SELinux on the system.
# SELINUX= can take one of these three values:
# enforcing - SELinux security policy is enforced.
# permissive - SELinux prints warnings instead of enforcing.
# disabled - No SELinux policy is loaded.
SELINUX=disabled
Re: MailWatch periodically stops logs to DB
Posted: 14 Nov 2020 20:11
by kit400
shawniverson wrote: ↑14 Nov 2020 16:16
That everything else is operating normally narrows this problem to something going on between mailscanner and/or mariadb.
Try to identify a pattern. When it fails for this period, is it during the same window of time?
Capture logs around and during the time the logging stops.
Random time.
I wrote a watchdog that sends an alert to telegram if this happens, but so far I could not find anything in the logs. After reboot everything is restored.
sysinfo from alert:
Code: Select all
------------------------------------------------------------------
No new mails at ms.*****
last one was 2020-11-14 10:55:13
------------------------------------------------------------------
================= netstat ===================
1 FIN_WAIT2
5 ESTABLISHED
8 TIME_WAIT
14 CLOSE_WAIT
29 LISTEN
================== http ===================
7
================== mysql ===================
2
+--------+-------------+-----------+-------------+---------+------+--------------------------+------------------+----------+
| Id | User | Host | db | Command | Time | State | Info | Progress |
+--------+-------------+-----------+-------------+---------+------+--------------------------+------------------+----------+
| 1 | system user | | | Daemon | | InnoDB purge coordinator | | 0.000 |
| 2 | system user | | | Daemon | | InnoDB purge worker | | 0.000 |
| 3 | system user | | | Daemon | | InnoDB purge worker | | 0.000 |
| 4 | system user | | | Daemon | | InnoDB purge worker | | 0.000 |
| 5 | system user | | | Daemon | | InnoDB shutdown handler | | 0.000 |
| 15946 | mailwatch | localhost | mailscanner | Sleep | 48 | | | 0.000 |
| 184164 | mailwatch | localhost | mailscanner | Sleep | 4 | | | 0.000 |
| 184168 | root | localhost | | Query | 0 | Init | show processlist | 0.000 |
+--------+-------------+-----------+-------------+---------+------+--------------------------+------------------+----------+
================== free ===================
total used free shared buff/cache available
Mem: 7996620 3514716 282452 379052 4199452 3797560
Swap: 8292348 6400 8285948
Filesystem Size Used Avail Use% Mounted on
devtmpfs 3.8G 0 3.8G 0% /dev
tmpfs 3.9G 0 3.9G 0% /dev/shm
tmpfs 3.9G 369M 3.5G 10% /run
tmpfs 3.9G 0 3.9G 0% /sys/fs/cgroup
/dev/sda4 141G 22G 120G 16% /
none 3.9G 964K 3.9G 1% /var/spool/MailScanner/incoming
/dev/sda2 976M 171M 739M 19% /boot
/dev/sda1 599M 6.9M 592M 2% /boot/efi
tmpfs 781M 0 781M 0% /run/user/0
tmpfs 781M 0 781M 0% /run/user/1001
tmpfs 781M 0 781M 0% /run/user/1000
=============== uptime who ==================
11:15:01 up 5 days, 11:52, 2 users, load average: 0.12, 0.06, 0.02
USER TTY FROM LOGIN@ IDLE JCPU PCPU WHAT
*** pts/0 ******* Thu16 42:55m 0.06s 0.02s -bash
*** pts/1 ******* 09:01 2:12m 0.08s 0.12s sshd: *** [priv]
================== ps --sort %cpu ==========
0.0 1828523 root 268036 ps -eo pcpu,pid,user,vsize,args --sort %cpu
0.0 1828524 root 217080 tail -10
0.1 2072 unbound 315696 /usr/sbin/unbound -d
0.1 1814324 postfix 586900 MailScanner: waiting for messages
0.2 1065 root 512696 /usr/libexec/platform-python -s /usr/sbin/firewalld --nofork --nopid
0.2 1115 root 1552584 /usr/bin/python3.6 -s /usr/bin/fail2ban-server -xf start
0.5 1828399 sshd 86708 sshd: unknown [net]
0.8 1360 mysql 3694264 /usr/libexec/mysqld --basedir=/usr
1.6 2430 clamscan 2207428 /usr/sbin/clamd -c /etc/clamd.d/scan.conf
=============== ps --sort memory Usage +====
0.2 1115 root 1552584 /usr/bin/python3.6 -s /usr/bin/fail2ban-server -xf start
0.0 871 polkitd 1762064 /usr/lib/polkit-1/polkitd --no-debug
0.0 2081 opendma+ 2120520 /usr/sbin/opendmarc -c /etc/opendmarc.conf -P /var/run/opendmarc/opendmarc.pid
0.0 2096 opendkim 2178428 /usr/sbin/opendkim -x /etc/opendkim.conf -P /var/run/opendkim/opendkim.pid
1.6 2430 clamscan 2207428 /usr/sbin/clamd -c /etc/clamd.d/scan.conf
0.0 2202 apache 2436744 /usr/sbin/httpd -DFOREGROUND
0.0 3248 apache 2436744 /usr/sbin/httpd -DFOREGROUND
0.0 2201 apache 2502280 /usr/sbin/httpd -DFOREGROUND
0.0 2203 apache 2633416 /usr/sbin/httpd -DFOREGROUND
0.8 1360 mysql 3694264 /usr/libexec/mysqld --basedir=/usr
================== iostat ===================
Linux 4.18.0-193.19.1.el8_2.x86_64 (ms.******) 11/14/2020 _x86_64_ (4 CPU)
avg-cpu: %user %nice %system %iowait %steal %idle
1.56 0.01 0.63 0.11 0.00 97.69
Device tps kB_read/s kB_wrtn/s kB_read kB_wrtn
sda 9.69 11.37 224.14 5400116 106412108
scd0 0.00 0.00 0.00 1040 0
Re: MailWatch periodically stops logs to DB
Posted: 14 Nov 2020 20:30
by kit400
shawniverson wrote: ↑14 Nov 2020 16:18
Also, check the system date and time during the failure for any time anomalies such as an unexpected jump in the system clock
Ok. I've installed chronyd.
But I don't think this is a problem.
I save the state of the system as in the post above every minute.
Code: Select all
...
NAME=`date +%Y.%m.%d`
NAME2=`date +%H-%M`
/home/myuser/bin/report/all > $DIR/$NAME-$NAME2
and they are all in place with the correct time
Re: MailWatch periodically stops logs to DB
Posted: 15 Nov 2020 17:43
by kit400
So problem is in mailscanner \ MailWatch SQL
In normal state there are 3 connections to DB
Code: Select all
+-------+-------------+-----------+-------------+---------+------+--------------------------+------------------+----------+
| Id | User | Host | db | Command | Time | State | Info | Progress |
+-------+-------------+-----------+-------------+---------+------+--------------------------+------------------+----------+
| 20 | mailwatch | localhost | mailscanner | Sleep | 147 | | | 0.000 |
| 23792 | mailwatch1 | localhost | mailscanner | Sleep | 150 | | | 0.000 |
| 25591 | mailwatch | localhost | mailscanner | Sleep | 17 | | | 0.000 |
+-------+-------------+-----------+-------------+---------+------+--------------------------+------------------+----------+
When the problem is only 2:
Code: Select all
+-------+-------------+-----------+-------------+---------+------+--------------------------+------------------+----------+
| Id | User | Host | db | Command | Time | State | Info | Progress |
+-------+-------------+-----------+-------------+---------+------+--------------------------+------------------+----------+
| 20 | mailwatch | localhost | mailscanner | Sleep | 6 | | | 0.000 |
| 25948 | mailwatch | localhost | mailscanner | Sleep | 30 | | | 0.000 |
+-------+-------------+-----------+-------------+---------+------+--------------------------+------------------+----------+
I`ve made mailwatch1 mysql usrer with the same grants and chenge it in
/etc/MailScanner/custom/MailWatchConf.pm
at the same time, process
MailWatch SQL disappears and turns into
MailScanner with the same PID
How can I restart MailWatch SQL only?
How can i debug MailWatch SQL?
Re: MailWatch periodically stops logs to DB
Posted: 15 Nov 2020 19:24
by shawniverson
Okay, this is helpful.
"MailWatch SQL" is actually a MailScanner child process running a Custom Function. Can you capture the entire name of the child process beyond the ":" ?
Something is going wrong with this Custom Function and/or the managing child process.
The 3-4 hours is most likely the child dying of old age and re-spawning.
We will need to focus debugging on this child process. Debug mode in MailScanner isn't going to be helpful since it just processes a message and exits.
We probably need to add some additional verbosity to the Custom Function and see if we can capture additional details.
Re: MailWatch periodically stops logs to DB
Posted: 19 Nov 2020 10:09
by kit400
I found an error today
Code: Select all
Nov 19 04:55:26 ms ms-init[1333016]: Could not use Custom Function code MailScanner::CustomConfig::InitMailWatchLogging, it could not be "eval"ed. Make sure the module is correct with perl -wc (Error: DBD::mysql::st execute failed: Incorrect string value: '\xCF\xCA>' for column `mailscanner`.`maillog`.`messageid` at row 1 at /usr/share/MailScanner/perl/custom/MailWatch.pm line 226, <CLIENT> line 2522.
MailWatch.pm line 226 is:
Code: Select all
$$message{messageid});
# This doesn't work in the event we have no connection by now ?
if (!$sth) {
MailScanner::Log::WarnLog("MailWatch: $$message{id}: MailWatch SQL Cannot insert row: %s", $sth->errstr);
} else {
MailScanner::Log::InfoLog("MailWatch: $$message{id}: Logged to MailWatch SQL");
}
# Unset
$message = undef;
in the
sub ListenForMessages
But the services (MailScanner,MailWatch, SQL Log) worked fine after that
Re: MailWatch periodically stops logs to DB
Posted: 19 Nov 2020 13:13
by shawniverson
Re: MailWatch periodically stops logs to DB
Posted: 05 Mar 2021 11:24
by kit400
I think I found a pattern:
Code: Select all
Mar 1 12:58:32 ms MailScanner[20192]: Could not use Custom Function code MailScanner::CustomConfig::InitMailWatchLogging, it could not be "eval"ed. Make sure the module is correct with perl -wc (Error: DBD::mysql::st execute failed: Incorrect string value: '\xAC\xE2\xAF.FR...' for column `mailscanner`.`maillog`.`report` at row 1 at /usr/share/MailScanner/perl/custom/MailWatch.pm line 226, <CLIENT> line 11096.
Mar 5 09:15:11 ms MailScanner[1643745]: Could not use Custom Function code MailScanner::CustomConfig::InitMailWatchLogging, it could not be "eval"ed. Make sure the module is correct with perl -wc (Error: DBD::mysql::st execute failed: Incorrect string value: '\xCF\xCA>' for column `mailscanner`.`maillog`.`messageid` at row 1 at /usr/share/MailScanner/perl/custom/MailWatch.pm line 226, <CLIENT> line 24503.
Mar 5 12:43:02 ms MailScanner[51829]: Could not use Custom Function code MailScanner::CustomConfig::InitMailWatchLogging, it could not be "eval"ed. Make sure the module is correct with perl -wc (Error: DBD::mysql::st execute failed: Incorrect string value: '\x87\xA2i\xE2\xA8_...' for column `mailscanner`.`maillog`.`report` at row 1 at /usr/share/MailScanner/perl/custom/MailWatch.pm line 226, <CLIENT> line 44176.
After these errors the MW stops writing records to the DB
Code: Select all
SHOW CREATE TABLE `mailscanner`.`maillog`;
CREATE TABLE `maillog` (
`maillog_id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
`timestamp` timestamp NULL DEFAULT NULL,
`id` longtext COLLATE utf8mb4_unicode_ci DEFAULT NULL,
`from_address` longtext COLLATE utf8mb4_unicode_ci DEFAULT NULL,
`from_domain` longtext COLLATE utf8mb4_unicode_ci DEFAULT NULL,
`to_address` longtext COLLATE utf8mb4_unicode_ci DEFAULT NULL,
`to_domain` longtext COLLATE utf8mb4_unicode_ci DEFAULT NULL,
`subject` longtext COLLATE utf8mb4_unicode_ci DEFAULT NULL,
`clientip` longtext COLLATE utf8mb4_unicode_ci DEFAULT NULL,
`archive` longtext COLLATE utf8mb4_unicode_ci DEFAULT NULL,
...
`report` longtext COLLATE utf8mb4_unicode_ci DEFAULT NULL,
...
) ENGINE=InnoDB AUTO_INCREMENT=576858 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_unicode_ci
Re: MailWatch periodically stops logs to DB
Posted: 07 Mar 2021 03:38
by shawniverson
So this looks like latin encoded characters trying to be inserted into the database.
Looks like the fix, which is used on the headers and subject fields for the same reason, could also be used on the reports and messageid fields:
/usr/share/MailScanner/perl/custom/MailWatch.pm around line 398:
Code: Select all
$msg{reports} = fix_latin($reports);
...
$msg{messageid} = fix_latin($messageid);