[SRU] ERROR Nonce already used

[Konrad Meier]

SRU for secondary fix (branch lp:~julian-edwards/maas/nonce-fix-bug-1190986)
[Impact]
 * Minimize possibility of hitting a nonce collision by using a longer nonce (uuid4) in both python-maas-client and commissioning scripts.

[Testcase]
 * Do some api calls and make sure that the piston_nonce postgres table is using the larger uuid nonce for the calls

[Regression Potential]
 * Minimal; replace random string of length 8 with uuidgen.

The error below happens sometimes. (~5% of all requests fail)

System: Ubuntu 12.04.2
MAAS-version: 1.2+bzr1373+dfsg-0ubuntu1~12.04.1
Juju-version: 0.7+bzr628+bzr631~precise1

$ juju status
2013-06-14 13:59:36,213 INFO Connecting to environment...
2013-06-14 13:59:36,295 ERROR Cannot connect to environment: Nonce already used: 55941407
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/juju/providers/common/connect.py", line 43, in run
    client = yield self._internal_connect(share)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1037, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 382, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/lib/python2.7/dist-packages/juju/providers/common/connect.py", line 59, in _internal_connect
    candidates = yield self._provider.get_zookeeper_machines()
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1037, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 382, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/lib/python2.7/dist-packages/juju/providers/common/findzookeepers.py", line 32, in find_zookeepers
    machine = yield provider.get_machine(instance_id)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 1037, in _inlineCallbacks
    result = result.throwExceptionIntoGenerator(g)
  File "/usr/lib/python2.7/dist-packages/twisted/python/failure.py", line 382, in throwExceptionIntoGenerator
    return g.throw(self.type, self.value, self.tb)
  File "/usr/lib/python2.7/dist-packages/juju/providers/maas/provider.py", line 125, in get_machines
    instances = yield self.maas_client.get_nodes(instance_ids)
  File "/usr/lib/python2.7/dist-packages/twisted/internet/defer.py", line 545, in _runCallbacks
    current.result = callback(current.result, *args, **kw)
  File "/usr/lib/python2.7/dist-packages/juju/providers/maas/maas.py", line 95, in _process_error
    raise ProviderError(error.response)
ProviderError: Nonce already used: 55941407
2013-06-14 13:59:36,297 ERROR Nonce already used: 55941407

I think the problem is caused by the MAAS-database table "piston_nonce"
In my system this table contains a hughe amount of tokens that are never deleted:
maasdb=# SELECT count(id) FROM piston_nonce;
  count
---------
 3619099
(1 row)

[Julian Edwards (julian-edwards)]

Can you attach all the maas logs under /var/log/maas please.

Thanks.

[Konrad Meier (konrad-meier)]

Requested logfiles in attachment.

[Raphaël Badin (rvb)]

