Debug output is below. I'm matching dial-peer 3001 which is what I would expect (incoming called-number taking priority over destination-pattern). I posted the new ISR config in a previous post.
=~=~=~=~=~=~=~=~=~=~=~= PuTTY log 2010.10.05 10:20:33 =~=~=~=~=~=~=~=~=~=~=~=
sh logg
Syslog logging: enabled (0 messages dropped, 3 messages rate-limited,
0 flushes, 0 overruns, xml disabled, filtering disabled)
No Active Message Discriminator.
No Inactive Message Discriminator.
Console logging: disabled
Monitor logging: disabled
Buffer logging: level debugging, 504 messages logged, xml disabled,
filtering disabled
Logging Exception size (4096 bytes)
Count and timestamp logging messages: disabled
Persistent logging: disabled
Trap logging: level informational, 58 message lines logged
Log Buffer (10000000 bytes):
000054: Oct 5 10:18:52.683: //-1/xxxxxxxxxxxx/H323/cch323_timer_dispatch: Timer[CCH323_RAS_PERIODIC_RRQ_TIMER] expired
000055: Oct 5 10:18:52.683: //-1/xxxxxxxxxxxx/H323/cch323_send_event_to_ras: Queued event CCH323_RAS_EVENT_SEND_LT_RRQ to RAS Global SM
000056: Oct 5 10:18:52.683: //-1/xxxxxxxxxxxx/H323/cch323_iev_queue_service: Dispatch 0xA internal event to RAS Global SM
000057: Oct 5 10:18:52.683: //-1/xxxxxxxxxxxx/H323/cch323_run_ras_sm: received event CCH323_RAS_EVENT_SEND_LT_RRQ while at CCH323_RAS_STATE_IDLE state
000058: Oct 5 10:18:52.683: RAS OUTGOING PDU ::=
value RasMessage ::= registrationRequest :
{
requestSeqNum 1262
protocolIdentifier { 0 0 8 2250 0 4 }
discoveryComplete TRUE
callSignalAddress
{
}
rasAddress
{
ipAddress :
{
ip '06060607'H
port 63383
}
}
terminalType
{
mc FALSE
undefinedNode FALSE
}
gatekeeperIdentifier {"ZONE_01"}
endpointVendor
{
vendor
{
t35CountryCode 181
t35Extension 0
manufacturerCode 18
}
}
timeToLive 60
keepAlive TRUE
endpointIdentifier {"672C9F6C00000001"}
willSupplyUUIEs FALSE
maintainConnection TRUE
}
000059: Oct 5 10:18:52.687: RAS OUTGOING ENCODE BUFFER::= 0E4004ED060008914A00048000010006060607F7970006005A004F004E0045005F0030003100B5000012288F000002003B0180211E003600370032004300390046003600430030003000300030003000300030003101000180
000060: Oct 5 10:18:52.687:
000061: Oct 5 10:18:52.687: //-1/xxxxxxxxxxxx/H323/cch323_run_ras_sm: changing to CCH323_RAS_STATE_RRQ state
000062: Oct 5 10:18:52.751: //-1/xxxxxxxxxxxx/H323/cch323_ct_main: SOCK 2 Event 0x1
000063: Oct 5 10:18:52.751: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: owner_data=0x49D57F60, len=70, msgPtr=0x49D566E8
000064: Oct 5 10:18:52.751: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: Received msg for RAS
000065: Oct 5 10:18:52.751: RAS INCOMING ENCODE BUFFER::= 124004ED060008914A0004000C005A004F004E0045005F003000311E0036003700320043003900460036004300300030003000300030003000300031208A0002003B01000180
000066: Oct 5 10:18:52.751:
000067: Oct 5 10:18:52.751: RAS INCOMING PDU ::=
value RasMessage ::= registrationConfirm :
{
requestSeqNum 1262
protocolIdentifier { 0 0 8 2250 0 4 }
callSignalAddress
{
}
gatekeeperIdentifier {"ZONE_01"}
endpointIdentifier {"672C9F6C00000001"}
timeToLive 60
willRespondToIRR FALSE
maintainConnection TRUE
}
000068: Oct 5 10:18:52.755: //-1/xxxxxxxxxxxx/H323/cch323_ras_handle_recv_msg: received msg of type RCF_CHOSEN
000069: Oct 5 10:18:52.755: //-1/xxxxxxxxxxxx/H323/cch323_run_ras_sm: received event CCH323_RAS_EVENT_RCF while at CCH323_RAS_STATE_RRQ state
000070: Oct 5 10:18:52.755: //-1/xxxxxxxxxxxx/H323/cch323_run_ras_sm: changing to CCH323_RAS_STATE_IDLE state
000071: Oct 5 10:19:37.755: //-1/xxxxxxxxxxxx/H323/cch323_timer_dispatch: Timer[CCH323_RAS_PERIODIC_RRQ_TIMER] expired
000072: Oct 5 10:19:37.755: //-1/xxxxxxxxxxxx/H323/cch323_send_event_to_ras: Queued event CCH323_RAS_EVENT_SEND_LT_RRQ to RAS Global SM
000073: Oct 5 10:19:37.755: //-1/xxxxxxxxxxxx/H323/cch323_iev_queue_service: Dispatch 0xA internal event to RAS Global SM
000074: Oct 5 10:19:37.755: //-1/xxxxxxxxxxxx/H323/cch323_run_ras_sm: received event CCH323_RAS_EVENT_SEND_LT_RRQ while at CCH323_RAS_STATE_IDLE state
000075: Oct 5 10:19:37.755: RAS OUTGOING PDU ::=
value RasMessage ::= registrationRequest :
{
requestSeqNum 1263
protocolIdentifier { 0 0 8 2250 0 4 }
discoveryComplete TRUE
callSignalAddress
{
}
rasAddress
{
ipAddress :
{
ip '06060607'H
port 63383
}
}
terminalType
{
mc FALSE
undefinedNode FALSE
}
gatekeeperIdentifier {"ZONE_01"}
endpointVendor
{
vendor
{
t35CountryCode 181
t35Extension 0
manufacturerCode 18
}
}
timeToLive 60
keepAlive TRUE
endpointIdentifier {"672C9F6C00000001"}
willSupplyUUIEs FALSE
maintainConnection TRUE
}
000076: Oct 5 10:19:37.759: RAS OUTGOING ENCODE BUFFER::= 0E4004EE060008914A00048000010006060607F7970006005A004F004E0045005F0030003100B5000012288F000002003B0180211E003600370032004300390046003600430030003000300030003000300030003101000180
000077: Oct 5 10:19:37.759:
000078: Oct 5 10:19:37.759: //-1/xxxxxxxxxxxx/H323/cch323_run_ras_sm: changing to CCH323_RAS_STATE_RRQ state
000079: Oct 5 10:19:37.819: //-1/xxxxxxxxxxxx/H323/cch323_ct_main: SOCK 2 Event 0x1
000080: Oct 5 10:19:37.819: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: owner_data=0x49D57F60, len=70, msgPtr=0x49D568B8
000081: Oct 5 10:19:37.819: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: Received msg for RAS
000082: Oct 5 10:19:37.819: RAS INCOMING ENCODE BUFFER::= 124004EE060008914A0004000C005A004F004E0045005F003000311E0036003700320043003900460036004300300030003000300030003000300031208A0002003B01000180
000083: Oct 5 10:19:37.819:
000084: Oct 5 10:19:37.819: RAS INCOMING PDU ::=
value RasMessage ::= registrationConfirm :
{
requestSeqNum 1263
protocolIdentifier { 0 0 8 2250 0 4 }
callSignalAddress
{
}
gatekeeperIdentifier {"ZONE_01"}
endpointIdentifier {"672C9F6C00000001"}
timeToLive 60
willRespondToIRR FALSE
maintainConnection TRUE
}
000085: Oct 5 10:19:37.819: //-1/xxxxxxxxxxxx/H323/cch323_ras_handle_recv_msg: received msg of type RCF_CHOSEN
000086: Oct 5 10:19:37.819: //-1/xxxxxxxxxxxx/H323/cch323_run_ras_sm: received event CCH323_RAS_EVENT_RCF while at CCH323_RAS_STATE_RRQ state
000087: Oct 5 10:19:37.819: //-1/xxxxxxxxxxxx/H323/cch323_run_ras_sm: changing to CCH323_RAS_STATE_IDLE state
000088: Oct 5 10:19:56.112: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
INVITE sip:3001@6.6.6.7:5060 SIP/2.0
Date: Tue, 05 Oct 2010 14:19:55 GMT
Call-Info: <10.1.200.20:5060>;method="NOTIFY;Event=telephone-event;Duration=500"10.1.200.20:5060>
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
From: <1001>;tag=672f0396-d595-4a92-b33d-446800d37753-277724971001>
Allow-Events: presence, kpml
P-Asserted-Identity: <1001>1001>
Supported: timer,resource-priority,replaces
Supported: Geolocation
Min-SE: 1800
Remote-Party-ID: <1001>;party=calling;screen=yes;privacy=off1001>
Content-Length: 0
User-Agent: Cisco-CUCM7.1
To: <3001>3001>
Contact: <1001>1001>
Expires: 180
Call-ID: 9ee9bd00-cab1340b-1d-14c8010a@10.1.200.20
Via: SIP/2.0/TCP 10.1.200.20:5060;branch=z9hG4bK2423dd8b96
CSeq: 101 INVITE
Session-Expires: 1800
Max-Forwards: 70
000089: Oct 5 10:19:56.120: //-1/7661A559800A/CCAPI/cc_api_display_ie_subfields:
cc_api_call_setup_ind_common:
cisco-username=1001
----- ccCallInfo IE subfields -----
cisco-ani=1001
cisco-anitype=0
cisco-aniplan=0
cisco-anipi=0
cisco-anisi=1
dest=3001
cisco-desttype=0
cisco-destplan=0
cisco-rdie=FFFFFFFF
cisco-rdn=
cisco-lastrdn=
cisco-rdntype=0
cisco-rdnplan=0
cisco-rdnpi=-1
cisco-rdnsi=-1
cisco-redirectreason=-1 fwd_final_type =0
final_redirectNumber =
hunt_group_timeout =0
000090: Oct 5 10:19:56.124: //-1/7661A559800A/CCAPI/cc_api_call_setup_ind_common:
Interface=0x4705BD7C, Call Info(
Calling Number=1001,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed),
Called Number=3001(TON=Unknown, NPI=Unknown),
Calling Translated=FALSE, Subscriber Type Str=Unknown, FinalDestinationFlag=TRUE,
Incoming Dial-peer=3001, Progress Indication=NULL(0), Calling IE Present=TRUE,
Source Trkgrp Route Label=, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=9
000091: Oct 5 10:19:56.124: //-1/7661A559800A/CCAPI/ccCheckClipClir:
In: Calling Number=1001(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed)
000092: Oct 5 10:19:56.124: //-1/7661A559800A/CCAPI/ccCheckClipClir:
Out: Calling Number=1001(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed)
000093: Oct 5 10:19:56.124: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
000094: Oct 5 10:19:56.124: :cc_get_feature_vsa malloc success
000095: Oct 5 10:19:56.124: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
000096: Oct 5 10:19:56.124: cc_get_feature_vsa count is 1
000097: Oct 5 10:19:56.124: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
000098: Oct 5 10:19:56.124: :FEATURE_VSA attributes are: feature_name:0,feature_time:1239945304,feature_id:9
000099: Oct 5 10:19:56.124: //9/7661A559800A/CCAPI/cc_api_call_setup_ind_common:
Set Up Event Sent;
Call Info(Calling Number=1001(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed),
Called Number=3001(TON=Unknown, NPI=Unknown))
000100: Oct 5 10:19:56.128: //9/7661A559800A/CCAPI/cc_process_call_setup_ind:
Event=0x472D5190
000101: Oct 5 10:19:56.128: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_search:
Try with the demoted called number 3001
000102: Oct 5 10:19:56.132: //9/7661A559800A/CCAPI/ccCallSetContext:
Context=0x464789A4
000103: Oct 5 10:19:56.132: //9/7661A559800A/CCAPI/cc_process_call_setup_ind:
>>>>CCAPI handed cid 9 with tag 3001 to app "_ManagedAppProcess_Default"
000104: Oct 5 10:19:56.132: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 100 Trying
Via: SIP/2.0/TCP 10.1.200.20:5060;branch=z9hG4bK2423dd8b96
From: <1001>;tag=672f0396-d595-4a92-b33d-446800d37753-277724971001>
To: <3001>3001>
Date: Tue, 05 Oct 2010 14:19:56 GMT
Call-ID: 9ee9bd00-cab1340b-1d-14c8010a@10.1.200.20
CSeq: 101 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-12.x
Content-Length: 0
000105: Oct 5 10:19:56.136: //9/7661A559800A/CCAPI/ccCallProceeding:
Progress Indication=NULL(0)
000106: Oct 5 10:19:56.136: //9/7661A559800A/CCAPI/ccCallSetupRequest:
Destination=, Calling IE Present=TRUE, Mode=0,
Outgoing Dial-peer=3000, Params=0x46479CFC, Progress Indication=NULL(0)
000107: Oct 5 10:19:56.140: //9/7661A559800A/CCAPI/ccCheckClipClir:
In: Calling Number=1001(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed)
000108: Oct 5 10:19:56.140: //9/7661A559800A/CCAPI/ccCheckClipClir:
Out: Calling Number=1001(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed)
000109: Oct 5 10:19:56.140: //9/7661A559800A/CCAPI/ccCallSetupRequest:
Destination Pattern=3..., Called Number=3001, Digit Strip=FALSE
000110: Oct 5 10:19:56.140: //9/7661A559800A/CCAPI/ccCallSetupRequest:
Calling Number=1001(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed),
Called Number=3001(TON=Unknown, NPI=Unknown),
Redirect Number=, Display Info=
Account Number=1001, Final Destination Flag=TRUE,
Guid=7661A559-CFC2-11DF-800A-B8130721089B, Outgoing Dial-peer=3000
000111: Oct 5 10:19:56.140: //9/7661A559800A/CCAPI/cc_api_display_ie_subfields:
ccCallSetupRequest:
cisco-username=1001
----- ccCallInfo IE subfields -----
cisco-ani=1001
cisco-anitype=0
cisco-aniplan=0
cisco-anipi=0
cisco-anisi=1
dest=3001
cisco-desttype=0
cisco-destplan=0
cisco-rdie=FFFFFFFF
cisco-rdn=
cisco-lastrdn=
cisco-rdntype=0
cisco-rdnplan=0
cisco-rdnpi=-1
cisco-rdnsi=-1
cisco-redirectreason=-1 fwd_final_type =0
final_redirectNumber =
hunt_group_timeout =0
000112: Oct 5 10:19:56.140: //9/7661A559800A/CCAPI/ccIFCallSetupRequestPrivate:
Interface=0x478B1418, Interface Type=1, Destination=, Mode=0x0,
Call Params(Calling Number=1001,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed),
Called Number=3001(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,
Subscriber Type Str=Unknown, FinalDestinationFlag=TRUE, Outgoing Dial-peer=3000, Call Count On=FALSE,
Source Trkgrp Route Label=, Target Trkgrp Route Label=, tg_label_flag=0, Application Call Id=)
000113: Oct 5 10:19:56.140: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
000114: Oct 5 10:19:56.140: :cc_get_feature_vsa malloc success
000115: Oct 5 10:19:56.140: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
000116: Oct 5 10:19:56.140: cc_get_feature_vsa count is 2
000117: Oct 5 10:19:56.140: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
000118: Oct 5 10:19:56.140: :FEATURE_VSA attributes are: feature_name:0,feature_time:1239945080,feature_id:10
000119: Oct 5 10:19:56.140: //-1/xxxxxxxxxxxx/H323/cch323_post_call_setup_request: callID=10
000120: Oct 5 10:19:56.140: //-1/xxxxxxxxxxxx/H323/cch323_post_call_setup_request: incoming_call=0 incoming_media=0
000121: Oct 5 10:19:56.140: //-1/xxxxxxxxxxxx/H323/cch323_post_call_setup_request: incoming_call=0 incoming_media=0
000122: Oct 5 10:19:56.140: //10/7661A559800A/CCAPI/ccIFCallSetupRequestPrivate:
SPI Call Setup Request Is Success; Interface Type=1, FlowMode=1
000123: Oct 5 10:19:56.144: //10/7661A559800A/CCAPI/ccCallSetContext:
Context=0x46479CAC
000124: Oct 5 10:19:56.144: //9/7661A559800A/CCAPI/ccSaveDialpeerTag:
Outgoing Dial-peer=3000
000125: Oct 5 10:19:56.144: //-1/xxxxxxxxxxxx/H323/cch323_get_new_ccb: ccb (0x49F6FE00) is in use
000126: Oct 5 10:19:56.144: //10/7661A559800A/H323/cch323_call_setup: gw_id=1
000127: Oct 5 10:19:56.144: //-1/xxxxxxxxxxxx/H323/h323_TD_get_mlpp_info: callID=10, tag=(CC_TAG_MLPP_INFO), Failed AV get
000128: Oct 5 10:19:56.144: //10/7661A559800A/H323/cch323_call_setup: Inserted ccb
000129: Oct 5 10:19:56.144: //-1/xxxxxxxxxxxx/H323/cch323_create_call_info_type_container:
cch323_create_call_info_type_container: creating callInfoType container for callID = 10
000130: Oct 5 10:19:56.144: //10/7661A559800A/H323/cch323_set_h245_state_mc_mode_outgoing: call_spi_mode = 3
000131: Oct 5 10:19:56.144: //10/7661A559800A/H323/cch323_set_h245_state_mc_mode_outgoing: h245 state m/c mode=0x4F0, h323_ctl=0x0
000132: Oct 5 10:19:56.144: //10/7661A559800A/H323/cch323_get_peer_info: Entry
000133: Oct 5 10:19:56.144: //10/7661A559800A/H323/cch323_get_peer_info: Have peer
000134: Oct 5 10:19:56.144: //10/7661A559800A/H323/cch323_get_peer_info: faxrate[45] proto[3] bitmask[10082] t38_inhibit[0] global_fax[0] t38fax[0]
000135: Oct 5 10:19:56.144: //10/7661A559800A/H323/cch323_set_pref_codec_list: First preferred codec(bytes)=16(20)
000136: Oct 5 10:19:56.144: //10/7661A559800A/H323/cch323_get_peer_info: Preferred codec set to G729IETF with Bytes = 20
000137: Oct 5 10:19:56.144: //10/7661A559800A/H323/cch323_get_peer_info: Flow Mode set to FLOW_THROUGH
000138: Oct 5 10:19:56.144: //10/7661A559800A/H323/cch323_get_peer_info: peer: 48B19904, peer->voice_peer_tag: BB8, ccb: 49F6FE00
000139: Oct 5 10:19:56.144: //10/7661A559800A/H323/cch323_set_h323_parms_from_dp: ccb h245addr bits = system[0x0007]
000140: Oct 5 10:19:56.148: //10/7661A559800A/H323/cch323_set_h323_parms_from_dp: ccb ccm bits = system[0x0028]
000141: Oct 5 10:19:56.148: //10/7661A559800A/H323/cch323_update_setup_callinfo: callingNumber = 1001
000142: Oct 5 10:19:56.148: //10/7661A559800A/H323/cch323_update_setup_callinfo: called_oct3 = 0x0, calling_oct3 = 0x0, calling_oct3a = 0x81
000143: Oct 5 10:19:56.148: //10/7661A559800A/H323/cch323_set_h323_control_options_outgoing: h245 sm mode = 1264
000144: Oct 5 10:19:56.148: //10/7661A559800A/H323/cch323_set_h323_control_options_outgoing: h323_ctl=0x20
000145: Oct 5 10:19:56.148: //10/7661A559800A/H323/cch323_call_setup: No account/pin number available
000146: Oct 5 10:19:56.148: //10/7661A559800A/H323/cch323_store_call_info: Call_setup Playout Mode: 1,Init 60, Min 40, Max 1000, Fax 300
000147: Oct 5 10:19:56.148: //10/7661A559800A/H323/cch323_call_setup_normal: Entry
000148: Oct 5 10:19:56.148: //10/7661A559800A/H323/cch323_call_setup_normal: SETUP_NTF_TIMER is not running. Continue processing.
000149: Oct 5 10:19:56.148: //10/7661A559800A/H323/cch323_h225_set_new_state: Changing from H225_IDLE state to H225_IDLE state
000150: Oct 5 10:19:56.148: //10/7661A559800A/H323/cch323_store_call_info: Call_setup Playout Mode: 1,Init 60, Min 40, Max 1000, Fax 300
000151: Oct 5 10:19:56.212: //-1/xxxxxxxxxxxx/H323/cch323_ct_main: SOCK 3 Event 0x1
000152: Oct 5 10:19:56.212: //-1/xxxxxxxxxxxx/H323/cch323_iev_queue_service: Dispatch 0xB internal event to H225 SM
000153: Oct 5 10:19:56.212: //10/7661A559800A/H323/run_h225_sm: Received event H225_EV_SETUP while at state H225_IDLE
000154: Oct 5 10:19:56.212: //10/7661A559800A/H323/check_qos_and_send_setup: Setup ccb 0x49F6FE00
000155: Oct 5 10:19:56.212: //10/7661A559800A/H323/cch323_rotary_validate: No peer_ccb available
000156: Oct 5 10:19:56.212: //10/7661A559800A/H323/send_setup: Entry
000157: Oct 5 10:19:56.212: //10/7661A559800A/H323/generic_send_setup: Entry
000158: Oct 5 10:19:56.212: //10/7661A559800A/H323/copy_token_from_ccb: copy_token_from_ccb: Entered
000159: Oct 5 10:19:56.212: //10/7661A559800A/H323/generic_send_setup:
generic_send_setup: is_overlap = 0, info_complete = 0
000160: Oct 5 10:19:56.212: //10/7661A559800A/H323/generic_send_setup: sending calling IE
000161: Oct 5 10:19:56.212: //10/7661A559800A/H323/cch323_get_embedded_obj_from_ccb: ccb=0x49F6FE00, tag=24, size=88
000162: Oct 5 10:19:56.212: //10/7661A559800A/H323/cch323_get_embedded_obj_from_ccb: Extraction FAILED
000163: Oct 5 10:19:56.212: //10/7661A559800A/H323/generic_send_setup: ====== PI = 0
000164: Oct 5 10:19:56.212: //10/7661A559800A/H323/generic_send_setup: Send infoXCap=128, infoXRate=16, rateMult=0, xMode=128, info_layer1_prot=163
000165: Oct 5 10:19:56.212: //10/7661A559800A/H323/generic_send_setup: src address = 6.6.6.7; dest address = 3.3.3.3
000166: Oct 5 10:19:56.212: H225.0 OUTGOING PDU ::=
value H323_UserInformation ::=
{
h323-uu-pdu
{
h323-message-body setup :
{
protocolIdentifier { 0 0 8 2250 0 4 }
sourceInfo
{
vendor
{
vendor
{
t35CountryCode 181
t35Extension 0
manufacturerCode 18
}
productId '436973636F47617465776179'H
versionId '32'H
}
gateway
{
protocol
{
voice :
{
supportedPrefixes
{
}
}, h323 :
{
supportedPrefixes
{
}
}
}
}
mc FALSE
undefinedNode FALSE
}
activeMC FALSE
conferenceID '7661A559CFC211DF800AB8130721089B'H
conferenceGoal create : NULL
callType pointToPoint : NULL
sourceCallSignalAddress ipAddress :
{
ip '06060607'H
port 38972
}
callIdentifier
{
guid '7662DDA9CFC211DF800CB8130721089B'H
}
mediaWaitForConnect FALSE
canOverlapSend FALSE
multipleCalls TRUE
maintainConnection TRUE
}
h245Tunneling FALSE
}
}
000167: Oct 5 10:19:56.220: H225.0 OUTGOING ENCODE BUFFER::= 2080060008914A000428C0B50000120B436973636F47617465776179003240023C0501002C050100007661A559CFC211DF800AB8130721089B00CD0D8000070006060607983C11007662DDA9CFC211DF800CB8130721089B010001000180018010800100
000168: Oct 5 10:19:56.220:
000169: Oct 5 10:19:56.224: //10/7661A559800A/H323/cch323_h225_set_new_state: Changing from H225_IDLE state to H225_SETUP state
000170: Oct 5 10:19:56.224: //-1/xxxxxxxxxxxx/H323/cch323_ct_main: SOCK 3 Event 0x1
000171: Oct 5 10:19:56.476: //-1/xxxxxxxxxxxx/H323/cch323_ct_main: SOCK 3 Event 0x1
000172: Oct 5 10:19:56.476: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: owner_data=0x49D55E4C, len=68, msgPtr=0x49D8C710
000173: Oct 5 10:19:56.476: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: Received msg for H.225
000174: Oct 5 10:19:56.476: H225.0 INCOMING ENCODE BUFFER::= 21C0060008914A00042800B500001240013C05040100204000030303038152110C11007662DDA9CFC211DF800CB8130721089B0180018010800100
000175: Oct 5 10:19:56.476:
000176: Oct 5 10:19:56.476: H225.0 INCOMING PDU ::=
value H323_UserInformation ::=
{
h323-uu-pdu
{
h323-message-body callProceeding :
{
protocolIdentifier { 0 0 8 2250 0 4 }
destinationInfo
{
vendor
{
vendor
{
t35CountryCode 181
t35Extension 0
manufacturerCode 18
}
}
gateway
{
protocol
{
voice :
{
supportedPrefixes
{
{
prefix dialedDigits : "1#"
}
}
}
}
}
mc FALSE
undefinedNode FALSE
}
h245Address ipAddress :
{
ip '03030303'H
port 33106
}
callIdentifier
{
guid '7662DDA9CFC211DF800CB8130721089B'H
}
multipleCalls TRUE
maintainConnection TRUE
}
h245Tunneling FALSE
}
}
000177: Oct 5 10:19:56.484: //-1/xxxxxxxxxxxx/H323/cch323_h225_receiver: Received msg of type CALLPROCIND_CHOSEN
000178: Oct 5 10:19:56.484: //10/7661A559800A/H323/callproc_ind: Entry
000179: Oct 5 10:19:56.484: //10/7661A559800A/H323/callproc_ind: ====== PI = 0
000180: Oct 5 10:19:56.484: //10/7661A559800A/H323/cch323_h225_receiver: CALLPROCIND_CHOSEN: src address = 6.6.6.7; dest address = 3.3.3.3
000181: Oct 5 10:19:56.484: //10/7661A559800A/H323/run_h225_sm: Received event H225_EV_CALLPROC_IND while at state H225_SETUP
000182: Oct 5 10:19:56.484: //10/7661A559800A/H323/h245_address_ind: ev=0
000183: Oct 5 10:19:56.484: //10/7661A559800A/CCAPI/ccIsInfoRingback:
Returning dpRingBack=0
000184: Oct 5 10:19:56.484: //10/7661A559800A/H323/callproc_notify: Peer not ready so not starting TCP
000185: Oct 5 10:19:56.484: //10/7661A559800A/H323/generic_callproc_notify: Entry
000186: Oct 5 10:19:56.484: //10/7661A559800A/CCAPI/cc_api_call_proceeding:
Interface=0x478B1418, Progress Indication=NULL(0)
000187: Oct 5 10:19:56.484: //10/7661A559800A/H323/cch323_h225_set_new_state: Changing from H225_SETUP state to H225_CALLPROC state
000188: Oct 5 10:19:56.836: //-1/xxxxxxxxxxxx/H323/cch323_ct_main: SOCK 3 Event 0x1
000189: Oct 5 10:19:56.836: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: owner_data=0x49D55E4C, len=74, msgPtr=0x49D55C08
000190: Oct 5 10:19:56.836: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: Received msg for H.225
000191: Oct 5 10:19:56.836: H225.0 INCOMING ENCODE BUFFER::= 23C0060008914A00042800B500001240013C050401002040000303030381521B0C0011007662DDA9CFC211DF800CB8130721089B0180018010800100
000192: Oct 5 10:19:56.836:
000193: Oct 5 10:19:56.836: H225.0 INCOMING PDU ::=
value H323_UserInformation ::=
{
h323-uu-pdu
{
h323-message-body alerting :
{
protocolIdentifier { 0 0 8 2250 0 4 }
destinationInfo
{
vendor
{
vendor
{
t35CountryCode 181
t35Extension 0
manufacturerCode 18
}
}
gateway
{
protocol
{
voice :
{
supportedPrefixes
{
{
prefix dialedDigits : "1#"
}
}
}
}
}
mc FALSE
undefinedNode FALSE
}
h245Address ipAddress :
{
ip '03030303'H
port 33106
}
callIdentifier
{
guid '7662DDA9CFC211DF800CB8130721089B'H
}
multipleCalls TRUE
maintainConnection TRUE
}
h245Tunneling FALSE
}
}
000194: Oct 5 10:19:56.840: //-1/xxxxxxxxxxxx/H323/cch323_h225_receiver: Received msg of type ALERTIND_CHOSEN
000195: Oct 5 10:19:56.844: //10/7661A559800A/H323/alert_ind: ====== PI = 0
000196: Oct 5 10:19:56.844: //10/7661A559800A/H323/alert_ind: alert ind ie_bit_mask 0x5E60, displayInfo
000197: Oct 5 10:19:56.844: //10/7661A559800A/H323/alert_ind: Rcvd ALERT Display Info IE =
000198: Oct 5 10:19:56.844: //10/7661A559800A/H323/cch323_put_embedded_obj_to_ccb: ccb=0x49F6FE00, tag=17, size=83
000199: Oct 5 10:19:56.844: //10/7661A559800A/H323/cch323_put_embedded_obj_to_ccb: Insertion PASSED, embedded at 0x49F72638
000200: Oct 5 10:19:56.844: //10/7661A559800A/H323/cch323_h225_receiver: ALERTIND_CHOSEN: src address = 6.6.6.7; dest address = 3.3.3.3
000201: Oct 5 10:19:56.844: //10/7661A559800A/H323/run_h225_sm: Received event H225_EV_ALERT_IND while at state H225_CALLPROC
000202: Oct 5 10:19:56.844: //10/7661A559800A/H323/h245_address_ind: ev=0
000203: Oct 5 10:19:56.844: //10/7661A559800A/CCAPI/ccIsInfoRingback:
Returning dpRingBack=0
000204: Oct 5 10:19:56.844: //10/7661A559800A/H323/cch323_get_embedded_obj_from_ccb: ccb=0x49F6FE00, tag=17, size=83
000205: Oct 5 10:19:56.844: //10/7661A559800A/H323/cch323_get_embedded_obj_from_ccb: Extraction PASSED from 0x49F72638
000206: Oct 5 10:19:56.844: //10/7661A559800A/H323/generic_alert_notify: aData display_info
000207: Oct 5 10:19:56.844: //10/7661A559800A/CCAPI/cc_api_call_alert:
Interface=0x478B1418, Progress Indication=NULL(0), Signal Indication=SIGNAL RINGBACK(1)
000208: Oct 5 10:19:56.844: //10/7661A559800A/CCAPI/cc_api_call_alert:
Call Entry(Retry Count=0, Responsed=TRUE)
000209: Oct 5 10:19:56.844: //10/7661A559800A/H323/cch323_h225_set_new_state: Changing from H225_CALLPROC state to H225_ALERT state
000210: Oct 5 10:19:56.844: //9/7661A559800A/CCAPI/ccCallAlert:
Progress Indication=NULL(0), Signal Indication=SIGNAL RINGBACK(1)
000211: Oct 5 10:19:56.844: //9/7661A559800A/CCAPI/ccCallAlert:
Call Entry(Responsed=TRUE, Alert Sent=TRUE)
000212: Oct 5 10:19:56.848: //9/7661A559800A/CCAPI/ccCallNotify:
Data Bitmask=0x7, Call Id=9
000213: Oct 5 10:19:56.848: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 180 Ringing
Via: SIP/2.0/TCP 10.1.200.20:5060;branch=z9hG4bK2423dd8b96
From: <1001>;tag=672f0396-d595-4a92-b33d-446800d37753-277724971001>
To: <3001>;tag=39F76DC-E923001>
Date: Tue, 05 Oct 2010 14:19:56 GMT
Call-ID: 9ee9bd00-cab1340b-1d-14c8010a@10.1.200.20
CSeq: 101 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Remote-Party-ID: <3001>;party=called;screen=no;privacy=off3001>
Contact: <3001>3001>
Server: Cisco-SIPGateway/IOS-12.x
Content-Length: 0
000214: Oct 5 10:20:04.448: //-1/xxxxxxxxxxxx/H323/cch323_ct_main: SOCK 3 Event 0x1
000215: Oct 5 10:20:04.448: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: owner_data=0x49D55E4C, len=93, msgPtr=0x49D55CF0
000216: Oct 5 10:20:04.448: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: Received msg for H.225
000217: Oct 5 10:20:04.448: H225.0 INCOMING ENCODE BUFFER::= 22C0060008914A0004000303030381522800B500001240013C050401002040007661A559CFC211DF800AB8130721089B1D0C0011007662DDA9CFC211DF800CB8130721089B0180018010800100
000218: Oct 5 10:20:04.448:
000219: Oct 5 10:20:04.448: H225.0 INCOMING PDU ::=
value H323_UserInformation ::=
{
h323-uu-pdu
{
h323-message-body connect :
{
protocolIdentifier { 0 0 8 2250 0 4 }
h245Address ipAddress :
{
ip '03030303'H
port 33106
}
destinationInfo
{
vendor
{
vendor
{
t35CountryCode 181
t35Extension 0
manufacturerCode 18
}
}
gateway
{
protocol
{
voice :
{
supportedPrefixes
{
{
prefix dialedDigits : "1#"
}
}
}
}
}
mc FALSE
undefinedNode FALSE
}
conferenceID '7661A559CFC211DF800AB8130721089B'H
callIdentifier
{
guid '7662DDA9CFC211DF800CB8130721089B'H
}
multipleCalls TRUE
maintainConnection TRUE
}
h245Tunneling FALSE
}
}
000220: Oct 5 10:20:04.456: //-1/xxxxxxxxxxxx/H323/cch323_h225_receiver: Received msg of type SETUPCFM_CHOSEN
000221: Oct 5 10:20:04.456: //10/7661A559800A/H323/setup_cfm_ind: ====== PI = 0
000222: Oct 5 10:20:04.456: //10/7661A559800A/H323/setup_cfm_ind: Set new event H225_EV_SETUP_CFM_IND
000223: Oct 5 10:20:04.456: //10/7661A559800A/H323/setup_cfm_ind: Rcvd CONNECT Display Info IE =
000224: Oct 5 10:20:04.456: //10/7661A559800A/H323/setup_cfm_ind: setup_cfm_ind:- Insertion PASSED
000225: Oct 5 10:20:04.456: //10/7661A559800A/H323/cch323_h225_receiver: SETUPCFM_CHOSEN: src address = 6.6.6.7; dest address = 3.3.3.3
000226: Oct 5 10:20:04.456: //10/7661A559800A/H323/run_h225_sm: Received event H225_EV_SETUP_CFM_IND while at state H225_ALERT
000227: Oct 5 10:20:04.456: //10/7661A559800A/H323/setup_cfm_notify: status = 8000009
000228: Oct 5 10:20:04.456: //10/7661A559800A/H323/cch323_h225_set_new_state: Changing from H225_ALERT state to H225_WAIT_FOR_H245 state
000229: Oct 5 10:20:04.456: //10/7661A559800A/H323/h245_address_ind: ev=2
000230: Oct 5 10:20:04.456: //10/7661A559800A/CCAPI/ccIsInfoRingback:
Returning dpRingBack=0
000231: Oct 5 10:20:04.456: //-1/xxxxxxxxxxxx/H323/cch323_iev_queue_service: Dispatch 0xB internal event to H245 IWF SM
000232: Oct 5 10:20:04.456: //10/7661A559800A/H323/run_h245_iwf_sm: received IWF_EV_H245_CONNECT_REQ while at state IWF_IDLE
000233: Oct 5 10:20:04.456: //10/7661A559800A/H323/cch323_send_event_to_h245_connection_sm: Changing to new event H245_CONNECT_REQ_EVENT
000234: Oct 5 10:20:04.456: //10/7661A559800A/H323/cch323_h245_connection_sm: state=0, event=1, ccb=49F6FE00, listen state=0
000235: Oct 5 10:20:04.456: //10/7661A559800A/H323/cch323_h245_connection_sm: H245_CONNECT: Received event H245_CONNECT_REQ_EVENT while at H245_NONE state
000236: Oct 5 10:20:04.460: //10/7661A559800A/H323/cch323_h245_set_new_state: Changing from H245_NONE state to H245_WAITING state
000237: Oct 5 10:20:04.460: //10/7661A559800A/H323/h245_iwf_set_new_state: changing from IWF_IDLE state to IWF_AWAIT_H245_CONN state
000238: Oct 5 10:20:04.460: //10/7661A559800A/H323/h245_connect_init: connection pending
000239: Oct 5 10:20:04.512: //-1/xxxxxxxxxxxx/H323/cch323_ct_main: SOCK 4 Event 0x1
000240: Oct 5 10:20:04.512: //10/7661A559800A/H323/cch323_h245_channel_established_ind: Using fd=4 to send msgs
000241: Oct 5 10:20:04.512: //10/7661A559800A/H323/cch323_send_event_to_h245_connection_sm: Changing to new event H245_ESTABLISHED_EVENT
000242: Oct 5 10:20:04.512: //10/7661A559800A/H323/cch323_h245_connection_sm: state=1, event=2, ccb=49F6FE00, listen state=0
000243: Oct 5 10:20:04.512: //10/7661A559800A/H323/cch323_h245_connection_sm: H245_CONNECT: Received event H245_ESTABLISHED_EVENT while at H245_WAITING state
000244: Oct 5 10:20:04.512: //10/7661A559800A/H323/cch323_h245_set_new_state: Changing from H245_WAITING state to H245_CONNECTED state
000245: Oct 5 10:20:04.512: //-1/xxxxxxxxxxxx/H323/cch323_iev_queue_service: Dispatch 0x2 internal event to H245 IWF SM
000246: Oct 5 10:20:04.512: //10/7661A559800A/H323/run_h245_iwf_sm: received IWF_EV_H245_CONNECTED while at state IWF_AWAIT_H245_CONN
000247: Oct 5 10:20:04.512: //10/7661A559800A/H323/h245_iwf_set_new_state: changing from IWF_AWAIT_H245_CONN state to IWF_H245_CONNECTED state
000248: Oct 5 10:20:04.512: //-1/xxxxxxxxxxxx/H323/cch323_ct_main: SOCK 4 Event 0x1
000249: Oct 5 10:20:04.712: //-1/xxxxxxxxxxxx/H323/cch323_ct_main: SOCK 4 Event 0x1
000250: Oct 5 10:20:04.712: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: owner_data=0x49F6FE00, len=286, msgPtr=0x49F72AE0
000251: Oct 5 10:20:04.712: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: Received msg for H.245
000252: Oct 5 10:20:04.712: h245_decode_one_pdu: more_pdus = 0, bytesLeftToDecode = 286
000253: Oct 5 10:20:04.712: H245 MSC INCOMING ENCODE BUFFER::= 027001060008817500078013800014000100000100000100000CC001000100148000184810B50000120C52747044746D6652656C6179000080001E83015080001D83014080001A83011080001421C0138000132180138000122140138000102020B500001209436C6561724368696480000522C00180000422800180000C2400010180000D2408010180000E220000C0000F2020B5000012074737323331617280000A22000040000220C0138000032040138000092240078000082020B500001207473732367233328000072020B500001207473732367232348000062020B50000120747373236723136008001021100040005000C000D0002000300060007000800100009000F000E000A000A00120013001402001D001A001800001E
000254: Oct 5 10:20:04.716:
000255: Oct 5 10:20:04.716: H245 MSC INCOMING PDU ::=
value MultimediaSystemControlMessage ::= request : terminalCapabilitySet :
{
sequenceNumber 1
protocolIdentifier { 0 0 8 245 0 7 }
multiplexCapability h2250Capability :
{
maximumAudioDelayJitter 20
receiveMultipointCapability
{
multicastCapability FALSE
multiUniCastConference FALSE
mediaDistributionCapability
{
{
centralizedControl FALSE
distributedControl FALSE
centralizedAudio FALSE
distributedAudio FALSE
centralizedVideo FALSE
distributedVideo FALSE
}
}
}
transmitMultipointCapability
{
multicastCapability FALSE
multiUniCastConference FALSE
mediaDistributionCapability
{
{
centralizedControl FALSE
distributedControl FALSE
centralizedAudio FALSE
distributedAudio FALSE
centralizedVideo FALSE
distributedVideo FALSE
}
}
}
receiveAndTransmitMultipointCapability
{
multicastCapability FALSE
multiUniCastConference FALSE
mediaDistributionCapability
{
{
centralizedControl FALSE
distributedControl FALSE
centralizedAudio FALSE
distributedAudio FALSE
centralizedVideo FALSE
distributedVideo FALSE
}
}
}
mcCapability
{
centralizedConferenceMC FALSE
decentralizedConferenceMC FALSE
}
rtcpVideoControlCapability FALSE
mediaPacketizationCapability
{
h261aVideoPacketization FALSE
}
logicalChannelSwitchingCapability FALSE
t120DynamicPortCapability FALSE
}
capabilityTable
{
{
capabilityTableEntryNumber 25
capability receiveAndTransmitDataApplicationCapability :
{
application nonStandard :
{
nonStandardIdentifier h221NonStandard :
{
t35CountryCode 181
t35Extension 0
manufacturerCode 18
}
data '52747044746D6652656C6179'H
}
maxBitRate 0
}
},
{
capabilityTableEntryNumber 31
capability receiveUserInputCapability : hookflash : NULL
},
{
capabilityTableEntryNumber 30
capability receiveUserInputCapability : dtmf : NULL
},
{
capabilityTableEntryNumber 27
capability receiveUserInputCapability : basicString : NULL
},
{
capabilityTableEntryNumber 21
capability receiveAudioCapability : g722-48k : 20
},
{
capabilityTableEntryNumber 20
capability receiveAudioCapability : g722-56k : 20
},
{
capabilityTableEntryNumber 19
capability receiveAudioCapability : g722-64k : 20
},
{
capabilityTableEntryNumber 17
capability receiveAudioCapability : nonStandard :
{
nonStandardIdentifier h221NonStandard :
{
t35CountryCode 181
t35Extension 0
manufacturerCode 18
}
data '436C65617243686964'H
}
},
{
capabilityTableEntryNumber 6
capability receiveAudioCapability : g729AnnexA : 2
},
{
capabilityTableEntryNumber 5
capability receiveAudioCapability : g729 : 2
},
{
capabilityTableEntryNumber 13
capability receiveAudioCapability : g729wAnnexB : 2
},
{
capabilityTableEntryNumber 14
capability receiveAudioCapability : g729AnnexAwAnnexB : 2
},
{
capabilityTableEntryNumber 15
capability receiveAudioCapability : g7231 :
{
maxAl-sduAudioFrames 1
silenceSuppression TRUE
}
},
{
capabilityTableEntryNumber 16
capability receiveAudioCapability : nonStandard :
{
nonStandardIdentifier h221NonStandard :
{
t35CountryCode 181
t35Extension 0
manufacturerCode 18
}
data '47373233316172'H
}
},
{
capabilityTableEntryNumber 11
capability receiveAudioCapability : g7231 :
{
maxAl-sduAudioFrames 1
silenceSuppression FALSE
}
},
{
capabilityTableEntryNumber 3
capability receiveAudioCapability : g711Ulaw64k : 20
},
{
capabilityTableEntryNumber 4
capability receiveAudioCapability : g711Alaw64k : 20
},
{
capabilityTableEntryNumber 10
capability receiveAudioCapability : g728 : 8
},
{
capabilityTableEntryNumber 9
capability receiveAudioCapability : nonStandard :
{
nonStandardIdentifier h221NonStandard :
{
t35CountryCode 181
t35Extension 0
manufacturerCode 18
}
data '47373236723332'H
}
},
{
capabilityTableEntryNumber 8
capability receiveAudioCapability : nonStandard :
{
nonStandardIdentifier h221NonStandard :
{
t35CountryCode 181
t35Extension 0
manufacturerCode 18
}
data '47373236723234'H
}
},
{
capabilityTableEntryNumber 7
capability receiveAudioCapability : nonStandard :
{
nonStandardIdentifier h221NonStandard :
{
t35CountryCode 181
t35Extension 0
manufacturerCode 18
}
data '47373236723136'H
}
}
}
capabilityDescriptors
{
{
capabilityDescriptorNumber 1
simultaneousCapabilities
{
{
5,
6,
13,
14,
3,
4,
7,
8,
9,
17,
10,
16,
15,
11,
11,
19,
20,
21
},
{
30,
27,
25
},
{
31
}
}
}
}
}
000256: Oct 5 10:20:04.740: h245_decode_one_pdu: H245ASNDecodePdu rc = 0, bytesLeftToDecode = 0
000257: Oct 5 10:20:04.740: h245_decode_one_pdu: Read Pkt body: more_pdus:0 rc:0 asn_rc:0
000258: Oct 5 10:20:04.740: //-1/xxxxxxxxxxxx/H323/cch323_get_dp_pref_mask:
cch323_get_dp_pref_mask:IPIPGW(10):setting mask for 729ar8also as 729 is configured
000259: Oct 5 10:20:04.740: //-1/xxxxxxxxxxxx/H323/cch323_get_dp_pref_mask:
cch323_get_dp_pref_mask:IPIPGW(10):setting mask for 729ar8also as 729 is configured
000260: Oct 5 10:20:04.740: //10/7661A559800A/H323/cch323_h245_cap_ind: Masks au=0x7000B9FF data=0x2 uinp=0x32
000261: Oct 5 10:20:04.740: //10/7661A559800A/H323/cch323_run_h245_cap_in_sm: Received H245_EVENT_CAP_IND while at state IDLE
000262: Oct 5 10:20:04.744: //10/7661A559800A/H323/h245_cap_in_set_new_state: changing from IDLE state to AWAITING_RESPONSE state
000263: Oct 5 10:20:04.744: //-1/xxxxxxxxxxxx/H323/cch323_iev_queue_service: Dispatch 0x4 internal event to H245 IWF SM
000264: Oct 5 10:20:04.744: //10/7661A559800A/H323/run_h245_iwf_sm: received IWF_EV_CAP_IND while at state IWF_H245_CONNECTED
000265: Oct 5 10:20:04.744: //10/7661A559800A/H323/h323_validate_cap_ind: Remote Pref Codecs UnOrdered (0x7000B9FF) = [G729IETF] [G729a] [G729b] [G729ab] [G711_ULAW_64K] [G711_ALAW_64K] [G726r16] [G726r24] [G726r32] [CLEARCHANNEL] [G728] [G723ar63] [G723r63] [G72264] [G72256] [G72248] []
000266: Oct 5 10:20:04.744: //10/7661A559800A/H323/h245_handle_cap_ind: TCS received from remote end. Setting h245 status flag H245_CAP_REQUEST_RCVD
000267: Oct 5 10:20:04.744: //-1/xxxxxxxxxxxx/H323/cch323_get_dp_pref_mask:
cch323_get_dp_pref_mask:IPIPGW(10):setting mask for 729ar8also as 729 is configured
000268: Oct 5 10:20:04.744: //10/7661A559800A/H323/cch323_set_extended_caps: Copying codec list into extended caps structure
000269: Oct 5 10:20:04.744: //10/7661A559800A/H323/cch323_set_extended_caps: G729IETF
000270: Oct 5 10:20:04.744: //10/7661A559800A/H323/cch323_set_extended_caps: G729a
000271: Oct 5 10:20:04.744: //10/7661A559800A/H323/cch323_iwf_cap_notify: Mask sent to other leg=C
000272: Oct 5 10:20:04.744: //10/7661A559800A/CCAPI/cc_api_caps_ind:
Destination Interface=0x0, Destination Call Id=-1, Source Call Id=10,
Caps(Codec=0xC, Fax Rate=0x2, Vad=0x2,
Modem=0x0, Codec Bytes=20, Signal Type=2)
000273: Oct 5 10:20:04.744: //10/7661A559800A/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))
000274: Oct 5 10:20:04.748: //9/7661A559800A/CCAPI/cc_api_call_disconnected:
Cause Value=65, Interface=0x4705BD7C, Call Id=9
000275: Oct 5 10:20:04.748: //9/7661A559800A/CCAPI/cc_api_call_disconnected:
Call Entry(Responsed=TRUE, Cause Value=65, Retry Count=0)
000276: Oct 5 10:20:04.748: //9/7661A559800A/CCAPI/cc_api_caps_ack:
Destination Interface=0x0, Destination Call Id=-1, Source Call Id=9,
Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_VOICE(0x2), Vad=ON(0x2),
Modem=OFF(0x0), Codec Bytes=160, Signal Type=2, Seq Num Start=2050)
000277: Oct 5 10:20:04.748: //10/7661A559800A/H323/cch323_h225_sent_deferred_setup_cfm_notify: ====== PI = 0; status = 8000019
000278: Oct 5 10:20:04.748: //10/7661A559800A/CCAPI/cc_api_call_connected:
Interface=0x478B1418, Data Bitmask=0x1, Progress Indication=NULL(0),
Connection Handle=0
000279: Oct 5 10:20:04.748: //10/7661A559800A/CCAPI/cc_api_call_connected:
Call Entry(Connected=TRUE, Responsed=TRUE, Retry Count=0)
000280: Oct 5 10:20:04.748: //10/7661A559800A/H323/cch323_modify_rtcp_session_parameters: updating RTP session params, h245.iwf_state = 2,h245.status = 21020040, in_type = 3, flag = 0
000281: Oct 5 10:20:04.748: //10/7661A559800A/H323/h245_handle_cap_ind: TCS ack is deferred
000282: Oct 5 10:20:04.752: //10/7661A559800A/H323/h245_iwf_set_new_state: changing from IWF_H245_CONNECTED state to IWF_AWAIT_PEER_CAP state
000283: Oct 5 10:20:04.752: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 501 Not Implemented
Via: SIP/2.0/TCP 10.1.200.20:5060;branch=z9hG4bK2423dd8b96
From: <1001>;tag=672f0396-d595-4a92-b33d-446800d37753-277724971001>
To: <3001>;tag=39F76DC-E923001>
Date: Tue, 05 Oct 2010 14:19:56 GMT
Call-ID: 9ee9bd00-cab1340b-1d-14c8010a@10.1.200.20
CSeq: 101 INVITE
Allow-Events: telephone-event
Reason: Q.850;cause=65
Server: Cisco-SIPGateway/IOS-12.x
Content-Length: 0
000284: Oct 5 10:20:04.756: //-1/xxxxxxxxxxxx/H323/cch323_post_call_statistics: callID=10
000285: Oct 5 10:20:04.756: //10/7661A559800A/CCAPI/ccCallDisconnect:
Cause Value=65, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
000286: Oct 5 10:20:04.756: //10/7661A559800A/CCAPI/ccCallDisconnect:
Cause Value=65, Call Entry(Responsed=TRUE, Cause Value=65)
000287: Oct 5 10:20:04.756: //10/7661A559800A/CCAPI/cc_api_get_transfer_info:
Transfer Number Is Null
000288: Oct 5 10:20:04.756: //9/7661A559800A/CCAPI/ccCallDisconnect:
Cause Value=65, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=65)
000289: Oct 5 10:20:04.756: //9/7661A559800A/CCAPI/ccCallDisconnect:
Cause Value=65, Call Entry(Responsed=TRUE, Cause Value=65)
000290: Oct 5 10:20:04.760: //9/7661A559800A/CCAPI/cc_api_call_disconnect_done:
Disposition=-11, Interface=0x4705BD7C, Tag=0x0, Call Id=9,
Call Entry(Disconnect Cause=65, Voice Class Cause Code=0, Retry Count=0)
000291: Oct 5 10:20:04.760: //9/7661A559800A/CCAPI/cc_api_call_disconnect_done:
Call Disconnect Event Sent
000292: Oct 5 10:20:04.760: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
000293: Oct 5 10:20:04.760: :cc_free_feature_vsa freeing 49E81050
000294: Oct 5 10:20:04.760: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
000295: Oct 5 10:20:04.760: vsacount in free is 1
000296: Oct 5 10:20:04.764: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
ACK sip:3001@6.6.6.7:5060 SIP/2.0
Date: Tue, 05 Oct 2010 14:19:55 GMT
From: <1001>;tag=672f0396-d595-4a92-b33d-446800d37753-277724971001>
Allow-Events: presence, kpml
Content-Length: 0
To: <3001>;tag=39F76DC-E923001>
Call-ID: 9ee9bd00-cab1340b-1d-14c8010a@10.1.200.20
Via: SIP/2.0/TCP 10.1.200.20:5060;branch=z9hG4bK2423dd8b96
CSeq: 101 ACK
Max-Forwards: 70
000297: Oct 5 10:20:04.768: //10/7661A559800A/H323/cch323_peer_caps_ack: Sending caps resp event to CAP sm
000298: Oct 5 10:20:04.768: //10/7661A559800A/H323/run_h245_iwf_sm: received IWF_EV_PEER_CAPS_ACK while at state IWF_AWAIT_PEER_CAP
000299: Oct 5 10:20:04.768: //10/7661A559800A/H323/cch323_do_call_disconnect: gw_id=1, discCause=65
000300: Oct 5 10:20:04.768: //-1/xxxxxxxxxxxx/H323/cch323_iev_queue_service: Dispatch 0x9 internal event to H225 SM
000301: Oct 5 10:20:04.768: //10/7661A559800A/H323/run_h225_sm: Received event H225_EV_RELEASE while at state H225_WAIT_FOR_H245
000302: Oct 5 10:20:04.768: //10/7661A559800A/H323/cch323_h225_send_release: Cause = 65; Location = 0
000303: Oct 5 10:20:04.768: //10/7661A559800A/H323/cch323_h225_send_release: h225TerminateRequest: src address = 101058055; dest address = 3.3.3.3
000304: Oct 5 10:20:04.768: H225.0 OUTGOING PDU ::=
value H323_UserInformation ::=
{
h323-uu-pdu
{
h323-message-body releaseComplete :
{
protocolIdentifier { 0 0 8 2250 0 4 }
callIdentifier
{
guid '7662DDA9CFC211DF800CB8130721089B'H
}
}
h245Tunneling FALSE
}
}
000305: Oct 5 10:20:04.768: H225.0 OUTGOING ENCODE BUFFER::= 2580060008914A0004110011007662DDA9CFC211DF800CB8130721089B10800100
000306: Oct 5 10:20:04.768:
000307: Oct 5 10:20:04.772: //10/7661A559800A/H323/cch323_h225_set_new_state: Changing from H225_WAIT_FOR_H245 state to H225_IDLE state
000308: Oct 5 10:20:04.772: //10/7661A559800A/H323/cch323_call_generic_cleanup: Disconnected flag 1
000309: Oct 5 10:20:04.772: //10/7661A559800A/H323/cch323_store_call_history_entry: Call Active Playout Mode: 1,Init 60, Min 40, Max 1000, Fax 300
000310: Oct 5 10:20:04.772: //10/7661A559800A/H323/cch323_store_call_history_entry: Call History Playout Mode: 1,Init 60, Min 40, Max 1000, Fax 300
000311: Oct 5 10:20:04.772: //10/7661A559800A/H323/run_h245_iwf_sm: received IWF_EV_H245_DISCONN while at state IWF_AWAIT_PEER_CAP
000312: Oct 5 10:20:04.772: //10/7661A559800A/H323/defaultHdlr: DEFAULT: Received IWF_EV_H245_DISCONN in state IWF_AWAIT_PEER_CAP
000313: Oct 5 10:20:04.772: //-1/xxxxxxxxxxxx/H323/h323_gw_clean_send_blocked_watch: fd 4
000314: Oct 5 10:20:04.772: //10/7661A559800A/CCAPI/cc_api_call_disconnect_done:
Disposition=0, Interface=0x478B1418, Tag=0x0, Call Id=10,
Call Entry(Disconnect Cause=65, Voice Class Cause Code=0, Retry Count=0)
000315: Oct 5 10:20:04.772: //10/7661A559800A/CCAPI/cc_api_call_disconnect_done:
Call Disconnect Event Sent
000316: Oct 5 10:20:04.772: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
000317: Oct 5 10:20:04.776: :cc_free_feature_vsa freeing 49E80F70
000318: Oct 5 10:20:04.776: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
000319: Oct 5 10:20:04.776: vsacount in free is 0
000320: Oct 5 10:20:04.776: //-1/xxxxxxxxxxxx/H323/cch323_call_generic_cleanup: Freeing ccb (0x49F6FE00)
000321: Oct 5 10:20:05.104: //-1/xxxxxxxxxxxx/H323/cch323_ct_main: SOCK 3 Event 0x1
000322: Oct 5 10:20:05.104: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: owner_data=0x49D55E4C, len=46, msgPtr=0x49D8C6B8
000323: Oct 5 10:20:05.104: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: Received msg for H.225
000324: Oct 5 10:20:05.104: //-1/xxxxxxxxxxxx/H323/validate_crv: No CCB for crv: 0x9
000325: Oct 5 10:20:05.104: //-1/xxxxxxxxxxxx/H323/cch323_h225_receiver: Parse error RXDATA_NONE
000326: Oct 5 10:20:05.104: //-1/xxxxxxxxxxxx/H323/cch323_cleanup_xport: CRV entry not found, returning
000327: Oct 5 10:20:22.820: //-1/xxxxxxxxxxxx/H323/cch323_timer_dispatch: Timer[CCH323_RAS_PERIODIC_RRQ_TIMER] expired
000328: Oct 5 10:20:22.820: //-1/xxxxxxxxxxxx/H323/cch323_send_event_to_ras: Queued event CCH323_RAS_EVENT_SEND_LT_RRQ to RAS Global SM
000329: Oct 5 10:20:22.820: //-1/xxxxxxxxxxxx/H323/cch323_iev_queue_service: Dispatch 0xA internal event to RAS Global SM
000330: Oct 5 10:20:22.820: //-1/xxxxxxxxxxxx/H323/cch323_run_ras_sm: received event CCH323_RAS_EVENT_SEND_LT_RRQ while at CCH323_RAS_STATE_IDLE state
000331: Oct 5 10:20:22.820: RAS OUTGOING PDU ::=
value RasMessage ::= registrationRequest :
{
requestSeqNum 1264
protocolIdentifier { 0 0 8 2250 0 4 }
discoveryComplete TRUE
callSignalAddress
{
}
rasAddress
{
ipAddress :
{
ip '06060607'H
port 63383
}
}
terminalType
{
mc FALSE
undefinedNode FALSE
}
gatekeeperIdentifier {"ZONE_01"}
endpointVendor
{
vendor
{
t35CountryCode 181
t35Extension 0
manufacturerCode 18
}
}
timeToLive 60
keepAlive TRUE
endpointIdentifier {"672C9F6C00000001"}
willSupplyUUIEs FALSE
maintainConnection TRUE
}
000332: Oct 5 10:20:22.824: RAS OUTGOING ENCODE BUFFER::= 0E4004EF060008914A00048000010006060607F7970006005A004F004E0045005F0030003100B5000012288F000002003B0180211E003600370032004300390046003600430030003000300030003000300030003101000180
000333: Oct 5 10:20:22.824:
000334: Oct 5 10:20:22.824: //-1/xxxxxxxxxxxx/H323/cch323_run_ras_sm: changing to CCH323_RAS_STATE_RRQ state
000335: Oct 5 10:20:22.888: //-1/xxxxxxxxxxxx/H323/cch323_ct_main: SOCK 2 Event 0x1
000336: Oct 5 10:20:22.888: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: owner_data=0x49D57F60, len=70, msgPtr=0x49D564A4
000337: Oct 5 10:20:22.888: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: Received msg for RAS
000338: Oct 5 10:20:22.888: RAS INCOMING ENCODE BUFFER::= 124004EF060008914A0004000C005A004F004E0045005F003000311E0036003700320043003900460036004300300030003000300030003000300031208A0002003B01000180
000339: Oct 5 10:20:22.888:
000340: Oct 5 10:20:22.888: RAS INCOMING PDU ::=
value RasMessage ::= registrationConfirm :
{
requestSeqNum 1264
protocolIdentifier { 0 0 8 2250 0 4 }
callSignalAddress
{
}
gatekeeperIdentifier {"ZONE_01"}
endpointIdentifier {"672C9F6C00000001"}
timeToLive 60
willRespondToIRR FALSE
maintainConnection TRUE
}
000341: Oct 5 10:20:22.888: //-1/xxxxxxxxxxxx/H323/cch323_ras_handle_recv_msg: received msg of type RCF_CHOSEN
000342: Oct 5 10:20:22.888: //-1/xxxxxxxxxxxx/H323/cch323_run_ras_sm: received event CCH323_RAS_EVENT_RCF while at CCH323_RAS_STATE_RRQ state
000343: Oct 5 10:20:22.888: //-1/xxxxxxxxxxxx/H323/cch323_run_ras_sm: changing to CCH323_RAS_STATE_IDLE state
ISR#