Skip to content

Commit 4be4367

Browse files
rozzarozza
authored
Fixed Logging in vendored tlschannel (#735)
JAVA-4201
1 parent 52c94d9 commit 4be4367

File tree

6 files changed

+83
-68
lines changed

6 files changed

+83
-68
lines changed

‎driver-core/src/main/com/mongodb/internal/connection/tlschannel/ServerTlsChannel.java‎

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -19,13 +19,13 @@
1919

2020
package com.mongodb.internal.connection.tlschannel;
2121

22+
import com.mongodb.diagnostics.logging.Logger;
23+
import com.mongodb.diagnostics.logging.Loggers;
2224
import com.mongodb.internal.connection.tlschannel.impl.BufferHolder;
2325
import com.mongodb.internal.connection.tlschannel.impl.ByteBufferSet;
2426
import com.mongodb.internal.connection.tlschannel.impl.TlsChannelImpl;
2527
import com.mongodb.internal.connection.tlschannel.impl.TlsChannelImpl.EofException;
2628
import com.mongodb.internal.connection.tlschannel.impl.TlsExplorer;
27-
import org.slf4j.Logger;
28-
import org.slf4j.LoggerFactory;
2929

3030
import javax.net.ssl.SNIHostName;
3131
import javax.net.ssl.SNIServerName;
@@ -50,7 +50,7 @@
5050
/** A server-side {@link TlsChannel}. */
5151
public class ServerTlsChannel implements TlsChannel {
5252

53-
private static final Logger logger = LoggerFactory.getLogger(ServerTlsChannel.class);
53+
private static final Logger LOGGER = Loggers.getLogger("connection.tls");
5454

5555
private interface SslContextStrategy {
5656

@@ -79,7 +79,7 @@ public SSLContext getSslContext(SniReader sniReader) throws IOException, EofExce
7979
try {
8080
chosenContext = sniSslContextFactory.getSslContext(nameOpt);
8181
} catch (Exception e) {
82-
logger.trace("client code threw exception during evaluation of server name indication", e);
82+
LOGGER.trace("client code threw exception during evaluation of server name indication", e);
8383
throw new TlsChannelCallbackException("SNI callback failed", e);
8484
}
8585
return chosenContext.orElseThrow(
@@ -367,7 +367,7 @@ private void initEngine() throws IOException, EofException {
367367
try {
368368
engine = engineFactory.apply(sslContext);
369369
} catch (Exception e) {
370-
logger.trace("client threw exception in SSLEngine factory", e);
370+
LOGGER.trace("client threw exception in SSLEngine factory", e);
371371
throw new TlsChannelCallbackException("SSLEngine creation callback failed", e);
372372
}
373373
impl =

‎driver-core/src/main/com/mongodb/internal/connection/tlschannel/async/AsynchronousTlsChannelGroup.java‎

Lines changed: 25 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,15 @@
1919

2020
package com.mongodb.internal.connection.tlschannel.async;
2121

22+
import com.mongodb.diagnostics.logging.Logger;
23+
import com.mongodb.diagnostics.logging.Loggers;
24+
import com.mongodb.internal.connection.tlschannel.NeedsReadException;
25+
import com.mongodb.internal.connection.tlschannel.NeedsTaskException;
26+
import com.mongodb.internal.connection.tlschannel.NeedsWriteException;
27+
import com.mongodb.internal.connection.tlschannel.TlsChannel;
28+
import com.mongodb.internal.connection.tlschannel.impl.ByteBufferSet;
29+
import com.mongodb.internal.connection.tlschannel.util.Util;
30+
2231
import java.io.IOException;
2332
import java.nio.channels.CancelledKeyException;
2433
import java.nio.channels.ClosedChannelException;
@@ -46,14 +55,8 @@
4655
import java.util.concurrent.locks.ReentrantLock;
4756
import java.util.function.Consumer;
4857
import java.util.function.LongConsumer;
49-
import org.slf4j.Logger;
50-
import org.slf4j.LoggerFactory;
51-
import com.mongodb.internal.connection.tlschannel.NeedsReadException;
52-
import com.mongodb.internal.connection.tlschannel.NeedsTaskException;
53-
import com.mongodb.internal.connection.tlschannel.NeedsWriteException;
54-
import com.mongodb.internal.connection.tlschannel.TlsChannel;
55-
import com.mongodb.internal.connection.tlschannel.impl.ByteBufferSet;
56-
import com.mongodb.internal.connection.tlschannel.util.Util;
58+
59+
import static java.lang.String.format;
5760

5861
/**
5962
* This class encapsulates the infrastructure for running {@link AsynchronousTlsChannel}s. Each
@@ -62,7 +65,7 @@
6265
*/
6366
public class AsynchronousTlsChannelGroup {
6467

65-
private static final Logger logger = LoggerFactory.getLogger(AsynchronousTlsChannelGroup.class);
68+
private static final Logger LOGGER = Loggers.getLogger("connection.tls");
6669

6770
/** The main executor of the group has a queue, whose size is a multiple of the number of CPUs. */
6871
private static final int queueLengthMultiplier = 32;
@@ -165,10 +168,10 @@ static final class WriteOperation extends Operation {
165168
new ScheduledThreadPoolExecutor(
166169
1,
167170
runnable ->
168-
new Thread(runnable, String.format("async-channel-group-%d-timeout-thread", id)));
171+
new Thread(runnable, format("async-channel-group-%d-timeout-thread", id)));
169172

170173
private final Thread selectorThread =
171-
new Thread(this::loop, String.format("async-channel-group-%d-selector", id));
174+
new Thread(this::loop, format("async-channel-group-%d-selector", id));
172175

173176
private final ConcurrentLinkedQueue<RegisteredSocket> pendingRegistrations =
174177
new ConcurrentLinkedQueue<>();
@@ -219,7 +222,7 @@ public AsynchronousTlsChannelGroup(int nThreads) {
219222
TimeUnit.MILLISECONDS,
220223
new LinkedBlockingQueue<>(nThreads * queueLengthMultiplier),
221224
runnable ->
222-
new Thread(runnable, String.format("async-channel-group-%d-handler-executor", id)),
225+
new Thread(runnable, format("async-channel-group-%d-handler-executor", id)),
223226
new ThreadPoolExecutor.CallerRunsPolicy());
224227
selectorThread.start();
225228
}
@@ -412,7 +415,7 @@ private void loop() {
412415
processPendingInterests();
413416
}
414417
} catch (Throwable e) {
415-
logger.error("error in selector loop", e);
418+
LOGGER.error("error in selector loop", e);
416419
} finally {
417420
executor.shutdown();
418421
// use shutdownNow to stop delayed tasks
@@ -426,7 +429,7 @@ private void loop() {
426429
try {
427430
selector.close();
428431
} catch (IOException e) {
429-
logger.warn("error closing selector: {}", e.getMessage());
432+
LOGGER.warn("error closing selector: " + e.getMessage());
430433
}
431434
}
432435
}
@@ -455,7 +458,7 @@ private void processWrite(RegisteredSocket socket) {
455458
try {
456459
doWrite(socket, op);
457460
} catch (Throwable e) {
458-
logger.error("error in operation", e);
461+
LOGGER.error("error in operation", e);
459462
}
460463
});
461464
}
@@ -474,7 +477,7 @@ private void processRead(RegisteredSocket socket) {
474477
try {
475478
doRead(socket, op);
476479
} catch (Throwable e) {
477-
logger.error("error in operation", e);
480+
LOGGER.error("error in operation", e);
478481
}
479482
});
480483
}
@@ -545,10 +548,10 @@ private void writeHandlingTasks(RegisteredSocket socket, WriteOperation op) thro
545548

546549
private void warnAboutNeedTask() {
547550
if (!loggedTaskWarning.getAndSet(true)) {
548-
logger.warn(
549-
"caught {}; channels used in asynchronous groups should run tasks themselves; "
551+
LOGGER.warn(format(
552+
"caught %s; channels used in asynchronous groups should run tasks themselves; "
550553
+ "although task is being dealt with anyway, consider configuring channels properly",
551-
NeedsTaskException.class.getName());
554+
NeedsTaskException.class.getName()));
552555
}
553556
}
554557

@@ -607,7 +610,9 @@ private void registerPendingSockets() throws ClosedChannelException {
607610
RegisteredSocket socket;
608611
while ((socket = pendingRegistrations.poll()) != null) {
609612
socket.key = socket.socketChannel.register(selector, 0, socket);
610-
logger.trace("registered key: {}", socket.key);
613+
if (LOGGER.isTraceEnabled()) {
614+
LOGGER.trace("registered key: " + socket.key);
615+
}
611616
socket.registered.countDown();
612617
}
613618
}

‎driver-core/src/main/com/mongodb/internal/connection/tlschannel/impl/BufferHolder.java‎

Lines changed: 19 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -19,17 +19,19 @@
1919

2020
package com.mongodb.internal.connection.tlschannel.impl;
2121

