Spring Session Oracle jdbc temp space issue ORA-01652

[chkrishna411]

We are using spring-session with jdbc backed by Oracle database.

we are using 1.3.4 version of spring-session. compile "org.springframework.session:spring-session-jdbc:1.3.4.RELEASE" compile "org.springframework.session:spring-session:1.3.4.RELEASE"

We are seeing temp space being utilized heavily by spring-session and it's keep on increasing gradually. It's not cleaning up automatically and after 2 to 3 days, it has consumed the entire TEMP space and our app was going down.

After researching on oracle database side, it looks like the following outer join query is the one which is using temporary LOB.

private static final String GET_SESSION_QUERY = "SELECT S.SESSION_ID, S.CREATION_TIME, S.LAST_ACCESS_TIME, S.MAX_INACTIVE_INTERVAL, SA.ATTRIBUTE_NAME, SA.ATTRIBUTE_BYTES " + "FROM %TABLE_NAME% S " + "LEFT OUTER JOIN %TABLE_NAME%_ATTRIBUTES SA ON S.SESSION_ID = SA.SESSION_ID " + "WHERE S.SESSION_ID = ?";

Once after killing those sessions directly from database, entire temp space usage came down to 0.

Failed Logs in the application: org.springframework.jdbc.UncategorizedSQLException: PreparedStatementCallback; uncategorized SQLException for SQL [UPDATE SPRING_SESSION_ATTRIBUTES SET ATTRIBUTE_BYTES = ? WHERE SESSION_ID = ? AND ATTRIBUTE_NAME = ?]; SQL state [72000]; error code [1652]; ORA-01652: unable to extend temp segment by 128 in tablespace TEMP ; nested exception is java.sql.SQLException: ORA-01652: unable to extend temp segment by 128 in tablespace TEMP

    at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:90)
    at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:82)
    at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:82)
    at org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:649)
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:870)
    at org.springframework.jdbc.core.JdbcTemplate.update(JdbcTemplate.java:931)
    at org.springframework.session.jdbc.JdbcOperationsSessionRepository$2.doInTransactionWithoutResult(JdbcOperationsSessionRepository.java:453)
    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:419)
    at org.springframework.session.jdbc.JdbcOperationsSessionRepository.save(JdbcOperationsSessionRepository.java:130)
    at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.commitSession(SessionRepositoryFilter.java:249)
    at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.access$100(SessionRepositoryFilter.java:221)
    at org.springframework.session.web.http.SessionRepositoryFilter.doFilterInternal(SessionRepositoryFilter.java:174)
    at org.springframework.session.web.http.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:80)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.boot.actuate.autoconfigure.MetricsFilter.doFilterInternal(MetricsFilter.java:106)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.web.filter.CorsFilter.doFilterInternal(CorsFilter.java:96)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803)
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)

[chkrishna411]

To elaborate more, We have enabled debug for spring session and following are the logs, which clearly tells that we are copying bytes into temporary lob. Can anyone please explain what would be the process for clean up.?

2019-01-22 12:31:24.273 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Executing prepared SQL statement [UPDATE CONSUMER_SESSION_ATTRIBUTES SET ATTRIBUTE_BYTES = ? WHERE SESSION_ID = ? AND ATTRIBUTE_NAME = ?] 2019-01-22 12:31:26.592 DEBUG [org.springframework.jdbc.support.lob.TemporaryLobCreator] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Copied bytes into temporary BLOB with length 12 2019-01-22 12:31:26.602 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] SQL update affected 0 rows 2019-01-22 12:31:26.604 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Executing prepared SQL update 2019-01-22 12:31:26.604 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Executing prepared SQL statement [INSERT INTO CONSUMER_SESSION_ATTRIBUTES(SESSION_ID, ATTRIBUTE_NAME, ATTRIBUTE_BYTES) SELECT SESSION_ID, ?, ? FROM CONSUMER_SESSION WHERE SESSION_ID = ?] 2019-01-22 12:31:28.006 DEBUG [org.springframework.jdbc.support.lob.TemporaryLobCreator] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Copied bytes into temporary BLOB with length 12 2019-01-22 12:31:28.017 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] SQL update affected 1 rows 2019-01-22 12:31:28.017 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Executing prepared SQL update 2019-01-22 12:31:28.017 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Executing prepared SQL statement [UPDATE CONSUMER_SESSION_ATTRIBUTES SET ATTRIBUTE_BYTES = ? WHERE SESSION_ID = ? AND ATTRIBUTE_NAME = ?] 2019-01-22 12:31:29.470 DEBUG [org.springframework.jdbc.support.lob.TemporaryLobCreator] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Copied bytes into temporary BLOB with length 3539 2019-01-22 12:31:29.498 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] SQL update affected 1 rows 2019-01-22 12:31:29.498 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Executing prepared SQL update 2019-01-22 12:31:29.498 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Executing prepared SQL statement [UPDATE CONSUMER_SESSION_ATTRIBUTES SET ATTRIBUTE_BYTES = ? WHERE SESSION_ID = ? AND ATTRIBUTE_NAME = ?] 2019-01-22 12:31:31.066 DEBUG [org.springframework.jdbc.support.lob.TemporaryLobCreator] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Copied bytes into temporary BLOB with length 10 2019-01-22 12:31:31.077 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] SQL update affected 1 rows 2019-01-22 12:31:31.077 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Executing prepared SQL update 2019-01-22 12:31:31.077 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Executing prepared SQL statement [UPDATE CONSUMER_SESSION_ATTRIBUTES SET ATTRIBUTE_BYTES = ? WHERE SESSION_ID = ? AND ATTRIBUTE_NAME = ?] 2019-01-22 12:31:32.234 DEBUG [org.springframework.jdbc.support.lob.TemporaryLobCreator] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Copied bytes into temporary BLOB with length 18 2019-01-22 12:31:32.245 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] SQL update affected 1 rows 2019-01-22 12:31:32.245 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Executing prepared SQL update 2019-01-22 12:31:32.245 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Executing prepared SQL statement [UPDATE CONSUMER_SESSION_ATTRIBUTES SET ATTRIBUTE_BYTES = ? WHERE SESSION_ID = ? AND ATTRIBUTE_NAME = ?] 2019-01-22 12:31:33.247 DEBUG [org.springframework.jdbc.support.lob.TemporaryLobCreator] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Copied bytes into temporary BLOB with length 16 2019-01-22 12:31:33.258 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] SQL update affected 1 rows 2019-01-22 12:31:33.258 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Executing prepared SQL update 2019-01-22 12:31:33.258 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Executing prepared SQL statement [UPDATE CONSUMER_SESSION_ATTRIBUTES SET ATTRIBUTE_BYTES = ? WHERE SESSION_ID = ? AND ATTRIBUTE_NAME = ?] 2019-01-22 12:31:33.959 DEBUG [org.springframework.jdbc.support.lob.TemporaryLobCreator] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Copied bytes into temporary BLOB with length 21 2019-01-22 12:31:33.970 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] SQL update affected 1 rows 2019-01-22 12:31:33.970 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Executing prepared SQL update 2019-01-22 12:31:33.970 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Executing prepared SQL statement [UPDATE CONSUMER_SESSION_ATTRIBUTES SET ATTRIBUTE_BYTES = ? WHERE SESSION_ID = ? AND ATTRIBUTE_NAME = ?] 2019-01-22 12:31:34.981 DEBUG [org.springframework.jdbc.support.lob.TemporaryLobCreator] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Copied bytes into temporary BLOB with length 16 2019-01-22 12:31:34.992 DEBUG [org.springframework.jdbc.core.JdbcTemplate] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] SQL update affected 1 rows 2019-01-22 12:31:34.992 DEBUG [org.springframework.jdbc.datasource.DataSourceUtils] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Returning JDBC Connection to DataSource 2019-01-22 12:31:34.992 DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] [http-nio-8080-exec-5] [f64b111d-217f-4984-83c1-9111e0ed557c] Initiating transaction commit

[vpavic]

Thanks for the report @chkrishna411.

Could you provide more details about your environment - specifically which versions of Spring Framework, Oracle database and Oracle JDBC driver do you use?

There have been a few similar reports against Spring Framework's JDBC support albeit very long time ago - see spring-projects/spring-framework#10666 and spring-projects/spring-framework#10877. Note thought, that OracleLobHandler has been removed in Spring Framework 5.0 - however since you're using Spring Session 1.3, chances are you're still on Spring Framework 4.3 where OracleLobHandler is still available. If so, could you try the following workaround?

@Bean
public LobHandler springSessionLobHandler() {
    OracleLobHandler lobHandler = new OracleLobHandler();
    lobHandler.setReleaseResourcesAfterRead(true);
    return lobHandler;
}

Also note that in Spring Session we're using DefaultLobHandler with createTemporaryLob turned on for Oracle due to #1203.

[chkrishna411]

We are using, Spring boot 1.5.8. Spring framework 4.3.12 Oracle version Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production

It looks like OracleLobHandler is deprecated in spring-jdbc:4.3.12 version.

After debugging, it seems like, spring session is using DefaultLobHandler for Create Lob's. Based on your suggestion, we need to use deprecated class by enabling release resources to properly clear the TEMP space.

We will test with OracleLobHandler. will there be anything else that we need to consider if we are using deprecated OracleLobHandler.?

[vpavic]

Thanks for following up @chkrishna411.

Yes, as mentioned in my previous comment, the OracleLobHandler was removed in Spring Framework 5.0 following a deprecation period. My aim here is to determine whether OracleLobHandler works for your case, because looking at DefaultLobHandler Javadoc it should supersede the capabilities of Oracle specific implementation:

Deprecated. in favor of DefaultLobHandler for the Oracle 10g driver and higher. Consider using the 10g/11g driver even against an Oracle 9i database! DefaultLobHandler.setCreateTemporaryLob(boolean) is the direct equivalent of this OracleLobHandler's implementation strategy, just using standard JDBC 4.0 API. That said, in most cases, regular DefaultLobHandler setup will work fine as well.

Could you also provide the information about Oracle JDBC driver version you use, as requested in the previous comment? If you're using a recent release of Oracle JDBC driver, this perhaps looks like a Spring Framework's JDBC support issue.

[chkrishna411]

We are using 12.1.0.1 JDBC Driver. ojdbc8-12.2.0.1.jar ucp-12.2.0.1.jar

[vpavic]

Did you manage to give OracleLobHandler a try @chkrishna411?

[chkrishna411]

We have tried using OracleLobHandler, but it didn't help. We have created almost 120,000 sessions in in our QA environment to simulate the issue. When we checked with DBA team, we have used almost 16GB, and it was not released.

[vpavic]

Thanks for the feedback @chkrishna411. Just to confirm, you did use OracleLobHandler with releaseResourcesAfterRead property set to true as described in this comment?

[vpavic]

Any feedback @chkrishna411? There's little we at the Session side can do, if anything this looks like a Framework issue, but before opening issue there I'd first like to confirm that you've tried using OracleLobHandler with releaseResourcesAfterRead property set to true.

[vpavic]

Closing due to lack of feedback. Please comment back if you can provide more details and we can re-open the issue.

[vpavic]

1654 got to the bottom of this.