Calls have no return voice to GSM(UC540)

[divine007]

Hello All

I have a uc540, that users can, make outgoing calls to gsm, but cant get a return voice

Here is the log i have gathered by doing show log

000280:  Jul 30 16:44:40.729:  //101/E9A6F0698127/SIP/Info/sipSPICheckResponseExt: INVITE response with  no RSEQ - disable IS_REL1XX

000281: Jul 30 16:44:40.729:  //101/E9A6F0698127/SIP/Error/sipSPICheckReliableProvStringtag: Unable to  access supported header values

000282: Jul 30 16:44:40.729: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentGTD: No GTD found in inbound container

000283: Jul 30 16:44:40.729: //101/E9A6F0698127/SIP/Info/sipSPIDoMediaNegotiation: Number of m-lines = 1

SIP: Attribute mid, level 1 instance 1 not found.

000284:  Jul 30 16:44:40.729:  //101/E9A6F0698127/SIP/Info/resolve_media_ip_address_to_bind: Media  already bound, use existing source_media_ip_addr

000285: Jul 30 16:44:40.729: //101/E9A6F0698127/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 192.168.30.1

000286:  Jul 30 16:44:40.729:  //101/E9A6F0698127/SIP/Info/sipSPIDoAudioNegotiation: Codec (g711ulaw)  Negotiation Successful on Static Payload for m-line 1

000287: Jul 30 16:44:40.729: //101/E9A6F0698127/SIP/Info/sipSPIDoPtimeNegotiation: One ptime attribute found - value:20

000288:  Jul 30 16:44:40.729:  //-1/xxxxxxxxxxxx/SIP/Info/convert_ptime_to_codec_bytes: Values :Codec:  g711ulaw ptime :20, codecbytes: 160

000289: Jul 30 16:44:40.729:  //-1/xxxxxxxxxxxx/SIP/Info/convert_codec_bytes_to_ptime: Values :Codec:  g711ulaw codecbytes :160, ptime: 20

000290: Jul 30 16:44:40.729:  //101/E9A6F0698127/SIP/Media/sipSPIDoPtimeNegotiation: Offered ptime:20,  Negotiated ptime:20 Negotiated codec bytes: 160 for codec g711ulaw

000291: Jul 30 16:44:40.729: //101/E9A6F0698127/SIP/Info/sipSPIDoDTMFRelayNegotiation: m-line index 1

000292: Jul 30 16:44:40.729: //101/E9A6F0698127/SIP/Info/sipSPICheckDynPayloadUse: Dynamic payload(101) could not be reserved.

000293: Jul 30 16:44:40.729: //101/E9A6F0698127/SIP/Info/sipSPIDoDTMFRelayNegotiation: RTP-NTE DTMF relay option

000294:  Jul 30 16:44:40.729:  //101/E9A6F0698127/SIP/Info/sipSPIDoDTMFRelayNegotiation: Case of full  named event(NE) match in fmtp list of events.

000295: Jul 30 16:44:40.729: //-1/xxxxxxxxxxxx/SIP/Info/sip_sdp_get_modem_relay_cap_params: NSE payload from X-cap = 0

000296:  Jul 30 16:44:40.729:  //101/E9A6F0698127/SIP/Info/sip_select_modem_relay_params: X-tmr not  present in SDP. Disable modem relay

000297: Jul 30 16:44:40.729:  //101/E9A6F0698127/SIP/Info/sipSPIGetSDPDirectionAttribute: No direction  attribute present or multiple direction attributes that can't be  handled for m-line:1 and num-a-lines:0

000298: Jul 30 16:44:40.729: //101/E9A6F0698127/SIP/Info/sipSPIDoAudioNegotiation: Codec negotiation successful for media line 1

        payload_type=0, codec_bytes=160, codec=g711ulaw, dtmf_relay=rtp-nte

        stream_type=voice+dtmf (1), dest_ip_address=41.190.224.227, dest_port=13000

000299:  Jul 30 16:44:40.729:  //101/E9A6F0698127/SIP/State/sipSPIChangeStreamState: Stream (callid =   -1)  State changed from (STREAM_DEAD) to (STREAM_ADDING)

000300: Jul 30 16:44:40.733: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISipSdpFree:

000301: Jul 30 16:44:40.733: //101/E9A6F0698127/SIP/Media/sipSPIUpdCallWithSdpInfo:

        Preferred Codec        : g711ulaw, bytes :160

        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

000302:  Jul 30 16:44:40.733:  //101/E9A6F0698127/SIP/Info/resolve_media_ip_address_to_bind: Media  already bound, use existing source_media_ip_addr

000303: Jul 30 16:44:40.733: //101/E9A6F0698127/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 192.168.30.1

000304: Jul 30 16:44:40.733: //101/E9A6F0698127/SIP/Media/sipSPIUpdCallWithSdpInfo:

          Stream type            : voice+dtmf

          Media line             : 1

          State                  : STREAM_ADDING (2)

          Stream address type    : 1

          Callid                 : 101

          Negotiated Codec       : g711ulaw, bytes :160

          Nego. Codec payload    : 0 (tx), 0 (rx)

          Negotiated DTMF relay  : rtp-nte

          Negotiated NTE payload : 101 (tx), 101 (rx)

          Negotiated CN payload  : 0

          Media Srce Addr/Port   : [192.168.30.1]:18806

          Media Dest Addr/Port   : [41.190.224.227]:13000

000305: Jul 30 16:44:40.733: //101/E9A6F0698127/SIP/Info/sipSPIProcessHistoryInfoHeader: No HI headers recvd from app container

000306: Jul 30 16:44:40.733: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQSIG: No QSIG Body found in inbound container

000307: Jul 30 16:44:40.733: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentQ931: No RawMsg Body found in inbound container

000308: Jul 30 16:44:40.733: //-1/xxxxxxxxxxxx/SIP/Info/sipSPICreateNewRawMsg: No Data to form The Raw Message

000309:  Jul 30 16:44:40.733:  //101/E9A6F0698127/SIP/Info/HandleSIP1xxSessionProgress:  ccsip_api_call_cut_progress returned: SIP_SUCCESS

000310: Jul 30  16:44:40.733: //101/E9A6F0698127/SIP/State/sipSPIChangeState: 0x8786E308  : State change from (STATE_RECD_PROCEEDING,  SUBSTATE_PROCEEDING_PROCEEDING)  to (STATE_RECD_PROCEEDING,  SUBSTATE_PROCEEDING_PROCEEDING)

000311: Jul 30 16:44:40.733:  //101/E9A6F0698127/SIP/Info/HandleSIP1xxSessionProgress: Transaction  Complete. Lock on Facilities released.

000312: Jul 30 16:44:40.733: //101/E9A6F0698127/SIP/Info/ccsip_bridge: confID = 21, srcCallID = 101, dstCallID = 100

000313:  Jul 30 16:44:40.733:  //101/E9A6F0698127/SIP/Info/sipSPIUupdateCcCallIds: Old src/dest  ccCallids: -1/-1, new src/dest ccCallids: 101/100

000314: Jul 30 16:44:40.733: //101/E9A6F0698127/SIP/Info/sipSPIUupdateCcCallIds: Old streamcallid=101, new streamcallid=101

000315: Jul 30 16:44:40.733: //101/E9A6F0698127/SIP/Info/ccsip_gw_set_sipspi_mode: Setting SPI mode to SIP-TDM

000316:  Jul 30 16:44:40.733: //101/E9A6F0698127/SIP/Info/ccsip_bridge:  xcoder_attached = 0, xmitFunc = -2141347968, ccb xmitFunc = -2141347968

000317: Jul 30 16:44:40.733: //101/E9A6F0698127/SIP/Media/sipSPIProcessRtpSessions: sipSPIProcessRtpSessions

000318:  Jul 30 16:44:40.733: //101/E9A6F0698127/SIP/Media/sipSPIAddStream:  Adding stream 1 of type voice+dtmf (callid 101) to the VOIP RTP library

000319:  Jul 30 16:44:40.733:  //101/E9A6F0698127/SIP/Info/resolve_media_ip_address_to_bind: Media  already bound, use existing source_media_ip_addr

000320: Jul 30 16:44:40.733: //101/E9A6F0698127/SIP/Media/sipSPISetMediaSrcAddr: Media src addr for stream 1 = 192.168.30.1

000321: Jul 30 16:44:40.733: //101/E9A6F0698127/SIP/Media/sipSPIUpdateRtcpSession: sipSPIUpdateRtcpSession for m-line 1

000322: Jul 30 16:44:40.733: //101/E9A6F0698127/SIP/Media/sipSPIUpdateRtcpSession: rtcp_session info

        laddr = 192.168.30.1, lport = 18806, raddr = 41.190.224.227, rport=13000, do_rtcp=TRUE

        src_callid = 101, dest_callid = 100, stream type = voice+dtmf, stream direction = SENDRECV

        media_ip_addr = 41.190.224.227, vrf tableid = 0 media_addr_type = 1

000323: Jul 30 16:44:40.733: //101/E9A6F0698127/SIP/Media/sipSPIUpdateRtcpSession: RTP session already created - update

000324: Jul 30 16:44:40.733: //101/E9A6F0698127/SIP/Media/sipSPIUpdateRtpSession: stun is disabled for stream:88027A8C

000325: Jul 30 16:44:40.737: //101/E9A6F0698127/SIP/Info/sipSPIUpdateRtcpSession:

DTMF inb/oob iwf enabled 0

000326: Jul 30 16:44:40.737: //101/E9A6F0698127/SIP/Media/sipSPIGetNewLocalMediaDirection:

        New Remote Media Direction = SENDRECV

        Present Local Media Direction = SENDRECV

        New Local Media Direction = SENDRECV

        retVal = 0

000327:  Jul 30 16:44:40.737:  //101/E9A6F0698127/SIP/State/sipSPIChangeStreamState: Stream (callid =   101)  State changed from (STREAM_ADDING) to (STREAM_ACTIVE)

000328: Jul 30 16:44:40.737: //101/E9A6F0698127/SIP/Info/ccsip_bridge:

DTMF inb/oob iwf enabled 0

000329: Jul 30 16:44:40.737: //101/E9A6F0698127/SIP/Info/ccsip_caps_ind: Entry

000330:  Jul 30 16:44:40.737:  //101/E9A6F0698127/SIP/Info/ccsip_get_rtcp_session_parameters: CURRENT  VALUES: stream_callid=101, current_seq_num=0x178C

000331: Jul 30  16:44:40.737:  //101/E9A6F0698127/SIP/Info/ccsip_get_rtcp_session_parameters: NEW  VALUES: stream_callid=101, current_seq_num=0x1255

000332: Jul 30 16:44:40.737: //101/E9A6F0698127/SIP/Info/ccsip_caps_ind: Load DSP with negotiated codec: g711ulaw, Bytes=160

000333: Jul 30 16:44:40.737: //101/E9A6F0698127/SIP/Info/ccsip_caps_ind: Set forking flag to 0x0

000334:  Jul 30 16:44:40.737:  //101/E9A6F0698127/SIP/Info/sipSPISetDTMFRelayMode: Set DSP for  dtmf-relay = CC_CAP_DTMF_RELAY_NTE_AND_OOB with rx payload = 101, tx  payload = 101

000335: Jul 30 16:44:40.737:  //101/E9A6F0698127/SIP/Info/sip_set_modem_caps: Preferred (or the one  that came from DSM) modem relay=0, from CLI config=0

000336: Jul 30 16:44:40.737: //101/E9A6F0698127/SIP/Info/sip_set_modem_caps: Disabling Modem Relay...

000337:  Jul 30 16:44:40.737: //101/E9A6F0698127/SIP/Info/sip_set_modem_caps:  Negotiation already Done. Set negotiated Modem caps and generate SDP  Xcap list

000338: Jul 30 16:44:40.737: //101/E9A6F0698127/SIP/Info/sip_set_modem_caps: Modem Relay & Passthru both disabled

000339:  Jul 30 16:44:40.737: //101/E9A6F0698127/SIP/Info/sip_set_modem_caps:  nse payload = 0, ptru mode = 0, ptru-codec=0, redundancy=0, xid=0,  relay=0, sprt-retry=12, latecncy=200, compres-dir=3, dict=1024,  strnlen=32

000340: Jul 30 16:44:40.737: //101/E9A6F0698127/SIP/Media/sipSPISetStreamInfo: 1 Active Streams

000341: Jul 30 16:44:40.737: //101/E9A6F0698127/SIP/Media/sipSPISetStreamInfo: Adding stream type (voice+dtmf) from media

line 1 codec g711ulaw

000342: Jul 30 16:44:40.737: //101/E9A6F0698127/SIP/Media/sipSPISetStreamInfo:

caps.stream_count=1,caps.stream[0].stream_type=0x3, caps.stream_list.xmitFunc=

000343: Jul 30 16:44:40.737: //101/E9A6F0698127/SIP/Media/sipSPISetStreamInfo: voip_rtp_xmit, caps.stream_list.context=

000344: Jul 30 16:44:40.737: //101/E9A6F0698127/SIP/Media/sipSPISetStreamInfo: 0x8A3D3F00 (gccb)

000345: Jul 30 16:44:40.737: //101/E9A6F0698127/SIP/Info/ccsip_caps_ind: Load DSP with codec : g711ulaw, Bytes=160, payload = 0

000346: Jul 30 16:44:40.737: //101/E9A6F0698127/SIP/Info/ccsip_caps_ind: ccsip_caps_ind: ccb->pld.flags_ipip = 0x2201

000347: Jul 30 16:44:40.737: //101/E9A6F0698127/SIP/Info/sipSPISrtpTranscoder:

Checking if transcoder is needed for SRTP-RTP

000348: Jul 30 16:44:40.737: //101/E9A6F0698127/SIP/Info/ccsip_caps_ind: Calling cc_api_caps_ack()

000349: Jul 30 16:44:40.737: //101/E9A6F0698127/SIP/Info/ccsip_caps_ack: Set forking flag to 0x0

000350:  Jul 30 16:44:43.529:  //101/E9A6F0698127/SIP/Info/ccsip_indicate_rt_packet_stats: Processing  stats for callid=101, proc_id=9

000351: Jul 30 16:44:46.357:  //101/E9A6F0698127/SIP/Info/ccsip_indicate_rt_packet_stats: Processing  stats for callid=101, proc_id=9

000352: Jul 30 16:44:52.321:  //101/E9A6F0698127/SIP/Info/ccsip_indicate_rt_packet_stats: Processing  stats for callid=101, proc_id=9

000353: Jul 30 16:44:56.605: //101/E9A6F0698127/SIP/Media/sipSPIUpdateRtpSession: stun is disabled for stream:88027A8C

000354: Jul 30 16:44:56.605: //101/E9A6F0698127/SIP/Info/ccsip_call_statistics: Requesting stats for callid=101

000355:  Jul 30 16:44:56.605: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo:  Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT

000356:  Jul 30 16:44:56.609:  //101/E9A6F0698127/SIP/Info/ccsip_indicate_rt_packet_stats: Processing  stats for callid=101, proc_id=1

000357: Jul 30 16:44:56.609:  //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event:  ccsip_spi_get_msg_type returned: 3 for event 7

000358: Jul 30 16:44:56.609: //101/E9A6F0698127/SIP/Info/sipSPISendCancel: Associated container=0x885EFD7C to Cancel

000359: Jul 30 16:44:56.609: //101/E9A6F0698127/SIP/Transport/sipSPISendCancel: Sending CANCEL to the transport layer

000360:  Jul 30 16:44:56.609:  //101/E9A6F0698127/SIP/Transport/sipSPITransportSendMessage:  msg=0x88027468, addr=41.190.224.226, port=5060, sentBy_port=0, is_req=1,  transport=1, switch=0, callBack=0x80EAE1FC

000361: Jul 30  16:44:56.609:  //101/E9A6F0698127/SIP/Transport/sipSPITransportSendMessage: Proceedable  for sending msg immediately

000362: Jul 30 16:44:56.609: //101/E9A6F0698127/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0

000363: Jul 30 16:44:56.609: //101/E9A6F0698127/SIP/Transport/sipTransportLogicSendMsg: Set to send the msg=0x88027468

[paolo bevilacqua]

Media Srce Addr/Port   : [192.168.30.1]:18806

Media Dest Addr/Port   : [41.190.224.227]:13000

Seems like the calls is going through NAT, possibly traversing a non Cisco router, from this the problem.