The bot created this issue to inform you that pyup.io has been set up on this repo.
Once you have closed it, the bot will open pull requests for updates as soon as they are available.

Sanic version 19.6.2
Simple API app with GET methods, JSON responses
Default setup of sanic_json_logging.

I get:
--- Logging error ---

Traceback (most recent call last):
File "/usr/local/Cellar/python/3.7.4_1/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/init.py", line 1025, in emit
msg = self.format(record)
File "/usr/local/Cellar/python/3.7.4_1/Frameworks/Python.framework/Versions/3.7/lib/python3.7/logging/init.py", line 869, in format
return fmt.format(record)
File "/Users/mark/ibis/devel/src/publicapi-server/venv/lib/python3.7/site-packages/sanic_json_logging/formatters.py", line 167, in format
ip = record.request.headers.get('X-Forwarded-For', record.request.ip)
AttributeError: 'str' object has no attribute 'headers'

on every request. Am I running an incompatible version of Sanic? Why would record.request be a string object in this case?

Thanks - I've been wanting JSON access logs for AWS and Elasticsearch as well, appreciate you building a library for this!

Using this in a microservice architecture, the User-Agent header is not always sent. The JSONReqFormatter has a hard coded expectation that User-Agent is in the request headers. So if User-Agent isn't passed it throws.

USed your package for one of the projects and this error came up

File /usr/local/lib/python3.6/site-packages/sanic_json_logging/init.py, line 48, in log_json_pre

current_task.context['req_id'] = req_id

What can i do to fix it?

TypeError: 'Context' object does not support item assignment while handling path

Do

request['req_id'] = str(uuid.uuid4())
request['req_start'] = time.perf_counter()

And the equiv in response middleware

Here's a small example of my error, the most obvious solution is to use hasattr or .get, but I have not idea what going on underhood of this lib.

uvicorn server:app --host 0.0.0.0 --port 5000 --loop uvloop --workers 2 --reload                                                    mkryvy@MacBook-Pro
INFO:     Uvicorn running on http://0.0.0.0:5000 (Press CTRL+C to quit)
INFO:     Started reloader process [93864] using statreload
INFO:     Started server process [93866]
{"timestamp": "2020-07-29T21:53:18.149500Z", "level": "INFO", "message": "Started server process [93866]", "type": "log", "logger": "uvicorn.error", "worker": 93866, "filename": "main.py", "lineno": 405}
INFO:     Waiting for application startup.
{"timestamp": "2020-07-29T21:53:18.149989Z", "level": "INFO", "message": "Waiting for application startup.", "type": "log", "logger": "uvicorn.error", "worker": 93866, "filename": "on.py", "lineno": 22}
INFO:     Application startup complete.
{"timestamp": "2020-07-29T21:53:18.150262Z", "level": "INFO", "message": "Application startup complete.", "type": "log", "logger": "uvicorn.error", "worker": 93866, "filename": "on.py", "lineno": 34}
{"timestamp": "2020-07-29T21:53:22.634855Z", "level": "ERROR", "message": "Exception occurred in one of response middleware handlers", "type": "exception", "logger": "sanic.error", "worker": 93866, "filename": "app.py", "lineno": 984, "traceback": "Traceback (most recent call last):<br>  File \"/Users/mkryvy/.local/share/virtualenvs/echo_service-W3-tao-R/lib/python3.8/site-packages/sanic/app.py\", line 976, in handle_request<br>    response = await self._run_response_middleware(<br>  File \"/Users/mkryvy/.local/share/virtualenvs/echo_service-W3-tao-R/lib/python3.8/site-packages/sanic/app.py\", line 1281, in _run_response_middleware<br>    _response = await _response<br>  File \"/Users/mkryvy/.local/share/virtualenvs/echo_service-W3-tao-R/lib/python3.8/site-packages/sanic_json_logging/__init__.py\", line 79, in log_json_post<br>    if 'req_id' in request:<br>TypeError: argument of type 'Request' is not iterable", "req_id": "e564a655-0696-485d-b75b-a3e2e4e1155b"}
INFO:     127.0.0.1:53246 - "GET /ping HTTP/1.1" 200 OK

(REMARK: Looks like you are doing the check of attr not in a super-efficient way)

 78                 # Pre middleware doesnt run on exception
 79                 import pdb; pdb.set_trace()
 80  ->             if 'req_id' in request:
 81                     req_id = request.ctx.req_id
 82                     time_taken = time.perf_counter() - request.ctx.req_start
 83                 else:
 84                     req_id = str(uuid.uuid4())
 85                     time_taken = -1

From documentation of this method, it's hard to understand what request type is

(Pdb) type(request)
<class 'sanic.request.Request'>
(Pdb) dir(request)
['__class__', '__delattr__', '__dir__', '__doc__', '__eq__', '__format__', '__ge__', '__getattribute__', '__gt__', '__hash__', '__init__', '__init_subclass__', '__le__', '__lt__', '__module__', '__ne__', '__new__', '__reduce__', '__reduce_ex__', '__repr__', '__setattr__', '__sizeof__', '__slots__', '__str__', '__subclasshook__', '__weakref__', '_cookies', '_ip', '_parsed_url', '_port', '_remote_addr', '_socket', 'app', 'args', 'body', 'body_finish', 'body_init', 'body_push', 'conn_info', 'content_type', 'cookies', 'ctx', 'endpoint', 'files', 'form', 'forwarded', 'get_args', 'get_query_args', 'headers', 'host', 'ip', 'json', 'load_json', 'match_info', 'method', 'parsed_args', 'parsed_files', 'parsed_form', 'parsed_forwarded', 'parsed_json', 'parsed_not_grouped_args', 'path', 'port', 'query_args', 'query_string', 'raw_url', 'receive_body', 'remote_addr', 'scheme', 'server_name', 'server_path', 'server_port', 'socket', 'stream', 'token', 'transport', 'uri_template', 'url', 'url_for', 'version']
(Pdb) 'a' in request
*** TypeError: argument of type 'Request' is not iterable
(Pdb) request.ctx
namespace(req_id='f64b0384-2459-4178-84d1-db2d0737f38a', req_start=7.191887143)
(Pdb)

