Bug 837468 - time sync issue for rhc app threaddump log
time sync issue for rhc app threaddump log
Status: CLOSED CURRENTRELEASE
Product: OpenShift Origin
Classification: Red Hat
Component: Containers (Show other bugs)
2.x
Unspecified Unspecified
medium Severity medium
: ---
: ---
Assigned To: Ram Ranganathan
libra bugs
: Triaged
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2012-07-03 23:16 EDT by Meng Bo
Modified: 2015-05-14 18:56 EDT (History)
3 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2012-07-13 19:43:26 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)
Description Meng Bo 2012-07-03 23:16:47 EDT
Description of problem:
This issue happens when I testing the rhc app threaddump, after threaddump an app, the message said "The thread dump file will be available via: rhc app tail -a ruby19 -f ruby19/logs/error_log-20120703-000000-EST -o '-n 250'", but when I trying to check the log using the given command, it will return


bash-3.2$ rhc app tail -a ruby19 -f ruby19/logs/error_log-20120703-000000-EST -o '-n 250'
Password: 

Attempting to tail files: ruby19/logs/error_log-20120703-000000-EST
Use ctl + c to stop
Could not find any files matching glob

Then I login to the app to check the log manually and found

[ruby19-bmengdev.dev.rhcloud.com logs]\> ls
access_log-20120704-000000-EST	error_log-20120704-000000-EST  production.log

The name of the log is not match for the one which threaddump command returned.

I tested this scenario in local time (GMT +8) 11 o'clock Jun 04, and the server side time is EDT 23 o'clock Jun 03.


Version-Release number of selected component (if applicable):


How reproducible:


Steps to Reproduce:
1.
2.
3.
  
Actual results:
the retruned log name is not match for the real one.

Expected results:
user can get the threaddump log by the returned message directly. 

Additional info:
Comment 1 Meng Bo 2012-07-04 00:28:06 EDT
sorry for lacking info about the step and the version,

Version-Release number of selected component (if applicable):
devenv_1874
rhc-0.95.7

Steps to Reproduce:
1.create a ruby app
rhc app create -a ruby19 -t ruby-1.9 
2.threaddump the app 
rhc app threadddump -a ruby19
Comment 2 Ram Ranganathan 2012-07-06 20:19:18 EDT
Hmm, looks like this happens because apache rolls over the file earlier than midnight -- seems to be a bug in rotatelogs. 

Here's what I saw on my instance right now (close to 8:00 PM EST). 
[ru19-rr331.dev.rhcloud.com logs]\> date
Fri Jul  6 20:16:05 EDT 2012

But file's rolled over ... 
[ru19-rr331.dev.rhcloud.com logs]\> ls
access_log-20120706-000000-EST	error_log-20120706-000000-EST  production.log
access_log-20120707-000000-EST	error_log-20120707-000000-EST
[ru19-rr331.dev.rhcloud.com logs]\> ps -ef | grep rotatelogs
502      23585 17451  0 20:11 ?        00:00:00 /usr/sbin/rotatelogs /var/lib/stickshift/458cad2821fe4311b65958225a3a75df/ruby-1.9/logs/error_log-%Y%m%d-%H%M%S-%Z 86400
502      23586 17451  0 20:11 ?        00:00:00 /usr/sbin/rotatelogs /var/lib/stickshift/458cad2821fe4311b65958225a3a75df/ruby-1.9/logs/access_log-%Y%m%d-%H%M%S-%Z 86400
502      26980 17693  0 20:16 ?        00:00:00 grep rotatelogs
[ru19-rr331.dev.rhcloud.com logs]\> lsof -n -P -p 23585 | grep error_log
rotatelog 23585 458cad2821fe4311b65958225a3a75df    3w   REG 202,66     3059  135463 /var/lib/stickshift/458cad2821fe4311b65958225a3a75df/ruby-1.9/logs/error_log-20120707-000000-EST

Its writing to the next day's log file. Seems to be an apache issue.
Comment 3 Ram Ranganathan 2012-07-06 20:33:34 EDT
Aah, okay -- looks like apache is by default rotating the logs at GMT/UTC ... 4 hours ahead of EST.  So we'd have to use the UTC date-time in the message we print out for dump logs (for both ruby-1.8 and ruby-1.9).


Fixed ruby-1.8 and ruby-1.9 cartridges with git commit aa1b1954dce5ec933755fd284da79c444fcfb908. 

To test - run between 20:01 and 23:59 EST (US eastern standard time) -- that's the 4 hr window where the log file is rolled over to the next day (@GMT).
Comment 4 Meng Bo 2012-07-09 23:16:41 EDT
Checked this issue with rhc-0.95.11, both ruby-1.8 and ruby-1.9 print out the correct log name now.

Tested this on 11:10 CST (23:10 EDT).

Issue fixed.

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