[Bug] AccessLogFilter for path matrics make Server OOM

Bug Type (问题类型)

logic (逻辑设计问题)

Before submit

我已经确认现有的 Issues 与 FAQ 中没有相同 / 重复问题 (I have confirmed and searched that there are no similar problems in the historical issue and documents)

Environment (环境信息)

Server Version: 1.3.0 (Apache Release Version)
Backend: RocksDB

Expected & Actual behavior (期望与实际表现)

API

PUT http://127.0.0.1:8080/graphs/hugegraph/graph/vertices/"1:mako"?action=append

{
    "label": "person",
    "properties": {
        "age": 30,
        "city": "Beijing"
    }
}

Get metrics

curl http:/127.0.0.1:8080/metrics |grep vertices

result
_graphs_hugegraph_graph_vertices_%221:mako%22_PUT_RESPONSE_TIME_HISTOGRAM

when there is many Vetices update

This Map will be oom
ServerReporter.java

    private SortedMap<String, Histogram> histograms;

@dosu

@dosu can you help me fix this bug

Bug releated PR #2286

@dosu

The root casue is this class logic

AccessLogFilter.java

@Override
    public void filter(ContainerRequestContext requestContext,
                       ContainerResponseContext responseContext) throws IOException {
        // Grab corresponding request / response info from context;
        URI uri = requestContext.getUriInfo().getRequestUri();
        String path = uri.getRawPath();//针对不同的path中包含变量的方法，会造成Metrics 采集 OOM
        String method = requestContext.getMethod();
        String metricsName = join(path, method);
        //TODO: 变量path 造成OOM。暂时先屏蔽，啥都不做
        MetricsUtil.registerCounter(join(metricsName, METRICS_PATH_TOTAL_COUNTER)).inc();
        if (statusOk(responseContext.getStatus())) {
            MetricsUtil.registerCounter(join(metricsName, METRICS_PATH_SUCCESS_COUNTER)).inc();
        } else {
            MetricsUtil.registerCounter(join(metricsName, METRICS_PATH_FAILED_COUNTER)).inc();
        }

        Object requestTime = requestContext.getProperty(REQUEST_TIME);
        if (requestTime != null) {
            long now = System.currentTimeMillis();
            long start = (Long) requestTime;
            long executeTime = now - start;

            MetricsUtil.registerHistogram(join(metricsName, METRICS_PATH_RESPONSE_TIME_HISTOGRAM))
                       .update(executeTime);

            HugeConfig config = configProvider.get();
            long timeThreshold = config.get(ServerOptions.SLOW_QUERY_LOG_TIME_THRESHOLD);
            // Record slow query if meet needs, watch out the perf
            if (timeThreshold > 0 && executeTime > timeThreshold &&
                needRecordLog(requestContext)) {
                // TODO: set RequestBody null, handle it later & should record "client IP"
                LOG.info("[Slow Query] execTime={}ms, body={}, method={}, path={}, query={}",
                         executeTime, null, method, path, uri.getQuery());
            }
        }

        // Unset the context in "HugeAuthenticator", need distinguish Graph/Auth server lifecycle
        GraphManager manager = managerProvider.get();
        // TODO: transfer Authorizer if we need after.
        if (manager.requireAuthentication()) {
            manager.unauthorize(requestContext.getSecurityContext());
        }
    }

@dosu could you fix this bug

@dosu

To fix the OOM issue caused by variable paths in metrics collection in the AccessLogFilter class, you can normalize the paths to avoid creating too many unique metric names. One common approach is to replace variable parts of the path (like IDs) with placeholders.

Here's the modified AccessLogFilter class with the fix:

package org.apache.hugegraph.api.filter;

import static org.apache.hugegraph.api.filter.PathFilter.REQUEST_TIME;
import static org.apache.hugegraph.metrics.MetricsUtil.METRICS_PATH_FAILED_COUNTER;
import static org.apache.hugegraph.metrics.MetricsUtil.METRICS_PATH_RESPONSE_TIME_HISTOGRAM;
import static org.apache.hugegraph.metrics.MetricsUtil.METRICS_PATH_SUCCESS_COUNTER;
import static org.apache.hugegraph.metrics.MetricsUtil.METRICS_PATH_TOTAL_COUNTER;

import java.io.IOException;
import java.net.URI;

import org.apache.hugegraph.auth.HugeAuthenticator;
import org.apache.hugegraph.config.HugeConfig;
import org.apache.hugegraph.config.ServerOptions;
import org.apache.hugegraph.core.GraphManager;
import org.apache.hugegraph.metrics.MetricsUtil;
import org.apache.hugegraph.util.Log;
import org.slf4j.Logger;

import jakarta.inject.Singleton;
import jakarta.ws.rs.HttpMethod;
import jakarta.ws.rs.container.ContainerRequestContext;
import jakarta.ws.rs.container.ContainerResponseContext;
import jakarta.ws.rs.container.ContainerResponseFilter;
import jakarta.ws.rs.core.Context;
import jakarta.ws.rs.ext.Provider;

@Provider
@Singleton
public class AccessLogFilter implements ContainerResponseFilter {

    private static final Logger LOG = Log.logger(AccessLogFilter.class);

    private static final String DELIMITER = "/";
    private static final String GRAPHS = "graphs";
    private static final String GREMLIN = "gremlin";
    private static final String CYPHER = "cypher";

    @Context
    private jakarta.inject.Provider<HugeConfig> configProvider;

    @Context
    private jakarta.inject.Provider<GraphManager> managerProvider;

    public static boolean needRecordLog(ContainerRequestContext context) {
        String path = context.getUriInfo().getPath();

        if (path.startsWith(GRAPHS)) {
            if (HttpMethod.GET.equals(context.getMethod()) || path.endsWith(CYPHER)) {
                return true;
            }
        }
        return path.endsWith(GREMLIN);
    }

    private String join(String path1, String path2) {
        return String.join(DELIMITER, path1, path2);
    }

    private String normalizePath(String path) {
        // Replace variable parts of the path with placeholders
        return path.replaceAll("/\\d+", "/{id}")
                   .replaceAll("/[a-f0-9-]{36}", "/{uuid}");
    }

    @Override
    public void filter(ContainerRequestContext requestContext,
                       ContainerResponseContext responseContext) throws IOException {
        URI uri = requestContext.getUriInfo().getRequestUri();
        String path = normalizePath(uri.getRawPath());
        String method = requestContext.getMethod();
        String metricsName = join(path, method);

        MetricsUtil.registerCounter(join(metricsName, METRICS_PATH_TOTAL_COUNTER)).inc();
        if (statusOk(responseContext.getStatus())) {
            MetricsUtil.registerCounter(join(metricsName, METRICS_PATH_SUCCESS_COUNTER)).inc();
        } else {
            MetricsUtil.registerCounter(join(metricsName, METRICS_PATH_FAILED_COUNTER)).inc();
        }

        Object requestTime = requestContext.getProperty(REQUEST_TIME);
        if (requestTime != null) {
            long now = System.currentTimeMillis();
            long start = (Long) requestTime;
            long executeTime = now - start;

            MetricsUtil.registerHistogram(join(metricsName, METRICS_PATH_RESPONSE_TIME_HISTOGRAM))
                       .update(executeTime);

            HugeConfig config = configProvider.get();
            long timeThreshold = config.get(ServerOptions.SLOW_QUERY_LOG_TIME_THRESHOLD);
            if (timeThreshold > 0 && executeTime > timeThreshold &&
                needRecordLog(requestContext)) {
                LOG.info("[Slow Query] execTime={}ms, body={}, method={}, path={}, query={}",
                         executeTime, null, method, path, uri.getQuery());
            }
        }

        GraphManager manager = managerProvider.get();
        if (manager.requireAuthentication()) {
            manager.unauthorize(requestContext.getSecurityContext());
        }
    }

    private boolean statusOk(int status) {
        return status >= 200 && status < 300;
    }
}

