Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Added new named logger for connection open retries and idle connection resiliency reconnects #2250

Merged
merged 7 commits into from
Nov 15, 2023
Merged

Added new named logger for connection open retries and idle connection resiliency reconnects #2250

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
83e6d93
Added new named logger
tkyc Nov 9, 2023
6163e72
Additional named logger changes
tkyc Nov 9, 2023
3effa93
FINE logging for start/success/failure of ICR
tkyc Nov 9, 2023
e1b2acc
FINE logging for start/success/failure of open connection retries
tkyc Nov 9, 2023
28bad50
Switched to isEmpty from isBlank to support jdk 8
tkyc Nov 14, 2023
dc42c7a
Added redirection logger
tkyc Nov 15, 2023
a2fbaed
Switched to FINE logging for redirection logger
tkyc Nov 15, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
45 changes: 35 additions & 10 deletions src/main/java/com/microsoft/sqlserver/jdbc/IdleConnectionResiliency.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,8 @@
import java.util.concurrent.atomic.AtomicInteger;
import java.util.logging.Level;

import static com.microsoft.sqlserver.jdbc.SQLServerConnection.loggerResiliency;


class IdleConnectionResiliency {
private static final java.util.logging.Logger loggerExternal = java.util.logging.Logger
Expand Down Expand Up @@ -423,17 +425,17 @@ private ReconnectThread() {}
connectRetryCount = con.getRetryCount();
eReceived = null;
stopRequested = false;
if (loggerExternal.isLoggable(Level.FINER)) {
loggerExternal.finer("ReconnectThread initialized. Connection retry count = " + connectRetryCount
if (loggerResiliency.isLoggable(Level.FINER)) {
loggerResiliency.finer("Idle connection resiliency - ReconnectThread initialized. Connection retry count = " + connectRetryCount
+ "; Command = " + cmd.toString());
}

}

@Override
public void run() {
if (loggerExternal.isLoggable(Level.FINER)) {
loggerExternal.finer("Starting ReconnectThread for command: " + command.toString());
if (loggerResiliency.isLoggable(Level.FINER)) {
loggerResiliency.finer("Idle connection resiliency - starting ReconnectThread for command: " + command.toString());
}
boolean interruptsEnabled = command.getInterruptsEnabled();
/*
Expand All @@ -457,25 +459,45 @@ public void run() {
long connectRetryInterval = TimeUnit.SECONDS.toMillis(con.getRetryInterval());

while ((connectRetryCount >= 0) && (!stopRequested) && keepRetrying) {
if (loggerExternal.isLoggable(Level.FINER)) {
loggerExternal.finer("Running reconnect for command: " + command.toString() + " ; ConnectRetryCount = "
if (loggerResiliency.isLoggable(Level.FINER)) {
loggerResiliency.finer("Idle connection resiliency - running reconnect for command: " + command.toString() + " ; connectRetryCount = "
+ connectRetryCount);
}

try {
eReceived = null;
con.connect(null, con.getPooledConnectionParent());
keepRetrying = false;

if (loggerResiliency.isLoggable(Level.FINE)) {
loggerResiliency.fine("Idle connection resiliency - reconnect attempt succeeded ; connectRetryCount = " + connectRetryCount);
}

} catch (SQLServerException e) {

if (loggerResiliency.isLoggable(Level.FINE)) {
loggerResiliency.fine("Idle connection resiliency - reconnect attempt failed ; connectRetryCount = " + connectRetryCount);
}

if (!stopRequested) {
eReceived = e;
if (con.isFatalError(e)) {

if (loggerResiliency.isLoggable(Level.FINER)) {
loggerResiliency.finer("Idle connection resiliency - reconnect for command: " + command.toString() + " encountered fatal error: " + e.getMessage() + " - stopping reconnect attempt.");
}

keepRetrying = false;
} else {
try {
if (connectRetryCount > 1) {
Thread.sleep(connectRetryInterval);
}
} catch (InterruptedException ie) {
if (loggerResiliency.isLoggable(Level.FINER)) {
loggerResiliency.finer("Idle connection resiliency - query timed out for command: " + command.toString() + ". Stopping reconnect attempt.");
}

// re-interrupt thread
Thread.currentThread().interrupt();

Expand All @@ -490,6 +512,9 @@ public void run() {
try {
command.checkForInterrupt();
} catch (SQLServerException e) {
if (loggerResiliency.isLoggable(Level.FINER)) {
loggerResiliency.finer("Idle connection resiliency - timeout occurred on reconnect: " + command.toString() + ". Stopping reconnect attempt.");
}
// Interrupted, timeout occurred. Stop retrying.
keepRetrying = false;
eReceived = e;
Expand All @@ -504,8 +529,8 @@ public void run() {

command.setInterruptsEnabled(interruptsEnabled);

if (loggerExternal.isLoggable(Level.FINER)) {
loggerExternal.finer("ReconnectThread exiting for command: " + command.toString());
if (loggerResiliency.isLoggable(Level.FINER)) {
loggerResiliency.finer("Idle connection resiliency - ReconnectThread exiting for command: " + command.toString());
}

if (timeout != null) {
Expand All @@ -520,8 +545,8 @@ public void run() {
}

void stop(boolean blocking) {
if (loggerExternal.isLoggable(Level.FINER)) {
loggerExternal.finer("ReconnectThread stop requested for command: " + command.toString());
if (loggerResiliency.isLoggable(Level.FINER)) {
loggerResiliency.finer("ReconnectThread stop requested for command: " + command.toString());
}
stopRequested = true;
if (blocking && this.isAlive()) {
Expand Down
99 changes: 76 additions & 23 deletions src/main/java/com/microsoft/sqlserver/jdbc/SQLServerConnection.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1580,7 +1580,10 @@ final SQLCollation getDatabaseCollation() {
.getLogger("com.microsoft.sqlserver.jdbc.internals.SQLServerConnection");
static final private java.util.logging.Logger loggerExternal = java.util.logging.Logger
.getLogger("com.microsoft.sqlserver.jdbc.Connection");

static final java.util.logging.Logger loggerResiliency = java.util.logging.Logger
.getLogger("com.microsoft.sqlserver.jdbc.Resiliency");
static final java.util.logging.Logger loggerRedirection = java.util.logging.Logger
.getLogger("com.microsoft.sqlserver.jdbc.Redirection");
private static String loggingClassNameBase = "com.microsoft.sqlserver.jdbc.SQLServerConnection";

/** Instance-specific loggingClassName to identity the connection in logs */
Expand Down Expand Up @@ -3072,9 +3075,9 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu
// and the original timeout is used instead of the timeout slice.
long intervalExpireFullTimeout = loginStartTime + loginTimeoutMs;

if (connectionlogger.isLoggable(Level.FINER)) {
connectionlogger.finer(toString() + " Start time: " + loginStartTime + " Time out time: " + timerExpire
+ " Timeout Unit Interval: " + timeoutUnitInterval);
if (loggerResiliency.isLoggable(Level.FINER)) {
loggerResiliency.finer(toString() + " Connection open - start time: " + loginStartTime + " time out time: " + timerExpire
+ " timeout unit interval: " + timeoutUnitInterval);
}

// Initialize loop variables
Expand Down Expand Up @@ -3106,6 +3109,9 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu
currentConnectPlaceHolder = currentFOPlaceHolder;
} else {
if (routingInfo != null) {
if (loggerRedirection.isLoggable(Level.FINE)) {
loggerRedirection.fine(toString() + " Connection open - redirecting to server and instance: " + routingInfo.getFullServerName());
}
currentPrimaryPlaceHolder = routingInfo;
routingInfo = null;
} else if (null == currentPrimaryPlaceHolder) {
Expand All @@ -3115,13 +3121,17 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu
currentConnectPlaceHolder = currentPrimaryPlaceHolder;
}

if (connectionlogger.isLoggable(Level.FINE)) {
connectionlogger
.fine(toString() + " This attempt server name: " + currentConnectPlaceHolder.getServerName()
if (loggerResiliency.isLoggable(Level.FINE) && retryAttempt > 0) {
loggerResiliency.fine(toString() + " Connection open - starting connection retry attempt number: " + retryAttempt);
}

if (loggerResiliency.isLoggable(Level.FINER)) {
loggerResiliency
.finer(toString() + " Connection open - attempt server name: " + currentConnectPlaceHolder.getServerName()
+ " port: " + currentConnectPlaceHolder.getPortNumber() + " InstanceName: "
+ currentConnectPlaceHolder.getInstanceName() + " useParallel: " + useParallel);
connectionlogger.fine(toString() + " This attempt endtime: " + intervalExpire);
connectionlogger.fine(toString() + " This attempt No: " + retryAttempt);
loggerResiliency.finer(toString() + " Connection open - attempt end time: " + intervalExpire);
loggerResiliency.finer(toString() + " Connection open - attempt number: " + retryAttempt);
}

// Attempt login. Use Place holder to make sure that the failoverdemand is done.
Expand All @@ -3144,6 +3154,10 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu

noOfRedirections++;

if (loggerRedirection.isLoggable(Level.FINE)) {
loggerRedirection.fine(toString() + " Connection open - redirection count: " + noOfRedirections);
}

if (noOfRedirections > 1) {
String msg = SQLServerException.getErrString("R_multipleRedirections");
terminate(SQLServerException.DRIVER_ERROR_UNSUPPORTED_CONFIG, msg);
Expand Down Expand Up @@ -3188,9 +3202,23 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu

continue;
}
} else
} else {
if (loggerResiliency.isLoggable(Level.FINE) && retryAttempt > 0) {
loggerResiliency.fine(toString() + " Connection open - connection retry succeeded on attempt number: " + retryAttempt);
}

break; // leave the while loop -- we've successfully connected
}
} catch (SQLServerException e) {

if (loggerResiliency.isLoggable(Level.FINE) && retryAttempt > 0) {
loggerResiliency.fine(toString() + " Connection open - connection retry failed on attempt number: " + retryAttempt);
}

if (loggerResiliency.isLoggable(Level.FINER) && (retryAttempt >= connectRetryCount)) {
loggerResiliency.finer(toString() + " Connection open - connection failed. Maximum connection retry count " + connectRetryCount + " reached.");
}

int errorCode = e.getErrorCode();
driverErrorCode = e.getDriverErrorCode();
sqlServerError = e.getSQLServerError();
Expand All @@ -3208,15 +3236,26 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu
|| timerHasExpired(timerExpire)
// for non-dbmirroring cases, do not retry after tcp socket connection succeeds
) {
if (connectionlogger.isLoggable(Level.FINE) && (retryAttempt >= connectRetryCount)) {
connectionlogger.fine(
"Connection failed. Maximum connection retry count " + connectRetryCount + " reached.");
if (loggerResiliency.isLoggable(Level.FINER)) {
loggerResiliency.finer(toString() + " Connection open - connection failed on attempt: " + retryAttempt + ".");
loggerResiliency.finer(toString() + " Connection open - connection failure. Driver error code: " + driverErrorCode);
if (null != sqlServerError && !sqlServerError.getErrorMessage().isEmpty()) {
loggerResiliency.finer(toString() + " Connection open - connection failure. SQL Server error : " + sqlServerError.getErrorMessage());
}
}

// close the connection and throw the error back
close();
throw e;
} else {
if (loggerResiliency.isLoggable(Level.FINER)) {
loggerResiliency.finer(toString() + " Connection open - connection failed on attempt: " + retryAttempt + ".");
loggerResiliency.finer(toString() + " Connection open - connection failure. Driver error code: " + driverErrorCode);
if (null != sqlServerError && !sqlServerError.getErrorMessage().isEmpty()) {
loggerResiliency.finer(toString() + " Connection open - connection failure. SQL Server error : " + sqlServerError.getErrorMessage());
}
}

// Close the TDS channel from the failed connection attempt so that we don't
// hold onto network resources any longer than necessary.
if (null != tdsChannel)
Expand All @@ -3231,6 +3270,14 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu
if ((!isDBMirroring || 1 == retryAttempt % 2
|| TimeUnit.SECONDS.toMillis(connectRetryInterval) >= remainingTime)
&& (remainingTime <= TimeUnit.SECONDS.toMillis(connectRetryInterval))) {
if (loggerResiliency.isLoggable(Level.FINER)) {
loggerResiliency.finer(toString() + " Connection open - connection failed on attempt: " + retryAttempt + ".");
loggerResiliency.finer(toString() + " Connection open - connection failure. Driver error code: " + driverErrorCode);
if (null != sqlServerError && !sqlServerError.getErrorMessage().isEmpty()) {
loggerResiliency.finer(toString() + " Connection open - connection failure. SQL Server error : " + sqlServerError.getErrorMessage());
}
}

throw e;
}
}
Expand All @@ -3244,19 +3291,19 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu
&& tlsRetryAttempt < INTERMITTENT_TLS_MAX_RETRY && !timerHasExpired(timerExpire)) {
// special case for TLS intermittent failures: no wait retries
tlsRetryAttempt++;
if (connectionlogger.isLoggable(Level.FINE)) {
connectionlogger.fine(
"Connection failed during SSL handshake. Retry due to an intermittent TLS 1.2 failure issue. Retry attempt = "
if (loggerResiliency.isLoggable(Level.FINER)) {
loggerResiliency.finer(toString() +
" Connection open - connection failed during SSL handshake. Retry due to an intermittent TLS 1.2 failure issue. Retry attempt = "
+ tlsRetryAttempt + " of " + INTERMITTENT_TLS_MAX_RETRY);
}
} else {
if (retryAttempt++ >= connectRetryCount && TransientError.isTransientError(sqlServerError)
&& !timerHasExpired(timerExpire) && (!isDBMirroring || (1 == retryAttempt % 2))) {
if (connectionlogger.isLoggable(Level.FINE)) {
connectionlogger.fine(toString() + " sleeping milisec: " + connectRetryInterval);
if (loggerResiliency.isLoggable(Level.FINER)) {
loggerResiliency.finer(toString() + " Connection open - sleeping milisec: " + connectRetryInterval);
}
if (connectionlogger.isLoggable(Level.FINEST)) {
connectionlogger.finest(toString() + "Connection failed on transient error "
if (loggerResiliency.isLoggable(Level.FINER)) {
loggerResiliency.finer(toString() + " Connection open - connection failed on transient error "
+ (sqlServerError != null ? sqlServerError.getErrorNumber() : "")
+ ". Wait for connectRetryInterval(" + connectRetryInterval + ")s before retry #"
+ retryAttempt);
Expand Down Expand Up @@ -4081,7 +4128,12 @@ boolean executeCommand(TDSCommand newCommand) throws SQLServerException {
preparedStatementHandleCache.clear();
}

if (loggerResiliency.isLoggable(Level.FINE)) {
loggerResiliency.fine(toString() + " Idle connection resiliency - starting idle connection resiliency reconnect.");
}

sessionRecovery.reconnect(newCommand);

} catch (InterruptedException e) {
// re-interrupt thread
Thread.currentThread().interrupt();
Expand All @@ -4090,10 +4142,11 @@ boolean executeCommand(TDSCommand newCommand) throws SQLServerException {
SQLServerException.makeFromDriverError(this, sessionRecovery, e.getMessage(), null,
false);
}

if (sessionRecovery.getReconnectException() != null) {
if (connectionlogger.isLoggable(Level.FINER)) {
connectionlogger.finer(
this.toString() + "Connection is broken and recovery is not possible.");
if (loggerResiliency.isLoggable(Level.FINER)) {
loggerResiliency.finer(
this.toString() + " Idle connection resiliency - connection is broken and recovery is not possible.");
}
throw sessionRecovery.getReconnectException();
}
Expand Down