Help confirming understanding Seaside multi ajax requests, session locking and retries

On 03/21/2017 11:46 AM, Mariano Martinez Peck via Glass wrote:

Hi guys,

This is a continuation from my email "Workaround to browser maximum connection limit ?".

Sorry for the long post. 

Long short story, I have an ajax request which, on response, fires a bunch of other Ajax requests, say 30. I added some  logging. 

1) 

1) WASession > handle:  I added this log:

handle: aRequestContext

  "acquire a lock on the receiver to prevent two separate gems from processing requests for the

same session at the same time"

  | result |

  result := System _lock: self kind: 3 autoRelease: true.

  result ~~ 1

    ifTrue: [ 

      "lock denied - presumably the request will be retried"

      GsFile

        gciLogServer:

          DateAndTime now greaseString,  '--AJAX TRACING: Session was locked to gem--' , System session asString.

      ^ WASessionLockNotAcquiredException

        signal: 'Session lock denied: ' , result printString ].

  GsFile

    gciLogServer:

      DateAndTime now greaseString, '--AJAX TRACING: Session was granted to gem--' , System session asString.

  ^ super handle: aRequestContext 

2) On #seasideProcessRequestWithRetry: aNativeRequest resultBlock: resultBlock I simply added this on top:

  GsFile

    gciLogServer:

     DateAndTime now greaseString,  '--AJAX TRACING: request received in Gem--' , System session asString.

-----

When I perform the mentioned scenario, this is the output I get:

[debrisdemo@quuveserver1 logs]$ grep -h -r "AJAX TRACING" *.log | sort

2017-03-21T14:39:09.431559085845947-04:00--AJAX TRACING: request received in Gem--7

2017-03-21T14:39:09.467015981674194-04:00--AJAX TRACING: Session was granted to gem--7

2017-03-21T14:39:10.62080311775208-04:00--AJAX TRACING: request received in Gem--6

2017-03-21T14:39:10.64005494117737-04:00--AJAX TRACING: Session was granted to gem--6

2017-03-21T14:39:10.85535597801208-04:00--AJAX TRACING: request received in Gem--11

2017-03-21T14:39:10.87811708450317-04:00--AJAX TRACING: Session was granted to gem--11

2017-03-21T14:39:11.02185392379761-04:00--AJAX TRACING: request received in Gem--10

2017-03-21T14:39:11.04404211044312-04:00--AJAX TRACING: Session was granted to gem--10

2017-03-21T14:39:11.22076201438904-04:00--AJAX TRACING: request received in Gem--13

2017-03-21T14:39:11.24725008010864-04:00--AJAX TRACING: Session was granted to gem--13

2017-03-21T14:39:11.42476797103882-04:00--AJAX TRACING: request received in Gem--16

2017-03-21T14:39:11.45253300666809-04:00--AJAX TRACING: Session was granted to gem--16

2017-03-21T14:39:11.62133288383484-04:00--AJAX TRACING: request received in Gem--12

2017-03-21T14:39:11.64478993415833-04:00--AJAX TRACING: Session was granted to gem--12

2017-03-21T14:39:11.82197690010071-04:00--AJAX TRACING: request received in Gem--8

2017-03-21T14:39:11.85350799560547-04:00--AJAX TRACING: Session was granted to gem--8

2017-03-21T14:39:11.85737299919128-04:00--AJAX TRACING: request received in Gem--12

2017-03-21T14:39:11.86467099189758-04:00--AJAX TRACING: Session was locked to gem--12

2017-03-21T14:39:11.96560001373291-04:00--AJAX TRACING: request received in Gem--12

2017-03-21T14:39:11.97410011291504-04:00--AJAX TRACING: Session was granted to gem--12

2017-03-21T14:39:12.02348208427429-04:00--AJAX TRACING: request received in Gem--14

2017-03-21T14:39:12.05155491828918-04:00--AJAX TRACING: Session was locked to gem--14

2017-03-21T14:39:12.06332397460938-04:00--AJAX TRACING: request received in Gem--14

2017-03-21T14:39:12.07150888442993-04:00--AJAX TRACING: Session was locked to gem--14

2017-03-21T14:39:12.17223906517029-04:00--AJAX TRACING: request received in Gem--14

2017-03-21T14:39:12.17896389961243-04:00--AJAX TRACING: Session was granted to gem--14

