| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2017-07-27 | |||
| 01:22:50 | mriedem | check the dev list about multi-tier conductor | |
| 01:22:55 | tonyb | mriedem: Oh I'm not that behind then | |
| 01:23:28 | rm_work | yeah, octavia folks are just *bleeding edge* :P | |
| 01:23:34 | rm_work | we always run into this stuff first | |
| 01:23:35 | tonyb | rm_work: my first grep didn't checkout master (it only downlaoded it) :( | |
| 01:24:51 | tonyb | mriedem: oh the conductor fleet stuff | |
| 01:25:45 | mriedem | yeah | |
| 01:25:59 | mriedem | a change merged today that allows you to disable that behavior if you need to | |
| 01:26:15 | mriedem | https://review.openstack.org/#/c/487485/ | |
| 01:29:08 | mriedem | although, even with that set to singleconductor, i'm seeing the superconductor running http://logs.openstack.org/58/487458/2/check/gate-tempest-dsvm-ironic-ipa-wholedisk-bios-agent_ipmitool-tinyipa-ubuntu-xenial/d148ee1/logs/ | |
| 01:29:16 | mriedem | dansmith: ^ maybe why the ironic job is still failing? | |
| 01:29:41 | dansmith | mriedem: in single conductor, the super conductor is the only one that gets hit | |
| 01:30:07 | mriedem | but we still start the cell conductor? | |
| 01:30:19 | mriedem | i'm seeing a request go through the scheduler, it picks a host, but then i don't see the request going through n-cpu | |
| 01:30:19 | dansmith | yeah, it was a hack for grenade remember | |
| 01:32:09 | mriedem | req-b1d7d389-f01a-4ea6-8de4-621fc28f7fc7 | |
| 01:32:17 | mriedem | http://logs.openstack.org/58/487458/2/check/gate-tempest-dsvm-ironic-ipa-wholedisk-bios-agent_ipmitool-tinyipa-ubuntu-xenial/d148ee1/logs/screen-n-super-cond.txt.gz#_Jul_26_21_32_58_412591 | |
| 01:32:22 | mriedem | super conductor just seems to die there | |
| 01:32:52 | mriedem | and i never see req-b1d7d389-f01a-4ea6-8de4-621fc28f7fc7 show up in n-cpu logs | |
| 01:33:22 | dansmith | is that req a boot request? | |
| 01:33:33 | dansmith | you'd never see it hit cpu if it got novalidhost right? | |
| 01:33:52 | mriedem | it didn't get novalidhost | |
| 01:33:57 | mriedem | i see n-sch pick a host | |
| 01:34:07 | mriedem | and yeah that's the boot request | |
| 01:34:15 | mriedem | super-cond, sch and cpu are all using nova.conf | |
| 01:34:24 | mriedem | which points at transport_url = rabbit://stackrabbit:secretrabbit@15.184.66.253:5672/ | |
| 01:34:52 | mriedem | db connection is set to nova_cell1 | |
| 01:34:53 | dansmith | yeah, which is a pretty normal setup | |
| 01:35:09 | dansmith | is it normal to have cpu deleting tons of orphan nodes? | |
| 01:36:08 | dansmith | and this is single node so no chance we're missing logs from another conductor I guess | |
| 01:36:59 | mriedem | lots of ComputeHostNotFound in the n-cpu logs | |
| 01:37:41 | mriedem | this is the host/node that's picked in the scheduler | |
| 01:37:41 | mriedem | Selected host: (ubuntu-xenial-infracloud-vanilla-10103211, eda7dc99-9e17-479c-b234-9d87956e9c56) ram: 384MB disk: 10240MB io_ops: 0 instances: 0 | |
| 01:37:42 | dansmith | so you think conductor got the selected host and cast to compute but it disappeared? | |
| 01:37:53 | mriedem | or conductor didn't get it.. | |
| 01:38:00 | dansmith | unfortunately, we don't get to see the _actual_ trnsport_url loaded in compute | |
| 01:38:07 | dansmith | that req showed up in conductor, no? | |
| 01:38:35 | dansmith | yeah, it clearly got to the conductor | |
| 01:39:07 | mriedem | yeah i see block_device_mapping in conductor | |
| 01:39:12 | mriedem | which comes after we get the scheduler response | |
| 01:39:37 | mriedem | http://logs.openstack.org/58/487458/2/check/gate-tempest-dsvm-ironic-ipa-wholedisk-bios-agent_ipmitool-tinyipa-ubuntu-xenial/d148ee1/logs/screen-n-super-cond.txt.gz#_Jul_26_21_32_58_377797 | |
| 01:40:20 | mriedem | i never see "Starting instance" in the n-cpu logs | |
| 01:40:24 | dansmith | well, they're all using the same config, and the config is good, I don't really see how it's breaking between conductor and compute | |
| 01:40:29 | mriedem | so it looks like the request never gets to build_and_run_instance in n-cpu | |
| 01:40:35 | mriedem | me neither | |
| 01:40:39 | dansmith | yeah | |
| 01:40:40 | dansmith | but I dunno how to explain that | |
| 01:43:08 | dansmith | the hostname and node id seem to match up between compute and what scheduler selected | |
| 01:43:34 | dansmith | if it picked a host that didn't exist we would cast to the wrong topic and it'd get dropped, but.. | |
| 01:43:38 | dansmith | they match | |
| 01:45:39 | dansmith | no rabbit dump at the end so we can't see if there are different topics or messages sitting in queues | |
| 01:48:02 | mriedem | ok so scheduler picks the host here | |
| 01:48:02 | mriedem | Jul 26 21:32:57.959669 ubuntu-xenial-infracloud-vanilla-10103211 nova-scheduler[12180]: DEBUG nova.scheduler.filter_scheduler [None req-b1d7d389-f01a-4ea6-8de4-621fc28f7fc7 tempest-BaremetalBasicOps-1511666062 tempest-BaremetalBasicOps-1511666062] Selected host: (ubuntu-xenial-infracloud-vanilla-10103211, eda7dc99-9e17-479c-b234-9d87956e9c56) ram: 384MB disk: 10240MB io_ops: 0 instances: 0 {{(pid=12180) _schedule /opt/stack/n | |
| 01:48:02 | mriedem | ova/nova/scheduler/filter_scheduler.py:157}} | |
| 01:48:25 | mriedem | super-conductor creates the bdms in cell1 here | |
| 01:48:26 | mriedem | Jul 26 21:32:58.377797 ubuntu-xenial-infracloud-vanilla-10103211 nova-conductor[13817]: DEBUG nova.conductor.manager [None req-b1d7d389-f01a-4ea6-8de4-621fc28f7fc7 tempest-BaremetalBasicOps-1511666062 tempest-BaremetalBasicOps-1511666062] [instance: 6e534573-5533-41d6-b9d7-28bfd7dbfe2d] block_device_mapping [BlockDeviceMapping(attachment_id=<?>,boot_index=0,connection_info=None,created_at=<?>,delete_on_termination=True,delete | |
| 01:48:27 | mriedem | >,deleted_at=<?>,destination_type='local',device_name=None,device_type='disk',disk_bus=None,guest_format=None,id=<?>,image_id='2120252b-74dd-46b0-8649-ef7bcbdd0f50',instance=<?>,instance_uuid=<?>,no_device=False,snapshot_id=None,source_type='image',tag=None,updated_at=<?>,volume_id=None,volume_size=None)] {{(pid=14569) _create_block_device_mapping /opt/stack/new/nova/nova/conductor/manager.py:829}} | |
| 01:49:20 | mriedem | 8 seconds before that in n-cpu we're deleting orphan compute nodes | |
| 01:49:20 | mriedem | http://logs.openstack.org/58/487458/2/check/gate-tempest-dsvm-ironic-ipa-wholedisk-bios-agent_ipmitool-tinyipa-ubuntu-xenial/d148ee1/logs/screen-n-cpu.txt.gz#_Jul_26_21_32_50_782647 | |
| 01:49:36 | dansmith | but, the node doesn't affect the host/topic it goes to | |
| 01:50:14 | mriedem | yeah | |
| 01:50:28 | mriedem | there is a gmr at the end of n-cpu | |
| 01:51:27 | dansmith | transport_url is obscured there too | |
| 01:51:35 | dansmith | also, | |
| 01:51:45 | dansmith | scheduler wouldn't have selected it if it wasn't getting written to the right db, | |
| 01:52:28 | dansmith | but I guess it could be going to the wrong conductor | |
| 01:52:55 | dansmith | so we could try setting the other conductor to the same mq vhost in this scenario, or not start it and see if n-cpu is timing out | |
| 01:53:12 | dansmith | although I don't really see how we could be on the wrong vhost, since we write the config early and don't restart cpu at all | |
| 01:56:43 | mriedem | i was wondering if something was going to the cell1 conductor, but there is nothing in it's logs | |
| 01:56:55 | mriedem | after it dumps the config anyway | |
| 01:57:22 | dansmith | yeah, seems unlikely, but it also has a barebones config, so maybe it's on warning only logs or something? | |
| 01:58:29 | mriedem | it's logging debug messages | |
| 01:59:07 | dansmith | yeah I guess so | |
| 01:59:17 | dansmith | well I dunno, I'm dry on ideas | |
| 01:59:33 | mriedem | there is a rabbit log | |
| 01:59:34 | mriedem | http://logs.openstack.org/58/487458/2/check/gate-tempest-dsvm-ironic-ipa-wholedisk-bios-agent_ipmitool-tinyipa-ubuntu-xenial/d148ee1/logs/rabbitmq/rabbit@ubuntu-xenial-infracloud-vanilla-10103211.txt.gz | |
| 01:59:43 | dansmith | yeah, but no queue dump right? | |
| 01:59:46 | mriedem | no | |
| 01:59:51 | mriedem | last thing we'd see in super-cond is Jul 26 21:32:58.377797 | |
| 01:59:58 | mriedem | and that's where the rabbit log ends | |
| 02:01:23 | mriedem | know how to dump the queue in the rabbitmq logs? | |
| 02:02:08 | dansmith | yeah, | |
| 02:02:41 | dansmith | rabbitmqctl report | |
| 02:02:44 | dansmith | I think gives you a ton of data | |
| 02:03:01 | dansmith | yup, that's all the status dumps in one command | |
| 02:03:35 | mriedem | hmm, but do we just dump that at the very end when collecting logs? | |
| 02:03:48 | mriedem | i know where logs are collected in devstack-gate | |
| 02:03:59 | dansmith | yeah, that will tell us if something is still in a queue | |
| 02:04:08 | mriedem | ok i could tinker with that | |
| 02:04:19 | mriedem | and fix jay's placement 'handle moves' patch | |
| 02:05:27 | dansmith | so the channels section of that dump will have some stuff like consumer_count and messages_unacknowledged | |
| 02:05:38 | dansmith | which would be the things that are sitting from a cast unretrieved | |
| 02:05:52 | dansmith | and then you should see the compute-$hostname topics for anything listening | |
| 02:06:06 | dansmith | not sure that will dump all vhosts | |
| 02:06:43 | dansmith | report doesn't take a vhost, so I imagine it will dump all of them | |
| 02:07:02 | openstackgerrit | Merged openstack/nova master: deprecate ``wsgi_log_format`` config variable https://review.openstack.org/486623 | |
| 02:07:07 | dansmith | yeah looks like it | |
| 02:08:44 | dansmith | mriedem: I'm going to retire for the evening but will pick things back up in the morning unless you fix it before then | |
| 02:14:20 | mriedem | adios | |
| 02:21:33 | melwitt | tonyb: excellent memory. I had forgotten about the low hanging fruit etherpad | |