1868684 - Airflow task taar_daily.addon_recommender failed for exec_date 2023-12-05, 04:00:00 UTC

Status: RESOLVED FIXED

(Data Platform and Tools :: General, defect)

Description

[Marlene Hirose]

Airflow task taar_daily.addon_recommender failed for exec_date 2023-12-06, 04:00:00 UTC

Task link:
https://workflow.telemetry.mozilla.org/dags/taar_daily/grid?dag_run_id=scheduled__2023-12-04T04%3A00%3A00%2B00%3A00&task_id=addon_recommender&tab=logs

Log extract:

10.20.2.206
*** Found remote logs:
***   * gs://airflow-remote-logs-prod-prod/dag_id=taar_daily/run_id=scheduled__2023-12-04T04:00:00+00:00/task_id=addon_recommender/attempt=3.log
[2023-12-06, 16:56:06 UTC] {taskinstance.py:1159} INFO - Dependencies all met for dep_context=non-requeueable deps ti=<TaskInstance: taar_daily.addon_recommender scheduled__2023-12-04T04:00:00+00:00 [queued]>
[2023-12-06, 16:56:06 UTC] {taskinstance.py:1159} INFO - Dependencies all met for dep_context=requeueable deps ti=<TaskInstance: taar_daily.addon_recommender scheduled__2023-12-04T04:00:00+00:00 [queued]>
[2023-12-06, 16:56:06 UTC] {taskinstance.py:1361} INFO - Starting attempt 3 of 3
[2023-12-06, 16:56:06 UTC] {taskinstance.py:1382} INFO - Executing <Task(SubDagOperator): addon_recommender> on 2023-12-04 04:00:00+00:00
[2023-12-06, 16:56:06 UTC] {standard_task_runner.py:57} INFO - Started process 146966 to run task
[2023-12-06, 16:56:06 UTC] {standard_task_runner.py:84} INFO - Running: ['airflow', 'tasks', 'run', 'taar_daily', 'addon_recommender', 'scheduled__2023-12-04T04:00:00+00:00', '--job-id', '2019635', '--raw', '--subdir', 'DAGS_FOLDER/telemetry-airflow/dags/taar_daily.py', '--cfg-path', '/tmp/tmpvtx82zgu']
[2023-12-06, 16:56:06 UTC] {standard_task_runner.py:85} INFO - Job 2019635: Subtask addon_recommender
[2023-12-06, 16:56:06 UTC] {task_command.py:416} INFO - Running <TaskInstance: taar_daily.addon_recommender scheduled__2023-12-04T04:00:00+00:00 [running]> on host 10.20.2.206
[2023-12-06, 16:56:06 UTC] {taskinstance.py:1662} INFO - Exporting env vars: AIRFLOW_CTX_DAG_EMAIL='[e-mail],[e-mail],[e-mail]' AIRFLOW_CTX_DAG_OWNER='[e-mail]' AIRFLOW_CTX_DAG_ID='taar_daily' AIRFLOW_CTX_TASK_ID='addon_recommender' AIRFLOW_CTX_EXECUTION_DATE='2023-12-04T04:00:00+00:00' AIRFLOW_CTX_TRY_NUMBER='3' AIRFLOW_CTX_DAG_RUN_ID='scheduled__2023-12-04T04:00:00+00:00'
[2023-12-06, 16:56:06 UTC] {warnings.py:109} WARNING - /home/airflow/.local/lib/python3.10/site-packages/airflow/utils/context.py:206: AirflowContextDeprecationWarning: Accessing 'execution_date' from the template is deprecated and will be removed in a future version. Please use 'data_interval_start' or 'logical_date' instead.
  warnings.warn(_create_deprecation_warning(key, self._deprecation_replacements[key]))
[2023-12-06, 16:56:06 UTC] {subdag.py:174} INFO - Found existing DagRun: scheduled__2023-12-04T04:00:00+00:00
[2023-12-06, 16:57:06 UTC] {base.py:287} INFO - Success criteria met. Exiting.
[2023-12-06, 16:57:06 UTC] {subdag.py:187} INFO - Execution finished. State is failed
[2023-12-06, 16:57:06 UTC] {taskinstance.py:1937} ERROR - Task failed with exception
Traceback (most recent call last):
  File "/home/airflow/.local/lib/python3.10/site-packages/airflow/models/taskinstance.py", line 1518, in _run_raw_task
    self._execute_task_with_callbacks(context, test_mode, session=session)
  File "/home/airflow/.local/lib/python3.10/site-packages/airflow/models/taskinstance.py", line 1684, in _execute_task_with_callbacks
    self.task.post_execute(context=context, result=result)  # type: ignore[union-attr]
  File "/home/airflow/.local/lib/python3.10/site-packages/airflow/operators/subdag.py", line 190, in post_execute
    raise AirflowException(f"Expected state: SUCCESS. Actual state: {dag_run.state}")
