search

createcandle / voco

Privacy friendly voice control for the Candle Controller / WebThings Gateway, with fully local AI assistant
https://www.candlesmarthome.com/voco-privacy-friendly-voice-control
Mozilla Public License 2.0
25 stars 6 forks source link

Voco stopped working #21

Closed pointout closed 1 year ago

pointout commented 3 years ago

I didn't use voco for a while. But yesterday I tried to call "snips" and got no answer. I tried an USB microphone also. The same behaviour. When I change the configuration of voco, voco says "I am listening", but no reaction on the wake word.

I did a text input in the voco-menu point (set alarm to 20:25pm).

Some logs: 2021-02-09 20:26:12.038 INFO : voco: Teaching Snips the updated thing titles: 2021-02-09 20:26:12.040 INFO : voco: ['lamp', 'Reading Lamp', 'Voice control'] 2021-02-09 20:26:12.048 INFO : voco: /\ /\ /\ Injecting names into Snips! update_request json: {"operations": [["addFromVanilla", {"Thing": ["lamp", "Reading Lamp", "Voice control"]}]]} 2021-02-09 20:26:12.050 INFO : voco: Saving to persistence data store at path: /home/pi/.webthings/data/voco/persistence.json 2021-02-09 20:26:12.052 INFO : voco: Persistence file existed. Will try to save to it. 2021-02-09 20:26:12.053 INFO : voco: Data stored 2021-02-09 20:26:12.055 INFO : voco: Injection: self.mqtt_client exists, will try to inject 2021-02-09 20:26:12.057 INFO : voco: [["addFromVanilla", {"Thing": ["lamp", "Reading Lamp", "Voice control"]}]] 2021-02-09 20:26:12.059 INFO : voco: Handling request to /init 2021-02-09 20:26:12.061 INFO : voco: Warning, the current persistent_data['mqtt_server'] IP was not actually spotted in the network by the ARP scan! 2021-02-09 20:26:12.063 INFO : voco: - satellite_targets: {} 2021-02-09 20:26:12.065 INFO : voco: - has_token: True 2021-02-09 20:26:12.067 INFO : voco: - is_satellite: False 2021-02-09 20:26:12.069 INFO : voco: - hostname: gateway 2021-02-09 20:26:12.073 INFO : voco: - mqtt_server: localhost 2021-02-09 20:26:12.076 INFO : voco: 15 seconds have passed. Time: 36 2021-02-09 20:26:12.078 INFO : voco: Periodic check: self.mqtt_connected = false - will try to run_mqtt 2021-02-09 20:26:12.080 INFO : voco: in run_mqtt 2021-02-09 20:26:12.082 INFO : voco: disconnecting mqtt first 2021-02-09 20:26:12.085 INFO : voco: self.persistent_data['mqtt_server'] = localhost 2021-02-09 20:26:12.087 INFO : voco: This device is NOT a satellite, so MQTT client is connecting to 127.0.0.1:1883 2021-02-09 20:26:12.089 INFO : voco: Error creating MQTT client connection: [Errno 111] Connection refused 2021-02-09 20:26:12.091 INFO : voco: /\ /\ /\ inject_updated_things_into_snips: starting an attempt 2021-02-09 20:26:12.093 INFO : voco: GET PATH = /things 2021-02-09 20:26:12.095 INFO : voco: intent in api_get: default 2021-02-09 20:26:12.097 INFO : voco: API GET: 200, OK 2021-02-09 20:26:12.098 INFO : voco: \/ \/ \/ No need for injection 2021-02-09 20:26:12.100 INFO : voco: 15 seconds have passed. Time: 51 2021-02-09 20:26:12.102 INFO : voco: Periodic check: self.mqtt_connected = false - will try to run_mqtt 2021-02-09 20:26:12.104 INFO : voco: in run_mqtt 2021-02-09 20:26:12.106 INFO : voco: disconnecting mqtt first 2021-02-09 20:26:12.108 INFO : voco: self.persistent_data['mqtt_server'] = localhost 2021-02-09 20:26:12.110 INFO : voco: This device is NOT a satellite, so MQTT client is connecting to 127.0.0.1:1883 2021-02-09 20:26:12.112 INFO : voco: Error creating MQTT client connection: [Errno 111] Connection refused 2021-02-09 20:26:12.114 INFO : voco: /\ /\ /\ inject_updated_things_into_snips: starting an attempt 2021-02-09 20:26:12.116 INFO : voco: GET PATH = /things 2021-02-09 20:26:12.118 INFO : voco: intent in api_get: default 2021-02-09 20:26:12.119 INFO : voco: API GET: 200, OK 2021-02-09 20:26:12.121 INFO : voco: \/ \/ \/ No need for injection 2021-02-09 20:26:12.123 INFO : voco: 15 seconds have passed. Time: 6 2021-02-09 20:26:12.125 INFO : voco: Periodic check: self.mqtt_connected = false - will try to run_mqtt 2021-02-09 20:26:12.127 INFO : voco: in run_mqtt 2021-02-09 20:26:12.128 INFO : voco: disconnecting mqtt first 2021-02-09 20:26:12.129 INFO : voco: self.persistent_data['mqtt_server'] = localhost 2021-02-09 20:26:12.130 INFO : voco: This device is NOT a satellite, so MQTT client is connecting to 127.0.0.1:1883 2021-02-09 20:26:12.131 INFO : voco: Error creating MQTT client connection: [Errno 111] Connection refused 2021-02-09 20:26:12.132 INFO : voco: /\ /\ /\ inject_updated_things_into_snips: starting an attempt 2021-02-09 20:26:12.133 INFO : voco: GET PATH = /things 2021-02-09 20:26:12.134 INFO : voco: intent in api_get: default 2021-02-09 20:26:12.135 INFO : voco: API GET: 200, OK 2021-02-09 20:26:12.136 INFO : voco: \/ \/ \/ No need for injection 2021-02-09 20:26:12.137 INFO : voco: handling /parse. Incoming text: set alarm to 20:25pm 2021-02-09 20:26:12.138 INFO : voco: Handling request to /init 2021-02-09 20:26:12.139 INFO : voco: Warning, the current persistent_data['mqtt_server'] IP was not actually spotted in the network by the ARP scan! 2021-02-09 20:26:12.140 INFO : voco: - satellite_targets: {} 2021-02-09 20:26:12.141 INFO : voco: - has_token: True 2021-02-09 20:26:12.142 INFO : voco: - is_satellite: False 2021-02-09 20:26:12.143 INFO : voco: - hostname: gateway 2021-02-09 20:26:12.145 INFO : voco: - mqtt_server: localhost 2021-02-09 20:26:12.146 INFO : voco: 15 seconds have passed. Time: 22 2021-02-09 20:26:12.147 INFO : voco: Periodic check: self.mqtt_connected = false - will try to run_mqtt 2021-02-09 20:26:12.148 INFO : voco: in run_mqtt 2021-02-09 20:26:12.149 INFO : voco: disconnecting mqtt first 2021-02-09 20:26:12.150 INFO : voco: self.persistent_data['mqtt_server'] = localhost 2021-02-09 20:26:12.151 INFO : voco: This device is NOT a satellite, so MQTT client is connecting to 127.0.0.1:1883 2021-02-09 20:26:12.152 INFO : voco: Error creating MQTT client connection: [Errno 111] Connection refused 2021-02-09 20:26:12.153 INFO : voco: /\ /\ /\ inject_updated_things_into_snips: starting an attempt 2021-02-09 20:26:12.154 INFO : voco: GET PATH = /things 2021-02-09 20:26:12.155 INFO : voco: intent in api_get: default 2021-02-09 20:26:12.156 INFO : voco: API GET: 200, OK

createcandle commented 3 years ago

Thanks for the log data.

Looking at it, all signs in your log point to the MQTT server not being available?

Initially Voco tries to connect to MQTT as normal:

voco: This device is NOT a satellite, so MQTT client is connecting to 127.0.0.1:1883

That somehow fails. Then Voco attempts to do a network scan to find if maybe the server IP address has changed. This is actually some useful feedback, because if the device is not a satellite (which the above message indicates), then there really is no need to go searching for the main server.

In theory at this point the persistent_data['mqtt_server'] IP address should just be 127.0.0.1 (the device itself).

Warning, the current persistent_data['mqtt_server'] IP was not actually spotted in the network by the ARP scan!

A network scan will not be able to find 127.0.0.1 on the network, so another reason to avoid doing network scans in this case :-)

But all that aside, the issue is the first one: somehow MQTT cannot be found.

Are you running on a Raspberry Pi with the WebThings 1.0.0 image?

Did this happen after a reboot?

If so, what happens if you disable Voco in the addon overview, and then re-enable it? If that works, then maybe after a reboot MQTT isn't up yet, but Voco is. In which case Voco is just too early.

// Then again, Voco already tries to reconnect to the correct local MQTT server later (This device is NOT a satellite, so MQTT client is connecting to 127.0.0.1:1883), so that's probably not it either.

It could be a fluke, where MQTT has just crashed somehow. Did a reboot fix the issue?

pointout commented 3 years ago

Gateway 1.0.0 with voco 2.5.8 After starting a second mosquitto process manually it worked. (See later)

This happens at disabling and enabling voco:

