[cisco-voip] SIP OPTIONS pings are blocked on Cisco CUBE 3945E - Resource failure, dropping OPTIONS
Maciej Bylica
mbgatherer at gmail.com
Wed Oct 10 03:13:17 EDT 2018
Hello
Anthony, thanks for the hint, but you were right this is not the core of
the issue.
I made some test via sipp with following results
1)
Test: Send 15xOPTIONS with the same Call-ID and From-tag
Result: All OPTIONS were replied
2)
Test: shortly after completing the above test I made another test: Send
15xOPTIONS with the same Call-ID as previously but different From-tag.
Result: None of the OPTIONS we’re replied.
3)
Test: Test 2 was re-run after a while
Result: All OPTIONS were replied
So it seems Cisco records the Call-ID and From-tag somewhere in memory and
drops subsequent OPTIONS with the same Call-ID and different From-tag that
come from the same endpoint for some time.
I have similar situation here.
The customer we are trying to connect sends several OPTIONS within
miliseconds.
First OPTIONS is replied properly, but subsequent packets with the same
Call-ID and different From-tag dropped.
Is there any solution for this.
Our customer is very reluctant to proceed with any changes (another open
source SIP proxies replies all the OPTIONS).
Thanks
Maciej.
wt., 9 paź 2018 o 23:45 Anthony Holloway <avholloway+cisco-voip at gmail.com>
napisał(a):
> I hope you saw that I wrote "Pseudo Config" and don't just try to copy and
> paste that. I'm also not very convinced that this is the core of your
> issue, but you're more than welcome to give it a try.
>
> You said the first OPTIONS does respond, so I'm guessing it's not going to
> be a binding error. In fact, if it was a binding error, OPTIONS would
> still respond, it would just have wrong IP info in the headers.
>
> Anyway, good luck with that test.
>
> On Tue, Oct 9, 2018 at 3:54 PM Maciej Bylica <mbgatherer at gmail.com> wrote:
>
>> Thanks, i am about to modify the config to check.
>>
>> Many thanks
>>
>>
>> wt., 9 paź 2018 o 20:58 Anthony Holloway <avholloway+cisco-voip at gmail.com>
>> napisał(a):
>>
>>> OPTIONS does not have to match a dial peer to work. However, if you are
>>> going to match a dial peer at all, it would likely be for the express
>>> purpose of replying from the correct interface, if you have more than one
>>> potential interfaces, and you for some reason cannot bind globally. Thus
>>> using the correct bind statement on a dial-peer for OPTIONS reply, would be
>>> necessary. In which case, you would need to match an incoming call leg
>>> dial peer by the SIP Via header alone, and not, say for example, incoming
>>> called number.
>>>
>>> Example Pseudo Configuration:
>>>
>>> voice class sip uri 100
>>> host ipv4:10.1.1.1
>>> !
>>> dial-peer voice 100 voip
>>> incoming uri via 100
>>> bind media interface g0/1
>>> bind control interface g0/1
>>> !
>>>
>>> On Tue, Oct 9, 2018 at 1:12 PM Maciej Bylica <mbgatherer at gmail.com>
>>> wrote:
>>>
>>>> Thanks for prompt answer.
>>>>
>>>> No, i am not using CCP.
>>>> As i see OPTIONS ping does not match with any dialpeer
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/info/1024/ccsipInitPldCallingInfo: non-numeric
>>>> calling number: *stringhere*
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/verbose/1024/sipSPIGetViaHostInURLFormat: VIA
>>>> URL:sip:10.10.10.10:5060, Host:100.64.4.31
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/verbose/67584/sipSPIGetShrlPeer: Try match
>>>> incoming dialpeer for Calling number: : *stringhere*
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Error/sipSPIGetPeerByCalledPartyId:
>>>>
>>>> input arg error
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/critical/10240/sipSPIGetCallConfig: No match
>>>> found for P-Called-Party-ID
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Error/sipSPIUpdateCallInfo:
>>>>
>>>> input argument error
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/verbose/1024/sipSPIGetCallConfig: Precondition
>>>> tag absent in Require/Supported header
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/verbose/2048/sipSPIGetCallConfig: Media
>>>> Antitrombone disabled
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/info/8192/sipSPISetMediaFlowMode: Storing the
>>>> configured mode as FLOW-THROUGH
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/info/2304/sipSPISetMediaFlowMode: xcoder
>>>> high-density disabled
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/info/8192/sipSPISetMediaFlowMode: Flow Mode
>>>> set to FLOW_THROUGH
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/info/10240/sipSPIGetCallConfig: Non dial peer
>>>> leg - using RTP Supported Codecs
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred
>>>> Codecs supported by GW 18
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred
>>>> Codecs supported by GW 0
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred
>>>> Codecs supported by GW 8
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred
>>>> Codecs supported by GW 9
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred
>>>> Codecs supported by GW 4
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred
>>>> Codecs supported by GW 2
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred
>>>> Codecs supported by GW 15
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/info/10240/sipSPIGetCallConfig: RTP Preferred
>>>> Codecs supported by GW 255
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/critical/32768/ccsip_ipip_media_forking_update_preferred_codec:
>>>> MF: Not a Forked SIP leg..
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/verbose/1/ccsip_set_srtp_config: No Srtp
>>>> configure for this leg.
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/verbose/12288/sipSPIGetModemInfoPerCall:
>>>> peer_callID=0
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Error/ccsip_ipip_media_forking_anchor_leg_config:
>>>>
>>>>
>>>> MF: *Dial-peer is absent*..
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/info/36864/sipSPIMFChangeState: MF: Prev state
>>>> = 0 & New state = -1
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Info/info/32768/ccsip_ipip_media_forking_anchor_leg_reset:
>>>> MF: Anchor leg config reset done...
>>>>
>>>> Oct 9 17:50:04.068:
>>>> //3652/95FFAA748E45/SIP/Error/ccsip_ipip_media_forking_intra_frame_request_config:
>>>>
>>>>
>>>> MF:video profile Dial-peer is absent..
>>>>
>>>>
>>>> OPTIONS looks like following:
>>>>
>>>> OPTIONS sip:domain.name.here:5060 SIP/2.0
>>>>
>>>> From: <sip:*stringhere*@domain.name.here>;tag=4a6000292f6a
>>>>
>>>> To: <sip:*stringhere*@domain.name.here>
>>>>
>>>>
>>>>
>>>> I do not have any script in use there, the configuration in pretty
>>>> basic.
>>>> What i have found is that second OPTIONS (the one that is left/dropped
>>>> without OK) also generates following output:
>>>>
>>>> Oct 9 17:50:38.070:
>>>> //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor:
>>>> Checking Invite Dialog
>>>>
>>>> Oct 9 17:50:38.070:
>>>> //3653/9862338A8E46/SIP/Info/verbose/4096/sipSPIFindCcbUASReqTable:
>>>> *****CCB found in UAS Request table. ccb=0x2766B958
>>>>
>>>> Oct 9 17:50:38.070:
>>>> //3653/9862338A8E46/SIP/Info/info/4096/sipSPICheckFromToRequest: Trying
>>>> with child CCB 0x0 index 0 curr_child 0
>>>>
>>>>
>>>> Oct 9 17:50:38.070:
>>>> //3653/9862338A8E46/SIP/Error/sipSPICheckFromToRequest:
>>>>
>>>>
>>>>
>>>> Failed FROM/TO Request check - IGNORE IF HAIRPIN CALL
>>>>
>>>> old_from: <sip:*stringhere*@domain.name.here>;tag=4a6000292f6a
>>>>
>>>> old_to: <sip:*stringhere*@domain.name.here>;tag=D7E844-1438
>>>>
>>>> new_from: <sip:*stringhere*@domain.name.here>;tag=6c7f09452671
>>>>
>>>> new_to: <sip:*stringhere*@domain.name.here>
>>>>
>>>> ....
>>>>
>>>> Oct 9 17:50:04.068: //-1/xxxxxxxxxxxx/SIP/Error/httpish_msg_free:
>>>>
>>>> Freeing NULL pointer!
>>>>
>>>> Could you please point me where i can find some information how to
>>>> create such dial-peer for OPTIONS or give me a brief example of this
>>>> configuration please.
>>>>
>>>> Thanks
>>>> Maciej.
>>>>
>>>>
>>>>
>>>>
>>>> wt., 9 paź 2018 o 16:39 Nick Barnett <nicksbarnett at gmail.com>
>>>> napisał(a):
>>>>
>>>>> 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
>>>>>>
>>>>> _______________________________________________
>>>> 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/20181010/da213664/attachment.html>
More information about the cisco-voip
mailing list