Erik Forsberg created AIRFLOW-1259:
--------------------------------------
Summary: Spontaneous death of gunicorn workers due to import error
Key: AIRFLOW-1259
URL: https://issues.apache.org/jira/browse/AIRFLOW-1259
Project: Apache Airflow
Issue Type: Bug
Affects Versions: 1.8.1
Reporter: Erik Forsberg
I'm running apache-airflow 1.8.1 in a python 3.4 virtualenv, and I'm having
trouble with the webserver component going offline almost daily.
It gets worse due to AIRFLOW-1235, since the death of the process is not
detected by systemd, which could otherwise restart it.
The root cause seems to be all-of-a-sudden import errors. Here's how it looked
in the log from yesterday evening:
{noformat}
May 31 17:23:18 airmaster01 airflow[26096]: [2017-05-31 17:23:18 +0000] [26108]
[INFO] Handling signal: ttin
May 31 17:23:18 airmaster01 airflow[26096]: [2017-05-31 17:23:18 +0000] [1412]
[INFO] Booting worker with pid: 1412
May 31 17:23:18 airmaster01 airflow[26096]: [2017-05-31 17:23:18,912] [1412]
{models.py:168} INFO - Filling up the DagBag from /home/airflow/production/dags
May 31 17:23:20 airmaster01 airflow[26096]: [2017-05-31 17:23:20 +0000] [26108]
[INFO] Handling signal: ttou
May 31 17:23:20 airmaster01 airflow[26096]:
/opt/airflow/production/lib/python3.4/site-packages/flask/exthook.py:71:
ExtDeprecationWarning: Importing flask.ext.cache is deprecated, use flask_cache
instead.
May 31 17:23:20 airmaster01 airflow[26096]: .format(x=modname),
ExtDeprecationWarning
May 31 17:23:20 airmaster01 airflow[26096]: [2017-05-31 17:23:20 +0000] [710]
[INFO] Worker exiting (pid: 710)
May 31 17:23:51 airmaster01 airflow[26096]: [2017-05-31 17:23:51 +0000] [26108]
[INFO] Handling signal: ttin
May 31 17:23:51 airmaster01 airflow[26096]: [2017-05-31 17:23:51 +0000] [1595]
[INFO] Booting worker with pid: 1595
May 31 17:23:51 airmaster01 airflow[26096]: [2017-05-31 17:23:51,850] [1595]
{models.py:168} INFO - Filling up the DagBag from /home/airflow/production/dags
May 31 17:23:53 airmaster01 airflow[26096]: [2017-05-31 17:23:53 +0000] [26108]
[INFO] Handling signal: ttou
May 31 17:23:53 airmaster01 airflow[26096]:
/opt/airflow/production/lib/python3.4/site-packages/flask/exthook.py:71:
ExtDeprecationWarning: Importing flask.ext.cache is deprecated, use flask_cache
instead.
May 31 17:23:53 airmaster01 airflow[26096]: .format(x=modname),
ExtDeprecationWarning
May 31 17:23:53 airmaster01 airflow[26096]: [2017-05-31 17:23:53 +0000] [895]
[INFO] Worker exiting (pid: 895)
May 31 17:24:24 airmaster01 airflow[26096]: [2017-05-31 17:24:24 +0000] [26108]
[INFO] Handling signal: ttin
May 31 17:24:24 airmaster01 airflow[26096]: [2017-05-31 17:24:24 +0000] [1786]
[INFO] Booting worker with pid: 1786
May 31 17:24:25 airmaster01 airflow[26096]: [2017-05-31 17:24:25,008] [1786]
{models.py:168} INFO - Filling up the DagBag from /home/airflow/production/dags
May 31 17:24:26 airmaster01 airflow[26096]: [2017-05-31 17:24:26 +0000] [26108]
[INFO] Handling signal: ttou
...skipping...
May 31 17:29:56 airmaster01 airflow[26096]: [2017-05-31 17:29:56 +0000] [26108]
[INFO] Handling signal: ttou
May 31 17:29:56 airmaster01 airflow[26096]:
/opt/airflow/production/lib/python3.4/site-packages/flask/exthook.py:71:
ExtDeprecationWarning: Importing flask.ext.cache is deprecated, use flask_cache
instead.
May 31 17:29:56 airmaster01 airflow[26096]: .format(x=modname),
ExtDeprecationWarning
May 31 17:29:56 airmaster01 airflow[26096]: [2017-05-31 17:29:56 +0000] [2805]
[INFO] Worker exiting (pid: 2805)
May 31 17:30:27 airmaster01 airflow[26096]: [2017-05-31 17:30:27 +0000] [26108]
[INFO] Handling signal: ttin
May 31 17:30:27 airmaster01 airflow[26096]: [2017-05-31 17:30:27 +0000] [3710]
[INFO] Booting worker with pid: 3710
May 31 17:30:27 airmaster01 airflow[26096]: [2017-05-31 17:30:27,859] [3710]
{models.py:168} INFO - Filling up the DagBag from /home/airflow/production/dags
May 31 17:30:30 airmaster01 airflow[26096]: [2017-05-31 17:30:30 +0000] [26108]
[INFO] Handling signal: ttou
May 31 17:30:30 airmaster01 airflow[26096]:
/opt/airflow/production/lib/python3.4/site-packages/flask/exthook.py:71:
ExtDeprecationWarning: Importing flask.ext.cache is deprecated, use flask_cache
instead.
May 31 17:30:30 airmaster01 airflow[26096]: .format(x=modname),
ExtDeprecationWarning
May 31 17:30:30 airmaster01 airflow[26096]: [2017-05-31 17:30:30 +0000] [2994]
[INFO] Worker exiting (pid: 2994)
May 31 17:31:01 airmaster01 airflow[26096]: [2017-05-31 17:31:01 +0000] [26108]
[INFO] Handling signal: ttin
May 31 17:31:01 airmaster01 airflow[26096]: [2017-05-31 17:31:01 +0000] [4240]
[INFO] Booting worker with pid: 4240
May 31 17:31:02 airmaster01 airflow[26096]:
/opt/airflow/production/lib/python3.4/site-packages/flask/exthook.py:71:
ExtDeprecationWarning: Importing flask.ext.cache is deprecated, use flask_cache
instead.
May 31 17:31:02 airmaster01 airflow[26096]: .format(x=modname),
ExtDeprecationWarning
May 31 17:31:02 airmaster01 airflow[26096]: [2017-05-31 17:31:02 +0000] [4240]
[ERROR] Exception in worker process:
May 31 17:31:02 airmaster01 airflow[26096]: Traceback (most recent call last):
May 31 17:31:02 airmaster01 airflow[26096]: File
"/opt/airflow/production/lib/python3.4/site-packages/gunicorn/arbiter.py", line
507, in spawn_worker
May 31 17:31:02 airmaster01 airflow[26096]: worker.init_process()
May 31 17:31:02 airmaster01 airflow[26096]: File
"/opt/airflow/production/lib/python3.4/site-packages/gunicorn/workers/base.py",
line 118, in init_process
May 31 17:31:02 airmaster01 airflow[26096]: self.wsgi = self.app.wsgi()
May 31 17:31:02 airmaster01 airflow[26096]: File
"/opt/airflow/production/lib/python3.4/site-packages/gunicorn/app/base.py",
line 67, in wsgi
May 31 17:31:02 airmaster01 airflow[26096]: self.callable = self.load()
May 31 17:31:02 airmaster01 airflow[26096]: File
"/opt/airflow/production/lib/python3.4/site-packages/gunicorn/app/wsgiapp.py",
line 65, in load
May 31 17:31:02 airmaster01 airflow[26096]: return self.load_wsgiapp()
May 31 17:31:02 airmaster01 airflow[26096]: File
"/opt/airflow/production/lib/python3.4/site-packages/gunicorn/app/wsgiapp.py",
line 52, in load_wsgiapp
May 31 17:31:02 airmaster01 airflow[26096]: return util.import_app(self.app_uri)
May 31 17:31:02 airmaster01 airflow[26096]: File
"/opt/airflow/production/lib/python3.4/site-packages/gunicorn/util.py", line
366, in import_app
May 31 17:31:02 airmaster01 airflow[26096]: app = eval(obj, mod.__dict__)
May 31 17:31:02 airmaster01 airflow[26096]: File "<string>", line 1, in <module>
May 31 17:31:02 airmaster01 airflow[26096]: File
"/opt/airflow/production/lib/python3.4/site-packages/airflow/www/app.py", line
161, in cached_app
May 31 17:31:02 airmaster01 airflow[26096]: File
"/opt/airflow/production/lib/python3.4/site-packages/airflow/www/app.py", line
60, in create_app
May 31 17:31:02 airmaster01 airflow[26096]: File
"/opt/airflow/production/lib/python3.4/site-packages/airflow/www/views.py",
line 74, in <module>
May 31 17:31:02 airmaster01 airflow[26096]: ImportError: cannot import name
'utils'
May 31 17:31:02 airmaster01 airflow[26096]: Traceback (most recent call last):
May 31 17:31:02 airmaster01 airflow[26096]: File
"/opt/airflow/production/lib/python3.4/site-packages/gunicorn/arbiter.py", line
507, in spawn_worker
May 31 17:31:02 airmaster01 airflow[26096]: worker.init_process()
May 31 17:31:02 airmaster01 airflow[26096]: File
"/opt/airflow/production/lib/python3.4/site-packages/gunicorn/workers/base.py",
line 118, in init_process
May 31 17:31:02 airmaster01 airflow[26096]: self.wsgi = self.app.wsgi()
May 31 17:31:02 airmaster01 airflow[26096]: File
"/opt/airflow/production/lib/python3.4/site-packages/gunicorn/app/base.py",
line 67, in wsgi
May 31 17:31:02 airmaster01 airflow[26096]: self.callable = self.load()
May 31 17:31:02 airmaster01 airflow[26096]: File
"/opt/airflow/production/lib/python3.4/site-packages/gunicorn/app/wsgiapp.py",
line 65, in load
May 31 17:31:02 airmaster01 airflow[26096]: return self.load_wsgiapp()
May 31 17:31:02 airmaster01 airflow[26096]: File
"/opt/airflow/production/lib/python3.4/site-packages/gunicorn/app/wsgiapp.py",
line 52, in load_wsgiapp
May 31 17:31:02 airmaster01 airflow[26096]: return util.import_app(self.app_uri)
May 31 17:31:02 airmaster01 airflow[26096]: File
"/opt/airflow/production/lib/python3.4/site-packages/gunicorn/util.py", line
366, in import_app
May 31 17:31:02 airmaster01 airflow[26096]: app = eval(obj, mod.__dict__)
May 31 17:31:02 airmaster01 airflow[26096]: File "<string>", line 1, in <module>
May 31 17:31:02 airmaster01 airflow[26096]: File
"/opt/airflow/production/lib/python3.4/site-packages/airflow/www/app.py", line
161, in cached_app
May 31 17:31:02 airmaster01 airflow[26096]: File
"/opt/airflow/production/lib/python3.4/site-packages/airflow/www/app.py", line
60, in create_app
May 31 17:31:02 airmaster01 airflow[26096]: File
"/opt/airflow/production/lib/python3.4/site-packages/airflow/www/views.py",
line 74, in <module>
May 31 17:31:02 airmaster01 airflow[26096]: ImportError: cannot import name
'utils'
May 31 17:31:02 airmaster01 airflow[26096]: [2017-05-31 17:31:02 +0000] [4240]
[INFO] Worker exiting (pid: 4240)
May 31 17:31:02 airmaster01 airflow[26096]:
/opt/airflow/production/lib/python3.4/site-packages/flask/exthook.py:71:
ExtDeprecationWarning: Importing flask.ext.cache is deprecated, use flask_cache
instead.
May 31 17:31:02 airmaster01 airflow[26096]: .format(x=modname),
ExtDeprecationWarning
May 31 17:31:02 airmaster01 airflow[26096]: [2017-05-31 17:31:02 +0000] [3176]
[INFO] Worker exiting (pid: 3176)
May 31 17:31:02 airmaster01 airflow[26096]:
/opt/airflow/production/lib/python3.4/site-packages/flask/exthook.py:71:
ExtDeprecationWarning: Importing flask.ext.cache is deprecated, use flask_cache
instead.
May 31 17:31:02 airmaster01 airflow[26096]: .format(x=modname),
ExtDeprecationWarning
May 31 17:31:02 airmaster01 airflow[26096]: [2017-05-31 17:31:02 +0000] [3510]
[INFO] Worker exiting (pid: 3510)
May 31 17:31:02 airmaster01 airflow[26096]:
/opt/airflow/production/lib/python3.4/site-packages/flask/exthook.py:71:
ExtDeprecationWarning: Importing flask.ext.cache is deprecated, use flask_cache
instead.
May 31 17:31:02 airmaster01 airflow[26096]: .format(x=modname),
ExtDeprecationWarning
May 31 17:31:02 airmaster01 airflow[26096]: [2017-05-31 17:31:02 +0000] [3319]
[INFO] Worker exiting (pid: 3319)
May 31 17:31:02 airmaster01 airflow[26096]:
/opt/airflow/production/lib/python3.4/site-packages/flask/exthook.py:71:
ExtDeprecationWarning: Importing flask.ext.cache is deprecated, use flask_cache
instead.
May 31 17:31:02 airmaster01 airflow[26096]: .format(x=modname),
ExtDeprecationWarning
May 31 17:31:02 airmaster01 airflow[26096]: [2017-05-31 17:31:02 +0000] [3710]
[INFO] Worker exiting (pid: 3710)
May 31 17:31:03 airmaster01 airflow[26096]: [2017-05-31 17:31:03 +0000] [26108]
[INFO] Shutting down: Master
May 31 17:31:03 airmaster01 airflow[26096]: [2017-05-31 17:31:03 +0000] [26108]
[INFO] Reason: Worker failed to boot.
{noformat}
Here's another example from the day before:
{noformat}
May 30 12:31:23 airmaster01 airflow[24741]: [2017-05-30 12:31:23 +0000] [24764]
[INFO] Reason: Worker failed to boot.
May 30 12:31:23 airmaster01 airflow[24741]: [2017-05-30 12:31:23 +0000] [24764]
[INFO] Shutting down: Master
May 30 12:31:22 airmaster01 airflow[24741]: [2017-05-30 12:31:22 +0000] [5521]
[INFO] Worker exiting (pid: 5521)
May 30 12:31:22 airmaster01 airflow[24741]: .format(x=modname),
ExtDeprecationWarning
May 30 12:31:22 airmaster01 airflow[24741]:
/opt/airflow/production/lib/python3.4/site-packages/flask/exthook.py:71:
ExtDeprecationWarning: Importing flask.ext.cache is deprecated, use flask_cache
instead.
May 30 12:31:22 airmaster01 airflow[24741]: [2017-05-30 12:31:22 +0000] [5879]
[INFO] Worker exiting (pid: 5879)
May 30 12:31:22 airmaster01 airflow[24741]: .format(x=modname),
ExtDeprecationWarning
May 30 12:31:22 airmaster01 airflow[24741]:
/opt/airflow/production/lib/python3.4/site-packages/flask/exthook.py:71:
ExtDeprecationWarning: Importing flask.ext.cache is deprecated, use flask_cache
instead.
May 30 12:31:22 airmaster01 airflow[24741]: [2017-05-30 12:31:22 +0000] [6036]
[INFO] Worker exiting (pid: 6036)
May 30 12:31:22 airmaster01 airflow[24741]: .format(x=modname),
ExtDeprecationWarning
May 30 12:31:22 airmaster01 airflow[24741]:
/opt/airflow/production/lib/python3.4/site-packages/flask/exthook.py:71:
ExtDeprecationWarning: Importing flask.ext.cache is deprecated, use flask_cache
instead.
May 30 12:31:22 airmaster01 airflow[24741]: [2017-05-30 12:31:22 +0000] [5699]
[INFO] Worker exiting (pid: 5699)
May 30 12:31:22 airmaster01 airflow[24741]: .format(x=modname),
ExtDeprecationWarning
May 30 12:31:22 airmaster01 airflow[24741]:
/opt/airflow/production/lib/python3.4/site-packages/flask/exthook.py:71:
ExtDeprecationWarning: Importing flask.ext.cache is deprecated, use flask_cache
instead.
May 30 12:31:21 airmaster01 airflow[24741]: [2017-05-30 12:31:21 +0000] [6554]
[INFO] Worker exiting (pid: 6554)
May 30 12:31:21 airmaster01 airflow[24741]: ImportError: No module named
'airflow.www.api'
May 30 12:31:21 airmaster01 airflow[24741]: File
"/opt/airflow/production/lib/python3.4/site-packages/airflow/www/app.py", line
131, in create_app
May 30 12:31:21 airmaster01 airflow[24741]: File
"/opt/airflow/production/lib/python3.4/site-packages/airflow/www/app.py", line
161, in cached_app
May 30 12:31:21 airmaster01 airflow[24741]: File "<string>", line 1, in <module>
May 30 12:31:21 airmaster01 airflow[24741]: app = eval(obj, mod.__dict__)
May 30 12:31:21 airmaster01 airflow[24741]: File
"/opt/airflow/production/lib/python3.4/site-packages/gunicorn/util.py", line
366, in import_app
May 30 12:31:21 airmaster01 airflow[24741]: return util.import_app(self.app_uri)
May 30 12:31:21 airmaster01 airflow[24741]: File
"/opt/airflow/production/lib/python3.4/site-packages/gunicorn/app/wsgiapp.py",
line 52, in load_wsgiapp
May 30 12:31:21 airmaster01 airflow[24741]: return self.load_wsgiapp()
May 30 12:31:21 airmaster01 airflow[24741]: File
"/opt/airflow/production/lib/python3.4/site-packages/gunicorn/app/wsgiapp.py",
line 65, in load
May 30 12:31:21 airmaster01 airflow[24741]: self.callable = self.load()
May 30 12:31:21 airmaster01 airflow[24741]: File
"/opt/airflow/production/lib/python3.4/site-packages/gunicorn/app/base.py",
line 67, in wsgi
May 30 12:31:21 airmaster01 airflow[24741]: self.wsgi = self.app.wsgi()
May 30 12:31:21 airmaster01 airflow[24741]: File
"/opt/airflow/production/lib/python3.4/site-packages/gunicorn/workers/base.py",
line 118, in init_process
May 30 12:31:21 airmaster01 airflow[24741]: worker.init_process()
May 30 12:31:21 airmaster01 airflow[24741]: File
"/opt/airflow/production/lib/python3.4/site-packages/gunicorn/arbiter.py", line
507, in spawn_worker
May 30 12:31:21 airmaster01 airflow[24741]: Traceback (most recent call last):
May 30 12:31:21 airmaster01 airflow[24741]: ImportError: No module named
'airflow.www.api'
May 30 12:31:21 airmaster01 airflow[24741]: File
"/opt/airflow/production/lib/python3.4/site-packages/airflow/www/app.py", line
131, in create_app
May 30 12:31:21 airmaster01 airflow[24741]: File
"/opt/airflow/production/lib/python3.4/site-packages/airflow/www/app.py", line
161, in cached_app
{noformat}
Here's my systemd unit file, if it's relevant:
{noformat}
[Unit]
Description=Airflow webserver production-webserver
After=network.target postgresql.service mysql.service redis.service
rabbitmq-server.service
Wants=postgresql.service mysql.service redis.service rabbitmq-server.service
[Service]
Environment=PATH=/usr/sbin:/usr/bin:/sbin:/bin:/opt/airflow/production/bin
Environment=AIRFLOW_HOME=/home/airflow/production
User=airflow
Group=airflow
Type=simple
ExecStart=/opt/airflow/production/bin/airflow webserver --pid
/run/airflow-production-airflow/webserver.pid
Restart=always
RestartSec=5s
[Install]
WantedBy=multi-user.target
{noformat}
Very confusing.
--
This message was sent by Atlassian JIRA
(v6.3.15#6346)
