Project

General

Profile

Bug #23857

Filter out collectd log spam

Added by nood lehead about 2 years ago. Updated over 1 year ago.

Status:
Resolved
Priority:
Nice to have
Assignee:
William Grzybowski
Category:
Middleware
Target version:
Seen in:
Severity:
New
Reason for Closing:
Reason for Blocked:
Needs QA:
No
Needs Doc:
Yes
Needs Merging:
Yes
Needs Automation:
No
Support Suite Ticket:
n/a
Hardware Configuration:

Build FreeNAS-11.0-U3 (c5dcf4416)
Platform Intel(R) Xeon(R) CPU X5690 @ 3.47GHz
Memory 49105MB
12 HGST 4TB NAS drives
12 Seagate 2TB drives

ChangeLog Required:
No

Description

Hi

I keep getting following error on Freenas 11 RC, I don't know what it means but everything seems to be working.

May  8 16:42:30 freenas collectd[3411]: aggregation plugin: Unable to read the current rate of "freenas.local/cpu-1/cpu-user".  
May  8 16:42:30 freenas collectd[3411]: utils_vl_lookup: The user object callback failed with status 2.
spam.png (58.4 KB) spam.png Rishabh Chauhan, 11/07/2017 10:39 AM
12945

Related issues

Related to FreeNAS - Bug #25342: Log spamming in 11.0Closed: Duplicate2017-07-28
Related to FreeNAS - Bug #23668: Can't read CPU usage on various CPU (2017-04-28 nightly AND BEFORE)Closed: Duplicate2017-04-28
Related to FreeNAS - Bug #26318: Collectd failed with status 2Closed: Duplicate2017-10-22
Is duplicate of FreeNAS - Bug #26528: freenas aggregation plugin makes freenas lost network connection and server rebootClosed: Duplicate2017-11-07

History

#1 Updated by Anthony Takata about 2 years ago

For some reason I think the collectd daemon is too impatient?

I get them all the time now.

May  6 00:54:31 bob collectd[17853]: aggregation plugin: Unable to read the current rate of "bob/cpu-5/cpu-system".
May  6 00:54:31 bob collectd[17853]: utils_vl_lookup: The user object callback failed with status 2.
May  6 02:24:11 bob collectd[17853]: aggregation plugin: Unable to read the current rate of "bob/cpu-14/cpu-user".
May  6 02:24:11 bob collectd[17853]: utils_vl_lookup: The user object callback failed with status 2.
May  6 06:51:31 bob collectd[17853]: aggregation plugin: Unable to read the current rate of "bob/cpu-7/cpu-user".
May  6 06:51:31 bob collectd[17853]: utils_vl_lookup: The user object callback failed with status 2.
May  6 07:26:31 bob collectd[17853]: aggregation plugin: Unable to read the current rate of "bob/cpu-13/cpu-system".
May  6 07:26:31 bob collectd[17853]: utils_vl_lookup: The user object callback failed with status 2.
May  6 07:49:31 bob collectd[17853]: aggregation plugin: Unable to read the current rate of "bob/cpu-33/cpu-system".
May  6 07:49:31 bob collectd[17853]: utils_vl_lookup: The user object callback failed with status 2.
May  6 07:51:31 bob collectd[17853]: aggregation plugin: Unable to read the current rate of "bob/cpu-8/cpu-interrupt".
May  6 07:51:31 bob collectd[17853]: utils_vl_lookup: The user object callback failed with status 2.
May  6 09:05:41 bob collectd[17853]: aggregation plugin: Unable to read the current rate of "bob/cpu-27/cpu-user".
May  6 09:05:41 bob collectd[17853]: utils_vl_lookup: The user object callback failed with status 2.
May  6 10:30:41 bob collectd[17853]: aggregation plugin: Unable to read the current rate of "bob/cpu-11/cpu-nice".
May  6 10:30:41 bob collectd[17853]: utils_vl_lookup: The user object callback failed with status 2.
May  6 13:47:21 bob collectd[17853]: aggregation plugin: Unable to read the current rate of "bob/cpu-14/cpu-user".
May  6 13:47:21 bob collectd[17853]: utils_vl_lookup: The user object callback failed with status 2.

... Blah blah blah throughout the day ...

May  8 04:04:51 bob collectd[17853]: aggregation plugin: Unable to read the current rate of "bob/cpu-31/cpu-interrupt".
May  8 04:04:51 bob collectd[17853]: utils_vl_lookup: The user object callback failed with status 2.
May  8 06:27:21 bob collectd[17853]: aggregation plugin: Unable to read the current rate of "bob/cpu-13/cpu-system".
May  8 06:27:21 bob collectd[17853]: utils_vl_lookup: The user object callback failed with status 2.
May  8 07:37:41 bob collectd[17853]: aggregation plugin: Unable to read the current rate of "bob/cpu-31/cpu-system".
May  8 07:37:41 bob collectd[17853]: utils_vl_lookup: The user object callback failed with status 2.
May  8 08:45:11 bob collectd[17853]: aggregation plugin: Unable to read the current rate of "bob/cpu-32/cpu-user".
May  8 08:45:11 bob collectd[17853]: utils_vl_lookup: The user object callback failed with status 2.
May  8 09:41:51 bob collectd[17853]: aggregation plugin: Unable to read the current rate of "bob/cpu-5/cpu-interrupt".
May  8 09:41:51 bob collectd[17853]: utils_vl_lookup: The user object callback failed with status 2.
May  8 17:19:11 bob collectd[17853]: aggregation plugin: Unable to read the current rate of "bob/cpu-20/cpu-user".

#2 Updated by Jerry Harrison about 2 years ago

May 10 04:33:05 corral1 collectd[3154]: aggregation plugin: Unable to read the current rate of "corral1.local/cpu-6/cpu-user".
May 10 04:33:05 corral1 collectd[3154]: utils_vl_lookup: The user object callback failed with status 2.

I am getting the same issue. My messages are listed above.

#3 Updated by M Lovelace about 2 years ago

May 10 05:40:59 crimelabnas collectd[13416]: aggregation plugin: Unable to read the current rate of "crimelabnas.crimelab.lims/cpu-1/cpu-user".
May 10 05:40:59 crimelabnas collectd[13416]: utils_vl_lookup: The user object callback failed with status 2.

I'm getting the same log/console spam about every 45-50 min.

#4 Updated by Sean Fagan about 2 years ago

  • Assignee changed from Sean Fagan to Suraj Ravichandran

Suraj, I have a vague recollection about you and collected here...?

#6 Updated by Jeff Hallam about 2 years ago

I am also seeing the same error. Everything seems to be working ok though.

May 10 13:12:25 freenas collectd[65491]: aggregation plugin: Unable to read the 
current rate of "freenas.localdomain/cpu-3/cpu-idle".                           
May 10 13:12:25 freenas collectd[65491]: utils_vl_lookup: The user object callba
ck failed with status 2.                                                        
May 10 17:46:45 freenas collectd[65491]: aggregation plugin: Unable to read the 
current rate of "freenas.localdomain/cpu-3/cpu-nice".                           
May 10 17:46:45 freenas collectd[65491]: utils_vl_lookup: The user object callba
ck failed with status 2.  

#7 Updated by Suraj Ravichandran about 2 years ago

  • Assignee changed from Suraj Ravichandran to Anonymous
  • Priority changed from No priority to Nice to have
  • Target version set to 11.1

Hi Bartosz, Is this something that you can look into? I would not be able to get to this in time and hence am requesting you take it over.

If not, then please feel free to hand this back to me.

#8 Updated by Anonymous about 2 years ago

  • Status changed from Unscreened to Screened

#9 Updated by Jerry Harrison about 2 years ago

  • ChangeLog Entry updated (diff)

#10 Updated by Andrew McCann about 2 years ago

Just to add i get the same messages from RC2 as well.

May 19 20:35:18 freenas collectd3531: aggregation plugin: Unable to read the current rate of "freenas.local/cpu-6/cpu-user".
May 19 20:35:18 freenas collectd3531: utils_vl_lookup: The user object callback failed with status 2.
May 19 21:40:48 freenas collectd3531: aggregation plugin: Unable to read the current rate of "freenas.local/cpu-3/cpu-user".
May 19 21:40:48 freenas collectd3531: utils_vl_lookup: The user object callback failed with status 2.
May 19 21:44:38 freenas collectd3531: aggregation plugin: Unable to read the current rate of "freenas.local/cpu-8/cpu-user".
May 19 21:44:38 freenas collectd3531: utils_vl_lookup: The user object callback failed with status 2.

