Home of the Squeezebox™ & Transporter® network music players.
Page 12 of 14 FirstFirst ... 21011121314 LastLast
Results 111 to 120 of 137
  1. #111
    Senior Member
    Join Date
    Jan 2010
    Location
    Hertfordshire
    Posts
    9,630
    Quote 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/].

  2. #112
    Senior Member
    Join Date
    Oct 2005
    Location
    Ireland
    Posts
    21,884
    Quote 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.

  3. #113
    Senior Member
    Join Date
    Jan 2010
    Location
    Hertfordshire
    Posts
    9,630
    Quote 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

  4. #114
    Senior Member
    Join Date
    Jan 2010
    Location
    Hertfordshire
    Posts
    9,630
    Quote 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

  5. #115
    Senior Member
    Join Date
    Jan 2010
    Location
    Hertfordshire
    Posts
    9,630
    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

  6. #116
    Senior Member
    Join Date
    Oct 2005
    Location
    Ireland
    Posts
    21,884
    Quote 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)

  7. #117
    Senior Member
    Join Date
    Oct 2005
    Location
    Ireland
    Posts
    21,884
    Quote 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

  8. #118
    Senior Member
    Join Date
    Jan 2010
    Location
    Hertfordshire
    Posts
    9,630
    Quote 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

  9. #119
    Senior Member
    Join Date
    Oct 2005
    Location
    Ireland
    Posts
    21,884
    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

  10. #120
    Senior Member
    Join Date
    Jan 2010
    Location
    Hertfordshire
    Posts
    9,630
    Quote 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

Posting Permissions

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