mirror of
https://git.anonymousland.org/anonymousland/synapse-product.git
synced 2024-12-12 06:14:19 -05:00
3d12d97415
For each request, track the amount of time spent waiting for a db connection. This entails adding it to the LoggingContext and we may as well add metrics for it while we are passing.
149 lines
4.6 KiB
Python
149 lines
4.6 KiB
Python
# Copyright 2016 OpenMarket Ltd
|
|
#
|
|
# Licensed under the Apache License, Version 2.0 (the "License");
|
|
# you may not use this file except in compliance with the License.
|
|
# You may obtain a copy of the License at
|
|
#
|
|
# http://www.apache.org/licenses/LICENSE-2.0
|
|
#
|
|
# Unless required by applicable law or agreed to in writing, software
|
|
# distributed under the License is distributed on an "AS IS" BASIS,
|
|
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
|
|
# See the License for the specific language governing permissions and
|
|
# limitations under the License.
|
|
|
|
from synapse.util.logcontext import LoggingContext
|
|
from twisted.web.server import Site, Request
|
|
|
|
import contextlib
|
|
import logging
|
|
import re
|
|
import time
|
|
|
|
ACCESS_TOKEN_RE = re.compile(r'(\?.*access(_|%5[Ff])token=)[^&]*(.*)$')
|
|
|
|
|
|
class SynapseRequest(Request):
|
|
def __init__(self, site, *args, **kw):
|
|
Request.__init__(self, *args, **kw)
|
|
self.site = site
|
|
self.authenticated_entity = None
|
|
self.start_time = 0
|
|
|
|
def __repr__(self):
|
|
# We overwrite this so that we don't log ``access_token``
|
|
return '<%s at 0x%x method=%s uri=%s clientproto=%s site=%s>' % (
|
|
self.__class__.__name__,
|
|
id(self),
|
|
self.method,
|
|
self.get_redacted_uri(),
|
|
self.clientproto,
|
|
self.site.site_tag,
|
|
)
|
|
|
|
def get_redacted_uri(self):
|
|
return ACCESS_TOKEN_RE.sub(
|
|
r'\1<redacted>\3',
|
|
self.uri
|
|
)
|
|
|
|
def get_user_agent(self):
|
|
return self.requestHeaders.getRawHeaders("User-Agent", [None])[-1]
|
|
|
|
def started_processing(self):
|
|
self.site.access_logger.info(
|
|
"%s - %s - Received request: %s %s",
|
|
self.getClientIP(),
|
|
self.site.site_tag,
|
|
self.method,
|
|
self.get_redacted_uri()
|
|
)
|
|
self.start_time = int(time.time() * 1000)
|
|
|
|
def finished_processing(self):
|
|
|
|
try:
|
|
context = LoggingContext.current_context()
|
|
ru_utime, ru_stime = context.get_resource_usage()
|
|
db_txn_count = context.db_txn_count
|
|
db_txn_duration_ms = context.db_txn_duration_ms
|
|
db_sched_duration_ms = context.db_sched_duration_ms
|
|
except Exception:
|
|
ru_utime, ru_stime = (0, 0)
|
|
db_txn_count, db_txn_duration_ms = (0, 0)
|
|
|
|
self.site.access_logger.info(
|
|
"%s - %s - {%s}"
|
|
" Processed request: %dms (%dms, %dms) (%dms/%dms/%d)"
|
|
" %sB %s \"%s %s %s\" \"%s\"",
|
|
self.getClientIP(),
|
|
self.site.site_tag,
|
|
self.authenticated_entity,
|
|
int(time.time() * 1000) - self.start_time,
|
|
int(ru_utime * 1000),
|
|
int(ru_stime * 1000),
|
|
db_sched_duration_ms,
|
|
db_txn_duration_ms,
|
|
int(db_txn_count),
|
|
self.sentLength,
|
|
self.code,
|
|
self.method,
|
|
self.get_redacted_uri(),
|
|
self.clientproto,
|
|
self.get_user_agent(),
|
|
)
|
|
|
|
@contextlib.contextmanager
|
|
def processing(self):
|
|
self.started_processing()
|
|
yield
|
|
self.finished_processing()
|
|
|
|
|
|
class XForwardedForRequest(SynapseRequest):
|
|
def __init__(self, *args, **kw):
|
|
SynapseRequest.__init__(self, *args, **kw)
|
|
|
|
"""
|
|
Add a layer on top of another request that only uses the value of an
|
|
X-Forwarded-For header as the result of C{getClientIP}.
|
|
"""
|
|
def getClientIP(self):
|
|
"""
|
|
@return: The client address (the first address) in the value of the
|
|
I{X-Forwarded-For header}. If the header is not present, return
|
|
C{b"-"}.
|
|
"""
|
|
return self.requestHeaders.getRawHeaders(
|
|
b"x-forwarded-for", [b"-"])[0].split(b",")[0].strip()
|
|
|
|
|
|
class SynapseRequestFactory(object):
|
|
def __init__(self, site, x_forwarded_for):
|
|
self.site = site
|
|
self.x_forwarded_for = x_forwarded_for
|
|
|
|
def __call__(self, *args, **kwargs):
|
|
if self.x_forwarded_for:
|
|
return XForwardedForRequest(self.site, *args, **kwargs)
|
|
else:
|
|
return SynapseRequest(self.site, *args, **kwargs)
|
|
|
|
|
|
class SynapseSite(Site):
|
|
"""
|
|
Subclass of a twisted http Site that does access logging with python's
|
|
standard logging
|
|
"""
|
|
def __init__(self, logger_name, site_tag, config, resource, *args, **kwargs):
|
|
Site.__init__(self, resource, *args, **kwargs)
|
|
|
|
self.site_tag = site_tag
|
|
|
|
proxied = config.get("x_forwarded", False)
|
|
self.requestFactory = SynapseRequestFactory(self, proxied)
|
|
self.access_logger = logging.getLogger(logger_name)
|
|
|
|
def log(self, request):
|
|
pass
|