wialon/gmqtt

Client still running after disconnect() in 0.6.9

Closed this issue · 1 comments

lbt commented

Linux Python 3.7.3 mqtt 0.6.9

This is normal production setup that runs well.
The problem occurs when trying to shutdown cleanly

Here is a log:

gmqtt.mqtt.handler : [RECEIVED PUBREC FOR] 32
gmqtt.mqtt.utils : FREE MID: 32
gmqtt.client : [REMOVE MESSAGE] 32
gmqtt.mqtt.handler : [CMD 0x50] b'\x00!'
gmqtt.mqtt.handler : [RECEIVED PUBREC FOR] 33
gmqtt.mqtt.utils : FREE MID: 33
gmqtt.client : [REMOVE MESSAGE] 33
gmqtt.mqtt.handler : [CMD 0x70] b'\x00 '
gmqtt.mqtt.handler : [CMD 0x70] b'\x00!'
^Csensor2mqtt.SensorController : Client received signal asking to exit

Ctrl-C hit at this point and the cleanup code is run in my finish()
First my callbacks to handle any ongoing mqtt activity if there was any.

sensor2mqtt.SensorController : Stop received, cleaning up
sensor2mqtt.DS18B20s : DS18B20s exiting cleanly
sensor2mqtt.PondSkimmer : Callback cancelled. Exiting

Still in finish() and "await client.disconnect()" is called

gmqtt.mqtt.protocol : [CONN CLOSE NORMALLY]
gmqtt.mqtt.handler : [CMD 0xe0] b''

My on_disconnect callback is called:

sensor2mqtt.SensorController : Disconnected

and back in finish() this is the debug line after the await client.disconnect() so the client is now supposed to be shutdown

sensor2mqtt.SensorController : client disconnected
__main__ : All done. Exiting

So now the main task is done and exiting ... lets see what task.print_stack() for each asyncio.all_tasks() has to say:

Stack for <Task pending coro=<main() running at /home/pi/sensor2mqtt/sensor2mqtt.py:85> cb=[_run_until_complete_cb() at /usr/lib/python3.7/asyncio/base_events.py:158]> (most recent call last):
  File "/home/pi/sensor2mqtt/sensor2mqtt.py", line 88, in <module>
    asyncio.run(main())
  File "/usr/lib/python3.7/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/usr/lib/python3.7/asyncio/base_events.py", line 571, in run_until_complete
    self.run_forever()
  File "/usr/lib/python3.7/asyncio/base_events.py", line 539, in run_forever
    self._run_once()
  File "/usr/lib/python3.7/asyncio/base_events.py", line 1775, in _run_once
    handle._run()
  File "/usr/lib/python3.7/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
  File "/home/pi/sensor2mqtt/sensor2mqtt.py", line 85, in main
    task.print_stack()
Stack for <Task pending coro=<Client.reconnect() running at /home/pi/venv-heating/lib/python3.7/site-packages/gmqtt/client.py:192> cb=[MqttPackageHandler._handle_exception_in_future()]> (most recent call last):
  File "/home/pi/venv-heating/lib/python3.7/site-packages/gmqtt/client.py", line 192, in reconnect
    async def reconnect(self, delay=False):

The asyncio.run(main()) is still there but the __main__ : All done. Exiting is the last line of main() so it should now exit.
But the client is still running so it goes on to print:

gmqtt.client : [QoS query IS EMPTY]
gmqtt.client : [QoS query IS EMPTY]
gmqtt.client : [QoS query IS EMPTY]

I think there is an unhandled exception going on in cb[MqttPackageHandler._handle_exception_in_future()]> but I'm not sure how to debug that yet.

This is my finish()

   async def finish(self):
        # This will wait until the client is signalled
        logger.debug(f"Waiting for stop event")
        await self.stop_event.wait()
        logger.debug(f"Stop received, cleaning up")
        for cb in self.cleanup_callbacks:
            res = cb()
            if inspect.isawaitable(res):
                await res

        await self.mqtt.disconnect()  # Disconnect after any last messages sent
        logger.debug(f"client disconnected")

and the end of my main()

    await sensors.finish()
    logger.warning(f"All done. Exiting")
    for task in asyncio.all_tasks():
        task.print_stack()


asyncio.run(main())
lbt commented

My bad.

I imported a long-lived django app and inside that app it run another mqtt client which publishes on save() and that wasn't being shutdown.

My logs had:

gmqtt.mqtt.protocol : [CONNECTION MADE]
gmqtt.mqtt.handler : [CMD 0x20] b'\x00\x00'

and later

gmqtt.mqtt.protocol : [CONNECTION MADE]
gmqtt.mqtt.handler : [CMD 0x20] b'\x00\x00'

Sorry for the noise.

  • 🚀1