RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1880392 - pmlogger_daily script compresses latest archive files immediately even if --compress-after (-x) option is specified.
Summary: pmlogger_daily script compresses latest archive files immediately even if --c...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 8
Classification: Red Hat
Component: pcp
Version: 8.4
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: rc
: 8.0
Assignee: Mark Goodwin
QA Contact: Jan Kurik
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2020-09-18 12:07 UTC by Yuki Okada
Modified: 2023-12-15 19:25 UTC (History)
8 users (show)

Fixed In Version: pcp-5.2.2-1.el8
Doc Type: No Doc Update
Doc Text:
Clone Of:
Environment:
Last Closed: 2021-05-18 15:19:49 UTC
Type: Bug
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Knowledge Base (Solution) 5442051 0 None None None 2020-09-29 09:20:18 UTC

Description Yuki Okada 2020-09-18 12:07:33 UTC
Description of problem:
- pmlogger_daily with "-x 7" option compresses latest PCP archive logs as shown below.

  $ date 
  Fri Sep 18 20:27:08 JST 2020
  $ ls -l /var/log/pcp/pmlogger/localhost.localdomain/
  total 400920
  -rw-r--r--. 1 pcp pcp  65696416 Sep  9 00:10 20200908.0.xz
  -rw-r--r--. 1 pcp pcp    121512 Sep  9 00:11 20200908.index
  -rw-r--r--. 1 pcp pcp    350400 Sep  9 00:11 20200908.meta.xz
  -rw-r--r--. 1 pcp pcp  34678164 Sep 10 00:10 20200909.0.xz
  -rw-r--r--. 1 pcp pcp    121252 Sep 10 00:10 20200909.index
  -rw-r--r--. 1 pcp pcp    241300 Sep 10 00:10 20200909.meta.xz
  [...]
  -rw-r--r--. 1 pcp pcp     26984 Sep 17 00:10 20200917.00.10-00.0.xz
  -rw-r--r--. 1 pcp pcp       252 Sep 17 00:10 20200917.00.10-00.index
  -rw-r--r--. 1 pcp pcp     51392 Sep 17 00:10 20200917.00.10-00.meta.xz
  -rw-r--r--. 1 pcp pcp   2076300 Sep 17 03:34 20200917.00.10.0.xz
  -rw-r--r--. 1 pcp pcp   2157444 Sep 17 06:58 20200917.00.10.1.xz
  -rw-r--r--. 1 pcp pcp   2058608 Sep 17 10:22 20200917.00.10.2.xz
  -rw-r--r--. 1 pcp pcp   2079940 Sep 17 13:46 20200917.00.10.3.xz
  -rw-r--r--. 1 pcp pcp   2137512 Sep 17 17:10 20200917.00.10.4.xz
  -rw-r--r--. 1 pcp pcp   2003596 Sep 17 20:34 20200917.00.10.5.xz
  -rw-r--r--. 1 pcp pcp   1992028 Sep 17 23:58 20200917.00.10.6.xz
  -rw-r--r--. 1 pcp pcp    148292 Sep 18 00:10 20200917.00.10.7.xz
  -rw-r--r--. 1 pcp pcp    121112 Sep 18 00:10 20200917.00.10.index
  -rw-r--r--. 1 pcp pcp    178684 Sep 18 00:09 20200917.00.10.meta.xz
  -rw-r--r--. 1 pcp pcp     26724 Sep 18 00:10 20200918.00.10-00.0.xz
  -rw-r--r--. 1 pcp pcp       252 Sep 18 00:10 20200918.00.10-00.index
  -rw-r--r--. 1 pcp pcp     51560 Sep 18 00:10 20200918.00.10-00.meta.xz
  -rw-r--r--. 1 pcp pcp   2008900 Sep 18 03:34 20200918.00.10.0.xz
  -rw-r--r--. 1 pcp pcp   2234992 Sep 18 06:58 20200918.00.10.1.xz
  -rw-r--r--. 1 pcp pcp   1944776 Sep 18 10:22 20200918.00.10.2.xz
  -rw-r--r--. 1 pcp pcp   2299800 Sep 18 13:44 20200918.00.10.3.xz
  -rw-r--r--. 1 pcp pcp   2202236 Sep 18 17:06 20200918.00.10.4.xz
  -rw-r--r--. 1 pcp pcp 104078584 Sep 18 20:25 20200918.00.10.5        <<<-------- Not compressed
  -rw-r--r--. 1 pcp pcp    102312 Sep 18 20:25 20200918.00.10.index
  -rw-r--r--. 1 pcp pcp  23074442 Sep 18 20:25 20200918.00.10.meta     <<<-------- Not compressed
  -rw-r--r--. 1 pcp pcp       231 Sep 18 00:10 Latest
  -rw-r--r--. 1 pcp pcp     32858 Sep 18 17:06 pmlogger.log
  -rw-r--r--. 1 pcp pcp     32598 Sep 18 00:10 pmlogger.log.prior
  
  # /usr/libexec/pcp/bin/pmlogger_daily -VV -x 7                       <<<-------- Run pmlogger_daily with "-x 7" option
  #
  
  $ date 
  Fri Sep 18 20:33:07 JST 2020
  $ ls -l /var/log/pcp/pmlogger/localhost.localdomain/
  total 258972
  -rw-r--r--. 1 pcp pcp 65696416 Sep  9 00:10 20200908.0.xz
  -rw-r--r--. 1 pcp pcp   121512 Sep  9 00:11 20200908.index
  -rw-r--r--. 1 pcp pcp   350400 Sep  9 00:11 20200908.meta.xz
  [...]
  -rw-r--r--. 1 pcp pcp    26724 Sep 18 00:10 20200918.00.10-00.0.xz
  -rw-r--r--. 1 pcp pcp      252 Sep 18 00:10 20200918.00.10-00.index
  -rw-r--r--. 1 pcp pcp    51560 Sep 18 00:10 20200918.00.10-00.meta.xz
  -rw-r--r--. 1 pcp pcp  2008900 Sep 18 03:34 20200918.00.10.0.xz
  -rw-r--r--. 1 pcp pcp  2234992 Sep 18 06:58 20200918.00.10.1.xz
  -rw-r--r--. 1 pcp pcp  1944776 Sep 18 10:22 20200918.00.10.2.xz
  -rw-r--r--. 1 pcp pcp  2299800 Sep 18 13:44 20200918.00.10.3.xz
  -rw-r--r--. 1 pcp pcp  2202236 Sep 18 17:06 20200918.00.10.4.xz
  -rw-r--r--. 1 pcp pcp  2318188 Sep 18 20:27 20200918.00.10.5.xz      <<<-------- compressed (This is unexpected)
  -rw-r--r--. 1 pcp pcp    27344 Sep 18 20:28 20200918.00.10.6.xz
  -rw-r--r--. 1 pcp pcp   102532 Sep 18 20:28 20200918.00.10.index
  -rw-r--r--. 1 pcp pcp   150948 Sep 18 20:28 20200918.00.10.meta.xz   <<<-------- compressed (This is unexpected)
  -rw-r--r--. 1 pcp pcp    27344 Sep 18 20:28 20200918.20.28-00.0.xz
  -rw-r--r--. 1 pcp pcp      252 Sep 18 20:28 20200918.20.28-00.index
  -rw-r--r--. 1 pcp pcp    51428 Sep 18 20:28 20200918.20.28-00.meta.xz
  -rw-r--r--. 1 pcp pcp  2565908 Sep 18 20:33 20200918.20.28.0
  -rw-r--r--. 1 pcp pcp      592 Sep 18 20:33 20200918.20.28.index
  -rw-r--r--. 1 pcp pcp   331054 Sep 18 20:33 20200918.20.28.meta
  -rw-r--r--. 1 pcp pcp      231 Sep 18 20:29 Latest
  -rw-r--r--. 1 pcp pcp    32523 Sep 18 20:29 pmlogger.log
  -rw-r--r--. 1 pcp pcp    32598 Sep 18 20:28 pmlogger.log.prior
  
- pmlogger_daily.log shows "Warning: no archive files found to compress" log. 

  $ cat /var/log/pcp/pmlogger/pmlogger_daily.log    
  [control:24] host="$version=1.1" primary="" socks="" dir="" args=""
  [control.d/local:10] host="$version=1.1" primary="" socks="" dir="" args=""
  [control.d/local:26] host="LOCALHOSTNAME" primary="y" socks="n" dir="/var/log/pcp/pmlogger/LOCALHOSTNAME" args="-r -T24h10m -c config.default -v 100Mb"
  Check pmlogger -P -h local: ... in /var/log/pcp/pmlogger/localhost.localdomain ...
  
  === daily maintenance of PCP archives for host local: ===
  
  ... try /var/lib/pcp/tmp/pmlogger/primary: host=localhost.localdomain arch=/var/log/pcp/pmlogger/localhost.localdomain/20200918.00.10
  primary pmlogger process 31158 identified, OK
  Looking for primary pmlogger ... found
  pcp      31158     1  0 00:10 ?        00:00:10 /usr/libexec/pcp/bin/pmlogger -P -r -T24h10m -c config.default -v 100mb -m pmlogger_check 20200918.00.10
  Terminating primary pmlogger ... SIGUSR1 ... SIGTERM ... done
  Launching new pmlogger in directory "/var/log/pcp/pmlogger/localhost.localdomain" as ...
  /usr/libexec/pcp/bin/pmlogger -r -T 24h10m -v 100Mb -m pmlogger_daily -P -l pmlogger.log -c /var/lib/pcp/config/pmlogger/config.default 20200918.20.28
  Waiting for new pmlogger to start ... done
  New pmlogger status ...
  pmlogger [19497] on host local: is logging metrics from host localhost.localdomain
  PMCD host        localhost.localdomain
  log started      Fri Sep 18 20:28:33 2020 (times in local time)
  last log entry   Fri Sep 18 20:28:43 2020
  current time     Fri Sep 18 20:28:49 2020
  log volume       0
  log size         244996
  ... try new /var/lib/pcp/tmp/pmlogger/primary: host=localhost.localdomain arch=/var/log/pcp/pmlogger/localhost.localdomain/20200918.20.28
  new primary pmlogger process 19497 identified, OK
  pmlogger_daily: Warning: no archive files found to cull
  pmlogger_daily: Warning: output archive (20200914) already exists
  [control.d/local:26] ... skip log merging and compressing for host "local:"
  Rewriting input archives using -c $PCP_VAR_DIR/config/pmlogrewrite
  Rewriting input archives using -c $PCP_VAR_DIR/config/pmlogrewrite
  Rewriting input archives using -c $PCP_VAR_DIR/config/pmlogrewrite
  pmlogger_daily: COMPRESSAFTER=7                                <<<------- -x option seems successfully passed to pmlogger_daily script
  pmlogger_daily: Warning: no archive files found to compress    <<<------- This warning shows there is no files to be compressed (But actually it was compressed)

Version-Release number of selected component (if applicable):
pcp-4.3.2-7.el7_8.x86_64

How reproducible:
100%

Steps to Reproduce:
1. Install pcp-zeroconf

  # yum install pcp-zeroconf

2. Run pmlogger_daily with -x option (Use 7 days in this example)

  # /usr/libexec/pcp/bin/pmlogger_daily -x 7

3. Check archive logs in /var/log/pcp/pmlogger/<hostname.domainname>/

Actual results:
latest archive logs are compressed

Expected results:
archive logs within 7 days are NOT compressed

Additional info:
- This issue also occurs in RHEL8 (pcp-5.0.2-5.el8.x86_64).
- Customer's original problem is specifying -x option to PMLOGGER_DAILY_PARAMS variable in /etc/sysconfig/pmlogger_timers does not work. PMLOGGER_DAILY_PARAMS is used as arguments of pmlogger_daily in /usr/lib/systemd/system/pmlogger_daily.service unit file.

  ---
  ExecStart=/usr/libexec/pcp/bin/pmlogger_daily $PMLOGGER_DAILY_PARAMS
  ---

- -x option was working as expected prior to pcp-4.3.2, where cron based log management is used (unlike systemd timer based).

Comment 3 Yuki Okada 2020-09-22 02:31:36 UTC
Compression seems to be run in line 1446. However, "Warning: no archive files found to compress" message appears in pmlogger_daily.log, so no file exists in $tmp/list, and the problematic compression would be run elsewhere.

[/usr/libexec/pcp/bin/pmlogger_daily]

   1430                     if [ -s $tmp/list ]
   1431                     then
   1432                         if $VERBOSE
   1433                         then
   1434                             if [ "$COMPRESSAFTER" -eq 0 ]
   1435                             then
   1436                                 echo "Archive files being compressed ..."
   1437                             else
   1438                                 echo "Archive files older than $COMPRESSAFTER days being compressed ..."
   1439                             fi
   1440                             fmt <$tmp/list | sed -e 's/^/    /'
   1441                         fi
   1442                         if $SHOWME
   1443                         then
   1444                             cat $tmp/list | xargs echo + $COMPRESS
   1445                         else
   1446                             cat $tmp/list | xargs $COMPRESS      <<<<<----------
   1447                         fi
   1448                     else
   1449                         $VERY_VERBOSE && echo "$prog: Warning: no archive files found to compress"     <<<<<----------
   1450                     fi

Comment 4 Mark Goodwin 2020-09-22 02:53:35 UTC
Yuki, it might be the pmlogger_daily -K that gets launched by pmlogger_check (see _compress_now() in /usr/libexec/pcp/bin/pmlogger_check). It's passing -K to pmlogger_daily, but not the -x flag on the cmdline, and so pmlogger_daily would be using $PCP_COMPRESSAFTER or if not set, falling back to $COMPRESSAFTER_DEFAULT.

Comment 5 Mark Goodwin 2020-09-22 02:58:36 UTC
The PCP_COMPRESSAFTER setting in the control file should still be honoured though. Uncomment #$PCP_COMPRESSAFTER=3 in /etc/pcp/pmlogger/control.d/local (or whatever control file you're using if not the one mentioned).

Comment 6 Yuki Okada 2020-09-22 11:00:23 UTC
Hi Mark,

Thank you for suggesting a workaround. Confirmed that archive files are NOT compressed by uncommenting PCP_COMPRESSAFTER variable.

BTW, regarding the comment 4, is pmlogger_check launched when pmlogger_daily is run manually. This issue is reproducible even if pmlogger_daily is run manually like below.

# /usr/libexec/pcp/bin/pmlogger_daily -x 7

Comment 7 Mark Goodwin 2020-09-22 23:01:01 UTC
Hi Yuki, yes pmlogger_daily uses pmlogger_check to restart pmlogger. And pmlogger_check then calls pmlogger_daily -K (right at the end, see below). This doesn't sound optimal due to the recursion, however note that pmlogger_daily -K ONLY does compression, which is kind of a stand-alone script in itself.

pmlogger_check :
   
    163 _compress_now()
    164 {
    165     # If $PCP_COMPRESSAFTER=0 in the control file(s), compress archives now.
    166     # Invoked just before exit when this script has finished successfully.
    167     $PCP_BINADM_DIR/pmlogger_daily -K $daily_args
    168 }
...

    985 # Prior to exiting we compress existing logs, if any. See pmlogger_daily -K
    986 # Do not compress on a virgin install - it confuses systemd's Type=forking
    987 # exit status checks. There is nothing to compress anyway. See RHBZ#1721223.
    988 [ -f "$PCP_LOG_DIR/pmlogger/pmlogger_daily.stamp" ] && _compress_now
    989 
    990 [ -f $tmp/err ] && status=1
    991 exit

So I guess one possible fix would be to ensure _compress_now in pmlogger_check included -x in the $daily_args passed to pmlogger_daily -K.

Given you now have a work-around, I do not think this would qualify for RHEL7 zstream - so I would propose to address this issue upstream in the next PCP release (pcp-5.2.2), which would then find it's way back into RHEL8 y-stream via rebase. Does that sound OK to you and the customer?

Thanks

Comment 8 Mark Goodwin 2020-09-22 23:20:12 UTC
Related:

commit 27a818f9937a9c074a339f63e0ff36b849f5cd0e
Author: Ken McDonell <kenj.au>
Date:   Tue Jul 7 08:22:26 2020 +1000

    pmlogger_daily: -k 0 fixes

Also related:


commit 6628ad55cf111d1e1b1de59f76bf024f53469752
Author: Mark Goodwin <mgoodwin>
Date:   Tue Sep 4 13:25:50 2018 +1000

    pmlogger_check: run periodic compression when exiting early
    
    We always want to run the compression logic for sub-volumes
    even if we are exiting early - otherwise pathological cases
    (e.g. via selinux) can cause this logic to never happen.

