[Home]

Summary:ASTERISK-06809: DTMF and IAX and transcoding creates extra codec translation instances
Reporter:mtaht (mtaht)Labels:
Date Opened:2006-04-18 21:06:14Date Closed:2011-06-07 14:08:04
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Core/NewFeature
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) bad_dtmf_speex.cap
( 1) temporary_speex_debugging_hack.patch
Description:For every DTMF tone going over a given channel the newpvt callback gets called twice. For expensive codecs on slow boxes this seems to do bad things. Also, timestamps get slightly moved back in time and repeated.

Attached is an ethereal packet trace where you can see the timestamps move around, going from a grandstream doing SIP INFO/ulaw  -> Asterisk -> transcoding to IAX/speex -> asterisk voicemail (transconding from ulaw to speex on the return leg).

When you have a working signaling channel, the codec channel should be (?) sending nothing or silence for the duration of the DTMF tone, and shouldn't need to be completely reset...

There's also a diff showing the translators get created/destroyed

(I note that this is a symptom of the larger problem that I'm debugging, which is unreliable DTMF via SIP info, but that's not this bug report)

****** ADDITIONAL INFORMATION ******

This is a little script of a call with some additional information

pbx*CLI> set verbose 5
Verbosity was 0 and is now 5
   -- Executing Answer("SIP/garage-7283", "") in new stack
   -- Executing SetCallerID("SIP/garage-7283", ""Mike Tahts House" <8315350278>") in new stack
   -- Executing Dial("SIP/garage-7283", "IAX2/transconf/299") in new stack
   -- Called transconf/299
Apr 19 01:52:13 WARNING[16041]: codec_speex.c:122 lintospeex_new: speex framesize is 160
   -- Call accepted by 12.161.196.165 (format speex)
   -- Format for call is speex
Apr 19 01:52:13 WARNING[16026]: codec_speex.c:348 lintospeex_destroy: destroying lintospeex 0
Apr 19 01:52:13 WARNING[16026]: codec_speex.c:122 lintospeex_new: speex framesize is 160
   -- IAX2/transconf-13 is ringing
   -- IAX2/transconf-13 answered SIP/garage-7283
Apr 19 01:52:13 WARNING[16041]: codec_speex.c:348 lintospeex_destroy: destroying lintospeex 0
Apr 19 01:52:13 WARNING[16041]: codec_speex.c:122 lintospeex_new: speex framesize is 160
Apr 19 01:52:20 DTMF[16041]: channel.c:1954 __ast_read: DTMF '2' received on SIP/garage-7283
Apr 19 01:52:20 WARNING[16041]: codec_speex.c:348 lintospeex_destroy: destroying lintospeex 0
Apr 19 01:52:20 WARNING[16041]: codec_speex.c:122 lintospeex_new: speex framesize is 160
Apr 19 01:52:20 WARNING[16041]: codec_speex.c:348 lintospeex_destroy: destroying lintospeex 0
Apr 19 01:52:20 WARNING[16041]: codec_speex.c:122 lintospeex_new: speex framesize is 160
Apr 19 01:52:29 DTMF[16041]: channel.c:1954 __ast_read: DTMF '0' received on SIP/garage-7283
Apr 19 01:52:29 WARNING[16041]: codec_speex.c:348 lintospeex_destroy: destroying lintospeex 0
Apr 19 01:52:29 WARNING[16041]: codec_speex.c:122 lintospeex_new: speex framesize is 160
Apr 19 01:52:29 WARNING[16041]: codec_speex.c:348 lintospeex_destroy: destroying lintospeex 0
Apr 19 01:52:29 WARNING[16041]: codec_speex.c:122 lintospeex_new: speex framesize is 160
Apr 19 01:52:38 DTMF[16041]: channel.c:1954 __ast_read: DTMF '2' received on SIP/garage-7283
Apr 19 01:52:38 WARNING[16041]: codec_speex.c:348 lintospeex_destroy: destroying lintospeex 0
Apr 19 01:52:38 WARNING[16041]: codec_speex.c:122 lintospeex_new: speex framesize is 160
Apr 19 01:52:38 WARNING[16041]: codec_speex.c:348 lintospeex_destroy: destroying lintospeex 0
Apr 19 01:52:38 WARNING[16041]: codec_speex.c:122 lintospeex_new: speex framesize is 160
Apr 19 01:52:38 DTMF[16041]: channel.c:1954 __ast_read: DTMF '0' received on SIP/garage-7283
Apr 19 01:52:38 WARNING[16041]: codec_speex.c:348 lintospeex_destroy: destroying lintospeex 0
Apr 19 01:52:38 WARNING[16041]: codec_speex.c:122 lintospeex_new: speex framesize is 160
Apr 19 01:52:38 WARNING[16041]: codec_speex.c:348 lintospeex_destroy: destroying lintospeex 0
Apr 19 01:52:38 WARNING[16041]: codec_speex.c:122 lintospeex_new: speex framesize is 160
Apr 19 01:52:38 DTMF[16041]: channel.c:1954 __ast_read: DTMF '1' received on SIP/garage-7283
Apr 19 01:52:38 WARNING[16041]: codec_speex.c:348 lintospeex_destroy: destroying lintospeex 0
Apr 19 01:52:38 WARNING[16041]: codec_speex.c:122 lintospeex_new: speex framesize is 160
Apr 19 01:52:39 WARNING[16041]: codec_speex.c:348 lintospeex_destroy: destroying lintospeex 0
Apr 19 01:52:39 WARNING[16041]: codec_speex.c:122 lintospeex_new: speex framesize is 160
Apr 19 01:52:44 DTMF[16041]: channel.c:1954 __ast_read: DTMF '1' received on SIP/garage-7283
Apr 19 01:52:44 WARNING[16041]: codec_speex.c:348 lintospeex_destroy: destroying lintospeex 0
Apr 19 01:52:44 WARNING[16041]: codec_speex.c:122 lintospeex_new: speex framesize is 160
Apr 19 01:52:44 DTMF[16041]: channel.c:1954 __ast_read: DTMF '2' received on SIP/garage-7283
Apr 19 01:52:44 WARNING[16041]: codec_speex.c:348 lintospeex_destroy: destroying lintospeex 0
Apr 19 01:52:44 WARNING[16041]: codec_speex.c:122 lintospeex_new: speex framesize is 160
Apr 19 01:52:44 DTMF[16041]: channel.c:1954 __ast_read: DTMF '3' received on SIP/garage-7283
Apr 19 01:52:44 WARNING[16041]: codec_speex.c:348 lintospeex_destroy: destroying lintospeex 0
Apr 19 01:52:44 WARNING[16041]: codec_speex.c:122 lintospeex_new: speex framesize is 160
Apr 19 01:52:45 DTMF[16041]: channel.c:1954 __ast_read: DTMF '4' received on SIP/garage-7283
Apr 19 01:52:45 WARNING[16041]: codec_speex.c:348 lintospeex_destroy: destroying lintospeex 0
Apr 19 01:52:45 WARNING[16041]: codec_speex.c:122 lintospeex_new: speex framesize is 160
Apr 19 01:52:50 DTMF[16041]: channel.c:1954 __ast_read: DTMF '2' received on SIP/garage-7283
Apr 19 01:52:50 WARNING[16041]: codec_speex.c:348 lintospeex_destroy: destroying lintospeex 0
Apr 19 01:52:50 WARNING[16041]: codec_speex.c:122 lintospeex_new: speex framesize is 160
Apr 19 01:52:51 WARNING[16041]: codec_speex.c:348 lintospeex_destroy: destroying lintospeex 0
Apr 19 01:52:51 WARNING[16041]: codec_speex.c:122 lintospeex_new: speex framesize is 160
Apr 19 01:53:17 WARNING[16041]: codec_speex.c:348 lintospeex_destroy: destroying lintospeex 0
   -- Hungup 'IAX2/transconf-13'
 == Spawn extension (internal, 313299, 3) exited non-zero on 'SIP/garage-7283'
   -- Executing Hangup("SIP/garage-7283", "") in new stack
 == Spawn extension (internal, h, 1) exited non-zero on 'SIP/garage-7283'
Comments:By: mtaht (mtaht) 2006-04-18 21:10:12

gdb backtraces. Note that only the first two dtmf entries are seen before gdb can't figure out the stack backtrace anymore.

gdb) break speextolin_new
gdb) commands
gdb) bt
gdb) c
gdb) end
gdb) c

Breakpoint 1, speextolin_new (pvt=0xa18bca8) at codec_speex.c:145
145     {
#0  speextolin_new (pvt=0xa18bca8) at codec_speex.c:145
#1  0x08069ddd in newpvt (t=0x5a5b60) at translate.c:128
---Type <return> to continue, or q <return> to quit---
#2  0x0806a699 in ast_translator_build_path (dest=64, source=512)
   at translate.c:264
#3  0x080627a0 in set_format (chan=0xa0c4028, fmt=64, rawformat=0xa0c4344,
   format=0xa0c40f8, trans=0xa0c4340, direction=0) at channel.c:2430
#4  0x08062917 in ast_set_read_format (chan=0xa0c4028, fmt=64)
   at channel.c:2443
ASTERISK-1  0x00fba438 in iax2_process_thread (data=0xa1262d0) at chan_iax2.c:6997
ASTERISK-2  0x080b202c in dummy_start (data=0xa1027b0) at utils.c:538
ASTERISK-3  0x00594947 in start_thread () from /lib/libpthread.so.0
ASTERISK-4  0x004182ce in clone () from /lib/libc.so.6
[New Thread -1229386832 (LWP 14387)]
[Switching to Thread -1216017488 (LWP 14380)]

Breakpoint 1, speextolin_new (pvt=0xa18bca8) at codec_speex.c:145
145     {
#0  speextolin_new (pvt=0xa18bca8) at codec_speex.c:145
#1  0x08069ddd in newpvt (t=0x5a5b60) at translate.c:128
#2  0x0806a699 in ast_translator_build_path (dest=64, source=512)
   at translate.c:264
#3  0x080627a0 in set_format (chan=0xa0c4028, fmt=64, rawformat=0xa0c4344,
   format=0xa0c40f8, trans=0xa0c4340, direction=0) at channel.c:2430
#4  0x0806390b in ast_channel_make_compatible (chan=0xa17e228, peer=0xa0c4028)
   at channel.c:2443
ASTERISK-1  0x00b614b7 in dial_exec_full (chan=0xa17e228, data=Variable "data" is not available.
) at app_dial.c:1573
---Type <return> to continue, or q <return> to quit---
ASTERISK-2  0x00b626cc in dial_exec (chan=0xa17e228, data=0xb784dfa8)
   at app_dial.c:1623
ASTERISK-3  0x08076fa9 in pbx_extension_helper (c=0xa17e228, con=Variable "con" is not available.
) at pbx.c:508
Previous frame inner to this frame (corrupt stack?)
By: mtaht (mtaht) 2006-04-18 21:32:26

See for example packets 1642,1643,1645,1646,1651,1653,1654
By: mtaht (mtaht) 2006-04-19 10:14:42

Actually it creates and destroys a new codec instance each things like background(somefile.gsm)
backgroiund(s)omeotherfile.gsm)

this seems to be the semi-right thing (although I would argue in favor of creating one one translator per channel per codec, and dtmf shouldn't touch the codec unless it has to...

anyway, I'm experimenting with pre-allocating a bunch of speex codecs so all newpvt has to do is mv a pointer and tuning it up a bit (buffer sizes seem overbig)...
By: mtaht (mtaht) 2006-04-20 01:13:52

This is 3 bugs in 1.

bug #1: I've concluded that the way ast_translator_build_path currently works is just wrong, at least in this particular case.

If there is a pre-existing path like slin->speex and the new path needs to be
gsm->slin->speex, the gsm codec should just be spliced into the slin stream, and the rest of the existing encoder path (slin->speex) should be untouched. A short period of silence should always be spliced in as well, or each encoder reset at the time of the splice, which still involves sending a packet to notify the decoder on the other end that something has changed in some cases.

bug #2: I'd argue in favor of keeping a pre-allocated pool of encoders/decoders around in the general case. Calling malloc/calloc in rt threads gives me willies.

bug #3: getting back to dtmf, which is tricky. In my case of sip info, there's a duration component of the message that could be passed down to the encoder/decoder to tell it dtmf is being signaled on the controlling channel, so as to "do the right thing" while dtmf is happening. In other words a codec should be able to request that it get dtmf frames, even if the overlying protocol is managing them)

(for all I know it already can, it's just not implemented in speex)

For speex, g729, g722
This could include sending silence or halting packet transmission for the period of the dtmf digits.

for ulaw inband the codec is more or less already aware of it... I don't understand what should happen for rfc2833.

anyway, I do hope all this stuff has already been figured out in the variable length dtmf code and I'm just repeating stuff everyone already knows.


By: Serge Vecher (serge-v) 2006-05-08 00:24:54

need to address the situation here.
By: Joshua C. Colp (jcolp) 2006-05-19 09:07:22

I'm closing this since it's not really a bug... but the way that the core works and the way the translation system works. If you want to suggest changes and things, try to stir up a thread on the asterisk-dev mailing list. While I like some of your ideas, and not others - this is not the place to really discuss it.