OpenStack Compute (nova)

starting multiple VMs causes some to be stuck in BUILDING

Bug #1051066 reported by Joe Gordon on 2012-09-14

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	OpenStack Compute (nova)	Fix Released	Critical	Vish Ishaya	OpenStack Compute (nova) 2012.2 "folsom"

Bug Description

It appears some of the VMs are not getting private IPs.

From Devstack:

vagrant@precise:~/devstack$ euca-run-instances ami-00000001 -t m1.tiny -n 8
RESERVATION r-fv50jn6l ecb58b362a9845fea121c8b5f6f30f6c default
INSTANCE i-00000037 ami-00000001 server-c23963ad-2be5-4415-a3d1-51dbac1257a4 server-c23963ad-2be5-4415-a3d1-51dbac1257a4 pending None (ecb58b362a9845fea121c8b5f6f30f6c, None) 0 m1.tiny 2012-09-14T20:17:26.000Z unknown zone aki-00000002 ari-00000003 monitoring-disabled instance-store
INSTANCE i-00000038 ami-00000001 server-35618d88-47ce-450c-8e27-903cc41e5c43 server-35618d88-47ce-450c-8e27-903cc41e5c43 pending None (ecb58b362a9845fea121c8b5f6f30f6c, None) 0 m1.tiny 2012-09-14T20:17:26.000Z unknown zone aki-00000002 ari-00000003 monitoring-disabled instance-store
INSTANCE i-00000039 ami-00000001 server-41c78a55-2e0f-4807-8698-2612723ed01e server-41c78a55-2e0f-4807-8698-2612723ed01e pending None (ecb58b362a9845fea121c8b5f6f30f6c, None) 0 m1.tiny 2012-09-14T20:17:26.000Z unknown zone aki-00000002 ari-00000003 monitoring-disabled instance-store
INSTANCE i-0000003a ami-00000001 server-3b9cf5af-b1fa-4dba-a497-b3d89dac81ac server-3b9cf5af-b1fa-4dba-a497-b3d89dac81ac pending None (ecb58b362a9845fea121c8b5f6f30f6c, None) 0 m1.tiny 2012-09-14T20:17:26.000Z unknown zone aki-00000002 ari-00000003 monitoring-disabled instance-store
INSTANCE i-0000003b ami-00000001 server-b7be7f0b-2c67-4d20-a790-fd3a578fcb6e server-b7be7f0b-2c67-4d20-a790-fd3a578fcb6e pending None (ecb58b362a9845fea121c8b5f6f30f6c, None) 0 m1.tiny 2012-09-14T20:17:26.000Z unknown zone aki-00000002 ari-00000003 monitoring-disabled instance-store
INSTANCE i-0000003c ami-00000001 server-fccd49bf-2de6-457e-9a19-d2817e9a2cd8 server-fccd49bf-2de6-457e-9a19-d2817e9a2cd8 pending None (ecb58b362a9845fea121c8b5f6f30f6c, None) 0 m1.tiny 2012-09-14T20:17:26.000Z unknown zone aki-00000002 ari-00000003 monitoring-disabled instance-store
INSTANCE i-0000003d ami-00000001 server-2288a020-825d-405a-a7bb-6a6dd1a8a544 server-2288a020-825d-405a-a7bb-6a6dd1a8a544 pending None (ecb58b362a9845fea121c8b5f6f30f6c, None) 0 m1.tiny 2012-09-14T20:17:26.000Z unknown zone aki-00000002 ari-00000003 monitoring-disabled instance-store
INSTANCE i-0000003e ami-00000001 server-e4dc8891-db72-4cc5-8149-75af6c1a1746 server-e4dc8891-db72-4cc5-8149-75af6c1a1746 pending None (ecb58b362a9845fea121c8b5f6f30f6c, None) 0 m1.tiny 2012-09-14T20:17:26.000Z unknown zone aki-00000002 ari-00000003 monitoring-disabled instance-store
vagrant@precise:~/devstack$ nova list
+--------------------------------------+---------------------------------------------+--------+------------------+
| ID | Name | Status | Networks |
+--------------------------------------+---------------------------------------------+--------+------------------+
| 2288a020-825d-405a-a7bb-6a6dd1a8a544 | Server 2288a020-825d-405a-a7bb-6a6dd1a8a544 | BUILD | |
| 35618d88-47ce-450c-8e27-903cc41e5c43 | Server 35618d88-47ce-450c-8e27-903cc41e5c43 | ACTIVE | private=10.0.0.3 |
| 3b9cf5af-b1fa-4dba-a497-b3d89dac81ac | Server 3b9cf5af-b1fa-4dba-a497-b3d89dac81ac | ACTIVE | private=10.0.0.5 |
| 41c78a55-2e0f-4807-8698-2612723ed01e | Server 41c78a55-2e0f-4807-8698-2612723ed01e | ACTIVE | private=10.0.0.4 |
| b7be7f0b-2c67-4d20-a790-fd3a578fcb6e | Server b7be7f0b-2c67-4d20-a790-fd3a578fcb6e | ACTIVE | private=10.0.0.6 |
| c23963ad-2be5-4415-a3d1-51dbac1257a4 | Server c23963ad-2be5-4415-a3d1-51dbac1257a4 | ACTIVE | private=10.0.0.2 |
| e4dc8891-db72-4cc5-8149-75af6c1a1746 | Server e4dc8891-db72-4cc5-8149-75af6c1a1746 | BUILD | |
| fccd49bf-2de6-457e-9a19-d2817e9a2cd8 | Server fccd49bf-2de6-457e-9a19-d2817e9a2cd8 | BUILD | |
+--------------------------------------+---------------------------------------------+--------+------------------+

