Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2018-02-02
16:53:21 melwitt I wish I could tell what refreshed the info_cache in this mystery refresh. doesn't look like it was from a periodic heal else we'd see a log message about that
16:53:54 sean-k-mooney mriedem: yes though i dont think we use it in nova yet
16:54:19 sean-k-mooney melwitt: sahid has some patches related to it currently
16:54:49 mriedem hmm http://logs.openstack.org/42/525842/11/check/neutron-tempest-linuxbridge/2502b64/logs/screen-q-svc.txt.gz#_Jan_29_16_01_36_095844
16:54:58 mriedem Jan 29 16:01:36.095844 ubuntu-xenial-rax-ord-0002240582 neutron-server[21191]: DEBUG neutron.notifiers.nova [None req-1655d8dd-b810-4510-ba6a-fb2a5019a84a None None] Ignoring state change previous_port_status: ACTIVE current_port_status: BUILD port_id 8de74fd2-a3bc-4d41-9c11-c04f25b52b6d {{(pid=21288) record_port_status_changed /opt/stack/new/neutron/neutron/notifiers/nova.py:208}}
16:56:48 sean-k-mooney mriedem: ya that looks... interesting. perhaps neutron does not allow an active port to go back to build?
16:57:25 melwitt mriedem: the mystery refresh might be this? https://github.com/openstack/nova/blob/master/nova/compute/manager.py#L3152
16:58:49 openstackgerrit Balazs Gibizer proposed openstack/nova master: Escalate UUID validation warning to error in test https://review.openstack.org/540386
16:59:01 mriedem melwitt: for that call, it's this http://logs.openstack.org/42/525842/11/check/neutron-tempest-linuxbridge/2502b64/logs/screen-n-cpu.txt.gz#_Jan_29_16_01_36_172052
16:59:09 mriedem same request id as for the rebooting instance message
16:59:23 giblet figleaf: ^^ now the test derives from nova.test.TestCase and therefore I could remove the explicit fixture setup from this test as well
16:59:24 melwitt oh :\
16:59:44 mriedem melwitt: what i'm confused about is the mystery vif-plugged happens, and the request id being used is here http://logs.openstack.org/42/525842/11/check/neutron-tempest-linuxbridge/2502b64/logs/screen-n-cpu.txt.gz#_Jan_29_16_01_37_230004
16:59:52 mriedem Jan 29 16:01:36.673427 ubuntu-xenial-rax-ord-0002240582 nova-compute[29444]: WARNING nova.compute.manager [None req-1cb07971-b6f2-41f9-b34b-bc03b867abdb service nova] [instance: 3fa55d94-b1f4-42f4-8ba0-9ca46c71d7c0] Received unexpected event network-vif-plugged-8de74fd2-a3bc-4d41-9c11-c04f25b52b6d for instance with vm_state active and task_state rebooting_hard.
17:00:04 mriedem Jan 29 16:01:37.230004 ubuntu-xenial-rax-ord-0002240582 nova-compute[29444]: DEBUG nova.network.base_api [None req-1cb07971-b6f2-41f9-b34b-bc03b867abdb service nova] [instance: 3fa55d94-b1f4-42f4-8ba0-9ca46c71d7c0] Updating instance_info_cache with network_info:
17:00:08 mriedem those are the same request id
17:00:37 openstackgerrit Chris Dent proposed openstack/nova-specs master: Add generation support in aggregate association https://review.openstack.org/540447
17:01:38 mriedem in the neutron logs, that's this request http://logs.openstack.org/42/525842/11/check/neutron-tempest-linuxbridge/2502b64/logs/screen-q-svc.txt.gz#_Jan_29_16_01_37_142123
17:01:45 mriedem RESP BODY: {"events": [{"status": "completed", "tag": "8de74fd2-a3bc-4d41-9c11-c04f25b52b6d", "name": "network-vif-plugged", "server_uuid": "3fa55d94-b1f4-42f4-8ba0-9ca46c71d7c0", "code": 200}]}
17:02:20 mriedem maybe there is just a bug in logging with request ids getting mixed up, idk, but i feel like i've seen that before
17:02:27 melwitt mriedem: how do you know the first one is the call from the compute manager reboot method?
17:02:28 sean-k-mooney mriedem: https://github.com/openstack/neutron/blob/3f1a9846d23198f4a89f89bac73ba80ef201dea0/neutron/notifiers/nova.py#L178-L215 if we go directly from active to build the unpugged event will not be sent
17:02:43 mriedem melwitt: same request id
17:03:05 sean-k-mooney melwitt: that is why we are seeing the ignored event http://logs.openstack.org/42/525842/11/check/neutron-tempest-linuxbridge/2502b64/logs/screen-q-svc.txt.gz#_Jan_29_16_01_36_095844
17:03:08 melwitt oh derp, I see now
17:03:16 melwitt got it
17:03:44 mriedem i don't know why we'd go from active to build
17:03:57 melwitt well, the external instance events are REST API calls to nova from neutron so they'd have separate request ids, right?
17:04:07 mriedem they shoud
17:04:09 mriedem *should
17:04:59 melwitt but yeah why the vif plug event call and the refresh info cache call have the same id doesn't make sense if we don't refresh for a plug event
17:05:29 mriedem i don't really trust the request id logging lately
17:07:15 mriedem so, again, idk wtf is going on - and since we can't rely on this, it seems we just can't wait for vif plugged events during hard reboot and have to punt on that
17:07:45 mriedem definitely some weird timing issues
17:08:09 mriedem this is likely also something one might not see in the real world,
17:08:16 mriedem because tempest is creating an instance and then immediately hard rebooting it
17:08:34 mriedem which is probably not helping the timing issue with the various events and such
17:09:13 mriedem which we could then argue, our code *should* wait for a vif plugged event during hard reboot...but it fails in the gate
17:09:30 melwitt yeah, agree
17:09:58 melwitt I'm working on the comment update, just was also examining logs and discussing about it in the middle of it
17:10:04 mriedem we could make vif plugging timeout be non-fatal in the LB job, but that's also a hack, and likely the test would timeout by then anyway b/c we're waiting 5 minutes for something to happen
17:11:17 melwitt yeah
17:14:33 figleaf giblet: just pulled down PS5, and it still fails locally for me. I don't know what could be the difference.
17:14:46 mriedem totally unrelated, but noticed https://review.openstack.org/#/c/274869/ - in what case does _heal_instance_info_cache() care about the instance.flavor?
17:15:57 melwitt does it send any notifications? that's the only thing that comes to mind
17:15:59 mriedem there must be a notification getting sent when the instance is updated as a result of updating the nw info cache i guess
17:20:15 openstackgerrit melanie witt proposed openstack/nova master: Don't wait for vif plug events during _hard_reboot https://review.openstack.org/540168
17:20:51 melwitt mriedem bauwser ^
17:24:06 mriedem heading to lunch, will take a look when i'm back
17:24:17 melwitt cool, thanks
17:24:18 mriedem btw, do we get a network-changed event at least from neutron during reboot after we unplug the vifs?
17:24:24 mriedem i didn't look for that yet in the logs
17:25:20 melwitt we don't. as sean-k-mooney mentioned, the os-vif unplug method for linuxbridge is a no-op, it just does a pass, so that seems consistent with the lack of any event about it
17:27:28 melwitt here's the unplug http://logs.openstack.org/42/525842/11/check/neutron-tempest-linuxbridge/2502b64/logs/screen-n-cpu.txt.gz#_Jan_29_16_01_37_704617
17:56:25 figleaf giblet: looks like zuul's environment matches mine: http://logs.openstack.org/86/540386/5/check/openstack-tox-py27/2b58498/job-output.txt.gz#_2018-02-02_17_26_13_388933
18:28:37 sean-k-mooney melwitt: looking at http://logs.openstack.org/42/525842/11/check/neutron-tempest-linuxbridge/2502b64/logs/screen-n-cpu.txt.gz#_Jan_29_16_01_37_811903 we are configuring libvirt to add the interface to the bridge iteself. the linuxbridge os-vif plugin plug method seams to be doing a lot of work that is not strictly require for neutron and presuable is there for nova network
18:30:24 sean-k-mooney for example it also addes the vm port to the bridge if not already done so and also ensure the bridge existis and has an uplink port (phyical or vlan) added and brings up the bridge
18:31:25 sean-k-mooney the only thing its doing that is really required is setting the mtu and making sure ip adresses are not configured on the tap on the host.
18:32:05 sean-k-mooney i would guess we can make that driver alot smaller once nova-networks support can be dropped.
19:18:07 openstackgerrit Matt Riedemann proposed openstack/nova stable/pike: doc: Add user index page https://review.openstack.org/540494
19:18:08 openstackgerrit Matt Riedemann proposed openstack/nova stable/pike: Migrate "launch instance" user guide docs https://review.openstack.org/540495
20:01:14 openstackgerrit Matt Riedemann proposed openstack/nova master: libvirt: fix native luks encryption failure to find volume_id https://review.openstack.org/539739
20:18:24 openstackgerrit Brianna Poulos proposed openstack/nova master: docs: Add booting from an encrypted volume https://review.openstack.org/540506
20:30:52 openstackgerrit Matt Riedemann proposed openstack/nova master: Fix test_get_allocation_candidates tests https://review.openstack.org/540513
20:30:54 mriedem_afk ^ fixes a gate issue that was introduced yesterday
20:43:25 openstackgerrit Matt Riedemann proposed openstack/nova master: docs: Add booting from an encrypted volume https://review.openstack.org/540506
20:43:54 openstackgerrit Brianna Poulos proposed openstack/nova master: docs: Add booting from an encrypted volume https://review.openstack.org/540506
20:43:59 mriedem d'oh!
20:47:10 bpoulos mriedem: looks like you just beat me to it :)
20:48:17 mriedem np, thanks for moving that over
20:48:44 imacdonn wow, race condition ;)
20:49:29 fried_rice leakypipes: It happened again: http://logs.openstack.org/60/531260/27/check/nova-tox-functional-py35/cdf1b02/job-output.txt.gz
20:52:53 fried_rice mriedem: Is https://bugs.launchpad.net/nova/+bug/1747063 / https://review.openstack.org/#/c/540513 a duplicate of https://bugs.launchpad.net/nova/+bug/1747001 / https://review.openstack.org/#/c/540420 ?
20:52:55 openstack Launchpad bug 1747063 in OpenStack Compute (nova) "TestProviderOperations.test_get_allocation_candidates randomly fails AssertionError because of hash seed" [High,In progress] - Assigned to Matt Riedemann (mriedem)
20:52:56 openstack Launchpad bug 1747001 in OpenStack Compute (nova) "Use of parse.urlencode with dict in nova/tests/unit/scheduler/client/test_report.py can result in unpredictable query strings and thus unreliable tests" [Low,In progress] - Assigned to Chris Dent (cdent)
21:07:02 tssurya dansmith, mriedem : after the upgrade to Ocata yesterday and we are observing that "memory_mb_used" in "compute_nodes" tables is not correct. However, the resource_tracker log in the hypervisor is correct. Was wondering if there is a known bug or if you have heard anything similar to this issue?
21:09:49 mriedem fried_rice: yes looks like it, i'll close mine
21:10:03 fried_rice rgr
21:11:33 mriedem tssurya: maybe
21:11:51 mriedem tssurya: likely https://review.openstack.org/#/c/520024/
21:11:57 mriedem https://bugs.launchpad.net/nova/+bug/1729621
21:11:58 openstack Launchpad bug 1729621 in OpenStack Compute (nova) "Inconsistent value for vcpu_used" [High,In progress] - Assigned to Maciej Jozefczyk (maciej.jozefczyk)
21:14:41 bauwser melwitt: https://review.openstack.org/#/c/540168/ +2d
21:14:54 bauwser call it a week
21:14:56 bauwser \o
21:27:38 tssurya mriedem : thank you, the issue we have looks related to the one you pointed.
21:32:32 openstackgerrit Matthew Edmonds proposed openstack/nova master: improve support matrix notes https://review.openstack.org/540534
21:46:58 yaaaaarwood mriedem: evening
21:47:21 yaaaaarwood mriedem: back for a few hours, finally worked out why I didn't see failures due to https://review.openstack.org/#/c/539739/ in my LM tests
21:48:13 yaaaaarwood mriedem: https://github.com/openstack/nova/blob/master/nova/virt/libvirt/migration.py#L153-L159 - without encryption_secret_uuid we just skip adding the encryption XML
21:48:22 yaaaaarwood mriedem: that's impossible to see in the logs at present
21:48:57 yaaaaarwood mriedem: mriedem the LM still completes, the instance just has an encrypted volume attached on the dest
21:49:51 mriedem unencrypted you mean?
21:50:26 yaaaaarwood yamahata: very much encrypted, the encrypted XML decrypts, without it the volume is presented as encrypted to the guest
21:50:36 yaaaaarwood encryption XML*
21:50:46 mriedem so is this another bug?
21:51:17 yaaaaarwood mriedem: no, it's not another bug
21:51:22 mriedem or just, the connection_info['volume_id'] was wrong but the LM tests weren't failing on it?
21:51:33 mriedem b/c ^reasons
21:52:01 yaaaaarwood mriedem: correct, without the volume_id set we didn't lookup the local secret and stash the UUID

Earlier   Later