Announcement

Collapse
No announcement yet.

Radio station stops playing

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

    Originally posted by bpa View Post
    IIRC Players never really log "rebufferting" - they show DECODE_UNDERRUN or AUDIO_UNDERRUN. I think audio,.output to DEBUG may log those.

    If you enable LMS player.source to INFO - the "Buffering... " message indicate rebuffering and also player stated will go into REBUFFERING. The log "rebuffering failed" event precedes stopping a playing stream (i.e. giving up).

    MPD internal buffer may be bigger than Touch and so can ride out the lumpiness of the stream.
    I noticed your player logs had normal human readable timestamps whereas mine had Unix Epoch times, how did you achieve that?

    Sent from my Pixel 3a using Tapatalk
    Living Room: Touch or Squeezelite (Pi3B) > Topping E30 > Audiolab 8000A > Monitor Audio S5 + BK200-XLS DF
    Bedroom: Radio
    Bathroom: Radio

    Comment


      Originally posted by slartibartfast View Post
      I noticed your player logs had normal human readable timestamps whereas mine had Unix Epoch times, how did you achieve that?
      Did nothing. Not sure which player logs as I had squeezeplay and Radio going.

      Radio is latest f/w.

      I think the squeezeplay is an oldish build - 8.0.1. r1340

      Comment


        Originally posted by bpa View Post
        Did nothing. Not sure which player logs as I had squeezeplay and Radio going.

        Radio is latest f/w.

        I think the squeezeplay is an oldish build - 8.0.1. r1340
        Are you still testing the stream after the reencoding of the Station IDs?

        Sent from my Pixel 3a using Tapatalk
        Living Room: Touch or Squeezelite (Pi3B) > Topping E30 > Audiolab 8000A > Monitor Audio S5 + BK200-XLS DF
        Bedroom: Radio
        Bathroom: Radio

        Comment


          Originally posted by bpa View Post
          IIRC Players never really log "rebufferting" - they show DECODE_UNDERRUN or AUDIO_UNDERRUN. I think audio,.output to DEBUG may log those.

          If you enable LMS player.source to INFO - the "Buffering... " message indicate rebuffering and also player stated will go into REBUFFERING. The log "rebuffering failed" event precedes stopping a playing stream (i.e. giving up).

          MPD internal buffer may be bigger than Touch and so can ride out the lumpiness of the stream.
          I think when the Touch stopped I couldn't resume playback by clicking "play", I had to click "next". Does that mean anything?

          Sent from my Pixel 3a using Tapatalk
          Living Room: Touch or Squeezelite (Pi3B) > Topping E30 > Audiolab 8000A > Monitor Audio S5 + BK200-XLS DF
          Bedroom: Radio
          Bathroom: Radio

          Comment


            Originally posted by slartibartfast View Post
            I think when the Touch stopped I couldn't resume playback by clicking "play", I had to click "next". Does that mean anything?
            Not sure what happens in "error" stop conditions. It could depend on whether you are playing - the streaming URL or the playlist URL - as "next" would imply - next track in playlist.
            playlist - http://www.deliciousagony.com/listen.pls
            streamign - http://deliciousagony.streamguys1.com/

            Comment


              Originally posted by bpa View Post
              Not sure what happens in "error" stop conditions. It could depend on whether you are playing - the streaming URL or the playlist URL - as "next" would imply - next track in playlist.
              playlist - http://www.deliciousagony.com/listen.pls
              streamign - http://deliciousagony.streamguys1.com/
              I am not sure what happened here but 04.32 was the last timestamp of a track on the Touch that stopped playing. I then started playing the Touch and the mpd player at 06.48 and the Touch stopped at 07.49 while the mpd player continued. I started the Touch an mpd player again at 09.06 then started squeezeplay at 10.44. They all continued to play until 13.50 when they all stopped but the Touch screen stayed on.
              At around 14.15 I finally realised that all the players had stopped and also realised that LMS, although still active had lost contact with the players and controllers, Then I restarted LMS.
              Here is the server log from that period. It looks like Delicious Agony went offline at 04.31 when the Touch stopped so that probably explains why it stopped at a time which was not a Stream ID. I don't know what happened at 07.49 when the Touch stopped or what was going on at 10.48 when the log shows issues but playback seems to continue. LMS crashing remains a mystery and the log contains nothing until I restart LMS.

              Code:
              [22-06-28 04:31:03.9817] Slim::Player::Protocols::HTTP::__ANON__ (497) cannot open session for http://deliciousagony.streamguys1.com/ 404 Not Available 
              [22-06-28 04:31:04.2306] Slim::Player::Protocols::HTTP::__ANON__ (497) cannot open session for http://deliciousagony.streamguys1.com/ 404 Not Available 
              [22-06-28 04:31:04.8854] Slim::Player::Protocols::HTTP::new (56) Couldn't create socket binding to  - 
              [22-06-28 04:31:04.8862] Slim::Player::Song::open (499) Warning: stream failed to open [http://deliciousagony.streamguys1.com/].
              [22-06-28 04:31:09.3285] Slim::Player::Protocols::HTTP::new (56) Couldn't create socket binding to  - 
              [22-06-28 04:31:09.3293] Slim::Player::Song::open (499) Warning: stream failed to open [http://deliciousagony.streamguys1.com/].
              [22-06-28 04:31:19.5268] Slim::Player::Protocols::HTTP::new (56) Couldn't create socket binding to  - 
              [22-06-28 04:31:19.5276] Slim::Player::Song::open (499) Warning: stream failed to open [http://deliciousagony.streamguys1.com/].
              [22-06-28 04:31:34.3057] Slim::Player::Protocols::HTTP::new (56) Couldn't create socket binding to  - 
              [22-06-28 04:31:34.3065] Slim::Player::Song::open (499) Warning: stream failed to open [http://deliciousagony.streamguys1.com/].
              [22-06-28 08:24:42.4846] Slim::Networking::Repositories::__ANON__ (147) Failed to fetch https://sourceforge.net/projects/lms-plugins-philippe44/files/dev/repo-sf.xml: Connect timed out: Resource temporarily unavailable
              [22-06-28 10:47:59.3919] Slim::Player::Protocols::HTTP::__ANON__ (497) cannot open session for http://deliciousagony.streamguys1.com/ 404 Not Available 
              [22-06-28 10:47:59.4235] Slim::Player::Protocols::HTTP::__ANON__ (497) cannot open session for http://deliciousagony.streamguys1.com/ 404 Not Available 
              [22-06-28 10:47:59.4327] Slim::Player::Protocols::HTTP::__ANON__ (497) cannot open session for http://deliciousagony.streamguys1.com/ 404 Not Available 
              [22-06-28 10:47:59.7961] Slim::Player::Protocols::HTTP::__ANON__ (497) cannot open session for http://deliciousagony.streamguys1.com/ 404 Not Available 
              [22-06-28 10:47:59.8042] Slim::Player::Protocols::HTTP::__ANON__ (497) cannot open session for http://deliciousagony.streamguys1.com/ 404 Not Available 
              [22-06-28 10:47:59.8310] Slim::Player::Protocols::HTTP::__ANON__ (497) cannot open session for http://deliciousagony.streamguys1.com/ 404 Not Available 
              [22-06-28 10:48:00.3957] Slim::Player::Protocols::HTTP::new (56) Couldn't create socket binding to  - 
              [22-06-28 10:48:00.3965] Slim::Player::Song::open (499) Warning: stream failed to open [http://deliciousagony.streamguys1.com/].
              [22-06-28 10:48:02.8752] Slim::Player::Protocols::HTTP::new (56) Couldn't create socket binding to  - 
              [22-06-28 10:48:02.8760] Slim::Player::Song::open (499) Warning: stream failed to open [http://deliciousagony.streamguys1.com/].
              [22-06-28 10:48:05.2351] Slim::Player::Protocols::HTTP::new (56) Couldn't create socket binding to  - 
              [22-06-28 10:48:05.2359] Slim::Player::Song::open (499) Warning: stream failed to open [http://deliciousagony.streamguys1.com/].
              [22-06-28 10:48:07.3681] Slim::Player::Protocols::HTTP::new (56) Couldn't create socket binding to  - 
              [22-06-28 10:48:07.3689] Slim::Player::Song::open (499) Warning: stream failed to open [http://deliciousagony.streamguys1.com/].
              [22-06-28 10:48:09.2939] Slim::Player::Protocols::HTTP::new (56) Couldn't create socket binding to  - 
              [22-06-28 10:48:09.2947] Slim::Player::Song::open (499) Warning: stream failed to open [http://deliciousagony.streamguys1.com/].
              [22-06-28 10:48:14.3454] Slim::Player::Protocols::HTTP::new (56) Couldn't create socket binding to  - 
              [22-06-28 10:48:14.3462] Slim::Player::Song::open (499) Warning: stream failed to open [http://deliciousagony.streamguys1.com/].
              [22-06-28 10:48:15.2368] Slim::Player::Protocols::HTTP::new (56) Couldn't create socket binding to  - 
              [22-06-28 10:48:15.2376] Slim::Player::Song::open (499) Warning: stream failed to open [http://deliciousagony.streamguys1.com/].
              [22-06-28 10:48:17.3426] Slim::Player::Protocols::HTTP::new (56) Couldn't create socket binding to  - 
              [22-06-28 10:48:17.3436] Slim::Player::Song::open (499) Warning: stream failed to open [http://deliciousagony.streamguys1.com/].
              [22-06-28 10:48:24.2293] Slim::Player::Protocols::HTTP::new (56) Couldn't create socket binding to  - 
              [22-06-28 10:48:24.2302] Slim::Player::Song::open (499) Warning: stream failed to open [http://deliciousagony.streamguys1.com/].
              [22-06-28 10:48:30.2486] Slim::Player::Protocols::HTTP::new (56) Couldn't create socket binding to  - 
              [22-06-28 10:48:30.2494] Slim::Player::Song::open (499) Warning: stream failed to open [http://deliciousagony.streamguys1.com/].
              [22-06-28 10:48:32.2073] Slim::Player::Protocols::HTTP::new (56) Couldn't create socket binding to  - 
              [22-06-28 10:48:32.2081] Slim::Player::Song::open (499) Warning: stream failed to open [http://deliciousagony.streamguys1.com/].
              [22-06-28 10:48:39.2068] Slim::Player::Protocols::HTTP::new (56) Couldn't create socket binding to  - 
              [22-06-28 10:48:39.2076] Slim::Player::Song::open (499) Warning: stream failed to open [http://deliciousagony.streamguys1.com/].
              Living Room: Touch or Squeezelite (Pi3B) > Topping E30 > Audiolab 8000A > Monitor Audio S5 + BK200-XLS DF
              Bedroom: Radio
              Bathroom: Radio

              Comment


                Originally posted by slartibartfast View Post
                I am not sure what happened here but 04.32 was the last timestamp of a track on the Touch that stopped playing. I then started playing the Touch and the mpd player at 06.48 and the Touch stopped at 07.49 while the mpd player continued. I started the Touch an mpd player again at 09.06 then started squeezeplay at 10.44. They all continued to play until 13.50 when they all stopped but the Touch screen stayed on.
                At around 14.15 I finally realised that all the players had stopped and also realised that LMS, although still active had lost contact with the players and controllers, Then I restarted LMS.
                Here is the server log from that period. It looks like Delicious Agony went offline at 04.31 when the Touch stopped so that probably explains why it stopped at a time which was not a Stream ID. I don't know what happened at 07.49 when the Touch stopped or what was going on at 10.48 when the log shows issues but playback seems to continue. LMS crashing remains a mystery and the log contains nothing until I restart LMS.
                How long had the stream been running when it stopped at 4.32 ? Some services "reset" connections that to have been playing for "too long".

                That said, the 404 error seems to indicate that the whole service went offline for a while.
                DNS works but binding error usually means there is no TCP service on port 80 on the ip address - so it looks like a system crash but the streamguys status page shows no issues.

                Comment


                  Originally posted by bpa View Post
                  How long had the stream been running when it stopped at 4.32 ? Some services "reset" connections that to have been playing for "too long".

                  That said, the 404 error seems to indicate that the whole service went offline for a while.
                  DNS works but binding error usually means there is no TCP service on port 80 on the ip address - so it looks like a system crash but the streamguys status page shows no issues.
                  Around 6 hours nothing excessive, the website had been down just before I started playing. When I mentioned it on Facebook Messenger they told me the site was down and to play the stream from TuneIn. I explained I was in the UK so that wasn't going to work. Around 5 or minutes later I got another message saying the site was up again. I wonder if the site went down again at 4.32.

                  Sent from my Pixel 3a using Tapatalk
                  Living Room: Touch or Squeezelite (Pi3B) > Topping E30 > Audiolab 8000A > Monitor Audio S5 + BK200-XLS DF
                  Bedroom: Radio
                  Bathroom: Radio

                  Comment


                    Originally posted by bpa View Post
                    IIRC Players never really log "rebufferting" - they show DECODE_UNDERRUN or AUDIO_UNDERRUN. I think audio,.output to DEBUG may log those.

                    If you enable LMS player.source to INFO - the "Buffering... " message indicate rebuffering and also player stated will go into REBUFFERING. The log "rebuffering failed" event precedes stopping a playing stream (i.e. giving up).

                    MPD internal buffer may be bigger than Touch and so can ride out the lumpiness of the stream.
                    I witnessed both Jive players rebuffering for a while but playback did eventually continue.

                    Sent from my Pixel 3a using Tapatalk
                    Living Room: Touch or Squeezelite (Pi3B) > Topping E30 > Audiolab 8000A > Monitor Audio S5 + BK200-XLS DF
                    Bedroom: Radio
                    Bathroom: Radio

                    Comment


                      I started playing on Squeezeplay at 3pm and playback stopped at around 10.35pm. I selected debug logging for audio.codec and audio.output and this is the complete log from squeezeplay with no entries after 3pm.

                      Code:
                      1656409264.672 DEBUG  audio.output - decode_portaudio_init:651 Portaudio version v19.1246976
                      1656409264.672 INFO   audio.output - get_padevice_id:556 Using device 3. Primary Sound Driver (Windows DirectSound)
                      1656409264.672 INFO   audio.output - decode_portaudio_init:682 Using latency 0.240000
                      1656409264.840 INFO   audio.output - get_padevice_maxrate:630 Setting maximum samplerate to 192000
                      1656409264.840 DEBUG  audio.output - decode_portaudio_openstream:403 Using sample rate 44100
                      1656409264.840 DEBUG  audio.output - decode_portaudio_openstream:406 Using latency 0.240000
                      1656409264.876 DEBUG  audio.output - decode_portaudio_openstream:445 Stream latency 0.240000
                      1656409264.876 DEBUG  audio.output - decode_portaudio_openstream:446 Stream samplerate 44100.000000
                      1656409267.855 DEBUG  audio.output - callback:118 pa status 4
                      1656409267.855 DEBUG  audio.output - callback:118 pa status 4
                      1656409267.855 DEBUG  audio.output - callback:118 pa status 4
                      1656409267.855 DEBUG  audio.output - callback:118 pa status 4
                      1656409267.855 DEBUG  audio.output - callback:118 pa status 4
                      1656409267.855 DEBUG  audio.output - callback:118 pa status 4
                      1656409267.855 DEBUG  audio.output - callback:118 pa status 4
                      1656409267.855 DEBUG  audio.output - callback:118 pa status 4
                      1656409267.855 DEBUG  audio.output - callback:118 pa status 4
                      1656409267.855 DEBUG  audio.output - callback:118 pa status 4
                      1656409267.856 DEBUG  audio.output - callback:118 pa status 4
                      1656409267.856 DEBUG  audio.output - callback:118 pa status 4
                      1656409267.856 DEBUG  audio.output - callback:118 pa status 4
                      1656409464.255 DEBUG  audio.output - decode_portaudio_stop:365 decode_portaudio_stop
                      1656409465.246 DEBUG  audio.codec - decode_mad_start:520 decode_mad_start()
                      1656409465.246 DEBUG  audio.output - decode_portaudio_start:347 decode_portaudio_start
                      1656409465.335 DEBUG  audio.codec - xing_parse:79 no xing header
                      1656409465.335 DEBUG  audio.codec - decode_mad_output:413 Skip encoder_delay=529 pcm->length=1152 offset=529
                      1656409665.372 DEBUG  audio.codec - decode_mad_stop:548 decode_mad_stop()
                      1656409665.372 DEBUG  audio.output - decode_portaudio_stop:365 decode_portaudio_stop
                      1656409665.992 DEBUG  audio.codec - decode_mad_start:520 decode_mad_start()
                      1656409665.992 DEBUG  audio.output - decode_portaudio_start:347 decode_portaudio_start
                      1656409667.660 DEBUG  audio.codec - xing_parse:79 no xing header
                      1656409667.661 DEBUG  audio.codec - decode_mad_output:413 Skip encoder_delay=529 pcm->length=1152 offset=529
                      1656409681.373 DEBUG  audio.codec - decode_mad_output:481 Reached end of stream
                      1656409681.398 DEBUG  audio.codec - decode_mad_stop:548 decode_mad_stop()
                      1656409741.711 DEBUG  audio.codec - decode_mad_start:520 decode_mad_start()
                      1656409741.711 DEBUG  audio.output - decode_portaudio_start:347 decode_portaudio_start
                      1656409741.785 DEBUG  audio.codec - xing_parse:84 xing magic 496e666f
                      1656409741.785 DEBUG  audio.codec - xing_parse:99 xing frames: 15424
                      1656409741.785 DEBUG  audio.codec - xing_parse:137 lame magic 4c414d45 bitlen 2016
                      1656409741.785 DEBUG  audio.codec - xing_parse:162 encoder delay=1105 padding=923
                      1656409741.785 DEBUG  audio.codec - xing_parse:163 total LAME samples 17768448
                      1656409741.785 DEBUG  audio.codec - decode_mad_output:413 Skip encoder_delay=1105 pcm->length=1152 offset=1105
                      1656410134.783 DEBUG  audio.codec - decode_mad_output:430 Removing encoder padding, lame_samples_remain=229
                      1656410134.783 DEBUG  audio.codec - decode_mad_output:430 Removing encoder padding, lame_samples_remain=0
                      1656410134.783 DEBUG  audio.codec - decode_mad_output:430 Removing encoder padding, lame_samples_remain=0
                      1656410134.783 DEBUG  audio.codec - decode_mad_output:439 Decoded more samples (17770752) than expected (0), assuming invalid LAME header and ignoring padding
                      1656422206.503 DEBUG  audio.codec - decode_mad_output:481 Reached end of stream
                      1656422206.537 DEBUG  audio.codec - decode_mad_stop:548 decode_mad_stop()
                      1656422206.538 DEBUG  audio.output - decode_portaudio_stop:365 decode_portaudio_stop
                      1656424850.203 DEBUG  audio.output - decode_portaudio_stop:365 decode_p
                      Living Room: Touch or Squeezelite (Pi3B) > Topping E30 > Audiolab 8000A > Monitor Audio S5 + BK200-XLS DF
                      Bedroom: Radio
                      Bathroom: Radio

                      Comment


                        Originally posted by slartibartfast View Post
                        I witnessed both Jive players rebuffering for a while but playback did eventually continue.
                        Just for clarity - the Rebuffering messages displayed on a player are under the direction of LMS when LMS has been told by the player about decoder or audio underrun (e.g. Slimproto message STMd I think)

                        Comment


                          Originally posted by slartibartfast View Post
                          I started playing on Squeezeplay at 3pm and playback stopped at around 10.35pm. I selected debug logging for audio.codec and audio.output and this is the complete log from squeezeplay with no entries after 3pm.
                          I've been using Squeezeplay on Linux which AFAICT doesn't use PortAudio (I.e. it looks like ALSA) so I'm not sure if underrun or other error messages are directly comparable.

                          It looks itis reporting that some data was "lost" and so MP3 frames are are undecodeable but perhaps this is due to Portaudio handling errors differently

                          Comment


                            Originally posted by bpa View Post
                            I've been using Squeezeplay on Linux which AFAICT doesn't use PortAudio (I.e. it looks like ALSA) so I'm not sure if underrun or other error messages are directly comparable.

                            It looks itis reporting that some data was "lost" and so MP3 frames are are undecodeable but perhaps this is due to Portaudio handling errors differently
                            I have definitely seen the expected audio.decode debug messages previously so no idea what happened this time.

                            Sent from my Pixel 3a using Tapatalk
                            Living Room: Touch or Squeezelite (Pi3B) > Topping E30 > Audiolab 8000A > Monitor Audio S5 + BK200-XLS DF
                            Bedroom: Radio
                            Bathroom: Radio

                            Comment


                              I have a small dumb program which just reads the stream in icy-metaint size chunks (i.e about 16000 bytes), looks for metadata and chops the remaining audio into files whenever it sees metadata.
                              Chunks normally arrive about 1 per sec (16000*8 = 128000bits so 128kbits/sec) but some take longer - the stream is lumpy.

                              The stream is read with blocking reads (i.e. it waits for complete 16000 bytes or full metdata string) - very occasionally, maybe once per long session - it just hangs, program waits for the chunk but no more data. I'm sure if I did a "non-blocking" read with proper error management, I could get an error code.

                              Summary, I think it is still a streaming problem with this station and it will stop every so often

                              Comment


                                Originally posted by bpa View Post
                                I have a small dumb program which just reads the stream in icy-metaint size chunks (i.e about 16000 bytes), looks for metadata and chops the remaining audio into files whenever it sees metadata.
                                Chunks normally arrive about 1 per sec (16000*8 = 128000bits so 128kbits/sec) but some take longer - the stream is lumpy.

                                The stream is read with blocking reads (i.e. it waits for complete 16000 bytes or full metdata string) - very occasionally, maybe once per long session - it just hangs, program waits for the chunk but no more data. I'm sure if I did a "non-blocking" read with proper error management, I could get an error code.

                                Summary, I think it is still a streaming problem with this station and it will stop every so often
                                Here is a squeezeplay log where playback stopped. Does it mean anything?

                                Code:
                                1656528254.316 DEBUG  audio.decode - :451 31.7%/99.8%
                                1656528255.444 DEBUG  audio.decode - :451 31.6%/100.0%
                                1656528256.525 DEBUG  audio.decode - :451 31.6%/100.0%
                                1656528257.765 DEBUG  audio.decode - :451 31.4%/99.4%
                                1656528258.812 DEBUG  audio.decode - :451 31.8%/99.8%
                                1656528259.892 DEBUG  audio.decode - :451 31.7%/99.3%
                                1656528261.016 DEBUG  audio.decode - :451 31.6%/99.8%
                                1656528262.096 DEBUG  audio.decode - :451 31.6%/99.9%
                                1656528263.176 DEBUG  audio.decode - :451 31.8%/99.4%
                                1656528264.211 DEBUG  audio.decode - :451 31.6%/99.4%
                                1656528265.292 DEBUG  audio.decode - :451 31.7%/99.2%
                                1656528266.416 DEBUG  audio.decode - :451 31.7%/99.9%
                                1656528267.496 DEBUG  audio.decode - :451 31.7%/99.8%
                                1656528268.503 DEBUG  audio.decode - :451 31.6%/100.0%
                                1656528269.571 DEBUG  audio.decode - :451 31.7%/99.8%
                                1656528270.606 DEBUG  audio.decode - :451 31.6%/99.9%
                                1656528271.747 DEBUG  audio.decode - :451 31.4%/99.9%
                                1656528272.650 DEBUG  audio.decode - :858 strm q
                                1656528272.650 DEBUG  audio.decode - :1265 stopping local pause timer
                                1656528272.650 DEBUG  audio.decode - decode_stop:664 decode_stop
                                1656528272.650 DEBUG  audio.decode - :194 source=off
                                1656528272.650 DEBUG  audio.decode - :754 disconnect streambuf
                                1656528272.650 DEBUG  audio.decode - decode_stop_handler:190 decode_stop_handler
                                1656528272.650 DEBUG  audio.codec - decode_mad_stop:548 decode_mad_stop()
                                1656528273.219 DEBUG  audio.decode - :1265 stopping local pause timer
                                1656528273.219 DEBUG  audio.decode - :1195 gainL, gainR: 15
                                Living Room: Touch or Squeezelite (Pi3B) > Topping E30 > Audiolab 8000A > Monitor Audio S5 + BK200-XLS DF
                                Bedroom: Radio
                                Bathroom: Radio

                                Comment

                                Working...
                                X