Dropped call after dynamic agent login

Running FreePBX 2.8.1.3 / Asterisk (Ver. 1.4.21.2)

Our agents use a speed dial number to log in/out of the queue. A few times this happens:

  1. Customer is waiting in queue.
  2. Agent (606) presses speed dial to log in to the queue. (The agent only presses a single button and does not hang up the call.)
  3. The “log in” macro runs and then hangs up.
  4. The customer is routed to the agent, and the agent’s phone rings.
  5. The agent picks up the phone and there is dead air. The customer said that the call just cut off.

It seems to me the the “hangup()” at the end of the macro is somehow hanging up on the customer. Is that possible? I can’t reproduce it and it only happens occassionally, but I would like to solve it. I’d love to hear any suggestions or ideas.

At the moment it should start recording the call I see this message:
The device state of this queue member, Local/606@from-internal/n, is still ‘Not in Use’ when it probably should not be! Please check UPGRADE.txt for correct configuration settings.

As far as I can tell from my searches that is not a problem?

Is there any possibility that the hangup in the macro could be hanging up the call routed from the queue?

The macros:
CLI> dialplan show macro-csr-queue-toggle
[ Context ‘macro-csr-queue-toggle’ created by ‘pbx_config’ ]
‘s’ => 1. Wait(1) [pbx_config]
2. Macro(user-callerid) [pbx_config]
3. GotoIf($[ “${CALLERID(number)}” != “${AMPUSER}” ]?pstncall) [pbx_config]
4. Set(CALLBACKNUM=${AMPUSER}) [pbx_config]
5. Goto(add) [pbx_config]
[pstncall] 6. Set(CALLBACKNUM=${CALLER_EXT}) [pbx_config]
[add] 7. Macro(csr-queue-add|${ARG1}|${CALLBACKNUM}) [pbx_config]
8. GotoIf($["${CSR_QUEUE_ADD}" = “1”]?done) [pbx_config]
[del] 9. Macro(csr-queue-del|${ARG1}|${CALLBACKNUM}) [pbx_config]
10. GotoIf($["${CSR_QUEUE_DEL}" = “1”]?done) [pbx_config]
[fail] 11. SayDigits(${ARG2}) [pbx_config]
12. Playback(sorry-cant-let-you-do-that) [pbx_config]
[done] 13. Hangup() [pbx_config]

-= 1 extension (14 priorities) in 1 context. =-
CLI> dialplan show macro-csr-queue-add
[ Context ‘macro-csr-queue-add’ created by ‘pbx_config’ ]
‘s’ => 1. Wait(1) [pbx_config]
2. GotoIf($["${ARG2}" = “”]?fail)) [pbx_config]
3. AddQueueMember(${ARG1}|Local/${ARG2}@from-internal/n||) [pbx_config]
4. GotoIf($["${AQMSTATUS}" != “ADDED”]?fail) [pbx_config]
5. QueueLog(${UNIQUEID}|${ARG1}|${ARG2}|AGENTLOGIN|0) [pbx_config]
6. Set(DB(agentlogin/q_${ARG1}a${ARG2})=${EPOCH}) [pbx_config]
7. UserEvent(Agentlogin|Agent: ${ARG2}) [pbx_config]
8. Wait(1) [pbx_config]
9. SayDigits(${ARG2}) [pbx_config]
10. Playback(agent-loginok) [pbx_config]
11. SET(CSR_QUEUE_ADD=1) [pbx_config]
12. MacroExit() [pbx_config]
[fail] 13. SET(CSR_QUEUE_ADD=0) [pbx_config]

Below is the log.

[2012-02-01 08:44:30] DEBUG[10623] app_macro.c: Executed application: AddQueueMember
[2012-02-01 08:44:30] VERBOSE[10623] logger.c: – Executing [s@macro-csr-queue-add:4] GotoIf(“SIP/606-0a02f8d0”, “0?fail”) in new stack
[2012-02-01 08:44:30] DEBUG[10623] app_macro.c: Executed application: GotoIf
[2012-02-01 08:44:30] VERBOSE[10623] logger.c: – Executing [s@macro-csr-queue-add:5] QueueLog(“SIP/606-0a02f8d0”, “1328107468.34007|1000|606|AGENTLOGIN|0”) in new stack
[2012-02-01 08:44:30] DEBUG[10623] app_macro.c: Executed application: QueueLog
[2012-02-01 08:44:30] VERBOSE[10623] logger.c: – Executing [s@macro-csr-queue-add:6] Set(“SIP/606-0a02f8d0”, “DB(agentlogin/q_1000_a_606)=1328107470”) in new stack
[2012-02-01 08:44:30] DEBUG[10623] app_macro.c: Executed application: Set
[2012-02-01 08:44:30] VERBOSE[10623] logger.c: – Executing [s@macro-csr-queue-add:7] UserEvent(“SIP/606-0a02f8d0”, “Agentlogin|Agent: 606”) in new stack
[2012-02-01 08:44:30] DEBUG[10623] app_macro.c: Executed application: UserEvent
[2012-02-01 08:44:30] VERBOSE[10623] logger.c: – Executing [s@macro-csr-queue-add:8] Wait(“SIP/606-0a02f8d0”, “1”) in new stack
[2012-02-01 08:44:31] DEBUG[10623] app_macro.c: Executed application: Wait
[2012-02-01 08:44:31] VERBOSE[10623] logger.c: – Executing [s@macro-csr-queue-add:9] SayDigits(“SIP/606-0a02f8d0”, “606”) in new stack
[2012-02-01 08:44:31] VERBOSE[10623] logger.c: – <SIP/606-0a02f8d0> Playing ‘digits/6’ (language ‘en’)
[2012-02-01 08:44:32] VERBOSE[10623] logger.c: – <SIP/606-0a02f8d0> Playing ‘digits/0’ (language ‘en’)
[2012-02-01 08:44:32] VERBOSE[10503] logger.c: – Told IAX2/jnctn-12163 in 1000 their queue position (which was 1)
[2012-02-01 08:44:32] VERBOSE[10503] logger.c: – <IAX2/jnctn-12163> Playing ‘queue-thankyou’ (language ‘en’)
[2012-02-01 08:44:33] VERBOSE[10623] logger.c: – <SIP/606-0a02f8d0> Playing ‘digits/6’ (language ‘en’)
[2012-02-01 08:44:34] DEBUG[10623] app_macro.c: Executed application: SayDigits
[2012-02-01 08:44:34] VERBOSE[10623] logger.c: – Executing [s@macro-csr-queue-add:10] Playback(“SIP/606-0a02f8d0”, “agent-loginok”) in new stack
[2012-02-01 08:44:34] VERBOSE[10623] logger.c: – <SIP/606-0a02f8d0> Playing ‘agent-loginok’ (language ‘en’)
[2012-02-01 08:44:34] VERBOSE[10503] logger.c: – Started music on hold, class ‘default’, on IAX2/jnctn-12163
[2012-02-01 08:44:34] VERBOSE[10503] logger.c: – Local/606@from-internal-2c92,1 is busy
[2012-02-01 08:44:34] VERBOSE[10503] logger.c: – Nobody picked up in 0 ms
[2012-02-01 08:44:34] VERBOSE[10503] logger.c: – Local/605@from-internal-2e5d,1 is busy
[2012-02-01 08:44:34] VERBOSE[10503] logger.c: – Nobody picked up in 0 ms
[2012-02-01 08:44:34] DEBUG[10503] app_queue.c: Everyone is busy at this time
[2012-02-01 08:44:35] DEBUG[10623] app_macro.c: Executed application: Playback
[2012-02-01 08:44:35] VERBOSE[10623] logger.c: – Executing [s@macro-csr-queue-add:11] Set(“SIP/606-0a02f8d0”, “CSR_QUEUE_ADD=1”) in new stack
[2012-02-01 08:44:35] DEBUG[10623] app_macro.c: Executed application: SET
[2012-02-01 08:44:35] VERBOSE[10623] logger.c: – Executing [s@macro-csr-queue-add:12] MacroExit(“SIP/606-0a02f8d0”, “”) in new stack
[2012-02-01 08:44:35] DEBUG[10623] app_macro.c: Executed application: Macro
[2012-02-01 08:44:35] VERBOSE[10623] logger.c: – Executing [s@macro-csr-queue-toggle:8] GotoIf(“SIP/606-0a02f8d0”, “1?done”) in new stack
[2012-02-01 08:44:35] VERBOSE[10623] logger.c: – Goto (macro-csr-queue-toggle,s,13)

********* The macro hangup
[2012-02-01 08:44:35] DEBUG[10623] app_macro.c: Executed application: GotoIf

[2012-02-01 08:44:35] VERBOSE[10623] logger.c: – Executing [s@macro-csr-queue-toggle:13] Hangup(“SIP/606-0a02f8d0”, “”) in new stack

[2012-02-01 08:44:35] VERBOSE[10623] logger.c: == Spawn extension (macro-csr-queue-toggle, s, 13) exited non-zero on ‘SIP/606-0a02f8d0’ in macro ‘csr-queue-toggle’
[2012-02-01 08:44:35] VERBOSE[10623] logger.c: == Spawn extension (macro-csr-queue-toggle, s, 13) exited non-zero on ‘SIP/606-0a02f8d0’

********* 4 secs pass…

[2012-02-01 08:44:39] VERBOSE[10503] logger.c: – Local/606@from-internal-a1fa,1 is ringing
[2012-02-01 08:44:44] DEBUG[10503] app_queue.c: Dunno what to do with control type -1
[2012-02-01 08:44:44] VERBOSE[10503] logger.c: – Local/606@from-internal-a1fa,1 answered IAX2/jnctn-12163
[2012-02-01 08:44:44] VERBOSE[10503] logger.c: – Stopped music on hold on IAX2/jnctn-12163

*** Here it should Begin MixMonitor instead of exiting the queue ****

[2012-02-01 08:44:44] WARNING[10503] app_queue.c: The device state of this queue member, Local/606@from-internal/n, is still ‘Not in Use’ when it probably should not be! Please check UPGRADE.txt for correct configuration settings.
[2012-02-01 08:44:44] VERBOSE[10503] logger.c: == Spawn extension (ext-queues, 1000, 11) exited non-zero on ‘IAX2/jnctn-12163’
[2012-02-01 08:44:44] VERBOSE[10503] logger.c: – Executing [h@ext-queues:1] Macro(“IAX2/jnctn-12163”, “hangupcall|”) in new stack
[2012-02-01 08:44:44] VERBOSE[10503] logger.c: – Executing [s@macro-hangupcall:1] GotoIf(“IAX2/jnctn-12163”, “1?skiprg”) in new stack
[2012-02-01 08:44:44] VERBOSE[10503] logger.c: – Goto (macro-hangupcall,s,4)


[2012-02-01 08:44:44] DEBUG[10503] app_macro.c: Executed application: GotoIf
[2012-02-01 08:44:44] VERBOSE[10503] logger.c: – Executing [s@macro-hangupcall:4] GotoIf(“IAX2/jnctn-12163”, “0?skipblkvm”) in new stack
[2012-02-01 08:44:44] DEBUG[10503] app_macro.c: Executed application: GotoIf
[2012-02-01 08:44:44] VERBOSE[10503] logger.c: – Executing [s@macro-hangupcall:5] NoOp(“IAX2/jnctn-12163”, “Cleaning Up Block VM Flag: BLKVM/1000/IAX2/jnctn-12163”) in new stack

[2012-02-01 08:44:44] DEBUG[10503] app_macro.c: Executed application: Noop
[2012-02-01 08:44:44] DEBUG[10503] func_db.c: DB_DELETE: BLKVM/1000/IAX2/jnctn-12163 not found in database.
[2012-02-01 08:44:44] VERBOSE[10503] logger.c: – Executing [s@macro-hangupcall:6] NoOp(“IAX2/jnctn-12163”, "Deleting: BLKVM/1000/IAX2/jnctn-12163 ") in new stack
[2012-02-01 08:44:44] DEBUG[10503] app_macro.c: Executed application: Noop
[2012-02-01 08:44:44] VERBOSE[10503] logger.c: – Executing [s@macro-hangupcall:7] GotoIf(“IAX2/jnctn-12163”, “1?theend”) in new stack
[2012-02-01 08:44:44] VERBOSE[10503] logger.c: – Goto (macro-hangupcall,s,9)
[2012-02-01 08:44:44] DEBUG[10503] app_macro.c: Executed application: GotoIf
[2012-02-01 08:44:44] VERBOSE[10503] logger.c: – Executing [s@macro-hangupcall:9] Hangup(“IAX2/jnctn-12163”, “”) in new stack
[2012-02-01 08:44:44] VERBOSE[10503] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on ‘IAX2/jnctn-12163’ in macro ‘hangupcall’
[2012-02-01 08:44:44] VERBOSE[10503] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on ‘IAX2/jnctn-12163’
[2012-02-01 08:44:44] VERBOSE[10503] logger.c: – Hungup ‘IAX2/jnctn-12163’

I’ll try to summarize: is this possible?:

  1. You dial a feature code that runs a macro where the last statement is “hangup.”
  2. A call to the queue gets routed to your phone before you hang it up.
  3. The call disconnects because of the hangup in the macro.

?

Thanks!