Revision history for this message

Vish Ishaya (vishvananda) wrote on 2012-09-14:

any traceback?

Changed in nova:
status:	New → Triaged
importance:	Undecided → High
importance:	High → Critical
milestone:	none → folsom-rc1

Revision history for this message

Boris Filippov (bfilippov) wrote on 2012-09-15:

Download full text (9.1 KiB)

Tried to reproduce it on devstack

[karadain@localhost devstack]$ euca-run-instances ami-00000001 -t m1.tiny -n 8
RESERVATION r-7bvqwocx d857f20c4265495bb0fdc43d21d67e36 default
INSTANCE i-0000000a ami-00000001 server-fe6ac7c3-6a64-48f6-8f33-d0cd7de1dc5d server-fe6ac7c3-6a64-48f6-8f33-d0cd7de1dc5d pending 0 m1.tiny 2012-09-15T13:30:38.000Z unknown zone aki-00000002 ari-00000003
INSTANCE i-0000000b ami-00000001 server-2169a834-a050-4c1f-84ee-8e664b36d9c2 server-2169a834-a050-4c1f-84ee-8e664b36d9c2 pending 0 m1.tiny 2012-09-15T13:30:39.000Z unknown zone aki-00000002 ari-00000003
INSTANCE i-0000000c ami-00000001 server-11f9ff3a-593d-482d-88b3-b20ff55e04a9 server-11f9ff3a-593d-482d-88b3-b20ff55e04a9 pending 0 m1.tiny 2012-09-15T13:30:39.000Z unknown zone aki-00000002 ari-00000003
INSTANCE i-0000000d ami-00000001 server-9938ecfb-a124-4e79-8790-1b1974c08fc2 server-9938ecfb-a124-4e79-8790-1b1974c08fc2 pending 0 m1.tiny 2012-09-15T13:30:39.000Z unknown zone aki-00000002 ari-00000003
INSTANCE i-0000000e ami-00000001 server-0541c3b2-11d1-46b4-9334-45ec47ac70ef server-0541c3b2-11d1-46b4-9334-45ec47ac70ef pending 0 m1.tiny 2012-09-15T13:30:39.000Z unknown zone aki-00000002 ari-00000003
INSTANCE i-0000000f ami-00000001 server-e940f970-980e-4804-85b6-1f1ad6eb1153 server-e940f970-980e-4804-85b6-1f1ad6eb1153 pending 0 m1.tiny 2012-09-15T13:30:39.000Z unknown zone aki-00000002 ari-00000003
INSTANCE i-00000010 ami-00000001 server-6e399d2d-d471-4672-becc-499a4130ffc8 server-6e399d2d-d471-4672-becc-499a4130ffc8 pending 0 m1.tiny 2012-09-15T13:30:39.000Z unknown zone aki-00000002 ari-00000003
INSTANCE i-00000011 ami-00000001 server-c91fee0d-4ccd-4386-8729-214529e25119 server-c91fee0d-4ccd-4386-8729-214529e25119 pending 0 m1.tiny 2012-09-15T13:30:39.000Z unknown zone aki-00000002 ari-00000003

