| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-07-25 | |||
| 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 | |
| 23:35:33 | sean-k-mooney | it is not caut locally in this funciton | |
| 23:35:33 | eandersson | oh | |
| 23:39:17 | sean-k-mooney | i should proably go to bed but there is likely a bug there but im to tired to track it this evening | |
| 23:40:04 | mnaser | efried: i think you were working on moving nova to use openstacksdk ? do you have some of the commit you did in nova that did that? trying to do something similar for another project | |
| 23:42:19 | eandersson | Thanks for the help sean-k-mooney | |
| 23:42:24 | eandersson | I'll create a bug report | |
| 23:42:46 | gmann | johnthetubaguy: melwitt sean-k-mooney efried added my comment/query on unified limit spec. I am not very clear about how we will handle GET for limits which are not going to move to new unified limits(for example server_groups). | |
| 23:43:29 | gmann | I am almost ok for proxy APIs (as per operators interest) if HTTPGone on those APIs is not acceptable. | |
| 23:45:35 | melwitt | gmann: thanks for reviewing. I am not 100% operators would be opposed to having to use an older microversion to use the APIs *but* I think the thing that makes it weird is that unified limits would be opt-in. so that is where I'm uneasy with removing proxy API in new microversion. wanted your opinion on that aspect as well | |
| 23:50:17 | gmann | melwitt: 'removing proxy API in new microversion' and keep them working for older one seems no benefit and even more maintenance. I was thinking we say those APIs are gone (410 response code HTTPGone) because nova quota system is gone and without microversion bump. similar approach as nova-network & n-cert case. | |
| 23:51:16 | gmann | and before we do that we can trigger the notification to users via deprecating those APIs | |
| 23:51:29 | melwitt | gmann: oh, sorry, I didn't know HTTPGone is different. my bad | |
| 23:52:07 | melwitt | yeah, I'd like to be able to do that but wasn't sure about the API perspective of deprecating something when the new thing is opt-in and not on by default | |
| 23:52:41 | gmann | melwitt: https://github.com/openstack/nova/blob/master/nova/api/openstack/compute/floating_ip_dns.py#L25 | |
| 23:53:02 | openstack | Launchpad bug 1837955 in OpenStack Compute (nova) "MaxRetriesExceeded sometime fails with messaging exception" [Undecided,New] | |
| 23:53:02 | eandersson | sean-k-mooney, https://bugs.launchpad.net/nova/+bug/1837955 | |
| 23:54:42 | gmann | melwitt: the only things make me feel uncomfortable to do that was the comment johnthetubaguy added in alternate section about Forum discussion with operators about keeping the old tooling. But i hope that is only for transition period not permanently | |