UniqueID is changed upon transfer to the queue

Asterisk Asterisk Support
1

Hi All!

Recently i noticed an issue with queue_log entries Asterisk stores when a call is transferred in the queue. Event COMPLETECALLER/AGENT is sometimes stored with different UniqueID than other events of that call. This makes it impossible to fully track this call.
Test Asterisk is 16.10.8. I also tried 16.8.0 and got the same behavior.
Has anyone experienced this? Is this an expected behavior? Could it be a bug or there are some configurations i need to fix?
I would be grateful for any information.

I have this scenario:
Customer calls in(0001).
An employee answers(2333), talks for a while and then makes attended transfer via feature #2 to the queue(test_queue) through extension(0002).
Queue has 1 member through chan local “Local/0011@from-queue” who answers the call.

extensions.conf

[internal]
exten => 0001,1,Dial(PJSIP/2333,,TtXx) ;Customer calls in(0001)

exten => 0002,1,Answer() ;attended transfer via feature #2 to the queue(test_queue) through extension(0002). 
 same => n,Queue(test_queue,,,,360)
 same => n,HangUp()

[from-queue] ;Queue has 1 member through chan local "Local/0011@from-queue" who answers the call.
exten => _XXXX,1,NoOp(${CALID})
 same => n,NoOp(${UNIQUEID})
 same => n,NoOp(${CALLERID(num)})
 same => n,Dial(${PJSIP_DIAL_CONTACTS(${EXTEN})},,U(voladj)t)
 same => n,HangUp()

After hangup here is what i see in queue_log table:

| 2020-06-08 14:32:51.949028 | 1591615971.150 | test_queue     | NONE                  | ENTERQUEUE    | NULL |                  | 2333           | 1     |       |       |
| 2020-06-08 14:33:05.738257 | 1591615971.150 | test_queue     | Local/0011@from-queue | CONNECT       | NULL | 14               | 1591615971.151 | 13    |       |       |
| 2020-06-08 14:33:11.029481 | 1591615960.147 | test_queue     | Local/0011@from-queue | COMPLETEAGENT | NULL | 14               | 6              | 1     |

In event COMPLETEAGENT uniqueid is changed from 1591615971.150 to 1591615960.147.

Enabling debug shows that once call is answered in the test_queue uniqueid was changed when local channel is optimized:

[Jun  8 14:33:05] DEBUG[24117][C-00000006]: stasis.c:438 topic_dtor: Destroying topic. name: cache:183/bridge:997eb75e-787e-4d85-aba8-dcaf27acaa60, detail: 
[Jun  8 14:33:05] DEBUG[24117][C-00000006]: stasis.c:446 topic_dtor: Topic 'cache:183/bridge:997eb75e-787e-4d85-aba8-dcaf27acaa60': 0x7ff424095520 destroyed
[Jun  8 14:33:05] DEBUG[24117][C-00000006]: stasis.c:438 topic_dtor: Destroying topic. name: bridge:997eb75e-787e-4d85-aba8-dcaf27acaa60, detail: 
[Jun  8 14:33:05] DEBUG[24117][C-00000006]: stasis.c:446 topic_dtor: Topic 'bridge:997eb75e-787e-4d85-aba8-dcaf27acaa60': 0x7ff42407cff0 destroyed
[Jun  8 14:33:05] DEBUG[24118]: devicestate.c:361 _ast_device_state: No provider found, checking channel drivers for Local - 0011@from-queue
[Jun  8 14:33:05] DEBUG[24118]: devicestate.c:466 do_state_change: Changing state for Local/0011@from-queue - state 1 (Not in use)
[Jun  8 14:33:05] DEBUG[7515]: app_queue.c:6378 handle_local_optimization_end: Local optimization: Changing queue member uniqueid from 1591615971.151 to 1591615971.153
[Jun  8 14:33:05] DEBUG[24233]: app_queue.c:2436 pending_members_remove: Removed Local/0011@from-queue from pending_members
[Jun  8 14:33:05] DEBUG[24233]: app_queue.c:2436 pending_members_remove: Removed Local/0011@from-queue from pending_members
[Jun  8 14:33:05] DEBUG[24233]: app_queue.c:2436 pending_members_remove: Removed Local/0011@from-queue from pending_members
[Jun  8 14:33:05] DEBUG[24233]: app_queue.c:2586 device_state_cb: Device 'Local/0011@from-queue' changed to state '1' (Not in use)
[Jun  8 14:33:05] DEBUG[24233]: app_queue.c:2591 device_state_cb: Device 'Queue:test_queue_avail' changed to state '2' (In use) but we don't care because they're not a member of any queue.
[Jun  8 14:33:05] DEBUG[24128]: cdr_mysql.c:353 mysql_log: Inserting a CDR record.

I know there is “no release” key exists as “/n” which won’t allow local channel to be optimized until call is hungup however this is not the reason as if i add this key i get the same behavior:

| 2020-06-08 14:47:26.615212 | 1591616846.177 | test_queue     | NONE                    | ENTERQUEUE    | NULL |                | 2333           | 1     |       |       |
| 2020-06-08 14:47:30.073185 | 1591616846.177 | test_queue     | Local/0011@from-queue/n | CONNECT       | NULL | 4              | 1591616846.178 | 3     |       |       |
| 2020-06-08 14:47:32.273585 | 1591616837.174 | test_queue     | Local/0011@from-queue/n | COMPLETEAGENT | NULL | 4              | 2              | 1     |       |

Various tests shows that this happens very often but not always, sometimes ID is correct:

| 2020-06-08 14:49:43.531755 | 1591616983.215 | test_queue     | NONE                    | ENTERQUEUE    | NULL |                | 2333           | 1     |       |       |
| 2020-06-08 14:49:50.472153 | 1591616983.215 | test_queue     | Local/0011@from-queue/n | CONNECT       | NULL | 7              | 1591616983.216 | 6     |       |       |
| 2020-06-08 14:50:18.781674 | 1591616983.215 | test_queue     | Local/0011@from-queue/n | COMPLETEAGENT | NULL | 7              | 28             | 1

I used these configurations:
features.conf

[featuremap]
blindxfer => *#         ; Blind transfer  (default is #) -- Make sure to set the T and/or t option in the Dial() or Queue() app call!
;disconnect => **    ; Disconnect  (default is *) -- Make sure to set the H and/or h option in the Dial() or Queue() app call!
atxfer => #2

queues.conf

 [general]
persistentmembers = yes
monitor-type = MixMonitor
setqueuevar=yes
setinterfacevar=yes
setinterfacevar=yes
setqueueentryvar=yes
setqueuevar=yes
leavewhenempty = inuse,ringing

[test_queue]
music = default
strategy = ringall
timeout = 15
wrapuptime = 10
autofill=yes
joinempty = no
ringinuse=yes

My Asterisk configuration:

PBX Core settings
Version: 16.10.0
Build Options: BUILD_NATIVE, OPTIONAL_API
Maximum calls: 10000 (Current 0)
Maximum open file handles: 500000
Root console verbosity: 7
Current console verbosity: 4
Debug level: 0
Maximum load average: 0.000000
Minimum free memory: 0 MB
Startup time: 14:11:46
Last reload time: 14:12:19
System: Linux/3.10.0-862.14.4.el7.x86_64 built by root on x86_64 2020-05-06 18:49:45 UTC
System name:
Entity ID: 00:50:56:91:17:95
PBX UUID: 67e09d16-bebd-4101-a97d-6ca76740294f
Default language: en
Language prefix: Enabled
User name and group: asterisk/asterisk
Executable includes: Disabled
Transcode via SLIN: Enabled
Transmit silence during rec: Disabled
Generic PLC: Enabled
Generic PLC on equal codecs: Disabled
Hide Msg Chan AMI events: Disabled
Min DTMF duration:: 50
Cache media frames: Enabled
RTP use dynamic payloads: 1
RTP dynamic payload types: 35-63,96-127

Thanks!

2

Yes. It’s very likely that that scenario would involve a masquerade.

I can’t remember the name offhand, but an extra variable representing first uniquie ID for a call, was introduced several years ago, to cover that sort of situation.

3

Hello david551,

Thank you for your reply. I dig a bit and it seems to be called LinkedID.
It can be received via:

${CHANNEL(LINKEDID)}
${CDR(linkedid)}

After tests i realized that COMPLETEAGENT event is written with correct uniqueid, it is all other events are with different id. So i will try to insert queue_log entries to connect them.

Thanks again!

4

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.