[Home]

Summary:ASTERISK-28922: Attended transfer not swapping channel
Reporter:Robert Sutton (rsutton@noojee.com.au)Labels:
Date Opened:2020-05-29 01:01:20Date Closed:
Priority:MajorRegression?
Status:Open/NewComponents:Bridges/bridge_simple
Versions:16.10.0 Frequency of
Occurrence		Occasional
Related
Issues:
Environment:ubunutu 18.04, docker, asterisk 16.10, pjsipAttachments:
Description:occasionally an attended transfer results in the agents channel name appearing in the bridge instead of the callers.

It appears that asterisk fails to swap the channel names.

The connected parties are as expected but the channel names are wrong which is causing problems for reporting and some of our other external systems.

I can't recreate this on demand, I would estimate the frequency at about 1 in 500 attended transfers.

There are 4 channels in volved
a (000005c6) caller
b (000005d1) agent -> a
c (000005cb) agent -> d
d (000005d2) other

The call flow is:
1 incoming call (a) answered by agent (b).
2 AMI originate a second call (c) to the agent.
3 agent answers second call (c) (the far end (d) is making progress, but not yet answered).
4 agent uses "swap" button on phone to talk to original caller (b).
5 agent transfers the caller to the other call (b,c) , simultaneously the other call (d) answers.
6 the bridge shows channels (d) and (b) in the bridge instead of (a) and (d)
7 the expected parties are bridged and call completes normally

{noformat}

2020-05-28T22:44:49.125240532Z     -- Called 147
2020-05-28T22:44:49.470682765Z     -- PJSIP/147-000005d1 is ringing
2020-05-28T22:44:49.470716891Z     -- PJSIP/147-000005d1 is ringing
2020-05-28T22:44:50.344321032Z     -- PJSIP/147-000005d1 answered
2020-05-28T22:44:50.344493873Z     -- Executing [55512341234@routesv2-handset:1] Set("PJSIP/147-000005d1", "AGIEXITONHANGUP=yes") in new stack
2020-05-28T22:44:50.344574542Z     -- Executing [55512341234@routesv2-handset:2] AGI("PJSIP/147-000005d1", "agi://127.0.0.1/route?targ=55512341234&ctx=Pre-Handset") in new stack
2020-05-28T22:44:50.348169514Z     -- AGI Script Executing Application: (Progress) Options: ()
2020-05-28T22:44:50.348553523Z     -- AGI Script Executing Application: (Playtones) Options: (ring)
2020-05-28T22:44:50.353520608Z     -- AGI Script Executing Application: (StopPlayTones) Options: ()

2020-05-28T22:44:50.478424444Z   == Begin MixMonitor Recording PJSIP/147-000005d1

2020-05-28T22:44:50.496147459Z     -- AGI Script Executing Application: (dial) Options: (PJSIP/55512341234@trunk,30,rb(set-header^1^1)B(set-clid^1^1(55533332222,)))
2020-05-28T22:44:50.496431063Z     -- PJSIP/147-000005d1 Internal Gosub(set-clid,1,1(55533332222,)) start
2020-05-28T22:44:50.496449977Z     -- Executing [1@set-clid:1] Verbose("PJSIP/147-000005d1", "1,preparing to set clid") in new stack
2020-05-28T22:44:50.496458410Z  preparing to set clid
2020-05-28T22:44:50.496536886Z     -- Executing [1@set-clid:2] Set("PJSIP/147-000005d1", "CALLERID(num)=55533332222") in new stack
2020-05-28T22:44:50.496557244Z     -- Executing [1@set-clid:3] Set("PJSIP/147-000005d1", "CALLERID(name)=") in new stack
2020-05-28T22:44:50.496646457Z     -- Executing [1@set-clid:4] Return("PJSIP/147-000005d1", "") in new stack
2020-05-28T22:44:50.496658470Z   == Spawn extension (routesv2-handset, 55512341234, 2) exited non-zero on 'PJSIP/147-000005d1'
2020-05-28T22:44:50.496664422Z     -- PJSIP/147-000005d1 Internal Gosub(set-clid,1,1(55533332222,)) complete GOSUB_RETVAL=
2020-05-28T22:44:50.502254652Z     -- PJSIP/trunk-000005d2 Internal Gosub(set-header,1,1) start
2020-05-28T22:44:50.502276235Z     -- Executing [1@set-header:1] Verbose("PJSIP/trunk-000005d2", "1,preparing to set headers") in new stack
2020-05-28T22:44:50.502324362Z  preparing to set headers
2020-05-28T22:44:50.502533577Z     -- Executing [1@set-header:2] Set("PJSIP/trunk-000005d2", "AGIEXITONHANGUP=yes") in new stack
2020-05-28T22:44:50.502548007Z     -- Executing [1@set-header:3] Set("PJSIP/trunk-000005d2", "PJSIP_HEADER(add,Call-Info)=") in new stack
2020-05-28T22:44:50.503072316Z     -- Executing [1@set-header:4] ExecIf("PJSIP/trunk-000005d2", "1?return()") in new stack
2020-05-28T22:44:50.503272445Z   == Spawn extension (routesv2-inbound, 55512341234, 1) exited non-zero on 'PJSIP/trunk-000005d2'
2020-05-28T22:44:50.503314327Z     -- PJSIP/trunk-000005d2 Internal Gosub(set-header,1,1) complete GOSUB_RETVAL=
2020-05-28T22:44:50.503323399Z     -- Called PJSIP/55512341234@trunk

2020-05-28T22:44:50.579111153Z   == Begin MixMonitor Recording PJSIP/147-000005d1
2020-05-28T22:44:50.679223223Z   == Begin MixMonitor Recording PJSIP/147-000005d1
2020-05-28T22:44:51.063049680Z OK  == End MixMonitor Recording PJSIP/147-000005d1
2020-05-28T22:44:51.124326992Z OK  == End MixMonitor Recording PJSIP/147-000005d1


2020-05-28T22:44:51.789749843Z     -- Call on PJSIP/trunk-000005d2 placed on hold
2020-05-28T22:44:51.792444137Z     -- Started music on hold, class 'default2', on channel 'PJSIP/trunk-000005d2'
2020-05-28T22:44:51.911628373Z     -- Stopped music on hold on PJSIP/trunk-000005c6
2020-05-28T22:44:52.632191581Z     -- Channel PJSIP/147-000005cb left 'simple_bridge' basic-bridge <44009243-408d-4889-8839-bc60e4ad46db>
2020-05-28T22:44:52.632661038Z     -- Channel PJSIP/trunk-000005c6 left 'simple_bridge' basic-bridge <44009243-408d-4889-8839-bc60e4ad46db>
2020-05-28T22:44:52.632735669Z   == Spawn extension (company-activity, activity-agi, 2) exited non-zero on 'PJSIP/147-000005cb'

2020-05-28T22:44:56.511197717Z     -- PJSIP/trunk-000005d2 is making progress passing it to PJSIP/147-000005d1
2020-05-28T22:44:56.511370052Z     -- PJSIP/trunk-000005d2 is making progress passing it to PJSIP/147-000005d1
2020-05-28T22:44:59.166297182Z     -- PJSIP/trunk-000005d2 answered PJSIP/147-000005d1
2020-05-28T22:44:59.167460733Z     -- Channel PJSIP/trunk-000005d2 joined 'simple_bridge' basic-bridge <d8d44dd2-9386-40ed-9782-b1c9f71d225a>
2020-05-28T22:44:59.167681295Z     -- Channel PJSIP/147-000005d1 joined 'simple_bridge' basic-bridge <d8d44dd2-9386-40ed-9782-b1c9f71d225a>

2020-05-28T22:44:59.200426835Z   == Begin MixMonitor Recording PJSIP/147-000005d1
2020-05-28T22:44:59.285524521Z   == Begin MixMonitor Recording PJSIP/147-000005d1
2020-05-28T22:44:59.306030575Z   == Begin MixMonitor Recording PJSIP/trunk-000005d2
2020-05-28T22:44:59.723198569Z OK  == End MixMonitor Recording PJSIP/147-000005d1
2020-05-28T22:44:59.756330292Z OK  == End MixMonitor Recording PJSIP/147-000005d1

{noformat}
Comments:By: Asterisk Team (asteriskteam) 2020-05-29 01:01:21.156-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].

Please note that once your issue enters an open state it has been accepted. As Asterisk is an open source project there is no guarantee or timeframe on when your issue will be looked into. If you need expedient resolution you will need to find and pay a suitable developer. Asking for an update on your issue will not yield any progress on it and will not result in a response. All updates are posted to the issue when they occur.
By: George Joseph (gjoseph) 2020-05-29 08:34:36.395-0500

Robert, is this something new you're seeing with 16.10 or was it happening with earlier versions?  If earlier versions, do you remember which version it started to appear?

There are multiple threads involved in this scenario and I'm thinking that events are being generated on one thread before the swap is completed on another.

By: Robert Sutton (rsutton@noojee.com.au) 2020-06-01 00:51:51.255-0500

I don't know if it was present in older versions.
By: Robert Sutton (rsutton@noojee.com.au) 2020-06-03 00:57:01.526-0500

Upon reviewing the call recordings it doesn't look like the parties became bridged.

Here is another example call
{noformat}
2020-06-03T03:24:20.849270119Z     -- Executing [55512341236@routesv2-inbound:1] Set("PJSIP/trunk-00007073", "AGIEXITONHANGUP=yes") in new stack
2020-06-03T03:24:20.854578844Z     -- Executing [55512341236@routesv2-inbound:2] Set("PJSIP/trunk-00007073", "recovery-did=55512341236") in new stack
2020-06-03T03:24:20.854628635Z     -- Executing [55512341236@routesv2-inbound:3] AGI("PJSIP/trunk-00007073", "agi://127.0.0.1/route?targ=55512341236&ctx=Pre-Inbound") in new stack
2020-06-03T03:24:26.485758564Z   == Begin MixMonitor Recording PJSIP/trunk-00007073
2020-06-03T03:24:26.501662881Z     -- Started music on hold, class 'queue17', on channel 'PJSIP/trunk-00007073'
2020-06-03T03:24:27.332354027Z     -- PJSIP/139-00007074 is ringing
2020-06-03T03:24:27.332564550Z     -- PJSIP/139-00007074 is ringing
2020-06-03T03:24:32.204200096Z     -- PJSIP/139-00007074 answered
2020-06-03T03:24:32.204428655Z     -- Executing [activity-agi@noojee-activity:1] Set("PJSIP/139-00007074", "AGIEXITONHANGUP=yes") in new stack
2020-06-03T03:24:32.204536628Z     -- Executing [activity-agi@noojee-activity:2] AGI("PJSIP/139-00007074", "agi://127.0.0.1/activityAgi") in new stack
2020-06-03T03:24:32.206292738Z     -- Started music on hold, class 'default', on channel 'PJSIP/139-00007074'
2020-06-03T03:24:32.206408007Z     -- Stopped music on hold on PJSIP/139-00007074
2020-06-03T03:24:32.226121203Z   == Begin MixMonitor Recording PJSIP/trunk-00007073
2020-06-03T03:24:32.226569302Z     -- AGI Script Executing Application: (bridge) Options: (PJSIP/trunk-00007073,x)
2020-06-03T03:24:32.226961487Z     -- Stopped music on hold on PJSIP/trunk-00007073
2020-06-03T03:24:32.227720243Z   == Spawn extension (routesv2-inbound, 55512341236, 3) exited non-zero on 'Surrogate/PJSIP/trunk-00007073'
2020-06-03T03:24:32.228644614Z     -- Channel PJSIP/trunk-00007073 joined 'simple_bridge' basic-bridge <cbfbb690-f7f7-4df1-a5ba-68eb4fb6ea5c>
2020-06-03T03:24:32.228657365Z     -- Channel PJSIP/139-00007074 joined 'simple_bridge' basic-bridge <cbfbb690-f7f7-4df1-a5ba-68eb4fb6ea5c>
2020-06-03T03:24:32.365138981Z   == Begin MixMonitor Recording PJSIP/trunk-00007073
2020-06-03T03:24:32.866628699Z OK  == End MixMonitor Recording PJSIP/trunk-00007073
2020-06-03T03:24:32.916866421Z OK  == End MixMonitor Recording PJSIP/trunk-00007073
2020-06-03T03:26:05.178322027Z     -- Started music on hold, class 'default2', on channel 'PJSIP/trunk-00007073'
2020-06-03T03:27:27.147709996Z     -- Stopped music on hold on PJSIP/trunk-00007073
2020-06-03T03:28:12.159161972Z     -- Started music on hold, class 'default2', on channel 'PJSIP/trunk-00007073'
2020-06-03T03:28:20.357329832Z     -- PJSIP/139-000070b1 is ringing
2020-06-03T03:28:20.357853432Z     -- PJSIP/139-000070b1 is ringing
2020-06-03T03:28:22.277879639Z     -- PJSIP/139-000070b1 answered
2020-06-03T03:28:22.278630439Z     -- Executing [55512341235@routesv2-handset:1] Set("PJSIP/139-000070b1", "AGIEXITONHANGUP=yes") in new stack
2020-06-03T03:28:22.278848578Z     -- Executing [55512341235@routesv2-handset:2] AGI("PJSIP/139-000070b1", "agi://127.0.0.1/route?targ=55512341235&ctx=Pre-Handset") in new stack
2020-06-03T03:28:22.416985194Z     -- AGI Script Executing Application: (mixmonitor) Options: (/var/spool/asterisk/monitor/1591154899.38777--55512341235-O-1.wav,,curl 'http://127.0.0.1:8080/rest/recordingMigration/migrate?guid=1591154902415-62483&apiKey=xxxxxxxx')
2020-06-03T03:28:22.417306143Z   == Begin MixMonitor Recording PJSIP/139-000070b1
2020-06-03T03:28:22.434042490Z     -- PJSIP/139-000070b1 Internal Gosub(set-clid,1,1(55512341234,)) start
2020-06-03T03:28:22.434123870Z     -- Executing [1@set-clid:1] Verbose("PJSIP/139-000070b1", "1,preparing to set clid") in new stack
2020-06-03T03:28:22.434195764Z     -- Executing [1@set-clid:2] Set("PJSIP/139-000070b1", "CALLERID(num)=55512341234") in new stack
2020-06-03T03:28:22.434323697Z     -- Executing [1@set-clid:3] Set("PJSIP/139-000070b1", "CALLERID(name)=") in new stack
2020-06-03T03:28:22.434558336Z     -- Executing [1@set-clid:4] Return("PJSIP/139-000070b1", "") in new stack
2020-06-03T03:28:22.434682006Z   == Spawn extension (routesv2-handset, 55512341235, 2) exited non-zero on 'PJSIP/139-000070b1'
2020-06-03T03:28:22.434696409Z     -- PJSIP/139-000070b1 Internal Gosub(set-clid,1,1(55512341234,)) complete GOSUB_RETVAL=
2020-06-03T03:28:22.439141280Z     -- PJSIP/trunk-000070b3 Internal Gosub(set-header,1,1) start
2020-06-03T03:28:22.439469881Z     -- Executing [1@set-header:1] Verbose("PJSIP/trunk-000070b3", "1,preparing to set headers") in new stack
2020-06-03T03:28:22.439496683Z     -- Executing [1@set-header:2] Set("PJSIP/trunk-000070b3", "AGIEXITONHANGUP=yes") in new stack
2020-06-03T03:28:22.439535849Z     -- Executing [1@set-header:3] Set("PJSIP/trunk-000070b3", "PJSIP_HEADER(add,Call-Info)=") in new stack
2020-06-03T03:28:22.440035744Z     -- Executing [1@set-header:4] ExecIf("PJSIP/trunk-000070b3", "1?return()") in new stack
2020-06-03T03:28:22.440333869Z   == Spawn extension (routesv2-inbound, 55512341235, 1) exited non-zero on 'PJSIP/trunk-000070b3'
2020-06-03T03:28:22.440353838Z     -- PJSIP/trunk-000070b3 Internal Gosub(set-header,1,1) complete GOSUB_RETVAL=
2020-06-03T03:28:22.527152300Z   == Begin MixMonitor Recording PJSIP/139-000070b1
2020-06-03T03:28:22.621167046Z   == Begin MixMonitor Recording PJSIP/139-000070b1
2020-06-03T03:28:23.098093551Z OK  == End MixMonitor Recording PJSIP/139-000070b1
2020-06-03T03:28:23.149926199Z OK  == End MixMonitor Recording PJSIP/139-000070b1
2020-06-03T03:28:26.568434624Z     -- PJSIP/trunk-000070b3 is making progress passing it to PJSIP/139-000070b1
2020-06-03T03:28:26.568690871Z     -- PJSIP/trunk-000070b3 is making progress passing it to PJSIP/139-000070b1
2020-06-03T03:28:34.884984499Z     -- PJSIP/trunk-000070b3 answered PJSIP/139-000070b1
2020-06-03T03:28:34.886288019Z     -- Channel PJSIP/trunk-000070b3 joined 'simple_bridge' basic-bridge <45abb372-a940-4e5e-b60b-57cf81e89aa6>
2020-06-03T03:28:34.886574156Z     -- Channel PJSIP/139-000070b1 joined 'simple_bridge' basic-bridge <45abb372-a940-4e5e-b60b-57cf81e89aa6>
2020-06-03T03:28:34.920705231Z   == Begin MixMonitor Recording PJSIP/139-000070b1
2020-06-03T03:28:34.997179763Z   == Begin MixMonitor Recording PJSIP/trunk-000070b3
2020-06-03T03:28:35.107008107Z   == Begin MixMonitor Recording PJSIP/trunk-000070b3
2020-06-03T03:28:35.565087787Z OK  == End MixMonitor Recording PJSIP/139-000070b1
2020-06-03T03:28:35.635236129Z OK  == End MixMonitor Recording PJSIP/trunk-000070b3
2020-06-03T03:28:50.052485553Z     -- Started music on hold, class 'default2', on channel 'PJSIP/trunk-000070b3'
2020-06-03T03:28:50.322835005Z     -- Stopped music on hold on PJSIP/trunk-00007073
2020-06-03T03:28:53.819300906Z     -- Channel PJSIP/139-00007074 left 'simple_bridge' basic-bridge <cbfbb690-f7f7-4df1-a5ba-68eb4fb6ea5c>
2020-06-03T03:28:53.819899905Z     -- Channel PJSIP/trunk-00007073 left 'simple_bridge' basic-bridge <cbfbb690-f7f7-4df1-a5ba-68eb4fb6ea5c>
2020-06-03T03:28:53.821052656Z   == Spawn extension (noojee-activity, activity-agi, 2) exited non-zero on 'PJSIP/139-00007074'
2020-06-03T03:28:53.896461826Z [Jun  3 13:28:53] NOTICE[91]: manager.c:4491 action_hangup: Request to hangup non-existent channel: PJSIP/139-00007074
2020-06-03T03:28:55.438142879Z OK  == End MixMonitor Recording PJSIP/trunk-00007073
2020-06-03T03:38:37.942288492Z     -- Stopped music on hold on PJSIP/trunk-000070b3
2020-06-03T03:38:37.942956798Z     -- Channel PJSIP/trunk-000070b3 left 'simple_bridge' basic-bridge <45abb372-a940-4e5e-b60b-57cf81e89aa6>
2020-06-03T03:38:37.943355251Z     -- Channel PJSIP/139-000070b1 left 'simple_bridge' basic-bridge <45abb372-a940-4e5e-b60b-57cf81e89aa6>
2020-06-03T03:38:37.945822649Z     -- <PJSIP/139-000070b1>AGI Script agi://127.0.0.1/route?targ=55512341235&ctx=Pre-Handset completed, returning 0
2020-06-03T03:38:37.946106991Z     -- Executing [55512341235@routesv2-handset:3] ExecIf("PJSIP/139-000070b1", "0?goto(failed)") in new stack
2020-06-03T03:38:37.946499118Z     -- Executing [55512341235@routesv2-handset:4] Hangup("PJSIP/139-000070b1", "") in new stack
2020-06-03T03:38:38.027230229Z   == Spawn extension (routesv2-handset, 55512341235, 4) exited non-zero on 'PJSIP/139-000070b1'
2020-06-03T03:38:38.027358146Z     -- Executing [h@routesv2-handset:1] Hangup("PJSIP/139-000070b1", "") in new stack
2020-06-03T03:38:38.027464144Z   == Spawn extension (routesv2-handset, h, 1) exited non-zero on 'PJSIP/139-000070b1'
2020-06-03T03:38:42.105281779Z OK  == End MixMonitor Recording PJSIP/trunk-000070b3
2020-06-03T03:38:42.169912002Z OK  == End MixMonitor Recording PJSIP/139-000070b1


{noformat}