#11 Updated by Moksh Mridul about 2 years ago

Andrew McCann wrote:

Just to add i get the same messages from RC2 as well.

May 19 20:35:18 freenas collectd3531: aggregation plugin: Unable to read the current rate of "freenas.local/cpu-6/cpu-user".
May 19 20:35:18 freenas collectd3531: utils_vl_lookup: The user object callback failed with status 2.
May 19 21:40:48 freenas collectd3531: aggregation plugin: Unable to read the current rate of "freenas.local/cpu-3/cpu-user".
May 19 21:40:48 freenas collectd3531: utils_vl_lookup: The user object callback failed with status 2.
May 19 21:44:38 freenas collectd3531: aggregation plugin: Unable to read the current rate of "freenas.local/cpu-8/cpu-user".
May 19 21:44:38 freenas collectd3531: utils_vl_lookup: The user object callback failed with status 2.

I can confirm i'm getting the same issue on version "FreeNAS-11-MASTER-201705200424 (3402e1f)"

#12 Updated by Bartosz Prokop about 2 years ago

  • Assignee changed from Anonymous to Bartosz Prokop

#13 Updated by John Salvador about 2 years ago

  • Seen in changed from 11.0-RC to 11.0-RC2

Related to a race condition?

collectd issue #1193
https://github.com/collectd/collectd/issues/1193

FreeNAS-11.0-RC2 (a4687be8c) -- r313908+e5a713ecc24(freenas/11.0-stable) -- with collectd 5.7.1 and get the same annoying messages.

A patch to utils_cache.c apparently fixes the issue -- https://github.com/collectd/collectd/commit/1f5216c763ac43c8525d2f869b5d8c6e2ec7d55f

#14 Updated by Andrew McCann about 2 years ago

This should be a fairly easy fix, could it not make 11.0?

#15 Avatar?id=14398&size=24x24 Updated by Kris Moore about 2 years ago

  • Target version changed from 11.1 to 11.0-U1

Bartosz, is this something you can pull into master / nightlies so we can test if it works? If so, we could get it into 11.0-U1.

#16 Updated by Bartosz Prokop about 2 years ago

We're using the 5.7.1 version which is the newest collectd version (released 3 months ago).
I can create a custom FreeBSD port that fetches the code directly from github, but doing so we can introduce more bugs to the FN11. We are basically bypassing collectd release procedures, testing etc. We can encounter a lot of regressions using collectd nightly code.

#17 Avatar?id=14398&size=24x24 Updated by Kris Moore about 2 years ago

  • Target version changed from 11.0-U1 to 11.1

Good point. Yes, lets hold off on that until upstream updates their version.

#18 Updated by Hermes Group about 2 years ago

  • Target version changed from 11.1 to 11.0
  • Seen in changed from 11.0-RC2 to 11.0-RC3
  • ChangeLog Entry updated (diff)

Just updated to RC3, I'm still getting the same warning

Johnny R.

Edit: I'm sorry, did I messed up this bug tracking? Is it correct?

#19 Updated by William Grzybowski about 2 years ago

  • Target version changed from 11.0 to 11.1
  • ChangeLog Entry updated (diff)

#20 Updated by Terry Sposato about 2 years ago

I am receiving this error also in a fresh install of 11-RELEASE.
I also don't see graphs rendered on the dashboard page for the new UI, I'm guessing it is related?

#21 Updated by Devin Kusek about 2 years ago

  • Target version changed from 11.1 to N/A
  • Seen in changed from 11.0-RC3 to 11.0

Im seeing this message as well on 11-RELEASE. Is there a target date for this to be fixed?

#22 Updated by William Grzybowski about 2 years ago

  • Assignee changed from Bartosz Prokop to William Grzybowski
  • Target version changed from N/A to 11.1

11.1, the same target you removed.

#23 Updated by Devin Kusek about 2 years ago

Understood. Thank you. I dont know how i fat fingured that.

#24 Updated by William Grzybowski almost 2 years ago

  • Status changed from Screened to Ready For Release

commit:3cd62ac6011|ports should fix this

#25 Updated by Dru Lavigne almost 2 years ago

  • Related to Bug #25342: Log spamming in 11.0 added

#26 Updated by Dru Lavigne almost 2 years ago

  • Related to Bug #23668: Can't read CPU usage on various CPU (2017-04-28 nightly AND BEFORE) added

#27 Updated by Philip Cook almost 2 years ago

Still seeing this in FreeNAS-11.0-U2 (e417d8aa5)

#28 Updated by Philip Cook almost 2 years ago

  • Seen in changed from 11.0 to 11.0-U2

#29 Updated by William Grzybowski almost 2 years ago

Philip Cook wrote:

Still seeing this in FreeNAS-11.0-U2 (e417d8aa5)

As stated in the ticket, this will be fixed in 11.1

#30 Updated by Dru Lavigne almost 2 years ago

  • Subject changed from "collectd user object callback failed" log spam at least once a day to Filter out collectd log spam

#31 Updated by Patrick Rachels almost 2 years ago

  • Target version changed from 11.1 to 11.0
  • Seen in changed from 11.0-U2 to 11.0-U3
  • Hardware Configuration updated (diff)

Getting the same error repeatedly in the logs.

#32 Updated by Dru Lavigne almost 2 years ago

  • Target version changed from 11.0 to 11.1

#33 Updated by Ethan Sheneman over 1 year ago

When will 11.1 be released? I've had this issue ever since I upgraded to 11 and I have to power cycle every couple weeks when it stops responding (both web interface and ssh). Never had this issue prior to 11. I'm not sure if aggregation plugin is to be blamed for system freeze.

#34 Updated by William Grzybowski over 1 year ago

Ethan Sheneman wrote:

When will 11.1 be released? I've had this issue ever since I upgraded to 11 and I have to power cycle every couple weeks when it stops responding (both web interface and ssh). Never had this issue prior to 11. I'm not sure if aggregation plugin is to be blamed for system freeze.

Your issue is completely unrelated to this ticket.

#35 Updated by Dru Lavigne over 1 year ago

  • Target version changed from 11.1 to 11.1-BETA1

#36 Updated by Stephen Makk over 1 year ago

I continue to have this problem with 11.0-U4

#37 Updated by William Grzybowski over 1 year ago

Stephen Makk wrote:

I continue to have this problem with 11.0-U4

Yes, as stated the fix will be available in 11.1, not before. Since its not critical.

#38 Updated by Drew Pfister over 1 year ago

Stephen Makk wrote:

I continue to have this problem with 11.0-U4

Don't hold your breath on it being fixed in 11.1 though. They like to kick the can down the road on bugs they deem non critical.

#39 Updated by Dru Lavigne over 1 year ago

As stated in the associated forum post, this is already in the queue for BETA1. No kicking of the can or grumpiness required.

#40 Updated by Dru Lavigne over 1 year ago

  • Related to Bug #26318: Collectd failed with status 2 added

#41 Updated by Dru Lavigne over 1 year ago

  • Status changed from Ready For Release to Resolved

#42 Updated by Rishabh Chauhan over 1 year ago

  • File spam.png spam.png added
  • Needs QA changed from Yes to No
  • QA Status Test Passes FreeNAS added
  • QA Status deleted (Not Tested)
12945

I ssh into the machine freenasrocks and used the following command to see if it is displaying normal messages,
#cat /var/log/messages | grep 'freenasrocks kernel'
Then I searched for the most common keyword in all the reported bug comments:
#cat /var/log/messages | grep 'aggregation plugin'
#cat /var/log/messages | grep 'Unable'
#cat /var/log/messages | grep 'collectd'
I did not get any output, hence test passed(refer the screenshot)

#43 Updated by Dru Lavigne over 1 year ago

  • Is duplicate of Bug #26528: freenas aggregation plugin makes freenas lost network connection and server reboot added

Also available in: Atom PDF