Bug #2172
Occasional audio stream not starting
0%
Description
Ticket for "No sound every 1 in 20-25 channel change" described in:
https://tvheadend.org/boards/5/topics/11660
Below is log output from pvr.tvh when I subscribe to a channel where the AC3 audio fails.
12:08:26 T:7152 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - Announce(flag=Player, sender=xbmc, message=OnPlay) 12:08:27 T:6608 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - demux read nothing 12:08:27 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - receive message [subscriptionStart] 12:08:27 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - demux subscription start 12:08:27 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - id: 1, type H264, codec: 28 12:08:27 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - demux subscription start 12:08:27 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - id: 2, type MPEG2AUDIO, codec: 86016 12:08:27 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - demux subscription start 12:08:27 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - id: 3, type AC3, codec: 86019 12:08:27 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - demux subscription start 12:08:27 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - id: 4, type TELETEXT, codec: 94215 12:08:27 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - demux subscription start 12:08:27 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - demux stream change 12:08:27 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - demux sourceInfo: 12:08:27 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - adapter : TBS6985-3 12:08:27 T:6608 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - demux read idx :-11 pts -4503599627370496.000000 len 0 12:08:27 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - network : CMORE 12:08:27 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - mux : 10903V 12:08:27 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - provider : Telenor 12:08:27 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - service : SVT1 HD 12:08:27 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - receive message [subscriptionStatus] 12:08:27 T:6608 DEBUG: CDVDDemuxPVRClient::RequestStreams(): added/updated stream 0:1 with codec_id 28 12:08:27 T:6608 DEBUG: CDVDDemuxPVRClient::RequestStreams(): added/updated stream 1:2 with codec_id 86016 12:08:27 T:6608 DEBUG: CDVDDemuxPVRClient::RequestStreams(): added/updated stream 2:3 with codec_id 86019 12:08:27 T:6608 DEBUG: CDVDDemuxPVRClient::RequestStreams(): added/updated stream 3:4 with codec_id 94215
For some reason, the AC3 stream seems to be missing from the backend (see "idx:3 num:0" below):
12:28:32 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - signalStatus: 12:28:32 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - status : GOOD 12:28:32 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - snr : 63350 12:28:32 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - ber : 0 12:28:32 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - unc : 0 12:28:32 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - signal : 52908 12:28:32 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - receive message [queueStatus] 12:28:32 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - stream stats: 12:28:32 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - idx:1 num:58840 12:28:32 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - idx:2 num:48981 12:28:32 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - idx:3 num:0 12:28:32 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - idx:4 num:58825 12:28:32 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - idx:5 num:0 12:28:32 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - queue stats: 12:28:32 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - pkts 1 12:28:32 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - bytes 691 12:28:32 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - delay 0 12:28:32 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - Idrop 0 12:28:32 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - Pdrop 0 12:28:32 T:9124 DEBUG: AddOnLog: Tvheadend Client: pvr.tvh - Bdrop 0
I noticed this during debugging of a teletext problem. My teletext problem seems like it could actually be the same problem. The teletext stream "id: 4" is also sometimes missing.
History
Updated by
Updated by John Smith over 10 years ago
Updated by I've been adding some debug prints to my backend and I think I have identified one failure mode. parse_sc() will initially set st->es_startcode to the first valid start code pattern it finds in the stream (0x000001XX). In some cases this will not be the correct start code. On subsequent valid start code patterns, parse_sc() will call parse_ac3() which will call depacketize(). depacketize() will fail and return 3 because it's expecting the start code to be equal to st->es_startcode. The buffer will never reset, no matter how much data is received, as long as depacketize() returns 3.
This is the code in depacketize():
plen = (buf[4] << 8) | buf[5];
if(plen + 6 > len || next_startcode != sc)
return 3;
if(plen + 6 < len)
return 1;
If depacketize() returns 1, the buffer will be reset. I don't really understand the intention of the next_startcode check in the code above so I don't want to just remove it even if I think it could fix this failure mode.
Updated by John Smith over 10 years ago
Jalle Grönroos wrote:
Can you post the full log somewhere?
Sorry, I've been focusing on the backend and I didn't save the XBMC log.
Updated by John Smith over 10 years ago
I haven't been able to think of a reason to keep that next_startcode check and everything's been working fine for me after removing it. It seems to fix the problem. Fix is included in PR:
https://github.com/tvheadend/tvheadend/pull/437
Updated by Mark Clarkstone over 10 years ago
Updated by - Status changed from New to Fixed
Fixed in commit:526417d1