Print

Please login or register.
1 Hour 1 Day 1 Week 1 Month Forever
Login with username, password and session length

[RoderickGI]

Has anyone else been seeing this?

For a while now I've been seeing a popup error saying one or more files from a JTV recording set are in use when I tag the recording in the Recording Rule for "Filename (path)", to move the recording at the end of the process.

See the first image for the error message, and the second for the Recording Rule tagging section.

My EPG isn't very complete or accurate these days, so as you can see in the example, I first ensure the tags I want for Series and Season exist, and then I use them in the "Filename (path)" tag. I thought that perhaps the Series and Season tags weren't being written, or otherwise weren't available, before the "Filename (path)" tag is written, and that may have been the issue. But I have changed one of my Rules so that all the data for the "Filename (path)" tag is hard coded, and I think (not positive) that the issue still occurs.

The problem doesn't always seem to happen, as I have two Rules that record every day, and I don't see the error popup every day.

If the error occurs the JTV recording set is usually broken, although sometimes with careful copying and replacing of files, I can recover it. In this last example, three *.cnk files were missing in the JTV set that was mostly correctly moved, but they were available in the original location to move across, after I skipped the error message. Trying Again on the error message never works, even after a long wait. Also the base *.jta, *.jtf, and *.jts files were duplicated, with one set in each location. One set seemed to be created at the start of the recording, and one set at the end of the recording. Either set of these last three files could be used to make a working playable set of JTV files.

So it appears that a somewhat random set of usually four to six files are being held open by MC, so that the Recording Rule tagging function can't move the files.

I haven't been able to catch a log of the issue as yet, because it occurs randomly. This could be related to MCs habit of randomly holding files open after it has finished with them. Yes, that happens.


Anyway, today I looked at the rule and noticed that there is a default "[Filename]" parameter in the new (well, recent) Run Command below tagging fields. See red arrow in second image. I'm wondering if that has something to do with the problem. i.e. Is MC trying to run a blank command with the command line argument of [Filename] for every rule, or any rule that has a value in that field?

Therefore I have deleted the default "[Filename]" parameter from two of my daily rules ("ABC News" and "Spicks And Specks") and I will see if the issue stops for those programs. Both are still using the tag [Series] in the "Filename (path)" tagging rule.

I shall update as I have information.

[CountryBumkin]

I don't use/have the command line argument. Are you saying MC added this itself recently?
I'll look again when I get home - in case this is something that just changed or happened with the last update.

[Yaobing]

I have been puzzled by MC sometimes not been able to delete/move some of these files.  That was part of the reason why I implemented "Clean up time-shifting folder" tool.

A couple of clarifications:

When recording in JTV format, JTF and JTI files are created for each recording, along with the original time-shifting set.  So you will see multiple sets of such files.  On the other hand, JTA and JTS files are shared.  There should be only one set, except the temporary sets created during file copy/move operations (with TEMP in the filename).  Due to some coding constraints, I need to make in-place duplication first, then move the duplicates to destination, instead of just copy file sets to the destination.

The [filename] default value in command line parameters will not cause problems because we made sure we do not execute anything unless the actual command is not empty.

[RoderickGI]

I have been puzzled by MC sometimes not been able to delete/move some of these files.  That was part of the reason why I implemented "Clean up time-shifting folder" tool.

I am convinced MC does hold on to files sometimes well past when it needs to. People have reported lots of different scenarios that pointed to the file still being locked by MC as the cause of an issue. Possibly a threading issue, or just timing.
EDIT: Here is another example of MC holding a file after it should. One I haven't seen before. https://yabb.jriver.com/interact/index.php/topic,117420.0.html It is a global issue.

Even if I leave the error message up on the screen and wait for MC to release the file, it never happens. I usually get a sequence of these errors, one after the other, so that if I skip one the next pops up and so on. If these files had been released by MC after a wait I would expect the later messages wouldn't happen.

So the issue could tie back to MC not releasing the files, which is a generic problem. I will note that cnk files that I get error messages for are usually from early in the recording, and not the later files. So I would expect them to be released. It seems that MC just forgets or fails to release them.

When recording in JTV format, JTF and JTI files are created for each recording, along with the original time-shifting set.  So you will see multiple sets of such files.

Yep, I do see multiple sets of JTF and JTI files, for all recordings. The second with a " (1)" added in the form;
"MotoGP 2018 2018-09-14.jtf" and "MotoGP 2018 2018-09-14 (1).jtf".
"MotoGP 2018 2018-09-14.jti" and "MotoGP 2018 2018-09-14 (1).jti".

On the other hand, JTA and JTS files are shared.  There should be only one set, except the temporary sets created during file copy/move operations (with TEMP in the filename).

In the example I am using at the moment there were two identical sets, one in the original directory, and one in the target directory for the move. Identically named as "MotoGP 2018 2018-09-14.jta" and "MotoGP 2018 2018-09-14.jts". The ones in the original directory were time stamped at the beginning of the recording, and the ones in the target directory were time stamped at the end of the recording. So maybe a product of the failed move, or... something.

The [filename] default value in command line parameters will not cause problems because we made sure we do not execute anything unless the actual command is not empty.

Excellent. I shall eliminate that from my list of possible causes.

I shall test with different configurations of Recording Rules and see if I can identify a consistent cause.

I don't use/have the command line argument. Are you saying MC added this itself recently?
I'll look again when I get home - in case this is something that just changed or happened with the last update.

As per the image, the value "[Filename]" was inserted by MC into the "Command line arguments" field, but nothing is in the "Run command" field. I don't know when that started happening. I have never used a Post-processing command with my Recording Rules.

24.0.2 (2/23/2018)
4. NEW: TV Recording rules may include running a Post-processing command (ComSkip for example) at the end of recording.

24.0.16 (4/18/2018)
7. NEW: Added a television option "If a recording rule does not include tagging or post-process command, apply respective defaults."

I don't have any Post-processing defaults set up, and I don't have this setting turned on.

[RoderickGI]

I have been testing this further, with a couple of Recording Rules that set a tag before then using it in the "Filename (path)" in Recording Rule. See the second image in the first post for a MotoGP example.

I have only seen the error once since my last post, so it certainly isn't consistent. I have now changed the associated recording rule to set the tags, but then explicitly defined the "Filename (path)" in Recording Rule instead of using tags. I shall see if the issue is repeated.

I did do a cleanup of recordings a couple of days ago, and there was quite a bit of evidence that this had been happening a bit. Just not for every recording using a rule that uses a tag in the "Filename (path)" in Recording Rule, and not for every Recording Rule that uses that technique. It is quite frustrating, because it is making recordings unreliable, given that I use the "Filename (path)" in Recording Rule technique a lot these days.

[Yaobing]

Setting other tags ([Series], etc.) before setting [Filename (path)] should be fine, at least in theory.  All tags that do not involve file path are set at the start of recording, including [Filename (name)].  Only [Filename (path)] and [Filename] (only one of these take effect, by the way, if you specify both which you should not) are set at the end of recording.

[RoderickGI]

Okay, that clarifies things a bit.

I can see that I am going to have to try to catch a log of one of these events. Not an easy thing to do given they are so unpredictable.

It looks like it is just coming down to MC occasionally holding files open longer than it should. Not an easy thing to resolve.

[RoderickGI]

This problem still seems to be occurring after the attempted fix in MC24.0.55.
24.0.55 (9/28/2018)
5. Changed: TV recordings' post-recording processing is done slightly later to avoid conflicts.  This is an attempt to fix post-recording file moving failures of JTV recordings.


I still see no pattern.

Tonight it was an episode of "The Making Of David Attenborough's Conquest Of The Skies".

Attached is an image showing the original files location before the [Filename (path)] move, and the destination directory. I have added notes to the image to show what is going on.

Although this example is with a particularly long file name, I often see this for the program "ABC News" which creates very short paths and filenames.

If I search the Log file for "David Attenborough's Conquest Of The Skies 2018-10-06" I find plenty of references, but if I search for one of the specific files that can't be moved, "The Making Of David Attenborough's Conquest Of The Skies 2018-10-06-0.jts.cnk", then I get no hits. So the problem file doesn't seem to be referenced in the log.

Maybe you can make more sense of the log Yaobing.

I will upload the 6MB log file to OneDrive and post a link here shortly.

EDIT: Here is the log. https://1drv.ms/u/s!Ak8KH39qCkz1idYx-ltuVGThWexFag

[Yaobing]

The recording ended at 4 pm.  The Previous Log.txt was started 5:19 pm, in which the only "StopRecording" logged was for "ABC News".  Do you have logging automatically reset?  If so, try setting the size limit higher.

[RoderickGI]

Oops. I think I have the log set to 100 MB. I'll have to check.

There may have been an upgrade to MC24.0.56, or a PC reboot for another software upgrade, which reset the log.

Sorry to give you a false start. This was the first occurrence for a while. I'll try again.

[RoderickGI]

I had the problem again last night, but didn't find the error message boxes until tonight.

Unfortunately the program finished at about 4am today, but the 6MB Previous Log started at 4pm, so the problem was missed again. I have now set the log at 1GB in the hope of catching the problem.

What I will note though is that the four *.cnk files that were left in the original directory cannot be moved to the correct destination directory using Windows Explorer to fix the recording, because Windows says that files are still in use... by MC24... 12 hours after the recording finished, and 16 hours after the file "Date modified". Sysinternal's Process Explorer confirmed all four files were still locked by Media Center 24.

Even closing down tme Media Center UI and Media Server didn't clear the lock. There was still a MC task in Task Manager, which was still using 34MB of memory and had 0.1MB/s Disk usage. I had to kill that process in order to clear the file locks, confirmed in Process Explorer, and then I could move the four files. Then I could successfully play the recording.

So MC is leaving an orphaned thread by the look of it, which stays forever and keeps the files locked. I've seen these orphaned threads before. I think we all have.

Once again, I shall try to catch this is a log.

[RoderickGI]

I had another "File in use" error tonight. This time for the daily "ABC News" recording. The recording started at 8/10/2018 @ 6:55pm and continued to7:40pm, including padding, and I have a log that covers 22 hours 18 minutes from 7/10/2018 9:22 pm, which means it finished at 7:40pm 8/10/2018. Basically, I was watching a show and the error message popped up, so I selected "Skip" for each file in use, and then saved the log.

The log file is here: https://1drv.ms/u/s!Ak8KH39qCkz1idYy23pOI1oKavujIw

The image attached shows the original recording location (E:\Recorded TV\ABC News 2018-10-08\) in the top window and the destination recording location (E:\Recorded TV\ABC News\ABC News 2018-10-08\) in the bottom window.

You will see that all but four *.cnk files have been moved, as before, and new *.jta, *.jtf, and *.jts files have been created.

Note the small size of the "ABC News 2018-10-08-7.jts.cnk", while all other *.jts.cnk files are 180,000 KB. That was also apparent for one of the *.jts.cnk files yesterday.

Here is an interesting twist though; those new *.jta, *.jtf, and *.jts files are still being updated at this moment, even though the recording is long finished, over an hour ago. In the image they have a date modified of 8:18 and 8:19 pm, but they are now up to 8:51 and 8:52 pm!

I assume there is a thread still running for the recording, as happened yesterday, and it is trying to complete the recording, or finish moving the files? I couldn't really check that properly as while I was writing the above MC locked up and I had to select to Close it. That still left a Media Center process running, JRservice, but the file locks were removed and I could move the file to the destination directory.

So, if willing, see if you can find anything in the log file. I couldn't find anything significant. In fact, I couldn't even find any reference to moving the files at the end of the recording. Mind you, there are a lot of message like;

80303844: 2728: TV: CTSFileReader::ReadSampleHeader: Caught up with writer (A) while in normal speed. Limit(27028814026), Current(27028814026), last good one (27028814026), bytes read 0
80303844: 2728: TV: CTSFileReader::ReadSampleHeader: Index Limit(112603), Current(112603).  Failure count 1813

which I don't understand, but could be MC still trying to write to the *.cnk files. The index has hit the index limit?

There are also reference to popup windows, which I assume are the "File in use" error messages;
80301234: 1808: General: CMCResourceHelper::GetIsModalPopupShowing: Main window disabled


I am wondering now, hard disk issues? The disk shows as healthy though. I might run a Disk Check... All fine. No errors.

[JimH]

I am wondering now, hard disk issues? The disk shows as healthy though. I might run a Disk Check... All fine. No errors.

Antivirus?

[Yaobing]

Note the small size of the "ABC News 2018-10-08-7.jts.cnk", while all other *.jts.cnk files are 180,000 KB. That was also apparent for one of the *.jts.cnk files yesterday.

The small size probably just means it is the last chunk of data.  Do you see any such file higher than "7" in that recording?
It seems that we have trouble moving the first chunk and the last chunk.

80303844: 2728: TV: CTSFileReader::ReadSampleHeader: Caught up with writer (A) while in normal speed. Limit(27028814026), Current(27028814026), last good one (27028814026), bytes read 0
80303844: 2728: TV: CTSFileReader::ReadSampleHeader: Index Limit(112603), Current(112603).  Failure count 1813

which I don't understand, but could be MC still trying to write to the *.cnk files. The index has hit the index limit?

These are for shows that you were watching.  It usually happens when watching reaches live point.  Not a big concern unless MC never gets out of it.

I will have a look of the log.

[Yaobing]

For a moment I thought I found a cause, but when I tested it, I could not reproduce.

What I thought was watching the show while recording is finishing up might have caused it. The "Caught up with writer" messages were caused by the watching thread.  Apparently the files were already moved away but somehow someone was still trying to access them.

Were you watching the show on the server machine or a client machine?

We should have already reference counted the recordings so it really should not have happened.

EDIT: It looks more like JRAnalyzer is accessing the files during the importing process, instead of a user watching the show.

[Yaobing]

Here is the weird thing:

At about 7:15 pm, 20 minutes into the recording, some background process started, which called Get Movie & TV Info, built thumbnail, and called AnalyzeAudio function on the file.  Why AnalyzeAudio?  I don't know.  It loaded the DirectShow wavefeeder, which built a DirectShow graph and started running it.  It appears that when it ended, the graph was not cleaned up properly.  The reader filter for JTV file kept running.  It seemed to be running at a fast speed (it started at 20 minutes into the recording, but in one minute or so it caught up with the end of recording).  It kept trying to read data that had not been written yet, thus producing "Caught up with writer (A)..." log lines.  I believe this was the reason the files were held up and could not be moved. 

[RoderickGI]

The small size probably just means it is the last chunk of data.  Do you see any such file higher than "7" in that recording?
It seems that we have trouble moving the first chunk and the last chunk.

The file "ABC News 2018-10-08-7.jts.cnk" was indeed the last *.jts.cnk" file, and of course the "ABC News 2018-10-08-0.jts.cnk" was the first.

The file "ABC News 2018-10-08-22.jta.cnk" was the last *.jta.cnk files, but the "ABC News 2018-10-08-10.jta.cnk" wasn't the first. But it does have a "Date modified" of 7:17pm, while "ABC News 2018-10-08-9.jta.cnk" has a "Date modified" of 7:15pm. So yes, it looks like something happened at 7:15pm.

Were you watching the show on the server machine or a client machine?

I wasn't watching any of these shows from recent errors, and no Clients were watching it. I may have still had a MC Client open on my Workstation, but I don't think so. Last night I was watching a program that wasn't recorded locally when the error popped up at 7:40pm.

EDIT: It looks more like JRAnalyzer is accessing the files during the importing process, instead of a user watching the show.

I noticed the JRAnalyzer log records. I think I saw that the JRAnalyzer was then repeated again later, for the same recording, perhaps this is a clue...

Here;
   Line 1159142: 80245812: 11860: Import: JRAnalyzer::AddFile: Filename: E:\Recorded TV\ABC News 2018-10-08\ABC News 2018-10-08.jtv

This occurred at 7:40pm. It is analysing the recording in its original location. But the program finished at 7:40pm, so MC would have been trying to move that file at that time. But I couldn't find any log entry for the files being moved, so I don't know if there is a conflict there.

Then;
   Line 1159476: 80246250: 9172: Import: JRAnalyzer::AddFile: Start
   Line 1159477: 80246250: 9172: Import: JRAnalyzer::AddFile: Filename: E:\Recorded TV\ABC News 2018-10-08\ABC News 2018-10-08.jtv
   Line 1159478: 80246250: 9172: Import: JRAnalyzer::AddFile: Start
   Line 1159479: 80246250: 9172: Import: JRAnalyzer::AddFile: Filename: E:\Recorded TV\ABC News 2018-10-08\ABC News 2018-10-08.jtv

About half a second later, consecutive log entries, different process number, different parameters, both finish with success. Is this normal?



Thanks to your last post, I think I found the issue.

I had the "E:\Recorded TV\" directory included in the Auto Import settings. We have discussed this previously, and you informed us this isn't required, as MC will import new TV recordings anyway. I removed those settings back then, but I must have restored a Library that still had them in, reinstating the settings.

