runIn() lag from the simulator?

General Discussion
1

I’m working on a simple SmartApp that just tells me if I left a door open by checking a contact sensor and sending a notification (or two) to my phone. Here’s the code:

/**
 *  Door Open Too Long
 *  Send a notification if a door (contact sensor) has been left open for too long,
 *  followed by an optional second notification.
 *
 *  Author: Joe Angell
 */
preferences {
	section("When it opens..."){
		input "contact1", "capability.contactSensor"
	}
	section("For this amount of time...") {
		input name: "minutes1", title: "Minutes", type: "number"
    }
	section("Send second notification after... (optional)") {
		input name: "minutes2", title: "Minutes", type: "number", required: false
	}
	section("Then send this message in a push notification"){
		input "messageText", "text", title: "Message Text"
	}
	section("And as text message to this number (optional)"){
		input "phone", "phone", title: "Phone Number", required: false
	}
}

def installed() {
	log.debug "Installed with settings: ${settings}"
	subscribe(contact1, "contact.open",   contactOpenHandler)
	subscribe(contact1, "contact.closed", contactClosedHandler)
}

def updated(settings) {
	log.debug "Updated with settings: ${settings}"
	unsubscribe()
	subscribe(contact1, "contact.open",   contactOpenHandler)
	subscribe(contact1, "contact.closed", contactClosedHandler)
}

def contactOpenHandler(evt) {
	log.debug "$evt.name: $evt.value:  Arming notification for $minutes1 minutes"

	unschedule("doNotification1")
	unschedule("doNotification2")

	runIn(minutes1 * 60, "doNotification1")
}

def contactClosedHandler(evt) {
	log.debug "$evt.name: $evt.value:  Canceling notification"
	unschedule("doNotification1")
	unschedule("doNotification2")
}

def sendNotification() {
    sendPush(messageText)
    if (phone) {
        sendSms(phone, messageText)
    }
}

def doNotification1(evt) {
	log.debug "First notification: $contact1.contact, event $evt"

    sendNotification()

	unschedule("doNotification1") // Temporary work-around to scheduling bug

	if (minutes2) {
		log.debug "$evt.name: $evt.value:  Arming second notification for $minutes2 minutes"
    	runIn(minutes2 * 60, "doNotification2")
    }
}

def doNotification2(evt) {
	log.debug "Second notification: $contact1.contact, event $evt"

	sendNotification()

	unschedule("doNotification2") // Temporary work-around to scheduling bug
}

I used the Curling Iron and Notify Me When examples to test it.

When run in the simulator with “minutes1” set to 1 with a virtual contact sensor, it seems to take a much longer than one minute for the task to run. It actually takes a really long time for anything to happen (tens of seconds to over a minute), such as registering that I flipped the virtual contact sensor to “closed” and back to “open”.

Here’s the output from a test run. You can see that it took 10 minutes from when runIn() was armed (the “Scheduling ‘doNotification1’” bit) to when it actually triggered (the “First Notification” bit), even though it should have only been 60 seconds. (As an aside, I’m not sure what the “error” at the top of the log is complaining about, exactly.)

12:14:32 PM EDT: error Cannot get property 'name' on null object
12:14:21 PM EDT: trace Deleting scheduled job 'doNotification1' for InstalledSmartApp: 8a68b42c3f434b98013f4d8ecef12ba2
12:14:20 PM EDT: debug First notification: physicalgraph.app.AttributeWrapper@1f006e5d, event null
12:04:43 PM EDT: trace Scheduling 'doNotification1' for InstalledSmartApp: 8a68b42c3f434b98013f4d8ecef12ba2
12:04:35 PM EDT: trace Deleting scheduled job 'doNotification2' for InstalledSmartApp: 8a68b42c3f434b98013f4d8ecef12ba2
12:04:28 PM EDT: trace Deleting scheduled job 'doNotification1' for InstalledSmartApp: 8a68b42c3f434b98013f4d8ecef12ba2
12:04:28 PM EDT: debug contact: open: Arming notification for 1 minutes
12:04:28 PM EDT: trace Deleting scheduled job 'doNotification2' for InstalledSmartApp: 8a68b42c3f434b98013f4d8ecef12ba2
12:04:22 PM EDT: trace Deleting scheduled job 'doNotification1' for InstalledSmartApp: 8a68b42c3f434b98013f4d8ecef12ba2
12:04:22 PM EDT: debug contact: closed: Canceling notification
12:04:16 PM EDT: trace contact.closed from contact1 was provided with contactClosedHandler...creating subscription
12:04:16 PM EDT: trace contact.open from contact1 was provided with contactOpenHandler...creating subscription
12:04:16 PM EDT: trace Door Open Too Long is attempting to unsubscribe from all events
12:04:16 PM EDT: debug Updated with settings: null

Note that timing-related events seem much be much more accurate when installed as an app from my phone, although I didn’t use a stopwatch to see how accurate it is or anything like that. It seems to be an issue specific to the simulator, which makes it difficult to test timing-based code.

I also had some problems with triggering notifications sent from the simulator. It seems to be working OK at the moment, and works fine when the app is running in the real word, but from the simulator it seemed unreliable. I’m going to chalk that up to a problem with an earlier version of my code for now.

Thanks!

– Joe

2

