[Technical Question] Sending a response for the method that was never invoked

[DBY047]

Hi,

Regularly, on devices we deployed and on our QA lab, we see episodes of TransportException. By episode, I means the IotHubTransport prints the error below for 37 seconds (from 02-08 02:46:44.072 to 02:47:21.379). There is 369 exceptions like that one in that period of time. Does someone have and explanation for this and if there is something we can do to fix this? QA and clients ask lots of questions about these exceptions. They think messages might be missed...

Encountered exception while sending message with correlation id 9ccdcde3-6055-4942-8be6-f900d142795f
com.microsoft.azure.sdk.iot.device.exceptions.TransportException: Sending a response for the method that was never invoked
	at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttDeviceMethod.throwMethodsTransportException(MqttDeviceMethod.java:200)
	at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttDeviceMethod.send(MqttDeviceMethod.java:117)
	at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttIotHubConnection.sendMessage(MqttIotHubConnection.java:362)
	at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.sendPacket(IotHubTransport.java:1448)
	at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.sendMessages(IotHubTransport.java:607)
	at com.microsoft.azure.sdk.iot.device.transport.IotHubSendTask.run(IotHubSendTask.java:53)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:422)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:279)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:152)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
	at java.lang.Thread.run(Thread.java:841)
Handling an exception from sending message: Attempt number 0
com.microsoft.azure.sdk.iot.device.exceptions.TransportException: Sending a response for the method that was never invoked
	at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttDeviceMethod.throwMethodsTransportException(MqttDeviceMethod.java:200)
	at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttDeviceMethod.send(MqttDeviceMethod.java:117)
	at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttIotHubConnection.sendMessage(MqttIotHubConnection.java:362)
	at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.sendPacket(IotHubTransport.java:1448)
	at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.sendMessages(IotHubTransport.java:607)
	at com.microsoft.azure.sdk.iot.device.transport.IotHubSendTask.run(IotHubSendTask.java:53)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:422)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:279)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:152)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
	at java.lang.Thread.run(Thread.java:841)
The device operation timeout has been exceeded for the message, so it has been abandoned ( Message details: Correlation Id [9ccdcde3-6055-4942-8be6-f900d142795f] Message Id [6baf3504-8b61-4abb-8e3a-3a0b9c4ad694] Request Id [1bc4] Device Operation Type [DEVICE_OPERATION_METHOD_SEND_RESPONSE] )
com.microsoft.azure.sdk.iot.device.exceptions.TransportException: Sending a response for the method that was never invoked
	at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttDeviceMethod.throwMethodsTransportException(MqttDeviceMethod.java:200)
	at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttDeviceMethod.send(MqttDeviceMethod.java:117)
	at com.microsoft.azure.sdk.iot.device.transport.mqtt.MqttIotHubConnection.sendMessage(MqttIotHubConnection.java:362)
	at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.sendPacket(IotHubTransport.java:1448)
	at com.microsoft.azure.sdk.iot.device.transport.IotHubTransport.sendMessages(IotHubTransport.java:607)
	at com.microsoft.azure.sdk.iot.device.transport.IotHubSendTask.run(IotHubSendTask.java:53)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:422)
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:279)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:152)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1112)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:587)
	at java.lang.Thread.run(Thread.java:841)

Thanks,

[timtay-microsoft]

What version of the SDK are you using here?

[DBY047]

SDK version 1.32.2

[timtay-microsoft]

What the error here means is that the SDK attempted to send a direct method response, but for some reason it could not correlate it to a received direct method invocation. My guess is that the state that tracks this request/response correlation was wiped by a reconnection event. What the customer would probably experience here is that the method invocations would fail on the service client side even if the method took affect on the device client side.

[timtay-microsoft]

#1468 should solve this issue so that the method response is always sent even if the SDK somehow loses track of the context about it.

[timtay-microsoft]

Device client version 1.34.2 has now been released and contains the fix for this behavior, so I'm closing this issue