My bad.

I have removed the "E:\Recorded TV\" directory from Auto Import again, and I shall watch and see if the problem recurs.

Still, if this is the problem, it is a bit of a trap for young players. Or even old hands like me! I would have though MC would manage that situation gracefully. But it is a user error.

It makes sense that Auto Import kicked in at 7:15pm and imported the program, running Get Movie & TV Info, built thumbnail, and called AnalyzeAudio function on the file. It also makes sense that if Auto Import of the TV recording directory is causing this problem, the error happens on apparently random occasions, as it requires Auto Import to run in the background during a recording, which doesn't always happen.

It seems that this advice https://yabb.jriver.com/interact/index.php/topic,77361.msg525984.html#msg525984 is now wrong, or at least is out of date. I couldn't find our more recent discussions on the topic with a quick search.
Ah, this one is more up to date https://yabb.jriver.com/interact/index.php/topic,116899.msg808622.html#msg808622
This is one of the discussions I was thinking of https://yabb.jriver.com/interact/index.php/topic,116693.msg806911.html#msg806911

--------------------------

One thing I did notice in trying to understand the logs is that there is no logging of the file move done using a [Filename (path)] or similar tag. This did make it harder to understand what was going on. It would be good if the move was logged.

I searched the log for "E:\Recorded TV\ABC News\" to try to find such a move, but only found the successful News recording from the previous day, and the processing of that recording by MC after the file move. i.e. "E:\Recorded TV\ABC News\ABC News Sunday 2018-10-07\ABC News Sunday 2018-10-07.jtv"

[Yaobing]

My bad.

I have removed the "E:\Recorded TV\" directory from Auto Import again, and I shall watch and see if the problem recurs.

Still, if this is the problem, it is a bit of a trap for young players. Or even old hands like me! I would have though MC would manage that situation gracefully. But it is a user error.

We definitely need to make this behave more gracefully.

[Yaobing]

I have removed the "E:\Recorded TV\" directory from Auto Import again, and I shall watch and see if the problem recurs.

You should also look at the setting "Analyze audio for video files" in "Configue Auto Import".  I had a lot of trouble understanding why the TV recording gets analyzed in AnalyzeAudio() function.  The background auto-import process collects a number of files to be analyzed, but in your instance, that collection was done before the TV program started being recorded.  It ended up being analyzed, I believe, because of that option, the function checks the option and loads video files on the fly.

[RoderickGI]

Well, I do want audio analysed in videos, both videos imported separately and TV recordings, so that I get the benefits volume leveling and so on. The volume in videos can be all over the place otherwise.

But as my TV Recording directory has now been removed from Auto Import, at least it shouldn't happen during a recording, but as part of the TV Recording import process at the end of the recording. Is it included as part of the TV Recording import process?

In fact, what settings define what processes are included in the TV Recording import process?
Does it read the Tasks setting from Auto Import? It probably should, for consistency.
Or are the steps all hard coded into the TV Recording import process?

[RoderickGI]

I've had another occurrence of the problem even without the TV Recording directory being watch by Auto Import.

This time the log clearly shows that MC runs the get thumbnail, get Cover Art, Get TV & Movie Info, and AnalyzeAudio processes before the recording stops.

The problem is for the ABC News recording again, "E:\Recorded TV\ABC News 2018-10-10\ABC News 2018-10-10.jtv", which should get moved to "E:\Recorded TV\ABC News\ABC News 2018-10-10\ABC News 2018-10-10.jtv".

The first and last *.jts.cnk, and the last two *.jta.cnk files don't get moved, and are still locked.

When I tried to exit the options dialogue after checking the setting again, MC locked up. When I killed MC the MC24 Service process was left running in Windows, but the files were unlocked. The recording was playable once I manually moved all the *.cnk files.

The attached image shows the files with date and times. It is a 5+30+10 minute recording, starting at 6:55pm and finishing at 7:45pm.

I'll upload the log to OneDrive shortly. Here it is: https://1drv.ms/u/s!Ak8KH39qCkz1idYzc1_6gQluH_TkuQ

If you think this is something in my environment or setup, please let me know. I always suspect Windows Updates these days, but this has been going on for a while, so at least recent updates shouldn't be the cause.

[Yaobing]

I am working on ignoring the files that are currently being recorded when AnalyzeAudio.