Playback.stop() doesnt work if playback.seek() is used

General
1

Hello,

I am having here a little confusing issue. I run mopidy 3.2.0 on Raspi 4.
If I use playback.seek() in my code the command playback.stop() doesnt work even that playback.get_state() says playback is stopped. Also in the debug output I see only my output from playback state but no futher activities:

INFO     2021-07-25 14:38:17,363 [2718:Dummy-8] mopidy_figlio.frontend
  Core Playback State:stopped

If I dont use playback.seek() and start playback with playback.play() and then stop with playback.stop() it works and I see this in the debug:

0:00:12.258675379  2359 0xb2c287c0 WARN                    alsa gstalsasink.c:1101:gst_alsasink_delay:<alsasink0> snd_pcm_delay returned negative delay
DEBUG    2021-07-25 14:01:03,448 [2359:MainThread] mopidy.audio.gst
  Got STATE_CHANGED bus message: old=GST_STATE_PLAYING new=GST_STATE_PAUSED pending=GST_STATE_NULL
DEBUG    2021-07-25 14:01:03,455 [2359:Audio-2] mopidy.audio.gst
  Changing state to GST_STATE_NULL: result=GST_STATE_CHANGE_SUCCESS
DEBUG    2021-07-25 14:01:03,456 [2359:Core-6] mopidy.core.playback
  Changing state: playing -> stopped
DEBUG    2021-07-25 14:01:03,457 [2359:Core-6] mopidy.core.playback
  Triggering playback state change event
DEBUG    2021-07-25 14:01:03,457 [2359:Core-6] mopidy.listener
  Sending playback_state_changed to CoreListener: {'old_state': 'playing', 'new_state': 'stopped'}
INFO     2021-07-25 14:01:03,459 [2359:Dummy-8] mopidy_figlio.frontend
  Core Playback State:stopped

I already checked code from Mopidy-Autoplay which is doing basically the same and I dont see what I am doing wrong in my code.

I would be happy if someone may can help me to fix this or if this is a real bug in mopidy.

Deps and config will follow and if needed I can provide full debug if wanted.

Thanks

Mike

################# Deps ######################
pi@musicpy4:~ $ mopidy deps
Executable: /usr/local/bin/mopidy
Platform: Linux-5.10.17-v7l±armv7l-with-debian-10.9
Python: CPython 3.7.3 from /usr/lib/python3.7
Mopidy: 3.2.0 from /usr/local/lib/python3.7/dist-packages
requests: 2.21.0 from /usr/lib/python3/dist-packages
setuptools: 40.8.0 from /usr/lib/python3/dist-packages
Pykka: 3.0.1 from /usr/local/lib/python3.7/dist-packages
importlib-metadata: 4.5.0 from /usr/local/lib/python3.7/dist-packages
zipp: 3.4.1 from /usr/local/lib/python3.7/dist-packages
typing-extensions: 3.10.0.0 from /usr/local/lib/python3.7/dist-packages
tornado: 6.1 from /usr/local/lib/python3.7/dist-packages
mopidy-figlio: 0.0.1 from /home/pi/develop/mopidy-figlio
Mopidy: 3.2.0 from /usr/local/lib/python3.7/dist-packages
Pykka: 3.0.1 from /usr/local/lib/python3.7/dist-packages
importlib-metadata: 4.5.0 from /usr/local/lib/python3.7/dist-packages
zipp: 3.4.1 from /usr/local/lib/python3.7/dist-packages
typing-extensions: 3.10.0.0 from /usr/local/lib/python3.7/dist-packages
setuptools: 40.8.0 from /usr/lib/python3/dist-packages
Mopidy-Iris: 3.58.0 from /usr/local/lib/python3.7/dist-packages
Mopidy: 3.2.0 from /usr/local/lib/python3.7/dist-packages
setuptools: 40.8.0 from /usr/lib/python3/dist-packages
Pykka: 3.0.1 from /usr/local/lib/python3.7/dist-packages
importlib-metadata: 4.5.0 from /usr/local/lib/python3.7/dist-packages
zipp: 3.4.1 from /usr/local/lib/python3.7/dist-packages
typing-extensions: 3.10.0.0 from /usr/local/lib/python3.7/dist-packages
GStreamer: 1.14.4.0 from /usr/lib/python3/dist-packages/gi
Detailed information:
Python wrapper: python-gi 3.30.4
Relevant elements:
Found:
uridecodebin
souphttpsrc
appsrc
alsasink
osssink
oss4sink
id3demux
id3v2mux
lamemp3enc
mpegaudioparse
mpg123audiodec
vorbisdec
vorbisenc
vorbisparse
oggdemux
oggmux
oggparse
flacdec
flacparse
shout2send
Not found:
pulsesink
flump3dec
mad

################# Config ###########################
pi@musicpy4:~ $ mopidy config
[core]
cache_dir = /tmp
config_dir = ~/.config/mopidy
data_dir = ~/Music/data
max_tracklist_length = 10000
restore_state = false

[logging]
verbosity = 0
format = %(levelname)-8s %(asctime)s [%(process)d:%(threadName)s] %(name)s\n %(message)s
color = false
config_file =

[loglevels]
mopidy_figlio.frontend = info

[audio]
mixer = software
mixer_volume = 5
output = alsasink
buffer_time = 5000

[proxy]
scheme =
hostname =
port =
username =
password =

[Figlio]
enabled = true

[file]
enabled = true
media_dirs =
~/Music|Music
excluded_file_extensions =
.directory
.html
.jpeg
.jpg
.log
.nfo
.pdf
.png
.txt
.zip
show_dotfiles = false
follow_symlinks = false
metadata_timeout = 1000

[http]
enabled = false ; Extension disabled by user config.

[m3u]
enabled = true
base_dir = ~/Music
default_encoding = latin-1
default_extension = .m3u8
playlists_dir = ~/Music

[softwaremixer]
enabled = true

[stream]
enabled = true
protocols =
http
https
mms
rtmp
rtmps
rtsp
metadata_blacklist =
timeout = 5000

[iris]
enabled = false ; Extension disabled by user config.

2

I think a debug log (maybe even a GST_DEBUG log if you can filter it sensibly) and your code would be helpful. When you say it doesn’t work do you mean you still hear audio and the tracklist plays right to the end or just the current track or just a few seconds? Have you tried a different audio device?

3

Hi, thanks for quick feedback.
The posted debugs are the output from GST_DEBUG=3 mopidy -vvv | tee ./mopidy.gstreamer already from the moment when I issue playback.stop() command. The playback doenst stop and continues till the end of the current track. It even stops at the end of the current track if I dont use stop() which is another issue because I want it to play all titles from the tracklist. If I dont use seek() it plays the whole track list.

Full debug is here:dpaste: Playback.stop() doesnt work if playback.seek() is used

This is my current POC code:


  def cb_card_inserted(self,channel):
    """
    This is the callback function which is called as soon as a RFID card is inserted or removed in the slot.
    Card insertation could be detected by photo sensor or physical contact switch.
    From the card the playlist URI, the position in the track list and the time position is read.
    Current format is: <playlist uri>,<track pos>,<time pos> 
    Example: m3u:rockantenne.m3u,4,0

    TODOS: a lot
    """
    # We stop plying as soon as card is removed
    if GPIO.input(channel) == GPIO.LOW:
      self.core.playback.stop()
      #self.core.playback.set_state("paused")
      logger.info("Core Playback State:{0}".format(self.core.playback.get_state().get()))
      return
    
    id = None
    rf_tlid = None
    rf_seek = None
    content = None
    reader = SimpleMFRC522()
    
    #Current MFRC522 implementation of SimpleMFRC522 support only 48 bytes maximum data length.
    #create own function for reading and writing.
    id, content = reader.read_no_block()
    logger.info("Card ID: {0} Content: {1}".format(id, content))
    playlist_uri, rf_tlid, rf_seek = content.split(",")
    logger.info("Playlist URI: {0} tlid: {1} seek: {2}".format(playlist_uri, rf_tlid, rf_seek))
    playlist = self.core.playlists.lookup(playlist_uri).get()
    #Playlist name is only derived from playlist filename
    #Add support of extended M3U Tag #PLAYLIST:
    logger.info("Playing: {0} Last Modifed:{1} URI:{2}".format(playlist.name, playlist.last_modified, playlist.uri))
    #self.announce("Ich spiele fĂĽr Dich " + playlist.name)
    tracks = self.core.playlists.get_items(playlist_uri).get()
    track_uris = [track.uri for track in tracks]
    logger.debug("Track URI: {0}".format(track_uris))
    self.core.tracklist.set_single(False)
    self.core.tracklist.set_consume(False)
    # Repeat mode is needed to not stop after first track is played
    self.core.tracklist.set_repeat(True)
    if self.core.tracklist.get_length().get():
      self.core.tracklist.clear()
    self.core.tracklist.add(uris=track_uris, at_position=1)
    first_tlid = self.core.tracklist.get_tl_tracks().get()[0].tlid -1
    logger.info("TL Tracks Type:{0}".format(type(self.core.tracklist.get_tl_tracks().get())))
    logger.info("TLIDs: {0}".format(self.core.tracklist.get_tl_tracks().get()))
    play = self.core.playback.play(tlid=int(rf_tlid)+first_tlid)
    #logger.info("Play command result:{0}".format(play.get()))
    logger.info("Tracklist version: {0} Length: {1} Index:{2}".format(self.core.tracklist.get_version().get(), self.core.tracklist.get_length().get(), self.core.tracklist.index(tlid=4).get()))
    seek = self.core.playback.seek(160000)    
    #seek = self.core.playback.seek(time_position=int(rf_seek))    
    logger.info("Seek: {0}".format(seek.get()))
    #logger.info("Next Track TLID:{0}".format(self.core.tracklist.get_eot_tlid().get()))

I didnt tried yet another audio device and I am not sure f I have another in a Raspi.

4

Hello,

I tried with my USB Headset Jabra LINK 360 and the behavior is the same.
As soon as the stop() command is issued I see only the output from my code and no further debug output. The track continues playing until its end and then playback stops. If track ends I see the debug output with “Got about-to-finish event” etc.
If I dont issue the stop() command there is no difference.

Many thanks for your help.

Michael

5

I would strip everything out of your function, except for the high/low check, and add logging to say if if it’s high or low. Then test that and make sure it’s working as expected when you insert or remove the card. Make sure it’s not being called more than once or anything weird like that.

Then add in play() when you insert the card and stop() when you remove it. The if that’s working properly, build up your code from there.

6

Also ensure you are calling .get() on all the futures as necessary.

7

I removed all unnecessary code, but the behavior is still the same. As soon as I use seek() the track doesnt stop even that get_state() says its stopped.

import logging
from mopidy import core
import pykka
import RPi.GPIO as GPIO

logger = logging.getLogger(__name__) #mopidy_figlio.frontend

class FiglioFrontend(pykka.ThreadingActor, core.CoreListener):
  def __init__(self, config, core):
    super().__init__()
    self.core = core
    self.config = config["Figlio"]
    GPIO.setwarnings(True)
    GPIO.setmode(GPIO.BCM)
    GPIO.setup(25, GPIO.IN, pull_up_down=GPIO.PUD_UP)
    GPIO.add_event_detect(25, GPIO.BOTH, callback=self.cb_card_inserted, bouncetime=1000)

  def on_start(self):
    logger.info('!!!!!!!!!!!!!!!!! Figlio Frontend started !!!!!!!!!!!!!!!!!!!!!!!!!!!!')

  def on_stop(self):
    logger.info('!!!!!!!!!!!!!!!!! Figlio Frontend stopped !!!!!!!!!!!!!!!!!!!!!!!!!!!!')
    GPIO.cleanup()

  def on_failure(self):
    logger.info('!!!!!!!!!!!!!!!!! Figlio Frontend failed !!!!!!!!!!!!!!!!!!!!!!!!!!!!')
    GPIO.cleanup()

  def cb_card_inserted(self,channel):
    # We stop plying as soon as card is removed
    if GPIO.input(channel) == GPIO.LOW:
      self.core.playback.stop()
      #self.core.playback.set_state("paused")
      logger.info("Core Playback State: {0}".format(self.core.playback.get_state().get()))
      return
        
    track_uris = ['file:///home/pi/Music/Blues/004%20doggin%27%20the%20blues.mp3', 'file:///home/pi/Music/Blues/003%20friendless%20blues.mp3']
    self.core.tracklist.add(uris=track_uris, at_position=1)
    play = self.core.playback.play().get()
    logger.info("Play command result:{0}".format(play))
    seek = self.core.playback.seek(160000).get()
    logger.info("Seek command result: {0}".format(seek))

