Musicbox seems playing but there is no sound

Hi,

I Use Pi Musicbox on a Raspberry Pi 2B with hifiberry digi+. I play music using spotify.

I have an issue where suddenly the audio stops. In the webinterface it seems like it is normally playing.

I have checked in the log and there seems to be something different compared to when it was working.
This message appears about every second:

2016-09-04 17:03:39,610 - DEBUG Position query failed

Before it looked the same but without the “Position query failed” message.

Just before this happened, the following was in the log:

2016-09-04 17:03:38,727 - DEBUG Triggering reached_end_of_stream event
2016-09-04 17:03:38,728 - DEBUG Sending reached_end_of_stream to AudioListener: {}
2016-09-04 17:03:38,840 - DEBUG Triggering event: state_changed(old_state=playing, new_state=stopped, target_state=None)
2016-09-04 17:03:38,842 - DEBUG Sending state_changed to AudioListener: {‘old_state’: u’playing’, ‘target_state’: None, ‘new_state’: u’stopped’}
2016-09-04 17:03:38,849 - DEBUG Setting GStreamer state to GST_STATE_NULL is OK
2016-09-04 17:03:38,850 - DEBUG Changing state: playing → stopped
2016-09-04 17:03:38,851 - DEBUG Triggering playback state change event
2016-09-04 17:03:38,851 - DEBUG Triggering track playback ended event
2016-09-04 17:03:38,853 - DEBUG Changing state: stopped → playing
2016-09-04 17:03:38,853 - DEBUG Triggering playback state change event
2016-09-04 17:03:38,855 - DEBUG Got message; processing events
2016-09-04 17:03:38,858 - DEBUG Will wait 3.642s for next message
2016-09-04 17:03:38,875 - DEBUG Got message; processing events
2016-09-04 17:03:38,877 - DEBUG System message: 15:03:38.877 I [social_presence.cpp:135] Presence: A track was played
2016-09-04 17:03:38,878 - DEBUG Setting GStreamer state to GST_STATE_READY is OK
2016-09-04 17:03:38,879 - DEBUG Triggering track playback started event
2016-09-04 17:03:38,900 - DEBUG Will wait 1.016s for next message
2016-09-04 17:03:38,907 - DEBUG Got message; processing events
2016-09-04 17:03:38,908 - DEBUG Will wait 0.985s for next message
2016-09-04 17:03:38,950 - DEBUG Setting GStreamer state to GST_STATE_PLAYING is async
2016-09-04 17:03:38,953 - DEBUG playback.on_seek_data(0) called
2016-09-04 17:03:38,954 - DEBUG Skipping seek due to issue #300
2016-09-04 17:03:38,955 - DEBUG playback.on_need_data(0) called
2016-09-04 17:03:38,959 - DEBUG Position query failed
2016-09-04 17:03:38,971 - DEBUG Sending playback_state_changed to CoreListener: {‘old_state’: u’playing’, ‘new_state’: u’stopped’}
2016-09-04 17:03:38,983 - DEBUG Sending track_playback_ended to CoreListener: {‘time_position’: 197625L, ‘tl_track’: TlTrack(tlid=207, track=Track(album=Album(artists=[Artist(name=u’Ramin Djawadi’, uri=‘spotify:artist:1hCkSJcXREhrodeIHQdav8’)], date=2016, name=u’Game of Thrones (Music from the HBO\xae Series - Season 6)‘, uri=‘spotify:album:7bBlW6L9r3ICFkbf2WRDXL’), artists=[Artist(name=u’Ramin Djawadi’, uri=‘spotify:artist:1hCkSJcXREhrodeIHQdav8’)], bitrate=320, date=2016, length=197000, name=u’The Red Woman’, track_no=8, uri=‘spotify:track:71oRf1ea6dkMq5DL1081jZ’))}
2016-09-04 17:03:38,994 - DEBUG Sending playback_state_changed to CoreListener: {‘old_state’: u’stopped’, ‘new_state’: u’playing’}
2016-09-04 17:03:39,001 - DEBUG Sending track_playback_started to CoreListener: {‘tl_track’: TlTrack(tlid=208, track=Track(album=Album(artists=[Artist(name=u’Ramin Djawadi’, uri=‘spotify:artist:1hCkSJcXREhrodeIHQdav8’)], date=2016, name=u’Game of Thrones (Music from the HBO\xae Series - Season 6)‘, uri=‘spotify:album:7bBlW6L9r3ICFkbf2WRDXL’), artists=[Artist(name=u’Ramin Djawadi’, uri=‘spotify:artist:1hCkSJcXREhrodeIHQdav8’)], bitrate=320, date=2016, length=442000, name=u’Hold the Door’, track_no=9, uri=‘spotify:track:3V3CHMcsZwOaJWbBiLo248’))}
2016-09-04 17:03:39,330 - INFO 304 GET /images/icons/play_alt_32x32.png (192.168.0.8) 4.60ms
2016-09-04 17:03:39,359 - INFO 304 GET /images/default_cover.png (192.168.0.8) 3.85ms
2016-09-04 17:03:39,370 - DEBUG Received WebSocket message from 192.168.0.8: u’{“method”:“core.playback.get_time_position”,“jsonrpc”:“2.0”,“id”:169}’
2016-09-04 17:03:39,374 - DEBUG Position query failed
2016-09-04 17:03:39,378 - DEBUG Received WebSocket message from 192.168.0.8: u’{“method”:“core.playback.get_time_position”,“jsonrpc”:“2.0”,“id”:170}’
2016-09-04 17:03:39,381 - DEBUG Position query failed
2016-09-04 17:03:39,566 - DEBUG Request from [::ffff:127.0.0.1]:36010: status
2016-09-04 17:03:39,578 - DEBUG Position query failed
2016-09-04 17:03:39,582 - DEBUG Response to [::ffff:127.0.0.1]:36010:

I hope you can help me solve this issue. In any case thanks for helping!

As with your other query, I used to have problem where the web interface was showing the track playing for 10 seconds - but no sound came out, it was the wifi adapter.
Try running it wired in or try another adapter.

Thanks for your very fast reply, I already use a wired connection so it could not be the wifi adapter.

I used to have a problem where my daughter would log into my spotify account at school and that would log me out at home, could you have similar situation?

I do not think that that could be causing it as I only have spotify on my own devices and I did not open anything. Also it should start working again at the moment I select a new song, which doesn’t happen.