VolumeSkill race condition causing Mycroft to stay muted forever

[TheLastProject]

Sometimes, when saying "Hey Mycroft" while Mycroft hasn't yet restored the volume will trigger the VolumeSkill again and cause it to believe the last known volume was 0. This causes the VolumeSkill to "restore" the volume to 0 when unmuting, effectively keeping Mycroft muted forever until the user manually restores the volume setting in ALSA/PulseAudio.

• I'm running Picroft
• With version 19.8.5 of the Mycroft software
• With the standard Wake Word

Try to provide steps that we can use to replicate the Issue

For example:

1. Install the Spotify skill
2. Say "Hey Mycroft"
3. Wait for Mycroft to beep
4. Say "Play the album proxy by Being as an Ocean"
5. Say "Hey Mycroft" again
6. Mycroft stays muted until manually restoring the ALSA settings.

Be as specific as possible about the expected condition, and the deviation from expected condition.

Expected: Mycroft sets its volume back to the previous level
Actual: Mycroft sets its volume back to 0

Provide log files or other output to help us see the error

Pay special attention to the output of VolumeSkill:

Establishing Mycroft Messagebus connection...                                                                                                                               
Connected to Messagebus!                                                                                                                                                    
 20:11:12.128 | INFO     | 20468 | mycroft.skills.skill_loader:_communicate_load_status:278 | Skill mycroft-spotify.forslund loaded successfully                            
 20:11:12.150 | INFO     | 20468 | mycroft.skills.skill_manager:put:73 | Updating settings meta during runtime...                                                           
 20:11:12.153 | INFO     | 20468 | mycroft.skills.padatious_service:train:89 | Training complete.                                                                           
 20:11:12.159 | INFO     | 20468 | msm.mycroft_skills_manager | invalidating skills cache                                                                                   
 20:11:12.161 | INFO     | 20468 | msm.mycroft_skills_manager | building SkillEntry objects for all skills                                                                  
 20:11:21.488 | INFO     | 20468 | mycroft.skills.skill_manager:send:60 | New Settings meta to upload.                                                                      
 20:11:25.462 | INFO     | 20474 | __main__:handle_wakeword:59 | Wakeword Detected: hey mycroft                                                                             
Playing WAVE '/home/pi/mycroft-core/mycroft/res/snd/start_listening.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo                                               
 20:11:25.960 | INFO     | 20474 | __main__:handle_record_begin:37 | Begin Recording...                                                                                     
 20:11:29.365 | INFO     | 20474 | __main__:handle_record_end:43 | End Recording...                                                                                         
 20:11:25.967 | INFO     | 20468 | VolumeSkill | MUTING!                                                                                                                    
55                                                                                                                                                                          
 20:11:25.968 | INFO     | 20468 | AlarmSkill | on started...                                                                                                               
 20:11:29.481 | INFO     | 20468 | AlarmSkill | on ended...                                                                                                                 
 20:11:31.160 | INFO     | 20468 | VolumeSkill | Volume before mute: 55                                                                                                     
 20:11:31.160 | INFO     | 20468 | VolumeSkill | 55                                                                                                                         
 20:11:31.569 | INFO     | 20474 | __main__:handle_utterance:64 | Utterance: ['play the album proxy by being as an ocean']                                                  
 20:11:46.583 | INFO     | 20474 | __main__:handle_wakeword:59 | Wakeword Detected: hey mycroft                                                                             
Playing WAVE '/home/pi/mycroft-core/mycroft/res/snd/start_listening.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo                                               
0                                                                                                                                                                           
 20:11:47.523 | INFO     | 20468 | VolumeSkill | MUTING!                                                                                                                    
 20:11:47.476 | INFO     | 20474 | __main__:handle_record_begin:37 | Begin Recording...                                                                                     
 20:11:47.523 | INFO     | 20468 | AlarmSkill | on started...                                                                                                               
 20:11:47.568 | INFO     | 20468 | VolumeSkill | Volume before mute: 0                                                                                                      
 20:11:47.569 | INFO     | 20468 | VolumeSkill | 0                                                                                                                          
0                                                                                                                                                                           
 20:11:47.589 | INFO     | 20468 | Playback Control Skill | Resolving Player for: the album proxy by being as an ocean                                                      
 20:11:47.744 | INFO     | 20474 | __main__:handle_record_end:43 | End Recording...                                                                                         
Removing event mycroft-playback-control.mycroftai:PlayQueryTimeout                                                                                                          
Removing event mycroft-playback-control.mycroftai:PlayQueryTimeout                                                                                                          
Removing event mycroft-playback-control.mycroftai:PlayQueryTimeout                                                                                                          
 20:11:47.787 | INFO     | 20468 | AlarmSkill | on ended...                                                                                                                 
0                                                                                                                                                                           
 20:11:47.887 | INFO     | 20468 | SpotifySkill | ('proxy', 'proxy: an a.n.i.m.o. story', 0.5225806451612903)                                                               
 20:11:47.888 | INFO     | 20468 | SpotifySkill | Spotify confidence: 0.5225806451612903                                                                                    
~~~~'type': 'album', 'uri': 'spotify:album:5DBBejLG3BjEylQNDbQWsT'}], 'limit': 10, 'next': None, 'offset': 0, 'previous': None, 'total': 1}}, 'name': None, 'type': 'album'}
~~~~:47.895 | INFO     | 20468 | mycroft.skills.settings:save_settings:109 | Skill settings successfully saved to /opt/mycroft/skills/mycroft-spotify.forslund/settings.json
Removing event mycroft-playback-control.mycroftai:PlayQueryTimeout                                                                                                          
 20:11:52.302 | INFO     | 20468 | Playback Control Skill | Playing with: mycroft-spotify.forslund                                                                          
 20:11:52.566 | INFO     | 20468 | Playback Control Skill | Audio service status: {}                                                                                        
 20:11:52.767 | INFO     | 20468 | SpotifySkill | Device detected: DeviceType.MYCROFT                                                                                       
 20:11:53.483 | INFO     | 20468 | SpotifySkill | playing album                                                                                                             
 20:11:55.492 | INFO     | 20468 | SpotifySkill | spotify_play: 039a0c66d9e426f038c08cbe1926ab002b3ef6a9                                                                    
Removing event mycroft-spotify.forslund:MonitorSpotify                                                                                                                      
 20:11:59.775 | INFO     | 20468 | mycroft.skills.padatious_service:train:87 | Training... (single_thread=False)                                                            

[TheLastProject]

The most interesting part is this:

 20:11:31.160 | INFO     | 20468 | VolumeSkill | 55       
[...]                                                                
 20:11:47.523 | INFO     | 20468 | VolumeSkill | MUTING!
[...]
 20:11:47.568 | INFO     | 20468 | VolumeSkill | Volume before mute: 0                                                                                                                         

Which seems to imply that the VolumeSkill retrieves an outdated value.

[forslund]

Thanks for reporting, the muting logic is in the volume skill so I'll transfer this issue there.