Tried to reproduce it on devstack

[karadain@localhost devstack]$ euca-run-instances ami-00000001 -t m1.tiny -n 8
RESERVATION	r-7bvqwocx	d857f20c4265495bb0fdc43d21d67e36	default
INSTANCE	i-0000000a	ami-00000001	server-fe6ac7c3-6a64-48f6-8f33-d0cd7de1dc5d	server-fe6ac7c3-6a64-48f6-8f33-d0cd7de1dc5d	pending		0		m1.tiny	2012-09-15T13:30:38.000Z	unknown zone	aki-00000002	ari-00000003
INSTANCE	i-0000000b	ami-00000001	server-2169a834-a050-4c1f-84ee-8e664b36d9c2	server-2169a834-a050-4c1f-84ee-8e664b36d9c2	pending		0		m1.tiny	2012-09-15T13:30:39.000Z	unknown zone	aki-00000002	ari-00000003
INSTANCE	i-0000000c	ami-00000001	server-11f9ff3a-593d-482d-88b3-b20ff55e04a9	server-11f9ff3a-593d-482d-88b3-b20ff55e04a9	pending		0		m1.tiny	2012-09-15T13:30:39.000Z	unknown zone	aki-00000002	ari-00000003
INSTANCE	i-0000000d	ami-00000001	server-9938ecfb-a124-4e79-8790-1b1974c08fc2	server-9938ecfb-a124-4e79-8790-1b1974c08fc2	pending		0		m1.tiny	2012-09-15T13:30:39.000Z	unknown zone	aki-00000002	ari-00000003
INSTANCE	i-0000000e	ami-00000001	server-0541c3b2-11d1-46b4-9334-45ec47ac70ef	server-0541c3b2-11d1-46b4-9334-45ec47ac70ef	pending		0		m1.tiny	2012-09-15T13:30:39.000Z	unknown zone	aki-00000002	ari-00000003
INSTANCE	i-0000000f	ami-00000001	server-e940f970-980e-4804-85b6-1f1ad6eb1153	server-e940f970-980e-4804-85b6-1f1ad6eb1153	pending		0		m1.tiny	2012-09-15T13:30:39.000Z	unknown zone	aki-00000002	ari-00000003
INSTANCE	i-00000010	ami-00000001	server-6e399d2d-d471-4672-becc-499a4130ffc8	server-6e399d2d-d471-4672-becc-499a4130ffc8	pending		0		m1.tiny	2012-09-15T13:30:39.000Z	unknown zone	aki-00000002	ari-00000003
INSTANCE	i-00000011	ami-00000001	server-c91fee0d-4ccd-4386-8729-214529e25119	server-c91fee0d-4ccd-4386-8729-214529e25119	pending		0		m1.tiny	2012-09-15T13:30:39.000Z	unknown zone	aki-00000002	ari-00000003

In my case, when i looked in scheduler log - i found this:

2012-09-15 18:20:11 DEBUG nova.scheduler.filter_scheduler [req-cd27e6df-deb3-459d-b5ef-18e55ee6eb8f demo demo] Filtered [host 'localhost.localdomain': free_ram_mb:-423 free_disk_mb:57344] from (pid=5001) _sched
ule /opt/stack/nova/nova/scheduler/filter_scheduler.py:261
Filtered [host 'localhost.localdomain': free_ram_mb:-423 free_disk_mb:57344]
2012-09-15 18:20:11 DEBUG nova.scheduler.filter_scheduler [req-cd27e6df-deb3-459d-b5ef-18e55ee6eb8f demo demo] Weighted WeightedHost host: localhost.localdomain from (pid=5001) _schedule /opt/stack/nova/nova/sc
heduler/filter_scheduler.py:271
Weighted WeightedHost host: localhost.localdomain
2012-09-15 18:20:11 DEBUG nova.scheduler.filters.retry_filter [req-cd27e6df-deb3-459d-b5ef-18e55ee6eb8f demo demo] Previously tried hosts: [].  (host=localhost.localdomain) from (pid=5001) host_passes /opt/stac
k/nova/nova/scheduler/filters/retry_filter.py:39
Previously tried hosts: [].  (host=localhost.localdomain)
2012-09-15 18:20:11 DEBUG nova.scheduler.host_manager [req-cd27e6df-deb3-459d-b5ef-18e55ee6eb8f demo demo] Host filter passes for localhost.localdomain from (pid=5001) passes_filters /opt/stack/nova/nova/schedu
ler/host_manager.py:177
Host filter passes for localhost.localdomain
2012-09-15 18:20:11 DEBUG nova.scheduler.filter_scheduler [req-cd27e6df-deb3-459d-b5ef-18e55ee6eb8f demo demo] Filtered [host 'localhost.localdomain': free_ram_mb:-935 free_disk_mb:57344] from (pid=5001) _sched
ule /opt/stack/nova/nova/scheduler/filter_scheduler.py:261
Filtered [host 'localhost.localdomain': free_ram_mb:-935 free_disk_mb:57344]
2012-09-15 18:20:11 DEBUG nova.scheduler.filter_scheduler [req-cd27e6df-deb3-459d-b5ef-18e55ee6eb8f demo demo] Weighted WeightedHost host: localhost.localdomain from (pid=5001) _schedule /opt/stack/nova/nova/sc
heduler/filter_scheduler.py:271
Weighted WeightedHost host: localhost.localdomain
2012-09-15 18:20:11 DEBUG nova.scheduler.filters.retry_filter [req-cd27e6df-deb3-459d-b5ef-18e55ee6eb8f demo demo] Previously tried hosts: [].  (host=localhost.localdomain) from (pid=5001) host_passes /opt/stac
k/nova/nova/scheduler/filters/retry_filter.py:39
Previously tried hosts: [].  (host=localhost.localdomain)
2012-09-15 18:20:11 DEBUG nova.scheduler.filters.ram_filter [req-cd27e6df-deb3-459d-b5ef-18e55ee6eb8f demo demo] host 'localhost.localdomain': free_ram_mb:-1447 free_disk_mb:57344 does not have 512 MB usable ram, it only has 266.0 MB usable ram. from (pid=5001) host_passes /opt/stack/nova/nova/scheduler/filters/ram_filter.py:49
host 'localhost.localdomain': free_ram_mb:-1447 free_disk_mb:57344 does not have 512 MB usable ram, it only has 266.0 MB usable ram.
2012-09-15 18:20:11 DEBUG nova.scheduler.host_manager [req-cd27e6df-deb3-459d-b5ef-18e55ee6eb8f demo demo] Host filter function <bound method RamFilter.host_passes of <nova.scheduler.filters.ram_filter.RamFilter object at 0x41f4bd0>> failed for localhost.localdomain from (pid=5001) passes_filters /opt/stack/nova/nova/scheduler/host_manager.py:174
Host filter function <bound method RamFilter.host_passes of <nova.scheduler.filters.ram_filter.RamFilter object at 0x41f4bd0>> failed for localhost.localdomain

Scheduler schedule instances one by one until compute node runs out of free RAM, then it report about failure, but don't set remaining instances in ERROR state.

Then I created a flavor only with 256 MB RAM, and all things go smoothly:

[karadain@localhost devstack]$ nova flavor-list
+----+-------------+-----------+------+-----------+------+-------+-------------+-----------+
| ID | Name        | Memory_MB | Disk | Ephemeral | Swap | VCPUs | RXTX_Factor | Is_Public |
+----+-------------+-----------+------+-----------+------+-------+-------------+-----------+
| 1  | m1.tiny     | 512       | 0    | 0         |      | 1     | 1.0         | True      |
| 2  | m1.small    | 2048      | 20   | 0         |      | 1     | 1.0         | True      |
| 3  | m1.medium   | 4096      | 40   | 0         |      | 2     | 1.0         | True      |
| 4  | m1.large    | 8192      | 80   | 0         |      | 4     | 1.0         | True      |
| 5  | m1.xlarge   | 16384     | 160  | 0         |      | 8     | 1.0         | True      |
| 6  | m1.verytiny | 256       | 0    | 0         |      | 1     | 1.0         | True      |
+----+-------------+-----------+------+-----------+------+-------+-------------+-----------+

Author use vagrant_devstack in original report, and as I remember it has not much RAM for instance in vagrant file by default. Maybe this is the case?

Revision history for this message

Joe Gordon (jogo) wrote on 2012-09-17:

When I run a single VM at a time I can spawn 8, but when I run all 8 at once some fail:

http://paste.openstack.org/show/20957/

This appears to be related to how the free_ram_mb is now updated dynamically from the compute node (not just based on a deterministic calculation). So when another VM is about to start the amount of free memory drops causing the other VMs to fail to start.

In the past the ram information was derived from a deterministic calculation, and now a non-deterministic formula is used.

Revision history for this message

Joe Gordon (jogo) wrote on 2012-09-17:

While the non-deterministic approach may allow for higher usage, it is much harder to debug. Where running the same command twice gives different results

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2012-09-17: Fix proposed to nova (master)

Fix proposed to branch: master
Review: https://review.openstack.org/13159

Changed in nova:
assignee:	nobody → Vish Ishaya (vishvananda)
status:	Triaged → In Progress

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2012-09-17:

Fix proposed to branch: master
Review: https://review.openstack.org/13172

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2012-09-18: Fix merged to nova (master)

Reviewed: https://review.openstack.org/13159
Committed: http://github.com/openstack/nova/commit/91734bad9139555294fe088d2c2d77a9712652ab
Submitter: Jenkins
Branch: master

commit 91734bad9139555294fe088d2c2d77a9712652ab
Author: Vishvananda Ishaya <email address hidden>
Date: Mon Sep 17 16:02:06 2012 -0700

Fixes error handling during schedule_run_instance

    If there are not enough hosts available during a multi-instance launch,
    every failing instance should be updated to error state, instead of
    just the first instance. Currently only the first instance is set
    to Error and the rest stay in building.

This patch makes a number of fixes to error handling during scheduling.

     * Moves instance faults into compute utils so they can be created
       from the scheduler.
     * Moves error handling into the driver so that each instance can be
       updated separately.
     * Sets an instance fault for failed scheduling
     * Sets task state back to none if there is a scheduling failure
     * Modifies chance scheduler to stop returning a list of instances
       as it is not used.
     * Modifies tests to check for these states.

In addition to the included tests, the code was manually verified on
a devstack install

Fixes bug 1051066
Fixes bug 1019017

Change-Id: I49267ce4a21e2f7cc7a996fb2ed5d625f6794730

Changed in nova:
status:	In Progress → Fix Committed

Thierry Carrez (ttx) on 2012-09-19

Changed in nova:
status:	Fix Committed → Fix Released

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2012-09-19:

Reviewed: https://review.openstack.org/13172
Committed: http://github.com/openstack/nova/commit/0cba85cb267994018c8a0d5e40b2ed0b5a7837df
Submitter: Jenkins
Branch: master

commit 0cba85cb267994018c8a0d5e40b2ed0b5a7837df
Author: Vishvananda Ishaya <email address hidden>
Date: Mon Sep 17 16:09:41 2012 -0700

Improve error handling of scheduler

Modifies scheduler errors to report instance faults and to set
instance_state back to None on failure.

Related to bug 1051066

Change-Id: Id9f36a75370849db7baf3fe24ce96c6f4284255d

Changed in nova:
status:	Fix Released → Fix Committed

Thierry Carrez (ttx) on 2012-09-19

Changed in nova:
status:	Fix Committed → Fix Released

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2012-09-19: Fix proposed to nova (milestone-proposed)

Fix proposed to branch: milestone-proposed
Review: https://review.openstack.org/13294

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2012-09-20: Fix merged to nova (milestone-proposed)

#10

Reviewed: https://review.openstack.org/13294
Committed: http://github.com/openstack/nova/commit/47e606a95a3a6396e30c825cd6ff913613a85b06
Submitter: Jenkins
Branch: milestone-proposed

commit 47e606a95a3a6396e30c825cd6ff913613a85b06
Author: Vishvananda Ishaya <email address hidden>
Date: Mon Sep 17 16:09:41 2012 -0700

Improve error handling of scheduler

Modifies scheduler errors to report instance faults and to set
instance_state back to None on failure.

Related to bug 1051066
Fixes bug 1052993

Change-Id: Id9f36a75370849db7baf3fe24ce96c6f4284255d
(cherry picked from commit 0cba85cb267994018c8a0d5e40b2ed0b5a7837df)

Thierry Carrez (ttx) on 2012-09-27

Changed in nova:
milestone:	folsom-rc1 → 2012.2

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.