zmlogger dying under 5.0.11

[Rich Graves]

Logger has been stable since a bunch of problems were fixed around 5.0.3 or so. But lately it's been dying every *second* night.

I've made two recent changes, both on November 30:

1) Upgraded from 5.0.10 to 5.0.11
2) Added a new 500GB partition /opt/zimbra/store4 and made it the active primary message volume

The problem is obviously with the logger mysql database, but I don't know exactly what to make of it. I see nothing in conf/my.logger.cnf to explain why it seems to think I want to replicate.

# cat log/logger_mysql_error.log
081130 07:30:48  mysqld ended

Starting mysqld daemon with databases from /opt/zimbra/logger/db/data
081130 07:50:37  mysqld started
081130  7:50:37  InnoDB: Started; log sequence number 0 43655
081130  7:50:37 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--relay-log=/opt/zimbra/logger/db/mysql-relay-bin' to avoid this problem.
081130  7:50:38 [ERROR] Failed to open the relay log './mail2-relay-bin.000001' (relay_log_pos 4)
081130  7:50:38 [ERROR] Could not find target log during relay log initialization
081130  7:50:38 [ERROR] Failed to initialize the master info structure
081130  7:50:38 [Note] /opt/zimbra/logger/mysql/libexec/mysqld: ready for connections.
Version: '5.0.51a-log'  socket: '/opt/zimbra/logger/db/mysql.sock'  port: 7307  Source distribution
081130  7:55:19 [Note] /opt/zimbra/logger/mysql/libexec/mysqld: Normal shutdown

081130  7:55:19  InnoDB: Starting shutdown...
081130  7:55:20  InnoDB: Shutdown completed; log sequence number 0 43655
081130  7:55:20 [Note] /opt/zimbra/logger/mysql/libexec/mysqld: Shutdown complete

STOPPING server from pid file /opt/zimbra/logger/db/mysql.pid
081130 07:55:20  mysqld ended
081130 07:55:20  mysqld ended


Starting mysqld daemon with databases from /opt/zimbra/logger/db/data
081130 07:59:00  mysqld started
081130  7:59:00  InnoDB: Started; log sequence number 0 43655
081130  7:59:00 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--relay-log=/opt/zimbra/logger/db/mysql-relay-bin' to avoid this problem.
081130  7:59:00 [ERROR] Failed to open the relay log './mail2-relay-bin.000001' (relay_log_pos 4)
081130  7:59:00 [ERROR] Could not find target log during relay log initialization
081130  7:59:00 [ERROR] Failed to initialize the master info structure
081130  7:59:00 [Note] /opt/zimbra/logger/mysql/libexec/mysqld: ready for connections.
Version: '5.0.51a-log'  socket: '/opt/zimbra/logger/db/mysql.sock'  port: 7307  Source distribution
081205 10:45:32 [Note] /opt/zimbra/logger/mysql/libexec/mysqld: Normal shutdown

081205 10:45:34  InnoDB: Starting shutdown...
081205 10:45:35  InnoDB: Shutdown completed; log sequence number 0 43655
081205 10:45:35 [Note] /opt/zimbra/logger/mysql/libexec/mysqld: Shutdown complete

STOPPING server from pid file /opt/zimbra/logger/db/mysql.pid
081205 10:45:35  mysqld ended
081205 10:45:35  mysqld ended


Starting mysqld daemon with databases from /opt/zimbra/logger/db/data
081205 10:45:43  mysqld started
081205 10:45:43  InnoDB: Started; log sequence number 0 43655
081205 10:45:43 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--relay-log=/opt/zimbra/logger/db/mysql-relay-bin' to avoid this problem.
081205 10:45:43 [ERROR] Failed to open the relay log './mail2-relay-bin.000001' (relay_log_pos 4)
081205 10:45:43 [ERROR] Could not find target log during relay log initialization
081205 10:45:43 [ERROR] Failed to initialize the master info structure
081205 10:45:43 [Note] /opt/zimbra/logger/mysql/libexec/mysqld: ready for connections.
Version: '5.0.51a-log'  socket: '/opt/zimbra/logger/db/mysql.sock'  port: 7307  Source distribution

*** logswatch version 3.2.3 (pid:31083) started at Sat Dec  6 04:02:55 CST 2008

