G729 Codec Translation issues

wzkds · December 30, 2021, 6:18pm

Hi All,

I’m looking for a bit of assistance in trying to figure out why calls are being dropped. After talking with our provider, I’ve figured out that the originating call is trying to setup the call with the g729 codec. The call appears to get setup correctly but runs into issues when trying to play the announcement or IVR (Depending on time of day). Both produce the same results.

Output from core show translation:

ilcmn*CLI> core show translation
         Translation times between formats (in microseconds) for one second of data
          Source Format (Rows) Destination Format (Columns)

           ulaw  alaw   gsm  g726 g726aal2 adpcm  slin  slin  slin  slin  slin  slin  slin  slin  slin lpc10  ilbc  g722 testlaw
     ulaw     -  9150 15000 15000    15000 15000  9000 17000 17000 17000 17000 17000 17000 17000 17000 15000 15000 17250   15000
     alaw  9150     - 15000 15000    15000 15000  9000 17000 17000 17000 17000 17000 17000 17000 17000 15000 15000 17250   15000
      gsm 15000 15000     - 15000    15000 15000  9000 17000 17000 17000 17000 17000 17000 17000 17000 15000 15000 17250   15000
     g726 15000 15000 15000     -    15000 15000  9000 17000 17000 17000 17000 17000 17000 17000 17000 15000 15000 17250   15000
 g726aal2 15000 15000 15000 15000        - 15000  9000 17000 17000 17000 17000 17000 17000 17000 17000 15000 15000 17250   15000
    adpcm 15000 15000 15000 15000    15000     -  9000 17000 17000 17000 17000 17000 17000 17000 17000 15000 15000 17250   15000
     slin  6000  6000  6000  6000     6000  6000     -  8000  8000  8000  8000  8000  8000  8000  8000  6000  6000  8250    6000
     slin 14500 14500 14500 14500    14500 14500  8500     -  8000  8000  8000  8000  8000  8000  8000 14500 14500 14000   14500
     slin 14500 14500 14500 14500    14500 14500  8500  8500     -  8000  8000  8000  8000  8000  8000 14500 14500  6000   14500
     slin 14500 14500 14500 14500    14500 14500  8500  8500  8500     -  8000  8000  8000  8000  8000 14500 14500 14500   14500
     slin 14500 14500 14500 14500    14500 14500  8500  8500  8500  8500     -  8000  8000  8000  8000 14500 14500 14500   14500
     slin 14500 14500 14500 14500    14500 14500  8500  8500  8500  8500  8500     -  8000  8000  8000 14500 14500 14500   14500
     slin 14500 14500 14500 14500    14500 14500  8500  8500  8500  8500  8500  8500     -  8000  8000 14500 14500 14500   14500
     slin 14500 14500 14500 14500    14500 14500  8500  8500  8500  8500  8500  8500  8500     -  8000 14500 14500 14500   14500
     slin 14500 14500 14500 14500    14500 14500  8500  8500  8500  8500  8500  8500  8500  8500     - 14500 14500 14500   14500
    lpc10 15000 15000 15000 15000    15000 15000  9000 17000 17000 17000 17000 17000 17000 17000 17000     - 15000 17250   15000
     ilbc 15000 15000 15000 15000    15000 15000  9000 17000 17000 17000 17000 17000 17000 17000 17000 15000     - 17250   15000
     g722 15600 15600 15600 15600    15600 15600  9600 17500  9000 17000 17000 17000 17000 17000 17000 15600 15600     -   15600
  testlaw 15000 15000 15000 15000    15000 15000  9000 17000 17000 17000 17000 17000 17000 17000 17000 15000 15000 17250       -

Here is the output of the call capture:

[2021-12-30 10:18:42] VERBOSE[6631][C-0000002f] netsock2.c: Using SIP RTP TOS bits 184
[2021-12-30 10:18:42] VERBOSE[6631][C-0000002f] netsock2.c: Using SIP RTP CoS mark 5
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [XXXXXXXXXX@from-trunk-sip-SBC2_Out:1] Set("SIP/SBC2_Out-00000034", "GROUP()=OUT_7") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [XXXXXXXXXX@from-trunk-sip-SBC2_Out:2] Goto("SIP/SBC2_Out-00000034", "from-trunk,XXXXXXXXXX,1") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx_builtins.c: Goto (from-trunk,XXXXXXXXXX,1)
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [XXXXXXXXXX@from-trunk:1] Set("SIP/SBC2_Out-00000034", "__DIRECTION=INBOUND") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [XXXXXXXXXX@from-trunk:2] Gosub("SIP/SBC2_Out-00000034", "sub-record-check,s,1(in,XXXXXXXXXX,dontcare)") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/SBC2_Out-00000034", "0?initialized") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@sub-record-check:2] Set("SIP/SBC2_Out-00000034", "__REC_STATUS=INITIALIZED") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@sub-record-check:3] Set("SIP/SBC2_Out-00000034", "NOW=1640881122") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@sub-record-check:4] Set("SIP/SBC2_Out-00000034", "__DAY=30") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@sub-record-check:5] Set("SIP/SBC2_Out-00000034", "__MONTH=12") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@sub-record-check:6] Set("SIP/SBC2_Out-00000034", "__YEAR=2021") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@sub-record-check:7] Set("SIP/SBC2_Out-00000034", "__TIMESTR=20211230-101842") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@sub-record-check:8] Set("SIP/SBC2_Out-00000034", "__FROMEXTEN=unknown") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@sub-record-check:9] Set("SIP/SBC2_Out-00000034", "__MON_FMT=wav") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/SBC2_Out-00000034", "Recordings initialized") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/SBC2_Out-00000034", "0?Set(ARG3=dontcare)") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@sub-record-check:12] Set("SIP/SBC2_Out-00000034", "REC_POLICY_MODE_SAVE=") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/SBC2_Out-00000034", "0?Set(REC_STATUS=NO)") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/SBC2_Out-00000034", "2?checkaction") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx_builtins.c: Goto (sub-record-check,s,17)
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/SBC2_Out-00000034", "1?sub-record-check,in,1") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx_builtins.c: Goto (sub-record-check,in,1)
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [in@sub-record-check:1] NoOp("SIP/SBC2_Out-00000034", "Inbound Recording Check to XXXXXXXXXX") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [in@sub-record-check:2] Set("SIP/SBC2_Out-00000034", "FROMEXTEN=unknown") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [in@sub-record-check:3] ExecIf("SIP/SBC2_Out-00000034", "10?Set(FROMEXTEN=NNNNNNNNNN)") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [in@sub-record-check:4] Gosub("SIP/SBC2_Out-00000034", "recordcheck,1(dontcare,in,XXXXXXXXXX)") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/SBC2_Out-00000034", "Starting recording check against dontcare") in new

[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [in@sub-record-check:4] Gosub("SIP/SBC2_Out-00000034", "recordcheck,1(dontcare,in,XXXXXXXXXX)") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/SBC2_Out-00000034", "Starting recording check against dontcare") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/SBC2_Out-00000034", "dontcare") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/SBC2_Out-00000034", "") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [in@sub-record-check:5] Return("SIP/SBC2_Out-00000034", "") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [XXXXXXXXXX@from-trunk:3] Set("SIP/SBC2_Out-00000034", "__FROM_DID=XXXXXXXXXX") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [XXXXXXXXXX@from-trunk:4] Set("SIP/SBC2_Out-00000034", "returnhere=1") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [XXXXXXXXXX@from-trunk:5] Gosub("SIP/SBC2_Out-00000034", "app-blacklist-check,s,1()") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@app-blacklist-check:1] GotoIf("SIP/SBC2_Out-00000034", "0?blacklisted") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@app-blacklist-check:2] Set("SIP/SBC2_Out-00000034", "CALLED_BLACKLIST=1") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@app-blacklist-check:3] Return("SIP/SBC2_Out-00000034", "") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [XXXXXXXXXX@from-trunk:6] Set("SIP/SBC2_Out-00000034", "CDR(did)=XXXXXXXXXX") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [XXXXXXXXXX@from-trunk:7] GotoIf("SIP/SBC2_Out-00000034", "0?") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [XXXXXXXXXX@from-trunk:8] ExecIf("SIP/SBC2_Out-00000034", "0 ?Set(CALLERID(name)=NNNNNNNNNN)") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [XXXXXXXXXX@from-trunk:9] Set("SIP/SBC2_Out-00000034", "__MOHCLASS=") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [XXXXXXXXXX@from-trunk:10] Set("SIP/SBC2_Out-00000034", "__REVERSAL_REJECT=FALSE") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [XXXXXXXXXX@from-trunk:11] GotoIf("SIP/SBC2_Out-00000034", "1?post-reverse-charge") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx_builtins.c: Goto (from-trunk,XXXXXXXXXX,13)
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [XXXXXXXXXX@from-trunk:13] NoOp("SIP/SBC2_Out-00000034", "") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [XXXXXXXXXX@from-trunk:14] Set("SIP/SBC2_Out-00000034", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [XXXXXXXXXX@from-trunk:15] Set("SIP/SBC2_Out-00000034", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [XXXXXXXXXX@from-trunk:16] Set("SIP/SBC2_Out-00000034", "CALLERID(name-pres)=allowed_not_screened") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [XXXXXXXXXX@from-trunk:17] Set("SIP/SBC2_Out-00000034", "CALLERID(num-pres)=allowed_not_screened") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [XXXXXXXXXX@from-trunk:18] NoOp("SIP/SBC2_Out-00000034", "CallerID Entry Point") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [XXXXXXXXXX@from-trunk:19] Goto("SIP/SBC2_Out-00000034", "app-daynight,0,1") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx_builtins.c: Goto (app-daynight,0,1)
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [0@app-daynight:1] GotoIf("SIP/SBC2_Out-00000034", "1?app-announcement-31,s,1:ivr-2,s,1") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx_builtins.c: Goto (app-announcement-31,s,1)
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@app-announcement-31:1] GotoIf("SIP/SBC2_Out-00000034", "0?begin") in new stack
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@app-announcement-31:2] Answer("SIP/SBC2_Out-00000034", "") in new stack
[2021-12-30 10:18:42] WARNING[6631][C-0000002f] channel.c: Unable to find a codec translation path: (g729) -> (ulaw)
[2021-12-30 10:18:42] WARNING[6631][C-0000002f] channel.c: Unable to find a codec translation path: (ulaw) -> (g729)
[2021-12-30 10:18:42] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@app-announcement-31:3] Wait("SIP/SBC2_Out-00000034", "1") in new stack
[2021-12-30 10:18:42] WARNING[19258][C-0000002f] channel.c: Unable to find a codec translation path: (slin) -> (g729)
[2021-12-30 10:18:42] ERROR[19258][C-0000002f] channel.c: Could not set write format to SLINEAR
[2021-12-30 10:18:43] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@app-announcement-31:4] NoOp("SIP/SBC2_Out-00000034", "Playing announcement Office Temp Closed Announcement") in new stack
[2021-12-30 10:18:43] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@app-announcement-31:5] Playback("SIP/SBC2_Out-00000034", "custom/weather-closed,noanswer") in new stack
[2021-12-30 10:18:43] WARNING[19258][C-0000002f] channel.c: Unable to find a codec translation path: (ulaw|slin) -> (g729)
[2021-12-30 10:18:43] WARNING[19258][C-0000002f] file.c: Unable to open custom/weather-closed (format (g729)): No such file or directory
[2021-12-30 10:18:43] WARNING[19258][C-0000002f] app_playback.c: Playback failed on SIP/SBC2_Out-00000034 for custom/weather-closed,noanswer
[2021-12-30 10:18:43] VERBOSE[19258][C-0000002f] pbx.c: Executing [s@app-announcement-31:6] Goto("SIP/SBC2_Out-00000034", "app-blackhole,hangup,1") in new stack
[2021-12-30 10:18:43] VERBOSE[19258][C-0000002f] pbx_builtins.c: Goto (app-blackhole,hangup,1)
[2021-12-30 10:18:43] VERBOSE[19258][C-0000002f] pbx.c: Executing [hangup@app-blackhole:1] NoOp("SIP/SBC2_Out-00000034", "Blackhole Dest: Hangup") in new stack
[2021-12-30 10:18:43] VERBOSE[19258][C-0000002f] pbx.c: Executing [hangup@app-blackhole:2] Hangup("SIP/SBC2_Out-00000034", "") in new stack
[2021-12-30 10:18:43] VERBOSE[19258][C-0000002f] pbx.c: Spawn extension (app-blackhole, hangup, 2) exited non-zero on 'SIP/SBC2_Out-00000034'

rsmithuk · December 30, 2021, 6:33pm

So it doesn’t look like you have G729 enabled. What version of FreePBX and Asterisk are you running?

Although I will be that guy that asks, is there a reason you using G729? Using it is very resource hungry if you are doing software transcoding.

wzkds · December 30, 2021, 6:45pm

We are running freepbx 13.0.197.31 and asterisk 13.18.3. I know its old we are migrating in the near future to the latest. To answer the g729 question, its just something I noticed with the SIP provider. One of the incoming callers uses it. Maybe i’m missing something or just don’t understand it, but we’ve got our trunk setup to only allow ulaw.

rsmithuk · December 30, 2021, 6:58pm

Ok, yeah v13 doesn’t include any form of G729. I think they started bundling in either v14 or 15.

It’s odd that your provider is passing G729 through, I would have expected that to fail earlier in the process.

Do you have disallow=all in your trunk config as well as allow=ulaw&alaw (or whatever codecs you use)?

wzkds · December 30, 2021, 8:11pm

That I do not. Here is the outbound side:

allow=ulaw
dtmfmode=rfc2833
host=x.x.x.x
nat=yes
port=5060
type=peer

And inbound:

canreinvite=yes
context=from-trunk
dtmfmode=rfc2833
insecure=very
nat=yes
port=5060
type=peer

rsmithuk · December 30, 2021, 8:31pm

You can either try adding the disallow= etc. or try asking your provider if they can only send using ulaw.

david55 · December 30, 2021, 10:53pm

Failing to include disallow can generate very long requests and, at least with some version of Asterisk, some of the funny codecs included break things.

I don’t see how your inbound section can possibly work, as there is no way for it to identify the peer. Almost certainly only the outbound section is ever being used, and is being used in both directions. insecure=invite (expanding your deprecated very) does nothing without a secret. If I’m right about the outbound section being used, insecure=port isn’t necessary.

wzkds · January 3, 2022, 7:16pm

Its a bit of a niche use case. Tweaking the trunk did fix the issue! Much appreciated!

system · January 10, 2022, 7:16pm

This topic was automatically closed 7 days after the last reply. New replies are no longer allowed.