Merge lp:~jtv/maas/1.5-bug-1354511 into lp:maas/1.5

[Jeroen T. Vermeulen]

Backport trunk r2668: 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.

Straight backport. For self-approval.

Jeroen

[Jeroen T. Vermeulen (jtv)]

Self-approving.

review: Approve

=== modified file 'src/maasserver/api.py'
--- src/maasserver/api.py	2014-07-24 00:09:02 +0000
+++ src/maasserver/api.py	2014-08-08 20:17:35 +0000
@@ -97,10 +97,6 @@
     b64encode,
     )
 from cStringIO import StringIO
-from datetime import (
-    datetime,
-    timedelta,
-    )
 from functools import partial
 import httplib
 from inspect import getdoc
@@ -704,12 +700,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-02-01 04:04:37 +0000
+++ src/maasserver/tests/test_api_commissioning.py	2014-08-08 20:17:35 +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 import reload_object
 from maasserver.testing.api import APITestCase
@@ -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`."""