External MQTT Timeout Issue with Microphone

I’m trying to configure Rhasspy to use an external MQTT broker. I have a working external MQTT broker using TLS and I can do a simple mosquitto_sub, mosquitto_pub pair with TLS and see communication. However, I can’t seem to get the audio input service to recognize my microphone and instead get timeout errors.

I know the user rhasspy is running as can see the microphone because I can see the target mic (ReSpeaker 4 Mic Array) using arecord -l:

$ arecord -l
**** List of CAPTURE Hardware Devices ****
card 1: ArrayUAC10 [ReSpeaker 4 Mic Array (UAC1.0)], device 0: USB Audio [USB Audio]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 2: PCH [HDA Intel PCH], device 0: ALC892 Analog [ALC892 Analog]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 2: PCH [HDA Intel PCH], device 2: ALC892 Alt Analog [ALC892 Alt Analog]
  Subdevices: 1/1
  Subdevice #0: subdevice #0

And I have successfully recorded audio with arecord.

For simplicity with rhasspy I’m using a minimal profile which just connects to the MQTT broker and sets up a microphone using arecord:

{
    "microphone": {
        "system": "arecord"
    },
    "mqtt": {
        "enabled": "true",
        "host": "192.168.0.15",
        "port": "8883",
        "site_id": "server",
        "tls": {
            "ca_certs": "/etc/mosquitto/certs/mqtt-server.crt",
            "certfile": "${RHASSPY_PROFILE_DIR}/certs/rhasspy-client.crt",
            "enabled": true,
            "keyfile": "${RHASSPY_PROFILE_DIR}/certs/rhasspy-client.key"
        }
    }
}

These are the logs when Rhasspy starts:

Starting up...
DEBUG:rhasspysupervisor:Namespace(debug=True, docker_compose='', local_mqtt_port=12183, mosquitto_path='mosquitto', profile='en', supervisord_conf='supervisord.conf', system_profiles=None, user_profiles=PosixPath('/home/homeassistant/.config/rhasspy/profiles'))
DEBUG:rhasspysupervisor:Loading profile en (user=/home/homeassistant/.config/rhasspy/profiles, system=None)
DEBUG:rhasspyprofile.profile:Loading /usr/lib/rhasspy/rhasspy-profile/rhasspyprofile/profiles/en/profile.json
DEBUG:rhasspyprofile.profile:Loading /home/homeassistant/.config/rhasspy/profiles/en/profile.json
DEBUG:rhasspysupervisor:Generating supervisord conf
DEBUG:rhasspysupervisor:Speakers disabled (system=dummy)
DEBUG:rhasspysupervisor:Wake word disabled (system=dummy)
DEBUG:rhasspysupervisor:Speech to text disabled (system=dummy)
DEBUG:rhasspysupervisor:Intent recognition disabled (system=dummy)
DEBUG:rhasspysupervisor:Intent handling disabled (system=dummy)
DEBUG:rhasspysupervisor:Text to speech disabled (system=dummy)
DEBUG:rhasspysupervisor:Dialogue disabled (system=dummy)
DEBUG:rhasspysupervisor:Wrote /home/homeassistant/.config/rhasspy/profiles/en/supervisord.conf
Starting services...
2022-06-23 01:35:55,168 INFO supervisord started with pid 82138
2022-06-23 01:35:56,170 INFO spawnerr: unknown error making dispatchers for 'microphone': EACCES
2022-06-23 01:35:57,172 INFO spawnerr: unknown error making dispatchers for 'microphone': EACCES
[DEBUG:2022-06-23 01:35:57,369] rhasspyserver_hermes: Namespace(certfile=None, host='0.0.0.0', keyfile=None, local_mqtt_port=12183, log_format='[%(levelname)s:%(asctime)s] %(name)s: %(message)s', log_level='DEBUG', mqtt_host=None, mqtt_password=None, mqtt_port=None, mqtt_username=None, port=12101, profile='en', set=[], system_profiles=None, url_root='', user_profiles='/home/homeassistant/.config/rhasspy/profiles', web_dir='/usr/lib/rhasspy/rhasspy-server-hermes/web')
[DEBUG:2022-06-23 01:35:57,441] rhasspyprofile.profile: Loading /usr/lib/rhasspy/rhasspy-profile/rhasspyprofile/profiles/en/profile.json
[DEBUG:2022-06-23 01:35:57,442] rhasspyprofile.profile: Loading /home/homeassistant/.config/rhasspy/profiles/en/profile.json
[DEBUG:2022-06-23 01:35:57,442] rhasspyprofile.profile: Loading default profile settings from /usr/lib/rhasspy/rhasspy-profile/rhasspyprofile/profiles/defaults.json
[DEBUG:2022-06-23 01:35:57,443] rhasspyserver_hermes: Loading MQTT TLS settings
[DEBUG:2022-06-23 01:35:57,443] rhasspyserver_hermes: MQTT TLS enabled: {'ca_certs': '/etc/mosquitto/certs/mqtt-server.crt', 'certfile': '/home/homeassistant/.config/rhasspy/profiles/en/certs/rhasspy-client.crt', 'keyfile': '/home/homeassistant/.config/rhasspy/profiles/en/certs/rhasspy-client.key', 'cert_reqs': <VerifyMode.CERT_REQUIRED: 2>, 'tls_version': 2, 'ciphers': None}
[DEBUG:2022-06-23 01:35:57,444] rhasspyserver_hermes: Starting core
[DEBUG:2022-06-23 01:35:57,444] rhasspyserver_hermes: Connecting to 192.168.0.15:8883 (retries: 0/10)
[DEBUG:2022-06-23 01:35:57,453] rhasspyserver_hermes: Connected to MQTT broker
[DEBUG:2022-06-23 01:35:57,453] rhasspyserver_hermes: Subscribed to hermes/hotword/+/detected
[DEBUG:2022-06-23 01:35:57,453] rhasspyserver_hermes: Subscribed to hermes/asr/textCaptured
[DEBUG:2022-06-23 01:35:57,453] rhasspyserver_hermes: Subscribed to hermes/intent/#
[DEBUG:2022-06-23 01:35:57,453] rhasspyserver_hermes: Subscribed to hermes/nlu/intentNotRecognized
[DEBUG:2022-06-23 01:35:57,453] rhasspyserver_hermes: Subscribed to rhasspy/asr/server/+/audioCaptured
[DEBUG:2022-06-23 01:35:57,453] rhasspyserver_hermes: Subscribed to hermes/audioServer/server/audioSummary
[DEBUG:2022-06-23 01:35:57,453] rhasspyserver_hermes: Subscribed to rhasspy/asr/server/+/audioCaptured
[DEBUG:2022-06-23 01:35:57,453] rhasspyserver_hermes: Subscribed to hermes/intent/#
[DEBUG:2022-06-23 01:35:57,454] rhasspyserver_hermes: Subscribed to hermes/hotword/+/detected
[DEBUG:2022-06-23 01:35:57,454] rhasspyserver_hermes: Subscribed to hermes/asr/textCaptured
[DEBUG:2022-06-23 01:35:57,454] rhasspyserver_hermes: Subscribed to hermes/nlu/intentNotRecognized
[DEBUG:2022-06-23 01:35:57,454] rhasspyserver_hermes: Subscribed to hermes/audioServer/server/audioSummary
[INFO:2022-06-23 01:35:57,454] rhasspyserver_hermes: Started
[DEBUG:2022-06-23 01:35:57,454] rhasspyserver_hermes: Starting web server at http://0.0.0.0:12101
Running on 0.0.0.0:12101 over http (CTRL + C to quit)
2022-06-23 01:35:59,177 INFO spawnerr: unknown error making dispatchers for 'microphone': EACCES
2022-06-23 01:36:02,184 INFO spawnerr: unknown error making dispatchers for 'microphone': EACCES
2022-06-23 01:36:02,185 INFO gave up: microphone entered FATAL state, too many start retries too quickly

As you can see on line 28, rhasspy successfully connects to my MQTT broker. However, the microphone fails with an EACCES error.

The Mosquitto Log shows the following:
1655948494: New connection from 192.168.0.15:34309 on port 8883. 1655948494: New client connected from 192.168.0.15:34309 as auto-234BC581-9B36-62C1-F8E3-02C7EDE8BD74 (p2, c1, k60).

This leads me to believe that rhasspy is successfully connecting to the external MQTT broker.

Before the next test I subscribe to the rhasspy and hermes MQTT topics with the following command to monitor:
mosquitto_sub -v -h 192.168.0.15 --key hass-client.key --cert hass-client.crt --cafile /etc/mosquitto/certs/mqtt-server.crt -t 'hermes/#' -t 'rhasspy/#' -p 8883 --tls-version tlsv1.2 -i test

Finally I attempt to refresh the device list from the UI:

[DEBUG:2022-06-23 01:41:42,265] rhasspyserver_hermes: Subscribed to rhasspy/audioServer/devices
[DEBUG:2022-06-23 01:41:42,268] rhasspyserver_hermes: -> AudioGetDevices(modes=[<AudioDeviceMode.INPUT: 'input'>], site_id='server', id='a7020fb5-3f7b-4fbe-beb4-29932b89def2', test=False)
[DEBUG:2022-06-23 01:41:42,269] rhasspyserver_hermes: Publishing 101 bytes(s) to rhasspy/audioServer/getDevices
[ERROR:2022-06-23 01:42:12,286] rhasspyserver_hermes:
Traceback (most recent call last):
  File "/usr/lib/rhasspy/usr/local/lib/python3.7/site-packages/quart/app.py", line 1821, in full_dispatch_request
    result = await self.dispatch_request(request_context)
  File "/usr/lib/rhasspy/usr/local/lib/python3.7/site-packages/quart/app.py", line 1869, in dispatch_request
    return await handler(**request_.view_args)
  File "/usr/lib/rhasspy/rhasspy-server-hermes/rhasspyserver_hermes/__main__.py", line 796, in api_microphones
    microphones = await core.get_microphones()
  File "/usr/lib/rhasspy/rhasspy-server-hermes/rhasspyserver_hermes/__init__.py", line 849, in get_microphones
    handle_finished(), messages, message_types
  File "/usr/lib/rhasspy/rhasspy-server-hermes/rhasspyserver_hermes/__init__.py", line 995, in publish_wait
    result_awaitable, timeout=timeout_seconds
  File "/usr/lib/rhasspy/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

From my previously subscription to the hermes and rhasspy topics I see a matching message on getDevices
rhasspy/audioServer/getDevices {"modes": ["input"], "siteId": "server", "id": "a7020fb5-3f7b-4fbe-beb4-29932b89def2", "test": false}

I feel like I’m missing something here. arecord works, my external MQTT broker works and rhasspy can successfully connect and interact with it, but interactions with arecord from rhasspy aren’t working. Thoughts?

Other configuration information:
Ubuntu 20.04 on a Pentium G3220.
Rhasspy 2.5.11 installed via Debian package

To try to further isolate the issue, I manually created a getDevices response message and published that to rhasspy/audioServer/devices

{
  "devices": [
    {
      "mode": "input",
      "id": "card 1: PCH [HDA Intel PCH], device 0: ALC892 Analog [ALC892 Analog]",
      "name": "card 1: PCH [HDA Intel PCH], device 0: ALC892 Analog [ALC892 Analog]",
      "description": "Subdevice #0: subdevice #0",
      "working": false
    },
    {
      "mode": "input",
      "id": "card 1: PCH [HDA Intel PCH], device 2: ALC892 Alt Analog [ALC892 Alt Analog]",
      "name": "card 1: PCH [HDA Intel PCH], device 2: ALC892 Alt Analog [ALC892 Alt Analog]",
      "description": "Subdevice #0: subdevice #0",
      "working": false
    },
    {
      "mode": "input",
      "id": "card 2: ArrayUAC10 [ReSpeaker 4 Mic Array (UAC1.0)], device 0: USB Audio [USB Audio]",
      "name": "card 2: ArrayUAC10 [ReSpeaker 4 Mic Array (UAC1.0)], device 0: USB Audio [USB Audio]",
      "description": "Subdevice #0: subdevice #0",
      "working": true
    }
  ],
  "siteId": "server",
  "id": "80fa3703-ad61-488c-b5b1-5e9e97cb5509"
}

The id field was set based on the id of the refresh request published on rhasspy/audioServer/getDevices.

The debug log showed the following

[DEBUG:2022-06-25 15:14:55,099] rhasspyserver_hermes: -> AudioGetDevices(modes=[<AudioDeviceMode.INPUT: 'input'>], site_id='server', id='80fa3703-ad61-488c-b5b1-5e9e97cb5509', test=False)
[DEBUG:2022-06-25 15:14:55,100] rhasspyserver_hermes: Publishing 101 bytes(s) to rhasspy/audioServer/getDevices
[DEBUG:2022-06-25 15:15:04,020] rhasspyserver_hermes: Handling AudioDevices (topic=rhasspy/audioServer/devices, id=c2927071-ebb5-48c9-9f01-de8b94f27051)
[DEBUG:2022-06-25 15:15:04,020] rhasspyserver_hermes: Handling AudioDevices (topic=rhasspy/audioServer/devices, id=6ea234c4-e40c-42bf-858d-5215bfa81600)
[DEBUG:2022-06-25 15:15:04,020] rhasspyserver_hermes: Handling AudioDevices (topic=rhasspy/audioServer/devices, id=d7a36953-abc6-40fb-ae51-f1fc39859526)
[DEBUG:2022-06-25 15:15:04,021] rhasspyserver_hermes: Handling AudioDevices (topic=rhasspy/audioServer/devices, id=01d22187-cc17-42d2-a095-e51b9cc583fb)
[DEBUG:2022-06-25 15:15:04,021] rhasspyserver_hermes: Handling AudioDevices (topic=rhasspy/audioServer/devices, id=d4db59c0-fd60-4693-9ffb-9cb66fba4c2e)
[DEBUG:2022-06-25 15:15:04,021] rhasspyserver_hermes: Handling AudioDevices (topic=rhasspy/audioServer/devices, id=50a2ac4e-8c17-4a4f-8407-b472cea37bb1)

And the UI updated the device dropdown list to show those inputs; however, they are still non-functional. Whenever I access the UI settings page and Rhasspy attempts to refresh the device list, the same timeout error as in the first post occurs because I’m not manually creating the response.

Based on this, it seems like some part of Rhasspy which is supposed to be listening to be managing responses with the Hermes protocol isn’t operating correctly.

Thoughts?