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

Call to get_current_track returns outdated information #2024

Open
hhoefener opened this issue Oct 26, 2021 · 4 comments
Open

Call to get_current_track returns outdated information #2024

hhoefener opened this issue Oct 26, 2021 · 4 comments

Comments

@hhoefener
Copy link

Situation

I want to use a physical button to move through the mopidy playlist. I implemented this by having the button trigger a call to core.playback.next. Now, I want to let the user know what the new track is and call core.playback.get_current_track.

Expected behavior

core.playback.get_current_track returns the track I just switched to.

Actual behavior

The call does not reflect the latest change and returns the previous track. This seems to only be the case when tracks are streamed from the internet (seen with tunein and youtube extensions) but not with local files.
@kingosticks
Copy link
Member

Debug log please.

@hhoefener
Copy link
Author

Here is the relevant part as far as I can tell. Just added two tunein stations to the tracklist and called next (2021-10-26 20:10:10,943) and get_current_track (2021-10-26 20:10:12,654) from my speaker (SPEAKER_IP_ADDRESS). Seems to be a race condition, as the new tunein station is not yet playing when I call get_current_track. What do you think?

Here is the log 
DEBUG    2021-10-26 20:10:10,943 [9:HttpServer] mopidy.http.handlers
  Received RPC message from SPEAKER_IP_ADDRESS: b'{"jsonrpc": "2.0", "id": 1, "method": "core.playback.next"}'
DEBUG    2021-10-26 20:10:11,129 [9:MainThread] mopidy.audio.gst
  Got STATE_CHANGED bus message: old=GST_STATE_PLAYING new=GST_STATE_PAUSED pending=GST_STATE_READY
WARNING  2021-10-26 20:10:11,130 [9:MainThread] mopidy.audio.gst
  GStreamer warning: Wav stream not finished properly
DEBUG    2021-10-26 20:10:11,130 [9:MainThread] mopidy.audio.gst
  Got WARNING bus message: error=GLib.Error('Wav stream not finished properly', 'gst-stream-error-quark', 10) debug='gstwavenc.c(1110): gst_wavenc_change_state (): /GstPlayBin:playbin0/GstPlaySink:playsink/GstBin:abin/GstBin:audio-sink/mopidy+audio+actor+_Outputs:mopidy+audio+actor+_outputs0/GstBin:bin0/GstWavEnc:wavenc0:\nWav stream not finished properly, no EOS received before shutdown'
DEBUG    2021-10-26 20:10:11,136 [9:Audio-2] mopidy.audio.gst
  Changing state to GST_STATE_READY: result=GST_STATE_CHANGE_SUCCESS
DEBUG    2021-10-26 20:10:11,137 [9:TuneInBackend-7] mopidy_tunein.tunein
  Tuning station id s264979
DEBUG    2021-10-26 20:10:11,138 [9:TuneInBackend-7] mopidy_tunein.actor
  Looking up URI: 'https://stream.wbez.org/vocalo128?DIST=TuneIn&TGT=TuneIn&maxServers=2&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTYzNTI3ODg2OCwiaXNzIjoidGlzcnYifQ.g38lQFsBXdJNMwCangNw1rrtXpaok9EETM84L59ed9Q'
DEBUG    2021-10-26 20:10:11,138 [9:TuneInBackend-7] mopidy_tunein.actor
  Unwrapping stream from URI: 'https://stream.wbez.org/vocalo128?DIST=TuneIn&TGT=TuneIn&maxServers=2&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTYzNTI3ODg2OCwiaXNzIjoidGlzcnYifQ.g38lQFsBXdJNMwCangNw1rrtXpaok9EETM84L59ed9Q'
DEBUG    2021-10-26 20:10:11,139 [9:MainThread] mopidy.audio.gst
  Got STATE_CHANGED bus message: old=GST_STATE_PAUSED new=GST_STATE_READY pending=GST_STATE_VOID_PENDING
TRACE    2021-10-26 20:10:12,049 [9:TuneInBackend-7] mopidy.audio.scan
  element souphttpsrc3: http-headers, uri=(string)"https://stream.wbez.org/vocalo128\?DIST\=TuneIn\&T...
