OriginateCallback receives inconsistent callbacks

[elijahsmith]

I have been testing a simple integration between our web app and an asterisk box. We originate calls using originateToExtensionAsync, using a local channel and a dialplan, and then record the outcome using a combination of OriginateCallback and AbstractManagerEventListener instances.

In particular, we are interested in recording:

• the outcome of the calls (Answered, Not Answered, Busy)
• the duration of the answered calls

To record the duration, we are watching for the HangupEvent (from the AbstractManagerEventListener), and then calculating the time between that and the onSuccess callback (from the OriginateCallback).

The issue is that sometimes, instead of calling onSuccess, the onNoAnswer callback is instead called. In these cases, the HangupEvent eventually shows up as well, but because no onSuccess ever fired, we are unable to record a duration. Further, our call records are inaccurate, as the call was answered!

After puzzling over this and looking carefully at the logs, I went searching in the closed issues here and see what seems to be a collection of issues that all describe the exact same problem:

#255
#207 (note that a commenter here suggests a fix which looks like it was later committed to the mainline: agamezg@7ef4d04)
#145

I will admit that I am not an asterisk expert, but what seems to be happening is that the NewStateEvent that updates the channel state is sometimes arriving after the OriginateResponseEvent which relies on that NewStateEvent to determine whether the channel is up or not.

Moreover, from reading through the past bug reports, this may be particular to local channels? In this case, we are running some prerequisites in the dialplan, so we don't want to dial the call until the dialplan is ready -- I believe we need the local channels in this case?

I'm hoping to reopen the discussion and determine the best way to make OriginateCallback behave correctly. One MR suggests adding a sleep at the top of handleOriginateEvent, for instance, presumably to allow the NewStateEvents to arrive. Others suggest adding additional clauses inside handleOriginateEvent to cover the states of the multiple channels involved. This is all a bit above my level of understanding, so I'm hoping to get some input.

I'm attaching a bit of the logs around this event; you can see the OriginateResponseEvent arriving about halfway through and causing our app to log IVRNoAnswer. There are several NewStateEvents which arrive before and after, but the ones for the channel named in the OriginateResponseEvent, Local/960@zambiaivr-0000013d;1', arrive after, while events for Local/960@zambiaivr-0000013d;2' arrive before...

asterisk-java.log

[videanuadrian]

Hi all,
I have the exact same issue.
Using originatetoExtensionAsync sometimes it calls onNoAnswer() instead of onSuccess().
Digging into the code it seems that the dialing event is received after the onNoAnswer is called.
Due to this, the channel is still down and the callback is triggered wrongfully.

this is how originateToExtensionAsyncis called:
pbx.originateToExtensionAsync("PJSIP/072377777@gnsnet", "agents", "myExten", 1, 30000, callerId, variables, originateCallback);

this is how a bad callback looks
`managerEventListener: DialEvent [subEvent=Begin, channel=null, destination=PJSIP/gnsnet-00000130, callerIdNum=null, callerIdName=null, uniqueId=null, destUniqueId=AwsEuc1bPbxOn1-1717482159.2100, dialString=null, dialStatus=null, connectedLineNum=null, connectedLineName=null]

managerEventListener: DialEvent [subEvent=Begin, channel=null, destination=PJSIP/gnsnet-00000130, callerIdNum=null, callerIdName=null, uniqueId=null, destUniqueId=AwsEuc1bPbxOn1-1717482159.2100, dialString=0723864007@gnsnet, dialStatus=null, connectedLineNum=null, connectedLineName=null]

OriginateCallbackListener: No Answer AsteriskChannel[id='AwsEuc1bPbxOn1-1717482159.2100',name='PJSIP/gnsnet-00000130',callerId='"0723864007" <1234>',state='DOWN',account='',dateOfCreation=Tue Jun 04 09:22:39 EEST 2024,dialedChannel=null,dialingChannel=null,linkedChannel=null]

managerEventListener: DialEvent [subEvent=End, channel=null, destination=PJSIP/gnsnet-00000130, callerIdNum=null, callerIdName=null, uniqueId=null, destUniqueId=AwsEuc1bPbxOn1-1717482159.2100, dialString=null, dialStatus=ANSWER, connectedLineNum=null, connectedLineName=null]
`