Jump to content

Strange log of recording


jirim100

Recommended Posts

jirim100

Strange log of recording:

 

Prima ZOOM 24.9.2020
W:\For The Record\Hitlerova kronika (9. díl) - Dobyvatel; vysíláno 2020-09-24.ts
Device: Hauppauge WinTV-soloHD DVBT Tuner (11)
EventID: 4481
Timer Name: Hitlerova kronika (9. díl) - Dobyvatel
Timer Start: 24.9.2020 19:45:00
Timer Duration: 01:35:00 (95 min. incl. 15 min. lead time, 15 min. follow-up time)
Timer Options: Teletext=1, DVB Subtitles=1, All Audio Tracks=1, Adjust PAT/PMT=1, EIT EPG Data=1, Transponder Dump=0
Timer Source: Search:Hitlerova kronika

19:45:05 / 00:00:00 (~ 0,00 MB) St19:45:07 / 00:00:04 (~ 0,93 MB) PID 3425: H.264 Video, 16:9, 1920x1080, 25 fps
19:45:07 / 00:00:04 (~ 0,93 MB) PID 3426: AC3 Audio 5.1, 48 khz, 384 kbps
19:45:15 / 00:00:12 (~ 10,58 MB) PID 3427: DVB Subtitles
21:20:01 / 01:34:58 (~ 6358,97 MB) Stop

Average Data Rate: 1,116 MB/s
Total Size: 6359,0 MB (6667860108 Bytes)
(9. díl) not running | EventID: 4481 PDC: 0x00000
19:45:18 / 00:00:13 (~ 5,13 MB) PID 553: DVB Subtitles
20:00:03 / 00:14:58 (~ 436,19 MB) Hitlerova kronika (9. díl) running | EventID: 4481 PDC: 0x00000
20:00:04 / 00:14:59 (~ 436,41 MB) Den D: Poslední svědectví (2. díl) not running | EventID: 4480 PDC: 0x00000
20:02:04 / 00:16:59 (~ 492,96 MB) PID 551: MPEG2 Video, 4:3, 720x576, 25 fps
20:16:54 / 00:31:49 (~ 888,19 MB) PID 551: MPEG2 Video, 16:9, 720x576, 25 fps
20:25:11 / 00:40:06 (~ 1084,88 MB) PID 551: MPEG2 Video, 4:3, 720x576, 25 fps
20:44:14 / 00:59:09 (~ 1593,25 MB) PID 551: MPEG2 Video, 16:9, 720x576, 25 fps
20:52:12 / 01:07:07 (~ 1798,56 MB) PID 551: MPEG2 Video, 4:3, 720x576, 25 fps
21:05:04 / 01:19:59 (~ 2127,48 MB) Den D: Poslední svědectví (2. díl) running | EventID: 4480 PDC: 0x00000
21:05:05 / 01:20:00 (~ 2127,98 MB) Poslední Pygmejové (1. díl) not running | EventID: 4479 PDC: 0x00000
21:08:43 / 01:23:37 (~ 2216,83 MB) PID 551: MPEG2 Video, 16:9, 720x576, 25 fps
21:20:00 / 01:34:55 (~ 2507,11 MB) Stop

Average Data Rate: 0,440 MB/s
Total Size: 2507,1 MB (2628893300 Bytes)

 

What this mean? In recorded ts file was two recordings (I had to separate these with TS Doctor), one from free channel "Prima ZOOM" (device Hauppauge WinTV-soloHD DVB-T) and the second from encrypted channel "Prima ZOOM HD" (device TT Connect CT2 4650 CI DVB-C).

 

DMS v. 2.1.7.0

Link to post
jirim100

Log files are here https://www.uschovna.cz/zasilka/CYYV6HEV4LSGKN6A-YA3/

 

It seems this happen when exist two timers with the same name (and created file name is the same) at the same time (from different channels). DMS should be create one with the name XXX.ts and the second with the name XXX_01.ts.

Edited by jirim100
Link to post

This could be the result of a name clash: Two recordings with the same file name start within a very short time interval. There are two measures in the DMS for preventing this:

  1. The DMS recorder checks if a file with the same name already exists. If yes, a number is appended to the new file name, in order to make it unique.
  2. The DMS never initiates more than one recording per second.

However, a short time after a recording has been started, Windows may not yet be able to report the existence of the file. Moreover, opening the file and writing to it does not necessarily start immediately after a recording has been initiated. The DMS first waits for broadcasted channel data (PMT, Program Map Table) in order to check the video, audio, subtitle etc. streams that are associated with the channel, so it can execute the recording with up-to-date information, since the PIDs in the channel list may be out-dated. Additionally the received PMT (particularly the contained CA descriptors) must be forwarded to the CI module, otherwise it does not start decryption. Your svcdebug.log shows how the two recordings got interleaved:

 

24.09.20 19:45:03.096 TRecording           StartRecording:  Prima ZOOM HD //recorded with TT-connect CT2_4650
//....
24.09.20 19:45:05.036 TRecording           StartRecording:  Prima ZOOM //recorded with Hauppauge WinTV-soloHD
24.09.20 19:45:05.088 TBDACIBSTModule WndProc Received PMT ready //the PMT is forwarded to the CT2_4650 CI

 

I never thought that such a clash is possible. I considered it to be highly unlikely. Nevertheless it seems that you somehow managed to hit this tiny mark. You should buy a lottery ticket :)

 

Link to post
jirim100

Thanks for perfect explanation.

 

I any case you should prevent this problem. Close the core code which is creating file on disk in critical section or in mutex (you probably know better than I the synchronization methods in windows).

 

I think, this problem can occurs again. I have many free-to-air DVB-T channels and encrypted DVB-C channels with the same EPG. Maybe, this problem can be simulated manually (create two or more timers with the same time and name of the file from mix free and paid channels). Maybe, you can even help simulate this collision programmatically in debug mode of your software.

 

 

I am glad, that I don't have to solve these problems.

Edited by jirim100
Link to post
1 hour ago, jirim100 said:

Close the core code which is creating file on disk in critical section or in mutex

 

That's not the point. The Windows API for file access is thread-safe anyway, so it's useless to enclose it again in critical sections. The critical points are

  1. The DMS creates recordings in shared read/write access mode, so that another process/thread can read/play the file while it is still recorded, which implies, that another recorder instance can write to the same file.
  2. The DMS creates the file name when a recording is initiated, not when the file is actually created, which may happen a bit later.

I don't know if there is a way to fix it without disadvantages. On occasion I will look after it.

 

Link to post

In the meantime I've found out that the issue can be reproduced by using the "EPG Monitoring -> Start/Stop by EPG running status" option (by default requiring a channel that provides PDC = Programme Delivery Control in the EPG). In this case the gap between initiating and actually writing the recording may last several minutes, while the DMS is waiting for the EPG to signal the programme start. So by using a suitable naming scheme another recording with the same filename can be started easily during this time.

 

The solution is simple: Besides checking a new filename against already existing files on the hard disk, the DMS must check it also against the filenames of other timers, that are already in the recording state, but perhaps not yet writing.

 

Link to post
jirim100
11 hours ago, Griga said:

The solution is simple: Besides checking a new filename against already existing files on the hard disk, the DMS must check it also against the filenames of other timers, that are already in the recording state, but perhaps not yet writing.

Yes, exactly!

I write for you some pseudocode how you can achieve this 😊:

 

...
List<string> FileNames = new List<string>(); // file names which will be created on disk
object objForFile = new object(); //object for critical section
....

string AdjustFileName(string fileName) {
  ...
  lock (objForFile) { //enter critical section
    while (ExistFileOnDisk(fileName)) {
      // increase postfix of the name of the file for example from file.ts to file_01.ts, from file_01.ts to file_02.ts, etc.
      fileName = IncreasePostfixOfName(fileName); 
    }
    while (FileNames.Contains(fileName)) {
      // increase postfix of the name of the file for example from file.ts to file_01.ts, from file_01.ts to file_02.ts, etc.
      fileName = IncreasePostfixOfName(fileName); 
    }
    FileNames.Add(fileName);
  }
  ...
  return fileName;  
}

HANDLE CreateFileOnDisk(string fileName)
{
  ...
  lock (objForFile) { //enter critical section
    HANDLE fHandle = CreateFile(fileName,...);
    FileNames.Remove(fileName);
  }
  return fHandle;
  ...
}

 

Edited by jirim100
Link to post
jirim100

I tried the fix and it looks good. I simulate the same situation and file names are different now and recorded ts files looks good.

 

26.09.20 18:46:32.909 TBDADVBSky           OpenDevice       bvDVBSky
26.09.20 18:46:32.909 TRecording           AllocateHardware TT-connect CT2_4650 DVB-C Tuner (8)
26.09.20 18:46:32.909 TRecording           StartRecording   TT-connect CT2_4650 DVB-C Tuner (8)
26.09.20 18:46:32.909 TBDADVBSky           SetTuner         TType: 0, Freq: 618000, Symrate: 6900, LOF: 0, Tone: 0, Pol: 5, DiseqC: 0, FEC: 0, APID: 3426, VPID: 3425, PMT: 3424, SID: 2104, TID: 121, NID: 1, SatMod: 0, DiseqCVal: 0, Flags: 25, Group: 1
26.09.20 18:46:35.230 TBDACIBSTModule CI Base SetTuner Entering
26.09.20 18:46:35.230 TBDACIBSTModule CI Base SetTuner Leaving
26.09.20 18:46:35.230 TRecording           StartRecording:  Prima ZOOM HD
26.09.20 18:46:35.232 SetStandbyBlock      TVCR
26.09.20 18:46:35.232 TServiceMain         AddReference     TVCR: 1
26.09.20 18:46:35.241 TBDACIBSTModule      GetAvailable     CAM Status 1
26.09.20 18:46:36.558 TBDAEMPIA            OpenDevice       bvEMPIA
26.09.20 18:46:36.558 TRecording           AllocateHardware Hauppauge WinTV-soloHD DVBT Tuner (11)
26.09.20 18:46:36.558 TRecording           StartRecording   Hauppauge WinTV-soloHD DVBT Tuner (11)
26.09.20 18:46:36.558 TBDAEMPIA            SetTuner         TType: 2, Freq: 506000, Symrate: 0, LOF: 0, Tone: 0, Pol: 2, DiseqC: 0, FEC: 0, APID: 552, VPID: 551, PMT: 550, SID: 15005, TID: 1005, NID: 8395, SatMod: 0, DiseqCVal: 0, Flags: 24, Group: 0
26.09.20 18:46:37.176 TRecording           StartRecording:  Prima ZOOM
26.09.20 18:46:37.236 TBDACIBSTModule WndProc Received PMT ready  // Prima ZOOM HD

 

Link to post
jirim100

I don't know how you implemented the fix, but now I edited the pseudo code in my post https://www.DVBViewer.tv/forum/topic/64392-strange-log-of-recording/?do=findComment&comment=490462, because in critical section have to be enclosed the whole code for adjusting file name (searching on disk together with adding to list) and the whole code for creating file on disk (core create file together with removing from list).

 

The using critical section in previous pseudo code is not enought (will work, but not at all boundary conditions) ☺️

Edited by jirim100
Link to post
1 hour ago, jirim100 said:

I don't know how you implemented the fix

 

It was just

 

if FileExists(Filename) then
  //we can't use this filename

 

changed to

 

if IsRecording(Filename) or FileExists(Filename) then
  //we can't use this filename

 

The IsRecording function was already available and waiting to be used for this purpose.

 

Critical sections and stuff are not necessary, because the whole recording administration (including intitiation, actual starting, stopping etc.) happens in a single thread. Only creating the file, writing to it and closing is executed in separate asynchronous "per recording" threads.

 

Link to post

Join the conversation

You can post now and register later. If you have an account, sign in now to post with your account.

Guest
Reply to this topic...

×   Pasted as rich text.   Paste as plain text instead

  Only 75 emoji are allowed.

×   Your link has been automatically embedded.   Display as a link instead

×   Your previous content has been restored.   Clear editor

×   You cannot paste images directly. Upload or insert images from URL.

×
×
  • Create New...