Playlist stalls

[ElFishi]

In order for this forum post not to be buried I am posting my issue her again:

I have a problem with playing long playlists in YT: In irregular intervals, probably btn 10 to 100 songs LMS stops playing the playlist:

One song has fully finished, LMS still shows the pause sign as if it was still playing, and the time elapsed is either at the length of the song or flipping between one second before and the end. The corresponding long entries look like this:

[24-02-22 12:41:03.0396] Plugins::YouTube::ProtocolHandler::getStreamJSON (533) found itag: 250
[24-02-22 12:41:03.0401] Plugins::YouTube::ProtocolHandler::getStreamJSON (538) matching format 250
[24-02-22 12:41:03.0405] Plugins::YouTube::ProtocolHandler::getStreamJSON (533) found itag: 251
[24-02-22 12:41:03.0410] Plugins::YouTube::ProtocolHandler::getStreamJSON (538) matching format 251
[24-02-22 12:41:03.0421] Plugins::YouTube::ProtocolHandler::getStreamJSON (566) candidate itag: 251, url/cipher: s=l2JI2JfQdSswRAIgKphL6Q7ysF-gMo6amALMzH8lj_JaJeWA28NiIiaxkx4CIEFXxEPi74ee6ZnwgO-IjymkWAuTcAbOyZoJCoyigqoA&sp=sig&url=https://rr3---sn-uxaxq5u5-4qie.googlevideo.com/videoplayback%3Fexpire%3D1708623662%26ei%3DzjLXZYL9F46li9oPqKi1gAo%26ip%3D185.162.220.252%26id%3Do-AC1w1IFliHzOmNHO16PWDomAZehFVW-645UqYxL5p1YW%26itag%3D251%26source%3Dyoutube%26requiressl%3Dyes%26xpc%3DEgVo2aDSNQ%253D%253D%26mh%3DLi%26mm%3D31%252C29%26mn%3Dsn-uxaxq5u5-4qie%252Csn-4g5ednsd%26ms%3Dau%252Crdu%26mv%3Dm%26mvi%3D3%26pcm2cms%3Dyes%26pl%3D22%26initcwndbps%3D1925000%26spc%3DUWF9f-tPWXXkRRbaifpsnqI3V8EO6QCCdDRLEAw8kf_Ru0w%26vprv%3D1%26svpuc%3D1%26mime%3Daudio%252Fwebm%26ns%3D06v9lSWa6KkfeQ1p78p5upkQ%26gir%3Dyes%26clen%3D5106736%26dur%3D294.941%26lmt%3D1605406344999971%26mt%3D1708601584%26fvip%3D1%26keepalive%3Dyes%26fexp%3D24007246%26c%3DWEB%26sefc%3D1%26txp%3D1311224%26n%3DQNht-d6ykB9aCUGLq%26sparams%3Dexpire%252Cei%252Cip%252Cid%252Citag%252Csource%252Crequiressl%252Cxpc%252Cspc%252Cvprv%252Csvpuc%252Cmime%252Cns%252Cgir%252Cclen%252Cdur%252Clmt%26lsparams%3Dmh%252Cmm%252Cmn%252Cms%252Cmv%252Cmvi%252Cpcm2cms%252Cpl%252Cinitcwndbps%26lsig%3DAPTiJQcwRQIhAOrTOPcgbSCVEEchHLZHtl9yc4sfGVH2YPJXQ1A8Z2WLAiB3gNbQb-sSyqdzltzmwz_VcYsJPrJ8Y8Jr69pKo4Oq4w%253D%253D
[24-02-22 12:41:03.0427] Plugins::YouTube::ProtocolHandler::getStreamJSON (567) candidate ops sig l2JI2JfQdSswRAIgKphL6Q7ysF-gMo6amALMzH8lj_JaJeWA28NiIiaxkx4CIEFXxEPi74ee6ZnwgO-IjymkWAuTcAbOyZoJCoyigqoA encrypted 1
[24-02-22 12:41:03.5094] Plugins::YouTube::WebM::__ANON__ (690) could not get codec info 403 Forbidden
[24-02-22 12:41:03.5105] Plugins::YouTube::ProtocolHandler::close (187) end of streaming for youtube://www.youtube.com/v/qIC1-GTHISo
[24-02-22 12:41:03.5112] Plugins::YouTube::ProtocolHandler::close (187) end of streaming for youtube://www.youtube.com/v/qIC1-GTHISo
[24-02-22 12:41:03.5145] Plugins::YouTube::ProtocolHandler::new (130) url: https://rr3---sn-uxaxq5u5-4qie.googlevideo.com/videoplayback?expire=1708623662&ei=zjLXZYL9F46li9oPqKi1gAo&ip=185.162.220.252&id=o-AC1w1IFliHzOmNHO16PWDomAZehFVW-645UqYxL5p1YW&itag=251&source=youtube&requiressl=yes&xpc=EgVo2aDSNQ%3D%3D&mh=Li&mm=31%2C29&mn=sn-uxaxq5u5-4qie%2Csn-4g5ednsd&ms=au%2Crdu&mv=m&mvi=3&pcm2cms=yes&pl=22&initcwndbps=1925000&spc=UWF9f-tPWXXkRRbaifpsnqI3V8EO6QCCdDRLEAw8kf_Ru0w&vprv=1&svpuc=1&mime=audio%2Fwebm&ns=06v9lSWa6KkfeQ1p78p5upkQ&gir=yes&clen=5106736&dur=294.941&lmt=1605406344999971&mt=1708601584&fvip=1&keepalive=yes&fexp=24007246&c=WEB&sefc=1&txp=1311224&n=QNht-d6ykB9aCUGLq&sparams=expire%2Cei%2Cip%2Cid%2Citag%2Csource%2Crequiressl%2Cxpc%2Cspc%2Cvprv%2Csvpuc%2Cmime%2Cns%2Cgir%2Cclen%2Cdur%2Clmt&lsparams=mh%2Cmm%2Cmn%2Cms%2Cmv%2Cmvi%2Cpcm2cms%2Cpl%2Cinitcwndbps&lsig=APTiJQcwRQIhAOrTOPcgbSCVEEchHLZHtl9yc4sfGVH2YPJXQ1A8Z2WLAiB3gNbQb-sSyqdzltzmwz_VcYsJPrJ8Y8Jr69pKo4Oq4w%3D%3D&sig=AJfQdSswRAIgKphL6Q7ysF-gMo6am2LMzH8lj_JaJeWAI8Ailiaxkx4CIEFXxEPi74ee6ZnwgO-IjymkWAuTcAbOyZoJCoyigqoN offset: 0
[24-02-22 12:41:03.8175] Plugins::YouTube::WebM::__ANON__ (636) could not find start offset 403 Forbidden
[24-02-22 12:41:03.8187] Plugins::YouTube::ProtocolHandler::__ANON__ (154) starting from offset
[24-02-22 12:44:46.9572] Plugins::YouTube::ProtocolHandler::canDoAction (91) action=stop
[24-02-22 12:44:46.9627] Plugins::YouTube::ProtocolHandler::close (187) end of streaming for youtube://www.youtube.com/v/_hJda31yQjo
[24-02-22 12:44:46.9651] Plugins::YouTube::ProtocolHandler::close (187) end of streaming for youtube://www.youtube.com/v/_hJda31yQjo
[24-02-22 12:44:46.9726] Plugins::YouTube::ProtocolHandler::getMetadataFor (850) updating thumbnail cache with hires https://i.ytimg.com/vi/_hJda31yQjo/maxresdefault.jpg
[24-02-22 12:44:46.9804] Plugins::YouTube::ProtocolHandler::getNextTrack (380) next track id: _hJda31yQjo url: http://www.youtube.com/watch?v=_hJda31yQjo master: youtube://www.youtube.com/v/_hJda31yQjo

