Skip to content

Commit d068172

Browse files
ikhoonikhoon
authored
Introduce RequestLogListener (#6543)
Motivation: A single `RequestLogProperty` can be received through `RequestLog.whenAvailable()`, but it is not straightforward to receive all events published by `RequestLog` using `.whenAvailable()`. To address the limitation, I propose introducing an interface that listens to all events by adding it to `RequestLog`. This will also simplify the integration of other implementations used for collecting metrics. Related: #6502 Modifications: - Introduced `RequestLogListener` API that can be attached to `RequestLog`. - `RequestLogAccess.addListener()` API was added and `DefaultRequestLog` implemented it. - The listener will be notified whenever a new property is set to `RequestLog`. If some properties have already been set, it will notified of them immediately. - Add `REQUEST_COMPLETE`, `RESPONSE_COMPLETE` and `ALL_COMPLETE` to `RequestLogProperty`. - Previously, there were APIs such as `whenRequestComplete()` and `whenComplete()` that computed and signaled request or response completion and but no explicit properties exist for them. `RequestLogProperty` should represent all states in `RequestLogListener`, I added the new completion properties. - Simplified child log propagation in `DefaultRequestLog` and the `Observation{Service,Client}` implementations by using `RequestLogListener`. Result: You can now use `RequestLogListener` to observe all `RequestLog` events.
1 parent fe78a35 commit d068172

File tree

10 files changed

+715
-262
lines changed

10 files changed

+715
-262
lines changed

‎core/src/main/java/com/linecorp/armeria/client/observation/ObservationClient.java‎

Lines changed: 21 additions & 20 deletions
Original file line numberDiff line numberDiff line change
@@ -29,7 +29,6 @@
2929
import com.linecorp.armeria.common.RequestHeadersBuilder;
3030
import com.linecorp.armeria.common.annotation.Nullable;
3131
import com.linecorp.armeria.common.annotation.UnstableApi;
32-
import com.linecorp.armeria.common.logging.RequestLogProperty;
3332
import com.linecorp.armeria.internal.common.RequestContextExtension;
3433
import com.linecorp.armeria.server.observation.ObservationService;
3534

@@ -138,24 +137,26 @@ public HttpResponse execute(ClientRequestContext ctx, HttpRequest req) throws Ex
138137
private static void enrichObservation(ClientRequestContext ctx,
139138
ClientObservationContext clientObservationContext,
140139
Observation observation) {
141-
ctx.log()
142-
.whenAvailable(RequestLogProperty.REQUEST_FIRST_BYTES_TRANSFERRED_TIME)
143-
.thenAccept(requestLog -> observation.event(Events.WIRE_SEND));
144-
145-
ctx.log()
146-
.whenAvailable(RequestLogProperty.RESPONSE_FIRST_BYTES_TRANSFERRED_TIME)
147-
.thenAccept(requestLog -> {
148-
if (requestLog.responseFirstBytesTransferredTimeNanos() != null) {
149-
observation.event(Events.WIRE_RECEIVE);
150-
}
151-
});
152-
153-
ctx.log().whenComplete()
154-
.thenAccept(requestLog -> {
155-
// TODO: ClientConnectionTimings - there is no way to record events
156-
// with a specific timestamp for an observation
157-
clientObservationContext.setResponse(requestLog);
158-
observation.stop();
159-
});
140+
ctx.log().addListener((property, log) -> {
141+
switch (property) {
142+
case REQUEST_FIRST_BYTES_TRANSFERRED_TIME:
143+
observation.event(Events.WIRE_SEND);
144+
break;
145+
case RESPONSE_FIRST_BYTES_TRANSFERRED_TIME:
146+
if (log.responseFirstBytesTransferredTimeNanos() != null) {
147+
observation.event(Events.WIRE_RECEIVE);
148+
}
149+
break;
150+
case ALL_COMPLETE:
151+
// TODO: ClientConnectionTimings - there is no way to record events
152+
// with a specific timestamp for an observation
153+
clientObservationContext.setResponse(log);
154+
observation.stop();
155+
break;
156+
default:
157+
// Do nothing.
158+
break;
159+
}
160+
});
160161
}
161162
}

‎core/src/main/java/com/linecorp/armeria/common/logging/DefaultRequestLog.java‎

Lines changed: 270 additions & 189 deletions
Large diffs are not rendered by default.

‎core/src/main/java/com/linecorp/armeria/common/logging/IdempotentRequestLogListener.java‎

Lines changed: 51 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,51 @@
1+
/*
2+
* Copyright 2025 LY Corporation
3+
*
4+
* LY Corporation licenses this file to you under the Apache License,
5+
* version 2.0 (the "License"); you may not use this file except in compliance
6+
* with the License. You may obtain a copy of the License at:
7+
*
8+
* https://www.apache.org/licenses/LICENSE-2.0
9+
*
10+
* Unless required by applicable law or agreed to in writing, software
11+
* distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
12+
* WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
13+
* License for the specific language governing permissions and limitations
14+
* under the License.
15+
*/
16+
17+
package com.linecorp.armeria.common.logging;
18+
19+
import static com.linecorp.armeria.common.logging.DefaultRequestLog.hasInterestedFlags;
20+
21+
import com.linecorp.armeria.internal.common.util.ReentrantShortLock;
22+
23+
/**
24+
* A {@link RequestLogListener} that delivers each event only once to the delegate listener.
25+
*/
26+
final class IdempotentRequestLogListener extends ReentrantShortLock implements RequestLogListener {
27+
28+
private static final long serialVersionUID = -573237359665852226L;
29+
30+
private final RequestLogListener delegate;
31+
private int notifiedFlags;
32+
33+
IdempotentRequestLogListener(RequestLogListener delegate) {
34+
this.delegate = delegate;
35+
}
36+
37+
@Override
38+
public void onEvent(RequestLogProperty property, RequestLog log) {
39+
lock();
40+
try {
41+
if (hasInterestedFlags(notifiedFlags, property)) {
42+
// Already notified.
43+
return;
44+
}
45+
notifiedFlags |= property.flag();
46+
} finally {
47+
unlock();
48+
}
49+
delegate.onEvent(property, log);
50+
}
51+
}

