Unhandled Exception: SocketException: Read failed (OS Error: Connection reset by peer, errno = 104)

vishal-android-freak commented 3 years ago

Getting this error on Android & iOS when I am manually calling the disconnect() on the client. I am not able to handle this exception as this seems to be an internal error. Auto-reconnect is enabled.

[ERROR:flutter/lib/ui/ui_dart_state.cc(186)] Unhandled Exception: SocketException: Read failed (OS Error: Connection reset by peer, errno = 104), address = mqtt_url, port = 41860
E/flutter (19249): #0      _NativeSocket.read (dart:io-patch/socket_patch.dart:1038:33)
E/flutter (19249): #1      _RawSocket.read (dart:io-patch/socket_patch.dart:1734:22)
E/flutter (19249): #2      _RawSecureSocket._readSocketOrBufferedData (dart:io/secure_socket.dart:947:22)
E/flutter (19249): #3      _ExternalBuffer.writeFromSource (dart:io/secure_socket.dart:1187:30)
E/flutter (19249): #4      _RawSecureSocket._readSocket (dart:io/secure_socket.dart:956:16)
E/flutter (19249): #5      _RawSecureSocket._readHandler (dart:io/secure_socket.dart:738:5)
E/flutter (19249): #6      _RawSecureSocket._eventDispatcher (dart:io/secure_socket.dart:726:9)
E/flutter (19249): #7      _rootRunUnary (dart:async/zone.dart:1370:13)

E/flutter (19249): #8      _CustomZone.runUnary (dart:async/zone.dart:1265:19)
E/flutter (19249): #9      _CustomZone.runUnaryGuarded (dart:async/zone.dart:1170:7)
E/flutter (19249): #10     _BufferingStreamSubscription._sendData (dart:async/stream_impl.dart:341:11)
E/flutter (19249): #11     _BufferingStreamSubscription._add (dart:async/stream_impl.dart:271:7)
E/flutter (19249): #12     _SyncStreamControllerDispatch._sendData (dart:async/stream_controller.dart:733:19)
E/flutter (19249): #13     _StreamController._add (dart:async/stream_controller.dart:607:7)
E/flutter (19249): #14     _StreamController.add (dart:async/stream_controller.dart:554:5)
E/flutter (19249): #15     new _RawSocket.<anonymous closure> (dart:io-patch/socket_patch.dart:1676:33)
E/flutter (19249): #16     _NativeSocket.issueReadEvent.issue (dart:io-patch/socket_patch.dart:1188:14)
E/flutter (19249): #17     _microtaskLoop (dart:async/schedule_microtask.dart:40:21)
E/flutter (19249): #18     _startMicrotaskLoop (dart:async/schedule_microtask.dart:49:5)

Just not able to understand the issue. Any help would be appreciated. This is happening when I am calling client.disconnect() when my app goes in the background. Using version 8.2.0

shamblett commented 3 years ago

Yes I've noticed that some of these socket exceptions generated by the Dart runtime don't like to be caught for some reason, of more concern is that it is being raised at all when you call disconnect with auto reconnect in force, this should work without issue.

I'll have a look at this.

vishal-android-freak commented 3 years ago

Exactly! This actually crashes the app in the background and the FCM background isolate stops working and therefore app stops getting notification in the background.

Let me know if you need any help in debugging or providing logs 👍

shamblett commented 3 years ago

Ok, I'm not seeing this, there is an example named mqtt_server_client_autoreconnect.dart in the examples directory, if I run this and just allow it disconnect it works Ok, if I run it, disconnect the broker thus triggering auto reconnect and re start the broker again when it calls disconnect it works Ok.

Note this was on the Dart VM, I'm not a flutter user. What version of the package are you using?

vishal-android-freak commented 3 years ago

I am using 8.2.0. The not-null safety version.

Did you try to manually disconnect it, you mean?

Edit: Also, wanted to confirm, is it necessary to call unsubscribe before calling disconnect?

shamblett commented 3 years ago

Ok thanks this should be alright with the latest auto reconnect fixes, I'll check. I'm just thinking one thing I've not tested is what if you call disconnect while auto reconnect is in progress, if you think this may be the case could you post the log output. I'll try this at my end.

vishal-android-freak commented 3 years ago

As soon as I call disconnect(), I get the error mentioned in the issue. I am sure it is trying to reconnect because I get this error.

[ERROR:flutter/lib/ui/ui_dart_state.cc(186)] Unhandled Exception: SocketException: Read failed (OS Error: Connection reset by peer, errno = 104), address = mqtt_url, port = 41860

Which says an attempt was being made to connect, but that failed somehow. I am guessing it has something to do with the auto reconnect logic.

And yes, auto reconnect was not in progress when I call disconnect. Had a stable ongoing mqtt connection and when I switch the app to background (by pressing the home button) I call disconnect()

shamblett commented 3 years ago

OK, running the auto reconnect example and not restarting the broker allows auto reconnect to run until we call disconnect, I'm not seeing the fault you are seeing but it doesn't exit cleanly so I need to look at this.

Why do you call disconnect when you enter background? Wouldn't the sequence be to disconnect then enter background, not the other way around. Why do you disconnect at all? Forgive my ignorance here as I'm not a flutter user.

vishal-android-freak commented 3 years ago

I am building a chat app over MQTT. If the app goes in the background ( by user pressing the home button ) the app is still in memory so the MQTT connection stays active and the user is seen online to the other person. Hence, calling disconnect is necessary as soon as the code detects that the app is going in the background.

shamblett commented 3 years ago

I'm not sure what you mean by 'so the MQTT connection stays active...', if you disconnect the MQTT connection is not active.

When you call disconnect the client sends a disconnect message to the broker as per the MQTT protocol, then it closes its network connections, you may be seeing this message being interrupted as you go into background.

What you need to do is attach a function to the onDisconnected callback, example -

// Thedisconnect callback
void onDisconnected() {
  print('EXAMPLE::OnDisconnected client callback - Client disconnection');
  if (client.connectionStatus!.disconnectionOrigin ==
      MqttDisconnectionOrigin.solicited) {
    // Go into background
  }
  // Not needed in your case
}

Only when this is called and the disconnect reason is solicited should you go into background, so call disconnect, wait for the callback then go into background.

You don't have to unsubscribe before you do this but you will have to re subscribe on re connecting.

When you go into background doesn't the app sort of get suspended and restored when you come out? I'm still not sure why you need to disconnect the broker.

vishal-android-freak commented 3 years ago

When the app goes in the background, everything stays in memory and the MQTT connection is active in the background and I have to manually call disconnect.

I tried this now - called connect() -> as soon as onConnected() callback was executed, I waited for 5 seconds and called disconnect() and got the same crash again.

[ERROR:flutter/lib/ui/ui_dart_state.cc(186)] Unhandled Exception: SocketException: Read failed (OS Error: Connection reset by peer, errno = 104), address = mqtt_url, port = 41860
E/flutter (19249): #0      _NativeSocket.read (dart:io-patch/socket_patch.dart:1038:33)
E/flutter (19249): #1      _RawSocket.read (dart:io-patch/socket_patch.dart:1734:22)
E/flutter (19249): #2      _RawSecureSocket._readSocketOrBufferedData (dart:io/secure_socket.dart:947:22)
E/flutter (19249): #3      _ExternalBuffer.writeFromSource (dart:io/secure_socket.dart:1187:30)
E/flutter (19249): #4      _RawSecureSocket._readSocket (dart:io/secure_socket.dart:956:16)
E/flutter (19249): #5      _RawSecureSocket._readHandler (dart:io/secure_socket.dart:738:5)
E/flutter (19249): #6      _RawSecureSocket._eventDispatcher (dart:io/secure_socket.dart:726:9)
E/flutter (19249): #7      _rootRunUnary (dart:async/zone.dart:1370:13)

