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

Thu Oct 11 16:59:30 EDT 2018

Should also throw out that, one of the carriers, didn’t care about options as long as there was something hitting it.   

> On Oct 11, 2018, at 2:57 PM, Kent Roberts <kent at fredf.org> wrote:
> 
> Oh sorry, I didn’t catch that on the receiving part.    Well, I probably should re-look at some of the commands, but we were one of the first adopters of SIP and not all the defaults that exist today, existed back then.   Some of it got left in cause it works with the carrier.    :)       Some of it was also trial and error with the carrier, and well when it starts working sometimes things don’t get revisited….   Hows that for an answer!!!
> 
> 
> 
>> On Oct 11, 2018, at 2:42 PM, Anthony Holloway <avholloway+cisco-voip at gmail.com <mailto:avholloway+cisco-voip at gmail.com>> wrote:
>> 
>> Kent,
>> 
>> I'm not sure why you sent that.  The problem is not with sending OPTION Ping, it's with responding to received OPTION Ping.
>> 
>> "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"
>> 
>> But since you brought it up... The default for that command is:
>> 
>> voice class sip options-keepalive up-interval 60 down-interval 30 retry 5
>> 
>> What is your reason for changing it from the default?  The rule of thumb is "use the defaults, unless you have a reason not to"
>> 
>> I see the obvious answer here: it pings less often; however, it's the why which I am interested in.
>> 
>> Thanks for sharing what you do.
>> 
>> On Thu, Oct 11, 2018 at 3:32 PM Kent Roberts <kent at fredf.org <mailto:kent at fredf.org>> wrote:
>> Here is what I use:
>> 
>> voice-class sip options-keepalive up-interval 180 down-interval 60 retry 2
>> 
>> Sh dial-peer voice sum    the Keepalive line will show busyout or active.
>> 
>> 
>> 
>> 
>>> On Oct 11, 2018, at 12:36 PM, Nick Barnett <nicksbarnett at gmail.com <mailto:nicksbarnett at gmail.com>> wrote:
>>> 
>>> I don’t know what the problem is either. Maybe if you grab ccapi inout debugs at the same time, your voice service voip section (at least, whole config would be better), sh ver, and show run | sec voice. Maybe even do a debug ccsip all if you have the ability to do that and NOT crash your CUBE. Obviously don’t debug ccsip all without thinking about what that will do.
>>> 
>>>  
>>> Even with all of that, I’m not sure I’ll have an answer, but I’ll look. I’ve had similar issues with my CUBEs and it was due to binding issues and another time it was a straight up bug and I had to bounce the box (which “fixed” it).  I don’t know why your initial debug was showing “could not add ccb to table” and I’m not even sure which CCB it’s talking about. My thoughts were that is customer callback… but I’m probably wrong on that one.
>>> 
>>>  
>>> Nick
>>> 
>>> 
>>> On Thu, Oct 11, 2018 at 11:11 AM Anthony Holloway <avholloway+cisco-voip at gmail.com <mailto:avholloway%2Bcisco-voip at gmail.com>> wrote:
>>> I feel obligated to reply, since I chimed in earlier....unfortunately, I don't have any ideas for you.  In fact, I have seen CUBE just ignore incoming SIP messages before, both OPTIONS and INVITEs alike.  Not many occasions, just a few.  I have never gotten resolution on it, it has either fixed itself, or in one special case, still happens.  It's my own, in fact.  It still randomly ignores inbound INVITES from my ITSP.  Fixing it, is on my to-do list, but...  The cobbler's children are always the worst-shod <https://english.stackexchange.com/questions/46681/a-saying-indicating-how-some-professionals-dont-apply-their-skills-for-themselv>.  The Calls Per Second on my CUBE is like 1.7, however, there are no other calls being setup, torn down, sup service, etc, and CUBE still just ignores its responsibility.
>>> 
>>> On Thu, Oct 11, 2018 at 9:51 AM Maciej Bylica <mbgatherer at gmail.com <mailto:mbgatherer at gmail.com>> wrote:
>>> Hello
>>> 
>>> Do you have an idea how to get around this problem?
>>> Have you ever encountered such limitations in the process of processing OPTIONS packages? 
>>> 
>>> Thanks
>>> Maciej.
>>> 
>>> śr., 10 paź 2018 o 09:13 Maciej Bylica <mbgatherer at gmail.com <mailto:mbgatherer at gmail.com>> napisał(a):
>>> 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 <mailto:avholloway%2Bcisco-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 <mailto: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 <mailto:avholloway%2Bcisco-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 <mailto: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 <http://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 at domain.name.here>;tag=4a6000292f6a
>>> To: <sip:stringhere at 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 at domain.name.here>;tag=4a6000292f6a
>>> 		old_to:	<sip:stringhere at domain.name.here>;tag=D7E844-1438
>>> 		new_from:	<sip:stringhere at domain.name.here>;tag=6c7f09452671
>>> 		new_to:	<sip:stringhere at 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 <mailto: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 <mailto: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 <mailto:cisco-voip at puck.nether.net>
>>> https://puck.nether.net/mailman/listinfo/cisco-voip <https://puck.nether.net/mailman/listinfo/cisco-voip>
>>> _______________________________________________
>>> cisco-voip mailing list
>>> cisco-voip at puck.nether.net <mailto:cisco-voip at puck.nether.net>
>>> https://puck.nether.net/mailman/listinfo/cisco-voip <https://puck.nether.net/mailman/listinfo/cisco-voip>
>>> _______________________________________________
>>> cisco-voip mailing list
>>> cisco-voip at puck.nether.net <mailto:cisco-voip at puck.nether.net>
>>> https://puck.nether.net/mailman/listinfo/cisco-voip <https://puck.nether.net/mailman/listinfo/cisco-voip>
>> 
> 

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://puck.nether.net/pipermail/cisco-voip/attachments/20181011/3e038dfa/attachment.html>