SNOW-2115047 Log http calls time (#1180)

sfc-gh-knozderko · web-flow · commit a03479167184 · 2025-05-26T12:22:06.000+02:00
diff --git a/Snowflake.Data/Core/RestRequester.cs b/Snowflake.Data/Core/RestRequester.cs
@@ -1,4 +1,5 @@
 using System;
+using System.Diagnostics;
 using Newtonsoft.Json;
 using System.Net.Http;
 using System.Threading;
@@ -107,27 +108,34 @@ protected virtual async Task<HttpResponseMessage> SendAsync(HttpRequestMessage m
                 restRequestTimeout.Token))
                 {
                     HttpResponseMessage response = null;
+                    logger.Debug($"Executing: {sid} {message.Method} {message.RequestUri} HTTP/{message.Version}");
+                    var watch = new Stopwatch();
                     try
                     {
-                        logger.Debug($"Executing: {sid} {message.Method} {message.RequestUri} HTTP/{message.Version}");
-
+                        watch.Start();
                         response = await _HttpClient
                             .SendAsync(message, HttpCompletionOption.ResponseHeadersRead, linkedCts.Token)
                             .ConfigureAwait(false);
+                        watch.Stop();
                         if (!response.IsSuccessStatusCode)
                         {
-                            logger.Error($"Failed Response: {sid} {message.Method} {message.RequestUri} StatusCode: {(int)response.StatusCode}, ReasonPhrase: '{response.ReasonPhrase}'");
+                            logger.Error($"Failed response after {watch.ElapsedMilliseconds} ms: {sid} {message.Method} {message.RequestUri} StatusCode: {(int)response.StatusCode}, ReasonPhrase: '{response.ReasonPhrase}'");
                         }
                         else
                         {
-                            logger.Debug($"Succeeded Response: {sid} {message.Method} {message.RequestUri}");
+                            logger.Debug($"Succeeded response after {watch.ElapsedMilliseconds} ms: {sid} {message.Method} {message.RequestUri}");
                         }
                         response.EnsureSuccessStatusCode();
 
                         return response;
                     }
                     catch (Exception e)
                     {
+                        if (watch.IsRunning)
+                        {
+                            watch.Stop();
+                            logger.Error($"Response receiving interrupted by exception after {watch.ElapsedMilliseconds} ms. {sid} {message.Method} {message.RequestUri}");
+                        }
                         // Disposing of the response if not null now that we don't need it anymore
                         response?.Dispose();
                         if (restRequestTimeout.IsCancellationRequested)

Original file line number	Diff line number	Diff line change
`@@ -1,4 +1,5 @@`
`1`	`1`	`using System;`
	`2`	`+using System.Diagnostics;`
`2`	`3`	`using Newtonsoft.Json;`
`3`	`4`	`using System.Net.Http;`
`4`	`5`	`using System.Threading;`
`@@ -107,27 +108,34 @@ protected virtual async Task<HttpResponseMessage> SendAsync(HttpRequestMessage m`
`107`	`108`	`restRequestTimeout.Token))`
`108`	`109`	`{`
`109`	`110`	`HttpResponseMessage response = null;`
	`111`	`+ logger.Debug($"Executing: {sid} {message.Method} {message.RequestUri} HTTP/{message.Version}");`
	`112`	`+ var watch = new Stopwatch();`
`110`	`113`	`try`
`111`	`114`	`{`
`112`		`- logger.Debug($"Executing: {sid} {message.Method} {message.RequestUri} HTTP/{message.Version}");`
`113`		`-`
	`115`	`+ watch.Start();`
`114`	`116`	`response = await _HttpClient`
`115`	`117`	`.SendAsync(message, HttpCompletionOption.ResponseHeadersRead, linkedCts.Token)`
`116`	`118`	`.ConfigureAwait(false);`
	`119`	`+ watch.Stop();`
`117`	`120`	`if (!response.IsSuccessStatusCode)`
`118`	`121`	`{`
`119`		`- logger.Error($"Failed Response: {sid} {message.Method} {message.RequestUri} StatusCode: {(int)response.StatusCode}, ReasonPhrase: '{response.ReasonPhrase}'");`
	`122`	`+ logger.Error($"Failed response after {watch.ElapsedMilliseconds} ms: {sid} {message.Method} {message.RequestUri} StatusCode: {(int)response.StatusCode}, ReasonPhrase: '{response.ReasonPhrase}'");`
`120`	`123`	`}`
`121`	`124`	`else`
`122`	`125`	`{`
`123`		`- logger.Debug($"Succeeded Response: {sid} {message.Method} {message.RequestUri}");`
	`126`	`+ logger.Debug($"Succeeded response after {watch.ElapsedMilliseconds} ms: {sid} {message.Method} {message.RequestUri}");`
`124`	`127`	`}`
`125`	`128`	`response.EnsureSuccessStatusCode();`
`126`	`129`
`127`	`130`	`return response;`
`128`	`131`	`}`
`129`	`132`	`catch (Exception e)`
`130`	`133`	`{`
	`134`	`+ if (watch.IsRunning)`
	`135`	`+ {`
	`136`	`+ watch.Stop();`
	`137`	`+ logger.Error($"Response receiving interrupted by exception after {watch.ElapsedMilliseconds} ms. {sid} {message.Method} {message.RequestUri}");`
	`138`	`+ }`
`131`	`139`	`// Disposing of the response if not null now that we don't need it anymore`
`132`	`140`	`response?.Dispose();`
`133`	`141`	`if (restRequestTimeout.IsCancellationRequested)`