| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2017-06-06 | |||
| 19:01:13 | mriedem | maybe it's something in oslo.log? | |
| 19:01:48 | mriedem | sdague: wasn't there something done with oslo.log recently to put extra metadata in messages or something? | |
| 19:02:58 | mriedem | this error summary stuff | |
| 19:03:26 | mriedem | + error." | |
| 19:03:26 | mriedem | "If the log format string - does not include ``%(error_summary)s`` it will be appended to the end + does not include ``%(error_summary)s`` the error summary will be - of the line automatically, only if there is an error. + appended to the end of the line automatically, only if there is an | |
| 19:03:49 | sdague | yeh, the NotImplementedError stuff is bleeding through there, that's going to need to be a dhellman ask | |
| 19:04:03 | sdague | that was only supposed to happen if we were in an active exception block | |
| 19:04:40 | mriedem | i'm pinging him in -oslo | |
| 19:04:44 | sdague | I think that's irrelevant and just bleed over because that was the last exception thrown | |
| 19:04:47 | clarkb | not to interrupt but looks like the nova python35 job is failing a lot and reseting things in the gate? | |
| 19:05:04 | sdague | clarkb: not really | |
| 19:05:11 | clarkb | http://logs.openstack.org/71/465171/11/gate/gate-nova-python35/2fcc59a/console.html#_2017-06-06_14_57_13_022429 and http://logs.openstack.org/89/418489/10/gate/gate-nova-tox-functional-py35-ubuntu-xenial/51b5776/console.html#_2017-06-06_13_35_33_574055 appear to be two different classes of error | |
| 19:05:30 | sdague | clarkb: there was one bad patch, and because the gate was taking a long time and other things were running a lot, it managed to run and fail a lot in the gate | |
| 19:05:35 | clarkb | gotcha | |
| 19:05:51 | sdague | this is the params one? | |
| 19:06:02 | sdague | man, the log server seems slow today | |
| 19:06:19 | mriedem | i blame systemd | |
| 19:06:26 | mriedem | er journald :) | |
| 19:06:30 | mriedem | somethingd | |
| 19:06:32 | sdague | yeh, the wrong params to __init__ was just a patch with out of date tests | |
| 19:06:33 | clarkb | sdague: mriedem its less that the log server is slow and that its a 12MB html file | |
| 19:06:44 | clarkb | sdague: the second one is a different error fwiw | |
| 19:06:50 | mriedem | i kid | |
| 19:07:45 | sdague | clarkb: it's actually the same thing | |
| 19:08:00 | sdague | https://review.openstack.org/#/c/418489/ needs work | |
| 19:08:08 | sdague | stuff was probably behind it and failing | |
| 19:09:44 | mriedem | here is the oslo.log bug https://bugs.launchpad.net/oslo.log/+bug/1696213 | |
| 19:09:45 | openstack | Launchpad bug 1696213 in oslo.log "error summary formatter is putting ": NotImplementedError" in non-error log messages" [Undecided,New] | |
| 19:10:03 | mriedem | back to this rebuild failure | |
| 19:14:44 | mriedem | http://logs.openstack.org/82/471082/1/gate/gate-novaclient-dsvm-functional-neutron-ubuntu-xenial/796acb7/logs/screen-n-cpu.txt.gz#_Jun_06_13_19_17_300332 | |
| 19:14:44 | mriedem | sdague: i see the problem | |
| 19:14:49 | mriedem | vif plugging callback timeout | |
| 19:14:50 | mriedem | during rebuild | |
| 19:14:53 | mriedem | so the instance never goes active | |
| 19:15:26 | mriedem | which someone from heat reported a rebuild bug about vif plug timeouts recently | |
| 19:16:05 | openstack | Launchpad bug 1694371 in OpenStack Compute (nova) "test_stack_snapshot_restore failing intermittently" [Undecided,New] | |
| 19:16:05 | mriedem | https://bugs.launchpad.net/nova/+bug/1694371 | |
| 19:17:54 | openstack | Launchpad bug 1694371 in OpenStack Compute (nova) "Timeout while waiting for network-vif-plugged event during server rebuild" [Undecided,New] | |
| 19:17:54 | mriedem | kevinbenton: we probably need some help from the neutron side here https://bugs.launchpad.net/nova/+bug/1694371 | |
| 19:18:06 | mriedem | kevinbenton: seeing rebuild tests timeout waiting for vif plugged events from neutron | |
| 19:22:19 | mriedem | dansmith: does it make sense to do anything in nova.objects.Instance.mutated_migration_context if there is no self.migration_context? | |
| 19:22:31 | mriedem | because we're lazy-loading 3 fields in there just to do nothing | |
| 19:23:03 | dansmith | um | |
| 19:23:11 | mriedem | i'm seeing this during a rebuild | |
| 19:23:13 | mriedem | where we're not migrating | |
| 19:23:21 | mriedem | but the rebuild code also handles evacuate, which is the migration | |
| 19:23:42 | mriedem | but it loos like we end up lazy-loading numa_topology, pci_requests and pci_devices one after another just to ultimately do nothing | |
| 19:24:48 | dansmith | yeah I guess not.. you see that debug log warning that there's no context too I guess? | |
| 19:25:27 | mriedem | http://logs.openstack.org/82/471082/1/gate/gate-novaclient-dsvm-functional-neutron-ubuntu-xenial/796acb7/logs/screen-n-cpu.txt.gz#_Jun_06_13_14_02_547424 | |
| 19:25:31 | mriedem | yup | |
| 19:25:32 | cfriesen_ | mriedem: if you're not actually migrating I think it'd be safe to bypass the mutated_migration_context | |
| 19:25:35 | mriedem | see the next 4 there | |
| 19:25:45 | mriedem | it lazy-loads 3 fields, and then says "you're dumb" | |
| 19:26:19 | mriedem | and i believe each lazy-load on those fields is going to be a full pull from the db via conductor... | |
| 19:27:58 | kevinbenton | mriedem: in a rebuild what does nova tell neutron? | |
| 19:28:06 | kevinbenton | mriedem: because the host_id doesn't change, right? | |
| 19:28:48 | cfriesen_ | mriedem: can a rebuild end up picking a new host? | |
| 19:29:46 | cfriesen_ | (when we're not doing an evacuate, I mean) | |
| 19:30:23 | mriedem | cfriesen_: kevinbenton: no, same host | |
| 19:30:35 | cfriesen_ | mriedem:, right, we specify the host in that case | |
| 19:30:39 | mriedem | kevinbenton: so my theory is neutron is not sending the event maybe because the host doesn't change | |
| 19:30:57 | mriedem | but i'd think that would be 100% fail | |
| 19:31:28 | mriedem | so i wonder if we're hitting a race where neutron is queueing notifications and thinks it already told nova something about a given port | |
| 19:32:29 | kevinbenton | mriedem: we did have a recent change on the neutron side that reduced some port status changes when they weren't needed | |
| 19:32:58 | kevinbenton | mriedem: so it's possible that there is a race that was being covered by side effects from that before | |
| 19:33:35 | kevinbenton | mriedem: do you have a set of logs from one of these failures? | |
| 19:35:25 | mriedem | kevinbenton: yeah that bug linked above has a log dive from me | |
| 19:35:30 | mriedem | showing where things happen on the nova side | |
| 19:37:43 | efried | sdague Can you please help me understand whether/how global_request_id affordance is needed in https://review.openstack.org/#/c/412634/28/nova/image/glance.py ? | |
| 19:38:25 | efried | I'm kinda hoping it's implicitly part of the ksa session... | |
| 19:38:45 | efried | ...or auth | |
| 19:40:38 | efried | ...because of the context | |
| 19:49:39 | openstackgerrit | Eric Fried proposed openstack/nova master: Adopts keystoneauth with glance client. https://review.openstack.org/412634 | |
| 19:49:50 | openstackgerrit | Eric Fried proposed openstack/nova master: Add service_token for nova-glance interaction https://review.openstack.org/419662 | |
| 19:51:26 | sdague | efried: it's not implicit | |
| 19:52:08 | efried | sdague So I need to add the header explicitly? | |
| 19:52:08 | sdague | efried: it's a single parameter to pass | |
| 19:52:17 | sdague | one sec | |
| 19:52:53 | sdague | efried: https://review.openstack.org/#/c/467242/6/nova/image/glance.py | |
| 19:53:10 | efried | sdague Right, I'm rebasing against that. | |
| 19:53:18 | efried | sdague But in the new version, we don't do any of that stuff. | |
| 19:53:32 | sdague | efried: yeh, so just add global_request_id=context.global_id | |
| 19:53:50 | sdague | to the constructor args for glanceclient.Client | |
| 19:54:23 | efried | sdague Okay, will do. Thanks. | |
| 19:54:43 | sdague | like this - https://github.com/openstack/nova/blob/2f712b84ecf8d149833dea17d2fa4b78ae9442c9/nova/volume/cinder.py#L105 | |
| 19:54:57 | openstackgerrit | Matt Riedemann proposed openstack/nova master: libvirt: log vm and task state when vif plugging times out https://review.openstack.org/471459 | |
| 19:54:59 | sdague | efried: cool | |
| 19:55:25 | efried | sdague But makes a guy wonder why the client couldn't grab it from the auth, which is made from the context, which contains that request ID... | |
| 19:56:26 | sdague | it could be more magical | |
| 19:56:41 | sdague | but, being explicit here seems fine | |
| 19:57:14 | efried | ight | |
| 19:57:34 | sdague | given that it was a one line change for each service linkage, being explicit didn't seem so bad :) | |
| 19:58:23 | efried | sdague But a zero-line change would have been cooler ;-) | |
| 19:59:21 | mriedem | 0-line change means non-0 amount of debugging in 2 years time | |
| 19:59:24 | mriedem | b/c of magic | |
| 20:00:34 | sdague | mriedem: ++ | |
| 20:00:35 | efried | sdague How/where does global_id get set on a RequestContext? | |
| 20:00:54 | sdague | it's a property which is either global_request_id or request_id | |
| 20:01:07 | sdague | so it prefers global_request_id if that was sent in | |
| 20:01:17 | sdague | otherwise it uses the service request id | |