From 7b7cc745d5f23c5acba7f6de34af45e6e60c0076 Mon Sep 17 00:00:00 2001 From: Elvis Souza Date: Fri, 24 Feb 2023 19:15:29 -0300 Subject: [PATCH] Better error treating and log formatting (#311) * Defines a log format for files * Adjusting log * some trace logs * fixing log format * adjusting logs * better id * bump * Adjusting logs * release notes * fixing tests * fixing test intermitence * Ensure will read the header before go to next step * release notes --- RELEASE-NOTES.md | 4 ++ gradle.properties | 2 +- .../server/dns/DnsQueryTCPHandler.java | 37 +++++++++++++------ .../server/dns/SocketClient.java | 12 +++++- .../dnsproxyserver/server/dns/TCPServer.java | 30 +++++++++------ .../dnsproxyserver/server/dns/UDPServer.java | 11 ++++-- src/main/resources/application.properties | 1 + .../server/dns/DnsQueryTCPHandlerTest.java | 3 +- .../templates/SocketClientTemplates.java | 6 ++- 9 files changed, 74 insertions(+), 32 deletions(-) diff --git a/RELEASE-NOTES.md b/RELEASE-NOTES.md index 5ff8be40d..33b70693e 100644 --- a/RELEASE-NOTES.md +++ b/RELEASE-NOTES.md @@ -1,3 +1,7 @@ +### 3.2.0-beta +* Better error treating and log formatting +* TCP Server: Ensure will read the header before go to next step + ### 3.1.7-beta * TCP Server Partially message read fix, fixing `status=headerMsgSizeDifferentFromReadBytes!` message diff --git a/gradle.properties b/gradle.properties index 7f6661112..f8d58098a 100644 --- a/gradle.properties +++ b/gradle.properties @@ -1,4 +1,4 @@ -version=3.1.7-beta +version=3.2.0-beta quarkusPluginId=io.quarkus quarkusPluginVersion=2.16.0.Final quarkusPlatformGroupId=io.quarkus.platform diff --git a/src/main/java/com/mageddo/dnsproxyserver/server/dns/DnsQueryTCPHandler.java b/src/main/java/com/mageddo/dnsproxyserver/server/dns/DnsQueryTCPHandler.java index 6f984f36f..ebaf7902b 100644 --- a/src/main/java/com/mageddo/dnsproxyserver/server/dns/DnsQueryTCPHandler.java +++ b/src/main/java/com/mageddo/dnsproxyserver/server/dns/DnsQueryTCPHandler.java @@ -2,7 +2,9 @@ import com.mageddo.utils.Shorts; import lombok.extern.slf4j.Slf4j; +import org.apache.commons.lang3.ClassUtils; import org.apache.commons.lang3.Validate; +import org.slf4j.MDC; import org.xbill.DNS.Message; import java.io.IOException; @@ -26,6 +28,7 @@ class DnsQueryTCPHandler implements SocketClientMessageHandler { @Override public void handle(SocketClient client) { try { + MDC.put("clientId", client.getId()); while (client.isOpen()) { final var in = client.getIn(); @@ -34,15 +37,23 @@ public void handle(SocketClient client) { return; } final var buff = readBodyAndValidate(in, msgSize); - final var query = new Message(buff); final var res = this.handler.handle(query, "tcp") .toWire(); - final var out = client.getOut(); - out.write(Shorts.toBytes((short) res.length)); - out.write(res); - out.flush(); + try { + final var out = client.getOut(); + out.write(Shorts.toBytes((short) res.length)); + out.flush(); + out.write(res); + out.flush(); + } catch (IOException e) { + log.info( + "status=outIsClosed, query={}, msg={}, class={}", + Messages.simplePrint(query), e.getMessage(), ClassUtils.getSimpleName(e) + ); + break; + } log.debug( "status=success, queryMsgSize={}, resMsgSize={}, req={}", @@ -52,6 +63,8 @@ public void handle(SocketClient client) { } } catch (Exception e) { log.warn("status=request-failed, msg={}", e.getMessage(), e); + } finally { + MDC.clear(); } } @@ -73,14 +86,14 @@ static byte[] readBodyAndValidate(InputStream in, short msgSize) { static short readHeaderAndValidate(InputStream in) { try { final var msgSizeBuf = ByteBuffer.allocate(2); - final int read = in.read(msgSizeBuf.array(), 0, msgSizeBuf.limit()); - if (read == -1) { - return -1; + for (int i = 0; i < msgSizeBuf.limit(); i++) { + final byte read = (byte) in.read(); + if (read == -1) { + log.info("status=incompleteHeader, bytes={}", i + 1); + return -1; + } + msgSizeBuf.put(i, read); } - Validate.isTrue( - read == msgSizeBuf.limit(), - "Must read the exactly header size, read=%d, expected=%d", read, msgSizeBuf.limit() - ); return msgSizeBuf.getShort(); } catch (IOException e) { throw new RuntimeException(e); diff --git a/src/main/java/com/mageddo/dnsproxyserver/server/dns/SocketClient.java b/src/main/java/com/mageddo/dnsproxyserver/server/dns/SocketClient.java index 66fc2e7b2..f7fe70ae1 100644 --- a/src/main/java/com/mageddo/dnsproxyserver/server/dns/SocketClient.java +++ b/src/main/java/com/mageddo/dnsproxyserver/server/dns/SocketClient.java @@ -10,7 +10,9 @@ import java.io.InputStream; import java.io.OutputStream; import java.io.UncheckedIOException; +import java.net.InetAddress; import java.net.Socket; +import java.net.SocketAddress; import java.time.Duration; import java.time.LocalDateTime; import java.util.UUID; @@ -121,7 +123,13 @@ public boolean isOpen() { && !this.socket.isInputShutdown(); } - public UUID getId() { - return id; + public String getId() { + return String.valueOf(this.id).substring(0, 8) + this.getSocketAddress(); } + + public SocketAddress getSocketAddress() { + return this.socket.getRemoteSocketAddress(); + } + } + diff --git a/src/main/java/com/mageddo/dnsproxyserver/server/dns/TCPServer.java b/src/main/java/com/mageddo/dnsproxyserver/server/dns/TCPServer.java index 4540c07a1..dceaeb69d 100644 --- a/src/main/java/com/mageddo/dnsproxyserver/server/dns/TCPServer.java +++ b/src/main/java/com/mageddo/dnsproxyserver/server/dns/TCPServer.java @@ -3,6 +3,7 @@ import com.mageddo.commons.concurrent.ThreadPool; import lombok.RequiredArgsConstructor; import lombok.extern.slf4j.Slf4j; +import org.slf4j.MDC; import javax.inject.Inject; import javax.inject.Singleton; @@ -57,23 +58,30 @@ void watchDog() { } final var clientsBefore = this.clients.size(); while (itr.hasNext()) { - final var client = itr.next().get(); - if (client == null) { - log.debug("status=clientWasGarbageCollected"); - } else if (client.isClosed()) { - itr.remove(); - log.debug("status=removedAlreadyClosed, runningTime={}", client.getRunningTime()); - } else if (runningForTooLong(client)) { - client.silentClose(); - itr.remove(); - log.debug("status=forcedRemove, runningTime={}", client.getRunningTime()); + try { + final var client = itr.next().get(); + if (client == null) { + log.debug("status=clientWasGarbageCollected"); + continue; + } + MDC.put("clientId", String.valueOf(client.getId())); + if (client.isClosed()) { + itr.remove(); + log.debug("status=removedAlreadyClosed, runningTime={}", client.getRunningTime()); + } else if (runningForTooLong(client)) { + client.silentClose(); + itr.remove(); + log.debug("status=forcedRemove, runningTime={}", client.getRunningTime()); + } + } finally { + MDC.clear(); } } log.debug( "status=watchdog, removed={}, clientsBefore={}, after={}", clientsBefore - this.clients.size(), clientsBefore, this.clients.size() ); - } catch (Throwable e){ + } catch (Throwable e) { log.error("status=watchdogFailed, msg={}", e.getMessage(), e); } } diff --git a/src/main/java/com/mageddo/dnsproxyserver/server/dns/UDPServer.java b/src/main/java/com/mageddo/dnsproxyserver/server/dns/UDPServer.java index d379d75b6..9a441ae38 100644 --- a/src/main/java/com/mageddo/dnsproxyserver/server/dns/UDPServer.java +++ b/src/main/java/com/mageddo/dnsproxyserver/server/dns/UDPServer.java @@ -48,13 +48,16 @@ private void start0() { void handle(DatagramSocket server, DatagramPacket datagram) { try { - final var reqMsg = new Message(datagram.getData()); - final var resData = this.requestHandler.handle(reqMsg, "udp").toWire(); + final var query = new Message(datagram.getData()); + final var res = this.requestHandler.handle(query, "udp"); + final var resData = res.toWire(); server.send(new DatagramPacket(resData, resData.length, datagram.getSocketAddress())); + log.debug( - "status=success, dataLength={}, datagramLength={}, serverAddr={}, clientAddr={}", - datagram.getData().length, datagram.getLength(), server.getLocalAddress(), datagram.getSocketAddress() + "status=success, query={}, res={}, serverAddr={}, clientAddr={}, dataLength={}, datagramLength={}", + Messages.simplePrint(query), Messages.simplePrint(res), + server.getLocalAddress(), datagram.getSocketAddress(), datagram.getData().length, datagram.getLength() ); } catch (Exception e) { log.warn("status=messageHandleFailed, msg={}", e.getMessage(), e); diff --git a/src/main/resources/application.properties b/src/main/resources/application.properties index fc984ccf5..3f3d90da2 100644 --- a/src/main/resources/application.properties +++ b/src/main/resources/application.properties @@ -7,6 +7,7 @@ quarkus.http.port=5380 # Logs quarkus.log.level=INFO quarkus.log.console.format=%d{HH:mm:ss.SSS} t=%15.-15t %-3.3p %i %0.-35C m=%M:%L %X %m%n +quarkus.log.file.format=%d{yyyy-MM-dd HH:mm:ss.SSS} t=%15.-15t %-3.3p %i %0.-35C m=%M:%L %X %m%n %prod.quarkus.log.category."com.mageddo".level=INFO quarkus.log.category."com.mageddo".level=DEBUG diff --git a/src/test/java/com/mageddo/dnsproxyserver/server/dns/DnsQueryTCPHandlerTest.java b/src/test/java/com/mageddo/dnsproxyserver/server/dns/DnsQueryTCPHandlerTest.java index e10f657d0..19d1faa40 100644 --- a/src/test/java/com/mageddo/dnsproxyserver/server/dns/DnsQueryTCPHandlerTest.java +++ b/src/test/java/com/mageddo/dnsproxyserver/server/dns/DnsQueryTCPHandlerTest.java @@ -19,7 +19,6 @@ import static org.junit.jupiter.api.Assertions.assertArrayEquals; import static org.junit.jupiter.api.Assertions.assertEquals; -import static org.mockito.Mockito.mock; class DnsQueryTCPHandlerTest { @@ -48,6 +47,8 @@ void mustReadEntireMessageBeforeHandleIt() throws Exception { final var data = query.toWire(); writeQueryMsgSlowly(queryOut, data); + // wait some time before "timeout" + Threads.sleep(50); IOUtils.closeQuietly(queryOut); }, diff --git a/src/test/java/com/mageddo/dnsproxyserver/templates/SocketClientTemplates.java b/src/test/java/com/mageddo/dnsproxyserver/templates/SocketClientTemplates.java index ee9ebc9ef..f5183c9b8 100644 --- a/src/test/java/com/mageddo/dnsproxyserver/templates/SocketClientTemplates.java +++ b/src/test/java/com/mageddo/dnsproxyserver/templates/SocketClientTemplates.java @@ -1,13 +1,17 @@ package com.mageddo.dnsproxyserver.templates; import com.mageddo.dnsproxyserver.server.dns.SocketClient; +import org.mockito.Mockito; import java.io.InputStream; import java.io.OutputStream; +import java.net.Socket; + +import static org.mockito.Mockito.mock; public class SocketClientTemplates { public static SocketClient buildWith(InputStream in, OutputStream out) { - return new SocketClient(null, null) { + return new SocketClient(mock(Socket.class), null) { private boolean closed; @Override