Graph for one metric not being shown anymore past some date

Started by LukaQ, October 23, 2017, 02:49:25 PM

Print
Go Down Pages1 2 All
User actions

LukaQ

October 23, 2017, 02:49:25 PM Last Edit: October 23, 2017, 02:52:34 PM by LukaQ
 So, I have graph for one of the metric H not being shown anymore past some date. Nothing was changed at that time, that whole node is still logged ok
Code Select 
{"_id":40,"updated":1508784155631,"rssi":47,"metrics":{
"C":{"label":"C","value":21.21,"unit":"°","updated":1508784155631,"pin":1,"graph":1},
"H":{"label":"H","value":53.87,"unit":"%","updated":1508784155631,"pin":1,"graph":1},
"P":{"label":"P","value":1007.34,"unit":"mBar","updated":1508784155631,"pin":1,"graph":1},
"START":{"label":"START","value":"Started","updated":1508742977303,"pin":0},"RSSI":{"label":"RSSI","value":-41,"unit":"db","updated":1508784155631,"pin":0,"graph":1}},"type":"WeatherMote","label":"Indoor Sensor","descr":"bme280"}

yet for H, last point was written to db on 4/10, and nothing else past that

What to do?

Felix

#1
October 23, 2017, 09:57:47 PM
Can you look at the logs to see exactly what data is coming in and if it's the same?
Maybe the bin file is corrupt, are you using good SD cards?

LukaQ

#2
October 24, 2017, 12:17:11 AM
Code Select 
{"_id":5,"updated":1508817989265,"rssi":30,"metrics":{
"C":{"label":"C","value":9.94,"unit":"°","updated":1508817989265,"pin":1,"graph":1},
"RSSI":{"label":"RSSI","value":-34,"unit":"db","updated":1508817989265,"graph":1,"pin":0}},"descr":"ds18b20","type":"WeatherMote","label":"Outdoor Sensor"}
{"_id":40,"updated":1508817993318,"rssi":47,"metrics":{
"C":{"label":"C","value":20.54,"unit":"°","updated":1508817993318,"pin":1,"graph":1},
"H":{"label":"H","value":53.39,"unit":"%","updated":1508817993318,"pin":1,"graph":1},
"P":{"label":"P","value":1011.5,"unit":"mBar","updated":1508817993318,"pin":1,"graph":1},
"START":{"label":"START","value":"Started","updated":1508742977303,"pin":0},"RSSI":{"label":"RSSI","value":-46,"unit":"db","updated":1508817993318,"pin":0,"graph":1}},"type":"WeatherMote","label":"Indoor Sensor","descr":"bme280"}
{"_id":40,"updated":1508818018359,"rssi":47,"metrics":{
"C":{"label":"C","value":20.57,"unit":"°","updated":1508818018359,"pin":1,"graph":1},
"H":{"label":"H","value":53.42,"unit":"%","updated":1508818018359,"pin":1,"graph":1},
"P":{"label":"P","value":1011.46,"unit":"mBar","updated":1508818018359,"pin":1,"graph":1},
"START":{"label":"START","value":"Started","updated":1508742977303,"pin":0},"RSSI":{"label":"RSSI","value":-46,"unit":"db","updated":1508818018359,"pin":0,"graph":1}},"type":"WeatherMote","label":"Indoor Sensor","descr":"bme280"}

That looks to me to be ok and as it was. How do I test SD card for corruption? SD card is 16G from SanDisk, that should be ok, I don't know if it is yet 1year old.
It's also weird that it wouldn't work past some day, I would think whole file would be corrupted, isn't that so? Everything else that I use on that PI works ok, all other graphs are ok

Felix

#3
October 24, 2017, 11:18:43 AM
I meant the gateway.sys.log not the gateway.db which only keeps the latest values.
I don't see why it would stop. You will need to investigate further and see what changed. Code doesnt just stop working because it has a bad day like us humans :)
If you find a cause let me know and I will fix it.

LukaQ