TRACE    2021-10-26 20:10:12,050 [9:TuneInBackend-7] mopidy.audio.scan
  element typefindelement3: have-type, caps=(structure)"application/x-icy\,\ metadata-interval\=\(int\)16...
TRACE    2021-10-26 20:10:12,060 [9:TuneInBackend-7] mopidy.audio.scan
  element decodebin5: have-audio;
TRACE    2021-10-26 20:10:12,064 [9:TuneInBackend-7] mopidy.audio.scan
  element fakesink3: GstMessageTag, taglist=(taglist)"taglist\,\ organization\=\(string\)/vocalo12...
TRACE    2021-10-26 20:10:12,064 [9:TuneInBackend-7] mopidy.audio.scan
  element fakesink3: GstMessageTag, taglist=(taglist)"taglist\,\ organization\=\(string\)/vocalo12...
TRACE    2021-10-26 20:10:12,065 [9:TuneInBackend-7] mopidy.audio.scan
  element fakesink3: GstMessageTag, taglist=(taglist)"taglist\,\ organization\=\(string\)/vocalo12...
TRACE    2021-10-26 20:10:12,066 [9:TuneInBackend-7] mopidy.audio.scan
  element pipeline3: GstMessageAsyncDone, running-time=(guint64)18446744073709551615;
DEBUG    2021-10-26 20:10:12,070 [9:TuneInBackend-7] mopidy_tunein.actor
  Unwrapped potential None stream: 'https://stream.wbez.org/vocalo128?DIST=TuneIn&TGT=TuneIn&maxServers=2&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTYzNTI3ODg2OCwiaXNzIjoidGlzcnYifQ.g38lQFsBXdJNMwCangNw1rrtXpaok9EETM84L59ed9Q'
DEBUG    2021-10-26 20:10:12,071 [9:TuneInBackend-7] mopidy.backend
  Backend translated URI from tunein:station:s264979 to https://stream.wbez.org/vocalo128?DIST=TuneIn&TGT=TuneIn&maxServers=2&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTYzNTI3ODg2OCwiaXNzIjoidGlzcnYifQ.g38lQFsBXdJNMwCangNw1rrtXpaok9EETM84L59ed9Q
DEBUG    2021-10-26 20:10:12,071 [9:Audio-2] mopidy.audio.actor
  Flags: 2
DEBUG    2021-10-26 20:10:12,072 [9:SoftwareMixer-1] mopidy.mixer
  Mixer event: volume_changed(volume=100)
DEBUG    2021-10-26 20:10:12,072 [9:SoftwareMixer-1] mopidy.listener
  Sending volume_changed to MixerListener: {'volume': 100}
DEBUG    2021-10-26 20:10:12,088 [9:Audio-2] mopidy.audio.gst
  Got source-setup signal: element=GstSoupHTTPSrc
DEBUG    2021-10-26 20:10:12,088 [9:Audio-2] mopidy.audio.gst
  Enabling live stream mode
DEBUG    2021-10-26 20:10:12,090 [9:MainThread] mopidy.audio.gst
  Got STATE_CHANGED bus message: old=GST_STATE_READY new=GST_STATE_PAUSED pending=GST_STATE_PLAYING
DEBUG    2021-10-26 20:10:12,091 [9:Audio-2] mopidy.audio.gst
  Changing state to GST_STATE_PLAYING: result=GST_STATE_CHANGE_ASYNC
DEBUG    2021-10-26 20:10:12,091 [9:Core-9] mopidy.listener
  Sending volume_changed to CoreListener: {'volume': 100}
INFO     2021-10-26 20:10:12,092 [9:HttpServer] tornado.access
  200 POST /mopidy/rpc (SPEAKER_IP_ADDRESS) 1150.42ms
DEBUG    2021-10-26 20:10:12,093 [9:MpdFrontend-13] mopidy.listener
  Sending mixer to MpdSession: {}
DEBUG    2021-10-26 20:10:12,654 [9:HttpServer] mopidy.http.handlers
  Received RPC message from SPEAKER_IP_ADDRESS: b'{"jsonrpc": "2.0", "id": 1, "method": "core.playback.get_current_track"}'
INFO     2021-10-26 20:10:12,656 [9:HttpServer] tornado.access
  200 POST /mopidy/rpc (SPEAKER_IP_ADDRESS) 2.09ms
DEBUG    2021-10-26 20:10:13,047 [9:MainThread] mopidy.audio.gst
  Got STREAM_START bus message
DEBUG    2021-10-26 20:10:13,047 [9:MainThread] mopidy.audio.actor
  Audio event: stream_changed(uri='https://stream.wbez.org/vocalo128?DIST=TuneIn&TGT=TuneIn&maxServers=2&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTYzNTI3ODg2OCwiaXNzIjoidGlzcnYifQ.g38lQFsBXdJNMwCangNw1rrtXpaok9EETM84L59ed9Q')
DEBUG    2021-10-26 20:10:13,047 [9:MainThread] mopidy.listener
  Sending stream_changed to AudioListener: {'uri': 'https://stream.wbez.org/vocalo128?DIST=TuneIn&TGT=TuneIn&maxServers=2&partnertok=eyJhbGciOiJIUzI1NiIsImtpZCI6InR1bmVpbiIsInR5cCI6IkpXVCJ9.eyJ0cnVzdGVkX3BhcnRuZXIiOnRydWUsImlhdCI6MTYzNTI3ODg2OCwiaXNzIjoidGlzcnYifQ.g38lQFsBXdJNMwCangNw1rrtXpaok9EETM84L59ed9Q'}
DEBUG    2021-10-26 20:10:13,048 [9:Core-9] mopidy.core.playback
  Triggering track playback ended event
DEBUG    2021-10-26 20:10:13,048 [9:Core-9] mopidy.listener
  Sending track_playback_ended to CoreListener: {'tl_track': TlTrack(tlid=1, track=Track(album=Album(name='WBEZ Chicago', uri='tunein:station:s27410'), artists=[Artist(name='WBEZ Chicago', uri='tunein:station:s27410')], name='All Things Considered', uri='tunein:station:s27410')), 'time_position': 10552}
DEBUG    2021-10-26 20:10:13,049 [9:Core-9] mopidy.core.playback
  Changing state: playing -> playing
DEBUG    2021-10-26 20:10:13,049 [9:Core-9] mopidy.core.playback
  Triggering playback state change event
DEBUG    2021-10-26 20:10:13,050 [9:Core-9] mopidy.listener
  Sending playback_state_changed to CoreListener: {'old_state': 'playing', 'new_state': 'playing'}
DEBUG    2021-10-26 20:10:13,050 [9:Core-9] mopidy.core.playback
  Triggering track playback started event
DEBUG    2021-10-26 20:10:13,050 [9:Core-9] mopidy.listener
  Sending track_playback_started to CoreListener: {'tl_track': TlTrack(tlid=2, track=Track(album=Album(name='Vocalo Radio - WBEZ-HD2', uri='tunein:station:s264979'), artists=[Artist(name='Vocalo Radio - WBEZ-HD2', uri='tunein:station:s264979')], name='A Tribe Called Quest - Check the Rhime', uri='tunein:station:s264979'))}
DEBUG    2021-10-26 20:10:13,053 [9:MpdFrontend-13] mopidy.listener
  Sending player to MpdSession: {}
DEBUG    2021-10-26 20:10:13,062 [9:Dummy-16] mopidy.audio.gst
  Got SEGMENT pad event: rate=1.0 format=time start=0 stop=18446744073709551615 position=0
DEBUG    2021-10-26 20:10:13,062 [9:Dummy-16] mopidy.audio.actor
  Audio event: position_changed(position=0)
DEBUG    2021-10-26 20:10:13,063 [9:Dummy-16] mopidy.listener
  Sending position_changed to AudioListener: {'position': 0}
DEBUG    2021-10-26 20:10:13,063 [9:Dummy-16] mopidy.audio.gst
  Got SEGMENT pad event: rate=1.0 format=time start=0 stop=18446744073709551615 position=0
DEBUG    2021-10-26 20:10:13,064 [9:Dummy-16] mopidy.audio.actor
  Audio event: position_changed(position=0)
DEBUG    2021-10-26 20:10:13,064 [9:Dummy-16] mopidy.listener
  Sending position_changed to AudioListener: {'position': 0}
DEBUG    2021-10-26 20:10:13,064 [9:MainThread] mopidy.audio.gst
  Got TAG bus message: tags={'organization': ['/vocalo128'], 'genre': ['Misc'], 'location': ['http://www.wbez.org']}
DEBUG    2021-10-26 20:10:13,068 [9:MainThread] mopidy.audio.actor
  Audio event: tags_changed(tags=['organization', 'genre', 'location'])
DEBUG    2021-10-26 20:10:13,068 [9:MainThread] mopidy.listener
  Sending tags_changed to AudioListener: {'tags': ['organization', 'genre', 'location']}
DEBUG    2021-10-26 20:10:13,070 [9:MainThread] mopidy.audio.gst
  Got TAG bus message: tags={'organization': ['/vocalo128'], 'genre': ['Misc'], 'location': ['http://www.wbez.org']}
DEBUG    2021-10-26 20:10:13,071 [9:MainThread] mopidy.audio.gst
  Got TAG bus message: tags={'organization': ['/vocalo128'], 'genre': ['Misc'], 'location': ['http://www.wbez.org'], 'has-crc': [False], 'channel-mode': ['joint-stereo'], 'audio-codec': ['MPEG-1 Layer 3 (MP3)'], 'nominal-bitrate': [128000]}
DEBUG    2021-10-26 20:10:13,071 [9:MainThread] mopidy.audio.actor
  Audio event: tags_changed(tags=['has-crc', 'channel-mode', 'audio-codec', 'nominal-bitrate'])
DEBUG    2021-10-26 20:10:13,072 [9:MainThread] mopidy.listener
  Sending tags_changed to AudioListener: {'tags': ['has-crc', 'channel-mode', 'audio-codec', 'nominal-bitrate']}
DEBUG    2021-10-26 20:10:13,073 [9:MainThread] mopidy.audio.gst
  Got ASYNC_DONE bus message.
DEBUG    2021-10-26 20:10:13,082 [9:MainThread] mopidy.audio.gst
  Got STATE_CHANGED bus message: old=GST_STATE_PAUSED new=GST_STATE_PLAYING pending=GST_STATE_VOID_PENDING
DEBUG    2021-10-26 20:10:13,082 [9:MainThread] mopidy.audio.actor
  Audio event: state_changed(old_state=playing, new_state=playing, target_state=None)
DEBUG    2021-10-26 20:10:13,082 [9:MainThread] mopidy.listener
  Sending state_changed to AudioListener: {'old_state': 'playing', 'new_state': 'playing', 'target_state': None}
DEBUG    2021-10-26 20:10:13,084 [9:MainThread] mopidy.audio.gst
  Got TAG bus message: tags={'organization': ['/vocalo128'], 'genre': ['Misc'], 'location': ['http://www.wbez.org'], 'has-crc': [False], 'channel-mode': ['joint-stereo'], 'audio-codec': ['MPEG-1 Layer 3 (MP3)'], 'nominal-bitrate': [128000], 'minimum-bitrate': [128012], 'maximum-bitrate': [128012], 'bitrate': [128012]}
DEBUG    2021-10-26 20:10:13,084 [9:MainThread] mopidy.audio.actor
  Audio event: tags_changed(tags=['minimum-bitrate', 'maximum-bitrate', 'bitrate'])
DEBUG    2021-10-26 20:10:13,084 [9:MainThread] mopidy.listener
  Sending tags_changed to AudioListener: {'tags': ['minimum-bitrate', 'maximum-bitrate', 'bitrate']}
DEBUG    2021-10-26 20:10:13,160 [9:HttpServer] mopidy.http.handlers
  Received WebSocket message from LAPTOP_IP_ADDRESS: '{"method":"core.tracklist.eot_track","params":{"tl_track":null},"jsonrpc":"2.0","id":1347}'
DEBUG    2021-10-26 20:10:13,161 [9:HttpServer] mopidy.http.handlers
  Sent WebSocket message to LAPTOP_IP_ADDRESS: '{"jsonrpc": "2.0", "id": 1347, "result": {"__model__": "TlTrack", "tlid": 3, "track": {"__model__": "Track", "uri": "tunein:station:s27410", "name": "All Things Considered", "artists": [{"__model__": "Artist", "uri": "tunein:station:s27410", "name": "WBEZ Chicago"}], "album": {"__model__": "Album", "uri": "tunein:station:s27410", "name": "WBEZ Chicago"}}}}'
