This is a Cisco UC520 that is being migrated from a PRI to a SIP trunk.
We can get outbound calls working just fine but anything inbound gives the caller a fast busy. The ISP says our PBX is responding with an "Error 500'. I have tried everything with the ACLs, translation, and more. Below is the current debug of what is happening. I also put it into pastebin here: http://pastebin.com/GgpM6sYi
Log Buffer (3000000 bytes):
308792: Aug 2 16:52:01.278: //577545/B871093F830F/SIP/Info/sipSPIUdeleteccCallIdFromTable: Removing call id 8D009
308793: Aug 2 16:52:01.278: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[132452] removed.
308794: Aug 2 16:52:01.278: //577545/B871093F830F/SIP/Info/sipSPIUdeleteCcbFromUASReqTable: ****Deleting from UAS Request table.
308795: Aug 2 16:52:01.278: //577545/B871093F830F/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x88377130 key=412914948@192.168.10.200metaswitch
308796: Aug 2 16:52:01.278: //577545/B871093F830F/SIP/Info/sipSPIUdeleteCcbFromUASRespTable: ****Deleting from UAS Response table.
308797: Aug 2 16:52:01.278: //577545/B871093F830F/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
308798: Aug 2 16:52:01.278: //577545/B871093F830F/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
308799: Aug 2 16:52:01.278: //577545/B871093F830F/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 88377130
308800: Aug 2 16:52:02.422: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.10.200]:5060, local_address:[ - ]
308801: Aug 2 16:52:02.422: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
308802: Aug 2 16:52:02.422: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0
308803: Aug 2 16:52:02.422: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
INVITE sip:3862623006@192.168.10.201:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.10.200:5060;branch=z9hG4bK320965553
From: "Gainesville FL" <sip:3522266288@192.168.10.200>;tag=3az08uIEqnPliFbft6C5F56C129705f3
To: <sip:3862623006@192.168.10.200>
Call-ID: 1374670431@192.168.10.200
CSeq: 18793 INVITE
Contact: <sip:3522266288@192.168.10.200:5060>
Max-Forwards: 70
User-Agent: ewb2bua/13.12.2
Supported: 100rel
Allow: UPDATE
Content-Type: application/sdp
Content-Length: 167
v=0
o=- 1292306845 1292306845 IN IP4 192.168.10.200
s=-
c=IN IP4 192.168.10.200
t=0 0
m=audio 16780 RTP/AVP 0 101
a=rtpmap:101 telephone-event/8000
a=ptime:20
308804: Aug 2 16:52:02.422: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
308805: Aug 2 16:52:02.422: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIAddContextToTable: Added context(0x88377130) with key=[132454] to table
308806: Aug 2 16:52:02.422: //-1/000000000000/SIP/Info/sipSPI_ipip_vcc_Initialization: Entry...
308807: Aug 2 16:52:02.422: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 192.168.10.200,Port 5060, Transport 1, SentBy Port 5060
308808: Aug 2 16:52:02.422: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling reg_invoke_ip_first_hop()
308809: Aug 2 16:52:02.422: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling ip_best_local_address()
308810: Aug 2 16:52:02.422: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: return addr 192.168.10.201
308811: Aug 2 16:52:02.422: //-1/CC33C7668311/SIP/State/sipSPIChangeState: 0x88377130 : State change from (STATE_NONE, SUBSTATE_NONE) to (STATE_IDLE, SUBSTATE_NONE)
308812: Aug 2 16:52:02.422: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 192.168.10.200,Port 5060, Transport 1, SentBy Port 5060
308813: Aug 2 16:52:02.422: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone est to SIP default timezone = GMT
308814: Aug 2 16:52:02.422: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 192.168.10.200,Port 5060, Transport 1, SentBy Port 5060
308815: Aug 2 16:52:02.422: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling reg_invoke_ip_first_hop()
308816: Aug 2 16:52:02.422: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: calling ip_best_local_address()
308817: Aug 2 16:52:02.422: //-1/xxxxxxxxxxxx/SIP/Info/resolve_sig_ip_address_to_bind: return addr 192.168.10.201
308818: Aug 2 16:52:02.426: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentGTD: No GTD found in inbound container
308819: Aug 2 16:52:02.426: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContentCSTA: No CSTA found in inbound container
308820: Aug 2 16:52:02.426: //-1/CC33C7668311/SIP/Info/sipSPIUaddCcbToUASReqTable: ****Adding to UAS Request table.
308821: Aug 2 16:52:02.426: //-1/CC33C7668311/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x88377130 key=1374670431@192.168.10.2003862623006
308822: Aug 2 16:52:02.426: //-1/CC33C7668311/SIP/Info/sipSPIMatchSrcIpGroup: Match not found on carrier id
308823: Aug 2 16:52:02.426: //-1/CC33C7668311/SIP/Info/sipSPIUaddCcbToUASRespTable: ****Adding to UAS Response table.
308824: Aug 2 16:52:02.426: //-1/CC33C7668311/SIP/Info/sipSPIUaddCcbToTable: Added to table. ccb=0x88377130 key=1374670431@192.168.10.200F80E7CFC-2DA
308825: Aug 2 16:52:02.426: //-1/CC33C7668311/SIP/Event/Session-Timer/sipSTSLMain: Event: E_STSL_SESSION_REFRESH_RESP
308826: Aug 2 16:52:02.426: //-1/CC33C7668311/SIP/Event/Session-Timer/sipSTSLMain: dir:1, method:102, resp_code:500, container:8C5B56C4
308827: Aug 2 16:52:02.426: //-1/CC33C7668311/SIP/Info/Session-Timer/sipSTSLMain:
SE: 0;refresher:none peer refresher:none, flags:0, posted event:E_STSL_INVALID_PEER_EVENT, reason:4
Configured SE:1800, Configured Min-SE:1800
308828: Aug 2 16:52:02.430: //-1/CC33C7668311/SIP/Info/sipSPISendInviteResponse: Associated container=0x8C5B56C4 to Invite Response 500
308829: Aug 2 16:52:02.430: //-1/CC33C7668311/SIP/Transport/sipSPITransportSendMessage: msg=0x8BFB50B8, addr=192.168.10.200, port=5060, sentBy_port=5060, local_addr=, is_req=0, transport=1, switch=0, callBack=0x8137C6E4
308830: Aug 2 16:52:02.430: //-1/CC33C7668311/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately
308831: Aug 2 16:52:02.430: //-1/CC33C7668311/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0
308832: Aug 2 16:52:02.430: //-1/CC33C7668311/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x8BFB50B8 to default port=5060
308833: Aug 2 16:52:02.430: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:192.168.10.200, rport:5060 with laddr:
308834: Aug 2 16:52:02.430: //-1/CC33C7668311/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x8BFB50B8
308835: Aug 2 16:52:02.430: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x8BFB50B8, addr=192.168.10.200, port=5060, local_addr=, connId=2 for UDP
308836: Aug 2 16:52:02.430: //-1/CC33C7668311/SIP/Info/sentErrResDisconnecting: Sent an 3456XX Error Response
308837: Aug 2 16:52:02.430: //-1/CC33C7668311/SIP/State/sipSPIChangeState: 0x88377130 : State change from (STATE_IDLE, SUBSTATE_NONE) to (STATE_DISCONNECTING, SUBSTATE_NONE)
308838: Aug 2 16:52:02.430: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Sent:
SIP/2.0 500 Internal Server Error
Via: SIP/2.0/UDP 192.168.10.200:5060;branch=z9hG4bK320965553
From: "Gainesville FL" <sip:3522266288@192.168.10.200>;tag=3az08uIEqnPliFbft6C5F56C129705f3
To: <sip:3862623006@192.168.10.200>;tag=F80E7CFC-2DA
Date: Tue, 02 Aug 2016 20:52:02 GMT
Call-ID: 1374670431@192.168.10.200
CSeq: 18793 INVITE
Allow-Events: telephone-event
Reason: Q.850;cause=63
Server: Cisco-SIPGateway/IOS-12.x
Content-Length: 0
308839: Aug 2 16:52:02.434: //-1/xxxxxxxxxxxx/SIP/Info/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [192.168.10.200]:5060, local_address:[ - ]
308840: Aug 2 16:52:02.434: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
308841: Aug 2 16:52:02.434: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0
308842: Aug 2 16:52:02.434: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
ACK sip:3862623006@192.168.10.201:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.10.200:5060;branch=z9hG4bK320965553
From: "Gainesville FL" <sip:3522266288@192.168.10.200>;tag=3az08uIEqnPliFbft6C5F56C129705f3
To: <sip:3862623006@192.168.10.200>;tag=F80E7CFC-2DA
Call-ID: 1374670431@192.168.10.200
CSeq: 18793 ACK
Max-Forwards: 70
User-Agent: ewb2bua/13.12.2
Content-Length: 0
308843: Aug 2 16:52:02.434: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_new_msg_preprocessor: Checking Invite Dialog
308844: Aug 2 16:52:02.434: //-1/CC33C7668311/SIP/Info/sipSPIFindCcbUASRespTable: *****CCB found in UAS Response table. ccb=0x88377130
308845: Aug 2 16:52:02.434: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 192.168.10.200,Port 5060, Transport 1, SentBy Port 5060
308846: Aug 2 16:52:02.434: //-1/xxxxxxxxxxxx/SIP/Info/sipSPISetDateHeader: Converting TimeZone est to SIP default timezone = GMT
308847: Aug 2 16:52:02.434: //-1/xxxxxxxxxxxx/SIP/Transport/sipSPIUpdateResponseInfo: Dialog Transaction Address 192.168.10.200,Port 5060, Transport 1, SentBy Port 5060
308848: Aug 2 16:52:02.434: //-1/CC33C7668311/SIP/State/sipSPIChangeState: 0x88377130 : State change from (STATE_DISCONNECTING, SUBSTATE_NONE) to (STATE_DEAD, SUBSTATE_NONE)
308849: Aug 2 16:52:02.434: //-1/CC33C7668311/SIP/Call/sipSPICallInfo:
The Call Setup Information is:
Call Control Block (CCB) : 0x88377130
State of The Call : STATE_DEAD
TCP Sockets Used : NO
Calling Number : 3522266288
Called Number : 3862623006
Source IP Address (Sig ): 192.168.10.201
Destn SIP Req Addr:Port : 192.168.10.200:0
Destn SIP Resp Addr:Port : 192.168.10.200:5060
Destination Name : 192.168.10.200
308850: Aug 2 16:52:02.434: //-1/CC33C7668311/SIP/Call/sipSPICallInfo:
Disconnect Cause (CC) : 63
Disconnect Cause (SIP) : 500
308851: Aug 2 16:52:02.434: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIDeleteContextFromTable: Context for key=[132454] removed.
308852: Aug 2 16:52:02.438: //-1/CC33C7668311/SIP/Info/sipSPIUdeleteCcbFromUASReqTable: ****Deleting from UAS Request table.
308853: Aug 2 16:52:02.438: //-1/CC33C7668311/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x88377130 key=1374670431@192.168.10.2003862623006
308854: Aug 2 16:52:02.438: //-1/CC33C7668311/SIP/Info/sipSPIUdeleteCcbFromUASRespTable: ****Deleting from UAS Response table.
308855: Aug 2 16:52:02.438: //-1/CC33C7668311/SIP/Info/sipSPIUdeleteCcbFromTable: Deleting from table. ccb=0x88377130 key=1374670431@192.168.10.200F80E7CFC-2DA
308856: Aug 2 16:52:02.438: //-1/CC33C7668311/SIP/Info/sipSPIFlushEventBufferQueue: There are 0 events on the internal queue that are going to be free'd
308857: Aug 2 16:52:02.438: //-1/CC33C7668311/SIP/Info/sipSPI_ipip_free_codec_profile: Codec Profiles Freed
308858: Aug 2 16:52:02.438: //-1/CC33C7668311/SIP/Info/sipSPIUfreeOneCCB: Freeing ccb 88377130
308859: Aug 2 16:52:02.438: //-1/xxxxxxxxxxxx/SIP/Info/sipSPIGetContextFromTable: NO context for key[132454]
