Bad news url in web UI breaks dinkum-skills.service

gez-mycroft · November 4, 2022, 5:39am

NOTE: Issue copied across from Github

Describe the bug
After entering a bad custom News URL, the system hangs on any utterance.
Asking Hey Mycroft, what time is it? hangs seemingly indefinitely with a swirling blue light. Other times, asking Hey Mycroft, what time is it? causes Mycroft to respond Just a second. and then Beats me..

To Reproduce

In the web UI at https://account.mycroft.ai/skills, configure the News skill to use the custom URL http://stream.wlrn.mobi/WLRNFMAAC32. Note that this is an HTTP stream, not a podcast feed as the service expects!
Allow time for the settings to sync.
Say Hey Mycroft, what time is it?
Wait indefinitely or hear an error message

Expected behavior
I would expect the News skill to fail gracefully, ideally with a useful error message, and certainly not to interfere with other skills.

Additional context
I tried clearing the custom setting in the web UI, but /home/mycroft/.config/mycroft/skills/news.mark2/settings.json still has the problematic url.

I gathered the logs below using SSH, but this was the first time I SSHed into the device: I had only used the web UI when this problem started.

After submitting this report, I intend to try to fix the configuration by hand.

Log files
This is the content of /home/mycroft/.config/mycroft/skills/news.mark2/settings.json:

{"station": "not_set", "custom_url": "http://stream.wlrn.mobi/WLRNFMAAC32"}

Here is an excerpt from journalctl -u dinkum-skills.service:

Oct 27 21:03:06 localhost.localdomain python[14968]: DEBUG:skills:Loading skill news.mark2
Oct 27 21:03:06 localhost.localdomain python[14968]: INFO:mycroft.util.log:/home/mycroft/.config/mycroft/skills/news.mark2/settings.json
Oct 27 21:03:06 localhost.localdomain python[14968]: DEBUG:mycroft.util.log:Added event: mycroft.skill.stop
Oct 27 21:03:06 localhost.localdomain python[14968]: DEBUG:mycroft.util.log:Added event: mycroft.skills.initialized
Oct 27 21:03:06 localhost.localdomain python[14968]: DEBUG:mycroft.util.log:Added event: mycroft.skill.enable_intent
Oct 27 21:03:06 localhost.localdomain python[14968]: DEBUG:mycroft.util.log:Added event: mycroft.skill.disable_intent
Oct 27 21:03:06 localhost.localdomain python[14968]: DEBUG:mycroft.util.log:Added event: mycroft.skill.set_cross_context
Oct 27 21:03:06 localhost.localdomain python[14968]: DEBUG:mycroft.util.log:Added event: mycroft.skill.remove_cross_context
Oct 27 21:03:06 localhost.localdomain python[14968]: DEBUG:mycroft.util.log:Added event: mycroft.skills.settings.changed
Oct 27 21:03:06 localhost.localdomain python[14968]: DEBUG:mycroft.util.log:Added event: play:query
Oct 27 21:03:06 localhost.localdomain python[14968]: DEBUG:mycroft.util.log:Added event: play:start
Oct 27 21:03:06 localhost.localdomain python[14968]: DEBUG:mycroft.util.log:Added event: play:stop
Oct 27 21:03:06 localhost.localdomain python[14968]: DEBUG:mycroft.util.log:Added event: play:pause
Oct 27 21:03:06 localhost.localdomain python[14968]: DEBUG:mycroft.util.log:Added event: play:resume
Oct 27 21:03:06 localhost.localdomain python[14968]: INFO:news.mark2:Creating custom News Station from Skill settings.
Oct 27 21:04:03 localhost.localdomain systemd[1]: dinkum-skills.service: start operation timed out. Terminating.
Oct 27 21:04:03 localhost.localdomain systemd[1]: dinkum-skills.service: Failed with result 'timeout'.
Oct 27 21:04:03 localhost.localdomain systemd[1]: Failed to start Mycroft service skills.service.

Here is a longer set of logs generated by journalctl -u dinkum-* --since="2022-10-27 20:27:11" --until="2022-10-27 20:27:32":

