Add example of logging config file

[matrixise]

In the doc, there is the description of --log-config <path> for the configuration of a config file. I think an example of config file could be really awesome for the new comers.

[!Important]

• We're using Polar.sh so you can upvote and help fund this issue.
• We receive the funding once the issue is completed & confirmed by you.
• Thank you in advance for helping prioritize & fund our backlog.

[tomchristie]

Agreed yup. As a starting point we could just link to this: https://docs.python.org/3/library/logging.config.html#logging-config-fileformat

Tho ideally a proper example that's relevant to uvicorn would be ace.

Any pull requests here would be most welcome (even if it's just linkig to the Python docs to start with.)

[ex-nerd]

It would also be worth mentioning that by enabling the custom log, other uvicorn loggers are likely to become disabled. See #511

[NightMachinery]

I found this helpful:

import sys
import uvicorn
from uvicorn.config import LOGGING_CONFIG

def main():
    root_path = ''
    if len(sys.argv) >= 2:
        root_path = sys.argv[1]
    ##
    # %(name)s : uvicorn, uvicorn.error, ... . Not insightful at all.
    LOGGING_CONFIG["formatters"]["access"]["fmt"] = '%(asctime)s %(levelprefix)s %(client_addr)s - "%(request_line)s" %(status_code)s'
    LOGGING_CONFIG["formatters"]["default"]["fmt"] = "%(asctime)s %(levelprefix)s %(message)s"

    date_fmt = "%Y-%m-%d %H:%M:%S"
    LOGGING_CONFIG["formatters"]["default"]["datefmt"] = date_fmt
    LOGGING_CONFIG["formatters"]["access"]["datefmt"] = date_fmt
    ##
    uvicorn.run("brishgarden.garden:app", host="127.0.0.1", port=7230, log_level="info", proxy_headers=True, root_path=root_path)

[ievgennaida]

I will appreciate good example for the uvicorn logging with other libs. Currently I am configuring root logger and setting formatter to all the available

   for logger_name in logging.root.manager.loggerDict.keys():
        override_logger = logging.getLogger(logger_name)
        for handler in override_logger.handlers:
            handler.setFormatter(formatter)

[ievgennaida]

Do you use any config file by default when nothing is passed to the --log-config?

[mattiacampana]

I would like to specify the log configuration in a separate file and use it with the option --log-config. In particular, I would like to add the timestamp to the logs. I've found this

LOGGING_CONFIG["formatters"]["default"]["fmt"] = "%(asctime)s [%(name)s] %(levelprefix)s %(message)s"

but I don't know how to specify it in a config file.

[euri10]

I would like to specify the log configuration in a separate file and use it with the option --log-config. In particular, I would like to add the timestamp to the logs. I've found this

LOGGING_CONFIG["formatters"]["default"]["fmt"] = "%(asctime)s [%(name)s] %(levelprefix)s %(message)s"

but I don't know how to specify it in a config file.

assuming you're passing a yaml file, something like the below should print the timestamp, this is well explained in python docs here

version: 1
formatters:
  simple:
    format: '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
handlers:
  console:
    class: logging.StreamHandler
    level: DEBUG
    formatter: simple
    stream: ext://sys.stdout
loggers:
  simpleExample:
    level: DEBUG
    handlers: [console]
    propagate: no
root:
  level: DEBUG
  handlers: [console]

[mattiacampana]

Thank you @euri10. However, I got the following error when I try to run uvicorn with --log-config option: configparser.MissingSectionHeaderError: File contains no section headers. What kind of header should I use? Should I specify an additional option to use the .yaml config file?

Sorry, but this is my very first time with this problem and I'm a bit confused...

[euri10]

dunno what you're doing, seems like you're using a ini logging format ?

you can use --log-config with :

1. yaml or json, it will be detected according to the file extension (.yaml or .yml and .json) see here :

https://github.com/encode/uvicorn/blob/bdab488ebfa84933d4b5f45c164366321d280015/uvicorn/config.py#L240-L247

2. a old ini file format, with any other file extentions, I think you ended up here, in that case it means your ini format is incorrect and I can just point you at the docs I already linked above for writing the correct format

3. a dictionary, more to be use when running programmatically

for reference with the above simplest log.yaml and running ❯ uvicorn app:app --log-config=log.yaml you get the timestamp as asked:

2020-11-18 13:54:22,907 - uvicorn.access - INFO - 127.0.0.1:53346 - "GET / HTTP/1.1" 200
2020-11-18 13:54:23,238 - uvicorn.access - INFO - 127.0.0.1:53346 - "GET / HTTP/1.1" 200
2020-11-18 13:54:23,804 - uvicorn.access - INFO - 127.0.0.1:53346 - "GET / HTTP/1.1" 200

[nicoinn]

I also had @mattiacampana 's issue --- fixed by updating to the latest uvicorn with pip install -U uvicorn

[romkazor]

How add custom header to access log? User-Agent or Authorization, etc.? Thanks.

[luca-drf]

Not sure if this is helpful but I had the same issue as @mattiacampana and I solved by defining a new formatter, a new handler and configuring the root logger to use them. Then setting disable_existing_loggers: False allows existing uvicorn loggers to inherit the custom configuration without having to modify them at "runtime":

version: 1
disable_existing_loggers: False
formatters:
  timestamped:
    format: '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
handlers:
  console:
    class: logging.StreamHandler
    level: INFO
    formatter: timestamped
    stream: ext://sys.stdout
root:
  level: INFO
  handlers: [console]

[luca-drf]

Not sure if this is helpful but I had the same issue as @mattiacampana and I solved by defining a new formatter, a new handler and configuring the root logger to use them. Then setting disable_existing_loggers: False allows existing uvicorn loggers to inherit the custom configuration without having to modify them at "runtime":

version: 1
disable_existing_loggers: False
formatters:
  timestamped:
    format: '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
handlers:
  console:
    class: logging.StreamHandler
    level: INFO
    formatter: timestamped
    stream: ext://sys.stdout
root:
  level: INFO
  handlers: [console]

Another solution I found, in order to use uvicorn formatter classes (and not lose colors, for instance), is to re-define loggers like this:

version: 1
disable_existing_loggers: False
formatters:
  default:
    (): 'uvicorn.logging.DefaultFormatter'
    fmt: '%(asctime)s %(levelprefix)-9s %(name)s -: %(message)s'
  access:
    (): 'uvicorn.logging.AccessFormatter'
    fmt: '%(asctime)s %(levelprefix)-9s %(name)s -: %(client_addr)s - "%(request_line)s" %(status_code)s'
handlers:
  default:
    class: logging.StreamHandler
    formatter: default
    stream: ext://sys.stderr
  access:
    class: logging.StreamHandler
    formatter: access
    stream: ext://sys.stdout
loggers:
  uvicorn:
    level: INFO
    handlers:
      - default
  uvicorn.error:
    level: INFO
  uvicorn.access:
    level: INFO
    propagate: False
    handlers:
      - access

[houmie]

I'm experiecing the same problem as @mattiacampana and @nicoinn. I already upgraded uvicorn to the latest version: uvicorn==0.13.4

Error:

May 31 10:10:40 api-stag gunicorn[21353]: Traceback (most recent call last):
May 31 10:10:40 api-stag gunicorn[21353]:   File "/home/admin/.pyenv/versions/venv/bin/gunicorn", line 8, in <module>
May 31 10:10:40 api-stag gunicorn[21353]:     sys.exit(run())
May 31 10:10:40 api-stag gunicorn[21353]:   File "/home/admin/.pyenv/versions/3.9.5/envs/venv/lib/python3.9/site-packages/gunicorn/app/wsgiapp.py", line 67, in run
May 31 10:10:40 api-stag gunicorn[21353]:     WSGIApplication("%(prog)s [OPTIONS] [APP_MODULE]").run()
May 31 10:10:40 api-stag gunicorn[21353]:   File "/home/admin/.pyenv/versions/3.9.5/envs/venv/lib/python3.9/site-packages/gunicorn/app/base.py", line 231, in run
May 31 10:10:40 api-stag gunicorn[21353]:     super().run()
May 31 10:10:40 api-stag gunicorn[21353]:   File "/home/admin/.pyenv/versions/3.9.5/envs/venv/lib/python3.9/site-packages/gunicorn/app/base.py", line 72, in run
May 31 10:10:40 api-stag gunicorn[21353]:     Arbiter(self).run()
May 31 10:10:40 api-stag gunicorn[21353]:   File "/home/admin/.pyenv/versions/3.9.5/envs/venv/lib/python3.9/site-packages/gunicorn/arbiter.py", line 58, in __init__
May 31 10:10:40 api-stag gunicorn[21353]:     self.setup(app)
May 31 10:10:40 api-stag gunicorn[21353]:   File "/home/admin/.pyenv/versions/3.9.5/envs/venv/lib/python3.9/site-packages/gunicorn/arbiter.py", line 93, in setup
May 31 10:10:40 api-stag gunicorn[21353]:     self.log = self.cfg.logger_class(app.cfg)
May 31 10:10:40 api-stag gunicorn[21353]:   File "/home/admin/.pyenv/versions/3.9.5/envs/venv/lib/python3.9/site-packages/gunicorn/glogging.py", line 195, in __init__
May 31 10:10:40 api-stag gunicorn[21353]:     self.setup(cfg)
May 31 10:10:40 api-stag gunicorn[21353]:   File "/home/admin/.pyenv/versions/3.9.5/envs/venv/lib/python3.9/site-packages/gunicorn/glogging.py", line 248, in setup
May 31 10:10:40 api-stag gunicorn[21353]:     fileConfig(cfg.logconfig, defaults=defaults,
May 31 10:10:40 api-stag gunicorn[21353]:   File "/home/admin/.pyenv/versions/3.9.5/lib/python3.9/logging/config.py", line 69, in fileConfig
May 31 10:10:40 api-stag gunicorn[21353]:     cp.read(fname)
May 31 10:10:40 api-stag gunicorn[21353]:   File "/home/admin/.pyenv/versions/3.9.5/lib/python3.9/configparser.py", line 697, in read
May 31 10:10:40 api-stag gunicorn[21353]:     self._read(fp, filename)
May 31 10:10:40 api-stag gunicorn[21353]:   File "/home/admin/.pyenv/versions/3.9.5/lib/python3.9/configparser.py", line 1082, in _read
May 31 10:10:40 api-stag gunicorn[21353]:     raise MissingSectionHeaderError(fpname, lineno, line)
May 31 10:10:40 api-stag gunicorn[21353]: configparser.MissingSectionHeaderError: File contains no section headers.
May 31 10:10:40 api-stag gunicorn[21353]: file: '/etc/app/log_conf.yml', line: 1
May 31 10:10:40 api-stag gunicorn[21353]: 'version: 1\n'

Service:

...
ExecStart=/home/admin/.pyenv/versions/venv/bin/gunicorn -c /etc/app/config.py main:app --log-config /etc/app/log_conf.yml

log_conf.yml

version: 1
disable_existing_loggers: False
formatters:
  default:
    (): 'uvicorn.logging.DefaultFormatter'
    format: '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
  access:
    (): 'uvicorn.logging.AccessFormatter'
    format: '%(asctime)s - %(name)s - %(levelname)s - %(message)s'
handlers:
  default:
    formatter: default
    class: logging.StreamHandler
    stream: ext://sys.stderr
  access:
    formatter: access
    class: logging.StreamHandler
    stream: ext://sys.stdout
loggers:
  uvicorn.error:
    level: INFO
    handlers:
      - default
    propagate: no
  uvicorn.access:
    level: INFO
    handlers:
      - access
    propagate: no

[euri10]

@houmie your error is in gunicron which tries to load a ini file, this is unrelated to uvicorn

[houmie]

@euri10

That's strange. This only happens when I try to pass in --log-config /etc/app/log_conf.yml.

ExecStart=/home/admin/.pyenv/versions/venv/bin/gunicorn -c /etc/app/config.py main:app --log-config /etc/app/log_conf.yml

If I don't do that it works fine.

ExecStart=/home/admin/.pyenv/versions/venv/bin/gunicorn -c /etc/app/config.py main:app

I even tried to load everything without gunicorn config.

ExecStart=/home/admin/.pyenv/versions/venv/bin/gunicorn main:app -w 1 -k uvicorn.workers.UvicornWorker --log-config /etc/app/log_conf.yml

It keeps complaining about the yml file:

May 31 11:12:41 api-stag gunicorn[22354]: configparser.MissingSectionHeaderError: File contains no section headers.
May 31 11:12:41 api-stag gunicorn[22354]: file: '/etc/app/log_conf.yml', line: 1
May 31 11:12:41 api-stag gunicorn[22354]: 'version: 1\n'

What could I be missing, please?

[euri10]

again, this has nothing to do with uvicorn, you are passing a yaml log file to gunicorn while it expects a ini file: https://docs.gunicorn.org/en/stable/settings.html#logconfig

[houmie]

Sorry my bad. I'm trying to get my head around this.

So how would I pass in --log-config /etc/app/log_conf.yml to uvicorn, if uvicorn was driven through gunicorn in the first place, as I demonstrated above?

Based on the docs: https://www.uvicorn.org/#running-with-gunicorn I'm not seeing how to achieve that.

Thanks

[euri10]

it's in the docs here https://www.uvicorn.org/deployment/#gunicorn

If you need to pass uvicorn's config arguments to gunicorn workers then you'll have to subclass UvicornWorker

[houmie]

Ah Thanks. I see. So it should look like this?

/etc/app/config.py

from uvicorn.workers import UvicornWorker

bind = "127.0.0.1:8000"
workers = 4
worker_class = "MyUvicornWorker"
...

class MyUvicornWorker(UvicornWorker):
    CONFIG_KWARGS = {"loop": "asyncio", "http": "h11", "lifespan": "off"}

And then the gunicorn service loads it like this, correct?

ExecStart=/home/admin/.pyenv/versions/venv/bin/gunicorn -c /etc/app/config.py main:app

Is there a way to load the uvicorn.yml file into the sub class without the pain of translating every line into CONFIG_KWARGS by hand?

[euri10]

/trying to keep calm and not throw a RTFM...

what about that ?

class MyUvicornWorker(UvicornWorker):
    CONFIG_KWARGS = {"log_config": "yourloginggingfile.yaml"}

please try not to hijack unrelated issues and read the docs, thanks

[houmie]

Please keep calm. Why are you so on the edge? I'm having a respectful and friendly conversation with you. Nobody is holding a gun against your head here.

The documentation is not very comprehensive.

May 31 13:18:34 api-stag gunicorn[25040]: Error: class uri 'MyUvicornWorker' invalid or not found:
May 31 13:18:34 api-stag gunicorn[25040]: [Traceback (most recent call last):
May 31 13:18:34 api-stag gunicorn[25040]:   File "/home/admin/.pyenv/versions/3.9.5/envs/venv/lib/python3.9/site-packages/gunicorn/util.py", line 88, in load_class
May 31 13:18:34 api-stag gunicorn[25040]:     return pkg_resources.load_entry_point(
May 31 13:18:34 api-stag gunicorn[25040]:   File "/home/admin/.pyenv/versions/3.9.5/envs/venv/lib/python3.9/site-packages/pkg_resources/__init__.py", line 474, in load_entry_point
May 31 13:18:34 api-stag gunicorn[25040]:     return get_distribution(dist).load_entry_point(group, name)
May 31 13:18:34 api-stag gunicorn[25040]:   File "/home/admin/.pyenv/versions/3.9.5/envs/venv/lib/python3.9/site-packages/pkg_resources/__init__.py", line 2845, in load_entry_point
May 31 13:18:34 api-stag gunicorn[25040]:     raise ImportError("Entry point %r not found" % ((group, name),))
May 31 13:18:34 api-stag gunicorn[25040]: ImportError: Entry point ('gunicorn.workers', 'MyUvicornWorker') not found

It seems pointing to the subclass in the same config.py is not enough. I have already set the Python Path to /etc/app. But it is still not able to find it. The documentation doesn't say anything about this.

[euri10]

just run gunicorn -k MyUvicornWorker with the above subclassed UvicornWorker, everything is in the docs, just take the time to read, but I know : https://twitter.com/jcsrb/status/1392459191353286656

[houmie]

¯_(ツ)_/¯ I know you don't believe me that I have checked the docs. The issue is that the sub class can't be found.

I have followed what you have suggested:

/etc/systemd/system/app.service:

ExecStart=/home/admin/.pyenv/versions/venv/bin/gunicorn -w 1 -k MyUvicornWorker main:app

A friendly reminder the subclass of MyUvicornWorker is in /etc/app/config.py. /etc/app is in PythonPath.

May 31 16:17:10 api-stag gunicorn[26055]: Error: class uri 'MyUvicornWorker' invalid or not found:
May 31 16:17:10 api-stag gunicorn[26055]: [Traceback (most recent call last):
May 31 16:17:10 api-stag gunicorn[26055]:   File "/home/admin/.pyenv/versions/3.9.5/envs/venv/lib/python3.9/site-packages/gunicorn/util.py", line 88, in load_class
May 31 16:17:10 api-stag gunicorn[26055]:     return pkg_resources.load_entry_point(
May 31 16:17:10 api-stag gunicorn[26055]:   File "/home/admin/.pyenv/versions/3.9.5/envs/venv/lib/python3.9/site-packages/pkg_resources/__init__.py", line 474, in load_entry_point
May 31 16:17:10 api-stag gunicorn[26055]:     return get_distribution(dist).load_entry_point(group, name)
May 31 16:17:10 api-stag gunicorn[26055]:   File "/home/admin/.pyenv/versions/3.9.5/envs/venv/lib/python3.9/site-packages/pkg_resources/__init__.py", line 2845, in load_entry_point
May 31 16:17:10 api-stag gunicorn[26055]:     raise ImportError("Entry point %r not found" % ((group, name),))
May 31 16:17:10 api-stag gunicorn[26055]: ImportError: Entry point ('gunicorn.workers', 'MyUvicornWorker') not found
May 31 16:17:10 api-stag gunicorn[26055]: ]
May 31 16:17:10 api-stag systemd[1]: app.service: Main process exited, code=exited, status=1/FAILURE
May 31 16:17:10 api-stag systemd[1]: app.service: Failed with result 'exit-code'.

[euri10]

adapt your path @houmie -k MyUvicornWorker should be probably -k config.MyUvicornWorker given what you described, dunno what to tell you other than read the errors you get more carefully maybe, and ask questions on SO next time ?

[ronalddas]

How add custom header to access log? User-Agent or Authorization, etc.? Thanks.

Any example for this? I want to log the request_id from nginx

[grillazz]

@ronalddas take a look here https://github.com/grillazz/fastapi-sqlalchemy-asyncpg/blob/main/config.ini

[ronalddas]

@grillazz Thanks for the reference, but I just ended up using asgi-logger