2021-02-10 07:26:29.290 INFO   : Unloading voco-notifier
2021-02-10 07:26:29.292 INFO   : Unloading API handler voco
2021-02-10 07:26:29.335 INFO   : voco: API GET: 200, OK
2021-02-10 07:26:29.337 INFO   : voco: \/ \/ \/ No need for injection
2021-02-10 07:26:29.338 INFO   : voco: 15 seconds have passed. Time: 18
2021-02-10 07:26:29.340 INFO   : voco: Periodic check: self.mqtt_connected = false - will try to run_mqtt
2021-02-10 07:26:29.341 INFO   : voco: in run_mqtt
2021-02-10 07:26:29.343 INFO   : voco: disconnecting mqtt first
2021-02-10 07:26:29.344 INFO   : voco: self.persistent_data['mqtt_server'] = localhost
2021-02-10 07:26:29.346 INFO   : voco: This device is NOT a satellite, so MQTT client is connecting to 127.0.0.1:1883
2021-02-10 07:26:29.347 INFO   : voco: Error creating MQTT client connection: [Errno 111] Connection refused
2021-02-10 07:26:29.349 INFO   : voco: /\ /\ /\ inject_updated_things_into_snips: starting an attempt
2021-02-10 07:26:29.350 INFO   : voco: GET PATH = /things
2021-02-10 07:26:29.351 INFO   : voco: intent in api_get: default
2021-02-10 07:26:29.353 INFO   : voco: API GET: 200, OK
2021-02-10 07:26:29.354 INFO   : voco: \/ \/ \/ No need for injection
2021-02-10 07:26:29.357 INFO   : voco: Shutting down Voco. Talk to you soon!
2021-02-10 07:26:29.358 INFO   : voco: Saving to persistence data store at path: /home/pi/.webthings/data/voco/persistence.json
2021-02-10 07:26:29.360 INFO   : voco: Persistence file existed. Will try to save to it.
2021-02-10 07:26:29.361 INFO   : voco: Data stored
2021-02-10 07:26:29.362 INFO   : voco: Notifier: voco-notifier unloaded
2021-02-10 07:26:31.692 INFO   : voco: 
2021-02-10 07:26:31.694 INFO   : voco: in stop_snips
2021-02-10 07:26:31.695 INFO   : voco:  -- 
2021-02-10 07:26:31.697 INFO   : voco:  -- sub processes count: 0
2021-02-10 07:26:31.698 INFO   : voco:  -- snips_actual_processes_count = 0
2021-02-10 07:26:31.700 INFO   : voco: self.external_processes should now be zero length: 0
2021-02-10 07:26:31.701 INFO   : voco: 
2021-02-10 07:26:31.703 INFO   : voco:  -- 
2021-02-10 07:26:31.704 INFO   : voco:  -- sub processes count: 0
2021-02-10 07:26:31.706 INFO   : voco:  -- snips_actual_processes_count = 0
2021-02-10 07:26:31.707 INFO   : voco: stop_snips: snips seems to have indeed been stopped
2021-02-10 07:26:43.931 INFO   : Loading add-on: voco
2021-02-10 07:26:45.496 INFO   : voco: numid=1,iface=MIXER,name='Headphone Playback Volume'
2021-02-10 07:26:45.499 INFO   : voco:   ; type=INTEGER,access=rw---R--,values=1,min=-10239,max=400,step=0
2021-02-10 07:26:45.501 INFO   : voco:   : values=-663
2021-02-10 07:26:45.503 INFO   : voco:   | dBscale-min=-102.39dB,step=0.01dB,mute=1```

didn't solve the problem. Then I did a reboot. Log is showing: 
```2021-02-10 07:28:36.091 INFO   : voco: This device is NOT a satellite, so MQTT client is connecting to 127.0.0.1:1883
2021-02-10 07:28:36.092 INFO   : voco: Error creating MQTT client connection: [Errno 111] Connection refused```

Snips is saying "I could not connect." and then "Hello, Iam listening."

Here the longer version:
```2021-02-10 07:28:36.039 INFO   : voco: ERROR, rapidfuzz is not installed. try 'pip3 install rapidfuzz'
2021-02-10 07:28:36.042 INFO   : voco: ERROR, alsaaudio is not installed. try 'pip3 install alsaaudio'
2021-02-10 07:28:36.044 INFO   : voco: end of intentions file
2021-02-10 07:28:36.045 INFO   : voco: succesfully imported intentions.py file
2021-02-10 07:28:36.047 INFO   : voco: Starting Voco addon
2021-02-10 07:28:36.049 INFO   : voco: audio controls: [{'card_id': 0, 'device_id': 0, 'simple_card_name': 'Headphones', 'full_card_name': 'bcm2835 Headphones', 'full_device_name': 'bcm2835 Headphones', 'human_device_name': 'Built-in headphone jack', 'control_name': 'Headphone', 'complex_control_id': None, 'complex_count': None, 'complex_max': None}]
2021-02-10 07:28:36.050 INFO   : voco: Possible audio capture devices: ['Attached device (1,0)']
2021-02-10 07:28:36.052 INFO   : voco: -Debugging was in config
2021-02-10 07:28:36.053 INFO   : voco: Debugging enabled
2021-02-10 07:28:36.055 INFO   : voco: -Microphone is present in the config data: Attached device (1,0)
2021-02-10 07:28:36.057 INFO   : voco: --Using microphone from config
2021-02-10 07:28:36.059 INFO   : voco: -Speaker is present in the config data: Headphone jack
2021-02-10 07:28:36.061 INFO   : voco: -Voice accent is present in the config data.
2021-02-10 07:28:36.062 INFO   : voco: -Voice pitch is present in the config data.
2021-02-10 07:28:36.063 INFO   : voco: -Voice speed is present in the config data.
2021-02-10 07:28:36.065 INFO   : voco: -Hotword sensitivity is present in the config data.
2021-02-10 07:28:36.066 INFO   : voco: -Metric preference is present in the config data.
2021-02-10 07:28:36.068 INFO   : voco: -Authorization token is present in the config data.
2021-02-10 07:28:36.069 INFO   : voco: -Sound detection is present in the config data.
2021-02-10 07:28:36.071 INFO   : voco: Volume should be set to initial value of: 90
2021-02-10 07:28:36.072 INFO   : voco: System audio volume percentage will be set to: 90
2021-02-10 07:28:36.074 INFO   : voco: -Raise the volume is present in the config data.
2021-02-10 07:28:36.075 INFO   : voco: self.persistent_data is now:
2021-02-10 07:28:36.077 INFO   : voco: {'site_id': 'kgxtjpsf', 'action_times': [], 'mqtt_server': 'localhost', 'is_satellite': False, 'listening': True, 'feedback_sounds': True, 'speaker_volume': 100, 'audio_output': 'Built-in headphone jack', 'main_site_id': 'kgxtjpsf', 'token': 'eyJhbGciOiJFUzI1NiIsInR5cCI6IkpXVCIsImtpZCI6IjQwNzJlZDAxLWI5YmQtNDgwNC04YTgzLTY2MDBjODcwMGE2OCJ9.eyJjbGllbnRfaWQiOiJsb2NhbC10b2tlbiIsInJvbGUiOiJhY2Nlc3NfdG9rZW4iLCJzY29wZSI6Ii90aGluZ3M6cmVhZHdyaXRlIiwiaWF0IjoxNjEyODk3ODYwLCJpc3MiOiJOb3Qgc2V0LiJ9.7Jf6B1g6tB-B6NVyV2JrUnIZRHVJtg1KFXMFLaOOBqPzEu06_HH5gRvaaxmrTBwfqpoYGf1bYJY9Gg1JuX3YPQ', 'thing_titles': ['lamp', 'Reading Lamp', 'Voice control'], 'property_titles': ['Timers', 'Reminders', 'Listening', 'Countdown', 'Sound detected', 'Level', 'Feedback sounds', 'Volume', 'On Off', 'Alarms', 'Status', 'Audio output'], 'property_strings': ['Built in headphone jack']}
2021-02-10 07:28:36.078 INFO   : voco: adding audio output property to Voco thing with list: ['Built-in headphone jack']
2021-02-10 07:28:36.080 INFO   : voco: adding sound detection property
2021-02-10 07:28:36.081 INFO   : voco: Voco thing has been created
2021-02-10 07:28:36.083 INFO   : voco: Voco thing created
2021-02-10 07:28:36.084 INFO   : voco: self.manager_proxy = <gateway_addon.addon_manager_proxy.AddonManagerProxy object at 0x759b1d30>
2021-02-10 07:28:36.086 INFO   : voco: Created new API HANDLER: voco
2021-02-10 07:28:36.087 INFO   : voco: Extension API handler initiated
2021-02-10 07:28:36.088 INFO   : voco: in run_mqtt
2021-02-10 07:28:36.090 INFO   : voco: self.persistent_data['mqtt_server'] = localhost
2021-02-10 07:28:36.091 INFO   : voco: This device is NOT a satellite, so MQTT client is connecting to 127.0.0.1:1883
2021-02-10 07:28:36.092 INFO   : voco: Error creating MQTT client connection: [Errno 111] Connection refused
2021-02-10 07:28:36.094 INFO   : voco: GET PATH = /things
2021-02-10 07:28:36.095 INFO   : voco: intent in api_get: default
2021-02-10 07:28:36.097 INFO   : voco: API GET: 200, OK
2021-02-10 07:28:36.098 INFO   : voco: self.api_server is now: http://127.0.0.1:8080
2021-02-10 07:28:36.100 INFO   : voco: Setting audio input to attached device
2021-02-10 07:28:36.101 INFO   : voco: Setting Pi audio_output to headphone jack
2021-02-10 07:28:36.102 INFO   : voco: Speaker volume from persistence was: 100
2021-02-10 07:28:36.104 INFO   : voco: in set_speaker_volume with 100
2021-02-10 07:28:36.105 INFO   : voco: property -> update. Value = 100
2021-02-10 07:28:36.107 INFO   : voco: property was already that value
2021-02-10 07:28:36.108 INFO   : voco: In unmute. current_control_name: Headphone
2021-02-10 07:28:36.109 INFO   : voco: Simpler timezone offset in seconds = 3600
2021-02-10 07:28:36.111 INFO   : voco: Starting the internal clock
2021-02-10 07:28:36.112 INFO   : voco: updated timer counts = {'timer': 0, 'alarm': 0, 'reminder': 0}
2021-02-10 07:28:36.114 INFO   : voco: [...] speak: Hello. I am listening. 
2021-02-10 07:28:36.115 INFO   : voco: [...] intent: {'siteId': 'kgxtjpsf'}
2021-02-10 07:28:36.117 INFO   : voco: in speak, site_id of intent is now: kgxtjpsf (my own is: kgxtjpsf)
2021-02-10 07:28:36.118 INFO   : voco: in speak, intent_message['origin'] = voice
2021-02-10 07:28:36.119 INFO   : voco: in speak, origin was not text
2021-02-10 07:28:36.121 INFO   : voco: handling speak LOCALLY
2021-02-10 07:28:36.122 INFO   : voco: 
2021-02-10 07:28:36.124 INFO   : voco: (...) Speaking locally: 'Hello. I am listening. ' at: kgxtjpsf
2021-02-10 07:28:36.125 INFO   : voco: In unmute. current_control_name: Headphone
2021-02-10 07:28:36.127 INFO   : voco: Alsa environment variable for speech output set to: Headphones
2021-02-10 07:28:36.128 INFO   : voco: nanotts_process did not exist yet
2021-02-10 07:28:36.129 INFO   : voco: nanotts_volume = 1.0
2021-02-10 07:28:36.131 INFO   : voco: speak aplay command: ['aplay', '-D', 'plughw:0,0', '/tmp/response.wav']
2021-02-10 07:28:36.132 INFO   : voco: Updating sound detected property to: False
2021-02-10 07:28:36.138 INFO   : voco: property -> update. Value = False
2021-02-10 07:28:36.140 INFO   : voco: property was already that value
2021-02-10 07:28:36.147 INFO   : voco: 15 seconds have passed. Time: 1
2021-02-10 07:28:36.149 INFO   : voco: Periodic check: self.mqtt_connected = false - will try to run_mqtt
2021-02-10 07:28:36.150 INFO   : voco: in run_mqtt
2021-02-10 07:28:36.151 INFO   : voco: disconnecting mqtt first
2021-02-10 07:28:36.152 INFO   : voco: self.persistent_data['mqtt_server'] = localhost
2021-02-10 07:28:36.153 INFO   : voco: This device is NOT a satellite, so MQTT client is connecting to 127.0.0.1:1883
2021-02-10 07:28:36.155 INFO   : voco: Error creating MQTT client connection: [Errno 111] Connection refused
2021-02-10 07:28:36.157 INFO   : voco: /\ /\ /\ inject_updated_things_into_snips: starting an attempt
2021-02-10 07:28:36.158 INFO   : voco: GET PATH = /things
2021-02-10 07:28:36.160 INFO   : voco: intent in api_get: default
2021-02-10 07:28:36.168 INFO   : voco: API GET: 200, OK
2021-02-10 07:28:36.170 INFO   : voco: Teaching Snips the updated thing titles:
2021-02-10 07:28:36.171 INFO   : voco: ['Voice control', 'lamp', 'Reading Lamp']
2021-02-10 07:28:36.173 INFO   : voco: Teaching Snips the updated property titles:
2021-02-10 07:28:36.174 INFO   : voco: ['Feedback sounds', 'Countdown', 'Status', 'Timers', 'Reminders', 'Audio output', 'Sound detected', 'On Off', 'Listening', 'Volume', 'Level', 'Alarms']
2021-02-10 07:28:36.176 INFO   : voco: Teaching Snips the updated property strings:
2021-02-10 07:28:36.178 INFO   : voco: ['Built in headphone jack']
2021-02-10 07:28:36.180 INFO   : voco: /\ /\ /\ Injecting names into Snips! update_request json: {"operations": [["addFromVanilla", {"Thing": ["Voice control", "lamp", "Reading Lamp"]}], ["addFromVanilla", {"Property": ["Feedback sounds", "Countdown", "Status", "Timers", "Reminders", "Audio output", "Sound detected", "On Off", "Listening", "Volume", "Level", "Alarms"]}], ["addFromVanilla", {"string": ["Built in headphone jack"]}]]}
2021-02-10 07:28:36.182 INFO   : voco: Saving to persistence data store at path: /home/pi/.webthings/data/voco/persistence.json
2021-02-10 07:28:36.184 INFO   : voco: Persistence file existed. Will try to save to it.
2021-02-10 07:28:36.186 INFO   : voco: Data stored
2021-02-10 07:28:36.188 INFO   : voco: Injection: self.mqtt_client exists, will try to inject
2021-02-10 07:28:36.191 INFO   : voco: [["addFromVanilla", {"Thing": ["Voice control", "lamp", "Reading Lamp"]}], ["addFromVanilla", {"Property": ["Feedback sounds", "Countdown", "Status", "Timers", "Reminders", "Audio output", "Sound detected", "On Off", "Listening", "Volume", "Level", "Alarms"]}], ["addFromVanilla", {"string": ["Built in headphone jack"]}]]
2021-02-10 07:28:36.193 INFO   : voco: 15 seconds have passed. Time: 17
2021-02-10 07:28:36.195 INFO   : voco: Periodic check: self.mqtt_connected = false - will try to run_mqtt
2021-02-10 07:28:36.197 INFO   : voco: in run_mqtt
2021-02-10 07:28:36.198 INFO   : voco: disconnecting mqtt first
2021-02-10 07:28:36.200 INFO   : voco: self.persistent_data['mqtt_server'] = localhost
2021-02-10 07:28:36.201 INFO   : voco: This device is NOT a satellite, so MQTT client is connecting to 127.0.0.1:1883
2021-02-10 07:28:36.203 INFO   : voco: Error creating MQTT client connection: [Errno 111] Connection refused
2021-02-10 07:28:36.204 INFO   : voco: /\ /\ /\ inject_updated_things_into_snips: starting an attempt
2021-02-10 07:28:36.206 INFO   : voco: GET PATH = /things
2021-02-10 07:28:36.208 INFO   : voco: intent in api_get: default
2021-02-10 07:28:36.210 INFO   : voco: API GET: 200, OK
2021-02-10 07:28:36.211 INFO   : voco: \/ \/ \/ No need for injection
2021-02-10 07:28:36.216 INFO   : voco: 15 seconds have passed. Time: 33
2021-02-10 07:28:36.218 INFO   : voco: Periodic check: self.mqtt_connected = false - will try to run_mqtt
2021-02-10 07:28:36.221 INFO   : voco: in run_mqtt
2021-02-10 07:28:36.223 INFO   : voco: disconnecting mqtt first
2021-02-10 07:28:36.225 INFO   : voco: self.persistent_data['mqtt_server'] = localhost
2021-02-10 07:28:36.226 INFO   : voco: This device is NOT a satellite, so MQTT client is connecting to 127.0.0.1:1883
2021-02-10 07:28:36.227 INFO   : voco: Error creating MQTT client connection: [Errno 111] Connection refused
2021-02-10 07:28:36.229 INFO   : voco: /\ /\ /\ inject_updated_things_into_snips: starting an attempt
2021-02-10 07:28:36.230 INFO   : voco: GET PATH = /things
2021-02-10 07:28:36.231 INFO   : voco: intent in api_get: default
2021-02-10 07:28:36.232 INFO   : voco: API GET: 200, OK
2021-02-10 07:28:36.234 INFO   : voco: \/ \/ \/ No need for injection
2021-02-10 07:28:36.235 INFO   : voco: 15 seconds have passed. Time: 49
2021-02-10 07:28:36.236 INFO   : voco: Periodic check: self.mqtt_connected = false - will try to run_mqtt
2021-02-10 07:28:36.238 INFO   : voco: in run_mqtt
2021-02-10 07:28:36.239 INFO   : voco: disconnecting mqtt first
2021-02-10 07:28:36.240 INFO   : voco: self.persistent_data['mqtt_server'] = localhost
2021-02-10 07:28:36.241 INFO   : voco: This device is NOT a satellite, so MQTT client is connecting to 127.0.0.1:1883
2021-02-10 07:28:36.243 INFO   : voco: Error creating MQTT client connection: [Errno 111] Connection refused
2021-02-10 07:28:36.244 INFO   : voco: /\ /\ /\ inject_updated_things_into_snips: starting an attempt
2021-02-10 07:28:36.245 INFO   : voco: GET PATH = /things
2021-02-10 07:28:36.247 INFO   : voco: intent in api_get: default
2021-02-10 07:28:36.248 INFO   : voco: API GET: 200, OK
2021-02-10 07:28:36.249 INFO   : voco: \/ \/ \/ No need for injection
2021-02-10 07:28:36.250 INFO   : voco: 15 seconds have passed. Time: 5
2021-02-10 07:28:36.251 INFO   : voco: Periodic check: self.mqtt_connected = false - will try to run_mqtt
2021-02-10 07:28:36.253 INFO   : voco: in run_mqtt
2021-02-10 07:28:36.257 INFO   : voco: disconnecting mqtt first
2021-02-10 07:28:36.259 INFO   : voco: self.persistent_data['mqtt_server'] = localhost
2021-02-10 07:28:36.261 INFO   : voco: This device is NOT a satellite, so MQTT client is connecting to 127.0.0.1:1883
2021-02-10 07:28:36.262 INFO   : voco: Error creating MQTT client connection: [Errno 111] Connection refused
2021-02-10 07:28:36.264 INFO   : voco: /\ /\ /\ inject_updated_things_into_snips: starting an attempt
2021-02-10 07:28:36.265 INFO   : voco: GET PATH = /things
2021-02-10 07:28:36.266 INFO   : voco: intent in api_get: default
2021-02-10 07:28:36.268 INFO   : voco: API GET: 200, OK
2021-02-10 07:28:36.269 INFO   : voco: \/ \/ \/ No need for injection
2021-02-10 07:28:36.270 INFO   : voco: 15 seconds have passed. Time: 21
2021-02-10 07:28:36.272 INFO   : voco: Periodic check: self.mqtt_connected = false - will try to run_mqtt
2021-02-10 07:28:36.273 INFO   : voco: in run_mqtt
2021-02-10 07:28:36.274 INFO   : voco: disconnecting mqtt first
2021-02-10 07:28:36.276 INFO   : voco: self.persistent_data['mqtt_server'] = localhost
2021-02-10 07:28:36.277 INFO   : voco: This device is NOT a satellite, so MQTT client is connecting to 127.0.0.1:1883
2021-02-10 07:28:36.279 INFO   : voco: Error creating MQTT client connection: [Errno 111] Connection refused
2021-02-10 07:28:36.280 INFO   : voco: /\ /\ /\ inject_updated_things_into_snips: starting an attempt
2021-02-10 07:28:36.281 INFO   : voco: GET PATH = /things
2021-02-10 07:28:36.283 INFO   : voco: intent in api_get: default
2021-02-10 07:28:36.284 INFO   : voco: API GET: 200, OK
2021-02-10 07:28:36.285 INFO   : voco: \/ \/ \/ No need for injection
2021-02-10 07:28:36.287 INFO   : voco: 15 seconds have passed. Time: 36
2021-02-10 07:28:36.288 INFO   : voco: Periodic check: self.mqtt_connected = false - will try to run_mqtt
2021-02-10 07:28:36.290 INFO   : voco: in run_mqtt
2021-02-10 07:28:36.291 INFO   : voco: disconnecting mqtt first
2021-02-10 07:28:36.292 INFO   : voco: self.persistent_data['mqtt_server'] = localhost
2021-02-10 07:17:26.371 INFO   : Opening database: /home/pi/.webthings/log/logs.sqlite3
2021-02-10 07:17:31.559 INFO   : wifi-setup: waitForWiFi: networks exist: [ 'ro-sig' ]
2021-02-10 07:17:31.653 INFO   : wifi-setup: waitForWifi: connection found
2021-02-10 07:17:31.812 INFO   : HTTP server listening on port 8080
2021-02-10 07:17:31.930 DEBUG  : Ignoring https://raw.githubusercontent.com/WebThingsIO/gateway-addon-ipc-schema/master/schema.json because it has no messageType
2021-02-10 07:32:30.138 DEBUG  : Ignoring https://raw.githubusercontent.com/WebThingsIO/gateway-addon-ipc-schema/master/messages/definitions.json because it has no messageType
2021-02-10 07:32:33.162 ERROR  : Error getting value for thingId: zb-000d6ffffec2f546 property: on
2021-02-10 07:32:33.165 ERROR  : getProperty: device: zb-000d6ffffec2f546 not found.
2021-02-10 07:32:33.169 WARN   : Rule get failed { code: 500,
  message: 'getProperty: device: zb-000d6ffffec2f546 not found.' }
2021-02-10 07:32:53.857 INFO   : Checking for add-on updates...
2021-02-10 07:32:54.204 INFO   : Loading add-on: thing-url-adapter
2021-02-10 07:32:54.210 INFO   : Loading add-on: voco
2021-02-10 07:32:54.214 INFO   : Loading add-on: zigbee-adapter
2021-02-10 07:32:54.815 ERROR  : Failed to load add-on zwave-adapter: Error: Add-on not enabled: zwave-adapter
    at AddonManager.loadAddon (/home/pi/webthings/gateway/build/webpack:/src/addon-manager.js:668:1)
2021-02-10 07:32:55.408 INFO   : Finished updating add-ons
2021-02-10 07:32:57.219 INFO   : thing-url-adapter: Opening database: /home/pi/.webthings/config/db.sqlite3
2021-02-10 07:32:57.268 INFO   : zigbee-adapter: Opening database: /home/pi/.webthings/config/db.sqlite3
2021-02-10 07:32:57.298 INFO   : thing-url-adapter: Ignoring https://raw.githubusercontent.com/WebThingsIO/gateway-addon-ipc-schema/master/schema.json because it has no messageType
2021-02-10 07:32:57.353 INFO   : zigbee-adapter: Ignoring https://raw.githubusercontent.com/WebThingsIO/gateway-addon-ipc-schema/master/schema.json because it has no messageType
2021-02-10 07:32:58.193 INFO   : voco: numid=1,iface=MIXER,name='Headphone Playback Volume'
2021-02-10 07:32:58.196 INFO   : voco:   ; type=INTEGER,access=rw---R--,values=1,min=-10239,max=400,step=0
2021-02-10 07:32:58.199 INFO   : voco:   : values=-663
2021-02-10 07:32:58.202 INFO   : voco:   | dBscale-min=-102.39dB,step=0.01dB,mute=1
2021-02-10 07:32:59.659 INFO   : thing-url-adapter: Ignoring https://raw.githubusercontent.com/WebThingsIO/gateway-addon-ipc-schema/master/messages/definitions.json because it has no messageType
2021-02-10 07:32:59.974 INFO   : zigbee-adapter: Ignoring https://raw.githubusercontent.com/WebThingsIO/gateway-addon-ipc-schema/master/messages/definitions.json because it has no messageType
2021-02-10 07:33:03.976 INFO   : thing-url-adapter: Loading add-on thing-url-adapter from /home/pi/.webthings/addons/thing-url-adapter
2021-02-10 07:33:03.983 INFO   : zigbee-adapter: Loading add-on zigbee-adapter from /home/pi/.webthings/addons/zigbee-adapter
2021-02-10 07:33:04.142 INFO   : zigbee-adapter: DEBUG config = ''
2021-02-10 07:33:04.244 INFO   : thing-url-adapter: Starting mDNS discovery
2021-02-10 07:33:05.235 INFO   : zigbee-adapter: this.driver = DeconzDriver {}
2021-02-10 07:33:05.243 INFO   : zigbee-adapter: DeconzDriver: Using serial port /dev/ttyACM0
2021-02-10 07:33:05.264 INFO   : zigbee-adapter: DeConz Firmware version: 264a0700
2021-02-10 07:33:05.331 INFO   : zigbee-adapter: Kicking WatchDog for 3600 seconds
2021-02-10 07:33:05.379 INFO   : zigbee-adapter:          MAC Address: 00212effff0506dd
2021-02-10 07:33:05.383 INFO   : zigbee-adapter:      Network PANID16: 677b
2021-02-10 07:33:05.386 INFO   : zigbee-adapter:       Network Addr16: 0000
2021-02-10 07:33:05.389 INFO   : zigbee-adapter:      Network PANID64: 00212effff0506dd
2021-02-10 07:33:05.392 INFO   : zigbee-adapter: APS Designated Coordinator: 1
2021-02-10 07:33:05.395 INFO   : zigbee-adapter:        Scan Channels: 00008000
2021-02-10 07:33:05.398 INFO   : zigbee-adapter:          APS PANID64: 0000000000000000
2021-02-10 07:33:05.401 INFO   : zigbee-adapter:  Trust Center Addr64: 00212effff0506dd
2021-02-10 07:33:05.404 INFO   : zigbee-adapter:        Security Mode: 3
2021-02-10 07:33:05.408 INFO   : zigbee-adapter:          Network Key: 98a4438c909d3b2fe87553e0c49e9f00
2021-02-10 07:33:05.411 INFO   : zigbee-adapter:    Operating Channel: 15
2021-02-10 07:33:05.414 INFO   : zigbee-adapter:     Protocol Version: 267
2021-02-10 07:33:05.417 INFO   : zigbee-adapter:    Network Update ID: 0
2021-02-10 07:33:05.420 INFO   : zigbee-adapter:          Permit Join: 0
2021-02-10 07:33:05.423 INFO   : zigbee-adapter:         WatchDog TTL: 3600
2021-02-10 07:33:05.426 INFO   : zigbee-adapter:              Version: 264a0700
2021-02-10 07:33:05.431 INFO   : zigbee-adapter: ZigbeeNode created: addr64: 00212effff0506dd addr16: 0000
2021-02-10 07:33:05.434 INFO   : zigbee-adapter: ZigbeeNode created: addr64: 000d6ffffec2f546 addr16: e41f
2021-02-10 07:33:05.437 INFO   : zigbee-adapter: ZigbeeNode created: addr64: 000d6ffffefcef39 addr16: 87e4
2021-02-10 07:33:05.446 INFO   : zigbee-adapter: ----- Scan Starting -----
2021-02-10 07:33:05.478 INFO   : zigbee-adapter: ----- Nodes -----
2021-02-10 07:33:05.482 INFO   : zigbee-adapter: Node: 00212effff0506dd 0000 Name: zb-00212effff0506dd-Dongle       rebindRequired: true endpoints: []
2021-02-10 07:33:05.485 INFO   : zigbee-adapter:   Neighbor: 000d6ffffefcef39 87e4 DT: Router R: Sibling  PJ: N D:   1 LQI: 218
2021-02-10 07:33:05.488 INFO   : zigbee-adapter:   Neighbor: 000d6ffffec2f546 e41f DT: Router R: Sibling  PJ: N D:   1 LQI: 255
2021-02-10 07:33:05.491 INFO   : zigbee-adapter: Node: 000d6ffffec2f546 e41f Name: zb-000d6ffffec2f546-switch       rebindRequired: true endpoints: [ '1', '242' ]
2021-02-10 07:33:05.494 INFO   : zigbee-adapter: Node: 000d6ffffefcef39 87e4 Name: zb-000d6ffffefcef39-switch       rebindRequired: true endpoints: [ '1', '242' ]
2021-02-10 07:33:05.497 INFO   : zigbee-adapter: -----------------
2021-02-10 07:33:05.500 INFO   : zigbee-adapter: ----- Scan Complete -----
2021-02-10 07:33:06.007 INFO   : zigbee-adapter: zb-000d6ffffec2f546-switch property: level profileId: 0104 endpoint: 1 clusterId: 0008 readRsp value: 100.0% (254)
2021-02-10 07:33:06.318 INFO   : zigbee-adapter: zb-000d6ffffec2f546-switch property: on profileId: 0104 endpoint: 1 clusterId: 0006 readRsp value: on (1)
2021-02-10 07:33:06.702 INFO   : zigbee-adapter: zb-000d6ffffefcef39-switch property: level profileId: 0104 endpoint: 1 clusterId: 0008 readRsp value: 100.0% (254)
2021-02-10 07:33:06.982 INFO   : zigbee-adapter: zb-000d6ffffefcef39-switch property: on profileId: 0104 endpoint: 1 clusterId: 0006 readRsp value: on (1)
2021-02-10 07:33:06.988 INFO   : zigbee-adapter: ----- Nodes -----
2021-02-10 07:33:06.992 INFO   : zigbee-adapter: Node: 00212effff0506dd 0000 Name: zb-00212effff0506dd-Dongle       rebindRequired: true endpoints: []
2021-02-10 07:33:06.997 INFO   : zigbee-adapter:   Neighbor: 000d6ffffefcef39 87e4 DT: Router R: Sibling  PJ: N D:   1 LQI: 218
2021-02-10 07:33:06.998 INFO   : zigbee-adapter:   Neighbor: 000d6ffffec2f546 e41f DT: Router R: Sibling  PJ: N D:   1 LQI: 255
2021-02-10 07:33:07.000 INFO   : zigbee-adapter: Node: 000d6ffffec2f546 e41f Name: zb-000d6ffffec2f546-switch       rebindRequired: true endpoints: [ '1', '242' ]
2021-02-10 07:33:07.002 INFO   : zigbee-adapter: Node: 000d6ffffefcef39 87e4 Name: zb-000d6ffffefcef39-switch       rebindRequired: true endpoints: [ '1', '242' ]
2021-02-10 07:33:07.004 INFO   : zigbee-adapter: -----------------
2021-02-10 07:33:07.006 INFO   : zigbee-adapter: ----- Update Network Addresses Complete -----```

After reboot:
```pi@gateway:~ $ ps aux | grep mosqu
root       637  100  2.6  29148 25032 ?        Rs   08:07   1:07 /usr/sbin/mosquitto -c /etc/mosquitto/mosquitto.conf

After running mosquitto -v snips was working. 

root      1904  100  2.5  28752 24440 ?        Rs   08:12   0:39 /usr/sbin/mosquitto -c /etc/mosquitto/mosquitto.conf
pi        1993  0.3  0.4   8676  4332 pts/1    S+   08:12   0:00 mosquitto -v

As long as the mosquitto process is running under user pi it is working:


2021-02-10 08:12:54.940 INFO   : voco: ['Built in headphone jack']
2021-02-10 08:12:54.943 INFO   : voco: /\ /\ /\ Injecting names into Snips! update_request json: {"operations": [["addFromVanilla", {"Thing": ["Reading Lamp", "Voice control", "lamp"]}], ["addFromVanilla", {"Property": ["Listening", "Alarms", "Sound detected", "Level", "Audio output", "Status", "Feedback sounds", "On Off", "Timers", "Volume", "Reminders", "Countdown"]}], ["addFromVanilla", {"string": ["Built in headphone jack"]}]]}
2021-02-10 08:12:54.945 INFO   : voco: Saving to persistence data store at path: /home/pi/.webthings/data/voco/persistence.json
2021-02-10 08:12:54.946 INFO   : voco: Persistence file existed. Will try to save to it.
2021-02-10 08:12:54.948 INFO   : voco: Data stored
2021-02-10 08:12:54.950 INFO   : voco: Injection: self.mqtt_client exists, will try to inject
2021-02-10 08:12:54.951 INFO   : voco: [["addFromVanilla", {"Thing": ["Reading Lamp", "Voice control", "lamp"]}], ["addFromVanilla", {"Property": ["Listening", "Alarms", "Sound detected", "Level", "Audio output", "Status", "Feedback sounds", "On Off", "Timers", "Volume", "Reminders", "Countdown"]}], ["addFromVanilla", {"string": ["Built in headphone jack"]}]]
2021-02-10 08:12:54.953 INFO   : voco: -on_connect: ** I am not a satellite
2021-02-10 08:12:54.955 INFO   : voco: -sending broadcast ping.
2021-02-10 08:12:54.956 INFO   : voco: - - - About to ping. Broadcast flag = True
2021-02-10 08:12:54.958 INFO   : voco: - - -  sending broadcast ping, announcing my IP as: 192.168.28.44
2021-02-10 08:12:54.960 INFO   : voco: Ping sent
2021-02-10 08:12:54.970 INFO   : voco:       -> MQTT message published succesfully
2021-02-10 08:12:54.972 INFO   : voco:       -> MQTT message published succesfully
2021-02-10 08:12:54.975 INFO   : voco: 
2021-02-10 08:12:54.977 INFO   : voco: 
2021-02-10 08:12:54.980 INFO   : voco: MQTT message to topic hermes/voco/ping received on: kgxtjpsf a.k.a. hostname gateway
2021-02-10 08:12:54.982 INFO   : voco: +
2021-02-10 08:12:54.985 INFO   : voco: {"ip": "192.168.28.44", "hostname": "gateway", "siteId": "kgxtjpsf", "satellite": false}
2021-02-10 08:12:54.989 INFO   : voco: +
2021-02-10 08:12:54.995 INFO   : voco: 
2021-02-10 08:12:54.998 INFO   : voco: 
2021-02-10 08:12:55.002 INFO   : voco: MQTT message to topic hermes/hotword/kgxtjpsf/loaded received on: kgxtjpsf a.k.a. hostname gateway
2021-02-10 08:12:55.007 INFO   : voco: +
2021-02-10 08:12:55.011 INFO   : voco: {"id":null,"reloaded":false,"siteId":"kgxtjpsf"}
2021-02-10 08:12:55.019 INFO   : voco: +
2021-02-10 08:12:55.024 INFO   : voco: Received loaded message
2021-02-10 08:12:55.032 INFO   : voco: 
2021-02-10 08:12:55.037 INFO   : voco: 
2021-02-10 08:12:55.048 INFO   : voco: MQTT message to topic hermes/voiceActivity/kgxtjpsf/vadUp received on: kgxtjpsf a.k.a. hostname gateway
2021-02-10 08:12:55.060 INFO   : voco: +
2021-02-10 08:12:55.066 INFO   : voco: {"siteId":"kgxtjpsf","signalMs":1612941169964}
2021-02-10 08:12:55.071 INFO   : voco: +
2021-02-10 08:12:55.079 INFO   : voco: detected sound
2021-02-10 08:12:55.084 INFO   : voco: detected sound.. and toggling property to on
2021-02-10 08:12:55.089 INFO   : voco: Updating sound detected property to: True
2021-02-10 08:12:55.093 INFO   : voco: property -> update. Value = True
2021-02-10 08:12:55.097 INFO   : voco: property updated to new value
2021-02-10 08:12:55.102 INFO   : voco: 
2021-02-10 08:12:55.106 INFO   : voco: 
2021-02-10 08:12:55.110 INFO   : voco: MQTT message to topic hermes/hotword/kgxtjpsf/detected received on: kgxtjpsf a.k.a. hostname gateway
2021-02-10 08:12:55.115 INFO   : voco: +
2021-02-10 08:12:55.120 INFO   : voco: {"siteId":"kgxtjpsf","modelId":"hey_snips","modelVersion":"workflow-hey_snips_subww_feedback_10seeds-2018_12_04T12_13_05_evaluated_model_0002","modelType":"universal","currentSensitivity":0.5,"detectionSignalMs":1612941170680,"endSignalMs":1612941170680}
2021-02-10 08:12:55.126 INFO   : voco: +
2021-02-10 08:12:55.132 INFO   : voco: (...) Hotword detected
2021-02-10 08:12:55.141 INFO   : voco: I should play a detected sound
2021-02-10 08:12:55.145 INFO   : voco: in play_sound. File: start_of_input
2021-02-10 08:12:55.147 INFO   : voco: play_sound aplay command: ['aplay', '/home/pi/.webthings/addons/voco/sounds/start_of_input100.wav', '-D', 'plughw:0,0']
2021-02-10 08:12:55.151 INFO   : voco: 
2021-02-10 08:12:55.156 INFO   : voco: 
2021-02-10 08:12:55.159 INFO   : voco: MQTT message to topic hermes/hotword/toggleOff received on: kgxtjpsf a.k.a. hostname gateway
2021-02-10 08:12:55.164 INFO   : voco: +
2021-02-10 08:12:55.166 INFO   : voco: {"siteId":"kgxtjpsf","sessionId":"219489b2-a109-4120-b912-3c5fdef82e21"}
2021-02-10 08:12:55.168 INFO   : voco: +
2021-02-10 08:12:55.171 INFO   : voco: MQTT message ends with toggleOff
2021-02-10 08:12:55.173 INFO   : voco: In mute. current_control_name: Headphone
2021-02-10 08:12:55.176 INFO   : voco: 
2021-02-10 08:12:55.178 INFO   : voco: 
2021-02-10 08:12:55.180 INFO   : voco: MQTT message to topic hermes/dialogueManager/sessionStarted received on: kgxtjpsf a.k.a. hostname gateway
2021-02-10 08:12:55.185 INFO   : voco: +
2021-02-10 08:12:55.190 INFO   : voco: {"sessionId":"219489b2-a109-4120-b912-3c5fdef82e21","customData":null,"siteId":"kgxtjpsf","reactivatedFromSessionId":null}
2021-02-10 08:12:55.194 INFO   : voco: +
2021-02-10 08:12:55.198 INFO   : voco: 
2021-02-10 08:12:55.203 INFO   : voco: 
2021-02-10 08:12:55.207 INFO   : voco: MQTT message to topic hermes/voiceActivity/kgxtjpsf/vadDown received on: kgxtjpsf a.k.a. hostname gateway
2021-02-10 08:12:55.212 INFO   : voco: +
2021-02-10 08:12:55.217 INFO   : voco: {"siteId":"kgxtjpsf","signalMs":1612941170410}
2021-02-10 08:12:55.219 INFO   : voco: +
2021-02-10 08:12:55.221 INFO   : voco: 
2021-02-10 08:12:55.223 INFO   : voco: 
2021-02-10 08:12:55.226 INFO   : voco: MQTT message to topic hermes/voiceActivity/kgxtjpsf/vadUp received on: kgxtjpsf a.k.a. hostname gateway
2021-02-10 08:12:55.227 INFO   : voco: +
2021-02-10 08:12:55.230 INFO   : voco: {"siteId":"kgxtjpsf","signalMs":1612941170762}
2021-02-10 08:12:55.232 INFO   : voco: +
2021-02-10 08:12:55.236 INFO   : voco: detected sound
2021-02-10 08:12:55.239 INFO   : voco: 
2021-02-10 08:12:55.244 INFO   : voco: 
2021-02-10 08:12:55.248 INFO   : voco: MQTT message to topic hermes/injection/complete received on: kgxtjpsf a.k.a. hostname gateway
2021-02-10 08:12:55.253 INFO   : voco: +
2021-02-10 08:12:55.257 INFO   : voco: {"requestId":"cd965f66-a887-4e96-bee6-ac8867d689c4"}
2021-02-10 08:12:55.261 INFO   : voco: +
2021-02-10 08:12:55.267 INFO   : voco: 
2021-02-10 08:12:55.277 INFO   : voco: 
2021-02-10 08:12:55.278 INFO   : voco: MQTT message to topic hermes/voiceActivity/kgxtjpsf/vadDown received on: kgxtjpsf a.k.a. hostname gateway
2021-02-10 08:12:55.282 INFO   : voco: +
2021-02-10 08:12:55.284 INFO   : voco: {"siteId":"kgxtjpsf","signalMs":1612941171306}
2021-02-10 08:12:55.286 INFO   : voco: +
2021-02-10 08:12:55.288 INFO   : voco: 
2021-02-10 08:12:55.290 INFO   : voco: 
2021-02-10 08:12:55.293 INFO   : voco: MQTT message to topic hermes/voiceActivity/kgxtjpsf/vadUp received on: kgxtjpsf a.k.a. hostname gateway
2021-02-10 08:12:55.295 INFO   : voco: +
2021-02-10 08:12:55.301 INFO   : voco: {"siteId":"kgxtjpsf","signalMs":1612941172266}
2021-02-10 08:12:55.303 INFO   : voco: +
2021-02-10 08:12:55.305 INFO   : voco: detected sound
2021-02-10 08:12:55.307 INFO   : voco: 
2021-02-10 08:12:55.308 INFO   : voco: 
2021-02-10 08:12:55.310 INFO   : voco: MQTT message to topic hermes/voiceActivity/kgxtjpsf/vadDown received on: kgxtjpsf a.k.a. hostname gateway
2021-02-10 08:12:55.312 INFO   : voco: +
2021-02-10 08:12:55.314 INFO   : voco: {"siteId":"kgxtjpsf","signalMs":1612941173097}
2021-02-10 08:12:55.315 INFO   : voco: +
2021-02-10 08:12:55.317 INFO   : voco: 
2021-02-10 08:12:55.319 INFO   : voco: 
2021-02-10 08:12:55.322 INFO   : voco: MQTT message to topic hermes/asr/textCaptured received on: kgxtjpsf a.k.a. hostname gateway
2021-02-10 08:12:55.324 INFO   : voco: +
2021-02-10 08:12:55.326 INFO   : voco: {"text":"what 's the time","likelihood":0.79734206,"tokens":[{"value":"what","confidence":0.96273625,"rangeStart":0,"rangeEnd":4,"time":{"start":0.0,"end":1.5018686}},{"value":"'s","confidence":0.43435955,"rangeStart":5,"rangeEnd":7,"time":{"start":1.5018686,"end":1.6870195}},{"value":"the","confidence":0.9665448,"rangeStart":8,"rangeEnd":11,"time":{"start":1.6870195,"end":2.081934}},{"value":"time","confidence":1.0,"rangeStart":12,"rangeEnd":16,"time":{"start":2.081934,"end":2.9399998}}],"seconds":2.0,"siteId":"kgxtjpsf","sessionId":"219489b2-a109-4120-b912-3c5fdef82e21"}
2021-02-10 08:12:55.328 INFO   : voco: +
2021-02-10 08:12:55.330 INFO   : voco: 
2021-02-10 08:12:55.333 INFO   : voco: 
2021-02-10 08:12:55.335 INFO   : voco: MQTT message to topic hermes/intent/createcandle:get_time received on: kgxtjpsf a.k.a. hostname gateway
2021-02-10 08:12:55.336 INFO   : voco: +
2021-02-10 08:12:55.338 INFO   : voco: {"sessionId":"219489b2-a109-4120-b912-3c5fdef82e21","customData":null,"siteId":"kgxtjpsf","input":"what 's the time","asrTokens":[[{"value":"what","confidence":0.96273625,"rangeStart":0,"rangeEnd":4,"time":{"start":0.0,"end":1.5018686}},{"value":"'s","confidence":0.43435955,"rangeStart":5,"rangeEnd":7,"time":{"start":1.5018686,"end":1.6870195}},{"value":"the","confidence":0.9665448,"rangeStart":8,"rangeEnd":11,"time":{"start":1.6870195,"end":2.081934}},{"value":"time","confidence":1.0,"rangeStart":12,"rangeEnd":16,"time":{"start":2.081934,"end":2.9399998}}]],"asrConfidence":0.79734206,"intent":{"intentName":"createcandle:get_time","confidenceScore":1.0},"slots":[],"alternatives":[{"intentName":"createcandle:list_timers","confidenceScore":0.10050081,"slots":[]},{"intentName":"createcandle:get_value","confidenceScore":0.038990613,"slots":[{"rawValue":"time","value":{"kind":"Custom","value":"time"},"alternatives":[],"range":{"start":12,"end":16},"entity":"Thing","slotName":"thing","confidenceScore":1.0}]}]}
2021-02-10 08:12:55.340 INFO   : voco: +
2021-02-10 08:12:55.342 INFO   : voco: 
2021-02-10 08:12:55.359 INFO   : voco: >>
2021-02-10 08:12:55.361 INFO   : voco: >> incoming intent   : createcandle:get_time
2021-02-10 08:12:55.363 INFO   : voco: >> intent_message    : what 's the time
2021-02-10 08:12:55.364 INFO   : voco: >> session ID        : 219489b2-a109-4120-b912-3c5fdef82e21
2021-02-10 08:12:55.366 INFO   : voco: >>
2021-02-10 08:12:55.368 INFO   : voco: INCOMING SLOTS = {'sentence': "what 's the time", 'thing': None, 'property': None, 'space': None, 'boolean': None, 'number': None, 'percentage': None, 'string': None, 'time_string': None, 'color': None, 'start_time': None, 'end_time': None, 'special_time': None, 'duration': None, 'period': None, 'timer_type': None, 'timer_last': None}
2021-02-10 08:12:55.369 INFO   : voco: __intent_get_time
2021-02-10 08:12:55.372 INFO   : voco: self.time_zone = CET
2021-02-10 08:12:55.374 INFO   : voco: human readable hour = 8
2021-02-10 08:12:55.375 INFO   : voco: human readable minute = 12
2021-02-10 08:12:55.377 INFO   : voco: 12 minutes past 8
2021-02-10 08:12:55.379 INFO   : voco: (...) It is 12 minutes past 8
2021-02-10 08:12:55.382 INFO   : voco: [...] speak: It is 12 minutes past 8
2021-02-10 08:12:58.095 INFO   : voco: [...] intent: {'sessionId': '219489b2-a109-4120-b912-3c5fdef82e21', 'customData': None, 'siteId': 'kgxtjpsf', 'input': "what 's the time", 'asrTokens': [[{'value': 'what', 'confidence': 0.96273625, 'rangeStart': 0, 'rangeEnd': 4, 'time': {'start': 0.0, 'end': 1.5018686}}, {'value': "'s", 'confidence': 0.43435955, 'rangeStart': 5, 'rangeEnd': 7, 'time': {'start': 1.5018686, 'end': 1.6870195}}, {'value': 'the', 'confidence': 0.9665448, 'rangeStart': 8, 'rangeEnd': 11, 'time': {'start': 1.6870195, 'end': 2.081934}}, {'value': 'time', 'confidence': 1.0, 'rangeStart': 12, 'rangeEnd': 16, 'time': {'start': 2.081934, 'end': 2.9399998}}]], 'asrConfidence': 0.79734206, 'intent': {'intentName': 'createcandle:get_time', 'confidenceScore': 1.0}, 'slots': [], 'alternatives': [{'intentName': 'createcandle:list_timers', 'confidenceScore': 0.10050081, 'slots': []}, {'intentName': 'createcandle:get_value', 'confidenceScore': 0.038990613, 'slots': [{'rawValue': 'time', 'value': {'kind': 'Custom', 'value': 'time'}, 'alternatives': [], 'range': {'start': 12, 'end': 16}, 'entity': 'Thing', 'slotName': 'thing', 'confidenceScore': 1.0}]}], 'origin': 'voice'}INFO:snips_dialogue_lib::coordinator::coordinator: Session [219489b2-a109-4120-b912-3c5fdef82e21]: closing session which was active: Nominal
2021-02-10 08:12:58.099 INFO   : voco: INFO:snips_dialogue_lib::coordinator::coordinator: Site [kgxtjpsf]: reset site -> turn off ASR and turn on Hotword
2021-02-10 08:12:58.125 INFO   : voco: INFO:snips_hotword_lib::audio    : Audio thread for site kgxtjpsf started.
2021-02-10 08:12:58.272 INFO   : voco: ERROR:rumqtt::client  : snips-tts|2017-gateway-1 Disconnected: (Error(Msg("socket closed"), State { next_error: None, backtrace: None }))
2021-02-10 08:12:58.275 INFO   : voco: ERROR:rumqtt::client             : snips-audio-server|2018-gateway-1 Disconnected: (Error(Msg("socket closed"), State { next_error: None, backtrace: None }))
2021-02-10 08:12:58.276 INFO   : voco: ERROR:rumqtt::client                              : snips-dialogue|2020-gateway-1 Disconnected: (Error(Msg("socket closed"), State { next_error: None, backtrace: None }))
2021-02-10 08:12:58.279 INFO   : voco: ERROR:rumqtt::client                                             : snips-nlu|2025-gateway-1 Disconnected: (Error(Msg("socket closed"), State { next_error: None, backtrace: None }))
2021-02-10 08:12:58.281 INFO   : voco: ERROR:rumqtt::client                                     : snips-injection|2030-gateway-1 Disconnected: (Error(Msg("socket closed"), State { next_error: None, backtrace: None }))
2021-02-10 08:12:58.283 INFO   : voco: ERROR:rumqtt::client            : snips-asr|2023-gateway-1 Disconnected: (Error(Msg("socket closed"), State { next_error: None, backtrace: None }))
2021-02-10 08:12:58.284 INFO   : voco: ERROR:rumqtt::client              : snips-hotword|2026-gateway-1 Disconnected: (Error(Msg("socket closed"), State { next_error: None, backtrace: None }))```
createcandle commented 3 years ago

Your logs seem to indicate you're not actually on the latest version of Voco.

Also, you haven't told me what system you're running this on. Are you using the Raspberry Pi image or something custom?

I also found this: https://github.com/eclipse/paho.mqtt.python/issues/457

pointout commented 3 years ago

Gateway 1.0.0 on Raspberry Pi 3+, I updated to actual version of voco 2.5.9. Same behaviour.

/var/log/moquitto.log.1 shows several times:

1612856514: New connection from ::1 on port 1883.
1612856514: New client connected from ::1 as snips-nlu|1950-gateway-1 (c0, k10).
1612856514: New connection from ::1 on port 1883.
1612856514: New client connected from ::1 as snips-hotword|1952-gateway-1 (c0, k10).
1612856515: Socket error on client snips-audio-server|1941-gateway-1, disconnecting.
service --status-all
[ - ]  mosquitto

My workaround is starting mosquitto -d and then deactivating and activating voco.

createcandle commented 3 years ago

Thanks. Interesting, since on the Raspberry Pi it should work well. Do you get the sense that Voco is causing Mosquitto to crash?

TobiBu commented 3 years ago

Hi,

I encountered the same issue on a raspberry Pi 4. Since a couple of days voco is not responding. Only diabling and enabling it again plays the usual "Hello, I am listening." sound but no feedback sound nor voice recognition or timer features work.

Log files say the following: 2021-02-21 00:03:06.056 INFO : voco: Error creating MQTT client connection: [Errno 111] Connection refused

and: `2021-02-21 12:56:30.038 INFO : voco: ERROR, rapidfuzz is not installed. try 'pip3 install rapidfuzz' 2021-02-21 12:56:30.039 INFO : voco: ERROR, alsaaudio is not installed. try 'pip3 install alsaaudio'

2021-02-21 13:21:25.885 INFO : voco: self.persistent_data['mqtt_server'] = localhost 2021-02-21 13:21:25.887 INFO : voco: This device is NOT a satellite, so MQTT client is connecting to 127.0.0.1:1883 2021-02-21 13:21:25.889 INFO : voco: Error creating MQTT client connection: [Errno 111] Connection refused`

and some error like this:

2021-02-21 13:32:39.112 INFO : Loading add-on: voco 2021-02-21 13:32:40.221 INFO : voco: numid=1,iface=MIXER,name='Headphone Playback Volume' 2021-02-21 13:32:40.223 INFO : voco: ; type=INTEGER,access=rw---R--,values=1,min=-10239,max=400,step=0 2021-02-21 13:32:40.224 INFO : voco: : values=-663 2021-02-21 13:32:40.225 INFO : voco: | dBscale-min=-102.39dB,step=0.01dB,mute=1 2021-02-21 13:33:49.939 ERROR : (node:879) MaxListenersExceededWarning: Possible EventEmitter memory leak detected. 11 event listeners added. Use emitter.setMaxListeners() to increase limit

Following the recommendation above of diabling voco and enabling it again does not help. Nor does a reboot with voco disabled work for me. Any help is highly appreciated.

pointout commented 3 years ago

In my case I had to start mosquitto manualy:

  1. Login to your raspi by ssh

    • enable ssh in "settings" - "developer".
    • Then make a ssh connection
    • standard user is "pi", standard Password is "raspberry"

  2. check if the mosquitto service is running with the command: service --status-all

    • if the list shows [ - ] mosquitto, you have to start it manualy by the command mosquitto -d

  3. Then disable voco and enable it again.

You have to do it after ervery re/boot, if the mosquitto service stopped the work.

pointout commented 3 years ago

@createcandle: I have deinstalled voco and made a reboot only with the Z-Wave and Zigbee add-on installed. (I have no z-wave dongle installed, but I think z-wave is enabled by default). The mosquitto service was not running, but I can switch my Zigbee-Ikea-Plugs with the webthings things buttons. The Voice-Controll thing is still present in the things menu, but as "not connected", although the voco add-on is deinstalled. The journalctl -xe command shows:

Feb 21 17:53:24 gateway run-app.sh[639]: 2021-02-21 17:53:24.491 INFO   : zigbee-adapter: ----- Update Network Addresses Complete -----
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.546 ERROR  : Failed to get property volume: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.548 ERROR  : Failed to get property status: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.550 ERROR  : Failed to get property listening: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.552 ERROR  : Failed to get property feedback-sounds: getProperty: device: voco not found
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.554 ERROR  : Failed to get property timer: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.556 ERROR  : Failed to get property alarm: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.558 ERROR  : Failed to get property reminder: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.560 ERROR  : Failed to get property countdown: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.562 ERROR  : Failed to get property audio_output: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.564 ERROR  : Failed to get property sound_detected: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.602 ERROR  : Failed to get property volume: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.605 ERROR  : Failed to get property status: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.607 ERROR  : Failed to get property listening: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.609 ERROR  : Failed to get property feedback-sounds: getProperty: device: voco not found
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.611 ERROR  : Failed to get property timer: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.612 ERROR  : Failed to get property alarm: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.614 ERROR  : Failed to get property reminder: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.617 ERROR  : Failed to get property countdown: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.618 ERROR  : Failed to get property audio_output: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.620 ERROR  : Failed to get property sound_detected: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.797 ERROR  : Failed to get property volume: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.799 ERROR  : Failed to get property status: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.801 ERROR  : Failed to get property listening: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.802 ERROR  : Failed to get property feedback-sounds: getProperty: device: voco not found
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.804 ERROR  : Failed to get property timer: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.806 ERROR  : Failed to get property alarm: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.808 ERROR  : Failed to get property reminder: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.810 ERROR  : Failed to get property countdown: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.812 ERROR  : Failed to get property audio_output: getProperty: device: voco not found.
Feb 21 17:53:28 gateway run-app.sh[639]: 2021-02-21 17:53:28.814 ERROR  : Failed to get property sound_detected: getProperty: device: voco not found.
Feb 21 17:54:12 gateway systemd[1]: mosquitto.service: Start operation timed out. Terminating.
Feb 21 17:54:12 gateway systemd[1]: mosquitto.service: Main process exited, code=killed, status=15/TERM
-- Subject: Unit process exited
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- An ExecStart= process belonging to unit mosquitto.service has exited.
--
-- The process' exit code is 'killed' and its exit status is 15.
Feb 21 17:54:12 gateway systemd[1]: mosquitto.service: Failed with result 'timeout'.
-- Subject: Unit failed
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- The unit mosquitto.service has entered the 'failed' state with result 'timeout'.
Feb 21 17:54:12 gateway systemd[1]: Failed to start Mosquitto MQTT v3.1/v3.1.1 Broker.
-- Subject: A start job for unit mosquitto.service has failed
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- A start job for unit mosquitto.service has finished with a failure.
--
-- The job identifier is 85 and the job result is failed.

Then I reinstalled voco and my old settings were restored, because the config was still present. journalctl -xe :

Feb 21 18:09:40 gateway run-app.sh[639]: 2021-02-21 18:09:40.480 INFO   : Fetching add-on https://github.com/createcandle/voco/releases/download/2.6.
Feb 21 18:10:06 gateway run-app.sh[639]: 2021-02-21 18:10:06.525 INFO   : Expanding add-on /tmp/8jI9RH/voco.tar.gz
Feb 21 18:10:47 gateway systemd[1]: mosquitto.service: Start operation timed out. Terminating.
Feb 21 18:10:47 gateway systemd[1]: mosquitto.service: Main process exited, code=killed, status=15/TERM
-- Subject: Unit process exited
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- An ExecStart= process belonging to unit mosquitto.service has exited.
--
-- The process' exit code is 'killed' and its exit status is 15.
Feb 21 18:10:47 gateway systemd[1]: mosquitto.service: Failed with result 'timeout'.
-- Subject: Unit failed
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- The unit mosquitto.service has entered the 'failed' state with result 'timeout'.
Feb 21 18:10:47 gateway systemd[1]: Failed to start Mosquitto MQTT v3.1/v3.1.1 Broker.
-- Subject: A start job for unit mosquitto.service has failed
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- A start job for unit mosquitto.service has finished with a failure.
--
-- The job identifier is 1203 and the job result is failed.
Feb 21 18:10:47 gateway systemd[1]: mosquitto.service: Service RestartSec=100ms expired, scheduling restart.
Feb 21 18:10:47 gateway systemd[1]: mosquitto.service: Scheduled restart job, restart counter is at 12.
-- Subject: Automatic restarting of a unit has been scheduled
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- Automatic restarting of the unit mosquitto.service has been scheduled, as the result for
-- the configured Restart= setting for the unit.
Feb 21 18:10:47 gateway systemd[1]: Stopped Mosquitto MQTT v3.1/v3.1.1 Broker.
-- Subject: A stop job for unit mosquitto.service has finished
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- A stop job for unit mosquitto.service has finished.
--
-- The job identifier is 1265 and the job result is done.
Feb 21 18:10:47 gateway systemd[1]: Starting Mosquitto MQTT v3.1/v3.1.1 Broker...
-- Subject: A start job for unit mosquitto.service has begun execution
-- Defined-By: systemd
-- Support: https://www.debian.org/support
--
-- A start job for unit mosquitto.service has begun execution.
-- The job identifier is 1265.
Feb 21 18:11:06 gateway run-app.sh[639]: 2021-02-21 18:11:06.398 INFO   : Loading add-on: voco
Feb 21 18:11:08 gateway run-app.sh[639]: 2021-02-21 18:11:08.205 ERROR  : Failed to get property volume: getProperty: device: voco not found.
Feb 21 18:11:08 gateway run-app.sh[639]: 2021-02-21 18:11:08.208 ERROR  : Failed to get property status: getProperty: device: voco not found.
Feb 21 18:11:08 gateway run-app.sh[639]: 2021-02-21 18:11:08.210 ERROR  : Failed to get property listening: getProperty: device: voco not found.
Feb 21 18:11:08 gateway run-app.sh[639]: 2021-02-21 18:11:08.212 ERROR  : Failed to get property feedback-sounds: getProperty: device: voco not found
Feb 21 18:11:08 gateway run-app.sh[639]: 2021-02-21 18:11:08.214 ERROR  : Failed to get property timer: getProperty: device: voco not found.
Feb 21 18:11:08 gateway run-app.sh[639]: 2021-02-21 18:11:08.216 ERROR  : Failed to get property alarm: getProperty: device: voco not found.
Feb 21 18:11:08 gateway run-app.sh[639]: 2021-02-21 18:11:08.217 ERROR  : Failed to get property reminder: getProperty: device: voco not found.
Feb 21 18:11:08 gateway run-app.sh[639]: 2021-02-21 18:11:08.219 ERROR  : Failed to get property countdown: getProperty: device: voco not found.
Feb 21 18:11:08 gateway run-app.sh[639]: 2021-02-21 18:11:08.221 ERROR  : Failed to get property audio_output: getProperty: device: voco not found.
Feb 21 18:11:08 gateway run-app.sh[639]: 2021-02-21 18:11:08.223 ERROR  : Failed to get property sound_detected: getProperty: device: voco not found.
Feb 21 18:11:09 gateway sudo[1256]:       pi : TTY=unknown ; PWD=/home/pi/webthings/gateway ; USER=root ; COMMAND=/usr/bin/amixer cset numid=1 90%
Feb 21 18:11:09 gateway sudo[1256]: pam_unix(sudo:session): session opened for user root by (uid=0)
Feb 21 18:11:09 gateway sudo[1256]: pam_unix(sudo:session): session closed for user root
Feb 21 18:11:09 gateway run-app.sh[639]: 2021-02-21 18:11:09.756 INFO   : voco: numid=1,iface=MIXER,name='Headphone Playback Volume'
Feb 21 18:11:09 gateway run-app.sh[639]: 2021-02-21 18:11:09.758 INFO   : voco:   ; type=INTEGER,access=rw---R--,values=1,min=-10239,max=400,step=0
Feb 21 18:11:09 gateway run-app.sh[639]: 2021-02-21 18:11:09.760 INFO   : voco:   : values=-663
Feb 21 18:11:09 gateway run-app.sh[639]: 2021-02-21 18:11:09.761 INFO   : voco:   | dBscale-min=-102.39dB,step=0.01dB,mute=1

Voco got all my settings from the previous installation of the add-on. I did my workaround and voco worked again. Could it be that not removing the voco thing is causing the troubles when voco is reinstalled?

@TobiBu Did you deinstall and install voco again before voco was not answering?

createcandle commented 3 years ago

@pointout thank you for the detailed log. I'm trying to figure out what could be the issue. I've created a new version that at least gets rid of some remaining Rapidfuzz library loading. Perhaps that will help. As a test I installed that version of Voco on a fresh gateway on a Raspberry Pi 4, and it seemed to work fine.

@TobiBu the MaxListenersExceededWarning warning is (as far as I understand) not an issue.

pointout commented 3 years ago

@createcandle thank you for your great work. I will test the update as soon as it is in the webthings add-on list. In my gateway I still see 2.6.0

TobiBu commented 3 years ago

In my case I had to start mosquitto manualy:

  1. Login to your raspi by ssh
  • enable ssh in "settings" - "developer".
  • Then make a ssh connection
  • standard user is "pi", standard Password is "raspberry"
  1. check if the mosquitto service is running with the command: service --status-all
  • if the list shows [ - ] mosquitto, you have to start it manualy by the command mosquitto -d
  1. Then disable voco and enable it again.

You have to do it after ervery re/boot, if the mosquitto service stopped the work.

Hi, Thanks a lot for this info. However, I tried to start mosquitto manually but this does not seem to work for me. It still shows the [-] after running mosquitto -d

Any ideas what might cause this?

createcandle commented 3 years ago

Could you try this and see what happens?

  1. Disable voco

  2. Enter this command in the `seashell addon

