http: store http request elapsed time

The goal is to detect speed regression of website access.

The elapsed time value is updated in the DB only if an arbitrary threshold is modified (<200ms = fast, <500ms = moderate, >500ms = slow).

src/surykatka/bot.py

@@ -284,6 +284,7 @@ class WebBot:
             result_dict["http_query"].append(
                 {
                     "status_code": network_change["status_code"],
+                    "total_seconds": network_change["total_seconds"],
                     "url": network_change["url"],
                     "ip": network_change["ip"],
                     "date": rfc822(network_change["status"]),

src/surykatka/db.py

@@ -20,6 +20,7 @@
 import peewee
 from playhouse.sqlite_ext import SqliteExtDatabase
 import datetime
+from playhouse.migrate import migrate, SqliteMigrator
 
 
 class LogDB:
@@ -114,6 +115,7 @@ class LogDB:
             ip = peewee.TextField()
             url = peewee.TextField()
             status_code = peewee.IntegerField()
+            total_seconds = peewee.FloatField(default=0)
 
             class Meta:
                 primary_key = peewee.CompositeKey("status", "ip", "url")
@@ -129,7 +131,7 @@ class LogDB:
     def createTables(self):
         # http://www.sqlite.org/pragma.html#pragma_user_version
         db_version = self._db.pragma("user_version")
-        expected_version = 2
+        expected_version = 3
         if db_version != expected_version:
             with self._db.transaction():
 
@@ -150,7 +152,18 @@ class LogDB:
                     # version 1 without SSL support
                     self._db.create_tables([self.SslChange])
 
-                else:
+                if (0 < db_version) and (db_version <= 2):
+                    # version 2 without the http total_seconds column
+                    migrator = SqliteMigrator(self._db)
+                    migrate(
+                        migrator.add_column(
+                            "HttpCodeChange",
+                            "total_seconds",
+                            self.HttpCodeChange.total_seconds,
+                        )
+                    )
+
+                if db_version >= expected_version:
                     raise ValueError("Can not downgrade SQLite DB")
 
                 self._db.pragma("user_version", expected_version)

src/surykatka/http.py

@@ -78,7 +78,6 @@ def request(url, timeout=TIMEOUT, headers=None, session=requests, version=0):
     except requests.exceptions.TooManyRedirects:
         response = requests.models.Response()
         response.status_code = 520
-
     return response
 
 
@@ -106,7 +105,20 @@ def reportHttp(db, ip=None, url=None):
     return query
 
 
-def logHttpStatus(db, ip, url, code, status_id):
+def calculateSpeedRange(total_seconds):
+    # Prevent updating the DB by defining acceptable speed range
+    if total_seconds == 0:
+        # error cases
+        return "BAD"
+    elif total_seconds < 0.2:
+        return "FAST"
+    elif total_seconds < 0.5:
+        return "MODERATE"
+    else:
+        return "SLOW"
+
+
+def logHttpStatus(db, ip, url, code, total_seconds, status_id):
 
     with db._db.atomic():
         try:
@@ -115,9 +127,20 @@ def logHttpStatus(db, ip, url, code, status_id):
         except db.HttpCodeChange.DoesNotExist:
             previous_entry = None
 
-        if (previous_entry is None) or (previous_entry.status_code != code):
+        if (
+            (previous_entry is None)
+            or (previous_entry.status_code != code)
+            or (
+                calculateSpeedRange(previous_entry.total_seconds)
+                != calculateSpeedRange(total_seconds)
+            )
+        ):
             previous_entry = db.HttpCodeChange.create(
-                status=status_id, ip=ip, url=url, status_code=code
+                status=status_id,
+                ip=ip,
+                url=url,
+                status_code=code,
+                total_seconds=total_seconds,
             )
         return previous_entry.status_id
 
@@ -146,4 +169,11 @@ def checkHttpStatus(db, status_id, url, ip, bot_version, timeout=TIMEOUT):
     response = request(
         ip_url, headers={"Host": hostname}, version=bot_version, **request_kw
     )
-    logHttpStatus(db, ip, url, response.status_code, status_id)
+    logHttpStatus(
+        db,
+        ip,
+        url,
+        response.status_code,
+        response.elapsed.total_seconds(),
+        status_id,
+    )

tests/test_db.py

@@ -19,6 +19,42 @@
 
 import unittest
 from surykatka.db import LogDB
+from playhouse.migrate import migrate, SqliteMigrator
+from collections import namedtuple
+from playhouse.reflection import Introspector
+
+ValidationResult = namedtuple(
+    "ValidationResult",
+    ("valid", "table_exists", "add_fields", "remove_fields", "change_fields"),
+)
+
+
+def validate_schema(model):
+    db = model._meta.database
+    table = model._meta.table_name
+    if not db.table_exists(table):
+        return ValidationResult(False, False, None, None, None)
+
+    introspector = Introspector.from_database(db)
+    db_model = introspector.generate_models(table_names=[table])[table]
+
+    columns = set(model._meta.columns)
+    db_columns = set(db_model._meta.columns)
+
+    to_remove = [model._meta.columns[c] for c in columns - db_columns]
+    to_add = [db_model._meta.columns[c] for c in db_columns - columns]
+    to_change = []
+    intersect = columns & db_columns  # Take intersection and remove matches.
+    for column in intersect:
+        field = model._meta.columns[column]
+        db_field = db_model._meta.columns[column]
+        if (field.field_type != db_field.field_type) and (
+            not (field.field_type == "BIGINT")
+        ):
+            to_change.append((field, db_field))
+
+    is_valid = not any((to_remove, to_add, to_change))
+    return ValidationResult(is_valid, True, to_add, to_remove, to_change)
 
 
 class SurykatkaDBTestCase(unittest.TestCase):
@@ -28,7 +64,7 @@ class SurykatkaDBTestCase(unittest.TestCase):
     def test_createTable(self):
         assert self.db._db.pragma("user_version") == 0
         self.db.createTables()
-        assert self.db._db.pragma("user_version") == 2
+        assert self.db._db.pragma("user_version") == 3
 
     def test_downgrade(self):
         assert self.db._db.pragma("user_version") == 0
@@ -56,10 +92,47 @@ class SurykatkaDBTestCase(unittest.TestCase):
                     self.db.DnsChange,
                 ]
             )
