| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-07-25 | |||
| 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 | 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: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: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 | |
| 23:25:58 | eandersson | I found two Messaging errors and both are the same issue | |
| 23:26:00 | sean-k-mooney | its posible that we only have 1 candiate host | |
| 23:26:06 | sean-k-mooney | and that we raced | |
| 23:26:10 | eandersson | Other than that no other oslo messaging issues | |
| 23:26:27 | sean-k-mooney | as a result of the fact overcommit is not working | |
| 23:26:41 | eandersson | If there was a rmq issue I am sure other services or request would have failed | |
| 23:26:56 | sean-k-mooney | neutron would be the first | |
| 23:26:57 | eandersson | We have a pretty massive deployment so always a lot of things going on | |
| 23:27:18 | sean-k-mooney | althogh they have redused the rpc traffic a lot in the last releae or two | |
| 23:29:59 | sean-k-mooney | oh the same message is also logged form here https://github.com/openstack/nova/blob/stable/rocky/nova/conductor/manager.py#L676 | |
| 23:30:04 | artom | Heh, for what it's worth, that per-compute libvirt connection mocking has issues: | |
| 23:30:08 | artom | " 2019-07-25 19:29:16,889 ERROR [nova.virt.libvirt.host] Hostname has changed from test_compute0 to test_compute1. A restart is required to take effect." | |
| 23:30:10 | sean-k-mooney | the other place was teh cellv1 version | |
| 23:31:18 | sean-k-mooney | actully never bind its the same function | |
| 23:33:17 | sean-k-mooney | so if this is a retry then we are executing https://github.com/openstack/nova/blob/stable/rocky/nova/conductor/manager.py#L642-L676 | |
| 23:34:08 | sean-k-mooney | and on line 655 we are trying to calim the alternate hosts which is failing with http://paste.openstack.org/show/754875/ because overcommit is not working | |
| 23:34:54 | eandersson | Yea pretty sure the error is within oslo.messaging | |
| 23:35:16 | sean-k-mooney | it might not be | |
| 23:35:25 | sean-k-mooney | when we rais the excetip form here https://github.com/openstack/nova/blob/stable/rocky/nova/conductor/manager.py#L676 | |