Bug 1217403 - [RFE] separate system-level logs of cron cartridge from gear-level logs
Summary: [RFE] separate system-level logs of cron cartridge from gear-level logs
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: OpenShift Container Platform
Classification: Red Hat
Component: Image
Version: 2.2.0
Hardware: Unspecified
OS: Unspecified
low
medium
Target Milestone: ---
: ---
Assignee: Timothy Williams
QA Contact: libra bugs
URL:
Whiteboard:
Depends On:
Blocks: 1328495
TreeView+ depends on / blocked
 
Reported: 2015-04-30 10:04 UTC by Evgheni Dereveanchin
Modified: 2019-11-14 06:42 UTC (History)
7 users (show)

Fixed In Version: openshift-origin-cartridge-cron-1.25.4.2-1.el6op
Doc Type: Enhancement
Doc Text:
Feature: Tag cron's system-level messages as they are sent to syslog. Reason: Cron's system-level messages may get lost among the gear-level cron logs, which may result in important messages being missed by system administrators. Result: Tagging cron's system-level messages allows administrators to set up syslog rules that would seperate system-level cron log messages from gear-level messages.
Clone Of:
: 1328495 (view as bug list)
Environment:
Last Closed: 2016-08-24 19:43:03 UTC
Target Upstream Version:


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
Red Hat Product Errata RHSA-2016:1773 normal SHIPPED_LIVE Important: Red Hat OpenShift Enterprise 2.2.10 security, bug fix, and enhancement update 2016-08-24 23:41:18 UTC

Description Evgheni Dereveanchin 2015-04-30 10:04:56 UTC
Description of problem:
Background:
 Currently the cron cartridge produces two kinds of logs:
  1) gear-level logs (sent to stdout and stderr) which are configurable
  2) system-level logs which are sent using "logger" and always processed by syslog

When configuring syslog logging from gears [1] both of these log messages are sent to the same file (/var/log/openshift_gears) and it is not possible to configure sending system-level logs to a different file.

This RFE is to improve this and make it possible to differentiate gear-level logs from system-level

[1] https://access.redhat.com/documentation/en-US/OpenShift_Enterprise/2/html/Administration_Guide/Enabling_Syslog_for_Cartridge_Logs_from_Gears.html
Version-Release number of selected component (if applicable):


How reproducible:
Always

Steps to Reproduce:
1. on default OpenShift 2 install, install a cron cartridge
2. create a test cron script like this:

#!/bin/bash
DATE=`date`
echo "TEST ------- ${DATE}"

3. check logs inside the gear:

Wed Apr  1 10:30:05 EDT 2015: START minutely cron run
__________________________________________________________________________
/var/lib/openshift/551bfd925a0008d7c1000162/app-root/runtime/repo//.openshift/cron/minutely/date.sh:
TEST ------- Wed Apr  1 10:30:05 EDT 2015
__________________________________________________________________________
Wed Apr  1 10:30:05 EDT 2015: END minutely cron run - status=0
__________________________________________________________________________

4. check /var/log/messages

Apr  1 10:33:05 node1 root[23173]: user-cron-jobs Wed Apr  1 10:33:05 EDT 2015: :START: minutely cron run for openshift user '551bfd925a0008d7c1000162'
Apr  1 10:33:05 node1 root[23199]: user-cron-jobs Wed Apr  1 10:33:05 EDT 2015: :END: minutely cron run for openshift user '551bfd925a0008d7c1000162'

5. configure syslog gear logging as described in [1] and set output type in the gear

Actual results:
both logs from steps 3 and 4 start going into /var/log/openshift_gears

Expected results:
logs from step 3 go to /var/log/openshift_gears
logs from step 4 (system-level) go to some other log file, not together with gear-level logs

Additional info:

Comment 3 Eric Rich 2016-04-18 22:06:22 UTC
I think this requires two changes. One change to the following line: 

https://github.com/openshift/origin-server/blob/master/cartridges/openshift-origin-cartridge-cron/bin/cron_runjobs.sh#L40

            To introduce a TAG flag to the system messages. 

            Example: 

            function log_message() {
               msg=${1-""}
               [ -z "$msg" ]  &&  return 0
               logger -i -s "user-cron-jobs" -p user.info -t "cron_sys_log:" "`date`: $msg"
            }

and a change to the docs on how to pick up tag's in the openshift syslog plugin. 

         2: Update the rsyslog configuration to account for this tag (and filter the logs out).

            Example:

            module(load="mmopenshift")
            action(type="mmopenshift")
            
            :syslogtag, isequal, "cron_sys_log:" /var/log/ABC.log
            

            if $!OpenShift!OPENSHIFT_APP_UUID != '' then
              *.* action(type="omfile" file="/var/log/openshift_gears" template="OpenShift")
            else {
              *.info;mail.none;authpriv.none;cron.none   action(type="omfile" file="/var/log/messages")
            }

Comment 5 Eric Rich 2016-04-19 14:05:59 UTC
(In reply to Eric Rich from comment #3)
> I think this requires two changes. One change to the following line: 
> 
> https://github.com/openshift/origin-server/blob/master/cartridges/openshift-
> origin-cartridge-cron/bin/cron_runjobs.sh#L40
> 
>             To introduce a TAG flag to the system messages. 
> 
>             Example: 
> 
>             function log_message() {
>                msg=${1-""}
>                [ -z "$msg" ]  &&  return 0
>                logger -i -s "user-cron-jobs" -p user.info -t "cron_sys_log:"
> "`date`: $msg"
>             }
> 

The following should provide a fix for this: https://github.com/openshift/origin-server/pull/6381

Comment 6 openshift-github-bot 2016-04-20 21:08:58 UTC
Commit pushed to master at https://github.com/openshift/origin-server

https://github.com/openshift/origin-server/commit/96ab0c03099d35a23f31089a22f60fab31957559
...cartridge-cron/bin/cron_runjobs.sh: Feature Enhancement for syslog tagging.

Bug 1217403
Bugzilla link https://bugzilla.redhat.com/show_bug.cgi?id=1217403

Adding the ability to filter/tag cron messages with syslog

Comment 13 Johnny Liu 2016-08-12 07:05:09 UTC
Re-test this bug with 2.2/2016-08-11.1, and following comment 11, add the following line to /etc/rsyslog.conf
  :syslogtag, contains, "cron_sys_log:" /var/log/ABC.log
Then restart rsyslog service.

Check logs, both system-level and gear-level logs are still sent to /var/log/openshift_gears, and another copy of system-level logs are sent to /var/log/ABC.log, but according to initial report, the request is asking to separate system-level logs from gear-level, is it an expected behavior?

# vim /var/log/ABC.log
...
Aug 12 14:50:04 node1 cron_sys_log:[25470]: user-cron-jobs Fri Aug 12 14:50:04 CST 2016: :START: minutely cron run for openshift user 'jialiu-php54app-1'
Aug 12 14:50:04 node1 cron_sys_log:[25498]: user-cron-jobs Fri Aug 12 14:50:04 CST 2016: :END: minutely cron run for openshift user 'jialiu-php54app-1'


# vim /var/log/openshift_gears
Aug 12 14:50:04 node1 cron_sys_log:[25470]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 user-cron-jobs Fri Aug 12 14:50:04 CST 2016: :START: minutely cron run for openshift user 'jialiu-php54app-1'
Aug 12 14:50:04 node1 cron_minutely[25476]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 __________________________________________________________________________
Aug 12 14:50:04 node1 cron_minutely[25476]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 Fri Aug 12 14:50:04 CST 2016: START minutely cron run
Aug 12 14:50:04 node1 cron_minutely[25476]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 __________________________________________________________________________
Aug 12 14:50:04 node1 run-parts(/var/lib/openshift/jialiu-php54app-1/app-root/runtime/repo//.openshift/cron/minutely)[25489]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 starting test.sh
Aug 12 14:50:04 node1 cron_minutely[25476]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 /var/lib/openshift/jialiu-php54app-1/app-root/runtime/repo//.openshift/cron/minutely/test.sh:
Aug 12 14:50:04 node1 cron_minutely[25476]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 TEST ------- Fri Aug 12 14:50:04 CST 2016
Aug 12 14:50:04 node1 run-parts(/var/lib/openshift/jialiu-php54app-1/app-root/runtime/repo//.openshift/cron/minutely)[25495]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 finished test.sh
Aug 12 14:50:04 node1 cron_minutely[25476]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 __________________________________________________________________________
Aug 12 14:50:04 node1 cron_minutely[25476]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 Fri Aug 12 14:50:04 CST 2016: END minutely cron run - status=0
Aug 12 14:50:04 node1 cron_minutely[25476]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 __________________________________________________________________________
Aug 12 14:50:04 node1 cron_sys_log:[25498]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 user-cron-jobs Fri Aug 12 14:50:04 CST 2016: :END: minutely cron run for openshift user 'jialiu-php54app-1'

Comment 14 Timothy Williams 2016-08-14 18:27:32 UTC
The below entry is also catching the cron_sys_log entries:

  *.*     action(type="omfile" file="/var/log/openshift_gears" template="OpenShift")

To remedy this, the new entry we are adding should be placed before the mmopenshift configuration and a '&~' added to the next line to stop further filtering of the log message. See below for an example:

:syslogtag, contains, "cron_sys_log:" /var/log/ABC.log
&~

action(type="mmopenshift")

if $!OpenShift!OPENSHIFT_APP_UUID != '' then
  # annotate and log syslog output from gears specially
  *.*     action(type="omfile" file="/var/log/openshift_gears" template="OpenShift")
else
  # otherwise send syslog where it usually goes
  *.info;mail.none;authpriv.none;cron.none   action(type="omfile" file="/var/log/messages")

Comment 15 Johnny Liu 2016-08-15 02:20:52 UTC
Following comment 14, the behavior is working as expection, so the bug is verified.

==> /var/log/openshift_gears <==
Aug 15 10:18:04 node1 cron_minutely[9219]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 __________________________________________________________________________
Aug 15 10:18:04 node1 cron_minutely[9219]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 Mon Aug 15 10:18:04 CST 2016: START minutely cron run
Aug 15 10:18:04 node1 cron_minutely[9219]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 __________________________________________________________________________
Aug 15 10:18:04 node1 run-parts(/var/lib/openshift/jialiu-php54app-1/app-root/runtime/repo//.openshift/cron/minutely)[9232]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 starting test.sh
Aug 15 10:18:04 node1 cron_minutely[9219]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 /var/lib/openshift/jialiu-php54app-1/app-root/runtime/repo//.openshift/cron/minutely/test.sh:
Aug 15 10:18:04 node1 cron_minutely[9219]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 TEST ------- Mon Aug 15 10:18:04 CST 2016
Aug 15 10:18:04 node1 run-parts(/var/lib/openshift/jialiu-php54app-1/app-root/runtime/repo//.openshift/cron/minutely)[9238]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 finished test.sh
Aug 15 10:18:04 node1 cron_minutely[9219]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 __________________________________________________________________________
Aug 15 10:18:04 node1 cron_minutely[9219]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 Mon Aug 15 10:18:04 CST 2016: END minutely cron run - status=0
Aug 15 10:18:04 node1 cron_minutely[9219]: app=php54app ns=jialiu appUuid=57a8643882611da20d00029b gearUuid=jialiu-php54app-1 __________________________________________________________________________

==> /var/log/ABC.log <==
Aug 15 10:18:04 node1 cron_sys_log:[9213]: user-cron-jobs Mon Aug 15 10:18:04 CST 2016: :START: minutely cron run for openshift user 'jialiu-php54app-1'
Aug 15 10:18:04 node1 cron_sys_log:[9241]: user-cron-jobs Mon Aug 15 10:18:04 CST 2016: :END: minutely cron run for openshift user 'jialiu-php54app-1'

Comment 17 errata-xmlrpc 2016-08-24 19:43:03 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, 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://rhn.redhat.com/errata/RHSA-2016-1773.html


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