Project

General

Profile

Bug #2171

MP2 radio stations hickups

Added by J H over 10 years ago. Updated almost 10 years ago.

Status:
Fixed
Priority:
Normal
Assignee:
-
Category:
-
Target version:
-
Start date:
2014-07-07
Due date:
% Done:

100%

Estimated time:
Found in version:
3.9.959~g6fab551
Affected Versions:

Description

I've noticed hickups in the audio of certain radio stations when using the git version of Tvheadend. The stable version plays fine. It's only the Music Choice channels, audio stream is MP2 and my provider is Ziggo in The Netherlands. I'm using Sundtek tuners and I've already did some testing with the support engineer of Sundtek to rule out the tuners.

Tvheadend log stays empty during playback, same for the playing software like XBMC, VLC etc.

OS: Ubuntu 14.04 LTS
Tvheadend v. 3.9.959~g6fab551

I've added a recording of a Music Choice channel. You can hear 4 hickups.


Files

tvheadend-debug.log (22 KB) tvheadend-debug.log J H, 2014-12-04 18:22
tvheadend-debug.log (1.04 MB) tvheadend-debug.log J H, 2014-12-04 21:31

History

#1

Updated by J H over 10 years ago

  • File Stutter.ts added

Added another maybe better example.

#2

Updated by J H about 10 years ago

Now on build 3.9.1539~g286509b and still existing. Also noticed stuttering on an unencrypted channel. Could someone please tell me if there's any way to log this in tvheadend? Normal debugging log shows no errors during playback.

#3

Updated by Jaroslav Kysela about 10 years ago

Could you provide the whole mux dump ? Use the 'play' link in the mux tab to gather the whole infomation. But only if the contents is not crypted..

#4

Updated by J H about 10 years ago

I'm sorry but I don't have a FTA channel that's affected. I was wrong.

It seems only some encrypted radio stations are wrong. I can provide you with a mux dump of one of those muxes if that is of any help?

#5

Updated by J H about 10 years ago

Is there any other information I can give to solve this issue?

#6

Updated by Jaroslav Kysela about 10 years ago

Could you grab the output stream from tvheadend using wireshark or tcpdump ? Only the TCP audio stream.. It looks like a timing issue..

#7

Updated by J H about 10 years ago

  • File stream-wireshark2.pcapng added

Added wireshark file. Not sure if this is the format you're looking for. If you need something else please say so.

#8

Updated by J H about 10 years ago

Did you spot a cause for this issue in the wireshark file?

#9

Updated by J H almost 10 years ago

Ziggo added a unencrypted Christmas Music Choice channel. Guess what... no stutter in playback. My best guess is there's something wrong with radio stations and encryption.

Could someone please take a look at it again?Version running now is 3.9.2165~g3579d04

#10

Updated by J H almost 10 years ago

Didn't mean unencrypted but unencrypted

#11

Updated by Jaroslav Kysela almost 10 years ago

Just some notes: Trying to analyze Stutter.ts - it looks like a raw (passthrough) TS file from TVH. There are missing frames in the audio stream:

A python script to analyze frame pts diffs:

import sys

fp = sys.stdin
prev = None
for l in fp.readlines():
  if l.startswith('pkt_pts_time='):
    next = float(l[13:-1])
    if prev:
      print "%.6f (diff %.6f)" % (next, next - prev)
    prev = next

Cmd line:

ffprobe -show_frames ~/Download/Stutter.ts | python a.py

Result:

90132.396111 (diff 0.026000)
90132.422111 (diff 0.026000)
90132.605111 (diff 0.183000) # gap - 1 + 6 missing frames
90132.631111 (diff 0.026000)
90132.683111 (diff 0.052000) # gap - 1 + 1 missing frame
90132.710111 (diff 0.027000)
90132.736111 (diff 0.026000)
90157.369111 (diff 0.026000)
90157.395111 (diff 0.026000)
90157.421111 (diff 0.026000)
90157.604111 (diff 0.183000) # gap - 1 + 6 missing frames
90157.630111 (diff 0.026000)
90157.683111 (diff 0.053000) # gap - 1 + 1 missing frame
90157.709111 (diff 0.026000)
90157.735111 (diff 0.026000)
90182.368111 (diff 0.026000)
90182.394111 (diff 0.026000)
90182.421111 (diff 0.027000)
90182.603111 (diff 0.182000) # gap - 1 + 6 missing frames
90182.630111 (diff 0.027000)
90182.682111 (diff 0.052000) # gap - 1 + 1 missing frame
90182.708111 (diff 0.026000)
90182.734111 (diff 0.026000)

Note that the time difference between gaps is 25 seconds each (descrambling key change?).

#12

Updated by Jaroslav Kysela almost 10 years ago

Could you provide --trace descrambler,capmt,cwc ?

#13

Updated by J H almost 10 years ago

Here you go. What I noticed is that the stutter in audio lines up perfectly with the ECM message in the log. Hope this puts you on the right track!

#14

Updated by Jaroslav Kysela almost 10 years ago

Could you do same test with this one-line addition ?

diff --git a/src/descrambler/descrambler.c b/src/descrambler/descrambler.c
index d42683e..94f7b3b 100755
--- a/src/descrambler/descrambler.c
+++ b/src/descrambler/descrambler.c
@@ -370,6 +370,7 @@ descrambler_descramble ( service_t *t,
       sbuf_free(&dr->dr_buf);
     }
     ki = tsb[3];
+    tvhtrace("descrambler", "ki = %02x", ki);
     if ((ki & 0x80) != 0x00) {
       if (key_valid(dr, ki) == 0) {
         if (tvhlog_limit(&dr->dr_loglimit_key, 10))
#15

Updated by J H almost 10 years ago

Same problem, log added

#16

Updated by Jaroslav Kysela almost 10 years ago

Which CSA do you use ?

$ grep CSA .config.mk 
CONFIG_TVHCSA = yes
CONFIG_DVBCSA = no
#17

Updated by J H almost 10 years ago

xbmc@mediacenter:~/tvheadend$ grep CSA .config.mk
CONFIG_TVHCSA = yes
CONFIG_DVBCSA = no
#18

Updated by Jaroslav Kysela almost 10 years ago

Another debug code:

diff --git a/src/descrambler/descrambler.c b/src/descrambler/descrambler.c
index d42683e..d838b1d 100755
--- a/src/descrambler/descrambler.c
+++ b/src/descrambler/descrambler.c
@@ -326,6 +326,9 @@ descrambler_descramble ( service_t *t,

   lock_assert(&t->s_stream_mutex);

+  static int didx = 0;
+  tvhtrace("descrambler", "descramble ts packet %i (PID %i)", didx++, st->es_pid);
+
   if (dr == NULL)
     return -1;
   count = failed = 0;
diff --git a/src/input/mpegts/tsdemux.c b/src/input/mpegts/tsdemux.c
index 2b4f7e0..d3016e3 100644
--- a/src/input/mpegts/tsdemux.c
+++ b/src/input/mpegts/tsdemux.c
@@ -256,6 +256,10 @@ ts_recv_packet2(mpegts_service_t *t, const uint8_t *tsb)
   elementary_stream_t *st;
   int pid = (tsb[1] & 0x1f) << 8 | tsb[2];

+  static int didx = 0;
+  tvhtrace("descrambler", "output ts packet %i PID %i", didx++, pid);
+  tvhlog_hexdump("descrambler", tsb, 188);
+
   if((st = service_stream_find((service_t*)t, pid)) != NULL)
     ts_recv_packet0(t, st, tsb);
 }
#19

Updated by J H almost 10 years ago

  • File tvheadend-debug.log added

Log added, for example audio stutter at:

  • 16:47:34
  • 16:47:54
  • 16:48:14

And so on with 20 seconds interval

#20

Updated by Jaroslav Kysela almost 10 years ago

OK. No descrambled TS packets are lost. So, it appears that the packets are missing before they enter to the descrambler.

Could you try simultaneous streaming the whole mux while the radio service is used, if it changes something? (Something like 'wget -O /dev/null <mux_play_url_from_the_mux_grid>'.)

#21

Updated by J H almost 10 years ago

Just tried, no changes.

#22

Updated by Jaroslav Kysela almost 10 years ago

I need to implement a way to insert the descrambling keys to the whole mux stream and also implement the re-play functionality, so I can do testing directly on my machine. It may take some time.

#23

Updated by J H almost 10 years ago

Ok, thanks very much! Please say when you need more info from me.

#24

Updated by Jaroslav Kysela almost 10 years ago

OK. Grab latest sources. Use --enable-tsdebug as the configure option. Then run tvheadend with "--tsdebug <directory>" arguments. Then run the test and you should see in directory two files. I need them for analyze what's going wrong. One file is raw input from the linuxdvb subsystem and the second file is almost same (tvh does some processing - no contents change) but with added descrambler keys.

#25

Updated by J H almost 10 years ago

  • File 658MHz in Ziggo-1417994463-0x7f6d1c009bc0-input.ts added
  • File 658MHz in Ziggo-1417994463-0x7f6d1c009bc0-mux.ts added

Resulted files are added.

#26

Updated by Jaroslav Kysela almost 10 years ago

Tried to re-play and guess what - no packets are lost, but I had to fix a little issue with the PCR extraction - v3.9-2214-g8668734 for tsfile.

I don't think that it's related for the live playback, but could you test the recent code ?

#27

Updated by J H almost 10 years ago

  • File 658MHz in Ziggo-1418052479-0x16e5200-input.ts added
  • File 658MHz in Ziggo-1418052479-0x16e5200-mux.ts added

Issue not resolved as you already suspected, added the .ts files

#28

Updated by Jaroslav Kysela almost 10 years ago

Could you try this ?

diff --git a/src/descrambler/descrambler.c b/src/descrambler/descrambler.c
index a15aa64..0706c9b 100755
--- a/src/descrambler/descrambler.c
+++ b/src/descrambler/descrambler.c
@@ -179,6 +179,8 @@ descrambler_keys ( th_descrambler_t *td, int type,
   if (tvhcsa_set_type(&dr->dr_csa, type) < 0)
     return;

+  usleep(500000);
+
   pthread_mutex_lock(&t->s_stream_mutex);

   LIST_FOREACH(td2, &t->s_descramblers, td_service_link)

BTW: Also the second re-play was successful (no gaps in the output stream).

#29

Updated by J H almost 10 years ago

TVH crashes with that code added. Do you need a crashlog and where can I find it?

#30

Updated by Jaroslav Kysela almost 10 years ago

diff --git a/src/descrambler/cwc.c b/src/descrambler/cwc.c
index bac4aa4..a36c8c2 100755
--- a/src/descrambler/cwc.c
+++ b/src/descrambler/cwc.c
@@ -809,7 +809,9 @@ forbid:
       es->es_keystate = ES_RESOLVED;
       es->es_resolved = 1;

+      pthread_mutex_unlock(&ct->cs_cwc->cwc_mutex);
       descrambler_keys((th_descrambler_t *)ct, DESCRAMBLER_DES, msg + 3, msg + 3 + 8);
+      pthread_mutex_lock(&ct->cs_cwc->cwc_mutex);
     } else {
       tvhlog(LOG_DEBUG, "cwc",
            "Received ECM reply%s for service \"%s\" " 
diff --git a/src/descrambler/descrambler.c b/src/descrambler/descrambler.c
index a15aa64..0706c9b 100755
--- a/src/descrambler/descrambler.c
+++ b/src/descrambler/descrambler.c
@@ -179,6 +179,8 @@ descrambler_keys ( th_descrambler_t *td, int type,
   if (tvhcsa_set_type(&dr->dr_csa, type) < 0)
     return;

+  usleep(500000);
+
   pthread_mutex_lock(&t->s_stream_mutex);

   LIST_FOREACH(td2, &t->s_descramblers, td_service_link)
#31

Updated by J H almost 10 years ago

I'm very happy to tell you this seemed to fix the issue. Tested multiple radio channels en playback seems fine again. Thanks very much for your time and effort!

#32

Updated by Jaroslav Kysela almost 10 years ago

It's not a fix, but just a debug code. It looks like a timing issue (wrong key is used for decoding some frames for a short period). The patch just delays the new key processing by 500 ms.

#33

Updated by J H almost 10 years ago

Ok I understand. If there's something to test please say so.

#34

Updated by Jaroslav Kysela almost 10 years ago

I found the real issue. Basically, the key was changed too quickly and tvh buffers some TS packets for the DES decoder. These buffered TS packets must be flushed (processed) before key changes, otherwise they are decoded with the new key which is invalid for them (thus some pieces of the audio stream weren't parsed properly). I'm working on a fix. I only wonder, why we haven't noted before, because this bug is really serious.

#35

Updated by J H almost 10 years ago

I made a forum post here asking if anybody else was having this issue, no replies. I also asked on tweakers.net in the tvheadend topic if anyone else noticed... no one. Guess I'm the only one left here listening to radio.

#36

Updated by Jaroslav Kysela almost 10 years ago

  • Status changed from New to Fixed
  • % Done changed from 0 to 100

Applied in changeset commit:tvheadend|67938bc9d9774dff7b99e4e134d5c38bde55cce9.

#37

Updated by Jaroslav Kysela almost 10 years ago

The above commit contains the proper fix for your issue. Could you test ?

#38

Updated by J H almost 10 years ago

Tested and confirmed to fix the issue. Thanks again!

#39

Updated by Jaroslav Kysela almost 10 years ago

J H wrote:

I made a forum post here asking if anybody else was having this issue, no replies. I also asked on tweakers.net in the tvheadend topic if anyone else noticed... no one. Guess I'm the only one left here listening to radio.

I think that the problem was that most of radio stations on SAT are not encrypted (at least it's true for my country and I think also for most of European countries).

#40

Updated by Jaroslav Kysela almost 10 years ago

  • File deleted (tvheadend-debug.log)
#41

Updated by Jaroslav Kysela almost 10 years ago

  • File deleted (658MHz in Ziggo-1417994463-0x7f6d1c009bc0-mux.ts)
#42

Updated by Jaroslav Kysela almost 10 years ago

  • File deleted (stream-wireshark2.pcapng)
#43

Updated by Jaroslav Kysela almost 10 years ago

  • File deleted (Stutter.ts)
#44

Updated by Jaroslav Kysela almost 10 years ago

  • File deleted (recording.ts)
#45

Updated by Jaroslav Kysela almost 10 years ago

  • File deleted (658MHz in Ziggo-1417994463-0x7f6d1c009bc0-input.ts)
#46

Updated by Jaroslav Kysela almost 10 years ago

  • File deleted (658MHz in Ziggo-1418052479-0x16e5200-mux.ts)
#47

Updated by Jaroslav Kysela almost 10 years ago

  • File deleted (658MHz in Ziggo-1418052479-0x16e5200-input.ts)

Also available in: Atom PDF