| Posted | Nick | Remark | |
|---|---|---|---|
| #openstack-nova - 2017-10-12 | |||
| 22:39:06 | dansmith | if that's really happening, we have a huge problem I think, but I don't understand how that could be | |
| 22:39:13 | melwitt | during the instance read, instance write was trying to happen in the same DB transaction | |
| 22:39:33 | melwitt | and I saw the read was happening in the quota check (scatter gather) | |
| 22:40:07 | melwitt | so while it was checking quota, the instance.save() of the resize (I think it was) failed mid-transaction bc it was trying to upgrade the read from the quota check to a write for the instance save | |
| 22:40:16 | dansmith | if this is a problem, it should be a problem with a single cell right? | |
| 22:40:28 | melwitt | yeah, the test setup was cell0 and cell1 | |
| 22:41:07 | dansmith | what I mean is before we were doing any cell switching | |
| 22:41:36 | melwitt | oh. yeah I mean I definitely see your point there and I currently don't understand how that isn't an issue | |
| 22:41:39 | dansmith | I don't think this has anything to do with the number of cells you have since it's all per-cell and as we established above, the cache isn't even synchronized across all, it's just on the one cell you're trying to populate | |
| 22:41:56 | melwitt | like, is there something different about us rolling our own green threads via spawn? | |
| 22:42:04 | dansmith | no | |
| 22:42:15 | dansmith | it would be in our handling of the db context manager if anything | |
| 22:42:48 | melwitt | yeah I agree nothing to do with number of cells | |
| 22:42:59 | dansmith | so | |
| 22:43:23 | melwitt | I had thought it was being two threads were trying to use the same context manager at the same time, but that doesn't make sense for the old style "main context manager" that's used by everything | |
| 22:43:32 | melwitt | like you said | |
| 22:43:42 | dansmith | it also doesn't make sense since both threads are using different ones | |
| 22:43:49 | dansmith | for the two cells | |
| 22:44:02 | dansmith | can you -W the backport or something so we don't merge this until we figure out what's going on? | |
| 22:44:45 | melwitt | they were using the same one in this test bc it was a unit test. untargeted context was going to same database cell0 (with my change to default to cell0) | |
| 22:44:50 | melwitt | okay | |
| 22:45:06 | dansmith | and you were scattering to cell0 as well? | |
| 22:45:16 | sapd_ | I can't fix this error! | |
| 22:45:31 | sapd_ | Can you give me any suggest :(( | |
| 22:46:26 | melwitt | dansmith: yes. scattering to cell0 and cell1 but since it was a unit test calling resize directly, there was no targeting | |
| 22:46:55 | melwitt | quota check scatters regardless I mean. the context passed to the resize was not targeted so it was trying to save the instance in cell0 | |
| 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? | |