| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2017-02-16 | |||
| 22:42:43 | mriedem | and we get here http://logs.openstack.org/50/435050/1/check/gate-tempest-dsvm-multinode-live-migration-ubuntu-xenial/49adcde/logs/subnode-2/screen-n-cpu.txt.gz#_2017-02-16_22_22_11_143 | |
| 22:42:51 | mriedem | 2017-02-16 22:22:11.143 14954 DEBUG nova.virt.libvirt.driver [req-025bf4d2-e5ba-4236-a334-f9eb98105ada tempest-LiveBlockMigrationTestJSON-793129345 tempest-LiveBlockMigrationTestJSON-793129345] [instance: 0ee93807-d206-4ddf-878c-efd1dd2eab3c] Instance is running spawn /opt/stack/new/nova/nova/virt/libvirt/driver.py:2689 | |
| 22:43:01 | mriedem | which calls spawn() on the libvirt driver | |
| 22:43:11 | mriedem | and after that, it's radio silence on that instance and request except for periodic tasks | |
| 22:43:26 | mriedem | i have a feeling we have some kind of deadlock or something in the libvirt driver's spawn flow | |
| 22:43:37 | mriedem | i've seen it since newton | |
| 22:47:37 | cfriesen | so you're thinking self._domain.createWithFlags() is triggering something wonky? | |
| 22:48:36 | cfriesen | or is there another async call before that? | |
| 22:50:57 | openstackgerrit | Eric Fried proposed openstack/nova master: PowerVM Driver: console https://review.openstack.org/409402 | |
| 22:51:30 | mriedem | cfriesen: i don't know what it is | |
| 22:51:41 | mriedem | last time i looked into this i was going to add some debug logging in the image create code | |
| 22:51:50 | mriedem | because that's gone through a lot of churn since newton | |
| 22:53:46 | cfriesen | mriedem: we're getting back to the debug log though, which means that we've done the image create, no? | |
| 22:54:58 | mriedem | this is also weird http://logs.openstack.org/50/435050/1/check/gate-tempest-dsvm-multinode-live-migration-ubuntu-xenial/49adcde/logs/subnode-2/screen-n-cpu.txt.gz#_2017-02-16_22_22_06_286 | |
| 22:55:04 | mriedem | Instance network_info: |[]| | |
| 22:57:21 | mriedem | so i wonder if, | |
| 22:57:33 | mriedem | the compute manager is just waiting for the async network_info stuff to get done | |
| 22:57:54 | mriedem | but it doesn't complete because it's empty - but i don't think that's how it works anyway, we allow booting a server with no networkin | |
| 22:58:02 | mriedem | and test it in tempest with the 2.37 microversion | |
| 22:58:45 | cfriesen | whatever it is, it's not blocking the self._create_domain_and_network() call because we're seeing the log right after it. So it has to be something async that we're not waiting for. | |
| 23:02:38 | mriedem | cfriesen: yeah right after that we see timer = loopingcall.FixedIntervalLoopingCall(_wait_for_boot) | |
| 23:02:51 | mriedem | which is waiting for the power state to be RUNNING | |
| 23:03:01 | mriedem | i guess we just never finish there | |
| 23:03:09 | mriedem | because i never see "Instance spawned successfully." | |
| 23:03:42 | mriedem | even though i see http://logs.openstack.org/50/435050/1/check/gate-tempest-dsvm-multinode-live-migration-ubuntu-xenial/49adcde/logs/subnode-2/screen-n-cpu.txt.gz#_2017-02-16_22_22_11_214 | |
| 23:03:48 | mriedem | [instance: 0ee93807-d206-4ddf-878c-efd1dd2eab3c] VM Started (Lifecycle Event) | |
| 23:04:06 | mriedem | and then right after that [instance: 0ee93807-d206-4ddf-878c-efd1dd2eab3c] VM Paused (Lifecycle Event) | |
| 23:04:44 | mriedem | Synchronizing instance power state after lifecycle event "Paused"; current vm_state: building, current task_state: spawning, current DB power_state: 0, VM power_state: 3 | |
| 23:04:50 | mriedem | 3 = paused | |
| 23:05:53 | mriedem | i don't see "Instance spawned successfully." anywhere in http://logs.openstack.org/50/435050/1/check/gate-tempest-dsvm-multinode-live-migration-ubuntu-xenial/49adcde/logs/subnode-2/screen-n-cpu.txt.gz | |
| 23:06:51 | mriedem | so the instance goes from started to paused, | |
| 23:06:56 | mriedem | and then is never unpaused | |
| 23:07:06 | mriedem | which is why the spawn() method never considers it done i guess | |
| 23:08:07 | mriedem | http://logs.openstack.org/50/435050/1/check/gate-tempest-dsvm-multinode-live-migration-ubuntu-xenial/49adcde/logs/subnode-2/libvirt/qemu/instance-00000001.txt.gz | |
| 23:08:44 | mriedem | what does this mean? "KVM: entry failed, hardware error 0x0" | |
| 23:13:07 | openstackgerrit | Sujitha proposed openstack/nova master: This patch is followup for https://review.openstack.org/#/c/415298/. https://review.openstack.org/435146 | |
| 23:15:45 | cdent | mriedem: casual googling suggests problems with nested virtualization | |
| 23:16:56 | mriedem | i'm crawling through the libvirtd logs | |
| 23:18:21 | openstackgerrit | Sujitha proposed openstack/nova master: Change tags to default field in Instance object. https://review.openstack.org/415298 | |
| 23:19:22 | openstackgerrit | Sujitha proposed openstack/nova master: This patch is followup for https://review.openstack.org/#/c/415298/. https://review.openstack.org/435146 | |
| 23:19:26 | mriedem | i see this start to go crazy | |
| 23:19:27 | mriedem | debug : qemuMonitorJSONIOProcess:255 : Total used 0 bytes out of 1023 available in buffer | |
| 23:19:31 | mriedem | debug : qemuMonitorJSONIOProcess:255 : Total used 0 bytes out of 2047 available in buffer | |
| 23:19:37 | mriedem | debug : qemuMonitorJSONIOProcess:255 : Total used 0 bytes out of 3071 available in buffer | |
| 23:19:44 | mriedem | debug : qemuMonitorJSONIOProcess:255 : Total used 0 bytes out of 4095 available in buffer | |
| 23:20:05 | mriedem | debug : qemuMonitorJSONIOProcess:255 : Total used 6689 bytes out of 6689 available in buffer | |
| 23:20:05 | mriedem | ... | |
| 23:20:50 | mriedem | maybe that's normal | |
| 23:21:51 | mriedem | 2017-02-16 22:22:11.139+0000: 8968: debug : qemuProcessHandleResume:765 : Transitioned guest instance-00000001 out of paused into resumed state | |
| 23:22:50 | mriedem | 2017-02-16 22:22:11.140+0000: 8968: debug : qemuProcessHandleStop:716 : Transitioned guest instance-00000001 to paused state | |
| 23:22:55 | openstackgerrit | Eric Fried proposed openstack/nova master: PowerVM Driver: config drive https://review.openstack.org/409404 | |
| 23:23:04 | openstackgerrit | Sujitha proposed openstack/nova master: [WIP] Reduce calls to load_tags() to 0 https://review.openstack.org/435146 | |
| 23:23:43 | mriedem | no errors in the libvirt logs | |
| 23:25:53 | mriedem | aha | |
| 23:25:57 | mriedem | right around that time in the syslog | |
| 23:25:58 | mriedem | http://logs.openstack.org/50/435050/1/check/gate-tempest-dsvm-multinode-live-migration-ubuntu-xenial/49adcde/logs/subnode-2/syslog.txt.gz#_Feb_16_22_22_11 | |
| 23:26:02 | mriedem | End of file while reading data: Input/output error | |
| 23:27:42 | mriedem | we shouldn't even be using virtlogd | |
| 23:27:51 | mriedem | dansmith: you ever seen anything like this? ^ | |
| 23:27:55 | mriedem | channel your inner berrange | |
| 23:28:58 | mriedem | maybe the i/o error with virtlogd is a result of the guest hw error? | |
| 23:29:49 | mriedem | i guess that's really normal | |
| 23:29:53 | mriedem | it's all over syslog in our ci runs | |
| 23:30:09 | cdent | that's an unfortunate way to spell normal | |
| 23:34:11 | mriedem | virt_type = kvm in nova.conf | |
| 23:34:13 | mriedem | that should be qemu | |
| 23:34:22 | mriedem | we don't support that in the gate with nested virt, how the hell was this even running | |
| 23:35:20 | mriedem | so yeah, that's the issue | |
| 23:36:52 | cdent | mriedem: how/where/why? | |
| 23:37:01 | cdent | as in wat? | |
| 23:37:05 | cdent | and wtf | |
| 23:37:14 | mriedem | it's qemu on the primary node, but kvm on the subnode | |
| 23:37:15 | mriedem | that's the bug | |
| 23:38:13 | cfriesen | anyone got a suggestion on the best way to deal with this? http://paste.openstack.org/show/599318/ I'm adding a check against cs.api_version in v2.shell.do_list() and it's failing a bunch of tests with that error | |
| 23:38:30 | cdent | mriedem: ah, and somehow this only showed up as a problem now? | |
| 23:39:32 | mriedem | cdent: i've been seeing it off and on | |
| 23:39:39 | mriedem | i just haven't taken the 2 hours to investigate :) | |
| 23:39:49 | cdent | ow | |
| 23:40:38 | cdent | do you ever sleep or eat or recreate in some fashion (please don't tell me this is your recreation)? | |
| 23:41:14 | mriedem | when my wife forces me, yes | |
| 23:41:31 | mriedem | i only care about this since it kicked the last change for ocata ga out of the gagte | |
| 23:41:32 | mriedem | *Gate | |
| 23:42:56 | mriedem | she gets up at 4am and goes to bed at 7pm though so i will start getting texts here pretty quick to get my ass home and take over parenting duties | |
| 23:47:35 | cdent | g'night | |
| 23:47:59 | openstackgerrit | Sujitha proposed openstack/nova master: Adding auto_disk_config field to InstancePayload https://review.openstack.org/419185 | |
| 23:51:28 | mriedem | https://review.openstack.org/#/c/435154/1 | |
| 23:51:30 | mriedem | YES! | |
| 23:51:33 | mriedem | sdague: ^^^^ | |
| 23:51:39 | mriedem | jogo: even you ^ | |
| 23:51:42 | mriedem | mtreinish: ^ | |
| 23:52:56 | mtreinish | mriedem: hah, nice | |
| 23:54:09 | mriedem | ok i'm tapping out, back online later | |
| 23:55:25 | jogo | mriedem: done | |
| 23:55:46 | mriedem | ha | |
| 23:55:47 | mriedem | o/ | |
| #openstack-nova - 2017-02-17 | |||
| 00:26:16 | cburgess | mrodden So... food update... | |
| 00:26:20 | cburgess | Opps | |
| 00:26:29 | cburgess | Wrong person. | |
| 00:26:47 | cburgess | mriedem You still around? | |
| 00:27:10 | melwitt | cburgess: he's heading home right now, said he'll be back online later | |