smaho-engineering / esptouch_flutter

ESP-Touch Dart API for Flutter. Platform-specific implementation for Android (Java) and iOS (Objective-C).
https://pub.dev/packages/esptouch_flutter
MIT License
100 stars 34 forks source link

java.lang.InterruptedException #5

Closed johnwargo closed 4 years ago

johnwargo commented 4 years ago

Thanks so much for making this package. It's just what I need for my ESP32 project. I build a test app using the connectivity package to get the device's Wi-Fi details then your sample code to configure the ESP32 device. My code to configure the device is:

print('setWifiConfig()');
if (_wifiName != null && _wifiBSSID != null && _wifiPassword != null) {
  final ESPTouchTask task = ESPTouchTask(
    ssid: _wifiName,
    bssid: _wifiBSSID,
    password: _wifiPassword,
  );
  final Stream<ESPTouchResult> stream = task.execute();
  final printResult = (ESPTouchResult result) {
    print('IP: ${result.ip} MAC: ${result.bssid}');
    setState(() {
      _remoteNotifyIPAddress = result.ip;
      _remoteNotifyMacAddress = result.bssid;
    });
  };
  StreamSubscription<ESPTouchResult> streamSubscription =
  stream.listen(printResult);
  // Don't forget to cancel your stream subscription:
  streamSubscription.cancel();
} else {
  print('Missing configuration value');
}

but when I run the app, I get the following:

D/EsptouchPlugin( 6006): Event Listener is triggered
D/EsptouchPlugin( 6006): Received stream configuration arguments: SSID: NETWORK_NAME, BBSID: 70:3a:cb:19:75:99, Password: PASSWORD, Packet: 1, Task parameter: {thresholdSucBroadcastCount=1, expectTaskResultCount=1, esptouchResultTotalLen=11, waitUdpReceivingMillisecond=15000, targetPort=7001, intervalDataCodeMillisecond=8, esptouchResultOneLen=1, esptouchResultMacLen=6, intervalGuideCodeMillisecond=8, timeoutDataCodeMillisecond=4000, waitUdpSendingMillisecond=45000, esptouchResultIpLen=4, totalRepeatTime=1, portListening=18266, timeoutGuideCodeMillisecond=2000}
D/EsptouchPlugin( 6006): Converted taskUtil parameter from map {thresholdSucBroadcastCount=1, expectTaskResultCount=1, esptouchResultTotalLen=11, waitUdpReceivingMillisecond=15000, targetPort=7001, intervalDataCodeMillisecond=8, esptouchResultOneLen=1, esptouchResultMacLen=6, intervalGuideCodeMillisecond=8, timeoutDataCodeMillisecond=4000, waitUdpSendingMillisecond=45000, esptouchResultIpLen=4, totalRepeatTime=1, portListening=18266, timeoutGuideCodeMillisecond=2000} to EsptouchTaskParameter com.espressif.iot.esptouch.task.EsptouchTaskParameter@3b00906.
D/EsptouchPlugin( 6006): Cancelling stream with configuration arguments{password=nothing is ever easy, bssid=70:3a:cb:19:75:62, taskParameter={thresholdSucBroadcastCount=1, expectTaskResultCount=1, esptouchResultTotalLen=11, waitUdpReceivingMillisecond=15000, targetPort=7001, intervalDataCodeMillisecond=8, esptouchResultOneLen=1, esptouchResultMacLen=6, intervalGuideCodeMillisecond=8, timeoutDataCodeMillisecond=4000, waitUdpSendingMillisecond=45000, esptouchResultIpLen=4, totalRepeatTime=1, portListening=18266, timeoutGuideCodeMillisecond=2000}, packet=1, ssid=Wargo}
D/EsptouchPlugin( 6006): Task existed, cancelling manually
D/EspTouchTaskUtil( 6006): cancel
D/EspTouchAsyncTask( 6006): cancelEsptouch
I/__EsptouchTask( 6006): Welcome Esptouch v0.3.7.0
D/UDPSocketServer( 6006): mServerSocket is created, socket read timeout: 60000, port: 18266
D/EspTouchAsyncTask( 6006): Expected task result count is : 1
D/__EsptouchTask( 6006): execute()
I/__EsptouchTask( 6006): localInetAddress: /192.168.86.30
D/__EsptouchTask( 6006): send gc code 
D/__EsptouchTask( 6006): __listenAsyn() start
I/__EsptouchTask( 6006): expectOneByte: 34
D/UDPSocketServer( 6006): receiveSpecLenBytes() entrance: len = 11
W/System.err( 6006): java.lang.InterruptedException
W/System.err( 6006):    at java.lang.Thread.sleep(Native Method)
W/System.err( 6006):    at java.lang.Thread.sleep(Thread.java:440)
W/System.err( 6006):    at java.lang.Thread.sleep(Thread.java:356)
W/System.err( 6006):    at com.espressif.iot.esptouch.udp.UDPSocketClient.sendData(UDPSocketClient.java:116)
W/System.err( 6006):    at com.espressif.iot.esptouch.udp.UDPSocketClient.sendData(UDPSocketClient.java:71)
W/System.err( 6006):    at com.espressif.iot.esptouch.task.__EsptouchTask.__execute(__EsptouchTask.java:253)
W/System.err( 6006):    at com.espressif.iot.esptouch.task.__EsptouchTask.executeForResults(__EsptouchTask.java:325)
W/System.err( 6006):    at com.espressif.iot.esptouch.EsptouchTask.executeForResults(EsptouchTask.java:106)
W/System.err( 6006):    at com.smaho.eng.esptouch.EspTouchTaskUtil$EspTouchAsyncTask.doInBackground(EspTouchTaskUtil.java:75)
W/System.err( 6006):    at com.smaho.eng.esptouch.EspTouchTaskUtil$EspTouchAsyncTask.doInBackground(EspTouchTaskUtil.java:33)
W/System.err( 6006):    at android.os.AsyncTask$3.call(AsyncTask.java:378)
W/System.err( 6006):    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
W/System.err( 6006):    at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:289)
W/System.err( 6006):    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167)
W/System.err( 6006):    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641)
W/System.err( 6006):    at java.lang.Thread.run(Thread.java:919)
W/UDPSocketClient( 6006): sendData is Interrupted
D/__EsptouchTask( 6006): send gc code 
D/__EsptouchTask( 6006): send gc code 
D/__EsptouchTask( 6006): send gc code 

