An Error occurred while processing a request in Timer Skill

[chgardener]

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]

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]

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]

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]

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]

@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]

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

[chgardener]

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:

Hope this helps.