Bug 963827 - [RFE] Logs generated by oo-admin-ctl-gears should include timestamps
[RFE] Logs generated by oo-admin-ctl-gears should include timestamps
Status: CLOSED CURRENTRELEASE
Product: OpenShift Container Platform
Classification: Red Hat
Component: Containers (Show other bugs)
1.2.0
All Linux
high Severity high
: ---
: ---
Assigned To: chris alfonso
libra bugs
:
: 964248 (view as bug list)
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2013-05-16 11:56 EDT by Jeremy Eder
Modified: 2017-03-08 12 EST (History)
5 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2013-06-28 11:46:25 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Comment 3 chris alfonso 2013-05-22 14:25:43 EDT
Fixing upstream and will pull in with rebase

https://github.com/openshift/origin-server/pull/2594
Comment 4 Jason DeTiberus 2013-05-23 09:21:07 EDT
*** Bug 964248 has been marked as a duplicate of this bug. ***
Comment 6 Johnny Liu 2013-05-24 05:11:15 EDT
Retest this bug with 1.2/2013-05-23.2 puddle, though most of issues are fixed, but still have some issues.

Now /var/log/openshift-gears-async-start.log has been removed, all logs will go to /var/log/openshift/node/platform.log. This is expected.

When "/etc/init.d/openshift-gears start", the following message is seen in /var/log/openshift/node/platform.log, the timestamp is seen in the log.
<--snip-->
May 24 01:43:25 INFO Background start initiated - process id = 27101
May 24 01:43:25 INFO Check  for more details.
May 24 01:43:25 DEBUG Setting for all gears with 5 parallel
May 24 01:43:25 DEBUG Created v2 model for 519f2209e587c41678000006
May 24 01:43:25 DEBUG The file context database is being reloaded.
May 24 01:43:25 DEBUG 519f2209e587c41678000006 start against 'php'
May 24 01:43:26 DEBUG Shell command '/sbin/runuser -m -s /bin/sh 519f2209e587c41678000006 -c "exec /usr/bin/runcon 'unconfined_u:system_r:openshift_t:s0:c0,c500' /bin/sh -c \"set -e; /var/lib/openshift/519f2209e587c41678000006/php/bin/control start\""' ran. rc=0 out=Starting PHP cart

May 24 01:43:26 INFO Starting 519f2209e587c41678000006... [ OK ]
<--snip-->

Seen from the line:
May 24 01:43:25 INFO Check  for more details.

Found that the log file is empty.

After check the patch, found this line
OpenShift::NodeLogger.logger.info("Check #{$gearsfile} for more details.") 
still has reference to #{$gearsfile}.

Suggest that revert the change, and change the value of $gearsfile to "/var/log/openshift/node/platform.log", and replace this line:
$stdout.reopen($gearsfile, 'w') 
to
$stdout.reopen($gearsfile, 'a')
Comment 7 Johnny Liu 2013-05-24 05:14:50 EDT
In addition, in the patch, due to "$stdout.reopen($gearsfile, 'w') " is removed, that will lead the following:

[root@node openshift]# /etc/init.d/openshift-gears start
Background start initiated - process id = 27101
Check /var/log/openshift/node/platform.log for more details.

Note: In the future, if you wish to start the OpenShift services in the
      foreground (waited), use:  service openshift-gears waited-start
[root@node openshift]# Starting 519f2209e587c41678000006... [ OK ]

The gear starting message will be printed out to std IO, the message is a little messed up.
Comment 8 chris alfonso 2013-05-24 10:35:25 EDT
What we should do here is remove the OpenShift::NodeLogger.logger.info("Check #{$gearsfile} for more details.") entirely, not revert the change. We don't want to use $stdout.reopen to add content to the platform.log, we want to go through the logger to add any messages. The logger is what sets up the log statement format, including the timestamp header.

I'll alter the "Starting 519f2209e587c41678000006... [ OK ]" to be "Starting gear 519f2209e587c41678000006... [ OK ]"
Comment 9 chris alfonso 2013-05-24 10:38:52 EDT
https://github.com/openshift/origin-server/pull/2632
Comment 10 chris alfonso 2013-05-31 11:07:49 EDT
This is now available in the latest OSE 1.2 puddle:

http://buildvm-devops.usersys.redhat.com/puddle/build/OpenShiftEnterprise/1.2/2013-05-31.1/
Comment 11 Johnny Liu 2013-06-03 05:32:10 EDT
Verified this bug with 1.2/2013-05-31.1 puddle, and PASS.

The following log is seen in /var/log/openshift/node/platform.log when start openshift-gear:
<--snip-->
June 03 02:22:59 INFO Background start initiated - process id = 3675
June 03 02:22:59 DEBUG AdminGearsControl: initialized for all gears with 5 parallel
June 03 02:22:59 DEBUG Created v2 model for 51a326f8d15e75a9340001d8
June 03 02:22:59 DEBUG 51a326f8d15e75a9340001d8 start against 'haproxy'
June 03 02:23:05 DEBUG Shell command '/sbin/runuser -m -s /bin/sh 51a326f8d15e75a9340001d8 -c "exec /usr/bin/runcon 'unconfined_u:system_r:openshift_t:s0:c6,c471' /bin/sh -c \"set -e; /var/lib/openshift/51a326f8d15e75a9340001d8/haproxy/bin/control start\""' ran. rc=0 out=CLIENT_RESULT: HAProxy instance is started

June 03 02:23:05 DEBUG The file context database is being reloaded.
June 03 02:23:05 DEBUG 51a326f8d15e75a9340001d8 start against 'jbosseap
June 03 02:23:33 DEBUG Shell command '/sbin/runuser -m -s /bin/sh 51a326f8d15e75a9340001d8 -c "exec /usr/bin/runcon 'unconfined_u:system_r:openshift_t:s0:c6,c471' /bin/sh -c \"set -e; /var/lib/openshift/51a326f8d15e75a9340001d8/jbosseap/bin/control start\""' ran. rc=0 out=Starting jbosseap cart
Found 127.12.222.1:8080 listening port

June 03 02:23:33 INFO Starting gear 51a326f8d15e75a9340001d8... [ OK ]
<--snip-->
Comment 12 Luke Meyer 2013-06-28 11:46:25 EDT
Closing all bugs introduced, fixed, and verified during 1.2 release work (thus never shipped).

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