Jetty.project: Jetty jdbc session manager causing exceptions for violating primary key in inserting session in the table

[dhawal96]

Jetty version
9.4.26.v20200117 and jetty-9.4.25.v20191220, maybe some older versions too

Java version
8

Description
Our application uses dropwizard 1.3.15, which comes shipped with Jetty version 9.4.18.v20190429. We have had to force bump all jetty modules to jetty-9.4.25.v20191220 in order to expose setting the samesite attribute to the session cookie for Chrome 80. Unfortunately, our application reports the following stacktrace several times a day after upgrading:

! com.microsoft.sqlserver.jdbc.SQLServerException: Violation of PRIMARY KEY constraint 'JETTYSESSIONS_PK'. Cannot insert duplicate key in object 'dbo.JETTYSESSIONS'. The duplicate key value is (4251317910uwtktdazin8denyp4qfdyqs57126, , 0.0.0.0). 
! at com.microsoft.sqlserver.jdbc.SQLServerException.makeFromDatabaseError(SQLServerException.java:217) 
! at com.microsoft.sqlserver.jdbc.SQLServerStatement.getNextResult(SQLServerStatement.java:1635) 
! at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.doExecutePreparedStatement(SQLServerPreparedStatement.java:426) 
! at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement$PrepStmtExecCmd.doExecute(SQLServerPreparedStatement.java:372) 
! at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:6276) 
! at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(SQLServerConnection.java:1793) 
! at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeCommand(SQLServerStatement.java:184) 
! at com.microsoft.sqlserver.jdbc.SQLServerStatement.executeStatement(SQLServerStatement.java:159) 
! at com.microsoft.sqlserver.jdbc.SQLServerPreparedStatement.executeUpdate(SQLServerPreparedStatement.java:315) 
! at org.eclipse.jetty.server.session.JDBCSessionDataStore.doInsert(JDBCSessionDataStore.java:727) 
! at org.eclipse.jetty.server.session.JDBCSessionDataStore.doStore(JDBCSessionDataStore.java:676) 
! at org.eclipse.jetty.server.session.AbstractSessionDataStore$1.run(AbstractSessionDataStore.java:142) 
! at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1382) 
! at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1401) 
! at org.eclipse.jetty.server.session.SessionContext.run(SessionContext.java:92) 
! at org.eclipse.jetty.server.session.AbstractSessionDataStore.store(AbstractSessionDataStore.java:155) 
! at org.eclipse.jetty.server.session.AbstractSessionCache.release(AbstractSessionCache.java:566) 
! at org.eclipse.jetty.server.session.SessionHandler.complete(SessionHandler.java:368) 
! at org.eclipse.jetty.server.Request.leaveSession(Request.java:399) 
! at org.eclipse.jetty.server.Request.onCompleted(Request.java:1531) 
! at org.eclipse.jetty.server.HttpChannel.onCompleted(HttpChannel.java:732) 
! at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:363) 
! at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:270) 
! at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) 
! at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) 
! at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) 
! at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) 
! at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) 
! at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) 
! at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) 
! at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:388) 
! at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806) 
! at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938) 
! at java.lang.Thread.run(Thread.java:748) 

At the same time we are receiving these errors, I don't see any user making a call to our application, which lets me to believe that this is happening in the background every few hours or so without user interaction (simply the application running). As you can see, the full stacktrace does not include our application code, only jetty and sql related.

We also tried version 9.4.26.v20200117, but it appears this issue still persists.

I think some change between version 9.4.18.v20190429 and 9.4.26.v20200117 caused this bug to appear, but it's quite difficult for me to try out all versions. The root issue is jetty tries to insert the same session id into the jdbc session table causing a primary key violation.

[janbartel]

It looks to me like there is a request that is finished being processed, which is why the session is being saved. The session's last saved field is 0, meaning that it has never been saved before, thus it is strange that there should already be an existing key for it in the database.

Can you please paste all of your configuration for sessions in jetty.

Also, please turn on debug logging for sessions and post the log to this issue. To enable debug for sessions, use -Dorg.eclipse.jetty.server.session=DEBUG system property (if using jetty stderr logger).