2017-03-21T14:39:12.220547914505-04:00--AJAX TRACING: request received in Gem--9

2017-03-21T14:39:12.24168992042542-04:00--AJAX TRACING: Session was granted to gem--9

2017-03-21T14:39:12.41850304603577-04:00--AJAX TRACING: request received in Gem--7

2017-03-21T14:39:12.42668199539185-04:00--AJAX TRACING: Session was granted to gem--7

2017-03-21T14:39:12.62308788299561-04:00--AJAX TRACING: request received in Gem--15

2017-03-21T14:39:12.64607095718384-04:00--AJAX TRACING: Session was granted to gem--15

2017-03-21T14:39:12.81803488731384-04:00--AJAX TRACING: request received in Gem--6

2017-03-21T14:39:12.82674098014832-04:00--AJAX TRACING: Session was locked to gem--6

2017-03-21T14:39:12.83830094337463-04:00--AJAX TRACING: request received in Gem--6

2017-03-21T14:39:12.84903788566589-04:00--AJAX TRACING: Session was locked to gem--6

2017-03-21T14:39:12.94985294342041-04:00--AJAX TRACING: request received in Gem--6

2017-03-21T14:39:12.96094799041748-04:00--AJAX TRACING: Session was granted to gem--6

2017-03-21T14:39:13.01887798309326-04:00--AJAX TRACING: request received in Gem--11

2017-03-21T14:39:13.03113889694214-04:00--AJAX TRACING: Session was granted to gem--11

2017-03-21T14:39:13.21864295005798-04:00--AJAX TRACING: request received in Gem--10

2017-03-21T14:39:13.23133301734924-04:00--AJAX TRACING: Session was granted to gem--10

2017-03-21T14:39:13.41963505744934-04:00--AJAX TRACING: request received in Gem--16

2017-03-21T14:39:13.42692899703979-04:00--AJAX TRACING: Session was granted to gem--16

2017-03-21T14:39:13.61887907981873-04:00--AJAX TRACING: request received in Gem--13

2017-03-21T14:39:13.63217806816101-04:00--AJAX TRACING: Session was granted to gem--13

2017-03-21T14:39:13.81860589981079-04:00--AJAX TRACING: request received in Gem--12

2017-03-21T14:39:13.83476805686951-04:00--AJAX TRACING: Session was locked to gem--12

2017-03-21T14:39:13.84605598449707-04:00--AJAX TRACING: request received in Gem--12

2017-03-21T14:39:13.85418105125427-04:00--AJAX TRACING: Session was locked to gem--12

2017-03-21T14:39:13.95503401756287-04:00--AJAX TRACING: request received in Gem--12

2017-03-21T14:39:13.96259903907776-04:00--AJAX TRACING: Session was locked to gem--12

2017-03-21T14:39:14.02077507972717-04:00--AJAX TRACING: request received in Gem--8

2017-03-21T14:39:14.03395390510559-04:00--AJAX TRACING: Session was granted to gem--8

2017-03-21T14:39:14.06341910362244-04:00--AJAX TRACING: request received in Gem--12

2017-03-21T14:39:14.07168793678284-04:00--AJAX TRACING: Session was granted to gem--12

2017-03-21T14:39:14.21781396865845-04:00--AJAX TRACING: request received in Gem--9

2017-03-21T14:39:14.22855997085571-04:00--AJAX TRACING: Session was locked to gem--9

2017-03-21T14:39:14.24069690704346-04:00--AJAX TRACING: request received in Gem--9

2017-03-21T14:39:14.25109100341797-04:00--AJAX TRACING: Session was locked to gem--9

2017-03-21T14:39:14.35198497772217-04:00--AJAX TRACING: request received in Gem--9

2017-03-21T14:39:14.35910391807556-04:00--AJAX TRACING: Session was granted to gem--9

2017-03-21T14:39:14.42120099067688-04:00--AJAX TRACING: request received in Gem--14

2017-03-21T14:39:14.4332959651947-04:00--AJAX TRACING: Session was locked to gem--14

2017-03-21T14:39:14.44424510002136-04:00--AJAX TRACING: request received in Gem--14

2017-03-21T14:39:14.45895600318909-04:00--AJAX TRACING: Session was locked to gem--14

2017-03-21T14:39:14.55992603302002-04:00--AJAX TRACING: request received in Gem--14

2017-03-21T14:39:14.57152605056763-04:00--AJAX TRACING: Session was granted to gem--14

2017-03-21T14:39:14.61931705474854-04:00--AJAX TRACING: request received in Gem--7

2017-03-21T14:39:14.63577008247375-04:00--AJAX TRACING: Session was locked to gem--7

2017-03-21T14:39:14.64788508415222-04:00--AJAX TRACING: request received in Gem--7

2017-03-21T14:39:14.65792894363403-04:00--AJAX TRACING: Session was locked to gem--7

2017-03-21T14:39:14.75875997543335-04:00--AJAX TRACING: request received in Gem--7

2017-03-21T14:39:14.76701188087463-04:00--AJAX TRACING: Session was locked to gem--7

2017-03-21T14:39:14.81798911094666-04:00--AJAX TRACING: request received in Gem--6

2017-03-21T14:39:14.82505297660828-04:00--AJAX TRACING: Session was granted to gem--6

2017-03-21T14:39:14.86797404289246-04:00--AJAX TRACING: request received in Gem--7

2017-03-21T14:39:14.87749290466309-04:00--AJAX TRACING: Session was locked to gem--7

2017-03-21T14:39:14.97828602790833-04:00--AJAX TRACING: request received in Gem--7

2017-03-21T14:39:14.9875009059906-04:00--AJAX TRACING: Session was granted to gem--7

2017-03-21T14:39:15.0185809135437-04:00--AJAX TRACING: request received in Gem--15

2017-03-21T14:39:15.02768397331238-04:00--AJAX TRACING: Session was locked to gem--15

2017-03-21T14:39:15.03932905197144-04:00--AJAX TRACING: request received in Gem--15

2017-03-21T14:39:15.0463490486145-04:00--AJAX TRACING: Session was locked to gem--15

2017-03-21T14:39:15.14704990386963-04:00--AJAX TRACING: request received in Gem--15

2017-03-21T14:39:15.15435194969177-04:00--AJAX TRACING: Session was granted to gem--15

2017-03-21T14:39:15.21826410293579-04:00--AJAX TRACING: request received in Gem--11

2017-03-21T14:39:15.23047399520874-04:00--AJAX TRACING: Session was locked to gem--11

2017-03-21T14:39:15.24233388900757-04:00--AJAX TRACING: request received in Gem--11

2017-03-21T14:39:15.25115609169006-04:00--AJAX TRACING: Session was granted to gem--11

2017-03-21T14:39:15.41745400428772-04:00--AJAX TRACING: request received in Gem--10

2017-03-21T14:39:15.42503094673157-04:00--AJAX TRACING: Session was granted to gem--10

2017-03-21T14:39:15.61884593963623-04:00--AJAX TRACING: request received in Gem--12

2017-03-21T14:39:15.62951707839966-04:00--AJAX TRACING: Session was granted to gem--12

2017-03-21T14:39:15.81818103790283-04:00--AJAX TRACING: request received in Gem--16

2017-03-21T14:39:15.82529711723328-04:00--AJAX TRACING: Session was granted to gem--16

[debrisdemo@quuveserver1 logs]$

And these are the conclusions I got so far:

1) Requests are being correctly load balanced across Gems by nginx on a round robin strategy.

2) The most important conclusion here (please confirm!) is that there are a few locks. I mean, there is NOT a lock PER request (which is what I imagined). There are less. I THINK this could happen if a request processing is very fast, then maybe for the time the next requests comes, we have already released the lock. And hence, the few locks I see in above lines are due to "long enough" requests that caused next requests to abort/wait/retry. For example, starting from the top, the first one big was the one on gem 8 which locked the gem 12.

Does this sounds correct? 

I think your analysis is correct ... you are getting blocked request handling because of parallel AJax requests for the same session : in one case there was a series of 3 locked messages over a span of .22 seconds (gem 12) and another set of 3 that took .21 seconds (gem 7) before the lock was granted ...

You might consider logging the oop of the session object, because it is possible for multiple gems to be in a retry loop for the same session ... I don't see any evidence of this in the above ...

Dale

_______________________________________________
Glass mailing list
[hidden email]
http://lists.gemtalksystems.com/mailman/listinfo/glass

On 03/21/2017 12:48 PM, Mariano Martinez Peck wrote:

On Tue, Mar 21, 2017 at 4:26 PM, Dale Henrichs via Glass <[hidden email]> wrote:

On 03/21/2017 11:46 AM, Mariano Martinez Peck via Glass wrote:

Hi guys,

This is a continuation from my email "Workaround to browser maximum connection limit ?".

Sorry for the long post. 

Long short story, I have an ajax request which, on response, fires a bunch of other Ajax requests, say 30. I added some  logging. 

1) 

1) WASession > handle:  I added this log:

handle: aRequestContext

  "acquire a lock on the receiver to prevent two separate gems from processing requests for the

same session at the same time"

  | result |

  result := System _lock: self kind: 3 autoRelease: true.

  result ~~ 1

    ifTrue: [ 

      "lock denied - presumably the request will be retried"

      GsFile

        gciLogServer:

          DateAndTime now greaseString,  '--AJAX TRACING: Session was locked to gem--' , System session asString.

      ^ WASessionLockNotAcquiredException

        signal: 'Session lock denied: ' , result printString ].

  GsFile

    gciLogServer:

      DateAndTime now greaseString, '--AJAX TRACING: Session was granted to gem--' , System session asString.

  ^ super handle: aRequestContext 

2) On #seasideProcessRequestWithRetry: aNativeRequest resultBlock: resultBlock I simply added this on top:

  GsFile

    gciLogServer:

     DateAndTime now greaseString,  '--AJAX TRACING: request received in Gem--' , System session asString.

-----

When I perform the mentioned scenario, this is the output I get:

[debrisdemo@quuveserver1 logs]$ grep -h -r "AJAX TRACING" *.log | sort

2017-03-21T14:39:09.431559085845947-04:00--AJAX TRACING: request received in Gem--7

2017-03-21T14:39:09.467015981674194-04:00--AJAX TRACING: Session was granted to gem--7

2017-03-21T14:39:10.62080311775208-04:00--AJAX TRACING: request received in Gem--6

2017-03-21T14:39:10.64005494117737-04:00--AJAX TRACING: Session was granted to gem--6

2017-03-21T14:39:10.85535597801208-04:00--AJAX TRACING: request received in Gem--11

2017-03-21T14:39:10.87811708450317-04:00--AJAX TRACING: Session was granted to gem--11

2017-03-21T14:39:11.02185392379761-04:00--AJAX TRACING: request received in Gem--10

2017-03-21T14:39:11.04404211044312-04:00--AJAX TRACING: Session was granted to gem--10

2017-03-21T14:39:11.22076201438904-04:00--AJAX TRACING: request received in Gem--13

2017-03-21T14:39:11.24725008010864-04:00--AJAX TRACING: Session was granted to gem--13

2017-03-21T14:39:11.42476797103882-04:00--AJAX TRACING: request received in Gem--16

2017-03-21T14:39:11.45253300666809-04:00--AJAX TRACING: Session was granted to gem--16

2017-03-21T14:39:11.62133288383484-04:00--AJAX TRACING: request received in Gem--12

2017-03-21T14:39:11.64478993415833-04:00--AJAX TRACING: Session was granted to gem--12

2017-03-21T14:39:11.82197690010071-04:00--AJAX TRACING: request received in Gem--8

2017-03-21T14:39:11.85350799560547-04:00--AJAX TRACING: Session was granted to gem--8

2017-03-21T14:39:11.85737299919128-04:00--AJAX TRACING: request received in Gem--12

2017-03-21T14:39:11.86467099189758-04:00--AJAX TRACING: Session was locked to gem--12

2017-03-21T14:39:11.96560001373291-04:00--AJAX TRACING: request received in Gem--12

2017-03-21T14:39:11.97410011291504-04:00--AJAX TRACING: Session was granted to gem--12

2017-03-21T14:39:12.02348208427429-04:00--AJAX TRACING: request received in Gem--14

2017-03-21T14:39:12.05155491828918-04:00--AJAX TRACING: Session was locked to gem--14

2017-03-21T14:39:12.06332397460938-04:00--AJAX TRACING: request received in Gem--14

2017-03-21T14:39:12.07150888442993-04:00--AJAX TRACING: Session was locked to gem--14

2017-03-21T14:39:12.17223906517029-04:00--AJAX TRACING: request received in Gem--14

2017-03-21T14:39:12.17896389961243-04:00--AJAX TRACING: Session was granted to gem--14

