Spurious data readings FGBS 001 in v200rc8

[pz1]

I do get spurious data from my universal sensor. Irregular in time and irregular in magnitude. The graph shows the temperature of the room, and the the heating wall. Below is the log which shows a temperature of 60973.539062 degrees centigrade. This is supposed to be the wall temperature. Some three minutes before it was 25.250000.

RRDtemp.PNG (23.83 KiB) Viewed 11444 times

Note: Below is a log of the error that I just described, which occured about an hour ago. This one is not on the graph.

Code: Select all

[2014-10-10 08:26:34.610] [I] [zway] Adding job: SensorMultilevel V1-4 Get
[2014-10-10 08:26:34.613] [D] SENDING (cb 0x8e): ( 01 0D 00 13 0D 06 60 0D 00 03 31 04 25 8E 1A )
[2014-10-10 08:26:34.615] [D] [zway] RECEIVED ACK
[2014-10-10 08:26:34.618] [D] RECEIVED: ( 01 04 01 13 01 E8 )
[2014-10-10 08:26:34.618] [D] [zway] SENT ACK
[2014-10-10 08:26:34.618] [D] [zway] Delivered to Z-Wave stack
[2014-10-10 08:26:34.631] [D] RECEIVED: ( 01 05 00 13 8E 00 67 )
[2014-10-10 08:26:34.631] [D] [zway] SENT ACK
[2014-10-10 08:26:34.631] [I] [zway] Job 0x13 (SensorMultilevel V1-4 Get): Delivered
[2014-10-10 08:26:34.632] [D] [zway] SETDATA devices.13.data.lastPacketInfo.delivered = True
[2014-10-10 08:26:34.632] [D] [zway] SETDATA devices.13.data.lastPacketInfo.packetLength = 9 (0x00000009)
[2014-10-10 08:26:34.632] [D] [zway] SETDATA devices.13.data.lastPacketInfo.deliveryTime = 13 (0x0000000d)
[2014-10-10 08:26:34.632] [D] [zway] SETDATA devices.13.data.lastPacketInfo = **********
[2014-10-10 08:26:34.632] [D] [zway] SendData Response with callback 0x8e received: received by recipient
[2014-10-10 08:26:34.632] [D] [zway] SETDATA devices.13.data.lastSend = 31874333 (0x01e65d1d)
[2014-10-10 08:26:34.633] [D] [zway] Job 0x13 (SensorMultilevel V1-4 Get): success
[2014-10-10 08:26:34.633] [I] [zway] Removing job: SensorMultilevel V1-4 Get
[2014-10-10 08:26:34.641] [D] RECEIVED: ( 01 12 00 04 00 0D 0C 60 0D 03 00 31 05 01 44 00 00 09 6C 92 )
[2014-10-10 08:26:34.641] [D] [zway] SENT ACK
[2014-10-10 08:26:34.641] [D] [zway] SETDATA devices.13.data.lastReceived = 0 (0x00000000)
[2014-10-10 08:26:34.641] [D] [zway] SETDATA devices.13.instances.0.commandClasses.96.data.myInstance = 0 (0x00000000)
[2014-10-10 08:26:34.642] [D] [zway] SETDATA devices.13.instances.3.commandClasses.49.data.1.deviceScale = 0 (0x00000000)
[2014-10-10 08:26:34.643] [D] [zway] SETDATA devices.13.instances.3.commandClasses.49.data.1.scale = 0 (0x00000000)
[2014-10-10 08:26:34.643] [D] [zway] SETDATA devices.13.instances.3.commandClasses.49.data.1.val = 24.120001
[2014-10-10 08:26:34.646] [D] [zway] SETDATA devices.13.instances.3.commandClasses.49.data.1.scaleString = "°C"
[2014-10-10 08:26:34.646] [D] [zway] SETDATA devices.13.instances.3.commandClasses.49.data.1 = Empty
[2014-10-10 08:26:34.647] [D] [zway] SETDATA devices.13.instances.0.commandClasses.96.data.myInstance = Empty
[2014-10-10 08:26:35.265] [I] [zway] Adding job: SensorMultilevel V1-4 Get
[2014-10-10 08:26:35.266] [D] SENDING (cb 0x8f): ( 01 0D 00 13 0D 06 60 0D 00 05 31 04 25 8F 1D )
[2014-10-10 08:26:35.268] [D] [zway] RECEIVED ACK
[2014-10-10 08:26:35.271] [D] RECEIVED: ( 01 04 01 13 01 E8 )
[2014-10-10 08:26:35.272] [D] [zway] SENT ACK
[2014-10-10 08:26:35.272] [D] [zway] Delivered to Z-Wave stack
[2014-10-10 08:26:35.284] [D] RECEIVED: ( 01 05 00 13 8F 00 66 )
[2014-10-10 08:26:35.284] [D] [zway] SENT ACK
[2014-10-10 08:26:35.284] [I] [zway] Job 0x13 (SensorMultilevel V1-4 Get): Delivered
[2014-10-10 08:26:35.284] [D] [zway] SETDATA devices.13.data.lastPacketInfo.delivered = True
[2014-10-10 08:26:35.284] [D] [zway] SETDATA devices.13.data.lastPacketInfo.packetLength = 9 (0x00000009)
[2014-10-10 08:26:35.285] [D] [zway] SETDATA devices.13.data.lastPacketInfo.deliveryTime = 12 (0x0000000c)
[2014-10-10 08:26:35.285] [D] [zway] SETDATA devices.13.data.lastPacketInfo = **********
[2014-10-10 08:26:35.285] [D] [zway] SendData Response with callback 0x8f received: received by recipient
[2014-10-10 08:26:35.285] [D] [zway] SETDATA devices.13.data.lastSend = 31874394 (0x01e65d5a)
[2014-10-10 08:26:35.285] [D] [zway] Job 0x13 (SensorMultilevel V1-4 Get): success
[2014-10-10 08:26:35.285] [I] [zway] Removing job: SensorMultilevel V1-4 Get
[2014-10-10 08:26:35.294] [D] RECEIVED: ( 01 12 00 04 00 0D 0C 60 0D 05 00 31 05 01 44 00 00 09 8B 73 )
[2014-10-10 08:26:35.294] [D] [zway] SENT ACK
[2014-10-10 08:26:35.294] [D] [zway] SETDATA devices.13.data.lastReceived = 0 (0x00000000)
[2014-10-10 08:26:35.294] [D] [zway] SETDATA devices.13.instances.0.commandClasses.96.data.myInstance = 0 (0x00000000)
[2014-10-10 08:26:35.294] [D] [zway] SETDATA devices.13.instances.5.commandClasses.49.data.1.deviceScale = 0 (0x00000000)
[2014-10-10 08:26:35.296] [D] [zway] SETDATA devices.13.instances.5.commandClasses.49.data.1.scale = 0 (0x00000000)
[2014-10-10 08:26:35.296] [D] [zway] SETDATA devices.13.instances.5.commandClasses.49.data.1.val = 24.430000
[2014-10-10 08:26:35.300] [D] [zway] SETDATA devices.13.instances.5.commandClasses.49.data.1.scaleString = "°C"
[2014-10-10 08:26:35.300] [D] [zway] SETDATA devices.13.instances.5.commandClasses.49.data.1 = Empty
[2014-10-10 08:26:35.300] [D] [zway] SETDATA devices.13.instances.0.commandClasses.96.data.myInstance = Empty
[2014-10-10 08:26:35.914] [I] [zway] Adding job: SensorMultilevel V1-4 Get
[2014-10-10 08:26:35.920] [D] [zway] Job 0x13: deleted from queue
[2014-10-10 08:26:35.920] [D] SENDING (cb 0x90): ( 01 0D 00 13 0D 06 60 0D 00 06 31 04 25 90 01 )
[2014-10-10 08:26:35.922] [D] [zway] RECEIVED ACK
[2014-10-10 08:26:35.926] [D] RECEIVED: ( 01 04 01 13 01 E8 )
[2014-10-10 08:26:35.926] [D] [zway] SENT ACK
[2014-10-10 08:26:35.926] [D] [zway] Delivered to Z-Wave stack
[2014-10-10 08:26:35.938] [D] RECEIVED: ( 01 05 00 13 90 00 79 )
[2014-10-10 08:26:35.939] [D] [zway] SENT ACK
[2014-10-10 08:26:35.939] [I] [zway] Job 0x13 (SensorMultilevel V1-4 Get): Delivered
[2014-10-10 08:26:35.939] [D] [zway] SETDATA devices.13.data.lastPacketInfo.delivered = True
[2014-10-10 08:26:35.940] [D] [zway] SETDATA devices.13.data.lastPacketInfo.packetLength = 9 (0x00000009)
[2014-10-10 08:26:35.940] [D] [zway] SETDATA devices.13.data.lastPacketInfo.deliveryTime = 13 (0x0000000d)
[2014-10-10 08:26:35.940] [D] [zway] SETDATA devices.13.data.lastPacketInfo = **********
[2014-10-10 08:26:35.940] [D] [zway] SendData Response with callback 0x90 received: received by recipient
[2014-10-10 08:26:35.940] [D] [zway] SETDATA devices.13.data.lastSend = 31874456 (0x01e65d98)
[2014-10-10 08:26:35.940] [D] [zway] Job 0x13 (SensorMultilevel V1-4 Get): success
[2014-10-10 08:26:35.940] [I] [zway] Removing job: SensorMultilevel V1-4 Get
[2014-10-10 08:26:35.948] [D] RECEIVED: ( 01 12 00 04 00 0D 0C 60 0D 06 00 31 05 01 44 00 5D 09 CA 6C )
[2014-10-10 08:26:35.948] [D] [zway] SENT ACK
[2014-10-10 08:26:35.948] [D] [zway] SETDATA devices.13.data.lastReceived = 0 (0x00000000)
[2014-10-10 08:26:35.949] [D] [zway] SETDATA devices.13.instances.0.commandClasses.96.data.myInstance = 0 (0x00000000)
[2014-10-10 08:26:35.949] [D] [zway] SETDATA devices.13.instances.6.commandClasses.49.data.1.deviceScale = 0 (0x00000000)
[2014-10-10 08:26:35.950] [D] [zway] SETDATA devices.13.instances.6.commandClasses.49.data.1.scale = 0 (0x00000000)
[2014-10-10 08:26:35.950] [D] [zway] SETDATA devices.13.instances.6.commandClasses.49.data.1.val = 60973.539062
[2014-10-10 08:26:35.953] [D] [zway] SETDATA devices.13.instances.6.commandClasses.49.data.1.scaleString = "°C"
[2014-10-10 08:26:35.954] [D] [zway] SETDATA devices.13.instances.6.commandClasses.49.data.1 = Empty
[2014-10-10 08:26:35.954] [D] [zway] SETDATA devices.13.instances.0.commandClasses.96.data.myInstance = Empty
[2014-10-10 08:26:36.047] [D] [zway] Job 0x13: deleted from queue
[2014-10-10 08:26:36.404] [I] [zway] Adding job: SensorMultilevel V1-4 Get
[2014-10-10 08:26:36.406] [D] SENDING (cb 0x91): ( 01 0D 00 13 0D 06 60 0D 00 04 31 04 25 91 02 )
[2014-10-10 08:26:36.408] [D] [zway] RECEIVED ACK
[2014-10-10 08:26:36.411] [D] RECEIVED: ( 01 04 01 13 01 E8 )
[2014-10-10 08:26:36.411] [D] [zway] SENT ACK
[2014-10-10 08:26:36.412] [D] [zway] Delivered to Z-Wave stack
[2014-10-10 08:26:36.424] [D] RECEIVED: ( 01 05 00 13 91 00 78 )
[2014-10-10 08:26:36.424] [D] [zway] SENT ACK
[2014-10-10 08:26:36.425] [I] [zway] Job 0x13 (SensorMultilevel V1-4 Get): Delivered
[2014-10-10 08:26:36.425] [D] [zway] SETDATA devices.13.data.lastPacketInfo.delivered = True
[2014-10-10 08:26:36.425] [D] [zway] SETDATA devices.13.data.lastPacketInfo.packetLength = 9 (0x00000009)
[2014-10-10 08:26:36.425] [D] [zway] SETDATA devices.13.data.lastPacketInfo.deliveryTime = 12 (0x0000000c)
[2014-10-10 08:26:36.425] [D] [zway] SETDATA devices.13.data.lastPacketInfo = **********
[2014-10-10 08:26:36.425] [D] [zway] SendData Response with callback 0x91 received: received by recipient
[2014-10-10 08:26:36.426] [D] [zway] SETDATA devices.13.data.lastSend = 31874501 (0x01e65dc5)
[2014-10-10 08:26:36.426] [D] [zway] Job 0x13 (SensorMultilevel V1-4 Get): success
[2014-10-10 08:26:36.426] [I] [zway] Removing job: SensorMultilevel V1-4 Get
[2014-10-10 08:26:36.434] [D] RECEIVED: ( 01 12 00 04 00 0D 0C 60 0D 04 00 8E 05 01 44 00 00 07 D6 9E )
[2014-10-10 08:26:36.434] [D] [zway] SENT ACK
[2014-10-10 08:26:36.434] [D] [zway] SETDATA devices.13.data.lastReceived = 0 (0x00000000)
[2014-10-10 08:26:36.434] [I] [zway] Node 13:0 CC MultiChannel: Received CC 0x8e command from instance 4, but it isn't registered, creating it
[2014-10-10 08:26:36.435] [D] [zway] SETDATA devices.13.instances.4.commandClasses.142.data = Empty
[2014-10-10 08:26:36.435] [D] [zway] SETDATA devices.13.instances.4.commandClasses.142.data.supported = Empty
[2014-10-10 08:26:36.435] [D] [zway] SETDATA devices.13.instances.4.commandClasses.142.data.supported = True
[2014-10-10 08:26:36.435] [D] [zway] SETDATA devices.13.instances.4.commandClasses.142.data.version = Empty
[2014-10-10 08:26:36.435] [D] [zway] SETDATA devices.13.instances.4.commandClasses.142.data.version = 1 (0x00000001)
[2014-10-10 08:26:36.435] [D] [zway] SETDATA devices.13.instances.4.commandClasses.142.data.security = Empty
[2014-10-10 08:26:36.436] [D] [zway] SETDATA devices.13.instances.4.commandClasses.142.data.security = False
[2014-10-10 08:26:36.436] [D] [zway] SETDATA devices.13.instances.4.commandClasses.142.data.interviewDone = Empty
[2014-10-10 08:26:36.437] [D] [zway] SETDATA devices.13.instances.4.commandClasses.142.data.interviewCounter = Empty
[2014-10-10 08:26:36.437] [D] [zway] SETDATA devices.13.instances.4.commandClasses.142.data.interviewDone = False
[2014-10-10 08:26:36.438] [D] [zway] SETDATA devices.13.instances.4.commandClasses.142.data.interviewCounter = 10 (0x0000000a)
[2014-10-10 08:26:36.438] [D] [zway] SETDATA devices.13.instances.4.commandClasses.142.data.groups = Empty
[2014-10-10 08:26:36.438] [D] [zway] SETDATA devices.13.instances.4.commandClasses.142.data.supported = False
[2014-10-10 08:26:36.438] [D] [zway] SETDATA devices.13.instances.0.commandClasses.96.data.myInstance = 0 (0x00000000)
[2014-10-10 08:26:36.438] [W] [zway] Node 13:4 CC MultiChannelAssociation: Discarding received Groupings Set packet
[2014-10-10 08:26:36.438] [D] [zway] SETDATA devices.13.instances.0.commandClasses.96.data.myInstance = Empty
[2014-10-10 08:26:43.760] [D] [zway] Job 0x13: deleted from queue
[2014-10-10 08:26:43.883] [D] [zway] Job 0x13: deleted from queue
[2014-10-10 08:26:45.629] [I] [zway] Adding job: Meter get (v2)

I don't remember having had such occurences with version 1.4. The difference is that this is a new additional FUS and I have extended the Z-Wave net with 5 StellaZ and two Range Extenders. I do use OpenRemoteHelpers now. Befor RaZ-OR. All driven from OpenRemote, which produced the graph using RRD.

[pofs]

It seems to be hot at your place

Looks like a device sends wrong values sometimes. If you look at the received packets, they all have the same scale, precision and size (0x44), but 4-byte value changes drastically for those wrong packets.

[pz1]

It seems to be hot at your place

Looks like a device sends wrong values sometimes. If you look at the received packets, they all have the same scale, precision and size (0x44), but 4-byte value changes drastically for those wrong packets.

I was tempted to say that v200 is a hot product
I have started sensor loggers for one channel of both my Fibaro's. You may remember I made an other post about their differences. Still waiting for a decent answer on my mails from them

[pz1]

This is what the logger registers on the other Fibaro Universal Sensor:

Code: Select all

{"deviceId":"ZWayVDev_15:3:49:1","deviceName":"Sensor 15:3:49:1","sensorData":[{"time":1413019083123,"value":16.68},{"time":1413019284191,"value":16.68},{"time":1413019485247,"value":17.18},{"time":1413019686313,"value":17.18},{"time":1413019887343,"value":17.18},{"time":1413020088812,"value":17.18},{"time":1413020290399,"value":17.18},{"time":1413020491346,"value":17.18},{"time":1413020692382,"value":17.18},{"time":1413020893419,"value":133055.2635392},{"time":1413021094476,"value":17.18},{"time":1413021295657,"value":17.18},{"time":1413021496559,"value":17.68},{"time":1413021697607,"value":17.68},{"time":1413021898645,"value":17.68},{"time":1413022099733,"value":17.68},{"time":1413022301809,"value":17.68},{"time":1413022502853,"value":17.68},{"time":1413022703904,"value":17.68},{"time":1413022904946,"value":17.68},{"time":1413023105995,"value":17.68},{"time":1413023307769,"value":17.68},{"time":1413023508821,"value":17.68},{"time":1413023709852,"value":17.68},{"time":1413023910898,"value":17.68},{"time":1413024111924,"value":17.68},{"time":1413024313060,"value":17.68},{"time":1413024514006,"value":17.68},{"time":1413024715047,"value":0},{"time":1413024916135,"value":17.68},{"time":1413025117179,"value":17.68},{"time":1413025318215,"value":17.68},{"time":1413025519258,"value":17.68},{"time":1413025720308,"value":17.68},{"time":1413025921361,"value":17.68},{"time":1413026122385,"value":17.68},{"time":1413026524467,"value":17.68},{"time":1413026725509,"value":17.68},{"time":1413026926557,"value":17.68},{"time":1413027145080,"value":17.68},{"time":1413027328606,"value":17.68},{"time":1413027529654,"value":17.68},{"time":1413027730697,"value":17.68},{"time":1413027931730,"value":18.18},{"time":1413028132756,"value":18.18},{"time":1413028333795,"value":18.18},{"time":1413028735876,"value":18.18},{"time":1413028937076,"value":18.18},{"time":1413029138214,"value":18.18},{"time":1413029339246,"value":18.18},{"time":1413029540287,"value":18.18},{"time":1413029741359,"value":18.18},{"time":1413029942399,"value":18.18},{"time":1413030143425,"value":18.18},{"time":1413030344465,"value":18.18},{"time":1413030545540,"value":18.18},{"time":1413030761853,"value":18.68},{"time":1413030947702,"value":18.68},{"time":1413031148740,"value":18.68},{"time":1413031349769,"value":18.68},{"time":1413031550802,"value":18.68},{"time":1413031751854,"value":19.18},{"time":1413031969742,"value":19.18},{"time":1413032153924,"value":19.18},{"time":1413032354970,"value":18.6299984},{"time":1413032556013,"value":19.18},{"time":1413032757038,"value":19.18},{"time":1413032958097,"value":19.18},{"time":1413033159160,"value":19.18},{"time":1413033360193,"value":19.18},{"time":1413033561247,"value":19.18},{"time":1413033762293,"value":19.18},{"time":1413034164369,"value":19.18},{"time":1413034365415,"value":19.18},{"time":1413034566444,"value":19.18},{"time":1413034767492,"value":19.68},{"time":1413034968518,"value":19.68},{"time":1413035169564,"value":19.68},{"time":1413035370597,"value":19.68},{"time":1413035571650,"value":19.68},{"time":1413035772680,"value":19.68},{"time":1413035974542,"value":19.68},{"time":1413036376583,"value":19.68},{"time":1413036577638,"value":19.68},{"time":1413036778668,"value":19.68},{"time":1413036979701,"value":19.68},{"time":1413037180750,"value":19.68},{"time":1413037381803,"value":19.68},{"time":1413037582820,"value":19.68},{"time":1413037783851,"value":19.68},{"time":1413037986923,"value":19.68},{"time":1413038185932,"value":19.68},{"time":1413038386978,"value":19.68},{"time":1413038588072,"value":19.68},{"time":1413038789059,"value":19.68},{"time":1413038990107,"value":19.68},{"time":1413039191140,"value":19.68},{"time":1413039392170,"value":19.68}]}

The same spurious data. For example a temperature value of 133055.2635392. The sensors are some five and six meters away from the Rasberry Pi. the one with this log is behind a wall of 9mm plasterboard.

So looks like similar errors. Is there anyone out there who has done some similar experiments with logging Fibaro Universal Sensor logging? Below of my Rule definition in version 2.0.0-rc8

logger.png.PNG (18.71 KiB) Viewed 11359 times

[pofs]

Can't be sure looking at just one short log fragment, but I've noticed one more strange thing.

Right after invalid temperature packet (from instance 6 in your log) comes another packet (from instance 4) which has a wrong CC id (0x8E instead of 0x31). Looks like some memory corruption to me.
Also might be a coincidence, but that 0x8E is exactly the same as callback id in the first of 4 Get commands in a batch.

Can you please show the entire log from the start?

[pz1]

Unfortunately I lost the logs, because the Pi crashed and could not be restarted. (I think it is about time that I get another Pi to use for experimentation)
What I can say that in this experiment calls for temperatures were coming independently from:

1. SensorValueLogging
2. OpenRemotHelpers which are called by OpenRemote

note: In OpenRemote there are two independant triggers to the same command

1. Regular update calls on all four temperature sensors at every 201 seconds
2. Calls by the RRDGraph plugin which asks for two of the sensors

Below is the OpenRemoteHelper code. I do not know what calls are made for the SensorValuelogging. Without the logging, the spikes were there as well.

Code: Select all

case "TemperatureLevel":
                var S = 1;
                zway.devices[N].instances[I].SensorMultilevel.Get();
                return zway.devices[N].instances[I].SensorMultilevel.data[S].val.value;

[pofs]

Then I think we should postpone until some new logs are collected

[pz1]

I should not write this, but since I am using rc10 I have not seen any spurious data in my RRDGraph . But may be that is because rc10 is functioning differently from rc8 (I do not get widgets, and can't configure rules there, etc)
I'll continue to work with these temp sensors over night, and revert to rc8 tomorrow morning, and see what happens

[pz1]

I'll continue to work with these temp sensors over night, and revert to rc8 tomorrow morning, and see what happens

I must add to the previous message that I had stopped the OpenRemote server. I assume OR en java jdk 1.8 had been installed in the RaZberry image that I downloaded for my "fresh" install.
So as promised yesterday morning I reverted to rc8. Now almost 24 hours later, the spurious data are still gone. (I did remove openremote from init.d)
Remain puzzled, why and how OR could have interfered. As both my Fibaro devices exhibited similar, but not synchonous behaviour, I think I can rule out wiring problems beteeen the Fibaro and the sensors.

PS: As I won't need OpenRemote on the Pi, I have removed it from the system

[pofs]

I suspect it might something to do with OR polling all the instances at nearly the same time.
In previous log requests are coming with ~0.5 second interval.