SageTV / unraid server crashed today. Huge endless recording found.

[glenner]

Hey... So my unraid server was up and running well. uptime was at 20 days. Then today poof: it all crashed in a messy heap. It looked like this:

1. around 2pm this afternoon, I noticed my Logitech Media Center docker seemed to be down, as my Squeezebox displays around my house were offline (requires unraid to be online).
2. the unraid dashboard was offline.
3. I could ping the unraid server ip. but ssh/telnet to the same ip did not work.
4. my unraid server is in the basement and headless. I connect remotely via ssh. I did have an ssh window open overnight, and noticed some syslogd messages in the console shown below. I had dozens of these messages in the console starting around 4:37AM.
5. since I could not access the server via the UI or ssh, I did a hard reset on the box. Not sure what other options I have in this case. It has since powered up, and I've started the array. It forced me to start a parity check which will take 6 hours+.
6. at the time, I had only 7 dockers installed and all were running (delugevpn, crashplan, logictechmediaserver, plex, noip, sickrage, sagetv) and 1 windows 10 VM (which doesn't do much... I set it up last week to try).
7. on reboot, I got a warning that my cache is 72% used, which seemed high. My mover is set to run every 8 hours.
8. I started to look at my cache files to see where all the usage was going. I found a 114GB "Daily Show" recording. That's not right... It should be about <3-4GB as it is a 30 minute show. It looks like the recording never stopped. I also had a Jimmy Kimmel recording with some really weird characters in the filename. See screencap on google drive.

https://drive.google.com/open?id=0B-...DRfSkhrZjFRcFU

What should I look at? It looks like SageTV did not end the recording on schedule. And that actually crashed whole unraid server. Maybe the weird Jimmy Kimmel filenaming messed things up? It's all very weird...

Console messages I saw starting at 4:37am. I noticed that in my scheduler, I also have SSD trim set to run at 4:30am. Not sure if that is related. I'm not even clear what SSD trim does, but I saw in a video you are supposed to run it to improve performance.

root@unraid:/mnt/user/downloads/complete/My Downloads#
Message from syslogd@unraid at Aug  9 00:04:37 ...
 kernel:page:ffffea000e823b40 count:0 mapcount:0 mapping:          (null) index:                                                 0x1

Message from syslogd@unraid at Aug  9 00:04:37 ...
 kernel:flags: 0x200000000000014(referenced|dirty)

Message from syslogd@unraid at Aug  9 00:04:37 ...
 kernel:page:ffffea000e823b80 count:0 mapcount:0 mapping:          (null) index:                                                 0x1

Message from syslogd@unraid at Aug  9 00:04:37 ...
 kernel:flags: 0x200000000000014(referenced|dirty)

Message from syslogd@unraid at Aug  9 00:04:37 ...
 kernel:page:ffffea0015220000 count:0 mapcount:0 mapping:          (null) index:                                                 0x1

Message from syslogd@unraid at Aug  9 00:04:37 ...
 kernel:page:ffffea0015220040 count:0 mapcount:0 mapping:          (null) index:                                                 0x1

Message from syslogd@unraid at Aug  9 00:04:37 ...
 kernel:flags: 0x200000000000014(referenced|dirty)

Message from syslogd@unraid at Aug  9 00:04:37 ...
 kernel:page:ffffea0015220080 count:0 mapcount:0 mapping:          (null) index:                                                 0x1

Message from syslogd@unraid at Aug  9 00:04:37 ...
 kernel:flags: 0x200000000000014(referenced|dirty)

Message from syslogd@unraid at Aug  9 00:04:37 ...
 kernel:page:ffffea00152200c0 count:0 mapcount:0 mapping:          (null) index:                                                 0x1

Message from syslogd@unraid at Aug  9 00:04:37 ...
 kernel:flags: 0x200000000000014(referenced|dirty)

Message from syslogd@unraid at Aug  9 00:04:37 ...
 kernel:page:ffffea0015220100 count:0 mapcount:0 mapping:          (null) index:                                                 0x1

Message from syslogd@unraid at Aug  9 00:04:37 ...
 kernel:flags: 0x200000000000014(referenced|dirty)

Message from syslogd@unraid at Aug  9 00:04:37 ...
 kernel:page:ffffea0015220140 count:0 mapcount:0 mapping:          (null) index:                                                 0x1

[BobPhoenix]

An SSD trim operation simply clears (writes zeros) to sectors that are not being used. An SSD will just write data to new sectors and mark the old ones as available rather than re-write over the same sector. This prolongs the life of the SSD because they are only good for so many writes. Always writing to an empty sector spreads the writes out over the whole SSD.

My suggestion is to record directly to your array rather than to the SSD and see if that makes a difference. A side benefit is that this will prolong the life of the SSD but may not make a great difference so without your problems I would normally not recommend it.

If that works then you might add a spinner and mount it on your cache drive under the share directory name you are currently writing to now.

This is why I did this: I needed to write 30TB of data to my cache drive and then back to the array to consolidate the data on one drive. Having a series on a single drive lets me binge watch a series and only spin up a single drive. My cache drive is very small and would have greatly extended the time required to do this consolidation.

Here is the script I wrote to mount the drive on my cache I added an execute of this script to my GO file to mount it at every boot.

mkdir -p /mnt/cache/MediaCenter

mount -w -t xfs  /dev/disk/by-id/ata-Hitachi_HDS724040ALE640_PKV331P1GPJJAY-part1 /mnt/cache/MediaCenter 2>&1

[glenner]

Originally Posted by BobPhoenix

An SSD trim operation simply clears (writes zeros) to sectors that are not being used. An SSD will just write data to new sectors and mark the old ones as available rather than re-write over the same sector. This prolongs the life of the SSD because they are only good for so many writes. Always writing to an empty sector spreads the writes out over the whole SSD.

I see... I've looked up SSD trim, so makes sense now... In any event, I'm running trim daily at 4:30am on my unraid server. But I don't think the SSD trim has much to do with my server crash today. It seems like I have some errors in the SageTV log. Sage was recording 3 shows this morning around 12am (Kimmel, Colbert, and Daily Show). After rebooting from the crash, I foudn The Kimmel show on the filesytem with special characters in the filename (see screencap in initial post). The daily show recording ended up being 114GB on my cache drive (also in screenshot).

Originally Posted by BobPhoenix

My suggestion is to record directly to your array rather than to the SSD and see if that makes a difference. A side benefit is that this will prolong the life of the SSD but may not make a great difference so without your problems I would normally not recommend it.

Hmm... I could try that... but I thought most unraid/Sage users are recording to the cache drive for performance reasons? I have 4 tuners now on unraid, whereas I used to only have 2 tuners. It used to be I could not record 3 late night shows at the same time, whereas now I theoretically can. If all 4 tuners are recording, I think that works out to 24GB/hour disk writes to the cache. I'm not sure recording to a single data drive in the parity enabled array can support that? I'll need to try I guess.. So I may need to go back to 2 tuners, or somehow figure out how to get Sage to record to multiple data disks simultaneously.

Is there a way to tell Sage to record each tuner to a different data drive, or something similar?

...but again... looking at the Sage log which I'll post next, I'm not sure how my 114GB endless recording issue depends on recording to the cache vs. the array.

[glenner]

So here is my SageTV log. Things start to go south around Aug 9 12am. It is trying to record Kimmel, Daily Show, and Colbert on 3 tuners. All 3 shows overlap.

I'm not really sure how to read the Sage log, but I see errors like this:

Wed 8/9 0:05:00.975 [MsgManager@512dbad3] MAJOR Change to file format detected...reload any active media players using: MediaFile[id=7816535 A[7760623,7760021,"The Daily Show With Trevor Noah",44784@0809.00:05,32,T] mask=TV host=unraid encodedBy=HDHomeRun 1055a735 Tuner 0 CFTODT format=MPEG2-PS 0:00:00 2892 kbps [#0 Video[MPEG2-Video 29.97003 fps 1920x1080 16:9 interlaced id=e0]#1 Audio[AC3 48000 Hz 6 channels 384 kbps MAIN idx=1 id=bd-80010000 eng]#2 Audio[AC3 48000 Hz 2 channels 192 kbps idx=2 id=bd-81010000 enm]#3 Audio[AC3 48000 Hz 2 channels 192 kbps idx=3 id=bd-82010000 eng]] /var/media/tv/TheDailyShowWithTrevorNoah-TheRussianScandalTheCremeDeLaKremlin-7760623-0.mpg, Seg0[Wed 8/9 0:05:00.003-Wed 12/31 19:00:00.000]]

Wed 8/9 0:14:52.682 [FSManager@118cf00b] Async encoder halt detector found a halt; kick the Seeker so it can restart the device file=MediaFile[id=7816533 A[7806155,7806148,"Jimmy Kimmel Live",24052@0808.23:35,62,T] mask=TV host=unraid encodedBy=HDHomeRun 1017d94a Tuner 1 WKBWDT format=MPEG2-PS 0:00:00 3512 kbps [#0 Video[MPEG2-Video 59.94006 fps 1280x720 16:9 progressive id=e0]#1 Audio[AC3 48000 Hz 6 channels 384 kbps MAIN idx=1 id=bd-80010000 eng]#2 Audio[AC3 48000 Hz 2 channels 128 kbps idx=2 id=bd-81010000 spa]] /var/media/tv/JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-0.mpg, Seg0[Tue 8/8 23:35:00.003-Wed 8/9 0:04:37.878], Seg1[Wed 8/9 0:04:37.879-Wed 12/31 19:00:00.000]] size=640512810

Wed 8/9 0:20:13.649 [Seeker@43a32c4c] SEEKER HAS DETECTED A HALT IN THE ENCODER...TRYING TO RESET IT file=/var/media/tv/JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-2.mpg size=126727180

Wed 8/9 0:38:34.559 [ThumbnailGen@1c99c27a] MediaFile creating thumbnail to /opt/sagetv/server/GeneratedThumbnails/varmediatvJimmyKimmelLiveS15E101MiloVentimigliaLindseyStirling78061550mpg.jpg for MediaFile[id=7816533 A[7806155,7806148,"Jimmy Kimmel Live",24052@0808.23:35,62,T] mask=TV host=unraid encodedBy=HDHomeRun 1017d94a Tuner 1 WKBWDT format=MPEG2-PS 0:00:00 5707 kbps [#0 Video[MPEG2-Video 59.94006 fps 1280x720 16:9 progressive id=e0]#1 Video[MPEG2-Video 29.97003 fps 704x480 4:3 interlaced id=e1]#2 Audio[AC3 48000 Hz 2 channels 128 kbps idx=4 id=bd-81010000 spa]#3 Audio[AC3 48000 Hz 6 channels 384 kbps idx=5 id=bd-82010000]#4 Audio[AC3 48000 Hz 2 channels 192 kbps idx=6 id=bd-83010000]#5 Audio[AC3 48000 Hz 2 channels 128 kbps idx=7 id=bd-84010000]{Trivia=, SeriesInfoID=184869, TagLine=, MediaType=TV, SeasonFinal=false, CollectionOverview=, IMDBID=, CollectionName=, TrailerUrl=, UserRating=0, Quotes=, MediaProviderID=tvdb, MediaProviderDataID=71998, EpisodeCount=0, ScrapedBy=Phoenix, MediaTitle=Jimmy Kimmel Live, DiscNumber=0, ScrapedDate=1502253420818, CollectionID=0}] /var/media/tv/JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-0.mpg, Seg0[Tue 8/8 23:35:00.003-Wed 8/9 0:04:37.878], Seg1[Wed 8/9 0:04:37.879-Wed 8/9 0:14:52.773], Seg2[Wed 8/9 0:14:52.774-Wed 8/9 0:20:14.016], Seg3[Wed 8/9 0:20:14.017-Wed 8/9 0:23:01.087], Seg4[Wed 8/9 0:24:14.151-Wed 8/9 0:26:29.111], Seg5[Wed 8/9 0:27:59.122-Wed 8/9 0:37:00.000]]
Wed 8/9 0:38:54.733 [SeekerWatchdog@648966] ERROR - Seeker has been hung for more than 60 seconds...system appears deadlocked...dumping thread states
Wed 8/9 0:38:54.744 [SeekerWatchdog@648966] Thread[1969764457@qtp-813427685-3,5,main]
Wed 8/9 0:38:54.744 [SeekerWatchdog@648966] 	java.lang.Object.wait(Native Method)
Wed 8/9 0:38:54.744 [SeekerWatchdog@648966] 	org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:563)
Wed 8/9 0:38:54.744 [SeekerWatchdog@648966] Thread[VideoFrame-0023a5000615,5,main]
Wed 8/9 0:38:54.744 [SeekerWatchdog@648966] 	java.lang.Object.wait(Native Method)
Wed 8/9 0:38:54.745 [SeekerWatchdog@648966] 	sage.VideoFrame.run(VideoFrame.java:792)
Wed 8/9 0:38:54.745 [SeekerWatchdog@648966] 	sage.Pooler$PooledThread.run(Pooler.java:254)

This last error at 12:38am by the SeekerWatchdog seems pretty serious. So not sure exactly what the Seeker is... looks like it starts and stops scheduled recordings. Maybe my seeker crashed and that's why my Daily Show never stopped recording overnight?

[EnterNoEscape]

Originally Posted by glenner

So here is my SageTV log. Things start to go south around Aug 9 12am. It is trying to record Kimmel, Daily Show, and Colbert on 3 tuners. All 3 shows overlap.

I'm not really sure how to read the Sage log, but I see errors like this:

Wed 8/9 0:05:00.975 [MsgManager@512dbad3] MAJOR Change to file format detected...reload any active media players using: MediaFile[id=7816535 A[7760623,7760021,"The Daily Show With Trevor Noah",44784@0809.00:05,32,T] mask=TV host=unraid encodedBy=HDHomeRun 1055a735 Tuner 0 CFTODT format=MPEG2-PS 0:00:00 2892 kbps [#0 Video[MPEG2-Video 29.97003 fps 1920x1080 16:9 interlaced id=e0]#1 Audio[AC3 48000 Hz 6 channels 384 kbps MAIN idx=1 id=bd-80010000 eng]#2 Audio[AC3 48000 Hz 2 channels 192 kbps idx=2 id=bd-81010000 enm]#3 Audio[AC3 48000 Hz 2 channels 192 kbps idx=3 id=bd-82010000 eng]] /var/media/tv/TheDailyShowWithTrevorNoah-TheRussianScandalTheCremeDeLaKremlin-7760623-0.mpg, Seg0[Wed 8/9 0:05:00.003-Wed 12/31 19:00:00.000]]

Wed 8/9 0:14:52.682 [FSManager@118cf00b] Async encoder halt detector found a halt; kick the Seeker so it can restart the device file=MediaFile[id=7816533 A[7806155,7806148,"Jimmy Kimmel Live",24052@0808.23:35,62,T] mask=TV host=unraid encodedBy=HDHomeRun 1017d94a Tuner 1 WKBWDT format=MPEG2-PS 0:00:00 3512 kbps [#0 Video[MPEG2-Video 59.94006 fps 1280x720 16:9 progressive id=e0]#1 Audio[AC3 48000 Hz 6 channels 384 kbps MAIN idx=1 id=bd-80010000 eng]#2 Audio[AC3 48000 Hz 2 channels 128 kbps idx=2 id=bd-81010000 spa]] /var/media/tv/JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-0.mpg, Seg0[Tue 8/8 23:35:00.003-Wed 8/9 0:04:37.878], Seg1[Wed 8/9 0:04:37.879-Wed 12/31 19:00:00.000]] size=640512810

Wed 8/9 0:20:13.649 [Seeker@43a32c4c] SEEKER HAS DETECTED A HALT IN THE ENCODER...TRYING TO RESET IT file=/var/media/tv/JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-2.mpg size=126727180

Wed 8/9 0:38:34.559 [ThumbnailGen@1c99c27a] MediaFile creating thumbnail to /opt/sagetv/server/GeneratedThumbnails/varmediatvJimmyKimmelLiveS15E101MiloVentimigliaLindseyStirling78061550mpg.jpg for MediaFile[id=7816533 A[7806155,7806148,"Jimmy Kimmel Live",24052@0808.23:35,62,T] mask=TV host=unraid encodedBy=HDHomeRun 1017d94a Tuner 1 WKBWDT format=MPEG2-PS 0:00:00 5707 kbps [#0 Video[MPEG2-Video 59.94006 fps 1280x720 16:9 progressive id=e0]#1 Video[MPEG2-Video 29.97003 fps 704x480 4:3 interlaced id=e1]#2 Audio[AC3 48000 Hz 2 channels 128 kbps idx=4 id=bd-81010000 spa]#3 Audio[AC3 48000 Hz 6 channels 384 kbps idx=5 id=bd-82010000]#4 Audio[AC3 48000 Hz 2 channels 192 kbps idx=6 id=bd-83010000]#5 Audio[AC3 48000 Hz 2 channels 128 kbps idx=7 id=bd-84010000]{Trivia=, SeriesInfoID=184869, TagLine=, MediaType=TV, SeasonFinal=false, CollectionOverview=, IMDBID=, CollectionName=, TrailerUrl=, UserRating=0, Quotes=, MediaProviderID=tvdb, MediaProviderDataID=71998, EpisodeCount=0, ScrapedBy=Phoenix, MediaTitle=Jimmy Kimmel Live, DiscNumber=0, ScrapedDate=1502253420818, CollectionID=0}] /var/media/tv/JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-0.mpg, Seg0[Tue 8/8 23:35:00.003-Wed 8/9 0:04:37.878], Seg1[Wed 8/9 0:04:37.879-Wed 8/9 0:14:52.773], Seg2[Wed 8/9 0:14:52.774-Wed 8/9 0:20:14.016], Seg3[Wed 8/9 0:20:14.017-Wed 8/9 0:23:01.087], Seg4[Wed 8/9 0:24:14.151-Wed 8/9 0:26:29.111], Seg5[Wed 8/9 0:27:59.122-Wed 8/9 0:37:00.000]]
Wed 8/9 0:38:54.733 [SeekerWatchdog@648966] ERROR - Seeker has been hung for more than 60 seconds...system appears deadlocked...dumping thread states
Wed 8/9 0:38:54.744 [SeekerWatchdog@648966] Thread[1969764457@qtp-813427685-3,5,main]
Wed 8/9 0:38:54.744 [SeekerWatchdog@648966] 	java.lang.Object.wait(Native Method)
Wed 8/9 0:38:54.744 [SeekerWatchdog@648966] 	org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:563)
Wed 8/9 0:38:54.744 [SeekerWatchdog@648966] Thread[VideoFrame-0023a5000615,5,main]
Wed 8/9 0:38:54.744 [SeekerWatchdog@648966] 	java.lang.Object.wait(Native Method)
Wed 8/9 0:38:54.745 [SeekerWatchdog@648966] 	sage.VideoFrame.run(VideoFrame.java:792)
Wed 8/9 0:38:54.745 [SeekerWatchdog@648966] 	sage.Pooler$PooledThread.run(Pooler.java:254)

This last error at 12:38am by the SeekerWatchdog seems pretty serious. So not sure exactly what the Seeker is... looks like it starts and stops scheduled recordings. Maybe my seeker crashed and that's why my Daily Show never stopped recording overnight?

The stack trace for Seeker looks like it was hung trying to open the file /var/media/tv/TheLateShowWithStephenColbert-S02E198-ChristophWaltzChrisODowdSeanEvans-7803310-0.mpg to append metadata. This would suggest that you experienced a disk related problem.

It also must have successfully transitioned to the daily show before this hang happened which is why it never stopped recording. It never stopped recording the daily show because Seeker was unable to resume it's task of starting and stopping the encoders.

[glenner]

Originally Posted by EnterNoEscape

The stack trace for Seeker looks like it was hung trying to open the file /var/media/tv/TheLateShowWithStephenColbert-S02E198-ChristophWaltzChrisODowdSeanEvans-7803310-0.mpg to append metadata. This would suggest that you experienced a disk related problem.

It also must have successfully transitioned to the daily show before this hang happened which is why it never stopped recording. It never stopped recording the daily show because Seeker was unable to resume it's task of starting and stopping the encoders.

Just curious I looked at the log, and can't find exactly what you are referring to. Which line in the trace stuck out to you?

Thanks for the diagnosis Dr. No Escape :-). But so not really sure what I do now... I noticed that last night, the 3 shows recorded relatively cleanly.... In that my server has not crashed, and my cache is not filling up. But I have noticed the Kimmel show needed 5 mpg files to record. Last night I have this on my filesystem for the 3 shows:

-rw-r--r-- 1 nobody users  4340175642 Aug 10 00:37 TheDailyShowWithTrevorNoah-TrumpsBestSmartestPeopleSuchGreatPeople-7763910-0.mpg
-rw-r--r-- 1 nobody users  7462190046 Aug 10 00:37 TheLateShowWithStephenColbert-S02E199-RobertPattinsonDavidTennantNiecyNash-7803350-0.mpg
-rw-r--r-- 1 nobody users    16199318 Aug 10 00:31 JimmyKimmelLive-S15E102-JimParsonsDamsonIdrisTheWaronDrugs-7806171-4.mpg
-rw-r--r-- 1 nobody users    51178980 Aug 10 00:19 JimmyKimmelLive-S15E102-JimParsonsDamsonIdrisTheWaronDrugs-7806171-3.mpg
-rw-r--r-- 1 nobody users    72468662 Aug 10 00:09 JimmyKimmelLive-S15E102-JimParsonsDamsonIdrisTheWaronDrugs-7806171-2.mpg
-rw-r--r-- 1 nobody users      557152 Aug 10 00:00 JimmyKimmelLive-S15E102-JimParsonsDamsonIdrisTheWaronDrugs-7806171-1.mpg
-rw-r--r-- 1 nobody users  1716638647 Aug  9 23:58 JimmyKimmelLive-S15E102-JimParsonsDamsonIdrisTheWaronDrugs-7806171-0.mpg

So I have 5 files for Kimmel for some reason. It looks like the tuner had trouble recording that show on ABC channel 7.1. I checked the show and I have a bunch of gaps in the recording.

As I have 2 tuners on an older HDHR dual, and 2 tuners on a new HDHR Extend, I've noticed signal strength is substantially better on the Extend than on the dual for some of my 3 harder to get stations (ABC, Fox, NBC). Though most of the time, all stations come through fine.

There does not seem to be a good way for me to tell Sage to prioritize the Extend tuners over the dual tuners, at all times. In fact, it seems to choose the dual ahead of the Extend whenever possible as best as I can tell. Today, I've disabled ABC, Fox, and NBC channel setup for the dual, and so maybe it will only use the Extend for those stations. I'll see if that helps.

In the meantime, I guess what I'm left with is these observations:

1. tuner issues, or any stability problems during a recording can cause serious issues. in my case it ended up bringing the whole unraid server down.
2. if the seeker hangs it does not seem to get restarted. is this something the watchdog should do? if the seeker is hung, kill it and start a new one?
3. unraid does not seem to keep historical system logs? so if I have to hard reset the unraid box as I did yesterday, there is no log to look at to see what unraid was doing (as best as I can tell).
4. instability in a single unraid docker can bring the whole server down. I was kind of hoping some kind of docker isolation might prevent this, but I guess that's not the case yet.

Thanks again for looking at my log! -glenner.

[Tiki]

You can use the encoder merit settings in Sage to prioritize certain tuners.

You used to have to edit Sage.properties to change merit, but can do it from the video sources setup screen inside Sage now.

[EnterNoEscape]

Originally Posted by glenner

Just curious I looked at the log, and can't find exactly what you are referring to. Which line in the trace stuck out to you?

Thanks for the diagnosis Dr. No Escape :-). But so not really sure what I do now... I noticed that last night, the 3 shows recorded relatively cleanly.... In that my server has not crashed, and my cache is not filling up. But I have noticed the Kimmel show needed 5 mpg files to record. Last night I have this on my filesystem for the 3 shows:

-rw-r--r-- 1 nobody users  4340175642 Aug 10 00:37 TheDailyShowWithTrevorNoah-TrumpsBestSmartestPeopleSuchGreatPeople-7763910-0.mpg
-rw-r--r-- 1 nobody users  7462190046 Aug 10 00:37 TheLateShowWithStephenColbert-S02E199-RobertPattinsonDavidTennantNiecyNash-7803350-0.mpg
-rw-r--r-- 1 nobody users    16199318 Aug 10 00:31 JimmyKimmelLive-S15E102-JimParsonsDamsonIdrisTheWaronDrugs-7806171-4.mpg
-rw-r--r-- 1 nobody users    51178980 Aug 10 00:19 JimmyKimmelLive-S15E102-JimParsonsDamsonIdrisTheWaronDrugs-7806171-3.mpg
-rw-r--r-- 1 nobody users    72468662 Aug 10 00:09 JimmyKimmelLive-S15E102-JimParsonsDamsonIdrisTheWaronDrugs-7806171-2.mpg
-rw-r--r-- 1 nobody users      557152 Aug 10 00:00 JimmyKimmelLive-S15E102-JimParsonsDamsonIdrisTheWaronDrugs-7806171-1.mpg
-rw-r--r-- 1 nobody users  1716638647 Aug  9 23:58 JimmyKimmelLive-S15E102-JimParsonsDamsonIdrisTheWaronDrugs-7806171-0.mpg

So I have 5 files for Kimmel for some reason. It looks like the tuner had trouble recording that show on ABC channel 7.1. I checked the show and I have a bunch of gaps in the recording.

As I have 2 tuners on an older HDHR dual, and 2 tuners on a new HDHR Extend, I've noticed signal strength is substantially better on the Extend than on the dual for some of my 3 harder to get stations (ABC, Fox, NBC). Though most of the time, all stations come through fine.

There does not seem to be a good way for me to tell Sage to prioritize the Extend tuners over the dual tuners, at all times. In fact, it seems to choose the dual ahead of the Extend whenever possible as best as I can tell. Today, I've disabled ABC, Fox, and NBC channel setup for the dual, and so maybe it will only use the Extend for those stations. I'll see if that helps.

In the meantime, I guess what I'm left with is these observations:

1. tuner issues, or any stability problems during a recording can cause serious issues. in my case it ended up bring the whole unraid server down.
2. if the seeker hangs it does not seem to get restarted. is this something the watchdog should do? if the seeker is hung, kill it and start a new one?
3. unraid does not seem to keep historical system logs? so if I have to hard reset the unraid box as I did yesterday, there is no log to look at to see what unraid was doing (as best as I can tell).
4. instability in a single unraid docker can bring the whole server down. I was kind of hoping some kind of docker isolation might prevent this, but I guess that's not the case yet.

Thanks again for looking at my log! -glenner.

This is at the top of the actually very helpful stack trace of all threads done by the watchdog.

Wed 8/9 0:38:54.807 [SeekerWatchdog@648966] 	java.io.RandomAccessFile.open0(Native Method)

Unfortunately the Watchdog can't really do much in this situation. It could technically start a new Seeker thread, but that could be disastrous if the old one suddenly resumed. I actually think the best course of action is what apparently was done in the embedded version and that was restart SageTV.

The Docker container does contain things, but since SageTV has unfettered access to the array, it can just keep writing and writing until you run out of space which apparently can bring the whole server down.

[BobPhoenix]

Originally Posted by glenner

but I thought most unraid/Sage users are recording to the cache drive for performance reasons?

I am sure you are correct but I would try it. I don't think if you get a 114GB recording to an array drive that unRAID would crash. But recording to your cache drive will fill it up in a situation like this and I can see it causing unRAID to freak out or crash.

An alternative solution would be to setup recording drives (note the plural there) and record to them but have them mounted with unassigned devices in unRAID out side of the array. They can be spinners hence the suggestion of multiple drives. Then you can use MC (MidnightCommander) to move your recordings to your array or schedule a script to move them.

That is the way I'm doing it now even though I know many will chime in and say they record many streams to a drive without problems. I prefer to spread out my recordings to multiple drives and outside of the array. That way my array is only written to in batches. I just got done transferring ~12TB of recordings to my unRAID array to clear out some space on my recording drives. But otherwise I only write to the array every few months to a year at a time. Yes the recording drives are unprotected but that is why I have multiple servers recording the same things (where possible). I have backups just not bit accurate backups of my shows.

[glenner]

Originally Posted by EnterNoEscape

This is at the top of the actually very helpful stack trace of all threads done by the watchdog.

Wed 8/9 0:38:54.807 [SeekerWatchdog@648966] 	java.io.RandomAccessFile.open0(Native Method)

Unfortunately the Watchdog can't really do much in this situation. It could technically start a new Seeker thread, but that could be disastrous if the old one suddenly resumed. I actually think the best course of action is what apparently was done in the embedded version and that was restart SageTV.

The Docker container does contain things, but since SageTV has unfettered access to the array, it can just keep writing and writing until you run out of space which apparently can bring the whole server down.

I see... so the seeker thread hung trying to generate thumbnail data for the Kimmel show? As I said, I did notice what appeared to be a corrupted filename for the Kimmel show. Here is my dir output I took at the time (note I had already deleted the corrupted Kimmel mpg files.. but the logo.txt files remain and they were generated with the same corrupted filenames (\001\001, etc). Next time I see corrupted filenames I'll keep the full directory listing. But so... really not clear why I would get bad filenames like that. I can see that the Seeker might have a problem opening that file... though ideally it wouldn't hang.

sagemedia/tv:
total 117723004
drwxr-xr-x 1 nobody users         2802 Aug  9 13:13 ./
drwxrwxrwx 1 nobody users            4 Aug  8 17:22 ../
-rw-r--r-- 1 nobody users         8385 Aug  9 13:11 JimmyKimmelLive-S15E101-MiloVentimigliaLindse\001\001\001\001\001\001\001\001\001\0017806155-1.logo.txt
-rw-r--r-- 1 nobody users         8476 Aug  9 13:12 JimmyKimmelLive-S15E101-MiloVentimigliaLindse\001\001\001\001\001\001\001\001\001\0017806155-2.logo.txt
-rw-r--r-- 1 nobody users         8476 Aug  9 13:13 JimmyKimmelLive-S15E101-MiloVentimigliaLindse\001\001\001\001\001\001\001\001\001\0017806155-5.logo.txt
-rw-r--r-- 1 nobody users           45 Aug  9 13:12 JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-1.edl
-rw-r--r-- 1 nobody users       474737 Aug  9 13:12 JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-1.log
-rw-r--r-- 1 nobody users          101 Aug  9 13:12 JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-1.txt
-rw-r--r-- 1 nobody users            0 Aug  9 13:12 JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-2.edl
-rw-r--r-- 1 nobody users       538853 Aug  9 13:12 JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-2.log
-rw-r--r-- 1 nobody users           78 Aug  9 13:12 JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-2.txt
-rw-r--r-- 1 nobody users            0 Aug  9 13:13 JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-3.edl
-rw-r--r-- 1 nobody users       171466 Aug  9 13:13 JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-3.log
-rw-r--r-- 1 nobody users           78 Aug  9 13:13 JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-3.txt
-rw-r--r-- 1 nobody users            0 Aug  9 13:13 JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-4.edl
-rw-r--r-- 1 nobody users        40699 Aug  9 13:13 JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-4.log
-rw-r--r-- 1 nobody users           68 Aug  9 13:13 JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-4.txt
-rw-r--r-- 1 nobody users           16 Aug  9 13:14 JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-5.edl
-rw-r--r-- 1 nobody users       191535 Aug  9 13:14 JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-5.log
-rw-r--r-- 1 nobody users           91 Aug  9 13:14 JimmyKimmelLive-S15E101-MiloVentimigliaLindseyStirling-7806155-5.txt
-rw-r--r-- 1 nobody users 113581809664 Aug  9 14:18 TheDailyShowWithTrevorNoah-TheRussianScandalTheCremeDeLaKremlin-7760623-0.mpg
-rw-r--r-- 1 nobody users   6965055880 Aug  9 00:37 TheLateShowWithStephenColbert-S02E198-ChristophWaltzChrisODowdSeanEvans-7803310-0.mpg

Note on the day of the crash Kimmel was also a spotty recording generating 5 mpg files... I guess I can't record Kimmel right now, at least on that dual tuner. I'll see if it records better on the Extend tuner tonight. It should because I can tune to ABC right now no problem.

It actually did not fill my cache drive. When I rebooted, the cache was about 75% full. unraid gave me a warning that my cache was getting full. But so on a 250GB cache, I still had about 60GB free. But who knows what limits you may be reaching with an open 114GB mpg file. Maybe the comskip process would go nuts with that?

I could ping unraid, but it was non-responsive otherwise. So maybe CPU or memory was pegged. I may never know... :-)

[glenner]

Originally Posted by BobPhoenix

I am sure you are correct but I would try it. I don't think if you get a 114GB recording to an array drive that unRAID would crash. But recording to your cache drive will fill it up in a situation like this and I can see it causing unRAID to freak out or crash.

My cache drive was 75% full at the time of the crash and still had 60GB free. So not clear what limit was reached... but clearly a 114GB recording seems to be a limit, at least on my setup. Personally I would like to see what comskip does with that... I think that process is CPU intensive.

Originally Posted by BobPhoenix

An alternative solution would be to setup recording drives (note the plural there) and record to them but have them mounted with unassigned devices in unRAID out side of the array. They can be spinners hence the suggestion of multiple drives. Then you can use MC (MidnightCommander) to move your recordings to your array or schedule a script to move them.

How do you tell Sage to simultaneous record in parallel on multiple drives? I've not seen a specific switch for that... In my old Windows setup I had 2 recording directories on 2 different physical drives (500GB and 2TB), and Sage only ever seemed to record all shows on my larger drive.

Originally Posted by BobPhoenix

That is the way I'm doing it now even though I know many will chime in and say they record many streams to a drive without problems. I prefer to spread out my recordings to multiple drives and outside of the array. That way my array is only written to in batches. I just got done transferring ~12TB of recordings to my unRAID array to clear out some space on my recording drives. But otherwise I only write to the array every few months to a year at a time. Yes the recording drives are unprotected but that is why I have multiple servers recording the same things (where possible). I have backups just not bit accurate backups of my shows.

Yeah... I'll need to see if this cache recording dir setup will be stable over the longer term. I don't mind the current setup.. but it's true that I don't particularly care either way if every show ends up in the parity protected array on a daily basis. Ideally just my "archived" shows that I want to keep need to be in the array.

That said, drives, SSDs, and a few watts here and there are relatively cheap... and so I don't really care how much they spin... as long as it all works, uptime/reliability is solid, and ideally unraid gives me a heads up or a fallback (parity rebuild) when it's time to replace drives.

Do your recording still show up as "recordings" after you've moved them to the array? Do you have a Sage recording dir defined on the array and another on an unassigned device? I might try the unassigned device route for recordings... but I'd want to have a good process to move my "keeper" recordings to the array and have them appear in Sage seamlessly.

[glenner]

Originally Posted by Tiki

You can use the encoder merit settings in Sage to prioritize certain tuners.

You used to have to edit Sage.properties to change merit, but can do it from the video sources setup screen inside Sage now.

Ok, I'll bite :-) ...that sounds useful. But I've never seen an encoder merit option in the Sage UI. Is it under the "Setup Video Sources" screen? I've got my 4 tuners there.... Don't see anyway to prioritize them...

[glenner]

Originally Posted by glenner

Ok, I'll bite :-) ...that sounds useful. But I've never seen an encoder merit option in the Sage UI. Is it under the "Setup Video Sources" screen? I've got my 4 tuners there.... Don't see anyway to prioritize them...

Actually... I found tuner merit explained here: https://forums.sagetv.com/forums/showthread.php?t=64374

I've set it up to prioritize Extend over Dual now.... The Extend has a 10-20% stronger signal strength on a bunch of channels... so this should help.

[btrcp2000]

I am finishing up zeroing drives today and this weekend will actually get to do something other than watch the paint dry. Stories like this and some others on the unraid forums scare the hell out of me. I have had crashplan going a year now and will continue, so I'm not so much worried about data loss, but one of the things that attracted me is the supposed stability of unraid. Nothing is foolproof, but it's been a long time since I've had anything unexplainable happen with my 9 yr old sage server (once I learned about nightly reboot scripts anyway). I'm still plowing forward, but it will be a while before I completely dismantle and part out the old server.

EDIT: and I'm sorry that happened to you, hope you are able to recover and keep it from happening again. thanks for sharing the details for the rest of us.

[glenner]

Originally Posted by btrcp2000

I am finishing up zeroing drives today and this weekend will actually get to do something other than watch the paint dry. Stories like this and some others on the unraid forums scare the hell out of me. I have had crashplan going a year now and will continue, so I'm not so much worried about data loss, but one of the things that attracted me is the supposed stability of unraid. Nothing is foolproof, but it's been a long time since I've had anything unexplainable happen with my 9 yr old sage server (once I learned about nightly reboot scripts anyway). I'm still plowing forward, but it will be a while before I completely dismantle and part out the old server.

EDIT: and I'm sorry that happened to you, hope you are able to recover and keep it from happening again. thanks for sharing the details for the rest of us.

I'm actually relatively happy with my unraid setup since I started building it a couple of months ago as part of my big migration off of an ancient (9 yrs too probably) WinXP + SageTV v6 system I had (and still have as a backup).

unraid itself is a nice tidy OS with a clean dashboard interface. The available dockers are all the ones I want, and it let me setup what I view as a proper dedicated media server. So far I'm running SageTV, Plex, Logitech Media Server, and few downloading apps (much better than what I had). I also have a Windows 10 VM up now and it works surprisingly well.

If the unraid parity protection and disk monitoring features save me from losing data in the future, then this will have been worth it. The downside is that unraid support is a smaller world than in the Windows world. I've never found a Windows issue that google or youtube could not fix for me. If you have a problem on unraid, hopefully it is minor and you can find the answer. I'm a little worried about running into the unraid problem I can't fix. In that case, I'm keeping my old Win machine around as a backup too. But I don't think it will ever come to that.

I've only had 2 "unraid crashes" so far... both times it involved the SageTV docker. The first "crash" happened when I had SageTV running both on unraid and another Windows machine. Both servers were trying to record the same show using the same tuner. This tuner contention created seeker halts on the unraid server, and ultimately SageTV hung. unraid did not actually go down, but I had to restart the SageTV docker.

The second instance is this time here where SageTV seemed to have a problem recording a Kimmel show on ABC, and that hung the seeker and allowed for a 114GB Daily Show recording to be generated. Tuner reception for me on 2-3 US channels is not always 100%. More like 95%. It depends a bit on whether there is storm over Lake Ontario, and how leafy the trees are. Literally. My attic CM 4221 install is as good as I can get it where I get 30+ channels, short of getting a newer antenna and maybe mounting outdoors. ABC is a Buffalo channel 70 miles away from Toronto... I get it fine most of the time (50%+ signal), but clearly last night there was an issue. I've found any tuner instability causes seeker halts or hangs, and in this case it ended up creating an endless recording that brought down the whole unraid server.

As the end of the day, I did not lose anything. No data was lost, other than my messed up Kimmel and Daily Show recordings. Parity check ran fine with no errors. I just had an annoying and initially scary reboot to deal with, and I'd certainly not want to do that on a daily or frequent basis.

Everything recorded fine last night. I'm hoping my tuner merit changes address this for good, as my Extend pair of tuners have much clearer reception.

I'm starting to think the Sage seeker is maybe a bit too aggressive in trying to record a show. Perhaps if it scrubs a show recording after a first failure, then these hangs/crashes might be prevented, and overall stability would be improved. I'd rather just miss a show than have Sage or unraid go offline. Can the seeker be tuned to skip shows that are not recording properly?

I think unraid will ultimately be rock solid and as good as my old Win setup (which was very reliable, but not 100% either).

One thing is for sure, if you are on unraid it definitely a prerequisite to have Linux proficiency. Sage on unraid/Linux is for advanced users in my mind... I also helps to make a pile of friends on this forum and the unraid one, as we can help each other when we get stuck. :-)

But overall SageTV on unraid looks really solid to me so far.

[BobPhoenix]

Originally Posted by glenner

How do you tell Sage to simultaneous record in parallel on multiple drives? I've not seen a specific switch for that... In my old Windows setup I had 2 recording directories on 2 different physical drives (500GB and 2TB), and Sage only ever seemed to record all shows on my larger drive.

Default setting is to record to the drive with the most free so if you have one drive larger than the other then yes it would go to that drive exclusively - all my recording drives are the same size 3TB. They were unRAID array drives before I upgraded to 4,6 & 8TB drives. There is a setting in Sage to spread recordings up among recording drives ignoring which drive has the most free. So if you had multiple recordings going at the same time it would be guaranteed to use multiple drives. But I believe if you end up recording one show at a time it will still record to the drive with the most space so your recordings would still end up on your largest drive. Anyway the setting is "Detailed Setup/General/Video Recording Path Optimization Style" set to Optimize for Bandwidth.

Originally Posted by glenner

Do your recording still show up as "recordings" after you've moved them to the array? Do you have a Sage recording dir defined on the array and another on an unassigned device? I might try the unassigned device route for recordings... but I'd want to have a good process to move my "keeper" recordings to the array and have them appear in Sage seamlessly.

Yes my recordings still show up as recordings. Technically they end up under archived recordings and I then unArchive them to get them back under regular recordings. I only have recording drives defined on the unassigned device. I have imported videos on the array. I copy my recordings to an imported folder and force an import scan so that SageTV will pick up that the recording have moved to an import folder.

You might also try to mount a spinner underneath a share name on your cache drive. Then you get all the recordings going to that drive instead of your cache drive and then mover will move the recordings to your array nightly/weekly/hourly how ever you have it defined. I usually just move mine from my recording drive every few months to a year depending on time and how full they are. I usually move when they get to 500GB (2.5TB used) of free space on each of my 4 recording drives.

[EnterNoEscape]

Originally Posted by glenner

I'm starting to think the Sage seeker is maybe a bit too aggressive in trying to record a show. Perhaps if it scrubs a show recording after a first failure, then these hangs/crashes might be prevented, and overall stability would be improved. I'd rather just miss a show than have Sage or unraid go offline. Can the seeker be tuned to skip shows that are not recording properly?

This is a really loaded question. The first thing that needs to be understood in this case is that the Seeker thread (there's only one) got hung up just trying to open the end of a file to append some metadata. This isn't a normal problem and often indicates impending disk failure and not necessarily on the disk it was trying to open a file on.

Once the thread is hung in the current SageTV model, it's hard to make any rational decisions other that take down the whole JVM and restart SageTV. The reason for this problem is because you can't (shouldn't; it's deprecated for a reason) just kill a thread in the JVM. The thread needs to terminate on it's own and if we spin up a new thread to resume Seeker functionality, then the old thread starts working again suddenly it gets very unpredictable because they will at best tell everything to do the same thing twice and at worse tell everything to do conflicting things and fight over global static objects.

I am working in that area on a new feature that I hope to be able to bring to SageTV before 2018 whereby these kinds of operations are planned on the Seeker thread, but are performed on their own threads and as such could be more easily isolated from breaking everything.

[glenner]

Originally Posted by EnterNoEscape

This is a really loaded question. The first thing that needs to be understood in this case is that the Seeker thread (there's only one) got hung up just trying to open the end of a file to append some metadata. This isn't a normal problem and often indicates impending disk failure and not necessarily on the disk it was trying to open a file on.

Once the thread is hung in the current SageTV model, it's hard to make any rational decisions other that take down the whole JVM and restart SageTV. The reason for this problem is because you can't (shouldn't; it's deprecated for a reason) just kill a thread in the JVM. The thread needs to terminate on it's own and if we spin up a new thread to resume Seeker functionality, then the old thread starts working again suddenly it gets very unpredictable because they will at best tell everything to do the same thing twice and at worse tell everything to do conflicting things and fight over global static objects.

I am working in that area on a new feature that I hope to be able to bring to SageTV before 2018 whereby these kinds of operations are planned on the Seeker thread, but are performed on their own threads and as such could be more easily isolated from breaking everything.

Thanks for the insight EnterNoEscape! Really appreciate gaining a better understanding of how Sage works. But so sure.. that makes sense. I can see you don't want to have a situation whereby there are 2 seeker threads running.

But in my case, most all of my hardware described in my sig is brand new. When the Seeker thread hang occurred, I think all Sage file i/o was going through my raid 1 cache pool with new Samsung evo960 250GB NVMe SSDs (best SSDs on the market I was told). My appdata and recordings are on the cache. So I would like to hope the unraid hardware was/is in order. I think the issue is the invalid filenames I observed on the system and referenced here. I also think that tuner instability (ie. transient border line signal strength on a particular show) can cause pretty weird things to happen. I don't see how filenames with special chars should be created in any situation like I found and documented. And if there are bad filenames like that, I can certainly see that Sage might have a problem opening the file.

In any event, I have not see this exact issue since I changed the merit on my tuners to prioritize the better tuners (Extend). I also have not seen corrupted filenames in any Sage generated recording file (*.mpg, *.txt, *.properties, *.edl, *.log, etc.)

That said, I did have a slightly different Seeker thread hang on Tuesday 8/15 early AM (12:02 am). Similar situation.... Sage is trying to record just Colbert and Kimmel simultaneously this time. Daily Show recording does not start till 12:35am.

At 12:02am, I see this in the log:

Tue 8/15 0:01:54.380 [Fork-PRQST-1215194@74c63839] Scanning video directory /var/media/tv
Tue 8/15 0:01:54.397 [Seeker@36dc6969] RootFile=/ fstype=0x9123683e fileLength=3033400588 file=/var/media/tv/TheLateShowWithStephenColbert-S02E202-AnthonyScaramucciBobOdenkirkLiamGallagher-7819453-0.mpg
Tue 8/15 0:01:54.397 [Seeker@36dc6969] RootFile=/ fstype=0x9123683e fileLength=1407686276 file=/var/media/tv/JimmyKimmelLive-S15E104-RayRomanoPaulaPattonBrysonTiller-7828057-1.mpg
Tue 8/15 0:01:54.397 [Seeker@36dc6969] Checking video directories for new files
Tue 8/15 0:01:54.398 [VideoFrame-0023a500074c@4fbc64a3] VF processing job null nPlayin=false
Tue 8/15 0:01:54.398 [VideoFrame-0023a500074c@4fbc64a3] VF thread is now waiting for 0:00:00.000
Tue 8/15 0:01:54.406 [VideoFrame-0023a500049e@6e046331] VF processing job null nPlayin=false
Tue 8/15 0:01:54.406 [VideoFrame-0023a500049e@6e046331] VF thread is now waiting for 0:00:00.000
Tue 8/15 0:01:54.408 [Seeker@36dc6969] Diskspace checking is running
Tue 8/15 0:01:54.417 [Seeker@36dc6969] Verifying existence of all TV media files in database fixDurs=false avoidArchive=true
Tue 8/15 0:01:54.505 [SeekerWatchdog@29bf0ec] ERROR - Seeker has been hung for more than 60 seconds...system appears deadlocked...dumping thread states
Tue 8/15 0:02:01.945 [Ministry@6f45f85d] Ministry is waiting for 180 sec
Tue 8/15 0:02:02.279 [SeekerWatchdog@29bf0ec] Thread[Timer-4,5,main]
Tue 8/15 0:02:02.280 [SeekerWatchdog@29bf0ec] 	java.lang.Object.wait(Native Method)
Tue 8/15 0:02:02.280 [SeekerWatchdog@29bf0ec] 	java.util.TimerThread.mainLoop(Timer.java:552)
Tue 8/15 0:02:02.280 [SeekerWatchdog@29bf0ec] 	java.util.TimerThread.run(Timer.java:505)

From that point forward, my extenders are offline, and SageTV is non-responsive. I restarted Sage the next day when I became aware of the issue. At least in this case, only Sage "crashed"... unraid server was fine.

Full log is attached.

If the Seeker's last log message is at 0:01:54.417. I'm not clear why the SeekerWatchdog logs that the Seeker is hung at 0:01:54.505 (1/10th second later). Is that normal?

[EnterNoEscape]

I believe the watchdog timer is reset each time Seeker awakes, so it's possible for delays in processing to cause enough time to pass to get the watchdog's attention sooner than you might expect.

Tue 8/15 0:02:02.584 [SeekerWatchdog@29bf0ec] 	java.io.UnixFileSystem.getBooleanAttributes0(Native Method)

It's another issue related to the filesystem. I'm trying to think of what could be a common thread here. When is the mover scheduled to move data from the cache to the array?

[glenner]

Originally Posted by EnterNoEscape

I believe the watchdog timer is reset each time Seeker awakes, so it's possible for delays in processing to cause enough time to pass to get the watchdog's attention sooner than you might expect.

Tue 8/15 0:02:02.584 [SeekerWatchdog@29bf0ec] 	java.io.UnixFileSystem.getBooleanAttributes0(Native Method)

It's another issue related to the filesystem. I'm trying to think of what could be a common thread here. When is the mover scheduled to move data from the cache to the array?

Good call! I did check my syslog just now. I had setup an unraid script to historically preserve all syslogs by tailing the syslog on each reboot to a separate file. I followed this process:

https://forums.lime-technology.com/t...comment-581595

But so the syslog shows my mover is set to run every 8 hours starting right at 12am (so 12am, 8am, 4pm daily). The mover runs right at midnight when I typically start to have problems. I also tend to record multiple late night shows at 12am... whereas typically nothing gets recorded at 8am or 4pm...

The syslog seems to show mover memory issues at the time in question? Here is the log, full log attached:

Aug 15 00:00:01 unraid root: mover started
Aug 15 00:00:01 unraid root: moving "sagemedia" to array
Aug 15 00:00:01 unraid root: .d..t...... ./
Aug 15 00:00:01 unraid root: .d..t...... sagemedia/
Aug 15 00:00:01 unraid root: .d..t...... sagemedia/tv/
Aug 15 00:00:01 unraid root: >f+++++++++ sagemedia/tv/WildKratts-S03E02-WheretheBisonRoam-7816684-0.mpg
Aug 15 00:00:25 unraid kernel: warn_alloc: 1069190 callbacks suppressed
Aug 15 00:00:25 unraid kernel: java: page allocation stalls for 10985ms, order:0, mode:0x34200ca(GFP_HIGHUSER_MOVABLE|__GFP_WRITE)
Aug 15 00:00:25 unraid kernel: CPU: 4 PID: 19630 Comm: java Not tainted 4.9.30-unRAID #1
Aug 15 00:00:25 unraid kernel: Hardware name: System manufacturer System Product Name/PRIME H270-PRO, BIOS 0323 01/04/2017
Aug 15 00:00:25 unraid kernel: ffffc9000c59ba68 ffffffff813a4a1b 0000000000000001 0000000000000000
Aug 15 00:00:25 unraid kernel: ffffc9000c59baf8 ffffffff810cb5b1 034200ca810c9d8d ffffffff8193d4e2
Aug 15 00:00:25 unraid kernel: ffffc9000c59ba90 0000000000000010 ffffc9000c59bb08 ffffc9000c59baa8
Aug 15 00:00:25 unraid kernel: Call Trace:
Aug 15 00:00:25 unraid kernel: [<ffffffff813a4a1b>] dump_stack+0x61/0x7e
Aug 15 00:00:25 unraid kernel: [<ffffffff810cb5b1>] warn_alloc+0x102/0x116
Aug 15 00:00:25 unraid kernel: [<ffffffff810cbb67>] __alloc_pages_nodemask+0x541/0xc71
Aug 15 00:00:25 unraid kernel: [<ffffffff8167c00e>] ? __schedule+0x2b1/0x46a
Aug 15 00:00:25 unraid kernel: [<ffffffff8107c0fd>] ? wake_up_bit+0x25/0x25
Aug 15 00:00:25 unraid kernel: [<ffffffff81245966>] ? fuse_request_free+0x3b/0x3e
Aug 15 00:00:25 unraid kernel: [<ffffffff81102d82>] alloc_pages_current+0xbe/0xe8
Aug 15 00:00:25 unraid kernel: [<ffffffff810c4d78>] __page_cache_alloc+0x89/0x9f
Aug 15 00:00:25 unraid kernel: [<ffffffff810c4ecc>] pagecache_get_page+0x13e/0x1e6
Aug 15 00:00:25 unraid kernel: [<ffffffff810c4f8f>] grab_cache_page_write_begin+0x1b/0x32
Aug 15 00:00:25 unraid kernel: [<ffffffff8124d8d7>] fuse_perform_write+0x186/0x484
Aug 15 00:00:25 unraid kernel: [<ffffffff81138461>] ? file_remove_privs+0x42/0x98
Aug 15 00:00:25 unraid kernel: [<ffffffff81153c96>] ? fsnotify_destroy_event+0x5d/0x64
Aug 15 00:00:25 unraid kernel: [<ffffffff811553eb>] ? inotify_handle_event+0xe2/0x100
Aug 15 00:00:25 unraid kernel: [<ffffffff8124dd95>] fuse_file_write_iter+0x1c0/0x203
Aug 15 00:00:25 unraid kernel: [<ffffffff81121078>] __vfs_write+0xc3/0xec
Aug 15 00:00:25 unraid kernel: [<ffffffff81121a5f>] vfs_write+0xcd/0x176
Aug 15 00:00:25 unraid kernel: [<ffffffff8112273a>] SyS_write+0x49/0x83
Aug 15 00:00:25 unraid kernel: [<ffffffff8167f537>] entry_SYSCALL_64_fastpath+0x1a/0xa9
Aug 15 00:00:25 unraid kernel: Mem-Info:
Aug 15 00:00:25 unraid kernel: active_anon:966116 inactive_anon:16963 isolated_anon:0
Aug 15 00:00:25 unraid kernel: active_file:6200848 inactive_file:655062 isolated_file:1472
Aug 15 00:00:25 unraid kernel: unevictable:0 dirty:654105 writeback:1654 unstable:0
Aug 15 00:00:25 unraid kernel: slab_reclaimable:115365 slab_unreclaimable:139851
Aug 15 00:00:25 unraid kernel: mapped:21220 shmem:135834 pagetables:6327 bounce:0
Aug 15 00:00:25 unraid kernel: free:66535 free_pcp:0 free_cma:0
Aug 15 00:00:25 unraid kernel: Node 0 active_anon:3864464kB inactive_anon:67852kB active_file:24803392kB inactive_file:2620248kB unevictable:0kB isolated(anon):0kB isolated(file):5888kB mapped:84880kB dirty:2616420kB writeback:6616kB shmem:543336kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 2611200kB writeback_tmp:0kB unstable:0kB pages_scanned:96 all_unreclaimable? no
Aug 15 00:00:25 unraid kernel: Node 0 DMA free:15896kB min:64kB low:80kB high:96kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15980kB managed:15896kB mlocked:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Aug 15 00:00:25 unraid kernel: lowmem_reserve[]: 0 2906 31944 31944
Aug 15 00:00:25 unraid kernel: Node 0 DMA32 free:127712kB min:12288kB low:15360kB high:18432kB active_anon:406164kB inactive_anon:0kB active_file:2281408kB inactive_file:241956kB unevictable:0kB writepending:242188kB present:3136448kB managed:3126452kB mlocked:0kB slab_reclaimable:57928kB slab_unreclaimable:5460kB kernel_stack:128kB pagetables:172kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Aug 15 00:00:25 unraid kernel: lowmem_reserve[]: 0 0 29038 29038
Aug 15 00:00:25 unraid kernel: Node 0 Normal free:122532kB min:122808kB low:153508kB high:184208kB active_anon:3458300kB inactive_anon:67852kB active_file:22521984kB inactive_file:2377792kB unevictable:0kB writepending:2380848kB present:30261248kB managed:29735764kB mlocked:0kB slab_reclaimable:403532kB slab_unreclaimable:553944kB kernel_stack:14864kB pagetables:25136kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
Aug 15 00:00:25 unraid kernel: lowmem_reserve[]: 0 0 0 0
Aug 15 00:00:25 unraid kernel: Node 0 DMA: 0*4kB 1*8kB (U) 1*16kB (U) 0*32kB 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (U) 3*4096kB (M) = 15896kB
Aug 15 00:00:25 unraid kernel: Node 0 DMA32: 76*4kB (UEH) 146*8kB (UH) 70*16kB (UMEH) 90*32kB (UMEH) 214*64kB (UMEH) 159*128kB (UMEH) 83*256kB (UMEH) 41*512kB (UMEH) 19*1024kB (UME) 3*2048kB (M) 5*4096kB (M) = 127840kB
Aug 15 00:00:25 unraid kernel: Node 0 Normal: 4244*4kB (UME) 12058*8kB (UME) 141*16kB (UMH) 5*32kB (EH) 1*64kB (H) 0*128kB 1*256kB (H) 1*512kB (H) 0*1024kB 1*2048kB (H) 1*4096kB (H) = 122832kB
Aug 15 00:00:25 unraid kernel: 6993296 total pagecache pages
Aug 15 00:00:25 unraid kernel: 0 pages in swap cache
Aug 15 00:00:25 unraid kernel: Swap cache stats: add 0, delete 0, find 0/0
Aug 15 00:00:25 unraid kernel: Free swap  = 0kB
Aug 15 00:00:25 unraid kernel: Total swap = 0kB
Aug 15 00:00:25 unraid kernel: 8353419 pages RAM
Aug 15 00:00:25 unraid kernel: 0 pages HighMem/MovableOnly
Aug 15 00:00:25 unraid kernel: 133891 pages reserved

At 12:03, it looks like unraid ends up killing a java process (SageTV?) presumably to free memory. Is that right?

Aug 15 00:03:08 unraid kernel: Out of memory: Kill process 14906 (java) score 38 or sacrifice child
Aug 15 00:03:08 unraid kernel: Killed process 14906 (java) total-vm:6664500kB, anon-rss:1256272kB, file-rss:0kB, shmem-rss:0kB
Aug 15 00:03:08 unraid kernel: oom_reaper: reaped process 14906 (java), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB

What do you think? Looks like the mover and my 2 recordings all running at 12am is a problem...