(RESOLVED I Think) Wink not relaying commands from the plugin to the devices

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

Amazon Alexa has a skill to control Wink. You may want to try it. The language needed is more natural than what Vera can do so far. May be a good option if you like voice activation… which I do and see people light up seeing it in action.

Yes, the echo is pretty way cool, I have one Echo and 2 Dots v2 in my home, the voice commands are impressive & darn functional too.

However, it can’t do with Wink devices what Vera can do using cybermage’s plugin, eg complex scenes & PLEGs

Amazon Echo story . . .
I purchased a third echo dot and installed it at my office. I set it up using my Amazon account (of course, right?) Well, I was sitting at my desk demonstrating it in front of my co-workers and I was explaining how I use it at home. I said, “Alexa, turn on the television.” Alexa said, “Ok.” Huh, why did she say ok? I checked a camera at my home and the television was on! Then I said, “Alexa, turn on living room lights.”, Alexa said, “Ok.” & I could see through my camera that my living room lights at home turned on!

Crap, the co-workers were wowed, but what did I teach? Let’s play a game on Chris and turn off his tv, lights, adjust his thermostat, or even unlock his deadbolt from a remote location just by saying Alexa . . .

I’ll have to figure out a way to separate the echo dot at the office from my home Amazon account.

Chris

I was hoping this would fix my Wink hub 2 from doing the same thing, but it was a no go. My devices update almost immediately on Vera when I change them from Wink but just error out when trying to control them from Vera. My devices paired with my Relay’s work fine though.

oh, the devices PAIRED with your relays, but not your relay sensors or buttons? i saw that AAU is subscribed on the Relays but only AVAILABLE for the WINK HUB 2, that probably has something to do with control, but still the issues with the sensors now have to be sorted out, it says my temp and humidity on my relays are thousands of degrees.