2017-03-21T14:39:12.220547914505-04:00--AJAX TRACING: request received in Gem--9

2017-03-21T14:39:12.24168992042542-04:00--AJAX TRACING: Session was granted to gem--9

2017-03-21T14:39:12.41850304603577-04:00--AJAX TRACING: request received in Gem--7

2017-03-21T14:39:12.42668199539185-04:00--AJAX TRACING: Session was granted to gem--7

2017-03-21T14:39:12.62308788299561-04:00--AJAX TRACING: request received in Gem--15

2017-03-21T14:39:12.64607095718384-04:00--AJAX TRACING: Session was granted to gem--15

2017-03-21T14:39:12.81803488731384-04:00--AJAX TRACING: request received in Gem--6

2017-03-21T14:39:12.82674098014832-04:00--AJAX TRACING: Session was locked to gem--6

2017-03-21T14:39:12.83830094337463-04:00--AJAX TRACING: request received in Gem--6

2017-03-21T14:39:12.84903788566589-04:00--AJAX TRACING: Session was locked to gem--6

2017-03-21T14:39:12.94985294342041-04:00--AJAX TRACING: request received in Gem--6

2017-03-21T14:39:12.96094799041748-04:00--AJAX TRACING: Session was granted to gem--6

2017-03-21T14:39:13.01887798309326-04:00--AJAX TRACING: request received in Gem--11

2017-03-21T14:39:13.03113889694214-04:00--AJAX TRACING: Session was granted to gem--11

2017-03-21T14:39:13.21864295005798-04:00--AJAX TRACING: request received in Gem--10

2017-03-21T14:39:13.23133301734924-04:00--AJAX TRACING: Session was granted to gem--10

2017-03-21T14:39:13.41963505744934-04:00--AJAX TRACING: request received in Gem--16

2017-03-21T14:39:13.42692899703979-04:00--AJAX TRACING: Session was granted to gem--16

2017-03-21T14:39:13.61887907981873-04:00--AJAX TRACING: request received in Gem--13

2017-03-21T14:39:13.63217806816101-04:00--AJAX TRACING: Session was granted to gem--13

2017-03-21T14:39:13.81860589981079-04:00--AJAX TRACING: request received in Gem--12

2017-03-21T14:39:13.83476805686951-04:00--AJAX TRACING: Session was locked to gem--12

2017-03-21T14:39:13.84605598449707-04:00--AJAX TRACING: request received in Gem--12

2017-03-21T14:39:13.85418105125427-04:00--AJAX TRACING: Session was locked to gem--12

2017-03-21T14:39:13.95503401756287-04:00--AJAX TRACING: request received in Gem--12

2017-03-21T14:39:13.96259903907776-04:00--AJAX TRACING: Session was locked to gem--12

2017-03-21T14:39:14.02077507972717-04:00--AJAX TRACING: request received in Gem--8

2017-03-21T14:39:14.03395390510559-04:00--AJAX TRACING: Session was granted to gem--8

2017-03-21T14:39:14.06341910362244-04:00--AJAX TRACING: request received in Gem--12

2017-03-21T14:39:14.07168793678284-04:00--AJAX TRACING: Session was granted to gem--12

2017-03-21T14:39:14.21781396865845-04:00--AJAX TRACING: request received in Gem--9

2017-03-21T14:39:14.22855997085571-04:00--AJAX TRACING: Session was locked to gem--9

2017-03-21T14:39:14.24069690704346-04:00--AJAX TRACING: request received in Gem--9

2017-03-21T14:39:14.25109100341797-04:00--AJAX TRACING: Session was locked to gem--9

2017-03-21T14:39:14.35198497772217-04:00--AJAX TRACING: request received in Gem--9

2017-03-21T14:39:14.35910391807556-04:00--AJAX TRACING: Session was granted to gem--9

2017-03-21T14:39:14.42120099067688-04:00--AJAX TRACING: request received in Gem--14

2017-03-21T14:39:14.4332959651947-04:00--AJAX TRACING: Session was locked to gem--14

2017-03-21T14:39:14.44424510002136-04:00--AJAX TRACING: request received in Gem--14

2017-03-21T14:39:14.45895600318909-04:00--AJAX TRACING: Session was locked to gem--14

2017-03-21T14:39:14.55992603302002-04:00--AJAX TRACING: request received in Gem--14