#4
October 24, 2017, 12:54:25 PM Last Edit: October 24, 2017, 01:15:30 PM by LukaQ
Code Select 
[10-04-17_16:22:55.660] [LOG]   >: [5] C:16.50   [RSSI:-35][ACK-sent]
[10-04-17_16:22:55.663] [LOG]   post: /home/pi/gateway/data/db/0005_C.bin[1507126975,16.5]
[10-04-17_16:22:55.665] [LOG]   post: /home/pi/gateway/data/db/0005_RSSI.bin[1507126975,-35]
[10-04-17_16:22:55.671] [LOG]      [5] DB-Updates:1
[10-04-17_16:17:21.864] [INFO]  LOADING USER METRICS...
[10-04-17_16:17:21.883] [INFO]  LOADING USER METRICS MODULE [_example.js]
[10-04-17_16:17:23.025] [LOG]   >: [40] C:21.45 H:51.65 P:1016.58   [RSSI:-46][ACK-sent]
[10-04-17_16:17:23.046] [LOG]   post: /home/pi/gateway/data/db/0040_C.bin[1507126643,21.45]
[10-04-17_16:17:23.065] [LOG]   post: /home/pi/gateway/data/db/0040_H.bin[1507126643,51.65]
[10-04-17_16:17:23.066] [ERROR]    POST ERROR: undefined
[10-04-17_16:17:23.069] [LOG]   post: /home/pi/gateway/data/db/0040_P.bin[1507126643,1016.58]
[10-04-17_16:17:23.084] [LOG]   post: /home/pi/gateway/data/db/0040_RSSI.bin[1507126643,-46]
[10-04-17_16:17:23.115] [LOG]      [40] DB-Updates:1
[10-04-17_16:37:03.757] [INFO]  AUTHORIZING CONNECTION FROM ::1:41990
[10-04-17_16:37:03.769] [INFO]  NEW CONNECTION FROM 192.168.2.1
[10-04-17_16:37:11.730] [LOG]   >: [5] C:16.50   [RSSI:-35][ACK-sent]
[10-04-17_16:37:11.735] [LOG]   post: /home/pi/gateway/data/db/0005_C.bin[1507127831,16.5]
[10-04-17_16:37:11.742] [LOG]   post: /home/pi/gateway/data/db/0005_RSSI.bin[1507127831,-35]
[10-04-17_16:37:11.757] [LOG]      [5] DB-Updates:1
[10-04-17_16:37:18.796] [LOG]   >: [40] C:21.46 H:51.75 P:1016.48   [RSSI:-43][ACK-sent]
[10-04-17_16:37:18.801] [LOG]   post: /home/pi/gateway/data/db/0040_C.bin[1507127838,21.46]
[10-04-17_16:37:18.803] [LOG]   post: /home/pi/gateway/data/db/0040_H.bin[1507127838,51.75]
[10-04-17_16:37:18.804] [ERROR]    POST ERROR: undefined
[10-04-17_16:37:18.805] [LOG]   post: /home/pi/gateway/data/db/0040_P.bin[1507127838,1016.48]
[10-04-17_16:37:18.810] [LOG]   post: /home/pi/gateway/data/db/0040_RSSI.bin[1507127838,-43]
[10-04-17_16:37:18.819] [LOG]      [40] DB-Updates:1
[10-04-17_16:37:42.835] [LOG]   >: [40] C:21.49 H:51.67 P:1016.47   [RSSI:-46][ACK-sent]
[10-04-17_16:37:42.838] [LOG]   post: /home/pi/gateway/data/db/0040_C.bin[1507127862,21.49]
[10-04-17_16:37:42.846] [LOG]   post: /home/pi/gateway/data/db/0040_H.bin[1507127862,51.67]
[10-04-17_16:37:42.847] [ERROR]    POST ERROR: undefined
[10-04-17_16:37:42.852] [LOG]   post: /home/pi/gateway/data/db/0040_P.bin[1507127862,1016.47]
[10-04-17_16:37:42.855] [LOG]   post: /home/pi/gateway/data/db/0040_RSSI.bin[1507127862,-46]
[10-04-17_16:37:42.874] [LOG]      [40] DB-Updates:1
[10-04-17_16:38:07.884] [LOG]   >: [40] C:21.49 H:51.70 P:1016.47   [RSSI:-47][ACK-sent]
[10-04-17_16:38:07.889] [LOG]   post: /home/pi/gateway/data/db/0040_C.bin[1507127887,21.49]
[10-04-17_16:38:07.890] [LOG]   post: /home/pi/gateway/data/db/0040_H.bin[1507127887,51.7]
[10-04-17_16:38:07.890] [ERROR]    POST ERROR: undefined
[10-04-17_16:38:07.892] [LOG]   post: /home/pi/gateway/data/db/0040_P.bin[1507127887,1016.47]
[10-04-17_16:38:07.894] [LOG]   post: /home/pi/gateway/data/db/0040_RSSI.bin[1507127887,-47]
[10-04-17_16:38:07.907] [LOG]      [40] DB-Updates:1
[10-04-17_16:38:13.913] [LOG]   >: [5] C:16.50   [RSSI:-35][ACK-sent]
[10-04-17_16:38:13.917] [LOG]   post: /home/pi/gateway/data/db/0005_C.bin[1507127893,16.5]
[10-04-17_16:38:13.919] [LOG]   post: /home/pi/gateway/data/db/0005_RSSI.bin[1507127893,-35]
[10-04-17_16:38:13.927] [LOG]      [5] DB-Updates:1
[10-04-17_16:38:31.962] [LOG]   >: [40] C:21.46 H:51.70 P:1016.54   [RSSI:-45][ACK-sent]
[10-04-17_16:38:31.966] [LOG]   post: /home/pi/gateway/data/db/0040_C.bin[1507127911,21.46]
[10-04-17_16:38:31.968] [LOG]   post: /home/pi/gateway/data/db/0040_H.bin[1507127911,51.7]
[10-04-17_16:38:31.969] [ERROR]    POST ERROR: undefined

