openstack/swift
Code Issues Proposed changes

Merge "Unify backend logging"

Browse Source
This commit is contained in:
Jenkins 2014-04-08 17:56:58 +00:00 committed by Gerrit Code Review
commit 7060355988
9 changed files with 106 additions and 38 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
doc/source/logs.rst
View File

@ -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 <pid of the proxy>".``
request_time The duration of the request.
additional_info Additional useful information.
=================== ==========================================================

22
swift/account/server.py
View File

@ -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:

22
swift/common/utils.py
View File

@ -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:

14
swift/container/server.py
View File

@ -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:

13
swift/obj/server.py
View File

@ -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)

17
test/unit/account/test_server.py
View File

@ -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()

19
test/unit/common/test_utils.py
View File

@ -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):

17
test/unit/container/test_server.py
View File

@ -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()

18
test/unit/obj/test_server.py
View File

@ -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()