Session attributes missing intermittently - Spring Session + Pivotal GemFire Implementation

Question

Facing a strange issue for sometime in Spring Session with Pivotal GemFire integration.

We have multiple HTTP requests, which eventually does set/get of session attributes in a varying order based on several conditions.

At some given point...

    (T) session.getAttribute(sessionKeyN); // (T) is template object

... is retrieving null. We have cross verified that no session.setAttribute(..) is invoked in between two session.getAttribute(..) calls out of which one misses the object.

We enabled trace logging in GemFire client. There we see a mismatch in hashmaps being read/written. Sharing the logs:

>2018-09-24T02:46:15:342-0700 [20180924_451_5_4,20180912045104000005] TRACE org.apache.geode.DataSerializer: **Writing HashMap with 8 elements**: {LOGIN_DATE_TIME=09-24-2018 02:46:08 AM, TERMINAL=terminal.Terminal@5aa33970, org.springframework.session.FindByIndexNameSessionRepository.PRINCIPAL_NAME_INDEX_NAME=testuser, LOG_TRANSACTION_ID=20180924_451_5_4,20180912045104000005, USER=user.User@70b4b11b, TRANSACTION_HEADER=TransactionHeader@4144221c, XXXX_LOGIN=true, SPRING_SECURITY_CONTEXT=org.springframework.security.core.context.SecurityContextImpl@65bb8fc1: Authentication: org.springframework.security.authentication.UsernamePasswordAuthenticationToken@65bb8fc1: Principal: testuser; Credentials: [PROTECTED]; Authenticated: true; Details: null;}
>2018-09-24T02:46:15:342-0700 [20180924_451_5_4,20180912045104000005] TRACE org.apache.geode.internal.**InternalDataSerializer: basicWriteObject**: {LOGIN_DATE_TIME=09-24-2018 02:46:08 AM, TERMINAL=terminal.Terminal@5aa33970, org.springframework.session.FindByIndexNameSessionRepository.PRINCIPAL_NAME_INDEX_NAME=testuser, LOG_TRANSACTION_ID=20180924_451_5_4,20180912045104000005, USER=user.User@70b4b11b, TRANSACTION_HEADER=TransactionHeader@4144221c, XXXX_LOGIN=true, SPRING_SECURITY_CONTEXT=org.springframework.security.core.context.SecurityContextImpl@65bb8fc1: Authentication: org.springframework.security.authentication.UsernamePasswordAuthenticationToken@65bb8fc1: Principal: testuser; Credentials: [PROTECTED]; Authenticated: true; Details: null;}
>2018-09-24T02:46:15:342-0700 [20180924_451_5_4,20180912045104000005] TRACE org.apache.geode.DataSerializer: Writing STRING_BYTES of len=8
>2018-09-24T02:46:15:342-0700 [20180924_451_5_4,20180912045104000005] TRACE org.apache.geode.DataSerializer: Writing String "testuser"
>2018-09-24T02:46:15:342-0700 [20180924_451_5_4,20180912045104000005] TRACE org.apache.geode.DataSerializer: Writing STRING_BYTES of len=36
>2018-09-24T02:46:15:342-0700 [20180924_451_5_4,20180912045104000005] TRACE org.apache.geode.DataSerializer: Writing String "5c4948d9-7438-4dff-badc-fdc0f9997781"
>2018-09-24T02:46:15:342-0700 [20180924_451_5_4,20180912045104000005] TRACE org.apache.geode.internal.InternalDataSerializer: basicWriteObject: { @type = org.springframework.session.data.gemfire.AbstractGemFireOperationsSessionRepository$GemFireSession, id = 5c4948d9-7438-4dff-badc-fdc0f9997781, creationTime = 2018-09-24T09:44:23.180Z, lastAccessedTime = 2018-09-24T09:46:14.909Z, maxInactiveInterval = PT30M, principalName = testuser }
>2018-09-24T02:46:15:342-0700 [20180924_451_5_4,20180912045104000005] TRACE org.apache.geode.internal.InternalDataSerializer: DataSerializer Serializing an instance of org.apache.geode.cache.Operation
>2018-09-24T02:46:15:342-0700 [20180924_451_5_4,20180912045104000005] TRACE org.apache.geode.internal.InternalDataSerializer: basicWriteObject: UPDATE
>2018-09-24T02:46:15:342-0700 [20180924_451_5_4,20180912045104000005] DEBUG org.apache.geode.cache.client.internal.PutOp: PutOpImpl constructing message with operation=UPDATE
>2018-09-24T02:46:15:144-0700 [20180924_451_5_4,20180912045104000005] DEBUG org.apache.geode.internal.cache.LocalRegion: invoking listeners: [org.springframework.session.data.gemfire.GemFireOperationsSessionRepository@4471a4f]
>2018-09-24T02:46:15:144-0700 [20180924_451_5_4,20180912045104000005] TRACE org.apache.geode.internal.cache.LocalRegion: dispatchListenerEvent event=EntryEventImpl[op=LOCAL_LOAD_CREATE;region=/XXXX2wl;key=5c4948d9-7438-4dff-badc-fdc0f9997781;oldValue=null;newValue={ @type = org.springframework.session.data.gemfire.AbstractGemFireOperationsSessionRepository$GemFireSession, id = 5c4948d9-7438-4dff-badc-fdc0f9997781, creationTime = 2018-09-24T09:44:23.180Z, lastAccessedTime = 2018-09-24T09:46:15.079Z, maxInactiveInterval = PT30M, principalName = testuser };callbackArg=null;originRemote=false;originMember=tstplXXXX0004(ClientConfigXXXX2Application:28299:loner):35884:0c27e20a:ClientConfigXXXX2Application;callbacksInvoked;version={v20; rv161; mbr=10.5.230.71(server_devplgemf0066:123628)<v23>:1024; time=1537782375131; remote};isFromServer]
>2018-09-24T02:46:15:144-0700 [20180924_451_5_4,20180912045104000005] TRACE org.apache.geode.internal.cache.versions.VersionTag: deserializing class org.apache.geode.internal.cache.versions.VMVersionTag with flags 0x4
>2018-09-24T02:46:15:144-0700 [20180924_451_5_4,20180912045104000005] TRACE org.apache.geode.internal.InternalDataSerializer: basicReadObject: header=1
>2018-09-24T02:46:15:144-0700 [20180924_451_5_4,20180912045104000005] TRACE org.apache.geode.DataSerializer: **Read HashMap with 9 elements**: {LOGIN_DATE_TIME=09-24-2018 02:46:08 AM, TERMINAL=terminal.Terminal@5a2aa051, **CUSTOMER_SEARCH_RESPONSE=CustomerInfo@600fa25f**, org.springframework.session.FindByIndexNameSessionRepository.PRINCIPAL_NAME_INDEX_NAME=testuser, LOG_TRANSACTION_ID=20180924_451_5_4,20180912045104000005, USER=user.User@7178708f, TRANSACTION_HEADER=TransactionHeader@30215dcd, XXXX_LOGIN=true, SPRING_SECURITY_CONTEXT=org.springframework.security.core.context.SecurityContextImpl@65bb8fc1: Authentication: org.springframework.security.authentication.UsernamePasswordAuthenticationToken@65bb8fc1: Principal: testuser; Credentials: [PROTECTED]; Authenticated: true; Details: null;}

