[Bug] TV: missing audio stream in records (Sky) (2 Viewers)

Brette

MP Donator
  • Premium Supporter
  • January 11, 2007
    204
    18
    Sinsheim
    Home Country
    Germany Germany
    MediaPortal Version: 1.5.0

    Description
    MPV: 1.6.0 Final (Same issue at 1.5.0)
    Hardware: DD Cine S2 V6.5 / Deltacam Twin

    Some Sky Stations included 3 audio streams at movies.
    Before the movie starts (advertising) there is only 1 audio stream.
    In case the recording starts at this time, the 2 "new" audio streams are missing in the recorded file.

    Thanks!
    Brette

    Logs will follow

    Steps to Reproduce:
    start a record before the movie with 3 audiostreams begins.
     
    Last edited:

    mm1352000

    Retired Team Member
  • Premium Supporter
  • September 1, 2008
    21,577
    8,224
    Home Country
    New Zealand New Zealand
    Hello Brette

    ...yes, full log files will be required. This situation should be supported. Of course, you can't see/select the 2 additional audio streams until they actually start (presumably when the movie itself starts).

    mm
     

    Brette

    MP Donator
  • Premium Supporter
  • January 11, 2007
    204
    18
    Sinsheim
    Home Country
    Germany Germany
    Hello mm

    by watching TV threre is no issue.
    It is possible to select all the audio streams and threre are working well.

    The "new" audio streams can be selected also at recordings, but they are silent.
    Start recording at the channel 5 minutes before the movie starts -> the state of the channel at the tv-server changes to scrambled "YES" when the movie starts.

    I suspect the cam need a "trigger" to unscramble to 2 new audio streams.

    At 20:15 tomorrow i will start a new record.
    Then i will post the logfiles.

    Brette
     

    mm1352000

    Retired Team Member
  • Premium Supporter
  • September 1, 2008
    21,577
    8,224
    Home Country
    New Zealand New Zealand
    Hello again Brette

    by watching TV threre is no issue.
    It is possible to select all the audio streams and threre are working well.

    The "new" audio streams can be selected also at recordings, but they are silent.
    Start recording at the channel 5 minutes before the movie starts -> the state of the channel at the tv-server changes to scrambled "YES" when the movie starts.
    Ahhh, this could be very interesting. :)

    I suspect the cam need a "trigger" to unscramble to 2 new audio streams.
    Yep. TV Server should send that trigger... but maybe the DD driver is ignoring the request because the channel wasn't changed... or maybe there is some other reason why the request is not sent to the CAM. Really looking forward to seeing these log files... :)

    mm
    PS: please make sure TV Server log level is set to debug:
    http://wiki.team-mediaportal.com/1_.../TV-Server_Configuration/06_General#Log_Level
     

    mm1352000

    Retired Team Member
  • Premium Supporter
  • September 1, 2008
    21,577
    8,224
    Home Country
    New Zealand New Zealand
    Hello Zoidberg77

    this has also been reported by rbo Heffernan vonlanken and radical in this german thread.
    Ahhhh, okay. Seems this problem was reported a long time ago. Unfortunately I don't speak/understand any language other than English and a little Japanese (except via Google Translate) so I don't monitor the German section.

    I've seen this too sometimes on recordings from Sky Cinema HD at 20:15 (with 10 min pre-record). I could try to fetch some logs too if you're interested, but I'm using md*** if this does matter...
    Yes - please post log files. The problem may be dependent on the method used for decryption (MD or CAM) or the tuner used (ie. CA/CI API), the CAM itself... and TsWriter and the TVLibrary.

    Right now I think the streams are probably recorded as encrypted. The first question to answer is: is TV Server sending a new decrypt request as required. This is relevant for all methods of decryption.

    mm
     

    radical

    Portal Pro
    December 16, 2010
    1,466
    191
    Home Country
    Germany Germany
    Ahhhh, okay. Seems this problem was reported a long time ago. Unfortunately I don't speak/understand any language other than English and a little Japanese (except via Google Translate) so I don't monitor the German section.

    Till now no one have reported it, because most of users who having this issue are using M***I. We just waited for someone who can verify this without using an softcam. So it won't be blamed on M***I.
     

    mm1352000

    Retired Team Member
  • Premium Supporter
  • September 1, 2008
    21,577
    8,224
    Home Country
    New Zealand New Zealand
    Well, I'm inviting anybody to post log files... :)
     

    Brette

    MP Donator
  • Premium Supporter
  • January 11, 2007
    204
    18
    Sinsheim
    Home Country
    Germany Germany
    Hi,

    here are the logs, also including the tuner logfile
    The movie starts at 11:45 on Sky HD Cinema
     

    mm1352000

    Retired Team Member
  • Premium Supporter
  • September 1, 2008
    21,577
    8,224
    Home Country
    New Zealand New Zealand
    Thanks (y)

    So, lets start by looking at the TsWriter log files...
    Original PMT with only the German audio is received when the recording starts:
    [2014-01-04 11:38:09,250] [6ef7908] [a5c] - pmtgrabber: got pmt 64 sid:83
    [2014-01-04 11:38:09,250] [6ef7908] [a5c] - pmtgrabber: PMT pids changed from:
    [2014-01-04 11:38:09,250] [6ef7908] [a5c] - pcr pid: 0
    [2014-01-04 11:38:09,250] [6ef7908] [a5c] - pmt pid: 0
    [2014-01-04 11:38:09,250] [6ef7908] [a5c] - pmtgrabber: PMT pids changed to:
    [2014-01-04 11:38:09,250] [6ef7908] [a5c] - pcr pid: 4ff
    [2014-01-04 11:38:09,250] [6ef7908] [a5c] - pmt pid: 64
    [2014-01-04 11:38:09,250] [6ef7908] [a5c] - video pid: 4ff type: H264
    [2014-01-04 11:38:09,250] [6ef7908] [a5c] - audio pid: 503 language: deu type: AC3
    [2014-01-04 11:38:09,250] [6ef7908] [a5c] - pmtgrabber: got new pmt version:15 ffffffff, service_id:83

    That is version 15. We send it to the tuner to start decryption:
    [collapse]
    [2014-01-04 11:38:09,250] [Log ] [26 ] [INFO ] - subch:0 OnPMTReceived() pmt:64 ran:True dynamic:False
    [2014-01-04 11:38:09,250] [Log ] [scheduler thread] [DEBUG] - WaitForPMT: Found PMT after 0,2496004 seconds.
    [2014-01-04 11:38:09,250] [Log ] [scheduler thread] [INFO ] - subch:0 SendPmt:83 83 FFFFFFFF 15
    [2014-01-04 11:38:09,250] [Log ] [scheduler thread] [INFO ] - Decode pmt
    [2014-01-04 11:38:09,250] [Log ] [scheduler thread] [INFO ] - descr1 len:6 9 4 18 33 f8 b6
    [2014-01-04 11:38:09,266] [Log ] [scheduler thread] [INFO ] - descr1 len:6 9 4 9 c4 fb b6
    [2014-01-04 11:38:09,266] [Log ] [scheduler thread] [INFO ] - descr1 len:6 9 4 9 af ff b6
    [2014-01-04 11:38:09,266] [Log ] [scheduler thread] [INFO ] - descr1 len:6 9 4 9 8c fa b6
    [2014-01-04 11:38:09,266] [Log ] [scheduler thread] [INFO ] - Set descriptor data with length 3
    [2014-01-04 11:38:09,266] [Log ] [scheduler thread] [INFO ] - PROBLEM : descriptor lengths dont match 7 10
    [2014-01-04 11:38:09,266] [Log ] [scheduler thread] [INFO ] - Set descriptor data with length 3
    [2014-01-04 11:38:09,266] [Log ] [scheduler thread] [INFO ] - Set descriptor data with length 6
    [2014-01-04 11:38:09,266] [Log ] [scheduler thread] [INFO ] - PROBLEM : descriptor lengths dont match 3 9
    [2014-01-04 11:38:09,266] [Log ] [scheduler thread] [INFO ] - subch:0 SendPMT version:21 len:84 131
    [2014-01-04 11:38:09,282] [Log ] [scheduler thread] [DEBUG] - Digital Devices:--> Setting service id 131 for decrypting returned 0
    [2014-01-04 11:38:09,282] [Log ] [scheduler thread] [INFO ] - subch:0 cam flags:True
    [2014-01-04 11:38:09,282] [Log ] [scheduler thread] [INFO ] - subch:0 SetMpegPidMapping
    [2014-01-04 11:38:09,282] [Log ] [scheduler thread] [INFO ] - subch:0 pid:4FF pcr
    [2014-01-04 11:38:09,282] [Log ] [scheduler thread] [INFO ] - subch:0 pid:64 pmt
    [2014-01-04 11:38:09,282] [Log ] [scheduler thread] [INFO ] - subch:0 pid:20 teletext type:6
    [2014-01-04 11:38:09,282] [Log ] [scheduler thread] [INFO ] - subch:0 map pid:20 teletext type:6
    [2014-01-04 11:38:09,297] [Log ] [scheduler thread] [INFO ] - subch:0 pid:4FF video type:H.264
    [2014-01-04 11:38:09,297] [Log ] [scheduler thread] [INFO ] - subch:0 map pid:4FF video type:H.264
    [2014-01-04 11:38:09,297] [Log ] [scheduler thread] [INFO ] - subch:0 pid:503 audio lang:deu type:AC3
    [2014-01-04 11:38:09,297] [Log ] [scheduler thread] [INFO ] - subch:0 map pid:503 audio lang:deu type:AC3
    [2014-01-04 11:38:09,297] [Log ] [scheduler thread] [DEBUG] - OnPMTReceived: MDAPI disabled. Possible reasons are _mdplugs=null or provider not listed
    [2014-01-04 11:38:09,297] [Log ] [scheduler thread] [INFO ] - subch:0 stop tif
    [2014-01-04 11:38:09,297] [Log ] [scheduler thread] [DEBUG] - WaitForPmt: PMT handling took 0,0468001 seconds.
    [2014-01-04 11:38:09,297] [Log ] [scheduler thread] [DEBUG] - card: Tuner locked: True
    [2014-01-04 11:38:09,313] [Log ] [scheduler thread] [INFO ] - **************************************************
    [2014-01-04 11:38:09,313] [Log ] [scheduler thread] [INFO ] - ***** SIGNAL LEVEL: 100, SIGNAL QUALITY: 100 *****
    [2014-01-04 11:38:09,313] [Log ] [scheduler thread] [INFO ] - **************************************************
    [2014-01-04 11:38:09,313] [Log ] [scheduler thread] [DEBUG] - card: tuned user: scheduler7 subchannel: 0
    [2014-01-04 11:38:09,313] [Log ] [scheduler thread] [INFO ] - user:scheduler7 add
    [2014-01-04 11:38:09,375] [Log ] [scheduler thread] [DEBUG] - Scheduler: MakeFileName() using "moviesformat" (_isSerie=False)
    [2014-01-04 11:38:12,012] [Log ] [scheduler thread] [INFO ] - Scheduler : record to G:\\Lawless - Die Gesetzlosen - Sky Cinema HD - 2014-01-04.ts
    [2014-01-04 11:38:12,012] [Log ] [scheduler thread] [INFO ] - Controller: epg stop
    [2014-01-04 11:38:12,027] [Log ] [scheduler thread] [DEBUG] - Recorder.start add audioVideoEventHandler
    [2014-01-04 11:38:12,027] [Log ] [scheduler thread] [INFO ] - card: StartRecording 3 G:\\Lawless - Die Gesetzlosen - Sky Cinema HD - 2014-01-04.ts
    [2014-01-04 11:38:12,027] [Log ] [scheduler thread] [INFO ] - StartRecording to G:\\Lawless - Die Gesetzlosen - Sky Cinema HD - 2014-01-04.ts
    [2014-01-04 11:38:12,027] [Log ] [scheduler thread] [INFO ] - subch:0 StartRecord(G:\\Lawless - Die Gesetzlosen - Sky Cinema HD - 2014-01-04.ts)
    [2014-01-04 11:38:12,027] [Log ] [scheduler thread] [INFO ] - subch:0-0 tswriter StartRecording...
    [2014-01-04 11:38:12,027] [Log ] [scheduler thread] [INFO ] - SetRecorderPids
    [2014-01-04 11:38:12,027] [Log ] [scheduler thread] [INFO ] - Set video / audio observer
    [2014-01-04 11:38:12,074] [Log ] [scheduler thread] [INFO ] - DVB subch:0 Started recording
    [2014-01-04 11:38:12,074] [Log ] [26 ] [INFO ] - PID seen - type = Video
    [2014-01-04 11:38:12,074] [Log ] [26 ] [DEBUG] - Recorder audioVideoEventHandler Video
    [2014-01-04 11:38:12,090] [Log ] [scheduler thread] [INFO ] - card: WaitForFile - waiting _eventAudio & _eventVideo
    [2014-01-04 11:38:12,105] [Log ] [26 ] [INFO ] - PID seen - type = Audio
    [2014-01-04 11:38:12,105] [Log ] [26 ] [DEBUG] - Recorder audioVideoEventHandler Audio
    [2014-01-04 11:38:12,105] [Log ] [scheduler thread] [INFO ] - card: WaitForFile - video and audio are seen after 0,0156 seconds[/collapse]

    Two minutes later we see version 16 of the PMT:
    [2014-01-04 11:40:23,738] [6ef7908] [a5c] - pmtgrabber: got new pmt version:16 15, service_id:83
    [2014-01-04 11:40:23,738] [6ef7908] [a5c] - pmtgrabber: NO callback done because a/v pids still the same.

    It is not sent to the tuner because the video/audio PIDs are still the same.

    Less than one second later we see version 17 of the PMT:
    [2014-01-04 11:40:24,144] [6ef7908] [a5c] - pmtgrabber: PMT pids changed from:
    [2014-01-04 11:40:24,144] [6ef7908] [a5c] - pcr pid: 4ff
    [2014-01-04 11:40:24,144] [6ef7908] [a5c] - pmt pid: 64
    [2014-01-04 11:40:24,144] [6ef7908] [a5c] - video pid: 4ff type: H264
    [2014-01-04 11:40:24,144] [6ef7908] [a5c] - audio pid: 503 language: deu type: AC3
    [2014-01-04 11:40:24,144] [6ef7908] [a5c] - pmtgrabber: PMT pids changed to:
    [2014-01-04 11:40:24,144] [6ef7908] [a5c] - pcr pid: 4ff
    [2014-01-04 11:40:24,144] [6ef7908] [a5c] - pmt pid: 64
    [2014-01-04 11:40:24,144] [6ef7908] [a5c] - video pid: 4ff type: H264
    [2014-01-04 11:40:24,144] [6ef7908] [a5c] - audio pid: 503 language: deu type: AC3
    [2014-01-04 11:40:24,144] [6ef7908] [a5c] - audio pid: 504 language: eng type: AC3
    [2014-01-04 11:40:24,144] [6ef7908] [a5c] - pmtgrabber: got new pmt version:17 16, service_id:83
    [2014-01-04 11:40:24,144] [6ef7908] [a5c] - pmtgrabber: do callback pid 64

    Now we see the Engish audio for the first time. This PMT triggers a new decryption request due to the new PID detected:
    [2014-01-04 11:40:24,144] [Log ] [26 ] [INFO ] - subch:0 OnPMTReceived() pmt:64 ran:True dynamic:True
    [2014-01-04 11:40:26,063] [Log ] [26 ] [INFO ] - subch:0 SendPmt:83 83 15 17
    [2014-01-04 11:40:26,063] [Log ] [26 ] [INFO ] - Decode pmt
    [2014-01-04 11:40:26,063] [Log ] [26 ] [INFO ] - descr1 len:6 9 4 18 33 f8 b6
    [2014-01-04 11:40:26,063] [Log ] [26 ] [INFO ] - descr1 len:6 9 4 9 c4 fb b6
    [2014-01-04 11:40:26,063] [Log ] [26 ] [INFO ] - descr1 len:6 9 4 9 af ff b6
    [2014-01-04 11:40:26,063] [Log ] [26 ] [INFO ] - descr1 len:6 9 4 9 8c fa b6
    [2014-01-04 11:40:26,063] [Log ] [26 ] [INFO ] - Set descriptor data with length 3
    [2014-01-04 11:40:26,078] [Log ] [26 ] [INFO ] - PROBLEM : descriptor lengths dont match 7 10
    [2014-01-04 11:40:26,078] [Log ] [26 ] [INFO ] - Set descriptor data with length 3
    [2014-01-04 11:40:26,078] [Log ] [26 ] [INFO ] - Set descriptor data with length 6
    [2014-01-04 11:40:26,078] [Log ] [26 ] [INFO ] - PROBLEM : descriptor lengths dont match 3 9
    [2014-01-04 11:40:26,078] [Log ] [26 ] [INFO ] - Set descriptor data with length 6
    [2014-01-04 11:40:26,078] [Log ] [26 ] [INFO ] - PROBLEM : descriptor lengths dont match 3 9
    [2014-01-04 11:40:26,078] [Log ] [26 ] [INFO ] - subch:0 SendPMT version:23 len:105 131
    [2014-01-04 11:40:26,078] [Log ] [26 ] [DEBUG] - Digital Devices:--> Setting service id 131 for decrypting returned 0
    [2014-01-04 11:40:26,078] [Log ] [26 ] [INFO ] - subch:0 cam flags:True
    [2014-01-04 11:40:26,078] [Log ] [26 ] [INFO ] - subch:0 SetMpegPidMapping
    [2014-01-04 11:40:26,094] [Log ] [26 ] [INFO ] - subch:0 pid:4FF pcr
    [2014-01-04 11:40:26,094] [Log ] [26 ] [INFO ] - subch:0 pid:64 pmt
    [2014-01-04 11:40:26,094] [Log ] [26 ] [INFO ] - subch:0 pid:20 teletext type:6
    [2014-01-04 11:40:26,094] [Log ] [26 ] [INFO ] - subch:0 map pid:20 teletext type:6
    [2014-01-04 11:40:26,094] [Log ] [26 ] [INFO ] - subch:0 pid:4FF video type:H.264
    [2014-01-04 11:40:26,094] [Log ] [26 ] [INFO ] - subch:0 map pid:4FF video type:H.264
    [2014-01-04 11:40:26,094] [Log ] [26 ] [INFO ] - subch:0 pid:503 audio lang:deu type:AC3
    [2014-01-04 11:40:26,094] [Log ] [26 ] [INFO ] - subch:0 map pid:503 audio lang:deu type:AC3
    [2014-01-04 11:40:26,094] [Log ] [26 ] [INFO ] - subch:0 pid:504 audio lang:eng type:AC3
    [2014-01-04 11:40:26,094] [Log ] [26 ] [INFO ] - subch:0 map pid:504 audio lang:eng type:AC3
    [2014-01-04 11:40:26,109] [Log ] [26 ] [INFO ] - SetRecorderPids
    [2014-01-04 11:40:26,109] [Log ] [26 ] [DEBUG] - OnPMTReceived: MDAPI disabled. Possible reasons are _mdplugs=null or provider not listed
    [2014-01-04 11:40:26,109] [Log ] [26 ] [INFO ] - PID seen - type = Video
    [2014-01-04 11:40:26,109] [Log ] [26 ] [DEBUG] - Recorder audioVideoEventHandler Video
    [2014-01-04 11:40:26,109] [Log ] [26 ] [INFO ] - PID seen - type = Audio
    [2014-01-04 11:40:26,109] [Log ] [26 ] [DEBUG] - Recorder audioVideoEventHandler Audio

    Finally, we see PMT version 18 less than 1 second after version 17:
    [2014-01-04 11:40:26,187] [6ef7908] [a5c] - pmtgrabber: got new pmt version:18 17, service_id:83
    [2014-01-04 11:40:26,187] [6ef7908] [a5c] - pmtgrabber: NO callback done because a/v pids still the same.

    No decrypt request is sent to the tuner because the video/audio PIDs are the same.

    So, my first question would be: why are there so many PMT versions?
    I can't tell for sure, but it looks like the CA descriptors are not changing:
    [2014-01-04 11:38:09,250] [Log ] [scheduler thread] [INFO ] - descr1 len:6 9 4 18 33 f8 b6
    [2014-01-04 11:38:09,266] [Log ] [scheduler thread] [INFO ] - descr1 len:6 9 4 9 c4 fb b6
    [2014-01-04 11:38:09,266] [Log ] [scheduler thread] [INFO ] - descr1 len:6 9 4 9 af ff b6
    [2014-01-04 11:38:09,266] [Log ] [scheduler thread] [INFO ] - descr1 len:6 9 4 9 8c fa b6

    [2014-01-04 11:40:26,063] [Log ] [26 ] [INFO ] - descr1 len:6 9 4 18 33 f8 b6
    [2014-01-04 11:40:26,063] [Log ] [26 ] [INFO ] - descr1 len:6 9 4 9 c4 fb b6
    [2014-01-04 11:40:26,063] [Log ] [26 ] [INFO ] - descr1 len:6 9 4 9 af ff b6
    [2014-01-04 11:40:26,063] [Log ] [26 ] [INFO ] - descr1 len:6 9 4 9 8c fa b6

    From the tuner log files we see:
    04.01.2014 11:38:08 DDTuner Device 210:100: Acquire DVB-S Tuner 1
    04.01.2014 11:38:08 DDTuner Device 210:100: Start DVB-S Tuner 1
    04.01.2014 11:38:09 DDTuner Device 210:100: Tune success DVB-S Tuner 1
    Version = 4
    Error = 00000000
    Frequency = 11.914.000
    Multiplyer = 1.000
    LNBLow = 9.750.000
    LNBHigh = 10.600.000
    LNBSwitch = 11.700.000
    Polarity = 1
    Range = FFFFFFFF
    LNBSource = 0FF
    L-Frequency = 1.314.000.000
    LockStatus = 5
    Offset = -163.322
    S/N = 122
    Quality = 100
    Strength = 66
    SymbolRate = 27.500.000

    04.01.2014 11:38:09 DDCommonInterface Device 210:100: Set Program 131 CI 3
    04.01.2014 11:38:09 DDCommonInterface Device 210:100: Set Program 131 CI 3
    04.01.2014 11:40:26 DDCommonInterface Device 210:100: Set Program 131 CI 3

    So it looks like DD receives our decrypt requests... but we can't tell if it actually applies them...

    mm
     

    Users who are viewing this thread

    Top Bottom