Advanced Plugin Logging

This topic idea came out of a discussion I had with Bill and he suggested I put it in its own topic. For those developing plugins (whether starting from scratch or just making some “minor” modifications for your specific system), it is often help to have debugging output. This allows you to trace when plugin callbacks are invoked and to access the internal state of the plugin (values of variables, functions being invoked, etc).

One easy way to get debugging output is by using the builtin console.log() facility, which will let you print a string into the log of the HR Designer. Many of the published plugins take this approach and it may be all that is needed in many cases. One potential drawback is that the log output is only available in the simulator of the Designer. When your HRP is loaded onto a device, these messages are suppressed/inaccessible. For many, that may not be a problem.

Both because I tend to make a lot of mistakes (and thus often want a lot of debugging output to dig through to see what is going on) and because the theater I control with my Home Remote is in my basement and my development machine is upstairs (and I don’t like running up and down the stairs all the time), I wanted a mechanism to access debugging information whether in the simulator or the app. I use the debugLog() function below in my plugins rather than console.log(), although it behaves in a similar manner.

In order to make use of debugLog(), you need to make a 3 minor changes to your plugin. First , you need to declare the following global variables:

var VERSION = "Plugin Version Number";
var debug = true;
var LOG_MAX = 5000;  // maximum size of the log in characters; set to 0 for unlimited
var LOG_TRIM = 500;  // when maximum size reached, trim the log plus this much more so not constantly trimming
  • VERSION is just a string to track the version number of your plugin. I just use the date, but the format doesn’t matter at all.
  • debug is a flag that let’s you globally turn on/off the debugging output. If set to false, no messages will be generated.
  • LOG_MAX and LOG_TRIM are used to control the size of the contents of the device.Log attribute so that it doesn’t get enormous. If you set LOG_MAX to 0, the log will not be trimmed.

Second, you need to include the debugLog() function itself:

function debugLog(s) {
    // Logs a string to both the console and the device Log attribute
    //  because the console is not available in the app.  It can also
    //  trim the device Log to keep it from growing too large if
    //  LOG_MAX is not 0.
    if(debug) {
        var device = plugin.Devices[plugin.Name];

        // is this the first time through?
        if(device && !device.Log) {
            // log is empty, so start it off with version info
            var verstr = plugin.Name + ": version " + VERSION;
            console.log(verstr);
            device.Log = verstr + "\n";
        }

        var logstr = plugin.Name + ": " + s;

        // send it to the console
        console.log(logstr);

        // send it to the device log
        if(device && device.Log) {
            device.Log += logstr + "\n";
           
            // trim the log if necessary
            if(LOG_MAX && (device.Log.length > LOG_MAX)) {
                device.Log = device.Log.slice(-(LOG_MAX + LOG_TRIM));
            }
        }
    }
}

Third , you need to add the “Log” Attribute to your device object. I do this through onSynchronizeDevices() with:

    device.Attributes = [ "Log" ];

But if you already have the device object created, you could also just select the device object under “Devices” and in the “Properties” pane, add “Log” to the Attributes:
attributes

Once you have done this, just use debugLog() instead of console.log() in your plugin and the logged messages are available through device.Log, which you can bind like any other device attribute. I built an interface in my remote to access the Logs for several of my plugins using a Page Browser and a Label:
log

Although it doesn’t show a vertical scroll bar, you can scroll it vertically as well. It has worked fairly well for me, especially when experimenting with different ways of sending commands and trying to observe the effect it has on the devices.

I hope this is helpful. In the interest of keeping my own published plugins clean, I’m probably (haven’t completely decided yet) going to strip most of the debugLog() functionality and just have it be a wrapper for console.log(), but in my own setup, I keep it live in all of my plugins. I like to be able to see the version information and confirm that the plugin is communicating correctly.

I’m interested in what other debugging techniques people use–I’ve refined this code over several iterations already and I’m sure there are more features/capabilities I could add to it. Happy to answer any questions or clarify anything above. Hope you find it useful!

HFN

2 Likes

I am just curious if I could use this technique to count the number of times a motion sensor was triggered? I know the debugLog will not show in HRP, will the debugLog function continue to work in the backgound?

I think that you could use a similar approach to expose a count to the rest of Home Remote. However, as @bill mentioned in the other thread, as soon as the screen turned off, plugins essentially resets their connection, so you would still have the same problems noted there and the plugin would not “see” any triggers during that time, so the count would not be accurate.

I can do my calculations in the SmartThings hub. But once I have the calculated value, what is the best way to get it to HA?

Is there a virtual device type that I should use and set its value to my calculated value? Or is there a better way?

I’m not sure, as I don’t know anything about SmartThings, but I would guess that you would access the value via Home Remote’s built-in SmartThings device. That would probably be a lot easier than writing your own plugin to retrieve the information.

I will try asking on an ST forum, but from the HA perspective I agree.

Thank you for posting this debug log technique. I’ve been using it for a Blue Iris plugin I’m working on. I did however have a problem running on IOS.

In the simulator it works fine. But on IOS, I was only seeing one line displayed. It took me a while to figure this out - but it seems the line … device.Log += logstr + “\n”; … isn’t working. I finally realized I needed it to change the code a bit and it’s working fine now.

device.Log = (device.Log).concat(logstr + “\n”);

On a side note: I have javascript for an MD5 hash function. Works in the simulator, but calculates the wrong value running on IOS. All JS must not be the same.

Thanks /keith

Thanks for letting me know, Keith! It is interesting that it doesn’t work on iOS, because that is the platform I was using also. I was running on an old iPad 4 (so not the latest version of iOS)–I wonder if Apple changed something, because I’m almost positive it worked fine for me (I at least never noticed anything missing in the logs). Maybe there’s something about iOS’s javascript implementation that also broke the md5 function? Very strange.

I’ve recently moved to a new house and don’t really have anything set up where I could test this out right now, but I will definitely make a note to update the plugin once I get my setup going again.

1 Like

Hi, @hotelfoxtrotnovember great advice on the additional debug logic. I’m still a little new to THR and not quite sure how to get the log do display in the app. You mentioned it’s a Page Browser and you bind it to the device.log but can you provide more details? I tried a few different things but I’m not getting it.

Thanks.

@gmhanna The simplest way to see the output is to just create a label on a page and bind the Text property to the device’s .Log attribute. Are you writing a plugin that uses the Advanced Logging stuff? Or have you added it to an existing plugin? Either way, you should be able to select the binding from the list for the Text property on the label (just like you would bind any other dynamic data to a label).

To be clear, you don’t need a Page Browser for just one device. I was trying to describe something a little more complicated I did, since I had written a number of plugins and wanted to be able to see debugging output for each of them. I created a page that just had a single Label on it and bound Text to @Device.Log. That way, I could then use a Page Browser on another page, point it at the label page, and set the Device property to the appropriate device I wanted to show the log for. It was mainly a way to save some screen space. You could just as easily have separate labels to show logs for each device at the same time.

I hope that’s clear, but if not, please let me know!

Perfect, thank you @hotelfoxtrotnovember!