2017-03-21T14:39:14.57152605056763-04:00--AJAX TRACING: Session was granted to gem--14

2017-03-21T14:39:14.61931705474854-04:00--AJAX TRACING: request received in Gem--7

2017-03-21T14:39:14.63577008247375-04:00--AJAX TRACING: Session was locked to gem--7

2017-03-21T14:39:14.64788508415222-04:00--AJAX TRACING: request received in Gem--7

2017-03-21T14:39:14.65792894363403-04:00--AJAX TRACING: Session was locked to gem--7

2017-03-21T14:39:14.75875997543335-04:00--AJAX TRACING: request received in Gem--7

2017-03-21T14:39:14.76701188087463-04:00--AJAX TRACING: Session was locked to gem--7

2017-03-21T14:39:14.81798911094666-04:00--AJAX TRACING: request received in Gem--6

2017-03-21T14:39:14.82505297660828-04:00--AJAX TRACING: Session was granted to gem--6

2017-03-21T14:39:14.86797404289246-04:00--AJAX TRACING: request received in Gem--7

2017-03-21T14:39:14.87749290466309-04:00--AJAX TRACING: Session was locked to gem--7

2017-03-21T14:39:14.97828602790833-04:00--AJAX TRACING: request received in Gem--7

2017-03-21T14:39:14.9875009059906-04:00--AJAX TRACING: Session was granted to gem--7

2017-03-21T14:39:15.0185809135437-04:00--AJAX TRACING: request received in Gem--15

2017-03-21T14:39:15.02768397331238-04:00--AJAX TRACING: Session was locked to gem--15

2017-03-21T14:39:15.03932905197144-04:00--AJAX TRACING: request received in Gem--15

2017-03-21T14:39:15.0463490486145-04:00--AJAX TRACING: Session was locked to gem--15

2017-03-21T14:39:15.14704990386963-04:00--AJAX TRACING: request received in Gem--15

2017-03-21T14:39:15.15435194969177-04:00--AJAX TRACING: Session was granted to gem--15

2017-03-21T14:39:15.21826410293579-04:00--AJAX TRACING: request received in Gem--11

2017-03-21T14:39:15.23047399520874-04:00--AJAX TRACING: Session was locked to gem--11

2017-03-21T14:39:15.24233388900757-04:00--AJAX TRACING: request received in Gem--11

2017-03-21T14:39:15.25115609169006-04:00--AJAX TRACING: Session was granted to gem--11

2017-03-21T14:39:15.41745400428772-04:00--AJAX TRACING: request received in Gem--10

2017-03-21T14:39:15.42503094673157-04:00--AJAX TRACING: Session was granted to gem--10

2017-03-21T14:39:15.61884593963623-04:00--AJAX TRACING: request received in Gem--12

2017-03-21T14:39:15.62951707839966-04:00--AJAX TRACING: Session was granted to gem--12

2017-03-21T14:39:15.81818103790283-04:00--AJAX TRACING: request received in Gem--16

2017-03-21T14:39:15.82529711723328-04:00--AJAX TRACING: Session was granted to gem--16

[debrisdemo@quuveserver1 logs]$

And these are the conclusions I got so far:

1) Requests are being correctly load balanced across Gems by nginx on a round robin strategy.

2) The most important conclusion here (please confirm!) is that there are a few locks. I mean, there is NOT a lock PER request (which is what I imagined). There are less. I THINK this could happen if a request processing is very fast, then maybe for the time the next requests comes, we have already released the lock. And hence, the few locks I see in above lines are due to "long enough" requests that caused next requests to abort/wait/retry. For example, starting from the top, the first one big was the one on gem 8 which locked the gem 12.

Does this sounds correct? 

I think your analysis is correct ... you are getting blocked request handling because of parallel AJax requests for the same session : in one case there was a series of 3 locked messages over a span of .22 seconds (gem 12) and another set of 3 that took .21 seconds (gem 7) before the lock was granted ...

Yes, exactly. Ok, I am glad I am understanding the situation :)

 

You might consider logging the oop of the session object, because it is possible for multiple gems to be in a retry loop for the same session ... I don't see any evidence of this in the above ...

mmm I don't understand this. The session should be the same for all gems as all those requests were fired from a given ajax request.

with the session oop logged, your *should* turns into an *is* or *is not* :) ... I was thinking more along the general case, when there are likely to be multiple sessions firing off ajax requests ...