Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

ctrl+c hang up on oracle #3635

Closed
sergun opened this issue Jul 27, 2021 · 1 comment
Closed

ctrl+c hang up on oracle #3635

sergun opened this issue Jul 27, 2021 · 1 comment
Labels
bug Something isn't working

Comments

@sergun
Copy link

sergun commented Jul 27, 2021

Posted this bug to both dbt and dbt-oracle repositories since not sure if the issue relates to dbt or oracle adapter:
techindicium/dbt-oracle#23

  • Oracle DBT version:
    dbt-core 0.19.2
    dbt-oracle 0.4.3
  • Python version:
    3.9.6
  • Operating System:
    Linux f034a66acec7 3.10.0-957.el7.x86_64 Configs and docs #1 SMP Thu Nov 8 23:39:32 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

Description

dbt cli does not stop when try to interrupt execution by ctrl+c

What I Did

Executed dbt project by:
dbt --debug run
and
pressed ctrl+c a few times after execution of some SQL-query started

dbt only ends after I manually kill some of ORACLE sessions being executed the query.

from x
^C2021-07-27 16:49:39.349302 (MainThread): Acquiring new oracle connection "master".
2021-07-27 16:49:39.349622 (MainThread): Cancelling query 'model.my_new_project.table1'
^C^C^C^C^C2021-07-27 16:50:25.722387 (Thread-1): Oracle error: DPI-1002: invalid OCI handle
2021-07-27 16:51:16.768438 (Thread-1): On model.my_new_project.table1: ROLLBACK
2021-07-27 16:51:16.769097 (MainThread): Connection 'master' was properly closed.
2021-07-27 16:51:16.769974 (MainThread): Connection 'model.my_new_project.table1' was left open.
2021-07-27 16:51:16.770296 (MainThread): On model.my_new_project.table1: ROLLBACK
2021-07-27 16:51:16.769617 (Thread-1): Failed to rollback model.my_new_project.table1
Traceback (most recent call last):
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/oracle/connections.py", line 153, in exception_handler
    yield
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/oracle/connections.py", line 210, in add_query
    cursor.execute(sql, bindings)
cx_Oracle.DatabaseError: DPI-1002: invalid OCI handle

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/base/connections.py", line 221, in _rollback_handle
    connection.handle.rollback()
cx_Oracle.OperationalError: ORA-03114: not connected to ORACLE
2021-07-27 16:51:16.773197 (Thread-1): On model.my_new_project.table1: Close
2021-07-27 16:51:16.770619 (MainThread): Failed to rollback model.my_new_project.table1
Traceback (most recent call last):
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/task/runnable.py", line 339, in execute_nodes
    self.run_queue(pool)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/task/runnable.py", line 264, in run_queue
    self.job_queue.join()
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/graph/queue.py", line 173, in join
    self.inner.join()
  File "/home/user1/.conda/envs/sql/lib/python3.9/queue.py", line 90, in join
    self.all_tasks_done.wait()
  File "/home/user1/.conda/envs/sql/lib/python3.9/threading.py", line 312, in wait
    waiter.acquire()
KeyboardInterrupt

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/oracle/connections.py", line 134, in cancel
    Connection.close(oracle_connection)
cx_Oracle.OperationalError: ORA-03113: end-of-file on communication channel
Process ID: 0
Session ID: 2976 Serial number: 56963

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/task/runnable.py", line 384, in execute_with_hooks
    res = self.execute_nodes()
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/task/runnable.py", line 347, in execute_nodes
    self._cancel_connections(pool)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/task/runnable.py", line 315, in _cancel_connections
    for conn_name in adapter.cancel_open_connections():
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/base/impl.py", line 1069, in cancel_open_connections
    return self.connections.cancel_open()
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/sql/connections.py", line 47, in cancel_open
    self.cancel(connection)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/oracle/connections.py", line 134, in cancel
    Connection.close(oracle_connection)
KeyboardInterrupt

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/base/connections.py", line 221, in _rollback_handle
    connection.handle.rollback()
