MailWatch periodically stops logs to DB

Bugs in eFa 4
Post Reply
kit400
Posts: 9
Joined: 09 Nov 2020 07:22
Location: Kiev, Ukraine

MailWatch periodically stops logs to DB

Post by kit400 » 09 Nov 2020 10:00

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

User avatar
pdwalker
Posts: 1383
Joined: 18 Mar 2015 09:16

Re: MailWatch periodically stops logs to DB

Post by pdwalker » 12 Nov 2020 08:50

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?

kit400
Posts: 9
Joined: 09 Nov 2020 07:22
Location: Kiev, Ukraine

Re: MailWatch periodically stops logs to DB

Post by kit400 » 14 Nov 2020 09:49

>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 |
+--------+-------------+-----------+-------------+---------+------+--------------------------+------------------+----------+

kit400
Posts: 9
Joined: 09 Nov 2020 07:22
Location: Kiev, Ukraine

Re: MailWatch periodically stops logs to DB

Post by kit400 » 14 Nov 2020 13:26

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'.

User avatar
shawniverson
Posts: 3398
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: MailWatch periodically stops logs to DB

Post by shawniverson » 14 Nov 2020 16:10

Any SELinux denials in /var/log/audit ?

User avatar
shawniverson
Posts: 3398
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: MailWatch periodically stops logs to DB

Post by shawniverson » 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.

Here are the relevant log locations:
/var/log/audit
/var/log/mariadb
/var/log/messages
/var/log/maillog
/var/log/cron
/var/log/dnf

User avatar
shawniverson
Posts: 3398
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: MailWatch periodically stops logs to DB

Post by shawniverson » 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

kit400
Posts: 9
Joined: 09 Nov 2020 07:22
Location: Kiev, Ukraine

Re: MailWatch periodically stops logs to DB

Post by kit400 » 14 Nov 2020 18:07

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

kit400
Posts: 9
Joined: 09 Nov 2020 07:22
Location: Kiev, Ukraine

Re: MailWatch periodically stops logs to DB

Post by kit400 » 14 Nov 2020 20:11

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

kit400
Posts: 9
Joined: 09 Nov 2020 07:22
Location: Kiev, Ukraine

Re: MailWatch periodically stops logs to DB

Post by kit400 » 14 Nov 2020 20:30

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

kit400
Posts: 9
Joined: 09 Nov 2020 07:22
Location: Kiev, Ukraine

Re: MailWatch periodically stops logs to DB

Post by kit400 » 15 Nov 2020 17:43

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
Image

How can I restart MailWatch SQL only?
How can i debug MailWatch SQL?

User avatar
shawniverson
Posts: 3398
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: MailWatch periodically stops logs to DB

Post by shawniverson » 15 Nov 2020 19:24

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.

kit400
Posts: 9
Joined: 09 Nov 2020 07:22
Location: Kiev, Ukraine

Re: MailWatch periodically stops logs to DB

Post by kit400 » 19 Nov 2020 10:09

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

User avatar
shawniverson
Posts: 3398
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: MailWatch periodically stops logs to DB

Post by shawniverson » 19 Nov 2020 13:13


kit400
Posts: 9
Joined: 09 Nov 2020 07:22
Location: Kiev, Ukraine

Re: MailWatch periodically stops logs to DB

Post by kit400 » 05 Mar 2021 11:24

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

User avatar
shawniverson
Posts: 3398
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: MailWatch periodically stops logs to DB

Post by shawniverson » 07 Mar 2021 03:38

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);

Post Reply