Logging frequency

Help
,
1

Environment

CentOS 6.5 VM
netdata kickstart-offline

Problem/Question

I have set up netdata on a test VM to monitor the output of a command that I am interested in. I am not interested in other charts/metrics so I disabled ALL the plugins/charts I saw in netdata.conf except from charts.d. In my charts.d.conf I enabled my own script (mytest.chart.sh) for the charts.d collector in usr/libexec/netdata/charts.d/. As it is not a fast changing thing I set mytest_update_every=1800 as once every half an hour is more than enough for this use case. I lefte the update_every = 1 entry in the global section of the netdata.conf file to the default 1 and let it do its thing overnight.

This morning I saw that the values haven’t been updated and I see these messages in the logs:

2020-12-07 20:00:00: netdata INFO  : PLUGINSD[charts.d] : mytest.total: too old data (last updated at 1607362200.0, last collected at 1607364000.48231). Resetting it. Will not store the next entry.
2020-12-07 21:00:00: netdata INFO  : PLUGINSD[charts.d] : RRD database for chart 'mytest.total' on host 'VM-02-testakis' is 1799.54004 secs in the past (counter #0, update #2). Adjusting it to current time.
2020-12-07 21:00:00: netdata INFO  : PLUGINSD[charts.d] : mytest.total: too old data (last updated at 1607365800.0, last collected at 1607367600.40036). Resetting it. Will not store the next entry.
2020-12-07 22:00:00: netdata INFO  : PLUGINSD[charts.d] : RRD database for chart 'mytest.total' on host 'VM-02-testakis' is 1799.58734 secs in the past (counter #0, update #2). Adjusting it to current time.
2020-12-07 22:00:00: netdata INFO  : PLUGINSD[charts.d] : mytest.total: too old data (last updated at 1607369400.0, last collected at 1607371200.87341). Resetting it. Will not store the next entry.
2020-12-07 22:35:55: netdata INFO  : WEB_SERVER[static1] : Data collection interval change detected in query: 1 -> 1800
2020-12-07 22:36:06: netdata INFO  : WEB_SERVER[static1] : Data collection interval change detected in query: 1 -> 1800
2020-12-07 22:36:06: netdata INFO  : WEB_SERVER[static1] : Data collection interval change detected in query: 1 -> 1800
2020-12-07 22:36:07: netdata INFO  : WEB_SERVER[static1] : Data collection interval change detected in query: 1 -> 1800
2020-12-07 22:36:07: netdata INFO  : WEB_SERVER[static1] : Data collection interval change detected in query: 1 -> 1800
2020-12-07 22:36:07: netdata INFO  : WEB_SERVER[static1] : Data collection interval change detected in query: 1 -> 1800
2020-12-07 22:36:08: netdata INFO  : WEB_SERVER[static1] : Data collection interval change detected in query: 1 -> 1800
2020-12-07 22:36:08: netdata INFO  : WEB_SERVER[static1] : Data collection interval change detected in query: 1 -> 1800
2020-12-07 22:36:14: netdata INFO  : WEB_SERVER[static1] : Data collection interval change detected in query: 1 -> 1800
2020-12-07 22:37:33: netdata INFO  : WEB_SERVER[static1] : POLLFD: LISTENER: client slot 5 (fd 38) from 10.20.12.100 port 54728 is idle for more than 60 seconds - closing it.
2020-12-07 23:00:00: netdata INFO  : PLUGINSD[charts.d] : RRD database for chart 'mytest.total' on host 'VM-02-testakis' is 1799.55983 secs in the past (counter #0, update #2). Adjusting it to current time.
2020-12-07 23:00:00: netdata INFO  : PLUGINSD[charts.d] : mytest.total: too old data (last updated at 1607373000.0, last collected at 1607374800.59830). Resetting it. Will not store the next entry.
2020-12-07 23:30:00: netdata ERROR : PLUGINSD[charts.d] : read failed: end of file (errno 9, Bad file descriptor)
2020-12-07 23:30:00: netdata INFO  : PLUGINSD[charts.d] : PARSER ended
2020-12-07 23:30:00: netdata ERROR : PLUGINSD[charts.d] : '/opt/netdata/usr/libexec/netdata/plugins.d/charts.d.plugin' (pid 4436) disconnected after 16 successful data collections (ENDs).
2020-12-07 23:30:01: netdata INFO  : PLUGINSD[charts.d] : connected to '/opt/netdata/usr/libexec/netdata/plugins.d/charts.d.plugin' running on pid 39528
2020-12-07 23:30:01: charts.d: INFO: main: started from '/opt/netdata/usr/libexec/netdata/plugins.d/charts.d.plugin' with options: 1
2020-12-07 23:30:01: charts.d: INFO: main: Configuration file '/opt/netdata/usr/lib/netdata/conf.d/charts.d.conf' loaded.
2020-12-07 23:30:01: charts.d: INFO: main: Configuration file '/opt/netdata/etc/netdata/charts.d.conf' loaded.
2020-12-07 23:30:01: charts.d: INFO: ap: is disabled. Add a line with ap=yes in '/opt/netdata/etc/netdata/charts.d.conf' to enable it (or remove the line that disables it).
2020-12-07 23:30:01: charts.d: INFO: apcupsd: is disabled. Add a line with apcupsd=yes in '/opt/netdata/etc/netdata/charts.d.conf' to enable it (or remove the line that disables it).
2020-12-07 23:30:01: charts.d: INFO: example: is disabled. Add a line with example=force in '/opt/netdata/etc/netdata/charts.d.conf' to enable it (or remove the line that disables it).
2020-12-07 23:30:01: charts.d: INFO: example2: is disabled. Add a line with example2=yes in '/opt/netdata/etc/netdata/charts.d.conf' to enable it (or remove the line that disables it).
2020-12-07 23:30:01: charts.d: INFO: libreswan: is disabled. Add a line with libreswan=yes in '/opt/netdata/etc/netdata/charts.d.conf' to enable it (or remove the line that disables it).
2020-12-07 23:30:01: charts.d: INFO: nut: is disabled. Add a line with nut=yes in '/opt/netdata/etc/netdata/charts.d.conf' to enable it (or remove the line that disables it).
2020-12-07 23:30:01: charts.d: INFO: opensips: is disabled. Add a line with opensips=yes in '/opt/netdata/etc/netdata/charts.d.conf' to enable it (or remove the line that disables it).
2020-12-07 23:30:01: charts.d: INFO: sensors: is disabled. Add a line with sensors=force in '/opt/netdata/etc/netdata/charts.d.conf' to enable it (or remove the line that disables it).
2020-12-07 23:30:01: netdata INFO  : PLUGINSD[charts.d] : RRDSET: chart name 'mytest.total' on host 'VM-02-testakis' already exists.
2020-12-07 23:30:01: netdata INFO  : PLUGINSD[charts.d] : RRDSET: chart name 'netdata.plugin_chartsd_mytest' on host 'VM-02-testakis' already exists.
2020-12-08 00:17:32: netdata INFO  : WEB_SERVER[static1] : Data collection interval change detected in query: 1 -> 1800
2020-12-08 00:17:32: netdata INFO  : WEB_SERVER[static1] : Data collection interval change detected in query: 1 -> 1800
2020-12-08 00:17:32: netdata INFO  : WEB_SERVER[static1] : Data collection interval change detected in query: 1 -> 1800
2020-12-08 00:17:32: netdata INFO  : WEB_SERVER[static1] : Data collection interval change detected in query: 1 -> 1800
2020-12-08 00:17:34: netdata INFO  : WEB_SERVER[static1] : Data collection interval change detected in query: 1 -> 1800
2020-12-08 00:30:00: netdata INFO  : PLUGINSD[charts.d] : RRD database for chart 'mytest.total' on host 'VM-02-testakis' is 1799.55709 secs in the past (counter #0, update #2). Adjusting it to current time.
2020-12-08 00:30:00: netdata INFO  : PLUGINSD[charts.d] : mytest.total: too old data (last updated at 1607378400.0, last collected at 1607380200.57092). Resetting it. Will not store the next entry.
2020-12-08 01:30:00: netdata INFO  : PLUGINSD[charts.d] : RRD database for chart 'mytest.total' on host 'VM-02-testakis' is 1799.57158 secs in the past (counter #0, update #2). Adjusting it to current time.
2020-12-08 01:30:00: netdata INFO  : PLUGINSD[charts.d] : mytest.total: too old data (last updated at 1607382000.0, last collected at 1607383800.71581). Resetting it. Will not store the next entry.
2020-12-08 02:02:01: netdata ERROR : ACLK_Stats : heartbeat missed 997086 monotonic microseconds
2020-12-08 02:02:01: netdata ERROR : STATSD : heartbeat missed 997086 monotonic microseconds
2020-12-08 02:30:00: netdata INFO  : PLUGINSD[charts.d] : RRD database for chart 'mytest.total' on host 'VM-02-testakis' is 1799.65022 secs in the past (counter #0, update #2). Adjusting it to current time.
2020-12-08 02:30:00: netdata INFO  : PLUGINSD[charts.d] : mytest.total: too old data (last updated at 1607385600.0, last collected at 1607387400.150223). Resetting it. Will not store the next entry.
2020-12-08 03:30:00: netdata INFO  : PLUGINSD[charts.d] : RRD database for chart 'mytest.total' on host 'VM-02-testakis' is 1799.54029 secs in the past (counter #0, update #2). Adjusting it to current time.
2020-12-08 03:30:00: netdata INFO  : PLUGINSD[charts.d] : mytest.total: too old data (last updated at 1607389200.0, last collected at 1607391000.40287). Resetting it. Will not store the next entry.
2020-12-08 03:33:20: netdata ERROR : PLUGINSD[charts.d] : read failed: end of file (errno 9, Bad file descriptor)
2020-12-08 03:33:20: netdata INFO  : PLUGINSD[charts.d] : PARSER ended
2020-12-08 03:33:20: netdata ERROR : PLUGINSD[charts.d] : '/opt/netdata/usr/libexec/netdata/plugins.d/charts.d.plugin' (pid 39528) disconnected after 16 successful data collections (ENDs).
2020-12-08 03:33:21: netdata INFO  : PLUGINSD[charts.d] : connected to '/opt/netdata/usr/libexec/netdata/plugins.d/charts.d.plugin' running on pid 10583
2020-12-08 03:33:21: charts.d: INFO: main: started from '/opt/netdata/usr/libexec/netdata/plugins.d/charts.d.plugin' with options: 1
2020-12-08 03:33:21: charts.d: INFO: main: Configuration file '/opt/netdata/usr/lib/netdata/conf.d/charts.d.conf' loaded.
2020-12-08 03:33:21: charts.d: INFO: main: Configuration file '/opt/netdata/etc/netdata/charts.d.conf' loaded.
2020-12-08 03:33:21: charts.d: INFO: ap: is disabled. Add a line with ap=yes in '/opt/netdata/etc/netdata/charts.d.conf' to enable it (or remove the line that disables it).
2020-12-08 03:33:21: charts.d: INFO: apcupsd: is disabled. Add a line with apcupsd=yes in '/opt/netdata/etc/netdata/charts.d.conf' to enable it (or remove the line that disables it).
2020-12-08 03:33:21: charts.d: INFO: example: is disabled. Add a line with example=force in '/opt/netdata/etc/netdata/charts.d.conf' to enable it (or remove the line that disables it).
2020-12-08 03:33:21: charts.d: INFO: example2: is disabled. Add a line with example2=yes in '/opt/netdata/etc/netdata/charts.d.conf' to enable it (or remove the line that disables it).
2020-12-08 03:33:21: charts.d: INFO: libreswan: is disabled. Add a line with libreswan=yes in '/opt/netdata/etc/netdata/charts.d.conf' to enable it (or remove the line that disables it).
2020-12-08 03:33:21: charts.d: INFO: nut: is disabled. Add a line with nut=yes in '/opt/netdata/etc/netdata/charts.d.conf' to enable it (or remove the line that disables it).
2020-12-08 03:33:21: charts.d: INFO: opensips: is disabled. Add a line with opensips=yes in '/opt/netdata/etc/netdata/charts.d.conf' to enable it (or remove the line that disables it).
2020-12-08 03:33:21: charts.d: INFO: sensors: is disabled. Add a line with sensors=force in '/opt/netdata/etc/netdata/charts.d.conf' to enable it (or remove the line that disables it).
2020-12-08 03:33:21: netdata INFO  : PLUGINSD[charts.d] : RRDSET: chart name 'mytest.total' on host 'VM-02-testakis' already exists.
2020-12-08 03:33:21: netdata INFO  : PLUGINSD[charts.d] : RRDSET: chart name 'netdata.plugin_chartsd_mytest' on host 'VM-02-testakis' already exists.
2020-12-08 04:30:00: netdata INFO  : PLUGINSD[charts.d] : RRD database for chart 'mytest.total' on host 'VM-02-testakis' is 1799.64348 secs in the past (counter #0, update #2). Adjusting it to current time.
2020-12-08 04:30:00: netdata INFO  : PLUGINSD[charts.d] : mytest.total: too old data (last updated at 1607392800.0, last collected at 1607394600.143480). Resetting it. Will not store the next entry.
2020-12-08 05:30:00: netdata INFO  : PLUGINSD[charts.d] : RRD database for chart 'mytest.total' on host 'VM-02-testakis' is 1799.56014 secs in the past (counter #0, update #2). Adjusting it to current time.
2020-12-08 05:30:00: netdata INFO  : PLUGINSD[charts.d] : mytest.total: too old data (last updated at 1607396400.0, last collected at 1607398200.60143). Resetting it. Will not store the next entry.
2020-12-08 06:30:00: netdata INFO  : PLUGINSD[charts.d] : RRD database for chart 'mytest.total' on host 'VM-02-testakis' is 1799.53981 secs in the past (counter #0, update #2). Adjusting it to current time.
2020-12-08 06:30:00: netdata INFO  : PLUGINSD[charts.d] : mytest.total: too old data (last updated at 1607400000.0, last collected at 1607401800.39810). Resetting it. Will not store the next entry.
2020-12-08 07:30:00: netdata INFO  : PLUGINSD[charts.d] : RRD database for chart 'mytest.total' on host 'VM-02-testakis' is 1799.54644 secs in the past (counter #0, update #2). Adjusting it to current time.
2020-12-08 07:30:00: netdata INFO  : PLUGINSD[charts.d] : mytest.total: too old data (last updated at 1607403600.0, last collected at 1607405400.46440). Resetting it. Will not store the next entry.
2020-12-08 07:36:40: netdata ERROR : PLUGINSD[charts.d] : read failed: end of file (errno 9, Bad file descriptor)
2020-12-08 07:36:40: netdata INFO  : PLUGINSD[charts.d] : PARSER ended
2020-12-08 07:36:40: netdata ERROR : PLUGINSD[charts.d] : '/opt/netdata/usr/libexec/netdata/plugins.d/charts.d.plugin' (pid 10583) disconnected after 16 successful data collections (ENDs).
2020-12-08 07:36:41: netdata INFO  : PLUGINSD[charts.d] : connected to '/opt/netdata/usr/libexec/netdata/plugins.d/charts.d.plugin' running on pid 45595

What I expected to happen

These logs happened every half an hour so it seems to me that it was correctly configured to run every half an hour but I do not understand why the chart’s values are not updated or the messages.

Why is it saying that the data are too old and why are they not stored/updated? Why is there this data collection interval change detection in query message every half an hour?

I also tried changing the global:update every
field to 1800 as well and then I got this error message on service startup:

020-12-08 13:26:15: netdata ERROR : MAIN : Invalid data collection frequency (update every) 1800 given. Defaulting to 3600. (errno 2, No such file or directory)

Is half an hour too long for netdata?

Would it be better if I used the go or python collectors? Which one is the most appropriate?

Thanks,
Nikos

1 Like
2

Hi @pattakosn ,

I am so sorry for responding so late. Due to christmas a lot of Netdata members were on vacation, so some things slipped through the cracks.

I was wondering if you could try a more “usual” collection frequency (e.g 5 or 60) and see if it works as expected.

To be honest, I have never seen a user using such a high collection frequency, so it would be very interesting if that is the issue!

Cheers :slight_smile:

3

Hi Odyssea and thank you for your reply anyway. It seems that big intervals cause trouble. We did not want to run our sampling command so often as we did not want to cause too much unnecessary overhead to our db. Per second granularity was too much for our needs which can be server on per hour basis.

The solution we ended up with was to run the netdata collector every second and modified our custom collector to “report” to the netdata collector cached values which are actually updated however rarely we want (ie every half an hour).

It would be interesting to do it using the go collectors but I haven’t yet tried, I may do it soon.
Thank you.

1 Like
4

Currently most of our engineers are on vacations, but I will ping them once they return. I don’t think that we have documented this apparent upper bound of collector update frequency (cc @joel, @ilyam8 ).

In the case of a custom collector, although we generally prefer Go, since it’s easier to maintain and more robust due to not requiring the python runtime, python might be the easier choice.

Whatever you decide, please do keep us posted.

Cheers :slight_smile:

5

@pattakosn hi :wave:

Is it possible to show mytest.chart.sh source code?

1 Like
6

I don’t believe we have ever documented the upper bound of the frequency. Does anyone know what that is, exactly? I think we’ve always figured users would want to keep that number at 1, or as close as their environment allows, without thinking of the opposite. It’s strange that when you put in 1800, it then defaulted to 3600.

1 Like