Exemple #1
0
        def iter_response(iterable):
            iterator = iter(iterable)
            try:
                chunk = next(iterator)
                while not chunk:
                    chunk = next(iterator)
            except StopIteration:
                chunk = b''
            for h, v in start_response_args[0][1]:
                if h.lower() in ('content-length', 'transfer-encoding'):
                    break
            else:
                if not chunk:
                    start_response_args[0][1].append(('Content-Length', '0'))
                elif isinstance(iterable, list):
                    start_response_args[0][1].append(
                        ('Content-Length', str(sum(len(i) for i in iterable))))
            resp_headers = dict(start_response_args[0][1])
            start_response(*start_response_args[0])
            req = Request(env)

            # Log timing information for time-to-first-byte (GET requests only)
            method = self.method_from_req(req)
            if method == 'GET':
                status_int = status_int_for_logging()
                policy_index = get_policy_index(req.headers, resp_headers)
                metric_name = self.statsd_metric_name(req, status_int, method)
                metric_name_policy = self.statsd_metric_name_policy(
                    req, status_int, method, policy_index)
                if metric_name:
                    self.access_logger.timing_since(
                        metric_name + '.first-byte.timing', start_time)
                if metric_name_policy:
                    self.access_logger.timing_since(
                        metric_name_policy + '.first-byte.timing', start_time)

            bytes_sent = 0
            client_disconnect = False
            try:
                while chunk:
                    bytes_sent += len(chunk)
                    yield chunk
                    chunk = next(iterator)
            except StopIteration:  # iterator was depleted
                return
            except GeneratorExit:  # generator was closed before we finished
                client_disconnect = True
                raise
            finally:
                status_int = status_int_for_logging(client_disconnect)
                self.log_request(req,
                                 status_int,
                                 input_proxy.bytes_received,
                                 bytes_sent,
                                 start_time,
                                 time.time(),
                                 resp_headers=resp_headers)
                close_method = getattr(iterable, 'close', None)
                if callable(close_method):
                    close_method()
Exemple #2
0
        def iter_response(iterable):
            iterator = iter(iterable)
            try:
                chunk = next(iterator)
                while not chunk:
                    chunk = next(iterator)
            except StopIteration:
                chunk = ''
            for h, v in start_response_args[0][1]:
                if h.lower() in ('content-length', 'transfer-encoding'):
                    break
            else:
                if not chunk:
                    start_response_args[0][1].append(('Content-Length', '0'))
                elif isinstance(iterable, list):
                    start_response_args[0][1].append(
                        ('Content-Length', str(sum(len(i) for i in iterable))))
            resp_headers = dict(start_response_args[0][1])
            start_response(*start_response_args[0])
            req = Request(env)

            # Log timing information for time-to-first-byte (GET requests only)
            method = self.method_from_req(req)
            if method == 'GET':
                status_int = status_int_for_logging()
                policy_index = get_policy_index(req.headers, resp_headers)
                metric_name = self.statsd_metric_name(req, status_int, method)
                metric_name_policy = self.statsd_metric_name_policy(
                    req, status_int, method, policy_index)
                if metric_name:
                    self.access_logger.timing_since(
                        metric_name + '.first-byte.timing', start_time)
                if metric_name_policy:
                    self.access_logger.timing_since(
                        metric_name_policy + '.first-byte.timing', start_time)

            bytes_sent = 0
            client_disconnect = False
            try:
                while chunk:
                    bytes_sent += len(chunk)
                    yield chunk
                    chunk = next(iterator)
            except StopIteration:  # iterator was depleted
                return
            except GeneratorExit:  # generator was closed before we finished
                client_disconnect = True
                raise
            finally:
                status_int = status_int_for_logging(client_disconnect)
                self.log_request(
                    req, status_int, input_proxy.bytes_received, bytes_sent,
                    start_time, time.time(), resp_headers=resp_headers)
                close_method = getattr(iterable, 'close', None)
                if callable(close_method):
                    close_method()
Exemple #3
0
    def log_request(self, req, status_int, bytes_received, bytes_sent,
                    start_time, end_time, resp_headers=None):
        """
        Log a request.

        :param req: swob.Request object for the request
        :param status_int: integer code for the response status
        :param bytes_received: bytes successfully read from the request body
        :param bytes_sent: bytes yielded to the WSGI server
        :param start_time: timestamp request started
        :param end_time: timestamp request completed
        :param resp_headers: dict of the response headers
        """
        resp_headers = resp_headers or {}
        req_path = get_valid_utf8_str(req.path)
        the_request = quote(unquote(req_path), QUOTE_SAFE)
        if req.query_string:
            the_request = the_request + '?' + req.query_string
        logged_headers = None
        if self.log_hdrs:
            if self.log_hdrs_only:
                logged_headers = '\n'.join('%s: %s' % (k, v)
                                           for k, v in req.headers.items()
                                           if k in self.log_hdrs_only)
            else:
                logged_headers = '\n'.join('%s: %s' % (k, v)
                                           for k, v in req.headers.items())

        method = self.method_from_req(req)
        end_gmtime_str = time.strftime('%d/%b/%Y/%H/%M/%S',
                                       time.gmtime(end_time))
        duration_time_str = "%.4f" % (end_time - start_time)
        start_time_str = "%.9f" % start_time
        end_time_str = "%.9f" % end_time
        policy_index = get_policy_index(req.headers, resp_headers)
        self.access_logger.info(' '.join(
            quote(str(x) if x else '-', QUOTE_SAFE)
            for x in (
                get_remote_client(req),
                req.remote_addr,
                end_gmtime_str,
                method,
                the_request,
                req.environ.get('SERVER_PROTOCOL'),
                status_int,
                req.referer,
                req.user_agent,
                self.obscure_sensitive(req.headers.get('x-auth-token')),
                bytes_received,
                bytes_sent,
                req.headers.get('etag', None),
                req.environ.get('swift.trans_id'),
                logged_headers,
                duration_time_str,
                req.environ.get('swift.source'),
                ','.join(req.environ.get('swift.log_info') or ''),
                start_time_str,
                end_time_str,
                policy_index
            )))
        # Log timing and bytes-transferred data to StatsD
        metric_name = self.statsd_metric_name(req, status_int, method)
        # Only log data for valid controllers (or SOS) to keep the metric count
        # down (egregious errors will get logged by the proxy server itself).
        if metric_name:
            self.access_logger.timing(metric_name + '.timing',
                                      (end_time - start_time) * 1000)
            self.access_logger.update_stats(metric_name + '.xfer',
                                            bytes_received + bytes_sent)
Exemple #4
0
    def log_request(self,
                    req,
                    status_int,
                    bytes_received,
                    bytes_sent,
                    start_time,
                    end_time,
                    resp_headers=None):
        """
        Log a request.

        :param req: swob.Request object for the request
        :param status_int: integer code for the response status
        :param bytes_received: bytes successfully read from the request body
        :param bytes_sent: bytes yielded to the WSGI server
        :param start_time: timestamp request started
        :param end_time: timestamp request completed
        :param resp_headers: dict of the response headers
        """
        resp_headers = resp_headers or {}
        logged_headers = None
        if self.log_hdrs:
            if self.log_hdrs_only:
                logged_headers = '\n'.join('%s: %s' % (k, v)
                                           for k, v in req.headers.items()
                                           if k in self.log_hdrs_only)
            else:
                logged_headers = '\n'.join('%s: %s' % (k, v)
                                           for k, v in req.headers.items())

        method = self.method_from_req(req)
        end_gmtime_str = time.strftime('%d/%b/%Y/%H/%M/%S',
                                       time.gmtime(end_time))
        duration_time_str = "%.4f" % (end_time - start_time)
        start_time_str = "%.9f" % start_time
        end_time_str = "%.9f" % end_time
        policy_index = get_policy_index(req.headers, resp_headers)
        self.access_logger.info(' '.join(
            quote(str(x) if x else '-', QUOTE_SAFE)
            for x in (get_remote_client(req), req.remote_addr, end_gmtime_str,
                      method, req.path_qs, req.environ.get('SERVER_PROTOCOL'),
                      status_int, req.referer, req.user_agent,
                      self.obscure_sensitive(req.headers.get('x-auth-token')),
                      bytes_received, bytes_sent,
                      req.headers.get('etag', None),
                      req.environ.get('swift.trans_id'), logged_headers,
                      duration_time_str, req.environ.get('swift.source'),
                      ','.join(req.environ.get('swift.log_info') or ''),
                      start_time_str, end_time_str, policy_index)))

        # Log timing and bytes-transferred data to StatsD
        metric_name = self.statsd_metric_name(req, status_int, method)
        metric_name_policy = self.statsd_metric_name_policy(
            req, status_int, method, policy_index)
        # Only log data for valid controllers (or SOS) to keep the metric count
        # down (egregious errors will get logged by the proxy server itself).

        if metric_name:
            self.access_logger.timing(metric_name + '.timing',
                                      (end_time - start_time) * 1000)
            self.access_logger.update_stats(metric_name + '.xfer',
                                            bytes_received + bytes_sent)
        if metric_name_policy:
            self.access_logger.timing(metric_name_policy + '.timing',
                                      (end_time - start_time) * 1000)
            self.access_logger.update_stats(metric_name_policy + '.xfer',
                                            bytes_received + bytes_sent)
Exemple #5
0
        def iter_response(iterable):
            iterator = reiterate(iterable)
            content_length = None
            for h, v in start_response_args[0][1]:
                if h.lower() == 'content-length':
                    content_length = int(v)
                    break
                elif h.lower() == 'transfer-encoding':
                    break
            else:
                if isinstance(iterator, list):
                    content_length = sum(len(i) for i in iterator)
                    start_response_args[0][1].append(
                        ('Content-Length', str(content_length)))

            req = Request(env)
            method = self.method_from_req(req)
            if method == 'HEAD':
                content_length = 0
            if content_length is not None:
                iterator = enforce_byte_count(iterator, content_length)

            wire_status_int = int(start_response_args[0][0].split(' ', 1)[0])
            resp_headers = dict(start_response_args[0][1])
            start_response(*start_response_args[0])

            # Log timing information for time-to-first-byte (GET requests only)
            ttfb = 0.0
            if method == 'GET':
                policy_index = get_policy_index(req.headers, resp_headers)
                metric_name = self.statsd_metric_name(req, wire_status_int,
                                                      method)
                metric_name_policy = self.statsd_metric_name_policy(
                    req, wire_status_int, method, policy_index)
                ttfb = time.time() - start_time
                if metric_name:
                    self.access_logger.timing(
                        metric_name + '.first-byte.timing', ttfb * 1000)
                if metric_name_policy:
                    self.access_logger.timing(
                        metric_name_policy + '.first-byte.timing', ttfb * 1000)

            bytes_sent = 0
            client_disconnect = False
            start_status = wire_status_int
            try:
                for chunk in iterator:
                    bytes_sent += len(chunk)
                    yield chunk
            except StopIteration:  # iterator was depleted
                return
            except GeneratorExit:  # generator was closed before we finished
                client_disconnect = True
                raise
            except Exception:
                start_status = 500
                raise
            finally:
                status_int = status_int_for_logging(start_status,
                                                    client_disconnect)
                self.log_request(req,
                                 status_int,
                                 input_proxy.bytes_received,
                                 bytes_sent,
                                 start_time,
                                 time.time(),
                                 resp_headers=resp_headers,
                                 ttfb=ttfb,
                                 wire_status_int=wire_status_int)
                iterator.close()
Exemple #6
0
    def log_request(self,
                    req,
                    status_int,
                    bytes_received,
                    bytes_sent,
                    start_time,
                    end_time,
                    resp_headers=None,
                    ttfb=0,
                    wire_status_int=None):
        """
        Log a request.

        :param req: swob.Request object for the request
        :param status_int: integer code for the response status
        :param bytes_received: bytes successfully read from the request body
        :param bytes_sent: bytes yielded to the WSGI server
        :param start_time: timestamp request started
        :param end_time: timestamp request completed
        :param resp_headers: dict of the response headers
        :param wire_status_int: the on the wire status int
        """
        resp_headers = resp_headers or {}
        logged_headers = None
        if self.log_hdrs:
            if self.log_hdrs_only:
                logged_headers = '\n'.join('%s: %s' % (k, v)
                                           for k, v in req.headers.items()
                                           if k in self.log_hdrs_only)
            else:
                logged_headers = '\n'.join('%s: %s' % (k, v)
                                           for k, v in req.headers.items())

        method = self.method_from_req(req)
        duration_time_str = "%.4f" % (end_time - start_time)
        policy_index = get_policy_index(req.headers, resp_headers)

        acc, cont, obj = None, None, None
        swift_path = req.environ.get('swift.backend_path', req.path)
        if swift_path.startswith('/v1/'):
            _, acc, cont, obj = split_path(swift_path, 1, 4, True)

        replacements = {
            # Time information
            'end_time':
            StrFormatTime(end_time),
            'start_time':
            StrFormatTime(start_time),
            # Information worth to anonymize
            'client_ip':
            StrAnonymizer(get_remote_client(req), self.anonymization_method,
                          self.anonymization_salt),
            'remote_addr':
            StrAnonymizer(req.remote_addr, self.anonymization_method,
                          self.anonymization_salt),
            'path':
            StrAnonymizer(req.path_qs, self.anonymization_method,
                          self.anonymization_salt),
            'referer':
            StrAnonymizer(req.referer, self.anonymization_method,
                          self.anonymization_salt),
            'user_agent':
            StrAnonymizer(req.user_agent, self.anonymization_method,
                          self.anonymization_salt),
            'headers':
            StrAnonymizer(logged_headers, self.anonymization_method,
                          self.anonymization_salt),
            'client_etag':
            StrAnonymizer(req.headers.get('etag'), self.anonymization_method,
                          self.anonymization_salt),
            'account':
            StrAnonymizer(acc, self.anonymization_method,
                          self.anonymization_salt),
            'container':
            StrAnonymizer(cont, self.anonymization_method,
                          self.anonymization_salt),
            'object':
            StrAnonymizer(obj, self.anonymization_method,
                          self.anonymization_salt),
            # Others information
            'method':
            method,
            'protocol':
            req.environ.get('SERVER_PROTOCOL'),
            'status_int':
            status_int,
            'auth_token':
            self.obscure_sensitive(req.headers.get('x-auth-token')),
            'bytes_recvd':
            bytes_received,
            'bytes_sent':
            bytes_sent,
            'transaction_id':
            req.environ.get('swift.trans_id'),
            'request_time':
            duration_time_str,
            'source':
            req.environ.get('swift.source'),
            'log_info':
            ','.join(req.environ.get('swift.log_info', '')),
            'policy_index':
            policy_index,
            'ttfb':
            ttfb,
            'pid':
            self.pid,
            'wire_status_int':
            wire_status_int or status_int,
        }
        self.access_logger.info(
            self.log_formatter.format(self.log_msg_template, **replacements))

        # Log timing and bytes-transferred data to StatsD
        metric_name = self.statsd_metric_name(req, status_int, method)
        metric_name_policy = self.statsd_metric_name_policy(
            req, status_int, method, policy_index)
        # Only log data for valid controllers (or SOS) to keep the metric count
        # down (egregious errors will get logged by the proxy server itself).

        if metric_name:
            self.access_logger.timing(metric_name + '.timing',
                                      (end_time - start_time) * 1000)
            self.access_logger.update_stats(metric_name + '.xfer',
                                            bytes_received + bytes_sent)
        if metric_name_policy:
            self.access_logger.timing(metric_name_policy + '.timing',
                                      (end_time - start_time) * 1000)
            self.access_logger.update_stats(metric_name_policy + '.xfer',
                                            bytes_received + bytes_sent)
Exemple #7
0
    def log_request(self, req, status_int, bytes_received, bytes_sent,
                    start_time, end_time, resp_headers=None):
        """
        Log a request.

        :param req: swob.Request object for the request
        :param status_int: integer code for the response status
        :param bytes_received: bytes successfully read from the request body
        :param bytes_sent: bytes yielded to the WSGI server
        :param start_time: timestamp request started
        :param end_time: timestamp request completed
        :param resp_headers: dict of the response headers
        """
        resp_headers = resp_headers or {}
        logged_headers = None
        if self.log_hdrs:
            if self.log_hdrs_only:
                logged_headers = '\n'.join('%s: %s' % (k, v)
                                           for k, v in req.headers.items()
                                           if k in self.log_hdrs_only)
            else:
                logged_headers = '\n'.join('%s: %s' % (k, v)
                                           for k, v in req.headers.items())

        method = self.method_from_req(req)
        duration_time_str = "%.4f" % (end_time - start_time)
        policy_index = get_policy_index(req.headers, resp_headers)

        acc, cont, obj = None, None, None
        if req.path.startswith('/v1/'):
            _, acc, cont, obj = split_path(req.path, 1, 4, True)

        replacements = {
            # Time information
            'end_time': StrFormatTime(end_time),
            'start_time': StrFormatTime(start_time),
            # Information worth to anonymize
            'client_ip': StrAnonymizer(get_remote_client(req),
                                       self.anonymization_method,
                                       self.anonymization_salt),
            'remote_addr': StrAnonymizer(req.remote_addr,
                                         self.anonymization_method,
                                         self.anonymization_salt),
            'path': StrAnonymizer(req.path_qs, self.anonymization_method,
                                  self.anonymization_salt),
            'referer': StrAnonymizer(req.referer, self.anonymization_method,
                                     self.anonymization_salt),
            'user_agent': StrAnonymizer(req.user_agent,
                                        self.anonymization_method,
                                        self.anonymization_salt),
            'headers': StrAnonymizer(logged_headers, self.anonymization_method,
                                     self.anonymization_salt),
            'client_etag': StrAnonymizer(req.headers.get('etag'),
                                         self.anonymization_method,
                                         self.anonymization_salt),
            'account': StrAnonymizer(acc, self.anonymization_method,
                                     self.anonymization_salt),
            'container': StrAnonymizer(cont, self.anonymization_method,
                                       self.anonymization_salt),
            'object': StrAnonymizer(obj, self.anonymization_method,
                                    self.anonymization_salt),
            # Others information
            'method': method,
            'protocol':
                req.environ.get('SERVER_PROTOCOL'),
            'status_int': status_int,
            'auth_token':
                self.obscure_sensitive(
                    req.headers.get('x-auth-token')),
            'bytes_recvd': bytes_received,
            'bytes_sent': bytes_sent,
            'transaction_id': req.environ.get('swift.trans_id'),
            'request_time': duration_time_str,
            'source': req.environ.get('swift.source'),
            'log_info':
                ','.join(req.environ.get('swift.log_info', '')),
            'policy_index': policy_index,
        }
        self.access_logger.info(
            self.log_formatter.format(self.log_msg_template,
                                      **replacements))

        # Log timing and bytes-transferred data to StatsD
        metric_name = self.statsd_metric_name(req, status_int, method)
        metric_name_policy = self.statsd_metric_name_policy(req, status_int,
                                                            method,
                                                            policy_index)
        # Only log data for valid controllers (or SOS) to keep the metric count
        # down (egregious errors will get logged by the proxy server itself).

        if metric_name:
            self.access_logger.timing(metric_name + '.timing',
                                      (end_time - start_time) * 1000)
            self.access_logger.update_stats(metric_name + '.xfer',
                                            bytes_received + bytes_sent)
        if metric_name_policy:
            self.access_logger.timing(metric_name_policy + '.timing',
                                      (end_time - start_time) * 1000)
            self.access_logger.update_stats(metric_name_policy + '.xfer',
                                            bytes_received + bytes_sent)