Hello, I am storing data from queues on a postgres database, and in some calls the event is set as as COMPLETECALLER when an agent hangup.
Here is an exemple:
The call enter on queue
[2022-04-01 13:57:50] VERBOSE[37536][C-00004eda] pbx.c: Executing [7699@queues:3] Queue("SIP/ag561-00006f00", "ura-informatica,tTc") in new stack
[2022-04-01 13:57:50] VERBOSE[37536][C-00004eda] res_musiconhold.c: Started music on hold, class 'default', on channel 'SIP/ag561-00006f00'
[2022-04-01 13:57:50] DEBUG[37536][C-00004eda] format_wav.c: Skipping unknown block 'LIST'
[2022-04-01 13:59:42] VERBOSE[37536][C-00004eda] app_queue.c: Called DAHDI/156
[2022-04-01 13:59:42] VERBOSE[37536][C-00004eda] app_queue.c: DAHDI/156-1 is ringing
[2022-04-01 13:59:43] VERBOSE[37536][C-00004eda] app_queue.c: DAHDI/156-1 is ringing
The call is answer by the agent DAHDI/156
[2022-04-01 13:59:44] VERBOSE[37536][C-00004eda] app_queue.c: DAHDI/156-1 answered SIP/ag561-00006f00
[2022-04-01 13:59:44] VERBOSE[37536][C-00004eda] res_musiconhold.c: Stopped music on hold on SIP/ag561-00006f00
[2022-04-01 13:59:44] VERBOSE[38728][C-00004eda] bridge_channel.c: Channel DAHDI/156-1 joined 'simple_bridge' basic-bridge <26ee329f-2ef6-47e8-9f21-520b72066f99>
[2022-04-01 13:59:44] VERBOSE[37536][C-00004eda] bridge_channel.c: Channel SIP/ag561-00006f00 joined 'simple_bridge' basic-bridge <26ee329f-2ef6-
At 14:07:44 the agent DAHDI/156 Hangup
[2022-04-01 14:07:44] VERBOSE[38728][C-00004eda] bridge_channel.c: Channel DAHDI/156-1 left 'simple_bridge' basic-bridge <26ee329f-2ef6-47e8-9f21-520b72066f99>
[2022-04-01 14:07:44] VERBOSE[38728][C-00004eda] sig_analog.c: Hanging up on 'DAHDI/156-1'
[2022-04-01 14:07:44] VERBOSE[37536][C-00004eda] bridge_channel.c: Channel SIP/ag561-00006f00 left 'simple_bridge' basic-bridge <26ee329f-2ef6-47e8-9f21-520b72066f99>
[2022-04-01 14:07:44] VERBOSE[38728][C-00004eda] chan_dahdi.c: Hungup 'DAHDI/156-1'
SIP/ag561-00006f00 still on the call to answer the survey
[2022-04-01 14:07:45] VERBOSE[37536][C-00004eda] pbx.c: Executing [7699@queues:4] GotoIf("SIP/ag561-00006f00", "1?survey") in new stack
[2022-04-01 14:07:45] VERBOSE[37536][C-00004eda] pbx_builtins.c: Goto (queues,7699,7)
[2022-04-01 14:07:45] VERBOSE[37536][C-00004eda] pbx.c: Executing [7699@queues:7] Gosub("SIP/ag561-00006f00", "4-6,s,1(DAHDI/156-1)") in new stack
[2022-04-01 14:07:45] VERBOSE[37536][C-00004eda] pbx.c: Executing [s@4-6:1] NoOp("SIP/ag561-00006f00", "==================== LINKEDID: 1648832270.64527 | SURVEY: 4 | QUESTION: 6 ====================") in new stack
[2022-04-01 14:07:45] VERBOSE[37536][C-00004eda] pbx.c: Executing [s@4-6:2] Set("SIP/ag561-00006f00", "PESQUISAID=1") in new stack
[2022-04-01 14:07:45] VERBOSE[37536][C-00004eda] pbx.c: Executing [s@4-6:3] GotoIf("SIP/ag561-00006f00", "1?answer") in new stack
[2022-04-01 14:07:45] VERBOSE[37536][C-00004eda] pbx_builtins.c: Goto (4-6,s,6)
[2022-04-01 14:07:45] VERBOSE[37536][C-00004eda] pbx.c: Executing [s@4-6:6] Answer("SIP/ag561-00006f00", "") in new stack
[2022-04-01 14:07:45] VERBOSE[37536][C-00004eda] pbx.c: Executing [s@4-6:7] BackGround("SIP/ag561-00006f00", "/var/lib/asterisk/sounds/pt_BR/custom/audio_2") in new stack
[2022-04-01 14:07:45] DEBUG[37536][C-00004eda] format_wav.c: Skipping unknown block 'LIST'
[2022-04-01 14:07:45] VERBOSE[37536][C-00004eda] file.c: <SIP/ag561-00006f00> Playing '/var/lib/asterisk/sounds/pt_BR/custom/audio_2.slin' (language 'pt_BR')
[2022-04-01 14:07:50] DTMF[37536][C-00004eda] channel.c: DTMF begin '6' received on SIP/ag561-00006f00
[2022-04-01 14:07:50] DTMF[37536][C-00004eda] channel.c: DTMF begin ignored '6' on SIP/ag561-00006f00
[2022-04-01 14:07:50] DTMF[37536][C-00004eda] channel.c: DTMF end '6' received on SIP/ag561-00006f00, duration 255 ms
[2022-04-01 14:07:50] DTMF[37536][C-00004eda] channel.c: DTMF end passthrough '6' on SIP/ag561-00006f00
[2022-04-01 14:07:50] VERBOSE[37536][C-00004eda] pbx.c: Executing [6@4-6:1] Set("SIP/ag561-00006f00", "ODBC_PESQUISA()=6,5135814886,1648832270.64527,s,2022-04-01 14:07:45,6,DAHDI/156-1,1648832270.64527.wav") in new stack
[2022-04-01 14:07:50] VERBOSE[37536][C-00004eda] pbx.c: Executing [6@4-6:2] Wait("SIP/ag561-00006f00", "2") in new stack
[2022-04-01 14:07:52] VERBOSE[37536][C-00004eda] pbx.c: Executing [6@4-6:3] Playback("SIP/ag561-00006f00", "auth-thankyou") in new stack
[2022-04-01 14:07:52] VERBOSE[37536][C-00004eda] file.c: <SIP/ag561-00006f00> Playing 'auth-thankyou.slin' (language 'pt_BR')
[2022-04-01 14:07:53] VERBOSE[37536][C-00004eda] pbx.c: Executing [6@4-6:4] Busy("SIP/ag561-00006f00", "") in new stack
Side A (caller) hangup at 14:07:56
[2022-04-01 14:07:56] VERBOSE[37536][C-00004eda] pbx.c: Spawn extension (4-6, 6, 4) exited non-zero on 'SIP/ag561-00006f00'
[2022-04-01 14:07:56] VERBOSE[37537][C-00004eda] app_mixmonitor.c: MixMonitor close filestream (mixed)
[2022-04-01 14:07:57] VERBOSE[37537][C-00004eda] app_mixmonitor.c: End MixMonitor Recording SIP/ag561-00006f00
As the agent hangup is expected that event is set as COMPLETEAGENT but it is set as COMPLETECALLER and at the “wrong” time, 14:07:56.
SELECT * FROM queue_log WHERE callid = '1648832270.64527' ORDER BY time;
time | callid | queuename | agent | event | data1 | data2 | data3 | data4 | data5 | id | peer | name
----------------------------+------------------+-----------------+-----------+----------------+-------+------------------+-------+-------+-------+---------+------+----------------
2022-04-01 13:57:50.693107 | 1648832270.64527 | ura-informatica | NONE | ENTERQUEUE | | 5135814886 | 2 | | | 1169169 | |
2022-04-01 13:59:44.568842 | 1648832270.64527 | ura-informatica | DAHDI/156 | CONNECT | 114 | 1648832382.64672 | 2 | | | 1169180 | 7626 | Rafa - Emanuel
2022-04-01 14:07:56.906998 | 1648832270.64527 | ura-informatica | DAHDI/156 | COMPLETECALLER | 114 | 492 | 2 | | | 1169209 | 7626 | Rafa - Emanuel
That is not a problem that occurs always, but is happen with some frequency, why is that happening? what can I do to prevent it from happening, is it a Bug?
Asterisk: 16.24.1
SO: Debian 9
PSQL: 9.6