Merge lp:~jtv/maas/bug-1354511 into lp:~maas-committers/maas/trunk

[Jeroen T. Vermeulen]

When timing out nodes that haven't finished commissioning, compare the last-update timestamp to the database clock (from which it was also generated), not to the Python-side clock. Timezone skew between the two could cause nodes to time out immediately, or hours late.

The timezone skew was causing test failures for me (and, I gather, for Julian as well) as a result of recent travel. A database cluster set up while in one time zone might break tests run in another. The new test simulates this situation, and reproduces the problem, as long as your timezone offset from UTC is less than 12 hours.

I intend to backport this fix to the currently maintained versions; I believe those are at least 1.2 (in 12.04 LTS), 1.5 (in 14.04 LTS), and 1.6 (for 14.10).

Jeroen

[Blake Rouse (blake-rouse)]

Looks good. No blockers, just two comments. Comments inline.

review: Approve

=== modified file 'src/maasserver/api.py'
--- src/maasserver/api.py	2014-08-05 15:48:54 +0000
+++ src/maasserver/api.py	2014-08-08 19:55:26 +0000
@@ -102,10 +102,6 @@
     b64encode,
     )
 from cStringIO import StringIO
-from datetime import (
-    datetime,
-    timedelta,
-    )
 from functools import partial
 import httplib
 from inspect import getdoc
@@ -858,12 +854,35 @@
         Anything that has been commissioning for longer than
         settings.COMMISSIONING_TIMEOUT is moved into the FAILED_TESTS status.
         """
-        interval = timedelta(minutes=settings.COMMISSIONING_TIMEOUT)
-        cutoff = datetime.now() - interval
-        query = Node.objects.filter(
-            status=NODE_STATUS.COMMISSIONING, updated__lte=cutoff)
+        # Compute the cutoff time on the database, using the database's
+        # clock to compare to the "updated" timestamp, also set from the
+        # database's clock.  Otherwise, a sufficient difference between the
+        # two clocks (including timezone offset!) might cause commissioning to
+        # "time out" immediately, or hours late.
+        #
+        # This timeout relies on nothing else updating the commissioning node
+        # within the hour.  Otherwise, the timestamp will be refreshed as a
+        # side effect and timeout will be postponed.
+        #
+        # This query both identifies and updates the failed nodes.  It
+        # refreshes the "updated" timestamp, but does not run any Django-side
+        # code associated with saving the nodes.
+        params = {
+            'commissioning': NODE_STATUS.COMMISSIONING,
+            'failed_tests': NODE_STATUS.FAILED_TESTS,
+            'minutes': settings.COMMISSIONING_TIMEOUT
+            }
+        query = Node.objects.raw("""
+            UPDATE maasserver_node
+            SET
+                status = %(failed_tests)s,
+                updated = now()
+            WHERE
+                status = %(commissioning)s AND
+                updated <= (now() - interval '%(minutes)f minutes')
+            RETURNING *
+            """ % params)
         results = list(query)
-        query.update(status=NODE_STATUS.FAILED_TESTS)
         # Note that Django doesn't call save() on updated nodes here,
         # but I don't think anything requires its effects anyway.
         return results

=== modified file 'src/maasserver/tests/test_api_commissioning.py'
--- src/maasserver/tests/test_api_commissioning.py	2014-08-08 19:04:18 +0000
+++ src/maasserver/tests/test_api_commissioning.py	2014-08-08 19:55:26 +0000
@@ -15,15 +15,12 @@
 __all__ = []
 
 from base64 import b64encode
-from datetime import (
-    datetime,
-    timedelta,
-    )
 import httplib
 import json
 
 from django.conf import settings
 from django.core.urlresolvers import reverse
+from django.db import connection
 from maasserver.enum import NODE_STATUS
 from maasserver.testing.api import APITestCase
 from maasserver.testing.factory import factory
@@ -36,9 +33,22 @@
 class TestCommissioningTimeout(MAASServerTestCase):
     """Testing of commissioning timeout API."""
 
+    def age_node(self, node, minutes, cursor=None):
+        """Set back the update/creation timestamps on `node` by `minutes`."""
+        if cursor is None:
+            cursor = connection.cursor()
+        cursor.execute("""
+            UPDATE maasserver_node
+            SET
+                created = created - interval '%f minutes',
+                updated = updated - interval '%f minutes'
+            WHERE id = %d
+            """ % (minutes, minutes, node.id))
+
     def test_check_with_no_action(self):
         self.client_log_in()
         node = factory.make_node(status=NODE_STATUS.READY)
+        self.age_node(node, settings.COMMISSIONING_TIMEOUT + 100)
         response = self.client.post(
             reverse('nodes_handler'), {'op': 'check_commissioning'})
         # Anything that's not commissioning should be ignored.
@@ -49,8 +59,8 @@
 
     def test_check_with_commissioning_but_not_expired_node(self):
         self.client_log_in()
-        node = factory.make_node(
-            status=NODE_STATUS.COMMISSIONING)
+        node = factory.make_node(status=NODE_STATUS.COMMISSIONING)
+        self.age_node(node, settings.COMMISSIONING_TIMEOUT - 1)
         response = self.client.post(
             reverse('nodes_handler'), {'op': 'check_commissioning'})
         node = reload_object(node)
@@ -60,12 +70,8 @@
 
     def test_check_with_commissioning_and_expired_node(self):
         self.client_log_in()
-        # Have an interval 1 second longer than the timeout.
-        interval = timedelta(seconds=1, minutes=settings.COMMISSIONING_TIMEOUT)
-        updated_at = datetime.now() - interval
-        node = factory.make_node(
-            status=NODE_STATUS.COMMISSIONING, created=datetime.now(),
-            updated=updated_at)
+        node = factory.make_node(status=NODE_STATUS.COMMISSIONING)
+        self.age_node(node, settings.COMMISSIONING_TIMEOUT + 1)
 
         response = self.client.post(
             reverse('nodes_handler'), {'op': 'check_commissioning'})
@@ -82,6 +88,36 @@
                  for response_node in json.loads(response.content)],
             ))
 
+    def test_check_ignores_timezone_skew_between_python_and_database(self):
+        cursor = connection.cursor()
+        # Set time zone, for the duration of the ongoing transaction.
+        cursor.execute("SET LOCAL TIME ZONE +13")
+        self.client_log_in()
+        late_node = factory.make_node(status=NODE_STATUS.COMMISSIONING)
+        self.age_node(
+            late_node, settings.COMMISSIONING_TIMEOUT + 1, cursor=cursor)
+        timely_node = factory.make_node(status=NODE_STATUS.COMMISSIONING)
+        self.age_node(
+            timely_node, settings.COMMISSIONING_TIMEOUT - 1, cursor=cursor)
+
+        response = self.client.post(
+            reverse('nodes_handler'), {'op': 'check_commissioning'})
+        self.assertEqual(
+            (httplib.OK, [late_node.system_id]),
+            (
+                response.status_code,
+                [
+                    response_node['system_id']
+                    for response_node in json.loads(response.content)
+                ],
+            ))
+        self.assertEqual(
+            NODE_STATUS.FAILED_TESTS,
+            reload_object(late_node).status)
+        self.assertEqual(
+            NODE_STATUS.COMMISSIONING,
+            reload_object(timely_node).status)
+
 
 class AdminCommissioningScriptsAPITest(MAASServerTestCase):
     """Tests for `CommissioningScriptsHandler`."""