| 00:00.21 | *** join/#storm _mup_ (~mup@li37-90.members.linode.com) |
| 00:27.52 | *** join/#storm fcorrea (~fcorrea@71.16.235.2) |
| 01:39.13 | *** join/#storm stub (~stub@110.49.249.48) |
| 01:39.14 | *** join/#storm stub (~stub@canonical/launchpad/stub) |
| 03:07.54 | *** join/#storm lifeless (~robertc@121-72-80-56.dsl.telstraclear.net) |
| 04:57.18 | *** join/#storm stub (~stub@canonical/launchpad/stub) |
| 05:15.43 | *** join/#storm stub (~stub@canonical/launchpad/stub) |
| 07:02.45 | *** join/#storm lifeless (~robertc@122.58.129.196) |
| 09:20.17 | *** join/#storm chriswhit (~chriswhit@5adbca7b.bb.sky.com) |
| 09:20.24 | *** part/#storm chriswhit (~chriswhit@5adbca7b.bb.sky.com) |
| 15:56.06 | *** join/#storm jkakar (~jkakar@wsip-24-234-121-106.lv.lv.cox.net) |
| 16:39.12 | *** join/#storm keppla (~keppla@p4FD4737D.dip.t-dialin.net) |
| 20:43.17 | *** join/#storm milosn (~milosn@cpc12-rdng20-2-0-cust598.15-3.cable.virginmedia.com) |
| 20:43.41 | milosn | hey stormers :D |
| 20:45.45 | milosn | i was just wondering when its appropriate to call store.flush() manualy, reason i am asking ... i am using storm in my web application, and in particular page i am doing updates/inserts via storm and immidietly after calling a refresh of certain part of the page via AJAX |
| 20:46.16 | milosn | what i observed is diplay of staled data, not always but it does happen at times |
| 20:47.01 | milosn | and this is in my sandbox, i assume the behavior can only worsen when application is live and under a bit more load |
| 20:48.32 | milosn | updates/inserts happen in a thread, store.commit() is called at the end ... when that AJAX call returns JSON response i do a refresh of one part of the page, and thats when i get stale data displayed |
| 20:48.53 | milosn | hope thats clear enough explanation of what happens ;) |
| 20:50.06 | milosn | backend i am using is postgres |
| 20:52.43 | marienz | milosn: if you've already called commit() also calling flush() shouldn't make a difference |
| 20:53.04 | milosn | hmmm |
| 20:53.20 | marienz | milosn: flush() exists primarily to get stuff flushed to the db before calling commit(), which can be necessary for any server-side actions to happen (ids generated, that kind of thing) |
| 20:53.33 | milosn | i see |
| 20:53.53 | marienz | milosn: I've not used storm in the kind of way you're using it, but this sounds to me as if your other thread is getting cached data, through it having started its transaction before your other thread committed |
| 20:55.06 | milosn | isnt call to store.commit() blocking? |
| 20:55.21 | marienz | milosn: if I'm right a possible fix will be to always commit at the end of each request, even if you didn't write to the store in it |
| 20:55.35 | marienz | milosn: (that is: if you just read data) |
| 20:55.50 | milosn | i already do that, always commit |
| 20:56.12 | marienz | milosn: then I don't quite see what might be going on |
| 20:56.44 | milosn | as i said, thread that does inserts/updates finishes ... only after its done doing what its doing the json response is generated and i get response in my app, only after that i refresh the part of the page |
| 20:57.05 | marienz | store.commit() does three things (this is literally from the code): flush(), invalidate() the store's cache, and commit() the underlying db connection |
| 20:57.07 | milosn | so it could be some caching bug in storm |
| 20:57.20 | milosn | hmm yeah i understand |
| 20:57.35 | marienz | it could certainly be caching, but without some kind of failing test I'm not going to assume it's a storm bug :) |
| 20:57.35 | milosn | is it possible to tell storm to never use cached data? |
| 20:57.42 | milosn | ok ok :) |
| 20:57.44 | milosn | i agree |
| 20:57.47 | marienz | I rather doubt that's a good idea |
| 20:57.59 | marienz | commit() throws out any cached objects the store has |
| 20:58.07 | milosn | hmmm |
| 20:58.19 | marienz | which database is this? |
| 20:59.34 | milosn | and this is in particularly sensitive part of the application, i do a refund on the credit card transaction and mark the transaction as refunded, reload the page to show new status ... but for some reason the data displayed is stale, as if the transaction was not refunded :D |
| 20:59.44 | milosn | basicaly showing my refund button again :P |
| 20:59.59 | milosn | its postgres |
| 21:00.55 | milosn | i added checks in the refund code, but if there is a "stale window" wide enough to re-display the data ... |
| 21:01.11 | milosn | theoreticaly its wide enough to refund twice |
| 21:01.14 | milosn | or more times :) |
| 21:01.24 | marienz | then my guess would be (but note I've barely used postgres!) the problem is storm is using serializable transactions and your transaction started at the end of the previous request rather than the start of the current one |
| 21:02.27 | milosn | hmmm not sure i follow that last thing ... give me a second |
| 21:03.24 | marienz | storm (starting from 0.10) defaults backends to SERIALIZABLE unless explicitly told not to |
| 21:03.51 | marienz | the postgresql documentation (for 8.2, but presumably other versions too) confirms "a SELECT query sees only data committed before the transaction began" |
| 21:04.21 | marienz | I am not sure if the postgresql transaction actually begins after commit rather than the first time you actually hit the db, but it certainly seems possible |
| 21:04.30 | marienz | (and it'd explain what you see) |
| 21:04.50 | milosn | hmmm |
| 21:05.03 | marienz | if I'm right then a commit at the start of each request would help |
| 21:05.13 | marienz | note it's entirely possible I'm *not* right |
| 21:07.54 | marienz | ah, the psycopg docs indicate I'm not entirely right: the transaction should start on the first actual query, not when you commit the previous one |
| 21:08.13 | marienz | still, this is what I'd check for: your thing seeing stale data being in a transaction started before your other request committed |
| 21:09.33 | milosn | i dont think thats possible, DB modifying code is in one thread in one web request, select code is in complitely new thread in complitely new request |
| 21:09.56 | milosn | second request only happens after the first returns :) |
| 21:10.01 | milosn | i am positive on that |
| 21:10.24 | milosn | so i dont understand how the second transaction starts before the first finishes |
| 21:10.41 | milosn | unlesl postgres backend does something funky :P |
| 21:10.42 | marienz | and that new thread constructs a completely fresh storm store? |
| 21:11.16 | milosn | stores are cached on the thread object, threads are pooled by twisted |
| 21:11.24 | milosn | basicaly its twisted application |
| 21:11.27 | marienz | great |
| 21:11.59 | marienz | so it's not necessarily technically a new thread, it may be reusing a pooled thread. Are you sure that all possible previous uses of that thread will have committed, and will not have done anything to the db after committing? |
| 21:12.02 | milosn | so i would not bet its fresh, because i would assume its called thread pool for a reason :) |
| 21:12.07 | marienz | exactly |
| 21:12.37 | marienz | I'd probably turn on query logging and try to make sure transactions start when they should |
| 21:13.20 | milosn | i am postive that either 1) store.flush() 2) store.rollback() is called at the end of each use of store |
| 21:13.28 | marienz | flush() doesn't end the transaction |
| 21:13.33 | marienz | did you mean commit? |
| 21:13.58 | marienz | you want either commit or rollback at the end of each use |
| 21:14.43 | milosn | ah sorry, yes, commit() |
| 21:14.45 | milosn | http://pastie.org/2784644 |
| 21:15.01 | milosn | all my store stuff is wrapped in transact() |
| 21:15.36 | milosn | so its either commit()-ed or rollback()-ed |
| 21:17.19 | marienz | and fn completes synchronously? |
| 21:18.13 | milosn | yes fn contains my storm code |
| 21:18.30 | marienz | I don't think I can really figure this out without failing code. I do recommend you try to reproduce it with storm's logging on so you can see if there's anything suspicious ordering-wise across threads |
| 21:18.32 | milosn | and it executes inside thread and its all sync code |
| 21:19.06 | marienz | also, doublecheck everything's using the right store |
| 21:19.20 | marienz | I find it a little suspicious your transact decorator isn't passing fn the store it should use |
| 21:19.36 | marienz | if you have a getStore call sitting outside the decorated fn it'll run on the wrong thread |
| 21:19.48 | milosn | yeah i know, it never happens :) |
| 21:20.12 | milosn | its always used inside the "right" thread, so store is the same |
| 21:20.19 | milosn | i have no bugs regrading that |
| 21:20.27 | marienz | I am surprised by your optimism |
| 21:20.34 | milosn | basicaly stale data happens with 2 different requests |
| 21:20.45 | milosn | which is what i found surprising |
| 21:20.51 | marienz | I can't figure out off the top of my head without trying if it'll fail obviously if you get that wrong |
| 21:21.27 | milosn | marienz: i will try to reproduce the behavior i am seeing with simplified example |
| 21:21.34 | milosn | no twisted and web and what not |
| 21:22.08 | marienz | anyway, I recommend you experiment with storm.tracer.debug to make sure everything's happening in the right order (and nothing starts a transaction too early), and see if you can simplify it down |
| 21:22.22 | marienz | I don't mind twisted.web at all, but something others can run will help you get this debugged |
| 21:22.47 | marienz | (I guess it could be something much higher-level going wrong, causing your read request to start before your other request has actually committed) |
| 21:29.34 | milosn | if store.commit() is sync, that should not happen :) |
| 21:30.20 | milosn | unless, there is a bug in twisted or storm someplace ... or, after all, in my code, which i fail to see atm (the bug) |
| 21:30.26 | milosn | not perfect |
| 21:30.27 | milosn | :D |
| 21:31.16 | milosn | ill try to reproduce in simple script, so ill get something pasted for you guys to have a look in next couple of days |
| 21:36.37 | marienz | well, if you're not waiting for your deferToThread deferred to call back before you send stuff back to the browser... |
| 21:36.50 | milosn | marienz: http://pastie.org/2784735 ... relevant application code, probably wont make much sence, but store is the same |
| 21:37.15 | milosn | lot of verbose error checking since i am trying to get around stale data issue :) |
| 21:40.40 | milosn | marienz: i do wait for the thread, json response is generated at the end of the thread in a callback |
| 21:40.52 | marienz | nods |
| 21:41.04 | marienz | I'll just shut up now, I doubt I can contribute anything useful I haven't already said at this point |
| 21:42.40 | milosn | hmmm, ill get back to you with simplified example, if i manage to reproduce it |
| 22:17.02 | milosn | marienz: now i tried about 50-ish times to get the stale data behaviour in the browser and i cant ... strange |
| 22:17.08 | marienz | bah |
| 22:17.18 | milosn | ill keep trying :) |
| 22:17.43 | milosn | i need to be 100% sure this does not happen again! |
| 22:18.02 | marienz | unless you have a commit (or rollback) at the start of each request the problem can be triggered by the last thing the previous user of the thread did rather than what the new request does |
| 22:18.09 | marienz | this'll obviously make it painful to debug |
| 22:18.32 | marienz | I think in your position I'd add a redundant commit or rollback at the start of each request just to make sure you really have a fresh transaction |
| 22:18.58 | marienz | (that wallpapers over something, but I don't know off the top of my head if you can check if the transaction has started) |
| 22:19.15 | milosn | hmm commit() or rollback() ... rollback() should be better choice? |
| 22:19.45 | marienz | that depends |
| 22:20.31 | marienz | ifff this is indeed what's going on, and it happens to involve an uncommitted change, not just reads, adding rollback here will change behavior more, as presumably most of your requests eventually commits rather than rolling back |
| 22:20.44 | milosn | hmm first thought was to put it in my getStore() method, but i use that multiple times from the same thread |
| 22:20.48 | milosn | so thats a no go |
| 22:21.12 | marienz | I'd feel much better if I knew how to check for an incorrectly already-started transaction, but I don't know if psycopg lets you do that |
| 22:21.29 | marienz | it seems reasonable to me to put it in your transaction wrapper |
| 22:21.33 | marienz | (the one you pastebinned earlier) |
| 22:21.55 | milosn | ive turned on debuging, let me turn it off again and try to get stale data |
| 22:21.57 | marienz | you shouldn't be touching the store without using that wrapper, right? |
| 22:22.06 | milosn | no, never |
| 22:22.22 | marienz | then I guess a commit or rollback at the top of that wrapper, before it calls fn, makes some sense to me |
| 22:22.31 | marienz | the thing is that call *should* be a noop, but I don't know how to check for that |
| 22:27.57 | milosn | ive added store.rollback() in the wrapper, just after the first getStore() that happens in deferToThread() context |
| 22:29.09 | milosn | actualy, ill comment it for now ... and get back to it if i see stale data issue again |
| 22:29.35 | milosn | its symptomatic i cant repoduce it any more, and i was getting it 1 out of 5 times before |
| 22:33.21 | milosn | hmmm now i am starting to wonder if there was indeed a bug in my code, i dont think i changed anything |
| 22:33.41 | milosn | anyway i need sleep, marienz thanks for your help ... ill be back :) |