22+
import com.mongodb.diagnostics.logging.Logger;
23+
import com.mongodb.diagnostics.logging.Loggers;
2224
import com.mongodb.internal.connection.tlschannel.BufferAllocator;
23-
import org.slf4j.Logger;
24-
import org.slf4j.LoggerFactory;
2525

2626
import java.nio.Buffer;
2727
import java.nio.ByteBuffer;
2828
import java.util.Optional;
2929

30+
import static java.lang.String.format;
31+
3032
public class BufferHolder {
3133

32-
private static final Logger logger = LoggerFactory.getLogger(BufferHolder.class);
34+
private static final Logger LOGGER = Loggers.getLogger("connection.tls");
3335
private static final byte[] zeros = new byte[TlsChannelImpl.maxTlsPacketSize];
3436

3537
public final String name;
@@ -85,28 +87,32 @@ public boolean dispose() {
8587
public void resize(int newCapacity) {
8688
if (newCapacity > maxSize)
8789
throw new IllegalArgumentException(
88-
String.format(
90+
format(
8991
"new capacity (%s) bigger than absolute max size (%s)", newCapacity, maxSize));
90-
logger.trace(
91-
"resizing buffer {}, increasing from {} to {} (manual sizing)",
92-
name,
93-
buffer.capacity(),
94-
newCapacity);
92+
if (LOGGER.isTraceEnabled()) {
93+
LOGGER.trace(format(
94+
"resizing buffer %s, increasing from %s to %s (manual sizing)",
95+
name,
96+
buffer.capacity(),
97+
newCapacity));
98+
}
9599
resizeImpl(newCapacity);
96100
}
97101

98102
public void enlarge() {
99103
if (buffer.capacity() >= maxSize) {
100104
throw new IllegalStateException(
101-
String.format(
105+
format(
102106
"%s buffer insufficient despite having capacity of %d", name, buffer.capacity()));
103107
}
104108
int newCapacity = Math.min(buffer.capacity() * 2, maxSize);
105-
logger.trace(
106-
"enlarging buffer {}, increasing from {} to {} (automatic enlarge)",
109+
if (LOGGER.isTraceEnabled()) {
110+
LOGGER.trace(format(
111+
"enlarging buffer %s, increasing from %s to %s (automatic enlarge)",
107112
name,
108113
buffer.capacity(),
109-
newCapacity);
114+
newCapacity));
115+
}
110116
resizeImpl(newCapacity);
111117
}
112118

‎driver-core/src/main/com/mongodb/internal/connection/tlschannel/impl/TlsChannelImpl.java‎

Lines changed: 29 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -19,15 +19,15 @@
1919

2020
package com.mongodb.internal.connection.tlschannel.impl;
2121

22+
import com.mongodb.diagnostics.logging.Logger;
23+
import com.mongodb.diagnostics.logging.Loggers;
2224
import com.mongodb.internal.connection.tlschannel.NeedsReadException;
2325
import com.mongodb.internal.connection.tlschannel.NeedsTaskException;
2426
import com.mongodb.internal.connection.tlschannel.NeedsWriteException;
2527
import com.mongodb.internal.connection.tlschannel.TlsChannelCallbackException;
2628
import com.mongodb.internal.connection.tlschannel.TrackingAllocator;
2729
import com.mongodb.internal.connection.tlschannel.WouldBlockException;
2830
import com.mongodb.internal.connection.tlschannel.util.Util;
29-
import org.slf4j.Logger;
30-
import org.slf4j.LoggerFactory;
3131

3232
import javax.net.ssl.SSLEngine;
3333
import javax.net.ssl.SSLEngineResult;
@@ -47,11 +47,12 @@
4747
import java.util.concurrent.locks.ReentrantLock;
4848
import java.util.function.Consumer;
4949

50+
import static java.lang.String.format;
5051
import static javax.net.ssl.SSLEngineResult.HandshakeStatus.NOT_HANDSHAKING;
5152

5253
public class TlsChannelImpl implements ByteChannel {
5354

54-
private static final Logger logger = LoggerFactory.getLogger(TlsChannelImpl.class);
55+
private static final Logger LOGGER = Loggers.getLogger("connection.tls");
5556

5657
public static final int buffersInitialSize = 4096;
5758

@@ -319,13 +320,13 @@ private SSLEngineResult callEngineUnwrap(ByteBufferSet dest) throws SSLException
319320
try {
320321
SSLEngineResult result =
321322
engine.unwrap(inEncrypted.buffer, dest.array, dest.offset, dest.length);
322-
if (logger.isTraceEnabled()) {
323-
logger.trace(
324-
"engine.unwrap() result [{}]. Engine status: {}; inEncrypted {}; inPlain: {}",
323+
if (LOGGER.isTraceEnabled()) {
324+
LOGGER.trace(format(
325+
"engine.unwrap() result [%s]. Engine status: %s; inEncrypted %s; inPlain: %s",
325326
Util.resultToString(result),
326327
result.getHandshakeStatus(),
327328
inEncrypted,
328-
dest);
329+
dest));
329330
}
330331
return result;
331332
} catch (SSLException e) {
@@ -352,9 +353,11 @@ private int readFromChannel() throws IOException, EofException {
352353
public static int readFromChannel(ReadableByteChannel readChannel, ByteBuffer buffer)
353354
throws IOException, EofException {
354355
Util.assertTrue(buffer.hasRemaining());
355-
logger.trace("Reading from channel");
356+
LOGGER.trace("Reading from channel");
356357
int c = readChannel.read(buffer); // IO block
357-
logger.trace("Read from channel; response: {}, buffer: {}", c, buffer);
358+
if (LOGGER.isTraceEnabled()) {
359+
LOGGER.trace(format("Read from channel; response: %s, buffer: %s", c, buffer));
360+
}
358361
if (c == -1) {
359362
throw new EofException();
360363
}
@@ -421,13 +424,13 @@ private SSLEngineResult callEngineWrap(ByteBufferSet source) throws SSLException
421424
try {
422425
SSLEngineResult result =
423426
engine.wrap(source.array, source.offset, source.length, outEncrypted.buffer);
424-
if (logger.isTraceEnabled()) {
425-
logger.trace(
426-
"engine.wrap() result: [{}]; engine status: {}; srcBuffer: {}, outEncrypted: {}",
427+
if (LOGGER.isTraceEnabled()) {
428+
LOGGER.trace(format(
429+
"engine.wrap() result: [%s]; engine status: %s; srcBuffer: %s, outEncrypted: %s",
427430
Util.resultToString(result),
428431
result.getHandshakeStatus(),
429432
source,
430-
outEncrypted);
433+
outEncrypted));
431434
}
432435
return result;
433436
} catch (SSLException e) {
@@ -438,10 +441,12 @@ private SSLEngineResult callEngineWrap(ByteBufferSet source) throws SSLException
438441

439442
private void ensureInPlainCapacity(int newCapacity) {
440443
if (inPlain.buffer.capacity() < newCapacity) {
441-
logger.trace(
442-
"inPlain buffer too small, increasing from {} to {}",
444+
if (LOGGER.isTraceEnabled()) {
445+
LOGGER.trace(format(
446+
"inPlain buffer too small, increasing from %s to %s",
443447
inPlain.buffer.capacity(),
444-
newCapacity);
448+
newCapacity));
449+
}
445450
inPlain.resize(newCapacity);
446451
}
447452
}
@@ -468,7 +473,9 @@ private void writeToChannel() throws IOException {
468473
private static void writeToChannel(WritableByteChannel channel, ByteBuffer src)
469474
throws IOException {
470475
while (src.hasRemaining()) {
471-
logger.trace("Writing to channel: {}", src);
476+
if (LOGGER.isTraceEnabled()) {
477+
LOGGER.trace("Writing to channel: " + src);
478+
}
472479
int c = channel.write(src);
473480
if (c == 0) {
474481
/*
@@ -525,13 +532,13 @@ private void doHandshake(boolean force) throws IOException, EofException {
525532
if (invalid || shutdownSent) throw new ClosedChannelException();
526533
if (force || !negotiated) {
527534
engine.beginHandshake();
528-
logger.trace("Called engine.beginHandshake()");
535+
LOGGER.trace("Called engine.beginHandshake()");
529536
handshake(Optional.empty(), Optional.empty());
530537
// call client code
531538
try {
532539
initSessionCallback.accept(engine.getSession());
533540
} catch (Exception e) {
534-
logger.trace("client code threw exception in session initialization callback", e);
541+
LOGGER.trace("client code threw exception in session initialization callback", e);
535542
throw new TlsChannelCallbackException("session initialization callback failed", e);
536543
}
537544
negotiated = true;
@@ -658,7 +665,9 @@ private void tryShutdown() {
658665
shutdown();
659666
}
660667
} catch (Throwable e) {
661-
logger.debug("error doing TLS shutdown on close(), continuing: {}", e.getMessage());
668+
if (LOGGER.isDebugEnabled()) {
669+
LOGGER.debug("error doing TLS shutdown on close(), continuing: " + e.getMessage());
670+
}
662671
}
663672
}
664673
} finally {

0 commit comments

Comments
 (0)