| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2019-10-17 | |||
| 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 | |
| 09:33:58 | sean-k-mooney | bauzas: ya looking at the conductor logs for the gate jobs the non debug version is not very useful | |
| 09:34:08 | sean-k-mooney | we likely should make https://zuul.opendev.org/t/openstack/build/df644e9fdde346f2813e6220312a9ca5/log/controller/logs/screen-n-super-cond.txt.gz#867 info level | |
| 09:35:11 | eandersson | I enabled debug | |
| 09:35:40 | eandersson | > [instance: x] Selected host: compute1031; Selected node: compute1031; ; Alternates: [] schedule_and_build_instances | |
| 09:35:48 | bauzas | eandersson: I checked and events are shown by default if you are on Pike and above when you call out instance-action API | |
| 09:35:49 | eandersson | > Re-scheduling is disabled. populate_retry | |
| 09:36:08 | bauzas | eandersson: but you need to login with admin creds | |
| 09:36:22 | bauzas | https://docs.openstack.org/api-ref/compute/?expanded=show-server-action-details-detail#id170 | |
| 09:36:52 | bauzas | anyway, gotta run, | |
| 09:36:54 | bauzas | \o | |
| 09:37:21 | eandersson | http://paste.openstack.org/show/EUjnd5TWftogxGIVaSNP/ | |
| 09:37:25 | eandersson | This is the last log line | |
| 09:37:35 | eandersson | from the conductor / scheduler | |
| 09:38:13 | eandersson | yea bauzas nothing interesting in the events | |
| 09:39:06 | eandersson | Everything looks to be scheduled fine | |
| 09:39:21 | sean-k-mooney | right that is the last log for the instace we expect to see in the conductor log | |
| 09:39:54 | sean-k-mooney | well unless there is an error | |
| 09:40:00 | eandersson | no errors in the logs | |
| 09:40:08 | eandersson | :'( | |
| 09:40:36 | sean-k-mooney | and nothing in the compute agent long in debug either | |
| 09:40:41 | sean-k-mooney | it just disappars? | |
| 09:40:48 | eandersson | I pasted some logs early on | |
| 09:41:00 | sean-k-mooney | you captured the rpc right beign recived | |
| 09:41:03 | eandersson | let me check again | |
| 09:41:14 | sean-k-mooney | oh ill scroll back | |
| 09:45:26 | tssurya | eandersson: what's the exact boot request you are making ? | |
| 09:45:47 | sean-k-mooney | i dont see the logs for the compute scrolling back unfortunetly. | |
| 09:46:08 | eandersson | sean-k-mooney, I think the logs we discussed were things like | |
| 09:46:14 | eandersson | > instance x has been scheduled to this compute host | |
| 09:47:02 | eandersson | Let me enable even more debug logs | |
| 09:47:57 | sean-k-mooney | ah am you can re disable debug on the conductor/schduler since we are pretty sure its getting to the compute node at this point right | |
| 09:48:14 | eandersson | Yea already disabled | |
| 09:48:18 | eandersson | generates a lot of logs :p | |
| 09:48:59 | sean-k-mooney | for 200 servers with all servceince in debug i belive its something like 30GB a day in uncompressed logs | |
| 09:49:23 | sean-k-mooney | thats what kolla-ansibel said in there configuration docs in anycase | |
| 09:49:42 | eandersson | hehe well that is without kubernetes, octavia etc hitting your apis constantly | |
| 09:49:50 | eandersson | plus all other automation | |
| 09:50:19 | sean-k-mooney | right you would really want log rotate to be working well if you use debug always | |
| 09:51:17 | sean-k-mooney | we shoudl try to have more of a blance however. e.g. make info more useful without being just spam | |
| 09:52:06 | eandersson | On compute I see a message being received, but nothing more | |
| 09:52:29 | eandersson | > DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: ad3b7ccda9944e9e87f497f4401aa0b4 __call__ | |
| 09:52:57 | sean-k-mooney | ok so its not building the libvirt xml or plugging any ports | |
| 09:53:09 | sean-k-mooney | its just reciving it | |
| 09:53:14 | eandersson | yea | |
| 09:53:28 | sean-k-mooney | did you also check with the instance uuid | |
| 09:53:34 | eandersson | I bet this compute is bust, but everything seems fine (including already existing vms) | |
| 09:53:39 | eandersson | yea | |