Odd recording/Playback issues over the last two weeks.

[wnjj]

Originally Posted by bigbill

My sage servers are win 10

Sorry, thought I saw 7 somewhere (probably my brain registering 7zip on your logs files) but regardless I’m guessing it still applies. The time stamps on your system are definitely different than mine and I saw similar start/end time weirdness when copying.

[bigbill]

From what I see all my shows time stamps are the begin time. Including lots of them that are recorded to the drive I want them to stay on, which means I do nothing with them.

I guess its really odd that our systems are handling the timestamps completely differently. Mine is always the beginning of the recording and your's the completion of the recording timestamp.

That should be explainable, The only difference I know about is since windows 8 they added Storage Services, and they radically changed it for v10. I don't remember if windows 7 used GPT or not. I seem to remember it only had MBR.
-Bill

[Narflex]

This is very weird. The timestamp is the 'modification time', so it should always be when the recording finished...when SageTV reimports the file, it assumes that as well. But if the time is totally off (i.e. the timestamp isn't even within the boundaries of the program), then it'll ignore the file timestamp. You files fall within a fraction of a second of that not being true. But if you changed the timestamp to be 'now' whenever you copied a file...that should likely fix the problem (except for when there's start padding on a show, then that'll be off).

[gary201]

I have the same issue where 1/2 of the timeline is green and the other is red. My recorded files are on on two Nas devices, both of which have the correct time (freenas mini and a qnap). The files are not moved after recording and no post processing other than comskip, which scans them just fine. When you try to play one on an hd300 the point where green meets red is time index 0 where the green is negative (eg a 30 min show the left edge of green is -29.59.

I don't have any issues skipping around, just starting the initial play where I have to press play then quickly skip backward to the beginning.

Basic environment, Linux system with two hdhomerun tuners. No cable here, all OTA. It's also somewhat random as to what shows are affected.

[bigbill]

Gary, have you checked your shows timestamps? Are the from the beginning or ending of the show?

The only thing I see we have in common are the HDHomeruns. I don't use a nas, nor linux and mine only seem to occur if i move them from one drive to another. -Bill

[bigbill]

Originally Posted by Narflex

This is very weird. The timestamp is the 'modification time', so it should always be when the recording finished...

Jeffery, how would I troubleshoot why the timestamps are from the beginning of the file instead of the ending time like they should be? Debug logging maybe? I am seeing they are beginning timestamps consistently for all my shows. -Bill

[wnjj]

There are several date 'types' when you view a file in explorer. Do any of them have the right time? Are they all the same? Check on these for both an original file and one you've copied/moved.

From what I see just messing around, files you copy update the 'created' date to the current one but leave 'modified' alone. I would think a fresh recorded show should have created when it started and modified when it ends.

[bigbill]

I never noticed there were so many date columns. But the important ones are the exact same, created and modified.


Holy Cow!
Date aquired, Date Archived, Date Completed, Date last saved, Date Received, Date Released, Date Sent, Date Taken, Date Visited.. Most of them are blank .

[bigbill]

Here is a screenshot showing good and bad modified timestamps.

the highlighted ones are the problem recordings and have the modified time wrong. These are all recorded to drives local to sagetv. I thought I had narrowed it down to one particular TV Station, but then I found one that had the issue and wasn't the same station as most of the others.

I did find the gui Merit parameter and have changed it so a different HDHR turner will be used as primary just to see if it makes a difference. Not sure how the tuner could control what time the modified timestamp would be though.

Did the debug logging option get removed in the new version? I've seen it a zillion times over the years, but now that I want to turn it on... I cannot find it.

[wnjj]

Originally Posted by bigbill

Here is a screenshot showing good and bad modified timestamps.

the highlighted ones are the problem recordings and have the modified time wrong. These are all recorded to drives local to sagetv. I thought I had narrowed it down to one particular TV Station, but then I found one that had the issue and wasn't the same station as most of the others.

I did find the gui Merit parameter and have changed it so a different HDHR turner will be used as primary just to see if it makes a difference. Not sure how the tuner could control what time the modified timestamp would be though.

Did the debug logging option get removed in the new version? I've seen it a zillion times over the years, but now that I want to turn it on... I cannot find it.

I think some of those date fields may come from meta data within media files.

Debug logging is on full time these days so that's why there isn't an option.

Is there any correlation to the "bad" timestamps and back to back recordings? Maybe the modified date doesn't get touched after the file completes due to what the system is doing when it ends and/or closes the file? Do you have "remove back to back padding" enabled or not? Just wild guesses here.

P.S. Your list of TV shows looks a lot like ours.

[Narflex]

Debug logging is forced on now...so you have no way to turn it off from the UI anymore.

And I have no idea why the OS is setting the modified times incorrectly...SageTV only sets the modified time if it re-imports a file and sees the modified time is wildly off; and it will set it to be the Airing end time (which is not what anybody has reported seeing as the problem). Modified should be that...when the file was last modified (i.e. when the recording ended). Is there maybe some plugin people are using that is messing with the timestamps?

[wnjj]

Even stranger is the CBS news has a modified time 5 minutes after creation, but is a 35 minute show. Something is messing those up.

[wnjj]

Originally Posted by Narflex

Debug logging is forced on now...so you have no way to turn it off from the UI anymore.

And I have no idea why the OS is setting the modified times incorrectly...SageTV only sets the modified time if it re-imports a file and sees the modified time is wildly off; and it will set it to be the Airing end time (which is not what anybody has reported seeing as the problem). Modified should be that...when the file was last modified (i.e. when the recording ended). Is there maybe some plugin people are using that is messing with the timestamps?

Jeff, Any chance it's related to switching encoding files due to back to back recordings on the same tuner? Maybe the first recording file isn't released properly to the OS for it to update the modification date?

[bigbill]

My Remove Padding on back to back is set to YES. I seem to remember changing that sometime back. I wonder if it was around the time this started happening. -Bill

[wnjj]

Originally Posted by bigbill

My Remove Padding on back to back is set to YES. I seem to remember changing that sometime back. I wonder if it was around the time this started happening. -Bill

I run the same setting but I’m starting to think switching files while recording could be a factor. If you run padding and have that setting on NO, it will cause the other tuner to pick up the next show. Do all of the messed up shows have other shows recording immediately after them? The capture device code does something different (switch instead of stop) when there are back to back recordings.

[bigbill]

It looks like the shows that have the issues have shows after them. I do see shows that didn't screw up with shows after them though. But I believe they are on different channels.

I don't believe I am using any padding. At least I cannot find an option to add padding. I thought there was something. I checked each favorite and they all start and end on time.

BTW, Is the debug log incorporated into those sagetv_?.txt files? Or is it somewhere else? Is there a way to have more than 4, as the data scrolls off pretty fast to go back more than a 3-12 hours. I am considering importing them into Splunk or something to have a bit of history. -Bill

[wnjj]

Originally Posted by bigbill

It looks like the shows that have the issues have shows after them. I do see shows that didn't screw up with shows after them though. But I believe they are on different channels.

I don't believe I am using any padding. At least I cannot find an option to add padding. I thought there was something. I checked each favorite and they all start and end on time.

BTW, Is the debug log incorporated into those sagetv_?.txt files? Or is it somewhere else? Is there a way to have more than 4, as the data scrolls off pretty fast to go back more than a 3-12 hours. I am considering importing them into Splunk or something to have a bit of history. -Bill

Yeah, those are the logs. Just set up a couple favorites that are back to back on the same channel (or wait for ones you already have) then grab the logs right after they record. I’m not sure if anything of interest will show up there. I’m suspicious of the file name change method which is part of the DirectShow filter code and ito compatibility with how the OS is handling the file closing.

Here's a super old discussion of exactly what I suspect: http://microsoft.public.win32.progra...n-t-close-file It may or may not be relevant today.

[bigbill]

Had 4 shows record back to back last night. No red areas in them. But one of the shows has the same create and modified dates, the rest look like they should be, one hour apart. The zip file is really a .7z file, so you will probably need to rename to open those logs. I'm a novice at reading them so maybe someone else will see something. The screen shot shows the recorded files and you can see which has the incorrect timestamp and which do not.

-Bill

PS. If there is a key to help understand them so I know what the different things defined in the log like Carny etc, that would be much appreciated.

[bigbill]

Ok. I got the show Hawaii50 to become 1/2 red by moving it from one local drive E: to another F: around 9:24am today. It was the only show from last night that had the modified timestamp the same as the created timestamp.

I see it gets library imported again at 9:38 am. There is what appears to be a RECOVERY keyword a few entries further down.

I have attached the log from the time I moved the file.

Its a 7z file renamed to .zip

Should I be stopping the sage service when I move the file to another drive? I am pretty sure I read that I should have Sage still running when i move a show. -Bill

[wnjj]

So I'll have to retract one of my earlier statements. I do have several shows that have the same created and modified time (at the start). That was likely the same problem I had with those funny summer Olympic shows I copied 2 years ago.

Here's the thing: The ONLY shows that are messed up are ones that have recordings following them on the same tuner but not all of that type are messed up.

If you look in your log files, you will see "switchOutputFile0" whenever the capture graph is asked to change the file without stopping/starting. From what I've read online here you're supposed to stop the capture graph, change the filename, then restart. I'm pretty sure the current Sage code does not do this but just switches the file name. I'm guessing that results in files left hanging that never get their modified date corrected. I'm not sure why some of the work but unsupported methods are likely to be flakey.