Skip to content

[Feat/logger] 로깅 모듈 (@ServiceLog)#63

Merged
ekgns33 merged 17 commits intomainfrom
feat/logger
Apr 26, 2025
Merged

[Feat/logger] 로깅 모듈 (@ServiceLog)#63
ekgns33 merged 17 commits intomainfrom
feat/logger

Conversation

@jeeheaG
Copy link
Contributor

@jeeheaG jeeheaG commented Apr 20, 2025

[작업 사항]

  • 로그 형식 논의 #59 에 해당하는 로깅 모듈 작업
  • 현재 부화 api 의 컨트롤러 메서드에만 메서드로그 적용해두었음

[전달 사항]

  • 모든 HTTP 요청에 대한 로그가 기록됩니다.

    20250421 01:47:07.682 [http-nio-auto-1-exec-3] [INFO] o.r.r.c.l.HttpRequestLogAspect - HTTP_REQUEST [method=POST, uri=/api/v1/incubating-eggs/5/hatch, query_params=[test_param1=val1, test_param2=val2], time=2025-04-21T01:47:07] 
    
  • 클래스 또는 메서드에 @ServiceLog 사용 시 클래스에 포함된 모든 메서드의 요청/종료 로그가 기록됩니다.

    20250421 01:47:07.699 [http-nio-auto-1-exec-3] [INFO] o.r.r.c.l.MethodLogAspect - METHOD_CALL [name=HatchClient.getRandomRunimoDefinition, authenticated=true, user_id=test-user-uuid-1, params=[egg_type=FOREST], time=2025-04-21T01:47:07] 
    
    20250421 01:47:07.714 [http-nio-auto-1-exec-3] [INFO] o.r.r.c.l.MethodLogAspect - METHOD_END [name=HatchClient.getRandomRunimoDefinition, elapsed_time=15ms, return=org.runimo.runimo.runimo.domain.RunimoDefinition@58694c0f, time=2025-04-21T01:47:07] 
    
    

[유의 사항]

  • Exception이 던져질 때 해당 요청 처리가 끊기므로 Handler 에서 핸들링되어서 응답은 잘 가더라도, 메서드 종료 로그는 안찍힘

코드 정리도 더 할 수 있을 것 같고 log 패키지 정리도 안되어보여서 신경쓰이네요
우선 기능 feature 부터 올립니다

Summary by CodeRabbit

  • New Features

    • Introduced comprehensive logging for HTTP requests and service methods, including request details, method execution, user context, and performance metrics.
    • Added a custom annotation to enable detailed business logic logging on specific methods or classes.
  • Enhancements

    • Improved string representation for response objects by automatically generating toString methods.
  • Style

    • Applied consistent annotation-based enhancements for better maintainability and logging clarity.

@jeeheaG jeeheaG requested a review from ekgns33 April 20, 2025 17:26
@jeeheaG jeeheaG self-assigned this Apr 20, 2025
@coderabbitai
Copy link

coderabbitai bot commented Apr 20, 2025

Walkthrough

This update introduces a comprehensive logging framework to the codebase. New aspect-oriented components are added to log HTTP requests and method invocations across controllers and service layers. Custom log info records and a formatter are implemented for structured, consistent log messages. A custom @ServiceLog annotation enables targeted logging on service methods or classes. Additionally, the @ToString annotation is applied to response classes for improved string representation, and the @ServiceLog annotation is now used in a controller method to activate the new logging aspect.

Changes

File(s) Change Summary
.../log/HttpRequestLogAspect.java,
.../log/MethodLogAspect.java
Added new aspect classes for logging HTTP requests and method invocations using Spring AOP and custom annotations.
.../log/LogMessageFormatter.java Introduced a component for formatting log messages for HTTP requests and method events.
.../log/ServiceLog.java Added a custom annotation for marking methods or classes for logging.
.../log/model/HttpRequestLogInfo.java,
.../log/model/MethodStartLogInfo.java,
.../log/model/MethodEndLogInfo.java
Added immutable record classes to encapsulate log details for HTTP requests and method events.
.../response/ErrorResponse.java,
.../response/Response.java,
.../response/SuccessResponse.java
Applied Lombok's @ToString annotation to response classes for automatic string representation.
.../hatch/controller/HatchController.java Annotated the hatch method with @ServiceLog to enable method-level logging.

Sequence Diagram(s)

