Author Topic: First DTMF Not Detected (Read 5508 times)

shakeel8787 · « **on:** February 24, 2016, 04:25:16 PM »

Hi,

I have a simple scxml application developed on composer, which collects digits using the 'User Input' Block. The application works fine, except that it does not recognize the first digit (DTMF) I press. But later on all the digits are recognized correctly. On pressing the first DTMF, the message is interepted, but the digit is not collected.

I can see the below from SIP log and MCP log

[u][b]SIP Log[/b][/u]
[i]18:06:01.154: SipDialog: event CONNECTED_SEND_RESOK, t=194222, s=7, r=8, m=000000000378fe38
18:06:01.154 SIPCONN(msml-dn): HandleSipDialogEvent(CONNECTED_SEND_RESOK) - filtered
18:06:01.154 SIPMS(msml-dn): process next prompt
18:06:01.154 SIPMS(msml-dn): start_timeout timer set {id=400556049,timeout=10000}
18:06:01.154: $-NET:SIP::0:406

18:06:01.154: CGSIPListener[0]: Accepted new connection on socket 484
18:06:01.170: $+NET:SIP::0:0
18:06:01.170: SIPS:LOGBLOCK:BEGIN:SIPMSG:[
18:06:01.170: SIPTR: Received [484,TCP] 1323 bytes from 192.168.10.193:56668 <<<<<
INFO sip:112791809@192.168.10.191:5060 SIP/2.0
Via: SIP/2.0/TCP 192.168.10.193:5060;branch=z9hG4bK0000000010C2CFE0cdc6d9abcdef09
Via: SIP/2.0/TCP 192.168.10.193:5070;branch=z9hG4bK000000001FA61B90cdc6d9
From: <sip:msml-dn@192.168.10.191:5060>;tag=A2E6C519-19AD-4795-1E96-A0A2915A84E8
To: sip:112791809@jcci.com;tag=56CA7757-2EE0-4A24-88FD-8E8F78084668-181429
Max-Forwards: 69
CSeq: 2 INFO
Call-ID: 86573D1B-7381-44DA-B880-9E9A6780FA2A-181110@192.168.10.191
Content-Length: 263
Content-Type: application/vnd.radisys.msml+xml
X-Genesys-GVP-Session-ID: 46CDC57D-4742-420E-CD93-4894118F5566;gvp.rm.datanodes=1;gvp.rm.tenant-id=101_IVRAppDefault
P-Location: SM;origlocname="Jeddah";origsiglocname="Jeddah";origmedialocname="Jeddah";termlocname="Jeddah";termsiglocname="Jeddah";termmedialocname="Jeddah";smaccounting="true"
User-Agent: Avaya CM/R016x.03.0.124.0 AVAYA-SM-6.3.16.0.631601
P-Charging-Vector: icid-value="AAS:777-23f676801e5da58d05620bf670d"
Av-Global-Session-ID: 8076f623-58da-4501-be20-56d00d670000
Min-SE: 90
Supported: timer, uui

<?xml version="1.0" encoding="UTF-8"?>
<msml version="1.1">
<event name="app.digits" id="conn:A2E6C519-19AD-4795-1E96-A0A2915A84E8/dialog:CollectDigits2417">
<name>dtmf.digits</name>
<value>8</value>
<name>dtmf.end</name>
<value>undefined</value>
</event>
</msml>
18:06:01.170: SIPDLG[1078]: register TRN[194223]
gsip:DLG[1078]: Remote CSeq mismatch: 2 < 3. Rejecting request
18:06:01.170: Sending [484,TCP] 479 bytes to 192.168.10.193:56668 >>>>>
SIP/2.0 [color=red]500 Server Internal Error[/color]
Via: SIP/2.0/TCP 192.168.10.193:5060;branch=z9hG4bK0000000010C2CFE0cdc6d9abcdef09;received=192.168.10.193
Via: SIP/2.0/TCP 192.168.10.193:5070;branch=z9hG4bK000000001FA61B90cdc6d9
From: <sip:msml-dn@192.168.10.191:5060>;tag=A2E6C519-19AD-4795-1E96-A0A2915A84E8
To: sip:112791809@jcci.com;tag=56CA7757-2EE0-4A24-88FD-8E8F78084668-181429
CSeq: 2 INFO
Call-ID: 86573D1B-7381-44DA-B880-9E9A6780FA2A-181110@192.168.10.191
Content-Length: 0

18:06:01.170: SipDialog: event CONNECTED_SEND_RESREJECT, t=194223, s=7, r=5, m=000000000378fe38
18:06:01.170 SIPCONN(msml-dn): HandleSipDialogEvent(CONNECTED_SEND_RESREJECT) - filtered
18:06:01.170: SIPS:LOGBLOCK:END:SIPMSG:]
18:06:01.170: $-NET:SIP::0:187

