Uploaded image for project: 'Apache Airflow'
  1. Apache Airflow
  2. AIRFLOW-1259

Spontaneous death of gunicorn workers due to import error

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Open
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 1.8.1
    • Fix Version/s: None
    • Component/s: database
    • Labels:

      Description

      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:

      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.
      

      Here's another example from the day before:

      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
      

      Here's my systemd unit file, if it's relevant:

      [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
      

      Very confusing.

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                Unassigned
                Reporter:
                forsberg Erik Forsberg
              • Votes:
                2 Vote for this issue
                Watchers:
                4 Start watching this issue

                Dates

                • Created:
                  Updated: