From f23080fb09da3eb5681bdd307fb7fd729251ede6 Mon Sep 17 00:00:00 2001 From: Jared Casey Date: Mon, 4 Aug 2025 12:27:18 -0600 Subject: [PATCH] PYCO-76: Logging Improvements Changes ------- * Add logger to test environment * Allow initial log message, `Python Couchbase Analytics Client ({PYCBAC_VERSION})`, to display if either root logger has a handler or PYCBAC_LOG_LEVEL environment is set. --- couchbase_analytics/protocol/__init__.py | 6 ++++-- couchbase_analytics/tests/test_server_t.py | 1 - tests/__init__.py | 4 ++++ tests/environments/base_environment.py | 21 ++++++++++++--------- tests/test_config.ini | 2 +- tests/utils/__init__.py | 1 - tests/utils/_run_web_server.py | 2 -- tests/utils/_test_async_httpx.py | 15 +++++++++++---- tests/utils/_test_httpx.py | 9 +++++++-- 9 files changed, 39 insertions(+), 22 deletions(-) diff --git a/couchbase_analytics/protocol/__init__.py b/couchbase_analytics/protocol/__init__.py index 8c4f837..07b8725 100644 --- a/couchbase_analytics/protocol/__init__.py +++ b/couchbase_analytics/protocol/__init__.py @@ -35,11 +35,13 @@ def configure_logger() -> None: import os log_level = os.getenv('PYCBAC_LOG_LEVEL', None) - if log_level: + handlers_setup = logging.getLogger().hasHandlers() + if log_level is not None or handlers_setup: logger = logging.getLogger() - if not logger.hasHandlers(): + if not handlers_setup: from couchbase_analytics.common.logging import LOG_DATE_FORMAT, LOG_FORMAT + log_level = log_level or 'INFO' logging.basicConfig(format=LOG_FORMAT, datefmt=LOG_DATE_FORMAT, level=log_level.upper()) logger.info(f'Python Couchbase Analytics Client ({PYCBAC_VERSION})') diff --git a/couchbase_analytics/tests/test_server_t.py b/couchbase_analytics/tests/test_server_t.py index 74ddbd4..8652756 100644 --- a/couchbase_analytics/tests/test_server_t.py +++ b/couchbase_analytics/tests/test_server_t.py @@ -122,7 +122,6 @@ def test_error_retriable_response_retries_exceeded(self, test_env: BlockingTestE with pytest.raises(QueryError) as ex: test_env.cluster_or_scope.execute_query(statement, q_opts) - print(ex.value) test_env.assert_error_context_num_attempts(allowed_retries + 1, ex.value._context) test_env.assert_error_context_contains_last_dispatch(ex.value._context) diff --git a/tests/__init__.py b/tests/__init__.py index 362877b..37106bc 100644 --- a/tests/__init__.py +++ b/tests/__init__.py @@ -13,9 +13,13 @@ # See the License for the specific language governing permissions and # limitations under the License. +import logging from enum import Enum from typing import AsyncGenerator, Generator, Optional, TypeVar +TEST_LOGGER_NAME = 'couchbase_analytics_test' +logger = logging.getLogger(TEST_LOGGER_NAME) + T = TypeVar('T') AsyncYieldFixture = AsyncGenerator[T, None] YieldFixture = Generator[T, None, None] diff --git a/tests/environments/base_environment.py b/tests/environments/base_environment.py index 8afd4ab..7e2ff7c 100644 --- a/tests/environments/base_environment.py +++ b/tests/environments/base_environment.py @@ -16,6 +16,7 @@ from __future__ import annotations import json +import logging import pathlib import sys from os import path @@ -37,7 +38,7 @@ from couchbase_analytics.options import ClusterOptions, SecurityOptions from couchbase_analytics.result import BlockingQueryResult from couchbase_analytics.scope import Scope -from tests import AnalyticsTestEnvironmentError +from tests import TEST_LOGGER_NAME, AnalyticsTestEnvironmentError from tests.test_server import ResultType from tests.utils._run_web_server import WebServerHandler @@ -47,6 +48,8 @@ TEST_AIRLINE_DATA_PATH = path.join(pathlib.Path(__file__).parent.parent, 'test_data', 'airline.json') +logger = logging.getLogger(TEST_LOGGER_NAME) + class TestEnvironmentOptionsKwargs(TypedDict, total=False): async_cluster: Optional[AsyncCluster] @@ -199,7 +202,6 @@ def enable_test_server(self) -> BlockingTestEnvironment: from tests.utils._client_adapter import _TestClientAdapter from tests.utils._test_httpx import TestHTTPTransport - print(f'{self._cluster=}') new_adapter = _TestClientAdapter( adapter=self._cluster._impl._client_adapter, http_transport_cls=TestHTTPTransport, @@ -207,7 +209,7 @@ def enable_test_server(self) -> BlockingTestEnvironment: new_adapter.create_client() self._cluster._impl._client_adapter = new_adapter url = self._cluster._impl.client_adapter.connection_details.url.get_formatted_url() - print(f'Connecting to test server at {url}') + logger.info(f'Connecting to test server at {url}') self._server_handler.start_server() self.warmup_test_server() return self @@ -336,6 +338,7 @@ def get_environment( else: sec_opts = SecurityOptions(disable_server_certificate_verification=True) + logger.info(f'Creating Cluster with options={env_opts}') if sec_opts is not None: opts = ClusterOptions(security_options=sec_opts) env_opts['cluster'] = Cluster.create_instance(connstr, cred, opts) @@ -425,7 +428,7 @@ async def enable_test_server(self) -> AsyncTestEnvironment: await new_adapter.create_client() self._async_cluster._impl._client_adapter = new_adapter url = self._async_cluster._impl.client_adapter.connection_details.url.get_formatted_url() - print(f'Connecting to test server at {url}') + logger.info(f'Connecting to test server at {url}') self._server_handler.start_server() await self.warmup_test_server() return self @@ -559,7 +562,7 @@ def get_environment( else: sec_opts = SecurityOptions(disable_server_certificate_verification=True) - print(f'{env_opts=}') + logger.info(f'Creating AsyncCluster with options={env_opts}') if sec_opts is not None: opts = ClusterOptions(security_options=sec_opts) env_opts['async_cluster'] = AsyncCluster.create_instance(connstr, cred, opts) @@ -574,20 +577,20 @@ def get_environment( @pytest.fixture(scope='class', name='sync_test_env') def base_test_environment(analytics_config: AnalyticsConfig) -> BlockingTestEnvironment: - print('Creating sync test environment') + logger.info('Creating sync test environment') return BlockingTestEnvironment.get_environment(analytics_config) @pytest.fixture(scope='class', name='sync_test_env_with_server') def base_test_environment_with_server(analytics_config: AnalyticsConfig) -> BlockingTestEnvironment: - print('Creating sync test environment w/ test server') + logger.info('Creating sync test environment w/ test server') server_handler = WebServerHandler() return BlockingTestEnvironment.get_environment(analytics_config, server_handler=server_handler) @pytest.fixture(scope='class', name='async_test_env') def base_async_test_environment(analytics_config: AnalyticsConfig, anyio_backend: str) -> AsyncTestEnvironment: - print('Creating async test environment') + logger.info('Creating async test environment') return AsyncTestEnvironment.get_environment(analytics_config, backend=anyio_backend) @@ -595,6 +598,6 @@ def base_async_test_environment(analytics_config: AnalyticsConfig, anyio_backend def base_async_test_environment_with_server( analytics_config: AnalyticsConfig, anyio_backend: str ) -> AsyncTestEnvironment: - print('Creating async test environment w/ test server') + logger.info('Creating async test environment w/ test server') server_handler = WebServerHandler() return AsyncTestEnvironment.get_environment(analytics_config, server_handler=server_handler, backend=anyio_backend) diff --git a/tests/test_config.ini b/tests/test_config.ini index 82d35de..7acdd29 100644 --- a/tests/test_config.ini +++ b/tests/test_config.ini @@ -1,6 +1,6 @@ [analytics] scheme = http -host = 3585106b-20250708.cb-sdk.bemdas.com +host = 192.168.107.129 port = 8095 username = Administrator password = password diff --git a/tests/utils/__init__.py b/tests/utils/__init__.py index 07ae16b..e50b1d3 100644 --- a/tests/utils/__init__.py +++ b/tests/utils/__init__.py @@ -81,7 +81,6 @@ async def __anext__(self) -> bytes: if len(self._data) == 0: raise StopAsyncIteration if len(self._end_data) > 0: - print(f'end_data={self._end_data}') # ending a results array self._data += b'], ' self._data += bytearray(self._end_data) diff --git a/tests/utils/_run_web_server.py b/tests/utils/_run_web_server.py index 0d550d7..b62cde2 100644 --- a/tests/utils/_run_web_server.py +++ b/tests/utils/_run_web_server.py @@ -24,8 +24,6 @@ WEB_SERVER_PATH = path.join(pathlib.Path(__file__).parent.parent, 'test_server', 'web_server.py') -print(f'Web server script path: {WEB_SERVER_PATH}') - logging.basicConfig( level=logging.INFO, stream=sys.stderr, format='%(asctime)s - %(levelname)s - (PID:%(process)d) - %(message)s' ) diff --git a/tests/utils/_test_async_httpx.py b/tests/utils/_test_async_httpx.py index da7ad7d..7b51a6f 100644 --- a/tests/utils/_test_async_httpx.py +++ b/tests/utils/_test_async_httpx.py @@ -1,3 +1,4 @@ +import logging import typing from httpcore import AsyncConnectionPool, Origin, Request, Response @@ -10,6 +11,10 @@ from httpcore._trace import Trace from httpx import AsyncHTTPTransport, Limits, create_ssl_context +from tests import TEST_LOGGER_NAME + +cb_logger = logging.getLogger(TEST_LOGGER_NAME) + class TestAsyncHTTPConnection(AsyncHTTPConnection): def __init__(self, *args, **kwargs) -> None: # type: ignore @@ -19,9 +24,10 @@ async def _connect(self, request: Request) -> AsyncNetworkStream: timeouts = request.extensions.get('timeout', {}) sni_hostname = request.extensions.get('sni_hostname', None) timeout = timeouts.get('connect', None) - # TESTING_OVERRIDE + # -- START PYCBAC TESTING -- test_connect_timeout = timeouts.get('test_connect_timeout', None) - print(f'PYCBAC OVERRIDE: connect timeout: {timeout}, test_connect_timeout: {test_connect_timeout}') + cb_logger.debug(f'PYCBAC OVERRIDE: connect timeout: {timeout}, test_connect_timeout: {test_connect_timeout}') + # -- END PYCBAC TESTING -- retries_left = self._retries delays = exponential_backoff(factor=RETRIES_BACKOFF_FACTOR) @@ -144,9 +150,10 @@ async def handle_async_request(self, request: Request) -> Response: timeouts = request.extensions.get('timeout', {}) timeout = timeouts.get('pool', None) - # TESTING_OVERRIDE + # -- START PYCBAC TESTING -- test_pool_timeout = timeouts.get('test_pool_timeout', None) - print(f'PYCBAC OVERRIDE: pool timeout: {timeout}, test_pool_timeout: {test_pool_timeout}') + cb_logger.debug(f'PYCBAC OVERRIDE: pool timeout: {timeout}, test_pool_timeout: {test_pool_timeout}') + # -- END PYCBAC TESTING -- with self._optional_thread_lock: # Add the incoming request to our request queue. diff --git a/tests/utils/_test_httpx.py b/tests/utils/_test_httpx.py index e0a85f2..68396b2 100644 --- a/tests/utils/_test_httpx.py +++ b/tests/utils/_test_httpx.py @@ -1,3 +1,4 @@ +import logging import time import typing @@ -11,6 +12,10 @@ from httpcore._trace import Trace from httpx import HTTPTransport, Limits, create_ssl_context +from tests import TEST_LOGGER_NAME + +cb_logger = logging.getLogger(TEST_LOGGER_NAME) + class TestHTTPConnection(HTTPConnection): def __init__(self, *args, **kwargs) -> None: # type: ignore @@ -22,7 +27,7 @@ def _connect(self, request: Request) -> NetworkStream: timeout = timeouts.get('connect', None) # -- START PYCBAC TESTING -- test_connect_timeout = timeouts.get('test_connect_timeout', None) - print(f'PYCBAC OVERRIDE: connect timeout: {timeout}, test_connect_timeout: {test_connect_timeout}') + cb_logger.debug(f'PYCBAC OVERRIDE: connect timeout: {timeout}, test_connect_timeout: {test_connect_timeout}') # -- END PYCBAC TESTING -- retries_left = self._retries @@ -158,7 +163,7 @@ def handle_request(self, request: Request) -> Response: timeout = timeouts.get('pool', None) # -- START PYCBAC TESTING -- test_pool_timeout = timeouts.get('test_pool_timeout', None) - print(f'PYCBAC OVERRIDE: pool timeout: {timeout}, test_pool_timeout: {test_pool_timeout}') + cb_logger.debug(f'PYCBAC OVERRIDE: pool timeout: {timeout}, test_pool_timeout: {test_pool_timeout}') # -- END PYCBAC TESTING -- with self._optional_thread_lock: