Bug fixes and logging improvements #619

anushprabhu · 2018-09-13T20:12:22Z

Checklist

I have read the contribution guidelines.
I added or modified the existing tests to cover the change (we do not allow our test coverage to go down).
This pull-request is submitted against the master branch.

Description of the changes

Fixing bugs and improving logging in AMQP logs.

Reference/Link to the issue solved with this PR (if any)

Setting the twin's ETag in AddDeviceWithTwinAsync

Removing configure awaits; add 5s delay in MQTT WS close

Setting CompletedSynchronously everywhere

Add logs for amqp ws tpm

AMQP - handle sync completion

Add client side tracing to the TPM over AMQP/WS scenario

anushprabhu · 2018-09-13T20:31:37Z

@CIPop is added to the review. #Closed

anushprabhu · 2018-09-13T20:32:00Z

@alextolp is added to the review. #Closed

anushprabhu · 2018-09-13T20:32:21Z

@rajeevmv is added to the review. #Closed

mounicaArroju · 2018-09-13T22:13:47Z

provisioning/transport/mqtt/src/Microsoft.Azure.Devices.Provisioning.Transport.Mqtt.csproj

@@ -9,6 +9,7 @@
    <OutputPath>.\bin\$(Configuration)</OutputPath>
    <DocumentationFile>$(OutputPath)\$(TargetFramework)\$(AssemblyName).xml</DocumentationFile>
    <RootDir>$(MSBuildProjectDirectory)\..\..\..\..</RootDir>
+    <NoWarn>CA2007</NoWarn>


remove this change

Yes please! Thank you @mounicaArroju for pointing it out. (This is why the build was probably not failing anymore with the current code.)

We cannot have ConfigureAwait with DotNetty. See other comment.

In reply to: 217796093 [](ancestors = 217796093)

See above: there is always an implicit configuration of the awaited operation. (Default is true.)
Default FXCop rules are making the ConfigureAwait usage mandatory: your semantic is identical to ConfigureAwait(true). I don't agree with that either since the control has already been returned to the dotNetty thread when the first await is encountered.

CIPop · 2018-09-14T16:04:06Z

common/src/device/transport/mqtt/ClientWebSocketChannel.cs

-            catch (Exception)
-            {
-                Abort();
+                    catch (Exception)


Never catch Exception without rethrowing. This needs to be somehow captured and marshalled to the caller.

We don't rethrow b/c of the Task.Delay. Please let us know if there's a better way to do this

In reply to: 217763304 [](ancestors = 217763304)

Same as above - I don't understand the reason but this is a bad practice in general.

CIPop · 2018-09-14T16:04:45Z

common/src/device/transport/mqtt/ClientWebSocketChannel.cs

@@ -140,7 +146,7 @@ protected override async void DoBeginRead()
                do
                {
                    byteBuffer = allocHandle.Allocate(allocator);
-                    allocHandle.LastBytesRead = await DoReadBytes(byteBuffer).ConfigureAwait(false);


This breaks the build - ConfigureAwait is mandatory on all await statements.
Why are you changing the behavior?

We were seeing hangs in mqtt runners and the recommendation from Max was that we could never use ConfigureAwait with dot netty. After removing this, we never saw hangs again. We should avoid adding ConfigureAwaits in paths that use their own thread pool

In reply to: 217763495 [](ancestors = 217763495)

could never use ConfigureAwait with dot netty.

@alextolp ConfigureAwait is mandatory by FXCop rules. Not setting it will break the build. You can either set it to true (return on this context) or false (any context).

@nayato I don't understand the reasoning of not using any thread to continue the execution. Up to the first await statement the void callback will execute on the original thread. After that, the thread returns to dotNetty. Why spend the cycles to ensure that we're returning on that random thread at a future time?

@CIPop the whole point is that it is not a random thread. DotNetty overrides current task scheduler so if you don't opt-out with ConfigureAwait continuation will be posted to executor thread. Primary benefit of doing that is to avoid synchronization on data access and random issues associated with data races when we fail to do so.

Thanks @nayato - didn't know that! (Really cool!)
In that case the right code here would be .ConfigureAwait(true).

Do we want to have explicit .ConfigureAwait(true) as it is the default?

In reply to: 218609670 [](ancestors = 218609670)

Yes, otherwise build will break due to the FXCop rule. Our code should be explicit instead of implicit. DotNetty is a special case as it has its own TaskScheduler. Most library code should always do .ConfigureAwait(false) to allow completions on the current thread and avoid a thread switch.

CIPop · 2018-09-14T17:02:13Z

common/src/device/transport/mqtt/ClientWebSocketChannel.cs


-                    using (var cancellationTokenSource = new CancellationTokenSource(TimeSpan.FromSeconds(30)))
+                Task.Run(async () =>


Never start a task that is not awaited by something. The result is not captured in this case and so the application will have no chance to get exceptions, etc.

Christian - we observed hangs in mqtt client and the recommendation from Max was to add a 5s delay before closing. Could you recommend another way where the client can close but we don't block it for 5s?

In reply to: 217779370 [](ancestors = 217779370)

I can't find a connection - this handler is a void async which means it's not awaited by the caller anyway. We may need to lock to avoid calling CloseAsync from multiple threads.
Are you by any chance calling non-static methods on ProvisioningClient from multiple threads?

@CIPop to give some context here: I don't know about 5 sec but the dispatch there is to avoid blocking executor thread. WS client tends to deadlock on simultaneous closure. Locking CloseAsync while running on executor thread will not buy us anything. That said, I don't see why we couldn't await on that task except that if CloseAsync deadlocks we would still want to make progress wherever we await it.

@alextolp, are you using .NET Framework or .NET Core when you're seeing the deadlock?

@nayato, according to MSDN Task.Run uses the default task scheduler (I read that as the current task scheduler and might be wrong). Wouldn't that if written like this, it would still run in the dotNetty executor loop?

CIPop · 2018-09-14T17:02:59Z

common/src/device/transport/mqtt/ClientWebSocketChannel.cs

-                            WebSocketCloseStatus.NormalClosure,
-                            string.Empty,
-                            cancellationTokenSource.Token).ConfigureAwait(false);
+                        using (var cancellationTokenSource = new CancellationTokenSource(TimeSpan.FromSeconds(30)))


Propagate the cancellation token passed by the public API.

The two cancellation tokens have different roles. The one passed by the public API is about the caller timeout.

This one is about timeout on ws.Close()

If caller timed out, we should not pass a cancelled token to Close() and let it happen anyway

In reply to: 217779575 [](ancestors = 217779575)

I think if the operation token expired we should not attempt to do graceful WS termination. Instead we should reset the TCP connection.

iothub/service/src/HttpRegistryManager.cs

CIPop · 2018-09-14T18:00:57Z

provisioning/transport/amqp/src/AmqpClientConnection.cs

+
+                    if (Logging.IsEnabled) Logging.Info(this, $"{nameof(AmqpClientConnection)}.{nameof(OpenAsync)}: Sent Protocol Header: {_sentHeader.ToString()} writeAsyncResult: {writeAsyncResult} completedSynchronously: {args.CompletedSynchronously}");
+
+                    if (args.CompletedSynchronously)


I believe this fixes #552. Please remove all TODO and Ignore statements from the e2e tests.
/cc @abhipsaMisra @prmathur-microsoft we need to check this for IoT Hub client as well.

provisioning/transport/amqp/src/AmqpClientConnection.cs

CIPop · 2018-09-14T18:02:04Z

provisioning/transport/amqp/src/AmqpClientConnection.cs

@@ -184,6 +193,8 @@ async Task<ClientWebSocket> CreateClientWebSocketAsync(Uri websocketUri, TimeSpa

        private void OnWriteHeaderComplete(TransportAsyncCallbackArgs args)
        {
+            if (Logging.IsEnabled) Logging.Enter(this, $"{nameof(AmqpClientConnection)}.{nameof(OnWriteHeaderComplete)}");


Enter is missing Exit. Please ensure that all Enter statements have an equivalent Exit.

CIPop · 2018-09-14T18:03:13Z

provisioning/transport/mqtt/src/Microsoft.Azure.Devices.Provisioning.Transport.Mqtt.csproj

@@ -9,6 +9,7 @@
    <OutputPath>.\bin\$(Configuration)</OutputPath>
    <DocumentationFile>$(OutputPath)\$(TargetFramework)\$(AssemblyName).xml</DocumentationFile>
    <RootDir>$(MSBuildProjectDirectory)\..\..\..\..</RootDir>
+    <NoWarn>CA2007</NoWarn>


Yes please! Thank you @mounicaArroju for pointing it out. (This is why the build was probably not failing anymore with the current code.)

CIPop · 2018-09-14T21:58:23Z

provisioning/transport/mqtt/src/ProvisioningTransportHandlerMqtt.cs

            try
            {
                if (message.Security is SecurityProviderX509)
                {
-                    security = (SecurityProviderX509)message.Security;
+                    SecurityProviderX509 x509Security = (SecurityProviderX509)message.Security;


This seems to be incorrect.

Yes, doesn't look like it's needed

In reply to: 217852616 [](ancestors = 217852616)

CIPop · 2018-09-14T21:59:15Z

Thanks @anushprabhu ! I left a few comments.
Please squash into a single commit as well.

CIPop

Thanks @alextolp.
There are still a few issues to address.

CIPop · 2018-09-18T01:22:29Z

common/src/device/transport/mqtt/ClientWebSocketChannel.cs


-                    using (var cancellationTokenSource = new CancellationTokenSource(TimeSpan.FromSeconds(30)))
+                Task.Run(async () =>


I can't find a connection - this handler is a void async which means it's not awaited by the caller anyway. We may need to lock to avoid calling CloseAsync from multiple threads.
Are you by any chance calling non-static methods on ProvisioningClient from multiple threads?

CIPop · 2018-09-18T01:23:28Z

common/src/device/transport/mqtt/ClientWebSocketChannel.cs

-                            WebSocketCloseStatus.NormalClosure,
-                            string.Empty,
-                            cancellationTokenSource.Token).ConfigureAwait(false);
+                        using (var cancellationTokenSource = new CancellationTokenSource(TimeSpan.FromSeconds(30)))


I think if the operation token expired we should not attempt to do graceful WS termination. Instead we should reset the TCP connection.

CIPop · 2018-09-18T01:23:51Z

common/src/device/transport/mqtt/ClientWebSocketChannel.cs

-            catch (Exception)
-            {
-                Abort();
+                    catch (Exception)


Same as above - I don't understand the reason but this is a bad practice in general.

CIPop · 2018-09-18T18:48:53Z

common/src/device/transport/mqtt/ClientWebSocketChannel.cs

@@ -140,7 +146,7 @@ protected override async void DoBeginRead()
                do
                {
                    byteBuffer = allocHandle.Allocate(allocator);
-                    allocHandle.LastBytesRead = await DoReadBytes(byteBuffer).ConfigureAwait(false);


could never use ConfigureAwait with dot netty.

@alextolp ConfigureAwait is mandatory by FXCop rules. Not setting it will break the build. You can either set it to true (return on this context) or false (any context).

@nayato I don't understand the reasoning of not using any thread to continue the execution. Up to the first await statement the void callback will execute on the original thread. After that, the thread returns to dotNetty. Why spend the cycles to ensure that we're returning on that random thread at a future time?

iothub/service/src/HttpRegistryManager.cs

CIPop · 2018-09-18T18:52:48Z

provisioning/transport/mqtt/src/Microsoft.Azure.Devices.Provisioning.Transport.Mqtt.csproj

@@ -9,6 +9,7 @@
    <OutputPath>.\bin\$(Configuration)</OutputPath>
    <DocumentationFile>$(OutputPath)\$(TargetFramework)\$(AssemblyName).xml</DocumentationFile>
    <RootDir>$(MSBuildProjectDirectory)\..\..\..\..</RootDir>
+    <NoWarn>CA2007</NoWarn>


See above: there is always an implicit configuration of the awaited operation. (Default is true.)
Default FXCop rules are making the ConfigureAwait usage mandatory: your semantic is identical to ConfigureAwait(true). I don't agree with that either since the control has already been returned to the dotNetty thread when the first await is encountered.

CIPop · 2018-09-18T18:57:15Z

Blocking merge: @prmathur-microsoft @tameraw @yzhong94 - we will not accept new PRs until we can enable all E2E tests.

For DPS changes: AMQP Provisioning tests hanging #552 appears to be addressed by this PR - please remove all associated [Ignore] statements (search code base for #552).
There is a new feature added for IoT Hub Service client that requires a new E2E test.

CIPop · 2018-10-05T00:01:40Z

@anushprabhu @alextolp I will cherry pick some of the fixes as well as do the ConfigureAwait into a separate PR.
Sorry about the wait - we're switching to a new engineering process which took a bit longer than expected.

CIPop · 2018-10-11T19:41:18Z

@anushprabhu @alextolp - I cherry picked some of the items from here. Please rebase and submit a new PR for the IoT enhancement (we cannot accept that w/o a test).

timjl and others added 8 commits September 12, 2018 17:12

Merge pull request Azure#90 from Azure/tilarden/setTwinEtag

8412602

Setting the twin's ETag in AddDeviceWithTwinAsync

Merge pull request Azure#86 from Azure/alextolp/removeconfigureawaits

463a428

Removing configure awaits; add 5s delay in MQTT WS close

Merge pull request Azure#66 from Azure/alextolp/setcompletedsync

d3d48e2

Setting CompletedSynchronously everywhere

Merge pull request Azure#65 from Azure/alextolp/amqpwsaddlogs

352e85c

Add logs for amqp ws tpm

Merge pull request Azure#64 from Azure/alextolp/amqpsyncfix

651e36e

AMQP - handle sync completion

Merge pull request Azure#63 from Azure/ravokkar/tpmamqpws-tracing

d32b634

Add client side tracing to the TPM over AMQP/WS scenario

Fix merge changes from other repo

816b6b8

Fix merge changes

7e58a68

mounicaArroju reviewed Sep 13, 2018

View reviewed changes

CIPop suggested changes Sep 14, 2018

View reviewed changes

CIPop suggested changes Sep 18, 2018

View reviewed changes

CIPop self-assigned this Sep 18, 2018

CIPop added the do-not-merge PR is not ready to be merged in. label Sep 18, 2018

CIPop mentioned this pull request Sep 19, 2018

Amqp link recovery fix #611

Closed

2 tasks

CIPop closed this Oct 11, 2018


		using (var cancellationTokenSource = new CancellationTokenSource(TimeSpan.FromSeconds(30)))
		Task.Run(async () =>


		if (Logging.IsEnabled) Logging.Info(this, $"{nameof(AmqpClientConnection)}.{nameof(OpenAsync)}: Sent Protocol Header: {_sentHeader.ToString()} writeAsyncResult: {writeAsyncResult} completedSynchronously: {args.CompletedSynchronously}");

		if (args.CompletedSynchronously)

Bug fixes and logging improvements #619

Bug fixes and logging improvements #619

Conversation

anushprabhu commented Sep 13, 2018 • edited Loading

Checklist

Description of the changes

Reference/Link to the issue solved with this PR (if any)

anushprabhu commented Sep 13, 2018

anushprabhu commented Sep 13, 2018

anushprabhu commented Sep 13, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

CIPop commented Sep 14, 2018

CIPop left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

CIPop commented Sep 18, 2018

CIPop commented Oct 5, 2018

CIPop commented Oct 11, 2018

anushprabhu commented Sep 13, 2018 •

edited

Loading