We have 3 to 4 environments with identical setup, each with multiple clustered application servers (WebSphere) and Oracle Supercluster databases.
The problem I am seeing seems to be happening in only one of the environments that too about 20% of the time.
We have
Two applications deployed to same application server cluster
Both applications use the same data source configured to use the Oracle database which is a Oracle Supercluster.
Following is the structure of the table in question
TABLE SESSION_TBL
(
ID NUMBER(12, 0) NOT NULL,
USER_ID VARCHAR2(256 BYTE) NOT NULL,
SESSION_ID VARCHAR2(60 BYTE) NOT NULL,
LOGIN_TIME TIMESTAMP(6) NOT NULL
)
Application 1 stores a record using JDBC
String sql = "Insert into SESSION_TBL " +
" (USER_ID, SESSION_ID, LOGIN_TIME ) " +
" values (?,?,SYSDATE)";
try
{
sessionId = getNewSessionId(userId);
st = conn.prepareStatement(sql);
st.setString(1, userId);
st.setString(2, sessionId);
int rows = st.executeUpdate();
}
After a few seconds, Application 2 executes the following code to look up the record inserted by the first application and compares with the current time
Statement st = null;
ResultSet result = null;
String sql = " Select * " +
" from SESSION_TBL " +
" where USER_ID = '" + userId + "' " +
" and SESSION_ID = '" + sessionId + "' ";
try {
st = conn.createStatement();
result = st.executeQuery(sql);
if(!result.next()) { // We have no data, need to expire the session
logger.debug("End hasSessionExpired()");
return true;
}
else {
logger.debug("SessionInfo:ResultSet not null");
}
// Get the time user logged in
// java.sql.Timestamp
Timestamp database_date = result.getTimestamp("LOGIN_TIME"); // get date from db
long databaseDate = database_date.getTime(); // Convert to UNIX time
// Get the current time from the database, so we are getting the time
// from the same sources to compare
// See the code below for this function
long currentTime = getCurrentTimeFromDB (conn);
// Both time values would be in milli seconds
long diffSecs = (currentTime - databaseDate)/1000;
logger.info ("db:" + databaseDate + " now:" + currentTime + " diffSecs:" + diffSecs);
Code to get the current time from the database
public static long getCurrentTimeFromDB () {
.
.
// Using SYSDATE. We only need precision upto seconds
String s = "SELECT SYSDATE NOW FROM DUAL";
rs = statement.executeQuery(s);
if (rs.next()) {
Timestamp dbTime = rs.getTimestamp("NOW");
currentTime = dbTime.getTime();
}
return currentTime;
}
In about 1 of 5 or so executions, I see the current time to be earlier than the time of the record creation (login time). When this happens I see an output of the debug statement like the following:
db:1538793249000 now:1538793023000 diffSecs:-226
db:1538793249000 now:1538793023000 diffSecs:-202
db:1538793249000 now:1538793023000 diffSecs:-225
Seems like about 200+ seconds earlier
If you notice one thing the data type of the column (LOGIN_TIME) is a Timestamp and I am using SYSDATE to populate it. However, I am also using SYSDATE to get the time from DUAL. Of the 4 environments we have, this is happening in one and not always. Is there something wrong in the code or is it possible that the database Oracle super cluster) is actually returning a date that is not correct.
I thought I would put an answer in case someone else runs into a similar problem. As folks have suggested (in the comments) that the cluster nodes times could be out of sync. We have 2 nodes in the cluster, one node was ahead (of the current time) by a couple of minutes. One could detect if the time is out of sync, by running a SYSDATE query against each node.