WsgiMiddleware - Accidentally filled _wsgi_error_buffer by azure HttpLoggingPolicy logs?

[b0lle]

Hi guys,

thank you for this #45 piece of code. I am using this to host my flask api in azure functions.
As I recently found out there seems to be an issue with the middleware in connection with KeyVault. In my opinion the HttpLoggingPolicy class in azu.core.pipeline.policies._universal uses the logging module to log the status of the http response. Unfortunately this populates the _wsgi_error_buffer in WsgiMiddleware (C:\Program Files\Microsoft\Azure Functions Core Tools\workers\python\3.8\WINDOWS\X64\azure\functions_http_wsgi.py).
When this buffer is filled with any content, then the handle_error function of the WsgiMiddleware raises an error with the content of the buffer.
I do not know why the buffer was filled. But it has to be connected because disabling the logger of the HttpLoggingPolicy (logging.getLogger('azure.core.pipeline.policies.http_logging_policy').setLevel(logging.ERROR)) solved the issue in local debugging. Unfortunately this didnt solve the issue in the deployed function.

Here are some details about the api endpoints, the access to the keyvault and the error message:

# az_func__init__.py
import azure.functions as func
from .app import create_app
from .config import app_config

connection = app_config['az_production']
app = create_app(connection)
application = app.wsgi_app


def main(req: func.HttpRequest, context: func.Context) -> func.HttpResponse:
    return func.WsgiMiddleware(application).handle(req, context)

# app.py.txt
from azure.identity import DefaultAzureCredential
from azure.keyvault.secrets import SecretClient
from flask import Flask
from flask_restful import Resource
from flask_bcrypt import Bcrypt
from flask_sqlalchemy import SQLAlchemy

app = Flask(__name__)
db = SQLAlchemy()
bcrypt = Bcrypt()

class Endpoint(Resource):
  def get(self):
    vault_url = 'myVaultUrl'
    credentials = AzureCliCredential()
    secret_client = SecretClient(vault_url, credentials)
    secret = secret_client.get_secret("db-connection-str")
    return {'secret': secret}

def create_app(connection_obj):
    app.config.from_object(connection_obj)
    api = Api(app)
    bcrypt.init_app(app)
    db.init_app(app)
    db.create_all(app=app)
    api.add_resource(Endpoint, '/')

This is the error message (to get the error message I printed the exception in _http_wsgi.py - handle_error):

[2021-02-11T09:19:05.653] error_message: [2021-02-11 10:18:58,855] INFO in _universal: Response status: 401
[2021-02-11T09:19:05.739] Executed 'Functions.AdApi' (Failed, Id=0d594991-4412-4cef-9b1e-14f1d6f27602, Duration=13984ms)
[2021-02-11T09:19:05.742] System.Private.CoreLib: Exception while executing function: Functions.AdApi. System.Private.CoreLib: Result: Failure
Exception: Exception: [2021-02-11 10:18:58,855] INFO in _universal: Response status: 401

Stack: File "C:\Program Files\Microsoft\Azure Functions Core Tools\workers\python\3.8/WINDOWS/X64\azure_functions_worker\dispatcher.py", line 343, in _handle__invocation_request
call_result = await self._loop.run_in_executor(
File "C:\MyPrograms\Anaconda3\lib\concurrent\futures\thread.py", line 57, in run
result = self.fn(*self.args, **self.kwargs)
File "C:\Program Files\Microsoft\Azure Functions Core Tools\workers\python\3.8/WINDOWS/X64\azure_functions_worker\dispatcher.py", line 480, in _run_sync_func
return func(**params)
File "C:\Azure\dea-anomalydetection-prod-func\AdApi_init.py", line 19, in

main
raise ex
File "C:\Azure\dea-anomalydetection-prod-func\AdApi_init_.py", line 16, in main
return func.WsgiMiddleware(application).handle(req, context)
File "C:\Program Files\Microsoft\Azure Functions Core Tools\workers\python\3.8/WINDOWS/X64\azure\functions_http_wsgi.py", line 161, in handle
return self._handle(req, context)
File "C:\Program Files\Microsoft\Azure Functions Core Tools\workers\python\3.8/WINDOWS/X64\azure\functions_http_wsgi.py", line 174, in _handle
self._handle_errors()
File "C:\Program Files\Microsoft\Azure Functions Core Tools\workers\python\3.8/WINDOWS/X64\azure\functions_http_wsgi.py", line 184, in _handle_errors
raise Exception(error_message)

As you can see in the exception:
The content seems to be from "INFO in _universal:" So I disabled the logging of the function:
logger = logging.getLogger('azure.core.pipeline.policies.http_logging_policy')
logger.setLevel(logging.ERROR)
which solved the issue local (VS Studio Code) but not deployed

[b0lle]

I solved this issue. It was a missconfiguration of the python logger in my application. I set the logging config to

from logging import dictConfig

dictConfig({
    'version': 1,
    'formatters': {'default': {
        'format': '[%(asctime)s] %(levelname)s in %(module)s: %(message)s',
    }},
    'handlers': {
        'wsgi': {
            'class': 'logging.StreamHandler',
            'stream': 'ext://flask.logging.wsgi_errors_stream',
            'formatter': 'default'
        }
    },
    'root': {
        'level': 'INFO',
        'handlers': ['wsgi']
    }
})

As you can see: I logged my stream data to the wsgi error handler and set the level to 'INFO'. Because of the behavior of _handle_errors (C:\Program Files\Microsoft\Azure Functions Core Tools\workers\python\3.8/WINDOWS/X64\azure\functions_http_wsgi.py", line 184, in _handle_errors) which raises an exception if the buffer is not empty, the application failed in azure functions even for info logs. I found this config in a flask tutorial somewhere.

I hope that you dont tap in this trap. But if you do I hope you find this post useful.
Cheers!