MAAS

commission fails with HTTP Error 400: BAD REQUEST

Bug #1541030 reported by stsp on 2016-02-02

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	MAAS	Invalid	High	Unassigned	MAAS 1.9.5

Bug Description

I am using maas-1.9.0+bzr4533-0ubuntu1~trusty1

When trying to commission a node, I see the following at the
end of the commissioning stage:

Success
Success
Success
Success
Success
Success
Success
Success
Success
Success
Success
request to http://192.168.10.202/MAAS/metadata//2012-03-01/ failed. sleeping 1.:
HTTP Error 400: BAD REQUEST
request to http://192.168.10.202/MAAS/metadata//2012-03-01/ failed. sleeping 1.:
HTTP Error 400: BAD REQUEST
request to http://192.168.10.202/MAAS/metadata//2012-03-01/ failed. sleeping 2.:
HTTP Error 400: BAD REQUEST
[ message repeats a few times ]
http error [400]
Success
Success
Success
Success
Success
Success
Success

I've dumped the HTTP requests and it appears that the failure
is to upload the 00-maas-07-block-devices.out file. All other files
are uploaded fine, I can see them in the commissioning output in UI.
Only this one fails, and as the result:

Storage
0.0GB over 0 disks

which is, of course, not what was expected.
The only mentioning in the logs I could find, was this in regiond.log:

2016-01-28 16:57:21 [-] 127.0.0.1 - - [28/Jan/2016:13:57:21 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 200 2 "-" "Python-urllib/2.7"
2016-01-28 16:57:26 [-] 127.0.0.1 - - [28/Jan/2016:13:57:25 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 200 2 "-" "Python-urllib/2.7"
2016-01-28 16:57:27 [-] 127.0.0.1 - - [28/Jan/2016:13:57:26 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 200 2 "-" "Python-urllib/2.7"
2016-01-28 16:57:27 [-] 127.0.0.1 - - [28/Jan/2016:13:57:27 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 200 2 "-" "Python-urllib/2.7"
2016-01-28 16:57:28 [-] 127.0.0.1 - - [28/Jan/2016:13:57:27 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 200 2 "-" "Python-urllib/2.7"
2016-01-28 16:57:33 [-] 127.0.0.1 - - [28/Jan/2016:13:57:33 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 200 2 "-" "Python-urllib/2.7"
2016-01-28 16:57:34 [-] 127.0.0.1 - - [28/Jan/2016:13:57:33 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 200 2 "-" "Python-urllib/2.7"
2016-01-28 16:57:34 [-] 127.0.0.1 - - [28/Jan/2016:13:57:34 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 200 2 "-" "Python-urllib/2.7"
2016-01-28 16:57:35 [-] 127.0.0.1 - - [28/Jan/2016:13:57:35 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 200 2 "-" "Python-urllib/2.7"
2016-01-28 16:57:36 [-] 127.0.0.1 - - [28/Jan/2016:13:57:36 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 200 2 "-" "Python-urllib/2.7"
2016-01-28 16:57:37 [-] 127.0.0.1 - - [28/Jan/2016:13:57:36 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 200 2 "-" "Python-urllib/2.7"
2016-01-28 16:57:38 [-] 127.0.0.1 - - [28/Jan/2016:13:57:37 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 400 68 "-" "Python-urllib/2.7"
2016-01-28 16:57:39 [-] 127.0.0.1 - - [28/Jan/2016:13:57:38 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 400 68 "-" "Python-urllib/2.7"
2016-01-28 16:57:40 [-] 127.0.0.1 - - [28/Jan/2016:13:57:40 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 400 68 "-" "Python-urllib/2.7"
2016-01-28 16:57:42 [-] 127.0.0.1 - - [28/Jan/2016:13:57:42 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 400 68 "-" "Python-urllib/2.7"
2016-01-28 16:57:47 [-] 127.0.0.1 - - [28/Jan/2016:13:57:46 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 400 68 "-" "Python-urllib/2.7"
2016-01-28 16:57:48 [-] 127.0.0.1 - - [28/Jan/2016:13:57:48 +0000] "GET /MAAS/rpc/ HTTP/1.1" 200 412 "-" "provisioningserver.rpc.clusterserv
ice.ClusterClientService"
2016-01-28 16:57:55 [-] 127.0.0.1 - - [28/Jan/2016:13:57:54 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 400 68 "-" "Python-urllib/2.7"
2016-01-28 16:58:11 [-] 127.0.0.1 - - [28/Jan/2016:13:58:11 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 400 68 "-" "Python-urllib/2.7"
2016-01-28 16:58:18 [-] 127.0.0.1 - - [28/Jan/2016:13:58:18 +0000] "GET /MAAS/rpc/ HTTP/1.1" 200 412 "-" "provisioningserver.rpc.clusterserv
ice.ClusterClientService"
2016-01-28 16:58:44 [-] 127.0.0.1 - - [28/Jan/2016:13:58:43 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 200 2 "-" "Python-urllib/2.7"
2016-01-28 16:58:44 [-] 127.0.0.1 - - [28/Jan/2016:13:58:44 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 200 2 "-" "Python-urllib/2.7"
2016-01-28 16:58:45 [-] 127.0.0.1 - - [28/Jan/2016:13:58:44 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 200 2 "-" "Python-urllib/2.7"
2016-01-28 16:58:46 [-] 127.0.0.1 - - [28/Jan/2016:13:58:45 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 200 2 "-" "Python-urllib/2.7"
2016-01-28 16:58:46 [-] 127.0.0.1 - - [28/Jan/2016:13:58:46 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 200 2 "-" "Python-urllib/2.7"
2016-01-28 16:58:47 [-] 127.0.0.1 - - [28/Jan/2016:13:58:47 +0000] "POST /MAAS/metadata/2012-03-01/ HTTP/1.1" 200 2 "-" "Python-urllib/2.7"

apache log is not much helpful too:

192.168.10.143 - - [02/Feb/2016:19:12:27 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 200 300 "-" "Python-urllib/2.7"
192.168.10.143 - - [02/Feb/2016:19:12:31 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 200 300 "-" "Python-urllib/2.7"
192.168.10.143 - - [02/Feb/2016:19:12:32 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 200 300 "-" "Python-urllib/2.7"
192.168.10.143 - - [02/Feb/2016:19:12:33 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 200 300 "-" "Python-urllib/2.7"
192.168.10.143 - - [02/Feb/2016:19:12:33 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 200 300 "-" "Python-urllib/2.7"
192.168.10.143 - - [02/Feb/2016:19:12:35 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 200 300 "-" "Python-urllib/2.7"
192.168.10.143 - - [02/Feb/2016:19:12:35 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 200 300 "-" "Python-urllib/2.7"
192.168.10.143 - - [02/Feb/2016:19:12:36 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 400 293 "-" "Python-urllib/2.7"
192.168.10.143 - - [02/Feb/2016:19:12:37 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 400 293 "-" "Python-urllib/2.7"
192.168.10.143 - - [02/Feb/2016:19:12:38 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 400 293 "-" "Python-urllib/2.7"
192.168.10.143 - - [02/Feb/2016:19:12:41 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 400 293 "-" "Python-urllib/2.7"
192.168.10.143 - - [02/Feb/2016:19:12:45 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 400 293 "-" "Python-urllib/2.7"
192.168.10.143 - - [02/Feb/2016:19:12:53 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 400 293 "-" "Python-urllib/2.7"
192.168.10.202 - - [02/Feb/2016:19:12:57 +0300] "GET /MAAS/rpc/ HTTP/1.0" 200 598 "-" "provisioningserver.rpc.clusterservice.ClusterClientSe
rvice"
192.168.10.143 - - [02/Feb/2016:19:13:09 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 400 293 "-" "Python-urllib/2.7"
192.168.10.202 - - [02/Feb/2016:19:13:27 +0300] "GET /MAAS/rpc/ HTTP/1.0" 200 598 "-" "provisioningserver.rpc.clusterservice.ClusterClientSe
rvice"
192.168.10.143 - - [02/Feb/2016:19:13:42 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 200 300 "-" "Python-urllib/2.7"
192.168.10.143 - - [02/Feb/2016:19:13:43 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 200 300 "-" "Python-urllib/2.7"
192.168.10.143 - - [02/Feb/2016:19:13:43 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 200 300 "-" "Python-urllib/2.7"
192.168.10.143 - - [02/Feb/2016:19:13:44 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 200 300 "-" "Python-urllib/2.7"
192.168.10.143 - - [02/Feb/2016:19:13:45 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 200 300 "-" "Python-urllib/2.7"
192.168.10.143 - - [02/Feb/2016:19:13:45 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 200 300 "-" "Python-urllib/2.7"
192.168.10.143 - - [02/Feb/2016:19:13:46 +0300] "POST /MAAS/metadata//2012-03-01/ HTTP/1.1" 200 300 "-" "Python-urllib/2.7"

As you can see, some POSTs got 200, and some (actually just one
but it repeats) is getting 400.
Where should I dig to investigate the problem?

# dpkg -l '*maas*'|cat
Desired=Unknown/Install/Remove/Purge/Hold
| Status=Not/Inst/Conf-files/Unpacked/halF-conf/Half-inst/trig-aWait/Trig-pend
|/ Err?=(none)/Reinst-required (Status,Err: uppercase=bad)
||/ Name Version Architecture Description
+++-=============================================-===================================-============-===============================================================================
ii maas 1.9.0+bzr4533-0ubuntu1~trusty1 all MAAS server all-in-one metapackage
ii maas-cli 1.9.0+bzr4533-0ubuntu1~trusty1 all MAAS command line API tool
ii maas-cluster-controller 1.9.0+bzr4533-0ubuntu1~trusty1 all MAAS server cluster controller
ii maas-common 1.9.0+bzr4533-0ubuntu1~trusty1 all MAAS server common files
ii maas-dhcp 1.9.0+bzr4533-0ubuntu1~trusty1 all MAAS DHCP server
ii maas-dns 1.9.0+bzr4533-0ubuntu1~trusty1 all MAAS DNS server
ii maas-enlist 0.4+bzr38-0ubuntu1 armhf MAAS enlistment tool
ii maas-proxy 1.9.0+bzr4533-0ubuntu1~trusty1 all MAAS Caching Proxy
ii maas-region-controller 1.9.0+bzr4533-0ubuntu1~trusty1 all MAAS server complete region controller
ii maas-region-controller-min 1.9.0+bzr4533-0ubuntu1~trusty1 all MAAS Server minimum region controller
ii maas-test 0.1+bzr147-0ubuntu1 all Utility to test hardware compatibility with MAAS
ii python-django-maas 1.9.0+bzr4533-0ubuntu1~trusty1 all MAAS server Django web framework
ii python-maas-client 1.9.0+bzr4533-0ubuntu1~trusty1 all MAAS python API client
ii python-maas-provisioningserver 1.9.0+bzr4533-0ubuntu1~trusty1 all MAAS server provisioning libraries

Revision history for this message

Andres Rodriguez (andreserl) wrote on 2016-02-02:

Any chance you can login into the commissioning environment an obtain the file 00-maas-07-block-devices.out ? Also, what type of storage do you have connected?

Changed in maas:
status:	New → Incomplete
milestone:	none → 1.9.1

Revision history for this message

stsp (stsp-0) wrote on 2016-02-03:

Download full text (7.0 KiB)

Do you think the content of that file could prevent
its uploading? I've never thought of that.
I can simply grab it from http transaction, see below.
Btw, would it be possible to add some logging of such
failures? I don't even know where to start looking in.

HTTP dumps below:

--- Data:
--VsAiBdiqkSfzXNnvxYmJsohrifRNILY
Content-Disposition: form-data; name="status"

WORKING
--VsAiBdiqkSfzXNnvxYmJsohrifRNILY
Content-Disposition: form-data; name="script_result"

0
--VsAiBdiqkSfzXNnvxYmJsohrifRNILY
Content-Disposition: form-data; name="error"

finished 00-maas-07-block-devices [6/9]: 0
--VsAiBdiqkSfzXNnvxYmJsohrifRNILY
Content-Disposition: form-data; name="op"

signal
--VsAiBdiqkSfzXNnvxYmJsohrifRNILY
Content-Disposition: form-data; name="00-maas-07-block-devices.out"; filename="00-maas-07-block-devices.out"
Content-Type: application/octet-stream

[
{
"BLOCK_SIZE": "4096",
"NA...

HTTP dumps below:

request to http://192.168.10.202/MAAS/metadata//2012-03-01/ failed. sleeping 16.
: HTTP Error 400: BAD REQUEST                                                   
--- Headers:                                                                    
{'content-length': '1514', 'content-type': 'multipart/form-data; boundary=VsAiBd
iqkSfzXNnvxYmJsohrifRNILY', 'Authorization': 'OAuth realm="", oauth_nonce="7ffde
230c5d34e98980b4a53a4f5de26", oauth_timestamp="1454494085", oauth_consumer_key="
gSUCXVsHWQcLx99NS7", oauth_signature_method="PLAINTEXT", oauth_version="1.0", oa
uth_token="kkkZNp7Kfqvt8fVjD5", oauth_signature="%265KgVQ8pbb4AnmgeKjbhaAFmJWzQf
gkaE"'}                                                                         
--- End Headers                                                                 
                                                                                
--- Data:                                                                       
--VsAiBdiqkSfzXNnvxYmJsohrifRNILY                                               
Content-Disposition: form-data; name="status"                                   
                                                                                
WORKING                                                                         
--VsAiBdiqkSfzXNnvxYmJsohrifRNILY                                               
Content-Disposition: form-data; name="script_result"                            
                                                                                
0                                                                               
--VsAiBdiqkSfzXNnvxYmJsohrifRNILY                                               
Content-Disposition: form-data; name="error"                                    
                                                                                
finished 00-maas-07-block-devices [6/9]: 0                                      
--VsAiBdiqkSfzXNnvxYmJsohrifRNILY                                               
Content-Disposition: form-data; name="op"                                       
                                                                                
signal                                                                          
--VsAiBdiqkSfzXNnvxYmJsohrifRNILY                                               
Content-Disposition: form-data; name="00-maas-07-block-devices.out"; filename="00-maas-07-block-devices.out"                                                    
Content-Type: application/octet-stream                                          
                                                                                
[                                                                               
 {                                                                              
  "BLOCK_SIZE": "4096",                                                         
  "NAME": "sda",                                                                
  "SATA": "1",                                                                  
  "ID_PATH": "/dev/disk/by-id/wwn-0x5000cca654cecb82",                          
  "PATH": "/dev/sda",                                                           
  "ROTA": "1",                                                                  
  "RM": "0",                                                                    
  "MODEL": "Hitachi HTS54503",                                                  
  "RO": "0",                                                                    
  "RPM": "5400",                                                                
  "SERIAL": "TA5B11GZH1JYHS",                                                   
  "SIZE": "320072933376"                                                        
 },                                                                             
 {                                                                              
  "BLOCK_SIZE": "4096",                                                         
  "NAME": "sdb",                                                                
  "ID_PATH": "/dev/disk/by-id/wwn-0x3000000100000001",                          
  "PATH": "/dev/sdb",                                                           
  "ROTA": "1",                                                                  
  "RM": "0",                                                                    
  "MODEL": "VIRTUAL-DISK",                                                      
  "RO": "1",                                                                    
  "SERIAL": "3000000100000001",                                                 
  "SIZE": "1468006400"                                                          
 },                                                                             
 {                                                                              
  "BLOCK_SIZE": "4096",                                                         
  "NAME": "mtdblock0",                                                          
  "PATH": "/dev/mtdblock0",                                                     
  "ROTA": "0",                                                                  
  "RM": "0",                                                                    
  "MODEL": "",                                                                  
  "RO": "0",                                                                    
  "SIZE": "1048576"                                                             
 },                                                                             
 {                                                                              
  "BLOCK_SIZE": "4096",                                                         
  "NAME": "mtdblock1",                                                          
  "PATH": "/dev/mtdblock1",                                                     
  "ROTA": "0",                                                                  
  "RM": "0",                                                                    
  "MODEL": "",                                                                  
  "RO": "0",                                                                    
  "SIZE": "65536"                                                               
 }                                                                              
]                                                                               
                                                                                
--VsAiBdiqkSfzXNnvxYmJsohrifRNILY--                                             
                                                                                
--- End Data

Changed in maas:
status:	Incomplete → New

Revision history for this message

Andres Rodriguez (andreserl) wrote on 2016-02-03:

It may be the case that the contents might be the issue, but that's what we'll look into.

Commissioning logging is something that is already available but only supported when deploying wily, as it is done using the version of cloud-init that is in wily+. However, there are some improvements needed to be done there.

Revision history for this message

stsp (stsp-0) wrote on 2016-02-03:

Could you please help me debugging this?
I simply don't know where to start looking in on a server side.
Where is that script that controls the upload, so that I can
trace it through?

Revision history for this message

stsp (stsp-0) wrote on 2016-02-03:

I seem to went a little further debugging this.
The HTTP reply contains:

HTTP/1.1 400 BAD REQUEST
Date: Wed, 03 Feb 2016 14:08:47 GMT
Server: TwistedWeb/13.2.0
Content-Type: application/json
X-Frame-Options: SAMEORIGIN
Vary: Cookie
Connection: close
Transfer-Encoding: chunked

44
{"size": ["Ensure this value is greater than or equal to 4194304."]}
0

So obviously it doesn't like my block file because there
are some entries coming from mtd device, which are too
small. But they are not HDD at all!
What would be the fix for this?

Revision history for this message

stsp (stsp-0) wrote on 2016-02-03:

Consider addong the following change so that the problem
is at least visible:

--- maas_api_helper.py.old 2016-02-03 18:29:45.923014862 +0300
+++ maas_api_helper.py 2016-02-03 18:25:48.530820526 +0300
@@ -138,6 +138,7 @@
pass

warn("request to %s failed. sleeping %d.: %s" % (url, naptime, exc))
+ warn("%s\n" % (exc.read()))
time.sleep(naptime)

raise exc

Revision history for this message

Andres Rodriguez (andreserl) wrote on 2016-02-03:

Do you have a flash device or anything there with not so much storage size?

Changed in maas:
importance:	Undecided → High

Revision history for this message

stsp (stsp-0) wrote on 2016-02-03:

Surely.
And as you can see from the file, it is partitioned
to even smaller parts, which maas treats separately
(hope it doesn't treat separately the HDD partitions).
So when it sees the small partition, it bails.
It should instead just ignore the small partitions I suppose.

Gavin Panella (allenap) on 2016-02-04

Changed in maas:
status:	New → Triaged

Revision history for this message

stsp (stsp-0) wrote on 2016-02-04:

I think the good fix would be to add '-S' switch to
lsblk. But this option is not supported in trusty, only
in later releases (needs Util-linux 2.23).

Revision history for this message

stsp (stsp-0) wrote on 2016-02-11:

#10

I installed maas from xenial-proposed to get something
latest. But I can't even run it.
There are no more the upstart services, but it seems the
systemd service is instead packaged:

# ls /lib/systemd/system/maas-regiond.service
/lib/systemd/system/maas-regiond.service

But:

# service maas-regiond start
maas-regiond: unrecognized service
# systemctl start maas-regiond
Failed to start maas-regiond.service: Unknown unit: maas-regiond.service

I suppose I am doing something silly, but I've never used systemd.
Any help? How to launch maas now?

Revision history for this message

stsp (stsp-0) wrote on 2016-02-11:

#11

Nevermind, had to install systemd-sysv and disable selinux.

Revision history for this message

stsp (stsp-0) wrote on 2016-02-19:

#12

So 'lsblk -S' tested and fixes the problem.
I took it from newer ubuntu and modified an image.

Andres Rodriguez (andreserl) on 2016-03-01

Changed in maas:
milestone:	1.9.1 → 1.9.2

Andres Rodriguez (andreserl) on 2016-04-27

Changed in maas:
milestone:	1.9.2 → 1.9.3

Andres Rodriguez (andreserl) on 2016-05-17

Changed in maas:
milestone:	1.9.3 → 1.9.4

Andres Rodriguez (andreserl) on 2016-07-13

Changed in maas:
milestone:	1.9.4 → 1.9.5

Revision history for this message

Andres Rodriguez (andreserl) wrote on 2017-11-03:

#13

We believe this is no longer an issue in the latest releases of MAAS. Please upgrade to the latest version of MAAS, and If you believe this issue is still present, please re-open this bug report or file a new one.

Changed in maas:
status:	Triaged → Invalid

Revision history for this message

stsp (stsp-0) wrote on 2017-11-04:

#14

And why Invalid?
This bug was perfectly valid, so
if it is fixed, you could mark it
as such.

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.