Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

How to add response time in gunicorn access log #2404

Closed
swarnagowri opened this issue Aug 18, 2020 · 10 comments
Closed

How to add response time in gunicorn access log #2404

swarnagowri opened this issue Aug 18, 2020 · 10 comments
Assignees

Comments

@swarnagowri
Copy link

swarnagowri commented Aug 18, 2020

I have a gunicorn *config.py and need to add response time to gunicorn access log:

Here's what I added to achieve this after referring several docs and forums:

...  
accesslog = some_path/filename
access_log_format = '%(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s" %(T)s %(M)s %(D)s %(L)s'
...

gunicorn version 19.7.1

And the outout in access log:

<ip1> - - [18/Aug/2020:08:00:54 CDT] "DELETE /ws/v1/sessions HTTP/1.1" 200 139 "-" "python-requests/2.22.0" 0 - 9582 0.009582
<ip2> - - [18/Aug/2020:08:01:30 CDT] "POST /ws/v1/sessions?userId=<userId> HTTP/1.1" 200 928 "-" "python-requests/2.22.0" 0 - 40070 0.040070

I am new to python, gunicorn and web apis. I am unable to figure out how to add response time to the log. Is this the correct way? I saw in #2218 that although the change says request time, the testing seems to show response time. Is the request time the same as response time? Please help. I was not sure how to add this to a forum over here, so raised this as an issue. I checked from https://github.com/benoitc/gunicorn/search?q=request_start&unscoped_q=request_start that request time is the response time, as the request is handled, and the response is written and then the time difference is being measured as request time. Is this understanding correct?

@benoitc
Copy link
Owner

benoitc commented Aug 26, 2020

request time is afaik the response time .

something like "%(h) %(l) %(u) %(t) \"%(r)\" %(s) %(b} \"%({Referer}i)\" \"%({User-agent}i)\" %(D)"

should provide the response time and analyse it like described in this old post: https://www.sumologic.com/insight/apache-response-time/

@benoitc benoitc self-assigned this Aug 26, 2020
@swarnagowri
Copy link
Author

Thank you, that answers my question.

@jaytimbadia
Copy link

jaytimbadia commented Jul 23, 2021

Hey I am using fastapi and serving up with gunicorn
my gunicorn config file:

import os
import logging
import sys
import json 

from types import FrameType
from typing import cast

from loguru import logger

from dotenv import load_dotenv

load_dotenv('server/core/.dev_env')

# json_logs = True if os.getenv("JSON_LOGS") == "1" else False
# print(json_logs, type(json_logs))

host: str = os.getenv('host')
port: int = os.getenv('port')
env: str = os.getenv("env")
use_bind = f"{host}:{port}"

workers_per_core_str = os.getenv("WORKERS_PER_CORE")
web_concurrency_str = int(os.getenv("WEB_CONCURRENCY"))
cores = os.getenv("CORES")

print(web_concurrency_str, type(web_concurrency_str))
workers_per_core = int(workers_per_core_str)
default_web_concurrency = workers_per_core * int(cores)

if web_concurrency_str != 0:
    web_concurrency = int(web_concurrency_str)
    assert web_concurrency > 0
else:
    web_concurrency = max(int(default_web_concurrency), 1)


loglevel = 'DEBUG'
accesslog = "access.log"
errorlog = "error.log"
access_log_format = '%(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s" %(D)s'


options = {
        "bind": use_bind,
        "workers": web_concurrency,
        "accesslog": "access.log",
        "errorlog": "error.log",
        "worker_class": "uvicorn.workers.UvicornWorker",
    }

print(json.dumps(options))
logger.info('logging files')

I am providing the log format, still I am not able to get logs in the mentioned format.
My logs:
127.0.0.1:52244 - "GET /docs HTTP/1.1" 200
127.0.0.1:52244 - "GET /openapi.json HTTP/1.1" 200
127.0.0.1:52244 - "GET /v1/api/get_data_sources HTTP/1.1" 405
127.0.0.1:52254 - "GET /docs HTTP/1.1" 200
127.0.0.1:52254 - "GET /openapi.json HTTP/1.1" 200
127.0.0.1:52256 - "GET /docs HTTP/1.1" 200
127.0.0.1:52256 - "GET /openapi.json HTTP/1.1" 200
127.0.0.1:52256 - "GET /v1/api/get_data_sources HTTP/1.1" 405

