[BUG] MQTT client loses connection after TCP error

[AlexanderPilhar]

Describe the bug Device is a M5Stack Core2. My application uses MQTT to communicate with backend infrastructure. It initialises a connection on start-up and subscribes to a single topic. When a message is received the application displays some information on the device. After a random time the MQTT client does not receive any further messages. The application itself keeps running fine. In console logs i can see the following entry:

EXCEPTION error. 
Connection closed
  0: tcp_error_                system/modules/tcp.toit:204:3
  1: TcpSocket_.ensure_state_  system/modules/tcp.toit:77:14
  2: TcpSocket.write           system/modules/tcp.toit:161:14
  3: ClientSocketResource.write system/components/network.toit:129:26
  4: register_network.<lambda> system/components/network.toit:34:12
  5: KernelBroker.register_descriptor_procedure.<lambda> system/kernel/rpc.toit:44:14
  6: RpcRequest_.process.<block> <sdk>/rpc/broker.toit:98:26
  7: RpcRequest_.process       <sdk>/rpc/broker.toit:95:3
  8: RpcRequestQueue_.ensure_processing_task_.<lambda>.<block>.<block> <sdk>/rpc/broker.toit:214:20
  9: RpcRequestQueue_.ensure_processing_task_.<lambda>.<block> <sdk>/rpc/broker.toit:209:9
 10: RpcRequestQueue_.ensure_processing_task_.<lambda> <sdk>/rpc/broker.toit:204:56

To reproduce Steps to reproduce the behavior:

1. Create a MQTT client and connect to a MQTT broker.
2. Subscribe to a topic.
3. Monitor and log messages received via MQTT.
4. Make the network unavailable for a short period of time.
5. Make the network available again.
6. Check console logs for the entry mentioned above (Connection closed).
7. Check console logs for some entry that says: INFO: connected to wifi (ssid) in x seconds.
8. Check the application not being able to receive further MQTT messages.

Expected behavior Some sort of event or notification I can subscribe to in my application so I can reconnect the MQTT client.

Screenshots None

SDK and console version (please complete the following information): Model: esp32-4mb Firmware: v1.6.13

Additional context The device is connected to a Gateway (LTE-M/WiFi) via WiFi. The provider resets the LTE-M connection periodically. The above mentioned log entry sometimes occurs after a LTE-M connection reset. Sometimes it occurs when the WiFi signal is lost. Sometimes it occurs for unknown reason. Sometimes the application itself keeps working fine (just need to reset the device using the reset-button on the M5Stack Core2). Sometimes the application and the device are unresponsive (can't reset or turn off and on again; must flash the device using M5Stack flashing tool 'M5Burner' and then reinstall toit and reclaim the device in order to make the device useable again).

[AlexanderPilhar]

Okay, I just found out something new which makes this issue irrelevant, I think.

The device became completely unresponsive once again (not reacting to touch input or reset-button or on/off-button). I started monitoring the serial output and saw that toit was still working, periodically entering deep sleep. Decided to restart the the gateway. Device became responsive again and working as expected.

Closing this now as there is nothing wrong with toit, I think.

[floitsch]

It's still strange that the program didn't see any notification. I'm working on a new implementation of the MQTT package. Hopefully that will improve the situation.

[AlexanderPilhar]

Maybe because it was able to reconnect to WiFi but still unable to establish a connection to the internet due to some issues with the gateway. After a restart of the gateway the application was working as expected, so things seem to recover correctly after all.

[AlexanderPilhar]

Oh, last night the TCP error occured once more but without the gateway being the reason. This time the MQTT client could not reestablish the connection it seems.

May 12 23:06 stack trace

EXCEPTION error. 
Connection closed
  0: tcp_error_                system/modules/tcp.toit:204:3
  1: TcpSocket_.ensure_state_  system/modules/tcp.toit:77:14
  2: TcpSocket.write           system/modules/tcp.toit:161:14
  3: ClientSocketResource.write system/components/network.toit:129:26
  4: register_network.<lambda> system/components/network.toit:34:12
  5: KernelBroker.register_descriptor_procedure.<lambda> system/kernel/rpc.toit:44:14
  6: RpcRequest_.process.<block> <sdk>/rpc/broker.toit:98:26
  7: RpcRequest_.process       <sdk>/rpc/broker.toit:95:3
  8: RpcRequestQueue_.ensure_processing_task_.<lambda>.<block>.<block> <sdk>/rpc/broker.toit:214:20
  9: RpcRequestQueue_.ensure_processing_task_.<lambda>.<block> <sdk>/rpc/broker.toit:209:9
 10: RpcRequestQueue_.ensure_processing_task_.<lambda> <sdk>/rpc/broker.toit:204:56

May 12 23:06 stack trace

EXCEPTION error. 
Connection closed
  0: tcp_error_                system/modules/tcp.toit:204:3
  1: TcpSocket_.ensure_state_  system/modules/tcp.toit:77:14
  2: TcpSocket.read            system/modules/tcp.toit:153:14
  3: ClientSocketResource.read system/components/network.toit:120:20
  4: register_network.<lambda> system/components/network.toit:32:12
  5: KernelBroker.register_descriptor_procedure.<lambda> system/kernel/rpc.toit:44:14
  6: RpcRequest_.process.<block> <sdk>/rpc/broker.toit:98:26
  7: RpcRequest_.process       <sdk>/rpc/broker.toit:95:3
  8: RpcRequestQueue_.ensure_processing_task_.<lambda>.<block>.<block> <sdk>/rpc/broker.toit:214:20
  9: RpcRequestQueue_.ensure_processing_task_.<lambda>.<block> <sdk>/rpc/broker.toit:209:9
 10: RpcRequestQueue_.ensure_processing_task_.<lambda> <sdk>/rpc/broker.toit:204:56

[floitsch]

The current version of the MQTT package doesn't attempt to reconnect by itself yet. The next version will be able to do that. see https://github.com/toitware/mqtt/issues/9

[floitsch]

v2 of the mqtt package was just released.