Announcement

Collapse
No announcement yet.

spotty is skipping songs, it starts with a new one before playing the whole song.

Collapse
X
 
  • Filter
  • Time
  • Show
Clear All
new posts

    spotty is skipping songs, it starts with a new one before playing the whole song.

    I use the lms image in docker on a synology 218+. LMS works, my music library on the nas does plays perfect. YouTube plugin plays fine as does campout.

    It does the skipping with a wireless Logitech radio as with the Logitech squeezebox touch. It does it when connected through lan, wifi and vonnets.

    in the file section for spotty i tried all options now i use only flac and disabled all others. enabling just ogg vorbis and disabling the others, works, but with the same skipping.

    I don't see the skipping in the log files.

    I have a spotify family subscription, tried without and with spotify client id. no difference.

    I reinstalled lms in docker, starting fresch, no improvement.

    i removed c3po decoder helper as it gave errors.

    No idea what i should do with the other errors? It seems connection related but how or where?
    Any help is greatly appreciated!

    Regards Bart



    this is the scanner log:

    [23-02-14 15:30:45.3423] main::main (202) Starting Logitech Media Server scanner (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001
    [23-02-14 15:30:45.6627] Slim::Utils::PluginManager::load (219) Skipping plugin: ExtendedBrowseModes - in erroneous state: needs-disable
    [23-02-14 15:30:45.7315] Slim::Music::Import::runImporter (579) Starting Slim::Music::PlaylistFolderScan scan
    [23-02-14 15:30:45.7322] Slim::Utils::Scanner::Local::rescan (179) Discovering audio files in /music/playlist
    [23-02-14 15:30:45.8253] Slim::Utils::Scanner::Local::__ANON__ (191) Start processing found tracks
    [23-02-14 15:30:45.8258] Slim::Utils::Scanner::Local::__ANON__ (199) Connect do DB
    [23-02-14 15:30:45.8265] Slim::Utils::Scanner::Local::__ANON__ (202) Get latest ID
    [23-02-14 15:30:45.8272] Slim::Utils::Scanner::Local::__ANON__ (225) Build temporary table for new tracks
    [23-02-14 15:30:46.0211] Slim::Utils::Scanner::Local::__ANON__ (245) Build temporary table for changed tracks
    [23-02-14 15:30:46.0228] Slim::Utils::Scanner::Local::__ANON__ (282) Get deleted tracks count
    [23-02-14 15:30:46.0237] Slim::Utils::Scanner::Local::__ANON__ (289) Get new tracks count
    [23-02-14 15:30:46.0248] Slim::Utils::Scanner::Local::__ANON__ (294) Get changed tracks count
    [23-02-14 15:30:46.0255] Slim::Utils::Scanner::Local::deleteTracks (370) Removing deleted audio files (0)
    [23-02-14 15:30:46.0262] Slim::Utils::Scanner::Local::updateTracks (537) Rescanning changed audio files (0)
    [23-02-14 15:30:46.0265] Slim::Utils::Scanner::Local::addTracks (453) Scanning new audio files (0)
    [23-02-14 15:30:46.0273] Slim::Music::Import::endImporter (712) Completed Slim::Music::PlaylistFolderScan Scan in 0.296 seconds.
    [23-02-14 15:30:46.0982] Slim::Music::Artwork::updateStandaloneArtwork (234) Starting updateStandaloneArtwork for 1155 albums
    [23-02-14 15:30:53.4330] Slim::Music::Import::endImporter (712) Completed updateStandaloneArtwork Scan in 7.405 seconds.
    [23-02-14 15:30:53.4556] Slim::Music::Artwork:​recacheAllArtwork (657) Starting precacheArtwork for 17 albums
    [23-02-14 15:30:53.7845] Slim::Music::Artwork::__ANON__ (808) precacheArtwork finished in 0.322852849960327
    [23-02-14 15:30:53.7849] Slim::Music::Import::endImporter (712) Completed precacheArtwork Scan in 0.347 seconds.
    [23-02-14 15:30:53.7878] Slim::Music::Import::runScanPostProcessing (481) Starting Database optimization.
    [23-02-14 15:30:56.4447] Slim::Music::Import::endImporter (712) Completed dbOptimize Scan in 2.656 seconds.​



    This is the server log.

    [23-02-14 14:10:56.6835] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-14 14:11:01.3677] main::checkDataSource (1107) Warning: Schema updated or no media found in the database, initiating scan.
    [23-02-14 14:12:33.2798] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-14 14:21:34.0487] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-14 14:21:35.7074] Slim::Utils::Misc::msg (1325) Warning: [14:21:35.7066] Subroutine preferences redefined at /config/cache/InstalledPlugins/Plugins/C3PO/PreferencesHelper.pm line 53.
    [23-02-14 14:24:19.9706] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-14 14:24:20.5575] Slim::Utils::Misc::msg (1325) Warning: [14:24:20.5571] Subroutine preferences redefined at /config/cache/InstalledPlugins/Plugins/C3PO/PreferencesHelper.pm line 53.
    [23-02-14 14:29:49.2481] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-14 14:29:50.9901] Slim::Utils::Misc::msg (1325) Warning: [14:29:50.9896] Subroutine preferences redefined at /config/cache/InstalledPlugins/Plugins/C3PO/PreferencesHelper.pm line 53.
    [23-02-14 14:29:51.7898] main::checkDataSource (1107) Warning: Schema updated or no media found in the database, initiating scan.
    [23-02-14 14:53:28.1615] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-14 14:53:30.0363] Slim::Utils::Misc::msg (1325) Warning: [14:53:30.0349] Subroutine preferences redefined at /config/cache/InstalledPlugins/Plugins/C3PO/PreferencesHelper.pm line 53.
    [23-02-14 14:53:30.8024] main::checkDataSource (1107) Warning: Schema updated or no media found in the database, initiating scan.
    [23-02-14 15:27:45.8000] Slim::Utils::Misc::msg (1325) Warning: [15:27:45.7986] Use of uninitialized value in concatenation (.) or string at /config/cache/InstalledPlugins/Plugins/C3PO/Plugin.pm line 279.
    [23-02-14 15:31:40.6538] Slim::Utils::Misc::msg (1325) Warning: [15:31:40.6534] Use of uninitialized value in concatenation (.) or string at /config/cache/InstalledPlugins/Plugins/C3PO/Plugin.pm line 279.
    [23-02-14 15:35:33.7756] Slim::Utils::Misc::msg (1325) Warning: [15:35:33.7752] Use of uninitialized value in concatenation (.) or string at /config/cache/InstalledPlugins/Plugins/C3PO/Plugin.pm line 279.
    [23-02-14 16:22:02.7739] Slim::Utils::Misc::msg (1325) Warning: [16:22:02.7734] Use of uninitialized value in concatenation (.) or string at /config/cache/InstalledPlugins/Plugins/C3PO/Plugin.pm line 279.
    [23-02-14 16:26:30.4572] Slim::Utils::Misc::msg (1325) Warning: [16:26:30.4567] Use of uninitialized value in concatenation (.) or string at /config/cache/InstalledPlugins/Plugins/C3PO/Plugin.pm line 279.
    [23-02-14 16:53:21.6197] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-14 16:53:22.9189] Slim::Utils::Misc::msg (1325) Warning: [16:53:22.9181] Subroutine preferences redefined at /config/cache/InstalledPlugins/Plugins/C3PO/PreferencesHelper.pm line 53.
    [23-02-14 19:05:06.8756] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-14 19:05:07.7989] Slim::Utils::Misc::msg (1325) Warning: [19:05:07.7985] Subroutine preferences redefined at /config/cache/InstalledPlugins/Plugins/C3PO/PreferencesHelper.pm line 53.
    [23-02-14 19:05:12.0495] Plugins::Spotty::Connect:​aemonManager::checkAPIConnectPlayers (210) Connect daemon is running, but not connected - shutting down to force restart: 00:04:20:27:9d:87 Keuken radio
    [23-02-15 06:33:45.5557] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-15 06:33:53.2542] Slim::Utils::Misc::msg (1325) Warning: [06:33:53.2537] Subroutine preferences redefined at /config/cache/InstalledPlugins/Plugins/C3PO/PreferencesHelper.pm line 53.
    [23-02-15 10:14:30.5953] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-15 10:14:32.9432] Slim::Web::Cometd::handler (431) errorNeedsClient: 172.17.0.1, 00:04:20:2c:c2:9b, status, -, 10, menu:menu, useContextMenu:1, subscribe:600
    [23-02-15 12:04:55.1048] Slim::Utils::Scanner::Local::rescan (179) Discovering audio files in /music/playlist
    [23-02-15 12:04:55.1582] Slim::Utils::Scanner::Local::__ANON__ (191) Start processing found tracks
    [23-02-15 12:04:55.1585] Slim::Utils::Scanner::Local::__ANON__ (199) Connect do DB
    [23-02-15 12:04:55.1588] Slim::Utils::Scanner::Local::__ANON__ (202) Get latest ID
    [23-02-15 12:04:55.1595] Slim::Utils::Scanner::Local::__ANON__ (225) Build temporary table for new tracks
    [23-02-15 12:04:55.3393] Slim::Utils::Scanner::Local::__ANON__ (245) Build temporary table for changed tracks
    [23-02-15 12:04:55.3628] Slim::Utils::Scanner::Local::__ANON__ (282) Get deleted tracks count
    [23-02-15 12:04:55.3631] Slim::Utils::Scanner::Local::__ANON__ (289) Get new tracks count
    [23-02-15 12:04:55.3637] Slim::Utils::Scanner::Local::__ANON__ (294) Get changed tracks count
    [23-02-15 12:04:55.3643] Slim::Utils::Scanner::Local::deleteTracks (370) Removing deleted audio files (0)
    [23-02-15 12:04:55.3647] Slim::Utils::Scanner::Local::updateTracks (537) Rescanning changed audio files (0)
    [23-02-15 12:04:55.3650] Slim::Utils::Scanner::Local::addTracks (453) Scanning new audio files (0)
    [23-02-15 12:29:07.8481] Slim::Utils::Misc::msg (1325) Warning: [12:29:07.8475] APE: [Tag larger than maximum possible size] /music/The Rumjacks/The Rumjacks - Brass for Gold (2022) Mp3 320kbps [PMEDIA] ⭐️/01. Bounding Main.mp3
    [23-02-15 12:29:07.8889] Slim::Utils::Misc::msg (1325) Warning: [12:29:07.8884] APE: [Tag larger than maximum possible size] /music/The Rumjacks/The Rumjacks - Brass for Gold (2022) Mp3 320kbps [PMEDIA] ⭐️/01. Bounding Main.mp3
    [23-02-15 14:34:32.9467] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-15 14:43:41.7149] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-15 14:43:44.0419] Slim::Web::Cometd::handler (431) errorNeedsClient: 172.17.0.1, 00:04:20:27:9d:87, status, -, 10, menu:menu, useContextMenu:1, subscribe:600
    [23-02-15 19:45:43.1275] Plugins::Spotty::API::__ANON__ (1442) API call: me/player/devices
    [23-02-15 19:45:43.1402] Plugins::Spotty::API::__ANON__ (1446) error: 503 Service Unavailable
    [23-02-15 22:19:40.8654] Plugins::Spotty::Connect:​aemonManager::checkAPIConnectPlayers (210) Connect daemon is running, but not connected - shutting down to force restart: 00:04:20:27:9d:87 Keuken radio
    [23-02-16 06:33:40.9080] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-16 16:43:31.4179] Plugins::Spotty::API::__ANON__ (1442) API call: me/player/devices
    [23-02-16 16:43:31.6503] Plugins::Spotty::API::__ANON__ (1446) error: 503 Service Unavailable
    [23-02-16 19:43:45.7338] Plugins::Spotty::API::__ANON__ (1442) API call: me/player/devices
    [23-02-16 19:43:45.7343] Plugins::Spotty::API::__ANON__ (1446) error: 503 Service Unavailable
    [23-02-17 00:14:32.9068] Plugins::Spotty::Connect:​aemonManager::checkAPIConnectPlayers (210) Connect daemon is running, but not connected - shutting down to force restart: 00:04:20:27:9d:87 Keuken radio
    [23-02-17 06:33:27.4088] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-17 10:19:50.3598] Plugins::Spotty::API::Token::_killTokenHelper (201) Token refresh call helper has closed unexpectedly? - Please consider re-setting your Spotify credentials should this continue to happen.
    [23-02-17 19:20:48.1013] Plugins::Spotty::API::__ANON__ (1442) API call: me/player/devices
    [23-02-17 19:20:48.1018] Plugins::Spotty::API::__ANON__ (1446) error: 503 Service Unavailable
    [23-02-17 21:12:46.1208] Plugins::Spotty::API::__ANON__ (1442) API call: me/player/devices
    [23-02-17 21:12:46.1212] Plugins::Spotty::API::__ANON__ (1446) error: 503 Service Unavailable
    [23-02-18 06:33:32.6872] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-18 13:28:18.8690] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-22 09:43:12.0197] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-22 10:53:01.8775] Slim::Menu::TrackInfo::cliQuery (1382) Didn't get either valid trackId or url.
    [23-02-22 12:40:10.2112] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-22 12:41:47.5357] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-22 12:41:49.7294] Slim::Web::Cometd::handler (431) errorNeedsClient: 172.17.0.1, 00:04:20:2c:c2:9b, status, -, 10, menu:menu, useContextMenu:1, subscribe:600
    [23-02-22 12:41:50.3540] Slim::Web::Cometd::handler (431) errorNeedsClient: 172.17.0.1, 00:04:20:27:9d:87, status, -, 10, menu:menu, useContextMenu:1, subscribe:600
    [23-02-22 13:05:29.1643] Plugins::Spotty::API::__ANON__ (1442) API call: me/player/devices
    [23-02-22 13:05:29.1646] Plugins::Spotty::API::__ANON__ (1446) error: 503 Service Unavailable
    [23-02-22 13:13:23.0639] Slim::Player::Squeezebox2::statHandler (156) Error: 00:04:20:27:9d:87: Decoder does not support file format, code 0
    [23-02-22 21:06:02.7191] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-22 22:01:58.1268] Plugins::Spotty::API::Token::_gotTokenInfo (187) Failed to create session or connect to servers.
    [23-02-23 06:33:10.2105] main::init (377) Starting Logitech Media Server (v8.3.0, 1667251155, Fri Nov 4 09:20:18 CET 2022) perl 5.032001 - x86_64-linux-gnu-thread-multi
    [23-02-23 13:01:23.4741] Plugins::Spotty::API::Token::_killTokenHelper (201) Timed out waiting for a token

    #2
    Can you specify when about in this log you'd see your issues? I'm seeing quite a few issues related to Spotty (503, "timed out waiting for a token" etc.). But do they correlate with when the issue happened? Where about are you living? We've seen issues connecting to Spotify's servers from certain regions in the past.

    And as you've messed with all settings: would you mind resetting them all, or at least post them here? Some of them _can_ cause problems when set inappropriately.
    Michael

    "It doesn't work - what shall I do?" - "Please check your server.log and/or scanner.log file!"
    (LMS: Settings/Information)

    Comment


      #3
      Hi Michael - while we are talking about it, i also had a bad skipping/truncating problem with Spotty a couple days ago (have not tried again since) I attach the log - in my case, every other track skipped to the next track at about 30 or 40 seconds in - i.e. tracks 2, 4, 6, 8, 10 all skipped/truncated. Win 10 i7 laptop, via Upnp Bridge 2.1.13.6 to a Wiim pro, all Spotty settings at default other than Ogg vorbis disabled, all Upnp bridge settings at default. I am in western canada, if you think server location is the issue. upnpbridge log Feb 23 spotty skips.txt

      Comment


        #4
        Sorry i just realized my previous post attached a log from the UpnP Bridge, not Spotty or LMS. Which is the correct log for Spotty issues in Win 10 - is it C>Program Data>Squeezebox>Logs>Server ?

        Comment


          #5
          There's a link to download the compressed version of server.log.zip in Settings/Information (in LMS).

          What I forgot to ask: are you using Spotify Connect or do you control playback all through LMS?
          Michael

          "It doesn't work - what shall I do?" - "Please check your server.log and/or scanner.log file!"
          (LMS: Settings/Information)

          Comment


            #6
            Originally posted by mherger View Post
            There's a link to download the compressed version of server.log.zip in Settings/Information (in LMS).

            What I forgot to ask: are you using Spotify Connect or do you control playback all through LMS?
            Thank you for patiently explaining the same info that has been in your signature for the last several thousand posts But when i go to that log location, it seems to have almost no entries from today's date (02/25), despite the fact i have played 3 or 4 different spotty/spotify albums today. I pasted today's entries below - am i in the wrong log? The skipping behaviour is remarkably consistent - every different Spotify album i play skips at about 32 seconds in, on every other track, starting with the even-numbered tracks - 2,4,6,8 etc. LMS 8.3.1, upnp bridge 2.1.13.6, Win 10 i7 laptop.

            I am not using Spotify connect in LMS. When i try Spotify connect without LMS (android phone to Wiim Pro) there is no skipping behaviour.

            [23-02-25 08:13:14.5077] main::init (377) Starting Logitech Media Server (v8.3.1, 1676361197, Fri Feb 17 06:33:29 WEST 2023) perl 5.014001 - MSWin32-x86-multi-thread
            [23-02-25 16:17:23.7107] Slim::Utils::Misc::msg (1325) Warning: [16:17:23.7088] Use of uninitialized value in concatenation (.) or string at C:\PROGRA~2\SQUEEZ~1\server\HTML\EN\ajaxProgress.t xt line 6.​

            Comment


              #7
              I've been seeing this too on Alpine, with my lms packages and spotty-custom binary, though I'm pretty sure it was happening with the 64bit statically linked helper also. I know that doesn't give you much more to go on. For me it seems to skip to the next song prematurely, I'd say usually it's about 80-90% through a song and then jumps to the next song, but I'm never paying attention enough to know exactly.

              Comment


                #8
                Do you have your http mode set to either persistent or cached?

                Comment


                  #9
                  Originally posted by spacecase-25 View Post
                  Do you have your http mode set to either persistent or cached?
                  Mine is set to "Normal streaming". I don't mess with the any of the default settings usually unless I'm having an issue. I haven't changed any of the defaults for the Spotty plugin.

                  Comment


                    #10
                    Originally posted by Spacegrass View Post

                    Thank you for patiently explaining the same info that has been in your signature for the last several thousand posts But when i go to that log location, it seems to have almost no entries from today's date (02/25), despite the fact i have played 3 or 4 different spotty/spotify albums today. I pasted today's entries below - am i in the wrong log? The skipping behaviour is remarkably consistent - every different Spotify album i play skips at about 32 seconds in, on every other track, starting with the even-numbered tracks - 2,4,6,8 etc. LMS 8.3.1, upnp bridge 2.1.13.6, Win 10 i7 laptop.

                    I am not using Spotify connect in LMS. When i try Spotify connect without LMS (android phone to Wiim Pro) there is no skipping behaviour.

                    [23-02-25 08:13:14.5077] main::init (377) Starting Logitech Media Server (v8.3.1, 1676361197, Fri Feb 17 06:33:29 WEST 2023) perl 5.014001 - MSWin32-x86-multi-thread
                    [23-02-25 16:17:23.7107] Slim::Utils::Misc::msg (1325) Warning: [16:17:23.7088] Use of uninitialized value in concatenation (.) or string at C:\PROGRA~2\SQUEEZ~1\server\HTML\EN\ajaxProgress.t xt line 6.​
                    Actually, i now believe my skipping issue is related to Upnp Bridge, not Spotty - i downloaded Spotty 4.8.7 and Upnp bridge 2.1.14 this morning, and on playing the same Spotty/Spotify album as yesterday, via Upnp to Wiim Pro, identical skipping behaviour as above. But when i then played the same Spotty/Spotify album to a native Squeezebox (no Upnp) there was no skipping. I will post the Upnp log in the Upnp thread. Sorry for the mistaken Spotty slandering!

                    Comment


                      #11
                      Originally posted by sodface View Post

                      Mine is set to "Normal streaming". I don't mess with the any of the default settings usually unless I'm having an issue. I haven't changed any of the defaults for the Spotty plugin.
                      Go ahead and change that. Should fix your problem.

                      Comment


                        #12
                        Originally posted by spacecase-25 View Post

                        Go ahead and change that. Should fix your problem.
                        I'll give it a shot, it did it a lot today, pretty annoying.

                        Comment

                        Working...
                        X