Session synchronization across threads

[Ray Miller]

Hi,

I'm working on a web application that stores  a list of work items in the session, and removes each item from the list as it is viewed. Something like:

(defpage "/init-work-list" []

  (session/swap! assoc :work-list ["a" "b" "c" "d" "e" "f" "g"])  

  (common/layout

   [:p (link-to (url "/work-on-item/" "a") "Start work")]))

(defpage "/work-on-item/:item"

  {:keys [item]}

  (session/swap! assoc :work-list (remove #{item} (session/get :work-list)))

  (common/layout

   [:p "Current item is " item]

   (if-let [next-item (first (session/get :work-list))]

     [:p (link-to (url "/work-on-item/" (first (session/get :work-list))) "Next item")]

     [:p "Done. " (link-to (url "/init-work-list") "Start again")])))

Of course, the real application is doing much more work, and I'm stashing data in the session to avoid an expensive database query that builds the work list. The problem I have is that, when a subsequent query hits a different thread, it is seeing an old version of the work list. I've  added some debugging to print the work list before and after session/swap!, and see the following:

First request:

2012-11-12 15:09:28,711 [1073027@qtp-15335895-5] DEBUG Work list (before) ({:pos 33411111, :chr 6} {:pos 34542876, :chr 15} {:pos 241724480, :chr 2})

2012-11-12 15:09:28,711 [1073027@qtp-15335895-5] DEBUG Work list (after) ({:pos 34542876, :chr 15} {:pos 241724480, :chr 2})

Second request (a full 30 seconds later):

2012-11-12 15:10:08,780 [14979322@qtp-15335895-3] DEBUG Work list (before) ({:pos 33411111, :chr 6} {:pos 34542876, :chr 15} {:pos 241724480, :chr 2})

2012-11-12 15:10:08,781 [14979322@qtp-15335895-3] DEBUG Work list (after) ({:pos 34542876, :chr 15} {:pos 241724480, :chr 2})

Have I misunderstood the behaviour of session data? Is there a better way to achieve what I'm trying to do?

This is clojure 1.4.0, noir 1.3.0-beta8.

Ray.

[Ray Miller]

I still haven't gotten to the bottom of this problem. Unfortunately I have so far been unable to reproduce the problem with a small demo app, but it happens frequently (if intermittently) in my real application.

For now I'm using a work-around of storing the work list in an atom under my control, keyed by session id. AIUI this isn't too different from the standard Noir session with a memory store, but so far the problem hasn't occurred when I'm using an atom in this way.

Does anyone have any insights into what's going on here?

Ray.

[Mark Rathwell]

What is your setup? If you are in a distributed environment, you
should store sessions in a central location (database, memcache, nosql
store, etc.), not in memory of one machine.

Still not sure I'm following your question though.

[Ray Miller]

Hi Mark,

This is a simple setup with just one server. The problem occurs both
running the application under lein run, and with immutant (and the
immutant session store). The logs seem to be showing that a change to
session data made in one thread is not visible in a different thread
30 seconds later. I'm baffled that this happens even under lein run
with only one user hitting the server. I guess I have two questions:

1. Has anyone else had a similar problem with session data?
2. Does anyone have any suggestions on what else I can do to debug the problem?

I spent some time trying to reproduce the problem with a minimal Noir
app but so far my test app has not exhibited the problem. I'll have
another go at this when I get some time, but I really would appreciate
any pointers that might help me get to the bottom of this.

Ray.

[Mark Rathwell]

Could you expand on what you mean when you say different threads are accessing the session?  Do you mean separate requests (with the same session cookie)?  Or do you have some background thread trying to modify the session store?  Can't quite picture what you are describing.

[Chris Granger]

is the first request finishing before the next request is made? Sessions don't persist until the request finishes.

Cheers,
Chris.

[Ray Miller]

On 14 November 2012 19:04, Mark Rathwell <mark.r...@gmail.com> wrote:
> Could you expand on what you mean when you say different threads are
> accessing the session? Do you mean separate requests (with the same session
> cookie)? Or do you have some background thread trying to modify the session
> store? Can't quite picture what you are describing.

I have one client, with one session cookie. Jetty spawns multiple
threads to handle the incoming requests, there are no other threads
involved. I used log4j to log debug messages with the thread id, which
makes me think the second jetty thread is seeing an old version of the
session data. The code looks like:

(debug "Work list (before)" (session/get :work-list))
(session/swap! remove-variant-from-work-list params)
(debug "Work list (after)" (session/get :work-list))

This produces the expected log lines:

2012-11-12 15:09:28,711 [1073027@qtp-15335895-5] DEBUG Work list
(before) ({:pos 33411111, :chr 6} {:pos 34542876, :chr 15} {:pos
241724480, :chr 2})
2012-11-12 15:09:28,711 [1073027@qtp-15335895-5] DEBUG Work list
(after) ({:pos 34542876, :chr 15} {:pos 241724480, :chr 2})

At this point, HTML is delivered to the browser, I review the form and
post it back to the server. It happens that the post is handled by a
different Jetty thread (about 30 seconds after the first request):

2012-11-12 15:10:08,780 [14979322@qtp-15335895-3] DEBUG Work list
(before) ({:pos 33411111, :chr 6} {:pos 34542876, :chr 15} {:pos
241724480, :chr 2})
2012-11-12 15:10:08,781 [14979322@qtp-15335895-3] DEBUG Work list
(after) ({:pos 34542876, :chr 15} {:pos 241724480, :chr 2})

As you see, the work list retrieved from the session by this thread
has the original 3 items, not the 2 I expect.

[Ray Miller]

On 14 November 2012 19:05, Chris Granger <ibd...@gmail.com> wrote:
> is the first request finishing before the next request is made? Sessions
> don't persist until the request finishes.

I believe so. Is there an easy way I can confirm this?

Ray.

[Mark Rathwell]

All I can think is, as Chris implied, the session hasn't actually been persisted to the store yet by the thread handling the initial request, meaning the request still, somehow, hasn't finished.