search

MycroftAI / mycroft-timer

Mycroft AI official Timer Skill - set multiple named timers
https://mycroft.ai/skills
Apache License 2.0
7 stars 30 forks source link

An Error occurred while processing a request in Timer Skill #91

Open chgardener opened 3 years ago

chgardener commented 3 years ago

Mycroft randomly says "An Error occurred while processing a request in Timer Skill". This usually happens when some other unrelated Request is being handled, for example asking for the weather.

Running Mycroft 20.8.1 on a Raspberry Pi 4 (Buster). I'll try to catch the debug messages from the cli-client.

krisgesling commented 3 years ago

Hey there, thanks for flagging this.

Have you found any utterances that consistently cause this to happen?

If not can you post some more detail from your log files - particularly /var/log/mycroft/skills.log This should give us more of a clue about what in the Timer Skill has failed and why it got triggered.

forslund commented 3 years ago

I have seen something similar. I started looking at it but didn't quite conclude how it happened. In my case it seems like the code could reach https://github.com/MycroftAI/mycroft-timer/blob/20.08/__init__.py#L132 without the event first being registered (if I recall correctly).

I guess it could happen if it gets two listening ended before the wait for the speak message stops blocking

chgardener commented 3 years ago

Ok, I looked into the skills.log and found two instances over the last 2 weeks. They both happened after the msm updater and while spotify closed a connection to api.spotify.com:

2021-04-27 18:19:46.878 | INFO     |   697 | msm.skill_entry | Nothing new for mycroft-singing
2021-04-27 18:19:47.702 | INFO     |   697 | msm.skill_entry | Nothing new for mycroft-ip
2021-04-27 18:19:48.006 | INFO     |   697 | msm.skill_entry | Nothing new for mycroft-spotify
2021-04-27 18:19:48.536 | INFO     |   697 | msm.skill_entry | Nothing new for mycroft-audio-record
2021-04-27 18:19:49.246 | INFO     |   697 | msm.skill_entry | Nothing new for mycroft-naptime
2021-04-27 18:19:49.865 | INFO     |   697 | mycroft.skills.skill_updater:_log_next_download_time:265 | Next scheduled skill update: 2021-04-27 19:19:49.862234
2021-04-27 18:19:49.924 | INFO     |   697 | mycroft.skills.skill_updater:update_skills:168 | Skill update complete
2021-04-27 18:23:04.942 | INFO     |   697 | AutoVolume | Mic thresh: 1174.994 Low level: 1163.6853050000004 High level: 9175.086945000003
2021-04-27 18:23:04.942 | INFO     |   697 | AutoVolume | Setting volume to :60%
2021-04-27 18:24:49.694 | INFO     |   697 | AutoVolume | Mic thresh: 1153.4738916666668 Low level: 1163.6853050000004 High level: 9175.086945000003
2021-04-27 18:24:49.695 | INFO     |   697 | AutoVolume | Setting volume to :35%
2021-04-27 18:41:29.919 | INFO     |   697 | AutoVolume | Mic thresh: 1186.308591666667 Low level: 1163.6853050000004 High level: 9175.086945000003
2021-04-27 18:41:29.920 | INFO     |   697 | AutoVolume | Setting volume to :60%
2021-04-27 18:44:39.838 | INFO     |   697 | AutoVolume | Mic thresh: 1067.7653166666666 Low level: 1163.6853050000004 High level: 9175.086945000003
2021-04-27 18:44:39.839 | INFO     |   697 | AutoVolume | Setting volume to :35%
2021-04-27 18:50:18.502 | WARNING  |   697 | urllib3.connectionpool | Connection pool is full, discarding connection: accounts.spotify.com
2021-04-27 18:50:18.502 | WARNING  |   697 | urllib3.connectionpool | Connection pool is full, discarding connection: accounts.spotify.com
2021-04-27 18:50:18.509 | WARNING  |   697 | urllib3.connectionpool | Connection pool is full, discarding connection: accounts.spotify.com
2021-04-27 18:50:18.731 | WARNING  |   697 | urllib3.connectionpool | Connection pool is full, discarding connection: api.spotify.com
2021-04-27 18:50:18.737 | WARNING  |   697 | urllib3.connectionpool | Connection pool is full, discarding connection: api.spotify.com
2021-04-27 18:50:37.019 | WARNING  |   697 | urllib3.connectionpool | Connection pool is full, discarding connection: api.spotify.com
2021-04-27 18:50:37.022 | WARNING  |   697 | urllib3.connectionpool | Connection pool is full, discarding connection: api.spotify.com
2021-04-27 18:51:00.281 | WARNING  |   697 | urllib3.connectionpool | Connection pool is full, discarding connection: api.spotify.com
2021-04-27 18:51:00.287 | WARNING  |   697 | urllib3.connectionpool | Connection pool is full, discarding connection: api.spotify.com
2021-04-27 18:51:00.294 | WARNING  |   697 | urllib3.connectionpool | Connection pool is full, discarding connection: api.spotify.com
2021-04-27 18:51:08.115 | WARNING  |   697 | urllib3.connectionpool | Connection pool is full, discarding connection: api.spotify.com
2021-04-27 18:51:08.120 | WARNING  |   697 | urllib3.connectionpool | Connection pool is full, discarding connection: api.spotify.com
2021-04-27 18:51:08.129 | WARNING  |   697 | urllib3.connectionpool | Connection pool is full, discarding connection: api.spotify.com
2021-04-27 18:51:14.678 | WARNING  |   697 | urllib3.connectionpool | Connection pool is full, discarding connection: api.spotify.com
2021-04-27 18:51:14.684 | WARNING  |   697 | urllib3.connectionpool | Connection pool is full, discarding connection: api.spotify.com
2021-04-27 18:51:14.697 | WARNING  |   697 | urllib3.connectionpool | Connection pool is full, discarding connection: api.spotify.com
2021-04-27 18:51:24.279 | ERROR    |   697 | mycroft.skills.mycroft_skill.mycroft_skill:on_error:835 | An error occurred while processing a request in Timer Skill
Traceback (most recent call last):
  File "/home/pi/mycroft-core/mycroft/skills/mycroft_skill/event_container.py", line 66, in wrapper
    handler(message)
  File "/opt/mycroft/skills/mycroft-timer.mycroftai/__init__.py", line 130, in handle_listener_ended
    self.is_not_listening)
  File "/home/pi/mycroft-core/mycroft/messagebus/client/client.py", line 213, in remove
    self.emitter.remove_listener(event_name, func)
  File "/home/pi/mycroft-core/.venv/lib/python3.7/site-packages/pyee/_base.py", line 152, in remove_listener
    self._remove_listener(event, f)
  File "/home/pi/mycroft-core/.venv/lib/python3.7/site-packages/pyee/_base.py", line 147, in _remove_listener
    self._events[event].pop(f)
