[cisco-voip] SIP OPTIONS pings are blocked on Cisco CUBE 3945E - Resource failure, dropping OPTIONS

[Maciej Bylica]

Hi

I have really strange problem with SIP OPTIONS pings.
The Cisco i have (CUBE 3945 ios Version 15.3(3)M5) responds only to the
first OPTIONS packet that is received from the endpoint.
The rest of OPTIONs are dropped with following debug output:

Oct  9 12:52:06 10.10.10.10 8694907: Oct  9 10:55:58.194:
//-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI :
SIPSPI_EV_CC_OPTIONS_RESP
Oct  9 12:52:06 10.10.10.10 8694908: Oct  9 10:55:58.194:
//148025/BCB3C79A92C0/SIP/Info/info/4096/sact_idle_new_message_options:
ccsip_api_options_ind returned: SIP_SUCCESS
Oct  9 12:52:06 10.10.10.10 8694909: Oct  9 10:55:58.194:
//148025/BCB3C79A92C0/SIP/State/sipSPIChangeState: 0x258D7210 : State
change from (STATE_IDLE, SUBSTATE_NONE)  to (SIP_STATE_OPTIONS_WAIT,
SUBSTATE_NONE)
Oct  9 12:52:06 10.10.10.10 8694910: Oct  9 10:55:58.194:
//148025/BCB3C79A92C0/SIP/Error/sipSPIUaddCcbToTable:
Oct  9 12:52:06 10.10.10.10 8694911:  *Could not add ccb to table*.
ccb=0x258D7210
key=c3c4f5582a4bfa1ff4b7e741c3cb6c6822f738b4cd7e78633fc70f5441197d3
Oct  9 12:52:06 10.10.10.10 8694912: Oct  9 10:55:58.194:
//148025/BCB3C79A92C0/SIP/Error/sact_idle_new_message_options:
Oct  9 12:52:06 10.10.10.10 8694913:  *Resource failure, dropping OPTIONS*

The true is that Cisco receives quite significant amount of SIP OPTIONs
from the endpoint in short time, like 10 OPTIONS packeges within
miliseconds.
The after-effect i want to achieve is a response for each incoming OPTIONS

Example of a successful response:
Oct  9 11:30:37 10.10.10.10 8625106: Oct  9 09:34:28.569:
//-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI :
SIPSPI_EV_CC_OPTIONS_RESP
Oct  9 11:30:37 10.10.10.10 8625107: Oct  9 09:34:28.569:
//146857/5A42A0608E30/SIP/Info/info/4096/sact_idle_new_message_options:
ccsip_api_options_ind returned: SIP_SUCCESS
Oct  9 11:30:37 10.10.10.10 8625108: Oct  9 09:34:28.569:
//146857/5A42A0608E30/SIP/State/sipSPIChangeState: 0x258B1110 : State
change from (STATE_IDLE, SUBSTATE_NONE)  to (SIP_STATE_OPTIONS_WAIT,
SUBSTATE_NONE)
Oct  9 11:30:37 10.10.10.10 8625109: Oct  9 09:34:28.569:
//146857/5A42A0608E30/SIP/Info/verbose/4096/sipSPIUaddCcbToTable: Added to
table. ccb=0x258B1110
key=c3c4f5582a4bfa1ff4b7e741c3cb6c6822f738b4cd7e78633fc70f5441197d3 balance
1
Oct  9 11:30:37 10.10.10.10 8625110: Oct  9 09:34:28.569:
//146857/5A42A0608E30/SIP/Info/verbose/4096/sipSPIUaddccCallIdToTable:
Adding call id 23DA9 to table
Oct  9 11:30:37 10.10.10.10 8625111: Oct  9 09:34:28.569:
//-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event:
ccsip_spi_get_msg_type returned: 3 for event 38
Oct  9 11:30:37 10.10.10.10 8625112: Oct  9 09:34:28.569:
//-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created
msg=0x203FFDA4 with refCount = 1
Oct  9 11:30:37 10.10.10.10 8625113: Oct  9 09:34:28.569:
//146857/5A42A0608E30/SIP/Info/info/4096/sipSPISendOptionsResponse:
Associated container=0x2673A528 to Options Response
Oct  9 11:30:37 10.10.10.10 8625114: Oct  9 09:34:28.569:
//-1/xxxxxxxxxxxx/SIP/Info/verbose/8192/sipSPIAppHandleContainerBody:
sipSPIAppHandleContainerBody len 164
Oct  9 11:30:37 10.10.10.10 8625115: Oct  9 09:34:28.569:
//146857/5A42A0608E30/SIP/Transport/sipSPITransportSendMessage:
msg=0x203FFDA4, addr=11.11.11.11, port=5060, sentBy_port=5060, local_addr=,
is_req=0, transport=1, switch=0, callBack=0x4F48054
Oct  9 11:30:37 10.10.10.10 8625116: Oct  9 09:34:28.569:
//146857/5A42A0608E30/SIP/Info/info/2048/sipSPIGetExtensionCfg: SIP
extension config:1, check sys cfg:1
Oct  9 11:30:37 10.10.10.10 8625117: Oct  9 09:34:28.569:
//146857/5A42A0608E30/SIP/Transport/sipSPITransportSendMessage: Proceedable
for sending msg immediately
Oct  9 11:30:37 10.10.10.10 8625118: Oct  9 09:34:28.569:
//146857/5A42A0608E30/SIP/Transport/sipTransportLogicSendMsg: Trying to
send resp=0x203FFDA4 to default port=5060
Oct  9 11:30:37 10.10.10.10 8625119: Oct  9 09:34:28.569:
//-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection:
connection required for raddr:11.11.11.11, rport:5060 with laddr:
Oct  9 11:30:37 10.10.10.10 8625120: Oct  9 09:34:28.569:
//-1/xxxxxxxxxxxx/SIP/Transport/sipInstanceGetConnectionId: Registering
gcb=0x258B1110 with connection=0x2426673C context list
Oct  9 11:30:37 10.10.10.10 8625121: Oct  9 09:34:28.569:
//146857/5A42A0608E30/SIP/Transport/sipTransportLogicSendMsg: Connection
obtained...sending msg=0x203FFDA4
Oct  9 11:30:37 10.10.10.10 8625122: Oct  9 09:34:28.569:
//-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send
for msg=0x203FFDA4, addr=11.11.11.11, port=5060, local_addr=, connId=2 for
UDP
Oct  9 11:30:37 10.10.10.10 8625123: Oct  9 09:34:28.569:
//146857/5A42A0608E30/SIP/Msg/ccsipDisplayMsg:
Oct  9 11:30:37 10.10.10.10 8625124: Sent:
Oct  9 11:30:37 10.10.10.10 8625125: SIP/2.0 200 OK#015

Could someone help me with this? I really appreciate your advice.

Maciej
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://puck.nether.net/pipermail/cisco-voip/attachments/20181009/92e2be8d/attachment.html>