FXO with MGCP cause value=47 (Media resources not available)

[Leo Salcie Tejeda]

Hi Guys,

I have setup a FXO interface with MGCP, after the call is received on the router a fast busy tone is received with a error cause value=47 . I know cause value=47 in some cases are transcoder issue but I don't have Transcoder resource because all the way is only use G.711Ulaw, at CUCM service parameter Intraregion/Interregion are forced to G.711/G7.22 so I really don't know why on earth could be tryng to use transcoding or another kind of Media Resoruces.

CallMExpress#

*Oct  3 13:03:59.178: EIGRP-IPv4(1): Neighbor 192.168.7.1 not on common subnet for FastEthernet0/1

*Oct  3 13:04:04.086: //-1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:

   Interface=0x4B5DC5A4, Interface Type=6, Destination=98092201111, Mode=0x9,

   Call Params(Calling Number=,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),

   Called Number=98092201111(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,

   Subscriber Type Str=, FinalDestinationFlag=FALSE, Outgoing Dial-peer=0, Call Count On=FALSE,

   Source Trkgrp Route Label=, Target Trkgrp Route Label=, tg_label_flag=0, Application Call Id=A000000001ab04e7000000F5)

*Oct  3 13:04:04.086: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Oct  3 13:04:04.086: :cc_get_feature_vsa malloc success

*Oct  3 13:04:04.086: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Oct  3 13:04:04.086:  cc_get_feature_vsa count is 1

*Oct  3 13:04:04.086: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Oct  3 13:04:04.086: :FEATURE_VSA attributes are: feature_name:0,feature_time:1294008000,feature_id:49

*Oct  3 13:04:04.086: //49/A44CDE5D801A/CCAPI/ccIFCallSetupRequestPrivate:

   SPI Call Setup Request Is Success; Interface Type=6, FlowMode=1

*Oct  3 13:04:04.086: //49/A44CDE5D801A/CCAPI/ccCallSetContext:

   Context=0x490C03C8

*Oct  3 13:04:04.086: //-1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:

   Interface=0x4B02FDF0, Interface Type=9, Destination=0.0.0.0, Mode=0x9,

   Call Params(Calling Number=,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),

   Called Number=(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,

   Subscriber Type Str=, FinalDestinationFlag=FALSE, Outgoing Dial-peer=0, Call Count On=TRUE,

   Source Trkgrp Route Label=, Target Trkgrp Route Label=, tg_label_flag=0, Application Call Id=A000000001ab04e7000000F5)

*Oct  3 13:04:04.086: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Oct  3 13:04:04.090: :cc_get_feature_vsa malloc success

*Oct  3 13:04:04.090: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Oct  3 13:04:04.090:  cc_get_feature_vsa count is 2

*Oct  3 13:04:04.090: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Oct  3 13:04:04.090: :FEATURE_VSA attributes are: feature_name:0,feature_time:1294007776,feature_id:50

*Oct  3 13:04:04.090: //50/A44CDE5D801A/CCAPI/ccIFCallSetupRequestPrivate:

   SPI Call Setup Request Is Success; Interface Type=9, FlowMode=1

*Oct  3 13:04:04.090: //50/A44CDE5D801A/CCAPI/ccCallSetContext:

   Context=0x490C0108

*Oct  3 13:04:04.094: //50/A44CDE5D801A/CCAPI/cc_api_call_connected:

   Interface=0x4B02FDF0, Data Bitmask=0x0, Progress Indication=NULL(0),

   Connection Handle=0

*Oct  3 13:04:04.094: //50/A44CDE5D801A/CCAPI/cc_api_call_connected:

   Call Entry(Connected=TRUE, Responsed=TRUE, Retry Count=0)

*Oct  3 13:04:04.098: //49/A44CDE5D801A/CCAPI/cc_api_call_proceeding:

   Interface=0x4B5DC5A4, Progress Indication=NULL(0)

*Oct  3 13:04:13.122: EIGRP-IPv4(1): Neighbor 192.168.7.1 not on common subnet for FastEthernet0/1

*Oct  3 13:04:14.094: //49/A44CDE5D801A/CCAPI/cc_api_call_disconnected:

   Cause Value=16, Interface=0x4B5DC5A4, Call Id=49

*Oct  3 13:04:14.094: //49/A44CDE5D801A/CCAPI/cc_api_call_disconnected:

   Call Entry(Responsed=TRUE, Cause Value=16, Retry Count=0)

*Oct  3 13:04:14.094: //50/A44CDE5D801A/CCAPI/ccCallDisconnect:

   Cause Value=47, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)

*Oct  3 13:04:14.094: //50/A44CDE5D801A/CCAPI/ccCallDisconnect:

   Cause Value=47, Call Entry(Responsed=TRUE, Cause Value=47)

*Oct  3 13:04:14.094: //49/A44CDE5D801A/CCAPI/ccCallDisconnect:

   Cause Value=47, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=16)

*Oct  3 13:04:14.094: //49/A44CDE5D801A/CCAPI/ccCallDisconnect:

   Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)

*Oct  3 13:04:14.094: //49/A44CDE5D801A/CCAPI/cc_api_get_transfer_info:

   Transfer Number Is Null

*Oct  3 13:04:14.098: //50/A44CDE5D801A/CCAPI/cc_api_call_disconnect_done:

   Disposition=0, Interface=0x4B02FDF0, Tag=0x0, Call Id=50,

   Call Entry(Disconnect Cause=47, Voice Class Cause Code=0, Retry Count=0)

*Oct  3 13:04:14.098: //50/A44CDE5D801A/CCAPI/cc_api_call_disconnect_done:

   Call Disconnect Event Sent

*Oct  3 13:04:14.098: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Oct  3 13:04:14.098: :cc_free_feature_vsa freeing 4D20FDD8

*Oct  3 13:04:14.098: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Oct  3 13:04:14.098:  vsacount in free is 1

*Oct  3 13:04:14.102: //49/A44CDE5D801A/CCAPI/cc_api_call_disconnect_done:

   Disposition=0, Interface=0x4B5DC5A4, Tag=0x0, Call Id=49,

   Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)

*Oct  3 13:04:14.106: //49/A44CDE5D801A/CCAPI/cc_api_call_disconnect_done:

   Call Disconnect Event Sent

*Oct  3 13:04:14.106: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Oct  3 13:04:14.106: :cc_free_feature_vsa freeing 4D20FEB8

*Oct  3 13:04:14.106: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Oct  3 13:04:14.106:  vsacount in free is 0

CallMExpress#

show voice dsp group all

dsp 1:

  State: UP, firmware: 28.3.3

  Max signal/voice channel: 8/8

  Max credits: 160

  num_of_sig_chnls_allocated: 6

  Transcoding channels allocated: 0

  Group: FLEX_GROUP_VOICE, complexity: FLEX

    Shared credits: 160, reserved credits: 0

    Signaling channels allocated: 6

    Voice channels allocated: 0

    Credits used (rounded-up): 0

dsp 5:

  State: UP, firmware: 28.3.3

  Max signal/voice channel: 8/8

  Max credits: 160

  num_of_sig_chnls_allocated: 0

  Transcoding channels allocated: 0

  Group: FLEX_GROUP_VOICE, complexity: FLEX

    Shared credits: 160, reserved credits: 0

    Signaling channels allocated: 0

    Voice channels allocated: 0

    Credits used (rounded-up): 0

DSP groups on slot 1:

This command is not applicable to slot 1

DSP groups on slot 2:

This command is not applicable to slot 2

  0 DSP resource allocation failure

CallMExpress#

Any advance would be appreciated

Regards

MGCP, CCNA, CCNA Voice certified       

[Leo Salcie Tejeda]

Ok I was tired to think why the call is needing resources so I registered some transcoding resoruces, right now the call is established using codec G711 so WHY the call is requiring transcoding? I have tried using a IP communicator and Cisco 7965.

_____________________________
MGCP, CCNA, CCNA Voice certified

[Ayodeji Okanlawon]

Leo,

Most likely the transcoder is used for MTP purposes. Cause code 47 does not necesarily  mean its a transcoder issue, it could also be a MTP problem.

What is your setup like? MTP usually are used for dtmf mismatch...If you send over cucm traces, We will see what the transcoder is used for. Please let me know the called and calling number

Please rate all useful posts

"'Nature is too thin a screen, the glory of the omnipresent God bursts through it everywhere"-Ralph Waldo Emerson

[Leo Salcie Tejeda]

My scenario is as follow:

CUCM with MGCP fxo using a router 2911, fxo is conected to a PSTN line. Call is dialed from softphone (IP Communicator), the call is received at GW who send teh call to the PSTN line.

CUCM       MGCP         GW (2911)     FXO                 Line      PSTN

          --------------------->               ---------------->      <--------------

Attached the CUCM's calls logs

Thanks in advance

_____________________________
MGCP, CCNA, CCNA Voice certified

[Kevin Monteiro]

     Hi Leo,

Can you attach the show tech and version of  cucm being used here..

Debug mgcp packets

debug voip vtsp all

debug vpm signal

Try re-creating the issue and capture these debugs.

I see a strange behaviour though its hitting the dial-peer 0 which is the default dial-peer.

It should not be hitting that dial-peer (DP: 0) if its registered as MGCP.

Regards,

Kevin

[Leo Salcie Tejeda]

@Kein, attached to this email the logs.

_____________________________
MGCP, CCNA, CCNA Voice certified

[Kevin Monteiro]

Hey Leo,

can you capture the debugs again and let me know the calling and called party number.

show tech

debug mgcp packets

debug vpm signal

debug voip vtsp all

Regards,

Kevin

[Kevin Monteiro]

Hi Leo,

Try applying the following:

Router4.90(config)#mgcp

Router4.90(config)#no mgcp fax t38 inhibit

Router4.90(config)#no mgcp default-package fxr-package

Let me know how it goes.

Regards,

Kevin

[Kevin Monteiro]

Hi Leo,

Just wanted to know if the above solution worked for you.

Let me know the same.

Regards,

Kevin Monteiro

[Amit23]

guys... i have same issue..

i have 3925 router...with 4 port fxo card...

incoming working...but outgoing giving buy tone and disconnect..

called number: called num:5011471

----------------------------------

QCCI-CME-001#
QCCI-CME-001#
Jul 21 11:24:03 Qatar: //-1/xxxxxxxxxxxx/VTSP:(0/2/0):-1:-1:-1/vtsp_allocate_cdb:  
   CDB=0x14DC38F0
Jul 21 11:24:03 Qatar: //-1/xxxxxxxxxxxx/VTSP:(0/2/0):-1:-1:-1/vtsp_insert_cdb:
Jul 21 11:24:03 Qatar: //-1/xxxxxxxxxxxx/VTSP:(0/2/0):-1:-1:-1/vtsp_process_event:  
   [state:INVALID STATE MACHINE, event:E_CC_SETUP_REQ]
Jul 21 11:24:03 Qatar: htsp_timer_stop3
Jul 21 11:24:03 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:-1:-1/vtsp_og_call_req:  
   Echo Cancel=TRUE, Gain Control=0
   Auto Gain Control=FALSE, Dual Tone Detect Mask=0x0, Seq Tone Detect=FALSE
