maas throws unauthorized sometimes for no reason

[Kapil Thangavelu]

adam reported this on irc, he's running into it roughly half the time on automated testing deploys for openstack. This looks like its happening pretty early during provider storage validation, wnen the oauth token fails.

Started by command line by jenkins
Building on master in workspace /var/lib/jenkins/jobs/pipeline_deploy_new/workspace
Copying file to pipeline_parameters
[workspace] $ /bin/sh -xe /tmp/hudson6223724874141311688.sh
+ . ./pipeline_parameters
+ export OPENSTACK_RELEASE=havana
+ export INSTALLATION_SOURCE=default
+ export PIPELINE_ID=929b8d1d-df48-4569-a7ab-58a660a7aa01
+ export OPENSTACK_COMPONENT=manual_trigger
+ export DEPLOY_TOPOLOGY=default
+ export UBUNTU_RELEASE=saucy
+ export OPENSTACK_BRANCH=manual_trigger
+ /var/lib/jenkins/tools/openstack-ubuntu-testing/bin/archive_job
INFO:root:Archiving Jenkins job.
DEBUG:root:Checking env for parameter: PIPELINE_ID
DEBUG:root:Found: 929b8d1d-df48-4569-a7ab-58a660a7aa01
DEBUG:root:Checking env for parameter: STATUS
DEBUG:root:Checking env for parameter: BUILD_TAG
DEBUG:root:Found: jenkins-pipeline_deploy_new-81
DEBUG:root:Checking env for parameter: PARENT_BUILD_TAG
DEBUG:root:Found: jenkins-pipeline_runner-1004
DEBUG:root:Checking env for parameter: OPENSTACK_BRANCH
DEBUG:root:Found: manual_trigger
DEBUG:root:Checking env for parameter: OPENSTACK_COMPONENT
DEBUG:root:Found: manual_trigger
DEBUG:root:Checking env for parameter: UBUNTU_RELEASE
DEBUG:root:Found: saucy
DEBUG:root:Checking env for parameter: OPENSTACK_RELEASE
DEBUG:root:Found: havana
DEBUG:root:Checking env for extra parameter: GIT_COMMIT
DEBUG:root:Checking env for extra parameter: AUTHOR
DEBUG:root:Checking env for extra parameter: BUILD_URL
DEBUG:root:Checking env for extra parameter: DEPLOYMENT
DEBUG:root:Checking env for extra parameter: DEPLOY_TOPOLOGY
DEBUG:root:Checking env for extra parameter: INSTALLATION_SOURCE
INFO:root:Test job saved: jenkins-pipeline_deploy_new-81
INFO:root:Archived job, pipeline id: 929b8d1d-df48-4569-a7ab-58a660a7aa01 build_tag: jenkins-pipeline_deploy_new-81.
debug
[workspace] $ /bin/bash -ex /tmp/hudson8734886804262490862.sh
+ . ./pipeline_parameters
++ export OPENSTACK_RELEASE=havana
++ OPENSTACK_RELEASE=havana
++ export INSTALLATION_SOURCE=default
++ INSTALLATION_SOURCE=default
++ export PIPELINE_ID=929b8d1d-df48-4569-a7ab-58a660a7aa01
++ PIPELINE_ID=929b8d1d-df48-4569-a7ab-58a660a7aa01
++ export OPENSTACK_COMPONENT=manual_trigger
++ OPENSTACK_COMPONENT=manual_trigger
++ export DEPLOY_TOPOLOGY=default
++ DEPLOY_TOPOLOGY=default
++ export UBUNTU_RELEASE=saucy
++ UBUNTU_RELEASE=saucy
++ export OPENSTACK_BRANCH=manual_trigger
++ OPENSTACK_BRANCH=manual_trigger
+ export DEPLOYMENT_CONFIG=/var/lib/jenkins/tools/openstack-ubuntu-testing/etc/deployer/deployments.cfg
+ DEPLOYMENT_CONFIG=/var/lib/jenkins/tools/openstack-ubuntu-testing/etc/deployer/deployments.cfg
+ export JUJU_ENVIRONMENT=maas
+ JUJU_ENVIRONMENT=maas
+ rm -rf openstack-ubuntu-testing pipeline_parameters saucy
+ bzr branch lp:openstack-ubuntu-testing
Branched 495 revisions.
+ nosetests -svd openstack-ubuntu-testing/tests/openstack_deploy/test_openstack_deploy.py
test_001_deploy (tests.openstack_deploy.test_openstack_deploy.OSDeploymentTest) ... 2013-08-29 23:15:58 [DEBUG] deployer.env: Connected to environment
2013-08-29 23:15:58 [DEBUG] deployer.import: Getting charms...
2013-08-29 23:15:58 [DEBUG] deployer.charm: Branching charm lp:~openstack-ubuntu-testing/charms/precise/nova-compute/trunk @ saucy/nova-compute
2013-08-29 23:16:05 [DEBUG] deployer.charm: Branching charm lp:~openstack-ubuntu-testing/charms/precise/nova-cloud-controller/trunk @ saucy/nova-cloud-controller
2013-08-29 23:16:15 [DEBUG] deployer.charm: Branching charm lp:~openstack-ubuntu-testing/charms/precise/ceph/trunk @ saucy/ceph
2013-08-29 23:16:20 [DEBUG] deployer.charm: Branching charm lp:~openstack-ubuntu-testing/charms/precise/keystone/trunk @ saucy/keystone
2013-08-29 23:16:26 [DEBUG] deployer.charm: Branching charm lp:charms/rabbitmq-server @ saucy/rabbitmq
2013-08-29 23:16:31 [DEBUG] deployer.charm: Branching charm lp:charms/mysql @ saucy/mysql
2013-08-29 23:16:38 [DEBUG] deployer.charm: Branching charm lp:~openstack-ubuntu-testing/charms/precise/openstack-dashboard/trunk @ saucy/openstack-dashboard
2013-08-29 23:16:43 [DEBUG] deployer.charm: Branching charm lp:~openstack-ubuntu-testing/charms/precise/cinder/trunk @ saucy/cinder
2013-08-29 23:16:49 [DEBUG] deployer.charm: Branching charm lp:~openstack-ubuntu-testing/charms/precise/glance/trunk @ saucy/glance
2013-08-29 23:16:56 [DEBUG] deployer.deploy: Resolving configuration
2013-08-29 23:16:56 [INFO] deployer.import: Deploying services...
2013-08-29 23:16:56 [INFO] deployer.import: Deploying service nova-compute using local:saucy/nova-compute
2013-08-29 23:16:58 [DEBUG] deployer.import: Waiting for deploy delay
2013-08-29 23:17:03 [INFO] deployer.import: Deploying service nova-cloud-controller using local:saucy/nova-cloud-controller
2013-08-29 23:17:04 [ERROR] deployer.env: Error deploying service 'nova-cloud-controller'
2013-08-29 23:17:04 [ERROR] deployer.env: Command (juju deploy -e maas --config /tmp/tmph9jbrV --repository=. local:saucy/nova-cloud-controller nova-cloud-controller) Output:

 error: gomaasapi: got error back from server: 401 UNAUTHORIZED