Thats all what I get from debug after line 32 when stop() command is issued.

INFO     2021-08-01 19:07:56,527 [6757:Dummy-8] mopidy_figlio.frontend
  Core Playback State: stopped

Playback of the current track continues to the end and then stops playing. Next track isnt played:

DEBUG    2021-08-01 19:08:07,327 [6757:Dummy-10] mopidy.audio.gst
  Got about-to-finish event.
DEBUG    2021-08-01 19:08:07,327 [6757:Dummy-10] mopidy.audio.actor
  Running about-to-finish callback.
DEBUG    2021-08-01 19:08:14,831 [6757:MainThread] mopidy.audio.gst
  Got EOS (end of stream) bus message.
DEBUG    2021-08-01 19:08:14,832 [6757:MainThread] mopidy.audio.actor
  Audio event: reached_end_of_stream()
DEBUG    2021-08-01 19:08:14,834 [6757:MainThread] mopidy.listener
  Sending reached_end_of_stream to AudioListener: {}
DEBUG    2021-08-01 19:08:14,835 [6757:Core-6] mopidy.core.playback
  Changing state: stopped -> stopped
DEBUG    2021-08-01 19:08:14,835 [6757:Core-6] mopidy.core.playback
  Triggering playback state change event
DEBUG    2021-08-01 19:08:14,836 [6757:Core-6] mopidy.listener
  Sending playback_state_changed to CoreListener: {'old_state': 'stopped', 'new_state': 'stopped'}
DEBUG    2021-08-01 19:08:14,838 [6757:Core-6] mopidy.core.playback
  Triggering track playback ended event
DEBUG    2021-08-01 19:08:14,839 [6757:Core-6] mopidy.listener
  Sending track_playback_ended to CoreListener: {'tl_track': TlTrack(tlid=1, track=Track(artists=[Artist(name='Big Joe Turner')], bitrate=160001, genre='Blues', length=185971, name="Doggin' The Blues", uri='file:///home/pi/Music/Blues/004%20doggin%27%20the%20blues.mp3')), 'time_position': 185364}
8

Hello, even if I send the stop() right after the seek command ist doesnt stop, continue the current track at seeked postion, then stops and doesnt play next track from tracklist.

import logging
from mopidy import core
import pykka

logger = logging.getLogger(__name__) #mopidy_figlio.frontend

class FiglioFrontend(pykka.ThreadingActor, core.CoreListener):
  def __init__(self, config, core):
    super().__init__()
    self.core = core
    self.config = config["Figlio"]
    track_uris = ['file:///home/pi/Music/Blues/004%20doggin%27%20the%20blues.mp3', 'file:///home/pi/Music/Blues/003%20friendless%20blues.mp3']
    self.core.tracklist.add(uris=track_uris)
    play = self.core.playback.play().get()
    logger.info("Play command result:{0}".format(play))
    self.core.playback.seek(160000).get()
    logger.info("Sending Stop command")
    self.core.playback.stop().get()

Debug code is here:
https://dpaste.com/BTX9W286U

9

OK, anything in __init__() runs at the time Mopidy creates the frontend (in the main thread). You generally want to do your initialisation work in on_start() running in your frontend’s thread. Ultimately cb_card_inserted needs to be running in FiglioFrontend’s ThreadingActor, not MainThread.

10

p.s. gpiozero is a much nicer library than RPi.GPIO.

11

@kingosticks Thank you for your feedback, I was to much focusing on minimizing the code. Changed now everything to run at on_start but its still the same situation. If I run stop() the current track continues til the end and then stops. Next track isnt played even if I doesnt run stop.
Thanks for the hint with gpizero, I will definately have a look at it.

Here is my current code:

import logging
from mopidy import core
import pykka

logger = logging.getLogger(__name__) #mopidy_figlio.frontend

class FiglioFrontend(pykka.ThreadingActor, core.CoreListener):
    def __init__(self, config, core):
        super().__init__()
        self.core = core
        self.config = config["Figlio"]
    
    def on_start(self):
        logger.info('!!!!!!!!!!!!!!!!! Figlio Frontend started !!!!!!!!!!!!!!!!!!!!!!!!!!!!')
        track_uris = ['file:///home/pi/Music/Blues/004%20doggin%27%20the%20blues.mp3', 'file:///home/pi/Music/Blues/003%20friendless%20blues.mp3']
        self.core.tracklist.add(uris=track_uris)
        play= self.core.playback.play().get()
        logger.info("Play command result:{0}".format(play))
        seek = self.core.playback.seek(160000).get()
        logger.info("Seek command result: {0}".format(seek))
        input("Press Enter to stop...")
        stop = self.core.playback.stop().get()
        logger.info("Sent Stop command: {0}".format(stop))

    def on_stop(self):
        logger.info('!!!!!!!!!!!!!!!!! Figlio Frontend stopped !!!!!!!!!!!!!!!!!!!!!!!!!!!!')
    

    def on_failure(self):
        logger.info('!!!!!!!!!!!!!!!!! Figlio Frontend failed !!!!!!!!!!!!!!!!!!!!!!!!!!!!')
12

OK super, I’ll try that code out. Thinking some more, I don’t think any other frontends would try and start/stop playback within on-start(). Technically, at the point the frontend starts we might not have started our glib mainloop which I would expect breaks gstreamer events. That might be the reason. Could you just insert a sleep before you start using core.playback?

13

I tried the same code on a Raspi2B to ensure that its not related to my setup. Even if I add a 10 second sleep as first command in on_start() it doesnt work. Same behavior as above described.
Doing that in on_start() is only to have a minmalistic code. I am open for any other ideas.

14

Thanks for gpiozero, look´ s like python becomes more and more a natural language. This library make things of course easier.
I used pause command and have even with that curious results.
If I insert card the track starts playing at the correct seek postion. If I then press pause button, the track starts from beginning. Pressing pause button again, the track pause and play as expected. If I then remove the card the stop() command works correct.

import logging
from mopidy import core
import pykka
from gpiozero import Button

logger = logging.getLogger(__name__) #mopidy_figlio.frontend

class FiglioFrontend(pykka.ThreadingActor, core.CoreListener):
    def __init__(self, config, core):
        super().__init__()
        self.core = core
        self.config = config["Figlio"]
    
    def on_start(self):
        logger.info('!!!!!!!!!!!!!!!!! Figlio Frontend started !!!!!!!!!!!!!!!!!!!!!!!!!!!!')
        #Define button to play/pause
        self.button = Button(17,pull_up=False)
        self.button.when_released = self.cb_pause_play
        #photo sensor; If high or active, card is inserted.
        self.sensor = Button(25,pull_up=False)
        self.sensor.when_pressed = self.cb_card_inserted
        self.sensor.when_released = self.cb_stop
        logger.info("Playback State: {0}".format(self.core.playback.get_state().get()))

    def on_stop(self):
        logger.info('!!!!!!!!!!!!!!!!! Figlio Frontend stopped !!!!!!!!!!!!!!!!!!!!!!!!!!!!')

    def on_failure(self):
        logger.info('!!!!!!!!!!!!!!!!! Figlio Frontend failed !!!!!!!!!!!!!!!!!!!!!!!!!!!!')

    def cb_stop(self):
        stop = self.core.playback.stop().get()
        logger.info("Sent Stop command: {0}".format(stop))
        logger.info("Playback State: {0}".format(self.core.playback.get_state().get()))
    
    def cb_play(self):
        play = self.core.playback.play().get()
        logger.info("Sent Play command: {0}".format(play))
        logger.info("Playback State: {0}".format(self.core.playback.get_state().get()))
    
    def cb_pause_play(self):
        logger.info("Pause/Play pressed")
        if self.core.playback.get_state().get() == core.PlaybackState.PLAYING:
            self.core.playback.pause()
        else:
            self.core.playback.play()
        logger.info("Playback State: {0}".format(self.core.playback.get_state().get()))

    def cb_card_inserted(self):
        logger.info("Card inserted")
        track_uris = ['file:///home/pi/Music/Blues/004%20doggin%27%20the%20blues.mp3', 'file:///home/pi/Music/Blues/003%20friendless%20blues.mp3']
        self.core.tracklist.add(uris=track_uris)
        seek = self.core.playback.seek(160000).get()
        logger.info("Seek command result: {0}".format(seek))
        logger.info("Playback State: {0}".format(self.core.playback.get_state().get()))

    def cb_card_removed():
        pass

