Influx DB suddenly stopped logging data

poeterdebier · November 1, 2019, 1:07pm

Issue of the topic: As of 23:59 last night my Influx database is not receiving any more data (I think)*. As far as I know I did not change any configuration files regarding Influx and I am sure I did not change anything around that time because I was sleeping. I was wondering if the community could help me pin point the cause of the problem! Now I do not observe the log files of openHAB on a regular basis but is there not suppose to be some entries related to sending data from openHAB to Influx? I cannot see them.

The following things I have done so far:

Logged a part of openHAB (see attached)
Used Chronograf to acces the DB remotely. Same as with Grafana, see the data up till 23:59
Restarted openHAB

If additional info is required let me know. Thanks in advance, Piet

*Just in case this could be relevant I did play around with some DNS settings during the afternnoon. Not sure if this could be related but I thought I mention it anyway. Looking at the data Grafana is displaying up till the point it stopped makes me think its unrelated.

Platform information:
- Hardware: Raspberry Pi 3B+
- OS: Linux version 4.14.79-v7+
- Java Runtime Environment: java version “1.8.0_201”
- openHAB version: 2.4.0

14:02:15.618 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel m3meter_value to value 806.659 ㎥
14:02:15.633 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel m3meter_value_timestamp to value 2019-11-01T14:00:07.000+0100
14:02:29.995 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_equipment_identifier to value E0043007105550718
14:02:30.006 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_delivery_tariff1 to value 959.580 kWh
14:02:30.015 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_delivery_tariff2 to value 1070.823 kWh
14:02:30.027 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_production_tariff1 to value 0.000 kWh
14:02:30.039 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_production_tariff2 to value 0.000 kWh
14:02:30.049 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_tariff_indicator to value 0002
14:02:30.061 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_actual_delivery to value 0.138 kW
14:02:30.072 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_actual_production to value 0.000 kW
14:02:30.087 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_power_failures to value 7
14:02:30.101 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_long_power_failures to value 3
14:02:30.111 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_power_failure_log_timestamp0 to value 2018-03-22T20:04:19.000+0100
14:02:30.117 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_power_failure_log_timestamp0_entries to value 1
14:02:30.122 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_power_failure_log_timestamp0_entries_obisId to value 0-0:96.7.19
14:02:30.131 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_power_failure_log_timestamp0_entries_obisId_duration0 to value 1428 s
14:02:30.137 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_voltage_sags_l1 to value 7
14:02:30.144 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_voltage_swells_l1 to value 1
14:02:30.150 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_instant_voltage_l1 to value 228.2 V
14:02:30.156 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_instant_current_l1 to value 0 A
14:02:30.162 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_instant_power_delivery_l1 to value 0.137 kW
14:02:30.169 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_instant_power_production_l1 to value 0.000 kW
14:02:43.230 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_equipment_identifier to value E0043007105550718
14:02:43.246 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_delivery_tariff1 to value 959.580 kWh
14:02:43.264 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_delivery_tariff2 to value 1070.823 kWh
14:02:43.296 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_production_tariff1 to value 0.000 kWh
14:02:43.319 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_production_tariff2 to value 0.000 kWh
14:02:43.323 [INFO ] [smarthome.event.ItemStateChangedEvent] - Piektarief changed from 1070.821 kWh to 1070.823 kWh
14:02:43.336 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_tariff_indicator to value 0002
14:02:43.341 [INFO ] [smarthome.event.ItemStateChangedEvent] - dsmr_electricity_v5_0_mysmartmeter_electricityV5_emeter_delivery_tariff2 changed from 1070.821 kWh to 1070.823 kWh
14:02:43.349 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_actual_delivery to value 0.143 kW
14:02:43.368 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_actual_production to value 0.000 kW
14:02:43.376 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_power_failures to value 7
14:02:43.387 [INFO ] [smarthome.event.ItemStateChangedEvent] - Huidig_electriciteitverbruik changed from 0.140 kW to 0.143 kW
14:02:43.392 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_long_power_failures to value 3
14:02:43.398 [INFO ] [smarthome.event.ItemStateChangedEvent] - dsmr_electricity_v5_0_mysmartmeter_electricityV5_emeter_actual_delivery changed from 0.140 kW to 0.143 kW
14:02:43.404 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_power_failure_log_timestamp0 to value 2018-03-22T20:04:19.000+0100
14:02:43.415 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_power_failure_log_timestamp0_entries to value 1
14:02:43.422 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_power_failure_log_timestamp0_entries_obisId to value 0-0:96.7.19
14:02:43.429 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_power_failure_log_timestamp0_entries_obisId_duration0 to value 1428 s
14:02:43.435 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_voltage_sags_l1 to value 7
14:02:43.441 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_voltage_swells_l1 to value 1
14:02:43.447 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_instant_voltage_l1 to value 228.8 V
14:02:43.453 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_instant_current_l1 to value 0 A
14:02:43.465 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_instant_power_delivery_l1 to value 0.139 kW
14:02:43.475 [DEBUG] [smr.internal.handler.DSMRMeterHandler] - Updating state for channel emeter_instant_power_production_l1 to value 0.000 kW
14:02:43.486 [INFO ] [smarthome.event.ItemStateChangedEvent] - dsmr_electricity_v5_0_mysmartmeter_electricityV5_emeter_instant_power_delivery_l1 changed from 0.144 kW to 0.139 kW

just an image how it looks

jswim788 · November 1, 2019, 8:51pm

I don’t think so. Most of the time I see the output go to /var/log/syslog, so generally you should look there for issues. Also check to see if /var/log/influxdb exists and if anything is there.

check your /etc/influxdb/influxdb.conf file and make sure logging is enabled. See Configure InfluxDB OSS | InfluxDB OSS v1 Documentation
Make sure that log-enabled = true and suppress-write-log = false and check the other log settings.

If the influx logging is enabled, and you see nothing in these logs, then you can be pretty sure there is an issue on the openHAB side. If you do see something, perhaps that will give you a clue as to what is going wrong.

[ Edit ] one more: make sure that the influxd is still running. Did it stop for some reason?

ps -ef | grep -i influx

poeterdebier · November 2, 2019, 10:42am

Jonh thanks for the help,

I checked the influxdb.conf file (you can see part of it attached to this message). I did uncaption the log-enabled and the suppress-write-log just to see if that would make a difference. It did not work. Just to make sure: I did not change anything around these files before the logging stopped working. FOr me that is the strangest thing. Also no updates etc.

There are no files in: /var/log/influxdb
Not sure how the acces/read/check these syslog files though. Any tips how to conveniently read these files?

Maybe it is a problem regarding openHAB only I just don’t know how to verify this (and ultimately fix it).

Part of the influxDB file which says “logging” is enabled (note captions)

[meta]
  # Where the metadata/raft database is stored
  dir = "/var/lib/influxdb/meta"

  # Automatically create a default retention policy when creating a database.
  # retention-autocreate = true

  # If log messages are printed for the meta service
  # logging-enabled = true

###
### [data]
###
### Controls where the actual shard data for InfluxDB lives and how it is
### flushed from the WAL. "dir" may need to be changed to a suitable place
### for your system, but the WAL settings are an advanced configuration. The
### defaults should work for most systems.
###

Part of the influxDB.conf file where suppress-write-log is false (note captions)

  # Determines whether the HTTP write request logs should be suppressed when the log is enabled.
  # suppress-write-log = false

jswim788 · November 2, 2019, 8:48pm

are you able to tell if influxDB is running? Did you try this from the command line?

ps -ef | grep -i influx

I wonder if the influx daemon stopped for some reason?

You can view the syslog with a text editor such as nano or vim. It’s just a text file. I often use tail -F on it.

You should look to see if the syslog has anything related to influx. Try this:

grep -i influx /var/log/syslog

Hopefully you’ll see something.

poeterdebier · November 2, 2019, 10:48pm

Evening John,

I did try:

ps -ef | grep -i influx

from the command line. See the output below.

pi@pi3:~ $ ps -ef | grep -i influx
influxdb   399     1  6 14:25 ?        00:35:51 /usr/bin/influxd -config /etc/influxdb/influxdb.conf
pi       21963 21943  0 23:22 pts/2    00:00:00 grep --color=auto -i influx
pi       31924 31903  0 22:17 pts/0    00:00:02 influx

I also had a look at the syslogs. Thanks for the tip that nano could be used. The older logs with the .gz I downloaded to my computer as grep did not search through the zip files.

Here is 55 minutes of the syslog (used grep -i openhab). Assuming these “POST” entries are related to openHAB sending data to influx it looks like they stopped at 23:59:00. This is also the latest datapoint in my database which I can still see using Grafana and/or Chronograf (also proof that Influx is running).

Today I tried to get my whole setup working locally on my computer just to see if I could get it workign again from scratch (not on a rpi but rather a mac) but this also did not seem to work. I will have a look at it tomorrow again and see if I find something usefull in those logfiles. Thanks for the help anyway.

