adey / bangali

bangali's random code stuff for smartthings
GNU General Public License v3.0
46 stars 52 forks source link

Set level in 1.0 seems to never occur #58

Open mjb4450 opened 4 years ago

mjb4450 commented 4 years ago

I’ve been using this app for years, love it thank you.

I have just installed the v1.0 version about a week ago and since then I’ve had issues with all of my rooms. After much exploration it seems to be that the set level for lights is never happening. It will turn the light on and off to the previous light level setting but never set the level of the light according to the level being programmed in the rules. I have created multiple new test rooms, both advanced and basic, and all have same issue. I’ve also watched the logs and it appears set level works still when checking is set to dim lights. I have confirmed all files appear to be current in the ide, I’ve used community installer and manually checked. I have opened existing rooms and saved them again, done everything I can think of prior to just creating all new dummy rooms. All with same results.

Also, is there a trick to deleting rooms? I’ve now got a bunch of dummy test rooms as I have been trying to figure out above and when I go to delete them even after erasing all settings in the room I still get an error and room is not deleted.

Thank you

adey commented 4 years ago

thats odd … set level is used on almost all of my rooms and i am not seeing the issue in any of my rooms. please share the view all settings for one these rooms so i can take a look at what the settings are.

i will check on deleting rooms. but in the IDE if you go from My Locations > smartapps you will find the rooms all listed under rooms manager category. click on room you want to delete and delete it from there. same for the corresponding rooms occupancy device as well under My Locations > devices.

mjb4450 commented 4 years ago

Here is a new room I created for an example. Ironically the dim when checking does seem to work but as that is set to 50% sooner or later the lights come on each time 50% less until they end up at 1% since the motion causes the lights to come on at their previous level instead of the set level.
C8C48140-957E-4F68-A4B2-CF8A40D7AE78

adey commented 4 years ago

just created a test room with simulated devices and exactly the same settings. its setting the level to 40% as it should.

puzzling.

heres the device live log from one of the lights:

0c8f8f38-0548-472c-967b-fa6c7ddbdaaa 8:56:51 PM: trace ---- DONE ----
0c8f8f38-0548-472c-967b-fa6c7ddbdaaa 8:56:51 PM: debug bulbMode: Color; bulbValue: Color
#FFFFFF; colorIndicator: 100000
0c8f8f38-0548-472c-967b-fa6c7ddbdaaa 8:56:51 PM: debug flattenHueSat for hue: 0, sat: 0 comes to 100000
0c8f8f38-0548-472c-967b-fa6c7ddbdaaa 8:56:51 PM: trace Executing 'simulateBulbState' Color
0c8f8f38-0548-472c-967b-fa6c7ddbdaaa 8:56:51 PM: trace Executing 'on'
0c8f8f38-0548-472c-967b-fa6c7ddbdaaa 8:56:51 PM: trace ---- DONE ----
0c8f8f38-0548-472c-967b-fa6c7ddbdaaa 8:56:51 PM: debug bulbMode: Off; bulbValue: Off; colorIndicator: 0
0c8f8f38-0548-472c-967b-fa6c7ddbdaaa 8:56:51 PM: trace Executing 'simulateBulbState' Off
0c8f8f38-0548-472c-967b-fa6c7ddbdaaa 8:56:51 PM: trace executing 'setLevel' 40%
0c8f8f38-0548-472c-967b-fa6c7ddbdaaa 8:56:51 PM: trace executing 'setLevel' 40% 

you are not seeing the setLevel in either the live log or the device event log?

mjb4450 commented 4 years ago

1) I have determined that rooms manager is able to set the level and color for Hue lights and set the level for a iNovelli switch. All other dimmer switches I have are Leviton. Is it possible that the reason its only ON/OFF because the app does not think my switches are dimmers?

Leviton DZMX1-1LZ Decora Z-Wave Controls Universal Dimmer

2) Not sure if this is related but these lines show up in the logs for all of my rooms every 5min or so..

3f89cd38-4c12-434c-9a52-24079c20dcc9 1:11:28 AM: error java.lang.NullPointerException: Cannot set property 'isExecuting' on null object @line 2131 (runEvery5)

