diff --git a/docker_test_tools/environment.py b/docker_test_tools/environment.py index acb933b..a288402 100644 --- a/docker_test_tools/environment.py +++ b/docker_test_tools/environment.py @@ -10,6 +10,8 @@ SEPARATOR = '|' +log = logging.getLogger(__name__) + class EnvironmentController(object): """Utility for managing environment operations.""" @@ -44,7 +46,7 @@ def get_services(self): :return dict: of format {'service-name': check_callback} """ - logging.debug("Getting environment services, using docker compose: %s", self.compose_path) + log.debug("Getting environment services, using docker compose: %s", self.compose_path) try: services_output = subprocess.check_output( ['docker-compose', '-f', self.compose_path, '-p', self.project_name, 'config', '--services'], @@ -62,12 +64,12 @@ def setup(self): Should be called once before *all* the tests start. """ try: - logging.debug("Setting up the environment") + log.debug("Setting up the environment") self.cleanup() self.run_containers() self.start_log_collection() except: - logging.exception("Setup failure, tearing down the test environment") + log.exception("Setup failure, tearing down the test environment") self.teardown() raise @@ -76,7 +78,7 @@ def teardown(self): Should be called once after *all* the tests finish. """ - logging.debug("Tearing down the environment") + log.debug("Tearing down the environment") try: self.stop_log_collection() finally: @@ -88,7 +90,7 @@ def cleanup(self): Kills and removes the environment containers. """ if self.reuse_containers: - logging.warning("Container reuse enabled: Skipping environment cleanup") + log.warning("Container reuse enabled: Skipping environment cleanup") return self.kill_containers() @@ -96,7 +98,7 @@ def cleanup(self): def run_containers(self): """Run environment containers.""" - logging.debug("Running environment containers, using docker compose: %s", self.compose_path) + log.debug("Running environment containers, using docker compose: %s", self.compose_path) try: subprocess.check_output( ['docker-compose', '-f', self.compose_path, '-p', self.project_name, 'up', '--build', '-d'], @@ -107,7 +109,7 @@ def run_containers(self): def start_log_collection(self): """Start a log collection process which writes docker-compose logs into a file.""" - logging.debug("Starting logs collection from environment containers") + log.debug("Starting logs collection from environment containers") self.logs_file = open(self.log_path, 'w') self.logs_process = subprocess.Popen( ['docker-compose', '-f', self.compose_path, '-p', self.project_name, 'logs', '--no-color', '-f', '-t'], @@ -116,7 +118,7 @@ def start_log_collection(self): def stop_log_collection(self): """Stop the log collection process and close the log file.""" - logging.debug("Stopping logs collection from environment containers") + log.debug("Stopping logs collection from environment containers") if self.logs_process: self.logs_process.kill() self.logs_process.wait() @@ -131,7 +133,7 @@ def split_logs(self): Each line in the collected log file is in a format of: 'service.name_number | message' This method writes each line to it's service log file amd keeps only the message. """ - logging.debug("Splitting log file into separated files per service") + log.debug("Splitting log file into separated files per service") services_log_files = {} log_dir = os.path.dirname(self.log_path) try: @@ -151,7 +153,7 @@ def split_logs(self): def remove_containers(self): """Remove the environment containers.""" - logging.debug("Removing environment containers, using docker compose: %s", self.compose_path) + log.debug("Removing environment containers, using docker compose: %s", self.compose_path) try: subprocess.check_output( ['docker-compose', '-f', self.compose_path, '-p', self.project_name, 'rm', '-f'], @@ -162,7 +164,7 @@ def remove_containers(self): def kill_containers(self): """Kill the environment containers.""" - logging.debug("Killing environment containers, using docker compose: %s", self.compose_path) + log.debug("Killing environment containers, using docker compose: %s", self.compose_path) try: subprocess.check_output( ['docker-compose', '-f', self.compose_path, '-p', self.project_name, 'kill'], @@ -177,7 +179,7 @@ def kill_container(self, name): :param str name: container name as it appears in the docker compose file. """ self.validate_service_name(name) - logging.debug("Killing %s container", name) + log.debug("Killing %s container", name) try: subprocess.check_output( ['docker-compose', '-f', self.compose_path, '-p', self.project_name, 'kill', name], @@ -192,7 +194,7 @@ def restart_container(self, name): :param str name: container name as it appears in the docker compose file. """ self.validate_service_name(name) - logging.debug("Restarting container %s", name) + log.debug("Restarting container %s", name) try: subprocess.check_output( ['docker-compose', '-f', self.compose_path, '-p', self.project_name, 'restart', name], @@ -207,7 +209,7 @@ def pause_container(self, name): :param str name: container name as it appears in the docker compose file. """ self.validate_service_name(name) - logging.debug("Pausing %s container", name) + log.debug("Pausing %s container", name) try: subprocess.check_output( ['docker-compose', '-f', self.compose_path, '-p', self.project_name, 'pause', name], @@ -222,7 +224,7 @@ def unpause_container(self, name): :param str name: container name as it appears in the docker compose file. """ self.validate_service_name(name) - logging.debug("Unpausing %s container", name) + log.debug("Unpausing %s container", name) try: subprocess.check_output( ['docker-compose', '-f', self.compose_path, '-p', self.project_name, 'unpause', name], @@ -237,7 +239,7 @@ def stop_container(self, name): :param str name: container name as it appears in the docker compose file. """ self.validate_service_name(name) - logging.debug("Stopping %s container", name) + log.debug("Stopping %s container", name) try: subprocess.check_output( ['docker-compose', '-f', self.compose_path, '-p', self.project_name, 'stop', name], @@ -252,7 +254,7 @@ def start_container(self, name): :param str name: container name as it appears in the docker compose file. """ self.validate_service_name(name) - logging.debug("Starting %s container", name) + log.debug("Starting %s container", name) try: subprocess.check_output( ['docker-compose', '-f', self.compose_path, '-p', self.project_name, 'start', name], @@ -284,7 +286,7 @@ def is_container_ready(self, name): :param str name: container name as it appears in the docker compose file. """ self.validate_service_name(name) - logging.debug("Getting %s container state", name) + log.debug("Getting %s container state", name) container_id = self.get_container_id(name) try: status_output = subprocess.check_output( @@ -293,7 +295,7 @@ def is_container_ready(self, name): ) except subprocess.CalledProcessError as error: - logging.warning("Failed getting container %s state, reason: %s", name, error.output) + log.warning("Failed getting container %s state, reason: %s", name, error.output) return False if '"Health":' in status_output: @@ -301,7 +303,7 @@ def is_container_ready(self, name): else: is_ready = '"Status":"running"' in status_output - logging.debug("Container %s ready: %s", name, is_ready) + log.debug("Container %s ready: %s", name, is_ready) return is_ready def wait_for_services(self, services=None, interval=1, timeout=60): @@ -311,7 +313,7 @@ def wait_for_services(self, services=None, interval=1, timeout=60): If it doesn't the method will wait for a 'running' state. """ services = services if services else self.services - logging.info('Waiting for %s to reach the required state', services) + log.info('Waiting for %s to reach the required state', services) def service_checks(): """Return True if services checks pass.""" @@ -319,11 +321,11 @@ def service_checks(): try: waiting.wait(service_checks, sleep_seconds=interval, timeout_seconds=timeout) - logging.info('Services %s reached the required state', services) + log.info('Services %s reached the required state', services) return True except waiting.TimeoutExpired: - logging.error('%s failed to to reach the required state', services) + log.error('%s failed to to reach the required state', services) return False @contextmanager @@ -415,7 +417,7 @@ def wait_for_health(self, name, health_check=None, interval=1, timeout=60): :param int interval: interval (in seconds) between checks. :param int timeout: timeout (in seconds) for all checks to pass. """ - logging.debug("Waiting for %s container to be healthy", name) + log.debug("Waiting for %s container to be healthy", name) health_check = health_check if health_check else lambda: self.is_container_ready(name) waiting.wait(health_check, sleep_seconds=interval, timeout_seconds=timeout) @@ -427,7 +429,7 @@ def validate_service_name(self, name): def _get_environment_variables(): """Set the compose api version according to the server's api version""" server_api_version = get_server_api_version() - logging.debug("docker server api version is %s, updating environment_variables", server_api_version) + log.debug("docker server api version is %s, updating environment_variables", server_api_version) env = os.environ.copy() env['COMPOSE_API_VERSION'] = env['DOCKER_API_VERSION'] = server_api_version return env diff --git a/docker_test_tools/plugin.py b/docker_test_tools/plugin.py index 1bad0c7..5f78e03 100644 --- a/docker_test_tools/plugin.py +++ b/docker_test_tools/plugin.py @@ -1,17 +1,12 @@ # pylint: disable=unused-argument -import logging - from nose2.events import Plugin from docker_test_tools.config import Config from docker_test_tools.environment import EnvironmentController -log = logging.getLogger('nose2.plugins.docker_test_tools') - class EnvironmentPlugin(Plugin): """Nose2 plugin, used for managing docker environment operations.""" - configSection = 'environment' commandLineSwitch = (None, 'environment', 'Enable docker test tools environment') diff --git a/docker_test_tools/utils.py b/docker_test_tools/utils.py index 8970200..b6a3253 100644 --- a/docker_test_tools/utils.py +++ b/docker_test_tools/utils.py @@ -4,6 +4,9 @@ import waiting +log = logging.getLogger(__name__) + + def run_health_checks(checks, interval=1, timeout=60): """Return True if all health checks pass (return True). @@ -13,7 +16,7 @@ def run_health_checks(checks, interval=1, timeout=60): :raise bool: True is all the services are healthy, False otherwise. """ - logging.info('Waiting for the required health checks to pass...') + log.info('Waiting for the required health checks to pass...') try: waiting.wait(lambda: all([health_check() for health_check in checks]), sleep_seconds=interval, timeout_seconds=timeout) @@ -21,7 +24,7 @@ def run_health_checks(checks, interval=1, timeout=60): return True except waiting.TimeoutExpired: - logging.error("Required health checks didn't pass within timeout") + log.error("Required health checks didn't pass within timeout") return False @@ -42,12 +45,12 @@ def get_curl_health_check(service_name, url): :return function: function used to determine if the given service is responsive. """ - logging.debug('Defining a CURL based health check for service: %s at: %s', service_name, url) + log.debug('Defining a CURL based health check for service: %s at: %s', service_name, url) def curl_health_check(): """Return True if the service is responsive.""" is_ready = is_curl_responsive(url) - logging.debug('Service %s ready: %s', service_name, is_ready) + log.debug('Service %s ready: %s', service_name, is_ready) return is_ready return curl_health_check diff --git a/docker_test_tools/wiremock.py b/docker_test_tools/wiremock.py index b0b8870..7e610a6 100644 --- a/docker_test_tools/wiremock.py +++ b/docker_test_tools/wiremock.py @@ -10,6 +10,8 @@ import requests +log = logging.getLogger(__name__) + class WiremockError(Exception): """Raised on wiremock controller failures.""" @@ -42,7 +44,7 @@ def set_mapping_from_dir(self, dir_path): :param str dir_path: directory path to scan - should contain json mapping files. """ - logging.debug('Setting service %s wiremock mapping using directory %s', self.url, dir_path) + log.debug('Setting service %s wiremock mapping using directory %s', self.url, dir_path) if not os.path.isdir(dir_path): raise ValueError("'%s' is not a valid dir" % dir_path) @@ -62,7 +64,7 @@ def set_mapping_from_file(self, json_path): :param str json_path: json stub file path. """ - logging.debug('Setting service %s wiremock mapping using file %s', self.url, json_path) + log.debug('Setting service %s wiremock mapping using file %s', self.url, json_path) with open(json_path, 'r') as json_file: json_object = json.load(json_file) self.set_mapping_from_json(json_object) @@ -73,11 +75,11 @@ def set_mapping_from_json(self, json_object): :param json_object: json data of mapping stub. :raise WiremockError: on failure to configure service. """ - logging.debug('Setting service %s wiremock mapping using json: %s', self.url, json_object) + log.debug('Setting service %s wiremock mapping using json: %s', self.url, json_object) try: requests.post(self.admin_mapping_url, json=json_object).raise_for_status() except: - logging.exception("Failed setting service %s wiremock mapping using json: %s", self.url, json_object) + log.exception("Failed setting service %s wiremock mapping using json: %s", self.url, json_object) raise WiremockError("Failed setting service %s wiremock mapping using json: %s" % (self.url, json_object)) def reset_mapping(self): @@ -85,11 +87,11 @@ def reset_mapping(self): :raise WiremockError: on failure to reset service mapping. """ - logging.debug('Resetting %s wiremock mapping', self.url) + log.debug('Resetting %s wiremock mapping', self.url) try: requests.post(self.mapping_reset_url).raise_for_status() except: - logging.exception('Failed resetting %s wiremock mapping', self.url) + log.exception('Failed resetting %s wiremock mapping', self.url) raise WiremockError('Failed resetting %s wiremock mapping' % self.url) def get_request_journal(self): diff --git a/tests/integration/test_example.py b/tests/integration/test_example.py index fc280ea..d6c843b 100644 --- a/tests/integration/test_example.py +++ b/tests/integration/test_example.py @@ -7,6 +7,8 @@ from docker_test_tools.wiremock import WiremockController from docker_test_tools.utils import get_curl_health_check +log = logging.getLogger(__name__) + # Define health check functions for the environment services consul_health_check = get_curl_health_check('consul.service', url='http://consul.service:8500') mock_service_health_check = get_curl_health_check('mocked.service', url='http://mocked.service:9999/__admin') @@ -31,72 +33,72 @@ def setUp(self): def test_services_sanity(self): """Validate services are responsive once the test start.""" - logging.info('Validating consul container is responsive') + log.info('Validating consul container is responsive') self.assertEquals(requests.get('http://consul.service:8500').status_code, httplib.OK) - logging.info('Validating wiremock container is responsive') + log.info('Validating wiremock container is responsive') self.assertEquals(requests.get('http://mocked.service:9999/__admin').status_code, httplib.OK) def test_service_down(self): """Validate service down scenario.""" - logging.info('Validating consul container is responsive') + log.info('Validating consul container is responsive') self.assertEquals(requests.get('http://consul.service:8500').status_code, httplib.OK) - logging.info('Validating consul container is unresponsive while in `container_down` context') + log.info('Validating consul container is unresponsive while in `container_down` context') with self.controller.container_down(name='consul.service', health_check=consul_health_check): with self.assertRaises(requests.ConnectionError): requests.get('http://consul.service:8500') - logging.info('Validating consul container has recovered and is responsive') + log.info('Validating consul container has recovered and is responsive') self.assertEquals(requests.get('http://consul.service:8500').status_code, httplib.OK) def test_service_stopped(self): """Validate service stopped scenario.""" - logging.info('Validating consul container is responsive') + log.info('Validating consul container is responsive') self.assertEquals(requests.get('http://consul.service:8500').status_code, httplib.OK) - logging.info('Validating consul container is unresponsive while in `container_stopped` context') + log.info('Validating consul container is unresponsive while in `container_stopped` context') with self.controller.container_stopped(name='consul.service', health_check=consul_health_check): with self.assertRaises(requests.ConnectionError): requests.get('http://consul.service:8500') - logging.info('Validating consul container has recovered and is responsive') + log.info('Validating consul container has recovered and is responsive') self.assertEquals(requests.get('http://consul.service:8500').status_code, httplib.OK) def test_service_paused(self): """Validate service paused scenario.""" - logging.info('Validating consul container is responsive') + log.info('Validating consul container is responsive') self.assertEquals(requests.get('http://consul.service:8500', timeout=2).status_code, httplib.OK) - logging.info('Validating consul container is unresponsive while in `container_paused` context') + log.info('Validating consul container is unresponsive while in `container_paused` context') with self.controller.container_paused(name='consul.service', health_check=consul_health_check): with self.assertRaises(requests.Timeout): requests.get('http://consul.service:8500', timeout=2) - logging.info('Validating consul container has recovered and is responsive') + log.info('Validating consul container has recovered and is responsive') self.assertEquals(requests.get('http://consul.service:8500', timeout=2).status_code, httplib.OK) def test_mocked_service_configuration(self): """Validate wiremock service.""" - logging.info('Validating mocked service fail to find `test` endpoint') + log.info('Validating mocked service fail to find `test` endpoint') self.assertEquals(requests.post('http://mocked.service:9999/test').status_code, httplib.NOT_FOUND) - logging.info('Use WiremockController to stub the service `test` endpoint') + log.info('Use WiremockController to stub the service `test` endpoint') stubs_dir_path = os.path.join(os.path.dirname(__file__), '..', 'resources', 'wiremock_stubs') self.wiremock.set_mapping_from_dir(stubs_dir_path) - logging.info('Validating mocked service response on `test` endpoint') + log.info('Validating mocked service response on `test` endpoint') self.assertEquals(requests.post('http://mocked.service:9999/test').status_code, httplib.OK) def test_mocked_service_request_journal(self): """Validate wiremock request journal.""" - logging.info('Validating first request reaches the journal') + log.info('Validating first request reaches the journal') requests.post('http://mocked.service:9999/some-unique-request-33452') journal = self.wiremock.get_request_journal() inner_url = journal[-1]['request']['url'] self.assertEquals(inner_url, "/some-unique-request-33452") - logging.info('Validating filtering of specific requests from the journal') + log.info('Validating filtering of specific requests from the journal') requests.post('http://mocked.service:9999/test2') requests.post('http://mocked.service:9999/test2') filtered = self.wiremock.get_matching_requests('/test2') @@ -104,7 +106,7 @@ def test_mocked_service_request_journal(self): self.assertEquals(filtered[0]['request']['url'], "/test2") self.assertEquals(filtered[1]['request']['url'], "/test2") - logging.info('Validating the deletion of requests from the journal') + log.info('Validating the deletion of requests from the journal') self.wiremock.delete_request_journal() journal = self.wiremock.get_matching_requests('/test2') self.assertEquals(len(journal), 0)