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 911 forks source link

Internal errors and dropped message: Log analyzer said to report this #599

Closed ash7777 closed 9 years ago

ash7777 commented 9 years ago

I modified MinOZW to unlock my Shlage BE469 door lock, and the log analyzer said to report some issues in the log file that resulted. The unlock worked, but apparently not perfectly.

The analysis link is: http://www.openzwave.com/log-analyzer/public/c9f5da6a-5a32-47ec-804f-b9c1b30618f9/

Let me know if you need any additional information.

Thanks!

Fishwaldo commented 9 years ago

without knowing what you changed:

Warning 58 - a whole bunch of messages were transmitted in quick succession without gettting a chance to ACK. Did you modify any timeouts or queue code?

Error 4 - Again, seems the Queues got all messed up.

Can you tell us what you changed? that way I can figure out if your change is buggy, or its a OZW bug?

ash7777 commented 9 years ago

I have attached the modified program I used (comments haven't been updated from the original program). It has a variable "doThisOne" that I used so I could change the variable I wanted (I didn't set the variable, just directly changed the next line to execute). Perhaps OZW was confused because I was stepping in a debugger, which can cause abnormally long delays during execution?

On 6/15/2015 6:33 AM, Justin Hammond wrote:

without knowing what you changed:

Warning 58 - a whole bunch of messages were transmitted in quick succession without gettting a chance to ACK. Did you modify any timeouts or queue code?

Error 4 - Again, seems the Queues got all messed up.

Can you tell us what you changed? that way I can figure out if your change is buggy, or its a OZW bug?

— Reply to this email directly or view it on GitHub https://github.com/OpenZWave/open-zwave/issues/599#issuecomment-112026386.

// Home Automation Core.cpp : Defines the exported functions for the DLL application. //

include "stdafx.h"

include "Home Automation Core.h"

include "Manager.h"

include "Options.h"

include "pthread.h"

include "Notification.h"

using namespace OpenZWave;

static pthread_mutex_t g_criticalSection; static pthread_cond_t initCond = PTHREAD_COND_INITIALIZER; static pthread_mutex_t initMutex = PTHREAD_MUTEX_INITIALIZER;

typedef struct { uint32 m_homeId; uint8 m_nodeId; bool m_polled; list m_values; }NodeInfo;

static list<NodeInfo*> g_nodes; bool temp = false; static uint32 g_homeId = 0; static bool g_initFailed = false;

// This is an example of an exported variable HOMEAUTOMATIONCORE_API int nHomeAutomationCore=0;

// This is an example of an exported function. HOMEAUTOMATIONCORE_API int fnHomeAutomationCore(void) { return 42; }

NodeInfo* GetNodeInfo(const Notification* _notification) { const uint32 homeId = _notification->GetHomeId(); const uint8 nodeId = _notification->GetNodeId(); for (list<NodeInfo>::iterator it = g_nodes.begin(); it != g_nodes.end(); ++it) { NodeInfo* nodeInfo = it; if (nodeInfo->m_homeId == homeId && nodeInfo->m_nodeId == nodeId) return nodeInfo; }

return NULL;

}

