Strange server.log behavior

[llecras]

Hello,

I am facing problems with my jboss 5.1.0 server.log file.

Everything is going well until my server.log is archived and renamed by server.log.2010.01.XX

At this point, a new server.log file is created and my old file changes. Everything in this file is replaced by the following section repeated n times:

2010-01-12 00:15:45,822 WARN  [org.jboss.system.server.profileservice.hotdeploy.HDScanner] (HDScanner) Scan failed
java.io.IOException: Error listing files: /home/appli/jboss-5.1.0.GA/server/default/tmp/3j001-itksji-g239nreo-1-g239nx8v-v/admin-console.war
        at org.jboss.virtual.plugins.context.file.FileHandler.getChildren(FileHandler.java:225)
        at org.jboss.virtual.plugins.context.AbstractVFSContext.getChildren(AbstractVFSContext.java:219)
        at org.jboss.virtual.plugins.context.AbstractVFSContext.visit(AbstractVFSContext.java:336)
        at org.jboss.virtual.plugins.context.AbstractVFSContext.visit(AbstractVFSContext.java:306)
        at org.jboss.virtual.VFS.visit(VFS.java:421)
        at org.jboss.virtual.VirtualFile.visit(VirtualFile.java:437)
        at org.jboss.deployers.vfs.spi.structure.modified.SynchWrapperModificationChecker.hasStructureBeenModifed(SynchWrapperModificationChecker.java:90)
        at org.jboss.deployers.vfs.spi.structure.modified.AbstractStructureModificationChecker.hasStructureBeenModified(AbstractStructureModificationChecker.java:195)
        at org.jboss.deployers.vfs.spi.structure.modified.AbstractStructureModificationChecker.hasStructureBeenModified(AbstractStructureModificationChecker.java:138)
        at org.jboss.system.server.profileservice.repository.HotDeploymentRepository.getModifiedDeployments(HotDeploymentRepository.java:120)
        at org.jboss.system.server.profile.repository.AbstractProfile.getModifiedDeployments(AbstractProfile.java:128)
        at org.jboss.system.server.profileservice.hotdeploy.HDScanner.scan(HDScanner.java:336)
        at org.jboss.system.server.profileservice.hotdeploy.HDScanner.run(HDScanner.java:255)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
        at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:317)
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:150)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:98)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:181)
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:205)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)

Any idea?

Many thanks.

[jaikiran]

Are you sure both these events are related? I mean, do you see these WARN message in the previous log file before rotation? Also does this happen if you configure the server.log file to be a size based rolling file appender instead of daily rolling file appender (see JBOSS_HOME/server/<servername>/conf/jboss-log4j.xml contents for example)?

[llecras]

Yes these events are related.

Before the log file rotation, the server.log is clean.

After the rotation, I lost my logs and the file contains a succession of the warn message posted before.

This file continues to grow at the frequence of a new message every 5 secondes...

I have not tried a size based rolling file appender yet. I will see if I can try that.

[dmlloyd]

llecras wrote:

Yes these events are related.

Before the log file rotation, the server.log is clean.

After the rotation, I lost my logs and the file contains a succession of the warn message posted before.

This file continues to grow at the frequence of a new message every 5 secondes...

I have not tried a size based rolling file appender yet. I will see if I can try that.

You say "after the rotation, I lost my logs...", are you saying that the rotated server.log.2010.01.XX file is empty or changed somehow?

[llecras]

Yes, at rotation time, something goes wrong and I lost my logs for the previous day.

A new server.log is created, which is normal.

But a new server.log.2010.01.XX is created empty. This file is then filled by the HDScanner error every 5 secondes...

[dmlloyd]

Can you paste your log appender configuration?

[llecras]

<!-- A time/date based rolling appender -->
   <appender name="FILE" class="org.jboss.logging.appender.DailyRollingFileAppender">
      <errorHandler class="org.jboss.logging.util.OnlyOnceErrorHandler"/>
      <param name="File" value="/var/log/appli/server.log"/>
      <param name="Append" value="true"/>
      <!--
         Set the threshold via a system property. Note this is parsed by log4j,
         so the full JBoss system property format is not supported; e.g.
         setting a default via ${jboss.server.log.threshold:WARN} will not work.
       -->
      <param name="Threshold" value="DEBUG"/>

      <!-- Rollover at midnight each day -->
      <param name="DatePattern" value="'.'yyyy-MM-dd"/>

      <!-- Rollover at the top of each hour
      <param name="DatePattern" value="'.'yyyy-MM-dd-HH"/>
      -->

      <layout class="org.apache.log4j.PatternLayout">
         <!-- The default pattern: Date Priority [Category] (Thread) Message\n -->
         <param name="ConversionPattern" value="%d %-5p [%c] (%t) %m%n"/>

         <!-- The full pattern: Date MS Priority [Category] (Thread:NDC) Message\n
         <param name="ConversionPattern" value="%d %-5r %-5p [%c] (%t:%x) %m%n"/>
          -->
      </layout>
   </appender>

[dmlloyd]

I don't see anything unusual or problematic in your configuration.  Just to clarify though, the expected behavior is that every day, "server.log" is closed and renamed to "server.log.2010-01-XX" (note the hyphens, not the dots) and a brand new, empty file will become the new "server.log".  Clearly the HDScanner message is a different issue, which happens to trigger the log rotation (which occurs when the first message is logged from the next day in your case).  So as far as logging is concerned, the "correct result" would be a series of files filled with this log message at 5 second intervals.  The original logs would only exist at the start of the file from the first day the server was up, assuming no other messages are logged.

If you're seeing files named "server.log.2010.01.XX" (note the dots, not hyphens) then you've got another log rotation program fighting for the privilege of rotating the logs, which explains the discrepancy that you are perceiving.  Otherwise, I'm not sure I understand what the problem is.

[llecras]

My log files are named like server.log.2010-01-XX (hyphens, not dots).

Sorry, I made a mistake in my previous posts.

I think I will try to deactivate the HDScanner temporarily...

[sbommala]

Hello,

I am having the exact same problem.  Is there a solution/workaround for this?

[llecras]

Hello,

I just found the cause of that problem.

In fact I had a jboss process that did not stop correctly, and I restart a new process.

So I had 2 jboss processes running. When I killed the old one, it corrects the log problem.

I hope it will help...

[sbommala]

Thanks much for your response.  I was able to find few hung processes and killed them all.