Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2017-05-02
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 dansmith or any of the other stuff I have added in my dependent patch
21:13:01 sdague oh, maybe, not the double host thing I guess is new?
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
01:27:54 openstackgerrit melanie witt proposed openstack/nova master: WIP Use six.text_type() when logging Instance object https://review.openstack.org/461912
01:37:07 openstackgerrit Zhenyu Zheng proposed openstack/nova master: Support tag instances when boot(3/4) https://review.openstack.org/459593
02:19:03 openstackgerrit jichenjc proposed openstack/nova master: Use plain routes list for limits endpoint instead of stevedore https://review.openstack.org/458805
02:19:04 openstackgerrit jichenjc proposed openstack/nova master: Use plain routes list for hosts endpoint instead of stevedore https://review.openstack.org/459231
02:19:04 openstackgerrit jichenjc proposed openstack/nova master: use plain routes list for hypervisor endpoint instead of stevedore https://review.openstack.org/459235
02:21:40 openstackgerrit jichenjc proposed openstack/nova master: Use plain routes list for os-instance-usage-audit-log endpoint instead of stevedore https://review.openstack.org/461647

Earlier   Later