2.3.0.111 : java.lang.RuntimeException: invalid time value 2021-11-24T20:30:00.000-0600

Not sure where the correct place is to post this, or to whom. There seems to be a change in 2.3.0.111 (from 2.2.9.146) in timeToString() conversion. This is on a C-7. I don't like to bother Bruce (@bravenel) or Victor (@gopher.ny) about something involving a community driver, but it appears that the error is coming from some change within the depths of the Hubitat code.

I'm using a Community integration (app and driver) (Sure PetCare (Connect)), ported to Hubitat from SmartThings by Dominick Meglio (@dman2306) that has been working fine through the past year, across every Hubitat firmware upgrade since Christmas 2020. This integration blew up with the 2.3.0.111 update, parent app throws an error (see subject line) every minute when it refreshes the related child device. The Sure PetCare Pet Door integration is my wife's favorite part of the Hubitat installation.

Here is log screenshot:

Log screenshot

If I revert back to 2.2.9.146, the errors stop. If I then update back to 2.3.0.111, the errors return, every minute. Repeatable. No changes have been made to the app or drivers or to their settings.

Background and Operation

The SureFlap Pet Door is a cloud-integrated device with its own hub (integrated to Hubitat). It senses the microchip in each cat's neck, and unlocks the Pet Door to allow the cat to enter and exit, and maintains a history and presence for each cat. Using either the Hubitat Pet Door user app, or the SureFlap mobile app, a Curfew window can be set during which the cats can enter but not leave. The curfew has not been changed, neither by the Hubitat Pet Door user app, nor by the SureFlap mobile app.

Once a minute the Hubitat Pet Door user app polls the Pet Door device and updates the curfew time (in case it was changed by the mobile app) and cat presence (in case the cats enter or leave), plus some other states. If I change the Curfew time (presently, lock pet door at 8:30 pm, unlock pet door at 4:00 am), either by Hubitat Pet Door user app or by the mobile app, the time value changes to the updated times (lock, unlock) and the error message changes appropriately, but still keeps happening.

Here is the code for the Groovy routine that is causing the error on line 694:

Refresh routine
def refreshDevices() {
	logDebug "Executing refreshDevices..."
    if (atomicState.refreshCounter == null || atomicState.refreshCounter >= 10) {
    	atomicState.refreshCounter = 0
    } else {
    	atomicState.refreshCounter = atomicState.refreshCounter + 1
    }
    def resp = apiGET("/api/me/start")
	getChildDevices().each { device ->
    	device.setStatusRespCode(resp.status)
        device.setStatusResponse(resp.data)
    	if (device.typeName == "Sure PetCare Pet") {
        	logDebug "High Freq Refreshing device ${device.typeName}..."
			device.refresh()
        } else if (device.typeName == "Sure PetCare Pet Door Connect") {
        	logDebug "High Freq Refreshing device ${device.typeName}..."
			device.refresh()
        	//Update curfew status
            def flap = resp.data.data.devices.find{device.deviceNetworkId.toInteger() == it.id}
            if (flap.control.curfew && !flap.control.curfew.isEmpty()) {
				def curfewObject = flap.control.curfew[0] ?: flap.control.curfew
            	app.updateSetting("curfewEnabled#${device.deviceNetworkId}", [type: "bool", value: true]) 
                app.updateSetting("starting#${device.deviceNetworkId}", [type: "time", value: timeToString(curfewObject.lock_time, "yyyy-MM-dd'T'HH:mm:ss.SSSXX")]) 
                app.updateSetting("ending#${device.deviceNetworkId}", [type: "time", value: timeToString(curfewObject.unlock_time, "yyyy-MM-dd'T'HH:mm:ss.SSSXX")]) 
            } else {
            	app.updateSetting("curfewEnabled#${device.deviceNetworkId}", [type: bool, value: false]) 
            }
        } else if (atomicState.refreshCounter == 10) {
        	logDebug "Low Freq Refreshing device ${device.name} ..."
            try {
    			device.refresh()
        	} catch (e) {
        		//WORKAROUND - Catch unexplained exception when refreshing devices.
        		logResponse(e.response)
        	}
        } 
	}
}

The line (694) throwing the error is the "starting" time:

app.updateSetting("starting#${device.deviceNetworkId}", [type: "time", value: timeToString(curfewObject.lock_time, "yyyy-MM-dd'T'HH:mm:ss.SSSXX")])

I believe that the following line, for the "ending" time, would throw a similar error if it were ever reached.

Because I can't look into the Hubitat built-in timeToString() or app.updateSetting() code, I really don't know what changed between 2.2.9.146 and 2.3.0.111.

The code for the app that is throwing the error is here:

The code for the three drivers is here:

The ported integration thread is here:

Anyone have any ideas on how to change the time format string to accommodate changes in 2.3.0? Or, is anyone else seeing time conversion errors with 2.3.0?

+1 same error different device

1 Like

Ah yes, there's a change in updateSetting with type time. It's checking time format instead of just failing silently. String time format should be HH:MM (updateSetting validates the string now), or parameter can be a Date object, and updateSetting will pull the time out of it using whatever time zone that Date object has.

1 Like

Get rid of the single quotes around the character T that separates the date and time components.

This doesn't work. See Victor's post above. Must be HH:MM or date object, not full time string.

Oh.. this is a clear indicator for me to wait until this has been fixed. This integration also happens to be my wife's favorite home automation ! :slight_smile:

Thanks, Victor. That fixed it. Changed the type to "Date" (from "time") on the two app.updateSetting() lines:

  app.updateSetting("starting#${device.deviceNetworkId}", [type: "Date", value: timeToString(curfewObject.lock_time, "yyyy-MM-dd'T'HH:mm:ss.SSSXX")]) 
  app.updateSetting("ending#${device.deviceNetworkId}", [type: "Date", value: timeToString(curfewObject.unlock_time, "yyyy-MM-dd'T'HH:mm:ss.SSSXX")])

And the resulting app works on both 2.2.9.146 and 2.3.0.111. Thanks so much. I'll pass this on to Dominick Meglio (@dman2306).

I didn't see anything about change in updateSetting in the release notes.

EDIT:

Unrelated Red Herrings

As a comment, when the hub restarted after I edited these two lines, tested on 2.2.9.146, then tried to update, which spun forever and never began the update process, so I reverted to 2.3.0.111 using the previous version on the Hub, I got the Server Error 500 that Victor addressed in another thread, and the following error appeared in the logs:

Edit: The Excluded attribute hubUpdateResp error by the Dashboard app was caused by Jean May's (@thebearmay's) Hubitat Information driver, due to the fact that his attribute was getting filled with the entire voluminous 2.3.0 Release Notes. He has since updated his driver code to version 2.6.10 (on GitHub and Hubitat Package Manager), and the Excluded attribute error appears no more. This was just a red herring, unrelated to the updateSetting() issue described and fixed in this thread.

A reboot from Settings fixed everything, and now everything is well.

Thanks so much, Victor.

1 Like

Ok, thought the regex didn't allow for that.

This is a different context completely. And, it pertains to the built-in type of object called 'time'. That's not a Hub Variable type, but rather one used in the UI to bring up a time selector (which does return a full time string). It's confusing, and has tripped me up at least twice.

1 Like

Is there an actual fix coming or is the code/hub change actually doing what it is supposed to do now? :man_shrugging:
I'm not a coder so wouldn't know.
Can you clarify @gopher.ny? Thanks.

The code is doing what it's supposed to, yes.

2 Likes

I believe that's why making the change that Victor suggested now works on 2.2.9.146 and on 2.3.0.111, as I tested and noted above.

@Kulfsson
Looks like you may need to visit your code.
Unless of course you are talking about the OP's code.

1 Like

I believe, from context, he is talking about the same Integration that I have. Accordingly, lines 694 and 695 need to be changed from type: "time" to type: "Date" as I noted above. That's a forward and backwards compatible change.

1 Like

2 posts were split to a new topic: RM 5.1 error?

I think the solution is in here now, so I would be able to use the same fix as suggested. I'll hang on for some time though, not wanting to stir the pot so close to holidays :slight_smile:

2 Likes

Kristjan, I understand your hesitancy.

The fix that I implemented, based on Victor's discussion, has worked now for over 4 hours without error, whereas the errors started immediately upon 2.3.0.111 update, with errors every minute. That's why I wanted to understand the fix, make a minimal change that was the "right" change, and to test it for forwards and backwards compatibility before I let it run and posted my results here, and why I twice edited my post above to identify unrelated red herring issues.

Here is my comment. If you make the simple changes to lines 694 and 695 of the app, back up your database first (of course) so that you could back out the changes by a simple Restore of that backed up database. Or, you could always use Hubitat Package Manager to Repair the integration. That way, you can test the fix independently of doing the 2.3.0 update. I am a cautious person, and prefer to make one change at a time, rather than lots of changes at a time, so that I can identify the failure point if something goes wrong. It should only take a few minutes to back up your database, make the two simple edits, save the edited app, and let things keep running.

Regarding the 2.3.0 update, it seems very solid, appears to have been thoroughly tested, and can mitigate another problem that the SureFlap integration has. Specifically, this integration produces an enormous number of events, and has an enormous state size. Take a look at the Device page for your SureFlap Hub and each pet. And, on events, note that the SureFlap Hub is polled every 10 minutes for, among other things, its firmware level, the Hub name, its MAC address, its firmware level, etc. It gets an event each minute for each pet's microchip number. I certainly hope you are not changing your pet's microchip numerous times an hour. That's way too many events for stuff that only rarely changes.

You may not see it, but my SureFlap integration pushes about 325 events an hour, which is just over the 300 event threshold for a warning message. As a temporary mitigation, if you are seeing the event warning, then, with the 2.3.0 firmware update, you can set, on a device or app level, the warning threshold for spammy apps and devices. I set mine at 350 for the SureFlap app, to temporarily stop this. But it's still generating a load on the Hubitat hub, by far the biggest load of any integration or device.

Going forward, I'm going to make a pass through the code and see about reducing the burden on the Hubitat hub. But that won't happen over Thanksgiving.

Anyway, you might want to stay on whatever Hubitat firmware you have, make the two small changes to the app code, and let it run for awhile to convince you that the change does exactly what Victor said it would - type: "Date" is the proper type for the updateSetting() call to use. Then, independently, you can evaluate the 2.3.0 update as you wish.

1 Like

Thanks, I updated the lines with Date and so far it looks good.

I also see the big amount of events, and have been slightly worried about in the past, but the percentage used of hub resources is still small, so haven´t worried. Would be good if it can be tempered a bit so it takes less resources.

2 Likes