Jul 21 11:24:03 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:-1:-1/vtsp_do_call_setup_req:
Jul 21 11:24:03 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_dsm_opened_cb:
Jul 21 11:24:03 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_process_event:  
   [state:S_SETUP_REQ_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
Jul 21 11:24:03 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/act_setup_req_pend_succ:
Jul 21 11:24:03 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_request_call:  
   Mode=9, Peer=0
Jul 21 11:24:03 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_create_call_active_on_setup_req:  
   Target Carrier ID=
Jul 21 11:24:03 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_create_call_active_on_setup_req:  
   Source Carrier ID=htsp_setup_req
Jul 21 11:24:03 Qatar:  Orig called num:50114712
Jul 21 11:24:03 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_request_call:  
   Progress Indication=0, Info Trans Capability=0
   Calling Number=, TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed
   Called Number=50114712, TON=Unknown, NPI=Unknown
Jul 21 11:24:03 Qatar: htsp_process_event: [0/2/0, FXOGS_ONHOOK, E_HTSP_SETUP_REQ]fxogs_onhook_setup
Jul 21 11:24:03 Qatar: [0/2/0] set signal state = 0x0 timestamp = 0
Jul 21 11:24:03 Qatar: htsp_timer - 10000 msec
Jul 21 11:24:03 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_process_event:  
   [state:S_SETUP_REQUEST, event:E_TSP_PROCEEDING]
Jul 21 11:24:03 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/act_setup_pend_proceeding:
Jul 21 11:24:03 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_timer:  
   Timer Start Time=7717154, Timer Value=25000(ms)
Jul 21 11:24:03 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/act_setup_pend_proceeding:  
   Peer=0, Progress Indication=0, Return Code=2
Jul 21 11:24:03 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_dsm_opened_cb:
Jul 21 11:24:03 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_process_event:  
   [state:S_NULL, event:E_VTSP_DSM_OPEN_SUCCESS]
Jul 21 11:24:03 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/act_setup_req_wait_pend_success:  
   Event=76
Jul 21 11:24:03 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_timer_stop:  
   Timer Stop Time=7717154
Jul 21 11:24:13 Qatar: htsp_process_event: [0/2/0, FXOGS_WAIT_TIP_GROUND, E_HTSP_EVENT_TIMER]fxogs_offhook_disc
Jul 21 11:24:13 Qatar: htsp_timer_stop
Jul 21 11:24:13 Qatar: [0/2/0] set signal state = 0x4 timestamp = 0
Jul 21 11:24:13 Qatar: htsp_timer - 1000 msec
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_process_event:  
   [state:S_SETUP_REQ_PROC, event:E_TSP_DISCONNECT_IND]
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/act_setup_pend_release_ind:  
   Cause Value=16
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_ring_noan_timer_stop:  
   Timer Stop Time=7718154
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_cc_call_disconnected:
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_cc_call_disconnected:  
   Cause Value=16
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_set_release_source:  
   Release Direction=PSTN, Release Source=Called Party-PSTN
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/act_setup_pend_release_ind:  
   Peer=0
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_process_event:  
   [state:S_WAIT_HOST_DISC, event:E_CC_DISCONNECT]
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/act_host_disc_cleanup:  
   dsm_indicate_error=0, short_cleardown_timeout=1, Mode=9
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_dsm_save_fax_config:
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_dsm_save_fax_config:  
   Call Entry=NULL, Call Id=-1
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/act_host_disc_cleanup:  
   Exit State=16
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_dsm_get_levels_done_cb:
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_process_event:  
   [state:S_WAIT_STATS, event:E_VTSP_DSM_STATS_COMPLETE]
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/act_dsm_dsp_stats_complete:
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_timer:  
   Timer Start Time=7718154, Timer Value=5000(ms)
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_process_event:  
   [state:S_WAIT_RELEASE, event:E_VTSP_DSM_STATS_COMPLETE]
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_process_event:  
   Unexpected EVENT [E_VTSP_DSM_STATS_COMPLETE] Received For STATE [S_WAIT_RELEASE];
   Previous STATE [0.16 ]
Jul 21 11:24:13 Qatar: htsp_process_event: [0/2/0, FXOGS_ONHOOK, E_HTSP_RELEASE_REQ]fxogs_onhook_release
Jul 21 11:24:13 Qatar: htsp_timer_stop2
Jul 21 11:24:13 Qatar: htsp_timer_stop3
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_process_event:  
   [state:S_WAIT_RELEASE, event:E_TSP_DISCONNECT_CONF]
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/act_wrelease_release:
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_play_busy_timer_stop:  
   Timer Stop Time=7718154
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_timer_stop:  
   Timer Stop Time=7718154
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_do_call_history:
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_do_call_history:  
   Coder Rate=-1
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:1:1/vtsp_is_valid_dsm_handle:  
   DMGR=0x2E9008C, VTSP CDB=0x14DC38F0
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:-1:-1/vtsp_dsm_closed_cb:
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:-1:-1/vtsp_process_event:  
   [state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:-1:-1/act_terminate:
Jul 21 11:24:13 Qatar: //315/880E90F28097/VTSP:(0/2/0):-1:-1:-1/vtsp_timer_stop:  
   Timer Stop Time=7718154
Jul 21 11:24:13 Qatar: //-1/880E90F28097/VTSP:(0/2/0):-1:-1:-1/vtsp_free_cdb:  
   CDB=0x14DC38F0
Jul 21 11:24:13 Qatar: htsp_process_event: [0/2/0, FXOGS_ONHOOK, E_DSP_SIG_0110]
Jul 21 11:24:13 Qatar: fxogs_line_reversal_clid_wait. On_hook line reversal detected possibily due to crossed cable
Jul 21 11:24:14 Qatar: htsp_process_event: [0/2/0, FXOGS_ONHOOK, E_HTSP_EVENT_TIMER]
QCCI-CME-001#
QCCI-CME-001#
QCCI-CME-001#u all
All possible debugging has been turned off
QCCI-CME-001#
QCCI-CME-001#
QCCI-CME-001#
QCCI-CME-001#

[Leo Salcie Tejeda]

Hi,

I solved the issue upgrading the router's IOS. It was a IOS bug, at last that worked for me.

Regards

[Brian Meade]

Grab the CallManager traces for one of these calls.