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

Tue Oct 9 10:39:36 EDT 2018

Are you using Customer Call Back? Which dial peer is the options ping
hitting? Does that dial peer have the CCB script on it? If so... maybe make
another dial peer for options pings that does not have the script enabled.
This is just a hunch...

On Tue, Oct 9, 2018 at 6:50 AM Maciej Bylica <mbgatherer at gmail.com> wrote:

> 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
> _______________________________________________
> cisco-voip mailing list
> cisco-voip at puck.nether.net
> https://puck.nether.net/mailman/listinfo/cisco-voip
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://puck.nether.net/pipermail/cisco-voip/attachments/20181009/b4824926/attachment.html>