Tvheadend

Hi,

I have an Rpi4 running on the latest LibreELEC (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

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 and a few minutes later I also connected to the web interface of TVH and there were no issues at all.

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

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

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

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)
There is a connection from the client to the server about one minute before everything crashed (I don't understand why, since I was watching the video since 22:43)

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" 

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

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

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

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.

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

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

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
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.
Is there any extra log I can activate in order to better debug the system?

Thanks for helping!

Luca