| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-07-25 | |||
| 22:29:11 | eandersson | > There was a conflict when trying to complete your request.\n\n Unable to allocate inventory: Unable to create allocation for | |
| 22:29:13 | eandersson | > MaxRetriesExceeded: Exceeded maximum number of retries. Exhausted all hosts available for retrying build failures for instance | |
| 22:29:35 | eandersson | Hit a scheduling race condition which is fine, but then just got stuck (never into an error'd state) | |
| 22:29:44 | sean-k-mooney | it should not get stuc indefinetly and go to an error state | |
| 22:29:58 | eandersson | Yea - exactly | |
| 22:30:26 | eandersson | We have seen this a few times when something like Senlin is aggressively scaling up | |
| 22:31:25 | eandersson | And of course Senlin is unhappy because it just sits there waiting for it to go into ACTIVE (or ERROR'd) state. | |
| 22:31:29 | sean-k-mooney | if you are using any numa related resouces like hugepages or cpu pinning or if you are using sriov/pci passthough these are not tracked in placenet so if you have more then 1 schduler with more then 1 worker they can race | |
| 22:31:49 | eandersson | Yea - that is exactly it. | |
| 22:32:49 | eandersson | We are fine with it failing due to the race condition. | |
| 22:33:00 | sean-k-mooney | if we make it to 2020 then this should be fixed in U when all that stuff is in placmenet. but back to your current problem are there any error in the conductor that could indicate why the instance was not put into error state | |
| 22:33:20 | eandersson | Nope just the above errors. | |
| 22:34:27 | eandersson | Starts with the expected | |
| 22:34:29 | eandersson | > Free vcpu 0.00 VCPU < requested 20 VCPU | |
| 22:34:51 | sean-k-mooney | what release are you running? | |
| 22:35:26 | sean-k-mooney | this is where that error is being raised by the way https://github.com/openstack/nova/blob/3370f0f03ce17aaf3a7ebaa95d497f62bef238c0/nova/conductor/manager.py#L630 | |
| 22:35:31 | eandersson | Rocky | |
| 22:35:58 | sean-k-mooney | have you disabled the core,ram and disk filters | |
| 22:36:04 | eandersson | We have not | |
| 22:36:25 | sean-k-mooney | http://lists.openstack.org/pipermail/openstack-dev/2018-January/126283.html | |
| 22:36:38 | sean-k-mooney | they have been deprecated and should not be enabled after ocata | |
| 22:37:30 | sean-k-mooney | we stopped reporting the info it used i think in rocky or stien | |
| 22:38:02 | sean-k-mooney | so it might not have been a race we could have elimiated all the host because the filter did not work | |
| 22:40:40 | eandersson | I feel like that would have been a more visible problem thou | |
| 22:40:54 | eandersson | We are seeing this happen in %0.1> | |
| 22:41:15 | sean-k-mooney | ya i think if we got to this part of the code its not the filters | |
| 22:41:34 | sean-k-mooney | you should turn them off however as they will break when you upgade to stien | |
| 22:42:23 | sean-k-mooney | so after we log that message we shoudl raise here https://github.com/openstack/nova/blob/stable/rocky/nova/conductor/manager.py#L601 | |
| 22:42:50 | sean-k-mooney | and end up just below it here https://github.com/openstack/nova/blob/stable/rocky/nova/conductor/manager.py#L615 | |
| 22:43:22 | sean-k-mooney | at which port we shoudl notify that the vm state should be error | |
| 22:47:39 | sean-k-mooney | https://github.com/openstack/nova/blob/stable/rocky/nova/scheduler/utils.py#L573 is where teh exception is being loged as a waning | |
| 22:47:54 | sean-k-mooney | and we do an instance.save right after it | |
| 22:48:19 | sean-k-mooney | that save should have updated the instance to error | |
| 22:48:49 | eandersson | Does overcommit no longer work in aggregates? | |
| 22:49:10 | sean-k-mooney | we broke that | |
| 22:49:29 | sean-k-mooney | in ocata | |
| 22:51:30 | sean-k-mooney | from ocata on you need to set the overcommit per node | |
| 22:51:37 | sean-k-mooney | in stien we implemneted https://github.com/openstack/nova-specs/blob/master/specs/stein/implemented/initial-allocation-ratios.rst | |
| 22:51:56 | sean-k-mooney | which allow you to manage allocation ratios directly via placement | |
| 22:52:09 | sean-k-mooney | and only specifiy an initall option in teh config | |
| 22:53:21 | sean-k-mooney | eandersson: but yes that is why melwitt sent http://lists.openstack.org/pipermail/openstack-dev/2018-January/126283.html and why we deprecated teh core,ram and disk filters and there aggrate* conterparts | |
| 22:56:11 | eandersson | We might have placement slightly misconfigured | |
| 22:57:26 | mriedem | https://docs.openstack.org/nova/latest/admin/configuration/schedulers.html#allocation-ratios on the scheduler allocation ratio + placement config stuff | |
| 22:57:48 | mriedem | the initial* options are only new in stein | |
| 22:57:52 | mriedem | so that doesn't help you in rocky | |
| 22:58:31 | sean-k-mooney | eandersson: in rocky the nova compute agent will continuoly set the ratios back to whatever is in the compute node config | |
| 22:58:32 | melwitt | eandersson: >= ocata there's no notion of a per aggregate allocation ratio. so you have to set them separately per compute host nova.conf | |
| 22:58:32 | mriedem | you can either override allocation ratios per compute or override the providers in placement...but i think compute will overwrite anything you set out of band | |
| 22:58:38 | sean-k-mooney | or use the defualt in code if not set | |
| 22:59:08 | eandersson | We set the computes wrong for non-overcommited at the moment | |
| 22:59:17 | eandersson | That could be causing the issue | |
| 22:59:45 | mriedem | note that you might not even be getting this far https://github.com/openstack/nova/blob/stable/rocky/nova/conductor/manager.py#L619 | |
| 22:59:51 | sean-k-mooney | its tricky becaue it will inially appar to work fine until you start filling your hosts | |
| 22:59:56 | mriedem | ^ is only if you hit a primary host, it fails and you reschedule | |
| 23:00:08 | mriedem | if initial scheduling fails, you should get NoValidHost and the instances should be put into ERROR status | |
| 23:00:59 | mriedem | if initial scheduling fails, you should go here https://github.com/openstack/nova/blob/stable/rocky/nova/conductor/manager.py#L1240 | |
| 23:01:04 | mriedem | and the instances go into cell0 with ERROR status | |
| 23:01:14 | mriedem | if your nova_cell0 db fell over then you're missing some updates... | |
| 23:01:15 | eandersson | > | OS-EXT-STS:task_state | scheduling | |
| 23:01:16 | eandersson | > | OS-EXT-STS:vm_state | building | |
| 23:01:22 | eandersson | It was stuck like this until we deleted btw | |
| 23:01:28 | eandersson | 12 hours later | |
| 23:01:36 | mriedem | was the instance ever reported as being on a host? | |
| 23:01:38 | mriedem | or in cell0? | |
| 23:01:53 | sean-k-mooney | mriedem: for some reason that is not happening and the error eandersson is seeing is loged form here https://github.com/openstack/nova/blob/stable/rocky/nova/scheduler/utils.py#L573 | |
| 23:01:57 | eandersson | It tried to schedule, but the moment it did it failed with | |
| 23:01:58 | eandersson | > Free vcpu 0.00 VCPU < requested 20 VCPU | |
| 23:02:00 | mriedem | if something fell over in conductor, like the db insert/update, you should have had error logs | |
| 23:02:21 | mriedem | sean-k-mooney: that utils code is called from multple places in conductor | |
| 23:02:22 | eandersson | Only other time I have seen this happen was when we moved nova-conductor to a new host | |
| 23:02:34 | eandersson | and forgot that the db is configured in mysql | |
| 23:02:38 | sean-k-mooney | yes | |
| 23:02:42 | mriedem | sean-k-mooney: https://github.com/openstack/nova/blob/stable/rocky/nova/conductor/manager.py#L1205 | |
| 23:02:51 | sean-k-mooney | i tracked it from here https://github.com/openstack/nova/blob/stable/rocky/nova/conductor/manager.py#L601 | |
| 23:02:57 | sean-k-mooney | based on teh message that was loged | |
| 23:03:33 | mriedem | ok i think i've reported a bug that we could be failing to set instances to ERROR in build_instances if something fails, i remember talking with gibi about it | |
| 23:03:47 | melwitt | +1 look for db-related errors in the log. that is how I've seen other situations internally where instance got stuck in building/scheduling state | |
| 23:04:18 | sean-k-mooney | eandersson are you seeing the "'Setting instance to %s state.'" message | |
| 23:04:53 | eandersson | Does that have the instance uuid? | |
| 23:04:59 | sean-k-mooney | yes | |
| 23:05:13 | mriedem | rpc could have also fallen over | |
| 23:05:15 | eandersson | Then no | |
| 23:05:31 | sean-k-mooney | mriedem: right that is the only thing between those two lines that could fail | |
| 23:05:33 | mriedem | in that case you'd probably have MessagingTimeouts for the db save rpc calls | |
| 23:06:52 | eandersson | I have 1-2 MySQL server has gone away in the logs, but nothing near the time that happened | |
| 23:07:18 | eandersson | (also those only failed on select 1) | |
| 23:07:22 | sean-k-mooney | well i was wondering if the notifier = rpc.get_notifier(service) line is where it stoped | |
| 23:07:34 | sean-k-mooney | so it might not be related to the db | |
| 23:07:36 | sean-k-mooney | but to rabbit | |
| 23:09:11 | eandersson | hmm does placement do rpc? | |
| 23:09:20 | eandersson | or would this be within nova only? | |
| 23:09:25 | sean-k-mooney | this is in nova | |
| 23:09:30 | sean-k-mooney | in the conductor | |
| 23:09:42 | sean-k-mooney | and no placment does not do any rpc as far as i am aware | |
| 23:10:14 | sean-k-mooney | its just a wsgi app in front of a db | |
| 23:10:42 | eandersson | One thing I don't like with oslo.messaging is that it ack's the message before it gets processed | |
| 23:14:24 | eandersson | oh | |
| 23:14:26 | eandersson | > Exception during message handling | |
| 23:14:46 | eandersson | > Exception during message handling: MaxRetriesExceeded: Exceeded maximum number of retries. | |
| 23:15:02 | eandersson | That is the error I posted above | |