Agent logged off, but Asterisk failed to process the logoff.

[AndyS]

QM 1.5.1 / Asterisk 1.4.22-rc5.

Agent logged off using "Log off" button in agent panel, however he still showed as logged in within Asterisk.  Logs show that Asterisk was trying to call that extension at the same time - perhaps this is related?  I manually logged the agent off but the customer is concerned about this event.


[Feb 23 14:01:57] VERBOSE[16969] logger.c:   == Manager 'admin' logged on from 127.0.0.1
[Feb 23 14:01:57] VERBOSE[16970] logger.c:     -- Executing [21@queuemetrics:1] Answer("Local/21@queuemetrics-2acd,2", "") in new stack
[Feb 23 14:01:57] VERBOSE[16970] logger.c:     -- Executing [21@queuemetrics:2] NoOp("Local/21@queuemetrics-2acd,2", " "QM: Logging off Agent/8109" ") in new stack
[Feb 23 14:01:57] VERBOSE[16970] logger.c:     -- Executing [21@queuemetrics:3] System("Local/21@queuemetrics-2acd,2", "asterisk -rx "agent logoff Agent/8109"") in new stack
[Feb 23 14:01:57] VERBOSE[16972] logger.c:     -- Executing [10@queuemetrics:1] Answer("Local/21@queuemetrics-2acd,1", "") in new stack
[Feb 23 14:01:57] VERBOSE[16972] logger.c:     -- Executing [10@queuemetrics:2] Wait("Local/21@queuemetrics-2acd,1", "10") in new stack
[Feb 23 14:01:57] VERBOSE[4314] logger.c:     -- Remote UNIX connection
[Feb 23 14:01:57] DEBUG[15295] chan_agent.c: Hungup, howlong is 0, autologoff is 0
[Feb 23 14:01:57] VERBOSE[15295] logger.c:   == Spawn extension (ext-queues, 8161, 20) exited non-zero on 'SIP/67.16.113.13-b79918c0'
[Feb 23 14:01:57] VERBOSE[15558] logger.c:   == End MixMonitor Recording SIP/67.16.113.13-b79918c0
[Feb 23 14:01:57] VERBOSE[15492] logger.c:   == Spawn extension (macro-dial, s, 7) exited non-zero on 'Local/8109@from-internal-1f22,2' in macro 'dial'
[Feb 23 14:01:57] VERBOSE[15492] logger.c:   == Spawn extension (macro-dial, s, 7) exited non-zero on 'Local/8109@from-internal-1f22,2' in macro 'exten-vm'
[Feb 23 14:01:57] VERBOSE[15492] logger.c:   == Spawn extension (macro-dial, s, 7) exited non-zero on 'Local/8109@from-internal-1f22,2'
[Feb 23 14:01:57] VERBOSE[15492] logger.c:     -- Executing [h@macro-dial:1] Macro("Local/8109@from-internal-1f22,2", "hangupcall") in new stack
[Feb 23 14:01:57] VERBOSE[15492] logger.c:     -- Executing [s@macro-hangupcall:1] ResetCDR("Local/8109@from-internal-1f22,2", "w") in new stack
[Feb 23 14:01:57] DEBUG[15492] app_macro.c: Executed application: ResetCDR
[Feb 23 14:01:57] VERBOSE[15492] logger.c:     -- Executing [s@macro-hangupcall:2] NoCDR("Local/8109@from-internal-1f22,2", "") in new stack
[Feb 23 14:01:57] DEBUG[15492] app_macro.c: Executed application: NoCDR
[Feb 23 14:01:57] VERBOSE[15492] logger.c:     -- Executing [s@macro-hangupcall:3] GotoIf("Local/8109@from-internal-1f22,2", "1?skiprg") in new stack
[Feb 23 14:01:57] VERBOSE[15492] logger.c:     -- Goto (macro-hangupcall,s,6)
[Feb 23 14:01:57] DEBUG[15492] app_macro.c: Executed application: GotoIf
[Feb 23 14:01:57] VERBOSE[15492] logger.c:     -- Executing [s@macro-hangupcall:6] GotoIf("Local/8109@from-internal-1f22,2", "1?skipblkvm") in new stack
[Feb 23 14:01:57] VERBOSE[15492] logger.c:     -- Goto (macro-hangupcall,s,9)
[Feb 23 14:01:57] DEBUG[15492] app_macro.c: Executed application: GotoIf
[Feb 23 14:01:57] VERBOSE[15492] logger.c:     -- Executing [s@macro-hangupcall:9] GotoIf("Local/8109@from-internal-1f22,2", "1?theend") in new stack
[Feb 23 14:01:57] VERBOSE[15492] logger.c:     -- Goto (macro-hangupcall,s,11)
[Feb 23 14:01:57] DEBUG[15492] app_macro.c: Executed application: GotoIf
[Feb 23 14:01:57] VERBOSE[15492] logger.c:     -- Executing [s@macro-hangupcall:11] Hangup("Local/8109@from-internal-1f22,2", "") in new stack
[Feb 23 14:01:57] VERBOSE[15492] logger.c:   == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'Local/8109@from-internal-1f22,2' in macro 'hangupcall'
[Feb 23 14:01:57] VERBOSE[15492] logger.c:   == Spawn extension (macro-hangupcall, s, 11) exited non-zero on 'Local/8109@from-internal-1f22,2'
[Feb 23 14:01:57] VERBOSE[16963] logger.c:   == Manager 'admin' logged off from 127.0.0.1
[Feb 23 14:01:58] VERBOSE[16973] logger.c:     -- Remote UNIX connection disconnected
[Feb 23 14:01:58] VERBOSE[16970] logger.c:     -- Executing [21@queuemetrics:4] Hangup("Local/21@queuemetrics-2acd,2", "") in new stack
[Feb 23 14:01:58] VERBOSE[16970] logger.c:   == Spawn extension (queuemetrics, 21, 4) exited non-zero on 'Local/21@queuemetrics-2acd,2'
[Feb 23 14:01:58] VERBOSE[16972] logger.c:   == Spawn extension (queuemetrics, 10, 2) exited non-zero on 'Local/21@queuemetrics-2acd,1'
[Feb 23 14:02:00] VERBOSE[16969] logger.c:   == Manager 'admin' logged off from 127.0.0.1
[Feb 23 14:02:01] VERBOSE[16990] logger.c:   == Parsing '/etc/asterisk/manager.conf': [Feb 23 14:02:01] VERBOSE[16990] logger.c: Found
[Feb 23 14:02:01] VERBOSE[16990] logger.c:   == Parsing '/etc/asterisk/manager_additional.conf': [Feb 23 14:02:01] VERBOSE[16990] logger.c: Found
[Feb 23 14:02:01] VERBOSE[16990] logger.c:   == Parsing '/etc/asterisk/manager_custom.conf': [Feb 23 14:02:01] VERBOSE[16990] logger.c: Found
[Feb 23 14:02:01] VERBOSE[16990] logger.c:   == Parsing '/etc/asterisk/users.conf': [Feb 23 14:02:01] VERBOSE[16990] logger.c: Found
[Feb 23 14:02:01] NOTICE[16990] manager.c: 127.0.0.1 tried to authenticate with nonexistent user 'sendcron'
[Feb 23 14:02:01] VERBOSE[16992] logger.c:   == Parsing '/etc/asterisk/manager.conf': [Feb 23 14:02:01] VERBOSE[16992] logger.c: Found
[Feb 23 14:02:01] VERBOSE[16992] logger.c:   == Parsing '/etc/asterisk/manager_additional.conf': [Feb 23 14:02:01] VERBOSE[16992] logger.c: Found
[Feb 23 14:02:01] VERBOSE[16992] logger.c:   == Parsing '/etc/asterisk/manager_custom.conf': [Feb 23 14:02:01] VERBOSE[16992] logger.c: Found
[Feb 23 14:02:01] VERBOSE[16992] logger.c:   == Parsing '/etc/asterisk/users.conf': [Feb 23 14:02:01] VERBOSE[16992] logger.c: Found
[Feb 23 14:02:01] NOTICE[16992] manager.c: 127.0.0.1 tried to authenticate with nonexistent user 'sendcron'
[Feb 23 14:02:02] VERBOSE[16990] logger.c:   == Connect attempt from '127.0.0.1' unable to authenticate
[Feb 23 14:02:02] VERBOSE[16992] logger.c:   == Connect attempt from '127.0.0.1' unable to authenticate
[Feb 23 14:02:02] VERBOSE[17017] logger.c:   == Parsing '/etc/asterisk/manager.conf': [Feb 23 14:02:02] VERBOSE[17017] logger.c: Found
[Feb 23 14:02:02] VERBOSE[17017] logger.c:   == Parsing '/etc/asterisk/manager_additional.conf': [Feb 23 14:02:02] VERBOSE[17017] logger.c: Found
[Feb 23 14:02:02] VERBOSE[17017] logger.c:   == Parsing '/etc/asterisk/manager_custom.conf': [Feb 23 14:02:02] VERBOSE[17017] logger.c: Found
[Feb 23 14:02:02] VERBOSE[17017] logger.c:   == Parsing '/etc/asterisk/users.conf': [Feb 23 14:02:02] VERBOSE[17017] logger.c: Found
[Feb 23 14:02:02] NOTICE[17017] manager.c: 127.0.0.1 tried to authenticate with nonexistent user 'listencron'
[Feb 23 14:02:02] VERBOSE[17019] logger.c:   == Parsing '/etc/asterisk/manager.conf': [Feb 23 14:02:02] VERBOSE[17019] logger.c: Found
[Feb 23 14:02:02] VERBOSE[17019] logger.c:   == Parsing '/etc/asterisk/manager_additional.conf': [Feb 23 14:02:02] VERBOSE[17019] logger.c: Found
[Feb 23 14:02:02] VERBOSE[17019] logger.c:   == Parsing '/etc/asterisk/manager_custom.conf': [Feb 23 14:02:02] VERBOSE[17019] logger.c: Found
[Feb 23 14:02:02] VERBOSE[17019] logger.c:   == Parsing '/etc/asterisk/users.conf': [Feb 23 14:02:02] VERBOSE[17019] logger.c: Found
[Feb 23 14:02:02] NOTICE[17019] manager.c: 127.0.0.1 tried to authenticate with nonexistent user 'updatecron'
[Feb 23 14:02:03] VERBOSE[17017] logger.c:   == Connect attempt from '127.0.0.1' unable to authenticate
[Feb 23 14:02:03] VERBOSE[17019] logger.c:   == Connect attempt from '127.0.0.1' unable to authenticate
[Feb 23 14:02:16] VERBOSE[4594] logger.c:     -- Unregistered SIP '8109'


What can we do to prevent this happening in the future?

Regards, Andrew.

[QueueMetrics]

It seems to have correctly run the command:

Code: [Select]

asterisk -rx "agent logoff Agent/8109"
Of course this only works if your agent was Agent/8109; if it was - say - SIP/8109, you have to edit the dialplan in order to run the correct logo-off command.

[AndyS]

I agree that it ran the command, and the agent was Agent/8109, but although the command was issued it never completed successfully as the agent remained logged on in Asterisk (I had to do a manual agent logoff to remove them).

Andrew.

[QueueMetrics]

Is the problem you are experiencing happening always or just sometimes?