rm ~/.webthings/data/voco/persistence.json

That will remove the persistent data.

  1. Re-enable voco.

This is like a fresh install. You'll have to copy the authorization code again for example.

pointout commented 3 years ago

@TobiBu That's correct, but you should have a running process of mosquitto under the user pi:

pi@gateway:~ $ sudo ps aux | grep mosqu
pi        2478  0.8  0.2   8804  2812 ?        Ss   Feb21 138:48 mosquitto -d
root     20091  100  2.5  28620 24452 ?        Rs   16:13   0:30 /usr/sbin/mosq itto -c /etc/mosquitto/mosquitto.conf
pi       20100  0.0  0.0   7348   504 pts/0    S+   16:14   0:00 grep --color=auto mosqu
pointout commented 3 years ago

@createcandle I still have only Version 2.6.0 in the gateway addon list. I deactivated voco, killed the mosquitto (user pi) process, removed the persistence.json, activated voco. Same as before. Voco is saying, that it is listening, but does not. I also reinstalled voco. The same. I'll try again, when the update 2.6.1 is shown.

just for info: vim shows:"~/.webthings/data/voco/persistence.json" [Incomplete last line] 1 line, 898964 characters, when I open the persistence.json file.

createcandle commented 3 years ago

Did the later version solve the issue?

pointout commented 3 years ago

I have V 2.6.1 installed and still have to start mosquitto manually after reboot.

createcandle commented 2 years ago

I believe I may have figured out what this issue was. Mosquitto was running with persistence enabled. At some point this could lead to HUGE backlogs of data that Mosquitto is hoarding, which causes it to crash.

This issue is preventatively fixed in the upcoming Candle 2.0 release.