This is an automated email from the ASF dual-hosted git repository. stigahuang pushed a commit to branch branch-4.4.1 in repository https://gitbox.apache.org/repos/asf/impala.git
commit cb37ad441d6f7d62f94eb5b2a64f3089a6a59d51 Author: Michael Smith <[email protected]> AuthorDate: Tue Jul 23 13:11:30 2024 -0700 IMPALA-13252: Consistently use PrintId to print TUniqueId Some logging formats TUniqueId inconsistently by relying on the Thrift to_string/toString generated printers. This makes it difficult to track a specific query through logs. Adds operator<<(ostream, TUniqueId) to simplify logging TUniqueId correctly, uses PrintId instead of toString in Java, and adds a verifier to test_banned_log_messages to ensure TUniqueId is not printed in logs. Change-Id: If01bf20a240debbbd4c0a22798045ea03f17b28e Reviewed-on: http://gerrit.cloudera.org:8080/21606 Reviewed-by: Yida Wu <[email protected]> Tested-by: Impala Public Jenkins <[email protected]> --- be/src/util/debug-util.h | 4 ++++ .../org/apache/impala/catalog/local/CatalogdMetaProvider.java | 4 +++- .../java/org/apache/impala/common/KuduTransactionManager.java | 11 +++++++---- fe/src/main/java/org/apache/impala/service/Frontend.java | 11 ++++++----- tests/common/patterns.py | 7 +++++++ tests/custom_cluster/test_custom_statestore.py | 5 +++-- tests/verifiers/test_banned_log_messages.py | 5 +++++ 7 files changed, 35 insertions(+), 12 deletions(-) diff --git a/be/src/util/debug-util.h b/be/src/util/debug-util.h index 4d7255e45..fcec0e7dc 100644 --- a/be/src/util/debug-util.h +++ b/be/src/util/debug-util.h @@ -74,6 +74,10 @@ constexpr int TUniqueIdBufferSize = 33; void PrintIdCompromised(const TUniqueId& id, char out[TUniqueIdBufferSize], const char separator = ':'); +inline ostream& operator<<(ostream& os, const TUniqueId& id) { + return os << PrintId(id); +} + inline ostream& operator<<(ostream& os, const UniqueIdPB& id) { return os << PrintId(id); } diff --git a/fe/src/main/java/org/apache/impala/catalog/local/CatalogdMetaProvider.java b/fe/src/main/java/org/apache/impala/catalog/local/CatalogdMetaProvider.java index fb80adb2b..79789f04e 100644 --- a/fe/src/main/java/org/apache/impala/catalog/local/CatalogdMetaProvider.java +++ b/fe/src/main/java/org/apache/impala/catalog/local/CatalogdMetaProvider.java @@ -17,6 +17,8 @@ package org.apache.impala.catalog.local; +import static org.apache.impala.util.TUniqueIdUtil.PrintId; + import java.lang.management.ManagementFactory; import java.nio.ByteBuffer; import java.util.ArrayList; @@ -1571,7 +1573,7 @@ public class CatalogdMetaProvider implements MetaProvider { if (!catalogServiceId_.equals(Catalog.INITIAL_CATALOG_SERVICE_ID)) { LOG.warn("Detected catalog service restart: service ID changed from " + "{} to {}. Invalidating all cached metadata on this coordinator.", - catalogServiceId_, serviceId); + PrintId(catalogServiceId_), PrintId(serviceId)); } catalogServiceId_ = serviceId; cache_.invalidateAll(); diff --git a/fe/src/main/java/org/apache/impala/common/KuduTransactionManager.java b/fe/src/main/java/org/apache/impala/common/KuduTransactionManager.java index e31ab0b57..77305b3a2 100644 --- a/fe/src/main/java/org/apache/impala/common/KuduTransactionManager.java +++ b/fe/src/main/java/org/apache/impala/common/KuduTransactionManager.java @@ -17,11 +17,14 @@ package org.apache.impala.common; +import static org.apache.impala.util.TUniqueIdUtil.PrintId; + import java.util.concurrent.ConcurrentHashMap; import org.apache.impala.thrift.TUniqueId; import org.apache.kudu.client.KuduTransaction; -import org.apache.log4j.Logger; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import com.google.common.base.Preconditions; @@ -33,7 +36,7 @@ import com.google.common.base.Preconditions; * to commit or rollback the transaction. */ public class KuduTransactionManager { - public static final Logger LOG = Logger.getLogger(KuduTransactionManager.class); + public static final Logger LOG = LoggerFactory.getLogger(KuduTransactionManager.class); // Map of Kudu transactions. // It's thread safe. @@ -62,8 +65,8 @@ public class KuduTransactionManager { Preconditions.checkNotNull(queryId); KuduTransaction txn = transactions_.remove(queryId); if (txn == null) { - LOG.info("Kudu transaction with query-id " + queryId + " was already removed " - + "from KuduTransactionManager object or never existed."); + LOG.info("Kudu transaction with query-id {} was already removed " + + "from KuduTransactionManager object or never existed.", PrintId(queryId)); }; return txn; } diff --git a/fe/src/main/java/org/apache/impala/service/Frontend.java b/fe/src/main/java/org/apache/impala/service/Frontend.java index 4da39d05a..92f0bfa3c 100644 --- a/fe/src/main/java/org/apache/impala/service/Frontend.java +++ b/fe/src/main/java/org/apache/impala/service/Frontend.java @@ -18,6 +18,7 @@ package org.apache.impala.service; import static org.apache.impala.common.ByteUnits.MEGABYTE; +import static org.apache.impala.util.TUniqueIdUtil.PrintId; import com.google.common.annotations.VisibleForTesting; import com.google.common.base.MoreObjects; @@ -2726,7 +2727,7 @@ public class Frontend { planCtx.compilationState_.setKuduTransactionToken(null); abortKuduTransaction(queryCtx.getQuery_id()); timeline.markEvent( - "Kudu transaction aborted: " + queryCtx.getQuery_id().toString()); + "Kudu transaction aborted: " + PrintId(queryCtx.getQuery_id())); } catch (TransactionException te) { LOG.error("Could not abort transaction because: " + te.getMessage()); } @@ -3201,10 +3202,10 @@ public class Frontend { KuduTransaction txn = null; try { // Open Kudu transaction. - LOG.info("Open Kudu transaction: " + queryCtx.getQuery_id().toString()); + LOG.info("Open Kudu transaction: {}", PrintId(queryCtx.getQuery_id())); txn = client.newTransaction(); timeline.markEvent( - "Kudu transaction opened with query id: " + queryCtx.getQuery_id().toString()); + "Kudu transaction opened with query id: " + PrintId(queryCtx.getQuery_id())); token = txn.serialize(); if (analysisResult.isUpdateStmt()) { analysisResult.getUpdateStmt().setKuduTransactionToken(token); @@ -3229,7 +3230,7 @@ public class Frontend { * @param queryId is the id of the query. */ public void abortKuduTransaction(TUniqueId queryId) throws TransactionException { - LOG.info("Abort Kudu transaction: " + queryId.toString()); + LOG.info("Abort Kudu transaction: {}", PrintId(queryId)); KuduTransaction txn = kuduTxnManager_.deleteTransaction(queryId); Preconditions.checkNotNull(txn); if (txn != null) { @@ -3250,7 +3251,7 @@ public class Frontend { * @param queryId is the id of the query. */ public void commitKuduTransaction(TUniqueId queryId) throws TransactionException { - LOG.info("Commit Kudu transaction: " + queryId.toString()); + LOG.info("Commit Kudu transaction: {}", PrintId(queryId)); KuduTransaction txn = kuduTxnManager_.deleteTransaction(queryId); Preconditions.checkNotNull(txn); if (txn != null) { diff --git a/tests/common/patterns.py b/tests/common/patterns.py index 1214e5e37..850feb541 100644 --- a/tests/common/patterns.py +++ b/tests/common/patterns.py @@ -24,7 +24,14 @@ import re # http://www.cloudera.com/content/www/en-us/documentation/enterprise/latest/topics/impala_identifiers.html VALID_IMPALA_IDENTIFIER_REGEX = re.compile(r'^[a-zA-Z][a-zA-Z0-9_]{,127}$') +INT64_MASK = (1 << 64) - 1 + def is_valid_impala_identifier(identifier): """Return True if identifier is a valid Impala identifier, False otherwise.""" return VALID_IMPALA_IDENTIFIER_REGEX.match(identifier) is not None + + +def print_id(id): + """Stringify a TUniqueId as e.g. 8a4673c8fbe83a74:309751e900000000""" + return '{:016x}:{:016x}'.format(id.hi & INT64_MASK, id.lo & INT64_MASK) diff --git a/tests/custom_cluster/test_custom_statestore.py b/tests/custom_cluster/test_custom_statestore.py index 8693b9834..ef0dbd817 100644 --- a/tests/custom_cluster/test_custom_statestore.py +++ b/tests/custom_cluster/test_custom_statestore.py @@ -32,6 +32,7 @@ from tests.common.custom_cluster_test_suite import CustomClusterTestSuite from tests.common.environ import build_flavor_timeout from tests.common.skip import SkipIfBuildType from tests.common.impala_test_suite import ImpalaTestSuite +from tests.common.patterns import print_id from time import sleep from Types.ttypes import TNetworkAddress @@ -118,8 +119,8 @@ class TestCustomStatestore(CustomClusterTestSuite): for x in range(20): response = self.__register_subscriber() if response.status.status_code == TErrorCode.OK: - self.registration_id = response.registration_id - LOG.log(logging.INFO, "Registration id %s, x=%d" % (response.registration_id, x)) + LOG.log(logging.INFO, "Registration id %s, x=%d" % ( + print_id(response.registration_id), x)) else: assert 'Maximum subscriber limit reached:' in ''.join(response.status.error_msgs) return diff --git a/tests/verifiers/test_banned_log_messages.py b/tests/verifiers/test_banned_log_messages.py index 6a5cf483b..2b70f45a0 100644 --- a/tests/verifiers/test_banned_log_messages.py +++ b/tests/verifiers/test_banned_log_messages.py @@ -42,3 +42,8 @@ class TestBannedLogMessages: def test_no_unsupported_operations(self): """Test that cluster logs do not contain jamm.CannotAccessFieldException""" self.assert_message_absent('CannotAccessFieldException') + + def test_no_tuniqueid(self): + """Test that cluster logs do not contain TUniqueId. They should instead print + IDs with the format 8a4673c8fbe83a74:309751e900000000.""" + self.assert_message_absent('[^a-zA-Z]TUniqueId(')
