-
Notifications
You must be signed in to change notification settings - Fork 496
Description
Context
- OS, version, SKU and CPU architecture used: Any
- Application's .NET Target Framework : .net 8.0 (affects any)
- Device: Any
- SDK version used: Client 1.42.3 (at least that is the nuget version number), but problem would affect other SDKS too
Description of the issue
The AmqpIotTransportLog class is logging values to the Logger EventSource incorrectly. The order of the method arguments is supposed to be (this/context, message, member), but it is supplying them the order (this/context, member, message). That happens to be payload field order, which might explain how the mistake was made?
You can see in the provided log output log from the below sample, where the first few, have the message in the message field, but then we start seeing log entries with output messages
Something similar seems to be happening in AmqpAuthenticationRefresher's RefreshLoopAsync, where it seems to accidentally be butting the message into the member field. It also looks to be trying to use a DateTime as the member name, presumably as a way to correlate various messages that belong to the same call.
This means I need to jump though hoops when trying to clean up these
Code sample exhibiting the issue
new ConsoleListener();
var auth = AuthenticationMethodFactory.CreateAuthenticationWithRegistrySymmetricKey("REDACTED", "REDACTED");
var myclient = DeviceClient.Create("REDACTED", auth);
await myclient.OpenAsync();
return;
class ConsoleListener : EventListener
{
protected override void OnEventSourceCreated(EventSource source)
{
if (source.Name == "Microsoft-Azure-Devices-Device-Client")
{
EnableEvents(source, EventLevel.LogAlways);
}
}
protected override void OnEventWritten(EventWrittenEventArgs eventData)
{
if (eventData.EventId is 4 or 5 or 6) //Info Error CriticalFailure
{
var payloadNames = eventData.PayloadNames;
string context = eventData.Payload[payloadNames.IndexOf("thisOrContextObject")] as string;
string member = eventData.Payload[payloadNames.IndexOf("memberName")] as string;
string message = eventData.Payload[payloadNames.IndexOf("message")] as string;
Console.WriteLine($"""
Name: {eventData.EventName}
Context: {context}
Member: {member}
Message: {message}
""");
}
}
}Console log of the issue
Name: Info
Context: IotHubConnectionString#30542218
Member: .ctor
Message: IAuthenticationMethod is DeviceAuthenticationWithSakRefresh: DeviceAuthenticationWithSakRefresh#48132822
Name: Info
Context: RetryDelegatingHandler#3841804
Member: EnsureOpenedAsync
Message: Opening connection
Name: Info
Context: ProtocolRoutingDelegatingHandler#52243212
Member: ProtocolRoutingDelegatingHandler.OpenAsync
Message: Trying Amqp_Tcp_Only
Name: Info
Context: AmqpConnectionHolder#958745
Member: EnsureConnectionAsync
Message: Creating new AmqpConnection
Name: Info
Context: AmqpTransportInitiator#49205706
Member: source:tp-initiator.operation:Connect.detail:boondocks-iot-staging.azure-devices.net:5671
Message: AmqpLogOperationInformational:
Name: Info
Context: TlsTransport#1936867
Member: source:tls0.operation:Execute.detail:BeginOpen
Message: AmqpLogOperationVerbose:
Name: Info
Context: TlsTransport#1936867
Member: source:tls0.operation:Execute.detail:EndOpen
Message: AmqpLogOperationVerbose:
Name: Info
Context: AmqpConnection#37779129
Member: source:out-connection0.operation:Execute.detail:BeginOpen
Message: AmqpLogOperationVerbose:
Name: Info
Context: AmqpConnection#37779129
Member: source:out-connection0.connection:out-connection0
Message: AmqpOpenConnection:
Name: Info
Context: AmqpConnection#37779129
Member: source:out-connection0.operation:S:HDR.fromState:Start.toState:HeaderSent
Message: AmqpStateTransition:
Name: Info
Context: AmqpConnection#37779129
Member: source:out-connection0.operation:S:OPEN.fromState:HeaderSent.toState:OpenPipe
Message: AmqpStateTransition:
Name: Info
Context: AmqpConnection#37779129
Member: source:out-connection0.operation:R:HDR.fromState:OpenPipe.toState:OpenSent
Message: AmqpStateTransition:
Name: Info
Context: AmqpConnection#37779129
Member: source:out-connection0.operation:R:OPEN.fromState:OpenSent.toState:Opened
Message: AmqpStateTransition:
Name: Info
Context: AmqpConnection#37779129
Member: source:out-connection0.operation:Execute.detail:EndOpen
Message: AmqpLogOperationVerbose:
Name: Info
Context: AmqpSession#60139509
Member: source:session1.operation:Execute.detail:BeginOpen
Message: AmqpLogOperationVerbose:
Name: Info
Context: AmqpSession#60139509
Member: source:session1.operation:S:BEGIN.fromState:Start.toState:OpenSent
Message: AmqpStateTransition:
Name: Info
Context: AmqpSession#60139509
Member: source:session1.operation:R:BEGIN.fromState:OpenSent.toState:Opened
Message: AmqpStateTransition:
Name: Info
Context: AmqpSession#60139509
Member: source:session1.operation:Execute.detail:EndOpen
Message: AmqpLogOperationVerbose:
Name: Info
Context: AmqpSession#52255261
Member: source:session2.operation:Execute.detail:BeginOpen
Message: AmqpLogOperationVerbose:
Name: Info
Context: AmqpSession#52255261
Member: source:session2.operation:S:BEGIN.fromState:Start.toState:OpenSent
Message: AmqpStateTransition:
Name: Info
Context: AmqpSession#52255261
Member: source:session2.operation:R:BEGIN.fromState:OpenSent.toState:Opened
Message: AmqpStateTransition:
Name: Info
Context: AmqpSession#52255261
Member: source:session2.operation:Execute.detail:EndOpen
Message: AmqpLogOperationVerbose:
Name: Info
Context: RequestResponseAmqpLink#3345428
Member: source:cbs3.operation:Execute.detail:BeginOpen
Message: AmqpLogOperationVerbose:
Name: Info
Context: SendingAmqpLink#10370984
Member: source:sender4.operation:Execute.detail:BeginOpen
Message: AmqpLogOperationVerbose:
Name: Info
Context: SendingAmqpLink#10370984
Member: source:sender4.operation:S:ATTACH.fromState:Start.toState:OpenSent
Message: AmqpStateTransition:
Name: Info
Context: ReceivingAmqpLink#38416196
Member: source:receiver5.operation:Execute.detail:BeginOpen
Message: AmqpLogOperationVerbose:
Name: Info
Context: ReceivingAmqpLink#38416196
Member: source:receiver5.operation:S:ATTACH.fromState:Start.toState:OpenSent
Message: AmqpStateTransition:
Name: Info
Context: SendingAmqpLink#10370984
Member: source:sender4.operation:R:ATTACH.fromState:OpenSent.toState:Opened
Message: AmqpStateTransition:
Name: Info
Context: SendingAmqpLink#10370984
Member: source:sender4.operation:Execute.detail:EndOpen
Message: AmqpLogOperationVerbose:
Name: Info
Context: ReceivingAmqpLink#38416196
Member: source:receiver5.operation:R:ATTACH.fromState:OpenSent.toState:Opened
Message: AmqpStateTransition:
Name: Info
Context: ReceivingAmqpLink#38416196
Member: source:receiver5.operation:Execute.detail:EndOpen
Message: AmqpLogOperationVerbose:
Name: Info
Context: RequestResponseAmqpLink#3345428
Member: source:cbs3.operation:Execute.detail:EndOpen
Message: AmqpLogOperationVerbose:
Name: Info
Context: RequestResponseAmqpLink#3345428
Member: source:out-connection0.obj:cbs3.entityName:$cbs
Message: AmqpOpenEntitySucceeded:
Name: Info
Context: ReceivingAmqpLink#38416196
Member: source:receiver5.deliveryId:0.transferCount:1
Message: AmqpReceiveMessage:
Name: Info
Context: ReceivingAmqpLink#38416196
Member: source:receiver5.deliveryId:0.settled:True.state:accepted()
Message: AmqpDispose:
Name: Info
Context: AmqpAuthenticationRefresher#43796409
Member: Microsoft.Azure.Devices.Client.Transport.AmqpIot.AmqpIotCbsTokenProvider before RefreshLoopAsync
Message: 7/25/2025 6:04:16 PM
Name: Info
Context: AmqpAuthenticationRefresher#43796409
Member: Microsoft.Azure.Devices.Client.Transport.AmqpIot.AmqpIotCbsTokenProvider waiting 00:51:00.5555647 RefreshLoopAsync.
Message: 7/25/2025 6:04:16 PM
Name: Info
Context: SendingAmqpLink#17934983
Member: source:sender6.operation:Execute.detail:BeginOpen
Message: AmqpLogOperationVerbose:
Name: Info
Context: SendingAmqpLink#17934983
Member: source:sender6.operation:S:ATTACH.fromState:Start.toState:OpenSent
Message: AmqpStateTransition:
Name: Info
Context: SendingAmqpLink#17934983
Member: source:sender6.operation:R:ATTACH.fromState:OpenSent.toState:Opened
Message: AmqpStateTransition:
Name: Info
Context: SendingAmqpLink#17934983
Member: source:sender6.operation:Execute.detail:EndOpen
Message: AmqpLogOperationVerbose: