PDA

View Full Version : [Announce] Spotty 2.4.x - Spotify Connect for your Squeezebox



mherger
2018-08-27, 00:13
A belated announcement for Spotty 2.4.x:


adding improved support for synced players: expose the sync group rather than individual players
add workaround for Connect on players with large buffers: if the player was able to buffer a full track or more, the could have been a huge gap between what the Spotify app would show as currently playing and what was actually playing.


Please note that the second change is currently optional, as it does improve the situation for some cases, while it seemed to be more sensitive to other timing related hiccups in most of my test cases. If you see your Spotify app controlling a Spotty device a track or more ahead, then give this option a try. Otherwise better leave it alone :-).

This workaround is in response to issues reported by users of eg. the Innuos devices, which run Squeezelite with a very large buffer, keeping full tracks in there.

gwlevans
2018-09-08, 07:56
Hi,

Since version 2.4.4 I get sounds distortion after a few seconds of music. Worked fine on 2.3. Raspberry Pi 3B+ Picore player 4.0, HRT Streamer II USB.

Any ideas?

Thanks,

Gareth

mniemann
2018-09-08, 08:24
I'm trying to use Spotty 2.4.4 on our OSX Server, but after the installation, it fails and returns the following error.

Do I have to grant specific permissions or install a dedicated helper app for this environment?

Thanks for your help in advance!

Best regards
Max


"Beim Ausführen der Spotty Helfer-Anwendung ist ein Fehler aufgetreten. Vermutlich wird diese auf ihrem System nicht unterstützt. Bitte wenden Sie sich an mich, unter Angabe der folgenden Plattform-Informationen:

Betriebssystem: Mac OS X 10.7.4 / x86_64

Ordner für Hilfsprogramme:
/Library/PreferencePanes/Squeezebox.prefPane/Contents/server/Bin/darwin-x86_64
/Library/PreferencePanes/Squeezebox.prefPane/Contents/server/Bin/darwin
/Library/PreferencePanes/Squeezebox.prefPane/Contents/server/Bin
/Users/homeserver/Library/iTunes/Scripts/iTunes-LAME.app/Contents/Resources/
/usr/bin
/bin
/usr/sbin
/sbin
/usr/local/bin
/usr/libexec
/opt/local/bin
/Users/homeserver/Library/Caches/Squeezebox/InstalledPlugins/Plugins/Spotty/Bin/darwin-thread-multi-2level
/Users/homeserver/Library/Caches/Squeezebox/InstalledPlugins/Plugins/Spotty/Bin"

wbree
2018-09-08, 10:51
I noticed that after install Spotty 2.4.4 recently I have more than 1000 lines with this message:

[18-09-07 20:44:16.6283] Slim::Utils::Misc::msg (1252) Warning: [20:44:16.6278] DBIx::Class::ResultSet::single(): Query returned more than one row. SQL that returns multiple rows is DEPRECATED for ->find and ->single at /Slim/Schema.pm line 2284
[18-09-07 20:44:16.6427] Slim::Utils::Misc::msg (1252) Warning: [20:44:16.6423] DBIx::Class::ResultSet::single(): Query returned more than one row. SQL that returns multiple rows is DEPRECATED for ->find and ->single at /Slim/Schema.pm line 2284
[18-09-07 20:44:16.6570] Slim::Utils::Misc::msg (1252) Warning: [20:44:16.6566] DBIx::Class::ResultSet::single(): Query returned more than one row. SQL that returns multiple rows is DEPRECATED for ->find and ->single at /Slim/Schema.pm line 2284
[18-09-07 20:44:16.6707] Slim::Utils::Misc::msg (1252) Warning: [20:44:16.6703] DBIx::Class::ResultSet::single(): Query returned more than one row. SQL that returns multiple rows is DEPRECATED for ->find and ->single at /Slim/Schema.pm line 2284
[18-09-07 20:44:16.6849] Slim::Utils::Misc::msg (1252) Warning: [20:44:16.6845] DBIx::Class::ResultSet::single(): Query returned more than one row. SQL that returns multiple rows is DEPRECATED for ->find and ->single at /Slim/Schema.pm line 2284
[18-09-07 20:44:16.6962] Slim::Utils::Misc::msg (1252) Warning: [20:44:16.6958] DBIx::Class::ResultSet::single(): Query returned more than one row. SQL that returns multiple rows is DEPRECATED for ->find and ->single at /Slim/Schema.pm line 2284
[18-09-07 20:44:16.7102] Slim::Utils::Misc::msg (1252) Warning: [20:44:16.7097] DBIx::Class::ResultSet::single(): Query returned more than one row. SQL that returns multiple rows is DEPRECATED for ->find and ->single at /Slim/Schema.pm line 2284
[18-09-07 20:44:16.7245] Slim::Utils::Misc::msg (1252) Warning: [20:44:16.7240] DBIx::Class::ResultSet::single(): Query returned more than one row. SQL that returns multiple rows is DEPRECATED for ->find and ->single at /Slim/Schema.pm line 2284


I'm not sure If these warnings has something to do with the upgrade. It can be a coincidence. I also know that it is a warning, so no error. And everything seems to be ok.
But I find it a little bit irritating that LMS generated these lines.
Can I do something to prevent this or at least minimize it.

Wilco

slartibartfast
2018-09-08, 13:45
I noticed that after install Spotty 2.4.4 recently I have more than 1000 lines with this message:


I'm not sure If these warnings has something to do with the upgrade. It can be a coincidence. I also know that it is a warning, so no error. And everything seems to be ok.
But I find it a little bit irritating that LMS generated these lines.
Can I do something to prevent this or at least minimize it.

WilcoWhen I had the same issue a clear and rescan fixed it.
https://r.tapatalk.com/shareLink?url=https%3A%2F%2Fforums%2Eslimdevices%2 Ecom%2Fshowthread%2Ephp%3Ft%3D109326&share_tid=109326&share_fid=813&share_type=t


Sent from my SM-G900F using Tapatalk

mherger
2018-09-08, 22:37
> I'm trying to use Spotty 2.4.4 on our OSX Server, but after the
> installation, it fails and returns the following error.
>> Betriebssystem: Mac OS X 10.7.4 / x86_64

I think 10.7 is too old. Could you please run the binaries from
/Users/homeserver/Library/Caches/Squeezebox/InstalledPlugins/Plugins/Spotty/Bin/darwin-thread-multi-2level
in a terminal window and send me the output?

--

Michael

mherger
2018-09-08, 22:39
> I noticed that after install Spotty 2.4.4 recently I have more than 1000
> lines with this message:
>> [18-09-07 20:44:16.6283] Slim::Utils::Misc::msg (1252) Warning:
>> [20:44:16.6278] DBIx::Class::ResultSet::single(): Query returned more
>> than one row. SQL that returns multiple rows is DEPRECATED for ->find
>> and ->single at /Slim/Schema.pm line 2284

This has nothing to do with Spotty. The most likely cause I know is
tracks with an artist of "Various Artists" (or whatever the name set in
Settings/My Music). You'd have to tag the files with the tracks' real
artists, and set the Compilation flag on them.

Please continue the discussion in a related or new thread should that
not be it.

--

Michael

mniemann
2018-09-09, 04:13
Hey Michael,

thank you very much for your fast reply!


>Could you please run the binaries from
/Users/homeserver/Library/Caches/Squeezebox/InstalledPlugins/Plugins/Spotty/Bin/darwin-thread-multi-2level
in a terminal window and send me the output?

It says:
Segmentation fault: 11

Best
Max

mherger
2018-09-09, 06:40
> It says: > Segmentation fault: 11

Unfortunately I don't remember what the oldest macOS would be to run
Spotty on. But I'm pretty sure 10.7 isn't recent enough. And I don't
have anything older than 10.11 to test with...

--

Michael

gwlevans
2018-09-09, 07:47
I Just rebuilt on a PI2B with a HifiBerry DAC+ and I am still getting the distortion on Spotty, BBC IPlayer, etc. play fine. I am a bit stumped.


Hi,

Since version 2.4.4 I get sounds distortion after a few seconds of music. Worked fine on 2.3. Raspberry Pi 3B+ Picore player 4.0, HRT Streamer II USB.

Any ideas?

Thanks,

Gareth

PlusMinus
2018-09-29, 05:49
Hello Michael

My spotify username contains some special characters and when I enter them, the plugins fails to work with the following erro message:


[18-09-29 11:36:14.8921] Slim::Networking::IO::Select::__ANON__ (131) Error: Select task failed calling Slim::Web::HTTP::processHTTP: Wide character in subroutine entry at /config/cache/InstalledPlugins/Plugins/
Spotty/Plugin.pm line 357.
; fh=Slim::Web::HTTP::ClientConn=GLOB(0x9c20488)
[18-09-29 11:36:16.3251] Slim::Utils::PluginManager::shutdownPlugins (418) Warning: error running Plugins::Spotty::Plugin->shutdownPlugin: Wide character in subroutine entry at /config/cache/InstalledPlugins/Plu
gins/Spotty/Plugin.pm line 357.


$newId = substr( md5_hex($credentials->{username}), 0, 8 );

So the error appears to be in this line. I'm not a perl programmer, but maybe this can help to fix the problem: stackoverflow.com/questions/32285925/wide-character-in-subroutine-entry-utf-8-encoded-cyrillic-words-as-sequence


Cheers,

Matthias

mherger
2018-09-29, 07:14
My spotify username contains some special characters and when I enter them, the plugins fails to work with the following erro message:


$newId = substr( md5_hex($credentials->{username}), 0, 8 );

Thanks! Yes, md5_hex() has a problem with Unicode. Would the authentication using the Spotify app on your mobile or desktop work?

I'll look into this. Thanks for the report!

PlusMinus
2018-09-29, 07:46
Thanks! Yes, md5_hex() has a problem with Unicode. Would the authentication using the Spotify app on your mobile or desktop work?

No, didn't work. I had to restart lms to enter the plugin’s setting page again. I’m using the plugin right now with my girlfriends account and it works like a charm. Thanks for your work.

mherger
2018-09-29, 22:28
Did you get the latest update 2.4.8? Could you please try again?
--

Michael

PlusMinus
2018-09-30, 01:28
I did get the latest update and I was able to add my account but I wasn’t able to authorize it. I hope the next error is still within your reach


[18-09-30 07:58:07.4413] Slim::Web::JSONRPC::requestMethod (456) Request failed with error: Bad dispatch!
[18-09-30 07:58:13.4290] Slim::Control::Request::execute (1888) Error: While trying to run function coderef [Slim::Control::Queries::statusQuery]: [Wide character in subroutine entry at /usr/share/perl5/Slim/Utils/DbCache.pm line 126.




121 sub _key {
122 my ( $key ) = @_;
123
124 # Get a 60-bit unsigned int from MD5 (SQLite uses 64-bit signed ints for the key)
125 # Have to concat 2 values here so it works on a 32-bit machine
126 my $md5 = Digest::MD5::md5_hex($key);
127 return hex( substr($md5, 0, 8) ) . hex( substr($md5, 8, 7) );
128 }

mherger
2018-09-30, 06:13
> I did get the latest update and I was able to add my account but I
> wasnÂ’t able to authorize it. I hope the next error is still within your
> reach

I probably should indeed "fix" this for good in LMS. But for the time
being I'll try to find a workaround for Spotty. I'm sorry for the hassle.

--

Michael

PlusMinus
2018-09-30, 08:38
This is the error I get now:


thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: MercuryError', /checkout/src/libcore/result.rs:906:4
note: Run with `RUST_BACKTRACE=1` for a backtrace.

or


thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: Error { repr: Os { code: 13, message: "Permission denied" } }', /checkout/src/libcore/result.rs:906:4
note: Run with `RUST_BACKTRACE=1` for a backtrace.

ashmore
2018-09-30, 14:28
Hi

With advanced apologies if I'm posting in the wrong place.

Here's the issue: when using spotify on my android to play music on my boom or picore, tracks end prematurely and the playlist stops, or end prematurely - typically in the last few seconds of the track - and move onto the next track.
Spotify works brilliantly via the LMS

A test on Spotify (2.3.9?) shows the helper is not connecting, but I notice I have a lot of spotify related programmes running. Perhaps not all are needed.

This is what's installed
protocol handler 1.1.1
Spotty2.4.4
spotify2.3.9

Here is a log file recorded while the issue presented. The pause event coincides with the premature track ending.

[18-09-30 22:26:34.8054] Plugins::Spotty::Connect::__ANON__ (198) Got a new track to be played next: spotify:track:1bgAD4PEqcoLK9DS5jVDwi
[18-09-30 22:26:34.8067] Plugins::Spotty::Connect::Context::getPlay (146) Has spotify://track:1bgAD4PEqcoLK9DS5jVDwi been played? no
[18-09-30 22:26:34.8108] Plugins::Spotty::Plugin::purgeAudioCacheAfterXTrac ks (441) Played 3 song(s) since last audio cache purge.
[18-09-30 22:26:44.9549] Slim::Plugin::AudioScrobbler::Plugin::_handshakeOK (349) Invalid Last.fm username or password.
[18-09-30 22:26:48.0789] Plugins::Spotty::Connect::_connectEvent (331) Got called from spotty helper: stop
[18-09-30 22:26:48.0817] Plugins::Spotty::API::__ANON__ (1398) Trying to read from cache for me
[18-09-30 22:26:48.0826] Plugins::Spotty::API::__ANON__ (1401) Returning cached data for me
[18-09-30 22:26:48.0843] Plugins::Spotty::API::__ANON__ (1407) API call: me/player
[18-09-30 22:26:48.1709] Plugins::Spotty::Connect::__ANON__ (413) Spotify told us to pause: 00:04:20:1e:38:ec
[18-09-30 22:26:48.1807] Plugins::Spotty::Connect::_onPause (292) Got a pause event - tell Spotify Connect controller to pause, too
[18-09-30 22:26:48.1833] Plugins::Spotty::API::__ANON__ (1398) Trying to read from cache for me
[18-09-30 22:26:48.1842] Plugins::Spotty::API::__ANON__ (1401) Returning cached data for me

slartibartfast
2018-09-30, 14:50
Hi

With advanced apologies if I'm posting in the wrong place.

Here's the issue: when using spotify on my android to play music on my boom or picore, tracks end prematurely and the playlist stops, or end prematurely - typically in the last few seconds of the track - and move onto the next track.
Spotify works brilliantly via the LMS

A test on Spotify (2.3.9?) shows the helper is not connecting, but I notice I have a lot of spotify related programmes running. Perhaps not all are needed.

This is what's installed
protocol handler 1.1.1
Spotty2.4.4
spotify2.3.9

Here is a log file recorded while the issue presented. The pause event coincides with the premature track ending.

[18-09-30 22:26:34.8054] Plugins::Spotty::Connect::__ANON__ (198) Got a new track to be played next: spotify:track:1bgAD4PEqcoLK9DS5jVDwi
[18-09-30 22:26:34.8067] Plugins::Spotty::Connect::Context::getPlay (146) Has spotify://track:1bgAD4PEqcoLK9DS5jVDwi been played? no
[18-09-30 22:26:34.8108] Plugins::Spotty::Plugin::purgeAudioCacheAfterXTrac ks (441) Played 3 song(s) since last audio cache purge.
[18-09-30 22:26:44.9549] Slim::Plugin::AudioScrobbler::Plugin::_handshakeOK (349) Invalid Last.fm username or password.
[18-09-30 22:26:48.0789] Plugins::Spotty::Connect::_connectEvent (331) Got called from spotty helper: stop
[18-09-30 22:26:48.0817] Plugins::Spotty::API::__ANON__ (1398) Trying to read from cache for me
[18-09-30 22:26:48.0826] Plugins::Spotty::API::__ANON__ (1401) Returning cached data for me
[18-09-30 22:26:48.0843] Plugins::Spotty::API::__ANON__ (1407) API call: me/player
[18-09-30 22:26:48.1709] Plugins::Spotty::Connect::__ANON__ (413) Spotify told us to pause: 00:04:20:1e:38:ec
[18-09-30 22:26:48.1807] Plugins::Spotty::Connect::_onPause (292) Got a pause event - tell Spotify Connect controller to pause, too
[18-09-30 22:26:48.1833] Plugins::Spotty::API::__ANON__ (1398) Trying to read from cache for me
[18-09-30 22:26:48.1842] Plugins::Spotty::API::__ANON__ (1401) Returning cached data for meSpotify 2.3.9? How old is that?

Sent from my SM-G900F using Tapatalk

ashmore
2018-09-30, 14:56
Old! It's the Triode version. I've switched it off too see if if was affecting the behaviour I described, but the premature track endings persist.

slartibartfast
2018-09-30, 14:57
Old! It's the Triode version. I've switched it off too see if if was affecting the behaviour I described, but the premature track endings persist.The triode version? Are you even using Spotty? You don't need the protocol handler or Triodes version to use Spotty. Both should probably be uninstalled. Do you have the latest Spotify on your Android?

Sent from my SM-G900F using Tapatalk

ashmore
2018-09-30, 15:09
Yeah I've got Spotty running. It's works well through LMS, and yes I'm using the latest version on android 8.4.72

slartibartfast
2018-09-30, 15:13
Yeah I've got Spotty running. It's works well through LMS, and yes I'm using the latest version on android 8.4.72Which version of LMS and what is it running on?

Sent from my SM-G900F using Tapatalk

ashmore
2018-09-30, 15:28
Logitech Media Server Version: 7.7.6 - 1452060463 @ Thu Jan 21 02:17:04 UTC 2016

it's on a synology NAS and is the most recent version in their library. I don't know how I would update it manually.

slartibartfast
2018-09-30, 15:35
Logitech Media Server Version: 7.7.6 - 1452060463 @ Thu Jan 21 02:17:04 UTC 2016

it's on a synology NAS and is the most recent version in their library. I don't know how I would update it manually.Hopefully Michael will see your post, my only experience is with a Raspberry Pi. Has this always happened since you installed Spotty?

Sent from my SM-G900F using Tapatalk

ashmore
2018-09-30, 16:04
Yes. I only installed spotty recently, and it's consistent. Thanks for trying.

mherger
2018-10-02, 13:05
>> thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value:
>> MercuryError', /checkout/src/libcore/result.rs:906:4

Hmm... did you build this yourself? What version of the spotty helper is
this?

>> thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value:
>> Error { repr: Os { code: 13, message: "Permission denied" } }',

Sounds like a permissions issue. I might have asked before: what OS are
you running your LMS on? How did you install?

--

Michael

GrosMatou
2018-10-02, 22:38
Hello,

I recently installed the spotty plugin (v2.4.9 - LMS 7.9.1-1504317335 on a Synology NAS), and I want to start by congratulating you for the work done. A big step forward compared to my previous tests of spotify plugins (I went to deezer for years).
However, I encounter a problem with spotty, with the function connect (but maybe it's a limitation by spotify). After starting the server, everything is going very well, I can use connect from my PC, my phone ... but after a long time without use (the next day for example), can not find my squeezebox in the available devices. I then have to restart the LMS server and everything works again. I also had a disconnection problem 2 or 3 times during a title change, which forced me to restart LMS to use connect again.
Any ideas?
(I feel that the box "Don't announce Squeezebox players running in Spotify Connect mode in your network. Check this option if you don't want your Spotify Connect enabled Squeezebox player to show up in all Spotify apps in your network." ticks automatically even if I unchecked it, after a while. Maybe it's related?)

Thank you in advance !

Matthias

mherger
2018-10-03, 10:19
> However, I encounter a problem with spotty, with the function connect
> (but maybe it's a limitation by spotify). After starting the server,
> everything is going very well, I can use connect from my PC, my phone
> ... but after a long time without use (the next day for example), can
> not find my squeezebox in the available devices. I then have to restart
> the LMS server and everything works again. I also had a disconnection
> problem 2 or 3 times during a title change, which forced me to restart
> LMS to use connect again.

I've seen similar reports again. And just today I found this posting on
the librespot project (on which spotty is based):

https://github.com/librespot-org/librespot/issues/247#issuecomment-426593668

Seems to be an issue not limited to you.

--

Michael

slartibartfast
2018-10-03, 10:32
Michael, did you miss this post?
https://forums.slimdevices.com/showthread.php?p=922001

Sent from my SM-G900F using Tapatalk

jsmathers
2018-10-03, 11:16
I've been using Spotty for a long time and loving it. Thanks again Michael for all of your work. Here are a couple things I have noticed, which are likely known limitations, but just wanted to list them here to see if there is a plan to fix them at some point. These issues are causing me pain when trying to add Google Assistant voice commands for controlling LMS/Spotify.

1. When issuing Pause from the LMS web interface the track correctly shows as Paused in Spotify App. However, when issuing Play from LMS web interface (rather than from the Spotify app), the Spotify App status does not update as playing. Also, once the song is done playing, LMS will repeat playing the current song even if there are other songs in the Spotify playlist.

2. When issuing Next track from the LMS web interface (rather than from the Spotify app), LMS just repeats playing the current track even if there are other songs in the Spotify playlist.

EDIT: I am using Spotty 2.4.9. See below for my other setup details.
Logitech Media Server Version: 7.9.1 - 1504317335 @ Mon Sep 4 22:13:00 UTC 2017
Hostname: DS414
OS: Synology DiskStation - EN - utf8
Platform: armle-linux
Perl Version: 5.24.0 - armle-linux
Audio::Scan: 0.95
Database Version: DBD::SQLite 1.34_01 (sqlite 3.7.7.1)
Total Players Recognized: 7

mherger
2018-10-03, 12:31
(I feel that the box "Don't announce Squeezebox players running in Spotify Connect mode in your network. Check this option if you don't want your Spotify Connect enabled Squeezebox player to show up in all Spotify apps in your network." ticks automatically even if I unchecked it, after a while. Maybe it's related?)

That pref would be checked if the spotty helper repeatedly crashed. In that case it would only be visible to apps configured to use the same credentials as Spotty. Un-checking wouldn't help, but just cause confusion again, as it would make Spotty visible for a while, then crash again and disappear.

mherger
2018-10-03, 12:34
> 1. When issuing Pause from the LMS web interface the track correctly
> shows as Paused in Spotify App. However, when issuing Play from LMS web
> interface (rather than from the Spotify app), the Spotify App status
> does not update as playing. Also, once the song is done playing, LMS
> will repeat playing the current song even if there are other songs in
> the Spotify playlist.
>
> 2. When issuing Next track from the LMS web interface (rather than from
> the Spotify app), LMS just repeats playing the current track even if
> there are other songs in the Spotify playlist.

My best recommendation would be: use either LMS or Spotify to control
the Squeezebox. Using a mix is difficult at best... I can certainly try
to improve the behaviour. But it will always remain fragile, as both LMS
and Spotify try to take control over the playback.

--

Michael

mherger
2018-10-03, 12:34
> Michael, did you miss this post?
> https://forums.slimdevices.com/showthread.php?p=922001

I did, and I thought I even responded to it...

--

Michael

mherger
2018-10-03, 12:35
Logitech Media Server Version: 7.7.6 - 1452060463 @ Thu Jan 21 02:17:04 UTC 2016

it's on a synology NAS and is the most recent version in their library. I don't know how I would update it manually.

There's a thread in these forums about how to update LMS to 7.9.2 nightlies. It should be as easy as installing any package.

ElFishi
2018-10-03, 22:35
spotty 2.4.9
the problem I reported on earlier versions (https://forums.slimdevices.com/showthread.php?108898-Announce-Spotty-2-3-0-Spotify-Connect-for-your-Squeezebox&p=921818&viewfull=1#post921818) is still there for me.
In the morning I can't see SB players to connect to in the Spotify app although there a three instances of "spotty-hf -c ..." running and the log says every minute

[18-10-04 07:29:17.6062] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (99) Checking Spotty Connect helper daemons...

When I wake one player from standby I get

[18-10-04 07:30:17.6106] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (99) Checking Spotty Connect helper daemons...
[18-10-04 07:30:17.6123] Plugins::Spotty::Connect::DaemonManager::startHelp er (151) Need to create Connect daemon for 00:04:20:12:xx:xx
[18-10-04 07:30:17.6146] Plugins::Spotty::Connect::Daemon::start (66) Starting Spotty Connect daemon:
/var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/Spotty/Bin/arm-linux/spotty-hf -c /var/lib/squeezeboxserver/cache/spotty/a7912f50 -n Salonbox, Cabinetbox & Goldfinger --disable-audio-cache --bitrate 96 --player-mac 00:04:20:12:xx:xx --lms 192.168.0.107:9000 --disable-discovery
[18-10-04 07:30:17.6379] Plugins::Spotty::Connect::DaemonManager::stopHelpe r (170) Shutting down Connect daemon for b8:27:eb:d5:zz:zz (pid: 12672)
[18-10-04 07:30:17.6403] Plugins::Spotty::Connect::Daemon::stop (120) Quitting Spotty Connect daemon for b8:27:eb:d5:zz:zz
[18-10-04 07:30:18.1159] Plugins::Spotty::Connect::_connectEvent (331) Got called from spotty helper: volume
[18-10-04 07:30:18.1166] Plugins::Spotty::Connect::_connectEvent (338) Ignoring initial volume reset right after daemon start
[18-10-04 07:31:17.6483] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (99) Checking Spotty Connect helper daemons...


and I can connect again.

mherger
2018-10-03, 23:25
> [18-10-04 07:29:17.6062] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (99) Checking Spotty Connect helper daemons...

Could you please send me the full server.log file?

--

Michael

GrosMatou
2018-10-04, 00:20
I've seen similar reports again. And just today I found this posting on
the librespot project (on which spotty is based):

https://github.com/librespot-org/librespot/issues/247#issuecomment-426593668

Seems to be an issue not limited to you.

--

Michael

Thanks for your answer.
I read this posting and others... and can't find any solution :(

Can I send you a log for helping ?

mherger
2018-10-04, 03:57
> I read this posting and others... and can't find any solution :(

I'm not saying there is a solution. I'm only saying that there seems to
be a problem with librespot. (Un-)fortunately I'm not seeing this
behaviour myself, and most other Spotty users probably don't experience
it either. Therefore this is difficult to find a fix for.

--

Michael

ElFishi
2018-10-04, 04:43
> [18-10-04 07:29:17.6062] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (99) Checking Spotty Connect helper daemons...

Could you please send me the full server.log file?

--

Michael

can I send it somehow privately?

mherger
2018-10-04, 06:08
> can I send it somehow privately?

https://www.dropbox.com/request/T3RctyzGgNg0oFDubq6a

--

Michael

ElFishi
2018-10-04, 08:37
> can I send it somehow privately?

https://www.dropbox.com/request/T3RctyzGgNg0oFDubq6a

--

Michael
erledigt

mherger
2018-10-04, 08:50
erledigt

What I'm seeing is that around 7:30 the helper got restarted for a group of three synced players. Did you trigger this restart or did this happen automatically? Did you have to re-sync them in the morning?

24 minutes later I see that the helper is restarted, this time with a different sync master. What did trigger this? Did you re-sync the players then or something?

Would you see the same disappearing of players if they were not synced?

And could you please upload a really full server.log? The copy you sent doesn't even cover 24h, which means it likely doesn't cover from when you stopped using Spotty, to the morning, when you picked it up again.

That's a lot of questions, please try to answer them all.

ElFishi
2018-10-04, 09:53
I'll try my level best:


What I'm seeing is that around 7:30 the helper got restarted for a group of three synced players. Did you trigger this restart or did this happen automatically? Did you have to re-sync them in the morning?
I woke up one player from stand by, after that the helper got restarted. before that there was just the minute by minute Checking messages.



24 minutes later I see that the helper is restarted, this time with a different sync master. What did trigger this? Did you re-sync the players then or something?

I didn't trigger anything but something tripped: I use Power Switch II to switch the mains power of my amp and preamp with the player called SalonBox. By that time the amps went off, but the SBs kept playing. I wasn't in the room but Goldfinger played on so I didn't notice at first. The players ran the same song over and over and were disconnected from the Spotify app. I went to the app, connected to my three players again, this is when the helper seems to have restarted.



Would you see the same disappearing of players if they were not synced?

will try this night.



And could you please upload a really full server.log? The copy you sent doesn't even cover 24h, which means it likely doesn't cover from when you stopped using Spotty, to the morning, when you picked it up again.

I dropped you an archive that also includes server.log.1.gz. I didn't clip anything, it apparently rolled over.



That's a lot of questions, please try to answer them all.
Thanks for looking into this. Happy to answer more questions or these ones better, just holler.

ElFishi
2018-10-04, 23:11
Would you see the same disappearing of players if they were not synced?


Yes. And more:
All three players unsynced, I have nine instances of "spotty-hf -c ...", nothing to connect to in Spotify App.
Woke up one SB, started playing immediately, but still nothing under "Connect to a Device" in Spotify.
Paused player, no change.
Started other player, started playing the last song played yesterday. Still no device seen in Spotify.
When music plays I see three more instances of "spotty-hf -n ...."
Unticked and re-ticked one player in LMS/Spotty/Spotify connect, and got that player shown to connect to in app.
Other players still not there.
Connected to that player started a playlist in Spotify: no reaction, no music played, progress bar in app not moving.
Second attempt to start a song gets 1 second of music and then the player trips [07:43]: amp goes off (Power Switch II) and player shows boot screen.
When player was back I could continue to play from playlist.
Went back and unticked/ticked the other two players [07:55]. One showed in app subsequently, the other didn't.
[07:58] music stops by itself. No device connected in app. Connected to one player [08:01], resumed playlist.


Dropped you the server.log

mherger
2018-10-05, 02:23
>> Would you see the same disappearing of players if they were not synced?
>
> Yes. And more:
> All three players unsynced, I have nine instances of "spotty-hf -c ...",
> nothing to connect to in Spotify App.

Can you get the full command line? That's not enough to make good sense.

Do you have more than the three usually synced players? You have _nine_
of them?

> Connected to that player started a playlist in Spotify: no reaction, no
> music played, progress bar in app not moving.
> Second attempt to start a song gets 1 second of music and then the
> player trips [07:43]: amp goes off (Power Switch II) and player shows
> boot screen.

What kind of player is this? Are you saying it spontaneously rebooted?!?

Two observations form your log files:

- the one which covers a full day shows a server restart around
midnight. Is this something you did on purpose, or something that
happens automatically?

- you seem to be using a custom client_id. Is this correct? Did you
modify it in the log file?

- right after the restart I don't see any message for the newly started
daemons. Is this due to logging not being enabled yet? Is logging not
enabled when the server starts? Please make sure it does: check the
"keep settings on restart" box on the logging page.

And always send me a full day worth of log files...
--

Michael

ElFishi
2018-10-05, 07:17
>> Would you see the same disappearing of players if they were not synced?
>
> Yes. And more:
> All three players unsynced, I have nine instances of "spotty-hf -c ...",
> nothing to connect to in Spotify App.

Can you get the full command line? That's not enough to make good sense.

Do you have more than the three usually synced players? You have _nine_
of them?

Sorry, my bad. I have all threads displayed in htop, when I press "H" they collapse and only three processes show. One for each player

pi@Zorin:~ $ ps -Lfu squeezeboxserver
UID PID PPID LWP C NLWP STIME TTY TIME CMD
squeeze+ 17689 28064 17689 0 3 Okt04 ? 00:00:00 /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/Spotty/Bin/arm-linux/spotty-hf -c /var/lib/squeezeboxserver/cache/spotty/a7912f50 -n Cabinetbox --disable-audio-cache --bitrate 96 --player-mac 00:04:20:12:82:40 --lms 192.168.0.107:9000 --disable-discovery
squeeze+ 17689 28064 17696 0 3 Okt04 ? 00:00:00 /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/Spotty/Bin/arm-linux/spotty-hf -c /var/lib/squeezeboxserver/cache/spotty/a7912f50 -n Cabinetbox --disable-audio-cache --bitrate 96 --player-mac 00:04:20:12:82:40 --lms 192.168.0.107:9000 --disable-discovery
squeeze+ 17689 28064 17711 0 3 Okt04 ? 00:00:00 /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/Spotty/Bin/arm-linux/spotty-hf -c /var/lib/squeezeboxserver/cache/spotty/a7912f50 -n Cabinetbox --disable-audio-cache --bitrate 96 --player-mac 00:04:20:12:82:40 --lms 192.168.0.107:9000 --disable-discovery
squeeze+ 18910 28064 18910 0 3 12:46 ? 00:00:00 /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/Spotty/Bin/arm-linux/spotty-hf -c /var/lib/squeezeboxserver/cache/spotty/a7912f50 -n Salonbox --disable-audio-cache --bitrate 96 --player-mac 00:04:20:12:7c:83 --lms 192.168.0.107:9000 --disable-discovery
squeeze+ 18910 28064 18911 0 3 12:46 ? 00:00:00 /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/Spotty/Bin/arm-linux/spotty-hf -c /var/lib/squeezeboxserver/cache/spotty/a7912f50 -n Salonbox --disable-audio-cache --bitrate 96 --player-mac 00:04:20:12:7c:83 --lms 192.168.0.107:9000 --disable-discovery
squeeze+ 18910 28064 18916 0 3 12:46 ? 00:00:00 /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/Spotty/Bin/arm-linux/spotty-hf -c /var/lib/squeezeboxserver/cache/spotty/a7912f50 -n Salonbox --disable-audio-cache --bitrate 96 --player-mac 00:04:20:12:7c:83 --lms 192.168.0.107:9000 --disable-discovery
squeeze+ 20682 28064 20682 0 3 13:15 ? 00:00:00 /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/Spotty/Bin/arm-linux/spotty-hf -c /var/lib/squeezeboxserver/cache/spotty/a7912f50 -n Goldfinger --disable-audio-cache --bitrate 96 --player-mac b8:27:eb:d5:60:af --lms 192.168.0.107:9000 --disable-discovery
squeeze+ 20682 28064 20683 0 3 13:15 ? 00:00:00 /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/Spotty/Bin/arm-linux/spotty-hf -c /var/lib/squeezeboxserver/cache/spotty/a7912f50 -n Goldfinger --disable-audio-cache --bitrate 96 --player-mac b8:27:eb:d5:60:af --lms 192.168.0.107:9000 --disable-discovery
squeeze+ 20682 28064 20688 0 3 13:15 ? 00:00:00 /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/Spotty/Bin/arm-linux/spotty-hf -c /var/lib/squeezeboxserver/cache/spotty/a7912f50 -n Goldfinger --disable-audio-cache --bitrate 96 --player-mac b8:27:eb:d5:60:af --lms 192.168.0.107:9000 --disable-discovery
squeeze+ 28059 1 28059 0 1 Sep23 ? 00:00:00 /bin/bash /usr/sbin/squeezeboxserver_safe /usr/sbin/squeezeboxserver --prefsdir /var/lib/squeezeboxserver/prefs --logdir /var/log/squeezeboxserver/ --cachedir /var/lib/squeezeboxserver/cache --charset=utf8
squeeze+ 28064 28059 28064 3 1 Sep23 ? 10:30:03 /usr/bin/perl /usr/sbin/squeezeboxserver /usr/sbin/squeezeboxserver /usr/sbin/squeezeboxserver --prefsdir /var/lib/squeezeboxserver/prefs --logdir /var/log/squeezeboxserver/ --cachedir /var/lib/squeezeboxserver/cache --charset=utf8
pi@Zorin:~ $





> Connected to that player started a playlist in Spotify: no reaction, no
> music played, progress bar in app not moving.
> Second attempt to start a song gets 1 second of music and then the
> player trips [07:43]: amp goes off (Power Switch II) and player shows
> boot screen.

What kind of player is this? Are you saying it spontaneously rebooted?!?

SB3. Yes.


Two observations form your log files:

- the one which covers a full day shows a server restart around
midnight. Is this something you did on purpose, or something that
happens automatically?

I am not aware I did anything at that time. I can't see anything in syslog at that time either. I have no clue why this happens. Can I check for anything?


- you seem to be using a custom client_id. Is this correct? Did you
modify it in the log file?

the logfile I dropped in your dropbox is unmodified. What is a custom client_id?


- right after the restart I don't see any message for the newly started
daemons. Is this due to logging not being enabled yet? Is logging not
enabled when the server starts? Please make sure it does: check the
"keep settings on restart" box on the logging page.

The logging continued after the restart of the player, I didn't have to do anything. Even though the "keep settings" was not ticked.



And always send me a full day worth of log files...
--

Michael
I dropped you the latest vintage of log files. I noticed two restart entries over the day today when I was out.
In the end you see the result of me unticking one player (Cabinetbox), and re-ticking it again, b/c it didn't show in Spotify to connect to. I see one spotty-hf process going away and then coming back. But I don't see Cabinetbox show up in Spotify Connect.
I then restarted LMS from the commandline. This gave me all three players to connect to.

gunnar
2018-10-05, 15:42
Hi!
I replaced the old LMS 7.7.x on my QNAP NAS with QLMS 7.9.2 today, and also installed Spotty. Installation went smoothly, and Spotty shows up as a service in both the server and the player. Did only try one player, which is a SB3 classic. But it wont play from Spotify, "Problem opening file", or something similar, translated from Norwegian. I can choose the same player through the direct function from the Spotify app on my iPhone, but the same happens, it won`t play. I can search, and the artist/album/tracks/coverart is found. I can playjust fine from my local collection on the NAS. I have 5 players, and I`m very happy that you have developed this plugin. I used the Triode plugin until just a few days ago, and it still worked, except no Spotify search.

mherger
2018-10-05, 22:43
> also installed Spotty. Installation went smoothly, and Spotty shows up
> as a service in both the server and the player. Did only try one player,
> which is a SB3 classic. But it wont play from Spotify, "Problem opening
> file", or something similar, translated from Norwegian. I can choose

Please check Settings/Advanced/File Types: there's a Spotty section. If
transcoding to FLAC is enabled, try to disable it. Give it another try.

Go to Settings/Advanced/Logging: set logging for plugin.spotty=INFO. Try
again, then send me your server.log.zip file
(https://www.dropbox.com/request/T3RctyzGgNg0oFDubq6a)

--

Michael

mherger
2018-10-05, 23:04
> pi@Zorin:~ $ ps -Lfu squeezeboxserver

ah, the -L modifier would show every thread of a process, which triples
the number of spotty "processes".

> spotty-hf -c /var/lib/squeezeboxserver/cache/spotty/a7912f50 -n Cabinetbox --disable-audio-cache --bitrate 96 --player-mac 00:04:20:12:82:40 --lms 192.168.0.107:9000 --disable-discovery

A few explanations: --bitrate 96 is for the Connect daemon only. It
doesn't stream, but still has to download the data. Playback would use
whatever you set it to (most likely 320kbps).

--disable-discover would indicate that either the daemon had crashed a
lot before, or that you (accidentally) disabled it in the settings.

Which leads me to a question I've asked before (I think): what OS are
you running? What other services? One reason to have to disable
discovery would be that there's another service running on your system
used to announce itself in the network. If discovery is disabled, the
daemon is only visible to Spotify if it's connected to the Spotify's
servers at all times. I'm not sure how well it does recover from
temporary disconnections.

....which makes me think I should probably monitor this, too: just
checked my own account. And indeed, my office SB has disappeared from
Spotify. As it's not in my local network I would only see it if it was
known the Spotify servers. Which it isn't right now. Maybe there was a
network interruption while I was away? Could it be you suffer from (even
short) network disconnections during the night? Some internet providers
do this regularly (eg. daily).

> the logfile I dropped in your dropbox is unmodified. What is a custom
> client_id?

Never mind... sometimes I don't remember my own work...

--

Michael

ElFishi
2018-10-06, 05:29
--disable-discover would indicate that either the daemon had crashed a
lot before, or that you (accidentally) disabled it in the settings.


I am quite confident that I never touched that tickbox. But you never know...
I unticked it this morning and immediately I had my players show up in Spotify connect.
Playing music wasn't without problems after that, which you may be able to follow in the log. I will outline more below.



Which leads me to a question I've asked before (I think): what OS are
you running? What other services?

RPi 3, Distribution: Raspbian GNU/Linux 9 (stretch), Kernel version: Linux 4.14.70-v7+ armv7l, Firmware: #1144
quite a few other services:
Influx, Grafana, Telegraf, Mosquitto
FuguHub (a webserver/homecloud)
avahi
node
minidlna, smb
perl/rpi-monitor
maybe minissdpd is in the way, but I think it comes with Debian


One reason to have to disable
discovery would be that there's another service running on your system
used to announce itself in the network. ...Maybe there was a
network interruption while I was away? Could it be you suffer from (even
short) network disconnections during the night? Some internet providers
do this regularly (eg. daily).

My ISP resets the connection around 3am every day.

I dropped you more logfiles, here is a short account of what I did this morning:

10:15 spotty connect work, spotty does not play, progress bar in app not moving
10:17 music plays for 10sec then stops, pressed |< in spotify app, music plays again
10:19 music stops briefly
10:20 music stops again, progress bar keeps moving
10:22 pressed >|, music starts again
11:14 music stops, players disconnected
11:22 connected, started, bar moves, no music
11:23 pressed |<, no music
11:24 connected This computer, connected players, music playing again
11:25 music stops, bar still moving, pressed |<, music again
11:27 undid all syncs btn player, music continues
11:30 connected to Salonbox only
11:55 stopped player to standby

gunnar
2018-10-06, 10:28
>
Please check Settings/Advanced/File Types: there's a Spotty section. If
transcoding to FLAC is enabled, try to disable it. Give it another try.

Michael

Yes! It works! Had to disable FLAC. MP3 is deactivated and greyed out, and can`t be changed.
When I opened the server WEB-GUI, and selected Spotty, there was a message at the top: "Credentials missing". Not sure why, user/password seemed to be ok. I`ll play some music and try "Spotify connect" via my phone.

mherger
2018-10-06, 13:25
> avahi

That's likely what causes the local announcement to fail. That said:
I'll work on discovering the situation where the daemon would still be
running, but Spotify wouldn't know about it.

> My ISP resets the connection around 3am every day.

I'm pretty sure this is the reason why you lose connection over night.
I'll try to find a workaround for this situation. Thanks for all your
logs and persistence!

--

Michael

frratnam
2018-10-06, 13:52
Hi:
I am trying to install spotify/spotty after my old Triode got removed by mistake.
I am getting the following message in server log "Plugins::Spotty::Connect::canSpotifyConnect (72) Cannot support Spotty Connect, need at least helper version 0.12.0"

And in the advanced tab of LMS, I get the following message:

There has been a problem running the Spotty helper application. Most likely your operating system and/or platform is not supported. Please report the following details to me:

Operating system: Red Hat / i686-linux

Helper Applications Folder:
Information is not avaialable. Please update Logitech Media Server to 7.7.6 or more recent.
ldd (GNU libc) 2.18

Can you recommend what I need to do?

ElFishi
2018-10-06, 14:26
> avahi

That's likely what causes the local announcement to fail. That said:
I'll work on discovering the situation where the daemon would still be
running, but Spotify wouldn't know about it.

avahi ships with raspbian stretch lite, I think. Shouldn't more people experience problems, then?


> My ISP resets the connection around 3am every day.

I'm pretty sure this is the reason why you lose connection over night.
I'll try to find a workaround for this situation.

Thats the usual procedure for most ISPs in my neck of the wood: Am I the only one who struggles?


Thanks for all your
logs and persistence!

Ha, look who's talking!:D
Thanks for bringing all this stuff to us!

mherger
2018-10-06, 14:49
> avahi ships with raspbian stretch lite, I think. Shouldn't more people
> experience problems, then?

Most probably don't realize, as "discovery" through Spotify's servers is
working reasonably well. Unless...

>>> My ISP resets the connection around 3am every day.
>>
>> I'm pretty sure this is the reason why you lose connection over night.
>> I'll try to find a workaround for this situation.
>>
> Thats the usual procedure for most ISPs in my neck of the wood: Am I the
> only one who struggles?

....if you hit this issue. Are you living in German? I think it's
something I've heard of most often for German ISPs...

v2.4.10 should find its way to you in the next few hours. Please give it
another try. It would try to restart the daemon if Spotify didn't report
it as connected any more. It can take an hour before it reconnects. But
that should be fine for your disconnection at 3am.

--

Michael

mherger
2018-10-06, 14:49
> Operating system: Red Hat / i686-linux
>
> Helper Applications Folder:
> Information is not avaialable. Please update Logitech Media Server to
> 7.7.6 or more recent.
> ldd (GNU libc) 2.18

Is this Vortexbox 2.3 or older? I think you'd need to update to 2.4.

--

Michael

ElFishi
2018-10-06, 14:59
....if you hit this issue. Are you living in German? I think it's
something I've heard of most often for German ISPs...
confirmed.



v2.4.10 should find its way to you in the next few hours. Please give it
another try. It would try to restart the daemon if Spotify didn't report
it as connected any more. It can take an hour before it reconnects. But
that should be fine for your disconnection at 3am.

Its there already, lightspeed!
Hang in there, I'll report tomorrow.

ElFishi
2018-10-07, 02:34
When I started the Spotify App this morning I had all 3 players waiting for me to connect to :o

Music playing stably this morning. Thanks!

ashmore
2018-10-07, 02:50
There's a thread in these forums about how to update LMS to 7.9.2 nightlies. It should be as easy as installing any package.

HI

Thanks both (<Michael, Slarti..). I've updated all my software and the issues are fixed.

ashmore
2018-10-07, 04:30
Hi

Having undated to 7.9.2 I'm getting some drop outs and premature ends in Spotty. The spotify connect app continues to drop songs randomly too. Here's a bit of a log file. Anything in settings I'm doing wrong?



[22:13:22.047829] metadata_updated:86 new meta
[22:13:32.017258] log_message:81 log: 21:13:32.017 W [playlist:1575] Lost items added 3b78262c6e313fd90257960f6cad978a02!!!
[22:13:32.017581] log_message:81 log: 21:13:32.017 W [playlist:1575] Lost items added f6e41bad5f6dc913d79b6413ed6838bb04!!!
[22:13:32.086126] log_message:81 log: 21:13:32.086 E [ap:4172] ChannelError(3, 0, playlist)
[22:13:32.086300] log_message:81 log: 21:13:32.086 E [ap:4172] ChannelError(4, 0, playlist)
[22:13:32.131021] metadata_updated:86 new meta
[22:13:42.116638] log_message:81 log: 21:13:42.116 W [playlist:1575] Lost items added 3b78262c6e313fd90257960f6cad978a02!!!
[22:13:42.116969] log_message:81 log: 21:13:42.116 W [playlist:1575] Lost items added f6e41bad5f6dc913d79b6413ed6838bb04!!!
[22:13:42.214660] log_message:81 log: 21:13:42.214 E [ap:4172] ChannelError(3, 0, playlist)
[22:13:42.214782] log_message:81 log: 21:13:42.214 E [ap:4172] ChannelError(4, 0, playlist)
[22:13:42.259273] metadata_updated:86 new meta
[22:13:48.876906] log_message:81 log: 21:13:48.876 I [offline-mgr:2032] 0 files are locked. 0 images are locked
[22:13:48.877004] log_message:81 log: 21:13:48.876 I [offline-mgr:2058] 0 files unlocked. 0 images unlocked
[22:13:48.946286] logged_out:61 logged out
[22:13:59.737707] main:448 /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/Spotify/Bin/arm-linux/spotifyd 2.3.8 started ( libspotify: 12.1.51.g86c92b43 Release Linux-armv5 )
[22:45:28.845749] main:448 /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/SpotifyProtocolHandler/Bin/arm-linux/spotifyd 2.3.8 started ( libspotify: 12.1.51.g86c92b43 Release Linux-armv5 )
[23:11:12.863095] main:619 req: status.json res: (null) par: (null) prot: HTTP/1.0 auth: (null)
[23:11:12.863304] process_status:1464 process status
[11:53:28.130385] main:448 /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/SpotifyProtocolHandler/Bin/arm-linux/spotifyd 2.3.8 started ( libspotify: 12.1.51.g86c92b43 Release Linux-armv5 )
[10:31:31.283342] main:448 /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/SpotifyProtocolHandler/Bin/arm-linux/spotifyd 2.3.8 started ( libspotify: 12.1.51.g86c92b43 Release Linux-armv5 )
[12:27:50.559115] main:619 req: status.json res: (null) par: (null) prot: HTTP/1.0 auth: (null)
[12:27:50.559331] process_status:1464 process status

slartibartfast
2018-10-07, 04:34
Hi

Having undated to 7.9.2 I'm getting some drop outs and premature ends in Spotty. The spotify connect app continues to drop songs randomly too. Here's a bit of a log file. Anything in settings I'm doing wrong?



[22:13:22.047829] metadata_updated:86 new meta
[22:13:32.017258] log_message:81 log: 21:13:32.017 W [playlist:1575] Lost items added 3b78262c6e313fd90257960f6cad978a02!!!
[22:13:32.017581] log_message:81 log: 21:13:32.017 W [playlist:1575] Lost items added f6e41bad5f6dc913d79b6413ed6838bb04!!!
[22:13:32.086126] log_message:81 log: 21:13:32.086 E [ap:4172] ChannelError(3, 0, playlist)
[22:13:32.086300] log_message:81 log: 21:13:32.086 E [ap:4172] ChannelError(4, 0, playlist)
[22:13:32.131021] metadata_updated:86 new meta
[22:13:42.116638] log_message:81 log: 21:13:42.116 W [playlist:1575] Lost items added 3b78262c6e313fd90257960f6cad978a02!!!
[22:13:42.116969] log_message:81 log: 21:13:42.116 W [playlist:1575] Lost items added f6e41bad5f6dc913d79b6413ed6838bb04!!!
[22:13:42.214660] log_message:81 log: 21:13:42.214 E [ap:4172] ChannelError(3, 0, playlist)
[22:13:42.214782] log_message:81 log: 21:13:42.214 E [ap:4172] ChannelError(4, 0, playlist)
[22:13:42.259273] metadata_updated:86 new meta
[22:13:48.876906] log_message:81 log: 21:13:48.876 I [offline-mgr:2032] 0 files are locked. 0 images are locked
[22:13:48.877004] log_message:81 log: 21:13:48.876 I [offline-mgr:2058] 0 files unlocked. 0 images unlocked
[22:13:48.946286] logged_out:61 logged out
[22:13:59.737707] main:448 /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/Spotify/Bin/arm-linux/spotifyd 2.3.8 started ( libspotify: 12.1.51.g86c92b43 Release Linux-armv5 )
[22:45:28.845749] main:448 /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/SpotifyProtocolHandler/Bin/arm-linux/spotifyd 2.3.8 started ( libspotify: 12.1.51.g86c92b43 Release Linux-armv5 )
[23:11:12.863095] main:619 req: status.json res: (null) par: (null) prot: HTTP/1.0 auth: (null)
[23:11:12.863304] process_status:1464 process status
[11:53:28.130385] main:448 /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/SpotifyProtocolHandler/Bin/arm-linux/spotifyd 2.3.8 started ( libspotify: 12.1.51.g86c92b43 Release Linux-armv5 )
[10:31:31.283342] main:448 /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/SpotifyProtocolHandler/Bin/arm-linux/spotifyd 2.3.8 started ( libspotify: 12.1.51.g86c92b43 Release Linux-armv5 )
[12:27:50.559115] main:619 req: status.json res: (null) par: (null) prot: HTTP/1.0 auth: (null)
[12:27:50.559331] process_status:1464 process statusHave you got Spotify Protocol Handler installed? That should be removed if using Spotty.

Sent from my SM-G900F using Tapatalk

gnoe
2018-10-07, 05:20
I still had LMSRepack running on my Synology DS712+, so I had to upgrade to LMS 7.9.2. Installation (after uninstalling Repack version) was successfull and it worked again without a hassle.
As I was very happy with the Spotty plugin (worked fine until the end on the legacy LMS), I installed this latest Spotty v2.4.10 but cannot get it working :(

After a while, I can see the SB receivers appear in the Spotify Apps (on different devices), and also sometimes the Spotty Authorization 'device' (but not always visible). Selecting Spotty Authorization says 'connecting...' but no magic happens. Also selecting the SB receivers doesn't result in any playback. So I checked the logfile, which sais:


Plugins::Spotty::Settings::Auth::handler (70) Authorization failed: thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: Error { repr: Os { code: 110, message: "Operation timed out" } }', /checkout/src/libcore/result.rs:906:4
note: Run with `RUST_BACKTRACE=1` for a backtrace.

I tried to search the forum to find similar problems, but could not find a right solution. I also tried to manually add my Spotify login credentials in the advanced plugin screen, without success.
BTW, in my Spotify Account profile, I have removed the granted access to Spotty as there were two types (maybe one old and one of the current Spotty install). I thought to remove both because they might interfere with each other and to add the access approval again.

Hope someone can help me out?

ashmore
2018-10-07, 10:22
Have you got Spotify Protocol Handler installed? That should be removed if using Spotty.

I did!. Thank you. Now turned off and the LMS Spotty (mostly) works as it should. Spotify connect (as managed through my android spotify app) is still flaky though. Mostly tracks not progressing from one to another. Is that a known thing?

Simon

slartibartfast
2018-10-07, 10:52
I did!. Thank you. Now turned off and the LMS Spotty (mostly) works as it should. Spotify connect (as managed through my android spotify app) is still flaky though. Mostly tracks not progressing from one to another. Is that a known thing?

SimonTracks not progressing used to be a thing if I remember correctly but is fixed as far as I know.

Sent from my SM-G900F using Tapatalk

ashmore
2018-10-07, 11:17
I'm running an extended test on my system to see if I can pin things down a little better; a little too aware of my 'instantly asking for help' mode thus far. My observations are of an ethernetted (real word!?) SB Boom. I also run a picore PI so I'm going to run that for a while and see if the issue is the same there. Will report back once I've experimented some more.

In the meantime, thank you for continuing to be so available to try to help.

Simon

guterm
2018-10-07, 11:19
New Spotty installation v2.4.10 running on LMS v7.9.2 - 1538738519, on Ubuntu
Authorization works fine, can see the Spotty menu, but all entries are empty.
The following errors show up in the log file: "Plugins::Spotty::API::__ANON__ (1480) error: 400 Bad Request"
Error is repeated upon each menu click.

Thoughts and ideas are very much welcome!

- Vadim

slartibartfast
2018-10-07, 11:23
New Spotty installation v2.4.10 running on LMS v7.9.2 - 1538738519, on Ubuntu
Authorization works fine, can see the Spotty menu, but all entries are empty.
The following errors show up in the log file: "Plugins::Spotty::API::__ANON__ (1480) error: 400 Bad Request"
Error is repeated upon each menu click.

Thoughts and ideas are very much welcome!

- VadimDo you have a premium Spotify account?

Sent from my SM-G900F using Tapatalk

ustinov
2018-10-07, 12:21
Since a few weeks I have an Odroid XU4Q, but i keep gettign erractic behavior with Spotty.
Playback stops in the middle of a playlist or album, often the first seconds of a song are skipped when I start or skip manually to the next track.
Changing the spotty helper or using th eoptimize buffer option did not help.

Below the relevant part of the log (Spotty on info) where playback was stopped just before the end of a track in the middle of an album. It seems Spotty thinks this was the last track.
Any idea what is going on, Michael?

Spotify connect from iPad air 1 on IOS12
Server and squeezelite player on Odroid XU4Q running DietPi 6.16
Spotty 2.40.10, helper spotty-hf (auto)

Logitech Media Server Version: 7.9.1 - 1518692686 @ Thu Feb 15 11:18:06 UTC 2018
Hostname: DietPi
[...]
Operating system: Debian - EN - utf8
Platform Architecture: armv7l-linux
Perl Version: 5.24.1 - arm-linux-gnueabihf-thread-multi-64int
Audio::Scan: 0.95
Database Version: DBD::SQLite 1.34_01 (sqlite 3.7.7.1)
Total Players Recognized: 1

Player Model: SqueezeLite
Player Type: squeezelite
Firmware: v1.8.7-1020




[18-10-07 14:41:16.2793] main::init (387) Starting Logitech Media Server (v7.9.1, 1518692686, Thu Feb 15 11:18:06 UTC 2018) perl 5.024001 - arm-linux-gnueabihf-thread-multi-64int
[18-10-07 14:41:16.2953] main::changeEffectiveUserAndGroup (1040) Warning: Logitech Media Server must not be run as root! Only do this if you know what you're doing!!
[18-10-07 14:41:17.7085] Plugins::Spotty::Plugin::purgeAudioCache (455) Starting audio cache cleanup...
[18-10-07 14:41:17.7098] Plugins::Spotty::Plugin::purgeAudioCache (478) Max. cache size is: 0MB, current cache size is 0MB
[18-10-07 14:41:17.7103] Plugins::Spotty::Plugin::purgeAudioCache (509) Starting temporary file cleanup... (/var/lib/squeezeboxserver/cache/spotty)
[18-10-07 14:41:17.7140] Plugins::Spotty::Plugin::purgeAudioCache (529) Audio cache cleanup done!
[18-10-07 14:41:17.7327] Plugins::Spotty::Helper::_findBin (196) Trying helper applicaton: /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/Spotty/Bin/arm-linux/spotty-hf
[18-10-07 14:41:17.7875] Plugins::Spotty::Helper::_findBin (199) Found helper applicaton: /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/Spotty/Bin/arm-linux/spotty-hf
[18-10-07 14:41:23.7089] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (99) Checking Spotty Connect helper daemons...
[18-10-07 14:41:23.7096] Plugins::Spotty::Connect::DaemonManager::startHelp er (151) Need to create Connect daemon for 00:1e:06:36:05:7a
[18-10-07 14:41:23.7143] Plugins::Spotty::Connect::Daemon::start (66) Starting Spotty Connect daemon:
/var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/Spotty/Bin/arm-linux/spotty-hf -c /var/lib/squeezeboxserver/cache/spotty/001e0636057a -n Squeezelite Woonkamer --disable-audio-cache --bitrate 96 --player-mac 00:1e:06:36:05:7a --lms 192.168.10.113:9000
[18-10-07 14:41:29.3769] Plugins::Spotty::Connect::_connectEvent (331) Got called from spotty helper: volume
[18-10-07 14:41:29.3773] Plugins::Spotty::Connect::_connectEvent (342) Set volume to 50
[18-10-07 14:42:22.8942] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (99) Checking Spotty Connect helper daemons...
[18-10-07 14:43:22.8976] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (99) Checking Spotty Connect helper daemons...

[...]



[18-10-07 15:06:17.1889] Plugins::Spotty::Connect::__ANON__ (198) Got a new track to be played next: spotify:track:7yVCPF2RjQaQkPV0SylA5p
[18-10-07 15:06:17.1896] Plugins::Spotty::Connect::Context::getPlay (146) Has spotify://track:7yVCPF2RjQaQkPV0SylA5p been played? no
[18-10-07 15:06:17.1924] Plugins::Spotty::Plugin::purgeAudioCacheAfterXTrac ks (441) Played 1 song(s) since last audio cache purge.
[18-10-07 15:06:22.9534] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (99) Checking Spotty Connect helper daemons...
[18-10-07 15:07:22.9543] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (99) Checking Spotty Connect helper daemons...
[18-10-07 15:08:22.9561] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (99) Checking Spotty Connect helper daemons...
[18-10-07 15:09:22.9586] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (99) Checking Spotty Connect helper daemons...
[18-10-07 15:10:22.9624] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (99) Checking Spotty Connect helper daemons...
[18-10-07 15:11:13.6972] Plugins::Spotty::API::__ANON__ (1399) Trying to read from cache for me
[18-10-07 15:11:13.7000] Plugins::Spotty::API::__ANON__ (1408) API call: me
[18-10-07 15:11:13.7090] Plugins::Spotty::Connect::_getNextTrack (180) We're approaching the end of a track - get the next track
[18-10-07 15:11:13.7106] Plugins::Spotty::Connect::Context::addPlay (126) Adding track to played list: spotify://track:7yVCPF2RjQaQkPV0SylA5p
[18-10-07 15:11:13.7166] Plugins::Spotty::API::__ANON__ (1408) API call: me/player/next
[18-10-07 15:11:13.8439] Plugins::Spotty::API::__ANON__ (1456) Caching result for 60 using max-age (https://api.spotify.com/v1/me)
[18-10-07 15:11:13.8444] Plugins::Spotty::API::__ANON__ (1458) Data cached (https://api.spotify.com/v1/me)
[18-10-07 15:11:13.8614] Plugins::Spotty::API::__ANON__ (1408) API call: me/player
[18-10-07 15:11:13.9504] Plugins::Spotty::Connect::__ANON__ (198) Got a new track to be played next: spotify:track:1rEkUEBFYEtqDLYaTuElsx
[18-10-07 15:11:13.9511] Plugins::Spotty::Connect::Context::getPlay (146) Has spotify://track:1rEkUEBFYEtqDLYaTuElsx been played? no
[18-10-07 15:11:13.9541] Plugins::Spotty::Plugin::purgeAudioCacheAfterXTrac ks (441) Played 2 song(s) since last audio cache purge.
[18-10-07 15:11:22.9649] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (99) Checking Spotty Connect helper daemons...
[18-10-07 15:12:22.9666] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (99) Checking Spotty Connect helper daemons...
[18-10-07 15:13:22.9685] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (99) Checking Spotty Connect helper daemons...
[18-10-07 15:14:22.9703] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (99) Checking Spotty Connect helper daemons...
[18-10-07 15:14:55.9655] Plugins::Spotty::API::__ANON__ (1399) Trying to read from cache for me
[18-10-07 15:14:55.9678] Plugins::Spotty::API::__ANON__ (1408) API call: me
[18-10-07 15:14:56.2514] Plugins::Spotty::Connect::_getNextTrack (180) We're approaching the end of a track - get the next track
[18-10-07 15:14:56.2519] Plugins::Spotty::Connect::Context::addPlay (126) Adding track to played list: spotify://track:1rEkUEBFYEtqDLYaTuElsx
[18-10-07 15:14:56.2539] Plugins::Spotty::API::__ANON__ (1408) API call: me/player/next
[18-10-07 15:14:56.3306] Plugins::Spotty::API::__ANON__ (1456) Caching result for 60 using max-age (https://api.spotify.com/v1/me)
[18-10-07 15:14:56.3312] Plugins::Spotty::API::__ANON__ (1458) Data cached (https://api.spotify.com/v1/me)
[18-10-07 15:14:56.3703] Plugins::Spotty::API::__ANON__ (1408) API call: me/player
[18-10-07 15:14:56.4504] Plugins::Spotty::Connect::__ANON__ (198) Got a new track to be played next: spotify:track:1rEkUEBFYEtqDLYaTuElsx
[18-10-07 15:14:56.4509] Plugins::Spotty::Connect::Context::getPlay (146) Has spotify://track:1rEkUEBFYEtqDLYaTuElsx been played? yes
[18-10-07 15:14:56.4517] Plugins::Spotty::Connect::_delayedStop (233) Stopping playback in -213.068786087036s, as we have likely reached the end of our context (playlist, album, ...)
[18-10-07 15:14:56.4537] Plugins::Spotty::Plugin::purgeAudioCacheAfterXTrac ks (441) Played 3 song(s) since last audio cache purge.
[18-10-07 15:14:56.5498] Plugins::Spotty::API::__ANON__ (1399) Trying to read from cache for me
[18-10-07 15:14:56.5504] Plugins::Spotty::API::__ANON__ (1402) Returning cached data for me
[18-10-07 15:14:56.5515] Plugins::Spotty::API::__ANON__ (1408) API call: me/player/pause?device_id=ca231b83b0db8807e614a33de70015381d 21f034
[18-10-07 15:14:56.6691] Plugins::Spotty::Connect::_onPause (292) Got a pause event - tell Spotify Connect controller to pause, too
[18-10-07 15:14:56.6706] Plugins::Spotty::API::__ANON__ (1399) Trying to read from cache for me
[18-10-07 15:14:56.6710] Plugins::Spotty::API::__ANON__ (1402) Returning cached data for me
[18-10-07 15:14:56.6720] Plugins::Spotty::API::__ANON__ (1408) API call: me/player/pause?device_id=ca231b83b0db8807e614a33de70015381d 21f034
[18-10-07 15:14:57.0441] Plugins::Spotty::Connect::_connectEvent (331) Got called from spotty helper: change
[18-10-07 15:14:57.0455] Plugins::Spotty::API::__ANON__ (1399) Trying to read from cache for me
[18-10-07 15:14:57.0460] Plugins::Spotty::API::__ANON__ (1402) Returning cached data for me
[18-10-07 15:14:57.0469] Plugins::Spotty::API::__ANON__ (1408) API call: me/player
[18-10-07 15:15:16.2837] Plugins::Spotty::Connect::_connectEvent (331) Got called from spotty helper: stop
[18-10-07 15:15:16.2877] Plugins::Spotty::API::__ANON__ (1399) Trying to read from cache for me
[18-10-07 15:15:16.2892] Plugins::Spotty::API::__ANON__ (1402) Returning cached data for me
[18-10-07 15:15:16.2921] Plugins::Spotty::API::__ANON__ (1408) API call: me/player

guterm
2018-10-07, 12:45
Do you have a premium Spotify account?

Sent from my SM-G900F using Tapatalk

Yes, premium family account.

Tried with 7.9.1, cleaned cache, now getting a slightly different error:
"Plugins::Spotty::API::__ANON__ (1480) error: Connect timed out: No route to host"
Box is connected with wired Ethernet connection...
host spotify.com
spotify.com has address 67.222.68.81
ping 67.222.68.81
PING 67.222.68.81 (67.222.68.81) 56(84) bytes of data.
64 bytes from 67.222.68.81: icmp_seq=1 ttl=52 time=30.4 ms

guterm
2018-10-07, 13:38
Yes, premium family account.

Tried with 7.9.1, cleaned cache, now getting a slightly different error:
"Plugins::Spotty::API::__ANON__ (1480) error: Connect timed out: No route to host"
Box is connected with wired Ethernet connection...
host spotify.com
spotify.com has address 67.222.68.81
ping 67.222.68.81
PING 67.222.68.81 (67.222.68.81) 56(84) bytes of data.
64 bytes from 67.222.68.81: icmp_seq=1 ttl=52 time=30.4 ms

"Solved" by switching to OpenDNS from Google DNS, but I am curious what the root cause of the problem was/is...

ashmore
2018-10-07, 13:49
I'm running an extended test on my system to see if I can pin things down a little better

Ok, strange behaviour for Spotify app via android today. For clarity this is not spotty but connect. Having had a maximum of two successive tracks before stopping on the boom, this afternoon the picore (also ethernet) played the whole of Sgt Pepper's (60 odd tracks), but now won't play more than two tracks at a time. No logs to see - presumably because this is outside LMS.

I'm at a loss - network load maybe?

Simon

slartibartfast
2018-10-07, 13:54
Ok, strange behaviour for Spotify app via android today. For clarity this is not spotty but connect. Having had a maximum of two successive tracks before stopping on the boom, this afternoon the picore (also ethernet) played the whole of Sgt Pepper's (60 odd tracks), but now won't play more than two tracks at a time. No logs to see - presumably because this is outside LMS.

I'm at a loss - network load maybe?

SimonHave you set logging for Spotty to "Info"?

Sent from my SM-G900F using Tapatalk

mherger
2018-10-07, 21:41
> When I started the Spotify App this morning I had all 3 players waiting
> for me to connect to :o

That sounds promising! And this morning? Still?

--

Michael

mherger
2018-10-07, 21:43
> Plugins::Spotty::Settings::Auth::handler (70) Authorization failed: thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: Error { repr: Os { code: 110, message: "Operation timed out" } }', /checkout/src/libcore/result.rs:906:4
> note: Run with `RUST_BACKTRACE=1` for a backtrace.

This could be the result of a temporary network issue.

> BTW, in my Spotify Account profile, I have removed the granted access to
> Spotty as there were two types (maybe one old and one of the current
> Spotty install). I thought to remove both because they might interfere
> with each other and to add the access approval again.

Make sure you re-authenticate Spotty.

--

Michael

mherger
2018-10-07, 21:51
> [18-10-07 15:11:13.9504] Plugins::Spotty::Connect::__ANON__ (198) Got a new track to be played next: spotify:track:1rEkUEBFYEtqDLYaTuElsx
> [18-10-07 15:11:13.9511] Plugins::Spotty::Connect::Context::getPlay (146) Has spotify://track:1rEkUEBFYEtqDLYaTuElsx been played? no
....
> [18-10-07 15:14:56.4504] Plugins::Spotty::Connect::__ANON__ (198) Got a new track to be played next: spotify:track:1rEkUEBFYEtqDLYaTuElsx
> [18-10-07 15:14:56.4509] Plugins::Spotty::Connect::Context::getPlay (146) Has spotify://track:1rEkUEBFYEtqDLYaTuElsx been played? yes

That's an odd one: Spotify seems to tell you to play the same track
twice in a row. Therefore Spotty assumes we've reached the end of the
playlist. You didn't manually tell it to repeat that track somehow? Or
really have the same track in the playlist twice in a row?

--

Michael

ElFishi
2018-10-08, 01:38
> When I started the Spotify App this morning I had all 3 players waiting
> for me to connect to :o

That sounds promising! And this morning? Still?

--

Michael

Synced my three players again yesterday.
This morning I could connect to the three of them w/o problem :cool:

This time I connected via the Android app. My Windows notebook has just lost its SDD :(

gnoe
2018-10-08, 23:56
> Plugins::Spotty::Settings::Auth::handler (70) Authorization failed: thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: Error { repr: Os { code: 110, message: "Operation timed out" } }', /checkout/src/libcore/result.rs:906:4
> note: Run with `RUST_BACKTRACE=1` for a backtrace.

This could be the result of a temporary network issue.


> BTW, in my Spotify Account profile, I have removed the granted access to
> Spotty as there were two types (maybe one old and one of the current
> Spotty install). I thought to remove both because they might interfere
> with each other and to add the access approval again.

Make sure you re-authenticate Spotty.

--

Michael

Ah thanks, I'll focus on network connection first then. I have some unpredictable DNS resolving problems with my Synology because of router configuration (Asus ac86u with Merlin/adblocking/VPN etc).
This may also result in re-autentication problems then.

ElFishi
2018-10-09, 09:59
> When I started the Spotify App this morning I had all 3 players waiting
> for me to connect to :o

That sounds promising! And this morning? Still?

--

Michael

Played a little more music. Mostly stable.
Had one occasion this afternoon, where Connect lost the connection and the player just kept playing the same song again.
But I could reconnect right away.

About 18:50 today one of my synced players tripped again and re-booted in the middle of playing a song. My untrained eyes didn't notice anything striking in the log, though.
What could this be?

log files in your dropbox again.

ElFishi
2018-10-09, 23:44
sent more logs.

last night my ISP went down. During that time I rebooted the LMS-RPi
This morning internet was back but spotify connect plays up.
I can connect but the connection drops immediately. Music continues to play, but no next song.

ElFishi
2018-10-10, 23:54
with connected players I get this every minute:

[18-10-11 07:47:47.2952] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (99) Checking Spotty Connect helper daemons...
[18-10-11 07:47:47.3002] Plugins::Spotty::API::__ANON__ (1399) Trying to read from cache for me
[18-10-11 07:47:47.3016] Plugins::Spotty::API::__ANON__ (1408) API call: me
[18-10-11 07:47:47.3713] Plugins::Spotty::API::__ANON__ (1408) API call: me/player/devices
[18-10-11 07:47:47.4840] Plugins::Spotty::API::__ANON__ (1456) Caching result for 60 using max-age (https://api.spotify.com/v1/me)
[18-10-11 07:47:47.4859] Plugins::Spotty::API::__ANON__ (1458) Data cached (https://api.spotify.com/v1/me)
[18-10-11 07:47:47.4986] Plugins::Spotty::Connect::DaemonManager::__ANON__ (166) Daemon for b8:27:eb:d5:60:af seems to be alive, but not known to Spotify - restart
[18-10-11 07:47:47.4999] Plugins::Spotty::Connect::DaemonManager::stopHelpe r (184) Shutting down Connect daemon for b8:27:eb:d5:60:af (pid: 2316)
[18-10-11 07:47:47.5010] Plugins::Spotty::Connect::Daemon::stop (120) Quitting Spotty Connect daemon for b8:27:eb:d5:60:af
[18-10-11 07:47:47.5068] Plugins::Spotty::Connect::Daemon::start (66) Starting Spotty Connect daemon:
/var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/Spotty/Bin/arm-linux/spotty-hf -c /var/lib/squeezeboxserver/cache/spotty/a7912f50 -n Goldfinger, Salonbox & Cabinetbox --disable-audio-cache --bitrate 96 --player-mac b8:27:eb:d5:60:af --lms 192.168.0.107:9000 --disable-discovery
[18-10-11 07:47:47.9390] Plugins::Spotty::Connect::_connectEvent (331) Got called from spotty helper: volume
[18-10-11 07:47:47.9397] Plugins::Spotty::Connect::_connectEvent (338) Ignoring initial volume reset right after daemon start
Everytime I connect to my synced players from spotify I lose connection within less than a minute.
This does not happen when players are connected singly.

slartibartfast
2018-10-11, 00:22
with connected players I get this every minute:

[18-10-11 07:47:47.2952] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (99) Checking Spotty Connect helper daemons...
[18-10-11 07:47:47.3002] Plugins::Spotty::API::__ANON__ (1399) Trying to read from cache for me
[18-10-11 07:47:47.3016] Plugins::Spotty::API::__ANON__ (1408) API call: me
[18-10-11 07:47:47.3713] Plugins::Spotty::API::__ANON__ (1408) API call: me/player/devices
[18-10-11 07:47:47.4840] Plugins::Spotty::API::__ANON__ (1456) Caching result for 60 using max-age (https://api.spotify.com/v1/me)
[18-10-11 07:47:47.4859] Plugins::Spotty::API::__ANON__ (1458) Data cached (https://api.spotify.com/v1/me)
[18-10-11 07:47:47.4986] Plugins::Spotty::Connect::DaemonManager::__ANON__ (166) Daemon for b8:27:eb:d5:60:af seems to be alive, but not known to Spotify - restart
[18-10-11 07:47:47.4999] Plugins::Spotty::Connect::DaemonManager::stopHelpe r (184) Shutting down Connect daemon for b8:27:eb:d5:60:af (pid: 2316)
[18-10-11 07:47:47.5010] Plugins::Spotty::Connect::Daemon::stop (120) Quitting Spotty Connect daemon for b8:27:eb:d5:60:af
[18-10-11 07:47:47.5068] Plugins::Spotty::Connect::Daemon::start (66) Starting Spotty Connect daemon:
/var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/Spotty/Bin/arm-linux/spotty-hf -c /var/lib/squeezeboxserver/cache/spotty/a7912f50 -n Goldfinger, Salonbox & Cabinetbox --disable-audio-cache --bitrate 96 --player-mac b8:27:eb:d5:60:af --lms 192.168.0.107:9000 --disable-discovery
[18-10-11 07:47:47.9390] Plugins::Spotty::Connect::_connectEvent (331) Got called from spotty helper: volume
[18-10-11 07:47:47.9397] Plugins::Spotty::Connect::_connectEvent (338) Ignoring initial volume reset right after daemon start
Everytime I connect to my synced players from spotify I lose connection within less than a minute.
This does not happen when players are connected singly.Have you updated to the latest Spotty 2.4.10?

Sent from my SM-G900F using Tapatalk

mherger
2018-10-11, 00:35
> Everytime I connect to my synced players from spotify I lose connection
> within less than a minute.
> This does not happen when players are connected singly.
Crap... That would answer the comment I left in place for that
particular function:

# does this still work with grouped players?!?

I guess this is a NO. Thanks for the heads up. There's more work to do...

--

Michael

mherger
2018-10-11, 00:35
Have you updated to the latest Spotty 2.4.10?

He certainly did, because that log snippet shows activity only added in 2.4.10 ;-)

pablolie
2018-10-11, 08:21
I play with 2 synched players most of the time, 3 at times (Touc/Radio + Boom), and have no issues with the 2.4.10 plugin.

mherger
2018-10-11, 08:44
> I play with 2 synched players most of the time, 3 at times (Touc/Radio +
> Boom), and have no issues with the 2.4.10 plugin.

Then I guess local announcements are working fine in your case. It's
only a problem for environments where that's not true.

--

Michael

ElFishi
2018-10-11, 14:45
> I play with 2 synched players most of the time, 3 at times (Touc/Radio +
> Boom), and have no issues with the 2.4.10 plugin.

Then I guess local announcements are working fine in your case. It's
only a problem for environments where that's not true.

--

Michael

Happy to tamper with my local announcements if you tell me how.

gnoe
2018-10-12, 06:54
Ah thanks, I'll focus on network connection first then. I have some unpredictable DNS resolving problems with my Synology because of router configuration (Asus ac86u with Merlin/adblocking/VPN etc).
This may also result in re-autentication problems then.

Ok, here's an update. The problems were caused by VPN and/or DNS issues. I have a permanent OpenVPN tunnel on my router to a VPN provider. All clients as well as the Synology are routed through this tunnel. Disabling the tunnel makes Spotty work again. The Spotty Api is registered again in my Spotify Profile on the website.

However, I'd like to understand the root cause and enable the VPN on my router again. Can anyone enlighten me in the inner workings of Spotify/Spotty and it's apparent dependency of a certain type of (internet) connection?

/Edit: enabling the VPN tunnel again resulted in this line in the LMS logfile:
Plugins::Spotty::API::__ANON__ (1468) Invalid data

Because I had another issue with the Synology in DNS resolving (it just didn't resolve where other clients resolved DNS through the tunnel) when the VPN was active, I have manually added DNS's for in the Syno network settings, so they are different from the other clients.

ustinov
2018-10-27, 03:51
> [18-10-07 15:11:13.9504] Plugins::Spotty::Connect::__ANON__ (198) Got a new track to be played next: spotify:track:1rEkUEBFYEtqDLYaTuElsx
> [18-10-07 15:11:13.9511] Plugins::Spotty::Connect::Context::getPlay (146) Has spotify://track:1rEkUEBFYEtqDLYaTuElsx been played? no
....
> [18-10-07 15:14:56.4504] Plugins::Spotty::Connect::__ANON__ (198) Got a new track to be played next: spotify:track:1rEkUEBFYEtqDLYaTuElsx
> [18-10-07 15:14:56.4509] Plugins::Spotty::Connect::Context::getPlay (146) Has spotify://track:1rEkUEBFYEtqDLYaTuElsx been played? yes

That's an odd one: Spotify seems to tell you to play the same track
twice in a row. Therefore Spotty assumes we've reached the end of the
playlist. You didn't manually tell it to repeat that track somehow? Or
really have the same track in the playlist twice in a row?

--

Michael

Sorry Michael.
I thought I was being ignored, but I just did not recognise my own log in your reply. :)
No, I did not play that track before, but further research seems to suggest it is indeed the problem with Spotty thinking the same track is played twice. Apparently because it receives the current track as next track.
Yesterday I updated to Spotty 2.5.1 (using helper spotty-hf 0.12.0 (auto)), but the problem of stopping albums or playlists remains.

I put a partial log on pastebin of playing the radiohead Kid A album, no shuffle. Music stopped at the end of track 3, and the log seems to show that the next track after track 3 was actually the same track. So Spotty stopped.

Since nobody else is complaining, and it happens to me all the time, could there be something with my setup/account that is different or should be reset?
I already did a clean re-install of the Spotify app on the iPad.
I do see I have 'optimize pre-buffering' on for this log but it happens also when this is off (that was the reason I turned it on)
Should I further investigate with that option off, or can this not be related?

Setup is still Spotify IOS app, connect from iPad air 1 on IOS12
Server and squeezelite player on Odroid XU4Q running DietPi 6.17.12.
This happens also when using Spotty to stream to iPeng on my iPhone, so it appears not player related.

I will turn off optimize pre-buffering again and see what the log says then.

Thanks

Peter
-------------------------------
Setup:
Logitech Media Server Version: 7.9.1 - 1518692686 @ Thu Feb 15 11:18:06 UTC 2018
Hostname: DietPi
Server IP Address: 192.168.10.113
Server HTTP Port Number: 9000
Operating system: Debian - EN - utf8
Platform Architecture: armv7l-linux
Perl Version: 5.24.1 - arm-linux-gnueabihf-thread-multi-64int
Audio::Scan: 0.95
Database Version: DBD::SQLite 1.34_01 (sqlite 3.7.7.1)

Log: https://pastebin.com/3vZQwy0w

EDIT: I just checked that the same thing happens if I turn off pre-buffering optimization. Sometimes the next song is reported as being the same song that is playing (and almost ending) and Spotty stops.
I do have another problem with Spotify app progress barr not starting at 0 (changes between 11 and 34s), and the first seconds (not sure if its the 11-34s or less) are skipped before audio begins. This is also happening when using iPeng on iPhone as player. When playing on the iPad speaker ( no Spotty) progress always start at 0 and I can hear the song from the beginning.

Could this be a problem with progess/buffer being calculated incorrectly? With 'next song' being requested too soon or too late?

mherger
2018-10-28, 22:23
> I do see I have 'optimize pre-buffering' on for this log but it happens
> also when this is off (that was the reason I turned it on)
> Should I further investigate with that option off, or can this not be
> related?

That option actually would have been what I'd have suggested next...

> Server and squeezelite player on Odroid XU4Q running DietPi 6.17.12.

Are you using any non-default settings for squeezelite? Like large
buffers? If so, could you please try without them?

--

Michael

ustinov
2018-10-29, 15:28
> I do see I have 'optimize pre-buffering' on for this log but it happens
> also when this is off (that was the reason I turned it on)
> Should I further investigate with that option off, or can this not be
> related?

That option actually would have been what I'd have suggested next...

> Server and squeezelite player on Odroid XU4Q running DietPi 6.17.12.

Are you using any non-default settings for squeezelite? Like large
buffers? If so, could you please try without them?

--

Michael

Thanks Michael.

Squeezelite is normally started using systemd with options -a 4096:1024:16:0 -n 'Squeezelite Woonkamer' -f /var/log/squeezelite.log
This is the dafult settings Dietpi installs it with , except for the -C 5, which I removed to keep the HDMI connection with my receiver alive.

If I remove the -a 4096:1024:16:0 and reboot, it consistently stops after the one song. Below the log when I restarted a stopped track. Again it stopped after one track, but no 'Has spotify://track:xxxxxxxxxxxxxxx been played? yes', with Spotty debug on info.
I no longer get audio over HDMI. Is that the :0 option?

Is there another option I should try?


[18-10-29 22:24:05.0330] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (90) Checking Spotty Connect helper daemons...
[18-10-29 22:25:05.0356] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (90) Checking Spotty Connect helper daemons...
[18-10-29 22:26:05.0372] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (90) Checking Spotty Connect helper daemons...
[18-10-29 22:27:05.0397] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (90) Checking Spotty Connect helper daemons...
[18-10-29 22:28:05.0416] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (90) Checking Spotty Connect helper daemons...
[18-10-29 22:29:00.9520] Plugins::Spotty::Connect::_connectEvent (331) Got called from spotty helper: change
[18-10-29 22:29:00.9539] Plugins::Spotty::API::__ANON__ (1382) Trying to read from cache for me
[18-10-29 22:29:00.9543] Plugins::Spotty::API::__ANON__ (1391) API call: me
[18-10-29 22:29:00.9577] Plugins::Spotty::API::__ANON__ (1391) API call: me/player
[18-10-29 22:29:01.1486] Plugins::Spotty::Connect::DaemonManager::checkAPIC onnectPlayers (218) Updating id of Connect connected dameon for 00:1e:06:36:05:7a
[18-10-29 22:29:01.1490] Plugins::Spotty::Connect::__ANON__ (371) Got a change event, but actually this is a play next track event
[18-10-29 22:29:01.1493] Plugins::Spotty::Connect::__ANON__ (377) Got a new track to be played: spotify:track:7tLTov4Ax1pyGcaV4qWrP5
[18-10-29 22:29:01.1566] Plugins::Spotty::Connect::getNextTrack (125) Don't get next track as we got called by a play track event from spotty
[18-10-29 22:29:01.1580] Plugins::Spotty::API::__ANON__ (1382) Trying to read from cache for me
[18-10-29 22:29:01.1584] Plugins::Spotty::API::__ANON__ (1391) API call: me
[18-10-29 22:29:01.2069] Plugins::Spotty::API::__ANON__ (1391) API call: me/player
[18-10-29 22:29:01.2643] Plugins::Spotty::API::__ANON__ (1439) Caching result for 60 using max-age (https://api.spotify.com/v1/me)
[18-10-29 22:29:01.2649] Plugins::Spotty::API::__ANON__ (1441) Data cached (https://api.spotify.com/v1/me)
[18-10-29 22:29:01.2954] Plugins::Spotty::API::__ANON__ (1439) Caching result for 60 using max-age (https://api.spotify.com/v1/me)
[18-10-29 22:29:01.2960] Plugins::Spotty::API::__ANON__ (1441) Data cached (https://api.spotify.com/v1/me)
[18-10-29 22:29:01.3254] Plugins::Spotty::Connect::DaemonManager::checkAPIC onnectPlayers (218) Updating id of Connect connected dameon for 00:1e:06:36:05:7a
[18-10-29 22:29:01.3269] Plugins::Spotty::API::__ANON__ (1382) Trying to read from cache for me
[18-10-29 22:29:01.3273] Plugins::Spotty::API::__ANON__ (1385) Returning cached data for me
[18-10-29 22:29:01.3277] Plugins::Spotty::Connect::Context::new (55) Create new Connect context...
[18-10-29 22:29:01.3290] Plugins::Spotty::API::__ANON__ (1382) Trying to read from cache for albums/0BiNb8HYR4JvuxUa31Z58Q?limit=50&market=from_token&offset=0
[18-10-29 22:29:01.3299] Plugins::Spotty::API::__ANON__ (1385) Returning cached data for albums/0BiNb8HYR4JvuxUa31Z58Q?limit=50&market=from_token&offset=0
[18-10-29 22:29:01.3351] Plugins::Spotty::Connect::Context::addPlay (126) Adding track to played list: spotify://track:7tLTov4Ax1pyGcaV4qWrP5
[18-10-29 22:29:01.3376] Plugins::Spotty::Plugin::purgeAudioCacheAfterXTrac ks (450) Played 3 song(s) since last audio cache purge.
[18-10-29 22:29:05.0435] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (90) Checking Spotty Connect helper daemons...
[18-10-29 22:30:05.0447] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (90) Checking Spotty Connect helper daemons...
[18-10-29 22:31:05.0456] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (90) Checking Spotty Connect helper daemons...
[18-10-29 22:32:05.0481] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (90) Checking Spotty Connect helper daemons...
[18-10-29 22:33:05.0513] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (90) Checking Spotty Connect helper daemons...
[18-10-29 22:34:05.0532] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (90) Checking Spotty Connect helper daemons...
[18-10-29 22:35:05.0556] Plugins::Spotty::Connect::DaemonManager::initHelpe rs (90) Checking Spotty Connect helper daemons...

mherger
2018-10-29, 22:08
> Squeezelite is normally started using systemd with options -a
> 4096:1024:16:0 -n 'Squeezelite Woonkamer' -f /var/log/squeezelite.log
> This is the dafult settings Dietpi installs it with , except for the -C
> 5, which I removed to keep the HDMI connection with my receiver alive.

Hmmm... none of the buffer options used (which I know can cause issues).
Unless they did compile with some non-standard parameters this shouldn't
behave any different than a pCP. I'm sorry to say I have no idea what is
going on there :-(

--

Michael

ralphy
2018-10-30, 04:30
Using -a 4096:1024 also adds a lot of buffering within alsa. Try changing -a 4096:1024:16:0 to -a 80:4 and let squeezelite probe the other 2 values.

ustinov
2018-10-31, 03:07
>[...]
Are you using any non-default settings for squeezelite? Like large
buffers? If so, could you please try without them?

--

Michael

I use the build that came with Dietpi, but you may be on to something. Yesterday I played a several albums to iPeng on my iPhone through Spotty and they did not stop prematurely.
I will look at different builds for squeezelite, but that will be over the weekend probably.

Thanks!

ustinov
2018-10-31, 05:25
Using -a 4096:1024 also adds a lot of buffering within alsa. Try changing -a 4096:1024:16:0 to -a 80:4 and let squeezelite probe the other 2 values.

I will try. Thanks!

EDIT: With -a 80:4 I get no sound from my speakers (over HDMI), but -a 80:4:16:0 seems to do the trick. No stops all afternoon, playing three whole albums.
I did notice once the last song was cut short. I will see if that happens more often.

Keeping my fingers crossed, but this looks like the solution to my problem.

Thanks guys!

sdiesel77
2018-11-03, 08:16
Hi Guys,
I just enabled the Spotify Connect option, I must have done something wrong as it's not working for me.
I can see Picoreplayer in my Spotify but even when selected and even if Spotify shows the song as playing I can see that my Pi3 player screen doesn't show it and doesn't play the song.
But if I go to my App Orange Squeez and go to Spotty app here is works.

https://uploads.tapatalk-cdn.com/20181103/97618396e51bd5cf89f946ed4d57396c.jpg

sdiesel77
2018-11-04, 02:43
It seems nobody has this issue :(

slartibartfast
2018-11-04, 02:46
It seems nobody has this issue :(What does the server log say when Spotty is set to info?

Sent from my SM-G900F using Tapatalk

sdiesel77
2018-11-04, 03:28
This is what I see.

Here is the first line:
error getting token MercuryError
[18-11-03 18:12:51.8938] Plugins::Spotty::API::_gotTokenResponse (194) Failed to get Spotify access token
[18-11-03 18:15:04.1584] Plugins::Spotty::API::_gotTokenResponse (179) Failed to get Spotify access token: malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "error getting token ...") at /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/Spotty/API.pm line 176.


25893

slartibartfast
2018-11-04, 04:01
This is what I see.

Here is the first line:
error getting token MercuryError
[18-11-03 18:12:51.8938] Plugins::Spotty::API::_gotTokenResponse (194) Failed to get Spotify access token
[18-11-03 18:15:04.1584] Plugins::Spotty::API::_gotTokenResponse (179) Failed to get Spotify access token: malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "error getting token ...") at /volume1/@appstore/SqueezeCenter/Cache/InstalledPlugins/Plugins/Spotty/API.pm line 176.


25893Have a look at this post. JoseA with a Synology had a similar issue.
https://forums.slimdevices.com/showthread.php?108574-Spotty-on-Synology-Can-not-login-in-Spotify

Sent from my SM-G900F using Tapatalk

sdiesel77
2018-11-04, 05:25
Have a look at this post. JoseA with a Synology had a similar issue.
https://forums.slimdevices.com/showthread.php?108574-Spotty-on-Synology-Can-not-login-in-Spotify

Sent from my SM-G900F using Tapatalk

Thanks so much ! Issue fixed :cool: