cron logrotation fail on existing files

Bug #1614536 reported by Simon Déziel
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
tomcat7 (Ubuntu)
New
Undecided
Unassigned

Bug Description

We keep receiving cron messages from our tomcat machines:

/etc/cron.daily/tomcat7:
gzip: /var/log/tomcat7/lnhpd-catalina.2016-08-15.log.gz already exists; not overwritten

And when looking at /var/log/tomcat7:

# ll /var/log/tomcat7/lnhpd-catalina.2016-08-15.*
-rw-r--r-- 1 tomcat7 tomcat7 143355 Aug 17 08:22 /var/log/tomcat7/lnhpd-catalina.2016-08-15.log
-rw-r--r-- 1 tomcat7 tomcat7 10605 Aug 15 23:56 /var/log/tomcat7/lnhpd-catalina.2016-08-15.log.gz

We notice the uncompressed file was created on Aug 17th despite what the date embedded in the file name says. On Aug 17th, at 8:22, the tomcat7 service was manually restarted due to security update to OpenJDK-7. This seems to have trigger the problematic behavior.

The first entry in the newly created is from the 17th:

# head -1 /var/log/tomcat7/lnhpd-catalina.2016-08-15.log
2016-08-17 00:11:40,179 [http-bio-8080-exec-8] INFO ca.gc.hc.util.ApplicationGlobals- Initializing Localization to en_CA

And if we look at the last entry of the previous day:

# zcat /var/log/tomcat7/lnhpd-catalina.2016-08-16.log.gz | tail -1
2016-08-16 23:55:57,185 [http-bio-8080-exec-10] WARN org.apache.struts.util.PropertyMessageResources- Resource resources/ApplicationResources_fr_CA.properties Not Found.

So both files have consecutive log entries but the newly created file has the wrong date embedded in its name.

Having tomcat reusing old dates for new files causes problem later on when the cron job tries to compress old logs and trip on existing files. This is what generates the cron emails.

Additional information on the machine:

# lsb_release -rd
Description: Ubuntu 14.04.5 LTS
Release: 14.04

# apt-cache policy tomcat7 openjdk-7-jre-headless
tomcat7:
  Installed: 7.0.52-1ubuntu0.6
  Candidate: 7.0.52-1ubuntu0.6
  Version table:
 *** 7.0.52-1ubuntu0.6 0
        500 http://archive.ubuntu.com/ubuntu/ trusty-updates/main amd64 Packages
        500 http://security.ubuntu.com/ubuntu/ trusty-security/main amd64 Packages
        100 /var/lib/dpkg/status
     7.0.52-1 0
        500 http://archive.ubuntu.com/ubuntu/ trusty/main amd64 Packages
openjdk-7-jre-headless:
  Installed: 7u111-2.6.7-0ubuntu0.14.04.3
  Candidate: 7u111-2.6.7-0ubuntu0.14.04.3
  Version table:
 *** 7u111-2.6.7-0ubuntu0.14.04.3 0
        500 http://archive.ubuntu.com/ubuntu/ trusty-updates/main amd64 Packages
        500 http://security.ubuntu.com/ubuntu/ trusty-security/main amd64 Packages
        100 /var/lib/dpkg/status
     7u51-2.4.6-1ubuntu4 0
        500 http://archive.ubuntu.com/ubuntu/ trusty/main amd64 Packages

ProblemType: Bug
DistroRelease: Ubuntu 14.04
Package: tomcat7 7.0.52-1ubuntu0.6
ProcVersionSignature: Ubuntu 3.13.0-93.140-generic 3.13.11-ckt39
Uname: Linux 3.13.0-93-generic x86_64
ApportVersion: 2.14.1-0ubuntu3.21
Architecture: amd64
Date: Thu Aug 18 09:20:02 2016
PackageArchitecture: all
ProcEnviron:
 TERM=xterm
 PATH=(custom, no user)
 LANG=en_CA.UTF-8
 SHELL=/bin/bash
SourcePackage: tomcat7
UpgradeStatus: No upgrade log present (probably fresh install)
modified.conffile..etc.tomcat7.server.xml: [modified]
modified.conffile..etc.tomcat7.tomcat.users.xml: [modified]
mtime.conffile..etc.tomcat7.server.xml: 2016-08-15T10:35:37.546984
mtime.conffile..etc.tomcat7.tomcat.users.xml: 2016-01-26T13:16:49.046413

Revision history for this message
Simon Déziel (sdeziel) wrote :
Revision history for this message
Simon Déziel (sdeziel) wrote :

To silence the cron messages, an easy workaround is to disable log compression in /etc/default/tomcat7 by setting "LOGFILE_COMPRESS=0". This will bypass the problematic section of /etc/cron.daily/tomcat7.

I check the cron job from tomcat8 and it is identical so maybe the problem also affects it. It all depends if the fresh logs can still be created with old dates embedded in their names or not.

Revision history for this message
Simon Déziel (sdeziel) wrote :

What's weird is that old dates are not always reused:

# date
Thu Aug 18 09:17:56 EDT 2016

# service tomcat7 restart
 * Stopping Tomcat servlet engine tomcat7 [ OK ]
 * Starting Tomcat servlet engine tomcat7 [ OK ]

# ll -tr /var/log/tomcat7/
...
-rw-r--r-- 1 tomcat7 tomcat7 139590 Aug 18 09:16 sptt-catalina
-rw-r--r-- 1 tomcat7 tomcat7 101 Aug 18 09:17 lnhpd-catalina
-rw-r--r-- 1 tomcat7 tomcat7 145076 Aug 18 09:17 rtbd_access.2016-08-18.log
-rw-r--r-- 1 tomcat7 tomcat7 159354 Aug 18 09:17 lnhpd-catalina.2016-08-17.log
-rw-r--r-- 1 tomcat7 tomcat7 0 Aug 18 09:17 localhost.2016-08-18.log
-rw-r--r-- 1 tomcat7 adm 38205 Aug 18 09:17 catalina.out
-rw-r--r-- 1 tomcat7 tomcat7 4201 Aug 18 09:17 catalina.2016-08-18.log

Here, only lnhpd-catalina.2016-08-17.log has the wrong date, the others are fine.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.