Flask Extension Gunicorn GLogging Error With Access Logs

[disfluxly]

Describe your environment
Using Python 3.6, with a basic flask application with gunicorn.

Python Libs:

Flask==1.1.1
gunicorn==20.0.4
opentelemetry-sdk==0.3a0
opentelemetry-ext-flask==0.3a0

Reproducible Structure

app/
- __init__.py
- api.py
- wsgi.py
config/
- gunicorn_config.py
-log_config.py

app/__init__.py

from app import api
from flask import Flask
from opentelemetry.ext.flask import instrument_app

def create_app():
	app = Flask(__name__)

	instrument_app(app)
	app.register_blueprint(api.blueprint)

	return app

app/api.py

from flask import Blueprint

blueprint = Blueprint('api', __name__)

@blueprint.route('/')
def index():
	return {'status': 'success'}

app/wsgi.py

from app import create_app


app = create_app()

config/gunicorn_config.py

import logging.config
import os

from config.log_config import LOGGING, LOG_LEVEL

workers = os.environ.get('GUNICORN_WORKERS', 4)
bind = "{}:{}".format(os.environ.get('GUNICORN_HOST', '0.0.0.0'), os.environ.get('GUNICORN_PORT', 8000))

loglevel = LOG_LEVEL
logconfig_dict = LOGGING

timeout = os.environ.get('GUNICORN_WORKER_TIMEOUT', 60)

config/log_config.py

import os

LOG_LEVEL = os.environ.get('LOG_LEVEL', 'DEBUG')

LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
}

Steps to reproduce
At the root of the above, run gunicorn -c config/gunicorn_config.py app.wsgi:app

Hit the base endpoint curl http://localhost:8000

Get the following error thrown by gunicorn:

Traceback (most recent call last):
  File "/Users/disflux/miniconda3/envs/flasktest/lib/python3.6/site-packages/gunicorn/workers/sync.py", line 184, in handle_request
    self.log.access(resp, req, environ, request_time)
  File "/Users/disflux/miniconda3/envs/flasktest/lib/python3.6/site-packages/gunicorn/glogging.py", line 341, in access
    request_time))
  File "/Users/disflux/miniconda3/envs/flasktest/lib/python3.6/site-packages/gunicorn/glogging.py", line 323, in atoms
    atoms.update({"{%s}e" % k.lower(): v for k, v in environ_variables})
  File "/Users/disflux/miniconda3/envs/flasktest/lib/python3.6/site-packages/gunicorn/glogging.py", line 323, in <dictcomp>
    atoms.update({"{%s}e" % k.lower(): v for k, v in environ_variables})
AttributeError: 'object' object has no attribute 'lower'

It appears that the error is caused by adding Objects as keys to the environment, which is done by OpenTelemetry here:
https://github.com/open-telemetry/opentelemetry-python/blob/master/ext/opentelemetry-ext-flask/src/opentelemetry/ext/flask/__init__.py#L15-L17

This ends up triggering the error in Gunicorn Glogging:
https://github.com/benoitc/gunicorn/blob/master/gunicorn/glogging.py#L326

Note: Gunicorn only executes this if certain logging configuration is enabled (access logs), as indicated by the if statement here:
https://github.com/benoitc/gunicorn/blob/master/gunicorn/glogging.py#L335-L338

What is the expected behavior?
No errors :)

I'd expect that we wouldn't be storing objects as a key in the environment.

[Oberon00]

This seems to be a bug in gunicorn, the WSGI spec does not demand anywhere that the environ may only contain string keys and even explicitly says:

the application is allowed to modify the dictionary in any way it desires

(https://www.python.org/dev/peps/pep-3333/#specification-details)

Arguably, using non-string objects as keys is rather unusual though so we should still consider working around this gunicorn bug.

EDIT: I reported this upstream: benoitc/gunicorn#2234