Bug#928476: rsyslog: fills up disk space with a single error message repeated

classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|

Bug#928476: rsyslog: fills up disk space with a single error message repeated

Mark Szentes-Wanner
Package: rsyslog
Version: 8.24.0-1
Severity: normal

Dear Michael,

I recently opened up a search query in KDE Dolphin and left the window open for a few days. Only later did I realize that rsyslog filled up the available disk space with millions of these messages:

May  5 01:24:22 concha dbus-daemon[1293]: Rejected: destination has a full message queue, 0 matched rules; type="signal", sender=":1.9" (uid=1000 pid=1362 comm="kded5 [kdeinit5]                                  ") interface="org.kde.KDirNotify" member="FilesAdded" error name="(unset)" requested_reply="0" destination="org.freedesktop.DBus" (uid=1000 pid=14887 comm="filenamesearch.so [kdeinit5] filenamesearch local:")
May  5 01:24:22 concha dbus-daemon[1293]: Rejected: destination has a full message queue, 0 matched rules; type="signal", sender=":1.9" (uid=1000 pid=1362 comm="kded5 [kdeinit5]                                  ") interface="org.kde.KDirNotify" member="FilesAdded" error name="(unset)" requested_reply="0" destination="org.freedesktop.DBus" (uid=1000 pid=14887 comm="filenamesearch.so [kdeinit5] filenamesearch local:")

I expected rsyslog to recognize repetitions of the same line and just post "the previous message repeated 10000 times". Please improve the recognition of repetitions. I attached a few sample lines for further investigations.

Thank you!

Best regards,

Mark


-- System Information:
Debian Release: 9.9
  APT prefers stable-updates
  APT policy: (500, 'stable-updates'), (500, 'stable')
Architecture: amd64 (x86_64)
Foreign Architectures: i386

Kernel: Linux 4.9.0-8-amd64 (SMP w/4 CPU cores)
Locale: LANG=de_AT.UTF-8, LC_CTYPE=de_AT.UTF-8 (charmap=UTF-8), LANGUAGE=de_AT:de (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
Init: systemd (via /run/systemd/system)

Versions of packages rsyslog depends on:
ii  init-system-helpers  1.48
ii  libc6                2.24-11+deb9u4
ii  libestr0             0.1.10-2
ii  libfastjson4         0.99.4-1
ii  liblogging-stdlog0   1.0.5-2+b2
ii  liblognorm5          2.0.1-1.1+b1
ii  libsystemd0          232-25+deb9u11
ii  libuuid1             2.29.2-1+deb9u1
ii  lsb-base             9.20161125
ii  zlib1g               1:1.2.8.dfsg-5

Versions of packages rsyslog recommends:
ii  logrotate  3.11.0-0.1

Versions of packages rsyslog suggests:
pn  rsyslog-doc                    <none>
pn  rsyslog-gnutls                 <none>
pn  rsyslog-gssapi                 <none>
pn  rsyslog-mongodb                <none>
pn  rsyslog-mysql | rsyslog-pgsql  <none>
pn  rsyslog-relp                   <none>

-- no debconf information


example.log.gz (464 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Bug#928476: rsyslog: fills up disk space with a single error message repeated

Michael Biebl-3
Am 05.05.2019 um 16:23 schrieb Mark Szentes-Wanner:

> Package: rsyslog
> Version: 8.24.0-1
> Severity: normal
>
> Dear Michael,
>
> I recently opened up a search query in KDE Dolphin and left the window open for a few days. Only later did I realize that rsyslog filled up the available disk space with millions of these messages:
>
> May  5 01:24:22 concha dbus-daemon[1293]: Rejected: destination has a full message queue, 0 matched rules; type="signal", sender=":1.9" (uid=1000 pid=1362 comm="kded5 [kdeinit5]                                  ") interface="org.kde.KDirNotify" member="FilesAdded" error name="(unset)" requested_reply="0" destination="org.freedesktop.DBus" (uid=1000 pid=14887 comm="filenamesearch.so [kdeinit5] filenamesearch local:")
> May  5 01:24:22 concha dbus-daemon[1293]: Rejected: destination has a full message queue, 0 matched rules; type="signal", sender=":1.9" (uid=1000 pid=1362 comm="kded5 [kdeinit5]                                  ") interface="org.kde.KDirNotify" member="FilesAdded" error name="(unset)" requested_reply="0" destination="org.freedesktop.DBus" (uid=1000 pid=14887 comm="filenamesearch.so [kdeinit5] filenamesearch local:")
>
> I expected rsyslog to recognize repetitions of the same line and just post "the previous message repeated 10000 times". Please improve the recognition of repetitions. I attached a few sample lines for further investigations.
You can turn that feature on, see
https://www.rsyslog.com/doc/v8-stable/configuration/action/rsconf1_repeatedmsgreduction.html

It's turned off by default since it has its own set of problems.

By default, rsyslog applies rate limiting on imuxsock
https://www.rsyslog.com/tag/systemlogratelimitinterval/

If you get more then 200 of such messages within 5 seconds, then this
rate limiting will kick in.

How many of those messages did you get within a 5 second window?


--
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?


signature.asc (836 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Bug#928476: rsyslog: fills up disk space with a single error message repeated

Mark Szentes-Wanner
In reply to this post by Mark Szentes-Wanner
Dear Michael

Am 05.05.19 um 21:06 schrieb Michael Biebl:

> Am 05.05.2019 um 21:03 schrieb Michael Biebl:
>> Am 05.05.2019 um 16:23 schrieb Mark Szentes-Wanner:
>>> Package: rsyslog
>>> Version: 8.24.0-1
>>> Severity: normal
>>>
>>> Dear Michael,
>>>
>>> I recently opened up a search query in KDE Dolphin and left the window open for a few days. Only later did I realize that rsyslog filled up the available disk space with millions of these messages:
>>>
>>> May  5 01:24:22 concha dbus-daemon[1293]: Rejected: destination has a full message queue, 0 matched rules; type="signal", sender=":1.9" (uid=1000 pid=1362 comm="kded5 [kdeinit5]                                  ") interface="org.kde.KDirNotify" member="FilesAdded" error name="(unset)" requested_reply="0" destination="org.freedesktop.DBus" (uid=1000 pid=14887 comm="filenamesearch.so [kdeinit5] filenamesearch local:")
>>> May  5 01:24:22 concha dbus-daemon[1293]: Rejected: destination has a full message queue, 0 matched rules; type="signal", sender=":1.9" (uid=1000 pid=1362 comm="kded5 [kdeinit5]                                  ") interface="org.kde.KDirNotify" member="FilesAdded" error name="(unset)" requested_reply="0" destination="org.freedesktop.DBus" (uid=1000 pid=14887 comm="filenamesearch.so [kdeinit5] filenamesearch local:")
>>>
>>> I expected rsyslog to recognize repetitions of the same line and just post "the previous message repeated 10000 times". Please improve the recognition of repetitions. I attached a few sample lines for further investigations.
>> You can turn that feature on, see
>> https://www.rsyslog.com/doc/v8-stable/configuration/action/rsconf1_repeatedmsgreduction.html
>>
>> It's turned off by default since it has its own set of problems.
>>
>> By default, rsyslog applies rate limiting on imuxsock
>> https://www.rsyslog.com/tag/systemlogratelimitinterval/
>>
>> If you get more then 200 of such messages within 5 seconds, then this
>> rate limiting will kick in.
>>
>> How many of those messages did you get within a 5 second window?
>>
>>
> Ok, this was apparently changed and rate limiting is turned off by default:
> https://www.rsyslog.com/doc/v8-stable/configuration/modules/imuxsock.html#syssock-ratelimit-interval
>
> Quoting the documentation:
> "Specifies the rate-limiting interval in seconds. Default value is 0,
> which turns off rate limiting. Set it to a number of seconds (5
> recommended) to activate rate-limiting. The default of 0 has been chosen
> as people experienced problems with this feature activated by default.
> Now it needs an explicit opt-in by setting this parameter."
>
> I'm following upstreams advice here and will close this bug report.
>
> You can configure rsyslog to your liking though and either turn on rate
> limiting or repeated message reduction.
>
> Regards,
> Michael

I urge you to reconsider this point. The vast majority of users is
better served by rate limiting turned on and will not pay attention to
this detail until bitten by a disastrous disk fill-up. I think the
number of users experiencing problems with rate limiting seems to be a
fraction of the Debian users with default configuration.

20 years ago, I payed attention that /var/log was on a different
partition than / or /home. After so many years with rate limiting and no
problems from logs running wild and filling up their partition, I have
not been worrying about this danger and have not been protecting systems
by putting the /var/log on a separate partition. Suddenly I discovered
that logs potentially can threaten a system again.


I can summarize the sequence how we got here:


1. Debian systems used plain old syslog with protection from repeat messages

2. Debian systems switch from plain old syslog to rsyslog still with
protection from repeat messages

3. rsyslog defaults to switch off  protection from repeat messages on
Debian systems.


I find the points of upstream quite moot. The page you directed me to
names only 4 reasons:


* Very old versions of rsyslog did not have the ability to include the
repeated message itself within the repeat message.

this is not relevant for Debian.

* Versions before 7.3.2 applied repeat message reduction to the output
side. This had some implications:
   ** they did not account for the actual message origin, so two
processes emitting an equally-looking messsage triggered the repeated
message reduction code
   ** repeat message processing could be set on a per-action basis,
which has switched to per-input basis for 7.3.2 and above

not relevant wrt the default.


* While turning this feature on can save some space in logs, most log
analysis tools need to see the repeated messages, they can’t handle the
“last message repeated” format.

this is a weakness of those analysis tools and needs to be fixed there.
The "last message repeated" format is not new and has been there for
long time. Moreover, rate limiting can be turned off.


* This is a feature that worked decades ago when logs were small and
reviewed by a human, it fails badly on high volume logs processed by tools.
The majority of users do not have high volume logs. Those who do can and
will set up their rsyslog.conf appropriately. I still review my logs
personally.


Michael please enable rate limiting by default on Debian, weighing the
interests of different user types. A professional user with high volume
logs processed by tools will tweak their configuration anyway. Some
users with less experience will not know how to recover a system with no
space left on disk.


BTW, in my case, I suddenly had over 3000 lines of log per second
resulting in over 15 GiB per day.


Thanks, regards,


Mark

Reply | Threaded
Open this post in threaded view
|

Bug#928476: rsyslog: fills up disk space with a single error message repeated

Michael Biebl-3
Am 05.05.19 um 23:01 schrieb Mark Szentes-Wanner:

[snip]

> I urge you to reconsider this point. The vast majority of users is
> better served by rate limiting turned on and will not pay attention to
> this detail until bitten by a disastrous disk fill-up. I think the

I rely on the expertise of upstream here, who has years/decades of
experience with syslog.
If you think the current defaults are bad, please consider talking to
upstream about this.
The upstream bug tracker is at https://github.com/rsyslog/rsyslog

Regards,
Michael
--
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?


signature.asc (849 bytes) Download Attachment