Azure / azure-iot-sdk-java

A Java SDK for connecting devices to Microsoft Azure IoT services
https://azure.github.io/azure-iot-sdk-java/
Other
200 stars 237 forks source link

the MessageCallback was not been called #109

Closed xiaolingcong closed 7 years ago

xiaolingcong commented 7 years ago

Hi Support, We are using Android Version 4.4 for developing a Cloud connector for our business application in the mobile device.when I send messages frequently with MQTT, the MessageCallback was not been called.It seems to be that messages was sent fail.So there maybe lost some datas.

OS and version used: Android 4.4

Java runtime used: JDK "1.8.0_102"

SDK version used:iot-device-client:1.1.25 for Android

this is my logs: qq 20170626091956

prmathur-microsoft commented 7 years ago

Your comment talks about MQTT but the image you sent is on AMQP. Can you please clarify which protocol was in use when this issue was seen ?

Also could you please provide some repro steps as to what was done before this issue occurs ? What caused the drop of connection ? Would you have such information ? Were you able to connect to internet when this issue occurred?

xiaolingcong commented 7 years ago

Hi,"AMQPService" is log tag, I use MQTT procotol. I am suer the network is normal when this issue occured, when I am trying send too many messages in a few seconds, this issue will happen, I am not sure the connection is normal or not at this time.

prmathur-microsoft commented 7 years ago

We are investigating this issue on our end and we will update you soon.

prmathur-microsoft commented 7 years ago

We are trying to reproduce this issue, however we cannot see it at our end. Can you please provide us your steps to reproduce this issue ?

xiaolingcong commented 7 years ago

Hi,I think this is not the root cause,because when my application runs for a few hours,it will happen,and I checked the logs,it seems that when I called the method “sendEventAsync” of DeviceClient object,the thread has blocked,it cause this issue。

this is my code which send message: public void sendMessage(Message message,final String tag){ curClient.sendEventAsync(message, AMQPService.this, tag); GoloLog.d(TAG+",messageId:"+message.getMessageId()); }

this is my logs: Line 17472: 2017-07-15 14:32:22 687 D/Golo (13600): AMQPService,sendMessage,{"name":"device.message.gps","payload":[],"version":"1.0.0"} Line 17473: 2017-07-15 14:32:22 688 D/Golo (13600): AMQPService:IoT Hub responded to message with status OK_EMPTY:1_66b9880c-f27d-4bbc-bc2a-22081c9ce0a6 Line 17474: 2017-07-15 14:32:22 717 D/Golo (13600): AMQPService,messageId:66b9880c-f27d-4bbc-bc2a-22081c9ce0a6 Line 17479: 2017-07-15 14:32:23 788 D/Golo (13600): AMQPService,sendMessage,{"name":"message.gps","payload":[],"version":"1.0.0"} Line 17480: 2017-07-15 14:32:23 788 D/Golo (13600): AMQPService,messageId:1eefbe41-bb7c-4419-a9c4-7b6b915a65cf Line 17481: 2017-07-15 14:32:23 789 D/Golo (13600): AMQPService:IoT Hub responded to message with status OK_EMPTY:1_1eefbe41-bb7c-4419-a9c4-7b6b915a65cf Line 17484: 2017-07-15 14:32:23 907 D/Golo (13600): AMQPService,sendMessage,{"name":"device.message.data","payload":[],"version":"1.0.0"} Line 17485: 2017-07-15 14:32:23 908 D/Golo (13600): AMQPService,messageId:a05f759f-c0bd-4089-83d1-8ae9412ddc97 Line 17486: 2017-07-15 14:32:23 909 D/Golo (13600): AMQPService:IoT Hub responded to message with status OK_EMPTY:1_a05f759f-c0bd-4089-83d1-8ae9412ddc97 Line 17640: 2017-07-15 14:32:54 665 D/Golo (13600): AMQPService,sendMessage,{"name":"device.message.gps","payload":[],"version":"1.0.0"} Line 17641: 2017-07-15 14:32:54 670 D/Golo (13600): AMQPService,messageId:4dfec54e-14fe-40b7-8e38-1aa11eb3838f Line 17644: 2017-07-15 14:32:54 783 D/Golo (13600): AMQPService,sendMessage,{"name":"device.message.data","payload":[],"version":"1.0.0"} Line 17924: 2017-07-15 14:33:54 668 D/Golo (13600): AMQPService,timeout Line 17925: 2017-07-15 14:33:54 668 D/Golo (13600): AMQPService< stop the iot connection> Line 17926: 2017-07-15 14:33:54 688 D/Golo (13600): AMQPService,disconnect Line 18224: 2017-07-15 14:34:54 713 D/Golo (13600): AMQPService,start Connect IOT

you can see after the last message,there is no messageId logs, and when after one mimute,I close the connection,but it still block , even at this moment ,I can not create the new connection to IOT anymore, I have to restart my application to keep the connection。

this is the close connection code: public void disconnect(){ GoloLog.d(TAG+",disconnect"); if(curClient!=null&&isOpen()){ try { isOpen=false; curClient.closeNow(); GoloLog.d(TAG+",has disconnected"); } catch (IOException e1) { // TODO Auto-generated catch block e1.printStackTrace(); } } if(serviceCallBack!=null&&!Common.IS_DISCONNECT){ serviceCallBack.onConnect(false); } }

xiaolingcong commented 7 years ago

Hi Support: Can you have a look at this issue? It is very urgency。Thanks。 I has do many testing,when I leave the office,I keep the device online and send the messages,but when I come back to work,the connection of device is always lost ,the network is available。

xiaolingcong commented 7 years ago

Hi,Support: I write a demo and I test it on my phone ,it has happended too. I will upload the demo, can you have a look at it. thanks.(please run it for a few hours) MQTTDemo.zip

xiaolingcong commented 7 years ago

this is iot connect logs qq 20170719092752

1_20170718200653.txt

this is my logs qq 20170719093120

prmathur-microsoft commented 7 years ago

Thanks for providing code and logs. We will look at these logs and see if we can repro this issue at our end.

xiaolingcong commented 7 years ago

Ok,thank you.

xiaolingcong commented 7 years ago

Hi ,Support: The AMQP procotol can support setting the expiryTime when send the messages,can the MQTT support it too? this is the code of sending message of AMQP procotol:

qq 20170720150430

this is the code of sending message of MQTT procotol qq 20170720150514

anhashia commented 7 years ago

Hi @xiaolingcong Looking at it !

xiaolingcong commented 7 years ago

@anhashia ok,thank you。

anhashia commented 7 years ago

Hi @xiaolingcong

I looked at your log. It looks like you are hitting an issue (bug) that was recently addressed (fixed) in following commit. https://github.com/Azure/azure-iot-sdk-java/commit/84edf31e8aae9c4320bb838a579d83de82cd7399 The issue was related to SAS token not renewing on reconnect. That is why your re-connection attempts are failing even though you mostly likely have a valid internet connection. It can happen if your device has a flaky internet connection and is periodically disconnecting and reconnecting. It is basically trying with an already expired SAS token from initial session.

Unfortunately, this commit hasn't yet made to labelled release Java Device Client com.microsoft.azure.sdk.iot:iot-device-client:1.3.31

So you will have to build the device client SDK locally based on the latest available master and use that in your testing to take this fix till it makes to next labeled release 1.3.32.

Please try with the latest master which has the fix and let me know if you still see the issue.

Also can you please confirm the timestamps in your log ? Are they UTC time stamps or are they of particular time zone ?

xiaolingcong commented 7 years ago

Hi,@anhashia Thanks for your response,I will try it with the latest master,but when the 1.3.32 will be released? And the time zone of the device is GMT 8:00.

anhashia commented 7 years ago

Hi @xiaolingcong

I see that last release was on 2017-7-14. It normally follows bi-weekly cadence. Going by that, new release (1.3.32) should be available on this Friday (July 28th).

xiaolingcong commented 7 years ago

@anhashia ok,thanks a lot.

prmathur-microsoft commented 7 years ago

A maven package with the fix for this is released. Please give it a try and let us know if it does not resolve your issue. Also feel free to reopen in such case.

xiaolingcong commented 7 years ago

OK, I will try it ,when It has done,I will let you know the result.Thanks.

xiaolingcong commented 7 years ago

I has tested it for a few days.It does not happen again,It seems that the bug has been fixed.Thanks.