strange behaviour with CloudFetch

Start with the CloudFetchQueue, ResultFileDownloadManager, ResultSetDownloadHandler, and FetchResults entry points named in the debug log, then reproduce the large Azure Databricks query. Trace the transition at the final row offset and verify that complete result retrieval finishes without the reported missing-file warning or unexplained delay.

Hi,

i have created a small python-script to fetch data from the sql-endpoint in azure databricks. The queried view has 2126641 rows. As you can see, CloudFetch serves batches as files as expected. Also the performance and data-throughput is very good until this line:

2024-11-27 05:35:22,038 - DEBUG - CloudFetchQueue: Cannot find downloaded file for row 2126641

It tries to fetch a file for the last position, what fails. After that, there is obviously a gap of 22 seconds, where seemingly nothing happens. When monitoring the network-traffic, you can see that until that point, i have full throughput of my internet-connection. After this point, nearly no more network-activity until the connection was closed. I did this test, because i experienced a similar behaviour over a ODBC-Connection with Simba Spark-Driver, where also CloudFetch should be used. So i am not sure if this behaviour is special to the API-Connection and databricks-sql-connector or if this is a general problem with CloudFetch or if this is intended and why it should be?
Any thoughts about this?

tested with databricks-sql-connector 3.6 and python 3.9 as well as with python 3.12.5.

2024-11-27 05:35:08,235 - INFO - Starting Databricks SQL query... 2024-11-27 05:35:09,821 - DEBUG - retry parameter: _retry_delay_min given_or_default 1.0 2024-11-27 05:35:09,821 - DEBUG - retry parameter: _retry_delay_max given_or_default 60.0 2024-11-27 05:35:09,821 - DEBUG - retry parameter: _retry_stop_after_attempts_count given_or_default 30 2024-11-27 05:35:09,821 - DEBUG - retry parameter: _retry_stop_after_attempts_duration given_or_default 900.0 2024-11-27 05:35:09,821 - DEBUG - retry parameter: _retry_delay_default given_or_default 5.0 2024-11-27 05:35:09,824 - DEBUG - Sending request: OpenSession(<REDACTED>) 2024-11-27 05:35:09,824 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.azuredatabricks.net:443 2024-11-27 05:35:10,212 - DEBUG - https://<REDACTED>.azuredatabricks.net:443 "POST /sql/1.0/warehouses/<REDACTED> HTTP/1.1" 200 None 2024-11-27 05:35:10,213 - DEBUG - Received response: TOpenSessionResp(<REDACTED>) 2024-11-27 05:35:10,213 - INFO - Successfully opened session 01efac78-fc58-1b8c-b7bd-06ce90e9b72f 2024-11-27 05:35:10,213 - DEBUG - Executing query: SELECT * FROM apteco.src.at_kunden-aktionen 2024-11-27 05:35:10,213 - DEBUG - Sending request: ExecuteStatement(<REDACTED>) 2024-11-27 05:35:11,530 - DEBUG - https://<REDACTED>.azuredatabricks.net:443 "POST /sql/1.0/warehouses/<REDACTED> HTTP/1.1" 200 None 2024-11-27 05:35:11,538 - DEBUG - Received response: TExecuteStatementResp(<REDACTED>) 2024-11-27 05:35:11,539 - DEBUG - Initialize CloudFetch loader, row set start offset: 0, file list: 2024-11-27 05:35:11,539 - DEBUG - - start row offset: 0, row count: 110592 2024-11-27 05:35:11,539 - DEBUG - - start row offset: 110592, row count: 77136 2024-11-27 05:35:11,539 - DEBUG - - start row offset: 187728, row count: 110592 2024-11-27 05:35:11,539 - DEBUG - - start row offset: 298320, row count: 110592 2024-11-27 05:35:11,539 - DEBUG - - start row offset: 408912, row count: 110592 2024-11-27 05:35:11,539 - DEBUG - ResultFileDownloadManager: adding file link, start offset 0, row count: 110592 2024-11-27 05:35:11,539 - DEBUG - ResultFileDownloadManager: adding file link, start offset 110592, row count: 77136 2024-11-27 05:35:11,539 - DEBUG - ResultFileDownloadManager: adding file link, start offset 187728, row count: 110592 2024-11-27 05:35:11,539 - DEBUG - ResultFileDownloadManager: adding file link, start offset 298320, row count: 110592 2024-11-27 05:35:11,539 - DEBUG - ResultFileDownloadManager: adding file link, start offset 408912, row count: 110592 2024-11-27 05:35:11,539 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 0 2024-11-27 05:35:11,539 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:11,539 - DEBUG - - start: 0, row count: 110592 2024-11-27 05:35:11,540 - DEBUG - ResultSetDownloadHandler: starting file download, offset 0, row count 110592 2024-11-27 05:35:11,540 - DEBUG - - start: 110592, row count: 77136 2024-11-27 05:35:11,541 - DEBUG - ResultSetDownloadHandler: starting file download, offset 110592, row count 77136 2024-11-27 05:35:11,541 - DEBUG - - start: 187728, row count: 110592 2024-11-27 05:35:11,543 - DEBUG - ResultSetDownloadHandler: starting file download, offset 187728, row count 110592 2024-11-27 05:35:11,544 - DEBUG - - start: 298320, row count: 110592 2024-11-27 05:35:11,544 - DEBUG - ResultSetDownloadHandler: starting file download, offset 298320, row count 110592 2024-11-27 05:35:11,544 - DEBUG - - start: 408912, row count: 110592 2024-11-27 05:35:11,547 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.blob.core.windows.net:443 2024-11-27 05:35:11,548 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.blob.core.windows.net:443 2024-11-27 05:35:11,549 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.blob.core.windows.net:443 2024-11-27 05:35:11,550 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.blob.core.windows.net:443 2024-11-27 05:35:11,551 - DEBUG - ResultSetDownloadHandler: starting file download, offset 408912, row count 110592 2024-11-27 05:35:11,553 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.blob.core.windows.net:443 2024-11-27 05:35:12,085 - DEBUG - https://<REDACTED>.blob.core.windows.net:443 "GET /jobs/7551410669527543/sql/2024-11-27/03/results_2024-11-27T03:50:13Z_0841d744-5100-492c-90b5-f6df3c75cd28?sig=<REDACTED>&se=<REDACTED>&sv=<REDACTED>&spr=<REDACTED>&sp=<REDACTED>&sr=<REDACTED> HTTP/1.1" 200 9596381 2024-11-27 05:35:12,088 - DEBUG - https://<REDACTED>.blob.core.windows.net:443 "GET /jobs/7551410669527543/sql/2024-11-27/03/results_2024-11-27T03:50:14Z_27728922-8a08-4e33-9855-350ef4e99397?sig=<REDACTED>&se=<REDACTED>&sv=<REDACTED>&spr=<REDACTED>&sp=<REDACTED>&sr=<REDACTED> HTTP/1.1" 200 6690419 2024-11-27 05:35:12,105 - DEBUG - https://<REDACTED>.blob.core.windows.net:443 "GET /jobs/7551410669527543/sql/2024-11-27/03/results_2024-11-27T03:50:14Z_408d6edd-64e3-4a00-b735-46f67958d59f?sig=<REDACTED>&se=<REDACTED>&sv=<REDACTED>&spr=<REDACTED>&sp=<REDACTED>&sr=<REDACTED> HTTP/1.1" 200 10095071 2024-11-27 05:35:12,111 - DEBUG - https://<REDACTED>.blob.core.windows.net:443 "GET /jobs/7551410669527543/sql/2024-11-27/03/results_2024-11-27T03:50:14Z_44fba0fb-35df-483e-8414-e336493e9da7?sig=<REDACTED>&se=<REDACTED>&sv=<REDACTED>&spr=<REDACTED>&sp=<REDACTED>&sr=<REDACTED> HTTP/1.1" 200 10099743 2024-11-27 05:35:12,145 - DEBUG - https://<REDACTED>.blob.core.windows.net:443 "GET /jobs/7551410669527543/sql/2024-11-27/03/results_2024-11-27T03:50:13Z_2dd105bf-c426-4035-86bc-a54868d98f71?sig=<REDACTED>&se=<REDACTED>&sv=<REDACTED>&spr=<REDACTED>&sp=<REDACTED>&sr=<REDACTED> HTTP/1.1" 200 10099510 2024-11-27 05:35:13,448 - DEBUG - ResultSetDownloadHandler: successfully downloaded file, offset 0, row count 110592 2024-11-27 05:35:13,466 - DEBUG - CloudFetchQueue: Found downloaded file, row count: 110592, new start offset: 110592 2024-11-27 05:35:13,468 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 110592 2024-11-27 05:35:13,468 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:13,637 - DEBUG - ResultSetDownloadHandler: successfully downloaded file, offset 110592, row count 77136 2024-11-27 05:35:13,639 - DEBUG - CloudFetchQueue: Found downloaded file, row count: 77136, new start offset: 187728 2024-11-27 05:35:13,641 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 187728 2024-11-27 05:35:13,642 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:13,761 - DEBUG - ResultSetDownloadHandler: successfully downloaded file, offset 408912, row count 110592 2024-11-27 05:35:13,947 - DEBUG - ResultSetDownloadHandler: successfully downloaded file, offset 298320, row count 110592 2024-11-27 05:35:14,369 - DEBUG - ResultSetDownloadHandler: successfully downloaded file, offset 187728, row count 110592 2024-11-27 05:35:14,371 - DEBUG - CloudFetchQueue: Found downloaded file, row count: 110592, new start offset: 298320 2024-11-27 05:35:14,372 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 298320 2024-11-27 05:35:14,372 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:14,373 - DEBUG - CloudFetchQueue: Found downloaded file, row count: 110592, new start offset: 408912 2024-11-27 05:35:14,373 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 408912 2024-11-27 05:35:14,373 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:14,374 - DEBUG - CloudFetchQueue: Found downloaded file, row count: 110592, new start offset: 519504 2024-11-27 05:35:14,374 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 519504 2024-11-27 05:35:14,374 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:14,374 - DEBUG - CloudFetchQueue: Cannot find downloaded file for row 519504 2024-11-27 05:35:14,375 - DEBUG - Sending request: FetchResults(<REDACTED>) 2024-11-27 05:35:14,488 - DEBUG - https://<REDACTED>.azuredatabricks.net:443 "POST /sql/1.0/warehouses/<REDACTED> HTTP/1.1" 200 None 2024-11-27 05:35:14,494 - DEBUG - Received response: TFetchResultsResp(<REDACTED>) 2024-11-27 05:35:14,494 - DEBUG - Initialize CloudFetch loader, row set start offset: 519504, file list: 2024-11-27 05:35:14,494 - DEBUG - - start row offset: 519504, row count: 38765 2024-11-27 05:35:14,494 - DEBUG - - start row offset: 558269, row count: 82979 2024-11-27 05:35:14,494 - DEBUG - - start row offset: 641248, row count: 110592 2024-11-27 05:35:14,494 - DEBUG - - start row offset: 751840, row count: 94279 2024-11-27 05:35:14,494 - DEBUG - - start row offset: 846119, row count: 110592 2024-11-27 05:35:14,494 - DEBUG - - start row offset: 956711, row count: 11559 2024-11-27 05:35:14,495 - DEBUG - ResultFileDownloadManager: adding file link, start offset 519504, row count: 38765 2024-11-27 05:35:14,495 - DEBUG - ResultFileDownloadManager: adding file link, start offset 558269, row count: 82979 2024-11-27 05:35:14,495 - DEBUG - ResultFileDownloadManager: adding file link, start offset 641248, row count: 110592 2024-11-27 05:35:14,495 - DEBUG - ResultFileDownloadManager: adding file link, start offset 751840, row count: 94279 2024-11-27 05:35:14,495 - DEBUG - ResultFileDownloadManager: adding file link, start offset 846119, row count: 110592 2024-11-27 05:35:14,495 - DEBUG - ResultFileDownloadManager: adding file link, start offset 956711, row count: 11559 2024-11-27 05:35:14,495 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 519504 2024-11-27 05:35:14,495 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:14,495 - DEBUG - - start: 519504, row count: 38765 2024-11-27 05:35:14,495 - DEBUG - ResultSetDownloadHandler: starting file download, offset 519504, row count 38765 2024-11-27 05:35:14,495 - DEBUG - - start: 558269, row count: 82979 2024-11-27 05:35:14,496 - DEBUG - ResultSetDownloadHandler: starting file download, offset 558269, row count 82979 2024-11-27 05:35:14,497 - DEBUG - - start: 641248, row count: 110592 2024-11-27 05:35:14,498 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.blob.core.windows.net:443 2024-11-27 05:35:14,498 - DEBUG - ResultSetDownloadHandler: starting file download, offset 641248, row count 110592 2024-11-27 05:35:14,499 - DEBUG - - start: 751840, row count: 94279 2024-11-27 05:35:14,499 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.blob.core.windows.net:443 2024-11-27 05:35:14,500 - DEBUG - ResultSetDownloadHandler: starting file download, offset 751840, row count 94279 2024-11-27 05:35:14,501 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.blob.core.windows.net:443 2024-11-27 05:35:14,501 - DEBUG - - start: 846119, row count: 110592 2024-11-27 05:35:14,503 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.blob.core.windows.net:443 2024-11-27 05:35:14,503 - DEBUG - ResultSetDownloadHandler: starting file download, offset 846119, row count 110592 2024-11-27 05:35:14,503 - DEBUG - - start: 956711, row count: 11559 2024-11-27 05:35:14,505 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.blob.core.windows.net:443 2024-11-27 05:35:14,505 - DEBUG - ResultSetDownloadHandler: starting file download, offset 956711, row count 11559 2024-11-27 05:35:14,506 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.blob.core.windows.net:443 2024-11-27 05:35:14,748 - DEBUG - https://<REDACTED>.blob.core.windows.net:443 "GET /jobs/7551410669527543/sql/2024-11-27/03/results_2024-11-27T03:50:13Z_6fabdb84-db50-4d88-8248-21725025b495?sig=<REDACTED>&se=<REDACTED>&sv=<REDACTED>&spr=<REDACTED>&sp=<REDACTED>&sr=<REDACTED> HTTP/1.1" 200 10282750 2024-11-27 05:35:14,764 - DEBUG - https://<REDACTED>.blob.core.windows.net:443 "GET /jobs/7551410669527543/sql/2024-11-27/03/results_2024-11-27T03:50:15Z_a588537d-fb44-41de-be68-acd73b0652f2?sig=<REDACTED>&se=<REDACTED>&sv=<REDACTED>&spr=<REDACTED>&sp=<REDACTED>&sr=<REDACTED> HTTP/1.1" 200 3542569 2024-11-27 05:35:14,772 - DEBUG - https://<REDACTED>.blob.core.windows.net:443 "GET /jobs/7551410669527543/sql/2024-11-27/03/results_2024-11-27T03:50:13Z_5f83ceaa-3c17-49f6-b733-e6f981c144ca?sig=<REDACTED>&se=<REDACTED>&sv=<REDACTED>&spr=<REDACTED>&sp=<REDACTED>&sr=<REDACTED> HTTP/1.1" 200 10127499 2024-11-27 05:35:14,803 - DEBUG - https://<REDACTED>.blob.core.windows.net:443 "GET /jobs/7551410669527543/sql/2024-11-27/03/results_2024-11-27T03:50:13Z_13175d31-f5f7-4bd4-87c0-5b062af131e2?sig=<REDACTED>&se=<REDACTED>&sv=<REDACTED>&spr=<REDACTED>&sp=<REDACTED>&sr=<REDACTED> HTTP/1.1" 200 8770934 2024-11-27 05:35:14,804 - DEBUG - https://<REDACTED>.blob.core.windows.net:443 "GET /jobs/7551410669527543/sql/2024-11-27/03/results_2024-11-27T03:50:13Z_3b3a5a31-5acf-431e-a447-9439379dfc9c?sig=<REDACTED>&se=<REDACTED>&sv=<REDACTED>&spr=<REDACTED>&sp=<REDACTED>&sr=<REDACTED> HTTP/1.1" 200 1059435 2024-11-27 05:35:14,812 - DEBUG - https://<REDACTED>.blob.core.windows.net:443 "GET /jobs/7551410669527543/sql/2024-11-27/03/results_2024-11-27T03:50:13Z_e01076e7-9e64-4bf2-803e-78166cd91d8e?sig=<REDACTED>&se=<REDACTED>&sv=<REDACTED>&spr=<REDACTED>&sp=<REDACTED>&sr=<REDACTED> HTTP/1.1" 200 7583682 2024-11-27 05:35:15,488 - DEBUG - ResultSetDownloadHandler: successfully downloaded file, offset 519504, row count 38765 2024-11-27 05:35:15,490 - DEBUG - CloudFetchQueue: Found downloaded file, row count: 38765, new start offset: 558269 2024-11-27 05:35:15,490 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 558269 2024-11-27 05:35:15,491 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:15,505 - DEBUG - ResultSetDownloadHandler: successfully downloaded file, offset 956711, row count 11559 2024-11-27 05:35:16,221 - DEBUG - ResultSetDownloadHandler: successfully downloaded file, offset 641248, row count 110592 2024-11-27 05:35:16,260 - DEBUG - ResultSetDownloadHandler: successfully downloaded file, offset 846119, row count 110592 2024-11-27 05:35:16,406 - DEBUG - ResultSetDownloadHandler: successfully downloaded file, offset 558269, row count 82979 2024-11-27 05:35:16,408 - DEBUG - CloudFetchQueue: Found downloaded file, row count: 82979, new start offset: 641248 2024-11-27 05:35:16,408 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 641248 2024-11-27 05:35:16,409 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:16,409 - DEBUG - CloudFetchQueue: Found downloaded file, row count: 110592, new start offset: 751840 2024-11-27 05:35:16,410 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 751840 2024-11-27 05:35:16,410 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:16,711 - DEBUG - ResultSetDownloadHandler: successfully downloaded file, offset 751840, row count 94279 2024-11-27 05:35:16,712 - DEBUG - CloudFetchQueue: Found downloaded file, row count: 94279, new start offset: 846119 2024-11-27 05:35:16,713 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 846119 2024-11-27 05:35:16,713 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:16,713 - DEBUG - CloudFetchQueue: Found downloaded file, row count: 110592, new start offset: 956711 2024-11-27 05:35:16,714 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 956711 2024-11-27 05:35:16,714 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:16,714 - DEBUG - CloudFetchQueue: Found downloaded file, row count: 11559, new start offset: 968270 2024-11-27 05:35:16,714 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 968270 2024-11-27 05:35:16,715 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:16,715 - DEBUG - CloudFetchQueue: Cannot find downloaded file for row 968270 2024-11-27 05:35:16,715 - DEBUG - Sending request: FetchResults(<REDACTED>) 2024-11-27 05:35:16,804 - DEBUG - https://<REDACTED>.azuredatabricks.net:443 "POST /sql/1.0/warehouses/<REDACTED> HTTP/1.1" 200 None 2024-11-27 05:35:16,810 - DEBUG - Received response: TFetchResultsResp(<REDACTED>) 2024-11-27 05:35:16,810 - DEBUG - Initialize CloudFetch loader, row set start offset: 968270, file list: 2024-11-27 05:35:16,810 - DEBUG - - start row offset: 968270, row count: 109947 2024-11-27 05:35:16,810 - DEBUG - - start row offset: 1078217, row count: 134690 2024-11-27 05:35:16,810 - DEBUG - - start row offset: 1212907, row count: 134543 2024-11-27 05:35:16,811 - DEBUG - - start row offset: 1347450, row count: 138304 2024-11-27 05:35:16,811 - DEBUG - ResultFileDownloadManager: adding file link, start offset 968270, row count: 109947 2024-11-27 05:35:16,811 - DEBUG - ResultFileDownloadManager: adding file link, start offset 1078217, row count: 134690 2024-11-27 05:35:16,811 - DEBUG - ResultFileDownloadManager: adding file link, start offset 1212907, row count: 134543 2024-11-27 05:35:16,811 - DEBUG - ResultFileDownloadManager: adding file link, start offset 1347450, row count: 138304 2024-11-27 05:35:16,811 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 968270 2024-11-27 05:35:16,811 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:16,811 - DEBUG - - start: 968270, row count: 109947 2024-11-27 05:35:16,811 - DEBUG - ResultSetDownloadHandler: starting file download, offset 968270, row count 109947 2024-11-27 05:35:16,811 - DEBUG - - start: 1078217, row count: 134690 2024-11-27 05:35:16,812 - DEBUG - ResultSetDownloadHandler: starting file download, offset 1078217, row count 134690 2024-11-27 05:35:16,813 - DEBUG - - start: 1212907, row count: 134543 2024-11-27 05:35:16,813 - DEBUG - ResultSetDownloadHandler: starting file download, offset 1212907, row count 134543 2024-11-27 05:35:16,814 - DEBUG - - start: 1347450, row count: 138304 2024-11-27 05:35:16,815 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.blob.core.windows.net:443 2024-11-27 05:35:16,816 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.blob.core.windows.net:443 2024-11-27 05:35:16,816 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.blob.core.windows.net:443 2024-11-27 05:35:16,816 - DEBUG - ResultSetDownloadHandler: starting file download, offset 1347450, row count 138304 2024-11-27 05:35:16,818 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.blob.core.windows.net:443 2024-11-27 05:35:17,071 - DEBUG - https://<REDACTED>.blob.core.windows.net:443 "GET /jobs/7551410669527543/sql/2024-11-27/03/results_2024-11-27T03:50:16Z_40b06242-8d61-4cab-9790-414f3c11ed3b?sig=<REDACTED>&se=<REDACTED>&sv=<REDACTED>&spr=<REDACTED>&sp=<REDACTED>&sr=<REDACTED> HTTP/1.1" 200 11756633 2024-11-27 05:35:17,087 - DEBUG - https://<REDACTED>.blob.core.windows.net:443 "GET /jobs/7551410669527543/sql/2024-11-27/03/results_2024-11-27T03:50:13Z_2132da5e-ee5f-4d5a-88ea-fd15a3e854a9?sig=<REDACTED>&se=<REDACTED>&sv=<REDACTED>&spr=<REDACTED>&sp=<REDACTED>&sr=<REDACTED> HTTP/1.1" 200 9550729 2024-11-27 05:35:17,128 - DEBUG - https://<REDACTED>.blob.core.windows.net:443 "GET /jobs/7551410669527543/sql/2024-11-27/03/results_2024-11-27T03:50:15Z_7a2381de-e34c-4fd4-8382-348ffc717c75?sig=<REDACTED>&se=<REDACTED>&sv=<REDACTED>&spr=<REDACTED>&sp=<REDACTED>&sr=<REDACTED> HTTP/1.1" 200 11444939 2024-11-27 05:35:17,136 - DEBUG - https://<REDACTED>.blob.core.windows.net:443 "GET /jobs/7551410669527543/sql/2024-11-27/03/results_2024-11-27T03:50:15Z_7dc02dd4-48c9-4f16-91ad-324a403e075d?sig=<REDACTED>&se=<REDACTED>&sv=<REDACTED>&spr=<REDACTED>&sp=<REDACTED>&sr=<REDACTED> HTTP/1.1" 200 11476774 2024-11-27 05:35:18,126 - DEBUG - ResultSetDownloadHandler: successfully downloaded file, offset 968270, row count 109947 2024-11-27 05:35:18,129 - DEBUG - CloudFetchQueue: Found downloaded file, row count: 109947, new start offset: 1078217 2024-11-27 05:35:18,129 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 1078217 2024-11-27 05:35:18,129 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:18,589 - DEBUG - ResultSetDownloadHandler: successfully downloaded file, offset 1347450, row count 138304 2024-11-27 05:35:18,901 - DEBUG - ResultSetDownloadHandler: successfully downloaded file, offset 1078217, row count 134690 2024-11-27 05:35:18,903 - DEBUG - CloudFetchQueue: Found downloaded file, row count: 134690, new start offset: 1212907 2024-11-27 05:35:18,904 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 1212907 2024-11-27 05:35:18,904 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:19,212 - DEBUG - ResultSetDownloadHandler: successfully downloaded file, offset 1212907, row count 134543 2024-11-27 05:35:19,214 - DEBUG - CloudFetchQueue: Found downloaded file, row count: 134543, new start offset: 1347450 2024-11-27 05:35:19,215 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 1347450 2024-11-27 05:35:19,215 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:19,215 - DEBUG - CloudFetchQueue: Found downloaded file, row count: 138304, new start offset: 1485754 2024-11-27 05:35:19,216 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 1485754 2024-11-27 05:35:19,216 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:19,216 - DEBUG - CloudFetchQueue: Cannot find downloaded file for row 1485754 2024-11-27 05:35:19,217 - DEBUG - Sending request: FetchResults(<REDACTED>) 2024-11-27 05:35:19,301 - DEBUG - https://<REDACTED>.azuredatabricks.net:443 "POST /sql/1.0/warehouses/<REDACTED> HTTP/1.1" 200 None 2024-11-27 05:35:19,306 - DEBUG - Received response: TFetchResultsResp(<REDACTED>) 2024-11-27 05:35:19,307 - DEBUG - Initialize CloudFetch loader, row set start offset: 1485754, file list: 2024-11-27 05:35:19,307 - DEBUG - - start row offset: 1485754, row count: 138263 2024-11-27 05:35:19,307 - DEBUG - - start row offset: 1624017, row count: 134729 2024-11-27 05:35:19,307 - DEBUG - - start row offset: 1758746, row count: 135124 2024-11-27 05:35:19,307 - DEBUG - - start row offset: 1893870, row count: 134731 2024-11-27 05:35:19,307 - DEBUG - - start row offset: 2028601, row count: 98040 2024-11-27 05:35:19,307 - DEBUG - ResultFileDownloadManager: adding file link, start offset 1485754, row count: 138263 2024-11-27 05:35:19,307 - DEBUG - ResultFileDownloadManager: adding file link, start offset 1624017, row count: 134729 2024-11-27 05:35:19,307 - DEBUG - ResultFileDownloadManager: adding file link, start offset 1758746, row count: 135124 2024-11-27 05:35:19,307 - DEBUG - ResultFileDownloadManager: adding file link, start offset 1893870, row count: 134731 2024-11-27 05:35:19,307 - DEBUG - ResultFileDownloadManager: adding file link, start offset 2028601, row count: 98040 2024-11-27 05:35:19,307 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 1485754 2024-11-27 05:35:19,307 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:19,307 - DEBUG - - start: 1485754, row count: 138263 2024-11-27 05:35:19,308 - DEBUG - ResultSetDownloadHandler: starting file download, offset 1485754, row count 138263 2024-11-27 05:35:19,308 - DEBUG - - start: 1624017, row count: 134729 2024-11-27 05:35:19,308 - DEBUG - ResultSetDownloadHandler: starting file download, offset 1624017, row count 134729 2024-11-27 05:35:19,310 - DEBUG - - start: 1758746, row count: 135124 2024-11-27 05:35:19,310 - DEBUG - ResultSetDownloadHandler: starting file download, offset 1758746, row count 135124 2024-11-27 05:35:19,311 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.blob.core.windows.net:443 2024-11-27 05:35:19,311 - DEBUG - - start: 1893870, row count: 134731 2024-11-27 05:35:19,313 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.blob.core.windows.net:443 2024-11-27 05:35:19,313 - DEBUG - ResultSetDownloadHandler: starting file download, offset 1893870, row count 134731 2024-11-27 05:35:19,313 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.blob.core.windows.net:443 2024-11-27 05:35:19,313 - DEBUG - - start: 2028601, row count: 98040 2024-11-27 05:35:19,315 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.blob.core.windows.net:443 2024-11-27 05:35:19,315 - DEBUG - ResultSetDownloadHandler: starting file download, offset 2028601, row count 98040 2024-11-27 05:35:19,317 - DEBUG - Starting new HTTPS connection (1): <REDACTED>.blob.core.windows.net:443 2024-11-27 05:35:19,579 - DEBUG - https://<REDACTED>.blob.core.windows.net:443 "GET /jobs/7551410669527543/sql/2024-11-27/03/results_2024-11-27T03:50:17Z_06f8cf6d-7006-46cd-a082-970abb569d38?sig=<REDACTED>&se=<REDACTED>&sv=<REDACTED>&spr=<REDACTED>&sp=<REDACTED>&sr=<REDACTED> HTTP/1.1" 200 11490369 2024-11-27 05:35:19,595 - DEBUG - https://<REDACTED>.blob.core.windows.net:443 "GET /jobs/7551410669527543/sql/2024-11-27/03/results_2024-11-27T03:50:17Z_775e8acf-3bd6-4dbe-afb7-c4756050517d?sig=<REDACTED>&se=<REDACTED>&sv=<REDACTED>&spr=<REDACTED>&sp=<REDACTED>&sr=<REDACTED> HTTP/1.1" 200 11459162 2024-11-27 05:35:19,613 - DEBUG - https://<REDACTED>.blob.core.windows.net:443 "GET /jobs/7551410669527543/sql/2024-11-27/03/results_2024-11-27T03:50:16Z_b930b2f8-4320-473e-ac95-2ad11a8526df?sig=<REDACTED>&se=<REDACTED>&sv=<REDACTED>&spr=<REDACTED>&sp=<REDACTED>&sr=<REDACTED> HTTP/1.1" 200 11760370 2024-11-27 05:35:19,614 - DEBUG - https://<REDACTED>.blob.core.windows.net:443 "GET /jobs/7551410669527543/sql/2024-11-27/03/results_2024-11-27T03:50:17Z_4f5bc771-1a98-458a-aa7e-1eabc28f2a7a?sig=<REDACTED>&se=<REDACTED>&sv=<REDACTED>&spr=<REDACTED>&sp=<REDACTED>&sr=<REDACTED> HTTP/1.1" 200 8336820 2024-11-27 05:35:19,638 - DEBUG - https://<REDACTED>.blob.core.windows.net:443 "GET /jobs/7551410669527543/sql/2024-11-27/03/results_2024-11-27T03:50:16Z_b7ab8d34-e018-44c1-9bd1-4cb272e7c589?sig=<REDACTED>&se=<REDACTED>&sv=<REDACTED>&spr=<REDACTED>&sp=<REDACTED>&sr=<REDACTED> HTTP/1.1" 200 11458675 2024-11-27 05:35:21,283 - DEBUG - ResultSetDownloadHandler: successfully downloaded file, offset 2028601, row count 98040 2024-11-27 05:35:21,499 - DEBUG - ResultSetDownloadHandler: successfully downloaded file, offset 1758746, row count 135124 2024-11-27 05:35:21,741 - DEBUG - ResultSetDownloadHandler: successfully downloaded file, offset 1893870, row count 134731 2024-11-27 05:35:21,975 - DEBUG - ResultSetDownloadHandler: successfully downloaded file, offset 1485754, row count 138263 2024-11-27 05:35:21,990 - DEBUG - CloudFetchQueue: Found downloaded file, row count: 138263, new start offset: 1624017 2024-11-27 05:35:21,992 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 1624017 2024-11-27 05:35:21,992 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:22,032 - DEBUG - ResultSetDownloadHandler: successfully downloaded file, offset 1624017, row count 134729 2024-11-27 05:35:22,034 - DEBUG - CloudFetchQueue: Found downloaded file, row count: 134729, new start offset: 1758746 2024-11-27 05:35:22,035 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 1758746 2024-11-27 05:35:22,035 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:22,036 - DEBUG - CloudFetchQueue: Found downloaded file, row count: 135124, new start offset: 1893870 2024-11-27 05:35:22,036 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 1893870 2024-11-27 05:35:22,036 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:22,037 - DEBUG - CloudFetchQueue: Found downloaded file, row count: 134731, new start offset: 2028601 2024-11-27 05:35:22,037 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 2028601 2024-11-27 05:35:22,037 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:22,038 - DEBUG - CloudFetchQueue: Found downloaded file, row count: 98040, new start offset: 2126641 2024-11-27 05:35:22,038 - DEBUG - CloudFetchQueue: Trying to get downloaded file for row 2126641 2024-11-27 05:35:22,038 - DEBUG - ResultFileDownloadManager: schedule downloads 2024-11-27 05:35:22,038 - DEBUG - CloudFetchQueue: Cannot find downloaded file for row 2126641 2024-11-27 05:35:44,867 - INFO - Query Execution Time: 31.40 seconds 2024-11-27 05:35:44,868 - INFO - Total Rows Fetched: 2126641 2024-11-27 05:35:44,868 - DEBUG - Sending request: CloseOperation(<REDACTED>) 2024-11-27 05:35:45,005 - DEBUG - https://<REDACTED>.azuredatabricks.net:443 "POST /sql/1.0/warehouses/<REDACTED> HTTP/1.1" 200 None 2024-11-27 05:35:45,006 - DEBUG - Received response: TCloseOperationResp(<REDACTED>) 2024-11-27 05:35:45,006 - INFO - Closing session 01efac78-fc58-1b8c-b7bd-06ce90e9b72f 2024-11-27 05:35:45,006 - DEBUG - Sending request: CloseSession(<REDACTED>) 2024-11-27 05:35:45,078 - DEBUG - https://<REDACTED>.azuredatabricks.net:443 "POST /sql/1.0/warehouses/<REDACTED> HTTP/1.1" 200 None 2024-11-27 05:35:45,079 - DEBUG - Received response: TCloseSessionResp(<REDACTED>) 2024-11-27 05:35:45,079 - INFO - Connection closed