diff --git a/gateleen-routing/README_routing.md b/gateleen-routing/README_routing.md index 7886d452..3a50831a 100644 --- a/gateleen-routing/README_routing.md +++ b/gateleen-routing/README_routing.md @@ -138,27 +138,43 @@ Each request header entry is validated in the format `: `, so you ar ## Micrometer metrics The routing feature is monitored with micrometer. The following metrics are available: -* gateleen_forwarded_requests_total +* gateleen_forwarded_total +* gateleen_forwarded_seconds +* gateleen_forwarded_seconds_max +* gateleen_forwarded_seconds_count +* gateleen_forwarded_seconds_sum Additional tags are provided to split the forward count into sub counts. | tag | description | |------------|-------------------------------------------------------------------------------------------------------------------| | metricName | The `metricName` property from the corresponding routing rule. With this, you are able to count requests per rule | -| type | Describes where the request was forwarded to. Possible values are `local`, `external` and `null` | +| type | Describes where the request was forwarded to. Possible values are `local`, `external` and `null` | +| quantile | Values of `0.75` and `0.95` for percentile durations of requests | Example metrics: ``` -# HELP gateleen_forwarded_requests_total Number of forwarded requests -# TYPE gateleen_forwarded_requests_total counter -gateleen_forwarded_requests_total{metricName="infotool_v1_informations",type="external",} 678765.0 -gateleen_forwarded_requests_total{metricName="amp-mutation",type="local",} 8875.0 -gateleen_forwarded_requests_total{metricName="edds-profile-houseservice-v2",type="storage",} 7777.0 -gateleen_forwarded_requests_total{metricName="password-reset",type="external",} 4.0 -gateleen_forwarded_requests_total{metricName="inventory-v1-session-start",type="external",} 0.0 -gateleen_forwarded_requests_total{metricName="edds-azb-catdir",type="null",} 5577.0 +# HELP gateleen_forwarded_total Amount of forwarded requests +# TYPE gateleen_forwarded_total counter +gateleen_forwarded_total{metricName="storage-resources",type="storage",} 67565.0 +gateleen_forwarded_total{metricName="infotool_v1_informations",type="external",} 655.0 +gateleen_forwarded_total{metricName="infotool-v1",type="storage",} 4320.0 +# HELP gateleen_forwarded_seconds_max Durations of forwarded requests +# TYPE gateleen_forwarded_seconds_max gauge +gateleen_forwarded_seconds_max{metricName="storage-resources",type="storage",} 8.5515 +gateleen_forwarded_seconds_max{metricName="infotool_v1_informations",type="external",} 3.456 +# HELP gateleen_forwarded_seconds Durations of forwarded requests +# TYPE gateleen_forwarded_seconds summary +gateleen_forwarded_seconds{metricName="storage-resources",type="storage",quantile="0.75",} 6.2158 +gateleen_forwarded_seconds{metricName="storage-resources",type="storage",quantile="0.95",} 8.2123 +gateleen_forwarded_seconds_count{metricName="storage-resources",type="storage",} 67565.0 +gateleen_forwarded_seconds_sum{metricName="storage-resources",type="storage",} 656434.0 +gateleen_forwarded_seconds{metricName="infotool_v1_informations",type="external",quantile="0.75",} 4.2365 +gateleen_forwarded_seconds{metricName="infotool_v1_informations",type="external",quantile="0.95",} 4.8998 +gateleen_forwarded_seconds_count{metricName="infotool_v1_informations",type="external",} 7567.0 +gateleen_forwarded_seconds_sum{metricName="infotool_v1_informations",type="external",} 256324.0 ``` To enable the metrics, set a `MeterRegistry` instance by calling `withMeterRegistry(MeterRegistry meterRegistry)` method in `RouterBuilder` class. \ No newline at end of file diff --git a/gateleen-routing/src/main/java/org/swisspush/gateleen/routing/AbstractForwarder.java b/gateleen-routing/src/main/java/org/swisspush/gateleen/routing/AbstractForwarder.java index 96c57d8f..dccf549b 100644 --- a/gateleen-routing/src/main/java/org/swisspush/gateleen/routing/AbstractForwarder.java +++ b/gateleen-routing/src/main/java/org/swisspush/gateleen/routing/AbstractForwarder.java @@ -23,8 +23,10 @@ public abstract class AbstractForwarder implements Handler { protected final MonitoringHandler monitoringHandler; protected final String metricNameTag; - public static final String FORWARDER_METRIC_NAME = "gateleen.forwarded.requests"; - public static final String FORWARDER_METRIC_DESCRIPTION = "gateleen.forwarded.requests"; + public static final String FORWARDER_COUNT_METRIC_NAME = "gateleen.forwarded"; + public static final String FORWARDER_COUNT_METRIC_DESCRIPTION = "Amount of forwarded requests"; + public static final String FORWARDS_METRIC_NAME = "gateleen.forwarded.seconds"; + public static final String FORWARDS_METRIC_DESCRIPTION = "Durations of forwarded requests"; public static final String FORWARDER_METRIC_TAG_TYPE = "type"; public static final String FORWARDER_METRIC_TAG_METRICNAME = "metricName"; public static final String FORWARDER_NO_METRICNAME = "no-metric-name"; @@ -43,10 +45,10 @@ public AbstractForwarder(Rule rule, LoggingResourceManager loggingResourceManage protected boolean doHeadersFilterMatch(final HttpServerRequest request) { final Logger log = RequestLoggerFactory.getLogger(getClass(), request); - if(rule.getHeadersFilterPattern() != null){ + if (rule.getHeadersFilterPattern() != null) { log.debug("Looking for request headers with pattern {}", rule.getHeadersFilterPattern().pattern()); boolean matchFound = HttpHeaderUtil.hasMatchingHeader(request.headers(), rule.getHeadersFilterPattern()); - if(matchFound) { + if (matchFound) { log.debug("Matching request headers found"); } else { log.debug("No matching request headers found. Looking for the next routing rule"); @@ -79,11 +81,10 @@ protected void respondError(HttpServerRequest req, StatusCode statusCode) { } } - protected boolean isRequestToExternalTarget(String target) { - boolean isInternalRequest = false; - if (target != null) { - isInternalRequest = target.contains("localhost") || target.contains("127.0.0.1"); + protected String getRequestTarget(String target) { + if (target != null && (target.contains("localhost") || target.contains("127.0.0.1"))) { + return "local"; } - return !isInternalRequest; + return "external"; } } diff --git a/gateleen-routing/src/main/java/org/swisspush/gateleen/routing/Forwarder.java b/gateleen-routing/src/main/java/org/swisspush/gateleen/routing/Forwarder.java index e59ca45e..9eb2a718 100755 --- a/gateleen-routing/src/main/java/org/swisspush/gateleen/routing/Forwarder.java +++ b/gateleen-routing/src/main/java/org/swisspush/gateleen/routing/Forwarder.java @@ -2,6 +2,7 @@ import io.micrometer.core.instrument.Counter; import io.micrometer.core.instrument.MeterRegistry; +import io.micrometer.core.instrument.Timer; import io.netty.channel.ConnectTimeoutException; import io.netty.handler.codec.http.HttpResponseStatus; import io.vertx.core.*; @@ -66,8 +67,9 @@ public class Forwarder extends AbstractForwarder { private static final int STATUS_CODE_2XX = 2; private static final Logger LOG = LoggerFactory.getLogger(Forwarder.class); - private Counter localForwardCounter; - private Counter externalForwardCounter; + private Counter forwardCounter; + private Timer forwardTimer; + private MeterRegistry meterRegistry; public Forwarder(Vertx vertx, HttpClient client, Rule rule, final ResourceStorage storage, LoggingResourceManager loggingResourceManager, LogAppenderRepository logAppenderRepository, @@ -95,16 +97,18 @@ public Forwarder(Vertx vertx, HttpClient client, Rule rule, final ResourceStorag */ @Override public void setMeterRegistry(MeterRegistry meterRegistry) { + this.meterRegistry = meterRegistry; if (meterRegistry != null) { - localForwardCounter = Counter.builder(FORWARDER_METRIC_NAME) - .description(FORWARDER_METRIC_DESCRIPTION) - .tag(FORWARDER_METRIC_TAG_TYPE, "local") + forwardCounter = Counter.builder(FORWARDER_COUNT_METRIC_NAME) + .description(FORWARDER_COUNT_METRIC_DESCRIPTION) + .tag(FORWARDER_METRIC_TAG_TYPE, getRequestTarget(target)) .tag(FORWARDER_METRIC_TAG_METRICNAME, metricNameTag) .register(meterRegistry); - externalForwardCounter = Counter.builder(FORWARDER_METRIC_NAME) - .description(FORWARDER_METRIC_DESCRIPTION) - .tag(FORWARDER_METRIC_TAG_TYPE, "external") + forwardTimer = Timer.builder(FORWARDS_METRIC_NAME) + .description(FORWARDS_METRIC_DESCRIPTION) + .publishPercentiles(0.75, 0.95) .tag(FORWARDER_METRIC_TAG_METRICNAME, metricNameTag) + .tag(FORWARDER_METRIC_TAG_TYPE, getRequestTarget(target)) .register(meterRegistry); } } @@ -176,7 +180,9 @@ public void handle(final RoutingContext ctx, final Buffer bodyData, @Nullable fi } target = rule.getHost() + ":" + port; - handleForwardMetrics(target); + if (forwardCounter != null) { + forwardCounter.increment(); + } if (monitoringHandler != null) { monitoringHandler.updateRequestsMeter(target, req.uri()); @@ -216,10 +222,9 @@ public void handle(final RoutingContext ctx, final Buffer bodyData, @Nullable fi }); } - private void handleForwardMetrics(String target) { - Counter counter = isRequestToExternalTarget(target) ? externalForwardCounter : localForwardCounter; - if (counter != null) { - counter.increment(); + private void handleForwardDurationMetrics(Timer.Sample timerSample) { + if (timerSample != null && forwardTimer != null) { + timerSample.stop(forwardTimer); } } @@ -280,11 +285,19 @@ private void handleRequest(final HttpServerRequest req, final Buffer bodyData, f final String uniqueId = req.headers().get("x-rp-unique_id"); final String timeout = req.headers().get("x-timeout"); Long startTime = null; + + Timer.Sample timerSample = null; + if (meterRegistry != null) { + timerSample = Timer.start(meterRegistry); + } + if (monitoringHandler != null) { startTime = monitoringHandler.startRequestMetricTracking(rule.getMetricName(), req.uri()); } Long finalStartTime = startTime; + Timer.Sample finalTimerSample = timerSample; + client.request(req.method(), port, rule.getHost(), targetUri, new Handler<>() { @Override public void handle(AsyncResult event) { @@ -299,7 +312,7 @@ public void handle(AsyncResult event) { return; } HttpClientRequest cReq = event.result(); - final Handler> cResHandler = getAsyncHttpClientResponseHandler(req, targetUri, log, profileHeaderMap, loggingHandler, finalStartTime, afterHandler); + final Handler> cResHandler = getAsyncHttpClientResponseHandler(req, targetUri, log, profileHeaderMap, loggingHandler, finalStartTime, finalTimerSample, afterHandler); cReq.response(cResHandler); if (timeout != null) { @@ -333,7 +346,7 @@ public void handle(AsyncResult event) { return; } - installExceptionHandler(req, targetUri, finalStartTime, cReq); + installExceptionHandler(req, targetUri, finalStartTime, finalTimerSample, cReq); /* * If no bodyData is available @@ -464,11 +477,14 @@ private void setProfileHeaders(Logger log, Map profileHeaderMap, } } - private void installExceptionHandler(final HttpServerRequest req, final String targetUri, final Long startTime, HttpClientRequest cReq) { + private void installExceptionHandler(final HttpServerRequest req, final String targetUri, final Long startTime, @Nullable Timer.Sample timerSample, HttpClientRequest cReq) { cReq.exceptionHandler(exception -> { if (monitoringHandler != null && startTime != null) { monitoringHandler.stopRequestMetricTracking(rule.getMetricName(), startTime, req.uri()); } + + handleForwardDurationMetrics(timerSample); + if (exception instanceof TimeoutException) { error("Timeout", req, targetUri); respondError(req, StatusCode.TIMEOUT); @@ -490,7 +506,7 @@ private void installExceptionHandler(final HttpServerRequest req, final String t }); } - private Handler> getAsyncHttpClientResponseHandler(final HttpServerRequest req, final String targetUri, final Logger log, final Map profileHeaderMap, final LoggingHandler loggingHandler, @Nullable final Long startTime, @Nullable final Handler afterHandler) { + private Handler> getAsyncHttpClientResponseHandler(final HttpServerRequest req, final String targetUri, final Logger log, final Map profileHeaderMap, final LoggingHandler loggingHandler, @Nullable final Long startTime, @Nullable Timer.Sample timerSample, @Nullable final Handler afterHandler) { return asyncResult -> { HttpClientResponse cRes = asyncResult.result(); if (asyncResult.failed()) { @@ -510,6 +526,9 @@ private Handler> getAsyncHttpClientResponseHandl if (monitoringHandler != null) { monitoringHandler.stopRequestMetricTracking(rule.getMetricName(), startTime, req.uri()); } + + handleForwardDurationMetrics(timerSample); + loggingHandler.setResponse(cRes); req.response().setStatusCode(cRes.statusCode()); req.response().setStatusMessage(cRes.statusMessage()); diff --git a/gateleen-routing/src/main/java/org/swisspush/gateleen/routing/NullForwarder.java b/gateleen-routing/src/main/java/org/swisspush/gateleen/routing/NullForwarder.java index 2224c9d2..bed0d498 100755 --- a/gateleen-routing/src/main/java/org/swisspush/gateleen/routing/NullForwarder.java +++ b/gateleen-routing/src/main/java/org/swisspush/gateleen/routing/NullForwarder.java @@ -46,8 +46,8 @@ public NullForwarder(Rule rule, LoggingResourceManager loggingResourceManager, L @Override public void setMeterRegistry(MeterRegistry meterRegistry) { if(meterRegistry != null) { - forwardCounter = Counter.builder(FORWARDER_METRIC_NAME) - .description(FORWARDER_METRIC_DESCRIPTION) + forwardCounter = Counter.builder(FORWARDER_COUNT_METRIC_NAME) + .description(FORWARDER_COUNT_METRIC_DESCRIPTION) .tag(FORWARDER_METRIC_TAG_METRICNAME, metricNameTag) .tag(FORWARDER_METRIC_TAG_TYPE, "null") .register(meterRegistry); diff --git a/gateleen-routing/src/main/java/org/swisspush/gateleen/routing/StorageForwarder.java b/gateleen-routing/src/main/java/org/swisspush/gateleen/routing/StorageForwarder.java index c7324cf4..32a0f38a 100755 --- a/gateleen-routing/src/main/java/org/swisspush/gateleen/routing/StorageForwarder.java +++ b/gateleen-routing/src/main/java/org/swisspush/gateleen/routing/StorageForwarder.java @@ -2,6 +2,7 @@ import io.micrometer.core.instrument.Counter; import io.micrometer.core.instrument.MeterRegistry; +import io.micrometer.core.instrument.Timer; import io.netty.handler.codec.http.HttpResponseStatus; import io.vertx.core.AsyncResult; import io.vertx.core.Handler; @@ -47,6 +48,10 @@ public class StorageForwarder extends AbstractForwarder { private GateleenExceptionFactory gateleenExceptionFactory; private Counter forwardCounter; + private Timer forwardTimer; + private MeterRegistry meterRegistry; + + private static final String TYPE_STORAGE = "storage"; public StorageForwarder(EventBus eventBus, Rule rule, LoggingResourceManager loggingResourceManager, LogAppenderRepository logAppenderRepository, @Nullable MonitoringHandler monitoringHandler, @@ -68,11 +73,19 @@ public StorageForwarder(EventBus eventBus, Rule rule, LoggingResourceManager log */ @Override public void setMeterRegistry(MeterRegistry meterRegistry) { + this.meterRegistry = meterRegistry; if (meterRegistry != null) { - forwardCounter = Counter.builder(FORWARDER_METRIC_NAME) - .description(FORWARDER_METRIC_DESCRIPTION) + forwardCounter = Counter.builder(FORWARDER_COUNT_METRIC_NAME) + .description(FORWARDER_COUNT_METRIC_DESCRIPTION) .tag(FORWARDER_METRIC_TAG_METRICNAME, metricNameTag) - .tag(FORWARDER_METRIC_TAG_TYPE, "storage") + .tag(FORWARDER_METRIC_TAG_TYPE, TYPE_STORAGE) + .register(meterRegistry); + + forwardTimer = Timer.builder(FORWARDS_METRIC_NAME) + .description(FORWARDS_METRIC_DESCRIPTION) + .publishPercentiles(0.75, 0.95) + .tag(FORWARDER_METRIC_TAG_METRICNAME, metricNameTag) + .tag(FORWARDER_METRIC_TAG_TYPE, TYPE_STORAGE) .register(meterRegistry); } } @@ -90,7 +103,9 @@ public void handle(final RoutingContext ctx) { Long startTime = null; - if (forwardCounter != null) { + Timer.Sample timerSample = null; + if(meterRegistry != null) { + timerSample = Timer.start(meterRegistry); forwardCounter.increment(); } @@ -124,6 +139,9 @@ public void handle(final RoutingContext ctx) { requestBuffer.appendBuffer(buffer); }); Long finalStartTime = startTime; + + Timer.Sample finalTimerSample = timerSample; + ctx.request().endHandler(event -> eventBus.request(address, requestBuffer, new DeliveryOptions().setSendTimeout(10000), (Handler>>) result -> { @@ -131,6 +149,11 @@ public void handle(final RoutingContext ctx) { if (monitoringHandler != null) { monitoringHandler.stopRequestMetricTracking(rule.getMetricName(), finalStartTime, ctx.request().uri()); } + + if(finalTimerSample != null) { + finalTimerSample.stop(forwardTimer); + } + if (result.failed()) { String statusMessage = "Storage request for " + ctx.request().uri() + " failed with message: " + result.cause().getMessage(); response.setStatusCode(StatusCode.INTERNAL_SERVER_ERROR.getStatusCode()); diff --git a/gateleen-routing/src/test/java/org/swisspush/gateleen/routing/RouterTest.java b/gateleen-routing/src/test/java/org/swisspush/gateleen/routing/RouterTest.java index 2d789b95..2c90dfbc 100755 --- a/gateleen-routing/src/test/java/org/swisspush/gateleen/routing/RouterTest.java +++ b/gateleen-routing/src/test/java/org/swisspush/gateleen/routing/RouterTest.java @@ -172,7 +172,7 @@ private RouterBuilder routerBuilder() { } private void assertNoCountersIncremented(TestContext context) { - for (Counter counter : meterRegistry.get(AbstractForwarder.FORWARDER_METRIC_NAME).counters()) { + for (Counter counter : meterRegistry.get(AbstractForwarder.FORWARDER_COUNT_METRIC_NAME).counters()) { context.assertEquals(0.0, counter.count(), "No counter should have been incremented"); } } @@ -249,7 +249,7 @@ public DummyHttpServerResponse response() { GETRandomResourceRequest request = new GETRandomResourceRequest(); router.route(request); - Counter counter = meterRegistry.get(AbstractForwarder.FORWARDER_METRIC_NAME).tag(AbstractForwarder.FORWARDER_METRIC_TAG_METRICNAME, "loop_4").counter(); + Counter counter = meterRegistry.get(AbstractForwarder.FORWARDER_COUNT_METRIC_NAME).tag(AbstractForwarder.FORWARDER_METRIC_TAG_METRICNAME, "loop_4").counter(); context.assertEquals(1.0, counter.count(), "Counter for `loop_4` rule should have been incremented by 1"); context.assertEquals("1", request.headers().get("x-hops"), "x-hops header should have value 1"); @@ -419,7 +419,7 @@ public DummyHttpServerResponse response() { context.assertEquals(StatusCode.INTERNAL_SERVER_ERROR.getStatusCode(), request.response().getStatusCode(), "StatusCode should be 500"); context.assertEquals("Request hops limit exceeded", request.response().getStatusMessage(), "StatusMessage should be 'Request hops limit exceeded'"); - Counter counter = meterRegistry.get(AbstractForwarder.FORWARDER_METRIC_NAME).tag(AbstractForwarder.FORWARDER_METRIC_TAG_METRICNAME, "loop_4").counter(); + Counter counter = meterRegistry.get(AbstractForwarder.FORWARDER_COUNT_METRIC_NAME).tag(AbstractForwarder.FORWARDER_METRIC_TAG_METRICNAME, "loop_4").counter(); context.assertEquals(5.0, counter.count(), "Counter for `loop_4` rule should have been incremented by 5"); } @@ -496,7 +496,7 @@ public DummyHttpServerResponse response() { context.assertEquals(StatusCode.OK.getStatusCode(), request.response().getStatusCode(), "StatusCode should be 200"); context.assertEquals(StatusCode.OK.getStatusMessage(), request.response().getStatusMessage(), "StatusMessage should be OK"); - Counter counter = meterRegistry.get(AbstractForwarder.FORWARDER_METRIC_NAME).tag(AbstractForwarder.FORWARDER_METRIC_TAG_METRICNAME, "loop_4").counter(); + Counter counter = meterRegistry.get(AbstractForwarder.FORWARDER_COUNT_METRIC_NAME).tag(AbstractForwarder.FORWARDER_METRIC_TAG_METRICNAME, "loop_4").counter(); context.assertEquals(20.0, counter.count(), "Counter for `loop_4` rule should have been incremented by 20"); } @@ -773,7 +773,7 @@ public HttpServerRequest pause() { context.assertFalse(router.isRoutingBroken(), "Routing should not be broken anymore"); context.assertNull(router.getRoutingBrokenMessage(), "RoutingBrokenMessage should be null"); - Counter counter = meterRegistry.get(AbstractForwarder.FORWARDER_METRIC_NAME).tag(AbstractForwarder.FORWARDER_METRIC_TAG_TYPE, "local").counter(); + Counter counter = meterRegistry.get(AbstractForwarder.FORWARDER_COUNT_METRIC_NAME).tag(AbstractForwarder.FORWARDER_METRIC_TAG_TYPE, "local").counter(); context.assertEquals(1.0, counter.count(), "Counter should have been incremented by 1"); } @@ -908,7 +908,7 @@ public void testStorageRequestWithHeadersFilterPresent(TestContext context) { context.assertEquals(StatusCode.OK.getStatusCode(), request.response().getStatusCode(), "StatusCode should be 200"); context.assertEquals(StatusCode.OK.getStatusMessage(), request.response().getStatusMessage(), "StatusMessage should be OK"); - Counter counter = meterRegistry.get(AbstractForwarder.FORWARDER_METRIC_NAME).tag(AbstractForwarder.FORWARDER_METRIC_TAG_METRICNAME, "forward_storage").counter(); + Counter counter = meterRegistry.get(AbstractForwarder.FORWARDER_COUNT_METRIC_NAME).tag(AbstractForwarder.FORWARDER_METRIC_TAG_METRICNAME, "forward_storage").counter(); context.assertEquals(1.0, counter.count(), "Counter for `forward_storage` rule should have been incremented by 1"); } @@ -982,7 +982,7 @@ public void testNullForwarderRequestWithHeadersFilterPresent(TestContext context context.assertEquals(StatusCode.OK.getStatusCode(), request.response().getStatusCode(), "StatusCode should be 200"); context.assertEquals(StatusCode.OK.getStatusMessage(), request.response().getStatusMessage(), "StatusMessage should be OK"); - Counter counter = meterRegistry.get(AbstractForwarder.FORWARDER_METRIC_NAME).tag(AbstractForwarder.FORWARDER_METRIC_TAG_METRICNAME, "forward_null").counter(); + Counter counter = meterRegistry.get(AbstractForwarder.FORWARDER_COUNT_METRIC_NAME).tag(AbstractForwarder.FORWARDER_METRIC_TAG_METRICNAME, "forward_null").counter(); context.assertEquals(1.0, counter.count(), "Counter for `forward_null` rule should have been incremented by 1"); } @@ -1010,7 +1010,7 @@ public void testForwarderRequestWithHeadersFilterPresent(TestContext context) { // however, this means that the headersFilter evaluation did not return a 400 Bad Request context.assertEquals(StatusCode.INTERNAL_SERVER_ERROR.getStatusCode(), request.response().getStatusCode(), "StatusCode should be 500"); - Counter counter = meterRegistry.get(AbstractForwarder.FORWARDER_METRIC_NAME).tag(AbstractForwarder.FORWARDER_METRIC_TAG_METRICNAME, "forward_backend").counter(); + Counter counter = meterRegistry.get(AbstractForwarder.FORWARDER_COUNT_METRIC_NAME).tag(AbstractForwarder.FORWARDER_METRIC_TAG_METRICNAME, "forward_backend").counter(); context.assertEquals(1.0, counter.count(), "Counter for `forward_backend` rule should have been incremented by 1"); }