Open Stack

On 12/12/2014 3:36 AM, joejiang wrote:
> Hi folks,
> when i launch instance use cirros image in the new openstack
> environment(juno version & centos7 OS base), the following piece is
> error logs from compute node.
>   anybody meet the same error?
>
>
>
>
> ----------------------------
> 2014-12-12 17:16:52.481 12966 ERROR nova.compute.manager [-] [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d] Failed to allocate network(s)
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d] Traceback (most recent call last):
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]   File
> "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2190,
> in _build_resources
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]     requested_networks,
> security_groups)
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]   File
> "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1683,
> in _build_networks_for_instance
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]     requested_networks, macs,
> security_groups, dhcp_options)
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]   File
> "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 1717,
> in _allocate_network
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]
> instance.save(expected_task_state=[None])
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]   File
> "/usr/lib/python2.7/site-packages/nova/objects/base.py", line 189, in
> wrapper
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]     ctxt, self, fn.__name__, args,
> kwargs)
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]   File
> "/usr/lib/python2.7/site-packages/nova/conductor/rpcapi.py", line 351,
> in object_action
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]     objmethod=objmethod,
> args=args, kwargs=kwargs)
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]   File
> "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/client.py", line
> 152, in call
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]     retry=self.retry)
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]   File
> "/usr/lib/python2.7/site-packages/oslo/messaging/transport.py", line 90,
> in _send
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]     timeout=timeout, retry=retry)
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]   File
> "/usr/lib/python2.7/site-packages/oslo/messaging/_drivers/amqpdriver.py", line
> 408, in send
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]     retry=retry)
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]   File
> "/usr/lib/python2.7/site-packages/oslo/messaging/_drivers/amqpdriver.py", line
> 399, in _send
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]     raise result
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d] RemoteError: Remote error:
> OperationalError (OperationalError) (1048, "Column 'instance_uuid'
> cannot be null") 'UPDATE instance_extra SET updated_at=%s,
> instance_uuid=%s WHERE instance_extra.id = %s' (datetime.datetime(2014,
> 12, 12, 9, 16, 52, 434376), None, 5L)
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d] [u'Traceback (most recent call
> last):\n', u'  File
> "/usr/lib/python2.7/site-packages/nova/conductor/manager.py", line 400,
> in _object_dispatch\n    return getattr(target, method)(context, *args,
> **kwargs)\n', u'  File
> "/usr/lib/python2.7/site-packages/nova/objects/base.py", line 204, in
> wrapper\n    return fn(self, ctxt, *args, **kwargs)\n', u'  File
> "/usr/lib/python2.7/site-packages/nova/objects/instance.py", line 500,
> in save\n    columns_to_join=_expected_cols(expected_attrs))\n', u'
>   File "/usr/lib/python2.7/site-packages/nova/db/api.py", line 746, in
> instance_update_and_get_original\n
>   columns_to_join=columns_to_join)\n', u'  File
> "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 143,
> in wrapper\n    return f(*args, **kwargs)\n', u'  File
> "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 2289,
> in instance_update_and_get_original\n
>   columns_to_join=columns_to_join)\n', u'  File
> "/usr/lib/python2.7/site-packages/nova/db/sqlalchemy/api.py", line 2380,
> in _instance_update\n    session.add(instance_ref)\n', u'  File
> "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line
> 470, in __exit__\n    self.rollback()\n', u'  File
> "/usr/lib64/python2.7/site-packages/sqlalchemy/util/langhelpers.py",
> line 60, in __exit__\n    compat.reraise(exc_type, exc_value,
> exc_tb)\n', u'  File
> "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line
> 467, in __exit__\n    self.commit()\n', u'  File
> "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line
> 377, in commit\n    self._prepare_impl()\n', u'  File
> "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line
> 357, in _prepare_impl\n    self.session.flush()\n', u'  File
> "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line
> 1919, in flush\n    self._flush(objects)\n', u'  File
> "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line
> 2037, in _flush\n    transaction.rollback(_capture_exception=True)\n',
> u'  File
> "/usr/lib64/python2.7/site-packages/sqlalchemy/util/langhelpers.py",
> line 60, in __exit__\n    compat.reraise(exc_type, exc_value,
> exc_tb)\n', u'  File
> "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line
> 2001, in _flush\n    flush_context.execute()\n', u'  File
> "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line
> 372, in execute\n    rec.execute(self)\n', u'  File
> "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/unitofwork.py", line
> 526, in execute\n    uow\n', u'  File
> "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/persistence.py", line
> 60, in save_obj\n    mapper, table, update)\n', u'  File
> "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/persistence.py", line
> 518, in _emit_update_statements\n    execute(statement, params)\n', u'
>   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py",
> line 729, in execute\n    return meth(self, multiparams, params)\n', u'
>   File "/usr/lib64/python2.7/site-packages/sqlalchemy/sql/elements.py",
> line 321, in _execute_on_connection\n    return
> connection._execute_clauseelement(self, multiparams, params)\n', u'
>   File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py",
> line 826, in _execute_clauseelement\n    compiled_sql,
> distilled_params\n', u'  File
> "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line
> 958, in _execute_context\n    context)\n', u'  File
> "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line
> 1156, in _handle_dbapi_exception\n    util.raise_from_cause(newraise,
> exc_info)\n', u'  File
> "/usr/lib64/python2.7/site-packages/sqlalchemy/util/compat.py", line
> 199, in raise_from_cause\n    reraise(type(exception), exception,
> tb=exc_tb)\n', u'  File
> "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line
> 951, in _execute_context\n    context)\n', u'  File
> "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line
> 436, in do_execute\n    cursor.execute(statement, parameters)\n', u'
>   File "/usr/lib64/python2.7/site-packages/MySQLdb/cursors.py", line
> 174, in execute\n    self.errorhandler(self, exc, value)\n', u'  File
> "/usr/lib64/python2.7/site-packages/MySQLdb/connections.py", line 36, in
> defaulterrorhandler\n    raise errorclass, errorvalue\n',
> u'OperationalError: (OperationalError) (1048, "Column \'instance_uuid\'
> cannot be null") \'UPDATE instance_extra SET updated_at=%s,
> instance_uuid=%s WHERE instance_extra.id = %s\' (datetime.datetime(2014,
> 12, 12, 9, 16, 52, 434376), None, 5L)\n'].
> 2014-12-12 17:16:52.481 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]
> 2014-12-12 17:16:52.515 12966 INFO nova.scheduler.client.report [-]
> Compute_service record updated for ('computenode.domain.com')
> 2014-12-12 17:16:52.517 12966 ERROR nova.compute.manager [-] [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d] Build of instance
> 67e215e0-2193-439d-89c4-be8c378df78d aborted: Failed to allocate the
> network(s), not rescheduling.
> 2014-12-12 17:16:52.517 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d] Traceback (most recent call last):
> 2014-12-12 17:16:52.517 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]   File
> "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2030,
> in _do_build_and_run_instance
> 2014-12-12 17:16:52.517 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]     filter_properties)
> 2014-12-12 17:16:52.517 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]   File
> "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2129,
> in _build_and_run_instance
> 2014-12-12 17:16:52.517 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]     'create.error', fault=e)
> 2014-12-12 17:16:52.517 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]   File
> "/usr/lib/python2.7/site-packages/nova/openstack/common/excutils.py",
> line 82, in __exit__
> 2014-12-12 17:16:52.517 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]     six.reraise(self.type_,
> self.value, self.tb)
> 2014-12-12 17:16:52.517 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]   File
> "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2102,
> in _build_and_run_instance
> 2014-12-12 17:16:52.517 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]     block_device_mapping) as
> resources:
> 2014-12-12 17:16:52.517 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]   File
> "/usr/lib64/python2.7/contextlib.py", line 17, in __enter__
> 2014-12-12 17:16:52.517 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]     return self.gen.next()
> 2014-12-12 17:16:52.517 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]   File
> "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 2205,
> in _build_resources
> 2014-12-12 17:16:52.517 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]     reason=msg)
> 2014-12-12 17:16:52.517 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d] BuildAbortException: Build of
> instance 67e215e0-2193-439d-89c4-be8c378df78d aborted: Failed to
> allocate the network(s), not rescheduling.
> 2014-12-12 17:16:52.517 12966 TRACE nova.compute.manager [instance:
> 67e215e0-2193-439d-89c4-be8c378df78d]
> 2014-12-12 17:16:52.566 12966 INFO nova.network.neutronv2.api [-]
> [instance: 67e215e0-2193-439d-89c4-be8c378df78d] Unable to reset device
> ID for port None
> 2014-12-12 17:17:04.977 12966 WARNING nova.compute.manager
> [req-f9b96041-ff4c-4b3c-8a0e-bdedf79193d6 None] While synchronizing
> instance power states, found 1 instances in the database and 0 instances
> on the hypervisor
>
>
>
>
> _______________________________________________
> Mailing list: http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack
> Post to     : openstack at lists.openstack.org
> Unsubscribe : http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack
>

I can't say I've seen this, something is trying to update the 
instance_extra table with a null instance_uuid which isn't allowed by 
the schema.

However, the openstack-dev mailing list is not the appropriate place for 
asking about this.  If you're seeing a problem, you should report a bug 
in the bug tracker on launchpad [1].

Make sure you point out your environment setup, how you deployed it, 
which version of code you're running, and the recreate steps.  Looks 
like you have a mysql backend, you said you're running Juno code (2014.2 
release or stable/juno trunk?), and what does the server create call 
look like?

We have devstack running tempest on stable/juno with mysql as a backend 
so if this were something obvious I'd think we would have hit it in 
community CI by now.

[1] https://bugs.launchpad.net/nova

-- 

Thanks,

Matt Riedemann