Red Hat Bugzilla – Bug 837468
time sync issue for rhc app threaddump log
Last modified: 2015-05-14 18:56:17 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:
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
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.
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).
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.