tvheadend player crashed LibreElec10

ciclista71 · March 10, 2022 at 3:57 PM

Hi,

I have an Rpi4 with the latest LE 10.0.1 and tvheadend server 4.3.1979

I recorded a video, yesterday evening, and it all went well till I decided to start watching it (while it was still being recorded).

This is how it went:

Recording started at 21:30 and should have finished at 00:30

Code

Mar 09 21:09:30 LibreELEC tvheadend[9167]: dvr: "CLV-2022-03-09-21:10" on "Rai 3 HD" recorder starting

At 22:10 or so I ssh'ed to LE to check some files and folders, and a few minutes later I also connected to the web interface of TVH because I was mistakenly recording twice the same video, so I stopped the automatic EPG recording and let the manual recording proceed. This all happened over WiFi, no issues

At 22:44 I decided to play the video, so I sat in front on my TV, went to the LiveTV section of my LE, went to recordings, and played the file.

Code

2022-03-09 22:44:14.748 T:817 INFO <general>: VideoPlayer::OpenFile: pvr://recordings/tv/active/CLV-2022-03-09-21_10/CLV-2022-03-09-21%3a10 (1969), TV%20(Rai%203%20HD), 20220309_201000, 1367281094.pvr
2022-03-09 22:44:15.037 T:17827 INFO <general>: CDVDVideoCodecDRMPRIME::Open - using decoder V4L2 mem2mem H.264 decoder wrapper
2022-03-09 22:44:15.078 T:17828 INFO <general>: Creating audio stream (codec id: 86019, channels: 2, sample rate: 48000, no pass-through)
2022-03-09 22:44:21.079 T:817 INFO <general>: Display resolution ADJUST : 1920x1080 @ 50.000000 Hz (21) (w3ight: -1458166273442578432.000)

Note that at that time I don't see any clear message from TVH, just the below (I was expecting to see the hello message from the TVH server):

Code

Mar 09 22:43:52 LibreELEC tvheadend[9167]: http: 127.0.0.1: HTTP/1.1 HEAD (2) /imagecache/524 -- 404
Mar 09 22:43:52 LibreELEC tvheadend[9167]: http: 127.0.0.1: HTTP/1.1 HEAD (2) /imagecache/525 -- 404
Mar 09 22:43:52 LibreELEC tvheadend[9167]: http: 127.0.0.1: HTTP/1.1 HEAD (2) /imagecache/529 -- 404
Mar 09 22:43:52 LibreELEC tvheadend[9167]: http: 127.0.0.1: HTTP/1.1 HEAD (2) /imagecache/528 -- 404
Mar 09 22:43:52 LibreELEC tvheadend[9167]: http: 127.0.0.1: HTTP/1.1 HEAD (2) /imagecache/344 -- 404
Mar 09 22:43:52 LibreELEC tvheadend[9167]: http: 127.0.0.1: HTTP/1.1 HEAD (2) /imagecache/527 -- 404
Mar 09 22:43:52 LibreELEC tvheadend[9167]: http: 127.0.0.1: HTTP/1.1 HEAD (2) /imagecache/74 -- 404
Mar 09 22:44:06 LibreELEC tvheadend[9167]: http: 127.0.0.1: HTTP/1.1 HEAD (2) /imagecache/462 -- 404
Mar 09 22:44:08 LibreELEC tvheadend[9167]: http: 127.0.0.1: HTTP/1.1 HEAD (2) /imagecache/462 -- 404

It all went well until 22:59, when all of a sudden the video froze and I lost all kind of connections (connection to TVH and connection to the WiFi)

About one minute before everything crashed, I do see a connection from the client to the server (I don't understand why, since I was watching the video since 22:43)

Code

Mar 09 22:58:26 LibreELEC tvheadend[9167]: htsp: Got connection from 127.0.0.1
Mar 09 22:58:26 LibreELEC tvheadend[9167]: htsp: 127.0.0.1: Welcomed client software: Kodi Media Center (HTSPv34)
Mar 09 22:58:26 LibreELEC tvheadend[9167]: htsp: 127.0.0.1 [ Kodi Media Center ]: Identified as user 'tvheadend'
Mar 09 22:58:26 LibreELEC tvheadend[9167]: htsp: 127.0.0.1 [ tvheadend | Kodi Media Center ]: Privileges updated
Mar 09 22:59:40 LibreELEC tvheadend[9167]: mpegts: too much queued table input data (over 2MB) for Sony CXD2880 #0 : DVB-T #0, discarding new
Mar 09 22:59:50 LibreELEC tvheadend[9167]: mpegts: too much queued table input data (over 2MB) for Sony CXD2880 #0 : DVB-T #0, discarding new
Mar 09 23:00:00 LibreELEC tvheadend[9167]: mpegts: too much queued table input data (over 2MB) for Sony CXD2880 #0 : DVB-T #0, discarding new
Mar 09 23:00:10 LibreELEC tvheadend[9167]: htsp: 127.0.0.1 [ tvheadend | Kodi Media Center ]: Write error -- Broken pipe
Mar 09 23:00:10 LibreELEC tvheadend[9167]: htsp: 127.0.0.1 [ tvheadend | Kodi Media Center ]: Write error -- Broken pipe
Mar 09 23:00:10 LibreELEC tvheadend[9167]: htsp: 127.0.0.1 [ tvheadend | Kodi Media Center ]: Disconnected
Mar 09 23:00:10 LibreELEC tvheadend[9167]: subscription: 01E1: "HTSP" unsubscribing, hostname="127.0.0.1", username="tvheadend", client="Kodi Media Center"

Display More

So it looks like there was a connection and then kind of another one that made the entire system hang.

WiFi went down for a couple of seconds

Code

Mar 09 22:59:54 LibreELEC wpa_supplicant[510]: wlan0: CTRL-EVENT-DISCONNECTED bssid=dc:39:6f:f2:32:9d reason=2
Mar 09 22:59:59 LibreELEC wpa_supplicant[510]: wlan0: CTRL-EVENT-CONNECTED - Connection to dc:39:6f:f2:32:9d completed [id=0 id_str=]

but nevertheless, I couldn't SSH LE anymore, and also NFS connection went down (I save the videos to my NAS) - note that I could access my NAS from all other systems, meaning my WiFi was perfectly working and I saved other things from other systems to that very same NAS exactly during that time

Code

Mar 09 23:13:26 LibreELEC kernel: nfs: server 192.168.1.120 not responding, still trying
Mar 09 23:15:36 LibreELEC kernel: nfs: server 192.168.1.120 not responding, still trying

Mar 09 23:17:46 LibreELEC kernel: nfs: server 192.168.1.120 not responding, still trying
Mar 09 23:19:56 LibreELEC kernel: nfs: server 192.168.1.120 not responding, still trying
Mar 09 23:22:05 LibreELEC kernel: nfs: server 192.168.1.120 not responding, still trying
Mar 09 23:24:15 LibreELEC kernel: nfs: server 192.168.1.120 not responding, still trying
Mar 09 23:26:25 LibreELEC kernel: nfs: server 192.168.1.120 not responding, still trying
Mar 09 23:28:34 LibreELEC kernel: nfs: server 192.168.1.120 not responding, still trying
Mar 09 23:30:44 LibreELEC kernel: nfs: server 192.168.1.120 not responding, still trying
Mar 09 23:32:54 LibreELEC kernel: nfs: server 192.168.1.120 not responding, still trying
Mar 09 23:35:04 LibreELEC kernel: nfs: server 192.168.1.120 not responding, still trying
Mar 09 23:37:13 LibreELEC kernel: nfs: server 192.168.1.120 not responding, still trying
Mar 09 23:39:23 LibreELEC kernel: nfs: server 192.168.1.120 not responding, still trying
Mar 10 11:29:20 LibreELEC kernel: nfs: server 192.168.1.120 OK

Display More

At 00.43, system crashed. I had gone to sleep so I hadn't played with LE or with TVH since 23:15, more or less.

Code

Mar 10 00:42:38 LibreELEC tvheadend[9167]: mpegts: too much queued table input data (over 2MB) for Sony CXD2880 #0 : DVB-T #0, discarding new
Mar 10 00:42:48 LibreELEC tvheadend[9167]: mpegts: too much queued table input data (over 2MB) for Sony CXD2880 #0 : DVB-T #0, discarding new
Mar 10 00:43:45 LibreELEC kernel: kworker/u8:2 invoked oom-killer: gfp_mask=0x2dc2(GFP_KERNEL|__GFP_HIGHMEM|__GFP_NOWARN|__GFP_ZERO), order=0, oom_score_adj=0
Mar 10 00:43:45 LibreELEC kernel: CPU: 0 PID: 23182 Comm: kworker/u8:2 Tainted: G         C        5.10.76 #1
Mar 10 00:43:45 LibreELEC kernel: Hardware name: Raspberry Pi 4 Model B Rev 1.4 (DT)
Mar 10 00:43:45 LibreELEC kernel: Workqueue: brcmf_wq/mmc1:0001:1 brcmf_sdio_dataworker [brcmfmac]
Mar 10 00:43:45 LibreELEC kernel: Call trace:
Mar 10 00:43:45 LibreELEC kernel:  dump_backtrace+0x0/0x1e4
Mar 10 00:43:45 LibreELEC kernel:  show_stack+0x24/0x30
Mar 10 00:43:45 LibreELEC kernel:  dump_stack+0xf8/0x168
Mar 10 00:43:45 LibreELEC kernel:  dump_header+0x50/0x1e4
Mar 10 00:43:45 LibreELEC kernel:  oom_kill_process+0x228/0x230
Mar 10 00:43:45 LibreELEC kernel:  out_of_memory+0x1ec/0x34c
Mar 10 00:43:45 LibreELEC kernel:  __alloc_pages_slowpath.constprop.0+0x824/0xb20
Mar 10 00:43:45 LibreELEC kernel:  __alloc_pages_nodemask+0x28c/0x2e0
Mar 10 00:43:45 LibreELEC kernel:  __vmalloc_area_node+0x10c/0x270
Mar 10 00:43:45 LibreELEC kernel:  vzalloc+0xb8/0x130
Mar 10 00:43:45 LibreELEC kernel:  brcmf_sdio_dataworker+0x2158/0x25f0 [brcmfmac]
Mar 10 00:43:45 LibreELEC kernel:  process_one_work+0x1e8/0x45c
Mar 10 00:43:45 LibreELEC kernel:  worker_thread+0x78/0x4e4
Mar 10 00:43:45 LibreELEC kernel:  kthread+0x134/0x140
Mar 10 00:43:45 LibreELEC kernel:  ret_from_fork+0x10/0x38
Mar 10 00:43:45 LibreELEC kernel: Mem-Info:
Mar 10 00:43:45 LibreELEC kernel: active_anon:1648 inactive_anon:889462 isolated_anon:0
active_file:15 inactive_file:4728 isolated_file:96
unevictable:7338 dirty:0 writeback:818
slab_reclaimable:8185 slab_unreclaimable:10741
mapped:6306 shmem:10545 pagetables:2216 bounce:0
free:6886 free_pcp:162 free_cma:160
Mar 10 00:43:45 LibreELEC kernel: Node 0 active_anon:6592kB inactive_anon:3557848kB active_file:60kB inactive_file:18912kB unevictable:29352kB isolated(anon):0kB isolated(file):384kB mapped:25224kB dirty:0kB writeback:3272kB shmem:42180kB writeback_tmp:0kB kernel_stack:3440kB all_unreclaimable? yes
Mar 10 00:43:45 LibreELEC kernel: DMA free:15304kB min:3732kB low:4664kB high:5596kB reserved_highatomic:0KB active_anon:0kB inactive_anon:721640kB active_file:0kB inactive_file:7476kB unevictable:172kB writepending:0kB present:970752kB managed:885712kB mlocked:0kB pagetables:1384kB bounce:0kB free_pcp:120kB local_pcp:56kB free_cma:640kB
Mar 10 00:43:45 LibreELEC kernel: lowmem_reserve[]: 0 2929 2929 2929
Mar 10 00:43:45 LibreELEC kernel: DMA32 free:12240kB min:12648kB low:15808kB high:18968kB reserved_highatomic:0KB active_anon:6592kB inactive_anon:2836208kB active_file:60kB inactive_file:11308kB unevictable:29180kB writepending:2760kB present:3080192kB managed:2999448kB mlocked:0kB pagetables:7480kB bounce:0kB free_pcp:528kB local_pcp:252kB free_cma:0kB

Display More

System recovered by himself at 11:29 on the next day. My recording stopped at 23.09 (not at 00:30)

Code

2022-03-10 11:29:31.373 T:22867    INFO <general>: PVR Manager: Starting
2022-03-10 11:29:31.437 T:990      INFO <general>: AddOnLog: pvr.hts: Async updates initialised
2022-03-10 11:29:31.712 T:22872    INFO <general>: PVR Manager: Started

Code

Mar 10 00:43:00 LibreELEC tvheadend[9167]: mpegts: too much queued table input data (over 2MB) for Sony CXD2880 #0 : DVB-T #0, discarding new
Mar 10 11:29:23 LibreELEC systemd[1]: service.tvheadend43.service: Main process exited, code=killed, status=9/KILL
Mar 10 11:29:23 LibreELEC systemd[1]: service.tvheadend43.service: Failed with result 'signal'.
Mar 10 11:29:25 LibreELEC systemd[1]: service.tvheadend43.service: Scheduled restart job, restart counter is at 2.
Mar 10 11:29:25 LibreELEC tvheadend[22817]: main: Log started
Mar 10 11:29:25 LibreELEC tvheadend[22817]: http: Starting HTTP server 0.0.0.0:9981
Mar 10 11:29:25 LibreELEC tvheadend[22817]: htsp: Starting HTSP server 0.0.0.0:9982

It looks clear that as soon as I try to use the TVH Player, something breaks the system and everything collapses, but is there any other alternatives to play a recording?

I tried with another Kodi I have on my FireTV but I got various issues (can't FFW, for instance), so actually I don't know how to proceed.

I could just use the Rpi4 for the tvheadend server, but then I need some good players that can handle interlaced videos and .ts files that grow over time

Thanks for helping!

Luca

Mario77 · March 10, 2022 at 6:10 PM

ciclista71

Are you using the pass recording profile or you v been experimenting with other profiles?

ciclista71 · March 11, 2022 at 8:50 AM

I am using the pass, I tried with mkv as well but I didn't see great improvements

ciclista71 · March 31, 2022 at 4:36 PM

I did many changes, to try to improve the situation:

- I saw that the TVH Server had the pass stream set as default; I understood it should be set as htsp, so I changed that

- I disabled samba and disabled avahi

- I have removed many EPG updates not related to my country or providers (I just left OTA EPG)

I recorded my TV program and this part has always worked well. The duration of the recording is 220 minutes, so if I had had network issues I would have seen them. Instead, it all went well: no network errors, good upload bitrate, no CPU spikes, used MEM is good.

I have some "dropped in" errors, don't know what it is. This happens continuously, not only when I am recording.

Then, however, as soon as I start watching it, or maybe some time after (or when I go back and forth quickly with FFWD or FRWD, kodi hangs: NFS stops working, TVH server crashes, connmand removes IP routes and IP addresses, WiFi goes down, and for about 10 minutes everything gets stuck. If I go to the system menu and try to go down from Network to Storage, Kodi hangs and the remote also stops working. I will try to monitor that part as well, as soon as it happens (in a couple of days, I think, so as soon as I have time to watch the recorded program)

This only happens when I play a video, because every time I SSH, nothing happens: recording lasts for 220 minutes without issues. I changed many time the configuration of the TVH server with my browser and it all worked fine.

I really don't know where to look at, since kodi fails right when I need it.

WiFi is stable, I got just one disconnection (lasting 6 seconds) once in the last 24 hours

Code

Mar 31 04:53:11 LibreELEC wpa_supplicant[497]: wlan0: CTRL-EVENT-DISCONNECTED bssid=dc:39:6f: reason=2
Mar 31 04:53:17 LibreELEC wpa_supplicant[497]: wlan0: CTRL-EVENT-CONNECTED - Connection to dc:39:6f: completed [id=0 id_str=]

Note that during that time, TVH didn't notice any issues, no event is reported at 04:35 (I have activated debug=all in TVH server)

Code

2022-03-31 04:43:39.172 [   INFO]:epgdb: stored (size 490075)
2022-03-31 04:45:00.004 [  DEBUG]:epg: now/next 128803/122350 set on Rai Storia
2022-03-31 04:45:00.004 [  DEBUG]:epg: inform HTSP of now event change on Rai Storia
2022-03-31 04:45:00.004 [  DEBUG]:epg: arm channel timer @ 2022-03-31;05:40:00(+0200) for Rai Storia
2022-03-31 05:00:00.000 [  DEBUG]:epg: expire event 130648 (Tenn's: ATP 1000 Miami (diretta)) from Sky Sport Uno HD
2022-03-31 05:00:00.000 [  DEBUG]:epg: now/next 0/0 set on Sky Sport Uno HD
2022-03-31 05:00:00.000 [  DEBUG]:epg: inform HTSP of now event change on Sky Sport Uno HD

I will keep you posted.

ciclista71 · April 1, 2022 at 5:10 PM

I have just seen an interesting thing: my LibreELEC got disconnected from the network, BUT the events are strange:

I see the first errors in the logs at 17:39:07, with NFS that cannot be reached - there is nothing before this

Code

Apr 01 17:39:07 LibreELEC kernel: nfs: server 192.168.1.120 not responding, still trying

but I stop reporting data about my network at 17:35

During the hole (I send the data to an external server, so you don't see any data when the WiFi is down, but I also stored them in the LibreELEC) I don't see any errors in the interface (which is strange): err_in and err_out always report 0.

WiFi gets disconnected at 17:43:26 on the LibreELEC and at the same time I see a similar log in my router (it was the router to de-register the device)

WiFi is reestablished at 17:43:32, just 6 seconds later.

So it looks like there is a problem with the WiFi which is not detected by anyone until very late in some cases. This causes network drops and as soon as the WiFi is removed and re-added, it all works fine.

Maybe I could force a disconnection if I see problems? But how?

ciclista71 · February 5, 2023 at 8:07 PM

What I have seen is that there is a problem on the WiFi whenever I use it "heavily".

For instance, doing an scp on my mac from my Rpi4 in order to download a video file from my LE server made the wifi crash when transfer rate was 18%. And there is nothing I can do, it will always fail.

So I guess the problem is in the WiFi firmware

Code

Lucas-iMac:Movies luca$ scp root@192.168.1.143:/var/media/DVR/RegistrazioniTV/CLV/CLV2023-01-25.ts .
CLV2023-01-25.ts                                                                                                                                                                              18% 1448MB  28.9KB/s - stalled -client_loop: send disconnect: Broken pipe
scp: Connection closed