Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Bug Report] DeviceClient.sendEventAsync fails and doesn't invoke MessageSentCallback #1734

Closed
szlisiecki opened this issue Aug 11, 2023 · 4 comments
Closed

[Bug Report] DeviceClient.sendEventAsync fails and doesn't invoke MessageSentCallback #1734

szlisiecki opened this issue Aug 11, 2023 · 4 comments
Assignees
@timtay-microsoft
Labels
bug IoTSDK

Comments

@szlisiecki
Copy link

Context

  • OS and version used: Ubuntu 20.04.4 LTS
  • Java runtime used: 11.0.15
  • SDK version used: iot-device-client 2.1.4

Description of the issue

Everything works just fine for couple of days and than just stops sending messages to IoTHub. Also messageSentCallback is not invoked.

Code sample exhibiting the issue

MultiplexingClient multiplexingClient = new MultiplexingClient(host, IotHubClientProtocol.AMQPS, null);
DeviceClient deviceClient = new DeviceClient(connString, IotHubClientProtocol.AMQPS);
multiplexingClient.registerDeviceClient(deviceClient);

deviceClient.sendEventAsync(message, messageSentCallback, null);

Console log of the issue

As you can see, during sending message, I get information that IotHub message was acknowledged.
For messages that were not sent I can not see in logs information that message was acknowledged by IoTHub.
So I suppose that I can not send messages because IoTHub doesn't want to acknowledge these messages. And the internal state of azure sdk is "some kind of hang up". The processing of message is stoped. Azure sdk doesn't even call a handler (messageSentCallback) to inform that something is wrong with the message.

Logs before crash

2023-08-08 20:13:11.041 [XXXXX-Multiplexed-bdf2bbaa-Cxn48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-IotHubSendTask] TRACE c.m.a.s.i.d.t.IotHubTransport - Dequeued a message from waiting queue to be sent ( Message details: Correlation Id [93ebb01d-8d38-47a2-9607-fc780d044578] Message Id [2310a6c1-fa99-411d-8630-f669a4bc6d25] )

2023-08-08 20:13:11.041 [XXXXX-Multiplexed-bdf2bbaa-Cxn48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-IotHubSendTask] TRACE c.m.a.s.i.d.t.IotHubTransport - Adding transport message to the inProgressPackets to wait for acknowledgement ( Message details: Correlation Id [93ebb01d-8d38-47a2-9607-fc780d044578] Message Id [2310a6c1-fa99-411d-8630-f669a4bc6d25] )

2023-08-08 20:13:11.041 [XXXXX-Multiplexed-bdf2bbaa-Cxn48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-IotHubSendTask] DEBUG c.m.a.s.i.d.t.IotHubTransport - Sending message ( Message details: Correlation Id [93ebb01d-8d38-47a2-9607-fc780d044578] Message Id [2310a6c1-fa99-411d-8630-f669a4bc6d25] )

2023-08-08 20:13:11.041 [XXXXX-Multiplexed-bdf2bbaa-Cxn48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-IotHubSendTask] TRACE c.m.a.s.i.d.t.a.AmqpsIotHubConnection - Adding message to amqp message queue to be sent later ( Message details: Correlation Id [93ebb01d-8d38-47a2-9607-fc780d044578] Message Id [2310a6c1-fa99-411d-8630-f669a4bc6d25] )

2023-08-08 20:13:11.041 [XXXXX-Multiplexed-bdf2bbaa-Cxn48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-IotHubSendTask] TRACE c.m.a.s.i.d.t.IotHubTransport - Sent message ( Message details: Correlation Id [93ebb01d-8d38-47a2-9607-fc780d044578] Message Id [2310a6c1-fa99-411d-8630-f669a4bc6d25] ) to protocol level, returned status code was OK

2023-08-08 20:13:11.047 [XXXXX-Multiplexed-bdf2bbaa-Cnx48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-ReactorRunner-ConnectionOwner] TRACE c.m.a.s.i.d.t.a.AmqpsIotHubConnection - Sending message over amqp ( Message details: Correlation Id [93ebb01d-8d38-47a2-9607-fc780d044578] Message Id [2310a6c1-fa99-411d-8630-f669a4bc6d25] )

2023-08-08 20:13:11.047 [XXXXX-Multiplexed-bdf2bbaa-Cnx48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-ReactorRunner-ConnectionOwner] TRACE c.m.a.s.i.d.t.a.AmqpsSenderLinkHandler - Converting IoT Hub message to proton message for telemetry sender link with address /devices/YYYYYYYYYYYY/messages/events and link correlation id 3c04354b-e36c-4209-ab1c-773e9c4327f8. IoT Hub message correlationId 93ebb01d-8d38-47a2-9607-fc780d044578

2023-08-08 20:13:11.047 [XXXXX-Multiplexed-bdf2bbaa-Cnx48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-ReactorRunner-ConnectionOwner] TRACE c.m.a.s.i.d.t.a.AmqpsSenderLinkHandler - Sending 1005 bytes over the amqp telemetry sender link with address /devices/YYYYYYYYYYYY/messages/events and link correlation id 
3c04354b-e36c-4209-ab1c-773e9c4327f8 with link credit 46

2023-08-08 20:13:11.047 [XXXXX-Multiplexed-bdf2bbaa-Cnx48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-ReactorRunner-ConnectionOwner] TRACE c.m.a.s.i.d.t.a.AmqpsSenderLinkHandler - Message was sent over telemetry sender link with address /devices/YYYYYYYYYYYY/messages/events and link correlation id 
3c04354b-e36c-4209-ab1c-773e9c4327f8 with delivery tag 5

2023-08-08 20:13:11.047 [XXXXX-Multiplexed-bdf2bbaa-Cnx48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-ReactorRunner-ConnectionOwner] TRACE c.m.a.s.i.d.t.a.AmqpsSenderLinkHandler - Current link credit on telemetry sender link with address /devices/YYYYYYYYYYYY/messages/events and link correlation id 
3c04354b-e36c-4209-ab1c-773e9c4327f8 is 45

2023-08-08 20:13:11.047 [XXXXX-Multiplexed-bdf2bbaa-Cnx48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-ReactorRunner-ConnectionOwner] TRACE c.m.a.s.i.d.t.a.AmqpsSenderLinkHandler - Link flow received on telemetry sender link with address /devices/YYYYYYYYYYYY/messages/events and link correlation id 
3c04354b-e36c-4209-ab1c-773e9c4327f8. Current link credit is now 45.

2023-08-08 20:13:11.153 [XXXXX-Multiplexed-bdf2bbaa-Cnx48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-ReactorRunner-ConnectionOwner] DEBUG c.m.a.s.i.d.t.IotHubTransport - **IotHub message was acknowledged**. Checking if there is record of sending this message ( Message details: Correlation Id [93ebb01d-8d38-47a2-9607-fc780d044578] Message Id [2310a6c1-fa99-411d-8630-f669a4bc6d25] )

2023-08-08 20:13:11.153 [XXXXX-Multiplexed-bdf2bbaa-Cnx48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-ReactorRunner-ConnectionOwner] TRACE c.m.a.s.i.d.t.IotHubTransport - Message was sent by this client, adding it to callbacks queue with OK ( Message details: Correlation Id [93ebb01d-8d38-47a2-9607-fc780d044578] Message Id [2310a6c1-fa99-411d-8630-f669a4bc6d25] )

2023-08-08 20:13:11.153 [XXXXX-Multiplexed-bdf2bbaa-Cxn48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-IotHubSendTask] DEBUG c.m.a.s.i.d.t.IotHubTransport - Invoking the callback function for sent message, IoT Hub responded to message ( Message details: Correlation Id [93ebb01d-8d38-47a2-9607-fc780d044578] Message Id [2310a6c1-fa99-411d-8630-f669a4bc6d25] ) with status OK

2023-08-08 20:13:11.153 [XXXXX-Multiplexed-bdf2bbaa-Cxn48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-IotHubSendTask] DEBUG c.o.l.s.l.azure.MessageSentCallback - IoT Hub responded to message created 2023-08-08T20:13:10.558Z from YYYYYYYYYYYY with status OK

logs after crash

2023-08-08 20:12:26.164 [XXXXX-Multiplexed-bdf2bbaa-Cxn48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-IotHubSendTask] TRACE c.m.a.s.i.d.t.IotHubTransport - Dequeued a message from waiting queue to be sent ( Message details: Correlation Id [3baaf87a-7768-4a93-96e6-cc0c25d12296] Message Id [74612e9e-7a18-4532-9737-01490c738a3b] )

2023-08-08 20:12:26.164 [XXXXX-Multiplexed-bdf2bbaa-Cxn48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-IotHubSendTask] TRACE c.m.a.s.i.d.t.IotHubTransport - Adding transport message to the inProgressPackets to wait for acknowledgement ( Message details: Correlation Id [3baaf87a-7768-4a93-96e6-cc0c25d12296] Message Id [74612e9e-7a18-4532-9737-01490c738a3b] )

2023-08-08 20:12:26.164 [XXXXX-Multiplexed-bdf2bbaa-Cxn48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-IotHubSendTask] DEBUG c.m.a.s.i.d.t.IotHubTransport - Sending message ( Message details: Correlation Id [3baaf87a-7768-4a93-96e6-cc0c25d12296] Message Id [74612e9e-7a18-4532-9737-01490c738a3b] )

2023-08-08 20:12:26.164 [XXXXX-Multiplexed-bdf2bbaa-Cxn48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-IotHubSendTask] TRACE c.m.a.s.i.d.t.a.AmqpsIotHubConnection - Adding message to amqp message queue to be sent later ( Message details: Correlation Id [3baaf87a-7768-4a93-96e6-cc0c25d12296] Message Id [74612e9e-7a18-4532-9737-01490c738a3b] )

2023-08-08 20:12:26.164 [XXXXX-Multiplexed-bdf2bbaa-Cxn48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-IotHubSendTask] TRACE c.m.a.s.i.d.t.IotHubTransport - Sent message ( Message details: Correlation Id [3baaf87a-7768-4a93-96e6-cc0c25d12296] Message Id [74612e9e-7a18-4532-9737-01490c738a3b] ) to protocol level, returned status code was OK

2023-08-08 20:12:26.214 [XXXXX-Multiplexed-bdf2bbaa-Cnx48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-ReactorRunner-ConnectionOwner] TRACE c.m.a.s.i.d.t.a.AmqpsIotHubConnection - Sending message over amqp ( Message details: Correlation Id [3baaf87a-7768-4a93-96e6-cc0c25d12296] Message Id [74612e9e-7a18-4532-9737-01490c738a3b] )

2023-08-08 20:12:26.215 [XXXXX-Multiplexed-bdf2bbaa-Cnx48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-ReactorRunner-ConnectionOwner] TRACE c.m.a.s.i.d.t.a.AmqpsSenderLinkHandler - Converting IoT Hub message to proton message for telemetry sender link with address /devices/YYYYYYYYYYYY/messages/events and link correlation id 52c263e6-915c-4d93-9ccc-874b2b50ae87. IoT Hub message correlationId 3baaf87a-7768-4a93-96e6-cc0c25d12296

2023-08-08 20:12:26.215 [XXXXX-Multiplexed-bdf2bbaa-Cnx48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-ReactorRunner-ConnectionOwner] TRACE c.m.a.s.i.d.t.a.AmqpsSenderLinkHandler - Sending 1005 bytes over the amqp telemetry sender link with address /devices/YYYYYYYYYYYY/messages/events and link correlation id 52c263e6-915c-4d93-9ccc-874b2b50ae87 with link credit 44

2023-08-08 20:12:26.215 [XXXXX-Multiplexed-bdf2bbaa-Cnx48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-ReactorRunner-ConnectionOwner] TRACE c.m.a.s.i.d.t.a.AmqpsSenderLinkHandler - Message was sent over telemetry sender link with address /devices/YYYYYYYYYYYY/messages/events and link correlation id 52c263e6-915c-4d93-9ccc-874b2b50ae87 with delivery tag 7

2023-08-08 20:12:26.215 [XXXXX-Multiplexed-bdf2bbaa-Cnx48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-ReactorRunner-ConnectionOwner] TRACE c.m.a.s.i.d.t.a.AmqpsSenderLinkHandler - Current link credit on telemetry sender link with address /devices/YYYYYYYYYYYY/messages/events and link correlation id 52c263e6-915c-4d93-9ccc-874b2b50ae87 is 43

2023-08-08 20:12:26.215 [XXXXX-Multiplexed-bdf2bbaa-Cnx48ab2303-4071-4407-bb9f-fa1c85c29b75-azure-iot-sdk-ReactorRunner-ConnectionOwner] TRACE c.m.a.s.i.d.t.a.AmqpsSenderLinkHandler - Link flow received on telemetry sender link with address /devices/YYYYYYYYYYYY/messages/events and link correlation id 52c263e6-915c-4d93-9ccc-874b2b50ae87. Current link credit is now 43.
@szlisiecki szlisiecki added the bug label Aug 11, 2023
@laudibert
Copy link

We are the client owning the IoT Hub that receives the messages from @szlisiecki component.

We did find any logs in IoT Hub related to this problem that happens randomly on some devices.

@timtay-microsoft timtay-microsoft mentioned this issue Oct 19, 2023
Merged
@timtay-microsoft
Copy link
Member

It looks like there is a bug in this SDK wherein a newly closed device session (within a multiplexed connection) doesn't cancel all the currently queued messages. #1753 should fix this for you. That said, you'll want to make sure that you are monitoring the state of each device's session within the multiplexed connection. The fact that you are hitting this bug suggests that your device session is closing unexpectedly.

@timtay-microsoft timtay-microsoft self-assigned this Oct 19, 2023
@timtay-microsoft
Copy link
Member

Version 2.3.1 has been released with this fix, so I'll close this thread

@timtay-microsoft
Copy link
Member

Closing this thread again as some service side fixes were deployed that helped fix this issue alongside the above-mentioned SDK-side changes

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@timtay-microsoft timtay-microsoft

Labels
bug IoTSDK
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@laudibert @timtay-microsoft @szlisiecki