SageTV Community  

Go Back   SageTV Community > SageTV Products > SageTV Software

Notices

SageTV Software Discussion related to the SageTV application produced by SageTV. Questions, issues, problems, suggestions, etc. relating to the SageTV software application should be posted here. (Check the descriptions of the other forums; all hardware related questions go in the Hardware Support forum, etc. And, post in the customizations forum instead if any customizations are active.)

Reply
 
Thread Tools Search this Thread Display Modes
  #41  
Old 04-07-2018, 07:55 PM
wnjj wnjj is offline
Sage Icon
 
Join Date: Jan 2009
Posts: 1,028
Try setting “seeker/fast_mux_switch=false” in sage.properties (with sage shut down when you edit). I think that forces a complete graph rebuild between shows.
Reply With Quote
  #42  
Old 04-07-2018, 10:15 PM
bigbill's Avatar
bigbill bigbill is offline
Sage Aficionado
 
Join Date: Dec 2006
Location: San Diego, California
Posts: 366
I just edited it and started the service. Looks like I have 4 back to back shows recording tomorrow evening on the same channel.

Thanks! Bill
__________________
Sage Server: SageTV v9.1.8
Hardware Dell T20 Mini Tower, 4th Gen Pentium, 8GB RAM, Win10 Pro 64 bit, 3 x 4TB WD Green, 128GB SSD boot drive. Capture: 2 Dual HDHR, (OTA Winegard HD8200U, CM4221HD), 3 @ STP-HD200's fw=v20100909 TV's: 70", 55" & 40" Sony's - Playon/PlayLater, Blue Iris. FFMPEG script converting MPEG2 to MP4 long term storage.

Motorhome Sage Server: SageTV v9.1.8 Intel NUC6CAYH, HD300, Nvidia Shield 2017, 1 Dual HDHR 4TB Passport storage, Winegard BatWing RV antenna.
Reply With Quote
  #43  
Old 04-07-2018, 11:06 PM
bigbill's Avatar
bigbill bigbill is offline
Sage Aficionado
 
Join Date: Dec 2006
Location: San Diego, California
Posts: 366
I also just corrected the modified timestamp for the show that got screwed up when I moved it this morning. After fixing the mod time I moved it to another drive... It did not remove the red line for the show or fix anything. Bummer.
The log looks very different than this mornings log where it deleted the file first. Then imported it in.

If I get another incorrect time on a file I will try to change the modified date prior to moving it the first time.

-Bill
__________________
Sage Server: SageTV v9.1.8
Hardware Dell T20 Mini Tower, 4th Gen Pentium, 8GB RAM, Win10 Pro 64 bit, 3 x 4TB WD Green, 128GB SSD boot drive. Capture: 2 Dual HDHR, (OTA Winegard HD8200U, CM4221HD), 3 @ STP-HD200's fw=v20100909 TV's: 70", 55" & 40" Sony's - Playon/PlayLater, Blue Iris. FFMPEG script converting MPEG2 to MP4 long term storage.

Motorhome Sage Server: SageTV v9.1.8 Intel NUC6CAYH, HD300, Nvidia Shield 2017, 1 Dual HDHR 4TB Passport storage, Winegard BatWing RV antenna.

Last edited by bigbill; 04-08-2018 at 09:58 AM.
Reply With Quote
  #44  
Old 04-08-2018, 10:09 AM
bigbill's Avatar
bigbill bigbill is offline
Sage Aficionado
 
Join Date: Dec 2006
Location: San Diego, California
Posts: 366
This morning I decided to make a "copy" of that same show I modified the timestamp last night and put it in a drive that Sagetv doesn't use. I then deleted the show via the Sagetv client, using the Delete and Clear Watched button. After that was complete, I moved the file into a sage monitored directory and then ran the Scan Imported Media button under Settings.

That show has been rehabilitated now, It no longer has the red line.

In case this information helps, My SageTV server is:

Windows 10 Version 1709, OS Build 16299.309


-Bill

Next time I need to move a show I will use the Touch command it if it has the erroneous modified time stamp.
__________________
Sage Server: SageTV v9.1.8
Hardware Dell T20 Mini Tower, 4th Gen Pentium, 8GB RAM, Win10 Pro 64 bit, 3 x 4TB WD Green, 128GB SSD boot drive. Capture: 2 Dual HDHR, (OTA Winegard HD8200U, CM4221HD), 3 @ STP-HD200's fw=v20100909 TV's: 70", 55" & 40" Sony's - Playon/PlayLater, Blue Iris. FFMPEG script converting MPEG2 to MP4 long term storage.

Motorhome Sage Server: SageTV v9.1.8 Intel NUC6CAYH, HD300, Nvidia Shield 2017, 1 Dual HDHR 4TB Passport storage, Winegard BatWing RV antenna.
Reply With Quote
  #45  
Old 04-09-2018, 11:00 AM
Narflex's Avatar
Narflex Narflex is offline
Sage
 
Join Date: Feb 2003
Location: Redondo Beach, CA
Posts: 6,301
Quote:
Originally Posted by wnjj View Post
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.
We wrote out our file sink filter...so we won't be subjected to the bug you are referring to here. I'm quite sure we are properly closing the files...or otherwise we would have had bug reports over the years relating to not being able to delete files that just finished recording when another one is on right after it (and we do that behavior a lot because of intelligent recording).

HOWEVER...I just looked at the code for our writer filter (called Dump): https://github.com/google/sagetv/blo.../MPEG2Dump.cpp

And we do close the file differently depending upon whether we did a fast switch or not. It does still look like we close it though. But maybe somebody else will see a problem in there that I don't.

I am very intrigued to know the answer once somebody figures out what's happening here...this is definitely a mystery.
__________________
Jeffrey Kardatzke
Google
Founder of SageTV
Reply With Quote
  #46  
Old 04-09-2018, 12:32 PM
bigbill's Avatar
bigbill bigbill is offline
Sage Aficionado
 
Join Date: Dec 2006
Location: San Diego, California
Posts: 366
I had 4 back to back shows on the same channel record last night. All of them have the correct modified date. Is it because I made this change? “seeker/fast_mux_switch=false” It had be true prior to last nights recordings.

Maybe that will help find out whats happening. My guess is most folks do not move their recordings like i do so they haven't reported this bug yet. It appears that if I do not move the recording the modified date doesn't mess up the timeline. But that is really just a guess as I don't have enough data.

-Bill
__________________
Sage Server: SageTV v9.1.8
Hardware Dell T20 Mini Tower, 4th Gen Pentium, 8GB RAM, Win10 Pro 64 bit, 3 x 4TB WD Green, 128GB SSD boot drive. Capture: 2 Dual HDHR, (OTA Winegard HD8200U, CM4221HD), 3 @ STP-HD200's fw=v20100909 TV's: 70", 55" & 40" Sony's - Playon/PlayLater, Blue Iris. FFMPEG script converting MPEG2 to MP4 long term storage.

Motorhome Sage Server: SageTV v9.1.8 Intel NUC6CAYH, HD300, Nvidia Shield 2017, 1 Dual HDHR 4TB Passport storage, Winegard BatWing RV antenna.
Reply With Quote
  #47  
Old 04-09-2018, 12:41 PM
wnjj wnjj is offline
Sage Icon
 
Join Date: Jan 2009
Posts: 1,028
Quote:
Originally Posted by bigbill View Post
I had 4 back to back shows on the same channel record last night. All of them have the correct modified date. Is it because I made this change? “seeker/fast_mux_switch=false” It had be true prior to last nights recordings.

Maybe that will help find out whats happening. My guess is most folks do not move their recordings like i do so they haven't reported this bug yet. It appears that if I do not move the recording the modified date doesn't mess up the timeline. But that is really just a guess as I don't have enough data.

-Bill
Yes, I believe fast switching is causing the bad modified times, at least on some files. I agree that it's likely always been there (as seen on my system too) but most people don't move the shows around.
Reply With Quote
  #48  
Old 04-09-2018, 04:32 PM
wnjj wnjj is offline
Sage Icon
 
Join Date: Jan 2009
Posts: 1,028
Quote:
Originally Posted by Narflex View Post
We wrote out our file sink filter...so we won't be subjected to the bug you are referring to here. I'm quite sure we are properly closing the files...or otherwise we would have had bug reports over the years relating to not being able to delete files that just finished recording when another one is on right after it (and we do that behavior a lot because of intelligent recording).

HOWEVER...I just looked at the code for our writer filter (called Dump): https://github.com/google/sagetv/blo.../MPEG2Dump.cpp

And we do close the file differently depending upon whether we did a fast switch or not. It does still look like we close it though. But maybe somebody else will see a problem in there that I don't.

I am very intrigued to know the answer once somebody figures out what's happening here...this is definitely a mystery.
Thanks for the clarification. I had forgotten about the writer filter. By closing "differently" I assume you referring to Async vs not? Does non-fast switch close the file when the graph teardown ultimately calls the CMPEG2Dump destructor, which in turn calls CloseFile with FALSE (i.e. not async)?

It looks like file writing is normally done through an AsyncIO worker thread, presumably to keep the main filter receiver loop ready for real-time data (ReceiveCanBlock=false). When fast switch happens, it queues the remaining data and a close request then proceeds to queue the new file stream. Since the new file works fine, I'm at a loss as to why the previous file didn't get the modified date set since the thread is still working normally. Everything I've read says the modified time stamp happens when you call CloseHandle and as you said, files don't seem to be locked indicating they are closed.

As for why many, but not most back-to-back files have this issue I'm wondering if the difference is whether they fall into the 5 second timeout revert to non-seamless switch or something else is causing an issue in how the async thread runs. Either one could be randomly affected by what the system or disk is doing and how 'CloseFile' is used.

It's possible that something at the OS or HDD driver level (caching?) has changed with regard to file close/time stamps causing this to show up in recent years, again only noticeable if you move back-to-back files around with fast switch on.

I can't see anything obvious yet but will keep looking. Using that dll with dump logging enabled from months ago may reveal something.
Reply With Quote
  #49  
Old 04-09-2018, 06:08 PM
Narflex's Avatar
Narflex Narflex is offline
Sage
 
Join Date: Feb 2003
Location: Redondo Beach, CA
Posts: 6,301
Quote:
Originally Posted by wnjj View Post
Thanks for the clarification. I had forgotten about the writer filter. By closing "differently" I assume you referring to Async vs not?
Yes
Quote:
Originally Posted by wnjj View Post
Does non-fast switch close the file when the graph teardown ultimately calls the CMPEG2Dump destructor, which in turn calls CloseFile with FALSE (i.e. not async)?
Yeah...I'm pretty sure that's how that works.

Quote:
Originally Posted by wnjj View Post
It looks like file writing is normally done through an AsyncIO worker thread, presumably to keep the main filter receiver loop ready for real-time data (ReceiveCanBlock=false). When fast switch happens, it queues the remaining data and a close request then proceeds to queue the new file stream. Since the new file works fine, I'm at a loss as to why the previous file didn't get the modified date set since the thread is still working normally. Everything I've read says the modified time stamp happens when you call CloseHandle and as you said, files don't seem to be locked indicating they are closed.
Yeah, I didn't see anything wrong...but the correlation of the 2 different code paths and the results people are posting are interesting. If somebody had an example of a bad timestamp that was NOT from a back-to-back recording then we're probably looking in the wrong place.

Quote:
Originally Posted by wnjj View Post
As for why many, but not most back-to-back files have this issue I'm wondering if the difference is whether they fall into the 5 second timeout revert to non-seamless switch or something else is causing an issue in how the async thread runs.
I also noticed a 'double free' if that timeout occurs, which could also possibly crash recording...so I'm guessing that timeout doesn't happen too often (and it really should never happen).

Quote:
Originally Posted by wnjj View Post
Either one could be randomly affected by what the system or disk is doing and how 'CloseFile' is used.

It's possible that something at the OS or HDD driver level (caching?) has changed with regard to file close/time stamps causing this to show up in recent years, again only noticeable if you move back-to-back files around with fast switch on.

I can't see anything obvious yet but will keep looking. Using that dll with dump logging enabled from months ago may reveal something.
Good luck! It's also interesting that this problem never came up in the prior 14 years of people using SageTV....which makes me very suspicious it's a Windows update that's causing this problem. Would be good to check on OS correlation to this problem if that wasn't done already.
__________________
Jeffrey Kardatzke
Google
Founder of SageTV
Reply With Quote
  #50  
Old 04-10-2018, 09:25 PM
wnjj wnjj is offline
Sage Icon
 
Join Date: Jan 2009
Posts: 1,028
Quote:
Originally Posted by Narflex View Post
Yes
I also noticed a 'double free' if that timeout occurs, which could also possibly crash recording...so I'm guessing that timeout doesn't happen too often (and it really should never happen).



Good luck! It's also interesting that this problem never came up in the prior 14 years of people using SageTV....which makes me very suspicious it's a Windows update that's causing this problem. Would be good to check on OS correlation to this problem if that wasn't done already.
I see that extra file name “delete” in there too.

Here’s another idea to consider that might explain the apparent sync/async file close dependency. When the switchover is done async, the final writing and closing is left in a native worker thread which may take some time to compete. Meanwhile the java code continues on, calling “completeFileSwitch” which among other things inserts the metadata into the media file. I wonder if there’s an intermittent conflict between the native writing & closing and the metadata insertion. One way to test this is to disable metadata using the property seeker/mpeg_metadata_embedding=false and then record a bunch of back to back shows.

Metadata insertion hasn’t been around for as many years although plenty long enough. It could be a mix of OS or even Java updates affected this.

EDIT: I think I found it for sure now. Looking where the metadata is written there is this:

Code:
    // PRESERVE TIMESTAMP ON THE FILE!!!
    long fileTime = f.lastModified();
So if the metadata process starts before the native thread has closed the file, it fetches the CREATION time since MODIFIED hasn’t been updated yet. Then, once the metadata is written, it resets the modified time back the original creation time it saved.

The solution requires some signal from the native code that the file is closed or the MPEGDump’s SetOutputFile function needs to loop until the original file is closed before returning to Javaland when doing a switch.

Last edited by wnjj; 04-10-2018 at 10:16 PM.
Reply With Quote
  #51  
Old 04-11-2018, 06:16 PM
Narflex's Avatar
Narflex Narflex is offline
Sage
 
Join Date: Feb 2003
Location: Redondo Beach, CA
Posts: 6,301
That looks like a very real possibility as the culprit. Impressive sleuthing!

Can someone who has this problem do the test he suggests by setting seeker/mpeg_metadata_embedding=false? Once that's verified I have a few ideas how to fix this in Java (since fixing things in the Windows code is not something I can really do since I have no way to compile/test that anymore since I'm Windows free now).
__________________
Jeffrey Kardatzke
Google
Founder of SageTV
Reply With Quote
  #52  
Old 04-11-2018, 06:33 PM
wnjj wnjj is offline
Sage Icon
 
Join Date: Jan 2009
Posts: 1,028
Quote:
Originally Posted by Narflex View Post
That looks like a very real possibility as the culprit. Impressive sleuthing!

Can someone who has this problem do the test he suggests by setting seeker/mpeg_metadata_embedding=false? Once that's verified I have a few ideas how to fix this in Java (since fixing things in the Windows code is not something I can really do since I have no way to compile/test that anymore since I'm Windows free now).
It looks like my recording schedule is empty tonight. I’ll queue up a bunch of back to back recording. I’ll wait for some bad ones before switching the setting.

One option in Java may be to compare the modified time to the current time or scheduled time and if it’s off more than X, wait until it isn’t (with a timeout).

Last edited by wnjj; 04-11-2018 at 08:41 PM.
Reply With Quote
  #53  
Old 04-11-2018, 08:39 PM
wnjj wnjj is offline
Sage Icon
 
Join Date: Jan 2009
Posts: 1,028
It turns out I do have some legit recordings for later tonight. I did manage to record 4 shows (with others after) with metadata embedding turned off and all were fine. Generally about half of the previous shows that had others after had messed up times.

I turned the metadata setting back on since I want the metadata in my legit shows. There's some back to back recording scheduled and I'm guessing at least one will be wrong when I check again tomorrow.
Reply With Quote
  #54  
Old 04-13-2018, 06:31 PM
wnjj wnjj is offline
Sage Icon
 
Join Date: Jan 2009
Posts: 1,028
One of 3 back to back were bad with metadata on again. I'm really confident that's the issue.
Reply With Quote
  #55  
Old 04-16-2018, 12:57 PM
Narflex's Avatar
Narflex Narflex is offline
Sage
 
Join Date: Feb 2003
Location: Redondo Beach, CA
Posts: 6,301
Do you want to do the Java fix? I'm not sure when exactly I'd get around to it...and you're great for testing it.

All I was thinking of doing was changing sage.media.format.MpegMetadata.addFileMetadata and adding another parameter for 'long targetFileTime'. If it's zero, (which you'd pass from the main invocation) behave as usual. But if it's more than X amount of time (maybe 30 seconds) off from the file's timestamp...then use the targetFileTime rather than the lastModified time from the file when setting the file modification time. And then in addMediaFileMetadata in that same class, pass in MediaFile.getRecordEnd() (which should match the end time very closely).

Then we don't need to worry about the asynchronous closing stuff in native code which is far more complicated to fix.

If you're not comfortable doing a Java change...let me know and I'll do it...but not test it..and then let you test it (assuming you know how to build the open source Sage.jar).
__________________
Jeffrey Kardatzke
Google
Founder of SageTV
Reply With Quote
  #56  
Old 04-16-2018, 03:52 PM
wnjj wnjj is offline
Sage Icon
 
Join Date: Jan 2009
Posts: 1,028
Quote:
Originally Posted by Narflex View Post
Do you want to do the Java fix? I'm not sure when exactly I'd get around to it...and you're great for testing it.

All I was thinking of doing was changing sage.media.format.MpegMetadata.addFileMetadata and adding another parameter for 'long targetFileTime'. If it's zero, (which you'd pass from the main invocation) behave as usual. But if it's more than X amount of time (maybe 30 seconds) off from the file's timestamp...then use the targetFileTime rather than the lastModified time from the file when setting the file modification time. And then in addMediaFileMetadata in that same class, pass in MediaFile.getRecordEnd() (which should match the end time very closely).

Then we don't need to worry about the asynchronous closing stuff in native code which is far more complicated to fix.

If you're not comfortable doing a Java change...let me know and I'll do it...but not test it..and then let you test it (assuming you know how to build the open source Sage.jar).
Seems simple enough and nice that it's contained to a single file. I've built the jar before and it was easy enough but it's been awhile. I suppose it's also a good time to update my system anyway since I'm still running the version from last June. None of the updates so far had affected me.

When I get time, I'll grab the latest code, make the edits, compile and test locally to prove the concept. After that I'll have to figure out how to submit a pull request. I'll also need added to the official authors, whatever that takes. Alternatively I could just have you check in the changes too. It looks like minor changes to the function calls to pass in '0' or mf.getEndRecord() and "if ((targetFileTime !=0) && (Math.abs(fileTime - targetFileTime) > 30000)) fileTime=targetFileTime;" in the main function.
Reply With Quote
  #57  
Old 04-16-2018, 09:07 PM
wnjj wnjj is offline
Sage Icon
 
Join Date: Jan 2009
Posts: 1,028
Code change is made and deployed on my system. Will know in a day or two if the messed up timestamps stop. I'll queue up some back-to-back recordings. I added a debug log print when the 'if' happens so we can prove it's needed. That can be removed for release.

Last edited by wnjj; 04-16-2018 at 10:36 PM.
Reply With Quote
  #58  
Old 04-17-2018, 08:37 AM
wnjj wnjj is offline
Sage Icon
 
Join Date: Jan 2009
Posts: 1,028
Success!

I added this code:
Code:
  public static void addFileMetadata(java.io.File f, int type, String metadataStr, long targetFileTime) throws java.io.IOException
  {
    int i, j, packetcount=0;
    int pos=0;
    // PRESERVE TIMESTAMP ON THE FILE!!!
    long fileTime = f.lastModified();
    // Async file writes may not have updated the modified time yet.  Use the target end time in that case.
    if ((targetFileTime != 0) && (Math.abs(fileTime - targetFileTime) > 30000))
    {
      if (sage.Sage.DBG) System.out.println("Corrected modified time of " + f.getName() + " from " + fileTime + " to " + targetFileTime);
      fileTime = targetFileTime;
    }
After about 4 shows, I had this in my log file:
Code:
Tue 4/17 0:30:00.606 [Seeker@a5e79b] Corrected modified time of PerryMason-TheCaseoftheReluctantModel-8622997-0.mpg from 1523946600144 to 1523950200010
So that proves the time was off when fetched here. The final code changes are:
Code:
        addFileMetadata(f, new Integer(args[2]).intValue(), args[3], 0);
,
Code:
      addFileMetadata(mf.getFile(0), type, rv.toString(), mf.getRecordEnd());
and
Code:
  public static void addFileMetadata(java.io.File f, int type, String metadataStr, long targetFileTime) throws java.io.IOException
  {
    int i, j, packetcount=0;
    int pos=0;
    // PRESERVE TIMESTAMP ON THE FILE!!!
    long fileTime = f.lastModified();
    // Async file writes may not have updated the modified time yet.  Use the target end time in that case.
    if ((targetFileTime != 0) && (Math.abs(fileTime - targetFileTime) > 30000))
      fileTime = targetFileTime;
Jeff, if you want to submit them, feel free. I've yet to get on the authors list or ever use Github to submit any code.
Reply With Quote
  #59  
Old 04-17-2018, 11:10 AM
Narflex's Avatar
Narflex Narflex is offline
Sage
 
Join Date: Feb 2003
Location: Redondo Beach, CA
Posts: 6,301
Great, thanks for testing that out...and awesome work finding the source of the problem!

I've pushed the changed to GitHub now so whenever the next build is done, it'll be in there.
__________________
Jeffrey Kardatzke
Google
Founder of SageTV
Reply With Quote
  #60  
Old 04-17-2018, 11:40 AM
wnjj wnjj is offline
Sage Icon
 
Join Date: Jan 2009
Posts: 1,028
Quote:
Originally Posted by Narflex View Post
Great, thanks for testing that out...and awesome work finding the source of the problem!

I've pushed the changed to GitHub now so whenever the next build is done, it'll be in there.
Thanks. Happy to help.

Nice work identifying a simple, Java-only fix.
Reply With Quote
Reply


Currently Active Users Viewing This Thread: 1 (0 members and 1 guests)
 
Thread Tools Search this Thread
Search this Thread:

Advanced Search
Display Modes

Posting Rules
You may not post new threads
You may not post replies
You may not post attachments
You may not edit your posts

BB code is On
Smilies are On
[IMG] code is On
HTML code is Off

Forum Jump

Similar Threads
Thread Thread Starter Forum Replies Last Post
Recording Playback Issues Post Upgrade SteveW SageTV Github Development 14 01-19-2017 12:19 PM
Extender issues after start TV recording playback starfire SageTV Github Development 30 11-08-2016 11:00 AM
HD200 - cool, but 2 issues - memory & playback issues with hdpvr agover SageTV Media Extender 3 12-16-2008 12:50 PM
Vista 64 Recording playback issues HELP!!! chrisc983 SageTV Software 1 05-08-2008 12:59 AM
Why only 2 weeks snoopy SageTV EPG Service 2 10-12-2006 08:38 PM


All times are GMT -6. The time now is 07:30 PM.


Powered by vBulletin® Version 3.8.7
Copyright ©2000 - 2019, vBulletin Solutions, Inc.
Copyright 2003-2005 SageTV, LLC. All rights reserved.