View source for Luup Debugging

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 [http://www.lua.org/ lua.org] and the [http://www.lua.org/manual/5.1/ Lua reference manual] which lists all the functions and variables that are built into Lua.  

The [http://lua-users.org/wiki/TutorialDirectory Lua Tutorial], on [http://Lua-Users.org lua-users.org], can also be of great help here.

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

==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: [http://the.earth.li/~sgtatham/putty/latest/x86/putty.exe]  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 ''<tt>login as:</tt>'' prompt enter the username: ''<tt>root</tt>'' 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: [http://www.intel.com/cd/ids/developer/asmo-na/eng/downloads/upnp/tools/218896.htm?desturl=http://softwarecommunity.intel.com/isn/downloads/zips/IntelToolsForUPnPTechnology.zip]  We use 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.  

<tt>LuaUPnP.log</tt> 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.  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.
*41 - incoming data (as above)
*50 - Lua code.  When you log something in Lua code using the <tt>luup.log</tt> 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.
*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 <tt>#</tt> 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 <tt>luup.log</tt> (see [[Luup_Lua_extensions#function:_log|Luup_Lua_extensions log function]]) to see what's happening in your Lua code.

==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 <tt>luup.log</tt>.  

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

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

Always log critical errors, <tt>01</tt>, 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 <tt>lu_lua</tt> (See [[Luup_Requests#lu_lua|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 <tt>SetTarget</tt> action looks like this is within this function declaration:

  ''function SetTarget_run(lul_device,lul_settings)''

As explained in [[Luup_Declarations]] the <tt>lul_device</tt> 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 <tt>SetTarget</tt> action, which logs the device that received the UPnP Action (we'll use 10) and the argument <tt>newTargetValue</tt> 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 <tt>luup.log</tt> line from this test code, without the <tt>lul_device=</tt> and <tt>lul_settings=</tt> 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 <tt>lul_device</tt> and <tt>lul_settings</tt> to your Lua code.