Understanding The Transport Layer For SIP and H323

Ayodeji Okanlawon · ‎03-16-2014

The transport layer play a very vital role in all VoIP solution. Cisco CUCM, voice gateways, IP Phones/end points all rely on the transport layer to succesfully establish communications/sessions with their intended destinations. To understand how this affect SIP and H.323 gateways that we will be discussing in this document, we need to understand the OSI layer.

The OSI layer is a conceptual model that characterizes and standardizes the internal functions of a communication system by partitioning it into abstraction layers. The model groups similar communication functions into one of seven logical layers. A layer serves the layer above it and is served by the layer below it.

The OSI model is also used within Cisco SIP stack. While most of the functionality we see during troubleshooting happens at either the session layer or application layer, the foundation of it is actually done at the transport layer. Events at the transport layer even though not very visible unless we dig deeper is very crucial. The table below shows where each component of the UC solution operates in the OSI model.

Application Presentation Session Transport Network Data Link Physical	cucm/soft phone
	Codecs
	SIP/H.323/MGCP
	RTP/UDP/TCP
	IP
	Frame relay, ATM.,Ethernet,HDLC
	Raw Data

From the table we can see that all of our SIP, H323, MGCP gateway signaling occurs at the session layer which means that they are heavily dependent on the transport layer

There are two main types of transport protocol cisco gateways use: TCP or UDP.

This blog will not go into the details of what each protocol is, we will only look at the application with regards to the SIP stack and the H323 stack within CUCM,CUBE and H323 gateway. As most of my blogs/document employ a vey direct and practical approach, I will be using real life logs to explain how this all work.

TCP VS UDP

TCP is connection oriented. Hence nothing happens at the layer above it (session, presentation or application) until a connection is established with the destination peer.

UDP is connectionless, hence it doesn't check for a connection state before blindly progressing to the upper layers.

Understanding TCP transaction..

Before we go ahead lets take a look at the key transaction elements of the TCP protocol.

TCP is a socket oriented protocol and it has different states that it uses to establish communication with each participant in a session. Lets look at the basic connection establishment. TCP uses a three way hand shake to establish a communication between two parties. These three way is defined as follows:

SYNC, SYNC+ACK, ACK.

As depicted in the table below, the sending party sends a SYNC, then the receiving party sends a SYNC+ACK and finally the sending sends an ACK to the SYCN of the receiving party. Once this is completed TCP moves to the Establishment state.

SYNC
SYNC + ACK
ACK
ESTABLISH

A (SYNC)--------------------------------------->B

A<--------------------------------------------------B(SYNC + ACK (to the first SYNC))

A--------------------------------------------------->B(ACK(to B's sync))

A(ESTAB)<--------------------------------------->B(ESTAB)

It is important to understand this states as they are crucial in troubleshooting connection related issues.

To see the TCP transaction on a cisco gateways you can use

debug ip tcp transaction

debug ip tcp packet

Ok lets apply this in a practical way.

H323 and the Transport layer

Before we look at the example below, it is important to know that before a gateway can send a h225 setup request to CUCM, it must first establish a tcp connection. Without a tcp connection, this will not be possible. Now lets see how this applies.

Table below shows the traces for incoming call to a h323 gateway via ISDN. Trace analysis inset

PSTN-------e1--Gateway----H323----CUCM---sccp--IP Phone

This is an incoming call from 5553620788 to 3259009 returns a busy signal
####ISDN Call setup#####
Dec 28 15:22:42.870: ISDN Se0/0/0:23 Q931: RX <- SETUP pd = 8 callref = 0x7E0C

Bearer Capability i = 0x8090A2

Standard = CCITT

Transfer Capability = Speech

Transfer Mode = Circuit

Transfer Rate = 64 kbit/s

Channel ID i = 0xA98381

Exclusive, Channel 1

Facility i = 0x9F8B0100A10802015C0201008400

Protocol Profile = Networking Extensions

0xA10802015C0201008400

Component = Invoke component

Invoke Id = 92

Operation = CallingName

Name not available

Calling Party Number i = 0x2183, '5553620788'

Plan:ISDN, Type:National

Called Party Number i = 0xC1, '3259009'

Plan:ISDN, Type:Subscriber(local)

Dec 28 15:22:42.870: ISDN Se0/0/0:23 Q931: Received SETUP callref = 0xFE0C callID = 0x000D switch = primary-ni interface = User

####h225 call setup####

Dec 28 15:22:42.870: //-1/42358F99800D/CCAPI/cc_api_display_ie_subfields:

cc_api_call_setup_ind_common:

cisco-username=

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

cisco-ani=5553620788

cisco-anitype=2

cisco-aniplan=1

cisco-anipi=0

cisco-anisi=3

dest=3259009

cisco-desttype=4

cisco-destplan=1

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

Dec 28 15:22:42.870: //-1/42358F99800D/CCAPI/cc_api_call_setup_ind_common:

Interface=0x323209CC, Call Info(

Calling Number=5553620788,(Calling Name=)(TON=National, NPI=ISDN, Screening=Network, Presentation=Allowed),

Called Number=3259009(TON=Subscriber, NPI=ISDN),

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

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

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

Dec 28 15:22:42.870: //-1/42358F99800D/CCAPI/ccCheckClipClir:

In: Calling Number=5553620788(TON=National, NPI=ISDN, Screening=Network, Presentation=Allowed)

Dec 28 15:22:42.870: //-1/42358F99800D/CCAPI/ccCheckClipClir:

Out: Calling Number=5553620788(TON=National, NPI=ISDN, Screening=Network, Presentation=Allowed)

Dec 28 15:22:42.870: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Dec 28 15:22:42.870: :cc_get_feature_vsa malloc success

Dec 28 15:22:42.870: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Dec 28 15:22:42.870: cc_get_feature_vsa count is 1

Dec 28 15:22:42.870: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Dec 28 15:22:42.870: :FEATURE_VSA attributes are: feature_name:0,feature_time:753124840,feature_id:37

Dec 28 15:22:42.870: //315/42358F99800D/CCAPI/cc_api_call_setup_ind_common:

Set Up Event Sent;

Call Info(Calling Number=5553620788(TON=National, NPI=ISDN, Screening=Network, Presentation=Allowed),

Called Number=3259009(TON=Subscriber, NPI=ISDN))

Dec 28 15:22:42.870: //315/42358F99800D/CCAPI/cc_process_call_setup_ind:

Event=0x3213BB30

Dec 28 15:22:42.870: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_search:

Try with the demoted called number 3259009

Dec 28 15:22:42.870: //315/42358F99800D/CCAPI/ccCallSetContext:

Context=0x32B9F744

Dec 28 15:22:42.870: //315/42358F99800D/CCAPI/cc_process_call_setup_ind:

>>>>CCAPI handed cid 315 with tag 200 to app "_ManagedAppProcess_Default"

Dec 28 15:22:42.870: //315/42358F99800D/CCAPI/ccCallProceeding:

Progress Indication=NULL(0)

Dec 28 15:22:42.874: //315/42358F99800D/CCAPI/ccCallSetupRequest:

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

Outgoing Dial-peer=501, Params=0x32BA34E4, Progress Indication=NULL(0)

Dec 28 15:22:42.874: //315/42358F99800D/CCAPI/ccCheckClipClir:

In: Calling Number=5553620788(TON=National, NPI=ISDN, Screening=Network, Presentation=Allowed)

Dec 28 15:22:42.874: //315/42358F99800D/CCAPI/ccCheckClipClir:

Out: Calling Number=5553620788(TON=National, NPI=ISDN, Screening=Network, Presentation=Allowed)

Dec 28 15:22:42.874: //315/42358F99800D/CCAPI/ccCallSetupRequest:

Destination Pattern=3......, Called Number=3259009, Digit Strip=FALSE

Dec 28 15:22:42.874: //315/42358F99800D/CCAPI/ccCallSetupRequest:

Calling Number=5553620788(TON=National, NPI=ISDN, Screening=Network, Presentation=Allowed),

Called Number=3259009(TON=Subscriber, NPI=ISDN),

Redirect Number=, Display Info=

Account Number=, Final Destination Flag=TRUE,

Guid=42358F99-5039-11E2-800D-F866F26A4840, Outgoing Dial-peer=501

Dec 28 15:22:42.874: //315/42358F99800D/CCAPI/cc_api_display_ie_subfields:

ccCallSetupRequest:

cisco-username=

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

cisco-ani=5553620788

cisco-anitype=2

cisco-aniplan=1

cisco-anipi=0

cisco-anisi=3

dest=3259009

cisco-desttype=4

cisco-destplan=1

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

Dec 28 15:22:42.874: //315/42358F99800D/CCAPI/ccIFCallSetupRequestPrivate:

Interface=0x31850F48, Interface Type=1, Destination=, Mode=0x0,

Call Params(Calling Number=5553620788,(Calling Name=)(TON=National, NPI=ISDN, Screening=Network, Presentation=Allowed),

Called Number=3259009(TON=Subscriber, NPI=ISDN), Calling Translated=FALSE,

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

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

Dec 28 15:22:42.874: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Dec 28 15:22:42.874: :cc_get_feature_vsa malloc success

Dec 28 15:22:42.874: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Dec 28 15:22:42.874: cc_get_feature_vsa count is 2

Dec 28 15:22:42.874: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Dec 28 15:22:42.874: :FEATURE_VSA attributes are: feature_name:0,feature_time:753124616,feature_id:38

Dec 28 15:22:42.874: //316/42358F99800D/CCAPI/ccIFCallSetupRequestPrivate:

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

Dec 28 15:22:42.874: //316/42358F99800D/CCAPI/ccCallSetContext:

Context=0x32BA3494

Dec 28 15:22:42.874: //315/42358F99800D/CCAPI/ccSaveDialpeerTag:

Outgoing Dial-peer=501

Dec 28 15:22:42.874: //316/42358F99800D/CCAPI/ccGetMediaClassTag:

media class tag 0

Dec 28 15:22:42.874: //316/42358F99800D/CCAPI/ccSetMediaclassIp2ipTags:

media class tags set: NR 0, ASP 0

Dec 28 15:22:42.874: //315/42358F99800D/CCAPI/ccSetMediaclassIp2ipTags:

media class tags set: NR 0, ASP 0

Dec 28 15:22:42.874: //316/42358F99800D/CCAPI/ccGet_xc_nr_asp_info:

media class tags: NR 0, ASP 0

Dec 28 15:22:42.874: //315/42358F99800D/CCAPI/ccGet_xc_nr_asp_info:

###voice gateway attempts to setup call to primary cucm (publisher-which was down in this case)###

media class tags: NR 0, ASP 0cch323_ip_best_local_address: IP 10.1.100.100 found for bound IDB Loopback0cch323_ip_best_local_address: IP 10.1.100.100 found for bound IDB Loopback0

*********TCP Transaction for the down dial-peer (publisher was down)*************
Dec 28 15:22:42.874: TCB2CEF6C08 created

Dec 28 15:22:42.874: TCB2CEF6C08 setting property TCP_NO_DELAY (0) 3235B6D0

Dec 28 15:22:42.874: TCB2CEF6C08 setting property TCP_TOS (11) 3235B71C

Dec 28 15:22:42.874: TCB2CEF6C08 setting property TCP_NONBLOCKING_WRITE (10) 3235B730

Dec 28 15:22:42.874: TCB2CEF6C08 setting property TCP_NONBLOCKING_READ (14) 3235B730

Dec 28 15:22:42.874: TCB2CEF6C08 setting property TCP_KEEPALIVE (17) 3235B730

Dec 28 15:22:42.874: TCP: Setting Keepalive interval and retries to 60 and 4

Dec 28 15:22:42.874: TCB2CEF6C08 setting property TCP_VRFTABLEID (20) 329424A0

Dec 28 15:22:42.874: TCB2CEF6C08 setting property TCP_NO_DELAY (0) 3235B71C

vr#

Dec 28 15:22:42.874: TCP: Random local port generated 41942, network 1

Dec 28 15:22:42.874: TCB2CEF6C08 bound to 10.1.100.100.41942

Dec 28 15:22:42.874: Reserved port 41942 in Transport Port Agent for TCP IP type 1

Dec 28 15:22:42.874: TCP: sending SYN, seq 3207241951, ack 0---------------------Here TCP SYNC was sent to CUCM

Dec 28 15:22:42.874: TCP0: Connection to 10.1.1.11:1720, advertising MSS 1460

Dec 28 15:22:42.874: TCP0: state was CLOSED -> SYNSENT [41942 -> 10.1.1.11(1720)]-------client changed from closed stated to sync sent

Dec 28 15:22:42.874: ISDN Se0/0/0:23 Q931: TX -> CALL_PROC pd = 8 callref = 0xFE0C

Channel ID i = 0xA98381

Exclusive, Channel 1

vr#

Dec 28 15:22:44.866: TCP389: ACK timeout timer expired----------------------------------Here We see that TCP timer expired for the SYNC

Dec 28 15:22:44.874: 10.1.100.100:41942 <---> 10.1.1.11:1720 congestion window changes

Dec 28 15:22:44.874: cwnd from 1460 to 1460, ssthresh from 65535 to 2920

Dec 28 15:22:44.874: TCP0: timeout #1 - timeout is 4000 ms, seq 3207241951----------------Here we see the sequence number (seq 3207241951) corresponds to the SYN sent seq number

Dec 28 15:22:44.874: TCP: (41942) -> 10.1.1.11(1720)

Dec 28 15:22:45.494: RAS OUTGOING PDU ::=

vr#

Dec 28 15:22:45.494: RAS OUTGOING ENCODE BUFFER::= 00000542060008914A0004000A016464C9802800B500001240013C05010000

Dec 28 15:22:45.494:

Dec 28 15:22:45.874: Released port 41942 in Transport Port Agent for TCP IP type 1 delay 240000-------------TCP port closed because timer expired

Dec 28 15:22:45.874: TCP0: state was SYNSENT -> CLOSED [41942 -> 10.1.1.11(1720)]-----client changes state from TCP SYNSENT changed to closed

Dec 28 15:22:45.874: TCB 0x2CEF6C08 destroyed---------------TCP connection destroyed

Dec 28 15:22:45.874: //316/42358F99800D/CCAPI/cc_api_call_disconnected:

Cause Value=38, Interface=0x31850F48, Call Id=316---------------------The CCAPI leg then disconnnects also.

Dec 28 15:22:45.874: //316/42358F99800D/CCAPI/cc_api_call_disconnected:

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

Dec 28 15:22:45.874: //315/42358F99800D/CCAPI/ccCallReleaseResources:

release reserved xcoding resource.

Dec 28 15:22:45.874: //316/42358F99800D/CCAPI/ccCallSetAAA_Accounting:

Accounting=1, Call Id=316

Dec 28 15:22:45.874: //316/42358F99800D/CCAPI/ccCallDisconnect:

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

Dec 28 15:22:45.874: //316/42358F99800D/CCAPI/ccCallDisconnect:

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

Dec 28 15:22:45.874: //316/42358F99800D/CCAPI/cc_api_get_transfer_info:

Transfer Number=NULL

Dec 28 15:22:45.874: //316/42358F99800D/CCAPI/cc_api_call_disconnect_done:

Disposition=0, Interface=0x31850F48, Tag=0x0, Call Id=316,

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

Dec 28 15:22:45.874: //316/42358F99800D/CCAPI/cc_api_call_disconnect_done:

Call Disconnect Event Sent

Dec 28 15:22:45.874: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

Dec 28 15:22:45.874: :cc_free_feature_vsa freeing 2CE3C500

Dec 28 15:22:45.874: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

Dec 28 15:22:45.874: vsacount in free is 1

######Next the Second dial-peer is tried after the first one failed#######

Dec 28 15:22:45.874: //315/42358F99800D/CCAPI/ccCallSetupRequest:

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

Outgoing Dial-peer=502, Params=0x32BA2074, Progress Indication=NULL(0)-----------NB that no incoming dial-peer is matched again..its already matched for the first call leg..

Dec 28 15:22:45.874: //315/42358F99800D/CCAPI/ccCheckClipClir:

In: Calling Number=5553620788(TON=National, NPI=ISDN, Screening=Network, Presentation=Allowed)

Dec 28 15:22:45.874: //315/42358F99800D/CCAPI/ccCheckClipClir:

Out: Calling Number=5553620788(TON=National, NPI=ISDN, Screening=Network, Presentation=Allowed)

Dec 28 15:22:45.874: //315/42358F99800D/CCAPI/ccCallSetupRequest:

Destination Pattern=3......, Called Number=3259009, Digit Strip=FALSE

Dec 28 15:22:45.874: //315/42358F99800D/CCAPI/ccCallSetupRequest:

Calling Number=5553620788(TON=National, NPI=ISDN, Screening=Network, Presentation=Allowed),

Called Number=3259009(TON=Subscriber, NPI=ISDN),

Redirect Number=, Display Info=

Account Number=, Final Destination Flag=TRUE,

Guid=42358F99-5039-11E2-800D-F866F26A4840, Outgoing Dial-peer=502

Dec 28 15:22:45.874: //315/42358F99800D/CCAPI/cc_api_display_ie_subfields:

ccCallSetupRequest:

cisco-username=

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

cisco-ani=5553620788

cisco-anitype=2

cisco-aniplan=1

cisco-anipi=0

cisco-anisi=3

dest=3259009

cisco-desttype=4

cisco-destplan=1

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

Dec 28 15:22:45.874: //315/42358F99800D/CCAPI/ccIFCallSetupRequestPrivate:

Interface=0x31850F48, Interface Type=1, Destination=, Mode=0x0,

Call Params(Calling Number=5553620788,(Calling Name=)(TON=National, NPI=ISDN, Screening=Network, Presentation=Allowed),

Called Number=3259009(TON=Subscriber, NPI=ISDN), Calling Translated=FALSE,

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

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

Dec 28 15:22:45.874: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Dec 28 15:22:45.874: :cc_get_feature_vsa malloc success

Dec 28 15:22:45.874: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Dec 28 15:22:45.874: cc_get_feature_vsa count is 2

Dec 28 15:22:45.874: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Dec 28 15:22:45.874: :FEATURE_VSA attributes are: feature_name:0,feature_time:753124616,feature_id:39

Dec 28 15:22:45.874: //317/42358F99800D/CCAPI/ccIFCallSetupRequestPrivate:

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

Dec 28 15:22:45.874: //317/42358F99800D/CCAPI/ccCallSetContext:

Context=0x32BA2024

Dec 28 15:22:45.874: //315/42358F99800D/CCAPI/ccSaveDialpeerTag:

Outgoing Dial-peer=502

Dec 28 15:22:45.874: //317/42358F99800D/CCAPI/ccGetMediaClassTag:

media class tag 0

Dec 28 15:22:45.874: //317/42358F99800D/CCAPI/ccSetMediaclassIp2ipTags:

media class tags set: NR 0, ASP 0

Dec 28 15:22:45.874: //315/42358F99800D/CCAPI/ccSetMediaclassIp2ipTags:

media class tags set: NR 0, ASP 0

Dec 28 15:22:45.874: //317/42358F99800D/CCAPI/ccGet_xc_nr_asp_info:

media class tags: NR 0, ASP 0

Dec 28 15:22:45.874: //315/42358F99800D/CCAPI/ccGet_xc_nr_asp_info:

media class tags: NR 0, ASP 0cch323_ip_best_local_address: IP 10.1.100.100 found for bound IDB Loopback0cch323_ip_best_local_address: IP 10.1.100.100 found for bound IDB Loopback0

Dec 28 15:22:45.874: TCB32B89814 created-----------A new TCP connection is created for the second dial-peer

Dec 28 15:22:45.874: TCB32B89814 setting property TCP_NO_DELAY (0) 3235B6D0

Dec 28 15:22:45.874: TCB32B89814 setting property TCP_TOS (11) 3235B71C

Dec 28 15:22:45.874: TCB32B89814 setting property TCP_NONBLOCKING_WRITE (10) 3235B730

Dec 28 15:22:45.874: TCB32B89814 setting property TCP_NONBLOCKING_READ (14) 3235B730

Dec 28 15:22:45.874: TCB32B89814 setting property TCP_KEEPALIVE (17) 3235B730

Dec 28 15:22:45.874: TCP: Setting Keepalive interval and retries to 60 and 4

Dec 28 15:22:45.874: TCB32B89814 setting property TCP_VRFTABLEID (20) 329424A0

Dec 28 15:22:45.874: TCB32B89814 setting property TCP_NO_DELAY (0) 3235B71C

Dec 28 15:22:45.874: TCP: Random local port generated 63553, network 1

Dec 28 15:22:45.874: TCB32B89814 bound to 10.1.100.100.63553

Dec 28 15:22:45.874: Reserved port 63553 in Transport Port Agent for TCP IP type 1

Dec 28 15:22:45.874: TCP: sending SYN, seq 3513163156, ack 0---------------TCP SYN was sent to CUCM Subcriver here..NB the Seq number (seq 3513163156)

Dec 28 15:22:45.878: TCP0: Connection to 10.1.1.12:1720, advertising MSS 1460---------------TCP connection to 10.1.1.12

Dec 28 15:22:45.878: TCP0: state was CLOSED -> SYNSENT [63553 -> 10.1.1.12(1720)]--------------NB: State changed from CLosed to SYNSENT

Dec 28 15:22:45.878: TCP0: state was SYNSENT -> ESTAB [63553 -> 10.1.1.12(1720)]---------------NB: State changed from SYNSENT to ESTABLISHED

Dec 28 15:22:45.878: TCP: tcb 32B89814 connection to 10.1.1.12:1720, peer MSS 1460, MSS is 1460cch323_ip_best_local_address: IP 10.1.100.100 found for bound IDB Loopback0---Here TCP connection is established to 10.1.1.12

***********NEXT we see the CALL PROCEEDING.......and we see H245 capabilities exchange after TCP connection is established****************

Dec 28 15:22:45.878: H245 FS OLC OUTGOING PDU ::=

value OpenLogicalChannel ::=

{

forwardLogicalChannelNumber 1

forwardLogicalChannelParameters

{

dataType audioData : g729 : 2

multiplexParameters h2250LogicalChannelParameters :

{

sessionID 1

mediaControlChannel unicastAddress : iPAddress :

{

network '0A016464'H

tsapIdentifier 16423

}

silenceSuppression FALSE

}

Dec 28 15:22:45.878: H245 FS OLC OUTGOING ENCODE BUFFER::= 0000000D4001800B050001000A016464402700

Dec 28 15:22:45.878:

Dec 28 15:22:45.878: H245 FS OLC OUTGOING PDU ::=

value OpenLogicalChannel ::=

{

forwardLogicalChannelNumber 1

forwardLogicalChannelParameters

{

dataType nullData : NULL

multiplexParameters none : NULL

}

reverseLogicalChannelParameters

{

dataType audioData : g729 : 2

multiplexParameters h2250LogicalChannelParameters :

{

sessionID 1

mediaChannel unicastAddress : iPAddress :

{

network '0A016464'H

tsapIdentifier 16422

}

mediaControlChannel unicastAddress : iPAddress :

{

network '0A016464'H

tsapIdentifier 16423

}

silenceSuppression FALSE

}

Dec 28 15:22:45.878: H245 FS OLC OUTGOING ENCODE BUFFER::= 400000060401004D40018012150001000A0164644026000A016464402700

Dec 28 15:22:45.878:

Dec 28 15:22:45.878: H225 NONSTD OUTGOING PDU ::=

value H323_UU_NonStdInfo ::=

{

version 2

protoParam qsigNonStdInfo :

{

iei 4

rawMesg '04038090A21803A983811C0E9F8B0100A1080201...'H

}

Dec 28 15:22:45.878: H225 NONSTD OUTGOING ENCODE BUFFER::= 60010200010480EC04038090A21803A983811C0E9F8B0100A10802015C02010084006C0C2183323034333632303738387008C1333235393030391CB89E810003677464000000AD49414D2C0D0A50524E2C6973646E2A2C2C4E492A2A2A2C0D0A5553492C726174652C632C732C632C310D0A5553492C6C6179312C756C61770D0A544D522C30300D0A43504E2C30322C2C312C333235393030390D0A43474E2C30342C2C312C792C342C323034333632303738380D0A4350432C30390D0A4643492C2C2C2C2C2C2C792C0D0A4743492C34323335386639393530333931316532383030646638363666323661343834300D0A0D0A

Dec 28 15:22:45.878:

Dec 28 15:22:45.878: 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

}

gateway

{

protocol

{

voice :

{

supportedPrefixes

{

}

mc FALSE

undefinedNode FALSE

}

activeMC FALSE

conferenceID '42358F99503911E2800DF866F26A4840'H

conferenceGoal create : NULL

callType pointToPoint : NULL

sourceCallSignalAddress ipAddress :

{

ip '0A016464'H

port 63553

}

callIdentifier

{

guid '42358F99503911E2804A903A21A7A74D'H

}

fastStart

{

'0000000D4001800B050001000A016464402700'H,

'400000060401004D40018012150001000A016464...'H

}

mediaWaitForConnect FALSE

canOverlapSend FALSE

multipleCalls TRUE

maintainConnection TRUE

symmetricOperationRequired NULL

}

h245Tunneling TRUE

nonStandardControl

{

nonStandardIdentifier h221NonStandard :

{

t35CountryCode 181

t35Extension 0

manufacturerCode 18

}

data '60010200010480EC04038090A21803A983811C0E...'H

}

tunnelledSignallingMessage

{

tunnelledProtocolID

{

id tunnelledProtocolAlternateID :

{

protocolType "gtd"

}

messageContent

{

'49414D2C0D0A50524E2C6973646E2A2C2C4E492A...'H

}

tunnellingRequired NULL

}

Dec 28 15:22:45.882: H225.0 OUTGOING ENCODE BUFFER::= 2080060008914A00042800B500001240013C0501000042358F99503911E2800DF866F26A484000CD1D820007000A016464F841110042358F99503911E2804A903A21A7A74D3402130000000D4001800B050001000A0164644027001E400000060401004D40018012150001000A0164644026000A0164644027000100010001800180010010A8018080FC0140B500001280F460010200010480EC04038090A21803A983811C0E9F8B0100A10802015C02010084006C0C2183323034333632303738387008C1333235393030391CB89E810003677464000000AD49414D2C0D0A50524E2C6973646E2A2C2C4E492A2A2A2C0D0A5553492C726174652C632C732C632C310D0A5553492C6C6179312C756C61770D0A544D522C30300D0A43504E2C30322C2C312C333235393030390D0A43474E2C30342C2C312C792C342C323034333632303738380D0A4350432C30390D0A4643492C2C2C2C2C2C2C792C0D0A4743492C34323335386639393530333931316532383030646638363666323661343834300D0A0D0A80B542046774640180AD49414D2C0D0A50524E2C6973646E2A2C2C4E492A2A2A2C0D0A5553492C726174652C632C732C632C310D0A5553492C6C6179312C756C61770D0A544D522C30300D0A43504E2C30322C2C312C333235393030390D0A43474E2C30342C2C312C792C342C323034333632303738380D0A4350432C30390D0A4643492C2C2C2C2C2C2C792C0D0A4743492C34323335386639393530333931316532383030646638363666323661343834300D0A0D0A

Dec 28 15:22:45.882:

Dec 28 15:22:46.242: H225.0 INCOMING ENCODE BUFFER::= 2180060008914A000522C0B50000120F436973636F43616C6C4D616E6167657200310110C0110042358F99503911E2804A903A21A7A74D0100010010A00100100140B500001209820400000400010300

Dec 28 15:22:46.242:

Dec 28 15:22:46.242: H225.0 INCOMING PDU ::=

value H323_UserInformation ::=

{

h323-uu-pdu

{

h323-message-body callProceeding :

{

protocolIdentifier { 0 0 8 2250 0 5 }

destinationInfo

{

vendor

{

vendor

{

t35CountryCode 181

t35Extension 0

manufacturerCode 18

}

productId '436973636F43616C6C4D616E61676572'H

versionId '31'H

}

terminal

{

}

mc FALSE

undefinedNode FALSE

}

callIdentifier

{

guid '42358F99503911E2804A903A21A7A74D'H

}

multipleCalls FALSE

maintainConnection FALSE

}

h245Tunneling FALSE

nonStandardControl

{

nonStandardIdentifier h221NonStandard :

{

t35CountryCode 181

t35Extension 0

manufacturerCode 18

}

data '820400000400010300'H

}

Dec 28 15:22:46.242: H225 NONSTD INCOMING ENCODE BUFFER::= 820400000400010300

Dec 28 15:22:46.242:

Dec 28 15:22:46.242: H225 NONSTD INCOMING PDU ::=

value H323_UU_NonStdInfo ::=

{

callMgrParam

{

interclusterVersion 3

enterpriseID {}

}

Dec 28 15:22:46.242: //317/42358F99800D/CCAPI/cc_api_set_called_ccm_detected:

CallInfo(called ccm detected=TRUE ccmVersion 3)

Dec 28 15:22:46.242: //317/42358F99800D/CCAPI/cc_api_call_proceeding:

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

Dec 28 15:22:46.246: H225.0 INCOMING ENCODE BUFFER::= 2580060008914A00051100110042358F99503911E2804A903A21A7A74D10800100

Dec 28 15:22:46.246:

Dec 28 15:22:46.246: H225.0 INCOMING PDU ::=

value H323_UserInformation ::=

{

h323-uu-pdu

{

h323-message-body releaseComplete :

{

protocolIdentifier { 0 0 8 2250 0 5 }

callIdentifier

{

guid '42358F99503911E2804A903A21A7A74D'H

}

h245Tunneling FALSE

}

Dec 28 15:22:46.246: //317/42358F99800D/CCAPI/cc_api_call_disconnected:

Cause Value=27, Interface=0x31850F48, Call Id=317

Dec 28 15:22:46.246: //317/42358F99800D/CCAPI/cc_api_call_disconnected:

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

Dec 28 15:22:46.246: //315/42358F99800D/CCAPI/ccCallReleaseResources:

release reserved xcoding resource.

Dec 28 15:22:46.246: //317/42358F99800D/CCAPI/ccCallSetAAA_Accounting:

Accounting=0, Call Id=317

Dec 28 15:22:46.246: //317/42358F99800D/CCAPI/ccCallDisconnect:

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

Dec 28 15:22:46.246: //317/42358F99800D/CCAPI/ccCallDisconnect:

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

Dec 28 15:22:46.246: //317/42358F99800D/CCAPI/cc_api_get_transfer_info:

Transfer Number=NULL

Dec 28 15:22:46.246: H225.0 OUTGOING PDU ::=

value H323_UserInformation ::=

{

h323-uu-pdu

{

h323-message-body releaseComplete :

{

protocolIdentifier { 0 0 8 2250 0 4 }

callIdentifier

{

guid '42358F99503911E2804A903A21A7A74D'H

}

h245Tunneling FALSE

}

Dec 28 15:22:46.246: H225.0 OUTGOING ENCODE BUFFER::= 2580060008914A00041100110042358F99503911E2804A903A21A7A74D10800100

Dec 28 15:22:46.246:

Dec 28 15:22:46.246: TCP0: state was ESTAB -> FINWAIT1 [63553 -> 10.1.1.12(1720)]

Dec 28 15:22:46.246: TCP0: sending FIN

Dec 28 15:22:46.246: //317/42358F99800D/CCAPI/cc_api_call_disconnect_done:

Disposition=0, Interface=0x31850F48, Tag=0x0, Call Id=317,

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

Dec 28 15:22:46.246: //317/42358F99800D/CCAPI/cc_api_call_disconnect_done:

Call Disconnect Event Sent

Dec 28 15:22:46.246: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

Dec 28 15:22:46.246: :cc_free_feature_vsa freeing 2CE3C500

Dec 28 15:22:46.246: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

Dec 28 15:22:46.246: vsacount in free is 1

Dec 28 15:22:46.250: //315/42358F99800D/CCAPI/ccCallDisconnect:

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

Dec 28 15:22:46.250: //315/42358F99800D/CCAPI/ccCallDisconnect:

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

Dec 28 15:22:46.250: //315/42358F99800D/CCAPI/cc_api_get_transfer_info:

Transfer Number=NULL

Dec 28 15:22:46.250: TCP0: state was FINWAIT1 -> FINWAIT2 [63553 -> 10.1.1.12(1720)]

Dec 28 15:22:46.250: TCP0: FIN processed

Dec 28 15:22:46.250: TCP0: state was FINWAIT2 -> TIMEWAIT [63553 -> 10.1.1.12(1720)]

Dec 28 15:22:46.250: ISDN Se0/0/0:23 Q931: TX -> DISCONNECT pd = 8 callref = 0xFE0C

Cause i = 0x809B - Destination out of order

Dec 28 15:22:47.050: ISDN Se0/0/0:23 Q931: RX <- RELEASE pd = 8 callref = 0x7E0C

vr#

Dec 28 15:22:47.058: ISDN Se0/0/0:23 Q931: TX -> RELEASE_COMP pd = 8 callref = 0xFE0C

Dec 28 15:22:47.062: //315/42358F99800D/CCAPI/cc_api_call_disconnect_done:

Disposition=0, Interface=0x323209CC, Tag=0x0, Call Id=315,

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

Dec 28 15:22:47.062: //315/42358F99800D/CCAPI/cc_api_call_disconnect_done:

Call Disconnect Event Sent

Dec 28 15:22:47.062: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

Dec 28 15:22:47.062: :cc_free_feature_vsa freeing 2CE3C5E0

Dec 28 15:22:47.062: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

Dec 28 15:22:47.062: vsacount in free is 0

vr#

Dec 28 15:22:47.614: TCP389: ACK timeout timer expired

Dec 28 15:22:47.614: TCP389: bad seg from 10.11.200.5 -- outside window: port 22 seq 4156975486 ack 2825658332 rcvnxt 4156975574 rcvwnd 3624 len 88

vr#

Dec 28 15:22:50.494: RAS OUTGOING PDU ::=

value RasMessage ::= gatekeeperRequest :

{

requestSeqNum 1347

protocolIdentifier { 0 0 8 2250 0 4 }

rasAddress ipAddress :

{

ip '0A016464'H

port 51584

}

endpointType

{

vendor

{

vendor

{

t35CountryCode 181

t35Extension 0

manufacturerCode 18

}

gateway

{

protocol

{

voice :

{

vr#supportedPrefixes

{

}

mc FALSE

undefinedNode FALSE

}

Dec 28 15:22:50.494: RAS OUTGOING ENCODE BUFFER::= 00000542060008914A0004000A016464C9802800B500001240013C05010000

Dec 28 15:22:50.494:

vr#

Dec 28 15:22:55.493: RAS OUTGOING PDU ::=

value RasMessage ::= gatekeeperRequest :

{

requestSeqNum 1347

protocolIdentifier { 0 0 8 2250 0 4 }

rasAddress ipAddress :

{

ip '0A016464'H

port 51584

}

endpointType

{

vendor

{

vendor

{

t35CountryCode 181

t35Extension 0

manufacturerCode 18

}

gateway

{

protocol

{

voice :

{

vr#supportedPrefixes

{

}

mc FALSE

undefinedNode FALSE

}

Dec 28 15:22:55.493: RAS OUTGOING ENCODE BUFFER::= 00000542060008914A0004000A016464C9802800B500001240013C05010000

Dec 28 15:22:55.493:

SIP stack and the transport layer

How does this apply to SIP then? good question..

For any sip signaling to occur, INVITE etc, your transport layer needs to be active. Without an active TCP or UDP connection, no sip messagin packets can be delivered to its intended destination. This is very crucial to know when troubleshooting complex sip related issues.

To see the transaction at the transport layer, you will need to use "debug ccsip all on the CUBE" be careful with this as this can potentially make your gateway unstable. Ensure this is done when there is minimal traffic on the CUBE

SIP over TCP, trace analysis

ITSP---SIP--CUBE---SIP---CUCM--SCCP--IP phone

+++We get an INVITE from ITSP to CUBE++++ This was over UDP..I have skipped that bit, we will come to it later

Received:
INVITE sip:441524268009@172.16.40.74:5060 SIP/2.0
Via: SIP/2.0/UDP 10.106.38.24:5081;branch=z9hG4bKviun6d007oohoante3q0.1
From: <sip:07824433293@212.136.178.216:5060;user=phone>;tag=716266201-1392681048861-
Call-ID: BW235048861170214-1531745628@212.136.178.216
CSeq: 555822479 INVITE

+++Next we see what CUBE does before it sends this INVITE out to CUCM (172.16.40.104). CUBE goes into its transport stack to create a TCP connection to the cucm.++++

+++CUBE chooses who the target_host and the outbound_host is. If there is no outbound_host, then a target host is used++++

6048941: Feb 17 23:38:43.882: //13207949/000000000000/SIP/Info/ccsip_call_setup_request: After processing SETUP REQccb->pld.flags_ipip = 400000
6048942: Feb 17 23:38:43.882: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetOutboundHostAndDestHostPrivate: CCSIP: target_host : 172.16.40.104 target_port : 5060

6055494: Feb 17 23:50:48.868: //13207995/291F11629FB7/SIP/Transport/sipSPISendInvite: Sending Invite to the transport layer
6055495: Feb 17 23:50:48.868: //13207995/291F11629FB7/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE
6055496: Feb 17 23:50:48.868: //13207995/291F11629FB7/SIP/Transport/sipSPITransportSendMessage: msg=0x2B45213C, addr=172.16.40.104, port=5060, sentBy_port=0, local_addr=172.16.40.74, is_req=1, transport=2, switch=0, callBack=0x41386D6
6055497: Feb 17 23:50:48.868: //13207995/291F11629FB7/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
6055498: Feb 17 23:50:48.868: //13207995/291F11629FB7/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0

++++++Next we see what CUBE does before it sends this INVITE out to CUCM (172.16.40.104)+++++

+++CUBE chooses who the target_host and the outbound_host is. If there is no outbound_host, then a target host is used++++

6055335: Feb 17 23:50:48.868: //13207995/000000000000/SIP/Info/ccsip_call_setup_request: After processing SETUP REQccb->pld.flags_ipip = 400000
6055336: Feb 17 23:50:48.868: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetOutboundHostAndDestHostPrivate: CCSIP: target_host : 10.105.40.104 target_port : 5060

+++CUBE attempts to create a TCP connection to the target host and starts the TCP connection timer to monitor the request+++

6055499: Feb 17 23:50:48.868: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostRequestConnection: Posting TCP conn create request for addr=172.16.40.104, port=5060, context=0x20DFE258
6055500: Feb 17 23:50:48.868: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetConnWaitTimer: Wait timer set for connection=0x20E00B0C,addr=172.16.40.104, port=5060
6055501: Feb 17 23:50:48.868: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportSetConnWaitTimer:
Wait Conn Timer started for 5000 msec

+++Next CUBE sends a trying to ITSP+++

Sent:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 10.106.38.24:5081;branch=z9hG4bKviun6d007oohoante3q0.1
From: <sip:07824433293@212.136.178.216:5060;user=phone>;tag=716266201-1392681048861-
Date: Mon, 17 Feb 2014 23:50:48 GMT
Call-ID: BW235048861170214-1531745628@212.136.178.216

++++Next after 500msec (the tcp timer expires and CUBE didnt get a response back from the CUCM, it tore down the TCP instance and immediately disconnected the call without even sending the INVITE to cucm++++

6055579: Feb 17 23:50:53.685: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIHandleServerTCBTimerPop: Die timer Popped on TCB(0x1FDBF160)
6055580: Feb 17 23:50:53.685: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIFreeOneTCB: Sizeof tcbQ: 15
6055581: Feb 17 23:50:53.685: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIFreeOneTCB: DeQ'd TCB(0x1FDBF160) from EDB(0x2C71E87C)
6055582: Feb 17 23:50:53.685: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIFreeOneTCB: EnQing TCB(0x1FDBF160) for reuse
6055583: Feb 17 23:50:53.685: //0/000000000000/SIP/Info/sipSPITerminateEvent: 14 Transactions still active on Event:kpml ID:
6055584: Feb 17 23:50:53.869: //13207995/291F11629FB7/SIP/Transport/sipTransportPostInternalMsg: Posting Internal Msg type=1
6055585: Feb 17 23:50:53.869: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostCloseConnection: Posting TCP conn close for addr=172.16.40.104, port=5060, local_addr=172.16.40.74, connid=3
6055586: Feb 17 23:50:53.869: //-1/xxxxxxxxxxxx/SIP/Transport/sipDeleteConnInstance: Deleted conn=0x20E00B0C, connid=3, addr=172.16.40.104, port=5060, local_addr=172.16.40.74, transport=TCP
6055587: Feb 17 23:50:53.869: //-1/xxxxxxxxxxxx/SIP/Info/sip_tcp_purge_entry: Socket fd: 0 closed for connid 3 with address: 172.16.40.104, remote port: 5060
6055588: Feb 17 23:50:53.869: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 61
6055589: Feb 17 23:50:53.869: //13207995/291F11629FB7/SIP/Error/sipTransportPostSendFailure: Posting send failure msg
6055590: Feb 17 23:50:53.869: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 53
6055591: Feb 17 23:50:53.869: //-1/xxxxxxxxxxxx/SIP/Error/act_idle_send_msg_failure: Send Error to 172.16.40.104:5060 for transport TCP
6055592: Feb 17 23:50:53.869: //13207995/291F11629FB7/SIP/Info/ccsip_set_cc_cause_for_spi_err: Categorized cause:38, category:186

NB: With TCP, the retry timers and the retry INVITE configured on CUBE/CUCM do not have any impact. SIP over TCP relies on the tcp connect timer.

I believe you can adjust the tcp timer with the command below: The default is 500ms

voice service voip

sip-ua

timers connect 150

Now lets consider UDP

SIP over UDP, trace analysis

ITSP---SIP--CUBE---SIP---CUCM--SCCP--IP phone

+++INVITE received from ITSP+++++

Received:
INVITE sip:441524268009@172.16.40.74:5060 SIP/2.0
Via: SIP/2.0/UDP 10.106.38.24:5081;branch=z9hG4bKfvh0u4006gchdc3ui0j1.1
From: <sip:07824433293@212.136.178.216:5060;user=phone>;tag=405705061-1392680323875-Call-ID: BW233843875170214-1076124930@212.136.178.216
CSeq: 555459986 INVITE

++++++Next we see what CUBE does before it sends this INVITE out to CUCM (172.16.40.104)+++++

+++CUBE chooses who the target_host and the outbound_host is. If there is no outbound_host, then a target host is used++++

6048941: Feb 17 23:38:43.882: //13207949/000000000000/SIP/Info/ccsip_call_setup_request: After processing SETUP REQccb->pld.flags_ipip = 400000
6048942: Feb 17 23:38:43.882: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetOutboundHostAndDestHostPrivate: CCSIP: target_host : 172.16.40.104 target_port : 5060

+++Next CUBE goes into its transport stack to create a UDP connection to the target host.++++

++In reality there is no connection before the messages are sent through+++

6049144: Feb 17 23:38:44.384: //13207949/78FF09239F64/SIP/Transport/sipSPISendInvite: Sending Invite to the transport layer
6049145: Feb 17 23:38:44.384: //13207949/78FF09239F64/SIP/Transport/sipSPIGetSwitchTransportFlag: Return the Global configuration, Switch Transport is FALSE
6049146: Feb 17 23:38:44.384: //13207949/78FF09239F64/SIP/Transport/sipSPITransportSendMessage: msg=0x2D8643FC, addr=172.16.40.104, port=5060, sentBy_port=0, local_addr=172.16.40.74, is_req=1, transport=1, switch=0, callBack=0x0
6049147: Feb 17 23:38:44.384: //13207949/78FF09239F64/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
6049148: Feb 17 23:38:44.384: //13207949/78FF09239F64/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
6049149: Feb 17 23:38:44.384: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:172.16.40.104, rport:5060 with laddr:172.16.40.74

6049150: Feb 17 23:38:44.384: //13207949/78FF09239F64/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x2D8643FC
6049151: Feb 17 23:38:44.384: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x2D8643FC, addr=172.16.40.104, port=5060, local_addr=172.16.40.74, connId=7 for UDP

++++Next we see CUBE sending the INVITE out immediately, this confirms that it doesnt wait for any connection establishment as TCP does+++

6049152: Feb 17 23:38:44.384: //13207949/78FF09239F64/SIP/Msg/ccsipDisplayMsg:

Sent:
INVITE sip:901524268009@172.16.40.104:5060 SIP/2.0
Via: SIP/2.0/UDP 172.16.40.74:5060;branch=z9hG4bK27CD90BBA7
Remote-Party-ID: <sip:07824433293@172.16.40.74>;party=calling;screen=no;privacy=off
From: <sip:07824433293@172.16.40.74>;tag=CB3DC3F8-148D
To: <sip:901524268009@172.16.40.104>
Date: Mon, 17 Feb 2014 23:38:44 GMT
Call-ID: 78FFA54B-976311E3-9F6A8F4D-5D7E5E41@172.16.40.74

+++Exactly 1sec after the first INVITE was sent, CUBE sends another INVITE because it didnt get a response to the first one++++

6049164: Feb 17 23:38:45.384: //13207949/78FF09239F64/SIP/Msg/ccsipDisplayMsg:

Sent:
INVITE sip:901524268009@172.16.40.104:5060 SIP/2.0
Via: SIP/2.0/UDP 172.16.40.74:5060;branch=z9hG4bK27CD90BBA7
Remote-Party-ID: <sip:07824433293@172.16.40.74>;party=calling;screen=no;privacy=off
From: <sip:07824433293@172.16.40.74>;tag=CB3DC3F8-148D
To: <sip:901524268009@172.16.40.104>
Date: Mon, 17 Feb 2014 23:38:45 GMT
Call-ID: 78FFA54B-976311E3-9F6A8F4D-5D7E5E41@172.16.40.74

+++Exactly 2 secs after the last INVITE CUBE sends an out of retreis message and disconnected the call+++

6049165: Feb 17 23:38:47.385: //13207949/78FF09239F64/SIP/Error/act_sentinvite_wait_100: Out of retries
6049166: Feb 17 23:38:47.385: //13207949/78FF09239F64/SIP/Info/ccsip_set_cc_cause_for_spi_err: Categorized cause:102, category:129
6049167: Feb 17 23:38:47.385: //13207949/78FF09239F64/SIP/Info/ccsip_set_release_source_for_peer: ownCallId[13207949], src[6]
6049168: Feb 17 23:38:47.385: //13207949/78FF09239F64/SIP/Info/sipSPIInitiateDisconnect: Initiate call disconnect(102) for outgoing call

The sip timers configured on the CUBE impacted how many retries was sent and the time in between retries. The config on this cube was this

sip-ua
retry invite 2

This meant that the default timers retrying time of 500ms was used. That's not a good idea, you should always change your timers from the default..This is a good one to use..

sip-ua
retry invite 2
timers trying 150

It is important to note that with OPTIONS ping configured this behaviour will be different. CUBE/CUCM marks a dial-peer down when it doesn't receive a response to the OPTIONS ping sent to the target host....

MUSINGS:

The transport layer play an important role in any UC solution. Whether you are using H323, SIP or MGCP you need to understand what happens at the transport layer for you to be able to manage, troubleshoot effectively.

Aman Soi · ‎03-17-2014

Thanks for sharing the detailed blog.

regds,

aman