Luup Debugging

Revision as of 19:16, 12 June 2009

This document assumes you have already read Luup_Intro for a general introduction to Luup, Luup_Plugins to learn what goes into a plugin, and that you are creating the Luup plugin using either the web-based Luup plugin generator (coming soon) or are creating Luup's XML files by hand as described here: Luup_Plugins_ByHand. This document will help you debug the Lua code that you write and see what's going on with your plugins.

To learn about Lua, see lua.org and the Lua reference manual which lists all the functions and variables that are built-in to Lua. Additionally, the Luup engine provides extra variables and functions you can call with your Lua code as documented here: Luup_Lua_extensions

Third party tools

There are a couple tools that will help a lot when debugging your plugin.

putty If you are using Microsoft Windows you can download a utility, putty, to login to Vera's console here: [1] You don't need to install putty. Just put the .exe file on your desktop, run it, and in the host name type in the IP address of Vera and click 'open'. At the login as: prompt enter the username: root and then when prompted enter the root password you setup.

DeviceSpy / Intel Tools for UPnP This is a set of tools for Microsoft Windows you can download here: [2] In particular we will be using the utility called DeviceSpy.

Luup logs

Vera is running Linux, and you can login to Vera's console to monitor the logs. Before Vera will let you login you must set a 'root' password. Do this by either going to Vera's Advanced, Net & Wi-fi tab and clicking 'Advanced configuration', or by opening a Windows command prompt and typing: telnet vera_ip (where vera_ip is the IP address of Vera). If you login with telnet, type: passwd and press enter to set a root password.

If you have a Mac or Linux PC you can now login directly to Vera using ssh. From the console type: ssh root@vera_ip (where vera_ip is the IP address of Vera). If you are using Windows, use putty as described above.

When you are at the root@HomeControl:~# prompt type in: cd /var/log/cmh to go to the log directory. The command: ls -lh lists all the log files. LuaUPnP.log is the main log file. To see everything that is being logged by Luup in real time is called "tailing the log". Do this by typing: tail -f LuaUPnP.log. To stop following the log press Ctrl+C. Press the up arrow to scroll through the recent commands to run them again by hitting enter, without retyping them.

Note that Vera doesn't have a lot of memory for the logs. So regularly you will see the logs say 'Going to rotate logs' and then stop. This means the memory filled up so the logs are being removed. If the check box in Vera's Advanced, Logs page "Archive old logs on findvera (recommended)" is checked, the logs will be sent to Mi Casa Verde's server and archived for 7 days before purging. TODO: We'll add instructions for logging to a USB memory stick so you have more room.

Each line starts with the log level and the date time, such as: 02 06/12/09 18:50:15.254

The first number, log level, has this meaning:

01=Critical error. Something is wrong that shouldn't happen

02=Warning. This is something to make note of, though it's not always a problem

03=StartStop. These log messages indicate Luup engine is starting/stopping. This happens every time you save configuration changes.

04=Job. This relates to 'jobs'

05=Home Automation. These logs are status messages from Home Automation devices

06=Variable. A UPnP Variable has changed

07=Event. An event is triggered. This is what you attach to a scene

08=Action. A UPnP Action was received

09=Enumeration. When the Luup engine starts this lists all the devices in the system.

10=General Status. There are lots of these messages to indicate something happening in the system.

40=outgoing data, 41=incoming data. This is all data coming and going to external devices, such as the Z-Wave dongle, in their raw form. This true for your Luup plugins talking to serial/network devices too.

50=Lua code. When you log something in Lua code using the lu_log function it has this log level.

200=UPnP message. There are a huge amount of logs generated from the UPnP engine showing all activity.

By default the Luup engine will skip logs with status 10 and 200 because they generate such a large amount of activity. Vera can actually be less reliable when 10 and 200 are activated because the logs grow so quickly sometimes that it is hard to archive them as fast as they come in. You can see what logs will shown by typing: cat /etc/cmh/cmh.conf. By default you will see: LogLevels = 1,2,3,4,5,6,7,8,9,50 meaning the Luup engine will log those log levels and ignore the rest. When you click 'Verbose logging' in Vera's web ui under setup, logs, you will see: #LogLevels = 1,2,3,4,5,6,7,8,9,50. The # in front means the log levels are ignored and all logs are stored, except UPnP. If you really want to see the UPnP messages, which will fill up the memory very fast, you can type: vi /etc/cmh/cmh.conf and move the cursor on top of the 0 in LogUPnP = 0. Then press r1 to replace the 0 with a 1, and then type :wq to write the changes and quit. These somewhat arcane commands are part of Linux's default text editor, vi. After you make a change, you will want to restart the Luup engine. Do this by clicking the 'save' button. Because you normally just want full logging temporarily, Luup will automatically revert to the default log levels after 4 hours unless you check 'Lock log levels' in Vera's Advanced, Log page.

To make sense of what's in the logs it's best to use grep and 'regular expressions'. If you're a true uber geek this is the greatest joy. If you're a mere mortal, it's best to just stick to some examples. In regular expressions the symbol ^ means 'show me lines that start with' and the symbol \| means 'or'. So here are some samples:

Show me everything in the log that is a 'critical error': grep '^01' LuaUPnP.log

I enabled Verbose logging, so incoming/outgoing data is logged, show me that plus any normal log messages (0-9) plus any log messages in my Lua code: grep '^0\|^4\|^5 (meaning any line that starts with 0, which 0-9, or 4, which is 40 and 41, or 5, which is 50.

I want the same data, but I want to follow the logs in real time with the same filter: tail -f LuaUPnP.log | grep '^0\|^4\|^5

You can also put in the 'grep' strings that you want to match. Let's say you see in the logs that every time a job status changes it logs using log level 10 (status) some line that includes the string: 'Job::m_eJobStatus'. You want to follow the logs and show just Lua logs, critical errors, and job status changes: tail -f LuaUPnP.log | grep '^5\|^01\|Job::m_eJobStatus.