[Asterisk-video] app_rtsp: asterisk hangup (exceptionally long queue)

Wed Sep 12 11:31:33 CDT 2007

Hey guys!

Earlier this day I found out that this "exceptionally long queue" bug is
easily reproduceable in cooperation with another application we use.
This was due to a loop which started a rtsp-stream of a non-existent
video several times a second.

So I just translated this to extensions.conf and now I can reproduce
within seconds... Check it out:

exten => stream,1,h324m_gw_answer
exten => stream,2,mp4play(/usr/local/movies/logo.mp4)
exten => stream,3,mp4play(/usr/local/movies/logo.mp4)
exten => stream,4,rtsp(rtsp://${DSS}:554/static/nonPresentVideo.mp4)
exten => stream,5,Goto(4)
exten => stream,6,Hangup

This, of course, is not a very realistic scenario, but this way we can
find out easily what fills up the queue without having to wait for six
minutes.

Another thing:
When you try this using a SIP-phone you'll end up with a CPU load of
100% but you won't get the "exceptionally long queue"-warnings.
"sip show channels" also shows that the call has not been hung up
correctly although the SIP-phone itself says different. The loop seems
to go on in the background.

Hope this helps debugging,
Thomas

Am Mittwoch, den 12.09.2007, 00:02 +0200 schrieb Sergio Garcia Murillo:
> You're right perhaps it's not everything related whith bandwith, as the
> frames should be queued inside
> of the libh324m and not in the local channel.
> I'll try to think more about it to see what could be happening.
> 
> BR
> Sergio
> 
> ----- Original Message ----- 
> From: "Thomas Frieling" <thomas.frieling at viif.de>
> To: "Development discussion of video media support in Asterisk"
> <asterisk-video at lists.digium.com>
> Sent: Tuesday, September 11, 2007 6:21 PM
> Subject: Re: [Asterisk-video] app_rtsp: asterisk hangup
> 
> 
> > OK I understand this... But don't you think we should check the buffer
> > periodically and maybe clear it or even hangup before it is too late?
> >
> > I just reproduced the problem two times by looping four videos (each ~10
> > seconds) all the time with app_rtsp. After about five or six minutes the
> > problem occured again (the errors and 100% CPU load). Since the videos
> > were played correctly for about ten times before the crash, maybe our
> > guess about the too high framerate is incorrect.
> >
> > How can I find out which queue it is exactly which causes the problem
> > and maybe see when it is filled up?
> >
> > BR,
> > Thomas
> >
> > PS: here are some logs:
> >
> > [Sep 11 17:34:15] ERROR[30677] app_rtsp.c: -Received rtcp [164]
> > [Sep 11 17:34:15] ERROR[30677] app_rtsp.c: -Received rtcp length [84]
> > [Sep 11 17:34:15] ERROR[30677] app_rtsp.c: -rtcp type [200,28]
> > [Sep 11 17:34:15] ERROR[30677] app_rtsp.c: -rtcp type [202,56]
> > [Sep 11 17:34:15] ERROR[30677] app_rtsp.c: -rtcp type [204,84]
> > [Sep 11 17:34:15] ERROR[30677] app_rtsp.c: -Started playback [10000]
> > [Sep 11 17:34:22] ERROR[30677] app_rtsp.c: -Received rtcp [164]
> > [Sep 11 17:34:15] ERROR[30677] app_rtsp.c: -Received rtcp length [84]
> > [Sep 11 17:34:15] ERROR[30677] app_rtsp.c: -rtcp type [200,28]
> > [Sep 11 17:34:15] ERROR[30677] app_rtsp.c: -rtcp type [202,56]
> > [Sep 11 17:34:15] ERROR[30677] app_rtsp.c: -rtcp type [204,84]
> > [Sep 11 17:34:15] ERROR[30677] app_rtsp.c: -Started playback [10000]
> > [Sep 11 17:34:22] ERROR[30677] app_rtsp.c: -Received rtcp [164]
> > [Sep 11 17:34:22] ERROR[30677] app_rtsp.c: -Received rtcp length [84]
> > [Sep 11 17:34:22] ERROR[30677] app_rtsp.c: -rtcp type [200,28]
> > [Sep 11 17:34:22] ERROR[30677] app_rtsp.c: -rtcp type [202,56]
> > [Sep 11 17:34:22] ERROR[30677] app_rtsp.c: -rtcp type [204,84]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: Playback finished
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -rtsp_play end loop[Sep 11
> > 17:34:25] WARNING[30677] app_rtsp.c: -TEARDOWN
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: <rtsp_play[Sep 11 17:34:25]
> > WARNING[30677] app_rtsp.c: >rtsp play
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: >DESCRIBE
> > [/static/intro-b.mp4]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: <DESCRIBE
> > [/static/intro-b.mp4]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -rtsp play loop
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -Receiving describe
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [v=0]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [o=StreamingServer
> > 3398513665 1189517873000 IN IP4 127.0.0.1]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line
> > [s=/static/intro-b.mp4]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [u=http:///]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [e=admin@]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [c=IN IP4 0.0.0.0]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [b=AS:29]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [t=0 0]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [a=control:*]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [a=x-copyright:
> > MP4/3GP File hinted with GPAC 0.4.5-DEV (C)2000-2005 -
> > http://gpac.sourceforge.net]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [a=range:npt=0-
> > 10.00000]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [m=video 0 RTP/AVP
> > 96]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -creating media [1,m=video
> > 0 RTP/AVP 96]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [a=control:trackID=2]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [a=rtpmap:96
> > H263-2000/15]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line
> > [a=cliprect:0,0,144,176]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [Content-Base:
> > rtsp://127.0.0.1/static/intro-b.mp4/]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [v=0]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [o=StreamingServer
> > 3398513665 1189517873000 IN IP4 127.0.0.1]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line
> > [s=/static/intro-b.mp4]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [u=http:///]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [e=admin@]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [c=IN IP4 0.0.0.0]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [b=AS:29]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [t=0 0]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [a=control:*]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [a=x-copyright:
> > MP4/3GP File hinted with GPAC 0.4.5-DEV (C)2000-2005 -
> > http://gpac.sourceforge.net]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [a=range:npt=0-
> > 10.00000]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [m=video 0 RTP/AVP
> > 96]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -creating media [1,m=video
> > 0 RTP/AVP 96]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [a=control:trackID=2]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line [a=rtpmap:96
> > H263-2000/15]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -line
> > [a=cliprect:0,0,144,176]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -video
> > [1048576,96,trackID=2]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -SETUP VIDEO [trackID=2]
> > [Sep 11 17:34:25] WARNING[30677] app_rtsp.c: -PLAY [/static/intro-b.mp4]
> > [Sep 11 17:34:25] ERROR[30677] app_rtsp.c: -Started playback [10000]
> > [Sep 11 17:34:25] ERROR[30677] app_rtsp.c: -Received rtcp [166]
> > [Sep 11 17:34:25] ERROR[30677] app_rtsp.c: -Received rtcp length [84]
> > [Sep 11 17:34:25] ERROR[30677] app_rtsp.c: -rtcp type [200,28]
> > [Sep 11 17:34:25] ERROR[30677] app_rtsp.c: -rtcp type [202,56]
> > [Sep 11 17:34:25] ERROR[30677] app_rtsp.c: -rtcp type [204,84]
> > [Sep 11 17:34:32] ERROR[30677] app_rtsp.c: -Received rtcp [166]
> > [Sep 11 17:34:32] ERROR[30677] app_rtsp.c: -Received rtcp length [84]
> > [Sep 11 17:34:32] ERROR[30677] app_rtsp.c: -rtcp type [200,28]
> > [Sep 11 17:34:32] ERROR[30677] app_rtsp.c: -rtcp type [202,56]
> > [Sep 11 17:34:32] ERROR[30677] app_rtsp.c: -rtcp type [204,84]
> > [Sep 11 17:34:35] WARNING[30677] app_rtsp.c: Playback finished
> > [Sep 11 17:34:35] WARNING[30677] app_rtsp.c: -rtsp_play end loop[Sep 11
> > 17:34:35] WARNING[30677] app_rtsp.c: -TEARDOWN
> > [Sep 11 17:34:35] WARNING[30677] app_rtsp.c: <rtsp_play[Sep 11 17:34:35]
> > WARNING[30677] app_rtsp.c: >rtsp play
> > [Sep 11 17:34:36] WARNING[30676] channel.c: Exceptionally long queue
> > length queuing to Local/stream at video-9710,2
> > [Sep 11 17:34:36] WARNING[30676] channel.c: Exceptionally long queue
> > length queuing to Local/stream at video-9710,2
> > [Sep 11 17:34:36] WARNING[30676] channel.c: Exceptionally long queue
> > length queuing to Local/stream at video-9710,2
> > [Sep 11 17:34:36] WARNING[30676] channel.c: Exceptionally long queue
> > length queuing to Local/stream at video-9710,2
> > [Sep 11 17:34:36] WARNING[30676] channel.c: Exceptionally long queue
> > length queuing to Local/stream at video-9710,2
> > [Sep 11 17:34:36] WARNING[30676] channel.c: Exceptionally long queue
> > length queuing to Local/stream at video-9710,2
> > [Sep 11 17:34:36] WARNING[30676] channel.c: Exceptionally long queue
> > length queuing to Local/stream at video-9710,2
> > [Sep 11 17:34:36] WARNING[30676] channel.c: Exceptionally long queue
> > length queuing to Local/stream at video-9710,2
> > [Sep 11 17:34:36] WARNING[30676] channel.c: Exceptionally long queue
> > length queuing to Local/stream at video-9710,2
> > [Sep 11 17:34:36] WARNING[30676] channel.c: Exceptionally long queue
> > length queuing to Local/stream at video-9710,2
> > [...]
> >
> >
> > Am Dienstag, den 11.09.2007, 16:53 +0200 schrieb Sergio Garcia:
> > >
> > > It could be possible to implement it, but you'll have to drop all the
> frames
> > > until the next I frame. And if the bandwith is so high you'll end up
> droping
> > > almost instantaneously the next frames. And even that way the I frame is
> going
> > > to arrive late and not be synchronized with audio..
> > >
> > > So if you want to offer any kind of quality service the only option is
> using
> > > videos encoded at the best bitrate according it's use. You may even find
> that
> > > you have to encode the same video at different bitrates for different
> kind of
> > > access.
> > >
> > > BR
> > > Sergio
> > >
> > > ---------- Original Message ----------------------------------
> > > From: Thomas Frieling <thomas.frieling at viif.de>
> > > Reply-To: Development discussion of video media support in
> Asterisk<asterisk-video at lists.digium.com>
> > > Date:  Tue, 11 Sep 2007 16:44:52 +0200
> > >
> > > >Hi Klaus!
> > > >
> > > >Sounds pretty convincing to me... But if this is really the case, then
> > > >we should definitely handle this problem before it occurs: Maybe we can
> > > >check the queue's size before sending a package and decide to skip some
> > > >packages to synchronize the outgoing stream.
> > > >This would help keeping sound and video synchronous and it would
> prevent
> > > >the "exceptionally long queue" error.
> > > >
> > > >What do you think about this? Would it be hard to implement?
> > > >
> > > >Greetings,
> > > >Thomas
> > > >
> > > >Am Montag, den 10.09.2007, 09:35 +0200 schrieb Klaus Darilion:
> > > >> Thomas Frieling schrieb:
> > > >> > Hi all!
> > > >> >
> > > >> > When using app_rtsp with a 3G handset extensively asterisk starts
> > > >> > consuming 100% of the CPU and the following error appears very
> often
> > > >> > (~80 times a second) on the CLI:
> > > >> >
> > > >> > [Sep  7 12:52:55] WARNING[11822]: channel.c:924 ast_queue_frame:
> > > >> > Exceptionally long queue length queuing to
> Local/stream at video-bad8,2
> > > >> >
> > > >> > Does anyone know what this warning means or where it comes from?
> Which
> > > >> > logfile should I (or anyone who'd like to) take a look at?
> > > >>
> > > >>
> > > >> I guess the framerate received from app_rtsp is bigger then the
> > > >> framerate received from the h324m connection. Every time h324m_gw
> reads
> > > >> a frame from the incoming 64kbit data call, it writes an frame to the
> > > >> data call too.
> > > >>
> > > >> Thus if app_rtsp feeds to many frames the queue buffer might grow.
> > > >>
> > > >> btw: shouldn't the pseudo channel (Local/..) be gone when app_rtsp
> > > >> answers the call?
> > > >>
> > > >> regards
> > > >> klaus
> > > >>
> > > >> _______________________________________________
> > > >> --Bandwidth and Colocation Provided by http://www.api-digital.com--
> > > >>
> > > >> asterisk-video mailing list
> > > >> To UNSUBSCRIBE or update options visit:
> > > >>    http://lists.digium.com/mailman/listinfo/asterisk-video
> > > >-- 
> > > >www.ViiF.de - your Mobile Video Community
> > > >
> > > >~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> > > >
> > > >Thomas Frieling - IT Development
> > > >ViiF Mobile Video GmbH, Poststr. 21-22, 10178 Berlin
> > > >Cell: +49 (0) 173 63 62 62 3
> > > >
> > > >mailto:thomas at ViiF.de
> > > >
> > > >Sitz: Berlin, Amtgericht Berlin-Charlottenburg, HRB: 108350B
> > > >
> > > >GeschÃ¤ftsfÃ¼hrer: Daniel HÃ¶pfner, Steffen BrÃ¼nn
> > > >
> > > >~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> > > >
> > > >_______________________________________________
> > > >--Bandwidth and Colocation Provided by http://www.api-digital.com--
> > > >
> > > >asterisk-video mailing list
> > > >To UNSUBSCRIBE or update options visit:
> > > >   http://lists.digium.com/mailman/listinfo/asterisk-video
> > >
> > >
> > >
> > > _______________________________________________
> > > --Bandwidth and Colocation Provided by http://www.api-digital.com--
> > >
> > > asterisk-video mailing list
> > > To UNSUBSCRIBE or update options visit:
> > >    http://lists.digium.com/mailman/listinfo/asterisk-video
> > -- 
> > www.ViiF.de - your Mobile Video Community
> >
> > ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> >
> > Thomas Frieling - IT Development
> > ViiF Mobile Video GmbH, Poststr. 21-22, 10178 Berlin
> > Cell: +49 (0) 173 63 62 62 3
> >
> > mailto:thomas at ViiF.de
> >
> > Sitz: Berlin, Amtgericht Berlin-Charlottenburg, HRB: 108350B
> >
> > Geschäftsführer: Daniel Höpfner, Steffen Brünn
> >
> > ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
> >
> > _______________________________________________
> > --Bandwidth and Colocation Provided by http://www.api-digital.com--
> >
> > asterisk-video mailing list
> > To UNSUBSCRIBE or update options visit:
> >    http://lists.digium.com/mailman/listinfo/asterisk-video
> 
> 
> _______________________________________________
> --Bandwidth and Colocation Provided by http://www.api-digital.com--
> 
> asterisk-video mailing list
> To UNSUBSCRIBE or update options visit:
>    http://lists.digium.com/mailman/listinfo/asterisk-video
-- 
www.ViiF.de - your Mobile Video Community

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~

Thomas Frieling - IT Development
ViiF Mobile Video GmbH, Poststr. 21-22, 10178 Berlin 
Cell: +49 (0) 173 63 62 62 3

mailto:thomas at ViiF.de

Sitz: Berlin, Amtgericht Berlin-Charlottenburg, HRB: 108350B

Geschäftsführer: Daniel Höpfner, Steffen Brünn

~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~