Earlier  
Later
New Search
Posted Nick Remark
#openstack-nova - 2017-10-12
22:47:04 dansmith melwitt: so it was a unit test, where were the get and save that were conflicting?
22:47:36 dansmith okay resize was doing the save untargeted,
22:47:39 melwitt dansmith: the get was in the quota check for the new flavor, the save was trying to save the state of the instance for the resize
22:47:43 melwitt right
22:48:07 dansmith but how in a unit test could those be going on at the same time?
22:48:10 dansmith all in the same test right?
22:49:13 melwitt yeah. well, not using SpawnIsSynchonous, real green threads were started for the quota check. but the result should be waited for before proceeding to the save.
22:49:22 dansmith right
22:49:39 melwitt so oslo.db caches "TransactionContext" objects thread locally
22:50:22 melwitt and there was on in there and it was set to read mode, then the save found it and failed when it saw the conflict of trying to do a write mode
22:50:36 melwitt *one in there
22:51:00 dansmith you mean you were in the save, and there was already a transaction context, and you traced that back to the scatter?
22:51:39 melwitt yeah. things worked fine without the scatter involved
22:51:56 dansmith what I mean is, how did you examine that transaction context to know it was from the scatter?
22:52:06 dansmith and where locally does it cache it?
22:52:19 dansmith like in context.db_connection.something ?
22:52:26 melwitt I didn't see a way to link it to the scatter. one sec
22:52:54 melwitt this https://github.com/openstack/oslo.db/blob/master/oslo_db/sqlalchemy/enginefacade.py#L997-L1041
22:53:27 melwitt is how oslo.db does a transaction scope. and what I was seeing is it pulls a transaction context by thread, if it has one, and uses that if it finds it
22:53:33 dansmith that looks like it caches it in TLS,
22:53:36 dansmith which is what I'd expect
22:53:44 melwitt and it was finding one that was in read mode, and it tried to use it to write for the save and it blew up
22:53:59 dansmith right which should mean each thread has its own context, which is the only way this could not be broken :)
22:54:54 dansmith https://github.com/openstack/oslo.db/blob/master/oslo_db/sqlalchemy/enginefacade.py#L1085
22:55:05 melwitt when the transaction goes out of scope, it destroys the cached context for the thread
22:55:21 dansmith right
22:55:24 melwitt but it wasn't destroying it (from the read) and it was using it for a write
22:55:29 melwitt tried to use it for a write
22:56:22 dansmith see, if it wasn't for the report in the wild just now,
22:56:28 melwitt yeah, I saw that too. I was thinking it seemed like two threads were in the transaction scope at the same time and messing up each other. which I don't really get if it's one context per thread
22:56:43 dansmith well, if they share a context it makes perfect sense
22:57:04 dansmith see, if it wasn't for the report in the wild just now, I'd say this was likely a bug in our overriding of some of these methods in the fixture
22:57:40 dansmith however, now I'm wondering if we're doing a copy.copy() of a context with a stale per-thread transactioncontext somewhere and keeping it around
22:57:46 dansmith orrrrr
22:57:48 melwitt so you think handing each thread a copy of the context should fix it? I thought we're already doing that before my change
22:57:48 dansmith hmm
22:57:55 dansmith yeah we are
22:57:57 dansmith BUUUT
22:58:29 dansmith we're doing copy.copy() in target_cell(), I wonder if we need a copy.deepcopy() to avoid linking threads together by copying contexts but not deep into the db connection thing
22:58:35 dansmith like a bad std making it around campus
22:59:21 melwitt hm, yeah. damn
22:59:22 dansmith is that context._enginefacade_context setting that on RequestContext or TransactionContext or something else?
22:59:30 dansmith I've lost track this deep in the rabbit hole
22:59:40 melwitt setting the mode?
22:59:55 dansmith must be requestcontext no?
23:00:11 dansmith no the line I linked above, setting the thread-local thing
23:00:38 dansmith also, in your example, you said your context would have already been targeted to cell0,
23:00:43 melwitt oh, I see. uh, yeah it's so hard to tell.
23:00:51 dansmith but you mean untargeted and thus pointing at cell0 by virtue of the config right?
23:00:59 dansmith I wonder if we should do two things:
23:01:04 melwitt but it's probably RequestContext like you said
23:01:22 melwitt yes, untargeted but going to cell0 by config
23:01:25 dansmith 1. Make target_cell freak out or log a warning if we try to target a targeted cell, at least to see if we do that anywhere
23:01:38 dansmith 2. copy.deepcopy() in that mofo
23:01:40 dansmith and maybe
23:01:52 melwitt yeah that thing is being set on RequestContext
23:02:02 dansmith 3. Check for context._enginefacade_context before the copy and log another warning
23:02:22 melwitt yeah, sounds like a plan
23:02:55 dansmith I'm also mildly skeptical of reproducing this in a unittest environment and not introducing other unrealistic situations,
23:03:06 dansmith but since you have a reproducer for that, I guess it's the best place to start
23:03:12 dansmith but I reserve the right to object to fakery
23:03:26 melwitt heh
23:04:22 melwitt dansmith: okay. I really have to run out for an appointment right now. did you want to run with those changes? otherwise I can try them out later after I'm back
23:04:46 dansmith melwitt: i have to run too, but when I'm back I can put up a patch if you can try testing against it
23:05:32 melwitt dansmith: yep, can do. thanks for the brain-crushing discussion
23:05:52 melwitt ditto
23:16:08 dansmith sapd_: anything weird about your deployment that would be a clue as to why you're seeing this?
23:16:15 dansmith sapd_: that's even more puzzling tome
23:16:24 dansmith sapd_: only one main cell I assume right?
23:17:44 sapd_ yes. I have only one cell, cell1 and 3 dbs for nova - nova-api , nova_cell0. nova_cell1
23:20:16 dansmith sapd_: and you see that transaction message when? on every list? when listing during other activity?
23:21:27 sapd_ when I use to listing instance, though I can use horizon normal.
23:24:40 dansmith sapd_: does that mean
23:24:49 dansmith listing from the command line only?
23:26:44 Kevin_Zheng https://review.openstack.org/#/c/509326
23:27:10 openstackgerrit Takashi NATSUME proposed openstack/nova master: Add 'delete_host' command in 'nova-manage cell_v2' https://review.openstack.org/510324
23:27:33 Kevin_Zheng mriedem ^ could you review this one again?
23:37:05 openstackgerrit Merged openstack/nova stable/pike: Ensure instance can migrate when launched concurrently https://review.openstack.org/508591
23:39:45 openstackgerrit Dan Smith proposed openstack/nova master: Deepcopy context during targeting, and sanity check some things https://review.openstack.org/511651
23:43:07 openstackgerrit Merged openstack/nova master: Add missing tests for _remove_deleted_instances_allocations https://review.openstack.org/496847
#openstack-nova - 2017-10-13
00:12:52 openstackgerrit Dan Smith proposed openstack/nova master: Regenerate context during targeting, and sanity check some things https://review.openstack.org/511651
00:24:03 openstackgerrit Dan Smith proposed openstack/nova master: Regenerate context during targeting, and sanity check some things https://review.openstack.org/511651
00:50:02 openstackgerrit Merged openstack/nova master: Make TestRPC inherit from the base nova TestCase https://review.openstack.org/507239
01:16:11 sapd_ dansmith, listing from command :D
01:16:56 dansmith sapd_: is anything else going on on the cloud when you're doing this btw?
01:17:05 dansmith sapd_: also is it only when you do --all-tenants?
01:17:38 sapd_ no, When I use normal user, I get this error too.
01:30:01 dansmith sapd_: you could try applying this: https://review.openstack.org/#/c/511651/
01:30:12 dansmith sapd_: back out the other change and apply this, api and conductor nodes at least
01:35:57 openstackgerrit Chen Hanxiao proposed openstack/nova master: libvirt: properly decode error message from qemu guest agent https://review.openstack.org/511459
01:47:50 sapd_ When I turn on DEBUG mode, I see Generated UUID 7bfa7fa8-ea0b-43bd-9b13-ffb1f92806a1 for service 67 _from_db_object /usr/lib/python2.7/dist-packages/nova/objects/service.py:245
01:48:15 sapd_ But service with id 67 was nova-compute ocata, and It was deleted dansmith
01:48:31 sapd_ The new service with id 95
01:51:20 sapd_ The compute name is compute-1, I saw three records in services table in nova_cell1 database
02:00:08 alex_xu efried: the aggregate/shared is the most complex part, previous implementation is using the sql building the mapping between shared rp and root rp, currently we move that into the python code
02:00:54 alex_xu efried: the basic logic is ensure the correct combination of the root rp and shared rp, and find out the traits in those combination
02:03:50 sapd_ hi dansmith! I fixed that error, I deleted two records of a compute service.
02:07:18 alex_xu gmann: fyi, we got some feedback from nova meeting http://eavesdrop.openstack.org/meetings/nova/2017/nova.2017-10-12-21.00.log.html#l-90
02:15:59 gmann alex_xu: yea i saw. i will update BP/spec accordingly
02:22:27 alex_xu gmann: thanks

Earlier   Later