Insert of JDBC session attribute fails if concurrent request deletes session

[rfajarachmad]

Hi everyone,

I'm using spring-session 1.3.2.RELEASE with postgresql, I got this following error on my production environment. When I tried to login into the system, the session was created in the database normally, but somehow this exception occurred, I haven't found how to replicate this. does anyone know how to fix it ?

Oops! Appears that an error has occured. Please refresh the page and try again.. Exception message: PreparedStatementCallback; SQL [INSERT INTO SPRING_SESSION_ATTRIBUTES(SESSION_ID, ATTRIBUTE_NAME, ATTRIBUTE_BYTES) VALUES (?, ?, ?)]; ERROR: insert or update on table "spring_session_attributes" violates foreign key constraint "spring_session_attributes_fk"
  Detail: Key (session_id)=(3483b536-25b7-4206-89b7-2323626ba198) is not present in table "spring_session".; nested exception is org.postgresql.util.PSQLException: ERROR: insert or update on table "spring_session_attributes" violates foreign key constraint "spring_session_attributes_fk"
  Detail: Key (session_id)=(3483b536-25b7-4206-89b7-2323626ba198) is not present in table "spring_session".
org.springframework.dao.DataIntegrityViolationException: PreparedStatementCallback; SQL [INSERT INTO SPRING_SESSION_ATTRIBUTES(SESSION_ID, ATTRIBUTE_NAME, ATTRIBUTE_BYTES) VALUES (?, ?, ?)]; ERROR: insert or update on table "spring_session_attributes" violates foreign key constraint "spring_session_attributes_fk"
  Detail: Key (session_id)=(3483b536-25b7-4206-89b7-2323626ba198) is not present in table "spring_session".; nested exception is org.postgresql.util.PSQLException: ERROR: insert or update on table "spring_session_attributes" violates foreign key constraint "spring_session_attributes_fk"
  Detail: Key (session_id)=(3483b536-25b7-4206-89b7-2323626ba198) is not present in table "spring_session".
    at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:243)
    at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:73)
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:657)
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:906)
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:967)
    at org.springframework.session.jdbc.JdbcOperationsSessionRepository$2.doInTransactionWithoutResult(JdbcOperationsSessionRepository.java:464)
    at org.springframework.transaction.support.TransactionCallbackWithoutResult.doInTransaction(TransactionCallbackWithoutResult.java:34)
    at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:133)
    at org.springframework.session.jdbc.JdbcOperationsSessionRepository.save(JdbcOperationsSessionRepository.java:418)
    at org.springframework.session.jdbc.JdbcOperationsSessionRepository.save(JdbcOperationsSessionRepository.java:130)
    at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.commitSession(SessionRepositoryFilter.java:245)
    at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.access$100(SessionRepositoryFilter.java:217)
    at org.springframework.session.web.http.SessionRepositoryFilter.doFilterInternal(SessionRepositoryFilter.java:170)
    at org.springframework.session.web.http.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:80)
    at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:344)
    at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:261)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:110)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:615)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:169)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)
    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:962)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:445)
    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1115)
    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:637)
    at org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run(JIoEndpoint.java:318)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:745)
Caused by: org.postgresql.util.PSQLException: ERROR: insert or update on table "spring_session_attributes" violates foreign key constraint "spring_session_attributes_fk"
  Detail: Key (session_id)=(3483b536-25b7-4206-89b7-2323626ba198) is not present in table "spring_session".
    at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2182)
    at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1911)
    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:173)
    at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:622)
    at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:472)
    at org.postgresql.jdbc.PgStatement.executeUpdate(PgStatement.java:429)
    at org.springframework.jdbc.core.JdbcTemplate$2.doInPreparedStatement(JdbcTemplate.java:913)
    at org.springframework.jdbc.core.JdbcTemplate$2.doInPreparedStatement(JdbcTemplate.java:906)
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:641)
    ... 30 more

The configuration

<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
       xmlns:context="http://www.springframework.org/schema/context"
       xmlns="http://www.springframework.org/schema/beans"
       xsi:schemaLocation="http://www.springframework.org/schema/beans
        http://www.springframework.org/schema/beans/spring-beans.xsd
        http://www.springframework.org/schema/context
        http://www.springframework.org/schema/context/spring-context.xsd">

    <context:annotation-config/>
    <bean class="org.springframework.session.jdbc.config.annotation.web.http.JdbcHttpSessionConfiguration"/>

    <bean id="dataSource"
          class="org.springframework.jdbc.datasource.DriverManagerDataSource">
        <property name="driverClassName" value="${driverClassName}" />
        <property name="url" value="${database.url}" />
        <property name="username" value="${database.username}" />
        <property name="password" value="${database.password}" />
    </bean>


    <bean class="org.springframework.jdbc.datasource.DataSourceTransactionManager">
        <constructor-arg ref="dataSource"/>
    </bean>

    <bean class="org.springframework.session.web.http.DefaultCookieSerializer">
        <property name="cookieName" value="MYCOOKIE" />
    </bean>
</beans>

[vpavic]

Thanks for the report @rfajarachmad.

Can you show us your Spring Session related tables? With psql you can execute these commands to obtain the required information:

> \dS+ spring_session
> \dS+ spring_session_attributes

Also it would be useful to know which sequence of actions has led to this error.

[cwmccann]

Hi, I've been getting the same errors periodically. Not sure how to reproduce the issue as I found it scanning the logs.

Here is how my tables look:

                                  Table "public.spring_session"
        Column         |          Type          | Modifiers | Storage  | Stats target | Description
-----------------------+------------------------+-----------+----------+--------------+-------------
 primary_id            | character(36)          | not null  | extended |              |
 session_id            | character(36)          | not null  | extended |              |
 creation_time         | bigint                 | not null  | plain    |              |
 last_access_time      | bigint                 | not null  | plain    |              |
 max_inactive_interval | integer                | not null  | plain    |              |
 expiry_time           | bigint                 | not null  | plain    |              |
 principal_name        | character varying(100) |           | extended |              |
Indexes:
    "spring_session_pk" PRIMARY KEY, btree (primary_id)
    "spring_session_ix1" UNIQUE, btree (session_id)
    "spring_session_ix2" btree (expiry_time)
    "spring_session_ix3" btree (principal_name)
Referenced by:
    TABLE "spring_session_attributes" CONSTRAINT "spring_session_attributes_fk" FOREIGN KEY (session_primary_id) REFERENCES spring_session(primary_id) ON DELETE CASCADE

                            Table "public.spring_session_attributes"
       Column       |          Type          | Modifiers | Storage  | Stats target | Description
--------------------+------------------------+-----------+----------+--------------+-------------
 session_primary_id | character(36)          | not null  | extended |              |
 attribute_name     | character varying(200) | not null  | extended |              |
 attribute_bytes    | bytea                  | not null  | extended |              |
Indexes:
    "spring_session_attributes_pk" PRIMARY KEY, btree (session_primary_id, attribute_name)
    "spring_session_attributes_ix1" btree (session_primary_id)
Foreign-key constraints:
    "spring_session_attributes_fk" FOREIGN KEY (session_primary_id) REFERENCES spring_session(primary_id) ON DELETE CASCADE

[cwmccann]

I did add some extra logging to the rest error handler for this particular exception and the session looks intact.

c.m.m.server.config.RestErrorHandler -  Session.getCreationTime() = 1522704779144
c.m.m.server.config.RestErrorHandler -  Session.getLastAccessedTime() = 1522705160150
c.m.m.server.config.RestErrorHandler -  Session.getMaxInactiveInterval() = 1800
c.m.m.server.config.RestErrorHandler -  now = 1522705160490

[vpavic]

@cwmccann If you are using Spring Session 1.3 then you have configured your database schema incorrectly. The presence of primary_id column in spring_session table indicates that schema scripts for Spring Session 2.0 have been used (see #835).

Make sure you use the correct schema scripts, which are included in the Spring Session JAR itself.

[cwmccann]

I missed that the original issue was with spring session 1.3. I'm using:
org.springframework.session:spring-session-jdbc: -> 2.0.2.RELEASE so it looks like the ddl is at the right level.

[vpavic]

Thanks for the update @cwmccann. So it appears the same issue, affecting both 1.3 and 2.0.

If someone could provide a sample to reproduce this, that would be great.

[vpavic]

One additional piece of information that could be useful is how many instances of your application do you run in a cluster? Are the system clocks on all servers in sync?

[cwmccann]

I haven't figured out how to reproduce it yet. In this setup I have 3 services using the jdbc session, 2 on one box and 1 on another. NTP is not setup on them but the time seems to be within a second of each other.

[pminearo]

I am a little confused with this issue. The original stack trace above is from 1.3.2 because JdbcOperationsSessionRepository.java:464 in 2.0.3 is a "}". But there is mention that it is in both 1.3 and 2.0: "So it appears the same issue, affecting both 1.3 and 2.0.". I am not sure the issue is in 2.0.

We are seeing the same error in our production environment with 1.3.1. However, we are not seeing this error in our testing environment which has 2.0.2. We are releasing out to production in the next week, or so. Maybe something will pop up then; hopefully not. Does anyone have a stack trace for 2.0? Since the code base has changed a fair bit between 1.3 and 2.0; it would be nice to have a newer stack trace.

I was looking through the 2.0 code base and could not see how it could have a primary key issue except in a few situations:

1. Somehow the parent row in "spring_session" is deleted right before the attribute is inserted.
2. "ps.setString(1, session.primaryKey);" in JdbcOperationsSessionRepository.java line 502 and 517 has a bogus number, or is NULL(?)
3. "if (session.isNew()) {" on line 368 is returning false when it should be returning true. Meaning the Session should be new because it doesn't exist anymore? Maybe it was deleted because it timed out or something? However, it is not being flagged as new.

A stack trace from the 2.0.3 code base would be helpful; but I have yet to find one. Also, we are using Spring Security 5.0.4.RELEASE. In production we use: Spring Security 4.2.3.RELEASE and Spring Session 1.3.1.RELEASE. Could there have been something between Spring Security and Spring Session?

[candrews]

I'm pretty sure this is a duplicate of #1070

[vpavic]

@candrews I don't think so - #1070 was caused by a regression introduced in 2.0.3.RELEASE while this was reported against earlier releases.

[pminearo]

We just got a stack trace for version 2.0.2 I know things have changed in 2.0.3/4, but I think the logic is similar. What it looks like is happening is, somehow the Session is not being flagged as new. This leads to the code trying to update the session, and since updateCount == 0, an insert happens. This causes the Stack Trace.

Since, nothing else is logged out I can not tell what was in the session. However, I cross referenced the time stamp in the stack trace with our access logs. One second before the timestamp on the stack trace there was a logout. The logout returns a 302 (redirect) to send the user back to the login page. One of the frameworks we are using makes a call back to the server before the login page (still trying to figure out why). It seems that the session is not being dropped from the server. It is getting dropped from the DB, but not the server which is Tomcat in our case.

This means the session is not being flagged, or validated, as a new session?? Even though, it is not in the DB. I didn't look upstream in the code to see how the session is found and verified as new. But it does bring up the point that it is possible for a Session to exist in the Server and not in the DB.

• Should JdbcOperationsSessionRepository validate a Session that is not new before updating?
• Or is there a better place up stream for a Session to be validated?

org.springframework.dao.DataIntegrityViolationException: PreparedStatementCallback; SQL [INSERT INTO SPRING_SESSION_ATTRIBUTES(SESSION_PRIMARY_ID, ATTRIBUTE_NAME, ATTRIBUTE_BYTES) VALUES (?, ?, ?)ORA-02291: integrity constraint (ETPBA.SPRING_SESSION_ATTRIBUTES_FK) violated - parent key not found
; nested exception is java.sql.SQLIntegrityConstraintViolationException: ORA-02291: integrity constraint (ETPBA.SPRING_SESSION_ATTRIBUTES_FK) violated - parent key not found
at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:246)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72)
at org.springframework.jdbc.core.JdbcTemplate.translateException(JdbcTemplate.java:1402)
at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:620)
at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:850)
at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:905)
at org.springframework.session.jdbc.JdbcOperationsSessionRepository$2.doInTransactionWithoutResult(JdbcOperationsSessionRepository.java:445)
at org.springframework.transaction.support.TransactionCallbackWithoutResult.doInTransaction(TransactionCallbackWithoutResult.java:36)
at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:140)
at org.springframework.session.jdbc.JdbcOperationsSessionRepository.save(JdbcOperationsSessionRepository.java:409)
at org.springframework.session.jdbc.JdbcOperationsSessionRepository.save(JdbcOperationsSessionRepository.java:130)
at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.commitSession(SessionRepositoryFilter.java:228)
at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.access$100(SessionRepositoryFilter.java:196)
at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryResponseWrapper.onResponseCommitted(SessionRepositoryFilter.java:184)
at org.springframework.session.web.http.OnCommittedResponseWrapper.doOnResponseCommitted(OnCommittedResponseWrapper.java:227)
at org.springframework.session.web.http.OnCommittedResponseWrapper.access$000(OnCommittedResponseWrapper.java:38)
at org.springframework.session.web.http.OnCommittedResponseWrapper$SaveContextPrintWriter.flush(OnCommittedResponseWrapper.java:249)

[pminearo]

Did a little more research and we think we figured out what is going on. It's a race condition. Essentially, what is going on is this:

• The page the user's browser is displaying has an ajax call to refresh the data every x seconds.
• The user clicks on the logout at the same time the ajax call is being made.
• The server gets 2 requests and forks 2 threads, 1 for each request, handing each thread a copy of the HttpSession object. The reason the isNew() returns false.
• The logout request removes the Session information from the DB just before the ajax request tries to update the session tables.
• The ajax request, having a not new Session, tries to update the spring_session table to which nothing gets updated. Then the request tries to update the spring_session_attribute table to which nothing gets updated. Then it tries to insert the session attributes to which there is no session. This is what throws the Integrity Constraint exception.

I noticed in 2.0.3.RELEASE the code changed to this:

....
List<String> addedAttributeNames = session.delta.entrySet().stream()
	.filter(entry -> entry.getValue() == DeltaValue.ADDED)
	.map(Map.Entry::getKey)
	.collect(Collectors.toList());
insertSessionAttributes(session, addedAttributeNames);
List<String> updatedAttributeNames = session.delta.entrySet().stream()
	.filter(entry -> entry.getValue() == DeltaValue.UPDATED)
	.map(Map.Entry::getKey)
	.collect(Collectors.toList());
updateSessionAttributes(session, updatedAttributeNames);
....

Not sure if the change in logic here will fix this problem. I did not look upstream to see how the DeltaValue is figured out. In a race condition like this, there is still the possibility for the DeltaValue.ADDED to be set even though there is no Session in the DB. So, maybe, right before the insertSessionAttribute(), or in the insertSessionAttribute() method, validate the Session still exists.
If it is done before, the code can skip inserting, updating, and deleting. If done in the method, just the insert gets skipped. The updating and deleting are called, but will be no-ops. Agreeably, this is an edge case; but one that can be easily solved by validating the session before doing anything with the attributes.