From 67de0c88f456a5bd8a812fc8cbfd7fad209a7ab4 Mon Sep 17 00:00:00 2001 From: Michael Barton Date: Sun, 16 Jan 2011 09:52:08 +0000 Subject: [PATCH 01/25] ipv6 support --- bin/swauth-add-account | 2 +- bin/swauth-add-user | 2 +- bin/swauth-delete-account | 2 +- bin/swauth-delete-user | 2 +- bin/swauth-list | 2 +- bin/swauth-prep | 2 +- bin/swauth-set-account-service | 2 +- bin/swift-ring-builder | 13 +++++++-- etc/proxy-server.conf-sample | 4 +-- swift/auth/server.py | 3 +- swift/common/bench.py | 3 +- swift/common/middleware/acl.py | 2 +- swift/common/middleware/swauth.py | 15 +++++----- swift/common/utils.py | 33 ++++++++++++++++++++++ swift/common/wsgi.py | 6 +++- swift/container/server.py | 2 +- swift/obj/server.py | 2 +- test/unit/common/middleware/test_swauth.py | 18 ++++++------ test/unit/common/test_utils.py | 21 ++++++++++++++ 19 files changed, 99 insertions(+), 37 deletions(-) diff --git a/bin/swauth-add-account b/bin/swauth-add-account index 32aceffc7b..fe18b5a72d 100755 --- a/bin/swauth-add-account +++ b/bin/swauth-add-account @@ -18,9 +18,9 @@ import gettext from optparse import OptionParser from os.path import basename from sys import argv, exit -from urlparse import urlparse from swift.common.bufferedhttp import http_connect_raw as http_connect +from swift.common.utils import urlparse if __name__ == '__main__': diff --git a/bin/swauth-add-user b/bin/swauth-add-user index a844ed2a37..045dc0a766 100755 --- a/bin/swauth-add-user +++ b/bin/swauth-add-user @@ -18,9 +18,9 @@ import gettext from optparse import OptionParser from os.path import basename from sys import argv, exit -from urlparse import urlparse from swift.common.bufferedhttp import http_connect_raw as http_connect +from swift.common.utils import urlparse if __name__ == '__main__': diff --git a/bin/swauth-delete-account b/bin/swauth-delete-account index c46e5e3b91..3d98f6ec4e 100755 --- a/bin/swauth-delete-account +++ b/bin/swauth-delete-account @@ -18,9 +18,9 @@ import gettext from optparse import OptionParser from os.path import basename from sys import argv, exit -from urlparse import urlparse from swift.common.bufferedhttp import http_connect_raw as http_connect +from swift.common.utils import urlparse if __name__ == '__main__': diff --git a/bin/swauth-delete-user b/bin/swauth-delete-user index 5ee162437c..ede076dd5b 100755 --- a/bin/swauth-delete-user +++ b/bin/swauth-delete-user @@ -18,9 +18,9 @@ import gettext from optparse import OptionParser from os.path import basename from sys import argv, exit -from urlparse import urlparse from swift.common.bufferedhttp import http_connect_raw as http_connect +from swift.common.utils import urlparse if __name__ == '__main__': diff --git a/bin/swauth-list b/bin/swauth-list index 7433e3ddfd..85a7633966 100755 --- a/bin/swauth-list +++ b/bin/swauth-list @@ -22,9 +22,9 @@ import gettext from optparse import OptionParser from os.path import basename from sys import argv, exit -from urlparse import urlparse from swift.common.bufferedhttp import http_connect_raw as http_connect +from swift.common.utils import urlparse if __name__ == '__main__': diff --git a/bin/swauth-prep b/bin/swauth-prep index 5a931ae1d0..3d2cb7d3eb 100755 --- a/bin/swauth-prep +++ b/bin/swauth-prep @@ -18,9 +18,9 @@ import gettext from optparse import OptionParser from os.path import basename from sys import argv, exit -from urlparse import urlparse from swift.common.bufferedhttp import http_connect_raw as http_connect +from swift.common.utils import urlparse if __name__ == '__main__': diff --git a/bin/swauth-set-account-service b/bin/swauth-set-account-service index 32eb06dc6b..054e4cfc4b 100755 --- a/bin/swauth-set-account-service +++ b/bin/swauth-set-account-service @@ -22,9 +22,9 @@ import gettext from optparse import OptionParser from os.path import basename from sys import argv, exit -from urlparse import urlparse from swift.common.bufferedhttp import http_connect_raw as http_connect +from swift.common.utils import urlparse if __name__ == '__main__': diff --git a/bin/swift-ring-builder b/bin/swift-ring-builder index c448bea5ca..41293f7d37 100755 --- a/bin/swift-ring-builder +++ b/bin/swift-ring-builder @@ -235,10 +235,17 @@ swift-ring-builder add z-:/_ print 'Invalid add value: %s' % argv[3] exit(EXIT_ERROR) i = 1 - while i < len(rest) and rest[i] in '0123456789.': + if rest[i] == '[': + while i < len(rest) and rest[i] != ']': + i += 1 + ip = rest[2:i] i += 1 - ip = rest[1:i] - rest = rest[i:] + rest = rest[i:] + else: + while i < len(rest) and rest[i] in '0123456789.': + i += 1 + ip = rest[1:i] + rest = rest[i:] if not rest.startswith(':'): print 'Invalid add value: %s' % argv[3] diff --git a/etc/proxy-server.conf-sample b/etc/proxy-server.conf-sample index fda7d0d034..2d85f19508 100644 --- a/etc/proxy-server.conf-sample +++ b/etc/proxy-server.conf-sample @@ -68,13 +68,13 @@ use = egg:swift#swauth # auth_prefix = /auth/ # Cluster strings are of the format name:url where name is a short name for the # Swift cluster and url is the url to the proxy server(s) for the cluster. -# default_swift_cluster = local:http://127.0.0.1:8080/v1 +# default_swift_cluster = local#http://127.0.0.1:8080/v1 # You may also use the format name::url::url where the first url is the one # given to users to access their account (public url) and the second is the one # used by swauth itself to create and delete accounts (private url). This is # useful when a load balancer url should be used by users, but swauth itself is # behind the load balancer. Example: -# default_swift_cluster = local::https://public.com:8080/v1::http://private.com:8080/v1 +# default_swift_cluster = local##https://public.com:8080/v1##http://private.com:8080/v1 # token_life = 86400 # node_timeout = 10 # Highly recommended to change this. diff --git a/swift/auth/server.py b/swift/auth/server.py index a0bd31ccda..967f853291 100644 --- a/swift/auth/server.py +++ b/swift/auth/server.py @@ -20,7 +20,6 @@ from contextlib import contextmanager from time import gmtime, strftime, time from urllib import unquote, quote from uuid import uuid4 -from urlparse import urlparse from hashlib import md5, sha1 import hmac import base64 @@ -32,7 +31,7 @@ from webob.exc import HTTPBadRequest, HTTPConflict, HTTPForbidden, \ from swift.common.bufferedhttp import http_connect_raw as http_connect from swift.common.db import get_db_connection -from swift.common.utils import get_logger, split_path +from swift.common.utils import get_logger, split_path, urlparse class AuthController(object): diff --git a/swift/common/bench.py b/swift/common/bench.py index 4abafeb947..169497ef13 100644 --- a/swift/common/bench.py +++ b/swift/common/bench.py @@ -16,13 +16,12 @@ import uuid import time import random -from urlparse import urlparse from contextlib import contextmanager import eventlet.pools from eventlet.green.httplib import CannotSendRequest -from swift.common.utils import TRUE_VALUES +from swift.common.utils import TRUE_VALUES, urlparse from swift.common import client from swift.common import direct_client diff --git a/swift/common/middleware/acl.py b/swift/common/middleware/acl.py index f6784953ac..f08780eedb 100644 --- a/swift/common/middleware/acl.py +++ b/swift/common/middleware/acl.py @@ -13,7 +13,7 @@ # See the License for the specific language governing permissions and # limitations under the License. -from urlparse import urlparse +from swift.common.utils import urlparse def clean_acl(name, value): diff --git a/swift/common/middleware/swauth.py b/swift/common/middleware/swauth.py index 961f3a3ba4..568b00fb35 100644 --- a/swift/common/middleware/swauth.py +++ b/swift/common/middleware/swauth.py @@ -21,7 +21,6 @@ from httplib import HTTPConnection, HTTPSConnection from time import gmtime, strftime, time from traceback import format_exc from urllib import quote, unquote -from urlparse import urlparse from uuid import uuid4 from eventlet.timeout import Timeout @@ -32,7 +31,7 @@ from webob.exc import HTTPAccepted, HTTPBadRequest, HTTPConflict, \ from swift.common.bufferedhttp import http_connect_raw as http_connect from swift.common.middleware.acl import clean_acl, parse_acl, referrer_allowed -from swift.common.utils import cache_from_env, get_logger, split_path +from swift.common.utils import cache_from_env, get_logger, split_path, urlparse class Swauth(object): @@ -61,23 +60,23 @@ class Swauth(object): self.auth_prefix += '/' self.auth_account = '%s.auth' % self.reseller_prefix self.default_swift_cluster = conf.get('default_swift_cluster', - 'local:http://127.0.0.1:8080/v1') + 'local#http://127.0.0.1:8080/v1') # This setting is a little messy because of the options it has to # provide. The basic format is cluster_name:url, such as the default - # value of local:http://127.0.0.1:8080/v1. But, often the url given to + # value of local#http://127.0.0.1:8080/v1. But, often the url given to # the user needs to be different than the url used by Swauth to # create/delete accounts. So there's a more complex format of # cluster_name::url::url, such as - # local::https://public.com:8080/v1::http://private.com:8080/v1. + # local##https://public.com:8080/v1##http://private.com:8080/v1. # The double colon is what sets the two apart. - if '::' in self.default_swift_cluster: + if '##' in self.default_swift_cluster: self.dsc_name, self.dsc_url, self.dsc_url2 = \ - self.default_swift_cluster.split('::', 2) + self.default_swift_cluster.split('##', 2) self.dsc_url = self.dsc_url.rstrip('/') self.dsc_url2 = self.dsc_url2.rstrip('/') else: self.dsc_name, self.dsc_url = \ - self.default_swift_cluster.split(':', 1) + self.default_swift_cluster.split('#', 1) self.dsc_url = self.dsc_url2 = self.dsc_url.rstrip('/') self.dsc_parsed = urlparse(self.dsc_url) if self.dsc_parsed.scheme not in ('http', 'https'): diff --git a/swift/common/utils.py b/swift/common/utils.py index 299980493a..05b15e99fa 100644 --- a/swift/common/utils.py +++ b/swift/common/utils.py @@ -34,6 +34,7 @@ from ConfigParser import ConfigParser, NoSectionError, NoOptionError from optparse import OptionParser from tempfile import mkstemp import cPickle as pickle +from urlparse import urlparse as stdlib_urlparse, ParseResult import eventlet from eventlet import greenio, GreenPool, sleep, Timeout, listen @@ -845,3 +846,35 @@ def ratelimit_sleep(running_time, max_rate, incr_by=1): elif running_time - now > time_per_request: eventlet.sleep((running_time - now) / clock_accuracy) return running_time + time_per_request + + +class ModifiedParseResult(ParseResult): + "Parse results class for urlparse." + + @property + def hostname(self): + netloc = self.netloc.split('@', 1)[-1] + if netloc.startswith('['): + return netloc[1:].split(']')[0] + elif ':' in netloc: + return netloc.rsplit(':')[0] + return netloc + + @property + def port(self): + netloc = self.netloc.split('@', 1)[-1] + if netloc.startswith('['): + netloc = netloc.rsplit(']')[1] + if ':' in netloc: + return int(netloc.rsplit(':')[1]) + return None + + +def urlparse(url): + """ + urlparse augmentation. + This is necessary because urlparse can't handle RFC 2732 URLs. + + :param url: URL to parse. + """ + return ModifiedParseResult(*stdlib_urlparse(url)) diff --git a/swift/common/wsgi.py b/swift/common/wsgi.py index 9450bcf439..cedc4b2c8b 100644 --- a/swift/common/wsgi.py +++ b/swift/common/wsgi.py @@ -68,11 +68,15 @@ def get_socket(conf, default_port=8080): """ bind_addr = (conf.get('bind_ip', '0.0.0.0'), int(conf.get('bind_port', default_port))) + address_family = [addr[0] for addr in socket.getaddrinfo(bind_addr[0], + bind_addr[1], socket.AF_UNSPEC, socket.SOCK_STREAM) + if addr[0] in (socket.AF_INET, socket.AF_INET6)][0] sock = None retry_until = time.time() + 30 while not sock and time.time() < retry_until: try: - sock = listen(bind_addr, backlog=int(conf.get('backlog', 4096))) + sock = listen(bind_addr, backlog=int(conf.get('backlog', 4096)), + family=address_family) if 'cert_file' in conf: sock = ssl.wrap_socket(sock, certfile=conf['cert_file'], keyfile=conf['key_file']) diff --git a/swift/container/server.py b/swift/container/server.py index 7ba375ce33..1ffba8a909 100644 --- a/swift/container/server.py +++ b/swift/container/server.py @@ -88,7 +88,7 @@ class ContainerController(object): account_partition = req.headers.get('X-Account-Partition') account_device = req.headers.get('X-Account-Device') if all([account_host, account_partition, account_device]): - account_ip, account_port = account_host.split(':') + account_ip, account_port = account_host.rsplit(':', 1) new_path = '/' + '/'.join([account, container]) info = broker.get_info() account_headers = {'x-put-timestamp': info['put_timestamp'], diff --git a/swift/obj/server.py b/swift/obj/server.py index 4afc38057d..f20b40d57a 100644 --- a/swift/obj/server.py +++ b/swift/obj/server.py @@ -294,7 +294,7 @@ class ObjectController(object): full_path = '/%s/%s/%s' % (account, container, obj) try: with ConnectionTimeout(self.conn_timeout): - ip, port = host.split(':') + ip, port = host.rsplit(':', 1) conn = http_connect(ip, port, contdevice, partition, op, full_path, headers_out) with Timeout(self.node_timeout): diff --git a/test/unit/common/middleware/test_swauth.py b/test/unit/common/middleware/test_swauth.py index 00c010b9dc..a6edab9c2c 100644 --- a/test/unit/common/middleware/test_swauth.py +++ b/test/unit/common/middleware/test_swauth.py @@ -151,21 +151,21 @@ class TestAuth(unittest.TestCase): app = FakeApp() self.assertRaises(Exception, auth.filter_factory({ 'super_admin_key': 'supertest', - 'default_swift_cluster': 'local:badscheme://host/path'}), app) + 'default_swift_cluster': 'local#badscheme://host/path'}), app) ath = auth.filter_factory({'super_admin_key': 'supertest'})(app) self.assertEquals(ath.default_swift_cluster, - 'local:http://127.0.0.1:8080/v1') + 'local#http://127.0.0.1:8080/v1') ath = auth.filter_factory({'super_admin_key': 'supertest', - 'default_swift_cluster': 'local:http://host/path'})(app) + 'default_swift_cluster': 'local#http://host/path'})(app) self.assertEquals(ath.default_swift_cluster, - 'local:http://host/path') + 'local#http://host/path') ath = auth.filter_factory({'super_admin_key': 'supertest', - 'default_swift_cluster': 'local:https://host/path/'})(app) + 'default_swift_cluster': 'local#https://host/path/'})(app) self.assertEquals(ath.dsc_url, 'https://host/path') self.assertEquals(ath.dsc_url2, 'https://host/path') ath = auth.filter_factory({'super_admin_key': 'supertest', 'default_swift_cluster': - 'local::https://host/path/::http://host2/path2/'})(app) + 'local##https://host/path/##http://host2/path2/'})(app) self.assertEquals(ath.dsc_url, 'https://host/path') self.assertEquals(ath.dsc_url2, 'http://host2/path2') @@ -2882,7 +2882,7 @@ class TestAuth(unittest.TestCase): def test_get_conn_default_https(self): local_auth = auth.filter_factory({'super_admin_key': 'supertest', - 'default_swift_cluster': 'local:https://1.2.3.4/v1'})(FakeApp()) + 'default_swift_cluster': 'local#https://1.2.3.4/v1'})(FakeApp()) conn = local_auth.get_conn() self.assertEquals(conn.__class__, auth.HTTPSConnection) self.assertEquals(conn.host, '1.2.3.4') @@ -2890,7 +2890,7 @@ class TestAuth(unittest.TestCase): def test_get_conn_overridden(self): local_auth = auth.filter_factory({'super_admin_key': 'supertest', - 'default_swift_cluster': 'local:https://1.2.3.4/v1'})(FakeApp()) + 'default_swift_cluster': 'local#https://1.2.3.4/v1'})(FakeApp()) conn = \ local_auth.get_conn(urlparsed=auth.urlparse('http://5.6.7.8/v1')) self.assertEquals(conn.__class__, auth.HTTPConnection) @@ -2899,7 +2899,7 @@ class TestAuth(unittest.TestCase): def test_get_conn_overridden_https(self): local_auth = auth.filter_factory({'super_admin_key': 'supertest', - 'default_swift_cluster': 'local:http://1.2.3.4/v1'})(FakeApp()) + 'default_swift_cluster': 'local#http://1.2.3.4/v1'})(FakeApp()) conn = \ local_auth.get_conn(urlparsed=auth.urlparse('https://5.6.7.8/v1')) self.assertEquals(conn.__class__, auth.HTTPSConnection) diff --git a/test/unit/common/test_utils.py b/test/unit/common/test_utils.py index 1f5a94edd5..b9e8a3f81b 100644 --- a/test/unit/common/test_utils.py +++ b/test/unit/common/test_utils.py @@ -477,6 +477,27 @@ log_name = yarr''' total += i self.assertTrue(abs(50 - (time.time() - start) * 100) < 10) + def test_urlparse(self): + parsed = utils.urlparse('http://127.0.0.1/') + self.assertEquals(parsed.scheme, 'http') + self.assertEquals(parsed.hostname, '127.0.0.1') + self.assertEquals(parsed.path, '/') + + parsed = utils.urlparse('http://127.0.0.1:8080/') + self.assertEquals(parsed.port, 8080) + + parsed = utils.urlparse('https://127.0.0.1/') + self.assertEquals(parsed.scheme, 'https') + + parsed = utils.urlparse('http://[::1]/') + self.assertEquals(parsed.hostname, '::1') + + parsed = utils.urlparse('http://[::1]:8080/') + self.assertEquals(parsed.hostname, '::1') + self.assertEquals(parsed.port, 8080) + + parsed = utils.urlparse('www.example.com') + self.assertEquals(parsed.hostname, '') if __name__ == '__main__': unittest.main() From a44635ca9767d8ee737e0189063cf3b5b3842285 Mon Sep 17 00:00:00 2001 From: Michael Barton Date: Sat, 29 Jan 2011 00:54:12 +0000 Subject: [PATCH 02/25] support WAL journaling instead of .pending files --- swift/common/db.py | 195 +++++++-------------------------------------- 1 file changed, 29 insertions(+), 166 deletions(-) diff --git a/swift/common/db.py b/swift/common/db.py index be96411619..36ef1f3c91 100644 --- a/swift/common/db.py +++ b/swift/common/db.py @@ -33,7 +33,7 @@ import simplejson as json import sqlite3 from swift.common.utils import normalize_timestamp, renamer, \ - mkdirs, lock_parent_directory, fallocate + mkdirs, lock_parent_directory from swift.common.exceptions import LockTimeout @@ -41,8 +41,7 @@ from swift.common.exceptions import LockTimeout BROKER_TIMEOUT = 25 #: Pickle protocol to use PICKLE_PROTOCOL = 2 -#: Max number of pending entries -PENDING_CAP = 131072 +PENDING_COMMIT_TIMEOUT = 900 class DatabaseConnectionError(sqlite3.DatabaseError): @@ -139,7 +138,7 @@ def get_db_connection(path, timeout=30, okay_to_create=False): conn.execute('PRAGMA synchronous = NORMAL') conn.execute('PRAGMA count_changes = OFF') conn.execute('PRAGMA temp_store = MEMORY') - conn.execute('PRAGMA journal_mode = DELETE') + conn.execute('PRAGMA journal_mode = WAL') conn.create_function('chexor', 3, chexor) except sqlite3.DatabaseError: import traceback @@ -152,13 +151,10 @@ class DatabaseBroker(object): """Encapsulates working with a database.""" def __init__(self, db_file, timeout=BROKER_TIMEOUT, logger=None, - account=None, container=None, pending_timeout=10, - stale_reads_ok=False): + account=None, container=None, stale_reads_ok=False): """ Encapsulates working with a database. """ self.conn = None self.db_file = db_file - self.pending_file = self.db_file + '.pending' - self.pending_timeout = pending_timeout self.stale_reads_ok = stale_reads_ok self.db_dir = os.path.dirname(db_file) self.timeout = timeout @@ -233,7 +229,7 @@ class DatabaseBroker(object): conn.close() with open(tmp_db_file, 'r+b') as fp: os.fsync(fp.fileno()) - with lock_parent_directory(self.db_file, self.pending_timeout): + with lock_parent_directory(self.db_file, self.timeout): if os.path.exists(self.db_file): # It's as if there was a "condition" where different parts # of the system were "racing" each other. @@ -348,11 +344,6 @@ class DatabaseBroker(object): :param count: number to get :returns: list of objects between start and end """ - try: - self._commit_puts() - except LockTimeout: - if not self.stale_reads_ok: - raise with self.get() as conn: curs = conn.execute(''' SELECT * FROM %s WHERE ROWID > ? ORDER BY ROWID ASC LIMIT ? @@ -401,11 +392,7 @@ class DatabaseBroker(object): :returns: dict containing keys: hash, id, created_at, put_timestamp, delete_timestamp, count, max_row, and metadata """ - try: - self._commit_puts() - except LockTimeout: - if not self.stale_reads_ok: - raise + self._commit_puts() query_part1 = ''' SELECT hash, id, created_at, put_timestamp, delete_timestamp, %s_count AS count, @@ -455,34 +442,6 @@ class DatabaseBroker(object): (rec['sync_point'], rec['remote_id'])) conn.commit() - def _preallocate(self): - """ - The idea is to allocate space in front of an expanding db. If it gets - within 512k of a boundary, it allocates to the next boundary. - Boundaries are 2m, 5m, 10m, 25m, 50m, then every 50m after. - """ - if self.db_file == ':memory:': - return - MB = (1024 * 1024) - - def prealloc_points(): - for pm in (1, 2, 5, 10, 25, 50): - yield pm * MB - while True: - pm += 50 - yield pm * MB - - stat = os.stat(self.db_file) - file_size = stat.st_size - allocated_size = stat.st_blocks * 512 - for point in prealloc_points(): - if file_size <= point - MB / 2: - prealloc_size = point - break - if allocated_size < prealloc_size: - with open(self.db_file, 'rb+') as fp: - fallocate(fp.fileno(), int(prealloc_size)) - @property def metadata(self): """ @@ -717,11 +676,6 @@ class ContainerBroker(DatabaseBroker): :returns: True if the database has no active objects, False otherwise """ - try: - self._commit_puts() - except LockTimeout: - if not self.stale_reads_ok: - raise with self.get() as conn: row = conn.execute( 'SELECT object_count from container_stat').fetchone() @@ -729,17 +683,16 @@ class ContainerBroker(DatabaseBroker): def _commit_puts(self, item_list=None): """Handles commiting rows in .pending files.""" - if self.db_file == ':memory:' or not os.path.exists(self.pending_file): + pending_file = self.db_file + '.pending' + if self.db_file == ':memory:' or not os.path.exists(pending_file): + return + if not os.path.getsize(pending_file): + os.unlink(pending_file) return if item_list is None: item_list = [] - with lock_parent_directory(self.pending_file, self.pending_timeout): - self._preallocate() - if not os.path.getsize(self.pending_file): - if item_list: - self.merge_items(item_list) - return - with open(self.pending_file, 'r+b') as fp: + with lock_parent_directory(pending_file, PENDING_COMMIT_TIMEOUT): + with open(pending_file, 'r+b') as fp: for entry in fp.read().split(':'): if entry: try: @@ -752,11 +705,11 @@ class ContainerBroker(DatabaseBroker): except Exception: self.logger.exception( _('Invalid pending entry %(file)s: %(entry)s'), - {'file': self.pending_file, 'entry': entry}) + {'file': pending_file, 'entry': entry}) if item_list: self.merge_items(item_list) try: - os.ftruncate(fp.fileno(), 0) + os.unlink(pending_file) except OSError, err: if err.errno != errno.ENOENT: raise @@ -774,7 +727,6 @@ class ContainerBroker(DatabaseBroker): delete :param sync_timestamp: max update_at timestamp of sync rows to delete """ - self._commit_puts() with self.get() as conn: conn.execute(""" DELETE FROM object @@ -818,30 +770,9 @@ class ContainerBroker(DatabaseBroker): record = {'name': name, 'created_at': timestamp, 'size': size, 'content_type': content_type, 'etag': etag, 'deleted': deleted} - if self.db_file == ':memory:': - self.merge_items([record]) - return - if not os.path.exists(self.db_file): + if self.db_file != ':memory:' and not os.path.exists(self.db_file): raise DatabaseConnectionError(self.db_file, "DB doesn't exist") - pending_size = 0 - try: - pending_size = os.path.getsize(self.pending_file) - except OSError, err: - if err.errno != errno.ENOENT: - raise - if pending_size > PENDING_CAP: - self._commit_puts([record]) - else: - with lock_parent_directory( - self.pending_file, self.pending_timeout): - with open(self.pending_file, 'a+b') as fp: - # Colons aren't used in base64 encoding; so they are our - # delimiter - fp.write(':') - fp.write(pickle.dumps( - (name, timestamp, size, content_type, etag, deleted), - protocol=PICKLE_PROTOCOL).encode('base64')) - fp.flush() + self.merge_items([record]) def is_deleted(self, timestamp=None): """ @@ -851,11 +782,6 @@ class ContainerBroker(DatabaseBroker): """ if self.db_file != ':memory:' and not os.path.exists(self.db_file): return True - try: - self._commit_puts() - except LockTimeout: - if not self.stale_reads_ok: - raise with self.get() as conn: row = conn.execute(''' SELECT put_timestamp, delete_timestamp, object_count @@ -878,11 +804,6 @@ class ContainerBroker(DatabaseBroker): reported_put_timestamp, reported_delete_timestamp, reported_object_count, reported_bytes_used, hash, id) """ - try: - self._commit_puts() - except LockTimeout: - if not self.stale_reads_ok: - raise with self.get() as conn: return conn.execute(''' SELECT account, container, created_at, put_timestamp, @@ -919,11 +840,6 @@ class ContainerBroker(DatabaseBroker): :returns: list of object names """ - try: - self._commit_puts() - except LockTimeout: - if not self.stale_reads_ok: - raise rv = [] with self.get() as conn: row = conn.execute(''' @@ -960,11 +876,6 @@ class ContainerBroker(DatabaseBroker): :returns: list of tuples of (name, created_at, size, content_type, etag) """ - try: - self._commit_puts() - except LockTimeout: - if not self.stale_reads_ok: - raise if path is not None: prefix = path if path: @@ -1193,17 +1104,16 @@ class AccountBroker(DatabaseBroker): def _commit_puts(self, item_list=None): """Handles commiting rows in .pending files.""" - if self.db_file == ':memory:' or not os.path.exists(self.pending_file): + pending_file = self.db_file + '.pending' + if self.db_file == ':memory:' or not os.path.exists(pending_file): + return + if not os.path.getsize(pending_file): + os.unlink(pending_file) return if item_list is None: item_list = [] - with lock_parent_directory(self.pending_file, self.pending_timeout): - self._preallocate() - if not os.path.getsize(self.pending_file): - if item_list: - self.merge_items(item_list) - return - with open(self.pending_file, 'r+b') as fp: + with lock_parent_directory(pending_file, PENDING_COMMIT_TIMEOUT): + with open(pending_file, 'r+b') as fp: for entry in fp.read().split(':'): if entry: try: @@ -1219,11 +1129,11 @@ class AccountBroker(DatabaseBroker): except Exception: self.logger.exception( _('Invalid pending entry %(file)s: %(entry)s'), - {'file': self.pending_file, 'entry': entry}) + {'file': pending_file, 'entry': entry}) if item_list: self.merge_items(item_list) try: - os.ftruncate(fp.fileno(), 0) + os.unlink(pending_file) except OSError, err: if err.errno != errno.ENOENT: raise @@ -1234,11 +1144,6 @@ class AccountBroker(DatabaseBroker): :returns: True if the database has no active containers. """ - try: - self._commit_puts() - except LockTimeout: - if not self.stale_reads_ok: - raise with self.get() as conn: row = conn.execute( 'SELECT container_count from account_stat').fetchone() @@ -1258,7 +1163,6 @@ class AccountBroker(DatabaseBroker): :param sync_timestamp: max update_at timestamp of sync rows to delete """ - self._commit_puts() with self.get() as conn: conn.execute(''' DELETE FROM container WHERE @@ -1286,11 +1190,6 @@ class AccountBroker(DatabaseBroker): :returns: put_timestamp of the container """ - try: - self._commit_puts() - except LockTimeout: - if not self.stale_reads_ok: - raise with self.get() as conn: ret = conn.execute(''' SELECT put_timestamp FROM container @@ -1311,6 +1210,8 @@ class AccountBroker(DatabaseBroker): :param object_count: number of objects in the container :param bytes_used: number of bytes used by the container """ + if self.db_file != ':memory:' and not os.path.exists(self.db_file): + raise DatabaseConnectionError(self.db_file, "DB doesn't exist") if delete_timestamp > put_timestamp and \ object_count in (None, '', 0, '0'): deleted = 1 @@ -1321,24 +1222,7 @@ class AccountBroker(DatabaseBroker): 'object_count': object_count, 'bytes_used': bytes_used, 'deleted': deleted} - if self.db_file == ':memory:': - self.merge_items([record]) - return - commit = False - with lock_parent_directory(self.pending_file, self.pending_timeout): - with open(self.pending_file, 'a+b') as fp: - # Colons aren't used in base64 encoding; so they are our - # delimiter - fp.write(':') - fp.write(pickle.dumps( - (name, put_timestamp, delete_timestamp, object_count, - bytes_used, deleted), - protocol=PICKLE_PROTOCOL).encode('base64')) - fp.flush() - if fp.tell() > PENDING_CAP: - commit = True - if commit: - self._commit_puts() + self.merge_items([record]) def can_delete_db(self, cutoff): """ @@ -1346,7 +1230,6 @@ class AccountBroker(DatabaseBroker): :returns: True if the account can be deleted, False otherwise """ - self._commit_puts() with self.get() as conn: row = conn.execute(''' SELECT status, put_timestamp, delete_timestamp, container_count @@ -1372,11 +1255,6 @@ class AccountBroker(DatabaseBroker): """ if self.db_file != ':memory:' and not os.path.exists(self.db_file): return True - try: - self._commit_puts() - except LockTimeout: - if not self.stale_reads_ok: - raise with self.get() as conn: row = conn.execute(''' SELECT put_timestamp, delete_timestamp, container_count, status @@ -1401,11 +1279,6 @@ class AccountBroker(DatabaseBroker): delete_timestamp, container_count, object_count, bytes_used, hash, id) """ - try: - self._commit_puts() - except LockTimeout: - if not self.stale_reads_ok: - raise with self.get() as conn: return conn.execute(''' SELECT account, created_at, put_timestamp, delete_timestamp, @@ -1422,11 +1295,6 @@ class AccountBroker(DatabaseBroker): :returns: list of container names """ - try: - self._commit_puts() - except LockTimeout: - if not self.stale_reads_ok: - raise rv = [] with self.get() as conn: row = conn.execute(''' @@ -1460,11 +1328,6 @@ class AccountBroker(DatabaseBroker): :returns: list of tuples of (name, object_count, bytes_used, 0) """ - try: - self._commit_puts() - except LockTimeout: - if not self.stale_reads_ok: - raise if delimiter and not prefix: prefix = '' orig_marker = marker From 4e100f6b325cbc5b2d83b4f3b622636ca25b069d Mon Sep 17 00:00:00 2001 From: Michael Barton Date: Sat, 29 Jan 2011 01:23:18 +0000 Subject: [PATCH 03/25] retry connect refactor --- swift/common/db.py | 49 +++++++++++++++++++++++++--------------------- 1 file changed, 27 insertions(+), 22 deletions(-) diff --git a/swift/common/db.py b/swift/common/db.py index 36ef1f3c91..ca667edf1a 100644 --- a/swift/common/db.py +++ b/swift/common/db.py @@ -27,6 +27,7 @@ import cPickle as pickle import errno from random import randint from tempfile import mkstemp +import traceback from eventlet import sleep import simplejson as json @@ -41,6 +42,7 @@ from swift.common.exceptions import LockTimeout BROKER_TIMEOUT = 25 #: Pickle protocol to use PICKLE_PROTOCOL = 2 +CONNECT_ATTEMPTS = 4 PENDING_COMMIT_TIMEOUT = 900 @@ -122,29 +124,32 @@ def get_db_connection(path, timeout=30, okay_to_create=False): :param okay_to_create: if True, create the DB if it doesn't exist :returns: DB connection object """ - try: - connect_time = time.time() - conn = sqlite3.connect(path, check_same_thread=False, - factory=GreenDBConnection, timeout=timeout) - if path != ':memory:' and not okay_to_create: + # retry logic to address: + # http://www.mail-archive.com/sqlite-users@sqlite.org/msg57092.html + for tries in xrange(1, CONNECT_ATTEMPTS + 1): + try: + connect_time = time.time() + conn = sqlite3.connect(path, check_same_thread=False, + factory=GreenDBConnection, timeout=timeout) # attempt to detect and fail when connect creates the db file - stat = os.stat(path) - if stat.st_size == 0 and stat.st_ctime >= connect_time: - os.unlink(path) - raise DatabaseConnectionError(path, - 'DB file created by connect?') - conn.row_factory = sqlite3.Row - conn.text_factory = str - conn.execute('PRAGMA synchronous = NORMAL') - conn.execute('PRAGMA count_changes = OFF') - conn.execute('PRAGMA temp_store = MEMORY') - conn.execute('PRAGMA journal_mode = WAL') - conn.create_function('chexor', 3, chexor) - except sqlite3.DatabaseError: - import traceback - raise DatabaseConnectionError(path, traceback.format_exc(), - timeout=timeout) - return conn + if path != ':memory:' and not okay_to_create: + stat = os.stat(path) + if stat.st_size == 0 and stat.st_ctime >= connect_time: + os.unlink(path) + raise DatabaseConnectionError(path, + 'DB file created by connect?') + conn.execute('PRAGMA synchronous = NORMAL') + conn.execute('PRAGMA count_changes = OFF') + conn.execute('PRAGMA temp_store = MEMORY') + conn.execute('PRAGMA journal_mode = WAL') + conn.create_function('chexor', 3, chexor) + conn.row_factory = sqlite3.Row + conn.text_factory = str + return conn + except sqlite3.DatabaseError, e: + if tries == CONNECT_ATTEMPTS or 'locking protocol' not in str(e): + raise DatabaseConnectionError(path, traceback.format_exc(), + timeout=timeout) class DatabaseBroker(object): From d83ce428afec5af180e5f85104da6242f8801fc1 Mon Sep 17 00:00:00 2001 From: Michael Barton Date: Sat, 29 Jan 2011 01:40:55 +0000 Subject: [PATCH 04/25] increase WAL autocheckpoint --- swift/common/db.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/swift/common/db.py b/swift/common/db.py index ca667edf1a..e06739d85f 100644 --- a/swift/common/db.py +++ b/swift/common/db.py @@ -44,6 +44,7 @@ BROKER_TIMEOUT = 25 PICKLE_PROTOCOL = 2 CONNECT_ATTEMPTS = 4 PENDING_COMMIT_TIMEOUT = 900 +AUTOCHECKPOINT = 8192 class DatabaseConnectionError(sqlite3.DatabaseError): @@ -142,6 +143,7 @@ def get_db_connection(path, timeout=30, okay_to_create=False): conn.execute('PRAGMA count_changes = OFF') conn.execute('PRAGMA temp_store = MEMORY') conn.execute('PRAGMA journal_mode = WAL') + conn.execute('PRAGMA wal_autocheckpoint = %s' % AUTOCHECKPOINT) conn.create_function('chexor', 3, chexor) conn.row_factory = sqlite3.Row conn.text_factory = str From 0649d9cc602baaacdd428e3455df4f6a9254e681 Mon Sep 17 00:00:00 2001 From: Michael Barton Date: Sat, 29 Jan 2011 03:26:26 +0000 Subject: [PATCH 05/25] replication fixes for WAL --- swift/common/db.py | 2 ++ swift/common/db_replicator.py | 4 +++- 2 files changed, 5 insertions(+), 1 deletion(-) diff --git a/swift/common/db.py b/swift/common/db.py index e06739d85f..0f288b74a1 100644 --- a/swift/common/db.py +++ b/swift/common/db.py @@ -288,6 +288,7 @@ class DatabaseBroker(object): self.conn = None orig_isolation_level = conn.isolation_level conn.isolation_level = None + conn.execute('PRAGMA journal_mode = DELETE') # remove any journal files conn.execute('BEGIN IMMEDIATE') try: yield True @@ -295,6 +296,7 @@ class DatabaseBroker(object): pass try: conn.execute('ROLLBACK') + conn.execute('PRAGMA journal_mode = WAL') # back to WAL mode conn.isolation_level = orig_isolation_level self.conn = conn except Exception: diff --git a/swift/common/db_replicator.py b/swift/common/db_replicator.py index 49756f1f7b..01a7d202de 100644 --- a/swift/common/db_replicator.py +++ b/swift/common/db_replicator.py @@ -180,7 +180,9 @@ class Replicator(Daemon): return False # perform block-level sync if the db was modified during the first sync if os.path.exists(broker.db_file + '-journal') or \ - os.path.getmtime(broker.db_file) > mtime: + os.path.exists(broker.db_file + '-wal') or \ + os.path.exists(broker.db_file + '-shm') or \ + os.path.getmtime(broker.db_file) > mtime: # grab a lock so nobody else can modify it with broker.lock(): if not self._rsync_file(broker.db_file, remote_file, False): From 68cda9b72446df358120bd9fed00a8804e960375 Mon Sep 17 00:00:00 2001 From: Michael Barton Date: Sat, 29 Jan 2011 18:22:16 +0000 Subject: [PATCH 06/25] refactor db open retry loop slightly --- swift/common/db.py | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/swift/common/db.py b/swift/common/db.py index 0f288b74a1..1e0057908c 100644 --- a/swift/common/db.py +++ b/swift/common/db.py @@ -127,7 +127,7 @@ def get_db_connection(path, timeout=30, okay_to_create=False): """ # retry logic to address: # http://www.mail-archive.com/sqlite-users@sqlite.org/msg57092.html - for tries in xrange(1, CONNECT_ATTEMPTS + 1): + for attempt in xrange(CONNECT_ATTEMPTS): try: connect_time = time.time() conn = sqlite3.connect(path, check_same_thread=False, @@ -139,19 +139,18 @@ def get_db_connection(path, timeout=30, okay_to_create=False): os.unlink(path) raise DatabaseConnectionError(path, 'DB file created by connect?') + conn.execute('PRAGMA journal_mode = WAL') conn.execute('PRAGMA synchronous = NORMAL') + conn.execute('PRAGMA wal_autocheckpoint = %s' % AUTOCHECKPOINT) conn.execute('PRAGMA count_changes = OFF') conn.execute('PRAGMA temp_store = MEMORY') - conn.execute('PRAGMA journal_mode = WAL') - conn.execute('PRAGMA wal_autocheckpoint = %s' % AUTOCHECKPOINT) conn.create_function('chexor', 3, chexor) conn.row_factory = sqlite3.Row conn.text_factory = str return conn except sqlite3.DatabaseError, e: - if tries == CONNECT_ATTEMPTS or 'locking protocol' not in str(e): - raise DatabaseConnectionError(path, traceback.format_exc(), - timeout=timeout) + errstr = traceback.format_exc() + raise DatabaseConnectionError(path, errstr, timeout=timeout) class DatabaseBroker(object): From 625255da39d0dda986c47f4390343513a34e5943 Mon Sep 17 00:00:00 2001 From: Michael Barton Date: Sat, 29 Jan 2011 19:26:06 +0000 Subject: [PATCH 07/25] remove pending_timeout references --- swift/account/server.py | 7 ------- swift/common/db.py | 3 +-- swift/common/db_replicator.py | 2 +- swift/container/server.py | 4 ---- 4 files changed, 2 insertions(+), 14 deletions(-) diff --git a/swift/account/server.py b/swift/account/server.py index 2c83f51cc6..94399eec22 100644 --- a/swift/account/server.py +++ b/swift/account/server.py @@ -86,8 +86,6 @@ class AccountController(object): return Response(status='507 %s is not mounted' % drive) broker = self._get_account_broker(drive, part, account) if container: # put account container - if 'x-cf-trans-id' in req.headers: - broker.pending_timeout = 3 if req.headers.get('x-account-override-deleted', 'no').lower() != \ 'yes' and broker.is_deleted(): return HTTPNotFound(request=req) @@ -140,9 +138,6 @@ class AccountController(object): if self.mount_check and not check_mount(self.root, drive): return Response(status='507 %s is not mounted' % drive) broker = self._get_account_broker(drive, part, account) - if not container: - broker.pending_timeout = 0.1 - broker.stale_reads_ok = True if broker.is_deleted(): return HTTPNotFound(request=req) info = broker.get_info() @@ -171,8 +166,6 @@ class AccountController(object): if self.mount_check and not check_mount(self.root, drive): return Response(status='507 %s is not mounted' % drive) broker = self._get_account_broker(drive, part, account) - broker.pending_timeout = 0.1 - broker.stale_reads_ok = True if broker.is_deleted(): return HTTPNotFound(request=req) info = broker.get_info() diff --git a/swift/common/db.py b/swift/common/db.py index 1e0057908c..7040b2446a 100644 --- a/swift/common/db.py +++ b/swift/common/db.py @@ -157,11 +157,10 @@ class DatabaseBroker(object): """Encapsulates working with a database.""" def __init__(self, db_file, timeout=BROKER_TIMEOUT, logger=None, - account=None, container=None, stale_reads_ok=False): + account=None, container=None): """ Encapsulates working with a database. """ self.conn = None self.db_file = db_file - self.stale_reads_ok = stale_reads_ok self.db_dir = os.path.dirname(db_file) self.timeout = timeout self.logger = logger or logging.getLogger() diff --git a/swift/common/db_replicator.py b/swift/common/db_replicator.py index 01a7d202de..5c4d4ebd8e 100644 --- a/swift/common/db_replicator.py +++ b/swift/common/db_replicator.py @@ -318,7 +318,7 @@ class Replicator(Daemon): self.logger.debug(_('Replicating db %s'), object_file) self.stats['attempted'] += 1 try: - broker = self.brokerclass(object_file, pending_timeout=30) + broker = self.brokerclass(object_file) broker.reclaim(time.time() - self.reclaim_age, time.time() - (self.reclaim_age * 2)) info = broker.get_replication_info() diff --git a/swift/container/server.py b/swift/container/server.py index cfcdded1e4..9a6b4aa210 100644 --- a/swift/container/server.py +++ b/swift/container/server.py @@ -219,8 +219,6 @@ class ContainerController(object): if self.mount_check and not check_mount(self.root, drive): return Response(status='507 %s is not mounted' % drive) broker = self._get_container_broker(drive, part, account, container) - broker.pending_timeout = 0.1 - broker.stale_reads_ok = True if broker.is_deleted(): return HTTPNotFound(request=req) info = broker.get_info() @@ -246,8 +244,6 @@ class ContainerController(object): if self.mount_check and not check_mount(self.root, drive): return Response(status='507 %s is not mounted' % drive) broker = self._get_container_broker(drive, part, account, container) - broker.pending_timeout = 0.1 - broker.stale_reads_ok = True if broker.is_deleted(): return HTTPNotFound(request=req) info = broker.get_info() From cb584303218805d1c1374d732caac26457a6ffe8 Mon Sep 17 00:00:00 2001 From: gholt Date: Wed, 2 Feb 2011 13:39:08 -0800 Subject: [PATCH 08/25] logging: use routes to separate logging configurations --- bin/swift-drive-audit | 2 +- bin/swift-log-uploader | 2 +- swift/account/auditor.py | 2 +- swift/account/reaper.py | 2 +- swift/account/server.py | 2 +- swift/auth/server.py | 2 +- swift/common/daemon.py | 4 ++-- swift/common/db_replicator.py | 2 +- swift/common/middleware/catch_errors.py | 2 +- swift/common/middleware/cname_lookup.py | 2 +- swift/common/middleware/ratelimit.py | 2 +- swift/common/middleware/swauth.py | 2 +- swift/common/utils.py | 2 ++ swift/common/wsgi.py | 2 +- swift/container/auditor.py | 2 +- swift/container/server.py | 2 +- swift/container/updater.py | 2 +- swift/obj/auditor.py | 2 +- swift/obj/replicator.py | 2 +- swift/obj/server.py | 2 +- swift/obj/updater.py | 2 +- swift/proxy/server.py | 2 +- swift/stats/access_processor.py | 2 +- swift/stats/account_stats.py | 3 ++- swift/stats/log_processor.py | 4 ++-- swift/stats/log_uploader.py | 3 ++- swift/stats/stats_processor.py | 2 +- test/unit/auth/test_server.py | 4 ++-- test/unit/common/test_daemon.py | 4 ++-- test/unit/common/test_utils.py | 8 +++++--- 30 files changed, 41 insertions(+), 35 deletions(-) diff --git a/bin/swift-drive-audit b/bin/swift-drive-audit index e92d1e3c12..5203f54b6b 100755 --- a/bin/swift-drive-audit +++ b/bin/swift-drive-audit @@ -99,7 +99,7 @@ if __name__ == '__main__': device_dir = conf.get('device_dir', '/srv/node') minutes = int(conf.get('minutes', 60)) error_limit = int(conf.get('error_limit', 1)) - logger = get_logger(conf, 'drive-audit') + logger = get_logger(conf, log_route='drive-audit') devices = get_devices(device_dir, logger) logger.debug("Devices found: %s" % str(devices)) if not devices: diff --git a/bin/swift-log-uploader b/bin/swift-log-uploader index 9d0e27836c..93cb8f6f97 100755 --- a/bin/swift-log-uploader +++ b/bin/swift-log-uploader @@ -34,7 +34,7 @@ if __name__ == '__main__': uploader_conf.update(plugin_conf) # pre-configure logger - logger = utils.get_logger(uploader_conf, plugin, + logger = utils.get_logger(uploader_conf, plugin, log_route='log-uploader', log_to_console=options.get('verbose', False)) # currently LogUploader only supports run_once options['once'] = True diff --git a/swift/account/auditor.py b/swift/account/auditor.py index 1f24f93acc..63551354d8 100644 --- a/swift/account/auditor.py +++ b/swift/account/auditor.py @@ -28,7 +28,7 @@ class AccountAuditor(Daemon): def __init__(self, conf): self.conf = conf - self.logger = get_logger(conf, 'account-auditor') + self.logger = get_logger(conf, log_route='account-auditor') self.devices = conf.get('devices', '/srv/node') self.mount_check = conf.get('mount_check', 'true').lower() in \ ('true', 't', '1', 'on', 'yes', 'y') diff --git a/swift/account/reaper.py b/swift/account/reaper.py index dd0d4b3890..ba78db8d98 100644 --- a/swift/account/reaper.py +++ b/swift/account/reaper.py @@ -53,7 +53,7 @@ class AccountReaper(Daemon): def __init__(self, conf): self.conf = conf - self.logger = get_logger(conf) + self.logger = get_logger(conf, log_route='account-reaper') self.devices = conf.get('devices', '/srv/node') self.mount_check = conf.get('mount_check', 'true').lower() in \ ('true', 't', '1', 'on', 'yes', 'y') diff --git a/swift/account/server.py b/swift/account/server.py index 2c83f51cc6..f15ac38c11 100644 --- a/swift/account/server.py +++ b/swift/account/server.py @@ -42,7 +42,7 @@ class AccountController(object): """WSGI controller for the account server.""" def __init__(self, conf): - self.logger = get_logger(conf) + self.logger = get_logger(conf, log_route='account-server') self.root = conf.get('devices', '/srv/node') self.mount_check = conf.get('mount_check', 'true').lower() in \ ('true', 't', '1', 'on', 'yes', 'y') diff --git a/swift/auth/server.py b/swift/auth/server.py index f9cd56dd0e..1258a706e7 100644 --- a/swift/auth/server.py +++ b/swift/auth/server.py @@ -90,7 +90,7 @@ class AuthController(object): """ def __init__(self, conf): - self.logger = get_logger(conf) + self.logger = get_logger(conf, log_route='auth-server') self.super_admin_key = conf.get('super_admin_key') if not self.super_admin_key: msg = _('No super_admin_key set in conf file! Exiting.') diff --git a/swift/common/daemon.py b/swift/common/daemon.py index eee3428679..91230e4d2b 100644 --- a/swift/common/daemon.py +++ b/swift/common/daemon.py @@ -26,7 +26,7 @@ class Daemon(object): def __init__(self, conf): self.conf = conf - self.logger = utils.get_logger(conf, 'swift-daemon') + self.logger = utils.get_logger(conf, log_route='daemon') def run_once(self): """Override this to run the script once""" @@ -84,7 +84,7 @@ def run_daemon(klass, conf_file, section_name='', logger = kwargs.pop('logger') else: logger = utils.get_logger(conf, conf.get('log_name', section_name), - log_to_console=kwargs.pop('verbose', False)) + log_to_console=kwargs.pop('verbose', False), log_route=section_name) try: klass(conf).run(once=once, **kwargs) except KeyboardInterrupt: diff --git a/swift/common/db_replicator.py b/swift/common/db_replicator.py index 49756f1f7b..3c3731d45a 100644 --- a/swift/common/db_replicator.py +++ b/swift/common/db_replicator.py @@ -92,7 +92,7 @@ class Replicator(Daemon): def __init__(self, conf): self.conf = conf - self.logger = get_logger(conf) + self.logger = get_logger(conf, log_route='replicator') self.root = conf.get('devices', '/srv/node') self.mount_check = conf.get('mount_check', 'true').lower() in \ ('true', 't', '1', 'on', 'yes', 'y') diff --git a/swift/common/middleware/catch_errors.py b/swift/common/middleware/catch_errors.py index 10d8614194..16ade84689 100644 --- a/swift/common/middleware/catch_errors.py +++ b/swift/common/middleware/catch_errors.py @@ -30,7 +30,7 @@ class CatchErrorMiddleware(object): self.logger = getattr(app, 'logger', None) if not self.logger: # and only call get_logger if we have to - self.logger = get_logger(conf) + self.logger = get_logger(conf, log_route='catch-errors') def __call__(self, env, start_response): try: diff --git a/swift/common/middleware/cname_lookup.py b/swift/common/middleware/cname_lookup.py index f13155c1fe..8ea9f88071 100644 --- a/swift/common/middleware/cname_lookup.py +++ b/swift/common/middleware/cname_lookup.py @@ -53,7 +53,7 @@ class CNAMELookupMiddleware(object): self.storage_domain = '.' + self.storage_domain self.lookup_depth = int(conf.get('lookup_depth', '1')) self.memcache = None - self.logger = get_logger(conf) + self.logger = get_logger(conf, log_route='cname-lookup') def __call__(self, env, start_response): if not self.storage_domain: diff --git a/swift/common/middleware/ratelimit.py b/swift/common/middleware/ratelimit.py index 4657b6abcd..485b1db26e 100644 --- a/swift/common/middleware/ratelimit.py +++ b/swift/common/middleware/ratelimit.py @@ -39,7 +39,7 @@ class RateLimitMiddleware(object): if logger: self.logger = logger else: - self.logger = get_logger(conf) + self.logger = get_logger(conf, log_route='ratelimit') self.account_ratelimit = float(conf.get('account_ratelimit', 0)) self.max_sleep_time_seconds = \ float(conf.get('max_sleep_time_seconds', 60)) diff --git a/swift/common/middleware/swauth.py b/swift/common/middleware/swauth.py index 5965e710ac..32328e8eb6 100644 --- a/swift/common/middleware/swauth.py +++ b/swift/common/middleware/swauth.py @@ -51,7 +51,7 @@ class Swauth(object): def __init__(self, app, conf): self.app = app self.conf = conf - self.logger = get_logger(conf) + self.logger = get_logger(conf, log_route='swauth') self.log_headers = conf.get('log_headers') == 'True' self.reseller_prefix = conf.get('reseller_prefix', 'AUTH').strip() if self.reseller_prefix and self.reseller_prefix[-1] != '_': diff --git a/swift/common/utils.py b/swift/common/utils.py index 8da3d1f8f4..698fae2cc1 100644 --- a/swift/common/utils.py +++ b/swift/common/utils.py @@ -395,6 +395,8 @@ def get_logger(conf, name=None, log_to_console=False, log_route=None): :param conf: Configuration dict to read settings from :param name: Name of the logger :param log_to_console: Add handler which writes to console on stderr + :param log_route: Route for the logging, not emitted to the log, just used + to separate logging configurations """ if not conf: conf = {} diff --git a/swift/common/wsgi.py b/swift/common/wsgi.py index 9450bcf439..46207fe8e1 100644 --- a/swift/common/wsgi.py +++ b/swift/common/wsgi.py @@ -113,7 +113,7 @@ def run_wsgi(conf_file, app_section, *args, **kwargs): logger = kwargs.pop('logger') else: logger = get_logger(conf, log_name, - log_to_console=kwargs.pop('verbose', False)) + log_to_console=kwargs.pop('verbose', False), log_route='wsgi') # redirect errors to logger and close stdio capture_stdio(logger) diff --git a/swift/container/auditor.py b/swift/container/auditor.py index d1ceb4f98a..0b1c10e03e 100644 --- a/swift/container/auditor.py +++ b/swift/container/auditor.py @@ -28,7 +28,7 @@ class ContainerAuditor(Daemon): def __init__(self, conf): self.conf = conf - self.logger = get_logger(conf, 'container-auditor') + self.logger = get_logger(conf, log_route='container-auditor') self.devices = conf.get('devices', '/srv/node') self.mount_check = conf.get('mount_check', 'true').lower() in \ ('true', 't', '1', 'on', 'yes', 'y') diff --git a/swift/container/server.py b/swift/container/server.py index cfcdded1e4..561dad2ea9 100644 --- a/swift/container/server.py +++ b/swift/container/server.py @@ -49,7 +49,7 @@ class ContainerController(object): save_headers = ['x-container-read', 'x-container-write'] def __init__(self, conf): - self.logger = get_logger(conf) + self.logger = get_logger(conf, log_route='container-server') self.root = conf.get('devices', '/srv/node/') self.mount_check = conf.get('mount_check', 'true').lower() in \ ('true', 't', '1', 'on', 'yes', 'y') diff --git a/swift/container/updater.py b/swift/container/updater.py index 883dd17101..0bd000f3f2 100644 --- a/swift/container/updater.py +++ b/swift/container/updater.py @@ -37,7 +37,7 @@ class ContainerUpdater(Daemon): def __init__(self, conf): self.conf = conf - self.logger = get_logger(conf, 'container-updater') + self.logger = get_logger(conf, log_route='container-updater') self.devices = conf.get('devices', '/srv/node') self.mount_check = conf.get('mount_check', 'true').lower() in \ ('true', 't', '1', 'on', 'yes', 'y') diff --git a/swift/obj/auditor.py b/swift/obj/auditor.py index 09fdd77774..8ed05049f3 100644 --- a/swift/obj/auditor.py +++ b/swift/obj/auditor.py @@ -31,7 +31,7 @@ class ObjectAuditor(Daemon): def __init__(self, conf): self.conf = conf - self.logger = get_logger(conf, 'object-auditor') + self.logger = get_logger(conf, log_route='object-auditor') self.devices = conf.get('devices', '/srv/node') self.mount_check = conf.get('mount_check', 'true').lower() in \ ('true', 't', '1', 'on', 'yes', 'y') diff --git a/swift/obj/replicator.py b/swift/obj/replicator.py index dcfcb926f9..8dec8aa801 100644 --- a/swift/obj/replicator.py +++ b/swift/obj/replicator.py @@ -207,7 +207,7 @@ class ObjectReplicator(Daemon): :param logger: logging object """ self.conf = conf - self.logger = get_logger(conf, 'object-replicator') + self.logger = get_logger(conf, log_route='object-replicator') self.devices_dir = conf.get('devices', '/srv/node') self.mount_check = conf.get('mount_check', 'true').lower() in \ ('true', 't', '1', 'on', 'yes', 'y') diff --git a/swift/obj/server.py b/swift/obj/server.py index f2e2b31314..e3626bf692 100644 --- a/swift/obj/server.py +++ b/swift/obj/server.py @@ -266,7 +266,7 @@ class ObjectController(object): /etc/object-server.conf-sample or /etc/swift/object-server.conf-sample. """ - self.logger = get_logger(conf) + self.logger = get_logger(conf, log_route='object-server') self.devices = conf.get('devices', '/srv/node/') self.mount_check = conf.get('mount_check', 'true').lower() in \ ('true', 't', '1', 'on', 'yes', 'y') diff --git a/swift/obj/updater.py b/swift/obj/updater.py index 2b28ff08c5..356be64da4 100644 --- a/swift/obj/updater.py +++ b/swift/obj/updater.py @@ -35,7 +35,7 @@ class ObjectUpdater(Daemon): def __init__(self, conf): self.conf = conf - self.logger = get_logger(conf, 'object-updater') + self.logger = get_logger(conf, log_route='object-updater') self.devices = conf.get('devices', '/srv/node') self.mount_check = conf.get('mount_check', 'true').lower() in \ ('true', 't', '1', 'on', 'yes', 'y') diff --git a/swift/proxy/server.py b/swift/proxy/server.py index 1eae0dfc30..a66f643a68 100644 --- a/swift/proxy/server.py +++ b/swift/proxy/server.py @@ -1607,7 +1607,7 @@ class BaseApplication(object): def __init__(self, conf, memcache=None, logger=None, account_ring=None, container_ring=None, object_ring=None): if logger is None: - self.logger = get_logger(conf) + self.logger = get_logger(conf, log_route='proxy-server') else: self.logger = logger if conf is None: diff --git a/swift/stats/access_processor.py b/swift/stats/access_processor.py index 2aee505415..6965ef2b4a 100644 --- a/swift/stats/access_processor.py +++ b/swift/stats/access_processor.py @@ -34,7 +34,7 @@ class AccessLogProcessor(object): conf.get('service_ips', '').split(',')\ if x.strip()] self.warn_percent = float(conf.get('warn_percent', '0.8')) - self.logger = get_logger(conf) + self.logger = get_logger(conf, log_route='access-processor') def log_line_parser(self, raw_log): '''given a raw access log line, return a dict of the good parts''' diff --git a/swift/stats/account_stats.py b/swift/stats/account_stats.py index 325746386c..34b024d2c2 100644 --- a/swift/stats/account_stats.py +++ b/swift/stats/account_stats.py @@ -48,7 +48,8 @@ class AccountStat(Daemon): self.devices = server_conf.get('devices', '/srv/node') self.mount_check = server_conf.get('mount_check', 'true').lower() in \ ('true', 't', '1', 'on', 'yes', 'y') - self.logger = get_logger(stats_conf, 'swift-account-stats-logger') + self.logger = \ + get_logger(stats_conf, log_route='account-stats') def run_once(self): self.logger.info(_("Gathering account stats")) diff --git a/swift/stats/log_processor.py b/swift/stats/log_processor.py index 5dbc92afbe..727e687f38 100644 --- a/swift/stats/log_processor.py +++ b/swift/stats/log_processor.py @@ -40,7 +40,7 @@ class LogProcessor(object): def __init__(self, conf, logger): if isinstance(logger, tuple): - self.logger = get_logger(*logger) + self.logger = get_logger(*logger, log_route='log-processor') else: self.logger = logger @@ -226,7 +226,7 @@ class LogProcessorDaemon(Daemon): c = conf.get('log-processor') super(LogProcessorDaemon, self).__init__(c) self.total_conf = conf - self.logger = get_logger(c) + self.logger = get_logger(c, log_route='log-processor') self.log_processor = LogProcessor(conf, self.logger) self.lookback_hours = int(c.get('lookback_hours', '120')) self.lookback_window = int(c.get('lookback_window', diff --git a/swift/stats/log_uploader.py b/swift/stats/log_uploader.py index b425738938..a828188eb7 100644 --- a/swift/stats/log_uploader.py +++ b/swift/stats/log_uploader.py @@ -65,7 +65,8 @@ class LogUploader(Daemon): self.filename_format = source_filename_format self.internal_proxy = InternalProxy(proxy_server_conf) log_name = 'swift-log-uploader-%s' % plugin_name - self.logger = utils.get_logger(uploader_conf, plugin_name) + self.logger = \ + utils.get_logger(uploader_conf, plugin_name, log_route=plugin_name) def run_once(self): self.logger.info(_("Uploading logs")) diff --git a/swift/stats/stats_processor.py b/swift/stats/stats_processor.py index 95dba7604c..f9496c1df9 100644 --- a/swift/stats/stats_processor.py +++ b/swift/stats/stats_processor.py @@ -20,7 +20,7 @@ class StatsLogProcessor(object): """Transform account storage stat logs""" def __init__(self, conf): - self.logger = get_logger(conf) + self.logger = get_logger(conf, log_route='stats-processor') def process(self, obj_stream, data_object_account, data_object_container, data_object_name): diff --git a/test/unit/auth/test_server.py b/test/unit/auth/test_server.py index 4060766d65..d58556ab22 100644 --- a/test/unit/auth/test_server.py +++ b/test/unit/auth/test_server.py @@ -456,7 +456,7 @@ class TestAuthServer(unittest.TestCase): def test_basic_logging(self): log = StringIO() log_handler = StreamHandler(log) - logger = get_logger(self.conf, 'auth') + logger = get_logger(self.conf, 'auth-server', log_route='auth-server') logger.logger.addHandler(log_handler) try: auth_server.http_connect = fake_http_connect(201) @@ -534,7 +534,7 @@ class TestAuthServer(unittest.TestCase): orig_Request = auth_server.Request log = StringIO() log_handler = StreamHandler(log) - logger = get_logger(self.conf, 'auth') + logger = get_logger(self.conf, 'auth-server', log_route='auth-server') logger.logger.addHandler(log_handler) try: auth_server.Request = request_causing_exception diff --git a/test/unit/common/test_daemon.py b/test/unit/common/test_daemon.py index a4addcee51..1d54e78c3e 100644 --- a/test/unit/common/test_daemon.py +++ b/test/unit/common/test_daemon.py @@ -28,7 +28,7 @@ class MyDaemon(daemon.Daemon): def __init__(self, conf): self.conf = conf - self.logger = utils.get_logger(None, 'server') + self.logger = utils.get_logger(None, 'server', log_route='server') MyDaemon.forever_called = False MyDaemon.once_called = False @@ -99,7 +99,7 @@ user = %s sio = StringIO() logger = logging.getLogger('server') logger.addHandler(logging.StreamHandler(sio)) - logger = utils.get_logger(None, 'server') + logger = utils.get_logger(None, 'server', log_route='server') daemon.run_daemon(MyDaemon, conf_file, logger=logger) self.assert_('user quit' in sio.getvalue().lower()) diff --git a/test/unit/common/test_utils.py b/test/unit/common/test_utils.py index 0c81b15698..8da913c489 100644 --- a/test/unit/common/test_utils.py +++ b/test/unit/common/test_utils.py @@ -289,17 +289,19 @@ Error: unable to locate %s sio = StringIO() logger = logging.getLogger('server') logger.addHandler(logging.StreamHandler(sio)) - logger = utils.get_logger(None, 'server') + logger = utils.get_logger(None, 'server', log_route='server') logger.warn('test1') self.assertEquals(sio.getvalue(), 'test1\n') logger.debug('test2') self.assertEquals(sio.getvalue(), 'test1\n') - logger = utils.get_logger({'log_level': 'DEBUG'}, 'server') + logger = utils.get_logger({'log_level': 'DEBUG'}, 'server', + log_route='server') logger.debug('test3') self.assertEquals(sio.getvalue(), 'test1\ntest3\n') # Doesn't really test that the log facility is truly being used all the # way to syslog; but exercises the code. - logger = utils.get_logger({'log_facility': 'LOG_LOCAL3'}, 'server') + logger = utils.get_logger({'log_facility': 'LOG_LOCAL3'}, 'server', + log_route='server') logger.warn('test4') self.assertEquals(sio.getvalue(), 'test1\ntest3\ntest4\n') From ee3886f2ca45e8983b13af04a06fee000aab61bb Mon Sep 17 00:00:00 2001 From: Clay Gerrard Date: Thu, 3 Feb 2011 13:46:28 -0600 Subject: [PATCH 09/25] moved warning messages out of proxy.logger.info A few warning/client error messages were useing the .info log level which we reserve for access logs. They were changed to warnings. --- swift/proxy/server.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/swift/proxy/server.py b/swift/proxy/server.py index 1eae0dfc30..14f79a2c61 100644 --- a/swift/proxy/server.py +++ b/swift/proxy/server.py @@ -624,7 +624,7 @@ class Controller(object): res.bytes_transferred += len(chunk) except GeneratorExit: res.client_disconnect = True - self.app.logger.info(_('Client disconnected on read')) + self.app.logger.warn(_('Client disconnected on read')) except (Exception, TimeoutError): self.exception_occurred(node, _('Object'), _('Trying to read during GET of %s') % req.path) @@ -1054,7 +1054,7 @@ class ObjectController(Controller): if req.headers.get('transfer-encoding') and chunk == '': break except ChunkReadTimeout, err: - self.app.logger.info( + self.app.logger.warn( _('ERROR Client read timeout (%ss)'), err.seconds) return HTTPRequestTimeout(request=req) except Exception: @@ -1064,7 +1064,7 @@ class ObjectController(Controller): return Response(status='499 Client Disconnect') if req.content_length and req.bytes_transferred < req.content_length: req.client_disconnect = True - self.app.logger.info( + self.app.logger.warn( _('Client disconnected without sending enough data')) return Response(status='499 Client Disconnect') statuses = [] From c62842bfd111c9f2ac4dbd343582332452ec13b3 Mon Sep 17 00:00:00 2001 From: Michael Barton Date: Thu, 3 Feb 2011 19:50:16 +0000 Subject: [PATCH 10/25] update all ring-builder grammars --- bin/swift-ring-builder | 47 +++++++++++++++++++++++++++++++++--------- 1 file changed, 37 insertions(+), 10 deletions(-) diff --git a/bin/swift-ring-builder b/bin/swift-ring-builder index 41293f7d37..c6d91f92b4 100755 --- a/bin/swift-ring-builder +++ b/bin/swift-ring-builder @@ -48,6 +48,8 @@ The can be of the form: /sdb1 Matches devices with the device name sdb1 _shiny Matches devices with shiny in the meta data _"snet: 5.6.7.8" Matches devices with snet: 5.6.7.8 in the meta data + [::1] Matches devices in any zone with the ip ::1 + z1-[::1]:5678 Matches devices in zone 1 with the ip ::1 and port 5678 Most specific example: d74z1-1.2.3.4:5678/sdb1_"snet: 5.6.7.8" Nerd explanation: @@ -76,6 +78,13 @@ The can be of the form: i += 1 match.append(('ip', search_value[:i])) search_value = search_value[i:] + elif len(search_value) and search_value[0] == '[': + i = 1 + while i < len(search_value) and search_value[i] != ']': + i += 1 + i += 1 + match.append(('ip', search_value[:i].lstrip('[').rstrip(']'))) + search_value = search_value[i:] if search_value.startswith(':'): i = 1 while i < len(search_value) and search_value[i].isdigit(): @@ -110,6 +119,16 @@ The can be of the form: return devs +def format_device(dev): + """ + Format a device for display. + """ + if ':' in dev['ip']: + return 'd%(id)sz%(zone)s-[%(ip)s]:%(port)s/%(device)s_"%(meta)s"' % dev + else: + return 'd%(id)sz%(zone)s-%(ip)s:%(port)s/%(device)s_"%(meta)s"' % dev + + class Commands: def unknown(): @@ -236,10 +255,11 @@ swift-ring-builder add z-:/_ exit(EXIT_ERROR) i = 1 if rest[i] == '[': + i += 1 while i < len(rest) and rest[i] != ']': i += 1 - ip = rest[2:i] i += 1 + ip = rest[1:i].lstrip('[').rstrip(']') rest = rest[i:] else: while i < len(rest) and rest[i] in '0123456789.': @@ -286,8 +306,12 @@ swift-ring-builder add z-:/_ builder.add_dev({'id': next_dev_id, 'zone': zone, 'ip': ip, 'port': port, 'device': device_name, 'weight': weight, 'meta': meta}) - print 'Device z%s-%s:%s/%s_"%s" with %s weight got id %s' % \ - (zone, ip, port, device_name, meta, weight, next_dev_id) + if ':' in ip: + print 'Device z%s-[%s]:%s/%s_"%s" with %s weight got id %s' % \ + (zone, ip, port, device_name, meta, weight, next_dev_id) + else: + print 'Device z%s-%s:%s/%s_"%s" with %s weight got id %s' % \ + (zone, ip, port, device_name, meta, weight, next_dev_id) pickle.dump(builder, open(argv[1], 'wb'), protocol=2) exit(EXIT_RING_UNCHANGED) @@ -349,6 +373,13 @@ swift-ring-builder set_info i += 1 change.append(('ip', change_value[:i])) change_value = change_value[i:] + elif len(change_value) and change_value[0] == '[': + i = 1 + while i < len(change_value) and change_value[i] != ']': + i += 1 + i += 1 + change.append(('ip', change_value[:i].lstrip('[').rstrip(']'))) + change_value = change_value[i:] if change_value.startswith(':'): i = 1 while i < len(change_value) and change_value[i].isdigit(): @@ -373,15 +404,13 @@ swift-ring-builder set_info if len(devs) > 1: print 'Matched more than one device:' for dev in devs: - print ' d%(id)sz%(zone)s-%(ip)s:%(port)s/%(device)s_' \ - '"%(meta)s"' % dev + print ' %s' % format_device(dev) if raw_input('Are you sure you want to update the info for ' 'these %s devices? (y/N) ' % len(devs)) != 'y': print 'Aborting device modifications' exit(EXIT_ERROR) for dev in devs: - orig_dev_string = \ - 'd%(id)sz%(zone)s-%(ip)s:%(port)s/%(device)s_"%(meta)s"' % dev + orig_dev_string = format_device(dev) test_dev = dict(dev) for key, value in change: test_dev[key] = value @@ -397,9 +426,7 @@ swift-ring-builder set_info exit(EXIT_ERROR) for key, value in change: dev[key] = value - new_dev_string = \ - 'd%(id)sz%(zone)s-%(ip)s:%(port)s/%(device)s_"%(meta)s"' % dev - print 'Device %s is now %s' % (orig_dev_string, new_dev_string) + print 'Device %s is now %s' % (orig_dev_string, format_device(dev)) pickle.dump(builder, open(argv[1], 'wb'), protocol=2) exit(EXIT_RING_UNCHANGED) From c2931e157c4db364e4ce9d971920be2a83641431 Mon Sep 17 00:00:00 2001 From: Michael Barton Date: Thu, 3 Feb 2011 19:53:47 +0000 Subject: [PATCH 11/25] random newline --- test/unit/common/test_utils.py | 1 + 1 file changed, 1 insertion(+) diff --git a/test/unit/common/test_utils.py b/test/unit/common/test_utils.py index 69d24759b7..af38b18208 100644 --- a/test/unit/common/test_utils.py +++ b/test/unit/common/test_utils.py @@ -501,5 +501,6 @@ log_name = yarr''' # make sure its accurate to 10th of a second self.assertTrue(abs(100 - (time.time() - start) * 100) < 10) + if __name__ == '__main__': unittest.main() From f9fa63686c802ce8d3f2e4e29ecc7fb686835ba9 Mon Sep 17 00:00:00 2001 From: Clay Gerrard Date: Thu, 3 Feb 2011 15:23:07 -0600 Subject: [PATCH 12/25] Moved proxy server access log messages into their own log level Added new "access" log level available on swift loggers that will be routed to the LOG_NOTICE priority in syslog for easy redirection of access log messages via rsyslog and syslog-ng. --- doc/source/overview_stats.rst | 15 ++++++++------- swift/common/utils.py | 15 +++++++++++++++ swift/proxy/server.py | 2 +- test/unit/common/test_utils.py | 6 ++++++ test/unit/proxy/test_server.py | 2 +- 5 files changed, 31 insertions(+), 9 deletions(-) diff --git a/doc/source/overview_stats.rst b/doc/source/overview_stats.rst index 6364de4611..40a5dd01af 100644 --- a/doc/source/overview_stats.rst +++ b/doc/source/overview_stats.rst @@ -15,9 +15,10 @@ Access logs *********** Access logs are the proxy server logs. Rackspace uses syslog-ng to redirect -the proxy log output to an hourly log file. For example, a proxy request that -is made on August 4, 2010 at 12:37 gets logged in a file named 2010080412. -This allows easy log rotation and easy per-hour log processing. +proxy log messages with the syslog priority LOG_NOTICE to an hourly log +file. For example, a proxy request that is made on August 4, 2010 at 12:37 gets +logged in a file named 2010080412. This allows easy log rotation and easy +per-hour log processing. ****************** Account stats logs @@ -99,11 +100,11 @@ Running the stats system on SAIO destination df_local1 { file("/var/log/swift/proxy.log" owner() group()); }; destination df_local1_err { file("/var/log/swift/proxy.error" owner() group()); }; destination df_local1_hourly { file("/var/log/swift/hourly/$YEAR$MONTH$DAY$HOUR" owner() group()); }; - filter f_local1 { facility(local1) and level(info); }; + filter f_local1 { facility(local1) and level(notice); }; - filter f_local1_err { facility(local1) and not level(info); }; + filter f_local1_err { facility(local1) and not level(notice); }; - # local1.info -/var/log/swift/proxy.log + # local1.notice -/var/log/swift/proxy.log # write to local file and to remove log server log { source(s_all); @@ -181,4 +182,4 @@ earlier. This file will have one entry per account per hour for each account with activity in that hour. One .csv file should be produced per hour. Note that the stats will be delayed by at least two hours by default. This can be changed with the new_log_cutoff variable in the config file. See -`log-processing.conf-sample` for more details. \ No newline at end of file +`log-processing.conf-sample` for more details. diff --git a/swift/common/utils.py b/swift/common/utils.py index 8da3d1f8f4..5c462b5d08 100644 --- a/swift/common/utils.py +++ b/swift/common/utils.py @@ -48,6 +48,11 @@ import logging logging.thread = eventlet.green.thread logging.threading = eventlet.green.threading logging._lock = logging.threading.RLock() +# setup access level logging +ACCESS = 25 +logging._levelNames[ACCESS] = 'ACCESS' +# syslog priority "notice" is used for proxy access log lines +SysLogHandler.priority_map['ACCESS'] = 'notice' # These are lazily pulled from libc elsewhere _sys_fallocate = None @@ -310,6 +315,16 @@ class LogAdapter(object): def getEffectiveLevel(self): return self.logger.getEffectiveLevel() + def access(self, msg, *args): + """ + Convenience function for proxy access request log level. Only + proxy access log messages should use this method. The python + logging lvl is set to 25, just above info. SysLogHandler is + monkey patched to map this log lvl to the LOG_NOTICE syslog + priority. + """ + self.logger.log(ACCESS, msg, *args) + def exception(self, msg, *args): _junk, exc, _junk = sys.exc_info() call = self.logger.error diff --git a/swift/proxy/server.py b/swift/proxy/server.py index 14f79a2c61..dc501faba5 100644 --- a/swift/proxy/server.py +++ b/swift/proxy/server.py @@ -1790,7 +1790,7 @@ class Application(BaseApplication): if getattr(req, 'client_disconnect', False) or \ getattr(response, 'client_disconnect', False): status_int = 499 - self.logger.info(' '.join(quote(str(x)) for x in ( + self.logger.access(' '.join(quote(str(x)) for x in ( client or '-', req.remote_addr or '-', time.strftime('%d/%b/%Y/%H/%M/%S', time.gmtime()), diff --git a/test/unit/common/test_utils.py b/test/unit/common/test_utils.py index 0c81b15698..1fd18b6ee6 100644 --- a/test/unit/common/test_utils.py +++ b/test/unit/common/test_utils.py @@ -303,9 +303,15 @@ Error: unable to locate %s logger.warn('test4') self.assertEquals(sio.getvalue(), 'test1\ntest3\ntest4\n') + # make sure debug doesn't log by default logger.debug('test5') self.assertEquals(sio.getvalue(), 'test1\ntest3\ntest4\n') + # make sure access lvl logs by default + logger.access('test6') + self.assertEquals(sio.getvalue(), + 'test1\ntest3\ntest4\ntest6\n') + def test_storage_directory(self): self.assertEquals(utils.storage_directory('objects', '1', 'ABCDEF'), diff --git a/test/unit/proxy/test_server.py b/test/unit/proxy/test_server.py index e991d84084..4b0404454f 100644 --- a/test/unit/proxy/test_server.py +++ b/test/unit/proxy/test_server.py @@ -1802,7 +1802,7 @@ class TestObjectController(unittest.TestCase): class Logger(object): - def info(self, msg): + def access(self, msg): self.msg = msg orig_logger = prosrv.logger From ee4a9a85ac8763b14deb9c55e6c9be2a163bb5a8 Mon Sep 17 00:00:00 2001 From: gholt Date: Fri, 4 Feb 2011 11:16:21 -0800 Subject: [PATCH 13/25] Indexing and integrity changes in dbs. --- swift/common/db.py | 125 +++++++++++++++++++++++++-------------------- 1 file changed, 69 insertions(+), 56 deletions(-) diff --git a/swift/common/db.py b/swift/common/db.py index 7040b2446a..4327ffa311 100644 --- a/swift/common/db.py +++ b/swift/common/db.py @@ -166,6 +166,7 @@ class DatabaseBroker(object): self.logger = logger or logging.getLogger() self.account = account self.container = container + self.db_version = -1 def initialize(self, put_timestamp=None): """ @@ -573,7 +574,7 @@ class ContainerBroker(DatabaseBroker): conn.executescript(""" CREATE TABLE object ( ROWID INTEGER PRIMARY KEY AUTOINCREMENT, - name TEXT UNIQUE, + name TEXT, created_at TEXT, size INTEGER, content_type TEXT, @@ -581,7 +582,7 @@ class ContainerBroker(DatabaseBroker): deleted INTEGER DEFAULT 0 ); - CREATE INDEX ix_object_deleted ON object (deleted); + CREATE INDEX ix_object_deleted_name ON object (deleted, name); CREATE TRIGGER object_insert AFTER INSERT ON object BEGIN @@ -812,6 +813,12 @@ class ContainerBroker(DatabaseBroker): reported_object_count, reported_bytes_used, hash, id) """ with self.get() as conn: + if self.db_version == -1: + self.db_version = 0 + for row in conn.execute(''' + SELECT name FROM sqlite_master + WHERE name = 'ix_object_deleted_name' '''): + self.db_version = 1 return conn.execute(''' SELECT account, container, created_at, put_timestamp, delete_timestamp, object_count, bytes_used, @@ -906,7 +913,10 @@ class ContainerBroker(DatabaseBroker): elif prefix: query += ' name >= ? AND' query_args.append(prefix) - query += ' +deleted = 0 ORDER BY name LIMIT ?' + if self.db_version < 1: + query += ' +deleted = 0 ORDER BY name LIMIT ?' + else: + query += ' deleted = 0 ORDER BY name LIMIT ?' query_args.append(limit - len(results)) curs = conn.execute(query, query_args) curs.row_factory = None @@ -954,18 +964,19 @@ class ContainerBroker(DatabaseBroker): max_rowid = -1 for rec in item_list: conn.execute(''' - DELETE FROM object WHERE name = ? AND - (created_at < ?) + DELETE FROM object WHERE name = ? AND created_at < ? AND + deleted IN (0, 1) ''', (rec['name'], rec['created_at'])) - try: + if not conn.execute(''' + SELECT name FROM object WHERE name = ? AND + deleted IN (0, 1) + ''', (rec['name'],)).fetchall(): conn.execute(''' INSERT INTO object (name, created_at, size, content_type, etag, deleted) VALUES (?, ?, ?, ?, ?, ?) ''', ([rec['name'], rec['created_at'], rec['size'], rec['content_type'], rec['etag'], rec['deleted']])) - except sqlite3.IntegrityError: - pass if source: max_rowid = max(max_rowid, rec['ROWID']) if source: @@ -1009,7 +1020,7 @@ class AccountBroker(DatabaseBroker): conn.executescript(""" CREATE TABLE container ( ROWID INTEGER PRIMARY KEY AUTOINCREMENT, - name TEXT UNIQUE, + name TEXT, put_timestamp TEXT, delete_timestamp TEXT, object_count INTEGER, @@ -1017,8 +1028,9 @@ class AccountBroker(DatabaseBroker): deleted INTEGER DEFAULT 0 ); - CREATE INDEX ix_container_deleted ON container (deleted); - CREATE INDEX ix_container_name ON container (name); + CREATE INDEX ix_container_deleted_name ON + container (deleted, name); + CREATE TRIGGER container_insert AFTER INSERT ON container BEGIN UPDATE account_stat @@ -1287,6 +1299,12 @@ class AccountBroker(DatabaseBroker): bytes_used, hash, id) """ with self.get() as conn: + if self.db_version == -1: + self.db_version = 0 + for row in conn.execute(''' + SELECT name FROM sqlite_master + WHERE name = 'ix_container_deleted_name' '''): + self.db_version = 1 return conn.execute(''' SELECT account, created_at, put_timestamp, delete_timestamp, container_count, object_count, bytes_used, hash, id @@ -1355,7 +1373,10 @@ class AccountBroker(DatabaseBroker): elif prefix: query += ' name >= ? AND' query_args.append(prefix) - query += ' +deleted = 0 ORDER BY name LIMIT ?' + if self.db_version < 1: + query += ' +deleted = 0 ORDER BY name LIMIT ?' + else: + query += ' deleted = 0 ORDER BY name LIMIT ?' query_args.append(limit - len(results)) curs = conn.execute(query, query_args) curs.row_factory = None @@ -1399,51 +1420,43 @@ class AccountBroker(DatabaseBroker): record = [rec['name'], rec['put_timestamp'], rec['delete_timestamp'], rec['object_count'], rec['bytes_used'], rec['deleted']] - try: + curs = conn.execute(''' + SELECT name, put_timestamp, delete_timestamp, + object_count, bytes_used, deleted + FROM container WHERE name = ? AND + (put_timestamp < ? OR delete_timestamp < ? OR + object_count != ? OR bytes_used != ?) AND + deleted IN (0, 1)''', + (rec['name'], rec['put_timestamp'], + rec['delete_timestamp'], rec['object_count'], + rec['bytes_used'])) + curs.row_factory = None + row = curs.fetchone() + if row: + row = list(row) + for i in xrange(5): + if record[i] is None and row[i] is not None: + record[i] = row[i] + if row[1] > record[1]: # Keep newest put_timestamp + record[1] = row[1] + if row[2] > record[2]: # Keep newest delete_timestamp + record[2] = row[2] conn.execute(''' - INSERT INTO container (name, put_timestamp, - delete_timestamp, object_count, bytes_used, - deleted) - VALUES (?, ?, ?, ?, ?, ?) - ''', record) - except sqlite3.IntegrityError: - curs = conn.execute(''' - SELECT name, put_timestamp, delete_timestamp, - object_count, bytes_used, deleted - FROM container WHERE name = ? AND - (put_timestamp < ? OR delete_timestamp < ? OR - object_count != ? OR bytes_used != ?)''', - (rec['name'], rec['put_timestamp'], - rec['delete_timestamp'], rec['object_count'], - rec['bytes_used'])) - curs.row_factory = None - row = curs.fetchone() - if row: - row = list(row) - for i in xrange(5): - if record[i] is None and row[i] is not None: - record[i] = row[i] - if row[1] > record[1]: # Keep newest put_timestamp - record[1] = row[1] - if row[2] > record[2]: # Keep newest delete_timestamp - record[2] = row[2] - conn.execute('DELETE FROM container WHERE name = ?', - (record[0],)) - # If deleted, mark as such - if record[2] > record[1] and \ - record[3] in (None, '', 0, '0'): - record[5] = 1 - else: - record[5] = 0 - try: - conn.execute(''' - INSERT INTO container (name, put_timestamp, - delete_timestamp, object_count, bytes_used, - deleted) - VALUES (?, ?, ?, ?, ?, ?) - ''', record) - except sqlite3.IntegrityError: - continue + DELETE FROM container WHERE name = ? AND + deleted IN (0, 1) + ''', (record[0],)) + # If deleted, mark as such + if record[2] > record[1] and \ + record[3] in (None, '', 0, '0'): + record[5] = 1 + else: + record[5] = 0 + conn.execute(''' + INSERT INTO container (name, put_timestamp, + delete_timestamp, object_count, bytes_used, + deleted) + VALUES (?, ?, ?, ?, ?, ?) + ''', record) if source: max_rowid = max(max_rowid, rec['ROWID']) if source: From 2fffdfede24f79df757faffd197afff32ca432eb Mon Sep 17 00:00:00 2001 From: gholt Date: Fri, 4 Feb 2011 11:37:35 -0800 Subject: [PATCH 14/25] Move db version resolution to its own function --- swift/common/db.py | 36 +++++++++++++++++++++--------------- 1 file changed, 21 insertions(+), 15 deletions(-) diff --git a/swift/common/db.py b/swift/common/db.py index 4327ffa311..2341f8141f 100644 --- a/swift/common/db.py +++ b/swift/common/db.py @@ -166,7 +166,7 @@ class DatabaseBroker(object): self.logger = logger or logging.getLogger() self.account = account self.container = container - self.db_version = -1 + self._db_version = -1 def initialize(self, put_timestamp=None): """ @@ -645,6 +645,15 @@ class ContainerBroker(DatabaseBroker): ''', (self.account, self.container, normalize_timestamp(time.time()), str(uuid4()), put_timestamp)) + def _get_db_version(self, conn): + if self._db_version == -1: + self._db_version = 0 + for row in conn.execute(''' + SELECT name FROM sqlite_master + WHERE name = 'ix_object_deleted_name' '''): + self._db_version = 1 + return self._db_version + def _newid(self, conn): conn.execute(''' UPDATE container_stat @@ -813,12 +822,6 @@ class ContainerBroker(DatabaseBroker): reported_object_count, reported_bytes_used, hash, id) """ with self.get() as conn: - if self.db_version == -1: - self.db_version = 0 - for row in conn.execute(''' - SELECT name FROM sqlite_master - WHERE name = 'ix_object_deleted_name' '''): - self.db_version = 1 return conn.execute(''' SELECT account, container, created_at, put_timestamp, delete_timestamp, object_count, bytes_used, @@ -913,7 +916,7 @@ class ContainerBroker(DatabaseBroker): elif prefix: query += ' name >= ? AND' query_args.append(prefix) - if self.db_version < 1: + if self._get_db_version(conn) < 1: query += ' +deleted = 0 ORDER BY name LIMIT ?' else: query += ' deleted = 0 ORDER BY name LIMIT ?' @@ -1094,6 +1097,15 @@ class AccountBroker(DatabaseBroker): ''', (self.account, normalize_timestamp(time.time()), str(uuid4()), put_timestamp)) + def _get_db_version(self, conn): + if self._db_version == -1: + self._db_version = 0 + for row in conn.execute(''' + SELECT name FROM sqlite_master + WHERE name = 'ix_container_deleted_name' '''): + self._db_version = 1 + return self._db_version + def update_put_timestamp(self, timestamp): """ Update the put_timestamp. Only modifies it if it is greater than @@ -1299,12 +1311,6 @@ class AccountBroker(DatabaseBroker): bytes_used, hash, id) """ with self.get() as conn: - if self.db_version == -1: - self.db_version = 0 - for row in conn.execute(''' - SELECT name FROM sqlite_master - WHERE name = 'ix_container_deleted_name' '''): - self.db_version = 1 return conn.execute(''' SELECT account, created_at, put_timestamp, delete_timestamp, container_count, object_count, bytes_used, hash, id @@ -1373,7 +1379,7 @@ class AccountBroker(DatabaseBroker): elif prefix: query += ' name >= ? AND' query_args.append(prefix) - if self.db_version < 1: + if self._get_db_version(conn) < 1: query += ' +deleted = 0 ORDER BY name LIMIT ?' else: query += ' deleted = 0 ORDER BY name LIMIT ?' From 98090b7217c69bba06b2f9ecb1dfaceb29de877d Mon Sep 17 00:00:00 2001 From: gholt Date: Fri, 4 Feb 2011 11:50:30 -0800 Subject: [PATCH 15/25] Fix account db change --- swift/common/db.py | 16 ++++++---------- 1 file changed, 6 insertions(+), 10 deletions(-) diff --git a/swift/common/db.py b/swift/common/db.py index 2341f8141f..83cd0e8188 100644 --- a/swift/common/db.py +++ b/swift/common/db.py @@ -1430,12 +1430,8 @@ class AccountBroker(DatabaseBroker): SELECT name, put_timestamp, delete_timestamp, object_count, bytes_used, deleted FROM container WHERE name = ? AND - (put_timestamp < ? OR delete_timestamp < ? OR - object_count != ? OR bytes_used != ?) AND - deleted IN (0, 1)''', - (rec['name'], rec['put_timestamp'], - rec['delete_timestamp'], rec['object_count'], - rec['bytes_used'])) + deleted IN (0, 1) + ''', (rec['name'],)) curs.row_factory = None row = curs.fetchone() if row: @@ -1447,16 +1443,16 @@ class AccountBroker(DatabaseBroker): record[1] = row[1] if row[2] > record[2]: # Keep newest delete_timestamp record[2] = row[2] - conn.execute(''' - DELETE FROM container WHERE name = ? AND - deleted IN (0, 1) - ''', (record[0],)) # If deleted, mark as such if record[2] > record[1] and \ record[3] in (None, '', 0, '0'): record[5] = 1 else: record[5] = 0 + conn.execute(''' + DELETE FROM container WHERE name = ? AND + deleted IN (0, 1) + ''', (record[0],)) conn.execute(''' INSERT INTO container (name, put_timestamp, delete_timestamp, object_count, bytes_used, From 0f0e093972dccad7ec00f7e3fd73573aa09f4f46 Mon Sep 17 00:00:00 2001 From: Clay Gerrard Date: Fri, 4 Feb 2011 20:58:31 -0600 Subject: [PATCH 16/25] fix st command help hangs Before running the command function global the main func would start the print and error queues. Inside the command function the the option parser would see the the help option, print the help text, and raise SystemExit, which wasn't getting caught. --- bin/st | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/bin/st b/bin/st index 58285423bd..4e6024f84f 100755 --- a/bin/st +++ b/bin/st @@ -1723,7 +1723,7 @@ Example: error_thread.abort = True while error_thread.isAlive(): error_thread.join(0.01) - except Exception: + except (SystemExit, Exception): for thread in threading_enumerate(): thread.abort = True raise From 461bf8df712f1b03ed547bdf0a068aae434d50ef Mon Sep 17 00:00:00 2001 From: Clay Gerrard Date: Sat, 5 Feb 2011 15:38:49 -0600 Subject: [PATCH 17/25] added new proxy-server configuration options for access_log_facility and access_log_name --- swift/common/utils.py | 15 +++++++-------- swift/common/wsgi.py | 8 ++++---- swift/proxy/server.py | 12 +++++++++++- test/unit/common/test_utils.py | 4 ++-- test/unit/proxy/test_server.py | 10 +++++++--- 5 files changed, 31 insertions(+), 18 deletions(-) diff --git a/swift/common/utils.py b/swift/common/utils.py index 5c462b5d08..595ad3ac03 100644 --- a/swift/common/utils.py +++ b/swift/common/utils.py @@ -48,11 +48,11 @@ import logging logging.thread = eventlet.green.thread logging.threading = eventlet.green.threading logging._lock = logging.threading.RLock() -# setup access level logging -ACCESS = 25 -logging._levelNames[ACCESS] = 'ACCESS' +# setup notice level logging +NOTICE = 25 +logging._levelNames[NOTICE] = 'NOTICE' # syslog priority "notice" is used for proxy access log lines -SysLogHandler.priority_map['ACCESS'] = 'notice' +SysLogHandler.priority_map['NOTICE'] = 'notice' # These are lazily pulled from libc elsewhere _sys_fallocate = None @@ -315,15 +315,14 @@ class LogAdapter(object): def getEffectiveLevel(self): return self.logger.getEffectiveLevel() - def access(self, msg, *args): + def notice(self, msg, *args): """ - Convenience function for proxy access request log level. Only - proxy access log messages should use this method. The python + Convenience function for syslog priority LOG_NOTICE. The python logging lvl is set to 25, just above info. SysLogHandler is monkey patched to map this log lvl to the LOG_NOTICE syslog priority. """ - self.logger.log(ACCESS, msg, *args) + self.logger.log(NOTICE, msg, *args) def exception(self, msg, *args): _junk, exc, _junk = sys.exc_info() diff --git a/swift/common/wsgi.py b/swift/common/wsgi.py index 9450bcf439..e1e6e0c8f1 100644 --- a/swift/common/wsgi.py +++ b/swift/common/wsgi.py @@ -168,10 +168,10 @@ def run_wsgi(conf_file, app_section, *args, **kwargs): signal.signal(signal.SIGHUP, signal.SIG_DFL) signal.signal(signal.SIGTERM, signal.SIG_DFL) run_server() - logger.info('Child %d exiting normally' % os.getpid()) + logger.notice('Child %d exiting normally' % os.getpid()) return else: - logger.info('Started child %s' % pid) + logger.notice('Started child %s' % pid) children.append(pid) try: pid, status = os.wait() @@ -182,8 +182,8 @@ def run_wsgi(conf_file, app_section, *args, **kwargs): if err.errno not in (errno.EINTR, errno.ECHILD): raise except KeyboardInterrupt: - logger.info('User quit') + logger.notice('User quit') break greenio.shutdown_safe(sock) sock.close() - logger.info('Exited') + logger.notice('Exited') diff --git a/swift/proxy/server.py b/swift/proxy/server.py index dc501faba5..c4d8178c61 100644 --- a/swift/proxy/server.py +++ b/swift/proxy/server.py @@ -1612,6 +1612,16 @@ class BaseApplication(object): self.logger = logger if conf is None: conf = {} + if 'access_log_name' in conf or 'access_log_facility' in conf: + access_log_conf = { + 'log_name': conf.get('access_log_name', conf.get('log_name', + 'proxy-server')), + 'log_facility': conf.get('access_log_facility', + conf.get('log_facility', 'LOG_LOCAL0')), + } + self.access_logger = get_logger(access_log_conf) + else: + self.access_logger = self.logger swift_dir = conf.get('swift_dir', '/etc/swift') self.node_timeout = int(conf.get('node_timeout', 10)) self.conn_timeout = float(conf.get('conn_timeout', 0.5)) @@ -1790,7 +1800,7 @@ class Application(BaseApplication): if getattr(req, 'client_disconnect', False) or \ getattr(response, 'client_disconnect', False): status_int = 499 - self.logger.access(' '.join(quote(str(x)) for x in ( + self.access_logger.info(' '.join(quote(str(x)) for x in ( client or '-', req.remote_addr or '-', time.strftime('%d/%b/%Y/%H/%M/%S', time.gmtime()), diff --git a/test/unit/common/test_utils.py b/test/unit/common/test_utils.py index 1fd18b6ee6..d709c65d3e 100644 --- a/test/unit/common/test_utils.py +++ b/test/unit/common/test_utils.py @@ -307,8 +307,8 @@ Error: unable to locate %s logger.debug('test5') self.assertEquals(sio.getvalue(), 'test1\ntest3\ntest4\n') - # make sure access lvl logs by default - logger.access('test6') + # make sure notice lvl logs by default + logger.notice('test7') self.assertEquals(sio.getvalue(), 'test1\ntest3\ntest4\ntest6\n') diff --git a/test/unit/proxy/test_server.py b/test/unit/proxy/test_server.py index 4b0404454f..9e49b09e74 100644 --- a/test/unit/proxy/test_server.py +++ b/test/unit/proxy/test_server.py @@ -1802,11 +1802,12 @@ class TestObjectController(unittest.TestCase): class Logger(object): - def access(self, msg): + def info(self, msg): self.msg = msg orig_logger = prosrv.logger - prosrv.logger = Logger() + orig_access_logger = prosrv.access_logger + prosrv.logger = prosrv.access_logger = Logger() sock = connect_tcp(('localhost', prolis.getsockname()[1])) fd = sock.makefile() fd.write( @@ -1822,11 +1823,13 @@ class TestObjectController(unittest.TestCase): prosrv.logger.msg) exp = 'host1' self.assertEquals(prosrv.logger.msg[:len(exp)], exp) + prosrv.access_logger = orig_access_logger prosrv.logger = orig_logger # Turn on header logging. orig_logger = prosrv.logger - prosrv.logger = Logger() + orig_access_logger = prosrv.access_logger + prosrv.logger = prosrv.access_logger = Logger() prosrv.log_headers = True sock = connect_tcp(('localhost', prolis.getsockname()[1])) fd = sock.makefile() @@ -1840,6 +1843,7 @@ class TestObjectController(unittest.TestCase): self.assert_('Goofy-Header%3A%20True' in prosrv.logger.msg, prosrv.logger.msg) prosrv.log_headers = False + prosrv.access_logger = orig_access_logger prosrv.logger = orig_logger def test_chunked_put_utf8_all_the_way_down(self): From bb57e753b02cdd115aa9a440aed4597bc2ab20de Mon Sep 17 00:00:00 2001 From: gholt Date: Thu, 10 Feb 2011 00:01:07 -0800 Subject: [PATCH 18/25] Fix drive-audit's default log_name --- bin/swift-drive-audit | 1 + 1 file changed, 1 insertion(+) diff --git a/bin/swift-drive-audit b/bin/swift-drive-audit index 5203f54b6b..77912e720e 100755 --- a/bin/swift-drive-audit +++ b/bin/swift-drive-audit @@ -99,6 +99,7 @@ if __name__ == '__main__': device_dir = conf.get('device_dir', '/srv/node') minutes = int(conf.get('minutes', 60)) error_limit = int(conf.get('error_limit', 1)) + conf['log_name'] = conf.get('log_name', 'drive-audit') logger = get_logger(conf, log_route='drive-audit') devices = get_devices(device_dir, logger) logger.debug("Devices found: %s" % str(devices)) From f73d7ad52fafe95fbd06771c0bde8131e004b7d1 Mon Sep 17 00:00:00 2001 From: Chuck Thier Date: Thu, 10 Feb 2011 10:09:31 -0600 Subject: [PATCH 19/25] Adding python-netifaces to dependencies for packaging docs --- doc/source/debian_package_guide.rst | 1 + 1 file changed, 1 insertion(+) diff --git a/doc/source/debian_package_guide.rst b/doc/source/debian_package_guide.rst index 4f82f97858..e8086adc16 100644 --- a/doc/source/debian_package_guide.rst +++ b/doc/source/debian_package_guide.rst @@ -107,6 +107,7 @@ Instructions for Deploying Debian Packages for Swift apt-get install rsync python-openssl python-setuptools python-webob python-simplejson python-xattr python-greenlet python-eventlet + python-netifaces #. Install base packages:: From 8193e517af7be246da9e2d3a2aca7b85d3242191 Mon Sep 17 00:00:00 2001 From: Clay Gerrard Date: Thu, 10 Feb 2011 11:57:51 -0600 Subject: [PATCH 20/25] slightly more consistant stats process log names Also a quick fix to the auditor tests xattr mock --- bin/swift-account-stats-logger | 2 +- bin/swift-log-uploader | 2 +- swift/common/middleware/catch_errors.py | 6 +----- swift/stats/log_uploader.py | 6 +++--- test/unit/obj/test_auditor.py | 3 ++- 5 files changed, 8 insertions(+), 11 deletions(-) diff --git a/bin/swift-account-stats-logger b/bin/swift-account-stats-logger index 7b95b20249..6256b690b5 100755 --- a/bin/swift-account-stats-logger +++ b/bin/swift-account-stats-logger @@ -23,4 +23,4 @@ if __name__ == '__main__': # currently AccountStat only supports run_once options['once'] = True run_daemon(AccountStat, conf_file, section_name='log-processor-stats', - **options) + log_name="account-stats", **options) diff --git a/bin/swift-log-uploader b/bin/swift-log-uploader index 93cb8f6f97..7c36e2c2cc 100755 --- a/bin/swift-log-uploader +++ b/bin/swift-log-uploader @@ -34,7 +34,7 @@ if __name__ == '__main__': uploader_conf.update(plugin_conf) # pre-configure logger - logger = utils.get_logger(uploader_conf, plugin, log_route='log-uploader', + logger = utils.get_logger(uploader_conf, log_route='log-uploader', log_to_console=options.get('verbose', False)) # currently LogUploader only supports run_once options['once'] = True diff --git a/swift/common/middleware/catch_errors.py b/swift/common/middleware/catch_errors.py index 16ade84689..716bda4da1 100644 --- a/swift/common/middleware/catch_errors.py +++ b/swift/common/middleware/catch_errors.py @@ -26,11 +26,7 @@ class CatchErrorMiddleware(object): def __init__(self, app, conf): self.app = app - # if the application already has a logger we should use that one - self.logger = getattr(app, 'logger', None) - if not self.logger: - # and only call get_logger if we have to - self.logger = get_logger(conf, log_route='catch-errors') + self.logger = get_logger(conf, log_route='catch-errors') def __call__(self, env, start_response): try: diff --git a/swift/stats/log_uploader.py b/swift/stats/log_uploader.py index a828188eb7..d87d799324 100644 --- a/swift/stats/log_uploader.py +++ b/swift/stats/log_uploader.py @@ -64,9 +64,9 @@ class LogUploader(Daemon): self.container_name = container_name self.filename_format = source_filename_format self.internal_proxy = InternalProxy(proxy_server_conf) - log_name = 'swift-log-uploader-%s' % plugin_name - self.logger = \ - utils.get_logger(uploader_conf, plugin_name, log_route=plugin_name) + log_name = '%s-log-uploader' % plugin_name + self.logger = utils.get_logger(uploader_conf, log_name, + log_route=plugin_name) def run_once(self): self.logger.info(_("Uploading logs")) diff --git a/test/unit/obj/test_auditor.py b/test/unit/obj/test_auditor.py index 66540a3693..14d58480dd 100644 --- a/test/unit/obj/test_auditor.py +++ b/test/unit/obj/test_auditor.py @@ -14,7 +14,7 @@ # limitations under the License. # TODO: Tests -from test import unit as _setup_mocks +from test import unit import unittest import tempfile import os @@ -57,6 +57,7 @@ class TestAuditor(unittest.TestCase): def tearDown(self): rmtree(os.path.dirname(self.testdir), ignore_errors=1) + unit.xattr_data = {} def test_object_audit_extra_data(self): self.auditor = auditor.ObjectAuditor(self.conf) From 5d0bc6b9c76756a07648f04b4a309677fbec3635 Mon Sep 17 00:00:00 2001 From: Clay Gerrard Date: Thu, 10 Feb 2011 14:59:52 -0600 Subject: [PATCH 21/25] logging refactor to support proxy access logs New log level "notice" set to python log level 25 maps to syslog priority LOG_NOTICE. Used for some messages in the proxy server, but will be available to all apps using the LogAdapter returned from get_logger. Cleaned up some code in get_logger so that console logging works with log_routes and removed some unneeded bits. NamedFormatter functionality was split between LogAdapter (which now inherits from logging.LoggerAdapter) and TxnFormatter (which now is only responsible for adding the log records txn_id). The proxy server app now configures a separate logger for access line logging. By default it will use the same settings as the regular proxy logger. --- bin/swift-bench | 8 +- doc/source/overview_stats.rst | 15 +-- swift/common/utils.py | 149 +++++++++------------ swift/proxy/server.py | 24 ++-- test/unit/common/test_utils.py | 234 +++++++++++++++++++++++++++------ test/unit/proxy/test_server.py | 141 ++++++++++++++++++-- 6 files changed, 412 insertions(+), 159 deletions(-) diff --git a/bin/swift-bench b/bin/swift-bench index 3c167ee06f..0554782a06 100755 --- a/bin/swift-bench +++ b/bin/swift-bench @@ -22,7 +22,7 @@ import uuid from optparse import OptionParser from swift.common.bench import BenchController -from swift.common.utils import readconf, LogAdapter, NamedFormatter +from swift.common.utils import readconf, LogAdapter # The defaults should be sufficient to run swift-bench on a SAIO CONF_DEFAULTS = { @@ -125,9 +125,9 @@ if __name__ == '__main__': options.log_level.lower(), logging.INFO)) loghandler = logging.StreamHandler() logger.addHandler(loghandler) - logger = LogAdapter(logger) - logformat = NamedFormatter('swift-bench', logger, - fmt='%(server)s %(asctime)s %(levelname)s %(message)s') + logger = LogAdapter(logger, 'swift-bench') + logformat = logging.Formatter('%(server)s %(asctime)s %(levelname)s ' + '%(message)s') loghandler.setFormatter(logformat) controller = BenchController(logger, options) diff --git a/doc/source/overview_stats.rst b/doc/source/overview_stats.rst index 40a5dd01af..6364de4611 100644 --- a/doc/source/overview_stats.rst +++ b/doc/source/overview_stats.rst @@ -15,10 +15,9 @@ Access logs *********** Access logs are the proxy server logs. Rackspace uses syslog-ng to redirect -proxy log messages with the syslog priority LOG_NOTICE to an hourly log -file. For example, a proxy request that is made on August 4, 2010 at 12:37 gets -logged in a file named 2010080412. This allows easy log rotation and easy -per-hour log processing. +the proxy log output to an hourly log file. For example, a proxy request that +is made on August 4, 2010 at 12:37 gets logged in a file named 2010080412. +This allows easy log rotation and easy per-hour log processing. ****************** Account stats logs @@ -100,11 +99,11 @@ Running the stats system on SAIO destination df_local1 { file("/var/log/swift/proxy.log" owner() group()); }; destination df_local1_err { file("/var/log/swift/proxy.error" owner() group()); }; destination df_local1_hourly { file("/var/log/swift/hourly/$YEAR$MONTH$DAY$HOUR" owner() group()); }; - filter f_local1 { facility(local1) and level(notice); }; + filter f_local1 { facility(local1) and level(info); }; - filter f_local1_err { facility(local1) and not level(notice); }; + filter f_local1_err { facility(local1) and not level(info); }; - # local1.notice -/var/log/swift/proxy.log + # local1.info -/var/log/swift/proxy.log # write to local file and to remove log server log { source(s_all); @@ -182,4 +181,4 @@ earlier. This file will have one entry per account per hour for each account with activity in that hour. One .csv file should be produced per hour. Note that the stats will be delayed by at least two hours by default. This can be changed with the new_log_cutoff variable in the config file. See -`log-processing.conf-sample` for more details. +`log-processing.conf-sample` for more details. \ No newline at end of file diff --git a/swift/common/utils.py b/swift/common/utils.py index 595ad3ac03..3ba291e266 100644 --- a/swift/common/utils.py +++ b/swift/common/utils.py @@ -289,7 +289,8 @@ class LoggerFileObject(object): return self -class LogAdapter(object): +# double inhereitence to support property with setter +class LogAdapter(logging.LoggerAdapter, object): """ A Logger like object which performs some reformatting on calls to :meth:`exception`. Can be used to store a threadlocal transaction id. @@ -297,11 +298,10 @@ class LogAdapter(object): _txn_id = threading.local() - def __init__(self, logger): - self.logger = logger - for proxied_method in ('debug', 'log', 'warn', 'warning', 'error', - 'critical', 'info'): - setattr(self, proxied_method, getattr(logger, proxied_method)) + def __init__(self, logger, server): + logging.LoggerAdapter.__init__(self, logger, {}) + self.server = server + setattr(self, 'warn', self.warning) @property def txn_id(self): @@ -315,24 +315,34 @@ class LogAdapter(object): def getEffectiveLevel(self): return self.logger.getEffectiveLevel() - def notice(self, msg, *args): + def process(self, msg, kwargs): + """ + Add extra info to message + """ + kwargs['extra'] = {'server': self.server, 'txn_id': self.txn_id} + return msg, kwargs + + def notice(self, msg, *args, **kwargs): """ Convenience function for syslog priority LOG_NOTICE. The python logging lvl is set to 25, just above info. SysLogHandler is monkey patched to map this log lvl to the LOG_NOTICE syslog priority. """ - self.logger.log(NOTICE, msg, *args) + self.log(NOTICE, msg, *args, **kwargs) - def exception(self, msg, *args): + def _exception(self, msg, *args, **kwargs): + logging.LoggerAdapter.exception(self, msg, *args, **kwargs) + + def exception(self, msg, *args, **kwargs): _junk, exc, _junk = sys.exc_info() - call = self.logger.error + call = self.error emsg = '' if isinstance(exc, OSError): if exc.errno in (errno.EIO, errno.ENOSPC): emsg = str(exc) else: - call = self.logger.exception + call = self._exception elif isinstance(exc, socket.error): if exc.errno == errno.ECONNREFUSED: emsg = _('Connection refused') @@ -341,7 +351,7 @@ class LogAdapter(object): elif exc.errno == errno.ETIMEDOUT: emsg = _('Connection timeout') else: - call = self.logger.exception + call = self._exception elif isinstance(exc, eventlet.Timeout): emsg = exc.__class__.__name__ if hasattr(exc, 'seconds'): @@ -350,53 +360,25 @@ class LogAdapter(object): if exc.msg: emsg += ' %s' % exc.msg else: - call = self.logger.exception - call('%s: %s' % (msg, emsg), *args) + call = self._exception + call('%s: %s' % (msg, emsg), *args, **kwargs) -class NamedFormatter(logging.Formatter): +class TxnFormatter(logging.Formatter): """ - NamedFormatter is used to add additional information to log messages. - Normally it will simply add the server name as an attribute on the - LogRecord and the default format string will include it at the - begining of the log message. Additionally, if the transaction id is - available and not already included in the message, NamedFormatter will - add it. - - NamedFormatter may be initialized with a format string which makes use - of the standard LogRecord attributes. In addition the format string - may include the following mapping key: - - +----------------+---------------------------------------------+ - | Format | Description | - +================+=============================================+ - | %(server)s | Name of the swift server doing logging | - +----------------+---------------------------------------------+ - - :param server: the swift server name, a string. - :param logger: a Logger or :class:`LogAdapter` instance, additional - context may be pulled from attributes on this logger if - available. - :param fmt: the format string used to construct the message, if none is - supplied it defaults to ``"%(server)s %(message)s"`` + Custom logging.Formatter will append txn_id to a log message if the record + has one and the message does not. """ - - def __init__(self, server, logger, - fmt="%(server)s %(message)s"): - logging.Formatter.__init__(self, fmt) - self.server = server - self.logger = logger - def format(self, record): - record.server = self.server msg = logging.Formatter.format(self, record) - if self.logger.txn_id and (record.levelno != logging.INFO or - self.logger.txn_id not in msg): - msg = "%s (txn: %s)" % (msg, self.logger.txn_id) + if (record.txn_id and record.levelno != logging.INFO and + record.txn_id not in msg): + msg = "%s (txn: %s)" % (msg, record.txn_id) return msg -def get_logger(conf, name=None, log_to_console=False, log_route=None): +def get_logger(conf, name=None, log_to_console=False, log_route=None, + fmt="%(server)s %(message)s"): """ Get the current system logger using config settings. @@ -412,48 +394,46 @@ def get_logger(conf, name=None, log_to_console=False, log_route=None): """ if not conf: conf = {} - if not hasattr(get_logger, 'root_logger_configured'): - get_logger.root_logger_configured = True - get_logger(conf, name, log_to_console, log_route='root') if name is None: name = conf.get('log_name', 'swift') if not log_route: log_route = name - if log_route == 'root': - logger = logging.getLogger() - else: - logger = logging.getLogger(log_route) - logger.propagate = False - if not hasattr(get_logger, 'handler4facility'): - get_logger.handler4facility = {} - facility = getattr(SysLogHandler, conf.get('log_facility', 'LOG_LOCAL0'), - SysLogHandler.LOG_LOCAL0) - if facility in get_logger.handler4facility: - logger.removeHandler(get_logger.handler4facility[facility]) - get_logger.handler4facility[facility].close() - del get_logger.handler4facility[facility] - if log_to_console: - # check if a previous call to get_logger already added a console logger - if hasattr(get_logger, 'console') and get_logger.console: - logger.removeHandler(get_logger.console) - get_logger.console = logging.StreamHandler(sys.__stderr__) - logger.addHandler(get_logger.console) - get_logger.handler4facility[facility] = \ - SysLogHandler(address='/dev/log', facility=facility) + logger = logging.getLogger(log_route) + logger.propagate = False + # all swift new handlers will get the same formatter + formatter = TxnFormatter(fmt) + + # a single swift logger will only get one SysLog Handler if not hasattr(get_logger, 'handler4logger'): get_logger.handler4logger = {} if logger in get_logger.handler4logger: logger.removeHandler(get_logger.handler4logger[logger]) - get_logger.handler4logger[logger] = \ - get_logger.handler4facility[facility] - logger.addHandler(get_logger.handler4facility[facility]) + + # facility for this logger will be set by last call wins + facility = getattr(SysLogHandler, conf.get('log_facility', 'LOG_LOCAL0'), + SysLogHandler.LOG_LOCAL0) + handler = SysLogHandler(address='/dev/log', facility=facility) + handler.setFormatter(formatter) + logger.addHandler(handler) + get_logger.handler4logger[logger] = handler + + # setup console logging + if log_to_console or hasattr(get_logger, 'console_handler4logger'): + # remove pre-existing console handler for this logger + if not hasattr(get_logger, 'console_handler4logger'): + get_logger.console_handler4logger = {} + if logger in get_logger.console_handler4logger: + logger.removeHandler(get_logger.console_handler4logger[logger]) + + console_handler = logging.StreamHandler(sys.__stderr__) + console_handler.setFormatter(formatter) + logger.addHandler(console_handler) + get_logger.console_handler4logger[logger] = console_handler + + # set the level for the logger logger.setLevel( getattr(logging, conf.get('log_level', 'INFO').upper(), logging.INFO)) - adapted_logger = LogAdapter(logger) - formatter = NamedFormatter(name, adapted_logger) - get_logger.handler4facility[facility].setFormatter(formatter) - if hasattr(get_logger, 'console'): - get_logger.console.setFormatter(formatter) + adapted_logger = LogAdapter(logger, name) return adapted_logger @@ -486,8 +466,9 @@ def capture_stdio(logger, **kwargs): # collect stdio file desc not in use for logging stdio_fds = [0, 1, 2] - if hasattr(get_logger, 'console'): - stdio_fds.remove(get_logger.console.stream.fileno()) + for _junk, handler in getattr(get_logger, + 'console_handler4logger', {}).items(): + stdio_fds.remove(handler.stream.fileno()) with open(os.devnull, 'r+b') as nullfile: # close stdio (excludes fds open for logging) diff --git a/swift/proxy/server.py b/swift/proxy/server.py index c4d8178c61..b2b41d6434 100644 --- a/swift/proxy/server.py +++ b/swift/proxy/server.py @@ -1606,22 +1606,20 @@ class BaseApplication(object): def __init__(self, conf, memcache=None, logger=None, account_ring=None, container_ring=None, object_ring=None): - if logger is None: - self.logger = get_logger(conf) - else: - self.logger = logger if conf is None: conf = {} - if 'access_log_name' in conf or 'access_log_facility' in conf: - access_log_conf = { - 'log_name': conf.get('access_log_name', conf.get('log_name', - 'proxy-server')), - 'log_facility': conf.get('access_log_facility', - conf.get('log_facility', 'LOG_LOCAL0')), - } - self.access_logger = get_logger(access_log_conf) + if logger is None: + self.logger = get_logger(conf) + access_log_conf = {} + for key in ('log_facility', 'log_name', 'log_level'): + value = conf.get('access_' + key, conf.get(key, None)) + if value: + access_log_conf[key] = value + self.access_logger = get_logger(access_log_conf, + log_route='proxy-access') else: - self.access_logger = self.logger + self.logger = self.access_logger = logger + swift_dir = conf.get('swift_dir', '/etc/swift') self.node_timeout = int(conf.get('node_timeout', 10)) self.conn_timeout = float(conf.get('conn_timeout', 0.5)) diff --git a/test/unit/common/test_utils.py b/test/unit/common/test_utils.py index d709c65d3e..959caa8919 100644 --- a/test/unit/common/test_utils.py +++ b/test/unit/common/test_utils.py @@ -19,6 +19,7 @@ from __future__ import with_statement import logging import mimetools import os +import errno import socket import sys import time @@ -31,6 +32,8 @@ from tempfile import NamedTemporaryFile from eventlet import sleep +from swift.common.exceptions import TimeoutError, MessageTimeout, \ + ConnectionTimeout from swift.common import utils @@ -76,6 +79,17 @@ class MockSys(): __stderr__ = sys.__stderr__ +def reset_loggers(): + if hasattr(utils.get_logger, 'handler4logger'): + for logger, handler in utils.get_logger.handler4logger.items(): + logger.removeHandler(handler) + delattr(utils.get_logger, 'handler4logger') + if hasattr(utils.get_logger, 'console_handler4logger'): + for logger, h in utils.get_logger.console_handler4logger.items(): + logger.removeHandler(h) + delattr(utils.get_logger, 'console_handler4logger') + + class TestUtils(unittest.TestCase): """ Tests for swift.common.utils """ @@ -308,10 +322,131 @@ Error: unable to locate %s self.assertEquals(sio.getvalue(), 'test1\ntest3\ntest4\n') # make sure notice lvl logs by default - logger.notice('test7') - self.assertEquals(sio.getvalue(), - 'test1\ntest3\ntest4\ntest6\n') + logger.notice('test6') + def test_clean_logger_exception(self): + # setup stream logging + sio = StringIO() + logger = utils.get_logger(None) + handler = logging.StreamHandler(sio) + logger.logger.addHandler(handler) + + def strip_value(sio): + v = sio.getvalue() + sio.truncate(0) + return v + + def log_exception(exc): + try: + raise exc + except (Exception, TimeoutError): + logger.exception('blah') + try: + # establish base case + self.assertEquals(strip_value(sio), '') + logger.info('test') + self.assertEquals(strip_value(sio), 'test\n') + self.assertEquals(strip_value(sio), '') + logger.info('test') + logger.info('test') + self.assertEquals(strip_value(sio), 'test\ntest\n') + self.assertEquals(strip_value(sio), '') + + # test OSError + for en in (errno.EIO, errno.ENOSPC): + log_exception(OSError(en, 'my %s error message' % en)) + log_msg = strip_value(sio) + self.assert_('Traceback' not in log_msg) + self.assert_('my %s error message' % en in log_msg) + # unfiltered + log_exception(OSError()) + self.assert_('Traceback' in strip_value(sio)) + + # test socket.error + log_exception(socket.error(errno.ECONNREFUSED, + 'my error message')) + log_msg = strip_value(sio) + self.assert_('Traceback' not in log_msg) + self.assert_('errno.ECONNREFUSED message test' not in log_msg) + self.assert_('Connection refused' in log_msg) + log_exception(socket.error(errno.EHOSTUNREACH, + 'my error message')) + log_msg = strip_value(sio) + self.assert_('Traceback' not in log_msg) + self.assert_('my error message' not in log_msg) + self.assert_('Host unreachable' in log_msg) + log_exception(socket.error(errno.ETIMEDOUT, 'my error message')) + log_msg = strip_value(sio) + self.assert_('Traceback' not in log_msg) + self.assert_('my error message' not in log_msg) + self.assert_('Connection timeout' in log_msg) + # unfiltered + log_exception(socket.error(0, 'my error message')) + log_msg = strip_value(sio) + self.assert_('Traceback' in log_msg) + self.assert_('my error message' in log_msg) + + # test eventlet.Timeout + log_exception(ConnectionTimeout(42, 'my error message')) + log_msg = strip_value(sio) + self.assert_('Traceback' not in log_msg) + self.assert_('ConnectionTimeout' in log_msg) + self.assert_('(42s)' in log_msg) + self.assert_('my error message' not in log_msg) + log_exception(MessageTimeout(42, 'my error message')) + log_msg = strip_value(sio) + self.assert_('Traceback' not in log_msg) + self.assert_('MessageTimeout' in log_msg) + self.assert_('(42s)' in log_msg) + self.assert_('my error message' in log_msg) + + # test unhandled + log_exception(Exception('my error message')) + log_msg = strip_value(sio) + self.assert_('Traceback' in log_msg) + self.assert_('my error message' in log_msg) + + finally: + logger.logger.removeHandler(handler) + reset_loggers() + + def test_txn_formatter(self): + # setup stream logging + sio = StringIO() + logger = utils.get_logger(None) + handler = logging.StreamHandler(sio) + handler.setFormatter(utils.TxnFormatter()) + logger.logger.addHandler(handler) + + def strip_value(sio): + v = sio.getvalue() + sio.truncate(0) + return v + + try: + self.assertFalse(logger.txn_id) + logger.error('my error message') + log_msg = strip_value(sio) + self.assert_('my error message' in log_msg) + self.assert_('txn' not in log_msg) + logger.txn_id = '12345' + logger.error('test') + log_msg = strip_value(sio) + self.assert_('txn' in log_msg) + self.assert_('12345' in log_msg) + # test no txn on info message + self.assertEquals(logger.txn_id, '12345') + logger.info('test') + log_msg = strip_value(sio) + self.assert_('txn' not in log_msg) + self.assert_('12345' not in log_msg) + # test txn already in message + self.assertEquals(logger.txn_id, '12345') + logger.warn('test 12345 test') + self.assertEquals(strip_value(sio), 'test 12345 test\n') + finally: + logger.logger.removeHandler(handler) + reset_loggers() def test_storage_directory(self): self.assertEquals(utils.storage_directory('objects', '1', 'ABCDEF'), @@ -397,56 +532,71 @@ log_name = yarr''' logger = utils.get_logger(None, 'dummy') # mock utils system modules - utils.sys = MockSys() - utils.os = MockOs() + _orig_sys = utils.sys + _orig_os = utils.os + try: + utils.sys = MockSys() + utils.os = MockOs() - # basic test - utils.capture_stdio(logger) - self.assert_(utils.sys.excepthook is not None) - self.assertEquals(utils.os.closed_fds, [0, 1, 2]) - self.assert_(utils.sys.stdout is not None) - self.assert_(utils.sys.stderr is not None) + # basic test + utils.capture_stdio(logger) + self.assert_(utils.sys.excepthook is not None) + self.assertEquals(utils.os.closed_fds, [0, 1, 2]) + self.assert_(utils.sys.stdout is not None) + self.assert_(utils.sys.stderr is not None) - # reset; test same args, but exc when trying to close stdio - utils.os = MockOs(raise_funcs=('dup2',)) - utils.sys = MockSys() + # reset; test same args, but exc when trying to close stdio + utils.os = MockOs(raise_funcs=('dup2',)) + utils.sys = MockSys() - # test unable to close stdio - utils.capture_stdio(logger) - self.assert_(utils.sys.excepthook is not None) - self.assertEquals(utils.os.closed_fds, []) - self.assert_(utils.sys.stdout is not None) - self.assert_(utils.sys.stderr is not None) + # test unable to close stdio + utils.capture_stdio(logger) + self.assert_(utils.sys.excepthook is not None) + self.assertEquals(utils.os.closed_fds, []) + self.assert_(utils.sys.stdout is not None) + self.assert_(utils.sys.stderr is not None) - # reset; test some other args - logger = utils.get_logger(None, log_to_console=True) - utils.os = MockOs() - utils.sys = MockSys() + # reset; test some other args + logger = utils.get_logger(None, log_to_console=True) + utils.os = MockOs() + utils.sys = MockSys() - # test console log - utils.capture_stdio(logger, capture_stdout=False, - capture_stderr=False) - self.assert_(utils.sys.excepthook is not None) - # when logging to console, stderr remains open - self.assertEquals(utils.os.closed_fds, [0, 1]) - logger.logger.removeHandler(utils.get_logger.console) - # stdio not captured - self.assertFalse(hasattr(utils.sys, 'stdout')) - self.assertFalse(hasattr(utils.sys, 'stderr')) + # test console log + utils.capture_stdio(logger, capture_stdout=False, + capture_stderr=False) + self.assert_(utils.sys.excepthook is not None) + # when logging to console, stderr remains open + self.assertEquals(utils.os.closed_fds, [0, 1]) + reset_loggers() + + # stdio not captured + self.assertFalse(hasattr(utils.sys, 'stdout')) + self.assertFalse(hasattr(utils.sys, 'stderr')) + reset_loggers() + finally: + utils.sys = _orig_sys + utils.os = _orig_os def test_get_logger_console(self): - reload(utils) # reset get_logger attrs + reset_loggers() logger = utils.get_logger(None) - self.assertFalse(hasattr(utils.get_logger, 'console')) + console_handlers = [h for h in logger.logger.handlers if + isinstance(h, logging.StreamHandler)] + self.assertFalse(console_handlers) logger = utils.get_logger(None, log_to_console=True) - self.assert_(hasattr(utils.get_logger, 'console')) - self.assert_(isinstance(utils.get_logger.console, - logging.StreamHandler)) + console_handlers = [h for h in logger.logger.handlers if + isinstance(h, logging.StreamHandler)] + self.assert_(console_handlers) # make sure you can't have two console handlers - old_handler = utils.get_logger.console + self.assertEquals(len(console_handlers), 1) + old_handler = console_handlers[0] logger = utils.get_logger(None, log_to_console=True) - self.assertNotEquals(utils.get_logger.console, old_handler) - logger.logger.removeHandler(utils.get_logger.console) + console_handlers = [h for h in logger.logger.handlers if + isinstance(h, logging.StreamHandler)] + self.assertEquals(len(console_handlers), 1) + new_handler = console_handlers[0] + self.assertNotEquals(new_handler, old_handler) + reset_loggers() def test_ratelimit_sleep(self): running_time = 0 diff --git a/test/unit/proxy/test_server.py b/test/unit/proxy/test_server.py index 9e49b09e74..71b61e1e2c 100644 --- a/test/unit/proxy/test_server.py +++ b/test/unit/proxy/test_server.py @@ -16,6 +16,7 @@ from __future__ import with_statement import cPickle as pickle import logging +from logging.handlers import SysLogHandler import os import sys import unittest @@ -465,8 +466,138 @@ class TestController(unittest.TestCase): test(404, 507, 503) test(503, 503, 503) + class TestProxyServer(unittest.TestCase): + def test_access_log(self): + + class MyApp(proxy_server.Application): + + def handle_request(self, req): + resp = Response(request=req) + req.response = resp + req.start_time = time() + return resp + + def start_response(*args): + pass + + class MockLogger(): + + def __init__(self): + self.buffer = StringIO() + + def info(self, msg, args=None): + if args: + msg = msg % args + self.buffer.write(msg) + + def strip_value(self): + rv = self.buffer.getvalue() + self.buffer.truncate(0) + return rv + + class SnarfStream(object): + # i can't seem to subclass cStringIO + + def __init__(self, *args, **kwargs): + self.sio = StringIO() + + def strip_value(self): + rv = self.getvalue().strip() + self.truncate(0) + return rv + + def __getattr__(self, name): + try: + return object.__getattr__(self, name) + except AttributeError: + try: + return getattr(self.sio, name) + except AttributeError: + return self.__getattribute__(name) + + snarf = SnarfStream() + _orig_get_logger = proxy_server.get_logger + + def mock_get_logger(*args, **kwargs): + if kwargs.get('log_route') != 'proxy-access': + return _orig_get_logger(*args, **kwargs) + kwargs['log_route'] = 'snarf' + logger = _orig_get_logger(*args, **kwargs) + if [h for h in logger.logger.handlers if + isinstance(h, logging.StreamHandler) and h.stream is snarf]: + # snarf handler already setup! + return logger + formatter = logger.logger.handlers[0].formatter + formatter._fmt += ' %(levelname)s' + snarf_handler = logging.StreamHandler(snarf) + snarf_handler.setFormatter(formatter) + logger.logger.addHandler(snarf_handler) + return logger + + def test_conf(conf): + app = MyApp(conf, memcache=FakeMemcache(), account_ring=FakeRing(), + container_ring=FakeRing(), object_ring=FakeRing()) + req = Request.blank('') + app(req.environ, start_response) + + try: + proxy_server.get_logger = mock_get_logger + test_conf({}) + line = snarf.strip_value() + print line + self.assert_(line.startswith('swift')) + self.assert_(line.endswith('INFO')) + test_conf({'log_name': 'snarf-test'}) + line = snarf.strip_value() + print line + self.assert_(line.startswith('snarf-test')) + self.assert_(line.endswith('INFO')) + test_conf({'log_name': 'snarf-test', 'log_level': 'ERROR'}) + line = snarf.strip_value() + print line + self.assertFalse(line) + test_conf({'log_name': 'snarf-test', 'log_level': 'ERROR', + 'access_log_name': 'access-test', + 'access_log_level': 'INFO'}) + line = snarf.strip_value() + print line + self.assert_(line.startswith('access-test')) + self.assert_(line.endswith('INFO')) + + # test facility + def get_facility(logger): + h = [h for h in logger.logger.handlers if + isinstance(h, SysLogHandler)][0] + return h.facility + + conf = {'log_facility': 'LOG_LOCAL0'} + app = MyApp(conf, memcache=FakeMemcache(), account_ring=FakeRing(), + container_ring=FakeRing(), object_ring=FakeRing()) + self.assertEquals(get_facility(app.logger), + SysLogHandler.LOG_LOCAL0) + self.assertEquals(get_facility(app.access_logger), + SysLogHandler.LOG_LOCAL0) + conf = {'log_facility': 'LOG_LOCAL0', + 'access_log_facility': 'LOG_LOCAL1'} + app = MyApp(conf, memcache=FakeMemcache(), account_ring=FakeRing(), + container_ring=FakeRing(), object_ring=FakeRing()) + self.assertEquals(get_facility(app.logger), + SysLogHandler.LOG_LOCAL0) + self.assertEquals(get_facility(app.access_logger), + SysLogHandler.LOG_LOCAL1) + conf = {'access_log_facility': 'LOG_LOCAL1'} + app = MyApp(conf, memcache=FakeMemcache(), account_ring=FakeRing(), + container_ring=FakeRing(), object_ring=FakeRing()) + self.assertEquals(get_facility(app.logger), + SysLogHandler.LOG_LOCAL0) + self.assertEquals(get_facility(app.access_logger), + SysLogHandler.LOG_LOCAL1) + + finally: + proxy_server.get_logger = _orig_get_logger + def test_unhandled_exception(self): class MyApp(proxy_server.Application): @@ -1805,8 +1936,7 @@ class TestObjectController(unittest.TestCase): def info(self, msg): self.msg = msg - orig_logger = prosrv.logger - orig_access_logger = prosrv.access_logger + orig_logger, orig_access_logger = prosrv.logger, prosrv.access_logger prosrv.logger = prosrv.access_logger = Logger() sock = connect_tcp(('localhost', prolis.getsockname()[1])) fd = sock.makefile() @@ -1823,12 +1953,8 @@ class TestObjectController(unittest.TestCase): prosrv.logger.msg) exp = 'host1' self.assertEquals(prosrv.logger.msg[:len(exp)], exp) - prosrv.access_logger = orig_access_logger - prosrv.logger = orig_logger # Turn on header logging. - orig_logger = prosrv.logger - orig_access_logger = prosrv.access_logger prosrv.logger = prosrv.access_logger = Logger() prosrv.log_headers = True sock = connect_tcp(('localhost', prolis.getsockname()[1])) @@ -1843,8 +1969,7 @@ class TestObjectController(unittest.TestCase): self.assert_('Goofy-Header%3A%20True' in prosrv.logger.msg, prosrv.logger.msg) prosrv.log_headers = False - prosrv.access_logger = orig_access_logger - prosrv.logger = orig_logger + prosrv.logger, prosrv.access_logger = orig_logger, orig_access_logger def test_chunked_put_utf8_all_the_way_down(self): # Test UTF-8 Unicode all the way through the system From 5082b6d38958234351756757385f0301ff704087 Mon Sep 17 00:00:00 2001 From: Clay Gerrard Date: Thu, 10 Feb 2011 15:05:53 -0600 Subject: [PATCH 22/25] updated proxy-server.conf-sample to include access_log_* defaults --- etc/proxy-server.conf-sample | 3 +++ 1 file changed, 3 insertions(+) diff --git a/etc/proxy-server.conf-sample b/etc/proxy-server.conf-sample index fad511ca30..3af7db0f8a 100644 --- a/etc/proxy-server.conf-sample +++ b/etc/proxy-server.conf-sample @@ -24,6 +24,9 @@ use = egg:swift#proxy # set log_name = proxy-server # set log_facility = LOG_LOCAL0 # set log_level = INFO +# set access_log_name = proxy-server +# set access_log_facility = LOG_LOCAL0 +# set access_log_level = INFO # set log_headers = False # recheck_account_existence = 60 # recheck_container_existence = 60 From c973bf53fb08efd93943511f367b1fb5075fde41 Mon Sep 17 00:00:00 2001 From: Clay Gerrard Date: Thu, 10 Feb 2011 15:23:59 -0600 Subject: [PATCH 23/25] cleaned up some comments --- swift/common/utils.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/swift/common/utils.py b/swift/common/utils.py index 3ba291e266..4df8b624bc 100644 --- a/swift/common/utils.py +++ b/swift/common/utils.py @@ -51,7 +51,6 @@ logging._lock = logging.threading.RLock() # setup notice level logging NOTICE = 25 logging._levelNames[NOTICE] = 'NOTICE' -# syslog priority "notice" is used for proxy access log lines SysLogHandler.priority_map['NOTICE'] = 'notice' # These are lazily pulled from libc elsewhere @@ -289,7 +288,7 @@ class LoggerFileObject(object): return self -# double inhereitence to support property with setter +# double inheritance to support property with setter class LogAdapter(logging.LoggerAdapter, object): """ A Logger like object which performs some reformatting on calls to @@ -391,6 +390,7 @@ def get_logger(conf, name=None, log_to_console=False, log_route=None, :param conf: Configuration dict to read settings from :param name: Name of the logger :param log_to_console: Add handler which writes to console on stderr + :param fmt: Override log format """ if not conf: conf = {} @@ -400,10 +400,10 @@ def get_logger(conf, name=None, log_to_console=False, log_route=None, log_route = name logger = logging.getLogger(log_route) logger.propagate = False - # all swift new handlers will get the same formatter + # all new handlers will get the same formatter formatter = TxnFormatter(fmt) - # a single swift logger will only get one SysLog Handler + # get_logger will only ever add one SysLog Handler to a logger if not hasattr(get_logger, 'handler4logger'): get_logger.handler4logger = {} if logger in get_logger.handler4logger: From 0c0920701a95d0b96c3e50dff31f7b1acc81b905 Mon Sep 17 00:00:00 2001 From: gholt Date: Thu, 10 Feb 2011 15:10:53 -0800 Subject: [PATCH 24/25] PEP8 Fixes --- swift/common/db.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/swift/common/db.py b/swift/common/db.py index 83cd0e8188..9f322e7b7d 100644 --- a/swift/common/db.py +++ b/swift/common/db.py @@ -287,7 +287,7 @@ class DatabaseBroker(object): self.conn = None orig_isolation_level = conn.isolation_level conn.isolation_level = None - conn.execute('PRAGMA journal_mode = DELETE') # remove any journal files + conn.execute('PRAGMA journal_mode = DELETE') # remove journal files conn.execute('BEGIN IMMEDIATE') try: yield True @@ -295,7 +295,7 @@ class DatabaseBroker(object): pass try: conn.execute('ROLLBACK') - conn.execute('PRAGMA journal_mode = WAL') # back to WAL mode + conn.execute('PRAGMA journal_mode = WAL') # back to WAL mode conn.isolation_level = orig_isolation_level self.conn = conn except Exception: From 694fa02b6741148b7e7a4c04da9be0af3c6f6708 Mon Sep 17 00:00:00 2001 From: Devin Carlen Date: Sat, 12 Feb 2011 18:27:59 -0800 Subject: [PATCH 25/25] Added missing lockfile configuration to sample rsync.conf --- etc/rsyncd.conf-sample | 3 +++ 1 file changed, 3 insertions(+) diff --git a/etc/rsyncd.conf-sample b/etc/rsyncd.conf-sample index 2f0c9a84e2..c3b9952b16 100644 --- a/etc/rsyncd.conf-sample +++ b/etc/rsyncd.conf-sample @@ -7,13 +7,16 @@ pid file = /var/run/rsyncd.pid max connections = 2 path = /srv/node read only = false +lock file = /var/lock/account.lock [container] max connections = 4 path = /srv/node read only = false +lock file = /var/lock/container.lock [object] max connections = 8 path = /srv/node read only = false +lock file = /var/lock/object.lock