[Python] Registered callbacks are still invoked after disconnecting hermes client.

Question

[Python] Registered callbacks are still invoked after disconnecting hermes client.

cpoisson opened this issue 6 years ago · 0 comments

What is the issue
Registered callbacks are still invoked after disconnecting hermes client.
It leads to the following problems:

Invoke actions we don't want to trigger.
Program fault when the registered callback has been destroyed and garbage collected.

Protocol

Create an hermes client object and register a callback on an event
disconnect the client
Create an hermes client object and register an another callback on the same event.
Trigger the event

Observed

Both callbacks are invoked.

Logs

From a test suite using hermes invent listener embedded in a context manager. Exiting the context calls the correct method to disconnect the hermes client.

pytest tests -svv --cache-clear --showlocals --log-level=debug                                      

========================================================================================================= test session starts =========================================================================================================
platform darwin -- Python 3.7.2, pytest-4.4.1, py-1.8.0, pluggy-0.9.0 -- /Users/charles/.virtualenvs/snips-tests/bin/python3
cachedir: .pytest_cache
rootdir: /Users/charles/Workspace-snips/snips-platform-tests
collected 3 items

First tests starts and instantiate two listeners during its execution:

IntentListener-7b17
EndSessionListener-2216

tests/platform/test_dialogue.py::TestPublishEndSession::test_publish_end_session 2019-04-29 13:27:27,532 - DEBUG : SnipsPlatform.start - Snips Platform is starting...
2019-04-29 13:27:27,653 - DEBUG : SnipsAudioServer._start_process - Started - ['snips-audio-server', '--hijack', '0.0.0.0:8888', '--no-mike', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96067).
2019-04-29 13:27:27,786 - DEBUG : SnipsService._start_process - Started - ['snips-hotword', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96068).
2019-04-29 13:27:27,906 - DEBUG : SnipsService._start_process - Started - ['snips-asr', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96071).
2019-04-29 13:27:28,032 - DEBUG : SnipsService._start_process - Started - ['snips-nlu', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96072).
2019-04-29 13:27:28,158 - DEBUG : SnipsDialogue._start_process - Started - ['snips-dialogue', '--sound-feedback-disabled-default', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96073).
2019-04-29 13:27:28,283 - DEBUG : SnipsService._start_process - Started - ['snips-tts', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96074).
2019-04-29 13:27:28,284 - INFO : SnipsPlatform.start - Snips Platform started
2019-04-29 13:27:28,284 - DEBUG : IntentListener-7b17.start - Connecting to localhost:1883
2019-04-29 13:27:28,293 - DEBUG : IntentListener-7b17._subscribe_event - Subscribed to event
2019-04-29 13:27:28,294 - INFO : IntentListener-7b17.start - Listening started
2019-04-29 13:27:28,294 - INFO : SnipsAudioServer.inject_audio - Streaming /Users/charles/Workspace-snips/snips-platform-tests/tests/platform/assets/hey_snips-whats_the_weather_in_tokyo.wav to localhost:8888
2019-04-29 13:27:28,295 - DEBUG : SnipsAudioServer.inject_audio - Stream finished
2019-04-29 13:27:32,798 - DEBUG : IntentListener-7b17._on_event - Event received, queue length: 1
2019-04-29 13:27:32,802 - DEBUG : EndSessionListener-2216.start - Connecting to localhost:1883
2019-04-29 13:27:32,804 - DEBUG : EndSessionListener-2216._subscribe_event - Subscribed to event
2019-04-29 13:27:32,804 - INFO : EndSessionListener-2216.start - Listening started
2019-04-29 13:27:32,805 - DEBUG : EndSessionListener-2216._on_event - Event received, queue length: 1
2019-04-29 13:27:32,905 - DEBUG : EndSessionListener-2216.stop - Stop Listening 
2019-04-29 13:27:33,008 - INFO : EndSessionListener-2216.stop - Listening stopped
2019-04-29 13:27:33,009 - DEBUG : IntentListener-7b17.stop - Stop Listening 
2019-04-29 13:27:33,107 - INFO : IntentListener-7b17.stop - Listening stopped
2019-04-29 13:27:33,107 - DEBUG : SnipsPlatform.terminate - Snips Platform is terminating...
2019-04-29 13:27:33,110 - DEBUG : SnipsAudioServer.terminate - Terminated - ['snips-audio-server', '--hijack', '0.0.0.0:8888', '--no-mike', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96067).
2019-04-29 13:27:33,114 - DEBUG : SnipsService.terminate - Terminated - ['snips-hotword', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96068).
2019-04-29 13:27:33,119 - DEBUG : SnipsService.terminate - Terminated - ['snips-asr', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96071).
2019-04-29 13:27:33,135 - DEBUG : SnipsService.terminate - Terminated - ['snips-nlu', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96072).
2019-04-29 13:27:33,137 - DEBUG : SnipsDialogue.terminate - Terminated - ['snips-dialogue', '--sound-feedback-disabled-default', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96073).
2019-04-29 13:27:33,138 - DEBUG : SnipsService.terminate - Terminated - ['snips-tts', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96074).
2019-04-29 13:27:33,138 - INFO : SnipsPlatform.terminate - Snips Platform terminated
PASSED

Looks good, the second test starts

tests/platform/test_dialogue.py::TestPublishEndSession::test_session_timeout

We force the garbage collection of python objects here.

2019-04-29 13:27:33,149 - DEBUG : EndSessionListener-2216.__del__ - Delete object invoked
2019-04-29 13:27:33,150 - DEBUG : IntentListener-7b17.__del__ - Delete object invoked

The previous listeners are deleted by the garbage collector.

2019-04-29 13:27:33,150 - DEBUG : SnipsPlatform.start - Snips Platform is starting...
2019-04-29 13:27:33,283 - DEBUG : SnipsAudioServer._start_process - Started - ['snips-audio-server', '--hijack', '0.0.0.0:8888', '--no-mike', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96075).
2019-04-29 13:27:33,415 - DEBUG : SnipsService._start_process - Started - ['snips-hotword', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96076).
2019-04-29 13:27:33,537 - DEBUG : SnipsService._start_process - Started - ['snips-asr', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96077).
2019-04-29 13:27:33,662 - DEBUG : SnipsService._start_process - Started - ['snips-nlu', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96078).
2019-04-29 13:27:33,785 - DEBUG : SnipsDialogue._start_process - Started - ['snips-dialogue', '--sound-feedback-disabled-default', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96079).
2019-04-29 13:27:33,908 - DEBUG : SnipsService._start_process - Started - ['snips-tts', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96080).
2019-04-29 13:27:33,908 - INFO : SnipsPlatform.start - Snips Platform started
2019-04-29 13:27:33,908 - DEBUG : IntentListener-4de8.start - Connecting to localhost:1883
2019-04-29 13:27:33,909 - DEBUG : IntentListener-4de8._subscribe_event - Subscribed to event
2019-04-29 13:27:33,910 - INFO : IntentListener-4de8.start - Listening started
2019-04-29 13:27:33,910 - INFO : SnipsAudioServer.inject_audio - Streaming /Users/charles/Workspace-snips/snips-platform-tests/tests/platform/assets/hey_snips-whats_the_weather_in_tokyo.wav to localhost:8888
2019-04-29 13:27:33,911 - DEBUG : SnipsAudioServer.inject_audio - Stream finished
[1]    96066 illegal hardware instruction (core dumped)  pytest tests -svv --cache-clear --showlocals --log-level=debug

Here we crash. A method in a previously destroyed object was called.

The following logs shows what happen when the garbage collection is not forced.

tests/platform/test_dialogue.py::TestPublishEndSession::test_session_timeout 2019-04-29 13:37:14,449 - DEBUG : SnipsPlatform.start - Snips Platform is starting...
2019-04-29 13:37:14,581 - DEBUG : SnipsAudioServer._start_process - Started - ['snips-audio-server', '--hijack', '0.0.0.0:8888', '--no-mike', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96161).
2019-04-29 13:37:14,713 - DEBUG : SnipsService._start_process - Started - ['snips-hotword', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96162).
2019-04-29 13:37:14,841 - DEBUG : SnipsService._start_process - Started - ['snips-asr', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96163).
2019-04-29 13:37:14,968 - DEBUG : SnipsService._start_process - Started - ['snips-nlu', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96164).
2019-04-29 13:37:15,093 - DEBUG : SnipsDialogue._start_process - Started - ['snips-dialogue', '--sound-feedback-disabled-default', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96165).
2019-04-29 13:37:15,215 - DEBUG : SnipsService._start_process - Started - ['snips-tts', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96166).
2019-04-29 13:37:15,215 - INFO : SnipsPlatform.start - Snips Platform started
2019-04-29 13:37:15,215 - DEBUG : IntentListener-cf64.start - Connecting to localhost:1883
2019-04-29 13:37:15,217 - DEBUG : IntentListener-cf64._subscribe_event - Subscribed to event
2019-04-29 13:37:15,217 - INFO : IntentListener-cf64.start - Listening started
2019-04-29 13:37:15,217 - INFO : SnipsAudioServer.inject_audio - Streaming /Users/charles/Workspace-snips/snips-platform-tests/tests/platform/assets/hey_snips-whats_the_weather_in_tokyo.wav to localhost:8888
2019-04-29 13:37:15,218 - DEBUG : SnipsAudioServer.inject_audio - Stream finished

2019-04-29 13:37:19,671 - DEBUG : IntentListener-eeca._on_event - Event received by an inactive listener. Ignoring...

Hum, this listener was not instantiated in this tests, the method call backed as not been garbage collected yet.

2019-04-29 13:37:19,672 - DEBUG : IntentListener-cf64._on_event - Event received, queue length: 1
2019-04-29 13:37:19,733 - DEBUG : EndSessionListener-dfc6.start - Connecting to localhost:1883
2019-04-29 13:37:19,735 - DEBUG : EndSessionListener-dfc6._subscribe_event - Subscribed to event
2019-04-29 13:37:19,735 - INFO : EndSessionListener-dfc6.start - Listening started
2019-04-29 13:37:25,041 - DEBUG : EndSessionListener-dfc6._on_event - Event received, queue length: 1

2019-04-29 13:37:25,042 - DEBUG : EndSessionListener-ea75._on_event - Event received by an inactive listener. Ignoring...

This listener too

2019-04-29 13:37:25,073 - DEBUG : EndSessionListener-dfc6.stop - Stop Listening 
2019-04-29 13:37:25,177 - INFO : EndSessionListener-dfc6.stop - Listening stopped
2019-04-29 13:37:25,177 - DEBUG : IntentListener-cf64.stop - Stop Listening 
2019-04-29 13:37:25,260 - INFO : IntentListener-cf64.stop - Listening stopped
2019-04-29 13:37:25,260 - DEBUG : SnipsPlatform.terminate - Snips Platform is terminating...
2019-04-29 13:37:25,263 - DEBUG : SnipsAudioServer.terminate - Terminated - ['snips-audio-server', '--hijack', '0.0.0.0:8888', '--no-mike', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96161).
2019-04-29 13:37:25,267 - DEBUG : SnipsService.terminate - Terminated - ['snips-hotword', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96162).
2019-04-29 13:37:25,271 - DEBUG : SnipsService.terminate - Terminated - ['snips-asr', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96163).
2019-04-29 13:37:25,287 - DEBUG : SnipsService.terminate - Terminated - ['snips-nlu', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96164).
2019-04-29 13:37:25,289 - DEBUG : SnipsDialogue.terminate - Terminated - ['snips-dialogue', '--sound-feedback-disabled-default', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96165).
2019-04-29 13:37:25,291 - DEBUG : SnipsService.terminate - Terminated - ['snips-tts', '--assistant', '/var/folders/1g/0sv9v9pn5mb3q1n6szct90t00000gn/T/proj_WEATHER-DEMO-EN/assistant'] (pid=96166).
2019-04-29 13:37:25,291 - INFO : SnipsPlatform.terminate - Snips Platform terminated
PASSED