There are some errors. before this errors started to be, this has come to light
Code Select 
[10-04-17_16:17:20.690] [INFO]  LOADING USER METRICS...
[10-04-17_16:17:20.709] [INFO]  LOADING USER METRICS MODULE [_example.js]


So _example.js...

Code Select 
  H : { name:'H',
	regexp:/\bH\:([\d\.]+)\b/i, 
	value:'', 
	duplicateInterval:3600, 
	unit:'%', 
	pin:1, 
	graph:1, 
	graphOptions:	{legendLbl:'Humidity',
			 lines: { steps: false, lineWidth:1 },
			 colors:['#F9c'],
			 //yaxis: { tickSize: 0.1},
			 series: { curvedLines: { active: false, apply: false, nrSplinePoints: 1}, 
					 lines: { show: true, fill: true, fillColor: "rgba(205, 20, 255, 0.3)" },
      			   	   	points: { show: false, fill: false },
				  autoMarkings: { enabled: true, showMinMax: true, showAvg: true, minMaxAlpha: 0.3, lineWidth: 1, avgcolor: "rgb(255, 0, 0)"},		
				 }
			}

      },
Do you see anything wrong here?

and what would this be?
Code Select 
POST ERROR: undefined


FYI:If I delete the H database of node 40, it's starts new file and it can log again and no POST ERRORs anymore

Felix

#5
October 24, 2017, 01:30:33 PM
I dont see anything wrong but I only looked at the code visually. Most likely if it loads and the metrics are recognized, it works fine.
Undefined error doesn't say much. You need to add more debugging code there perhaps.

BTW I've seen very good brand SD cards fail after just a few months.

LukaQ

#6
October 24, 2017, 01:47:55 PM
Quote from: Felix on October 24, 2017, 01:30:33 PM
Undefined error doesn't say much. You need to add more debugging code there perhaps.
Where to?
It is interesting, that if file is deleted and new on is created, db is ok, but if I copy what I had, same thing continues. Maybe there is something to be seen in db file? would you fancy a look at it?

What SD cards do you use? how long do you have them before you do something?

Felix

#7
October 24, 2017, 02:35:28 PM
If I recall correctly, I have seen corrupted bin files from you before. Noone else has reported a problem in that area, and I haven't seen any myself except with corrupted SD cards.
I don't think it's worthwhile for me to investigate further just to find the same problem.
The bad ones are Kingston, the good ones are sandisk.

LukaQ

#8
October 24, 2017, 03:46:22 PM
before this, it wasn't corrupted bin file, just one point in log with date, that was far off, like 1970 and it draw graph that way. This is something totally different

Felix

#9
October 24, 2017, 05:02:32 PM
Oh yes, that invalid date corrupted the data graph, now I remember. How that point got in your data was still not determined as far as I remember.
For this one .. we still have not found why the data "stopped" so it's not clear if its corruption or some other problem.
In the log there is an unknown exception. That's where you need to dig further. Add some exception handling where the logging happens, here is the logger being invoked in gateway.js:

https://github.com/LowPowerLab/RaspberryPi-Gateway/blob/master/gateway.js#L556

Code Select 
try {
  console.log('post: ' + logfile + '[' + ts + ','+graphValue + ']');
  dbLog.postData(logfile, ts, graphValue, matchingMetric.duplicateInterval || null);
} catch (err) { console.error('   POST ERROR: ' + err.message); /*console.log('   POST ERROR STACK TRACE: ' + err.stack); */ }


