search

jperkin / node-openzwave

node.js interface to libopenzwave
Other
109 stars 54 forks source link

'Assertion failed' on OS X #7

Open phillipsnick opened 11 years ago

phillipsnick commented 11 years ago

I have successfully got everything working on a Raspberry Pi but for development I am trying to get this working on OS X 10.8.5 with my Aeon Z-Stick S2. The example mac application within open-zwave works as expected and outputs state changes of devices, but when running your example with all logging enabled I get an assertion failed error.

Assertion failed: (Type_Notification==m_type), function GetNotification, file ../deps/open-zwave/cpp/src/Notification.h, line 165.
[1]    7624 abort      node main.js
...
var zwave = new OZW('/dev/cu.SLAB_USBtoUART', {
        logging: true,           // enable logging to OZW_Log.txt
        consoleoutput: true,     // copy logging to the console
        saveconfig: true,        // write an XML network layout
        driverattempts: 3        // try this many times before giving up
});
...

Not too sure how to debug this further.

jperkin commented 11 years ago

Odd, nothing should be calling GetNotification() - this is with the latest unmodified version?

phillipsnick commented 11 years ago

Far as I am aware it was all unmodified. As I haven't used any node or zwave stuff on my Mac Book yet I figured I would start from fresh on it to make sure it wasn't just a one off, and to show the steps I did to replicate the issue.

Used the following USB stick driver on the Mac Book http://www.silabs.com/products/mcu/Pages/USBtoUARTBridgeVCPDrivers.aspx

Installed Node for Mac from http://nodejs.org/download/

➜  ~  node -v
v0.10.21
➜  ~  npm -v
1.3.11

Setting up the app...

mkdir ozw
cd ozw
npm install openzwave
nano app.js
node app.js

