search

JarbasHiveMind / HiveMind-voice-sat

OpenVoiceOS Voice Satellite
Apache License 2.0
17 stars 11 forks source link

PHAL doesn't connect to the message bus. #32

Closed goldyfruit closed 1 year ago

goldyfruit commented 1 year ago 
2023-09-05 13:02:05.898 - OVOS - ovos_plugin_manager.ocp:load:54 - INFO - Loaded OCP plugin: ovos-ocp-files-plugin
2023-09-05 13:02:06.345 - OVOS - ovos_plugin_manager.ocp:load:54 - INFO - Loaded OCP plugin: ovos-ocp-m3u-plugin
2023-09-05 13:02:06.790 - OVOS - ovos_plugin_manager.ocp:load:54 - INFO - Loaded OCP plugin: ovos-ocp-news-plugin
2023-09-05 13:02:07.234 - OVOS - ovos_plugin_manager.ocp:load:54 - INFO - Loaded OCP plugin: ovos-ocp-rss-plugin
2023-09-05 13:02:08.306 - OVOS - hivemind_bus_client.client:connect:116 - INFO - Connecting to Hivemind
2023-09-05 13:02:08.434 - OVOS - hivemind_bus_client.protocol:bind:99 - INFO - Initializing HiveMindSlaveInternalProtocol
2023-09-05 13:02:08.443 - OVOS - hivemind_bus_client.protocol:bind:102 - INFO - registering protocol handlers
2023-09-05 13:02:13.476 - OVOS - hivemind_bus_client.protocol:start_handshake:139 - INFO - hivemind does not support binarization protocol
2023-09-05 13:02:13.844 - OVOS - hivemind_bus_client.protocol:handle_handshake:169 - INFO - HANDSHAKE: {'envelope': '7073494679785072afb03ffa3a1b3c1b3c353c0fb1b2c76e', 'binarize': False}
2023-09-05 13:02:13.852 - OVOS - hivemind_bus_client.protocol:receive_handshake:152 - INFO - Received password envelope
2023-09-05 13:02:14.373 - OVOS - ovos_audio.service:__init__:49 - INFO - Starting Audio Service
2023-09-05 13:02:14.382 - OVOS - ovos_audio.service:on_started:31 - INFO - Audio service started.
2023-09-05 13:02:14.435 - OVOS - ovos_config.utils:__init__:21 - WARNING - Deprecation version=0.1.0. Caller=ovos_config.config:283. Import from ovos_utils.file_utils directly
2023-09-05 13:02:14.691 - OVOS - ovos_audio.service:_maybe_reload_tts:291 - INFO - (re)loading TTS engine
2023-09-05 13:02:14.898 - OVOS - ovos_utils.configuration:get_xdg_base - WARNING - Deprecation version=0.1.0. Caller=ovos_tts_plugin_mimic:93. configuration moved to the `ovos_config` package.
2023-09-05 13:02:15.001 - OVOS - ovos_utils.configuration:read_mycroft_config - WARNING - Deprecation version=0.1.0. Caller=ovos_tts_plugin_mimic:106. configuration moved to the `ovos_config` package.
2023-09-05 13:02:15.027 - OVOS - ovos_plugin_manager.tts:create:197 - INFO - Found plugin ovos-tts-plugin-server
2023-09-05 13:02:15.054 - OVOS - ovos_utils.file_utils:resolve_resource_file:153 - WARNING - Deprecation version=0.1.0. Caller=ovos_plugin_manager.templates.tts:526. Expected a dict config and got None.
2023-09-05 13:02:20.068 - OVOS - ovos_plugin_manager.tts:create:200 - INFO - Loaded plugin ovos-tts-plugin-server
2023-09-05 13:02:20.075 - OVOS - ovos_audio.service:_maybe_reload_tts:310 - INFO - (re)loading fallback TTS engine
2023-09-05 13:02:20.159 - OVOS - ovos_plugin_manager.tts:create:197 - INFO - Found plugin ovos-tts-plugin-mimic3-server
2023-09-05 13:02:20.175 - OVOS - ovos_utils.file_utils:resolve_resource_file:153 - WARNING - Deprecation version=0.1.0. Caller=ovos_plugin_manager.templates.tts:526. Expected a dict config and got None.
2023-09-05 13:02:20.467 - OVOS - ovos_plugin_manager.tts:create:200 - INFO - Loaded plugin ovos-tts-plugin-mimic3-server
2023-09-05 13:02:20.547 - OVOS - ovos_audio.audio:load_services:94 - INFO - Loading audio service plugin: ovos_audio_simple
2023-09-05 13:02:20.553 - OVOS - ovos_audio.audio:find_default:69 - WARNING - default backend set to OCP, but OCP is disabled
2023-09-05 13:02:20.559 - OVOS - ovos_audio.audio:find_default:71 - INFO - Finding default audio backend...
2023-09-05 13:02:20.565 - OVOS - ovos_audio.audio:find_default:79 - INFO - no default found
2023-09-05 13:02:20.657 - OVOS - ovos_audio.service:on_alive:27 - INFO - Audio service is alive.
2023-09-05 13:02:20.666 - OVOS - ovos_dinkum_listener.service:__init__:123 - INFO - Starting Voice Service
2023-09-05 13:02:20.672 - OVOS - hivemind_voice_satellite.service:on_alive:15 - INFO - HiveMind Voice Satellite alive.
2023-09-05 13:02:20.678 - OVOS - ovos_dinkum_listener.service:_before_start:293 - INFO - Starting service...
2023-09-05 13:02:20.765 - OVOS - ovos_audio.service:run:238 - WARNING - No audio backends loaded! Audio playback is not available
2023-09-05 13:02:20.781 - OVOS - ovos_audio.service:run:240 - INFO - Running audio service in TTS only mode
2023-09-05 13:02:20.786 - OVOS - ovos_audio.service:on_ready:23 - INFO - Audio service is ready.
2023-09-05 13:02:22.894 - OVOS - hivemind_voice_satellite.service:on_alive:15 - INFO - HiveMind Voice Satellite alive.
2023-09-05 13:02:22.898 - OVOS - ovos_dinkum_listener.service:_before_start:293 - INFO - Starting service...
2023-09-05 13:02:22.959 - OVOS - ovos_dinkum_listener.voice_loop.hotwords:load_hotword_engines:108 - INFO - creating hotword engines
2023-09-05 13:02:22.993 - OVOS - ovos_workshop.skills.mycroft_skill:__call__:67 - WARNING - skill_id should be a kwarg, please update PHAL
2023-09-05 13:02:22.998 - OVOS - ovos_plugin_manager.wakewords:load_module:165 - INFO - Loading "hey_mycroft" wake word via ovos-ww-plugin-precise-lite with config: {'module': 'ovos-ww-plugin-precise-lite', 'model': 'https://github.com/OpenVoiceOS/precise-lite-models/raw/master/wakewords/en/hey_mycroft.tflite', 'expected_duration': 3, 'trigger_level': 3, 'sensitivity': 0.5, 'listen': True, 'fallback_ww': 'hey_mycroft_precise'}
2023-09-05 13:02:23.006 - OVOS - ovos_workshop.skills.mycroft_skill:__call__:81 - WARNING - skill initialized without bus!! this is legacy behaviour and requires you to call skill.bind(bus) or skill._startup(skill_id, bus)
bus will be required starting on ovos-core 0.1.0
2023-09-05 13:02:23.079 - OVOS - ovos_bus_client.client.client:on_error:110 - WARNING - Connection Refused. Is Messagebus Service running?
2023-09-05 13:02:23.100 - OVOS - ovos_bus_client.client.client:on_error:119 - ERROR - Exception closing websocket at ws://0.0.0.0:8181/core: [Errno 111] Connection refused
2023-09-05 13:02:23.124 - OVOS - ovos_bus_client.client.client:on_error:121 - WARNING - Message Bus Client will reconnect in 5.0 seconds.
2023-09-05 13:02:23.131 - OVOS - ovos_workshop.skills.base:is_classic_core:85 - WARNING - Deprecation version=0.1.0. Caller=ovos_workshop.skills.mycroft_skill:168. Support for `mycroft_core` will be deprecated
2023-09-05 13:02:23.322 - OVOS - ovos_plugin_manager.wakewords:load_module:172 - INFO - Loaded the Wake Word hey_mycroft with module ovos-ww-plugin-precise-lite
INFO: Created TensorFlow Lite XNNPACK delegate for CPU.
2023-09-05 13:02:23.347 - OVOS - ovos_dinkum_listener.voice_loop.hotwords:load_hotword_engines:158 - INFO - Loading hotword: hey_mycroft with engine: <ovos_ww_plugin_precise_lite.PreciseLiteHotwordPlugin object at 0x7f55be5550>
2023-09-05 13:02:23.356 - OVOS - ovos_dinkum_listener.voice_loop.hotwords:load_hotword_engines:189 - WARNING - No wakeup words loaded
2023-09-05 13:02:23.363 - OVOS - ovos_dinkum_listener.voice_loop.hotwords:load_hotword_engines:191 - WARNING - No stop words loaded
2023-09-05 13:02:23.382 - OVOS - ovos_workshop.skills.base:is_classic_core:85 - WARNING - Deprecation version=0.1.0. Caller=ovos_workshop.skills.ovos:39. Support for `mycroft_core` will be deprecated
2023-09-05 13:02:23.385 - OVOS - ovos_dinkum_listener.voice_loop.voice_loop:start:166 - INFO - Listening mode: ListeningMode.WAKEWORD
2023-09-05 13:02:23.411 - OVOS - ovos_utils.gui:get_ui_directories:94 - INFO - Checking for legacy UI directories
2023-09-05 13:02:23.478 - OVOS - ovos_workshop.skills.base:is_classic_core:85 - WARNING - Deprecation version=0.1.0. Caller=ovos_workshop.skills.mycroft_skill:148. Support for `mycroft_core` will be deprecated
2023-09-05 13:02:23.481 - ovos.PHAL - WARNING - Tried to initialize ovos.PHAL multiple times, ignoring
2023-09-05 13:02:23.493 - OVOS - ovos_PHAL.service:on_started:26 - INFO - PHAL is started
2023-09-05 13:02:23.579 - OVOS - hivemind_voice_satellite.service:on_started:11 - INFO - HiveMind Voice Satellite started.
2023-09-05 13:02:23.583 - OVOS - hivemind_voice_satellite.service:on_started:11 - INFO - HiveMind Voice Satellite started.
2023-09-05 13:02:23.597 - OVOS - hivemind_voice_satellite.service:on_ready:7 - INFO - HiveMind Voice Satellite is ready.
2023-09-05 13:02:23.607 - OVOS - ovos_dinkum_listener.service:run:268 - INFO - Service ready
2023-09-05 13:02:23.618 - OVOS - ovos_dinkum_listener.voice_loop.voice_loop:run:191 - INFO - Starting loop in mode: ListeningMode.WAKEWORD
2023-09-05 13:02:23.662 - OVOS - ovos_PHAL.service:on_ready:10 - INFO - PHAL is ready.
2023-09-05 13:02:28.135 - OVOS - ovos_bus_client.client.client:on_error:110 - WARNING - Connection Refused. Is Messagebus Service running?
2023-09-05 13:02:28.144 - OVOS - ovos_bus_client.client.client:on_error:119 - ERROR - Exception closing websocket at ws://0.0.0.0:8181/core: [Errno 111] Connection refused
2023-09-05 13:02:28.151 - OVOS - ovos_bus_client.client.client:on_error:121 - WARNING - Message Bus Client will reconnect in 10.0 seconds.
2023-09-05 13:02:34.752 - OVOS - ovos_dinkum_listener.voice_loop.voice_loop:run:219 - INFO - Wakeword detected
2023-09-05 13:02:35.898 - OVOS - ovos_dinkum_listener.voice_loop.voice_loop:run:249 - INFO - speech finished
2023-09-05 13:02:36.369 - OVOS - ovos_dinkum_listener.voice_loop.voice_loop:_after_cmd:657 - INFO - transcribed: "To what time is it?"
2023-09-05 13:02:36.693 - OVOS - hivemind_bus_client.protocol:handle_bus:196 - INFO - BUS: skill-ovos-date-time.openvoiceos:handle_query_time
2023-09-05 13:02:36.712 - OVOS - hivemind_bus_client.protocol:handle_bus:196 - INFO - BUS: mycroft.skill.handler.start
2023-09-05 13:02:36.767 - OVOS - hivemind_bus_client.protocol:handle_bus:196 - INFO - BUS: enclosure.active_skill
2023-09-05 13:02:36.793 - OVOS - ovos_audio.service:execute_tts:322 - INFO - Speak: It is one oh two
2023-09-05 13:02:37.064 - OVOS - ovos_audio.utils:report_timing:63 - ERROR - Failed to upload metrics
2023-09-05 13:02:37.084 - OVOS - hivemind_bus_client.protocol:handle_bus:196 - INFO - BUS: speak
2023-09-05 13:02:37.120 - OVOS - hivemind_bus_client.protocol:handle_bus:196 - INFO - BUS: enclosure.mouth.events.deactivate
2023-09-05 13:02:37.154 - OVOS - hivemind_bus_client.protocol:handle_bus:196 - INFO - BUS: enclosure.mouth.display
2023-09-05 13:02:37.192 - OVOS - hivemind_bus_client.protocol:handle_bus:196 - INFO - BUS: enclosure.mouth.display
2023-09-05 13:02:37.224 - OVOS - hivemind_bus_client.protocol:handle_bus:196 - INFO - BUS: enclosure.mouth.display
2023-09-05 13:02:37.255 - OVOS - hivemind_bus_client.protocol:handle_bus:196 - INFO - BUS: enclosure.mouth.display
2023-09-05 13:02:37.294 - OVOS - hivemind_bus_client.protocol:handle_bus:196 - INFO - BUS: enclosure.mouth.display
2023-09-05 13:02:37.327 - OVOS - hivemind_bus_client.protocol:handle_bus:196 - INFO - BUS: enclosure.mouth.display
Playing WAVE '/home/ovos/.cache/mycroft/OVOSServerTTS/default/en-us/09a291f749a395b326daccc0d8218325.wav' : Signed 16 bit Little Endian, Rate 22050 Hz, Mono
2023-09-05 13:02:38.164 - OVOS - ovos_bus_client.client.client:on_error:110 - WARNING - Connection Refused. Is Messagebus Service running?
2023-09-05 13:02:38.174 - OVOS - ovos_bus_client.client.client:on_error:119 - ERROR - Exception closing websocket at ws://0.0.0.0:8181/core: [Errno 111] Connection refused
2023-09-05 13:02:38.184 - OVOS - ovos_bus_client.client.client:on_error:121 - WARNING - Message Bus Client will reconnect in 20.0 seconds.
2023-09-05 13:02:40.068 - OVOS - hivemind_bus_client.protocol:handle_bus:196 - INFO - BUS: enclosure.mouth.display
2023-09-05 13:02:45.095 - OVOS - hivemind_bus_client.protocol:handle_bus:196 - INFO - BUS: enclosure.mouth.reset
2023-09-05 13:02:45.113 - OVOS - hivemind_bus_client.protocol:handle_bus:196 - INFO - BUS: enclosure.mouth.events.activate
2023-09-05 13:02:45.131 - OVOS - hivemind_bus_client.protocol:handle_bus:196 - INFO - BUS: mycroft.skill.handler.complete
2023-09-05 13:02:58.197 - OVOS - ovos_bus_client.client.client:on_error:110 - WARNING - Connection Refused. Is Messagebus Service running?
2023-09-05 13:02:58.211 - OVOS - ovos_bus_client.client.client:on_error:119 - ERROR - Exception closing websocket at ws://0.0.0.0:8181/core: [Errno 111] Connection refused
2023-09-05 13:02:58.225 - OVOS - ovos_bus_client.client.client:on_error:121 - WARNING - Message Bus Client will reconnect in 40.0 seconds.
Ramblurr commented 1 year ago

