ZWave Debugging

Revision as of 17:31, 6 February 2009

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'