NX: Logging using FileHandler

[Bill Robertson]

I am using a FileHandler with java SimpleFormatter() class to
log all of my exceptions. My enclosing class creates the file (i.e. systemstart.logging) and it nicely appears in the location specified.
But it also creates a .lck file, like systemstart.logging.lck, and its
always blank. I have looked through and through the API's and cannot
determine what the .lck file is all about.
Does anyone know?

[Philippe Maquet]

Hi Bill,
It's a file generated by FileHandler for internal locking purposes. Don't care about it.
Best,
Phil.

[Bill Robertson]

thanks Phil. I wish I could prevent them from showing up, they are annoying.

[Dave Knipp]

Phil is all over the place man, he's got all the answers
[ October 23, 2003: Message edited by: Dave Knipp ]

[Philippe Maquet]

[Jim Yingst]

One option is to configure your logging handlers with the logging.properties file (found in [JDK dir]/jre/lib) rather than setting it up in your code. By default, there's no FileHandler set up, and there's one ConsoleHandler which logs at INFO level. But you can change/add a few lines:

handlers= java.util.logging.FileHandler, java.util.logging.ConsoleHandler
 
...
java.util.logging.FileHandler.pattern = %h/java%u.log
java.util.logging.FileHandler.limit = 50000
java.util.logging.FileHandler.count = 1
java.util.logging.FileHandler.formatter = java.util.logging.XMLFormatter
java.util.logging.FileHandler.level = FINEST
java.util.logging.FileHandler.formatter = java.util.logging.SimpleFormatter
...
suncertify.level = FINEST

Now you've got logging to a file in the [user dir]/java directory. The idea is that file logging only shows up on systems where the user has configured logging.properties for it. So the Sun grader won't see it unless he explicitly asks for it - and if he does, that's fine, he shouldn't be upset if there's a locking file; that's normal.

[Philippe Maquet]

Hi Jim,
The problem with using the default global logging.properties IMO is that you don't know what the grader will see - or not.
During development, I use a specific config file (got from the system property "java.util.logging.config.file"). So I may activate/deactivate handlers and set their level, as well as activate/deactivate individual loggers and set their individual level.
When the grader will run the apps, logging will maybe be turned off by default (or set at Level.WARNING for example), using the following method :

    public static void checkLoggingConfigFile(Level defaultLevel) {
        String configFile = System.getProperty("java.util.logging.config.file");
        if (configFile == null || configFile.equals("")) {
            Logger.getLogger("").setLevel(defaultLevel));
        }
    }

Maybe I'll make that default level an application property (in suncertify.properties).
Anyway, because I think it's very unlikely that the grader will be willing to change its default config file just to check my logging ( ), I'll be sure with this solution that the grader will not be overwhelmed by console messages (at the level INFO for example) if he doesn't decide it expressly. ...
I'll probably furnish 3 config files (one per mode) with all possible loggers listed and their level set at a fair value, so he can play with them if he wishes.
Jim, if you've any comment, they'll be welcome : I am playing with logging just since this morning...
Best,
Phil.

[Jim Yingst]

I'll be sure with this solution that the grader will not be overwhelmed by console messages (at the level INFO for example) if he doesn't decide it expressly. ...
Well, I chose my INFO messages so that they don't overwhelm; there's very little to report at that level. For a client, it's just thing like "connected to server" or "connection closed" (or error messages of course). For a server, It's mostly just "server started" and "server shut down". Everything else is at FINE or FINER or FINEST. I figure if a grader has a config file set at that level, they shouldn't be surprised if they get more messages.
During development, I use a specific config file (got from the system property "java.util.logging.config.file").
Mmmm, I'll look into this; might be worthwhile. I haven't really tried all the different ways loggers can be set up, maybe there's a better way.

[Philippe Maquet]

Hi Jim,
Thanks for your comments.
[Phil]:
During development, I use a specific config file (got from the system property "java.util.logging.config.file").
[Jim]:
Mmmm, I'll look into this; might be worthwhile. I haven't really tried all the different ways loggers can be set up, maybe there's a better way.
In the meantime you'll have had a look into it for sure ( ), but as it may help others, I post here my own search results.
Here is how I am doing.
Any class which uses a logger uses its own logger, named with the package name + the class name, like here :

    private static Logger log = Logger.getLogger("suncertify.db.Cache");

During development, I use 3 different logging config files which are taken into account or not depending on the system property value "java.util.logging.config.file".
If my server is started like this :

java -cp . -Djava.util.logging.config.file=c:\scjd\serverlog.properties suncertify.Run server

my serverlog.properties config file will be used,
while with the config file omitted like here :

java -cp . suncertify.Run server

the server will set the global logging level at its (or the user's) preferred value, and not the one specified in the default global logging config file (see the method posted above).
My config files look like this one :

# Handlers
#handlers = java.util.logging.FileHandler, java.util.logging.ConsoleHandler
handlers = java.util.logging.ConsoleHandler
# ConsoleHandler settings
java.util.logging.ConsoleHandler.level = ALL
# FileHandler settings
java.util.logging.FileHandler.formatter = java.util.logging.SimpleFormatter
java.util.logging.FileHandler.level = ALL
java.util.logging.FileHandler.pattern = %t/URLyBirdServer%u.log
# Individual loggers settings
.level = OFF
suncertify.level = WARNING
#suncertify.db.level =
suncertify.db.Cache.level = ALL
suncertify.db.Data.level = INFO
#suncertify.db.MetaData.level = FINER
#(continued)

In the "# Individual loggers settings" section, I list all my loggers (and loggers paths) in alphabetical order, so I can quickly change a given logger level for debugging purposes.
In the lines above :

the global level if OFF

my default suncertify level is WARNING

my default suncertify.db level is "same as parent" (because commented out)

my suncertify.db.Cache level is temporarily set to ALL, probably because I am debugging Cache

my suncertify.db.Data level is set to INFO because whatever its parent level I want its info messages to be logged

as MetaData is now debugged, my suncertify.db.MetaData level line is now commented out

(...)

I think it's an handy way of doing and ... it works fine.
Best,
Phil.
[ October 24, 2003: Message edited by: Philippe Maquet ]

[Bill Robertson]

During development, I use 3 different logging config files which are taken into account or not depending on the system property value "java.util.logging.config.file".
If my server is started like this :
code:
----------------------------------------------------------------------------
java -cp . -Djava.util.logging.config.file=c:\scjd\serverlog.properties suncertify.Run server
----------------------------------------------------------------------------
my serverlog.properties config file will be used,
while with the config file omitted like here :

The problem here is that my directions say "When you submit your assignment, each part (client and server) must be executable using a command of this exact form: java -jar <path_and_filename> [<mode>]
Your programs must not require use of command line arguments other than the single mode flag, which must be supported. Your programs must not require use of command line property specifications."
You may want to check yours.
Also, I dont know how we can assume any directory to place the logs other
than the current working directory because we are not guaranteed where they
will run our jar file. Unless you create sometype of logging file
on the fly in you code in the current working directory.

[Philippe Maquet]

Hi Bill,
Thanks for your comments.

The problem here is that my directions say "When you submit your assignment, each part (client and server) must be executable using a command of this exact form: java -jar <path_and_filename> [<mode>]
Your programs must not require use of command line arguments other than the single mode flag, which must be supported. Your programs must not require use of command line property specifications."
You may want to check yours.

I thought of that. "Your programs must not require use of command line arguments". Well, they won't require them. Here are my arguments :

My programs will perfectly work (I mean hopefully ), without any command line argument and without any logging configuration file.

The "-Djava.util.logging.config.file=(...)" is not a command line argument of my programs, but a command line of the java application.

Even if the grader has another interpretation, he will not be required to use it.

Better, I'll have application properties (stored in suncertify.properties) used to set (through the GUI) the global logging level in case a logging configuration file would not be used (see previous posts).

Also, I dont know how we can assume any directory to place the logs other
than the current working directory because we are not guaranteed where they
will run our jar file. Unless you create sometype of logging file
on the fly in you code in the current working directory.

I don't know any standard way (from external config information) to put log files in the current directory. That's why I used the "%t/URLyBirdServer%u.log" pattern above, which stores the log files in the temp directory. But anyway, all config files I will ship with my application will have the FileHandler definition line commented out as in the example above (the first "handlers=" line), in such a way that if my grader uses my provided config files and wants to enable the FileHandler, he will do it under his own responsability.
Do you agree with the arguments above ?
Best,
Phil.

[Bill Robertson]

Yes and no. "-Djava.util.logging.config.file=(...)" is a command line,
but as you mentioned, a command line of the java application.
config.files are great, but in this case I am just taking the user's
current working directory and adding the directory "Logs" and then placing
everything in there. I don't know how they could ask for more.
How will the grader choose to use your config files. And the config files
shipped with your application will be located where ?

[Philippe Maquet]

Hi Bill,

How will the grader choose to use your config files.

In my instructions they tell me about user guides, while in other assignments there is a readme.txt file for such a purpose ...

And the config files
shipped with your application will be located where ?

Anywhere within the packaging JAR file, as far as it's documented.
Best,
Phil.

[Bill Robertson]

So you are saying, for example, if your packages are all in directory
"code" you stick the properties file in "code" and then jar it up.
So your code looks for your properties file using the current working
directory + "code" ?
Am I correct

[Philippe Maquet]

Hi Bill,

So you are saying, for example, if your packages are all in directory
"code" you stick the properties file in "code" and then jar it up.
So your code looks for your properties file using the current working
directory + "code" ?
Am I correct

Sorry about it, but no you aren't.
I think that you are mixing locations :

Within the jar file, I can store my sample logging config files in any place, as far as I document it. It can even be some badly named "MyStuff" directory.

If the grader - because he's in a good mood - decides to play with them, he may put them in any place he likes (even in "c:\temp").

If the grader - he's still in a good mood - decides to use them, he will use the -D system property described above, pointing to the place where he put the config file.

My code doesn't need to look at that place. It just checks if a config file is in use (see a few posts above). If it's the case, my code does nothing (I let the logging API self-configurating with the help of the config file). If it's not the case, I set a global logging level as explained above.

Hope it's clearer.
Andrew and/or Jim and/or Mark, please put a little of your wisdom in this thread ... Bill is going to make me doubting about my logging solution and ... finally about myself ! BTW, why did I ever think of replying to Jim above ?
Best,
Phil.
[ October 24, 2003: Message edited by: Philippe Maquet ]

[Bill Robertson]

Its clear now. Its just that I would think the grader would not want
to go through the trouble of using the config file.

[Jim Yingst]

I figure the logging is for me, not for the grader. I'd be perfectly happy if the grader doesn't look at it at all, since it's not a requirement. I just don't want it to get in the grader's way.

[Bill Robertson]

But if your logging exceptions you will want the grader to
easily identify how and where your logging to.

[Jim Yingst]

But if your logging exceptions you will want the grader to
easily identify how and where your logging to.
OK, true. Also junior programmers need to be able to find it easily. But it's not something the user needs to know about, so I'm not spending a lot of time in the user manual explaining how to configure logging. A few comments in my logging code ought to do the trick for any programmer who wants to figure out where the logging goes. (It all gets directed to a java.util.Logger. I just provide a few convenience methods in a class called Logging. Ought to be pretty obvious to any programmer looking at the code.) Cheers...

[Akash Singh]

Hi Bill, Jim and Phil.

I have few questions on Logger. I would appreciate your response.

1. In following example code for chained exception. Would you like to log
at each point where exception is thrown , or only high level exception .

  
  import java.io.*;
import java.util.logging.*;
public class Junk {
     public static void main(String args[]) {
         try {
             a();
         } catch(HighLevelException e) {
             getLogger().log(Level.SEVERE, "HighLevelException" ,e.getCause());
         }
     }
     static void a() throws HighLevelException {
         try {
             b();
         } catch(MidLevelException e) {
             getLogger().log(Level.SEVERE, "MidLevelException" ,e.getCause());
             throw new HighLevelException(e);
         }
     }
     static void b() throws MidLevelException {
         c();
     }
     static void c() throws MidLevelException {
         try {
             d();
         } catch(LowLevelException e) {
             getLogger().log(Level.SEVERE, "LowLevelException" ,e.getCause());
             throw new MidLevelException(e);
         }
     }
     static void d() throws LowLevelException {
        e();
     }
     static void e() throws LowLevelException {
         throw new LowLevelException();
     }
     static public Logger getLogger(){
         Logger logger=null;
         try {
              Handler handler = new FileHandler("zunk.log");
              handler.setFormatter(new SimpleFormatter () );
              // handler.setFormatter(new XMLFormatter () );
              Logger.getLogger("").addHandler(handler);
              logger = Logger.getLogger("junk");
           } catch (IOException logException) {
             System.err.println("Logging error");
           }
        return logger;
    }
 }
 class HighLevelException extends Exception {
     HighLevelException(Throwable cause) { super(cause); }
 }
 class MidLevelException extends Exception {
     MidLevelException(Throwable cause)  { super(cause); }
 }
 class LowLevelException extends Exception {
 }
  

2. Which formatter (SimpleFormatter or XMLFormatter) is appropriate
to use ?
3. My plan is not to have dependency at all on java.util.logging.Properties file. Want to Use a ApplicationLogger class, that will have a method getLogger. This method would write database and server log into present working directory.
Any comment on this, please .

Regards,
Akash

[Andrew Monkhouse]

Hi Phil,

Originally posted by Philippe Maquet:

Within the jar file, I can store my sample logging config files in any place, as far as I document it. It can even be some badly named "MyStuff" directory.

If the grader - because he's in a good mood - decides to play with them, he may put them in any place he likes (even in "c:\temp").

If the grader - he's still in a good mood - decides to use them, he will use the -D system property described above, pointing to the place where he put the config file.

My code doesn't need to look at that place. It just checks if a config file is in use (see a few posts above). If it's the case, my code does nothing (I let the logging API self-configurating with the help of the config file). If it's not the case, I set a global logging level as explained above.

I agree with your reasoning.
However I would tend to have a value in the properties file (default to turned off) rather than having a command line option. Same logic applies: the examiner is not required to manually edit the file, but the option is there.
My preference of properties file over command line argument is that it is easier to get a user to turn logging on remotely if needed - tell them to edit the properties file using any text editor, and change a value from FALSE to TRUE. Simple. Try telling them to change a command line option over the phone! Especially with the users who only know that they "Click on the Start button, go to Programs, go to..." - they may not have permission to change anything in the standard application menus, and even if they do, they may not know how to do it.
I would not create a log file by default, unless it was automatically overwritten each time - too much danger of the customer being unaware of it and 6 months later they are out of hard drive space and cursing the developer (when they track down the issue).
Regards, Andrew

[Andrew Monkhouse]

Hi Akash,

Originally posted by Akash Singh:
Hi Bill, Jim and Phil.
I have few questions on Logger. I would appreciate your response.

Hmmm, I guess I shouldn't answer then

Originally posted by Akash Singh:
1. In [the] example code [above] for chained exception. Would you like to log at each point where exception is thrown , or only high level exception .

This can be a value judgement. But I tend to log something I might be interested in later as soon as I possibly can. So normally I would log the exception at the point where it is thrown / first caught.

Originally posted by Akash Singh:
2. Which formatter (SimpleFormatter or XMLFormatter) is appropriate
to use ?

Who (or what) is going to be reading these messages? If you are planning on putting them into some tool that can give you some nice way of working with these messages, then by all means use XML.
But if you are just going to read the messages directly from the file, you may find it simpler to read plain text.
Regards, Andrew
[ October 25, 2003: Message edited by: Andrew Monkhouse ]

[Philippe Maquet]

Hi Jim,

Jim:
I figure the logging is for me, not for the grader. I'd be perfectly happy if the grader doesn't look at it at all, since it's not a requirement. I just don't want it to get in the grader's way.

Jim:
But it's not something the user needs to know about, so I'm not spending a lot of time in the user manual explaining how to configure logging.

We have different opinions, but I understand yours.
I think logging is :

for me as a developer

for the application I am building

for the admin user

It seems that we agree on point 1. Logging brings much help in debugging and it's worth while to use it just for that purpose.
But once you get it, you get "for free" an additional application feature (point 2 above). Without any additional effort, you offer the application a light but useful monitoring tool.
Now if point 2 is true, 3 is true too. As an admin user interested by that activity monitoring feature, your area of interest may be different from what the developper had in mind. Maybe the latter put Level.INFO messages in areas you don't want to be monitored. So it may be useful for the admin user to have some easy way to activate/deactivate logging parts and fix his own right levels of information.
Further, I don't any application in production which never fails somewhere in its life. So if logging is there and is accessible to the admin user, if he suspects some part to be guilty, and if your logging granularity is high enough, he may activate logging for any given class or group of classes at the highest level, just to check his doubts.
Best,
Phil.

[Philippe Maquet]

Hi Akash,

1. In following example code for chained exception. Would you like to log
at each point where exception is thrown , or only high level exception .

I asked the same question to myself, and I have no definitive answer yet.
It could change, but here is what I am thinking now :
Exceptions should be logged at all levels, but maybe not at the same Logger.level, depending on the exception type.
For checked exceptions, I would use Level.FINER just before throwing (that's what Logger.throwing() does BTW). Because as - by definition - checked exceptions are catched somewhere, they'll probably get logged at a higher logging level within the catch block. By doing what you do in your example, you'll get the same information logged multiple times at the same Level.SEVERE level, which is not very useful IMO and harder to read and interpret.
For unchecked exceptions, it's quite different. Because they may be uncached, it's probably better to log them
at level Level.SEVERE (or WARNING) before they are thrown. Now, if you know that some RuntimeException thrown from a low-level tier will be catched by some mid-tier part of your application simply because it's its job to catch them, I think you should treat them in the same way as checked exceptions.
Best,
Phil.

[Philippe Maquet]

Hi Andrew,
Thanks for your comments.

I agree with your reasoning.
However I would tend to have a value in the properties file (default to turned off) rather than having a command line option. Same logic applies: the examiner is not required to manually edit the file, but the option is there.
My preference of properties file over command line argument is that it is easier to get a user to turn logging on remotely if needed - tell them to edit the properties file using any text editor, and change a value from FALSE to TRUE. Simple. Try telling them to change a command line option over the phone! Especially with the users who only know that they "Click on the Start button, go to Programs, go to..." - they may not have permission to change anything in the standard application menus, and even if they do, they may not know how to do it.

I agree with you and you let me think to a nice solution. It will take some time to make it 100% clear in my mind, so I'll wait a bit before telling you.

I would not create a log file by default, unless it was automatically overwritten each time - too much danger of the customer being unaware of it and 6 months later they are out of hard drive space and cursing the developer (when they track down the issue).

You're right and I didn't intent to do that.
Best,
Phil.

[Bill Robertson]

Andrew

I would not create a log file by default, unless it was automatically overwritten each time - too much danger of the customer being unaware of it and 6 months later they are out of hard drive space and cursing the developer (when they track down the issue).

This is what I am doing. But it is cleared after each run. Also during
the running of the program if specific exceptions occur the user
is given a message to view the logs or call the help desk!!!
Do you see this as a problem?

[Jim Yingst]

But once you get it, you get "for free" an additional application feature (point 2 above). Without any additional effort, you offer the application a light but useful monitoring tool.
This can be beneficial, but it's not exactly "for free" if I have to document it really carefully the way I do the other end-user features. You're right that people like server admins could find this useful though, so I guess I will mention it in the server section of the user guide. But I don't plan on describing the file syntax in detail, for example. I'll give a couple typical examples and refer them to Sun's documentation for details. My point is that it was an optional feature in the first place, and the only people who should be interested in it are people who can be expected to have a more tecnical background and be able to think for themselves to some extent. By letting things be specified in a logging.properties file rather than set up by the program, we make the system more flexible and configurable for those who wish to use the logging - but I don't want to do a lot of extra documentation because of this. It's an advanced user feature, as far as I'm concerned.
[Phil]: Exceptions should be logged at all levels, but maybe not at the same Logger.level, depending on the exception type.
Ewww. I dislike having a bunch of redundant logging code, and redundant messages in the log file. A single stack trace should have most all the info I need. My rule of thumb in most cases is to try to log an exception exactly once, at whatever level I have decided to catch a given exception and not rethrow it. If I'm just going to rethrow, or wrap the expression in a new and different expression and then re-throw, I know that the expression will still be logged later when it's eventually caught. I'm very meticulous about that. My main thread and event handlers all have high-level catch blocks which log any previously uncaught Throwables.
Now there are cases where a mig-level method needs to catch an exception and do something special in response before re-throwning. Maybe the mid-level method has some additional information about what's going on, which should also be logged. So there are some cases where I'll log a midlevel catcher. But in most cases, if a mid-level method has data I want logged, I'll just catch the low-level exception and wrap it in a new exception with the additional info. No logging needed, because all the info is in the new exception, and I know everything will be logged later on when it's eventually caught at a higher level.

[Philippe Maquet]

Hi Jim,

[Phil]: But once you get it, you get "for free" an additional application feature (point 2 above). Without any additional effort, you offer the application a light but useful monitoring tool.
[Jim]: This can be beneficial, but it's not exactly "for free" if I have to document it really carefully the way I do the other end-user features. You're right that people like server admins could find this useful though, so I guess I will mention it in the server section of the user guide. But I don't plan on describing the file syntax in detail, for example. I'll give a couple typical examples and refer them to Sun's documentation for details. My point is that it was an optional feature in the first place, and the only people who should be interested in it are people who can be expected to have a more tecnical background and be able to think for themselves to some extent. By letting things be specified in a logging.properties file rather than set up by the program, we make the system more flexible and configurable for those who wish to use the logging - but I don't want to do a lot of extra documentation because of this. It's an advanced user feature, as far as I'm concerned.

So we don't disagree at all with this. As logging configuration is a system admin task, and system admins are - by definition - people with a strong technical background, a few lines of extra doc are enough IMO too (+ the list of all existing loggers of course, but that one we have to build it anyway for own use while we develop.). So OK, let's translate my "for free" in "at the cost of less than 5 additional lines in our doc".
Now I'll probably go a step further. As Andrew noticed above, the -D command-line argument solution is not very handy. I do think it doesn't break our requirements because it's not an application argument, but Andrew is right anyway ...
I thought of a simple no-arg solution, I just need to make some tests, and I'll come back here with it soon.

[Phil]: Exceptions should be logged at all levels, but maybe not at the same Logger.level, depending on the exception type.
[Jim]: Ewww. I dislike having a bunch of redundant logging code, and redundant messages in the log file. A single stack trace should have most all the info I need.

Mmh. It's just the aim of using the FINER level when throwing. If your handler is set at INFO, WARNING or SEVERE levels, you won't log anything when throwing. By reading the Logger.throwing() method documentation (method that I don't use BTW - I use Logger.log(Level.FINER, (...)) instead to have more control) :

public void throwing(String sourceClass,
String sourceMethod,
Throwable thrown)
Log throwing an exception.
This is a convenience method to log that a method is terminating by throwing an exception. The logging is done using the FINER level.
If the logger is currently enabled for the given message level then the given arguments are stored in a LogRecord which is forwarded to all registered output handlers. The LogRecord's message is set to "THROW".

,
I easily convinced myself that it could be good practice because if it was not the case, Logger.logging() would have no purpose by definition.

My rule of thumb in most cases is to try to log an exception exactly once, at whatever level I have decided to catch a given exception and not rethrow it. If I'm just going to rethrow, or wrap the expression in a new and different expression and then re-throw, I know that the expression will still be logged later when it's eventually caught.

Weird situation : I read that quote of you three times and the more I read it, the more I got convinced you were right. But at fourth reading, you finally reinforced my conviction about logging exceptions at the FINER level when throwing.
As a low-level class writer (the class, not you ! - still my english problem ... ), you cannot make any assumption on how the exceptions you throw will he handled by the client classes or yours. Maybe you will write them yourself, maybe a junior programmer will write part of them, or even your customer development team. How can you make sure that all your low-level exceptions will be properly logged in all catch blocks ?
What will happen if a junior (and lazy) programmer calls your low-level method this way :

try {
    JimDB = new JimDB("jim.dat");
} catch (IOException e) {} // will be handled by the end of this week

That lazy junior forgets his comment, the app enters in production and from time to time it seems to work weirdly. Your customer suspects JimDB to be guilty (the guilty guy is always the other one), but doesn't see anything useful in its standard log files.
If you used the Logger.throwing() technique (or its Logger.log(Level.FINER) equivalent), you'll simply answer : "OK, please activate org.jim.db logger at FINER level, set up a specific file handler, reproduce the problem, and send me that log file". And when you'll receive the log file, it will just take you 1 minute to be able to reply "Sorry, but someone in your team didn't correctly handle the IOException my JimDB constructor throws.". In comparison, in case you didn't log your exception before throwing, you'll enter in a nightmare instead.
Convinced ?

My main thread and event handlers all have high-level catch blocks which log any previously uncaught Throwables.

Very good point I didn't think of. I'll write it in my to_do file !
Best,
Phil.
PS: I really enjoy this discussion with all of you. Thank you !

[Jim Yingst]

All right, you've convinced me that there may be a use for additional logging of exceptions. Most of my experience has been with systems that had way too much logging, or rather, logging at an inappropriate level. So my instinct is to just turn a lot of it off. I suppose I could make more use of different logging levels. The other thing is that for me, logging code often clutters things up. I often don't put in the FINEST stuff until there's a specific problem I'm trying to debug; then I remove it when I'm done. I value the compactness of the code more than the low-level messages. Plus many FINEST messages end up wasting machine cycles even when they're not yielding any messages. E.g.

logger.log(Level.FINEST, "Reading record " + recNo + " values = " + Arrays.asList(fields));

Even when the level is higher than FINEST, this call still results in a bunch of string concatenation to form the message, before the logger realizes it doesn't actually have to send the message anywhere. We can improve on this by using the log methods which take Object or Object[] parameters, because we can set these up to invoke the Object's toString() only after the handlers have determined that the message really does need to be logged. But this also requires us to make a custom Formatter, since the SimpleFormatter and XMLFormatter both seem to ignore Object and Object[] parameters completely.
OK, there are my reasons for disliking too much low-level logging. But you're right that there can be benefits, especially if you need to defend against the stupidity of other programmers. I think the "throwing" method is likely to be useful when an unchecked exception is first thrown, though I'm still skeptical about catching and logging in mid-level methods, as that can lead to a lot more logging code. Yes, some junior programmer may put in a an empty catch block somewhere, and that may take you a bit more time to track down without having everything logged. But one you do identify the problem, you get to go and beat the offending programmer senseless; it's very satisfying. I think that as long as the initial throw is logged, you have enough to go on, as you can see that there's a throw but no catch; from there you look at the stack trace and check the source for the methods that handled the exception.
I think a lot of this depends on how much maintenance you expect to have to do on a project. For a big project where you're actually being paid, then more extensive logging is probably warranted; for the Sun assignment, I think it's more of an optional thing; they never gave any indication they wanted logging, and you can always justify leaving it out in order to improve readability. As long as there's some sort of notification when an error occurs, like a pop-up. IMO anyway. Cheers...
[ October 25, 2003: Message edited by: Jim Yingst ]

[Philippe Maquet]

Hi Jim,

I'm still skeptical about catching and logging in mid-level methods (...) I think that as long as the initial throw is logged, you have enough to go on, as you can see that there's a throw but no catch; from there you look at the stack trace and check the source for the methods that handled the exception.

Agreed.
Best,
Phil.

[Andrew Monkhouse]

Hi Everyone,

Andrew I would not create a log file by default, unless it was automatically overwritten each time
Bill This is what I am doing. But it is cleared after each run. Also during the running of the program if specific exceptions occur the user
is given a message to view the logs or call the help desk!!!
Do you see this as a problem?

No problems.
One very nice solution that we used at my last company was to use rotating logs. So we could see the logs for the last 5 times the user used our program. But same basic concept - overwrite the log files so that you don't run out of space.

Jim Ewww. I dislike having a bunch of redundant logging code, and redundant messages in the log file.

I would prefer to have redundant log messages. I can always filter them out / skip over them if they aren't relevant to what I am currently looking for. But the one log message that the developer thought wasn't relevant is quite often the one that is needed.

Jim A single stack trace should have most all the info I need.

Perhaps - but is the logging for you?
I am used to customer support getting the log first, and trying to resolve the issue from that before it goes to a coder. So they should never see a stack trace.

Jim Now there are cases where a mig-level method ...

Wow - you are coding for MIGs? Defence force ready code!

Phil As a low-level class writer (the class, not you ! - still my english problem ... ), you cannot make any assumption on how the exceptions you throw will he handled by the client classes or yours. Maybe you will write them yourself, maybe a junior programmer will write part of them, or even your customer development team. How can you make sure that all your low-level exceptions will be properly logged in all catch blocks ?

I agree 100%.
There is also the loss of precision that often happens as an exception is passed up the chain. At the point that you catch the IOException, you might know whether it is a problem with disk space or with file permissions. But if you just wrap it inside a "ReallyBadException" and pass it up the chain, you are assuming that the person who catches that exception will log the causes of the exception. I can already see the junior programmer complaining to management because all he got out of your Data class was that something bad happened, and there is nothing in the log.

Jim My main thread and event handlers all have high-level catch blocks which log any previously uncaught Throwables.

Hmmm, missed that the first time around.
What are you doing here? Catching Throwable? And then logging it and continuing with the application?
There are subclasses of Throwable that really shouldn't be caught (all the Error subclasses and most of the RuntimeException classes), and if you do catch them then you almost certainly should throw them again.

Jim many FINEST messages end up wasting machine cycles even when they're not yielding any messages.

True - but this is more a comment that we need inteligent logging than no logging.
Logging the full details of each record read from the database (or cache) when it is going to be called every time anyone does a find (or just about any other operation) is definately going to be overkill.
But Exceptions are meant to be just that - exceptions to normal processing. So logging within the exception code is IMHO always justifiable.
I wouldn't worry about the performance of the logging code until after you have done tests and proven that the logging is actually the bottleneck in your system. You might end up getting a marginal increase in performance in an area of your code that was not a problem, but at the risk of making it harder for the support staff to do their job.
Regards, Andrew

[Jim Yingst]

Perhaps - but is the logging for you?
In this case, yes. There's no requirement for logging at all. I only put it in my program so I can see what's going on, and it's tiresome to remove later, so I leave it there in case someone else wants to see it. But the needs of the hypothetical support staff arent' a high priority for me; I want my individicual methods to be higly readable, and putting in a log of FINEST messages just clutters the code up (regardless of whether they get printed or not.)
[b]I am used to customer support getting the log first, and trying to resolve the issue from that before it goes to a coder. So they should never see a stack trace.
My thinking is that anyone looking at a log file shouldn't whine about seeing a stack trace. Especially at FINER or FINEST. I provide nice user friendly error messages in pop-ups; the log file has no obligation to hide stack traces in my opinion. I guess it's a different sort of company culture.
There is also the loss of precision that often happens as an exception is passed up the chain.
No, the loss of precision occurs when you catch the exception and log without rethrowing, but fail to log the stack trace.
At the point that you catch the IOException, you might know whether it is a problem with disk space or with file permissions. But if you just wrap it inside a "ReallyBadException" and pass it up the chain, you are assuming that the person who catches that exception will log the causes of the exception. I can already see the junior programmer complaining to management because all he got out of your Data class was that something bad happened, and there is nothing in the log.
Well this depends on the company's established error handling and logging policies, company culture, and your relationship with management, but my first inclination is to get the junior programmer to understand how to use nested exceptions (i.e., log the damn things), or get him sacked. Stack traces are our friends. Failure to report and use stack traces should be considered a crime. If management doesn't agree, then OK, I have to employ a lot more defensive logging to protect myself against the falures of others. But I guess I've been lucky thus far in that respect. JDK 1.4 has been out for a while now, and well before that I was creating custom NestingException classes to provide good stack traces under JDK 1.2 and 1.3. It was a lot easier to do that than to insert extra log statements everywhere exceptions were handled, and my coworkers quickly found the extra stack trace info to be valuable. Maybe the key is that I haven't worked that much with non-programmers who wanted to look at error logs. Or if they did, they understood that stack traces were something they'd just have to deal with.
To reiterate though - I've conceded that logging the initial throwing of the error is probably beneficial, though I maintain it shouldn't be necessary. But OK, it may be necessary, or at least a timesaver in tracking down some problems. Log the initial throw, and log the final catch. Everything in between though is unnecessary as far as I'm concerned, unless company poliy is otherwise.
On to another topic...
What are you doing here? Catching Throwable? And then logging it and continuing with the application?
Certainly not. If it's an Error, I catch it, try to log it and then display a user message, then exit. Wouldn't dream of continuing. Even though that's often what will happen if I don't catch it.
Consider: what happens if an Error is thrown in code that was called as a result of a user pressing a button? Chances are that the processing was being done by the event handler thread, unless you delegate another thread for it. If none of your own code catches it, it gets handled by the event handler thread itself, which prints a stack trace to System.err. Then what? Perhaps surprisingly, the program will probably keep right on going, andling new events as they come in. So whatever the button was supposed to do doesn't get done, and there's a message about that on the console if the user bothers to look there (if they even know what the console is.) But other than that, the program just keeps on going. No popup message to the user explaining that the previous action failed, or that something may be seriously wrong with the JVM. Nada. It's all too easy for the user to go on, thinking nothing is wrong.
Maybe you're thinking "Wrong! The uncaught exception will cause the event handler thread to terminate." Well, that's true. The problem is, that doesn't acually cause the JVM to terminate, as there are other non-daemon threads still around. And when another user event comes in, the JVM actually goes to the trouble of starting a new event handler thread. You can see a demo of this:

import java.awt.event.*;
import javax.swing.*;
public class ErrorButton extends JFrame {
    public ErrorButton() {
        JButton button = new JButton("Create Error");
        button.addActionListener(new ActionListener() {
            public void actionPerformed(ActionEvent e) {
                Thread t = Thread.currentThread();
                System.out.println(
                    "Thread: " + System.identityHashCode(t) + ": " + t);
                throw new Error();
            }
        });
        getContentPane().add(button);
        pack();
        setDefaultCloseOperation(JFrame.EXIT_ON_CLOSE);
        setLocation(200, 200);
        setVisible(true);
    }
    public static void main(String[] args) {
        new ErrorButton();
    }
}

Every time the button is pushed, we get a new Error thrown, whihc is never caught. Yet the GUI keeps right on going; if you press the button again, it's handled again. And check out the output regarding the currentThread() which is executing the event handler. Though the name of the thread is the same each time, along with the other info from toString(), it's not actually the same thread, as seen by System.identityHashCode(). You can see the difference by commenting out the throw new Error() - you'll see that the identity hash code remains the same in that case, because the event handler thread isn't getting killed off by the uncaught Error, then replaced.
Annoyingly, I can't find good documentation of how/if the event handler deals with uncaught Throwables. But in J2SDK 1.4.2 you can take a look at the class java.awt.EventDispatchThread (not in the API since it's package-level) and look at the run() method - comments there describe what's going on, at least for this implementation.
Other implementations may handle things differently. But the general point is, it's entirely possible to have an uncaught exception which creates no visible effect at all, other than output to System.err which most users will never see. There are other ways this can occur in a multi-threaded environment - most commonly, the thread that was prcessing the exception is killed, but other threads are alive and well, and their continued activity serves to confuse the user into thinking that all is well.
So, what to do? I try to make sure every event handler I write catches unchecked throwables and tries to log them and produce a user message. If it's an Error, then I System.exit(1) as well. That seems safest - exiting this application is hardly the end of the world after all; there's no possibility of having a large amount of unsaved data, so why not? Send a message and exit; let the user restart, and hopefully things will work better then. Sure, for more robust commercial applications there may be more elaborate failure recovery procedures (and the truth is, you can deal sensibly with some Errors if you know what caused them). But that's going well outside the scope of this assignment I think.
[ October 25, 2003: Message edited by: Jim Yingst ]

[Jim Yingst]

Oh, there is one other sorta-exception where I do endorse catching an exception, logging it, and then retrowing it. That's in a networked server using RMI. You want to make sure there's a good long on your server for any exception that's thrown from the server, as well as a log entry on the client. So I have logging in my RemoteDBImpl class, which is basically where the highest-level of methods of the server are located. So those methods catch and log exceptions before passing them on to clients. From the server's point of view, it's logging from the top level, but from the client POV, it looks like mid-level. So you could say I endorse mid-levle error logging in this case. Sort of.

[Philippe Maquet]

Hi Jim,
I won't quote anything from your two previous posts, because everything in them was interesting.
I was not aware of that issue of uncached runtime exceptions or errors. Better than some theoretical issue warning, you posted a nice demonstration of the issue and a way to get rid of it. I've bookmarked this thread just for that.
Thank you for having posted them !
Best,
Phil.

[Andrew Monkhouse]

Hi Jim,
I originally started to write about why just catching everything, logging it, and ignoring it was bad, then a few other things popped up, so I reduced it to that one line with a on the end. And then you gave a much better explanation of what was wrong with that scenario, along with an example.
Thanks.
Regards, Andrew

[Akash Singh]

Hi Jim,

Oh, there is one other sorta-exception where I do endorse catching an exception, logging it, and then retrowing it. That's in a networked server using RMI. You want to make sure there's a good long on your server for any exception that's thrown from the server, as well as a log entry on the client. So I have logging in my RemoteDBImpl class, which is basically where the highest-level of methods of the server are located. So those methods catch and log exceptions before passing them on to clients.

You mean : To log RMI server(High level from server POV) exception before sending to client, I should write method in RemoteDBImpl like this--

public DataInfo getRecord(int recNum)
   throws DatabaseException, RemoteException {
   try {
      return dataObject.getRecord(recNum);
   } catch (DatabaseException dbe){
      // log database problem in getting record
      // log client who got this problem
      throw dbe;
   }
   catch (RemoteException re){
      // log network problem
      // log client who got this problem
      throw re;
   }
}

Is my understanding correct about your comment ?
If yes,
1. How to identify client who got this problem , if client is not using
the system using some id. In my design(FBN), client is tracked by the RemoteObject its holding to handle lock/unlock. In this case, how can i log client. I think, I can not log really a meaningful client identity in
this assignment unless i enforce user to log in using some ID.
2. Is it Ok to catch RemoteException and rethrow it ?
Regards
Akash.

[Jim Yingst]

Is my understanding correct about your comment ?
Yes, except for point 2 below.
If yes,
1. How to identify client who got this problem , if client is not using
the system using some id. In my design(FBN), client is tracked by the RemoteObject its holding to handle lock/unlock. In this case, how can i log client. I think, I can not log really a meaningful client identity in
this assignment unless i enforce user to log in using some ID.
Right, logging a client ID is probably more complex than is required for this assignment. However if you're using a connection factory pattern, with one remote object per client, then you can generate some sort of unique identifier for the client, even though you don't know the client's name. You can use System.identityHashCode(Object) to get an number which is probably unique, good enough for most purposes. You could also have the connection object store the time that the connection was first opened, and use that to help identify a client. The server could also just assign each connection a number, incrementing a counter. You could even provide clients with a method to discover the client ID which the server has assigned, and log it. This way when a user calls with a problem, you can look at the user log file, get their cient ID, and then look for correspoding server log entries.
I hadn't done anything like that, but I think I may add it now, as it's fairly easy and useful. But it's surely optional; don't worry too much about it if you don't want to.
2. Is it Ok to catch RemoteException and rethrow it ?
It would be OK if there were something to catch. I think your compiler will probably complain that the RemoteException is never thrown within the try block. Your call
dataObject.getRecord(recNum);
doesn't throw a RemoteException, does it? In fact, the remote implementation does not need any "throws RemoteException" in any of its methods (unless they call other Remote methods maybe). The remote interface will need those exceptions declared, and the generated stub classes will have them, but most likely there's no reason a RemoteException will ever be thrown from within your server implementation. They're thrown by the RMI networking layer, between the client and server. Only hte client sees them.

[Akash Singh]

Thanks a lot for excellent explanation; appreciate your help Jim.
I would correct my RemoteDBImpl class.

Regards,
Akash