Project

General

Profile

Bug #23857

Filter out collectd log spam

Added by nood lehead over 1 year ago. Updated about 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 over 1 year 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 over 1 year 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 over 1 year 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 over 1 year 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 over 1 year 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 over 1 year 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 over 1 year ago

  • Status changed from Unscreened to Screened

#9 Updated by Jerry Harrison over 1 year ago

  • ChangeLog Entry updated (diff)

#10 Updated by Andrew McCann over 1 year 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 over 1 year 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 over 1 year ago

  • Assignee changed from Anonymous to Bartosz Prokop

#13 Updated by John Salvador over 1 year 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 over 1 year ago

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

#15 Avatar?id=14398&size=24x24 Updated by Kris Moore over 1 year 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 over 1 year 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 over 1 year 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 over 1 year 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 over 1 year ago

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

#20 Updated by Terry Sposato over 1 year 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 over 1 year 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 over 1 year 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 over 1 year ago

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

#24 Updated by William Grzybowski over 1 year ago

  • Status changed from Screened to Ready For Release

commit:3cd62ac6011|ports should fix this

#25 Updated by Dru Lavigne over 1 year ago

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

#26 Updated by Dru Lavigne over 1 year 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 over 1 year ago

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

#28 Updated by Philip Cook over 1 year ago

  • Seen in changed from 11.0 to 11.0-U2

#29 Updated by William Grzybowski over 1 year 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 over 1 year 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 over 1 year 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 over 1 year ago

  • Target version changed from 11.0 to 11.1

#33 Updated by Ethan Sheneman about 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 about 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 about 1 year ago

  • Target version changed from 11.1 to 11.1-BETA1

#36 Updated by Stephen Makk about 1 year ago

I continue to have this problem with 11.0-U4

#37 Updated by William Grzybowski about 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 about 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 about 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 about 1 year ago

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

#41 Updated by Dru Lavigne about 1 year ago

  • Status changed from Ready For Release to Resolved

#42 Updated by Rishabh Chauhan about 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 about 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