PiCroft - responds immediate to wake word, takes 3+ minutes for audio response


#1

I have a fresh install of the latest Picroft image on my RPi 3B+. I’m using the Playstation Eye and a 3.5MM Audio Out which I’ve confirmed work correctly via the Setup Wizard.

When I say “hey mycroft”, I get the audio confirmation it’s listening, and even see my statement (e.g. “What time is it”) in the logs in the CLI-Client.

In the CLI-Client, I also immediately (well, within 3 seconds or so), see the Response (“It is eighteen thirty” or whatever). However, the audio response takes at least three minutes to come through…sometimes I’d say even 10 minutes.

What could be causing such a delay? The only USB I have plugged in the Pi is the Playstation Eye, and I’m using a 5V 3Amp power supply, so wouldn’t think it’s a power issue.

I’ve restarted the PiCroft a few times, no luck. What might I be overlooking?

Edit: I’m using the “Google Voice”.

Also, just to mention - after I say “Hey Mycroft” and give a command (“What time is it”), I can pretty quickly say “Hey Mycroft” and it’ll make the “listening noise” again. So (as evidenced by the CLI Client too), it’s not like it’s stuck processing my request (I can make say five requests back to back), I just don’t hear the audio response for a long time…


#2

what voice are you using?


#3

Google Voice. (I’ve also edited my OP with a little more info)


#4

The audio log will show the call and response for the reply. Does the call show the delay or the response itself?

Have you tried with a different voice?


#5

The audio log (viewed via ssh into the Picroft and using ``tail -n 200 audio.log) shows:

22:57:25.599 - mycroft.audio.speech:mute_and_speak:128 - INFO - Speak: [the response here]

But I didn’t actually hear that response until about 23:03:00…

I’ve just changed the voice via the Panel on the mycroft.ai site, will reboot and let you know.

Edit: Changed from the Google Voice to “American Male”, and the lag seems to have gone away. …perhaps it’s an issue with the Google Voice? Is that a known issue or is it still something up with my local machine?


#6

It does sound like a lag in the audio response from Google voice, these are proxied through Mycroft servers to anonymise them from Google but American Male is being served from the same location.

It looks like from your messages this was happening over a period of time, so not just a short term bottleneck somewhere, is that right?


#7

Yes, it’s happening over a period of time. Meaning, it happened on say Saturday, so I re-formatted and flashed the SD Card to test a “fresh” copy, and it happened again. (Both times using “Google Voice”).

Last night it was seemingly working quicker with the “American Male”, but I’ll test that more today.

(FWIW, even with “American Male” I asked “What is the latest news”, and it pretty quickly replied “Here is this hours’ news from NPR One”, but then took I’d guess at least 30 minutes for it to actually load the NPR audio…but I assume that’s a different issue.)


#8

What sort of internet connection are you on? What’s your average download, upload speeds and ping response time?

The NPR audio feed loads directly from their site so would be a different but potentially related issue.


#9

Advertised, 300 MB down but just ran a test, average 150MB down and 120.77 Up.


#10

O_o jealous!

That clearly is not the problem then…

For the NPR News delay, is the Playback Control Skill triggering and then the long delay before playback starts, or is it hanging prior to that? Eg saying “play NPR News” should result in:

04:07:58.546 - Playback Control Skill - INFO - Resolving Player for: NPR News
04:08:03.461 - Playback Control Skill - INFO - Playing with: mycroft-npr-news.mycroftai
04:08:04.374 - NewsSkill - INFO - Playing news from URL: https://play.podtrac.com/npr-500005/edge1.pod.npr.org/anon.npr-mp3/npr/newscasts/2019/08/28/newscast220811.mp3?awCollectionId=500005&awEpisodeId=755274649&orgId=1&d=300&p=500005&story=755274649&t=podcast&e=755274649&size=4500000&ft=pod&f=500005
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   360  100   360    0     0    310      0  0:00:01  0:00:01 --:--:--   310
  0     0    0     0    0     0      0      0 --:--:--  0:00:02 --:--:--     0
  3 4368k    3  144k    0     0  20009      0  0:03:43  0:00:07  0:03:36 32111

I’ve also set my Picroft to Google Voice and for short responses like the time I’m getting about a 3-5 second lag. The length of the response will change how long it takes to synthesise the response audio but nothing should be taking 3 minutes.

It seems like it must be a local issue. I know you said at the top you were using the latest Picroft image, but can I confirm this is the one dated 2019-07-20?


#11

So at 17:53 I said “Play NPR” and it said the usual “Here’s this hours’ news on NPR”. Even at 18:00 it wasn’t playing the news, so I rebooted.

Here’s the log from that (this is from audio.log):

01:52:59.293 - AlarmSkill - INFO - on started...
01:53:02.195 - AlarmSkill - INFO - on ended...
01:53:03.860 - Playback Control Skill - INFO - Resolving Player for: npr
01:53:08.337 - Playback Control Skill - INFO - Playing with: mycroft-npr-news.mycroftai
01:53:08.830 - NewsSkill - INFO - Playing news from URL: https://play.podtrac.com/npr-500005/edge1.pod.npr.org/anon.npr-mp3/npr/newscasts/2019/08/29/newscast200813.mp3?awCollectionId=500005&awEpisodeId=755660242&orgId=1&d=300&p=500005&story=755660242&t=podcast&e=755660242&size=4500000&ft=pod&f=500005
01:53:13.017 - ConfigurationSkill - INFO - Remote configuration updated

(I’m not sure how to best view logs like you did. I ssh’ed in to the PiCroft, did cd /var/log/mycroft, then did tail -20 skills.log).

Edit: The news started playing at18:11 and I believe this was the output when it did:

  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   360  100   360    0     0   1058      0 --:--:-- --:--:-- --:--:--  1058
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0

#12

Yeah tail -f /var/log/mycroft/skills.log is my go to command.
The -f flag is for follow so the terminal will output new log messages as they are written to the file.
Edit: or if you’re talking about the pretty code output here, you can place code between three backticks like this:
```
Some code
```

Back to the task at hand though, was there anything in skills.log between these two blocks:

01:53:08.830 - NewsSkill - INFO - Playing news from URL: ...
01:53:13.017 - ConfigurationSkill - INFO - Remote configuration updated

???

  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   360  100   360    0     0   1058      0 --:--:-- --:--:-- --:--:--  1058
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0

#13

Thanks for your continued help!

Nope, it doesn’t look like anything was between the two. (Note I don’t have the ConfigurationSkill bit either, but assume that’s independent of the NewsSkill loading).

From voice.log:

17:12:03.974 - main:handle_wakeword:57 - INFO - Wakeword Detected: hey mycroft
17:12:05.609 - main:handle_utterance:62 - INFO - Utterance: [“what’s the news”]

and skills.log:

17:18:41.954 - NewsSkill - INFO - Playing news from URL: https://play.podtrac.com/npr-500005/...
  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   360  100   360    0     0   1042      0 --:--:-- --:--:-- --:--:--  1040
  0     0    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
 11 4368k   11  513k    0     0  17718      0  0:04:12  0:00:29  0:03:43 1618919:33:29.398 - mycroft.messagebus.load_config:load_message_bus_config:33 - INFO - Loading message bus configs

I don’t recall (sorry!) if the news audio was just 6 minutes after my request, but I’d think it was closer to 15…but the skills.log I assume do correctly show the time the news started playing? Or is that part simply the time the request was made to fetch the URL - and the audio indeed could have been further delayed?