Playlist playback speed error

csibug · April 5, 2020, 6:32pm

Hi All,

the environment:

raspberry pi zero w
mopidy 2.2.3 running as a service.
gstreamer 1.10.4-1
audio from hdmi
Advanced Linux Sound Architecture Driver Version k4.19.66+.

I have a playlist with a local file and a radio stream url: http://stream001.radio.hu:8080/mr1.mp3

the local file play is ok, but the radio stream plays pretty slow (maybe half speed).

here is the mopidy debug log fragment:

Apr  5 20:17:13 bbuddypi mopidy[1223]:   Backend translated URI from local:track:radios/kossuth.mp3 to file:///home/pi/bbuddy_git/bbuddy/tts/radios/kossuth.mp3
Apr  5 20:17:13 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:13,695 [1223:SoftwareMixer-1] mopidy.mixer
Apr  5 20:17:13 bbuddypi mopidy[1223]:   Mixer event: volume_changed(volume=100)
Apr  5 20:17:13 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:13,710 [1223:SoftwareMixer-1] mopidy.listener
Apr  5 20:17:13 bbuddypi mopidy[1223]:   Sending volume_changed to MixerListener: {'volume': 100}
Apr  5 20:17:13 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:13,745 [1223:Audio-2] mopidy.audio.gst
Apr  5 20:17:13 bbuddypi mopidy[1223]:   Got source-setup signal: element=GstFileSrc
Apr  5 20:17:13 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:13,806 [1223:Audio-2] mopidy.audio.gst
Apr  5 20:17:13 bbuddypi mopidy[1223]:   Changing state to GST_STATE_PLAYING: result=GST_STATE_CHANGE_ASYNC
Apr  5 20:17:13 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:13,819 [1223:Core-7] mopidy.listener
Apr  5 20:17:13 bbuddypi mopidy[1223]:   Sending volume_changed to CoreListener: {'volume': 100}
Apr  5 20:17:13 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:13,832 [1223:HttpServer] mopidy.http.handlers
Apr  5 20:17:13 bbuddypi mopidy[1223]:   Sent WebSocket message to 127.0.0.1: '{"jsonrpc": "2.0", "id": 15, "result": null}'
Apr  5 20:17:13 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:13,858 [1223:MpdFrontend-8] mopidy.listener
Apr  5 20:17:13 bbuddypi mopidy[1223]:   Sending mixer to MpdSession: {}
Apr  5 20:17:13 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:13,893 [1223:MainThread] mopidy.audio.gst
Apr  5 20:17:13 bbuddypi mopidy[1223]:   Got STATE_CHANGED bus message: old=GST_STATE_PAUSED new=GST_STATE_READY pending=GST_STATE_VOID_PENDING
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,064 [1223:Dummy-13] mopidy.audio.gst
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Got SEGMENT pad event: rate=1.0 format=time start=0 stop=18446744073709551615 position=0
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,084 [1223:Dummy-13] mopidy.audio.actor
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Audio event: position_changed(position=0L)
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,100 [1223:Dummy-13] mopidy.listener
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Sending position_changed to AudioListener: {'position': 0L}
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,107 [1223:Dummy-11] mopidy.audio.gst
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Got about-to-finish event.
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,077 [1223:MainThread] mopidy.audio.gst
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Got STREAM_START bus message
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,116 [1223:MainThread] mopidy.audio.actor
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Audio event: stream_changed(uri='file:///home/pi/bbuddy_git/bbuddy/tts/radios/kossuth.mp3')
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,119 [1223:MainThread] mopidy.listener
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Sending stream_changed to AudioListener: {'uri': 'file:///home/pi/bbuddy_git/bbuddy/tts/radios/kossuth.mp3'}
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,135 [1223:Core-7] mopidy.core.playback
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Changing state: stopped -> playing
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,137 [1223:Core-7] mopidy.core.playback
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Triggering playback state change event
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,140 [1223:Core-7] mopidy.listener
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Sending playback_state_changed to CoreListener: {'old_state': u'stopped', 'new_state': u'playing'}
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,156 [1223:MpdFrontend-8] mopidy.listener
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Sending player to MpdSession: {}
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,209 [1223:Core-7] mopidy.core.playback
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Triggering track playback started event
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,191 [1223:Dummy-11] mopidy.audio.actor
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Running about-to-finish callback.
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,289 [1223:Core-7] mopidy.listener
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Sending track_playback_started to CoreListener: {'tl_track': TlTrack(tlid=3, track=Track(uri='local:track:radios/kossuth.mp3'))}
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,263 [1223:MainThread] mopidy.audio.gst
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Got TAG bus message: tags={'nominal-bitrate': [32000L], 'audio-codec': [u'MPEG-1 Layer 3 (MP3)'], 'has-crc': [False], 'channel-mode': [u'mono']}
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,312 [1223:MainThread] mopidy.audio.actor
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Audio event: tags_changed(tags=['nominal-bitrate', 'audio-codec', 'has-crc', 'channel-mode'])
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,333 [1223:MainThread] mopidy.listener
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Sending tags_changed to AudioListener: {'tags': ['nominal-bitrate', 'audio-codec', 'has-crc', 'channel-mode']}
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,387 [1223:MainThread] mopidy.audio.gst
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Got STATE_CHANGED bus message: old=GST_STATE_READY new=GST_STATE_PAUSED pending=GST_STATE_PLAYING
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,405 [1223:MainThread] mopidy.audio.gst
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Got ASYNC_DONE bus message.
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,438 [1223:MainThread] mopidy.audio.gst
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Got TAG bus message: tags={'nominal-bitrate': [32000L], 'has-crc': [False], 'audio-codec': [u'MPEG-1 Layer 3 (MP3)'], 'minimum-bitrate': [32000L], 'bitrate': [32000L], 'maximum
-bitrate': [32000L], 'channel-mode': [u'mono']}
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,461 [1223:MainThread] mopidy.audio.actor
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Audio event: tags_changed(tags=['minimum-bitrate', 'bitrate', 'maximum-bitrate'])
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,454 [1223:StreamBackend-3] mopidy.stream.actor
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Unwrapping stream from URI: http://stream001.radio.hu:8080/mr1.mp3
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,479 [1223:MainThread] mopidy.listener
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Sending tags_changed to AudioListener: {'tags': ['minimum-bitrate', 'bitrate', 'maximum-bitrate']}
Apr  5 20:17:14 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:14,987 [1223:MainThread] mopidy.audio.gst
Apr  5 20:17:14 bbuddypi mopidy[1223]:   Got STATE_CHANGED bus message: old=GST_STATE_PAUSED new=GST_STATE_PLAYING pending=GST_STATE_VOID_PENDING
Apr  5 20:17:15 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:15,002 [1223:MainThread] mopidy.audio.actor
Apr  5 20:17:15 bbuddypi mopidy[1223]:   Audio event: state_changed(old_state=playing, new_state=playing, target_state=None)
Apr  5 20:17:15 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:15,020 [1223:MainThread] mopidy.listener
Apr  5 20:17:15 bbuddypi mopidy[1223]:   Sending state_changed to AudioListener: {'old_state': u'playing', 'target_state': None, 'new_state': u'playing'}
Apr  5 20:17:16 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:16,480 [1223:StreamBackend-3] mopidy.stream.actor
Apr  5 20:17:16 bbuddypi mopidy[1223]:   Unwrapped potential None stream: http://stream001.radio.hu:8080/mr1.mp3
Apr  5 20:17:16 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:16,499 [1223:SoftwareMixer-1] mopidy.mixer
Apr  5 20:17:16 bbuddypi mopidy[1223]:   Mixer event: volume_changed(volume=100)
Apr  5 20:17:16 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:16,506 [1223:SoftwareMixer-1] mopidy.listener
Apr  5 20:17:16 bbuddypi mopidy[1223]:   Sending volume_changed to MixerListener: {'volume': 100}
Apr  5 20:17:16 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:16,532 [1223:Core-7] mopidy.listener
Apr  5 20:17:16 bbuddypi mopidy[1223]:   Sending volume_changed to CoreListener: {'volume': 100}
Apr  5 20:17:16 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:16,545 [1223:MpdFrontend-8] mopidy.listener
Apr  5 20:17:16 bbuddypi mopidy[1223]:   Sending mixer to MpdSession: {}
Apr  5 20:17:16 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:16,580 [1223:Dummy-11] mopidy.audio.gst
Apr  5 20:17:16 bbuddypi mopidy[1223]:   Got source-setup signal: element=GstSoupHTTPSrc
Apr  5 20:17:16 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:16,786 [1223:MainThread] mopidy.audio.gst
Apr  5 20:17:16 bbuddypi mopidy[1223]:   Got STREAM_START bus message
Apr  5 20:17:16 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:16,811 [1223:MainThread] mopidy.audio.actor
Apr  5 20:17:16 bbuddypi mopidy[1223]:   Audio event: stream_changed(uri='http://stream001.radio.hu:8080/mr1.mp3')
Apr  5 20:17:16 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:16,854 [1223:MainThread] mopidy.listener
Apr  5 20:17:16 bbuddypi mopidy[1223]:   Sending stream_changed to AudioListener: {'uri': 'http://stream001.radio.hu:8080/mr1.mp3'}
Apr  5 20:17:16 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:16,892 [1223:Core-7] mopidy.core.playback
Apr  5 20:17:16 bbuddypi mopidy[1223]:   Triggering track playback ended event
Apr  5 20:17:16 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:16,985 [1223:MainThread] mopidy.audio.gst
Apr  5 20:17:16 bbuddypi mopidy[1223]:   Got BUFFERING bus message: percent=1%
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,013 [1223:Core-7] mopidy.core.tracklist
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Triggering event: tracklist_changed()
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,098 [1223:Core-7] mopidy.listener
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Sending tracklist_changed to CoreListener: {}
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,065 [1223:Dummy-13] mopidy.audio.gst
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Got SEGMENT pad event: rate=1.0 format=time start=0 stop=18446744073709551615 position=0
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,117 [1223:Dummy-13] mopidy.audio.actor
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Audio event: position_changed(position=0L)
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,120 [1223:Dummy-13] mopidy.listener
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Sending position_changed to AudioListener: {'position': 0L}
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,169 [1223:Core-7] mopidy.listener
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Sending track_playback_ended to CoreListener: {'time_position': 888L, 'tl_track': TlTrack(tlid=3, track=Track(uri='local:track:radios/kossuth.mp3'))}
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,180 [1223:Dummy-13] mopidy.audio.gst
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Got SEGMENT pad event: rate=1.0 format=time start=0 stop=18446744073709551615 position=0
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,182 [1223:MpdFrontend-8] mopidy.listener
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Sending playlist to MpdSession: {}
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,239 [1223:Core-7] mopidy.core.playback
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Changing state: playing -> playing
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,340 [1223:Core-7] mopidy.core.playback
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Triggering playback state change event
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,293 [1223:Dummy-13] mopidy.audio.actor
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Audio event: position_changed(position=0L)
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,356 [1223:Dummy-13] mopidy.listener
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Sending position_changed to AudioListener: {'position': 0L}
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,370 [1223:Core-7] mopidy.listener
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Sending playback_state_changed to CoreListener: {'old_state': u'playing', 'new_state': u'playing'}
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,391 [1223:MpdFrontend-8] mopidy.listener
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Sending player to MpdSession: {}
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,332 [1223:MainThread] mopidy.audio.gst
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Got TAG bus message: tags={'genre': [u'News, Talk, Hungary'], 'organization': [u'Kossuth Radio'], 'location': [u'http://kossuth.humtva.radio.ebu.io./ebu83humtva']}
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,417 [1223:MainThread] mopidy.audio.actor
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Audio event: tags_changed(tags=['genre', 'organization', 'location'])
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,420 [1223:MainThread] mopidy.listener
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Sending tags_changed to AudioListener: {'tags': ['genre', 'organization', 'location']}
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,462 [1223:Core-7] mopidy.core.playback
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Triggering track playback started event
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,486 [1223:Core-7] mopidy.listener
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Sending track_playback_started to CoreListener: {'tl_track': TlTrack(tlid=4, track=Track(name=u'MR1 Kossuth', uri='http://stream001.radio.hu:8080/mr1.mp3'))}
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,500 [1223:MainThread] mopidy.audio.gst
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Got TAG bus message: tags={'genre': [u'News, Talk, Hungary'], 'organization': [u'Kossuth Radio'], 'location': [u'http://kossuth.humtva.radio.ebu.io./ebu83humtva']}
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,553 [1223:MainThread] mopidy.audio.gst
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Got TAG bus message: tags={'location': [u'http://kossuth.humtva.radio.ebu.io./ebu83humtva'], 'has-crc': [False], 'genre': [u'News, Talk, Hungary'], 'organization': [u'Kossuth Radio'], 'nominal-bitrate': [64000L], 'audio-codec': [u'MPEG-1 Layer 3 (MP3)'], 'channel-mode': [u'joint-stereo']}
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,579 [1223:MainThread] mopidy.audio.actor
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Audio event: tags_changed(tags=['has-crc', 'nominal-bitrate', 'audio-codec', 'channel-mode'])
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,596 [1223:MainThread] mopidy.listener
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Sending tags_changed to AudioListener: {'tags': ['has-crc', 'nominal-bitrate', 'audio-codec', 'channel-mode']}
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,622 [1223:MainThread] mopidy.audio.gst
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Got STATE_CHANGED bus message: old=GST_STATE_PLAYING new=GST_STATE_PAUSED pending=GST_STATE_VOID_PENDING
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,640 [1223:MainThread] mopidy.audio.actor
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Audio event: state_changed(old_state=playing, new_state=paused, target_state=playing)
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,643 [1223:MainThread] mopidy.listener
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Sending state_changed to AudioListener: {'old_state': u'playing', 'target_state': u'playing', 'new_state': u'paused'}
Apr  5 20:17:17 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:17,681 [1223:MainThread] mopidy.audio.gst
Apr  5 20:17:17 bbuddypi mopidy[1223]:   Got ASYNC_DONE bus message.
Apr  5 20:17:22 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:22,138 [1223:MainThread] mopidy.audio.gst
Apr  5 20:17:22 bbuddypi mopidy[1223]:   Got BUFFERING bus message: percent=100%
Apr  5 20:17:22 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:22,205 [1223:MainThread] mopidy.audio.gst
Apr  5 20:17:22 bbuddypi mopidy[1223]:   Got TAG bus message: tags={'nominal-bitrate': [64000L], 'has-crc': [False], 'audio-codec': [u'MPEG-1 Layer 3 (MP3)'], 'minimum-bitrate': [64006L], 'maximum-bitrate': [64006L], 'location': [u'http://kossuth.humtva.radio.ebu.io./ebu83humtva'], 'genre': [u'News, Talk, Hungary'], 'organization': [u'Kossuth Radio'], 'bitrate': [63975L], 'channel-mode': [u'joint-stereo']}
Apr  5 20:17:22 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:22,218 [1223:MainThread] mopidy.audio.actor
Apr  5 20:17:22 bbuddypi mopidy[1223]:   Audio event: tags_changed(tags=['minimum-bitrate', 'bitrate', 'maximum-bitrate'])
Apr  5 20:17:22 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:22,221 [1223:MainThread] mopidy.listener
Apr  5 20:17:22 bbuddypi mopidy[1223]:   Sending tags_changed to AudioListener: {'tags': ['minimum-bitrate', 'bitrate', 'maximum-bitrate']}
Apr  5 20:17:22 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:22,272 [1223:MainThread] mopidy.audio.gst
Apr  5 20:17:22 bbuddypi mopidy[1223]:   Got TAG bus message: tags={'nominal-bitrate': [64000L], 'has-crc': [False], 'title': [u'Sportvilag'], 'audio-codec': [u'MPEG-1 Layer 3 (MP3)'], 'minimum-bitrate': [64006L], 'maximum-bitrate': [64006L], 'bitrate': [63998L], 'channel-mode': [u'joint-stereo']}
Apr  5 20:17:22 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:22,289 [1223:MainThread] mopidy.audio.actor
Apr  5 20:17:22 bbuddypi mopidy[1223]:   Audio event: tags_changed(tags=['title', 'bitrate'])
Apr  5 20:17:22 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:22,292 [1223:MainThread] mopidy.listener
Apr  5 20:17:22 bbuddypi mopidy[1223]:   Sending tags_changed to AudioListener: {'tags': ['title', 'bitrate']}
Apr  5 20:17:22 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:22,338 [1223:Core-7] mopidy.listener
Apr  5 20:17:22 bbuddypi mopidy[1223]:   Sending stream_title_changed to CoreListener: {'title': u'Sportvilag'}
Apr  5 20:17:22 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:22,361 [1223:MpdFrontend-8] mopidy.listener
Apr  5 20:17:22 bbuddypi mopidy[1223]:   Sending playlist to MpdSession: {}
Apr  5 20:17:22 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:22,440 [1223:MainThread] mopidy.audio.gst
Apr  5 20:17:22 bbuddypi mopidy[1223]:   Got STATE_CHANGED bus message: old=GST_STATE_PAUSED new=GST_STATE_PLAYING pending=GST_STATE_VOID_PENDING
Apr  5 20:17:22 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:22,459 [1223:MainThread] mopidy.audio.actor
Apr  5 20:17:22 bbuddypi mopidy[1223]:   Audio event: state_changed(old_state=paused, new_state=playing, target_state=None)
Apr  5 20:17:22 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:22,473 [1223:MainThread] mopidy.listener
Apr  5 20:17:22 bbuddypi mopidy[1223]:   Sending state_changed to AudioListener: {'old_state': u'paused', 'target_state': None, 'new_state': u'playing'}
Apr  5 20:17:22 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:22,513 [1223:MainThread] mopidy.audio.gst
Apr  5 20:17:22 bbuddypi mopidy[1223]:   Got TAG bus message: tags={'nominal-bitrate': [64000L], 'has-crc': [False], 'title': [u'Sportvilag'], 'audio-codec': [u'MPEG-1 Layer 3 (MP3)'], 'minimum-bitrate': [63700L], 'maximum-bitrate': [64006L], 'bitrate': [63994L], 'channel-mode': [u'joint-stereo']}
Apr  5 20:17:22 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:22,591 [1223:MainThread] mopidy.audio.actor
Apr  5 20:17:22 bbuddypi mopidy[1223]:   Audio event: tags_changed(tags=['minimum-bitrate', 'bitrate'])
Apr  5 20:17:22 bbuddypi mopidy[1223]: DEBUG    2020-04-05 20:17:22,612 [1223:MainThread] mopidy.listener

i have successfully turned on gstreamer debug logging.

0:00:58.393696415 ESC[336m 1223ESC[00m  0x1b20fc0 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:3491:gst_base_src_start_complete:<filesrc0>ESC[00m pad not activated yet
0:00:58.927776728 ESC[336m 1223ESC[00m  0x1b20fc0 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:00:58.975254778 ESC[336m 1223ESC[00m  0x1b20fc0 ESC[33;01mWARN   ESC[00m ESC[00;01m                 bin gstbin.c:2802:gst_bin_do_latency_func:<pipeline0>ESC[00m did not really configure latency of 0:00:00.000000000
0:00:59.081303655 ESC[336m 1223ESC[00m  0x17e5950 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:2400:gst_base_src_update_length:<filesrc0>ESC[00m processing at or past EOS
0:00:59.114392993 ESC[336m 1223ESC[00m  0x1b20fc0 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:00:59.823473885 ESC[336m 1223ESC[00m  0x1afcfa0 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:3491:gst_base_src_start_complete:<source>ESC[00m pad not activated yet
0:00:59.889307576 ESC[336m 1223ESC[00m  0x1afcfa0 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:3491:gst_base_src_start_complete:<source>ESC[00m pad not activated yet
0:00:59.949905371 ESC[336m 1223ESC[00m  0x17e50f0 ESC[33;01mWARN   ESC[00m ESC[00m                alsa conf.c:4974:snd_config_expand:ESC[00m alsalib error: Unknown parameters {AES0 0x02 AES1 0x82 AES2 0x00 AES3 0x02}
0:00:59.950255364 ESC[336m 1223ESC[00m  0x17e50f0 ESC[33;01mWARN   ESC[00m ESC[00m                alsa pcm.c:2495:snd_pcm_open_noupdate:ESC[00m alsalib error: Unknown PCM default:{AES0 0x02 AES1 0x82 AES2 0x00 AES3 0x02}
0:01:00.764755240 ESC[336m 1223ESC[00m 0xb411a180 ESC[33;01mWARN   ESC[00m ESC[00m     audio-resampler audio-resampler.c:273:convert_taps_gint16_c:ESC[00m can't find exact taps
0:01:00.805746430 ESC[336m 1223ESC[00m 0xb411a120 ESC[33;01mWARN   ESC[00m ESC[00m                alsa pcm_hw.c:1250:snd_pcm_hw_get_chmap:ESC[00m alsalib error: Cannot read Channel Map ctl
: No such file or directory
0:01:01.175042132 ESC[336m 1223ESC[00m  0x1b73cc0 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:2400:gst_base_src_update_length:<source>ESC[00m processing at or past EOS
0:02:22.882408535 ESC[336m 1223ESC[00m  0x1b20fc0 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:3491:gst_base_src_start_complete:<filesrc1>ESC[00m pad not activated yet
0:02:22.931275933 ESC[336m 1223ESC[00m  0x1b20fc0 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:22.941267811 ESC[336m 1223ESC[00m  0x1b20fc0 ESC[33;01mWARN   ESC[00m ESC[00;01m                 bin gstbin.c:2802:gst_bin_do_latency_func:<pipeline1>ESC[00m did not really configure latency of 0:00:00.000000000
0:02:22.977145369 ESC[336m 1223ESC[00m 0xb3714c30 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:2400:gst_base_src_update_length:<filesrc1>ESC[00m processing at or past EOS
0:02:22.982684301 ESC[336m 1223ESC[00m  0x1b20fc0 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:23.764887718 ESC[336m 1223ESC[00m  0x1afcfa0 ESC[33;01mWARN   ESC[00m ESC[00m                alsa gstalsasink.c:1099:gst_alsasink_delay:<alsasink0>ESC[00m snd_pcm_delay returned negative delay
0:02:23.907406975 ESC[336m 1223ESC[00m  0x1afcfa0 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:3491:gst_base_src_start_complete:<source>ESC[00m pad not activated yet
0:02:23.936017624 ESC[336m 1223ESC[00m  0x1afcfa0 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:3491:gst_base_src_start_complete:<source>ESC[00m pad not activated yet
0:02:23.954023404 ESC[336m 1223ESC[00m 0xb411a120 ESC[33;01mWARN   ESC[00m ESC[00m                alsa conf.c:4974:snd_config_expand:ESC[00m alsalib error: Unknown parameters {AES0 0x02 AES1 0x82 AES2 0x00 AES3 0x02}
0:02:23.954397400 ESC[336m 1223ESC[00m 0xb411a120 ESC[33;01mWARN   ESC[00m ESC[00m                alsa pcm.c:2495:snd_pcm_open_noupdate:ESC[00m alsalib error: Unknown PCM default:{AES0 0x02 AES1 0x82 AES2 0x00 AES3 0x02}
0:02:24.163226845 ESC[336m 1223ESC[00m  0x1b73cc0 ESC[33;01mWARN   ESC[00m ESC[00m     audio-resampler audio-resampler.c:273:convert_taps_gint16_c:ESC[00m can't find exact taps
0:02:24.197289429 ESC[336m 1223ESC[00m 0xb411a180 ESC[33;01mWARN   ESC[00m ESC[00m                alsa pcm_hw.c:1250:snd_pcm_hw_get_chmap:ESC[00m alsalib error: Cannot read Channel Map ctl
: No such file or directory
0:02:24.257097701 ESC[336m 1223ESC[00m 0xb411a150 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:2400:gst_base_src_update_length:<source>ESC[00m processing at or past EOS
0:02:26.627526971 ESC[336m 1223ESC[00m 0xb413f980 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:26.679525345 ESC[336m 1223ESC[00m 0xb411a150 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:26.679925340 ESC[336m 1223ESC[00m 0xb411a150 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:26.680160337 ESC[336m 1223ESC[00m 0xb411a150 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:26.680404334 ESC[336m 1223ESC[00m 0xb411a150 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:26.680640332 ESC[336m 1223ESC[00m 0xb411a150 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:26.681879317 ESC[336m 1223ESC[00m 0xb411a150 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:26.683429298 ESC[336m 1223ESC[00m 0xb411a150 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:26.683746294 ESC[336m 1223ESC[00m 0xb411a150 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:26.683979291 ESC[336m 1223ESC[00m 0xb411a150 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:26.684221288 ESC[336m 1223ESC[00m 0xb411a150 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:26.684451286 ESC[336m 1223ESC[00m 0xb411a150 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:26.684680283 ESC[336m 1223ESC[00m 0xb411a150 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:26.685864269 ESC[336m 1223ESC[00m 0xb411a150 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:26.686176265 ESC[336m 1223ESC[00m 0xb411a150 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:26.686405262 ESC[336m 1223ESC[00m 0xb411a150 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:26.686646259 ESC[336m 1223ESC[00m 0xb411a150 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:26.686873256 ESC[336m 1223ESC[00m 0xb411a150 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:26.687099254 ESC[336m 1223ESC[00m 0xb411a150 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4350:gst_bin_query:ESC[00m implement duration caching in GstBin again
0:02:27.128875933 ESC[336m 1223ESC[00m  0x1856bc0 ESC[33;01mWARN   ESC[00m ESC[00m                alsa gstalsasink.c:1099:gst_alsasink_delay:<alsasink0>ESC[00m snd_pcm_delay returned negative delay
0:02:27.144414746 ESC[336m 1223ESC[00m  0x1b73cc0 ESC[33;01mWARN   ESC[00m ESC[00m     audio-resampler audio-resampler.c:273:convert_taps_gint16_c:ESC[00m can't find exact taps
0:02:27.199489084 ESC[336m 1223ESC[00m 0xb411a180 ESC[33;01mWARN   ESC[00m ESC[00m                alsa pcm_hw.c:559:snd_pcm_hw_delay:ESC[00m alsalib error: SNDRV_PCM_IOCTL_DELAY failed (-32): Broken pipe
0:02:27.199860079 ESC[336m 1223ESC[00m 0xb411a180 ESC[33;01mWARN   ESC[00m ESC[00m                alsa pcm_hw.c:559:snd_pcm_hw_delay:ESC[00m alsalib error: SNDRV_PCM_IOCTL_DELAY failed (-32): Broken pipe
0:02:32.262696057 ESC[336m 1223ESC[00m  0x1856bc0 ESC[33;01mWARN   ESC[00m ESC[00m                alsa gstalsasink.c:1099:gst_alsasink_delay:<alsasink0>ESC[00m snd_pcm_delay returned negative delay
0:10:08.346151732 ESC[336m 1223ESC[00m  0x1afcfa0 ESC[33;01mWARN   ESC[00m ESC[00m                alsa gstalsasink.c:1099:gst_alsasink_delay:<alsasink0>ESC[00m snd_pcm_delay returned negative delay

thanks for all the help!

kingosticks · April 5, 2020, 6:58pm

I think there was some fixes for this in later versions. This is an old verison of Mopidy presumably running on a very old version of Raspbian (Gstreamer 1.10). Can you upgrade to a version we support?

csibug · April 5, 2020, 7:07pm

thank you for your quick answer!

do i need to upgrade to 3.x version or is there a fix in a later 2.x?

i think i understand, so i need to update the raspbian version too.

thank you again!

kingosticks · April 5, 2020, 7:23pm

The fix I am thinking of actually went into 2.2.3 so you have that already. You could have a look at the other changes in 2.x but nothing springs to mind.

It’s very possible you’d find different behaviour with the latest version of GStreamer that is available in latest version of Raspbian, and that is the only version we want to support.

csibug · April 5, 2020, 8:01pm

Thanks again, i’m currently upgrading to the latest raspbian. i will report back the results.
br.

jjok · April 6, 2020, 7:59am

There’s an issue still open, but like my comment says, I have not experienced the problem since using Mopidy 3.

csibug · April 7, 2020, 11:27am

thank you for your feedback.
i’ve successfully upgraded my OS and mopidy to 3.0.2, but the error still there. what kind of log should i generate to support investigation?

csibug · April 7, 2020, 11:40am

gstreamer.log

0:01:29.975288949 ESC[335m 9082ESC[00m 0xb340e6c0 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:3583:gst_base_src_start_complete:<filesrc0>ESC[00m pad not ac
tivated yet
0:01:30.207990622 ESC[335m 9082ESC[00m 0xb340e6c0 ESC[32;01mFIXME  ESC[00m ESC[00;01m                 bin gstbin.c:4338:gst_bin_query:ESC[00m implement duration caching in GstBi
n again
0:01:30.226788515 ESC[335m 9082ESC[00m 0xb340e6c0 ESC[33;01mWARN   ESC[00m ESC[00;01m                 bin gstbin.c:2787:gst_bin_do_latency_func:<pipeline0>ESC[00m did not really
 configure latency of 0:00:00.000000000
0:01:30.279638214 ESC[335m 9082ESC[00m  0x1bdedb0 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:2445:gst_base_src_update_length:<filesrc0>ESC[00m processing
at or past EOS
0:01:30.873034830 ESC[335m 9082ESC[00m  0x1b435a0 ESC[33;01mWARN   ESC[00m ESC[00m               pulse pulsesink.c:615:gst_pulseringbuffer_open_device:<autoaudiosink0-actual-sin
k-pulse>ESC[00m error: Failed to connect: Connection refused
0:01:30.965549302 ESC[335m 9082ESC[00m  0x1b435a0 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:3583:gst_base_src_start_complete:<source>ESC[00m pad not acti
vated yet
0:01:30.986187185 ESC[335m 9082ESC[00m  0x1b435a0 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:3583:gst_base_src_start_complete:<source>ESC[00m pad not acti
vated yet
0:01:31.038724885 ESC[335m 9082ESC[00m  0x1bde950 ESC[33;01mWARN   ESC[00m ESC[00m                alsa conf.c:4871:parse_args:ESC[00m alsalib error: Unknown parameter AES0
0:01:31.038989884 ESC[335m 9082ESC[00m  0x1bde950 ESC[33;01mWARN   ESC[00m ESC[00m                alsa conf.c:5031:snd_config_expand:ESC[00m alsalib error: Parse arguments error
: No such file or directory
0:01:31.039163883 ESC[335m 9082ESC[00m  0x1bde950 ESC[33;01mWARN   ESC[00m ESC[00m                alsa pcm.c:2565:snd_pcm_open_noupdate:ESC[00m alsalib error: Unknown PCM default:{AES0 0x02 AES1 0x82 AES2 0x00 AES3 0x02}
0:01:31.769230718 ESC[335m 9082ESC[00m 0xb3e39b80 ESC[33;01mWARN   ESC[00m ESC[00m     audio-resampler audio-resampler.c:274:convert_taps_gint16_c:ESC[00m can't find exact taps
0:01:31.818512437 ESC[335m 9082ESC[00m 0xb3e39e30 ESC[33;01mWARN   ESC[00m ESC[00m                alsa pcm_hw.c:1355:snd_pcm_hw_get_chmap:ESC[00m alsalib error: Cannot read Channel Map ctl
: No such file or directory
0:01:31.846969274 ESC[335m 9082ESC[00m  0x1db96f0 ESC[33;01mWARN   ESC[00m ESC[00m           audiosink gstaudiosink.c:218:audioringbuffer_thread_func:<autoaudiosink0-actual-sink-alsa>ESC[00m failed to set thread priority
0:01:32.168998437 ESC[335m 9082ESC[00m  0x1bded50 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:2445:gst_base_src_update_length:<source>ESC[00m processing at or past EOS
0:01:32.170601428 ESC[335m 9082ESC[00m  0x1bded50 ESC[33;01mWARN   ESC[00m ESC[00m        audiodecoder gstaudiodecoder.c:1596:gst_audio_decoder_drain:<mpg123audiodec0>ESC[00m still 1 frames left after draining
0:01:43.043566219 ESC[335m 9082ESC[00m 0xb340e6c0 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:3583:gst_base_src_start_complete:<filesrc1>ESC[00m pad not activated yet
0:01:43.086192974 ESC[335m 9082ESC[00m 0xb340e6c0 ESC[33;01mWARN   ESC[00m ESC[00;01m                 bin gstbin.c:2787:gst_bin_do_latency_func:<pipeline1>ESC[00m did not really configure latency of 0:00:00.000000000
0:01:43.110182837 ESC[335m 9082ESC[00m 0xb3e73b20 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:2445:gst_base_src_update_length:<filesrc1>ESC[00m processing at or past EOS
0:01:43.442824929 ESC[335m 9082ESC[00m  0x1b435a0 ESC[33;01mWARN   ESC[00m ESC[00m                alsa gstalsasink.c:1101:gst_alsasink_delay:<autoaudiosink0-actual-sink-alsa>ESC[00m snd_pcm_delay returned negative delay
0:01:43.539948371 ESC[335m 9082ESC[00m  0x1b435a0 ESC[33;01mWARN   ESC[00m ESC[00m               pulse pulsesink.c:615:gst_pulseringbuffer_open_device:<autoaudiosink0-actual-sink-pulse>ESC[00m error: Failed to connect: Connection refused
0:01:43.574429174 ESC[335m 9082ESC[00m  0x1b435a0 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:3583:gst_base_src_start_complete:<source>ESC[00m pad not activated yet
0:01:43.580920136 ESC[335m 9082ESC[00m  0x1b435a0 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:3583:gst_base_src_start_complete:<source>ESC[00m pad not activated yet
0:01:43.597546041 ESC[335m 9082ESC[00m  0x1db9750 ESC[33;01mWARN   ESC[00m ESC[00m                alsa conf.c:4871:parse_args:ESC[00m alsalib error: Unknown parameter AES0
0:01:43.597817039 ESC[335m 9082ESC[00m  0x1db9750 ESC[33;01mWARN   ESC[00m ESC[00m                alsa conf.c:5031:snd_config_expand:ESC[00m alsalib error: Parse arguments error: No such file or directory
0:01:43.598005038 ESC[335m 9082ESC[00m  0x1db9750 ESC[33;01mWARN   ESC[00m ESC[00m                alsa pcm.c:2565:snd_pcm_open_noupdate:ESC[00m alsalib error: Unknown PCM default:{AES0 0x02 AES1 0x82 AES2 0x00 AES3 0x02}
0:01:43.977813859 ESC[335m 9082ESC[00m  0x1bde950 ESC[33;01mWARN   ESC[00m ESC[00m     audio-resampler audio-resampler.c:274:convert_taps_gint16_c:ESC[00m can't find exact taps
0:01:43.991489780 ESC[335m 9082ESC[00m 0xb3e39b50 ESC[33;01mWARN   ESC[00m ESC[00m                alsa pcm_hw.c:1355:snd_pcm_hw_get_chmap:ESC[00m alsalib error: Cannot read Channel Map ctl
: No such file or directory
0:01:31.846969274 ESC[335m 9082ESC[00m  0x1db96f0 ESC[33;01mWARN   ESC[00m ESC[00m           audiosink gstaudiosink.c:218:audioringbuffer_thread_func:<autoaudiosink0-actual-sink-alsa>ESC[00m failed to set thread priority
0:01:32.168998437 ESC[335m 9082ESC[00m  0x1bded50 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:2445:gst_base_src_update_length:<source>ESC[00m processing at or past EOS
0:01:32.170601428 ESC[335m 9082ESC[00m  0x1bded50 ESC[33;01mWARN   ESC[00m ESC[00m        audiodecoder gstaudiodecoder.c:1596:gst_audio_decoder_drain:<mpg123audiodec0>ESC[00m still 1 frames left after draining
0:01:43.043566219 ESC[335m 9082ESC[00m 0xb340e6c0 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:3583:gst_base_src_start_complete:<filesrc1>ESC[00m pad not activated yet
0:01:43.086192974 ESC[335m 9082ESC[00m 0xb340e6c0 ESC[33;01mWARN   ESC[00m ESC[00;01m                 bin gstbin.c:2787:gst_bin_do_latency_func:<pipeline1>ESC[00m did not really configure latency of 0:00:00.000000000
0:01:43.110182837 ESC[335m 9082ESC[00m 0xb3e73b20 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:2445:gst_base_src_update_length:<filesrc1>ESC[00m processing at or past EOS
0:01:43.442824929 ESC[335m 9082ESC[00m  0x1b435a0 ESC[33;01mWARN   ESC[00m ESC[00m                alsa gstalsasink.c:1101:gst_alsasink_delay:<autoaudiosink0-actual-sink-alsa>ESC[00m snd_pcm_delay returned negative delay
0:01:43.539948371 ESC[335m 9082ESC[00m  0x1b435a0 ESC[33;01mWARN   ESC[00m ESC[00m               pulse pulsesink.c:615:gst_pulseringbuffer_open_device:<autoaudiosink0-actual-sink-pulse>ESC[00m error: Failed to connect: Connection refused
0:01:43.574429174 ESC[335m 9082ESC[00m  0x1b435a0 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:3583:gst_base_src_start_complete:<source>ESC[00m pad not activated yet
0:01:43.580920136 ESC[335m 9082ESC[00m  0x1b435a0 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:3583:gst_base_src_start_complete:<source>ESC[00m pad not activated yet
0:01:43.597546041 ESC[335m 9082ESC[00m  0x1db9750 ESC[33;01mWARN   ESC[00m ESC[00m                alsa conf.c:4871:parse_args:ESC[00m alsalib error: Unknown parameter AES0
0:01:43.597817039 ESC[335m 9082ESC[00m  0x1db9750 ESC[33;01mWARN   ESC[00m ESC[00m                alsa conf.c:5031:snd_config_expand:ESC[00m alsalib error: Parse arguments error: No such file or directory
0:01:43.598005038 ESC[335m 9082ESC[00m  0x1db9750 ESC[33;01mWARN   ESC[00m ESC[00m                alsa pcm.c:2565:snd_pcm_open_noupdate:ESC[00m alsalib error: Unknown PCM default:{AES0 0x02 AES1 0x82 AES2 0x00 AES3 0x02}
0:01:43.977813859 ESC[335m 9082ESC[00m  0x1bde950 ESC[33;01mWARN   ESC[00m ESC[00m     audio-resampler audio-resampler.c:274:convert_taps_gint16_c:ESC[00m can't find exact taps
0:01:43.991489780 ESC[335m 9082ESC[00m 0xb3e39b50 ESC[33;01mWARN   ESC[00m ESC[00m                alsa pcm_hw.c:1355:snd_pcm_hw_get_chmap:ESC[00m alsalib error: Cannot read Channel Map ctl
: No such file or directory
0:01:44.004258707 ESC[335m 9082ESC[00m 0xb341ba90 ESC[33;01mWARN   ESC[00m ESC[00m           audiosink gstaudiosink.c:218:audioringbuffer_thread_func:<autoaudiosink0-actual-sink-alsa>ESC[00m failed to set thread priority
0:01:44.122739027 ESC[335m 9082ESC[00m 0xb3e39e30 ESC[33;01mWARN   ESC[00m ESC[00m             basesrc gstbasesrc.c:2445:gst_base_src_update_length:<source>ESC[00m processing at or past EOS
0:01:44.128857992 ESC[335m 9082ESC[00m 0xb3e39e30 ESC[33;01mWARN   ESC[00m ESC[00m        audiodecoder gstaudiodecoder.c:1596:gst_audio_decoder_drain:<mpg123audiodec1>ESC[00m still 1 frames left after draining
0:01:45.554979805 ESC[335m 9082ESC[00m  0x1c6d880 ESC[33;01mWARN   ESC[00m ESC[00m                alsa gstalsasink.c:1101:gst_alsasink_delay:<autoaudiosink0-actual-sink-alsa>ESC[00m snd_pcm_delay returned negative delay
0:01:45.823675261 ESC[335m 9082ESC[00m  0x1bde950 ESC[33;01mWARN   ESC[00m ESC[00m     audio-resampler audio-resampler.c:274:convert_taps_gint16_c:ESC[00m can't find exact taps
0:01:45.832893208 ESC[335m 9082ESC[00m 0xb3e39b50 ESC[33;01mWARN   ESC[00m ESC[00m                alsa pcm_hw.c:611:snd_pcm_hw_delay:ESC[00m alsalib error: SNDRV_PCM_IOCTL_DELAY failed (-32): Broken pipe
0:01:45.833191207 ESC[335m 9082ESC[00m 0xb3e39b50 ESC[33;01mWARN   ESC[00m ESC[00m                alsa pcm_hw.c:611:snd_pcm_hw_delay:ESC[00m alsalib error: SNDRV_PCM_IOCTL_DELAY failed (-32): Broken pipe
0:01:45.859829054 ESC[335m 9082ESC[00m  0x1dafef0 ESC[33;01mWARN   ESC[00m ESC[00m           audiosink gstaudiosink.c:218:audioringbuffer_thread_func:<autoaudiosink0-actual-sink-alsa>ESC[00m failed to set thread priority
0:01:50.516516279 ESC[335m 9082ESC[00m  0x1c6d880 ESC[33;01mWARN   ESC[00m ESC[00m                alsa gstalsasink.c:1101:gst_alsasink_delay:<autoaudiosink0-actual-sink-alsa>ESC[00m snd_pcm_delay returned negative delay

mopidy deps:

 mopidy deps
Executable: /usr/bin/mopidy
Platform: Linux-4.19.97+-armv6l-with-debian-10.3
Python: CPython 3.7.3 from /usr/lib/python3.7
Mopidy: 3.0.2 from /usr/lib/python3/dist-packages
Mopidy-ALSAMixer: 2.0.0 from /usr/lib/python3/dist-packages
Mopidy-Local: 3.1.1 from /usr/lib/python3/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
        pulsesink
        id3demux
        id3v2mux
        lamemp3enc
        mpegaudioparse
        mpg123audiodec
        vorbisdec
        vorbisenc
        vorbisparse
        oggdemux
        oggmux
        oggparse
        flacdec
        flacparse
        shout2send
      Not found:
        flump3dec
        mad

csibug · April 7, 2020, 12:05pm

some additional info: if the first track is the stream, then the stream plays well. if the first track is a local mp3 and the second is the stream, then the stream plays at half speed. the local track always plays at the right speed.

kingosticks · April 7, 2020, 12:07pm

This looks like the alsa issue described at https://muthii.com/blog/?p=361. Could you try the workaround?

kingosticks · April 7, 2020, 12:43pm

Also hardcoding the sample rate in Mopidy’s output config would probably help. If only I could remember the syntax. Something like:

output = audioresample ! rate=48000 ! alsasink

But not that exactly…

csibug · April 7, 2020, 12:44pm

thank you for the answer. i think the setting mentioned in the article above is for kodi. i’m trying to learn more about alsa…

kingosticks · April 7, 2020, 1:22pm

Yes, but your HDMI output should also be able to handle 48k so seems as good a number as any to target. ALSA documentation is generally bad, good luck.

csibug · April 7, 2020, 8:11pm

thank you for all the help. the following workaround solved the problem:
output = audioresample ! audio/x-raw, rate=48000 ! alsasink.
the strange thing is, the gstreamer log isn’t looking any better

Topic		Replies	Views
Mopidy with Gstreamer does not play a single stream or file General	5	2342	October 11, 2015
Flac radio playback possible? Pi MusicBox	16	5751	April 27, 2016
Playlist radiostream not working anymore with 1.1.0 General	4	1767	August 12, 2015
Streaming radio station pausing/buffering General	22	8659	December 26, 2019
Mopidy slowly plays FLAC 48khz General	0	443	May 18, 2020

Playlist playback speed error

Related Topics