Bug 889751 - engine: engine log have same time on all the rotated logs from the same date
engine: engine log have same time on all the rotated logs from the same date
Status: CLOSED CURRENTRELEASE
Product: Red Hat Enterprise Virtualization Manager
Classification: Red Hat
Component: ovirt-engine (Show other bugs)
3.1.0
x86_64 Linux
unspecified Severity high
: ---
: 3.2.0
Assigned To: Ofer Schreiber
Dušan Kajan
integration
:
Depends On:
Blocks: 915537
  Show dependency treegraph
 
Reported: 2012-12-23 04:51 EST by Dafna Ron
Modified: 2014-03-30 21:26 EDT (History)
10 users (show)

See Also:
Fixed In Version: sf15
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:


Attachments (Terms of Use)


External Trackers
Tracker ID Priority Status Summary Last Updated
oVirt gerrit 14097 None None None Never

  None (edit)
Description Dafna Ron 2012-12-23 04:51:52 EST
Description of problem:

I am trying to debug something on qa production and I was trying to locate a log from a specific day and time. 
looking at the logs I can see several logs from the same day - all having the same time: 

-rw-r--r--. 1 root  root    481604 Dec 20 03:29 engine.log.1-20121220_03.gz
-rw-r--r--. 1 root  root    476656 Dec 20 03:29 engine.log.2-20121220_03.gz
-rw-r--r--. 1 root  root    523856 Dec 20 03:29 engine.log.3-20121220_03.gz
-rw-r--r--. 1 root  root    537812 Dec 20 03:29 engine.log.4-20121220_03.gz
-rw-r--r--. 1 root  root    544682 Dec 20 03:29 engine.log.5-20121220_03.gz
-rw-r--r--. 1 root  root    525419 Dec 20 03:29 engine.log.6-20121220_03.gz
-rw-r--r--. 1 root  root    478257 Dec 20 03:29 engine.log.7-20121220_03.gz
-rw-r--r--. 1 root  root    480262 Dec 20 03:29 engine.log.8-20121220_03.gz

this is present for all other logs. each day has the same time on all logs rotated on that day. 

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

upgraded from 3.0 to si25.1

How reproducible:


Steps to Reproduce:
1. cd /var/log/ovirt-engine/
2. ls -ltr
3.
  
Actual results:

-rw-r--r--. 1 root  root    481604 Dec 20 03:29 engine.log.1-20121220_03.gz
-rw-r--r--. 1 root  root    476656 Dec 20 03:29 engine.log.2-20121220_03.gz
-rw-r--r--. 1 root  root    523856 Dec 20 03:29 engine.log.3-20121220_03.gz
-rw-r--r--. 1 root  root    537812 Dec 20 03:29 engine.log.4-20121220_03.gz
-rw-r--r--. 1 root  root    544682 Dec 20 03:29 engine.log.5-20121220_03.gz
-rw-r--r--. 1 root  root    525419 Dec 20 03:29 engine.log.6-20121220_03.gz
-rw-r--r--. 1 root  root    478257 Dec 20 03:29 engine.log.7-20121220_03.gz
-rw-r--r--. 1 root  root    480262 Dec 20 03:29 engine.log.8-20121220_03.gz

Expected results:

each log should show the time it rotated on

Additional info:

-rw-r--r--. 1 root  root    479308 Dec 19 03:21 engine.log.1-20121219_03.gz
-rw-r--r--. 1 root  root    483234 Dec 19 03:21 engine.log.2-20121219_03.gz
-rw-r--r--. 1 root  root    483387 Dec 19 03:21 engine.log.3-20121219_03.gz
-rw-r--r--. 1 root  root    490203 Dec 19 03:21 engine.log.4-20121219_03.gz
-rw-r--r--. 1 root  root    509099 Dec 19 03:21 engine.log.5-20121219_03.gz
-rw-r--r--. 1 root  root    476059 Dec 19 03:21 engine.log.6-20121219_03.gz
-rw-r--r--. 1 root  root    474438 Dec 19 03:21 engine.log.7-20121219_03.gz
-rw-r--r--. 1 ovirt ovirt 10485954 Dec 19 04:45 server.log.7
-rw-r--r--. 1 ovirt ovirt 10485797 Dec 19 10:39 server.log.6
-rw-r-----. 1 ovirt ovirt   569327 Dec 19 12:35 console.log
-rw-r--r--. 1 ovirt ovirt      704 Dec 19 14:20 boot.log
-rw-r--r--. 1 ovirt ovirt 10485897 Dec 19 16:28 server.log.5
-rw-r--r--. 1 ovirt ovirt 10485843 Dec 19 21:35 server.log.4
-rw-r--r--. 1 ovirt ovirt 10485774 Dec 20 03:27 server.log.3
-rw-r--r--. 1 root  root    481604 Dec 20 03:29 engine.log.1-20121220_03.gz
-rw-r--r--. 1 root  root    476656 Dec 20 03:29 engine.log.2-20121220_03.gz
-rw-r--r--. 1 root  root    523856 Dec 20 03:29 engine.log.3-20121220_03.gz
-rw-r--r--. 1 root  root    537812 Dec 20 03:29 engine.log.4-20121220_03.gz
-rw-r--r--. 1 root  root    544682 Dec 20 03:29 engine.log.5-20121220_03.gz
-rw-r--r--. 1 root  root    525419 Dec 20 03:29 engine.log.6-20121220_03.gz
-rw-r--r--. 1 root  root    478257 Dec 20 03:29 engine.log.7-20121220_03.gz
-rw-r--r--. 1 root  root    480262 Dec 20 03:29 engine.log.8-20121220_03.gz
-rw-r--r--. 1 ovirt ovirt 10485780 Dec 20 09:20 server.log.2
-rw-r--r--. 1 root  root   3143680 Dec 20 13:12 engine-logs.tar
-rw-r--r--. 1 ovirt ovirt 10485947 Dec 20 15:00 server.log.1
-rw-r--r--. 1 root  root    510573 Dec 21 03:33 engine.log.1-20121221_03.gz
-rw-r--r--. 1 root  root    520469 Dec 21 03:33 engine.log.2-20121221_03.gz
-rw-r--r--. 1 root  root    480828 Dec 21 03:33 engine.log.3-20121221_03.gz
-rw-r--r--. 1 root  root    483329 Dec 21 03:33 engine.log.4-20121221_03.gz
-rw-r--r--. 1 root  root    475468 Dec 21 03:33 engine.log.5-20121221_03.gz
-rw-r--r--. 1 root  root    472511 Dec 21 03:33 engine.log.6-20121221_03.gz
-rw-r--r--. 1 root  root    502358 Dec 22 03:21 engine.log.1-20121222_03.gz
-rw-r--r--. 1 root  root    527305 Dec 22 03:21 engine.log.2-20121222_03.gz
-rw-r--r--. 1 root  root    502447 Dec 22 03:21 engine.log.3-20121222_03.gz
-rw-r--r--. 1 root  root    503340 Dec 22 03:21 engine.log.4-20121222_03.gz
-rw-r--r--. 1 root  root    502269 Dec 22 03:21 engine.log.5-20121222_03.gz
-rw-r--r--. 1 root  root   1471949 Dec 23 00:01 ovirt-engine-dwhd.log
-rw-r--r--. 1 root  root    498948 Dec 23 03:41 engine.log.1-20121223_03.gz
-rw-r--r--. 1 root  root    498729 Dec 23 03:41 engine.log.2-20121223_03.gz
-rw-r--r--. 1 root  root    503384 Dec 23 03:41 engine.log.3-20121223_03.gz
-rw-r--r--. 1 root  root    502448 Dec 23 03:41 engine.log.4-20121223_03.gz
-rw-r--r--. 1 root  root    503645 Dec 23 03:41 engine.log.5-20121223_03.gz
-rw-r--r--. 1 root  root    503695 Dec 23 03:41 engine.log.6-20121223_03.gz
Comment 3 Simon Grinberg 2012-12-25 10:51:48 EST
Modification time has too change, since when you rotate you change all the files. At the rotation point: 