E/flutter (19249): #8      _CustomZone.runUnary (dart:async/zone.dart:1265:19)
E/flutter (19249): #9      _CustomZone.runUnaryGuarded (dart:async/zone.dart:1170:7)
E/flutter (19249): #10     _BufferingStreamSubscription._sendData (dart:async/stream_impl.dart:341:11)
E/flutter (19249): #11     _BufferingStreamSubscription._add (dart:async/stream_impl.dart:271:7)
E/flutter (19249): #12     _SyncStreamControllerDispatch._sendData (dart:async/stream_controller.dart:733:19)
E/flutter (19249): #13     _StreamController._add (dart:async/stream_controller.dart:607:7)
E/flutter (19249): #14     _StreamController.add (dart:async/stream_controller.dart:554:5)
E/flutter (19249): #15     new _RawSocket.<anonymous closure> (dart:io-patch/socket_patch.dart:1676:33)
E/flutter (19249): #16     _NativeSocket.issueReadEvent.issue (dart:io-patch/socket_patch.dart:1188:14)
E/flutter (19249): #17     _microtaskLoop (dart:async/schedule_microtask.dart:40:21)
E/flutter (19249): #18     _startMicrotaskLoop (dart:async/schedule_microtask.dart:49:5)

Edit: Tried removing autoReconnect and still getting the same error. Not sure, why it tries connecting again to the MQTT broker and that's why we are getting an SocketException error.

shamblett commented 3 years ago

How do you know its trying to connect again? As I've said I can't reproduce this behavior so I'll need a full log output so I can see how far through the disconnect we are going. I take in the above example you are not going into background, just calling disconnect 5 seconds after connecting. Also how do you wait for 5 seconds? This should be asynchronous.

vishal-android-freak commented 3 years ago

How do you know its trying to connect again? As I've said I can't reproduce this behavior so I'll need a full log output so I can see how far through the disconnect we are going.

[ERROR:flutter/lib/ui/ui_dart_state.cc(186)] Unhandled Exception: SocketException: Read failed (OS Error: Connection reset by peer, errno = 104), address = mqtt_url, port = 41860

