INTERNAL: Add operation status message to log when operation is not successful. #80

uhm0311 · 2024-06-05T02:01:28Z

🔗 Related Issue

Exception이 발생하진 않았으나 연산이 실패한 경우, OperationStatus를 확인하지 않으면 정확한 연산 실패 원인을 알 수 없다.

⌨️ What I did

Exception이 발생하진 않았으나 연산이 실패한 경우, OperationStatus를 워닝 로그로 출력합니다.
로그 레벨은 임의로 우선 워닝으로 설정했으나 더 적합하다고 생각하는 로그 레벨이 있다면 의견 주세요.

oliviarla

리뷰 완료입니다.

src/main/java/com/navercorp/arcus/spring/cache/ArcusCache.java

jhpark816

리뷰 완료

jhpark816 · 2024-06-10T00:50:55Z

src/main/java/com/navercorp/arcus/spring/cache/ArcusCache.java

+      OperationStatus status = future.getStatus();
+      if (!status.isSuccess()) {
+        logger.warn("failed to getValue a key: {}, status: {}, statusCode: {}",
+                arcusKey, status.getMessage(), status.getStatusCode());


단순히 key miss인 경우는 제외해야 할 것 같습니다.
그 외에는 어떤 OperationStatus가 있나요?

다른 연산들도 그 semantic에 따라
필요한 경우만 logging하여야 할 것 같습니다.

get은 항상 END로 끝나므로 key miss인 경우에 단순히 값만 없고 OperationStatus는 success 입니다.

uhm0311 · 2024-06-10T02:35:24Z

OperationStatus의 StatusCode에 따라 로그 레벨을 다르게 출력하도록 수정했습니다.

oliviarla · 2024-06-10T02:57:16Z

@uhm0311
java client API의 add, delete, set, asyncGet, flush에서 각각 성공하지 않았을 때 발생하는 상태 코드를 간단히 정리해주실 수 있나요?

발생 가능한 상태 코드를 살펴보고 특정 조건일 때에만 로깅을 남기는 것이 어떤가요?
예를 들어 java client의 add 메서드는 StatusCode.ERR_NOT_STORED 외에 발생 가능한 상태 코드가 없어보이는데, 사용자가 putIfAbsent를 호출하였다면 의도를 충분히 이해하고 있을 것이고 따라서 logging 하지 않아도 되는 정보라는 생각이 듭니다.

다양한 케이스를 고려하다보니 현재 코드는 간단한 로깅 작업임에도 불구하고 한눈에 보고 이해하기 어렵습니다. 다만 하위 호환성으로 받아들이는 상태 코드가 버전마다 다르다면 어쩔 수 없이 이 형태로 구현해야 할 것 같긴 합니다.

uhm0311 · 2024-06-10T03:06:58Z

서버 응답 모음

CLIENT_ERROR, SERVER_ERROR와 같은 에러는 없는 경우의 응답입니다.

get

키 존재 여부에 관계 없이 END, 성공

add

STORED, 값 저장 완료, 성공
NOT_STORED, 키가 이미 존재하는 경우, 실패

delete

DELETED, 값 제거 완료, 성공
NOT_FOUND, 키가 존재하지 않는 경우, 실패

flush

OK, Prefix가 존재하는 경우, 성공
NOT_FOUND, Prefix가 존재하지 않는 경우, 성공

무조건 로깅하는 이유

evict 실패 원인에 대한 문의가 있었기 때문에 로그를 통해 NOT_FOUND이면 캐시 키가 없다는 것을 알리기 위함입니다.

jhpark816 · 2024-06-11T02:35:54Z

@oliviarla @brido4125
이 작업이 우선적으로 처리되어야 할 것 같습니다.

brido4125

테스트 코드에서 임의로 timeout 발생 시킨 뒤 적절한 로그가 발생하는지
junit4에서 검증 가능하다면 하는게 좋을 것 같습니다.

src/main/java/com/navercorp/arcus/spring/cache/ArcusCache.java

uhm0311 · 2024-06-11T09:34:48Z

@brido4125

Mockito와 같은 라이브러리들의 버전 문제인지는 모르겠지만 TestLogger 클래스 없이는 로그 메세지를 검증할 좋은 방법이 없어서 로그 메세지를 출력하지 않고 메모리에 저장해두는 TestLogger 클래스를 추가했습니다.

oliviarla · 2024-06-11T11:16:25Z

저는 단순한 로깅 기능에 테스트코드까지 추가하는게 의미가 있는지 잘 모르겠는데, @uhm0311 님은 테스트코드가 필요하다고 보시나요?

jhpark816

리뷰 완료

jhpark816 · 2024-06-12T00:43:17Z

src/main/java/com/navercorp/arcus/spring/cache/ArcusCache.java

+      if (!status.isSuccess()) {
+        logOperationStatus("getValue", "key", arcusKey, status, false);
+      }
+    } else {


아래 형태의 코드가 읽기 좋습니다.

value = future.get(timeoutMilliSeconds, TimeUnit.MILLISECONDS); if (value != null) { logger.debug("arcus cache hit for {}", arcusKey); if (arcusFrontCache != null) { arcusFrontCache.set(arcusKey, value, frontExpireSeconds); } } else { logger.debug("arcus cache miss for {}", arcusKey); if (!future.getStatus().isSuccess()) { // which error ?? OperationStatus status = future.getStatus(); logger.info("failed to get a key: {}, status: {}", arcusKey, status.getMessage()); } }

위의 else에서 future.getStatus().isSuccess() == false 경우는 어떤 경우가 있나요?

Exceptional한 상황이 아니면 없습니다.
따라서 CLIENT_ERROR, SERVER_ERROR, CANCELLED를 포함하는 모든 실패 상황을 로깅합니다.

jhpark816 · 2024-06-12T00:51:58Z

src/main/java/com/navercorp/arcus/spring/cache/ArcusCache.java

+        OperationStatus status = future.getStatus();
+        boolean debugLevel = status.getStatusCode() == StatusCode.ERR_NOT_FOUND;
+
+        logOperationStatus("evict", "key", arcusKey, status, debugLevel);


기존에 아래와 같이 로깅하고 있었네요.
이 경우에는 status 정보만 추가하면 될 것 같습니다.

logger.info("failed to evict a key: {}", arcusKey);

jhpark816 · 2024-06-12T00:53:13Z

src/main/java/com/navercorp/arcus/spring/cache/ArcusCache.java

+        OperationStatus status = future.getStatus();
+        boolean debugLevel = status.getStatusCode() == StatusCode.ERR_NOT_FOUND;
+
+        logOperationStatus("clear", "prefix", arcusPrefix, status, debugLevel);


여기도 기존 info 로그에 status.getMessage() 정보만 추가하면 될 것 같습니다.

jhpark816 · 2024-06-12T00:55:14Z

src/main/java/com/navercorp/arcus/spring/cache/ArcusCache.java

      if (!success) {
-        logger.info("failed to put a key: {}", arcusKey);
+        OperationStatus status = future.getStatus();
+        logOperationStatus("put", "key", arcusKey, status, false);


기존 info 로그 메세지에 status 정보만 추가합시다.

status Code와 status Message 중에서 하나만 출력하면 될 것 같고,
어떤 내용이 나은 지는 확인해 주세요.

jhpark816 · 2024-06-12T01:11:34Z

src/main/java/com/navercorp/arcus/spring/cache/ArcusCache.java


-      if (added && arcusFrontCache != null) {
+        logOperationStatus("putIfAbsent", "key", arcusKey, status, debugLevel);
+      } else if (arcusFrontCache != null) {


다른 연산인 delete, flush 외에도 set 연산에서도 실패하면 기존에 info logging하고 있었습니다.
add 연산에서도 실패하면 동일하게 info logging 하면 될 것 같습니다.

boolean success = future.get(timeoutMilliSeconds, TimeUnit.MILLISECONDS); if (success) { if (arcusFrontCache != null) { arcusFrontCache.set(arcusKey, value, frontExpireSeconds); } } else { OperationStatus status = future.getStatus(); logger.info(....); }

jhpark816 · 2024-06-12T01:14:12Z

src/test/java/com/navercorp/arcus/spring/cache/ArcusCacheTest.java

+
+  private static final OperationStatus NOT_STORED = new OperationStatus(false, "NOT_STORED", StatusCode.ERR_NOT_STORED);
+  private static final OperationStatus NOT_FOUND = new OperationStatus(false, "NOT_FOUND", StatusCode.ERR_NOT_FOUND);
+  private static final OperationStatus UNDEFINED = new OperationStatus(false, "UNDEFINED", StatusCode.UNDEFINED);


테스트 코드는 살펴보지 않았지만,
반드시 필요한 테스트만 추가하는 것이 좋습니다.

jhpark816 · 2024-06-12T01:18:03Z

@oliviarla
내 리뷰 의견을 보고 다른 의견이 있다면 알려주세요.

uhm0311 · 2024-06-12T06:36:40Z

@jhpark816

반영했습니다.

jhpark816 · 2024-06-12T06:41:47Z

@oliviarla @brido4125 리뷰 바랍니다.

…uccessful.

uhm0311 requested review from oliviarla and brido4125 June 5, 2024 02:01

uhm0311 force-pushed the uhm0311/develop branch from ff25eae to c756628 Compare June 5, 2024 02:12

oliviarla reviewed Jun 5, 2024

View reviewed changes

uhm0311 force-pushed the uhm0311/develop branch from c756628 to 29577d7 Compare June 5, 2024 02:58

uhm0311 mentioned this pull request Jun 7, 2024

INTERNAL: Remove value type in put log message. #81

Merged

uhm0311 force-pushed the uhm0311/develop branch from 29577d7 to a197850 Compare June 7, 2024 06:12

oliviarla reviewed Jun 7, 2024

View reviewed changes

src/main/java/com/navercorp/arcus/spring/cache/ArcusCache.java Outdated Show resolved Hide resolved

src/main/java/com/navercorp/arcus/spring/cache/ArcusCache.java Outdated Show resolved Hide resolved

jhpark816 reviewed Jun 10, 2024

View reviewed changes

uhm0311 force-pushed the uhm0311/develop branch from a197850 to df06aa0 Compare June 10, 2024 02:33

uhm0311 requested review from oliviarla and jhpark816 June 10, 2024 02:35

brido4125 reviewed Jun 11, 2024

View reviewed changes

src/main/java/com/navercorp/arcus/spring/cache/ArcusCache.java Outdated Show resolved Hide resolved

uhm0311 force-pushed the uhm0311/develop branch from df06aa0 to a21e800 Compare June 11, 2024 09:32

uhm0311 requested a review from brido4125 June 11, 2024 09:32

jhpark816 reviewed Jun 12, 2024

View reviewed changes

uhm0311 force-pushed the uhm0311/develop branch from a21e800 to 2169575 Compare June 12, 2024 06:31

uhm0311 marked this pull request as draft June 12, 2024 06:32

uhm0311 force-pushed the uhm0311/develop branch from 2169575 to 8e40b3c Compare June 12, 2024 06:34

uhm0311 changed the title ~~INTERNAL: Add warning log when OperationStatus.isSuccess() is false.~~ INTERNAL: Add operation status message to log when OperationStatus.isSuccess() is false. Jun 12, 2024

uhm0311 force-pushed the uhm0311/develop branch from 8e40b3c to 069ed26 Compare June 12, 2024 06:35

uhm0311 marked this pull request as ready for review June 12, 2024 06:36

uhm0311 requested a review from jhpark816 June 12, 2024 06:36

INTERNAL: Add operation status message to log when operation is not s…

037d81f

…uccessful.

uhm0311 changed the title ~~INTERNAL: Add operation status message to log when OperationStatus.isSuccess() is false.~~ INTERNAL: Add operation status message to log when operation is not successful. Jun 12, 2024

uhm0311 force-pushed the uhm0311/develop branch from 069ed26 to 037d81f Compare June 12, 2024 06:47

oliviarla approved these changes Jun 12, 2024

View reviewed changes

brido4125 approved these changes Jun 12, 2024

View reviewed changes

jhpark816 merged commit bc986f2 into naver:develop Jun 12, 2024
1 check passed

uhm0311 mentioned this pull request Jun 14, 2024

INTERNAL: Catch all kind of exception. #84

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

INTERNAL: Add operation status message to log when operation is not successful. #80

INTERNAL: Add operation status message to log when operation is not successful. #80

uhm0311 commented Jun 5, 2024 •

edited

Loading

oliviarla left a comment

jhpark816 left a comment

jhpark816 Jun 10, 2024

uhm0311 Jun 10, 2024

uhm0311 commented Jun 10, 2024

oliviarla commented Jun 10, 2024

uhm0311 commented Jun 10, 2024 •

edited

Loading

jhpark816 commented Jun 11, 2024

brido4125 left a comment

uhm0311 commented Jun 11, 2024

oliviarla commented Jun 11, 2024

jhpark816 left a comment

jhpark816 Jun 12, 2024

uhm0311 Jun 12, 2024 •

edited

Loading

jhpark816 Jun 12, 2024

jhpark816 Jun 12, 2024

jhpark816 Jun 12, 2024

jhpark816 Jun 12, 2024

jhpark816 Jun 12, 2024

jhpark816 Jun 12, 2024

jhpark816 commented Jun 12, 2024

uhm0311 commented Jun 12, 2024

jhpark816 commented Jun 12, 2024

INTERNAL: Add operation status message to log when operation is not successful. #80

INTERNAL: Add operation status message to log when operation is not successful. #80

Conversation

uhm0311 commented Jun 5, 2024 • edited Loading

🔗 Related Issue

⌨️ What I did

oliviarla left a comment

Choose a reason for hiding this comment

jhpark816 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

uhm0311 commented Jun 10, 2024

oliviarla commented Jun 10, 2024

uhm0311 commented Jun 10, 2024 • edited Loading

서버 응답 모음

get

add

delete

flush

무조건 로깅하는 이유

jhpark816 commented Jun 11, 2024

brido4125 left a comment

Choose a reason for hiding this comment

uhm0311 commented Jun 11, 2024

oliviarla commented Jun 11, 2024

jhpark816 left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

uhm0311 Jun 12, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jhpark816 commented Jun 12, 2024

uhm0311 commented Jun 12, 2024

jhpark816 commented Jun 12, 2024

uhm0311 commented Jun 5, 2024 •

edited

Loading

uhm0311 commented Jun 10, 2024 •

edited

Loading

uhm0311 Jun 12, 2024 •

edited

Loading