18:06:02.389: $+NET:SIP::0:0
18:06:02.389: SIPS:LOGBLOCK:BEGIN:SIPMSG:[
18:06:02.389: SIPTR: Received [484,TCP] 1323 bytes from 192.168.10.193:56668 <<<<<
INFO sip:112791809@192.168.10.191:5060 SIP/2.0
Via: SIP/2.0/TCP 192.168.10.193:5060;branch=z9hG4bK000000001AF6D0B0cdc6daabcdef09
Via: SIP/2.0/TCP 192.168.10.193:5070;branch=z9hG4bK000000001F957070cdc6da
From: <sip:msml-dn@192.168.10.191:5060>;tag=A2E6C519-19AD-4795-1E96-A0A2915A84E8
To: sip:112791809@jcci.com;tag=56CA7757-2EE0-4A24-88FD-8E8F78084668-181429
Max-Forwards: 69
CSeq: 4 INFO
Call-ID: 86573D1B-7381-44DA-B880-9E9A6780FA2A-181110@192.168.10.191
Content-Length: 263
Content-Type: application/vnd.radisys.msml+xml
X-Genesys-GVP-Session-ID: 46CDC57D-4742-420E-CD93-4894118F5566;gvp.rm.datanodes=1;gvp.rm.tenant-id=101_IVRAppDefault
P-Location: SM;origlocname="Jeddah";origsiglocname="Jeddah";origmedialocname="Jeddah";termlocname="Jeddah";termsiglocname="Jeddah";termmedialocname="Jeddah";smaccounting="true"
User-Agent: Avaya CM/R016x.03.0.124.0 AVAYA-SM-6.3.16.0.631601
P-Charging-Vector: icid-value="AAS:777-23f676801e5da58d05620bf670d"
Av-Global-Session-ID: 8076f623-58da-4501-be20-56d00d670000
Min-SE: 90
Supported: timer, uui

<?xml version="1.0" encoding="UTF-8"?>
<msml version="1.1">
<event name="app.digits" id="conn:A2E6C519-19AD-4795-1E96-A0A2915A84E8/dialog:CollectDigits2417">
<name>dtmf.digits</name>
<value>8</value>
<name>dtmf.end</name>
<value>undefined</value>
</event>
</msml>
18:06:02.389: SIPDLG[1078]: register TRN[194224]
18:06:02.389: SipDialog: event CONNECTED_REQUEST, t=194224, s=7, r=5, m=000000000378fe38
18:06:02.389 SIPCONN(msml-dn): HandleSipDialogEvent(CONNECTED_REQUEST)
18:06:02.389 SIPCONN(msml-dn): new transaction
18:06:02.389 SIPCONN(msml-dn): 1pcc event CONNECTED_REQUEST
18:06:02.389 SIPCONN(msml-dn): Handle INFO
18:06:02.389 SIPCONN(msml-dn): SendResponse(200,194224)
18:06:02.389: Sending [484,TCP] 710 bytes to 192.168.10.193:56668 >>>>>
SIP/2.0 200 OK
Via: SIP/2.0/TCP 192.168.10.193:5060;branch=z9hG4bK000000001AF6D0B0cdc6daabcdef09;received=192.168.10.193
Via: SIP/2.0/TCP 192.168.10.193:5070;branch=z9hG4bK000000001F957070cdc6da
From: <sip:msml-dn@192.168.10.191:5060>;tag=A2E6C519-19AD-4795-1E96-A0A2915A84E8
To: sip:112791809@jcci.com;tag=56CA7757-2EE0-4A24-88FD-8E8F78084668-181429
CSeq: 4 INFO
Call-ID: 86573D1B-7381-44DA-B880-9E9A6780FA2A-181110@192.168.10.191
Contact: <sip:112791809@192.168.10.191:5060>
X-Genesys-CallUUID: H2CG4795V95G13Q15UGTFJGE9K00008M
Allow: INVITE, ACK, PRACK, CANCEL, BYE, REFER, INFO, UPDATE, MESSAGE, NOTIFY, OPTIONS
P-Asserted-Identity: <sip:112791809@jcci.com>
Supported: uui
Content-Length: 0[/i]

[u][b]MCP Log[/b][/u]
[i]016-02-24 18:06:01.057 DBUG 0078016C-100032BF 3680 0B200000 MPCDTMFDispatcher.cxx:99 MPCDTMFDispatcher::MediaTransmit - LastDTMFRxTimeIndex=0, LastProcessedDTMF=false, LastDTMF=18, LastRxTime=4294967295, PacketTimeIndex=2705160745
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 3680 0B200000 MPCDTMFDispatcher.cxx:99 MPCDTMFDispatcher::MediaTransmit - LastDTMFRxTimeIndex=0, LastProcessedDTMF=false, LastDTMF=18, LastRxTime=4294967295, PacketTimeIndex=2705160745
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 3680 0B200000 MPCPlayer.cxx:532 MPCPlayer::Stop: m_State=1 nStopReason=0
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 3680 0B200000 MPCPlayer.cxx:2349 Getting mark... 440
2016-02-24 18:06:01.057 DBUG 00000000-00000000 756 01B00000 AppEventBase.h:61 app.MSML AMEVENT_MSML_MSMLSESSIONEVENT -
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 01B00000 MSMLAppInstance.cxx:686 Received MSML CallLeg event AMEVENT_MSML_MSMLSESSIONEVENT
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 01B00000 AppCallLeg.h:174 Call Leg Application Event
2016-02-24 18:06:01.057 DBUG 00000000-00000000 756 01B00000 AppEventBase.h:61 app.MSML AMEVENT_MSML_MSMLSESSIONEVENT -
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 01B00000 MSMLAppInstance.cxx:686 Received MSML CallLeg event AMEVENT_MSML_MSMLSESSIONEVENT
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 01B00000 MSMLDialogPlay.cxx:1911 MSMLDialogPlay::DtmfProcess: process DTMF 8
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 4792 0B200000 MPCPlayer.cxx:2271 MPCPlayer::NotifyPlayDone: m_nStopReason=0 m_nState=7 m_nFlushDur=560 m_nLocalBargeinOffset=440; Last prompt info: Orig URI [file://\\callcenterui\arm\target/announcement/101100311_pcma.wav]; Media URI [gvpstream://1]
2016-02-24T18:06:01.057 Trc 21004 INFO 0078016C-100032BF 4792 02B00FAD prompt_stop
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 4792 0B200000 MPCMediaStream.cxx:671 MPCMediaStream[000000001FDC4D30]::ReleaseListener - pListener=000000001FA92770
2016-02-24 18:06:01.057 DBUG 00000000-00000000 4544 0B100000 MPCDialog.cxx:1405 MPCDialog::ProcessPlayDone, LogID=0078016C-100032BF DialogID=20152997 nPlaydoneReason=0 nBargeinLocalDur=440 nMarkDur=440
2016-02-24 18:06:01.057 DBUG 00000000-00000000 4544 0B100000 MPCDialog.cxx:1410 MPCDialog::ProcessPlayDone, LogID=0078016C-100032BF DialogID=20152997 nMarkIndex=-1 nTotalPlayedBytes=3520 nTotalPlayedDur=440
2016-02-24 18:06:01.057 DBUG 00000000-00000000 1400 01C00000 CMMsgBase.h:183 cmapi.msg: CM_MSG_CALLLEG_APP_EVENT - StrEventInfo == <?xml version="1.0" encoding="UTF-8"?>
<msml version="1.1">
<event name="app.digits"
2016-02-24 18:06:01.057 DBUG 00000000-00000000 756 01B00000 AppEventBase.h:61 app.MSML AMEVENT_MSML_MSMLSESSIONEVENT -
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 01B00000 MSMLAppInstance.cxx:686 Received MSML CallLeg event AMEVENT_MSML_MSMLSESSIONEVENT
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 01B00000 MSMLDialog.cxx:1817 MSMLDialog::Terminate, current state 12
2016-02-24 18:06:01.057 DBUG 00000000-00000000 756 0B100000 MPCConnection.cxx:2074 MPCConnection::DisconnectRoute nLogID=0078016C-100032BF nConnID=10152990 ControlSinkID=20152997
2016-02-24 18:06:01.057 DBUG 00000000-00000000 756 0B100000 MPCDialog.cxx:1159 MPCDialog::GetSinks, LogID=0078016C-100032BF DialogID=20152997 ControlSourceID=10152990
2016-02-24 18:06:01.057 DBUG 00000000-00000000 756 0B100000 MPCControlObject.cxx:368 MPCControlObject::UnregisterSinkHelper LogID=0078016C-100032BF ObjectID=10152990 SourceID=00010000 SinkID=00010007 pRoute=1C2D8B20
2016-02-24 18:06:01.057 DBUG 00000000-00000000 756 0B100000 MPCDialog.cxx:1116 MPCDialog::UnregisterReverseRoute, LogID=0078016C-100032BF DialogID=20152997 ControlSourceID=10152990
2016-02-24 18:06:01.057 DBUG 00000000-00000000 756 0B100000 MPCDialog.cxx:967 MPCDialog::DisconnectRoute, LogID=0078016C-100032BF DialogID=20152997 ControlSinkID=10152990
2016-02-24 18:06:01.057 DBUG 00000000-00000000 756 0B100000 MPCConnection.cxx:2336 MPCConnection::GetSinks nLogID=0078016C-100032BF nConnID=10152990 ControlSourceID=20152997
2016-02-24 18:06:01.057 DBUG 00000000-00000000 756 0B100000 MPCConnection.cxx:2349 MPCConnection::GetSink - Sinks.size()=[1]
2016-02-24 18:06:01.057 DBUG 00000000-00000000 756 0B100000 MPCConnection.cxx:2361 MPCConnection::GetFCRSink nLogID=0078016C-100032BF nConnID=10152990
2016-02-24 18:06:01.057 DBUG 00000000-00000000 756 0B100000 MPCControlObject.cxx:416 MPCControlObject::UnregisterSinkHelper LogID=0078016C-100032BF ObjectID=20152997 OperatorID=00010006 SinkID=00010000 pRoute=1C2D84A0
2016-02-24 18:06:01.057 DBUG 00000000-00000000 756 0B100000 MPCConnection.cxx:2315 MPCConnection::UnregisterReverseRoute nLogID=0078016C-100032BF nConnID=10152990 ControlSourceID=20152997
2016-02-24 18:06:01.057 DBUG 00000000-00000000 756 0B100000 MPCDialog.cxx:780 MPCDialog::Destroy, LogID=0078016C-100032BF DialogID=20152997
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 0B200000 MPCPlayer.cxx:532 MPCPlayer::Stop: m_State=0 nStopReason=10
2016-02-24 18:06:01.057 DBUG 00000000-00000000 756 0B100000 MPCControlObject.cxx:368 MPCControlObject::UnregisterSinkHelper LogID=0078016C-100032BF ObjectID=20152997 SourceID=00010005 SinkID=00010006 pRoute=00000000
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 0B200000 MPCPlayer.cxx:532 MPCPlayer::Stop: m_State=0 nStopReason=10
2016-02-24 18:06:01.057 DBUG 00000000-00000000 756 0B100000 MPCDialog.cxx:1298 MPCDialog::QueueDestroyedEvent, LogID=0078016C-100032BF DialogID=20152997
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 01B00000 MSMLDialog.cxx:1191 MSMLDialog is in TERMINATED state with: m_nFromDialogRouteState=3, m_nToDialogRouteState=3, m_nVXMLDialogRouteState=0, m_bDialogCreated=true
2016-02-24 18:06:01.057 DBUG 00000000-00000000 756 01B00000 AppEventBase.h:61 app.MSML AMEVENT_MSML_MSMLSESSIONEVENT -
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 01B00000 MSMLAppInstance.cxx:686 Received MSML CallLeg event AMEVENT_MSML_MSMLSESSIONEVENT
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 01B00000 MSMLDialog.cxx:1191 MSMLDialog is in TERMINATED state with: m_nFromDialogRouteState=3, m_nToDialogRouteState=0, m_nVXMLDialogRouteState=0, m_bDialogCreated=true
2016-02-24 18:06:01.057 DBUG 00000000-00000000 756 01B00000 AppEventBase.h:61 app.MSML AMEVENT_MSML_MSMLSESSIONEVENT -
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 01B00000 MSMLAppInstance.cxx:686 Received MSML CallLeg event AMEVENT_MSML_MSMLSESSIONEVENT
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 01B00000 MSMLDialog.cxx:1191 MSMLDialog is in TERMINATED state with: m_nFromDialogRouteState=0, m_nToDialogRouteState=0, m_nVXMLDialogRouteState=0, m_bDialogCreated=true
2016-02-24 18:06:01.057 DBUG 00000000-00000000 756 01B00000 AppEventBase.h:61 app.MSML AMEVENT_MSML_MSMLSESSIONEVENT -
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 01B00000 MSMLAppInstance.cxx:686 Received MSML CallLeg event AMEVENT_MSML_MSMLSESSIONEVENT
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 01B00000 MSMLDialog.cxx:1191 MSMLDialog is in TERMINATED state with: m_nFromDialogRouteState=0, m_nToDialogRouteState=0, m_nVXMLDialogRouteState=0, m_bDialogCreated=false
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 01B00000 MSMLSession.cxx:286 MSMLSession::DialogDestroyed attempt to remove dialog conn:A2E6C519-19AD-4795-1E96-A0A2915A84E8/dialog:prompt2417
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 01B00000 AppCallLeg.h:174 Call Leg Application Event
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 01B00000 MSMLDialog.cxx:331 MSMLDialog::~MSMLDialog
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 0B200000 MPCMediaStream.cxx:590 MPCMediaStream[000000001FDC4D30]::ReleaseMediaStream
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 0B200000 MPCMediaStream.cxx:1097 MPCMediaStream[000000001FDC4D30]::Destroy
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 0B200000 MPCMediaStream.cxx:1307 MPCMediaStream[000000001FDC4D30]::~MPCMediaStream
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 01B00000 MSMLDialogPlay.cxx:383 Release Fetch Request : 000000001C29FD00
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 756 01B00000 MSMLSession.cxx:1094 MSMLSession::CanDelete() - m_bDestroyed=false, m_nReqState=0, m_VXMLDialogMap.size()=0, m_MSMLDialogSet.size()=1, m_setConfsClearHandler.size()=0
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 620 02800000 LMCallSIP.C:2841 Sending INFO: <?xml version="1.0" encoding="UTF-8"?>
<msml version="1.1">
<event name="app.digits" id="conn:A2E6C519-19AD-4795-1E96-A0A2915A84E8/dialog:CollectDigits2417">
<name>dtmf.digits</name>
<value>8</value>
<name>dtmf.end</name>
<value>undefined</value>
</event>
</msml>
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 620 02800000 LMCallSIP.C:2843 ApplicationEvent - m_nState=11
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 620 02800000 LMCallSIPStack.C:167 LMCallSIP::SendRequest for X-Genesys-GVP-Session-ID
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 620 02800000 LMCallSIPStack.C:190 LMCallSIP::SendRequest - X-Genesys-GVP-Session-ID: 46CDC57D-4742-420E-CD93-4894118F5566;gvp.rm.datanodes=1;gvp.rm.tenant-id=101_IVRAppDefault
2016-02-24 18:06:01.057 DBUG 00000000-00000000 620 08500000 VGSIPTransportMgr.cxx:3464 VGSIPTransportMgr::ResolveDNS for 192.168.10.193:5060
2016-02-24 18:06:01.057 DBUG 00000000-00000000 620 08500000 VGSIPTransportMgr.cxx:3575 VGSIPTransportMgr::ResolveDNS nResult 2
2016-02-24T18:06:01.057 Trc 33009 INFO 00000000-00000000 620 02800FA1 Request sent: INFO sip:112791809@192.168.10.191:5060 SIP/2.0
Via: SIP/2.0/TCP 192.168.10.193:5070;branch=z9hG4bK000000001FA61B90cdc6d9
From: <sip:msml-dn@192.168.10.191:5060>;tag=A2E6C519-19AD-4795-1E96-A0A2915A84E8
To: sip:112791809@jcci.com;tag=56CA7757-2EE0-4A24-88FD-8E8F78084668-181429
Max-Forwards: 70
CSeq: 2 INFO
Call-ID: 86573D1B-7381-44DA-B880-9E9A6780FA2A-181110@192.168.10.191
Content-Length: 263
Content-Type: application/vnd.radisys.msml+xml
Route: <sip:000000000CA7EE80@192.168.10.193:5060;transport=TCP;lr;gvp.rm.datanodes=1;idtag=00000433>
X-Genesys-GVP-Session-ID: 46CDC57D-4742-420E-CD93-4894118F5566;gvp.rm.datanodes=1;gvp.rm.tenant-id=101_IVRAppDefault
P-Location: SM;origlocname="Jeddah";origsiglocname="Jeddah";origmedialocname="Jeddah";termlocname="Jeddah";termsiglocname="Jeddah";termmedialocname="Jeddah";smaccounting="true"
User-Agent: Avaya CM/R016x.03.0.124.0 AVAYA-SM-6.3.16.0.631601
P-Charging-Vector: icid-value="AAS:777-23f676801e5da58d05620bf670d"
Av-Global-Session-ID: 8076f623-58da-4501-be20-56d00d670000
Min-SE: 90
Supported: timer, uui

<?xml version="1.0" encoding="UTF-8"?>
<msml version="1.1">
<event name="app.digits" id="conn:A2E6C519-19AD-4795-1E96-A0A2915A84E8/dialog:CollectDigits2417">
<name>dtmf.digits</name>
<value>8</value>
<name>dtmf.end</name>
<value>undefined</value>
</event>
</msml>
2016-02-24 18:06:01.057 DBUG 00000000-00000000 1400 01C00000 CMMsgBase.h:183 cmapi.msg: CM_MSG_CALLLEG_APP_EVENT - StrEventInfo == <?xml version="1.0" encoding="UTF-8"?>
<msml version="1.1">
<event name="msml.dialog
2016-02-24 18:06:01.057 DBUG 00000000-00000000 1400 01C00000 CMMsgBase.h:183 cmapi.msg: CM_MSG_LMNOTIFY_APPLICATIONEVENT - 00000000-100032BF; RequestID=1, Status = 0 - Send data successful.
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 1400 01C00000 CMCallLeg.C:1759 Call leg has received SIP INFO notification: RequestID=1, Status=0 - Send data successful.
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF-0000591B-0078016C-100032BF 4468 01F00000 FMThreadQueue.cxx:1197 Processing ReleaseRequest
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF-0000591B-0078016C-100032BF 4468 01F00000 FMUserRequest.cxx:130 Deleting Request
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 620 02800000 LMCallSIP.C:2841 Sending INFO: <?xml version="1.0" encoding="UTF-8"?>
<msml version="1.1">
<event name="msml.dialog.exit" id="conn:A2E6C519-19AD-4795-1E96-A0A2915A84E8/dialog:prompt2417"/>
</msml>
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 620 02800000 LMCallSIP.C:2843 ApplicationEvent - m_nState=11
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 620 02800000 LMCallSIPStack.C:167 LMCallSIP::SendRequest for X-Genesys-GVP-Session-ID
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 620 02800000 LMCallSIPStack.C:190 LMCallSIP::SendRequest - X-Genesys-GVP-Session-ID: 46CDC57D-4742-420E-CD93-4894118F5566;gvp.rm.datanodes=1;gvp.rm.tenant-id=101_IVRAppDefault
2016-02-24 18:06:01.057 DBUG 00000000-00000000 620 08500000 VGSIPTransportMgr.cxx:3464 VGSIPTransportMgr::ResolveDNS for 192.168.10.193:5060
2016-02-24 18:06:01.057 DBUG 00000000-00000000 620 08500000 VGSIPTransportMgr.cxx:3575 VGSIPTransportMgr::ResolveDNS nResult 2
2016-02-24T18:06:01.057 Trc 33009 INFO 00000000-00000000 620 02800FA1 Request sent: INFO sip:112791809@192.168.10.191:5060 SIP/2.0
Via: SIP/2.0/TCP 192.168.10.193:5070;branch=z9hG4bK000000001FA63C90cdc6d9
From: <sip:msml-dn@192.168.10.191:5060>;tag=A2E6C519-19AD-4795-1E96-A0A2915A84E8
To: sip:112791809@jcci.com;tag=56CA7757-2EE0-4A24-88FD-8E8F78084668-181429
Max-Forwards: 70
CSeq: 3 INFO
Call-ID: 86573D1B-7381-44DA-B880-9E9A6780FA2A-181110@192.168.10.191
Content-Length: 165
Content-Type: application/vnd.radisys.msml+xml
Route: <sip:000000000CA7EE80@192.168.10.193:5060;transport=TCP;lr;gvp.rm.datanodes=1;idtag=00000433>
X-Genesys-GVP-Session-ID: 46CDC57D-4742-420E-CD93-4894118F5566;gvp.rm.datanodes=1;gvp.rm.tenant-id=101_IVRAppDefault
P-Location: SM;origlocname="Jeddah";origsiglocname="Jeddah";origmedialocname="Jeddah";termlocname="Jeddah";termsiglocname="Jeddah";termmedialocname="Jeddah";smaccounting="true"
User-Agent: Avaya CM/R016x.03.0.124.0 AVAYA-SM-6.3.16.0.631601
P-Charging-Vector: icid-value="AAS:777-23f676801e5da58d05620bf670d"
Av-Global-Session-ID: 8076f623-58da-4501-be20-56d00d670000
Min-SE: 90
Supported: timer, uui

<?xml version="1.0" encoding="UTF-8"?>
<msml version="1.1">
<event name="msml.dialog.exit" id="conn:A2E6C519-19AD-4795-1E96-A0A2915A84E8/dialog:prompt2417"/>
</msml>
2016-02-24 18:06:01.057 DBUG 00000000-00000000 1400 01C00000 CMMsgBase.h:183 cmapi.msg: CM_MSG_LMNOTIFY_APPLICATIONEVENT - 00000000-100032BF; RequestID=2, Status = 0 - Send data successful.
2016-02-24 18:06:01.057 DBUG 0078016C-100032BF 1400 01C00000 CMCallLeg.C:1759 Call leg has received SIP INFO notification: RequestID=2, Status=0 - Send data successful.
2016-02-24 18:06:01.077 DBUG 0078016C-100032BF 3680 0B200000 MPCDTMFDispatcher.cxx:99 MPCDTMFDispatcher::MediaTransmit - LastDTMFRxTimeIndex=2705160745, LastProcessedDTMF=true, LastDTMF=8, LastRxTime=2705160745, PacketTimeIndex=2705160745
2016-02-24T18:06:01.081 Trc 33009 INFO 00000000-00000000 972 02800FA1 Response received: SIP/2.0 200 OK
Via: SIP/2.0/TCP 192.168.10.193:5070;branch=z9hG4bK000000001FA63C90cdc6d9
From: <sip:msml-dn@192.168.10.191:5060>;tag=A2E6C519-19AD-4795-1E96-A0A2915A84E8
To: sip:112791809@jcci.com;tag=56CA7757-2EE0-4A24-88FD-8E8F78084668-181429
CSeq: 3 INFO
Call-ID: 86573D1B-7381-44DA-B880-9E9A6780FA2A-181110@192.168.10.191
Contact: <sip:112791809@192.168.10.191:5060>
Content-Length: 0
X-Genesys-CallUUID: H2CG4795V95G13Q15UGTFJGE9K00008M
Allow: INVITE, ACK, PRACK, CANCEL, BYE, REFER, INFO, UPDATE, MESSAGE, NOTIFY, OPTIONS
P-Asserted-Identity: <sip:112791809@jcci.com>
Supported: uui

2016-02-24 18:06:01.081 DBUG 0078016C-100032BF 620 02800000 LMCallSIPHandler.C:153 LMCallSIP::HandleDerivedEvent - nEventType=1, m_nState=11, m_nIntfState=6
2016-02-24 18:06:01.096 DBUG 0078016C-100032BF 3680 0B200000 MPCDTMFDispatcher.cxx:99 MPCDTMFDispatcher::MediaTransmit - LastDTMFRxTimeIndex=2705160745, LastProcessedDTMF=true, LastDTMF=8, LastRxTime=2705160745, PacketTimeIndex=2705160745
2016-02-24T18:06:01.104 Trc 33009 INFO 00000000-00000000 972 02800FA1 Response received: SIP/2.0 [color=red]500 Server Internal Error[/color]
Via: SIP/2.0/TCP 192.168.10.193:5070;branch=z9hG4bK000000001FA61B90cdc6d9
From: <sip:msml-dn@192.168.10.191:5060>;tag=A2E6C519-19AD-4795-1E96-A0A2915A84E8
To: sip:112791809@jcci.com;tag=56CA7757-2EE0-4A24-88FD-8E8F78084668-181429
CSeq: 2 INFO
Call-ID: 86573D1B-7381-44DA-B880-9E9A6780FA2A-181110@192.168.10.191
Content-Length: 0

2016-02-24 18:06:01.104 DBUG 0078016C-100032BF 620 02800000 LMCallSIPHandler.C:153 LMCallSIP::HandleDerivedEvent - nEventType=1, m_nState=11, m_nIntfState=6
2016-02-24 18:06:01.116 DBUG 0078016C-100032BF 3680 0B200000 MPCDTMFDispatcher.cxx:99 MPCDTMFDispatcher::MediaTransmit - LastDTMFRxTimeIndex=2705160745, LastProcessedDTMF=true, LastDTMF=8, LastRxTime=2705160745, PacketTimeIndex=2705160745
2016-02-24 18:06:01.128 DBUG 00000000-00000000 4544 0B100000 MPCDialog.cxx:108 MPCDialog::~MPCDialog LogID=0078016C-100032BF DialogID=20152997
2016-02-24 18:06:01.136 DBUG 0078016C-100032BF 3680 0B200000 MPCDTMFDispatcher.cxx:99 MPCDTMFDispatcher::MediaTransmit - LastDTMFRxTimeIndex=2705160745, LastProcessedDTMF=true, LastDTMF=8, LastRxTime=2705160745, PacketTimeIndex=2705160745
2016-02-24 18:06:01.136 DBUG 0078016C-100032BF 3680 0B200000 MPCDTMFDispatcher.cxx:99 MPCDTMFDispatcher::MediaTransmit - LastDTMFRxTimeIndex=2705160745, LastProcessedDTMF=true, LastDTMF=8, LastRxTime=2705160745, PacketTimeIndex=2705160745
2016-02-24 18:06:01.136 DBUG 0078016C-100032BF 3680 0B200000 MPCDTMFDispatcher.cxx:99 MPCDTMFDispatcher::MediaTransmit - LastDTMFRxTimeIndex=2705160745, LastProcessedDTMF=true, LastDTMF=8, LastRxTime=2705160745, PacketTimeIndex=2705160745
2016-02-24T18:06:02.014 Trc 33009 INFO 00000000-00000000 972 02800FA1 Request received: OPTIONS sip:192.168.10.193:5070 SIP/2.0
Via: SIP/2.0/UDP 192.168.10.193:5064;branch=z9hG4bK000000001B613210cdc6da
From: <sip:GVP@192.168.10.193:5064>;tag=D7224047-5D25-468F-43B8-5AF837FB5E7B
To: sip:192.168.10.193:5070
Max-Forwards: 70
CSeq: 2704391 OPTIONS
Call-ID: 96311EAD-2B13-4906-7B92-32F1F0EF7364-5064@192.168.10.193
Contact: <sip:GVP@192.168.10.193:5064>
Content-Length: 0
Supported: timer, uui

2016-02-24 18:06:02.014 DBUG 972 08500000 MPCSDPNegotiation.cxx:560 SDPNegotiation::NegotiateSDP - nSDPOfferAns=[0], bRemotePref=[true]
2016-02-24 18:06:02.014 DBUG 972 08500000 MPCSDPNegotiation.cxx:593 Generating brand new SDP offer
2016-02-24 18:06:02.014 DBUG 00000000-00000000 972 08500000 VGRTPTypes.cxx:1710 RTPMediaDescListToVGSdp
2016-02-24 18:06:02.014 DBUG 00000000-00000000 972 08500000 VGSIPTransportMgr.cxx:3464 VGSIPTransportMgr::ResolveDNS for 192.168.10.193:5064
2016-02-24 18:06:02.014 DBUG 00000000-00000000 972 08500000 VGSIPTransportMgr.cxx:3575 VGSIPTransportMgr::ResolveDNS nResult 2
2016-02-24T18:06:02.014 Trc 33009 INFO 00000000-00000000 972 02800FA1 Response sent: SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.168.10.193:5064;branch=z9hG4bK000000001B613210cdc6da
From: <sip:GVP@192.168.10.193:5064>;tag=D7224047-5D25-468F-43B8-5AF837FB5E7B
To: sip:192.168.10.193:5070
CSeq: 2704391 OPTIONS
Call-ID: 96311EAD-2B13-4906-7B92-32F1F0EF7364-5064@192.168.10.193
Content-Length: 1522
Content-Type: application/sdp

v=0
o=- 269822361 1 IN IP4 192.168.10.193
s=phone-call
c=IN IP4 192.168.10.193
t=0 0
m=audio 0 RTP/AVP 8 0 9 2 18 3 105 106 112 113 101
a=rtpmap:8 pcma/8000
a=rtpmap:0 pcmu/8000
a=rtpmap:9 g722/8000
a=rtpmap:2 g726-32/8000
a=rtpmap:18 g729/8000
a=rtpmap:3 gsm/8000
a=rtpmap:105 AMR/8000
a=fmtp:105 octet-align=0
a=rtpmap:106 AMR/8000
a=fmtp:106 octet-align=1
a=rtpmap:112 AMR-WB/16000
a=fmtp:112 octet-align=0
a=rtpmap:113 AMR-WB/16000
a=fmtp:113 octet-align=1
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=sendrecv
m=video 0 RTP/AVP 34 99 100 113 114 115 116 117 118 120
a=rtpmap:34 h263/90000
a=fmtp:34 profile=0;level=70
a=rtpmap:99 h263-1998/90000
a=fmtp:99 profile=0;level=70
a=rtpmap:100 h263-1998/90000
a=fmtp:100 profile=0;level=70;F=1;I=1;J=1;T=1;P=1
a=rtpmap:113 h264/90000
a=fmtp:113 profile-level-id=42001F; packetization-mode=0; use-level-src-parameter-sets=0
a=rtpmap:114 h264/90000
a=fmtp:114 profile-level-id=42001F; packetization-mode=1; use-level-src-parameter-sets=0
a=rtpmap:115 h264/90000
a=fmtp:115 profile-level-id=42401F; packetization-mode=0; use-level-src-parameter-sets=0
a=rtpmap:116 h264/90000
a=fmtp:116 profile-level-id=42401F; packetization-mode=1; use-level-src-parameter-sets=0
a=rtpmap:117 h264/90000
a=fmtp:117 profile-level-id=4D001F; packetization-mode=0; use-level-src-parameter-sets=0
a=rtpmap:118 h264/90000
a=fmtp:118 profile-level-id=4D001F; packetization-mode=1; use-level-src-parameter-sets=0
a=rtpmap:120 vp8/90000
a=sendrecv

2016-02-24 18:06:02.296 DBUG 0078016C-100032BF 3680 0B200000 MPCDTMFDispatcher.cxx:99 MPCDTMFDispatcher::MediaTransmit - LastDTMFRxTimeIndex=2705160745, LastProcessedDTMF=true, LastDTMF=8, LastRxTime=2705160745, PacketTimeIndex=2705161985
2016-02-24 18:06:02.296 DBUG 00000000-00000000 756 01B00000 AppEventBase.h:61 app.MSML AMEVENT_MSML_MSMLSESSIONEVENT -
2016-02-24 18:06:02.296 DBUG 0078016C-100032BF 756 01B00000 MSMLAppInstance.cxx:686 Received MSML CallLeg event AMEVENT_MSML_MSMLSESSIONEVENT
2016-02-24 18:06:02.296 DBUG 0078016C-100032BF 756 01B00000 AppCallLeg.h:174 Call Leg Application Event
2016-02-24 18:06:02.296 DBUG 00000000-00000000 1400 01C00000 CMMsgBase.h:183 cmapi.msg: CM_MSG_CALLLEG_APP_EVENT - StrEventInfo == <?xml version="1.0" encoding="UTF-8"?>
<msml version="1.1">
<event name="app.digits"
2016-02-24 18:06:02.296 DBUG 0078016C-100032BF 620 02800000 LMCallSIP.C:2841 Sending INFO: <?xml version="1.0" encoding="UTF-8"?>
<msml version="1.1">
<event name="app.digits" id="conn:A2E6C519-19AD-4795-1E96-A0A2915A84E8/dialog:CollectDigits2417">
<name>dtmf.digits</name>
<value>8</value>
<name>dtmf.end</name>
<value>undefined</value>
</event>
</msml>
2016-02-24 18:06:02.296 DBUG 0078016C-100032BF 620 02800000 LMCallSIP.C:2843 ApplicationEvent - m_nState=11
2016-02-24 18:06:02.296 DBUG 0078016C-100032BF 620 02800000 LMCallSIPStack.C:167 LMCallSIP::SendRequest for X-Genesys-GVP-Session-ID
2016-02-24 18:06:02.296 DBUG 0078016C-100032BF 620 02800000 LMCallSIPStack.C:190 LMCallSIP::SendRequest - X-Genesys-GVP-Session-ID: 46CDC57D-4742-420E-CD93-4894118F5566;gvp.rm.datanodes=1;gvp.rm.tenant-id=101_IVRAppDefault
2016-02-24 18:06:02.296 DBUG 00000000-00000000 620 08500000 VGSIPTransportMgr.cxx:3464 VGSIPTransportMgr::ResolveDNS for 192.168.10.193:5060
2016-02-24 18:06:02.296 DBUG 00000000-00000000 620 08500000 VGSIPTransportMgr.cxx:3575 VGSIPTransportMgr::ResolveDNS nResult 2
2016-02-24T18:06:02.296 Trc 33009 INFO 00000000-00000000 620 02800FA1 Request sent: INFO sip:112791809@192.168.10.191:5060 SIP/2.0
Via: SIP/2.0/TCP 192.168.10.193:5070;branch=z9hG4bK000000001F957070cdc6da
From: <sip:msml-dn@192.168.10.191:5060>;tag=A2E6C519-19AD-4795-1E96-A0A2915A84E8
To: sip:112791809@jcci.com;tag=56CA7757-2EE0-4A24-88FD-8E8F78084668-181429
Max-Forwards: 70
CSeq: 4 INFO
Call-ID: 86573D1B-7381-44DA-B880-9E9A6780FA2A-181110@192.168.10.191
Content-Length: 263
Content-Type: application/vnd.radisys.msml+xml
Route: <sip:000000000CA7EE80@192.168.10.193:5060;transport=TCP;lr;gvp.rm.datanodes=1;idtag=00000433>
X-Genesys-GVP-Session-ID: 46CDC57D-4742-420E-CD93-4894118F5566;gvp.rm.datanodes=1;gvp.rm.tenant-id=101_IVRAppDefault
P-Location: SM;origlocname="Jeddah";origsiglocname="Jeddah";origmedialocname="Jeddah";termlocname="Jeddah";termsiglocname="Jeddah";termmedialocname="Jeddah";smaccounting="true"
User-Agent: Avaya CM/R016x.03.0.124.0 AVAYA-SM-6.3.16.0.631601
P-Charging-Vector: icid-value="AAS:777-23f676801e5da58d05620bf670d"
Av-Global-Session-ID: 8076f623-58da-4501-be20-56d00d670000
Min-SE: 90
Supported: timer, uui

<?xml version="1.0" encoding="UTF-8"?>
<msml version="1.1">
<event name="app.digits" id="conn:A2E6C519-19AD-4795-1E96-A0A2915A84E8/dialog:CollectDigits2417">
<name>dtmf.digits</name>
<value>8</value>
<name>dtmf.end</name>
<value>undefined</value>
</event>
</msml>
2016-02-24 18:06:02.296 DBUG 00000000-00000000 1400 01C00000 CMMsgBase.h:183 cmapi.msg: CM_MSG_LMNOTIFY_APPLICATIONEVENT - 00000000-100032BF; RequestID=3, Status = 0 - Send data successful.
2016-02-24 18:06:02.296 DBUG 0078016C-100032BF 1400 01C00000 CMCallLeg.C:1759 Call leg has received SIP INFO notification: RequestID=3, Status=0 - Send data successful.
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 3680 0B200000 MPCDTMFDispatcher.cxx:99 MPCDTMFDispatcher::MediaTransmit - LastDTMFRxTimeIndex=2705161985, LastProcessedDTMF=true, LastDTMF=8, LastRxTime=2705161985, PacketTimeIndex=2705161985
2016-02-24T18:06:02.315 Trc 33009 INFO 00000000-00000000 972 02800FA1 Request received: INFO sip:Genesys@192.168.10.193:5070 SIP/2.0
Via: SIP/2.0/UDP 192.168.10.193:5060;branch=z9hG4bK000000001AF6CDE0cdc6daabcdef09
Via: SIP/2.0/UDP 192.168.10.191:5060;branch=z9hG4bKCB2155AF-241A-48EC-9027-69BF35B19F4E-8248
From: sip:112791809@jcci.com;tag=56CA7757-2EE0-4A24-88FD-8E8F78084668-181429
To: <sip:msml-dn@192.168.10.191:5060>;tag=A2E6C519-19AD-4795-1E96-A0A2915A84E8
Max-Forwards: 58
CSeq: 5 INFO
Call-ID: 86573D1B-7381-44DA-B880-9E9A6780FA2A-181110@192.168.10.191
Contact: <sip:112791809@192.168.10.191:5060>
Content-Length: 157
Content-Type: application/vnd.radisys.msml+xml

<?xml version="1.0" encoding="UTF-8"?>
<msml version="1.1">
<dialogend id="conn:A2E6C519-19AD-4795-1E96-A0A2915A84E8/dialog:CollectDigits2417"/>
</msml>

2016-02-24T18:06:02.315 Trc 33009 INFO 00000000-00000000 972 02800FA1 Response received: SIP/2.0 200 OK
Via: SIP/2.0/TCP 192.168.10.193:5070;branch=z9hG4bK000000001F957070cdc6da
From: <sip:msml-dn@192.168.10.191:5060>;tag=A2E6C519-19AD-4795-1E96-A0A2915A84E8
To: sip:112791809@jcci.com;tag=56CA7757-2EE0-4A24-88FD-8E8F78084668-181429
CSeq: 4 INFO
Call-ID: 86573D1B-7381-44DA-B880-9E9A6780FA2A-181110@192.168.10.191
Contact: <sip:112791809@192.168.10.191:5060>
Content-Length: 0
X-Genesys-CallUUID: H2CG4795V95G13Q15UGTFJGE9K00008M
Allow: INVITE, ACK, PRACK, CANCEL, BYE, REFER, INFO, UPDATE, MESSAGE, NOTIFY, OPTIONS
P-Asserted-Identity: <sip:112791809@jcci.com>
Supported: uui

2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 620 02800000 LMCallSIPHandler.C:153 LMCallSIP::HandleDerivedEvent - nEventType=0, m_nState=11, m_nIntfState=6
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 620 02800000 LMCallSIPHandler.C:2432 Received SIP INFO
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 620 02800000 LMCallSIPUtil.C:742 PushBackUnknownHeaders: Prefix=[Sip.Info.]
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 620 02800000 LMCallSIPHandler.C:153 LMCallSIP::HandleDerivedEvent - nEventType=1, m_nState=11, m_nIntfState=6
2016-02-24 18:06:02.315 DBUG 00000000-00000000 1400 01C00000 CMMsgBase.h:183 cmapi.msg: CM_MSG_LMNOTIFY_NETWORKEVENT - 00000000-100032BF; EventType=0; ContentType=application/vnd.radisys.msml+xmlExtra Info=<?xml version="1.0" encoding="UTF-8"?>
<msml version="1.1">
<dialogend id="conn:A2E6C519-19AD-4795-1E96-A0A2915A84E8/dialog:CollectDigits2417"/>
</msml>

2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 1400 01C00000 CMCallLeg.C:1735 Call leg has received SIP INFO: application/vnd.radisys.msml+xml <?xml version="1.0" encoding="UTF-8"?>
<msml version="1.1">
<dialogend id="conn:A2E6C519-19AD-4795-1E96-A0A2915A84E8/dialog:CollectDigits2417"/>
</msml>

2016-02-24 18:06:02.315 DBUG 00000000-00000000 756 01B00000 AppCallLegEvent.h:64 app.MSML AMEVENT_CALLLEG_NETWORKEVENT - CallLegID=0078016C-100032BF,ContentType=application/vnd.radisys.msml+xml,INFO=<?xml version="1.0" encoding="UTF-8"?>
<msml version="1.1">
<dialogend id="conn:A2E6C519-19AD-4795-1E96-A0A2915A84E8/dialog:CollectDigits2417"/>
</
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 MSMLAppInstance.cxx:502 Received MSML CallLeg event AMEVENT_CALLLEG_NETWORKEVENT
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 MSMLAppInstance.cxx:580 NetworkEvent
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 MSMLSession.cxx:800 MSMLSession::ProcessSIPMsg with type = 0
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 08500000 SessionConfiguration.C:112 SessConfig::GetValue - Param=[msml.dialogend.silentfail]; Value=[false]; [Global]
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 MSMLSession.cxx:487 MSMLSession::ProcessRequests: enter
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 MSMLDialog.cxx:1817 MSMLDialog::Terminate, current state 9
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 MSMLDialog.cxx:1817 MSMLDialog::Terminate, current state 10
2016-02-24 18:06:02.315 DBUG 00000000-00000000 756 0B100000 MPCConnection.cxx:2074 MPCConnection::DisconnectRoute nLogID=0078016C-100032BF nConnID=10152990 ControlSinkID=20152996
2016-02-24 18:06:02.315 DBUG 00000000-00000000 756 0B100000 MPCDialog.cxx:1159 MPCDialog::GetSinks, LogID=0078016C-100032BF DialogID=20152996 ControlSourceID=10152990
2016-02-24 18:06:02.315 DBUG 00000000-00000000 756 0B100000 MPCControlObject.cxx:368 MPCControlObject::UnregisterSinkHelper LogID=0078016C-100032BF ObjectID=10152990 SourceID=00010000 SinkID=00010004 pRoute=1C2D8980
2016-02-24 18:06:02.315 DBUG 00000000-00000000 756 0B100000 MPCDialog.cxx:1116 MPCDialog::UnregisterReverseRoute, LogID=0078016C-100032BF DialogID=20152996 ControlSourceID=10152990
2016-02-24 18:06:02.315 DBUG 00000000-00000000 756 0B100000 MPCDialog.cxx:780 MPCDialog::Destroy, LogID=0078016C-100032BF DialogID=20152996
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 0B200000 MPCPlayer.cxx:532 MPCPlayer::Stop: m_State=0 nStopReason=10
2016-02-24 18:06:02.315 DBUG 00000000-00000000 756 0B100000 MPCControlObject.cxx:368 MPCControlObject::UnregisterSinkHelper LogID=0078016C-100032BF ObjectID=20152996 SourceID=00010002 SinkID=00010003 pRoute=00000000
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 0B200000 MPCPlayer.cxx:532 MPCPlayer::Stop: m_State=0 nStopReason=10
2016-02-24 18:06:02.315 DBUG 00000000-00000000 756 0B100000 MPCDialog.cxx:1298 MPCDialog::QueueDestroyedEvent, LogID=0078016C-100032BF DialogID=20152996
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 MSMLDialog.cxx:1191 MSMLDialog is in TERMINATED state with: m_nFromDialogRouteState=0, m_nToDialogRouteState=3, m_nVXMLDialogRouteState=0, m_bDialogCreated=true
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 MSMLSession.cxx:508 MSMLSession::ProcessRequests: element response 0
2016-02-24 18:06:02.315 DBUG 00000000-00000000 756 01B00000 AppEventBase.h:61 app.MSML AMEVENT_MSML_MSMLSESSIONEVENT -
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 MSMLAppInstance.cxx:686 Received MSML CallLeg event AMEVENT_MSML_MSMLSESSIONEVENT
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 MSMLDialog.cxx:1191 MSMLDialog is in TERMINATED state with: m_nFromDialogRouteState=0, m_nToDialogRouteState=0, m_nVXMLDialogRouteState=0, m_bDialogCreated=true
2016-02-24 18:06:02.315 DBUG 00000000-00000000 756 01B00000 AppEventBase.h:61 app.MSML AMEVENT_MSML_MSMLSESSIONEVENT -
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 MSMLAppInstance.cxx:686 Received MSML CallLeg event AMEVENT_MSML_MSMLSESSIONEVENT
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 MSMLDialog.cxx:1191 MSMLDialog is in TERMINATED state with: m_nFromDialogRouteState=0, m_nToDialogRouteState=0, m_nVXMLDialogRouteState=0, m_bDialogCreated=false
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 MSMLSession.cxx:286 MSMLSession::DialogDestroyed attempt to remove dialog conn:A2E6C519-19AD-4795-1E96-A0A2915A84E8/dialog:CollectDigits2417
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 MSMLDialog.cxx:331 MSMLDialog::~MSMLDialog
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 MSMLSession.cxx:1094 MSMLSession::CanDelete() - m_bDestroyed=false, m_nReqState=2, m_VXMLDialogMap.size()=0, m_MSMLDialogSet.size()=0, m_setConfsClearHandler.size()=0
2016-02-24 18:06:02.315 DBUG 00000000-00000000 756 01B00000 AppEventBase.h:61 app.MSML AMEVENT_MSML_MSMLSESSIONEVENT -
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 MSMLAppInstance.cxx:686 Received MSML CallLeg event AMEVENT_MSML_MSMLSESSIONEVENT
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 MSMLSession.cxx:487 MSMLSession::ProcessRequests: enter
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 MSMLSession.cxx:508 MSMLSession::ProcessRequests: element response 1
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 MSMLSession.cxx:566 Send 200 response
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 AppCallLeg.h:195 Call Leg send network event response
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 756 01B00000 MSMLSession.cxx:1094 MSMLSession::CanDelete() - m_bDestroyed=false, m_nReqState=0, m_VXMLDialogMap.size()=0, m_MSMLDialogSet.size()=0, m_setConfsClearHandler.size()=0
2016-02-24 18:06:02.315 DBUG 00000000-00000000 1400 01C00000 CMMsgBase.h:183 cmapi.msg: CM_MSG_CALLLEG_NETWORKEVENTRESPONSE - CallObjID == 0078016C-100032BF; Binding State == 1
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 620 02800000 LMCallSIP.C:2960 NetworkEventResponse nResponse=200
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 620 02800000 LMCallSIPStack.C:203 LMCallSIP::SendResponse for ID Headers
2016-02-24 18:06:02.315 DBUG 0078016C-100032BF 620 02800000 LMCallSIPStack.C:225 LMCallSIP::SendResponse - X-Genesys-GVP-Session-ID: 46CDC57D-4742-420E-CD93-4894118F5566;gvp.rm.datanodes=1;gvp.rm.tenant-id=101_IVRAppDefault
2016-02-24 18:06:02.315 DBUG 00000000-00000000 620 08500000 VGSIPTransportMgr.cxx:3464 VGSIPTransportMgr::ResolveDNS for 192.168.10.193:5060[/i]

victor · « **Reply #1 on:** February 25, 2016, 04:37:33 AM »

What are the versions?

shakeel8787 · « **Reply #2 on:** February 25, 2016, 07:17:15 AM »

[b][u]Versions[/u][/b]
SIP Server:8.1.101.91
MCP:8.1.700.44
RM:8.1.700.61
URS:8.1.400.23
ORS:8.1.400.30

Fra · « **Reply #3 on:** February 25, 2016, 02:59:15 PM »

It seems quite an 'interesting' and critical issue: hav you spotted the following message, just before the 500 Error is sent out?

***
Remote CSeq mismatch: 2 < 3. Rejecting request
***

It seems that the MCP is responding to the request with a CSeq lower than one expected by SIPS: argh!

Fra

hsujdik · « **Reply #4 on:** February 25, 2016, 06:06:53 PM »

Another interesting (yet concerning) point is that the previous tcp connection for that call looks like it got broken somehow. Just prior receiving the INFO message with CSeq 2, a new tcp socket (484) has been open

18:06:01.154: CGSIPListener[0]: Accepted new connection on socket 484
18:06:01.170: $+NET:SIP::0:0
18:06:01.170: SIPS:LOGBLOCK:BEGIN:SIPMSG:[
18:06:01.170: SIPTR: Received [484,TCP] 1323 bytes from 192.168.10.193:56668 <<<<<

Maybe logs a earlier than that point you sent could tell a little bit more on what happened

shakeel8787 · « **Reply #5 on:** February 29, 2016, 07:50:53 AM »

Thank You all.

The issue is fixed now after setting the parameter[i] 'sip-treatment-dtmf-interruptable' [/i]to [i]'true'[/i] and restarting the SIP Server.

Regards
Shakeel

SA.MALIK · « **Reply #6 on:** July 05, 2018, 12:06:01 PM »

has below CSeq mismatch gone after adding the parameter 'sip-treatment-dtmf-interruptable' to 'true'

gsip:DLG[24004354]: Remote CSeq mismatch: 5 < 6. Rejecting request
10:31:41.492: Sending [0,UDP] 511 bytes to 10.123.114.132:5060 >>>>>
SIP/2.0 500 Server Internal Error

Thanks

victor · « **Reply #7 on:** July 06, 2018, 02:42:06 AM »

We just had the same issue! Did something change from the previous version? I don’t recall ever having any issue like this before.

Sent from my iPhone using Tapatalk

Genesys CTI User Forum

News:

Author Topic: First DTMF Not Detected (Read 5508 times)

shakeel8787

First DTMF Not Detected

victor

Re: First DTMF Not Detected

shakeel8787

Re: First DTMF Not Detected

Fra

Re: First DTMF Not Detected

hsujdik

Re: First DTMF Not Detected

shakeel8787

Re: First DTMF Not Detected

SA.MALIK

Re: First DTMF Not Detected

victor

Re: First DTMF Not Detected