The full script I used for app.js (simply your example with a change to the device and extra logging parameters. 

var OpenZWave = require('openzwave');

var zwave = new OpenZWave('/dev/cu.SLAB_USBtoUART', {
        logging: true,           // enable logging to OZW_Log.txt
        consoleoutput: true,     // copy logging to the console
        saveconfig: true,        // write an XML network layout
        driverattempts: 3        // try this many times before giving up
});
var nodes = [];

zwave.on('driver ready', function() {
    console.log('scanning...');
});

zwave.on('driver failed', function() {
    console.log('failed to start driver');
    zwave.disconnect();
    process.exit();
});

zwave.on('node added', function(nodeid) {
    nodes[nodeid] = {
        manufacturer: '',
        product: '',
        type: '',
        loc: '',
        values: {},
    };
});

zwave.on('value added', function(nodeid, type, value) {
    nodes[nodeid]['values'][type] = value;
});

zwave.on('value changed', function(nodeid, type, value) {
    if (nodes[nodeid]['values'][type] != value) {
        console.log('node%d: %s=%s->%s', nodeid, type,
                nodes[nodeid]['values'][type], value);
        nodes[nodeid]['values'][type] = value;
    }
});

zwave.on('node ready', function(nodeid, nodeinfo) {
    nodes[nodeid]['manufacturer'] = nodeinfo.manufacturer;
    nodes[nodeid]['product'] = nodeinfo.product;
    nodes[nodeid]['type'] = nodeinfo.type;
    nodes[nodeid]['loc'] = nodeinfo.loc;
    console.log('node%d: %s, %s', nodeid,
            nodeinfo.manufacturer,
            nodeinfo.product);
    console.log('node%d: type="%s", location="%s"', nodeid,
            nodeinfo.type,
            nodeinfo.loc);
    for (val in nodes[nodeid]['values']) {
        console.log('node%d: %s=%s', nodeid, val, nodes[nodeid]['values'][val]);
    }
});

zwave.on('scan complete', function() {
    console.log('scan complete, hit ^C to finish.');
});

zwave.connect();

process.on('SIGINT', function() {
    console.log('disconnecting...');
    zwave.disconnect();
    process.exit();
});

Still get the same message

Assertion failed: (Type_Notification==m_type), function GetNotification, file ../deps/open-zwave/cpp/src/Notification.h, line 165.
[1]    4158 abort      node app.js

Noticed the firmware of the stick may be slightly out of date as the latest appears to be 3.07. But as this same app works on the Raspberry Pi I wouldn't have thought this would cause this issue.

2013-10-19 13:09:46.943 contrlr, Received reply to FUNC_ID_ZW_GET_VERSION:
2013-10-19 13:09:46.943 contrlr,     Static Controller library, version Z-Wave 2.78
2013-10-19 13:09:46.943 contrlr,   Expected reply was received
2013-10-19 13:09:46.943 contrlr,   Message transaction complete
phillipsnick commented 11 years ago

Thought I'd give it a go on Ubuntu 12.04 LTS x64 too.

Looks like the same issue but different error message.

2013-10-19 19:33:25.576 contrlr, Removing current message
node: ../deps/open-zwave/cpp/src/Notification.h:165: uint8 OpenZWave::Notification::GetNotification() const: Assertion `Type_Notification==m_type' failed.
jperkin commented 11 years ago

Weird. Can you send me the full log so I get an idea of what it's doing? Thanks.

mrose17 commented 11 years ago

just a data point: my MBP is on node 0.10.20 and npm 1.3.11 and i am not seeing any assertions when i run the test program.

phillipsnick commented 11 years ago 
2013-10-19 19:33:25.431 mgr,     Added driver for controller /dev/ttyUSB0
2013-10-19 19:33:25.431   Opening controller /dev/ttyUSB0
2013-10-19 19:33:25.431 Trying to open serial port /dev/ttyUSB0 (attempt 1)
2013-10-19 19:33:25.451 Serial port /dev/ttyUSB0 opened (attempt 1)
2013-10-19 19:33:25.451 contrlr, Queuing (Command) FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2013-10-19 19:33:25.451 contrlr, Queuing (Command) FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2013-10-19 19:33:25.451 contrlr, Queuing (Command) FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2013-10-19 19:33:25.451 contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2013-10-19 19:33:25.451 contrlr, Queuing (Command) FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2013-10-19 19:33:25.452 
2013-10-19 19:33:25.452 contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x15) - FUNC_ID_ZW_GET_VERSION: 0x01, 0x03, 0x00, 0x15, 0xe9
2013-10-19 19:33:25.455 contrlr,   Received: 0x01, 0x10, 0x01, 0x15, 0x5a, 0x2d, 0x57, 0x61, 0x76, 0x65, 0x20, 0x32, 0x2e, 0x37, 0x38, 0x00, 0x01, 0x9b
2013-10-19 19:33:25.455 
2013-10-19 19:33:25.455 contrlr, Received reply to FUNC_ID_ZW_GET_VERSION:
2013-10-19 19:33:25.455 contrlr,     Static Controller library, version Z-Wave 2.78
2013-10-19 19:33:25.455 contrlr,   Expected reply was received
2013-10-19 19:33:25.455 contrlr,   Message transaction complete
2013-10-19 19:33:25.455 
2013-10-19 19:33:25.456 contrlr, Removing current message
2013-10-19 19:33:25.456 
2013-10-19 19:33:25.456 contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x20) - FUNC_ID_ZW_MEMORY_GET_ID: 0x01, 0x03, 0x00, 0x20, 0xdc
2013-10-19 19:33:25.458 contrlr,   Received: 0x01, 0x08, 0x01, 0x20, 0x01, 0x61, 0xd5, 0x5c, 0x01, 0x3e
2013-10-19 19:33:25.458 
2013-10-19 19:33:25.458 contrlr, Received reply to FUNC_ID_ZW_MEMORY_GET_ID. Home ID = 0x0161d55c.  Our node ID = 1
2013-10-19 19:33:25.458 contrlr,   Expected reply was received
2013-10-19 19:33:25.458 contrlr,   Message transaction complete
2013-10-19 19:33:25.458 
2013-10-19 19:33:25.458 contrlr, Removing current message
2013-10-19 19:33:25.458 
2013-10-19 19:33:25.458 contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x05) - FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES: 0x01, 0x03, 0x00, 0x05, 0xf9
2013-10-19 19:33:25.461 contrlr,   Received: 0x01, 0x04, 0x01, 0x05, 0x08, 0xf7
2013-10-19 19:33:25.461 
2013-10-19 19:33:25.461 contrlr, Received reply to FUNC_ID_ZW_GET_CONTROLLER_CAPABILITIES:
2013-10-19 19:33:25.461 contrlr,     There is no SUC ID Server (SIS) in this network.
2013-10-19 19:33:25.461 contrlr,     The PC controller is a primary controller.
2013-10-19 19:33:25.461 contrlr,   Expected reply was received
2013-10-19 19:33:25.461 contrlr,   Message transaction complete
2013-10-19 19:33:25.461 
2013-10-19 19:33:25.462 contrlr, Removing current message
2013-10-19 19:33:25.462 
2013-10-19 19:33:25.462 contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x07) - FUNC_ID_SERIAL_API_GET_CAPABILITIES: 0x01, 0x03, 0x00, 0x07, 0xfb
2013-10-19 19:33:25.467 contrlr,   Received: 0x01, 0x2b, 0x01, 0x07, 0x03, 0x07, 0x00, 0x86, 0x00, 0x02, 0x00, 0x01, 0xfe, 0x80, 0xfe, 0x88, 0x0f, 0x00, 0x00, 0x00, 0xfb, 0x97, 0x7f, 0x82, 0x07, 0x00, 0x00, 0x80, 0x00, 0x80, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0xc2
2013-10-19 19:33:25.467 
2013-10-19 19:33:25.467 contrlr,  Received reply to FUNC_ID_SERIAL_API_GET_CAPABILITIES
2013-10-19 19:33:25.467 contrlr,     Serial API Version:   3.7
2013-10-19 19:33:25.467 contrlr,     Manufacturer ID:      0x0086
2013-10-19 19:33:25.467 contrlr,     Product Type:         0x0002
2013-10-19 19:33:25.467 contrlr,     Product ID:           0x0001
2013-10-19 19:33:25.467 contrlr, Queuing (Command) FUNC_ID_ZW_GET_RANDOM: 0x01, 0x04, 0x00, 0x1c, 0x20, 0xc7
2013-10-19 19:33:25.468 contrlr, Queuing (Command) FUNC_ID_SERIAL_API_GET_INIT_DATA: 0x01, 0x03, 0x00, 0x02, 0xfe
2013-10-19 19:33:25.468 contrlr, Queuing (Command) FUNC_ID_SERIAL_API_SET_TIMEOUTS: 0x01, 0x05, 0x00, 0x06, 0x64, 0x0f, 0x97
2013-10-19 19:33:25.468 contrlr, Queuing (Command) FUNC_ID_SERIAL_API_APPL_NODE_INFORMATION: 0x01, 0x07, 0x00, 0x03, 0x01, 0x02, 0x01, 0x00, 0xf9
2013-10-19 19:33:25.468 contrlr,   Expected reply was received
2013-10-19 19:33:25.468 contrlr,   Message transaction complete
2013-10-19 19:33:25.468 
2013-10-19 19:33:25.468 contrlr, Removing current message
2013-10-19 19:33:25.468 
2013-10-19 19:33:25.468 contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x56) - FUNC_ID_ZW_GET_SUC_NODE_ID: 0x01, 0x03, 0x00, 0x56, 0xaa
2013-10-19 19:33:25.471 contrlr,   Received: 0x01, 0x04, 0x01, 0x56, 0x00, 0xac
2013-10-19 19:33:25.471 
2013-10-19 19:33:25.471 contrlr, Received reply to GET_SUC_NODE_ID.  Node ID = 0
2013-10-19 19:33:25.471 contrlr,   Expected reply was received
2013-10-19 19:33:25.471 contrlr,   Message transaction complete
2013-10-19 19:33:25.471 
2013-10-19 19:33:25.471 contrlr, Removing current message
2013-10-19 19:33:25.471 
2013-10-19 19:33:25.472 contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x1c) - FUNC_ID_ZW_GET_RANDOM: 0x01, 0x04, 0x00, 0x1c, 0x20, 0xc7
2013-10-19 19:33:25.524 contrlr,   Received: 0x01, 0x25, 0x01, 0x1c, 0x01, 0x20, 0x20, 0x01, 0x3e, 0xe8, 0x71, 0x39, 0x77, 0x50, 0xbb, 0x2f, 0xea, 0xea, 0x22, 0x7b, 0x27, 0x91, 0xaa, 0x43, 0x10, 0x7e, 0x03, 0xf0, 0xda, 0x5c, 0x45, 0x88, 0x99, 0xd6, 0x50, 0x7c, 0x43, 0x04, 0x1e
2013-10-19 19:33:25.524 
2013-10-19 19:33:25.524 contrlr, Received reply to FUNC_ID_ZW_GET_RANDOM: true
2013-10-19 19:33:25.524 contrlr,   Expected reply was received
2013-10-19 19:33:25.524 contrlr,   Message transaction complete
2013-10-19 19:33:25.524 
2013-10-19 19:33:25.524 contrlr, Removing current message
2013-10-19 19:33:25.525 
2013-10-19 19:33:25.525 contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x02) - FUNC_ID_SERIAL_API_GET_INIT_DATA: 0x01, 0x03, 0x00, 0x02, 0xfe
2013-10-19 19:33:25.574 contrlr,   Received: 0x01, 0x25, 0x01, 0x02, 0x05, 0x00, 0x1d, 0x07, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x00, 0x03, 0x01, 0xc4
2013-10-19 19:33:25.574 
2013-10-19 19:33:25.574 mgr,     Driver with Home ID of 0x0161d55c is now ready.
2013-10-19 19:33:25.574 
2013-10-19 19:33:25.574 contrlr, Received reply to FUNC_ID_SERIAL_API_GET_INIT_DATA:
2013-10-19 19:33:25.574 contrlr,     Node 001 - New
2013-10-19 19:33:25.575 Node001, AdvanceQueries queryPending=0 queryRetries=0 queryStage=ProtocolInfo live=1
2013-10-19 19:33:25.575 Node001, QueryStage_ProtocolInfo
2013-10-19 19:33:25.575 Node001, Queuing (Query) Get Node Protocol Info (Node=1): 0x01, 0x04, 0x00, 0x41, 0x01, 0xbb
2013-10-19 19:33:25.575 Node001, Queuing (Query) Query Stage Complete (ProtocolInfo)
2013-10-19 19:33:25.575 contrlr,     Node 002 - New
2013-10-19 19:33:25.575 Node002, AdvanceQueries queryPending=0 queryRetries=0 queryStage=ProtocolInfo live=1
2013-10-19 19:33:25.575 Node002, QueryStage_ProtocolInfo
2013-10-19 19:33:25.575 Node002, Queuing (Query) Get Node Protocol Info (Node=2): 0x01, 0x04, 0x00, 0x41, 0x02, 0xb8
2013-10-19 19:33:25.575 Node002, Queuing (Query) Query Stage Complete (ProtocolInfo)
2013-10-19 19:33:25.575 contrlr,     Node 003 - New
2013-10-19 19:33:25.575 Node003, AdvanceQueries queryPending=0 queryRetries=0 queryStage=ProtocolInfo live=1
2013-10-19 19:33:25.575 Node003, QueryStage_ProtocolInfo
2013-10-19 19:33:25.575 Node003, Queuing (Query) Get Node Protocol Info (Node=3): 0x01, 0x04, 0x00, 0x41, 0x03, 0xb9
2013-10-19 19:33:25.575 Node003, Queuing (Query) Query Stage Complete (ProtocolInfo)
2013-10-19 19:33:25.576 contrlr,   Expected reply was received
2013-10-19 19:33:25.576 contrlr,   Message transaction complete
2013-10-19 19:33:25.576 
2013-10-19 19:33:25.576 contrlr, Removing current message
jperkin commented 11 years ago

Oh, and your zwcfg*xml file? Thanks.

phillipsnick commented 11 years ago

@mrose17 does seem a little odd I'm getting this error, especially now I am seeing it on my Ubuntu box.

Wondering if it's something paired with my USB stick. Will give that a test now actually.

phillipsnick commented 11 years ago

@jperkin I don't seem to have one of those files. Is there something I need to do to create one?

I have a zwscene.xml file, which has no scenes defined by the looks of it.

<?xml version="1.0" encoding="utf-8" ?>
<Scenes xmlns="http://code.google.com/p/open-zwave/" version="1" />
jperkin commented 11 years ago

Ok, so I guess it's failing before getting a chance to write the file. From the logs it appears as though there are 3 devices paired, is that not to be expected? There is a soft reset call you can issue if you have old cached devices on the stick, I'll add support for calling that from node, it may help (and is useful anyway).

phillipsnick commented 11 years ago

I have paired 3 devices previously. And have just powered them all to test, still the same issue.

Also running the open zwave test application here is the next few lines which would appear after the above (included some repeat lines too)

2013-10-19 19:52:33.869 Node003, Queuing (Query) Query Stage Complete (ProtocolInfo)
2013-10-19 19:52:33.869 contrlr,   Expected reply was received
2013-10-19 19:52:33.869 contrlr,   Message transaction complete
2013-10-19 19:52:33.869
2013-10-19 19:52:33.869 contrlr, Removing current message
2013-10-19 19:52:33.869
2013-10-19 19:52:33.869 contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x06) - FUNC_ID_SERIAL_API_SET_TIMEOUTS: 0x01, 0x05, 0x00, 0x06, 0x64, 0x0f, 0x97
2013-10-19 19:52:33.871 contrlr,   Received: 0x01, 0x05, 0x01, 0x06, 0x64, 0x0f, 0x96
2013-10-19 19:52:33.871
2013-10-19 19:52:33.871 contrlr, Received reply to FUNC_ID_SERIAL_API_SET_TIMEOUTS
2013-10-19 19:52:33.871 contrlr,   Expected reply was received
2013-10-19 19:52:33.871 contrlr,   Message transaction complete
2013-10-19 19:52:33.871
2013-10-19 19:52:33.872 contrlr, Removing current message
2013-10-19 19:52:33.872
2013-10-19 19:52:33.872 contrlr, Sending (Command) message (Callback ID=0x00, Expected Reply=0x00) - FUNC_ID_SERIAL_API_APPL_NODE_INFORMATION: 0x01, 0x07, 0x00, 0x03, 0x01, 0x02, 0x01, 0x00, 0xf9
2013-10-19 19:52:33.873 contrlr, Removing current message
2013-10-19 19:52:33.873
2013-10-19 19:52:33.873 Node001, Sending (Query) message (Callback ID=0x00, Expected Reply=0x41) - Get Node Protocol Info (Node=1): 0x01, 0x04, 0x00, 0x41, 0x01, 0xbb
2013-10-19 19:52:33.876 Node001,   Received: 0x01, 0x09, 0x01, 0x41, 0x92, 0x16, 0x00, 0x02, 0x02, 0x01, 0x33
2013-10-19 19:52:33.876
2013-10-19 19:52:33.876 Node001, Received reply to FUNC_ID_ZW_GET_NODE_PROTOCOL_INFO
2013-10-19 19:52:33.876 Node001,   Protocol Info for Node 1:
2013-10-19 19:52:33.876 Node001,     Listening     = true
2013-10-19 19:52:33.876 Node001,     Beaming       = true
2013-10-19 19:52:33.877 Node001,     Routing       = false
2013-10-19 19:52:33.877 Node001,     Max Baud Rate = 40000
2013-10-19 19:52:33.877 Node001,     Version       = 3
2013-10-19 19:52:33.877 Node001,     Security      = false
2013-10-19 19:52:33.879 Node001,   Basic device class    (0x02) - Static Controller
2013-10-19 19:52:33.879 Node001,   Generic device Class  (0x02) - Static Controller
2013-10-19 19:52:33.879 Node001,   Specific device class (0x01) - Static PC Controller
2013-10-19 19:52:33.879 Node001,     COMMAND_CLASS_BASIC is not mapped
2013-10-19 19:52:33.879 Node001,   Mandatory Command Classes for Node 1:
2013-10-19 19:52:33.879 Node001,     None
2013-10-19 19:52:33.879 Node001,   Mandatory Command Classes controlled by Node 1:
2013-10-19 19:52:33.879 Node001,     COMMAND_CLASS_BASIC
2013-10-19 19:52:33.879 Node001,   Expected reply was received
2013-10-19 19:52:33.879 Node001,   Message transaction complete
2013-10-19 19:52:33.879
zonak commented 11 years ago

I was getting the mentioned error on my Mac before I installed the SiLabs USBtoUART driver - but after the driver installation everything worked fine. If the driver is installed maybe you want to check if you got the correct device name.

I also am getting the same error on a Ubuntu 13.04 and the RaspberryPi with the steward image.

Hope this info helps ...

mrose17 commented 11 years ago

zonak - hi. i'm glad to see that you're trying out the RPi with node-openzwave with a steward image. i'd like to have a conversation regarding node-openzwave and the steward, but i don't want to clutter up this issue. could i ask you to either email me at mrose17 at gmail dot com, or open an issue at https://github.com/mrose17/node-openzwave/issues ? thanks!

phillipsnick commented 11 years ago

@zonak what device name did you use on Mac, was it /dev/cu.SLAB_USBtoUART?

zonak commented 11 years ago

Yes, I am using /dev/cu.SLAB_USBtoUART for the device definition.

I re-installed 0.0.17 on the RPi and it works there too now - not sure what could be causing this but I'll keep trying to reproduce it and figure out if I am able to pinpoint a cause.