Attribute CUSTOMER_SEARCH_RESPONSE is missing even though no session.setAttribute(..) for it was invoked.

This is not WRT to one attribute and also not consistent. A re-run might not show this issue.

Answer 1

After working with another Pivotal (GemFire) customer on a similar problem (also using Spring Session and Pivotal GemFire (SSDG) to manage HTTP session state in a highly concurrent Web application/environment), we uncovered the underlying issue(s) and ultimately found BUGS in Pivotal GemFire!

In nutshell, these bugs lead to Lost Updates due to Race Conditions that are exasperated in a highly concurrent (multi-user) Web environment, where multiple HTTP requests might possibly be accessing and modifying the same HTTP session under load. And, the greater the concurrency (users) and the greater the load (number of HTTP requests to the same HTTP session), the more apparent this problem becomes.

In fact, I have written several Integration Tests illustrating this problem.

First, I wrote a Load Integration Test (MultiThreadedClientProxyRegionSessionIntegrationTests). This class spawns 180 Threads (users) performing 10,000 concurrent requests to the same underlying Session. The Session object, though not exactly the same, is modeled after SSDG's GemFireSession object representation.

Second, I wrote another Integration Test (TwoThreadsClientProxyRegionSessionIntegrationTests) that reliably and repeatedly reproduces the problem.

Both of these test classes were written purely with the GemFire API, thereby illustrating that Pivotal GemFire is the problem, not SSDG.

I have written similar test using Spring Session Data GemFire both in my example, and now, also included in the SSDG test suite (along with many other MultiThread/Concurrency based integration tests), itself, ensuring Spring Session (for Pivotal GemFire) will never encounter this problem again, and if it does, I'll know about it sooner than later.

In short, the 2 underlying Pivotal GemFire bugs are:

• GEODE-6152
• GEODE-6032

The workaround is as follows:

First, you must configure your Spring Session, GemFire cache client application with:

1. A client PROXY Region to manage the Session state (default)
2. Set copy-on-read set to true.

3. And, you must use GemFire DataSerialization, by setting the sessionSerializerBeanName appropriately:

   @SpringBootApplication @ClientCacheApplication(copyOnRead = true, subscriptionEnabled = true) @EnableGemFireHttpSession( clientRegionShortcut = ClientRegionShortcut.PROXY, sessionSerializerBeanName = GemFireHttpSessionConfiguration.SESSION_DATA_SERIALIZER_BEAN_NAME ) class MySpringBootSpringSessionDataGemFireApplication { ... }

See here, for example.

You will also need to upgrade to Spring Session for Pivotal GemFire 2.1.2.RELEASE (to be released soon), since I made several important, recent enhancements, such as:

1. Issue #12 - Prevent SessionRepository.save(Session) on non-dirty Sessions.
2. Issue #9 - Add server-side configuration support for GemFire/Geode DataSerialization when SSDG is not used to configure Spring Session on the servers.
3. Issue #17 - Consider support for customizable IsDirty application domain object checking.

Using GemFire DataSerialization with Deltas will not prevent, but greatly reduces the possibility of lost updates and other race condition intrinsically inherit in a Web environment, particularly since a Servlet container (e.g. Tomcat) is multi-threaded, processing each HTTP request in a separate thread.

While SSDG goes to great effort to ensure the HTTP session representation (i.e. GemFireSession) is thread-safe, you must also ensure that any object you put in the HTTP session is also thread-safe since it can and most likely will be accessed by more than 1 thread in a highly-concurrent Web application, especially 1 where more than a single HTTP request can access the same HTTP session (by session ID) at a time.

Anyway, food for thought.

When the configuration above is used, everything works as expected, and when not, lost updates can and will occur dues to the GemFire BUGS!

In fact, my load test revealed that out of 10,000 Session updates, where ~9800 Session attributes get added, only ~1100 successfully are, that is a whopping ~89% loss of data!!!

However, when the configuration above is applied, all data is accounted for correctly.

Hope this helps!