cx_Oracle.OperationalError: ORA-03114: not connected to ORACLE
2021-07-27 16:51:16.775293 (MainThread): On model.my_new_project.table1: Close
2021-07-27 16:51:16.775648 (MainThread): Sending event: {'category': 'dbt', 'action': 'invocation', 'label': 'end', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7fe375709250>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7fe36186e700>, <snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7fe36186e9a0>]}
2021-07-27 16:51:16.777113 (MainThread): Flushing usage events
2021-07-27 16:51:16.776313 (Thread-1): Database Error in model table1 (models/app/bod1/table1.sql)
  DPI-1002: invalid OCI handle
  compiled SQL at target/run/my_new_project/models/app/bod1/table1.sql
Traceback (most recent call last):
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/oracle/connections.py", line 153, in exception_handler
    yield
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/oracle/connections.py", line 210, in add_query
    cursor.execute(sql, bindings)
cx_Oracle.DatabaseError: DPI-1002: invalid OCI handle

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/task/base.py", line 344, in safe_run
    result = self.compile_and_execute(manifest, ctx)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/task/base.py", line 287, in compile_and_execute
    result = self.run(ctx.node, manifest)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/task/base.py", line 389, in run
    return self.execute(compiled_node, manifest)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/task/run.py", line 248, in execute
    result = MacroGenerator(materialization_macro, context)()
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/clients/jinja.py", line 332, in __call__
    return self.call_macro(*args, **kwargs)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/clients/jinja.py", line 259, in call_macro
    return macro(*args, **kwargs)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/jinja2/runtime.py", line 675, in __call__
    return self._invoke(arguments, autoescape)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/jinja2/runtime.py", line 679, in _invoke
    rv = self._func(*arguments)
  File "<template>", line 63, in macro
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/jinja2/sandbox.py", line 462, in call
    return __context.call(__obj, *args, **kwargs)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/jinja2/runtime.py", line 290, in call
    return __obj(*args, **kwargs)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/clients/jinja.py", line 332, in __call__
    return self.call_macro(*args, **kwargs)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/clients/jinja.py", line 259, in call_macro
    return macro(*args, **kwargs)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/jinja2/runtime.py", line 675, in __call__
    return self._invoke(arguments, autoescape)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/jinja2/runtime.py", line 679, in _invoke
    rv = self._func(*arguments)
  File "<template>", line 41, in macro
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/jinja2/sandbox.py", line 462, in call
    return __context.call(__obj, *args, **kwargs)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/jinja2/runtime.py", line 290, in call
    return __obj(*args, **kwargs)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/base/impl.py", line 227, in execute
    return self.connections.execute(
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/sql/connections.py", line 124, in execute
    _, cursor = self.add_query(sql, auto_begin)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/oracle/connections.py", line 218, in add_query
    return connection, cursor
  File "/home/user1/.conda/envs/sql/lib/python3.9/contextlib.py", line 135, in __exit__
    self.gen.throw(type, value, traceback)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/oracle/connections.py", line 165, in exception_handler
    raise dbt.exceptions.DatabaseException(str(e).strip()) from e
dbt.exceptions.DatabaseException: Database Error in model table1 (models/app/bod1/table1.sql)
  DPI-1002: invalid OCI handle
  compiled SQL at target/run/my_new_project/models/app/bod1/table1.sql
2021-07-27 16:51:16.783620 (Thread-1): Sending event: {'category': 'dbt', 'action': 'run_model', 'label': '35c93ca4-bdb7-4114-b5b9-814d780b095b', 'context': [<snowplow_tracker.self_describing_json.SelfDescribingJson object at 0x7fe3757092e0>]}
2021-07-27 16:51:16.860326 (MainThread): Error sending message, disabling tracking
2021-07-27 16:51:16.860570 (MainThread): Connection 'master' was properly closed.
2021-07-27 16:51:16.861145 (Thread-1): 16:51:16 | 3 of 4 ERROR creating table model schema1.table1..... [ERROR in 105.74s]
2021-07-27 16:51:16.861467 (MainThread): Connection 'model.my_new_project.table1' was properly closed.
2021-07-27 16:51:16.861878 (Thread-1): Finished running node model.my_new_project.table1
2021-07-27 16:51:16.862228 (MainThread): Encountered an error:
2021-07-27 16:51:16.862758 (MainThread): not connected
2021-07-27 16:51:16.863655 (MainThread): Traceback (most recent call last):
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/task/runnable.py", line 339, in execute_nodes
    self.run_queue(pool)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/task/runnable.py", line 264, in run_queue
    self.job_queue.join()
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/graph/queue.py", line 173, in join
    self.inner.join()
  File "/home/user1/.conda/envs/sql/lib/python3.9/queue.py", line 90, in join
    self.all_tasks_done.wait()
  File "/home/user1/.conda/envs/sql/lib/python3.9/threading.py", line 312, in wait
    waiter.acquire()
KeyboardInterrupt

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/oracle/connections.py", line 134, in cancel
    Connection.close(oracle_connection)
cx_Oracle.OperationalError: ORA-03113: end-of-file on communication channel
Process ID: 0
Session ID: 2976 Serial number: 56963

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/task/runnable.py", line 384, in execute_with_hooks
    res = self.execute_nodes()
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/task/runnable.py", line 347, in execute_nodes
    self._cancel_connections(pool)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/task/runnable.py", line 315, in _cancel_connections
    for conn_name in adapter.cancel_open_connections():
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/base/impl.py", line 1069, in cancel_open_connections
    return self.connections.cancel_open()
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/sql/connections.py", line 47, in cancel_open
    self.cancel(connection)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/oracle/connections.py", line 134, in cancel
    Connection.close(oracle_connection)
KeyboardInterrupt

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/main.py", line 125, in main
    results, succeeded = handle_and_check(args)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/main.py", line 203, in handle_and_check
    task, res = run_from_args(parsed)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/main.py", line 256, in run_from_args
    results = task.run()
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/task/runnable.py", line 426, in run
    result = self.execute_with_hooks(selected_uids)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/task/runnable.py", line 390, in execute_with_hooks
    adapter.cleanup_connections()
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/base/impl.py", line 175, in cleanup_connections
    self.connections.cleanup_all()
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/base/connections.py", line 198, in cleanup_all
    self.close(connection)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/base/connections.py", line 275, in close
    cls._close_handle(connection)
  File "/home/user1/.conda/envs/sql/lib/python3.9/site-packages/dbt/adapters/base/connections.py", line 234, in _close_handle
    connection.handle.close()
cx_Oracle.InterfaceError: not connected```
@sergun sergun added bug Something isn't working triage labels Jul 27, 2021
@jtcohen6 jtcohen6 removed the triage label Jul 28, 2021
@jtcohen6
Copy link
Contributor

@sergun Thanks for including the stacktrace, and for opening the issue in both places. I'm pretty sure that the fix for this will need to be in the dbt-oracle codebase.

dbt supports query cancellation via a series of methods, and it looks like the dbt-oracle adapter implements the foundational cancel method here. You can see the first log line from that cancel method in your logs above, followed by an Oracle error:

2021-07-27 16:49:39.349622 (MainThread): Cancelling query 'model.my_new_project.table1'
^C^C^C^C^C2021-07-27 16:50:25.722387 (Thread-1): Oracle error: DPI-1002: invalid OCI handle

I'm not sure what DPI-1002: invalid OCI handle means. (It seems like this may be related to an older issue: oracle/python-cx_Oracle#117.) It seems to me that will require a deep dive into cx_Oracle, rather than a change to dbt-core.

Should the dbt-oracle maintainers decide that the adapter cannot support query cancellation, due to limitations with Oracle, there's some prior art for that in dbt. An adapter can set the method is_cancelable, as dbt-bigquery does here:

https://github.com/dbt-labs/dbt/blob/e3cb050bbc8faa763f325c89247d9da4d0984724/plugins/bigquery/dbt/adapters/bigquery/impl.py#L144-L146

Then, on keyboard interrupt, dbt will print a log line and exit the process, without trying to cancel the running query:

https://github.com/dbt-labs/dbt/blob/e3cb050bbc8faa763f325c89247d9da4d0984724/core/dbt/task/runnable.py#L308-L311

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@jtcohen6 @sergun