Quanlong Huang created IMPALA-12711:
---------------------------------------
Summary: DDL/DML errors are not shown in impalad logs
Key: IMPALA-12711
URL: https://issues.apache.org/jira/browse/IMPALA-12711
Project: IMPALA
Issue Type: Bug
Components: Backend
Reporter: Quanlong Huang
Assignee: Quanlong Huang
Since IMPALA-10811, DDLs are executed in an async thread by default. The errors
are not logged after that. For instance, run "INVALIDATE METADATA a.b" on an
inexisting table, the error shown in the client is "ERROR:
TableNotFoundException: Table not found: a.b". However, in the impalad logs, it
looks like the statement succeeds.
{noformat}
I0115 13:47:43.256397 23443 Frontend.java:2072]
dc497affd5678498:365a460000000000] Analyzing query: INVALIDATE METADATA a.b db:
default
I0115 13:47:43.256489 23443 Frontend.java:2084]
dc497affd5678498:365a460000000000] The original executor group sets from
executor membership snapshot: [TExecutorGroupSet(curr_num_executors:3,
expected_num_executors:20, exec_group_name_prefix:)]
I0115 13:47:43.256561 23443 RequestPoolService.java:200]
dc497affd5678498:365a460000000000] Default pool only, scheduler allocation is
not specified.
I0115 13:47:43.256652 23443 Frontend.java:2104]
dc497affd5678498:365a460000000000] A total of 1 executor group sets to be
considered for auto-scaling: [TExecutorGroupSet(curr_num_executors:3,
expected_num_executors:20, exec_group_name_prefix:,
max_mem_limit:9223372036854775807, num_cores_per_executor:2147483647)]
I0115 13:47:43.256775 23443 Frontend.java:2138]
dc497affd5678498:365a460000000000] Consider executor group set:
TExecutorGroupSet(curr_num_executors:3, expected_num_executors:20,
exec_group_name_prefix:, max_mem_limit:9223372036854775807,
num_cores_per_executor:2147483647) with assumption of 0 cores per node.
I0115 13:47:43.263244 23443 AnalysisContext.java:508]
dc497affd5678498:365a460000000000] Analysis took 4 ms
I0115 13:47:43.264606 23443 BaseAuthorizationChecker.java:114]
dc497affd5678498:365a460000000000] Authorization check took 1 ms
I0115 13:47:43.264681 23443 Frontend.java:2400]
dc497affd5678498:365a460000000000] Analysis and authorization finished.
I0115 13:47:43.301832 23443 Frontend.java:2319]
dc497affd5678498:365a460000000000] Selected executor group:
TExecutorGroupSet(curr_num_executors:3, expected_num_executors:20,
exec_group_name_prefix:, max_mem_limit:9223372036854775807,
num_cores_per_executor:2147483647), reason: query is not auto-scalable
I0115 13:47:43.305258 23443 client-request-state.cc:785]
dc497affd5678498:365a460000000000] DDL exec mode=asynchronous
I0115 13:47:43.306367 23443 impala-hs2-server.cc:573] ExecuteStatement():
return_val=TExecuteStatementResp {
01: status (struct) = TStatus {
01: statusCode (i32) = 0,
},
02: operationHandle (struct) = TOperationHandle {
01: operationId (struct) = THandleIdentifier {
01: guid (string) = "\x98\x84g\xd5\xffzI\xdc\x00\x00\x00\x00\x00FZ6",
02: secret (string) = "<HIDDEN>",
},
02: operationType (i32) = 0,
03: hasResultSet (bool) = false,
},
}
I0115 13:47:43.509263 23443 impala-hs2-server.cc:887] CloseOperation():
query_id=dc497affd5678498:365a460000000000
I0115 13:47:43.509281 23443 impala-server.cc:1554] UnregisterQuery():
query_id=dc497affd5678498:365a460000000000
I0115 13:47:43.509642 23298 impala-server.cc:1586] Query successfully
unregistered: query_id=dc497affd5678498:365a460000000000{noformat}
If the DDL is executed with "set enable_async_ddl_execution=false", the error
is shown in the logs:
{noformat}
I0115 13:48:31.054708 23794 Frontend.java:2072]
8a48ab2ae184395d:dd53cfc100000000] Analyzing query: INVALIDATE METADATA a.b db:
default
I0115 13:48:31.054780 23794 Frontend.java:2084]
8a48ab2ae184395d:dd53cfc100000000] The original executor group sets from
executor membership snapshot: [TExecutorGroupSet(curr_num_executors:3,
expected_num_executors:20, exec_group_name_prefix:)]
I0115 13:48:31.054841 23794 RequestPoolService.java:200]
8a48ab2ae184395d:dd53cfc100000000] Default pool only, scheduler allocation is
not specified.
I0115 13:48:31.054934 23794 Frontend.java:2104]
8a48ab2ae184395d:dd53cfc100000000] A total of 1 executor group sets to be
considered for auto-scaling: [TExecutorGroupSet(curr_num_executors:3,
expected_num_executors:20, exec_group_name_prefix:,
max_mem_limit:9223372036854775807, num_cores_per_executor:2147483647)]
I0115 13:48:31.055053 23794 Frontend.java:2138]
8a48ab2ae184395d:dd53cfc100000000] Consider executor group set:
TExecutorGroupSet(curr_num_executors:3, expected_num_executors:20,
exec_group_name_prefix:, max_mem_limit:9223372036854775807,
num_cores_per_executor:2147483647) with assumption of 0 cores per node.
I0115 13:48:31.055748 23794 AnalysisContext.java:508]
8a48ab2ae184395d:dd53cfc100000000] Analysis took 0 ms
I0115 13:48:31.055960 23794 BaseAuthorizationChecker.java:114]
8a48ab2ae184395d:dd53cfc100000000] Authorization check took 0 ms
I0115 13:48:31.056037 23794 Frontend.java:2400]
8a48ab2ae184395d:dd53cfc100000000] Analysis and authorization finished.
I0115 13:48:31.056233 23794 Frontend.java:2319]
8a48ab2ae184395d:dd53cfc100000000] Selected executor group:
TExecutorGroupSet(curr_num_executors:3, expected_num_executors:20,
exec_group_name_prefix:, max_mem_limit:9223372036854775807,
num_cores_per_executor:2147483647), reason: query is not auto-scalable
I0115 13:48:31.056829 23794 client-request-state.cc:785]
8a48ab2ae184395d:dd53cfc100000000] DDL exec mode=synchronous
I0115 13:48:31.191787 23794 client-request-state.cc:264]
8a48ab2ae184395d:dd53cfc100000000] TableNotFoundException: Table not found: a.b
// <---- This is the error we should log
I0115 13:48:31.191802 23794 impala-server.cc:1554]
8a48ab2ae184395d:dd53cfc100000000] UnregisterQuery():
query_id=8a48ab2ae184395d:dd53cfc100000000
I0115 13:48:31.192154 23300 impala-server.cc:1586] Query successfully
unregistered: query_id=8a48ab2ae184395d:dd53cfc100000000
{noformat}
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
