Powernode 1 Spotify connect stability

Hi all,

I've had had absolutely no issues with spotify connect on my powernode 1. However, since the two most recent updates of bluos, spotify has become rather unstable.

Track skipping does not work normally, lags, and even the iOS spotify client shows a different song than the PN1 is playing. After a couple of seconds, sometimes the PN1 picks up the new song. In the firmware release before the current one, the PN1 started rebooting.

I've had a look at the log and I see a lot of errors. These might be related?

If you need more logs or scenario's, do let me know. The last two firmwares kind of took the joy out of spotify connect and I would really like to go back two versions less recent...

Aug 20 18:03:40 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending response: operation canceled
Aug 20 18:03:40 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending response: operation canceled
Aug 20 18:03:40 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending response: operation canceled
Aug 20 18:03:40 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending response: operation canceled
Aug 20 18:03:40 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending response: operation canceled
Aug 20 18:03:40 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:40 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:40 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:40 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:40 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:40 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:40 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:40 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:40 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:40 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:40 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:40 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:47 (none) user.info sovi-discover: Removing address 192.168.179.114/192.168.179.255 wlan0
Aug 20 18:03:47 (none) daemon.info avahi-daemon[2069]: Interface wlan0.IPv4 no longer relevant for mDNS.
Aug 20 18:03:47 (none) daemon.info avahi-daemon[2069]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.179.114.
Aug 20 18:03:47 (none) daemon.info avahi-daemon[2069]: Withdrawing address record for 192.168.179.114 on wlan0.
Aug 20 18:03:48 (none) user.info sovi-spotify: onConnectionNotify: 3
Aug 20 18:03:48 (none) user.info sovi-spotify: onConnectionNotify: 6
Aug 20 18:03:48 (none) user.info sovi-discover: Adding address 192.168.179.114/192.168.179.255 wlan0
Aug 20 18:03:48 (none) daemon.info avahi-daemon[2069]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.179.114.
Aug 20 18:03:48 (none) daemon.info avahi-daemon[2069]: New relevant interface wlan0.IPv4 for mDNS.
Aug 20 18:03:48 (none) daemon.info avahi-daemon[2069]: Registering new address record for 192.168.179.114 on wlan0.IPv4.
Aug 20 18:03:48 (none) user.info sovi-discover: SDDP wlan0: SDDP initializing
Aug 20 18:03:48 (none) user.info sovi-discover: SDDP wlan0: Closing multicast socket 7
Aug 20 18:03:48 (none) user.info sovi-discover: SDDP wlan0: Closing unicast socket 6
Aug 20 18:03:49 (none) user.info ./ms.pl: main::HttpRequest ./ms.pl (960) [1] 127.0.0.1: /Songs?length=1
Aug 20 18:03:51 (none) user.info ./ms.pl: main::HttpRequest ./ms.pl (960) [1] 127.0.0.1: /Songs?length=1
Aug 20 18:03:51 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:127.0.0.1] multicast recv socket is bound to 0.0.0.0:9003
Aug 20 18:03:51 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:127.0.0.1] multicast send socket is bound to 0.0.0.0:58167
Aug 20 18:03:51 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:192.168.179.114] multicast recv socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:192.168.179.114] multicast send socket is bound to 0.0.0.0:42693
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] unicast socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:127.0.0.1] multicast recv socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:127.0.0.1] multicast send socket is bound to 0.0.0.0:52527
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:192.168.179.114] multicast recv socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:192.168.179.114] multicast send socket is bound to 0.0.0.0:38742
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] unicast socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:127.0.0.1] multicast recv socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:127.0.0.1] multicast send socket is bound to 0.0.0.0:33926
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:192.168.179.114] multicast recv socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:192.168.179.114] multicast send socket is bound to 0.0.0.0:37352
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] unicast socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:127.0.0.1] multicast recv socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:127.0.0.1] multicast send socket is bound to 0.0.0.0:38296
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:192.168.179.114] multicast recv socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:192.168.179.114] multicast send socket is bound to 0.0.0.0:38954
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] unicast socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:127.0.0.1] multicast recv socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:127.0.0.1] multicast send socket is bound to 0.0.0.0:44686
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:192.168.179.114] multicast recv socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:192.168.179.114] multicast send socket is bound to 0.0.0.0:37403
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] unicast socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:127.0.0.1] multicast recv socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:127.0.0.1] multicast send socket is bound to 0.0.0.0:47568
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:192.168.179.114] multicast recv socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:192.168.179.114] multicast send socket is bound to 0.0.0.0:58404
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] unicast socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:127.0.0.1] multicast recv socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:127.0.0.1] multicast send socket is bound to 0.0.0.0:43780
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:192.168.179.114] multicast recv socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:192.168.179.114] multicast send socket is bound to 0.0.0.0:48468
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] unicast socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending response: operation canceled
Aug 20 18:03:52 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending response: operation canceled
Aug 20 18:03:52 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending response: operation canceled
Aug 20 18:03:52 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending response: operation canceled
Aug 20 18:03:52 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending response: operation canceled
Aug 20 18:03:52 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:52 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:52 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:52 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:52 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:52 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:52 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:52 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:52 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:52 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:52 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:52 (none) user.err ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] error sending rebroadcast: operation canceled
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:127.0.0.1] multicast recv socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:127.0.0.1] multicast send socket is bound to 0.0.0.0:51157
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:192.168.179.114] multicast recv socket is bound to 0.0.0.0:9003
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:192.168.179.114] multicast send socket is bound to 0.0.0.0:41225
Aug 20 18:03:52 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] unicast socket is bound to 0.0.0.0:9003
Aug 20 18:03:53 (none) user.info sovi-spotify: onConnectionNotify: 4
Aug 20 18:03:53 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:127.0.0.1] multicast recv socket is bound to 0.0.0.0:9003
Aug 20 18:03:53 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:127.0.0.1] multicast send socket is bound to 0.0.0.0:37677
Aug 20 18:03:53 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:192.168.179.114] multicast recv socket is bound to 0.0.0.0:9003
Aug 20 18:03:53 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] [iface:192.168.179.114] multicast send socket is bound to 0.0.0.0:45299
Aug 20 18:03:53 (none) user.info ./cp.pl: main::_logRaat ./cp.pl (4470) [discovery] unicast socket is bound to 0.0.0.0:9003
Aug 20 18:03:54 (none) user.info sovi-spotify: [error] send(pcm): Broken pipe
Aug 20 18:03:54 (none) user.info ./ms.pl: Controller::play Controller.pm (1615) 
Aug 20 18:03:54 (none) user.info sovi-spotify: [error] send(pcm): Broken pipe
Aug 20 18:03:54 (none) user.info dspout: Command(l=1): S
Aug 20 18:03:54 (none) user.info dspout: Command(l=4): I100
Aug 20 18:03:54 (none) user.info ./ms.pl: Controller::_Codec_play Controller.pm (1150) Spotify:spotify_pcm01:pcm/44100/16/2/31
Aug 20 18:03:54 (none) user.info dspout: Command(l=4): I100
Aug 20 18:03:54 (none) user.info ./ms.pl: Controller::streamStarted Controller.pm (2633) streamId=51
Aug 20 18:03:54 (none) user.info dspout: Command(l=5): I5000
Aug 20 18:03:54 (none) user.info ./ms.pl: Sources::SpotifyCodec::setMetadata Sources/SpotifyCodec.pm (81) $VAR1 = {           'inactive' => bless( do{\(my $o = 0)}, 'JSON::XS::Boolean' ),           'ts' => 788234801,           'offsetMs' => 0,           'artist' => 'T
Aug 20 18:03:55 (none) user.info ./ms.pl: Sources::SpotifyCodec::setMetadata Sources/SpotifyCodec.pm (81) $VAR1 = {           'inactive' => bless( do{\(my $o = 0)}, 'JSON::XS::Boolean' ),           'ts' => 788235321,           'offsetMs' => 1004,           'artist' =>
Aug 20 18:04:01 (none) daemon.err udhcpc[2003]: sending discover
Aug 20 18:04:04 (none) daemon.err udhcpc[2003]: sending discover
Aug 20 18:04:07 (none) daemon.err udhcpc[2003]: sending discover
Aug 20 18:04:10 (none) user.info ./ms.pl: main::__ANON__ ./ms.pl (4861) saving volume level: 16
Aug 20 18:04:30 (none) daemon.err udhcpc[2003]: sending discover
Aug 20 18:04:33 (none) daemon.err udhcpc[2003]: sending discover
Aug 20 18:04:36 (none) daemon.err udhcpc[2003]: sending discover
Aug 20 18:04:59 (none) daemon.err udhcpc[2003]: sending discover
Aug 20 18:05:02 (none) daemon.err udhcpc[2003]: sending discover
Aug 20 18:05:05 (none) daemon.err udhcpc[2003]: sending discover
Aug 20 18:05:28 (none) daemon.err udhcpc[2003]: sending discover
Aug 20 18:05:31 (none) daemon.err udhcpc[2003]: sending discover
Aug 20 18:05:34 (none) daemon.err udhcpc[2003]: sending discover
Aug 20 18:05:57 (none) daemon.err udhcpc[2003]: sending discover
Aug 20 18:06:00 (none) daemon.err udhcpc[2003]: sending discover
Aug 20 18:06:03 (none) daemon.err udhcpc[2003]: sending discover
Aug 20 18:06:16 (none) user.info ./ms.pl: main::HttpRequest ./ms.pl (960) [1] 127.0.0.1: /Songs?length=1