Hi there,
THE PROBLEM[/B]:
SPOTTY ONLY PLAYS INTERMITTENTLY. I CAN SUCCESSFULLY BROWSE PLAYLISTS
AND PLAY AND I SEE THE TRACKS APPEAR IN THE PLAYING LIST, BUT NOTHING
COMES OUT OF THE SPEAKERS. PLAYING LOCAL MUSIC OR MUSIC FROM BBC IPLAYER
OR SOUNDCLOUD WORKS FINE. AFTER UPDATING THE SERVER AND PLAYER IT WORKED
PROPERLY FOR A BIT BUT THEN STOPPED AGAIN.
[B]WHAT VERSIONS AM I RUNNING
Logitechmediaserver 7.9.2
Squeezelite v1.9.5-1193
Spotty v3.1.3
WHAT HAVE I TRIED?
- I upgraded server and player as described above
- I tried playing to a different client since I have Squeezebox radio
devices on my network. It worked occasionally but then stopped working
again
- I tried resetting my auth credentials - after that it played for 30
seconds and then stopped again
LOGS
I set the Spotty log to debug level. After resetting auth credentials I
restarted the server and it played for a 30 second period before it
died. Here are the startup logs (note that I've snipped out my token
manually):
Code:
--------------------
[20-01-19 20:40:58.0956] main::init (387) Starting Logitech Media Server
(v7.9.2, 1578727069, Mon Jan 13 15:39:42 CET 2020) perl 5.018002 -
x86_64-linux-gnu-thread-multi
[20-01-19 20:40:58.5045] Slim::Utils::Misc::msg (1255) Warning:
[20:40:58.5041] DBIx::Class::ResultSet::update_or_create(): Query returned more
than one row. SQL that r
eturns multiple rows is DEPRECATED for ->find and ->single at
/usr/share/perl5/Slim/Schema.pm line 1871
[20-01-19 20:40:59.3542] Plugins::AutoRescan::Plugin::initPlugin (102)
Initialising v1.4.1 (trunk-7.x)
[20-01-19 20:41:01.1438] Plugins::Spotty::Plugin::purgeAudioCache (469)
Starting temporary file cleanup... (/var/lib/squeezeboxserver/cache/spotty)
[20-01-19 20:41:01.1444] Plugins::Spotty::Plugin::purgeAudioCache (483) Audio
cache cleanup done!
[20-01-19 20:41:01.3569] Slim::Plugin::MusicMagic::Plugin::initPlugin (154)
Can't connect to port 10002 - MusicIP disabled.
[20-01-19 20:41:01.9718] Plugins::Spotty::Helper::_findBin (196) Trying
helper application:
/var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/Spotty/Bin/i386-linu
x/spotty-x86_64
[20-01-19 20:41:01.9862] Plugins::Spotty::Helper::helperCheck (122) Found
helper capabilities table: do {
my $a = {
debug => bless(do{\(my $o = 0)}, "JSON::XS::Boolean"),
"lms-auth" => bless(do{\(my $o = 1)}, "JSON::XS::Boolean"),
"ogg-direct" => 'fix',
podcasts => 'fix',
"save-token" => 'fix',
version => "0.35.0",
"volume-normalisation" => 'fix',
};
$a->{"ogg-direct"} = \${$a->{"lms-auth"}};
$a->{podcasts} = \${$a->{"lms-auth"}};
$a->{"save-token"} = \${$a->{"lms-auth"}};
$a->{"volume-normalisation"} = \${$a->{"lms-auth"}};
$a;
}
[20-01-19 20:41:01.9867] Plugins::Spotty::Helper::_findBin (199) Found helper
application:
/var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/Spotty/Bin/i386-linux/spotty-x86_64
[20-01-19 20:41:05.1011] Plugins::Spotty::API::getToken (81) Found cached
token: (snip)
[20-01-19 20:41:05.1018] Plugins::Spotty::API::__ANON__ (1382) Trying to read
from cache for me
[20-01-19 20:41:05.1025] Plugins::Spotty::API::__ANON__ (1391) API call: me
[20-01-19 20:41:05.1064] Plugins::Spotty::ProtocolHandler::getMetadataFor
(190) Found cached metadata for spotify:track:0IbKDougbWSz6DUAixncoB
[20-01-19 20:41:05.1078] Plugins::Spotty::ProtocolHandler::getMetadataFor
(191) {
album => "Yesterday",
artist => "Gareth Emery, NASH, Linney",
cover =>
"https://i.scdn.co/image/29b42a1fe6587c1128cba43dd193d41d5ecef264";,
duration => "199.5",
title => "Yesterday",
}
[20-01-19 20:41:05.1105] Plugins::Spotty::ProtocolHandler::getMetadataFor
(170) Returning metadata cached in song object for
spotify://track:0IbKDougbWSz6DUAixncoB
[20-01-19 20:41:05.1116] Plugins::Spotty::ProtocolHandler::getMetadataFor
(171) {
album => "Yesterday",
artist => "Gareth Emery, NASH, Linney",
bitrate => "320k VBR",
cover =>
"https://i.scdn.co/image/29b42a1fe6587c1128cba43dd193d41d5ecef264";,
duration => "199.5",
icon => "/html/images/cover.png",
originalType => "Ogg Vorbis (Spotify)",
title => "Yesterday",
type => "Ogg Vorbis (Spotify)",
url => "spotify://track:0IbKDougbWSz6DUAixncoB",
}
--------------------
there are quite a few variants on these metadata messages, with other
entries like this:
Code:
--------------------
[20-01-19 20:41:05.5680] Plugins::Spotty::API::__ANON__ (1415) {
country => "GB",
display_name => "abi_saffrey",
explicit_content => {
filter_enabled => bless(do{\(my $o = 1)}, "JSON::XS::Boolean"),
filter_locked => bless(do{\(my $o = 0)}, "JSON::XS::Boolean"),
},
external_urls => { spotify => "https://open.spotify.com/user/abi_saffrey"; },
followers => { href => undef, total => 0 },
href => "https://api.spotify.com/v1/users/abi_saffrey";,
id => "abi_saffrey",
images => [],
product => "premium",
type => "user",
uri => "spotify:user:abi_saffrey",
}
[20-01-19 20:41:05.5726] Plugins::Spotty::API::__ANON__ (1444) Caching result
for 60 using max-age (https://api.spotify.com/v1/me)
[20-01-19 20:41:05.5738] Plugins::Spotty::API::__ANON__ (1446) Data cached
(https://api.spotify.com/v1/me)
--------------------
and occasionally also messages like this:
Code:
--------------------
[20-01-19 20:41:06.0337]
Plugins::Spotty::Connect::DaemonManager::initHelpers (90) Checking Spotty
Connect helper daemons...
[20-01-19 20:41:06.0344] Plugins::Spotty::Connect::DaemonManager::initHelpers
(124) This is a standalone player with Spotify Connect disabled:
00:04:20:1e:5c:44
[20-01-19 20:41:06.0348] Plugins::Spotty::Connect::DaemonManager::initHelpers
(124) This is a standalone player with Spotify Connect disabled:
00:04:20:2a:51:6f
[20-01-19 20:41:06.0353] Plugins::Spotty::Connect::DaemonManager::initHelpers
(124) This is a standalone player with Spotify Connect disabled:
74:e5:43:cb:ae:84
[20-01-19 20:41:06.0364] Plugins::Spotty::ProtocolHandler::getMetadataFor
(190) Found cached metadata for spotify:track:5Lugtz8tfLgGDeqF9wJHHQ
--------------------
I turned off connect mode when I started having problems. I also spotted
this in amongst all the metadata messages:
Code:
--------------------
[20-01-19 20:42:13.2507]
Plugins::Spotty::Plugin::purgeAudioCacheAfterXTracks (451) Played 2 song(s)
since last audio cache purge.
--------------------
I don't think it had got through 2 songs, but not sure if this is
important.
I can zip up the whole server.log and post it somewhere if that would
help, or reduce log level to `INFO` if that's better.
OTHER INFORMATION
I did notice that after some of this poking around there were quite a
few spotty processes running. I also tried copying some of the command
lines I saw there:
Code:
--------------------
$
/var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/Spotty/Bin/i386-linux/spotty-x86_64
-n Squeezebox -c /var/lib/squeezeboxserver/cache/spotty/02270050
--single-track spotify://track:4DwJQdtHQOygOAaio9HsSr --bitrate 320
--disable-discovery --disable-audio-cache --pass-through
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: Os {
code: 13, kind: PermissionDenied, message: "Permission denied" }',
src/libcore/result.rs:997:5
note: Run with `RUST_BACKTRACE=1` environment variable to display a backtrace.
Aborted
--------------------
but if I'm "PermissionDenied" I don't understand why I can browse and
play songs and why it sometimes works. I also tried running this with
`-v` but it didn't provide any more useful information.
------------------------------------------------------------------------
psaffrey's Profile: http://forums.slimdevices.com/member.php?userid=66276
View this thread: http://forums.slimdevices.com/showthread.php?t=111512
_______________________________________________
plugins mailing list
[email protected]
http://lists.slimdevices.com/mailman/listinfo/plugins
