| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2017-04-21 | |||
| 19:25:47 | mriedem | yes ^ is the dest logs | |
| 19:28:09 | mriedem | http://logs.openstack.org/43/458843/1/check/gate-tempest-dsvm-multinode-live-migration-ubuntu-xenial/697a501/logs/libvirt/qemu/instance-00000001.txt.gz | |
| 19:28:18 | mriedem | /build/qemu-5OJ39u/qemu-2.8+dfsg/nbd/server.c:nbd_receive_request():L710: read failed 2017-04-21 13:54:08.792+0000: shutting down, reason=failed | |
| 19:29:35 | kashyap | For future note: Incidentally, we're going to get finer-grained details about shutdown reasons | |
| 19:29:44 | kashyap | Whether it is guest-triggered, or host-triggerred | |
| 19:29:48 | kashyap | And what precisely caused it, etc | |
| 19:30:14 | kashyap | (There's a long thread on qemu-devel upstream, to iron out the details.) | |
| 19:31:07 | mriedem | well, /build/qemu-5OJ39u/qemu-2.8+dfsg/nbd/server.c:nbd_receive_request():L710: read failed | |
| 19:31:08 | mriedem | caused it | |
| 19:31:09 | mriedem | i guess | |
| 19:31:24 | kashyap | Yes, I recall seeing that | |
| 19:32:51 | mriedem | /build/qemu-5OJ39u/qemu-2.8+dfsg/nbd/server.c:nbd_receive_request():L710: read failed | |
| 19:32:53 | mriedem | oops | |
| 19:33:00 | mriedem | http://logs.openstack.org/43/458843/1/check/gate-tempest-dsvm-multinode-live-migration-ubuntu-xenial/697a501/logs/libvirt/libvirtd.txt.gz#_2017-04-21_13_54_08_792 | |
| 19:33:00 | kashyap | mriedem: Yep, I recall it | |
| 19:33:13 | kashyap | I even reported it recently here: http://lists.nongnu.org/archive/html/qemu-devel/2017-04/msg01086.html | |
| 19:33:40 | kashyap | Quoting myself: | |
| 19:33:42 | kashyap | on the destination, _without_ gracefully completing or cancelling the | |
| 19:33:42 | kashyap | Just writing for completeness' sake, if you try to stop the NBD server | |
| 19:33:43 | kashyap | `drive-mirror` job on the source, you see the below: | |
| 19:33:53 | kashyap | /home/stack/src/qemu/nbd/server.c:nbd_receive_request():L706: read failed | |
| 19:33:53 | kashyap | {"return": {}} | |
| 19:33:53 | kashyap | {"execute":"nbd-server-stop"} | |
| 19:33:53 | kashyap | [...] | |
| 19:33:56 | kashyap | [...] | |
| 19:35:05 | mriedem | kashyap: so this is a known bug in qemu? | |
| 19:35:22 | kashyap | mriedem: It's actually benign | |
| 19:35:24 | kashyap | Because: | |
| 19:35:54 | kashyap | It means the source has gone away unexpectedly or that you stopped the NBD server before the source was disconnected | |
| 19:36:02 | kashyap | I know Nova shouldn't care this level of detail. | |
| 19:36:26 | kashyap | I'm checking if my discussion resulted in another patch | |
| 19:37:27 | mriedem | around that same time in syslog http://logs.openstack.org/43/458843/1/check/gate-tempest-dsvm-multinode-live-migration-ubuntu-xenial/697a501/logs/syslog.txt.gz#_Apr_21_13_54_08 | |
| 19:37:59 | kashyap | mriedem: What were you trying to quote in the previous libvirtd log? Your link seems broken here | |
| 19:38:20 | mriedem | that's where it failed | |
| 19:38:26 | mriedem | 2017-04-21 13:54:08.792+0000: 12165: debug : qemuProcessStop:5941 : Shutting down vm=0x7f918c009d40 name=instance-00000001 id=2 pid=5792, reason=failed, asyncJob=migration in, flags=1 | |
| 19:39:48 | mriedem | Apr 21 13:54:08ubuntu-xenial-2-node-osic-cloud1-s3500-8527282 virtlogd[12188]: End of file while reading data: Input/output error | |
| 19:39:48 | mriedem | then around that time in syslog | |
| 19:40:19 | kashyap | But _what_ caused the guest shutdown... | |
| 19:40:25 | mriedem | no idea | |
| 19:42:34 | kashyap | mriedem: Checking with Eric Blake & Max, both should know this code in libvirt / QEMU respectively | |
| 19:52:08 | cdent | thank you mriedem, someone had to respond to leakypipes | |
| 19:53:41 | kashyap | mriedem: Is this mig. failure blocking Gate? | |
| 19:55:22 | kashyap | At least, I found out (w/ help from Max) the commit that introduced it. | |
| 19:56:45 | mriedem | cdent: ha | |
| 19:56:53 | mriedem | kashyap: i think this is probably random failure | |
| 19:57:10 | kashyap | mriedem: Ah, okay, good. | |
| 19:57:21 | kashyap | http://logs.openstack.org/43/458843/1/check/gate-tempest-dsvm-multinode-live-migration-ubuntu-xenial/697a501/logs/subnode-2/libvirt/qemu/instance-00000001.txt.gz | |
| 19:57:21 | kashyap | The actual culprit failure is on the source host: | |
| 19:57:25 | mriedem | stable/ocata is blocked b/c of the live migration job, and to fix that i need to get this other change in, but i think this is just an intermittent failure | |
| 19:57:42 | mriedem | oh fun | |
| 19:57:43 | mriedem | qemu-system-x86_64: /build/qemu-5OJ39u/qemu-2.8+dfsg/block/io.c:1514: bdrv_co_pwritev: Assertion `!(bs->open_flags & BDRV_O_INACTIVE)' failed. | |
| 19:57:47 | kashyap | Yep | |
| 19:57:50 | mriedem | i have no idea what that means | |
| 20:02:44 | kashyap | mriedem: It means (according to the QEMU commit that introduced it): | |
| 20:03:08 | kashyap | Something tried to write to the image file on the source, _while_ it is being migrated | |
| 20:03:40 | kashyap | Anyway, it's unreasonably late here, I'll get to this on Monday | |
| 20:04:11 | kashyap | Cool; Gerrit is also offline on time. Everything is in harmony, and the earth keeps spinning | |
| 20:05:37 | mriedem | kashyap: ack, thanks for taking a look | |
| 20:06:12 | openstackgerrit | Matt Riedemann proposed openstack/nova master: Do not log live migration success when it actually failed https://review.openstack.org/458958 | |
| 20:06:18 | mriedem | superdan: dig this ^ | |
| 20:06:33 | mriedem | sdague: ^ you too | |
| 20:06:39 | mriedem | classic terrible | |
| 20:08:30 | superdan | mriedem: does that cleanup flags thing tell us not to destroy disks, etc in the case of failure? | |
| 20:08:41 | superdan | like, I'm surprised that falling through is the right thing to do | |
| 20:09:12 | openstackgerrit | Steve Noyes proposed openstack/nova master: Add Cinder v3 detach to shutdown_instance https://review.openstack.org/456877 | |
| 20:09:29 | superdan | mriedem: doesn't look like it does to me | |
| 20:10:34 | superdan | mriedem: so if we fail, have not shared path, we'll do_cleanup=True and tell the driver to run cleanup right? | |
| 20:11:12 | mriedem | looks that way | |
| 20:11:13 | superdan | and libvirt goes right into deleting stuff | |
| 20:11:34 | mriedem | even though you should be rolling back | |
| 20:11:39 | mriedem | but this isn't where rollback is called from | |
| 20:12:20 | superdan | right, this is if post-at-destination fails, which presumably could fail for some mundane reason and then we eff things up by doing the cleanup | |
| 20:12:57 | mriedem | is live_migration started from the source or dest host? | |
| 20:13:02 | superdan | source | |
| 20:13:13 | mriedem | oh right it has the dest parameter | |
| 20:13:37 | mriedem | i lose track of the musical chairs game that is live migration | |
| 20:13:47 | superdan | yeah it's confusing | |
| 20:14:37 | mriedem | so the source side though it was done, and calls _post_live_migration (source compute stiffl) | |
| 20:14:39 | mriedem | *still | |
| 20:15:10 | mriedem | which does an rpc call to post_live_migration_at_destination on the dest host | |
| 20:15:20 | superdan | oh, we don't get here unless it actually migrated | |
| 20:15:33 | mriedem | that fails becuase the guest isn't found on the dest host | |
| 20:15:34 | superdan | and then we just failed in the post call, but whatever, we don't own it anymore | |
| 20:16:43 | mriedem | yeah post_live_migration_at_destination fails and returns the failure back through rpc | |
| 20:17:00 | mriedem | we get the failure, log the trace "Post live migration at destination %s failed" | |
| 20:17:03 | superdan | right, so I guess it's okay | |
| 20:17:12 | superdan | we don't get to this post method unless libvirt said it worked | |
| 20:17:12 | mriedem | then drop through and start cleaning up the source | |
| 20:17:16 | superdan | so we can clean up regardless | |
| 20:17:17 | mriedem | meanwhile, the guest is not on the dest either | |
| 20:17:20 | mriedem | yeah | |
| 20:17:25 | superdan | yeah, but nothing we can do about it | |
| 20:17:26 | mriedem | so basically, | |
| 20:17:30 | mriedem | your sh is f'ed | |
| 20:17:34 | mriedem | and you instance is gone | |
| 20:17:40 | mriedem | *your | |
| 20:17:45 | superdan | yeah, I just wanted to make sure we didn't delete the thing if migration failed | |
| 20:17:50 | superdan | that's a double kick in the pands | |
| 20:18:03 | mriedem | meanwhile we've deleted your disks | |
| 20:18:19 | mriedem | this is really like, well, it's all busted, oh and btw we deleted your instance | |