diff --git a/doc/source/logs.rst b/doc/source/logs.rst index 56f0588f1b..c2981aac34 100644 --- a/doc/source/logs.rst +++ b/doc/source/logs.rst @@ -100,6 +100,7 @@ these log lines is:: remote_addr - - [datetime] "request_method request_path" status_int content_length "referer" "transaction_id" "user_agent" request_time + additional_info =================== ========================================================== **Log Field** **Value** @@ -117,4 +118,5 @@ user_agent The value of the HTTP User-Agent header. Swift's proxy server sets its user-agent to ``"proxy-server ".`` request_time The duration of the request. +additional_info Additional useful information. =================== ========================================================== diff --git a/swift/account/server.py b/swift/account/server.py index 83a2bff79f..919b51bbfd 100644 --- a/swift/account/server.py +++ b/swift/account/server.py @@ -28,7 +28,7 @@ from swift.common.request_helpers import get_param, get_listing_content_type, \ split_and_validate_path from swift.common.utils import get_logger, hash_path, public, \ normalize_timestamp, storage_directory, config_true_value, \ - json, timing_stats, replication + json, timing_stats, replication, get_log_line from swift.common.constraints import check_mount, check_float, check_utf8 from swift.common import constraints from swift.common.db_replicator import ReplicatorRpc @@ -290,21 +290,13 @@ class AccountController(object): ' %(path)s '), {'method': req.method, 'path': req.path}) res = HTTPInternalServerError(body=traceback.format_exc()) - trans_time = '%.4f' % (time.time() - start_time) - additional_info = '' - if res.headers.get('x-container-timestamp') is not None: - additional_info += 'x-container-timestamp: %s' % \ - res.headers['x-container-timestamp'] if self.log_requests: - log_msg = '%s - - [%s] "%s %s" %s %s "%s" "%s" "%s" %s "%s"' % ( - req.remote_addr, - time.strftime('%d/%b/%Y:%H:%M:%S +0000', time.gmtime()), - req.method, req.path, - res.status.split()[0], res.content_length or '-', - req.headers.get('x-trans-id', '-'), - req.referer or '-', req.user_agent or '-', - trans_time, - additional_info) + trans_time = time.time() - start_time + additional_info = '' + if res.headers.get('x-container-timestamp') is not None: + additional_info += 'x-container-timestamp: %s' % \ + res.headers['x-container-timestamp'] + log_msg = get_log_line(req, res, trans_time, additional_info) if req.method.upper() == 'REPLICATE': self.logger.debug(log_msg) else: diff --git a/swift/common/utils.py b/swift/common/utils.py index 5281be9410..c1f0a1031e 100644 --- a/swift/common/utils.py +++ b/swift/common/utils.py @@ -292,6 +292,28 @@ def generate_trans_id(trans_id_suffix): uuid.uuid4().hex[:21], time.time(), trans_id_suffix) +def get_log_line(req, res, trans_time, additional_info): + """ + Make a line for logging that matches the documented log line format + for backend servers. + + :param req: the request. + :param res: the response. + :param trans_time: the time the request took to complete, a float. + :param additional_info: a string to log at the end of the line + + :returns: a properly formated line for logging. + """ + + return '%s - - [%s] "%s %s" %s %s "%s" "%s" "%s" %.4f "%s"' % ( + req.remote_addr, + time.strftime('%d/%b/%Y:%H:%M:%S +0000', time.gmtime()), + req.method, req.path, res.status.split()[0], + res.content_length or '-', req.referer or '-', + req.headers.get('x-trans-id', '-'), + req.user_agent or '-', trans_time, additional_info or '-') + + def get_trans_id_time(trans_id): if len(trans_id) >= 34 and trans_id[:2] == 'tx' and trans_id[23] == '-': try: diff --git a/swift/container/server.py b/swift/container/server.py index 380bb39ca1..784ee7fe42 100644 --- a/swift/container/server.py +++ b/swift/container/server.py @@ -31,7 +31,7 @@ from swift.common.request_helpers import get_param, get_listing_content_type, \ from swift.common.utils import get_logger, hash_path, public, \ normalize_timestamp, storage_directory, validate_sync_to, \ config_true_value, json, timing_stats, replication, \ - override_bytes_from_content_type + override_bytes_from_content_type, get_log_line from swift.common.constraints import check_mount, check_float, check_utf8 from swift.common import constraints from swift.common.bufferedhttp import http_connect @@ -504,17 +504,9 @@ class ContainerController(object): 'ERROR __call__ error with %(method)s %(path)s '), {'method': req.method, 'path': req.path}) res = HTTPInternalServerError(body=traceback.format_exc()) - trans_time = '%.4f' % (time.time() - start_time) if self.log_requests: - log_message = '%s - - [%s] "%s %s" %s %s "%s" "%s" "%s" %s' % ( - req.remote_addr, - time.strftime('%d/%b/%Y:%H:%M:%S +0000', - time.gmtime()), - req.method, req.path, - res.status.split()[0], res.content_length or '-', - req.headers.get('x-trans-id', '-'), - req.referer or '-', req.user_agent or '-', - trans_time) + trans_time = time.time() - start_time + log_message = get_log_line(req, res, trans_time, '') if req.method.upper() == 'REPLICATE': self.logger.debug(log_message) else: diff --git a/swift/obj/server.py b/swift/obj/server.py index 025c6f15ba..2c8214e07f 100644 --- a/swift/obj/server.py +++ b/swift/obj/server.py @@ -29,7 +29,8 @@ from hashlib import md5 from eventlet import sleep, Timeout from swift.common.utils import public, get_logger, \ - config_true_value, timing_stats, replication, normalize_delete_at_timestamp + config_true_value, timing_stats, replication, \ + normalize_delete_at_timestamp, get_log_line from swift.common.bufferedhttp import http_connect from swift.common.constraints import check_object_creation, \ check_float, check_utf8 @@ -680,15 +681,7 @@ class ObjectController(object): res = HTTPInternalServerError(body=traceback.format_exc()) trans_time = time.time() - start_time if self.log_requests: - log_line = '%s - - [%s] "%s %s" %s %s "%s" "%s" "%s" %.4f' % ( - req.remote_addr, - time.strftime('%d/%b/%Y:%H:%M:%S +0000', - time.gmtime()), - req.method, req.path, res.status.split()[0], - res.content_length or '-', req.referer or '-', - req.headers.get('x-trans-id', '-'), - req.user_agent or '-', - trans_time) + log_line = get_log_line(req, res, trans_time, '') if req.method in ('REPLICATE', 'REPLICATION') or \ 'X-Backend-Replication' in req.headers: self.logger.debug(log_line) diff --git a/test/unit/account/test_server.py b/test/unit/account/test_server.py index ca9d6f6c87..9e6cc0d7de 100644 --- a/test/unit/account/test_server.py +++ b/test/unit/account/test_server.py @@ -20,6 +20,7 @@ import unittest from tempfile import mkdtemp from shutil import rmtree from StringIO import StringIO +from time import gmtime from test.unit import FakeLogger import simplejson @@ -1653,6 +1654,22 @@ class TestAccountController(unittest.TestCase): self.assertEqual(resp.status_int, 404) self.assertFalse(self.controller.logger.log_dict['info']) + def test_log_line_format(self): + req = Request.blank( + '/sda1/p/a', + environ={'REQUEST_METHOD': 'HEAD', 'REMOTE_ADDR': '1.2.3.4'}) + self.controller.logger = FakeLogger() + with mock.patch( + 'time.gmtime', mock.MagicMock(side_effect=[gmtime(10001.0)])): + with mock.patch( + 'time.time', + mock.MagicMock(side_effect=[10000.0, 10001.0, 10002.0])): + req.get_response(self.controller) + self.assertEqual( + self.controller.logger.log_dict['info'], + [(('1.2.3.4 - - [01/Jan/1970:02:46:41 +0000] "HEAD /sda1/p/a" 404 ' + '- "-" "-" "-" 2.0000 "-"',), {})]) + if __name__ == '__main__': unittest.main() diff --git a/test/unit/common/test_utils.py b/test/unit/common/test_utils.py index 2996f35557..f8849821d3 100644 --- a/test/unit/common/test_utils.py +++ b/test/unit/common/test_utils.py @@ -24,6 +24,7 @@ import eventlet.event import grp import logging import os +import mock import random import re import socket @@ -55,7 +56,7 @@ from swift.common.exceptions import (Timeout, MessageTimeout, ReplicationLockTimeout) from swift.common import utils from swift.common.container_sync_realms import ContainerSyncRealms -from swift.common.swob import Response +from swift.common.swob import Request, Response from test.unit import FakeLogger @@ -1893,6 +1894,22 @@ cluster_dfw1 = http://dfw1.host/v1/ utils.get_hmac('GET', '/path', 1, 'abc'), 'b17f6ff8da0e251737aa9e3ee69a881e3e092e2f') + def test_get_log_line(self): + req = Request.blank( + '/sda1/p/a/c/o', + environ={'REQUEST_METHOD': 'HEAD', 'REMOTE_ADDR': '1.2.3.4'}) + res = Response() + trans_time = 1.2 + additional_info = 'some information' + exp_line = '1.2.3.4 - - [01/Jan/1970:02:46:41 +0000] "HEAD ' \ + '/sda1/p/a/c/o" 200 - "-" "-" "-" 1.2000 "some information"' + with mock.patch( + 'time.gmtime', + mock.MagicMock(side_effect=[time.gmtime(10001.0)])): + self.assertEquals( + exp_line, + utils.get_log_line(req, res, trans_time, additional_info)) + class TestSwiftInfo(unittest.TestCase): diff --git a/test/unit/container/test_server.py b/test/unit/container/test_server.py index 628308117a..4fd319ab90 100644 --- a/test/unit/container/test_server.py +++ b/test/unit/container/test_server.py @@ -22,6 +22,7 @@ from shutil import rmtree from StringIO import StringIO from tempfile import mkdtemp from test.unit import FakeLogger +from time import gmtime from xml.dom import minidom from eventlet import spawn, Timeout, listen @@ -1956,6 +1957,22 @@ class TestContainerController(unittest.TestCase): self.assertEqual(resp.status_int, 404) self.assertFalse(self.controller.logger.log_dict['info']) + def test_log_line_format(self): + req = Request.blank( + '/sda1/p/a/c', + environ={'REQUEST_METHOD': 'HEAD', 'REMOTE_ADDR': '1.2.3.4'}) + self.controller.logger = FakeLogger() + with mock.patch( + 'time.gmtime', mock.MagicMock(side_effect=[gmtime(10001.0)])): + with mock.patch( + 'time.time', + mock.MagicMock(side_effect=[10000.0, 10001.0, 10002.0])): + req.get_response(self.controller) + self.assertEqual( + self.controller.logger.log_dict['info'], + [(('1.2.3.4 - - [01/Jan/1970:02:46:41 +0000] "HEAD /sda1/p/a/c" ' + '404 - "-" "-" "-" 2.0000 "-"',), {})]) + if __name__ == '__main__': unittest.main() diff --git a/test/unit/obj/test_server.py b/test/unit/obj/test_server.py index c21bf222fa..1614783d4c 100755 --- a/test/unit/obj/test_server.py +++ b/test/unit/obj/test_server.py @@ -3385,7 +3385,7 @@ class TestObjectController(unittest.TestCase): self.assertEqual( self.object_controller.logger.log_dict['info'], [(('None - - [01/Jan/1970:02:46:41 +0000] "PUT' - ' /sda1/p/a/c/o" 405 - "-" "-" "-" 1.0000',), + ' /sda1/p/a/c/o" 405 - "-" "-" "-" 1.0000 "-"',), {})]) def test_not_utf8_and_not_logging_requests(self): @@ -3519,6 +3519,22 @@ class TestObjectController(unittest.TestCase): self.assertEqual( self.object_controller.logger.log_dict['info'], []) + def test_log_line_format(self): + req = Request.blank( + '/sda1/p/a/c/o', + environ={'REQUEST_METHOD': 'HEAD', 'REMOTE_ADDR': '1.2.3.4'}) + self.object_controller.logger = FakeLogger() + with mock.patch( + 'time.gmtime', mock.MagicMock(side_effect=[gmtime(10001.0)])): + with mock.patch( + 'time.time', + mock.MagicMock(side_effect=[10000.0, 10001.0, 10002.0])): + req.get_response(self.object_controller) + self.assertEqual( + self.object_controller.logger.log_dict['info'], + [(('1.2.3.4 - - [01/Jan/1970:02:46:41 +0000] "HEAD /sda1/p/a/c/o" ' + '404 - "-" "-" "-" 2.0000 "-"',), {})]) + if __name__ == '__main__': unittest.main()