Playback stops after __ANON__ (154) starting from offset

and when I press >> (fwd) the next song plays and the log continues with canDoAction (91) action=stop

Since I started tracking the issue every stalled playlist playback by the YouTube plugin was associated with the same log entries

[24-02-26 08:14:16.0609] Plugins::YouTube::WebM::__ANON__ (690) could not get codec info 403 Forbidden
[24-02-26 08:14:16.3646] Plugins::YouTube::WebM::__ANON__ (636) could not find start offset 403 Forbidden

[Jumpy91]

Thanks for your detailed description. I have the same problem here on my end. I thought i am the only one who has this problem.

Logitech Media Server-Status Logitech Media Server Version: 8.4.1 - 1708338002 @ Tue Feb 20 03:02:42 CET 2024 Hostname: LMS IP-Adresse des Servers: 192.168.2.25 Server-HTTP-Portnummer: 9002 Betriebssystem: Debian (Docker) - DE - utf8 Plattformarchitektur: x86_64-linux Datenbankversion: SQLite Anzahl erkannter Player: 3

Perl- und Modulversionen Perl-Version: 5.32.1 - x86_64-linux-gnu-thread-multi Audio::Scan: 1.06 DBD::SQLite: 1.58 (sqlite 3.22.0) IO::Socket::SSL: 2.069 Mozilla::CA: Net::SSLeay: 1.88 - OpenSSL 1.1.1w 11 Sep 2023

[ElFishi]

I run this little script in the background as workaround. Could be more finely tuned, but works.

    #!/usr/bin/env python

    import time
    import requests
    import json
    import logging
    from   datetime import datetime

    import os, stat

    # Configure logging to write messages to a file
    logging.basicConfig(
            filename =      'skipLMS.log',
            level =         logging.INFO,
            format =        '%(asctime)s %(levelname).1s %(message)s',
            datefmt =       '%Y-%m-%d %H:%M:%S'
    )

    ServerLMS = "http://lmsserver:9000/jsonrpc.js"
    logfile = "/var/log/squeezeboxserver/server.log"
    trigger = "start offset 403 Forbidden"

    '''
            References
            http://www.dabeaz.com/generators/Generators.pdf pp 75
            https://stackoverflow.com/questions/62036007/rotate-reopen-file-in-python3-when-signal-is-received
    '''

    def follow(filename):

            while True:
                    with open(filename,'r') as thefile:
                            f_ino = os.stat(logfile)[stat.ST_INO]
                            f_dev = os.stat(logfile)[stat.ST_DEV]
                            logging.info(f"Follow {filename}, ino {f_ino}, dev {f_dev}")

                            thefile.seek(0, 2) # End-of-file

                            while True:
                                    line = thefile.readline()

                                    try:
                                            if (os.stat(logfile)[stat.ST_INO] != f_ino or
                                                    os.stat(logfile)[stat.ST_DEV] != f_dev):
                                                    logging.info("file ino or dev has changed.")
                                                    break

                                    except OSError:
                                            pass

                                    if not line:
                                            time.sleep(1)
                                            continue

                                    yield line

                    time.sleep(2)

    def execute (player,cmd):
            data = { 'id': 1, 'method': 'slim.request', 'params': [player,cmd]}
            response = requests.get(ServerLMS, data=json.dumps(data)).json()
            result = response['result']
            return result

    def skip_song():
            count = execute("",["player", "count", "?"])
            count = count['_count']
            players = execute('', ['players','0', count])
            players = players['players_loop']
            logging.info( f"Found players: { ', '.join(player['name'] for player in players) }" )

            for player in players:

                    if player['isplaying']:
                            status = execute(player['playerid'],['status','-',1,''])
                            logging.info(f"{player['name']} is playing { status['current_title']}: {status['time']:.1f} / {status['duration']}")
                            time_elapsed = status['time']
                            timeleft = status['duration'] - time_elapsed
                            logging.info(f"Time left: {timeleft:.1f}")

                            if timeleft < 9.0:
                                    time.sleep(timeleft)
                                    execute(player['playerid'],['playlist','index','+1'])
                                    logging.info("player told to skip.")
                            else:
                                    time.sleep(2)
                                    status = execute(player['playerid'],['status','-',1,''])
                                    if status['time'] - time_elapsed < 1:
                                            execute(player['playerid'],['playlist','index','+1'])
                                            logging.info("player told to skip.")

    logging.info("SkipLMS: Follow LMS server.log and skip song if playlist is stuck at the end of a song.")

    loglines = follow(logfile)

    for line in loglines:

            if trigger in line:
                    skip_song()

            logging.debug(line.replace("\n",""))

[philippe44]

I've released 0.212 which make LMS fail when such issue occurs and it should move to next track automatically

[ElFishi]

I am closing this as 212 likely solves the issue. I've been running Youtube/LMS for two weeks now and maaaayyyybe had one stop.