Oct 31 23:50:00 pi3 influxd[377]: [httpd] 192.168.2.4 - openhab [31/Oct/2019:23:50:00 +0100] "POST /write?consistency=one&db=openhab_db&p=%5BREDACTED%5D&precision=n&rp=autogen&u=openhab HTTP/1.1" 204 0 "-" "okhttp/2.4.0" c4d1e747-fc30-11e9-a105-b827ebea354b 11824
Oct 31 23:51:00 pi3 influxd[377]: [httpd] 192.168.2.4 - openhab [31/Oct/2019:23:51:00 +0100] "POST /write?consistency=one&db=openhab_db&p=%5BREDACTED%5D&precision=n&rp=autogen&u=openhab HTTP/1.1" 204 0 "-" "okhttp/2.4.0" e886fa3e-fc30-11e9-a106-b827ebea354b 8990
Oct 31 23:51:00 pi3 influxd[377]: [httpd] 192.168.2.4 - openhab [31/Oct/2019:23:51:00 +0100] "POST /write?consistency=one&db=openhab_db&p=%5BREDACTED%5D&precision=n&rp=autogen&u=openhab HTTP/1.1" 204 0 "-" "okhttp/2.4.0" e8958db6-fc30-11e9-a107-b827ebea354b 10139
Oct 31 23:52:00 pi3 influxd[377]: [httpd] 192.168.2.4 - openhab [31/Oct/2019:23:52:00 +0100] "POST /write?consistency=one&db=openhab_db&p=%5BREDACTED%5D&precision=n&rp=autogen&u=openhab HTTP/1.1" 204 0 "-" "okhttp/2.4.0" 0c49ab7d-fc31-11e9-a108-b827ebea354b 9688
Oct 31 23:53:00 pi3 influxd[377]: [httpd] 192.168.2.4 - openhab [31/Oct/2019:23:53:00 +0100] "POST /write?consistency=one&db=openhab_db&p=%5BREDACTED%5D&precision=n&rp=autogen&u=openhab HTTP/1.1" 204 0 "-" "okhttp/2.4.0" 300d89ff-fc31-11e9-a109-b827ebea354b 55110
Oct 31 23:54:00 pi3 influxd[377]: [httpd] 192.168.2.4 - openhab [31/Oct/2019:23:54:00 +0100] "POST /write?consistency=one&db=openhab_db&p=%5BREDACTED%5D&precision=n&rp=autogen&u=openhab HTTP/1.1" 204 0 "-" "okhttp/2.4.0" 53d0457d-fc31-11e9-a10a-b827ebea354b 10368
Oct 31 23:55:00 pi3 influxd[377]: [httpd] 192.168.2.4 - openhab [31/Oct/2019:23:55:00 +0100] "POST /write?consistency=one&db=openhab_db&p=%5BREDACTED%5D&precision=n&rp=autogen&u=openhab HTTP/1.1" 204 0 "-" "okhttp/2.4.0" 77937d60-fc31-11e9-a10b-b827ebea354b 9473
Oct 31 23:55:00 pi3 influxd[377]: [httpd] 192.168.2.4 - openhab [31/Oct/2019:23:55:00 +0100] "POST /write?consistency=one&db=openhab_db&p=%5BREDACTED%5D&precision=n&rp=autogen&u=openhab HTTP/1.1" 204 0 "-" "okhttp/2.4.0" 77a2548b-fc31-11e9-a10c-b827ebea354b 54496
Oct 31 23:56:00 pi3 influxd[377]: [httpd] 192.168.2.4 - openhab [31/Oct/2019:23:56:00 +0100] "POST /write?consistency=one&db=openhab_db&p=%5BREDACTED%5D&precision=n&rp=autogen&u=openhab HTTP/1.1" 204 0 "-" "okhttp/2.4.0" 9b56e674-fc31-11e9-a10d-b827ebea354b 23668
Oct 31 23:56:00 pi3 influxd[377]: [httpd] 192.168.2.4 - openhab [31/Oct/2019:23:56:00 +0100] "POST /write?consistency=one&db=openhab_db&p=%5BREDACTED%5D&precision=n&rp=autogen&u=openhab HTTP/1.1" 204 0 "-" "okhttp/2.4.0" 9b65c9c9-fc31-11e9-a10e-b827ebea354b 12748
Oct 31 23:57:00 pi3 influxd[377]: [httpd] 192.168.2.4 - openhab [31/Oct/2019:23:57:00 +0100] "POST /write?consistency=one&db=openhab_db&p=%5BREDACTED%5D&precision=n&rp=autogen&u=openhab HTTP/1.1" 204 0 "-" "okhttp/2.4.0" bf2a6bd0-fc31-11e9-a10f-b827ebea354b 18374
Oct 31 23:58:00 pi3 influxd[377]: [httpd] 192.168.2.4 - openhab [31/Oct/2019:23:58:00 +0100] "POST /write?consistency=one&db=openhab_db&p=%5BREDACTED%5D&precision=n&rp=autogen&u=openhab HTTP/1.1" 204 0 "-" "okhttp/2.4.0" e2dd8ef7-fc31-11e9-a110-b827ebea354b 57147
Oct 31 23:58:00 pi3 influxd[377]: [httpd] 192.168.2.4 - openhab [31/Oct/2019:23:58:00 +0100] "POST /write?consistency=one&db=openhab_db&p=%5BREDACTED%5D&precision=n&rp=autogen&u=openhab HTTP/1.1" 204 0 "-" "okhttp/2.4.0" e2ec198d-fc31-11e9-a111-b827ebea354b 9570
Oct 31 23:59:00 pi3 influxd[377]: [httpd] 192.168.2.4 - openhab [31/Oct/2019:23:59:00 +0100] "POST /write?consistency=one&db=openhab_db&p=%5BREDACTED%5D&precision=n&rp=autogen&u=openhab HTTP/1.1" 204 0 "-" "okhttp/2.4.0" 06a1bc0b-fc32-11e9-a112-b827ebea354b 8820
Nov  1 00:09:00 pi3 influxd[377]: ts=2019-10-31T23:09:00.409005Z lvl=info msg="Snapshot for path written" log_id=0IaEBlOG000 engine=tsm1 trace_id=0Iq16khl000 op_name=tsm1_cache_snapshot path=/var/lib/influxdb/data/openhab_db/autogen/312 duration=197.126ms
Nov  1 01:45:26 pi3 influxd[377]: ts=2019-11-01T00:45:26.875298Z lvl=info msg="Executing query" log_id=0IaEBlOG000 service=query query="SELECT mean(value) FROM openhab_db.autogen.Current_Valve_Opening_groteslaapkamer WHERE time >= now() - 1w GROUP BY time(20m)"
Nov  1 01:45:26 pi3 influxd[377]: ts=2019-11-01T00:45:26.876581Z lvl=info msg="Executing query" log_id=0IaEBlOG000 service=query query="SELECT moving_average(mean(value), 20) FROM openhab_db.autogen.Current_Temperature_groteslaapkamer WHERE time >= now() - 1w GROUP BY time(20m) fill(none)"
Nov  1 01:45:27 pi3 influxd[377]: ts=2019-11-01T00:45:27.010175Z lvl=info msg="Executing query" log_id=0IaEBlOG000 service=query query="SELECT mean(value) FROM openhab_db.autogen.Current_Valve_Opening_kleineslaapkamer WHERE time >= now() - 1w GROUP BY time(20m)"
Nov  1 01:45:27 pi3 influxd[377]: ts=2019-11-01T00:45:27.012453Z lvl=info msg="Executing query" log_id=0IaEBlOG000 service=query query="SELECT moving_average(mean(value), 20) FROM openhab_db.autogen.Current_Temperature_kleineslaapkamer WHERE time >= now() - 1w GROUP BY time(20m) fill(none)"
Nov  1 01:45:27 pi3 influxd[377]: ts=2019-11-01T00:45:27.065382Z lvl=info msg="Executing query" log_id=0IaEBlOG000 service=query query="SELECT mean(value) FROM openhab_db.autogen.Current_Valve_Opening_picoslaapkamer WHERE time >= now() - 1w GROUP BY time(20m)"

jswim788 · November 3, 2019, 5:39am

This is some progress in the sense that you can be pretty sure now that the problem is openHAB not writing instead of influx having some issue.

What does your persistence file look like? From your syslog something is trying to write every minute.

Very odd for this to hit out of the blue. Maybe take a closer look at the logs as you mention and something will be there to explain it.

poeterdebier · November 3, 2019, 9:08am

Goodmorning,

From your syslog something is trying to write every minute.

Yeah but is stops at 23:59:00 apparently for no reason.

Here is my persistence file:

Strategies {
    everyMinute     : "0 * * ? * *"
    everyHour       : "0 0 * ? * *"
    everyDay        : "0 0 0 * * ?"
    every5Minutes   : "0 */5 * ? * *"
}

Items {
    
    Current_Temperature_groteslaapkamer :  strategy = everyMinute
    Current_Temperature_kleineslaapkamer : strategy = everyMinute
    Current_Temperature_picoslaapkamer : strategy = everyMinute
    Current_Temperature_woonkamergroep : strategy = everyMinute

    Target_Temperature_groteslaapkamer : strategy = everyMinute 
    Target_Temperature_kleineslaapkamer : strategy = everyMinute
    Target_Temperature_picoslaapkamer : strategy = everyMinute
    Target_Temperature_woonkamergroep : strategy = everyMinute

    gvalve* : strategy = everyMinute

    Switch_State_boiler : strategy = everyMinute
 
    OWM_Outside_Temperature : strategy = everyHour 

    Huidig_electriciteitverbruik : strategy = everyMinute
    Daltarief : strategy = everyMinute
    Piektarief : strategy = everyMinute

    Huidige_gasmeterstand : strategy = every5Minutes

    Current_Humidity_woonkamer : strategy = everyMinute
}

gr Piet