disable_json_access_log=False doesn't work. AttributeError: 'str' object has no attribute 'headers'

[idavydiak]

Hi. Maybe I'm doing something wrong, but it doesn't want to work for for me.

Problem

Here is what I get when I use disable_json_access_log=False setup_json_logging(app, disable_json_access_log=False, configure_task_local_storage=False)

{"timestamp": "2021-12-07T13:42:05.399182Z", "level": "INFO", "method": "GET", "type": "access", "path": "/test", "remote": "127.0.0.1:44290", "user_agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:94.0) Gecko/20100101 Firefox/94.0", "host": "localhost:8000", "response_time": 0.0, "req_id": "50aea029-7e0b-4c77-8eba-d3066077012f", "logger": "sanic.access", "worker": 18340, "status_code": 200, "length": 4}
--- Logging error ---
Traceback (most recent call last):
  File "/home/dave/.pyenv/versions/3.9.0/lib/python3.9/logging/__init__.py", line 1079, in emit
    msg = self.format(record)
  File "/home/dave/.pyenv/versions/3.9.0/lib/python3.9/logging/__init__.py", line 923, in format
    return fmt.format(record)
  File "/home/dave/.local/share/virtualenvs/sanic-f0iRZCxx/lib/python3.9/site-packages/sanic_json_logging/formatters.py", line 174, in format
    ip = record.request.headers.get("X-Forwarded-For", record.request.ip)
AttributeError: 'str' object has no attribute 'headers'
Call stack:
  File "/home/dave/work/projects/test/sanic/app.py", line 12, in <module>
    app.run(
  File "/home/dave/.local/share/virtualenvs/sanic-f0iRZCxx/lib/python3.9/site-packages/sanic/app.py", line 1051, in run
    serve_single(server_settings)
  File "/home/dave/.local/share/virtualenvs/sanic-f0iRZCxx/lib/python3.9/site-packages/sanic/server/runners.py", line 199, in serve_single
    serve(**server_settings)
  File "/home/dave/.local/share/virtualenvs/sanic-f0iRZCxx/lib/python3.9/site-packages/sanic/server/runners.py", line 150, in serve
    loop.run_forever()
  File "connection_task", line 15, in connection_task
    from sanic.http import Http, Stage
  File "/home/dave/.local/share/virtualenvs/sanic-f0iRZCxx/lib/python3.9/site-packages/sanic/http.py", line 146, in http1
    await self.protocol.request_handler(self.request)
  File "handle_request", line 100, in handle_request
    "_future_routes",
  File "/home/dave/.local/share/virtualenvs/sanic-f0iRZCxx/lib/python3.9/site-packages/sanic/response.py", line 122, in send
    await self.stream.send(data, end_stream=end_stream)
  File "http1_response_header", line 68, in http1_response_header
    HEADER_CEILING = 16_384
  File "/home/dave/.local/share/virtualenvs/sanic-f0iRZCxx/lib/python3.9/site-packages/sanic/http.py", line 477, in log_response
    access_logger.info("", extra=extra)
Message: ''
Arguments: ()

How to reproduce

cat Pipfile

[[source]]
url = "https://pypi.org/simple"
verify_ssl = true
name = "pypi"

[packages]
sanic = "==21.9.3"
sanic-json-logging = "==4.1.2"

[requires]
python_version = "3.9"(sanic)

cat app.py

from sanic_json_logging import setup_json_logging
from sanic import Sanic, response

app = Sanic(name="test")
setup_json_logging(app, disable_json_access_log=False, configure_task_local_storage=False)

@app.route("/test")
def health(request):
    return response.text("test")

if __name__ == "__main__":
    app.run(
        host="0.0.0.0",
        port=8000,
        debug=True,
        auto_reload=True,
        access_log=True,
    )

pipenv shell
pipenv install
python app.py

In another terminal curl localhost:8000/test or browser localhost:8000/test

why I use disable_json_access_log=False

When I use disable_json_access_log=False then I have logs in format I need, but there is an error

When I use disable_json_access_log=True it doesn't look like I want

---

The goal to have all logs in json format (including access logs) Could you help me to fix it?

[timotta]

Same behaviour here, using versions:

sanic==22.6.1
sanic-json-logging==4.1.2

[timotta]

I have created a workaround:

from sanic_json_logging.formatters import JSONReqFormatter

original_format = JSONReqFormatter.format

def fixed(*args, **kwargs):
    try:
        return original_format(*args, **kwargs)
    except:
        return ""

JSONReqFormatter.format = fixed

app = Sanic("myapp")
setup_json_logging(app, disable_json_access_log=False)

Now, instead of a error, it logs an empty line

[timotta]

An updated workaround:

original_format = JSONReqFormatter.format

def fixed(original_self, record, *args, **kwargs):
    if hasattr(record, "request") and hasattr(record.request, "headers"):
        return original_format(original_self, record, *args, **kwargs)
    return ""

JSONReqFormatter.format = fixed

app = Sanic("myapp")
setup_json_logging(app, disable_json_access_log=False)

With the same "log empty line" problem

[timotta]

Found that the problem is solved if access_log is False on app.run:

    app.run(
        ...
        access_log=False,
    )

The access log still happens because of the disable_json_access_log=False