sequenceDiagram
    participant Client
    participant Controller
    participant HttpRequestLogAspect
    participant MethodLogAspect
    participant Service

    Client->>Controller: HTTP Request
    activate HttpRequestLogAspect
    HttpRequestLogAspect->>Controller: Log HTTP Request Details
    deactivate HttpRequestLogAspect

    activate MethodLogAspect
    MethodLogAspect->>Controller: Log Method Start
    Controller->>Service: Service Call (with @ServiceLog)
    MethodLogAspect->>Service: Log Method Start (if annotated)
    Service-->>Controller: Return Result
    MethodLogAspect->>Service: Log Method End (if annotated)
    Controller-->>Client: HTTP Response
    MethodLogAspect->>Controller: Log Method End
    deactivate MethodLogAspect
Loading

Poem

In the warren of code, where the logs now flow,
Aspects and annotations make details show.
From HTTP requests to each method’s start,
Structured records capture every part.
With @ToString in tow, responses gleam bright—
A rabbit’s delight in logs, crisp and right!
🐇✨

✨ Finishing Touches
  • 📝 Generate Docstrings

🪧 Tips

Chat

There are 3 ways to chat with CodeRabbit:

  • Review comments: Directly reply to a review comment made by CodeRabbit. Example:
    • I pushed a fix in commit <commit_id>, please review it.
    • Generate unit testing code for this file.
    • Open a follow-up GitHub issue for this discussion.
  • Files and specific lines of code (under the "Files changed" tab): Tag @coderabbitai in a new review comment at the desired location with your query. Examples:
    • @coderabbitai generate unit testing code for this file.
    • @coderabbitai modularize this function.
  • PR comments: Tag @coderabbitai in a new PR comment to ask questions about the PR branch. For the best results, please provide a very specific query, as very limited context is provided in this mode. Examples:
    • @coderabbitai gather interesting stats about this repository and render them as a table. Additionally, render a pie chart showing the language distribution in the codebase.
    • @coderabbitai read src/utils.ts and generate unit testing code.
    • @coderabbitai read the files in the src/scheduler package and generate a class diagram using mermaid and a README in the markdown format.
    • @coderabbitai help me debug CodeRabbit configuration file.

Note: Be mindful of the bot's finite context window. It's strongly recommended to break down tasks such as reading entire modules into smaller chunks. For a focused discussion, use review comments to chat about specific files and their changes, instead of using the PR comments.

CodeRabbit Commands (Invoked using PR comments)

  • @coderabbitai pause to pause the reviews on a PR.
  • @coderabbitai resume to resume the paused reviews.
  • @coderabbitai review to trigger an incremental review. This is useful when automatic reviews are disabled for the repository.
  • @coderabbitai full review to do a full review from scratch and review all the files again.
  • @coderabbitai summary to regenerate the summary of the PR.
  • @coderabbitai generate docstrings to generate docstrings for this PR.
  • @coderabbitai generate sequence diagram to generate a sequence diagram of the changes in this PR.
  • @coderabbitai resolve resolve all the CodeRabbit review comments.
  • @coderabbitai configuration to show the current CodeRabbit configuration for the repository.
  • @coderabbitai help to get help.

Other keywords and placeholders

  • Add @coderabbitai ignore anywhere in the PR description to prevent this PR from being reviewed.
  • Add @coderabbitai summary to generate the high-level summary at a specific location in the PR description.
  • Add @coderabbitai anywhere in the PR title to generate the title automatically.

CodeRabbit Configuration File (.coderabbit.yaml)

  • You can programmatically configure CodeRabbit by adding a .coderabbit.yaml file to the root of your repository.
  • Please see the configuration documentation for more information.
  • If your editor has YAML language server enabled, you can add the path at the top of this file to enable auto-completion and validation: # yaml-language-server: $schema=https://coderabbit.ai/integrations/schema.v2.json

Documentation and Community

  • Visit our Documentation for detailed information on how to use CodeRabbit.
  • Join our Discord Community to get help, request features, and share feedback.
  • Follow us on X/Twitter for updates and announcements.

Copy link

@coderabbitai coderabbitai bot left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actionable comments posted: 3

🧹 Nitpick comments (5)
src/main/java/org/runimo/runimo/common/log/model/HttpRequestLogInfo.java (2)

3-10: Remove unused import.

The StringTokenizer import on line 7 is not used in the code.

-import java.util.StringTokenizer;

30-46: Consider enhancing query parameter parsing for edge cases.

The current implementation has some limitations:

  1. It doesn't handle URL decoding of parameter values
  2. It doesn't support multiple values for the same parameter name
  3. It might not handle all edge cases for malformed query strings

Consider using Spring's UriComponentsBuilder or servlet's request.getParameterMap() for more robust parsing.

 private static Map<String, String> getQueryParamMap(String queryString) {
     if (queryString == null || queryString.isBlank()) {
         return Collections.emptyMap();
     }

-    Map<String, String> queryParams = new HashMap<>();
-
-    String[] paramPairs = queryString.split("&");
-    for (String paramPair : paramPairs) {
-        String[] keyVal = paramPair.split("=", 2);
-
-        String val = keyVal.length < 2 ? "" : keyVal[1];
-        queryParams.put(keyVal[0], val);
-    }
-
-    return queryParams;
+    // Use servlet API to handle all edge cases
+    Map<String, String> queryParams = new HashMap<>();
+    Map<String, String[]> parameterMap = request.getParameterMap();
+    
+    for (Map.Entry<String, String[]> entry : parameterMap.entrySet()) {
+        String[] values = entry.getValue();
+        queryParams.put(entry.getKey(), values.length > 0 ? values[0] : "");
+    }
+    
+    return queryParams;
 }

Alternatively, if you want to keep the current parsing approach but with URL decoding:

 private static Map<String, String> getQueryParamMap(String queryString) {
     if (queryString == null || queryString.isBlank()) {
         return Collections.emptyMap();
     }

     Map<String, String> queryParams = new HashMap<>();

     String[] paramPairs = queryString.split("&");
     for (String paramPair : paramPairs) {
         String[] keyVal = paramPair.split("=", 2);

-        String val = keyVal.length < 2 ? "" : keyVal[1];
-        queryParams.put(keyVal[0], val);
+        String key = java.net.URLDecoder.decode(keyVal[0], java.nio.charset.StandardCharsets.UTF_8);
+        String val = keyVal.length < 2 ? "" : java.net.URLDecoder.decode(keyVal[1], java.nio.charset.StandardCharsets.UTF_8);
+        queryParams.put(key, val);
     }

     return queryParams;
 }
src/main/java/org/runimo/runimo/common/response/Response.java (1)

5-8: LGTM! Consistent use of @tostring across response classes.

The addition of @ToString improves logging and debugging by providing better string representations of Response objects. This aligns with similar annotations on child classes like SuccessResponse and ErrorResponse.

For child classes, consider using @ToString(callSuper=true) to include the parent class fields in their string representation and avoid duplication.

src/main/java/org/runimo/runimo/common/log/HttpRequestLogAspect.java (1)

32-44: Consider enhancing error handling for more robust logging

The aspect logs HTTP requests correctly, but could be improved in a few ways:

  1. Line 35-38: When ServletRequestAttributes is null, consider including more context about which request is being processed
  2. There's no exception handling around the formatter call, which could potentially fail
@Before("controller()")
public void apiRequestLogger() {
    try {
        ServletRequestAttributes attributes = ((ServletRequestAttributes) RequestContextHolder.getRequestAttributes());
        if (attributes == null) {
-           log.info("ServletRequestAttributes is null");
+           log.warn("ServletRequestAttributes is null, unable to log HTTP request details");
            return;
        }

        HttpServletRequest request = attributes.getRequest();
        HttpRequestLogInfo logInfo = HttpRequestLogInfo.of(request);

        log.info(logMessageFormatter.toHttpRequestLogMessage(logInfo));
+   } catch (Exception e) {
+       log.warn("Failed to log HTTP request: {}", e.getMessage());
+   }
}
src/main/java/org/runimo/runimo/common/log/LogMessageFormatter.java (1)

55-60: Beware of huge toString() outputs in the return log.

Large collections or binary payloads may explode your log volume and slow the JVM.
Consider truncating, hashing, or whitelisting types before calling String.valueOf() on the return value.

📜 Review details

Configuration used: CodeRabbit UI
Review profile: CHILL
Plan: Pro

📥 Commits

Reviewing files that changed from the base of the PR and between b2fcfee and c41eb6e.

📒 Files selected for processing (11)
  • src/main/java/org/runimo/runimo/common/log/HttpRequestLogAspect.java (1 hunks)
  • src/main/java/org/runimo/runimo/common/log/LogMessageFormatter.java (1 hunks)
  • src/main/java/org/runimo/runimo/common/log/MethodLogAspect.java (1 hunks)
  • src/main/java/org/runimo/runimo/common/log/ServiceLog.java (1 hunks)
  • src/main/java/org/runimo/runimo/common/log/model/HttpRequestLogInfo.java (1 hunks)
  • src/main/java/org/runimo/runimo/common/log/model/MethodEndLogInfo.java (1 hunks)
  • src/main/java/org/runimo/runimo/common/log/model/MethodStartLogInfo.java (1 hunks)
  • src/main/java/org/runimo/runimo/common/response/ErrorResponse.java (1 hunks)
  • src/main/java/org/runimo/runimo/common/response/Response.java (1 hunks)
  • src/main/java/org/runimo/runimo/common/response/SuccessResponse.java (1 hunks)
  • src/main/java/org/runimo/runimo/hatch/controller/HatchController.java (2 hunks)
