fix(server): record bounded request body and client IP in slow query log - #3177
Conversation
Replaces apache#2466 by @SunnyBoy-WYH. Fixes apache#2468. The slow query log has printed body=null since apache#2347 disabled the capture from apache#2327, which broke gzip batch imports. AccessLogFilter now also runs as a request filter and keeps at most log.slow_query_body_limit bytes (default 512, 0 disables) of POST/PUT bodies on slow-log paths, replaying the prefix in front of the rest of the entity stream. Nothing is read for other paths, for GET/DELETE, or when the slow query log is off, so loader batch imports are untouched. Compressed bodies are logged as <gzip> instead of being decoded. The client IP is the Grizzly Request peer address, as in AuthenticationFilter. Adds AccessLogFilterTest and removes the unused PathFilter.REQUEST_PARAMS_JSON constant. Co-authored-by: SunnyBoy-WYH <1289220708@qq.com>
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## master #3177 +/- ##
============================================
+ Coverage 32.66% 36.63% +3.96%
- Complexity 5500 6344 +844
============================================
Files 789 800 +11
Lines 67703 68925 +1222
Branches 8945 9155 +210
============================================
+ Hits 22116 25251 +3135
+ Misses 42983 40679 -2304
- Partials 2604 2995 +391 ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
There was a problem hiding this comment.
Pull request overview
This PR restores and improves slow-query logging in hugegraph-server by safely capturing a bounded preview of POST/PUT request bodies (without breaking downstream entity consumption) and by logging the client IP, addressing regressions from earlier slow-log body handling.
Changes:
- Make
AccessLogFilteralso act as a request filter to capture a bounded request-body preview (with replay) for slow-log-eligible paths, and include client IP in the slow query log line. - Add
log.slow_query_body_limit(default 512 bytes, 0 disables, max 1 MiB) to control slow-log body recording. - Add
AccessLogFilterTestand include it inUnitTestSuite; remove the unusedPathFilter.REQUEST_PARAMS_JSONconstant.
Reviewed changes
Copilot reviewed 6 out of 6 changed files in this pull request and generated no comments.
Show a summary per file
| File | Description |
|---|---|
| hugegraph-server/hugegraph-test/src/main/java/org/apache/hugegraph/unit/UnitTestSuite.java | Registers the new AccessLogFilterTest in the unit test suite. |
| hugegraph-server/hugegraph-test/src/main/java/org/apache/hugegraph/unit/api/filter/AccessLogFilterTest.java | Adds unit tests covering slow-log path selection, bounded body capture/replay, truncation, encoding skip, CR/LF escaping, and IP logging. |
| hugegraph-server/hugegraph-dist/src/assembly/static/conf/rest-server.properties | Documents and sets default for log.slow_query_body_limit. |
| hugegraph-server/hugegraph-api/src/main/java/org/apache/hugegraph/config/ServerOptions.java | Introduces SLOW_QUERY_LOG_BODY_LIMIT config option with validation and description. |
| hugegraph-server/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/PathFilter.java | Removes unused REQUEST_PARAMS_JSON constant. |
| hugegraph-server/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/AccessLogFilter.java | Implements bounded request-body preview capture + single-line escaping + client IP logging for slow queries. |
Suppressed comments (1)
hugegraph-server/hugegraph-api/src/main/java/org/apache/hugegraph/api/filter/AccessLogFilter.java:95
needRecordLog()doesn’t account forPathFilterredirecting non-whitelisted requests from/graphs/...to/graphspaces/{space}/graphs/.... As a result, slow-log paths undergraphspaces/(including/graphspaces/.../graphs/.../cypherand.../graph/vertices) won’t be considered loggable, and the new request-body capture won’t run for them either (this also contradicts the new unit test expectations).
public static boolean needRecordLog(ContainerRequestContext context) {
String path = context.getUriInfo().getPath();
// GraphsAPI/CypherAPI/Job GremlinAPI
if (path.startsWith(GRAPHS)) {
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
- exercise the real gzip decoder on the preserved batch stream - verify slow-log filtering leaves compressed payloads untouched - align the cluster test config with the new body limit
imbajin
left a comment
There was a problem hiding this comment.
Blocking: no. Summary: Two important correctness gaps remain in the request-body preview path: declared non-UTF-8 request charsets are decoded incorrectly, and redirected job requests can skip capture because the request-filter ordering is unspecified. Evidence: exact head 0260a43; AccessLogFilterTest passed 18/18 locally; all reported latest-head GitHub checks passed.
| private static String preview(byte[] bytes, int length, int limit) { | ||
| boolean truncated = length > limit; | ||
| int size = Math.min(length, limit); | ||
| CharsetDecoder decoder = CHARSET.newDecoder() |
There was a problem hiding this comment.
| * @param requestContext requestContext | ||
| */ | ||
| @Override | ||
| public void filter(ContainerRequestContext requestContext) throws IOException { |
There was a problem hiding this comment.
- decode slow-log previews with the request media type charset - run redirect forwarding after the default body capture priority - cover UTF-16 previews and redirect priority registration - align touched code with the 120-column limit
Purpose
Replaces #2466 by @SunnyBoy-WYH (the head branch lives on a personal fork and now conflicts with master). Fixes #2468.
The slow query log has printed
body=nullsince #2347 commented out the body capture added in #2327, because reading the body broke gzip batch imports from hugegraph-loader. The TODO left inAccessLogFilteralso asked for the client IP.Changes
AccessLogFilternow also runs as a (post-matching) request filter and keeps a bounded preview of the request body for POST/PUT requests on slow-log paths (needRecordLog). It reads at mostlog.slow_query_body_limitbytes (+1 to detect truncation) and replays them in front of the untouched remainder of the entity stream with aSequenceInputStream, so the resource still receives the whole body and per-request memory is bounded by the limit, not by the body size.log.slow_query_threshold=0), when the limit is 0, for GET/DELETE, or for paths that are never slow-logged. Loader batch imports (.../vertices/batch,.../edges/batch) are not slow-log paths, so their entity stream is never touched, gzip or not.@Decompress(DecompressInterceptorruns later as a ReaderInterceptor), the entity is not read and the log shows<encoded>. The decision is based on the resource, not on theContent-Encodingheader, so a client cannot opt out of body recording by sending a header, and no header value is echoed into the log.CharsetDecoder, so a multi-byte character cut by the limit is dropped rather than logged as U+FFFD. A truncated preview ends with....%0Ain a query string produced a raw line break inslow_query.log.Requestpeer address viaProvider<Request>, the same patternAuthenticationFilteruses, with<unknown_ip>as fallback. No DNS lookup on the log path.log.slow_query_body_limit(bytes, default 512, 0 disables body recording, max 1 MiB). This answers the open question in fix(server): fix server slow log, support loader import & client IP #2466 about making the 512 limit configurable and gives operators a switch when gremlin/cypher bodies must not reach the log. The option description andrest-server.propertiessay that the prefix is written as-is and may contain sensitive literals. Body recording stays on by default, matching feat(api): support recording slow query log #2327, fix(api): refactor/downgrade record logic for slow log #2347 and fix(server): fix server slow log, support loader import & client IP #2466; note that the same file already receives full GET query strings (/gremlin?gremlin=...) today.[Slow Query] ip=..., execTime=...ms, method=..., path=..., query=..., body=...PathFilter.REQUEST_PARAMS_JSONconstant is removed;PathFilteris otherwise untouched.Review threads from #2466
<unknown_ip>): bodies are cut at the configured limit, PUT is handled, the log call uses local variables,<unknown_ip>is the placeholder. DELETE is left out on purpose: every@DELETEendpoint takes path or query parameters only, so there is no body to record, and Copilot asked to drop it as well.REQUEST_PARAMS_JSON): the original storedgetPathParameters()from a@PreMatchingfilter, before matching happens, so it was always empty. GET requests logquery=and the path, which carry the parameters already.getRemoteAddr()replacesInetAddress.getByName(uri.getHost()), which resolved the server host name and did a blocking DNS lookup on every slow query.X-Forwarded-Forwithout a trusted-proxy list lets any client choose the logged IP. That needs its own option and is left for a follow-up.Verification
AccessLogFilterTest(new, 18 cases, added toUnitTestSuite): slow-log path selection, bounded capture and full replay, truncation mark, exact-limit body, multi-byte cut, CR/LF kept in the preview, empty body,Content-Encodingheader ignored, skips (log off, limit 0, GET/DELETE, batch import on a@Decompressresource,@Decompressresource on a slow-log path), and the log line (client IP, GET query, one line with CR/LF in path/query/body,<unknown_ip>, fast requests, log off). The test swaps the module's log4j2 logger for the class under test and restores it, so it passes when run alone as well as inside the suite.mvn test -pl hugegraph-server/hugegraph-test -am -P unit-teston JDK 11 (Linux x86_64):UnitTestSuite679 tests, 0 failures, 0 errors, 1 skipped (pre-existingRocksDBSessionTest.testMergeWithStringList).AccessLogFilterTestalso passes when run alone and when a single method is run alone.log.slow_query_threshold=1,log.slow_query_body_limit=64):/graphs/hugegraph/graph/vertices/batchreturn 201/200 (loader path, stream untouched, not logged)...query=limit=2, body=null, cypher logs the statement, a pretty-printed body with CR/LF is one log line, a query string with%0Ais one log lineip=100.123.70.122), local ones logip=127.0.0.1Content-Encoding: gzipheader on a plain/gremlinbody neither hides the body nor changes the resultlog.slow_query_body_limit=0logsbody=null,log.slow_query_threshold=0logs nothing, no exceptions from the filterNotes
path=in the line still comes from the existingnormalizePath()used for metric names, which prints for examplegraphspaces/graphspace/graphs/hugegraph/graph/vertices. Unchanged here.log.slow_query_body_limitis listed inrest-server.properties; hugegraph-doc needs a line for it.