Webcore Missing Executions

Bry · 2020-04-26 13:51:33 UTC

1) Give a description of the problem
Simple piston to turn lights on and off is missing executions

2) What is the expected behaviour?
Light on at 10 min past sunset, off at 10 minutes to sunrise

3) What is happening/not happening?
This piston has been working well for a while, but lately, some events have failed to fire. See the logs below. For example, the lights turned off as scheduled yesterday morning. They did not turn on as scheduled last night, so I turned them on manually at the switch. This morning, the lights did not turn off as scheduled.

Looking for an explanation/solution.

Thanks!

**4) Post a Green Snapshot of the piston![image|45x37]

5) Attach logs after turning logging level to Full

4/26/2020, 5:59:59 AM +97ms
+1ms ╔Received event [Ocean City].time = 1587895200000 with a delay of -903ms
+140ms ║Runtime (36957 bytes) successfully initialized in 75ms (v0.3.110.20191009) (139ms)
+141ms ║╔Execution stage started
+211ms ║║Error while executing physical command OC Front Lights.off([]): java.lang.reflect.UndeclaredThrowableException
+213ms ║║Executed [OC Front Lights].off (19ms)
+216ms ║╚Execution stage complete. (75ms)
+218ms ║Setting up scheduled job for Sun, Apr 26 2020 @ 7:58:00 PM EDT (in 50280.686s), with 1 more job pending
+224ms ╚Event processed successfully (224ms)

4/25/2020, 8:07:00 PM +125ms
+0ms ╔Received event [Ocean City].execute = recovery with a delay of 82ms
+136ms ║Runtime (36948 bytes) successfully initialized in 72ms (v0.3.110.20191009) (135ms)
+137ms ║╔Execution stage started
+186ms ║╚Execution stage complete. (48ms)
+187ms ║Setting up scheduled job for Sun, Apr 26 2020 @ 6:00:00 AM EDT (in 35579.688s), with 1 more job pending
+195ms ╚Event processed successfully (195ms)

4/25/2020, 6:00:59 AM +59ms
+0ms ╔Received event [Ocean City].time = 1587808860000 with a delay of -942ms
+142ms ║Runtime (36955 bytes) successfully initialized in 70ms (v0.3.110.20191009) (140ms)
+143ms ║╔Execution stage started
+1190ms ║║Executed [OC Front Lights].off (993ms)
+1194ms ║╚Execution stage complete. (1051ms)
+1195ms ║Setting up scheduled job for Sat, Apr 25 2020 @ 7:57:00 PM EDT (in 50159.746s), with 1 more job pending
+1283ms ╚Event processed successfully (1282ms)

Terminal · 2020-04-26 15:58:08 UTC

I have gotten a few of the “java.lang.reflect.UndeclaredThrowableException” errors on normal device turn on and offs. I got one yesterday on my piston to enable my cameras. It has happened a few other times as well. Here is the one from yesterday. It does three cameras the other two went fine. It’s in a loop for three cameras.

This is the error I got, the same as your’s.
Error while executing physical command Front Door Camera.on([]): java.lang.reflect.UndeclaredThrowableException

orangebucket · 2020-04-27 07:03:54 UTC

Your logs show that the ten minutes past sunset timer event wasn’t received. A recovery event fired ten minutes later so the ten minutes to sunrise wake up was able to be scheduled.

Seems to be happening a lot with ST of late. In my case the timer events getting missed are the ones my motion device handlers depend on to reset to inactive.

There have bee frequent status messages about problems in the Americas, though I am getting clobbered in the UK.

Bry · 2020-04-28 00:37:22 UTC

Thanks. Got errors on 2 different switches tonight. The same switch and another switch. Didn’t have logging turned on for the other switch, but the error message is more verbose. It seems to make references to the DH. These are both Inovelli switches with their custom DH. Could the custom DH be factoring in here?

Error while executing physical command OC Party Lights.on([]): org.springframework.dao.InvalidDataAccessResourceUsageException: could not load an entity: [physicalgraph.device.DeviceTypeHandler #4a4848be-f1e5-4544-8536-96041e92753d]; SQL [select devicetype0_.id as id39_0_, devicetype0_.version as version39_0_, devicetype0_.checksum as checksum39_0_, devicetype0_.code as code39_0_, devicetype0_.date_created as date5_39_0_, devicetype0_.device_type_id as device6_39_0_, devicetype0_.handler_version as handler7_39_0_, devicetype0_.last_updated as last8_39_0_, devicetype0_.state as state39_0_ from device_type_handler devicetype0_ where devicetype0_.id=?]; nested exception is org.hibernate.exception.SQLGrammarException: could not load an entity: [physicalgraph.device.DeviceTypeHandler #4a4848be-f1e5-4544-8536-96041e92753d]

lflorack · 2020-04-28 12:37:05 UTC

Me too. For the past few days, there’s lots of things like this:

║Error while executing physical command Thermostat.setCoolingSetpoint([73.0]):
org.springframework.dao.InvalidDataAccessResourceUsageException: could not
load an entity: [physicalgraph.device.DeviceTypeHandler
#c37c6f62-0fae-454e-9f50-5e0d523f500e]; SQL [select devicetype0_.id
as id55_0_, devicetype0_.version as version55_0_, devicetype0_.checksum
as checksum55_0_, devicetype0_.code as code55_0_,
devicetype0_.date_created as date5_55_0_, devicetype0_.device_type
id as device6_55_0, devicetype0_.handler_version as handler7_55_0_,
devicetype0_.last_updated as last8_55_0_, devicetype0_.state as
state55_0_ from device_type_handler devicetype0_ where devicetype0_.id=?];
nested exception is org.hibernate.exception.SQLGrammarException: could not load
an entity: [physicalgraph.device.DeviceTypeHandler
#c37c6f62-0fae-454e-9f50-5e0d523f500e]

and this:

║Error while executing physical command Thermostat.setHeatingSetpoint([67.0]):
java.lang.reflect.UndeclaredThrowableException

and this:

║Piston waited at a semaphore for 7787ms

Also, some pistons not firing at all and then the errors are interspersed with hours of the exact same pistons and devices running without errors.

Seems that ST is messing things up on their end.

ST Support request #944307

Pantheon · 2020-04-28 12:44:52 UTC

I have been reading similar posts in the ST forum. I have not noticed any hiccups in either system recently. At least my wife hasn’t voiced any concerns. She is my true benchmark for how things are running

Bry · 2020-04-28 16:38:03 UTC

So is there anything in the logging to indicate where the failure lies? i.e. ST, or webCore?

smartie · 2020-04-28 18:06:50 UTC

Just received the same - didn’t open the shades.

lflorack · 2020-04-28 20:02:44 UTC

Here’s an email thread with ST Help Desk (newest in thread is at the top)

Tejaswi,

My thermostat is not the issue. As I said in the title, there are many errors with many different devices:

Undeclared Throwable Exceptions
Semaphores
General slowness of many automations
Intermittent skipping of actions
Loss of commands (some make it to the device, others don’t
Errors while executing physical commands

Then hours of no errors when everything runs fine – which my system was doing up until a few days ago

So, it’s not just my thermostat. In fact, it’s not very unlikely that it’s on this end at all. The timing of all this started a day or so before ST started announcing is was having the issues as I described them above. It’s on your end . These errors always show up her when you guys have issues with your infrastructure or system.

I’m just adding info to let you know that in spite of ST saying that it is all clear now. It is not clear. Please look into fixing whatever it is on your end that’s causing the above issues.

Lee Florack

From: SmartThings Support [mailto:[email protected]]
Sent: Tuesday, April 28, 2020 13:52
To: Lee Florack <[email protected]>
Subject: [SmartThings] Re: 944307 | Many recent missed events and errors

In replies all text above this line is added to the ticket

Tejaswi Vadlamudi (SmartThings)

Apr 28, 10:52 AM MST

Hi Lee,

Thank you for contacting Samsung SmartThings Support.

I appreciate the opportunity to assist you.

I understand your concern that you are getting errors while executing physical commands for Thermostat. I am sorry for the trouble you are experiencing.

I checked your account [email protected] and see that CT-100 Z-Wave Thermostat is working Online . In order to assist you better, I request you to send us the following details so that we can work from there.

Screenshot of the error while executing commands.
Model number of the Thermostat.
Time stamps of the error.
Mobile model and Os version.
SmartThings app version.

I look forward to hearing from you!

Regards,
Tejaswi
Samsung SmartThings Support

Lee Florack

Apr 28, 7:36 AM MST

Hello,

For the past few days - continuing today, I’m getting many errors like this:

║Error while executing physical command Thermostat.setCoolingSetpoint([73.0]):
org.springframework.dao.InvalidDataAccessResourceUsageException: could not
load an entity: [physicalgraph.device.DeviceTypeHandler
#c37c6f62-0fae-454e-9f50-5e0d523f500e]; SQL [select devicetype0_.id
as id55_0_, devicetype0_.version as version55_0_, devicetype0_.checksum
as checksum55_0_, devicetype0_.code as code55_0_,
devicetype0_.date_created as date5_55_0_, devicetype0_.device_type
id as device6_55_0, devicetype0_.handler_version as handler7_55_0_,
devicetype0_.last_updated as last8_55_0_, devicetype0_.state as
state55_0_ from device_type_handler devicetype0_ where devicetype0_.id=?];
nested exception is org.hibernate.exception.SQLGrammarException: could not load
an entity: [physicalgraph.device.DeviceTypeHandler
#c37c6f62-0fae-454e-9f50-5e0d523f500e]

…and this:

║Error while executing physical command Thermostat.setHeatingSetpoint([67.0]):
java.lang.reflect.UndeclaredThrowableException

…and this:

║Piston waited at a semaphore for 7787ms

Also, some things not firing at all. Completely missed actions and sometimes partially missed actions. Every once in a while, the errors are interspersed with hours of the exact same pistons and devices running without errors.

Lee Florack

lflorack · 2020-04-28 20:05:56 UTC

The errors look like ST to me, but I’ve been wrong before.

eibyer · 2020-04-28 20:43:18 UTC

I get the same throwable exception on my hue bulbs.

Terminal · 2020-04-29 01:33:05 UTC

Just got it again tonight. A piston to turn on a ceiling fan didn’t work two times I tried it tonight. I have a piston that uses echo speaks to detect which echo I spoke to and to toggle the fan in that room. It had been working great for quite some time now, but I had made a tweak a few days ago and figured that I had screwed something up, see here.

I turned on logging so I could see what the issue was and of coarse everything worked as it should, so I figured it was just some kind of timing issue.

For giggles though I went and looked at the piston that is called to toggle the fan. The log wasn’t turned on but in the logs were three entries with the same error you guys are seeing the first two corresponding with the times I tried to execute the piston tonight. The last was from about a month ago. So this has been happening for awhile.

4/28/2020, 9:12:14 PM +286ms
+131ms ║Error while executing physical command Office Fan.off([]): java.lang.reflect.UndeclaredThrowableException
4/28/2020, 6:32:51 PM +321ms
+138ms ║Error while executing physical command Office Fan.on([]): java.lang.reflect.UndeclaredThrowableException
3/28/2020, 8:37:42 AM +288ms
+1209ms ║Error while executing physical command Office Fan.off([]): java.lang.reflect.UndeclaredThrowableException

Terminal · 2020-04-29 13:18:55 UTC

Was looking through some of my pitons to see if I could find anymore of these errors and came across this one. This piston just turns on lighting in the laundry room. I had not noticed it had not been working. I think a few times I saw the laundry room light was on and thought it maybe should have been out, but I just figured one of the cats had jumped up on the washer or dryer and set off the motion sensor.

Errors seem to start around the end of March.
4/27/2020, 9:26:26 AM +400ms
+10131ms ║Piston waited at a semaphore for 10018ms
4/27/2020, 8:15:43 AM +137ms
+153ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
4/26/2020, 8:18:44 PM +125ms
+159ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
4/26/2020, 2:05:17 PM +822ms
+9699ms ║Piston waited at a semaphore for 9584ms
4/26/2020, 1:20:21 PM +264ms
+10035ms ║Piston waited at a semaphore for 9907ms
4/26/2020, 11:31:19 AM +122ms
+165ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
4/22/2020, 10:35:35 AM +651ms
+10229ms ║Piston waited at a semaphore for 10101ms
4/22/2020, 2:53:51 AM +83ms
+148ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
4/21/2020, 5:40:47 AM +152ms
+155ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
4/21/2020, 5:33:23 AM +268ms
+10136ms ║Piston waited at a semaphore for 10015ms
4/20/2020, 9:20:55 AM +93ms
+145ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
4/19/2020, 11:08:39 AM +71ms
+142ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
4/19/2020, 9:08:18 AM +278ms
+185ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
4/18/2020, 1:44:26 PM +149ms
+146ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
4/16/2020, 4:00:07 PM +89ms
+144ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
4/8/2020, 1:57:05 AM +394ms
+10107ms ║Piston waited at a semaphore for 9808ms
4/6/2020, 6:03:16 AM +109ms
+350ms ║Error while executing physical command Laundry room dimmer.off([]): org.springframework.dao.InvalidDataAccessResourceUsageException: could not load an entity: [physicalgraph.device.DeviceTypeHandler #cf1cdc96-a2b5-421a-acaf-79e3e24d3892]; SQL [select devicetype0_.id as id87_0_, devicetype0_.version as version87_0_, devicetype0_.checksum as checksum87_0_, devicetype0_.code as code87_0_, devicetype0_.date_created as date5_87_0_, devicetype0_.device_type_id as device6_87_0_, devicetype0_.handler_version as handler7_87_0_, devicetype0_.last_updated as last8_87_0_, devicetype0_.state as state87_0_ from device_type_handler devicetype0_ where devicetype0_.id=?]; nested exception is org.hibernate.exception.SQLGrammarException: could not load an entity: [physicalgraph.device.DeviceTypeHandler #cf1cdc96-a2b5-421a-acaf-79e3e24d3892]
4/5/2020, 6:03:53 PM +992ms
+6609ms ║Piston waited at a semaphore for 6509ms
4/5/2020, 6:03:09 PM +26ms
+5317ms ║Piston waited at a semaphore for 5007ms
4/5/2020, 6:03:09 PM +124ms
+5121ms ║Piston waited at a semaphore for 5008ms
4/5/2020, 5:48:49 PM +128ms
+152ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
4/5/2020, 12:17:42 PM +241ms
+10133ms ║Piston waited at a semaphore for 10015ms
4/5/2020, 10:46:17 AM +656ms
+10224ms ║Piston waited at a semaphore for 10099ms
4/4/2020, 7:31:12 PM +974ms
+8478ms ║Piston waited at a semaphore for 8263ms
4/4/2020, 4:12:20 PM +96ms
+169ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
4/4/2020, 12:12:35 PM +210ms
+10162ms ║Piston waited at a semaphore for 10049ms
4/1/2020, 12:22:38 PM +237ms
+10455ms ║Piston waited at a semaphore for 9999ms
3/31/2020, 9:51:43 PM +240ms
+10300ms ║Piston waited at a semaphore for 9923ms
3/31/2020, 8:13:40 PM +166ms
+155ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
3/31/2020, 5:11:59 PM +119ms
+298ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
3/31/2020, 4:34:16 PM +821ms
+8901ms ║Piston waited at a semaphore for 8794ms
3/31/2020, 4:34:16 PM +716ms
+8972ms ║Piston waited at a semaphore for 8764ms
3/31/2020, 3:23:50 PM +99ms
+157ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
3/31/2020, 5:09:03 AM +117ms
+213ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
3/30/2020, 1:10:41 PM +110ms
+161ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
3/30/2020, 12:36:04 PM +92ms
+154ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
3/29/2020, 9:38:26 PM +91ms
+155ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
3/29/2020, 1:07:08 PM +697ms
+10130ms ║Piston waited at a semaphore for 10020ms
3/29/2020, 8:59:52 AM +121ms
+153ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
3/28/2020, 9:33:47 PM +964ms
+4619ms ║Piston waited at a semaphore for 4510ms
3/28/2020, 9:33:48 PM +199ms
+4356ms ║Piston waited at a semaphore for 4257ms
3/28/2020, 9:33:47 PM +995ms
+4364ms ║Piston waited at a semaphore for 4262ms
3/28/2020, 11:45:44 AM +279ms
+277ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
3/27/2020, 6:29:06 AM +595ms
+194ms ║Error while executing physical command Laundry room dimmer.off([]): java.lang.reflect.UndeclaredThrowableException
3/21/2020, 1:03:15 PM +53ms
+10135ms ║Piston waited at a semaphore for 10016ms
3/19/2020, 1:02:56 PM +404ms
+10140ms ║Piston waited at a semaphore for 10017ms
3/14/2020, 1:07:30 PM +364ms
+10706ms ║Piston waited at a semaphore for 10099ms
3/14/2020, 1:07:20 PM +707ms
+10003ms ║Piston waited at a semaphore for 9800ms

lflorack · 2020-04-29 16:01:20 UTC

Here’s some additional errors from my logs this morning. Note that the errors do not happen during every piston run. It happens a lot, just not every time. Also, for the past two days - morning and night, my thermostat has not set it’s new heat and cool setpoints (due to errors) properly as it my piston has done without fail for over three years.

Multiple semaphores on these and other devices also continue. The latest I got from the Help Desk is, “There is a known issue previously related to automations not working and unable to load now the issue has been resolved.”

I have cleared the webCoRE cache.

I’m pretty sure that’s not true. It is NOT resolved.

lflorack · 2020-04-30 17:06:20 UTC

As of about 1300 EDST yesterday, all of my automations suddenly started running normally again. I did nothing that was suggested by ST support on my end because I knew it was on the ST end of things - their contrary statements notwithstanding.

I hope that all of the similar issues everyone was having have cleared up too.

Bry · 2020-04-30 23:25:23 UTC

Interesting. I’ve paused my two problematic pistons in webCore and implemented them in SharpTools’ Rule Engine. They’re running fine there!

WCmore · 2020-04-30 23:37:47 UTC

With the toilet paper shortage, I’d be reluctant to use that… LOL

Bry · 2020-04-30 23:41:54 UTC

Crap (pun intended) lol. Typo fixed!