[dhawal96]

Here is our schema in liquibase:

    <comment>Create JETTYSESSIONS table</comment>
    <createTable tableName="JETTYSESSIONS">
      <column name="SESSIONID" type="java.sql.Types.NVARCHAR(120)">
         <constraints nullable="false"/>
      </column>
      <column name="CONTEXTPATH" type="java.sql.Types.NVARCHAR(60)">
         <constraints nullable="false"/>
      </column>
      <column name="VIRTUALHOST" type="java.sql.Types.NVARCHAR(60)">
         <constraints nullable="false"/>
      </column>
      <column name="LASTNODE" type="java.sql.Types.NVARCHAR(60)"/>
      <column name="ACCESSTIME" type="BIGINT"/>
      <column name="LASTACCESSTIME" type="BIGINT"/>
      <column name="CREATETIME" type="BIGINT"/>
      <column name="COOKIETIME" type="BIGINT"/>
      <column name="LASTSAVEDTIME" type="BIGINT"/>
      <column name="EXPIRYTIME" type="BIGINT"/>
      <column name="MAXINTERVAL" type="BIGINT"/>
      <column name="MAP" type="java.sql.Types.VARBINARY(MAX)"/>
    </createTable>
  </changeSet>

    <comment>Primary key JETTYSESSIONS_PK added to JETTYSESSIONS table</comment>
    <addPrimaryKey tableName="JETTYSESSIONS"
                   columnNames="SESSIONID, CONTEXTPATH, VIRTUALHOST"
                   constraintName="JETTYSESSIONS_PK"/>
  </changeSet>

Here is our session configuration:

    @Override
    public void run(Configuration configuration, Environment environment)
    {
        environment.lifecycle().addLifeCycleListener(new AbstractLifeCycleListener()
        {
            @Override
            public void lifeCycleStarting(LifeCycle event)
            {
                if (!(event instanceof Server))
                {
                    return;
                }

                DefaultSessionIdManager sessionIdManager = new DefaultSessionIdManager(
                    (Server) event);
                SessionHandler sessionHandler = new SessionHandler();
                sessionHandler.setSessionIdManager(sessionIdManager);

                DataSourceFactory dataSourceFactory = configuration.getDataSourceFactory();

                String driver = dataSourceFactory.getDriverClass();
                String url = dataSourceFactory.getUrl()
                    + ";user=" + dataSourceFactory.getUser()
                    + ";password=" + dataSourceFactory.getPassword();

                DatabaseAdaptor databaseAdaptor = new DatabaseAdaptor();
                databaseAdaptor.setDriverInfo(driver, url);
                databaseAdaptor.setBlobType("varbinary(MAX)");

                JDBCSessionDataStoreFactory jdbcSessionDataStoreFactory = new JDBCSessionDataStoreFactory();
                jdbcSessionDataStoreFactory.setDatabaseAdaptor(databaseAdaptor);
                JDBCSessionDataStore dataStore =
                    (JDBCSessionDataStore) jdbcSessionDataStoreFactory.getSessionDataStore(sessionHandler);

                JDBCSessionDataStore.SessionTableSchema sessionTableSchema =
                    new JDBCSessionDataStore.SessionTableSchema();
                sessionTableSchema.setTableName("JETTYSESSIONS");

                dataStore.setSessionTableSchema(sessionTableSchema);

                SessionCache sessionCache = new NullSessionCache(sessionHandler);
                sessionCache.setSaveOnCreate(true);
                sessionCache.setSessionDataStore(dataStore);

                sessionHandler.setSessionCache(sessionCache);
                sessionHandler.setHttpOnly(true);
                sessionHandler.setSessionCookie("SESSION_COOKIE");

                sessionHandler.setMaxInactiveInterval(24 * 3600);

                environment.servlets().setSessionHandler(sessionHandler);

                environment.getApplicationContext().getServletContext().getSessionCookieConfig()
                    .setComment(HttpCookie.SAME_SITE_NONE_COMMENT);
            }
        });
        }

[dhawal96]

actually @janbartel the 0.0.0.0 is not the last saved field, but the VIRTUALHOST column. (see the primary key I've listed in the above comment. Correct me if I'm wrong.

[janbartel]

Thanks for the info, I will look it over.

I'm referring to the lastsaved field on the SessionData object, not the virtual host field as shown in the primary key.

[janbartel]

@dhawal96 I'm really going to need to see the log output with session debug enabled, please post as soon as you have it.

Also, can you please dump out the database row for some of these sessions that exhibit the problem, and post those as well as the jetty log.

[janbartel]

@dhawal96 also, there is something odd about your session ids as reported by the database exception: the settings you posted for the DefaultSessionIdManager should result in each session id being prefixed by "node0", yet I don't see that. Is it possible that a different session id manager is being used, or that there are other settings being applied?

[janbartel]

@dhawal96 any progress?

[dhawal96]

@janbartel we are using SLF4J logging, putting it on debug mode may take some time, because the application having the issues is in prod deployment. I will look into providing that info when possible. By the way, where is the code that prefixes session IDs with "node0"? I'm not aware of this, maybe newer Jetty versions removed this? Also, not sure if this helps, but I looked at a couple login calls being made to our application before the stacktrace, and I found the following:

2020-01-29 01:07:10,831  WARN - org.eclipse.jetty.server.session - Error loading session 1128335879937lon6lkswm1f85qadzwh5tw128 

and

2020-01-29 01:07:10,895  WARN  org.eclipse.jetty.server.session - Save of new session 1128335879937lon6lkswm1f85qadzwh5tw128 failed 

before the primary key violation.

[janbartel]

@dhawal96 for the prefix of "nodeX" see line https://github.com/eclipse/jetty.project/blob/jetty-9.4.26.v20200117/jetty-server/src/main/java/org/eclipse/jetty/server/session/DefaultSessionIdManager.java#L270, and also https://github.com/eclipse/jetty.project/blob/jetty-9.4.26.v20200117/jetty-server/src/main/java/org/eclipse/jetty/server/session/DefaultSessionIdManager.java#L327. The code you pasted shows you setting up the DefaultSessionIdManager, and I don't see you supplying a value for the workerName explicitly. If the environment variable JETTY_WORKER_INSTANCE was set elsewhere, then you'd still have the prefix "nodeX" on your sessions, where "X" is the value of JETTY_WORKER_INSTANCE. As I don't see the "nodeX" prefix at all, I'm wondering if somewhere else is supplying a different session configuration that is out of your control?

Also, please post as much of the logs you have - I need to see the lifecycles of these sessions that are causing the problem. It would be ideal if you could gather more logs with DEBUG enabled for sessions - do you have a test bed that can reproduce the problem?

[dhawal96]

@janbartel Ok.. actually I do see piece I left out:

        ((DefaultSessionIdManager) sessionHandler.getSessionIdManager())
            .setWorkerName(MyClass.getValue());

So it makes sense we don't see "node0", we have our own implementation for getting the value.

I am now setting DEBUG mode on, will provide an update shortly with a better stacktrace. By the way, I noticed the log "org.eclipse.jetty.server.session - Error loading session 1128335879937lon6lkswm1f85qadzwh5tw128" was recently added in a newer Jetty version than 9.4.18.v20190429. I'm taking a guess here... but I think for some reason Jetty code cannot load an existing session ID from our database, even though the entry is already present in the table. Then since it's not found, it tries to insert and causes a primary key violation. This is solely a guess atm, but do you think something like that is possible?

[janbartel]

@dhawal96 I think I have an idea what is going on. You are on the right track.

For some reason, your database is intermittently reporting it cannot load an existing session. Seems like it is not consistent, sometimes it can load it, sometimes not. The fix for #3913 was done for jetty-9.4.21, and it appears that in it we changed behaviour by not rethrowing an UnreadableSessionDataException upon failure to load a session, and returned null instead. Returning null is making it look as if the session doesn't exist. At some later point in the request handling your app must ask for a session: because the cookie is set on the request with the (previously unreadable) session id, the new session will try and use this same id, causing the clash. It's worth noting that when we re-use this id, it is only because the database reports that the id exists! So some queries for this id do work, even if the whole session cannot be read for some reason.

I'm working on a fix to reinstate the throw for UnreadableSessionDataException.

Meanwhile, you might want to look at your database to see what is the cause of the intermittent errors. It's worth fixing, because the previous jetty behaviour - which I will reinstate - was to invalidate the unreadable session, so because of the flakiness in reading sessions your users are having their sessions needlessly invalidated and recreated.

[dhawal96]

@janbartel if I'm understanding correct, the old behavior throws an exception, which basically recreates a new session ID if the load fails for some reason, even though db entry exists. The new behavior will simply return "null", equivalent to saying "session doesn't exist", then tries to insert it into the database even though the id is already inserted. Is that correct?

Also, "I'm working on a fix to reinstate the throw for UnreadableSessionDataException", is there a link of a related issue/ticket I can follow? Sounds like this is the fix for us

[dhawal96]

@janbartel I've enabled debug mode. Waiting for the next exception and then I'll post a stacktrace

[janbartel]

Raised PR #4528

[dhawal96]

@janbartel here's a debug log
debug_stacktrace.txt

[dhawal96]

@janbartel thank for you swiftly responding to this issue. Are you able to provide an ETA when the new jetty version can be released? As you know, Chrome 80 is set to release early next week, it would be great if we can utilize the new version asap. Thanks.

[janbartel]

@dhawal96 thanks for the debug logs. Very interesting. I think you have bigger issues that just the fix (that I'll still do, because it re-instates previous behaviour).

It looks to me from the logs like you have multiple servers, and a non-sticky load balancer. The sessions are bouncing around from one server to the other, multiple servers handling the same session concurrently, and maybe even that servers change their worker names each time they start up?

Taking the last and least serious issue first, if servers change identity each time they restart, then session cookies will all be reset the first time a request accesses a session on a server.

Secondly, as your requests for the same session are not always directed to the same server, pretty much every time you handle a request you will be resetting the session cookie because the server that is handling it is likely different from the last server that handled it.

Most importantly, if a session is "live" on multiple servers at once, the state of the session is non-deterministic: there's just no way to guarantee how updating session attributes interleaves amongst the servers. Worse, it is entirely possible that a session that has been invalidated by one server can be resurrected by a different server, depending on the states of the requests using the session on the different servers.

Some of the most interesting log information happens at time 2020-01-29 22:16:32,044. We see a call to invalidate the session. This must be from some previous request that is not captured in the log, as pretty much all requests before this point in the log report an error trying to load the session, so it must be for an earlier request where the load succeeded. The invalidate proceeds as expected, and the session is deleted from the database. At 2020-01-29 22:16:32,146 we see that the code creates a new session, and that a new id is selected, because the id that was present on the session cookie has just been deleted from the database at 2020-01-29 22:16:32,100. There are many other requests for the old session cookie for the deleted session - these all report an error on attempting to load it, which is strange, as the row not existing is not an error. In any case, at 2020-01-29 22:16:28,247 the code requests the creation of a session for the deleted id, and at this point the database reports that it _does_ exist, leading to the primary key clash. The only way that row could exist is if either the row was never really deleted during the invalidation, or some other server has resurrected the session in the meantime. There's no evidence of a failure to delete, so the only option is that another server is involved.

I very strongly recommend that you use a sticky load balancer to ensure a session is live on only 1 server at a time and thus the integrity of the session is maintained. It may also be the case that you should consider the DefaultSessionCache if, as it seems from the logs, that you have multiple simultaneous requests for the same session - this will significantly lower the load on the database by caching the session data in memory, and also help to ensure the integrity of the state of the session. It might be worthwile having a read of the page on session use-cases here: https://www.eclipse.org/jetty/documentation/9.4.26.v20200117/sessions-usecases.html

[janbartel]

As regards same-site cookies, the next release for 9.4 will contain the ability to set a default value for the same-site attribute, see https://github.com/eclipse/jetty.project/pull/4512

[dhawal96]

@janbartel any update when 9.4.27 can be released? thanks

[joakime]

Jetty 9.4.27.v20200227 has been released.

[janbartel]

I believe this issue is fixed so closing.