#1251 closed defect (fixed)

Huge munin-graph log with cron graph_strategy

Reported by: foutrelis Owned by: nobody
Priority: normal Milestone: Munin 2.0.12
Component: master Version: 2.0.10
Severity: normal Keywords:
Cc:

Description (last modified by kenyon)

After upgrading to Munin 2.0.4 (from 1.4.7), I noticed that it now produces a huge munin-graph.log file and a bigger than necessary munin-html.log file. The issue exists in Munin 2.0.6 as well. /etc/munin/munin.conf is the default configuration file with a single host added.

More specifically:

munin-graph.log


Previously it would log about 36 lines per run; now it's sticking 1321 lines into the log file each time it runs.

For each graph it would output something like this:

2012/08/19 03:15:08 [INFO] Graphed service [host identifier]:uptime (0.11 sec)

But now:

2012/08/25 02:45:22 Request path is /host/path/uptime-year.png
2012/08/25 02:45:22 asked for (host, path, uptime, year)
2012/08/25 02:45:22 Starting munin-graph
2012/08/25 02:45:22 [INFO] Looking into drawing /usr/share/munin/www/host/path/uptime-year.png
2012/08/25 02:45:22 [INFO] Graphed service host;path:uptime (0.03 sec for 1 graphs)
2012/08/25 02:45:22 Munin-graph finished (0.03 sec)
2012/08/25 02:45:22 X-Munin-Request: 240/0
2012/08/25 02:45:22 Content-Length: 19428
2012/08/25 02:45:22 Last-Modified: Sat, 25 Aug 2012 02:45:22 GMT
2012/08/25 02:45:22 Expires: Sun, 26 Aug 2012 00:00:00 GMT

(the above repeats 3 more times; for uptime-month.png, uptime-week.png, uptime-day.png)

The amount of log information generated is about 22.5 MiB/day with 33 plugins enabled and a total of 132 generated graph images. Rotated weekly, this goes up to ~157.5 MiB. (More plugins enabled would mean even bigger log files.)

munin-html.log


This one went from storing 4 lines of text per run to about 171. The extra lines repeat the following two warnings:

[PERL WARNING] Use of uninitialized value in string eq at /usr/share/perl5/vendor_perl/Munin/Master/HTMLConfig.pm line 461.
[PERL WARNING] Use of uninitialized value in string eq at /usr/share/perl5/vendor_perl/Munin/Master/HTMLConfig.pm line 488.

