Merge lp:~rvb/maas/nonce-bug-1190986 into lp:~maas-committers/maas/trunk

[Raphaël Badin]

Add utility to remove old nonces.

Note that this is *just* the utility itself (function cleanup_old_nonces). Now this needs to be "croned" using either a cronjob or — preferably — a celery beat tasks + an API call.

[Gavin Panella (allenap)]

Looks good, and easy to understand!

[1]

+    create_checkpoint_nonce()
+    # Delete old nonces.
+    checkpoint = find_checkpoint_nonce()
+    if checkpoint is None:
+        return 0
+    return delete_old_nonces(checkpoint)

Seems odd to create the new nonce before deleting; there is a very
slow race condition there.

[2]

+def delete_old_nonces(checkpoint):
+    """Delete nonces older than the given nonce."""
+    nonce_to_delete = Nonce.objects.filter(id__lte=checkpoint.id)
+    count = nonce_to_delete.count()
+    nonce_to_delete.delete()
+    return count

Do we need the count?

[3]

+from __future__ import (
+    absolute_import,
+    print_function,
+    unicode_literals,
+    )
+
+__metaclass__ = type
+__all__ = []

Please merge trunk and update this to the newest template; there's a
'str = None' missing from there.

[4]

+        self.patch(module_time, "time").return_value = (
+            now - timestamp_threshold)

I'd hesitate from patching time.time() - it may be used by nose before
the patching machinery is invoked to repair its work. How about:

        from maasserver import nonces_cleanup

        timemod = self.patch(nonces_cleanup, "time")
        timemod.time.return_value = now - timestamp_threshold
        ...
        timemod.time.return_value = now

?

[5]

+        self.assertLessEqual(before, float(checkpoint.key.strip(key_suffix)))
+        self.assertGreaterEqual(
+            after, float(checkpoint.key.strip(key_suffix)))

strip() doesn't work like that; key_suffix will be used as
*characters* to strip. In this instance it works, but perhaps a
different mechanism ought to be used, e.g.:

        checkpoint_time = float(re.search(r'[\d.]+', checkpoint.key).group(0))

Also, with testtools you can do the above check in one go:

        self.assertThat(checkpoint_time, MatchesAll(
            MatchesAny(Equals(before), GreaterThan(before)),
            MatchesAny(Equals(after), LessThan(after))))

Though it's not really any clearer.

review: Approve

[Raphaël Badin (rvb)]

Thanks for the review!
>
>
> [1]
>
> +    create_checkpoint_nonce()
> +    # Delete old nonces.
> +    checkpoint = find_checkpoint_nonce()
> +    if checkpoint is None:
> +        return 0
> +    return delete_old_nonces(checkpoint)
>
> Seems odd to create the new nonce before deleting; there is a very
> slow race condition there.

Where do you see the race condition exactly?

> [2]
>
> +def delete_old_nonces(checkpoint):
> +    """Delete nonces older than the given nonce."""
> +    nonce_to_delete = Nonce.objects.filter(id__lte=checkpoint.id)
> +    count = nonce_to_delete.count()
> +    nonce_to_delete.delete()
> +    return count
>
> Do we need the count?

Well, we could do without, but it's pretty cheap, and I think it's pretty useful to give the caller some feedback about the actual clean-up (i.e. did it really happen or not); especially considering the two-phase strategy.

> [3]
>
> +from __future__ import (
> +    absolute_import,
> +    print_function,
> +    unicode_literals,
> +    )
> +
> +__metaclass__ = type
> +__all__ = []
>
> Please merge trunk and update this to the newest template; there's a
> 'str = None' missing from there.

All right, done.

> [4]
>
> +        self.patch(module_time, "time").return_value = (
> +            now - timestamp_threshold)
>
> I'd hesitate from patching time.time() - it may be used by nose before
> the patching machinery is invoked to repair its work. How about:
>
>        from maasserver import nonces_cleanup
>
>        timemod = self.patch(nonces_cleanup, "time")
>        timemod.time.return_value = now - timestamp_threshold
>        ...
>        timemod.time.return_value = now

Indeed, it's a tad cleaner, done.

> [5]
>
> +        self.assertLessEqual(before, float(checkpoint.key.strip(key_suffix)))
> +        self.assertGreaterEqual(
> +            after, float(checkpoint.key.strip(key_suffix)))
>
> strip() doesn't work like that; key_suffix will be used as
> *characters* to strip. In this instance it works, but perhaps a
> different mechanism ought to be used, e.g.:
>
>        checkpoint_time = float(re.search(r'[\d.]+', checkpoint.key).group(0))
>
> Also, with testtools you can do the above check in one go:
>
>        self.assertThat(checkpoint_time, MatchesAll(
>            MatchesAny(Equals(before), GreaterThan(before)),
>            MatchesAny(Equals(after), LessThan(after))))
>
> Though it's not really any clearer.

