[Home]

Summary:ASTERISK-28131: ${ANSWEREDTIME} is incorrect in Dial app in Asterisk 15.6
Reporter:Kapil Bansal (kkbansal004@gmail.com)Labels:
Date Opened:2018-10-25 08:04:38Date Closed:2018-10-26 07:59:59
Priority:CriticalRegression?
Status:Closed/CompleteComponents:Applications/app_dial
Versions:15.6.0 15.6.1 Frequency of
Occurrence		Constant
Related
Issues:
Environment:Centos 6.9Attachments:
Description:$\{ANSWEREDTIME} is incorrect and same as $\{DIALEDTIME} in Dial app in Asterisk 15.6
Comments:By: Asterisk Team (asteriskteam) 2018-10-25 08:04:39.920-0500

Thanks for creating a report! The issue has entered the triage process. That means the issue will wait in this status until a Bug Marshal has an opportunity to review the issue. Once the issue has been reviewed you will receive comments regarding the next steps towards resolution.

A good first step is for you to review the [Asterisk Issue Guidelines|https://wiki.asterisk.org/wiki/display/AST/Asterisk+Issue+Guidelines] if you haven't already. The guidelines detail what is expected from an Asterisk issue report.

Then, if you are submitting a patch, please review the [Patch Contribution Process|https://wiki.asterisk.org/wiki/display/AST/Patch+Contribution+Process].
By: George Joseph (gjoseph) 2018-10-25 14:38:03.471-0500

Asterisk 15 is now in "Security Fix Only" mode so can you recreate the issue in 16.0?

Did it work in earlier versions of 15?
Can you give us a dialplan snippet?
How are you examining the two variables?


By: Kapil Bansal (kkbansal004@gmail.com) 2018-10-25 14:46:12.353-0500

Yes, it's working on earlier versions. I also test this on asterisk 11.25 and it's working properly.

Telnet packet for asterisk 15.6.1.

Event: VarSet
Privilege: dialplan,all
Channel: SIP/SIP10-00000046
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 4030247051
CallerIDName: 00917976111924
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode: KOOKOO-inbound
Context: kookoo_route_v2
Exten: 914030247050
Priority: 11
Uniqueid: 1540471046.128
Linkedid: 1540471046.128
Variable: ANSWEREDTIME
Value: 13

Event: VarSet
Privilege: dialplan,all
Channel: SIP/SIP10-00000046
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 4030247051
CallerIDName: 00917976111924
ConnectedLineNum: <unknown>
ConnectedLineName: <unknown>
Language: en
AccountCode: KOOKOO-inbound
Context: kookoo_route_v2
Exten: 914030247050
Priority: 11
Uniqueid: 1540471046.128
Linkedid: 1540471046.128
Variable: DIALEDTIME
Value: 13
By: Kapil Bansal (kkbansal004@gmail.com) 2018-10-26 00:54:04.765-0500

Please check below logs for asterisk 15.6 and 11.25 for same dial plan.
Call duration almost same after call answered but value of  ${ANSWEREDTIME} is different.

DialPlan:-

[test_dial]
exten => s,1,Answer()
exten => s,2,Dial(SIP/99853XXXXXX@LCR1,30,g)
exten => s,3,Verbose(1,"Ansewered Time : ${ANSWEREDTIME}")
exten => s,4,Verbose(1,"Dialeded Time : ${DIALEDTIME}")
exten => s,5,Hangup()


CLI logs for asterisk 15.6 :-

  -- Executing [s@test_dial:1] Answer("SIP/SIP10-0000004e", "") in new stack
      > 0x7fcfe802c740 -- Strict RTP learning after ICE completion
      > 0x7fcfe802c740 -- Strict RTP switching to RTP target address 172.16.15.10:7544 as source
   -- Executing [s@test_dial:2] Dial("SIP/SIP10-0000004e", "SIP/9985XXXXX@LCR1,30,g") in new stack
 == Using SIP RTP CoS mark 5
   -- Called SIP/99853XXXX@LCR1
      > 0x7fd0100660d0 -- Strict RTP learning after remote address set to: 172.16.15.103:32506
   -- SIP/LCR1-0000004f is making progress passing it to SIP/SIP10-0000004e
      > 0x7fd0100660d0 -- Strict RTP switching to RTP target address 172.16.15.103:32506 as source
 == Manager 'kookoo' logged on from 172.16.15.238
 == Manager 'kookoo' logged off from 172.16.15.238
 == Manager 'kookoo' logged on from 172.16.15.238
 == Manager 'kookoo' logged off from 172.16.15.238
      > 0x7fcfe802c740 -- Strict RTP learning complete - Locking on source address 172.16.15.10:7544
      > 0x7fd0100660d0 -- Strict RTP learning complete - Locking on source address 172.16.15.103:32506
   -- SIP/LCR1-0000004f answered SIP/SIP10-0000004e
   -- Channel SIP/LCR1-0000004f joined 'simple_bridge' basic-bridge <637b46a6-2cd8-440f-906b-488a7fb0b705>
   -- Channel SIP/SIP10-0000004e joined 'simple_bridge' basic-bridge <637b46a6-2cd8-440f-906b-488a7fb0b705>
   -- Channel SIP/LCR1-0000004f left 'simple_bridge' basic-bridge <637b46a6-2cd8-440f-906b-488a7fb0b705>
   -- Channel SIP/SIP10-0000004e left 'simple_bridge' basic-bridge <637b46a6-2cd8-440f-906b-488a7fb0b705>
   -- Executing [s@test_dial:3] Verbose("SIP/SIP10-0000004e", "1,"Ansewered Time : 8"") in new stack
"Ansewered Time : 8"
   -- Executing [s@test_dial:4] Verbose("SIP/SIP10-0000004e", "1,"Dialeded Time : 8"") in new stack
"Dialeded Time : 8"
   -- Executing [s@test_dial:5] Hangup("SIP/SIP10-0000004e", "") in new stack

CLI Logs for asterisk 11.25 :-

   -- Executing [s@test_dial:1] Answer("SIP/LCR-000001c0", "") in new stack
   -- Executing [s@test_dial:2] Dial("SIP/LCR-000001c0", "SIP/99853XXXXX@LCR1,30,g") in new stack
 == Using SIP RTP CoS mark 5
   -- Called SIP/99853XXXXX@LCR1
   -- SIP/LCR1-000001c1 is making progress passing it to SIP/LCR-000001c0
 == Manager 'kookoo' logged on from 172.16.15.103
   -- SIP/LCR1-000001c1 answered SIP/LCR-000001c0
   -- Locally bridging SIP/LCR-000001c0 and SIP/LCR1-000001c1
   -- Executing [s@test_dial:3] Verbose("SIP/LCR-000001c0", "1,"Ansewered Time : 3"") in new stack
"Ansewered Time : 3"
   -- Executing [s@test_dial:4] Verbose("SIP/LCR-000001c0", "1,"Dialeded Time : 11"") in new stack
"Dialeded Time : 11"
   -- Executing [s@test_dial:5] Hangup("SIP/LCR-000001c0", "") in new stack
 == Spawn extension (test_dial, s, 5) exited non-zero on 'SIP/LCR-000001c0'
By: Kapil Bansal (kkbansal004@gmail.com) 2018-10-26 01:33:57.367-0500

Asterisk 16 also have same issue.

   -- Executing [s@test_dial:1] Answer("SIP/SIP10-00000000", "") in new stack
      > 0x7f75a8005ea0 -- Strict RTP learning after ICE completion
      > 0x7f75a8005ea0 -- Strict RTP switching to RTP target address 172.16.15.10:9316 as source
   -- Executing [s@test_dial:2] Dial("SIP/SIP10-00000000", "SIP/99853XXXXX@LCR1,30,g") in new stack
 == Using SIP RTP CoS mark 5
   -- Called SIP/9985XXXXXX@LCR1
      > 0x7f75a400de10 -- Strict RTP learning after remote address set to: 172.16.15.103:32514
   -- SIP/LCR1-00000001 is making progress passing it to SIP/SIP10-00000000
      > 0x7f75a400de10 -- Strict RTP switching to RTP target address 172.16.15.103:32514 as source
   -- SIP/LCR1-00000001 answered SIP/SIP10-00000000
   -- Channel SIP/LCR1-00000001 joined 'simple_bridge' basic-bridge <80cbb071-bc5a-40c6-b147-dd8f148364f0>
   -- Channel SIP/LCR1-00000001 left 'simple_bridge' basic-bridge <80cbb071-bc5a-40c6-b147-dd8f148364f0>
   -- Channel SIP/SIP10-00000000 left 'simple_bridge' basic-bridge <80cbb071-bc5a-40c6-b147-dd8f148364f0>
   -- Executing [s@test_dial:3] Verbose("SIP/SIP10-00000000", "1,"Ansewered Time : 12"") in new stack
"Ansewered Time : 12"
   -- Executing [s@test_dial:4] Verbose("SIP/SIP10-00000000", "1,"Dialeded Time : 12"") in new stack
"Dialeded Time : 12"
   -- Executing [s@test_dial:5] Hangup("SIP/SIP10-00000000", "") in new stack
 == Spawn extension (test_dial, s, 5) exited non-zero on 'SIP/SIP10-00000000'
By: George Joseph (gjoseph) 2018-10-26 08:00:00.054-0500

Kapil,

You're calling Answer() just before dialing so of course the times are going to be equal.

By: Kapil Bansal (kkbansal004@gmail.com) 2018-10-26 08:09:07.746-0500

Hi Georag,

I am using same dial plan in asterisk 11 also but the answered time is different from dialled time because dialled also include ring time.  

By: Asterisk Team (asteriskteam) 2018-10-26 08:09:07.955-0500

This issue has been reopened as a result of your commenting on it as the reporter. It will be triaged once again as applicable.
By: George Joseph (gjoseph) 2018-10-26 08:35:40.630-0500

It may have been broken in 11.
In your dialplan...
  ANSWEREDTIME is the time from when you call Answer() to the end of the call.
  DIALEDTIME is the time from when you call Dial() to the end of the call.
Because you explicitly call Answer() just before you call Dial(), they're going to be the same.

Why do you call Answer() explicitly?
By: Kapil Bansal (kkbansal004@gmail.com) 2018-10-30 08:01:27.190-0500

If not doing Answer() it's not allow to play anything before dial and disconnect after 4-5 sec.
By: Kapil Bansal (kkbansal004@gmail.com) 2018-10-31 04:38:45.635-0500

Hi,
Answer(), is to answer the primary channel(user channel),  without that we can't play back any file to the user  in case of we have IVR OR  Moh to playback.


ANSWEREDTIME should be returned the duration of channel2 (which I give Dial command) . It was the scenario in asterisk 11.x.

but in asterisk 15.x and 16, we are facing the issue.

below is from Dial command description


This application sets the following channel variables:
$\{DIALEDTIME}: This is the time from dialing a channel until when it is
disconnected.
$\{ANSWEREDTIME}: This is the amount of time for actual call.
$\{DIALEDPEERNAME}: The name of the outbound channel that answered the call.
$\{DIALEDPEERNUMBER}: The number that was dialed for the answered outbound
channel.
$\{FORWARDERNAME}: If a call forward occurred, the name of the forwarded
channel.
$\{DIALSTATUS}: This is the status of the call

Thanks and Regards,
Rajesh Ganji.








By: Kapil Bansal (kkbansal004@gmail.com) 2018-11-05 07:45:50.686-0600

Hi,
is there any update.
By: Kevin Harwell (kharwell) 2018-11-06 15:23:58.459-0600

[~kkbansal004@gmail.com],

As George has stated the times are the same because you "Answer" the call before dialing. This is correct behavior according to the documentation you posted (same [here|https://wiki.asterisk.org/wiki/display/AST/Asterisk+13+Application_Dial] and more [here|https://wiki.asterisk.org/wiki/display/AST/Dial+Channel+Variables]). I agree with George in that if this was not the behavior in Asterisk 11 then that was probably due to a bug, which may have been inadvertently fixed since then.

That being said it sounds like you are wanting to play back audio before the dial. If you use the "[Progress|https://wiki.asterisk.org/wiki/display/AST/Asterisk+13+Application_Progress]" application instead of "Answer" this should allow you to do that as well as reflect the proper dial and answer times. For instance:
{noformat}
exten => 102,1,NoOp()
same => n,Progress()
same => n,Playback(demo-congrats,noanswer)
same => n,Dial(PJSIP/102,10)
same => n,Hangup()
{noformat}