Menu
▾
▴
Re: [Wrapper-user] Logging randomly just "stops"
|
From: Leif M. <le...@ta...> - 2008-07-10 00:21:19
|
Bill, When you shut the Wrapper down at 16:30, there was a single "Wrapper Stopped" line logged. If the Wrapper is not getting anything from the JVM, that is all that is expected. This tells me that the Wrapper's ability to write something to the log file is working correctly. It does not, however, confirm that the Wrapper is receiving and processing any JVM output correctly. Rather that you going through and adding System.out calls manually, the easiest thing to do would be to set the wrapper.debug=true property. This will cause log entries originating from the Wrapper and Java processes to be logged every 5 seconds. Doing this will tell us if all logging is stopping, only JVM console output, or possibly only the log4j output. I understand that it is difficult to test on customer systems. The debug property should not affect how the application runs and is a very low risk change. The only effect will be to have a large wrapper.log file. Question: In the log examples you sent me, the last entry on 2008/07/08 was at 01:03. The Wrapper was then stopped at 16:30. What happened to the 2008/07/08 01:30 Wrapper shutdown that should happen every night. Is it possible that something there could be causing the problem? I am not sure what normally happens during that shutdown period. Cheers, Leif On Thu, Jul 10, 2008 at 4:43 AM, Davis, Bill [DAS] <Bil...@io...> wrote: > 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 > |
