Open Stack

Given that the get_console_log RPC call times out (i.e. the
compute-node-specific topic message is not being processed)
and that the instance is stuck in the scheduling task, this
suggests an issue with the nova-compute service on the node
that your new instance is being scheduled to.

Can you check if the nova-compute service on that host is
responsive (check the scheduler logs to figure out which
node if you have several) and restart it if necessary.

Cheers,
Eoghan

----- Original Message -----
> 
> 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/action
> returned with HTTP 500
> 
> 
> 
> 
> 
> 2012/9/3 Eoghan Glynn < eglynn at redhat.com >
> 
> 
> 
> 
> 
> > 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
> 
> 
> 
> 
> 
> 
> 
>