Odd recording/Playback issues over the last two weeks.

[wnjj]

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.

[bigbill]

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

[bigbill]

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

[bigbill]

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.

[Narflex]

Originally Posted by wnjj

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.

[bigbill]

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

[wnjj]

Originally Posted by bigbill

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.

[wnjj]

Originally Posted by Narflex

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.

[Narflex]

Originally Posted by wnjj

Thanks for the clarification. I had forgotten about the writer filter. By closing "differently" I assume you referring to Async vs not?

Yes

Originally Posted by wnjj

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.

Originally Posted by wnjj

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.

Originally Posted by wnjj

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).

Originally Posted by wnjj

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.

[wnjj]

Originally Posted by Narflex

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:

    // 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.

[Narflex]

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).

[wnjj]

Originally Posted by Narflex

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).

[wnjj]

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.

[wnjj]

One of 3 back to back were bad with metadata on again. I'm really confident that's the issue.

[Narflex]

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).

[wnjj]

Originally Posted by Narflex

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.

[wnjj]

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.

[wnjj]

Success!

I added this 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:

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:

        addFileMetadata(f, new Integer(args[2]).intValue(), args[3], 0);

,

      addFileMetadata(mf.getFile(0), type, rv.toString(), mf.getRecordEnd());

and

  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.

[Narflex]

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.

[wnjj]

Originally Posted by Narflex

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.