!!!!!!!!!!!!!!!!! Figlio Frontend started !!!!!!!!!!!!!!!!!!!!!!!!!!!!
INFO     2021-08-08 11:34:04,914 [7335:MainThread] mopidy.commands
  Starting GLib mainloop
INFO     2021-08-08 11:34:04,981 [7335:FiglioFrontend-7] mopidy_figlio.frontend
  Playback State: stopped
INFO     2021-08-08 11:34:07,160 [7335:Dummy-10] mopidy_figlio.frontend
  Card inserted
INFO     2021-08-08 11:34:07,292 [7335:Dummy-10] mopidy_figlio.frontend
  Seek command result: False
INFO     2021-08-08 11:34:07,294 [7335:Dummy-10] mopidy_figlio.frontend
  Playback State: stopped
INFO     2021-08-08 11:34:10,720 [7335:Dummy-10] mopidy_figlio.frontend
  Pause/Play pressed
INFO     2021-08-08 11:34:10,799 [7335:Dummy-10] mopidy_figlio.frontend
  Playback State: stopped
INFO     2021-08-08 11:34:13,486 [7335:Dummy-10] mopidy_figlio.frontend
  Pause/Play pressed
INFO     2021-08-08 11:34:13,511 [7335:Dummy-10] mopidy_figlio.frontend
  Playback State: paused
INFO     2021-08-08 11:34:14,938 [7335:Dummy-10] mopidy_figlio.frontend
  Pause/Play pressed
INFO     2021-08-08 11:34:14,947 [7335:Dummy-10] mopidy_figlio.frontend
  Playback State: playing
INFO     2021-08-08 11:34:16,530 [7335:Dummy-10] mopidy_figlio.frontend
  Sent Stop command: None
INFO     2021-08-08 11:34:16,532 [7335:Dummy-10] mopidy_figlio.frontend
  Playback State: stopped
15

It’s a bit tricky for me to run this code since I don’t have any buttons to press. Can you provide a debug log, there’s not enough printing in this to see what is happening.

Also note:

  • seek should return True to indicate success.
  • performing play when the track is already playing will restart playback from the start.

So from your last post, the thing that doesn’t make sense to me is, if seek() is failing, why is playback starting? And then of course, why is seek() failing in the first place? The debug log would help.

16

I take that back, I can reproduce this. This looks like our bug. As a workaround for now, start playback before seeking in cb_card_inserted.

1 Like
17

I opened issue Seeking when stopped does not go into PLAYING state · Issue #2005 · mopidy/mopidy · GitHub for this. Fix looks simple.

2 Likes
18

I tried already play() before seek(), it doesnt work either. Pls. see above and let me know if you need more debugs.
Thank you very much for fixing this. Looking forward to test it.

19

You’d have to insert a sleep also I think. The bug can be avoided if seeking when playing. But changing from stopped to playing is not instantaneous and actually happens a short while after play returns. So issuing seek too quickly after the play still hits the bug. To be honest it’s a crap workaround. Slightly better would be to move the seek into track_playback_started instead.

Alternatively you are welcome to try the fix I submitted at Fix/seek when stopped by kingosticks · Pull Request #2006 · mopidy/mopidy · GitHub

20

Thanks for the fix, I will test it soon.