Results 1 to 6 of 6

Thread: zmlogger dying under 5.0.11

  1. #1
    Rich Graves is offline Outstanding Member
    Join Date
    Jan 2007
    Location
    Minnesota
    Posts
    717
    Rep Power
    9

    Default zmlogger dying under 5.0.11

    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.

    Code:
    # 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

  2. #2
    Rich Graves is offline Outstanding Member
    Join Date
    Jan 2007
    Location
    Minnesota
    Posts
    717
    Rep Power
    9

    Default

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

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

  3. #3
    Rich Graves is offline Outstanding Member
    Join Date
    Jan 2007
    Location
    Minnesota
    Posts
    717
    Rep Power
    9

    Default

    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?

  4. #4
    phoenix is offline Zimbra Consultant & Moderator
    Join Date
    Sep 2005
    Location
    Vannes, France
    Posts
    23,201
    Rep Power
    56

    Default

    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 &ndash; Server Status Error
    Last edited by phoenix; 12-06-2008 at 10:23 AM.
    Regards


    Bill


    Acompli: A new adventure for Co-Founder KevinH.

  5. #5
    Rich Graves is offline Outstanding Member
    Join Date
    Jan 2007
    Location
    Minnesota
    Posts
    717
    Rep Power
    9

  6. #6
    Rich Graves is offline Outstanding Member
    Join Date
    Jan 2007
    Location
    Minnesota
    Posts
    717
    Rep Power
    9

    Default

    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?

    Code:
    [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
    }

Thread Information

Users Browsing this Thread

There are currently 1 users browsing this thread. (0 members and 1 guests)

Similar Threads

  1. How to downgrade from 5.0.11 to 5.04 ?
    By SergKz in forum Installation
    Replies: 4
    Last Post: 12-02-2008, 01:59 PM
  2. Replies: 3
    Last Post: 11-27-2008, 12:40 AM
  3. Migration Zimbra RHEL5 32bits 5.0.6 to 5.0.11
    By navista in forum Installation
    Replies: 2
    Last Post: 11-25-2008, 03:57 AM
  4. multiple zmlogger instances running
    By altimage in forum Administrators
    Replies: 5
    Last Post: 11-28-2007, 12:40 PM
  5. Zmlogger error message
    By Rick Baker in forum Administrators
    Replies: 6
    Last Post: 10-19-2007, 11:34 PM

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •