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:
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") }
(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
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
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'
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")
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'
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