Picroft aborts speeking since 19.02 update

Wiggins · March 10, 2019, 6:29pm

I am running Picroft on Model 3B+ with the Google AIY kit. Since the 19.02 update it will only speak a certain amount of text, answers get cut off. Although no sound is playing the message bus indicates that Picroft is still speaking because the button continues to flash.

For example, if I ask “who is chuck norris” the spoken response is “Carlos Ray Norris is an American martial artist, actor, film producer”, cutting off the last two words (“and screenwriter”)… This is 100% reproducible.

I’ve tried running mimic from the command line with a text file as input and it correctly speaks the entire content. The Picroft audio log shows the complete text.

gez-mycroft · March 12, 2019, 12:28am

Hi Wiggins,

Needless to say that should not be happening. Can you ask your Mycroft to “Create a support ticket”?

This will upload your logs to Termbin and email you a link. If you can either post that here, or if you’d prefer send it to support [at] mycroft.ai so we can take a look at what else might be going on in the background.

Wiggins · March 12, 2019, 2:11am

OK, thanks, I emailed the logs to support.

forslund · March 19, 2019, 4:05pm

Hi @Wiggins most interesting bug there. Can’t quite figure out a good explanation for this behaviour.

Are you running the local mimic tts (Alan Pope voice / British Male)? If so is there any difference if you run the American Male (mimic2) voice? (select on home.mycroft.ai)

For the 19.02 we did a slight change in how the playback thread waits for audio completion. But even if the audio player exited prematurely it shouldn’t be able to interfere with single sentence output. I will test the phrase on my picroft and see if I can reproduce.

Olaf · March 19, 2019, 7:15pm

Same problem here with a newly installed Picroft on 19.2.1 when asked about Shakespeare:

19:06:50.494 - mycroft.audio.speech:mute_and_speak:122 - INFO - Speak: William Shakespeare is an English poet, playwright and actor, widely regarded as the greatest writer in the English.

Audio output stops after “regarded” and other output of similar length.

Logs can be found here

Just changed mimic voice to kal and had the same problem, aborted sentence. And the same for mimic2 with American Male (beta).

gez-mycroft · March 19, 2019, 8:47pm

Hi Olaf, are you also using the AIY Kit or is this just standard Picroft?

Wiggins · March 20, 2019, 1:54am

Here’s the summary of my situation:

Pi Model 3B+ with Google AIY hat
using local Mimic
Before 19.-02 branch everything working fine
After update mycroft audio is cut off
To accommodate AIY, play command in mycroft.conf set to: “play_wav_cmdline”: “aplay %1”
running aplay from command line plays complete audio
using a cached mycroft wav file, “aplay file.wav” on command line plays complete file
using “play -d5 file.wav” plays as I hear it from mycroft
have been testing with “who is chuck norris” and “who is steve jobs” (apporx. 100 times each) and cuts off at the same place every time
also happens on other skills

I also tried Olaf’s Shakespeare test with an identical result.

It occurred to me that on at least one install of the older version I had built Mimic from source so I tried that again but nothing changed. Anyway, Mimic cannot be the problem if valid WAV files are created, right?

Olaf · March 20, 2019, 9:41am

Same as @Wiggins, 3B+ with AIY, freshly installed on Sunday

forslund · March 20, 2019, 5:55pm

Hmm, I did a try with my picroft I don’t have the AIY-voicekit but I tried installing the aiy skill and changing the play_wav_cmdline to match yours but could not reproduce.

Can you try switching over to paplay instead of aplay (if pulseaudio is installed)?

/Å

Wiggins · March 21, 2019, 1:56am

No luck with paplay.

It might be worth repeating that the button continues to flash (based on the message bus) until the audio would have stopped playing if it played through.

zelt195r · March 24, 2019, 5:16pm

I am having the same problem…mycrofts stops speaking in the middle of a sentence. I have the google aiy hat. The older version of mycroft worked fine but after updating to the new version the problem started. i also tried changing the play with paplay but no difference.

forslund · March 25, 2019, 8:51am

On Friday I may have found another issue that may be partly related to this. A couple of errors in how mimic2 (American Male) handled long utterances (longer than 70 characters). The issue would only mainly notable on picroft due to slight difference in how sentences are chunked.

(On other devices utterances with multiple sentences are split and each sentence is sent separately to the TTS on picroft they’re treated as a single long text to work around an issue we encountered with alsa)

This is definitely not the whole solution here… As a test could someone try editing mycroft/tts/__init__.py and insert a line

                sleep(5)

after L100.

I wonder if it’s a larger buffer when using the AIY voice hat and that the playback command is somehow terminated before the audio is fully played.

This is very much a shot in the dark since the Light indicator seems to be indicating that playback is still going on…

Dominik · March 25, 2019, 9:28am

I see the problem with my Picroft/AIY and my Mark-I. In addition I have set lang=“de-de” and use Google-TTS, not Mimic2. There are error messages in voice.log when the issue occurs, messages look related to the chunking of the sentences. I can provide logs later today if necessary…

forslund · March 25, 2019, 9:35am

@Dominik do you mean audio.log? (that’s the one handling tts)

Logs are most welcome and any modified config files and example sentences used to trigger the issue.

Dominik · March 25, 2019, 12:14pm

Yes, i meant the audio.log. I can provide log files and examples in a few hours…

Dominik · March 25, 2019, 6:23pm

so here is the audio.log for “wie ist das wetter”:

19:31:29.356 - mycroft.audio.speech:mute_and_speak:122 - INFO - Speak: Es ist gerade Regenschauer und 6 Grad. Das heutige Maximun ist 6 und der Tiefstwert 3.
19:31:29.364 - gtts.tts - DEBUG - slow: False
19:31:29.364 - gtts.tts - DEBUG - slow: False
19:31:29.365 - gtts.tts - DEBUG - lang: de
19:31:29.365 - gtts.tts - DEBUG - lang: de
19:31:29.365 - gtts.tts - DEBUG - pre_processor_funcs: [<function tone_marks at 0x75aa9cd8>, <function end_of_line at 0x75a26108>, <function abbreviations at 0x75a2615
0>, <function word_sub at 0x75a26198>]
19:31:29.365 - gtts.tts - DEBUG - pre_processor_funcs: [<function tone_marks at 0x75aa9cd8>, <function end_of_line at 0x75a26108>, <function abbreviations at 0x75a2615
0>, <function word_sub at 0x75a26198>]
19:31:29.366 - gtts.tts - DEBUG - lang_check: True
19:31:29.366 - gtts.tts - DEBUG - lang_check: True
19:31:29.366 - gtts.tts - DEBUG - tokenizer_func: <bound method Tokenizer.run of re.compile('(?<=\\?).|(?<=\\!).|(?<=\\？).|(?<=\\！).|(?<!\\.[a-z])\\. |(?<!\\.[a-z])\
\, |\\、|\\:|\\—|\\。|\\;|\\\n|\\[|\\)|\\،|\\¿|\\…|\\¡|\\‥|\\]|\\(|\\，|\\：', re.IGNORECASE) from: [<function tone_marks at 0x75a26228>, <function period_comma at 0x7
5a26270>, <function other_punctuation at 0x75a262b8>]>
19:31:29.366 - gtts.tts - DEBUG - tokenizer_func: <bound method Tokenizer.run of re.compile('(?<=\\?).|(?<=\\!).|(?<=\\？).|(?<=\\！).|(?<!\\.[a-z])\\. |(?<!\\.[a-z])\
\, |\\、|\\:|\\—|\\。|\\;|\\\n|\\[|\\)|\\،|\\¿|\\…|\\¡|\\‥|\\]|\\(|\\，|\\：', re.IGNORECASE) from: [<function tone_marks at 0x75a26228>, <function period_comma at 0x7
5a26270>, <function other_punctuation at 0x75a262b8>]>
19:31:29.368 - gtts.tts - DEBUG - text: Es ist gerade Regenschauer und 6 Grad. Das heutige Maximun ist 6 und der Tiefstwert 3.
19:31:29.368 - gtts.tts - DEBUG - text: Es ist gerade Regenschauer und 6 Grad. Das heutige Maximun ist 6 und der Tiefstwert 3.
19:31:29.375 - urllib3.connectionpool - DEBUG - Starting new HTTP connection (1): translate.google.com:80
19:31:29.375 - urllib3.connectionpool - DEBUG - Starting new HTTP connection (1): translate.google.com:80
19:31:29.447 - urllib3.connectionpool - DEBUG - http://translate.google.com:80 "GET / HTTP/1.1" 302 226
19:31:29.447 - urllib3.connectionpool - DEBUG - http://translate.google.com:80 "GET / HTTP/1.1" 302 226
19:31:29.457 - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): translate.google.com:443
19:31:29.457 - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): translate.google.com:443
19:31:29.648 - urllib3.connectionpool - DEBUG - https://translate.google.com:443 "GET / HTTP/1.1" 200 None
19:31:29.648 - urllib3.connectionpool - DEBUG - https://translate.google.com:443 "GET / HTTP/1.1" 200 None
19:31:29.857 - gtts.tts - DEBUG - Unable to get language list: 'NoneType' object is not subscriptable
Traceback (most recent call last):
  File "/opt/venvs/mycroft-core/lib/python3.4/site-packages/gtts/lang.py", line 36, in tts_langs
    langs.update(_fetch_langs())
  File "/opt/venvs/mycroft-core/lib/python3.4/site-packages/gtts/lang.py", line 62, in _fetch_langs
    js_path = soup.find(src=re.compile(JS_FILE))['src']
TypeError: 'NoneType' object is not subscriptable

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/mycroft-core/lib/python3.4/site-packages/gtts/tts.py", line 117, in __init__
    langs = tts_langs()
  File "/opt/venvs/mycroft-core/lib/python3.4/site-packages/gtts/lang.py", line 41, in tts_langs
    raise RuntimeError("Unable to get language list: %s" % str(e))
RuntimeError: Unable to get language list: 'NoneType' object is not subscriptable
19:31:29.857 - gtts.tts - DEBUG - Unable to get language list: 'NoneType' object is not subscriptable
Traceback (most recent call last):
  File "/opt/venvs/mycroft-core/lib/python3.4/site-packages/gtts/lang.py", line 36, in tts_langs
    langs.update(_fetch_langs())
  File "/opt/venvs/mycroft-core/lib/python3.4/site-packages/gtts/lang.py", line 62, in _fetch_langs
    js_path = soup.find(src=re.compile(JS_FILE))['src']
TypeError: 'NoneType' object is not subscriptable
During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/opt/venvs/mycroft-core/lib/python3.4/site-packages/gtts/tts.py", line 117, in __init__
    langs = tts_langs()
  File "/opt/venvs/mycroft-core/lib/python3.4/site-packages/gtts/lang.py", line 41, in tts_langs
    raise RuntimeError("Unable to get language list: %s" % str(e))
RuntimeError: Unable to get language list: 'NoneType' object is not subscriptable
19:31:29.858 - gtts.tts - WARNING - Unable to get language list: 'NoneType' object is not subscriptable
19:31:29.858 - gtts.tts - WARNING - Unable to get language list: 'NoneType' object is not subscriptable
19:31:29.860 - gtts.tts - DEBUG - pre-processing: <function tone_marks at 0x75aa9cd8>
19:31:29.860 - gtts.tts - DEBUG - pre-processing: <function tone_marks at 0x75aa9cd8>
19:31:29.861 - gtts.tts - DEBUG - pre-processing: <function end_of_line at 0x75a26108>
19:31:29.861 - gtts.tts - DEBUG - pre-processing: <function end_of_line at 0x75a26108>
19:31:29.862 - gtts.tts - DEBUG - pre-processing: <function abbreviations at 0x75a26150>
19:31:29.862 - gtts.tts - DEBUG - pre-processing: <function abbreviations at 0x75a26150>
19:31:29.863 - gtts.tts - DEBUG - pre-processing: <function word_sub at 0x75a26198>
19:31:29.863 - gtts.tts - DEBUG - pre-processing: <function word_sub at 0x75a26198>
19:31:29.863 - gtts.tts - DEBUG - text_parts: 1
19:31:29.863 - gtts.tts - DEBUG - text_parts: 1
19:31:29.869 - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): translate.google.com:443
19:31:29.869 - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): translate.google.com:443
19:31:30.063 - urllib3.connectionpool - DEBUG - https://translate.google.com:443 "GET / HTTP/1.1" 200 None
19:31:30.063 - urllib3.connectionpool - DEBUG - https://translate.google.com:443 "GET / HTTP/1.1" 200 None
19:31:30.121 - gtts.tts - DEBUG - payload-0: {'textlen': 86, 'client': 'tw-ob', 'ttsspeed': 1, 'tk': '988152.624202', 'q': 'Es ist gerade Regenschauer und 6 Grad. Das heutige Maximun ist 6 und der Tiefstwert 3.', 'idx': 0, 'ie': 'UTF-8', 'total': 1, 'tl': 'de'}
19:31:30.121 - gtts.tts - DEBUG - payload-0: {'textlen': 86, 'client': 'tw-ob', 'ttsspeed': 1, 'tk': '988152.624202', 'q': 'Es ist gerade Regenschauer und 6 Grad. Das heutige Maximun ist 6 und der Tiefstwert 3.', 'idx': 0, 'ie': 'UTF-8', 'total': 1, 'tl': 'de'}
19:31:30.131 - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): translate.google.com:443
19:31:30.131 - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): translate.google.com:443
19:31:30.464 - urllib3.connectionpool - DEBUG - https://translate.google.com:443 "GET /translate_tts?textlen=86&client=tw-ob&ttsspeed=1&tk=988152.624202&q=Es+ist+gerade+Regenschauer+und+6+Grad.+Das+heutige+Maximun+ist+6+und+der+Tiefstwert+3.&idx=0&ie=UTF-8&total=1&tl=de HTTP/1.1" 200 30624
19:31:30.464 - urllib3.connectionpool - DEBUG - https://translate.google.com:443 "GET /translate_tts?textlen=86&client=tw-ob&ttsspeed=1&tk=988152.624202&q=Es+ist+gerade+Regenschauer+und+6+Grad.+Das+heutige+Maximun+ist+6+und+der+Tiefstwert+3.&idx=0&ie=UTF-8&total=1&tl=de HTTP/1.1" 200 30624
19:31:30.497 - gtts.tts - DEBUG - headers-0: {'Referer': 'http://translate.google.com/', 'Accept-Encoding': 'gzip, deflate', 'User-Agent': 'Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/47.0.2526.106 Safari/537.36', 'Accept': '*/*', 'Connection': 'keep-alive'}
19:31:30.497 - gtts.tts - DEBUG - headers-0: {'Referer': 'http://translate.google.com/', 'Accept-Encoding': 'gzip, deflate', 'User-Agent': 'Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/47.0.2526.106 Safari/537.36', 'Accept': '*/*', 'Connection': 'keep-alive'}
19:31:30.498 - gtts.tts - DEBUG - url-0: https://translate.google.com/translate_tts?textlen=86&client=tw-ob&ttsspeed=1&tk=988152.624202&q=Es+ist+gerade+Regenschauer+und+6+Grad.+Das+heutige+Maximun+ist+6+und+der+Tiefstwert+3.&idx=0&ie=UTF-8&total=1&tl=de
19:31:30.498 - gtts.tts - DEBUG - url-0: https://translate.google.com/translate_tts?textlen=86&client=tw-ob&ttsspeed=1&tk=988152.624202&q=Es+ist+gerade+Regenschauer+und+6+Grad.+Das+heutige+Maximun+ist+6+und+der+Tiefstwert+3.&idx=0&ie=UTF-8&total=1&tl=de
19:31:30.499 - gtts.tts - DEBUG - status-0: 200
19:31:30.499 - gtts.tts - DEBUG - status-0: 200
19:31:30.500 - gtts.tts - DEBUG - part-0 written to <_io.BufferedWriter name='/tmp/mycroft/cache/tts/e3b13207a90ba10e8402fa11eb72ad27.mp3'>
19:31:30.500 - gtts.tts - DEBUG - part-0 written to <_io.BufferedWriter name='/tmp/mycroft/cache/tts/e3b13207a90ba10e8402fa11eb72ad27.mp3'>
19:31:30.501 - gtts.tts - DEBUG - Saved to /tmp/mycroft/cache/tts/e3b13207a90ba10e8402fa11eb72ad27.mp3
19:31:30.501 - gtts.tts - DEBUG - Saved to /tmp/mycroft/cache/tts/e3b13207a90ba10e8402fa11eb72ad27.mp3
19:31:30.529 - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): api.mycroft.ai:443
19:31:30.529 - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): api.mycroft.ai:443
High Performance MPEG 1.0/2.0/2.5 Audio Player for Layers 1, 2 and 3
        version 1.20.1; written and copyright by Michael Hipp and others
        free software (LGPL) without any warranty but with best wishes

Directory: /tmp/mycroft/cache/tts/
Playing MPEG stream 1 of 1: e3b13207a90ba10e8402fa11eb72ad27.mp3 ...

