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

Maciej Bylica mbgatherer at gmail.com
Tue Oct 9 16:54:16 EDT 2018


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/20181009/f88f357f/attachment.html>


More information about the cisco-voip mailing list