Ok I think I traced this issue down. I added a traceback.print_stack() statement in the constructor of the MessageBusClient

HiveMind-voice-sat - ovos_PHAL.service:on_started:26 - INFO - PHAL is started
HiveMind-voice-sat - ovos_workshop.skills.mycroft_skill:__call__:81 - WARNING - skill initialized without bus!! this is legacy behaviour and requires you to call skill.bind(bus) or skill._startup(skill_id, bus)
bus will be required starting on ovos-core 0.1.0
2023-09-12 17:47:20.070 - HiveMind-voice-sat - ovos_bus_client.client.client:__init__:47 - INFO - XXX MessageBusClient ctor XXX
  File "/home/ovos/.venv/bin/hivemind-voice-sat", line 8, in <module>
    sys.exit(connect())
  File "/home/ovos/.venv/lib/python3.11/site-packages/click/core.py", line 1157, in __call__
    return self.main(*args, **kwargs)
  File "/home/ovos/.venv/lib/python3.11/site-packages/click/core.py", line 1078, in main
    rv = self.invoke(ctx)
  File "/home/ovos/.venv/lib/python3.11/site-packages/click/core.py", line 1434, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/home/ovos/.venv/lib/python3.11/site-packages/click/core.py", line 783, in invoke
    return __callback(*args, **kwargs)
  File "/home/ovos/.venv/lib/python3.11/site-packages/hivemind_voice_satellite/__main__.py", line 44, in connect
    phal = PHAL(bus=bus)
  File "/home/ovos/.venv/lib/python3.11/site-packages/ovos_workshop/skills/mycroft_skill.py", line 85, in __call__
    return super().__call__(*args, **kwargs)
  File "/home/ovos/.venv/lib/python3.11/site-packages/ovos_PHAL/service.py", line 43, in __init__
    bus = MessageBusClient()
  File "/home/ovos/.venv/lib/python3.11/site-packages/ovos_bus_client/client/client.py", line 48, in __init__
    traceback.print_stack()

This shows that the bus is being stripped in the constructor inheritance chain and then being re-initialized after the super chain is finished

class PHAL(OVOSAbstractApplication):
  def __init__(self, config=None, bus=None,
                 on_ready=on_ready, on_error=on_error,
                 on_stopping=on_stopping, on_started=on_started, on_alive=on_alive,
                 watchdog=lambda: None, skill_id="ovos.PHAL", **kwargs):
        super().__init__(skill_id=skill_id, bus=bus)

class OVOSAbstractApplication(OVOSSkill):
    def __init__(self, skill_id, bus=None, resources_dir=None,
                 lang=None, settings=None, gui=None, enable_settings_manager=False):
        super().__init__(bus=bus, gui=gui, resources_dir=resources_dir,
                         enable_settings_manager=enable_settings_manager)

class OVOSSkill(MycroftSkill):
    def __init__(self, *args, **kwargs):
        super(OVOSSkill, self).__init__(*args, **kwargs)

class MycroftSkill(BaseSkill, metaclass=_SkillMetaclass):
    def __init__(self, name=None, bus=None, use_settings=True, *args, **kwargs):
        super().__init__(name=name, bus=bus, *args, **kwargs)

class _SkillMetaclass(ABCMeta):
    def __call__(cls, *args, **kwargs):

Also the presence of the warning emitted here reinforces my idea.

My guess is the problem is at MycroftSkill layer?