DVR suddenly stopping on Raspberry PI

Spoke too soon. Not working again. I noticed that I got the same message the other poster did that the update was ready (in my case 1701) and I needed to reboot. I did so and it's back to the old behavior. I did briefly get to a settings page and saw that it said the OS was up to date, but since then cannot go back to the settings page.

I'm trying to get it to generate diagnostic logs, but it won't complete. Here are the logs I can see starting with the downloading of new OS.

2021/04/28 10:15:19.853060 [SYS] Downloading new OS v2021.0428.1701
2021/04/28 10:15:22.233299 [SYS] Created database snapshot: backup-20210428.101521
2021/04/28 10:15:22.233967 [SYS] Removing old backup backup-20210415.103920
2021/04/28 10:15:43.178982 [SYS] Installing new OS v2021.0428.1701
2021/04/28 10:19:15.012707 [SYS] Starting Channels DVR v2021.04.22.1948 (linux-arm64 pid:830) in /mnt/data/channels-dvr/data
2021/04/28 10:19:15.302836 [SYS] Started HTTP Server
2021/04/28 10:19:16.070850 [HDR] Found 0 devices
2021/04/28 10:19:20.209620 [DVR] Recording engine started in /media/DVR
2021/04/28 10:19:20.444842 [SYS] Bonjour service running for dvr-server.local. [192.168.1.110]
2021/04/28 10:19:20.528572 [DVR] Skipping job 1619640000-33 Good Witch
2021/04/28 10:19:20.528652 [DVR] Waiting 4h40m39.471361176s until next job 1619647200-15 The Love Boat
2021/04/28 10:19:31.492478 [IDX] Pruned 0 expired airings from X-LOCAST in 48.95616ms.
2021/04/28 10:19:31.531250 [IDX] Pruned 1 expired airings from X-TVE in 38.561337ms.
2021/04/28 10:19:36.379725 [SYS] Created database snapshot: backup-20210428.101935
2021/04/28 10:19:36.380374 [SYS] Removing old backup backup-20210416.103930
2021/04/28 10:22:26.778852 [SYS] Shutting down...
2021/04/28 10:22:26.780117 [SYS] Bonjour service stopped.
2021/04/28 10:22:26.788895 [DVR] Recording engine stopped.
2021/04/28 10:22:27.789239 [SYS] Goodbye.
2021/04/28 10:22:32.247665 [SYS] Starting Channels DVR v2021.04.22.1948 (linux-arm64 pid:305) in /mnt/data/channels-dvr/data
2021/04/28 10:22:32.524633 [SYS] Started HTTP Server
2021/04/28 10:22:32.544432 [SYS] Waiting on dependencies network-online.target time-sync.target
2021/04/28 10:22:36.019731 [SYS] Waiting on dependencies time-sync.target
2021/04/28 10:23:25.982867 [SYS] Done waiting on dependencies
2021/04/28 10:23:26.421564 [HDR] Found 0 devices
2021/04/28 10:23:36.568684 [DVR] Recording engine started in /media/DVR
2021/04/28 10:23:36.570653 [SYS] Bonjour service running for dvr-server.local. [192.168.1.110]
2021/04/28 10:23:37.362629 [DVR] Skipping job 1619640000-33 Good Witch
2021/04/28 10:23:37.363091 [DVR] Waiting 4h36m22.637173542s until next job 1619647200-15 The Love Boat
2021/04/28 10:23:47.422811 [IDX] Pruned 0 expired airings from X-LOCAST in 20.386519ms.
2021/04/28 10:23:47.428140 [IDX] Pruned 0 expired airings from X-TVE in 4.934518ms.
2021/04/28 10:23:51.563487 [SYS] Created database snapshot: backup-20210428.102351
2021/04/28 10:23:51.564058 [SYS] Removing old backup backup-20210417.103940
2021/04/28 10:25:06.473817 [SYS] Starting Channels DVR v2021.04.22.1948 (linux-arm64 pid:307) in /mnt/data/channels-dvr/data
2021/04/28 10:25:06.645545 [SYS] Started HTTP Server
2021/04/28 10:25:06.670354 [SYS] Waiting on dependencies network-online.target time-sync.target
2021/04/28 10:25:10.480369 [SYS] Waiting on dependencies time-sync.target
2021/04/28 10:27:42.046211 [SYS] Done waiting on dependencies
2021/04/28 10:27:42.505398 [HDR] Found 0 devices
2021/04/28 10:27:49.835039 [DVR] Recording engine started in /media/DVR
2021/04/28 10:27:50.125440 [SYS] Bonjour service running for dvr-server.local. [192.168.1.110]
2021/04/28 10:27:50.214818 [DVR] Skipping job 1619640000-33 Good Witch
2021/04/28 10:27:50.215078 [DVR] Waiting 4h32m9.78496777s until next job 1619647200-15 The Love Boat
2021/04/28 10:28:11.448849 [IDX] Pruned 0 expired airings from X-LOCAST in 58.462185ms.
2021/04/28 10:28:11.572017 [IDX] Pruned 2 expired airings from X-TVE in 112.63387ms.
2021/04/28 10:29:21.807153 [SYS] Starting Channels DVR v2021.04.22.1948 (linux-arm64 pid:740) in /mnt/data/channels-dvr/data
2021/04/28 10:29:22.144953 [SYS] Started HTTP Server
2021/04/28 10:29:22.923816 [HDR] Found 0 devices
2021/04/28 10:29:26.089017 [DVR] Recording engine started in /media/DVR
2021/04/28 10:29:26.298080 [SYS] Bonjour service running for dvr-server.local. [192.168.1.110]
2021/04/28 10:29:26.381724 [DVR] Skipping job 1619640000-33 Good Witch
2021/04/28 10:29:26.381902 [DVR] Waiting 4h30m33.618122069s until next job 1619647200-15 The Love Boat
2021/04/28 10:29:38.923588 [IDX] Pruned 0 expired airings from X-LOCAST in 78.207735ms.
2021/04/28 10:29:38.971138 [IDX] Pruned 1 expired airings from X-TVE in 47.383528ms.
2021/04/28 10:29:43.927630 [SYS] Created database snapshot: backup-20210428.102943
2021/04/28 10:29:43.928540 [SYS] Removing old backup backup-20210418.103950
2021/04/28 10:31:10.649487 [SYS] Starting Channels DVR v2021.04.22.1948 (linux-arm64 pid:795) in /mnt/data/channels-dvr/data
2021/04/28 10:31:10.948518 [SYS] Started HTTP Server
2021/04/28 10:31:11.779465 [HDR] Found 0 devices
2021/04/28 10:31:16.101217 [DVR] Recording engine started in /media/DVR
2021/04/28 10:31:16.324447 [DVR] Skipping job 1619640000-33 Good Witch
2021/04/28 10:31:16.324521 [DVR] Waiting 4h28m43.675493203s until next job 1619647200-15 The Love Boat
2021/04/28 10:31:16.327312 [SYS] Bonjour service running for dvr-server.local. [192.168.1.110]
2021/04/28 10:31:26.771446 [IDX] Pruned 16 expired airings from X-LOCAST in 63.954851ms.
2021/04/28 10:31:26.919629 [IDX] Pruned 31 expired airings from X-TVE in 147.989468ms.
2021/04/28 10:31:29.356619 [SYS] Created database snapshot: backup-20210428.103128
2021/04/28 10:31:29.357767 [SYS] Removing old backup backup-20210419.104001
2021/04/28 10:32:36.986338 [TRS] DNS: OK: Resolved host via system DNS
2021/04/28 10:32:38.515553 [TRS] Cloud Reachable: OK: Connected to community.getchannels.com
2021/04/28 10:32:38.633166 [TRS] Local Time: OK: Local clock is accurate
2021/04/28 10:32:38.633404 [TRS] Remote Access: OK: Remote access not configured
2021/04/28 10:32:38.798468 [TRS] Disk Permissions: OK

it still just stops once it gets to the "Removing Old backup" place

When its stuck are you able to SSH in or ping the Pi?

Is the settings page loading partially or not at all?

Yes, I can SSH into it.

The settings page is accessible very briefly at reboot, but once it gets to that Removing Old Backup place, I can't access it. I can access the logs in support, but I can't generate the diagnostic logs. I tried to generate this logs during that brief window but they never completed.

I'm still not sure what you mean by "can't access" settings. What exactly does it show in the browser? Is it a browser error? Or does part of the page load and then there's a spinner?

Does systemctl status channels-dvr show it as running?

It seems normal for the output to stop after 'Removing old backup'. That's what I see too, that's the last thing that happens after a successful boot up.

Yes, the menu is across the top but there is a spinning icon below.

I ran that command and it says Channels is active.

Edit to add: restarted another time and it's working for the moment. I submitted the logs in case. 013eb9f7-21d3-4394-b306-af09dd96378b

Okay please open http://x.x.x.x:8089/debug/stack and file>save then email to [email protected]

it appears for the moment to be working again after another reboot so I was able to generate the diagnostics.

013eb9f7-21d3-4394-b306-af09dd96378b

It appears that the linux OOM killer is kicking in for some reason.

[   89.686745] channels-dvr invoked oom-killer: gfp_mask=0x6200ca(GFP_HIGHUSER_MOVABLE), nodemask=(null), order=0, oom_score_adj=-500
[   89.686771] channels-dvr cpuset=/ mems_allowed=0
[   89.686790] CPU: 3 PID: 366 Comm: channels-dvr Tainted: G         C O      4.19.127-v8 #1
[   89.686800] Hardware name: Raspberry Pi 4 Model B Rev 1.2 (DT)
[   89.686808] Call trace:
[   89.686821]  dump_backtrace+0x0/0x170
[   89.686830]  show_stack+0x24/0x30
[   89.686842]  dump_stack+0xa8/0xdc
[   89.686851]  dump_header+0x64/0x244
[   89.686858]  oom_kill_process+0xe4/0x350
[   89.686866]  out_of_memory+0xf8/0x300
[   89.686873]  __alloc_pages_nodemask+0x7f4/0xdc0
[   89.686883]  __handle_mm_fault+0x348/0xb70
[   89.686891]  handle_mm_fault+0x134/0x210
[   89.686900]  do_page_fault+0x150/0x4c0
[   89.686909]  do_translation_fault+0xa4/0xb4
[   89.686917]  do_mem_abort+0x68/0x110
[   89.686924]  el0_da+0x20/0x24
[   89.686931] Mem-Info:
[   89.686944] active_anon:699138 inactive_anon:141109 isolated_anon:18
                active_file:637 inactive_file:531 isolated_file:26
                unevictable:0 dirty:0 writeback:0 unstable:0
                slab_reclaimable:5661 slab_unreclaimable:11228
                mapped:50 shmem:17 pagetables:2620 bounce:0
                free:4858 free_pcp:0 free_cma:645
