76951bc8d907 *** Found local files: *** * /opt/airflow/logs/dag_id=mantasmy_test_dag/run_id=manual__2024-04-03T11:37:19.456785+00:00/task_id=create_table_apps_log_test/attempt=1.log [2024-04-03, 11:37:30 UTC] {listener.py:218} DEBUG - on_starting: Job [2024-04-03, 11:37:30 UTC] {taskinstance.py:1094} DEBUG - previous_execution_date was called [2024-04-03, 11:37:30 UTC] {__init__.py:51} DEBUG - Loading core task runner: StandardTaskRunner [2024-04-03, 11:37:30 UTC] {taskinstance.py:1094} DEBUG - previous_execution_date was called [2024-04-03, 11:37:30 UTC] {base_task_runner.py:68} DEBUG - Planning to run as the user [2024-04-03, 11:37:30 UTC] {taskinstance.py:844} DEBUG - Refreshing TaskInstance from DB [2024-04-03, 11:37:30 UTC] {taskinstance.py:1168} DEBUG - dependency 'Task Instance Not Running' PASSED: True, Task is not in running state. [2024-04-03, 11:37:30 UTC] {taskinstance.py:1168} DEBUG - dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying. [2024-04-03, 11:37:30 UTC] {taskinstance.py:1168} DEBUG - dependency 'Previous Dagrun State' PASSED: True, The task did not have depends_on_past set. [2024-04-03, 11:37:30 UTC] {taskinstance.py:1168} DEBUG - dependency 'Task Instance State' PASSED: True, Task state queued was valid. [2024-04-03, 11:37:30 UTC] {taskinstance.py:1159} INFO - Dependencies all met for dep_context=non-requeueable deps ti= [2024-04-03, 11:37:30 UTC] {taskinstance.py:1168} DEBUG - dependency 'Pool Slots Available' PASSED: True, There are enough open slots in trino_major_pool to execute the task [2024-04-03, 11:37:30 UTC] {taskinstance.py:1168} DEBUG - dependency 'Task Concurrency' PASSED: True, The max task concurrency has not been reached. [2024-04-03, 11:37:30 UTC] {taskinstance.py:1168} DEBUG - dependency 'Not In Retry Period' PASSED: True, The task instance was not marked for retrying. [2024-04-03, 11:37:30 UTC] {taskinstance.py:1168} DEBUG - dependency 'Previous Dagrun State' PASSED: True, The task did not have depends_on_past set. [2024-04-03, 11:37:30 UTC] {taskinstance.py:1159} INFO - Dependencies all met for dep_context=requeueable deps ti= [2024-04-03, 11:37:30 UTC] {taskinstance.py:1361} INFO - Starting attempt 1 of 3 [2024-04-03, 11:37:30 UTC] {taskinstance.py:1382} INFO - Executing on 2024-04-03 11:37:19.456785+00:00 [2024-04-03, 11:37:30 UTC] {standard_task_runner.py:57} INFO - Started process 340 to run task [2024-04-03, 11:37:30 UTC] {standard_task_runner.py:84} INFO - Running: ['***', 'tasks', 'run', 'mantasmy_test_dag', 'create_table_apps_log_test', 'manual__2024-04-03T11:37:19.456785+00:00', '--job-id', '21', '--raw', '--subdir', 'DAGS_FOLDER/dags/test.py', '--cfg-path', '/tmp/tmp9esws7mb'] [2024-04-03, 11:37:30 UTC] {standard_task_runner.py:85} INFO - Job 21: Subtask create_table_apps_log_test [2024-04-03, 11:37:30 UTC] {cli_action_loggers.py:67} DEBUG - Calling callbacks: [] [2024-04-03, 11:37:30 UTC] {listener.py:218} DEBUG - on_starting: TaskCommandMarker [2024-04-03, 11:37:30 UTC] {taskinstance.py:1094} DEBUG - previous_execution_date was called [2024-04-03, 11:37:30 UTC] {task_command.py:415} INFO - Running on host 76951bc8d907 [2024-04-03, 11:37:30 UTC] {settings.py:353} DEBUG - Disposing DB connection pool (PID 340) [2024-04-03, 11:37:30 UTC] {settings.py:212} DEBUG - Setting up DB connection pool (PID 340) [2024-04-03, 11:37:30 UTC] {settings.py:285} DEBUG - settings.prepare_engine_args(): Using NullPool [2024-04-03, 11:37:30 UTC] {taskinstance.py:844} DEBUG - Refreshing TaskInstance from DB [2024-04-03, 11:37:30 UTC] {taskinstance.py:1094} DEBUG - previous_execution_date was called [2024-04-03, 11:37:30 UTC] {taskinstance.py:925} DEBUG - Clearing XCom data [2024-04-03, 11:37:30 UTC] {retries.py:92} DEBUG - Running RenderedTaskInstanceFields.write with retries. Try 1 of 3 [2024-04-03, 11:37:30 UTC] {retries.py:92} DEBUG - Running RenderedTaskInstanceFields._do_delete_old_records with retries. Try 1 of 3 [2024-04-03, 11:37:30 UTC] {taskinstance.py:1660} INFO - Exporting env vars: AIRFLOW_CTX_DAG_EMAIL='mantasmy@w.com' AIRFLOW_CTX_DAG_OWNER='data-automation' AIRFLOW_CTX_DAG_ID='mantasmy_test_dag' AIRFLOW_CTX_TASK_ID='create_table_apps_log_test' AIRFLOW_CTX_EXECUTION_DATE='2024-04-03T11:37:19.456785+00:00' AIRFLOW_CTX_TRY_NUMBER='1' AIRFLOW_CTX_DAG_RUN_ID='manual__2024-04-03T11:37:19.456785+00:00' [2024-04-03, 11:37:30 UTC] {__init__.py:117} DEBUG - Preparing lineage inlets and outlets [2024-04-03, 11:37:30 UTC] {__init__.py:158} DEBUG - inlets: [], outlets: [] [2024-04-03, 11:37:30 UTC] {listener.py:69} DEBUG - OpenLineage listener got notification about task instance start [2024-04-03, 11:37:30 UTC] {manager.py:161} DEBUG - extractor for TrinoOperator is [2024-04-03, 11:37:30 UTC] {manager.py:101} DEBUG - Using extractor DefaultExtractor task_type=TrinoOperator ***_dag_id=mantasmy_test_dag task_id=create_table_apps_log_test ***_run_id=manual__2024-04-03T11:37:19.456785+00:00 [2024-04-03, 11:37:30 UTC] {base.py:73} INFO - Using connection ID 't_default' for task execution. [2024-04-03, 11:37:30 UTC] {trino.py:501} INFO - Create brand new wTrinoHook for connection t_default [2024-04-03, 11:37:30 UTC] {base.py:73} INFO - Using connection ID 't_default' for task execution. [2024-04-03, 11:37:30 UTC] {base.py:162} WARNING - OpenLineage provider method failed to extract data from provider. [2024-04-03, 11:37:30 UTC] {manager.py:107} DEBUG - Found task metadata for operation create_table_apps_log_test: None [2024-04-03, 11:37:30 UTC] {manager.py:276} WARNING - Extractor returns non-valid metadata: None [2024-04-03, 11:37:30 UTC] {http.py:114} DEBUG - Constructing openlineage client to send events to http://api:5000 - config HttpConfig(url='http://api:5000', endpoint='api/v1/lineage', timeout=5.0, verify=True, auth=, session=None, adapter=None) [2024-04-03, 11:37:30 UTC] {client.py:98} DEBUG - OpenLineageClient will emit event b'{"eventTime": "2024-04-03T11:37:30.721165+00:00", "eventType": "START", "inputs": [], "job": {"facets": {"jobType": {"_producer": "https://github.com/apache/airflow/tree/providers-openlineage/1.6.0", "_schemaURL": "https://raw.githubusercontent.com/OpenLineage/OpenLineage/main/spec/OpenLineage.json#/definitions/JobTypeJobFacet", "integration": "AIRFLOW", "jobType": "TASK", "processingType": "BATCH"}, "ownership": {"_producer": "https://github.com/apache/airflow/tree/providers-openlineage/1.6.0", "_schemaURL": "https://raw.githubusercontent.com/OpenLineage/OpenLineage/main/spec/OpenLineage.json#/definitions/OwnershipJobFacet", "owners": [{"name": "data-automation"}]}}, "name": "mantasmy_test_dag.create_table_apps_log_test", "namespace": "\\"airflow\\""}, "outputs": [], "producer": "https://github.com/apache/airflow/tree/providers-openlineage/1.6.0", "run": {"facets": {"airflow": {"_producer": "https://github.com/apache/***/tree/providers-openlineage/1.6.0", "_schemaURL": "https://raw.githubusercontent.com/OpenLineage/OpenLineage/main/spec/OpenLineage.json#/definitions/BaseFacet", "dag": {"dag_id": "mantasmy_test_dag", "schedule_interval": "0 0 * * 1", "tags": "[]", "timetable": {"expression": "0 0 * * 1", "timezone": "UTC"}}, "dagRun": {"conf": {}, "dag_id": "mantasmy_test_dag", "data_interval_end": "2024-04-01T00:00:00+00:00", "data_interval_start": "2024-03-25T00:00:00+00:00", "external_trigger": true, "run_id": "manual__2024-04-03T11:37:19.456785+00:00", "run_type": "manual", "start_date": "2024-04-03T11:37:20.278143+00:00"}, "task": {"_is_setup": false, "_is_teardown": false, "_local_do_xcom_push": false, "_trino_hook": "", "args": {"conn_id": "t_default", "depends_on_past": false, "do_xcom_push": true, "email": "mantasmy@w.com", "email_on_failure": false, "email_on_retry": false, "handler": ".fetch_many at 0xffff670e3520>", "max_active_tis_per_dag": 5, "owner": "data-automation", "pool": "trino_major_pool", "split_statements": true, "sql": "\\n CREATE TABLE if not exists db.schema.table2 as\\n SELECT app_id, msid, instance_id from db.schema.table limit 1\\n ", "start_date": "2021-05-03T00:00:00+00:00", "task_id": "create_table_apps_log_test"}, "autocommit": false, "conn_id": "t_default", "depends_on_past": false, "disable_bi_events": false, "disable_jinja_template": false, "do_xcom_push": true, "downstream_task_ids": "[]", "email": "mantasmy@w.com", "email_on_failure": false, "email_on_retry": false, "executor_config": {}, "hook_params": {}, "ignore_first_depends_on_past": true, "inlets": "[]", "logger_conn_id": "frog_default", "mapped": false, "max_active_tis_per_dag": 5, "operator_class": "TrinoOperator", "outlets": "[]", "owner": "data-automation", "pool": "trino_major_pool", "pool_slots": 1, "priority_weight": 1, "query_headers_overrides": {}, "queue": "default", "retries": 2, "retry_exponential_backoff": false, "retry_on_failure": true, "retry_policy": "", "return_last": true, "show_return_value_in_logs": false, "split_statements": true, "sql": "\\n CREATE TABLE if not exists db.schema.table2 as\\n SELECT app_id, msid, instance_id from db.schema.table limit 1\\n ", "start_date": "2021-05-03T00:00:00+00:00", "task_id": "create_table_apps_log_test", "trigger_rule": "all_success", "upstream_task_ids": "[\'drop_table_apps_log_test\']", "wait_for_downstream": false, "wait_for_past_depends_before_skipping": false, "weight_rule": "downstream"}, "taskInstance": {"pool": "trino_major_pool", "try_number": 1}, "taskUuid": "e248d33d-a546-325d-ba05-b40066c57aac"}, "nominalTime": {"_producer": "https://github.com/apache/airflow/tree/providers-openlineage/1.6.0", "_schemaURL": "https://raw.githubusercontent.com/OpenLineage/OpenLineage/main/spec/OpenLineage.json#/definitions/NominalTimeRunFacet", "nominalEndTime": "2024-04-01T00:00:00+00:00", "nominalStartTime": "2024-03-25T00:00:00+00:00"}, "parent": {"_producer": "https://github.com/apache/airflow/tree/providers-openlineage/1.6.0", "_schemaURL": "https://raw.githubusercontent.com/OpenLineage/OpenLineage/main/spec/OpenLineage.json#/definitions/ParentRunFacet", "job": {"name": "mantasmy_test_dag", "namespace": "\\"airflow\\""}, "run": {"runId": "43ab1d2b-7b46-3785-9df2-b0cad16ff9fc"}}, "parentRun": {"_producer": "https://github.com/apache/airflow/tree/providers-openlineage/1.6.0", "_schemaURL": "https://raw.githubusercontent.com/OpenLineage/OpenLineage/main/spec/OpenLineage.json#/definitions/ParentRunFacet", "job": {"name": "mantasmy_test_dag", "namespace": "\\"airflow\\""}, "run": {"runId": "43ab1d2b-7b46-3785-9df2-b0cad16ff9fc"}}, "processing_engine": {"_producer": "https://github.com/apache/airflow/tree/providers-openlineage/1.6.0", "_schemaURL": "https://raw.githubusercontent.com/OpenLineage/OpenLineage/main/spec/OpenLineage.json#/definitions/ProcessingEngineRunFacet", "name": "Airflow", "openlineageAdapterVersion": "1.6.0", "version": "2.7.0"}}, "runId": "e248d33d-a546-325d-ba05-b40066c57aac"}, "schemaURL": "https://openlineage.io/spec/1-0-5/OpenLineage.json#/definitions/RunEvent"}' [2024-04-03, 11:37:30 UTC] {connectionpool.py:245} DEBUG - Starting new HTTP connection (1): api:5000 [2024-04-03, 11:37:30 UTC] {connectionpool.py:473} DEBUG - http://api:5000 "POST /api/v1/lineage HTTP/1.1" 201 0 [2024-04-03, 11:37:30 UTC] {sql.py:276} INFO - Executing: CREATE TABLE if not exists db.schema.table2 as SELECT app_id, msid, instance_id from db.schema.table limit 1 [2024-04-03, 11:37:30 UTC] {sql.py:393} DEBUG - Executing following statements against DB: ['CREATE TABLE if not exists db.schema.table2 as\n SELECT app_id, msid, instance_id from db.schema.table limit 1'] [2024-04-03, 11:37:30 UTC] {base.py:73} INFO - Using connection ID 't_default' for task execution. [2024-04-03, 11:37:30 UTC] {base.py:73} INFO - Using connection ID 't_default' for task execution. [2024-04-03, 11:37:30 UTC] {unix.py:63} DEBUG - /etc/timezone found, contents: Etc/UTC [2024-04-03, 11:37:30 UTC] {unix.py:122} DEBUG - /etc/localtime found [2024-04-03, 11:37:30 UTC] {unix.py:138} DEBUG - 2 found: {'/etc/timezone': 'Etc/UTC', '/etc/localtime is a symlink to': 'Etc/UTC'} [2024-04-03, 11:37:30 UTC] {sql.py:457} INFO - Running statement: CREATE TABLE if not exists db.schema.table2 as SELECT app_id, msid, instance_id from db.schema.table limit 1, parameters: None [2024-04-03, 11:37:30 UTC] {connectionpool.py:245} DEBUG - Starting new HTTP connection (1): router [2024-04-03, 11:37:31 UTC] {connectionpool.py:473} DEBUG - http://router "POST /v1/statement HTTP/1.1" 200 324 [2024-04-03, 11:37:31 UTC] {connectionpool.py:1014} DEBUG - Starting new HTTPS connection (1): w [2024-04-03, 11:37:31 UTC] {connectionpool.py:473} DEBUG - tw "GET statement/queued/20240403_113731_58965_kznmh/yf3490f921575b3f15e363f1fb90bbf2f34db1695/1 HTTP/1.1" 200 324 [2024-04-03, 11:37:31 UTC] {connectionpool.py:473} DEBUG - tw "GET statement/queued/20240403_113731_58965_kznmh/y3535fe8eb7023a801d08c99a64b0b05b75e11b99/2 HTTP/1.1" 200 333 [2024-04-03, 11:37:33 UTC] {connectionpool.py:473} DEBUG - tw "GET statement/executing/20240403_113731_58965_kznmh/yf28d07146a6040c72c8f1cbda6157ee4e89bf0af/0 HTTP/1.1" 200 689 [2024-04-03, 11:37:33 UTC] {connectionpool.py:473} DEBUG - tw "GET statement/executing/20240403_113731_58965_kznmh/ycec3476dd51898eddc10ec845dd8096ae62e4849/1 HTTP/1.1" 200 658 [2024-04-03, 11:37:33 UTC] {sql.py:466} INFO - Rows affected: 1 [2024-04-03, 11:37:33 UTC] {connectionpool.py:473} DEBUG - tw "GET statement/executing/20240403_113731_58965_kznmh/y8d739fe5cc4e308464f194343cd3f8605b4c22d1/2 HTTP/1.1" 200 593 [2024-04-03, 11:37:33 UTC] {logging_mixin.py:151} WARNING - /home/***/.local/lib/python3.10/site-packages/***/providers/common/sql/hooks/sql.py:407 AirflowProviderDeprecationWarning: Call to deprecated method _make_common_data_structure. (The `_make_serializable` method is deprecated and support will be removed in a future version of the common.sql provider. Please update the DbApiHook's provider to a version based on common.sql >= 1.9.1.) [2024-04-03, 11:37:33 UTC] {trino.py:577} INFO - Trino query #20240403_113731_58965_kznmh finished [2024-04-03, 11:37:33 UTC] {bi_events_hook.py:118} WARNING - Connection frog_default doesn't exists, BI events will not be reported [2024-04-03, 11:37:33 UTC] {__init__.py:75} DEBUG - Lineage called with inlets: [], outlets: [] [2024-04-03, 11:37:33 UTC] {taskinstance.py:844} DEBUG - Refreshing TaskInstance from DB [2024-04-03, 11:37:33 UTC] {taskinstance.py:1458} DEBUG - Clearing next_method and next_kwargs. [2024-04-03, 11:37:33 UTC] {taskinstance.py:1400} INFO - Marking task as SUCCESS. dag_id=mantasmy_test_dag, task_id=create_table_apps_log_test, execution_date=20240403T113719, start_date=20240403T113730, end_date=20240403T113733 [2024-04-03, 11:37:33 UTC] {taskinstance.py:2436} DEBUG - Task Duration set to 2.637272 [2024-04-03, 11:37:33 UTC] {listener.py:126} DEBUG - OpenLineage listener got notification about task instance success [2024-04-03, 11:37:33 UTC] {manager.py:161} DEBUG - extractor for TrinoOperator is [2024-04-03, 11:37:33 UTC] {manager.py:101} DEBUG - Using extractor DefaultExtractor task_type=TrinoOperator ***_dag_id=mantasmy_test_dag task_id=create_table_apps_log_test ***_run_id=manual__2024-04-03T11:37:19.456785+00:00 [2024-04-03, 11:37:33 UTC] {base.py:73} INFO - Using connection ID 't_default' for task execution. [2024-04-03, 11:37:33 UTC] {manager.py:107} DEBUG - Found task metadata for operation create_table_apps_log_test: OperatorLineage(inputs=[], outputs=[], run_facets={}, job_facets={}) [2024-04-03, 11:37:33 UTC] {client.py:98} DEBUG - OpenLineageClient will emit event b'{"eventTime": "2024-04-03T11:37:33.358437+00:00", "eventType": "COMPLETE", "inputs": [], "job": {"facets": {"jobType": {"_producer": "https://github.com/apache/airflow/tree/providers-openlineage/1.6.0", "_schemaURL": "https://raw.githubusercontent.com/OpenLineage/OpenLineage/main/spec/OpenLineage.json#/definitions/JobTypeJobFacet", "integration": "AIRFLOW", "jobType": "TASK", "processingType": "BATCH"}}, "name": "mantasmy_test_dag.create_table_apps_log_test", "namespace": "\\"airflow\\""}, "outputs": [], "producer": "https://github.com/apache/airflow/tree/providers-openlineage/1.6.0", "run": {"facets": {"parent": {"_producer": "https://github.com/apache/airflow/tree/providers-openlineage/1.6.0", "_schemaURL": "https://raw.githubusercontent.com/OpenLineage/OpenLineage/main/spec/OpenLineage.json#/definitions/ParentRunFacet", "job": {"name": "mantasmy_test_dag", "namespace": "\\"airflow\\""}, "run": {"runId": "43ab1d2b-7b46-3785-9df2-b0cad16ff9fc"}}, "parentRun": {"_producer": "https://github.com/apache/airflow/tree/providers-openlineage/1.6.0", "_schemaURL": "https://raw.githubusercontent.com/OpenLineage/OpenLineage/main/spec/OpenLineage.json#/definitions/ParentRunFacet", "job": {"name": "mantasmy_test_dag", "namespace": "\\"airflow\\""}, "run": {"runId": "43ab1d2b-7b46-3785-9df2-b0cad16ff9fc"}}}, "runId": "e248d33d-a546-325d-ba05-b40066c57aac"}, "schemaURL": "https://openlineage.io/spec/1-0-5/OpenLineage.json#/definitions/RunEvent"}' [2024-04-03, 11:37:33 UTC] {connectionpool.py:245} DEBUG - Starting new HTTP connection (1): api:5000 [2024-04-03, 11:37:33 UTC] {connectionpool.py:473} DEBUG - http://api:5000 "POST /api/v1/lineage HTTP/1.1" 201 0 [2024-04-03, 11:37:33 UTC] {listener.py:222} DEBUG - before_stopping: TaskCommandMarker [2024-04-03, 11:37:33 UTC] {cli_action_loggers.py:85} DEBUG - Calling callbacks: [] [2024-04-03, 11:37:33 UTC] {local_task_job_runner.py:228} INFO - Task exited with return code 0 [2024-04-03, 11:37:33 UTC] {dagrun.py:740} DEBUG - number of tis tasks for : 0 task(s) [2024-04-03, 11:37:33 UTC] {taskinstance.py:2784} INFO - 0 downstream tasks scheduled from follow-on schedule check [2024-04-03, 11:37:33 UTC] {listener.py:222} DEBUG - before_stopping: Job