MySQL replication monitoring with Python

July 28, 2009

Setting up a MySQL fail over Master-Master replication system is something one can find many guides for.

However, monitoring and recovering from a failure of the system is not as well documented, according to a quick Google search.

The top items from that search were:

  • Something called: MYSQL master-master replication monitor shell script that mainly included the following piece of code:
    #!/bin/bash
    mysqladmin -u root -h dbserver1.mycorp.com -p 'MyPASSWORD' ping
    if [ $? -ne 0 ]; then
      echo "Send email, mysql not running"
    else
     echo "Do nothing everything is working"
    fi
    done

    Which, while succinct and informative, not exactly thorough.

  • Next on the list is some sort of crazy java-based real-time monitor, that is totally overkill and doesn’t answer the exact specifications we had in mind. It also happens to be not that far in its idea from my our (I did not figure out this one by myself – I was greatly assisted by my GNU/Linux mentor at work!) eventual solution.
  • The third and final thing on the list remotely resembling what we needed was a pure MySQL solution, which while elegant, and providing some interesting insights and tips, did not answer the requirements stated below.

First, an overview of the setup.

MySQL Replication in Normal Status

MySQL Replication in Normal Status

The load balancer listens on port 3306 to requests from the web servers on a virtual IP, and internally sends the traffic to whichever server is declared active at the moment.

Throughout the example I will use, 10.0.170.5 is the virtual IP, 10.0.170.10 is MySQL1, and 10.0.170.20 is MySQL2.

As high availability server configurations, and database replication are subjects that fill many books, by people much smarter than me, I won’t even try to cover the whole issue here.

However, I will give a short explanation of the example given, as far as is relevant to the script at hand.
The Master-Master replication means that writes to the database can be made to either of the two servers, and the changes will be made in both of the servers.
There are a usually a lot of considerations in regards to synchronization of data when dealing with multiple masters, however I really won’t go into it, since it isn’t entirely relevant as you will see.

In this example, the main purpose of the two-server cluster, is resilience, and sleeping soundly at night.

A load balancer is a great thing, and usually very smart when actually balancing loads, however a fail over configuration is quite well, simple.

A load balancer configured for fail over thinks like this: “I will give server ‘A’ data, as long as it returns an expected answer to a question I will ask it every few seconds. If it does not answer or gives me a bad answer, I will give the data to server ‘B’. As soon as it answers me properly once more, I will return the data to ‘A’ – and so on and so forth…”

Keeping it simple in itself is a good thing, however when dealing with databases, certain problems arise.
I will display a few common scenarios to explain, and will go into more detail later with actual examples of case handling, and more scenarios later.

  • Case 1 (“All is Cool”):
    • The LB points traffic to the Master.
    • Slave replicates all data quietly in the background.
    • The master gets data.
    • Everything is OK.
    • Stay in Bed.
  • Case 2 (“The Master Dies”)
    • The LB points traffic to the Master.
    • The Master Dies.
    • Not spending time on sorrow, the LB passes the torch to the designated slave.
    • Slave serves data properly, as he diligently synchronized everything when the Master was still alive.
    • Everything is OK
    • Write something in log, send email etc. Will check why Master is dead, and contemplate burial place in the morning (unless time critical application, where SLA prevents single point of failure until morning – since no resilience as long as data is going to slave and Master is dead – in that case, wake up and do something).
  • Case 3 (“Master Arises from the Dead”):
    • LB refers all traffic to Master
    • Master Dies, or perhaps power cycles, or for some other reason is not entirely dead – but cannot handle traffic for now.
    • Load Balancer transfers traffic to Slave.
    • After a while that the Slave has been handling traffic, Master comes back to life.
    • Even though he was once the Master, he cannot assume the Master role yet, as the slave who became the new Master in the meantime, has a different set of data
    • The Load Balancer must wait until the old Master replicates (as a slave in the cluster) the accumulated data by the old Slave
    • Return traffic to resurrected Master
    • Everything is OK, log events.

I mentioned the Master’s resurrection in bold, as it is a scenario that introduces some complexity to the logic of a allmost-case automated script.

I went into some detail of the scenarios, so as to give a better idea of the logic used to create the script.
Many times in designing some automated process, it help me to think like the machine, and simulate the decisions to be made by the machine, as if I were to make the decisions.

These a only a part of the possible scenarios we may encounter, however, such a detailed breakdown would be unpractical, and also not as useful perhaps as a diagram.

A short high-level technical overview of the solution and then down to the details:

As stated earlier, the Load Balancer listens on the virtual IP, 10.0.170.5.
It probes an SNMP object on the server named in this example MySQL1, which must provide the value “100″, otherwise it transfers the traffic to MySQL2.

Our script is located on MySQL1 and we use the following process to allow the SNMP to run it, and retrieve its output:

Assuming that the script is in  /opt/, we add the the following line to /etc/snmp/snmpd.conf (or wherever snmpd.conf is located on your machine).

extend mysql_monitor /opt/rep_stat.py

Afterward, restart the snmpd daemon.
Thus we have added the an SNMP object to the server’s MIB which we call “mysql_monitor”.
Then, run the following command from the shell:

[admin@MySQL1]#snmptranslate -On NET-SNMP-EXTEND-MIB::nsExtendOutputFull.\"mysql_monitor\"

The output of this command should be the numerical form (Object ID) of the object named “mysql_monitor”, it should look something like

1.3.6.1.4.1.2681.1.2.102

or something similar.

The code is then copied and pasted into the configuration of the Load Balancer’s probe, which we set to check every 15 seconds.

There were three main reasons I chose Python as the tool for this particular solution.

  1. There is a bit more logic involved in this script than I would have cared to handle with bash.
  2. Dealing with multiple MySQL queries, and handling their results in a sane fashion, is something not to be expected by bash, so it was down to PHP or Python.
  3. Given the choice between PHP or Python, albeit that PHP is excellent in dealing with MySQL, Python is a superior choice for a system script.
MySQL Replication Python Diagram thumbnail - Click to view full PDF

MySQL Replication Python Diagram thumbnail - Click to view full PDF

The diagram is a flowchart that the script follows each time the Load Balancer runs it.

#!/usr/bin/env python
#
# filename = rep_stat.py
#
# check replication status

import sys,MySQLdb,time
tprint = sys.stdout.write

# set directory and filename for logging
logdir = "/var/log/rep_stat/"
logfilename = "rep_stat.log"

# rep_logger function - writes log to file
def rep_logger(message):
    logfile = open ( "%s%s" % (logdir,logfilename) , "a" )
    logfile.write ( ("%s:    %s%s") % (time.ctime(),message,"\n" ) )
    logfile.close()

### get mysql root password

# where to find password
mycnf="/root/.my.cnf"

# simple file parser - can be used in a more general sense as well
def getpassword():
    try:
        mycnfopen = open( mycnf , "r" )
    except:
        rep_logger ( "could not find my.cnf" )
        sys.exit()
    mycnflines = mycnfopen.readlines()
    for line in mycnflines:
        if line.find("password") > -1:
            splitline = line.split("=")
            password = splitline[1]
            # here is a little hack used to make the newline character disappear
            if password[-1:] == "\n":
                password = password[:-1]
            return password

# connect to MySQL

# connection details
db_host_master = "localhost"
db_host_slave = "10.0.170.20"
db_user = "root"
db_passwd = getpassword()
db_dbname = "status_example"

# utc is good to prevent tz issues

# epochnow returns seconds since epoch (disregard values smaller than a second)
def epochnow():
    return int(time.time())

# define some queries:
query_getlastcheck = "SELECT lastcheck FROM lastcheck"
query_updatelastcheck = ( "UPDATE lastcheck SET lastcheck = %s" % epochnow() )
query_slavestatus = ( "SHOW SLAVE STATUS" )

# do some logic
try:
    conn = MySQLdb.connect (
                            host = db_host_master,
                            user = db_user,
                            passwd = db_passwd,
                            db = db_dbname
                            )
    cursor = conn.cursor()
    cursor.execute (query_getlastcheck)
    row = cursor.fetchone()
    # leaving connection open for rest of script unless disaster
except:
    # here local mysql fails - return slave
    rep_logger ("Error connecting to master DB")
    tprint ("200")
    sys.exit()

try:
    slaveconn = MySQLdb.connect (
                                host = db_host_slave,
                                user = db_user,
                                passwd = db_passwd,
                                db = db_dbname
                                )
    curslave = slaveconn.cursor()
    curslave.execute (query_getlastcheck)
    rowslave = curslave.fetchone()
    curslave.close()
    slaveconn.close()
except:
    # here slave mysql fails - return master
    rep_logger ("Error doing query on slave DB")
    tprint ("100")
    sys.exit()


timedelta = (epochnow() - row[0])

if ( timedelta <= 20 ):
    # normal - things are ok
    rep_logger ( "THIS IS A TEST - EVERYTHING IS GOOD" ) # for testing
    cursor.execute (query_updatelastcheck)
    cursor.close()
    conn.close()
    tprint ("100")
    sys.exit()
elif ( timedelta >20 ):
    # apparently we missed a check for some reason
    # do more testing for status
    rep_logger ( "LastCheck > 20 seconds" )
    # seconds behind (last in show slave status tuple, hence the '-1')
    cursor.execute (query_slavestatus)
    row = cursor.fetchone()
    try:
        # hopefully we get an int back
        seconds_behind = int(row[-1])
    except:
        # something strange has happened, leave the master alone
        rep_logger ( "Seconds behind not integer" )
        cursor.close()
        conn.close()
        tprint ("200")
        sys.exit()
    if ( seconds_behind == 1 or seconds_behind == 0 ):
        # mysql failed but came back and is replicating normally
        rep_logger ( "Seconds behind <=1 is good..." ) # for testing
        cursor.execute (query_updatelastcheck)
        cursor.close()
        conn.close()
        tprint ("100")
        sys.exit()
    elif ( seconds_behind > 1 ):
        # mysql failed, but came back ok, but is still behind in replication
        # maybe next check it will be ok
        rep_logger ( "Seconds behind >1 still busy catching up, come back later" ) # for testing
        cursor.close()
        conn.close()
        tprint ("200")
        sys.exit()
    else:
        # something strange has happened, leave the master alone
        rep_logger ( "Seconds behind invalid value" )
        cursor.close()
        conn.close()
        tprint ("200")
        sys.exit()

else: # final timedelta case
    # something here went wrong, log and return slave
    rep_logger ( "TIMEDELTA FATAL ERROR" )
    cursor.close()
    conn.close()
    tprint ("200")
    sys.exit()

I won’t cover the whole script as in previous posts, since the second part, the main logic, is basically an algorithm described exactly in the decision tree flowchart attached above.

However, there are a few cute tricks that I think can benefit anyone looking to write some system scripts in Python, particularly when handling MySQL.

#!/usr/bin/env python
#
# filename = rep_stat.py
#
# check replication status
 
import sys,MySQLdb,time
tprint = sys.stdout.write
 
# set directory and filename for logging
logdir = "/var/log/rep_stat/"
logfilename = "rep_stat.log"

Just some really basic stuff, like using #!/usr/bin/env python instead of #!/usr/bin/python for more cross-platform compatibility – I try and use env for all scripts rather than the usual she-bang (one of the many things Yotam taught me, thanks!).

In the import section, you can find sys which is always useful, and time, which I will explain its usage in this script a bit later, and the

MySQLdb

module.

tprint is just an alias for the C style output method, sys.stdout.write(), which I usually prefer to print, in anything other than very short, one line throwaway code, which isn’t something I create much in Python anyways.

Next, we set the variables logdir and logfilename which we will use in the following function, rep_logger().

# rep_logger function - writes log to file
def rep_logger(message):
    logfile = open ( "%s%s" % (logdir,logfilename) , "a" )
    logfile.write ( ("%s:    %s%s") % (time.ctime(),message,"\n" ) )
    logfile.close()

This is a simple, relatively generalized, logging function in Python, in case you don’t want to use such built-ins as the syslog module, which is of no use if you aren’t running the script with root privileges, and also if you don’t want to pollute the system log with your debugging.
I like it because it is very convenient, and the time.ctime() method supplies a nicely formatted time stamp for the event logged.
Here is some actual output from a server:

[admin@MySQL1 ~]# tail /var/log/rep_stat/rep_stat.log
Fri Jul 24 02:55:32 2009:    LastCheck > 20 seconds
Fri Jul 24 02:55:32 2009:    Seconds behind <=1 is good...
Fri Jul 24 02:56:47 2009:    LastCheck > 20 seconds
Fri Jul 24 02:56:47 2009:    Seconds behind <=1 is good...
Sat Jul 25 12:55:32 2009:    LastCheck > 20 seconds
Sat Jul 25 12:55:32 2009:    Seconds behind <=1 is good...
Sun Jul 26 01:53:11 2009:    LastCheck > 20 seconds
Sun Jul 26 01:53:11 2009:    Seconds behind <=1 is good...
Sun Jul 26 03:41:26 2009:    LastCheck > 20 seconds
Sun Jul 26 03:41:26 2009:    Seconds behind <=1 is good...

Later I will also explain the meaning of this output, as it provides some insight regarding the logic of the script.

### get mysql user password
 
# where to find password
mycnf="/home/admin/.my.cnf"

# simple file parser - can be used in a more general sense as well
def getpassword():
    try:
        mycnfopen = open( mycnf , "r" )
    except:
        rep_logger ( "could not find my.cnf" )
        sys.exit()
    mycnflines = mycnfopen.readlines()
    for line in mycnflines:
        if line.find("password") > -1:
            splitline = line.split("=")
            password = splitline[1]
            # here is a little hack used to make the newline character disappear
            if password[-1:] == "\n":
                password = password[:-1]
            return password

This is a simple little file parsing function I created for this script, however it may be useful in many other cases.
Here I use it, to prevent the need to write the password in the code, which seems like bad security practices to me, as “.my.cnf” is a file used frequently anyways on servers, for easy password-less client access from the the shell, however it tends to just stay there, whereas on the other hand, scripts have a tendency to be shared, and copied and posted online etc.
Theoretically, the password could even be hashed and so on, so as to strengthen security for real (the password is stored in clear text in “.my.cnf” anyways in this case) however that is beyond the scope of this post.

Finally we reach the part that actually has something with MySQL replication.

The core of the script’s logic is based on the time between the LB’s checks of the MySQL server’s availability.


The main trick done here, is storing the time stamp of each check in the DB, and thus when retrieving the time of the last check, we also check the availability of the server (perform a query), and then use the result of the current check, to find out the time difference between now and the last check.

But first, here is a quick preparation that must be done before, which I neglected to include before.

CREATE DATABASE 'status_example';
USE status_example;
CREATE TABLE lastcheck (lastcheck BIGINT);
INSERT INTO lastcheck (lastcheck) VALUES (398433600);  --or any other valid epoch value that is in the past

I take it for granted that you know how to GRANT proper permissions to the DB user designated for the the purpose of actually performing the queries.
The user will need permissions to do SHOW SLAVE STATUS and SELECT and UPDATE on the table of the database we created above.

So, back to business.

All cases tested in the script are explained the flowchart, so I won’t go into all the details of each try clause. I chose the try style test, because it is quite trustworthy with MySQLdb, as it is not very tolerant, and the slightest deviation from expected input will raise an exception.

timedelta is the current UTC time minus the result of the query_getlastcheck query (see below for its actual output).
Since we have set the LB to check the MySQL status every 15 seconds, if we get a value of over 20 seconds, this means that the LB wasn’t able to properly contact the Master and update the DB with a new time stamp for some reason.
This could be a result of the LB just being lazy, as can be seen in the logs attached above, or the Master going down and coming back again (like someone unplugged the Master by mistake, realized their mistake and quickly plugged it back in).
In cases as these, as has been stated above, we must check the replication status before returning “everything is OK” (“100″). This is done with the help of query_slavestatus, and its decision tree is visible in the flow chart, as well as documented in the comments in the code.

Output of query_getlastcheck when run from the shell (-E is used to beautify things):

[admin@MySQL1 ~]# mysql -E -e "show slave status"
*************************** 1. row ***************************
             Slave_IO_State: Waiting for master to send event
                Master_Host: 10.0.170.20
                Master_User: slave_user
                Master_Port: 3306
              Connect_Retry: 60
            Master_Log_File: mysql-bin.000014
        Read_Master_Log_Pos: 98
             Relay_Log_File: mysql1-slave-relay.001315
              Relay_Log_Pos: 235
      Relay_Master_Log_File: mysql-bin.000014
           Slave_IO_Running: Yes
          Slave_SQL_Running: Yes
            Replicate_Do_DB:
        Replicate_Ignore_DB:
         Replicate_Do_Table:
     Replicate_Ignore_Table:
    Replicate_Wild_Do_Table:
Replicate_Wild_Ignore_Table:
                 Last_Errno: 0
                 Last_Error:
               Skip_Counter: 0
        Exec_Master_Log_Pos: 98
            Relay_Log_Space: 235
            Until_Condition: None
             Until_Log_File:
              Until_Log_Pos: 0
         Master_SSL_Allowed: No
         Master_SSL_CA_File:
         Master_SSL_CA_Path:
            Master_SSL_Cert:
          Master_SSL_Cipher:
             Master_SSL_Key:
      Seconds_Behind_Master: 0

Seconds_Behind_Master is the most interesting part in our case, which is also why, when the script retrieves this data, at:

elif ( timedelta >20 ):
    # apparently we missed a check for some reason
    # do more testing for status
    rep_logger ( "LastCheck > 20 seconds" )
    # seconds behind (last in show slave status tuple, hence the '-1')
    cursor.execute (query_slavestatus)
    row = cursor.fetchone()
    try:
        # hopefully we get an int back
        seconds_behind = int(row[-1])

We use row[-1], as python gets the data in a nice, easy-to-use tuple, and we make a reference to the last element (-1).
That is how we know the resuscitated Master has caught up (since the replication works in both directions), and is ready to receive request once again.

I have done my best to explain this whole thing, I hope you find some value in it, and that you are able to perhaps implement some of or even as is in your own systems.

I would very much appreciate any feedback and/or critique, as I am always curious and happy to learn more, and am always aware that there are better methods to do things.

I know I learned a lot from writing this script, and even from writing this post about the script.

Hope it wasn’t too long!

P.S.
I am well aware that it doesn’t cover all possible cases, and would like to hear of suggestions as to how it might be more efficient/thorough. In addition it is important not to neglect a separate monitor of the slave system.

tags: , , ,
posted in scripts by tom

Follow comments via the RSS Feed | Leave a comment | Trackback URL

5 Comments to "MySQL replication monitoring with Python"

  1. Danial Poeschel wrote:

    I depend on having each model backed up and watching each appliance, as opposed to simply monitoring naturally on the Internet, after which responding in a short enough point in time for a resolution.

  2. tom wrote:

    That is definitely a viable method. The solution suggested here is not by any means the optimal solution.
    In addition this is sort of an end case – not the usual way of handling mission critical data with MySQL replications.
    Thanks!

  3. Greg wrote:

    You can get the results from “show slave status” to be in a dict form by using a DictCursor. This lets you specifically look at ‘seconds_behind_master’ instead of just assuming it is the last thing in your row (which it isn’t in 5.5).

    cursor = conn.cursor(MySQLdb.cursors.DictCursor)

  4. tom wrote:

    Greg, Thanks!

    Sorry to say I haven’t re-visited this subject in a while (posted this 2.5 years ago).

    I actually had some qualms regarding the whole setup and its robustness. What is your opinion of the method / algorithm as a whole?

  5. Greg wrote:

    Honestly, I’m not an expert on what you’re doing here. I am doing something much more basic – digging into the status of a slave and sending alerts with monit if there is a problem.

    I am fairly new to python, though and your code was a very helpful basis.

    My comment was only to help for someone who used your code but was using a version of mysql that would break on the seconds_behind_master check. (also, it is a simple fix). It will of course, break if someone changes the name of that variable in a future release. :(

Leave Your Comment

 
Powered by Wordpress. Theme by Shlomi Noach, openark.org
Hosted by Evolution On-line