41c20b66-00cd-4676-9031-181e4f06e06a 2:18:29 AM: error java.lang.NullPointerException: Cannot invoke method toInteger() on null object @line 337 (varRuleTimeOffset)

793d4162-a909-4999-babd-9cd0fec72b54 1:11:20 AM: error java.lang.NullPointerException: Cannot set property 'isExecuting' on null object @line 2131 (runEvery5)

4e1368fc-fe2b-4d75-8fba-f780b275f8f2 1:11:15 AM: error java.util.concurrent.TimeoutException: Execution timed out after 40 units. Start time: Sun Dec 08 07:10:17 UTC 2019 @line -1 (doCall)

7030bece-bc0d-4f75-a36d-c9bd680ff89d 1:11:13 AM: error java.lang.NullPointerException: Cannot set property 'isExecuting' on null object @line 2131 (runEvery5)

ffc4297f-f913-4dc4-b8da-1ad5d54d2556 1:11:05 AM: error java.lang.NullPointerException: Cannot set property 'isExecuting' on null object @line 2131 (runEvery5)

b5a87091-37f1-4614-9c65-3f6c34508256 1:11:05 AM: error java.lang.NullPointerException: Cannot set property 'isExecuting' on null object @line 2131 (runEvery5)

3f89cd38-4c12-434c-9a52-24079c20dcc9 1:13:50 AM: error java.lang.NullPointerException: Cannot set property 'isExecuting' on null object @line 2131 (runEvery5)

3f89cd38-4c12-434c-9a52-24079c20dcc9 1:12:21 AM: error java.lang.NullPointerException:

41c20b66-00cd-4676-9031-181e4f06e06a 2:18:29 AM: error java.lang.NullPointerException: Cannot invoke method toInteger() on null object @line 337 (varRuleTimeOffset)

3f89cd38-4c12-434c-9a52-24079c20dcc9 2:18:24 AM: error java.lang.NullPointerException: Cannot set property 'isExecuting' on null object @line 2131 (runEvery5)

3) I turned on debug for my test room “front door”.. Watching the live logging in the ide I can see when the smartlighting App changes my lights but nothing with setlevel from rooms manager app. Is there another way to see device logging that I am not doing correctly? When the checking reduces the lights by 50% I don't see that either so could I be looking in the incorrect spot for the info you need?

smartlighting example: a27b17ac-a9cd-4d3d-b09f-1c54387b0d29 1:49:15 AM: debug smartLighting: Bathroom Wall setLevel(90) a27b17ac-a9cd-4d3d-b09f-1c54387b0d29 1:49:15 AM: trace timeWindowStop = null a27b17ac-a9cd-4d3d-b09f-1c54387b0d29 1:49:15 AM: trace ambientLightOK = true a27b17ac-a9cd-4d3d-b09f-1c54387b0d29 1:49:15 AM: debug smartLighting: Kitchen Lights setLevel(90) a27b17ac-a9cd-4d3d-b09f-1c54387b0d29 1:49:15 AM: trace ambientLightOK = true a27b17ac-a9cd-4d3d-b09f-1c54387b0d29 1:49:15 AM: trace timeWindowStop = null a27b17ac-a9cd-4d3d-b09f-1c54387b0d29 1:49:15 AM: debug smartLighting: Bathroom Light setLevel(90) a27b17ac-a9cd-4d3d-b09f-1c54387b0d29 1:49:15 AM: trace timeWindowStart = null

roomsmanager:923f23e9-262e-4de4-b965-6b51b1d84c72 2:03:14 AM: info Front Door: switchOnEventHandler 923f23e9-262e-4de4-b965-6b51b1d84c72 2:03:14 AM: info Front Door: switchOnEventHandler 923f23e9-262e-4de4-b965-6b51b1d84c72 2:03:14 AM: info Front Door: switchOnEventHandler 923f23e9-262e-4de4-b965-6b51b1d84c72 2:03:14 AM: info Front Door: switchOnEventHandler 923f23e9-262e-4de4-b965-6b51b1d84c72 2:03:14 AM: info Front Door: switchOnEventHandler 923f23e9-262e-4de4-b965-6b51b1d84c72 2:03:13 AM: info Front Door: motionInactiveEventHandler 923f23e9-262e-4de4-b965-6b51b1d84c72 2:03:11 AM: info Front Door: processHumidity 923f23e9-262e-4de4-b965-6b51b1d84c72 2:03:11 AM: info Front Door: processCoolHeat 923f23e9-262e-4de4-b965-6b51b1d84c72 2:03:10 AM: info Front Door: turnSwitchesOnAndOff 923f23e9-262e-4de4-b965-6b51b1d84c72 2:03:10 AM: debug Front Door: processRules: rules to execute: [1] 923f23e9-262e-4de4-b965-6b51b1d84c72 2:03:10 AM: info Front Door: processRules 923f23e9-262e-4de4-b965-6b51b1d84c72 2:03:10 AM: debug Front Door: Front Door unschedule calling class: handle switches 923f23e9-262e-4de4-b965-6b51b1d84c72 2:03:10 AM: info Front Door: previousStateStack 923f23e9-262e-4de4-b965-6b51b1d84c72 2:03:10 AM: info Front Door: Front Door handleSwitches: room state - old: vacant new: occupied 923f23e9-262e-4de4-b965-6b51b1d84c72 2:03:10 AM: debug Front Door: Front Door unschedule calling class: motion active handler 923f23e9-262e-4de4-b965-6b51b1d84c72 2:03:10 AM: info Front Door: motionActiveEventHandler 923f23e9-262e-4de4-b965-6b51b1d84c72 2:03:10 AM: info Front Door: switchOnEventHandler 923f23e9-262e-4de4-b965-6b51b1d84c72 2:03:10 AM: info Front Door: motionActiveEventHandler

adey commented 4 years ago

for the rooms that are having this issue have you tried saving the rooms and do these rooms save without any error? please also watch live logging while saving these rooms and see if there are any errors in the log on save.

adey commented 4 years ago

please update the rooms child app code save / publish in the IDE then save the rooms in the ST app while watching the live logs and lets see if that works better.

mjb4450 commented 4 years ago

This post has been edited from original after another week of diagnosis:

I’ve updated the code as requested and there appears to be no difference. (I had seen lights going to 80% instead of set level being broke still and found that it was due to another smart lights rule I created to just prove to myself that the same lights did indeed work with set level. I have removed that test and the rooms manager is indeed still having setlevel issues)

So as an example from one of the rooms manger rules, lights Programmed to come on to 90% , hue works perfect with 90% and correct color, an inovelli Dimmer comes on perfect to 90%, Leviton comes on at whatever the level was last for that light when it was last on instead of it’s rule which is set to 90%. I’ve changed the rule’s level to other Set levels and added extra Leviton lights all following the same pattern with all but Leviton acting correct on set level.. It almost seems like rooms manager somehow thinks my Leviton dimmers are of/on lights since they are not being told a set level by rooms manager when a rule hits. The hue lights and other dimmer all work correctly.

Interestingly the Checking (Dimming) seems to work fine for all lights including Leviton.

This means lights will come on, dim then come back with level of previous dim level then repeat until finally dimmed to 1% and all future on equal 1%.

This error is still occurring error java.lang.NullPointerException: Cannot set property 'isExecuting' on null object @line 2131 (runEvery5)

I’ve now jacked up most of my rules and rooms and the only constant is my whole system is gone set level bonkers where rooms manger will not set level on the rules. This all worked for over a year and then stopped when I updated to V1.0

I would like to try v0.96 ( or whatever was Previous version) to see if problem disappears.

how do I get the previous versions?

Thank you for helping me

mjb4450 commented 4 years ago

I would like to try v0.96 ( or whatever the previous version was before v1.0) to see if this setlevel problem disappears. How do I get the previous versions?

adey commented 4 years ago

This error is still occurring error java.lang.NullPointerException: Cannot set property 'isExecuting' on null object @line 2131 (runEvery5)

this means the code is not installed properly or the settings were not saved after the code was published. could you please save/publish the latest code and then go into each room and save the settings for it. that should be make the error go away. if the error is no longer there and the setlevel still not working i will help with sharing the 0.96 version for you.

mjb4450 commented 4 years ago

Thank you. I have completely updated all code, saved everything and the one occasional error in logs has gone away, however, the main problem still remains.

Here is an example of the problem: If I set a room rule to have lights go to 90% for three lights when occupied, the Hue Lights go to 90%, the iNovelli switch goes to 90% and the Leviton goes to whatever % it was last on before it turned off.. So, if I manually set the Leviton to 62% it will be the only item to not go to 90% upon occupied.. it just turns on to 62%..

To me, this seems to indicate the rooms manager does not understand it is a dimmable light for some reason when initially turning ON. I have tried to watch the live logs and I see nothing that indicates the Leviton is being told to go to 90%.

Strangely.. Rooms manager DOES dim the Leviton light the correct setting when it goes to CHECKING. so a 62% light bumps down to 12% when checking @ 50% reduce when checking, then will go back up to 62% if it goes back to occupied. It does not go to the set level in rules which in this case is 90%. If I manually change the Leviton to any % it will use that % from there on for its set level when turning back on just as if it was an on/off switch only.

I have tried this with new and existing rooms, with same results. I have even created test rooms and same results.

================================

Since I believe this is some sort of device type issue with Rooms Manager this is what I have done to further determine the issue:

I have had about 40 of these Leviton dimmers for 4+ years now and never an issue until now. When smart things ads them they are given this device type: "Z-Wave Dimmer Switch Generic"

*** If I manually change their type to: "Simulated Dimmer Switch"

The device then CORRECTLY goes to the exact level they are supposed to in rules. In other words, all three lights in the 90% set room go to 90%.. it works as it used to before v1.0.. Since this a simulated device type it does not actually control the light so this does not help much other than for troubleshooting.

Once I set the Type back to the original type the inital level in rules no longer works again...

mjb4450 commented 4 years ago

update: I have tried to use a non generic device handler - the one below appears to be specific to my dimmer. It operates the dimmer and has more advanced features when using the smartthings app but still does not operate correctly with Rooms Manager. It does the same thing as reported above where the original set level is never initiated. Wouldnt this mean the rooms manager is just not sending the level? How can i force rooms manager to put extra info in live logging to determine this? is there a spot in the code where i can have it be more verbose?

https://github.com/jasonxh/SmartThings-jasonxh/blob/master/devicetypes/jasonxh/leviton-decora-zwave-plus-dimmer.src/leviton-decora-zwave-plus-dimmer.groovy

mjb4450 commented 4 years ago

**I am still struggling with this issue at both of my houses..

Here are the settings:**

image

The same rule sets multiple lights. Here are the logs for each:

The Leviton light switch is still returning to whatever previous setlevel instead of the rules setlevel which in this case is 60%. The inovelli switch works correctly

BATHROOM WALL (inovelli) 54d46abc-d1da-4049-8f9d-d549c6181e56 2:17:18 AM: debug 'zw device: 48, command: 2603, payload: 3C 3C 00 ' parsed to [[name:switch, value:on, linkText:Bathroom Wall, descriptionText:Bathroom Wall switch is on, isStateChange:true, displayed:true], [name:level, value:60, unit:%, linkText:Bathroom Wall, descriptionText:Bathroom Wall level is 60%, isStateChange:false, displayed:false]]

BATHROOM LIGHT (leviton) 39b44f55-42eb-4686-adb9-a1086b463e35 2:25:46 AM: debug Parsed SwitchMultilevelReport(value: 89) to [[name:level, value:89, unit:%, linkText:Bathroom Light, descriptionText:Bathroom Light level is 89%, isStateChange:true, displayed:true], [name:switch, value:on, linkText:Bathroom Light, descriptionText:Bathroom Light switch is on, isStateChange:false, displayed:false]] 39b44f55-42eb-4686-adb9-a1086b463e35 2:25:43 AM: debug setLevel >> value: 60, durationSeconds: null

==================== Here is a much larger log segment for BATHROOM

LIGHT:39b44f55-42eb-4686-adb9-a1086b463e35 2:33:37 AM: debug Parsed SwitchMultilevelReport(value: 0) to [[name:level, value:0, unit:%, linkText:Bathroom Light, descriptionText:Bathroom Light level is 0%, isStateChange:true, displayed:true], [name:switch, value:off, linkText:Bathroom Light, descriptionText:Bathroom Light switch is off, isStateChange:true, displayed:true]] 39b44f55-42eb-4686-adb9-a1086b463e35 2:33:37 AM: debug Parsed SwitchMultilevelReport(value: 0) to [[name:level, value:0, unit:%, linkText:Bathroom Light, descriptionText:Bathroom Light level is 0%, isStateChange:true, displayed:true], [name:switch, value:off, linkText:Bathroom Light, descriptionText:Bathroom Light switch is off, isStateChange:true, displayed:true]] 39b44f55-42eb-4686-adb9-a1086b463e35 2:33:34 AM: debug setLevel >> value: 89, durationSeconds: null 39b44f55-42eb-4686-adb9-a1086b463e35 2:29:08 AM: debug Parsed SwitchMultilevelReport(value: 64) to [[name:level, value:64, unit:%, linkText:Bathroom Light, descriptionText:Bathroom Light level is 64%, isStateChange:false, displayed:false], [name:switch, value:on, linkText:Bathroom Light, descriptionText:Bathroom Light switch is on, isStateChange:false, displayed:false]] 39b44f55-42eb-4686-adb9-a1086b463e35 2:29:05 AM: debug setLevel >> value: 64, durationSeconds: null 39b44f55-42eb-4686-adb9-a1086b463e35 2:29:05 AM: debug setLevel >> value: 64, durationSeconds: null 39b44f55-42eb-4686-adb9-a1086b463e35 2:25:46 AM: debug Parsed SwitchMultilevelReport(value: 89) to [[name:level, value:89, unit:%, linkText:Bathroom Light, descriptionText:Bathroom Light level is 89%, isStateChange:true, displayed:true], [name:switch, value:on, linkText:Bathroom Light, descriptionText:Bathroom Light switch is on, isStateChange:false, displayed:false]] 39b44f55-42eb-4686-adb9-a1086b463e35 2:25:43 AM: debug setLevel >> value: 60, durationSeconds: null 39b44f55-42eb-4686-adb9-a1086b463e35 2:25:27 AM: debug Parsed SwitchMultilevelReport(value: 0) to [[name:level, value:0, unit:%, linkText:Bathroom Light, descriptionText:Bathroom Light level is 0%, isStateChange:true, displayed:true], [name:switch, value:off, linkText:Bathroom Light, descriptionText:Bathroom Light switch is off, isStateChange:true, displayed:true]] 39b44f55-42eb-4686-adb9-a1086b463e35 2:20:59 AM: debug Parsed SwitchMultilevelReport(value: 64) to [[name:level, value:64, unit:%, linkText:Bathroom Light, descriptionText:Bathroom Light level is 64%, isStateChange:false, displayed:false], [name:switch, value:on, linkText:Bathroom Light, descriptionText:Bathroom Light switch is on, isStateChange:false, displayed:false]] 39b44f55-42eb-4686-adb9-a1086b463e35 2:20:56 AM: debug setLevel >> value: 64, durationSeconds: null 39b44f55-42eb-4686-adb9-a1086b463e35 2:17:20 AM: debug Parsed SwitchMultilevelReport(value: 89) to [[name:level, value:89, unit:%, linkText:Bathroom Light, descriptionText:Bathroom Light level is 89%, isStateChange:false, displayed:false], [name:switch, value:on, linkText:Bathroom Light, descriptionText:Bathroom Light switch is on, isStateChange:false, displayed:false]] 39b44f55-42eb-4686-adb9-a1086b463e35 2:17:20 AM: debug Parsed ApplicationBusy(waitTime: 0, status: 0) to null

Rooms Manager is not setting the setval correctly for the Leviton light switches, not sure why but I have used generic and custom handlers with same results. It seems like Rooms manager is allowing the switches to just turn on and set themselves to their previous setLevel.

As discussed before, the dimming does work but as you can tell from the logs it just dims from the incorrect occupied setting level.

Could you please help me get the rooms manager to correctly setLevel my 50+ wall dimmers like before v1.0.0

Where in the code does it set the level so I may edit it or compare it to previous version? Can i get the previous version v.0.9.6

adey commented 4 years ago

i am really sorry i forgot to check github in a while. my apologies.

would you mind posting the message above in this thread on the community forum:

https://community.smartthings.com/t/rooms-manager-smarter-rooms-personalized-home-automation-with-occupancy/102576

i frequent that much more often and also want to see if anyone else is experiencing the same issue.