[2.3.0] 400 BAD REQUEST on juju bootstrap

Bug #1740935 reported by Chris Sanders
24
This bug affects 5 people
Affects Status Importance Assigned to Milestone
MAAS
Undecided
Unassigned

Bug Description

MAAS version: 2.3.0 (6434-gd354690-0ubuntu1~16.04.1
Juju version: 2.3.1

Creating a Pod via virsh on the same machine as maas was able to successfully bootstrap in version 2.2.2 of MAAS w/ juju 2.3.1. It appears there is a regression and I can not bootstrap with MAAS 2.3.0.

After adding the maas cloud and credentials a bootstrap now fails with the 400 BAD REQUEST, full --debug from juju below.

juju bootstrap maas --debug
20:09:58 INFO juju.cmd supercommand.go:56 running juju [2.3.1 gc go1.9.2]
20:09:58 DEBUG juju.cmd supercommand.go:57 args: []string{"/snap/juju/3106/bin/juju", "bootstrap", "maas", "--debug"}
20:09:58 DEBUG juju.cmd.juju.commands bootstrap.go:826 authenticating with region "" and credential "maas-creds" ()
20:09:58 DEBUG juju.cmd.juju.commands bootstrap.go:954 provider attrs: map[]
20:09:59 INFO cmd authkeys.go:114 Adding contents of "/home/csanders/.local/share/juju/ssh/juju_id_rsa.pub" to authorized-keys
20:09:59 DEBUG juju.cmd.juju.commands bootstrap.go:1010 preparing controller with config: map[apt-ftp-proxy: http-proxy: default-series:xenial enable-os-refresh-update:true resource-tags: provisioner-harvest-mode:destroyed cloudinit-userdata: apt-mirror: enable-os-upgrade:true logforward-enabled:false name:controller authorized-keys:ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQD6X0l+8zpulC0RrigmQd7BT7DvvzjwjAEO8twj+F0STjSV7WLvgzNWojZNZRF4UgdWQVPGhu3eo9kYNW28/Ol7xHslTsV9OUicePqYbzMobwmfwM9FtWsPNU45y2CBWm56yo5ycAEtE5RZO38O6yrPlT2cULX82/Fj7H8x5Sq2He5HUiqlatIuUu7XpI1/H9Qw+gNzShAjg2XKQsAT/yqVhtxQPnJHKiQ6zvShmNwsclOn9QKevflrZGGwFXMcf/YdQaj/rJfIYp1VDbmpujfqXxiSq6RLzyC4u9rvpqefrYjbhCjzV6XykA3CaFNE6+SKpgQUxkG8GN0fkGkswSgP juju-client-key
 apt-no-proxy: proxy-ssh:false ignore-machine-addresses:false uuid:80e3ad59-3dce-42ee-89db-8444634e4aa1 fan-config: max-status-history-size:5G net-bond-reconfigure-delay:17 type:maas firewall-mode:instance https-proxy: image-stream:released transmit-vendor-metrics:true update-status-hook-interval:5m container-networking-method: ssl-hostname-verification:true image-metadata-url: max-action-results-size:5G max-status-history-age:336h no-proxy:127.0.0.1,localhost,::1 agent-metadata-url: egress-subnets: agent-stream:released apt-http-proxy: logging-config: apt-https-proxy: automatically-retry-hooks:true development:false disable-network-management:false max-action-results-age:336h test-mode:false ftp-proxy:]
20:09:59 DEBUG juju.provider.maas environprovider.go:61 opening model "controller".
20:09:59 INFO cmd bootstrap.go:499 Creating Juju controller "maas" on maas
20:09:59 INFO juju.cmd.juju.commands bootstrap.go:563 combined bootstrap constraints:
20:09:59 DEBUG juju.environs.bootstrap bootstrap.go:199 model "controller" supports service/machine networks: true
20:09:59 DEBUG juju.environs.bootstrap bootstrap.go:201 network management by juju enabled: true
20:09:59 INFO cmd bootstrap.go:233 Loading image metadata
20:09:59 INFO cmd bootstrap.go:296 Looking for packaged Juju agent version 2.3.1 for amd64
20:09:59 INFO juju.environs.bootstrap tools.go:72 looking for bootstrap agent binaries: version=2.3.1
20:09:59 DEBUG juju.environs.tools tools.go:102 finding agent binaries in stream: "released"
20:09:59 DEBUG juju.environs.tools tools.go:104 reading agent binaries with major.minor version 2.3
20:09:59 DEBUG juju.environs.tools tools.go:112 filtering agent binaries by version: 2.3.1
20:09:59 DEBUG juju.environs.tools tools.go:118 filtering agent binaries by architecture: amd64
20:09:59 DEBUG juju.environs.tools urls.go:109 trying datasource "keystone catalog"
20:09:59 DEBUG juju.environs.simplestreams simplestreams.go:683 using default candidate for content id "com.ubuntu.juju:released:tools" are {20161007 mirrors:1.0 content-download streams/v1/cpc-mirrors.sjson []}
20:09:59 INFO juju.environs.bootstrap tools.go:74 found 16 packaged agent binaries
20:09:59 INFO cmd bootstrap.go:371 Starting new instance for initial controller
20:10:00 INFO cmd bootstrap.go:151 Launching controller instance(s) on maas...
20:10:00 DEBUG juju.provider.maas environ.go:929 attempting to acquire node in zone "default"
20:10:03 DEBUG juju.cloudconfig.instancecfg instancecfg.go:828 Setting numa ctl preference to false
20:10:03 DEBUG juju.service discovery.go:63 discovered init system "systemd" from series "xenial"
20:10:03 DEBUG juju.provider.maas environ.go:1019 maas user data; 3452 bytes
20:10:05 ERROR juju.cmd.juju.commands bootstrap.go:519 failed to bootstrap model: cannot start bootstrap instance: unexpected: ServerError: 400 BAD REQUEST (Failed to render preseed: 'NoneType' object has no attribute 'url')
20:10:05 DEBUG juju.cmd.juju.commands bootstrap.go:520 (error details: [{github.com/juju/juju/cmd/juju/commands/bootstrap.go:611: failed to bootstrap model} {github.com/juju/juju/provider/common/bootstrap.go:202: cannot start bootstrap instance} {github.com/juju/juju/provider/maas/environ.go:1043: } {github.com/juju/juju/provider/maas/environ.go:882: } {github.com/juju/gomaasapi/errors.go:41: } {github.com/juju/gomaasapi/controller.go:745: } {github.com/juju/gomaasapi/controller.go:776: } {github.com/juju/gomaasapi/client.go:124: } {ServerError: 400 BAD REQUEST (Failed to render preseed: 'NoneType' object has no attribute 'url')}])
20:10:05 DEBUG juju.cmd.juju.commands bootstrap.go:1117 cleaning up after failed bootstrap
20:10:05 INFO juju.provider.common destroy.go:20 destroying model "controller"
20:10:05 INFO juju.provider.common destroy.go:31 destroying instances
20:10:05 INFO juju.provider.common destroy.go:55 destroying storage
20:10:05 INFO cmd supercommand.go:465 command finished

During this process the maas log shows the following, which you can see in the UI. A machine is allocated and the immediately removed.

Jan 2 20:10:00 maas maas.api: [info] Request from user admin to acquire a machine with constraints: [('zone', ['default']), ('mem', ['3584']), ('agent_name', ['80e3ad59-3dce-42ee-89db-8444634e4aa1'])]
Jan 2 20:10:01 maas maas.drivers.pod.virsh: [info] joint-stork: Successfully set network boot order
Jan 2 20:10:03 maas maas.node: [info] joint-stork: Storage layout was set to flat.
Jan 2 20:10:03 maas maas.node: [info] joint-stork: Status transition from READY to ALLOCATED
Jan 2 20:10:03 maas maas.node: [info] joint-stork: allocated to user admin
Jan 2 20:10:04 maas maas.node: [info] joint-stork: Releasing node
Jan 2 20:10:04 maas maas.node: [info] joint-stork: Status transition from ALLOCATED to RELEASING
Jan 2 20:10:04 maas maas.node: [info] joint-stork: Decomposing machine
Jan 2 20:10:05 maas maas.node: [info] joint-stork: Deleting machine

I tried composing the machine manually and then bootstrapping to that. This gets much further, but eventually hangs during the bootstrap still. This may or may not be related so I'll include it here just in case.

19:36:10 INFO cmd bootstrap.go:333 Connected to 10.0.8.214
19:36:10 INFO juju.cloudconfig userdatacfg_unix.go:408 Fetching agent: curl
-sSfw 'agent binaries from %{url_effective} downloaded: HTTP %{http_code}; time
%{time_total}s; size %{size_download} bytes; speed %{speed_download} bytes/s '
--retry 10 -o $bin/tools.tar.gz
<[https://streams.canonical.com/juju/tools/agent/2.3.1/juju-2.3.1-ubuntu-amd64.tgz]>
19:36:10 INFO cmd bootstrap.go:400 Running machine configuration script...

I have a test MAAS which is still on 2.2.2 and the whole process can be created in a single bootstrap command with out issues using juju 2.3.1 (same one used here that doesn't work on MAAS 2.3.0).

Revision history for this message
Blake Rouse (blake-rouse) wrote :

20:10:05 ERROR juju.cmd.juju.commands bootstrap.go:519 failed to bootstrap model: cannot start bootstrap instance: unexpected: ServerError: 400 BAD REQUEST (Failed to render preseed: 'NoneType' object has no attribute 'url')

Seems that preseed rendering failed for that machine. Can you include the MAAS logs for around that time?

Changed in maas:
status: New → Incomplete
Revision history for this message
Chris Sanders (chris.sanders) wrote :

The only thing in maas.log at this time is already included, are you looking for a different log file than /var/log/maas.log or do I need to enable more verbosity somehow?

Changed in maas:
status: Incomplete → New
Revision history for this message
Chris Sanders (chris.sanders) wrote :
Download full text (8.7 KiB)

I've just re-run this while watching all 3 of the maas log files.

Rackd.log has no output during this operation.

regiond:
2018-01-02 21:16:48 regiond: [info] 10.0.100.1 GET /MAAS/api/2.0/users/?op=whoami HTTP/1.1 --> 200 OK (referrer: -; agent: Go-http-client/1.1)
2018-01-02 21:16:53 regiond: [info] 10.0.100.1 GET /MAAS/api/2.0/users/?op=whoami HTTP/1.1 --> 200 OK (referrer: -; agent: Go-http-client/1.1)
2018-01-02 21:16:53 regiond: [info] 10.0.100.1 GET /MAAS/api/2.0/zones/ HTTP/1.1 --> 200 OK (referrer: -; agent: Go-http-client/1.1)
2018-01-02 21:16:55 regiond: [info] 127.0.0.1 GET /MAAS/rpc/ HTTP/1.0 --> 200 OK (referrer: -; agent: provisioningserver.rpc.clusterservice.ClusterClientService)
2018-01-02 21:16:56 regiond: [info] 10.0.100.1 POST /MAAS/api/2.0/machines/?op=allocate HTTP/1.1 --> 200 OK (referrer: -; agent: Go-http-client/1.1)
2018-01-02 21:16:56 regiond: [info] 10.0.100.1 POST /MAAS/api/2.0/machines/xyxwet/?op=deploy HTTP/1.1 --> 400 BAD_REQUEST (referrer: -; agent: Go-http-client/1.1)
2018-01-02 21:16:57 regiond: [info] 10.0.100.1 POST /MAAS/api/2.0/machines/?op=release HTTP/1.1 --> 200 OK (referrer: -; agent: Go-http-client/1.1)
2018-01-02 21:16:57 regiond: [info] 10.0.100.1 GET /MAAS/api/2.0/files/9b344ab7-ed2a-4295-8cb3-e2f94301d5b9-provider-state/ HTTP/1.1 --> 404 NOT_FOUND (referrer: -; agent: Go-http-client/1.1)
2018-01-02 21:16:57 regiond: [info] 10.0.100.1 GET /MAAS/api/2.0/machines/?agent_name=9b344ab7-ed2a-4295-8cb3-e2f94301d5b9 HTTP/1.1 --> 200 OK (referrer: -; agent: Go-http-client/1.1)
2018-01-02 21:16:57 regiond: [info] 10.0.100.1 GET /MAAS/api/2.0/files/?prefix=9b344ab7-ed2a-4295-8cb3-e2f94301d5b9- HTTP/1.1 --> 200 OK (referrer: -; agent: Go-http-client/1.1)
2018-01-02 21:17:02 maasserver.region_controller: [info] Reloaded DNS configuration; removed node native-ibex

maas.log:
Jan 2 21:16:53 maas2 maas.api: [info] Request from user admin to acquire a machine with constraints: [('mem', ['3584']), ('zone', ['default']), ('agent_name', ['9b344ab7-ed2a-4295-8cb3-e2f94301d5b9'])]
Jan 2 21:16:54 maas2 maas.drivers.pod.virsh: [info] native-ibex: Successfully set network boot order
Jan 2 21:16:56 maas2 maas.node: [info] native-ibex: Storage layout was set to flat.
Jan 2 21:16:56 maas2 maas.node: [info] native-ibex: Status transition from READY to ALLOCATED
Jan 2 21:16:56 maas2 maas.node: [info] native-ibex: allocated to user admin
Jan 2 21:16:56 maas2 maas.node: [info] native-ibex: Releasing node
Jan 2 21:16:56 maas2 maas.node: [info] native-ibex: Status transition from ALLOCATED to RELEASING
Jan 2 21:16:56 maas2 maas.node: [info] native-ibex: Decomposing machine
Jan 2 21:16:57 maas2 maas.node: [info] native-ibex: Deleting machine

juju bootstrap debug:
juju bootstrap maas2-lxd --debug
15:16:48 INFO juju.cmd supercommand.go:56 running juju [2.3.1 gc go1.9.2]
15:16:48 DEBUG juju.cmd supercommand.go:57 args: []string{"/snap/juju/3106/bin/juju", "bootstrap", "maas2-lxd", "--debug"}
15:16:48 DEBUG juju.cmd.juju.commands bootstrap.go:826 authenticating with region "" and credential "maas-creds" ()
15:16:48 DEBUG juju.cmd.juju.commands bootstrap.go:954 provider attrs: map[]
15:16:48 INFO cmd authkeys.go:114 Add...

Read more...

Xav Paice (xavpaice)
tags: added: canonical-bootstack
Revision history for this message
Andres Rodriguez (andreserl) wrote :

Hi All,

Is this still an issue?

Changed in maas:
status: New → Incomplete
Revision history for this message
Chris Sanders (chris.sanders) wrote :

Yes, I've just relaunched the machine I previously tested this with and nothing has changed. I'm not sure why there would be an expectation that anything changed, MAAS still reports version: 2.3.0 (6434-gd354690-0ubuntu1~16.04.1). I'm now running juju 2.3.4 but as previously demonstrated the juju version doesn't appear to be relevant since this is a regression between MAAS 2.2.2 and 2.3.0.

Is there a MAAS update I was suppose to check against, at least xenial packages don't appear to be any different from when this bug was opened, I feel like I'm missing something.

Revision history for this message
Andres Rodriguez (andreserl) wrote :

Ok, so if I understand correctly:

1. Fresh MAAS install
2. Imported images & Configured MAAS DHCP
3. Pointed juju at MAAS
4. It fails.

Can you provide the following info:

1. /etc/maas/{regiond.conf,rackd.conf}
2. /var/log/maas/*.log
3. Exact configuration made to Juju for the MAAS provider.
4. Did you do any extra configuration (e.g. created new users, new api keys, etc).
5. Have you tried allocating machines with the API key directly through the MAAS API/CLI with the same constranints juju does? e.g.:

 maas login <user> http://<your-maas>:5240/MAAS <apikey>
 maas <user> machines allocate <constraints>

Revision history for this message
Chris Sanders (chris.sanders) wrote :

Yes that was the process.

1. It's all default is there anything specific you need, I'll have to re-do this entire process again at some point to get these logs. When/if I get a chance to do that I will.
2. See above logs they're already on the report.
3. Also above there isn't anything here but stock 'add maas cloud'
4. No
5. No

Changed in maas:
status: Incomplete → New
Revision history for this message
Chris Sanders (chris.sanders) wrote :

I've just rerun this operation.

etc/maas and /var/log/maas are attached.

I'm not sure what to log about the juju config.
 * juju add-cloud
 * juju add-credentials
 * juju bootstrap
That's really all there is to it.

All logs and etc are now attached.

I created a POD and tried to bootstrap, it fails reporting that the node never entered deployed state. It's worth pointing out that MAAS does produces a successful Install Output but the node after the operation is listed as "Ready" having spent some time in deploying but never reporting deployed.

Then I tried the MAAS CLI as you suggest. I am able to allocate a machine, after which the bootstrap creates it's own POD. That POD almost instantly fails, this is the CLI and the ERROR from juju.

juju bootstrap maas23-lxd
Creating Juju controller "maas23-lxd" on maas23-lxd
Looking for packaged Juju agent version 2.3.7 for amd64
Launching controller instance(s) on maas23-lxd...
ERROR failed to bootstrap model: cannot start bootstrap instance: unexpected: ServerError: 400 BAD REQUEST (Failed to render preseed: 'NoneType' object has no attribute 'url')

I then deployed the POD through MAAS no juju at all. I'm a bit surprised that the status reports "Ubuntu 16.04 LTS" when I would have expected "Deployed" at least that is what I thought it use to report.

Revision history for this message
Chris Sanders (chris.sanders) wrote :

/var/log as requested

Revision history for this message
Chris Sanders (chris.sanders) wrote :

I thought I had already stated this, but just in case.
This can be reproduced by installing MAAS in a LXD with https://github.com/chris-sanders/maas-lxd

That's the exact process we're using, LXD installation follows the MAAS documenation and sets up virsh. I'll continue to reproduce if you need, but if my response times are slow it's trivial to reproduce with the above script and profile.

Revision history for this message
Paul Goins (vultaire) wrote :

I'm also able to reproduce this.

Revision history for this message
Paul Goins (vultaire) wrote :

Apologies; I should have provided more detail.

Juju version: 2.5.0-cosmic-amd64
LXC version: 3.9
MAAS version: 2.3.5 (6511-gf466fdb-0ubuntu1) (Note: running in a xenial container)

Revision history for this message
Paul Goins (vultaire) wrote :

Problem persists in MAAS 2.4.2 (7034-g2f5deb8b8-0ubuntu1).

Revision history for this message
Paul Goins (vultaire) wrote :

Problem appears to be resolved in MAAS 2.5.0 (7442-gdf68e30a5-0ubuntu1~18.04.1), installed via Launchpad (ppa:maas/next). I'm successfully able to bootstrap and deploy a rabbitmq-server charm to my LXD-based MAAS. (Using Bionic.)

Revision history for this message
Adam Collard (adam-collard) wrote :

This bug has not seen any activity in the last 6 months, so it is being automatically closed.

If you are still experiencing this issue, please feel free to re-open.

MAAS Team

Changed in maas:
status: New → Invalid
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers