PSTN phones is busy but CUCM does not relay the busy signal to the IP phone

bejoy.cisco · ‎11-06-2013

Dear Experts,

I am experiencing this issue with CUCM 9.1. When a call is made from an IP phone to a PSTN number and if the PSTN number is busy, the call goes blank. The Ip phone goes to a long silence.

What I have learned from the the debugs is that when the far end phone is busy the service provider is sending a busy signal to the voice gateway (which is an H.232 GW). But some how the GW is not able to relay it to the CUCM.

Have any one faced this issue before. Please help with your valuable solutions.

Regards

Bejoy Thomas

Ayodeji Okanlawon · ‎11-06-2013

Can you send us the ff:

debug isdn q931

please include calling and called number

Please rate all useful posts

"opportunity is a haughty goddess who waste no time with those who are unprepared"

Please rate all useful posts

bejoy.cisco · ‎11-06-2013

Hi,

I am not at the site right now. So i do not have the 'debug ISDN q931' but i do have 'Debug voice ccap inout'

calling number: 5004 (IP phone)

called number: 33512100

Voice_GW_1#

Nov 5 14:11:31.994: //-1/00B10D2AF426/CCAPI/cc_api_display_ie_subfields:

cc_api_call_setup_ind_common:

cisco-username=IPT Helpdesk (TEMP)

----- ccCallInfo IE subfields -----

cisco-ani=5004

cisco-anitype=0

cisco-aniplan=0

cisco-anipi=0

cisco-anisi=1

dest=33512100

cisco-desttype=0

cisco-destplan=0

cisco-rdie=FFFFFFFF

cisco-rdn=

cisco-rdntype=-1

cisco-rdnplan=-1

cisco-rdnpi=-1

cisco-rdnsi=-1

cisco-redirectreason=-1 fwd_final_type =0

final_redirectNumber =

hunt_group_timeout =0

Nov 5 14:11:31.994: //-1/00B10D2AF426/CCAPI/cc_api_call_setup_ind_common:

Interface=0x3120854C, Call Info(

Calling Number=5004,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed),

Called Number=33512100(TON=Unknown, NPI=Unknown),

Calling Translated=FALSE, Subscriber Type Str=Unknown, FinalDestinationFlag=TRUE,

Incoming Dial-peer=100, Progress Indication=NULL(0), Calling IE Present=TRUE,

Source Trkgrp Route Label=, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=140570

Nov 5 14:11:31.994: //-1/00B10D2AF426/CCAPI/ccCheckClipClir:

In: Calling Number=5004(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed)

Nov 5 14:11:31.994: //-1/00B10D2AF426/CCAPI/ccCheckClipClir:

Out: Calling Number=5004(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed)

Nov 5 14:11:31.994: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Nov 5 14:11:31.994: :cc_get_feature_vsa malloc success

Nov 5 14:11:31.994: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Nov 5 14:11:31.994: cc_get_feature_vsa count is 7

Nov 5 14:11:31.994: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Nov 5 14:11:31.994: :FEATURE_VSA attributes are: feature_name:0,feature_time:811966896,feature_id:137618

Nov 5 14:11:31.994: //140570/00B10D2AF426/CCAPI/cc_api_call_setup_ind_common:

Set Up Event Sent;

Call Info(Calling Number=5004(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed),

Called Number=33512100(TON=Unknown, NPI=Unknown))

Nov 5 14:11:31.994: //140570/00B10D2AF426/CCAPI/cc_process_call_setup_ind:

Event=0x31581408

Nov 5 14:11:31.994: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_search:

Try with the demoted called number 33512100

Nov 5 14:11:31.994: //140570/00B10D2AF426/CCAPI/ccCallSetContext:

Context=0x2BC94C54

Nov 5 14:11:31.994: //140570/00B10D2AF426/CCAPI/cc_process_call_setup_ind:

>>>>CCAPI handed cid 140570 with tag 100 to app "_ManagedAppProcess_num2name"

Nov 5 14:11:31.994: //140570/00B10D2AF426/CCAPI/ccCallProceeding:

Progress Indication=NULL(0)

Nov 5 14:11:31.998: //140570/00B10D2AF426/CCAPI/ccCallSetupRequest:

Destination=, Calling IE Present=TRUE, Mode=0,

Outgoing Dial-peer=1, Params=0x2BC7D724, Progress Indication=NULL(0)

Nov 5 14:11:31.998: //140570/00B10D2AF426/CCAPI/ccCheckClipClir:

In: Calling Number=5004(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed)

Nov 5 14:11:31.998: //140570/00B10D2AF426/CCAPI/ccCheckClipClir:

Out: Calling Number=5004(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed)

Nov 5 14:11:31.998: //140570/00B10D2AF426/CCAPI/ccCallSetupRequest:

Destination Pattern=.T, Called Number=33512100, Digit Strip=TRUE

Nov 5 14:11:31.998: //140570/00B10D2AF426/CCAPI/ccCallSetupRequest:

Calling Number=5004(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed),

Called Number=33512100(TON=Unknown, NPI=Unknown),

Redirect Number=, Display Info=Bejoy

Account Number=IPT Helpdesk (TEMP), Final Destination Flag=TRUE,

Guid=00B10D2A-93FC-8127-F426-F203AC1F2383, Outgoing Dial-peer=1

Nov 5 14:11:31.998: //140570/00B10D2AF426/CCAPI/cc_api_display_ie_subfields:

ccCallSetupRequest:

cisco-username=IPT Helpdesk (TEMP)

----- ccCallInfo IE subfields -----

cisco-ani=5004

cisco-anitype=0

cisco-aniplan=0

cisco-anipi=0

cisco-anisi=1

dest=33512100

cisco-desttype=0

cisco-destplan=0

cisco-rdie=74

cisco-rdn=

cisco-rdntype=-1

cisco-rdnplan=-1

cisco-rdnpi=-1

cisco-rdnsi=-1

cisco-redirectreason=-1 fwd_final_type =0

final_redirectNumber =

hunt_group_timeout =0

Nov 5 14:11:31.998: //140570/00B10D2AF426/CCAPI/ccIFCallSetupRequestPrivate:

Interface=0x315B7394, Interface Type=6, Destination=, Mode=0x0,

Call Params(Calling Number=5004,(Calling Name=5004)(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed),

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

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

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

Nov 5 14:11:31.998: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Nov 5 14:11:31.998: :cc_get_feature_vsa malloc success

Nov 5 14:11:31.998: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Nov 5 14:11:31.998: cc_get_feature_vsa count is 8

Nov 5 14:11:31.998: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Nov 5 14:11:31.998: :FEATURE_VSA attributes are: feature_name:0,feature_time:811968464,feature_id:137619

Nov 5 14:11:31.998: //140571/00B10D2AF426/CCAPI/ccIFCallSetupRequestPrivate:

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

Nov 5 14:11:31.998: //140571/00B10D2AF426/CCAPI/ccCallSetContext:

Context=0x2BC7D6D4

Nov 5 14:11:31.998: //140570/00B10D2AF426/CCAPI/ccSaveDialpeerTag:

Outgoing Dial-peer=1

Nov 5 14:11:32.126: //140571/00B10D2AF426/CCAPI/cc_api_call_proceeding:

Interface=0x315B7394, Progress Indication=INBAND(8)

Nov 5 14:11:32.126: //140570/00B10D2AF426/CCAPI/ccCallCutProgress:

Progress Indication=INBAND(8), Signal Indication=INTERCEPT(2), Cause Value=0

Voice Call Send Alert=FALSE, Call Entry(Alert Sent=FALSE)

Nov 5 14:11:32.126: //140570/00B10D2AF426/CCAPI/ccCallCutProgress:

Call Entry(Responsed=TRUE)

Nov 5 14:11:32.126: //140571/00B10D2AF426/CCAPI/cc_api_get_called_ccm_detected:

CallInfo(ccm detected=0)

Nov 5 14:11:32.126: //140570/00B10D2AF426/CCAPI/ccConferenceCreate:

(confID=0x2BACB38C, callID1=0x2251A, gcid=0-0-0-0, tag=0x0)

Nov 5 14:11:32.126: //140571/00B10D2AF426/CCAPI/ccConferenceCreate:

(confID=0x2BACB38C, callID2=0x2251B, gcid=0-0-0-0, tag=0x0)

Nov 5 14:11:32.126: //140570/00B10D2AF426/CCAPI/ccConferenceCreate:

Conference Id=0x2BACB38C, Call Id1=140570, Call Id2=140571, Tag=0x0

Nov 5 14:11:32.126: //140570/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

Nov 5 14:11:32.126: cc_api_get_xcode_stream : 4702

Nov 5 14:11:32.126: //140570/00B10D2AF426/CCAPI/cc_api_bridge_done:

Conference Id=0xD85E, Source Interface=0x3120854C, Source Call Id=140570,

Destination Call Id=140571, Disposition=0x0, Tag=0x0

Nov 5 14:11:32.126: //140571/00B10D2AF426/CCAPI/cc_api_bridge_done:

Conference Id=0xD85E, Source Interface=0x315B7394, Source Call Id=140571,

Destination Call Id=140570, Disposition=0x0, Tag=0xFFFFFFFF

Nov 5 14:11:32.126: //140570/00B10D2AF426/CCAPI/cc_generic_bridge_done:

Conference Id=0xD85E, Source Interface=0x315B7394, Source Call Id=140571,

Destination Call Id=140570, Disposition=0x0, Tag=0xFFFFFFFF

Nov 5 14:11:32.126: //140570/00B10D2AF426/CCAPI/ccConferenceCreate:

Call Entry(Conference Id=0xD85E, Destination Call Id=140571)

Nov 5 14:11:32.126: //140571/00B10D2AF426/CCAPI/ccConferenceCreate:

Call Entry(Conference Id=0xD85E, Destination Call Id=140570)

Nov 5 14:11:32.126: //140571/00B10D2AF426/CCAPI/cc_api_caps_ind:

Destination Interface=0x3120854C, Destination Call Id=140570, Source Call Id=140571,

Caps(Codec=0x1, Fax Rate=0x1, Vad=0x1,

Modem=0x2, Codec Bytes=20, Signal Type=3)

Nov 5 14:11:32.126: //140571/00B10D2AF426/CCAPI/cc_api_caps_ind:

Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),

Playout Max=1000(ms), Fax Nom=300(ms))

Nov 5 14:11:32.126: //140570/00B10D2AF426/CCAPI/ccCallNotify:

Data Bitmask=0x7, Call Id=140570

Nov 5 14:11:32.126: //140571/00B10D2AF426/CCAPI/cc_api_get_called_ccm_detected:

CallInfo(ccm detected=0)

Nov 5 14:11:32.126: //140570/00B10D2AF426/CCAPI/cc_process_notify_bridge_done:

Conference Id=0xD85E, Call Id1=140570, Call Id2=140571

Nov 5 14:11:32.142: //140570/00B10D2AF426/CCAPI/cc_api_caps_ind:

Destination Interface=0x315B7394, Destination Call Id=140571, Source Call Id=140570,

Caps(Codec=0x1, Fax Rate=0x1, Vad=0x2,

Modem=0x2, Codec Bytes=160, Signal Type=2)

Nov 5 14:11:32.142: //140570/00B10D2AF426/CCAPI/cc_api_caps_ind:

Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),

Playout Max=1000(ms), Fax Nom=300(ms))

Nov 5 14:11:32.142: //140570/00B10D2AF426/CCAPI/cc_api_caps_ack:

Destination Interface=0x315B7394, Destination Call Id=140571, Source Call Id=140570,

Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_NONE(0x1), Vad=ON(0x2),

Modem=ON(0x2), Codec Bytes=160, Signal Type=2, Seq Num Start=6673)

Nov 5 14:11:32.146: //140571/00B10D2AF426/CCAPI/cc_api_caps_ack:

Destination Interface=0x3120854C, Destination Call Id=140570, Source Call Id=140571,

Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_NONE(0x1), Vad=ON(0x2),

Modem=ON(0x2), Codec Bytes=160, Signal Type=2, Seq Num Start=6673)

Nov 5 14:11:32.146: //140571/00B10D2AF426/CCAPI/cc_api_voice_mode_event:

Call Id=140571

Nov 5 14:11:32.146: //140571/00B10D2AF426/CCAPI/cc_api_voice_mode_event:

Call Entry(Context=0x2BC7D6D4)

Nov 5 14:11:36.066: //140571/00B10D2AF426/CCAPI/cc_api_call_alert:

Interface=0x315B7394, Progress Indication=NOT END TO END ISDN(1), Signal Indication=SIGNAL RINGBACK(1)

Nov 5 14:11:36.066: //140571/00B10D2AF426/CCAPI/cc_api_call_alert:

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

Nov 5 14:11:36.066: //140570/00B10D2AF426/CCAPI/ccCallAlert:

Progress Indication=NOT END TO END ISDN(1), Signal Indication=SIGNAL RINGBACK(1)

Nov 5 14:11:36.066: //140570/00B10D2AF426/CCAPI/ccCallAlert:

Call Entry(Responsed=TRUE, Alert Sent=TRUE)

Nov 5 14:11:36.066: //140571/00B10D2AF426/CCAPI/cc_api_get_called_ccm_detected:

CallInfo(ccm detected=0)

Nov 5 14:11:36.066: //140570/00B10D2AF426/CCAPI/ccCallAlert:

Progress Indication=NULL(0), Signal Indication=SIGNAL RINGBACK(1)

Nov 5 14:11:36.066: //140570/00B10D2AF426/CCAPI/ccCallAlert:

Call Entry(Responsed=TRUE, Alert Sent=TRUE)

Nov 5 14:11:36.066: //140571/00B10D2AF426/CCAPI/cc_api_get_called_ccm_detected:

CallInfo(ccm detected=0)

Nov 5 14:11:36.066: //140570/00B10D2AF426/CCAPI/cc_api_get_delay_xport:

CallInfo(delay xport=FALSE)

Nov 5 14:11:36.066: //140570/00B10D2AF426/CCAPI/cc_api_get_delay_xport:

CallInfo(delay xport=FALSE)

Nov 5 14:11:39.642: //140571/00B10D2AF426/CCAPI/cc_api_call_disconnected:

Cause Value=17, Interface=0x315B7394, Call Id=140571

Nov 5 14:11:39.642: //140571/00B10D2AF426/CCAPI/cc_api_call_disconnected:

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

Nov 5 14:11:39.642: //140570/00B10D2AF426/CCAPI/ccCallReleaseResources:

release reserved xcoding resource.

Nov 5 14:11:39.642: //140571/00B10D2AF426/CCAPI/ccCallSetAAA_Accounting:

Accounting=0, Call Id=140571

Nov 5 14:11:39.642: //140570/00B10D2AF426/CCAPI/ccConferenceDestroy:

Conference Id=0xD85E, Tag=0x0

Nov 5 14:11:39.642: //140570/00B10D2AF426/CCAPI/cc_api_bridge_drop_done:

Conference Id=0xD85E, Source Interface=0x3120854C, Source Call Id=140570,

Destination Call Id=140571, Disposition=0x0, Tag=0x0

Nov 5 14:11:39.642: //140571/00B10D2AF426/CCAPI/cc_api_bridge_drop_done:

Conference Id=0xD85E, Source Interface=0x315B7394, Source Call Id=140571,

Destination Call Id=140570, Disposition=0x0, Tag=0x0

Nov 5 14:11:39.642: //140570/00B10D2AF426/CCAPI/cc_generic_bridge_done:

Conference Id=0xD85E, Source Interface=0x315B7394, Source Call Id=140571,

Destination Call Id=140570, Disposition=0x0, Tag=0x0

Nov 5 14:11:39.642: //140571/00B10D2AF426/CCAPI/ccCallDisconnect:

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

Nov 5 14:11:39.642: //140571/00B10D2AF426/CCAPI/ccCallDisconnect:

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

Nov 5 14:11:39.642: //140571/00B10D2AF426/CCAPI/cc_api_get_transfer_info:

Transfer Number Is Null

Nov 5 14:11:39.774: //140571/00B10D2AF426/CCAPI/cc_api_call_disconnect_done:

Disposition=0, Interface=0x315B7394, Tag=0x0, Call Id=140571,

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

Nov 5 14:11:39.774: //140571/00B10D2AF426/CCAPI/cc_api_call_disconnect_done:

Call Disconnect Event Sent

Nov 5 14:11:39.774: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

Nov 5 14:11:39.774: :cc_free_feature_vsa freeing 3065A7C8

Nov 5 14:11:39.774: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

Nov 5 14:11:39.774: vsacount in free is 7

Nov 5 14:11:40.246: //140568/F2F421CA8564/CCAPI/cc_api_call_digit_begin:

Consume mask is not set. Relaying Digit 1 to dstCallId 0x22519

Nov 5 14:11:40.246: //140568/F2F421CA8564/CCAPI/cc_relay_digit_begin_for_3way_conference:

Check DTMF relay digit begin for 3way conf

Nov 5 14:11:40.338: //140568/F2F421CA8564/CCAPI/cc_api_call_digit_end:

Consume mask is not set. Relaying Digit 1 to dstCallId 0x22519

Nov 5 14:11:40.338: //140568/F2F421CA8564/CCAPI/cc_relay_digit_end_for_3way_conference:

Check DTMF relay digit end for 3way conf

Voice_GW_1#

Voice_GW_1#ter no

Nov 5 14:11:47.474: %ISDN-6-DISCONNECT: Interface Serial0/0/0:11 disconnected from 33671600 , call lasted 39 seconds

Nov 5 14:11:47.474: //140568/F2F421CA8564/CCAPI/cc_api_call_disconnected:

Cause Value=16, Interface=0x315B7394, Call Id=140568

Nov 5 14:11:47.474: //140568/F2F421CA8564/CCAPI/cc_api_call_disconnected:

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

Nov 5 14:11:47.478: //140568/F2F421CA8564/CCAPI/ccConferenceDestroy:

Conference Id=0xD85D, Tag=0x0

Nov 5 14:11:47.478: //140568/F2F421CA8564/CCAPI/cc_api_bridge_drop_done:

Conference Id=0xD85D, Source Interface=0x315B7394, Source Call Id=140568,

Destination Call Id=140569, Disposition=0x0, Tag=0x0

Nov 5 14:11:47.478: //140569/F2F421CA8564/CCAPI/cc_api_bridge_drop_done:

Conference Id=0xD85D, Source Interface=0x3120854C, Source Call Id=140569,

Destination Call Id=140568, Disposition=0x0, Tag=0x0

Nov 5 14:11:47.478: //140568/F2F421CA8564/CCAPI/cc_generic_bridge_done:

Conference Id=0xD85D, Source Interface=0x3120854C, Source Call Id=140569,

Destination Call Id=140568, Disposition=0x0, Tag=0x0

Nov 5 14:11:47.478: //140568/F2F421CA8564/CCAPI/ccCallDisconnect:

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

Nov 5 14:11:47.478: //140568/F2F421CA8564/CCAPI/ccCallDisconnect:

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

Voice_GW_1#

Nov 5 14:11:47.478: //140568/F2F421CA8564/CCAPI/cc_api_get_transfer_info:

Transfer Number Is Null

Nov 5 14:11:47.602: //140568/F2F421CA8564/CCAPI/cc_api_call_disconnect_done:

Disposition=0, Interface=0x315B7394, Tag=0x0, Call Id=140568,

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

Nov 5 14:11:47.602: //140568/F2F421CA8564/CCAPI/cc_api_call_disconnect_done:

Call Disconnect Event Sent

Nov 5 14:11:47.602: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

Nov 5 14:11:47.602: :cc_free_feature_vsa freeing 3065AB48

Nov 5 14:11:47.602: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

Nov 5 14:11:47.602: vsacount in free is 6

Nov 5 14:11:47.602: //140569/F2F421CA8564/CCAPI/ccCallDisconnect:

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

Nov 5 14:11:47.602: //140569/F2F421CA8564/CCAPI/ccCallDisconnect:

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

Nov 5 14:11:47.602: //140569/F2F421CA8564/CCAPI/cc_api_get_transfer_info:

Transfer Number Is Null

Nov 5 14:11:47.606: //140569/F2F421CA8564/CCAPI/cc_api_call_disconnect_done:

Disposition=0, Interface=0x3120854C, Tag=0x0, Call Id=140569,

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

Voice_GW_1#

Voice_GW_1#u all

All possible debugging has been turned off

Voice_GW_1#

Ayodeji Okanlawon · ‎11-06-2013

We need to know what the PSTN is sending to the gateway when the call is busy. ccapi debug wont tell us this.What we see on the voip leg is cause code 17--which is user busy. But it could be that the PSTN played a prompt or something to say that the other party has hung up...So I need the isdn q931 logs

Please rate all useful posts

"opportunity is a haughty goddess who waste no time with those who are unprepared"

Please rate all useful posts

acampbell · ‎11-06-2013

Bejoy,

Pleaae also see this old troubleshooting link:-

http://www.cisco.com/en/US/tech/tk652/tk653/technologies_tech_note09186a0080111b58.shtml#voipout

You can try this on your g/way global config

!

voice call send-alert

voice call convert-discpi-to-prog

voice rtp send-recv

!

Regards,
Alex.
Please rate useful posts.

Regards, Alex. Please rate useful posts.

Ayodeji Okanlawon · ‎11-06-2013

Alex,

While I agree that the above could possibly resolve the issue, I requested the debugs so we could have a clearer picture. We resolved a similar issue a few weeks ago in the thread beelow

https://supportforums.cisco.com/message/4076621#4076621

Please rate all useful posts

"opportunity is a haughty goddess who waste no time with those who are unprepared"

Please rate all useful posts

bejoy.cisco · ‎11-06-2013

Hi,

Here is the latest 'Debug ISDN q931'

Calling number 5004 (IP phone)

called number: 33512100 (Cell Phone)

Call action: call made from IP phone to mobile phone. when the mobile phone rang I press the cancel button on the mobile phone. The call ended on the mobile phone, but the IP phone still shows 'TO 33512100' and enters a long silence. I end the call on Ip phone by pressing the 'endcall' soft key.

=~=~=~=~=~=~=~=~=~=~=~= PuTTY log 2013.11.06 16:05:32 =~=~=~=~=~=~=~=~=~=~=~=

Voice_GW_2#

*Nov 6 13:06:39.724: //-1/004F49E50100/CCAPI/cc_api_display_ie_subfields:

cc_api_call_setup_ind_common:

cisco-username=IPT Helpdesk (TEMP)

----- ccCallInfo IE subfields -----

cisco-ani=5004

cisco-anitype=0

cisco-aniplan=0

cisco-anipi=0

cisco-anisi=1

dest=33512100

cisco-desttype=0

cisco-destplan=0

cisco-rdie=FFFFFFFF

cisco-rdn=

cisco-rdntype=-1

cisco-rdnplan=-1

cisco-rdnpi=-1

cisco-rdnsi=-1

cisco-redirectreason=-1 fwd_final_type =0

final_redirectNumber =

hunt_group_timeout =0

*Nov 6 13:06:39.724: //-1/004F49E50100/CCAPI/cc_api_call_setup_ind_common:

Interface=0x22857BE8, Call Info(

Calling Number=5004,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed),

Called Number=33512100(TON=Unknown, NPI=Unknown),

Calling Translated=FALSE, Subscriber Type Str=Unknown, FinalDestinationFlag=TRUE,

Incoming Dial-peer=100, Progress Indication=NULL(0), Calling IE Present=TRUE,

Source Trkgrp Route Label=, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=12059

*Nov 6 13:06:39.724: //-1/004F49E50100/CCAPI/ccCheckClipClir:

In: Calling Number=5004(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed)

*Nov 6 13:06:39.724: //-1/004F49E50100/CCAPI/ccCheckClipClir:

Out: Calling Number=5004(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed)

*Nov 6 13:06:39.724: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Nov 6 13:06:39.724: :cc_get_feature_vsa malloc success

*Nov 6 13:06:39.728: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Nov 6 13:06:39.728: cc_get_feature_vsa count is 1

*Nov 6 13:06:39.728: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Nov 6 13:06:39.728: :FEATURE_VSA attributes are: feature_name:0,feature_time:1024473568,feature_id:12047

*Nov 6 13:06:39.728: //12059/004F49E50100/CCAPI/cc_api_call_setup_ind_common:

Set Up Event Sent;

Call Info(Calling Number=5004(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed),

Called Number=33512100(TON=Unknown, NPI=Unknown))

*Nov 6 13:06:39.728: //12059/004F49E50100/CCAPI/cc_process_call_setup_ind:

Event=0x22CF86E0

*Nov 6 13:06:39.728: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_search:

Try with the demoted called number 33512100

*Nov 6 13:06:39.728: //12059/004F49E50100/CCAPI/ccCallSetContext:

Context=0x39FD8AA4

*Nov 6 13:06:39.728: //12059/004F49E50100/CCAPI/cc_process_call_setup_ind:

>>>>CCAPI handed cid 12059 with tag 100 to app "_ManagedAppProcess_num2name"

*Nov 6 13:06:39.728: //12059/004F49E50100/CCAPI/ccCallProceeding:

Progress Indication=NULL(0)

*Nov 6 13:06:39.732: //12059/004F49E50100/CCAPI/ccCallSetupRequest:

Destination=, Calling IE Present=TRUE, Mode=0,

Outgoing Dial-peer=1, Params=0x3D444844, Progress Indication=NULL(0)

*Nov 6 13:06:39.732: //12059/004F49E50100/CCAPI/ccCheckClipClir:

In: Calling Number=5004(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed)

*Nov 6 13:06:39.732: //12059/004F49E50100/CCAPI/ccCheckClipClir:

Out: Calling Number=5004(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed)

*Nov 6 13:06:39.732: //12059/004F49E50100/CCAPI/ccCallSetupRequest:

Destination Pattern=.T, Called Number=33512100, Digit Strip=TRUE

*Nov 6 13:06:39.732: //12059/004F49E50100/CCAPI/ccCallSetupRequest:

Calling Number=5004(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed),

Called Number=33512100(TON=Unknown, NPI=Unknown),

Redirect Number=, Display Info=Bejoy

Account Number=IPT Helpdesk (TEMP), Final Destination Flag=TRUE,

Guid=004F49E5-3F3E-A127-0100-9D03AC1F2383, Outgoing Dial-peer=1

*Nov 6 13:06:39.732: //12059/004F49E50100/CCAPI/cc_api_display_ie_subfields:

ccCallSetupRequest:

cisco-username=IPT Helpdesk (TEMP)

----- ccCallInfo IE subfields -----

cisco-ani=5004

cisco-anitype=0

cisco-aniplan=0

cisco-anipi=0

cisco-anisi=1

dest=33512100

cisco-desttype=0

cisco-destplan=0

cisco-rdie=74