+            migrate(
+                SqliteMigrator(self.db._db).drop_column(
+                    "HttpCodeChange", "total_seconds"
+                ),
+            )
             self.db._db.pragma("user_version", 1)
 
         self.db.createTables()
-        assert self.db._db.pragma("user_version") == 2
+        assert self.db._db.pragma("user_version") == 3
+        assert validate_schema(self.db.SslChange).valid, validate_schema(
+            self.db.SslChange
+        )
+
+    def test_migrationFromVersion2(self):
+        assert self.db._db.pragma("user_version") == 0
+        # Recreate version 2
+        with self.db._db.transaction():
+
+            self.db._db.create_tables(
+                [
+                    self.db.Status,
+                    self.db.ConfigurationChange,
+                    self.db.HttpCodeChange,
+                    self.db.NetworkChange,
+                    self.db.PlatformChange,
+                    self.db.DnsChange,
+                    self.db.SslChange,
+                ]
+            )
+            migrate(
+                SqliteMigrator(self.db._db).drop_column(
+                    "HttpCodeChange", "total_seconds"
+                ),
+            )
+            self.db._db.pragma("user_version", 2)
+
+        self.db.createTables()
+        assert self.db._db.pragma("user_version") == 3
+        assert validate_schema(self.db.HttpCodeChange).valid, validate_schema(
+            self.db.HttpCodeChange
+        )
 
 
 def suite():

tests/test_http.py

@@ -184,23 +184,32 @@ class SurykatkaHttpTestCase(unittest.TestCase):
         ip = "127.0.0.1"
         url = "http://example.org"
         status_code = 200
+        total_seconds = 0.1
         status_id = logStatus(self.db, "foo")
-        result = logHttpStatus(self.db, ip, url, status_code, status_id)
+        result = logHttpStatus(
+            self.db, ip, url, status_code, total_seconds, status_id
+        )
         assert self.db.HttpCodeChange.select().count() == 1
         assert self.db.HttpCodeChange.get().ip == ip
         assert self.db.HttpCodeChange.get().url == url
         assert self.db.HttpCodeChange.get().status_code == status_code
         assert self.db.HttpCodeChange.get().status_id == status_id
+        assert self.db.HttpCodeChange.get().total_seconds == total_seconds
         assert result == status_id
 
     def test_logHttpStatus_insertOnlyOnePerStatusIdIPUrl(self):
         ip = "127.0.0.1"
         url = "http://example.org"
         status_code = 200
+        total_seconds = 0.1
         status_id = logStatus(self.db, "foo")
-        result = logHttpStatus(self.db, ip, url, status_code, status_id)
+        result = logHttpStatus(
+            self.db, ip, url, status_code, total_seconds, status_id
+        )
         try:
-            logHttpStatus(self.db, ip, url, status_code + 1, status_id)
+            logHttpStatus(
+                self.db, ip, url, status_code + 1, total_seconds + 1, status_id
+            )
         except peewee.IntegrityError:
             assert self.db.HttpCodeChange.select().count() == 1
             assert self.db.HttpCodeChange.get().status_id == result
@@ -211,26 +220,37 @@ class SurykatkaHttpTestCase(unittest.TestCase):
         ip = "127.0.0.1"
         url = "http://example.org"
         status_code = 200
+        total_seconds = 0.1
         status_id = logStatus(self.db, "foo")
-        result = logHttpStatus(self.db, ip, url, status_code, status_id)
+        result = logHttpStatus(
+            self.db, ip, url, status_code, total_seconds, status_id
+        )
         status_id_2 = logStatus(self.db, "foo")
-        result_2 = logHttpStatus(self.db, ip, url, status_code, status_id_2)
+        result_2 = logHttpStatus(
+            self.db, ip, url, status_code, total_seconds, status_id_2
+        )
         assert result_2 == result
         assert self.db.HttpCodeChange.select().count() == 1
         assert self.db.HttpCodeChange.get().ip == ip
         assert self.db.HttpCodeChange.get().url == url
         assert self.db.HttpCodeChange.get().status_code == status_code
+        assert self.db.HttpCodeChange.get().total_seconds == total_seconds
         assert self.db.HttpCodeChange.get().status_id == status_id
 
     def test_logHttpStatus_insertWhenDifferentStatusCode(self):
         ip = "127.0.0.1"
         url = "http://example.org"
         status_code = 200
+        total_seconds = 0.1
         status_code_2 = status_code + 1
         status_id = logStatus(self.db, "foo")
-        result = logHttpStatus(self.db, ip, url, status_code, status_id)
+        result = logHttpStatus(
+            self.db, ip, url, status_code, total_seconds, status_id
+        )
         status_id_2 = logStatus(self.db, "foo")
-        result_2 = logHttpStatus(self.db, ip, url, status_code_2, status_id_2)
+        result_2 = logHttpStatus(
+            self.db, ip, url, status_code_2, total_seconds, status_id_2
+        )
         assert result_2 != result
         assert self.db.HttpCodeChange.select().count() == 2
         assert (
@@ -251,6 +271,12 @@ class SurykatkaHttpTestCase(unittest.TestCase):
             ).status_code
             == status_code
         )
+        assert (
+            self.db.HttpCodeChange.get(
+                self.db.HttpCodeChange.status == status_id
+            ).total_seconds
+            == total_seconds
+        )
         assert (
             self.db.HttpCodeChange.get(
                 self.db.HttpCodeChange.status == status_id_2
@@ -269,18 +295,152 @@ class SurykatkaHttpTestCase(unittest.TestCase):
             ).status_code
             == status_code_2
         )
