Azure / Azure/azure-iot-sdk-csharp

[Bug Report] AmqpIotTransportLog logs Message as Member and vice versa

Open
#3,490 0 comments 0 reactions 0 assignees View on GitHub
bug
Dominant language
C#
Stars
477
Forks
492
Avg merge
9h 55m
Merged PRs (30d)
2

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
```c#
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
```text
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:

```

Contributor guide

Open the contributing guide

Research direction

Start by locating AmqpIotTransportLog and AmqpAuthenticationRefresher.RefreshLoopAsync, then run the provided ConsoleListener sample to inspect EventSource payload fields. Done means the logged message and memberName values match their intended fields in both logging paths, with coverage or verification for the affected output.

Written by the indexing model from the issue text.

Assessment

Tech stack
azure, csharp
Domain
networking
Issue type
Bug
Difficulty
3/5
Estimated time
1-2 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
45/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.