diff --git a/Directory.Packages.props b/Directory.Packages.props index 4ae02af2..9f7a970a 100644 --- a/Directory.Packages.props +++ b/Directory.Packages.props @@ -9,9 +9,9 @@ - - - + + + @@ -30,4 +30,4 @@ - + \ No newline at end of file diff --git a/src/Speckle.Sdk/Api/GraphQL/Client.cs b/src/Speckle.Sdk/Api/GraphQL/Client.cs index fb5066fc..6ae4b8fa 100644 --- a/src/Speckle.Sdk/Api/GraphQL/Client.cs +++ b/src/Speckle.Sdk/Api/GraphQL/Client.cs @@ -104,6 +104,16 @@ public sealed class Client : ISpeckleGraphQLClient, IDisposable public async Task ExecuteGraphQLRequest(GraphQLRequest request, CancellationToken cancellationToken = default) { using var activity = _activityFactory.Start(); + activity?.SetTag("responseType", typeof(T)); + activity?.SetTag("request.query", request.Query); + activity?.SetTag("request.operationName", request.OperationName); + activity?.SetTag("request.variables", request.Variables); + activity?.SetTag("request.extensions", request.Extensions); + activity?.SetTag("clientOptions.endPoint", GQLClient.Options.EndPoint); + activity?.SetTag("clientOptions.medaType", GQLClient.Options.MediaType); + activity?.SetTag("clientOptions.webSocketEndPoint", GQLClient.Options.WebSocketEndPoint); + activity?.SetTag("clientOptions.webSocketProtocol", GQLClient.Options.WebSocketProtocol); + try { var ret = await ExecuteWithResiliencePolicies(async () => @@ -118,10 +128,10 @@ public sealed class Client : ISpeckleGraphQLClient, IDisposable activity?.SetStatus(SdkActivityStatusCode.Ok); return ret; } - catch (Exception e) + catch (Exception ex) { activity?.SetStatus(SdkActivityStatusCode.Error); - activity?.RecordException(e); + activity?.RecordException(ex); throw; } } diff --git a/src/Speckle.Sdk/Api/Operations/Operations.Receive.cs b/src/Speckle.Sdk/Api/Operations/Operations.Receive.cs index 9c3e7536..51d11e18 100644 --- a/src/Speckle.Sdk/Api/Operations/Operations.Receive.cs +++ b/src/Speckle.Sdk/Api/Operations/Operations.Receive.cs @@ -1,6 +1,6 @@ using System.Collections.Concurrent; -using System.Diagnostics; using Microsoft.Extensions.Logging; +using Speckle.Sdk.Logging; using Speckle.Sdk.Models; using Speckle.Sdk.Serialisation; using Speckle.Sdk.Serialisation.Utilities; @@ -40,11 +40,51 @@ public partial class Operations CancellationToken cancellationToken = default ) { - // Setup Progress Reporting - var internalProgressAction = GetInternalProgressAction(onProgressAction); + using var receiveActivity = activityFactory.Start("Operations.Receive"); + if (remoteTransport != null) + { + receiveActivity?.SetTags("remoteTransportContext", remoteTransport.TransportContext); + } + receiveActivity?.SetTag("objectId", objectId); + + try + { + using IDisposable? d1 = UseDefaultTransportIfNull(localTransport, out localTransport); + receiveActivity?.SetTags("localTransportContext", localTransport.TransportContext); + + var result = await ReceiveImpl( + objectId, + remoteTransport, + localTransport, + GetInternalProgressAction(onProgressAction), + onTotalChildrenCountKnown, + cancellationToken + ) + .ConfigureAwait(false); + + receiveActivity?.SetStatus(SdkActivityStatusCode.Ok); + return result; + } + catch (Exception ex) + { + receiveActivity?.SetStatus(SdkActivityStatusCode.Error); + receiveActivity?.RecordException(ex); + throw; + } + } + + /// + private async Task ReceiveImpl( + string objectId, + ITransport? remoteTransport, + ITransport localTransport, + Action? internalProgressAction, + Action? onTotalChildrenCountKnown, + CancellationToken cancellationToken + ) + { // Setup Local Transport - using IDisposable? d1 = UseDefaultTransportIfNull(localTransport, out localTransport); localTransport.OnProgressAction = internalProgressAction; localTransport.CancellationToken = cancellationToken; @@ -65,21 +105,6 @@ public partial class Operations BlobStorageFolder = (remoteTransport as IBlobCapableTransport)?.BlobStorageFolder }; - // Setup Logging - using var receiveActivity = activityFactory.Start(); - receiveActivity?.SetTag("remoteTransportContext", remoteTransport?.TransportContext); - receiveActivity?.SetTag("localTransportContext", localTransport.TransportContext); - receiveActivity?.SetTag("objectId", objectId); - var timer = Stopwatch.StartNew(); - - // Receive Json - logger.LogDebug( - "Starting receive {objectId} from transports {localTransport} / {remoteTransport}", - objectId, - localTransport.TransportName, - remoteTransport?.TransportName - ); - // Try Local Receive string? objString = await LocalReceive(objectId, localTransport, onTotalChildrenCountKnown).ConfigureAwait(false); @@ -103,19 +128,10 @@ public partial class Operations .ConfigureAwait(false); } - using var activity = activityFactory.Start("Deserialize"); + using var serializerActivity = activityFactory.Start(); + // Proceed to deserialize the object, now safely knowing that all its children are present in the local (fast) transport. - Base res = await serializer.DeserializeAsync(objString).ConfigureAwait(false); - - timer.Stop(); - logger.LogDebug( - "Finished receiving {objectId} from {source} in {elapsed} seconds", - objectId, - remoteTransport?.TransportName, - timer.Elapsed.TotalSeconds - ); - - return res; + return await DeserializeActivity(objString, serializer).ConfigureAwait(false); } /// diff --git a/src/Speckle.Sdk/Api/Operations/Operations.Send.cs b/src/Speckle.Sdk/Api/Operations/Operations.Send.cs index 7670484e..3afe0be8 100644 --- a/src/Speckle.Sdk/Api/Operations/Operations.Send.cs +++ b/src/Speckle.Sdk/Api/Operations/Operations.Send.cs @@ -2,6 +2,7 @@ using System.Collections.Concurrent; using System.Diagnostics; using Microsoft.Extensions.Logging; using Speckle.Newtonsoft.Json.Linq; +using Speckle.Sdk.Logging; using Speckle.Sdk.Models; using Speckle.Sdk.Serialisation; using Speckle.Sdk.Transports; @@ -100,7 +101,7 @@ public partial class Operations var rootObjectId = await SerializerSend(value, serializerV2, cancellationToken).ConfigureAwait(false); sendTimer.Stop(); - activity?.SetTag("transportElapsedBreakdown", transports.ToDictionary(t => t.TransportName, t => t.Elapsed)); + activity?.SetTags("transportElapsedBreakdown", transports.ToDictionary(t => t.TransportName, t => t.Elapsed)); activity?.SetTag( "note", "the elapsed summary doesn't need to add up to the total elapsed... Threading magic..." diff --git a/src/Speckle.Sdk/Api/Operations/Operations.Serialize.cs b/src/Speckle.Sdk/Api/Operations/Operations.Serialize.cs index 1c2e3cd3..d7a53028 100644 --- a/src/Speckle.Sdk/Api/Operations/Operations.Serialize.cs +++ b/src/Speckle.Sdk/Api/Operations/Operations.Serialize.cs @@ -1,4 +1,6 @@ +using System.Diagnostics.CodeAnalysis; using Speckle.Newtonsoft.Json; +using Speckle.Sdk.Logging; using Speckle.Sdk.Models; using Speckle.Sdk.Serialisation; using Speckle.Sdk.Transports; @@ -39,6 +41,24 @@ public partial class Operations public async Task DeserializeAsync(string value, CancellationToken cancellationToken = default) { var deserializer = new SpeckleObjectDeserializer { CancellationToken = cancellationToken }; - return await deserializer.DeserializeAsync(value).ConfigureAwait(false); + return await DeserializeActivity(value, deserializer).ConfigureAwait(false); + } + + /// + private async Task DeserializeActivity([NotNull] string? objString, SpeckleObjectDeserializer deserializer) + { + using var activity = activityFactory.Start(); + try + { + Base res = await deserializer.DeserializeAsync(objString).ConfigureAwait(false); + activity?.SetStatus(SdkActivityStatusCode.Ok); + return res; + } + catch (Exception ex) + { + activity?.SetStatus(SdkActivityStatusCode.Error); + activity?.RecordException(ex); + throw; + } } } diff --git a/src/Speckle.Sdk/Logging/ISdkActivityFactory.cs b/src/Speckle.Sdk/Logging/ISdkActivityFactory.cs index 62d336f8..04db90bb 100644 --- a/src/Speckle.Sdk/Logging/ISdkActivityFactory.cs +++ b/src/Speckle.Sdk/Logging/ISdkActivityFactory.cs @@ -1,8 +1,10 @@ +using System.Runtime.CompilerServices; + namespace Speckle.Sdk.Logging; public interface ISdkActivityFactory : IDisposable { - Speckle.Sdk.Logging.ISdkActivity? Start(string? name = default, string source = ""); + ISdkActivity? Start(string? name = default, [CallerMemberName] string source = ""); } public sealed class NullActivityFactory : ISdkActivityFactory diff --git a/src/Speckle.Sdk/Logging/ISpeckleActivityExtensions.cs b/src/Speckle.Sdk/Logging/ISpeckleActivityExtensions.cs new file mode 100644 index 00000000..7b5cd862 --- /dev/null +++ b/src/Speckle.Sdk/Logging/ISpeckleActivityExtensions.cs @@ -0,0 +1,12 @@ +namespace Speckle.Sdk.Logging; + +public static class ISpeckleActivityExtensions +{ + public static void SetTags(this ISdkActivity activity, string prefix, IReadOnlyDictionary tags) + { + foreach (var tag in tags) + { + activity.SetTag(tag.Key, $"{prefix}.{tag.Value}"); + } + } +} diff --git a/src/Speckle.Sdk/Models/Extensions/BaseExtensions.cs b/src/Speckle.Sdk/Models/Extensions/BaseExtensions.cs index fd2ac7c6..af305ced 100644 --- a/src/Speckle.Sdk/Models/Extensions/BaseExtensions.cs +++ b/src/Speckle.Sdk/Models/Extensions/BaseExtensions.cs @@ -1,4 +1,5 @@ using System.Collections; +using System.Diagnostics.Contracts; using Speckle.Sdk.Models.Collections; namespace Speckle.Sdk.Models.Extensions; @@ -288,4 +289,13 @@ public static class BaseExtensions } } } + + /// + /// totalChildrenCount was a property in v2 on all Base objects, + /// it has since been removed, so is a reliable albeit hacky way to tell if a was from v2 + /// + /// + /// true if the is likley to have come from a v2 data source + [Pure] + public static bool SmellsLikeV2Data(this Base speckleObject) => speckleObject["totalChildrenCount"] is not null; } diff --git a/src/Speckle.Sdk/Serialisation/SpeckleObjectDeserializer.cs b/src/Speckle.Sdk/Serialisation/SpeckleObjectDeserializer.cs index 84b99404..e5f87f90 100644 --- a/src/Speckle.Sdk/Serialisation/SpeckleObjectDeserializer.cs +++ b/src/Speckle.Sdk/Serialisation/SpeckleObjectDeserializer.cs @@ -1,4 +1,5 @@ using System.Collections.Concurrent; +using System.Diagnostics.CodeAnalysis; using System.Numerics; using System.Reflection; using Speckle.Newtonsoft.Json; @@ -12,7 +13,7 @@ namespace Speckle.Sdk.Serialisation; public sealed class SpeckleObjectDeserializer { - private bool _isBusy; + private volatile bool _isBusy; private readonly object _callbackLock = new(); private readonly object?[] _invokeNull = [null]; @@ -45,7 +46,7 @@ public sealed class SpeckleObjectDeserializer /// was null /// cannot be deserialised to type // /// did not contain the required json objects (closures) - public async Task DeserializeAsync(string rootObjectJson) + public async Task DeserializeAsync([NotNull] string? rootObjectJson) { if (_isBusy) { @@ -56,10 +57,20 @@ public sealed class SpeckleObjectDeserializer try { + if (rootObjectJson is null) + { + throw new ArgumentNullException( + nameof(rootObjectJson), + $"Cannot deserialize {nameof(rootObjectJson)}, value was null" + ); + } + _isBusy = true; _deserializedObjects = new(StringComparer.Ordinal); _currentCount = 0; - return (Base)(await DeserializeJsonAsyncInternal(rootObjectJson).NotNull().ConfigureAwait(false)); + + var result = (Base)await DeserializeJsonAsyncInternal(rootObjectJson).NotNull().ConfigureAwait(false); + return result; } finally { @@ -70,10 +81,6 @@ public sealed class SpeckleObjectDeserializer private async Task DeserializeJsonAsyncInternal(string objectJson) { - if (objectJson is null) - { - throw new ArgumentNullException(nameof(objectJson), $"Cannot deserialize {nameof(objectJson)}, value was null"); - } // Apparently this automatically parses DateTimes in strings if it matches the format: // JObject doc1 = JObject.Parse(objectJson); @@ -90,7 +97,7 @@ public sealed class SpeckleObjectDeserializer } catch (Exception ex) when (!ex.IsFatal() && ex is not OperationCanceledException) { - throw new SpeckleDeserializeException($"Failed to deserialize", ex); + throw new SpeckleDeserializeException("Failed to deserialize", ex); } lock (_callbackLock)