DEBUG    2021-10-26 20:10:13,161 [9:HttpServer] mopidy.http.handlers
  Received WebSocket message from LAPTOP_IP_ADDRESS: '{"method":"core.tracklist.get_next_tlid","jsonrpc":"2.0","id":1348}'
DEBUG    2021-10-26 20:10:13,162 [9:HttpServer] mopidy.http.handlers
  Sent WebSocket message to LAPTOP_IP_ADDRESS: '{"jsonrpc": "2.0", "id": 1348, "result": 3}'
DEBUG    2021-10-26 20:10:13,163 [9:HttpServer] mopidy.http.handlers
  Received WebSocket message from LAPTOP_IP_ADDRESS: '{"method":"core.tracklist.get_previous_tlid","jsonrpc":"2.0","id":1349}'
DEBUG    2021-10-26 20:10:13,163 [9:HttpServer] mopidy.http.handlers
  Sent WebSocket message to LAPTOP_IP_ADDRESS: '{"jsonrpc": "2.0", "id": 1349, "result": 1}'
DEBUG    2021-10-26 20:10:13,164 [9:HttpServer] mopidy.http.handlers
  Received WebSocket message from LAPTOP_IP_ADDRESS: '{"method":"core.playback.get_stream_title","jsonrpc":"2.0","id":1350}'
DEBUG    2021-10-26 20:10:13,164 [9:HttpServer] mopidy.http.handlers
  Sent WebSocket message to LAPTOP_IP_ADDRESS: '{"jsonrpc": "2.0", "id": 1350, "result": null}'
DEBUG    2021-10-26 20:10:13,248 [9:MainThread] mopidy.audio.gst
  Got TAG bus message: tags={'organization': ['/vocalo128'], 'genre': ['Misc'], 'location': ['http://www.wbez.org'], 'has-crc': [False], 'channel-mode': ['joint-stereo'], 'audio-codec': ['MPEG-1 Layer 3 (MP3)'], 'nominal-bitrate': [128000], 'minimum-bitrate': [127706], 'maximum-bitrate': [128012], 'bitrate': [127995]}
DEBUG    2021-10-26 20:10:13,248 [9:MainThread] mopidy.audio.actor
  Audio event: tags_changed(tags=['minimum-bitrate', 'bitrate'])
DEBUG    2021-10-26 20:10:13,248 [9:MainThread] mopidy.listener
  Sending tags_changed to AudioListener: {'tags': ['minimum-bitrate', 'bitrate']}
DEBUG    2021-10-26 20:10:13,807 [9:MainThread] mopidy.audio.gst
  Got TAG bus message: tags={'title': ["Chicago's Urban Alternative - Vocalo"], 'has-crc': [False], 'channel-mode': ['joint-stereo'], 'audio-codec': ['MPEG-1 Layer 3 (MP3)'], 'nominal-bitrate': [128000], 'minimum-bitrate': [127706], 'maximum-bitrate': [128012], 'bitrate': [128004]}
DEBUG    2021-10-26 20:10:13,808 [9:MainThread] mopidy.audio.actor
  Audio event: tags_changed(tags=['title', 'bitrate'])
DEBUG    2021-10-26 20:10:13,808 [9:MainThread] mopidy.listener
  Sending tags_changed to AudioListener: {'tags': ['title', 'bitrate']}
DEBUG    2021-10-26 20:10:13,809 [9:Core-9] mopidy.listener
  Sending stream_title_changed to CoreListener: {'title': "Chicago's Urban Alternative - Vocalo"}
DEBUG    2021-10-26 20:10:13,809 [9:MpdFrontend-13] mopidy.listener
  Sending playlist to MpdSession: {}

@fmarzocca
Copy link

This is my experience. In order to let the user know which track is playing, after a next I watch for the core event track_playback_started(tl_track) and retrieve the current playing track name. Anyway, what you report looks like a bug.

@kingosticks
Copy link
Member

Commands like this in Mopidy are async. The track change is not guaranteed to have finished by the time next returns. You need to wait for the event as suggested.

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
@kingosticks @fmarzocca @hhoefener