Fix erp5 slow queries logs

ERP5 software release has some support for mariadb slow queries:
 - run `pt-query-digest` daily
 - check that the number of slow queries and the slowest slow query do not exceed some thresholds defined as instance parameters

but this had issues:
 - the daily `pt-query-digest` reports where kept as not-compressed text files, which over time takes quite a lot of disk space
 - the threshold detection was not working, since strings and floats were compared - see nexedi/slapos.toolbox!83

This uses new techniques in software release testing from nexedi/slapos.core!245, we use [faketime] to simulate running crontabs and promises at a specific time in the future, so that we can assert the exact expected behaviour of crontab scripts.

[faketime]: https://github.com/wolfcw/libfaketime

See merge request nexedi/slapos!801

software/caddy-frontend/test/test.py

@@ -66,6 +66,7 @@ from cryptography.x509.oid import NameOID
 
 from slapos.testing.testcase import makeModuleSetUpAndTestCaseClass
 from slapos.testing.utils import findFreeTCPPort
+from slapos.testing.utils import getPromisePluginParameterDict
 setUpModule, SlapOSInstanceTestCase = makeModuleSetUpAndTestCaseClass(
     os.path.abspath(
         os.path.join(os.path.dirname(__file__), '..', 'software.cfg')))
@@ -243,44 +244,6 @@ def isHTTP2(domain, ip):
   return 'Using HTTP2, server supports multi-use' in err
 
 