DBI connect('database=zimbra_logger;mysql_read_default_file=/opt/zimbra/conf/my.
logger.cnf;mysql_socket=/opt/zimbra/logger/db/mysql.sock','zimbra',...) failed:
Too many connections at /opt/zimbra/libexec/zmlogger line 176
Can't call method "prepare" on unblessed reference at /opt/zimbra/libexec/zmlogg
er line 57.

[zimbra@mail2 ~]$ tail -44 log/logger_myslow.log
# User@Host: zimbra[zimbra] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 1  Rows_examined: 70059
select avg(available) from disk_status where server = 'mail.carleton.edu' and device = '/dev/mapper/store2p1' and time >= '2008-12-05 03:00:00' and time <= '2008-12-05 04:00:00';
# User@Host: zimbra[zimbra] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 1  Rows_examined: 70059
select avg(total) from disk_status where server = 'mail.carleton.edu' and device = '/dev/mapper/store3p1' and time >= '2008-12-05 03:00:00' and time <= '2008-12-05 04:00:00';
# User@Host: zimbra[zimbra] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 1  Rows_examined: 70059
select avg(available) from disk_status where server = 'mail.carleton.edu' and device = '/dev/mapper/store3p1' and time >= '2008-12-05 03:00:00' and time <= '2008-12-05 04:00:00';
# User@Host: zimbra[zimbra] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 1  Rows_examined: 70059
select avg(total) from disk_status where server = 'mail.carleton.edu' and device = '/dev/mapper/store4p1' and time >= '2008-12-05 03:00:00' and time <= '2008-12-05 04:00:00';
# User@Host: zimbra[zimbra] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 1  Rows_examined: 70059
select avg(available) from disk_status where server = 'mail.carleton.edu' and device = '/dev/mapper/store4p1' and time >= '2008-12-05 03:00:00' and time <= '2008-12-05 04:00:00';
# User@Host: zimbra[zimbra] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 1  Rows_examined: 70059
select avg(total) from disk_status where server = 'mail.carleton.edu' and device = '/dev/md1' and time >= '2008-12-05 03:00:00' and time <= '2008-12-05 04:00:00';
# User@Host: zimbra[zimbra] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 1  Rows_examined: 70059
select avg(available) from disk_status where server = 'mail.carleton.edu' and device = '/dev/md1' and time >= '2008-12-05 03:00:00' and time <= '2008-12-05 04:00:00';
# User@Host: zimbra[zimbra] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 1  Rows_examined: 70059
select avg(total) from disk_status where server = 'mail.carleton.edu' and device = '/dev/md0' and time >= '2008-12-05 03:00:00' and time <= '2008-12-05 04:00:00';
# Time: 081205  4:00:13
# User@Host: zimbra[zimbra] @ localhost []
# Query_time: 1  Lock_time: 0  Rows_sent: 1  Rows_examined: 70059
select avg(available) from disk_status where server = 'mail.carleton.edu' and device = '/dev/md0' and time >= '2008-12-05 03:00:00' and time <= '2008-12-05 04:00:00';
# User@Host: zimbra[zimbra] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 1  Rows_examined: 70059
select avg(total) from disk_status where server = 'mail.carleton.edu' and device = '/dev/mapper/vgLocal-lvVar' and time >= '2008-12-05 03:00:00' and time <= '2008-12-05 04:00:00';
# User@Host: zimbra[zimbra] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 1  Rows_examined: 70059
select avg(available) from disk_status where server = 'mail.carleton.edu' and device = '/dev/mapper/vgLocal-lvVar' and time >= '2008-12-05 03:00:00' and time <= '2008-12-05 04:00:00';
# User@Host: zimbra[zimbra] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 1  Rows_examined: 271
select period_start from disk_aggregate where period='day' order by period_start desc limit 1;
# Time: 081205  4:00:15
# User@Host: zimbra[zimbra] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 0  Rows_examined: 0
delete from disk_status where time < '2008-11-04 00:00:00';
/opt/zimbra/logger/mysql/libexec/mysqld, Version: 5.0.51a-log (Source distribution). started with:
Tcp port: 7307  Unix socket: /opt/zimbra/logger/db/mysql.sock
Time                 Id Command    Argument

[Rich Graves]

This can't be good. Immediately upon zmlogger stop/start:

[zimbra@mail2 ~]$ logmysql
ERROR 1040 (08004): Too many connections

[Rich Graves]

OK, I treated the symptom. With max_connections = 20 (default was 10) it now works.

Previously discussed at

[SOLVED] Message: system failure: getting database logger connection on admin login

But no bugzilla for this?

[phoenix]

It's likely a problem with the logger not stopping correctly when you stop/start Zimbra, it leaves processes lying around. Stop Zimbra then kill any remaining Zimbra processes, restart Zimbra and it will be OK. There's a fix to the logger script in this bug report: Bug 33604 – Server Status Error

[Rich Graves]

Marking solved. 5.011 Bug - zmlogger fails to stop

Bug 33604 – Server Status Error

[Rich Graves]

And the reason it was happening nightly was (on RHEL)

/etc/cron.daily/zmlogwatch
/etc/logrotate.d/zimbra

...which appear to be redundant!

Is the former an artifact that should have been removed when upgrading from 4.5 to 5.0?

[zimbra@mail2 ~]$ rpm -qif /etc/logrotate.d/zimbra
file /etc/logrotate.d/zimbra is not owned by any package
[zimbra@mail2 ~]$ rpm -qif /etc/cron.daily/zmlogwatch
file /etc/cron.daily/zmlogwatch is not owned by any package
[zimbra@mail2 ~]$ ls -l  /etc/cron.daily/zmlogwatch
-rwxr-xr-x  1 root root 128 Sep  3  2007 /etc/cron.daily/zmlogwatch
[zimbra@mail2 ~]$ ls -l /etc/logrotate.d/zimbra
-r--r--r--  1 root root 2247 Nov 30 07:40 /etc/logrotate.d/zimbra
[zimbra@mail2 ~]$ cat /etc/cron.daily/zmlogwatch
#!/bin/sh
su - zimbra -c 'zmlogswatchctl stop'
rm -f /tmp/zmlogger.out /tmp/logswatch.out
su - zimbra -c 'zmlogswatchctl start'
/var/log/zimbra.log {
    daily
    missingok
    notifempty
    create 0644 zimbra zimbra
    postrotate
      killall -HUP syslogd 2> /dev/null || true
      kill -HUP `cat /opt/zimbra/log/swatch.pid 2> /dev/null` 2> /dev/null || tr
ue
      kill -HUP `cat /opt/zimbra/log/logswatch.pid 2> /dev/null` 2> /dev/null ||
 true
    endscript
    compress
}