I've refactored that code a bit, instead of the heavy artillery, I've used "checkpoint_time = checkpoint.key[:-len(key_suffix)]".

[Gavin Panella (allenap)]

> > [1]
> >
> > +    create_checkpoint_nonce()
> > +    # Delete old nonces.
> > +    checkpoint = find_checkpoint_nonce()
> > +    if checkpoint is None:
> > +        return 0
> > +    return delete_old_nonces(checkpoint)
> >
> > Seems odd to create the new nonce before deleting; there is a very
> > slow race condition there.
>
> Where do you see the race condition exactly?

In cleanup_old_nonces():

+    create_checkpoint_nonce()
+    # Delete old nonces.
+    checkpoint = find_checkpoint_nonce()

If there's a delay between create_checkpoint_nonce() and
find_checkpoint_nonce() of more than timestamp_threshold - which I
grant is *extremely* unlikely - then it'll delete the nonce just
created.

However, it doesn't matter anyway: by then it'll be time to delete the
new nonce! So, it's fine to leave it as it is.

>
> > [2]
> >
> > +def delete_old_nonces(checkpoint):
> > +    """Delete nonces older than the given nonce."""
> > +    nonce_to_delete = Nonce.objects.filter(id__lte=checkpoint.id)
> > +    count = nonce_to_delete.count()
> > +    nonce_to_delete.delete()
> > +    return count
> >
> > Do we need the count?
>
> Well, we could do without, but it's pretty cheap, and I think it's pretty
> useful to give the caller some feedback about the actual clean-up (i.e. did it
> really happen or not); especially considering the two-phase strategy.

The count is not too bad as long as indexes are being used -
http://wiki.postgresql.org/wiki/Slow_Counting - but note the caveat:

  PostgreSQL will still need to read the resulting rows to verify that
  they exist; other database systems may only need to reference the
  index in this situation.

I guess it's going to be visiting those rows again very soon to delete
them, so they'll be hot and the delete will be quicker, but that might
be a false assumption. When regularly deleting nonces it probably
won't be a significant overhead, but the first run of this code might
be punishing.

PostgreSQL does return a count of deleted rows, eliminating the need
for a separate count, which might be a way to mitigate this. I wonder
if Django surfaces that in some way?

See http://www.postgresql.org/docs/9.1/interactive/sql-delete.html.

Another thought: key__endswith probably creates a LIKE '%SUFFIX'
clause, which can be very inefficient. I suggest talking to Jeroen or
Stuart Bishop about this. Can this code be changed to use a prefix
match instead? Can you check that an index on Nonce.key exists, and
that it supports prefix (or suffix) matches?

[Jeroen T. Vermeulen (jtv)]

> PostgreSQL does return a count of deleted rows, eliminating the need
> for a separate count, which might be a way to mitigate this. I wonder
> if Django surfaces that in some way?

Even if it doesn't, psycopg2 does. It's cursor.rowcount, right after the deletion.

.

> Another thought: key__endswith probably creates a LIKE '%SUFFIX'
> clause, which can be very inefficient. I suggest talking to Jeroen or
> Stuart Bishop about this. Can this code be changed to use a prefix
> match instead? Can you check that an index on Nonce.key exists, and
> that it supports prefix (or suffix) matches?

You can create a function index on the result of "LIKE '%SUFFIX'". But I do wonder: after the initial cleanup, how many nonces can there ever be? Maybe it's worth dealing with the initial cleanup as a separate situation, where we can cut corners and/or just accept a delay.

[Raphaël Badin (rvb)]

> > > [1]
> > >
> > > +    create_checkpoint_nonce()
> > > +    # Delete old nonces.
> > > +    checkpoint = find_checkpoint_nonce()
> > > +    if checkpoint is None:
> > > +        return 0
> > > +    return delete_old_nonces(checkpoint)
> > >
> > > Seems odd to create the new nonce before deleting; there is a very
> > > slow race condition there.
> >
> > Where do you see the race condition exactly?
>
> In cleanup_old_nonces():
>
> +    create_checkpoint_nonce()
> +    # Delete old nonces.
> +    checkpoint = find_checkpoint_nonce()
>
> If there's a delay between create_checkpoint_nonce() and
> find_checkpoint_nonce() of more than timestamp_threshold - which I
> grant is *extremely* unlikely - then it'll delete the nonce just
> created.
>
> However, it doesn't matter anyway: by then it'll be time to delete the
> new nonce! So, it's fine to leave it as it is.

