11 Replies Latest reply on Jan 22, 2010 10:47 AM by sukumar bommala

    Strange server.log behavior

    Ludovic Lecras Newbie

      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.

        • 1. Re: Strange server.log behavior
          jaikiran pai Master

          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)?

          • 2. Re: Strange server.log behavior
            Ludovic Lecras Newbie

            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.
            • 3. Re: Strange server.log behavior
              David Lloyd Master

              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?

              • 4. Re: Strange server.log behavior
                Ludovic Lecras Newbie

                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...

                • 5. Re: Strange server.log behavior
                  David Lloyd Master
                  Can you paste your log appender configuration?
                  • 6. Re: Strange server.log behavior
                    Ludovic Lecras Newbie
                    <!-- 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>
                    • 7. Re: Strange server.log behavior
                      David Lloyd Master

                      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.

                      • 8. Re: Strange server.log behavior
                        Ludovic Lecras Newbie

                        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...

                        • 9. Re: Strange server.log behavior
                          sukumar bommala Newbie

                          Hello,

                           

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

                          • 10. Re: Strange server.log behavior
                            Ludovic Lecras Newbie

                            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...

                            • 11. Re: Strange server.log behavior
                              sukumar bommala Newbie

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