Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Array indexes mix-up in curl_json plugin #2266

Closed
ghost opened this issue May 6, 2017 · 1 comment · Fixed by #2281
Closed

Array indexes mix-up in curl_json plugin #2266

ghost opened this issue May 6, 2017 · 1 comment · Fixed by #2281

Comments

@ghost
Copy link

ghost commented May 6, 2017

  • Version of collectd: 5.6.2
  • Operating system / distribution: gentoo

Bug description

I'm trying to fetch two values from a json array with curl_json
I want "datapoints/0/1" and "datapoints/0/2"
"datapoints/0/1" works normaly but "datapoints/0/2" will have the value of "datapoints/0/3"
Also, the RRD for "datapoints/0/1" seems to be used twice in one interval, i'm guessing "datapoint/0/2" is somehow added to this RRD but is rejected because too recent

remote json content

{"datapoints":[[10,11,12,13,14,15,16]]}

collectd.conf extract

LoadPlugin rrdtool
LoadPlugin curl_json
<Plugin curl_json>
    <URL "http://madx.org/collectd.json">
        Host "test"
        Instance "bug"
                  
        <Key "datapoints/0/1">
            Type "gauge" 
            Instance "eleven"
        </Key>

        <Key "datapoints/0/2">
            Type "gauge"
            Instance "twelve"
        </Key>
    </URL>
</Plugin>

syslog output

May  6 15:33:04 baldur collectd[13470]: plugin_load: plugin "syslog" successfully loaded.
May  6 15:33:04 baldur collectd[13471]: cpufreq plugin: Found 4 CPUs
May  6 15:33:04 baldur collectd[13471]: Initialization complete, entering read-loop.
May  6 15:33:04 baldur collectd[13471]: rrdtool plugin: Adjusting "RandomTimeout" to 0.000 seconds.
May  6 15:33:04 baldur collectd[13471]: nut plugin: Connection to (localhost, 3493) established.
May  6 15:33:05 baldur collectd[13471]: cu_rrd_create_file: File "test/curl_json-bug/gauge-eleven.rrd" is already being created.
May  6 15:33:05 baldur collectd[13471]: Filter subsystem: Built-in target `write': Dispatching value to all write plugins failed with status -1.
May  6 15:33:05 baldur collectd[13471]: Filter subsystem: Built-in target `write': Some write plugin is back to normal operation. `write' succeeded.
May  6 15:33:15 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077595 when last update time is 1494077595 (minimum one second step)
May  6 15:33:25 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077605 when last update time is 1494077605 (minimum one second step)
May  6 15:33:35 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077615 when last update time is 1494077615 (minimum one second step)
May  6 15:33:45 baldur collectd[13471]: uc_update: Value too old: name = test/curl_json-bug/gauge-eleven; value time = 1494077625.094; last cache update = 1494077625.094;
May  6 15:33:45 baldur collectd[13471]: Filter subsystem: Built-in target `write': Dispatching value to all write plugins failed with status -1.
May  6 15:33:54 baldur collectd[13471]: Filter subsystem: Built-in target `write': Some write plugin is back to normal operation. `write' succeeded.
May  6 15:33:55 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077635 when last update time is 1494077635 (minimum one second step)
May  6 15:34:05 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077645 when last update time is 1494077645 (minimum one second step)
May  6 15:34:15 baldur collectd[13471]: Filter subsystem: Built-in target `write': Dispatching value to all write plugins failed with status -1.
May  6 15:34:24 baldur collectd[13471]: Filter subsystem: Built-in target `write': Some write plugin is back to normal operation. `write' succeeded.
May  6 15:34:25 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077665 when last update time is 1494077665 (minimum one second step)
May  6 15:34:35 baldur collectd[13471]: uc_update: Value too old: name = test/curl_json-bug/gauge-eleven; value time = 1494077675.002; last cache update = 1494077675.002;
May  6 15:34:35 baldur collectd[13471]: Filter subsystem: Built-in target `write': Dispatching value to all write plugins failed with status -1.
May  6 15:34:44 baldur collectd[13471]: Filter subsystem: Built-in target `write': Some write plugin is back to normal operation. `write' succeeded.
May  6 15:34:45 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077685 when last update time is 1494077685 (minimum one second step)
May  6 15:34:55 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077695 when last update time is 1494077695 (minimum one second step)
May  6 15:35:05 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077705 when last update time is 1494077705 (minimum one second step)
May  6 15:35:15 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077715 when last update time is 1494077715 (minimum one second step)
May  6 15:35:25 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077725 when last update time is 1494077725 (minimum one second step)
May  6 15:35:35 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077735 when last update time is 1494077735 (minimum one second step)
May  6 15:35:45 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077745 when last update time is 1494077745 (minimum one second step)
May  6 15:35:55 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077755 when last update time is 1494077755 (minimum one second step)
May  6 15:36:05 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077765 when last update time is 1494077765 (minimum one second step)
May  6 15:36:15 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077775 when last update time is 1494077775 (minimum one second step)
May  6 15:36:25 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077785 when last update time is 1494077785 (minimum one second step)
May  6 15:36:35 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077795 when last update time is 1494077795 (minimum one second step)
May  6 15:36:45 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077805 when last update time is 1494077805 (minimum one second step)
May  6 15:36:55 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077815 when last update time is 1494077815 (minimum one second step)
May  6 15:37:05 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077825 when last update time is 1494077825 (minimum one second step)
May  6 15:37:15 baldur collectd[13471]: uc_update: Value too old: name = test/curl_json-bug/gauge-eleven; value time = 1494077835.141; last cache update = 1494077835.141;
May  6 15:37:15 baldur collectd[13471]: Filter subsystem: Built-in target `write': Dispatching value to all write plugins failed with status -1.
May  6 15:37:24 baldur collectd[13471]: Filter subsystem: Built-in target `write': Some write plugin is back to normal operation. `write' succeeded.
May  6 15:37:25 baldur collectd[13471]: uc_update: Value too old: name = test/curl_json-bug/gauge-eleven; value time = 1494077845.046; last cache update = 1494077845.046;
May  6 15:37:25 baldur collectd[13471]: Filter subsystem: Built-in target `write': Dispatching value to all write plugins failed with status -1.
May  6 15:37:34 baldur collectd[13471]: Filter subsystem: Built-in target `write': Some write plugin is back to normal operation. `write' succeeded.
May  6 15:37:35 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077855 when last update time is 1494077855 (minimum one second step)
May  6 15:37:45 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077865 when last update time is 1494077865 (minimum one second step)
May  6 15:37:55 baldur collectd[13471]: uc_update: Value too old: name = test/curl_json-bug/gauge-eleven; value time = 1494077875.124; last cache update = 1494077875.124;
May  6 15:37:55 baldur collectd[13471]: Filter subsystem: Built-in target `write': Dispatching value to all write plugins failed with status -1.
May  6 15:38:04 baldur collectd[13471]: Filter subsystem: Built-in target `write': Some write plugin is back to normal operation. `write' succeeded.
May  6 15:38:05 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077885 when last update time is 1494077885 (minimum one second step)
May  6 15:38:15 baldur collectd[13471]: rrdtool plugin: rrd_update_r (test/curl_json-bug/gauge-eleven.rrd) failed: test/curl_json-bug/gauge-eleven.rrd: illegal attempt to update using time 1494077895 when last update time is 1494077895 (minimum one second step)