‎core/src/main/java/com/linecorp/armeria/common/logging/RequestLogAccess.java‎

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -230,6 +230,13 @@ public interface RequestLogAccess {
230230
*/
231231
RequestLog ensureAvailable(Iterable<RequestLogProperty> properties);
232232

233+
/**
234+
* Adds the specified {@link RequestLogListener} which will be invoked when a {@link RequestLogProperty}
235+
* becomes available.
236+
*/
237+
@UnstableApi
238+
void addListener(RequestLogListener listener);
239+
233240
/**
234241
* Returns the {@link RequestLog} for the {@link Request}, where all properties may not be available yet.
235242
* Note that this method is potentially unsafe; an attempt to access an unavailable property will trigger

‎core/src/main/java/com/linecorp/armeria/common/logging/RequestLogListener.java‎

Lines changed: 39 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,39 @@
1+
/*
2+
* Copyright 2025 LY Corporation
3+
*
4+
* LY Corporation licenses this file to you under the Apache License,
5+
* version 2.0 (the "License"); you may not use this file except in compliance
6+
* with the License. You may obtain a copy of the License at:
7+
*
8+
* https://www.apache.org/licenses/LICENSE-2.0
9+
*
10+
* Unless required by applicable law or agreed to in writing, software
11+
* distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
12+
* WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
13+
* License for the specific language governing permissions and limitations
14+
* under the License.
15+
*/
16+
17+
package com.linecorp.armeria.common.logging;
18+
19+
import com.linecorp.armeria.common.annotation.UnstableApi;
20+
21+
/**
22+
* A listener that listens to all events of a {@link RequestLog}.
23+
*
24+
* <p>If a {@link RequestLogProperty} was completed before adding this listener to the {@link RequestLog},
25+
* the {@link #onEvent(RequestLogProperty, RequestLog)} method will be invoked immediately with the already
26+
* completed property upon adding the listener.
27+
*
28+
* <p>Note that this listener may be invoked in the I/O worker thread so make sure to offload any blocking
29+
* operations to a separate thread pool.
30+
*/
31+
@UnstableApi
32+
@FunctionalInterface
33+
public interface RequestLogListener {
34+
35+
/**
36+
* Invoked when the specified {@link RequestLogProperty} is completed.
37+
*/
38+
void onEvent(RequestLogProperty property, RequestLog log);
39+
}

‎core/src/main/java/com/linecorp/armeria/common/logging/RequestLogProperty.java‎

Lines changed: 42 additions & 25 deletions
Original file line numberDiff line numberDiff line change
@@ -37,16 +37,6 @@ public enum RequestLogProperty {
3737
*/
3838
REQUEST_START_TIME(true),
3939

40-
/**
41-
* {@link RequestLog#requestEndTimeNanos()}, {@link RequestLog#requestDurationNanos()}.
42-
*/
43-
REQUEST_END_TIME(true),
44-
45-
/**
46-
* {@link RequestLog#requestFirstBytesTransferredTimeNanos()}.
47-
*/
48-
REQUEST_FIRST_BYTES_TRANSFERRED_TIME(true),
49-
5040
/**
5141
* {@link RequestLog#channel()}, {@link RequestLog#sessionProtocol()}, {@link RequestLog#sslSession()},
5242
* {@link RequestLog#connectionTimings()}.
@@ -73,6 +63,11 @@ public enum RequestLogProperty {
7363
*/
7464
REQUEST_HEADERS(true),
7565

66+
/**
67+
* {@link RequestLog#requestFirstBytesTransferredTimeNanos()}.
68+
*/
69+
REQUEST_FIRST_BYTES_TRANSFERRED_TIME(true),
70+
7671
/**
7772
* {@link RequestLog#requestContent()}, {@link RequestLog#rawRequestContent()}.
7873
*/
@@ -98,30 +93,40 @@ public enum RequestLogProperty {
9893
*/
9994
REQUEST_CAUSE(true),
10095

96+
/**
97+
* {@link RequestLog#requestEndTimeNanos()}, {@link RequestLog#requestDurationNanos()}.
98+
*/
99+
REQUEST_END_TIME(true),
100+
101+
/**
102+
* Indicates that the request is complete and all request properties are available.
103+
*/
104+
REQUEST_COMPLETE(true),
105+
101106
// Response properties
102107

108+
/**
109+
* {@link RequestLog#responseCause()}.
110+
*/
111+
// Notify the response cause before other response properties to propagate the cause as early as possible.
112+
RESPONSE_CAUSE(false),
113+
103114
/**
104115
* {@link RequestLog#responseStartTimeMicros()}, {@link RequestLog#responseStartTimeMillis()},
105116
* {@link RequestLog#responseStartTimeNanos()}.
106117
*/
107118
RESPONSE_START_TIME(false),
108119

109120
/**
110-
* {@link RequestLog#responseEndTimeNanos()}, {@link RequestLog#responseDurationNanos()},
111-
* {@link RequestLog#totalDurationNanos()}.
121+
* {@link RequestLog#responseHeaders()}.
112122
*/
113-
RESPONSE_END_TIME(false),
123+
RESPONSE_HEADERS(false),
114124

115125
/**
116126
* {@link RequestLog#responseFirstBytesTransferredTimeNanos()}.
117127
*/
118128
RESPONSE_FIRST_BYTES_TRANSFERRED_TIME(false),
119129

120-
/**
121-
* {@link RequestLog#responseHeaders()}.
122-
*/
123-
RESPONSE_HEADERS(false),
124-
125130
/**
126131
* {@link RequestLog#responseContent()}.
127132
*/
@@ -132,20 +137,32 @@ public enum RequestLogProperty {
132137
*/
133138
RESPONSE_CONTENT_PREVIEW(false),
134139

140+
/**
141+
* {@link RequestLog#responseLength()}.
142+
*/
143+
// TODO(ikhoon): Check if this property is actually used anywhere.
144+
RESPONSE_LENGTH(false),
145+
135146
/**
136147
* {@link RequestLog#responseTrailers()}.
137148
*/
138149
RESPONSE_TRAILERS(false),
139150

140151
/**
141-
* {@link RequestLog#responseLength()}.
152+
* {@link RequestLog#responseEndTimeNanos()}, {@link RequestLog#responseDurationNanos()},
153+
* {@link RequestLog#totalDurationNanos()}.
142154
*/
143-
RESPONSE_LENGTH(false),
155+
RESPONSE_END_TIME(false),
144156

145157
/**
146-
* {@link RequestLog#responseCause()}.
158+
* Indicates that the response is complete and all response properties are available.
159+
*/
160+
RESPONSE_COMPLETE(false),
161+
162+
/**
163+
* Indicates that both the request and response are complete and all properties are available.
147164
*/
148-
RESPONSE_CAUSE(false);
165+
ALL_COMPLETE(false);
149166

150167
private static final Set<RequestLogProperty> REQUEST_PROPERTIES =
151168
Arrays.stream(values())
@@ -154,7 +171,7 @@ public enum RequestLogProperty {
154171

155172
private static final Set<RequestLogProperty> RESPONSE_PROPERTIES =
156173
Arrays.stream(values())
157-
.filter(p -> !p.isRequestProperty)
174+
.filter(p -> !p.isRequestProperty && p != ALL_COMPLETE)
158175
.collect(Sets.toImmutableEnumSet());
159176

160177
private static final Set<RequestLogProperty> ALL_PROPERTIES =
@@ -165,8 +182,8 @@ public enum RequestLogProperty {
165182
static final int FLAGS_ALL_COMPLETE;
166183

167184
static {
168-
FLAGS_REQUEST_COMPLETE = flags(REQUEST_PROPERTIES);
169-
FLAGS_RESPONSE_COMPLETE = flags(RESPONSE_PROPERTIES);
185+
FLAGS_REQUEST_COMPLETE = flags(REQUEST_PROPERTIES) & ~REQUEST_COMPLETE.flag();
186+
FLAGS_RESPONSE_COMPLETE = flags(RESPONSE_PROPERTIES) & ~RESPONSE_COMPLETE.flag();
170187
FLAGS_ALL_COMPLETE = FLAGS_REQUEST_COMPLETE | FLAGS_RESPONSE_COMPLETE;
171188
}
172189

‎core/src/main/java/com/linecorp/armeria/server/observation/ObservationService.java‎

Lines changed: 19 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -26,7 +26,6 @@
2626
import com.linecorp.armeria.common.HttpResponse;
2727
import com.linecorp.armeria.common.annotation.Nullable;
2828
import com.linecorp.armeria.common.annotation.UnstableApi;
29-
import com.linecorp.armeria.common.logging.RequestLogProperty;
3029
import com.linecorp.armeria.internal.common.RequestContextExtension;
3130
import com.linecorp.armeria.server.HttpService;
3231
import com.linecorp.armeria.server.ServiceRequestContext;
@@ -140,23 +139,24 @@ public HttpResponse serve(ServiceRequestContext ctx, HttpRequest req) throws Exc
140139
private static void enrichObservation(ServiceRequestContext ctx,
141140
ServiceObservationContext serviceObservationContext,
142141
Observation observation) {
143-
ctx.log()
144-
.whenAvailable(RequestLogProperty.REQUEST_FIRST_BYTES_TRANSFERRED_TIME)
145-
.thenAccept(requestLog -> observation.event(
146-
HttpServiceObservationDocumentation.Events.WIRE_RECEIVE));
147-
148-
ctx.log()
149-
.whenAvailable(RequestLogProperty.RESPONSE_FIRST_BYTES_TRANSFERRED_TIME)
150-
.thenAccept(requestLog -> {
151-
if (requestLog.responseFirstBytesTransferredTimeNanos() != null) {
152-
observation.event(HttpServiceObservationDocumentation.Events.WIRE_SEND);
153-
}
154-
});
155-
156-
ctx.log().whenComplete()
157-
.thenAccept(requestLog -> {
158-
serviceObservationContext.setResponse(requestLog);
159-
observation.stop();
160-
});
142+
ctx.log().addListener((property, log) -> {
143+
switch (property) {
144+
case REQUEST_FIRST_BYTES_TRANSFERRED_TIME:
145+
observation.event(HttpServiceObservationDocumentation.Events.WIRE_RECEIVE);
146+
break;
147+
case RESPONSE_FIRST_BYTES_TRANSFERRED_TIME:
148+
if (log.responseFirstBytesTransferredTimeNanos() != null) {
149+
observation.event(HttpServiceObservationDocumentation.Events.WIRE_SEND);
150+
}
151+
break;
152+
case ALL_COMPLETE:
153+
serviceObservationContext.setResponse(log);
154+
observation.stop();
155+
break;
156+
default:
157+
// Do nothing.
158+
break;
159+
}
160+
});
161161
}
162162
}

‎core/src/test/java/com/linecorp/armeria/common/logging/DefaultRequestLogTest.java‎

Lines changed: 0 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -31,7 +31,6 @@
3131
import java.util.concurrent.ExecutorService;
3232
import java.util.concurrent.Executors;
3333
import java.util.concurrent.atomic.AtomicInteger;
34-
import java.util.function.BiFunction;
3534

3635
import org.junit.jupiter.api.BeforeEach;
3736
import org.junit.jupiter.api.Test;
@@ -66,13 +65,6 @@
6665

6766
class DefaultRequestLogTest {
6867

69-
private static final BiFunction<RequestContext, HttpHeaders, String> headersSanitizer =
70-
(ctx, headers) -> "sanitized_headers";
71-
private static final BiFunction<RequestContext, Object, String> contentSanitizer =
72-
(ctx, content) -> "sanitized_content";
73-
private static final BiFunction<RequestContext, HttpHeaders, String> trailersSanitizer =
74-
(ctx, trailers) -> "sanitized_trailers";
75-
7668
@Mock
7769
private RequestContext ctx;
7870

@@ -188,7 +180,6 @@ void rpcFailure_responseContentWithCause() {
188180
@ValueSource(booleans = {true, false})
189181
void addChild(boolean isResponseEndingWithFirstChild) {
190182
when(ctx.method()).thenReturn(HttpMethod.GET);
191-
when(ctx.eventLoop()).thenReturn(ContextAwareEventLoop.of(ctx, ImmediateEventLoop.INSTANCE));
192183
final DefaultRequestLog firstChild = new DefaultRequestLog(ctx);
193184
final DefaultRequestLog lastChild = new DefaultRequestLog(ctx);
194185
log.addChild(firstChild);

0 commit comments

Comments
 (0)