Bug 911766

(In reply to comment #0)
> The mrtg package got its cron script turned into a systemd service in F18.
> Now, every time it fires to generate new graph data, it logs this..
> 
> Feb 15 16:44:35 firewall systemd[1]: Starting Multi-router Traffic Grapher...
> Feb 15 16:44:35 firewall systemd[1]: Started Multi-router Traffic Grapher.
> Feb 15 16:49:35 firewall systemd[1]: Starting Multi-router Traffic Grapher...
> Feb 15 16:49:35 firewall systemd[1]: Started Multi-router Traffic Grapher.
> Feb 15 16:54:35 firewall systemd[1]: Starting Multi-router Traffic Grapher...
> Feb 15 16:54:35 firewall systemd[1]: Started Multi-router Traffic Grapher.
> Feb 15 16:59:35 firewall systemd[1]: Starting Multi-router Traffic Grapher...
> Feb 15 16:59:35 firewall systemd[1]: Started Multi-router Traffic Grapher.
> 
> Which isn't particularly useful, especially on a system with a small disk.

The journal only stores a reference to the string, so the disk usage is not that high. I agree, that this might be a problem, especially when browsing the journal.

> ISTR a similar problem used to happen with cron, but it was possible to
> silence that.
> 
> If there's a setting in systemd that the mrtg job should be using, please
> reassign.

Hmm, how did you silence cron for cases like this?

I am a bit unsure how we should handle this best. On first thought it sounds like a strange feature to disable these log messages when a unit file says so...

This seem expected behaviour to me since the unit is being started every 5 minutes.

mrtg.crond.in
*/5 * * * * root LANG=C LC_ALL=C @bindir@/mrtg @sysconfdir@/mrtg/mrtg.cfg --lock-file @localstatedir@/lock/mrtg/mrtg_l --confcache-file @localstatedir@/lib/mrtg/mrtg.ok

Junk removed the unit look like this.

[Unit]
Description=Multi-router Traffic Grapher

[Service]
ExecStart=/usr/bin/mrtg /etc/mrtg/mrtg.cfg --lock-file /var/lock/mrtg/mrtg_l --confcache-file /var/lib/mrtg/mrtg.ok

[Install]
WantedBy=multi-user.target

With the mrtg.timer 

mrtg.timer

[Unit]
Description=periodic invocation of MRTG

[Timer]
OnBootSec=1m
OnUnitActiveSec=5m

[Install]
WantedBy=multi-user.target

If you want to silence this then you would have to silence the starting message. 

And we really should not have to require 2 units ( which is half of his message as in one starting the timer one starting the service) to use timer units as in we ought to be able to just have a mrtg.timer unit that looks like this. which in turn would reduce the startup noise by half...

[Unit]
Description=Multi-router Traffic Grapher

[Timer]
OnBootSec=1m
OnUnitActiveSec=5m
ExecStart=/usr/bin/mrtg /etc/mrtg/mrtg.cfg --lock-file /var/lock/mrtg/mrtg_l --confcache-file /var/lib/mrtg/mrtg.ok


[Install]
WantedBy=multi-user.target

And we probably should be tying this to a specific timer.target as we briefly touch upon in BRNO ( which in turn would be enable in the multi-user.target )

This does not solve the problem with the extensive logging, but maybe
your actual problem. :)

Mrtg can (and people think it should) run in daemon mode. There is
even stuff prepared in the service file:
  http://pkgs.fedoraproject.org/cgit/mrtg.git/tree/mrtg.service

If that works for you, maybe that should be the default in the Fedora
package instead of the cron mode?

In this case converting to a daemon will work, but we should find a better solution.

I think that systemd should not log every start/stop for repetitive tasks, for frequency < 1/day, unless SYSTEMD_LOG_LEVEL=debug is used. Let's just say something like
  mrtg.timer will fire once every 5min 0s from now on.
and somehow mark the start/stop jobs not to be logged.

E.g. my logs are full of: 
Mar 23 21:01:01 spora run-parts(/etc/cron.hourly)[15813]: starting 0anacron
Mar 23 21:01:01 spora run-parts(/etc/cron.hourly)[15819]: finished 0anacron
Mar 23 21:01:01 spora run-parts(/etc/cron.hourly)[15821]: starting mcelog.cron
Mar 23 21:01:01 spora run-parts(/etc/cron.hourly)[15825]: finished mcelog.cron
which is totally useless. When they are converted to .timer units, I'd prefer
not to have this noise.

Well, so cron currently generates messages similar to this, and I am pretty sure we should continue to do that. If we want to filter them, this might be something to do on display, rather then on generation...

*** Bug 984565 has been marked as a duplicate of this bug. ***

crond logging has its place away from /var/log/messages.

The system needs to be quiet by default and only log stuff in appropriate locations when something goes wrong.
I.e.: not TWO lines in the wrong place when stuff succeeds.

Why move away from cron? Did init use to run cron jobs? So why should systemd?
Cron logged one line per item in a specific log file. Not in /var/log/messages.
`Because we can` is the wrong answer.

This is thus not an improvement but a nuisance instead.

Now pleas explain what steps we can take to make /var/log/messages quiet again as it was?

I guess the direction is clear: log only when necessary (depending on circumstances and loglevel).
What can we do to help fix this bug?

(In reply to udo from comment #10)
> I guess the direction is clear: log only when necessary (depending on
> circumstances and loglevel).
Yeah, I'd agree that this could be useful. Maybe write a patch which does that. It would be much easier to have a discussion if we have something concrete to discuss.

The message is coming from unit_start in src/core/unit.c, and it this function has access to the unit object... It should be possible to do some test there.

(BTW, logging a pair of messages every five minutes, with identical content should consume about ~1000 bytes * 2 * 12 * 24 * 30 = 20MB /month, which is annoying but not critical.)

It is not about diskspace.
It is about readability and accessability of logging.
Nothing beats /var/log/messages and other separate logs under /var/log as they were a few years ago. (do not forget ~/.xsession-errors !)
Easy access with less. more, cat, grep etc.
No extra tooling needed to access different format logs.
That stuff was quickly accessed with simple tools, no filtering needed. nOt looking for the tree in the woods but looking for the branch in the tree.
It appears that THAT focus is still not in place.
And thus we downgrade the severity for a bug in the previous version of Fedora.

The downgrade of the Severity by Zbigniew was absolutely right.
"urgent" is defined in Bugzilla's Field Descriptions as:
  catastrophic issues which severely impact the mission-critical operations
  of an organization. This may mean that the operational servers, development
  systems or customer applications are down or not functioning and
  no procedural workaround exists.
I assert that the problem discussed in this BZ is not a catastrophe.
Also a workaround exists: rsyslog has a powerful configuration language that allows one to filter messages.

Sure, but design flaws like these get not acted on in the manner they should (simple problem, quick fix, right?) and the responses (see comment #11) are very unexpected to say the least.
People do not appear to understand how a unix system should look like, how it should behave and especially what NOT it should do.
Please give me links with stuff to read about this very specific design thing while I wait for an acceptable fix. I might start to understand unreasonable stuff that is implemented for seemingly (!) no real reason.
Of course this will be put away as a rant but this issue has parallels with the gnome desktop 'cut' icon color feature (bug) that took years because other stuff was so much more important. (basic, core feature!)

(In reply to udo from comment #14)
> Sure, but design flaws like these get not acted on in the manner they should
> (simple problem, quick fix, right?)

Almost every problem has a simple, straightforward, incorrect solution.
This bug for instance can be quickly solved by downgrading these messages to debug level. However, if we do that, someone else quickly files a bug complaining about the loss of these mission-critical (to them) log messages.

Thus we only have global log levels and not per service. Nice.
What did syslog do back in the day?
Of course we were forced onto a different syslog, found new log sources like systemd, etc and now we are experiencing a problem to put it nicely.
It is a very basic issue.
So why do we encounter it now? 
I am a user, using non-beta software.
Please fix. Please do not leave stuff over a new release of a distro.
That is not fair as a distro is a fake reason to kill bugs that are not acted upon.

Please stop setting needinfo on various bugs to their owners.

Any updates?
Any progress?
Any things we can do to help this bug along towards fixing?
If needinfo is not wanted, we'll see now how this works.

This message is a reminder that Fedora 18 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 18. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '18'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 18's end of life.

Thank you for reporting this issue and we are sorry that we may not be 
able to fix it before Fedora 18 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior to Fedora 18's end of life.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Any updates?
Any progress?
Any things we can do to help this bug along towards fixing?
If needinfo is not wanted, we'll see now how this works.

Because:

is it really necessary to spam /var/log/messages with:

Sep  3 18:03:15 surf2 systemd[1]: Starting Multi-router Traffic Grapher...
Sep  3 18:03:15 surf2 systemd[1]: Started Multi-router Traffic Grapher.

Sep  3 18:08:15 surf2 systemd[1]: Starting Multi-router Traffic Grapher...
Sep  3 18:08:15 surf systemd[1]: Started Multi-router Traffic Grapher.

etc?

Is it so hard to log it elsewhere? Log less?
See the original crond log file please. (/var/log/cron)

Because it takes so long to fix, one might get the impression that either other stuff is way more interesting than basic software quality and usability ort that the design is in teh way of fixing these simple issues.
If no one explains, then we can only wonder.

Wow. Almost 2 years and still no solution to this simple yet annoying design flaw. Great job.

(In reply to Michal Schmidt from comment #15)
> (In reply to udo from comment #14)
> > Sure, but design flaws like these get not acted on in the manner they should
> > (simple problem, quick fix, right?)
> 
> Almost every problem has a simple, straightforward, incorrect solution.

Almost every grand design has a quick result at first but later needs tweaking.
The result is that we litter every system with nonsense loggings that used to be in tidy, fitting places.
The fact that no real workaround, let alone a solution has come makes me worry very once more about a project.

I guess the only real solution is to get rid of the `cron replacement` script and reinstate mrtg as a process run from the real cron.
I see no benefit in using systemd as cron 'replacement'.

To make stuff easier for you folks:

# pwd
/etc/cron.d
# cat mrtg
# Runs mrtg
*/5 * * * * LANG=C /usr/bin/mrtg /etc/mrtg/mrtg.cfg --lock-file /var/lock/mrtg/mrtg_l --confcache-file /var/lib/mrtg/mrtg.ok

Result is no more systemd-like logging in /var/log/messages about doing simple crond tasks.
Perhaps `rm -f /lib/systemd/system/mrtg.timer /lib/systemd/system/mrtg.service ` is needed as simply disabling a timer does not behave as expected.
Aaaah: https://bbs.archlinux.org/viewtopic.php?id=182107 another bug; who should one *create* a file somewhere if one wants to disable a service, i.e. simply not invoke something? 
In crond a simple '#' in front of the relevant crontab line is enough.

Can you please start(!) fixing the rest of the logging issues of systemd?

Small omission:
Before 'LANG=C' we need 'root'; i.e.:

*/5 * * * * root LANG=C /usr/bin/mrtg /etc/mrtg/mrtg.cfg --lock-file /var/lock/mrtg/mrtg_l --confcache-file /var/lib/mrtg/mrtg.ok

This message is a reminder that Fedora 20 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 20. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '20'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 20 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

This message is a reminder that Fedora 21 is nearing its end of life.
Approximately 4 (four) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 21. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '21'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 21 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

This bug appears to have been reported against 'rawhide' during the Fedora 24 development cycle.
Changing version to '24'.

More information and reason for this action is here:
https://fedoraproject.org/wiki/Fedora_Program_Management/HouseKeeping/Fedora24#Rawhide_Rebase

Hi Lennard Poettering,

Now I am also facing the same issue here in my system. I have few timer services which are more frequent. Logs of these services are coming continuously and taking more memory to store logs.

I have memory constraints/limitations to keep all logs. Now I am restricting this using logic like logs truncations and log files rotations after a particular size.

Example:
Here I am using a timer service to redirect logs to specific log files. 

Mar 03 21:06:17 systemd[1]: Starting Dump journal logs into respective daemon logs...
Mar 03 21:06:17 systemd[1]: Started Dump journal logs into respective daemon logs.
Mar 03 21:06:46 systemd[1]: Starting Dump journal logs into respective daemon logs...
Mar 03 21:06:46 systemd[1]: Started Dump journal logs into respective daemon logs.
Mar 03 21:07:15 systemd[1]: Starting Dump journal logs into respective daemon logs...
Mar 03 21:07:15 systemd[1]: Started Dump journal logs into respective daemon logs.
Mar 03 21:07:26 systemd[1]: Starting Dump journal logs into respective daemon logs...
Mar 03 21:07:26 systemd[1]: Started Dump journal logs into respective daemon logs.

Issues in my system:
1. Memory is getting filled with these continuous logs.
2. log file rotation logic can override the initial bootup services logs which is critical in the case of my system.

Is there any fix on this systemd limitation?. Is it possible to think of a solution here which can disable the logging for a particular target/service.

Thanks,
Vinu Palackal

In general the whole 'starting XXXX', 'started XXXX' is superfluous in a production system, especially beyond bootup.
Please change the loglevel so that we do not see this stuff.
Why does this take so long?

This message is a reminder that Fedora 24 is nearing its end of life.
Approximately 2 (two) weeks from now Fedora will stop maintaining
and issuing updates for Fedora 24. It is Fedora's policy to close all
bug reports from releases that are no longer maintained. At that time
this bug will be closed as EOL if it remains open with a Fedora  'version'
of '24'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version'
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not
able to fix it before Fedora 24 is end of life. If you would still like
to see this bug fixed and are able to reproduce it against a later version
of Fedora, you are encouraged  change the 'version' to a later Fedora
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's
lifetime, sometimes those efforts are overtaken by events. Often a
more recent Fedora release includes newer upstream software that fixes
bugs or makes them obsolete.

*** Bug 995792 has been marked as a duplicate of this bug. ***

The workaround for mrtg is a cron job.
The solution is more sane logging (wayyyy more quiet, more UNIX(tm)) and perhaps less feature creap.

Redhat employed(employs) LP.
So redhat can ask LP to enable a more sane default loglevel in systemd.
Redhat can set a more sane loglevel as a kernel commandline parameter with it's kernels.
ETc.
Redhat did neither.

I'm having the same issue. Have a timer service running every minute. For my surprise the daemon.log keeps growing and growing with the same silly messages:

...
2017-08-09T09:16:46-07:00 systemd[1]: Starting Multi-router Traffic Grapher...
2017-08-09T09:17:56-07:00 systemd[1]: Started Multi-router Traffic Grapher.
2017-08-09T09:17:56-07:00 systemd[1]: Starting Multi-router Traffic Grapher...
2017-08-09T09:19:16-07:00 systemd[1]: Started Multi-router Traffic Grapher.
2017-08-09T09:19:16-07:00 systemd[1]: Starting Multi-router Traffic Grapher...
2017-08-09T09:20:36-07:00 systemd[1]: Started Multi-router Traffic Grapher.
...

This has non sense.

(In reply to Rickm from comment #34)
> I'm having the same issue. 

See coment 24 for a cron workaround. For a real solution I can only hope that this bug is acted upon with this decade.

Another workaround could be to filter things from the logs.
Not exactly tailored for this specific bug but to work as an idea:

# pwd
/etc/rsyslog.d
# cat drop-user-messages.conf 
:syslogtag,contains,"yum"       stop
:syslogtag,contains,"cupsd"       stop
:msg,contains,"[system] Activating via systemd: service name"	stop
:msg,contains,"[system] Successfully activated service"	stop
user.* -/var/log/user.log
& stop


This rsyslog config file puts all 'user' category logging in a separate log file, away from /var/log/messages.
All 'user' stuff, except for yum and cupsd that weirdly enough are also in the 'user' category.
Then we also filter out messages containing "[system] Activating via systemd: service name" and messages containing "[system] Successfully activated service".
This message example could be adapted to:

:msg,contains,"Starting Multi-router Traffic Grapher"	stop	
:msg,contains,"Started Multi-router Traffic Grapher"	stop	

or simply:

:msg,contains,"Multi-router Traffic Grapher"	stop	

This will filter both systemd-related messages.
Of course the better approach would be to stop producing these messages but this is a quicker `fix`.

FWIW here is the upstream issue in the systemd github repo: https://github.com/systemd/systemd/issues/9328 and here is a pull request to address it: https://github.com/systemd/systemd/pull/14279

Thanks but I will not hodl my breath over this:

@poettering

    I am pretty sure we should log everything that happens

Says enough about his pride.

With https://github.com/systemd/systemd/pull/19050, we can set LogLevelMax=notice to avoid the messages about starting and stopping.
I'll set it to POST since it'll be a while before this becomes available. I'll move the bug over the the package
providing the timer once it's available to actually add the override in the unit file.

Why doesn't a systemd.log_level=warning have the desired effect?
Why does this have to be implemented per systemd part?

Of course I am happy for a constructive response in a 7 year old bug, but I am wondering who is doing the architecting of this systemd thing.

FEDORA-2021-775e2373a1 has been submitted as an update to Fedora 34. https://bodhi.fedoraproject.org/updates/FEDORA-2021-775e2373a1

FEDORA-2021-775e2373a1 has been pushed to the Fedora 34 testing repository.
Soon you'll be able to install the update with the following command:
`sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2021-775e2373a1`
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2021-775e2373a1

See also https://fedoraproject.org/wiki/QA:Updates_Testing for more information on how to test updates.

FEDORA-2021-775e2373a1 has been pushed to the Fedora 34 stable repository.
If problem still persists, please make note of it in this bug report.

Please set LogLevelMax=notice in mrtg.service and any other units which start frequently and should not log
on each start/stop.
(Docs: https://www.freedesktop.org/software/systemd/man/systemd.exec.html#LogLevelMax=)

Thanks, mrtg.service is updated in Rawhide. I've successfully tested it with systemd-248.3-1.fc35,
start/stop messages are no more logged.

I've also removed deprecated StandardOutput=syslog - there was a warning because of it in log.

Cool, thanks for the quick reponse!