Skip to content

Commit 09ae6b8

Browse files
tkyctkyc
authored
Added new named logger for connection open retries and idle connection resiliency reconnects (#2250)
1 parent 1f69f48 commit 09ae6b8

File tree

2 files changed

+111
-33
lines changed

2 files changed

+111
-33
lines changed

‎src/main/java/com/microsoft/sqlserver/jdbc/IdleConnectionResiliency.java

Lines changed: 35 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -11,6 +11,8 @@
1111
import java.util.concurrent.atomic.AtomicInteger;
1212
import java.util.logging.Level;
1313

14+
import static com.microsoft.sqlserver.jdbc.SQLServerConnection.loggerResiliency;
15+
1416

1517
class IdleConnectionResiliency {
1618
private static final java.util.logging.Logger loggerExternal = java.util.logging.Logger
@@ -423,17 +425,17 @@ private ReconnectThread() {}
423425
connectRetryCount = con.getRetryCount();
424426
eReceived = null;
425427
stopRequested = false;
426-
if (loggerExternal.isLoggable(Level.FINER)) {
427-
loggerExternal.finer("ReconnectThread initialized. Connection retry count = " + connectRetryCount
428+
if (loggerResiliency.isLoggable(Level.FINER)) {
429+
loggerResiliency.finer("Idle connection resiliency - ReconnectThread initialized. Connection retry count = " + connectRetryCount
428430
+ "; Command = " + cmd.toString());
429431
}
430432

431433
}
432434

433435
@Override
434436
public void run() {
435-
if (loggerExternal.isLoggable(Level.FINER)) {
436-
loggerExternal.finer("Starting ReconnectThread for command: " + command.toString());
437+
if (loggerResiliency.isLoggable(Level.FINER)) {
438+
loggerResiliency.finer("Idle connection resiliency - starting ReconnectThread for command: " + command.toString());
437439
}
438440
boolean interruptsEnabled = command.getInterruptsEnabled();
439441
/*
@@ -457,25 +459,45 @@ public void run() {
457459
long connectRetryInterval = TimeUnit.SECONDS.toMillis(con.getRetryInterval());
458460

459461
while ((connectRetryCount >= 0) && (!stopRequested) && keepRetrying) {
460-
if (loggerExternal.isLoggable(Level.FINER)) {
461-
loggerExternal.finer("Running reconnect for command: " + command.toString() + " ; ConnectRetryCount = "
462+
if (loggerResiliency.isLoggable(Level.FINER)) {
463+
loggerResiliency.finer("Idle connection resiliency - running reconnect for command: " + command.toString() + " ; connectRetryCount = "
462464
+ connectRetryCount);
463465
}
466+
464467
try {
465468
eReceived = null;
466469
con.connect(null, con.getPooledConnectionParent());
467470
keepRetrying = false;
471+
472+
if (loggerResiliency.isLoggable(Level.FINE)) {
473+
loggerResiliency.fine("Idle connection resiliency - reconnect attempt succeeded ; connectRetryCount = " + connectRetryCount);
474+
}
475+
468476
} catch (SQLServerException e) {
477+
478+
if (loggerResiliency.isLoggable(Level.FINE)) {
479+
loggerResiliency.fine("Idle connection resiliency - reconnect attempt failed ; connectRetryCount = " + connectRetryCount);
480+
}
481+
469482
if (!stopRequested) {
470483
eReceived = e;
471484
if (con.isFatalError(e)) {
485+
486+
if (loggerResiliency.isLoggable(Level.FINER)) {
487+
loggerResiliency.finer("Idle connection resiliency - reconnect for command: " + command.toString() + " encountered fatal error: " + e.getMessage() + " - stopping reconnect attempt.");
488+
}
489+
472490
keepRetrying = false;
473491
} else {
474492
try {
475493
if (connectRetryCount > 1) {
476494
Thread.sleep(connectRetryInterval);
477495
}
478496
} catch (InterruptedException ie) {
497+
if (loggerResiliency.isLoggable(Level.FINER)) {
498+
loggerResiliency.finer("Idle connection resiliency - query timed out for command: " + command.toString() + ". Stopping reconnect attempt.");
499+
}
500+
479501
// re-interrupt thread
480502
Thread.currentThread().interrupt();
481503

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

505530
command.setInterruptsEnabled(interruptsEnabled);
506531

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

511536
if (timeout != null) {
@@ -520,8 +545,8 @@ public void run() {
520545
}
521546

522547
void stop(boolean blocking) {
523-
if (loggerExternal.isLoggable(Level.FINER)) {
524-
loggerExternal.finer("ReconnectThread stop requested for command: " + command.toString());
548+
if (loggerResiliency.isLoggable(Level.FINER)) {
549+
loggerResiliency.finer("ReconnectThread stop requested for command: " + command.toString());
525550
}
526551
stopRequested = true;
527552
if (blocking && this.isAlive()) {

‎src/main/java/com/microsoft/sqlserver/jdbc/SQLServerConnection.java

Lines changed: 76 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -1592,7 +1592,10 @@ final SQLCollation getDatabaseCollation() {
15921592
.getLogger("com.microsoft.sqlserver.jdbc.internals.SQLServerConnection");
15931593
static final private java.util.logging.Logger loggerExternal = java.util.logging.Logger
15941594
.getLogger("com.microsoft.sqlserver.jdbc.Connection");
1595-
1595+
static final java.util.logging.Logger loggerResiliency = java.util.logging.Logger
1596+
.getLogger("com.microsoft.sqlserver.jdbc.Resiliency");
1597+
static final java.util.logging.Logger loggerRedirection = java.util.logging.Logger
1598+
.getLogger("com.microsoft.sqlserver.jdbc.Redirection");
15961599
private static String loggingClassNameBase = "com.microsoft.sqlserver.jdbc.SQLServerConnection";
15971600

15981601
/** Instance-specific loggingClassName to identity the connection in logs */
@@ -3093,9 +3096,9 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu
30933096
// and the original timeout is used instead of the timeout slice.
30943097
long intervalExpireFullTimeout = loginStartTime + loginTimeoutMs;
30953098

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

31013104
// Initialize loop variables
@@ -3127,6 +3130,9 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu
31273130
currentConnectPlaceHolder = currentFOPlaceHolder;
31283131
} else {
31293132
if (routingInfo != null) {
3133+
if (loggerRedirection.isLoggable(Level.FINE)) {
3134+
loggerRedirection.fine(toString() + " Connection open - redirecting to server and instance: " + routingInfo.getFullServerName());
3135+
}
31303136
currentPrimaryPlaceHolder = routingInfo;
31313137
routingInfo = null;
31323138
} else if (null == currentPrimaryPlaceHolder) {
@@ -3136,13 +3142,17 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu
31363142
currentConnectPlaceHolder = currentPrimaryPlaceHolder;
31373143
}
31383144

3139-
if (connectionlogger.isLoggable(Level.FINE)) {
3140-
connectionlogger
3141-
.fine(toString() + " This attempt server name: " + currentConnectPlaceHolder.getServerName()
3145+
if (loggerResiliency.isLoggable(Level.FINE) && retryAttempt > 0) {
3146+
loggerResiliency.fine(toString() + " Connection open - starting connection retry attempt number: " + retryAttempt);
3147+
}
3148+
3149+
if (loggerResiliency.isLoggable(Level.FINER)) {
3150+
loggerResiliency
3151+
.finer(toString() + " Connection open - attempt server name: " + currentConnectPlaceHolder.getServerName()
31423152
+ " port: " + currentConnectPlaceHolder.getPortNumber() + " InstanceName: "
31433153
+ currentConnectPlaceHolder.getInstanceName() + " useParallel: " + useParallel);
3144-
connectionlogger.fine(toString() + " This attempt endtime: " + intervalExpire);
3145-
connectionlogger.fine(toString() + " This attempt No: " + retryAttempt);
3154+
loggerResiliency.finer(toString() + " Connection open - attempt end time: " + intervalExpire);
3155+
loggerResiliency.finer(toString() + " Connection open - attempt number: " + retryAttempt);
31463156
}
31473157

31483158
// Attempt login. Use Place holder to make sure that the failoverdemand is done.
@@ -3165,6 +3175,10 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu
31653175

31663176
noOfRedirections++;
31673177

3178+
if (loggerRedirection.isLoggable(Level.FINE)) {
3179+
loggerRedirection.fine(toString() + " Connection open - redirection count: " + noOfRedirections);
3180+
}
3181+
31683182
if (noOfRedirections > 1) {
31693183
String msg = SQLServerException.getErrString("R_multipleRedirections");
31703184
terminate(SQLServerException.DRIVER_ERROR_UNSUPPORTED_CONFIG, msg);
@@ -3209,9 +3223,23 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu
32093223

32103224
continue;
32113225
}
3212-
} else
3226+
} else {
3227+
if (loggerResiliency.isLoggable(Level.FINE) && retryAttempt > 0) {
3228+
loggerResiliency.fine(toString() + " Connection open - connection retry succeeded on attempt number: " + retryAttempt);
3229+
}
3230+
32133231
break; // leave the while loop -- we've successfully connected
3232+
}
32143233
} catch (SQLServerException e) {
3234+
3235+
if (loggerResiliency.isLoggable(Level.FINE) && retryAttempt > 0) {
3236+
loggerResiliency.fine(toString() + " Connection open - connection retry failed on attempt number: " + retryAttempt);
3237+
}
3238+
3239+
if (loggerResiliency.isLoggable(Level.FINER) && (retryAttempt >= connectRetryCount)) {
3240+
loggerResiliency.finer(toString() + " Connection open - connection failed. Maximum connection retry count " + connectRetryCount + " reached.");
3241+
}
3242+
32153243
int errorCode = e.getErrorCode();
32163244
driverErrorCode = e.getDriverErrorCode();
32173245
sqlServerError = e.getSQLServerError();
@@ -3229,15 +3257,26 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu
32293257
|| timerHasExpired(timerExpire)
32303258
// for non-dbmirroring cases, do not retry after tcp socket connection succeeds
32313259
) {
3232-
if (connectionlogger.isLoggable(Level.FINE) && (retryAttempt >= connectRetryCount)) {
3233-
connectionlogger.fine(
3234-
"Connection failed. Maximum connection retry count " + connectRetryCount + " reached.");
3260+
if (loggerResiliency.isLoggable(Level.FINER)) {
3261+
loggerResiliency.finer(toString() + " Connection open - connection failed on attempt: " + retryAttempt + ".");
3262+
loggerResiliency.finer(toString() + " Connection open - connection failure. Driver error code: " + driverErrorCode);
3263+
if (null != sqlServerError && !sqlServerError.getErrorMessage().isEmpty()) {
3264+
loggerResiliency.finer(toString() + " Connection open - connection failure. SQL Server error : " + sqlServerError.getErrorMessage());
3265+
}
32353266
}
32363267

32373268
// close the connection and throw the error back
32383269
close();
32393270
throw e;
32403271
} else {
3272+
if (loggerResiliency.isLoggable(Level.FINER)) {
3273+
loggerResiliency.finer(toString() + " Connection open - connection failed on attempt: " + retryAttempt + ".");
3274+
loggerResiliency.finer(toString() + " Connection open - connection failure. Driver error code: " + driverErrorCode);
3275+
if (null != sqlServerError && !sqlServerError.getErrorMessage().isEmpty()) {
3276+
loggerResiliency.finer(toString() + " Connection open - connection failure. SQL Server error : " + sqlServerError.getErrorMessage());
3277+
}
3278+
}
3279+
32413280
// Close the TDS channel from the failed connection attempt so that we don't
32423281
// hold onto network resources any longer than necessary.
32433282
if (null != tdsChannel)
@@ -3252,6 +3291,14 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu
32523291
if ((!isDBMirroring || 1 == retryAttempt % 2
32533292
|| TimeUnit.SECONDS.toMillis(connectRetryInterval) >= remainingTime)
32543293
&& (remainingTime <= TimeUnit.SECONDS.toMillis(connectRetryInterval))) {
3294+
if (loggerResiliency.isLoggable(Level.FINER)) {
3295+
loggerResiliency.finer(toString() + " Connection open - connection failed on attempt: " + retryAttempt + ".");
3296+
loggerResiliency.finer(toString() + " Connection open - connection failure. Driver error code: " + driverErrorCode);
3297+
if (null != sqlServerError && !sqlServerError.getErrorMessage().isEmpty()) {
3298+
loggerResiliency.finer(toString() + " Connection open - connection failure. SQL Server error : " + sqlServerError.getErrorMessage());
3299+
}
3300+
}
3301+
32553302
throw e;
32563303
}
32573304
}
@@ -3265,19 +3312,19 @@ private void login(String primary, String primaryInstanceName, int primaryPortNu
32653312
&& tlsRetryAttempt < INTERMITTENT_TLS_MAX_RETRY && !timerHasExpired(timerExpire)) {
32663313
// special case for TLS intermittent failures: no wait retries
32673314
tlsRetryAttempt++;
3268-
if (connectionlogger.isLoggable(Level.FINE)) {
3269-
connectionlogger.fine(
3270-
"Connection failed during SSL handshake. Retry due to an intermittent TLS 1.2 failure issue. Retry attempt = "
3315+
if (loggerResiliency.isLoggable(Level.FINER)) {
3316+
loggerResiliency.finer(toString() +
3317+
" Connection open - connection failed during SSL handshake. Retry due to an intermittent TLS 1.2 failure issue. Retry attempt = "
32713318
+ tlsRetryAttempt + " of " + INTERMITTENT_TLS_MAX_RETRY);
32723319
}
32733320
} else {
32743321
if (retryAttempt++ >= connectRetryCount && TransientError.isTransientError(sqlServerError)
32753322
&& !timerHasExpired(timerExpire) && (!isDBMirroring || (1 == retryAttempt % 2))) {
3276-
if (connectionlogger.isLoggable(Level.FINE)) {
3277-
connectionlogger.fine(toString() + " sleeping milisec: " + connectRetryInterval);
3323+
if (loggerResiliency.isLoggable(Level.FINER)) {
3324+
loggerResiliency.finer(toString() + " Connection open - sleeping milisec: " + connectRetryInterval);
32783325
}
3279-
if (connectionlogger.isLoggable(Level.FINEST)) {
3280-
connectionlogger.finest(toString() + "Connection failed on transient error "
3326+
if (loggerResiliency.isLoggable(Level.FINER)) {
3327+
loggerResiliency.finer(toString() + " Connection open - connection failed on transient error "
32813328
+ (sqlServerError != null ? sqlServerError.getErrorNumber() : "")
32823329
+ ". Wait for connectRetryInterval(" + connectRetryInterval + ")s before retry #"
32833330
+ retryAttempt);
@@ -4102,7 +4149,12 @@ boolean executeCommand(TDSCommand newCommand) throws SQLServerException {
41024149
preparedStatementHandleCache.clear();
41034150
}
41044151

4152+
if (loggerResiliency.isLoggable(Level.FINE)) {
4153+
loggerResiliency.fine(toString() + " Idle connection resiliency - starting idle connection resiliency reconnect.");
4154+
}
4155+
41054156
sessionRecovery.reconnect(newCommand);
4157+
41064158
} catch (InterruptedException e) {
41074159
// re-interrupt thread
41084160
Thread.currentThread().interrupt();
@@ -4111,10 +4163,11 @@ boolean executeCommand(TDSCommand newCommand) throws SQLServerException {
41114163
SQLServerException.makeFromDriverError(this, sessionRecovery, e.getMessage(), null,
41124164
false);
41134165
}
4166+
41144167
if (sessionRecovery.getReconnectException() != null) {
4115-
if (connectionlogger.isLoggable(Level.FINER)) {
4116-
connectionlogger.finer(
4117-
this.toString() + "Connection is broken and recovery is not possible.");
4168+
if (loggerResiliency.isLoggable(Level.FINER)) {
4169+
loggerResiliency.finer(
4170+
this.toString() + " Idle connection resiliency - connection is broken and recovery is not possible.");
41184171
}
41194172
throw sessionRecovery.getReconnectException();
41204173
}

0 commit comments

Comments
 (0)