Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Looping when asked to "play the news" #45

Open
Bulwagga opened this issue Apr 8, 2023 · 13 comments
Open

Looping when asked to "play the news" #45

Bulwagga opened this issue Apr 8, 2023 · 13 comments

Comments

@Bulwagga
Copy link
Contributor

Bulwagga commented Apr 8, 2023

Process to reproduce on Pi 3B+
Boot image https://downloads.openvoiceos.com/images/raspbian/raspbian-ovos-dev.zip
04-Apr-2023 15:42 1327830572.

Start ovos-cli-client - returns message "Connected to Messagebus!"
ask "what time is it" and the system returns and speaks the correct time
ask "play the news" and the system loops:
Apr 7 18:52:41 raspOvos ovos-systemd-audio[721]: 2023-04-07 18:52:41.335 - audio - ovos_plugin_common_play.ocp.player:handle_player_media_update:557 - INFO - MediaState changed: <MediaState.NO_MEDIA: 1>
Apr 7 18:52:46 raspOvos ovos-systemd-audio[721]: 2023-04-07 18:52:46.212 - audio - ovos_plugin_common_play.ocp.media:handle_track_state_change:355 - INFO - TrackState changed: <TrackState.PLAYING_AUDIOSERVICE: 21>
Apr 7 18:52:46 raspOvos ovos-systemd-audio[721]: 2023-04-07 18:52:46.310 - audio - ovos_plugin_common_play.ocp.player:handle_player_media_update:557 - INFO - MediaState changed: <MediaState.LOADED_MEDIA: 3>
Apr 7 18:52:46 raspOvos ovos-systemd-audio[721]: 2023-04-07 18:52:46.391 - audio - ovos_plugin_common_play.ocp.media:handle_track_state_change:355 - INFO - TrackState changed: <TrackState.QUEUED_AUDIOSERVICE: 31>
Apr 7 18:52:46 raspOvos ovos-systemd-audio[721]: 2023-04-07 18:52:46.430 - audio - mycroft.audio.audioservice:_stop:230 - INFO - END Stop
Apr 7 18:52:51 raspOvos ovos-systemd-audio[721]: 2023-04-07 18:52:51.275 - audio - ovos_plugin_common_play.ocp.media:handle_track_state_change:355 - INFO - TrackState changed: <TrackState.PLAYING_AUDIOSERVICE: 21>
Apr 7 18:52:51 raspOvos ovos-systemd-audio[721]: 2023-04-07 18:52:51.360 - audio - ovos_plugin_common_play.ocp.player:handle_player_media_update:557 - INFO - MediaState changed: <MediaState.LOADED_MEDIA: 3>
Apr 7 18:52:51 raspOvos ovos-systemd-audio[721]: 2023-04-07 18:52:51.383 - audio - ovos_plugin_common_play.ocp.media:handle_track_state_change:355 - INFO - TrackState changed: <TrackState.QUEUED_AUDIOSERVICE: 31>
Apr 7 18:52:51 raspOvos ovos-systemd-audio[721]: 2023-04-07 18:52:51.456 - audio - ovos_plugin_common_play.ocp.player:handle_player_media_update:557 - INFO - MediaState changed: <MediaState.NO_MEDIA: 1>
Apr 7 18:52:51 raspOvos ovos-systemd-audio[721]: 2023-04-07 18:52:51.482 - audio - mycroft.audio.audioservice:_stop:230 - INFO - END Stop

Screenshot from 2023-04-07 20-26-49
@builderjer
Copy link
Member

I have seen this issue also, with everything OCP, not just the news. There are several updates being made to ocp now, and I will update the image with the new version soon. You can try updating it manually and see if that helps. Any feed back would help. Both with ocp, and knowing when to update it in the image

@Bulwagga
Copy link
Contributor Author

Here is how the looping starts... Beginning with the answer to the time query. Note the bolded error. In ovos_plugin_common_play/ocp/player.py, in line 287 the available backends array is empty.