[   89.686972] Node 0 active_anon:2796552kB inactive_anon:564436kB active_file:2548kB inactive_file:2124kB unevictable:0kB isolated(anon):72kB isolated(file):104kB mapped:200kB dirty:0kB writeback:0kB shmem:68kB writeback_tmp:0kB unstable:0kB all_unreclaimable? yes
[   89.686994] DMA32 free:13312kB min:1580kB low:2348kB high:3116kB active_anon:783908kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:916480kB managed:835388kB mlocked:0kB kernel_stack:0kB pagetables:1460kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:2580kB
[   89.687011] lowmem_reserve[]: 0 2936 2936
[   89.687027] Normal free:6120kB min:6188kB low:9192kB high:12196kB active_anon:2012496kB inactive_anon:564200kB active_file:2672kB inactive_file:1676kB unevictable:0kB writepending:0kB present:3080192kB managed:3007228kB mlocked:0kB kernel_stack:2672kB pagetables:9020kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[   89.687045] lowmem_reserve[]: 0 0 0
[   89.687056] DMA32: 54*4kB (UEC) 44*8kB (UEC) 13*16kB (UEC) 15*32kB (UEC) 10*64kB (UEC) 6*128kB (UEC) 6*256kB (UEC) 2*512kB (E) 2*1024kB (UE) 1*2048kB (C) 1*4096kB (E) = 13416kB
[   89.687098] Normal: 97*4kB (UME) 43*8kB (UME) 22*16kB (UM) 11*32kB (UME) 13*64kB (UM) 36*128kB (UME) 1*256kB (E) 0*512kB 0*1024kB 0*2048kB 0*4096kB = 7132kB
[   89.687131] 1297 total pagecache pages
[   89.687140] 10 pages in swap cache
[   89.687148] Swap cache stats: add 241319, delete 241399, find 0/1433
[   89.687155] Free swap  = 0kB
[   89.687162] Total swap = 960652kB
[   89.687168] 999168 pages RAM
[   89.687175] 0 pages HighMem/MovableOnly
[   89.687182] 38514 pages reserved
[   89.687189] 16384 pages cma reserved
[   89.687196] Tasks state (memory values in pages):
[   89.687203] [  pid  ]   uid  tgid total_vm      rss pgtables_bytes swapents oom_score_adj name
[   89.687229] [    116]     0   116    17318        7    94208      147          -250 systemd-journal
[   89.687242] [    126]     0   126     2495       11    45056      273         -1000 systemd-udevd
[   89.687257] [    301]  1008   301     3656      209    57344      690             0 systemd-resolve
[   89.687269] [    302]  1009   302    58231        0    73728      188             0 systemd-timesyn
[   89.687281] [    307]   501   307  1549238   837295  9170944   232309          -500 channels-dvr
[   89.687292] [    308]  1002   308     1417        5    40960      157          -900 dbus-daemon
[   89.687303] [    309]     0   309    59815        4    86016      370             0 NetworkManager
[   89.687315] [    313]     0   313    59138        2    77824      311             0 rauc
[   89.687326] [    315]     0   315    74587        0    61440       67             0 rngd
[   89.687337] [    320]     0   320     2386        0    45056      122             0 wpa_supplicant
[   89.687349] [    321] 61623   321      514        5    32768       23             0 wsdd2
[   89.687360] [    328]     0   328     1966        0    40960      105             0 systemd-logind
[   89.687372] [    349]     0   349      681        0    32768       27             0 dropbear
[   89.687383] [    353]     0   353      519        2    32768       22             0 agetty
[   89.687395] [    402]     0   402   297716     1409   303104     1746          -500 dockerd
[   89.687406] [    404]     0   404     6857        0    86016      452             0 nmbd
[   89.687417] [    433]     0   433     9592       78   102400      558             0 winbindd
[   89.687428] [    457]     0   457     9697       20   102400      589             0 winbindd
[   89.687440] [    458]     0   458    11075       14   118784      652             0 smbd
[   89.687451] [    463]     0   463    10597        0   106496      622             0 smbd-notifyd
[   89.687462] [    464]     0   464    10597        0   106496      622             0 cleanupd
[   89.687473] [    466]     0   466     9556       58    98304      547             0 winbindd
[   89.687485] [    470]     0   470     9559       78    98304      538             0 winbindd
[   89.687496] [    473]     0   473   254508      856   221184      605          -500 containerd
[   89.687507] Out of memory: Kill process 307 (channels-dvr) score 392 or sacrifice child
[   89.687553] Killed process 307 (channels-dvr) total-vm:6196952kB, anon-rss:3349180kB, file-rss:0kB, shmem-rss:0kB
[   90.569037] oom_reaper: reaped process 307 (channels-dvr), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB

Is that something I can address? I'm running the image and haven't even tried to add Pluto or anything like that.

I'm not quite sure what's going on yet. It says the DVR is using 3.3GB of RAM which doesn't make any sense.

The diagnostics I got was right after kill/restart, and it was only using a little bit.

Maybe you can run htop over SSH and watch if the memory keeps growing, and then submit diagnostics when its around 1GB or 2GB before it gets killed.

1 Like

In case this ends up being relevant, @tmm1, this is the same drive as the one I had all of the problems with, which have all gone away with the 4 TB version.

I was out today and of course the DVR seems to have a crashed a few times and I couldn't be here to check the memory.

One weird thing is when I came home, the settings page was doing the "menu on top + spinner" thing but it seems to still be recording a show - I was able to go to the library via the web browser and play the show as it recorded (note: my apps cannot find the DVR server).

Also, saw this in the logs, which seemed new:

2021/04/28 18:00:04.184083 [ERR] Recovered from panic: assertion failed: write: circular dependency occurred
github.com/fancybits/channels-server/dvr.(*Recorder).RunRecorder.func3()
:568
github.com/fancybits/channels-server/dvr.(*Job).Run()
:347
github.com/fancybits/channels-server/tuner.NewStream()
:146
github.com/fancybits/channels-server/tve.(*Channel).Stream()
:187
github.com/fancybits/channels-server/tve.(*client).Stream()
:1055
github.com/fancybits/channels-server/tve.(*client).PlaybackURL()
:920
github.com/fancybits/channels-server/tve.(*discoveryClient).resolveURL()
:219
github.com/fancybits/channels-server/tve.(*client).discoveryAuth()
:770
github.com/fancybits/channels-server/tve.(*client).cacheSet()
:1009
github.com/fancybits/channels-server/settings.Set()
:130
github.com/tmm1/buckets.(*Bucket).Put()
:68
github.com/etcd-io/bbolt.(*DB).Update()
:701
github.com/etcd-io/bbolt.(*Tx).Commit()
:160
github.com/etcd-io/bbolt.(*Bucket).spill()
:537
github.com/etcd-io/bbolt.(*Bucket).spill()
:570
github.com/etcd-io/bbolt.(*node).spill()
:346
github.com/etcd-io/bbolt.(*node).spill()
:374
github.com/etcd-io/bbolt.(*node).write()
:233
github.com/etcd-io/bbolt._assert()
:1172

I will try to watch memory tomorrow.

OK, on reboot, it cycled through at least two RAM death spirals. I missed the first but was able to capture logs on the next when it was using over 3GB. I emailed the logs in. Thanks.

It seems like your settings.db has become corrupted somehow through all the reboots.

Maybe you can use the backup restore to pull an older one?

Is there a process for doing that if I can't load the settings page?

I think unfortunately it deletes an old db backup every time it restarts so on the system itself there's nothing very old, but on my backup drive of the entire DVR I have one from last Thursday that was before the first time it crashed.

You can try loading http://x:8089/restore and do it from there.

Or it might be simplest over SSH:

cd /mnt/data/channels-dvr/data
mv settings.db settings.db.corrupt
cp /media/DVR/Database/backup-X/settings.db .
systemctl restart channels-dvr

Does the cp command need a destination after it - like mnt//data/channels-dvr/data/settings.db ? When I copy that command and run, I get a list of options for using cp

there is a dot at the end meaning copy into current folder

1 Like

Thanks for the help. It seems to be working normally again. Fingers crossed.

1 Like