Skip to content

Conversation

@Kami
Copy link
Member

@Kami Kami commented Jun 27, 2018

While testing the release, I encountered an edge case with gunicorn worker log messages.

We don't specify a special logging config which is to be used by gunicorn worker processes. This means that if an error or similar occurs in a worker process during start up, those errors are ignored in production and not logged to the corresponding service log file.

This makes a lot of config file related troubleshooting hard since error messages are simply not logged anywhere.

It looks like this issue has existed for a while and it only affects production (and not dev environment) which API services run under gunicorn process.

I personally view this as a blocker and need to merge for v2.8.0 release.

Corresponding st2-packages pull request / change is work in progress.

Example log file before this change:

ubuntu@ip-172-31-7-207:/etc/st2$ tail -F /var/log/st2/st2auth.log
2018-06-27 10:29:41,844 139935593191536 INFO __init__ [-] Connecting to database "st2" @ "127.0.0.1:27017" as user "stackstorm".
2018-06-27 10:29:41,847 139935593191536 INFO __init__ [-] Successfully connected to database "st2" @ "127.0.0.1:27017" as user "stackstorm".

As you can see, everything looks fine yet service failed to start due to the configuration error. Problem is the error is simply lost and not logged anywhere.

And after this change:

ubuntu@ip-172-31-7-207:/etc/st2$ tail -F /var/log/st2/st2auth.log
2018-06-27 11:00:36 [2341] [INFO] Listening at: http://127.0.0.1:9100 (2341)
2018-06-27 11:00:36 [2341] [INFO] Using worker: eventlet
2018-06-27 11:00:36 [2354] [INFO] Booting worker with pid: 2354
2018-06-27 11:00:36,605 139762783471888 INFO __init__ [-] Connecting to database "st2" @ "127.0.0.1:27017" as user "stackstorm".
2018-06-27 11:00:36,609 139762783471888 INFO __init__ [-] Successfully connected to database "st2" @ "127.0.0.1:27017" as user "stackstorm".
2018-06-27 11:00:37,529 139762783471888 WARNING named [-] Could not load flat_filea
2018-06-27 11:00:37,529 139762783471888 ERROR __init__ [-] Invalid authentication backend specified: flat_filea
Traceback (most recent call last):
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2auth/backends/__init__.py", line 58, in get_backend_instance
    invoke_on_load=False)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/stevedore/driver.py", line 61, in __init__
    warn_on_missing_entrypoint=warn_on_missing_entrypoint
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/stevedore/named.py", line 89, in __init__
    self._init_plugins(extensions)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/stevedore/driver.py", line 113, in _init_plugins
    (self.namespace, name))
NoMatches: No 'st2auth.backends.backend' driver found, looking for 'flat_filea'
2018-06-27 11:00:37 [2354] [ERROR] Exception in worker process
Traceback (most recent call last):
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/gunicorn/arbiter.py", line 583, in spawn_worker
    worker.init_process()
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/gunicorn/workers/geventlet.py", line 102, in init_process
    super(EventletWorker, self).init_process()
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/gunicorn/workers/base.py", line 129, in init_process
    self.load_wsgi()
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/gunicorn/workers/base.py", line 138, in load_wsgi
    self.wsgi = self.app.wsgi()
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/gunicorn/app/base.py", line 67, in wsgi
    self.callable = self.load()
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/gunicorn/app/wsgiapp.py", line 52, in load
    return self.load_wsgiapp()
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/gunicorn/app/wsgiapp.py", line 41, in load_wsgiapp
    return util.import_app(self.app_uri)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/gunicorn/util.py", line 350, in import_app
    __import__(module)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2auth/wsgi.py", line 25, in <module>
    application = app.setup_app(config)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2auth/app.py", line 64, in setup_app
    router.add_spec(spec, transforms=transforms)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2common/router.py", line 188, in add_spec
    __import__(module_name)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2auth/controllers/v1/auth.py", line 88, in <module>
    token_controller = TokenController()
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2auth/controllers/v1/auth.py", line 60, in __init__
    self.handler = HANDLER_MAPPINGS[cfg.CONF.auth.mode]()
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2auth/handlers.py", line 131, in __init__
    self._auth_backend = get_backend_instance(name=cfg.CONF.auth.backend)
  File "/opt/stackstorm/st2/local/lib/python2.7/site-packages/st2auth/backends/__init__.py", line 62, in get_backend_instance
    raise ValueError(message)
ValueError: Invalid authentication backend specified: flat_filea

gunicorn (st2api, st2auth, st2stream).

In production, those services run in a worker subprocess which is
managed by gunicorn master process. If we don't have a special
logging config file for gunicorn worker processes, some messages
which are produced by gunicorn workers are lost.

This makes debugging and other things a lot harder.
@Kami Kami added the bug label Jun 27, 2018
@Kami Kami added this to the 2.8.0 milestone Jun 27, 2018
@Kami Kami changed the title [WIP] Add gunicorn logging config for all the API services which run under gunicorn Add gunicorn logging config for all the API services which run under gunicorn Jun 27, 2018
Kami added a commit to StackStorm/st2-packages that referenced this pull request Jun 27, 2018
API based services.

This way we don't miss various log messages generated by gunicorn worker
processes.

Corresponding StackStorm/st2 change: StackStorm/st2#4206
@Kami
Copy link
Member Author

Kami commented Jun 27, 2018

Corresponding st2-packages PR - StackStorm/st2-packages#568

Copy link
Contributor

@bigmstone bigmstone left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

Copy link
Contributor

@blag blag left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM

@Kami Kami merged commit 7c2ef17 into master Jun 27, 2018
@Kami Kami deleted the add_gunicorn_loggign_configs branch June 27, 2018 16:59
cognifloyd pushed a commit that referenced this pull request Feb 16, 2025
… API based services.

This way we don't miss various log messages generated by gunicorn worker
processes.

Corresponding StackStorm/st2 change: #4206

Cherry-picked from StackStorm/st2-packages@1c1a704
cognifloyd pushed a commit that referenced this pull request Feb 17, 2025
… API based services.

This way we don't miss various log messages generated by gunicorn worker
processes.

Corresponding StackStorm/st2 change: #4206

Cherry-picked from StackStorm/st2-packages@1c1a704
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants