Time shift files not getting removed when playback is stopped (1 Viewer)

[gwatkins]

I seem to have stumbled across an issue with the time shift files not getting removed. I have my time shift files being written to a 1.5gb RAM drive. If I stop the live tv playback normally they get removed and everything is fine. However, I have two tuners and if I am watching live tv and then I have two stations set to record at the same time then live tv will stop playback so that the tuners can start recording but when that happens the time shift files from the live tv do not get removed. Then when I try to start live tv again it will eventually stop the playback because the ram drive is full. I have to shutdown MP and delete the files manually. This problem would probably only be evident if you are using a ram drive for time shifting but even if not it would still leave a large amount of unused files on the ts drive. I think either one of two things could be done to prevent this...1) Remove the time shift files no matter how the playback was stopped and 2) Delete the existing time shift files, if any, prior to creating new time shift files for a new channel.

 

[gwatkins]

Here are the log files. The last occurrences of this happened on 4/3 between 4:00 and 5:00 in the afternoon.

 

[mm1352000]

Thanks for the logs.

In short, I can see what you're saying but I think we need to talk this through.

Let's start with the problem. It appears in the TsWriter log:

[2014-04-03 16:46:40,773] [6abe118] [15c] - MultiFileWriter: failed to create file R:\\live5-0.ts.tsbuffer1.ts

I have to take your word for the fact that this error is occurring because your RAM drive is full. I can't actually confirm that. All I can say is that TsWriter is unable to create a file. Anyhow...

Let's assume you're right and that the cause is that timeshift files aren't deleted when you're kicked off the tuner.
It looks like you were last kicked from watching KDFI DT at around 3pm on 4/3. You had started timeshifting on tuner 6 at about 2pm:
[2014-04-03 13:59:43,987] [Log ] [13 ] [INFO ] - card: Tune on card 6 to subchannel KDFI DT
[2014-04-03 13:59:43,989] [Log ] [13 ] [DEBUG] - card: user: MEDIA-PC:6:-1 tune ATSC:tv:Terrestrial KDFI DT Freq:-1 ONID:1 TSID:2805 SID:3 PMT:0x30 FTA:True LCN:36 phys:36 maj:27 min:1 mod:Mod8Vsb

TV Server stopped you from timeshifting because it need to record Judge Mathis at 3pm:
[2014-04-03 14:58:15,627] [Log ] [scheduler thread] [INFO ] - Scheduler: Time to record 21txa 2:58 PM-4:00 PM Judge Mathis *
[2014-04-03 14:58:15,686] [Log ] [scheduler thread] [INFO ] - card: Tune on card 5 to subchannel KTXA-DT
[2014-04-03 14:58:15,688] [Log ] [scheduler thread] [DEBUG] - card: user: scheduler387:5:-1 tune ATSC:tv:Terrestrial KTXA-DT Freq:-1 ONID:1 TSID:2841 SID:1 PMT:0x30 FTA:True LCN:29 phys:29 maj:21 min:1 mod:Mod8Vsb

...and Dr Phil at the same time:
[2014-04-03 14:58:16,814] [Log ] [scheduler thread] [INFO ] - Scheduler: Time to record CBS 2:58 PM-4:00 PM Dr. Phil *
[2014-04-03 14:58:16,831] [Log ] [scheduler thread] [INFO ] - Controller: channel #1 ATSC:tv:Terrestrial KTVT Freq:-1 ONID:1 TSID:2839 SID:1 PMT:0x30 FTA:True LCN:19 phys:19 maj:11 min:1 mod:Mod8Vsb

Okay, so fair enough - it is clear that TV Server does legitimately need to stop you from timeshifting as both tuners are required for recording. That happens here:
[collapse][2014-04-03 14:58:17,138] [Log ] [scheduler thread] [INFO ] - Controller: card:5 type:Atsc users: 1
[2014-04-03 14:58:17,139] [Log ] [scheduler thread] [INFO ] - Controller: card:5 type:Atsc is not available, tuned to different transponder
[2014-04-03 14:58:17,140] [Log ] [scheduler thread] [INFO ] - Controller: card:6 type:Atsc users: 1
[2014-04-03 14:58:17,140] [Log ] [scheduler thread] [INFO ] - Controller: card:6 type:Atsc is available
[2014-04-03 14:58:17,141] [Log ] [scheduler thread] [DEBUG] - CardReservation.CancelCardReservation id=592
[2014-04-03 14:58:17,142] [Log ] [scheduler thread] [INFO ] - scheduler: try max 1 of 1 free cards for recording
[2014-04-03 14:58:17,143] [Log ] [scheduler thread] [INFO ] - Scheduler : card is not tuned to the same transponder and not recording, kicking all users. record on card:6 priority:3
[2014-04-03 14:58:17,144] [Log ] [scheduler thread] [INFO ] - Scheduler : kicking user:MEDIA-PC
[2014-04-03 14:58:17,155] [Log ] [scheduler thread] [INFO ] - Controller: StopTimeShifting 6
[2014-04-03 14:58:17,158] [Log ] [scheduler thread] [DEBUG] - CardTuner.RequestCardStopReservation: placed reservation with id=594, user=MEDIA-PC
[2014-04-03 14:58:17,259] [Log ] [scheduler thread] [DEBUG] - CardTuner.Stop: ticket id=594, found=True
[2014-04-03 14:58:17,260] [Log ] [scheduler thread] [INFO ] - Stop cardid=6, ticket=594, tunestate=TunePending, stopstate=Stopping
[2014-04-03 14:58:17,261] [Log ] [scheduler thread] [INFO ] - card Hauppauge WinTV-7164 BDA ATSC/QAM Tuner: StopTimeShifting user:MEDIA-PC sub:0
[2014-04-03 14:58:17,263] [Log ] [scheduler thread] [DEBUG] - card not IDLE - removing user: MEDIA-PC
[2014-04-03 14:58:17,265] [Log ] [scheduler thread] [DEBUG] - usermanagement.RemoveUser: MEDIA-PC, subch: 0 of 1, card: 6
[2014-04-03 14:58:17,266] [Log ] [scheduler thread] [INFO ] - user:MEDIA-PC remove
[2014-04-03 14:58:17,329] [Log ] [scheduler thread] [INFO ] - subch:0-0 tswriter StopTimeshifting...
[2014-04-03 14:58:17,503] [Log ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
[2014-04-03 14:58:17,504] [Log ] [scheduler thread] [INFO ] - DVB subch:0 Decompose()
[2014-04-03 14:58:17,508] [Log ] [scheduler thread] [INFO ] - FreeSubChannel CA: freeing sub channel : 0
[2014-04-03 14:58:17,509] [Log ] [scheduler thread] [INFO ] - tvcard:FreeSubChannel : no subchannels present, pausing graph
[2014-04-03 14:58:17,509] [Log ] [scheduler thread] [INFO ] - dvbtopGraph called
[2014-04-03 14:58:17,510] [Log ] [scheduler thread] [INFO ] - tvcard:FreeAllSubChannels
[2014-04-03 14:58:17,511] [Log ] [scheduler thread] [INFO ] - dvbtopGraph
[2014-04-03 14:58:17,726] [Log ] [scheduler thread] [INFO ] - debug: IMediaControl stopped! hr = 0x0
[2014-04-03 14:58:17,728] [Log ] [scheduler thread] [INFO ] - dvbtopGraph called
[2014-04-03 14:58:17,729] [Log ] [scheduler thread] [INFO ] - tvcard:FreeAllSubChannels
[2014-04-03 14:58:17,729] [Log ] [scheduler thread] [INFO ] - dvbtopGraph filterstate already stopped, returning.
[2014-04-03 14:58:17,730] [Log ] [scheduler thread] [INFO ] - user:MEDIA-PC remove
[2014-04-03 14:58:17,731] [Log ] [scheduler thread] [DEBUG] - CardReservation.RemoveStopTicket: removed STOP reservation with id=594
[2014-04-03 14:58:17,733] [Log ] [TS_File_Cleanup] [INFO ] - card: delete timeshift files R:\\live6-0.ts
[2014-04-03 14:58:17,734] [Log ] [TS_File_Cleanup] [INFO ] - card: trying to delete R:\live6-0.ts.tsbuffer
[2014-04-03 14:58:22,735] [Log ] [TS_File_Cleanup] [INFO ] - card: delete timeshift files R:\\live6-0.ts
[2014-04-03 14:58:22,736] [Log ] [TS_File_Cleanup] [INFO ] - card: trying to delete R:\live6-0.ts.tsbuffer
[2014-04-03 14:58:27,738] [Log ] [TS_File_Cleanup] [INFO ] - card: delete timeshift files R:\\live6-0.ts
[2014-04-03 14:58:27,740] [Log ] [TS_File_Cleanup] [INFO ] - card: trying to delete R:\live6-0.ts.tsbuffer
[2014-04-03 14:58:32,741] [Log ] [TS_File_Cleanup] [INFO ] - card: delete timeshift files R:\\live6-0.ts
[2014-04-03 14:58:32,742] [Log ] [TS_File_Cleanup] [INFO ] - card: trying to delete R:\live6-0.ts.tsbuffer
[2014-04-03 14:58:37,743] [Log ] [TS_File_Cleanup] [INFO ] - card: delete timeshift files R:\\live6-0.ts
[2014-04-03 14:58:37,745] [Log ] [TS_File_Cleanup] [INFO ] - card: trying to delete R:\live6-0.ts.tsbuffer[/collapse]

Note the last half dozen or so entries. These tell us that TV Server tries 5 times over the space of 20 seconds to delete the first timeshift file. It appears that this fails because MediaPortal is still timeshifting until 3:01pm:
[collapse]
[2014-04-03 14:08:29,263] [296db008] [1934] - Demux : Video to render 1.174 Sec
[2014-04-03 14:58:21,583] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:58:25,826] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:58:30,068] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:58:34,314] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:58:38,556] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:58:42,798] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:58:47,041] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:58:51,288] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:58:55,530] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:58:59,772] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:59:04,015] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:59:08,222] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:59:12,465] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:59:16,707] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:59:20,951] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:59:25,193] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:59:29,435] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:59:33,677] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:59:37,922] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:59:42,164] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:59:46,406] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:59:50,654] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:59:54,897] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 14:59:59,139] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 15:00:03,381] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 15:00:07,623] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 15:00:11,866] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 15:00:16,108] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 15:00:20,350] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 15:00:24,592] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 15:00:28,835] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 15:00:33,077] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 15:00:37,319] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 15:00:41,561] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 15:00:45,804] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 15:00:50,046] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 15:00:54,288] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 15:00:58,530] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 15:01:02,773] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 15:01:07,015] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 15:01:11,257] [296db008] [ 3a4] - CTsReaderFilter:uration - correction to predicted duration: 345505.000
[2014-04-03 15:01:13,256] [296db008] [16e4] - CTsReaderFilter:ause() - IsTimeShifting = 1 - state = 2
[2014-04-03 15:01:13,256] [296db008] [16e4] - CTsReaderFilter:ause() - END - state = 1
[2014-04-03 15:01:13,268] [296db008] [16e4] - CTsReaderFilter:top(), state 1
[2014-04-03 15:01:13,278] [296db008] [16e4] - CTsReaderFilter:top() -stop source, state 1
[2014-04-03 15:01:13,280] [296db008] [16e4] - CTsReaderFilter:top() -stop source done, state 0[/collapse]

So it is not that TV Server doesn't want to delete the files. It tries and fails for a legitimate reason: you're still watching TV from the timeshift files.

How to solve this problem?

I think either one of two things could be done to prevent this...1) Remove the time shift files no matter how the playback was stopped

We already do this.

and 2) Delete the existing time shift files, if any, prior to creating new time shift files for a new channel.

Yes, something like this may be a possible solution.
However, consider that when you change channel, you're actually still able to timeshift back through the previous channel(s) you were watching. In other words, we can't just delete all the timeshift files on channel change.
We'd have to identify the files that have been orphaned by cross-checking the files which exist with the active tuners and users. From a code perspective this is much harder than you might think.
In short, I acknowledge a potential problem in certain uncommon scenarios, however a fix would be difficult to create and will not come quickly.

One last comment:

...but even if not it would still leave a large amount of unused files on the ts drive.

This shouldn't happen in practice because orphaned files would eventually be reused and subsequently deleted if/when the same tuner is used again by the same number of users. So, files may hang around for awhile but they shouldn't pile up forever until manually deleted.

 

[gwatkins]

Thanks for the quick reply. I used to use MCE before I switched to MP and when MCE encountered the scenario where it needed to stop live playback in order to record two channels it would generate a popup notification warning that it was about to switch channels in order to record a program. You then had the option to go ahead and let it switch to the recorded channel or cancel the recording. If you did nothing then it would automatically stop the live playback and switch to live playback of the recorded channel that was being assigned to the tuner you were watching. I think this is much better than simply stopping the playback with no notification why. To my wife it simply seems like it just froze during playback so she restarts MP but since the files were not removed from the RAM drive it stops the live playback after a few minutes. Plus I assume since it would be automatically changing channels that it could then delete the ts files as it would during a manual change. Another suggestion would be to have MP delete any existing ts files on startup. Any thoughts on that?