Home of the Squeezebox™ & Transporter® network music players.
Page 1 of 2 12 LastLast
Results 1 to 10 of 16
  1. #1
    Junior Member
    Join Date
    Nov 2016
    Posts
    13

    Spotty plays only intermittently

    Hi there,

    The problem:

    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.

    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.

  2. #2
    Babelfish's Best Boy mherger's Avatar
    Join Date
    Apr 2005
    Location
    Switzerland
    Posts
    20,365

    Spotty plays only intermittently

    > Squeezelite v1.9.5-1193

    You could try to enable streaming PCM or FLAC instead of Ogg. Go to
    Settings/Filetypes and disable SPT -> Ogg streaming. Or try to update
    Squeezelite. Ralphy did fix Ogg streaming at some point. Don't ask me at
    which one exactly...

    --

    Michael

  3. #3
    Senior Member ralphy's Avatar
    Join Date
    Jan 2006
    Location
    Canada
    Posts
    2,336
    Quote Originally Posted by mherger View Post
    > Squeezelite v1.9.5-1193

    You could try to enable streaming PCM or FLAC instead of Ogg. Go to
    Settings/Filetypes and disable SPT -> Ogg streaming. Or try to update
    Squeezelite. Ralphy did fix Ogg streaming at some point. Don't ask me at
    which one exactly...

    --

    Michael
    It was fixed at squeezelite v1.9.3-1174
    Ralphy

    1-Touch, 5-Classics, 3-Booms, 1-UE Radio
    Squeezebox client builds donations always appreciated.

  4. #4
    Babelfish's Best Boy mherger's Avatar
    Join Date
    Apr 2005
    Location
    Switzerland
    Posts
    20,365

    Spotty plays only intermittently

    >>> Squeezelite v1.9.5-1193
    >
    > It was fixed at squeezelite v1.9.3-1174


    Oh, then this should not be the problem here. Thanks for chiming in.

    --

    Michael

  5. #5
    Junior Member
    Join Date
    Nov 2016
    Posts
    13
    Quote Originally Posted by mherger View Post
    >>> Squeezelite v1.9.5-1193
    >
    > It was fixed at squeezelite v1.9.3-1174


    Oh, then this should not be the problem here. Thanks for chiming in.

    --

    Michael
    I tried this anyway - disabling Ogg Vorbis in the Spotty section of the file types - but it didn't make any difference. Then it suddenly started working for 3 quarters of a song before it cut out again. I can't see anything distinctive in the logs for this cutout except possibly an entry of this line:

    Code:
    [20-01-20 22:07:34.2260] Plugins::Spotty::Plugin::purgeAudioCacheAfterXTracks (451) Played 3 song(s) since last audio cache purge.
    At this point, `ps` showed several spotty processes running so I was partly wondering if a bad previous process made it think 3 songs had played and then purged for the running one. This doesn't explain why the original process failed, though.

    I also tried switching on logging for squeezelite and after some startup messages I get this:

    Code:
    [22:24:16.933633] slimproto:887 connecting to 192.168.8.104:3483
    [22:24:16.933839] slimproto:926 connected
    [22:24:16.933869] slimproto:937 local player
    [22:24:16.933887] sendHELO:142 mac: 74:e5:43:cb:ae:84
    [22:24:16.933905] sendHELO:144 cap: CanHTTPS=1,Model=squeezelite,AccuratePlayPoints=1,HasDigitalOut=1,HasPolarityInversion=1,Firmware=v1.9.5-1193,ModelName=SqueezeLite,M
    axSampleRate=768000,dsf,dff,alc,aac,ogg,ops,ogf,flc,aif,pcm,mp3,loc
    [22:24:16.943213] output_thread:763 start error: File descriptor in bad state
    with that last message repeated many times.

    Any other debug steps I can try? Do the spotty commands themselves log anywhere? As I said before, running them directly using the command line I can see in `ps` gives a permissions error, although I can see recent credentials in `/var/lib/squeezeboxserver/cache/spotty/02270050/credentials.json`.

    Peter

  6. #6
    Babelfish's Best Boy mherger's Avatar
    Join Date
    Apr 2005
    Location
    Switzerland
    Posts
    20,365

    Spotty plays only intermittently

    > I tried this anyway - disabling Ogg Vorbis in the Spotty section of the
    > file types - but it didn't make any difference. Then it suddenly
    > started working for 3 quarters of a song before it cut out again. I


    Hmm... that sounds really odd. Like intermittent networking issues or
    something.


    > At this point, `ps` showed several spotty processes running so I was


    That's fine: every Connect enabled player would launch a background
    task. And every track being played another one. You could have two
    processes per player.

    > [22:24:16.943213] output_thread:763 start error: File descriptor in bad state


    I'm not too familiar with squeezelite. You might want to ask in a
    squeezelite related thread what that message means.

    --

    Michael

  7. #7
    Junior Member
    Join Date
    Nov 2016
    Posts
    13
    Quote Originally Posted by mherger View Post
    >
    Hmm... that sounds really odd. Like intermittent networking issues or
    something.
    I agree that it's odd, but the setup (which includes a server running on a Gigabyte Brix, Squeezelite running on the same, two Duet receivers, a Squeezebox radio and a Squeezebox Boom) still works flawlessly for locally stored music, SoundCloud and BBC iPlayer. Up until recently, Spotty was working perfectly as well and we were listening up to 10 hours a day. I'm trying to rack my brains to think what changed but without success


    Quote Originally Posted by mherger View Post
    >
    I'm not too familiar with squeezelite. You might want to ask in a
    squeezelite related thread what that message means.
    I don't think Squeezelite is the problem here, because I get the same problem when I desynchronise the Squeezelite-based player and run Spotty to, say, the Squeezebox Radio. I'm also really surprised I can't spot anything in the logs - I would expect that when the stream of data stops one of the processes working on that stream should say something about it.

    I'd like to work down to the Spotty helper tool command line and run that to watch it but when I copy the Spotty command lines I see in `ps` I get a PermissionDenied. Are there docs (or code?) somewhere I can follow to shows how the Spotty command lines are strung together? I presume one to pull a token from Spotify and cache it, and then another to use that token to get a stream. Can I use Spotty on its own to direct the Spotify stream into a raw device so I can remove all the other machinery from the equation? Or better yet drive down until I'm on `curl` or something similarly basic, so I can see if there is anything wrong with my Spotify account itself.

    I'm also not sure if there's anywhere accessible at the Spotify end where they keep a log of API-driven access. Are you aware of a console of any sort I could see there to locate any errors?

    Peter

  8. #8
    Babelfish's Best Boy mherger's Avatar
    Join Date
    Apr 2005
    Location
    Switzerland
    Posts
    20,365

    Spotty plays only intermittently

    > I'd like to work down to the Spotty helper tool command line and run
    > that to watch it but when I copy the Spotty command lines I see in `ps`
    > I get a PermissionDenied.


    This could be caused by the fact that you're likely not using the same
    account when interacting with your system as LMS is using.

    > Are there docs (or code?) somewhere I can
    > follow to shows how the Spotty command lines are strung together? I


    spotty -h

    > presume one to pull a token from Spotify and cache it, and then another
    > to use that token to get a stream. Can I use Spotty on its own to direct


    The commands are all logged in server.log. You'll probably have to wrap
    some parameters in quotes.

    > I'm also not sure if there's anywhere accessible at the Spotify end
    > where they keep a log of API-driven access.


    Nothing I'm aware of.

    Are you using Connect mode or LMS? Use the latter for your testing, it's
    robuster.
    --

    Michael

  9. #9
    Junior Member
    Join Date
    Nov 2016
    Posts
    13
    Quote Originally Posted by mherger View Post
    >This could be caused by the fact that you're likely not using the same
    account when interacting with your system as LMS is using.
    Yes, good point. Thanks.

    Quote Originally Posted by mherger View Post
    Are you using Connect mode or LMS? Use the latter for your testing, it's
    robuster.
    I'm only using LMS - I disabled Connect mode as soon as I started having problems.

    I tried reproducing the spotty commands from `server.log`, although I can only find the one to obtain tokens and not the streaming command - I got that from using `ps`

    Code:
    $ sudo -u squeezeboxserver /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/Spotty/Bin/i386-linux/spotty-x86_64 -n Squeezebox -c "/var/lib/squeezeboxserver/cache/spotty/02270050" -i abcdef1234567890 --scope "user-read-private,user-follow-modify,user-follow-read,user-library-read,user-library-modify,user-top-read,user-read-recently-played,user-read-playback-state,user-modify-playback-state,playlist-read-private,playlist-read-collaborative,playlist-modify-public,playlist-modify-private" --save-token "/tmp/0NL6Y9jNhr"
    error getting token MercuryError
    I also changing the directory at the end in case it was to do with file permissions, but without any change.

    Looking at the code:

    https://github.com/michaelherger/spo...c/main.rs#L493

    It looks like we're calling an API via librespot and it's just not returning properly, but the error message is none too informative - not sure if there's any way to get at more detail of the error...?

    Having said that, this call must be working at some level because I'm able to browse the playlists and (occasionally) play, so I also tried running one of the stream commands:

    Code:
    $ sudo -u squeezeboxserver /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/SpottBin/i386-linux/spotty-x86_64 -n Squeezebox -c /var/lib/squeezeboxserver/cache/spotty/02270050 --single-track spotify://track:6fenHIxXuuzKB55wY4WCHP --bitrate 320 --disable-discovery --disable-audio-cache --pass-through
    This just seems to hang forever. If I do `sudo lsof | grep -i spotty`, there is an entry like this:

    Code:
    spotty-x8 18333 18339 squeezeboxserver   13u     IPv4              78474       0t0        TCP cube:45016->180.64.199.104.bc.googleusercontent.com:4070 (ESTABLISHED)
    so it looks like it is connected to something... but nothing is coming through.

    I feel sure there is an error message somewhere that I just can't see, which is why I'd still like to unpack the Spotty layer and make the underlying API call directly with more basic tools like `curl`. I might be able to figure this out by picking through the librespot code but it certainly might save me some time if you have any suggestions

    At the end of this series of debugging, it managed to play one track from a playlist before dying again. Combed through the logs looking for anything that made this one play look different without success

    Peter

  10. #10
    Babelfish's Best Boy mherger's Avatar
    Join Date
    Apr 2005
    Location
    Switzerland
    Posts
    20,365

    Spotty plays only intermittently

    > I tried reproducing the spotty commands from `server.log`, although I
    > can only find the one to obtain tokens and not the streaming command - I
    > got that from using `ps`


    Ah, right. The playback is "hidden" inside the transcoding framework.
    But you shouldn't need to get a token if you've been using Spotty
    through LMS recently. It would be picked up from the cache folder.

    > $ sudo -u squeezeboxserver /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/SpottBin/i386-linux/spotty-x86_64 -n Squeezebox -c /var/lib/squeezeboxserver/cache/spotty/02270050 --single-track spotify://track:6fenHIxXuuzKB55wY4WCHP --bitrate 320 --disable-discovery --disable-audio-cache --pass-through
    >
    >
    > This just seems to hang forever. If I do `sudo lsof | grep -i spotty`,
    > there is an entry like this:


    Hmm... what if you left out the --pass-through parameter? And make sure
    you re-direct output, as the output will mess up your terminal window badly.

    > I feel sure there is an error message somewhere that I just can't see,


    I'm not so sure about that, tbh. You could try to build your own binary
    with debug messages enabled. But I don't think it's too verbose.

    > which is why I'd still like to unpack the Spotty layer and make the
    > underlying API call directly with more basic tools like `curl`. I might
    > be able to figure this out by picking through the librespot code but it
    > certainly might save me some time if you have any suggestions


    AFAIK Spotify still doesn't use straight http requests to serve the
    audio tracks. And they wouldn't like you pulling files that way -
    they'll try hard to prevent you from seeing what's going on :-).

    > At the end of this series of debugging, it managed to play one track
    > from a playlist before dying again. Combed through the logs looking for
    > anything that made this one play look different without success


    That's really, really odd. I mean, I've seen failure, too. Sometimes
    there seem to be issues on Spotify's end, causing failure to play music
    for a few minutes or an hour. But for days? I haven't seen this yet.

    I might have asked this before, but you're not trying to do this in a VM
    or Docker? Would you have another machine to run the same tests (with
    correct paths, of course)?

    --

    Michael

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •