diff --git a/conftest.py b/conftest.py index 21f152e45..783a5a250 100644 --- a/conftest.py +++ b/conftest.py @@ -1,6 +1,5 @@ import six import pytest -from twisted.python import log collect_ignore = ["scrapy/stats.py", "scrapy/project.py"] @@ -10,35 +9,6 @@ if six.PY3: if len(file_path) > 0 and file_path[0] != '#': collect_ignore.append(file_path) -class LogObservers: - """Class for keeping track of log observers across test modules""" - - def __init__(self): - self.observers = [] - - def add(self, logfile='test.log'): - fileobj = open(logfile, 'wb') - observer = log.FileLogObserver(fileobj) - log.startLoggingWithObserver(observer.emit, 0) - self.observers.append((fileobj, observer)) - - def remove(self): - fileobj, observer = self.observers.pop() - log.removeObserver(observer.emit) - fileobj.close() - - -@pytest.fixture(scope='module') -def log_observers(): - return LogObservers() - - -@pytest.fixture() -def setlog(request, log_observers): - """Attach test.log file observer to twisted log, for trial compatibility""" - log_observers.add() - request.addfinalizer(log_observers.remove) - @pytest.fixture() def chdir(tmpdir): diff --git a/pytest.ini b/pytest.ini index 355ee31c3..3046dfd85 100644 --- a/pytest.ini +++ b/pytest.ini @@ -1,5 +1,5 @@ [pytest] -usefixtures = chdir setlog +usefixtures = chdir python_files=test_*.py __init__.py addopts = --doctest-modules --assert=plain twisted = 1 diff --git a/scrapy/utils/test.py b/scrapy/utils/test.py index a4b769970..ad4a6aa7c 100644 --- a/scrapy/utils/test.py +++ b/scrapy/utils/test.py @@ -46,19 +46,6 @@ def get_testenv(): env['PYTHONPATH'] = get_pythonpath() return env -def get_testlog(): - """Get Scrapy log of current test, ignoring the rest""" - with open("test.log", "rb") as fp: - loglines = fp.readlines() - - thistest = [] - for line in loglines[::-1]: - thistest.append(line) - if "[-] -->" in line: - break - return "".join(thistest[::-1]) - - def assert_samelines(testcase, text1, text2, msg=None): """Asserts text1 and text2 have the same lines, ignoring differences in line endings between platforms diff --git a/tests/requirements.txt b/tests/requirements.txt index 4da8e30ea..4f1520021 100644 --- a/tests/requirements.txt +++ b/tests/requirements.txt @@ -4,3 +4,4 @@ mitmproxy==0.10.1 netlib==0.10.1 pytest-twisted jmespath +testfixtures diff --git a/tests/test_closespider.py b/tests/test_closespider.py index 1700a861e..fa0b48998 100644 --- a/tests/test_closespider.py +++ b/tests/test_closespider.py @@ -39,7 +39,6 @@ class TestCloseSpider(TestCase): close_on = 5 crawler = get_crawler(ErrorSpider, {'CLOSESPIDER_ERRORCOUNT': close_on}) yield crawler.crawl(total=1000000) - self.flushLoggedErrors(crawler.spider.exception_cls) reason = crawler.spider.meta['close_reason'] self.assertEqual(reason, 'closespider_errorcount') key = 'spider_exceptions/{name}'\ diff --git a/tests/test_crawl.py b/tests/test_crawl.py index 0fcc7c31e..f2ebf9c69 100644 --- a/tests/test_crawl.py +++ b/tests/test_crawl.py @@ -1,8 +1,12 @@ import json import socket +import logging + +from testfixtures import LogCapture from twisted.internet import defer from twisted.trial.unittest import TestCase -from scrapy.utils.test import get_crawler, get_testlog + +from scrapy.utils.test import get_crawler from tests import mock from tests.spiders import FollowAllSpider, DelaySpider, SimpleSpider, \ BrokenStartRequestsSpider, SingleRequestSpider, DuplicateStartRequestsSpider @@ -72,36 +76,47 @@ class CrawlTestCase(TestCase): @defer.inlineCallbacks def test_retry_503(self): crawler = get_crawler(SimpleSpider) - yield crawler.crawl("http://localhost:8998/status?n=503") - self._assert_retried() + with LogCapture() as l: + yield crawler.crawl("http://localhost:8998/status?n=503") + self._assert_retried(l) @defer.inlineCallbacks def test_retry_conn_failed(self): crawler = get_crawler(SimpleSpider) - yield crawler.crawl("http://localhost:65432/status?n=503") - self._assert_retried() + with LogCapture() as l: + yield crawler.crawl("http://localhost:65432/status?n=503") + self._assert_retried(l) @defer.inlineCallbacks def test_retry_dns_error(self): with mock.patch('socket.gethostbyname', side_effect=socket.gaierror(-5, 'No address associated with hostname')): crawler = get_crawler(SimpleSpider) - yield crawler.crawl("http://example.com/") - self._assert_retried() + with LogCapture() as l: + yield crawler.crawl("http://example.com/") + self._assert_retried(l) @defer.inlineCallbacks def test_start_requests_bug_before_yield(self): - crawler = get_crawler(BrokenStartRequestsSpider) - yield crawler.crawl(fail_before_yield=1) - errors = self.flushLoggedErrors(ZeroDivisionError) - self.assertEqual(len(errors), 1) + with LogCapture('scrapy', level=logging.ERROR) as l: + crawler = get_crawler(BrokenStartRequestsSpider) + yield crawler.crawl(fail_before_yield=1) + + self.assertEqual(len(l.records), 1) + record = l.records[0] + self.assertIsNotNone(record.exc_info) + self.assertIs(record.exc_info[0], ZeroDivisionError) @defer.inlineCallbacks def test_start_requests_bug_yielding(self): - crawler = get_crawler(BrokenStartRequestsSpider) - yield crawler.crawl(fail_yielding=1) - errors = self.flushLoggedErrors(ZeroDivisionError) - self.assertEqual(len(errors), 1) + with LogCapture('scrapy', level=logging.ERROR) as l: + crawler = get_crawler(BrokenStartRequestsSpider) + yield crawler.crawl(fail_yielding=1) + + self.assertEqual(len(l.records), 1) + record = l.records[0] + self.assertIsNotNone(record.exc_info) + self.assertIs(record.exc_info[0], ZeroDivisionError) @defer.inlineCallbacks def test_start_requests_lazyness(self): @@ -145,28 +160,29 @@ foo body with multiples lines '''}) crawler = get_crawler(SimpleSpider) - yield crawler.crawl("http://localhost:8998/raw?{0}".format(query)) - log = get_testlog() - self.assertEqual(log.count("Got response 200"), 1) + with LogCapture() as l: + yield crawler.crawl("http://localhost:8998/raw?{0}".format(query)) + self.assertEqual(str(l).count("Got response 200"), 1) @defer.inlineCallbacks def test_retry_conn_lost(self): # connection lost after receiving data crawler = get_crawler(SimpleSpider) - yield crawler.crawl("http://localhost:8998/drop?abort=0") - self._assert_retried() + with LogCapture() as l: + yield crawler.crawl("http://localhost:8998/drop?abort=0") + self._assert_retried(l) @defer.inlineCallbacks def test_retry_conn_aborted(self): # connection lost before receiving data crawler = get_crawler(SimpleSpider) - yield crawler.crawl("http://localhost:8998/drop?abort=1") - self._assert_retried() + with LogCapture() as l: + yield crawler.crawl("http://localhost:8998/drop?abort=1") + self._assert_retried(l) - def _assert_retried(self): - log = get_testlog() - self.assertEqual(log.count("Retrying"), 2) - self.assertEqual(log.count("Gave up retrying"), 1) + def _assert_retried(self, log): + self.assertEqual(str(log).count("Retrying"), 2) + self.assertEqual(str(log).count("Gave up retrying"), 1) @defer.inlineCallbacks def test_referer_header(self): diff --git a/tests/test_pipeline_media.py b/tests/test_pipeline_media.py index e4fae3983..0e946303b 100644 --- a/tests/test_pipeline_media.py +++ b/tests/test_pipeline_media.py @@ -1,9 +1,9 @@ from __future__ import print_function +from testfixtures import LogCapture from twisted.trial import unittest from twisted.python.failure import Failure from twisted.internet import reactor from twisted.internet.defer import Deferred, inlineCallbacks -from twisted.python import log as txlog from scrapy.http import Request, Response from scrapy.spider import Spider @@ -11,7 +11,6 @@ from scrapy.utils.request import request_fingerprint from scrapy.contrib.pipeline.media import MediaPipeline from scrapy.utils.signal import disconnect_all from scrapy import signals -from scrapy import log def _mocked_download_func(request, info): @@ -60,26 +59,21 @@ class BaseMediaPipelineTestCase(unittest.TestCase): fail = Failure(Exception()) results = [(True, 1), (False, fail)] - events = [] - txlog.addObserver(events.append) - new_item = self.pipe.item_completed(results, item, self.info) - txlog.removeObserver(events.append) - self.flushLoggedErrors() + with LogCapture() as l: + new_item = self.pipe.item_completed(results, item, self.info) assert new_item is item - assert len(events) == 1 - assert events[0]['logLevel'] == log.ERROR - assert events[0]['failure'] is fail + assert len(l.records) == 1 + record = l.records[0] + assert record.levelname == 'ERROR' + assert record.failure is fail # disable failure logging and check again self.pipe.LOG_FAILED_RESULTS = False - events = [] - txlog.addObserver(events.append) - new_item = self.pipe.item_completed(results, item, self.info) - txlog.removeObserver(events.append) - self.flushLoggedErrors() + with LogCapture() as l: + new_item = self.pipe.item_completed(results, item, self.info) assert new_item is item - assert len(events) == 0 + assert len(l.records) == 0 @inlineCallbacks def test_default_process_item(self): diff --git a/tests/test_proxy_connect.py b/tests/test_proxy_connect.py index 5ce48ebf8..0f06fd53d 100644 --- a/tests/test_proxy_connect.py +++ b/tests/test_proxy_connect.py @@ -5,10 +5,11 @@ import time from threading import Thread from libmproxy import controller, proxy from netlib import http_auth +from testfixtures import LogCapture from twisted.internet import defer from twisted.trial.unittest import TestCase -from scrapy.utils.test import get_testlog, get_crawler +from scrapy.utils.test import get_crawler from scrapy.http import Request from tests.spiders import SimpleSpider, SingleRequestSpider from tests.mockserver import MockServer @@ -50,39 +51,44 @@ class ProxyConnectTestCase(TestCase): @defer.inlineCallbacks def test_https_connect_tunnel(self): crawler = get_crawler(SimpleSpider) - yield crawler.crawl("https://localhost:8999/status?n=200") - self._assert_got_response_code(200) + with LogCapture() as l: + yield crawler.crawl("https://localhost:8999/status?n=200") + self._assert_got_response_code(200, l) @defer.inlineCallbacks def test_https_noconnect(self): os.environ['https_proxy'] = 'http://scrapy:scrapy@localhost:8888?noconnect' crawler = get_crawler(SimpleSpider) - yield crawler.crawl("https://localhost:8999/status?n=200") - self._assert_got_response_code(200) + with LogCapture() as l: + yield crawler.crawl("https://localhost:8999/status?n=200") + self._assert_got_response_code(200, l) os.environ['https_proxy'] = 'http://scrapy:scrapy@localhost:8888' @defer.inlineCallbacks def test_https_connect_tunnel_error(self): crawler = get_crawler(SimpleSpider) - yield crawler.crawl("https://localhost:99999/status?n=200") - self._assert_got_tunnel_error() + with LogCapture() as l: + yield crawler.crawl("https://localhost:99999/status?n=200") + self._assert_got_tunnel_error(l) @defer.inlineCallbacks def test_https_tunnel_auth_error(self): os.environ['https_proxy'] = 'http://wrong:wronger@localhost:8888' crawler = get_crawler(SimpleSpider) - yield crawler.crawl("https://localhost:8999/status?n=200") + with LogCapture() as l: + yield crawler.crawl("https://localhost:8999/status?n=200") # The proxy returns a 407 error code but it does not reach the client; # he just sees a TunnelError. - self._assert_got_tunnel_error() + self._assert_got_tunnel_error(l) os.environ['https_proxy'] = 'http://scrapy:scrapy@localhost:8888' @defer.inlineCallbacks def test_https_tunnel_without_leak_proxy_authorization_header(self): request = Request("https://localhost:8999/echo") crawler = get_crawler(SingleRequestSpider) - yield crawler.crawl(seed=request) - self._assert_got_response_code(200) + with LogCapture() as l: + yield crawler.crawl(seed=request) + self._assert_got_response_code(200, l) echo = json.loads(crawler.spider.meta['responses'][0].body) self.assertTrue('Proxy-Authorization' not in echo['headers']) @@ -90,13 +96,12 @@ class ProxyConnectTestCase(TestCase): def test_https_noconnect_auth_error(self): os.environ['https_proxy'] = 'http://wrong:wronger@localhost:8888?noconnect' crawler = get_crawler(SimpleSpider) - yield crawler.crawl("https://localhost:8999/status?n=200") - self._assert_got_response_code(407) + with LogCapture() as l: + yield crawler.crawl("https://localhost:8999/status?n=200") + self._assert_got_response_code(407, l) - def _assert_got_response_code(self, code): - log = get_testlog() - self.assertEqual(log.count('Crawled (%d)' % code), 1) + def _assert_got_response_code(self, code, log): + self.assertEqual(str(log).count('Crawled (%d)' % code), 1) - def _assert_got_tunnel_error(self): - log = get_testlog() - self.assertEqual(log.count('TunnelError'), 1) + def _assert_got_tunnel_error(self, log): + self.assertEqual(str(log).count('TunnelError'), 1) diff --git a/tests/test_spidermiddleware_httperror.py b/tests/test_spidermiddleware_httperror.py index 5394f0eee..503865f63 100644 --- a/tests/test_spidermiddleware_httperror.py +++ b/tests/test_spidermiddleware_httperror.py @@ -1,9 +1,10 @@ from unittest import TestCase +from testfixtures import LogCapture from twisted.trial.unittest import TestCase as TrialTestCase from twisted.internet import defer -from scrapy.utils.test import get_crawler, get_testlog +from scrapy.utils.test import get_crawler from tests.mockserver import MockServer from scrapy.http import Response, Request from scrapy.spider import Spider @@ -174,14 +175,13 @@ class TestHttpErrorMiddlewareIntegrational(TrialTestCase): @defer.inlineCallbacks def test_logging(self): crawler = get_crawler(_HttpErrorSpider) - yield crawler.crawl(bypass_status_codes={402}) - # print(get_testlog()) + with LogCapture() as log: + yield crawler.crawl(bypass_status_codes={402}) self.assertEqual(crawler.spider.parsed, {'200', '402'}) self.assertEqual(crawler.spider.skipped, {'402'}) self.assertEqual(crawler.spider.failed, {'404', '500'}) - log = get_testlog() - self.assertIn('Ignoring response <404', log) - self.assertIn('Ignoring response <500', log) - self.assertNotIn('Ignoring response <200', log) - self.assertNotIn('Ignoring response <402', log) + self.assertIn('Ignoring response <404', str(log)) + self.assertIn('Ignoring response <500', str(log)) + self.assertNotIn('Ignoring response <200', str(log)) + self.assertNotIn('Ignoring response <402', str(log)) diff --git a/tests/test_utils_defer.py b/tests/test_utils_defer.py index b9cb3ab44..260ed6c2e 100644 --- a/tests/test_utils_defer.py +++ b/tests/test_utils_defer.py @@ -74,7 +74,6 @@ class DeferUtilsTest(unittest.TestCase): def test_process_parallel_failure(self): d = process_parallel([cb1, cb_fail, cb3], 'res', 'v1', 'v2') self.failUnlessFailure(d, TypeError) - self.flushLoggedErrors() return d diff --git a/tests/test_utils_signal.py b/tests/test_utils_signal.py index a9f377dab..571073911 100644 --- a/tests/test_utils_signal.py +++ b/tests/test_utils_signal.py @@ -1,11 +1,11 @@ +from testfixtures import LogCapture from twisted.trial import unittest -from twisted.python import log as txlog from twisted.python.failure import Failure from twisted.internet import defer, reactor from scrapy.xlib.pydispatch import dispatcher from scrapy.utils.signal import send_catch_log, send_catch_log_deferred -from scrapy import log + class SendCatchLogTest(unittest.TestCase): @@ -14,26 +14,24 @@ class SendCatchLogTest(unittest.TestCase): test_signal = object() handlers_called = set() - def log_received(event): - handlers_called.add(log_received) - assert "error_handler" in event['message'][0] - assert event['logLevel'] == log.ERROR - - txlog.addObserver(log_received) dispatcher.connect(self.error_handler, signal=test_signal) dispatcher.connect(self.ok_handler, signal=test_signal) - result = yield defer.maybeDeferred(self._get_result, test_signal, arg='test', \ - handlers_called=handlers_called) + with LogCapture() as l: + result = yield defer.maybeDeferred( + self._get_result, test_signal, arg='test', + handlers_called=handlers_called + ) assert self.error_handler in handlers_called assert self.ok_handler in handlers_called - assert log_received in handlers_called + self.assertEqual(len(l.records), 1) + record = l.records[0] + self.assertIn('error_handler', record.getMessage()) + self.assertEqual(record.levelname, 'ERROR') self.assertEqual(result[0][0], self.error_handler) self.assert_(isinstance(result[0][1], Failure)) self.assertEqual(result[1], (self.ok_handler, "OK")) - txlog.removeObserver(log_received) - self.flushLoggedErrors() dispatcher.disconnect(self.error_handler, signal=test_signal) dispatcher.disconnect(self.ok_handler, signal=test_signal) @@ -73,12 +71,9 @@ class SendCatchLogTest2(unittest.TestCase): def test_error_logged_if_deferred_not_supported(self): test_signal = object() test_handler = lambda: defer.Deferred() - log_events = [] - txlog.addObserver(log_events.append) dispatcher.connect(test_handler, test_signal) - send_catch_log(test_signal) - self.assertTrue(log_events) - self.assertIn("Cannot return deferreds from signal handler", str(log_events)) - txlog.removeObserver(log_events.append) - self.flushLoggedErrors() + with LogCapture() as l: + send_catch_log(test_signal) + self.assertEqual(len(l.records), 1) + self.assertIn("Cannot return deferreds from signal handler", str(l)) dispatcher.disconnect(test_handler, test_signal) diff --git a/tox.ini b/tox.ini index ae2ef9e07..5385cb87c 100644 --- a/tox.ini +++ b/tox.ini @@ -50,6 +50,7 @@ deps = # tests requirements pytest>=2.6.0 pytest-twisted + testfixtures [testenv:py34] basepython = python3.4