Hi,
We are encountering a weird error when we try to use a heat template(resource
group) to provision 3 baremetal machines. Only the first instance is
provisioned successfully while other 2 instances failed because they are
assigned to the same ironic node and they failed to bind a network port,
according to the logs.
Btw, it succeeds if we just provision one node at a time.
Have you ever encountered similar issues or any suggestions on how to fixing
this issue?
Any comments/suggestions would be appreciated greatly.
Feel free to let me know if you need further details about this issues.
---------------- start of n-sch.log -----------------------
2016-06-14 18:41:50.872 ^[[00;32mDEBUG nova.scheduler.filter_scheduler
[^[[01;36mreq-8d084465-4ed7-440e-b016-6dc7fcc3882b ^[[00;36madmin
admin^[[00;32m] ^[[01;35m^[[00;32mFiltered [(Magnum,
6671314c-12a6-4090-85dc-2d1882188af0) ram: 16384MB disk: 69632MB io_ops: 0
instances: 0, (Magnum, 695ae540-83a4-4d06-a17b-02e72c81805a) ram: 16384MB disk:
857088MB io_ops: 0 instances: 0, (Magnum, 9bf2b3ba-d62d-4e3f-8c39-df174b786749)
ram: 16384MB disk: 570368MB io_ops: 0 instances: 0]^[[00m ^[[00;33mfrom
(pid=20074) _schedule
/opt/stack/nova/nova/scheduler/filter_scheduler.py:118^[[00m
1097 2016-06-14 18:41:50.873 ^[[00;32mDEBUG nova.scheduler.filter_scheduler
[^[[01;36mreq-8d084465-4ed7-440e-b016-6dc7fcc3882b ^[[00;36m admin
admin^[[00;32m] ^[[01;35m^[[00;32mSelected host: WeighedHost [host: (Magnum,
695ae540-83a4-4d06-a17b-02e72c81805a) ram: 16384 MB disk: 857088MB io_ops:
0 instances: 0, weight: 1.25]^[[00m ^[[00;33mfrom (pid=20074) _schedule
/opt/stack/nova/nova/scheduler/fi lter_scheduler.py:131^[[00m
1142 2016-06-14 18:41:51.628 ^[[00;32mDEBUG nova.scheduler.filter_scheduler
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36m admin
admin^[[00;32m] ^[[01;35m^[[00;32mWeighed [WeighedHost [host: (Magnum,
695ae540-83a4-4d06-a17b-02e72c81805a) ram: 12288MB dis k: 840704MB io_ops:
0 instances: 0, weight: 1.11066308244], WeighedHost [host: (Magnum,
9bf2b3ba-d62d-4e3f-8c39-df174b786749) ram: 16384MB disk: 570368MB io_ops:
0 instances: 0, weight: 0.999103942652], WeighedHost [host: (Magnum,
6671314c-12a6-4090-85dc-2d18821 88af0) ram: 16384MB disk: 69632MB io_ops: 0
instances: 0, weight: 0.560931899642]]^[[00m ^[[00;33mfrom (pid=20074)
_schedule /opt/s tack/nova/nova/scheduler/filter_scheduler.py:123^[[00m
1143 2016-06-14 18:41:51.628 ^[[00;32mDEBUG nova.scheduler.filter_scheduler
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36m admin
admin^[[00;32m] Selected host: WeighedHost [host: (Magnum,
695ae540-83a4-4d06-a17b-02e72c81805a) ram: 12288 MB disk: 840704MB io_ops:
0 instances: 0, weight: 1.11066308244]^[[00m ^[[00;33mfrom (pid=20074)
_schedule /opt/stack/nova/nova/sch eduler/filter_scheduler.py:131
-------------- end of n-sch.log --------------------------
--------------- n-cpu.log----------------------
13129 2016-06-14 18:41:51.087 ^[[00;36mINFO nova.compute.claims
[^[[01;36mreq-8d084465-4ed7-440e-b016-6dc7fcc3882b ^[[00;36madmin
admin^[[00;36m] ^[[01;35m[instance: cf88cb38-e54e-4e19-85ec-d97a03098dfb]
^[[00;36mTotal disk: 837 GB, used: 0.00 GB^[[00m
13159 2016-06-14 18:41:51.581 ^[[00;32mDEBUG nova.compute.manager
[^[[01;36mreq-8d084465-4ed7-440e-b016-6dc7fcc3882b ^[[00;36madmin
admin^[[00;32m] ^[[01;35m [instance: cf88cb38-e54e-4e19-85ec-d97a03098dfb]
^[[00;32mStart spawning the instance on the hypervisor.^[[00m ^[[00;33mfrom
(pid=20107) _build_and_run _instance
/opt/stack/nova/nova/compute/manager.py:2057
13160 2016-06-14 18:41:51.581 ^[[00;32mDEBUG nova.virt.ironic.driver
[^[[01;36mreq-8d084465-4ed7-440e-b016-6dc7fcc3882b ^[[00;36madmin
admin^[[00;32m][instance: cf88cb38-e54e-4e19-85ec-d97a03098dfb] ^[[Spawn called
for instance^[[00m ^[[00;33mfrom (pid=20107) spawn
/opt/stack/nova/nova/virt/ironic/driver.py:685
13165 2016-06-14 18:41:51.769 ^[[00;32mDEBUG nova.compute.manager
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin
admin^[[00;32m] ^[[01;35m [instance: 0b8e174e-5d6a-4976-89f3-47c5554748f0]
^[[00;32mStarting instance...^[[00m ^[[00;33mfrom (pid=20107)
_do_build_and_run_instance /opt/stack/no va/nova/compute/manager.py:1895
13171 2016-06-14 18:41:51.884 ^[[00;36mINFO nova.compute.claims
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin
admin^[[00;36m] ^[[01;35m[i nstance: 0b8e174e-5d6a-4976-89f3-47c5554748f0]
^[[00;36mAttempting claim: memory 4096 MB, disk 16 GB, vcpus 1 CPU
13174 2016-06-14 18:41:51.885 ^[[00;36mINFO nova.compute.claims
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin
admin^[[00;36m] ^[[01;35m[i nstance: 0b8e174e-5d6a-4976-89f3-47c5554748f0]
^[[00;36mTotal disk: 837 GB, used: 16.00 GB^[[00m
13175 2016-06-14 18:41:51.886 ^[[00;36mINFO nova.compute.claims
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin
admin^[[00;36m] ^[[01;35m[i nstance: 0b8e174e-5d6a-4976-89f3-47c5554748f0]
^[[00;36mdisk limit: 837.00 GB, free: 821.00 GB^[[00m
13180 2016-06-14 18:41:51.903 ^[[00;36mINFO nova.compute.claims
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin
admin^[[00;36m] ^[[01;35m[i nstance: 0b8e174e-5d6a-4976-89f3-47c5554748f0]
^[[00;36mClaim successful^[[00m
13204 2016-06-14 18:41:52.485 ^[[00;32mDEBUG nova.virt.ironic.driver
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin
admin^[[00;32m] ^[[01; 35m[instance: 0b8e174e-5d6a-4976-89f3-47c5554748f0]
^[[00;32mSpawn called for instance^[[00m ^[[00;33mfrom (pid=20107) spawn
/opt/stack/nova/nova/virt/ ironic/driver.py:685^[[00m
13205 2016-06-14 18:41:52.538 ^[[00;32mDEBUG nova.network.neutronv2.api
[^[[01;36mreq-8d084465-4ed7-440e-b016-6dc7fcc3882b ^[[00;36madmin
admin^[[00;32m] ^[[ 01;35m[instance: cf88cb38-e54e-4e19-85ec-d97a03098dfb]
^[[00;32mSuccessfully created port: 605ee23b-66da-4aba-98ee-347008a2a495^[[00m
^[[00;33mfrom (pi d=20107) _create_port
/opt/stack/nova/nova/network/neutronv2/api.py:261^[[00m
13211 2016-06-14 18:41:52.879 ^[[00;32mDEBUG neutronclient.v2_0.client
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin
admin^[[00;32m] ^[[0 1;35m^[[00;32mError message: {"NeutronError":
{"message": "Unable to complete operation for network
3290e2fe-f607-4997-ac14-0d73ef800078. The mac addre ss ec:b1:d7:83:74:43
is in use.", "type": "MacAddressInUse", "detail": ""}}^[[00m ^[[00;33mfrom
(pid=20107) _handle_fault_response /usr/local/lib/pytho
n2.7/dist-packages/neutronclient/v2_0/client.py:263^[[00m
13212 2016-06-14 18:41:52.879 ^[[01;33mWARNING nova.network.neutronv2.api
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin
admin^[[01;33m] ^ [[01;35m[instance: 0b8e174e-5d6a-4976-89f3-47c5554748f0]
^[[01;33mNeutron error: MAC address ec:b1:d7:83:74:43 is already in use on
network 3290e2fe-f6 07-4997-ac14-0d73ef800078.^[[00m
13213 2016-06-14 18:41:52.880 ^[[01;31mERROR nova.compute.manager
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin
admin^[[01;31m] ^[[01;35m ^[[01;31mInstance failed network setup after 1
attempt(s)^[[00m
13227 ^[[01;31m2016-06-14 18:41:52.880 TRACE nova.compute.manager
^[[01;35m^[[00mPortInUse: Port ec:b1:d7:83:74:43 is still in use.
13256 2016-06-14 18:41:53.015 ^[[00;32mDEBUG nova.compute.manager
[^[[01;36mreq-709fdcfe-a0ed-4ab5-ae4d-cd06109d9598 ^[[00;36madmin
admin^[[00;32m] ^[[01;35m [instance: 181593eb-a85e-4118-ae37-7f9204011631]
^[[00;32mStarting instance...^[[00m ^[[00;33mfrom (pid=20107)
_do_build_and_run_instance /opt/stack/no
va/nova/compute/manager.py:1895^[[00m
13258 2016-06-14 18:41:53.072 ^[[00;32mDEBUG nova.network.base_api
[^[[01;36mreq-8d084465-4ed7-440e-b016-6dc7fcc3882b ^[[00;36madmin
admin^[[00;32m] ^[[01;35 m[instance: cf88cb38-e54e-4e19-85ec-d97a03098dfb]
^[[00;32mUpdating instance_info_cache with network_info: [VIF({'profile': {},
'ovs_interfaceid': u'60 5ee23b-66da-4aba-98ee-347008a2a495',
'preserve_on_delete': False, 'network': Network({'bridge': 'br-int', 'subnets':
[Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed',
'floating_ips': [], 'address': u'172.30.100.159'})], 'version': 4, 'meta':
{'dhcp_server': u'172.30.100.100'}, 'dns' : [], 'routes': [], 'cidr':
u'172.30.100.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway',
'address': u'172.30.100.1'})})], 'meta': {' injected': False, 'tenant_id':
u'602ced91cf2c4cd59d86d7bce8b53bdc', 'mtu': 1500}, 'id':
u'3290e2fe-f607-4997-ac14-0d73ef800078', 'label': u'sharednet1' }),
'devname': u'tap605ee23b-66', 'vnic_type': u'normal', 'qbh_params': None,
'meta': {}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True},
'address': u'ec:b1:d7:83:74:43', 'active': False, 'type': u'ovs', 'id':
u'605ee23b-66da-4aba-98ee-347008a2a495', 'qbg_params': None})]^[[00m ^[[00;33mf
rom (pid=20107) update_instance_cache_with_nw_info
/opt/stack/nova/nova/network/base_api.py:43^[[00m
13278 2016-06-14 18:41:53.177 ^[[00;32mDEBUG ironicclient.common.http
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin
admin^[[00;32m] ^[[01 ;35m^[[00;32mError contacting Ironic server: Node
695ae540-83a4-4d06-a17b-02e72c81805a is associated with instance
cf88cb38-e54e-4e19-85ec-d97a03098dfb . (HTTP 409). Attempt 1 of 2^[[00m
^[[00;33mfrom (pid=20107) wrapper
/usr/local/lib/python2.7/dist-packages/ironicclient/common/http.py:200^[[00m
13280 2016-06-14 18:41:53.231 ^[[01;31mERROR nova.compute.manager
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin
admin^[[01;31m] ^[[01;35m [instance: 0b8e174e-5d6a-4976-89f3-47c5554748f0]
^[[01;31mInstance failed to spawn^[[00m
13302 ^[[01;31m2016-06-14 18:41:53.231 TRACE nova.compute.manager
^[[01;35m[instance: 0b8e174e-5d6a-4976-89f3-47c5554748f0] ^[[00mConflict: Node
695ae540-83a 4-4d06-a17b-02e72c81805a is associated with instance
cf88cb38-e54e-4e19-85ec-d97a03098dfb. (HTTP 409)
13336 2016-06-14 18:41:53.576 ^[[00;32mDEBUG nova.compute.manager
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin
admin^[[00;32m] ^[[01;35m [instance: 0b8e174e-5d6a-4976-89f3-47c5554748f0]
^[[00;32mBuild of instance 0b8e174e-5d6a-4976-89f3-47c5554748f0 was
re-scheduled: Node 695ae540-83a4-4 d06-a17b-02e72c81805a is associated
with instance cf88cb38-e54e-4e19-85ec-d97a03098dfb. (HTTP 409)^[[00m
^[[00;33mfrom (pid=20107) _do_build_and_run_in stance
/opt/stack/nova/nova/compute/manager.py:1943^[[00m
13357 2016-06-14 18:41:53.855 ^[[00;32mDEBUG nova.compute.manager
[^[[01;36mreq-709fdcfe-a0ed-4ab5-ae4d-cd06109d9598 ^[[00;36madmin
admin^[[00;32m] ^[[01;35m [instance: 181593eb-a85e-4118-ae37-7f9204011631]
^[[00;32mStart spawning the instance on the hypervisor.^[[00m ^[[00;33mfrom
(pid=20107) _build_and_run _instance
/opt/stack/nova/nova/compute/manager.py:2057^[[00m
13366 2016-06-14 18:41:54.062 ^[[00;32mDEBUG nova.virt.ironic.driver
[^[[01;36mreq-8d084465-4ed7-440e-b016-6dc7fcc3882b ^[[00;36madmin
admin^[[00;32m] ^[[01; 35m^[[00;32mplug:
instance_uuid=cf88cb38-e54e-4e19-85ec-d97a03098dfb vif=[VIF({'profile': {},
'ovs_interfaceid': u'605ee23b-66da-4aba-98ee-347008a2a495 ',
'preserve_on_delete': False, 'network': Network({'bridge': 'br-int', 'subnets':
[Subnet({'ips': [FixedIP({'meta': {}, 'version': 4, 'type': 'fixed',
'floating_ips': [], 'address': u'172.30.100.159'})], 'version': 4, 'meta':
{'dhcp_server': u'172.30.100.100'}, 'dns': [], 'routes': [], 'cidr': u'172.
30.100.0/24', 'gateway': IP({'meta': {}, 'version': 4, 'type': 'gateway',
'address': u'172.30.100.1'})})], 'meta': {'injected': False, 'tenant_id': u'6
02ced91cf2c4cd59d86d7bce8b53bdc', 'mtu': 1500}, 'id':
u'3290e2fe-f607-4997-ac14-0d73ef800078', 'label': u'sharednet1'}), 'devname':
u'tap605ee23b-66', 'vnic_type': u'normal', 'qbh_params': None, 'meta':
{}, 'details': {u'port_filter': True, u'ovs_hybrid_plug': True}, 'address':
u'ec:b1:d7:83:74:43', ' active': False, 'type': u'ovs', 'id':
u'605ee23b-66da-4aba-98ee-347008a2a495', 'qbg_params': None})]^[[00m
^[[00;33mfrom (pid=20107) _plug_vifs /opt/st
ack/nova/nova/virt/ironic/driver.py:998^[[00m
13381 2016-06-14 18:41:54.365 ^[[00;36mINFO nova.compute.claims
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin
admin^[[00;36m] ^[[01;35m[i nstance: 0b8e174e-5d6a-4976-89f3-47c5554748f0]
^[[00;36mTotal disk: 557 GB, used: 0.00 GB^[[00m
13382 2016-06-14 18:41:54.368 ^[[00;36mINFO nova.compute.claims
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin
admin^[[00;36m] ^[[01;35m[i nstance: 0b8e174e-5d6a-4976-89f3-47c5554748f0]
^[[00;36mdisk limit: 557.00 GB, free: 557.00 GB^[[00m
13422 2016-06-14 18:41:54.953 ^[[00;32mDEBUG nova.compute.manager
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin
admin^[[00;32m] ^[[01;35m [instance: 0b8e174e-5d6a-4976-89f3-47c5554748f0]
^[[00;32mStart spawning the instance on the hypervisor.^[[00m ^[[00;33mfrom
(pid=20107) _build_and_run _instance
/opt/stack/nova/nova/compute/manager.py:2057^[[00m
13424 2016-06-14 18:41:55.105 ^[[01;31mERROR nova.compute.manager
[^[[01;36mreq-709fdcfe-a0ed-4ab5-ae4d-cd06109d9598 ^[[00;36madmin
admin^[[01;31m] ^[[01;35m ^[[01;31mInstance failed network setup after 1
attempt(s)
13438 ^[[01;31m2016-06-14 18:41:55.105 TRACE nova.compute.manager
^[[01;35m^[[00mPortBindingFailed: Binding failed for port
2cc0584b-d9fd-47fa-96c4-2b89a046b 43b, please check neutron logs for more
information.
13461 PortBindingFailed: Binding failed for port
2cc0584b-d9fd-47fa-96c4-2b89a046b43b, please check neutron logs for more
information.
13502 2016-06-14 18:41:56.313 ^[[01;31mERROR nova.virt.ironic.driver
[^[[01;36mreq-709fdcfe-a0ed-4ab5-ae4d-cd06109d9598 ^[[00;36madmin a
dmin^[[01;31m] ^[[01;35m^[[01;31mError preparing deploy for instance
181593eb-a85e-4118-ae37-7f9204011631 on baremetal node 667131
4c-12a6-4090-85dc-2d1882188af0.^[[00m
13548 ^[[01;31m2016-06-14 18:41:56.314 TRACE nova.compute.manager ^[[01;35m,
please check neutron logs for more information.
13549 ^[[01;31m2016-06-14 18:41:56.314 TRACE nova.compute.manager
^[[01;35m[instance: 181593eb-a85e-4118-ae37-7f9204011631]
13595 2016-06-14 18:41:57.431 ^[[01;31mERROR nova.compute.manager
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin admi
n^[[01;31m] ^[[01;35m[instance: 0b8e174e-5d6a-4976-89f3-47c5554748f0]
^[[01;31mInstance failed to spawn^[[00m
13639 ^[[01;31m2016-06-14 18:41:57.431 TRACE nova.compute.manager
^[[01;35m[instance: 0b8e174e-5d6a-4976-89f3-47c5554748f0] ^[[00mPortBi
ndingFailed: Binding failed for port b57e053b-8da2-4856-8b96-d209f229be72,
please check neutron logs for more information.
13646 2016-06-14 18:41:57.457 ^[[00;36mINFO nova.virt.ironic.driver
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin ad
min^[[00;36m] ^[[01;35m[instance: 0b8e174e-5d6a-4976-89f3-47c5554748f0]
Successfully unprovisioned Ironic node 9bf2b3ba-d
62d-4e3f-8c39-df174b786749^[[00m
13665 2016-06-14 18:41:57.841 ^[[00;32mDEBUG nova.compute.manager
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin admi
n^[[00;32m] ^[[01;35m[instance: 0b8e174e-5d6a-4976-89f3-47c5554748f0]
^[[00;32mBuild of instance 0b8e174e-5d6a-4976-89f3-47c555474 8f0 was
re-scheduled: Binding failed for port b57e053b-8da2-4856-8b96-d209f229be72,
please check neutron logs for more information .^[[00m ^[[00;33mfrom
(pid=20107) _do_build_and_run_instance
/opt/stack/nova/nova/compute/manager.py:1943^[[00m
13695 2016-06-14 18:41:58.450 ^[[00;36mINFO nova.compute.claims
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin admin^
[[00;36m] ^[[01;35m[instance: 0b8e174e-5d6a-4976-89f3-47c5554748f0]
^[[00;36mTotal disk: 68 GB, used: 0.00 GB
13728 2016-06-14 18:41:59.320 ^[[01;31mERROR ironicclient.common.http
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin
admin^[[01;31m] ^[[01;35m^[[01;31mError contacting Ironic server: Node
6671314c-12a6-4090-85dc-2d1882188af0 is associated with ins tance
181593eb-a85e-4118-ae37-7f9204011631. (HTTP 409). Attempt 2 of 2^[[00m
13729 2016-06-14 18:41:59.321 ^[[01;31mERROR nova.compute.manager
[^[[01;36mreq-885b8ffc-d8a5-449c-a31e-335e88d2b839 ^[[00;36madmin admi
n^[[01;31m] ^[[01;35m[instance: 0b8e174e-5d6a-4976-89f3-47c5554748f0]
^[[01;31mInstance failed to spawn
13751 ^[[01;31m2016-06-14 18:41:59.321 TRACE nova.compute.manager
^[[01;35m[instance: 0b8e174e-5d6a-4976-89f3-47c5554748f0] ^[[00mConfli ct:
Node 6671314c-12a6-4090-85dc-2d1882188af0 is associated with instance
181593eb-a85e-4118-ae37-7f9204011631. (HTTP 409)
13767 ^[[01;31m2016-06-14 18:42:00.136 TRACE nova.compute.manager
^[[01;35m^[[00mPortBindingFailed: Binding failed for port 31b1745a-61b
6-46b1-b6d0-b93c08107d01, please check neutron logs for more information.
---------------------- end of n-cpu.log ----------------------
Regards,
Gary
_______________________________________________
Mailing list: http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack
Post to : openstack@lists.openstack.org
Unsubscribe : http://lists.openstack.org/cgi-bin/mailman/listinfo/openstack