Looks like piston is not cleaning up the nonce table (see https://bitbucket.org/jespern/django-piston/issue/187/too-many-nonces).

[Konrad Meier (konrad-meier)]

@Raphaël: Yes I think that is the problem.
In my system the "piston_nonce" table is growing fast.
Right now I have 4016258 nonces for a single token_key.

I am not sure whose responsibility it is to clean that table.

[Jeroen T. Vermeulen (jtv)]

For reference, the django-social-auth project added a "clean_nonces" command to take of their own manifestation of this problem in December 2012: https://github.com/omab/django-social-auth/issues/410 — but unfortunately that particular solution seems to be based on a field Nonce.timestamp. I'm not seeing that field even in piston upstream.

[Konrad Meier (konrad-meier)]

As a workaround I added a cronjob to clean the table every 5 min:
*/5 * * * * su -c 'psql -d maasdb -c "DELETE FROM piston_nonce WHERE id < (SELECT max(id)-1000 FROM piston_nonce);"' postgres >> /var/log/maas/nonce_cron.log
Since there is no timestamp in the table I keep the last 1k entries.

[Raphaël Badin (rvb)]

There is no 'timestamp' column in the Nonce table so fixing this is not as easy as cleaning up the old nonces with a simple SQL query.

But I think I've got a solution that is both simple and doable without performing brain surgery on piston:
Let timestamp_threshold be the duration for which a nonce is valid (the value is in piston's codebase)
Every 5 minutes, run a script that does this:
  1. create a (fake) Nonce with token_key='', consumer_key='' and key=time.time()
  2.a. find the most recent Nonce (sort by id and take the nonce with the biggest id) with token_key='', consumer_key='' and key < time.time() - timestamp_threshold
  2.b. delete all the nonces which are older than the nonce fetched in 2.a., if any.

The idea is basically to create "checkpoint" nonces and then use them to clean up old nonces. The "checkpoint" nonces won't point to a customer so won't be considered by the oauth machinery. The Nonce.key field is a charfield with 255 which should be plenty to store a timestamp (storing a timestamp in a charfield is a bit hacky, I give you that, but it should work).

[Raphaël Badin (rvb)]

If you're using a earlier version of MAAS that doesn't contain the fix yet, it's easy to reproduce the fix:
Save the script from http://paste.ubuntu.com/6762313/ into nonces_cleanup.py and then run it using cron, every 5 minutes:
cat nonces_cleanup.py | sudo maas shell

Note that the cleanup will not happen the first time you run the script, only the second time (and all the other times after that); Read the script if you want to know why ;).

[David Britton (dpb)]

Got another instance maybe? maas package version: 1.6.1+bzr2548-0ubuntu1~ppa1

ERROR 2014-08-19 20:01:18,871 maasserver ################################ Exception: 'Nonce already used: 48723931' ################################
ERROR 2014-08-19 20:01:18,871 maasserver Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/django/core/handlers/base.py", line 112, in get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
  File "/usr/lib/python2.7/dist-packages/django/views/decorators/vary.py", line 19, in inner_func
    response = func(*args, **kwargs)
  File "/usr/lib/python2.7/dist-packages/piston/resource.py", line 128, in __call__
    actor, anonymous = self.authenticate(request, rm)
  File "/usr/lib/python2.7/dist-packages/maasserver/api_support.py", line 67, in authenticate
    RestrictedResource, self).authenticate(request, rm)
  File "/usr/lib/python2.7/dist-packages/piston/resource.py", line 103, in authenticate
    if not authenticator.is_authenticated(request):
  File "/usr/lib/python2.7/dist-packages/maasserver/api_auth.py", line 60, in is_authenticated
    raise OAuthUnauthorized(error)
OAuthUnauthorized: 'Nonce already used: 48723931'

[David Britton (dpb)]

comment #9 was while running juju bootstrap -v

[Greg Lutostanski (lutostag)]

Since it was hit while running juju I'm inclined to believe that it is because http://bazaar.launchpad.net/~juju/gomaasapi/trunk/view/head:/oauth.go is still using the old nonce generation method ([0-9]{8} rather than uuid) which is much more collision prone.

[Andres Rodriguez (andreserl)]

https://code.launchpad.net/~lutostag/gomaasapi/fix_nonce_generation/+merge/231638

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Chris J Arges (arges)]

Hello Konrad, or anyone else affected,

Accepted maas into trusty-proposed. The package will build now and be available at http://launchpad.net/ubuntu/+source/maas/1.5.4+bzr2294-0ubuntu1 in a few hours, and then in the -proposed repository.

Please help us by testing this new package. See https://wiki.ubuntu.com/Testing/EnableProposed for documentation how to enable and use -proposed. Your feedback will aid us getting this update out to other Ubuntu users.

If this package fixes the bug for you, please add a comment to this bug, mentioning the version of the package you tested, and change the tag from verification-needed to verification-done. If it does not fix the bug for you, please add a comment stating that, and change the tag to verification-failed. In either case, details of your testing will help us make a better decision.

Further information regarding the verification process can be found at https://wiki.ubuntu.com/QATeam/PerformingSRUVerification . Thank you in advance!

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Andres Rodriguez (andreserl)]

Been tested and issue fixed.

[Launchpad Janitor (janitor)]

This bug was fixed in the package maas - 1.5.4+bzr2294-0ubuntu1.1

---------------
maas (1.5.4+bzr2294-0ubuntu1.1) trusty-proposed; urgency=medium

  * Add hardware enablement for armhf/keystone (LP: #1350103)
 -- Greg Lutostanski <email address hidden> Thu, 18 Sep 2014 16:43:56 -0500

[Rolf Leggewie (r0lf)]

saucy has seen the end of its life and is no longer receiving any updates. Marking the saucy task for this ticket as "Won't Fix".