Tfx: Airflow UI does not pick up TFX component logs
Summary
For some reason TFX writes the log files in a different format/path then expected by the Airflow Web UI. Therefore the logs on the UI don't show the really intressting logs (the root cause) but only that something went wrong (example s. below).
So for example, if the log root of Airflow is: /usr/local/airflow/logs
Official Log File
The log that appears on the UI is: /usr/local/airflow/logs/chicago_taxi_simple/CsvExampleGen/2019-05-29T11:03:26.751866+00:00
Which is follwing the offical format: {dag_id}/{task_id}/{execution_date}/{try_number}.log
Actual TFX log file
But the relevant logs are here: /usr/local/airflow/logs/chicago_taxi_simple.CsvExampleGen/chicago_taxi_simple.CsvExampleGen.checkcache/2019-05-29T11:03:26.751866+00:00
This seems to follow a different format (dot instead of sub folder): {dag_id}.{task_id}/{execution_date}/{try_number}.log
Question
Is there a way to either change the AirFlow UI or TFX, so that the relevant log appears in the UI. I had a look at the LoggerConfig but it does not contain a setting to change anything but the root log folder.
Additional Information
Both a local airflow instance and one running on a K8s cluster have the same problem. The airflow version is v1.10.2. I am running the chicago example pipeline with the settings described in this repo.
Just to make clear what I mean. This is the log on the UI (no information about the actual error):
[2019-05-29 11:03:54,685] {models.py:1359} INFO - Dependencies all met for <TaskInstance: chicago_taxi_simple.CsvExampleGen 2019-05-29T11:03:26.751866+00:00 [queued]>
[2019-05-29 11:03:54,706] {models.py:1359} INFO - Dependencies all met for <TaskInstance: chicago_taxi_simple.CsvExampleGen 2019-05-29T11:03:26.751866+00:00 [queued]>
[2019-05-29 11:03:54,706] {models.py:1571} INFO -
--------------------------------------------------------------------------------
Starting attempt 1 of 1
--------------------------------------------------------------------------------
[2019-05-29 11:03:54,725] {models.py:1593} INFO - Executing <Task(Component): CsvExampleGen> on 2019-05-29T11:03:26.751866+00:00
[2019-05-29 11:03:54,725] {base_task_runner.py:118} INFO - Running: ['bash', '-c', 'airflow run chicago_taxi_simple CsvExampleGen 2019-05-29T11:03:26.751866+00:00 --job_id 44 --raw -sd DAGS_FOLDER/taxi_pipeline_simple.py --cfg_path /tmp/tmpsg_x9rv7']
[2019-05-29 11:03:55,295] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen WARNING:root:OSError while attempting to symlink the latest log directory
[2019-05-29 11:03:55,553] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen [2019-05-29 11:03:55,553] {settings.py:174} INFO - settings.configure_orm(): Using pool settings. pool_size=5, pool_recycle=1800, pid=13
[2019-05-29 11:03:56,145] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen [2019-05-29 11:03:56,145] {__init__.py:51} INFO - Using executor LocalExecutor
[2019-05-29 11:03:56,577] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen [2019-05-29 11:03:56,576] {models.py:273} INFO - Filling up the DagBag from /usr/local/airflow/dags/taxi_pipeline_simple.py
[2019-05-29 11:04:02,105] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen /usr/local/airflow/dags/assets
[2019-05-29 11:04:02,105] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen /usr/local/airflow/dags/assets/data/simple
[2019-05-29 11:04:02,105] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen [2019-05-29 11:04:02,105] {cli.py:520} INFO - Running <TaskInstance: chicago_taxi_simple.CsvExampleGen 2019-05-29T11:03:26.751866+00:00 [running]> on host chicagotaxisimplecsvexamplegen-ee1d5266818e4cf0bab94a46b794c766
[2019-05-29 11:04:02,382] {logging_mixin.py:95} INFO - [2019-05-29 11:04:02,381] {base_executor.py:56} INFO - Adding to queue: airflow run chicago_taxi_simple.CsvExampleGen chicago_taxi_simple.CsvExampleGen.checkcache 2019-05-29T11:03:26.751866+00:00 --local -sd DAGS_FOLDER/taxi_pipeline_simple.py --cfg_path /tmp/tmpvn0z61z_
[2019-05-29 11:04:07,172] {logging_mixin.py:95} INFO - [2019-05-29 11:04:07,172] {sequential_executor.py:45} INFO - Executing command: airflow run chicago_taxi_simple.CsvExampleGen chicago_taxi_simple.CsvExampleGen.checkcache 2019-05-29T11:03:26.751866+00:00 --local -sd DAGS_FOLDER/taxi_pipeline_simple.py --cfg_path /tmp/tmpvn0z61z_
[2019-05-29 11:04:07,673] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen WARNING:root:OSError while attempting to symlink the latest log directory
[2019-05-29 11:04:07,911] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen [2019-05-29 11:04:07,910] {settings.py:174} INFO - settings.configure_orm(): Using pool settings. pool_size=5, pool_recycle=1800, pid=23
[2019-05-29 11:04:08,401] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen [2019-05-29 11:04:08,401] {__init__.py:51} INFO - Using executor LocalExecutor
[2019-05-29 11:04:08,750] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen [2019-05-29 11:04:08,749] {models.py:273} INFO - Filling up the DagBag from /usr/local/airflow/dags/taxi_pipeline_simple.py
[2019-05-29 11:04:14,220] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen /usr/local/airflow/dags/assets
[2019-05-29 11:04:14,220] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen /usr/local/airflow/dags/assets/data/simple
[2019-05-29 11:04:14,220] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen [2019-05-29 11:04:14,219] {cli.py:520} INFO - Running <TaskInstance: chicago_taxi_simple.CsvExampleGen.chicago_taxi_simple.CsvExampleGen.checkcache 2019-05-29T11:03:26.751866+00:00 [queued]> on host chicagotaxisimplecsvexamplegen-ee1d5266818e4cf0bab94a46b794c766
[2019-05-29 11:04:24,343] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen /usr/local/lib/python3.6/site-packages/psycopg2/__init__.py:144: UserWarning: The psycopg2 wheel package will be renamed from release 2.8; in order to keep installing from binary please use "pip install psycopg2-binary" instead. For details see: <http://initd.org/psycopg/docs/install.html#binary-install-from-pypi>.
[2019-05-29 11:04:24,343] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen """)
[2019-05-29 11:04:24,343] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen /usr/local/lib/python3.6/site-packages/apache_beam/__init__.py:84: UserWarning: Running the Apache Beam SDK on Python 3 is not yet fully supported. You may encounter buggy behavior or missing features.
[2019-05-29 11:04:24,343] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen 'Running the Apache Beam SDK on Python 3 is not yet fully supported. '
[2019-05-29 11:04:25,072] {logging_mixin.py:95} INFO - [2019-05-29 11:04:25,070] {jobs.py:1926} ERROR - Task instance <TaskInstance: chicago_taxi_simple.CsvExampleGen.chicago_taxi_simple.CsvExampleGen.checkcache 2019-05-29 11:03:26.751866+00:00 [failed]> failed
[2019-05-29 11:04:25,125] {logging_mixin.py:95} INFO - [2019-05-29 11:04:25,125] {jobs.py:2100} INFO - [backfill progress] | finished run 0 of 1 | tasks waiting: 3 | succeeded: 0 | running: 0 | failed: 1 | skipped: 0 | deadlocked: 0 | not ready: 3
[2019-05-29 11:04:25,135] {logging_mixin.py:95} INFO - [2019-05-29 11:04:25,135] {jobs.py:2199} ERROR - Task instance <TaskInstance: chicago_taxi_simple.CsvExampleGen.chicago_taxi_simple.CsvExampleGen.exec 2019-05-29 11:03:26.751866+00:00 [upstream_failed]> with upstream_failed state
[2019-05-29 11:04:25,181] {logging_mixin.py:95} INFO - [2019-05-29 11:04:25,181] {jobs.py:2251} ERROR - Task instance <TaskInstance: chicago_taxi_simple.CsvExampleGen.chicago_taxi_simple.CsvExampleGen.publishcache 2019-05-29 11:03:26.751866+00:00 [upstream_failed]> upstream failed
[2019-05-29 11:04:25,219] {logging_mixin.py:95} INFO - [2019-05-29 11:04:25,218] {jobs.py:2251} ERROR - Task instance <TaskInstance: chicago_taxi_simple.CsvExampleGen.chicago_taxi_simple.CsvExampleGen.publishexec 2019-05-29 11:03:26.751866+00:00 [upstream_failed]> upstream failed
[2019-05-29 11:04:25,251] {logging_mixin.py:95} INFO - [2019-05-29 11:04:25,251] {models.py:5258} INFO - Marking run <DagRun chicago_taxi_simple.CsvExampleGen @ 2019-05-29T11:03:26.751866+00:00: backfill_2019-05-29T11:03:26.751866+00:00, externally triggered: False> failed
[2019-05-29 11:04:25,299] {logging_mixin.py:95} INFO - [2019-05-29 11:04:25,299] {jobs.py:2100} INFO - [backfill progress] | finished run 1 of 1 | tasks waiting: 0 | succeeded: 0 | running: 0 | failed: 4 | skipped: 0 | deadlocked: 0 | not ready: 0
[2019-05-29 11:04:25,324] {models.py:1788} ERROR - ---------------------------------------------------
Some task instances failed:
{('chicago_taxi_simple.CsvExampleGen', 'chicago_taxi_simple.CsvExampleGen.exec', datetime.datetime(2019, 5, 29, 11, 3, 26, 751866, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1), ('chicago_taxi_simple.CsvExampleGen', 'chicago_taxi_simple.CsvExampleGen.publishexec', datetime.datetime(2019, 5, 29, 11, 3, 26, 751866, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1), ('chicago_taxi_simple.CsvExampleGen', 'chicago_taxi_simple.CsvExampleGen.publishcache', datetime.datetime(2019, 5, 29, 11, 3, 26, 751866, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1), ('chicago_taxi_simple.CsvExampleGen', 'chicago_taxi_simple.CsvExampleGen.checkcache', datetime.datetime(2019, 5, 29, 11, 3, 26, 751866, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1)}
Traceback (most recent call last):
File "/usr/local/lib/python3.6/site-packages/airflow/models.py", line 1657, in _run_raw_task
result = task_copy.execute(context=context)
File "/usr/local/lib/python3.6/site-packages/airflow/operators/subdag_operator.py", line 103, in execute
executor=self.executor)
File "/usr/local/lib/python3.6/site-packages/airflow/models.py", line 4324, in run
job.run()
File "/usr/local/lib/python3.6/site-packages/airflow/jobs.py", line 202, in run
self._execute()
File "/usr/local/lib/python3.6/site-packages/airflow/utils/db.py", line 73, in wrapper
return func(*args, **kwargs)
File "/usr/local/lib/python3.6/site-packages/airflow/jobs.py", line 2447, in _execute
raise AirflowException(err)
airflow.exceptions.AirflowException: ---------------------------------------------------
Some task instances failed:
{('chicago_taxi_simple.CsvExampleGen', 'chicago_taxi_simple.CsvExampleGen.exec', datetime.datetime(2019, 5, 29, 11, 3, 26, 751866, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1), ('chicago_taxi_simple.CsvExampleGen', 'chicago_taxi_simple.CsvExampleGen.publishexec', datetime.datetime(2019, 5, 29, 11, 3, 26, 751866, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1), ('chicago_taxi_simple.CsvExampleGen', 'chicago_taxi_simple.CsvExampleGen.publishcache', datetime.datetime(2019, 5, 29, 11, 3, 26, 751866, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1), ('chicago_taxi_simple.CsvExampleGen', 'chicago_taxi_simple.CsvExampleGen.checkcache', datetime.datetime(2019, 5, 29, 11, 3, 26, 751866, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1)}
[2019-05-29 11:04:25,345] {models.py:1819} INFO - Marking task as FAILED.
[2019-05-29 11:04:25,364] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen /usr/local/lib/python3.6/site-packages/psycopg2/__init__.py:144: UserWarning: The psycopg2 wheel package will be renamed from release 2.8; in order to keep installing from binary please use "pip install psycopg2-binary" instead. For details see: <http://initd.org/psycopg/docs/install.html#binary-install-from-pypi>.
[2019-05-29 11:04:25,364] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen """)
[2019-05-29 11:04:25,365] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen /usr/local/lib/python3.6/site-packages/apache_beam/__init__.py:84: UserWarning: Running the Apache Beam SDK on Python 3 is not yet fully supported. You may encounter buggy behavior or missing features.
[2019-05-29 11:04:25,365] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen 'Running the Apache Beam SDK on Python 3 is not yet fully supported. '
[2019-05-29 11:04:25,450] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen Traceback (most recent call last):
[2019-05-29 11:04:25,450] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen File "/usr/local/bin/airflow", line 32, in <module>
[2019-05-29 11:04:25,450] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen args.func(args)
[2019-05-29 11:04:25,450] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen File "/usr/local/lib/python3.6/site-packages/airflow/utils/cli.py", line 74, in wrapper
[2019-05-29 11:04:25,450] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen return f(*args, **kwargs)
[2019-05-29 11:04:25,450] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen File "/usr/local/lib/python3.6/site-packages/airflow/bin/cli.py", line 526, in run
[2019-05-29 11:04:25,450] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen _run(args, dag, ti)
[2019-05-29 11:04:25,450] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen File "/usr/local/lib/python3.6/site-packages/airflow/bin/cli.py", line 445, in _run
[2019-05-29 11:04:25,450] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen pool=args.pool,
[2019-05-29 11:04:25,450] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen File "/usr/local/lib/python3.6/site-packages/airflow/utils/db.py", line 73, in wrapper
[2019-05-29 11:04:25,450] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen return func(*args, **kwargs)
[2019-05-29 11:04:25,450] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen File "/usr/local/lib/python3.6/site-packages/airflow/models.py", line 1657, in _run_raw_task
[2019-05-29 11:04:25,451] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen result = task_copy.execute(context=context)
[2019-05-29 11:04:25,451] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen File "/usr/local/lib/python3.6/site-packages/airflow/operators/subdag_operator.py", line 103, in execute
[2019-05-29 11:04:25,451] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen executor=self.executor)
[2019-05-29 11:04:25,451] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen File "/usr/local/lib/python3.6/site-packages/airflow/models.py", line 4324, in run
[2019-05-29 11:04:25,451] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen job.run()
[2019-05-29 11:04:25,451] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen File "/usr/local/lib/python3.6/site-packages/airflow/jobs.py", line 202, in run
[2019-05-29 11:04:25,451] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen self._execute()
[2019-05-29 11:04:25,451] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen File "/usr/local/lib/python3.6/site-packages/airflow/utils/db.py", line 73, in wrapper
[2019-05-29 11:04:25,451] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen return func(*args, **kwargs)
[2019-05-29 11:04:25,451] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen File "/usr/local/lib/python3.6/site-packages/airflow/jobs.py", line 2447, in _execute
[2019-05-29 11:04:25,451] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen raise AirflowException(err)
[2019-05-29 11:04:25,451] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen airflow.exceptions.AirflowException: ---------------------------------------------------
[2019-05-29 11:04:25,451] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen Some task instances failed:
[2019-05-29 11:04:25,451] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen {('chicago_taxi_simple.CsvExampleGen', 'chicago_taxi_simple.CsvExampleGen.exec', datetime.datetime(2019, 5, 29, 11, 3, 26, 751866, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1), ('chicago_taxi_simple.CsvExampleGen', 'chicago_taxi_simple.CsvExampleGen.publishexec', datetime.datetime(2019, 5, 29, 11, 3, 26, 751866, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1), ('chicago_taxi_simple.CsvExampleGen', 'chicago_taxi_simple.CsvExampleGen.publishcache', datetime.datetime(2019, 5, 29, 11, 3, 26, 751866, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1), ('chicago_taxi_simple.CsvExampleGen', 'chicago_taxi_simple.CsvExampleGen.checkcache', datetime.datetime(2019, 5, 29, 11, 3, 26, 751866, tzinfo=<TimezoneInfo [UTC, GMT, +00:00:00, STD]>), 1)}
[2019-05-29 11:04:25,451] {base_task_runner.py:101} INFO - Job 44: Subtask CsvExampleGen
[2019-05-29 11:04:29,715] {logging_mixin.py:95} INFO - [2019-05-29 11:04:29,713] {jobs.py:2527} INFO - Task exited with return code 1
An this is the log with the real information (saying that the metadata store was unable to open database file):
[2019-05-29 11:04:14,270] {models.py:1359} INFO - Dependencies all met for <TaskInstance: chicago_taxi_simple.CsvExampleGen.chicago_taxi_simple.CsvExampleGen.checkcache 2019-05-29T11:03:26.751866+00:00 [queued]>
[2019-05-29 11:04:14,278] {models.py:1359} INFO - Dependencies all met for <TaskInstance: chicago_taxi_simple.CsvExampleGen.chicago_taxi_simple.CsvExampleGen.checkcache 2019-05-29T11:03:26.751866+00:00 [queued]>
[2019-05-29 11:04:14,278] {models.py:1571} INFO -
--------------------------------------------------------------------------------
Starting attempt 1 of 1
--------------------------------------------------------------------------------
[2019-05-29 11:04:14,295] {models.py:1593} INFO - Executing <Task(BranchPythonOperator): chicago_taxi_simple.CsvExampleGen.checkcache> on 2019-05-29T11:03:26.751866+00:00
[2019-05-29 11:04:14,295] {base_task_runner.py:118} INFO - Running: ['bash', '-c', 'airflow run chicago_taxi_simple.CsvExampleGen chicago_taxi_simple.CsvExampleGen.checkcache 2019-05-29T11:03:26.751866+00:00 --job_id 46 --raw -sd DAGS_FOLDER/taxi_pipeline_simple.py --cfg_path /tmp/tmprrn3fjt_']
[2019-05-29 11:04:14,794] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache WARNING:root:OSError while attempting to symlink the latest log directory
[2019-05-29 11:04:15,017] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache [2019-05-29 11:04:15,017] {settings.py:174} INFO - settings.configure_orm(): Using pool settings. pool_size=5, pool_recycle=1800, pid=31
[2019-05-29 11:04:15,493] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache [2019-05-29 11:04:15,493] {__init__.py:51} INFO - Using executor LocalExecutor
[2019-05-29 11:04:15,861] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache [2019-05-29 11:04:15,861] {models.py:273} INFO - Filling up the DagBag from /usr/local/airflow/dags/taxi_pipeline_simple.py
[2019-05-29 11:04:21,192] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache /usr/local/airflow/dags/assets
[2019-05-29 11:04:21,192] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache /usr/local/airflow/dags/assets/data/simple
[2019-05-29 11:04:21,192] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache [2019-05-29 11:04:21,191] {cli.py:520} INFO - Running <TaskInstance: chicago_taxi_simple.CsvExampleGen.chicago_taxi_simple.CsvExampleGen.checkcache 2019-05-29T11:03:26.751866+00:00 [running]> on host chicagotaxisimplecsvexamplegen-ee1d5266818e4cf0bab94a46b794c766
[2019-05-29 11:04:21,223] {python_operator.py:95} INFO - Exporting the following env vars:
AIRFLOW_CTX_DAG_ID=chicago_taxi_simple.CsvExampleGen
AIRFLOW_CTX_TASK_ID=chicago_taxi_simple.CsvExampleGen.checkcache
AIRFLOW_CTX_EXECUTION_DATE=2019-05-29T11:03:26.751866+00:00
AIRFLOW_CTX_DAG_RUN_ID=backfill_2019-05-29T11:03:26.751866+00:00
[2019-05-29 11:04:21,263] {models.py:1788} ERROR - <built-in function CreateMetadataStore> returned a result with an error set
RuntimeError: Cannot connect sqlite3 database: unable to open database file
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/usr/local/lib/python3.6/site-packages/airflow/models.py", line 1657, in _run_raw_task
result = task_copy.execute(context=context)
File "/usr/local/lib/python3.6/site-packages/airflow/operators/python_operator.py", line 131, in execute
branch = super(BranchPythonOperator, self).execute(context)
File "/usr/local/lib/python3.6/site-packages/airflow/operators/python_operator.py", line 103, in execute
return_value = self.execute_callable()
File "/usr/local/lib/python3.6/site-packages/airflow/operators/python_operator.py", line 108, in execute_callable
return self.python_callable(*self.op_args, **self.op_kwargs)
File "/usr/local/lib/python3.6/site-packages/tfx/orchestration/airflow/airflow_adapter.py", line 110, in check_cache_and_maybe_prepare_execution
self._logger) as m:
File "/usr/local/lib/python3.6/site-packages/tfx/orchestration/metadata.py", line 53, in __enter__
self._store = metadata_store.MetadataStore(self._connection_config)
File "/usr/local/lib/python3.6/site-packages/ml_metadata/metadata_store/metadata_store.py", line 48, in __init__
config.SerializeToString())
SystemError: <built-in function CreateMetadataStore> returned a result with an error set
[2019-05-29 11:04:21,298] {models.py:1819} INFO - Marking task as FAILED.
[2019-05-29 11:04:21,452] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache /usr/local/lib/python3.6/site-packages/psycopg2/__init__.py:144: UserWarning: The psycopg2 wheel package will be renamed from release 2.8; in order to keep installing from binary please use "pip install psycopg2-binary" instead. For details see: <http://initd.org/psycopg/docs/install.html#binary-install-from-pypi>.
[2019-05-29 11:04:21,452] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache """)
[2019-05-29 11:04:21,452] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache /usr/local/lib/python3.6/site-packages/apache_beam/__init__.py:84: UserWarning: Running the Apache Beam SDK on Python 3 is not yet fully supported. You may encounter buggy behavior or missing features.
[2019-05-29 11:04:21,452] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache 'Running the Apache Beam SDK on Python 3 is not yet fully supported. '
[2019-05-29 11:04:21,521] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache RuntimeError: Cannot connect sqlite3 database: unable to open database file
[2019-05-29 11:04:21,521] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache
[2019-05-29 11:04:21,521] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache The above exception was the direct cause of the following exception:
[2019-05-29 11:04:21,521] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache
[2019-05-29 11:04:21,521] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache Traceback (most recent call last):
[2019-05-29 11:04:21,521] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache File "/usr/local/bin/airflow", line 32, in <module>
[2019-05-29 11:04:21,521] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache args.func(args)
[2019-05-29 11:04:21,521] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache File "/usr/local/lib/python3.6/site-packages/airflow/utils/cli.py", line 74, in wrapper
[2019-05-29 11:04:21,521] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache return f(*args, **kwargs)
[2019-05-29 11:04:21,522] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache File "/usr/local/lib/python3.6/site-packages/airflow/bin/cli.py", line 526, in run
[2019-05-29 11:04:21,522] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache _run(args, dag, ti)
[2019-05-29 11:04:21,522] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache File "/usr/local/lib/python3.6/site-packages/airflow/bin/cli.py", line 445, in _run
[2019-05-29 11:04:21,522] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache pool=args.pool,
[2019-05-29 11:04:21,522] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache File "/usr/local/lib/python3.6/site-packages/airflow/utils/db.py", line 73, in wrapper
[2019-05-29 11:04:21,522] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache return func(*args, **kwargs)
[2019-05-29 11:04:21,522] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache File "/usr/local/lib/python3.6/site-packages/airflow/models.py", line 1657, in _run_raw_task
[2019-05-29 11:04:21,522] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache result = task_copy.execute(context=context)
[2019-05-29 11:04:21,522] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache File "/usr/local/lib/python3.6/site-packages/airflow/operators/python_operator.py", line 131, in execute
[2019-05-29 11:04:21,522] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache branch = super(BranchPythonOperator, self).execute(context)
[2019-05-29 11:04:21,522] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache File "/usr/local/lib/python3.6/site-packages/airflow/operators/python_operator.py", line 103, in execute
[2019-05-29 11:04:21,522] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache return_value = self.execute_callable()
[2019-05-29 11:04:21,522] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache File "/usr/local/lib/python3.6/site-packages/airflow/operators/python_operator.py", line 108, in execute_callable
[2019-05-29 11:04:21,522] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache return self.python_callable(*self.op_args, **self.op_kwargs)
[2019-05-29 11:04:21,522] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache File "/usr/local/lib/python3.6/site-packages/tfx/orchestration/airflow/airflow_adapter.py", line 110, in check_cache_and_maybe_prepare_execution
[2019-05-29 11:04:21,522] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache self._logger) as m:
[2019-05-29 11:04:21,522] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache File "/usr/local/lib/python3.6/site-packages/tfx/orchestration/metadata.py", line 53, in __enter__
[2019-05-29 11:04:21,523] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache self._store = metadata_store.MetadataStore(self._connection_config)
[2019-05-29 11:04:21,523] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache File "/usr/local/lib/python3.6/site-packages/ml_metadata/metadata_store/metadata_store.py", line 48, in __init__
[2019-05-29 11:04:21,523] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache config.SerializeToString())
[2019-05-29 11:04:21,523] {base_task_runner.py:101} INFO - Job 46: Subtask chicago_taxi_simple.CsvExampleGen.checkcache SystemError: <built-in function CreateMetadataStore> returned a result with an error set
[2019-05-29 11:04:24,267] {logging_mixin.py:95} INFO - [2019-05-29 11:04:24,265] {jobs.py:2527} INFO - Task exited with return code 1
rummens
All 16 comments
This is likely because the "CsvExampleGen" component you see in the web UI is actually a sub-DAG in Airflow, which includes four components (.check_cache, .exec, .publish and .publish_cache).
I am not sure why the documented way of log investigation for sub dag did not work in our case. It may be related to how the sub-dag is created?
cc + @ruoyu90 @krazyhaas
zhitaoli
on 29 May 2019
Will this happen to all other components as well or is it just the Example Gen?
Is there a way to change the config back to a normal DAG?
rummens
on 29 May 2019
We're looking into it. It's likely related to all components.
krazyhaas
on 29 May 2019
I'll likely have a fix for this out tomorrow. I'd like another day to test the potential change.
krazyhaas
on 30 May 2019
Awesome thank you. Happy to test myself, once you have it ready. 馃憤
rummens
on 30 May 2019
Any update?
rummens
on 3 Jun 2019
Just waiting for approvals on the code review.
krazyhaas
on 3 Jun 2019
👍1
Quick update -- we're having issues with an unrelated test that's blocking the checkin. If you want to patch the change into your code, it's literally a two-line change to enable this.
krazyhaas
on 4 Jun 2019
I assume you are talking about #188? If so I see your changes and should be able to replicate them. Thanks :-)
rummens
on 4 Jun 2019
Done! You should now be able to see both the component/subcomponent logs as well as the actual nodes in the DAG viewer. Sorry about the delay -- getting the test updated and passing was actually more work than the code change itself. :)
krazyhaas
on 5 Jun 2019
👍1
I can confirm that it works. Both logs appear in the UI. Thank you.
rummens
on 7 Jun 2019
@rummens Do you remember what was causing that error with not being able to open the database file? I'm getting that error now on the taxi example.
jmugan
on 26 Sep 2019
Yes the path that I was using was just wrong or not accessible because of privilege problems. Change the metadb root variable and make sure the path is okay.
rummens
on 26 Sep 2019
Dang, that's not my problem. The path seems fine. It just starting doing that out of the blue. I'll keep digging, thanks.
jmugan
on 26 Sep 2019
Changed permissions? Keep in mind that the airflow path might differ from your development path (except if you are developing in ~/airflow.
Maybe delete DB file and let TFX create a new one?
I also had some issues with multiple reads to the DB causing an issue but the error message was different.
rummens
on 26 Sep 2019
👍1
Oh, wait, it looks like they changed it where you need to put the db name on the end of the path and not just pass the path. Hallelujah! Thanks!
jmugan
on 26 Sep 2019
Was this page helpful?
0 / 5 - 0 ratings
Related issues
ianhellstrom
路
3Comments
Malonl
路
6Comments
Mageswaran1989
路
7Comments
josekidengan
路
4Comments
rcrowe-google
路
3Comments