/
RequestTimeoutHandlingDirective.java
executable file
·160 lines (136 loc) · 7.73 KB
/
RequestTimeoutHandlingDirective.java
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
/*
* Copyright (c) 2017 Contributors to the Eclipse Foundation
*
* See the NOTICE file(s) distributed with this work for additional
* information regarding copyright ownership.
*
* This program and the accompanying materials are made available under the
* terms of the Eclipse Public License 2.0 which is available at
* http://www.eclipse.org/legal/epl-2.0
*
* SPDX-License-Identifier: EPL-2.0
*/
package org.eclipse.ditto.services.gateway.endpoints.directives;
import static akka.http.javadsl.server.Directives.extractRequestContext;
import static org.eclipse.ditto.services.gateway.endpoints.directives.SecurityResponseHeadersDirective.createSecurityResponseHeaders;
import static org.eclipse.ditto.services.gateway.endpoints.utils.DirectivesLoggingUtils.enhanceLogWithCorrelationId;
import static org.eclipse.ditto.services.gateway.endpoints.utils.HttpUtils.getRawRequestUri;
import java.time.Duration;
import java.util.function.Supplier;
import org.eclipse.ditto.model.base.exceptions.DittoRuntimeException;
import org.eclipse.ditto.model.base.headers.DittoHeaders;
import org.eclipse.ditto.services.gateway.starter.service.util.ConfigKeys;
import org.eclipse.ditto.services.utils.akka.LogUtil;
import org.eclipse.ditto.services.utils.metrics.instruments.timer.StartedTimer;
import org.eclipse.ditto.services.utils.metrics.instruments.timer.StoppedTimer;
import org.eclipse.ditto.services.utils.tracing.TraceUtils;
import org.eclipse.ditto.services.utils.tracing.TracingTags;
import org.eclipse.ditto.signals.commands.base.exceptions.GatewayServiceUnavailableException;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import com.typesafe.config.Config;
import akka.http.javadsl.model.ContentTypes;
import akka.http.javadsl.model.HttpHeader;
import akka.http.javadsl.model.HttpRequest;
import akka.http.javadsl.model.HttpResponse;
import akka.http.javadsl.server.Directives;
import akka.http.javadsl.server.RequestContext;
import akka.http.javadsl.server.Route;
import akka.util.ByteString;
/**
* Custom Akka HTTP directive which handles a request timeout.
*/
public final class RequestTimeoutHandlingDirective {
private static final Logger LOGGER = LoggerFactory.getLogger(RequestTimeoutHandlingDirective.class);
private static final Duration SEARCH_WARN_TIMEOUT_MS = Duration.ofMillis(5_000);
private static final Duration HTTP_WARN_TIMEOUT_MS = Duration.ofMillis(1_000);
private RequestTimeoutHandlingDirective() {
throw new AssertionError();
}
/**
* Handles a request timeout.
*
* @param correlationId the correlation ID which will be added to the log.
* @param inner the inner Route to wrap with the response headers.
* @return the new Route wrapping {@code inner} with the response headers.
*/
public static Route handleRequestTimeout(final CharSequence correlationId, final Supplier<Route> inner) {
return Directives.extractActorSystem(actorSystem -> {
final Config config = actorSystem.settings().config();
return extractRequestContext(requestContext ->
enhanceLogWithCorrelationId(correlationId, () -> {
final StartedTimer timer =
TraceUtils.newHttpRoundTripTimer(requestContext.getRequest()).build();
LOGGER.debug("Started mutable timer <{}>.", timer);
final Supplier<Route> innerWithTimer = () -> Directives.mapResponse(response -> {
final int statusCode = response.status().intValue();
if (timer.isRunning()) {
final StoppedTimer stoppedTimer = enhanceLogWithCorrelationId(correlationId, () -> {
final StoppedTimer result = timer.tag(TracingTags.STATUS_CODE, statusCode).stop();
LOGGER.debug("Finished timer <{}> with status <{}>.", timer, statusCode);
return result;
});
checkDurationWarning(stoppedTimer, correlationId);
}
return response;
}, inner);
return Directives.withRequestTimeoutResponse(request ->
doHandleRequestTimeout(correlationId, config, requestContext, timer),
innerWithTimer);
})
);
});
}
private static void checkDurationWarning(final StoppedTimer mutableTimer, final CharSequence correlationId) {
final Duration duration = mutableTimer.getDuration();
final String requestPath = mutableTimer.getTag(TracingTags.REQUEST_PATH);
LogUtil.logWithCorrelationId(LOGGER, correlationId, logger -> {
if (requestPath != null && requestPath.contains("/search/things") &&
SEARCH_WARN_TIMEOUT_MS.minus(duration).isNegative()) {
logger.warn("Encountered slow search which took over {} ms: <{}> ms!",
SEARCH_WARN_TIMEOUT_MS.toMillis(), duration.toMillis());
} else if (HTTP_WARN_TIMEOUT_MS.minus(duration).isNegative()) {
logger.warn("Encountered slow HTTP request which took over {} ms: {} ms!",
HTTP_WARN_TIMEOUT_MS.toMillis(), duration.toMillis());
}
});
}
private static HttpResponse doHandleRequestTimeout(final CharSequence correlationId,
final Config config,
final RequestContext requestContext,
final StartedTimer timer) {
final Duration duration = config.getDuration(ConfigKeys.AKKA_HTTP_SERVER_REQUEST_TIMEOUT);
final DittoRuntimeException cre = GatewayServiceUnavailableException.newBuilder()
.dittoHeaders(DittoHeaders.newBuilder()
.correlationId(correlationId)
.build())
.build();
final HttpRequest request = requestContext.getRequest();
/* We have to log and create a trace here because the RequestResultLoggingDirective won't be called by akka
in case of a timeout */
final int statusCode = cre.getStatusCode().toInt();
LogUtil.logWithCorrelationId(LOGGER, correlationId, logger -> {
final String requestMethod = request.method().name();
final String requestUri = request.getUri().toRelative().toString();
logger.warn("Request <{} {}> timed out after <{}>!", requestMethod, requestUri, duration);
logger.info("StatusCode of request <{} {}> was <{}>.", requestMethod, requestUri, statusCode);
final String rawRequestUri = getRawRequestUri(request);
logger.debug("Raw request URI was <{}>.", rawRequestUri);
if (timer.isRunning()) {
timer.tag(TracingTags.STATUS_CODE, statusCode)
.stop();
logger.debug("Finished mutable timer <{}> after a request timeout with status <{}>", timer, statusCode);
} else {
logger.warn("Wanted to stop() timer which was already stopped indicating that a requestTimeout" +
" was detected where it should not have been");
}
});
/* We have to add security response headers explicitly here because SecurityResponseHeadersDirective won't be
called by akka in case of a timeout */
final Iterable<HttpHeader> securityResponseHeaders = createSecurityResponseHeaders(config);
return HttpResponse.create()
.withStatus(statusCode)
.withEntity(ContentTypes.APPLICATION_JSON, ByteString.fromString(cre.toJsonString()))
.addHeaders(securityResponseHeaders);
}
}