.logN is renamed to log.N+1
.
.
.log2 is renamed to log.3
.log1 is renamed to log.2
.log is renamed to log.1
new .log is created. 

So ls -ltr has to change due to the fact this is probably done with mv. 

What I fail to understand is why the time stamp in the file name the same, it was most likely introduced to overcome the above and provide indication on the actual date the file was first rotated from .log to .log.n.zip. But instead it is modified to the last rotation time for all files. 

This should be fixed.
Comment 4 Simon Grinberg 2012-12-25 10:58:15 EST
Looking at bug 889796 the said above is not accurate, it looks like the rotation itself does not have to lead to the same time on all the files.
Comment 5 Yaniv Kaul 2012-12-25 11:10:42 EST
Simon, look at /usr/share/ovirt-engine/scripts/ovirtlogrot.sh and you'll understand why they all have the same exact timestamp:

dateformat="+%Y%m%d_%H"

date=`date $dateformat`

for i in `ls $logdir/engine.log.* -t`; do
 m=`expr match $i .*gz`
 if [ $m == 0 ]
 then
  cat $i | gzip -9 > $i-$date.gz && rm $i
 fi
done;


Probably better changed to something like:

dateformat="+%Y%m%d_%H%M%S"

for i in `ls $logdir/engine.log.* -t`; do
 m=`expr match $i .*gz`
 if [ $m == 0 ]
 then
  date=`date $dateformat`
  cat $i | gzip -9 > $i-$date.gz && rm $i
 fi
done;
Comment 6 Simon Grinberg 2012-12-25 12:12:43 EST
(In reply to comment #5)
The suggested code which provides a better granularity on the time the script actually started the zip will not solve the issue -> you will now have the order the files where zipped, not more then that. 

What the script needs to do it to take the original creation date of $i (the compressed file) and use it as the $date for the zipped file. 
Something like: 
    date=$(stat -c %y $i)
And remove the white spaces
Comment 7 Yaniv Kaul 2012-12-25 15:24:55 EST
Not sure what further information is requested from me.
Comment 8 Kiril Nesenko 2013-01-09 07:11:31 EST
Patch is posted for review: http://gerrit.ovirt.org/#/c/10810/
Comment 10 Kiril Nesenko 2013-01-10 05:33:42 EST
Patch is posted for review: http://gerrit.ovirt.org/#/c/10846/
Comment 12 Dušan Kajan 2013-03-28 10:16:20 EDT
FailedQA - sf11
On clean setup there are NO "engine|jasperserver|server.log.*" files yet. So 'if' condition is skipped.

"engine.log.*" doesn't match "engine.log"



[root@myserver]# /etc/cron.daily/ovirt-cron
ls: cannot access /var/log/ovirt-engine/engine.log.*: No such file or directory
ls: cannot access /var/log/ovirt-engine/server.log.*: No such file or directory
ls: cannot access /var/log/ovirt-engine/jasperserver.log.*: No such file or directory
ls: cannot access /var/log/ovirt-engine/engine.log.*.gz: No such file or directory
ls: cannot access /var/log/ovirt-engine/engine.log.*.xz: No such file or directory
ls: cannot access /var/log/ovirt-engine/server.log.*.gz: No such file or directory
ls: cannot access /var/log/ovirt-engine/server.log.*.xz: No such file or directory
ls: cannot access /var/log/ovirt-engine/jasperserver.log.*.gz: No such file or directory
ls: cannot access /var/log/ovirt-engine/jasperserver.log.*.xz: No such file or directory
Comment 13 Itamar Heim 2013-06-11 05:24:05 EDT
3.2 has been released
Comment 14 Itamar Heim 2013-06-11 05:45:05 EDT
3.2 has been released

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