| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2021-01-22 | |||
| 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 | |
| 17:52:37 | melwitt | get_job_info https://github.com/openstack/nova/blob/master/nova/virt/libvirt/guest.py#L863-L873 | |
| 17:58:01 | lyarwood | is it just a race? | |
| 17:58:26 | lyarwood | but did libvirtd log the job as finished after n-cpu had already given up? | |
| 18:10:36 | openstackgerrit | Balazs Gibizer proposed openstack/nova master: Replace blind retry with libvirt event waiting in detach https://review.opendev.org/c/openstack/nova/+/770246 | |
| 18:11:13 | melwitt | lyarwood: I will check | |
| 18:15:54 | gibi | have a nice weekend folks! o/ | |
| 18:16:01 | lyarwood | and you gibi \o | |
| 18:16:16 | lyarwood | o/ all | |
| 18:16:19 | sean-k-mooney | o/ | |
| 18:17:05 | melwitt | lyarwood: interesting, it looks like in libvirtd log it shows current == end but what we get in nova when we query is not, it's current == end - 1 | |
| 18:17:29 | melwitt | lyarwood: and also o/ | |
| 18:18:52 | sean-k-mooney | gibi: finished reviewing you qos series, +1 on most of it but left two -1s nothing major just look to confirm detach will work too and a minor issue with comments | |
| 18:19:22 | sean-k-mooney | gibi: but ya enjoy your weekend | |
| 18:26:15 | gmann | lbragstad: 1 comment on this https://review.opendev.org/c/openstack/placement/+/760240/15/placement/tests/functional/gabbits/resource-provider-legacy-rbac.yaml#20 | |
| 18:27:11 | gmann | lbragstad: we should check all persona for legacy policy also. | |
| 18:27:22 | gmann | basically checking all those tokens with enforce_scope false and true | |
| 18:27:42 | sean-k-mooney | ok im going to finish there too o/ | |
| 18:30:05 | lbragstad | gmann ok - i was thinking you only wanted testing for the default personas that were supported prior to secure RBAC? | |