I have the following FastAPI application:
from fastapi import FastAPI
import logging
import uvicorn
app = FastAPI(title="api")
LOG = logging.getLogger(__name__)
LOG.info("API is starting up")
LOG.info(uvicorn.Config.asgi_version)
@app.get("/")
async def get_index():
LOG.info("GET /")
return {"Hello": "Api"}
The application locally is run with:
uvicorn api:app --reload
INFO: Will watch for changes in these directories: ['/Users/user/code/backend/api']
INFO: Uvicorn running on http://127.0.0.1:8000 (Press CTRL+C to quit)
INFO: Started reloader process [44258] using StatReload
INFO: Started server process [44260]
INFO: Waiting for application startup.
INFO: Application startup complete.
It is not logging any of the startup messages. Later on when sending an HTTP request to the API:
INFO: 127.0.0.1:50538 - "POST /api/v1/endpoint HTTP/1.1" 200 OK
In the function body there is LOG.info("example") that does not get logged either. Is there a way to make FastAPI logging work with Uvicorn and also in production (independently of the execution environments like Uvicorn)?
uvicorn loggerStraight from the documentation:
Logging
--log-config <path>- Logging configuration file. Options:dictConfig()formats: .json, .yaml. Any other format will be processed withfileConfig(). Set theformatters.default.use_colorsandformatters.access.use_colorsvalues to override the auto-detected behavior.
- If you wish to use a YAML file for your logging config, you will need to include PyYAML as a dependency for your project or install uvicorn with the
[standard]optional extras.--log-level <str>- Set the log level. Options: 'critical', 'error', 'warning', 'info', 'debug', 'trace'. Default: 'info'.--no-access-log- Disable access log only, without changing log level.--use-colors/--no-use-colors- Enable / disable colorized formatting of the log records, in case this is not set it will be auto-detected. This option is ignored if the--log-configCLI option is used.
As shown above, the --log-level flag specifies the lowest severity log message the logger will handle, where 'trace' is the lowest severity/level and 'critical' is the highest one. For instance, if the level is set to 'info', the logger will only handle 'info', 'warning', 'error' and 'critical' messages, whereas 'debug' and 'trace' messages will be ignored. If the level is set to 'trace', the logger will handle all the messages.
uvicorn from the command lineWhen running uvicorn using the command line interface, you could set the log level as follows. On a side note, if one would like to disable the "access log" messages only, without changing the log level, they could use the --no-access-log flag (the --access-log flag is enabled by default). Moreover, in order to change the host and/or port, one could do that using --host 0.0.0.0 and/or --port 8000. In the example below, main refers to the filename of the application (e.g., main.py)—see this answer for more details.
uvicorn main:app --log-level trace
uvicorn programmaticallyTo run uvicorn from within a Python program, you could use the following. One could set the logging level, using the log_level flag in uvicorn.run(), as shown below. Again, if one would like to disable the "access log" messages only, they could do that by setting the access_log argument to False (i.e., access_log=False). To change the host and/or port, one could use, for instance, host='0.0.0.0' and/or port=8000.
uvicorn.run(app, log_level="trace")
uvicorn logger to log custom messages tooUvicorn, as shown in its implementation here, internally uses various loggers such as uvicorn, uvicorn.access, uvicorn.error and uvicorn.asgi. The logger, however, that comes by the name uvicorn.error seems to be the one mostly used by Uvicorn, as shown here and here, for instance, to log various warnings, errors, as well as other type of information. On the other hand, uvicorn.access logger appears to be used for logging HTTP requests; for example, see here. For uvicorn.asgi logger, see here as well.
Hence, one could use the uvicorn.error logger to log their own custom messages/errors, as shown in the example below, along with the uvicorn messages (again, the logging level could be changed using the log_level flag in uvicorn.run()) The uvicorn.error logger, as shown in the implementation here, will propagate a message by default to its ancestor logger, i.e., uvicorn.
On a side note, the parent logger, in this case uvicorn, would normally pass on the message to the highest-level logger, known as the root logger, but the uvicorn logger seems to have propagate flag set to False (see the relevant implementation), meaning that its messages won't propagate to the root logger (which is perfectly fine—as described in the official Python documentation, it is strongly advised that you do not log to the root logger in your library). For the sake of completeness, it should be noted that in order to disable this behaviour—not that you have to—on uvicorn.error logger in the example below, one could set the propagate attribute to False for that logger as well, e.g., logger.propagate = False.
main.py
from fastapi import FastAPI
import uvicorn
import logging
app = FastAPI(title='api')
logger = logging.getLogger('uvicorn.error')
@app.get('/')
async def main():
logger.info('GET /') # or logger.debug(), logger.error(), etc.
return 'success'
if __name__ == '__main__':
uvicorn.run(app, log_level="trace")
uvicorn loggers to log custom messages tooThis approach demonstrates how to customise the uvicorn loggers, as well as use them to log both uvicorn and custom messages.
To define a custom format for the uvicorn loggers, one could use the log_config attribute in uvicorn.run() to pass a logging configuration dictionary (i.e., dictConfig()), as shown in the exmaple below, including the various schema details, such as formatters, handlers and loggers. You could then define the uvicorn.error logger in main.py, as demonstrated in the previous section, and use it across your application.
For the file handler in the example below, RotatingFileHandler is used, in which:
You can use the
maxBytesandbackupCountvalues to allow the file to rollover at a predetermined size. When the size is about to be exceeded, the file is closed and a new file is silently opened for output. Rollover occurs whenever the current log file is nearlymaxBytesin length; but if either ofmaxBytesorbackupCountis zero, rollover never occurs, so you generally want to setbackupCountto at least 1, and have a non-zeromaxBytes(by default, the file would grow indefinitely).When
backupCountis non-zero, the system will save old log files by appending the extensions ‘.1’, ‘.2’ etc., to the filename. For example, with abackupCountof 5 and a base file name ofapp.log, you would getapp.log,app.log.1,app.log.2, up toapp.log.5. The file being written to is alwaysapp.log. When this file is filled, it is closed and renamed toapp.log.1, and if filesapp.log.1,app.log.2, etc. exist, then they are renamed toapp.log.2,app.log.3etc. respectively.
main.py
from fastapi import FastAPI
import uvicorn
import logging
import settings
app = FastAPI(title='api')
logger = logging.getLogger('uvicorn.error')
@app.get('/')
async def main():
logger.info('GET /') # or logger.debug(), logger.error(), etc.
return 'success'
if __name__ == '__main__':
uvicorn.run(app, log_config=settings.LOGGING_CONFIG)
settings.py
LOGGING_CONFIG = {
'version': 1,
'disable_existing_loggers': True,
'formatters': {
'standard': {
'format': '%(asctime)s [%(levelname)s] %(name)s: %(message)s'
},
'custom_formatter': {
'format': "%(asctime)s [%(processName)s: %(process)d] [%(threadName)s: %(thread)d] [%(levelname)s] %(name)s: %(message)s"
},
},
'handlers': {
'default': {
'formatter': 'standard',
'class': 'logging.StreamHandler',
'stream': 'ext://sys.stdout', # Default is stderr
},
'stream_handler': {
'formatter': 'custom_formatter',
'class': 'logging.StreamHandler',
'stream': 'ext://sys.stdout', # Default is stderr
},
'file_handler': {
'formatter': 'custom_formatter',
'class': 'logging.handlers.RotatingFileHandler',
'filename': 'app.log',
'maxBytes': 1024 * 1024 * 1, # = 1MB
'backupCount': 3,
},
},
'loggers': {
'uvicorn': {
'handlers': ['default', 'file_handler'],
'level': 'TRACE',
'propagate': False
},
'uvicorn.access': {
'handlers': ['stream_handler', 'file_handler'],
'level': 'TRACE',
'propagate': False
},
'uvicorn.error': {
'handlers': ['stream_handler', 'file_handler'],
'level': 'TRACE',
'propagate': False
},
'uvicorn.asgi': {
'handlers': ['stream_handler', 'file_handler'],
'level': 'TRACE',
'propagate': False
},
},
}
One could have the log messages displayed and/or saved in JSON format, if they wish, by either using a simple JSON format such as:
settings.py
LOGGING_CONFIG = {
'version': 1,
'disable_existing_loggers': True,
'formatters': {
'standard': ..., # same as above or customise that as well
'custom_formatter': {
'format': "{'time':'%(asctime)s', 'process_name': '%(processName)s', 'process_id': '%(process)s', 'thread_name': '%(threadName)s', 'thread_id': '%(thread)s','level': '%(levelname)s', 'logger_name': '%(name)s', 'message': '%(message)s'}"
},
},
... # the rest is the same as in the original settings.py above
}
Or, a more elegant version, as demonstrated previously in this answer and as shown below. Please refer to that answer and this one for further details, as well as the relevant middleware and methods for logging Request and Response information, which would go into the extra parameter when logging messages in the application, for example:
logger.info("some msg", extra={'extra_info': get_extra_info(request, response)})
If you don't need that kind of information, please feel free not to use the extra parameter, as well as remove the extra_info part from the get_log() function below.
settings.py
import logging, json
class CustomJSONFormatter(logging.Formatter):
def __init__(self, fmt):
logging.Formatter.__init__(self, fmt)
def format(self, record):
logging.Formatter.format(self, record)
return json.dumps(get_log(record), indent=2)
def get_log(record):
d = {
"time": record.asctime,
"process_name": record.processName,
"process_id": record.process,
"thread_name": record.threadName,
"thread_id": record.thread,
"level": record.levelname,
"logger_name": record.name,
"pathname": record.pathname,
"line": record.lineno,
"message": record.message,
}
if hasattr(record, "extra_info"):
d["req"] = record.extra_info["req"]
d["res"] = record.extra_info["res"]
return d
LOGGING_CONFIG = {
'version': 1,
'disable_existing_loggers': True,
'formatters': {
'standard': ..., # same as above or customise that as well
'custom_formatter': {
'()': lambda: CustomJSONFormatter(fmt='%(asctime)s')
},
},
... # the rest is the same as in the original settings.py above
}
Output example:
{
"time": "2024-10-27 11:05:00,300",
"process_name": "MainProcess",
"process_id": 4102,
"thread_name": "AnyIO worker thread",
"thread_id": 1147,
"level": "INFO",
"logger_name": "uvicorn.error",
"pathname": "C:\\...",
"line": 33,
"message": "GET /",
"req": {
"url": "/",
"headers": {
"host": "localhost:8000",
"user-agent": "Mozilla...",
"accept": "text/html,application/xhtml+xml,..."
},
"method": "GET",
"http_version": "1.1",
"original_url": "/",
"query": {}
},
"res": {
"status_code": 200,
"status": "OK"
}
}
uvicorn loggersIn case one wished having a separate custom Python logger instead of customising the existing uvicorn loggers, as demonstrated earlier, they would need to add a StreamHandler and/or FileHandler and set the desired level, i.e., DEBUG, INFO, WARNING, etc.—the lowest level offered by Python's logging module is DEBUG, with the default level being WARNING (if one is interested in adding a custom log level, see this post).
You could either do that using a dictConfig(), as shown earlier, or directly using the logging's module functions and classes. The following example is based on this answer, which demonstrates how to customise the format of the logging messages in JSON (hence, see that answer, if you are looking for a similar format presented in the previous section), as well as this answer that shows how to log both the request and response bodies in the background.
More details and examples can also be found in Python's official documentation page here. You may also want to have a look at all the available LogRecord attributes that can be used to format the logging records.
Setting log_level="trace" in uvicorn.run() would set the level of the uvicorn logger to TRACE, as described earlier—in case one needed that as well. Also, one could still customise the uvicorn loggers, if they wish, using the LOGGING_CONFIG dictionary provided in the previous section and passing it to the settings, i.e., uvicorn.run(..., log_config=settings.LOGGING_CONFIG). In that way, one could get the uvicorn logs in an elegant format and have them saved to a file on disk as well.
from fastapi import FastAPI
import logging
import uvicorn
import sys
app = FastAPI()
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
formatter = logging.Formatter("%(asctime)s [%(processName)s: %(process)d] [%(threadName)s: %(thread)d] [%(levelname)s] %(name)s: %(message)s")
stream_handler = logging.StreamHandler(sys.stdout)
stream_handler.setFormatter(formatter)
file_handler = logging.FileHandler("info.log")
file_handler.setFormatter(formatter)
logger.addHandler(stream_handler)
logger.addHandler(file_handler)
logger.info('API is starting up')
@app.get('/')
async def main():
logger.info('GET /')
return 'ok'
if __name__ == '__main__':
uvicorn.run(app, log_level="trace") # or `log_config=settings.LOGGING_CONFIG`
In each of the above cases, one may wish to initialise the logger at startup inside a lifespan handler, and then add it to request.state, so that it can be accessed outside the main file of the application as well; for instance, from a submodule that uses APIRouter to create endpoints, lying inside a routers package, which is normally the case when building Bigger Applications. To do that, please have a look at this answer.