Home of the Squeezebox™ & Transporter® network music players.
Page 5 of 7 FirstFirst ... 34567 LastLast
Results 41 to 50 of 67
  1. #41
    Senior Member
    Join Date
    Oct 2005
    Location
    Ireland
    Posts
    19,946
    Quote Originally Posted by mrw View Post
    I will look further at the processing. I was asking myself: "What might happen if the stream 'restarts from scratch' for some reason when we're in the middle of processing the icy metadata ? Could we end up breaking the icy metadata filter ?". Would require examination of the code. And understanding what icy is supposed to look like.
    Icy is straight forward - it is a chunk of data every so many characters in the streams - the size is defined in header icy-metadataint. So http processing will get a chunk of data and then pass it to icy processing. Generically it should be a series of <parametername>=<value> - so if icy processing is flexible it'll ignore "unknown" parameter names and just use StreamTitle and StreamURL.

    If stream restarts - no matter. icy data counter will restart. If processing icy data then it will already be complete. If icy data is incomplete it should be discarded with http restart.

    If there is a chance to fix this - ideally the code has to be in Lua and not in C. I think we should lob the issue to Ralphy and the community radio thread and get their opinion - if only to be able to better instrument "audio_thread_execute" line 849 and 1053 and paths to those lines.

  2. #42
    Senior Member
    Join Date
    Jan 2010
    Location
    Hertfordshire
    Posts
    5,814
    12 hours now with no issues, time to turn it off.

    Sent from my Pixel 3a using Tapatalk

  3. #43
    Junior Member
    Join Date
    Oct 2009
    Posts
    26
    Quote Originally Posted by bpa View Post
    Is there metadata shown at the time of night ? Program title , images etc.

    "night" is a bit vague - is it early night 8pm-10pm or late 10pm-2am ?

    I can run my Radio on the LBC to see if it is reproducible but (i) I'm not sure whether non UK stream will be the same as UK (ii) narrowing down a time might indicate the issue (e.g. some station load balance / reduce capacity at night when there are fewer listeners) or possibly program related - metadata change if feed joins a syndicated service (e.g.IIRC R4 after midnight joins World service)
    Usually between 10pm and 11pm GMT.

    Switched the radio to :

    http://media-ice.musicradio.com/ClassicFMMP3.m3u

    earlier this morning, logged in via ssh and recorded the following from /var/log/messages. The radio crashes/rebooted at 13:55 but did not resume the stream (which is what usually happens):

    Code:
    tail -f messages
    Nov 30 11:33:16 squeezeplay: INFO   audio.decode - Playback.lua:476 connect *.*.*.*:80 GET /ClassicFMMP3 HTTP/1.0^M
    Nov 30 11:33:16 squeezeplay: INFO   audio.decode - Playback.lua:479 GET /ClassicFMMP3 HTTP/1.0^M
    Nov 30 11:33:16 squeezeplay: Accept: */*^M
    Nov 30 11:33:16 squeezeplay: Cache-Control: no-cache^M
    Nov 30 11:33:16 squeezeplay: User-Agent: iTunes/4.7.1 (Unix; N; linux; x86_64-linux; EN; utf8) SqueezeNetwork/7.7.7-sn/TRUNK^M
    Nov 30 11:33:16 squeezeplay: Icy-MetaData: 1^M
    Nov 30 11:33:16 squeezeplay: Connection: close^M
    Nov 30 11:33:16 squeezeplay: Host: media-ice.musicradio.com^M
    Nov 30 11:33:16 squeezeplay: ^M
    Nov 30 11:33:17 squeezeplay: INFO   applet.NowPlaying - NowPlayingApplet.lua:422 enable volume UI in NP
    Nov 30 11:34:18 squeezeplay: WARN   net.thread - NetworkThread.lua:146 network thread timeout for Task(SocketHttp {mysqueezebox.com_Request}(R))
    Nov 30 11:35:03 squeezeplay: INFO   applet.NowPlaying - NowPlayingApplet.lua:422 enable volume UI in NP
    Nov 30 11:35:18 squeezeplay: INFO   applet.NowPlaying - NowPlayingApplet.lua:422 enable volume UI in NP
    Nov 30 11:36:04 squeezeplay: INFO   squeezeplay.applets - AppletManager.lua:708 store settings: Playback
    Nov 30 11:37:00 squeezeplay: WARN   net.thread - NetworkThread.lua:146 network thread timeout for Task(SocketHttp {mysqueezebox.com_Request}(R))
    Nov 30 11:38:31 squeezeplay: INFO   applet.NowPlaying - NowPlayingApplet.lua:422 enable volume UI in NP
    .
    .
    
    Nov 30 13:48:29 squeezeplay: INFO   applet.NowPlaying - NowPlayingApplet.lua:422 enable volume UI in NP
    Nov 30 13:49:01 squeezeplay: INFO   applet.NowPlaying - NowPlayingApplet.lua:422 enable volume UI in NP
    Nov 30 13:53:27 squeezeplay: INFO   applet.NowPlaying - NowPlayingApplet.lua:422 enable volume UI in NP
    Nov 30 13:53:56 squeezeplay: INFO   applet.NowPlaying - NowPlayingApplet.lua:422 enable volume UI in NP
    Nov 30 13:55:27 squeezeplay: audio_thread_execute:849 exit, parent is dead
    Nov 30 13:55:27 squeezeplay: audio_thread_execute:1053 Audio thread exited
    Nov 30 13:55:30 watchdog[688]: pinging process 747 (/var/run/squeezeplay.pid) gave errno = 3 = 'No such process'
    Nov 30 13:55:31 root: watchdog error 3
    Nov 30 13:55:31 root: 7.7.3 r16676 root@ec2mbubld01.idc.logitech.com Fri Feb 14 09:25:26 PST 2014 Base build revision: bad080aecfec8226a4c1699b29d32cbba4ba396b
    Nov 30 13:55:31 root: 13:55:31 up 11 days, 15:13, load average: 0.75, 0.96, 0.80
    Nov 30 13:55:31 root:   PID   TID CLS RTPRIO %CPU %MEM    VSZ   RSS WCHAN           COMMAND
    Nov 30 13:55:31 root:     1     1 TS       -  0.0  0.9   2792   584 wait            init
    Nov 30 13:55:31 root:     2     2 TS       -  0.0  0.0      0     0 kthreadd        kthreadd
    Nov 30 13:55:31 root:     3     3 FF      98  0.0  0.0      0     0 posix_cpu_timer posixcputmr/0
    Nov 30 13:55:31 root:     4     4 FF      40  0.0  0.0      0     0 ksoftirqd       sirq-high/0
    Nov 30 13:55:31 root:     5     5 FF      40  0.3  0.0      0     0 ksoftirqd       sirq-timer/0
    Nov 30 13:55:31 root:     6     6 FF      40  0.0  0.0      0     0 ksoftirqd       sirq-net-tx/0
    Nov 30 13:55:31 root:     7     7 FF      40  0.0  0.0      0     0 ksoftirqd       sirq-net-rx/0
    Nov 30 13:55:31 root:     8     8 FF      40  0.0  0.0      0     0 ksoftirqd       sirq-block/0
    Nov 30 13:55:31 root:     9     9 FF      88  1.3  0.0      0     0 ksoftirqd       sirq-tasklet/0
    Nov 30 13:55:31 root:    10    10 FF      40  0.0  0.0      0     0 ksoftirqd       sirq-sched/0
    Nov 30 13:55:31 root:    11    11 FF      40  0.0  0.0      0     0 ksoftirqd       sirq-hrtimer/0
    Nov 30 13:55:31 root:    12    12 FF      40  0.0  0.0      0     0 ksoftirqd       sirq-rcu/0
    Nov 30 13:55:31 root:    13    13 TS       -  0.0  0.0      0     0 -               desched/0
    Nov 30 13:55:31 root:    14    14 TS       -  0.0  0.0      0     0 rcu_sched_grace rcu_sched_grace
    Nov 30 13:55:31 root:    15    15 FF       1  0.0  0.0      0     0 worker_thread   events/0
    Nov 30 13:55:31 root:    16    16 TS       -  0.0  0.0      0     0 worker_thread   khelper
    Nov 30 13:55:31 root:    41    41 FF      90  0.5  0.0      0     0 irqd            IRQ-34
    Nov 30 13:55:31 root:    67    67 TS       -  0.0  0.0      0     0 worker_thread   kblockd/0
    Nov 30 13:55:31 root:    70    70 TS       -  0.0  0.0      0     0 worker_thread   cqueue
    Nov 30 13:55:31 root:    78    78 FF      40  0.0  0.0      0     0 irqd            IRQ-3
    Nov 30 13:55:31 root:    81    81 FF      40  0.0  0.0      0     0 irqd            IRQ-4
    Nov 30 13:55:31 root:    85    85 TS       -  0.0  0.0      0     0 worker_thread   kmmcd
    Nov 30 13:55:31 root:   110   110 FF       1  0.0  0.0      0     0 krcupreemptd    krcupreemptd
    Nov 30 13:55:31 root:   111   111 TS       -  0.0  0.0      0     0 pdflush         pdflush
    Nov 30 13:55:31 root:   112   112 TS       -  0.0  0.0      0     0 pdflush         pdflush
    Nov 30 13:55:31 root:   113   113 TS       -  0.0  0.0      0     0 kswapd          kswapd0
    Nov 30 13:55:31 root:   114   114 TS       -  0.0  0.0      0     0 worker_thread   aio/0
    Nov 30 13:55:31 root:   115   115 TS       -  0.0  0.0      0     0 worker_thread   unionfs_siod/0
    Nov 30 13:55:31 root:   120   120 FF      40  0.0  0.0      0     0 irqd            IRQ-39
    Nov 30 13:55:31 root:   244   244 FF      40  0.0  0.0      0     0 irqd            IRQ-57
    Nov 30 13:55:31 root:   247   247 TS       -  0.0  0.0      0     0 -               mtdblockd
    Nov 30 13:55:31 root:   248   248 FF      40  0.0  0.0      0     0 irqd            IRQ-33
    Nov 30 13:55:31 root:   280   280 TS       -  0.0  0.0      0     0 ubi_thread      ubi_bgt0d
    Nov 30 13:55:31 root:   285   285 FF      40  0.0  0.0      0     0 irqd            IRQ-24
    Nov 30 13:55:31 root:   291   291 FF      40  0.0  0.0      0     0 irqd            IRQ-168
    Nov 30 13:55:31 root:   292   292 FF      40  0.0  0.0      0     0 irqd            IRQ-167
    Nov 30 13:55:31 root:   293   293 FF      40  0.0  0.0      0     0 irqd            IRQ-64
    Nov 30 13:55:31 root:   300   300 FF      40  0.0  0.0      0     0 irqd            IRQ-182
    Nov 30 13:55:31 root:   304   304 FF      40  0.0  0.0      0     0 irqd            IRQ-46
    Nov 30 13:55:31 root:   306   306 FF      40  0.0  0.0      0     0 irqd            IRQ-9
    Nov 30 13:55:31 root:   319   319 FF      40  0.0  0.0      0     0 irqd            IRQ-12
    Nov 30 13:55:31 root:   327   327 FF      40  0.0  0.0      0     0 irqd            IRQ-166
    Nov 30 13:55:31 root:   331   331 FF      50  0.0  0.0      0     0 hrtimer_nanosle loadavg
    Nov 30 13:55:31 root:   335   335 FF      40  0.0  0.0      0     0 irqd            IRQ-32
    Nov 30 13:55:31 root:   345   345 TS       -  0.0  0.0      0     0 ubifs_bg_thread ubifs_bgt0_2
    Nov 30 13:55:31 root:   382   382 TS       -  0.0  1.0   2036   656 select          udevd
    Nov 30 13:55:31 root:   656   656 TS       -  0.0  0.8   2800   508 -               syslogd
    Nov 30 13:55:31 root:   665   665 TS       -  0.0  0.7   2792   484 syslog          klogd
    Nov 30 13:55:31 root:   688   688 RR       1  0.0  2.8   1816  1756 wait            watchdog
    Nov 30 13:55:31 root:   690   690 TS       -  0.2  0.4   1624   300 hrtimer_nanosle monitor_msp430
    Nov 30 13:55:31 root:   696   696 TS       -  0.0  0.9   2876   608 select          inetd
    Nov 30 13:55:31 root:   706   706 TS       -  0.0  0.0      0     0 compat_down_int AR6K Async
    Nov 30 13:55:31 root:   734   734 FF       1  0.0  0.0      0     0 sdio_irq_thread ksdiorqd
    Nov 30 13:55:31 root:   739   739 TS       -  0.0  0.7   2092   488 select          wpa_supplicant
    Nov 30 13:55:31 root:   741   741 TS       -  0.0  0.3   1816   228 select          wpa_cli
    Nov 30 13:55:31 root:   748   748 TS       -  0.0  0.3   2792   204 read_chan       init
    Nov 30 13:55:31 root:   750   750 TS       -  0.0  1.0   2796   636 read_chan       getty
    Nov 30 13:55:31 root:   784   784 TS       -  0.0  0.8   2792   512 select          udhcpc
    Nov 30 13:55:31 root:  5325  5325 TS       -  0.0  1.7   2584  1100 select          dropbear
    Nov 30 13:55:31 root:  5327  5327 TS       -  0.0  1.0   2796   668 wait            sh
    Nov 30 13:55:31 root:  5429  5429 TS       -  0.0  0.7   2792   476 -               tail
    Nov 30 13:55:31 root:  7130  7130 RR       1  0.0  0.8   2792   536 wait            repair.sh
    Nov 30 13:55:31 root:  7136  7136 RR       1  0.0  0.8   2792   508 wait            psall
    Nov 30 13:55:31 root:  7137  7137 RR       1  0.0  0.8   2796   532 -               logger
    Nov 30 13:55:31 root:  7138  7138 RR       1  0.0  1.2   2248   752 -               ps
    Nov 30 13:55:33 watchdog[688]: repair binary returned 3
    Nov 30 13:55:33 watchdog[688]: shutting down the system because of error 3
    LMS Version 8.0.0 running on OSX
    Classic White, Classic Black, Radio , Raspberry Pi +IQAudio, 2 x Raspberry Pi

  4. #44
    Senior Member
    Join Date
    May 2010
    Location
    London, UK
    Posts
    709
    Quote Originally Posted by bpa View Post
    I think we should lob the issue to Ralphy and the community radio thread and get their opinion - if only to be able to better instrument "audio_thread_execute" line 849 and 1053 and paths to those lines.
    Thanks for Icy comments. The error messages that you describe are emitted by jive_alsa, in response to its discovery that its parent process, jive, is already dead. So nothing to be gained there, I think. I'm considering what trace debug lines might be added to jive itself to assist.

    Quote Originally Posted by drbob49 View Post
    Switched the radio to :

    http://media-ice.musicradio.com/ClassicFMMP3.m3u

    earlier this morning, logged in via ssh and recorded the following from /var/log/messages. The radio crashes/rebooted at 13:55 but did not resume the stream (which is what usually happens):
    By contrast, the LBC stream that started at 04:56:41 yesterday continued unimpeded for about 30 hours, without any interruption, until I turned it off this morning. I restarted later this morning, during which time the stream has restarted itself twice due to audio under-run, but without causing any issue. (Attempts at rebuffering failed, I assume that the remote server would have "gone away").

    So this is not going to be easy to track down. Perhaps I'll switch from LBC to ClassicFM, at least that gives me soothing music.

  5. #45
    Senior Member
    Join Date
    May 2010
    Location
    London, UK
    Posts
    709
    Quote Originally Posted by mrw View Post
    Perhaps I'll switch from LBC to ClassicFM, at least that gives me soothing music.
    Well, that did the trick. I was rewarded with:
    Code:
    jive: src/audio/streambuf.c:382: streambuf_icy_filter: Assertion `r == icy_len' failed.
    at about 3.30 in the morning. Source code: https://github.com/Logitech/squeezep...reambuf.c#L382
    Edit: This message does not show up in the system log, it is spat out of jive's STDERR handle.

    I believe that there is a defect in the code here, but that must wait further examination and testing with a suitably modified jive binary.

    In the meantime, the only way to proceed, I think, is to turn off Icy metadata capturing altogether. That would require a tweak to LMS, or perhaps the lua source code on the Radio.

    I'm not sure what the best approach for an ordinary user would be.

  6. #46
    Senior Member
    Join Date
    Oct 2005
    Location
    Ireland
    Posts
    19,946
    Quote Originally Posted by mrw View Post
    Well, that did the trick. I was rewarded with:
    Code:
    jive: src/audio/streambuf.c:382: streambuf_icy_filter: Assertion `r == icy_len' failed.
    at about 3.30 in the morning. Source code: https://github.com/Logitech/squeezep...reambuf.c#L382
    Edit: This message does not show up in the system log, it is spat out of jive's STDERR handle.

    I believe that there is a defect in the code here, but that must wait further examination and testing with a suitably modified jive binary.

    In the meantime, the only way to proceed, I think, is to turn off Icy metadata capturing altogether. That would require a tweak to LMS, or perhaps the lua source code on the Radio.

    I'm not sure what the best approach for an ordinary user would be.
    IIRC When a stream is proxied, icy metatada is filtered by LMS - so that maybe the workaround (or a way to confirm icy is the issue)

    Disable icy in jive in the player means user will lose all icy metadata from all streams played directly .

    I should think a patch for Touch should be possible, if the issues is something like "unexpected" icy parameters (i.e. not StreamTitle and StreamURL) and/or with unusual/confusing values.
    The problem could be in 2nd part of icy processing where icy metadata from a direct stream is sent back to LMS to display

    Again the Community Radio guys might be able to help out - especially as it seem this problem affects a few stations. Might be a cause of some reboots which were blamed on other things.

  7. #47
    Senior Member
    Join Date
    May 2010
    Location
    London, UK
    Posts
    709
    Quote Originally Posted by bpa View Post
    I should think a patch for Touch should be possible, if the issues is something like "unexpected" icy parameters (i.e. not StreamTitle and StreamURL) and/or with unusual/confusing values.
    The problem with this particular failed assertion is, I suspect, this: streambuf_fast_read will not return all available data if the relevant icy data is wrapped around in the fifo buffer. A second read is required in those circumstances. And the code only attempts one read. That's my 'defect'.

    Which is not to say that "unexpected" icy parameters will not break things elsewhere, or that a duff icy metadata length byte wouldn't equally create difficulty.

    I noticed that the ClassicFM and LBC streams can produce some relatively large icy metadata when a track changes, or in other circumstances:
    Code:
    Dec  1 03:28:53 squeezeplay: DEBUG  audio.decode - streambuf_icy_filter:383 got icy metadata: StreamTitle='Leo Delibes - Sylvia - Valse Lente';StreamUrl='';track_info='k4Smc3RhdHVzoUihQM5fxbhnpHR5cGWhVKJpZKY0MDI1MDSEpnN0YXR1c6FDoUDOX8W57KR0eXBloVSiaWSmNDU4NDc2hKZzdGF0dXOhQ6FAzl/FuuikdHlwZaFUomlkpjQwNDM1OA==';UTC='20201201T032839.656';
    
    Nov 29 14:32:01 squeezeplay: DEBUG  audio.decode - streambuf_icy_filter:383 got icy metadata: StreamTitle='';StreamUrl='ADBREAK_LENGTH_229999:0851508063&ClashCodes={}';UTC='20201129T143125.424';
    So the odds of either of these streams triggering this assertion failure is somewhat greater than a stream that is more modest in its icy metadata offering. And it's not helpful that an assert failure message ends up discarded through STDERR, I would think better redirected to the system logger, at least pro-tem.

    Quote Originally Posted by bpa View Post
    Again the Community Radio guys might be able to help out - especially as it seem this problem affects a few stations.
    I'll share my findings with @ralphy. I'll have to fire up my SqueezeOS build system and test more rigorously - it lives somewhere in Amazon.

    Quote Originally Posted by bpa View Post
    Might be a cause of some reboots which were blamed on other things.
    Agree.

  8. #48
    Senior Member
    Join Date
    May 2010
    Location
    London, UK
    Posts
    709
    I used to play the Classic FM stream quite a lot in the past (2/3 years ago ?), but I never noticed this problem.
    I wonder what icy metadata was supplied then.

  9. #49
    Senior Member
    Join Date
    Oct 2005
    Location
    Ireland
    Posts
    19,946
    Quote Originally Posted by mrw View Post
    I used to play the Classic FM stream quite a lot in the past (2/3 years ago ?), but I never noticed this problem.
    I wonder what icy metadata was supplied then.
    I think icy is being used to help support "ads" in some way and this is a new use - rather than just Streamtitle and StreamURL.

    I may do a test of LBC "proxied" to see if it breaks. Synced players are also effectively proxied and so icy would never get to the players.

  10. #50
    Senior Member
    Join Date
    Jan 2010
    Location
    Hertfordshire
    Posts
    5,814
    Quote Originally Posted by bpa View Post
    I think icy is being used to help support "ads" in some way and this is a new use - rather than just Streamtitle and StreamURL.

    I may do a test of LBC "proxied" to see if it breaks. Synced players are also effectively proxied and so icy would never get to the players.
    I started playing Classic FM hours ago and the playing time in the now playing screen is 41 minutes. So I thought it must have rebooted but the Radio uptime is currently over 8 days. What happened there?

    Sent from my Pixel 3a using Tapatalk

Tags for this Thread

Posting Permissions

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