Bug 837468

Summary:	time sync issue for rhc app threaddump log
Product:	OKD	Reporter:	Meng Bo <bmeng>
Component:	Containers	Assignee:	Ram Ranganathan <ramr>
Status:	CLOSED CURRENTRELEASE	QA Contact:	libra bugs <libra-bugs>
Severity:	medium	Docs Contact:
Priority:	medium
Version:	2.x	CC:	mfisher, rmillner, xtian
Target Milestone:	---	Keywords:	Triaged
Target Release:	---
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2012-07-13 23:43:26 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Meng Bo 2012-07-04 03:16:47 UTC

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 04:28:06 UTC

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-07 00:19:18 UTC

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-07 00:33:34 UTC

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-10 03:16:41 UTC

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.