That's what I had in mind, we can call that a race, because technically, this is a race but it has no bad consequence whatsoever. Plus it's highly unlikely.

> PostgreSQL does return a count of deleted rows, eliminating the need
> for a separate count, which might be a way to mitigate this. I wonder
> if Django surfaces that in some way?

I don't think Django exposes that. There is a still-open tick for it in Django bugtracker: https://code.djangoproject.com/ticket/16891.

I tried to see if I could find the 'rowcount' in Django's guts after the query has been performed but I can't so far…

> Another thought: key__endswith probably creates a LIKE '%SUFFIX'
> clause, which can be very inefficient. I suggest talking to Jeroen or
> Stuart Bishop about this. Can this code be changed to use a prefix
> match instead? Can you check that an index on Nonce.key exists, and
> that it supports prefix (or suffix) matches?

I changed that to using prefixes.

But I'm not really concerned about the efficiency here considering that only the *second* run can be a bit inefficient.

=== added file 'src/maasserver/nonces_cleanup.py'
--- src/maasserver/nonces_cleanup.py	1970-01-01 00:00:00 +0000
+++ src/maasserver/nonces_cleanup.py	2013-10-10 07:40:34 +0000
@@ -0,0 +1,94 @@
+# Copyright 2013 Canonical Ltd.  This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""Nonces cleanup utilities."""
+
+from __future__ import (
+    absolute_import,
+    print_function,
+    unicode_literals,
+    )
+
+str = None
+
+__metaclass__ = type
+__all__ = [
+    'cleanup_old_nonces',
+    ]
+
+
+import time
+
+from oauth.oauth import OAuthServer
+from piston.models import Nonce
+
+
+timestamp_threshold = OAuthServer.timestamp_threshold
+
+
+def cleanup_old_nonces():
+    """Clean up old nonces.
+
+    This method does two things:
+    - it creates a "checkpoint" nonce which stores its creation
+      time.
+    - it removes the expired nonces by using existing "checkpoint"
+      nonces to figure out which nonces can be safely deleted.
+
+    Given the two-step nature of this method, it needs to be called
+    at least twice, the two calls being separated by 5 minutes, to
+    actually be able to delete old nonces.
+    The typical usage is to call this at regular intervals in a
+    cron-like fashion.
+    """
+    create_checkpoint_nonce()
+    # Delete old nonces.
+    checkpoint = find_checkpoint_nonce()
+    if checkpoint is None:
+        return 0
+    return delete_old_nonces(checkpoint)
+
+
+def create_checkpoint_nonce():
+    """Create a "checkpoint" nonce.
+
+    A "checkpoint" nonce is a Nonce with empty strings in
+    'token_key' and 'consumer_key' and its creation time in the
+    'key' field.
+    """
+    now = time.time()
+    Nonce.objects.get_or_create(
+        token_key='', consumer_key='', key=get_time_string(now))
+
+# Key prefix used when creating checkpoint nonces to avoid clashing with
+# real-world nonce created by piston.
+key_prefix = "CHECKPOINT#"
+
+
+def get_time_string(time_value):
+    """Convert a time value, as returned by time.time() into a string."""
+    return "%s%f" % (key_prefix, time_value)
+
+
+def delete_old_nonces(checkpoint):
+    """Delete nonces older than the given nonce."""
+    nonce_to_delete = Nonce.objects.filter(id__lte=checkpoint.id)
+    count = nonce_to_delete.count()
+    nonce_to_delete.delete()
+    return count
+
+
+def find_checkpoint_nonce():
+    """Return the most recent "checkpoint" nonce.
+
+    The returned nonce will be older than 'timestamp_threshold'.
+    Returns None if such a nonce does not exist.
+    """
+    time_limit = get_time_string(time.time() - timestamp_threshold)
+    nonces = Nonce.objects.filter(
+        token_key='', consumer_key='',
+        key__lte=time_limit, key__startswith=key_prefix)
+    try:
+        return nonces.latest('id')
+    except Nonce.DoesNotExist:
+        return None

=== added file 'src/maasserver/tests/test_nonces_cleanup.py'
--- src/maasserver/tests/test_nonces_cleanup.py	1970-01-01 00:00:00 +0000
+++ src/maasserver/tests/test_nonces_cleanup.py	2013-10-10 07:40:34 +0000
@@ -0,0 +1,119 @@
+# Copyright 2013 Canonical Ltd.  This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""Tests for the nonces cleanup module."""
+
+from __future__ import (
+    absolute_import,
+    print_function,
+    unicode_literals,
+    )
+
+str = None
+
+__metaclass__ = type
+__all__ = []
+
+
+import time
+
+from maasserver.nonces_cleanup import (
+    cleanup_old_nonces,
+    create_checkpoint_nonce,
+    delete_old_nonces,
+    find_checkpoint_nonce,
+    get_time_string,
+    key_prefix,
+    time as module_time,
+    timestamp_threshold,
+    )
+from maasserver.testing.testcase import MAASServerTestCase
+from maastesting.matchers import ContainsAll
+from piston.models import Nonce
+from testtools.matchers import StartsWith
+
+
+class TestCleanupOldNonces(MAASServerTestCase):
+
+    def test_cleanup_old_nonces_returns_0_if_no_checkpoint(self):
+        self.assertEquals(0, cleanup_old_nonces())
+
+    def test_cleanup_old_nonces_cleans_up_old_nonces(self):
+        now = time.time()
+        # Patch the module's time module so that the nonces appear as if
+        # they were created now - timestamp_threshold seconds ago.
+        timemod = self.patch(module_time, "time")
+        timemod.return_value = now - timestamp_threshold
+        old_nonces = [Nonce.objects.create() for i in range(3)]
+        self.assertEquals(0, cleanup_old_nonces())
+        # Patch the module's time module back.
+        timemod.return_value = now
+        new_nonces = [Nonce.objects.create() for i in range(3)]
+
+        cleanup_count = cleanup_old_nonces()
+
+        # The old nonces plus the checkpoint nonce are deleted.
+        self.assertEquals(len(old_nonces) + 1, cleanup_count)
+        self.assertThat(Nonce.objects.all(), ContainsAll(new_nonces))
+        self.assertEqual(len(new_nonces) + 1, Nonce.objects.all().count())
+
+
+class TestUtilities(MAASServerTestCase):
+
+    def test_create_checkpoint_nonce_creates_checkpoint_nonce(self):
+        before = time.time()
+        create_checkpoint_nonce()
+        checkpoint = Nonce.objects.get(token_key='', consumer_key='')
+        after = time.time()
+        checkpoint_time = checkpoint.key[len(key_prefix):]
+        self.assertLessEqual(before, float(checkpoint_time))
+        self.assertGreaterEqual(after, float(checkpoint_time))
+
+    def test_create_checkpoint_nonce_gets_checkpoint_if_exists(self):
+        now = time.time()
+        self.patch(module_time, "time").return_value = now
+        create_checkpoint_nonce()
+        nonce1 = Nonce.objects.filter(
+            token_key='', consumer_key='').latest('id')
+        create_checkpoint_nonce()
+        nonce2 = Nonce.objects.filter(
+            token_key='', consumer_key='').latest('id')
+        self.assertEqual(nonce1.id, nonce2.id)
+
+    def test_delete_old_nonces_delete_nonces(self):
+        # Create old nonces.
+        [Nonce.objects.create() for i in range(3)]
+        checkpoint = Nonce.objects.create()
+        new_nonces = [Nonce.objects.create() for i in range(3)]
+        delete_old_nonces(checkpoint)
+        self.assertItemsEqual(new_nonces, Nonce.objects.all())
+
+    def test_find_checkpoint_nonce_returns_None_if_no_checkpoint(self):
+        self.assertIsNone(find_checkpoint_nonce())
+
+    def test_find_checkpoint_nonce_returns_most_recent_checkpoint(self):
+        now = time.time()
+        self.patch(module_time, "time").return_value = now
+        # Create a "checkpoint" nonce created timestamp_threshold + 5
+        # seconds ago.
+        Nonce.objects.create(
+            token_key='', consumer_key='',
+            key=get_time_string(now - 5 - timestamp_threshold))
+        # Create a "checkpoint" nonce created timestamp_threshold
+        # seconds ago.
+        checkpoint = Nonce.objects.create(
+            token_key='', consumer_key='',
+            key=get_time_string(now - timestamp_threshold))
+        # Create a "checkpoint" nonce created 1 second ago.
+        Nonce.objects.create(
+            token_key='', consumer_key='', key=get_time_string(now - 1))
+
+        self.assertEqual(checkpoint, find_checkpoint_nonce())
+
+    def test_get_time_string_returns_comparable_string(self):
+        now = time.time()
+        self.assertGreater(get_time_string(now + 1), get_time_string(now))
+
+    def test_get_time_string_ends_with_suffix(self):
+        now = time.time()
+        self.assertThat(get_time_string(now), StartsWith(key_prefix))