Buy or Renew
Buy or Renew
Cisco + Splunk: Itā€™s a new day for your data. Learn more.
Ā 
cancel
Turn on suggestions
Auto-suggest helps you quickly narrow down your search results by suggesting possible matches as you type.
Showing results forĀ 
Search instead forĀ 
Did you mean:Ā 
cancel
Start a conversation
1915
Views
5
Helpful
5
Replies

SBC Immediately Sends 504 Gateway Timeout

Go to solution
AdamB32212
Level 1
Level 1

ā€Ž10-12-2021 08:16 AM

Here's a scenario for UA1 to UA2 call through a Cisco UBE (CUBE):

1 UA1 sends INVITE

2 SBC sends 100 Trying back 

3 SBC forwards INVITE to UA2

4 SBC gets 100 Trying from UA2

5 SBC gets 183 Session Progress w/100rel from UA2

6 SBC sends 183 Session Progress w/100rel to UA1

7 SBC sends PRACK to UA2

8 SBC gets 200 OK (PRACK) from UA2

9 SBC sends 183 Session Progress w/100rel to UA1 again

10 SBC sends 504 Gateway Timeout to UA1

 

(In reality there are other UAs behind UA1 and UA2, but that does not matter.)

 

Now, the time between 6 and 10 is 1.3 sec, which seems awfully quick.

 

Why is that happening and how can this be corrected?

 

The only clues I am seeing are:

Log showing: 8253778: Oct 12 14:43:41.317: //137961/9F894D46A84F/SIP/Error/act_sentrel1xx_wait_prack:
Out of retries state:11

 

and presence of "Reason: Q.850;cause=102" in 504.

Here are excerpts from the Cisco Log:


8253185: Oct 12 14:43:39.630: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
INVITE sip:3065551022;phone-context=disa.mil@disa.mil;user=phone SIP/2.0
From: <sip:4565551013@muos.mil>;tag=dd748d41
To: <sip:3065551022@disa.mil;user=phone>
Call-ID: 155-3f5b0fa28b75b630eaa487b43902e256@muos.mil
CSeq: 1 INVITE
Max-Forwards: 67
Require: resource-priority
Supported: 100rel,timer
Session-Expires: 1800
Min-SE: 90
Contact: <sip:4565551013@172.16.5.6:8950;CCA-ID=mas-wh.muos.mil>
Via: SIP/2.0/UDP 172.16.5.6:8970;branch=dsnInviteBranch,SIP/2.0/UDP 172.16.5.4:13009;branch=z9hG4bKcscfinvite,SIP/2.0/UDP 172.16.5.6:8970;branch=triggerInvite,SIP/2.0/UDP 172.16.5.4:13001;branch=z9hG4bK048d0f2179346854abe74137b631edda,SIP/2.0/UDP 172.16.5.6:8950;branch=z9hG4bK79
P-Asserted-Identity: <sip:4565551013@muos.mil;user=phone>
P-Charging-Vector: icid-value=aca71405067b308297aa5b40fcb8;orig-ioi=muos.mil
P-Charging-Function-Addresses: ccf="aaa://muos.mil:3868;transport=tcp"
Record-Route: <sip:3Zqkv7%0Baqqf4aaaacGsip%3A4565551013%40muos.mil@scscf.muos.mil:8975;lr;maddr=172.16.5.6>,<sip:172.16.5.4:13009;lr>,<sip:172.16.5.4:13001;lr>
Resource-Priority: dsn.1
Route: <sip:mgc.muos.mil;lr>
Content-Type: application/sdp
Allow: INVITE,PRACK,ACK,CANCEL,BYE,OPTIONS,UPDATE
Content-Length: 0


8253448: Oct 12 14:43:39.646: //137961/9F894D46A84F/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 172.16.5.6:8970;branch=dsnInviteBranch,SIP/2.0/UDP 172.16.5.4:13009;branch=z9hG4bKcscfinvite,SIP/2.0/UDP 172.16.5.6:8970;branch=triggerInvite,SIP/2.0/UDP 172.16.5.4:13001;branch=z9hG4bK048d0f2179346854abe74137b631edda,SIP/2.0/UDP 172.16.5.6:8950;branch=z9hG4bK79
From: <sip:4565551013@muos.mil>;tag=dd748d41
To: <sip:3065551022@disa.mil;user=phone>
Date: Tue, 12 Oct 2021 14:43:39 GMT
Call-ID: 155-3f5b0fa28b75b630eaa487b43902e256@muos.mil
CSeq: 1 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-16.9.5
Session-ID: 00000000000000000000000000000000;remote=ddbc9c6df7d45a9884cc2a7a066c3c03
Content-Length: 0

8253659: Oct 12 14:43:39.654: //137962/9F894D46A84F/SIP/Msg/ccsipDisplayMsg:
Sent:
INVITE sips:3065551022@10.229.32.110:5061 SIP/2.0
Via: SIP/2.0/TLS 10.229.32.109:5061;branch=z9hG4bK10E2D22B2
Remote-Party-ID: <sips:4565551013@10.229.32.109>;party=calling;screen=no;privacy=off
From: <sips:4565551013@10.229.32.109>;tag=7ACC78EE-D9C
To: <sips:3065551022@10.229.32.110>
Date: Tue, 12 Oct 2021 14:43:39 GMT
Call-ID: 9F8C81FD-2AA111EC-A8559244-CE487D6D@10.229.32.109
Supported: 100rel,timer,resource-priority,replaces
Min-SE: 1800
Cisco-Guid: 2676575558-0715198956-2823787076-3460857197
User-Agent: Cisco-SIPGateway/IOS-16.9.5
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
CSeq: 101 INVITE
Timestamp: 1634049819
Contact: <sips:4565551013@10.229.32.109:5061>
Expires: 180
Allow-Events: telephone-event
Max-Forwards: 66
Resource-Priority: dsn-000000.1
Session-ID: ddbc9c6df7d45a9884cc2a7a066c3c03;remote=00000000000000000000000000000000
Session-Expires: 1800
P-Charging-Vector: icid-value=aca71405067b308297aa5b40fcb8;orig-ioi=muos.mil
P-Charging-Function-Addresses: ccf="aaa://muos.mil:3868;transport=tcp"
Content-Length: 0

8253669: Oct 12 14:43:39.662: //137962/9F894D46A84F/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 100 Trying
Via: SIP/2.0/TLS 10.229.32.109:5061;branch=z9hG4bK10E2D22B2
From: <sips:4565551013@10.229.32.109>;tag=7ACC78EE-D9C
To: <sips:3065551022@10.229.32.110>
Date: Tue, 12 Oct 2021 14:45:25 GMT
Call-ID: 9F8C81FD-2AA111EC-A8559244-CE487D6D@10.229.32.109
Timestamp: 1634049819
CSeq: 101 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-16.9.2
Session-ID: 00000000000000000000000000000000;remote=ddbc9c6df7d45a9884cc2a7a066c3c03
Content-Length: 0

8253681: Oct 12 14:43:39.814: //137962/9F894D46A84F/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 183 Session Progress
Via: SIP/2.0/TLS 10.229.32.109:5061;branch=z9hG4bK10E2D22B2
From: <sips:4565551013@10.229.32.109>;tag=7ACC78EE-D9C
To: <sips:3065551022@10.229.32.110>;tag=61739953-BC7
Date: Tue, 12 Oct 2021 14:45:25 GMT
Call-ID: 9F8C81FD-2AA111EC-A8559244-CE487D6D@10.229.32.109
Timestamp: 1634049819
CSeq: 101 INVITE
Require: 100rel
RSeq: 10
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Contact: <sips:3065551022@10.229.32.110:5061>
Server: Cisco-SIPGateway/IOS-16.9.2
Session-ID: f0ae1774b5c15ec480ef99df452b49cf;remote=ddbc9c6df7d45a9884cc2a7a066c3c03
Content-Length: 0


8253751: Oct 12 14:43:39.817: //137961/9F894D46A84F/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 172.16.5.6:8970;branch=dsnInviteBranch,SIP/2.0/UDP 172.16.5.4:13009;branch=z9hG4bKcscfinvite,SIP/2.0/UDP 172.16.5.6:8970;branch=triggerInvite,SIP/2.0/UDP 172.16.5.4:13001;branch=z9hG4bK048d0f2179346854abe74137b631edda,SIP/2.0/UDP 172.16.5.6:8950;branch=z9hG4bK79
From: <sip:4565551013@muos.mil>;tag=dd748d41
To: <sip:3065551022@disa.mil;user=phone>;tag=7ACC7991-3DD
Date: Tue, 12 Oct 2021 14:43:39 GMT
Call-ID: 155-3f5b0fa28b75b630eaa487b43902e256@muos.mil
CSeq: 1 INVITE
Require: 100rel
RSeq: 6799
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Remote-Party-ID: <sip:3065551022@172.19.140.114>;party=called;screen=no;privacy=off
Contact: <sip:3065551022@172.19.140.114:5060>
Record-Route: <sip:3Zqkv7%0Baqqf4aaaacGsip%3A4565551013%40muos.mil@scscf.muos.mil:8975;lr;maddr=172.16.5.6>,<sip:172.16.5.4:13009;lr>,<sip:172.16.5.4:13001;lr>
Server: Cisco-SIPGateway/IOS-16.9.5
Session-ID: f0ae1774b5c15ec480ef99df452b49cf;remote=ddbc9c6df7d45a9884cc2a7a066c3c03
Content-Length: 0

8253753: Oct 12 14:43:39.817: //137962/9F894D46A84F/SIP/Msg/ccsipDisplayMsg:
Sent:
PRACK sips:3065551022@10.229.32.110:5061 SIP/2.0
Via: SIP/2.0/TLS 10.229.32.109:5061;branch=z9hG4bK10E2E1E4E
From: <sips:4565551013@10.229.32.109>;tag=7ACC78EE-D9C
To: <sips:3065551022@10.229.32.110>;tag=61739953-BC7
Date: Tue, 12 Oct 2021 14:43:39 GMT
Call-ID: 9F8C81FD-2AA111EC-A8559244-CE487D6D@10.229.32.109
CSeq: 102 PRACK
RAck: 10 101 INVITE
Allow-Events: telephone-event
Max-Forwards: 70
Session-ID: ddbc9c6df7d45a9884cc2a7a066c3c03;remote=f0ae1774b5c15ec480ef99df452b49cf
Content-Length: 0

8253764: Oct 12 14:43:39.819: //137962/9F894D46A84F/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 200 OK
Via: SIP/2.0/TLS 10.229.32.109:5061;branch=z9hG4bK10E2E1E4E
From: <sips:4565551013@10.229.32.109>;tag=7ACC78EE-D9C
To: <sips:3065551022@10.229.32.110>;tag=61739953-BC7
Date: Tue, 12 Oct 2021 14:45:25 GMT
Call-ID: 9F8C81FD-2AA111EC-A8559244-CE487D6D@10.229.32.109
Server: Cisco-SIPGateway/IOS-16.9.2
CSeq: 102 PRACK
Session-ID: f0ae1774b5c15ec480ef99df452b49cf;remote=ddbc9c6df7d45a9884cc2a7a066c3c03
Content-Length: 0

8253776: Oct 12 14:43:40.318: //137961/9F894D46A84F/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 172.16.5.6:8970;branch=dsnInviteBranch,SIP/2.0/UDP 172.16.5.4:13009;branch=z9hG4bKcscfinvite,SIP/2.0/UDP 172.16.5.6:8970;branch=triggerInvite,SIP/2.0/UDP 172.16.5.4:13001;branch=z9hG4bK048d0f2179346854abe74137b631edda,SIP/2.0/UDP 172.16.5.6:8950;branch=z9hG4bK79
From: <sip:4565551013@muos.mil>;tag=dd748d41
To: <sip:3065551022@disa.mil;user=phone>;tag=7ACC7991-3DD
Date: Tue, 12 Oct 2021 14:43:39 GMT
Call-ID: 155-3f5b0fa28b75b630eaa487b43902e256@muos.mil
CSeq: 1 INVITE
Require: 100rel
RSeq: 6799
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Remote-Party-ID: <sip:3065551022@172.19.140.114>;party=called;screen=no;privacy=off
Contact: <sip:3065551022@172.19.140.114:5060>
Record-Route: <sip:3Zqkv7%0Baqqf4aaaacGsip%3A4565551013%40muos.mil@scscf.muos.mil:8975;lr;maddr=172.16.5.6>,<sip:172.16.5.4:13009;lr>,<sip:172.16.5.4:13001;lr>
Server: Cisco-SIPGateway/IOS-16.9.5
Session-ID: f0ae1774b5c15ec480ef99df452b49cf;remote=ddbc9c6df7d45a9884cc2a7a066c3c03
Content-Length: 0


8253777: Oct 12 14:43:40.319: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7F6ACECB3CB8
8253778: Oct 12 14:43:41.317: //137961/9F894D46A84F/SIP/Error/act_sentrel1xx_wait_prack:
Out of retries state:11
8253779: Oct 12 14:43:41.317: //137961/9F894D46A84F/SIP/Info/critical/4096/ccsip_set_cc_cause_for_spi_err: Categorized cause:102, category:129
8253780: Oct 12 14:43:41.317: //137961/9F894D46A84F/SIP/Info/verbose/4096/ccsip_set_release_source_for_peer: ownCallId[137961], src[6]
8253781: Oct 12 14:43:41.317: %VOICE_IEC-3-GW: SIP: Internal Error (PRACK wait timeout): IEC=1.1.129.7.62.0 on callID 137961 GUID=9F894D462AA111ECA84F9244CE487D6D
8253782: Oct 12 14:43:41.317: //137961/9F894D46A84F/SIP/Info/critical/4096/sipSPIInitiateDisconnect: Initiate call disconnect(102) for incoming call
8253783: Oct 12 14:43:41.317: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x7F6A5D9B9E08) counter, current msg->refCount = 1
8253784: Oct 12 14:43:41.317: //-1/xxxxxxxxxxxx/SIP/Error/sipSPIGetContentQSIG:
No Inbound Container Created !!!
8253785: Oct 12 14:43:41.318: //-1/xxxxxxxxxxxx/SIP/Error/sipSPIGetContentQ931:
No Inbound Container Created !!!
8253786: Oct 12 14:43:41.318: //137961/9F894D46A84F/SIP/Info/verbose/4096/ccsip_ipip_media_service_get_event_data: Event id = 34
8253787: Oct 12 14:43:41.318: //137961/9F894D46A84F/SIP/Info/critical/32768/ccsip_ipip_media_forking_post_event: MF: Not a Anchor SIP leg..
8253788: Oct 12 14:43:41.318: //137961/9F894D46A84F/SIP/Error/sipSPI_ipip_ExtractAndAddPassthruCopyListDataToContainer:
Container is NULL
8253789: Oct 12 14:43:41.318: //137961/9F894D46A84F/SIP/Info/info/1024/sipAddSipContainerToCallEntry: Unable to add passthru hdrs to container
8253790: Oct 12 14:43:41.318: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7F6ACECB3CB8 with refCount = 1
8253791: Oct 12 14:43:41.318: //137961/9F894D46A84F/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1
8253792: Oct 12 14:43:41.318: //137961/9F894D46A84F/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP extension config:1, check sys cfg:1
8253793: Oct 12 14:43:41.318: //137961/9F894D46A84F/SIP/Info/critical/512/sentErrResDisconnecting: Sent an 3456XX Error Response
8253794: Oct 12 14:43:41.319: //137962/9F894D46A84F/SIP/Info/info/8192/ccsip_call_statistics: Stats are not supported for IPIP call.
8253795: Oct 12 14:43:41.319: //137962/9F894D46A84F/SIP/Info/verbose/4096/ccsip_ipip_media_service_get_event_data: Event id = 34
8253796: Oct 12 14:43:41.319: //137962/9F894D46A84F/SIP/Info/critical/4096/ccsip_ipip_mf_create_xml_metadata_for_disconnect: MF: Not a Forked leg..
8253797: Oct 12 14:43:41.319: //137962/9F894D46A84F/SIP/Info/critical/32768/ccsip_ipip_media_forking_post_event: MF: Not a Anchor SIP leg..
8253798: Oct 12 14:43:41.319: //137961/9F894D46A84F/SIP/Info/info/8192/ccsip_call_statistics: Stats are not supported for IPIP call.
8253799: Oct 12 14:43:41.319: //137961/9F894D46A84F/SIP/Info/verbose/4096/ccsip_ipip_media_service_get_event_data: Event id = 34
8253800: Oct 12 14:43:41.319: //137961/9F894D46A84F/SIP/Info/critical/4096/ccsip_ipip_mf_create_xml_metadata_for_disconnect: MF: Not a Forked leg..
8253801: Oct 12 14:43:41.319: //137961/9F894D46A84F/SIP/Info/critical/32768/ccsip_ipip_media_forking_post_event: MF: Not a Anchor SIP leg..
8253802: Oct 12 14:43:41.320: //137961/9F894D46A84F/SIP/Msg/ccsipDisplayMsg:
8253802: Oct 12 14:43:41.320: //137961/9F894D46A84F/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 504 Gateway Timeout
Via: SIP/2.0/UDP 172.16.5.6:8970;branch=dsnInviteBranch,SIP/2.0/UDP 172.16.5.4:13009;branch=z9hG4bKcscfinvite,SIP/2.0/UDP 172.16.5.6:8970;branch=triggerInvite,SIP/2.0/UDP 172.16.5.4:13001;branch=z9hG4bK048d0f2179346854abe74137b631edda,SIP/2.0/UDP 172.16.5.6:8950;branch=z9hG4bK79
From: <sip:4565551013@muos.mil>;tag=dd748d41
To: <sip:3065551022@disa.mil;user=phone>;tag=7ACC7991-3DD
Call-ID: 155-3f5b0fa28b75b630eaa487b43902e256@muos.mil
Session-ID: f0ae1774b5c15ec480ef99df452b49cf;remote=ddbc9c6df7d45a9884cc2a7a066c3c03
CSeq: 1 INVITE
Reason: Q.850;cause=102
Content-Length: 0

8253826: Oct 12 14:43:41.322: //137962/9F894D46A84F/SIP/Msg/ccsipDisplayMsg:
Sent:
CANCEL sips:3065551022@10.229.32.110:5061 SIP/2.0
Via: SIP/2.0/TLS 10.229.32.109:5061;branch=z9hG4bK10E2D22B2
From: <sips:4565551013@10.229.32.109>;tag=7ACC78EE-D9C
To: <sips:3065551022@10.229.32.110>
Date: Tue, 12 Oct 2021 14:43:39 GMT
Call-ID: 9F8C81FD-2AA111EC-A8559244-CE487D6D@10.229.32.109
CSeq: 101 CANCEL
Max-Forwards: 70
Timestamp: 1634049821
Reason: Q.850;cause=102
Session-ID: ddbc9c6df7d45a9884cc2a7a066c3c03;remote=00000000000000000000000000000000
Content-Length: 0


8253827: Oct 12 14:43:41.322: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7F6ACECA60F0
8253828: Oct 12 14:43:41.326: //-1/xxxxxxxxxxxx/SIP/Info/notify/512/sip_tls_tcp_read_socket:
ReadBlock nbytes 415 offset 0
8253829: Oct 12 14:43:41.326: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7F6ACECA60F0 with refCount = 1
8253830: Oct 12 14:43:41.326: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7F6ACECB3CB8 with refCount = 1
8253831: Oct 12 14:43:41.326: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7F6ACECA60F0
8253832: Oct 12 14:43:41.326: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
8253833: Oct 12 14:43:41.326: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 5061 connId 16
8253834: Oct 12 14:43:41.327: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog
8253835: Oct 12 14:43:41.327: //137962/9F894D46A84F/SIP/Info/info/1024/sipSPIMatchRespToReqTran: removing unneeded z9hG4bK10E2D22B2 from via branch list
8253836: Oct 12 14:43:41.327: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x7F6ACECB3CB8) counter, current msg->refCount = 2
8253837: Oct 12 14:43:41.327: //137962/9F894D46A84F/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 200 OK
Via: SIP/2.0/TLS 10.229.32.109:5061;branch=z9hG4bK10E2D22B2
From: <sips:4565551013@10.229.32.109>;tag=7ACC78EE-D9C
To: <sips:3065551022@10.229.32.110>
Date: Tue, 12 Oct 2021 14:45:27 GMT
Call-ID: 9F8C81FD-2AA111EC-A8559244-CE487D6D@10.229.32.109
Timestamp: 1634049821
CSeq: 101 CANCEL
Session-ID: f0ae1774b5c15ec480ef99df452b49cf;remote=ddbc9c6df7d45a9884cc2a7a066c3c03
Content-Length: 0


8253838: Oct 12 14:43:41.327: //137962/9F894D46A84F/SIP/Info/verbose/1024/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX
8253839: Oct 12 14:43:41.327: //137962/9F894D46A84F/SIP/Info/sact_disconnecting_new_message_response: [sact_disconnecting_new_message_response] Received Response Class [2] Method Code [104]

8253840: Oct 12 14:43:41.327: //137962/9F894D46A84F/SIP/Info/info/12288/sipSPIIcpifUpdate: CallState: 2 Playout: 0 DiscTime:206014525 ConnTime 0
8253841: Oct 12 14:43:41.328: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7F6AC269A628
8253842: Oct 12 14:43:41.328: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Decrement msg (0x7F6ACECB3CB8) counter, current msg->refCount = 1
8253843: Oct 12 14:43:41.328: //-1/xxxxxxxxxxxx/SIP/Info/notify/512/sip_tls_tcp_read_socket:
ReadBlock nbytes 539 offset 0
8253844: Oct 12 14:43:41.329: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7F6A6030C788 with refCount = 1
8253845: Oct 12 14:43:41.329: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x7F6ACECA60F0 with refCount = 1
8253846: Oct 12 14:43:41.329: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x7F6A6030C788
8253847: Oct 12 14:43:41.329: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
8253848: Oct 12 14:43:41.329: //-1/xxxxxxxxxxxx/SIP/Info/info/4608/sipHolderGetConnInstance: Return existing connection for port 5061 connId 16
8253849: Oct 12 14:43:41.329: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog
8253850: Oct 12 14:43:41.329: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x7F6ACECA60F0) counter, current msg->refCount = 2
8253851: Oct 12 14:43:41.329: //137962/9F894D46A84F/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 487 Request Cancelled
Via: SIP/2.0/TLS 10.229.32.109:5061;branch=z9hG4bK10E2D22B2
From: <sips:4565551013@10.229.32.109>;tag=7ACC78EE-D9C
To: <sips:3065551022@10.229.32.110>;tag=61739953-BC7
Date: Tue, 12 Oct 2021 14:45:27 GMT
Call-ID: 9F8C81FD-2AA111EC-A8559244-CE487D6D@10.229.32.109
Timestamp: 1634049819
CSeq: 101 INVITE
Allow-Events: telephone-event
Server: Cisco-SIPGateway/IOS-16.9.2
Reason: Q.850;cause=16
Session-ID: ddbc9c6df7d45a9884cc2a7a066c3c03;remote=f0ae1774b5c15ec480ef99df452b49cf
Content-Length: 0

Labels:
0 Helpful
2 Accepted Solutions

Accepted Solutions

Go to solution
Roger Kallberg
VIP
VIP
In response to AdamB32212

ā€Ž10-26-2021 11:01 PM

1.5 second for this specific thing in a call setup is an eon of time. The real issue at hand is that your not getting a response from your service provider on the PRACK. As @b.winter suggested either try turning PRACK off to the service provider side or reach out to your service provider and ask for why they donā€™t respond to the PRACK message. It could be as simple as that they donā€™t support PRACK.



Response Signature


View solution in original post

0 Helpful

Go to solution
adam.crisp.tech
Level 1
Level 1

ā€Ž10-27-2021 01:26 AM

 It's the response to the 183 the cube sends towards UA1 that is not being responded to in a timely manner.

Possible ideas

1. UA1 doesn't support prack - although it does say that 100rel is supported in it's initial invite.

Maybe ask for that to be disabled on UA1 or have your incoming dial-peer filter out that header

2. There's a firewall blocking traffic from CUBE to UA1.

Initial invite from UA1 has:

 

Contact: <sip:4565551013@172.16.5.6:8950;CCA-ID=mas-wh.muos.mil>
Via: SIP/2.0/UDP 172.16.5.6:8970;branch=dsnInviteBranch,SIP/2.0/UDP 172.16.5.4:13009;branch=z9hG4bKcscfinvite,SIP/2.0/UDP 172.16.5.6:8970;branch=triggerInvite,SIP/2.0/UDP 172.16.5.4:13001;branch=z9hG4bK048d0f2179346854abe74137b631edda,SIP/2.0/UDP 172.16.5.6:8950;branch=z9hG4bK79

 

and the CUBE is sending the 183:

 

SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 172.16.5.6:8970;branch=dsnInviteBranch,SIP/2.0/UDP 172.16.5.4:13009;branch=z9hG4bKcscfinvite,SIP/2.0/UDP 172.16.5.6:8970;branch=triggerInvite,SIP/2.0/UDP 172.16.5.4:13001;branch=z9hG4bK048d0f2179346854abe74137b631edda,SIP/2.0/UDP 172.16.5.6:8950;branch=z9hG4bK79

 

try enabling debug ip icmp to see if you're unreachable messages on the send to 172.16.5.6:8970

This is probably not the problem as we don't see re-invites from ua1.

 

3. UDP MTU issues:

the 183 is about 1100 bytes, so you should be OK, but it's worth checking. You could ask for a tcp to be used instead.

 

good luck

View solution in original post

0 Helpful
5 Replies 5

Go to solution
b.winter
VIP
VIP

ā€Ž10-13-2021 04:42 AM - edited ā€Ž10-13-2021 04:49 AM

Hi,

 

as per your logs, the CUBE sends 183 Session Progress twice back to the provider, but doesn't get any answer and probably therefore terminates the call.

 

As I have understood the RFC for PRACK:

After sending out the first 183 Session Progress, the CUBE waits for T1 (500ms).

If it doesn't get any answer, the CUBE sends out a second 183 Session Progress and waits again for 2*T1 (2*500ms = 1s).

And if the CUBE still doesn't get any answer in this period, it terminates the call.

 

So you could try to turn off PRACK towards provider or ask the provider, why they are not answering to 183 Session Progress (even if the INVITE from provider indicates, that they support it).

Go to solution
AdamB32212
Level 1
Level 1
In response to b.winter

ā€Ž10-26-2021 01:37 PM

1.5 sec seems very low...

 

Here's what I found in the PRACK RFC:

https://www.ietf.org/rfc/rfc3262.txt

   If a reliable provisional response is retransmitted for 64*T1 seconds

   without reception of a corresponding PRACK, the UAS SHOULD reject the

   original request with a 5xx response.

 

 

0 Helpful

Go to solution
Roger Kallberg
VIP
VIP
In response to AdamB32212

ā€Ž10-26-2021 11:01 PM

1.5 second for this specific thing in a call setup is an eon of time. The real issue at hand is that your not getting a response from your service provider on the PRACK. As @b.winter suggested either try turning PRACK off to the service provider side or reach out to your service provider and ask for why they donā€™t respond to the PRACK message. It could be as simple as that they donā€™t support PRACK.



Response Signature


0 Helpful

Go to solution
b.winter
VIP
VIP
In response to AdamB32212

ā€Ž10-27-2021 12:59 AM

Hi,

 

just imagine: 64*T1 would be 32 secondes. You cannot wait half a minute for a call to disconnect because of a failure.

The logs also give you a log message: 8253778: Oct 12 14:43:41.317: //137961/9F894D46A84F/SIP/Error/act_sentrel1xx_wait_prack:
Out of retries state:11

 

What's also very weird is the VIA-header and the Record-Route header in the provider messages, as they contain multiple IP's. Maybe this leads to SIP-routing issues on the CUBE.

Via: SIP/2.0/UDP 172.16.5.6:8970;branch=dsnInviteBranch,SIP/2.0/UDP 172.16.5.4:13009;branch=z9hG4bKcscfinvite,SIP/2.0/UDP 172.16.5.6:8970;branch=triggerInvite,SIP/2.0/UDP 172.16.5.4:13001;branch=z9hG4bK048d0f2179346854abe74137b631edda,SIP/2.0/UDP 172.16.5.6:8950;branch=z9hG4bK79

and

Record-Route: <sip:3Zqkv7%0Baqqf4aaaacGsip%3A4565551013%40muos.mil@scscf.muos.mil:8975;lr;maddr=172.16.5.6>,<sip:172.16.5.4:13009;lr>,<sip:172.16.5.4:13001;lr>

Normally you have multiple VIA- and Record-Router headers for multiple IP's / hostnames.

0 Helpful

Go to solution
adam.crisp.tech
Level 1
Level 1

ā€Ž10-27-2021 01:26 AM

 It's the response to the 183 the cube sends towards UA1 that is not being responded to in a timely manner.

Possible ideas

1. UA1 doesn't support prack - although it does say that 100rel is supported in it's initial invite.

Maybe ask for that to be disabled on UA1 or have your incoming dial-peer filter out that header

2. There's a firewall blocking traffic from CUBE to UA1.

Initial invite from UA1 has:

 

Contact: <sip:4565551013@172.16.5.6:8950;CCA-ID=mas-wh.muos.mil>
Via: SIP/2.0/UDP 172.16.5.6:8970;branch=dsnInviteBranch,SIP/2.0/UDP 172.16.5.4:13009;branch=z9hG4bKcscfinvite,SIP/2.0/UDP 172.16.5.6:8970;branch=triggerInvite,SIP/2.0/UDP 172.16.5.4:13001;branch=z9hG4bK048d0f2179346854abe74137b631edda,SIP/2.0/UDP 172.16.5.6:8950;branch=z9hG4bK79

 

and the CUBE is sending the 183:

 

SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP 172.16.5.6:8970;branch=dsnInviteBranch,SIP/2.0/UDP 172.16.5.4:13009;branch=z9hG4bKcscfinvite,SIP/2.0/UDP 172.16.5.6:8970;branch=triggerInvite,SIP/2.0/UDP 172.16.5.4:13001;branch=z9hG4bK048d0f2179346854abe74137b631edda,SIP/2.0/UDP 172.16.5.6:8950;branch=z9hG4bK79

 

try enabling debug ip icmp to see if you're unreachable messages on the send to 172.16.5.6:8970

This is probably not the problem as we don't see re-invites from ua1.

 

3. UDP MTU issues:

the 183 is about 1100 bytes, so you should be OK, but it's worth checking. You could ask for a tcp to be used instead.

 

good luck

0 Helpful
Getting Started

Find answers to your questions by entering keywords or phrases in the Search bar above. New here? Use these resources to familiarize yourself with the community:

Customers Also Viewed These Support Documents