Do not swallow server errors of `TransientService` #3559

hexoul · 2021-05-13T01:11:09Z

Motivation:

Should not swallow errors of TransientService #3551 Should not swallow server errors of TransientService

Modifications:

Log response in case of server error regardless of TransientServiceOption.
Modify verifications of HealthCheckServiceTest and PrometheusExpositionServiceTest as they are TransientServices.

Result:

Leave a log for a failed request(5xx Server Error) even though the request is served by TransientService.
Close Should not swallow errors of TransientService #3551

codecov · 2021-05-13T02:07:49Z

Codecov Report

Merging #3559 (ae031ce) into master (161f082) will increase coverage by 0.06%.
The diff coverage is 100.00%.

❗ Current head ae031ce differs from pull request most recent head 0c261de. Consider uploading reports for the commit 0c261de to get more accurate results

@@             Coverage Diff              @@
##             master    #3559      +/-   ##
============================================
+ Coverage     73.85%   73.91%   +0.06%     
- Complexity    14260    14277      +17     
============================================
  Files          1254     1254              
  Lines         54447    54466      +19     
  Branches       6951     6954       +3     
============================================
+ Hits          40213    40261      +48     
+ Misses        10688    10664      -24     
+ Partials       3546     3541       -5

Impacted Files	Coverage Δ	Complexity Δ
...ria/internal/common/logging/LoggingDecorators.java	`92.59% <100.00%> (+2.11%)`	`21.00 <6.00> (+7.00)`
...inecorp/armeria/server/logging/LoggingService.java	`100.00% <100.00%> (ø)`	`6.00 <2.00> (-1.00)`
.../linecorp/armeria/client/DefaultClientFactory.java	`69.89% <0.00%> (-2.16%)`	`29.00% <0.00%> (-1.00%)`
...a/com/linecorp/armeria/common/util/Exceptions.java	`43.35% <0.00%> (-2.10%)`	`31.00% <0.00%> (-1.00%)`
...p/armeria/common/stream/AbstractStreamMessage.java	`81.73% <0.00%> (-1.93%)`	`15.00% <0.00%> (ø%)`
...armeria/internal/common/CancellationScheduler.java	`77.14% <0.00%> (-0.96%)`	`85.00% <0.00%> (-1.00%)`
.../linecorp/armeria/client/Http1ResponseDecoder.java	`66.66% <0.00%> (-0.61%)`	`44.00% <0.00%> (-1.00%)`
...inecorp/armeria/server/HttpResponseSubscriber.java	`78.94% <0.00%> (-0.36%)`	`68.00% <0.00%> (ø%)`
...corp/armeria/common/logging/DefaultRequestLog.java	`77.08% <0.00%> (+0.25%)`	`225.00% <0.00%> (+1.00%)`
...a/com/linecorp/armeria/client/HttpChannelPool.java	`78.68% <0.00%> (+0.27%)`	`67.00% <0.00%> (ø%)`
... and 11 more

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 384df27...0c261de. Read the comment docs.

ikhoon · 2021-05-13T01:44:35Z

core/src/main/java/com/linecorp/armeria/internal/common/logging/LoggingDecorators.java

+        if (!isTransientService) {
+            ctx.log().whenRequestComplete().thenAccept(requestLogger).exceptionally(e -> {
+                try (SafeCloseable ignored = ctx.push()) {
+                    logger.warn("{} Unexpected exception while logging request: ", ctx, e);
+                }
+                return null;
+            });
+        }


Don't we need to log an unexpected exception? Because it is unexpected. 😆
How about?

CompletableFuture<Void> requestCompletionFuture = ctx.log().whenRequestComplete(); if (!isTransientService) { requestCompletionFuture = requestCompletionFuture.thenAccept(requestLogger); } requestCompletionFuture.exceptionally(e -> { ... });

SGTM! Updated.

core/src/main/java/com/linecorp/armeria/internal/common/logging/LoggingDecorators.java

ikhoon · 2021-05-13T10:14:58Z

The following test looks flaky.
https://github.com/line/armeria/pull/3559/checks?check_run_id=2573691460#step:7:2150

HealthCheckServiceTest > waitWithWrongTimeout() FAILED
    Wanted but not invoked:
    logger.isDebugEnabled();
    -> at com.linecorp.armeria.server.healthcheck.HealthCheckServiceTest.waitWithWrongTimeout(HealthCheckServiceTest.java:327)
    Actually, there were zero interactions with this mock.
        at com.linecorp.armeria.server.healthcheck.HealthCheckServiceTest.waitWithWrongTimeout(HealthCheckServiceTest.java:327)

trustin · 2021-05-14T00:18:47Z

core/src/main/java/com/linecorp/armeria/internal/common/logging/LoggingDecorators.java

