juju-quickstart: bad API server response: 'NoneType' object is not iterable

[John George]

The following error is seen on multiple substrates (AWS, Joyent, HP, MaaS).
First seen with gitbranch:1.22:github.com/juju/juju revision 044f1023

juju --show-log quickstart -e test-release-joyent --constraints mem=2G --no-browser /var/lib/jenkins/repository/landscape-scalable.yaml
2015-02-10 13:38:09 INFO juju.cmd supercommand.go:37 running juju [1.22-beta3-precise-amd64 gc]
13:38:10 WARNING platform_support@get_juju_command:134 a customized juju is being used
juju quickstart v1.6.0
contents loaded for bundle landscape-scalable (services: 6)
ssh-agent has been started.
To interact with Juju or quickstart again after quickstart
finishes, please run the following in a terminal to start ssh-agent:
  eval `ssh-agent`

bootstrapping the test-release-joyent environment
retrieving the environment status
retrieving the Juju API address
retrieving the Juju environment credentials
connecting to wss://72.2.113.157:17070
environment type: joyent
bootstrap node series: trusty
charm URL: cs:trusty/juju-gui-18
requesting juju-gui deployment
juju-gui deployment request accepted
exposing service juju-gui
requesting new unit deployment
juju-gui/0 deployment request accepted
unit placed on 72.2.113.157
machine 0 is started
juju-gui/0 is ready on machine 0

Juju GUI URL: https://72.2.113.157
username: admin
password: 3df26d0e2ad0964a81f50256adb67bee

connecting to the Juju GUI server
requesting a deployment of the landscape-scalable bundle with the following services:
  haproxy, rabbitmq-server, postgresql, landscape, landscape-msg, apache2
juju-quickstart: error: bad API server response: invalid request: 'NoneType' object is not iterable
2015-02-10 13:41:37 ERROR juju.cmd supercommand.go:411 subprocess encountered error code 1
<class 'subprocess.CalledProcessError'>: Command '('juju', '--show-log', 'quickstart', '-e', 'test-release-joyent', '--constraints', 'mem=2G', '--no-browser', '/var/lib/jenkins/repository/landscape-scalable.yaml')' returned non-zero exit status 1

[Richard Harding (rharding)]

John, can you confirm that this is against the 1.22 branch. Did this test pass in 1.21? Is there a way to see the results and determine if this is due to a quickstart update or a juju update or is this a new test?

We'll chase down and attempt to duplicate, but having more info can save us some time chasing our tails if you know more details.

Thanks

[John George (jog)]

The error looks like it's being emitted from quickstart/app.py in the quickstart code:
def watch(env, unit_name):
    """Start watching the given unit and the machine the unit belongs to.

    Output a human readable message each time a relevant change is found.

    The following changes are considered relevant for a healthy unit:
        - the machine is pending;
        - the unit is pending;
        - the machine is started;
        - the unit is reachable;
        - the unit is installed;
        - the unit is started.

    Stop watching and return the unit public address when the unit is started.
    Raise a ProgramExit if the API server returns an error response, or if
    either the service unit or the machine is removed or in error.
    """
    address = unit_status = machine_id = machine_status = ''
    collected_machine_changes = []
    watcher = env.watch_changes(watchers.unit_machine_changes)
    while True:
        try:
            unit_changes, machine_changes = watcher.next()
        except jujuclient.EnvError as err:
            raise ProgramExit(
                'bad API server response: {}'.format(err.message))

[Richard Harding (rharding)]

Francesco, can you start to see if we can replicate this in current stable and then we'll see with current beta of 1.22. If this was run with -v would we get better details on the failure point? Should we suggest some debug flags be added to the test runs so that the output is more useful when it fails?

[John George (jog)]

I see the failures on 1.21, 1.22 and master. One instance of a run log can be found here:
http://data.vapour.ws/juju-ci/products/version-2321/aws-quickstart-bundle/build-118/consoleText

Logs for other jobs can be found by drilling down from http://reports.vapour.ws/releases for example Revision Build 2321, look for *quickstart* in the bundle tests table. Hovering your mouse over entries in the "Last build" column will provide links to logs (sometimes there is more than one test attempt).

[Francesco Banconi (frankban)]

The error is due to an backward incompatible change in the Juju mega-watcher for units API.
We assumed this was solved in [1] but it seems that's not the case.
Specifically, unitInfo.Ports is sent by juju-core as a null value in the JSON stream, in the case there are no ports opened [2].
The python-jujuclient fails trying to loop over the juju-gui unit ports (set to None) [3].
The deployer process started by the GUI server propagates the error, and the GUI server correctly reports it to Quickstart.
So the juju-core regression affects the whole stack: juju-quickstart -> GUI server -> juju-deployer -> python-jujuclient.

I'll investigate more with juju-core folks.

[1] https://github.com/juju/juju/commit/8b0a9a9a9443fbacef00fa00d1f71365826f0eb6

[2] an empty slice should be used for compatiblePorts in place of the nil slice currently used. Moreover, unitInfo.Ports does not seem to be populated even after the fix. Perhaps we should watch the openedPorts mongo document in the mega-watcher and force a unitInfo update accordingly.

[3] http://bazaar.launchpad.net/~juju-deployers/python-jujuclient/trunk/view/head:/jujuclient.py#L2048

[Francesco Banconi (frankban)]

To clarify: I marked this as critical because the Ports issue prevents from deploying any bundle, either using quickstart or the Juju GUI.
PS: thanks John for reporting this and for the quickstart logs you provided.

[Dimiter Naydenov (dimitern)]

I'll get someone to work on this tomorrow, if that's OK. For now a few responses to the points in #6 in reverse order:

[2.2] Ports are *no longer* on the unit document (the field is there, but it's not populated anymore). Instead, they are in a separate collection "openedPorts". So opening and closing ports on a unit or a machine won't trigger a change to be reported by the watcher (MachineInfo or UnitInfo are not changed). Let me make it clear this is *by design*, not a bug. For me this means we need to communicate such architectural changes between the GUI and Core teams early and think of the implications.

[2.1] In addition to that above, returning a nil or empty slice to signify no entries is very common and idiomatic in Go and is never causing issues when trying to iterate over it. However, since the wire-format of the API is JSON, null and. [] are neither handled the same way, nor expected to mean the same thing. I suspect there are similar lurking API issues stemming from the assumption that Go's way of handling serialization/deserialization (JSON or otherwise) will work for non-Go clients of the serializated data.

Now, how we can solve these for this issue, but both of them require closer sync up across Juju API and its users to prevent them from happening in the future.

For [2.1], it's easy to ensure both Ports and PortRanges slices of UnitInfo are empty slices when they have a length of 0.
To properly fix [2.2] though, we need to extend the megawatcher to report changes to openedPorts collection, like Francesco suggests.

[Ian Booth (wallyworld)]

Lowered to High in trunk because I reverted the bad commit

[Greg Lutostanski (lutostag)]

After upgrade to 1.21.3 from juju/stable ppa on the oil machines we are getting https://bugs.launchpad.net/juju-core/+bug/1420917 (dupe of this bug for every deploy)
We have the following installed on our machines from juju/stable:

(ci-oil)prodstack-cdo@wekufe:~$ juju ssh ci-oil-slave5/0 'dpkg -l | grep -E "juju-core|juju-deployer"'
Warning: Permanently added '10.33.17.231' (ECDSA) to the list of known hosts.
ii juju-core 1.21.3-0ubuntu1~12.04.1~juju1 Juju is devops distilled - client
ii juju-deployer 0.4.3-0ubuntu1~ubuntu12.04.1~ppa1 Deploy complex stacks of services using Juju
ii python-jujuclient 0.18.4-5 Python API client for juju-core

juju-core was updated in the ppa 22 hours ago so looks like this is the culprit. A mismatch between juju-deployer and juju-core expectations.

We are getting the following error for every deploy in oil -- which is a large impact:
2015-02-25 02:36:03,829 [DEBUG] deployer.import: Adding units...
2015-02-25 02:36:05,165 [ERROR] oil_ci.deploy.oil_deployer: Deployment failed: 'NoneType' object is not iterable
Traceback (most recent call last):
  File "/usr/lib/python2.7/dist-packages/oil_ci/deploy/oil_deployer.py", line 140, in deploy
    debug=True, verbose=True)
  File "/usr/lib/python2.7/dist-packages/oil_ci/juju/juju_deployer.py", line 85, in run_deployer
    importer.Importer(env, deploy, options=opts).run()
  File "/usr/lib/python2.7/dist-packages/deployer/action/importer.py", line 202, in run
    self.add_units()
  File "/usr/lib/python2.7/dist-packages/deployer/action/importer.py", line 22, in add_units
    env_status = self.env.status()
  File "/usr/lib/python2.7/dist-packages/deployer/env/go.py", line 203, in status
    return self.client.get_stat()
  File "/usr/lib/python2.7/dist-packages/jujuclient.py", line 599, in get_stat
    return StatusTranslator().run(watch)
  File "/usr/lib/python2.7/dist-packages/jujuclient.py", line 999, in run
    self._unit(d)
  File "/usr/lib/python2.7/dist-packages/jujuclient.py", line 1031, in _unit
    for p in ports:
TypeError: 'NoneType' object is not iterable

Help would be appreciated.

[Darryl Weaver (dweaver)]

I can confirm that we are seeing the same issues as in OIL on the Orange Boxes, this will effect demos of openstack deployments.

[Michael Partridge (m-part)]

I saw this as of yesterday, on version 1.21.3 from the stable repo. This is blocking us from setting up demo environments. Things such as this should not make it to stable....

[Samantha Jian-Pielak (samantha-jian)]

Seeing the same error when trying to deploying openstack on seamicro hardware:

ubuntu@Server16:~$ juju-deployer -c latest_Openstack.yaml -e maas
2015-02-25 16:28:19 Using deployment envExport
2015-02-25 16:28:19 Starting deployment of envExport
2015-02-25 16:28:19 Deploying services...
Traceback (most recent call last):
  File "/usr/bin/juju-deployer", line 9, in <module>
    load_entry_point('juju-deployer==0.4.3', 'console_scripts',
'juju-deployer')()
  File "/usr/lib/python2.7/dist-packages/deployer/cli.py", line 130, in
main
    run()
  File "/usr/lib/python2.7/dist-packages/deployer/cli.py", line 228, in run
    importer.Importer(env, deployment, options).run()
  File "/usr/lib/python2.7/dist-packages/deployer/action/importer.py",
line 196, in run
    self.deploy_services()
  File "/usr/lib/python2.7/dist-packages/deployer/action/importer.py",
line 72, in deploy_services
    env_status = self.env.status()
  File "/usr/lib/python2.7/dist-packages/deployer/env/go.py", line 203, in
status
    return self.client.get_stat()
  File "/usr/lib/python2.7/dist-packages/jujuclient.py", line 599, in
get_stat
    return StatusTranslator().run(watch)
  File "/usr/lib/python2.7/dist-packages/jujuclient.py", line 999, in run
    self._unit(d)
  File "/usr/lib/python2.7/dist-packages/jujuclient.py", line 1031, in
_unit
    for p in ports:
TypeError: 'NoneType' object is not iterable

ubuntu@Server16:~$ dpkg -s juju-core juju-deployer | grep Version
Version: 1.21.3-0ubuntu1~14.04.1~juju1
Version: 0.4.3-0ubuntu1~ubuntu14.04.1~ppa1

[Jason Hobbs (jason-hobbs)]

FYI this is now being tracked under bug 1425435

[Kapil Thangavelu (hazmat)]

new version of python jujuclient released on pypi with fix. 0.50.1 fwiw.h

On Thu, Feb 26, 2015 at 1:51 PM, Jason Hobbs <email address hidden>
wrote:

> FYI this is now being tracked under bug 1425435
>
> --
> You received this bug notification because you are subscribed to juju-
> core.
> https://bugs.launchpad.net/bugs/1420403
>
> Title:
> juju-quickstart: bad API server response: 'NoneType' object is not
> iterable
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/juju-core/+bug/1420403/+subscriptions
>

[Francesco Banconi (frankban)]

I am working on getting 0.50.1 into the Juju stable PPA.