[asterisk-bugs] [JIRA] (ASTERISK-21069) xmpp distributed device states aggregation update fails

Rusty Newton (JIRA) noreply at issues.asterisk.org
Tue Feb 19 09:22:18 CST 2013


     [ https://issues.asterisk.org/jira/browse/ASTERISK-21069?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Rusty Newton reassigned ASTERISK-21069:
---------------------------------------

    Assignee: Rusty Newton
    
> xmpp distributed device states aggregation update fails
> -------------------------------------------------------
>
>                 Key: ASTERISK-21069
>                 URL: https://issues.asterisk.org/jira/browse/ASTERISK-21069
>             Project: Asterisk
>          Issue Type: Bug
>      Security Level: None
>          Components: Resources/res_xmpp
>    Affects Versions: 11.1.2
>         Environment: raspbx with Asterisk 11.1.2 on Debian7 / Wheezy
>            Reporter: Marco Paland
>            Assignee: Rusty Newton
>
> I'm having a real hard time and no clue why the following happens.
> The custom device stats can't be updated on remote boxes. I file this as a bug.
> I have two asterisk pbx boxes. Box 1 has a ejabberd server installed. Jabber buddies and connections are fine.
> xmpp.conf is basically out of the book and nothing fancy:
> Server 1:{code}
> [general]
> debug=yes                               ; Enable debugging (disabled by default).
> autoregister=yes                        ; Auto register users from buddy list.
> [asterisk]
> type=client                             ; Client or Component connection
> serverhost=raspbx1                      ; Route to server for example, talk.google.com
> pubsub_node=pubsub.raspbx1              ; Node to use for publishing events via PubSub
> username=pbx1 at raspbx1/astvoip1          ; Username with optional resource.
> secret=pbx1                             ; Password
> usesasl=yes                             ; Use sasl or not
> buddy=pbx2 at raspbx1/astvoip2             ; Manual addition of buddy to list.
>                                         ; For distributed events, these buddies are
>                                         ; automatically added in the whitelist as
>                                         ; 'owners' of the node(s).
> distribute_events=yes                   ; Whether or not to distribute events using
>                                         ; this connection.  Default is 'no'.
> status=available                        ; One of: chat, available, away, xaway, or dnd
> {code}
> and Server 2:{code}
> [general]
> debug=yes                               ; Enable debugging (disabled by default).
> autoregister=yes                        ; Auto register users from buddy list.
> [asterisk]
> type=client                             ; Client or Component connection
> serverhost=raspbx1                      ; Route to server for example, talk.google.com
> pubsub_node=pubsub.raspbx1              ; Node to use for publishing events via PubSub
> username=pbx2 at raspbx1/astvoip2          ; Username with optional resource.
> secret=pbx2                             ; Password
> usesasl=yes                             ; Use sasl or not
> buddy=pbx1 at raspbx1/astvoip1             ; Manual addition of buddy to list.
>                                         ; For distributed events, these buddies are
>                                         ; automatically added in the whitelist as
>                                         ; 'owners' of the node(s).
> distribute_events=yes                   ; Whether or not to distribute events using
>                                         ; this connection.  Default is 'no'.
> status=available                        ; One of: chat, available, away, xaway, or dnd
> {code}
> on both boxes is the following hint:{code}
> [from-internal-custom]
> exten => 6123,hint,Custom:ext100
> {code}
> Okay, problem is to set the custom device state ext100 FROM box 2. Box 1 should reflect this state.
> On box 2:{code}
> raspbx2*CLI> devstate change Custom:ext100 RINGING
> Changing ext100 to RINGING
> <--- XMPP sent to 'asterisk' --->
> <iq to='pubsub.raspbx1' from='pbx2 at raspbx1/astvoip2' type='set' id='aaaau'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='device_state'><item id='Custom:ext100'><state xmlns='http://asterisk.org' eid='b8:27:eb:45:01:68' cachable='1'>RINGING</state></item></publish></pubsub></iq>
> <------------->
> <--- XMPP received from 'asterisk' --->
> <message from='pubsub.raspbx1' to='pbx2 at raspbx1' type='headline'><event xmlns='http://jabber.org/protocol/pubsub#event'><items node='device_state'><item id='Custom:ext100'><state xmlns='http://asterisk.org' eid='b8:27:eb:45:01:68' cachable='1'>RINGING</state></item></items></event><headers xmlns='http://jabber.org/protocol/shim'><header name='Collection'>device_state</header></headers></message>
> <------------->
> <--- XMPP received from 'asterisk' --->
> <iq from='pubsub.raspbx1' to='pbx2 at raspbx1/astvoip2' id='aaaau' type='result'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='device_state'><item id='Custom:ext100'/></publish></pubsub></iq>
> <------------->
> raspbx2*CLI> core show hints
>     -= Registered Asterisk Dial Plan Hints =-
>                    6123 at from-internal-custom: Custom:ext100         State:Ringing         Watchers  0
>                     200 at ext-local           : SIP/200               State:Unavailable     Watchers  0
> {code}
> and the coresponding log on box 1:{code}
> <--- XMPP received from 'asterisk' --->
> <message from='pubsub.raspbx1' to='pbx1 at raspbx1' type='headline'><event xmlns='http://jabber.org/protocol/pubsub#event'><items node='device_state'><item id='Custom:ext100'><state xmlns='http://asterisk.org' eid='b8:27:eb:45:01:68' cachable='1'>RINGING</state></item></items></event><headers xmlns='http://jabber.org/protocol/shim'><header name='Collection'>device_state</header></headers></message>
> <------------->
> [2013-02-12 15:58:40] DEBUG[1373]: res_xmpp.c:3023 xmpp_pak_message: XMPP client 'asterisk' received a message
> [2013-02-12 15:58:40] DEBUG[1359]: res_xmpp.c:1220 xmpp_pubsub_devstate_cb: Returning here
> [2013-02-12 15:58:40] DEBUG[1374]: devicestate.c:666 handle_devstate_change: Processing device state change for 'Custom:ext100'
> [2013-02-12 15:58:40] DEBUG[1374]: devicestate.c:612 process_collection: Adding per-server state of 'Not in use' for 'Custom:ext100'
> [2013-02-12 15:58:40] DEBUG[1374]: devicestate.c:612 process_collection: Adding per-server state of 'Ringing' for 'Custom:ext100'
> [2013-02-12 15:58:40] DEBUG[1374]: devicestate.c:619 process_collection: Aggregate devstate result is 'Ringing' for 'Custom:ext100'
> [2013-02-12 15:58:40] DEBUG[1374]: devicestate.c:641 process_collection: Aggregate state for device 'Custom:ext100' has changed to 'Ringing'
> [2013-02-12 15:58:40] DEBUG[1414]: app_queue.c:1806 handle_statechange: Device 'Custom:ext100' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
> [2013-02-12 15:58:40] DEBUG[1373]: res_xmpp.c:3537 xmpp_client_receive: XML parsing successful
> raspbx1*CLI> core show hints
>     -= Registered Asterisk Dial Plan Hints =-
>                     100 at ext-local           : SIP/100               State:Idle            Watchers  0
>                     101 at ext-local           : SIP/101               State:Unavailable     Watchers  0
>                    6123 at from-internal-custom: Custom:ext100         State:Idle            Watchers  1
> {code}
> State should be RINGING, but is still IDLE.
> Watcher is the BLF-LED on my phone.
> But if I set on box 1:{code}
> raspbx1*CLI> devstate change Custom:ext100 NOT_INUSE
> Changing ext100 to NOT_INUSE
> [2013-02-12 16:01:26] DEBUG[1418]: devicestate.c:442 devstate_event: device 'Custom:ext100' state '1'
> [2013-02-12 16:01:26] DEBUG[1374]: devicestate.c:666 handle_devstate_change: Processing device state change for 'Custom:ext100'
> [2013-02-12 16:01:26] DEBUG[1374]: devicestate.c:612 process_collection: Adding per-server state of 'Ringing' for 'Custom:ext100'
> [2013-02-12 16:01:26] DEBUG[1374]: devicestate.c:612 process_collection: Adding per-server state of 'Not in use' for 'Custom:ext100'
> [2013-02-12 16:01:26] DEBUG[1374]: devicestate.c:619 process_collection: Aggregate devstate result is 'Ringing' for 'Custom:ext100'
> [2013-02-12 16:01:26] DEBUG[1374]: devicestate.c:641 process_collection: Aggregate state for device 'Custom:ext100' has changed to 'Ringing'
> <--- XMPP sent to 'asterisk' --->
> <iq to='pubsub.raspbx1' from='pbx1 at raspbx1/astvoip1' type='set' id='aaaap'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='device_state'><item id='Custom:ext100'><state xmlns='http://asterisk.org' eid='b8:27:eb:15:1e:1f' cachable='1'>NOT_INUSE</state></item></publish></pubsub></iq>
> <------------->
> [2013-02-12 16:01:26] DEBUG[1367]: app_queue.c:1908 extension_state_cb: Extension '6123 at from-internal-custom' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
> [2013-02-12 16:01:26] DEBUG[1367]: chan_sip.c:3864 __sip_xmit: Trying to put 'NOTIFY sip:' onto UDP socket destined for 192.168.2.25:47210
> <--- XMPP received from 'asterisk' --->
> <message from='pubsub.raspbx1' to='pbx1 at raspbx1' type='headline'><event xmlns='http://jabber.org/protocol/pubsub#event'><items node='device_state'><item id='Custom:ext100'><state xmlns='http://asterisk.org' eid='b8:27:eb:15:1e:1f' cachable='1'>NOT_INUSE</state></item></items></event><headers xmlns='http://jabber.org/protocol/shim'><header name='Collection'>device_state</header></headers></message>
> <------------->
> [2013-02-12 16:01:26] DEBUG[1373]: res_xmpp.c:3023 xmpp_pak_message: XMPP client 'asterisk' received a message
> [2013-02-12 16:01:26] DEBUG[1373]: res_xmpp.c:1325 xmpp_pubsub_handle_event: Returning here, eid of incoming event matches ours!
> [2013-02-12 16:01:26] DEBUG[1373]: res_xmpp.c:3537 xmpp_client_receive: XML parsing successful
> <--- XMPP received from 'asterisk' --->
> <iq from='pubsub.raspbx1' to='pbx1 at raspbx1/astvoip1' id='aaaap' type='result'><pubsub xmlns='http://jabber.org/protocol/pubsub'><publish node='device_state'><item id='Custom:ext100'/></publish></pubsub></iq>
> <------------->
> [2013-02-12 16:01:26] DEBUG[1414]: app_queue.c:1806 handle_statechange: Device 'Custom:ext100' changed to state '6' (Ringing) but we don't care because they're not a member of any queue.
>   == Extension Changed 6123[from-internal-custom] new state Ringing for Notify User 100
> [2013-02-12 16:01:26] DEBUG[1373]: res_xmpp.c:3537 xmpp_client_receive: XML parsing successful
> <--- XMPP received from 'asterisk' --->
> <message from='pubsub.raspbx1' to='pbx1 at raspbx1' type='headline'><event xmlns='http://jabber.org/protocol/pubsub#event'><items node='device_state'><item id='Custom:ext100'><state xmlns='http://asterisk.org' eid='b8:27:eb:45:01:68' cachable='1'>NOT_INUSE</state></item></items></event><headers xmlns='http://jabber.org/protocol/shim'><header name='Collection'>device_state</header></headers></message>
> <------------->
> [2013-02-12 16:02:49] DEBUG[1373]: res_xmpp.c:3023 xmpp_pak_message: XMPP client 'asterisk' received a message
> [2013-02-12 16:02:49] DEBUG[1359]: res_xmpp.c:1220 xmpp_pubsub_devstate_cb: Returning here
> [2013-02-12 16:02:49] DEBUG[1374]: devicestate.c:666 handle_devstate_change: Processing device state change for 'Custom:ext100'
> [2013-02-12 16:02:49] DEBUG[1374]: devicestate.c:612 process_collection: Adding per-server state of 'Not in use' for 'Custom:ext100'
> [2013-02-12 16:02:49] DEBUG[1374]: devicestate.c:612 process_collection: Adding per-server state of 'Not in use' for 'Custom:ext100'
> [2013-02-12 16:02:49] DEBUG[1374]: devicestate.c:619 process_collection: Aggregate devstate result is 'Not in use' for 'Custom:ext100'
> [2013-02-12 16:02:49] DEBUG[1374]: devicestate.c:641 process_collection: Aggregate state for device 'Custom:ext100' has changed to 'Not in use'
> [2013-02-12 16:02:49] DEBUG[1367]: chan_sip.c:3864 __sip_xmit: Trying to put 'NOTIFY sip:' onto UDP socket destined for 192.168.2.25:47210
> [2013-02-12 16:02:49] DEBUG[1414]: app_queue.c:1806 handle_statechange: Device 'Custom:ext100' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
>   == Extension Changed 6123[from-internal-custom] new state Ringing for Notify User 100
> [2013-02-12 16:02:49] DEBUG[1373]: res_xmpp.c:3537 xmpp_client_receive: XML parsing successful
> raspbx1*CLI> core show hints
>     -= Registered Asterisk Dial Plan Hints =-
>                     100 at ext-local           : SIP/100               State:Idle            Watchers  0
>                     101 at ext-local           : SIP/101               State:Unavailable     Watchers  0
>                    6123 at from-internal-custom: Custom:ext100         State:Ringing         Watchers  1
> {code}
> And just NOW, the state is RINGING.
> Seems that there is a update problem.
> Why don't I get a RINGING state right after the xmpp message from box 2?
> And reseting the state is quite the same.
> A NOT_INUSE message from box 2 DOES NOT set the state to IDLE:{code}
> [2013-02-12 16:13:34] DEBUG[1373]: res_xmpp.c:3023 xmpp_pak_message: XMPP client 'asterisk' received a message
> [2013-02-12 16:13:34] DEBUG[1359]: res_xmpp.c:1220 xmpp_pubsub_devstate_cb: Returning here
> [2013-02-12 16:13:34] DEBUG[1374]: devicestate.c:666 handle_devstate_change: Processing device state change for 'Custom:ext100'
> [2013-02-12 16:13:34] DEBUG[1374]: devicestate.c:612 process_collection: Adding per-server state of 'Not in use' for 'Custom:ext100'
> [2013-02-12 16:13:34] DEBUG[1374]: devicestate.c:612 process_collection: Adding per-server state of 'Not in use' for 'Custom:ext100'
> [2013-02-12 16:13:34] DEBUG[1374]: devicestate.c:619 process_collection: Aggregate devstate result is 'Not in use' for 'Custom:ext100'
> [2013-02-12 16:13:34] DEBUG[1374]: devicestate.c:641 process_collection: Aggregate state for device 'Custom:ext100' has changed to 'Not in use'
> [2013-02-12 16:13:34] DEBUG[1367]: chan_sip.c:3864 __sip_xmit: Trying to put 'NOTIFY sip:' onto UDP socket destined for 192.168.2.25:47210
> [2013-02-12 16:13:34] DEBUG[1414]: app_queue.c:1806 handle_statechange: Device 'Custom:ext100' changed to state '1' (Not in use) but we don't care because they're not a member of any queue.
>   == Extension Changed 6123[from-internal-custom] new state Ringing for Notify User 100
> [2013-02-12 16:13:34] DEBUG[1373]: res_xmpp.c:3537 xmpp_client_receive: XML parsing successful
> <--- XMPP keep alive from 'asterisk' --->
> raspbx1*CLI> core show hints
>     -= Registered Asterisk Dial Plan Hints =-
>                     100 at ext-local           : SIP/100               State:Idle            Watchers  0
>                     101 at ext-local           : SIP/101               State:Unavailable     Watchers  0
>                    6123 at from-internal-custom: Custom:ext100         State:Ringing         Watchers  1
> raspbx1*CLI> devstate list
> ---------------------------------------------------------------------
> --- Custom Device States --------------------------------------------
> ---------------------------------------------------------------------
> ---
> --- Name: 'Custom:ext100'  State: 'NOT_INUSE'
> ---
> --- Name: 'Custom:ext101'  State: 'NOT_INUSE'
> ---
> ---------------------------------------------------------------------
> ---------------------------------------------------------------------
> {code}
> Is this a bug or do miss something?

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira



More information about the asterisk-bugs mailing list