| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-10-17 | |||
| 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 | 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: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: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 | sean-k-mooney | if you use the avialbality zone way partly | |
| 09:05:09 | bauzas | nope, it won't then | |
| 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 | ... | |
| 09:07:23 | sean-k-mooney | eandersson: is the only indication of this request the api log and the db entry? | |
| 09:07:35 | sean-k-mooney | e.g. are you not seeing it in any other service at all? | |
| 09:08:08 | eandersson | Let me search for the instance uuid | |
| 09:10:00 | eandersson | nova, placement and neutron-server are showing up | |
| 09:10:53 | bauzas | eandersson: we do non-blocking RPC calls for the nova-api service | |
| 09:11:25 | bauzas | eandersson: so I wouldn't be surprised if you wouldn't capture RPC timeouts | |
| 09:11:50 | bauzas | hence the rabbit queue checks | |
| 09:12:38 | eandersson | The rabbitmq queues look fine. Nothing queued, nothing stuck in unack'd. I could capture messages going to the queues. | |
| 09:13:21 | sean-k-mooney | in rocky we are not patching the api with eventlet so we dont have the heartbeat issue but i was just wondering how far it got in the boot process before going silent | |
| 09:14:34 | sean-k-mooney | if we only see reference to the instance boot request in the api but not in the conductor or schduler it implies its failing very early | |
| 09:14:51 | eandersson | I only see the compute in placement | |
| 09:15:10 | sean-k-mooney | ok so its getting to the schduler then | |
| 09:15:43 | sean-k-mooney | infact if its created the allcoation its pass the filters and selected the host | |
| 09:16:18 | sean-k-mooney | so its failing somethime beetween the schduler retruning to the conductor and the conductor callign the compute node | |
| 09:17:02 | bauzas | sean-k-mooney: that's not my understanding from what eandersson said by "I only see the compute in placement" | |
| 09:17:43 | sean-k-mooney | oh i may have misread that | |
| 09:17:47 | bauzas | eandersson: no GET logs on https://docs.openstack.org/api-ref/placement/?expanded=list-allocation-candidates-detail#list-allocation-candidates ? | |
| 09:18:03 | eandersson | I see build_and_run_instance hit the compute | |
| 09:18:16 | bauzas | WTF | |
| 09:18:20 | eandersson | when capturing a rabbitmq message | |
| 09:18:27 | eandersson | received by the compute | |
| 09:19:09 | bauzas | but no logs ? | |
| 09:19:21 | bauzas | I suspect your log factory not working then :D | |
| 09:19:29 | bauzas | that's... crazy | |