Log gunicorn errors to API service log file

[Kami]

This pull request fixes a bug / race I found while testing the recent package changes.

Right now if an error occurs in a gunicorn powered API service before API service logging if fully initialized, this error will be simply ignored.

This is of course problematic, because those errors usually mean fatal configuration errors which makes troubleshooting hard (no error is logged, yet service doesn't start or similar).

This pull request fixes that by passing --error-logfile argument to the gunicorn process (http://docs.gunicorn.org/en/stable/settings.html#errorlog). This way we log gunicorn errors to the existing API service log file.

Initially I thought we may need to use a different log file, but I tested it and re-using existing API log file seems to work fine.

Before (there was nothing in the log file yet the service crashed and failed to start):

...
2019-04-08 08:24:32,651 140122678001440 AUDIT (unknown file) [-] RunnerType updated. RunnerType RunnerTypeDB(description="A runner for emitting an announcement event on the stream.", enabled=True, id=5cab02aef0ff1832abc82140, name="announcement", output_key=None, output_schema={}, query_module=None, runner_module="announcement_runner", runner_package="announcement_runner", runner_parameters={'experimental': {'default': False, 'description': 'Flag to indicate acknowledgment of using experimental runner', 'required': True, 'type': 'boolean'}, 'route': {'default': 'general', 'description': 'The routing_key used to route the message to consumers. Might be a list of words, delimited by dots.', 'maxLength': 255, 'minLength': 1, 'type': 'string'}}, uid="runner_type:announcement") (runner_type_db={'description': 'A runner for emitting an announcement event on the stream.', 'enabled': True, 'id': '5cab02aef0ff1832abc82140', 'name': 'announcement', 'output_key': None, 'output_schema': {}, 'query_module': None, 'runner_module': 'announcement_runner', 'runner_package': 'announcement_runner', 'runner_parameters': {'experimental': {'default': False, 'description': 'Flag to indicate acknowledgment of using experimental runner', 'required': True, 'type': 'boolean'}, 'route': {'default': 'general', 'description': 'The routing_key used to route the message to consumers. Might be a list of words, delimited by dots.', 'maxLength': 255, 'minLength': 1, 'type': 'string'}}, 'uid': 'runner_type:announcement'})
2019-04-08 08:24:32,666 140122678001440 AUDIT (unknown file) [-] RunnerType updated. RunnerType RunnerTypeDB(description="A runner for launching linear action chains.", enabled=True, id=5cab02aef0ff1832abc82141, name="action-chain", output_key="published", output_schema={'published': {'type': 'object'}, 'tasks': {'type': 'array'}}, query_module=None, runner_module="action_chain_runner", runner_package="action_chain_runner", runner_parameters={'display_published': {'default': True, 'description': 'Intermediate published variables will be stored and displayed.', 'type': 'boolean'}, 'skip_notify': {'default': [], 'description': 'List of tasks to skip notifications for.', 'type': 'array'}}, uid="runner_type:action-chain") (runner_type_db={'description': 'A runner for launching linear action chains.', 'enabled': True, 'id': '5cab02aef0ff1832abc82141', 'name': 'action-chain', 'output_key': 'published', 'output_schema': {'published': {'type': 'object'}, 'tasks': {'type': 'array'}}, 'query_module': None, 'runner_module': 'action_chain_runner', 'runner_package': 'action_chain_runner', 'runner_parameters': {'display_published': {'default': True, 'description': 'Intermediate published variables will be stored and displayed.', 'type': 'boolean'}, 'skip_notify': {'default': [], 'description': 'List of tasks to skip notifications for.', 'type': 'array'}}, 'uid': 'runner_type:action-chain'})

After:

2019-04-08 08:25:30,708 140193663345320 AUDIT (unknown file) [-] RunnerType updated. RunnerType RunnerTypeDB(description="A runner for emitting an announcement event on the stream.", enabled=True, id=5cab02aef0ff1832abc82140, name="announcement", output_key=None, output_schema={}, query_module=None, runner_module="announcement_runner", runner_package="announcement_runner", runner_parameters={'experimental': {'default': False, 'description': 'Flag to indicate acknowledgment of using experimental runner', 'required': True, 'type': 'boolean'}, 'route': {'default': 'general', 'description': 'The routing_key used to route the message to consumers. Might be a list of words, delimited by dots.', 'maxLength': 255, 'minLength': 1, 'type': 'string'}}, uid="runner_type:announcement") (runner_type_db={'description': 'A runner for emitting an announcement event on the stream.', 'enabled': True, 'id': '5cab02aef0ff1832abc82140', 'name': 'announcement', 'output_key': None, 'output_schema': {}, 'query_module': None, 'runner_module': 'announcement_runner', 'runner_package': 'announcement_runner', 'runner_parameters': {'experimental': {'default': False, 'description': 'Flag to indicate acknowledgment of using experimental runner', 'required': True, 'type': 'boolean'}, 'route': {'default': 'general', 'description': 'The routing_key used to route the message to consumers. Might be a list of words, delimited by dots.', 'maxLength': 255, 'minLength': 1, 'type': 'string'}}, 'uid': 'runner_type:announcement'})
2019-04-08 08:25:30,724 140193663345320 AUDIT (unknown file) [-] RunnerType updated. RunnerType RunnerTypeDB(description="A runner for launching linear action chains.", enabled=True, id=5cab02aef0ff1832abc82141, name="action-chain", output_key="published", output_schema={'published': {'type': 'object'}, 'tasks': {'type': 'array'}}, query_module=None, runner_module="action_chain_runner", runner_package="action_chain_runner", runner_parameters={'display_published': {'default': True, 'description': 'Intermediate published variables will be stored and displayed.', 'type': 'boolean'}, 'skip_notify': {'default': [], 'description': 'List of tasks to skip notifications for.', 'type': 'array'}}, uid="runner_type:action-chain") (runner_type_db={'description': 'A runner for launching linear action chains.', 'enabled': True, 'id': '5cab02aef0ff1832abc82141', 'name': 'action-chain', 'output_key': 'published', 'output_schema': {'published': {'type': 'object'}, 'tasks': {'type': 'array'}}, 'query_module': None, 'runner_module': 'action_chain_runner', 'runner_package': 'action_chain_runner', 'runner_parameters': {'display_published': {'default': True, 'description': 'Intermediate published variables will be stored and displayed.', 'type': 'boolean'}, 'skip_notify': {'default': [], 'description': 'List of tasks to skip notifications for.', 'type': 'array'}}, 'uid': 'runner_type:action-chain'})
[2019-04-08 08:25:30 +0000] [23959] [ERROR] Exception in worker process
Traceback (most recent call last):
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/gunicorn/arbiter.py", line 583, in spawn_worker
    worker.init_process()
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/gunicorn/workers/geventlet.py", line 102, in init_process
    super(EventletWorker, self).init_process()
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/gunicorn/workers/base.py", line 129, in init_process
    self.load_wsgi()
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/gunicorn/workers/base.py", line 138, in load_wsgi
    self.wsgi = self.app.wsgi()
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/gunicorn/app/base.py", line 67, in wsgi
    self.callable = self.load()
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/gunicorn/app/wsgiapp.py", line 52, in load
    return self.load_wsgiapp()
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/gunicorn/app/wsgiapp.py", line 41, in load_wsgiapp
    return util.import_app(self.app_uri)
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/gunicorn/util.py", line 350, in import_app
    __import__(module)
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/st2api/wsgi.py", line 25, in <module>
    application = app.setup_app(config)
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/st2api/app.py", line 68, in setup_app
    validate_rbac_is_correctly_configured()
  File "/opt/stackstorm/st2/lib/python3.6/site-packages/st2api/validation.py", line 44, in validate_rbac_is_correctly_configured
    raise ValueError(msg)
ValueError: You have enabled RBAC, but RBAC backend is not set to "enterprise". For RBAC to work, you need to install "bwc-enterprise" package, set "rbac.backend" config option to "enterprise" and restart st2api service.
[2019-04-08 08:25:30 +0000] [23959] [INFO] Worker exiting (pid: 23959)
[2019-04-08 08:25:30 +0000] [23938] [INFO] Shutting down: Master
[2019-04-08 08:25:30 +0000] [23938] [INFO] Reason: Worker failed to boot.

[2019-04-08 08:25:36 +0000] [24018] [INFO] Starting gunicorn 19.9.0
[2019-04-08 08:25:36 +0000] [24018] [INFO] Listening at: http://127.0.0.1:9101 (24018)
[2019-04-08 08:25:36 +0000] [24018] [INFO] Using worker: eventlet
[2019-04-08 08:25:36 +0000] [24043] [INFO] Booting worker with pid: 24043

[blag]

It would be nice if this had tests, but LGTM even without them. I don't expect the gunicorn flags to churn much.

[Kami]

I agree, I will look into tests this week.