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
mageddo · Feb 24, 2023 · 7b7cc74 · 7b7cc74
1 parent bc0a951
commit 7b7cc74
Show file tree

Hide file tree

Showing 9 changed files with 74 additions and 32 deletions.
diff --git 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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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