80 create server logger (#104)

* Add dependency to Pom

* Centralized logger, prints date - time and class. followed by logger level (info/error..) and message

* Replace java.util.logger with new logger

* Add logger to tcp server

* Update tests to match new logger

* Switch old util logger to new centralized logger

* Update LOG_LEVEL with a fallback

* Delete src/main/java/org/example/ServerLogger.java

* Change logg -> log

* Refactor

* Refactor comment

Author: AnnaZiafar

pom.xml

@@ -71,6 +71,13 @@
             <version>1.20.0</version>
         </dependency>
 
+        <dependency>
+            <groupId>ch.qos.logback</groupId>
+            <artifactId>logback-classic</artifactId>
+            <version>1.5.32</version>
+            <scope>compile</scope>
+        </dependency>
+
     </dependencies>
     <build>
         <plugins>

src/main/java/org/example/TcpServer.java

@@ -1,32 +1,33 @@
 package org.example;
 
 import org.example.http.HttpResponseBuilder;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
 import java.io.IOException;
 import java.io.OutputStream;
-import java.io.PrintWriter;
 import java.net.ServerSocket;
 import java.net.Socket;
-import java.nio.charset.StandardCharsets;
 import java.util.Map;
 
 public class TcpServer {
 
     private final int port;
     private final ConnectionFactory connectionFactory;
+    private static final Logger log = LoggerFactory.getLogger(TcpServer.class);
 
     public TcpServer(int port, ConnectionFactory connectionFactory) {
         this.port = port;
         this.connectionFactory = connectionFactory;
     }
 
     public void start() {
-        System.out.println("Starting TCP server on port " + port);
+        log.info("Starting TCP server on port {}", port);
 
         try (ServerSocket serverSocket = new ServerSocket(port)) {
             while (true) {
                 Socket clientSocket = serverSocket.accept(); // block
-                System.out.println("Client connected: " + clientSocket.getRemoteSocketAddress());
+                log.info("Client connected");
                 Thread.ofVirtual().start(() -> handleClient(clientSocket));
             }
         } catch (IOException e) {
@@ -38,16 +39,22 @@ protected void handleClient(Socket client) {
         try(client){
             processRequest(client);
         } catch (Exception e) {
-            throw new RuntimeException("Failed to close socket", e);
+            log.error("Failed when handling connection to client", e);
         }
     }
 
+    /*
+    The connection handler must be run in a try-catch-finally. Otherwise - if we use try-with-resources - the
+    connection will always be closed when code reaches handleInternalServerError() and there will never
+    be an error print on the client's webpage.
+     */
     private void processRequest(Socket client) throws Exception {
         ConnectionHandler handler = null;
         try{
             handler = connectionFactory.create(client);
             handler.runConnectionHandler();
         } catch (Exception e) {
+            log.error("Internal Server Error", e);
             handleInternalServerError(client);
         } finally {
             if(handler != null)
@@ -68,7 +75,7 @@ private void handleInternalServerError(Socket client){
                 out.write(response.build());
                 out.flush();
             } catch (IOException e) {
-                System.err.println("Failed to send 500 response: " + e.getMessage());
+                log.error("Client disconnected before 500 response could be sent", e);
             }
         }
     }

src/main/java/org/example/filter/LoggingFilter.java

@@ -2,12 +2,13 @@
 
 import org.example.http.HttpResponseBuilder;
 import org.example.httpparser.HttpRequest;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 
-import java.util.logging.Logger;
 
 public class LoggingFilter implements Filter {
 
-    private static final Logger logg = Logger.getLogger(LoggingFilter.class.getName());
+    private static final Logger log = LoggerFactory.getLogger(LoggingFilter.class);
 
     @Override
     public void init() {
@@ -27,10 +28,8 @@ public void doFilter(HttpRequest request, HttpResponseBuilder response, FilterCh
             long endTime = System.nanoTime();
             long processingTimeInMs = (endTime - startTime) / 1000000;
 
-            String message = String.format("REQUEST: %s %s | STATUS: %s | TIME: %dms",
+            log.info("REQUEST: {} {} | STATUS: {} | TIME: {}ms",
                     request.getMethod(), request.getPath(), response.getStatusCode(), processingTimeInMs);
-
-            logg.info(message);
         }
 
     }

src/main/java/org/example/httpparser/HttpParseRequestLine.java

@@ -1,15 +1,17 @@
 package org.example.httpparser;
 
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
 import java.io.BufferedReader;
 import java.io.IOException;
-import java.util.logging.Logger;
 
 abstract class HttpParseRequestLine {
     private String method;
     private String uri;
     private String version;
-    private boolean debug = false;
-    private static final Logger logger = Logger.getLogger(HttpParseRequestLine.class.getName());
+
+    private static final Logger log = LoggerFactory.getLogger(HttpParseRequestLine.class);
 
     public void parseHttpRequest(BufferedReader br) throws IOException {
         BufferedReader reader = br;
@@ -31,11 +33,8 @@ public void parseHttpRequest(BufferedReader br) throws IOException {
             setVersion(requestLineArray[2]);
         }
 
-        if(debug) {
-            logger.info(getMethod());
-            logger.info(getUri());
-            logger.info(getVersion());
-        }
+        log.debug("METHOD: {} | URI: {} | VERSION: {}",
+                getMethod(), getUri(), getVersion());
     }
 
 

src/main/resources/logback.xml

@@ -0,0 +1,11 @@
+<configuration>
+<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
+    <encoder>
+        <pattern>%d{yyyy-MM-dd HH:mm:ss} %cyan(%logger{36}) %n%highlight(%-5level) - %msg%n</pattern>
+    </encoder>
+</appender>
+
+<root level="${LOG_LEVEL:-INFO}">
+    <appender-ref ref="CONSOLE" />
+</root>
+</configuration>

src/test/java/org/example/filter/LoggingFilterTest.java

@@ -1,47 +1,45 @@
 package org.example.filter;
 
+import ch.qos.logback.classic.spi.ILoggingEvent;
+import ch.qos.logback.core.read.ListAppender;
 import org.example.http.HttpResponseBuilder;
 import org.example.httpparser.HttpRequest;
-import org.junit.jupiter.api.AfterEach;
 import org.junit.jupiter.api.BeforeEach;
 import org.junit.jupiter.api.Test;
 import org.junit.jupiter.api.extension.ExtendWith;
-import org.mockito.ArgumentCaptor;
 import org.mockito.Mock;
 import org.mockito.junit.jupiter.MockitoExtension;
+import ch.qos.logback.classic.Logger;
+import org.slf4j.LoggerFactory;
 
-import java.util.logging.Handler;
-import java.util.logging.LogRecord;
-import java.util.logging.Logger;
+import java.util.List;
 
 import static org.assertj.core.api.Assertions.assertThat;
 import static org.mockito.Mockito.*;
 
 @ExtendWith(MockitoExtension.class)
 class LoggingFilterTest {
 
-    @Mock Handler handler;
     @Mock HttpRequest request;
     @Mock HttpResponseBuilder response;
     @Mock FilterChain chain;
 
     LoggingFilter filter = new LoggingFilter();
-    Logger logger;
+    ListAppender<ILoggingEvent> appender;
 
     @BeforeEach
     void setup(){
-        logger = Logger.getLogger(LoggingFilter.class.getName());
-        logger.addHandler(handler);
+        Logger logger = (Logger) LoggerFactory.getLogger(LoggingFilter.class);
+
+        appender = new ListAppender<>();
+        appender.start();
+
+        logger.addAppender(appender);
 
         when(request.getMethod()).thenReturn("GET");
         when(request.getPath()).thenReturn("/index.html");
     }
 
-    @AfterEach
-    void tearDown(){
-        logger.removeHandler(handler);
-    }
-
     @Test
     void loggingWorksWhenChainWorks(){
         when(response.getStatusCode()).thenReturn(HttpResponseBuilder.SC_OK);
@@ -79,11 +77,10 @@ void statusChangesFrom200To500WhenErrorOccurs(){
     }
 
     private void verifyLogContent(String expectedMessage){
-        //Use ArgumentCaptor to capture the actual message in the log
-        ArgumentCaptor<LogRecord> logCaptor = ArgumentCaptor.forClass(LogRecord.class);
-        verify(handler).publish(logCaptor.capture());
+        List<ILoggingEvent> logs = appender.list;
 
-        String message = logCaptor.getValue().getMessage();
+        assertThat(logs).isNotEmpty();
+        String message = logs.getFirst().getFormattedMessage();
 
         assertThat(message).contains(expectedMessage);
     }