🧰 Additional context used
🧬 Code Graph Analysis (4)
src/main/java/org/runimo/runimo/common/response/Response.java (2)
src/main/java/org/runimo/runimo/common/response/ErrorResponse.java (1)
  • ToString (6-24)
src/main/java/org/runimo/runimo/common/response/SuccessResponse.java (1)
  • ToString (7-25)
src/main/java/org/runimo/runimo/common/response/SuccessResponse.java (2)
src/main/java/org/runimo/runimo/common/response/ErrorResponse.java (1)
  • ToString (6-24)
src/main/java/org/runimo/runimo/common/response/Response.java (1)
  • ToString (8-30)
src/main/java/org/runimo/runimo/common/log/HttpRequestLogAspect.java (1)
src/main/java/org/runimo/runimo/common/log/MethodLogAspect.java (1)
  • Aspect (15-60)
src/main/java/org/runimo/runimo/common/log/MethodLogAspect.java (1)
src/main/java/org/runimo/runimo/common/log/HttpRequestLogAspect.java (1)
  • Aspect (20-46)
🔇 Additional comments (10)
src/main/java/org/runimo/runimo/common/log/ServiceLog.java (1)

8-15: LGTM! Simple and focused annotation for service method logging.

The annotation is well-designed with appropriate retention policy and target elements, allowing it to be applied to both classes and methods. This flexible design supports the logging framework being introduced.

Consider adding configuration attributes in the future if you need more fine-grained control over logging behavior (e.g., excluding sensitive parameters, controlling log levels).

src/main/java/org/runimo/runimo/hatch/controller/HatchController.java (1)

27-27: LGTM! Good application of the ServiceLog annotation.

The use of @ServiceLog on the hatch method aligns with the PR objective of enabling method-level logging for the hatch API controller. This will log method execution details including parameters, return values, and execution time.

src/main/java/org/runimo/runimo/common/response/SuccessResponse.java (1)

4-4: Adding @tostring enhances logging readability - good addition

The @ToString annotation will automatically generate a more informative string representation of this class, which is valuable for logging and debugging. This aligns well with the logging framework being introduced in this PR.

Also applies to: 7-7

src/main/java/org/runimo/runimo/common/response/ErrorResponse.java (1)

3-3: Good consistency with @tostring across response classes

Adding the @ToString annotation to ErrorResponse maintains consistency with other response classes and enhances the logging capabilities. This improves debuggability when these objects appear in logs.

Also applies to: 6-6

src/main/java/org/runimo/runimo/common/log/HttpRequestLogAspect.java (2)

1-24: AOP configuration looks good for controller-level HTTP request logging

The AspectJ configuration correctly targets controller methods and includes all necessary dependencies. The use of Lombok annotations for logging and constructor injection helps keep the code clean.


28-30: Pointcut definition effectively targets all controller methods

The pointcut expression execution(* org.runimo.runimo..controller.*Controller.*(..)) will capture all methods in any class ending with "Controller" in the controller package hierarchy, which is appropriate for HTTP request logging.

src/main/java/org/runimo/runimo/common/log/model/MethodEndLogInfo.java (2)

1-13: Record structure effectively captures method execution details

The record definition with @Builder is clean and appropriate for representing method end log information. The private access level on the builder ensures proper instantiation through the factory method.


25-28: Class name extraction looks good

The method correctly extracts the simple class name from the fully qualified name. While there might be alternative approaches (like using Class.getSimpleName() if available), the current implementation is straightforward and effective.

src/main/java/org/runimo/runimo/common/log/model/MethodStartLogInfo.java (1)

35-37: parameterNames may be null without the -parameters compiler flag.

MethodSignature#getParameterNames() returns null unless the class is compiled with -parameters.
Consider falling back to placeholder names or logging a warning to avoid NullPointerException in the loop above.

src/main/java/org/runimo/runimo/common/log/MethodLogAspect.java (1)

46-51: Verify authentication status before trusting the principal.

authentication can exist while isAuthenticated() is false (e.g., anonymous user).
Include this check to prevent misleading “authenticated=true” logs.

