| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2017-05-02 | |||
| 20:37:03 | jaypipes | mriedem: this onboarding thing is for potential new Nova contributors, yes? | |
| 20:37:21 | mriedem | jaypipes: that's my understanding | |
| 20:37:25 | jaypipes | kk | |
| 20:37:35 | jaypipes | mriedem: just wanted to make sure... | |
| 20:43:18 | openstackgerrit | Matt Riedemann proposed openstack/nova master: Transform instance.volume_attach notification https://review.openstack.org/401992 | |
| 20:43:19 | openstackgerrit | Matt Riedemann proposed openstack/nova master: Transform instance.volume_detach notification https://review.openstack.org/408676 | |
| 20:43:20 | openstackgerrit | Matt Riedemann proposed openstack/nova master: Transform instance.volume_attach.error notification https://review.openstack.org/455801 | |
| 20:46:56 | mriedem | ^ +2 on those 3 now | |
| 20:47:09 | mriedem | dansmith: did you figure out your dilemma yet? | |
| 20:57:16 | dansmith | mriedem: no | |
| 20:58:06 | dansmith | mriedem: I want to trace this delete call: http://logs.openstack.org/94/436094/23/check/gate-tempest-dsvm-neutron-linuxbridge-ubuntu-xenial/83b5f81/console.html#_2017-05-02_18_17_34_903731 | |
| 20:58:16 | dansmith | here's the api log: http://logs.openstack.org/94/436094/23/check/gate-tempest-dsvm-neutron-linuxbridge-ubuntu-xenial/83b5f81/logs/screen-n-api.txt.gz | |
| 20:59:01 | dansmith | the request-id for that is req-bc378dc5-41f0-4df8-95cf-4226ae088007 right? | |
| 20:59:06 | dansmith | so search for that in the api log, there is one hit | |
| 20:59:11 | dansmith | it's the return of the http call | |
| 20:59:23 | dansmith | but it should have been logged a bunch of times before that doing the actual delete | |
| 20:59:44 | dansmith | so, grab the instance uuid: 121af6e1-981e-4b5b-96c4-c9c19cd8b955 and search for that in the api log | |
| 21:00:14 | dansmith | the delete of that instance is here: http://logs.openstack.org/94/436094/23/check/gate-tempest-dsvm-neutron-linuxbridge-ubuntu-xenial/83b5f81/logs/screen-n-api.txt.gz#_May_02_17_55_49_123287 | |
| 21:00:24 | dansmith | four minutes after the http call returned | |
| 21:00:33 | dansmith | and with a different req-id | |
| 21:01:01 | dansmith | (brb) | |
| 21:08:28 | mriedem | dansmith: my guess would be the first delete request is ignored/lost somewhere in the api because the instance isn't in a cell yet, and the 2nd delete request is when the test tears down after a timeout | |
| 21:08:46 | mriedem | so when the first delete request comes in, i'm guessing we're building the instance in conductor | |
| 21:09:10 | dansmith | mriedem: it doesn't run any of the debugging messages that I have sprinkled throughout the delete-while-building code | |
| 21:09:46 | mriedem | do we know what the nova-osapi_compute is at all? | |
| 21:09:51 | mriedem | version i mean | |
| 21:10:10 | dansmith | what do you mean? that's not an upgrade test | |
| 21:10:32 | mriedem | i mean this check https://review.openstack.org/#/c/461513/2/nova/compute/api.py@1762 | |
| 21:11:15 | sdague | req-bc378dc5-41f0-4df8-95cf-4226ae088007 is the req id on the metadata server, right? | |
| 21:11:19 | dansmith | hmm, good point, I thought we removed that | |
| 21:11:49 | dansmith | sdague: why do you say that? | |
| 21:12:01 | mriedem | req-bc378dc5-41f0-4df8-95cf-4226ae088007 is the request id in the original response for DELETE | |
| 21:12:04 | mriedem | from what i can tell | |
| 21:12:11 | dansmith | yeah | |
| 21:12:40 | mriedem | dansmith: it's also odd that we don't see a debug message about fetching the instance for the original request | |
| 21:12:45 | mriedem | original DELETE request | |
| 21:12:46 | dansmith | right | |
| 21:12:59 | mriedem | so it seems that the compute api.get() method didn't find it | |
| 21:13:01 | sdague | oh, maybe, not the double host thing I guess is new? | |
| 21:13:01 | dansmith | or any of the other stuff I have added in my dependent patch | |
| 21:13:10 | sdague | that's weird, I wonder where that's coming from | |
| 21:13:13 | sdague | anyway, got torun | |
| 21:13:18 | mriedem | dansmith: but then we should get a 404 | |
| 21:13:19 | mriedem | not a 204 | |
| 21:13:27 | dansmith | mriedem: right | |
| 21:14:20 | mriedem | Fetching instance by UUID | |
| 21:14:22 | mriedem | is what i'd expect to see | |
| 21:15:46 | dansmith | yep | |
| 21:16:33 | mriedem | where did all of the "from (pid=16617)" and "from (pid=16616)" come from in the debug messages? | |
| 21:16:39 | mriedem | those aren't on the INFO messages | |
| 21:17:39 | dansmith | I think this must be from the systemd change | |
| 21:17:45 | dansmith | because those weren't in there a few days ago | |
| 21:17:48 | mriedem | https://github.com/openstack/oslo.log/commit/a5ee482ceeee78cc801b3419b9bc3efae04d0f26 | |
| 21:17:57 | openstackgerrit | OpenStack Proposal Bot proposed openstack/nova master: Updated from global requirements https://review.openstack.org/461446 | |
| 21:18:52 | mriedem | oslo.log 3.26.0 came into upper-constraints on 4/24 | |
| 21:19:34 | openstackgerrit | Abhishek Sharma M proposed openstack/nova master: Catching OverQuota Exception https://review.openstack.org/460305 | |
| 21:21:42 | dansmith | mriedem: sdague is pinging me through another channel whilst elevating the temperature of dead animal flesh exterior to his home | |
| 21:22:03 | dansmith | mriedem: about the possibility of an interaction between the journal logging calls when we're using eventlet | |
| 21:22:07 | dansmith | like blocking the process | |
| 21:22:11 | dansmith | which is kindof interesting | |
| 21:22:27 | mriedem | ok | |
| 21:22:30 | mriedem | that sounds super fun | |
| 21:22:39 | dansmith | not so much | |
| 21:22:52 | mriedem | also, these giant journal zips produced in the jobs now, how does one read those? | |
| 21:23:08 | dansmith | with journalctl Iimagine | |
| 21:23:12 | mriedem | oh journalctl | |
| 21:23:13 | mriedem | yeah | |
| 21:35:23 | mriedem | dansmith: so you're hitting this race and can't debug it b/c of the systemd thing? | |
| 21:35:41 | mriedem | or you think the systemd thing is causing the problem? | |
| 21:36:19 | dansmith | mriedem: I can't repro it locally, and the gate was hitting it on the base job repeatedly until I started adding debug to chase it dwn | |
| 21:36:42 | dansmith | now only one of the jobs seems to hit it, but yeah, I'm wondering why my messages aren't showing up to figure out how to debug further | |
| 21:37:35 | melwitt | sdague, mriedem, sfinucan: fyi, neither LC_ALL nor PYTHONIOENCODING are helping the issue with the log traces. back to the drawing board | |
| 21:39:08 | mriedem | what else doesn't work? | |
| 21:39:14 | mriedem | right now | |
| 21:41:32 | mriedem | given this is the first day i've seen the sun in about a week i think i'm just going to go outside and grill too | |
| 21:43:11 | melwitt | enjoy the outdoors, vampire | |
| 21:49:11 | openstackgerrit | melanie witt proposed openstack/nova master: WIP Use six.text_type() when logging Instance object https://review.openstack.org/461912 | |
| 22:00:01 | stvnoyes | summit | |
| 22:00:07 | stvnoyes | boston | |
| 22:00:30 | stvnoyes | pls ignore^^^ ;-) | |
| 22:38:44 | openstackgerrit | melanie witt proposed openstack/nova master: WIP Use six.text_type() when logging Instance object https://review.openstack.org/461912 | |
| 23:45:53 | mriedem | melwitt: i tried the six.text_type thing in a python shell earlier today and that won't solve it, like you said | |
| 23:46:14 | mriedem | at least i don't think so | |
| 23:47:05 | mriedem | melwitt: what i was going to try was doing encodeutils.safe_encode(value, incoming='utf-8') here https://github.com/openstack/oslo.versionedobjects/blob/master/oslo_versionedobjects/fields.py#L269 | |
| 23:47:29 | mriedem | because i think that's where the unicodedecodeerror starts | |
| 23:48:09 | melwitt | mriedem: yeah, I just tried the same thing with a WIP patch in the gate and it didn't help. I'm digging into what's going on. the __repr__ function for ovo returns a bytes string for python2 | |
| 23:49:11 | melwitt | and I can get the same error by just doing a unicode(instance object) or unicode(str(instance object)). I don't yet understand the connection to the logger | |
| 23:50:12 | mriedem | maybe it's something with the systemd log handler stuff that was in the latest oslo.log that started getting used in upper-constraints yesterday | |
| 23:50:13 | melwitt | it's blowing up during the emit() where it does a self.format(record), whatever format is doing causes it to blow up if there's unicode in the instance string | |
| 23:54:02 | mriedem | melwitt: umm, doesn't this look odd? https://github.com/openstack/oslo.log/blob/master/oslo_log/handlers.py#L95 | |
| 23:54:11 | mriedem | note that before the py2 conditional, it formats the record w/o encoding it | |
| 23:54:39 | melwitt | yeah, I was just looking at the same thing | |
| 23:55:10 | mriedem | it also seems the OSJournalHandler should be doing something similar | |
| 23:55:11 | melwitt | but, it's not that handler that I saw blowing up in the gate, it's the OSJournalHandler at L120 | |
| #openstack-nova - 2017-05-03 | |||
| 00:00:32 | melwitt | the instance string repr is a bytes string in python2, that's what the safe_encode does in the __repr__ function in ovo. the instance.display_name is of type unicode. I don't know if that's relevant to what's happening here | |
| 00:05:15 | mriedem | ooo fun i pulled the journal file down from a failed job and i'm poking through the nova-compute logs using journalctl | |
| 00:06:59 | melwitt | super fun | |
| 00:07:22 | melwitt | the OSJournalHandler is new as of about a month ago, fwiw | |
| 00:07:33 | mriedem | yeah | |
| 00:08:08 | melwitt | if the syslog one was the old default, it seems like it should have been making the same traces. I don't know what the old handler was | |