MPEG 2.0 layer III, 32 kbit/s, 24000 Hz mono
19:31:31.079 - urllib3.connectionpool - DEBUG - https://api.mycroft.ai:443 "POST /v1/device/28679107-9c23-4db7-b038-2c086311d200/metric/timing HTTP/1.1" 200 357
19:31:31.079 - urllib3.connectionpool - DEBUG - https://api.mycroft.ai:443 "POST /v1/device/28679107-9c23-4db7-b038-2c086311d200/metric/timing HTTP/1.1" 200 357

[0:07] Decoding of e3b13207a90ba10e8402fa11eb72ad27.mp3 finished.
19:31:38.261 - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): api.mycroft.ai:443
19:31:38.261 - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): api.mycroft.ai:443
19:31:38.332 - mycroft.audio.speech:mute_and_speak:122 - INFO - Speak: Heute wird ein Maximum von 6 und ein Minimum von 3 Grad vorhergesagt.
19:31:38.337 - mycroft.tts:execute:303 - DEBUG - TTS cache hit
19:31:38.359 - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): api.mycroft.ai:443
19:31:38.359 - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): api.mycroft.ai:443
High Performance MPEG 1.0/2.0/2.5 Audio Player for Layers 1, 2 and 3
        version 1.20.1; written and copyright by Michael Hipp and others
        free software (LGPL) without any warranty but with best wishes

Directory: /tmp/mycroft/cache/tts/
Playing MPEG stream 1 of 1: 5e74964ce84f7bb0ce594fcc3c072c5f.mp3 ...

MPEG 2.0 layer III, 32 kbit/s, 24000 Hz mono
19:31:38.797 - urllib3.connectionpool - DEBUG - https://api.mycroft.ai:443 "POST /v1/device/28679107-9c23-4db7-b038-2c086311d200/metric/timing HTTP/1.1" 200 242
19:31:38.797 - urllib3.connectionpool - DEBUG - https://api.mycroft.ai:443 "POST /v1/device/28679107-9c23-4db7-b038-2c086311d200/metric/timing HTTP/1.1" 200 242
19:31:38.897 - urllib3.connectionpool - DEBUG - https://api.mycroft.ai:443 "POST /v1/device/28679107-9c23-4db7-b038-2c086311d200/metric/timing HTTP/1.1" 200 342
19:31:38.897 - urllib3.connectionpool - DEBUG - https://api.mycroft.ai:443 "POST /v1/device/28679107-9c23-4db7-b038-2c086311d200/metric/timing HTTP/1.1" 200 342

[0:06] Decoding of 5e74964ce84f7bb0ce594fcc3c072c5f.mp3 finished.
19:31:44.783 - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): api.mycroft.ai:443
19:31:44.783 - urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): api.mycroft.ai:443
19:31:45.312 - urllib3.connectionpool - DEBUG - https://api.mycroft.ai:443 "POST /v1/device/28679107-9c23-4db7-b038-2c086311d200/metric/timing HTTP/1.1" 200 242
19:31:45.312 - urllib3.connectionpool - DEBUG - https://api.mycroft.ai:443 "POST /v1/device/28679107-9c23-4db7-b038-2c086311d200/metric/timing HTTP/1.1" 200 242

My configuration is:

"tts": {
    "module": "google",
"google": {
      "lang": "de"
    }
},
"lang": "de-de",
"play_wav_cmdline": "aplay %1",
"play_mp3_cmdline": "mpg123 %1"

forslund · March 25, 2019, 9:21pm

Thanks for that info!

It looks like something within the gtts module. I’ll see if I can reproduce and report upstream.

Wiggins · March 25, 2019, 10:26pm

I tried the delay and it did not work consistently. On some reboot cycles it would complete “who is steve jobs” several times in a row but then break on another query. Once broken it’s broken. On some cycles is would be broken from the beginning.

FWIW mp3 playback always works fine if I play NPR news.

forslund · March 26, 2019, 10:01am

@dominik I can’t reproduce your issue but I do see the error logs. By updating gtts to the latest version that error seems to go away.

On your picroft try running mycroft-pip install -U gtts

(Don’t do it on the mark-1 it’ll break the installation)

andlo · March 26, 2019, 7:46pm

I just flashed a new picroft with AIY on it. I see (well hear) this problem too.