No request time, nothing.

Can you please help, how can I get request time and length in the log file.
@benoitc @swarnagowri @brosner

@jose-lpa
Copy link

jose-lpa commented Oct 8, 2021

Hey I am using fastapi and serving up with gunicorn my gunicorn config file:

import os
import logging
import sys
import json 

from types import FrameType
from typing import cast

from loguru import logger

from dotenv import load_dotenv

load_dotenv('server/core/.dev_env')

# json_logs = True if os.getenv("JSON_LOGS") == "1" else False
# print(json_logs, type(json_logs))

host: str = os.getenv('host')
port: int = os.getenv('port')
env: str = os.getenv("env")
use_bind = f"{host}:{port}"

workers_per_core_str = os.getenv("WORKERS_PER_CORE")
web_concurrency_str = int(os.getenv("WEB_CONCURRENCY"))
cores = os.getenv("CORES")

print(web_concurrency_str, type(web_concurrency_str))
workers_per_core = int(workers_per_core_str)
default_web_concurrency = workers_per_core * int(cores)

if web_concurrency_str != 0:
    web_concurrency = int(web_concurrency_str)
    assert web_concurrency > 0
else:
    web_concurrency = max(int(default_web_concurrency), 1)


loglevel = 'DEBUG'
accesslog = "access.log"
errorlog = "error.log"
access_log_format = '%(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s "%(f)s" "%(a)s" %(D)s'


options = {
        "bind": use_bind,
        "workers": web_concurrency,
        "accesslog": "access.log",
        "errorlog": "error.log",
        "worker_class": "uvicorn.workers.UvicornWorker",
    }

print(json.dumps(options))
logger.info('logging files')

I am providing the log format, still I am not able to get logs in the mentioned format. My logs: 127.0.0.1:52244 - "GET /docs HTTP/1.1" 200 127.0.0.1:52244 - "GET /openapi.json HTTP/1.1" 200 127.0.0.1:52244 - "GET /v1/api/get_data_sources HTTP/1.1" 405 127.0.0.1:52254 - "GET /docs HTTP/1.1" 200 127.0.0.1:52254 - "GET /openapi.json HTTP/1.1" 200 127.0.0.1:52256 - "GET /docs HTTP/1.1" 200 127.0.0.1:52256 - "GET /openapi.json HTTP/1.1" 200 127.0.0.1:52256 - "GET /v1/api/get_data_sources HTTP/1.1" 405

No request time, nothing.

Can you please help, how can I get request time and length in the log file. @benoitc @swarnagowri @brosner

Just ran myself into this today, and it seems to be an issue of uvicorn, not gunicorn: encode/uvicorn#527

@jaytimbadia
Copy link

jaytimbadia commented Oct 8, 2021 via email

@joydeb28
Copy link

Facing the same issue. Did we find any solution??

@maxie7
Copy link

maxie7 commented Jun 22, 2022

I'm facing the same problem! It seems it doesn't apply access_log_format from config file.

accesslog = "/var/log/access.log"
# access_log_format = '%(h)s %(l)s %(u)s %(t)s "%(r)s" %(s)s %(b)s %(L)ss "%(f)s" "%(a)s"'
access_log_format = "%(h) %(l) %(u) %(t) \"%(r)\" %(s) %(b} \"%({Referer}i)\" \"%({User-agent}i)\" %(D)"
errorlog = "/var/log/error.log"

None of the above works. I only can get more info if I change loglevel to "debug"

I have gunicorn (version 20.1.0), I also tried gunicorn (19.7.1)
:rage1: :rage2: :rage3:

@liuzhuoling2011
Copy link

same problem

@liuzhuoling2011
Copy link

This repo saves time.
https://github.com/carlos-rian/guvicorn_logger

@benoitc
Copy link
Owner

benoitc commented Jun 18, 2024

this ticket is closed. Also p'ease try on latest version of gunicorn.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

7 participants