+            requestCompletionFuture.exceptionally(e -> {
+                try (SafeCloseable ignored = ctx.push()) {
+                    logger.warn("{} Unexpected exception while logging request: ", ctx, e);
+                }
+                return null;
+            });


This .exceptionally() call seems to be a duplicate. Could be simplified to:

final CompletableFuture<RequestOnlyLog> requestCompletionFuture; if (!isTransientService) { requestCompletionFuture = ctx.log().whenRequestComplete().thenAccept(...); } else { requestCompletionFuture = ctx.log().whenRequestComplete(); } requestCompletionFuture.exceptionally(...);

I also considered. But, even if whenRequestComplete() returns CompletableFuture<RequestOnlyLog>, whenRequestComplete().thenAccept(...) returns CompletableFuture<Void>. Meanwhile, raw use of CompletableFuture is ambiguous and using a template seems complicated. 🤔

Then, perhaps we can use thenApply? 😄

requestCompletionFuture = ctx.log().whenRequestComplete().thenApply(log -> { requestLogger.accept(log); return log; });

It's a bit verbose though. 😄

ikhoon

LGTM once Trustin's comment is addressed.
Thanks a lot! @hexoul

minwoox

Thanks a lot!

minwoox · 2021-05-14T03:27:21Z

core/src/main/java/com/linecorp/armeria/internal/common/logging/LoggingDecorators.java

+            requestCompletionFuture.exceptionally(e -> {
+                try (SafeCloseable ignored = ctx.push()) {
+                    logger.warn("{} Unexpected exception while logging request: ", ctx, e);
+                }
+                return null;
+            });


Then, perhaps we can use thenApply? 😄

requestCompletionFuture = ctx.log().whenRequestComplete().thenApply(log -> { requestLogger.accept(log); return log; });

It's a bit verbose though. 😄

hexoul · 2021-05-14T03:47:51Z

I like this way! #3559 (comment)

trustin

Thanks a lot!

hexoul requested review from ikhoon, minwoox and trustin as code owners May 13, 2021 01:11

ikhoon reviewed May 13, 2021

View reviewed changes

ikhoon added the defect label May 13, 2021

ikhoon added this to the 1.8.0 milestone May 13, 2021

hexoul force-pushed the do-not-swallow-5xx branch from 4f8bedc to f4de651 Compare May 13, 2021 12:27

trustin reviewed May 14, 2021

View reviewed changes

ikhoon approved these changes May 14, 2021

View reviewed changes

minwoox approved these changes May 14, 2021

View reviewed changes

hexoul added 7 commits May 14, 2021 13:15

Do not swallow server errors of TransientService

6d7190a

Fix style

85306b7

Address a comment by @ikhoon

c72fe19

Fix style

b4fccb2

Try to fix flaky test

105d326

Address comments

0e00417

Fix flaky test

0c261de

hexoul force-pushed the do-not-swallow-5xx branch from ae031ce to 0c261de Compare May 14, 2021 04:20

trustin approved these changes May 14, 2021

View reviewed changes

trustin merged commit 52675f7 into line:master May 14, 2021

hexoul deleted the do-not-swallow-5xx branch May 14, 2021 09:02

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Do not swallow server errors of `TransientService` #3559

Do not swallow server errors of `TransientService` #3559

hexoul commented May 13, 2021 •

edited

codecov bot commented May 13, 2021 •

edited

ikhoon May 13, 2021 •

edited

hexoul May 13, 2021

ikhoon commented May 13, 2021

trustin May 14, 2021

hexoul May 14, 2021

minwoox May 14, 2021

ikhoon left a comment

minwoox left a comment

minwoox May 14, 2021

hexoul commented May 14, 2021

trustin left a comment

Do not swallow server errors of TransientService #3559

Do not swallow server errors of TransientService #3559

Conversation

hexoul commented May 13, 2021 • edited

codecov bot commented May 13, 2021 • edited

Codecov Report

ikhoon May 13, 2021 • edited

Choose a reason for hiding this comment

hexoul May 13, 2021

Choose a reason for hiding this comment

ikhoon commented May 13, 2021

trustin May 14, 2021

Choose a reason for hiding this comment

hexoul May 14, 2021

Choose a reason for hiding this comment

minwoox May 14, 2021

Choose a reason for hiding this comment

ikhoon left a comment

Choose a reason for hiding this comment

minwoox left a comment

Choose a reason for hiding this comment

minwoox May 14, 2021

Choose a reason for hiding this comment

hexoul commented May 14, 2021

trustin left a comment

Choose a reason for hiding this comment

Do not swallow server errors of `TransientService` #3559

Do not swallow server errors of `TransientService` #3559

hexoul commented May 13, 2021 •

edited

codecov bot commented May 13, 2021 •

edited

ikhoon May 13, 2021 •

edited