Audio Demuxer/Parser problem on some channels

[herrnst]

Switched to Frodo and latest XVDR stuff and still seeing this issue while vdr-xvdr received many commits, so (re)opening this as Bugreport:

Running Ubuntu 12.04 64bit fully patched+nvidia-drivers-304.60, vdr-1.7.31, vdr-plugin-xvdr GIT-master-7e09df9 as of Oct 27, XBMC mainline-master 6d17467 as of Oct 27, xbmc-addon-xvdr GIT-master-ce18919 as of Oct 27.

On a few (but some of them more often watched channels, namely ProSieben and SAT.1, SD variants), audio "clicks" (on MP2 audio) or drops out (AC3 audio) every second. This happens everytime and is not limited to specific broadcasts, day/nighttimes or available audio channels on the tv channel.

When this happens, /var/log/syslog is spammed with "NEW AUDIO INFORMATION" messages every second (see below). Additionally, when AC3 is selected, XBMC's AudioEngine leaves lots of messages in xbmc.log. Furthermore, this - at some times (maybe depending on the duration the channel is played) - renders the VDR core unstable, resulting in VDR shutdowns/restarts without any segfault indication or other message e.g. in syslog.

I checked this behaviour with TVHeadend and plain VDR, and the problem (audio pops or drops) does NOT happen. Recordings are also fine. So I suspect some audio information parser problem inside vdr-plugin-xvdr.

If needed, I can provide e.g. a short recording in TS format (direct dump of /dev/frontend0 or so might be a bad idea as these channels are delivered scrambled on my cable network...).

Best regards

---

/var/log/syslog:

Oct 28 15:22:41 barias vdr: [29450] XVDR: --------------------------------------
Oct 28 15:22:41 barias vdr: [29450] XVDR: Channel streaming request: 7 - ProSieben
Oct 28 15:22:41 barias vdr: [29450] XVDR: Found available device 1
Oct 28 15:22:41 barias vdr: [29487] TS buffer on device 1 thread ended (pid=13581, tid=29487)
Oct 28 15:22:41 barias vdr: [29486] buffer stats: 137428 (3%) used
Oct 28 15:22:41 barias vdr: [29486] receiver on device 1 thread ended (pid=13581, tid=29486)
Oct 28 15:22:41 barias vdr: [29450] XVDR: Setting cached video information
Oct 28 15:22:41 barias vdr: [29450] XVDR: --------------------------------------
Oct 28 15:22:41 barias vdr: [29450] XVDR: NEW PICTURE INFORMATION:
Oct 28 15:22:41 barias vdr: [29450] XVDR: Picture Width: 576
Oct 28 15:22:41 barias vdr: [29450] XVDR: Picture Height: 720
Oct 28 15:22:41 barias vdr: [29450] XVDR: Display Aspect Ratio: 1.78
Oct 28 15:22:41 barias vdr: [29450] XVDR: --------------------------------------
Oct 28 15:22:41 barias vdr: [29787] cLiveStreamer stream processor thread started (pid=13581, tid=29787)
Oct 28 15:22:41 barias vdr: [29786] XVDR: LiveQueue started
Oct 28 15:22:41 barias vdr: [29450] XVDR: Successfully switched to channel 7 - ProSieben
Oct 28 15:22:41 barias vdr: [29450] XVDR: Started streaming of channel ProSieben (timeout 10 seconds, priority 50)
Oct 28 15:22:41 barias vdr: [29788] receiver on device 1 thread started (pid=13581, tid=29788)
Oct 28 15:22:41 barias vdr: [29789] TS buffer on device 1 thread started (pid=13581, tid=29789)
Oct 28 15:22:41 barias vdr: [29787] XVDR: streaming of channel started
Oct 28 15:22:42 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:42 barias vdr: [29787] XVDR: NEW AUDIO INFORMATION:
Oct 28 15:22:42 barias vdr: [29787] XVDR: Channels: 2
Oct 28 15:22:42 barias vdr: [29787] XVDR: Samplerate: 48000 Hz
Oct 28 15:22:42 barias vdr: [29787] XVDR: Bitrate: 192000 bps
Oct 28 15:22:42 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:42 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:42 barias vdr: [29787] XVDR: NEW AUDIO INFORMATION:
Oct 28 15:22:42 barias vdr: [29787] XVDR: Channels: 2
Oct 28 15:22:42 barias vdr: [29787] XVDR: Samplerate: 48000 Hz
Oct 28 15:22:42 barias vdr: [29787] XVDR: Bitrate: 384000 bps
Oct 28 15:22:42 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:42 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:42 barias vdr: [29787] XVDR: NEW PICTURE INFORMATION:
Oct 28 15:22:42 barias vdr: [29787] XVDR: Picture Width: 720
Oct 28 15:22:42 barias vdr: [29787] XVDR: Picture Height: 576
Oct 28 15:22:42 barias vdr: [29787] XVDR: Display Aspect Ratio: 1.78
Oct 28 15:22:42 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:42 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:42 barias vdr: [29787] XVDR: NEW AUDIO INFORMATION:
Oct 28 15:22:42 barias vdr: [29787] XVDR: Channels: 1
Oct 28 15:22:42 barias vdr: [29787] XVDR: Samplerate: 48000 Hz
Oct 28 15:22:42 barias vdr: [29787] XVDR: Bitrate: 448000 bps
Oct 28 15:22:42 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:42 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:42 barias vdr: [29787] XVDR: NEW AUDIO INFORMATION:
Oct 28 15:22:42 barias vdr: [29787] XVDR: Channels: 2
Oct 28 15:22:42 barias vdr: [29787] XVDR: Samplerate: 48000 Hz
Oct 28 15:22:42 barias vdr: [29787] XVDR: Bitrate: 384000 bps
Oct 28 15:22:42 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:43 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:43 barias vdr: [29787] XVDR: NEW AUDIO INFORMATION:
Oct 28 15:22:43 barias vdr: [29787] XVDR: Channels: 3
Oct 28 15:22:43 barias vdr: [29787] XVDR: Samplerate: 44100 Hz
Oct 28 15:22:43 barias vdr: [29787] XVDR: Bitrate: 56000 bps
Oct 28 15:22:43 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:43 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:43 barias vdr: [29787] XVDR: NEW AUDIO INFORMATION:
Oct 28 15:22:43 barias vdr: [29787] XVDR: Channels: 2
Oct 28 15:22:43 barias vdr: [29787] XVDR: Samplerate: 48000 Hz
Oct 28 15:22:43 barias vdr: [29787] XVDR: Bitrate: 384000 bps
Oct 28 15:22:43 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:44 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:44 barias vdr: [29787] XVDR: NEW AUDIO INFORMATION:
Oct 28 15:22:44 barias vdr: [29787] XVDR: Channels: 3
Oct 28 15:22:44 barias vdr: [29787] XVDR: Samplerate: 48000 Hz
Oct 28 15:22:44 barias vdr: [29787] XVDR: Bitrate: 384000 bps
Oct 28 15:22:44 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:44 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:44 barias vdr: [29787] XVDR: NEW AUDIO INFORMATION:
Oct 28 15:22:44 barias vdr: [29787] XVDR: Channels: 2
Oct 28 15:22:44 barias vdr: [29787] XVDR: Samplerate: 48000 Hz
Oct 28 15:22:44 barias vdr: [29787] XVDR: Bitrate: 384000 bps
Oct 28 15:22:44 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:45 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:45 barias vdr: [29787] XVDR: NEW AUDIO INFORMATION:
Oct 28 15:22:45 barias vdr: [29787] XVDR: Channels: 2
Oct 28 15:22:45 barias vdr: [29787] XVDR: Samplerate: 48000 Hz
Oct 28 15:22:45 barias vdr: [29787] XVDR: Bitrate: 448000 bps
Oct 28 15:22:45 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:45 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:45 barias vdr: [29787] XVDR: NEW AUDIO INFORMATION:
Oct 28 15:22:45 barias vdr: [29787] XVDR: Channels: 2
Oct 28 15:22:45 barias vdr: [29787] XVDR: Samplerate: 48000 Hz
Oct 28 15:22:45 barias vdr: [29787] XVDR: Bitrate: 384000 bps
Oct 28 15:22:45 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:46 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:46 barias vdr: [29787] XVDR: NEW AUDIO INFORMATION:
Oct 28 15:22:46 barias vdr: [29787] XVDR: Channels: 3
Oct 28 15:22:46 barias vdr: [29787] XVDR: Samplerate: 44100 Hz
Oct 28 15:22:46 barias vdr: [29787] XVDR: Bitrate: 56000 bps
Oct 28 15:22:46 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:46 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:46 barias vdr: [29787] XVDR: NEW AUDIO INFORMATION:
Oct 28 15:22:46 barias vdr: [29787] XVDR: Channels: 2
Oct 28 15:22:46 barias vdr: [29787] XVDR: Samplerate: 48000 Hz
Oct 28 15:22:46 barias vdr: [29787] XVDR: Bitrate: 384000 bps
Oct 28 15:22:46 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:47 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:47 barias vdr: [29787] XVDR: NEW AUDIO INFORMATION:
Oct 28 15:22:47 barias vdr: [29787] XVDR: Channels: 3
Oct 28 15:22:47 barias vdr: [29787] XVDR: Samplerate: 48000 Hz
Oct 28 15:22:47 barias vdr: [29787] XVDR: Bitrate: 384000 bps
Oct 28 15:22:47 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:47 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:47 barias vdr: [29787] XVDR: NEW AUDIO INFORMATION:
Oct 28 15:22:47 barias vdr: [29787] XVDR: Channels: 2
Oct 28 15:22:47 barias vdr: [29787] XVDR: Samplerate: 48000 Hz
Oct 28 15:22:47 barias vdr: [29787] XVDR: Bitrate: 384000 bps
Oct 28 15:22:47 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:48 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:48 barias vdr: [29787] XVDR: NEW AUDIO INFORMATION:
Oct 28 15:22:48 barias vdr: [29787] XVDR: Channels: 3
Oct 28 15:22:48 barias vdr: [29787] XVDR: Samplerate: 48000 Hz
Oct 28 15:22:48 barias vdr: [29787] XVDR: Bitrate: 448000 bps
Oct 28 15:22:48 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:48 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:48 barias vdr: [29787] XVDR: NEW AUDIO INFORMATION:
Oct 28 15:22:48 barias vdr: [29787] XVDR: Channels: 2
Oct 28 15:22:48 barias vdr: [29787] XVDR: Samplerate: 48000 Hz
Oct 28 15:22:48 barias vdr: [29787] XVDR: Bitrate: 384000 bps
Oct 28 15:22:48 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:49 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:49 barias vdr: [29787] XVDR: NEW AUDIO INFORMATION:
Oct 28 15:22:49 barias vdr: [29787] XVDR: Channels: 3
Oct 28 15:22:49 barias vdr: [29787] XVDR: Samplerate: 44100 Hz
Oct 28 15:22:49 barias vdr: [29787] XVDR: Bitrate: 56000 bps
Oct 28 15:22:49 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:49 barias vdr: [29787] XVDR: --------------------------------------
Oct 28 15:22:49 barias vdr: [29787] XVDR: NEW AUDIO INFORMATION:
Oct 28 15:22:49 barias vdr: [29787] XVDR: Channels: 2
Oct 28 15:22:49 barias vdr: [29787] XVDR: Samplerate: 48000 Hz
Oct 28 15:22:49 barias vdr: [29787] XVDR: Bitrate: 384000 bps
Oct 28 15:22:49 barias vdr: [29787] XVDR: --------------------------------------

xbmc.log
15:22:47 T:140593992013568    INFO: CSoftAE::InternalOpenSink - RAW passthrough enabled
15:22:47 T:140593992013568    INFO: CSoftAE::InternalOpenSink - keeping old sink with : AE_FMT_AC3, FL,FR, 48000hz
15:22:47 T:140593992013568   DEBUG: CSoftAE::InternalOpenSink - Internal Buffer Size: 2048
15:22:47 T:140592575137536   DEBUG: CDVDPlayerAudio:: Discontinuity - was:53517396534.613335, should be:53517294478.000000, error:-102056.613335
15:22:48 T:140592575137536   DEBUG: CDVDPlayerAudio:: Discontinuity - was:53517487663.138000, should be:53517358478.000000, error:-129185.138000
15:22:48 T:140592575137536   DEBUG: CDVDPlayerAudio:: Discontinuity - was:53517560314.152000, should be:53517455568.790337, error:-104745.361664
15:22:48 T:140592575137536   DEBUG: CDVDPlayerAudio:: Discontinuity - was:53517708572.467339, should be:53517601763.634003, error:-106808.833336
15:22:48 T:140592575137536    INFO: CAEStreamInfo::SyncAC3 - AC3 stream detected (2 channels, 48000Hz)
15:22:48 T:140592575137536   DEBUG: CDVDPlayerAudio:: Discontinuity - was:53517854604.867004, should be:53517710478.000000, error:-144126.867004
15:22:49 T:140593960490752   DEBUG: AddOnLog: VDR XVDR Client: Ping ...
15:22:49 T:140592575137536 WARNING: CDVDMessageQueue(audio)::Get - asked for new data packet, with nothing available
15:22:49 T:140592575137536    INFO: CAEStreamInfo::SyncAC3 - AC3 sync lost
15:22:49 T:140592676890368   DEBUG: CDVDPlayer::CheckContinuity - wrapback :1, prev:53519505300.000000, curr:53519502478.000000, diff:-2822.000000
15:22:49 T:140592575137536    INFO: CAEStreamInfo::SyncAC3 - AC3 stream detected (2 channels, 48000Hz)
15:22:49 T:140594353387392   DEBUG: ------ Window Deinit (DialogKaiToast.xml) ------
15:22:51 T:140592545765120   DEBUG: CPullupCorrection: detected pattern of length 1: 20000.00, frameduration: 20000.000000
15:22:51 T:140592676890368   DEBUG: CDVDDemuxPVRClient::UpdateStreams(): update stream 0:544 with codec_id 86016
15:22:51 T:140592676890368   DEBUG: CDVDDemuxPVRClient::UpdateStreams(): update stream 1:546 with codec_id 86019
15:22:51 T:140592676890368   DEBUG: CDVDDemuxPVRClient::UpdateStreams(): update stream 2:548 with codec_id 94215
15:22:51 T:140592676890368   DEBUG: CDVDDemuxPVRClient::UpdateStreams(): update stream 3:543 with codec_id 2
15:22:51 T:140592676890368  NOTICE: Opening audio stream: 1 source: 256
15:22:51 T:140592676890368  NOTICE: Finding audio codec for: 86019
15:22:51 T:140592676890368   DEBUG: FactoryCodec - Audio: passthrough - Opening
15:22:51 T:140592676890368   DEBUG: FactoryCodec - Audio: passthrough - Opened
15:22:51 T:140592676890368   DEBUG: CDVDPlayer::HandleMessages - player started 1
15:22:51 T:140592575137536   DEBUG: CDVDPlayerAudio: Sample rate changed, checking for passthrough
15:22:51 T:140592575137536   DEBUG: FactoryCodec - Audio: passthrough - Opening
15:22:51 T:140592575137536   DEBUG: FactoryCodec - Audio: passthrough - Opened
15:22:51 T:140592575137536    INFO: CAEStreamInfo::SyncAC3 - AC3 stream detected (2 channels, 48000Hz)
15:22:51 T:140592575137536   DEBUG: CDVDPlayerAudio: Sample rate changed, checking for passthrough
15:22:51 T:140592575137536   DEBUG: FactoryCodec - Audio: passthrough - Opening
15:22:51 T:140592575137536   DEBUG: FactoryCodec - Audio: passthrough - Opened
15:22:51 T:140592575137536   DEBUG: CDVDPlayerAudio:: synctype set to 1: skip/duplicate
15:22:51 T:140592575137536   DEBUG: CDVDPlayerAudio:: Discontinuity - was:53520548446.259003, should be:53520596053.997002, error:47607.737999
15:22:51 T:140592676890368   DEBUG: CDVDPlayer::HandleMessages - player started 1
15:22:52 T:140592575137536    INFO: CAEStreamInfo::SyncAC3 - AC3 sync lost
15:22:52 T:140592676890368   DEBUG: CDVDPlayer::CheckContinuity - wrapback :1, prev:53522449300.000000, curr:53522446478.000000, diff:-2822.000000
15:22:52 T:140592575137536    INFO: CAEStreamInfo::SyncAC3 - AC3 stream detected (2 channels, 48000Hz)
15:22:54 T:140592575137536    INFO: CAEStreamInfo::SyncAC3 - AC3 stream detected (2 channels, 48000Hz)
15:22:55 T:140593960490752   DEBUG: AddOnLog: VDR XVDR Client: Ping ...
15:22:55 T:140592575137536   DEBUG: CDVDPlayerAudio:: Discontinuity - was:53524361294.367004, should be:53524461729.563667, error:100435.196663
15:22:55 T:140592575137536    INFO: CAEStreamInfo::SyncAC3 - AC3 sync lost
15:22:55 T:140592676890368   DEBUG: CDVDPlayer::CheckContinuity - wrapback :1, prev:53525393300.000000, curr:53525390478.000000, diff:-2822.000000
15:22:55 T:140592575137536    INFO: CAEStreamInfo::SyncAC3 - AC3 stream detected (2 channels, 48000Hz)
15:22:57 T:140592575137536    INFO: CAEStreamInfo::SyncAC3 - AC3 stream detected (2 channels, 48000Hz)
15:22:58 T:140592545765120   DEBUG: CPullupCorrection: detected pattern of length 1: 20000.00, frameduration: 20000.000000
15:22:58 T:140592575137536    INFO: CAEStreamInfo::SyncAC3 - AC3 sync lost

[pipelka]

Very strange. Please record a minute of this stream and send it to me. I also need the corresponding VDR channels.conf entry.

[herrnst]

Simply pressing "record" is enough? Or anything special like "cat /dev/dvb/adapter0/* > demux" needed? (please advice in that case, to add on this, the channels get descrambled by sc-plugin, no hardware CAM)

[pipelka]

A plain recording is ok.

[herrnst]

https://www.dropbox.com/s/gr6xzgta7xslsrz/ProSieben-TS.tar.bz2

[herrnst]

Reading through this, I noticed I forgot the channels.conf line:

ProSieben;Unitymedia:442000:C0M256:C:6900:543=2:544=deu@3;546=deu@106:548:1831,1722,1838,1835:12103:9999:161:0

[pipelka]

Yes. Thanks. I'll take a look at it as soon as I find some time ;-)

[herrnst]

Ouch. Now, after having the channel approx. 6 minutes playing, out of a sudden:

Nov  1 20:21:35 barias vdr: [7853] XVDR: --------------------------------------
Nov  1 20:21:35 barias vdr: [7853] XVDR: NEW AUDIO INFORMATION:
Nov  1 20:21:35 barias vdr: [7853] XVDR: Channels: 1
Nov  1 20:21:35 barias vdr: [7853] XVDR: Samplerate: 44100 Hz
Nov  1 20:21:35 barias vdr: [7853] XVDR: Bitrate: 56000 bps
Nov  1 20:21:35 barias vdr: [7853] XVDR: --------------------------------------
Nov  1 20:21:35 barias vdr: [7853] XVDR: --------------------------------------
Nov  1 20:21:35 barias vdr: [7853] XVDR: NEW AUDIO INFORMATION:
Nov  1 20:21:35 barias vdr: [7853] XVDR: Channels: 2
Nov  1 20:21:35 barias vdr: [7853] XVDR: Samplerate: 48000 Hz
Nov  1 20:21:35 barias vdr: [7853] XVDR: Bitrate: 384000 bps
Nov  1 20:21:35 barias vdr: [7853] XVDR: --------------------------------------
Nov  1 20:21:36 barias vdr: [7853] XVDR: --------------------------------------
Nov  1 20:21:36 barias vdr: [7853] XVDR: NEW AUDIO INFORMATION:
Nov  1 20:21:36 barias vdr: [7853] XVDR: Channels: 3
Nov  1 20:21:36 barias vdr: [7853] XVDR: Samplerate: 48000 Hz
Nov  1 20:21:36 barias vdr: [7853] XVDR: Bitrate: 384000 bps
Nov  1 20:21:36 barias vdr: [7853] XVDR: --------------------------------------
Nov  1 20:21:36 barias vdr: [7853] XVDR: --------------------------------------
Nov  1 20:21:36 barias vdr: [7853] XVDR: NEW AUDIO INFORMATION:
Nov  1 20:21:36 barias vdr: [7853] XVDR: Channels: 2
Nov  1 20:21:36 barias vdr: [7853] XVDR: Samplerate: 48000 Hz
Nov  1 20:21:36 barias vdr: [7853] XVDR: Bitrate: 384000 bps
Nov  1 20:21:36 barias vdr: [7853] XVDR: --------------------------------------
Nov  1 20:21:36 barias vdr: [7853] XVDR: --------------------------------------
Nov  1 20:21:36 barias vdr: [7853] XVDR: NEW AUDIO INFORMATION:
Nov  1 20:21:36 barias vdr: [7853] XVDR: Channels: 3
Nov  1 20:21:36 barias vdr: [7853] XVDR: Samplerate: 48000 Hz
Nov  1 20:21:36 barias vdr: [7853] XVDR: Bitrate: 448000 bps
Nov  1 20:21:36 barias vdr: [7853] XVDR: --------------------------------------
Nov  1 20:21:37 barias vdr: [7853] XVDR: --------------------------------------
Nov  1 20:21:37 barias vdr: [7853] XVDR: NEW AUDIO INFORMATION:
Nov  1 20:21:37 barias vdr: [7853] XVDR: Channels: 2
Nov  1 20:21:37 barias vdr: [7853] XVDR: Samplerate: 48000 Hz
Nov  1 20:21:37 barias vdr: [7853] XVDR: Bitrate: 384000 bps
Nov  1 20:21:37 barias vdr: [7853] XVDR: --------------------------------------
Nov  1 20:21:38 barias vdr: [7853] XVDR: --------------------------------------
Nov  1 20:21:38 barias vdr: [7853] XVDR: NEW AUDIO INFORMATION:
Nov  1 20:21:38 barias vdr: [7853] XVDR: Channels: 2
Nov  1 20:21:38 barias vdr: [7853] XVDR: Samplerate: 16000 Hz
Nov  1 20:21:38 barias vdr: [7853] XVDR: Bitrate: 341166 bps
Nov  1 20:21:38 barias vdr: [7853] XVDR: --------------------------------------
Nov  1 20:21:38 barias kernel: [32572.607985] cLiveStreamer s[7853] general protection ip:7fc82f656ae9 sp:7fc7f63fabf0 error:0 in libc-2.15.so[7fc82f5d6000+1b5000]
Nov  1 20:21:38 barias lircd-0.9.0[957]: removed client
Nov  1 20:21:38 barias runvdr: restarting VDR

Really curious about what those professionals at the cable provider are doing to this stream :( I don't think this does not happen at all via DVB-S reception...

[herrnst]

I just played with the new timeshift feature on my HTPC (very nice feature, BTW. Ability to seek in the timeshift buffer would be extra-amazing :) ... I found out the stream played from the timeshift buffer also is problematic.

Might it be helpful if I push pause, wait 30sec, copy away the current timeshift buffer file and then send that over to you? This at least seems to differ from normal recordings (not mangled by VDR beforehand?).

[herrnst]

Answering the question myself: Here's 15mb of timeshift buffer from Pro7 (approx. 30sec) showing the problem.

https://dl.dropbox.com/s/caa6advatupkb0p/ProSieben-TimeShiftbuffer.tar.bz2?dl=1

[pipelka]

I took this opportunity and started to re-implement some parsers. This is an long over-due issue I never really started.

Ok. There are 2 new audio demuxers: AC3 and MP2 Audio

Please checkout the "demuxer" branch: https://github.com/pipelka/vdr-plugin-xvdr/tree/demuxer

Hopefully it will fix your issue.

[herrnst]

Yay!

While I actually did test only a minute or so, I can confirm the log spam seems to be gone and didn't have any audio drops, AC3 played perfectly on Pro7 now - will test more after the Bundesliga match ;D

For now, MANY thanks for your efforts! Will definitely report back later!

[pipelka]

Great ;-) The re-write reduced code-size dramatically. Next I'll re-write the video parsers.

[herrnst]

Hmm. Something extra-strange suddenly happened. Noticed some dropouts (looked like a reception problem, but monitoring femon didn't show any problems) until ca. 0:21 o'clock. Then out of a sudden, sound completely went away.

At that time, this - http://pastebin.com/hiBjfDFd - was posted to xbmc.log.

After that, the log got spammed with this: http://pastebin.com/gdxQa31L - Video played with big stutter at 2-3fps, and heavy mpeg decode error pixelation occured.

I then restarted VDR and XBMC (in various combinations, VDR first, XBMC first and so on). Video then started again. AC3 audio works without stutter, however, when switching to MP2, I get this: http://pastebin.com/eBM14ChP

To check for any generic problem, I then reinstalled libvdr-xvdr.so.1.7.31 to 45a7a22 as of 20121031. Audio then worked again, with the old bug - AC3 dropouts, syslog spam.

Note: Nothing logged to syslog while the described things happened. Timeshift ringbuffer uploading, posting link when done.

[herrnst]

Timeshift ringbuffer at https://dl.dropbox.com/s/rxcn32d9anvz6rj/ProSieben-ringbuffer.tar.bz2?dl=1

[pipelka]

I also had a crash after a couple of hours. I'm doing a long-term test with the updated "demuxer" branch now.

I think it's some memory allocation/corruption problem.

[herrnst]

What I found extra-strange was that even after kicking VDR, the MP2 errors didn't want to go away. Might this be handled/fixed by https://github.com/pipelka/vdr-plugin-xvdr/commit/b091ebb4e6ce9ac00d0783855b127ae461d2cd82 ?

[herrnst]

Update: Checked latest HEAD of demuxer branch, MP2 parser error messages in XBMC remain.

[pipelka]

After some investigation I found out that streams having "Data alignment indicator" set (in the packet elementary stream packet) are working flawlessly. Demuxing is done correctly. It seems XBMC doesn't like unaligned streams. I'll think about an easy method to align the streams.

[pipelka]

Alright. Next iteration. Please pull the latest version (maybe re-clone, because the branch was rebased). You should check if the audio issue (for AC3 and MPEG) is fixed. Drawback: HD (H.264) channels are currently broken and will not play. Hopefully, MPEG video channels will work.

[pipelka]

I added a demux test application in the addon. If audio doesn't work as expected please run:

./src/libxvdr/tests/demux serverip channelnumber

This will open the specified channel on the xvdr server and demux 100 packets. The output would then be interesting (if audio doesn't work as expected).

[herrnst]

Hmmmm ;) You might not like to hear that, but this latest variant breaks alot and quickly caused a VDR core crash... Lets see if I can put everything together (some raw paste's linked; will not bother with HD/H264 channels, they only cause funny syslog posts :) :

First try was RTL SD. Started with MPEG Video and Audio (simple 2ch stuff), worked normally so far. Then tried switching to AC3 audio. Wouldn't work on first try, but around third try, it did, but it switched back to MP2 audio after a few seconds. See this raw paste on what happened: http://pastebin.com/thUEqkjU

Second try: Sat.1 ("problematic" channel). Video plays normal, AC3 Audio drops "as usual", but no syslog messages. Raw paste at http://pastebin.com/9ZpKuVFi

Third one: Sat.1 with MP2 audio. Still showing decode errors, XBMC seems to fill up gaps in audio? http://pastebin.com/M6Wb5Muu

Now a very interesting one: WDR SD. A completely new effect - Black screen/no video, and MP2 audio very heavily dropping (much more extreme than AC3 on "problematic channels"). This paste also contains snippets from syslog - http://pastebin.com/b2jWng5k

Sorry for the not-so-good news...

[herrnst]

This is the output of your demux tool on Sat.1 (second and third report): http://pastebin.com/RpNLkerL

For the records, first report: http://pastebin.com/zsezre0c

And fourth: http://pastebin.com/yHc1EFEe

Hope this helps, and again thanks for your efforts!

[pipelka]

It's not as bad as it seems. At least the audio streams are aligned now. I have to analyze the logs, ...

[pipelka]

I updated the branch again. This time it only contains updated audio parsers (+ some changes). Please check if there is some improvement. Maybe we're able to near down the problem. I don't need the log files. The output of the "demux" test tool is much more valuable.

[herrnst]

Good to know about the logs (thought that might be of interest ;) ... Guess current demuxer tool with PTS output is the way to go?

[pipelka]

Yes. Please ;-)

[herrnst]

On for some results :)

First, my testing got "forcably" interrupted by a VDR (libvdr-xvdr) crash (that was on Pro7 with AC3 audio):

Nov 14 18:49:39 barias kernel: [ 792.865601] cLiveStreamer s[2994] trap divide error ip:7f7f63a88657 sp:7f7f422facf8 error:0 in libvdr-xvdr.so.1.7.31[7f7f63a6f000+39000]

Other than that, definitely great improvements!

AC3 dropping on problematic channels is still there, but the frequency is now down to about a 3-4second interval. MP2 decode errors are still there. I noticed that on audio dropping, video stutters a bit and on some occasions cause decode error pixelation. Log: http://pastebin.com/JvaVANE5 (this is from Pro7, Sat.1 is the same, log at http://pastebin.com/uPCB5Ydq )

The WDR problem from yesterday is gone. Noticed some odd message that XBMC couldn't determine exact frame duration, but saw no obvious problems. Log: http://pastebin.com/1HzGNH3E

RTL "auto-audio-switching" is also gone. All playing normally and fine here. Log: http://pastebin.com/fmSGQAWR

As an added bonus, quickly checked H264 channels, worked perfectly again ;) Paste for a Sky 1080i channel: http://pastebin.ca/2251564 - and a 720p (ARD HD): http://pastebin.ca/2251566

(Had to use another pastebin site, pastebin.com wouldn't let me paste more than 10 times every 24h ;D )

[pipelka]

Yet another iteration ;-)

I had some problems the my own audio channels and rewrote the audio demuxers partially again.

I also added a new test tool to the addon: ac3analyze

It analyzes the AC3 stream of a channels any displays sync timings. It may also be used on MP2 streams by changing "AC3" to "MPEG2AUDIO" in the code.

Would you please test the new version with your channels ?

If a channel has problems the output of ac3analyze and demux would be helpful.

Thanks Alex

[herrnst]

Oh my... Holy shit! :) This latest stuff seems to finally fix the problem (at least for me) :)

Running https://github.com/pipelka/vdr-plugin-xvdr/commit/caaa31670229b2f855208adcf0efd8fdaa383c2d and https://github.com/pipelka/xbmc-addon-xvdr/commit/1d8f64c16ff1937ecc58bb11271c016d76aa428c on my HTPC box (did a checkout/compile of master including the ac3 tool on my build VM and just copied the tool).

For reference, the output with vdr-xvdr@master: http://pastebin.com/LUNfaVzN

And with vdr-xvdr@demuxer HEAD: http://pastebin.com/87rvFjJ6

H.264 (1080i) channels still working fine.

Clearly something strange happening in sync at every audible gap in the master variant, gone in demuxer.

Many thanks for all the efforts! Guess I owe you a box of beer or so ;) Daniel

[pipelka]

Yeah. That's the kind of news I want to hear ;-) I'll let the code settle for some time in "demuxer" and then merge it into master. I think i removed some streams like teletext,... I need to add them again.

BTW, I just drink apple juice, ... Naah, just kidding, my favorite is dark wheat beer from my own micro-brewery in my basement ;-)

Thanks for testing, ... I'm sure I'll bother you again when rewriting the video parsers, ...

[herrnst]

Oh, we can also arrange on a six pack of apple juice or so, no problem (more beer for me then =)

Will let the demuxer plugin build run for a few days and see if anything regressed, will also check teletext and DVB subs (there are a few channels providing them).

Of course, if you need any testing on something, just let me know - glad if I can help with anything!

[herrnst]

Short feedback on this: No interruptions caused by this so far!

Updated to the teletext-parsing-commit afterwards, teletext seems garbled/broken/incomplete currently, but tested only two minutes or so. This eventually needs a bit of investigation, will check this again tomorrow and maybe post screenshots.

[pipelka]

Oh. Yes. Please re-pull.

[herrnst]

On 5f5ab5b, it seems better. Startpage (100) doesn't appear chopped at half (or mixed with other contents) anymore. Otherwise, still no crashes or other faults caused by the VDR plugin today :)