%SIP-3-BADPAIR: Unexpected event 38 (SIPSPI_EV_CC_OPTIONS_RESP) in state 9 (STATE_DISCONNECTING) substate 0 (SUBSTATE_NONE)

[the-lebowski]

I got a report from end users in a remote office today of their calls dropping.  I checked the cube and at roughly the same time I see these two messages in the logs:

May 5 08:20:36.730 PDT: %SIP-3-BADPAIR: Unexpected event 38 (SIPSPI_EV_CC_OPTIONS_RESP) in state 9 (STATE_DISCONNECTING) substate 0 (SUBSTATE_NONE)
May 5 08:20:37.234 PDT: %SIP-3-BADPAIR: Unexpected event 38 (SIPSPI_EV_CC_OPTIONS_RESP) in state 9 (STATE_DISCONNECTING) substate 0 (SUBSTATE_NONE)

I don't have debugs because the problem isn't happening right now and it seems to be intermittent.  However this happened twice this week and both times it appeared to be while on a webex audio bridge causing the calls to drop.  This offices uses local SIP trunk, 2911 CUBE running Version 15.4(3)M4 and registering to a remote CUCM via MPLS cloud.  I am wondering if anyone knows what would cause this?  

More data, it seems like any webex call that last 15 minutes gets dropped and these logs are generated on the CUBE.  The local users are keeping track of when they join the call and when it fails its like clockwork, call drops and these messages are generated.  The users phone generates a ton of these messages in the logs:

4630 ERR May 06 16:29:48.712629 ms-RTPSNDRCV.rtpsndrcv_readError[A:41] [stream=7][sock=29] receive error [last errno=111][count=181]
4631 NOT May 06 16:29:48.713545 JAVA-SIPCC-MED_API: media_server_callback_handler: ICMP Unreachable callback received
4632 NOT May 06 16:29:49.213346 JAVA-SIPCC-MED_API: media_server_callback_handler: ICMP Unreachable callback received
4633 NOT May 06 16:29:49.713270 JAVA-SIPCC-MED_API: media_server_callback_handler: ICMP Unreachable callback received
4634 NOT May 06 16:29:50.213194 JAVA-SIPCC-MED_API: media_server_callback_handler: ICMP Unreachable callback received
4635 NOT May 06 16:29:50.713239 JAVA-SIPCC-MED_API: media_server_callback_handler: ICMP Unreachable callback received
4636 NOT May 06 16:29:51.231109 JAVA-SIPCC-MED_API: media_server_callback_handler: ICMP Unreachable callback received
4637 NOT May 06 16:29:51.731246 JAVA-SIPCC-MED_API: media_server_callback_handler: ICMP Unreachable callback receive

Does no one have any idea what would cause this?  

[Nadeem Ahmed]

Can you please share show run from the CUBE? also if there any logs you have that would be quite easy to tell what causing this issue. Let me give it shot and trying looking over the configuration.

Br,

Nadeem

[the-lebowski]

Thats the only logs I have but it coincides with what the users reported.  Can I PM or email the 'show run' to you?  

[Nadeem Ahmed]

Sure

[the-lebowski]

How can I do that?  IE whats your email?  

Happened again while user was connected to webex audio using a 7841 phone.  

May 6 10:19:12.597 PDT: %SIP-3-BADPAIR: Unexpected event 38 (SIPSPI_EV_CC_OPTIONS_RESP) in state 9 (STATE_DISCONNECTING) substate 0 (SUBSTATE_NONE)

[jigy00001]

I have this problem also, How to do it ？

[the-lebowski]

The problem (in my case) was the phones loosing the path to call manager, so check your network.  

[jigy00001]

ok, thank you very much!

My friend told me it's network issue, He has solved it by changing ISP VPN.

[b.azimbaev]

Good afternoon, I have such a situation. We have a contact center, when customers are calling, calls are not heard. 
Weekends, night time works fine. namely, the problem begins in the afternoon. When it stops working, 
I restart the Cisco IP Voice Media streaming app service and it starts working normally again, 
then it takes about an hour to reboot the service again. 
And in the evening it starts to work stably. CUBE has an error such as 000369: Sep 6 10: 04: 04.324:% SIP-3-BADPAIR: Unexpected event 38 (SIPSPI_EV_CC_OPTIONS_RESP) in state 25 (SIP_STATE_MIDCALL_RECD_SUCCESS) substate 0 (SUBSTATE_NONE)
000370: Sep 6 10: 05: 49.072:% VOICE_IEC-3-GW: SIP: Internal Error (2xx, codec mismatch): IEC = 1.1.278.7.109.0 on callID 7828 GUID = 859EE31E0DFE11ECA1F79325F0C03700

[Mohammed al Baqari]

Hi,

When the call is connected, check on CUBE show call active voice brief,
pick a sample call and see the stats of tx/rx to see how they look.

This will help to see whether CUBE is receiving and pass RTP packets or
not.

***** please remember to rate useful posts

[b.azimbaev]

Hi Mohammed ai Baqari. Thanks for your feedback. I tried what you suggested below:

 media inactive detected:<y/n> media cntrl rcvd:<y/n> timestamp:<time>

long duration call detected:<y/n> long duration call duration :<sec> timestamp:<time>
LostPacketRate:<%> OutOfOrderRate:<%>
LocalUUID:<%> RemoteUUID:<%>
VRF:<%>
MODEMPASS <method> buf:<fills>/<drains> loss <overall%> <multipkt>/<corrected>
last <buf event time>s dur:<Min>/<Max>s
FR <protocol> [int dlci cid] vad:<y/n> dtmf:<y/n> seq:<y/n>
<codec> (payload size)
ATM <protocol> [int vpi/vci cid] vad:<y/n> dtmf:<y/n> seq:<y/n>
<codec> (payload size)
Tele <int> (callID) [channel_id] tx:<tot>/<v>/<fax>ms <codec> noise:<l> acom:<l> i/o:<l>/<l> dBm
MODEMRELAY info:<rcvd>/<sent>/<resent> xid:<rcvd>/<sent> total:<rcvd>/<sent>/<drops>
speeds(bps): local <rx>/<tx> remote <rx>/<tx>
Proxy <ip>:<audio udp>,<video udp>,<tcp0>,<tcp1>,<tcp2>,<tcp3> endpt: <type>/<manf>
bw: <req>/<act> codec: <audio>/<video>
tx: <audio pkts>/<audio bytes>,<video pkts>/<video bytes>,<t120 pkts>/<t120 bytes>
rx: <audio pkts>/<audio bytes>,<video pkts>/<video bytes>,<t120 pkts>/<t120 bytes>