[Home]

Summary:ASTERISK-13566: [patch] func_devstate not updating Custom hints, and not in sync with ASTDB
Reporter:Alec Davis (alecdavis)Labels:
Date Opened:2009-02-11 22:53:17.000-0600Date Closed:2009-02-25 10:51:51.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Functions/func_devstate
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) bug14461.diff2.txt
Description:astdb is always being updated, but sometimes hints are not.
It's not consistant, as I type this bug, it will come right and work correctly for a while, then go wrong.

astrid*CLI> database show CustomDevstate
...
/CustomDevstate/q8501_a8512                       : INUSE
...

astrid*CLI> core show hints
           8501GXP0001@BLF_Group_1         : Custom:q8501_a8512    State:Idle            Watchers  1

further manipulation from the command line.

astrid*CLI> devstate change Custom:q8501_a8512 NOT_INUSE
Changing q8501_a8512 to NOT_INUSE
 == Extension Changed 8501GXP0001[BLF_Group_1] new state InUse for Notify User GXP0001

astrid*CLI> devstate change Custom:q8501_a8512 INUSE
Changing q8501_a8512 to INUSE
 == Extension Changed 8501GXP0001[BLF_Group_1] new state Idle for Notify User GXP0001

But the weirdest thing, the BLF lamp on the phone comes right after approx 35 seconds, but still the Hint is incorrect.




****** ADDITIONAL INFORMATION ******

related: http://bugs.digium.com/view.php?id=11733

macro we use to login agent in and out.

[macro-custom-agent-inout]
;
; Standard extension macro:
;   ${ARG1} - Queue to Join
;
exten => s,1,Answer(0.3)
exten => s,n,MYSQL(Connect connid localhost asterisk asterisk asterisk)
exten => s,n,MYSQL(Query resultid ${connid} SELECT channel, extension, name FROM pbx WHERE cid_num='${MACRO_EXTEN:4}')
exten => s,n,MYSQL(Fetch fetchid ${resultid} channelpath CALLBACKNUM callername)
exten => s,n,MYSQL(Clear ${resultid})
exten => s,n,MYSQL(Disconnect ${connid})
exten => s,n,NoOp(MACRO_EXTEN=${MACRO_EXTEN:4} CALLBACKNUM=${CALLBACKNUM} channelpath=${channelpath} callername=${callername})
exten => s,n,AddQueueMember(${ARG1})
;If they're already logged in, log off
exten => s,n,GotoIf($["${AQMSTATUS}" = "MEMBERALREADY"]?a2)
exten => s,n,Set(DEVICE_STATE(Custom:q${MACRO_EXTEN:0:4}_a${CALLBACKNUM})=INUSE)
exten => s,n,UserEvent(Agentlogin,Agent: ${CALLBACKNUM})
exten => s,n,SendText(${ARG1} LOGIN)
exten => s,n,Playback(agent-loginok)
exten => s,n,Hangup()

exten => s,n(a2),RemoveQueueMember(${ARG1})
exten => s,n,Set(DEVICE_STATE(Custom:q${MACRO_EXTEN:0:4}_a${CALLBACKNUM})=NOT_INUSE)
exten => s,n,UserEvent(Agentlogoff,Agent: ${CALLBACKNUM})
exten => s,n,SendText(${ARG1} LOGOFF)
exten => s,n,Playback(agent-loggedoff)
exten => s,n,Hangup()
Comments:By: Alec Davis (alecdavis) 2009-02-12 03:45:41.000-0600

uploaded bug14461.diff.txt

handle_statechange is looking for an "&" in the hint extension and being Custom extension it never finds one.

the hint->exten return is "Custom:q8501_a8520"

It works for me, but probably this is only a pointer to where the problem may lie.

looking at ast_hint_state_changed in asterisk 1.2 http://svn.digium.com/view/asterisk/branches/1.2/pbx.c?revision=62737&view=markup it's clearly different.

Asterisk 1.4 and 1.6 are the same, both with the same reported problem.


By: Russell Bryant (russell) 2009-02-12 09:20:22.000-0600

I don't think the patch is valid.  Even if the string doesn't have a '&' in it, the loop will still execute one time on the entire string.
By: Alec Davis (alecdavis) 2009-02-12 11:10:53.000-0600

I agree, it's not valid, but I ran out of time to fix it.

A thought: regarding the BLF lamp actually reflecting the right state, but hint being wrong, albeit after 35 seconds (perhaps BLF subscription renewing), has me thinking there may be 2 places that notify the device. 1st one I have not found, and the 2nd one is were we are now, that I've forced to work.


By: Alec Davis (alecdavis) 2009-02-13 04:09:17.000-0600

please remove bug14461.diff.txt
uploaded bug14461.diff2.txt

I think this is as far as I can get.

The problem is that 'main/devicestate.c:_ast_device_state' returns the cached CustomDevice state, there's a race condition, the cache is not being updated fast enough.

Sometimes the cache is queried by '_ast_device_state' before it's updated.

The cache is updated by ''main/devicestate.c:devstate_event' which is called from 'ast_devstate_changed_literal', which has to be executed before '_ast_device_state'.

SO. the workaround, is to not use the cache for Custom DeviceStates, and let '_ast_device_state' get if from 'getproviderstate(provider, number)'

working console output with some extra debug:

[Feb 13 22:38:57] NOTICE[25204]: func_devstate.c:132 devstate_write: DEVICE_STATE function state=1 for device q8501_a8520
[Feb 13 22:38:57] NOTICE[25204]: devicestate.c:584 ast_devstate_changed_literal: state=1 for device Custom:q8501_a8520
[Feb 13 22:38:57] NOTICE[25204]: devicestate.c:546 devstate_event: cache state=1 for device Custom:q8501_a8520
[Feb 13 22:38:57] NOTICE[25174]: devicestate.c:346 _ast_device_state: provider for "Custom" - number:=q8501_a8520 state=1 device=Custom:q8501_a8520
[Feb 13 22:38:57] NOTICE[25172]: devicestate.c:750 process_collection: cache state=1 for device Custom:q8501_a8520
By: Alec Davis (alecdavis) 2009-02-13 04:21:49.000-0600

and for the record.
without the workaround. Less than a minute after asterisk was started, and only 2 BLF key presses later and it is wrong.

Each press of the same BLF key toggles a unique Device_State, one for each queue+phone, we use it to indicate to an agent whether they are logged into a queue or not, in this bug report the queue is '8501' and extension is '8520'.

Patches have been manually applied from latest trunk regarding inuse and inringing going negative.

Asterisk SVN-trunk-r174327M, Copyright (C) 1999 - 2008 Digium, Inc. and others.
Created by Mark Spencer <markster@digium.com>
Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details.
This is free software, with components licensed under the GNU General Public
License version 2 and other licenses; you are welcome to redistribute it under
certain conditions. Type 'core show license' for details.
=========================================================================
[ Booting...
[ Reading Master Configuration ]
[ Initializing Custom Configuration Options ]
Connected to Asterisk SVN-trunk-r174327M currently running on astrid (pid = 26587)
[Feb 13 23:18:03] NOTICE[26587]: loader.c:874 load_modules: 167 modules will be loaded.
....SNIP....

***BLF REGISTERING
[Feb 13 23:18:36] NOTICE[26602]: devicestate.c:346 _ast_device_state: provider for "Custom" - number:=q8501_a8520 state=1 device=Custom:q8501_a8520
[Feb 13 23:18:36] NOTICE[26602]: devicestate.c:346 _ast_device_state: provider for "Custom" - number:=q8501_a8520 state=1 device=Custom:q8501_a8520

*** FIRST BLF KEY PRESS. (Agent login), BLF Lights. Correct
[Feb 13 23:18:40] NOTICE[26629]: func_devstate.c:131 devstate_write: ---------------------------------------------------------------
[Feb 13 23:18:40] NOTICE[26629]: func_devstate.c:132 devstate_write: DEVICE_STATE function state=2 for device q8501_a8520
[Feb 13 23:18:40] NOTICE[26629]: devicestate.c:584 ast_devstate_changed_literal: state=2 for device Custom:q8501_a8520
[Feb 13 23:18:40] NOTICE[26600]: devicestate.c:346 _ast_device_state: provider for "Custom" - number:=q8501_a8520 state=2 device=Custom:q8501_a8520
[Feb 13 23:18:40] NOTICE[26597]: devicestate.c:750 process_collection: cache state=2 for device Custom:q8501_a8520
[Feb 13 23:18:40] NOTICE[26600]: devicestate.c:324 _ast_device_state: Cached state=2 for device Custom:q8501_a8520
[Feb 13 23:18:40] NOTICE[26629]: devicestate.c:546 devstate_event: cache state=2 for device Custom:q8501_a8520

*** 2nd BLF KEY PRESS. (Agent logout) BLF stays lit. WRONG!!
[Feb 13 23:18:47] NOTICE[26630]: func_devstate.c:131 devstate_write: ---------------------------------------------------------------
[Feb 13 23:18:47] NOTICE[26630]: func_devstate.c:132 devstate_write: DEVICE_STATE function state=1 for device q8501_a8520
[Feb 13 23:18:47] NOTICE[26630]: devicestate.c:584 ast_devstate_changed_literal: state=1 for device Custom:q8501_a8520
[Feb 13 23:18:47] NOTICE[26630]: devicestate.c:546 devstate_event: cache state=1 for device Custom:q8501_a8520
[Feb 13 23:18:47] NOTICE[26600]: devicestate.c:324 _ast_device_state: Cached state=2 for device Custom:q8501_a8520
[Feb 13 23:18:47] NOTICE[26597]: devicestate.c:750 process_collection: cache state=1 for device Custom:q8501_a8520

*** BLF light comes right, 34 seocnds later
[Feb 13 23:19:21] NOTICE[26602]: devicestate.c:324 _ast_device_state: Cached state=1 for device Custom:q8501_a8520
[Feb 13 23:19:21] NOTICE[26602]: devicestate.c:324 _ast_device_state: Cached state=1 for device Custom:q8501_a8520
[Feb 13 23:20:06] NOTICE[26602]: devicestate.c:324 _ast_device_state: Cached state=1 for device Custom:q8501_a8520
[Feb 13 23:20:06] NOTICE[26602]: devicestate.c:324 _ast_device_state: Cached state=1 for device Custom:q8501_a8520
astrid*CLI>

***3rd BLF Key press. (Agent login), Light doesn't come on.
[Feb 13 23:25:33] NOTICE[26631]: func_devstate.c:131 devstate_write: ---------------------------------------------------------------
[Feb 13 23:25:33] NOTICE[26631]: func_devstate.c:132 devstate_write: DEVICE_STATE function state=2 for device q8501_a8520
[Feb 13 23:25:33] NOTICE[26631]: devicestate.c:584 ast_devstate_changed_literal: state=2 for device Custom:q8501_a8520
[Feb 13 23:25:33] NOTICE[26631]: devicestate.c:546 devstate_event: cache state=2 for device Custom:q8501_a8520
[Feb 13 23:25:33] NOTICE[26600]: devicestate.c:324 _ast_device_state: Cached state=1 for device Custom:q8501_a8520
[Feb 13 23:25:33] NOTICE[26600]: devicestate.c:324 _ast_device_state: Cached state=1 for device Custom:q8501_a8520
[Feb 13 23:25:33] NOTICE[26597]: devicestate.c:750 process_collection: cache state=2 for device Custom:q8501_a8520

*** 4th BLF key press, (Agent logout), Light should go out (but was already), But comes on.
[Feb 13 23:25:40] NOTICE[26632]: func_devstate.c:131 devstate_write: ---------------------------------------------------------------
[Feb 13 23:25:40] NOTICE[26632]: func_devstate.c:132 devstate_write: DEVICE_STATE function state=1 for device q8501_a8520
[Feb 13 23:25:40] NOTICE[26632]: devicestate.c:584 ast_devstate_changed_literal: state=1 for device Custom:q8501_a8520
[Feb 13 23:25:40] NOTICE[26600]: devicestate.c:324 _ast_device_state: Cached state=2 for device Custom:q8501_a8520
[Feb 13 23:25:40] NOTICE[26597]: devicestate.c:750 process_collection: cache state=1 for device Custom:q8501_a8520
[Feb 13 23:25:40] NOTICE[26600]: devicestate.c:324 _ast_device_state: Cached state=1 for device Custom:q8501_a8520
[Feb 13 23:25:40] NOTICE[26632]: devicestate.c:546 devstate_event: cache state=1 for device Custom:q8501_a8520

*** 5th BLF key press, (Agent Login), Light was incorrectly ON, Now goes OUT.
[Feb 13 23:25:58] NOTICE[26633]: func_devstate.c:131 devstate_write: ---------------------------------------------------------------
[Feb 13 23:25:58] NOTICE[26633]: func_devstate.c:132 devstate_write: DEVICE_STATE function state=2 for device q8501_a8520
[Feb 13 23:25:58] NOTICE[26633]: devicestate.c:584 ast_devstate_changed_literal: state=2 for device Custom:q8501_a8520
[Feb 13 23:25:58] NOTICE[26600]: devicestate.c:324 _ast_device_state: Cached state=1 for device Custom:q8501_a8520
[Feb 13 23:25:58] NOTICE[26600]: devicestate.c:324 _ast_device_state: Cached state=2 for device Custom:q8501_a8520
[Feb 13 23:25:58] NOTICE[26597]: devicestate.c:750 process_collection: cache state=2 for device Custom:q8501_a8520
[Feb 13 23:25:58] NOTICE[26633]: devicestate.c:546 devstate_event: cache state=2 for device Custom:q8501_a8520
astrid*CLI>


By: Russell Bryant (russell) 2009-02-15 20:47:03.000-0600

I do plan to fix it in every release that the problem affects.

I marked it as targeting 1.6.1 since I wanted to fix it before we release 1.6.1.  It will be fixed in 1.6.0, as well, but you can only list a single target version in mantis.
By: Alec Davis (alecdavis) 2009-02-16 00:46:01.000-0600

Before I go stale on this one, is there any thing else you need from me?
By: Russell Bryant (russell) 2009-02-17 10:26:49.000-0600

Not at the moment.  I plan to work on this today, so if I need anything, I'll let you know in the next few hours.
By: Digium Subversion (svnbot) 2009-02-17 11:33:39.000-0600

Repository: asterisk
Revision: 176557

U   trunk/apps/app_queue.c
U   trunk/main/pbx.c

------------------------------------------------------------------------
r176557 | russell | 2009-02-17 11:33:38 -0600 (Tue, 17 Feb 2009) | 12 lines

Fix a race condition that caused device states to become incorrect for hints.

The problem here is that the hint processing code was subscribed to the wrong
event type.  So, it started processing state for a hint too soon, before the
device state cache had been updated.

Also, fix a similar bug in app_queue, as it was also subscribed to the wrong
event type.

(closes issue ASTERISK-13566)
Reported by: alecdavis

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=176557
By: Digium Subversion (svnbot) 2009-02-17 11:34:30.000-0600

Repository: asterisk
Revision: 176558

_U  branches/1.6.0/

------------------------------------------------------------------------
r176558 | russell | 2009-02-17 11:34:30 -0600 (Tue, 17 Feb 2009) | 19 lines

Blocked revisions 176557 via svnmerge

........
r176557 | russell | 2009-02-17 11:33:38 -0600 (Tue, 17 Feb 2009) | 12 lines

Fix a race condition that caused device states to become incorrect for hints.

The problem here is that the hint processing code was subscribed to the wrong
event type.  So, it started processing state for a hint too soon, before the
device state cache had been updated.

Also, fix a similar bug in app_queue, as it was also subscribed to the wrong
event type.

(closes issue ASTERISK-13566)
Reported by: alecdavis

........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=176558
By: Digium Subversion (svnbot) 2009-02-17 11:38:48.000-0600

Repository: asterisk
Revision: 176559

_U  branches/1.6.1/
U   branches/1.6.1/apps/app_queue.c
U   branches/1.6.1/main/pbx.c

------------------------------------------------------------------------
r176559 | russell | 2009-02-17 11:38:47 -0600 (Tue, 17 Feb 2009) | 20 lines

Merged revisions 176557 via svnmerge from
https://origsvn.digium.com/svn/asterisk/trunk

........
r176557 | russell | 2009-02-17 11:33:38 -0600 (Tue, 17 Feb 2009) | 12 lines

Fix a race condition that caused device states to become incorrect for hints.

The problem here is that the hint processing code was subscribed to the wrong
event type.  So, it started processing state for a hint too soon, before the
device state cache had been updated.

Also, fix a similar bug in app_queue, as it was also subscribed to the wrong
event type.

(closes issue ASTERISK-13566)
Reported by: alecdavis

........

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=176559
By: Alec Davis (alecdavis) 2009-02-23 16:45:50.000-0600

This doesn't appear to have made it into 1.6.0 branch, should it have done?
Looks like it was blocked?

Feedback: Currently using trunk it's working well.

karma +1 at least?????


By: Russell Bryant (russell) 2009-02-23 17:26:57.000-0600

Thanks for the feedback!

The code didn't go into 1.6.0 because the problem I fixed does not exist in 1.6.0, as it was realted to changes introduced in trunk after 1.6.0.  Do you have problems with 1.6.0, or were you just checking.

Also, karma added, thanks for the report!
By: Alec Davis (alecdavis) 2009-02-23 18:18:37.000-0600

The problems I'd seen was on trunk, so no it wasn't 1.6.0.
I was just checking, and seeing 3 commits above this note, the 2nd one for 1.6.0 I assumed it should have been there.

Thanks for the Karma on this bug.

I need to apply for Karma on other bugs, maybe there should be a page for "request Karma"


By: Russell Bryant (russell) 2009-02-25 10:51:36.000-0600

If there are bugs you didn't get karma for, feel free to contact Leif Madsen and he'll take care of it for you - lmadsen@digium.com