Wrong values in the RRDs

gauge-eleven.rrd should contain 11
gauge-twelve.rrd should contain 12

$ rrdinfo test/curl_json-bug/gauge-eleven.rrd | grep last_ds
ds[value].last_ds = "11"
$ rrdinfo test/curl_json-bug/gauge-twelve.rrd | grep last_ds
ds[value].last_ds = "13"
@octo octo self-assigned this May 15, 2017
@octo
Copy link
Member

octo commented May 15, 2017

Thank you @madchrist for reporting this issue and providing a test case. I was able to reproduce the problem with that. I think I know what the issue is: the array index is not initialized correctly, resulting in an off by one error. Unfortunately the code is a mess and desperately needs some refactoring. The main challenge is going to be not to break some other corner case.

The best way forward may be to implement some unit tests for the parser first and fix this in a second step.

octo added a commit to octo/collectd that referenced this issue May 16, 2017
octo added a commit to octo/collectd that referenced this issue May 16, 2017
octo added a commit to octo/collectd that referenced this issue May 16, 2017
octo added a commit to octo/collectd that referenced this issue May 16, 2017
Previously, the "key" was loaded by calling cj_cb_map_key() from
cj_cb_inc_array_index(). That means that the key for the previous element
was loaded as the array index was updated for the next element, resulting
in an off-by-one error. Also the key was not unset in time, resulting in
two metrics with the same identifier being created.

This patch fixes this with the following changes:

*   cj_advance_array() (nee cj_cb_inc_array_index()) now loads the key for
    the new index position instead of the previous one.
*   The initial "0" key is loaded from cj_cb_start_array().
*   cj_advance_array() always updates the key. The "update_key" argument
    has been removed.
*   Refactoring: key loading has been moved out of cj_cb_map_key() and
    into its own function, cj_load_key().
*   The unit tests have been expanded to cover this case.

Fixes: collectd#2266
octo added a commit to octo/collectd that referenced this issue May 16, 2017
This adds various tests involving arrays.

Issue: collectd#2266
octo added a commit to octo/collectd that referenced this issue May 16, 2017
Previously, the "key" was loaded by calling cj_cb_map_key() from
cj_cb_inc_array_index(). That means that the key for the previous element
was loaded as the array index was updated for the next element, resulting
in an off-by-one error. Also the key was not unset in time, resulting in
two metrics with the same identifier being created.

This patch fixes this with the following changes:

*   cj_advance_array() (nee cj_cb_inc_array_index()) now loads the key for
    the new index position instead of the previous one.
*   The initial "0" key is loaded from cj_cb_start_array().
*   cj_advance_array() always updates the key. The "update_key" argument
    has been removed.
*   Refactoring: key loading has been moved out of cj_cb_map_key() and
    into its own function, cj_load_key().

Unit tests are in a separate commit for easier cherry-picking.

Fixes: collectd#2266
octo added a commit to octo/collectd that referenced this issue May 16, 2017
Previously, the "key" was loaded by calling cj_cb_map_key() from
cj_cb_inc_array_index(). That means that the key for the previous element
was loaded as the array index was updated for the next element, resulting
in an off-by-one error. Also the key was not unset in time, resulting in
two metrics with the same identifier being created.

This patch fixes this with the following changes:

*   cj_advance_array() (nee cj_cb_inc_array_index()) now loads the key for
    the new index position instead of the previous one.
*   The initial "0" key is loaded from cj_cb_start_array().
*   cj_advance_array() always updates the key. The "update_key" argument
    has been removed.
*   Refactoring: key loading has been moved out of cj_cb_map_key() and
    into its own function, cj_load_key().

Unit tests are in a separate commit for easier cherry-picking.

Fixes: collectd#2266
octo added a commit to octo/collectd that referenced this issue May 16, 2017
This adds various tests involving arrays.

Issue: collectd#2266
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.

1 participant