| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2021-01-22 | |||
| 16:47:52 | gibi | stephenfin: thanks | |
| 16:50:05 | zigo | Great, tests.patcher_test.test_fork_after_monkey_patch fails in Py 3.9 ... :/ | |
| 16:53:48 | melwitt | lyarwood: I wanted to ask you about a failure in test_volume_swap I saw yesterday in the gate, have you seen a thing where it doesn't finish the copy and emits "COPY block job progress, current cursor: 1073741823 final cursor: 1073741824" a lot of times, showing that the cursor is only 1 from the end? | |
| 16:54:45 | melwitt | https://zuul.opendev.org/t/openstack/build/a078a17aa9924517b329cafc3f54fed4/log/controller/logs/screen-n-cpu.txt#11115 | |
| 16:57:44 | lyarwood | melwitt: I've not seen it 1 block (!?) away and not finish no | |
| 16:58:16 | lyarwood | melwitt: it's typically much greater than that, did it get there pretty quickly and then stall? | |
| 16:58:17 | melwitt | ack | |
| 16:58:37 | melwitt | erm.. let me check. | |
| 16:59:33 | melwitt | lyarwood: yeah looks like it actually. got there and then stuck on the last block for 4 minutes | |
| 17:00:12 | melwitt | do you suppose this could be similar to problems with live migration where we've needed post copy/auto converge? | |
| 17:00:20 | melwitt | seems weird | |
| 17:00:48 | lyarwood | yeah it might be but I can't think that the cirros image would be writing that much to the volume if at all | |
| 17:00:58 | lyarwood | I think we write timestamps during the test and that's it | |
| 17:01:18 | melwitt | hm ok | |
| 17:06:12 | lyarwood | melwitt: we could write this up as a Ubuntu QEMU bug again and see if upstream can help debug this further | |
| 17:06:37 | lyarwood | melwitt: assuming there's something we can log that would help them | |
| 17:08:08 | melwitt | lyarwood: good idea, let me go through and collect more data (if there is more) and I'll open one if I can find more to go on | |
| 17:08:20 | kashyap | melwitt: So ... just reading the scrollback; that "current" and "final" cursors differing means: the copy (i.e. migration w/ storage) hasn't finished succesfully | |
| 17:08:46 | kashyap | In the past we've hit that, and debugged on list; and I recall filing a libvirt RFE to fix that ... let me check | |
| 17:09:18 | melwitt | kashyap: yeah, I think I understood that but the weird thing is it quickly gets to the last block and then stays stuck there for 4 minutes until the test wait in tempest times out and kills it | |
| 17:09:37 | kashyap | Hmm | |
| 17:09:44 | kashyap | melwitt: Yeah, this definitely looks ome something new | |
| 17:10:17 | kashyap | Because in that old behaviour, libvirt was just making "educated guess" when the syncing has finished | |
| 17:10:41 | melwitt | I see | |
| 17:10:42 | kashyap | Especially the "current cursor" terminology looks new to me. I haven't seen the word "cursor" in this error's context before | |
| 17:11:05 | lyarwood | this is blockCopy and not blockRebase btw kashyap | |
| 17:11:09 | kashyap | melwitt: I don't want to bore you with a long bug, but for the record, here it is: https://bugzilla.redhat.com/show_bug.cgi?id=1382165 | |
| 17:11:11 | openstack | bugzilla.redhat.com bug 1382165 in libvirt "virDomainGetBlockJobInfo: Adjust job reporting based on QEMU stats & the "ready" field of `query-block-jobs`" [Unspecified,Closed: nextrelease] - Assigned to pkrempa | |
| 17:11:22 | kashyap | lyarwood: I see; nod | |
| 17:11:24 | lyarwood | I think we dropped that workaround a while ago | |
| 17:11:43 | kashyap | Yep | |
| 17:11:49 | kashyap | But just for clarity, blockCopy() is a _superset_ of blockRebase() | |
| 17:11:55 | melwitt | kashyap: any data/background helps :) | |
| 17:12:07 | kashyap | (So whatever worked, or failed w/ Rebase(), will also fails equal w/ Copy()) | |
| 17:12:29 | lyarwood | yeah https://review.opendev.org/c/openstack/nova/+/729596 removed it | |
| 17:12:38 | kashyap | melwitt: But yeah; filing an upstream Ubuntu QEMU bug would be cool to start with | |
| 17:13:01 | melwitt | k, I'll collect data points and write something up. thanks for the hints both | |
| 17:13:05 | kashyap | lyarwood: Yep, recall it as much, it just reminded me of it. | |
| 17:14:50 | lyarwood | if anyone has anything they'd like me review please let me know | |
| 17:14:51 | kashyap | melwitt: The libvirtd log might have some interesting stuff in there. /me tries to fish it out | |
| 17:14:53 | lyarwood | PLEASE :| | |
| 17:15:07 | kashyap | LOL | |
| 17:15:12 | melwitt | I feel for you. clicky clicky clicky | |
| 17:15:18 | melwitt | click all the things | |
| 17:15:29 | kashyap | lyarwood: I finished it the next day it came; I'm a free man! | |
| 17:15:44 | stephenfin | kashyap: no one likes a show off | |
| 17:15:48 | kashyap | stephenfin: LOL | |
| 17:15:51 | lyarwood | ./ban kashyap | |
| 17:15:57 | lyarwood | ^_^ | |
| 17:16:05 | kashyap | stephenfin: I know; the secret pleasure of doing the right thing goes away if one brags | |
| 17:18:19 | kashyap | melwitt: I'm looking at the log file here: https://storage.gra.cloud.ovh.net/v1/AUTH_dcaab5e32b234d56b626f72581e3644c/zuul_opendev_logs_a07/771749/1/check/nova-next/a078a17/controller/logs/libvirt/index.html | |
| 17:18:25 | kashyap | Hope that's the correct log tree | |
| 17:20:39 | melwitt | kashyap: yes that's right | |
| 17:21:02 | kashyap | melwitt: Unrelated: I know that the "controller" directory has the compute logs, but why is it named "controller"? | |
| 17:21:27 | kashyap | (Because there's also the "compute" top-level directory, which has its own QEMU/libvirt logs. It's always tripping me up | |
| 17:21:37 | melwitt | kashyap: in the case of multi-node job, to identify the "main" node vs one of the additional compute nodes | |
| 17:21:53 | kashyap | I see | |
| 17:22:04 | melwitt | in this case you're in the right place bc the swap volume got stuck on the main node | |
| 17:22:33 | melwitt | if it had happened on the other compute node, you'd want to look in the compute1 dir | |
| 17:22:47 | kashyap | melwitt: It looks like so; because I don't see the failure in this libvirtd log | |
| 17:22:58 | kashyap | And these copy failures are logged to libvirtd. So let me look in the other one | |
| 17:23:10 | sean-k-mooney | lyarwood: you should review gibis qos attach | |
| 17:23:16 | sean-k-mooney | series | |
| 17:23:20 | melwitt | kashyap: would there be a failure though? there was no error. it's just that the cursor never moved from the last block | |
| 17:23:41 | kashyap | melwitt: Not a failure per-se; but in Gate, we have libvirt log filters enabled | |
| 17:23:49 | melwitt | and the test timed out at the tempest level as a result of never seeing the 'available' status for the volume | |
| 17:23:50 | sean-k-mooney | lyarwood: im basically done with it and it looks ready to merge IMO | |
| 17:24:04 | kashyap | melwitt: ... so we should see more fine-grained info. And I was hoping to hurl a useful bit at one of the US-based libvirt developers :D | |
| 17:24:05 | sean-k-mooney | lyarwood: but it need a second core to review | |
| 17:24:17 | melwitt | kashyap: ack | |
| 17:25:10 | kashyap | melwitt: Oh, wait ... I first didn't see this error is _actually_ libvirt error. Looks like it's not | |
| 17:25:43 | sean-k-mooney | lyarwood: specifclly i was refering to https://review.opendev.org/q/topic:%22bp%252Fsupport-interface-attach-with-qos-ports%22+(status:open%20OR%20status:merged) if you are still lookign for somethign easy to review | |
| 17:26:15 | melwitt | kashyap: yeah it's not emitting an error afaik. it's just that we keep checking the job status and it shows it one block from the end and it stays that way for about 4 minutes and then we give up | |
| 17:28:38 | kashyap | melwitt: Have you got the instance name, please? | |
| 17:31:56 | kashyap | Found it | |
| 17:32:01 | melwitt | kashyap: uuid is 185d6573-58ee-47bc-8063-b447673db266, are you wanting the instanceNNNNNN id? | |
| 17:32:15 | melwitt | sorry, I was double checking whether I got the right one | |
| 17:32:29 | kashyap | melwitt: No-no; that's fine :-) | |
| 17:32:46 | melwitt | my eyes are like @_@ | |
| 17:33:07 | kashyap | melwitt: Heh; urgh; my FF browser is hung | |
| 17:33:54 | kashyap | Also there's an unpleasant easter egg in there (I knew it before too): ".txt" files are actually *gzip* files that will devour your RAM, if you try open them in your browser | |
| 17:35:03 | kashyap | Alright it came back. And it's this: instance-00000013 (185d6573-58ee-47bc-8063-b447673db266). Let's see if there's anything useful | |
| 17:37:04 | sean-k-mooney | kashyap: that depend on which of the ci provider the logs are uploaded too | |
| 17:37:41 | sean-k-mooney | the rackspace cloud for reason has there swift cluster configured in such a way that it always compresses them but does not send the correct headers | |
| 17:37:48 | sean-k-mooney | for things like curl to work | |
| 17:42:51 | kashyap | I see | |
| 17:42:59 | kashyap | melwitt: So ... something interesting (at least to me) :-) -- | |
| 17:43:21 | kashyap | I just extracted the exchange between libvirt and QEMU from the giant log here: https://kashyapc.fedorapeople.org/QMP_exchange_libvirtd_22Jan2021_NovaCI.txt | |
| 17:43:33 | kashyap | So ... the copy has actually *succeeded*. Here's the evidence: | |
| 17:43:46 | kashyap | - You `grep` for "blockdev-mirror" in there (at 2021-01-21 05:29:32.630+0000) -- that's the start of the copy job | |
| 17:44:29 | kashyap | - Then there's constant polling going on -- you'll see a lot of "io-status": "ok" going on there | |
| 17:44:58 | kashyap | - Finally, at 2021-01-21 05:34:24.571+0000 | |
| 17:45:40 | kashyap | We get the "ready" flag (which means copy has completed: notice the values of 'len' and 'offset' are equal: | |
| 17:45:43 | kashyap | {"return": [{"auto-finalize": true, "io-status": "ok", "device": "copy-vdb-libvirt-5-format", "auto-dismiss": false, "busy": true, "len": 1073741824, "offset": 1073741824, "status": "running", "paused": false, "speed": 0, "ready": false, "type": "mirror"}], "id": "libvirt-843"} | |
| 17:46:40 | kashyap | melwitt: So, all I can say for now is the copy has succeeded. So I'm not sure why it's saying the copy is not progressing | |
| 17:47:49 | kashyap | melwitt: I'm out of neurons, and need to make some food ... we can continue the chat in the (future) bug | |
| 17:48:48 | melwitt | thanks kashyap, that's helpful. have a nice weekend o/ | |
| 17:51:05 | kashyap | (I think it can't progress because it has reached the end of the copy -- the value in the error matches what I posted above: 1073741824. Hm, needs further digging.) | |
| 17:51:13 | kashyap | Have a good weekend, you too! | |
| 17:51:56 | melwitt | kashyap: yeah it seems the job_status api is returning the wrong thing then, or such | |