Jump to content

MediaServer stops randomly stops all recording when recording TS streams

reki

By reki
in Bug Reports DVBViewer Pro/GE

Recommended Posts

reki Rookie

reki

Posted
Posted (edited)

Hello,

 

I have following setup:

  • Windows 10,
  • MediaServer service,
  • Digital Devices MAX M4 card configured to record DVB-C channels,
  • four H.254 streams from Internet configured as TS Streams to record.

 

This setup works in principle, but after couple of hours of recording various programs, it stops recording. The bitrate in Status page shows 0.000 MB/s for all devices: Digital Devices DVB-C Tunner * and TS Stream Device *.  The svcdebug.log starts growing very fast, the following text is put over and over, till the file reaches its 4 MB limit:

 

Spoiler 


11.05.23 14:54:41.373 TFileDevice          RunDevice        
11.05.23 14:54:41.373 TRecording           AllocateHardware TS Stream Device 2
11.05.23 14:54:41.373 TRecording           StartRecord      TS Stream Device 2
11.05.23 14:54:41.373 TFileDevice          SetTuner         TType: 6, Freq: 0, Symrate: 3256015631, LOF: 37109, Tone: 7, Pol: 0, DiseqC: 0, FEC: 1, APID: 257, VPID: 256, PMT: 4096, SID: 1, TID: 1, NID: 65281, SatMod: 0, DiseqCVal: 23021, Flags: 24, Group: 0
11.05.23 14:54:41.376 TRecording           StartRecord      SetTuner failed.
11.05.23 14:54:41.376 TRecording           Release          TS Stream Device 2
11.05.23 14:54:41.376 TRecording           Free             TS Stream Device 2
11.05.23 14:54:41.376 TFileDevice          StopDevice       
11.05.23 14:54:41.376 TFileDevice          CloseDevice      
11.05.23 14:54:41.376 TRecording           Freed            TS Stream Device 2
11.05.23 14:54:41.376 TRecording           hamDeleted       TS Stream Device 2
11.05.23 14:54:41.376 TFileDevice          RunDevice        
11.05.23 14:54:41.377 TRecording           AllocateHardware TS Stream Device 2
11.05.23 14:54:41.377 TRecording           StartRecord      TS Stream Device 2
11.05.23 14:54:41.377 TFileDevice          SetTuner         TType: 6, Freq: 0, Symrate: 232908360, LOF: 55557, Tone: 7, Pol: 0, DiseqC: 0, FEC: 1, APID: 257, VPID: 256, PMT: 4096, SID: 1, TID: 1, NID: 0, SatMod: 0, DiseqCVal: 17161, Flags: 24, Group: 0
11.05.23 14:54:41.379 TRecording           StartRecord      SetTuner failed.
11.05.23 14:54:41.379 TRecording           Release          TS Stream Device 2
11.05.23 14:54:41.379 TRecording           Free             TS Stream Device 2
11.05.23 14:54:41.379 TFileDevice          StopDevice       
11.05.23 14:54:41.379 TFileDevice          CloseDevice      
11.05.23 14:54:41.379 TRecording           Freed            TS Stream Device 2
11.05.23 14:54:41.379 TRecording           hamDeleted       TS Stream Device 2
11.05.23 14:54:42.387 TFileDevice          RunDevice        
11.05.23 14:54:42.387 TRecording           AllocateHardware TS Stream Device 2
11.05.23 14:54:42.387 TRecording           StartRecord      TS Stream Device 2
11.05.23 14:54:42.387 TFileDevice          SetTuner         TType: 6, Freq: 0, Symrate: 3256015631, LOF: 37109, Tone: 7, Pol: 0, DiseqC: 0, FEC: 1, APID: 257, VPID: 256, PMT: 4096, SID: 1, TID: 1, NID: 65281, SatMod: 0, DiseqCVal: 23021, Flags: 24, Group: 0
11.05.23 14:54:42.390 TRecording           StartRecord      SetTuner failed.
11.05.23 14:54:42.390 TRecording           Release          TS Stream Device 2
11.05.23 14:54:42.390 TRecording           Free             TS Stream Device 2
11.05.23 14:54:42.390 TFileDevice          StopDevice       
11.05.23 14:54:42.390 TFileDevice          CloseDevice

 

svrec.log then is filled with infos about recordings over and over, each one 0.0 KB. In the log below to first entries are OK, then 0.0 KB over and over:
 

Spoiler 


10.05.23 12:33:04.141 D:\recordings\2023-05-10_12-13-00_TVN 24 Biznes i Swiat_Wiadomości.ts Discontinuities: 41  -  Total size: 723,73 MB  -  Device: TS Stream Device 2
10.05.23 12:33:06.194 D:\recordings\2023-05-10_11-58-07_Polsat News HD_Wiadomości.ts Discontinuities: 70  -  Total size: 956,94 MB  -  Device: TS Stream Device 3
10.05.23 12:59:04.496 D:\recordings\2023-05-10_12-58-00_Jedynka Polskie Radio_Wiadomości.ts Discontinuities: 0  -  Total size: 0,00 KB  -  Device: Digital Devices DVB-C Tuner 3 (1)
10.05.23 12:59:05.532 D:\recordings\2023-05-10_12-58-01_RMF FM_Wiadomości.ts Discontinuities: 0  -  Total size: 0,00 KB  -  Device: Digital Devices DVB-C Tuner 3 (1)
10.05.23 12:59:06.728 D:\recordings\2023-05-10_12-58-02_TOK FM_Wiadomości.ts Discontinuities: 0  -  Total size: 0,00 KB  -  Device: Digital Devices DVB-C Tuner 3 (1)
10.05.23 12:59:07.810 D:\recordings\2023-05-10_12-58-03_Trójka Polskie Radio_Wiadomości.ts Discontinuities: 0  -  Total size: 0,00 KB  -  Device: Digital Devices DVB-C Tuner 3 (1)
10.05.23 12:59:08.832 D:\recordings\2023-05-10_12-58-04_Radio Maryja_Wiadomości.ts Discontinuities: 0  -  Total size: 0,00 KB  -  Device: Digital Devices DVB-C Tuner 3 (1)
10.05.23 12:59:09.850 D:\recordings\2023-05-10_12-58-06_Radio Zet_Wiadomości.ts Discontinuities: 0  -  Total size: 0,00 KB  -  Device: Digital Devices DVB-C Tuner 3 (1)
10.05.23 12:59:10.859 D:\recordings\2023-05-10_12-58-07_TVN 24 HD (pol)_Wiadomości.ts Discontinuities: 0  -  Total size: 0,00 KB  -  Device: TS Stream Device
10.05.23 12:59:11.933 D:\recordings\2023-05-10_12-58-08_TVP Info HD_Wiadomości.ts Discontinuities: 0  -  Total size: 0,00 KB  -  Device: Digital Devices DVB-C Tuner 2 (4)
10.05.23 12:59:12.972 D:\recordings\2023-05-10_12-58-09_TV Trwam_Wiadomości.ts Discontinuities: 0  -  Total size: 0,00 KB  -  Device: Digital Devices DVB-C Tuner 4 (5)
10.05.23 13:00:08.728 D:\recordings\2023-05-10_12-59-04_Jedynka Polskie Radio_Wiadomości.ts Discontinuities: 0  -  Total size: 0,00 KB  -  Device: Digital Devices DVB-C Tuner 3 (1)
10.05.23 13:00:09.754 D:\recordings\2023-05-10_12-59-05_RMF FM_Wiadomości.ts Discontinuities: 0  -  Total size: 0,00 KB  -  Device: Digital Devices DVB-C Tuner 3 (1)

 

The exact moment of the crash is difficult to catch, because the log is truncated eventually. However, I found the moment when it starts:
 

Spoiler 


11.05.23 14:54:26.701 TFileDevice          CloseDevice      
11.05.23 14:54:27.744 TFileDevice          CheckAutoRetune  Retuning TS Stream Device 3
11.05.23 14:54:27.744 TFileDevice          StopDevice       
11.05.23 14:54:27.744 TFileDevice          CloseDevice      
11.05.23 14:54:28.774 TFileDevice          CheckAutoRetune  Retuning TS Stream Device
11.05.23 14:54:28.774 TFileDevice          StopDevice       
11.05.23 14:54:28.774 TFileDevice          CloseDevice      
11.05.23 14:54:31.939 TFileDevice          CheckAutoRetune  Retuning TS Stream Device 2
11.05.23 14:54:31.939 TFileDevice          StopDevice       
11.05.23 14:54:31.939 TFileDevice          CloseDevice      
11.05.23 14:54:32.998 TFileDevice          CheckAutoRetune  Retuning TS Stream Device 3
11.05.23 14:54:32.998 TFileDevice          StopDevice       
11.05.23 14:54:32.998 TFileDevice          CloseDevice      
11.05.23 14:54:34.054 TFileDevice          CheckAutoRetune  Retuning TS Stream Device
11.05.23 14:54:34.054 TFileDevice          StopDevice       
11.05.23 14:54:34.054 TFileDevice          CloseDevice      
11.05.23 14:54:37.205 TFileDevice          CheckAutoRetune  Retuning TS Stream Device 2
11.05.23 14:54:37.206 TFileDevice          StopDevice       
11.05.23 14:54:37.206 TFileDevice          CloseDevice      
11.05.23 14:54:38.252 TRecording ($027718B0)    Tick             No data within one minute, restarting!
11.05.23 14:54:38.253 TRecording ($027718B0)    D:\recordings\2023-05-11_13-58-08_Polsat News HD_Wiadomości.ts Discontinuities: 111  -  Total size: 1,66 GB  -  Device: TS Stream Device 2
11.05.23 14:54:38.265 SendUpdate           DVBVUPDATE REC
11.05.23 14:54:38.286 TRecording           Release          TS Stream Device 2
11.05.23 14:54:38.286 TRecording           Free             TS Stream Device 2
11.05.23 14:54:38.286 TFileDevice          StopDevice       
11.05.23 14:54:38.286 TFileDevice          CloseDevice      
11.05.23 14:54:38.287 TRecording           Freed            TS Stream Device 2
11.05.23 14:54:38.287 TRecording           hamDeleted       TS Stream Device 2
11.05.23 14:54:38.287 TFileDevice          RunDevice        
11.05.23 14:54:38.287 TRecording           AllocateHardware TS Stream Device 2
11.05.23 14:54:38.287 TRecording           StartRecord      TS Stream Device 2
11.05.23 14:54:38.287 TFileDevice          SetTuner         TType: 6, Freq: 0, Symrate: 3256015631, LOF: 37109, Tone: 7, Pol: 0, DiseqC: 0, FEC: 1, APID: 257, VPID: 256, PMT: 4096, SID: 1, TID: 1, NID: 65281, SatMod: 0, DiseqCVal: 23021, Flags: 24, Group: 0
11.05.23 14:54:38.288 TRecording           StartRecord      SetTuner failed.
11.05.23 14:54:38.288 TRecording           Release          TS Stream Device 2
11.05.23 14:54:38.288 TRecording           Free             TS Stream Device 2
11.05.23 14:54:38.288 TFileDevice          StopDevice       
11.05.23 14:54:38.288 TFileDevice          CloseDevice      
11.05.23 14:54:38.288 TRecording           Freed            TS Stream Device 2
11.05.23 14:54:38.288 TRecording           hamDeleted       TS Stream Device 2
11.05.23 14:54:38.288 TFileDevice          RunDevice        
11.05.23 14:54:38.288 TRecording           AllocateHardware TS Stream Device 2
11.05.23 14:54:38.288 TRecording           StartRecord      TS Stream Device 2
11.05.23 14:54:38.288 TFileDevice          SetTuner         TType: 6, Freq: 0, Symrate: 3256015631, LOF: 37109, Tone: 7, Pol: 0, DiseqC: 0, FEC: 1, APID: 257, VPID: 256, PMT: 4096, SID: 1, TID: 1, NID: 65281, SatMod: 0, DiseqCVal: 23021, Flags: 24, Group: 0
11.05.23 14:54:38.289 TRecording           StartRecord      SetTuner failed.
11.05.23 14:54:38.289 TRecording           Release          TS Stream Device 2
11.05.23 14:54:38.289 TRecording           Free             TS Stream Device 2
11.05.23 14:54:38.289 TFileDevice          StopDevice       
11.05.23 14:54:38.289 TFileDevice          CloseDevice      
11.05.23 14:54:38.289 TRecording           Freed            TS Stream Device 2
11.05.23 14:54:38.289 TRecording           hamDeleted       TS Stream Device 2
11.05.23 14:54:38.289 TFileDevice          CheckAutoRetune  Retuning TS Stream Device 3
11.05.23 14:54:38.289 TFileDevice          StopDevice       
11.05.23 14:54:38.289 TFileDevice          CloseDevice      
11.05.23 14:54:38.361 SendUpdate           DVBVUPDATE RST -769
11.05.23 14:54:39.301 TRecording ($026EE770)    Tick             No data within one minute, restarting!
11.05.23 14:54:39.301 TRecording ($026EE770)    D:\recordings\2023-05-11_13-58-10_Wydarzenia 24_Wiadomości.ts Discontinuities: 156  -  Total size: 1,92 GB  -  Device: TS Stream Device 3
11.05.23 14:54:39.306 SendUpdate           DVBVUPDATE REC
11.05.23 14:54:39.319 TRecording           Release          TS Stream Device 3
11.05.23 14:54:39.319 TRecording           Free             TS Stream Device 3
11.05.23 14:54:39.319 TFileDevice          StopDevice       
11.05.23 14:54:39.319 TFileDevice          CloseDevice      
11.05.23 14:54:39.319 TRecording           Freed            TS Stream Device 3
11.05.23 14:54:39.319 TRecording           hamDeleted       TS Stream Device 3

 


 

The log tells about TS Streams, but the cease of recording affects all channels, including DVB-C. If the MediaServer is left in this state, it eventually crashes because it runs out of RAM, I've seen it happen at about 1.2 GB of allocated memory in Windows Task manager.

 

MediaServer versions checked, 3.1.2.1, 3.2.4.0.

 

I include support file, but the logs might not contain the relevant moments since the log grows so fast.

 

 

support.zip

Edited by Griga
spoiler tags added
reki Rookie

reki

Posted
  • Author
Posted

I attach the screenshot of Status page after the bug happens. I am also observing the memory usage of DVBVservice.exe in Windows Task Manager. The Mediaserver starts with ~60 MB of RAM and steadily consumes more. It looks the memory consumption increases in linear manner, shown in the chart. It happens when TS Streams are recorded. Didn't notice it when only DVB-C is used. When the consumption reaches ~1.3 GB, recording crashes.

 

Screenshot_2023-05-11_17-06-06.png

memory-chart.png

reki Rookie

reki

Posted
  • Author
Posted

I managed to narrow the problem: the leak happens when at least two TS streams are recorded from specific online provider. They have following parameters by ffprobe:

  

Input #0, mpegts, from 'http://xxxxxxx-this-is-stream-url-xxxxxx':
  Duration: N/A, start: 27810.725756, bitrate: N/A
  Program 1 
    Metadata:
      service_name    : Service01
      service_provider: FFmpeg
  Stream #0:0[0x100]: Video: h264 (Main) ([27][0][0][0] / 0x001B), yuv420p(tv, bt709, top first), 1920x1080 [SAR 1:1 DAR 16:9], 25 fps, 50 tbr, 90k tbn
  Stream #0:1[0x101](pol): Audio: mp2 ([3][0][0][0] / 0x0003), 48000 Hz, stereo, fltp, 192 kb/s

 

I'll send the links in PM when needed, because they're generated links from paid online TV provider.

Griga Grand Master

Griga

Posted
Posted
1 hour ago, reki said:

I managed to narrow the problem: the leak happens when at least two TS streams are recorded from specific online provider.

 

Are you sure that your provider allows to receive two streams at the same time? I remember a case where this required two accounts/subscriptions.

 

On 5/11/2023 at 3:58 PM, reki said:

However, I found the moment when it starts:

 

The log indicates that two mechanisms triggered by "no data arriving anymore" are involved:

  • Media Server Options -> Hardware -> Retune on missing stream after (sec.). It is enabled by default for TS Stream devices and set to 5 seconds, in order to automatically handle a connection loss. You can disable it (set it to 0) if the TS Stream device is not automatically created on demand, but added manually to the device list.
  • Media Server Options -> Recordings -> Restart recording if no data for 60 secs, actually meaning "if no usable video/audio data". It tries to clear the situation by stopping the recording and re-initializing everything from the scratch.

 

22 hours ago, reki said:

The Mediaserver starts with ~60 MB of RAM and steadily consumes more. It looks the memory consumption increases in linear manner, shown in the chart. It happens when TS Streams are recorded.

 

Will be checked.

 

    reki Rookie

    reki

    Posted
    • Author
    Posted
    20 hours ago, Griga said:

    Are you sure that your provider allows to receive two streams at the same time? I remember a case where this required two accounts/subscriptions.

     

    The subscription allows four simultaneous connections. I verified it by running successfully four channels in mplayer on Linux. However, I cannot tell if the connection loss is caused by the the TV provider or on my side.

     

     

    Griga Grand Master

    Griga

    Posted
    Posted
    On 5/11/2023 at 6:34 PM, reki said:

    The Mediaserver starts with ~60 MB of RAM and steadily consumes more. It looks the memory consumption increases in linear manner, shown in the chart. It happens when TS Streams are recorded.

     

    I've tried some TS stream recording scenarios (including 2 streams simultaneously plus auto-retune and recording restarts triggered by interrupted streams) under debugger control with activated memory leak reporting, but found no evidence for a memory leak up to now.

     

    On 5/11/2023 at 3:58 PM, reki said:

    The exact moment of the crash is difficult to catch, because the log is truncated eventually. However, I found the moment when it starts:

     

    Obviously the desaster starts with the "Retune on missing stream" mechanism being triggered repeatedly for all TS Stream recordings, either by lost connections or gaps of 5 seconds or more without arriving data.

     

    For narrowing the cause down, please add x TS Stream devices in the Media Server Options -> Hardware (for recording a maximum of x TS Streams simultaneously) and set the "Retune on missing stream" option for all of them to 0, which deactivates it. What happens? Does the problem still occur in the same way as before?

     

    reki Rookie

    reki

    Posted
    • Author
    Posted

    I added two TS Stream devices and set Retune on missing stream to 0. In this configuration, memory footprint doesn't increase without bounds, but after some time one of the streams goes to 0.000 MB/s data rate, perhaps because of some provider issues. Having this setting set to 5 seconds, the recorder keeps recording, but the RAM usage constantly increases. Discont. counter also increases, perhaps because of connectivity problems.

    Griga Grand Master

    Griga

    Posted
    Posted

    Thanks for investigation. Unfortunately it seems to be impossible to get clean recordings of those streams, at least if you record two or more of them simultaneously. Anyway, your post tells me where I have to search for the memory leak. It will be difficult to find out how it can occur, though. I need a good simulation of what is actually happening, maybe with a second Media Server as data source that suddenly stops data delivery.

     

    I also need to know the streaming fomat. Is it HLS (with a .m3u8 file extension in the URL) or MPEG Dash (.mpd) or a simple transport stream (.ts)? If the URL doesn't reveal it, you can start DVBViewer in debug mode (see Windows start menu -> DVBViewer) and play such a stream for a short time (a few seconds only, otherwise you'll get a huge log). The resulting DVBViewer.log from the configuration folder will tell me what I need to know. Since the URLs may contain login details for your provider, you may want to send the zipped log as attachment in a private forum message (PM).

     

    BTW: Does the connection also break occasionally when you are watching a single stream in DVBViewer? Ot two of them, one in the main window and the other one as Picture in Picture?

     

    Please note: The tests above with DVBViewer "stand-alone" require to stop the Media Server before launching DVBViewer, if it is located on the Media Server PC and configured as Media Server Client. Otherwise DVBViewer will try to obtain the stream(s) from the Media Server (always as pure TS), in order to avoid double bandwidth occupancy in case of simultaneous playback and recording.

     

    reki Rookie

    reki

    Posted
    • Author
    Posted

    I'll analyze your post later, I just logged in to inform I had just observed that memory leak happens also when Retune on missing stream is set to 0, albeit slower. It went up to over 120 MB in 2-3 hours. The memory is OK when flag Restart recording if no data for 60 secs is false.

     

    I'll check the information from your last post in couple of hours.

    Griga Grand Master

    Griga

    Posted
    Posted

    Thanks for the PM. The provided DVBViewer.log clarifies some things.

     

    Your URLs create an obstacle for the Media Server/DVBViewer, because they don't indicate which kind of stream will arrive. So DMS/DVBViewer first assume internet radio (some MP3/AAC audio stream) and use the according code branch. However, the server reply (after redirecting DMS/DVBViewer to another URL) indicates "Content-Type: video/mp2t", which means, the server will send a transport stream. This information lets DMS/DVBViewer stop the process and retune with the code branch for transport streams.

     

    You can avoid this "trial and error" detour and accelerate tuning by telling DMS/DVBViewer beforehand what it is. Simply replace http:// in the URLs by ts:// (does not work for https://). This will let DMS/DVBViewer  use the correct branch immediately. Another possible method is to append a query part like ?x=.ts to the URL, which is usually ignored by servers (except if it has a certain meaning for them by chance), but tells DMS/DVBViewer what they have to expect. This also works with https:// URLs.

     

    I first thought that this "trial and error" mechanism causes the memory leak, because I immediately got a memory leak report after trying one of your URLs in the DMS for recording. However, I couldn't reproduce it. It only happened once. Then an entry in your DVBViewer.log attracted my attention:

     

    Quote

    17.05.23 16:36:51.241 THTTPStream          Socket Read Error 10054

     

    This is a WSAECONNRESET error. You can look up the meaning here. It basically means that the server has been shut down. It's what a client would get while receiving a stream from the DMS if you would suddenly stop the server. I simulated this event by letting the DMS receive and record a transport stream from a second DMS on another PC. Then I stopped the server DMS and again got a memory leak report for the recording (client) DMS. In this way it is reproducible. This kind of leaking is not directly related to retune actions, but of course it may happen again and again if the client automatically re-establishes the connection.

     

    Now the rest of the work is to investigate why this error causes a memory leak and how it can be fixed.... will be continued.

     

    reki Rookie

    reki

    Posted
    • Author
    Posted

    Sorry for late reply, @Griga. I tested your fixed version of DVBVservice.exe for several hours and couple of recordings and the problem seems solved. The memory usage stays at ~25 MB. Thank you!

    Griga Grand Master

    Griga

    Posted
    Posted
    7 hours ago, reki said:

    the problem seems solved

     

    That's fine :) Thanks for your contribution. Without your observations and logs it would have been impossible to pinpoint the bug. Solving issues like this requires almost criminalistic methods and a lot of patience...

     

    DVBViewer Pro is affected by the same bug. Please let me know if you need a fixed version. In TransEdit only the audio stream (internet radio) part is affected.

     

    reki Rookie

    reki

    Posted
    • Author
    Posted
    3 hours ago, Griga said:

    DVBViewer Pro is affected by the same bug. Please let me know if you need a fixed version. In TransEdit only the audio stream (internet radio) part is affected.

     

    I use Media Server only.

    Join the conversation

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

    Guest
    Unfortunately, your content contains terms that we do not allow. Please edit your content to remove the highlighted words below.
    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.

    ×
    Go to topic listing
    ×
    ×
    • Create New...