In this code, the normalizePath method replaces numeric IDs and UUIDs in the path with placeholders, which helps to reduce the number of unique metric names and prevent the OOM issue ^[1].

To continue talking to Dosu, mention @dosu.

@dosu

@dosu 上边思路是正确的，但是

private String normalizePath(String path) {
        // Replace variable parts of the path with placeholders
        return path.replaceAll("/\\d+", "/{id}")
                   .replaceAll("/[a-f0-9-]{36}", "/{uuid}");
    }

方法不能覆盖path = /graphs/hugegraph/graph/vertices/"2:mako" 这种场景，请修正下代码

@dosu

To handle paths with variable parts such as /graphs/hugegraph/graph/vertices/"2:mako", you can modify the normalizePath method to replace variable parts with placeholders. This will help in normalizing the paths for consistent logging and metrics collection.

Here is an example of how you can modify the normalizePath method:

private static final String VARIABLE_PART_REGEX = "/\\d+:\\w+";

private String normalizePath(String path) {
    // Replace variable parts with a placeholder
    return path.replaceAll(VARIABLE_PART_REGEX, "/{variable}")
               .replaceAll("/\\d+", "/{id}")
               .replaceAll("/[a-f0-9-]{36}", "/{uuid}");
}

You can then use this normalizePath method in the filter method to normalize the path before using it for metrics and logging:

@Override
public void filter(ContainerRequestContext requestContext,
                   ContainerResponseContext responseContext) throws IOException {
    URI uri = requestContext.getUriInfo().getRequestUri();
    String rawPath = uri.getRawPath();
    String path = normalizePath(rawPath);
    String method = requestContext.getMethod();
    String metricsName = join(path, method);

    MetricsUtil.registerCounter(join(metricsName, METRICS_PATH_TOTAL_COUNTER)).inc();
    if (statusOk(responseContext.getStatus())) {
        MetricsUtil.registerCounter(join(metricsName, METRICS_PATH_SUCCESS_COUNTER)).inc();
    } else {
        MetricsUtil.registerCounter(join(metricsName, METRICS_PATH_FAILED_COUNTER)).inc();
    }

    Object requestTime = requestContext.getProperty(REQUEST_TIME);
    if (requestTime != null) {
        long now = System.currentTimeMillis();
        long start = (Long) requestTime;
        long executeTime = now - start;

        MetricsUtil.registerHistogram(join(metricsName, METRICS_PATH_RESPONSE_TIME_HISTOGRAM))
                   .update(executeTime);

        HugeConfig config = configProvider.get();
        long timeThreshold = config.get(ServerOptions.SLOW_QUERY_LOG_TIME_THRESHOLD);
        if (timeThreshold > 0 && executeTime > timeThreshold &&
            needRecordLog(requestContext)) {
            LOG.info("[Slow Query] execTime={}ms, body={}, method={}, path={}, query={}",
                     executeTime, null, method, path, uri.getQuery());
        }
    }

    GraphManager manager = managerProvider.get();
    if (manager.requireAuthentication()) {
        manager.unauthorize(requestContext.getSecurityContext());
    }
}

This modification ensures that paths with variable parts are normalized, making the logging and metrics collection more consistent ^[1].

To continue talking to Dosu, mention @dosu.

fix #2569

Navigation Menu

Repository navigation

[Bug] AccessLogFilter for path matrics make Server OOM #2566

Bug Type (问题类型)

Before submit

Environment (环境信息)

Expected & Actual behavior (期望与实际表现)

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[Bug] AccessLogFilter for path matrics make Server OOM #2566

Description

Bug Type (问题类型)

Before submit

Environment (环境信息)

Expected & Actual behavior (期望与实际表现)

Activity

JackyYangPassion commented on Jul 1, 2024

JackyYangPassion commented on Jul 1, 2024

JackyYangPassion commented on Jul 2, 2024

dosubot commented on Jul 2, 2024

JackyYangPassion commented on Jul 2, 2024

dosubot commented on Jul 2, 2024

JackyYangPassion commented on Jul 2, 2024

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions