Device that comes on on Openluup restart
-
HI
I have a smart plug (one of many) that has the annoying habit that no matter what the condition it is in, if Openluup restarts, the plug turns on.
Any suggestions as to where I can look to correct this (i.e. I'd like it to go into its previous condition like everything else does....TIA
C
-
This sounds odd, I agree. You have other smart plugs which don’t exhibit this behaviour? A log created at startup time would be a good place to start looking.
-
I do indeed.
Startup log only shows one line relating to the device (20870)022-11-18 17:34:39.405 luup.create_device:: [20820] / / () 2022-11-18 17:34:39.406 luup.create_device:: [20830] D_Siren1.xml / / D_Siren1.json (urn:schemas-micasaverde-com:device:Siren:1) 2022-11-18 17:34:39.408 luup.create_device:: [20840] D_BinaryLight1.xml / / D_BinaryLight1.json (urn:schemas-upnp-org:device:BinaryLight:1) 2022-11-18 17:34:39.409 luup.create_device:: [20850] D_BinaryLight1.xml / / D_BinaryLight1.json (urn:schemas-upnp-org:device:BinaryLight:1) 2022-11-18 17:34:39.410 luup.create_device:: [20860] D_BinaryLight1.xml / / D_BinaryLight1.json (urn:schemas-upnp-org:device:BinaryLight:1) 2022-11-18 17:34:39.412 luup.create_device:: [20870] D_BinaryLight1.xml / / D_BinaryLight1.json (urn:schemas-upnp-org:device:BinaryLight:1) 2022-11-18 17:34:39.413 luup.create_device:: [20880] D_BinaryLight1.xml / / D_BinaryLight1.json (urn:schemas-upnp-org:device:BinaryLight:1) 2022-11-18 17:34:39.414 luup.create_device:: [20890] D_ComboDevice1.xml / / D_ComboDevice1.json (urn:schemas-micasaverde-com:device:ComboDevice:1) 2022-11-18 17:34:39.416 luup.create_device:: [20900] D_DimmableLight1.xml / / D_DimmableLight1.json (urn:schemas-upnp-org:device:DimmableLight:1) 2022-11-18 17:34:39.417 luup.create_device:: [20920] D_BinaryLight1.xml / / D_BinaryLight1.json (urn:schemas-upnp-org:device:BinaryLight:1) 2022-11-18 17:34:39.418 luup.create_device:: [20930] D_BinaryLight1.xml / / D_BinaryLight1.json (urn:schemas-upnp-org:device:BinaryLight:1) 2022-11-18 17:34:39.419 luup.create_device:: [25001] D_MotionSensor1.xml / / D_MotionSensor1.json (urn:schemas-micasaverde-com:device:MotionSensor:1) 2022-11-18 17:34:39.420 luup.create_device:: [25002] D_TemperatureSensor1.xml / / D_TemperatureSensor1.json (urn:schemas-micasaverde-com:device:TemperatureSensor:1) 2022-11-18 17:34:39.422 luup.create_device:: [25003] D_LightSensor1.xml / / D_LightSensor1.json (urn:schemas-micasaverde-com:device:LightSensor:1) 2022-11-18 17:34:39.423 luup.create_device:: [25004] D_MotionSensor1.xml / / D_MotionSensor1.json (urn:schemas-micasaverde-com:device:MotionSensor:1) 2022-11-18 17:34:39.424 luup.create_device:: [25005] D_TemperatureSensor1.xml / / D_TemperatureSensor1.json (urn:schemas-micasaverde-com:device:TemperatureSensor:1) 2022-11-18 17:34:39.425 luup.create_device:: [25006] D_LightSensor1.xml / / D_LightSensor1.json (urn:schemas-micasaverde-com:device:LightSensor:1) 2022-11-18 17:34:39.426 luup.create_device:: [25007] D_MotionSensor1.xml / / D_MotionSensor1.json (urn:schemas-micasaverde-com:device:MotionSensor:1) 2022-11-18 17:34:39.427 luup.create_device:: [25008] D_TemperatureSensor1.xml / / D_TemperatureSensor1.json (urn:schemas-micasaverde-com:device:TemperatureSensor:1) 2022-11-18 17:34:39.428 luup.create_device:: [25009] D_LightSensor1.xml / / D_LightSensor1.json (urn:schemas-micasaverde-com:device:LightSensor:1) 2022-11-18 17:34:39.429 luup.create_device:: [25010] D_MotionSensor1.xml / / D_MotionSensor1.json (urn:schemas-micasaverde-com:device:MotionSensor:1) 2022-11-18 17:34:39.430 luup.create_device:: [25011] D_TemperatureSensor1.xml / / D_TemperatureSensor1.json (urn:schemas-micasaverde-com:device:TemperatureSensor:1) 2022-11-18 17:34:39.431 luup.create_device:: [25012] D_LightSensor1.xml / / D_LightSensor1.json (urn:schemas-micasaverde-com:device:LightSensor:1) 2022-11-18 17:34:39.432 luup.create_device:: [25014] D_TemperatureSensor1.xml / / D_TemperatureSensor1.json (urn:schemas-micasaverde-com:device:TemperatureSensor:1) 2022-11-18 17:34:39.433 luup.create_device:: [25015] D_MotionSensor1.xml / / D_MotionSensor1.json (urn:schemas-micasaverde-com:device:MotionSensor:1) 2022-11-18 17:34:39.434 luup.create_device:: [25016] D_MotionSensor1.xml / / D_MotionSensor1.json (urn:schemas-micasaverde-com:device:MotionSensor:1) 2022-11-18 17:34:39.435 luup.create_device:: [25017] D_MotionSensor1.xml / / D_MotionSensor1.json (urn:schemas-micasaverde-com:device:MotionSensor:1) 2022-11-18 17:34:39.436 luup.create_device:: [25018] D_MotionSensor1.xml / / D_MotionSensor1.json (urn:schemas-micasaverde-com:device:MotionSensor:1) 2022-11-18 17:34:39.437 luup.create_device:: [25019] D_MotionSensor1.xml / / D_MotionSensor1.json (urn:schemas-micasaverde-com:device:MotionSensor:1)
Slightly before the Lua log shows a toggle off:
2022-11-18 17:34:44.203 openLuup.io.server:: HTTP:3480 connection from 192.168.70.249 tcp{client}: 0x55918bcf0908 2022-11-18 17:34:44.203 openLuup.server:: GET /data_request?id=user_data&ns=1&Timeout=15&output_format=json&_r=1668792884197 HTTP/1.1 tcp{client}: 0x55918c45ef88 2022-11-18 17:34:44.203 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x55918cc57d48 2022-11-18 17:34:44.258 openLuup.server:: request completed (508985 bytes, 32 chunks, 54 ms) tcp{client}: 0x55918c45ef88 2022-11-18 17:34:44.258 openLuup.server:: GET /data_request?DeviceNum=20870&id=action&serviceId=urn%3Amicasaverde-com%3AserviceId%3AHaDevice1&action=ToggleState&output_format=json&_r=1668792884202 HTTP/1.1 tcp{client}: 0x55918bcf0908 2022-11-18 17:34:44.258 luup.call_action:: 20870.urn:micasaverde-com:serviceId:HaDevice1.ToggleState 2022-11-18 17:34:44.258 luup.call_action:: action will be handled by parent: 37 2022-11-18 17:34:44.258 luup.variable_set:: 20870.urn:upnp-org:serviceId:SwitchPower1.Target was: 1 now: 0 #hooks:0 2022-11-18 17:34:44.289 openLuup.server:: request completed (37 bytes, 1 chunks, 31 ms) tcp{client}: 0x55918bcf0908 2022-11-18 17:34:44.343 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x55918c45ef88
Finally a little later I noticed it was on and turned it off:
2022-11-18 18:02:05.469 openLuup.server:: GET /data_request?id=status&Timeout=15&DataVersion=792889487&MinimumDelay=50&output_format=json&_r=1668794525468 HTTP/1.1 tcp{client}: 0x55918c604d18 2022-11-18 18:02:05.612 openLuup.server:: GET /data_request?id=lu_status2&output_format=json&DataVersion=792889487&Timeout=60&MinimumDelay=1500&_=1668762327388 HTTP/1.1 tcp{client}: 0x55918c250b48 2022-11-18 18:02:06.979 openLuup.io.server:: HTTP:3480 connection from 192.168.70.70 tcp{client}: 0x55918cc702f8 2022-11-18 18:02:06.980 openLuup.server:: GET /data_request?id=action&output_format=json&DeviceNum=20870&serviceId=urn:upnp-org:serviceId:SwitchPower1&action=SetTarget&newTargetValue=0 HTTP/1.1 tcp{client}: 0x55918cc702f8 2022-11-18 18:02:06.981 luup.call_action:: 20870.urn:upnp-org:serviceId:SwitchPower1.SetTarget 2022-11-18 18:02:06.981 luup.call_action:: action will be handled by parent: 37 2022-11-18 18:02:06.981 luup.variable_set:: 20870.urn:upnp-org:serviceId:SwitchPower1.Target was: 0 now: 0 #hooks:0 2022-11-18 18:02:07.008 openLuup.server:: request completed (35 bytes, 1 chunks, 27 ms) tcp{client}: 0x55918cc702f8 2022-11-18 18:02:07.212 openLuup.server:: request completed (821 bytes, 1 chunks, 1744 ms) tcp{client}: 0x55918c2fde18 2022-11-18 18:02:07.214 openLuup.server:: request completed (821 bytes, 1 chunks, 1744 ms) tcp{client}: 0x55918c604d18 2022-11-18 18:02:07.217 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x55918c604d18 2022-11-18 18:02:07.229 openLuup.io.server:: HTTP:3480 connection from 192.168.70.249 tcp{client}: 0x55918c64dc38 2022-11-18 18:02:07.229 openLuup.server:: GET /data_request?id=status&Timeout=15&DataVersion=792889488&MinimumDelay=50&output_format=json&_r=1668794527228 HTTP/1.1 tcp{client}: 0x55918c64dc38 2022-11-18 18:02:07.257 luup.variable_set:: 20870.urn:upnp-org:serviceId:SwitchPower1.Status was: 1 now: 0 #hooks:0 2022-11-18 18:02:07.329 openLuup.server:: GET /data_request?id=lu_status2&output_format=json&DataVersion=792889488&Timeout=60&MinimumDelay=1500&_=1668791726900 HTTP/1.1 tcp{client}: 0x55918c2fde18 2022-11-18 18:02:07.331 openLuup.server:: request completed (821 bytes, 1 chunks, 102 ms) tcp{client}: 0x55918c64dc38 2022-11-18 18:02:07.333 openLuup.server:: request completed (943 bytes, 1 chunks, 1721 ms) tcp{client}: 0x55918c250b48 2022-11-18 18:02:07.337 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0x55918c64dc38
So the total in the Lua log appears to be:
catman@openluup:~/Notvera/logs$ grep 20870 LuaUPnP.log.3 2022-11-18 17:34:39.565 luup_log:37: creating device numbers: [20420,25001,25002,25003,20520,20320,20560,25004,25005,25006,20660,20360,20393,20160,20413,20741,20092,20051,20860,20820,20920,20091,20720,20090,20330,20530,20470,20570,25007,25008,25009,20744,20170,20631,20870,20770,20394,20630,25014,20930,20830,20391,20742,20200,20300,20380,20480,20780,20880,20761,25015,25016,25018,25017,20900,20740,20840,20361,20060,20800,20650,20290,20416,20790,20392,20490,20411,20390,20890,25025,20362,20762,20850,20743,20364,20412,20363,20610,25010,25011,25012,20050,25019,25020,25021,20415,20414,20590,25022,25023,25024] 2022-11-18 17:34:44.258 openLuup.server:: GET /data_request?DeviceNum=20870&id=action&serviceId=urn%3Amicasaverde-com%3AserviceId%3AHaDevice1&action=ToggleState&output_format=json&_r=1668792884202 HTTP/1.1 tcp{client}: 0x55918bcf0908 2022-11-18 17:34:44.258 luup.call_action:: 20870.urn:micasaverde-com:serviceId:HaDevice1.ToggleState 2022-11-18 17:34:44.258 luup.variable_set:: 20870.urn:upnp-org:serviceId:SwitchPower1.Target was: 1 now: 0 #hooks:0 2022-11-18 18:02:06.980 openLuup.server:: GET /data_request?id=action&output_format=json&DeviceNum=20870&serviceId=urn:upnp-org:serviceId:SwitchPower1&action=SetTarget&newTargetValue=0 HTTP/1.1 tcp{client}: 0x55918cc702f8 2022-11-18 18:02:06.981 luup.call_action:: 20870.urn:upnp-org:serviceId:SwitchPower1.SetTarget 2022-11-18 18:02:06.981 luup.variable_set:: 20870.urn:upnp-org:serviceId:SwitchPower1.Target was: 0 now: 0 #hooks:0 2022-11-18 18:02:07.257 luup.variable_set:: 20870.urn:upnp-org:serviceId:SwitchPower1.Status was: 1 now: 0 #hooks:0
Highly odd
C
-
Just before the first toggle, there is this entry:
2022- 11-18 17:34:44.258 openLuup.server:: GET /data_request?DeviceNum=20870&id=action&serviceId=urn%3Amicasaverde-com%3AserviceId%3AHaDevice1&action=ToggleState&output_format=json&_r=1668792884202 HTTP/1.1 tcp{client}: 0x55918bcf0908
Which means that it has received an HTTP request to do that, from somewhere.
5/5