Community
OpenEnergyMonitor

Community

Log Rotate Errors


(John Banks) #1

I have an RPi running emoncms (Oct 2018 image) hostname = watchman

watchman has no emonTx connected. It receives inputs (via wifi) from other instances of emonTX/RPi/emoncms across the site at the inverter, incoming grid meter, etc.

watchman Server Info is below …
Server Info.pdf (230.8 KB)

A couple of days ago, I installed a cron job to do a weekly backup of watchman. I also installed sSMTP so as to receive emails (to my gmail account) regarding this backup cron job. It’s all working fine.

However now each day I’m also receiving an email regarding log rotate errors. See below …
Error Report.pdf (19.2 KB)

Why is this and how to fix the problem?

Any comments or suggestions would be most welcome

Thanks


(Bill Thomson) #2

Here’s some info that may shed some light on things:


(Brian Orpin) #3

Hi @johnbanks,

Just a small point, it is better to post the text of errors etc rather than include PDFs. In addition, the server info copied from the admin page has been specially formatted such that, if just pasted here, will display collapsed, again easier to read and refer to.

I note there are 2 errors a MYSQL and a logrotate error. A quick search on the logrotate error text and I found this https://lornajane.net/posts/2008/Logrotate-Error-on-Ubuntu which might help.


(John Banks) #4

@Bill.Thomson and @borpin

Many thanks for your input - I had just searched the Forum rather than googled globally.

Having done so, I noticed a comment that this problem could be a bug in MariaDB. So, assuming this is the case, we all have this problem but are unaware of it. I checked out my assumption …

My emonpi-node-13 instance of emoncms runs a ‘plain vanilla’ Oct 2018 image without sSMTP (MTA mail transfer agent) installed. The ‘problem’ daily cron job runs at 6:25 hrs and this is the syslog at that time …

Feb 7 06:25:02 emonpi-node-13 liblogging-stdlog: [origin software="rsyslogd" swVersion="8.24.0" x-pid="331" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
Feb 7 06:25:03 emonpi-node-13 CRON[4442]: (CRON) info (No MTA installed, discarding output)

So whatever happens – good, bad or indifferent- is unknown.

However my watchman instance of emoncms does have sSMTP installed. Here is the start of syslog at 6:25 hrs on the same day …

Feb 7 06:25:03 watchman liblogging-stdlog: [origin software="rsyslogd" swVersion="8.24.0" x-pid="311" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
Feb 7 06:25:04 watchman sSMTP[3268]: Creating SSL connection to host
Feb 7 06:25:04 watchman sSMTP[3268]: 220 smtp.gmail.com ESMTP j17sm25157847wrw.0 - gsmtp

Then many additional sSMTP related entries before …

Feb 7 06:25:05 watchman sSMTP[3268]: error: 'Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2 "No such file or directory")'
Feb 7 06:25:05 watchman sSMTP[3268]: Check that mysqld is running and that the socket: '/var/run/mysqld/mysqld.sock' exists!
Feb 7 06:25:05 watchman sSMTP[3268]: error: error running shared postrotate script for '/var/log/mysql/mysql.log /var/log/mysql/mysql-slow.log /var/log/mysql/mariadb-slow.log /var/log/mysql/error.log '
Feb 7 06:25:05 watchman sSMTP[3268]: run-parts: /etc/cron.daily/logrotate exited with return code 1

And then finally …

Feb 7 06:25:06 watchman sSMTP[3268]: Sent mail for [email protected] (221 2.0.0 closing connection j17sm25157847wrw.0 - gsmtp) uid=0 username=root outbytes=1212

And this results in the email I receive daily reporting the logrotate errors.

I decided to eliminate logrotate by moving its file out of the directory /etc/cron.daily. Next day I received no email reporting logrotate errors. At the scheduled 6:25 hrs run time for cron.daily, syslog then just showed the following …

Feb 8 06:25:01 watchman CRON[15771]: (root) CMD (test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily ))

The problem is not solved but just side stepped. Will I ‘live to regret’ this crude fix?

Any comments most welcome.

Thanks


(Brian Orpin) #5

Hi John, Sorry, cannot add any more to this.


(Bill Thomson) #6

You’re speaking of two separate instances of emonCMS, right?

If that’s the case, why not install an MTA on the node-13 instance?


(Paul) #7

I suspect that might result in 2 servers nagging at him with errors rather than just the one.


(Paul) #8

What does the mysql logrote file contain? It should be located somewhere like /etc/logrotate/logrotate.d/.

Is the OS read only? ie logs in ram. How much disc space is free? The potential issue with not rotating the logs (by deleting the cron) is that the logs could grow to an unmanageable level in a fault condition I guess.


(John Banks) #9

@pb66

The relevant file is /etc/logrotate.d/mysql-server …

# - I put everything in one block and added sharedscripts, so that mysql gets
#   flush-logs'd only once.
#  Else the binary logs would automatically increase by n times every day.
# - The error log is obsolete, messages go to syslog now.
/var/log/mysql/mysql.log /var/log/mysql/mysql-slow.log /var/log/mysql/mariadb-slow.log /var/log/mysql/error.log {
        daily
        rotate 7
        missingok
        create 640 mysql adm
        compress
        sharedscripts
        postrotate
          test -x /usr/bin/mysqladmin || exit 0
          if [ -f `my_print_defaults --mysqld | grep -m 1 -oP "pid-file=\K.+$"` ]; then
            # If this fails, check debian.conf!
            mysqladmin --defaults-file=/etc/mysql/debian.cnf --local flush-error-log \
              flush-engine-log flush-general-log flush-slow-log
          fi
        endscript
}

The OS is rw (mounted defaults) per the Oct2018 image. Disk space is not a problem (OS and data in partitions on a USB spinning hard drive).

I tried a find on “logrotate” but did not discover log or error files. In fact (as above) logrotate errors are sent to syslog.

In summary …

Plain vanilla instances of the Oct2018 image (no MTA) attempt a daily logrotate. Errors occur but the output is discarded per syslog …

Feb 7 06:25:03 emonpi-node-13 CRON[4442]: (CRON) info (No MTA installed, discarding output)

So logrotate does not happen but users are unaware for the most part, I guess.

In the special case of my watchman instance which does have an MTA, I’ve removed logrotate from cron.daily.

In both these cases, logrotate does not happen. So, given the absence of problems reported on the Forum, I’m assuming this is inconsequential.


(John Banks) #10

Sorry about the above - I’ve screwed up the formatting …


(Paul) #11

use triple backticks in the lines before and after a code block eg

    ```
    code
    ```

(Paul) #12

Did you keep a copy of the original?

If so can you try that to see if it is the same?

What is that line # If this fails, check debian.conf!? Have you done that?


(John Banks) #13

There maybe a misunderstanding?

The words “# - I put everything in one block and ~~~~~ etc” are part of the original file /etc/logrotate.d/mysql-server.

I (johnbanks) have changed no files.
/etc/logrotate.d/mysql-server is identical in both my emoncms instances.

Re debian.conf …
There are 2 occurences of debian.conf both of which are different and irrelevant to logrotate.
However it might be a typo for /etc/mysql/debian.cnf …

# Automatically generated for Debian scripts. DO NOT TOUCH!
[client]
host     = localhost
user     = root
password =
socket   = /var/run/mysqld/mysqld.sock
[mysql_upgrade]
host     = localhost
user     = root
password =
socket   = /var/run/mysqld/mysqld.sock
basedir  = /usr

And from my prior googling, I recall a comment about mariaDB creating the file debian.cnf.
And also that this problem could be a bug in MariaDB.
This maybe the definitive link which I’ve only just found …
[https://jira.mariadb.org/browse/MDEV-14367]


(Paul) #14

Ahhh! ok.

So this is something unique to the emonSD image?? I didn’t twig that these were identical images (or that they were emonSD) due to the hostnames or nicknames.

Actually just checked one of mine and it’s the same

[email protected]:~$ cat /etc/logrotate.d/mysql-server
# - I put everything in one block and added sharedscripts, so that mysql gets
#   flush-logs'd only once.
#   Else the binary logs would automatically increase by n times every day.
# - The error log is obsolete, messages go to syslog now.
/var/log/mysql/mysql.log /var/log/mysql/mysql-slow.log /var/log/mysql/mariadb-slow.log /var/log/mysql/error.log {
        daily
        rotate 7
        missingok
        create 640 mysql adm
        compress
        sharedscripts
        postrotate
          test -x /usr/bin/mysqladmin || exit 0
          if [ -f `my_print_defaults --mysqld | grep -m 1 -oP "pid-file=\K.+$"` ]; then
            # If this fails, check debian.conf!
            mysqladmin --defaults-file=/etc/mysql/debian.cnf --local flush-error-log \
              flush-engine-log flush-general-log flush-slow-log
          fi
        endscript
}
[email protected]:~$

I think the “debian.conf” is a typo. the file doesn’t exist and command actually uses debian.cnf directly below. I suspect “I”, whoever “I” is, was referring to the content or existence of debian.cnf rather than a similarly named file, but it isn’t totally clear.

[email protected]:~$ cat /etc/mysql/debian.cnf
cat: /etc/mysql/debian.cnf: Permission denied
[email protected]:~$ sudo cat /etc/mysql/debian.cnf
# Automatically generated for Debian scripts. DO NOT TOUCH!
[client]
host     = localhost
user     = root
password =
socket   = /var/run/mysqld/mysqld.sock
[mysql_upgrade]
host     = localhost
user     = root
password =
socket   = /var/run/mysqld/mysqld.sock
basedir  = /usr
[email protected]:~$ sudo cat /etc/mysql/debian.conf
cat: /etc/mysql/debian.conf: No such file or directory
[email protected]:~$

I wonder if the duplicate content is the issue? I know it says “DO NOT TOUCH!” but is it worth trying an edit?

Do you get any more info if you do a dummy rotate from the command line

sudo logrotate --debug /etc/logrotate.conf

below is the relevant bit of the output I got

rotating pattern: /var/log/mysql/mysql.log /var/log/mysql/mysql-slow.log /var/log/mysql/mariadb-slow.log /var/log/mysql/error.log  after 1 days (7 rotations)
empty log files are rotated, old logs are removed
considering log /var/log/mysql/mysql.log
  log /var/log/mysql/mysql.log does not exist -- skipping
considering log /var/log/mysql/mysql-slow.log
  log /var/log/mysql/mysql-slow.log does not exist -- skipping
considering log /var/log/mysql/mariadb-slow.log
  log /var/log/mysql/mariadb-slow.log does not exist -- skipping
considering log /var/log/mysql/error.log
  Now: 2019-02-08 19:20
  Last rotated at 2019-02-08 06:25
  log does not need rotating (log has been rotated at 2019-2-8 6:25, that is not day ago yet)
not running postrotate script, since no logs were rotated

also check the exit status once it has completed

[email protected]:~$ echo $?
0

anything but a 0 is considered “unsuccessful”

[edit]

A bit of googling and it seems “debug,force and verbose” are the option for properly testing logrotate

sudo logrotate -vdf /etc/logrotate.conf

again here’s the relevant bit from my output

rotating pattern: /var/log/mysql/mysql.log /var/log/mysql/mysql-slow.log /var/log/mysql/mariadb-slow.log /var/log/mysql/error.log  forced from command line (7 rotations)
empty log files are rotated, old logs are removed
considering log /var/log/mysql/mysql.log
  log /var/log/mysql/mysql.log does not exist -- skipping
considering log /var/log/mysql/mysql-slow.log
  log /var/log/mysql/mysql-slow.log does not exist -- skipping
considering log /var/log/mysql/mariadb-slow.log
  log /var/log/mysql/mariadb-slow.log does not exist -- skipping
considering log /var/log/mysql/error.log
  Now: 2019-02-08 19:30
  Last rotated at 2019-02-08 19:29
  log needs rotating
rotating log /var/log/mysql/error.log, log->rotateCount is 7
dateext suffix '-20190208'
glob pattern '-[0-9][0-9][0-9][0-9][0-9][0-9][0-9][0-9]'
renaming /var/log/mysql/error.log.7.gz to /var/log/mysql/error.log.8.gz (rotatecount 7, logstart 1, i 7),
renaming /var/log/mysql/error.log.6.gz to /var/log/mysql/error.log.7.gz (rotatecount 7, logstart 1, i 6),
renaming /var/log/mysql/error.log.5.gz to /var/log/mysql/error.log.6.gz (rotatecount 7, logstart 1, i 5),
renaming /var/log/mysql/error.log.4.gz to /var/log/mysql/error.log.5.gz (rotatecount 7, logstart 1, i 4),
renaming /var/log/mysql/error.log.3.gz to /var/log/mysql/error.log.4.gz (rotatecount 7, logstart 1, i 3),
renaming /var/log/mysql/error.log.2.gz to /var/log/mysql/error.log.3.gz (rotatecount 7, logstart 1, i 2),
renaming /var/log/mysql/error.log.1.gz to /var/log/mysql/error.log.2.gz (rotatecount 7, logstart 1, i 1),
renaming /var/log/mysql/error.log.0.gz to /var/log/mysql/error.log.1.gz (rotatecount 7, logstart 1, i 0),
log /var/log/mysql/error.log.8.gz doesn't exist -- won't try to dispose of it
renaming /var/log/mysql/error.log to /var/log/mysql/error.log.1
creating new /var/log/mysql/error.log mode = 0640 uid = 107 gid = 4
running postrotate script
running script with arg /var/log/mysql/mysql.log /var/log/mysql/mysql-slow.log /var/log/mysql/mariadb-slow.log /var/log/mysql/error.log : "
          test -x /usr/bin/mysqladmin || exit 0
          if [ -f `my_print_defaults --mysqld | grep -m 1 -oP "pid-file=\K.+$"` ]; then
            # If this fails, check debian.conf!
            mysqladmin --defaults-file=/etc/mysql/debian.cnf --local flush-error-log \
              flush-engine-log flush-general-log flush-slow-log
          fi
"
compressing log with: /bin/gzip

(Paul) #15

That case you linked (https://jira.mariadb.org/browse/MDEV-14367) suggests the unix_socket plugin gets deactivated when you upgrade to mariaDB 10.2 (I’m still at 10.1). Can you check the staus of your plugins? See below, 3rd from the end, mine is “ACTIVE”.

[email protected]:~$ sudo mysql
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 30255057
Server version: 10.1.26-MariaDB-0+deb9u1 Debian 9.1

Copyright (c) 2000, 2017, Oracle, MariaDB Corporation Ab and others.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

MariaDB [(none)]> SHOW PLUGINS;
+-------------------------------+----------+--------------------+---------+---------+
| Name                          | Status   | Type               | Library | License |
+-------------------------------+----------+--------------------+---------+---------+
| binlog                        | ACTIVE   | STORAGE ENGINE     | NULL    | GPL     |
| mysql_native_password         | ACTIVE   | AUTHENTICATION     | NULL    | GPL     |
| mysql_old_password            | ACTIVE   | AUTHENTICATION     | NULL    | GPL     |
| wsrep                         | ACTIVE   | STORAGE ENGINE     | NULL    | GPL     |
| CSV                           | ACTIVE   | STORAGE ENGINE     | NULL    | GPL     |
| MEMORY                        | ACTIVE   | STORAGE ENGINE     | NULL    | GPL     |
| MyISAM                        | ACTIVE   | STORAGE ENGINE     | NULL    | GPL     |
| MRG_MyISAM                    | ACTIVE   | STORAGE ENGINE     | NULL    | GPL     |
| CLIENT_STATISTICS             | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INDEX_STATISTICS              | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| TABLE_STATISTICS              | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| USER_STATISTICS               | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| Aria                          | ACTIVE   | STORAGE ENGINE     | NULL    | GPL     |
| PERFORMANCE_SCHEMA            | ACTIVE   | STORAGE ENGINE     | NULL    | GPL     |
| SEQUENCE                      | ACTIVE   | STORAGE ENGINE     | NULL    | GPL     |
| InnoDB                        | ACTIVE   | STORAGE ENGINE     | NULL    | GPL     |
| XTRADB_READ_VIEW              | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| XTRADB_INTERNAL_HASH_TABLES   | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| XTRADB_RSEG                   | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_TRX                    | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_LOCKS                  | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_LOCK_WAITS             | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_CMP                    | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_CMP_RESET              | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_CMPMEM                 | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_CMPMEM_RESET           | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_CMP_PER_INDEX          | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_CMP_PER_INDEX_RESET    | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_BUFFER_PAGE            | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_BUFFER_PAGE_LRU        | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_BUFFER_POOL_STATS      | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_METRICS                | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_FT_DEFAULT_STOPWORD    | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_FT_DELETED             | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_FT_BEING_DELETED       | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_FT_CONFIG              | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_FT_INDEX_CACHE         | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_FT_INDEX_TABLE         | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_SYS_TABLES             | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_SYS_TABLESTATS         | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_SYS_INDEXES            | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_SYS_COLUMNS            | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_SYS_FIELDS             | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_SYS_FOREIGN            | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_SYS_FOREIGN_COLS       | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_SYS_TABLESPACES        | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_SYS_DATAFILES          | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_CHANGED_PAGES          | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_MUTEXES                | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_SYS_SEMAPHORE_WAITS    | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| INNODB_TABLESPACES_ENCRYPTION | ACTIVE   | INFORMATION SCHEMA | NULL    | BSD     |
| INNODB_TABLESPACES_SCRUBBING  | ACTIVE   | INFORMATION SCHEMA | NULL    | BSD     |
| CHANGED_PAGE_BITMAPS          | ACTIVE   | INFORMATION SCHEMA | NULL    | GPL     |
| unix_socket                   | ACTIVE   | AUTHENTICATION     | NULL    | GPL     |
| FEEDBACK                      | DISABLED | INFORMATION SCHEMA | NULL    | GPL     |
| partition                     | ACTIVE   | STORAGE ENGINE     | NULL    | GPL     |
+-------------------------------+----------+--------------------+---------+---------+
56 rows in set (0.03 sec)

MariaDB [(none)]>


(John Banks) #16

Paul …
Ref yr 2 most recent responses …
I did …

sudo logrotate -vdf /etc/logrotate.conf

… on my plain vanilla emonSD (no MTA) instance and my emonSD with MTA instance.
The results were similar to yours and in both cases, echo $? returned 0.
And it did not prompt a nagging email from my with MTA instance.

Also I established that my version is …
Server version: 10.1.23-MariaDB-9+deb9u1 Raspbian 9.0

Your use of sudo prompted me to think about permissions …
I modified /etc/cron.daily/logrotate to add sudo …

#!/bin/sh

sudo test -x /usr/sbin/logrotate || exit 0
/usr/sbin/logrotate /etc/logrotate.conf

I did …
sudo nano /etc/crontab
… to modify the execution time for cron.daily so I could quickly see the result.

Followed by
sudo systemctl restart cron.service

It worked! …
No nagging email and a ‘clean’ report in syslog as follows …

Feb 8 23:53:01 watchman CRON[24655]: (root) CMD (test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily ))

Bottomline - if you add an MTA to an instance running emonSD and don’t want a daily nagging email then just add sudo to /etc/cron.daily/logrotate … as above.

Thank you very much for yr time on this - it’s been a valuable learning experience for me.
Regards


(Paul) #17

That is odd as the cron is run as root user, so adding sudo should not make any difference.

The fact you used sudo to open the crontab to edit means it is the root crontab, to be run as root. So why adding sudo should alter anything is a mystery.

Could it be that the log rotation wasn’t due so the post-rotate and impending message were not fired off?

My /etc/cron.daily/logrotate is the same as yours too (although I do not use mail notifications) so this shouldn’t be a emonSD only issue, besides I thought the emonSD (previously?) used hourly log rotations??? I hope we get a build guide for the current image one day!


(John Banks) #18

Paul …
I spoke too soon & too confidently …

This AM I received a nagging email and this in syslog …

Feb  9 06:25:02 watchman liblogging-stdlog:  [origin software="rsyslogd" swVersion="8.24.0" x-pid="311" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
Feb  9 06:25:02 watchman sSMTP[28163]: Creating SSL connection to host
Feb  9 06:25:03 watchman sSMTP[28163]: 220 smtp.gmail.com ESMTP z3sm5155032wmi.32 - gsmtp
Feb  9 06:25:03 watchman sSMTP[28163]: EHLO watchman
Feb  9 06:25:03 watchman sSMTP[28163]: 250 SMTPUTF8
Feb  9 06:25:03 watchman sSMTP[28163]: STARTTLS
Feb  9 06:25:03 watchman sSMTP[28163]: 220 2.0.0 Ready to start TLS
Feb  9 06:25:03 watchman sSMTP[28163]: SSL connection using RSA_AES_128_CBC_SHA1
Feb  9 06:25:03 watchman sSMTP[28163]: EHLO watchman
Feb  9 06:25:03 watchman sSMTP[28163]: 250 SMTPUTF8
Feb  9 06:25:03 watchman sSMTP[28163]: AUTH LOGIN
Feb  9 06:25:03 watchman sSMTP[28163]: 334 VXNlcm5hbWU6
Feb  9 06:25:03 watchman sSMTP[28163]: am9obmJhbmtzMDE0N0BnbWFpbC5jb20=
Feb  9 06:25:03 watchman sSMTP[28163]: 334 UGFzc3dvcmQ6
Feb  9 06:25:03 watchman sSMTP[28163]: bWdld3h1eG13b3RzcXpwYw==
Feb  9 06:25:03 watchman sSMTP[28163]: 235 2.7.0 Accepted
Feb  9 06:25:03 watchman sSMTP[28163]: MAIL FROM:<[email protected]>
Feb  9 06:25:03 watchman sSMTP[28163]: 250 2.1.0 OK z3sm5155032wmi.32 - gsmtp
Feb  9 06:25:03 watchman sSMTP[28163]: RCPT TO:<[email protected]>
Feb  9 06:25:03 watchman sSMTP[28163]: 250 2.1.5 OK z3sm5155032wmi.32 - gsmtp
Feb  9 06:25:03 watchman sSMTP[28163]: DATA
Feb  9 06:25:03 watchman sSMTP[28163]: 354  Go ahead z3sm5155032wmi.32 - gsmtp
Feb  9 06:25:03 watchman sSMTP[28163]: Received: by watchman (sSMTP sendmail emulation); Sat, 09 Feb 2019 06:25:02 +0000
Feb  9 06:25:03 watchman sSMTP[28163]: Date: Sat, 09 Feb 2019 06:25:02 +0000
Feb  9 06:25:03 watchman sSMTP[28163]: From: root (Cron Daemon)
Feb  9 06:25:03 watchman sSMTP[28163]: To: root
Feb  9 06:25:03 watchman sSMTP[28163]: Subject: Cron <[email protected]> test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily )
Feb  9 06:25:03 watchman sSMTP[28163]: MIME-Version: 1.0
Feb  9 06:25:03 watchman sSMTP[28163]: Content-Type: text/plain; charset=UTF-8
Feb  9 06:25:03 watchman sSMTP[28163]: Content-Transfer-Encoding: 8bit
Feb  9 06:25:03 watchman sSMTP[28163]: X-Cron-Env: <SHELL=/bin/sh>
Feb  9 06:25:03 watchman sSMTP[28163]: X-Cron-Env: <PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin>
Feb  9 06:25:03 watchman sSMTP[28163]: X-Cron-Env: <HOME=/root>
Feb  9 06:25:03 watchman sSMTP[28163]: X-Cron-Env: <LOGNAME=root>
Feb  9 06:25:03 watchman sSMTP[28163]:
Feb  9 06:25:03 watchman sSMTP[28163]: /etc/cron.daily/logrotate:
Feb  9 06:25:03 watchman sSMTP[28163]: #007mysqladmin: connect to server at 'localhost' failed
Feb  9 06:25:03 watchman sSMTP[28163]: error: 'Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2 "No such file or directory")'
Feb  9 06:25:03 watchman sSMTP[28163]: Check that mysqld is running and that the socket: '/var/run/mysqld/mysqld.sock' exists!
Feb  9 06:25:03 watchman sSMTP[28163]: error: error running shared postrotate script for '/var/log/mysql/mysql.log /var/log/mysql/mysql-slow.log /var/log/mysql/mariadb-slow.log /var/log/mysql/error.log '
Feb  9 06:25:03 watchman sSMTP[28163]: run-parts: /etc/cron.daily/logrotate exited with return code 1
Feb  9 06:25:04 watchman sSMTP[28163]: .
Feb  9 06:25:05 watchman sSMTP[28163]: 250 2.0.0 OK  1549693505 z3sm5155032wmi.32 - gsmtp
Feb  9 06:25:05 watchman sSMTP[28163]: QUIT
Feb  9 06:25:05 watchman sSMTP[28163]: 221 2.0.0 closing connection z3sm5155032wmi.32 - gsmtp
Feb  9 06:25:05 watchman sSMTP[28163]: Sent mail for [email protected] (221 2.0.0 closing connection z3sm5155032wmi.32 - gsmtp) uid=0 username=root outbytes=1212

It was a few mins before 9:14, so I amended /etc/crontab to run cron.daily at 9:14 (rather than 6:25) …

[email protected]:/etc/cron.d $ cat /etc/crontab
# /etc/crontab: system-wide crontab
# Unlike any other crontab you don't have to run the `crontab'
# command to install the new version when you edit this file
# and files in /etc/cron.d. These files also have username fields,
# that none of the other crontabs do.

SHELL=/bin/sh
PATH=/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin

# m h dom mon dow user  command
17 *    * * *   root    cd / && run-parts --report /etc/cron.hourly
14 9    * * *   root    test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily )
47 6    * * 7   root    test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.weekly )
52 6    1 * *   root    test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.monthly )

By 9:16, I had received NO nagging email and syslog revealed …

Feb  9 09:14:02 watchman CRON[29798]: (root) CMD (test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily ))

Apparently there was no problem at 9:14. So clearly there’s something additional happening at 6:25 other than just cron.daily running.

Looks like yr most recent comments are correct. I’m currently at a loss …


(Paul) #19

Hi John, the problem (as I understand it) seems to be that there is an error triggered by the rotating of the mysql log files. I’m unclear what that error is exactly, but the link you supplied seems feasible and at least worth exploring so if you could test to see if the “unix_socket” plugin is active as per my previous post that would be good.

Can you also check to see if /var/run/mysqld/mysqld.sock exists eg

[email protected]:~$ ls -la /var/run/mysqld/mysqld.sock
srwxrwxrwx 1 mysql mysql 0 Sep 29 11:52 /var/run/mysqld/mysqld.sock
[email protected]:~$

The probable reason you are not seeing an issue at 9.15 is the same reason you did not see a problem last night (after adding sudo) where basically the mysql logs are not due for rotation because 24hrs has not passed, if you leave the cron as 9.15, I suspect what normally happens at 6.25 will occur at 9.15 tomorrow because >24hrs will have passed, therefore the rotation (and post-rotation script) will run. Any attempt to run the rotation before 6.25 tomorrow will skip rotation (and post-rotation) as it is not due therefore no fault is triggered or registered.


