Summary: | ASTERISK-27065: call hangup after leaving app_queue | ||||
Reporter: | Marek Cervenka (cervajs) | Labels: | |||
Date Opened: | 2017-06-19 07:15:39 | Date Closed: | 2017-07-06 11:17:15 | ||
Priority: | Major | Regression? | |||
Status: | Closed/Complete | Components: | Applications/app_queue | ||
Versions: | 13.16.0 | Frequency of Occurrence | Constant | ||
Related Issues: |
| ||||
Environment: | centos 7 64bit module CDR unloaded queue_log to Sqlite via realtime | Attachments: | ( 0) revert_app_queue_duplicate.patch | ||
Description: | call hangup after leaving queue testA
dynamic agent paused in testA with unavailable device extensions.conf exten => _[*+#0-9].,n,Queue(testA,rt,,,20) exten => _[*+#0-9].,n,Queue(testB,rt,,,20) works ok in 13.15.0 | ||||
Comments: | By: Asterisk Team (asteriskteam) 2017-06-19 07:15:39.988-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: Benjamin Keith Ford (bford) 2017-06-19 11:58:22.611-0500 Hello [~cervajs], are you picking up the call for queue testA? If you are, then you will need the 'c' option with your 'rt' options so that the caller will continue in the dialplan after the callee hangs up. These options can be found on the wiki [1]. If you are not picking up the call for testA and letting it ring, queue testB should be entered next, and this is the behavior I see when trying to reproduce the issue. If your issue persists, please supply more information, such as your queues.conf and whether you are using sip or pjsip. [1] https://wiki.asterisk.org/wiki/display/AST/Asterisk+13+Application_Queue By: Marek Cervenka (cervajs) 2017-06-19 13:44:03.992-0500 not picking testA chan_sip testA = SUP_5006_a [SUP_5006_a] musicclass=default strategy=linear timeout=15 retry=5 timeoutpriority=app setinterfacevar=no setqueueentryvar=no random-periodic-announce=no announce-holdtime=yes announce-position=no leavewhenempty=paused,penalty,invalid reportholdtime=no ringinuse=yes dialplan -- Executing [111@capp-Sup_5006:7] Queue("SIP/test_zm-00000007", "SUP_5006_a,rt,,,20") in new stack [Jun 19 13:59:02] DEBUG[9772][C-00000007]: app_queue.c:7951 queue_exec: queue: SUP_5006_a, options: rt, url: , announce: , timeout: 20, agi: , macro: , gosub: , rule: , position: [Jun 19 13:59:02] DEBUG[9772][C-00000007]: app_queue.c:7981 queue_exec: NO QUEUE_PRIO variable found. Using default. [Jun 19 13:59:02] DEBUG[9772][C-00000007]: app_queue.c:8033 queue_exec: queue: SUP_5006_a, expires: 1497873562, priority: 0 [Jun 19 13:59:02] DEBUG[9772][C-00000007]: app_queue.c:3617 update_realtime_members: Queue SUP_5006_a has no realtime members defined. No need for update [Jun 19 13:59:02] DEBUG[9772][C-00000007]: app_queue.c:3732 join_queue: Queue 'SUP_5006_a' Join, Channel 'SIP/test_zm-00000007', Position '1' [Jun 19 13:59:02] DEBUG[9772][C-00000007]: app_queue.c:5304 is_our_turn: There are 0 available members. [Jun 19 13:59:02] DEBUG[9772][C-00000007]: app_queue.c:5322 is_our_turn: It's not our turn (SIP/test_zm-00000007). [Jun 19 13:59:02] DEBUG[9772][C-00000007]: app_queue.c:3617 update_realtime_members: Queue SUP_5006_a has no realtime members defined. No need for update [Jun 19 13:59:02] DEBUG[9772][C-00000007]: app_queue.c:4012 leave_queue: Queue 'SUP_5006_a' Leave, Channel 'SIP/test_zm-00000007' == Spawn extension (capp-Sup_5006, 111, 7) exited non-zero on 'SIP/test_zm-00000007' -- Executing [h@capp-Sup_5006:1] NoOp("SIP/test_zm-00000007", "qs LEAVEEMPTY") in new stack -- Executing [h@capp-Sup_5006:2] Hangup("SIP/test_zm-00000007", "") in new stack @Benjamin Keith Ford are you saying you cant replicate the problem? By: Marek Cervenka (cervajs) 2017-06-19 15:00:35.426-0500 another debug log from 13.16.0 [Jun 19 21:55:30] DEBUG[12173][C-00000002] app_queue.c: There are 0 available members. [Jun 19 21:55:30] DEBUG[12173][C-00000002] app_queue.c: It's not our turn (SIP/test_zm-00000002). [Jun 19 21:55:30] DEBUG[12173][C-00000002] app_queue.c: Queue SUP_5006_a has no realtime members defined. No need for update [Jun 19 21:55:30] DEBUG[12173][C-00000002] res_config_sqlite3.c: DB: cdrDb SQL: PRAGMA table_info("queue_log") [Jun 19 21:55:30] DEBUG[12173][C-00000002] res_config_sqlite3.c: DB: cdrDb SQL: INSERT INTO "queue_log" ("time", "data5", "data4", "data3", "data2", "data1", "event", "agent", "queuename", "callid") VALUES ('2017-06-19 21:55:30.058603', '', '', '0', '1', '1', 'EXITEMPTY', 'NONE', 'SUP_5006_a', '1497902129.22') [Jun 19 21:55:30] DEBUG[12173][C-00000002] app_queue.c: Queue 'SUP_5006_a' Leave, Channel 'SIP/test_zm-00000002' [Jun 19 21:55:30] DEBUG[12173][C-00000002] pbx.c: Spawn extension (capp-Sup_5006,111,7) exited non-zero on 'SIP/test_zm-00000002' [Jun 19 21:55:30] VERBOSE[12173][C-00000002] pbx.c: Spawn extension (capp-Sup_5006, 111, 7) exited non-zero on 'SIP/test_zm-00000002' [Jun 19 21:55:30] DEBUG[12173][C-00000002] channel.c: Soft-Hanging (0x10) up channel 'SIP/test_zm-00000002' [Jun 19 21:55:30] DEBUG[12173][C-00000002] channel.c: Soft-Hanging (0x80) up channel 'SIP/test_zm-00000002' [Jun 19 21:55:30] DEBUG[12173][C-00000002] pbx.c: Launching 'Gosub' [Jun 19 21:55:30] VERBOSE[12173][C-00000002] pbx.c: Executing [h@capp-Sup_5006:1] Gosub("SIP/test_zm-00000002", "extended_CDR,s,1") in new stack [Jun 19 21:55:30] DEBUG[12173][C-00000002] pbx.c: Launching 'NoOp' By: Benjamin Keith Ford (bford) 2017-06-19 15:08:28.782-0500 [~cervajs], I have not been able to replicate the problem. The call continues to the next queue in the dialplan. I'm assuming you are adding your queue members dynamically through the CLI or through a dialplan extension? Could you also supply your extensions.conf as an attachment to the issue? Also, do your queues show what you expect when you run 'queue show' in Asterisk? By: Marek Cervenka (cervajs) 2017-06-19 15:15:24.229-0500 debug log from asterisk 13.15.0 - the same configuration - WORKS OK [Jun 19 22:05:35] VERBOSE[12537][C-00000001] pbx.c: Executing [111@capp-Sup_5006:7] Queue("SIP/test_zm-00000001", "SUP_5006_a,rt,,,20") in new stack [Jun 19 22:05:35] DEBUG[12537][C-00000001] app_queue.c: queue: SUP_5006_a, options: rt, url: , announce: , timeout: 20, agi: , macro: , gosub: , rule: , position: [Jun 19 22:05:35] DEBUG[12537][C-00000001] app_queue.c: NO QUEUE_PRIO variable found. Using default. [Jun 19 22:05:35] DEBUG[12537][C-00000001] app_queue.c: queue: SUP_5006_a, expires: 1497902755, priority: 0 [Jun 19 22:05:35] DEBUG[12537][C-00000001] app_queue.c: Queue SUP_5006_a has no realtime members defined. No need for update [Jun 19 22:05:35] DEBUG[12537][C-00000001] app_queue.c: Queue 'SUP_5006_a' Join, Channel 'SIP/test_zm-00000001', Position '1' [Jun 19 22:05:35] DEBUG[12537][C-00000001] res_config_sqlite3.c: DB: cdrDb SQL: PRAGMA table_info("queue_log") [Jun 19 22:05:35] DEBUG[12537][C-00000001] res_config_sqlite3.c: DB: cdrDb SQL: INSERT INTO "queue_log" ("time", "data5", "data4", "data3", "data2", "data1", "event", "agent", "queuename", "callid") VALUES ('2017-06-19 22:05:35.499331', '', '', '1', '575750920', '', 'ENTERQUEUE', 'NONE', 'SUP_5006_a', '1497902735.11') [Jun 19 22:05:35] DEBUG[12537][C-00000001] channel.c: Driver for channel 'SIP/test_zm-00000001' does not support indication 3, emulating it [Jun 19 22:05:35] DEBUG[12537][C-00000001] channel.c: Channel SIP/test_zm-00000001 setting write format path: slin -> alaw [Jun 19 22:05:35] DEBUG[12537][C-00000001] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 19 22:05:35] DEBUG[12537][C-00000001] app_queue.c: There are 0 available members. [Jun 19 22:05:35] DEBUG[12537][C-00000001] app_queue.c: It's not our turn (SIP/test_zm-00000001). [Jun 19 22:05:35] DEBUG[12537][C-00000001] app_queue.c: Queue SUP_5006_a has no realtime members defined. No need for update [Jun 19 22:05:35] DEBUG[12537][C-00000001] res_config_sqlite3.c: DB: cdrDb SQL: PRAGMA table_info("queue_log") [Jun 19 22:05:35] DEBUG[12537][C-00000001] res_config_sqlite3.c: DB: cdrDb SQL: INSERT INTO "queue_log" ("time", "data5", "data4", "data3", "data2", "data1", "event", "agent", "queuename", "callid") VALUES ('2017-06-19 22:05:35.499594', '', '', '0', '1', '1', 'EXITEMPTY', 'NONE', 'SUP_5006_a', '1497902735.11') [Jun 19 22:05:35] DEBUG[12537][C-00000001] app_queue.c: Queue 'SUP_5006_a' Leave, Channel 'SIP/test_zm-00000001' [Jun 19 22:05:35] DEBUG[12537][C-00000001] app_queue.c: SIP/test_zm-00000001 is trying to call a queue member. [Jun 19 22:05:35] DEBUG[12537][C-00000001] app_queue.c: Trying 'Local/201@route_phones_1' with metric 1000000 [Jun 19 22:05:35] DEBUG[12537][C-00000001] app_queue.c: Local/201@route_phones_1 paused, can't receive call [Jun 19 22:05:35] DEBUG[12537][C-00000001] app_queue.c: Nobody left to try ringing in queue [Jun 19 22:05:35] DEBUG[12537][C-00000001] app_queue.c: Everyone is busy at this time [Jun 19 22:05:35] DEBUG[12537][C-00000001] res_config_sqlite3.c: DB: cdrDb SQL: PRAGMA table_info("queue_log") [Jun 19 22:05:35] DEBUG[12537][C-00000001] res_config_sqlite3.c: DB: cdrDb SQL: INSERT INTO "queue_log" ("time", "data5", "data4", "data3", "data2", "data1", "event", "agent", "queuename", "callid") VALUES ('2017-06-19 22:05:35.499840', '', '', '0', '1', '1', 'EXITEMPTY', 'NONE', 'SUP_5006_a', '1497902735.11') [Jun 19 22:05:35] DEBUG[12537][C-00000001] channel.c: Channel SIP/test_zm-00000001 setting write format path: alaw -> alaw [Jun 19 22:05:35] DEBUG[12537][C-00000001] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jun 19 22:05:35] DEBUG[12537][C-00000001] pbx_variables.c: Function CHANNEL(state) result is 'Up' [Jun 19 22:05:35] DEBUG[12537][C-00000001] pbx_variables.c: Expression result is '0' [Jun 19 22:05:35] DEBUG[12537][C-00000001] pbx.c: Launching 'ExecIf' [Jun 19 22:05:35] VERBOSE[12537][C-00000001] pbx.c: Executing [111@capp-Sup_5006:8] ExecIf("SIP/test_zm-00000001", "0?Answer()") in new stack queue show SUP_5006_a has 0 calls (max unlimited) in 'linear' strategy (0s holdtime, 0s talktime), W:0, C:0, A:2, SL:0.0% within 0s Members: 201@domain.com (Local/201@route_phones_1 from hint:201@subscribe_1) with penalty 1 (ringinuse enabled) (dynamic) (paused) (Unavailable) has taken no calls yet No Callers By: Marek Cervenka (cervajs) 2017-06-19 15:16:54.851-0500 important missing point is about agent paused in SUP_5006_a ? By: Benjamin Keith Ford (bford) 2017-06-19 15:17:56.930-0500 Can you also provide what Asterisk shows when you run 'dialplan show 111@capp-Sup_5006'? By: Marek Cervenka (cervajs) 2017-06-19 15:25:20.422-0500 mc*CLI> dialplan show capp-Sup_5006 {noformat} [ Context 'capp-Sup_5006' created by 'pbx_config' ] 'h' => 1. Gosub(extended_CDR,s,1) [pbx_config] 2. Hangup() [pbx_config] '_[*+#0-9].' => 1. ipbxlog("${UNIQUEID} - ") [pbx_config] 2. Execif($["${CHANNEL(state)}" != "Up"]?Answer()) [pbx_config] 3. QueueLog(SUP_5006_a,${UNIQUEID},NONE,EXTENQUEUE,${EXTEN}) [pbx_config] 4. QueueLog(SUP_5006_a,${UNIQUEID},NONE,IVRQUEUE,${ipbx_ivrqueue}) [pbx_config] 5. Execif($["${ENABLE_AGENT_CUSTOM_DEVICE}" = "yes"]?Set(__IPBX_QUEUE_CALL=SUP_5006_a)) [pbx_config] 6. Set(_IPBX_QUEUE_NAME=SUP_5006_a) [pbx_config] 7. Queue(SUP_5006_a,rt,,,20) [pbx_config] 8. Execif($["${CHANNEL(state)}" != "Up"]?Answer()) [pbx_config] 9. QueueLog(SUP_5006_b,${UNIQUEID},NONE,EXTENQUEUE,${EXTEN}) [pbx_config] 10. QueueLog(SUP_5006_b,${UNIQUEID},NONE,IVRQUEUE,${ipbx_ivrqueue}) [pbx_config] 11. Execif($["${ENABLE_AGENT_CUSTOM_DEVICE}" = "yes"]?Set(__IPBX_QUEUE_CALL=SUP_5006_b)) [pbx_config] 12. Set(_IPBX_QUEUE_NAME=SUP_5006_b) [pbx_config] 13. Queue(SUP_5006_b,rt,,,20) [pbx_config] 14. Return() [pbx_config] {noformat} By: Benjamin Keith Ford (bford) 2017-06-19 15:45:32.339-0500 Before calling this extension, if your queue agent shows as paused or Unavailable, then it will be unable to take calls. This seems to be a problem with your sip endpoint rather than the queues, which would explain why it does not work in 13.15.0 now. By: Marek Cervenka (cervajs) 2017-06-19 15:56:57.135-0500 please check and compare debug logs from 13.15.0 vs 13.16.0 there must be some change, because with exactly same config it behaves differently [Jun 19 13:59:02] DEBUG[9772][C-00000007]: app_queue.c:4012 leave_queue: Queue 'SUP_5006_a' Leave, Channel 'SIP/test_zm-00000007' == Spawn extension (capp-Sup_5006, 111, 7) exited non-zero on 'SIP/test_zm-00000007' while calling channel exited non-zero? can you try with dynamic paused agent with unavailable device? By: Marek Cervenka (cervajs) 2017-06-19 16:03:08.246-0500 paused isnt the problem SUP_5006_b has 0 calls (max unlimited) in 'linear' strategy (0s holdtime, 0s talktime), W:0, C:0, A:0, SL:0.0% within 0s Members: 202@domena.cz (Local/202@route_phones_1 from hint:202@subscribe_1) with penalty 1 (ringinuse enabled) (dynamic) (Unavailable) has taken no calls yet No Callers -- Executing [910104219@capp-Sup_5006:7] Queue("SIP/test_zm-00000003", "SUP_5006_a,rt,,,20") in new stack [Jun 19 22:58:48] DEBUG[12834][C-00000003]: app_queue.c:7951 queue_exec: queue: SUP_5006_a, options: rt, url: , announce: , timeout: 20, agi: , macro: , gosub: , rule: , position: [Jun 19 22:58:48] DEBUG[12834][C-00000003]: app_queue.c:7981 queue_exec: NO QUEUE_PRIO variable found. Using default. [Jun 19 22:58:48] DEBUG[12834][C-00000003]: app_queue.c:8033 queue_exec: queue: SUP_5006_a, expires: 1497905948, priority: 0 [Jun 19 22:58:48] DEBUG[12834][C-00000003]: app_queue.c:3617 update_realtime_members: Queue SUP_5006_a has no realtime members defined. No need for update [Jun 19 22:58:48] DEBUG[12834][C-00000003]: app_queue.c:3732 join_queue: Queue 'SUP_5006_a' Join, Channel 'SIP/test_zm-00000003', Position '1' [Jun 19 22:58:48] DEBUG[12834][C-00000003]: app_queue.c:5304 is_our_turn: There are 0 available members. [Jun 19 22:58:48] DEBUG[12834][C-00000003]: app_queue.c:5322 is_our_turn: It's not our turn (SIP/test_zm-00000003). [Jun 19 22:58:48] DEBUG[12834][C-00000003]: app_queue.c:3617 update_realtime_members: Queue SUP_5006_a has no realtime members defined. No need for update [Jun 19 22:58:48] DEBUG[12834][C-00000003]: app_queue.c:4012 leave_queue: Queue 'SUP_5006_a' Leave, Channel 'SIP/test_zm-00000003' == Spawn extension (capp-Sup_5006, 111, 7) exited non-zero on 'SIP/test_zm-00000003' By: Marek Cervenka (cervajs) 2017-06-21 07:25:51.173-0500 replicated issue on clean new machine with make basic-pbx call from chan_sip - device 400 to exten 111 [test] exten => 111,1,noop(test) same = n,Answer() same = n,Queue(customer_advocate,,,,1200) same = n,noop(operator) [customer_advocate] strategy=ringall member => PJSIP/1101 ; Maria Berny - Director of Customer Experience member => PJSIP/1115 ; Dusty Williams - Customer Advocate member => PJSIP/1102 ; Tommy Briar - Customer Advocate leavewhenempty=paused,penalty,unavailable,invalid,unknown queue show customer_advocate has 0 calls (max unlimited) in 'ringall' strategy (0s holdtime, 0s talktime), W:0, C:0, A:0, SL:0.0% within 0s Members: PJSIP/1102 (ringinuse enabled) (Invalid) has taken no calls yet PJSIP/1101 (ringinuse enabled) (Invalid) has taken no calls yet PJSIP/1115 (ringinuse enabled) (Invalid) has taken no calls yet No Callers -- Executing [111@test:3] Queue("SIP/400-00000000", "customer_advocate,,,,1200") in new stack [Jun 21 14:19:19] DEBUG[1686][C-00000000]: app_queue.c:7946 queue_exec: queue: customer_advocate, options: , url: , announce: , timeout: 1200, agi: , macro: , gosub: , rule: , position: [Jun 21 14:19:19] DEBUG[1686][C-00000000]: app_queue.c:7976 queue_exec: NO QUEUE_PRIO variable found. Using default. [Jun 21 14:19:19] DEBUG[1686][C-00000000]: app_queue.c:8028 queue_exec: queue: customer_advocate, expires: 1498048759, priority: 0 [Jun 21 14:19:19] DEBUG[1686][C-00000000]: app_queue.c:3617 update_realtime_members: Queue customer_advocate has no realtime members defined. No need for update [Jun 21 14:19:19] DEBUG[1686][C-00000000]: app_queue.c:3732 join_queue: Queue 'customer_advocate' Join, Channel 'SIP/400-00000000', Position '1' [Jun 21 14:19:19] WARNING[1686][C-00000000]: config.c:3050 find_engine: Realtime mapping for 'queue_log' found to engine 'sqlite3', but the engine is not available -- Started music on hold, class 'default', on channel 'SIP/400-00000000' [Jun 21 14:19:19] DEBUG[1686][C-00000000]: channel.c:3478 ast_settimeout_full: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jun 21 14:19:19] DEBUG[1686][C-00000000]: app_queue.c:5299 is_our_turn: There are 0 available members. [Jun 21 14:19:19] DEBUG[1686][C-00000000]: app_queue.c:5317 is_our_turn: It's not our turn (SIP/400-00000000). [Jun 21 14:19:19] DEBUG[1686][C-00000000]: app_queue.c:3617 update_realtime_members: Queue customer_advocate has no realtime members defined. No need for update [Jun 21 14:19:19] DEBUG[1686][C-00000000]: app_queue.c:2213 get_member_status: PJSIP/1102 is unavailable because his device state is 'invalid' [Jun 21 14:19:19] DEBUG[1686][C-00000000]: app_queue.c:2213 get_member_status: PJSIP/1101 is unavailable because his device state is 'invalid' [Jun 21 14:19:19] DEBUG[1686][C-00000000]: app_queue.c:2213 get_member_status: PJSIP/1115 is unavailable because his device state is 'invalid' [Jun 21 14:19:19] WARNING[1686][C-00000000]: config.c:3050 find_engine: Realtime mapping for 'queue_log' found to engine 'sqlite3', but the engine is not available [Jun 21 14:19:19] DEBUG[1686][C-00000000]: app_queue.c:4012 leave_queue: Queue 'customer_advocate' Leave, Channel 'SIP/400-00000000' [Jun 21 14:19:19] DEBUG[1686][C-00000000]: pbx.c:4345 __ast_pbx_run: Spawn extension (test,111,3) exited non-zero on 'SIP/400-00000000' == Spawn extension (test, 111, 3) exited non-zero on 'SIP/400-00000000' [Jun 21 14:19:19] DEBUG[1686][C-00000000]: channel.c:2582 ast_softhangup_nolock: Soft-Hanging (0x10) up channel 'SIP/400-00000000' -- Stopped music on hold on SIP/400-00000000 [Jun 21 14:19:19] DEBUG[1686][C-00000000]: channel.c:2731 ast_hangup: Hanging up channel 'SIP/400-00000000' [Jun 21 14:19:19] DEBUG[1686][C-00000000]: chan_sip.c:7155 sip_hangup: Hangup call SIP/400-00000000, SIP callid 801acbd9b7334f45b8395391ebc9ffa0 [Jun 21 14:19:19] DEBUG[1686][C-00000000]: chan_sip.c:6768 update_call_counter: Updating call counter for incoming call By: Joshua C. Colp (jcolp) 2017-06-21 08:27:24.184-0500 This is a result of the change done for ASTERISK-25665. Reverting that makes it work as expected. By: Marek Cervenka (cervajs) 2017-06-21 10:11:19.793-0500 revert patch By: Benjamin Keith Ford (bford) 2017-06-26 14:16:31.466-0500 [~cervajs], did reverting the patch fix your issue? By: Ivan Poddubny (ipoddubny) 2017-06-27 00:42:21.420-0500 I'm sorry about the regression that was introduced in my patch for ASTERISK-25665. I'll post the fix to Gerrit later today. The problem is caused by app_queue returning -1 instead of 0 when leaving an empty queue. It just needs to be set back to 0 before returning. By: Marek Cervenka (cervajs) 2017-06-27 02:39:22.962-0500 Benjamin Keith Ford: yes |