/var/log volume filling up due to growing logs of signedaudit

[Natxo Asenjo]

hi,

our ca master role got its /var/log disk full and after a quick analysis
the directory /var/log/pki/pki-tomcat/ca/signedAudit was the problem.

First time I come across this problem after 10 years ;-)

This directory has a lot of files called ca_audit.yyyymmddhhmmss, each 2M
large. It ended up costing 30G in total before we noticed.

So the quick fix was fast, deleting files, but what can I tweak to not have
this happen again in the future? And is this auditing crucial for some
process? Or can it be turned off somewhere?

Thanks in advance for your input.

--
regards,
natxo

[Rob Crittenden]

Natxo Asenjo via FreeIPA-users wrote:
> hi,
>
> our ca master role got its /var/log disk full and after a quick analysis
> the directory /var/log/pki/pki-tomcat/ca/signedAudit was the problem.
>
> First time I come across this problem after 10 years ;-)
>
> This directory has a lot of files called ca_audit.yyyymmddhhmmss, each
> 2M large. It ended up costing 30G in total before we noticed.
>
> So the quick fix was fast, deleting files, but what can I tweak to not
> have this happen again in the future? And is this auditing crucial for
> some process? Or can it be turned off somewhere?
>
> Thanks in advance for your input.

I checked with the CS team.

To disable completely you can use
https://github.com/dogtagpki/pki/wiki/Enabling-Signed-Audit-Logs (use
False instead of True). Restart the CA after.

A bit more configuration
https://github.com/dogtagpki/pki/wiki/Configuring-Signed-Audit-Logs

He also told me that this is disabled by default so someone must have
turned it on or for some reason their generating a ton of audit events.
Something else to look into perhaps.

Before doing anything you may want to see the last update to CS.cfg and
any backup files. The dates may be meaningful.

rob

[Sam Morris]

On 23/11/2022 16:49, Rob Crittenden via FreeIPA-users wrote:
> He also told me that this is disabled by default so someone must have
> turned it on or for some reason their generating a ton of audit events.
> Something else to look into perhaps.

FYI I've never turned these on and on my oldest IPA server I've got
signedAudit files going back a while...

# ls -tl /var/log/pki/pki-tomcat/*/signedAudit
    /var/log/pki/pki-tomcat/kra/signedAudit:
    total 29448
    -rw-r-----. 1 pkiuser pkiuser 2039803 Nov 23 17:00 kra_cert-kra_audit
    -rw-r-----. 1 pkiuser pkiuser 2048184 Nov 22 15:44 kra_cert-kra_audit.20221122154443
    -rw-r-----. 1 pkiuser pkiuser 2048083 Nov 21 14:21 kra_cert-kra_audit.20221121142144
    -rw-r-----. 1 pkiuser pkiuser 2048097 Nov 20 12:57 kra_cert-kra_audit.20221120125744
    -rw-r-----. 1 pkiuser pkiuser 2048170 Nov 18 23:43 kra_cert-kra_audit.20221118234343
    -rw-r-----. 1 pkiuser pkiuser 2048135 Nov 17 22:20 kra_cert-kra_audit.20221117222043
    -rw-r-----. 1 pkiuser pkiuser 2048130 Nov 16 21:00 kra_cert-kra_audit.20221116210043
    -rw-r-----. 1 pkiuser pkiuser 2048182 Nov 15 19:37 kra_cert-kra_audit.20221115193743
    -rw-r-----. 1 pkiuser pkiuser 2048193 Nov 14 18:14 kra_cert-kra_audit.20221114181443
    -rw-r-----. 1 pkiuser pkiuser 2048180 Nov 13 16:51 kra_cert-kra_audit.20221113165143
    -rw-r-----. 1 pkiuser pkiuser 2048139 Nov 12 15:28 kra_cert-kra_audit.20221112152843
    -rw-r-----. 1 pkiuser pkiuser 2048161 Nov 11 14:04 kra_cert-kra_audit.20221111140443
    -rw-r-----. 1 pkiuser pkiuser 2048138 Nov 10 12:39 kra_cert-kra_audit.20221110123943
    -rw-r-----. 1 pkiuser pkiuser 2048249 Nov  9 11:11 kra_cert-kra_audit.20221109111143
    -rw-r-----. 1 pkiuser pkiuser  160029 Oct 13 04:00 kra_cert-kra_audit.20221013040019
    -rw-r-----. 1 pkiuser pkiuser  407791 Sep  6 04:00 kra_cert-kra_audit.20220906040021
    -rw-r-----. 1 pkiuser pkiuser  253146 Jun 18 04:00 kra_cert-kra_audit.20220618040015
    -rw-r-----. 1 pkiuser pkiuser  497681 Jan 20  2022 kra_cert-kra_audit.20220120050032
    -rw-r-----. 1 pkiuser pkiuser  104466 Aug 13  2021 kra_cert-kra_audit.20210813122857

/var/log/pki/pki-tomcat/ca/signedAudit:
    total 25552
    -rw-r-----. 1 pkiuser pkiuser 1937836 Nov 23 16:53 ca_audit
    -rw-r-----. 1 pkiuser pkiuser 1630455 Oct 13 11:23 ca_audit.20221013112339
    -rw-r-----. 1 pkiuser pkiuser 1422360 Sep  6 14:13 ca_audit.20220906141341
    -rw-r-----. 1 pkiuser pkiuser 2048041 Aug  4 17:31 ca_audit.20220804173114
    -rw-r-----. 1 pkiuser pkiuser  508280 Jun 18 10:42 ca_audit.20220618104258
    -rw-r-----. 1 pkiuser pkiuser 2048203 Jun  7 04:00 ca_audit.20220607040024
    -rw-r-----. 1 pkiuser pkiuser 2048104 Apr 25  2022 ca_audit.20220425040038
    -rw-r-----. 1 pkiuser pkiuser 2048039 Mar  8  2022 ca_audit.20220308111337
    -rw-r-----. 1 pkiuser pkiuser 1973266 Jan 20  2022 ca_audit.20220120175522
    -rw-r-----. 1 pkiuser pkiuser 2048169 Dec 11  2021 ca_audit.20211211111420
    -rw-r-----. 1 pkiuser pkiuser 2048123 Nov  1  2021 ca_audit.20211101083204
    -rw-r-----. 1 pkiuser pkiuser  203387 Sep 12  2021 ca_audit.20210912105707
    -rw-r-----. 1 pkiuser pkiuser 2048279 Sep  7  2021 ca_audit.20210907142916
    -rw-r-----. 1 pkiuser pkiuser 2048144 Jul 21  2021 ca_audit.20210721040021
    -rw-r-----. 1 pkiuser pkiuser 2048225 Jun  2  2021 ca_audit.20210602040023

... but not all the way back to the original server installation (April
2021), isn't that weird?

I've been meaning to raise bugs regarding the rotation of PKI log files
on this list for some time but never got around to it. On a reasonably
old server there are always lots of very old log files in
/var/log/pki/pki-tomcat. On the server I'm looking at, we have...

catalina.*.log
host-manager.*.log
localhost.*.log
manager.*.log
---
These are mentioned in /etc/pki/pki-tomcat/logging.properties but
there's no configuration of retention or frequency in that file. They
appear to be rotated weekly and the oldest files are from Feb 2022 so I
guess there is something limiting their retention, I just don't know
where to configure it...

localhost_access_log.*.txt
---
Rotated daily, oldest file dates back to April 2021 so nothing expiring
old files. This one is mentioned in /etc/pki/pki-tomcat/server.xml,
according to https://tomcat.apache.org/tomcat-9.0-doc/config/valve.html
maxDays defaults to -1 which means keep forever. Maybe
ipa-server-install might want to set that to a sensible value?

