| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-07-25 | |||
| 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 | |
| 23:15:08 | eandersson | And this is from a normal failure | |
| 23:15:11 | eandersson | > Setting instance to ERROR state.: MaxRetriesExceeded: Exceeded maximum number of retries. | |
| 23:17:00 | mriedem | yeah that's this https://opendev.org/openstack/nova/src/branch/master/nova/scheduler/utils.py#L730 | |
| 23:17:10 | mriedem | called from https://github.com/openstack/nova/blob/stable/rocky/nova/conductor/manager.py#L619 | |
| 23:17:22 | mriedem | the instance change should be saved here https://opendev.org/openstack/nova/src/branch/master/nova/scheduler/utils.py#L736 | |
| 23:19:32 | sean-k-mooney | right but in the case where it remains in building we get Exception during message handling:... instead of Setting instance to ERROR state.:... | |
| 23:19:50 | sean-k-mooney | eandersson: is ^ correct | |
| 23:19:54 | eandersson | https://opendev.org/openstack/oslo.messaging/src/branch/master/oslo_messaging/rpc/server.py#L174 | |
| 23:20:03 | eandersson | This could be anything :'( | |
| 23:23:28 | sean-k-mooney | eandersson: it might be good to check your rabbitmq server logs and see if there are any errors | |
| 23:23:46 | sean-k-mooney | although i honestly dont really know how that code works | |
| 23:24:04 | eandersson | http://paste.openstack.org/show/754875/ | |
| 23:24:15 | eandersson | sean-k-mooney, I honestly don't think it's a rmq issue directly | |
| 23:25:00 | sean-k-mooney | ok its unlikely that its related to that placement error | |
| 23:25:17 | sean-k-mooney | that should happen before we try to build the instace | |
| 23:25:29 | eandersson | That log was from the same milisecond | |