-- Logs begin at Thu 2019-02-14 10:12:04 UTC, end at Thu 2022-10-27 21:43:08 UTC. --
Oct 27 20:27:11 localhost.localdomain python[378]: DEBUG:mycroft_hotword:Triggered
Oct 27 20:27:11 localhost.localdomain python[378]: DEBUG:voice:Wrote /tmp/mycroft/cache/mycroft_wake_words/151822199100.wav
Oct 27 20:27:11 localhost.localdomain python[378]: DEBUG:voice:Awake!
Oct 27 20:27:11 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Disabled idle timeout
Oct 27 20:27:11 localhost.localdomain python[374]: INFO:mycroft.util.log:Ducked volume
Oct 27 20:27:14 localhost.localdomain python[378]: DEBUG:voice:Wrote /tmp/mycroft/cache/mycroft_utterances/154566956529.wav
Oct 27 20:27:14 localhost.localdomain python[378]: DEBUG:urllib3.connectionpool:Starting new HTTPS connection (1): api.mycroft.ai:443
Oct 27 20:27:15 localhost.localdomain python[378]: DEBUG:urllib3.connectionpool:https://api.mycroft.ai:443 "POST /v1/transcribe?lang=en-US&limit=1 HTTP/1.1" 200 36
Oct 27 20:27:15 localhost.localdomain python[378]: INFO:mycroft.util.log:{'transcription': 'what time is it'}
Oct 27 20:27:15 localhost.localdomain python[378]: DEBUG:voice:STT: what time is it
Oct 27 20:27:15 localhost.localdomain python[374]: INFO:mycroft.util.log:Unducked volume
Oct 27 20:27:15 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Current sessions: {}
Oct 27 20:27:15 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Starting session: 9023859f-2de5-41b4-bf84-7b1bfac96cef
Oct 27 20:27:15 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Enter handle utterance: message.data:{'utterances': ['what time is it'], 'mycroft_session_id': '9023859f-2de5-41b4-bf84-7b1bfac96cef', 'hotword_audio_uri': 'file:///tmp/mycroft/cache/mycroft_wake_words/151822199100.wav', 'stt_audio_uri': 'file:///tmp/mycroft/cache/mycroft_utterances/154566956529.wav'}, session_id:9023859f-2de5-41b4-bf84-7b1bfac96cef
Oct 27 20:27:15 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Utterances: [('what time is it',)]
Oct 27 20:27:15 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Padatious Matching confidence > 0.95
Oct 27 20:27:15 localhost.localdomain python[377]: INFO:mycroft.util.log:Padatious match: {'name': 'news.mark2:PlayTheNews.intent', 'sent': 'what time is it', 'matches': {'utterance': 'what time is it'}, 'conf': 0.2827819915653492}
Oct 27 20:27:15 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Trying 2 fallback handler(s) at priority 5
Oct 27 20:27:15 localhost.localdomain python[683]: DEBUG:mycroft.util.log:Added event: fallback-query.mark2:QuestionQueryTimeout
Oct 27 20:27:15 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Continuing session: 9023859f-2de5-41b4-bf84-7b1bfac96cef
Oct 27 20:27:15 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Disabled idle timeout
Oct 27 20:27:15 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Completed action for session 9023859f-2de5-41b4-bf84-7b1bfac96cef: MessageAction(message_type='question:query', data={'mycroft_session_id': '9023859f-2de5-41b4-bf84-7b1bfac96cef', 'phrase': 'what time is it'}, delay=0.0)
Oct 27 20:27:15 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Handled by fallback skill fallback-query.mark2 at priority 5
Oct 27 20:27:15 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Completed action for session 9023859f-2de5-41b4-bf84-7b1bfac96cef: ShowPageAction(namespace='fallback-query.mark2.SearchingForAnswers.qml', page='file:///opt/mycroft-dinkum/skills/fallback-query.mark2/ui/SearchingForAnswers.qml', data=None)
Oct 27 20:27:15 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Exit handle utterance
Oct 27 20:27:15 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Completed action for session 9023859f-2de5-41b4-bf84-7b1bfac96cef: SpeakAction(utterance='Just a second', dialog='just.one.moment', wait=False)
Oct 27 20:27:15 localhost.localdomain python[374]: DEBUG:audio:Speak for session '9023859f-2de5-41b4-bf84-7b1bfac96cef': Just a second (cache=False)
Oct 27 20:27:15 localhost.localdomain python[374]: DEBUG:audio:Segments: ['Just a second']
Oct 27 20:27:15 localhost.localdomain python[374]: DEBUG:mycroft.util.log:Started TTS session 9023859f-2de5-41b4-bf84-7b1bfac96cef
Oct 27 20:27:15 localhost.localdomain python[374]: DEBUG:audio:Submitted TTS chunk 1/1 for session 9023859f-2de5-41b4-bf84-7b1bfac96cef: Just a second
Oct 27 20:27:15 localhost.localdomain python[374]: INFO:mycroft.util.log:Queued TTS chunk 1/1: file:///opt/mycroft/preloaded_cache/Mimic3/08c337e43e5de1dcf814cd674051b3f7.wav (session=9023859f-2de5-41b4-bf84-7b1bfac96cef): Just a second
Oct 27 20:27:15 localhost.localdomain python[374]: DEBUG:mycroft.util.log:Loading audio file: /opt/mycroft/preloaded_cache/Mimic3/08c337e43e5de1dcf814cd674051b3f7.wav
Oct 27 20:27:15 localhost.localdomain python[374]: INFO:mycroft.util.log:Ducked volume
Oct 27 20:27:15 localhost.localdomain python[374]: INFO:mycroft.util.log:Speaking TTS chunk 1/1 for 1.2770833333333333 sec from session 9023859f-2de5-41b4-bf84-7b1bfac96cef
Oct 27 20:27:16 localhost.localdomain python[374]: DEBUG:mycroft.util.log:TTS chunk finished playing for session 9023859f-2de5-41b4-bf84-7b1bfac96cef
Oct 27 20:27:16 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Audio finished: 9023859f-2de5-41b4-bf84-7b1bfac96cef
Oct 27 20:27:16 localhost.localdomain python[374]: INFO:mycroft.util.log:TTS session finished: 9023859f-2de5-41b4-bf84-7b1bfac96cef
Oct 27 20:27:16 localhost.localdomain python[377]: DEBUG:mycroft.util.log:TTS finished: 9023859f-2de5-41b4-bf84-7b1bfac96cef
Oct 27 20:27:16 localhost.localdomain python[374]: INFO:mycroft.util.log:Unducked volume
Oct 27 20:27:20 localhost.localdomain python[683]: DEBUG:mycroft.util.log:Removing event fallback-query.mark2:QuestionQueryTimeout
Oct 27 20:27:20 localhost.localdomain python[683]: INFO:fallback-query.mark2:Search timeout
Oct 27 20:27:20 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Requested session end: 9023859f-2de5-41b4-bf84-7b1bfac96cef
Oct 27 20:27:20 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Disabled idle timeout
Oct 27 20:27:20 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Completed action for session 9023859f-2de5-41b4-bf84-7b1bfac96cef: SpeakAction(utterance='Beats me', dialog='noAnswer', wait=True)
Oct 27 20:27:20 localhost.localdomain python[374]: DEBUG:audio:Speak for session '9023859f-2de5-41b4-bf84-7b1bfac96cef': Beats me (cache=False)
Oct 27 20:27:20 localhost.localdomain python[374]: DEBUG:audio:Segments: ['Beats me']
Oct 27 20:27:20 localhost.localdomain python[374]: DEBUG:mycroft.util.log:Started TTS session 9023859f-2de5-41b4-bf84-7b1bfac96cef
Oct 27 20:27:20 localhost.localdomain python[374]: DEBUG:audio:Submitted TTS chunk 1/1 for session 9023859f-2de5-41b4-bf84-7b1bfac96cef: Beats me
Oct 27 20:27:20 localhost.localdomain python[374]: INFO:mycroft.util.log:Queued TTS chunk 1/1: file:///opt/mycroft/preloaded_cache/Mimic3/5a1752f070528871fdc9809f0c3e301f.wav (session=9023859f-2de5-41b4-bf84-7b1bfac96cef): Beats me
Oct 27 20:27:20 localhost.localdomain python[374]: DEBUG:mycroft.util.log:Loading audio file: /opt/mycroft/preloaded_cache/Mimic3/5a1752f070528871fdc9809f0c3e301f.wav
Oct 27 20:27:20 localhost.localdomain python[374]: INFO:mycroft.util.log:Ducked volume
Oct 27 20:27:20 localhost.localdomain python[374]: INFO:mycroft.util.log:Speaking TTS chunk 1/1 for 0.8475208333333333 sec from session 9023859f-2de5-41b4-bf84-7b1bfac96cef
Oct 27 20:27:21 localhost.localdomain python[374]: DEBUG:mycroft.util.log:TTS chunk finished playing for session 9023859f-2de5-41b4-bf84-7b1bfac96cef
Oct 27 20:27:21 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Audio finished: 9023859f-2de5-41b4-bf84-7b1bfac96cef
Oct 27 20:27:21 localhost.localdomain python[374]: INFO:mycroft.util.log:TTS session finished: 9023859f-2de5-41b4-bf84-7b1bfac96cef
Oct 27 20:27:21 localhost.localdomain python[377]: DEBUG:mycroft.util.log:TTS finished: 9023859f-2de5-41b4-bf84-7b1bfac96cef
Oct 27 20:27:21 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Disabled idle timeout
Oct 27 20:27:21 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Completed action for session 9023859f-2de5-41b4-bf84-7b1bfac96cef: ClearDisplayAction()
Oct 27 20:27:21 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Idle timeout set for 2 second(s)
Oct 27 20:27:21 localhost.localdomain python[374]: INFO:mycroft.util.log:Unducked volume
Oct 27 20:27:21 localhost.localdomain python[377]: DEBUG:mycroft.util.log:Cleaning up ended session: 9023859f-2de5-41b4-bf84-7b1bfac96cef

I can confirm that the issue was fixed by manually editing /home/mycroft/.config/mycroft/skills/news.mark2/settings.json to contain:

{"station": "NPR", "custom_url": ""}