PYCO-76: Logging Improvements (#6)

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.

Author: thejcfactor

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})')
 

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)
 

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]

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,15 +202,14 @@ 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,
         )
         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,27 +577,27 @@ 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)
 
 
 @pytest.fixture(scope='class', name='async_test_env_with_server')
 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)

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

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)

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'
 )

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.

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: