check-mysql-replication-status: Lag flapping protection

CHANGELOG.md

@@ -4,6 +4,14 @@ This project adheres to [Semantic Versioning](http://semver.org/).
 This CHANGELOG follows the format listed [here](https://github.com/sensu-plugins/community/blob/master/HOW_WE_CHANGELOG.md)
 
 ## [Unreleased]
+### Fixed
+- check-mysql-replication-status: fix code flow if server is not a slave (@DrMurx)
+
+### Changed
+- check-mysql-replication-status: refactoring & spec tests (@DrMurx)
+
+### Added
+- check-mysql-replication-status: added protection against `SHOW SLAVE STATUS` high lag reporting bug (@DrMurx)
 
 ## [3.1.1] - 2019-03-04
 ### Fixed

README.md

@@ -80,6 +80,15 @@ $ /opt/sensu/embedded/bin/check-mysql-threads.rb --host=<DBHOST> --ini=/etc/sens
 $ /opt/sensu/embedded/bin/check-mysql-replication-status.rb --host=<SLAVE> --ini=/etc/sensu/my.ini
 ```
 
+**check-mysql-replication-status** example with lag outlier protection
+
+MariaDB/MySQL sometimes wrongly reports a very high replication lag for a short moment. The outlier protection helps mitigating this issue
+better than setting `occurrences` in sensu's `checks` definition because you don't lose any alerting granularity.
+
+```bash
+$ /opt/sensu/embedded/bin/check-mysql-replication-status.rb --host=<SLAVE> --ini=/etc/sensu/my.ini --lag-outlier-retry=1 --lag-outlier-threshold=86400 --lag-outlier-sleep=2
+```
+
 **check-mysql-msr-replication-status** example
 ```bash
 $ /opt/sensu/embedded/bin/check-mysql-replication-status.rb --host=<SLAVE> --ini=/etc/sensu/my.ini

bin/check-mysql-replication-status.rb

@@ -6,6 +6,7 @@
 # Copyright 2011 Sonian, Inc <chefs@sonian.net>
 # Updated by Oluwaseun Obajobi 2014 to accept ini argument
 # Updated by Nicola Strappazzon 2016 to implement Multi Source Replication
+# Refactored by Jan Kunzmann (Erasys GmbH) 2018
 #
 # Released under the same terms as Sensu (the MIT license); see LICENSE
 # for details.
@@ -45,7 +46,7 @@ class CheckMysqlReplicationStatus < Sensu::Plugin::Check::CLI
          description: 'Database port',
          default: 3306,
          # #YELLOW
-         proc: lambda { |s| s.to_i } # rubocop:disable Lambda
+         proc: proc { |s| s.to_i }
 
   option :socket,
          short: '-s SOCKET',
@@ -83,15 +84,40 @@ class CheckMysqlReplicationStatus < Sensu::Plugin::Check::CLI
          description: 'Warning threshold for replication lag',
          default: 900,
          # #YELLOW
-         proc: lambda { |s| s.to_i } # rubocop:disable Lambda
+         proc: proc { |s| s.to_i }
 
   option :crit,
          short: '-c',
          long: '--critical=VALUE',
          description: 'Critical threshold for replication lag',
          default: 1800,
          # #YELLOW
-         proc: lambda { |s| s.to_i } # rubocop:disable Lambda
+         proc: proc { |s| s.to_i }
+
+  option :lag_outlier_retry,
+         long: '--lag-outlier-retry=VALUE',
+         description: 'Number of retries when lag outlier is detected (0 = disable)',
+         default: 0,
+         proc: proc { |s| s.to_i }
+
+  option :lag_outlier_threshold,
+         long: '--lag-outlier-threshold=VALUE',
+         description: 'Lag threshold to trigger outlier protection',
+         default: 100_000,
+         proc: proc { |s| s.to_i }
+
+  option :lag_outlier_sleep,
+         long: '--lag-outlier-sleep=VALUE',
+         description: 'Sleep between lag outlier protection retries',
+         default: 1,
+         proc: proc { |s| s.to_i }
+
+  option :lag_outlier_report,
+         long: '--lag-outlier-report=VALUE',
+         description: 'Level to report lag outlier',
+         default: :ok,
+         proc: proc(&:to_sym),
+         in: %i[ok warning critical]
 
   def detect_replication_status?(row)
     %w[
@@ -111,7 +137,7 @@ def slave_running?(row)
     ].all? { |key| row[key] =~ /Yes/ }
   end
 
-  def run
+  def open_connection
     if config[:ini]
       ini = IniFile.load(config[:ini])
       section = ini[config[:ini_section]]
@@ -122,64 +148,102 @@ def run
       db_pass = config[:pass]
     end
     db_host = config[:host]
-    db_conn = config[:master_connection]
 
     if [db_host, db_user, db_pass].any?(&:nil?)
       unknown 'Must specify host, user, password'
     end
 
-    begin
-      db = Mysql.new(db_host, db_user, db_pass, nil, config[:port], config[:socket])
+    Mysql.new(db_host, db_user, db_pass, nil, config[:port], config[:socket])
+  end
 
-      results = if db_conn.nil?
-                  db.query 'SHOW SLAVE STATUS'
-                else
-                  db.query "SHOW SLAVE '#{db_conn}' STATUS"
-                end
+  def query_slave_status(db)
+    db_conn = config[:master_connection]
 
-      unless results.nil?
-        results.each_hash do |row|
-          warn "couldn't detect replication status" unless detect_replication_status?(row)
+    sql = if db_conn.nil?
+            'SHOW SLAVE STATUS'
+          else
+            "SHOW SLAVE '#{db_conn}' STATUS"
+          end
+    result = db.query sql
+    return nil if result.nil?
 
-          slave_running = slave_running?(row)
+    rows = result.fetch_hash
+    return nil if rows.empty?
 
-          output = if db_conn.nil?
-                     'Slave not running!'
-                   else
-                     "Slave on master connection #{db_conn} not running!"
-                   end
+    rows
+  end
 
-          output += ' STATES:'
-          output += " Slave_IO_Running=#{row['Slave_IO_Running']}"
-          output += ", Slave_SQL_Running=#{row['Slave_SQL_Running']}"
-          output += ", LAST ERROR: #{row['Last_SQL_Error']}"
+  def broken_slave_message(row)
+    db_conn = config[:master_connection]
 
-          critical output unless slave_running
+    running = if db_conn.nil?
+                'Slave not running!'
+              else
+                "Slave on master connection #{db_conn} not running!"
+              end
+
+    "#{running} STATES: " + [
+      "Slave_IO_Running=#{row['Slave_IO_Running']}",
+      "Slave_SQL_Running=#{row['Slave_SQL_Running']}",
+      "LAST ERROR: #{row['Last_SQL_Error']}"
+    ].join(', ')
+  end
 
-          replication_delay = row['Seconds_Behind_Master'].to_i
+  def ok_slave_message
+    db_conn = config[:master_connection]
 
-          message = "replication delayed by #{replication_delay}"
+    if db_conn.nil?
+      'slave running: true'
+    else
+      "master connection: #{db_conn}, slave running: true"
+    end
+  end
 
-          if replication_delay > config[:warn] &&
-             replication_delay <= config[:crit]
-            warning message
-          elsif replication_delay >= config[:crit]
-            critical message
-          elsif db_conn.nil?
-            ok "slave running: #{slave_running}, #{message}"
-          else
-            ok "master connection: #{db_conn}, slave running: #{slave_running}, #{message}"
-          end
-        end
-        ok 'show slave status was nil. This server is not a slave.'
-      end
-    rescue Mysql::Error => e
-      errstr = "Error code: #{e.errno} Error message: #{e.error}"
-      critical "#{errstr} SQLSTATE: #{e.sqlstate}" if e.respond_to?('sqlstate')
-    rescue StandardError => e
-      critical e
-    ensure
-      db.close if db
+  def run
+    db = open_connection
+
+    retries = config[:lag_outlier_retry]
+    unknown 'Invalid value for --lag-outlier-retry' if retries < 0
+
+    lag_outlier = 0
+
+    while retries >= 0
+      row = query_slave_status(db)
+      ok 'show slave status was nil. This server is not a slave.' if row.nil?
+      warn "couldn't detect replication status" unless detect_replication_status?(row)
+
+      slave_running = slave_running?(row)
+      critical broken_slave_message(row) unless slave_running
+
+      replication_delay = row['Seconds_Behind_Master'].to_i
+      retries -= 1
+
+      break if retries < 0 || replication_delay < config[:lag_outlier_threshold]
+
+      # Outlier detected - wait and retry
+      lag_outlier = [lag_outlier, replication_delay].max
+      sleep config[:lag_outlier_sleep]
+    end
+
+    message = "replication delayed by #{replication_delay}"
+    message = "#{message}, with max. outlier at #{lag_outlier}" if lag_outlier > 0
+
+    # Special reporting if outlier condition was met but calmed down
+    if lag_outlier > 0 && replication_delay == 0
+      critical message if config[:lag_outlier_report] == :critical
+      warning message if config[:lag_outlier_report] == :warning
+    else
+      # TODO: (breaking change) Thresholds are exclusive which is not consistent with all other checks
+      critical message if replication_delay > config[:crit]
+      warning message if replication_delay > config[:warn]
     end
+    ok "#{ok_slave_message}, #{message}"
+  rescue Mysql::Error => e
+    errstr = "Error code: #{e.errno} Error message: #{e.error}"
+    critical "#{errstr} SQLSTATE: #{e.sqlstate}" if e.respond_to?('sqlstate')
+  rescue StandardError => e
+    critical e
+  ensure
+    db.close if db
   end
 end

test/check-mysql-replication-status_spec.rb

@@ -0,0 +1,125 @@
+#!/usr/bin/env ruby
+#
+#   check-mysql-replication-status_spec
+#
+# DESCRIPTION:
+#  rspec tests for check-mysql-replication-status
+#
+# OUTPUT:
+#   RSpec testing output: passes and failures info
+#
+# PLATFORMS:
+#   Linux
+#
+# DEPENDENCIES:
+#   rspec
+#
+# USAGE:
+#   For Rspec Testing
+#
+# NOTES:
+#   For Rspec Testing
+#
+# LICENSE:
+#   Copyright 2018 Jan Kunzmann, Erasys GmbH <jan.kunzmann@erasys.de>
+#   Released under the same terms as Sensu (the MIT license); see LICENSE
+#   for details.
+#
+
+require_relative '../bin/check-mysql-replication-status'
+require_relative './spec_helper.rb'
+
+# rubocop:disable Metrics/BlockLength
+describe CheckMysqlReplicationStatus do
+  let(:checker) { described_class.new }
+  let(:exit_code) { nil }
+
+  before(:each) do
+    def checker.ok(*_args)
+      exit 0
+    end
+
+    def checker.warning(*_args)
+      exit 1
+    end
+
+    def checker.critical(*_args)
+      exit 2
+    end
+  end
+
+  [
+    # IO Thread status | SQL Thread status | Lag | Expected exit code | Expected reporting level
+    ['Yes', 'Yes', 0, 0, :ok],
+    ['No',  'Yes', nil, 2, :critical],
+    ['Yes', 'No', nil, 2, :critical],
+    ['No',  'No',  nil, 2, :critical],
+    ['Yes', 'Yes', 900, 0, :ok],
+    ['Yes', 'Yes', 901, 1, :warning],
+    ['Yes', 'Yes', 1800, 1, :warning],
+    ['Yes', 'Yes', 1801, 2, :critical],
+  ].each do |testdata|
+    it "returns #{testdata[4]} for default thresholds" do
+      slave_status_row = {
+        'Slave_IO_State' => '',
+        'Slave_IO_Running' => testdata[0],
+        'Slave_SQL_Running' => testdata[1],
+        'Last_IO_Error' => '',
+        'Last_SQL_Error' => '',
+        'Seconds_Behind_Master' => testdata[2]
+      }
+      allow(checker).to receive(:open_connection) # do nothing
+      allow(checker).to receive(:query_slave_status).and_return slave_status_row
+      expect(checker).to receive(testdata[4]).once.and_call_original
+      begin
+        checker.run
+      rescue SystemExit => e
+        exit_code = e.status
+      end
+      expect(exit_code).to eq testdata[3]
+    end
+  end
+
+  [
+    # Lag after outlier | Configured reporting level | Exit code | Expected reporting level | Expected message
+    [0, :ok, 0, :ok, 'slave running: true, replication delayed by 0, with max. outlier at 100000'],
+    [99_999, :ok, 2, :critical, 'replication delayed by 99999, with max. outlier at 100000'],
+    [0, :critical, 2, :critical, 'replication delayed by 0, with max. outlier at 100000'],
+  ].each do |testdata|
+    it "sleeps with lag outlier protection and returns #{testdata[3]} (using default thresholds)" do
+      checker.config[:lag_outlier_retry] = 1
+      checker.config[:lag_outlier_sleep] = 10
+      checker.config[:lag_outlier_report] = testdata[1]
+
+      slave_status_row = [
+        {
+          'Slave_IO_State' => '',
+          'Slave_IO_Running' => 'Yes',
+          'Slave_SQL_Running' => 'Yes',
+          'Last_IO_Error' => '',
+          'Last_SQL_Error' => '',
+          'Seconds_Behind_Master' => 100_000
+        },
+        {
+          'Slave_IO_State' => '',
+          'Slave_IO_Running' => 'Yes',
+          'Slave_SQL_Running' => 'Yes',
+          'Last_IO_Error' => '',
+          'Last_SQL_Error' => '',
+          'Seconds_Behind_Master' => testdata[0]
+        }
+      ]
+
+      allow(checker).to receive(:open_connection) # do nothing
+      allow(checker).to receive(:query_slave_status).and_return slave_status_row[0], slave_status_row[1]
+      expect(checker).to receive(:sleep).with(10)
+      expect(checker).to receive(testdata[3]).with(testdata[4]).once.and_call_original
+      begin
+        checker.run
+      rescue SystemExit => e
+        exit_code = e.status
+      end
+      expect(exit_code).to eq testdata[2]
+    end
+  end
+end

test/spec_helper.rb

@@ -1,2 +1,21 @@
-require 'codeclimate-test-reporter'
-CodeClimate::TestReporter.start
+RSpec.configure do |c|
+  # Sensu plugins run in the context of an at_exit handler. This prevents
+  # code-under-test from being run at the end of the rspec suite.
+  c.before(:each) do
+    Sensu::Plugin::CLI.class_eval do
+      # PluginStub
+      class PluginStub
+        def run; end
+
+        def ok(*); end
+
+        def warning(*); end
+
+        def critical(*); end
+
+        def unknown(*); end
+      end
+      class_variable_set(:@@autorun, PluginStub)
+    end
+  end
+end