add logs between 200 HTTP response and returning from download_chunk

src/snowflake/connector/azure_storage_client.py

@@ -248,5 +248,14 @@ def download_chunk(self, chunk_id: int) -> None:
             # single request
             r = self._send_request_with_authentication_and_retry("GET", url, chunk_id)
         if r.status_code in (200, 206):
+            logger.debug(
+                f"Writing downloaded chunk. chunk_id: {chunk_id}/{self.num_of_chunks}, url: {url}"
+            )
             self.write_downloaded_chunk(chunk_id, r.content)
+            logger.debug(
+                f"Wrote downloaded chunk. chunk_id: {chunk_id}/{self.num_of_chunks}, url: {url}"
+            )
         r.raise_for_status()
+        logger.debug(
+            f"Exiting download_chunk. chunk_id: {chunk_id}/{self.num_of_chunks}, url: {url}"
+        )

src/snowflake/connector/s3_storage_client.py

@@ -543,8 +543,14 @@ def download_chunk(self, chunk_id: int) -> None:
                 ignore_content_encoding=True,
             )
             if response.status_code == 200:
+                logger.debug(
+                    f"Writing downloaded chunk. chunk_id: {chunk_id}/{self.num_of_chunks}, url: {url}"
+                )
                 self.write_downloaded_chunk(0, response.content)
                 self.meta.result_status = ResultStatus.DOWNLOADED
+                logger.debug(
+                    f"Writing downloaded chunk. chunk_id: {chunk_id}/{self.num_of_chunks}, url: {url}"
+                )
             response.raise_for_status()
         else:
             chunk_size = self.chunk_size
@@ -560,8 +566,17 @@ def download_chunk(self, chunk_id: int) -> None:
                 headers={"Range": f"bytes={_range}"},
             )
             if response.status_code in (200, 206):
+                logger.debug(
+                    f"Writing downloaded chunk. chunk_id: {chunk_id}/{self.num_of_chunks}, url: {url}"
+                )
                 self.write_downloaded_chunk(chunk_id, response.content)
+                logger.debug(
+                    f"Wrote downloaded chunk. chunk_id: {chunk_id}/{self.num_of_chunks}, url: {url}"
+                )
             response.raise_for_status()
+            logger.debug(
+                f"Exiting download_chunk. chunk_id: {chunk_id}/{self.num_of_chunks}, url: {url}"
+            )
 
     def _get_bucket_accelerate_config(self, bucket_name: str) -> bool:
         query_parts = (("accelerate", ""),)

src/snowflake/connector/storage_client.py

@@ -285,6 +285,7 @@ def _send_request_with_retry(
                     with conn._rest._use_requests_session(url) as session:
                         logger.debug(f"storage client request with session {session}")
                         response = session.request(verb, url, **rest_kwargs)
+                        logger.debug(f"storage client response: {response}")
                 else:
                     logger.debug("storage client request with new session")
                     response = rest_call(url, **rest_kwargs)
@@ -294,6 +295,7 @@ def _send_request_with_retry(
                 else:
                     self.last_err_is_presigned_url = False
                     if response.status_code in self.TRANSIENT_HTTP_ERR:
+                        logger.debug(f"transient http error before sleep: {response}")
                         time.sleep(
                             min(
                                 # TODO should SLEEP_UNIT come from the parent
@@ -302,10 +304,16 @@ def _send_request_with_retry(
                                 self.SLEEP_MAX,
                             )
                         )
+                        logger.debug(f"transient http error after sleep: {response}")
                         self.retry_count[retry_id] += 1
                     elif self._has_expired_token(response):
+                        logger.debug(f"expired token: {response}")
                         self.credentials.update(cur_timestamp)
+                        logger.debug(f"updated expired token: {response}")
                     else:
+                        logger.debug(
+                            f"Exiting storage_client._send_request_with_retry(): {response}"
+                        )
                         return response
             except self.TRANSIENT_ERRORS as e:
                 self.last_err_is_presigned_url = False

src/snowflake/connector/vendored/requests/adapters.py

@@ -5,7 +5,7 @@
 This module contains the transport adapters that Requests uses to define
 and maintain connections.
 """
-
+import logging
 import os.path
 import socket  # noqa: F401
 
@@ -66,6 +66,8 @@ def SOCKSProxyManager(*args, **kwargs):
 DEFAULT_RETRIES = 0
 DEFAULT_POOL_TIMEOUT = None
 
+log = logging.getLogger(__name__)
+
 
 class BaseAdapter:
     """The Base Transport Adapter"""
@@ -535,4 +537,5 @@ def send(
             else:
                 raise
 
+        log.debug(f"Exiting adapters.send(). request: {request}")
         return self.build_response(request, resp)

src/snowflake/connector/vendored/urllib3/connectionpool.py

@@ -493,6 +493,7 @@ def _make_request(
                 exc_info=True,
             )
 
+        log.debug(f'Returning from _make_request(). {self.scheme}://{self.host}:{self.port} "{method} {url} {http_version}')
         return httplib_response
 
     def _absolute_url(self, path):
@@ -743,10 +744,13 @@ def urlopen(
             # Everything went great!
             clean_exit = True
 
+            log.debug(f"Clean exit from urlopen(). Method: {method}, url: {url}")
+
         except EmptyPoolError:
             # Didn't get a connection from the pool, no need to clean up
             clean_exit = True
             release_this_conn = False
+            log.debug(f"EmptyPoolError from urlopen(). Method: {method}, url: {url}")
             raise
 
         except (
@@ -803,6 +807,7 @@ def _is_ssl_error_message_from_http_proxy(ssl_error):
 
             # Keep track of the error for the retry warning.
             err = e
+            log.debug(f"Connection failures from urlopen(). Method: {method}, url: {url}")
 
         finally:
             if not clean_exit:
@@ -907,6 +912,7 @@ def _is_ssl_error_message_from_http_proxy(ssl_error):
                 **response_kw
             )
 
+        log.debug(f"Exiting urlopen(). Method: {method}, url: {url}, response: {response}")
         return response