[Asterisk-java-users] Problem with originateToExtensionAsync() and Local/ channels

[Ken N. M. <Ken...@um...>]

Hi there,

I'm having a problem with
DefaultAsteriskServer.originateToExtensionAsync() with asterisk-java 0.3
and Asterisk 1.4 (1.4.4 presently) when using Local channels.  On about
50% or so of the calls I originate using this method, the onDialing()
method on my callback is not called. =20

Here's some logging for a call that works, and a call that doesn't
(sorry for the really long lines!).  In this case, both calls are being
sent to Local/7777@longdistance, which is just a simple extension that
answers and plays back some DTMF digits, simulating a user.

2007-07-06 12:44:32,830 DEBUG
[org.asteriskjava.manager.internal.ManagerConnectionImpl] Dispatching
response with internalActionId '25769070_6':
org.asteriskjava.manager.response.ManagerResponse:
actionId=3D'AJ_ORIGINATE_0'; message=3D'Originate successfully queued';
response=3D'Success'; uniqueId=3D'null'; systemHashcode=3D19072308
2007-07-06 12:44:32,831 DEBUG
[org.asteriskjava.manager.internal.ManagerConnectionImpl] Dispatching
event:
org.asteriskjava.manager.event.NewChannelEvent[dateReceived=3DFri Jul 06
12:44:32 MDT
2007,privilege=3D'call,all',calleridnum=3D'<unknown>',calleridname=3D'<un=
known
>',callerid=3D'<unknown>',uniqueid=3D'1183747472.797',state=3D'Down',time=
stamp
=3D'null',channel=3D'Local/7777@longdistance-c4d6,1',systemHashcode=3D279=
6536]
2007-07-06 12:44:32,840 DEBUG
[org.asteriskjava.manager.internal.ManagerConnectionImpl] Dispatching
event:
org.asteriskjava.manager.event.NewChannelEvent[dateReceived=3DFri Jul 06
12:44:32 MDT
2007,privilege=3D'call,all',calleridnum=3D'<unknown>',calleridname=3D'<un=
known
>',callerid=3D'<unknown>',uniqueid=3D'1183747472.798',state=3D'Ring',time=
stamp
=3D'null',channel=3D'Local/7777@longdistance-c4d6,2',systemHashcode=3D208=
30161
]
2007-07-06 12:44:32,841 DEBUG
[org.asteriskjava.manager.internal.ManagerConnectionImpl] Dispatching
event:
org.asteriskjava.manager.event.NewCallerIdEvent[dateReceived=3DFri Jul =
06
12:44:32 MDT
2007,privilege=3D'call,all',calleridnum=3D'<Unknown>',cidcallingpres=3D'0=
',cal
leridname=3D'<Unknown>',callerid=3D'<Unknown>',uniqueid=3D'1183747472.797=
',cid
callingprestxt=3D'Presentation Allowed, Not
Screened',timestamp=3D'null',channel=3D'Local/7777@longdistance-c4d6,1',s=
yst
emHashcode=3D19136225]
2007-07-06 12:44:32,865 INFO
[org.asteriskjava.live.internal.ChannelManager] Adding channel
Local/7777@longdistance-c4d6,1(1183747472.797)
2007-07-06 12:44:32,867 DEBUG
[org.asteriskjava.manager.internal.ManagerConnectionImpl] Dispatching
response with internalActionId '25769070_7':
org.asteriskjava.manager.response.ManagerResponse: actionId=3D'null';
message=3D'null'; response=3D'Success'; uniqueId=3D'null';
systemHashcode=3D5942570
2007-07-06 12:44:32,867 INFO
[ca.ums.mdc.service.AlarmCalloutOriginateCallback]
Local/7777@longdistance-c4d6,1: Beginning dial.

In this case, onDialing() is called (which is what logs the final
"Beginning dial" line above), and then eventually onSuccess() is called
once the line is answered.  However, the next call, things don't work so
well:

2007-07-06 12:44:48,050 DEBUG
[org.asteriskjava.manager.internal.ManagerConnectionImpl] Dispatching
response with internalActionId '25769070_9':
org.asteriskjava.manager.response.ManagerResponse:
actionId=3D'AJ_ORIGINATE_1'; message=3D'Originate successfully queued';
response=3D'Success'; uniqueId=3D'null'; systemHashcode=3D30123815
2007-07-06 12:44:48,062 DEBUG
[org.asteriskjava.manager.internal.ManagerConnectionImpl] Dispatching
event:
org.asteriskjava.manager.event.NewChannelEvent[dateReceived=3DFri Jul 06
12:44:48 MDT
2007,privilege=3D'call,all',calleridnum=3D'<unknown>',calleridname=3D'<un=
known
>',callerid=3D'<unknown>',uniqueid=3D'1183747488.799',state=3D'Down',time=
stamp
=3D'null',channel=3D'Local/7777@longdistance-6370,1',systemHashcode=3D216=
89449
]
2007-07-06 12:44:48,063 INFO
[org.asteriskjava.live.internal.ChannelManager] Adding channel
Local/7777@longdistance-6370,1(1183747488.799)
2007-07-06 12:44:48,100 DEBUG
[org.asteriskjava.manager.internal.ManagerConnectionImpl] Dispatching
response with internalActionId '25769070_10':
org.asteriskjava.manager.response.ManagerError: actionId=3D'null';
message=3D'No such channel'; response=3D'Error'; uniqueId=3D'null';
systemHashcode=3D32790978
2007-07-06 12:44:48,190 DEBUG
[org.asteriskjava.manager.internal.ManagerConnectionImpl] Dispatching
event:
org.asteriskjava.manager.event.NewChannelEvent[dateReceived=3DFri Jul 06
12:44:48 MDT
2007,privilege=3D'call,all',calleridnum=3D'<unknown>',calleridname=3D'<un=
known
>',callerid=3D'<unknown>',uniqueid=3D'1183747488.800',state=3D'Ring',time=
stamp
=3D'null',channel=3D'Local/7777@longdistance-6370,2',systemHashcode=3D804=
3179]
2007-07-06 12:44:48,190 DEBUG
[org.asteriskjava.manager.internal.ManagerConnectionImpl] Dispatching
event:
org.asteriskjava.manager.event.NewCallerIdEvent[dateReceived=3DFri Jul =
06
12:44:48 MDT
2007,privilege=3D'call,all',calleridnum=3D'<Unknown>',cidcallingpres=3D'0=
',cal
leridname=3D'<Unknown>',callerid=3D'<Unknown>',uniqueid=3D'1183747488.799=
',cid
callingprestxt=3D'Presentation Allowed, Not
Screened',timestamp=3D'null',channel=3D'Local/7777@longdistance-6370,1',s=
yst
emHashcode=3D24458207]
2007-07-06 12:44:48,191 DEBUG
[org.asteriskjava.manager.internal.ManagerConnectionImpl] Dispatching
event:
org.asteriskjava.manager.event.NewExtenEvent[dateReceived=3DFri Jul 06
12:44:48 MDT
2007,privilege=3D'call,all',extension=3D'7777',appdata=3D'null',uniqueid=3D=
'1183
747488.800',context=3D'longdistance',timestamp=3D'null',channel=3D'Local/=
7777@
longdistance-6370,2',priority=3D'1',application=3D'Answer',systemHashcode=
=3D27
306108]
2007-07-06 12:44:48,192 DEBUG
[org.asteriskjava.manager.internal.ManagerConnectionImpl] Dispatching
event:
org.asteriskjava.manager.event.NewStateEvent[dateReceived=3DFri Jul 06
12:44:48 MDT
2007,privilege=3D'call,all',calleridnum=3D'<unknown>',calleridname=3D'<un=
known
>',callerid=3D'<unknown>',uniqueid=3D'1183747488.799',state=3D'Up',timest=
amp=3D'
null',channel=3D'Local/7777@longdistance-6370,1',systemHashcode=3D9795370=
]
2007-07-06 12:44:48,192 DEBUG
[org.asteriskjava.manager.internal.ManagerConnectionImpl] Dispatching
event:
org.asteriskjava.manager.event.OriginateResponseEvent[dateReceived=3DFri
Jul 06 12:44:48 MDT
2007,privilege=3D'call,all',internalactionid=3D'25769070_9',calleridname=3D=
'<u
nknown>',exten=3D's',actionid=3D'AJ_ORIGINATE_1',response=3D'Success',cal=
lerid
num=3D'<unknown>',reason=3D'4',context=3D'ExecAGIApp',uniqueid=3D'1183747=
488.799
',timestamp=3D'null',channel=3D'Local/7777@longdistance-6370,1',systemHas=
hco
de=3D12741325]
2007-07-06 12:44:48,193 DEBUG
[org.asteriskjava.manager.internal.ManagerConnectionImpl] Dispatching
event:
org.asteriskjava.manager.event.NewStateEvent[dateReceived=3DFri Jul 06
12:44:48 MDT
2007,privilege=3D'call,all',calleridnum=3D'<unknown>',calleridname=3D'<un=
known
>',callerid=3D'<unknown>',uniqueid=3D'1183747488.800',state=3D'Up',timest=
amp=3D'
null',channel=3D'Local/7777@longdistance-6370,2',systemHashcode=3D3262035=
8]
2007-07-06 12:44:48,193 DEBUG
[org.asteriskjava.manager.internal.ManagerConnectionImpl] Dispatching
event:
org.asteriskjava.manager.event.NewExtenEvent[dateReceived=3DFri Jul 06
12:44:48 MDT
2007,privilege=3D'call,all',extension=3D'7777',appdata=3D'3.5',uniqueid=3D=
'11837
47488.800',context=3D'longdistance',timestamp=3D'null',channel=3D'Local/7=
777@l
ongdistance-6370,2',priority=3D'2',application=3D'Wait',systemHashcode=3D=
44987
53]
2007-07-06 12:44:48,194 DEBUG
[org.asteriskjava.manager.internal.ManagerConnectionImpl] Dispatching
event:
org.asteriskjava.manager.event.NewExtenEvent[dateReceived=3DFri Jul 06
12:44:48 MDT
2007,privilege=3D'call,all',extension=3D's',appdata=3D'agi://127.0.0.1:45=
73/ca
llout.agi?acked=3D0',uniqueid=3D'1183747488.799',context=3D'ExecAGIApp',t=
imest
amp=3D'null',channel=3D'Local/7777@longdistance-6370,1',priority=3D'1',ap=
plica
tion=3D'AGI',systemHashcode=3D12411662]
2007-07-06 12:44:48,195 DEBUG
[org.asteriskjava.manager.internal.ManagerConnectionImpl] Dispatching
event:
ca.ums.mdc.voice.asterisk.userevents.AlarmCalloutAnsweredEvent[dateRecei
ved=3DFri Jul 06 12:44:48 MDT
2007,privilege=3D'user,all',answerchannel=3D'Local/7777@longdistance-6370=
,1'
,messageid=3D'1825',uniqueid=3D'null',timestamp=3D'null',userevent=3D'Ala=
rmCallo
utAnswered',channel=3D'null',systemHashcode=3D28460584]
2007-07-06 12:44:48,195 INFO
[ca.ums.mdc.service.AlarmCalloutOriginateCallback] 1825: answered
(Local/7777@longdistance-6370,1)
2007-07-06 12:44:48,200 INFO
[org.asteriskjava.live.internal.ChannelManager] Adding channel
Local/7777@longdistance-6370,2(1183747488.800)
2007-07-06 12:44:48,210 DEBUG
[org.asteriskjava.manager.internal.ManagerConnectionImpl] Dispatching
response with internalActionId '25769070_11':
org.asteriskjava.manager.response.ManagerResponse: actionId=3D'null';
message=3D'null'; response=3D'Success'; uniqueId=3D'null';
systemHashcode=3D18613390
2007-07-06 12:44:48,220 INFO
[ca.ums.mdc.service.AlarmCalloutOriginateCallback]
Local/7777@longdistance-6370,1: Call Answered.
2007-07-06 12:44:48,230 DEBUG
[ca.ums.mdc.service.AlarmCalloutOriginateCallback]
Local/7777@longdistance-6370,1: *** No dial event received prior to
answer ***

In this case, onDialing() is never called, even though onSuccess() does
get called once the call is answered (last 2 log lines).

Any ideas?  About the only thing "odd" about this application is that it
runs within JBoss (4.0.5), but other than that it's pretty straight
forward.

The other thing I've noticed is that the very first call I originate
when the application starts always works, but it's hit or miss whether
or not the next call that is made works.  Not sure if that helps?

--
Ken March, Senior IT Administrator
Universal Measurement Solutions (UMS) Ltd. / Kilowatts Design Company
Inc.