| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-10-17 | |||
| 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 | |
| 08:49:38 | bauzas | which will change the task to spawn | |
| 08:52:02 | bauzas | actually, https://docs.openstack.org/nova/latest/reference/vm-states.html#create-instance-states | |
| 08:52:29 | bauzas | we unset the task state before plugging the network and the devices | |
| 08:52:56 | bauzas | but since you're still on 'scheduling', I bet nothing goes down to compute and stays on conductor | |
| 08:52:58 | bauzas | again, logs... | |
| 08:55:01 | eandersson | If I search for the req from VM create I only find the api call | |
| 08:55:17 | eandersson | I only find the compute because it's in the database. | |
| 08:56:16 | eandersson | If I could reproduce it in the lab I could give you all the logs you can dream off :p | |
| 08:59:35 | bauzas | eandersson: even on production, can't you just query through some specific request-id ? | |
| 08:59:43 | eandersson | Yes | |
| 08:59:56 | eandersson | I can give you anything that is INFO or higher =] | |
| 09:00:39 | bauzas | that's enough | |
| 09:01:00 | bauzas | also, you could just query the os-instance-action API to get you a bit of what happened https://docs.openstack.org/api-ref/compute/?expanded=#servers-actions-servers-os-instance-actions | |
| 09:01:52 | bauzas | eandersson: accordingly, for a specific request-id corresponding to a server create, are you able to track the last service involved ? | |
| 09:02:10 | eandersson | nova.api is the last service with that request-id | |
| 09:02:26 | bauzas | crazy | |
| 09:02:27 | eandersson | > [<req> <x> <y>]<IP> "POST /v2.1/<tenant>/servers" status: 202 len: 472 microversion: 2.1 time: 1.453706 | |
| 09:03:29 | eandersson | I can see the scheduling request in the database under request_specs | |
| 09:03:35 | bauzas | eandersson: I'd suggest you to use the os-instance-action API then | |
| 09:03:45 | bauzas | and look at the events, if you enabled them | |
| 09:04:16 | bauzas | eandersson: the request_spec record is created by the nova-api service so that doesn't prove it reached the scheduler service | |
| 09:04:29 | eandersson | Sure | |
| 09:04:48 | eandersson | Wouldn't specifying the host actually by-pass the scheduler? | |
| 09:04:57 | bauzas | it depends, which release ? | |
| 09:05:00 | eandersson | Rocky | |
| 09:05:09 | bauzas | nope, it won't then | |
| 09:05:09 | sean-k-mooney | if you use the avialbality zone way partly | |
| 09:05:20 | sean-k-mooney | it will check that the az exists | |
| 09:05:21 | bauzas | sean-k-mooney: even with this, it will call out the scheduler | |
| 09:05:29 | sean-k-mooney | and then skip the rest | |
| 09:05:32 | sean-k-mooney | sure | |
| 09:05:38 | sean-k-mooney | but it does not run all the filters | |
| 09:05:43 | bauzas | oh yeah, syre | |
| 09:05:59 | bauzas | but eandersson tells us that nothing but nova-api shows evidence of the request ID | |
| 09:06:05 | bauzas | even not the conductor | |
| 09:06:11 | sean-k-mooney | it will still call the schduler however so you should see something in the log for it | |
| 09:06:13 | eandersson | Well conductor logs nothing | |
| 09:06:23 | eandersson | We have many thousands vms per day and the logs in the conductor is zero | |
| 09:06:40 | bauzas | you should call Alice to follow the rabbit... | |
| 09:06:54 | eandersson | ... | |