Squeezebox Radios Reboots, with talk radio in the UK, cable connected , cable connect

[bpa]

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.

[slartibartfast]

12 hours now with no issues, time to turn it off.

Sent from my Pixel 3a using Tapatalk

[drbob49]

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):

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

[mrw]

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.

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.

[mrw]

Perhaps I'll switch from LBC to ClassicFM, at least that gives me soothing music.

Well, that did the trick. I was rewarded with:

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.

[bpa]

Well, that did the trick. I was rewarded with:

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.

[mrw]

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:

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.

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.

Might be a cause of some reboots which were blamed on other things.

Agree.

[mrw]

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.

[bpa]

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.

[slartibartfast]

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