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

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

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

Thanks, that's kind of what I thought.

> 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 was thinking about doing that, actually, and fiddling with some of the threshold and flushing settings in case maybe the sudden flood of messages was overloading memory or something somewhere.  Good to know I was on the right track.

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

We have the disk space.  I'll probably want to change the number of files kept to a larger amount too (presently 10).  I might also move the log file to the D: drive which has 106gb free space (don't ask me why the C: drive is 30GB with 8GB free and the D: is >100 GB and unused. Seems silly to me, and potentially dangerous.)

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

That would be the one at 2007/07/*09* 01:19:25.096. Note the 09, not 08.  That was further down in the log file excerpts I sent, actually:

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

The 1AM shutdown-and-restart of the Wrapper to change the configuration file for the Mule server happens only approximately at 1AM to 1:30AM.  Time can vary based on evening processing tasks taking different amounts of time (payroll, several other things than happen only monthly/weekly/quarterly/annually/etc)

To make sure what we're doing is clear:  The Wrapper is ALWAYS running the Mule ESB server process except for a 1 minute interval twice at day at 16:30 (4:30PM)   and somewhere between 01:00 and 02:00 AM (or more accurately: whenever evening processing has completed) to swap between Mule configuration files for our normal daytime processing and evening processing tasks.   We do this because we don't want Mule accepting daytime data files during evening processing of the daytime data files we received...and Mule apparently ain't smart enough to not trigger file transfer and processing jobs in the evening.  Dumb ol' Mule!  Also, we likewise have some data transfers TO and FROM other systems to which we expect responses in the evenings that we don't want running during the day.  Thus the stop-and-start of the Wrapper around Mule, with the Mule config file swaps in between.

Thanks again for the guidance.  We'll see what we can come up with.  I may also try to figure out how to have the console stuff written to log4j from our code go to our own separate file, if possible. I prefer it in the Wrapper log, truthfully, to keep all the service's activity logging in ONE place, but hey, whatever works.   And I've got a lot of reading up on Wrapper, Mule and Log4j yet to do.  Among other technologies and tools!

 - Bill Davis