stdout being redirected to an open file?

[bjhartin]

All,

Does anyone know why text sent to stdout might intermittently get sent
to an open file? I have some code which writes data to a file and logs
its activity using log4j. On Friday, the log statements began to
intermittently appear in the file. I know the following things are
true:

* The code did not change
* The configuration did not change
* The log4j Logger is mapped only to a ConsoleAppender, i.e. log
statements are written only to stdout
* The name of the file is always unique

Here is the code:

//Create a unique filename for the order
filename = "Order " + orderId;

//Create the file
logger.info("Creating file " + fileName);
File file = new File(fileName);
FileWriter fw = new FileWriter(file);
logger.info("Writing File Content ");
fw.write(fileContent + System.getProperty("line.separator"));
logger.info("Closing File ");
fw.close();

It smells to me of an O/S or app server problem in which the file
handle for the open file is being provided for calls to stdout. Has
anyone ever seen this?

Thanks,

Brian

 

[Roedy Green]

Does anyone know why text sent to stdout might intermittently get sent
to an open file? I have some code which writes data to a file and logs
its activity using log4j. On Friday, the log statements began to
intermittently appear in the file.

See http://mindprod.com/console.htm

You can dynamically redirect System.out and System.err.

 

[Roedy Green]

See http://mindprod.com/console.htm

You can dynamically redirect System.out and System.err.

oops, did it again. That should be.

http://mindprod.com/jgloss/console.html

 

[bjhartin]

Hmm, I'll check to see if any other code is redirecting stdout. I
would assume that this is done per-JVM and not per-thread, right? This
code is running as part of a POJO that backs a stateless session bean,
so there are definitely other threads going in the JVM. However, I'm
not sure how they could redirect stdout to the particular file I'm
writing to, since it is created with a unique name each time the method
is called.

Thanks for your reply.

Brian

 

[Roedy Green]

I
would assume that this is done per-JVM and not per-thread, right?

there is only one static copy of Sysout.out.

 

[Roedy Green]

Hmm, I'll check to see if any other code is redirecting stdout. I
would assume that this is done per-JVM and not per-thread, right? This
code is running as part of a POJO that backs a stateless session bean,
so there are definitely other threads going in the JVM. However, I'm
not sure how they could redirect stdout to the particular file I'm
writing to, since it is created with a unique name each time the method
is called.

so you don't really want to mess with Sysout. You simply want to
direct some encoded character output to a file. For how to do that see
http://mindprod.com/applets/fileio.html

 

[bjhartin]

Perhaps I haven't explained the problem well. We're not having trouble
writing to a file. That part is fine. The problem is that in addition
to the expected data, the files intermittently contain data that was
destined for stdout. You can run the same code ten times and see the
problem only once or twice. In addition, the log statements which
unexpectedly appear in the file are often out of order, as if they're
being 'held up'. This does *not* reflect multithreading, because each
file is given a unique name created from a database sequence.

Since my original post I have discovered that other code on this box
has had trouble writing to stdout. Sometimes the output just vanishes,
while in our case it shows up in a file. I think we have a problem
with the app server, JVM or O/S.

Thanks for your replies.

 

[Roedy Green]

In addition, the log statements which
unexpectedly appear in the file are often out of order, as if they're
being 'held up'.

This sounds possibly like you are logging with many threads but your
logging class is not thread safe. See
http://mindprod.com/jgloss/threadsafe.html

As for System.out stuff getting mixed in, your first job is to track
which line in the code could have generated those lines, and make sure
System.out is not redirected at that point or if those lines are being
logged instead of System.outed.

Unless you are using some home-grown spooling software, I would put
blaming generic spooling low on my list of suspects. The problem would
likely show up all over the place, not just this program if that were
the source of the problem.

 

[bjhartin]

This sounds possibly like you are logging with many threads but your

logging class is not thread safe.

As I mentioned, we are using log4j with no customizations. log4j
claims to be thread-safe. The log4j code has syncrhronized blocks of
code for accessing resources for which there might be contention. At
any rate, our log4j configuration specifies only console logging, for
which contention should not be an issue, right?

As for System.out stuff getting mixed in, your first job is to track which line in the
code could have generated those lines, and make sure System.out is not
redirected at that point or if those lines are being logged instead of System.outed.

I did a search and System.setOut appears nowhere in our codebase, nor
in the log4j code. The code which generates the lines in question is
simply that I described in my first message, i.e. simple calls to
log4j's Logger.info() method.

Unless you are using some home-grown spooling software, I would put
blaming generic spooling low on my list of suspects. The problem would
likely show up all over the place, not just this program if that were
the source of the problem.

As I mentioned above, I recently discovered that other java apps on
this machine *are* having intermittent trouble writing to stdout.
However, the common thing among these apps is that they run under
Weblogic 8.1. Each app runs in its own JVM, i.e. its own Weblogic
server (keep in mind Weblogic servers are virtual).

Thanks for your help.