Have you seen this before? Do you know how I can fix this?

johnwargo commented 4 years ago

@vargavince91 OK, using this as an example, I replaced the call to

streamSubscription.cancel();

to

Future.delayed(Duration(minutes: 1), () => sub.cancel());

And the ESPTouch config worked but the app crashes when it comes to canceling the subscription:

════════ Exception caught by services library ══════════════════════════════════════════════════════
The following PlatformException was thrown while de-activating platform stream on channel eng.smaho.com/esptouch_plugin/results:
PlatformException(error, No active stream to cancel, null)

When the exception was thrown, this was the stack: 
#0      StandardMethodCodec.decodeEnvelope (package:flutter/src/services/message_codecs.dart:569:7)
#1      MethodChannel._invokeMethod (package:flutter/src/services/platform_channel.dart:156:18)
<asynchronous suspension>
#2      MethodChannel.invokeMethod (package:flutter/src/services/platform_channel.dart:329:12)
#3      EventChannel.receiveBroadcastStream.<anonymous closure> (package:flutter/src/services/platform_channel.dart:531:29)
...
════════════════════════════════════════════════════════════════════════════════════════════════════
vincevargadev commented 4 years ago

Thank you @johnwargo, I'll try to reproduce, investigate, and solve your issue asap!

johnwargo commented 4 years ago

@vargavince91 any progress? Anything I can do to help?

vincevargadev commented 4 years ago

@johnwargo Here is the code that prints your original exception.

https://github.com/smaho-engineering/esptouch_flutter/blob/fb00ef0b9cda8f2720b473fc2edd4324d77396b9/android/src/main/java/com/espressif/iot/esptouch/udp/UDPSocketClient.java#L115-L124

It is handling a java.lang.InterruptedException which is thrown because we interrupt (cancel) the task from the Flutter side.

It's not an uncaught exception, however, it might look like one as the entire stack trace is printed.

This part of the code is from the original Espressif Android, so I'm not really sure why they considered it a warning (Note logcat "w" level in Log.w and I also don't understand why they print the entire stack trace https://github.com/smaho-engineering/esptouch_flutter/blob/fb00ef0b9cda8f2720b473fc2edd4324d77396b9/android/src/main/java/com/espressif/iot/esptouch/udp/UDPSocketClient.java#L118

There are a couple of instances where the log levels doesn't make sense, but I'd prefer not to go through the entire plugin's logs.

The way I see it, interrupting the task is considered totally normal and should not be logged as a warning. Practically speaking, the plugin works consistently and you should be able to set up as many devices as you want, though the logs can be annoying.

When wrapping the two original libraries (ios+android), I tried to make as little changes as possible to the original code base, while still adapting the libs to our needs (1. be able to run from Flutter 2. be able to run with custom parameters and custom durations (e.g. run it for an hour).

For now (2.3.0), I changed the way we log: we now use the d level instead of w and removed the exception.printStrackTrace calls. Please let me know if you can think of a reason why that would be problematic.

vincevargadev commented 4 years ago

@johnwargo Oh and one more thing!

// Don't forget to cancel your stream subscription:
streamSubscription.cancel();

You should cancel the description with a delay. You need to first let the task run, then in accordance with the waitUdpReceiving and waitUdpSending durations, cancel the stream subscription. Another reason for cancelling the stream subscription is when the user left the screen where the task runs.

johnwargo commented 4 years ago

@vargavince91 thanks so much for looking into this for me. Do you mind providing some more detail for "then in accordance with the waitUdpReceiving and waitUdpSending durations, cancel the stream subscription."? I see in the simple example, the code waits an arbitrary time then cancels the stream subscription, but that is too arbitrary, right? What are you suggesting I do with those two durations you mention? Would those just be used as timeout values? but how would I use two of them?

vincevargadev commented 4 years ago

Oh, sorry, forgot to commit & push the example app. See commit: https://github.com/smaho-engineering/esptouch_flutter/commit/59b6addccc196000dc703556f2c0414c123df8fa

If you have questions, shoot. Also, we are open to improvements, both on the example app's part and on the plugin itself. If you find a way that makes canceling easier as part of the library without adding too much complexity, let me know!

johnwargo commented 4 years ago

@vargavince91 thanks, it's working.