Apr 9 21:09:12 raspOvos ovos-systemd-skills[729]: Error loading json '/home/ovos/.config/mycroft/skills/skill-caffeinewiz.neongeckocom/settings.json'
Apr 9 21:09:12 raspOvos ovos-systemd-skills[729]: JSONDecodeError('Expecting value: line 1 column 1 (char 0)')
Apr 9 21:09:13 raspOvos ovos-systemd-skills[729]: 2023-04-09 21:09:13.022 - skills - mycroft.skills.settings:upload:178 - ERROR - Device needs to be paired to upload settings
Apr 9 21:09:13 raspOvos ovos-systemd-audio[727]: 2023-04-09 21:09:13.378 - audio - mycroft.audio.service:execute_tts:309 - INFO - Speak: It is nine oh nine
Apr 9 21:09:13 raspOvos ovos-systemd-audio[727]: 2023-04-09 21:09:13.469 - audio - ovos_tts_plugin_mimic3_server:_validate_args_combo:93 - WARNING - lang defined twice! choosing en_GB over en_US for voice: en_UK/apope_low
Apr 9 21:09:18 raspOvos systemd-timesyncd[285]: Timed out waiting for reply from 64.111.99.224:123 (2.debian.pool.ntp.org).
Apr 9 21:09:28 raspOvos systemd-timesyncd[285]: Timed out waiting for reply from 216.66.48.42:123 (3.debian.pool.ntp.org).
Apr 9 21:09:28 raspOvos systemd-timesyncd[285]: Initial synchronization to time server 162.248.241.94:123 (3.debian.pool.ntp.org).
Apr 9 21:09:36 raspOvos ovos-systemd-phal[728]: 2023-04-09 21:09:36.267 - OVOS - ovos_bus_client.session:reset_default_session:171 - INFO - New Default Session Start: 541e2c55-4c25-496e-b7f6-636430bc2792
Apr 9 21:10:08 raspOvos ovos-systemd-audio[727]: 2023-04-09 21:10:08.201 - audio - ovos_plugin_common_play.ocp:classify_media:212 - INFO - OVOSCommonPlay MediaType prediction: {'entities': {'query': 'the'}, 'conf': 0.9, 'name': 'news'}
Apr 9 21:10:08 raspOvos ovos-systemd-audio[727]: 2023-04-09 21:10:08.455 - audio - ovos_bus_client.session:reset_default_session:171 - INFO - New Default Session Start: 00d85a20-90e2-4377-8417-4bf6832b1b33
Apr 9 21:10:17 raspOvos ovos-systemd-audio[727]: 2023-04-09 21:10:17.508 - audio - ovos_plugin_common_play.ocp:_search:377 - INFO - unable to use GUI, filtering non-audio results
Apr 9 21:10:21 raspOvos ovos-systemd-audio[727]: 2023-04-09 21:10:21.751 - audio - ovos_plugin_common_play.ocp.media:extract_stream:461 - INFO - OCP plugins metadata: {'duration': '2891966', 'uri': 'https://api.spreaker.com/download/episode/25675659/7559816.mp3'}
Apr 9 21:10:31 raspOvos ovos-systemd-audio[727]: 2023-04-09 21:10:31.090 - audio - ovos_plugin_common_play.ocp.player:_get_preferred_audio_backend:375 - ERROR - Preferred audio service backend not installed
Apr 9 21:10:34 raspOvos ovos-systemd-audio[727]: 2023-04-09 21:10:34.482 - audio - mycroft.audio.audioservice:_stop:230 - INFO - END Stop
Apr 9 21:10:34 raspOvos ovos-systemd-audio[727]: 2023-04-09 21:10:34.653 - audio - ovos_plugin_common_play.ocp.media:handle_track_state_change:512 - INFO - TrackState changed: <TrackState.PLAYING_AUDIOSERVICE: 21>
Apr 9 21:10:34 raspOvos ovos-systemd-audio[727]: 2023-04-09 21:10:34.729 - audio - ovos_plugin_common_play.ocp.media:handle_track_state_change:512 - INFO - TrackState changed: <TrackState.QUEUED_AUDIOSERVICE: 31>
Apr 9 21:10:35 raspOvos ovos-systemd-audio[727]: 2023-04-09 21:10:35.716 - audio - ovos_plugin_common_play.ocp.media:extract_stream:461 - INFO - OCP plugins metadata: {'uri': 'https://api.spreaker.com/download/episode/25675659/7559816.mp3'}
Apr 9 21:10:41 raspOvos ovos-systemd-audio[727]: 2023-04-09 21:10:41.706 - audio - ovos_plugin_common_play.ocp.media:handle_track_state_change:512 - INFO - TrackState changed: <TrackState.PLAYING_AUDIOSERVICE: 21>
Apr 9 21:10:41 raspOvos ovos-systemd-audio[727]: 2023-04-09 21:10:41.862 - audio - ovos_plugin_common_play.ocp.media:handle_track_state_change:512 - INFO - TrackState changed: <TrackState.QUEUED_AUDIOSERVICE: 31>
Apr 9 21:10:41 raspOvos ovos-systemd-audio[727]: 2023-04-09 21:10:41.957 - audio - mycroft.audio.audioservice:_stop:230 - INFO - END Stop

@builderjer
Copy link
Member

Did you update OCP? pip install -U git+https://github.com/OpenVoiceOS/ovos-ocp-audio-plugin.git
The preferred audio service not installed is strange. I know vlc is installed, and that is the first in the list that OCP checks. Are these logs from ~/.local/state/mycroft/audio.log
can you add this to your ~/.config/mycroft/mycroft.conf file

{
  "log_level": "DEBUG"
}

and restart/reboot. That should give a little more details. I am not sure this is a raspbian issue, but rather an OCP issue? Lets see if we can debug a little more before passing the buck. It could be that the RPI3 needs more time to process before deciding that the stream is no good.

I know that I have had the looping issue also, and it was suggested to let it wait longer.

I am working on shrinking and optimizing this image, so maybe it will have more resources to use with OCP.

@builderjer
Copy link
Member

This is still an issue, maybe @JarbasAl has a suggestion on how to fix this

@builderjer
Copy link
Member

And I am not sure this is an issue with this image. I just tested on a pi4 and got the same results as a pi3. Not sure its the delay, because OCP shows a high match and is stopping the search early. try's to start playing and goes into the loop. also hey mycroft "stop" or hey mycroft "stop playing" do not stop the loop

@builderjer
Copy link
Member

I think this has been fixed, can someone verify?

@Bulwagga
Copy link
Contributor Author

Look for an answer by 2/26 or so. Thanks.

@Bulwagga
Copy link
Contributor Author

Bulwagga commented Feb 23, 2024 •
edited
Loading

"Play the news" still loops in the manual install. I'm looking into OCP to see if there is some assumed package I don't have. I will also try the image install. Below is what I'm seeing in journalctl:
ovos_plugin_common_play.ocp.media:extract_stream:174 - INFO - OCP plugins metadata: {'uri': 'http://video.news.sky.>
ovos_plugin_common_play.ocp.media:handle_track_state_change:225 - INFO - TrackState changed: <TrackState.PLAYING_AU>
ovos_plugin_common_play.ocp.media:handle_track_state_change:225 - INFO - TrackState changed: <TrackState.QUEUED_AUD>
ovos_audio.audio:_stop:257 - INFO - END Stop
ovos_plugin_common_play.ocp.player:play:384 - INFO - Requested playback with mpris not stopped
ovos_plugin_common_play.ocp.media:extract_stream:174 - INFO - OCP plugins metadata: {'uri': 'http://video.news.sky.>
ovos_plugin_common_play.ocp.media:handle_track_state_change:225 - INFO - TrackState changed: <TrackState.PLAYING_AU>
ovos_plugin_common_play.ocp.media:handle_track_state_change:225 - INFO - TrackState changed: <TrackState.QUEUED_AUD>
ovos_audio.audio:_stop:257 - INFO - END Stop
ovos_plugin_common_play.ocp.media:extract_stream:174 - INFO - OCP plugins metadata: {'uri': 'http://video.news.sky.>
ovos_plugin_common_play.ocp.media:handle_track_state_change:225 - INFO - TrackState changed: <TrackState.PLAYING_AU>
ovos_plugin_common_play.ocp.media:handle_track_state_change:225 - INFO - TrackState changed: <TrackState.QUEUED_AUD>
ovos_audio.audio:_stop:257 - INFO - END Stop
ovos_plugin_common_play.ocp.media:extract_stream:174 - INFO - OCP plugins metadata: {'uri': 'http://video.news.sky.>
ovos_plugin_common_play.ocp.media:handle_track_state_change:225 - INFO - TrackState changed: <TrackState.PLAYING_AU>
ovos_plugin_common_play.ocp.media:handle_track_state_change:225 - INFO - TrackState changed: <TrackState.QUEUED_AUD>
ovos_audio.audio:_stop:257 - INFO - END Stop
ovos_plugin_common_play.ocp.media:extract_stream:174 - INFO - OCP plugins metadata: {'uri': 'http://video.news.sky.>
ovos_plugin_common_play.ocp.media:handle_track_state_change:225 - INFO - TrackState changed: <TrackState.PLAYING_AU>
ovos_plugin_common_play.ocp.media:handle_track_state_change:225 - INFO - TrackState changed: <TrackState.QUEUED_AUD>
ovos_plugin_common_play.ocp.media:extract_stream:174 - INFO - OCP plugins metadata: {'uri': 'http://video.news.sky.>
ovos_audio.audio:_stop:257 - INFO - END Stop

@Bulwagga
Copy link
Contributor Author

I believe someone has solved this in the OCP repository. I will try to implement and let you know.

@builderjer
Copy link
Member

I will be switching to ovos-media soon, so maybe leave this open until then?

@Bulwagga
Copy link
Contributor Author

Works for me. The additional documentation that closed the issue is now a dead link. Thanks!

@JarbasAl
Copy link
Member

I believe someone has solved this in the OCP repository. I will try to implement and let you know.

If that is the issue, edit your mycroft.conf and try this

"Audio": {
  "backends": {
      "OCP": {
          "type": "ovos_common_play",
          (...)
          "disable_mpris": True
      },
      (....)
``

@Bulwagga
Copy link
Contributor Author

Thank you. My first try adding the Audio section had no effect. I'll keep tinkering with it. I also saw this line and wondered if "disable_mpris": True isn't already set.

Let me boil this down for a while before you put in any more effort.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@Bulwagga @JarbasAl @builderjer