[Adam Gandelman (gandelman-a)]

Currently using maas 1.3+bzr1461+dfsg-0ubuntu2.2 from raring-proposed, but we've been seeing this for a while prior to upgrading.

[Adam Gandelman (gandelman-a)]

  "102":
    agent-state-info: '(error: could not access file ''tools/juju-1.12.0-saucy-amd64.tgz'':
      gomaasapi: got error back from server: 401 UNAUTHORIZED)'
    instance-id: pending
    series: saucy
  "103":

[Julian Edwards (julian-edwards)]

This is most likely to be a problem with clocks on juju clients. They need to be within the oauth tolerance between the maas server and any client.

[Julian Edwards (julian-edwards)]

Targeting juju-core for this because I think the client needs to make sure it's in sync with the server. It can do this by examining the Date header on responses.

[Julian Edwards (julian-edwards)]

Marking the maas task invalid as I'm reasonably sure that this is the problem (we've seen it many times before in early development of maas). Please re-open if it's determined otherwise.

[Raphaël Badin (rvb)]

fwiw, the default threshold is 300 seconds (5 minutes) so the clocks must be badly out of sync if this is the cause of the error.

[Adam Gandelman (gandelman-a)]

I've seen this periodically from the client-side. Randomly 'juju status' will fail with the same error, but subsequent calls will work.

[sodre (psodre)]

This is happening on my deploy as well.

[Kapil Thangavelu (hazmat)]

removing invalid mark against maas... this is happening all the time in the field.

[Julian Edwards (julian-edwards)]

Kapil, can you please provide the version of maas in use. Also can you provide /var/log/maas/*

Thanks.

[Julian Edwards (julian-edwards)]

FWIW this is only ever caused by one of two things:

 * clock sync is wrong (and maas cannot do anything about that)
 * the client attempts to re-use an existing nonce (there is a periodic job to clear those)