Ryan19929 commented on code in PR #68694:
URL: https://github.com/apache/doris/pull/68694#discussion_r4253945187
##########
be/src/common/logconfig.cpp:
##########
@@ -145,6 +148,7 @@ void custom_prefix(std::ostream& s, const
google::LogMessageInfo& l, void* arg)
s << l.thread_id << std::setfill('0');
s << ' ';
s << l.filename << ':' << l.line_number << "]";
+ append_query_log_identity(s);
Review Comment:
[P2] The longer prefix makes `LOG_LONG_STRING` truncate every full chunk
`LOG_LONG_STRING` (`common/logging.h:133`) splits a long string into chunks
of `30000 - 100` bytes. In glog 0.6 the custom prefix is written into the same
`LogStreamBuf` as the message, and that buffer holds about `kMaxLogMessageLen -
2 = 29998` bytes; anything beyond is dropped silently.
The old prefix was about 70 bytes, so the 100-byte margin was enough. With
`[hi-lo]` / `[hi-lo/N]` the prefix is about 105 bytes, and with the
`fragment_instance_id=` form it is longer still. So every full chunk now loses
about 7 to 60 trailing characters.
Concrete paths:
- query cancel → `PipelineFragmentContext::cancel` →
`LOG_LONG_STRING(WARNING, dbg_str)`;
- profile printing under `close_task`.
Please enlarge the margin (e.g. `30000 - 256`) and add a boundary test.
##########
fe/fe-core/src/main/java/org/apache/doris/qe/ConnectContext.java:
##########
@@ -630,6 +633,7 @@ public AuditEventBuilder getAuditEventBuilder() {
public void setThreadLocalInfo() {
MoreFieldsThread.setConnectContext(this);
+ QueryLogContext.setQueryId(queryId);
Review Comment:
[P2] Direct MDC writes outlive the request on pooled threads
`setThreadLocalInfo()`, and `setQueryId()` / `resetQueryId()` through
`updateQueryLogContext()` (:1219), write the MDC directly, with no scope.
Cleanup therefore depends on every thread entry eventually calling
`ConnectContext.remove()`. Two entries never do:
- **Transient-task disruptor thread.** `ConnectorRewriteGroupTask` calls
`setQueryId(...)` + `setThreadLocalInfo()`, and
`TaskHandler.onTransientTaskHandle()` never removes them. The next
`ExportTaskExecutor` on the same thread opens an `AutoCloseConnectContext`,
which captures that stale id as the "previous" value and restores it on close.
As a result, "Memory task execute failed" for the export is logged under the
earlier rewrite task's id.
- **HTTP (Jetty) threads.** `TableQueryPlanAction` (:252, the `_query_plan`
endpoint used by the Spark/Flink connectors) calls `context.setQueryId(...)`
after `RestBaseController.executeCheckPassword()` has installed the context.
Within httpv2, only `LoadAction` calls `ConnectContext.remove()`, and
`AuthInterceptor` has no `afterCompletion`. Until the same Jetty thread next
runs `executeCheckPassword()`, its logs carry the stale id. That includes
`RestBaseController` "parse auth info failed", `BaseController`,
`MetricsAction`, health/bootstrap endpoints and Spring exception logs.
Suggestion: clear at those entries (a `finally` in `TaskHandler`, and
`afterCompletion` in `AuthInterceptor` / `RestBaseController`), or make these
mirror writes scoped as well.
##########
fe/fe-common/src/main/java/org/apache/doris/common/Config.java:
##########
@@ -77,6 +77,9 @@ public class Config extends ConfigBase {
options = {"NORMAL", "ASYNC", "BRIEF"})
public static String sys_log_mode = "ASYNC";
+ @ConfField(description = "Attach query_id to runtime log events. Requires
restart.")
+ public static boolean sys_log_enable_query_id = true;
Review Comment:
[P2] The log-text migration is not reversible by the switch; please call it
out in the release note
The switch restores the pattern, but not the about 90 rewritten messages.
Examples:
- `dispatch load job: X to` → `dispatch load job [X] to`
- `kill query timeout, ..., query id: X` → `kill query timeout [X], ...`
- `stmt[5, X]` → `stmt[5] [X]`
BE has a similar set (`Query start execution`, `Cancel query, reason:`, the
`.tag("query_id")` removal in `PipelineFragmentContext::cancel`, …).
Alerting and grep rules that match `query id:` / `queryId:` / `Query <id>`
in the message body break whichever way the switch is set. The description
already says that byte-for-byte restoration is not provided. Please also list
the main text changes in the release note and docs, so operators can update
their log pipelines. The same applies to `be/src/common/config.cpp:320`.
##########
be/src/common/query_log_context.cpp:
##########
@@ -0,0 +1,170 @@
+// Licensed to the Apache Software Foundation (ASF) under one
+// or more contributor license agreements. See the NOTICE file
+// distributed with this work for additional information
+// regarding copyright ownership. The ASF licenses this file
+// to you under the Apache License, Version 2.0 (the
+// "License"); you may not use this file except in compliance
+// with the License. You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing,
+// software distributed under the License is distributed on an
+// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+// KIND, either express or implied. See the License for the
+// specific language governing permissions and limitations
+// under the License.
+
+#include "common/query_log_context.h"
+
+#include <bthread/bthread.h>
+
+#include <atomic>
+#include <charconv>
+#include <mutex>
+#include <ostream>
+
+#include "common/config.h"
+#include "common/logging.h"
+#include "gen_cpp/Types_types.h"
+#include "gen_cpp/types.pb.h"
+
+namespace doris {
+namespace {
+
+bthread_key_t query_log_key;
+std::atomic<bool> query_log_initialized {false};
+thread_local QueryLogIdentity* pthread_query_log_identity = nullptr;
+
+QueryLogIdentity* get_query_log_identity() {
+ if (bthread_self() != 0) {
+ return
static_cast<QueryLogIdentity*>(bthread_getspecific(query_log_key));
+ }
+ return pthread_query_log_identity;
+}
+
+void set_query_log_identity(QueryLogIdentity* identity) {
+ if (bthread_self() != 0) {
+ CHECK_EQ(0, bthread_setspecific(query_log_key, identity));
+ } else {
+ pthread_query_log_identity = identity;
+ }
+}
+
+// The caller provides space for 16 hex digits per half plus the separator.
+char* format_log_id(char* buffer, uint64_t hi, uint64_t lo) {
+ auto first = std::to_chars(buffer, buffer + 16, hi, 16);
+ *first.ptr++ = '-';
+ return std::to_chars(first.ptr, buffer + 33, lo, 16).ptr;
+}
+
+void write_log_id(std::ostream& stream, uint64_t hi, uint64_t lo) {
+ char buffer[33];
+ const auto* end = format_log_id(buffer, hi, lo);
+ stream.write(buffer, static_cast<std::streamsize>(end - buffer));
+}
+
+} // namespace
+
+QueryLogIdentity::QueryLogIdentity(const TUniqueId& query_id)
+ : query_hi(static_cast<uint64_t>(query_id.hi)),
+ query_lo(static_cast<uint64_t>(query_id.lo)) {}
+
+QueryLogIdentity::QueryLogIdentity(const PUniqueId& query_id)
+ : query_hi(static_cast<uint64_t>(query_id.hi())),
+ query_lo(static_cast<uint64_t>(query_id.lo())) {}
+
+QueryLogIdentity::QueryLogIdentity(const TUniqueId& query_id, const TUniqueId&
instance_id)
+ : QueryLogIdentity(query_id) {
+ instance_hi = static_cast<uint64_t>(instance_id.hi);
+ instance_lo = static_cast<uint64_t>(instance_id.lo);
+}
+
+QueryLogIdentity::QueryLogIdentity(const PUniqueId& query_id, const PUniqueId&
instance_id)
+ : QueryLogIdentity(query_id) {
+ instance_hi = static_cast<uint64_t>(instance_id.hi());
+ instance_lo = static_cast<uint64_t>(instance_id.lo());
+}
+
+void init_query_log_context() {
+ if (!config::sys_log_enable_query_id) {
+ return;
+ }
+ static std::once_flag once;
+ std::call_once(once, [] {
+ CHECK_EQ(0, bthread_key_create(&query_log_key, nullptr));
+ query_log_initialized.store(true, std::memory_order_release);
+ });
+}
+
+QueryLogIdentity current_query_log_identity() {
+ if (!query_log_initialized.load(std::memory_order_acquire)) {
+ return {};
+ }
+ auto* identity = get_query_log_identity();
+ return identity == nullptr ? QueryLogIdentity {} : *identity;
+}
+
+std::string query_id_log_suffix(const TUniqueId& query_id) {
+ const QueryLogIdentity query(query_id);
+ if (query.query_hi == 0 && query.query_lo == 0) {
+ return {};
+ }
+ const auto current = current_query_log_identity();
+ if (config::sys_log_enable_query_id && FLAGS_log_prefix &&
current.query_hi == query.query_hi &&
+ current.query_lo == query.query_lo) {
+ return {};
+ }
+ char buffer[36] = {' ', '['};
+ auto* end = format_log_id(buffer + 2, query.query_hi, query.query_lo);
+ *end++ = ']';
+ return {buffer, static_cast<size_t>(end - buffer)};
+}
+
+void ScopedQueryLogContext::reset(QueryLogIdentity identity) {
+ if (!query_log_initialized.load(std::memory_order_acquire)) {
+ return;
+ }
+ _identity = identity;
+ if (!_installed) {
+ _previous = get_query_log_identity();
+ set_query_log_identity(&_identity);
+ _installed = true;
+ }
+}
+
+ScopedQueryLogContext::~ScopedQueryLogContext() {
Review Comment:
[P3] Assert LIFO restoration in the destructor
The destructor restores `_previous` unconditionally. When a scope is
default-constructed and installed later via `reset()`, a non-LIFO use (`a`
default-constructed, `b(X)` installed, then `a.reset(Y)`) leaves the TLS
pointing at `b._identity` after `b` is destroyed. All current call sites are
LIFO, but a `DCHECK(get_query_log_identity() == &_identity)` here would catch
future misuse cheaply, in line with the AGENTS.md assertion style.
##########
fe/fe-core/src/main/java/org/apache/doris/qe/ConnectContext.java:
##########
@@ -1327,6 +1341,16 @@ public void cancelQuery(Status cancelReason) {
}
public void checkTimeout(long now) {
+ // Idle connections and metadata commands can retain an ID from the
preceding query.
+ boolean executingQuery = command == MysqlCommand.COM_QUERY || command
== MysqlCommand.COM_STMT_PREPARE
+ || command == MysqlCommand.COM_STMT_EXECUTE;
+ TUniqueId currentQueryId = executingQuery ? queryId : null;
+ try (QueryLogContext ignored = QueryLogContext.open(currentQueryId)) {
Review Comment:
[P3] Idle connections open an MDC scope every second
`ConnectPoolMgr` calls `checkTimeout()` for every connection once per
second. For idle connections `currentQueryId` is `null`, but a scope is still
opened and closed, which means two `ThreadContext` copy-on-write updates and
one allocation per connection per second. Skip the scope when `currentQueryId
== null`.
##########
fe/fe-core/src/main/java/org/apache/doris/qe/AutoCloseConnectContext.java:
##########
@@ -17,15 +17,19 @@
package org.apache.doris.qe;
+import org.apache.doris.common.QueryLogContext;
+
public class AutoCloseConnectContext implements AutoCloseable {
public final ConnectContext connectContext;
private final ConnectContext previousContext;
+ private final QueryLogContext queryLogContext;
public AutoCloseConnectContext(ConnectContext connectContext) {
this.previousContext = ConnectContext.get();
this.connectContext = connectContext;
+ this.queryLogContext = QueryLogContext.open(connectContext.queryId());
Review Comment:
[P2] Callers that pre-install the context make this scope restore the inner
id
`StreamingJobUtils.buildConnectContext()` calls `ctx.setThreadLocalInfo()`
and then `ctx.setQueryId(...)` **before** `new AutoCloseConnectContext(ctx)`.
At this point, therefore, `previousContext` is the internal ctx and
`QueryLogContext.open()` captures the internal id as the value to restore.
On `close()`, the MDC goes back to the internal SQL's id, not the caller's.
For example, on `DROP JOB` → `JobManager.unregisterJob` →
`StreamingInsertJob.cleanup()` → `JdbcSourceOffsetProvider.cleanMeta` →
`StreamingJobUtils.deleteJobMeta` → `execute(sql)`:
- the user's thread keeps logging under the internal id;
- `queryIdSuffix(context.queryId())` then appends the user id as well, so
one line shows two ids;
- on the `JobScheduler` thread the stale id is never cleared.
(The ConnectContext leak itself predates this PR; this PR turns it into a
wrong log prefix.) Suggest removing the pre-installation from
`buildConnectContext()` so that `AutoCloseConnectContext` does the install.
##########
fe/fe-core/src/main/java/org/apache/doris/qe/StmtExecutor.java:
##########
@@ -1359,7 +1362,7 @@ private void handleQueryWithRetry(TUniqueId queryId)
throws Exception {
// the plan would read nothing, or only what the failed
attempt left, and succeed.
LOG.warn("not retrying query {} with the same plan: a scan
node's ranges cannot be read"
+ " again by the backend. stmt: {}",
- DebugUtil.printId(context.queryId()),
parsedStmt.getOrigStmt().originStmt);
+ QueryLogContext.queryIdSuffix(context.queryId()),
parsedStmt.getOrigStmt().originStmt);
Review Comment:
[P3] Double space in the rewritten message
The format string at :1363 is still `"not retrying query {} with ..."`, but
the argument is now `queryIdSuffix(...)`, which returns `""` or `" [id]"`. The
output becomes `query with` or `query [id] with`. Use `"not retrying query{}
with ..."`.
##########
fe/fe-core/src/main/java/org/apache/doris/common/QueryLogContext.java:
##########
@@ -0,0 +1,145 @@
+// Licensed to the Apache Software Foundation (ASF) under one
+// or more contributor license agreements. See the NOTICE file
+// distributed with this work for additional information
+// regarding copyright ownership. The ASF licenses this file
+// to you under the Apache License, Version 2.0 (the
+// "License"); you may not use this file except in compliance
+// with the License. You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing,
+// software distributed under the License is distributed on an
+// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+// KIND, either express or implied. See the License for the
+// specific language governing permissions and limitations
+// under the License.
+
+package org.apache.doris.common;
+
+import org.apache.doris.common.util.DebugUtil;
+import org.apache.doris.proto.Types.PUniqueId;
+import org.apache.doris.thrift.TUniqueId;
+
+import org.apache.logging.log4j.ThreadContext;
+
+import java.util.concurrent.Executor;
+import java.util.function.Supplier;
+
+/** Query identity for runtime LogEvents, independent of connection and query
object lifetimes. */
+public final class QueryLogContext implements AutoCloseable {
+ public static final String QUERY_ID = "query_id";
+ private static final QueryLogContext NOOP = new QueryLogContext();
+ private static final ThreadLocal<String> PLANNING_QUERY_ID = new
ThreadLocal<>();
+
+ private final String previousQueryId;
+ private final boolean installed;
+
+ private QueryLogContext() {
+ previousQueryId = null;
+ installed = false;
+ }
+
+ private QueryLogContext(String queryId) {
+ previousQueryId = ThreadContext.get(QUERY_ID);
+ installed = true;
+ set(queryId);
+ }
+
+ public static QueryLogContext open(TUniqueId queryId) {
+ return Config.sys_log_enable_query_id ? new
QueryLogContext(format(queryId)) : NOOP;
+ }
+
+ /** Internal planning connections without an ID inherit the enclosing
planning identity. */
+ public static <T> T withPlanningContext(TUniqueId queryId, Supplier<T>
action) {
+ if (!Config.sys_log_enable_query_id) {
+ return action.get();
+ }
+ String previous = PLANNING_QUERY_ID.get();
+ String current = queryId == null ? previous : format(queryId);
+ PLANNING_QUERY_ID.set(current);
+ try (QueryLogContext ignored = new QueryLogContext(current)) {
+ return action.get();
+ } finally {
+ if (previous == null) {
+ PLANNING_QUERY_ID.remove();
+ } else {
+ PLANNING_QUERY_ID.set(previous);
+ }
+ }
+ }
+
+ public static void setQueryId(TUniqueId queryId) {
+ if (Config.sys_log_enable_query_id) {
+ set(format(queryId));
+ }
+ }
+
+ public static void clear() {
+ if (Config.sys_log_enable_query_id) {
+ ThreadContext.remove(QUERY_ID);
+ }
+ }
+
+ /**
+ * Keep the query ID in a runtime message only when the prefix does not
already contain it.
+ * This preserves attribution when logging is disabled or the caller has
no query context.
+ * Audit/protocol fields and IDs relating different queries must remain
explicit.
+ */
+ public static String queryIdSuffix(TUniqueId queryId) {
+ return suffix(format(queryId));
+ }
+
+ public static String queryIdSuffix(PUniqueId queryId) {
Review Comment:
[P3] Test-only leftovers
`queryIdSuffix(PUniqueId)`, the old `FlightSqlChannel` overloads (:56-58,
:108-110) and the 2-argument `FlightSqlResultCacheEntry` constructor are now
called only from tests. Please remove them, or migrate the tests to the
production entry points.
##########
fe/fe-core/src/main/java/org/apache/doris/nereids/NereidsPlanner.java:
##########
@@ -219,6 +220,12 @@ public Plan planWithLock(LogicalPlan plan,
PhysicalProperties requireProperties,
*/
private Plan planWithLock(LogicalPlan plan, PhysicalProperties
requireProperties,
ExplainLevel explainLevel, boolean showPlanProcess, Consumer<Plan>
lockCallback) {
+ return
QueryLogContext.withPlanningContext(statementContext.getConnectContext().queryId(),
+ () -> planWithLockInternal(plan, requireProperties,
explainLevel, showPlanProcess, lockCallback));
+ }
+
+ private Plan planWithLockInternal(LogicalPlan plan, PhysicalProperties
requireProperties,
Review Comment:
[P2] Conflicts and duplicated logic with #68727
A `git merge-tree` trial merge with #68727 conflicts in this file and in
`ConnectContext.checkTimeout`: both PRs split `planWithLock` into a
`planWithLockInternal` with their own wrapper, and #68727 moves the
`dumpNereidsMemo` log line that this PR rewrites.
Both PRs also implement "nested planning inherits the outer query id"
independently (`QueryLogContext.PLANNING_QUERY_ID` here,
`PlanningDiagnostics.inheritsQueryIdentity` there). Both use the MDC key
`"query_id"`, but #68727 hardcodes it and ignores `sys_log_enable_query_id`.
The two can be combined, with `withPlanningContext` outer and
`PlanningDiagnostics.plan` inner, but please agree on a merge order with
#68727. Whichever lands second should reuse `QueryLogContext`'s key and
inheritance logic.
##########
fe/fe-core/src/main/java/org/apache/doris/arrowflight/DorisFlightSqlProducer.java:
##########
@@ -220,6 +224,8 @@ private FlightInfo executeQueryStatement(String
peerIdentity, ConnectContext con
final FlightDescriptor descriptor) {
try {
Preconditions.checkState(null != connectContext);
+ // A new request has no query identity until statement execution
assigns one.
+ connectContext.resetQueryId();
Review Comment:
[P3] `resetQueryId()` now runs three times per Flight statement
The three calls are here, at `FlightSqlConnectProcessor.java:94`, and at
`ConnectProcessor.handleQuery()` (:221). `lastQueryId` semantics are preserved,
because the later calls are no-ops, but changing query-id state at three places
only for logging purposes is fragile. Keep one.
##########
be/src/util/brpc_closure.h:
##########
@@ -127,6 +129,7 @@ class AutoReleaseClosure : public google::protobuf::Closure
{
// Releases per-RPC resources, invokes the callback if it is still alive,
and then deletes itself.
void Run() override {
+ ScopedQueryLogContext query_log_scope(query_log_identity_);
Review Comment:
[P3] Include what you use
This file, together with `result_block_buffer.cpp`,
`varrow_flight_result_writer.cpp`, `fragment_mgr.cpp`, `internal_service.cpp`
and `pipeline_fragment_context.cpp`, uses `ScopedQueryLogContext` /
`query_id_log_suffix` but gets `common/query_log_context.h` only transitively
through `runtime/thread_context.h`. `query_context.cpp` and `pipeline_task.cpp`
include it directly, so please include it directly here too.
##########
be/src/service/internal_service.h:
##########
@@ -259,8 +261,8 @@ class PInternalService : public PBackendService {
Status _exec_plan_fragment_impl(const std::string& s_request,
PFragmentRequestVersion version,
bool compact,
- const std::function<void(RuntimeState*,
Status*)>& cb =
- std::function<void(RuntimeState*,
Status*)>());
+ const std::function<void(RuntimeState*,
Status*)>& cb = {},
+ ScopedQueryLogContext* query_log_scope =
nullptr);
Review Comment:
[P3] Logging concern leaks into the API
`_exec_plan_fragment_impl` gained a `ScopedQueryLogContext*` out-parameter
only to keep the log scope alive. It is also `reset` once per fragment,
although all fragments in one request share the query id. Consider opening the
scope at the RPC entry, where the query id is already known, and keeping the
signature unchanged.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
