This project has moved. For the latest updates, please go here.

Ideas why WMC is locking recording beyond end?

Apr 28, 2016 at 6:21 PM
I use Windows Media Center (on Windows 7 Ultimate 32-bit) for my OTA recordings. It is set up to start recording 3 minutes before and stop 3 minutes after episodes. MCEBuddy is configured to wait 1 minute once a file is available for conversion. Most of the time, though, it is upwards of 10-15 minutes before MCEBuddy thinks the file is available. Not that it shows much, but here is a log excerpt. As you can see, the recording starts at 6:57PM. From the WTV file, I confirmed that it should have ended at 8:03PM, but MCEBuddy doesn't "see" it until 8:16PM:
WARNING> 2016-04-27T18:57:56 MCEBuddy.Engine.QueueManager --> Monitor task Recorded TV : Unable to queue file for conversion - file inaccessible/locked by another process W:\Recorded TV\Survivor- Kaoh Rong - Brains vs. Brawn vs. Beauty_KTVTD_2016_04_27_18_57_00.wtv

2016-04-27T20:16:56 MCEBuddy.Engine.QueueManager --> Monitor task Recorded TV : File W:\Recorded TV\Survivor- Kaoh Rong - Brains vs. Brawn vs. Beauty_KTVTD_2016_04_27_18_57_00.wtv was last modified at 04/27/2016 20:16:00. Waiting for atleast 1 minutes before processing.
2016-04-27T20:17:56 MCEBuddy.Engine.QueueManager --> Monitor task Recorded TV : Checking Filter and Metadata Matches for File -> W:\Recorded TV\Survivor- Kaoh Rong - Brains vs. Brawn vs. Beauty_KTVTD_2016_04_27_18_57_00.wtv, Conversion Task ->MKV Unprocessed
2016-04-27T20:17:56 MCEBuddy.Engine.QueueManager --> File >Survivor- Kaoh Rong - Brains vs. Brawn vs. Beauty_KTVTD_2016_04_27_18_57_00.wtv<, checking filename filter >*.wtv<
I actually don't think this is an MCEBuddy issue, but thought I'd see if anyone had any ideas why this was happening. Thanks, in advance.
Coordinator
Apr 28, 2016 at 8:50 PM
MCE has locked the file

Unable to queue file for conversion - file inaccessible/locked by another process

Apr 28, 2016 at 9:04 PM
rboy1 wrote:
MCE has locked the file Unable to queue file for conversion - file inaccessible/locked by another process
I understand that part of the log. The recording starts but WMC has it opened/locked for writing. From my understanding, MCEBuddy will attempt to process the file AFTER the lock has been released (i.e., the recording is finished). The part I can't explain is, if the recording stopped at 8:03PM, why did MCEBuddy not "notice" until 8:17PM? I'm not saying it's MCEBuddy's fault--it may very well be WMC. I was just fishing for some insight. It's really not that big of a bother, but if someone had an idea, then I'd be willing to try it. I'm already using Debug log output, and there is no additional info in there, so I can't determine at what interval (or means) MCEBuddy is checking to determine if the file is no longer locked.
Coordinator
Apr 28, 2016 at 9:42 PM
Mcebuddy polls for updates every 5 minutes. You can change this settings in the system setting page. Maybe it took 2 polls before it saw that the lock was released.

Apr 29, 2016 at 4:05 PM
rboy1 wrote:
Mcebuddy polls for updates every 5 minutes. You can change this settings in the system setting page. Maybe it took 2 polls before it saw that the lock was released.
I already have that set to 60 seconds. I'll just have to assume that, for some reason, WMC is not releasing the lock on the file as soon as the recording is done, as it's pretty consistently between 10 and 15 minutes after the recording ends that MCEBuddy is able to start processing. Perhaps someone else that uses WMC can confirm this behavior?
May 13, 2016 at 2:09 PM
So I did a bit more investigating on this. I pulled MCEBuddy source to get an idea how the timers, file lock checking, and log messages I am seeing flowed. Found something interesting. From code inspection, all seemed to be sound; but when I went though an older archived log file and a current log file, I saw some discrepancies. Namely, in QueueManager.AddJobs, there is a call to MetadataMatchFilters for each conversion job (of which I only have one). One of the first things MetadataMatchFilters does is output a log message to the effect of "Checking Metadata for File ->". In my archived log file, I see this message while using MCEBuddy 2.4.3.0. The kicker is that the timestamp of the log message is consistent with the timing that I would have expected. WMC stops recording 3 minutes after the show ends, MCEBuddy polls every 60 seconds. So, from the log, a show ending at 8:00p has the following:
2016-03-13T20:03:48 MCEBuddy.Engine.QueueManager --> Checking Metadata for File -> E:\Recorded TV\Once Upon a Time_WFAAD_2016_03_13_18_57_00.wtv, Conversion Task ->Remux
As you can see, MCEBuddy picks up the file for conversion 48 seconds after the recording ends. This was the last time I saw that message in my log files, though. The next recorded show was after an update to MCEBuddy 2.4.3.1. Instead of "Checking Metadata for File", I now see "Checking Filter and Metadata Matches for File"; and,more often than not, there is now a 10-15 minute delay when compared to the log messages from 2.4.3.0.
2016-03-15T20:22:32 MCEBuddy.Engine.QueueManager --> Monitor task Recorded TV : Checking Filter and Metadata Matches for File -> W:\Recorded TV\Survivor- Kaoh Rong - Brains vs. Brawn vs. Beauty_KTVTD_2016_04_13_18_57_00.wtv, Conversion Task ->Remux
I have since updated to MCEBuddy 2.4.4.1, and am seeing the same behavior. The funny thing, though, is that I see no mention of the log message "Checking Filter and Metadata Matches for File" anywhere in the source code I pulled yesterday. Perhaps this is all just coincidence and it still is WMC's issue. But perhaps you could clarify what I'm seeing and why I can't resolve it with the source code? Thanks.