(John Banks) #20

Paul …

Thanks for the 24 hours explanation.

My unix_socket is ACTIVE per below …
| unix_socket | ACTIVE | AUTHENTICATION | NULL | GPL |

However, unlike you, I do not have the required /var/run/mysqld/mysqld.sock

[email protected]:/var/run/mysqld $ ls -la /var/run/mysqld/mysqld.sock

ls: cannot access '/var/run/mysqld/mysqld.sock': No such file or directory

Lucky googling - I stumbled across this …

EDIT: A really good way of finding the location of the socket file is:
netstat -ln | grep mysql
unix 2 [ ACC ] STREAM LISTENING 22418 /var/lib/mysql/mysql.sock

So I tried it …
[email protected]:/etc/cron.monthly $ netstat -ln | grep mysql

which gave the following result …
unix 2 [ ACC ] STREAM LISTENING 13879 /home/pi/data/mysql/mysql.sock

So I hunted further - see third from the bottom …

[email protected]:/etc/cron.monthly $ cd /home/pi/data/mysql
[email protected]:~/data/mysql $ ls -al
total 110776
drwxrwxrwx  5 mysql mysql     4096 Feb  7 02:24 .
drwxrwxrwx 10 pi    pi        4096 Feb  7 02:15 ..
-rw-rw----  1 mysql mysql    16384 Feb  7 01:15 aria_log.00000001
-rw-rw----  1 mysql mysql       52 Feb  7 01:15 aria_log_control
-rw-r--r--  1 mysql mysql        0 Aug 17 15:27 debian-10.1.flag
drwx------  2 mysql mysql     4096 Feb  6 23:54 emoncms
-rw-rw----  1 mysql mysql 12582912 Feb  7 02:24 ibdata1
-rw-rw----  1 mysql mysql 50331648 Feb  7 02:24 ib_logfile0
-rw-rw----  1 mysql mysql 50331648 Aug 17 15:28 ib_logfile1
-rw-rw----  1 mysql mysql        0 Aug 17 15:29 multi-master.info
drwx------  2 mysql mysql     4096 Aug 17 15:28 mysql
srwxrwxrwx  1 mysql mysql        0 Feb  7 02:24 mysql.sock
drwx------  2 mysql mysql     4096 Aug 17 15:28 performance_schema
-rw-rw----  1 mysql mysql    24576 Feb  7 02:24 tc.log

In my ignorance I tried to sudo cp from there to /var/run/mysqld/mysqld.sock - but that’s not allowed.

Is there a way to link both?