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

Thu Sep 13 16:30:03 CDT 2007

Great!!
I'll take a look at it and hope to have it resolved for monday.

Best regards
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: Wednesday, September 12, 2007 6:31 PM
Subject: Re: [Asterisk-video] app_rtsp: asterisk hangup (exceptionallylong
queue)

> 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
>
> ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
>
> _______________________________________________
> --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