| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-10-17 | |||
| 07:35:11 | gibi | eandersson: do you see logs like " Lock "compute_resources" acquired by "nova.compute.resource_tracker.instance_claim"" ? | |
| 07:36:49 | gibi | or in general any 'Lock "compute_resources"' | |
| 07:36:55 | eandersson | nothing ;'( | |
| 07:41:30 | eandersson | It's possible that the allocations are a legacy of some failed cold migrations tbh | |
| 07:41:46 | eandersson | but not sure why they would cause a deadlock | |
| 07:45:10 | eandersson | nvm the unaccounted for allocation was another vm stuck in bad state | |
| 07:45:15 | eandersson | just forgot --all-projects | |
| 07:46:21 | eandersson | stuck in building for over 24 hours :p | |
| 07:47:20 | eandersson | also nvm the disk allocation issue... my query had LIMIT 10 on it :D | |
| 07:48:08 | eandersson | Let me try to schedule a VM manually to that host and see if it works | |
| 07:54:21 | gibi | eandersson: I suggest to add oslo_concurrency=DEBUG to the [DEFAULT]/default_log_levels config of the nova-compute service because if you see Final resource view logs then you should see logs about the " Lock "compute_resources" as well | |
| 07:54:31 | eandersson | Sure I can do that now | |
| 07:54:39 | eandersson | Can reproduce this issue 100% on this host | |
| 07:55:34 | gibi | so the periodic jobs can run and update the resource view but no new instances get the chance to claim resoruces | |
| 07:57:00 | gibi | both uses the same compute_resources lock so I don't see how one of them can progress and not the other | |
| 07:57:18 | eandersson | > Lock "compute_resources" released by "nova.compute.resource_tracker._update_available_resource" : | |
| 07:57:57 | eandersson | > Running periodic task ComputeManager._poll_unconfirmed_resizes run_periodic_tasks | |
| 07:59:46 | eandersson | > Compute_service record updated for computexxx:computexxx _update_available_resource | |
| 07:59:51 | eandersson | > Lock "compute_resources" released by "nova.compute.resource_tracker._update_available_resource" | |
| 07:59:55 | eandersson | These are the last two lines | |
| 08:00:10 | gibi | eandersson: now when you boot a VM do you see Lock "compute_resources" acquired by "nova.compute.resource_tracker.instance_claim" ? | |
| 08:01:16 | eandersson | I don't see instance_claim | |
| 08:02:18 | gibi | then somehow the build request cannot grab the compute_resources lock | |
| 08:02:47 | eandersson | > > Instance x has been scheduled to this compute host, the scheduler has made an allocation against this compute node but the instance has yet to start. Skipping heal of allocation: | |
| 08:03:00 | eandersson | > _remove_deleted_instances_allocations | |
| 08:04:31 | gibi | eandersson: that is logged because instance.host is not set | |
| 08:06:40 | gibi | eandersson: do you see logs like Lock "805e10fe-2601-4849-9593-3a83f2875bfb" acquired by "nova.compute.manager._locked_do_build_and_run_instance" where the lock name is the uuid of the server being built? | |
| 08:07:17 | eandersson | nothing with locked_do_build | |
| 08:09:17 | gibi | eandersson: do you have max_concurrent_builds configured ? | |
| 08:09:43 | eandersson | nope | |
| 08:12:48 | eandersson | I don't see any lock not getting released | |
| 08:13:38 | eandersson | unless it was held before the vm was created | |
| 08:14:33 | gibi | this is strange. The instance.uuid lock is grabbed here https://github.com/openstack/nova/blob/1a226aaa9e8c969ddfdfe198c36f7966b1f692f3/nova/compute/manager.py#L2039 and inside that lock we set the instance.vm_state from SCHEDULING to BUILDING here https://github.com/openstack/nova/blob/1a226aaa9e8c969ddfdfe198c36f7966b1f692f3/nova/compute/manager.py#L2132 | |
| 08:15:17 | gibi | just to be sure does the instance.vm_state is in BUILDING ? | |
| 08:15:27 | gibi | or it is still in SCHEDULING ? | |
| 08:15:44 | gibi | eandersson: nvm | |
| 08:15:56 | gibi | the SCHEDULING was the task_state | |
| 08:15:58 | eandersson | > OS-EXT-STS:task_state | scheduling | |
| 08:16:04 | eandersson | > OS-EXT-STS:vm_state | building | |
| 08:17:04 | eandersson | btw restarting the nova-compute does nothing | |
| 08:17:22 | eandersson | but deleting the vm works fine | |
| 08:18:25 | gibi | eandersson: if restarting the compute does not fix the issue then it cannot be a lock as that would be cleaned up by the restart. also it cannot be that your compute run out of RPC workers to process incomming messages either | |
| 08:20:10 | gibi | but it feels like the build request does not reach the compute | |
| 08:20:45 | eandersson | I can see the build request in the db at least | |
| 08:21:24 | gibi | eandersson: does other computes using the same message bus (rabbit) work properly? | |
| 08:22:18 | eandersson | yep I see messaging flowing between nova and nova-compute | |
| 08:22:22 | eandersson | queues are all in rabbit | |
| 08:24:00 | eandersson | I could capture the rmq messages to the compute | |
| 08:26:43 | bauzas | good morning Nova | |
| 08:27:40 | bauzas | eandersson: gibi: any logs from the conductor vs. compute showing this ? | |
| 08:28:08 | eandersson | conductor is not in debug so got very little logs there :'( | |
| 08:28:36 | bauzas | eandersson: are you able to follow the req-id down to compute ? | |
| 08:28:51 | bauzas | or as gibi said, nothing there ? | |
| 08:28:57 | jkulik | is it possible to reconfigure the log-level via the eventlet_backdoor? | |
| 08:29:13 | jkulik | just in case it's activated ... | |
| 08:30:28 | jkulik | probably doesn't make sense if it's an old request and can't be reproduced. nevermind. | |
| 08:30:42 | eandersson | I can reproduce this 100% on this compute | |
| 08:31:03 | eandersson | but it's not a dev environment, so can't mess too much | |
| 08:31:57 | eandersson | I have about 10 VMs stuck in this state, so it isn't just one host. | |
| 08:33:17 | eandersson | but this host I am looking into fails 100%, even when specifying the compute using --availability-zone | |
| 08:37:14 | sean-k-mooney | eandersson: are you seeing the compute agent pause for a long peiord when running the update resouces periodic task? | |
| 08:38:24 | eandersson | It does not look like it | |
| 08:39:23 | sean-k-mooney | ok i was wondiering if it was related to libvirt thing we recetly fixed | |
| 08:39:34 | eandersson | That is what I was thinking as well. | |
| 08:39:41 | eandersson | When we started seeing htis. | |
| 08:39:48 | eandersson | I have that build in my lab. | |
| 08:40:05 | eandersson | I assume you are referring to https://review.opendev.org/#/c/687535/ | |
| 08:40:07 | sean-k-mooney | the fix for the eventlet issue with libvirt | |
| 08:40:20 | eandersson | ah not sure about that one | |
| 08:40:22 | eandersson | can you link it? | |
| 08:40:31 | sean-k-mooney | no i was thinkin of something else ya let me find it | |
| 08:40:44 | eandersson | (btw this is with rocky) | |
| 08:42:58 | bauzas | eandersson: sean-k-mooney: if that's a lock issue, the logs will tell it | |
| 08:43:15 | sean-k-mooney | yes it likely unrelated and not backported https://review.opendev.org/#/c/677736/ | |
| 08:43:30 | sean-k-mooney | its not a lock issue | |
| 08:43:37 | bauzas | again, tracking the request-id is super important | |
| 08:43:47 | sean-k-mooney | but it was causeing rpc issues | |
| 08:44:06 | bauzas | sean-k-mooney: we were suspecting some lock holding the RPC calls | |
| 08:44:20 | bauzas | but, anyway, logs, logs, logs | |
| 08:44:26 | eandersson | If it was an RPC issue it would timeout at some point at some end | |
| 08:44:32 | eandersson | right? | |
| 08:44:38 | bauzas | correct | |
| 08:44:44 | sean-k-mooney | eventrually you would gett a messaging time out yes | |
| 08:44:56 | eandersson | One of these VMs are stuck for 24 hours with no error logs | |
| 08:45:05 | bauzas | eandersson: again, are you able to track the request down on compute ? | |
| 08:45:35 | bauzas | what's the last step the logs are telling you for a specific instance ? | |
| 08:45:53 | openstackgerrit | Tushar Patil proposed openstack/nova-specs master: Allow compute nodes to use DISK_GB from shared storage RP https://review.opendev.org/650188 | |
| 08:45:53 | gibi | also the bug behind the https://review.opendev.org/#/c/677736/ says that this bug makes the compute marked down, which is not the case for eandersson | |
| 08:46:43 | bauzas | oh wait, the last task state is "scheduling" ? | |
| 08:46:58 | bauzas | that's waaaaay different from a compute issue then :) | |
| 08:47:15 | sean-k-mooney | gibi: right it cause the compute agent too block on the call to libvirt and nothing else gets processed until libvirt returns | |
| 08:47:56 | eandersson | Yea - not sure it is nova-compute specific, since restarting nova-compute has no effect | |
| 08:48:09 | eandersson | but that specific compute has this issue, but the next one works fine | |
| 08:48:31 | eandersson | keep in mind I am just bypassing the scheduler using --availability-zone nova:<compute> | |
| 08:48:33 | sean-k-mooney | there was a case about a mont ago where a patch was submitted for a codepath were we did not catch an exception that left the vm in building for ever. but i cant recall which one it was | |
| 08:48:53 | bauzas | eandersson: IIRC, 'scheduling' task state is different from 'spawning' | |
| 08:49:02 | eandersson | Yea | |
| 08:49:03 | sean-k-mooney | you would see a trace in the compute log if that was the case which also seams not to be the case | |
| 08:49:15 | bauzas | eandersson: so, I suspect nothing goes back from scheduler | |
| 08:49:27 | bauzas | so the conductor can't trigger the RPC call to compute | |