airflow.exceptions.AirflowException: Expected state: SUCCESS. Actual state: failed
[2023-12-06, 16:57:06 UTC] {taskinstance.py:1400} INFO - Marking task as FAILED. dag_id=taar_daily, task_id=addon_recommender, execution_date=20231204T040000, start_date=20231206T165606, end_date=20231206T165706
[2023-12-06, 16:57:06 UTC] {warnings.py:109} WARNING - /home/airflow/.local/lib/python3.10/site-packages/airflow/utils/email.py:154: RemovedInAirflow3Warning: Fetching SMTP credentials from configuration variables will be deprecated in a future release. Please set credentials using a connection instead.
  send_mime_email(e_from=mail_from, e_to=recipients, mime_msg=msg, conn_id=conn_id, dryrun=dryrun)
[2023-12-06, 16:57:06 UTC] {email.py:270} INFO - Email alerting: attempt 1
[2023-12-06, 16:57:06 UTC] {email.py:281} INFO - Sent an alert email to ['[e-mail]', '[e-mail]', '[e-mail]']
[2023-12-06, 16:57:06 UTC] {standard_task_runner.py:104} ERROR - Failed to execute job 2019635 for task addon_recommender (Expected state: SUCCESS. Actual state: failed; 146966)
[2023-12-06, 16:57:06 UTC] {local_task_job_runner.py:228} INFO - Task exited with return code 1
[2023-12-06, 16:57:07 UTC] {taskinstance.py:2778} INFO - 0 downstream tasks scheduled from follow-on schedule check

Comment 1

[Marlene Hirose]

This job failed yesterday too

Comment 2

[Harold Woo]

logs from zooming into the subdag:

*** Found remote logs:
***   * gs://airflow-remote-logs-prod-prod/dag_id=taar_daily.addon_recommender/run_id=scheduled__2023-12-04T04:00:00+00:00/task_id=run_jar_on_dataproc/attempt=3.log
[2023-12-06, 16:56:08 UTC] {taskinstance.py:1159} INFO - Dependencies all met for dep_context=non-requeueable deps ti=<TaskInstance: taar_daily.addon_recommender.run_jar_on_dataproc scheduled__2023-12-04T04:00:00+00:00 [queued]>
[2023-12-06, 16:56:08 UTC] {taskinstance.py:1159} INFO - Dependencies all met for dep_context=requeueable deps ti=<TaskInstance: taar_daily.addon_recommender.run_jar_on_dataproc scheduled__2023-12-04T04:00:00+00:00 [queued]>
[2023-12-06, 16:56:08 UTC] {taskinstance.py:1361} INFO - Starting attempt 3 of 1
[2023-12-06, 16:56:08 UTC] {taskinstance.py:1382} INFO - Executing <Task(DataprocSubmitSparkJobOperator): run_jar_on_dataproc> on 2023-12-04 04:00:00+00:00
[2023-12-06, 16:56:08 UTC] {standard_task_runner.py:57} INFO - Started process 118554 to run task
[2023-12-06, 16:56:08 UTC] {standard_task_runner.py:84} INFO - Running: ['airflow', 'tasks', 'run', 'taar_daily.addon_recommender', 'run_jar_on_dataproc', 'scheduled__2023-12-04T04:00:00+00:00', '--job-id', '2019636', '--raw', '--subdir', 'DAGS_FOLDER/telemetry-airflow/dags/taar_daily.py', '--cfg-path', '/tmp/tmptvzh07v0']
[2023-12-06, 16:56:08 UTC] {standard_task_runner.py:85} INFO - Job 2019636: Subtask run_jar_on_dataproc
[2023-12-06, 16:56:08 UTC] {task_command.py:416} INFO - Running <TaskInstance: taar_daily.addon_recommender.run_jar_on_dataproc scheduled__2023-12-04T04:00:00+00:00 [running]> on host 10.20.2.67
[2023-12-06, 16:56:08 UTC] {taskinstance.py:1662} INFO - Exporting env vars: AIRFLOW_CTX_DAG_EMAIL='[e-mail],[e-mail],[e-mail]' AIRFLOW_CTX_DAG_OWNER='[e-mail]' AIRFLOW_CTX_DAG_ID='taar_daily.addon_recommender' AIRFLOW_CTX_TASK_ID='run_jar_on_dataproc' AIRFLOW_CTX_EXECUTION_DATE='2023-12-04T04:00:00+00:00' AIRFLOW_CTX_TRY_NUMBER='3' AIRFLOW_CTX_DAG_RUN_ID='scheduled__2023-12-04T04:00:00+00:00'
[2023-12-06, 16:56:08 UTC] {dataproc.py:1097} INFO - Submitting spark_job job Train_the_Collaborative_Addon_Recommender_746be4ef
[2023-12-06, 16:56:09 UTC] {taskinstance.py:1937} ERROR - Task failed with exception
Traceback (most recent call last):
  File "/home/airflow/.local/lib/python3.10/site-packages/google/api_core/grpc_helpers.py", line 75, in error_remapped_callable
    return callable_(*args, **kwargs)
  File "/home/airflow/.local/lib/python3.10/site-packages/grpc/_channel.py", line 1161, in __call__
    return _end_unary_response_blocking(state, call, False, None)
  File "/home/airflow/.local/lib/python3.10/site-packages/grpc/_channel.py", line 1004, in _end_unary_response_blocking
    raise _InactiveRpcError(state)  # pytype: disable=not-instantiable
grpc._channel._InactiveRpcError: <_InactiveRpcError of RPC that terminated with:
	status = StatusCode.NOT_FOUND
	details = "Not found: Cluster projects/airflow-dataproc/regions/us-west1/clusters/addon-recommender-20231204"
	debug_error_string = "UNKNOWN:Error received from peer ipv4:74.125.135.95:443 {grpc_message:"Not found: Cluster projects/airflow-dataproc/regions/us-west1/clusters/addon-recommender-20231204", grpc_status:5, created_time:"2023-12-06T16:56:09.117945985+00:00"}"
>
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
  File "/home/airflow/.local/lib/python3.10/site-packages/airflow/providers/google/cloud/operators/dataproc.py", line 1490, in execute
    super().execute(context)
  File "/home/airflow/.local/lib/python3.10/site-packages/airflow/providers/google/cloud/operators/dataproc.py", line 1098, in execute
    job_object = self.hook.submit_job(
  File "/home/airflow/.local/lib/python3.10/site-packages/airflow/providers/google/common/hooks/base_google.py", line 475, in inner_wrapper
    return func(self, *args, **kwargs)
  File "/home/airflow/.local/lib/python3.10/site-packages/airflow/providers/google/cloud/hooks/dataproc.py", line 790, in submit_job
    return client.submit_job(
  File "/home/airflow/.local/lib/python3.10/site-packages/google/cloud/dataproc_v1/services/job_controller/client.py", line 547, in submit_job
    response = rpc(
  File "/home/airflow/.local/lib/python3.10/site-packages/google/api_core/gapic_v1/method.py", line 131, in __call__
    return wrapped_func(*args, **kwargs)
  File "/home/airflow/.local/lib/python3.10/site-packages/google/api_core/retry.py", line 366, in retry_wrapped_func
    return retry_target(
  File "/home/airflow/.local/lib/python3.10/site-packages/google/api_core/retry.py", line 204, in retry_target
    return target()
  File "/home/airflow/.local/lib/python3.10/site-packages/google/api_core/grpc_helpers.py", line 77, in error_remapped_callable
    raise exceptions.from_grpc_error(exc) from exc
google.api_core.exceptions.NotFound: 404 Not found: Cluster projects/airflow-dataproc/regions/us-west1/clusters/addon-recommender-20231204
[2023-12-06, 16:56:09 UTC] {taskinstance.py:1400} INFO - Marking task as FAILED. dag_id=taar_daily.addon_recommender, task_id=run_jar_on_dataproc, execution_date=20231204T040000, start_date=20231206T165608, end_date=20231206T165609
[2023-12-06, 16:56:09 UTC] {warnings.py:109} WARNING - /home/airflow/.local/lib/python3.10/site-packages/airflow/utils/email.py:154: RemovedInAirflow3Warning: Fetching SMTP credentials from configuration variables will be deprecated in a future release. Please set credentials using a connection instead.
  send_mime_email(e_from=mail_from, e_to=recipients, mime_msg=msg, conn_id=conn_id, dryrun=dryrun)
[2023-12-06, 16:56:09 UTC] {email.py:270} INFO - Email alerting: attempt 1
[2023-12-06, 16:56:09 UTC] {email.py:281} INFO - Sent an alert email to ['[e-mail]', '[e-mail]', '[e-mail]']
[2023-12-06, 16:56:09 UTC] {standard_task_runner.py:104} ERROR - Failed to execute job 2019636 for task run_jar_on_dataproc (404 Not found: Cluster projects/airflow-dataproc/regions/us-west1/clusters/addon-recommender-20231204; 118554)
[2023-12-06, 16:56:09 UTC] {local_task_job_runner.py:228} INFO - Task exited with return code 1
[2023-12-06, 16:56:09 UTC] {taskinstance.py:2778} INFO - 0 downstream tasks scheduled from follow-on schedule check

this recent PR refactors the subdagoperator(deprecated) and may fix this
https://github.com/mozilla/telemetry-airflow/pull/1864

Comment 3

[anicholson]

Some discussion here in Bug 1866892

Comment 4

[anicholson]

Logs in the more recent failures stopped fetching (fetchAddonsDatabase) from the API much earlier than the previous successes https://addons.mozilla.org/api/v4/addons/search/?app=firefox&page=28&sort=created&type=extension vs. https:addons.mozilla.org...page=1000+ in successful runs. Could this be a resource issue?

I don't have much Scala experience so I haven't read much into the source - https://github.com/mozilla/telemetry-batch-view

cc :akomar who I believe has some spark experience?

Comment 5

[Arkadiusz Komarzewski [:akomar]]

I'm following up with AMO folks to figure out next steps.