From 839f509fef191dc8f81e8c02b8fa3b7d46a59391 Mon Sep 17 00:00:00 2001 From: Jkorf Date: Wed, 9 Mar 2022 12:59:09 +0100 Subject: [PATCH] Removed ResubscribeMaxRetries default value of 5, Updated logging and log levels --- CryptoExchange.Net/Clients/BaseClient.cs | 11 ++-- CryptoExchange.Net/Clients/BaseRestClient.cs | 19 +++--- .../Clients/BaseSocketClient.cs | 15 ++--- CryptoExchange.Net/Objects/Options.cs | 2 +- .../OrderBook/SymbolOrderBook.cs | 14 ++-- .../Sockets/CryptoExchangeWebSocketClient.cs | 2 +- .../Sockets/SocketConnection.cs | 64 ++++++++----------- 7 files changed, 55 insertions(+), 72 deletions(-) diff --git a/CryptoExchange.Net/Clients/BaseClient.cs b/CryptoExchange.Net/Clients/BaseClient.cs index 150285c..362d4a0 100644 --- a/CryptoExchange.Net/Clients/BaseClient.cs +++ b/CryptoExchange.Net/Clients/BaseClient.cs @@ -196,10 +196,10 @@ namespace CryptoExchange.Net // If we have to output the original json data or output the data into the logging we'll have to read to full response // in order to log/return the json data - if (ClientOptions.OutputOriginalData || log.Level <= LogLevel.Debug) + if (ClientOptions.OutputOriginalData || log.Level == LogLevel.Trace) { data = await reader.ReadToEndAsync().ConfigureAwait(false); - log.Write(LogLevel.Debug, $"{(requestId != null ? $"[{requestId}] ": "")}Response received{(elapsedMilliseconds != null ? $" in {elapsedMilliseconds}" : " ")}ms: {data}"); + log.Write(LogLevel.Debug, $"{(requestId != null ? $"[{requestId}] ": "")}Response received{(elapsedMilliseconds != null ? $" in {elapsedMilliseconds}" : " ")}ms{(log.Level == LogLevel.Trace ? (": " + data) : "")}"); var result = Deserialize(data, serializer, requestId); if(ClientOptions.OutputOriginalData) result.OriginalData = data; @@ -209,6 +209,7 @@ namespace CryptoExchange.Net // If we don't have to keep track of the original json data we can use the JsonTextReader to deserialize the stream directly // into the desired object, which has increased performance over first reading the string value into memory and deserializing from that using var jsonReader = new JsonTextReader(reader); + log.Write(LogLevel.Debug, $"{(requestId != null ? $"[{requestId}] ": "")}Response received{(elapsedMilliseconds != null ? $" in {elapsedMilliseconds}" : " ")}ms"); return new CallResult(serializer.Deserialize(jsonReader)!); } catch (JsonReaderException jre) @@ -222,7 +223,7 @@ namespace CryptoExchange.Net data = await ReadStreamAsync(stream).ConfigureAwait(false); } else - data = "[Data only available in Debug LogLevel]"; + data = "[Data only available in Trace LogLevel]"; } log.Write(LogLevel.Error, $"{(requestId != null ? $"[{requestId}] " : "")}Deserialize JsonReaderException: {jre.Message}, Path: {jre.Path}, LineNumber: {jre.LineNumber}, LinePosition: {jre.LinePosition}, data: {data}"); return new CallResult(new DeserializeError($"Deserialize JsonReaderException: {jre.Message}, Path: {jre.Path}, LineNumber: {jre.LineNumber}, LinePosition: {jre.LinePosition}", data)); @@ -237,7 +238,7 @@ namespace CryptoExchange.Net data = await ReadStreamAsync(stream).ConfigureAwait(false); } else - data = "[Data only available in Debug LogLevel]"; + data = "[Data only available in Trace LogLevel]"; } log.Write(LogLevel.Error, $"{(requestId != null ? $"[{requestId}] " : "")}Deserialize JsonSerializationException: {jse.Message}, data: {data}"); @@ -253,7 +254,7 @@ namespace CryptoExchange.Net data = await ReadStreamAsync(stream).ConfigureAwait(false); } else - data = "[Data only available in Debug LogLevel]"; + data = "[Data only available in Trace LogLevel]"; } var exceptionInfo = ex.ToLogString(); diff --git a/CryptoExchange.Net/Clients/BaseRestClient.cs b/CryptoExchange.Net/Clients/BaseRestClient.cs index 513ea8c..542050f 100644 --- a/CryptoExchange.Net/Clients/BaseRestClient.cs +++ b/CryptoExchange.Net/Clients/BaseRestClient.cs @@ -147,13 +147,13 @@ namespace CryptoExchange.Net } } - log.Write(LogLevel.Debug, $"[{requestId}] Creating request for " + uri); if (signed && apiClient.AuthenticationProvider == null) { log.Write(LogLevel.Warning, $"[{requestId}] Request {uri.AbsolutePath} failed because no ApiCredentials were provided"); return new WebCallResult(new NoApiCredentialsError()); } + log.Write(LogLevel.Information, $"[{requestId}] Creating request for " + uri); var paramsPosition = parameterPosition ?? ParameterPositions[method]; var request = ConstructRequest(apiClient, uri, method, parameters, signed, paramsPosition, arraySerialization ?? this.arraySerialization, requestId, additionalHeaders); @@ -161,15 +161,12 @@ namespace CryptoExchange.Net if (paramsPosition == HttpMethodParameterPosition.InBody) paramString = $" with request body '{request.Content}'"; - if (log.Level == LogLevel.Trace) - { - var headers = request.GetHeaders(); - if (headers.Any()) - paramString += " with headers " + string.Join(", ", headers.Select(h => h.Key + $"=[{string.Join(",", h.Value)}]")); - } - + var headers = request.GetHeaders(); + if (headers.Any()) + paramString += " with headers " + string.Join(", ", headers.Select(h => h.Key + $"=[{string.Join(",", h.Value)}]")); + apiClient.TotalRequestsMade++; - log.Write(LogLevel.Debug, $"[{requestId}] Sending {method}{(signed ? " signed" : "")} request to {request.Uri}{paramString ?? " "}{(ClientOptions.Proxy == null ? "" : $" via proxy {ClientOptions.Proxy.Host}")}"); + log.Write(LogLevel.Trace, $"[{requestId}] Sending {method}{(signed ? " signed" : "")} request to {request.Uri}{paramString ?? " "}{(ClientOptions.Proxy == null ? "" : $" via proxy {ClientOptions.Proxy.Host}")}"); return await GetResponseAsync(request, deserializer, cancellationToken).ConfigureAwait(false); } @@ -200,7 +197,7 @@ namespace CryptoExchange.Net var data = await reader.ReadToEndAsync().ConfigureAwait(false); responseStream.Close(); response.Close(); - log.Write(LogLevel.Debug, $"[{request.RequestId}] Response received in {sw.ElapsedMilliseconds}ms: {data}"); + log.Write(LogLevel.Debug, $"[{request.RequestId}] Response received in {sw.ElapsedMilliseconds}ms{(log.Level == LogLevel.Trace ? (": "+data): "")}"); // Validate if it is valid json. Sometimes other data will be returned, 502 error html pages for example var parseResult = ValidateJson(data); @@ -231,7 +228,7 @@ namespace CryptoExchange.Net // Http status code indicates error using var reader = new StreamReader(responseStream); var data = await reader.ReadToEndAsync().ConfigureAwait(false); - log.Write(LogLevel.Debug, $"[{request.RequestId}] Error received: {data}"); + log.Write(LogLevel.Warning, $"[{request.RequestId}] Error received in {sw.ElapsedMilliseconds}ms: {data}"); responseStream.Close(); response.Close(); var parseResult = ValidateJson(data); diff --git a/CryptoExchange.Net/Clients/BaseSocketClient.cs b/CryptoExchange.Net/Clients/BaseSocketClient.cs index 7f9b339..7031b0e 100644 --- a/CryptoExchange.Net/Clients/BaseSocketClient.cs +++ b/CryptoExchange.Net/Clients/BaseSocketClient.cs @@ -188,9 +188,6 @@ namespace CryptoExchange.Net var connectResult = await ConnectIfNeededAsync(socketConnection, authenticated).ConfigureAwait(false); if (!connectResult) return new CallResult(connectResult.Error!); - - if (needsConnecting) - log.Write(LogLevel.Debug, $"Socket {socketConnection.Socket.Id} connected to {url} {(request == null ? "": "with request " + JsonConvert.SerializeObject(request))}"); } finally { @@ -200,7 +197,7 @@ namespace CryptoExchange.Net if (socketConnection.PausedActivity) { - log.Write(LogLevel.Information, $"Socket {socketConnection.Socket.Id} has been paused, can't subscribe at this moment"); + log.Write(LogLevel.Warning, $"Socket {socketConnection.Socket.Id} has been paused, can't subscribe at this moment"); return new CallResult( new ServerError("Socket is paused")); } @@ -225,10 +222,12 @@ namespace CryptoExchange.Net { subscription.CancellationTokenRegistration = ct.Register(async () => { - log.Write(LogLevel.Debug, $"Socket {socketConnection.Socket.Id} Cancellation token set, closing subscription"); + log.Write(LogLevel.Information, $"Socket {socketConnection.Socket.Id} Cancellation token set, closing subscription"); await socketConnection.CloseAsync(subscription).ConfigureAwait(false); }, false); } + + log.Write(LogLevel.Information, $"Socket {socketConnection.Socket.Id} subscription completed"); return new CallResult(new UpdateSubscription(socketConnection, subscription)); } @@ -310,7 +309,7 @@ namespace CryptoExchange.Net if (socketConnection.PausedActivity) { - log.Write(LogLevel.Information, $"Socket {socketConnection.Socket.Id} has been paused, can't send query at this moment"); + log.Write(LogLevel.Warning, $"Socket {socketConnection.Socket.Id} has been paused, can't send query at this moment"); return new CallResult(new ServerError("Socket is paused")); } @@ -618,7 +617,7 @@ namespace CryptoExchange.Net } catch (Exception ex) { - log.Write(LogLevel.Warning, $"Socket {socket.Socket.Id} Periodic send {identifier} failed: " + ex); + log.Write(LogLevel.Warning, $"Socket {socket.Socket.Id} Periodic send {identifier} failed: " + ex.ToLogString()); } } } @@ -672,7 +671,7 @@ namespace CryptoExchange.Net /// public virtual async Task UnsubscribeAllAsync() { - log.Write(LogLevel.Debug, $"Closing all {sockets.Sum(s => s.Value.SubscriptionCount)} subscriptions"); + log.Write(LogLevel.Information, $"Closing all {sockets.Sum(s => s.Value.SubscriptionCount)} subscriptions"); await Task.Run(async () => { diff --git a/CryptoExchange.Net/Objects/Options.cs b/CryptoExchange.Net/Objects/Options.cs index 62eb62c..e9669ad 100644 --- a/CryptoExchange.Net/Objects/Options.cs +++ b/CryptoExchange.Net/Objects/Options.cs @@ -164,7 +164,7 @@ namespace CryptoExchange.Net.Objects /// /// The maximum number of times to try to resubscribe after reconnecting /// - public int? MaxResubscribeTries { get; set; } = 5; + public int? MaxResubscribeTries { get; set; } /// /// Max number of concurrent resubscription tasks per socket after reconnecting a socket diff --git a/CryptoExchange.Net/OrderBook/SymbolOrderBook.cs b/CryptoExchange.Net/OrderBook/SymbolOrderBook.cs index 4734cc3..4504b39 100644 --- a/CryptoExchange.Net/OrderBook/SymbolOrderBook.cs +++ b/CryptoExchange.Net/OrderBook/SymbolOrderBook.cs @@ -224,7 +224,7 @@ namespace CryptoExchange.Net.OrderBook public async Task> StartAsync(CancellationToken? ct = null) { if (Status != OrderBookStatus.Disconnected) - throw new InvalidOperationException($"Can't start book unless state is {OrderBookStatus.Connecting}. Was {Status}"); + throw new InvalidOperationException($"Can't start book unless state is {OrderBookStatus.Disconnected}. Current state: {Status}"); log.Write(LogLevel.Debug, $"{Id} order book {Symbol} starting"); _cts = new CancellationTokenSource(); @@ -288,7 +288,7 @@ namespace CryptoExchange.Net.OrderBook if (_subscription != null) await _subscription.CloseAsync().ConfigureAwait(false); - log.Write(LogLevel.Debug, $"{Id} order book {Symbol} stopped"); + log.Write(LogLevel.Trace, $"{Id} order book {Symbol} stopped"); } /// @@ -417,7 +417,7 @@ namespace CryptoExchange.Net.OrderBook { var pbList = processBuffer.ToList(); if (pbList.Count > 0) - log.Write(LogLevel.Debug, "Processing buffered updates"); + log.Write(LogLevel.Debug, $"Processing {pbList.Count} buffered updates"); foreach (var bufferEntry in pbList) { @@ -436,7 +436,7 @@ namespace CryptoExchange.Net.OrderBook { if (sequence <= LastSequenceNumber) { - log.Write(LogLevel.Debug, $"{Id} order book {Symbol} update skipped #{sequence}"); + log.Write(LogLevel.Debug, $"{Id} order book {Symbol} update skipped #{sequence}, currently at #{LastSequenceNumber}"); return false; } @@ -664,7 +664,7 @@ namespace CryptoExchange.Net.OrderBook FirstUpdateId = item.StartUpdateId, LastUpdateId = item.EndUpdateId, }); - log.Write(LogLevel.Debug, $"{Id} order book {Symbol} update buffered #{item.StartUpdateId}-#{item.EndUpdateId} [{item.Asks.Count()} asks, {item.Bids.Count()} bids]"); + log.Write(LogLevel.Trace, $"{Id} order book {Symbol} update buffered #{item.StartUpdateId}-#{item.EndUpdateId} [{item.Asks.Count()} asks, {item.Bids.Count()} bids]"); } else { @@ -748,7 +748,7 @@ namespace CryptoExchange.Net.OrderBook { if (lastUpdateId <= LastSequenceNumber) { - log.Write(LogLevel.Debug, $"{Id} order book {Symbol} update skipped #{firstUpdateId}-{lastUpdateId}"); + log.Write(LogLevel.Trace, $"{Id} order book {Symbol} update skipped #{firstUpdateId}-{lastUpdateId}"); return; } @@ -774,7 +774,7 @@ namespace CryptoExchange.Net.OrderBook } LastSequenceNumber = lastUpdateId; - log.Write(LogLevel.Debug, $"{Id} order book {Symbol} update processed #{firstUpdateId}-{lastUpdateId}"); + log.Write(LogLevel.Trace, $"{Id} order book {Symbol} update processed #{firstUpdateId}-{lastUpdateId}"); } } diff --git a/CryptoExchange.Net/Sockets/CryptoExchangeWebSocketClient.cs b/CryptoExchange.Net/Sockets/CryptoExchangeWebSocketClient.cs index fa66a70..2da863d 100644 --- a/CryptoExchange.Net/Sockets/CryptoExchangeWebSocketClient.cs +++ b/CryptoExchange.Net/Sockets/CryptoExchangeWebSocketClient.cs @@ -254,7 +254,7 @@ namespace CryptoExchange.Net.Sockets } } - log.Write(LogLevel.Debug, $"Socket {Id} connected"); + log.Write(LogLevel.Debug, $"Socket {Id} connected to {Url}"); return true; } diff --git a/CryptoExchange.Net/Sockets/SocketConnection.cs b/CryptoExchange.Net/Sockets/SocketConnection.cs index 0332402..18920de 100644 --- a/CryptoExchange.Net/Sockets/SocketConnection.cs +++ b/CryptoExchange.Net/Sockets/SocketConnection.cs @@ -43,11 +43,6 @@ namespace CryptoExchange.Net.Sockets /// public event Action? ActivityUnpaused; - /// - /// Connecting closed event - /// - public event Action? Closed; - /// /// Unhandled message event /// @@ -118,7 +113,7 @@ namespace CryptoExchange.Net.Sockets if (pausedActivity != value) { pausedActivity = value; - log.Write(LogLevel.Debug, $"Socket {Socket.Id} Paused activity: " + value); + log.Write(LogLevel.Information, $"Socket {Socket.Id} Paused activity: " + value); if(pausedActivity) ActivityPaused?.Invoke(); else ActivityUnpaused?.Invoke(); } @@ -341,7 +336,7 @@ namespace CryptoExchange.Net.Sockets /// The data to send public virtual void Send(string data) { - log.Write(LogLevel.Debug, $"Socket {Socket.Id} sending data: {data}"); + log.Write(LogLevel.Trace, $"Socket {Socket.Id} sending data: {data}"); Socket.Send(data); } @@ -377,7 +372,7 @@ namespace CryptoExchange.Net.Sockets Socket.Reconnecting = true; DisconnectTime = DateTime.UtcNow; - log.Write(LogLevel.Information, $"Socket {Socket.Id} Connection lost, will try to reconnect{(ReconnectTry == 0 ? "": $" after {socketClient.ClientOptions.ReconnectInterval}")}"); + log.Write(LogLevel.Warning, $"Socket {Socket.Id} Connection lost, will try to reconnect"); if (!lostTriggered) { lostTriggered = true; @@ -409,13 +404,12 @@ namespace CryptoExchange.Net.Sockets if (socketClient.ClientOptions.MaxReconnectTries != null && ReconnectTry >= socketClient.ClientOptions.MaxReconnectTries) { - log.Write(LogLevel.Debug, $"Socket {Socket.Id} failed to reconnect after {ReconnectTry} tries, closing"); + log.Write(LogLevel.Warning, $"Socket {Socket.Id} failed to reconnect after {ReconnectTry} tries, closing"); ShouldReconnect = false; if (socketClient.sockets.ContainsKey(Socket.Id)) socketClient.sockets.TryRemove(Socket.Id, out _); - Closed?.Invoke(); _ = Task.Run(() => ConnectionClosed?.Invoke()); break; } @@ -439,17 +433,16 @@ namespace CryptoExchange.Net.Sockets if (socketClient.ClientOptions.MaxResubscribeTries != null && ResubscribeTry >= socketClient.ClientOptions.MaxResubscribeTries) { - log.Write(LogLevel.Debug, $"Socket {Socket.Id} failed to resubscribe after {ResubscribeTry} tries, closing"); + log.Write(LogLevel.Warning, $"Socket {Socket.Id} failed to resubscribe after {ResubscribeTry} tries, closing. Last resubscription error: {reconnectResult.Error}"); ShouldReconnect = false; if (socketClient.sockets.ContainsKey(Socket.Id)) socketClient.sockets.TryRemove(Socket.Id, out _); - Closed?.Invoke(); _ = Task.Run(() => ConnectionClosed?.Invoke()); } else - log.Write(LogLevel.Debug, $"Socket {Socket.Id} resubscribing all subscriptions failed on reconnected socket{(socketClient.ClientOptions.MaxResubscribeTries != null ? $", try {ResubscribeTry}/{socketClient.ClientOptions.MaxResubscribeTries}" : "")}. Disconnecting and reconnecting."); + log.Write(LogLevel.Debug, $"Socket {Socket.Id} resubscribing all subscriptions failed on reconnected socket{(socketClient.ClientOptions.MaxResubscribeTries != null ? $", try {ResubscribeTry}/{socketClient.ClientOptions.MaxResubscribeTries}" : "")}. Error: {reconnectResult.Error}. Disconnecting and reconnecting."); if (Socket.IsOpen) await Socket.CloseAsync().ConfigureAwait(false); @@ -458,7 +451,7 @@ namespace CryptoExchange.Net.Sockets } else { - log.Write(LogLevel.Debug, $"Socket {Socket.Id} data connection restored."); + log.Write(LogLevel.Information, $"Socket {Socket.Id} data connection restored."); ResubscribeTry = 0; if (lostTriggered) { @@ -482,24 +475,22 @@ namespace CryptoExchange.Net.Sockets log.Write(LogLevel.Information, $"Socket {Socket.Id} closed"); if (socketClient.sockets.ContainsKey(Socket.Id)) socketClient.sockets.TryRemove(Socket.Id, out _); - - Closed?.Invoke(); } } - private async Task ProcessReconnectAsync() + private async Task> ProcessReconnectAsync() { + if (!Socket.IsOpen) + return new CallResult(new WebError("Socket not connected")); + if (Authenticated) { - if (!Socket.IsOpen) - return false; - // If we reconnected a authenticated connection we need to re-authenticate var authResult = await socketClient.AuthenticateSocketAsync(this).ConfigureAwait(false); if (!authResult) { - log.Write(LogLevel.Information, $"Socket {Socket.Id} authentication failed on reconnected socket. Disconnecting and reconnecting."); - return false; + log.Write(LogLevel.Warning, $"Socket {Socket.Id} authentication failed on reconnected socket. Disconnecting and reconnecting."); + return authResult; } log.Write(LogLevel.Debug, $"Socket {Socket.Id} authentication succeeded on reconnected socket."); @@ -513,28 +504,23 @@ namespace CryptoExchange.Net.Sockets // Foreach subscription which is subscribed by a subscription request we will need to resend that request to resubscribe for (var i = 0; i < subscriptionList.Count; i += socketClient.ClientOptions.MaxConcurrentResubscriptionsPerSocket) { - var success = true; - var taskList = new List(); - foreach (var subscription in subscriptionList.Skip(i).Take(socketClient.ClientOptions.MaxConcurrentResubscriptionsPerSocket)) - { - if (!Socket.IsOpen) - continue; + if (!Socket.IsOpen) + return new CallResult(new WebError("Socket not connected")); - var task = socketClient.SubscribeAndWaitAsync(this, subscription.Request!, subscription).ContinueWith(t => - { - if (!t.Result) - success = false; - }); - taskList.Add(task); - } + var taskList = new List>>(); + foreach (var subscription in subscriptionList.Skip(i).Take(socketClient.ClientOptions.MaxConcurrentResubscriptionsPerSocket)) + taskList.Add(socketClient.SubscribeAndWaitAsync(this, subscription.Request!, subscription)); await Task.WhenAll(taskList).ConfigureAwait(false); - if (!success || !Socket.IsOpen) - return false; - } + if (taskList.Any(t => !t.Result.Success)) + return taskList.First(t => !t.Result.Success).Result; + } + + if (!Socket.IsOpen) + return new CallResult(new WebError("Socket not connected")); log.Write(LogLevel.Debug, $"Socket {Socket.Id} all subscription successfully resubscribed on reconnected socket."); - return true; + return new CallResult(true); } internal async Task UnsubscribeAsync(SocketSubscription socketSubscription)