1252 lines
50 KiB
Python
1252 lines
50 KiB
Python
# Copyright (c) 2010-2024 OpenStack Foundation
|
|
#
|
|
# Licensed under the Apache License, Version 2.0 (the "License");
|
|
# you may not use this file except in compliance with the License.
|
|
# You may obtain a copy of the License at
|
|
#
|
|
# http://www.apache.org/licenses/LICENSE-2.0
|
|
#
|
|
# Unless required by applicable law or agreed to in writing, software
|
|
# distributed under the License is distributed on an "AS IS" BASIS,
|
|
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or
|
|
# implied.
|
|
# See the License for the specific language governing permissions and
|
|
# limitations under the License.
|
|
|
|
"""Tests for swift.common.utils.logs"""
|
|
from __future__ import print_function
|
|
|
|
import contextlib
|
|
import errno
|
|
import hashlib
|
|
import logging
|
|
import os
|
|
import socket
|
|
import sys
|
|
import time
|
|
import unittest
|
|
import eventlet
|
|
import functools
|
|
import mock
|
|
|
|
import six
|
|
from six import StringIO
|
|
from six.moves import http_client
|
|
|
|
from test.unit import with_tempdir
|
|
from test.unit import quiet_eventlet_exceptions
|
|
from test.unit.common.test_utils import MockOs, MockSys
|
|
from swift.common.exceptions import Timeout, \
|
|
MessageTimeout, ConnectionTimeout
|
|
|
|
if six.PY2:
|
|
import eventlet.green.httplib as green_http_client
|
|
else:
|
|
import eventlet.green.http.client as green_http_client
|
|
|
|
from swift.common import utils
|
|
|
|
from swift.common.swob import Request, Response
|
|
from swift.common.utils.logs import SwiftLogFormatter
|
|
|
|
|
|
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')
|
|
# Reset the LogAdapter class thread local state. Use get_logger() here
|
|
# to fetch a LogAdapter instance because the items from
|
|
# get_logger.handler4logger above are the underlying logger instances,
|
|
# not the LogAdapter.
|
|
utils.get_logger(None).thread_locals = (None, None)
|
|
|
|
|
|
def reset_logger_state(f):
|
|
@functools.wraps(f)
|
|
def wrapper(self, *args, **kwargs):
|
|
reset_loggers()
|
|
try:
|
|
return f(self, *args, **kwargs)
|
|
finally:
|
|
reset_loggers()
|
|
return wrapper
|
|
|
|
|
|
class TestUtilsLogs(unittest.TestCase):
|
|
|
|
def test_NullLogger(self):
|
|
# Test swift.common.utils.NullLogger
|
|
sio = StringIO()
|
|
nl = utils.NullLogger()
|
|
nl.write('test')
|
|
self.assertEqual(sio.getvalue(), '')
|
|
|
|
def test_LoggerFileObject(self):
|
|
orig_stdout = sys.stdout
|
|
orig_stderr = sys.stderr
|
|
sio = StringIO()
|
|
handler = logging.StreamHandler(sio)
|
|
logger = logging.getLogger()
|
|
logger.addHandler(handler)
|
|
lfo_stdout = utils.LoggerFileObject(logger)
|
|
lfo_stderr = utils.LoggerFileObject(logger, 'STDERR')
|
|
print('test1')
|
|
self.assertEqual(sio.getvalue(), '')
|
|
sys.stdout = lfo_stdout
|
|
print('test2')
|
|
self.assertEqual(sio.getvalue(), 'STDOUT: test2\n')
|
|
sys.stderr = lfo_stderr
|
|
print('test4', file=sys.stderr)
|
|
self.assertEqual(sio.getvalue(), 'STDOUT: test2\nSTDERR: test4\n')
|
|
sys.stdout = orig_stdout
|
|
print('test5')
|
|
self.assertEqual(sio.getvalue(), 'STDOUT: test2\nSTDERR: test4\n')
|
|
print('test6', file=sys.stderr)
|
|
self.assertEqual(sio.getvalue(), 'STDOUT: test2\nSTDERR: test4\n'
|
|
'STDERR: test6\n')
|
|
sys.stderr = orig_stderr
|
|
print('test8')
|
|
self.assertEqual(sio.getvalue(), 'STDOUT: test2\nSTDERR: test4\n'
|
|
'STDERR: test6\n')
|
|
lfo_stdout.writelines(['a', 'b', 'c'])
|
|
self.assertEqual(sio.getvalue(), 'STDOUT: test2\nSTDERR: test4\n'
|
|
'STDERR: test6\nSTDOUT: a#012b#012c\n')
|
|
lfo_stdout.close()
|
|
lfo_stderr.close()
|
|
lfo_stdout.write('d')
|
|
self.assertEqual(sio.getvalue(), 'STDOUT: test2\nSTDERR: test4\n'
|
|
'STDERR: test6\nSTDOUT: a#012b#012c\nSTDOUT: d\n')
|
|
lfo_stdout.flush()
|
|
self.assertEqual(sio.getvalue(), 'STDOUT: test2\nSTDERR: test4\n'
|
|
'STDERR: test6\nSTDOUT: a#012b#012c\nSTDOUT: d\n')
|
|
for lfo in (lfo_stdout, lfo_stderr):
|
|
got_exc = False
|
|
try:
|
|
for line in lfo:
|
|
pass
|
|
except Exception:
|
|
got_exc = True
|
|
self.assertTrue(got_exc)
|
|
got_exc = False
|
|
try:
|
|
for line in lfo:
|
|
pass
|
|
except Exception:
|
|
got_exc = True
|
|
self.assertTrue(got_exc)
|
|
self.assertRaises(IOError, lfo.read)
|
|
self.assertRaises(IOError, lfo.read, 1024)
|
|
self.assertRaises(IOError, lfo.readline)
|
|
self.assertRaises(IOError, lfo.readline, 1024)
|
|
lfo.tell()
|
|
|
|
def test_LoggerFileObject_recursion(self):
|
|
crashy_calls = [0]
|
|
|
|
class CrashyLogger(logging.Handler):
|
|
def emit(self, record):
|
|
crashy_calls[0] += 1
|
|
try:
|
|
# Pretend to be trying to send to syslog, but syslogd is
|
|
# dead. We need the raise here to set sys.exc_info.
|
|
raise socket.error(errno.ENOTCONN, "This is an ex-syslog")
|
|
except socket.error:
|
|
self.handleError(record)
|
|
|
|
logger = logging.getLogger()
|
|
logger.setLevel(logging.DEBUG)
|
|
handler = CrashyLogger()
|
|
logger.addHandler(handler)
|
|
|
|
# Set up some real file descriptors for stdio. If you run
|
|
# nosetests with "-s", you already have real files there, but
|
|
# otherwise they're StringIO objects.
|
|
#
|
|
# In any case, since capture_stdio() closes sys.stdin and friends,
|
|
# we'd want to set up some sacrificial files so as to not goof up
|
|
# the testrunner.
|
|
new_stdin = open(os.devnull, 'r+b')
|
|
new_stdout = open(os.devnull, 'w+b')
|
|
new_stderr = open(os.devnull, 'w+b')
|
|
|
|
with contextlib.closing(new_stdin), contextlib.closing(new_stdout), \
|
|
contextlib.closing(new_stderr):
|
|
# logging.raiseExceptions is set to False in test/__init__.py, but
|
|
# is True in Swift daemons, and the error doesn't manifest without
|
|
# it.
|
|
with mock.patch('sys.stdin', new_stdin), \
|
|
mock.patch('sys.stdout', new_stdout), \
|
|
mock.patch('sys.stderr', new_stderr), \
|
|
mock.patch.object(logging, 'raiseExceptions', True):
|
|
# Note: since stdio is hooked up to /dev/null in here, using
|
|
# pdb is basically impossible. Sorry about that.
|
|
utils.capture_stdio(logger)
|
|
logger.info("I like ham")
|
|
self.assertGreater(crashy_calls[0], 1)
|
|
|
|
logger.removeHandler(handler)
|
|
|
|
def test_get_logger(self):
|
|
sio = StringIO()
|
|
logger = logging.getLogger('server')
|
|
logger.addHandler(logging.StreamHandler(sio))
|
|
logger = utils.get_logger(None, 'server', log_route='server')
|
|
logger.warning('test1')
|
|
self.assertEqual(sio.getvalue(), 'test1\n')
|
|
logger.debug('test2')
|
|
self.assertEqual(sio.getvalue(), 'test1\n')
|
|
logger = utils.get_logger({'log_level': 'DEBUG'}, 'server',
|
|
log_route='server')
|
|
logger.debug('test3')
|
|
self.assertEqual(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',
|
|
log_route='server')
|
|
logger.warning('test4')
|
|
self.assertEqual(sio.getvalue(),
|
|
'test1\ntest3\ntest4\n')
|
|
# make sure debug doesn't log by default
|
|
logger.debug('test5')
|
|
self.assertEqual(sio.getvalue(),
|
|
'test1\ntest3\ntest4\n')
|
|
# make sure notice lvl logs by default
|
|
logger.notice('test6')
|
|
self.assertEqual(sio.getvalue(),
|
|
'test1\ntest3\ntest4\ntest6\n')
|
|
|
|
def test_get_logger_name_and_route(self):
|
|
@contextlib.contextmanager
|
|
def add_log_handler(logger):
|
|
# install a handler to capture log messages formatted as per swift
|
|
sio = StringIO()
|
|
handler = logging.StreamHandler(sio)
|
|
handler.setFormatter(SwiftLogFormatter(
|
|
fmt="%(server)s: %(message)s", max_line_length=20)
|
|
)
|
|
logger.logger.addHandler(handler)
|
|
yield sio
|
|
logger.logger.removeHandler(handler)
|
|
|
|
logger = utils.get_logger({}, name='name', log_route='route')
|
|
# log_route becomes the LogAdapter.name and logging.Logger.name
|
|
self.assertEqual('route', logger.name)
|
|
self.assertEqual('route', logger.logger.name)
|
|
# name becomes the LogAdapter.server!
|
|
self.assertEqual('name', logger.server)
|
|
# LogAdapter.server is used when formatting a log message
|
|
with add_log_handler(logger) as sio:
|
|
logger.info('testing')
|
|
self.assertEqual('name: testing\n', sio.getvalue())
|
|
|
|
logger = utils.get_logger({'log_name': 'conf-name'}, name='name',
|
|
log_route='route')
|
|
self.assertEqual('route', logger.name)
|
|
self.assertEqual('name', logger.server)
|
|
with add_log_handler(logger) as sio:
|
|
logger.info('testing')
|
|
self.assertEqual('name: testing\n', sio.getvalue())
|
|
|
|
logger = utils.get_logger({'log_name': 'conf-name'}, log_route='route')
|
|
self.assertEqual('route', logger.name)
|
|
self.assertEqual('conf-name', logger.server)
|
|
with add_log_handler(logger) as sio:
|
|
logger.info('testing')
|
|
self.assertEqual('conf-name: testing\n', sio.getvalue())
|
|
|
|
logger = utils.get_logger({'log_name': 'conf-name'})
|
|
self.assertEqual('conf-name', logger.name)
|
|
self.assertEqual('conf-name', logger.server)
|
|
with add_log_handler(logger) as sio:
|
|
logger.info('testing')
|
|
self.assertEqual('conf-name: testing\n', sio.getvalue())
|
|
|
|
logger = utils.get_logger({})
|
|
self.assertEqual('swift', logger.name)
|
|
self.assertEqual('swift', logger.server)
|
|
with add_log_handler(logger) as sio:
|
|
logger.info('testing')
|
|
self.assertEqual('swift: testing\n', sio.getvalue())
|
|
|
|
logger = utils.get_logger({}, log_route='route')
|
|
self.assertEqual('route', logger.name)
|
|
self.assertEqual('swift', logger.server)
|
|
with add_log_handler(logger) as sio:
|
|
logger.info('testing')
|
|
self.assertEqual('swift: testing\n', sio.getvalue())
|
|
|
|
# same log_route, different names...
|
|
logger1 = utils.get_logger({'log_statsd_host': '1.2.3.4'},
|
|
name='name1', log_route='route')
|
|
logger2 = utils.get_logger({'log_statsd_host': '1.2.3.5'},
|
|
name='name2', log_route='route')
|
|
self.assertEqual('route', logger1.name)
|
|
self.assertEqual('route', logger1.logger.name)
|
|
self.assertEqual('name1', logger1.server)
|
|
# oh dear, the statsd client on the common logging.Logger instance got
|
|
# mutated when logger2 was created
|
|
self.assertEqual('name2.', logger1.logger.statsd_client._prefix)
|
|
self.assertEqual('route', logger2.name)
|
|
self.assertEqual('route', logger2.logger.name)
|
|
self.assertEqual('name2', logger2.server)
|
|
self.assertEqual('name2.', logger2.logger.statsd_client._prefix)
|
|
self.assertIs(logger2.logger, logger1.logger)
|
|
with add_log_handler(logger1) as sio:
|
|
logger1.info('testing')
|
|
self.assertEqual('name1: testing\n', sio.getvalue())
|
|
with add_log_handler(logger2) as sio:
|
|
logger2.info('testing')
|
|
self.assertEqual('name2: testing\n', sio.getvalue())
|
|
|
|
# different log_route, different names...
|
|
logger1 = utils.get_logger({'log_statsd_host': '1.2.3.4'},
|
|
name='name1', log_route='route1')
|
|
logger2 = utils.get_logger({'log_statsd_host': '1.2.3.5'},
|
|
name='name2', log_route='route2')
|
|
self.assertEqual('route1', logger1.name)
|
|
self.assertEqual('route1', logger1.logger.name)
|
|
self.assertEqual('name1', logger1.server)
|
|
self.assertEqual('name1.', logger1.logger.statsd_client._prefix)
|
|
self.assertEqual('route2', logger2.name)
|
|
self.assertEqual('route2', logger2.logger.name)
|
|
self.assertEqual('name2', logger2.server)
|
|
self.assertEqual('name2.', logger2.logger.statsd_client._prefix)
|
|
self.assertIsNot(logger2.logger, logger1.logger)
|
|
with add_log_handler(logger1) as sio:
|
|
logger1.info('testing')
|
|
self.assertEqual('name1: testing\n', sio.getvalue())
|
|
with add_log_handler(logger2) as sio:
|
|
logger2.info('testing')
|
|
self.assertEqual('name2: testing\n', sio.getvalue())
|
|
|
|
@with_tempdir
|
|
def test_get_logger_sysloghandler_plumbing(self, tempdir):
|
|
orig_sysloghandler = utils.logs.ThreadSafeSysLogHandler
|
|
syslog_handler_args = []
|
|
|
|
def syslog_handler_catcher(*args, **kwargs):
|
|
syslog_handler_args.append((args, kwargs))
|
|
return orig_sysloghandler(*args, **kwargs)
|
|
|
|
syslog_handler_catcher.LOG_LOCAL0 = orig_sysloghandler.LOG_LOCAL0
|
|
syslog_handler_catcher.LOG_LOCAL3 = orig_sysloghandler.LOG_LOCAL3
|
|
|
|
# Some versions of python perform host resolution while initializing
|
|
# the handler. See https://bugs.python.org/issue30378
|
|
orig_getaddrinfo = socket.getaddrinfo
|
|
|
|
def fake_getaddrinfo(host, *args):
|
|
return orig_getaddrinfo('localhost', *args)
|
|
|
|
with mock.patch.object(utils.logs, 'ThreadSafeSysLogHandler',
|
|
syslog_handler_catcher), \
|
|
mock.patch.object(socket, 'getaddrinfo', fake_getaddrinfo):
|
|
# default log_address
|
|
utils.get_logger({
|
|
'log_facility': 'LOG_LOCAL3',
|
|
}, 'server', log_route='server')
|
|
expected_args = [((), {'address': '/dev/log',
|
|
'facility': orig_sysloghandler.LOG_LOCAL3})]
|
|
if not os.path.exists('/dev/log') or \
|
|
os.path.isfile('/dev/log') or \
|
|
os.path.isdir('/dev/log'):
|
|
# Since socket on OSX is in /var/run/syslog, there will be
|
|
# a fallback to UDP.
|
|
expected_args = [
|
|
((), {'facility': orig_sysloghandler.LOG_LOCAL3})]
|
|
self.assertEqual(expected_args, syslog_handler_args)
|
|
|
|
# custom log_address - file doesn't exist: fallback to UDP
|
|
log_address = os.path.join(tempdir, 'foo')
|
|
syslog_handler_args = []
|
|
utils.get_logger({
|
|
'log_facility': 'LOG_LOCAL3',
|
|
'log_address': log_address,
|
|
}, 'server', log_route='server')
|
|
expected_args = [
|
|
((), {'facility': orig_sysloghandler.LOG_LOCAL3})]
|
|
self.assertEqual(
|
|
expected_args, syslog_handler_args)
|
|
|
|
# custom log_address - file exists, not a socket: fallback to UDP
|
|
with open(log_address, 'w'):
|
|
pass
|
|
syslog_handler_args = []
|
|
utils.get_logger({
|
|
'log_facility': 'LOG_LOCAL3',
|
|
'log_address': log_address,
|
|
}, 'server', log_route='server')
|
|
expected_args = [
|
|
((), {'facility': orig_sysloghandler.LOG_LOCAL3})]
|
|
self.assertEqual(
|
|
expected_args, syslog_handler_args)
|
|
|
|
# custom log_address - file exists, is a socket: use it
|
|
os.unlink(log_address)
|
|
with contextlib.closing(
|
|
socket.socket(socket.AF_UNIX, socket.SOCK_DGRAM)) as sock:
|
|
sock.settimeout(5)
|
|
sock.bind(log_address)
|
|
syslog_handler_args = []
|
|
utils.get_logger({
|
|
'log_facility': 'LOG_LOCAL3',
|
|
'log_address': log_address,
|
|
}, 'server', log_route='server')
|
|
expected_args = [
|
|
((), {'address': log_address,
|
|
'facility': orig_sysloghandler.LOG_LOCAL3})]
|
|
self.assertEqual(
|
|
expected_args, syslog_handler_args)
|
|
|
|
# Using UDP with default port
|
|
syslog_handler_args = []
|
|
utils.get_logger({
|
|
'log_udp_host': 'syslog.funtimes.com',
|
|
}, 'server', log_route='server')
|
|
self.assertEqual([
|
|
((), {'address': ('syslog.funtimes.com',
|
|
logging.handlers.SYSLOG_UDP_PORT),
|
|
'facility': orig_sysloghandler.LOG_LOCAL0})],
|
|
syslog_handler_args)
|
|
|
|
# Using UDP with non-default port
|
|
syslog_handler_args = []
|
|
utils.get_logger({
|
|
'log_udp_host': 'syslog.funtimes.com',
|
|
'log_udp_port': '2123',
|
|
}, 'server', log_route='server')
|
|
self.assertEqual([
|
|
((), {'address': ('syslog.funtimes.com', 2123),
|
|
'facility': orig_sysloghandler.LOG_LOCAL0})],
|
|
syslog_handler_args)
|
|
|
|
with mock.patch.object(utils.logs, 'ThreadSafeSysLogHandler',
|
|
side_effect=OSError(errno.EPERM, 'oops')):
|
|
with self.assertRaises(OSError) as cm:
|
|
utils.get_logger({
|
|
'log_facility': 'LOG_LOCAL3',
|
|
'log_address': 'log_address',
|
|
}, 'server', log_route='server')
|
|
self.assertEqual(errno.EPERM, cm.exception.errno)
|
|
|
|
@reset_logger_state
|
|
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):
|
|
sio.seek(0)
|
|
v = sio.getvalue()
|
|
sio.truncate(0)
|
|
return v
|
|
|
|
def log_exception(exc):
|
|
try:
|
|
raise exc
|
|
except (Exception, Timeout):
|
|
logger.exception('blah')
|
|
try:
|
|
# establish base case
|
|
self.assertEqual(strip_value(sio), '')
|
|
logger.info('test')
|
|
self.assertEqual(strip_value(sio), 'test\n')
|
|
self.assertEqual(strip_value(sio), '')
|
|
logger.info('test')
|
|
logger.info('test')
|
|
self.assertEqual(strip_value(sio), 'test\ntest\n')
|
|
self.assertEqual(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.assertNotIn('Traceback', log_msg)
|
|
self.assertIn('my %s error message' % en, log_msg)
|
|
# unfiltered
|
|
log_exception(OSError())
|
|
self.assertTrue('Traceback' in strip_value(sio))
|
|
|
|
# test socket.error
|
|
log_exception(socket.error(errno.ECONNREFUSED,
|
|
'my error message'))
|
|
log_msg = strip_value(sio)
|
|
self.assertNotIn('Traceback', log_msg)
|
|
self.assertNotIn('errno.ECONNREFUSED message test', log_msg)
|
|
self.assertIn('Connection refused', log_msg)
|
|
log_exception(socket.error(errno.EHOSTUNREACH,
|
|
'my error message'))
|
|
log_msg = strip_value(sio)
|
|
self.assertNotIn('Traceback', log_msg)
|
|
self.assertNotIn('my error message', log_msg)
|
|
self.assertIn('Host unreachable', log_msg)
|
|
log_exception(socket.error(errno.ETIMEDOUT, 'my error message'))
|
|
log_msg = strip_value(sio)
|
|
self.assertNotIn('Traceback', log_msg)
|
|
self.assertNotIn('my error message', log_msg)
|
|
self.assertIn('Connection timeout', log_msg)
|
|
|
|
log_exception(socket.error(errno.ENETUNREACH, 'my error message'))
|
|
log_msg = strip_value(sio)
|
|
self.assertNotIn('Traceback', log_msg)
|
|
self.assertNotIn('my error message', log_msg)
|
|
self.assertIn('Network unreachable', log_msg)
|
|
|
|
log_exception(socket.error(errno.EPIPE, 'my error message'))
|
|
log_msg = strip_value(sio)
|
|
self.assertNotIn('Traceback', log_msg)
|
|
self.assertNotIn('my error message', log_msg)
|
|
self.assertIn('Broken pipe', log_msg)
|
|
# unfiltered
|
|
log_exception(socket.error(0, 'my error message'))
|
|
log_msg = strip_value(sio)
|
|
self.assertIn('Traceback', log_msg)
|
|
self.assertIn('my error message', log_msg)
|
|
|
|
# test eventlet.Timeout
|
|
with ConnectionTimeout(42, 'my error message') \
|
|
as connection_timeout:
|
|
now = time.time()
|
|
connection_timeout.created_at = now - 123.456
|
|
with mock.patch('swift.common.utils.time.time',
|
|
return_value=now):
|
|
log_exception(connection_timeout)
|
|
log_msg = strip_value(sio)
|
|
self.assertNotIn('Traceback', log_msg)
|
|
self.assertTrue('ConnectionTimeout' in log_msg)
|
|
self.assertTrue('(42s after 123.46s)' in log_msg)
|
|
self.assertNotIn('my error message', log_msg)
|
|
|
|
with MessageTimeout(42, 'my error message') as message_timeout:
|
|
log_exception(message_timeout)
|
|
log_msg = strip_value(sio)
|
|
self.assertNotIn('Traceback', log_msg)
|
|
self.assertTrue('MessageTimeout' in log_msg)
|
|
self.assertTrue('(42s)' in log_msg)
|
|
self.assertTrue('my error message' in log_msg)
|
|
|
|
# test BadStatusLine
|
|
log_exception(http_client.BadStatusLine(''))
|
|
log_msg = strip_value(sio)
|
|
self.assertNotIn('Traceback', log_msg)
|
|
self.assertIn('''BadStatusLine("''"''', log_msg)
|
|
|
|
# green version is separate :-(
|
|
log_exception(green_http_client.BadStatusLine(''))
|
|
log_msg = strip_value(sio)
|
|
self.assertNotIn('Traceback', log_msg)
|
|
self.assertIn('''BadStatusLine("''"''', log_msg)
|
|
|
|
if not six.PY2:
|
|
# py3 introduced RemoteDisconnected exceptions which inherit
|
|
# from both BadStatusLine *and* OSError; make sure those are
|
|
# handled as BadStatusLine, not OSError
|
|
log_exception(http_client.RemoteDisconnected(
|
|
'Remote end closed connection'))
|
|
log_msg = strip_value(sio)
|
|
self.assertNotIn('Traceback', log_msg)
|
|
self.assertIn(
|
|
"RemoteDisconnected('Remote end closed connection'",
|
|
log_msg)
|
|
|
|
log_exception(green_http_client.RemoteDisconnected(
|
|
'Remote end closed connection'))
|
|
log_msg = strip_value(sio)
|
|
self.assertNotIn('Traceback', log_msg)
|
|
self.assertIn(
|
|
"RemoteDisconnected('Remote end closed connection'",
|
|
log_msg)
|
|
|
|
# test unhandled
|
|
log_exception(Exception('my error message'))
|
|
log_msg = strip_value(sio)
|
|
self.assertTrue('Traceback' in log_msg)
|
|
self.assertTrue('my error message' in log_msg)
|
|
|
|
finally:
|
|
logger.logger.removeHandler(handler)
|
|
|
|
@reset_logger_state
|
|
def test_swift_log_formatter_max_line_length(self):
|
|
# setup stream logging
|
|
sio = StringIO()
|
|
logger = utils.get_logger(None)
|
|
handler = logging.StreamHandler(sio)
|
|
formatter = utils.SwiftLogFormatter(max_line_length=10)
|
|
handler.setFormatter(formatter)
|
|
logger.logger.addHandler(handler)
|
|
|
|
def strip_value(sio):
|
|
sio.seek(0)
|
|
v = sio.getvalue()
|
|
sio.truncate(0)
|
|
return v
|
|
|
|
try:
|
|
logger.info('12345')
|
|
self.assertEqual(strip_value(sio), '12345\n')
|
|
logger.info('1234567890')
|
|
self.assertEqual(strip_value(sio), '1234567890\n')
|
|
logger.info('1234567890abcde')
|
|
self.assertEqual(strip_value(sio), '12 ... de\n')
|
|
formatter.max_line_length = 11
|
|
logger.info('1234567890abcde')
|
|
self.assertEqual(strip_value(sio), '123 ... cde\n')
|
|
formatter.max_line_length = 0
|
|
logger.info('1234567890abcde')
|
|
self.assertEqual(strip_value(sio), '1234567890abcde\n')
|
|
formatter.max_line_length = 1
|
|
logger.info('1234567890abcde')
|
|
self.assertEqual(strip_value(sio), '1\n')
|
|
formatter.max_line_length = 2
|
|
logger.info('1234567890abcde')
|
|
self.assertEqual(strip_value(sio), '12\n')
|
|
formatter.max_line_length = 3
|
|
logger.info('1234567890abcde')
|
|
self.assertEqual(strip_value(sio), '123\n')
|
|
formatter.max_line_length = 4
|
|
logger.info('1234567890abcde')
|
|
self.assertEqual(strip_value(sio), '1234\n')
|
|
formatter.max_line_length = 5
|
|
logger.info('1234567890abcde')
|
|
self.assertEqual(strip_value(sio), '12345\n')
|
|
formatter.max_line_length = 6
|
|
logger.info('1234567890abcde')
|
|
self.assertEqual(strip_value(sio), '123456\n')
|
|
formatter.max_line_length = 7
|
|
logger.info('1234567890abcde')
|
|
self.assertEqual(strip_value(sio), '1 ... e\n')
|
|
formatter.max_line_length = -10
|
|
logger.info('1234567890abcde')
|
|
self.assertEqual(strip_value(sio), '1234567890abcde\n')
|
|
finally:
|
|
logger.logger.removeHandler(handler)
|
|
|
|
@reset_logger_state
|
|
def test_swift_log_formatter(self):
|
|
# setup stream logging
|
|
sio = StringIO()
|
|
logger = utils.get_logger(None)
|
|
handler = logging.StreamHandler(sio)
|
|
handler.setFormatter(utils.SwiftLogFormatter())
|
|
logger.logger.addHandler(handler)
|
|
|
|
def strip_value(sio):
|
|
sio.seek(0)
|
|
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.assertIn('my error message', log_msg)
|
|
self.assertNotIn('txn', log_msg)
|
|
logger.txn_id = '12345'
|
|
logger.error('test')
|
|
log_msg = strip_value(sio)
|
|
self.assertIn('txn', log_msg)
|
|
self.assertIn('12345', log_msg)
|
|
# test txn in info message
|
|
self.assertEqual(logger.txn_id, '12345')
|
|
logger.info('test')
|
|
log_msg = strip_value(sio)
|
|
self.assertIn('txn', log_msg)
|
|
self.assertIn('12345', log_msg)
|
|
# test txn already in message
|
|
self.assertEqual(logger.txn_id, '12345')
|
|
logger.warning('test 12345 test')
|
|
self.assertEqual(strip_value(sio), 'test 12345 test\n')
|
|
# Test multi line collapsing
|
|
logger.error('my\nerror\nmessage')
|
|
log_msg = strip_value(sio)
|
|
self.assertIn('my#012error#012message', log_msg)
|
|
|
|
# test client_ip
|
|
self.assertFalse(logger.client_ip)
|
|
logger.error('my error message')
|
|
log_msg = strip_value(sio)
|
|
self.assertIn('my error message', log_msg)
|
|
self.assertNotIn('client_ip', log_msg)
|
|
logger.client_ip = '1.2.3.4'
|
|
logger.error('test')
|
|
log_msg = strip_value(sio)
|
|
self.assertIn('client_ip', log_msg)
|
|
self.assertIn('1.2.3.4', log_msg)
|
|
# test no client_ip on info message
|
|
self.assertEqual(logger.client_ip, '1.2.3.4')
|
|
logger.info('test')
|
|
log_msg = strip_value(sio)
|
|
self.assertNotIn('client_ip', log_msg)
|
|
self.assertNotIn('1.2.3.4', log_msg)
|
|
# test client_ip (and txn) already in message
|
|
self.assertEqual(logger.client_ip, '1.2.3.4')
|
|
logger.warning('test 1.2.3.4 test 12345')
|
|
self.assertEqual(strip_value(sio), 'test 1.2.3.4 test 12345\n')
|
|
finally:
|
|
logger.logger.removeHandler(handler)
|
|
|
|
@reset_logger_state
|
|
def test_prefixlogger(self):
|
|
# setup stream logging
|
|
sio = StringIO()
|
|
base_logger = utils.get_logger(None)
|
|
handler = logging.StreamHandler(sio)
|
|
base_logger.logger.addHandler(handler)
|
|
logger = utils.PrefixLoggerAdapter(base_logger, {})
|
|
logger.set_prefix('some prefix: ')
|
|
|
|
def strip_value(sio):
|
|
sio.seek(0)
|
|
v = sio.getvalue()
|
|
sio.truncate(0)
|
|
return v
|
|
|
|
def log_exception(exc):
|
|
try:
|
|
raise exc
|
|
except (Exception, Timeout):
|
|
logger.exception('blah')
|
|
try:
|
|
# establish base case
|
|
self.assertEqual(strip_value(sio), '')
|
|
logger.info('test')
|
|
self.assertEqual(strip_value(sio), 'some prefix: test\n')
|
|
self.assertEqual(strip_value(sio), '')
|
|
logger.info('test')
|
|
logger.info('test')
|
|
self.assertEqual(
|
|
strip_value(sio),
|
|
'some prefix: test\nsome prefix: test\n')
|
|
self.assertEqual(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.assertNotIn('Traceback', log_msg)
|
|
self.assertEqual('some prefix: ', log_msg[:13])
|
|
self.assertIn('my %s error message' % en, log_msg)
|
|
# unfiltered
|
|
log_exception(OSError())
|
|
log_msg = strip_value(sio)
|
|
self.assertIn('Traceback', log_msg)
|
|
self.assertEqual('some prefix: ', log_msg[:13])
|
|
|
|
finally:
|
|
base_logger.logger.removeHandler(handler)
|
|
|
|
@reset_logger_state
|
|
def test_nested_prefixlogger(self):
|
|
# setup stream logging
|
|
sio = StringIO()
|
|
base_logger = utils.get_logger(None)
|
|
handler = logging.StreamHandler(sio)
|
|
base_logger.logger.addHandler(handler)
|
|
inner_logger = utils.PrefixLoggerAdapter(base_logger, {})
|
|
inner_logger.set_prefix('one: ')
|
|
outer_logger = utils.PrefixLoggerAdapter(inner_logger, {})
|
|
outer_logger.set_prefix('two: ')
|
|
|
|
def strip_value(sio):
|
|
sio.seek(0)
|
|
v = sio.getvalue()
|
|
sio.truncate(0)
|
|
return v
|
|
|
|
try:
|
|
# establish base case
|
|
self.assertEqual(strip_value(sio), '')
|
|
inner_logger.info('test')
|
|
self.assertEqual(strip_value(sio), 'one: test\n')
|
|
|
|
outer_logger.info('test')
|
|
self.assertEqual(strip_value(sio), 'one: two: test\n')
|
|
self.assertEqual(strip_value(sio), '')
|
|
finally:
|
|
base_logger.logger.removeHandler(handler)
|
|
|
|
@reset_logger_state
|
|
def test_capture_stdio(self):
|
|
# stubs
|
|
logger = utils.logs.get_logger(None, 'dummy')
|
|
|
|
# mock utils system modules
|
|
mock_os = MockOs()
|
|
mock_sys = MockSys()
|
|
with mock.patch.object(utils.logs, 'os', mock_os), \
|
|
mock.patch.object(utils.logs, 'sys', mock_sys):
|
|
# basic test
|
|
utils.logs.capture_stdio(logger)
|
|
self.assertTrue(mock_sys.excepthook is not None)
|
|
self.assertEqual(mock_os.closed_fds, mock_sys.stdio_fds)
|
|
self.assertIsInstance(mock_sys.stdout,
|
|
utils.logs.LoggerFileObject)
|
|
self.assertIsInstance(mock_sys.stderr,
|
|
utils.logs.LoggerFileObject)
|
|
|
|
# reset; test same args, but exc when trying to close stdio
|
|
mock_os = MockOs(raise_funcs=('dup2',))
|
|
mock_sys = MockSys()
|
|
with mock.patch.object(utils.logs, 'os', mock_os), \
|
|
mock.patch.object(utils.logs, 'sys', mock_sys):
|
|
# test unable to close stdio
|
|
utils.logs.capture_stdio(logger)
|
|
self.assertTrue(utils.logs.sys.excepthook is not None)
|
|
self.assertEqual(utils.logs.os.closed_fds, [])
|
|
self.assertIsInstance(mock_sys.stdout,
|
|
utils.logs.LoggerFileObject)
|
|
self.assertIsInstance(mock_sys.stderr,
|
|
utils.logs.LoggerFileObject)
|
|
|
|
# reset; test some other args
|
|
mock_os = MockOs()
|
|
mock_sys = MockSys()
|
|
with mock.patch.object(utils.logs, 'os', mock_os), \
|
|
mock.patch.object(utils.logs, 'sys', mock_sys):
|
|
logger = utils.get_logger(None, log_to_console=True)
|
|
|
|
# test console log
|
|
utils.logs.capture_stdio(logger, capture_stdout=False,
|
|
capture_stderr=False)
|
|
self.assertTrue(utils.logs.sys.excepthook is not None)
|
|
# when logging to console, stderr remains open
|
|
self.assertEqual(mock_os.closed_fds,
|
|
mock_sys.stdio_fds[:2])
|
|
reset_loggers()
|
|
|
|
# stdio not captured
|
|
self.assertFalse(isinstance(mock_sys.stdout,
|
|
utils.logs.LoggerFileObject))
|
|
self.assertFalse(isinstance(mock_sys.stderr,
|
|
utils.logs.LoggerFileObject))
|
|
|
|
@reset_logger_state
|
|
def test_get_logger_console(self):
|
|
logger = utils.get_logger(None)
|
|
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)
|
|
console_handlers = [h for h in logger.logger.handlers if
|
|
isinstance(h, logging.StreamHandler)]
|
|
self.assertTrue(console_handlers)
|
|
# make sure you can't have two console handlers
|
|
self.assertEqual(len(console_handlers), 1)
|
|
old_handler = console_handlers[0]
|
|
logger = utils.get_logger(None, log_to_console=True)
|
|
console_handlers = [h for h in logger.logger.handlers if
|
|
isinstance(h, logging.StreamHandler)]
|
|
self.assertEqual(len(console_handlers), 1)
|
|
new_handler = console_handlers[0]
|
|
self.assertNotEqual(new_handler, old_handler)
|
|
|
|
def test_get_policy_index(self):
|
|
# Account has no information about a policy
|
|
req = Request.blank(
|
|
'/sda1/p/a',
|
|
environ={'REQUEST_METHOD': 'GET'})
|
|
res = Response()
|
|
self.assertIsNone(utils.get_policy_index(req.headers,
|
|
res.headers))
|
|
|
|
# The policy of a container can be specified by the response header
|
|
req = Request.blank(
|
|
'/sda1/p/a/c',
|
|
environ={'REQUEST_METHOD': 'GET'})
|
|
res = Response(headers={'X-Backend-Storage-Policy-Index': '1'})
|
|
self.assertEqual('1', utils.get_policy_index(req.headers,
|
|
res.headers))
|
|
|
|
# The policy of an object to be created can be specified by the request
|
|
# header
|
|
req = Request.blank(
|
|
'/sda1/p/a/c/o',
|
|
environ={'REQUEST_METHOD': 'PUT'},
|
|
headers={'X-Backend-Storage-Policy-Index': '2'})
|
|
res = Response()
|
|
self.assertEqual('2', utils.get_policy_index(req.headers,
|
|
res.headers))
|
|
|
|
def test_log_string_formatter(self):
|
|
# Plain ASCII
|
|
lf = utils.LogStringFormatter()
|
|
self.assertEqual(lf.format('{a} {b}', a='Swift is', b='great'),
|
|
'Swift is great')
|
|
|
|
lf = utils.LogStringFormatter()
|
|
self.assertEqual(lf.format('{a} {b}', a='', b='great'),
|
|
' great')
|
|
|
|
lf = utils.LogStringFormatter(default='-')
|
|
self.assertEqual(lf.format('{a} {b}', a='', b='great'),
|
|
'- great')
|
|
|
|
lf = utils.LogStringFormatter(default='-', quote=True)
|
|
self.assertEqual(lf.format('{a} {b}', a='', b='great'),
|
|
'- great')
|
|
|
|
lf = utils.LogStringFormatter(quote=True)
|
|
self.assertEqual(lf.format('{a} {b}', a='Swift is', b='great'),
|
|
'Swift%20is great')
|
|
|
|
# Unicode & co
|
|
lf = utils.LogStringFormatter()
|
|
self.assertEqual(lf.format('{a} {b}', a='Swift est',
|
|
b=u'g\u00e9nial ^^'),
|
|
u'Swift est g\u00e9nial ^^')
|
|
|
|
lf = utils.LogStringFormatter(quote=True)
|
|
self.assertEqual(lf.format('{a} {b}', a='Swift est',
|
|
b=u'g\u00e9nial ^^'),
|
|
'Swift%20est g%C3%A9nial%20%5E%5E')
|
|
|
|
def test_str_anonymizer(self):
|
|
anon = utils.StrAnonymizer('Swift is great!', 'md5', '')
|
|
self.assertEqual(anon, 'Swift is great!')
|
|
self.assertEqual(anon.anonymized,
|
|
'{MD5}45e6f00d48fdcf86213602a87df18772')
|
|
|
|
anon = utils.StrAnonymizer('Swift is great!', 'sha1', '')
|
|
self.assertEqual(anon, 'Swift is great!')
|
|
self.assertEqual(anon.anonymized,
|
|
'{SHA1}0010a3df215495d8bfa0ae4b66acc2afcc8f4c5c')
|
|
|
|
anon = utils.StrAnonymizer('Swift is great!', 'md5', 'salty_secret')
|
|
self.assertEqual(anon, 'Swift is great!')
|
|
self.assertEqual(anon.anonymized,
|
|
'{SMD5}ef4ce28fe3bdd10b6659458ceb1f3f0c')
|
|
|
|
anon = utils.StrAnonymizer('Swift is great!', 'sha1', 'salty_secret')
|
|
self.assertEqual(anon, 'Swift is great!')
|
|
self.assertEqual(anon.anonymized,
|
|
'{SSHA1}a4968f76acaddff0eb4069ebe8805d9cab44c9fe')
|
|
|
|
self.assertRaises(ValueError, utils.StrAnonymizer,
|
|
'Swift is great!', 'sha257', '')
|
|
|
|
def test_str_anonymizer_python_maddness(self):
|
|
with mock.patch('swift.common.utils.base.hashlib') as mocklib:
|
|
if six.PY2:
|
|
# python <2.7.9 doesn't have this algorithms_guaranteed, but
|
|
# our if block short-circuts before we explode
|
|
mocklib.algorithms = hashlib.algorithms
|
|
mocklib.algorithms_guaranteed.sideEffect = AttributeError()
|
|
else:
|
|
# python 3 doesn't have this algorithms but our if block
|
|
# short-circuts before we explode
|
|
mocklib.algorithms.sideEffect.sideEffect = AttributeError()
|
|
mocklib.algorithms_guaranteed = hashlib.algorithms_guaranteed
|
|
utils.StrAnonymizer('Swift is great!', 'sha1', '')
|
|
self.assertRaises(ValueError, utils.StrAnonymizer,
|
|
'Swift is great!', 'sha257', '')
|
|
|
|
def test_str_format_time(self):
|
|
dt = utils.StrFormatTime(10000.123456789)
|
|
self.assertEqual(str(dt), '10000.123456789')
|
|
self.assertEqual(dt.datetime, '01/Jan/1970/02/46/40')
|
|
self.assertEqual(dt.iso8601, '1970-01-01T02:46:40')
|
|
self.assertEqual(dt.asctime, 'Thu Jan 1 02:46:40 1970')
|
|
self.assertEqual(dt.s, '10000')
|
|
self.assertEqual(dt.ms, '123')
|
|
self.assertEqual(dt.us, '123456')
|
|
self.assertEqual(dt.ns, '123456789')
|
|
self.assertEqual(dt.a, 'Thu')
|
|
self.assertEqual(dt.A, 'Thursday')
|
|
self.assertEqual(dt.b, 'Jan')
|
|
self.assertEqual(dt.B, 'January')
|
|
self.assertEqual(dt.c, 'Thu Jan 1 02:46:40 1970')
|
|
self.assertEqual(dt.d, '01')
|
|
self.assertEqual(dt.H, '02')
|
|
self.assertEqual(dt.I, '02')
|
|
self.assertEqual(dt.j, '001')
|
|
self.assertEqual(dt.m, '01')
|
|
self.assertEqual(dt.M, '46')
|
|
self.assertEqual(dt.p, 'AM')
|
|
self.assertEqual(dt.S, '40')
|
|
self.assertEqual(dt.U, '00')
|
|
self.assertEqual(dt.w, '4')
|
|
self.assertEqual(dt.W, '00')
|
|
self.assertEqual(dt.x, '01/01/70')
|
|
self.assertEqual(dt.X, '02:46:40')
|
|
self.assertEqual(dt.y, '70')
|
|
self.assertEqual(dt.Y, '1970')
|
|
self.assertIn(dt.Z, ('GMT', 'UTC')) # It depends of Python 2/3
|
|
self.assertRaises(ValueError, getattr, dt, 'z')
|
|
|
|
def test_get_log_line(self):
|
|
req = Request.blank(
|
|
'/sda1/p/a/c/o',
|
|
environ={'REQUEST_METHOD': 'HEAD', 'REMOTE_ADDR': '1.2.3.4'})
|
|
res = Response()
|
|
trans_time = 1.2
|
|
additional_info = 'some information'
|
|
server_pid = 1234
|
|
exp_line = '1.2.3.4 - - [01/Jan/1970:02:46:41 +0000] "HEAD ' \
|
|
'/sda1/p/a/c/o" 200 - "-" "-" "-" 1.2000 "some information" 1234 -'
|
|
with mock.patch('time.time', mock.MagicMock(side_effect=[10001.0])):
|
|
with mock.patch(
|
|
'os.getpid', mock.MagicMock(return_value=server_pid)):
|
|
self.assertEqual(
|
|
exp_line,
|
|
utils.get_log_line(req, res, trans_time, additional_info,
|
|
utils.LOG_LINE_DEFAULT_FORMAT,
|
|
'md5', '54LT'))
|
|
|
|
|
|
class TestSwiftLoggerAdapter(unittest.TestCase):
|
|
@reset_logger_state
|
|
def test_thread_locals(self):
|
|
logger = utils.get_logger({}, 'foo')
|
|
adapter1 = utils.SwiftLoggerAdapter(logger, {})
|
|
adapter2 = utils.SwiftLoggerAdapter(logger, {})
|
|
locals1 = ('tx_123', '1.2.3.4')
|
|
adapter1.thread_locals = locals1
|
|
self.assertEqual(adapter1.thread_locals, locals1)
|
|
self.assertEqual(adapter2.thread_locals, locals1)
|
|
self.assertEqual(logger.thread_locals, locals1)
|
|
|
|
locals2 = ('tx_456', '1.2.3.456')
|
|
logger.thread_locals = locals2
|
|
self.assertEqual(adapter1.thread_locals, locals2)
|
|
self.assertEqual(adapter2.thread_locals, locals2)
|
|
self.assertEqual(logger.thread_locals, locals2)
|
|
logger.thread_locals = (None, None)
|
|
|
|
@reset_logger_state
|
|
def test_thread_locals_more(self):
|
|
logger = utils.get_logger(None)
|
|
# test the setter
|
|
logger.thread_locals = ('id', 'ip')
|
|
self.assertEqual(logger.thread_locals, ('id', 'ip'))
|
|
# reset
|
|
logger.thread_locals = (None, None)
|
|
self.assertEqual(logger.thread_locals, (None, None))
|
|
logger.txn_id = '1234'
|
|
logger.client_ip = '1.2.3.4'
|
|
self.assertEqual(logger.thread_locals, ('1234', '1.2.3.4'))
|
|
logger.txn_id = '5678'
|
|
logger.client_ip = '5.6.7.8'
|
|
self.assertEqual(logger.thread_locals, ('5678', '5.6.7.8'))
|
|
|
|
def test_exception(self):
|
|
# verify that the adapter routes exception calls to utils.LogAdapter
|
|
# for special case handling
|
|
logger = utils.get_logger({})
|
|
adapter = utils.SwiftLoggerAdapter(logger, {})
|
|
try:
|
|
raise OSError(errno.ECONNREFUSED, 'oserror')
|
|
except OSError:
|
|
with mock.patch('logging.LoggerAdapter.error') as mocked:
|
|
adapter.exception('Caught')
|
|
mocked.assert_called_with('Caught: Connection refused')
|
|
|
|
|
|
class TestPipeMutex(unittest.TestCase):
|
|
def setUp(self):
|
|
self.mutex = utils.PipeMutex()
|
|
|
|
def tearDown(self):
|
|
self.mutex.close()
|
|
|
|
def test_nonblocking(self):
|
|
evt_lock1 = eventlet.event.Event()
|
|
evt_lock2 = eventlet.event.Event()
|
|
evt_unlock = eventlet.event.Event()
|
|
|
|
def get_the_lock():
|
|
self.mutex.acquire()
|
|
evt_lock1.send('got the lock')
|
|
evt_lock2.wait()
|
|
self.mutex.release()
|
|
evt_unlock.send('released the lock')
|
|
|
|
eventlet.spawn(get_the_lock)
|
|
evt_lock1.wait() # Now, the other greenthread has the lock.
|
|
|
|
self.assertFalse(self.mutex.acquire(blocking=False))
|
|
evt_lock2.send('please release the lock')
|
|
evt_unlock.wait() # The other greenthread has released the lock.
|
|
self.assertTrue(self.mutex.acquire(blocking=False))
|
|
|
|
def test_recursive(self):
|
|
self.assertTrue(self.mutex.acquire(blocking=False))
|
|
self.assertTrue(self.mutex.acquire(blocking=False))
|
|
|
|
def try_acquire_lock():
|
|
return self.mutex.acquire(blocking=False)
|
|
|
|
self.assertFalse(eventlet.spawn(try_acquire_lock).wait())
|
|
self.mutex.release()
|
|
self.assertFalse(eventlet.spawn(try_acquire_lock).wait())
|
|
self.mutex.release()
|
|
self.assertTrue(eventlet.spawn(try_acquire_lock).wait())
|
|
|
|
def test_context_manager_api(self):
|
|
def try_acquire_lock():
|
|
return self.mutex.acquire(blocking=False)
|
|
|
|
with self.mutex as ref:
|
|
self.assertIs(ref, self.mutex)
|
|
self.assertFalse(eventlet.spawn(try_acquire_lock).wait())
|
|
self.assertTrue(eventlet.spawn(try_acquire_lock).wait())
|
|
|
|
def test_release_without_acquire(self):
|
|
self.assertRaises(RuntimeError, self.mutex.release)
|
|
|
|
def test_too_many_releases(self):
|
|
self.mutex.acquire()
|
|
self.mutex.release()
|
|
self.assertRaises(RuntimeError, self.mutex.release)
|
|
|
|
def test_wrong_releaser(self):
|
|
self.mutex.acquire()
|
|
with quiet_eventlet_exceptions():
|
|
self.assertRaises(RuntimeError,
|
|
eventlet.spawn(self.mutex.release).wait)
|
|
|
|
def test_blocking(self):
|
|
evt = eventlet.event.Event()
|
|
|
|
sequence = []
|
|
|
|
def coro1():
|
|
eventlet.sleep(0) # let coro2 go
|
|
|
|
self.mutex.acquire()
|
|
sequence.append('coro1 acquire')
|
|
evt.send('go')
|
|
self.mutex.release()
|
|
sequence.append('coro1 release')
|
|
|
|
def coro2():
|
|
evt.wait() # wait for coro1 to start us
|
|
self.mutex.acquire()
|
|
sequence.append('coro2 acquire')
|
|
self.mutex.release()
|
|
sequence.append('coro2 release')
|
|
|
|
c1 = eventlet.spawn(coro1)
|
|
c2 = eventlet.spawn(coro2)
|
|
|
|
c1.wait()
|
|
c2.wait()
|
|
|
|
self.assertEqual(sequence, [
|
|
'coro1 acquire',
|
|
'coro1 release',
|
|
'coro2 acquire',
|
|
'coro2 release'])
|
|
|
|
def test_blocking_tpool(self):
|
|
# Note: this test's success isn't a guarantee that the mutex is
|
|
# working. However, this test's failure means that the mutex is
|
|
# definitely broken.
|
|
sequence = []
|
|
|
|
def do_stuff():
|
|
n = 10
|
|
while n > 0:
|
|
self.mutex.acquire()
|
|
sequence.append("<")
|
|
eventlet.sleep(0.0001)
|
|
sequence.append(">")
|
|
self.mutex.release()
|
|
n -= 1
|
|
|
|
greenthread1 = eventlet.spawn(do_stuff)
|
|
greenthread2 = eventlet.spawn(do_stuff)
|
|
|
|
real_thread1 = eventlet.patcher.original('threading').Thread(
|
|
target=do_stuff)
|
|
real_thread1.start()
|
|
|
|
real_thread2 = eventlet.patcher.original('threading').Thread(
|
|
target=do_stuff)
|
|
real_thread2.start()
|
|
|
|
greenthread1.wait()
|
|
greenthread2.wait()
|
|
real_thread1.join()
|
|
real_thread2.join()
|
|
|
|
self.assertEqual(''.join(sequence), "<>" * 40)
|
|
|
|
def test_blocking_preserves_ownership(self):
|
|
pthread1_event = eventlet.patcher.original('threading').Event()
|
|
pthread2_event1 = eventlet.patcher.original('threading').Event()
|
|
pthread2_event2 = eventlet.patcher.original('threading').Event()
|
|
thread_id = []
|
|
owner = []
|
|
|
|
def pthread1():
|
|
thread_id.append(id(eventlet.greenthread.getcurrent()))
|
|
self.mutex.acquire()
|
|
owner.append(self.mutex.owner)
|
|
pthread2_event1.set()
|
|
|
|
orig_os_write = utils.os.write
|
|
|
|
def patched_os_write(*a, **kw):
|
|
try:
|
|
return orig_os_write(*a, **kw)
|
|
finally:
|
|
pthread1_event.wait()
|
|
|
|
with mock.patch.object(utils.os, 'write', patched_os_write):
|
|
self.mutex.release()
|
|
pthread2_event2.set()
|
|
|
|
def pthread2():
|
|
pthread2_event1.wait() # ensure pthread1 acquires lock first
|
|
thread_id.append(id(eventlet.greenthread.getcurrent()))
|
|
self.mutex.acquire()
|
|
pthread1_event.set()
|
|
pthread2_event2.wait()
|
|
owner.append(self.mutex.owner)
|
|
self.mutex.release()
|
|
|
|
real_thread1 = eventlet.patcher.original('threading').Thread(
|
|
target=pthread1)
|
|
real_thread1.start()
|
|
|
|
real_thread2 = eventlet.patcher.original('threading').Thread(
|
|
target=pthread2)
|
|
real_thread2.start()
|
|
|
|
real_thread1.join()
|
|
real_thread2.join()
|
|
self.assertEqual(thread_id, owner)
|
|
self.assertIsNone(self.mutex.owner)
|
|
|
|
@classmethod
|
|
def tearDownClass(cls):
|
|
# PipeMutex turns this off when you instantiate one
|
|
eventlet.debug.hub_prevent_multiple_readers(True)
|
|
|
|
|
|
class TestNoopMutex(unittest.TestCase):
|
|
def setUp(self):
|
|
self.mutex = utils.NoopMutex()
|
|
|
|
def test_acquire_release_api(self):
|
|
# Prior to 3.13, logging called these explicitly
|
|
self.mutex.acquire()
|
|
self.mutex.release()
|
|
|
|
def test_context_manager_api(self):
|
|
# python 3.13 started using it as a context manager
|
|
def try_acquire_lock():
|
|
return self.mutex.acquire(blocking=False)
|
|
|
|
with self.mutex as ref:
|
|
self.assertIs(ref, self.mutex)
|