ZWave Debugging

Advanced debugging for developers

Here are some hints on debugging ZWave 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 ZWave module. The log level for data that is sent to the ZWave dongle is 40 and for data received is 41. The log level for commands is 8 and for events is 7. Critical errors are 1, warnings are 5. Status messages are 10. 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, which is 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 ZWave serial bus type:

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

which means show log level 40 or 41. Normally Vera is polling all the nodes every few seconds, so the logs fill up quickly with ZWave 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, do:
/usr/bin/MessageSend localhost 0 9 1 966 5 0 (assuming the ZWave device is #9, as default).

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

Next you can send "COMMAND: #191 - Send Code" to either a ZWave Node and the parameter 9 (Text) is a command, or send it to the zwave 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 is 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 ZWave dongle), so the node id and 'send data' frame are assumed

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

ask node 4 (a thermostat) to report it's 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"

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. The 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\|^40\|^41\|^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\|^40\|^41\|^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 ZWave 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

Zwave Log Messages

Zwave 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"

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