Log time in case of exception

sfc-gh-knozderko · sfc-gh-knozderko · commit e5201441efc3 · 2025-05-26T10:08:54.000+02:00
diff --git a/Snowflake.Data/Core/RestRequester.cs b/Snowflake.Data/Core/RestRequester.cs
@@ -108,29 +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}");
-                        var watch = new Stopwatch();
                         watch.Start();
                         response = await _HttpClient
                             .SendAsync(message, HttpCompletionOption.ResponseHeadersRead, linkedCts.Token)
                             .ConfigureAwait(false);
                         watch.Stop();
                         if (!response.IsSuccessStatusCode)
                         {
-                            logger.Error($"Failed Response after {watch.ElapsedMilliseconds} ms: {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 after {watch.ElapsedMilliseconds} ms: {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 after {watch.ElapsedMilliseconds} ms by exception");
+                        }
                         // 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
`@@ -108,29 +108,34 @@ protected virtual async Task<HttpResponseMessage> SendAsync(HttpRequestMessage m`
`108`	`108`	`restRequestTimeout.Token))`
`109`	`109`	`{`
`110`	`110`	`HttpResponseMessage response = null;`
	`111`	`+ logger.Debug($"Executing: {sid} {message.Method} {message.RequestUri} HTTP/{message.Version}");`
	`112`	`+ var watch = new Stopwatch();`
`111`	`113`	`try`
`112`	`114`	`{`
`113`		`- logger.Debug($"Executing: {sid} {message.Method} {message.RequestUri} HTTP/{message.Version}");`
`114`		`- var watch = new Stopwatch();`
`115`	`115`	`watch.Start();`
`116`	`116`	`response = await _HttpClient`
`117`	`117`	`.SendAsync(message, HttpCompletionOption.ResponseHeadersRead, linkedCts.Token)`
`118`	`118`	`.ConfigureAwait(false);`
`119`	`119`	`watch.Stop();`
`120`	`120`	`if (!response.IsSuccessStatusCode)`
`121`	`121`	`{`
`122`		`- logger.Error($"Failed Response after {watch.ElapsedMilliseconds} ms: {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}'");`
`123`	`123`	`}`
`124`	`124`	`else`
`125`	`125`	`{`
`126`		`- logger.Debug($"Succeeded Response after {watch.ElapsedMilliseconds} ms: {sid} {message.Method} {message.RequestUri}");`
	`126`	`+ logger.Debug($"Succeeded response after {watch.ElapsedMilliseconds} ms: {sid} {message.Method} {message.RequestUri}");`
`127`	`127`	`}`
`128`	`128`	`response.EnsureSuccessStatusCode();`
`129`	`129`
`130`	`130`	`return response;`
`131`	`131`	`}`
`132`	`132`	`catch (Exception e)`
`133`	`133`	`{`
	`134`	`+ if (watch.IsRunning)`
	`135`	`+ {`
	`136`	`+ watch.Stop();`
	`137`	`+ logger.Error($"Response receiving interrupted after {watch.ElapsedMilliseconds} ms by exception");`
	`138`	`+ }`
`134`	`139`	`// Disposing of the response if not null now that we don't need it anymore`
`135`	`140`	`response?.Dispose();`
`136`	`141`	`if (restRequestTimeout.IsCancellationRequested)`