ZWave Debugging

Latest revision as of 20:39, 14 June 2016

[edit] Custom device types or names based on Z-Wave ID's

In the configuration directory (normally /etc/cmh) is a file called zwave_products_sys.xml. This contains a list of hardcoded settings for various ZWave devices. The file is a series of values separated by tabs, with one entry on each line. The format is:

Manufacturer, Basic, Generic, Specific, ChildNumber, ProductType, ProductID, Devicefilename, ZWaveClass, Default name, Custom variables

When a Z-Wave device is added it is compared against this file. If the device's manufacturer ID, Basic ZWave device class, Generic device class, Specific device class, Product Type and Product ID match what's in the file, then rather than using the default device information, the device will use the UPnP XML device file in Devicefilename, and the ZWave class ZWaveClass, and will have the Default name, and the UPnP variables in "Custom variables". If any of Manufacturer, Basic, Generic, Specific, ChildNumber, ProductType, ProductID are not specified, it's considered a match. If any of Devicefilename, ZWaveClass, Default name, Custom variables are not specified, the default values are used. ChildNumber is when there's a multi-channel or multi-instance, this is what the child device will use.

For example, for the Express controls 3-in-1 sensor which has manufacturer 001E and Product Type/ID are 2 and 1, the 3 embedded children are forced to be a motion sensor, light sensor, temperature sensor.

001E				1	2	1	D_MotionSensor1.xml	
001E				2	2	1	D_LightSensor1.xml	
001E				3	2	1	D_TemperatureSensor1.xml	

zwave_products_sys.xml is distributed with each MIOS release, so any changes you make to it are lost on upgrade. However, you can add your own rows in the file: zwave_products_user.xml in the same folder with the same format. Those will be saved when you upgrade.

To get the source values (manufacturer id, product type, etc.) grep for UpdateNode in LuaUPnP.log.

[edit] Easy Z-Wave Debugging

[edit] Z-Wave specifics