My env:
Python 3.8

-i https://pypi.org/simple
aiofiles==0.5.0
certifi==2020.6.20
chardet==3.0.4
click==7.1.2; python_version >= '2.7' and python_version not in '3.0, 3.1, 3.2, 3.3, 3.4'
h11==0.9.0
h2==3.2.0
hpack==3.0.0
hstspreload==2020.7.29; python_version >= '3.6'
httptools==0.1.1; sys_platform != 'win32' and sys_platform != 'cygwin' and platform_python_implementation != 'PyPy'
httpx==0.11.1; python_version >= '3.6'
hyperframe==5.2.0
idna==2.10; python_version >= '2.7' and python_version not in '3.0, 3.1, 3.2, 3.3'
multidict==4.7.6; python_version >= '3.5'
rfc3986==1.4.0
sanic-json-logging==3.2.0
sanic==20.6.3
sniffio==1.1.0; python_version >= '3.5'
ujson==3.0.0
urllib3==1.25.10; python_version >= '2.7' and python_version not in '3.0, 3.1, 3.2, 3.3, 3.4' and python_version < '4'
uvicorn==0.11.7
uvloop==0.14.0
websockets==8.1; python_full_version >= '3.6.1'

Hi there!

I'm wondering if there's a way to grab the request ID within the context of a request handler. This would be great for being able to forward the request ID, as I make requests to other services, so that I can follow the entire request trace path.

I tried looking through the req object that gets handed through to a handler, but I couldn't find the req_id anywhere.

Thanks!

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?

You can also notice the error on the auto closed pull requests:
"Scheduled weekly dependency update for week 20-26" (an example: https://travis-ci.com/github/terrycain/sanic-json-logging/builds/174516490)

`
tests/test_basic.py::test_json_access_logging_no_ua Exception occurred while handling uri: 'http://127.0.0.1:53599/test_get'

Traceback (most recent call last):

File "/home/travis/virtualenv/python3.6.7/lib/python3.6/site-packages/sanic/app.py", line 907, in handle_request

request, request_name=name

File "/home/travis/virtualenv/python3.6.7/lib/python3.6/site-packages/sanic/app.py", line 1265, in _run_request_middleware

response = await response

File "/home/travis/build/terrycain/sanic-json-logging/sanic_json_logging/init.py", line 41, in log_json_pre

request['req_id'] = req_id

TypeError: 'Request' object does not support item assignment
`

Using the code right from the examples/simple.py:

import logging

import sanic.response
import sanic.request

from sanic_json_logging import setup_json_logging, NoAccessLogSanic


app = NoAccessLogSanic('app1')
setup_json_logging(app)

logger = logging.getLogger('root')


async def log():
    logger.info('some informational message')


@app.route("/endpoint1", methods=['GET'])
async def endpoint1(request: sanic.request.Request) -> sanic.response.BaseHTTPResponse:
    await log()
    return sanic.response.text('')

app.run()

I have the following project (using poetry):

[tool.poetry]
name = "nal"
version = "0.1.0"
description = ""
authors = ["Aaron <[email protected]>"]

[tool.poetry.dependencies]
python = "^3.7"
sanic = "^19.6"
sanic_json_logging = "^1.3"

[tool.poetry.dev-dependencies]
pytest = "^3.0"

[build-system]
requires = ["poetry>=0.12"]
build-backend = "poetry.masonry.api"

When I run the project, everything starts up just fine:

⇒  poetry run python -m nal.main
[2019-07-09 08:01:30 -0600] [20986] [INFO] Goin' Fast @ http://127.0.0.1:8000
{"timestamp": "2019-07-09T14:01:30.924731Z", "level": "INFO", "message": "Goin' Fast @ http://127.0.0.1:8000", "type": "log", "logger": "sanic.root", "filename": "app.py", "lineno": 1383}
[2019-07-09 08:01:30 -0600] [20986] [INFO] Starting worker [20986]
{"timestamp": "2019-07-09T14:01:30.926515Z", "level": "INFO", "message": "Starting worker [20986]", "type": "log", "logger": "sanic.root", "filename": "server.py", "lineno": 802}

But when I send a request (using httpie):

⇒  http :8000/endpoint1
HTTP/1.1 200 OK
Connection: keep-alive
Content-Length: 0
Content-Type: text/plain; charset=utf-8
Keep-Alive: 5

I still get the access logs:

{
  "timestamp": "2019-07-09T14:02:23.807338Z",
  "level": "INFO",
  "message": "some informational message",
  "type": "log",
  "logger": "root",
  "filename": "main.py",
  "lineno": 16,
  "req_id": "4efb221f-a142-4604-b593-d8e72a69faa6"
}
{
  "timestamp": "2019-07-09T14:02:23.807491Z",
  "level": "INFO",
  "method": "GET",
  "path": "/endpoint1",
  "remote": "127.0.0.1:51702",
  "user_agent": "HTTPie/1.0.2",
  "host": "localhost:8000",
  "response_time": 0,
  "req_id": "28f6ae3d-0e31-4573-819f-4cb852939ee8",
  "logger": "sanic.access",
  "status_code": 200,
  "length": 0,
  "type": "access"
}

I would expect that all the access logs are disabled since I'm using NoAccessLogSanic and all.