void OnNotification(Notification const* _notification, void* _context) { // Must do this inside a critical section to avoid conflicts with the main thread pthread_mutex_lock(&g_criticalSection);

switch (_notification->GetType())
{
    case Notification::Type_ValueAdded:
        {
            NodeInfo* nodeInfo = GetNodeInfo(_notification);
            if (nodeInfo)
            {
                // Add the new value to our list
                nodeInfo->m_values.push_back(_notification->GetValueID());
            }
        }
        break;
    case Notification::Type_ValueRemoved:
        {
            NodeInfo* nodeInfo = GetNodeInfo(_notification);
            if (nodeInfo)
            {
                // Remove the value from out list
                for (list<ValueID>::iterator it = nodeInfo->m_values.begin(); it != nodeInfo->m_values.end(); ++it)
                {
                    if (*it == _notification->GetValueID())
                    {
                        nodeInfo->m_values.erase(it);
                        break;
                    }
                }
            }
            break;
        }
    case Notification::Type_ValueChanged:
        {
            // One of the node values has changed
            NodeInfo* nodeInfo = GetNodeInfo(_notification);
            if (nodeInfo)
            {
                nodeInfo = nodeInfo;        // placeholder for real action
            }
            break;
        }
    case Notification::Type_Group:
        {
            // One of the node's association groups has changed
            NodeInfo* nodeInfo = GetNodeInfo(_notification);
            if (nodeInfo)
            {
                nodeInfo = nodeInfo;        // placeholder for real action
            }
            break;
        }
    case Notification::Type_NodeAdded:
        {
            // Add the new node to our list
            NodeInfo* nodeInfo = new NodeInfo();
            nodeInfo->m_homeId = _notification->GetHomeId();
            nodeInfo->m_nodeId = _notification->GetNodeId();
            nodeInfo->m_polled = false;
            g_nodes.push_back(nodeInfo);
            if (temp == true)
            {
                Manager::Get()->CancelControllerCommand(_notification->GetHomeId());
            }
            break;
        }
    case Notification::Type_NodeRemoved:
        {
            // Remove the node from our list
            uint32 const homeId = _notification->GetHomeId();
            uint8 const nodeId = _notification->GetNodeId();
            for (list<NodeInfo*>::iterator it = g_nodes.begin(); it != g_nodes.end(); ++it)
            {
                NodeInfo* nodeInfo = *it;
                if (nodeInfo->m_homeId == homeId && nodeInfo->m_nodeId == nodeId)
                {
                    g_nodes.erase(it);
                    delete nodeInfo;
                    break;
                }
            }
            break;
        }
    case Notification::Type_NodeEvent:
        {
            // We have received an event from the node, caused by a
            // basic_set or hail message.
            NodeInfo* nodeInfo = GetNodeInfo(_notification);
            if (nodeInfo)
            {
                nodeInfo = nodeInfo;        // placeholder for real action
            }
            break;
        }
    case Notification::Type_PollingDisabled:
        {
            NodeInfo* nodeInfo = GetNodeInfo(_notification);
            if (nodeInfo)
            {
                nodeInfo->m_polled = false;
            }
            break;
        }
    case Notification::Type_PollingEnabled:
        {
            NodeInfo* nodeInfo = GetNodeInfo(_notification);
            if (nodeInfo)
            {
                nodeInfo->m_polled = true;
            }
            break;
        }

    case Notification::Type_DriverReady:
        {
            g_homeId = _notification->GetHomeId();
            break;
        }

    case Notification::Type_DriverFailed:
        {
            g_initFailed = true;
            pthread_cond_broadcast(&initCond);
            break;
        }

    case Notification::Type_AwakeNodesQueried:
    case Notification::Type_AllNodesQueried:
    case Notification::Type_AllNodesQueriedSomeDead:
        {
            pthread_cond_broadcast(&initCond);
            break;
        }
    case Notification::Type_DriverReset:
    case Notification::Type_Notification:
    case Notification::Type_NodeNaming:
    case Notification::Type_NodeProtocolInfo:
    case Notification::Type_NodeQueriesComplete:
        break;
}

pthread_mutex_unlock(&g_criticalSection);

}

// This is the constructor of a class that has been exported. // see Home Automation Core.h for the class definition CHomeAutomationCore::CHomeAutomationCore() { pthread_mutexattr_t mutexattr;

pthread_mutexattr_init(&mutexattr);
pthread_mutexattr_settype(&mutexattr, PTHREAD_MUTEX_RECURSIVE);
pthread_mutex_init(&g_criticalSection, &mutexattr);
pthread_mutexattr_destroy(&mutexattr);

pthread_mutex_lock(&initMutex);

