search

OpenZWave / open-zwave

a C++ library to control Z-Wave Networks via a USB Z-Wave Controller.
http://www.openzwave.net/
GNU Lesser General Public License v3.0
1.05k stars 916 forks source link

RefreshNodeInfo results in log flood #672

Closed gizmocuz closed 8 years ago

gizmocuz commented 8 years ago

Version: 1.3.509.g74a89

When issuing the command RefreshNodeInfo(homeid,node)

i have an endless stream of the following in the log:

2015-10-16 09:49:26.192 Detail, Node013, AdvanceQueries queryPending=0 queryRetries=0 queryStage=ProtocolInfo live=1 2015-10-16 09:49:26.193 Detail, Node013, QueryStage_Probe 2015-10-16 09:49:26.193 Info, Node013, NoOperation::Set - Routing=true 2015-10-16 09:49:26.194 Detail, Node013, Queuing (NoOp) NoOperation_Set (Node=13): 0x01, 0x09, 0x00, 0x13, 0x0d, 0x02, 0x00, 0x00, 0x25, 0x24, 0xeb 2015-10-16 09:49:26.194 Detail, Node013, Queuing (Query) Query Stage Complete (Probe) 2015-10-16 09:49:26.195 Detail, 2015-10-16 09:49:26.195 Info, Node013, Sending (NoOp) message (Callback ID=0x24, Expected Reply=0x13) - NoOperation_Set (Node=13): 0x01, 0x09, 0x00, 0x13, 0x0d, 0x02, 0x00, 0x00, 0x25, 0x24, 0xeb 2015-10-16 09:49:26.203 Detail, Node013, Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8 2015-10-16 09:49:26.204 Detail, Node013, ZW_SEND_DATA delivered to Z-Wave stack 2015-10-16 09:49:26.219 Detail, Node013, Received: 0x01, 0x05, 0x00, 0x13, 0x24, 0x00, 0xcd 2015-10-16 09:49:26.220 Detail, Node013, ZW_SEND_DATA Request with callback ID 0x24 received (expected 0x24) 2015-10-16 09:49:26.221 Info, Node013, Request RTT 25 Average Request RTT 25 2015-10-16 09:49:26.222 Detail, Expected callbackId was received 2015-10-16 09:49:26.222 Detail, Expected reply was received 2015-10-16 09:49:26.223 Detail, Message transaction complete 2015-10-16 09:49:26.223 Detail, 2015-10-16 09:49:26.224 Detail, Node013, Removing current message 2015-10-16 09:49:26.224 Detail, Node013, Notification: Notification - NoOperation 2015-10-16 09:49:26.231 Info, mgr, Manager::WriteConfig completed for driver with home ID of 0xd3cf129c 2015-10-16 09:49:26.233 Detail, Node013, Query Stage Complete (Probe) 2015-10-16 09:49:26.233 Detail, Node013, AdvanceQueries queryPending=0 queryRetries=0 queryStage=WakeUp live=1 2015-10-16 09:49:26.234 Detail, Node013, QueryStage_WakeUp 2015-10-16 09:49:26.234 Detail, Node013, QueryStage_ManufacturerSpecific1 2015-10-16 09:49:26.235 Detail, Node013, Checking for ManufacturerSpecific CC and Requesting values if present on this node

....here it starts.... 2015-10-16 09:39:08.697 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.698 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.698 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.698 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.699 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.699 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.700 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.700 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.701 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.701 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.702 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.702 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.703 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.703 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.704 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.704 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.705 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.705 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.706 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.706 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.707 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.707 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.708 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.708 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.708 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.709 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.709 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.710 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.710 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.711 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.711 Detail, Node013, QueryStage_NodePlusInfo 2015-10-16 09:39:08.712 Detail, Node013, QueryStage_NodePlusInfo

It does not stop.... after a few minutes, the log file is now 40MB

after a restart, it keeps logging the above

After i delete the config file (zwcfg_xxxx.xml) it starts normally again

The node is a zipato rgb bulp, included secure, on a ZWave.Me plus usb stick I could replicate this with the ozw control panel, selecting the node, and from controller select 'Refresh Node Info'

gizmocuz commented 8 years ago

I am 99% sure that this

            if ( pluscc )
            {
                m_queryPending = pluscc->RequestState( CommandClass::RequestFlag_Static, 1, Driver::MsgQueue_Query );
                addQSC = m_queryPending;
            }

does not set 'm_queryPending ' to 'true' and therefore causes an endless loop

Fishwaldo commented 8 years ago

Can you post a log of starting up without zecfg_*.xml so I can see what the zipato does differently?

Fishwaldo commented 8 years ago

(I believe you can attach log files to issues in github now)

gizmocuz commented 8 years ago

I can't attacht the low file (Attaching documents requires write permission to this repository)

I uploaded it to http://pastebin.com/hfqriicL

Fishwaldo commented 8 years ago

Cheers. I see why it's happening. We need to set that static requests flag on the zwplus CC. Fix soon.

gizmocuz commented 8 years ago

Great find!

Fishwaldo commented 8 years ago

Fixed.

gizmocuz commented 8 years ago

Thanks for the quick fix, tested and working great!