[ZBX-9290] re-read of the log in logrt (RollingFileAppender of log4j) Created: 2015 Feb 09  Updated: 2017 May 30  Resolved: 2015 May 27

Status: Closed
Project: ZABBIX BUGS AND ISSUES
Component/s: Agent (G)
Affects Version/s: 2.2.8
Fix Version/s: 2.0.15rc1, 2.2.10rc1, 2.4.6rc1, 2.5.0

Type: Incident report Priority: Trivial
Reporter: Kazuo Ito Assignee: Unassigned
Resolution: Fixed Votes: 1
Labels: logging, rotation
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

zabbix-server2.2.3
zabbix-agent2.2.8


Issue Links:
Duplicate

 Description   

Is not restarted zabbix_server and zabbix_agent, but was re-read of the log in logrt.

I think log4j update only file mtime without any modification when it rotates log files.



 Comments   
Comment by Kazuo Ito [ 2015 Feb 09 ]

src/zabbix_agent/logfiles.c is_same_file

	if (old->size > new->size)
	{
		/* File's size cannot decrease. Truncating or replacing a file with a smaller one */
		/* counts as 2 different files. */
		goto out;
	}

	if (old->size == new->size && old->mtime < new->mtime)   <------ here
	{
		/* File's mtime cannot increase without changing size unless manipulated. */
		goto out;
	}

log4j to close the current file in the rotation. - this.closeFile()

log4j-1.2.17 RollingFileAppender.java

  public // synchronization not necessary since doAppend is alreasy synched
  void rollOver() {
    File target;
    File file;

    if (qw != null) {
        long size = ((CountingQuietWriter) qw).getCount();
        LogLog.debug("rolling over count=" + size);
        //   if operation fails, do not roll again until
        //      maxFileSize more bytes are written
        nextRollover = size + maxFileSize;
    }
    LogLog.debug("maxBackupIndex="+maxBackupIndex);

    boolean renameSucceeded = true;
    // If maxBackups <= 0, then there is no file renaming to be done.
    if(maxBackupIndex > 0) {
      // Delete the oldest file, to keep Windows happy.
      file = new File(fileName + '.' + maxBackupIndex);
      if (file.exists())
       renameSucceeded = file.delete();

      // Map {(maxBackupIndex - 1), ..., 2, 1} to {maxBackupIndex, ..., 3, 2}
      for (int i = maxBackupIndex - 1; i >= 1 && renameSucceeded; i--) {
	file = new File(fileName + "." + i);
	if (file.exists()) {
	  target = new File(fileName + '.' + (i + 1));
	  LogLog.debug("Renaming file " + file + " to " + target);
	  renameSucceeded = file.renameTo(target);
	}
      }

    if(renameSucceeded) {
      // Rename fileName to fileName.1
      target = new File(fileName + "." + 1);

      this.closeFile(); // keep windows happy.   <--------- here

      file = new File(fileName);
      LogLog.debug("Renaming file " + file + " to " + target);
      renameSucceeded = file.renameTo(target);
      //
      //   if file rename failed, reopen file with append = true
      //
      if (!renameSucceeded) {
          try {
            this.setFile(fileName, true, bufferedIO, bufferSize);
          }
          catch(IOException e) {
              if (e instanceof InterruptedIOException) {
                  Thread.currentThread().interrupt();
              }
              LogLog.error("setFile("+fileName+", true) call failed.", e);
          }
      }
    }
    }
Comment by Andris Mednis [ 2015 Feb 13 ]

"File's mtime cannot increase without changing size" was a design choice based on Linux observation - if 0 bytes are written into logfile, mtime does not change. "If not sure report it twice" seemed a better choice than "in rare cases we may silently skip unanalyzed data to avoid duplicate alerts". We were not aware of log4j specific. A workaround is to comment out this check and recompile.

Comment by Igors Homjakovs (Inactive) [ 2015 May 07 ]

Fixed in svn://svn.zabbix.com/branches/dev/ZBX-9290

Comment by Igors Homjakovs (Inactive) [ 2015 May 07 ]

When a file is edited its mtime and size are not updated simultaneously. On my Ubuntu Linux machine with ext4 file system the mtime is always updated first. If Zabbix checks the status of a log file between that interval then it will be assumed that log file rotation has occurred and the content of the log file will be re-read.

In the proposed fix if mtime increases, but the size stays constant, the status of the file will be read again on the next item check.

Comment by Andris Zeila [ 2015 May 11 ]

(1) The 'retry' flag should be file based, rather than function variable. The is_same_file() function might be called for different file next time, resetting the flag.

igorsh RESOLVED in r53624.

wiper changed the implementation slightly, added comments, improved log messages.
please review r53701

igorsh CLOSED.

Comment by Igors Homjakovs (Inactive) [ 2015 May 25 ]

Available in 2.0.15rc1 r53772, 2.2.10rc1 r53774, 2.4.6rc1 r53777 and 2.5.0 (trunk) r53778

Generated at Tue Apr 16 22:34:49 EEST 2024 using Jira 9.12.4#9120004-sha1:625303b708afdb767e17cb2838290c41888e9ff0.