Re: [Wrapper-user] Logging randomly just "stops"

SourceForge Headquarters 1320 Columbia Street Suite 310 San Diego, CA 92101 +1 (858) 422-6466

Bill,
> When the application is in a state where it has stopped logging, are
> you running a service or in console mode?

We are running it as a service, on a Windows 2003 Server box, an HP Dual-core AMD Opteron, 2.6GHz, with 2GB RAM.  Win 2K3 Server R2 Standard Edition with Service Pack 2.

> If possible can you reproduce this running in console mode?  I am
> assuming for now you are running on windows.

I'll have to bump that up the chain of command and see if it will be allowed.  I do not have physical access to the server.

> 1) When in the stopped state, can you request a thread dump by pressing
> CTRL-BREAK?   If you see the dump, then the Wrapper process is
> correctly receiving and logging output from the Java process.

I'll see if that's possible for me to do (since I don't have direct access to the machine).

> 2) As an alternative to the thread dump, simply start the shutdown
> process.  If you see more log entries then once again things are
> working on the Wrapper side.

I'll keep an eye on that and see if I can look back through the logs and find one of these occurrences to see if when we run the batch script that shuts down the service the messages from Wrapper get logged or not.

Wrapper is running a Mule ESB Server process that we shutdown and switch between two configuration files for daytime and evening processing tasks at about 1:30 am and 4:30pm.

In looking at recent log files, the problem seems to happen EVERY day after we do the 1:30 am switch; it processes a boatload of transactions and at some point writing to the log just stops happening.   Then about 4:30 when the service is stopped, the config files for the Mule ESB Server are switched to evening processing and the service is started, we do get some Wrapper messages....but not the Mule shutdown messages.  Here's an example:

Here's the log entries centered around the 16:30 shutdown and restart of the service:

2008/07/08 01:03:44.824 | jvm 1    | INFO   | INFO|EmailNotification.send(82)| Adding rk...@dh... to email
2008/07/08 01:03:44.824 | jvm 1    | INFO   | INFO|EmailNotification.send(82)| Adding BC...@dh... to email
2008/07/08 01:03:44.824 | jvm 1    | INFO   | INFO|EmailNotification.send(82)| Adding BC...@dh... to email
2008/07/08 01:03:46.684 | jvm 1    | INFO   | INFO|AMSVendorExporter.exportSubmission(148)| Submission with id of 637 has finished exporting
2008/07/08 01:03:49.965 | jvm 1    | INFO   | INFO|EmailNotification.send(116)| The following email was sent on 07/08/2008 01:03:49
2008/07/08 01:03:49.965 | jvm 1    | INFO   | INFO|EmailNotification.send(116)| The following email was sent on 07/08/2008 01:03:49
2008/07/08 01:03:49.965 | jvm 1    | INFO   | INFO|EmailNotification.send(118)| Notification Type: gov.iowa.das.ite.i3.conversion.notification.PartialLoadNotification
2008/07/08 01:03:49.965 | jvm 1    | INFO   | INFO|EmailNotification.send(118)| Notification Type: gov.iowa.das.ite.i3.conversion.notification.PartialLoadNotification
2008/07/08 01:03:49.965 | jvm 1    | INFO   | INFO|EmailNotification.send(119)| Recipients: jw...@dh... mp...@dh... Tai...@io... les...@io... rk...@dh... BC...@dh...
2008/07/08 01:03:49.965 | jvm 1    | INFO   | INFO|EmailNotification.send(119)| Recipients: jw...@dh... mp...@dh... Tai...@io... les...@io... rk...@dh... BC...@dh...

2008/07/08 16:30:03.454 | wrapper  | STATUS | <-- Wrapper Stopped
2008/07/08 16:31:06.014 | wrapper  | STATUS | --> Wrapper Started as Service

2008/07/08 16:31:06.233 | wrapper  | STATUS | Launching a JVM...
2008/07/08 16:31:06.780 | jvm 1    | INFO   | Wrapper (Version 3.2.3) http://wrapper.tanukisoftware.org
2008/07/08 16:31:06.780 | jvm 1    | INFO   |   Copyright 1999-2006 Tanuki Software, Inc.  All Rights Reserved.
2008/07/08 16:31:06.780 | jvm 1    | INFO   |
2008/07/08 16:31:06.780 | jvm 1    | INFO   | log4j:INFO Using URL [file:/C:/Programs/I3Gateway/classes/log4j.xml] for automatic log4j configuration of repository named [default].
2008/07/08 16:31:06.999 | jvm 1    | INFO   | AbandonedObjectPool is used (org.apache.commons.dbcp.AbandonedObjectPool@7bb290)
2008/07/08 16:31:06.999 | jvm 1    | INFO   |    LogAbandoned: true
2008/07/08 16:31:06.999 | jvm 1    | INFO   |    RemoveAbandoned: true
2008/07/08 16:31:06.999 | jvm 1    | INFO   |    RemoveAbandonedTimeout: 300
2008/07/08 16:31:08.421 | jvm 1    | INFO   | INFO|MuleManager.getInstance(280)| Creating new MuleManager instance