A follow-up on this: I published the SmartApp and it into service on my basement door – meaning, this was NOT running in the simulator. The hub shows the log for the basement door to be like so:

16 Jun 2013 22:15:21 - moments ago	Basement Door was inactive
16 Jun 2013 22:15:14 - moments ago	Basement Door was closed
16 Jun 2013 22:15:10 - moments ago	Basement Door was opened
16 Jun 2013 22:15:10 - moments ago	Basement Door was active
16 Jun 2013 22:05:58 - 10 minutes ago	Basement Door was inactive
16 Jun 2013 22:05:52 - 10 minutes ago	Basement Door was closed
16 Jun 2013 22:05:47 - 10 minutes ago	Basement Door was opened
16 Jun 2013 22:05:47 - 10 minutes ago	Basement Door was active

As you can see, the basement door was was open for no more than 4 seconds at any given time, but I got a notification that it was still open for at least a minute. I did only get one notification, though, so it only had a problem with the timers in one case – unless there’s a bug in my code, that is.

As I was writing this, I got another notification that the door was open (mostly because I had previously run downstairs to make sure the door really was closed, opened it to make sure the sensor hadn’t fallen off, and closed it again. This notification was ~12 minutes after the door closed – well beyond the one minute mark I set, or even second 5 minute mark (which is 6 minutes total).

Is there a way to get a log for the app itself, similar to what is seen from the emulator but for a published app? I looked around but didn’t see anything obvious.

Speaking of notification, it would be nice to be able to remove a previously sent notification if it has been resolved. iMessage and Mail on iOS do this – if you read the message/mail on another device, the notification is removed from your queue. It would be cool to be able to do the same with SmartThings – once the basement door is closed, I’d like it to automatically remove the previously-sent notification via a function call, thus ensuring that notifications on my phone actually reflect the current system state.

Thanks again

– Joe

3

I decided to hack around the problem of runIn() tasks apparently not obeying unschedule() by checking the see if the contact sensor was still open when the callback is tripped. I actually had this in the first version of my code, but couldn’t figure out how to get it to work. I managed to find an example that implemented it (I think it was the over-automated garaged door opener one), so I was able to update my SmartApp with it.

Incidentally, it would be very handy to have more information about the language used to write SmartApps. It’s clear that you can write functions, but it’s not clear how to pass arguments and return values. This would have allowed me to have doNotification1 and doNotification2 call a common function to simplify the code. The updated code is below.

Hopefully over time the unsubscribe() issue and the runIn() lags will get fixed, we’ll get some more docs, etc. (my day job is writing an application with a public SDK, and we also have issues providing adequate documentation to third party developers, so I understand how it goes). SmartThings are still pretty new, and I don’t get too much time to play with coding SmartApps anyway, so I can be patiently impatient. :slight_smile:

Thanks!

– Joe

/**
 *  Door Open Too Long
 *  Send a notification if a door (contact sensor) has been left open for too long,
 *  followed by an optional second notification.
 *
 *  Author: Joe Angell
 */
preferences {
	section("When it opens..."){
		input "contact1", "capability.contactSensor"
	}
	section("For this amount of time...") {
		input name: "minutes1", title: "Minutes", type: "number"
    }
	section("Send second notification after... (optional)") {
		input name: "minutes2", title: "Minutes", type: "number", required: false
	}
	section("Then send this message in a push notification"){
		input "messageText", "text", title: "Message Text"
	}
	section("And as text message to this number (optional)"){
		input "phone", "phone", title: "Phone Number", required: false
	}
}

def installed() {
	log.debug "Installed with settings: ${settings}"
	subscribe(contact1, "contact.open",   contactOpenHandler)
	subscribe(contact1, "contact.closed", contactClosedHandler)
}

def updated(settings) {
	log.debug "Updated with settings: ${settings}"
	unsubscribe()
	subscribe(contact1, "contact.open",   contactOpenHandler)
	subscribe(contact1, "contact.closed", contactClosedHandler)
}

def contactOpenHandler(evt) {
	log.debug "$evt.name: $evt.value:  Arming notification for $minutes1 minutes"

	unschedule("doNotification1")
	unschedule("doNotification2")

	runIn(minutes1 * 60, "doNotification1")
}

def contactClosedHandler(evt) {
	log.debug "$evt.name: $evt.value:  Canceling notification"
	unschedule("doNotification1")
	unschedule("doNotification2")
}

def sendNotification() {
    sendPush(messageText)
    if (phone) {
        sendSms(phone, messageText)
    }
}

def doNotification1(evt) {
	log.debug "First notification: $contact1.contact, event $evt"

	def currentState = contact1.currentState("contact");
	if (currentState?.value == "closed") {
		log.debug "Door was closed; nothing to do"

	} else {
        sendNotification()
        
        if (minutes2) {
            log.debug "$evt.name: $evt.value:  Arming second notification for $minutes2 minutes"
            runIn(minutes2 * 60, "doNotification2")
        }
    }

    unschedule("doNotification1") // Temporary work-around to scheduling bug
}

def doNotification2(evt) {
	log.debug "Second notification: $contact1.contact, event $evt"

	def currentState = contact1.currentState("contact");
	if (currentState?.value == "closed") {
		log.debug "Door was closed; nothing to do"

	} else {
		sendNotification()
    }

	nschedule("doNotification2") // Temporary work-around to scheduling bug
}