Hello group,
I’ve just completed (first) a fresh install of the Wink Connect Plugin v0.22 via the Marketplace. I (second) did a manual update to v0.22b13 (uploading the 17 files in the .zip) & reloading the engine several times. I kept all of the plugin defaults (because I can’t remember changing any of them the first time I installed ages ago)
After several reloading & {CTRL}-{F5}'ing, everything installed smoothly I thought. Using the Wink app on my android phone, I clicked to turn a light off, and the light turned off. The corresponding device in Vera also reported the light off within the poll time (60 sec. default)
But when I tried to turn the device ON again using the Vera web interface (UI5), the vera claimed the light turned on, but the light never actually turned on. I tested the same problem on all of my devices connected to Wink
Some brief history:
I’ve been suffering constant boot loops over the last few weeks (not because of the Wink Connect plugin)
If I could understand the logs, maybe I can fix my problems quicker, but . . .
I restored a very old backup, & removed several plugins, including Wink Connect and I had the appearance of a stable system again.
Then re-installed, & re-upgraded the WC(formerly WHC) and here I sit.
I enabled debug mode, and tried again. The snippet below is part of the log file I posted below.
01 11/23/16 17:33:28.169 luup_log:162: Wink_Connect::HUB_PUBNUB::processIncoming: discarding invalid subscription data 'HTTP/1.1 200 OK'. <0x31507680>
01 11/23/16 17:33:28.179 luup_log:162: Wink_Connect::HUB_PUBNUB::processIncoming: discarding invalid subscription data 'Date: Wed, 23 Nov 2016 22:33:28 GMT'. <0x31507680>
01 11/23/16 17:33:28.191 luup_log:162: Wink_Connect::HUB_PUBNUB::processIncoming: discarding invalid subscription data 'Content-Type: text/javascript; charset="UTF-8"'. <0x31507680>
01 11/23/16 17:33:28.197 luup_log:162: Wink_Connect::HUB_PUBNUB::processIncoming: discarding invalid subscription data 'Content-Length: 27'. <0x31507680>
01 11/23/16 17:33:28.203 luup_log:162: Wink_Connect::HUB_PUBNUB::processIncoming: discarding invalid subscription data 'Connection: keep-alive'. <0x31507680>
01 11/23/16 17:33:28.210 luup_log:162: Wink_Connect::HUB_PUBNUB::processIncoming: discarding invalid subscription data 'Cache-Control: no-cache'. <0x31507680>
01 11/23/16 17:33:28.218 luup_log:162: Wink_Connect::HUB_PUBNUB::processIncoming: discarding invalid subscription data 'Access-Control-Allow-Origin: *'. <0x31507680>
01 11/23/16 17:33:28.228 luup_log:162: Wink_Connect::HUB_PUBNUB::processIncoming: discarding invalid subscription data 'Access-Control-Allow-Methods: GET'. <0x31507680>
01 11/23/16 17:33:28.229 luup_log:162: Wink_Connect::HUB_PUBNUB::processIncoming: discarding invalid subscription data ''. <0x31507680>
02 11/23/16 17:33:29.100 luup_log:162: Wink_Connect::HUB_PUBNUB::processSubscription: Received subscription data '[[],"14799391447126632",""]'. <0x308f8680>
02 11/23/16 17:33:29.102 luup_log:162: Wink_Connect::HUB_PUBNUB::SUBSCRIBE: Subscribing to Wink PUBNUB Device notifications. <0x308f8680>
01 11/23/16 17:33:29.102 lu_io_connected 0x1a978a8 args 0 0xdfd008 <0x308f8680>
02 11/23/16 17:33:29.103 luup_log:162: Wink_Connect::HUB_PUBNUB::SUBSCRIBE: self.is_connected [TRUE] luup.io.is_connected [FALSE]. <0x308f8680>
02 11/23/16 17:33:29.103 luup_log:162: Wink_Connect::HUB_PUBNUB::SUBSCRIBE: called - timeToken [14799391447126632] waitForData [FALSE]. <0x308f8680>
02 11/23/16 17:33:29.103 luup_log:162: (Wink_Connect::HUB_PUBNUB:asynchSend) Sending request. <0x308f8680>
50 11/23/16 17:33:29.104 luup_log:162: (Wink_Connect::HUB_PUBNUB::http_wrapper_request_luup) simple request type [GET] sendOnly [true] url [http://pubsub.pubnub.com/subscribe/sub-c-f7bf7f7e-0542-11e3-a5e8-02ee2ddab7fe/d43f3b0ecf5f09f738017bc893d643870ed04d98|hub-363328|user-304722,aad130539f1bde41f61b76881c11f55ea70bb2f1|eggtray-150907|user-304722,ca16f99a4590d325b1c11083b4690d7e97f4743c|light_bulb-1426196|user-304722,0f4c2be6bbe457c7aba703e14e428d16dffcd59d|light_bulb-1426199|user-304722,af14fccc2cf18ea32d041c395079a319f072da8f|light_bulb-1426197|user-304722,f5b5c86f32b8655b5fa7b51813c384b351432480|light_bulb-1426200|user-304722,8a085e195a20e4525cbc6491a1dac24cee99a4ea|light_bulb-1426198|user-304722,29f99a403b3b5ae91222b68c9e838a87bd5cd860|user-304722|water_heater-1518/0/14799391447126632]. <0x308f8680>
02 11/23/16 17:33:29.104 luup_log:162: (Wink_Connect::HUB_PUBNUB::LuupSendReceive) Sending request (sendOnly = true). <0x308f8680>
02 11/23/16 17:33:29.105 luup_log:162: (Wink_Connect::HUB_PUBNUB::LuupSendReceive) Sending sendData [
GET http://pubsub.pubnub.com/subscribe/sub-c-f7bf7f7e-0542-11e3-a5e8-02ee2ddab7fe/d43f3b0ecf5f09f738017bc893d643870ed04d98|hub-363328|user-304722,aad130539f1bde41f61b76881c11f55ea70bb2f1|eggtray-150907|user-304722,ca16f99a4590d325b1c11083b4690d7e97f4743c|light_bulb-1426196|user-304722,0f4c2be6bbe457c7aba703e14e428d16dffcd59d|light_bulb-1426199|user-304722,af14fccc2cf18ea32d041c395079a319f072da8f|light_bulb-1426197|user-304722,f5b5c86f32b8655b5fa7b51813c384b351432480|light_bulb-1426200|user-304722,8a085e195a20e4525cbc6491a1dac24cee99a4ea|light_bulb-1426198|user-304722,29f99a403b3b5ae91222b68c9e838a87bd5cd860|user-304722|water_heater-1518/0/14799391447126632 HTTP/1.1
Host: pubsub.pubnub.com
User-Agent: Mozilla/5.0 (Linux; Android 4.4; Nexus 4 Build/KRT16E) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/30.0.1599.105 Mobile Safari
Accept: */*
]. <0x308f8680>
50 11/23/16 17:33:29.111 luup_log:162: (Wink_Connect::HUB_PUBNUB::LuupSendReceive) sendOnly specified. Returning. <0x308f8680>
50 11/23/16 17:33:29.111 luup_log:162: (Wink_Connect::HUB_PUBNUB::http_wrapper_request_luup) processed headers. <0x308f8680>
50 11/23/16 17:33:29.111 luup_log:162: (Wink_Connect::HUB_PUBNUB::http_wrapper_request_luup) simple request returning success. <0x308f8680>
02 11/23/16 17:33:29.112 luup_log:162: (Wink_Connect::HUB_PUBNUB:asynchSend) completed. <0x308f8680>
02 11/23/16 17:33:29.112 luup_log:162: Wink_Connect::HUB_PUBNUB::SUBSCRIBE: respBody '' rData []. <0x308f8680>
02 11/23/16 17:33:29.112 luup_log:162: Wink_Connect::HUB_PUBNUB::SUBSCRIBE: Subscribe completed. <0x308f8680>
--snip
08 11/23/16 17:35:38.258 JobHandler_LuaUPnP::HandleActionRequest device: 168 service: urn:upnp-org:serviceId:SwitchPower1 action: SetTarget <0x32307680>
08 11/23/16 17:35:38.258 JobHandler_LuaUPnP::HandleActionRequest argument DeviceNum=168 <0x32307680>
08 11/23/16 17:35:38.259 JobHandler_LuaUPnP::HandleActionRequest argument serviceId=urn:upnp-org:serviceId:SwitchPower1 <0x32307680>
08 11/23/16 17:35:38.259 JobHandler_LuaUPnP::HandleActionRequest argument action=SetTarget <0x32307680>
08 11/23/16 17:35:38.259 JobHandler_LuaUPnP::HandleActionRequest argument newTargetValue=0 <0x32307680>
50 11/23/16 17:35:38.274 luup_log:162: (Wink_Connect::ACTION_SwitchPower1::setTarget): Processing setTarget Action - version [0.22b13] - device [168] target [0] targetSID [NIL]. <0x2ac9d000>
50 11/23/16 17:35:38.275 luup_log:162: (Wink_Connect::HUB_DEVICES::findWinkDeviceByVeraId): Searching for wink device with Vera ID [168]. <0x2ac9d000>
50 11/23/16 17:35:38.275 luup_log:162: (Wink_Connect::HUB_DEVICES::findWinkDeviceByVeraId): found device [6]. <0x2ac9d000>
50 11/23/16 17:35:38.276 luup_log:162: (Wink_Connect::ACTION_SwitchPower1::setTarget): Found device . Vera [168] Wink [6]. <0x2ac9d000>
02 11/23/16 17:35:38.276 luup_log:162: (Wink_Connect::HUB_DEVICES::updateDevice): found device table. <0x2ac9d000>
02 11/23/16 17:35:38.276 luup_log:162: (Wink_Connect::HUB_DEVICES::updateDevice): called - WinkDevice [1426198] cmd [{"desired_state": { "powered": false}}]. <0x2ac9d000>
02 11/23/16 17:35:38.278 luup_log:162: (Wink_Connect::HUB_DEVICES::updateDevice): REMOTE API URL [https://api.wink.com//light_bulbs/1426198]. <0x2ac9d000>
02 11/23/16 17:35:38.293 luup_log:162: (Wink_Connect::HUB_DEVICES::updateDevice): Sending http request [PUT] [https://api.wink.com//light_bulbs/1426198]. json [{"desired_state": { "powered": false}}] <0x2ac9d000>
02 11/23/16 17:35:38.294 luup_log:162: (Wink_Connect::HUB_DEVICES::updateDevice): Request Headers [
User-Agent: Mozilla/5.0 (Linux; Android 4.4; Nexus 4 Build/KRT16E) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/30.0.1599.105 Mobile Safari
Authorization: bearer ls_I1VvilpFWveO1pW4AjW0m-iJAF2ky
Content-Length: 38
Content-Type: application/json
] <0x2ac9d000>
01 11/23/16 17:35:38.401 luup_log:162: (Wink_Connect::HTTPS_FALLBACK) URL [https://api.wink.com//light_bulbs/1426198] <0x2ac9d000>
01 11/23/16 17:35:38.593 luup_log:162: (Wink_Connect::HTTPS_FALLBACK) curl command [curl --request PUT --header 'Content-Type: application/json' --data-binary '{"desired_state": { "powered": false}}' 'https://api.wink.com//light_bulbs/1426198' --insecure --connect-timeout 5 --max-time 10 --header 'Authorization: Bearer bearer ls_I1VvilpFWveO1pW4AjW0m-iJAF2ky'] <0x2ac9d000>
01 11/23/16 17:35:38.594 luup_log:162: (Wink_Connect::HTTPS_FALLBACK) curl call returned [] <0x2ac9d000>
02 11/23/16 17:35:38.595 luup_log:162: (Wink_Connect::HUB_DEVICES::updateDevice): Received http response [200] [NIL] []. <0x2ac9d000>
50 11/23/16 17:35:38.596 luup_log:162: (Wink_Connect::setChildVariable) Device [168] SID [urn:upnp-org:serviceId:SwitchPower1] variable [Target] current [0] new [0]. <0x2ac9d000>
50 11/23/16 17:35:38.596 luup_log:162: (Wink_Connect::setChildVariable) Device [168] SID [urn:upnp-org:serviceId:SwitchPower1] variable [Status] current [1] new [0]. <0x2ac9d000>
50 11/23/16 17:35:38.596 luup_log:162: (Wink_Connect::setChildVariable) Setting urn:upnp-org:serviceId:SwitchPower1::Status [0]. <0x2ac9d000>
06 11/23/16 17:35:38.597 Device_Variable::m_szValue_set device: 168 service: urn:upnp-org:serviceId:SwitchPower1 variable: Status was: 1 now: 0 #hooks: 2 upnp: 0 v:0xe29fe8/NONE duplicate:0 <0x2ac9d000>
50 11/23/16 17:35:38.787 luup_log:162: (Wink_Connect::setChildVariable) Device [168] SID [urn:upnp-org:serviceId:Dimming1] variable [LoadLevelTarget] current [0] new [0]. <0x2ac9d000>
50 11/23/16 17:35:38.788 luup_log:162: (Wink_Connect::setChildVariable) Device [168] SID [urn:upnp-org:serviceId:Dimming1] variable [LoadLevelStatus] current [100] new [0]. <0x2ac9d000>
50 11/23/16 17:35:38.789 luup_log:162: (Wink_Connect::setChildVariable) Setting urn:upnp-org:serviceId:Dimming1::LoadLevelStatus [0]. <0x2ac9d000>
06 11/23/16 17:35:38.789 Device_Variable::m_szValue_set device: 168 service: urn:upnp-org:serviceId:Dimming1 variable: LoadLevelStatus was: 100 now: 0 #hooks: 1 upnp: 0 v:0xead1b0/NONE duplicate:0 <0x2ac9d000>
50 11/23/16 17:35:38.869 luup_log:162: (Wink_Connect::ACTION_SwitchPower1::setTarget): Wink device updated [6]. <0x2ac9d000>
04 11/23/16 17:35:38.870 <Job ID="1737" Name="" Device="168" Created="2016-11-23 17:35:38" Started="2016-11-23 17:35:38" Completed="2016-11-23 17:35:38" Duration="0.609407000" Runtime="0.595277000" Status="Successful" LastNote=""/> <0x2ac9d000>
Does anyone see a problem, or have a suggestion?
Thanks,
Chris
UPDATE: I realized that there was one setting on my UI5 web page that I changed while troubleshooting my boot loops. In the Settings > Net & Wifi, I turned off the “Auto detect devices . . .” option. I re-checked the option & the Vera was again able to control the Wink devices. Case closed I hope.
Thanks,
C