KeyError: <bound method TimerSkill.is_not_listening of <mycroft-timer_mycroftai.TimerSkill object at 0x60aa9470>>
2021-04-27 19:01:09.535 | WARNING  |   697 | urllib3.connectionpool | Connection pool is full, discarding connection: api.spotify.com
2021-04-27 19:01:09.541 | WARNING  |   697 | urllib3.connectionpool | Connection pool is full, discarding connection: api.spotify.com
2021-04-27 19:01:09.542 | WARNING  |   697 | urllib3.connectionpool | Connection pool is full, discarding connection: api.spotify.com
2021-04-27 19:19:50.220 | INFO     |   697 | mycroft.skills.skill_updater:update_skills:147 | Beginning skill update...
2021-04-27 19:19:50.395 | WARNING  |   697 | msm.mycroft_skills_manager | No such default skill: mycroft-pandora
2021-04-27 19:19:50.396 | WARNING  |   697 | msm.mycroft_skills_manager | No such default skill: mycroft-pandora
chgardener commented 3 years ago

Also, at another time, I found the following:

´´´ 2021-05-02 16:46:05.613 | INFO | 697 | QuestionsAnswersSkill | Searching for john holloway on Removing event fallback-query.mycroftai:QuestionQueryTimeout Removing event fallback-query.mycroftai:QuestionQueryTimeout Removing event fallback-query.mycroftai:QuestionQueryTimeout Removing event fallback-query.mycroftai:QuestionQueryTimeout 2021-05-02 16:46:06.478 | INFO | 697 | QuestionsAnswersSkill | Timeout occured check responses ´´´

I have seen this several times when connected to the cli-client when the error happened, so maybe it's connected. BTW I never searched for John Holloway. The error does not only occur when Mycroft doesn't understand what I want, but I feel it happened a few times when he wasn't sure.

krisgesling commented 3 years ago

@chrisveilleux is doing a refactor of this Skill at the moment so could take a look at this also.

In terms of the "john holloway" I'm guessing that was an accidental activation? Or did it happen when you were actively using the device?

chgardener commented 3 years ago

Yeah, I wanted to turn on my HomeAssistant entity "Hallway" but Mycroft misunderstood me.

chgardener commented 3 years ago

Ok, so finally the error ocurred while I was connected to the cli websocket. According to the colour scheme, the traceback should've been written to the voice.log file, but I couldn't find it there. From the cli interface:

screenshot-timer-skill

Hope this helps.