[Home]

Summary:ASTERISK-24613: Wrong NewExten Manager Event sent directly after features.conf Blind Transfer
Reporter:Maciej Cygan (infinit0s)Labels:
Date Opened:2014-12-12 10:45:08.000-0600Date Closed:
Priority:MajorRegression?No
Status:Open/NewComponents:
Versions:13.0.0 13.0.1 13.0.2 Frequency of
Occurrence		Constant
Related
Issues:
Environment:Linux server 3.2.0-4-amd64 #1 SMP Debian 3.2.54-2 x86_64 GNU/Linux Attachments:( 0) manager.txt
( 1) output.txt
( 2) outputNEW.txt
Description:I have checked if similar issue was already raised but i was not able to find any, if however similar issue was reported i do apologise in advance for raising duplicate.

Issue: Wrong AppData and Application is sent in the NewExten event on the first Newexten after a blind transfer.

Instead of showing the correct Application and AppData for the new extension and priority, it shows the last Application and AppData from the old extension before the transfer.

Here is an example, showing how to reproduce the error.

Extensions.conf :
{noformat}
;TEST CONFIG
[main]
exten => _2XXX,1,NoOp(This is the first priority of ${EXTEN})
exten => _2XXX,n,NoOp(This is the second priority of ${EXTEN} - about to dial SIP/1${EXTEN:1})
exten => _2XXX,n,Dial(SIP/1${EXTEN:1},,rotwh)
exten => _2XXX,n,Hangup
{noformat}
To reproduce this error you will need 3 phones ( 1001,1005,1007 ).

Order of exectuion:

1007 calls 2001
1001 blind transfers to 2005, which dials SIP/1005


Directly after the transfer, Asterisk log shows the correct dialplan execution in the console output:
{noformat}
   -- Executing [2005@main:1] NoOp("SIP/1007-0000000b", "This is the first priority of 2005") in new stack
   -- Executing [2005@main:2] NoOp("SIP/1007-0000000b", "This is the second priority of 2005 - about to dial SIP/1005") in new stack
   -- Executing [2005@main:3] Dial("SIP/1007-0000000b", "SIP/1005,,rotwh") in new stack
{noformat}

however this is what I get in the first NewExten event output during this execution:
{noformat}
Event: Newexten
Privilege: call,all
Channel: SIP/1007-0000001d
ChannelState: 6
ChannelStateDesc: Up
CallerIDNum: 1007
CallerIDName: 1007
ConnectedLineNum: 1001
ConnectedLineName: 1001
AccountCode:
Context: main
Exten: 2005
Priority: 1
Uniqueid: 1418398132.45
Extension: 2005
Application: Dial
AppData: SIP/1001,,rotwh
{noformat}
The Application and AppData is wrong.  It should read:
{noformat}
Application: NoOp
AppData: This is the first priority of 2005
{noformat}
Comments:By: Rusty Newton (rnewton) 2014-12-16 18:39:36.990-0600

We require a complete debug log to help triage the issue. This document will provide instructions on how to collect debugging logs from an Asterisk machine for the purpose of helping bug marshals troubleshoot an issue: https://wiki.asterisk.org/wiki/display/AST/Collecting+Debug+Information


By: Rusty Newton (rnewton) 2014-12-16 18:43:19.084-0600

The priority looks wrong too, but your channels don't match in your two examples.

Can you provide the log requested above, following the linked instructions and being sure that it includes the "DEBUG" and "VERBOSE" logger channel types?
By: Rusty Newton (rnewton) 2014-12-16 18:43:46.147-0600

Use Send Back or Enter Feedback to send the issue back to us when you have the information. Thanks!
By: Matt King, M.A. Oxon. (kebl0155) 2014-12-21 05:14:19.957-0600

This is the debug log output as requested.  This looks normal.  It is the manager output that contains the bug.  The line in the debug level output that corresponds to the bug can be found by searching for the word FAULT.
By: Matt King, M.A. Oxon. (kebl0155) 2014-12-21 05:16:15.982-0600

This is the Manager output, that contains the bug.  Search for the word FAULT to find it.

In my example SIP/1003 dials extension 2001
2001 dials SIP/1001, which answers.
SIP/1001 then initiates a blind transfer to 2005.

The first Newexten event produced after the blind transfer is garbage.
By: Matt Jordan (mjordan) 2015-01-12 09:42:35.301-0600

You aren't providing all of the information requested. Please follow the linked instructions on the wiki for generating DEBUG information.

For us to correlate what occurs in AMI, we also need to see what the channel is executing. A properly generated DEBUG log, using the instructions on the wiki, will give us that.
By: Matt King, M.A. Oxon. (kebl0155) 2015-01-12 10:19:17.950-0600

My apologies, I had not realised that Asterisk 13 requires

core set debug 5

in order to enable debug logging.

Please find attached fresh output.




By: Matt King, M.A. Oxon. (kebl0155) 2015-01-21 07:51:36.423-0600

Um, why has this gone back to 'Waiting for feedback'?

The requested debug level logs have been supplied.
By: Matt King, M.A. Oxon. (kebl0155) 2015-01-21 07:54:10.181-0600

I don't think this issue should be in Waiting for Feedback, as we have supplied the full debug logs requested.

I hope I'm doing this right...
By: Matt Jordan (mjordan) 2015-01-21 08:57:48.088-0600

{quote}
You aren't providing all of the information requested. Please follow the linked instructions on the wiki for generating DEBUG information.

For us to correlate what occurs in AMI, we also need to see what the channel is executing. A properly generated DEBUG log, using the instructions on the wiki, will give us that.
{quote}

The DEBUG log doesn't show the AMI information. Right now, we have two disjoint pieces of information:
# The output of AMI with no context
# The context, without the output of AMI

Please provide a log showing all of the information together. If you have an AMI connection to Asterisk with full debugging enabled, the events should be displayed in the log.
By: Matt King, M.A. Oxon. (kebl0155) 2015-01-21 09:52:54.994-0600

This file contains both the debug level logging AND the manager events.
By: Matt King, M.A. Oxon. (kebl0155) 2015-01-21 09:54:31.232-0600

Ah, I think the first time we did the output, we didn't have an AMI connection running at the time.

Please find attached outputNEW.txt that contains everything as requested.

Sorry for the backwards and forwards on this - we weren't very clear on what you were asking us to do.
By: Matt King, M.A. Oxon. (kebl0155) 2015-01-29 10:35:01.727-0600

Hi there,

This is causing us to misreport blind transferred calls in our popular OrderlyStats product.

We are putting a rather elaborate work around to simply ignore the next Newexten after a blind transfer, but this will also result in misreported calls.

When you fix this, could we please get an increment to the Asterisk Call Manager version shown when logging into Manager?  That way we will know whether it is safe to trust the first Newexten after a transferred call, or whether this should be ignored.

Warm regards,

Matt King
Managing Director
Orderly Telecoms Ltd.
By: Matt Jordan (mjordan) 2015-01-29 14:15:10.508-0600

[~kebl0155]: This would, at best, warrant only a bug-fix bump to the AMI version. So, maybe.

See [Semantic Versioning|http://semver.org/].
By: Matt King, M.A. Oxon. (kebl0155) 2015-01-30 05:59:47.517-0600

Thanks Matt!  So long as we can tell from the manager version number that it's fixed, we'll be OK with that.

We're having to recommend our customers hold off from Asterisk 13 until this is fixed :(

Warm regards,

Matt.