Line 461 in that file is -> if ($config->{'graph_strategy'} eq "cgi") {

Line 488 in that file is -> next if ($config->{'graph_strategy'} eq "cgi");

I guess, in both cases, it doesn't appreciate having graph_strategy commented out in munin.conf.

Attachments (2)

footer_bg.jpg (118.8 KB) - added by Slavon8 at 2014-05-25T18:44:10+02:00.
http://postnasal.tumblr.com/
main-bg.gif (365 bytes) - added by Slavon8 at 2014-10-29T19:57:00+01:00.
Slavon Smartmil

Download all attachments as: .zip

Change History (13)

comment:1 Changed at 2012-09-05T10:53:07+02:00 by foutrelis

I messed up the formatting on the log excerpts. You can see them better at the downstream Arch bug report: https://bugs.archlinux.org/task/31277.

comment:2 Changed at 2012-09-05T11:26:08+02:00 by kenyon

  • Description modified (diff)

Fixing formatting.

comment:3 Changed at 2012-09-06T13:55:54+02:00 by snide

  • Resolution set to fixed
  • Status changed from new to closed

Fixed in 789c59e.

comment:4 Changed at 2012-09-06T14:49:58+02:00 by foutrelis

  • Resolution fixed deleted
  • Status changed from closed to reopened

From what I understand, 789c59e fixes the warnings printed to munin-html.log.

The primary issue, which is lots of CGI output being logged to munin-graph.log, remains unsolved.

comment:5 Changed at 2012-09-08T10:21:33+02:00 by gowness

With the new graph logging consists of each individual graph reporting similar to this:

2012/09/08 01:16:27 Request path is /ec2/munin-sentinel/vmstat-month.png
2012/09/08 01:16:27 asked for (ec2, munin-sentinel, vmstat, month)
2012/09/08 01:16:27 Starting munin-graph
2012/09/08 01:16:27 [INFO] Looking into drawing /srv/http/munin/ec2/munin-sentinel/vmstat-month.png
2012/09/08 01:16:27 [INFO] Graphed service ec2;munin-sentinel:vmstat (0.04 sec for 1 graphs)
2012/09/08 01:16:27 Munin-graph finished (0.04 sec)
2012/09/08 01:16:27 X-Munin-Request: 874/0
2012/09/08 01:16:27 Content-Length: 14899
2012/09/08 01:16:27 Last-Modified: Sat, 08 Sep 2012 08:16:27 GMT
2012/09/08 01:16:27 Expires: Sat, 08 Sep 2012 10:00:00 GMT

Not only does the log size increase vastly, but the munin_stats plugin reports incorrectly as well; Saying munin-graph takes 0.03 sec to run, as that is the last "finished" time that is in the log file.

After having this updated version running with 6 hosts totally 32 tests over 24 hours the log is already at 364MB.

comment:6 Changed at 2012-09-08T13:45:27+02:00 by snide

  • Resolution set to fixed
  • Status changed from reopened to closed

Oops, was focused on the warnings. I didn't notice that the bug was more about "Too much logs" than "warnings in logs" :)

8ad5dda should complete the fix.

comment:7 Changed at 2012-09-08T16:43:41+02:00 by foutrelis

  • Resolution fixed deleted
  • Status changed from closed to reopened

Would it be possible to also change the following in master/lib/Munin/Master/GraphOld.pm from INFO to DEBUG?

INFO "Starting munin-graph";
..
INFO "Munin-graph finished ($graph_time sec)";

It would further reduce the number of lines logged per run, in my configuration, from 396 to 132.

E.g., for the CPU graph it'd go from logging:

2012/09/08 14:15:09 Starting munin-graph
2012/09/08 14:15:10 [INFO] Graphed service [host]:cpu (0.06 sec for 1 graphs)
2012/09/08 14:15:10 Munin-graph finished (0.06 sec)
2012/09/08 14:15:10 Starting munin-graph
2012/09/08 14:15:10 [INFO] Graphed service [host]:cpu (0.04 sec for 1 graphs)
2012/09/08 14:15:10 Munin-graph finished (0.04 sec)
2012/09/08 14:15:10 Starting munin-graph
2012/09/08 14:15:10 [INFO] Graphed service [host]:cpu (0.05 sec for 1 graphs)
2012/09/08 14:15:10 Munin-graph finished (0.05 sec)
2012/09/08 14:15:10 Starting munin-graph
2012/09/08 14:15:10 [INFO] Graphed service [host]:cpu (0.04 sec for 1 graphs)
2012/09/08 14:15:10 Munin-graph finished (0.04 sec)

to logging:

2012/09/08 14:15:10 [INFO] Graphed service [host]:cpu (0.06 sec for 1 graphs)
2012/09/08 14:15:10 [INFO] Graphed service [host]:cpu (0.04 sec for 1 graphs)
2012/09/08 14:15:10 [INFO] Graphed service [host]:cpu (0.05 sec for 1 graphs)
2012/09/08 14:15:10 [INFO] Graphed service [host]:cpu (0.04 sec for 1 graphs)

Furthermore, if it's possible to call munin-graph once for each set of graphs instead of once per period (day/week/month/year), that would avoid the quadruplication of logged lines (as seen directly above). (This would bring the line count back to the same level with the 1.4.7 version I was using before.)

Thank you, and sorry for reopening this ticket again.

comment:8 Changed at 2012-12-10T19:00:43+01:00 by ilf

This is still present in 2.0.6 and very annoying. I would love to disable INFO logging completely in munin-update.log and munin-graph.log.

comment:9 Changed at 2013-03-20T08:13:15+01:00 by ckujau

Commit 8ad5dda helps (thanks!), but apparently the fix made it only into 2.0.7. The next Debian/stable for example will ship 2.0.6. So, let's file downstream bugs then :)

Edit: while the commit certainly helps, munin-graph is still logging too much as foutrelis pointed out earlier. Just for one service and one host, the following is printed:

2013/03/21 02:56:02 Starting munin-graph
2013/03/21 02:56:02 [INFO] Graphed service localdomain;localhost.localdomain:netstat (0.05 sec for 1 graphs)
2013/03/21 02:56:02 Munin-graph finished (0.05 sec)
2013/03/21 02:56:02 Starting munin-graph
2013/03/21 02:56:02 [INFO] Graphed service localdomain;localhost.localdomain:netstat (0.03 sec for 1 graphs)
2013/03/21 02:56:02 Munin-graph finished (0.03 sec)
2013/03/21 02:56:02 Starting munin-graph
2013/03/21 02:56:02 [INFO] Graphed service localdomain;localhost.localdomain:netstat (0.05 sec for 1 graphs)
2013/03/21 02:56:02 Munin-graph finished (0.05 sec)
2013/03/21 02:56:02 Starting munin-graph
2013/03/21 02:56:02 [INFO] Graphed service localdomain;localhost.localdomain:netstat (0.04 sec for 1 graphs)
2013/03/21 02:56:02 Munin-graph finished (0.04 sec)

For one munin-graph run (with 8 hosts and in total 120 services to graph), 94KB of logging output is produced. This amounts to ~26MB/day.

Munin 1.4.5 (and the same amount of hosts & services) produced 7K per run, amounting to ~2MB/day:

2012/12/01 16:45:50 Opened log file
2012/12/01 16:45:50 Starting munin-graph
2012/12/01 16:45:51 Graphed service : sensors_temp (1.26 sec * 4)
2012/12/01 16:45:51 Graphed service : processes (1.28 sec * 4)
2012/12/01 16:45:51 Graphed service : if_eth0 (1.33 sec * 4)
2012/12/01 16:45:51 Graphed service : df (1.41 sec * 4)
2012/12/01 16:45:51 Graphed service : multiping (1.80 sec * 4)
[...]
Last edited at 2013-03-21T03:23:30+01:00 by ckujau (previous) (diff)

comment:10 Changed at 2013-03-21T14:12:34+01:00 by snide

  • Milestone changed from Munin 2.0 to Munin 2.0.12
  • Resolution set to fixed
  • Status changed from reopened to closed
  • Version changed from devel to 2.0.10
Last edited at 2013-03-21T14:14:30+01:00 by snide (previous) (diff)

comment:11 Changed at 2014-03-28T12:09:12+01:00 by robertthomas

The most up to date listing of coupons for americanswan. Our editors check coupon codes to ensure validity every day.

Changed at 2014-10-29T19:57:00+01:00 by Slavon8

Note: See TracTickets for help on using tickets.