Github-dm-CDE commented on issue #33688:
URL: https://github.com/apache/airflow/issues/33688#issuecomment-1699300983
Hi @potiuk & @ephraimbuddy,
here are the task logs again (but this time from our RLS stage, which has
the same problem), with logging_level=DEBUG.
```bash
OBSCURED_CLIENT_SECRET Found local files:
OBSCURED_CLIENT_SECRET *
/var/log/airflow/dags/dag_id=prj_ck_cas_table_monitoring/run_id=manual__2023-08-30T14:22:51.684136+00:00/task_id=collect_CAS_table_metrics_public/attempt=1.log
[2023-08-30, 14:23:49 UTC] {taskinstance.py:1094} DEBUG -
previous_execution_date was called
[2023-08-30, 14:23:54 UTC] {__init__.py:51} DEBUG - Loading core task
runner: StandardTaskRunner
[2023-08-30, 14:23:58 UTC] {taskinstance.py:1094} DEBUG -
previous_execution_date was called
[2023-08-30, 14:24:02 UTC] {base_task_runner.py:68} DEBUG - Planning to run
as the user
[2023-08-30, 14:24:02 UTC] {taskinstance.py:844} DEBUG - Refreshing
TaskInstance <TaskInstance:
prj_ck_cas_table_monitoring.collect_CAS_table_metrics_public
manual__2023-08-30T14:22:51.684136+00:00 [queued]> from DB
[2023-08-30, 14:24:02 UTC] {taskinstance.py:1168} DEBUG - <TaskInstance:
prj_ck_cas_table_monitoring.collect_CAS_table_metrics_public
manual__2023-08-30T14:22:51.684136+00:00 [queued]> dependency 'Task Instance
State' PASSED: True, Task state queued was valid.
[2023-08-30, 14:24:02 UTC] {taskinstance.py:1168} DEBUG - <TaskInstance:
prj_ck_cas_table_monitoring.collect_CAS_table_metrics_public
manual__2023-08-30T14:22:51.684136+00:00 [queued]> dependency 'Previous Dagrun
State' PASSED: True, The task did not have depends_on_past set.
[2023-08-30, 14:24:02 UTC] {taskinstance.py:1168} DEBUG - <TaskInstance:
prj_ck_cas_table_monitoring.collect_CAS_table_metrics_public
manual__2023-08-30T14:22:51.684136+00:00 [queued]> dependency 'Task Instance
Not Running' PASSED: True, Task is not in running state.
[2023-08-30, 14:24:02 UTC] {taskinstance.py:1168} DEBUG - <TaskInstance:
prj_ck_cas_table_monitoring.collect_CAS_table_metrics_public
manual__2023-08-30T14:22:51.684136+00:00 [queued]> dependency 'Not In Retry
Period' PASSED: True, The task instance was not marked for retrying.
[2023-08-30, 14:24:02 UTC] {taskinstance.py:1159} INFO - Dependencies all
met for dep_context=non-requeueable deps ti=<TaskInstance:
prj_ck_cas_table_monitoring.collect_CAS_table_metrics_public
manual__2023-08-30T14:22:51.684136+00:00 [queued]>
[2023-08-30, 14:24:02 UTC] {taskinstance.py:1168} DEBUG - <TaskInstance:
prj_ck_cas_table_monitoring.collect_CAS_table_metrics_public
manual__2023-08-30T14:22:51.684136+00:00 [queued]> dependency 'Previous Dagrun
State' PASSED: True, The task did not have depends_on_past set.
[2023-08-30, 14:24:02 UTC] {taskinstance.py:1168} DEBUG - <TaskInstance:
prj_ck_cas_table_monitoring.collect_CAS_table_metrics_public
manual__2023-08-30T14:22:51.684136+00:00 [queued]> dependency 'Task
Concurrency' PASSED: True, Task concurrency is not set.
[2023-08-30, 14:24:02 UTC] {taskinstance.py:1168} DEBUG - <TaskInstance:
prj_ck_cas_table_monitoring.collect_CAS_table_metrics_public
manual__2023-08-30T14:22:51.684136+00:00 [queued]> dependency 'Pool Slots
Available' PASSED: True, There are enough open slots in default_pool to execute
the task
[2023-08-30, 14:24:02 UTC] {taskinstance.py:1168} DEBUG - <TaskInstance:
prj_ck_cas_table_monitoring.collect_CAS_table_metrics_public
manual__2023-08-30T14:22:51.684136+00:00 [queued]> dependency 'Not In Retry
Period' PASSED: True, The task instance was not marked for retrying.
[2023-08-30, 14:24:02 UTC] {taskinstance.py:1159} INFO - Dependencies all
met for dep_context=requeueable deps ti=<TaskInstance:
prj_ck_cas_table_monitoring.collect_CAS_table_metrics_public
manual__2023-08-30T14:22:51.684136+00:00 [queued]>
[2023-08-30, 14:24:02 UTC] {taskinstance.py:1361} INFO - Starting attempt 1
of 3
[2023-08-30, 14:24:02 UTC] {taskinstance.py:1382} INFO - Executing
<Task(CLIOperator): collect_CAS_table_metrics_public> on 2023-08-30
14:22:51.684136+00:00
[2023-08-30, 14:24:02 UTC] {standard_task_runner.py:57} INFO - Started
process 2355015 to run task
[2023-08-30, 14:24:02 UTC] {standard_task_runner.py:84} INFO - Running:
['airflow', 'tasks', 'run', 'prj_ck_cas_table_monitoring',
'collect_CAS_table_metrics_public', 'manual__2023-08-30T14:22:51.684136+00:00',
'--job-id', '2428156', '--raw', '--subdir',
'DAGS_FOLDER/prj_ck_cas_table_monitoring/prj_ck_cas_table_monitoring.py',
'--cfg-path', '/tmp/tmpo_h27u9p']
[2023-08-30, 14:24:02 UTC] {standard_task_runner.py:85} INFO - Job 2428156:
Subtask collect_CAS_table_metrics_public
[2023-08-30, 14:24:02 UTC] {cli_action_loggers.py:67} DEBUG - Calling
callbacks: [<function default_action_log at 0x7f880eea13a0>]
[2023-08-30, 14:24:07 UTC] {taskinstance.py:1094} DEBUG -
previous_execution_date was called
[2023-08-30, 14:24:08 UTC] {taskinstance.py:844} DEBUG - Refreshing
TaskInstance <TaskInstance:
prj_ck_cas_table_monitoring.collect_CAS_table_metrics_public
manual__2023-08-30T14:22:51.684136+00:00 [running]> from DB
[2023-08-30, 14:24:08 UTC] {job.py:216} DEBUG - [heartbeat]
[2023-08-30, 14:24:11 UTC] {task_command.py:415} INFO - Running
<TaskInstance: prj_ck_cas_table_monitoring.collect_CAS_table_metrics_public
manual__2023-08-30T14:22:51.684136+00:00 [running]> on host OBSCURED_HOSTNAME
[2023-08-30, 14:24:11 UTC] {settings.py:353} DEBUG - Disposing DB connection
pool (PID 2355015)
[2023-08-30, 14:24:11 UTC] {settings.py:212} DEBUG - Setting up DB
connection pool (PID 2355015)
[2023-08-30, 14:24:11 UTC] {settings.py:285} DEBUG -
settings.prepare_engine_args(): Using NullPool
[2023-08-30, 14:24:11 UTC] {taskinstance.py:844} DEBUG - Refreshing
TaskInstance <TaskInstance:
prj_ck_cas_table_monitoring.collect_CAS_table_metrics_public
manual__2023-08-30T14:22:51.684136+00:00 [running]> from DB
[2023-08-30, 14:24:13 UTC] {taskinstance.py:844} DEBUG - Refreshing
TaskInstance <TaskInstance:
prj_ck_cas_table_monitoring.collect_CAS_table_metrics_public
manual__2023-08-30T14:22:51.684136+00:00 [running]> from DB
[2023-08-30, 14:24:13 UTC] {job.py:216} DEBUG - [heartbeat]
[2023-08-30, 14:24:16 UTC] {taskinstance.py:1094} DEBUG -
previous_execution_date was called
[2023-08-30, 14:24:18 UTC] {taskinstance.py:844} DEBUG - Refreshing
TaskInstance <TaskInstance:
prj_ck_cas_table_monitoring.collect_CAS_table_metrics_public
manual__2023-08-30T14:22:51.684136+00:00 [running]> from DB
[2023-08-30, 14:24:18 UTC] {job.py:216} DEBUG - [heartbeat]
[2023-08-30, 14:24:20 UTC] {taskinstance.py:925} DEBUG - Clearing XCom data
[2023-08-30, 14:24:20 UTC] {retries.py:92} DEBUG - Running
RenderedTaskInstanceFields.write with retries. Try 1 of 3
[2023-08-30, 14:24:20 UTC] {retries.py:92} DEBUG - Running
RenderedTaskInstanceFields._do_delete_old_records with retries. Try 1 of 3
[2023-08-30, 14:24:20 UTC] {taskinstance.py:1660} INFO - Exporting env vars:
AIRFLOW_CTX_DAG_OWNER='CK' AIRFLOW_CTX_DAG_ID='prj_ck_cas_table_monitoring'
AIRFLOW_CTX_TASK_ID='collect_CAS_table_metrics_public'
AIRFLOW_CTX_EXECUTION_DATE='2023-08-30T14:22:51.684136+00:00'
AIRFLOW_CTX_TRY_NUMBER='1'
AIRFLOW_CTX_DAG_RUN_ID='manual__2023-08-30T14:22:51.684136+00:00'
[2023-08-30, 14:24:20 UTC] {__init__.py:117} DEBUG - Preparing lineage
inlets and outlets
[2023-08-30, 14:24:20 UTC] {__init__.py:158} DEBUG - inlets: [], outlets: []
[2023-08-30, 14:24:20 UTC] {logging_mixin.py:151} INFO - Execute cli task
[2023-08-30, 14:24:20 UTC] {base.py:73} INFO - Using connection ID
'sas_viya_conn' for task execution.
[2023-08-30, 14:24:20 UTC] {base.py:73} INFO - Using connection ID
'cxa_mssql_db_domain_user_format' for task execution.
[2023-08-30, 14:24:20 UTC] {logging_mixin.py:151} INFO - Environment
variables: ['LANG', 'PATH', 'VIYA_USERNAME', 'VIYA_PASSWORD', 'VIYA_HOST_URL',
'MSSQL_USERNAME', 'MSSQL_PASSWORD', 'MSSQL_HOST_URL', 'MSSQL_HOST_PORT',
'MSSQL_DATABASE']
[2023-08-30, 14:24:20 UTC] {logging_mixin.py:151} INFO - Bash command:
/srv/team-workspaces/ck/pex/viyacli.pex cas-monitoring --ssl_cert_file
OBSCURED_SSL_CERT_PATH --viya_caslib PUBLIC --viya_client_secret
OBSCURED_CLIENT_SECRET --monitoring_table sas_cas_table_status
[2023-08-30, 14:24:20 UTC] {bash.py:186} DEBUG - Exporting env vars:
AIRFLOW_CTX_DAG_OWNER='CK' AIRFLOW_CTX_DAG_ID='prj_ck_cas_table_monitoring'
AIRFLOW_CTX_TASK_ID='collect_CAS_table_metrics_public'
AIRFLOW_CTX_EXECUTION_DATE='2023-08-30T14:22:51.684136+00:00'
AIRFLOW_CTX_TRY_NUMBER='1'
AIRFLOW_CTX_DAG_RUN_ID='manual__2023-08-30T14:22:51.684136+00:00'
[2023-08-30, 14:24:20 UTC] {subprocess.py:63} INFO - Tmp dir root location:
/tmp
[2023-08-30, 14:24:20 UTC] {subprocess.py:75} INFO - Running command:
['/usr/bin/bash', '-c', '/srv/team-workspaces/ck/pex/viyacli.pex cas-monitoring
--ssl_cert_file OBSCURED_SSL_CERT_PATH --viya_caslib PUBLIC
--viya_client_secret OBSCURED_CLIENT_SECRET --monitoring_table
sas_cas_table_status']
[2023-08-30, 14:24:20 UTC] {subprocess.py:86} INFO - Output:
[2023-08-30, 14:24:23 UTC] {taskinstance.py:844} DEBUG - Refreshing
TaskInstance <TaskInstance:
prj_ck_cas_table_monitoring.collect_CAS_table_metrics_public
manual__2023-08-30T14:22:51.684136+00:00 [running]> from DB
[2023-08-30, 14:24:23 UTC] {job.py:216} DEBUG - [heartbeat]
[2023-08-30, 14:24:23 UTC] {subprocess.py:93} INFO - 2023-08-30 16:24:23.723
| WARNING | viya.mssql_utils:write_to_mssql:35 - No data was passed to insert
into the Database.
[2023-08-30, 14:24:23 UTC] {subprocess.py:97} INFO - Command exited with
return code 0
[2023-08-30, 14:24:23 UTC] {__init__.py:75} DEBUG - Lineage called with
inlets: [], outlets: []
[2023-08-30, 14:24:23 UTC] {taskinstance.py:844} DEBUG - Refreshing
TaskInstance <TaskInstance:
prj_ck_cas_table_monitoring.collect_CAS_table_metrics_public
manual__2023-08-30T14:22:51.684136+00:00 [running]> from DB
[2023-08-30, 14:24:23 UTC] {taskinstance.py:1458} DEBUG - Clearing
next_method and next_kwargs.
[2023-08-30, 14:24:23 UTC] {taskinstance.py:1400} INFO - Marking task as
SUCCESS. dag_id=prj_ck_cas_table_monitoring,
task_id=collect_CAS_table_metrics_public, execution_date=20230830T142251,
start_date=20230830T142402, end_date=20230830T142423
[2023-08-30, 14:24:23 UTC] {taskinstance.py:2436} DEBUG - Task Duration set
to 20.913392
[2023-08-30, 14:24:23 UTC] {cli_action_loggers.py:85} DEBUG - Calling
callbacks: []
[2023-08-30, 14:24:23 UTC] {local_task_job_runner.py:228} INFO - Task exited
with return code 0
[2023-08-30, 14:24:23 UTC] {dagrun.py:740} DEBUG - number of tis tasks for
<DagRun prj_ck_cas_table_monitoring @ 2023-08-30 14:22:51.684136+00:00:
manual__2023-08-30T14:22:51.684136+00:00, state:running, queued_at: 2023-08-30
16:22:51.722581+00:00. externally triggered: True>: 0 task(s)
[2023-08-30, 14:24:23 UTC] {taskinstance.py:2784} INFO - 0 downstream tasks
scheduled from follow-on schedule check
```
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
