Hello there,
I have a strange problem: some sessions which are dropped by the OD application end up as Far-End Disconnect instead of Near-End Disconnect. I checked the OD and VXML logs and it seems like the connection.disconnect.hangup event arrives twice.
First of all, the environment:
OD 6.0 SP3 (06.00.13.01)
EP 7.0.2
The OD logic is as follows:
Disconnect node obviously disconnects the call, no custom logic. SetReason_N sets Outcome variable as 'N' (for reporting purposes). There is also SetReason_F to set Outcome to 'F' (not on the image). Wrapup servlet signals the ending session to other non-OD components.
Engine_Hangup inside:
Engine_Hangup contains some after-call processing, setting up some variables, etc, and also contains a hookpoint called Engine_Hook (inside Body) for customer-specific logic. throw_dkAbandon throws custom event to signal unexpected disconnect, event is caught in the parent application, and is handled as a Far-End Disconnect.
OD log:
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Using SCESession
4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main servlet : SetReason_N
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Assigning [N] to [CallOutcome]
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Using SCESession 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main servlet : Engine_Hangup
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : ** Pushed Stack Frame [/Engine_Hangup]
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Using SCESession 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main servlet : Start
DEBUG - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Creating variable [vdu_cache] from factory [com.avaya.sce.runtime.connectivity.ic.pdc.VDUCacheVariableFactory]
DEBUG - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Creating variable [vdu] from factory [com.avaya.sce.runtime.connectivity.ic.pdc.VDUVariableFactory]
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Using SCESession 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main servlet : throw_dkAbandon
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Using SCESession 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main servlet : SetReason_F
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : ** Popped Stack Frame [/Engine_Hangup]
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Assigning [F] to [CallOutcome]
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Using SCESession 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main servlet : Engine_Hangup
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : ** Pushed Stack Frame [/Engine_Hangup]
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Using SCESession 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main servlet : Start
DEBUG - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Creating variable [vdu_cache] from factory [com.avaya.sce.runtime.connectivity.ic.pdc.VDUCacheVariableFactory]
DEBUG - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Creating variable [vdu] from factory [com.avaya.sce.runtime.connectivity.ic.pdc.VDUVariableFactory]
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Using SCESession 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main servlet : setOutVars
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Using SCESession 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main servlet : Body
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Using SCESession 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main servlet : Body-Begin
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Using SCESession 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main servlet : Body-Hook_Hangup
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : ** Pushed Stack Frame [/Hook_Hangup]
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Using SCESession 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main servlet : Start
DEBUG - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Creating variable [vdu] from factory [com.avaya.sce.runtime.connectivity.ic.pdc.VDUVariableFactory]
DEBUG - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Creating variable [vdu_cache] from factory [com.avaya.sce.runtime.connectivity.ic.pdc.VDUCacheVariableFactory]
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Using SCESession 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main servlet : Body
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Using SCESession 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main servlet : Body-Begin
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Using SCESession 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main servlet : Body-Return
DEBUG - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Subflow return node "Body-Return" forwarding to "Return"
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Using SCESession 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main servlet : Return
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Using SCESession 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main servlet : Body-Return
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : ** Popped Stack Frame [/Hook_Hangup]
information [Hook_Hangup]
DEBUG - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Subflow return node "Body-Return" forwarding to "Return"
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Using SCESession 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main servlet : Return
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Using SCESession 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main servlet : Wrapup
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : ** Popped Stack Frame [/Engine_Hangup]
information [Engine_Hangup]
DEBUG - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : session id:*****mpp***** | Engine_Main:Wrapup | @@@@@ END SESSION START
DEBUG - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : session id:*****mpp***** | Engine_Main:Wrapup | @@@@@ END SESSION END
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Using SCESession 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main servlet : Return
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Removing session from AvayaSessionTermination Servlet
INFO - 4A3A401B2A088D4E12F548F65A3AF7E8:/Engine_Main : Termination URL reply : <?xml version="1.0" encoding="UTF-8"?>
The black bold part is the beginning, after the Disconnect node (not in the logs). SetReason_N is called, as it should be. The problem appears in the red bold part: after entering to Engine_Hangup, a Disconnect event arrives immediately, and the logic continues on the 'On Disconnect' output of the Approot, throwing a dkAbandon event, which causes the call to be reported as Far-End Disconnect instead of Near-End. The thing is that the OD logic is working as it should, the problem comes from deeper. VXML log:
||FINE|CommonVXI.Cache|32455|Session=******mpp*****|Fetching fresh copy of
http://******/Engine_Main/Disconnect?___DDSESSIONID=0B14F9727475E86E557A98E82C929989%3A%2FEngine_Main from server|******mpp*****####
||FINE|VB|6344|Session=******mpp*****|successfully sent message VXML_PAGE_LOADED|******mpp*****####
||FINE|CommonVXI.Prompt|32455|Session=******mpp*****|osbprompt.cpp:865:(bargin: we can play)|******mpp*****####
||FINE|VB|6344|Session=******mpp*****|successfully sent message VXML_DIALOG_DISCONNECT|******mpp*****####
||FINE|CommonVXI.Prompt|32455|Session=******mpp*****|(bargin, we can play)|******mpp*****####
|PAVB_03335|INFO|VB|32455|Session=******mpp*****|Got VoiceXML exception: connection.disconnect.hangup in http://******/Engine_Main/Disconnect?___DDSESSIONID=0B14F9727475E86E557A98E82C929989%3A%2FEngine_Main|******mpp*****####
||FINE|CommonVXI.Interpreter|32455|Session=******mpp*****|VXI::DoEvent - Enter|******mpp*****####
||FINE|CommonVXI.Cache|32455|Session=******mpp*****|SBinetChannel::GetAbsoluteNameSetReason_N?___DDSESSIONID=0B14F9727475E86E557A98E82C929989%3A%2FEngine_Main|******mpp*****####
||FINE|CommonVXI.Cache|32455|Session=******mpp*****|SBinetHttpStream.cpp:1403:SBinetHttpStream::getHeaderInfo: Waited 4ms for HTTP response|******mpp*****####
||FINE|CommonVXI.Cache|32455|Session=******mpp*****|SBinetHttpStream.cpp:1409:SBinetHttpStream::getHeaderInfo: rc=0, HttpStatus=200|******mpp*****####
||FINE|CommonVXI.Cache|32455|Session=******mpp*****|Fetching fresh copy of
http://******/Engine_Main/SetReason_N?___DDSESSIONID=0B14F9727475E86E557A98E82C929989%3A%2FEngine_Main&avayadonotsave___noinputcount=0&avayadonotsave___nomatchcount=0 from server|******mpp*****####
||FINE|VB|6344|Session=******mpp*****|successfully sent message VXML_PAGE_LOADED|******mpp*****####
||FINE|CommonVXI.Cache|32455|Session=******mpp*****|SBinetChannel::GetAbsoluteName/Engine_Hangup/Start?___DDSESSIONID=0B14F9727475E86E557A98E82C929989%3A%2FEngine_Main&sagecall=Language|******mpp*****####
||FINE|CommonVXI.Cache|32455|Session=******mpp*****|SBinetHttpStream.cpp:1403:SBinetHttpStream::getHeaderInfo: Waited 7ms for HTTP response|******mpp*****####
||FINE|CommonVXI.Cache|32455|Session=******mpp*****|SBinetHttpStream.cpp:1409:SBinetHttpStream::getHeaderInfo: rc=0, HttpStatus=200|******mpp*****####
||FINE|CommonVXI.Cache|32455|Session=******mpp*****|Fetching fresh copy of
http://******/Engine_Hangup/Start?___DDSESSIONID=0B14F9727475E86E557A98E82C929989%3A%2FEngine_Main&sagecall=Language from server|******mpp*****####
||FINE|VB|6344|Session=******mpp*****|successfully sent message VXML_PAGE_LOADED|******mpp*****####
||FINE|CommonVXI.Jsi|32455|Session=******mpp*****|SBjsiFuncs.cpp:148:SBjsiCreateContext: entering |******mpp*****####
||FINE|CommonVXI.Jsi|32455|Session=******mpp*****|SBjsiFuncs.cpp:181:SBjsiCreateContext: exiting: returned rc=0|******mpp*****####
|PAVB_03335|INFO|VB|32455|Session=******mpp*****|Got VoiceXML exception: connection.disconnect.hangup in http://******/Engine_Hangup/Start?___DDSESSIONID=0B14F9727475E86E557A98E82C929989%3A%2FEngine_Main&sagecall=Language|******mpp*****####
||FINE|CommonVXI.Interpreter|32455|Session=******mpp*****|VXI::DoEvent - Enter|******mpp*****####
||FINE|CommonVXI.Cache|32455|Session=******mpp*****|SBinetChannel::GetAbsoluteNamethrow_dkAbandon?___DDSESSIONID=0B14F9727475E86E557A98E82C929989%3A%2FEngine_Main|******mpp*****####
||FINE|CommonVXI.Cache|32455|Session=******mpp*****|SBinetHttpStream.cpp:1403:SBinetHttpStream::getHeaderInfo: Waited 3ms for HTTP response|******mpp*****####
||FINE|CommonVXI.Cache|32455|Session=******mpp*****|SBinetHttpStream.cpp:1409:SBinetHttpStream::getHeaderInfo: rc=0, HttpStatus=200|******mpp*****####
||FINE|CommonVXI.Cache|32455|Session=******mpp*****|Fetching fresh copy of
http://******/Engine_Hangup/throw_dkAbandon?___DDSESSIONID=0B14F9727475E86E557A98E82C929989%3A%2FEngine_Main&avayadonotsave___noinputcount=0&avayadonotsave___nomatchcount=0 from server|******mpp*****####
The red bold parts show the duplicate disconnect event. Any ideas about this?
When I set MPP logging to FINEST level, I saw two messages preceding the connection.disconnect.hangup events: in the Disconnect node, just before the event, there was a VXML_DIALOG_DISCONNECT message, but VPChannel::IsHangup kept returning false even after this. Then, in the Engine_Hangup start node there was a VXML_DIALOG_HANGUP message, and after this VPChannel::IsHangup returned true. Then, the next disconnect event happened.
I'd really appreciate the help, I'm out of ideas. This does not look like an OD issue to me, as the same logic is installed at other customers as well, and it works fine for them. Even for this customer, the same error doesn't happen for every session.
