| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-10-17 | |||
| 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 | |
| 09:21:26 | eandersson | bauzas, talking about compute or conductor? | |
| 09:22:08 | bauzas | I frankly don't know what to say, I'm just lost | |
| 09:22:25 | eandersson | like look at the conductor https://zuul.opendev.org/t/openstack/build/9a820944e63e409cb8dbf5b83931263e/log/logs/screen-n-cond.txt.gz | |
| 09:22:29 | eandersson | and search for INFO | |
| 09:22:31 | bauzas | you're seeing only logs on api service, but you just told you're able to see a build call to compute | |
| 09:22:32 | eandersson | You'll find like 5 logs | |
| 09:22:58 | eandersson | https://zuul.opendev.org/t/openstack/build/d34ddb7bd62148968c33f4fe8f348e8b/log/controller/logs/screen-n-super-cond.txt.gz | |
| 09:23:29 | eandersson | I am not sure what you are talking about to be honest. | |
| 09:23:55 | eandersson | https://zuul.opendev.org/t/openstack/build/d34ddb7bd62148968c33f4fe8f348e8b/log/controller/logs/screen-n-sch.txt.gz | |
| 09:24:01 | eandersson | This is the scheduler, again search for INFO | |
| 09:24:05 | eandersson | you'll find like zero entries | |
| 09:24:44 | eandersson | We have 1k compute nodes, and enabling debug would be very... spammy | |
| 09:25:04 | eandersson | but unfortunately INFO does not provide a ton of logs outside of API | |
| 09:27:24 | bauzas | eandersson: as I proposed you, can you please do some 'nova instance-action-list' stuff to get more knowledge ? | |
| 09:27:39 | bauzas | but I understand your point, INFO logs aren't talkative | |
| 09:28:02 | bauzas | I thought we fixed that in Newton (or sometimes around it) | |
| 09:28:22 | eandersson | Is that the same as openstack server even list? | |
| 09:28:29 | eandersson | *event | |
| 09:29:02 | eandersson | because os-instance-actions just shows me the request id, server id, action and start time | |
| 09:29:16 | eandersson | let me check the body | |