Luup Debugging

Latest revision as of 07:20, 18 June 2013

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 into Lua.

The Lua Tutorial, on lua-users.org, can also be of great help here.

Additionally, the Luup engine provides a set of Extensions (variables and functions) you can call within your Lua code.

[edit] Third party tools

There are tools that will aid you in 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. If you don't see the root password or need help logging in see Logon # Can't find the root password?.

• DeviceSpy / Intel Tools for UPnP This is a set of tools for Microsoft Windows you can download here: [2] We use the utility called DeviceSpy

[edit] Luup logs

Vera is running Linux, and you can login to Vera's console to monitor the logs. A special user, called root, is used to login to Vera. The password setup mechanism is different between Vera1 or a Vera2 models.

[edit] Logging in on Vera1

The root password must first be set in Vera's configuration menu's. Do this by either going to Vera's Advanced, Net & Wi-fi tab and clicking 'Advanced configuration'

Alternatively, at a Windows prompt, you can type 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.

[edit] Logging in on Vera2 and Vera3

The root password for a Vera2 or Vera3 box is printed on a label on the underside of the box.

[edit] Getting around

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.
• 41 - Outgoing data. This is all data going to the external devices, such as the Z-Wave dongle, in their raw form. This is also true for your Luup plugins talking to the serial/network devices too.
• 42 - Incoming data. (as above)
• 50 - Lua code. When you log something in Lua code using the luup.log function it has this log level.
• 51 - Raw outgoing Serial data, from any Serial port attached to the Plugin.
• 52 - Raw incoming Serial data, from any Serial port attached to the Plugin.
• 61 - Outgoing Insteon data
• 62 - Incoming Insteon data
• 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' LuaUPnP.log

(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'

When you are writing your Lua code, include copious logging with luup.log (see Luup_Lua_extensions log function) to see what's happening in your Lua code.

[edit] Debug in small chunks without restarting each time

If you are adding code for an action, it takes time to upload your files and initiate the action. So it's best to debug the Lua code in tiny bite sized pieces first to be sure the syntax and basic operation is ok.

In Vera's web ui choose Devices, Luup plugins and click 'Test Lua UPnP code'. For the device number put in the number of the device you are debugging, which is shown when you click the + button next to the device. Or, if your Lua code isn't going to be calling any of the functions and variables you created in that device, you can just put in a device number of 0, which means this snippet of code runs by itself. If you put in a valid device number for a Luup plugin, it runs in the context of that device meaning it can call the other functions and variables in the plugin.

Put your small chunk of code in the input box and click 'go' to run it. Be sure the code outputs something to the log with luup.log.

In another console or putty window you can be following the logs with:

 tail -f LuaUPnP.log | grep '^01\|^5'

Always log critical errors, 01, because that way if your Lua code won't run due to a syntax error you will see the log entry.

In the real implementation your Lua code will probably be passed variables. For example, if the Lua code being run is in response to an action, it will be passed as a variable the arguments to the UPnP action. To test your small blocks of code with this you can simply add the same variable names and hardcode some test variables. The list of variables that are passed to your Lua code are documents here: Luup_Declarations. You can also see the complete Lua code that the Luup engine has generated including the function declarations with the lu_lua (See Luup_Requests lu_lua) request on the URL.

For example, I will view the complete Lua code for device #8:

 http://vera_ip:49451/data_request?id=lu_lua&DeviceNum=8

and I can see that the Lua code I put in my 'run' XML tag in the implementation file for the SetTarget action looks like this is within this function declaration:

 function SetTarget_run(lul_device,lul_settings)

As explained in Luup_Declarations the lul_device will the device number that is receiving the command. So if I want to test some Lua code that I will put inside a 'run' tag for the SetTarget action, which logs the device that received the UPnP Action (we'll use 10) and the argument newTargetValue which indicates if the device is being turned on or off, then I would put in the test code:

 lul_device=10
 lul_settings['newTargetValue']=1
 luup.log("Got a SetTarget action for device " .. lul_device .. " to turn on/off: " .. lul_settings['newTargetValue'])

now when you click 'go' see what goes in the Log. If your log entry is ok, copy the luup.log line from this test code, without the lul_device= and lul_settings= lines, into the actual implementation and you know that it will work when the real UPnP action is called and the Luup engine passes the actual lul_device and lul_settings to your Lua code.