Here's the 1:00AM shutdown and restart (exact time floats based on evening processing tasks times):

2008/07/09 01:19:23.877 | jvm 1    | INFO   | INFO|MuleManager.disposeAgents(1348)| disposing agents...
2008/07/09 01:19:23.987 | jvm 1    | INFO   | INFO|MuleManager.disposeAgents(1355)| Agents Successfully Disposed
2008/07/09 01:19:23.987 | jvm 1    | INFO   | INFO|AbstractApplicationContext.close(500)| Closing application context [org.springframework.context.support.FileSystemXmlApplicationContext;hashCode=2221396]
2008/07/09 01:19:23.987 | jvm 1    | INFO   | INFO|AbstractBeanFactory.destroySingletons(555)| Destroying singletons in factory ....
2008/07/09 01:19:23.987 | jvm 1    | INFO   | INFO|LocalSessionFactoryBean.destroy(1028)| Closing Hibernate SessionFactory
2008/07/09 01:19:23.987 | jvm 1    | INFO   | INFO|SessionFactoryImpl.close(766)| closing
2008/07/09 01:19:23.987 | jvm 1    | INFO   | INFO|AbstractResourceManager.stop(106)| Stopping ResourceManager
2008/07/09 01:19:23.987 | jvm 1    | INFO   | INFO|AbstractResourceManager.stop(116)| Stopped ResourceManager
2008/07/09 01:19:23.987 | jvm 1    | INFO   | INFO|MuleManager.dispose(441)|

2008/07/09 01:19:23.987 | jvm 1    | INFO   | ******************************************************************************
2008/07/09 01:19:23.987 | jvm 1    | INFO   | * Mule shut down normally on: Wednesday, July 9, 2008 1:19:23 AM CDT         *
2008/07/09 01:19:23.987 | jvm 1    | INFO   | * Server was up for: 0 days, 8 hours, 48 mins, 10.347 sec                    *
2008/07/09 01:19:23.987 | jvm 1    | INFO   | ******************************************************************************
2008/07/09 01:19:24.096 | wrapper  | STATUS | <-- Wrapper Stopped
2008/07/09 01:20:26.673 | wrapper  | STATUS | --> Wrapper Started as Service

2008/07/09 01:20:26.891 | wrapper  | STATUS | Launching a JVM...
2008/07/09 01:20:27.438 | jvm 1    | INFO   | Wrapper (Version 3.2.3) http://wrapper.tanukisoftware.org
2008/07/09 01:20:27.438 | jvm 1    | INFO   |   Copyright 1999-2006 Tanuki Software, Inc.  All Rights Reserved.
2008/07/09 01:20:27.438 | jvm 1    | INFO   |
2008/07/09 01:20:27.547 | jvm 1    | INFO   | log4j:INFO Using URL [file:/C:/Programs/I3Gateway/classes/log4j.xml] for automatic log4j configuration of repository named [default].
2008/07/09 01:20:27.657 | jvm 1    | INFO   | AbandonedObjectPool is used (org.apache.commons.dbcp.AbandonedObjectPool@7bb290)
2008/07/09 01:20:27.657 | jvm 1    | INFO   |    LogAbandoned: true
2008/07/09 01:20:27.657 | jvm 1    | INFO   |    RemoveAbandoned: true
2008/07/09 01:20:27.657 | jvm 1    | INFO   |    RemoveAbandonedTimeout: 300
2008/07/09 01:20:29.079 | jvm 1    | INFO   | INFO|MuleManager.getInstance(280)| Creating new MuleManager instance

Notice the Mule shutdown message on this one that doesn't show up on the 16:30 shutdown because logging has stopped.   I've put some blank lines around these log entries to highlight them.

I can't tell if it's Wrapper that needs configuration changing, or a bug in log4j or Mule.