Vera maps the command class BASIC to COMMAND_CLASS_SENSOR_BINARY, and responds to BASIC_GET or SENSOR_BINARY_GET with a _REPORT that has a value of 1 if Vera is running (ie it's always 1).

[edit] Advanced debugging for developers

Here are some hints for debugging Z-Wave protocol issues. You can access Vera by telnet, or if you already set a password, by ssh.

First, be sure you check the box "verbose logs" under 'Advanced', 'Logging', or, from a console run /usr/bin/VerboseLogging.sh enable.

The logs are in the directory /var/log/cmh. The first 2 digits are the 'log level'. The file: DCERouter.log contains the logging information from the core message router. The file: x-ZWave.log (where x is usually 9) contains all the logs from the Z-Wave module.

Log levels for data sent to the Z-Wave dongle:
01 = critical errors
02 = warnings
03 = start/stop/reload events
04 = jobs
05 = warnings
06 = variables (which indicates state changes)
07 = events
08 = commands
10 = status messages
41 = data sent to the Z-Wave dongle
42 = data received from the Z-Wave dongle
50 = luup log

For commands run in a scene, the logs won't be getting data from the user, but from a scene, so to see this requests, you should grep for RunScene .

For a complete list of the log levels, see the Luup Log Levels page.

So, if you want to watch the router's logs and see what commands are being sent to the various devices, do this:

cd /var/log/cmh
tail -f DCERouter.log | grep '^08'

Now from Vera's dashboard, send commands to the devices and you'll see them in the log. The | grep '^08' means to filter only lines that start with 08, meaning log level 08 ("Commands"). tail -f means "follow the log". To stop the tail and get back to the console, if you used ssh to login, you just press Ctrl+C. Unfortunately, often times telnet doesn't forward Ctrl+C, so, when using telnet you need to press Ctrl+Z and then type this to kill the tail command: killall tail; fg

To watch the traffic on the Z-Wave serial bus, type:

cd /var/log/cmh
tail -f 9-ZWave.log | grep '^41\|^42'

which means show log level 41 or 42. Normally Vera is polling all the nodes every few seconds, so the logs fill up quickly with Z-Wave traffic from the polling. If you want to turn off automatic polling temporarily for this session so the logs aren't cluttered with polling traffic, type:

/usr/bin/MessageSend localhost 0 9 1 966 5 0
(assuming the Z-Wave device is #9, as default, add 225 1 to make the change permanent)

To force a poll of device 13, type:
/usr/bin/MessageSend localhost 0 9 1 966 2 13 5 UPDATE

Next you can send "COMMAND: #191 - Send Code" to either a Z-Wave Node and the parameter 9 (Text) is a command, or send it to the Z-Wave device and it is a frame. The contents of text are a string of hex or decimal numbers separated with spaces, dashes or underscores, and hex values are preceded with 0x or x. So assuming a dimmable light is device 20 in node 15, either command below will dim it to 50%:

/usr/bin/MessageSend localhost 0 9 1 191 9 "0 x13 15 0x3 0x26 0x1 50 4 1" #send data (func id x13) to node 15 command class 0x26 command 0x1 (set multi level) to 10% (size=3) with transmit options=4 and funcid=1

/usr/bin/MessageSend localhost 0 20 1 191 9 "x26 x1 50" #send the message directly to device 20 (the node, not 9 the Z-Wave dongle), so the node id and 'send data' frame are assumed

--Luup update: wget "http://127.0.0.1:49451/data_request?id=lu_action&DeviceNum=1&serviceId=urn:micasaverde-com:serviceId:ZWaveNetwork1&action=SendData&Node=7&Data=x26-x1-20" node 7 to 20%

--Luup update: wget "http://127.0.0.1:49451/data_request?id=lu_action&DeviceNum=1&serviceId=urn:micasaverde-com:serviceId:ZWaveNetwork1&action=SendData&Data=0-x13-7-0x3-0x26-0x1-50-4-1" node 7 to 20%

/usr/bin/MessageSend localhost 0 14 1 191 9 "x85 2 1" #Tell device 14 to report its association group 1

Ask node 4 (a thermostat) to report its temperature: "0 0x13 0x4 0x2 0x40 0x2 5 1"

You can also put an R in front of the binary data, and include the full frame, and it simulates a received frame on the serial api, rather than sending a frame. So to simulate receiving a FUNC_ID_ZW_APPLICATION_UPDATE from node 1 run:
/usr/bin/MessageSend localhost 0 9 1 191 9 "R0x1 0x9 0x0 0x49 0x84 0x1 0x3 0x2 0x2 0x1 0x38"
or an encrypted message from node 29 with FUNC_ID_APPLICATION_COMMAND_HANDLER, COMMAND_CLASS_SECURITY: "R0x01 0x1C 0x00 0x04 0x00 29 0x16 0x98 0x81 0xEC 0xE1 0x10 0x56 0xFC 0x13 0xDF 0x04 0x45 0x60 0x24 0xA8 0x43 0x89 0xE8 0x22 0x36 0x15 0xA9 0xB1 0x1C"

--Luup update: wget "http://127.0.0.1:49451/data_request?id=lu_action&DeviceNum=1&serviceId=urn:micasaverde-com:serviceId:ZWaveNetwork1&action=SendData&Data=R0x1-0x16-0x0-0x4-0x0-0x4-0x10-0x8f-0x1-0x4-0x3-0x80-0x3-0x64-0x2-0x46-0x4-0x2-0x46-0x7-0x2-0x84-0x7-0x15"

Note that the logs will rotate regularly, meaning the DCERouter.log is archived as DCERouter.log.1.gz, and the old DCERouter.log.1.gz becomes DCERouter.log.2.gz. This is handled by the root cron process that runs /usr/bin/Rotate_Logs.sh.

Every time you do something with Vera this results in a "job". So let's assume you want to see what Vera is doing to configure a device. Type 'date' to see the date/time. Click the 'configure right now' button for the device. Type grep AddJob 9-ZWave.log to see all the log entries with 'AddJob' in them. Each one is given a number, and an abbreviated description. Say the first job after the 'date' is 10 01/26/09 16:35:51.640 JobHandler::AddJob job#6 :conf_jh#9 (0x00DD7390) P:40 S:0 <00DD7390> conf_jh#9 type ZWJob_ConfigureNode first 0 This means it's job#6, the name 'conf_jh#9' means it's a configure job from the main job handler for node #9. You may see lots of other jobs right after #6 to do things like set the Version/Manufacturer, set Associations, etc., because the main configure job (#6) may spawn many other jobs. To see all the log entries for job #6, type grep "job#6" 9-ZWave.log. Pay attention to the lines with m_eJobStatus which indicate the status, such as m_eJobStatus Job completed ok. Let's say you want to see what data is being sent/received as part of job#6, you could do this: grep 'job#6\|^41\|^42\|^01\|^05' 9-ZWave.log so you see all log entries for job #6, all incoming/outgoing data, plus critical errors (1) and warnings (5). Look for the line 'ready to run' in the logs, which will indicate where job #6 is starting. The logs are color coded, and the less that comes with busybox in Vera doesn't support the -R parameter to view the logs in color, which is much easier to read. So, you can set a root password if you haven't already (type passwd), and then use scp to copy the log files from Vera to another Linux/Mac/Windows with cygwin pc, and then run: grep 'job#6\|^41\|^42\|^01\|^05' 9-ZWave.log | less -R to see just the filtered portion of the logs in color.

You can also use MessageSend to send Vera's normal DCE commands directly to devices. The ID's are the same as LinuxMCE. You can also tail -f DCERouter.log | grep '^08'

From the console, if you want to see if a device is configured, enable verbose logging: /usr/bin/VerboseLogging.sh enable, restart the Z-Wave device: /usr/bin/MessageSend localhost 0 9 7 1 then wait for it to finish checking all the devices and grep UpdateNode 9-ZWave.log. You'll see: ZWaveJobHandler::UpdateNodes node 13 PK_DeviceTemplate 37 type ZWaveNonDimmableLight PK_Device 19 cap 0xc9 sec 0xc res 0x0 bas 0x4 gen 0x10 spe 0x3 config 1 LS (on/off)-45W-IPCAM classes 25,27,2b,2c,72,73,77,82,85,86,91,ef, config 1 means the device is configured. To reconfigure a device from the command line, send it command 776. For this device it would be: /usr/bin/MessageSend localhost 0 19 1 776.

Reset the Z-Wave network:
/usr/bin/MessageSend localhost 0 9 1 776 51 SIS

Do a 'soft reset' that doesn't lose any devices, but resets the dongle:
/usr/bin/MessageSend localhost 0 9 1 776 51 SOFT

[edit] Z-Wave Log Messages

[edit] Z-Wave LastNote

• Status="Aborted" LastNote="Timed out waiting for the node to reply"
• Status="Aborted" LastNote="Node is not configured"
• Status="Aborted" LastNote="Unable to get any information on node"
• Status="Aborted" LastNote="Transmit failed with code: 1": Code 1 means that Vera received no acknowledge from the device. This can happen either because the node is out of range, there are interferences or because of routing issues.

[edit] Remote Upgrade with preserve settings

curl -k -s -S --fail --retry 3 -o /tmp/firmware.img http://download.controlmyhouse.net/betafirmware/ftp/wl500gP-1.0.543.trx

/usr/bin/cmh-upgrade.sh

[edit] Z-Wave routing matrix

See http://forum.micasaverde.com/index.php?topic=2099.msg8292#msg8292 and http://forum.micasaverde.com/index.php?topic=5130.0.

[edit] Z-Wave stress test

Start a stress test of the Z-Wave network with this command. Stop by doing a /usr/bin/Reload.sh

wget "http://127.0.0.1:49451/data_request?id=lu_action&DeviceNum=1&serviceId=urn:micasaverde-com:serviceId:ZWaveNetwork1&action=SendData&Stress=X"

where X is:

#define STRESS_TEST_CONSTANT		1  // Constant BASIC_SET's
#define STRESS_TEST_NEIGHBOR_UPDATE	2  // Constant Neighbor updates
#define STRESS_TEST_WATCHDOG		3  // Constant Watchdog checks -- bugs in the Z-Wave serial API cause this to crash
#define STRESS_TEST_SOFT_RESET		4  // Constant soft resets

[edit] Dead battery operated devices

Vera does not flag malfunctioning battery operated devices on the GUI.

Use the following code to log all malfunctioning battery operated devices to a file:

http://forum.micasaverde.com/index.php?topic=5100.msg28346#msg28346

Use the following code to get email notifications about malfunctioning battery operated devices:

http://forum.micasaverde.com/index.php?topic=5130.0

[edit] Replace failed node

If you have a Z-Wave node that needs to be replaced with another of the same type, and you want the new node to have the same node ID, be sure the old defective node is removed and powered off. You must not try to connect it and power it up again. Connect or power on the new node that will replace it. It must be unpaired and ready to pair. Go to the 'advanced' section of the device and choose the 'commands' tab and click 'replace failed'. Then activate pairing on the new node. Wait a minute and the new node will be included with the same node id as the old one.

[edit] Demo Mode

Normally the state of a device changes after the Z-Wave command completes. If, for demos, you want to be able to show the state change immediately, whether or not the job actually succeeds, open this URL:

http://__ip_of_vera__:3480/data_request?id=lu_variableset&DeviceNum=1&serviceId=urn:micasaverde-com:serviceId:HaDevice1&Variable=SetState&Value=1

It takes effect on the next reload.

[edit] Not getting status changes with door locks, or door locks out of sync

This is a commonly reported problem. To debug this:

(1) Turn on verbose logging: click Advanced from the tool box, logs tab.

(2) Temporarily turn off polling so the logs don't have a bunch of background traffic: uncheck the poll nodes from the Z-Wave/options tab and click save. You can turn polling back on when you're done

(3) Wait a couple minutes after saving for Vera to settle down so the logs aren't going like crazy.

(4) Get Putty, a free Windows ssh client. Just google for putty download. You don't need to install it, just save it to your desktop. Run it, put Vera's IP in the host name, leave SSH checked and click Open. The user name is root and the password is on the bottom of Vera; it's the same as the wifi password or house id. If you don't see the root password see Logon # Can't find the root password?.

(5) Once you're logged in, type this command:

  tail -f /var/log/cmh/LuaUPnP.log | grep '^4\|^01\|HandlePoll\|^06'

(6) You'll be following (tailing) Vera's logs. grep is a filter to limit what you see to lines that start with 4 (which are the raw Z-Wave traffic--41 is traffic sent to Vera's Z-Wave chip, 42 is from the Z-Wave chip), lines that start with 01 are critical errors, lines that start with 06 are state changes, like lock/unlock, and lines containing the word HandlePoll indicate how Vera is handling any incoming data. See Luup_Loglevels If your tail command terminates, it means the logs rotated. Hit the up arrow to bring the command up again, and enter to restart it.

(7) Confirm that it's working by turning on and off a light from Vera's dashboard. You should see some ZWave traffic (41 and 42 lines), and a status change (06 lines) for Target and Status.

(8) Now have someone go next to the lock. Before they do anything hit enter a few times to add some blank space so you can clearly see if there's new log activity. If there's no log activity at all, not even 41 and 42 lines, that means there's no Z-Wave traffic. So the lock is not sending Vera any messages. If you see traffic, you should also see a status change (06 line) to indicate the door is now locked or unlocked. If you don't, copy what you see in putty by just highlighting it with the mouse. Putty automatically copies anything you copy into the clipboard. Paste it into an email you send to support.

[edit] Manual routing

If you are using Z-Wave 3.20, you can go to the advanced settings for a device, add a variable with the service id: urn:micasaverde-com:serviceId:ZWaveDevice1 and the variable name: ManualRoute and the value is a dot separated list of Z-Wave node ID's, just like the AutoRoute variable. The Auto route variable may be something like this: "2-20x,7-59x,2.7-78". This means there are 3 routes found. #1 uses node 2 as an intermediary, and it has a 'score' of 20. The score is a measure of latency and accuracy, the lower number is better. The 'x' that follows means the last attempt to use it failed, so it won't be used anymore. The next route uses node #7, it scored worse, and also failed. The 3rd route uses node 2 & 7. It had the worst score (78), but it's currently working (no x).

[edit] Very large Z-Wave networks

As part of the Heal/Repair process, each Z-Wave node is asked to discover all its neighbors. This is a standard Z-Wave function and is built into the Z-Wave module and is performed the same way on all Z-Wave controllers. The problem is that the amount of time it takes the Z-Wave network to perform this function grows exponentially based on the number of Z-Wave nodes. So in a really large Z-Wave network, with say 150 nodes, it can take more than 10 minutes per node to do the discovery, which means the heal process can take days. And during the Z-Wave node discovery the entire Z-Wave network is unavailable. We have a built-in watchdog, though, so that after 10 minutes it aborts the neighbor node discovery. Therefore, for large networks, the heal process may not complete at all and Z-Wave's built-in routing may never work. There is a solution which is to use MIOS routing instead. To do this, you need to build a network with the newer Z-Wave standard, 3.20. Go into Setup, Z-Wave Settings, Options. If the Version is not already 3.20, then check the option: Use Z-Wave version 3.20 instead of 2.78, then click save, then wait 5 minutes for it to re-flash the built-in Z-Wave chip, then go back into Setup, Z-Wave Settings, Advanced, and choose Reset Z-Wave network. After a minute, confirm the version is 3.20. Now check the option under Options "Use MiOS routing instead of Z-Wave (requires 4.5)", and uncheck "Limit neighbors to Z-Wave discovery (requries MiOS routing)". Then click Save. Pair your Z-Wave devices as normal. When you are all finished, do a repair network by choosing Z-Wave Settings, Repair, and click 'Go'. The Repair may take longer, however once it completes, you should be able to get a larger Z-Wave network to operate than you otherwise would.

[edit] Association

Z-Wave associations for a device are stored in the UPNP Variable service: urn:micasaverde-com:serviceId:ZWaveDevice1 variable: AssociationSet. You can view this by clicking the settings for a device, going to the advanced tab, and finding the AssociationSet variable. The associations are ; delimited, with the first digit being the group number followed by a comma separated list of nodes to be associated with that group. Note these are Z-Wave node ID's, not device ID's (ie the 'altid' in the UI). For multi-channel there is a . following the node id with the endpoint id. Example: 1,3.4,7;2,5.1,8 meaning group #1, node #3 endpoint #4, node #7 is non-multi-channel, group #2 is associated with node #5 endpoint #1, and with node #8.

[edit] Node version

The version info variable contains the version data reported by the node, like this: 3,2,78,3,62 Which is the library type, the zwave version & sub version, and the manufacturer version and sub version. So this node is running Z-Wave 2.78, manufacturer version 3.62.