[Bug Report] SetMethodHandlerAsync: No authenticated context

[and-rewsmith]

Context

• OS, version, SKU and CPU architecture used: Arm32 Debian 10
• Application's .NET Target Framework : net6.0
• Device: Raspberry Pi 2B
• SDK version used: 1.36.4

Description of the issue

I am a software engineer working for the iotedge team. In our E2E tests we get the following exception a considerable amount. We didn't used to get this exception before upgrading to dotnet 6.

This issue is similar to #2337, as it happens in the same test framework when trying to set the method handler. I have also tried to reproduce this locally, but not been able to.

I took your advice from the previous issue and added a connection status changed callback. This can be seen in the test framework logs. It looks like the disconnection reason is Bad_Credential. I'm assuming this is caused by the auth related exception when trying to open async.

Based on the stack trace and the wording of the exception, it seems like the problem is that the SDK is trying to write into some amqp resource but cannot do so because the context is not authenticated. Does this look like a bug in the SDK?

Our E2E framework test code:

[13:34:04 INF] Running test 'PlugAndPlayDeviceClient(Amqp)'
[13:34:04 INF] [  +0.067s] Deployed edge configuration to device with modules:
    ***/microsoft/azureiotedge-agent:20220419.2-linux-arm32v7
    ***/microsoft/azureiotedge-hub:20220419.2-linux-arm32v7
[13:34:33 INF] [ +29.176s] Modules (edgeAgent, edgeHub) entered the 'running' state
[13:34:43 INF] [ +10.217s] Edge Agent confirmed deployment
[13:34:43 INF] Detected change in connection status:
Changed Status: Disconnected Reason: Communication_Error
[13:34:43 INF] [  +0.033s] Deleted leaf device 'e2e-iotedge-pi-22-220419-124208.764-028'
[13:34:43 ERR] Encountered exception during task "Created leaf device 'e2e-iotedge-pi-22-220419-124208.764-028' on hub 'testiothub114.azure-devices.net'": This operation is only allowed using a successfully authenticated context.
[13:34:43 INF] [ +39.685s] Completed test 'PlugAndPlayDeviceClient(Amqp)'
[13:34:54 INF] Detected change in connection status:
Changed Status: Disconnected Reason: Bad_Credential
[13:34:57 INF] [ +13.884s] Completed test teardown
  Failed PlugAndPlayDeviceClient(Amqp) [1 m 29 s]
  Error Message:
   System.InvalidOperationException : This operation is only allowed using a successfully authenticated context.
  Stack Trace:
     at System.Net.Security.SslStream.ThrowNotAuthenticated()
   at Microsoft.Azure.Amqp.Transport.TlsTransport.WriteAsync(TransportAsyncCallbackArgs args)
   at Microsoft.Azure.Amqp.AsyncIO.AsyncWriter.WriteCore()
--- End of stack trace from previous location ---
   at Microsoft.Azure.Amqp.AsyncResult.End[TAsyncResult](IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpObject.OpenAsyncResult.End(IAsyncResult result)
   at Microsoft.Azure.Amqp.AmqpObject.EndOpen(IAsyncResult result)
   at System.Threading.Tasks.TaskFactory`1.FromAsyncCoreLogic(IAsyncResult iar, Func`2 endFunction, Action`1 endAction, Task`1 promise, Boolean requiresSynchronization)