Comment 9 Nathan Scott 2020-09-28 22:30:45 UTC
Moving to RHEL-8 as this is not a critical fix meeting the RHEL-7 requirements.

Comment 10 Yuki Okada 2020-09-29 02:05:33 UTC
Hi Mark, Nathan,

It's fine to move this BZ to RHEL8. RHEL7 zstream is not necessary because the workaround works fine.

Thanks.

Comment 12 Mark Goodwin 2020-10-21 22:46:06 UTC
After more thought, have concluded this is a usage issue, not a bug. The pmlogger_daily -x option can be used to induce early compression of archive volumes when the $PCP_COMPRESSAFTER environment variable has been explicitly set in the pmlogger control file to a value greater than zero. If that environment variable has not been set, then the default compression interval is zero days (i.e. all except the current volume) and -x has no effect. Note also in particular, -x cannot be used to prevent compression. As has been explained earlier, the correct way to prevent compression is to set $PCP_COMPRESSAFTER in the control file to a desired value greater than zero. For deleting/culling archive volumes, the same principles also apply to the $PCP_CULLAFTER environment variable, and the corresponding -k command line option.

The pmlogger_daily(1) man page has been updated to clarify this, with the following upstream commit for pcp-5.2.2 :

commit ffcdd814435aad7f7c9d86357224c563e26f6371
Author: Mark Goodwin <mgoodwin>
Date:   Thu Oct 22 09:20:49 2020 +1100

    docs: update pmlogger_daily(1) for -x, -K, -k options and $PCP_COMPRESSAFTER
    
    Update pmlogger_daily(1) to clarify -x, -k, -K and use of the
    $PCP_COMPRESSAFTER environment variable in pmlogger control files.
    
    Resolves: RHBZ#1880392

Comment 13 Yuki Okada 2020-10-22 08:21:40 UTC
Thanks Mark,

So we should not use PMLOGGER_DAILY_PARAMS in /etc/sysconfig/pmlogger_timers to configure -x or -k option of pmlogger_daily. Is that right?

  ## Type:        string
  ## Default:     ""
  #
  # Run the pmlogger_daily binary, via pmlogger_daily.service, with the
  # following parameters.
  #
  #PMLOGGER_DAILY_PARAMS=""

In that case, we need to update https://access.redhat.com/solutions/2209361 to use $PCP_COMPRESSAFTER in a control file, instead of PMLOGGER_DAILY_PARAMS in /etc/sysconfig/pmlogger_timers.

Comment 14 Mark Goodwin 2020-11-04 11:14:19 UTC
Hi Yuki, sorry for the delay - I thought I had replied to this.

yes that document will need clarifying. Note it describes the *maximum* time before compression and culling occurs. The $PCP_COMPRESSAFTER (default 0 days) and $PCP_CULLAFTER (default 14 days) variables defined in the control file (or environment) override the command line options. Having so many ways to specify these parameters is confusing, but on-going, the preferred method is to edit the variables in the control file, e.g. /etc/pcp/pmlogger/control.d/local. This can be done for individual pmloggers (just use separate control files as necessary).

Comment 18 John 2020-12-10 05:53:29 UTC
I've ended up here because all I want to do is limit pmlogger so it only keeps data from the last 7 days or so.

Of course, all of Red Hat's documentation on how to achieve this is utter nonsense.

I've tried setting:

1) PCP_CULLAFTER=7 in /etc/sysconfig/pmlogger.
2) $PCP_CULLAFTER=7 and export it, in /etc/pcp/pmlogger/control
3) $PCP_CULLAFTER=7 and export it, in /etc/pcp/pmlogger/control.d/local

None of them do any good.

The only thing that works is set PMLOGGER_DAILY_PARAMS="-k 7" in /etc/sysconfig/pmlogger_timers.

Well done Red Hat, it's just incredible how you manage to make the simplest thing as difficult as possible.

Comment 20 errata-xmlrpc 2021-05-18 15:19:49 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (pcp bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2021:1754

Comment 21 John 2022-07-28 04:46:38 UTC

"Mark Goodwin  2020-11-04 11:14:19 UTC
Hi Yuki, sorry for the delay - I thought I had replied to this.

yes that document will need clarifying."


HAVE YOU CLARIFIED THAT DOCUMENT YET MARK?


Note You need to log in before you can comment on or make changes to this bug.