any episode of America's Got Talent automatically deleted after watching

[johnsonx42]

Ok, this is the weirdest NextPVR symptom I've ever had, and you know I've had some weird ones over the years...

Every time I watch an episode of America's Got Talent, when it gets to the end OR if I exit somewhere near the end, the recording file is deleted and it's removed from the database.  So far this ONLY happens with America's Got Talent.  Any other recording I watch is fine.

The only thing that appears in the NPVR log when the recording ends and is deleted is this, tonight when I let the recording play to the end (from NPVR.log):

Code:

2020-08-12 21:06:49.541 [DEBUG][1] About to store playback position information
2020-08-12 21:06:49.541 [DEBUG][1] PlaybackPositionHelper.StorePlaybackPosition(Americas.Got.Talent.S15E12.Results.Show.1.ts, 3728, 3659)
2020-08-12 21:06:49.541 [DEBUG][1] PlaybackPositionHelper.DeletePlaybackPosition(E:\Recordings\Americas Got Talent\Season 15\Americas.Got.Talent.S15E12.Results.Show.1.ts)
2020-08-12 21:06:49.591 [DEBUG][1] Stop@0
2020-08-12 21:06:49.591 [DEBUG][1] Stopping graph@1
2020-08-12 21:06:49.862 [DEBUG][1] Stopping graph@2
2020-08-12 21:06:49.862 [DEBUG][1] Stopping graph@3
2020-08-12 21:06:49.879 [DEBUG][1] Removing filter  AC3 Audio Renderer
2020-08-12 21:06:49.894 [DEBUG][1] Removing filter  NPVR CC Dump
2020-08-12 21:06:49.894 [DEBUG][1] Removing filter  EVR Renderer
2020-08-12 21:06:49.916 [DEBUG][1] Removing filter  LAV Audio Decoder
2020-08-12 21:06:49.916 [DEBUG][1] Removing filter  Line 21 Decoder
2020-08-12 21:06:49.917 [DEBUG][1] Removing filter  Microsoft DTV-DVD Video Decoder
2020-08-12 21:06:49.950 [DEBUG][1] Removing filter  NPVR CC Extractor
2020-08-12 21:06:49.950 [DEBUG][1] Removing filter  NPVR TS Reader 5

and last night, when I exited about 10 minutes before the end (from NPVR.log.3):

Code:

2020-08-11 22:31:59.994 [DEBUG][1] About to store playback position information
2020-08-11 22:31:59.994 [DEBUG][1] PlaybackPositionHelper.StorePlaybackPosition(Americas.Got.Talent.S15E11.Live.Show.1.ts, 6605, 7259)
2020-08-11 22:31:59.994 [DEBUG][1] PlaybackPositionHelper.DeletePlaybackPosition(E:\Recordings\Americas Got Talent\Season 15\Americas.Got.Talent.S15E11.Live.Show.1.ts)
2020-08-11 22:32:00.054 [DEBUG][1] Stop@0
2020-08-11 22:32:00.055 [DEBUG][1] Stopping graph@1
2020-08-11 22:32:00.330 [DEBUG][1] Stopping graph@2
2020-08-11 22:32:00.330 [DEBUG][1] Stopping graph@3
2020-08-11 22:32:00.344 [DEBUG][1] Removing filter  AC3 Audio Renderer
2020-08-11 22:32:00.357 [DEBUG][1] Removing filter  Line 21 Decoder
2020-08-11 22:32:00.359 [DEBUG][1] Removing filter  EVR Renderer
2020-08-11 22:32:00.404 [DEBUG][1] Removing filter  Hauppauge AC3 Decoder
2020-08-11 22:32:00.404 [DEBUG][1] Removing filter  MainConcept (HCW) MPEG-2 Video Decoder
2020-08-11 22:32:00.407 [DEBUG][1] Removing filter  NPVR TS Reader 5

The only thing that shows up in NRecord.log at the same time is this:

Code:

2020-08-12 21:06:49.585 [DEBUG][83] GetExtraInfo: ResumePointsChanged

2020-08-12 21:06:49.587 [DEBUG][83] Resume point has changed for playback of recording
2020-08-12 21:06:49.588 [DEBUG][83] GetExtraInfo@exit

and:

Code:

2020-08-11 22:32:00.044 [DEBUG][149] GetExtraInfo: ResumePointsChanged
2020-08-11 22:32:00.045 [DEBUG][149] Resume point has changed for playback of recording
2020-08-11 22:32:00.053 [DEBUG][149] GetExtraInfo@exit

What also interesting is that ONLY the .ts file is deleted.  The other files that should be deleted by a normal delete operation are left behind, like the .xml, .edl, .log etc.
My config.xml has these settings pertaining to deleting:

Code:

<DeleteAdditionalExtensions>srt,txt,log,d2a,edl,csv,bat,wme,vprj,logo.txt,dvbsub,sm,xml,map</DeleteAdditionalExtensions>
<PromptForDeleteAfterPlayback>false</PromptForDeleteAfterPlayback>
<ConfirmOnDelete>true</ConfirmOnDelete>

any inkling of WTH is happening here?

[johnsonx42]

As it may be useful, here are the two records from RECENTLY_DELETED:

Code:

oid    unique_identifier    create_date    recurrence_oid    status
22    EP008298780516    2020-08-11 22:32:00.9544208    65    2
24    EP008298780517    2020-08-12 21:06:51.202373    65    2

and from PLAYBACK_POSITION:

Code:

filename    position    duration    last_watched
Americas.Got.Talent.S15E11.Live.Show.1.ts    6605    7259    2020-08-11 22:32:00
Americas.Got.Talent.S15E12.Results.Show.1.ts    3728    3659    2020-08-12 21:06:49

[mvallevand]

I am pretty sure it is related to those comskip resume change messages from parallel processing after watching the in-progress recording stops but my PC is too fast to be that far behind while watching to confirm.

Martin

[johnsonx42]

I could swear I've watched other in-progress recordings while comskip was running, but maybe not, or maybe the particular set of conditions hasn't arisen yet.
Comskip isn't falling behind though, it finishes when the recording finishes. However maybe when the recording and comskip finish while the recording is being watched, some error arises which sends it down the path of deleting the recording; it can't do it though while the recording is open, so that thread just sits and waits for the file to close.

BTW, sub, can you preface messages from outside utilities running in the nrecord process with something like "[External]" instead of "[Error]"? Even better if you could add in the executable name like "[Ext-Comskip]"

[johnsonx42]

ok, I watched Fool Us tonight, in-progress with comskip running, and sure enough, when the show was over I exited playback and the recording was immediately deleted.

logs attached, but no new information really

Code:

oid    unique_identifier    create_date    recurrence_oid    status
28    EP015344720080    2020-08-13 22:22:30.4866394    66    2

Code:

filename    position    duration    last_watched
Penn.&.Teller.Fool.Us.S07E03.Fool.Us.The.Home.Game.ts    3592    3593    2020-08-13 22:22:29

[johnsonx42]

this has to be something my comskip script is doing; did something change about the way the parameters are passed to parallelprocessing.bat? I'm using mostly the same script I used to use for the older Nextpvr...
there is a point in my script where it creates a temporary file based on one of the parameters passed from the recording service, then it later deletes the temporary file... if it's using the wrong parameter for that, it could be deleting the recording file, though I can't explain why it only happens if I watch a recording in-progress...

[johnsonx42]

no, I don't see any possible way my parallelprocessing.bat script is doing it; it only executes 1 delete command, definitely not being passed the recording file name, and it's before even invoking comskip, when the recording has just barely started. I also have logging that confirms %1, %2, %3 & %4 being passed are the same as always:

Code:

@echo off
cd c:\users\public\npvr-data\comskip
echo %date%,%time% - %~n1 (%3) recording from channel %2 on tuner %4 >>"%~dp0\recording.log"
echo %date%,%time% - invoking comskip on %1 >>"%~dp0\recording.log"
comskip %1
echo %date%,%time% - comskip finished with %1 >>"%~dp0\recording.log"

Code:

Wed 08/12/2020,20:00:01.48 - Americas.Got.Talent.S15E12.Results.Show.1 (1634) recording from channel 4.1 on tuner 21
Wed 08/12/2020,20:00:01.97 - invoking comskip on "E:\Recordings\Americas Got Talent\Season 15\Americas.Got.Talent.S15E12.Results.Show.1.ts"
Wed 08/12/2020,21:02:13.00 - comskip finished with "E:\Recordings\Americas Got Talent\Season 15\Americas.Got.Talent.S15E12.Results.Show.1.ts"

[johnsonx42]

just in case there's something I'm not seeing, I reduced my parallelprocessing.bat file down to the 6 lines I quoted above, nothing else.

[sub]

BTW, sub, can you preface messages from outside utilities running in the nrecord process with something like "[External]" instead of "[Error]"? Even better if you could add in the executable name like "[Ext-Comskip]"

I can't easily do this, because it would need reasonably significant changes to the logging code....however, I have changed it so you wont get [ERROR] with these messages. This was happening because the utility was outputting messages to StandardError (rather than StandardOutput).

In the next build, both StandardOutput and StandardError will both log debug messages, but it'll prefix these messages "> " so they look a little different than other messages in the logs.

[sub]

this has to be something my comskip script is doing; did something change about the way the parameters are passed to parallelprocessing.bat?  I'm using mostly the same script I used to use for the older Nextpvr...

Not that I'm aware of. It should be the same.

there is a point in my script where it creates a temporary file based on one of the parameters passed from the recording service, then it later deletes the temporary file... if it's using the wrong parameter for that, it could be deleting the recording file, though I can't explain why it only happens if I watch a recording in-progress...

It does sound a likely candidate.