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

Convert Access Log Generator to use Python logging #473

Open
wants to merge 5 commits into
base: main
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from 3 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
64 changes: 40 additions & 24 deletions daphne/access.py
Original file line number Diff line number Diff line change
@@ -1,4 +1,6 @@
import datetime
import logging

logger = logging.getLogger(__name__)


class AccessLogGenerator:
Expand All @@ -8,7 +10,18 @@ class AccessLogGenerator:
"""

def __init__(self, stream):
self.stream = stream
if stream:
logger.propagate = False
handler = logging.StreamHandler(stream)
formatter = logging.Formatter(
'%(host)s %(ident)s %(user)s [%(asctime)s] "%{request} %(message)s" '
"%(status)s %(length)s"
"%d/%b/%Y:%H:%M:%S"
)
handler.setFormatter(fmt=formatter)
logger.addHandler(handler)
else:
logger.addHandler(logging.NullHandler)

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm not super familiar with how the logging module works, but why are these lines needed? What happens if they are removed?

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My understanding is that the access log would be written to the default handler (likely console). If I am understanding the cli correctly, the access log is not written unless explicitly enabled,

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Shouldn't we just set propagate = False unconditionally then? (I totally might be misunderstanding how this all works, please bear with me)

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'll need to dig in after I recreate a testing environment. Looks like some other tweaks may be needed

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@mbidewell did you have a chance to dig into this?

def __call__(self, protocol, action, details):
"""
Expand All @@ -18,53 +31,56 @@ def __call__(self, protocol, action, details):
if protocol == "http" and action == "complete":
self.write_entry(
host=details["client"],
date=datetime.datetime.now(),
request="%(method)s %(path)s" % details,
request="%(method)s",
details="%(path)s" % details,
status=details["status"],
length=details["size"],
)
# Websocket requests
elif protocol == "websocket" and action == "connecting":
self.write_entry(
host=details["client"],
date=datetime.datetime.now(),
request="WSCONNECTING %(path)s" % details,
request="WSCONNECTING",
details="%(path)s" % details,
)
elif protocol == "websocket" and action == "rejected":
self.write_entry(
host=details["client"],
date=datetime.datetime.now(),
request="WSREJECT %(path)s" % details,
request="WSREJECT",
details="%(path)s" % details,
)
elif protocol == "websocket" and action == "connected":
self.write_entry(
host=details["client"],
date=datetime.datetime.now(),
request="WSCONNECT %(path)s" % details,
request="WSCONNECT",
details="%(path)s" % details,
)
elif protocol == "websocket" and action == "disconnected":
self.write_entry(
host=details["client"],
date=datetime.datetime.now(),
request="WSDISCONNECT %(path)s" % details,
request="WSDISCONNECT",
details="%(path)s" % details,
)

def write_entry(
self, host, date, request, status=None, length=None, ident=None, user=None
self, host, request, details, status=None, length=None, ident=None, user=None
):
"""
Writes an NCSA-style entry to the log file (some liberty is taken with
what the entries are for non-HTTP)
"""
self.stream.write(
'%s %s %s [%s] "%s" %s %s\n'
% (
host,
ident or "-",
user or "-",
date.strftime("%d/%b/%Y:%H:%M:%S"),
request,
status or "-",
length or "-",
)

logger.info(
"%s %s",
request,
details,
extra={
"host": host,
"request": request,
"details": details,
"ident": ident or "-",
"user": user or "-",
"status": status or "-",
"length": length or "-",
},
)
8 changes: 5 additions & 3 deletions daphne/cli.py
Original file line number Diff line number Diff line change
Expand Up @@ -228,6 +228,10 @@ def run(self, args):
elif args.verbosity >= 1:
access_log_stream = sys.stdout

access_logger = (
AccessLogGenerator(access_log_stream) if access_log_stream else None
)

# Import application
sys.path.insert(0, ".")
application = import_by_path(args.application)
Expand Down Expand Up @@ -270,9 +274,7 @@ def run(self, args):
websocket_connect_timeout=args.websocket_connect_timeout,
websocket_handshake_timeout=args.websocket_connect_timeout,
application_close_timeout=args.application_close_timeout,
action_logger=(
AccessLogGenerator(access_log_stream) if access_log_stream else None
),
action_logger=access_logger if access_log_stream else None,
root_path=args.root_path,
verbosity=args.verbosity,
proxy_forwarded_address_header=self._get_forwarded_host(args=args),
Expand Down
Loading