default on telemetry + logs to investigate failing test

Signed-off-by: Nikhil Suri <[email protected]>

Author: nikhilsuri-db

src/databricks/sql/client.py

@@ -320,7 +320,7 @@ def read(self) -> Optional[OAuthToken]:
         )
 
         self.force_enable_telemetry = kwargs.get("force_enable_telemetry", False)
-        self.enable_telemetry = kwargs.get("enable_telemetry", False)
+        self.enable_telemetry = kwargs.get("enable_telemetry", True)  # Default to True for telemetry
         self.telemetry_enabled = TelemetryHelper.is_telemetry_enabled(self)
 
         TelemetryClientFactory.initialize_telemetry_client(

src/databricks/sql/common/feature_flag.py

@@ -106,28 +106,37 @@ def get_flag_value(self, name: str, default_value: Any) -> Any:
 
     def _refresh_flags(self):
         """Performs a synchronous network request to fetch and update flags."""
+        import logging
+        logger = logging.getLogger(__name__)
+        
         headers = {}
         try:
             # Authenticate the request
             self._connection.session.auth_provider.add_headers(headers)
             headers["User-Agent"] = self._connection.session.useragent_header
 
+            logger.info(f"Fetching feature flags from: {self._feature_flag_endpoint}")
             response = self._http_client.request(
                 HttpMethod.GET, self._feature_flag_endpoint, headers=headers, timeout=30
             )
 
+            logger.info(f"Feature flag response status: {response.status}")
             if response.status == 200:
                 # Parse JSON response from urllib3 response data
                 response_data = json.loads(response.data.decode())
+                logger.info(f"Feature flag response data: {response_data}")
                 ff_response = FeatureFlagsResponse.from_dict(response_data)
                 self._update_cache_from_response(ff_response)
+                logger.info(f"Feature flags loaded: {self._flags}")
             else:
                 # On failure, initialize with an empty dictionary to prevent re-blocking.
+                logger.info(f"Feature flag fetch failed with status {response.status}, initializing empty flags")
                 if self._flags is None:
                     self._flags = {}
 
         except Exception as e:
             # On exception, initialize with an empty dictionary to prevent re-blocking.
+            logger.info(f"Feature flag fetch exception: {type(e).__name__}: {e}, initializing empty flags")
             if self._flags is None:
                 self._flags = {}
 

src/databricks/sql/telemetry/telemetry_client.py

@@ -110,15 +110,21 @@ def get_auth_flow(auth_provider):
     @staticmethod
     def is_telemetry_enabled(connection: "Connection") -> bool:
         if connection.force_enable_telemetry:
+            logger.info("Telemetry: force_enable_telemetry=True, telemetry ENABLED")
             return True
 
         if connection.enable_telemetry:
+            logger.info(f"Telemetry: enable_telemetry=True, checking feature flag: {TelemetryHelper.TELEMETRY_FEATURE_FLAG_NAME}")
             context = FeatureFlagsContextFactory.get_instance(connection)
             flag_value = context.get_flag_value(
                 TelemetryHelper.TELEMETRY_FEATURE_FLAG_NAME, default_value=False
             )
-            return str(flag_value).lower() == "true"
+            logger.info(f"Telemetry: feature flag value = '{flag_value}'")
+            enabled = str(flag_value).lower() == "true"
+            logger.info(f"Telemetry: feature flag check result = {enabled}")
+            return enabled
         else:
+            logger.info("Telemetry: enable_telemetry=False, telemetry DISABLED")
             return False
 
 
@@ -191,13 +197,12 @@ def __init__(
 
     def _export_event(self, event):
         """Add an event to the batch queue and flush if batch is full"""
-        logger.debug("Exporting event for connection %s", self._session_id_hex)
+        logger.info(f"Exporting telemetry event for connection {self._session_id_hex}")
         with self._lock:
             self._events_batch.append(event)
+        logger.info(f"Event added to batch, batch size now: {len(self._events_batch)}/{self._batch_size}")
         if len(self._events_batch) >= self._batch_size:
-            logger.debug(
-                "Batch size limit reached (%s), flushing events", self._batch_size
-            )
+            logger.info(f"Batch size reached ({self._batch_size}), flushing events")
             self._flush()
 
     def _flush(self):
@@ -465,9 +470,8 @@ def initialize_telemetry_client(
                 TelemetryClientFactory._initialize()
 
                 if session_id_hex not in TelemetryClientFactory._clients:
-                    logger.debug(
-                        "Creating new TelemetryClient for connection %s",
-                        session_id_hex,
+                    logger.info(
+                        f"Creating telemetry client for connection {session_id_hex}, telemetry_enabled={telemetry_enabled}"
                     )
                     if telemetry_enabled:
                         TelemetryClientFactory._clients[
@@ -481,14 +485,17 @@ def initialize_telemetry_client(
                             batch_size=batch_size,
                             client_context=client_context,
                         )
+                        logger.info(f"Created TelemetryClient for connection {session_id_hex}")
                     else:
                         TelemetryClientFactory._clients[
                             session_id_hex
                         ] = NoopTelemetryClient()
+                        logger.info(f"Created NoopTelemetryClient for connection {session_id_hex}")
         except Exception as e:
-            logger.debug("Failed to initialize telemetry client: %s", e)
+            logger.info(f"Failed to initialize telemetry client: {type(e).__name__}: {e}")
             # Fallback to NoopTelemetryClient to ensure connection doesn't fail
             TelemetryClientFactory._clients[session_id_hex] = NoopTelemetryClient()
+            logger.info(f"Fallback to NoopTelemetryClient for connection {session_id_hex}")
 
     @staticmethod
     def get_telemetry_client(session_id_hex):

tests/e2e/test_telemetry_e2e.py

@@ -277,6 +277,13 @@ def test_enable_telemetry_on_with_server_on_sends_events(
         Scenario: enable_telemetry=ON, force_enable_telemetry=OFF, server=ON
         Expected: 2 events (initial_log + latency_log)
         """
+        from databricks.sql.telemetry.telemetry_client import TelemetryHelper
+        
+        print(f"\n{'='*80}")
+        print(f"TEST: test_enable_telemetry_on_with_server_on_sends_events")
+        print(f"Feature flag being checked: {TelemetryHelper.TELEMETRY_FEATURE_FLAG_NAME}")
+        print(f"{'='*80}\n")
+        
         (
             captured_events,
             captured_futures,
@@ -296,6 +303,11 @@ def test_enable_telemetry_on_with_server_on_sends_events(
                     "telemetry_batch_size": 1,
                 }
             ) as conn:
+                print(f"\nConnection created:")
+                print(f"  enable_telemetry: {conn.enable_telemetry}")
+                print(f"  force_enable_telemetry: {conn.force_enable_telemetry}")
+                print(f"  telemetry_enabled (computed): {conn.telemetry_enabled}")
+                print(f"  telemetry_client type: {type(conn._telemetry_client).__name__}\n")
                 with conn.cursor() as cursor:
                     cursor.execute("SELECT 1")
                     cursor.fetchone()
@@ -424,6 +436,82 @@ def test_both_flags_off_does_not_send_events(self, telemetry_interceptors):
 
             print(f"\nStatement ID: {statement_id}")
 
+    def test_default_behavior_sends_events_with_server_flag_on(
+        self, telemetry_interceptors
+    ):
+        """
+        Scenario: Neither enable_telemetry nor force_enable_telemetry passed (uses defaults)
+        Expected: 2 events (initial_log + latency_log) when server feature flag is ON
+        
+        Default behavior:
+        - enable_telemetry defaults to True
+        - force_enable_telemetry defaults to False
+        - Telemetry will be sent if server feature flag is enabled
+        """
+        from databricks.sql.telemetry.telemetry_client import TelemetryHelper
+        
+        print(f"\n{'='*80}")
+        print(f"TEST: test_default_behavior_sends_events_with_server_flag_on")
+        print(f"Feature flag being checked: {TelemetryHelper.TELEMETRY_FEATURE_FLAG_NAME}")
+        print(f"Testing DEFAULT behavior (no flags passed explicitly)")
+        print(f"{'='*80}\n")
+        
+        (
+            captured_events,
+            captured_futures,
+            export_wrapper,
+            callback_wrapper,
+        ) = telemetry_interceptors
+
+        with patch.object(
+            TelemetryClient, "_export_event", export_wrapper
+        ), patch.object(
+            TelemetryClient, "_telemetry_request_callback", callback_wrapper
+        ):
+            # Connection without explicit telemetry flags - relies on defaults
+            with self.connection(
+                extra_params={
+                    "telemetry_batch_size": 1,
+                }
+            ) as conn:
+                # Verify defaults are as expected
+                print(f"\nConnection created with DEFAULT settings:")
+                print(f"  enable_telemetry (default): {conn.enable_telemetry}")
+                print(f"  force_enable_telemetry (default): {conn.force_enable_telemetry}")
+                print(f"  telemetry_enabled (computed): {conn.telemetry_enabled}")
+                print(f"  telemetry_client type: {type(conn._telemetry_client).__name__}\n")
+                
+                with conn.cursor() as cursor:
+                    cursor.execute("SELECT 99")
+                    cursor.fetchone()
+                    statement_id = cursor.query_id
+
+            time.sleep(2)
+            done, not_done = wait(captured_futures, timeout=10)
+
+            # With default enable_telemetry=True and server flag ON, expect 2 events
+            assert (
+                len(captured_events) == 2
+            ), f"Expected exactly 2 events with default settings, got {len(captured_events)}"
+            assert len(done) == 2, f"Expected exactly 2 responses, got {len(done)}"
+
+            # Verify HTTP responses
+            for future in done:
+                response = future.result()
+                assert 200 <= response.status < 300
+
+            # Assert payload for all events
+            for event in captured_events:
+                self.assertSystemConfiguration(event)
+                self.assertConnectionParams(
+                    event, expected_http_path=self.arguments["http_path"]
+                )
+
+            # Assert latency event (second event)
+            self.assertStatementExecution(captured_events[1])
+
+            print(f"\nStatement ID: {statement_id}")
+
     def test_sql_error_sends_telemetry_with_error_info(self, telemetry_interceptors):
         """
         Scenario: SQL query with invalid syntax causes error