Too many bindings to one dataholder...

[MarioGravel]

Here is what I got this morning...

[2016-01-25 11:56:21.187] [D] [zway] RECEIVED: ( 01 08 00 04 00 02 02 98 40 2B )
[2016-01-25 11:56:21.188] [D] [zway] SENT ACK
[2016-01-25 11:56:21.188] [D] [zway] SETDATA devices.2.data.lastReceived = 0 (0x00000000)
[2016-01-25 11:56:21.190] [I] [zway] Node 2:0 CC Security: sending Nonce Report
[2016-01-25 11:56:21.190] [I] [zway] Adding job: Nonce Report
[2016-01-25 11:56:21.191] [D] [zway] SENDING (cb 0xae): ( 01 11 00 13 02 0A 98 80 67 1C 3B A9 ED F4 8C 45 25 AE 5F )
[2016-01-25 11:56:21.197] [D] [zway] RECEIVED ACK
[2016-01-25 11:56:21.199] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2016-01-25 11:56:21.199] [D] [zway] SENT ACK
[2016-01-25 11:56:21.200] [D] [zway] Delivered to Z-Wave stack
[2016-01-25 11:56:21.217] [D] [zway] RECEIVED: ( 01 07 00 13 AE 00 00 02 47 )
[2016-01-25 11:56:21.218] [D] [zway] SENT ACK
[2016-01-25 11:56:21.218] [I] [zway] Job 0x13 (Nonce Report): Delivered
[2016-01-25 11:56:21.219] [D] [zway] SETDATA devices.2.data.lastPacketInfo.delivered = True
[2016-01-25 11:56:21.219] [D] [zway] SETDATA devices.2.data.lastPacketInfo.packetLength = 13 (0x0000000d)
[2016-01-25 11:56:21.220] [D] [zway] SETDATA devices.2.data.lastPacketInfo.deliveryTime = 18 (0x00000012)
[2016-01-25 11:56:21.221] [D] [zway] SETDATA devices.2.data.lastPacketInfo = **********
[2016-01-25 11:56:21.221] [D] [zway] SendData Response with callback 0xae received: received by recipient
[2016-01-25 11:56:21.222] [D] [zway] SETDATA devices.2.data.lastSend = 32150720 (0x01ea94c0)
[2016-01-25 11:56:21.223] [D] [zway] Job 0x13 (Nonce Report): success
[2016-01-25 11:56:21.224] [I] [zway] Removing job: Nonce Report
[2016-01-25 11:56:21.237] [D] [zway] RECEIVED: ( 01 1D 00 04 00 02 17 98 81 75 AD 24 67 FD 7E 47 A2 00 A3 EF 43 67 5C 0A 0B DA 8D 03 2A 76 2A )
[2016-01-25 11:56:21.238] [D] [zway] SENT ACK
[2016-01-25 11:56:21.238] [D] [zway] SETDATA devices.2.data.lastReceived = 0 (0x00000000)
[2016-01-25 11:56:21.239] [I] [zway] Node 2:0 CC Security: Received a secure message
[2016-01-25 11:56:21.240] [D] [zway] SETDATA devices.2.instances.0.commandClasses.152.data.firstPart = **********
[2016-01-25 11:56:21.241] [I] [zway] Node 2:0 CC Security: passing decrypted packet to application level: [ 20 01 ff ]
[2016-01-25 11:56:21.241] [D] [zway] SETDATA devices.1.instances.0.commandClasses.32.data.srcNodeId = 2 (0x00000002)
[2016-01-25 11:56:21.242] [D] [zway] SETDATA devices.1.instances.0.commandClasses.32.data.srcInstanceId = 0 (0x00000000)
[2016-01-25 11:56:21.242] [D] [zway] SETDATA devices.1.instances.0.commandClasses.32.data.level = 255 (0x000000ff)
[2016-01-25 11:56:21.247] [I] [core] Notification: device-info (device-OnOff): {"dev":"Aeon Labs (2.0.0) Button","l":"on"}
[2016-01-25 11:56:21.548] [D] [zway] RECEIVED: ( 01 08 00 04 00 02 02 98 40 2B )
[2016-01-25 11:56:21.549] [D] [zway] SENT ACK
[2016-01-25 11:56:21.550] [D] [zway] SETDATA devices.2.data.lastReceived = 0 (0x00000000)
[2016-01-25 11:56:21.551] [I] [zway] Node 2:0 CC Security: sending Nonce Report
[2016-01-25 11:56:21.552] [I] [zway] Adding job: Nonce Report
[2016-01-25 11:56:21.553] [D] [zway] SENDING (cb 0xaf): ( 01 11 00 13 02 0A 98 80 AF 68 E3 8D 4B BD 7D 04 25 AF 41 )
[2016-01-25 11:56:21.558] [D] [zway] RECEIVED ACK
[2016-01-25 11:56:21.560] [D] [zway] RECEIVED: ( 01 04 01 13 01 E8 )
[2016-01-25 11:56:21.561] [D] [zway] SENT ACK
[2016-01-25 11:56:21.561] [D] [zway] Delivered to Z-Wave stack
[2016-01-25 11:56:21.578] [D] [zway] RECEIVED: ( 01 07 00 13 AF 00 00 01 45 )
[2016-01-25 11:56:21.579] [D] [zway] SENT ACK
[2016-01-25 11:56:21.579] [I] [zway] Job 0x13 (Nonce Report): Delivered
[2016-01-25 11:56:21.580] [D] [zway] SETDATA devices.2.data.lastPacketInfo.delivered = True
[2016-01-25 11:56:21.581] [D] [zway] SETDATA devices.2.data.lastPacketInfo.packetLength = 13 (0x0000000d)
[2016-01-25 11:56:21.581] [D] [zway] SETDATA devices.2.data.lastPacketInfo.deliveryTime = 18 (0x00000012)
[2016-01-25 11:56:21.582] [D] [zway] SETDATA devices.2.data.lastPacketInfo = **********
[2016-01-25 11:56:21.582] [D] [zway] SendData Response with callback 0xaf received: received by recipient
[2016-01-25 11:56:21.583] [D] [zway] SETDATA devices.2.data.lastSend = 32150755 (0x01ea94e3)
[2016-01-25 11:56:21.583] [D] [zway] Job 0x13 (Nonce Report): success
[2016-01-25 11:56:21.584] [I] [zway] Removing job: Nonce Report
[2016-01-25 11:56:21.598] [D] [zway] RECEIVED: ( 01 24 00 04 00 02 1E 98 81 11 F3 4C 58 50 DF 7A 61 32 EE CE 8E CD 04 4D 9E 5D EC 63 AF 30 8A 3B 55 16 D1 5B 4D 46 )
[2016-01-25 11:56:21.598] [D] [zway] SENT ACK
[2016-01-25 11:56:21.599] [D] [zway] SETDATA devices.2.data.lastReceived = 0 (0x00000000)
[2016-01-25 11:56:21.600] [I] [zway] Node 2:0 CC Security: Received a secure message
[2016-01-25 11:56:21.601] [D] [zway] SETDATA devices.2.instances.0.commandClasses.152.data.firstPart = **********
[2016-01-25 11:56:21.602] [I] [zway] Node 2:0 CC Security: passing decrypted packet to application level: [ 71 05 00 00 00 ff 07 08 00 00 ]
[2016-01-25 11:56:21.603] [D] [zway] SETDATA devices.2.instances.0.commandClasses.113.data.7.eventParameters = byte[0]
[2016-01-25 11:56:21.603] [D] [zway]   ( zero-length buffer )
[2016-01-25 11:56:21.604] [D] [zway] SETDATA devices.2.instances.0.commandClasses.113.data.7.event = 8 (0x00000008)
[2016-01-25 11:56:21.616] [D] [zway] SETDATA devices.2.instances.0.commandClasses.113.data.7.eventString = "Motion detected, location unknown"
[2016-01-25 11:56:21.617] [D] [zway] SETDATA devices.2.instances.0.commandClasses.113.data.7.status = 255 (0x000000ff)
[2016-01-25 11:56:21.618] [D] [zway] SETDATA devices.2.instances.0.commandClasses.113.data.7 = Empty
[2016-01-25 11:56:21.624] [I] [core] Notification: error (core): Cannot create vDev based on: 2-0-113: Error: Too many bindings to one dataholder
[2016-01-25 11:56:21.628] [I] [core] Error: Too many bindings to one dataholder
    at Error (native)
    at ZWave.dataBind (automation/modules/ZWave/index.js:1081:18)
    at automation/modules/ZWave/index.js:2217:12
    at Array.forEach (native)
    at ZWave.parseAddCommandClass (automation/modules/ZWave/index.js:2120:25)
    at ZDataHolder.<anonymous> (automation/modules/ZWave/index.js:2297:12)
[2016-01-25 11:56:21.674] [I] [core] Notification: error (core): Cannot create vDev based on: 2-0-113: Error: Too many bindings to one dataholder
[2016-01-25 11:56:21.679] [I] [core] Error: Too many bindings to one dataholder
    at Error (native)
    at ZWave.dataBind (automation/modules/ZWave/index.js:1081:18)
    at automation/modules/ZWave/index.js:2217:12
    at Array.forEach (native)
    at ZWave.parseAddCommandClass (automation/modules/ZWave/index.js:2120:25)
    at ZDataHolder.<anonymous> (automation/modules/ZWave/index.js:2297:12)
[2016-01-25 11:56:21.684] [I] [core] Notification: error (core): Cannot create vDev based on: 2-0-113: Error: Too many bindings to one dataholder
[2016-01-25 11:56:21.688] [I] [core] Error: Too many bindings to one dataholder
    at Error (native)
    at ZWave.dataBind (automation/modules/ZWave/index.js:1081:18)
    at automation/modules/ZWave/index.js:2217:12
    at Array.forEach (native)
    at ZWave.parseAddCommandClass (automation/modules/ZWave/index.js:2120:25)
    at ZDataHolder.<anonymous> (automation/modules/ZWave/index.js:2297:12)
[2016-01-25 11:56:21.694] [I] [core] Notification: error (core): Cannot create vDev based on: 2-0-113: Error: Too many bindings to one dataholder
[2016-01-25 11:56:21.698] [I] [core] Error: Too many bindings to one dataholder
    at Error (native)
    at ZWave.dataBind (automation/modules/ZWave/index.js:1081:18)
    at automation/modules/ZWave/index.js:2217:12
    at Array.forEach (native)
    at ZWave.parseAddCommandClass (automation/modules/ZWave/index.js:2120:25)
    at ZDataHolder.<anonymous> (automation/modules/ZWave/index.js:2297:12)
[2016-01-25 11:56:21.704] [I] [core] Notification: error (core): Cannot create vDev based on: 2-0-113: Error: Too many bindings to one dataholder
[2016-01-25 11:56:21.709] [I] [core] Error: Too many bindings to one dataholder
    at Error (native)
    at ZWave.dataBind (automation/modules/ZWave/index.js:1081:18)
    at automation/modules/ZWave/index.js:2217:12
    at Array.forEach (native)
    at ZWave.parseAddCommandClass (automation/modules/ZWave/index.js:2120:25)
    at ZDataHolder.<anonymous> (automation/modules/ZWave/index.js:2297:12)

My device id 2 is an Aeotec MultiSensor6.

Any clue ? Questions ? Need more details ?

[pz1]

There is also quite a bit of discussion about this on the forum

[pz1]

In this forum post it was stated:

This error message occurs only if one dataholder is binded more than 500 times (not sure about exact number, but > 100 for sure). These bindings are done in JavaScript code (it is open). I suppose some bug in JS is producing more bindings than needed. That's why I ask for specific user experience - not everyone have this. Once we get more data we can understand where to look on.

Several users have responded with logs and other documentation, and are awaiting reponse.

[MarioGravel]

Do you need more info on that one ? I still have it and I can send more
info.
Le 2016-02-24 03:37, "pz1" notifications@github.com a écrit :

In this forum post
http://forum.z-wave.me/viewtopic.php?f=3419&t=22485&start=10#p60264 it
was stated:

This error message occurs only if one dataholder is binded more than 500
times (not sure about exact number, but > 100 for sure). These bindings are
done in JavaScript code (it is open). I suppose some bug in JS is producing
more bindings than needed. That's why I ask for specific user experience -
not everyone have this. Once we get more data we can understand where to
look on.

Several users have responded with logs and other documentation, and are
awaiting reponse.

—
Reply to this email directly or view it on GitHub
#318 (comment)
.

[maros]

I had this issue with Aeon Labs Multisensor 6 on 2.1.1. After upgrading to 2.2.1 this issue seems to be gone.

[MarioGravel]

It is not for fixed for me on 2.2.1.
I traced the error on the .js file but I can't get far enough.
I'm stuck here : automation/modules/ZWave/index.js

1053: var dataToBind = {
1054:               "zway": zway,
1055:               "nodeId": nodeId,
1056:               "instanceId": instanceId,
1057:               "commandClassId": commandClassId,
1058:               "path": path,
1059:               "func": data.bind(func, null, type === "child")
1060:           };

The error is :

[2016-03-16 15:19:36.392] [I] [core] Error: Too many bindings to one dataholder
    at Error (native)
    at ZWave.dataBind (automation/modules/ZWave/index.js:1059:18)
    at automation/modules/ZWave/index.js:2226:12
    at Array.forEach (native)
    at ZWave.parseAddCommandClass (automation/modules/ZWave/index.js:2129:25)
    at ZDataHolder.<anonymous> (automation/modules/ZWave/index.js:2306:12)

as far as I was able to trace, the func function passed as a parameter isn't called when the error occur. It is called until, at some point, we get the error.
So the problem is during the call of data.bind(func, null, type === "child") on line 1059 and not during the callback. I can't find this function in the .js files. I don't think I have access to the source of this function.

I have two multisensor on my z-way at the office : one on my desktop and the other in my cubicle. They are not solicited in the same way. I got the error for the one on my desktop but not the one on my cubicle that is less solicited. But now, I have the error for both of them.

Thanks !

[PoltoS]

It was not fixed yet. Please one of you, send me your expert UI backup and a part of the log that made the problem. I'll make sure we fix it asap.

[MarioGravel]

backup and log.zip

Note that I added some console.log("line number....") to know which line was executed but those insert never changed the line number of the code in automation/module/ZWave/index.js
Example:

                        console.log("LINE 2223 : Before binding");
                        // handle 0xFE unknown
                        // special case by Sigma for Unknown event - not listed in eventMask
                        self.dataBind(self.gateDataBinding, self.zway, nodeId, instanceId, commandClassId, notificationTypeId.toString(10) + ".event", function(type) { console.log("LINE 2226 : Callback function : Type = " + JSON.stringify(type));
                            var eventTypeId = parseInt(this.value, 10); console.log("LINE 2227 : Callback function : eventTypeId = " + JSON.stringify(eventTypeId));
                            if (eventTypeId === 0xFE) { console.log("LINE 2228");

This will put a lot of garbage into the log file... sorry about that.
But it allow us to see that the recursive calls get bigger and bigger every times until some "saturation".

Problems start at line #4350 of the log file.

Node 3 and node 5 are Multi Sensor 6.

Good luck !

[PoltoS]

Fixed 86a4a45