[cisco-voip] SIP Session progress voip loop problem on AS5XXX
Yura Monchak
yurun at portaone.com
Fri Jun 17 17:15:53 EDT 2005
Hello Voip Expert!
Again I am stuck with my investigation on this problem. The call
scenario is as follows
ISDN/PSTN USER A-----(LEG1)-------->AS5XXX------(LEG2)-------->SIP Proxy
ISDN/PSTN USER B<-----(LEG4)--------AS5XXX<------(LEG3)--------SIP Proxy
The call is originally addressed to the remote VOIP SIP proxy UA, but
SIP proxy decided to send it back to the same cisco for PSTN number B
termination as a redirect feature, because SIP UA was not available at
that time. SIP request relaying looks perfect for legs 2 and 3, the call
gets connected normally after USER B picks up the phone, however
progress tone sounds are not heard by the USER A.
USER A will always hear progress tones, if the terminating cisco (or
any other) gateway is not the same as originating cisco one. The problem
seems to be IOS independent and appears on 12.3.X IOSes.
Lower goes a debug output of handling 183 (sent and received). Does
anyone have any ideas where can I figure out the early audio loss point?
I almost sure the problem is somewhere on IP side, when cisco is trying
to send packets to itself. It seems to be the only circumstance that
belongs to the calls with this problem.
Thanks for any input.
Jun 17 07:47:09.345: Queued event from SIP SPI :
SIPSPI_EV_CC_CALL_PROCEEDING
Jun 17 07:47:09.345: CCSIP-SPI-CONTROL: act_recdinvite_proceeding
Jun 17 07:47:09.345: ISDN Se7/1:15 Q931: TX -> SETUP pd = 8 callref =
0x72E1
Bearer Capability i = 0x8090A3
Standard = CCITT
Transer Capability = Speech
Transfer Mode = Circuit
Transfer Rate = 64 kbit/s
Channel ID i = 0xA9839D
Exclusive, Channel 29
Calling Party Number i = 0x2180, '41245946'
Plan:ISDN, Type:National
Called Party Number i = 0x80, '23035950'
Plan:Unknown, Type:Unknown
Jun 17 07:47:10.117: ISDN Se7/1:15 Q931: RX <- CALL_PROC pd = 8 callref
= 0xF2E1
Channel ID i = 0xA9839D
Exclusive, Channel 29
Progress Ind i = 0x8288 - In-band info or appropriate now available
Jun 17 07:47:10.117: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_PROGRESS
Jun 17 07:47:10.117: CCSIP-SPI-CONTROL: ccsip_bridge: confID = 32804,
srcCallID = 80902, dstCallID = 80903
Jun 17 07:47:10.117: sipSPIUupdateCcCallIds: old src/dest ccCallids:
-1/-1, new src/dest ccCallids: 80902/80903
Jun 17 07:47:10.117: sipSPIUupdateCcCallIds: old streamcallid=-1, new
streamcallid=80902
Jun 17 07:47:10.117: CCSIP-SPI-CONTROL: sipSPIIncomingCallSDP
Jun 17 07:47:10.121: sipSPIUpdateSrcSdpFixedPart
Jun 17 07:47:10.121: sipSPIReserveRtpPort: reserved port 16886 for stream 1
Jun 17 07:47:10.121: sipSPIUpdateSrcSdpFixedPart: reserving rtp port for
stream 1, src_port=16886
Jun 17 07:47:10.121: sipSPIUpdateSrcSdpVariablePart
Jun 17 07:47:10.121: sipSPIUpdateSrcSdpVariablePart: setting stream 1
portnum to 16886
Jun 17 07:47:10.121: sipSPIUpdateSrcSdpVariablePart Negotiated NSE
payload : 100
Jun 17 07:47:10.121: sipSPIProcessRtpSessions
Jun 17 07:47:10.121: sipSPIAddStream: Adding stream 1 (callid 80902) to
the VOIP RTP library
Jun 17 07:47:10.121: sipSPISetMediaSrcAddr: media src addr for stream 1
= 83.233.248.51
Jun 17 07:47:10.121: sipSPIUpdateRtcpSession: for m-line 1
Jun 17 07:47:10.121: sipSPIUpdateRtcpSession: rtcp_session info
laddr = 83.233.248.51, lport = 16886, raddr = 83.233.248.51,
rport=17708, do_rtcp=TRUE
src_callid = 80902, dest_callid = 80903, stream type = 0
Jun 17 07:47:10.121: sipSPIUpdateRtcpSession:Extract src addr:check for
media src info via callback from VOIP RTP
Jun 17 07:47:10.121: sipSPIUpdateRtcpSession: No rtp session, creating a
new one
Jun 17 07:47:10.121: CCSIP-SPI-CONTROL: ccsip_caps_ind
Jun 17 07:47:10.121: ccsip_get_rtcp_session_parameters: CURRENT VALUES:
stream_callid=80902, current_seq_num=0x2424
Jun 17 07:47:10.121: ccsip_get_rtcp_session_parameters: NEW VALUES:
stream_callid=80902, current_seq_num=0x229F
Jun 17 07:47:10.121: ccsip_caps_ind: Load DSP with negotiated codec :
g729br8, Bytes=20
Jun 17 07:47:10.121: ccsip_caps_ind: set forking flag to 0x0
Jun 17 07:47:10.121: sipSPISetDTMFRelayMode: set DSP for dtmf-relay =
CC_CAP_DTMF_RELAY_INBAND_VOICE_AND_OOB
Jun 17 07:47:10.121: sip_set_modem_caps: Preferred (or the one that came
from DSM) modem relay=1, from CLI config=0
Jun 17 07:47:10.121: sip_set_modem_caps: Disabling Modem Relay...
Jun 17 07:47:10.121: sip_set_modem_caps: Negotiation already Done. Set
negotiated Modem caps
Jun 17 07:47:10.121: sip_set_modem_caps: Modem Relay is disabled, but
passthru is enabled
Jun 17 07:47:10.121: sip_set_modem_caps: nse payload = 100, ptru mode =
4, ptru-codec=1, redundancy=0, xid=0, relay=0, sprt-retry=12,
latecncy=200, compres-dir=3, dict=1024, strnlen=32
Jun 17 07:47:10.121: sipSPISetStreamInfo: num_streams = 1
Jun 17 07:47:10.121: sipSPISetStreamInfo: adding stream type 0 from mline 1
Jun 17 07:47:10.121: sipSPISetStreamInfo: caps.stream_count=1,
caps.stream[0].stream_type=0x1, caps.stream_list.xmitFunc=voip_rtp_xmit,
caps.stream_list.context=0x65441184 (gccb)
Jun 17 07:47:10.121: ccsip_caps_ind: Load DSP with codec : g729br8, Bytes=20
Jun 17 07:47:10.121: CCSIP-SPI-CONTROL: act_recdinvite_progress
Jun 17 07:47:10.121: sipSPIValidateGtd: Signal Forward disabled
Jun 17 07:47:10.121: Session Type is Media/Qos/Security/RTR
SDP body is attached
Jun 17 07:47:10.121: CCSIP-SPI-CONTROL: sipSPIIncomingCallSDP
Jun 17 07:47:10.121: SDP already there use old sdp and updatemedia if
needed
Jun 17 07:47:10.121: sipSPIUpdateSrcSdpVariablePart
Jun 17 07:47:10.121: sipSPIUpdateSrcSdpVariablePart: setting stream 1
portnum to 16886
Jun 17 07:47:10.121: sipSPIUpdateSrcSdpVariablePart Negotiated NSE
payload : 100
Jun 17 07:47:10.121: CCSIP-SPI-CONTROL: sipSPISendInviteResponse
Jun 17 07:47:10.121: sipSPIAddLocalContact
Jun 17 07:47:10.121: sip_generate_sdp_xcaps_list: Modem Relay and T38
disabled. X-cap not needed
Jun 17 07:47:10.121: Queued event from SIP SPI : SIPSPI_EV_SEND_MESSAGE
Jun 17 07:47:10.121: sip_stats_status_code
Jun 17 07:47:10.121: 0x6462FA4C : State change from (STATE_RECD_INVITE,
SUBSTATE_NONE) to (STATE_RECD_INVITE, SUBSTATE_RECD_INVITE_RECD_PROGRESS)
Jun 17 07:47:10.121: CCSIP-SPI-CONTROL: ccsip_caps_ack
Jun 17 07:47:10.125: ccsip_caps_ack: set forking flag to 0x3
Jun 17 07:47:10.125: Sent:
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP
83.233.248.50:5061;branch=z9hG4bKa029feaf393e8cf8c0ee6aa0569e03f3;rport
From: <sip:4741245946 at 83.233.248.51>;tag=f90cc34a1adfcb73bde5baf0b40eb147
To: <sip:23035950 at 83.233.248.51>;tag=81F241D0-26A5
Date: Fri, 17 Jun 2005 07:47:09 GMT
Call-ID: CBC9E530-DE3A11D9-AA5FBBE3-F0693E81 at 83.233.248.51
Server: Cisco-SIPGateway/IOS-12.x
CSeq: 200 INVITE
Allow-Events: telephone-event
Contact: <sip:23035950 at 83.233.248.51:5060>
Content-Disposition: session;handling=required
Content-Type: application/sdp
Content-Length: 255
v=0
o=CiscoSystemsSIP-GW-UserAgent 2210 4768 IN IP4 83.233.248.51
s=SIP Call
c=IN IP4 83.233.248.51
t=0 0
m=audio 16886 RTP/AVP 18 100
c=IN IP4 83.233.248.51
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=yes
a=rtpmap:100 X-NSE/8000
a=fmtp:100 192-194
Jun 17 07:47:10.125: Received:
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 83.233.248.51:5060
Record-Route: <sip:83.233.248.50;ftag=81F1F36C-210B;lr>
From: <sip:4741245946 at 83.233.248.51>;tag=81F1F36C-210B
To: <sip:4785391895 at 83.233.248.50>;tag=28a9f146f63bf7ea41dccc739a2b2b07
Call-ID: CBC9E530-DE3A11D9-AA5FBBE3-F0693E81 at 83.233.248.51
CSeq: 101 INVITE
Server: Sippy
Content-Length: 255
Content-Type: application/sdp
v=0
o=CiscoSystemsSIP-GW-UserAgent 2210 4768 IN IP4 83.233.248.51
s=SIP Call
c=IN IP4 83.233.248.51
t=0 0
m=audio 16886 RTP/AVP 18 100
c=IN IP4 83.233.248.51
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=yes
a=rtpmap:100 X-NSE/8000
a=fmtp:100 192-194
Jun 17 07:47:10.129: HandleUdpSocketReads :Msg enqueued for SPI with
IPaddr: 83.233.248.50:5060
Jun 17 07:47:10.129: CCSIP-SPI-CONTROL: act_recdproc_new_message
Jun 17 07:47:10.129: CCSIP-SPI-CONTROL: act_recdproc_new_message_response
Jun 17 07:47:10.129: CCSIP-SPI-CONTROL: sipSPICheckResponse
Jun 17 07:47:10.129: sip_stats_status_code
Jun 17 07:47:10.129: Roundtrip delay 20864 milliseconds for method INVITE
Jun 17 07:47:10.129: HandleSIP1xxSessionProgress: Content-Disposition
NOT received in 18x response - using default Content-Disposition values
Jun 17 07:47:10.129: sipSPIDoMediaNegotiation: number of m lines is 1
Jun 17 07:47:10.129: sipSPIDoAudioNegotiation: Codec (g729br8)
Negotiation Successful on Static Payload for m-line 1
Jun 17 07:47:10.129: sipSPIDoPtimeNegotiation: No ptime present or
multiple ptime attributes that can't be handled
Jun 17 07:47:10.129: sipSPIDoDTMFRelayNegotiation: m-line index 1
Jun 17 07:47:10.129: sipSPIDoDTMFRelayNegotiation: Requested DTMF-RELAY
option(s) not found in Preferred DTMF-RELAY option list!
Jun 17 07:47:10.129: sipSPIStreamTypeAndDtmfRelay: DTMF Relay mode :
Inband Voice
Jun 17 07:47:10.129: sip_sdp_get_modem_relay_cap_params:
Jun 17 07:47:10.129: sip_sdp_get_modem_relay_cap_params: NSE payload
from X-cap = 0
Jun 17 07:47:10.129: sip_do_nse_negotiation: NSE Payload 100 found in SDP
Jun 17 07:47:10.129: sip_do_nse_negotiation: Remote NSE payload = local
one = 100, Use it
Jun 17 07:47:10.129: sip_select_modem_relay_params: X-tmr not present in
SDP. Disable modem relay
Jun 17 07:47:10.129: sipSPIGetSDPDirectionAttribute:Symmetric NAT CLI
check enabled for media source address
Jun 17 07:47:10.129: sipSPIDoAudioNegotiation: Codec negotiation
successful for media line 1
payload_type=18, codec_bytes=20, codec=g729br8,
dtmf_relay=inband-voice
stream_type=voice-only (0), dest_ip_address=83.233.248.51,
dest_port=16886
Jun 17 07:47:10.129: sipSPIReplaceSDP
Jun 17 07:47:10.129: sipSPICopySdpInfo
Jun 17 07:47:10.129: sipSPIUpdCallWithSdpInfo:
Preferred Codec : g729r8, bytes :20
Preferred DTMF relay : rtp-nte
Preferred NTE payload : 101
Early Media : No
Delayed Media : No
Bridge Done : No
New Media : No
DSP DNLD Reqd : No
Jun 17 07:47:10.129: sipSPISetMediaSrcAddr: media src addr for stream 1
= 83.233.248.51
Jun 17 07:47:10.129: sipSPIUpdCallWithSdpInfo:Stream Type:0
M-line Index : 1
State : STREAM_ADDING (2)
Callid : 80899
Negotiated Codec : g729br8, bytes :20
Negotiated DTMF relay : inband-voice
Negotiated NTE payload : 0
Negotiated CN payload : 0
Media Srce Addr/Port : 83.233.248.51:17708
Media Dest Addr/Port : 83.233.248.51:16886
Jun 17 07:47:10.129: sipSPIGetGtdBody: No valid GTD body found.
Jun 17 07:47:10.129: sipSPICreateRawMsg: No GTD passed.
Jun 17 07:47:10.129: HandleSIP1xxSessionProgress: Transaction Complete.
Lock on Facilities released.
Jun 17 07:47:10.129: CCSIP-SPI-CONTROL: ccsip_bridge: confID = 32805,
srcCallID = 80899, dstCallID = 80898
Jun 17 07:47:10.129: sipSPIUupdateCcCallIds: old src/dest ccCallids:
-1/-1, new src/dest ccCallids: 80899/80898
Jun 17 07:47:10.129: sipSPIUupdateCcCallIds: old streamcallid=80899, new
streamcallid=80899
Jun 17 07:47:10.129: sipSPIProcessRtpSessions
Jun 17 07:47:10.129: sipSPIAddStream: Adding stream 1 (callid 80899) to
the VOIP RTP library
Jun 17 07:47:10.129: sipSPISetMediaSrcAddr: media src addr for stream 1
= 83.233.248.51
Jun 17 07:47:10.129: sipSPIUpdateRtcpSession: for m-line 1
Jun 17 07:47:10.129: sipSPIUpdateRtcpSession: rtcp_session info
laddr = 83.233.248.51, lport = 17708, raddr = 83.233.248.51,
rport=16886, do_rtcp=TRUE
src_callid = 80899, dest_callid = 80898, stream type = 0
Jun 17 07:47:10.129: sipSPIUpdateRtcpSession:Extract src addr:check for
media src info via callback from VOIP RTP
Jun 17 07:47:10.129: sipSPIUpdateRtcpSession rtp session already
created - update
Jun 17 07:47:10.133: CCSIP-SPI-CONTROL: ccsip_caps_ind
Jun 17 07:47:10.133: ccsip_get_rtcp_session_parameters: CURRENT VALUES:
stream_callid=80899, current_seq_num=0x2203
Jun 17 07:47:10.133: ccsip_get_rtcp_session_parameters: NEW VALUES:
stream_callid=80899, current_seq_num=0x78B
Jun 17 07:47:10.133: ccsip_caps_ind: Load DSP with negotiated codec :
g729br8, Bytes=20
Jun 17 07:47:10.133: ccsip_caps_ind: set forking flag to 0x0
Jun 17 07:47:10.133: sipSPISetDTMFRelayMode: set DSP for dtmf-relay =
CC_CAP_DTMF_RELAY_INBAND_VOICE_AND_OOB
Jun 17 07:47:10.133: sip_set_modem_caps: Preferred (or the one that came
from DSM) modem relay=1, from CLI config=0
Jun 17 07:47:10.133: sip_set_modem_caps: Disabling Modem Relay...
Jun 17 07:47:10.133: sip_set_modem_caps: Negotiation already Done. Set
negotiated Modem caps
Jun 17 07:47:10.133: sip_set_modem_caps: Modem Relay is disabled, but
passthru is enabled
Jun 17 07:47:10.133: sip_set_modem_caps: nse payload = 100, ptru mode =
4, ptru-codec=1, redundancy=0, xid=0, relay=0, sprt-retry=12,
latecncy=200, compres-dir=3, dict=1024, strnlen=32
Jun 17 07:47:10.133: sipSPISetStreamInfo: num_streams = 1
Jun 17 07:47:10.133: sipSPISetStreamInfo: adding stream type 0 from mline 1
Jun 17 07:47:10.133: sipSPISetStreamInfo: caps.stream_count=1,
caps.stream[0].stream_type=0x1, caps.stream_list.xmitFunc=voip_rtp_xmit,
caps.stream_list.context=0x656560B8 (gccb)
Jun 17 07:47:10.133: ccsip_caps_ind: Load DSP with codec : g729br8, Bytes=20
Jun 17 07:47:10.133: CCSIP-SPI-CONTROL: ccsip_caps_ack
Jun 17 07:47:10.133: ccsip_caps_ack: set forking flag to 0x3
Jun 17 07:47:10.133: ISDN Se7/0:15 Q931: TX -> PROGRESS pd = 8 callref
= 0x800C
Progress Ind i = 0x8188 - In-band info or appropriate now available
Jun 17 07:47:10.277: sipSPIUpdateMediaSrcInfo: NEW callids are :
mainstcallid: 80899, stream_callid:80899
Jun 17 07:47:10.277: sipSPIUpdateMediaSrcInfo NEW:rtp session to be
updated with the new src info old addr:port 83.233.248.51:16886 ,
newaddr:port 83.233.248.51:16886
Jun 17 07:47:10.281: sipSPIUpdateMediaSrcInfo: NEW callids are :
mainstcallid: 80902, stream_callid:80902
Jun 17 07:47:10.281: sipSPIUpdateMediaSrcInfo NEW:rtp session to be
updated with the new src info old addr:port 83.233.248.51:17708 ,
newaddr:port 83.233.248.51:17708
Jun 17 07:47:12.009: ISDN Se7/1:15 Q931: RX <- ALERTING pd = 8 callref
= 0xF2E1
Progress Ind i = 0x8488 - In-band info or appropriate now available
Progress Ind i = 0x8188 - In-band info or appropriate now available
Jun 17 07:47:12.009: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_ALERTING
Jun 17 07:47:12.009: CCSIP-SPI-CONTROL: act_recdinvite_alerting
Jun 17 07:47:12.009: sipSPIValidateGtd: Signal Forward disabled
Jun 17 07:47:14.025: ISDN Se7/1:15 Q931: RX <- ALERTING pd = 8 callref
= 0xF2E0
Progress Ind i = 0x8488 - In-band info or appropriate now available
Jun 17 07:47:14.029: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_ALERTING
Jun 17 07:47:14.029: CCSIP-SPI-CONTROL: act_recdinvite_alerting
Jun 17 07:47:14.029: sipSPIValidateGtd: Signal Forward disabled
--
Yura Monchak
More information about the cisco-voip
mailing list