printf("Starting MinOZW with OpenZWave Version %s\n", Manager::getVersionAsString().c_str());
Options::Create("C:/Users/Andrew/Documents/Visual Studio/Projects/AlarmSystem/OpenZWave/open-zwave-master/config", "", "");
Options::Get()->AddOptionInt("PollInterval", 500);
Options::Get()->AddOptionBool("IntervalBetweenPolls", true);
Options::Get()->AddOptionBool("ValidateValueChanges", true);
Options::Get()->Lock();

Manager::Create();

Manager::Get()->AddWatcher(OnNotification, NULL);

string port = "\\\\.\\COM4";
Manager::Get()->AddDriver(port);

// Now we just wait for either the AwakeNodesQueried or AllNodesQueried notification,
// then write out the config file.
// In a normal app, we would be handling notifications and building a UI for the user.
pthread_cond_wait(&initCond, &initMutex);

// Since the configuration file contains command class information that is only 
// known after the nodes on the network are queried, wait until all of the nodes 
// on the network have been queried (at least the "listening" ones) before
// writing the configuration file.  (Maybe write again after sleeping nodes have
// been queried as well.)
if (!g_initFailed)
{
    Sleep(2 * 60 * 1000);

    // The section below demonstrates setting up polling for a variable.  In this simple
    // example, it has been hardwired to poll COMMAND_CLASS_BASIC on the each node that 
    // supports this setting.
    pthread_mutex_lock(&g_criticalSection);
    NodeInfo* node = g_nodes.front();
    bool doThisOne = false;
    for (list<ValueID>::iterator it2 = node->m_values.begin(); it2 != node->m_values.end(); ++it2)
    {
        ValueID v = *it2;
        std::string label = Manager::Get()->GetValueLabel(v);
        std::string units = Manager::Get()->GetValueUnits(v);
        std::string help = Manager::Get()->GetValueHelp(v);
        int32 min = Manager::Get()->GetValueMin(v);
        int32 max = Manager::Get()->GetValueMax(v);
        bool readOnly = Manager::Get()->IsValueReadOnly(v);
        if (doThisOne)
            Manager::Get()->SetValue(v, false);

        int x = 67;
    }
    pthread_mutex_unlock(&g_criticalSection);

    Sleep(2 * 60 * 1000);

    // If we want to access our NodeInfo list, that has been built from all the
    // notification callbacks we received from the library, we have to do so
    // from inside a Critical Section.  This is because the callbacks occur on other 
    // threads, and we cannot risk the list being changed while we are using it.  
    // We must hold the critical section for as short a time as possible, to avoid
    // stalling the OpenZWave drivers.
    // At this point, the program just waits for 3 minutes (to demonstrate polling),
    // then exits
    for (int i = 0; i < 60 * 3; i++)
    {
        pthread_mutex_lock(&g_criticalSection);
        // but NodeInfo list and similar data should be inside critical section
        pthread_mutex_unlock(&g_criticalSection);
        Sleep(1000);
    }

    Driver::DriverData data;
    Manager::Get()->GetDriverStatistics(g_homeId, &data);
    printf("SOF: %d ACK Waiting: %d Read Aborts: %d Bad Checksums: %d\n", data.m_SOFCnt, data.m_ACKWaiting, data.m_readAborts, data.m_badChecksum);
    printf("Reads: %d Writes: %d CAN: %d NAK: %d ACK: %d Out of Frame: %d\n", data.m_readCnt, data.m_writeCnt, data.m_CANCnt, data.m_NAKCnt, data.m_ACKCnt, data.m_OOFCnt);
    printf("Dropped: %d Retries: %d\n", data.m_dropped, data.m_retries);
}

Manager::Get()->RemoveDriver(port);
Manager::Get()->RemoveWatcher(OnNotification, NULL);
Manager::Destroy();
Options::Destroy();
pthread_mutex_destroy(&g_criticalSection);

}

Fishwaldo commented 9 years ago

I cant see anything wrong with this... but yeah, as OZW is multithreaded, a debugger might be screwing with things there.