dbLog.postData is located in logUtil.js, you could add more exception handling there.
I suggested this could be corruption, maybe concurrency, but still I would expect it a lot more often, especially in for users who have lots of nodes and data. In years of use I would expect to see this type of thing myself if there was a bug in the code.

LukaQ

#10
October 25, 2017, 12:50:16 AM Last Edit: October 25, 2017, 12:55:37 AM by LukaQ
as far as I see in the gateway.sys.log, problem starts here:

Code Select 
[10-04-17_16:28:42.849] [LOG]   >: [40] C:21.47 H:51.52 P:1016.69   [RSSI:-42][ACK-sent]
[10-04-17_16:28:42.852] [LOG]   post: /home/pi/gateway/data/db/0040_C.bin[1507127322,21.47]
[10-04-17_16:28:42.853] [LOG]   post: /home/pi/gateway/data/db/0040_H.bin[1507127322,51.52]
[10-04-17_16:28:42.854] [LOG]   post: /home/pi/gateway/data/db/0040_P.bin[1507127322,1016.69]
[10-04-17_16:28:42.857] [LOG]   post: /home/pi/gateway/data/db/0040_RSSI.bin[1507127322,-42]
[10-04-17_16:28:42.863] [LOG]      [40] DB-Updates:1
[10-04-17_16:29:07.920] [LOG]   >: [40] C:21.47 H:51.54 P:1016.69   [RSSI:-65][ACK-sent]
[10-04-17_16:29:07.923] [LOG]   post: /home/pi/gateway/data/db/0040_C.bin[1507127347,21.47]
[10-04-17_16:29:07.924] [LOG]   post: /home/pi/gateway/data/db/0040_H.bin[1507127347,51.54]
[10-04-17_16:29:07.925] [LOG]   post: /home/pi/gateway/data/db/0040_P.bin[1507127347,1016.69]
[10-04-17_16:29:07.926] [LOG]   post: /home/pi/gateway/data/db/0040_RSSI.bin[1507127347,-65]
[10-04-17_16:29:07.933] [LOG]      [40] DB-Updates:1
[10-04-17_16:29:31.978] [LOG]   >: [40] C:21.46 H:51.53 P:1016.67   [RSSI:-45][ACK-sent]
[10-04-17_16:29:31.983] [LOG]   post: /home/pi/gateway/data/db/0040_C.bin[1507127371,21.46]
[10-04-17_16:29:31.984] [LOG]   post: /home/pi/gateway/data/db/0040_H.bin[1507127371,51.53]
[10-04-17_16:29:31.986] [LOG]   post: /home/pi/gateway/data/db/0040_P.bin[1507127371,1016.67]
[10-04-17_16:29:31.987] [LOG]   post: /home/pi/gateway/data/db/0040_RSSI.bin[1507127371,-45]
[10-04-17_16:29:31.994] [LOG]      [40] DB-Updates:1
[10-04-17_16:29:57.047] [LOG]   >: [40] C:21.48 H:51.54 P:1016.68   [RSSI:-55][ACK-sent]
[10-04-17_16:29:57.054] [LOG]   post: /home/pi/gateway/data/db/0040_C.bin[1507127397,21.48]
[10-04-17_16:29:57.056] [LOG]   post: /home/pi/gateway/data/db/0040_H.bin[1507127397,51.54]
[10-04-17_16:29:57.057] [LOG]   post: /home/pi/gateway/data/db/0040_P.bin[1507127397,1016.68]
[10-04-17_16:29:57.059] [LOG]   post: /home/pi/gateway/data/db/0040_RSSI.bin[1507127397,-55]
[10-04-17_16:29:57.065] [LOG]      [40] DB-Updates:1
[10-04-17_16:17:20.690] [INFO]  LOADING USER METRICS...
[10-04-17_16:17:20.709] [INFO]  LOADING USER METRICS MODULE [_example.js]
[10-04-17_16:17:32.891] [LOG]   >: [40] C:21.49 H:51.52 P:1016.61   [RSSI:-53][ACK-sent]
[10-04-17_16:17:32.924] [LOG]   post: /home/pi/gateway/data/db/0040_C.bin[1507126652,21.49]
[10-04-17_16:17:32.948] [LOG]   post: /home/pi/gateway/data/db/0040_H.bin[1507126652,51.52]
[10-04-17_16:17:32.949] [ERROR]    POST ERROR: undefined
[10-04-17_16:17:32.954] [LOG]   post: /home/pi/gateway/data/db/0040_P.bin[1507126652,1016.61]
[10-04-17_16:17:32.973] [LOG]   post: /home/pi/gateway/data/db/0040_RSSI.bin[1507126652,-53]
[10-04-17_16:17:32.998] [LOG]      [40] DB-Updates:1

If you look at the time, it was 10-04-17_16:29:57 the last time node was updated... then I rebooted the system for some reason and after boot it must have gotten new time, which was 10-04-17_16:17:20.690 and there the  first error started to show. Last logged point was 4:29pm with H being 51.53%. Last 3 points are as follows: 51.52, 51.54, 51.53, but in the log the is also 51.54, which is not on graph. Could this time jump do something like that?
I would really like to edit this bin file, delete those lines where time was, what was before that

There is one thing I would like to know also, how do you edit neDB bin file?

Felix

#11
October 25, 2017, 08:54:06 AM
There are some assumptions about the log data. It has to be entered sequentially. The logUtil code does some checks when you post new data:

- it checks if the data is later than the last point in the file, then it just appends it to the file
- if it determines it's somewhere in the middle, it will search for that same timestamp for updating, if it finds it


Code Select 
    if (timestamp > lastTime)
    {
      if (value != lastValue || (duplicateInterval==null || timestamp-lastTime>duplicateInterval)) //only write new value if different than last value or duplicateInterval seconds has passed (should be a setting?)
      {
        //timestamp is in the future, append
        fd = fs.openSync(filename, 'a');
        fs.writeSync(fd, buff, 0, 9, logsize);
        fs.closeSync(fd);
      }
    }
    else
    {
      //timestamp is somewhere in the middle of the log, identify exact timestamp to update
      fd = fs.openSync(filename, 'r');
      pos = exports.binarySearchExact(fd,timestamp,logsize);
      fs.closeSync(fd);

      if (pos!=-1)
      {
        fd = fs.openSync(filename, 'r+');
        fs.writeSync(fd, buff, 0, 9, pos);
        fs.closeSync(fd);
      }
    }


neDB is only used for gateway.db which is JSON format
the log data is a custom binary format which I've explained before: 9bytes per record = [1 byte reserved, 4 bytes timestamp, 4 bytes value]

You can try export the data to excel to look at it and determine where it went wrong and if it corresponds to your sys logs.

Regarding your last log, something is really wrong there. If you rebooted, even if the time is wrong, there should be a lot more log information during startup, not just user metrics loading.

LukaQ

#12
October 25, 2017, 10:12:17 AM
Quote from: Felix on October 25, 2017, 08:54:06 AM
- if it determines it's somewhere in the middle, it will search for that same timestamp for updating, if it finds it
Is this really sensible? If the time has passed, it has passed, this search would be only good if you were to edit data, which there is no option now. It's not great if system can do it by itself (that is if clock is moved or time is off)

What is your thinking here?


<5MB file = stupid amount of data, excel is not happy with me
In the file I do see some fields that are

Do you do this in terminal?
seems a lot of work to go from bin to hex to excel and format data and then perhaps back again

Felix

#13
October 25, 2017, 10:40:25 AM
The edit is not implemented, but posting to an existing timestamp will update it.
If the time moves to the past, then the inserts will fail, unless they match a past datapoint timestamp. That is bad but it's not critical. Normally your clock should not change willy nilly, especially set backwards in time. Forwards in time is no problem, logutil will append a new datapoint.

The export feature is for viewing, not for editing. It's one way basically. useful if you want to manipulate the data in a different way than the default graph in the app.

The app is free. I fix bugs, if you can reproduce the bug. I cannot fix bugs that don't exist or cannot be reproduced or happen random and cannot be pointed to a code location.
All you have at this point is a file with some bad data, a log file which is completely inconsistent with what I would expect. That is not helpful for me to work on it, I don't know where to begin.

LukaQ

#14
October 25, 2017, 12:33:07 PM
Don't get me wrong, help as much as you can, I don't think you are obligated to so do.
QuoteI fix bugs, if you can reproduce the bug.
Don't know if that is a bug or how you would call it, but here is something you can work with:



This are last 3 lines of .bin. And as you can see, last line was not written with 9 bytes. This is the reason it did not work. I removed last line, replaced it on server and now it is logging from this time forward, and there is no data in between old and new point, so they are just connected together like they should be.

maybe you can implement something to check if last point is 9 bytes long and is not null or something like that, if possible
Print
Go Up Pages1 2 All
User actions