Having trouble getting graphs to work

oilyfingers · April 24, 2017, 8:26am

Hello all,

Openhab noob here - hoping for some help in getting graphs to work. Current setup is very minimal - a temperature sensor on an ESP8266, pinging the temperature over MQTT every 30 seconds to mosquitto running on the same machine as OpenHab (RaspberryPi2).

I have a single item and I’m attempting to display both the temperature and a graph on the sitemap. The temperature works correctly - but no matter what I try I cannot get the graph working. I’m using rrdj4 for persistence.

What I find really odd - the temperature is shown as a text item, yet the opnhab logs show an error and a ‘null’ value received. rrd4j has a file running - but it all appears to be null entries. Certainly not valid data (viewed using xxd)

Any pointers as to what might be wrong would be greatly appreciated.

Screenshot from BasicUI:

Items file:

Number  TemperatureSensor1 "Temperature ESP2 [%.1f °C]" <temperature>  {mqtt="<[broker:temp_probe_1_out:state:default]"}

Sitemap:

sitemap home label="SmartHome"
{
        Frame label="Temperature"
        {
                Text item=TemperatureSensor1
        }

        Frame label="Temperature Graph"
        {
                Chart label="temperature graph" item=TemperatureSensor1 period=h refresh=30
        }
}

Persistance file:
/ Configuration file for “rrd4j” persistence module

// persistence strategies have a name and a definition and are referred to in the "Items" section
Strategies {

// for rrd charts, we need a cron strategy
everyMinute : "0 * * * * ?"
every10Minutes: "/10 * * * * ?"
}

Items {
TemperatureSensor1 : strategy = every10Minutes, restoreOnStartup
}

rrd4j.cfg remains untouched.

Extract from openhab log:

2017-04-24 08:19:23.409 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor1'
2017-04-24 08:19:23.725 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor1'
2017-04-24 08:20:24.049 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor1'

And the same from events.log

2017-04-24 08:04:44.411 [ItemStateChangedEvent     ] - TemperatureSensor1 changed from NULL to 19.40
2017-04-24 08:05:45.008 [ItemStateChangedEvent     ] - TemperatureSensor1 changed from 19.40 to 19.50
2017-04-24 08:10:17.940 [ItemStateChangedEvent     ] - TemperatureSensor1 changed from 19.50 to 19.30
2017-04-24 08:11:18.575 [ItemStateChangedEvent     ] - TemperatureSensor1 changed from 19.30 to 19.40
2017-04-24 08:13:19.868 [ItemStateChangedEvent     ] - TemperatureSensor1 changed from 19.40 to 19.30
2017-04-24 08:14:20.534 [ItemStateChangedEvent     ] - TemperatureSensor1 changed from 19.30 to 19.40
2017-04-24 08:16:21.828 [ItemStateChangedEvent     ] - TemperatureSensor1 changed from NULL to 19.40

rrd4j appears to be loading correctly (although I’m not sure what I’m meant to see here)

2017-04-24 07:56:04.474 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'home.items'
2017-04-24 07:56:05.104 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist'
2017-04-24 07:56:14.089 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'home.sitemap'

Finally, xxd output from TemperatureSensor1.rrd4j

xxd TemperatureSensor1.rrd 
0000000: 0052 0052 0044 0034 004a 002c 0020 0076  .R.R.D.4.J.,. .v
0000010: 0065 0072 0073 0069 006f 006e 0020 0030  .e.r.s.i.o.n. .0
0000020: 002e 0031 0020 0020 0000 0000 0000 001e  ...1. . ........
0000030: 0000 0001 0000 0002 0000 0000 58fc 5359  ............X.SY
0000040: 0073 0074 0061 0074 0065 0020 0020 0020  .s.t.a.t.e. . . 
0000050: 0020 0020 0020 0020 0020 0020 0020 0020  . . . . . . . . 
0000060: 0020 0020 0020 0020 0047 0041 0055 0047  . . . . .G.A.U.G
0000070: 0045 0020 0020 0020 0020 0020 0020 0020  .E. . . . . . . 
0000080: 0020 0020 0020 0020 0020 0020 0020 0020  . . . . . . . . 
0000090: 0000 0000 0000 001e 7ff8 0000 0000 0000  ................
00000a0: 7ff8 0000 0000 0000 7ff8 0000 0000 0000  ................
00000b0: 0000 0000 0000 0000 0000 0000 0000 0011  ................
00000c0: 0041 0056 0045 0052 0041 0047 0045 0020  .A.V.E.R.A.G.E. 
00000d0: 0020 0020 0020 0020 0020 0020 0020 0020  . . . . . . . . 
00000e0: 0020 0020 0020 0020 3fe0 0000 0000 0000  . . . . ?.......
00000f0: 0000 0001 0000 016d 7ff8 0000 0000 0000  .......m........
0000100: 0000 0000 0000 0000 0000 0000 7ff8 0000  ................
0000110: 0000 0000 7ff8 0000 0000 0000 7ff8 0000  ................
0000120: 0000 0000 7ff8 0000 0000 0000 7ff8 0000  ................
0000130: 0000 0000 7ff8 0000 0000 0000 7ff8 0000  ................
0000140: 0000 0000 7ff8 0000 0000 0000 7ff8 0000  ................
0000150: 0000 0000 7ff8 0000 0000 0000 7ff8 0000  ................
0000160: 0000 0000 7ff8 0000 0000 0000 7ff8 0000  ................
0000170: 0000 0000 7ff8 0000 0000 0000 7ff8 0000  ................
0000180: 0000 0000 7ff8 0000 0000 0000 7ff8 0000  ................
0000190: 0000 0000 7ff8 0000 0000 0000 7ff8 0000  ................
00001a0: 0000 0000 7ff8 0000 0000 0000 7ff8 0000  ................
00001b0: 0000 0000 7ff8 0000 0000 0000 7ff8 0000  ................
00001c0: 0000 0000 7ff8 0000 0000 0000 7ff8 0000  ................

If anyone could point me towards what’s going on here I’d greatly appreciate it!

opus · April 24, 2017, 8:31am

The first thing that jumps into my eyes is the 10 minute strategy. Rrd4j needs a strategy of every minute.

oilyfingers · April 24, 2017, 8:32am

Well spotted - it has been on every minute actually. I tried every 10 out of desperation!

opus · April 24, 2017, 8:35am

In this case delete the rrd files to restart the database. I’m not sure if you need to restart OH for that also.
I do assume you are using the default settings for the archives of rrd4j.

oilyfingers · April 24, 2017, 8:48am

Yes, I am using rrd4j defaults.

Tried deleting TemperatureSensor1.rrd, but it is immediately recreated - in its entirety. Even tried renaming it - a new one was created almost immediately.

Just to confirm - The path to the rrd file is:

/var/lib/openhab2/persistence/rrd4j

opus · April 24, 2017, 8:51am

It is the normal behaviour of rrd4j that the file is recreated in its NEVER changing size.

oilyfingers · April 24, 2017, 8:54am

I see - good to know it’s working correctly.

Deleting the file and restarting hasn’t fixed the charting issue though.

opus · April 24, 2017, 9:08am

You can check if anything is stored correctly in the Database by using the REST Api, did you install REST Documents via PaperUI?

oilyfingers · April 24, 2017, 9:26am

I have now. How can I use this to check?

opus · April 24, 2017, 9:39am

Under persistence go to the 3d Get "persistence/Items/{Itemname}"
For Services put in rrd4j and use your item name. The time settings will default to now and now-24hours. Hit try and you will be displayed the counted entries for this timeframe ( either zero = something is wrong or some values)

oilyfingers · April 24, 2017, 9:47am

Thanks for that.

Something definitely quite wrong! The response is:

{
  "name": "TemperatureSensor1",
  "datapoints": "0",
  "data": []
}

opus · April 24, 2017, 9:51am

Ok or better not Ok.
I’m away from my system, will have closer look in the evening.
It might by the problem the openhab.log is pointing too.

Writing on a smartphone isn’t fun.

opus · April 24, 2017, 3:36pm

The only other difference to my setup is that you are using a refresh intervall of your chart of 30 MILLISECONDS! If you wanted to say 30 seconds, that would be 30000! But that doesn’t explain the zero values persistet.
Did you try it with a restart of OH?
Continue looking…
[Edit]
I suggest you set the karaf console into Debugging fpr rrd4j persistence.
Start the karaf console with:

ssh IPofYourSystem@localhost -p 8101

logging with “habopen”

and enter:

log:set DEBUG org.openhab.persistence.openhab

followed by

log:tail

That way you will see the DEBUG reports when something is/should be persisted. A normal logg looks like:

17:41:00.098 [DEBUG] [sistence.rrd4j.internal.RRD4jService] - Stored ‘E5_3’ with state ‘1.39900000000000002131628207280300557613372802734375’ in rrd4j database (again)

In order to leave the constant logging diplay hit Ctrl +C and use “logout” to leave Karaf.

oilyfingers · April 24, 2017, 8:22pm

Good morning!

Thanks for this - Well spotted with the refresh interval. Again, changing things to try and make it work - changed back now to 30000.

Yes, tried the above with an OH restart.

Turned on logging as your suggestion and I get this (note, the item has changed to TemperatureSensor2 - item file changed to match. Just trying stuff - didn’t work!):

20:02:38.975 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor2'
20:02:39.319 [INFO ] [marthome.event.ItemStateChangedEvent] - TemperatureSensor2 changed from 15.00 to 14.60
20:03:39.625 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor2'
20:03:39.947 [INFO ] [marthome.event.ItemStateChangedEvent] - TemperatureSensor2 changed from 14.60 to 14.70
20:04:40.259 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor2'
20:05:40.899 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor2'
20:06:41.567 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor2'
20:07:42.224 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor2'
20:07:42.535 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor2'
20:08:42.863 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor2'
20:09:43.511 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor2'
20:10:44.158 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor2'
20:11:44.817 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor2'
20:11:45.126 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor2'
20:12:45.447 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor2'
20:12:45.770 [INFO ] [marthome.event.ItemStateChangedEvent] - TemperatureSensor2 changed from 14.70 to 14.80
20:13:46.078 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor2'
20:14:46.720 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor2'
20:15:47.374 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor2'
20:16:48.022 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor2'
20:17:48.660 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor2'
20:18:49.309 [WARN ] [b.core.events.EventPublisherDelegate] - given new state is NULL, couldn't post update for 'TemperatureSensor2'

I also had mosquitto_sub running watching the incoming data. These are the corresponding events for this period:

mosquitto_sub -h localhost -t "temp_probe_1_out"
TemperatureProbe1
14.60
TemperatureProbe1
14.70
TemperatureProbe1
14.70
TemperatureProbe1
14.70
TemperatureProbe1
14.70
TemperatureProbe1
nan
TemperatureProbe1
14.70
TemperatureProbe1
14.70
TemperatureProbe1
14.70
TemperatureProbe1
nan
TemperatureProbe1
14.80
TemperatureProbe1
14.80
TemperatureProbe1
14.80
TemperatureProbe1
14.80
TemperatureProbe1
14.80
TemperatureProbe1
14.80

Is there something weird going on here with my MQTT data? It seems every temperature log is preceded by a ‘null’ value.

No sign of rrd4j in the logs.

opus · April 24, 2017, 8:32pm

I have no experience with mosquito!
What makes me wonder:
In your log the TemperatureSensor1 isn’t logged at all! If it is still in the system it’s value should be logged at each time step according the strategy.

I have to say Good Night from here.

oilyfingers · April 24, 2017, 8:46pm

Ah, it’s morning here!

This problem I have fixed - a bug in the code on the ESP8266 was causing it to disconnect and then reconnect on every reading. Thus announcing itself to the channel.

MQTT data into the topic now reads constant data, and the null errors have gone from the log.

Still no charts though!

(also, did restart, and deleted the rrd4j files as above)

oilyfingers · April 25, 2017, 1:33am

Solved it!

Of course I’m now kicking myself.

Went for a full reinstall and in the process of writing all the config files I wondered why the rrd4j config file was in a different folder to the rest of the openhab2 config files.

I moved the rrd4j.persist file from /var/lib/openhab2/persistance to /etc/openhab2/persistance and it started working.

I guess that’s a problem when you are following tutorials using a 1.x config!

Thanks very much for your help.

opus · April 25, 2017, 5:09am

Good news in the morning.

Btw: You can use one of the buttons below your answer in order to mark this thread as solved. That way other know no further help is needed.