acme/debug.*.log
ca/debug.*.log
kra/debug.*.log
Rotated daily, have never been cleaned up.
---
https://github.com/dogtagpki/pki/issues/3731 filed but no one has taken
a look at it yet...
https://www.dogtagpki.org/wiki/PKI_10.5_Subsystem_Debug_Log remarks that
"[this] logging framework does not support rotation". That being the
case maybe FreeIPA could take it upon itself to ship a cron job that can
clean these up?

pki/debug.*.log
---
As for the other debug.*.log but these are totated weekly

ca/selftests.log.*
kra/selftests.log.*
---
According to https://www.dogtagpki.org/wiki/SelfTest#Logger these are
configured in /etc/pki/pki-tomcat/{ca,kra}/CS.cfg, it looks like these
should be rotated every month, but on this server they've only rolled
over 5 times since April 2021, at irregular intervals:

# ll /var/log/pki/pki-tomcat/ca/selftests.log* -th
    -rw-r-----. 1 pkiuser pkiuser  11K Nov 19 10:31 /var/log/pki/pki-tomcat/ca/selftests.log
    -rw-r-----. 1 pkiuser pkiuser 1.2K Sep 13 11:31 /var/log/pki/pki-tomcat/ca/selftests.log.20220913113055
    -rw-r-----. 1 pkiuser pkiuser 4.7K Aug  7 14:47 /var/log/pki/pki-tomcat/ca/selftests.log.20220807144705
    -rw-r-----. 1 pkiuser pkiuser  25K May 19  2022 /var/log/pki/pki-tomcat/ca/selftests.log.20220519113631
    -rw-r-----. 1 pkiuser pkiuser  20K Dec 21  2021 /var/log/pki/pki-tomcat/ca/selftests.log.20211221184830
    -rw-r-----. 1 pkiuser pkiuser  28K Aug 13  2021 /var/log/pki/pki-tomcat/ca/selftests.log.20210813112850

... in any case, there is an undocumented expirationTime parameter that
may related to retention; it's set to 0, maybe that means 'forever'?

This expirationTime parameter is also present for the system and
transaction logs that (in the default config) that never have anything
written to them.

Maybe you don't want to get too deep into being a configuration
management system looking after poor (IMHO) defaults in tomcat/dogtag,
on the other hand I think there's value in these changes being done once
by FreeIPA rather than by each user...

* use maxDays for the tomcat access log
 * add a cron job to clean up dogtag debug logs
 * use expirationTime for the signed audit/selftest/system/transaction
   (if it actaully relates to log retention... if not, ship cron jobs to
   clean them up?)

I'm happy to test the settings to find out if they work & write some
cron jobs if you think that's a sane approach... :)

[Sam Morris]

On 23/11/2022 19:12, Sam Morris via FreeIPA-users wrote:
> I've been meaning to raise bugs regarding the rotation of PKI log files
> on this list for some time but never got around to it. On a reasonably
> old server there are always lots of very old log files in
> /var/log/pki/pki-tomcat. On the server I'm looking at, we have...
>
> catalina.*.log
> host-manager.*.log
> localhost.*.log
> manager.*.log
>
> These are mentioned in /etc/pki/pki-tomcat/logging.properties but
> there's no configuration of retention or frequency in that file. They
> appear to be rotated weekly and the oldest files are from Feb 2022 so I
> guess there is something limiting their retention, I just don't know
> where to configure it...

These can be configured by adding a new line for each of the four 
loggers, like so:

1catalina.org.apache.juli.FileHandler.maxDays = 15

Log files are removed after Tomcat starts.
> localhost_access_log.*.txt
>
> Rotated daily, oldest file dates back to April 2021 so nothing expiring
> old files. This one is mentioned in /etc/pki/pki-tomcat/server.xml,
> according to https://tomcat.apache.org/tomcat-9.0-doc/config/valve.html
> maxDays defaults to -1 which means keep forever. Maybe
> ipa-server-install might want to set that to a sensible value?