-        if (authentication != null) {
+        if (authentication != null && authentication.isAuthenticated()) {
             methodStartLogInfo = MethodStartLogInfo.of(pjp, true, authentication.getName());

Comment on lines +27 to +41
@Around("annotatedClassAndMethod()")
public Object calledMethodLogger(ProceedingJoinPoint pjp) throws Throwable {
MethodStartLogInfo methodStartLogInfo = getMethodStartLogInfo(pjp);
log.info(logMessageFormatter.toMethodStartLogMessage(methodStartLogInfo));

long startTime = getCurrentTimeMillis();
Object proceedReturn = pjp.proceed();
long endTime = getCurrentTimeMillis();

MethodEndLogInfo methodEndLogInfo = MethodEndLogInfo.of(pjp, endTime - startTime,
proceedReturn);
log.info(logMessageFormatter.toMethodEndLogMessage(methodEndLogInfo));

return proceedReturn;
}
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🛠️ Refactor suggestion

Log method end and exceptions – move logging into try / catch / finally.

If the target method throws, the current implementation never emits an end‑log, contradicting the stated goal.
Wrap pjp.proceed() in try / catch (to log the exception) and finally (to guarantee an end record).

@Around("annotatedClassAndMethod()")
public Object calledMethodLogger(ProceedingJoinPoint pjp) throws Throwable {
    MethodStartLogInfo startInfo = getMethodStartLogInfo(pjp);
    log.info(logMessageFormatter.toMethodStartLogMessage(startInfo));

    long startTime = getCurrentTimeMillis();
-    Object proceedReturn = pjp.proceed();
-    long endTime = getCurrentTimeMillis();
-
-    MethodEndLogInfo endInfo = MethodEndLogInfo.of(pjp, endTime - startTime, proceedReturn);
-    log.info(logMessageFormatter.toMethodEndLogMessage(endInfo));
-    return proceedReturn;
+    try {
+        Object result = pjp.proceed();
+        MethodEndLogInfo endInfo =
+                MethodEndLogInfo.of(pjp, getCurrentTimeMillis() - startTime, result);
+        log.info(logMessageFormatter.toMethodEndLogMessage(endInfo));
+        return result;
+    } catch (Throwable ex) {
+        log.warn("METHOD_EXCEPTION [name={}, elapsed_time={}ms, exception={}]",
+                 pjp.getSignature().toShortString(),
+                 getCurrentTimeMillis() - startTime,
+                 ex.toString());
+        throw ex;
+    }
}

Committable suggestion skipped: line range outside the PR's diff.

Copy link
Contributor

@ekgns33 ekgns33 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

고생하셨습니다! 이제 로그를 편하게 볼 수 있겠군요 ㅎㅎ

  • NPE 관련해서 토끼가 두개 올려놨는데 해당 이슈만 resolve하고 머지해주세요!

@jeeheaG
Copy link
Contributor Author

jeeheaG commented Apr 24, 2025

확인이 늦었네요. 오늘내로 수정 사항 반영 후 머지하겠습니다!

-> 내일까지.. 하겠읍니다..

Copy link

@coderabbitai coderabbitai bot left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actionable comments posted: 3

♻️ Duplicate comments (2)
src/main/java/org/runimo/runimo/common/log/MethodLogAspect.java (1)

27-47: 🛠️ Refactor suggestion

Restructure method to log end info in finally block

If an exception is thrown, the method end log won't be recorded, as mentioned in the PR objectives.

Apply this change to ensure method end logs are always recorded:

@Around("annotatedClassAndMethod()")
public Object calledMethodLogger(ProceedingJoinPoint pjp) throws Throwable {
    MethodStartLogInfo methodStartLogInfo = getMethodStartLogInfo(pjp);
    log.info(logMessageFormatter.toMethodStartLogMessage(methodStartLogInfo));

    long startTime = getCurrentTimeMillis();
-    long endTime;
    Object proceedReturn = null;
    try {
        proceedReturn = pjp.proceed();
-    } catch (Throwable ex) {
-        log.info(logMessageFormatter.toMethodErrorLogMessage(ex));
-    }
-    endTime = getCurrentTimeMillis();
-
-    MethodEndLogInfo methodEndLogInfo = MethodEndLogInfo.of(pjp, endTime - startTime,
-        proceedReturn);
-    log.info(logMessageFormatter.toMethodEndLogMessage(methodEndLogInfo));
-
-    return proceedReturn;
+        return proceedReturn;
+    } catch (Throwable ex) {
+        log.error(logMessageFormatter.toMethodErrorLogMessage(ex));
+        throw ex;
+    } finally {
+        long endTime = getCurrentTimeMillis();
+        MethodEndLogInfo methodEndLogInfo = MethodEndLogInfo.of(pjp, endTime - startTime, proceedReturn);
+        log.info(logMessageFormatter.toMethodEndLogMessage(methodEndLogInfo));
+    }
}
src/main/java/org/runimo/runimo/common/log/LogMessageFormatter.java (1)

102-107: 🛠️ Refactor suggestion

Consider removing camelCase to snake_case conversion as noted in previous feedback

As mentioned in the previous review comment, this conversion might not be necessary for logs and could impact performance. The team has already agreed to remove it initially.

Remove the conversion as discussed in the previous feedback:

private StringBuilder convertMapToLogFormatString(Map<String, String> infoMap,
    StringBuilder sb) {
    sb.append("[");

    Iterator<Entry<String, String>> it = infoMap.entrySet().iterator();
    while (it.hasNext()) {
        Entry<String, String> entry = it.next();
-        sb.append(convertCamelCaseToSnakeCase(entry.getKey()));
+        sb.append(entry.getKey());
        sb.append("=");
        sb.append(entry.getValue());

        if (it.hasNext()) {
            sb.append(", ");
        }
    }

    sb.append("]");
    return sb;
}

-private String convertCamelCaseToSnakeCase(String camelCase) {
-    return camelCase
-        .replaceAll("([A-Z])(?=[A-Z])", "$1_")
-        .replaceAll("([a-z])([A-Z])", "$1_$2")
-        .toLowerCase();
-}
🧹 Nitpick comments (4)
src/main/java/org/runimo/runimo/common/log/MethodLogAspect.java (1)

62-64: Consider using System.nanoTime() for more precise time measurements

For measuring elapsed times, System.nanoTime() provides better precision than currentTimeMillis() and is specifically designed for measuring time intervals.

private long getCurrentTimeMillis() {
-    return System.currentTimeMillis();
+    return System.nanoTime() / 1_000_000; // Convert nanoseconds to milliseconds
}
src/main/java/org/runimo/runimo/common/log/LogMessageFormatter.java (3)

15-15: Address the TODO comment about refactoring duplicated code

There's a pattern of duplicated code across your logging methods. Consider creating a helper method to construct log messages.

Create a helper method to reduce code duplication across the formatting methods:

private String formatLogMessage(String prefix, Map<String, String> logFields) {
    StringBuilder sb = new StringBuilder();
    sb.append(prefix).append(" ");
    convertMapToLogFormatString(logFields, sb);
    return sb.toString();
}

Then use it in all your formatting methods to simplify them.


17-68: Refactor duplicate log formatting pattern across methods

The HTTP request, method start, and method end log formatting methods all follow the same pattern:

  1. Create a map of fields
  2. Build a string with a prefix
  3. Convert the map to a string
  4. Return the result

This can be simplified with a helper method to reduce duplication.

Add a helper method and refactor the existing methods to use it:

private String formatLogEntry(String prefix, Map<String, String> fields) {
    StringBuilder sb = new StringBuilder();
    sb.append(prefix).append(" ");
    convertMapToLogFormatString(fields, sb);
    return sb.toString();
}

Then you can simplify the formatting methods, for example:

public String toHttpRequestLogMessage(HttpRequestLogInfo logInfo) {
    String queryParamString = convertMapToLogFormatString(logInfo.queryParams(),
        new StringBuilder()).toString();

    Map<String, String> logs = new LinkedHashMap<>();
    logs.put("method", logInfo.requestMethod());
    logs.put("uri", logInfo.uri());
    logs.put("query_params", queryParamString);
    logs.put("time", getCurrentTime());

    return formatLogEntry("HTTP_REQUEST", logs);
}

98-100: Consider adding a timestamp format string for consistent output

The current implementation returns the raw string from ZonedDateTime.now().toString(). For logging, it's often better to use a consistent, configurable format.

Add a DateTimeFormatter for consistent timestamp output:

private String getCurrentTime() {
-    return ZonedDateTime.now().toString();
+    DateTimeFormatter formatter = DateTimeFormatter.ISO_OFFSET_DATE_TIME;
+    return ZonedDateTime.now().format(formatter);
}
📜 Review details

Configuration used: CodeRabbit UI
Review profile: CHILL
Plan: Pro

📥 Commits

Reviewing files that changed from the base of the PR and between c41eb6e and d645292.

📒 Files selected for processing (4)
  • src/main/java/org/runimo/runimo/common/log/LogMessageFormatter.java (1 hunks)
  • src/main/java/org/runimo/runimo/common/log/MethodLogAspect.java (1 hunks)
  • src/main/java/org/runimo/runimo/common/log/model/MethodEndLogInfo.java (1 hunks)
  • src/main/java/org/runimo/runimo/common/log/model/MethodStartLogInfo.java (1 hunks)
🚧 Files skipped from review as they are similar to previous changes (2)
  • src/main/java/org/runimo/runimo/common/log/model/MethodStartLogInfo.java
  • src/main/java/org/runimo/runimo/common/log/model/MethodEndLogInfo.java

Comment on lines +35 to +39
try {
proceedReturn = pjp.proceed();
} catch (Throwable ex) {
log.info(logMessageFormatter.toMethodErrorLogMessage(ex));
}
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

⚠️ Potential issue

Critical issue: Method swallows exceptions without rethrowing them

The current exception handling implementation catches all exceptions, logs them, but does not rethrow them. This causes two serious problems:

  1. Exceptions are silently suppressed, breaking the normal error propagation
  2. Methods will return null when they should be throwing exceptions

Apply this change to fix the exception handling:

try {
    proceedReturn = pjp.proceed();
} catch (Throwable ex) {
-    log.info(logMessageFormatter.toMethodErrorLogMessage(ex));
+    log.error(logMessageFormatter.toMethodErrorLogMessage(ex));
+    throw ex;
}
📝 Committable suggestion

‼️ IMPORTANT
Carefully review the code before committing. Ensure that it accurately replaces the highlighted code, contains no missing lines, and has no issues with indentation. Thoroughly test & benchmark the code to ensure it meets the requirements.

Suggested change
try {
proceedReturn = pjp.proceed();
} catch (Throwable ex) {
log.info(logMessageFormatter.toMethodErrorLogMessage(ex));
}
try {
proceedReturn = pjp.proceed();
} catch (Throwable ex) {
- log.info(logMessageFormatter.toMethodErrorLogMessage(ex));
+ log.error(logMessageFormatter.toMethodErrorLogMessage(ex));
+ throw ex;
}

Comment on lines +70 to +76
public String toMethodErrorLogMessage(Throwable ex) {
StringBuilder sb = new StringBuilder();
sb.append("METHOD_EXCEPTION ");
sb.append(ex.getMessage());

return sb.toString();
}
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

🛠️ Refactor suggestion

Enhance error log format to include more debug information

The current method error log only includes the exception message. For effective debugging, include the exception type and method information as well.

Improve the exception logging by adding more context:

public String toMethodErrorLogMessage(Throwable ex) {
    StringBuilder sb = new StringBuilder();
    sb.append("METHOD_EXCEPTION ");
-    sb.append(ex.getMessage());
+    sb.append("[exception_type=").append(ex.getClass().getName());
+    sb.append(", message=").append(ex.getMessage());
+    sb.append("]");

    return sb.toString();
}
📝 Committable suggestion

‼️ IMPORTANT
Carefully review the code before committing. Ensure that it accurately replaces the highlighted code, contains no missing lines, and has no issues with indentation. Thoroughly test & benchmark the code to ensure it meets the requirements.

Suggested change
public String toMethodErrorLogMessage(Throwable ex) {
StringBuilder sb = new StringBuilder();
sb.append("METHOD_EXCEPTION ");
sb.append(ex.getMessage());
return sb.toString();
}
public String toMethodErrorLogMessage(Throwable ex) {
StringBuilder sb = new StringBuilder();
sb.append("METHOD_EXCEPTION ");
sb.append("[exception_type=").append(ex.getClass().getName());
sb.append(", message=").append(ex.getMessage());
sb.append("]");
return sb.toString();
}

Copy link

@coderabbitai coderabbitai bot left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Actionable comments posted: 0

♻️ Duplicate comments (2)
src/main/java/org/runimo/runimo/common/log/MethodLogAspect.java (2)

35-39: ⚠️ Potential issue

Critical issue: Method swallows exceptions without rethrowing

The current exception handling implementation catches all exceptions, logs them, but does not rethrow them. This causes two serious problems:

  1. Exceptions are silently suppressed, breaking the normal error propagation
  2. Methods will return null when they should be throwing exceptions

Apply this change to fix the exception handling:

try {
    proceedReturn = pjp.proceed();
} catch (Throwable ex) {
    log.error(logMessageFormatter.toMethodErrorLogMessage(ex));
+    throw ex;
}

27-47: 🛠️ Refactor suggestion

Log method end and exceptions – improve with try/catch/finally pattern

The current implementation logs method end info even for failed method executions, but the timing logic and structure could be improved.

Apply this refactoring to improve exception handling and logging flow:

@Around("annotatedClassAndMethod()")
public Object calledMethodLogger(ProceedingJoinPoint pjp) throws Throwable {
    MethodStartLogInfo methodStartLogInfo = getMethodStartLogInfo(pjp);
    log.info(logMessageFormatter.toMethodStartLogMessage(methodStartLogInfo));

    long startTime = getCurrentTimeMillis();
-    long endTime;
    Object proceedReturn = null;
    try {
        proceedReturn = pjp.proceed();
+        return proceedReturn;
    } catch (Throwable ex) {
        log.error(logMessageFormatter.toMethodErrorLogMessage(ex));
+        throw ex;
+    } finally {
+        long elapsedTime = getCurrentTimeMillis() - startTime;
+        MethodEndLogInfo methodEndLogInfo = MethodEndLogInfo.of(pjp, elapsedTime, proceedReturn);
+        log.info(logMessageFormatter.toMethodEndLogMessage(methodEndLogInfo));
    }
-    endTime = getCurrentTimeMillis();
-
-    MethodEndLogInfo methodEndLogInfo = MethodEndLogInfo.of(pjp, endTime - startTime,
-        proceedReturn);
-    log.info(logMessageFormatter.toMethodEndLogMessage(methodEndLogInfo));
-
-    return proceedReturn;
}
🧹 Nitpick comments (4)
src/main/java/org/runimo/runimo/common/log/MethodLogAspect.java (4)

38-38: Enhance exception log message with more details

The current error log only includes the exception message, which might not provide enough information for debugging complex issues.

Improve error logging to include exception type and stack trace:

- log.error(logMessageFormatter.toMethodErrorLogMessage(ex));
+ log.error("METHOD_EXCEPTION in {}: {} - {}", 
+    pjp.getSignature().toShortString(), 
+    ex.getClass().getName(), 
+    ex.getMessage(), 
+    ex);  // Passing exception as last param includes stack trace

62-64: Consider more precise time measurement

For method timing, especially for operations that complete very quickly, using System.nanoTime() provides more precise measurements and is specifically designed for interval timing.

private long getCurrentTimeMillis() {
-    return System.currentTimeMillis();
+    return System.nanoTime() / 1_000_000; // Convert nanos to millis
}

52-58: Add null safety to authentication logic

The current code checks if authentication is null but not if the authentication name could be null.

Add null safety to the authentication handling:

Authentication authentication = SecurityContextHolder.getContext().getAuthentication();
if (authentication != null) {
-    methodStartLogInfo = MethodStartLogInfo.of(pjp, true, authentication.getName());
+    String username = authentication.getName();
+    methodStartLogInfo = MethodStartLogInfo.of(pjp, true, username != null ? username : "anonymous");
} else {
    methodStartLogInfo = MethodStartLogInfo.of(pjp, false, null);
}

15-21: Add Javadoc for the class explaining its purpose

Adding a class-level javadoc would help other developers understand the purpose and usage of this aspect.

+/**
+ * AOP aspect that provides method-level logging for classes or methods annotated with @ServiceLog.
+ * Logs method invocation starts, ends, execution time, and any exceptions thrown.
+ * Also captures authentication context when available.
+ */
@Aspect
@Slf4j
@RequiredArgsConstructor
@Component
public class MethodLogAspect {
📜 Review details

Configuration used: CodeRabbit UI
Review profile: CHILL
Plan: Pro

📥 Commits

Reviewing files that changed from the base of the PR and between d645292 and 2f01a02.

📒 Files selected for processing (1)
  • src/main/java/org/runimo/runimo/common/log/MethodLogAspect.java (1 hunks)
🧰 Additional context used
🧬 Code Graph Analysis (1)
src/main/java/org/runimo/runimo/common/log/MethodLogAspect.java (2)
src/main/java/org/runimo/runimo/common/log/HttpRequestLogAspect.java (1)
  • Aspect (20-46)
src/main/java/org/runimo/runimo/common/log/LogMessageFormatter.java (1)
  • Component (14-108)

@jeeheaG
Copy link
Contributor Author

jeeheaG commented Apr 25, 2025

로컬에선 pass 되는데 ci 환경에서만 테스트가 모두 JdbcSQLSyntaxErrorException 으로 fail 되네요.

RunimoApplicationTests > contextLoads() FAILED
    java.lang.IllegalStateException at DefaultCacheAwareContextLoaderDelegate.java:180
        Caused by: org.springframework.beans.factory.UnsatisfiedDependencyException at AutowiredAnnotationBeanPostProcessor.java:788
            Caused by: org.springframework.beans.factory.BeanCreationException at AbstractAutowireCapableBeanFactory.java:1812
                Caused by: org.springframework.jdbc.datasource.init.ScriptStatementFailedException at ScriptUtils.java:282
                    Caused by: org.h2.jdbc.JdbcSQLSyntaxErrorException at DbException.java:514

yml, sql, entity 쪽 바꾼 게 없는데 뭘까요..

내일 밤 이후에 다시 찾아보겠습니다

@ekgns33 ekgns33 merged commit ca98b38 into main Apr 26, 2025
2 of 4 checks passed
@ekgns33 ekgns33 deleted the feat/logger branch April 26, 2025 02:04
@ekgns33
Copy link
Contributor

ekgns33 commented Apr 26, 2025

해당 PR시점의 data.sql 이 이후 스키마에서 변화함에 따라 CI가 실패하는 이슈가 있습니다. Merge하면서 해결될 것 같습니다~

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants