openstack team mailing list archive

Thread
Date
Re: boot command fails

To: Eoghan Glynn <eglynn@xxxxxxxxxx>
From: Afef MDHAFFAR <afef.mdhaffar@xxxxxxxxx>
Date: Tue, 4 Sep 2012 13:15:14 +0200
Cc: openstack@xxxxxxxxxxxxxxxxxxx
In-reply-to: <19652360.165167.1346665629515.JavaMail.root@redhat.com>
Thank you for you answer.
Actually, the problem was related to many issues ... I tried to solve them.
However, I am still not able to launch an instance. When booting the image,
everything seems to be ok (no errors) but the status of the instance stucks
on "BUILD" and does not switch to "Active".
Here is the output of boot --debug:
nova --debug boot --flavor 1 --image 387e6ac0-9e51-449f-871f-5c350d28a05f
op1
connect: (ip, 5000)
send: 'POST /v2.0/tokens HTTP/1.1\r\nHost: ip:5000\r\nContent-Length:
117\r\ncontent-type: application/json\r\naccept-encoding: gzip,
deflate\r\naccept: application/json\r\nuser-agent:
python-novaclient\r\n\r\n{"auth": {"tenantName": "openstackDemo",
"passwordCredentials": {"username": "adminUser", "password":
"secretword"}}}'
reply: 'HTTP/1.1 200 OK\r\n'
header: Content-Type: application/json
header: Vary: X-Auth-Token
header: Date: Tue, 04 Sep 2012 10:56:33 GMT
header: Transfer-Encoding: chunked
connect: (ip, 8774)
send: u'GET /v2/141d12e2431f47a5bf77f90da4800960/flavors/1
HTTP/1.1\r\nHost: ip:8774\r\nx-auth-project-id:
openstackDemo\r\nx-auth-token:
db508fb3c43d455eb8f55a089a5a9812\r\naccept-encoding: gzip,
deflate\r\naccept: application/json\r\nuser-agent:
python-novaclient\r\n\r\n'
reply: 'HTTP/1.1 200 OK\r\n'
header: X-Compute-Request-Id: req-3f66603d-05e5-4603-bce6-621b528719c4
header: Content-Type: application/json
header: Content-Length: 349
header: Date: Tue, 04 Sep 2012 10:56:33 GMT
send: u'GET
/v2/141d12e2431f47a5bf77f90da4800960/images/387e6ac0-9e51-449f-871f-5c350d28a05f
HTTP/1.1\r\nHost: ip:8774\r\nx-auth-project-id:
openstackDemo\r\nx-auth-token:
db508fb3c43d455eb8f55a089a5a9812\r\naccept-encoding: gzip,
deflate\r\naccept: application/json\r\nuser-agent:
python-novaclient\r\n\r\n'
reply: 'HTTP/1.1 200 OK\r\n'
header: X-Compute-Request-Id: req-578567ec-d4a1-40e4-bf7f-00e57af73f7e
header: Content-Type: application/json
header: Content-Length: 786
header: Date: Tue, 04 Sep 2012 10:56:33 GMT
send: u'GET
/v2/141d12e2431f47a5bf77f90da4800960/images/387e6ac0-9e51-449f-871f-5c350d28a05f
HTTP/1.1\r\nHost: ip:8774\r\nx-auth-project-id:
openstackDemo\r\nx-auth-token:
db508fb3c43d455eb8f55a089a5a9812\r\naccept-encoding: gzip,
deflate\r\naccept: application/json\r\nuser-agent:
python-novaclient\r\n\r\n'
reply: 'HTTP/1.1 200 OK\r\n'
header: X-Compute-Request-Id: req-18d1f242-ff9b-49a4-abd6-1e4f975e7cbc
header: Content-Type: application/json
header: Content-Length: 786
header: Date: Tue, 04 Sep 2012 10:56:33 GMT
send: u'GET /v2/141d12e2431f47a5bf77f90da4800960/flavors/1
HTTP/1.1\r\nHost: ip:8774\r\nx-auth-project-id:
openstackDemo\r\nx-auth-token:
db508fb3c43d455eb8f55a089a5a9812\r\naccept-encoding: gzip,
deflate\r\naccept: application/json\r\nuser-agent:
python-novaclient\r\n\r\n'
reply: 'HTTP/1.1 200 OK\r\n'
header: X-Compute-Request-Id: req-95eb694e-7ce6-47e6-b64b-bca88cceb8a7
header: Content-Type: application/json
header: Content-Length: 349
header: Date: Tue, 04 Sep 2012 10:56:33 GMT
send: u'POST /v2/141d12e2431f47a5bf77f90da4800960/servers HTTP/1.1\r\nHost:
ip:8774\r\nContent-Length: 129\r\nx-auth-project-id:
openstackDemo\r\naccept-encoding: gzip, deflate\r\naccept:
application/json\r\nx-auth-token:
db508fb3c43d455eb8f55a089a5a9812\r\nuser-agent:
python-novaclient\r\ncontent-type: application/json\r\n\r\n{"server":
{"min_count": 1, "flavorRef": "1", "name": "op1", "imageRef":
"387e6ac0-9e51-449f-871f-5c350d28a05f", "max_count": 1}}'
reply: 'HTTP/1.1 202 Accepted\r\n'
header: X-Compute-Request-Id: req-cda73f6f-6410-4368-af4a-4b29018e0ae0
header: Location:
http://ip:8774/v2/141d12e2431f47a5bf77f90da4800960/servers/2314f007-d446-477a-bcf0-6a5f77d4d25b
header: Content-Type: application/json
header: Content-Length: 396
header: Date: Tue, 04 Sep 2012 10:56:34 GMT
send: u'GET
/v2/141d12e2431f47a5bf77f90da4800960/servers/2314f007-d446-477a-bcf0-6a5f77d4d25b
HTTP/1.1\r\nHost: ip:8774\r\nx-auth-project-id:
openstackDemo\r\nx-auth-token:
db508fb3c43d455eb8f55a089a5a9812\r\naccept-encoding: gzip,
deflate\r\naccept: application/json\r\nuser-agent:
python-novaclient\r\n\r\n'
reply: 'HTTP/1.1 200 OK\r\n'
header: X-Compute-Request-Id: req-f64a287d-26b3-47ca-8287-a506e53a52e8
header: Content-Type: application/json
header: Content-Length: 1267
header: Date: Tue, 04 Sep 2012 10:56:34 GMT
send: u'GET /v2/141d12e2431f47a5bf77f90da4800960/flavors/1
HTTP/1.1\r\nHost: ip:8774\r\nx-auth-project-id:
openstackDemo\r\nx-auth-token:
db508fb3c43d455eb8f55a089a5a9812\r\naccept-encoding: gzip,
deflate\r\naccept: application/json\r\nuser-agent:
python-novaclient\r\n\r\n'
reply: 'HTTP/1.1 200 OK\r\n'
header: X-Compute-Request-Id: req-72fe38ae-5696-460b-ae31-00c3514cf996
header: Content-Type: application/json
header: Content-Length: 349
header: Date: Tue, 04 Sep 2012 10:56:34 GMT
send: u'GET
/v2/141d12e2431f47a5bf77f90da4800960/images/387e6ac0-9e51-449f-871f-5c350d28a05f
HTTP/1.1\r\nHost: ip:8774\r\nx-auth-project-id:
openstackDemo\r\nx-auth-token:
db508fb3c43d455eb8f55a089a5a9812\r\naccept-encoding: gzip,
deflate\r\naccept: application/json\r\nuser-agent:
python-novaclient\r\n\r\n'
reply: 'HTTP/1.1 200 OK\r\n'
header: X-Compute-Request-Id: req-c5c6c0df-4ac7-4f50-b92a-35afb89aaa45
header: Content-Type: application/json
header: Content-Length: 786
header: Date: Tue, 04 Sep 2012 10:56:35 GMT
+-------------------------------------+--------------------------------------+
|               Property              |                Value
  |
+-------------------------------------+--------------------------------------+
| OS-DCF:diskConfig                   | MANUAL
  |
| OS-EXT-SRV-ATTR:host                | None
  |
| OS-EXT-SRV-ATTR:hypervisor_hostname | None
  |
| OS-EXT-SRV-ATTR:instance_name       | instance-00000045
 |
| OS-EXT-STS:power_state              | 0
 |
| OS-EXT-STS:task_state               | scheduling
  |
| OS-EXT-STS:vm_state                 | building
  |
| accessIPv4                          |
 |
| accessIPv6                          |
 |
| adminPass                           | vRxK5r8mYK6H
  |
| config_drive                        |
 |
| created                             | 2012-09-04T10:56:34Z
  |
| flavor                              | m1.tiny
 |
| hostId                              |
 |
| id                                  |
2314f007-d446-477a-bcf0-6a5f77d4d25b |
| image                               | tty-linux
 |
| key_name                            |
 |
| metadata                            | {}
  |
| name                                | op1
 |
| progress                            | 0
 |
| status                              | BUILD
 |
| tenant_id                           | 141d12e2431f47a5bf77f90da4800960
  |
| updated                             | 2012-09-04T10:56:34Z
  |
| user_id                             | cf8971efd8934844b559d26e238506cc
  |
+-------------------------------------+--------------------------------------+

Log files (nova-api, nova-scheduler, nova-compute, nova-network) show no
errors.
"nova-manage logs errors" shows no errors.

When I try to launch "nova console-log op1", it shows the http 500 error.
Then a new timeout error is added to nova-api.log. Here is the error shown
in nova-api.log
2012-09-04 08:31:01 DEBUG nova.rpc.amqp
[req-0c9fe15a-0d0c-4e4a-a506-aff83886bc48 cf8971efd8934844b559d26e238506cc
141d12e2431f47a5bf77f90da4800960] Making asynchronous cast on scheduler...
from (pid=431) cast /usr/lib/python2.7/dist-packages/nova/rpc/amqp.py:351
2012-09-04 08:31:01 INFO nova.api.openstack.wsgi
[req-0c9fe15a-0d0c-4e4a-a506-aff83886bc48 cf8971efd8934844b559d26e238506cc
141d12e2431f47a5bf77f90da4800960]
http://ip:8774/v2/141d12e2431f47a5bf77f90da4800960/servers returned with
HTTP 202
2012-09-04 08:31:01 INFO nova.api.openstack.wsgi
[req-3f4b9980-85cc-46ff-bf06-7d60659756f4 cf8971efd8934844b559d26e238506cc
141d12e2431f47a5bf77f90da4800960] GET
http://ip:8774/v2/141d12e2431f47a5bf77f90da4800960/servers/83035d31-86d7-461e-b42e-b03300111766
"/var/log/nova/nova-api.log" 9795L, 2009777C


                         1,1           Top
2012-09-04 13:09:16 TRACE nova.rpc.common     return
connection.drain_events(**kwargs)
2012-09-04 13:09:16 TRACE nova.rpc.common   File
"/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 57,
in drain_events
2012-09-04 13:09:16 TRACE nova.rpc.common     return
self.wait_multi(self.channels.values(), timeout=timeout)
2012-09-04 13:09:16 TRACE nova.rpc.common   File
"/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 63,
in wait_multi
2012-09-04 13:09:16 TRACE nova.rpc.common     chanmap.keys(),
allowed_methods, timeout=timeout)
2012-09-04 13:09:16 TRACE nova.rpc.common   File
"/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 120,
in _wait_multiple
2012-09-04 13:09:16 TRACE nova.rpc.common     channel, method_sig, args,
content = read_timeout(timeout)
2012-09-04 13:09:16 TRACE nova.rpc.common   File
"/usr/lib/python2.7/dist-packages/kombu/transport/pyamqplib.py", line 94,
in read_timeout
2012-09-04 13:09:16 TRACE nova.rpc.common     return
self.method_reader.read_method()
2012-09-04 13:09:16 TRACE nova.rpc.common   File
"/usr/lib/python2.7/dist-packages/amqplib/client_0_8/method_framing.py",
line 221, in read_method
2012-09-04 13:09:16 TRACE nova.rpc.common     raise m
2012-09-04 13:09:16 TRACE nova.rpc.common timeout: timed out
2012-09-04 13:09:16 TRACE nova.rpc.common
2012-09-04 13:09:16 ERROR nova.api.openstack
[req-ebaafb8a-770f-467e-b0c4-d89527bc87b4 cf8971efd8934844b559d26e238506cc
141d12e2431f47a5bf77f90da4800960] Caught error: Timeout while waiting on
RPC response.
2012-09-04 13:09:16 TRACE nova.api.openstack Traceback (most recent call
last):
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/nova/api/openstack/__init__.py", line 41,
in __call__
2012-09-04 13:09:16 TRACE nova.api.openstack     return
req.get_response(self.application)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/webob/request.py", line 1086, in
get_response
2012-09-04 13:09:16 TRACE nova.api.openstack     application,
catch_exc_info=False)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/webob/request.py", line 1055, in
call_application
2012-09-04 13:09:16 TRACE nova.api.openstack     app_iter =
application(self.environ, start_response)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/keystone/middleware/auth_token.py", line
176, in __call__
2012-09-04 13:09:16 TRACE nova.api.openstack     return self.app(env,
start_response)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/webob/dec.py", line 159, in __call__
2012-09-04 13:09:16 TRACE nova.api.openstack     return resp(environ,
start_response)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/webob/dec.py", line 159, in __call__
2012-09-04 13:09:16 TRACE nova.api.openstack     return resp(environ,
start_response)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/webob/dec.py", line 159, in __call__
2012-09-04 13:09:16 TRACE nova.api.openstack     return resp(environ,
start_response)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/routes/middleware.py", line 131, in
__call__
2012-09-04 13:09:16 TRACE nova.api.openstack     response =
self.app(environ, start_response)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/webob/dec.py", line 159, in __call__
2012-09-04 13:09:16 TRACE nova.api.openstack     return resp(environ,
start_response)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/webob/dec.py", line 147, in __call__
2012-09-04 13:09:16 TRACE nova.api.openstack     resp = self.call_func(req,
*args, **self.kwargs)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/webob/dec.py", line 210, in call_func
2012-09-04 13:09:16 TRACE nova.api.openstack     return self.func(req,
*args, **kwargs)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/nova/api/openstack/wsgi.py", line 803, in
__call__
2012-09-04 13:09:16 TRACE nova.api.openstack     content_type, body, accept)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/nova/api/openstack/wsgi.py", line 851, in
_process_stack
2012-09-04 13:09:16 TRACE nova.api.openstack     action_result =
self.dispatch(meth, request, action_args)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/nova/api/openstack/wsgi.py", line 926, in
dispatch
2012-09-04 13:09:16 TRACE nova.api.openstack     return method(req=request,
**action_args)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/nova/api/openstack/compute/contrib/console_output.py",
line 57, in get_console_output
2012-09-04 13:09:16 TRACE nova.api.openstack     length)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 100, in wrapped
2012-09-04 13:09:16 TRACE nova.api.openstack     return func(self, context,
target, *args, **kwargs)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 1549, in
get_console_output
2012-09-04 13:09:16 TRACE nova.api.openstack     instance, params=params)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 151, in
_call_compute_message
2012-09-04 13:09:16 TRACE nova.api.openstack     return
self._cast_or_call_compute_message(rpc.call, *args, **kwargs)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/nova/compute/api.py", line 143, in
_cast_or_call_compute_message
2012-09-04 13:09:16 TRACE nova.api.openstack     return rpc_method(context,
queue, kwargs)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/nova/rpc/__init__.py", line 68, in call
2012-09-04 13:09:16 TRACE nova.api.openstack     return
_get_impl().call(context, topic, msg, timeout)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/nova/rpc/impl_kombu.py", line 674, in call
2012-09-04 13:09:16 TRACE nova.api.openstack     return
rpc_amqp.call(context, topic, msg, timeout, Connection.pool)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/nova/rpc/amqp.py", line 343, in call
2012-09-04 13:09:16 TRACE nova.api.openstack     rv = list(rv)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/nova/rpc/amqp.py", line 304, in __iter__
2012-09-04 13:09:16 TRACE nova.api.openstack     self.done()
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/contextlib.py", line 24, in __exit__
2012-09-04 13:09:16 TRACE nova.api.openstack     self.gen.next()
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/nova/rpc/amqp.py", line 301, in __iter__
2012-09-04 13:09:16 TRACE nova.api.openstack     self._iterator.next()
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/nova/rpc/impl_kombu.py", line 572, in
iterconsume
2012-09-04 13:09:16 TRACE nova.api.openstack     yield
self.ensure(_error_callback, _consume)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/nova/rpc/impl_kombu.py", line 503, in
ensure
2012-09-04 13:09:16 TRACE nova.api.openstack     error_callback(e)
2012-09-04 13:09:16 TRACE nova.api.openstack   File
"/usr/lib/python2.7/dist-packages/nova/rpc/impl_kombu.py", line 553, in
_error_callback
2012-09-04 13:09:16 TRACE nova.api.openstack     raise rpc_common.Timeout()
2012-09-04 13:09:16 TRACE nova.api.openstack Timeout: Timeout while waiting
on RPC response.
2012-09-04 13:09:16 TRACE nova.api.openstack
2012-09-04 13:09:16 INFO nova.api.openstack
[req-ebaafb8a-770f-467e-b0c4-d89527bc87b4 cf8971efd8934844b559d26e238506cc
141d12e2431f47a5bf77f90da4800960]
http://ip:8774/v2/141d12e2431f47a5bf77f90da4800960/servers/2314f007-d446-477a-bcf0-6a5f77d4d25b/actionreturned
with HTTP 500



2012/9/3 Eoghan Glynn <eglynn@xxxxxxxxxx>

>
> > While trying to create a VM instance on openstack, the boot command
> > (nova boot) returns the following error:
> > ---
> > ERROR: The server has either erred or is incapable of performing the
> > requested operation. (HTTP 500)
> > ---
> > everything seems to be working (nova services are starting).
> >
> >
> > I am using an Ubuntu 12.04 server (amd64) with Xen as a
> > virtualization technology + the Essex version of openstack
> >
> >
> > The used image was manually created (it is an ubuntu also). I can
> > start it via xm commands.
> >
> >
> > Any idea how to solve this problem?
>
>
> The first step would be to surface more detailed information on the failure
> that has occurred.
>
> In Essex, most internal nova exceptions are mapped directly to 500 Server
> Error,
> which effectively hides the underlying error condition from the client.
>
> Folsom is more permissive in this regard, so that internal exceptions
> declared
> safe for exposure are returned to the user.
>
> So in your case, you'll need to scour the nova-api, nova-scheduler &
> nova-compute
> logs to get visibility on the underlying error condition.
>
> A quick short-cut would be to note the request ID returned (use "nova
> --debug boot ...")
> and then grep for this in the logs mentioned above.
>
> Cheers,
> Eoghan
>
Follow ups

Re: boot command fails
From: Eoghan Glynn, 2012-09-04
References

boot command fails
From: Afef MDHAFFAR, 2012-08-31
Re: boot command fails
From: Eoghan Glynn, 2012-09-03