Jedd/cxpla 84 add commit context to receive trace (#125)

* Smells like v2

* Fixed issue with cancellation of ParallelServerApi

* activity ok

* Serialize json

* settags extension method

* Isbusy fix

* Final polish

* added CallerMemberName

* removed absractions

Directory.Packages.props

@@ -9,9 +9,9 @@
     <!-- Keep at 7 for side by side -->
     <PackageVersion Include="Microsoft.Data.Sqlite" Version="7.0.7" />
     <PackageVersion Include="Microsoft.NET.Test.Sdk" Version="17.10.0" />
-    <PackageVersion Include="Microsoft.Extensions.DependencyInjection" Version="2.2.0"/>
-    <PackageVersion Include="Microsoft.Extensions.DependencyInjection.Abstractions" Version="2.2.0"/>
-    <PackageVersion Include="Microsoft.Extensions.Logging" Version="2.2.0"/>
+    <PackageVersion Include="Microsoft.Extensions.DependencyInjection" Version="2.2.0" />
+    <PackageVersion Include="Microsoft.Extensions.DependencyInjection.Abstractions" Version="2.2.0" />
+    <PackageVersion Include="Microsoft.Extensions.Logging" Version="2.2.0" />
     <PackageVersion Include="MongoDB.Driver" Version="2.19.2" />
     <PackageVersion Include="Moq" Version="4.20.70" />
     <PackageVersion Include="NUnit3TestAdapter" Version="4.5.0" />
@@ -30,4 +30,4 @@
     <GlobalPackageReference Include="GitVersion.MsBuild" Version="5.12.0" />
     <GlobalPackageReference Include="Speckle.InterfaceGenerator" Version="0.9.6" />
   </ItemGroup>
-</Project>
+</Project>

src/Speckle.Sdk/Api/GraphQL/Client.cs

@@ -104,6 +104,16 @@ public sealed class Client : ISpeckleGraphQLClient, IDisposable
   public async Task<T> ExecuteGraphQLRequest<T>(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;
     }
   }

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;
+    }
+  }
+
+  /// <inheritdoc cref="Receive(string,ITransport?,ITransport?,Action{ConcurrentBag{ProgressArgs}}?,Action{int}?,CancellationToken)"/>
+  private async Task<Base> ReceiveImpl(
+    string objectId,
+    ITransport? remoteTransport,
+    ITransport localTransport,
+    Action<ProgressArgs>? internalProgressAction,
+    Action<int>? 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);
   }
 
   /// <summary>

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..."

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<Base> 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);
+  }
+
+  /// <inheritdoc cref="SpeckleObjectDeserializer.DeserializeAsync"/>
+  private async Task<Base> 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;
+    }
   }
 }

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

src/Speckle.Sdk/Logging/ISpeckleActivityExtensions.cs

@@ -0,0 +1,12 @@
+namespace Speckle.Sdk.Logging;
+
+public static class ISpeckleActivityExtensions
+{
+  public static void SetTags<T>(this ISdkActivity activity, string prefix, IReadOnlyDictionary<string, T> tags)
+  {
+    foreach (var tag in tags)
+    {
+      activity.SetTag(tag.Key, $"{prefix}.{tag.Value}");
+    }
+  }
+}

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
       }
     }
   }
+
+  /// <summary>
+  /// <c>totalChildrenCount</c> 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 <paramref name="speckleObject"/> was from v2
+  /// </summary>
+  /// <param name="speckleObject"></param>
+  /// <returns>true if the <paramref name="speckleObject"/> is likley to have come from a v2 data source</returns>
+  [Pure]
+  public static bool SmellsLikeV2Data(this Base speckleObject) => speckleObject["totalChildrenCount"] is not null;
 }

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
   /// <exception cref="ArgumentNullException"><paramref name="rootObjectJson"/> was null</exception>
   /// <exception cref="SpeckleDeserializeException"><paramref name="rootObjectJson"/> cannot be deserialised to type <see cref="Base"/></exception>
   // /// <exception cref="TransportException"><see cref="ReadTransport"/> did not contain the required json objects (closures)</exception>
-  public async Task<Base> DeserializeAsync(string rootObjectJson)
+  public async Task<Base> 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<object?> 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)