To stop the service, we have a Windows Scheduled task that runs a batch script that does:

 Net Stop "I3InternalESBServer"

Then switches out the settings file for morning/evening processing, waits one minuen, and then does a:

  Net Start "I3InternalESBServer"

> 3) Make sure you are seeing the log entries both in the Console and the
> Log file.  If they are only showing up in the Console then that would
> point to a problem writing to the log file.

Again, I'll see if that is going to be allowed, but thanks for the tip.

> 4) At the point that the logging stops, how large is the wrapper.log
> file?  I assume you have plenty of disk space.

We have the log file size set to 1 MB before it starts a new one.   We have over 8 GB of free disk space.

> 5) What are your logging settings from the wrapper.conf file.

Here is our entire wrapper.conf file (it's small)

wrapper.java.command=../jre/bin/JavaESBServer.exe
wrapper.java.maxmemory=512
wrapper.java.mainclass=org.tanukisoftware.wrapper.WrapperSimpleApp

wrapper.app.parameter.1=gov.iowa.das.ite.i3.esb.server.ESBServer

wrapper.java.classpath.1=../lib/wrapper.jar
wrapper.java.classpath.2=../classes
wrapper.java.classpath.3=../lib/javamail-1.4.jar
wrapper.java.classpath.4=../lib/*.jar

wrapper.ntservice.name=I3InternalESBServer
wrapper.ntservice.displayname=I3InternalESBServer
wrapper.ntservice.description=I3InternalESBServer

wrapper.pidfile=../logs/wrapper.pid
wrapper.java.pidfile=../logs/java.pid

wrapper.logfile=../logs/I-3InternalESBServer-ROLLNUM.log
wrapper.logfile.maxsize=1m
wrapper.logfile.rollmode=SIZE
wrapper.logfile.maxfiles=10

wrapper.logfile.format=ZPLM
wrapper.logfile.loglevel=INFO

Here is also our log4j.xml file:

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration>

<log4j:configuration xmlns:log4j='http://logging.apache.org/'
        debug="false">

        <appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
                <layout class="org.apache.log4j.PatternLayout">
                        <param name="ConversionPattern"
                                value="%p|%C{1}.%M(%L)| %m%n" />
                </layout>
        </appender>

        <appender name="DB" class="org.apache.log4j.db.DBAppender">
                <connectionSource
                        class="org.apache.log4j.db.DataSourceConnectionSource">
                        <dataSource
                                class="org.apache.commons.dbcp.BasicDataSource">
                                <param name="driverClassName" value="com.mysql.jdbc.Driver" />
                                <param name="url" value="jdbc:mysql://localhost:3306/I3Gateway" />
                                <param name="username" value="conv_system" />
                                <param name="password" value="password" />
                                <param name="maxActive" value="10" />
                                <param name="maxIdle" value="1" />
                                <param name="defaultAutoCommit" value="true" />
                                <param name="removeAbandoned" value="true" />
                                <param name="removeAbandonedTimeout" value="300" />
                                <param name="logAbandoned" value="true" />
                                <param name="validationQuery" value="select 1" />
                        </dataSource>
                </connectionSource>
        </appender>

    <logger name="gov.iowa.das.ite.i3.conversion.server" additivity="true">
        <level value="INFO" />
        <appender-ref ref="CONSOLE" />
    </logger>

    <logger name="gov.iowa.das.ite.i3.conversion.notification" additivity="true">
        <level value="INFO" />
        <appender-ref ref="CONSOLE" />
    </logger>

    <root>
        <level value="INFO" />
        <appender-ref ref="CONSOLE" />
     </root>

</log4j:configuration>

> Once we have confirmed that some output from the JVM is making it to
> the Wrapper to be logged then the Wrapper can be ruled out and we can
> look into what on the Java side might be causing the problem.

I'm guessing since Wrapper startup and shutdown seem to be getting logged it's not Wrapper, but since Wrapper is apparently intercepting the logging activity, well, it's hard to tell where the problem is after that.

> All java side logging tools use System.out to print log information to
> the Java console.   So you can easily test that by adding some
> System.outs to your code.  If those show up in the Wrapper.log file,
> but the log4j calls do not then it is a java side logging problem of
> some sort.

I'll see if we can put some System.outs in the code next to the log.info or log.error calls which from what I can see our software uses exclusively.  It won't be something I can do quickly; I'll have to get approval to deploy it even on our test machine. It may take a few days.

> I may have more ideas after hearing back from you.

I greatly appreciate the assistance, Leif!

 - Bill Davis