openstack/swift
Code Issues Proposed changes

Unify backend logging

Browse Source 
Make account, object, and container servers construct log lines using the
same utility function so they will produce identically formatted lines.

This change reorders the fields logged for the account server.

This change also adds the "additional info" field to the two servers that
didn't log that field.  This makes the log lines identical across all 3
servers.  If people don't like that, I can take that out.  I think it makes
the documentation, parsing of the log lines, and the code a tad cleaner.

DocImpact

Change-Id: I268dc0df9dd07afa5382592a28ea37b96c6c2f44
Closes-Bug: 1280955
This commit is contained in:
Greg Lange 2014-03-26 22:55:55 +00:00
parent 0e366aa922
commit d32dc8d49c
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()