0

I have a jar that is called about every minute from another script. In this jar I have created a JavaLogger that logs what happens while the Jar runs. The log file that JavaLogger writes to is called myLog.0. I have the following code to allow it to go to .1/.2/.3/.4.

try {
  FileHandler fileHandler = new FileHandler(filePath, 5242880, 5, true);
  fileHandler.setFormatter(new java.util.logging.Formatter() {
    @Override
    public String format(LogRecord logRecord) {
      return "[" + logRecord.getLevel() + " " + createDateTimeLog() + "]  " + logRecord.getMessage() + "\r\n";
    }
  });
  logger.addHandler(fileHandler);
} catch (IOException e) {}

So I expect the logs to grow. However, every once and a while the log will print to myLog.0.1. I would guess that this is because the file is locked. However, this never happens mid-run of my jar. It logs to .0.1 the entire time the jar runs. Could the file still be locked from my previous run?

If so I have even tried to close the handler before the Jar exits. There is only one exit point from the jar and I put the following code right before it:

MyLogger.logger.getHandlers()[0].close();

I have run this through the debugger and there is only ever one handler (the FileHandler that I add).

As I said, this only happens randomly. The first 3 runs of the jar could be to .0 and then the fourth to .0.1. Then the next 10 could be correct again. It's hard to say. However it does happen fairly often (I would say it writes to .0.1 about every 1/8 of the time).

Any ideas / suggestions would be great. Thanks ahead of time.

dev
  • 1,477
  • 5
  • 18
  • 43

1 Answers1

1

Could the file still be locked from my previous run?

Could be that two JVMs are running your jar at the same time. Add code to grab the RuntimeMXBean and then add a single log statement to record the runtime name and the start time. The runtime name usually maps to a process id and a host name.

The FileHandler does everything it can to prevent two concurrently running JVMs from writing to the same log file. If this behavior was allowed the log file would be almost impossible to read and understand.

If you really want to write everything to one log file then you have to do one of the following:

  1. Prevent concurrent JVM processes from starting by changing how it is launched.
  2. Have your code detect if another JVM is running your code and exit before creating a FileHandler.
  3. Have each JVM write to a distinct log file and create code to safely merge the files into one.
  4. Create a proxy Handler that creates and closes a FileHandler for each log record. The proxy handler would use a predefined file name (different from the log file) and a FileLock to serialize access to the log file from different JVMs.
  5. Use a dedicated process to write to the log file and have all the JVMs send log messages to that process.
jmehrens
  • 10,580
  • 1
  • 38
  • 47
  • Sorry for the late response. I had to move on with the project and didn't have time to revisit this until now. Anyway, you seem to be correct about this. I have multiple instances of the jar running all at once. Then when they try to access the log, it is locked and they write to .0, .1, etc. I considered using a file lock (java.nio.channels). However I cannot seem to get it to work with the log file. Any ideas on where I should go from here? – dev Feb 11 '14 at 20:12
  • I updated the answer. If you need concurrent JVMs then the proxy handler is the way to go. I can include some example code if you need it. – jmehrens Feb 11 '14 at 23:23