+        assert (
+            self.db.HttpCodeChange.get(
+                self.db.HttpCodeChange.status == status_id_2
+            ).total_seconds
+            == total_seconds
+        )
+
+    def test_logHttpStatus_insertWhenDifferentTotalSeconds(self):
+        ip = "127.0.0.1"
+        url = "http://example.org"
+        status_code = 200
+        total_seconds_error = 0
+        total_seconds_fast = 0.001
+        total_seconds_moderate = 0.2
+        total_seconds_slow = 0.5
+        status_id = logStatus(self.db, "foo")
+        result = logHttpStatus(
+            self.db, ip, url, status_code, total_seconds_error, status_id
+        )
+        status_id_2 = logStatus(self.db, "foo")
+        result_2 = logHttpStatus(
+            self.db, ip, url, status_code, total_seconds_fast, status_id_2
+        )
+        status_id_3 = logStatus(self.db, "foo")
+        result_3 = logHttpStatus(
+            self.db, ip, url, status_code, total_seconds_moderate, status_id_3
+        )
+        status_id_4 = logStatus(self.db, "foo")
+        result_4 = logHttpStatus(
+            self.db, ip, url, status_code, total_seconds_slow, status_id_4
+        )
+        assert status_id == result
+        assert status_id_2 == result_2
+        assert status_id_3 == result_3
+        assert status_id_4 == result_4
+        assert self.db.HttpCodeChange.select().count() == 4
+
+        assert (
+            self.db.HttpCodeChange.get(
+                self.db.HttpCodeChange.status == status_id
+            ).total_seconds
+            == total_seconds_error
+        )
+        assert (
+            self.db.HttpCodeChange.get(
+                self.db.HttpCodeChange.status == status_id_2
+            ).total_seconds
+            == total_seconds_fast
+        )
+        assert (
+            self.db.HttpCodeChange.get(
+                self.db.HttpCodeChange.status == status_id_3
+            ).total_seconds
+            == total_seconds_moderate
+        )
+        assert (
+            self.db.HttpCodeChange.get(
+                self.db.HttpCodeChange.status == status_id_4
+            ).total_seconds
+            == total_seconds_slow
+        )
+
+    def test_logHttpStatus_skipSameFastRangeQuery(self):
+        ip = "127.0.0.1"
+        url = "http://example.org"
+        status_code = 200
+        total_seconds = 0.001
+        total_seconds_2 = 0.199
+        status_id = logStatus(self.db, "foo")
+        result = logHttpStatus(
+            self.db, ip, url, status_code, total_seconds, status_id
+        )
+        status_id_2 = logStatus(self.db, "foo")
+        result_2 = logHttpStatus(
+            self.db, ip, url, status_code, total_seconds_2, status_id_2
+        )
+        assert result_2 == result
+        assert self.db.HttpCodeChange.select().count() == 1
+        assert self.db.HttpCodeChange.get().ip == ip
+        assert self.db.HttpCodeChange.get().url == url
+        assert self.db.HttpCodeChange.get().status_code == status_code
+        assert self.db.HttpCodeChange.get().total_seconds == total_seconds
+        assert self.db.HttpCodeChange.get().status_id == status_id
+
+    def test_logHttpStatus_skipSameModerateRangeQuery(self):
+        ip = "127.0.0.1"
+        url = "http://example.org"
+        status_code = 200
+        total_seconds = 0.2
+        total_seconds_2 = 0.499
+        status_id = logStatus(self.db, "foo")
+        result = logHttpStatus(
+            self.db, ip, url, status_code, total_seconds, status_id
+        )
+        status_id_2 = logStatus(self.db, "foo")
+        result_2 = logHttpStatus(
+            self.db, ip, url, status_code, total_seconds_2, status_id_2
+        )
+        assert result_2 == result
+        assert self.db.HttpCodeChange.select().count() == 1
+        assert self.db.HttpCodeChange.get().ip == ip
+        assert self.db.HttpCodeChange.get().url == url
+        assert self.db.HttpCodeChange.get().status_code == status_code
+        assert self.db.HttpCodeChange.get().total_seconds == total_seconds
+        assert self.db.HttpCodeChange.get().status_id == status_id
+
+    def test_logHttpStatus_skipSameSlowRangeQuery(self):
+        ip = "127.0.0.1"
+        url = "http://example.org"
+        status_code = 200
+        total_seconds = 0.5
+        total_seconds_2 = 99
+        status_id = logStatus(self.db, "foo")
+        result = logHttpStatus(
+            self.db, ip, url, status_code, total_seconds, status_id
+        )
+        status_id_2 = logStatus(self.db, "foo")
+        result_2 = logHttpStatus(
+            self.db, ip, url, status_code, total_seconds_2, status_id_2
+        )
+        assert result_2 == result
+        assert self.db.HttpCodeChange.select().count() == 1
+        assert self.db.HttpCodeChange.get().ip == ip
+        assert self.db.HttpCodeChange.get().url == url
+        assert self.db.HttpCodeChange.get().status_code == status_code
+        assert self.db.HttpCodeChange.get().total_seconds == total_seconds
+        assert self.db.HttpCodeChange.get().status_id == status_id
 
     def test_logHttpStatus_insertDifferentUrl(self):
         ip = "127.0.0.1"
         ip_2 = ip + "2"
         url = "http://example.org"
         url_2 = url + "2"
+        total_seconds = 0.1
         status_code = 200
         status_id = logStatus(self.db, "foo")
-        logHttpStatus(self.db, ip, url, status_code, status_id)
-        logHttpStatus(self.db, ip_2, url, status_code, status_id)
-        logHttpStatus(self.db, ip, url_2, status_code, status_id)
-        logHttpStatus(self.db, ip_2, url_2, status_code, status_id)
+        logHttpStatus(self.db, ip, url, status_code, total_seconds, status_id)
+        logHttpStatus(
+            self.db, ip_2, url, status_code, total_seconds, status_id
+        )
+        logHttpStatus(
+            self.db, ip, url_2, status_code, total_seconds, status_id
+        )
+        logHttpStatus(
+            self.db, ip_2, url_2, status_code, total_seconds, status_id
+        )
         assert self.db.HttpCodeChange.select().count() == 4
 
     ################################################