I've test this one too, log files are removed after Tomcat starts.
> acme/debug.*.log
> ca/debug.*.log
> kra/debug.*.log
> Rotated daily, have never been cleaned up.
>
> https://github.com/dogtagpki/pki/issues/3731 filed but no one has taken
> a look at it yet...
> https://www.dogtagpki.org/wiki/PKI_10.5_Subsystem_Debug_Log remarks that
> "[this] logging framework does not support rotation". That being the
> case maybe FreeIPA could take it upon itself to ship a cron job that can
> clean these up?

One liner that works for me:

find /var/log/pki/pki-tomcat/ca -name 'debug.????-??-??.log' -print | 
LC_COLLATE=C sort | head -n -14 | xargs -r ls

Seems reasonably safe, if the user has configured a different debug log 
filename then it won't delete anything.
> pki/debug.*.log
>
> As for the other debug.*.log but these are totated weekly
>
> ca/selftests.log.*
> kra/selftests.log.*
>
> According to https://www.dogtagpki.org/wiki/SelfTest#Logger these are
> configured in /etc/pki/pki-tomcat/{ca,kra}/CS.cfg, it looks like these
> should be rotated every month, but on this server they've only rolled
> over 5 times since April 2021, at irregular intervals:
>  # ll /var/log/pki/pki-tomcat/ca/selftests.log* -th
>  -rw-r-----. 1 pkiuser pkiuser  11K Nov 19 10:31 /var/log/pki/pki-tomcat/ca/selftests.log
>  -rw-r-----. 1 pkiuser pkiuser 1.2K Sep 13 11:31 /var/log/pki/pki-tomcat/ca/selftests.log.20220913113055
>  -rw-r-----. 1 pkiuser pkiuser 4.7K Aug  7 14:47 /var/log/pki/pki-tomcat/ca/selftests.log.20220807144705
>  -rw-r-----. 1 pkiuser pkiuser  25K May 19  2022 /var/log/pki/pki-tomcat/ca/selftests.log.20220519113631
>  -rw-r-----. 1 pkiuser pkiuser  20K Dec 21  2021 /var/log/pki/pki-tomcat/ca/selftests.log.20211221184830
>  -rw-r-----. 1 pkiuser pkiuser  28K Aug 13  2021 /var/log/pki/pki-tomcat/ca/selftests.log.20210813112850
>
> ... in any case, there is an undocumented expirationTime parameter that
> may related to retention; it's set to 0, maybe that means 'forever'?
>
> This expirationTime parameter is also present for the system and
> transaction logs that (in the default config) that never have anything
> written to them.

According to https://github.com/dogtagpki/pki/issues/2284 the setting 
does't work. An external cron job is recommended to clean up old logs.

[Sam Morris]

On 24/11/2022 09:38, Sam Morris via FreeIPA-users wrote:
> > acme/debug.*.log
> > ca/debug.*.log
> > kra/debug.*.log
> > Rotated daily, have never been cleaned up.
> >
> > https://github.com/dogtagpki/pki/issues/3731 filed but no one has taken
> > a look at it yet...
> > https://www.dogtagpki.org/wiki/PKI_10.5_Subsystem_Debug_Log remarks that
> > "[this] logging framework does not support rotation". That being the
> > case maybe FreeIPA could take it upon itself to ship a cron job that can
> > clean these up?

Actaully I think that page is out of 
date--https://github.com/dogtagpki/pki/wiki/Configuring-Subsystem-Debug-Log 
is more current. And it says logging can be configured by editing 
/usr/share/pki/*/webapps/*/WEB-INF/classes/logging.properties.

But the wiki page says that logs are expired after 7 days, and this 
isn't happening. I've checked and all the logging.properties files have:

org.apache.juli.FileHandler.maxDays = 7

So why that's not happening is a mystery...