[
https://issues.apache.org/jira/browse/IMPALA-12878?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17824204#comment-17824204
]
Michael Smith commented on IMPALA-12878:
----------------------------------------
I think these are the relevant logs
{code}
I0305 23:36:03.451594 9555 impala-server.cc:1757] Cancel():
query_id=4a44182cfdd8b9ff:657a80a800000000
I0305 23:36:03.451778 9555 impala-beeswax-server.cc:278] close():
query_id=4a44182cfdd8b9ff:657a80a800000000
I0305 23:36:03.451787 9555 impala-server.cc:1531] UnregisterQuery():
query_id=4a44182cfdd8b9ff:657a80a800000000
I0305 23:36:03.451783 11258 client-request-state.cc:636]
4a44182cfdd8b9ff:657a80a800000000] Cancelled right after starting the
coordinator query id=4a44182cfdd8b9ff:657a80a800000000
I0305 23:36:03.451812 11258 coordinator.cc:794]
4a44182cfdd8b9ff:657a80a800000000] ExecState: query
id=4a44182cfdd8b9ff:657a80a800000000 execution cancelled
I0305 23:36:03.451833 11258 coordinator-backend-state.cc:1021]
4a44182cfdd8b9ff:657a80a800000000] query_id=4a44182cfdd8b9ff:657a80a800000000
target backend=127.0.0.1:27000: Sending CancelQueryFInstances rpc
I0305 23:36:03.452204 3752 control-service.cc:219] CancelQueryFInstances():
query_id=4a44182cfdd8b9ff:657a80a800000000
I0305 23:36:03.452219 3752 query-exec-mgr.cc:126] QueryState:
query_id=4a44182cfdd8b9ff:657a80a800000000 refcnt=5
I0305 23:36:03.452224 3752 query-state.cc:1010] Cancel:
query_id=4a44182cfdd8b9ff:657a80a800000000
I0305 23:36:03.452236 3752 krpc-data-stream-mgr.cc:339] cancelling active
streams for query_id=4a44182cfdd8b9ff:657a80a800000000
I0305 23:36:03.452373 11258 coordinator-backend-state.cc:1021]
4a44182cfdd8b9ff:657a80a800000000] query_id=4a44182cfdd8b9ff:657a80a800000000
target backend=127.0.0.1:27001: Sending CancelQueryFInstances rpc
I0305 23:36:03.453058 11258 coordinator-backend-state.cc:1021]
4a44182cfdd8b9ff:657a80a800000000] query_id=4a44182cfdd8b9ff:657a80a800000000
target backend=127.0.0.1:27002: Sending CancelQueryFInstances rpc
I0305 23:36:03.453500 11258 coordinator.cc:1085]
4a44182cfdd8b9ff:657a80a800000000] CancelBackends()
query_id=4a44182cfdd8b9ff:657a80a800000000, tried to cancel 3 backends
I0305 23:36:03.453569 11258 coordinator.cc:1463]
4a44182cfdd8b9ff:657a80a800000000] Release admission control resources for
query_id=4a44182cfdd8b9ff:657a80a800000000
I0305 23:36:03.453965 11263 impala-server.cc:1531] UnregisterQuery():
query_id=4a44182cfdd8b9ff:657a80a800000000
I0305 23:36:03.454357 11263 impala-server.cc:2564] Connection
b541419b2edcb47e:2e0d6bb7ea5852a7 from client 127.0.0.1:45146 to server
beeswax-frontend closed. The connection had 1 associated session(s).
I0305 23:36:03.454368 11263 impala-server.cc:1771] Closing session:
b541419b2edcb47e:2e0d6bb7ea5852a7
I0305 23:36:03.454384 11263 impala-server.cc:1818] Closed session:
b541419b2edcb47e:2e0d6bb7ea5852a7, client address: <127.0.0.1:45146>.
I0305 23:36:03.455348 3931 impala-server.cc:1563] Query successfully
unregistered: query_id=4a44182cfdd8b9ff:657a80a800000000
...
I0305 23:36:03.455291 9555 status.cc:129] Query not yet running
{code}
UnregisterQuery is called twice. This scenario relies on the 1st call to
UnregisterQuery being delayed until after the 2nd call (which passes
check_inflight=false because as part of closing the session) has completed
Finalize. Which seems to happen, as thread 9555 hits "Query not yet running"
just after the query is successfully unregisterd. Although for some reason
they're printed out of timestamp order.
> TestResultSpoolingCancellation.test_cancellation failed in UBSAN build
> ----------------------------------------------------------------------
>
> Key: IMPALA-12878
> URL: https://issues.apache.org/jira/browse/IMPALA-12878
> Project: IMPALA
> Issue Type: Bug
> Components: Backend
> Affects Versions: Impala 4.4.0
> Reporter: Riza Suminto
> Assignee: Michael Smith
> Priority: Major
> Labels: broken-build
>
> TestResultSpoolingCancellation.test_cancellation failed in UBSAN build. The
> following are the error messages.
> {code:java}
> Error Message
> query_test/test_result_spooling.py:356: in test_cancellation
> vector.get_value('cancel_delay')) util/cancel_util.py:99: in
> cancel_query_and_validate_state assert 'Invalid or unknown query handle'
> in str(close_error) E assert 'Invalid or unknown query handle' in
> "ImpalaBeeswaxException:\n INNER EXCEPTION: <class
> 'beeswaxd.ttypes.BeeswaxException'>\n MESSAGE: Query not yet running\n" E
> + where "ImpalaBeeswaxException:\n INNER EXCEPTION: <class
> 'beeswaxd.ttypes.BeeswaxException'>\n MESSAGE: Query not yet running\n" =
> str(ImpalaBeeswaxException())
> Stacktrace
> query_test/test_result_spooling.py:356: in test_cancellation
> vector.get_value('cancel_delay'))
> util/cancel_util.py:99: in cancel_query_and_validate_state
> assert 'Invalid or unknown query handle' in str(close_error)
> E assert 'Invalid or unknown query handle' in "ImpalaBeeswaxException:\n
> INNER EXCEPTION: <class 'beeswaxd.ttypes.BeeswaxException'>\n MESSAGE: Query
> not yet running\n"
> E + where "ImpalaBeeswaxException:\n INNER EXCEPTION: <class
> 'beeswaxd.ttypes.BeeswaxException'>\n MESSAGE: Query not yet running\n" =
> str(ImpalaBeeswaxException())
> Standard Error
> SET
> client_identifier=query_test/test_result_spooling.py::TestResultSpoolingCancellation::()::test_cancellation[query:selectl_returnflagfromtpch_parquet.lineitem|protocol:beeswax|exec_option:{'test_replan':1;'batch_size':0;'num_nodes':0;'disable_codegen_rows_threshold':0;'disa;
> -- executing against localhost:21000
> use tpch_parquet;
> -- 2024-03-05 23:36:03,429 INFO MainThread: Started query
> 8241403abf8b7dbb:4db1deee00000000
> SET
> client_identifier=query_test/test_result_spooling.py::TestResultSpoolingCancellation::()::test_cancellation[query:selectl_returnflagfromtpch_parquet.lineitem|protocol:beeswax|exec_option:{'test_replan':1;'batch_size':0;'num_nodes':0;'disable_codegen_rows_threshold':0;'disa;
> SET spool_query_results=true;
> SET test_replan=1;
> SET batch_size=0;
> SET num_nodes=0;
> SET disable_codegen_rows_threshold=0;
> SET disable_codegen=False;
> SET abort_on_error=1;
> SET exec_single_node_rows_threshold=0;
> -- executing async: localhost:21000
> select l_returnflag from tpch_parquet.lineitem;
> -- 2024-03-05 23:36:03,437 INFO MainThread: Started query
> 4a44182cfdd8b9ff:657a80a800000000
> SET
> client_identifier=query_test/test_result_spooling.py::TestResultSpoolingCancellation::()::test_cancellation[query:selectl_returnflagfromtpch_parquet.lineitem|protocol:beeswax|exec_option:{'test_replan':1;'batch_size':0;'num_nodes':0;'disable_codegen_rows_threshold':0;'disa;
> -- connecting to: localhost:21000
> -- 2024-03-05 23:36:03,437 INFO Thread-24: Could not connect to ('::1',
> 21000, 0, 0)
> Traceback (most recent call last):
> File
> "/data/jenkins/workspace/impala-cdw-master-staging-core-ubsan/repos/Impala/infra/python/env-gcc10.4.0/lib/python2.7/site-packages/thrift/transport/TSocket.py",
> line 137, in open
> handle.connect(sockaddr)
> File
> "/data/jenkins/workspace/impala-cdw-master-staging-core-ubsan/Impala-Toolchain/toolchain-packages-gcc10.4.0/python-2.7.16/lib/python2.7/socket.py",
> line 228, in meth
> return getattr(self._sock,name)(*args)
> error: [Errno 111] Connection refused
> -- fetching results from: <tests.common.impala_connection.OperationHandle
> object at 0x7fd2b172a410>
> -- getting state for operation:
> <tests.common.impala_connection.OperationHandle object at 0x7fd2b172a410>
> -- canceling operation: <tests.common.impala_connection.OperationHandle
> object at 0x7fd2b172a410>
> -- closing query for operation handle:
> <tests.common.impala_connection.OperationHandle object at 0x7fd2b172a410>
> -- getting runtime profile operation:
> <tests.common.impala_connection.OperationHandle object at 0x7fd2b172a410>
> {code}
> Error message "Query not yet running" is recently introduced in IMPALA-12493.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