cisco-rdn=

cisco-rdntype=-1

cisco-rdnplan=-1

cisco-rdnpi=-1

cisco-rdnsi=-1

cisco-redirectreason=-1 fwd_final_type =0

final_redirectNumber =

hunt_group_timeout =0

*Nov 6 13:06:39.732: //12059/004F49E50100/CCAPI/ccIFCallSetupRequestPrivate:

Interface=0x3D06F674, Interface Type=6, Destination=, Mode=0x0,

Call Params(Calling Number=5004,(Calling Name=5004)(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed),

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

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

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

*Nov 6 13:06:39.732: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Nov 6 13:06:39.732: :cc_get_feature_vsa malloc success

*Nov 6 13:06:39.732: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Nov 6 13:06:39.732: cc_get_feature_vsa count is 2

*Nov 6 13:06:39.732: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Nov 6 13:06:39.732: :FEATURE_VSA attributes are: feature_name:0,feature_time:1024475808,feature_id:12048

*Nov 6 13:06:39.732: //12060/004F49E50100/CCAPI/ccIFCallSetupRequestPrivate:

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

*Nov 6 13:06:39.732: //12060/004F49E50100/CCAPI/ccCallSetContext:

Context=0x3D4447F4

*Nov 6 13:06:39.732: //12059/004F49E50100/CCAPI/ccSaveDialpeerTag:

Outgoing Dial-peer=1

*Nov 6 13:06:39.732: ISDN Se0/0/0:15 Q931: Applying typeplan for sw-type 0x12 is 0x0 0x0, Calling num 5004

*Nov 6 13:06:39.736: ISDN Se0/0/0:15 Q931: Sending SETUP callref = 0x174B callID = 0x96CC switch = primary-net5 interface = User

*Nov 6 13:06:39.736: ISDN Se0/0/0:15 Q931: TX -> SETUP pd = 8 callref = 0x174B

Bearer Capability i = 0x9090A3

Standard = CCITT

Transfer Capability = 3.1kHz Audio

Transfer Mode = Circuit

Transfer Rate = 64 kbit/s

Channel ID i = 0xA9839E

Exclusive, Channel 30

Calling Party Number i = 0x0081, '5004'

Plan:Unknown, Type:Unknown

Called Party Number i = 0x80, '33512100'

Plan:Unknown, Type:Unknown

*Nov 6 13:06:39.776: ISDN Se0/0/0:15 Q931: RX <- SETUP_ACK pd = 8 callref = 0x974B

Channel ID i = 0xA9839E

Exclusive, Channel 30

*Nov 6 13:06:39.780: ISDN Se0/0/0:15 Q931: RX <- CALL_PROC pd = 8 callref = 0x974B

Progress Ind i = 0x8288 - In-band info or appropriate now available

*Nov 6 13:06:39.780: //12060/004F49E50100/CCAPI/cc_api_call_proceeding:

Interface=0x3D06F674, Progress Indication=INBAND(8)

*Nov 6 13:06:39.780: //12059/004F49E50100/CCAPI/ccCallCutProgress:

Progress Indication=INBAND(8), Signal Indication=INTERCEPT(2), Cause Value=0

Voice Call Send Alert=FALSE, Call Entry(Alert Sent=FALSE)

*Nov 6 13:06:39.780: //12059/004F49E50100/CCAPI/ccCallCutProgress:

Call Entry(Responsed=TRUE)

*Nov 6 13:06:39.780: //12060/004F49E50100/CCAPI/cc_api_get_called_ccm_detected:

CallInfo(ccm detected=0)

*Nov 6 13:06:39.780: //12059/004F49E50100/CCAPI/ccConferenceCreate:

(confID=0xFFFFFFFF, callID1=0x2F1B, gcid=0-0-0-0, tag=0x0)

*Nov 6 13:06:39.780: //12060/004F49E50100/CCAPI/ccConferenceCreate:

(confID=0xFFFFFFFF, callID2=0x2F1C, gcid=0-0-0-0, tag=0x0)

*Nov 6 13:06:39.780: //12059/004F49E50100/CCAPI/ccConferenceCreate:

Conference Id=0xFFFFFFFF, Call Id1=12059, Call Id2=12060, Tag=0x0

*Nov 6 13:06:39.780: //12059/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

*Nov 6 13:06:39.780: cc_api_get_xcode_stream : 4819

*Nov 6 13:06:39.780: //12059/004F49E50100/CCAPI/cc_api_bridge_done:

Conference Id=0x16BF, Source Interface=0x22857BE8, Source Call Id=12059,

Destination Call Id=12060, Disposition=0x0, Tag=0x0

*Nov 6 13:06:39.784: //12060/004F49E50100/CCAPI/cc_api_bridge_done:

Conference Id=0x16BF, Source Interface=0x3D06F674, Source Call Id=12060,

Destination Call Id=12059, Disposition=0x0, Tag=0xFFFFFFFF

*Nov 6 13:06:39.784: //12059/004F49E50100/CCAPI/cc_generic_bridge_done:

Conference Id=0x16BF, Source Interface=0x3D06F674, Source Call Id=12060,

Destination Call Id=12059, Disposition=0x0, Tag=0xFFFFFFFF

*Nov 6 13:06:39.784: //12059/004F49E50100/CCAPI/ccConferenceCreate:

Call Entry(Conference Id=0x16BF, Destination Call Id=12060)

*Nov 6 13:06:39.784: //12060/004F49E50100/CCAPI/ccConferenceCreate:

Call Entry(Conference Id=0x16BF, Destination Call Id=12059)

*Nov 6 13:06:39.784: //12059/004F49E50100/CCAPI/ccConferenceCreate:

*Nov 6 13:06:39.784: confID:0x16BF; callEntry1 callID1:0x2F1B, type:1; callEntry2 callID2:0x2F1C, type:6

*Nov 6 13:06:39.784: //12060/004F49E50100/CCAPI/cc_api_caps_ind:

Destination Interface=0x22857BE8, Destination Call Id=12059, Source Call Id=12060,

Caps(Codec=0x1, Fax Rate=0x1, Fax Version:=0, Vad=0x1,

Modem=0x2, Codec Bytes=20, Signal Type=3)

*Nov 6 13:06:39.784: //12060/004F49E50100/CCAPI/cc_api_caps_ind:

Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),

Playout Max=1000(ms), Fax Nom=300(ms))

*Nov 6 13:06:39.784: //12059/004F49E50100/CCAPI/ccCallNotify:

Data Bitmask=0x7, Call Id=12059

*Nov 6 13:06:39.784: //12060/004F49E50100/CCAPI/cc_api_get_called_ccm_detected:

CallInfo(ccm detected=0)

*Nov 6 13:06:39.784: //12059/004F49E50100/CCAPI/cc_process_notify_bridge_done:

Conference Id=0x16BF, Call Id1=12059, Call Id2=12060

*Nov 6 13:06:39.796: //12059/004F49E50100/CCAPI/cc_api_caps_ind:

Destination Interface=0x3D06F674, Destination Call Id=12060, Source Call Id=12059,

Caps(Codec=0x1, Fax Rate=0x1, Fax Version:=0, Vad=0x2,

Modem=0x2, Codec Bytes=160, Signal Type=2)

*Nov 6 13:06:39.796: //12059/004F49E50100/CCAPI/cc_api_caps_ind:

Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),

Playout Max=1000(ms), Fax Nom=300(ms))

*Nov 6 13:06:39.800: //12059/004F49E50100/CCAPI/cc_api_caps_ack:

Destination Interface=0x3D06F674, Destination Call Id=12060, Source Call Id=12059,

Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_NONE(0x1), Fax Version:=0, Vad=ON(0x2),

Modem=ON(0x2), Codec Bytes=160, Signal Type=2, Seq Num Start=9154)

*Nov 6 13:06:39.800: //12060/004F49E50100/CCAPI/cc_api_caps_ack:

Destination Interface=0x22857BE8, Destination Call Id=12059, Source Call Id=12060,

Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_NONE(0x1), Fax Version:=0, Vad=ON(0x2),

Modem=ON(0x2), Codec Bytes=160, Signal Type=2, Seq Num Start=9154)

*Nov 6 13:06:39.800: //12060/004F49E50100/CCAPI/cc_api_voice_mode_event:

Call Id=12060

*Nov 6 13:06:39.800: //12060/004F49E50100/CCAPI/cc_api_voice_mode_event:

Call Entry(Context=0x3D4447F4)

*Nov 6 13:06:44.116: ISDN Se0/0/0:15 Q931: RX <- ALERTING pd = 8 callref = 0x974B

Progress Ind i = 0x8281 - Call not end-to-end ISDN, may have in-band info

Progress Ind i = 0x8288 - In-band info or appropriate now available

*Nov 6 13:06:44.116: //12060/004F49E50100/CCAPI/cc_api_call_alert:

Interface=0x3D06F674, Progress Indication=NOT END TO END ISDN(1), Signal Indication=SIGNAL RINGBACK(1)

*Nov 6 13:06:44.116: //12060/004F49E50100/CCAPI/cc_api_call_alert:

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

*Nov 6 13:06:44.120: //12059/004F49E50100/CCAPI/ccCallAlert:

Progress Indication=NOT END TO END ISDN(1), Signal Indication=SIGNAL RINGBACK(1)

*Nov 6 13:06:44.120: //12059/004F49E50100/CCAPI/ccCallAlert:

Call Entry(Responsed=TRUE, Alert Sent=TRUE)

*Nov 6 13:06:44.120: //12060/004F49E50100/CCAPI/cc_api_get_called_ccm_detected:

CallInfo(ccm detected=0)

*Nov 6 13:06:44.120: //12059/004F49E50100/CCAPI/ccCallAlert:

Progress Indication=NULL(0), Signal Indication=SIGNAL RINGBACK(1)

*Nov 6 13:06:44.120: //12059/004F49E50100/CCAPI/ccCallAlert:

Call Entry(Responsed=TRUE, Alert Sent=TRUE)

*Nov 6 13:06:44.120: //12060/004F49E50100/CCAPI/cc_api_get_called_ccm_detected:

CallInfo(ccm detected=0)

*Nov 6 13:06:44.120: //12059/004F49E50100/CCAPI/cc_api_get_delay_xport:

CallInfo(delay xport=FALSE)

*Nov 6 13:06:44.120: //12059/004F49E50100/CCAPI/cc_api_get_delay_xport:

CallInfo(delay xport=FALSE)

*Nov 6 13:06:47.056: ISDN Se0/0/0:15 Q931: RX <- DISCONNECT pd = 8 callref = 0x974B

Cause i = 0x8091 - User busy

*Nov 6 13:06:47.056: ISDN Se0/0/0:15 Q931: TX -> RELEASE pd = 8 callref = 0x174B

*Nov 6 13:06:47.056: //12060/004F49E50100/CCAPI/cc_api_call_disconnected:

Cause Value=17, Interface=0x3D06F674, Call Id=12060

*Nov 6 13:06:47.056: //12060/004F49E50100/CCAPI/cc_api_call_disconnected:

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

*Nov 6 13:06:47.060: //12059/004F49E50100/CCAPI/ccCallReleaseResources:

release reserved xcoding resource.

*Nov 6 13:06:47.060: //12060/004F49E50100/CCAPI/ccCallSetAAA_Accounting:

Accounting=0, Call Id=12060

*Nov 6 13:06:47.060: //12059/004F49E50100/CCAPI/ccConferenceDestroy:

Conference Id=0x16BF, Tag=0x0

*Nov 6 13:06:47.060: //12059/004F49E50100/CCAPI/ccConferenceDestroy:

*Nov 6 13:06:47.060: confID:0x16BF; callEntry1 callID1:0x2F1B, type:1; callEntry2 callID2:0x2F1C, type:6

*Nov 6 13:06:47.060: //12059/004F49E50100/CCAPI/cc_api_bridge_drop_done:

Conference Id=0x16BF, Source Interface=0x22857BE8, Source Call Id=12059,

Destination Call Id=12060, Disposition=0x0, Tag=0x0

*Nov 6 13:06:47.060: //12060/004F49E50100/CCAPI/cc_api_bridge_drop_done:

Conference Id=0x16BF, Source Interface=0x3D06F674, Source Call Id=12060,

Destination Call Id=12059, Disposition=0x0, Tag=0x0

*Nov 6 13:06:47.060: //12059/004F49E50100/CCAPI/cc_generic_bridge_done:

Conference Id=0x16BF, Source Interface=0x3D06F674, Source Call Id=12060,

Destination Call Id=12059, Disposition=0x0, Tag=0x0

*Nov 6 13:06:47.060: //12060/004F49E50100/CCAPI/ccCallDisconnect:

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

*Nov 6 13:06:47.060: //12060/004F49E50100/CCAPI/ccCallDisconnect:

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

*Nov 6 13:06:47.060: //12060/004F49E50100/CCAPI/cc_api_get_transfer_info:

Transfer Number=NULL

*Nov 6 13:06:47.176: ISDN Se0/0/0:15 Q931: RX <- RELEASE_COMP pd = 8 callref = 0x974B

*Nov 6 13:06:47.176: //12060/004F49E50100/CCAPI/cc_api_call_disconnect_done:

Disposition=0, Interface=0x3D06F674, Tag=0x0, Call Id=12060,

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

*Nov 6 13:06:47.176: //12060/004F49E50100/CCAPI/cc_api_call_disconnect_done:

Call Disconnect Event Sent

*Nov 6 13:06:47.176: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Nov 6 13:06:47.180: :cc_free_feature_vsa freeing 3D104298

*Nov 6 13:06:47.180: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Nov 6 13:06:47.180: vsacount in free is 1

Voice_GW_2#

*Nov 6 13:06:56.080: //12059/004F49E50100/CCAPI/cc_api_call_disconnected:

Cause Value=16, Interface=0x22857BE8, Call Id=12059

*Nov 6 13:06:56.080: //12059/004F49E50100/CCAPI/cc_api_call_disconnected:

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

*Nov 6 13:06:56.080: //12059/004F49E50100/CCAPI/ccCallDisconnect:

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

*Nov 6 13:06:56.080: //12059/004F49E50100/CCAPI/ccCallDisconnect:

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

*Nov 6 13:06:56.080: //12059/004F49E50100/CCAPI/cc_api_get_transfer_info:

Transfer Number=NULL

*Nov 6 13:06:56.084: //12059/004F49E50100/CCAPI/cc_api_call_disconnect_done:

Disposition=0, Interface=0x22857BE8, Tag=0x0, Call Id=12059,

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

*Nov 6 13:06:56.084: //12059/004F49E50100/CCAPI/cc_api_call_disconnect_done:

Call Disconnect Event Sent

*Nov 6 13:06:56.084: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Nov 6 13:06:56.084: :cc_free_feature_vsa freeing 3D1039D8

*Nov 6 13:06:56.084: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Nov 6 13:06:56.084: vsacount in free is 0

Voice_GW_2#

bejoy.cisco · ‎11-06-2013

Hi Alex,

I tried the commands, but no luck

Ayodeji Okanlawon · ‎11-06-2013

From the logs, it is clear why that commadn will not help because there is no PI in the disconnect.

The gateway received the proper disconect from the PSTN..

Nov 6 13:06:47.056: ISDN Se0/0/0:15 Q931: RX <- DISCONNECT pd = 8 callref = 0x974B

Cause i = 0x8091 - User busy

*Nov 6 13:06:47.056: ISDN Se0/0/0:15 Q931: TX -> RELEASE pd = 8 callref = 0x174B

*Nov 6 13:06:47.056: //12060/004F49E50100/CCAPI/cc_api_call_disconnected:

Cause Value=17, Interface=0x3D06F674, Call Id=12060.

+++++

We can also see that the call disconnect was sent immediately..

Nov 6 13:06:47.176: //12060/004F49E50100/CCAPI/cc_api_call_disconnect_done:

Call Disconnect Event Sent

++++

So evrything looks okay on the gateway side. We will need to look at the CUCM logs to see whats going on and why CUCM is not telling the phone to hang up the call immediately. Can you please send us the detailed cucm traces.

Please rate all useful posts

"opportunity is a haughty goddess who waste no time with those who are unprepared"

Please rate all useful posts