Changing light status works, but slowly starts to respond less till i restart the app

[markg85]

Hi,

I think i need to clarify this a little.
I'm making a MiLight hub proxy so that it can be used with Samsung SmartThings.

The code i have right now:
note: heavily work in progress! I'm just hacking it together at the moment to get things working.

'use strict'

const milightmodule = require('node-milight-promise');
const Milight = milightmodule.MilightController;
const commands = milightmodule.commandsV6;
const discover = milightmodule.discoverBridges;
const express = require('express')
const app = express()
const bodyParser = require('body-parser')

let light = new Milight({
  ip: '10.0.3.101',
  type: 'v6'
});

/*
light.close().then(function () {
  console.log("All command have been executed - closing Milight");
});
console.log("Invocation of asynchronous Milight commands done");
*/

app.use(bodyParser.json());

function getCommandsObjectByType(type) {
  if (type == 'rgbw') {
    return commands.fullColor;
  } else if (type == 'cct') {
    return commands.white;
  }

  return commands.rgbw;
}

function handleSwitch(res, data, params, com) {
  if (data.status == 'on') {
    light.sendCommands(com.on(params.group));
  } else {
    light.sendCommands(com.off(params.group));
  }
  res.status(200).json({})
}

function handleBrightness(res, data, params, com) {
  
  console.log('Handle brightness')

  let level = parseInt(data.level);
  light.sendCommands(com.brightness(params.group, level))
  res.status(200).json({})
}

app.post('/gateways/:addr/:type/:group', (req, res) => {
  let com = getCommandsObjectByType(req.params.type);

  console.log('specific post')
  console.log(req.body)
 
  if (typeof req.body.status !== 'undefined') {
    handleSwitch(res, req.body, req.params, com);
  } else if (typeof req.body.level !== 'undefined') {
    handleBrightness(res, req.body, req.params, com);
  } else {
    console.log('  ' + typeof req.body.status)
  }

});

app.post('*', (req, res) => {
  console.log('fallback post')
  console.log(req.body)
  res.status(400).json()
});

app.listen(3000, () => {
  console.log('MiLight proxy hub is listening.')
})

That is the whole app at the moment. It's going to be on github in this repository sometime soon: https://github.com/markg85/MiLightNodeProxy
It allows me to set the light status and brightness, so far so good. And, the most awesome part, it really works on smartthings (which i import in Google Home to control the bulbs, that really works)!

I have 2 issues though.

1. After some time the commands just start are not working anymore. This seems to point at a session timeout. Here is the output of the commands while it isn't working.

specific post
{ status: 'on' }
2017-12-15T15:48:29.195Z Milight: bytesSent=22, buffer=[0x80,0x00,0x00,0x00,0x11,0x6E,0x00,0x00,0x25,0x00,0x31,0x00,0x00,0x01,0x01,0x07,0x00,0x00,0x00,0x01,0x00,0x3B]
2017-12-15T15:48:29.218Z Milight: bytesReceived=8, buffer=[0x88,0x00,0x00,0x00,0x03,0x00,0x25,0x01], remote=10.0.3.101
2017-12-15T15:48:29.318Z Milight: ready for next command
specific post
{ status: 'on' }
2017-12-15T15:48:29.496Z Milight: bytesSent=22, buffer=[0x80,0x00,0x00,0x00,0x11,0x6E,0x00,0x00,0x26,0x00,0x31,0x00,0x00,0x08,0x04,0x01,0x00,0x00,0x00,0x01,0x00,0x3F]
2017-12-15T15:48:29.525Z Milight: bytesReceived=8, buffer=[0x88,0x00,0x00,0x00,0x03,0x00,0x26,0x01], remote=10.0.3.101
2017-12-15T15:48:29.625Z Milight: ready for next command
specific post
{ status: 'on' }
2017-12-15T15:48:29.784Z Milight: bytesSent=22, buffer=[0x80,0x00,0x00,0x00,0x11,0x6E,0x00,0x00,0x27,0x00,0x31,0x00,0x00,0x08,0x04,0x01,0x00,0x00,0x00,0x02,0x00,0x40]
2017-12-15T15:48:29.802Z Milight: bytesReceived=8, buffer=[0x88,0x00,0x00,0x00,0x03,0x00,0x27,0x01], remote=10.0.3.101
2017-12-15T15:48:29.903Z Milight: ready for next command

And right after it reconnects, the lights work again:

2017-12-15T15:49:12.870Z Milight: bytesSent=27, buffer=[0x20,0x00,0x00,0x00,0x16,0x02,0x62,0x3A,0xD5,0xED,0xA3,0x01,0xAE,0x08,0x2D,0x46,0x61,0x41,0xA7,0xF6,0xDC,0xAF,0xD3,0xE6,0x00,0x00,0x1E]
2017-12-15T15:49:12.984Z Milight: bytesReceived=22, buffer=[0x28,0x00,0x00,0x00,0x11,0x00,0x02,0xF0,0xFE,0x6B,0x26,0x15,0x6A,0x5F,0xB8,0x80,0x30,0x00,0x01,0x9B,0x00,0x00], remote=10.0.3.101
2017-12-15T15:49:13.084Z Milight: ready for next command
2017-12-15T15:49:13.084Z Milight: Session Id: 0x9B,0x00
specific post
{ status: 'off' }
2017-12-15T15:49:38.578Z Milight: bytesSent=22, buffer=[0x80,0x00,0x00,0x00,0x11,0x9B,0x00,0x00,0x29,0x00,0x31,0x00,0x00,0x08,0x04,0x02,0x00,0x00,0x00,0x01,0x00,0x40]
2017-12-15T15:49:38.688Z Milight: bytesReceived=8, buffer=[0x88,0x00,0x00,0x00,0x03,0x00,0x29,0x00], remote=10.0.3.101
2017-12-15T15:49:38.788Z Milight: ready for next command
specific post
{ status: 'off' }
2017-12-15T15:49:38.878Z Milight: bytesSent=22, buffer=[0x80,0x00,0x00,0x00,0x11,0x9B,0x00,0x00,0x2A,0x00,0x31,0x00,0x00,0x01,0x01,0x08,0x00,0x00,0x00,0x01,0x00,0x3C]
2017-12-15T15:49:38.905Z Milight: bytesReceived=8, buffer=[0x88,0x00,0x00,0x00,0x03,0x00,0x2A,0x00], remote=10.0.3.101
2017-12-15T15:49:39.004Z Milight: ready for next command
specific post
{ status: 'off' }
2017-12-15T15:49:39.159Z Milight: bytesSent=22, buffer=[0x80,0x00,0x00,0x00,0x11,0x9B,0x00,0x00,0x2B,0x00,0x31,0x00,0x00,0x08,0x04,0x02,0x00,0x00,0x00,0x02,0x00,0x41]
2017-12-15T15:49:39.197Z Milight: bytesReceived=8, buffer=[0x88,0x00,0x00,0x00,0x03,0x00,0x2B,0x00], remote=10.0.3.101
2017-12-15T15:49:39.298Z Milight: ready for next command

Perhaps the keep-alive packet would fix this?

2. I have a couple RGBW lights (not WW apparently) and a couple CW/WW. All are exposed with the above code and can be set on/off individually! However, if i turn on all the lights then the ones that are in the CW/WW group will turn on, but the ones with corresponding numbers in the RGBW group won't turn on.
   So:
   CW/WW, group 1: on - goes on
   RGBW, group 1: on - stays off

I'm not adding any delays here so that might be a potential fix, do you know something else that might be causing this?

Bert regards,
Mark

[mwittig]

Regarding issue 1), this may be a session timeout indeed. Perhaps, the current iBox2 uses a shorter session timeout than the older makes. Session keep-alive would certainly solve the issue.

One thing you can try:
There is hard coded time for sessions, i.e. session will be reset if not used for 300 seconds. You can change that to a more aggressive timing, say 30 seconds. For this you need to change the timeout value to 30000 in line 67: https://github.com/mwittig/node-milight-promise/blob/master/src/milight-v6-mixin.js#L67

I'll make that configurable with the next release and possibly change the default.

Regarding issue 2) I am not sure. At a first glance your code only seems to handle either rgbww or cct or fullColor depending on the response of the '/gateways/:addr/:type/:group' post request. Does a group switch trigger multiple post requests? Did you trace the post responses?

[markg85]

Hi Marcus,

I've just set that at 30 seconds (30000) as advised. However, i'm a bit skeptical if this will work.
After a couple of hours (before changing it) the commands simply didn't work anymore. Here's a debug output of that time.

...
2017-12-16T12:57:29.474Z Milight: bytesSent=27, buffer=[0x20,0x00,0x00,0x00,0x16,0x02,0x62,0x3A,0xD5,0xED,0xA3,0x01,0xAE,0x08,0x2D,0x46,0x61,0x41,0xA7,0xF6,0xDC,0xAF,0xD3,0xE6,0x00,0x00,0x1E]
2017-12-16T12:57:29.587Z Milight: bytesReceived=22, buffer=[0x28,0x00,0x00,0x00,0x11,0x00,0x02,0xF0,0xFE,0x6B,0x26,0x15,0x6A,0x5F,0xB8,0x80,0x30,0x00,0x01,0x67,0x00,0x00], remote=10.0.3.101
2017-12-16T12:57:29.687Z Milight: ready for next command
2017-12-16T12:57:29.687Z Milight: Session Id: 0x67,0x00
specific post
{ status: 'off' }
2017-12-16T12:58:42.257Z Milight: bytesSent=22, buffer=[0x80,0x00,0x00,0x00,0x11,0x67,0x00,0x00,0x93,0x00,0x31,0x00,0x00,0x08,0x04,0x02,0x00,0x00,0x00,0x02,0x00,0x41]
2017-12-16T12:58:42.380Z Milight: bytesReceived=8, buffer=[0x88,0x00,0x00,0x00,0x03,0x00,0x93,0x01], remote=10.0.3.101
2017-12-16T12:58:42.480Z Milight: ready for next command
specific post
{ status: 'on' }
2017-12-16T12:58:58.317Z Milight: bytesSent=22, buffer=[0x80,0x00,0x00,0x00,0x11,0x67,0x00,0x00,0x94,0x00,0x31,0x00,0x00,0x08,0x04,0x01,0x00,0x00,0x00,0x02,0x00,0x40]
2017-12-16T12:58:58.497Z Milight: bytesReceived=8, buffer=[0x88,0x00,0x00,0x00,0x03,0x00,0x94,0x01], remote=10.0.3.101
2017-12-16T12:58:58.598Z Milight: ready for next command
specific post
{ status: 'off' }
2017-12-16T12:59:09.598Z Milight: bytesSent=22, buffer=[0x80,0x00,0x00,0x00,0x11,0x67,0x00,0x00,0x95,0x00,0x31,0x00,0x00,0x08,0x04,0x02,0x00,0x00,0x00,0x02,0x00,0x41]
2017-12-16T12:59:09.707Z Milight: bytesReceived=8, buffer=[0x88,0x00,0x00,0x00,0x03,0x00,0x95,0x01], remote=10.0.3.101
2017-12-16T12:59:09.807Z Milight: ready for next command
...

As you can see, right after a reconnect (the 27 bytes buffer) the commands still don't work at all.
I really have to turn off the app and start it up again.

We'll see if the 30 second reconnect solves it, i will report back about that one.

Regarding the group switch. As far as i can tell it's only doing one post per command.

[markg85]

To get back on the 30 second part. It works!
I've had that since the last post (for about 10 hours now) and no problems at all.

The fact that it works doesn't mean that it's the right fix in this case ;)
I think the keep alive packets are the solution. What i think happens now is probably a connection every 30 seconds so the device probably never went to sleep (neither will it do with keep alive) and that probably makes it work. It 'feels' fragile though.

[mwittig]

Sounds great.

Note, there is no connection as the protocol is based on UDP. "Session start" and "Session keep-alive" are just datagrams sent to the bridge. I doubt the bridge can handle keep-alive datagrams in sleep mode. Most likely there is no sleep mode at all. Unfortunately, I don't have a USB power meter to check that.

[mwittig]

Can you please do me a favor and check the same with 150 secs (150000)?

[markg85]

Sure, done.
I will report back in about 12 hours or so :)

[markg85]

150 seconds is a no-go.
It works for - say - the first 10 minutes (i didn't measure this!) or so, after that nothing works anymore.

I'm back to 30 seconds as that seems to work really well.

[mwittig]

Thanks for the update! I'll change the default value to 30000 then and I'll look into implementing keep-alive soon which is fairly easy to do.