Wowza cannot recover from out of aligned video without restart

Ferdinand_Hernandez · October 2, 2013, 5:44pm

Hi Guys,

I am having a weird problem about a stream that we are transcoding and recording usin transcoder and dvr addon. After a few days (4 days) of streaming and recording, we start receiving this message in the wowza logs

2013-10-01      14:23:52        CEST    comment server  WARN    200     -       CupertinoPacketHandler.resetStream[SVorigin/_definst_/327][11:6]: Time
codes jumped back in time.        -       -       -       518694.008      -       -       -       -       -       -       -       -       -       -
       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:23:52        CEST    comment server  WARN    200     -       CupertinoPacketHandler.resetStream[SVorigin/_definst_/327_720p][11:0]:
 Timecodes jumped back in time.   -       -       -       518694.046      -       -       -       -       -       -       -       -       -       -
       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:23:52        CEST    comment server  WARN    200     -       CupertinoPacketHandler.resetStream[SVorigin/_definst_/327_360p][11:0]:
 Timecodes jumped back in time.   -       -       -       518694.046      -       -       -       -       -       -       -       -       -       -
       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:23:59        CEST    comment server  WARN    200     -       DvrPacketHandler.resetStream[][0:11]: Timecodes jumped back in time.
    -       -       -       518701.058      -       -       -       -       -       -       -       -       -       -       -       -       -       -
       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:23:59        CEST    comment server  WARN    200     -       DvrPacketHandler.handlePacket[SVorigin/_definst_/327]: Tossing packet with excessive duration: {DvrAMFPacket: size:577, type:8, src:53, seq:5574205, absTimecode: 95443718, timecode:6455530, utcTc:1380630229824}      -
       -       -       518701.067      -       -       -       -       -       -       -       -       -       -       -       -       -       -
       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:24:02        CEST    comment server  WARN    200     -       DvrPacketHandler.handlePacket[]: Timecode out of order [video]: 69319082:88990229       -       -       -       518703.822      -       -       -       -       -       -       -       -       -       -       -       -
       -       -       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:24:02        CEST    comment server  WARN    200     -       DvrPacketHandler.handlePacket[]: Timecode out of order [video]: 69319082:88990229       -       -       -       518703.822      -       -       -       -       -       -       -       -       -       -       -       -
       -       -       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:24:02        CEST    comment server  WARN    200     -       DvrPacketHandler.resetStream[][0:11]: Timecodes jumped back in time.
    -       -       -       518703.823      -       -       -       -       -       -       -       -       -       -       -       -       -       -
       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:24:02        CEST    comment server  WARN    200     -       DvrPacketHandler.resetStream[][0:11]: Timecodes jumped back in time.
    -       -       -       518703.823      -       -       -       -       -       -       -       -       -       -       -       -       -       -
       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:24:02        CEST    comment server  WARN    200     -       LiveStreamDvrRecorder.endChunk[SVorigin/_definst_/327_360p/327-564334_360p]: Recalculating video duration by estimating.  Was -19667107.  Is now 3080.  -       -       -       518703.827      -       -       -       -
       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:24:02        CEST    comment server  WARN    200     -       LiveStreamDvrRecorder.endChunk[SVorigin/_definst_/327_720p/327-564334_720p]: Recalculating video duration by estimating.  Was -19667107.  Is now 3080.  -       -       -       518703.83       -       -       -       -
       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
       -       -       -
2013-10-01      14:24:02        CEST    comment server  WARN    200     -       DvrPacketHandler.handlePacket[SVorigin/_definst_/327_360p]: Tossing packet with excessive duration: {DvrAMFPacket: size:259, type:8, src:54, seq:6007694, absTimecode: 95443722, timecode:6455528, utcTc:1380630232590} -
       -       -       518703.85       -       -       -       -       -       -       -       -       -       -       -       -       -       -
       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:24:02        CEST    comment server  WARN    200     -       DvrPacketHandler.handlePacket[SVorigin/_definst_/327_720p]: Tossing packet with excessive duration: {DvrAMFPacket: size:259, type:8, src:55, seq:6007692, absTimecode: 95443722, timecode:6455528, utcTc:1380630232591} -
       -       -       518703.853      -       -       -       -       -       -       -       -       -       -       -       -       -       -
       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:24:04        CEST    comment server  INFO    200     -       [SVorigin/_definst_/327]: Received new PMT      -       -       -
       518705.693      -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
       -       -       -       -       -       -       -       -       -
2013-10-01      14:24:04        CEST    comment server  INFO    200     -       [SVorigin/_definst_/327]: PMT: Version 26 PCR pid: 0x65         -
       -       -       518705.694      -       -       -       -       -       -       -       -       -       -       -       -       -       -
       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:24:04        CEST    comment server  INFO    200     -       [SVorigin/_definst_/327]:       Stream: Type: 0x02 PID: 0x65 Video
      -       -       -       518705.694      -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:24:04        CEST    comment server  INFO    200     -       [SVorigin/_definst_/327]:       Stream: Type: 0x06 PID: 0x66    -
       -       -       518705.695      -       -       -       -       -       -       -       -       -       -       -       -       -       -
       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:24:04        CEST    comment server  INFO    200     -       [SVorigin/_definst_/327]:       Stream: Type: 0x03 PID: 0x67 Audio
      -       -       -       518705.695      -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:24:04        CEST    comment server  INFO    200     -       [SVorigin/_definst_/327]:       Stream: Type: 0x03 PID: 0x68 Audio
      -       -       -       518705.695      -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:24:04        CEST    comment server  INFO    200     -       [SVorigin/_definst_/327]:       Stream: Type: 0x03 PID: 0x69 Audio
      -       -       -       518705.696      -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:24:04        CEST    comment server  INFO    200     -       [SVorigin/_definst_/327]:       Stream: Type: 0x06 PID: 0x6f    -
       -       -       518705.696      -       -       -       -       -       -       -       -       -       -       -       -       -       -
       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:24:04        CEST    comment server  INFO    200     -       [SVorigin/_definst_/327]:       Stream: Type: 0x05 PID: 0x73    -
       -       -       518705.697      -       -       -       -       -       -       -       -       -       -       -       -       -       -
       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:24:04        CEST    comment server  INFO    200     -       [SVorigin/_definst_/327]:       Stream: Type: 0x86 PID: 0x1fae  -
       -       -       518705.697      -       -       -       -       -       -       -       -       -       -       -       -       -       -
       -       -       -       -       -       -       -       -       -       -       -
2013-10-01      14:24:09        CEST    comment server  WARN    200     -       LiveStreamDvrRecorder.endChunk[SVorigin/_definst_/327/327-564334]: Recalculating audio duration by estimating.  Was -19663405.  Is now 72.      -       -       -       518711.116      -       -       -       -       -
       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
       -       -
2013-10-01      14:24:11        CEST    comment server  INFO    200     -       DvrStreamStoreBase.storeChunks[SVorigin/_definst_/327-564334/327-564334.0] :  Resetting dvr time from dvr:0/pt:87488284 to dvr:1499976/pt:69324783/utc:1380630249891    -       -       -       518713.13       -       -
       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
       -       -       -       -       -
2013-10-01      14:24:25        CEST    comment server  WARN    200     -       LiveStreamDvrRecorder.endChunk[SVorigin/_definst_/327_360p/327-564334_360p]: Recalculating audio duration by estimating.  Was -19648103.  Is now -26113573.     -       -       -       518727.194      -       -       -
       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
       -       -       -       -
2013-10-01      14:24:25        CEST    comment server  WARN    200     -       DvrStreamStoreBase.storeChunks[SVorigin/_definst_/327-564334_360p/327-564334_360p.0] : AudioDuration=-26113573 is not positive.  Skipping chunks.       -       -       -       518727.194      -       -       -       -
       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
       -       -       -
2013-10-01      14:24:25        CEST    comment server  WARN    200     -       LiveStreamDvrRecorder.endChunk[SVorigin/_definst_/327_720p/327-564334_720p]: Recalculating audio duration by estimating.  Was -19648103.  Is now -26113573.     -       -       -       518727.194      -       -       -
       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
       -       -       -       -
2013-10-01      14:24:25        CEST    comment server  WARN    200     -       DvrStreamStoreBase.storeChunks[SVorigin/_definst_/327-564334_360p/327-564334_360p.0] : Skipping chunk. A/V packet times differ by 19668091 ms, more than allowed 2000 ms.   aTime=88988173 vTime=69320082       -       -
       -       518727.194      -       -       -       -       -       -       -       -       -       -       -       -       -       -       -
       -       -       -       -       -       -       -       -       -       -

This could be a problem of the streams not being align since we are streaming this to wowza (transcoder > nDVR) directly from DVB-T. I can see in the logs that wowza tried to restart the stream but it couldn’t recover. My questions are:

Isn’t wowza transcoder addon supposed to produce perfectly aligned audio and video even if the source is not aligned?
Why can’t wowza recover as soon as the streams became aligned again? Note: I am just guessing that the source streams became aligned again since as soon as I restart Wowza the streaming goes back to normal.

We have already tried setting the DVR properties to something like this:

   <Property>
                                        <Name>dvrPacketSortTime</Name>
                                        <Value>10000</Value>
                                        <Type>Integer</Type>
                                </Property>

An increase the recive buffer size like this

<RTP>
                        <IdleFrequency>75</IdleFrequency>
                        <DatagramConfiguration>
                                <Incoming>
                                        <ReuseAddress>true</ReuseAddress>
                                        <ReceiveBufferSize>2048000</ReceiveBufferSize>
                                        <SendBufferSize>65000</SendBufferSize>
                                        <!-- <MulticastBindToAddress>true</MulticastBindToAddress> -->
                                        <!-- <MulticastInterfaceAddress>192.168.1.22</MulticastInterfaceAddress> -->
                                        <!-- <TrafficClass>0</TrafficClass> -->
                                        <MulticastTimeout>50</MulticastTimeout>
                                        <DatagramMaximumPacketSize>8192</DatagramMaximumPacketSize>
                                </Incoming>

But to no avail.

Can you guys suggest any other settings we migh try? How can we make wowza recover from sudden unaligned streams?

Richard_Lanham · October 2, 2013, 5:03pm

Assuming you are re-streaming mpeg-ts from the DVB-T, it might help to enable the Advanced MediaCaster Monitor, which will reset “unhealthy” streams. The monitor should reset a stream with these timecode problems.

Richard

Richard_Lanham · October 3, 2013, 11:22am

You should be able to add just the Property settings you want, the rest will use default values

The mediacaster monitor reset is the same as resetting in StreamManager or using the MediaCaster API

Richard

Richard_Lanham · October 3, 2013, 9:20pm

Log messages from this module should be prefixed with the module name. "ModuleMediaCasterStreamMonitorAdvanced: "

Richard

Richard_Lanham · October 8, 2013, 2:09pm

That’s great. Thanks for the update, Ferdinand

Richard

Ferdinand_Hernandez · October 2, 2013, 8:35pm

Hi Richard,

I had a look at the article. Do I have to add all of these properties or just the ones I need? If I can just add what I need, please correct me if I am wrong, then in my case I would just need these part:

<!--
Monitors the time difference between the audio and video channel of a stream. If the difference between the currently arriving
video packet and the previous audio packet (or vice-versa) is greater than streamMonitorAVSyncTolerance and streamMonitorAVSyncToleranceEnable
is set to true, then the stream will be considered unhealthy and will be reset.
-->
<Property>
	<Name>streamMonitorAVSyncToleranceEnable</Name>
	<Value>false</Value>
	<Type>Boolean</Type>
</Property>
<Property>
	<Name>streamMonitorAVSyncTolerance</Name>
	<Value>5000</Value>
	<Type>Integer</Type>
</Property>

Will the DVR recording stop when the streams are reset? I am controling the stop and start of recording in my module base on the EPG.

Ferdinand_Hernandez · October 3, 2013, 3:30pm

Hi Richard,

Thank you for your patience. I have also added the logging properties.

<!--
Turns on debug logging of the monitoring.
-->
<Property>
	<Name>streamMonitorDebug</Name>
	<Value>false</Value>
	<Type>Boolean</Type>
</Property>

What are the keywords that I should filter from the logs to verify if the module is running and when it restarts a stream?

Ferdinand_Hernandez · October 8, 2013, 12:24pm

Log messages from this module should be prefixed with the module name. "ModuleMediaCasterStreamMonitorAdvanced: "

Richard

Hi Richard,

I just want to say thanks for your help. The ModuleMediaCasterStreamMonitorAdvanced seems to have done the trick for me. It restarts the streams automaticaaly as soon as it detects an anomaly in the timecodes of the video and audio.

Regards,

Ferdinand

Topic		Replies	Views
Wowza transcoder problem (Timecode out of order) Wowza Streaming Engine	3	3036	July 17, 2013
Timecode out of order [video] Wowza Streaming Engine	3	3236	January 11, 2014
DVR Window moving Wowza Streaming Engine	1	1742	April 14, 2014
Wowza DVR: preventing corruption and overwriting Wowza Streaming Engine	19	7394	May 14, 2012
Error on DVR recording Wowza Streaming Engine	3	2401	June 5, 2014

Wowza cannot recover from out of aligned video without restart

Related topics