Solved: CUBE does not forward BYE from SIP SP on outbound calls

Frank Mittrup · ‎04-26-2018

Hi all,

as my SIP SP can't help, I try to discuss the issue here.

Problem is, that on outbound calls the BYE from the PSTN is not accepted by CUBE with the error "SIP Message incomplete, trashed".

BYE for inbound calls does work. Effect is, that the call is hanging on CUCM.

Question, what is wrong with this BYE or is there a config so solve this?

Thanks,

Frank

Debug ccsip messages / Debug ccsip error:

*Apr 24 15:59:33.285: //14244/C09568800000/SIP/Msg/ccsipDisplayMsg:
Received:
BYE sip:493333320@55.66.77.88:5060 SIP/2.0
Via: SIP/2.0/UDP 217.10.68.150;branch=z9hG4bKfb19.ddc1ca52207e9e3df968ead13d6d0673.0
Via: SIP/2.0/UDP 172.20.40.8;branch=z9hG4bKfb19.fbc07f2ecffc15cc63f32186eb25f7f6.0
Via: SIP/2.0/UDP 212.9.44.29:5060;branch=z9hG4bK5a59c5f8
Max-Forwards: 68
From: <sip:022222534@217.10.68.150>;tag=as0f07981a
To: <sip:7777777t0@55.66.77.88>;tag=DCBC1BF8-1A8F
Call-ID: 47A223E6-470F11E8-9D14BB9C-D0573780@55.66.77.88
CSeq: 102 BYE
Reason: Q.850;cause=16
Content-Length: 0
X-hint: rr-enforced

*Apr 24 15:59:33.285: //-1/xxxxxxxxxxxx/SIP/Error/httpish_msg_free:
Freeing NULL pointer!
*Apr 24 15:59:33.285: //-1/xxxxxxxxxxxx/SIP/Error/sipUtilPvtVerifyIfRestricted:
From header is restricted
*Apr 24 15:59:33.285: //-1/xxxxxxxxxxxx/SIP/Error/sipUtilPvtVerifyIfRestricted:
Content-Length header is restricted
*Apr 24 15:59:33.285: //-1/xxxxxxxxxxxx/SIP/Error/sipUtilPvtVerifyIfRestricted:
To header is restricted
*Apr 24 15:59:33.285: //-1/xxxxxxxxxxxx/SIP/Error/sipUtilPvtVerifyIfRestricted:
Call-Id header is restricted
*Apr 24 15:59:33.285: //-1/xxxxxxxxxxxx/SIP/Error/sipUtilPvtVerifyIfRestricted:
Via header is restricted
*Apr 24 15:59:33.285: //-1/xxxxxxxxxxxx/SIP/Error/sipUtilPvtVerifyIfRestricted:
Cseq header is restricted
*Apr 24 15:59:33.289: //14244/C09568800000/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 217.10.68.150;branch=z9hG4bKfb19.ddc1ca52207e9e3df968ead13d6d0673.0,SIP/2.0/UDP 172.20.40.8;branch=z9hG4bKfb19.fbc07f2ecffc15cc63f32186eb25f7f6.0,SIP/2.0/UDP 212.9.44.29:5060;branch=z9hG4bK5a59c5f8
From: <sip:022222534@217.10.68.150>;tag=as0f07981a
To: <sip:493333320@55.66.77.88>;tag=DCBC1BF8-1A8F
Date: Tue, 24 Apr 2018 15:59:33 GMT
Call-ID: 47A223E6-470F11E8-9D14BB9C-D0573780@55.66.77.88
Server: Cisco-SIPGateway/IOS-15.6.3.M4
CSeq: 102 BYE
Reason: Q.850;cause=16
P-RTP-Stat: PS=585,OS=93600,PR=578,OR=92480,PL=0,JI=0,LA=0,DU=7
Session-ID: 6f83cc5800105000a00000ccfc99cfe2;remote=00a7cce0aa3e51aebcf31e2ddd171b5c
Content-Length: 0

*Apr 24 15:59:34.365: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
...
*Apr 24 15:59:34.365: //-1/xxxxxxxxxxxx/SIP/Error/HandleUdpIPv4SocketReads:
SIP Message incomplete, trashed
*Apr 24 15:59:38.285: //14242/C09568800000/SIP/Error/sipTransportPostSendFailure:
Posting send failure msg with tcb:0x0 reason=5
*Apr 24 15:59:38.285: //14242/C09568800000/SIP/Error/act_active_send_msg_failure:
Send Error to 10.1.1.12:5060 for transport TCP
*Apr 24 15:59:38.285: %SIP-3-INTERNAL: Cannot insert call history entry for callID : 14242
*Apr 24 15:59:38.285: //14242/C09568800000/SIP/Error/ccsip_api_call_disconnect_done:
API invocation failed
*Apr 24 15:59:38.285: //14242/C09568800000/SIP/Error/sipSPIFlushDeferredQueue:
Invalid deferredQueue
*Apr 24 15:59:38.285: //-1/xxxxxxxxxxxx/SIP/Error/sipConnectionManagerUnregisterCtxtInConnection:
Connection not found for addr=10.1.1.12, port=5060 local_addr=10.1.1.1
*Apr 24 15:59:38.285: //-1/xxxxxxxxxxxx/SIP/Error/httpish_msg_free:
Freeing NULL pointer!

The BYE from inbound calls looks like this and works:

BYE sip:493333320@55.66.77.88:5060 SIP/2.0
Via: SIP/2.0/UDP 217.10.68.150;branch=z9hG4bK8e3d.9006a567cc229f53fd65bd4b66f7ad0b.0
Via: SIP/2.0/UDP 172.20.40.7;branch=z9hG4bK8e3d.cfa9ee16b247bece12078dac1a0920bf.0
Via: SIP/2.0/UDP 217.10.68.137;branch=z9hG4bK8e3d.0cff6c0010aa47e6d6acc4abbb1bdd47.0
Via: SIP/2.0/UDP 217.116.117.8:5060;branch=z9hG4bK69815699
Max-Forwards: 67
From: "022222534" <sip:022222534@sipconnect.sipgate.de>;tag=as2d403889
To: <sip:00493333320@sipconnect.sipgate.de>;tag=DCBD732C-FA8
Call-ID: 692c598467ec75cf0731db4e4a8620a8@sipconnect.sipgate.de
CSeq: 104 BYE
Reason: Q.850;cause=16
Content-Length: 0
X-hint: rr-enforced

Jinto Alakkal · ‎04-27-2018

Hi Frank,

Can you try to change these dial peers session transport to tcp for the incoming and outgoing dial-peers to Service provider and see if it makes a difference

dial-peer voice 100 voip
 description FROM SP SIPGATE
 translation-profile incoming SIPGATE-to-+E164
 session protocol sipv2
 session transport udp
 destination dpg 100
 incoming uri via 100
 voice-class codec 1  
 voice-class sip bind control source-interface GigabitEthernet0/0
 voice-class sip bind media source-interface GigabitEthernet0/0
 dtmf-relay rtp-nte
 no vad

View solution in original post

R0g22 · ‎04-26-2018

Talking about the incomplete message first, CUBE is receiving this -

*Apr 24 15:59:34.365: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
...

I am not sure why but against this you see the CUBE printing the following -
*Apr 24 15:59:34.365: //-1/xxxxxxxxxxxx/SIP/Error/HandleUdpIPv4SocketReads:
SIP Message incomplete, trashed

Now the issue related to BYE. The working and non-working ones both look fine. I don't see a reason for CUBE to consume them. I do see the following however -

*Apr 24 15:59:33.285: //-1/xxxxxxxxxxxx/SIP/Error/sipUtilPvtVerifyIfRestricted:
From header is restricted
*Apr 24 15:59:33.285: //-1/xxxxxxxxxxxx/SIP/Error/sipUtilPvtVerifyIfRestricted:
Content-Length header is restricted
*Apr 24 15:59:33.285: //-1/xxxxxxxxxxxx/SIP/Error/sipUtilPvtVerifyIfRestricted:
To header is restricted
*Apr 24 15:59:33.285: //-1/xxxxxxxxxxxx/SIP/Error/sipUtilPvtVerifyIfRestricted:
Call-Id header is restricted
*Apr 24 15:59:33.285: //-1/xxxxxxxxxxxx/SIP/Error/sipUtilPvtVerifyIfRestricted:
Via header is restricted
*Apr 24 15:59:33.285: //-1/xxxxxxxxxxxx/SIP/Error/sipUtilPvtVerifyIfRestricted:
Cseq header is restricted

Can you do a "debug ccsip all" in off production hours for a failed scenario and attach it here ? Attach your CUBE config as well.

Frank Mittrup · ‎04-26-2018

Hi Nipun,

again, thanks for responding.

Attached you will finde a debug ccsip all including a show run at the beginning.

I changed all sensitiv IP's, Numbers and PW's.

There are some old inspection command which I disabled for a test. This was not imporving the situation.

Cheers,

Frank

R0g22 · ‎04-26-2018

Can you PM me the original logs and the config from CUBE please ?

Frank Mittrup · ‎04-26-2018

I did a find and replace of some internal IP's, users and passwords in config and debugs that it should be the same as the original. Will not make the original public here.

R0g22 · ‎04-27-2018

I understand that, that is why I requested you to PM me those and not attach them here.

Frank Mittrup · ‎04-27-2018

I send you a PM but can't attache a file there.

VijayMe · ‎04-27-2018

Hello Frank

Internal call leg is giving Disconnect cause code :500. Seems you need to add internal ip range to ip address trusted list in voice service voip.

The Call Setup Information is:

Call Control Block (CCB) : 0x0x24753FB8

State of The Call : STATE_DEAD

TCP Sockets Used : YES

Calling Number : +493333320

Called Number : +4922222534

Source IP Address (Sig ): 192.168.1.1

Destn SIP Req Addr:Port : 192.168.1.12:5060

Destn SIP Resp Addr:Port : 192.168.1.12:60057

Destination Name : 192.168.1.12

*Apr 26 15:23:46.800: //17802/121F2E000000/SIP/Call/sipSPIMediaCallInfo:

Number of Media Streams: 2

Media Stream : 1

Negotiated Codec : g711alaw

Negotiated Codec Bytes : 160

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

Negotiated Dtmf-relay : 6

Dtmf-relay Payload : 101 (tx), 101 (rx)

Source IP Address (Media): 192.168.1.1

Source IP Port (Media): 21362

Destn IP Address (Media): 192.168.18.9

Destn IP Port (Media): 27088

Orig Destn IP Address:Port (Media): [ - ]:0

*Apr 26 15:23:46.800: //17802/121F2E000000/SIP/Call/sipSPIMediaCallInfo:

Number of Media Streams: 2

Media Stream : 2

Negotiated Codec : h264

Negotiated Codec Bytes : 0

Nego. Codec payload : 100 (tx), 97 (rx)

Negotiated Dtmf-relay : 0

Dtmf-relay Payload : 0 (tx), 0 (rx)

Source IP Address (Media): 192.168.1.1

Source IP Port (Media): 0

Destn IP Address (Media): 192.168.18.9

Destn IP Port (Media): 0

Orig Destn IP Address:Port (Media): [ - ]:0

*Apr 26 15:23:46.800: //17802/121F2E000000/SIP/Call/sipSPICallInfo:

Disconnect Cause (CC) : 16

Disconnect Cause (SIP) : 500

for Error :

*Apr 26 15:23:55.728: //-1/xxxxxxxxxxxx/SIP/Info/critical/1024/httpish_msg_process_network_msg: MSG LINE READ FAILURE DUE TO RS->EOF
*Apr 26 15:23:55.728: //-1/xxxxxxxxxxxx/SIP/Info/critical/1024/ccsip_process_network_message: process_network_msg: not complete
*Apr 26 15:23:55.728: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x21A088FC
*Apr 26 15:23:55.728: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
...
*Apr 26 15:23:55.728: //-1/xxxxxxxxxxxx/SIP/Error/HandleUdpIPv4SocketReads:
SIP Message incomplete, trashed

you can reduce min time to 60 registrar server expires max 3600 min 60

Rate if this helps.

Frank Mittrup · ‎04-27-2018

Hi Vijay,

I quickly changed the 2 parameters in adding 0.0.0.0 0.0.0.0 to the Trustlist and changing the min timer but still the same issue that BYE does not go through.

Thanks,

Frank

Jinto Alakkal · ‎04-27-2018

Hi Frank,

Can you try to change these dial peers session transport to tcp for the incoming and outgoing dial-peers to Service provider and see if it makes a difference

dial-peer voice 100 voip
 description FROM SP SIPGATE
 translation-profile incoming SIPGATE-to-+E164
 session protocol sipv2
 session transport udp
 destination dpg 100
 incoming uri via 100
 voice-class codec 1  
 voice-class sip bind control source-interface GigabitEthernet0/0
 voice-class sip bind media source-interface GigabitEthernet0/0
 dtmf-relay rtp-nte
 no vad

Frank Mittrup · ‎04-30-2018

Hi Jinto,

that's the solution! Great hint! After changing the 2 dial-peers towards CUCM to UDP, it works.

Any idea on what is causing the TCP connection to break up?

I'm also checking, if there is a FW playing ugly games with me.

Thanks a lot.

Frank

Jinto Alakkal · ‎04-30-2018

Hi Frank,

I am glad that you got this issue resolved, this might be a firewall which is doing packet inspections for SIP and the SIP messages are really sensitive to this. When we use session transport TCP it just makes sure that the other end receives all the fragmented packets however the wait time to receive acknowledgements might be the issue here, this might also be caused by the service provider sending a different MTU than what we have in our Voice gateway (While using TCP).

Thanks!

Jinto.