-def getPluginParameterDict(software_path, filepath):
-  """Load the slapos monitor plugin and returns the configuration used by this plugin.
-
-  This allow to check that monitoring plugin are using a proper config.
-  """
-  # This is implemented by creating a wrapper script that loads the plugin wrapper
-  # script and returns its `extra_config_dict`. This might have to be adjusted if
-  # internals of slapos promise plugins change.
-
-  bin_file = os.path.join(software_path, 'bin', 'test-plugin-promise')
-
-  monitor_python_with_eggs = os.path.join(software_path, 'bin', 'monitor-pythonwitheggs')
-  if not os.path.exists(monitor_python_with_eggs):
-    raise ValueError("Monitoring stack's python does not exist at %s" % monitor_python_with_eggs)
-
-  with open(bin_file, 'w') as f:
-    f.write("""#!%s
-import os
-import importlib
-import sys
-import json
-
-filepath = sys.argv[1]
-sys.path[0:0] = [os.path.dirname(filepath)]
-filename = os.path.basename(filepath)
-module = importlib.import_module(os.path.splitext(filename)[0])
-
-print json.dumps(module.extra_config_dict)
-    """ % monitor_python_with_eggs)
-
-  os.chmod(bin_file, 0o755)
-  result = subprocess_output([bin_file, filepath]).strip()
-  try:
-    return json.loads(result)
-  except ValueError, e:
-    raise ValueError("%s\nResult was: %s" % (e, result))
-
-
 class TestDataMixin(object):
   def getTrimmedProcessInfo(self):
     return '\n'.join(sorted([
@@ -3569,7 +3532,7 @@ class TestSlave(SlaveHttpFrontendTestCase, TestDataMixin):
         'check-_monitor-ipv6-test-ipv6-packet-list-test.py'))[0]
     # get promise module and check that parameters are ok
     self.assertEqual(
-      getPluginParameterDict(self.software_path, monitor_file),
+      getPromisePluginParameterDict(monitor_file),
       {
         'frequency': '720',
         'address': 'monitor-ipv6-test'
@@ -3606,7 +3569,7 @@ class TestSlave(SlaveHttpFrontendTestCase, TestDataMixin):
         'check-_monitor-ipv4-test-ipv4-packet-list-test.py'))[0]
     # get promise module and check that parameters are ok
     self.assertEqual(
-      getPluginParameterDict(self.software_path, monitor_file),
+      getPromisePluginParameterDict(monitor_file),
       {
         'frequency': '720',
         'ipv4': 'true',
@@ -4702,8 +4665,7 @@ class TestRe6stVerificationUrlDefaultSlave(SlaveHttpFrontendTestCase,
     re6st_connectivity_promise_file = re6st_connectivity_promise_list[0]
 
     self.assertEqual(
-      getPluginParameterDict(
-        self.software_path, re6st_connectivity_promise_file),
+      getPromisePluginParameterDict(re6st_connectivity_promise_file),
       {
         'url': 'http://[2001:67c:1254:4::1]/index.html',
       }
@@ -4757,8 +4719,7 @@ class TestRe6stVerificationUrlSlave(SlaveHttpFrontendTestCase,
     re6st_connectivity_promise_file = re6st_connectivity_promise_list[0]
 
     self.assertEqual(
-      getPluginParameterDict(
-        self.software_path, re6st_connectivity_promise_file),
+      getPromisePluginParameterDict(re6st_connectivity_promise_file),
       {
         'url': 'some-re6st-verification-url',
       }
@@ -6462,7 +6423,7 @@ class TestSlaveRejectReportUnsafeDamaged(SlaveHttpFrontendTestCase):
     # get promise module and check that parameters are ok
 
     self.assertEqual(
-      getPluginParameterDict(self.software_path, monitor_file),
+      getPromisePluginParameterDict(monitor_file),
       {
         'frequency': '720',
         'ipv4': 'true',
@@ -6506,7 +6467,7 @@ class TestSlaveRejectReportUnsafeDamaged(SlaveHttpFrontendTestCase):
         'check-_monitor-ipv6-test-unsafe-ipv6-packet-list-test.py'))[0]
     # get promise module and check that parameters are ok
     self.assertEqual(
-      getPluginParameterDict(self.software_path, monitor_file),
+      getPromisePluginParameterDict(monitor_file),
       {
         'frequency': '720',
         'address': '${section:option}\nafternewline ipv6'

software/erp5/test/setup.py

@@ -48,6 +48,7 @@ setup(name=name,
         'psutil',
         'requests',
         'mysqlclient',
+        'backports.lzma',
         'cryptography',
         'pyOpenSSL',
         ],

software/erp5/test/test/test_mariadb.py

@@ -31,12 +31,19 @@ import json
 import glob
 import urlparse
 import socket
+import sys
 import time
 import contextlib
 import datetime
+import subprocess
+import gzip
 
+from backports import lzma
 import MySQLdb
 
+from slapos.testing.utils import CrontabMixin
+from slapos.testing.utils import getPromisePluginParameterDict
+
 from . import ERP5InstanceTestCase
 from . import setUpModule
 setUpModule  # pyflakes
@@ -56,8 +63,8 @@ class MariaDBTestCase(ERP5InstanceTestCase):
     return {
         'tcpv4-port': 3306,
         'max-connection-count': 5,
-        'max-slowqueries-threshold': 5,
-        'slowest-query-threshold': 10,
+        'max-slowqueries-threshold': 1,
+        'slowest-query-threshold': 0.1,
         # XXX what is this ? should probably not be needed here
         'name': cls.__name__,
         'monitor-passwd': 'secret',
@@ -86,6 +93,88 @@ class MariaDBTestCase(ERP5InstanceTestCase):
     )
 
 
+class TestCrontabs(MariaDBTestCase, CrontabMixin):
+
+  def test_full_backup(self):
+    self._executeCrontabAtDate('mariadb-backup', '2050-01-01')
+    with gzip.open(
+        os.path.join(
+            self.computer_partition_root_path,
+            'srv',
+            'backup',
+            'mariadb-full',
+            '20500101000000.sql.gz',
+        ),
+        'r') as dump:
+      self.assertIn('CREATE TABLE', dump.read())
+
+  def test_logrotate_and_slow_query_digest(self):
+    # slow query digest needs to run after logrotate, since it operates on the rotated
+    # file, so this tests both logrotate and slow query digest.
+
+    # run logrotate a first time so that it create state files
+    self._executeCrontabAtDate('logrotate', '2000-01-01')
+
+    # make two slow queries
+    cnx = self.getDatabaseConnection()
+    with contextlib.closing(cnx):
+      cnx.query("SELECT SLEEP(1.1)")
+      cnx.store_result()
+      cnx.query("SELECT SLEEP(1.2)")
+
+    # slow query crontab depends on crontab for log rotation
+    # to be executed first.
+    self._executeCrontabAtDate('logrotate', '2050-01-01')
+    # this logrotate leaves the log for the day as non compressed
+    rotated_log_file = os.path.join(
+        self.computer_partition_root_path,
+        'srv',
+        'backup',
+        'logrotate',
+        'mariadb_slowquery.log-20500101',
+    )
+    self.assertTrue(os.path.exists(rotated_log_file))
+
+    # then crontab to generate slow query report is executed
+    self._executeCrontabAtDate('generate-mariadb-slow-query-report', '2050-01-01')
+    # and it creates a report for the day
+    slow_query_report = os.path.join(
+        self.computer_partition_root_path,
+        'srv',
+        'monitor',
+        'private',
+        'slowquery_digest',
+        'slowquery_digest.txt-2050-01-01.xz',
+    )
+    with lzma.open(slow_query_report, 'r') as f:
+      # this is the hash for our "select sleep(n)" slow query
+      self.assertIn("ID 0xF9A57DD5A41825CA", f.read())
+
+    # on next day execution of logrotate, log files are compressed
+    self._executeCrontabAtDate('logrotate', '2050-01-02')
+    self.assertTrue(os.path.exists(rotated_log_file + '.xz'))
+    self.assertFalse(os.path.exists(rotated_log_file))
+
+    # there's a promise checking that the threshold is not exceeded
+    # and it reports a problem since we set a threshold of 1 slow query
+    check_slow_query_promise_plugin = getPromisePluginParameterDict(
+        os.path.join(
+            self.computer_partition_root_path,
+            'etc',
+            'plugin',
+            'check-slow-query-pt-digest-result.py',
+        ))
+    with self.assertRaises(subprocess.CalledProcessError) as error_context:
+      subprocess.check_output('faketime 2050-01-01 %s' % check_slow_query_promise_plugin['command'], shell=True)
+    self.assertEqual(
+        error_context.exception.output,
+"""\
+Threshold is lower than expected: 
+Expected total queries : 1.0 and current is: 2
+Expected slowest query : 0.1 and current is: 1
+""")
+
+
 class TestMariaDB(MariaDBTestCase):
   def test_utf8_collation(self):
     cnx = self.getDatabaseConnection()

software/slapos-sr-testing/buildout.hash.cfg

@@ -15,4 +15,4 @@
 
 [template]
 filename = instance.cfg
-md5sum = 25a4d7e438402d992edadf9339faf557
+md5sum = 14d2f49d20670e44c2a162bcec9e0a8e

software/slapos-sr-testing/instance.cfg

@@ -44,7 +44,7 @@ environment =
   SLAPOS_TEST_WORKING_DIR=${slapos-test-runner-environment:SLAPOS_TEST_WORKING_DIR}
 
 [slapos-test-runner-environment]
-PATH = {{ buildout['bin-directory'] }}:{{ curl_location }}/bin/:/usr/bin/:/bin
+PATH = {{ buildout['bin-directory'] }}:{{ curl_location }}/bin/:{{ faketime_location }}/bin/:/usr/bin/:/bin
 SLAPOS_TEST_IPV4 = ${slap-configuration:ipv4-random}
 SLAPOS_TEST_IPV6 = ${slap-configuration:ipv6-random}
 SLAPOS_TEST_WORKING_DIR = ${directory:working-dir}

software/slapos-sr-testing/software.cfg

@@ -4,6 +4,7 @@ extends =
   ../../component/bcrypt/buildout.cfg
   ../../component/curl/buildout.cfg
   ../../component/git/buildout.cfg
+  ../../component/faketime/buildout.cfg
   ../../component/pillow/buildout.cfg
   ../../component/python-cryptography/buildout.cfg
   ../../component/python-mysqlclient/buildout.cfg
@@ -174,6 +175,7 @@ eggs =
   ${python-pynacl:egg}
   ${python-cryptography:egg}
   ${python-mysqlclient:egg}
+  ${backports.lzma:egg}
   ${bcrypt:egg}
   slapos.libnetworkcache
   supervisor
@@ -200,7 +202,6 @@ eggs =
   ${slapos.test.dream-setup:egg}
   ${slapos.test.metabase-setup:egg}
   ${slapos.test.repman-setup:egg}
-  ${backports.lzma:egg}
 entry-points =
   runTestSuite=erp5.util.testsuite:runTestSuite
 scripts =
@@ -239,6 +240,7 @@ context =
   key slapos_location slapos-repository:location
   key interpreter eggs:interpreter
   key curl_location curl:location
+  key faketime_location faketime:location
   key tests :tests
 tests =
   ${slapos.test.kvm-setup:setup}
@@ -309,8 +311,6 @@ Django = 1.11
 # selenium==3.141.0
 urllib3 = 1.24.1
 
-backports.lzma = 0.0.13
-
 mock = 2.0.0
 testfixtures = 6.11
 funcsigs = 1.0.2

software/slapos-testing/software.cfg

@@ -83,8 +83,7 @@ setup = ${slapos.recipe.template-repository:location}
 
 [slapos.toolbox-setup]
 <= setup-develop-egg
-# XXX slapos.toolbox does not have `test` extra require, `mock` and `pycurl` are only listed in `tests_require` and are listed explicitly
-egg = slapos.toolbox
+egg = slapos.toolbox[test]
 setup = ${slapos.toolbox-repository:location}
 depends = ${slapos.core-setup:egg}
 
@@ -98,6 +97,7 @@ recipe = zc.recipe.egg
 eggs =
   ${lxml-python:egg}
   ${python-cryptography:egg}
+  ${backports.lzma:egg}
   ${pycurl:egg}
   ${bcrypt:egg}
   dnspython
@@ -113,7 +113,6 @@ eggs =
   ${slapos.toolbox-setup:egg}
   ${slapos.libnetworkcache-setup:egg}
   ${slapos.rebootstrap-setup:egg}
-  mock
   zope.testing
   supervisor
 entry-points =

stack/erp5/buildout.cfg

@@ -9,6 +9,7 @@ extends =
   ../../component/git/buildout.cfg
   ../../component/graphviz/buildout.cfg
   ../../component/gzip/buildout.cfg
+  ../../component/xz-utils/buildout.cfg
   ../../component/haproxy/buildout.cfg
   ../../component/hookbox/buildout.cfg
   ../../component/findutils/buildout.cfg
@@ -178,6 +179,7 @@ context =
     key erp5_location erp5:location
     key findutils_location findutils:location
     key gzip_location gzip:location
+    key xz_utils_location xz-utils:location
     key haproxy_location haproxy:location
     key instance_common_cfg instance-common:rendered
     key jsl_location jsl:location
@@ -560,11 +562,7 @@ setup = ${erp5:location}
 [zodbpack]
 recipe = zc.recipe.egg
 eggs =
-  ${lxml-python:egg}
-  ${pycurl:egg}
-  ${python-PyYAML:egg}
-  ${python-cryptography:egg}
-  ${python-cliff:egg}
+  ${slapos-toolbox:dependencies}
   slapos.toolbox[zodbpack]
 scripts =
   zodbpack

stack/erp5/buildout.hash.cfg

@@ -18,7 +18,7 @@ md5sum = 85ce1e2f3d251aa435fef8118dca8a63
 
 [mariadb-slow-query-report-script]
 filename = mysql-querydigest.sh.in
-md5sum = 0c0d98a68230cd0ad36046bb25b35f4a
+md5sum = 7b14d2b81f2c864e47682ddb03b1b663
 
 [mariadb-start-clone-from-backup]
 filename = instance-mariadb-start-clone-from-backup.sh.in
@@ -26,7 +26,7 @@ md5sum = d10b8e35b02b5391cf46bf0c7dbb1196
 
 [template-mariadb]
 filename = instance-mariadb.cfg.in
-md5sum = bfed6ac56c3ba0e96be4c9474dac6f20
+md5sum = 7d064777c1c4e7b275b255db4f4b1da9
 
 [template-kumofs]
 filename = instance-kumofs.cfg.in
@@ -70,7 +70,7 @@ md5sum = cc19560b9400cecbd23064d55c501eec
 
 [template]
 filename = instance.cfg.in
-md5sum = 328ea2bb5f2bff18f8be8c541c01f260
+md5sum = 5c5250112b87a3937f939028f9594b85
 
 [monitor-template-dummy]
 filename = dummy.cfg

stack/erp5/instance-mariadb.cfg.in

@@ -326,17 +326,18 @@ context =
   raw slow_query_path ${directory:srv}/backup/logrotate/mariadb_slowquery.log
   raw pt_query_exec ${binary-wrap-pt-digest:wrapper-path}
   raw dash {{ parameter_dict['dash-location'] }}/bin/dash
+  raw xz {{ parameter_dict['xz-utils-location'] }}/bin/xz
   key output_folder directory:slowquery
 
-[slow-query-digest-parameters]
-max_queries_threshold = {{ slapparameter_dict['max-slowqueries-threshold'] }}
-slowest_queries_threshold = {{ slapparameter_dict['slowest-query-threshold'] }}
-
+{%if slapparameter_dict.get('max-slowqueries-threshold') and slapparameter_dict.get('slowest-query-threshold') %}
 [{{ section('monitor-promise-slowquery-result') }}]
 <= monitor-promise-base
 module = check_command_execute
 name = check-slow-query-pt-digest-result.py
-config-command = "{{ parameter_dict['promise-check-slow-queries-digest-result'] }}" --ptdigest_path "${directory:slowquery}" --status_file ${monitor-directory:private}/mariadb_slow_query.report.json --max_queries_threshold "${slow-query-digest-parameters:max_queries_threshold}" --slowest_query_threshold "${slow-query-digest-parameters:slowest_queries_threshold}"
+config-command = "{{ parameter_dict['promise-check-slow-queries-digest-result'] }}" --ptdigest_path "${directory:slowquery}" --status_file ${monitor-directory:private}/mariadb_slow_query.report.json --max_queries_threshold "${:max_queries_threshold}" --slowest_query_threshold "${:slowest_queries_threshold}"
+max_queries_threshold = {{ slapparameter_dict['max-slowqueries-threshold'] }}
+slowest_queries_threshold = {{ slapparameter_dict['slowest-query-threshold'] }}
+{%-endif%}
 
 [{{ section('promise-check-computer-memory') }}]
 <= monitor-promise-base

stack/erp5/instance.cfg.in

@@ -144,6 +144,7 @@ coreutils-location = {{ coreutils_location }}
 dash-location = {{ dash_location }}
 findutils-location = {{ findutils_location }}
 gzip-location = {{ gzip_location }}
+xz-utils-location = {{ xz_utils_location }}
 mariadb-location = {{ mariadb_location }}
 template-my-cnf = {{ template_my_cnf }}
 template-mariadb-initial-setup = {{ template_mariadb_initial_setup }}

stack/erp5/mysql-querydigest.sh.in

 #!{{dash}}
 # BEWARE: This file is operated by slapgrid
 
+set -e
+
 SLOW_QUERY_PATH='{{slow_query_path}}'
 OUTPUT_FOLDER='{{output_folder}}'
 PT_QUERY_EXEC='{{pt_query_exec}}'
@@ -21,6 +23,6 @@ if [ ! -f "$SLOW_LOG" ]; then
   exit 1
 fi
 
-"$PT_QUERY_EXEC" "$SLOW_LOG" > "$OUTPUT_FILE" && \
-echo "Report generated successfully." || \
-echo "Report failed with code $?"
+"$PT_QUERY_EXEC" "$SLOW_LOG" > "$OUTPUT_FILE"
+
+{{ xz }} -9 "$OUTPUT_FILE"

stack/lamp/buildout.cfg

@@ -31,6 +31,7 @@ extends =
   ../../component/perl/buildout.cfg
   ../../component/sqlite3/buildout.cfg
   ../../component/stunnel/buildout.cfg
+  ../../component/xz-utils/buildout.cfg
   ../../component/zlib/buildout.cfg
   ../erp5/buildout.cfg
   ../logrotate/buildout.cfg
@@ -88,6 +89,7 @@ context =
     key logrotate_location logrotate:location
     key logrotate_cfg template-logrotate-base:rendered
     key gzip_location gzip:location
+    key xz_utils_location xz-utils:location
     key stunnel_location stunnel:location
     key template_monitor monitor2-template:rendered
     key mariadb_link_binary template-mariadb:link-binary
@@ -137,6 +139,4 @@ location = ${buildout:parts-directory}/${:_buildout_section_name_}
 [eggs]
 recipe = zc.recipe.egg
 eggs =
-  ${lxml-python:egg}
-  ${pycurl:egg}
-  slapos.toolbox
+  ${slapos-toolbox:eggs}

stack/lamp/buildout.hash.cfg

@@ -14,7 +14,7 @@
 # not need these here).
 [instance]
 filename = instance.cfg.in
-md5sum = be63b936ed521edaead8e0770ac64621
+md5sum = 5c953c0f5d3376718eb9c4030288647a
 
 [instance-apache-php]
 filename = instance-apache-php.cfg.in

stack/lamp/instance.cfg.in

@@ -78,6 +78,7 @@ coreutils-location = {{ coreutils_location }}
 dash-location = {{ dash_location }}
 findutils-location = {{ findutils_location }}
 gzip-location = {{ gzip_location }}
+xz-utils-location = {{ xz_utils_location }}
 mariadb-location = {{ mariadb_location }}
 template-my-cnf = {{ template_my_cnf }}
 template-mariadb-initial-setup = {{ template_mariadb_initial_setup }}

stack/slapos.cfg

@@ -23,6 +23,7 @@ extends =
   ../component/defaults.cfg
   ../component/git/buildout.cfg
   ../component/lxml-python/buildout.cfg
+  ../component/python-backports-lzma/buildout.cfg
   ../component/python-cffi/buildout.cfg
   ../component/python-cliff/buildout.cfg
   ../component/python-cachecontrol/buildout.cfg
@@ -103,10 +104,13 @@ eggs =
 [slapos-toolbox]
 recipe = zc.recipe.egg
 eggs =
+  ${:dependencies}
+  slapos.toolbox
+dependencies =
   ${lxml-python:egg}
   ${pycurl:egg}
   ${python-cryptography:egg}
-  slapos.toolbox
+  ${backports.lzma:egg}
 
 [jsonschema]
 recipe = zc.recipe.egg:custom
@@ -135,6 +139,7 @@ MarkupSafe = 1.0
 PyYAML = 3.13
 Werkzeug = 0.12
 asn1crypto = 1.3.0
+backports.lzma = 0.0.14
 cffi = 1.14.0
 click = 6.7
 cliff = 2.4.0
@@ -167,7 +172,7 @@ slapos.libnetworkcache = 0.20
 slapos.rebootstrap = 4.5
 slapos.recipe.build = 0.45
 slapos.recipe.cmmi = 0.16
-slapos.toolbox = 0.109
+slapos.toolbox = 0.110
 stevedore = 1.21.0
 subprocess32 = 3.5.3
 unicodecsv = 0.14.1