I get this error as soon as I call disconnect. Socket exception comes up when you try connecting and the connection was unsuccessful. Unfortunately, the log that I get is what I have pasted in the issue :(

I take in the above example you are not going into background, just calling disconnect 5 seconds after connecting. Also how do you wait for 5 seconds? This should be asynchronous.

Yes, it is async and the app is in the foreground. I am using the Timer() class for waiting 5 seconds

shamblett commented 3 years ago

You need to turn on logging on the client before you connect so I can see a client log, I need to see what part of disconnect is being executed when the exception is raised, the client logs this.

vishal-android-freak commented 3 years ago

Perfect. Trying this and sending logs right away!

vishal-android-freak commented 3 years ago

Here is the log

I/flutter (30408): 1-2021-05-04 18:55:45.190755 -- MqttConnectionBase::_onError - calling disconnected callback
I/flutter (30408): 1-2021-05-04 18:55:45.246753 -- MqttClient::internalDisconnect - not invoking disconnect, no connection handler
I/flutter (30408): 1-2021-05-04 18:55:45.250580 -- MqttConnectionBase::_onDone - calling disconnected callback
I/flutter (30408): 1-2021-05-04 18:55:45.250914 -- MqttClient::internalDisconnect - not invoking disconnect, no connection handler
E/flutter (30408): [ERROR:flutter/lib/ui/ui_dart_state.cc(186)] Unhandled Exception: SocketException: OS Error: Connection reset by peer, errno = 104, address = mqtt_url, port = 38106

shamblett commented 3 years ago

I need more than this, I need to see what was going on before you called disconnect, and the call to disconnect itself, thanks.

vishal-android-freak commented 3 years ago

Here is the entire log since the beginning of app start

Restarted application in 3,534ms.
I/FIAM.Headless(30408): went foreground
I/FIAM.Display(30408): Binding to activity: MainActivity
I/FIAM.Headless(30408): Setting display event component
Error handling 'checkPlatformOverride' custom request: method not available: ext.flutter.platformOverride
Error handling 'checkBrightnessOverride' custom request: method not available: ext.flutter.brightnessOverride
Error handling 'checkIsWidgetCreationTracked' custom request: method not available: ext.flutter.inspector.isWidgetCreationTracked
I/FLTFireMsgService(30408): FlutterFirebaseMessagingBackgroundService started!
W/FLTFireMsgService(30408): Attempted to start a duplicate background isolate. Returning...
I/FirebaseAuth(30408): [FirebaseAuth:] Preparing to create service connection to fallback implementation
W/System  (30408): Ignoring header X-Firebase-Locale because its value was null.
D/FirebaseAuth(30408): Notifying id token listeners about user ( ndX6Fiyfe0PRPrfMPpKVCi17SDv2 ).
I/flutter (30408): 1-2021-05-04 19:07:20.703594 -- MqttConnectionHandlerBase::connect - server mqtt_url, port 7654
I/flutter (30408): 1-2021-05-04 19:07:20.708339 -- SynchronousMqttServerConnectionHandler::internalConnect entered
I/flutter (30408): 1-2021-05-04 19:07:20.708870 -- SynchronousMqttServerConnectionHandler::internalConnect - initiating connection try 0, auto reconnect in progress false
I/flutter (30408): 1-2021-05-04 19:07:20.709208 -- SynchronousMqttServerConnectionHandler::internalConnect - secure selected
I/flutter (30408): 1-2021-05-04 19:07:20.710047 -- SynchronousMqttServerConnectionHandler::internalConnect - calling connect
I/flutter (30408): 1-2021-05-04 19:07:20.711252 -- MqttSecureConnection::connect - entered
D/ThumbnailPlugin(30408): buildThumbnailData( format:0, maxh:0, maxw:250, timeMs:0, quality:70 )
D/ThumbnailPlugin(30408): buildThumbnailData( format:0, maxh:0, maxw:250, timeMs:0, quality:70 )
D/ThumbnailPlugin(30408): original w:366, h:202 => 250, 138
D/ThumbnailPlugin(30408): original w:208, h:208 => 250, 250
I/flutter (30408): 1-2021-05-04 19:07:22.432412 -- MqttSecureConnection::connect - securing socket
I/flutter (30408): 1-2021-05-04 19:07:22.433154 -- MqttSecureConnection::connect - start listening
I/flutter (30408): 1-2021-05-04 19:07:22.433619 -- MqttServerConnection::_startListening
I/flutter (30408): 1-2021-05-04 19:07:22.434556 -- SynchronousMqttServerConnectionHandler::internalConnect - connection complete
I/flutter (30408): 1-2021-05-04 19:07:22.434724 -- SynchronousMqttServerConnectionHandler::internalConnect sending connect message
I/flutter (30408): 1-2021-05-04 19:07:22.437315 -- MqttConnectionHandlerBase::sendMessage - MQTTMessage of type MqttMessageType.connect
I/flutter (30408): Header: MessageType = MqttMessageType.connect, Duplicate = false, Retain = false, Qos = MqttQos.atMostOnce, Size = 0
I/flutter (30408): Connect Variable Header: ProtocolName=MQIsdp, ProtocolVersion=3, ConnectFlags=Connect Flags: Reserved1=false, CleanStart=false, WillFlag=false, WillQos=MqttQos.atMostOnce, WillRetain=false, PasswordFlag=true, UserNameFlag=true, KeepAlive=0
I/flutter (30408): MqttConnectPayload - client identifier is : P1mR9tWhGRLs
I/flutter (30408): 1-2021-05-04 19:07:22.445557 -- SynchronousMqttServerConnectionHandler::internalConnect - pre sleep, state = Connection status is connecting with return code of noneSpecified and a disconnection origin of none
I/flutter (30408): 1-2021-05-04 19:07:22.778724 -- MqttConnection::_onData
I/flutter (30408): 1-2021-05-04 19:07:22.784811 -- MqttServerConnection::_onData - message received MQTTMessage of type MqttMessageType.connectAck
I/flutter (30408): Header: MessageType = MqttMessageType.connectAck, Duplicate = false, Retain = false, Qos = MqttQos.atMostOnce, Size = 2
I/flutter (30408): Connect Variable Header: TopicNameCompressionResponse={0}, ReturnCode={MqttConnectReturnCode.connectionAccepted}
I/flutter (30408): 1-2021-05-04 19:07:22.790770 -- MqttServerConnection::_onData - message available event fired
I/flutter (30408): 1-2021-05-04 19:07:22.792872 -- MqttConnectionHandlerBase::_connectAckProcessor
I/flutter (30408): 1-2021-05-04 19:07:22.793332 -- MqttConnectionHandlerBase:_connectAckProcessor - state = connected
I/flutter (30408): ┌───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
[38;5;248mI/flutter (30408): │ #0   Common.logDebug[39;49m
[38;5;248mI/flutter (30408): │ #1   MqttClient.onClientConnected[39;49m
I/flutter (30408): ├┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄
I/flutter (30408): │ 🐛 client connected
I/flutter (30408): └───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter (30408): 1-2021-05-04 19:07:22.837918 -- PublishingManager::publish - entered with topic test
I/flutter (30408): 1-2021-05-04 19:07:22.841220 -- MqttConnectionHandlerBase::sendMessage - MQTTMessage of type MqttMessageType.publish
I/flutter (30408): Header: MessageType = MqttMessageType.publish, Duplicate = false, Retain = false, Qos = MqttQos.atLeastOnce, Size = 0
I/flutter (30408): Publish Variable Header: TopicName={/rego/P1mR9tWhGRLs/ephemeral}, MessageIdentifier={1}, VH Length={0}
I/flutter (30408): Payload: {499 bytes={<91><51><55><44><32><52><54><44><32><49><53><54><44><32><49><54><56><44><32><56><57><44><32><55><48><44><32><54><48><44><32><49><49><54><44><32><50><53><52><44><32><50><48><55><44><32><49><50><44><32><50><52><55><44><32><49><51><44><32><49><51><51><44><32><50><49><56><44><32><53><55><44><32><56><56><44><32><49><49><54><44><32><50><51><44><32><49><55><55><44><32><50><48><54><44><32><49><56><54><44><32><49><51><49><44><32><49><50><54><44><32><53><50><44><32><50><51><48><44><32><55><57><44><32><50><50><54><44><32><50><49><48><44><32><49><48><50><44><32><50><50><57><44><32><49><53><50><44><32><49><49><54><44><32><49><50><54><44><32><49><48><54><44><32><50><50
I/flutter (30408): 1-2021-05-04 19:07:22.848650 -- MqttConnectionHandlerBase::sendMessage - MQTTMessage of type MqttMessageType.subscribe
I/flutter (30408): Header: MessageType = MqttMessageType.subscribe, Duplicate = false, Retain = false, Qos = MqttQos.atLeastOnce, Size = 0
I/flutter (30408): Subscribe Variable Header: MessageIdentifier={2}
I/flutter (30408): Payload: Subscription [{1}]
I/flutter (30408): {{ Topic={test}, Qos={MqttQos.atLeastOnce} }}
I/flutter (30408):
I/flutter (30408): 1-2021-05-04 19:07:22.850307 -- MqttConnectionHandlerBase::sendMessage - MQTTMessage of type MqttMessageType.subscribe
I/flutter (30408): Header: MessageType = MqttMessageType.subscribe, Duplicate = false, Retain = false, Qos = MqttQos.atLeastOnce, Size = 0
I/flutter (30408): Subscribe Variable Header: MessageIdentifier={3}
I/flutter (30408): Payload: Subscription [{1}]
I/flutter (30408): {{ Topic={test}, Qos={MqttQos.atLeastOnce} }}
I/flutter (30408):
I/flutter (30408): 1-2021-05-04 19:07:22.850827 -- MqttConnectionHandlerBase::sendMessage - MQTTMessage of type MqttMessageType.subscribe
I/flutter (30408): Header: MessageType = MqttMessageType.subscribe, Duplicate = false, Retain = false, Qos = MqttQos.atLeastOnce, Size = 0
I/flutter (30408): Subscribe Variable Header: MessageIdentifier={4}
I/flutter (30408): Payload: Subscription [{1}]
I/flutter (30408): {{ Topic={test}, Qos={MqttQos.atLeastOnce} }}
I/flutter (30408):
I/flutter (30408): 1-2021-05-04 19:07:22.851897 -- MqttConnectionHandlerBase:: cancelling connect timer
I/flutter (30408): 1-2021-05-04 19:07:22.876019 -- SynchronousMqttServerConnectionHandler::internalConnect - post sleep, state = Connection status is connected with return code of connectionAccepted and a disconnection origin of none
I/flutter (30408): 1-2021-05-04 19:07:22.876278 -- SynchronousMqttServerConnectionHandler::internalConnect exited with state Connection status is connected with return code of connectionAccepted and a disconnection origin of none
I/flutter (30408): 1-2021-05-04 19:07:23.305615 -- MqttConnection::_onData
I/flutter (30408): 1-2021-05-04 19:07:23.307254 -- MqttServerConnection::_onData - message received MQTTMessage of type MqttMessageType.publishAck
I/flutter (30408): Header: MessageType = MqttMessageType.publishAck, Duplicate = false, Retain = false, Qos = MqttQos.atMostOnce, Size = 2
I/flutter (30408): PublishAck Variable Header: MessageIdentifier={1}
I/flutter (30408): 1-2021-05-04 19:07:23.307616 -- MqttServerConnection::_onData - message available event fired
I/flutter (30408): 1-2021-05-04 19:07:23.309631 -- MqttServerConnection::_onData - message received MQTTMessage of type MqttMessageType.subscribeAck
I/flutter (30408): Header: MessageType = MqttMessageType.subscribeAck, Duplicate = false, Retain = false, Qos = MqttQos.atMostOnce, Size = 3
I/flutter (30408): SubscribeAck Variable Header: MessageIdentifier={2}
I/flutter (30408): Payload: Qos grants [{1}]
I/flutter (30408): {{ Grant={MqttQos.atLeastOnce} }}
I/flutter (30408):
I/flutter (30408): 1-2021-05-04 19:07:23.309782 -- MqttServerConnection::_onData - message available event fired
I/flutter (30408): 1-2021-05-04 19:07:23.309927 -- MqttServerConnection::_onData - message received MQTTMessage of type MqttMessageType.subscribeAck
I/flutter (30408): Header: MessageType = MqttMessageType.subscribeAck, Duplicate = false, Retain = false, Qos = MqttQos.atMostOnce, Size = 3
I/flutter (30408): SubscribeAck Variable Header: MessageIdentifier={3}
I/flutter (30408): Payload: Qos grants [{1}]
I/flutter (30408): {{ Grant={MqttQos.atLeastOnce} }}
I/flutter (30408):
I/flutter (30408): 1-2021-05-04 19:07:23.309999 -- MqttServerConnection::_onData - message available event fired
I/flutter (30408): 1-2021-05-04 19:07:23.310086 -- MqttServerConnection::_onData - message received MQTTMessage of type MqttMessageType.subscribeAck
I/flutter (30408): Header: MessageType = MqttMessageType.subscribeAck, Duplicate = false, Retain = false, Qos = MqttQos.atMostOnce, Size = 3
I/flutter (30408): SubscribeAck Variable Header: MessageIdentifier={4}
I/flutter (30408): Payload: Qos grants [{1}]
I/flutter (30408): {{ Grant={MqttQos.atLeastOnce} }}
I/flutter (30408):
I/flutter (30408): 1-2021-05-04 19:07:23.310171 -- MqttServerConnection::_onData - message available event fired
I/flutter (30408): 1-2021-05-04 19:07:23.311067 -- MqttConnectionHandlerBase::messageAvailable - message type is MqttMessageType.publishAck
I/flutter (30408): 1-2021-05-04 19:07:23.311649 -- PublishingManager::handlePublishAcknowledgement for message id 1
I/flutter (30408): 1-2021-05-04 19:07:23.312193 -- MqttConnectionHandlerBase::messageAvailable - message type is MqttMessageType.subscribeAck
I/flutter (30408): 1-2021-05-04 19:07:23.313147 -- MqttConnectionHandlerBase::messageAvailable - message type is MqttMessageType.subscribeAck
I/flutter (30408): 1-2021-05-04 19:07:23.313430 -- MqttConnectionHandlerBase::messageAvailable - message type is MqttMessageType.subscribeAck
I/flutter (30408): 1-2021-05-04 19:07:23.318684 -- MqttConnection::_onData
I/flutter (30408): 1-2021-05-04 19:07:23.321156 -- MqttServerConnection::_onData - message received MQTTMessage of type MqttMessageType.publish
I/flutter (30408): Header: MessageType = MqttMessageType.publish, Duplicate = false, Retain = true, Qos = MqttQos.atLeastOnce, Size = 39
I/flutter (30408): Publish Variable Header: TopicName={/test}, MessageIdentifier={723}, VH Length={38}
I/flutter (30408): Payload: {1 bytes={<48>
I/flutter (30408): 1-2021-05-04 19:07:23.321393 -- MqttServerConnection::_onData - message available event fired
I/flutter (30408): 1-2021-05-04 19:07:23.321573 -- MqttConnectionHandlerBase::messageAvailable - message type is MqttMessageType.publish
I/flutter (30408): 1-2021-05-04 19:07:23.322444 -- PublishingManager::handlePublish - publish received from broker with topic /rego/W5s3xlhYrUp2/typingIndicator
I/flutter (30408): 1-2021-05-04 19:07:23.323088 -- MqttConnectionHandlerBase::sendMessage - MQTTMessage of type MqttMessageType.publishAck
I/flutter (30408): Header: MessageType = MqttMessageType.publishAck, Duplicate = false, Retain = false, Qos = MqttQos.atMostOnce, Size = 0
I/flutter (30408): PublishAck Variable Header: MessageIdentifier={723}
I/FIAM.Display(30408): Unbinding from activity: MainActivity
I/FIAM.Headless(30408): Removing display event component
I/flutter (30408): 1-2021-05-04 19:07:27.246433 -- MqttConnectionHandlerBase::disconnect - entered
I/flutter (30408): 1-2021-05-04 19:07:27.247395 -- MqttConnectionHandlerBase::sendMessage - MQTTMessage of type MqttMessageType.disconnect
I/flutter (30408): Header: MessageType = MqttMessageType.disconnect, Duplicate = false, Retain = false, Qos = MqttQos.atMostOnce, Size = 0
I/flutter (30408): 1-2021-05-04 19:07:27.248592 -- MqttConnectionHandlerBase::_performConnectionDisconnect entered
I/flutter (30408): ┌───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
[38;5;248mI/flutter (30408): │ #0   Common.logDebug[39;49m
[38;5;248mI/flutter (30408): │ #1   MqttClient.onClientDisconnected[39;49m
I/flutter (30408): ├┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄
I/flutter (30408): │ 🐛 client disconnected
I/flutter (30408): └───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter (30408): 1-2021-05-04 19:07:27.573945 -- MqttConnectionBase::_onError - calling disconnected callback
I/flutter (30408): 1-2021-05-04 19:07:27.575836 -- MqttClient::internalDisconnect - not invoking disconnect, no connection handler
I/flutter (30408): 1-2021-05-04 19:07:27.578705 -- MqttConnectionBase::_onDone - calling disconnected callback
I/flutter (30408): 1-2021-05-04 19:07:27.579021 -- MqttClient::internalDisconnect - not invoking disconnect, no connection handler
E/flutter (30408): [ERROR:flutter/lib/ui/ui_dart_state.cc(186)] Unhandled Exception: SocketException: OS Error: Connection reset by peer, errno = 104, address = mqtt_url, port = 38182
E/flutter (30408):

shamblett commented 3 years ago

From the above -

I/flutter (30408): PublishAck Variable Header: MessageIdentifier={723} I/FIAM.Display(30408): Unbinding from activity: MainActivity I/FIAM.Headless(30408): Removing display event component I/flutter (30408): 1-2021-05-04 19:07:27.246433 -- MqttConnectionHandlerBase::disconnect - entered

What does -

I/FIAM.Display(30408): Unbinding from activity: MainActivity I/FIAM.Headless(30408): Removing display event component

mean? If this means going into the background then its in the wrong place, it should be after the call to disconnect has completed, not before it.

vishal-android-freak commented 3 years ago

The problem here is that I get an event that the app has gone in the background only after the app goes in the background.

Should I try to call disconnect when my app is in the foreground with a timer and see the logs?

shamblett commented 3 years ago

Yes, run the example above but don't go into the background, as I say in the VM(which does this of course) I'm not seeing the exception.

vishal-android-freak commented 3 years ago

Got this after disconnecting in 5 seconds

Launching lib/main.dart on ONEPLUS A6013 in debug mode...
✓ Built build/app/outputs/flutter-apk/app-debug.apk.
W/quenfilabs.reg( 4706): Accessing hidden method Ljava/security/spec/ECParameterSpec;->getCurveName()Ljava/lang/String; (greylist, reflection, allowed)
I/ProviderInstaller( 4706): Installed default security provider GmsCore_OpenSSL
W/quenfilabs.reg( 4706): Accessing hidden method Lsun/misc/Unsafe;->getObject(Ljava/lang/Object;J)Ljava/lang/Object; (greylist, linking, allowed)
W/quenfilabs.reg( 4706): Accessing hidden field Ljava/net/Socket;->impl:Ljava/net/SocketImpl; (greylist, reflection, allowed)
W/quenfilabs.reg( 4706): Accessing hidden field Ljava/io/FileDescriptor;->descriptor:I (greylist, JNI, allowed)
W/quenfilabs.reg( 4706): Accessing hidden method Ljava/security/spec/ECParameterSpec;->setCurveName(Ljava/lang/String;)V (greylist, reflection, allowed)
W/quenfilabs.reg( 4706): Accessing hidden method Ldalvik/system/BlockGuard;->getThreadPolicy()Ldalvik/system/BlockGuard$Policy; (greylist,core-platform-api, linking, allowed)
W/quenfilabs.reg( 4706): Accessing hidden method Ldalvik/system/BlockGuard$Policy;->onNetwork()V (greylist, linking, allowed)
W/quenfilabs.reg( 4706): Accessing hidden method Lsun/misc/Unsafe;->getObject(Ljava/lang/Object;J)Ljava/lang/Object; (greylist, linking, allowed)
W/quenfilabs.reg( 4706): Accessing hidden method Lsun/misc/Unsafe;->getInt(Ljava/lang/Object;J)I (greylist, linking, allowed)
W/quenfilabs.reg( 4706): Accessing hidden method Lsun/misc/Unsafe;->putInt(Ljava/lang/Object;JI)V (greylist, linking, allowed)
Connecting to VM Service at ws://127.0.0.1:52385/EKP2zQEWma4=/ws
W/quenfilabs.reg( 4706): Accessing hidden method Lsun/misc/Unsafe;->compareAndSwapObject(Ljava/lang/Object;JLjava/lang/Object;Ljava/lang/Object;)Z (greylist, linking, allowed)
W/quenfilabs.reg( 4706): Accessing hidden method Lsun/misc/Unsafe;->putObject(Ljava/lang/Object;JLjava/lang/Object;)V (greylist, linking, allowed)
W/quenfilabs.reg( 4706): Accessing hidden method Lsun/misc/Unsafe;->getLong(Ljava/lang/Object;J)J (greylist,core-platform-api, linking, allowed)
I/FIAM.Headless( 4706): Successfully fetched 0 messages from backend
W/quenfilabs.reg( 4706): Accessing hidden method Lsun/misc/Unsafe;->getObject(Ljava/lang/Object;J)Ljava/lang/Object; (greylist, linking, allowed)
W/quenfilabs.reg( 4706): Accessing hidden method Lsun/misc/Unsafe;->getLong(Ljava/lang/Object;J)J (greylist,core-platform-api, linking, allowed)
I/FLTFireBGExecutor( 4706): Creating background FlutterEngine instance, with args: [--start-paused, --enable-dart-profiling]
W/FlutterEngine( 4706): Tried to automatically register plugins with FlutterEngine (io.flutter.embedding.engine.FlutterEngine@bce29b4) but could not find and invoke the GeneratedPluginRegistrant.
I/FLTFireMsgService( 4706): FlutterFirebaseMessagingBackgroundService started!
W/quenfilabs.reg( 4706): Accessing hidden method Lsun/misc/Unsafe;->compareAndSwapObject(Ljava/lang/Object;JLjava/lang/Object;Ljava/lang/Object;)Z (greylist, linking, allowed)
D/FlutterSecureStoragePl( 4706): Initializing StorageCipher
D/FlutterSecureStoragePl( 4706): StorageCipher initialization complete
I/DpmTcmClient( 4706): RegisterTcmMonitor from: $Proxy0
W/System  ( 4706): Ignoring header X-Firebase-Locale because its value was null.
D/FirebaseAuth( 4706): Notifying id token listeners about user ( ndX6Fiyfe0PRPrfMPpKVCi17SDv2 ).
D/SharedPreferencesImpl( 4706): Time required to fsync /data/user/0/com.quenfilabs.rego/shared_prefs/FlutterSharedPreferences.xml: [<1: 0, <2: 0, <4: 0, <8: 0, <16: 0, <32: 0, <64: 0, <128: 0, <256: 0, <512: 0, <1024: 0, <2048: 1, <4096: 0, <8192: 0, <16384: 0, >=16384: 0]
D/SharedPreferencesImpl( 4706): Time required to fsync /data/user/0/com.quenfilabs.rego/shared_prefs/com.google.android.gms.measurement.prefs.xml: [<1: 0, <2: 0, <4: 0, <8: 2, <16: 0, <32: 1, <64: 0, <128: 0, <256: 0, <512: 0, <1024: 0, <2048: 1, <4096: 0, <8192: 0, <16384: 0, >=16384: 0]
I/flutter ( 4706): 1-2021-05-04 20:20:00.979722 -- MqttConnectionHandlerBase::connect - server mqtt_url, port 8883
I/flutter ( 4706): 1-2021-05-04 20:20:00.984776 -- SynchronousMqttServerConnectionHandler::internalConnect entered
I/flutter ( 4706): 1-2021-05-04 20:20:00.985171 -- SynchronousMqttServerConnectionHandler::internalConnect - initiating connection try 0, auto reconnect in progress false
I/flutter ( 4706): 1-2021-05-04 20:20:00.985491 -- SynchronousMqttServerConnectionHandler::internalConnect - secure selected
I/flutter ( 4706): 1-2021-05-04 20:20:00.986325 -- SynchronousMqttServerConnectionHandler::internalConnect - calling connect
I/flutter ( 4706): 1-2021-05-04 20:20:00.987621 -- MqttSecureConnection::connect - entered
D/ThumbnailPlugin( 4706): buildThumbnailData( format:0, maxh:0, maxw:250, timeMs:0, quality:70 )
D/ThumbnailPlugin( 4706): buildThumbnailData( format:0, maxh:0, maxw:250, timeMs:0, quality:70 )
D/ThumbnailPlugin( 4706): original w:366, h:202 => 250, 138
D/ThumbnailPlugin( 4706): original w:208, h:208 => 250, 250
I/flutter ( 4706): 1-2021-05-04 20:20:02.667309 -- MqttSecureConnection::connect - securing socket
I/flutter ( 4706): 1-2021-05-04 20:20:02.668521 -- MqttSecureConnection::connect - start listening
I/flutter ( 4706): 1-2021-05-04 20:20:02.668942 -- MqttServerConnection::_startListening
I/flutter ( 4706): 1-2021-05-04 20:20:02.670033 -- SynchronousMqttServerConnectionHandler::internalConnect - connection complete
I/flutter ( 4706): 1-2021-05-04 20:20:02.670170 -- SynchronousMqttServerConnectionHandler::internalConnect sending connect message
I/flutter ( 4706): 1-2021-05-04 20:20:02.673143 -- MqttConnectionHandlerBase::sendMessage - MQTTMessage of type MqttMessageType.connect
I/flutter ( 4706): Header: MessageType = MqttMessageType.connect, Duplicate = false, Retain = false, Qos = MqttQos.atMostOnce, Size = 0
I/flutter ( 4706): Connect Variable Header: ProtocolName=MQIsdp, ProtocolVersion=3, ConnectFlags=Connect Flags: Reserved1=false, CleanStart=false, WillFlag=false, WillQos=MqttQos.atMostOnce, WillRetain=false, PasswordFlag=true, UserNameFlag=true, KeepAlive=0
I/flutter ( 4706): MqttConnectPayload - client identifier is : P1mR9tWhGRLs
I/flutter ( 4706): 1-2021-05-04 20:20:02.682181 -- SynchronousMqttServerConnectionHandler::internalConnect - pre sleep, state = Connection status is connecting with return code of noneSpecified and a disconnection origin of none
I/flutter ( 4706): 1-2021-05-04 20:20:07.685700 -- SynchronousMqttServerConnectionHandler::internalConnect - post sleep, state = Connection status is connecting with return code of noneSpecified and a disconnection origin of none
I/flutter ( 4706): 1-2021-05-04 20:20:07.687203 -- SynchronousMqttServerConnectionHandler::internalConnect - initiating connection try 1, auto reconnect in progress false
I/flutter ( 4706): 1-2021-05-04 20:20:07.687314 -- SynchronousMqttServerConnectionHandler::internalConnect - secure selected
I/flutter ( 4706): 1-2021-05-04 20:20:07.687394 -- SynchronousMqttServerConnectionHandler::internalConnect - calling connect
I/flutter ( 4706): 1-2021-05-04 20:20:07.687464 -- MqttSecureConnection::connect - entered
I/flutter ( 4706): 1-2021-05-04 20:20:07.991051 -- MqttConnection::_onData
I/flutter ( 4706): 1-2021-05-04 20:20:07.997010 -- MqttServerConnection::_onData - message received MQTTMessage of type MqttMessageType.connectAck
I/flutter ( 4706): Header: MessageType = MqttMessageType.connectAck, Duplicate = false, Retain = false, Qos = MqttQos.atMostOnce, Size = 2
I/flutter ( 4706): Connect Variable Header: TopicNameCompressionResponse={0}, ReturnCode={MqttConnectReturnCode.connectionAccepted}
I/flutter ( 4706): 1-2021-05-04 20:20:07.997601 -- MqttServerConnection::_onData - message available event fired
I/flutter ( 4706): 1-2021-05-04 20:20:07.999570 -- MqttConnectionHandlerBase::_connectAckProcessor
I/flutter ( 4706): 1-2021-05-04 20:20:08.000029 -- MqttConnectionHandlerBase:_connectAckProcessor - state = connected
I/flutter ( 4706): ┌───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
[38;5;248mI/flutter ( 4706): │ #0   Common.logDebug[39;49m
[38;5;248mI/flutter ( 4706): │ #1   MqttClient.onClientConnected[39;49m
I/flutter ( 4706): ├┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄
I/flutter ( 4706): │ 🐛 client connected
I/flutter ( 4706): └───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter ( 4706): 1-2021-05-04 20:20:08.044152 -- PublishingManager::publish - entered with topic test
I/flutter ( 4706): 1-2021-05-04 20:20:08.047344 -- MqttConnectionHandlerBase::sendMessage - MQTTMessage of type MqttMessageType.publish
I/flutter ( 4706): Header: MessageType = MqttMessageType.publish, Duplicate = false, Retain = false, Qos = MqttQos.atLeastOnce, Size = 0
I/flutter ( 4706): Publish Variable Header: TopicName=test}, MessageIdentifier={1}, VH Length={0}
I/flutter ( 4706): Payload: {499 bytes={<91><50><56><44><32><51><54><44><32><49><54><51><44><32><50><50><52><44><32><52><48><44><32><49><53><44><32><49><54><56><44><32><49><55><52><44><32><51><44><32><56><53><44><32><53><56><44><32><52><53><44><32><49><49><49><44><32><50><53><51><44><32><50><51><44><32><50><53><44><32><55><54><44><32><50><50><49><44><32><50><52><53><44><32><52><55><44><32><49><49><52><44><32><56><51><44><32><50><49><49><44><32><49><52><53><44><32><49><55><50><44><32><49><54><52><44><32><49><52><49><44><32><50><48><50><44><32><52><56><44><32><50><51><50><44><32><50><49><54><44><32><49><55><50><44><32><54><44><32><49><48><44><32><50><51><51><44><32><50><50><49><44><32><53><44><32
I/flutter ( 4706): 1-2021-05-04 20:20:08.053956 -- MqttConnectionHandlerBase::sendMessage - MQTTMessage of type MqttMessageType.subscribe
I/flutter ( 4706): Header: MessageType = MqttMessageType.subscribe, Duplicate = false, Retain = false, Qos = MqttQos.atLeastOnce, Size = 0
I/flutter ( 4706): Subscribe Variable Header: MessageIdentifier={2}
I/flutter ( 4706): Payload: Subscription [{1}]
I/flutter ( 4706): {{ Topic={tesdt}, Qos={MqttQos.atLeastOnce} }}
I/flutter ( 4706):
I/flutter ( 4706): 1-2021-05-04 20:20:08.055337 -- MqttConnectionHandlerBase::sendMessage - MQTTMessage of type MqttMessageType.subscribe
I/flutter ( 4706): Header: MessageType = MqttMessageType.subscribe, Duplicate = false, Retain = false, Qos = MqttQos.atLeastOnce, Size = 0
I/flutter ( 4706): Subscribe Variable Header: MessageIdentifier={3}
I/flutter ( 4706): Payload: Subscription [{1}]
I/flutter ( 4706): {{ Topic={/test}, Qos={MqttQos.atLeastOnce} }}
I/flutter ( 4706):
I/flutter ( 4706): 1-2021-05-04 20:20:08.055734 -- MqttConnectionHandlerBase::sendMessage - MQTTMessage of type MqttMessageType.subscribe
I/flutter ( 4706): Header: MessageType = MqttMessageType.subscribe, Duplicate = false, Retain = false, Qos = MqttQos.atLeastOnce, Size = 0
I/flutter ( 4706): Subscribe Variable Header: MessageIdentifier={4}
I/flutter ( 4706): Payload: Subscription [{1}]
I/flutter ( 4706): {{ Topic={test}, Qos={MqttQos.atLeastOnce} }}
I/flutter ( 4706):
I/flutter ( 4706): 1-2021-05-04 20:20:08.057137 -- MqttConnectionHandlerBase:: cancelling connect timer
I/flutter ( 4706): 1-2021-05-04 20:20:08.564569 -- MqttSecureConnection::connect - securing socket
I/flutter ( 4706): 1-2021-05-04 20:20:08.565013 -- MqttSecureConnection::connect - start listening
I/flutter ( 4706): 1-2021-05-04 20:20:08.565239 -- MqttServerConnection::_startListening
I/flutter ( 4706): 1-2021-05-04 20:20:08.565790 -- SynchronousMqttServerConnectionHandler::internalConnect - connection complete
I/flutter ( 4706): 1-2021-05-04 20:20:08.566 -- SynchronousMqttServerConnectionHandler::internalConnect sending connect message
I/flutter ( 4706): 1-2021-05-04 20:20:08.566279 -- MqttConnectionHandlerBase::sendMessage - MQTTMessage of type MqttMessageType.connect
I/flutter ( 4706): Header: MessageType = MqttMessageType.connect, Duplicate = false, Retain = false, Qos = MqttQos.atMostOnce, Size = 48
I/flutter ( 4706): Connect Variable Header: ProtocolName=MQIsdp, ProtocolVersion=3, ConnectFlags=Connect Flags: Reserved1=false, CleanStart=false, WillFlag=false, WillQos=MqttQos.atMostOnce, WillRetain=false, PasswordFlag=true, UserNameFlag=true, KeepAlive=0
I/flutter ( 4706): MqttConnectPayload - client identifier is : P1mR9tWhGRLs
I/flutter ( 4706): 1-2021-05-04 20:20:08.567597 -- SynchronousMqttServerConnectionHandler::internalConnect - pre sleep, state = Connection status is connected with return code of connectionAccepted and a disconnection origin of none
I/flutter ( 4706): 1-2021-05-04 20:20:08.907870 -- MqttConnectionBase::_onError - calling disconnected callback
I/flutter ( 4706): 1-2021-05-04 20:20:08.910565 -- MqttConnectionBase::_onDone - calling disconnected callback
E/flutter ( 4706): [ERROR:flutter/lib/ui/ui_dart_state.cc(186)] Unhandled Exception: SocketException: OS Error: Connection reset by peer, errno = 104, address = dev.regoapp.space, port = 39768
E/flutter ( 4706):
I/flutter ( 4706): 1-2021-05-04 20:20:08.921935 -- MqttConnection::_onData
I/flutter ( 4706): 1-2021-05-04 20:20:08.922236 -- MqttServerConnection::_onData - message received MQTTMessage of type MqttMessageType.connectAck
I/flutter ( 4706): Header: MessageType = MqttMessageType.connectAck, Duplicate = false, Retain = false, Qos = MqttQos.atMostOnce, Size = 2
I/flutter ( 4706): Connect Variable Header: TopicNameCompressionResponse={0}, ReturnCode={MqttConnectReturnCode.connectionAccepted}
I/flutter ( 4706): 1-2021-05-04 20:20:08.922364 -- MqttServerConnection::_onData - message available event fired
I/flutter ( 4706): 1-2021-05-04 20:20:08.922492 -- MqttConnectionHandlerBase::_connectAckProcessor
I/flutter ( 4706): 1-2021-05-04 20:20:08.922647 -- MqttConnectionHandlerBase:_connectAckProcessor - state = connected
I/flutter ( 4706): ┌───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
[38;5;248mI/flutter ( 4706): │ #0   Common.logDebug[39;49m
[38;5;248mI/flutter ( 4706): │ #1   MqttClient.onClientConnected[39;49m
I/flutter ( 4706): ├┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄
I/flutter ( 4706): │ 🐛 client connected
I/flutter ( 4706): └───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter ( 4706): 1-2021-05-04 20:20:08.925006 -- PublishingManager::publish - entered with topic test
I/flutter ( 4706): 1-2021-05-04 20:20:08.925777 -- MqttConnectionHandlerBase::sendMessage - MQTTMessage of type MqttMessageType.publish
I/flutter ( 4706): Header: MessageType = MqttMessageType.publish, Duplicate = false, Retain = false, Qos = MqttQos.atLeastOnce, Size = 0
I/flutter ( 4706): Publish Variable Header: TopicName={test}, MessageIdentifier={5}, VH Length={0}
I/flutter ( 4706): Payload: {506 bytes={<91><49><52><51><44><32><49><53><56><44><32><49><56><52><44><32><50><51><44><32><49><57><50><44><32><53><54><44><32><49><52><51><44><32><49><48><50><44><32><55><55><44><32><49><57><54><44><32><50><49><50><44><32><49><55><56><44><32><50><53><44><32><49><52><51><44><32><56><48><44><32><55><51><44><32><49><54><57><44><32><50><49><54><44><32><49><52><54><44><32><49><50><50><44><32><57><50><44><32><49><53><57><44><32><49><49><57><44><32><49><57><54><44><32><50><52><51><44><32><49><53><48><44><32><50><50><50><44><32><50><53><52><44><32><49><50><48><44><32><49><49><52><44><32><49><49><44><32><50><51><51><44><32><57><51><44><32><56><52><44><32><49><51><48><44><32
I/flutter ( 4706): 1-2021-05-04 20:20:08.927484 -- MqttConnectionHandlerBase:: cancelling connect timer
I/flutter ( 4706): 1-2021-05-04 20:20:08.934381 -- SynchronousMqttServerConnectionHandler::internalConnect - post sleep, state = Connection status is connected with return code of connectionAccepted and a disconnection origin of none
I/flutter ( 4706): 1-2021-05-04 20:20:08.934632 -- SynchronousMqttServerConnectionHandler::internalConnect exited with state Connection status is connected with return code of connectionAccepted and a disconnection origin of none
I/flutter ( 4706): 1-2021-05-04 20:20:09.221956 -- MqttConnection::_onData
I/flutter ( 4706): 1-2021-05-04 20:20:09.223662 -- MqttServerConnection::_onData - message received MQTTMessage of type MqttMessageType.publishAck
I/flutter ( 4706): Header: MessageType = MqttMessageType.publishAck, Duplicate = false, Retain = false, Qos = MqttQos.atMostOnce, Size = 2
I/flutter ( 4706): PublishAck Variable Header: MessageIdentifier={5}
I/flutter ( 4706): 1-2021-05-04 20:20:09.224104 -- MqttServerConnection::_onData - message available event fired
I/flutter ( 4706): 1-2021-05-04 20:20:09.225190 -- MqttConnectionHandlerBase::messageAvailable - message type is MqttMessageType.publishAck
I/flutter ( 4706): 1-2021-05-04 20:20:09.225921 -- PublishingManager::handlePublishAcknowledgement for message id 5
I/flutter ( 4706): 1-2021-05-04 20:20:13.061838 -- MqttConnectionHandlerBase::disconnect - entered
I/flutter ( 4706): 1-2021-05-04 20:20:13.064176 -- MqttConnectionHandlerBase::sendMessage - MQTTMessage of type MqttMessageType.disconnect
I/flutter ( 4706): Header: MessageType = MqttMessageType.disconnect, Duplicate = false, Retain = false, Qos = MqttQos.atMostOnce, Size = 0
I/flutter ( 4706): 1-2021-05-04 20:20:13.065680 -- MqttConnectionHandlerBase::_performConnectionDisconnect entered
I/flutter ( 4706): ┌───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
[38;5;248mI/flutter ( 4706): │ #0   Common.logDebug[39;49m
[38;5;248mI/flutter ( 4706): │ #1   MqttClient.onClientDisconnected[39;49m
I/flutter ( 4706): ├┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄
I/flutter ( 4706): │ 🐛 client disconnected
I/flutter ( 4706): └───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter ( 4706): ┌───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
[38;5;248mI/flutter ( 4706): │ #0   Common.logDebug[39;49m
[38;5;248mI/flutter ( 4706): │ #1   MqttClient.onClientDisconnected[39;49m
I/flutter ( 4706): ├┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄
I/flutter ( 4706): │ 🐛 client disconnected
I/flutter ( 4706): └───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter ( 4706): 1-2021-05-04 20:20:14.113228 -- MqttConnectionBase::_onError - calling disconnected callback
I/flutter ( 4706): 1-2021-05-04 20:20:14.113605 -- MqttClient::internalDisconnect - not invoking disconnect, no connection handler
I/flutter ( 4706): 1-2021-05-04 20:20:14.113960 -- MqttConnectionBase::_onDone - calling disconnected callback
I/flutter ( 4706): 1-2021-05-04 20:20:14.114115 -- MqttClient::internalDisconnect - not invoking disconnect, no connection handler
E/flutter ( 4706): [ERROR:flutter/lib/ui/ui_dart_state.cc(186)] Unhandled Exception: SocketException: Read failed (OS Error: Connection reset by peer, errno = 104), address = mqtt_url, port = 39774
[38;5;244mE/flutter ( 4706): #0      _NativeSocket.read (dart:io-patch/socket_patch.dart:1038:33)[39;49m
[38;5;244mE/flutter ( 4706): #1      _RawSocket.read (dart:io-patch/socket_patch.dart:1734:22)[39;49m
[38;5;244mE/flutter ( 4706): #2      _RawSecureSocket._readSocketOrBufferedData (dart:io/secure_socket.dart:947:22)[39;49m
[38;5;244mE/flutter ( 4706): #3      _ExternalBuffer.writeFromSource (dart:io/secure_socket.dart:1187:30)[39;49m
[38;5;244mE/flutter ( 4706): #4      _RawSecureSocket._readSocket (dart:io/secure_socket.dart:956:16)[39;49m
[38;5;244mE/flutter ( 4706): #5      _RawSecureSocket._readHandler (dart:io/secure_socket.dart:738:5)[39;49m
[38;5;244mE/flutter ( 4706): #6      _RawSecureSocket._eventDispatcher (dart:io/secure_socket.dart:726:9)[39;49m
[38;5;244mE/flutter ( 4706): #7      _rootRunUnary (dart:async/zone.dart:1370:13)[39;49m
[38;5;244mE/flutter ( 4706): #8      _CustomZone.runUnary (dart:async/zone.dart:1265:19)[39;49m
[38;5;244mE/flutter ( 4706): #9      _CustomZone.runUnaryGuarded (dart:async/zone.dart:1170:7)[39;49m
[38;5;244mE/flutter ( 4706): #10     _BufferingStreamSubscription._sendData (dart:async/stream_impl.dart:341:11)[39;49m
[38;5;244mE/flutter ( 4706): #11     _BufferingStreamSubscription._add (dart:async/stream_impl.dart:271:7)[39;49m
[38;5;244mE/flutter ( 4706): #12     _SyncStreamControllerDispatch._sendData (dart:async/stream_controller.dart:733:19)[39;49m
[38;5;244mE/flutter ( 4706): #13     _StreamController._add (dart:async/stream_controller.dart:607:7)[39;49m
[38;5;244mE/flutter ( 4706): #14     _StreamController.add (dart:async/stream_controller.dart:554:5)[39;49m
[38;5;244mE/flutter ( 4706): #15     new _RawSocket.<anonymous closure> (dart:io-patch/socket_patch.dart:1676:33)[39;49m
[38;5;244mE/flutter ( 4706): #16     _NativeSocket.issueReadEvent.issue (dart:io-patch/socket_patch.dart:1188:14)[39;49m
[38;5;244mE/flutter ( 4706): #17     _microtaskLoop (dart:async/schedule_microtask.dart:40:21)[39;49m
[38;5;244mE/flutter ( 4706): #18     _startMicrotaskLoop (dart:async/schedule_microtask.dart:49:5)[39;49m
E/flutter ( 4706):

vishal-android-freak commented 3 years ago

Did you get a chance to check this? @shamblett

shamblett commented 3 years ago

There are exception handlers in the client connection handlers -

 } on Exception catch (e) {
      completer.completeError(e);
      final message =
          'MqttNormalConnection::Connect - The connection to the message '
          'broker {$server}:{$port} could not be made.';
      throw NoConnectionException(message);

However I've noticed that the secure connection handler explicitly checks for socket exception, the normal connection handler doesn't. I'll update the code so all the connection handlers do the same here and check specifically for SocketException and re publish the package. I'll try and get this done over the weekend.

Hopefully the exception will now be caught, if not I'll have to try and re create why its being raised in the first place which could be a lengthy process.

vishal-android-freak commented 3 years ago

  void _disconnect() {
    if (client != null) {
      client.destroy();
      client = null;
    }
  }

If I replace client.destroy() with client.close() I don't see the following exception anymore:

[38;5;244mE/flutter ( 4706): #0      _NativeSocket.read (dart:io-patch/socket_patch.dart:1038:33)�[39;49m
�[38;5;244mE/flutter ( 4706): #1      _RawSocket.read (dart:io-patch/socket_patch.dart:1734:22)�[39;49m
�[38;5;244mE/flutter ( 4706): #2      _RawSecureSocket._readSocketOrBufferedData (dart:io/secure_socket.dart:947:22)�[39;49m
�[38;5;244mE/flutter ( 4706): #3      _ExternalBuffer.writeFromSource (dart:io/secure_socket.dart:1187:30)�[39;49m
�[38;5;244mE/flutter ( 4706): #4      _RawSecureSocket._readSocket (dart:io/secure_socket.dart:956:16)�[39;49m
�[38;5;244mE/flutter ( 4706): #5      _RawSecureSocket._readHandler (dart:io/secure_socket.dart:738:5)�[39;49m
�[38;5;244mE/flutter ( 4706): #6      _RawSecureSocket._eventDispatcher (dart:io/secure_socket.dart:726:9)�[39;49m
�[38;5;244mE/flutter ( 4706): #7      _rootRunUnary (dart:async/zone.dart:1370:13)�[39;49m
�[38;5;244mE/flutter ( 4706): #8      _CustomZone.runUnary (dart:async/zone.dart:1265:19)�[39;49m
�[38;5;244mE/flutter ( 4706): #9      _CustomZone.runUnaryGuarded (dart:async/zone.dart:1170:7)�[39;49m
�[38;5;244mE/flutter ( 4706): #10     _BufferingStreamSubscription._sendData (dart:async/stream_impl.dart:341:11)�[39;49m
�[38;5;244mE/flutter ( 4706): #11     _BufferingStreamSubscription._add (dart:async/stream_impl.dart:271:7)�[39;49m
�[38;5;244mE/flutter ( 4706): #12     _SyncStreamControllerDispatch._sendData (dart:async/stream_controller.dart:733:19)�[39;49m
�[38;5;244mE/flutter ( 4706): #13     _StreamController._add (dart:async/stream_controller.dart:607:7)�[39;49m
�[38;5;244mE/flutter ( 4706): #14     _StreamController.add (dart:async/stream_controller.dart:554:5)�[39;49m
�[38;5;244mE/flutter ( 4706): #15     new _RawSocket.<anonymous closure> (dart:io-patch/socket_patch.dart:1676:33)�[39;49m
�[38;5;244mE/flutter ( 4706): #16     _NativeSocket.issueReadEvent.issue (dart:io-patch/socket_patch.dart:1188:14)�[39;49m
�[38;5;244mE/flutter ( 4706): #17     _microtaskLoop (dart:async/schedule_microtask.dart:40:21)�[39;49m
�[38;5;244mE/flutter ( 4706): #18     _startMicrotaskLoop (dart:async/schedule_microtask.dart:49:5)�[39;49m
E/flutter ( 4706):

This means the socket is being accessed after calling destroy() which is causing the crash. Am I missing any callback that needs to be implemented which tells the client not to access the socket again?

vishal-android-freak commented 3 years ago

There are exception handlers in the client connection handlers -
 } on Exception catch (e) {
      completer.completeError(e);
      final message =
          'MqttNormalConnection::Connect - The connection to the message '
          'broker {$server}:{$port} could not be made.';
      throw NoConnectionException(message);
However I've noticed that the secure connection handler explicitly checks for socket exception, the normal connection handler doesn't. I'll update the code so all the connection handlers do the same here and check specifically for SocketException and re publish the package. I'll try and get this done over the weekend.

Hopefully the exception will now be caught, if not I'll have to try and re create why its being raised in the first place which could be a lengthy process.

I am actually using secure connection

shamblett commented 3 years ago

Well, form the dart API docs -

void destroy ()
Destroys the socket in both directions.

Calling destroy will make the send a close event on the stream and will no longer react on data being piped to it.

Call close (inherited from IOSink) to only close the Socket for sending data.

So 'no longer react...' to me sounds as though no exception should be raised even if you are accessing the socket after the destroy. I don't suppose it would do any harm doing a close first.

vishal-android-freak commented 3 years ago

After destroy is called if we try to interact with the same socket to set any options, etc., it sends a SocketException. I am now sure that the client isn't trying to autoconnect so that cannot be a reason for the socket exception.

shamblett commented 3 years ago

What happens if you close the socket, then destroy it, then try and interact?

vishal-android-freak commented 3 years ago

What happens if you close the socket, then destroy it, then try and interact?

Trying. Give me 5min.

vishal-android-freak commented 3 years ago

_disconnect() is being called twice inside bcz once _onError is being invoked as soon as I called client.disconnect() and second time onInternalDisconnect. This is strange. Logs:

I/flutter (25109): 1-2021-05-07 16:36:04.929549 -- MqttConnectionHandlerBase::disconnect - entered
I/flutter (25109): 1-2021-05-07 16:36:04.931029 -- MqttConnectionHandlerBase::sendMessage - MQTTMessage of type MqttMessageType.disconnect
I/flutter (25109): Header: MessageType = MqttMessageType.disconnect, Duplicate = false, Retain = false, Qos = MqttQos.atMostOnce, Size = 0
I/flutter (25109): 1-2021-05-07 16:36:04.932376 -- MqttConnectionHandlerBase::_performConnectionDisconnect entered
I/flutter (25109): ┌───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
[38;5;248mI/flutter (25109): │ #0   Common.logDebug[39;49m
[38;5;248mI/flutter (25109): │ #1   MqttClient.onClientDisconnected[39;49m
I/flutter (25109): ├┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄┄
I/flutter (25109): │ 🐛 client disconnected
I/flutter (25109): └───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────
I/flutter (25109): SocketException: Read failed (OS Error: Connection reset by peer, errno = 104), address = mqtt_url port = 40676
I/flutter (25109): 1-2021-05-07 16:36:05.619194 -- MqttConnectionBase::_onError - calling disconnected callback
I/flutter (25109): 1-2021-05-07 16:36:05.620839 -- MqttClient::internalDisconnect - not invoking disconnect, no connection handler
I/flutter (25109): 1-2021-05-07 16:36:05.624084 -- MqttConnectionBase::_onDone - calling disconnected callback
I/flutter (25109): 1-2021-05-07 16:36:05.624389 -- MqttClient::internalDisconnect - not invoking disconnect, no connection handler

shamblett commented 3 years ago

Yes why is onError being called? This is called from the catchError method of the socket stream, so what is invoking this? Its not the client, its coming from the socket layer. I'm going to add code to close the socket before calling destroy, see if that helps.

vishal-android-freak commented 3 years ago

Sure. Let me know once done!

shamblett commented 3 years ago

Package re published at version 9.3.0, please re test.

vishal-android-freak commented 3 years ago

Still onError is being called after disconnect but app doesn't crash anymore on v9.3.1 :) Thanks for all the help. Closing this!

RanaMusab commented 1 year ago

@shamblett getting same issue have you resolved it?

shamblett commented 1 year ago

This should be resolved, see the commentary above, do you have a log?

shamblett / mqtt_client

Unhandled Exception: SocketException: Read failed (OS Error: Connection reset by peer, errno = 104) #275