--- End of stack trace from previous location ---
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpIoTConnector.OpenConnectionAsync(TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpConnectionHolder.EnsureConnectionAsync(TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpConnectionHolder.OpenSessionAsync(DeviceIdentity deviceIdentity, TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.EnsureSessionIsOpenAsync(TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.AmqpIoT.AmqpUnit.OpenAsync(TimeSpan timeout)
   at Microsoft.Azure.Devices.Client.Transport.Amqp.AmqpTransportHandler.OpenAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ProtocolRoutingDelegatingHandler.OpenAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.<>c__DisplayClass27_0.<<ExecuteWithErrorHandlingAsync>b__0>d.MoveNext()
--- End of stack trace from previous location ---
   at Microsoft.Azure.Devices.Client.Transport.ErrorDelegatingHandler.ExecuteWithErrorHandlingAsync[T](Func`1 asyncOperation)
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass38_0.<<OpenInternalAsync>b__0>d.MoveNext()
--- End of stack trace from previous location ---
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnsureOpenedAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.<>c__DisplayClass23_0.<<EnableMethodsAsync>b__0>d.MoveNext()
--- End of stack trace from previous location ---
   at Microsoft.Azure.Devices.Client.Transport.RetryDelegatingHandler.EnableMethodsAsync(CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Client.InternalClient.SetMethodHandlerAsync(String methodName, MethodCallback methodHandler, Object userContext, CancellationToken cancellationToken)
   at Microsoft.Azure.Devices.Edge.Test.Common.LeafDevice.<>c__DisplayClass11_0.<<CreateLeafDeviceAsync>b__1>d.MoveNext() in /home/pi/myagent/_work/1/s/test/Microsoft.Azure.Devices.Edge.Test.Common/LeafDevice.cs:line 330
--- End of stack trace from previous location ---
   at Microsoft.Azure.Devices.Edge.Test.Common.LeafDevice.CreateLeafDeviceAsync(Device device, Func`1 clientFactory, IotHub iotHub, CancellationToken token) in /home/pi/myagent/_work/1/s/test/Microsoft.Azure.Devices.Edge.Test.Common/LeafDevice.cs:line 327
   at Microsoft.Azure.Devices.Edge.Test.Common.LeafDevice.DeleteIdentityIfFailedAsync(Device device, IotHub iotHub, CancellationToken token, Func`1 what) in /home/pi/myagent/_work/1/s/test/Microsoft.Azure.Devices.Edge.Test.Common/LeafDevice.cs:line 303
   at Microsoft.Azure.Devices.Edge.Test.Common.LeafDevice.DeleteIdentityIfFailedAsync(Device device, IotHub iotHub, CancellationToken token, Func`1 what) in /home/pi/myagent/_work/1/s/test/Microsoft.Azure.Devices.Edge.Test.Common/LeafDevice.cs:line 308
   at Microsoft.Azure.Devices.Edge.Test.Common.LeafDevice.CreateWithSasAsync(String leafDeviceId, Option`1 parentId, IotHub iotHub, ITransportSettings transport, String edgeHostname, CancellationToken token, ClientOptions options, Boolean nestedEdge) in /home/pi/myagent/_work/1/s/test/Microsoft.Azure.Devices.Edge.Test.Common/LeafDevice.cs:line 144
   at Microsoft.Azure.Devices.Edge.Test.Common.LeafDevice.<>c__DisplayClass5_0.<<CreateAsync>b__1>d.MoveNext() in /home/pi/myagent/_work/1/s/test/Microsoft.Azure.Devices.Edge.Test.Common/LeafDevice.cs:line 62
--- End of stack trace from previous location ---
   at Microsoft.Azure.Devices.Edge.Test.Common.Profiler.Run[T](Func`1 func, String message, Object[] properties) in /home/pi/myagent/_work/1/s/test/Microsoft.Azure.Devices.Edge.Test.Common/Profiler.cs:line 28
   at Microsoft.Azure.Devices.Edge.Test.PlugAndPlay.PlugAndPlayDeviceClient(Protocol protocol) in /home/pi/myagent/_work/1/s/test/Microsoft.Azure.Devices.Edge.Test/PlugAndPlay.cs:line 37
   at NUnit.Framework.Internal.TaskAwaitAdapter.GenericAdapter`1.BlockUntilCompleted()
   at NUnit.Framework.Internal.MessagePumpStrategy.NoMessagePumpStrategy.WaitForCompletion(AwaitAdapter awaitable)
   at NUnit.Framework.Internal.AsyncToSyncAdapter.Await(Func`1 invoke)
   at NUnit.Framework.Internal.Commands.TestMethodCommand.RunTestMethod(TestExecutionContext context)
   at NUnit.Framework.Internal.Commands.TestMethodCommand.Execute(TestExecutionContext context)
   at NUnit.Framework.Internal.Commands.BeforeAndAfterTestCommand.<>c__DisplayClass1_0.<Execute>b__0()
   at NUnit.Framework.Internal.Commands.BeforeAndAfterTestCommand.RunTestMethodInThreadAbortSafeZone(TestExecutionContext context, Action action)

[and-rewsmith]

@brycewang-microsoft This seems like another problem with similar circumstances as #2337. I'd really appreciate it if you could give your insight here. What is your intuition as to what is going wrong here?

[and-rewsmith]

@brycewang-microsoft FYA

[brycewang-microsoft]

Discussed with @and-rewsmith and @drwill-ms offline.

We noticed that our library Microsoft.Azure.Devices.Client has dependency on Microsoft.Azure.Amqp in out-of-date version. Currently @and-rewsmith is trying to override with the latest Amqp library and see if this will bring any changes. We will keep updates on this thread and investigate further after hearing back any news.

[and-rewsmith]

@brycewant-microsoft To update this bug with the discussion from our side channel, the LTS fix did not fix this issue and SDK logs were insufficient in getting this fixed. I am trying to collect wireshark logs now but it has not yet reproduced while tcpdump is running.

[brycewang-microsoft]

Synced up with @and-rewsmith offline for this. The nuget "Microsoft.Azure.Devices.Client" with Amqp v2.5.12 can fix this, which has been included in our LTS release.

Closing this issue and feel free to reopen it if needed.