Skip to content

Commit e361d1e

Browse files
ibauersachsibauersachs
committed
Extend logging in NIO clients to trace bugs
Related to #194, #260 and #267
1 parent b9662ab commit e361d1e

5 files changed

Lines changed: 61 additions & 22 deletions

File tree

‎src/main/java/org/xbill/DNS/NioTcpClient.java‎

Lines changed: 39 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -83,7 +83,7 @@ void send() throws IOException {
8383
}
8484

8585
verboseLog(
86-
"TCP write",
86+
"TCP write: transaction id=" + query.getHeader().getID(),
8787
channel.socket().getLocalSocketAddress(),
8888
channel.socket().getRemoteSocketAddress(),
8989
queryData);
@@ -97,8 +97,13 @@ void send() throws IOException {
9797
buffer.flip();
9898
while (buffer.hasRemaining()) {
9999
long n = channel.write(buffer);
100-
if (n < 0) {
101-
throw new EOFException();
100+
if (n == 0) {
101+
throw new EOFException(
102+
"Insufficient room for the data in the underlying output buffer for transaction "
103+
+ query.getHeader().getID());
104+
} else if (n < queryData.length) {
105+
throw new EOFException(
106+
"Could not write all data for transaction " + query.getHeader().getID());
102107
}
103108
}
104109

@@ -146,7 +151,11 @@ private void handleChannelException(IOException e) {
146151
try {
147152
channel.close();
148153
} catch (IOException ex) {
149-
log.error("failed to close channel", ex);
154+
log.warn(
155+
"Failed to close channel l={}/r={}",
156+
entry.getKey().local,
157+
entry.getKey().remote,
158+
ex);
150159
}
151160
return;
152161
}
@@ -197,27 +206,35 @@ private void processRead() {
197206
byte[] data = new byte[responseData.limit()];
198207
System.arraycopy(
199208
responseData.array(), responseData.arrayOffset(), data, 0, responseData.limit());
200-
verboseLog(
201-
"TCP read",
202-
channel.socket().getLocalSocketAddress(),
203-
channel.socket().getRemoteSocketAddress(),
204-
data);
205209

206210
// The message was shorter than the minimum length to find the transaction, abort
207211
if (data.length < 2) {
212+
verboseLog(
213+
"TCP read: response too short for a valid reply, discarding",
214+
channel.socket().getLocalSocketAddress(),
215+
channel.socket().getRemoteSocketAddress(),
216+
data);
208217
return;
209218
}
210219

220+
int id = ((data[0] & 0xFF) << 8) + (data[1] & 0xFF);
221+
verboseLog(
222+
"TCP read: transaction id=" + id,
223+
channel.socket().getLocalSocketAddress(),
224+
channel.socket().getRemoteSocketAddress(),
225+
data);
226+
211227
for (Iterator<Transaction> it = pendingTransactions.iterator(); it.hasNext(); ) {
212228
Transaction t = it.next();
213-
int id = ((data[0] & 0xFF) << 8) + (data[1] & 0xFF);
214229
int qid = t.query.getHeader().getID();
215230
if (id == qid) {
216231
t.f.complete(data);
217232
it.remove();
218233
return;
219234
}
220235
}
236+
237+
log.warn("Transaction for answer to id {} not found", id);
221238
}
222239

223240
private void processWrite(SelectionKey key) {
@@ -256,9 +273,10 @@ static CompletableFuture<byte[]> sendrecv(
256273
channelMap.computeIfAbsent(
257274
new ChannelKey(local, remote),
258275
key -> {
276+
log.debug("Opening async channel for l={}/r={}", local, remote);
277+
SocketChannel c = null;
259278
try {
260-
log.trace("Opening async channel for l={}/r={}", local, remote);
261-
SocketChannel c = SocketChannel.open();
279+
c = SocketChannel.open();
262280
c.configureBlocking(false);
263281
if (local != null) {
264282
c.bind(local);
@@ -267,13 +285,21 @@ static CompletableFuture<byte[]> sendrecv(
267285
c.connect(remote);
268286
return new ChannelState(c);
269287
} catch (IOException e) {
288+
if (c != null) {
289+
try {
290+
c.close();
291+
} catch (IOException ee) {
292+
// ignore
293+
}
294+
}
270295
f.completeExceptionally(e);
271296
return null;
272297
}
273298
});
274299
if (channel != null) {
275300
log.trace(
276-
"Creating transaction for {}/{}",
301+
"Creating transaction for id {} ({}/{})",
302+
query.getHeader().getID(),
277303
query.getQuestion().getName(),
278304
Type.string(query.getQuestion().getType()));
279305
Transaction t = new Transaction(query, data, endTime, channel.channel, f);

‎src/main/java/org/xbill/DNS/NioUdpClient.java‎

Lines changed: 17 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -59,6 +59,7 @@ private static void processPendingRegistrations() {
5959
while (!registrationQueue.isEmpty()) {
6060
Transaction t = registrationQueue.remove();
6161
try {
62+
log.trace("Registering OP_READ for transaction with id {}", t.id);
6263
t.channel.register(selector(), SelectionKey.OP_READ, t);
6364
t.send();
6465
} catch (IOException e) {
@@ -79,6 +80,7 @@ private static void checkTransactionTimeouts() {
7980

8081
@RequiredArgsConstructor
8182
private static class Transaction implements KeyProcessor {
83+
private final int id;
8284
private final byte[] data;
8385
private final int max;
8486
private final long endTime;
@@ -88,13 +90,17 @@ private static class Transaction implements KeyProcessor {
8890
void send() throws IOException {
8991
ByteBuffer buffer = ByteBuffer.wrap(data);
9092
verboseLog(
91-
"UDP write",
93+
"UDP write: transaction id=" + id,
9294
channel.socket().getLocalSocketAddress(),
9395
channel.socket().getRemoteSocketAddress(),
9496
data);
9597
int n = channel.send(buffer, channel.socket().getRemoteSocketAddress());
96-
if (n <= 0) {
97-
throw new EOFException();
98+
if (n == 0) {
99+
throw new EOFException(
100+
"Insufficient room for the datagram in the underlying output buffer for transaction "
101+
+ id);
102+
} else if (n < data.length) {
103+
throw new EOFException("Could not send all data for transaction " + id);
98104
}
99105
}
100106

@@ -124,7 +130,7 @@ public void processReadyKey(SelectionKey key) {
124130
byte[] data = new byte[read];
125131
System.arraycopy(buffer.array(), 0, data, 0, read);
126132
verboseLog(
127-
"UDP read",
133+
"UDP read: transaction id=" + id,
128134
channel.socket().getLocalSocketAddress(),
129135
channel.socket().getRemoteSocketAddress(),
130136
data);
@@ -154,7 +160,12 @@ private void silentCloseChannel() {
154160
}
155161

156162
static CompletableFuture<byte[]> sendrecv(
157-
InetSocketAddress local, InetSocketAddress remote, byte[] data, int max, Duration timeout) {
163+
InetSocketAddress local,
164+
InetSocketAddress remote,
165+
Message query,
166+
byte[] data,
167+
int max,
168+
Duration timeout) {
158169
long endTime = System.nanoTime() + timeout.toNanos();
159170
CompletableFuture<byte[]> f = new CompletableFuture<>();
160171
DatagramChannel channel = null;
@@ -163,7 +174,7 @@ static CompletableFuture<byte[]> sendrecv(
163174
channel = DatagramChannel.open();
164175
channel.configureBlocking(false);
165176

166-
Transaction t = new Transaction(data, max, endTime, channel, f);
177+
Transaction t = new Transaction(query.getHeader().getID(), data, max, endTime, channel, f);
167178
if (local == null || local.getPort() == 0) {
168179
boolean bound = false;
169180
for (int i = 0; i < 1024; i++) {

‎src/main/java/org/xbill/DNS/Resolver.java‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -167,7 +167,8 @@ default Message send(Message query) throws IOException {
167167
+ "/"
168168
+ Type.string(query.getQuestion().type)
169169
+ ", id="
170-
+ query.getHeader().getID());
170+
+ query.getHeader().getID(),
171+
e);
171172
}
172173
}
173174

‎src/main/java/org/xbill/DNS/SimpleResolver.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -370,7 +370,7 @@ CompletableFuture<Message> sendAsync(Message query, boolean forceTcp, Executor e
370370
if (tcp) {
371371
result = NioTcpClient.sendrecv(localAddress, address, query, out, timeoutValue);
372372
} else {
373-
result = NioUdpClient.sendrecv(localAddress, address, out, udpSize, timeoutValue);
373+
result = NioUdpClient.sendrecv(localAddress, address, query, out, udpSize, timeoutValue);
374374
}
375375

376376
return result.thenComposeAsync(

‎src/test/java/org/xbill/DNS/TSIGTest.java‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -222,12 +222,13 @@ void signedQuerySignedResponseViaResolver() throws IOException {
222222
NioUdpClient.sendrecv(
223223
any(),
224224
any(InetSocketAddress.class),
225+
any(),
225226
any(byte[].class),
226227
anyInt(),
227228
any(Duration.class)))
228229
.thenAnswer(
229230
a -> {
230-
Message qparsed = new Message(a.getArgument(2, byte[].class));
231+
Message qparsed = new Message(a.getArgument(3, byte[].class));
231232

232233
Message response = new Message(qparsed.getHeader().getID());
233234
response.setTSIG(key, Rcode.NOERROR, qparsed.getTSIG());

0 commit comments

Comments
 (0)