OpenVoiceOS / ovos-listener

ovos-core metapackage for speech daemon
Apache License 2.0
1 stars 1 forks source link

Service get "stuck" and doesn't listen anymore #12

Closed goldyfruit closed 8 months ago

goldyfruit commented 1 year ago

Very randomly, the listener service get stuck, consuming CPU resources. I was not able to really pinpoint the issue but it seems that the service is looping waiting for something.

Here are the logs when it started to not been responsive anymore.

2023-04-17 08:17:02.984 - voice - ovos_bus_client.session:reset_default_session:171 - INFO - New Default Session Start: 163bd72c-3261-4dd0-b5cc-dce57b92cbd0
2023-04-17 08:17:02.989 - voice - ovos_listener.service:handle_wakeword:98 - INFO - Wakeword Detected: hey_mycroft
2023-04-17 08:17:03.007 - voice - ovos_listener.mic:_listen_phrase:950 - DEBUG - Recording...
2023-04-17 08:17:03.009 - voice - ovos_listener.service:handle_record_begin:72 - INFO - Begin Recording...
2023-04-17 08:17:05.369 - voice - ovos_listener.mic:_listen_phrase:956 - INFO - Saving Utterance Recording
2023-04-17 08:17:05.373 - voice - ovos_listener.service:handle_record_end:79 - INFO - End Recording...
2023-04-17 08:17:05.375 - voice - ovos_listener.mic:listen:944 - DEBUG - Thinking...
2023-04-17 08:17:05.399 - voice - ovos_utils.sound:play_end_listening_sound:77 - DEBUG - Could not find 'end_listening' audio file!
2023-04-17 08:17:05.618 - voice - ovos_listener.mic:adjust_for_ambient_noise:976 - INFO - Silence threshold adjusted to 24.0
2023-04-17 08:17:05.620 - voice - ovos_listener.mic:listen:899 - DEBUG - Waiting for wake word...
2023-04-17 08:17:07.692 - voice - ovos_listener:transcribe:211 - DEBUG - STT: what time is it
2023-04-17 08:17:07.695 - voice - ovos_listener.service:handle_utterance:119 - INFO - Utterance: ['what time is it']

And here is a strace Python ovos_listener service.

futex(0x7f7400de40, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0xa3676c, FUTEX_WAKE_PRIVATE, 1)  = 1
openat(AT_FDCWD, "/tmp/mycroft/ipc/mic_level", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 13
futex(0xa36768, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=211159, tv_nsec=204258892}, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable)
futex(0xa36770, FUTEX_WAKE_PRIVATE, 1)  = 0
futex(0xa36770, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0xa36770, FUTEX_WAKE_PRIVATE, 1)  = 0
newfstatat(13, "", {st_mode=S_IFREG|0644, st_size=0, ...}, AT_EMPTY_PATH) = 0
futex(0xa36768, FUTEX_WAKE_PRIVATE, 1)  = 0
ioctl(13, TCGETS, 0x7eca7ce450)         = -1 ENOTTY (Inappropriate ioctl for device)
futex(0xa3676c, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=211159, tv_nsec=205143627}, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable)
futex(0xa36770, FUTEX_WAIT_PRIVATE, 2, NULL) = 0
futex(0xa36770, FUTEX_WAKE_PRIVATE, 1)  = 0
futex(0xa36768, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=211159, tv_nsec=205437200}, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable)
futex(0xa36770, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0xa36770, FUTEX_WAKE_PRIVATE, 1)  = 0
futex(0xa3676c, FUTEX_WAKE_PRIVATE, 1)  = 0
futex(0xa36770, FUTEX_WAKE_PRIVATE, 1)  = 0
lseek(13, 0, SEEK_CUR)                  = 0
futex(0xa36768, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=211159, tv_nsec=206127325}, FUTEX_BITSET_MATCH_ANY) = 0
futex(0xa36770, FUTEX_WAKE_PRIVATE, 1)  = 0
futex(0xa3676c, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=211159, tv_nsec=206449545}, FUTEX_BITSET_MATCH_ANY) = 0
futex(0xa36770, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0xa36770, FUTEX_WAKE_PRIVATE, 1)  = 0
futex(0xa36768, FUTEX_WAKE_PRIVATE, 1)  = 1
lseek(13, 0, SEEK_CUR)                  = 0
futex(0xa3676c, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=211159, tv_nsec=207118800}, FUTEX_BITSET_MATCH_ANY) = 0
futex(0xa36770, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0xa36770, FUTEX_WAKE_PRIVATE, 1)  = 0
futex(0xa36768, FUTEX_WAKE_PRIVATE, 1)  = 1
write(13, "Energy:  cur=82 thresh=300.000 m"..., 38) = 38
futex(0xa3676c, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=211159, tv_nsec=207764981}, FUTEX_BITSET_MATCH_ANY) = -1 EAGAIN (Resource temporarily unavailable)
futex(0xa36770, FUTEX_WAIT_PRIVATE, 2, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0xa36770, FUTEX_WAKE_PRIVATE, 1)  = 0
futex(0xa36768, FUTEX_WAKE_PRIVATE, 1)  = 1
close(13)                               = 0
futex(0x7eb4083f50, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = 0
futex(0xa3676c, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=211159, tv_nsec=236187850}, FUTEX_BITSET_MATCH_ANY) = 0
futex(0xa36770, FUTEX_WAKE_PRIVATE, 1)  = 0
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce360, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce300, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/home/ovos/.mycroft/mycroft.conf", 0x7eca7ce320, 0) = -1 ENOENT (No such file or directory)
newfstatat(AT_FDCWD, "/tmp/mycroft/ipc", {st_mode=S_IFDIR|0777, st_size=4096, ...}, 0) = 0
newfstatat(AT_FDCWD, "/tmp/mycroft/ipc/signal/buttonPress", 0x7eca7ce640, 0) = -1 ENOENT (No such file or directory)
futex(0x7f7400de40, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x7eb4083f50, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 0, NULL, FUTEX_BITSET_MATCH_ANY) = 0
futex(0xa36768, FUTEX_WAIT_BITSET_PRIVATE, 0, {tv_sec=211159, tv_nsec=321670439}, FUTEX_BITSET_MATCH_ANY) = 0
futex(0xa36770, FUTEX_WAKE_PRIVATE, 1)  = 0

I got this forever in strace log.

For some reason, the service seems to look for this /home/ovos/.mycroft/mycroft.conf file which doesn't not exist but I don't think this is the issue.

JarbasAl commented 1 year ago

do you have a VAD plugin enabled? might be the same as https://github.com/OpenVoiceOS/ovos-listener/issues/17 (undiagnosed)

goldyfruit commented 1 year ago

do you have a VAD plugin enabled? might be the same as OpenVoiceOS/ovos-listener#17 (undiagnosed)

Yes I do, the webrtcvad plugin but the plugin is correctly loaded.

JarbasAl commented 1 year ago

did you have wakeword/utterance upload enabled?

could this be coming from https://github.com/OpenVoiceOS/ovos-backend-client/issues/36

goldyfruit commented 1 year ago
│ listener                                                     │                                                                                                                                                                             │
│     sample_rate                                              │ 16000                                                                                                                                                                       │
│     mic_meter_ipc                                            │ False                                                                                                                                                                       │
│     record_wake_words                                        │ True                                                                                                                                                                        │
│     save_utterances                                          │ True                                                                                                                                                                        │
│     wake_word_upload                                         │                                                                                                                                                                             │
│         disable                                              │ True                                                                                                                                                                        │
│         url                                                  │                                                                                                                                                                             │
│     VAD                                                      │                                                                                                                                                                             │
│         silence_method                                       │ vad_and_ratio                                                                                                                                                               │
│         speech_seconds                                       │ 0.1                                                                                                                                                                         │
│         silence_seconds                                      │ 0.5                                                                                                                                                                         │
│         before_seconds                                       │ 0.5                                                                                                                                                                         │
│         min_seconds                                          │ 1                                                                                                                                                                           │
│         max_current_ratio_threshold                          │ 2                                                                                                                                                                           │
│         initial_energy_threshold                             │ 1000.0                                                                                                                                                                      │
│         module                                               │ ovos-vad-plugin-silero                                                                                                                                                      │
│         ovos-vad-plugin-silero                               │                                                                                                                                                                             │
│             threshold                                        │ 0.2                                                                                                                                                                         │
│         ovos-vad-plugin-webrtcvad                            │                                                                                                                                                                             │
│             vad_mode                                         │ 3                                                                                                                                                                           │
│         ovos-vad-plugin-precise                              │                                                                                                                                                                             │
│             debug                                            │ True                                                                                                                                                                        │
│     retry_mic_init                                           │ True                                                                                                                                                                        │
│     mute_during_output                                       │ False                                                                                                                                                                       │
│     duck_while_listening                                     │ 0.3                                                                                                                                                                         │
│     phoneme_duration                                         │ 120                                                                                                                                                                         │
│     multiplier                                               │ 1.0                                                                                                                                                                         │
│     energy_ratio                                             │ 1.5                                                                                                                                                                         │
│     wake_word                                                │ hey_mycroft                                                                                                                                                                 │
│     stand_up_word                                            │ wake_up                                                                                                                                                                     │
│     recording_timeout                                        │ 10.0                                                                                                                                                                        │
│     recording_timeout_with_silence                           │ 0.8                                                                                                                                                                         │
│     instant_listen                                           │ True                                                                                                                                                                        │
│     continuous_listen                                        │ False                                                                                                                                                                       │
│     hybrid_listen                                            │ False                                                                                                                                                                       │
│     listen_timeout                                           │ 45      
j1nx commented 1 year ago

Can you reproduce the issue with a restart of PulseAudio?

goldyfruit commented 1 year ago

Can you reproduce the issue with a restart of PulseAudio?

Yes, this is the same behaviour as when PulseAudio or PipeWire are restarted except that when it happens, I got a specific message in the logs:

Expression 'alsa_snd_pcm_poll_descriptors_revents( self->pcm, pfds, self->nfds, &revents )' failed in 'src/hostapi/alsa/pa_linux_alsa.c', line: 3665
Expression 'PaAlsaStreamComponent_EndPolling( &self->capture, capturePfds, &pollCapture, &xrun )' failed in 'src/hostapi/alsa/pa_linux_alsa.c', line: 3887
Expression 'PaAlsaStream_WaitForFrames( stream, &framesAvail, &xrun )' failed in 'src/hostapi/alsa/pa_linux_alsa.c', line: 4285
j1nx commented 1 year ago

So basically, an error occurs within the audio system making the voice service not reconnecting anymore.

In this case, the sound system most likely quickly recovers itself and just carry on, however when the voice service looses connection, it never re-connect again.

It is an old problem that surfaces.

This can be solved by some sort of microphone watchdog that quickly reconnects and/or restarts when it looses connection to the microphone. This does not solve the underlying reason of the sound system error, but sound issues/errors can happen often for different reasons without any clear cause. However the voice service should be able to identify that it lost microphone connection and recover from it.

goldyfruit commented 1 year ago

It is an old problem that surfaces.

I guess it would be valuable as well for the audio service.